HystrixRequestLog shows [Executed] after all commands have delivered values

[mattrjacobs]

crossposted from https://groups.google.com/forum/#!topic/hystrixoss/tiJlm32RHTQ

[mattrjacobs]

Unit test that checks HystrixRequestLog directly after command timeout in a loop has not shown the error.

However, I did inadvertently see the same symptom by only waiting for 1 out of n HystrixCommands to error in a single request. That reproduced the symptom, as seen by the thread above.

[mattrjacobs]

I can't reproduce this, so marking as 'Invalid' until I/others have a reproducible case. If you can reproduce this, please re-open this issue or open a new one

[mattrjacobs]

From the Google Group thread referenced above:

It looks like this only happens when the sub-command throws HystrixBadRequestException. I was able to reproduce this consistently with a unit test consisting of 1 semaphore based command that executes two thread-based commands. The first sub-command succeeds, the second I force a HystrixBadRequestException to be thrown. The command log ends up looking like this.

TestCommand[Executed][31ms], TestCommand3[SUCCESS][16ms], TestCommand2[Executed][0ms]

Since HystrixEventType has a BAD_REQUEST value, I am expecting this...

TestCommand[BAD_REQUEST][31ms], TestCommand3[SUCCESS][16ms], TestCommand2[BAD_REQUEST][0ms]

I then tried just having a single command that throws a HystrixBadRequestException (i.e. got rid of the sub-commands in the test) and even when I just execute a single request it reports the status as Executed rather than BAD_REQUEST.

[mattrjacobs]

This turned out to not be due to a race condition at all - just that the HystrixRequestLog was not being updated upon BadRequestExceptions. This is now fixed in 1.4.x and master. I also added more strict testing of HystrixRequestLog contents, and only found this missing case. After this is released, I would not expect you to see this condition again.

Thanks for helping get to the root of it.