diff --git a/hystrix-core/src/main/java/com/netflix/hystrix/AbstractCommand.java b/hystrix-core/src/main/java/com/netflix/hystrix/AbstractCommand.java index 823e66a35..bb60837ee 100644 --- a/hystrix-core/src/main/java/com/netflix/hystrix/AbstractCommand.java +++ b/hystrix-core/src/main/java/com/netflix/hystrix/AbstractCommand.java @@ -551,20 +551,14 @@ public void call(Notification n) { } - }).lift(new HystrixObservableTimeoutOperator<>(_self)).map(new Func1() { - - boolean once = false; - + }).lift(new HystrixObservableTimeoutOperator<>(_self)).doOnNext(new Action1() { @Override - public R call(R t1) { - if (!once) { - // report success - executionResult = executionResult.addEvents(HystrixEventType.SUCCESS); - once = true; + public void call(R r) { + if (shouldOutputOnNextEvents()) { + executionResult = executionResult.addEmission(HystrixEventType.EMIT); + eventNotifier.markEvent(HystrixEventType.EMIT, getCommandKey()); } - return t1; } - }).doOnCompleted(new Action0() { @Override @@ -572,6 +566,7 @@ public void call() { long duration = System.currentTimeMillis() - invocationStartTime; metrics.addCommandExecutionTime(duration); metrics.markSuccess(duration); + executionResult = executionResult.addEvents(HystrixEventType.SUCCESS); circuitBreaker.markSuccess(); eventNotifier.markCommandExecution(getCommandKey(), properties.executionIsolationStrategy().get(), (int) duration, executionResult.events); } @@ -781,7 +776,15 @@ private Observable getFallbackOrThrowException(final HystrixEventType eventTy executionResult = executionResult.addEvents(eventType); final AbstractCommand _cmd = this; - return getFallbackWithProtection().doOnCompleted(new Action0() { + return getFallbackWithProtection().doOnNext(new Action1() { + @Override + public void call(R r) { + if (shouldOutputOnNextEvents()) { + executionResult = executionResult.addEmission(HystrixEventType.FALLBACK_EMIT); + eventNotifier.markEvent(HystrixEventType.FALLBACK_EMIT, getCommandKey()); + } + } + }).doOnCompleted(new Action0() { @Override public void call() { @@ -886,6 +889,16 @@ protected void handleThreadEnd() { } } + /** + * + * @return if onNext events should be reported on + * This affects {@link HystrixRequestLog}, and {@link HystrixEventNotifier} currently. + * Metrics/hooks will be affected once they are in place + */ + protected boolean shouldOutputOnNextEvents() { + return false; + } + private static class HystrixObservableTimeoutOperator implements Operator { final AbstractCommand originalCommand; @@ -1402,32 +1415,36 @@ protected static class ExecutionResult { private final int executionTime; private final Exception exception; private final long commandRunStartTimeInNanos; + private final int numEmissions; + private final int numFallbackEmissions; private ExecutionResult(HystrixEventType... events) { - this(Arrays.asList(events), -1, null); + this(Arrays.asList(events), -1, null, 0, 0); } public ExecutionResult setExecutionTime(int executionTime) { - return new ExecutionResult(events, executionTime, exception); + return new ExecutionResult(events, executionTime, exception, numEmissions, numFallbackEmissions); } public ExecutionResult setException(Exception e) { - return new ExecutionResult(events, executionTime, e); + return new ExecutionResult(events, executionTime, e, numEmissions, numFallbackEmissions); } - private ExecutionResult(List events, int executionTime, Exception e) { + private ExecutionResult(List events, int executionTime, Exception e, int numEmissions, int numFallbackEmissions) { // we are safe assigning the List reference instead of deep-copying // because we control the original list in 'newEvent' this.events = events; this.executionTime = executionTime; if (executionTime >= 0 ) { - this.commandRunStartTimeInNanos = System.nanoTime() - this.executionTime*1000*1000; // 1000*1000 will conver the milliseconds to nanoseconds + this.commandRunStartTimeInNanos = System.nanoTime() - this.executionTime*1000*1000; // 1000*1000 will convert the milliseconds to nanoseconds } else { this.commandRunStartTimeInNanos = -1; } this.exception = e; + this.numEmissions = numEmissions; + this.numFallbackEmissions = numFallbackEmissions; } // we can return a static version since it's immutable @@ -1440,10 +1457,14 @@ private ExecutionResult(List events, int executionTime, Except * @return */ public ExecutionResult addEvents(HystrixEventType... events) { - ArrayList newEvents = new ArrayList<>(); - newEvents.addAll(this.events); - Collections.addAll(newEvents, events); - return new ExecutionResult(Collections.unmodifiableList(newEvents), executionTime, exception); + return new ExecutionResult(getUpdatedList(this.events, events), executionTime, exception, numEmissions, numFallbackEmissions); + } + + private static List getUpdatedList(List currentList, HystrixEventType... newEvents) { + ArrayList updatedEvents = new ArrayList<>(); + updatedEvents.addAll(currentList); + Collections.addAll(updatedEvents, newEvents); + return Collections.unmodifiableList(updatedEvents); } public int getExecutionTime() { @@ -1456,6 +1477,28 @@ public int getExecutionTime() { public Exception getException() { return exception; } + + /** + * This method may be called many times for {@code HystrixEventType.EMIT} and {@link HystrixEventType.FALLBACK_EMIT}. + * To save on storage, on the first time we see that event type, it gets added to the event list, and the count gets incremented. + * @param eventType emission event + * @return "updated" {@link ExecutionResult} + */ + public ExecutionResult addEmission(HystrixEventType eventType) { + switch (eventType) { + case EMIT: if (events.contains(HystrixEventType.EMIT)) { + return new ExecutionResult(events, executionTime, exception, numEmissions + 1, numFallbackEmissions); + } else { + return new ExecutionResult(getUpdatedList(this.events, HystrixEventType.EMIT), executionTime, exception, numEmissions +1, numFallbackEmissions); + } + case FALLBACK_EMIT: if (events.contains(HystrixEventType.FALLBACK_EMIT)) { + return new ExecutionResult(events, executionTime, exception, numEmissions, numFallbackEmissions + 1); + } else { + return new ExecutionResult(getUpdatedList(this.events, HystrixEventType.FALLBACK_EMIT), executionTime, exception, numEmissions, numFallbackEmissions + 1); + } + default: return this; + } + } } /* ******************************************************************************** */ @@ -1610,6 +1653,24 @@ public List getExecutionEvents() { return executionResult.events; } + /** + * Number of emissions of the execution of a command. Only interesting in the streaming case. + * @return number of OnNext emissions by a streaming command + */ + @Override + public int getNumberEmissions() { + return executionResult.numEmissions; + } + + /** + * Number of emissions of the execution of a fallback. Only interesting in the streaming case. + * @return number of OnNext emissions by a streaming fallback + */ + @Override + public int getNumberFallbackEmissions() { + return executionResult.numFallbackEmissions; + } + /** * The execution time of this command instance in milliseconds, or -1 if not executed. * diff --git a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixEventType.java b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixEventType.java index 40a0f36ba..464fb1adc 100644 --- a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixEventType.java +++ b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixEventType.java @@ -21,5 +21,5 @@ * These are most often accessed via {@link HystrixRequestLog} or {@link HystrixCommand#getExecutionEvents()}. */ public enum HystrixEventType { - SUCCESS, FAILURE, TIMEOUT, SHORT_CIRCUITED, THREAD_POOL_REJECTED, SEMAPHORE_REJECTED, FALLBACK_SUCCESS, FALLBACK_FAILURE, FALLBACK_REJECTION, EXCEPTION_THROWN, RESPONSE_FROM_CACHE, COLLAPSED, BAD_REQUEST + EMIT, SUCCESS, FAILURE, TIMEOUT, SHORT_CIRCUITED, THREAD_POOL_REJECTED, SEMAPHORE_REJECTED, FALLBACK_EMIT, FALLBACK_SUCCESS, FALLBACK_FAILURE, FALLBACK_REJECTION, EXCEPTION_THROWN, RESPONSE_FROM_CACHE, COLLAPSED, BAD_REQUEST } \ No newline at end of file diff --git a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixInvokableInfo.java b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixInvokableInfo.java index 99c08f339..9a990925c 100644 --- a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixInvokableInfo.java +++ b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixInvokableInfo.java @@ -53,6 +53,10 @@ public interface HystrixInvokableInfo { public List getExecutionEvents(); + public int getNumberEmissions(); + + public int getNumberFallbackEmissions(); + public int getExecutionTimeInMilliseconds(); public long getCommandRunStartTimeInNanos(); diff --git a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixObservableCommand.java b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixObservableCommand.java index 141ab7df7..0c944547b 100644 --- a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixObservableCommand.java +++ b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixObservableCommand.java @@ -20,6 +20,7 @@ import com.netflix.hystrix.HystrixCommandProperties.ExecutionIsolationStrategy; import com.netflix.hystrix.strategy.executionhook.HystrixCommandExecutionHook; import com.netflix.hystrix.strategy.properties.HystrixPropertiesStrategy; +import com.netflix.hystrix.strategy.eventnotifier.HystrixEventNotifier; /** * Used to wrap code that will execute potentially risky functionality (typically meaning a service call over the network) @@ -49,6 +50,18 @@ protected HystrixObservableCommand(HystrixCommandGroupKey group) { this(new Setter(group)); } + /** + * + * Overridden to true so that all onNext emissions are captured + * + * @return if onNext events should be reported on + * This affects {@link HystrixRequestLog}, and {@link HystrixEventNotifier} currently. Metrics/Hooks later + */ + @Override + protected boolean shouldOutputOnNextEvents() { + return true; + } + /** * Construct a {@link HystrixObservableCommand} with defined {@link Setter} that allows injecting property and strategy overrides and other optional arguments. *

diff --git a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixRequestLog.java b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixRequestLog.java index 24c56a35b..6fc547130 100644 --- a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixRequestLog.java +++ b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixRequestLog.java @@ -150,16 +150,24 @@ public Collection> getAllExecutedCommands() { *

  • TestCommand[FAILURE][1ms]
    • *
  • TestCommand[THREAD_POOL_REJECTED][1ms]
    • *
  • TestCommand[THREAD_POOL_REJECTED, FALLBACK_SUCCESS][1ms]
    • + *
  • TestCommand[EMIT, SUCCESS][1ms]
    • + *
  • TestCommand[EMITx5, SUCCESS][1ms]
    • + *
  • TestCommand[EMITx5, FAILURE, FALLBACK_EMITx6, FALLBACK_FAILURE][100ms]
    • *
  • TestCommand[FAILURE, FALLBACK_SUCCESS][1ms], TestCommand[FAILURE, FALLBACK_SUCCESS, RESPONSE_FROM_CACHE][1ms]x4
    • *
  • GetData[SUCCESS][1ms], PutData[SUCCESS][1ms], GetValues[SUCCESS][1ms], GetValues[SUCCESS, RESPONSE_FROM_CACHE][1ms], TestCommand[FAILURE, FALLBACK_FAILURE][1ms], TestCommand[FAILURE, * FALLBACK_FAILURE, RESPONSE_FROM_CACHE][1ms]
    • * *

    - * If a command has a multiplier such as x4 that means this command was executed 4 times with the same events. The time in milliseconds is the sum of the 4 executions. + * If a command has a multiplier such as x4, that means this command was executed 4 times with the same events. The time in milliseconds is the sum of the 4 executions. *

    * For example, TestCommand[SUCCESS][15ms]x4 represents TestCommand being executed 4 times and the sum of those 4 executions was 15ms. These 4 each executed the run() method since * RESPONSE_FROM_CACHE was not present as an event. - * + * + * If an EMIT or FALLBACK_EMIT has a multiplier such as x5, that means a HystrixObservableCommand was used and it emitted that number of OnNexts. + *

    + * For example, TestCommand[EMITx5, FAILURE, FALLBACK_EMITx6, FALLBACK_FAILURE][100ms] represents TestCommand executing observably, emitted 5 OnNexts, then an OnError. + * This command also has an Observable fallback, and it emits 6 OnNexts, then an OnCompleted. + * * @return String request log or "Unknown" if unable to instead of throwing an exception. */ public String getExecutedCommandsAsString() { @@ -179,7 +187,26 @@ public String getExecutedCommandsAsString() { //replicate functionality of Arrays.toString(events.toArray()) to append directly to existing StringBuilder builder.append("["); for (HystrixEventType event : events) { - builder.append(event).append(", "); + switch (event) { + case EMIT: + int numEmissions = command.getNumberEmissions(); + if (numEmissions > 1) { + builder.append(event).append("x").append(numEmissions).append(", "); + } else { + builder.append(event).append(", "); + } + break; + case FALLBACK_EMIT: + int numFallbackEmissions = command.getNumberFallbackEmissions(); + if (numFallbackEmissions > 1) { + builder.append(event).append("x").append(numFallbackEmissions).append(", "); + } else { + builder.append(event).append(", "); + } + break; + default: + builder.append(event).append(", "); + } } builder.setCharAt(builder.length() - 2, ']'); builder.setLength(builder.length() - 1); diff --git a/hystrix-core/src/test/java/com/netflix/hystrix/HystrixObservableCommandTest.java b/hystrix-core/src/test/java/com/netflix/hystrix/HystrixObservableCommandTest.java index 4ff8a9ccf..5fdbfed01 100644 --- a/hystrix-core/src/test/java/com/netflix/hystrix/HystrixObservableCommandTest.java +++ b/hystrix-core/src/test/java/com/netflix/hystrix/HystrixObservableCommandTest.java @@ -121,7 +121,7 @@ public void call(Subscriber sub) { * Test a successful semaphore-isolated command execution. */ @Test - public void testSempahoreIsolatedObserveSuccess() { + public void testSemaphoreIsolatedObserveSuccess() { try { TestHystrixCommand command = new SuccessfulTestCommand(); assertEquals(0, command.builder.metrics.getRollingCount(HystrixRollingNumberEvent.FAILURE)); @@ -150,6 +150,9 @@ public void testSempahoreIsolatedObserveSuccess() { assertEquals(0, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + assertEquals(2, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.EMIT)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.SUCCESS)); // semaphore isolated assertFalse(command.isExecutedInThread()); @@ -192,6 +195,9 @@ public void testThreadIsolatedObserveSuccess() { assertEquals(0, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + assertEquals(2, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.EMIT)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.SUCCESS)); // thread isolated assertTrue(command.isExecutedInThread()); @@ -206,7 +212,7 @@ public void testThreadIsolatedObserveSuccess() { * Test that a command can not be executed multiple times. */ @Test - public void testSempahoreIsolatedObserveMultipleTimes() { + public void testSemaphoreIsolatedObserveMultipleTimes() { SuccessfulTestCommand command = new SuccessfulTestCommand(); assertFalse(command.isExecutionComplete()); // first should succeed @@ -238,6 +244,9 @@ public void testSempahoreIsolatedObserveMultipleTimes() { // semaphore isolated assertFalse(command.isExecutedInThread()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + assertEquals(2, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.EMIT)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.SUCCESS)); } /** @@ -281,6 +290,8 @@ public void testSemaphoreIsolatedObserveKnownFailureWithNoFallback() { assertEquals(100, circuitBreaker.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + assertEquals(1, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FAILURE)); // semaphore isolated assertFalse(command.isExecutedInThread()); @@ -324,6 +335,8 @@ public void testSemaphoreIsolatedObserveUnknownFailureWithNoFallback() { assertEquals(100, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + assertEquals(1, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FAILURE)); // semaphore isolated assertFalse(command.isExecutedInThread()); @@ -333,7 +346,7 @@ public void testSemaphoreIsolatedObserveUnknownFailureWithNoFallback() { * Test a command execution that fails but has a fallback. */ @Test - public void tesSemaphoreIsolatedtObserveFailureWithFallback() { + public void tesSemaphoreIsolatedObserveFailureWithFallback() { TestHystrixCommand command = new KnownFailureTestCommandWithFallback(new TestCircuitBreaker()); try { assertEquals(false, command.observe().toBlocking().single()); @@ -363,6 +376,10 @@ public void tesSemaphoreIsolatedtObserveFailureWithFallback() { assertEquals(100, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + assertEquals(3, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FAILURE)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_EMIT)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_SUCCESS)); // semaphore isolated assertFalse(command.isExecutedInThread()); @@ -402,6 +419,10 @@ public void testThreadIsolatedObserveFailureWithFallback() { assertEquals(100, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + assertEquals(3, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FAILURE)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_EMIT)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_SUCCESS)); // thread isolated assertTrue(command.isExecutedInThread()); @@ -442,6 +463,9 @@ public void testSemaphoreIsolatedObserveFailureWithFallbackFailure() { assertEquals(100, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + assertEquals(2, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FAILURE)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_FAILURE)); // semaphore isolated assertFalse(command.isExecutedInThread()); @@ -481,6 +505,9 @@ public void testThreadIsolatedObserveFailureWithFailingFallback() { assertEquals(100, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + assertEquals(2, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FAILURE)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_FAILURE)); // thread isolated assertTrue(command.isExecutedInThread()); @@ -520,6 +547,8 @@ public void testThreadIsolatedObserveFailureWithNoFallback() { assertEquals(100, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + assertEquals(1, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FAILURE)); // thread isolated assertTrue(command.isExecutedInThread()); @@ -559,13 +588,17 @@ public void testSemaphoreIsolatedObserveFailureWithTimeoutAndFallback() { assertEquals(100, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + assertEquals(3, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.TIMEOUT)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_EMIT)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_SUCCESS)); // semaphore isolated assertFalse(command.isExecutedInThread()); } /** - * Test a command execution that fails with no fallback. + * Test a command execution that times out and performs a fallback */ @Test public void testThreadIsolatedObserveFailureWithTimeoutAndFallback() { @@ -598,6 +631,10 @@ public void testThreadIsolatedObserveFailureWithTimeoutAndFallback() { assertEquals(100, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + assertEquals(3, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.TIMEOUT)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_EMIT)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_SUCCESS)); // thread isolated assertTrue(command.isExecutedInThread()); @@ -1901,14 +1938,16 @@ public void testRequestCache1UsingThreadIsolation() { // the second one should not have executed as it should have received the cached value instead assertFalse(command2.executed); - // the execution log for command1 should show a SUCCESS - assertEquals(1, command1.getExecutionEvents().size()); + // the execution log for command1 should show an EMIT and a SUCCESS + assertEquals(2, command1.getExecutionEvents().size()); + assertTrue(command1.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command1.getExecutionEvents().contains(HystrixEventType.SUCCESS)); assertTrue(command1.getExecutionTimeInMilliseconds() > -1); assertFalse(command1.isResponseFromCache()); // the execution log for command2 should show it came from cache - assertEquals(2, command2.getExecutionEvents().size()); // it will include the SUCCESS + RESPONSE_FROM_CACHE + assertEquals(3, command2.getExecutionEvents().size()); // it will include the EMIT + SUCCESS + RESPONSE_FROM_CACHE + assertTrue(command2.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command2.getExecutionEvents().contains(HystrixEventType.SUCCESS)); assertTrue(command2.getExecutionEvents().contains(HystrixEventType.RESPONSE_FROM_CACHE)); assertTrue(command2.getExecutionTimeInMilliseconds() == -1); @@ -1956,12 +1995,14 @@ public void testRequestCache2UsingThreadIsolation() { // both should execute as they are different assertTrue(command2.executed); - // the execution log for command1 should show a SUCCESS - assertEquals(1, command1.getExecutionEvents().size()); + // the execution log for command1 should show an EMIT and a SUCCESS + assertEquals(2, command1.getExecutionEvents().size()); + assertTrue(command1.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command1.getExecutionEvents().contains(HystrixEventType.SUCCESS)); - // the execution log for command2 should show a SUCCESS - assertEquals(1, command2.getExecutionEvents().size()); + // the execution log for command2 should show an EMIT and a SUCCESS + assertEquals(2, command2.getExecutionEvents().size()); + assertTrue(command2.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command2.getExecutionEvents().contains(HystrixEventType.SUCCESS)); assertTrue(command2.getExecutionTimeInMilliseconds() > -1); assertFalse(command2.isResponseFromCache()); @@ -2013,16 +2054,19 @@ public void testRequestCache3UsingThreadIsolation() { // but the 3rd should come from cache assertFalse(command3.executed); - // the execution log for command1 should show a SUCCESS - assertEquals(1, command1.getExecutionEvents().size()); + // the execution log for command1 should show an EMIT and a SUCCESS + assertEquals(2, command1.getExecutionEvents().size()); + assertTrue(command1.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command1.getExecutionEvents().contains(HystrixEventType.SUCCESS)); - // the execution log for command2 should show a SUCCESS - assertEquals(1, command2.getExecutionEvents().size()); + // the execution log for command2 should show an EMIT and a SUCCESS + assertEquals(2, command2.getExecutionEvents().size()); + assertTrue(command2.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command2.getExecutionEvents().contains(HystrixEventType.SUCCESS)); // the execution log for command3 should show it came from cache - assertEquals(2, command3.getExecutionEvents().size()); // it will include the SUCCESS + RESPONSE_FROM_CACHE + assertEquals(3, command3.getExecutionEvents().size()); // it will include the EMIT + SUCCESS + RESPONSE_FROM_CACHE + assertTrue(command3.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command3.getExecutionEvents().contains(HystrixEventType.SUCCESS)); assertTrue(command3.getExecutionEvents().contains(HystrixEventType.RESPONSE_FROM_CACHE)); assertTrue(command3.getExecutionTimeInMilliseconds() == -1); @@ -2078,14 +2122,16 @@ public void testRequestCacheWithSlowExecution() { assertFalse(command3.executed); assertFalse(command4.executed); - // the execution log for command1 should show a SUCCESS - assertEquals(1, command1.getExecutionEvents().size()); + // the execution log for command1 should show an EMIT and a SUCCESS + assertEquals(2, command1.getExecutionEvents().size()); + assertTrue(command1.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command1.getExecutionEvents().contains(HystrixEventType.SUCCESS)); assertTrue(command1.getExecutionTimeInMilliseconds() > -1); assertFalse(command1.isResponseFromCache()); // the execution log for command2 should show it came from cache - assertEquals(2, command2.getExecutionEvents().size()); // it will include the SUCCESS + RESPONSE_FROM_CACHE + assertEquals(3, command2.getExecutionEvents().size()); // it will include the EMIT + SUCCESS + RESPONSE_FROM_CACHE + assertTrue(command2.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command2.getExecutionEvents().contains(HystrixEventType.SUCCESS)); assertTrue(command2.getExecutionEvents().contains(HystrixEventType.RESPONSE_FROM_CACHE)); assertTrue(command2.getExecutionTimeInMilliseconds() == -1); @@ -2149,16 +2195,19 @@ public void testNoRequestCache3UsingThreadIsolation() { // this should also execute since we disabled the cache assertTrue(command3.executed); - // the execution log for command1 should show a SUCCESS - assertEquals(1, command1.getExecutionEvents().size()); + // the execution log for command1 should show an EMIT and a SUCCESS + assertEquals(2, command1.getExecutionEvents().size()); + assertTrue(command1.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command1.getExecutionEvents().contains(HystrixEventType.SUCCESS)); - // the execution log for command2 should show a SUCCESS - assertEquals(1, command2.getExecutionEvents().size()); + // the execution log for command2 should show an EMIT and a SUCCESS + assertEquals(2, command2.getExecutionEvents().size()); + assertTrue(command2.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command2.getExecutionEvents().contains(HystrixEventType.SUCCESS)); - // the execution log for command3 should show a SUCCESS - assertEquals(1, command3.getExecutionEvents().size()); + // the execution log for command3 should show an EMIT and a SUCCESS + assertEquals(2, command3.getExecutionEvents().size()); + assertTrue(command3.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command3.getExecutionEvents().contains(HystrixEventType.SUCCESS)); assertEquals(3, circuitBreaker.metrics.getRollingCount(HystrixRollingNumberEvent.SUCCESS)); @@ -2213,16 +2262,20 @@ public void testRequestCacheViaQueueUsingSemaphoreIsolation() { // but the 3rd should come from cache assertFalse(command3.executed); - // the execution log for command1 should show a SUCCESS - assertEquals(1, command1.getExecutionEvents().size()); + // the execution log for command1 should show an EMIT and a SUCCESS + assertEquals(2, command1.getExecutionEvents().size()); + assertTrue(command1.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command1.getExecutionEvents().contains(HystrixEventType.SUCCESS)); - // the execution log for command2 should show a SUCCESS - assertEquals(1, command2.getExecutionEvents().size()); + + // the execution log for command2 should show an EMIT and a SUCCESS + assertEquals(2, command2.getExecutionEvents().size()); + assertTrue(command2.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command2.getExecutionEvents().contains(HystrixEventType.SUCCESS)); // the execution log for command3 should show it comes from cache - assertEquals(2, command3.getExecutionEvents().size()); // it will include the SUCCESS + RESPONSE_FROM_CACHE + assertEquals(3, command3.getExecutionEvents().size()); // it will include the EMIT + SUCCESS + RESPONSE_FROM_CACHE + assertTrue(command3.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command3.getExecutionEvents().contains(HystrixEventType.SUCCESS)); assertTrue(command3.getExecutionEvents().contains(HystrixEventType.RESPONSE_FROM_CACHE)); @@ -2281,16 +2334,19 @@ public void testNoRequestCacheViaQueueUsingSemaphoreIsolation() { // this should also execute because caching is disabled assertTrue(command3.executed); - // the execution log for command1 should show a SUCCESS - assertEquals(1, command1.getExecutionEvents().size()); + // the execution log for command1 should show an EMIT and a SUCCESS + assertEquals(2, command1.getExecutionEvents().size()); + assertTrue(command1.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command1.getExecutionEvents().contains(HystrixEventType.SUCCESS)); - // the execution log for command2 should show a SUCCESS - assertEquals(1, command2.getExecutionEvents().size()); + // the execution log for command2 should show an EMIT and a SUCCESS + assertEquals(2, command2.getExecutionEvents().size()); + assertTrue(command2.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command2.getExecutionEvents().contains(HystrixEventType.SUCCESS)); - // the execution log for command3 should show a SUCCESS - assertEquals(1, command3.getExecutionEvents().size()); + // the execution log for command3 should show an EMIT and a SUCCESS + assertEquals(2, command3.getExecutionEvents().size()); + assertTrue(command3.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command3.getExecutionEvents().contains(HystrixEventType.SUCCESS)); assertEquals(3, circuitBreaker.metrics.getRollingCount(HystrixRollingNumberEvent.SUCCESS)); @@ -2341,16 +2397,18 @@ public void testRequestCacheViaExecuteUsingSemaphoreIsolation() { // but the 3rd should come from cache assertFalse(command3.executed); - // the execution log for command1 should show a SUCCESS - assertEquals(1, command1.getExecutionEvents().size()); + // the execution log for command1 should show an EMIT and a SUCCESS + assertEquals(2, command1.getExecutionEvents().size()); + assertTrue(command1.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command1.getExecutionEvents().contains(HystrixEventType.SUCCESS)); - // the execution log for command2 should show a SUCCESS - assertEquals(1, command2.getExecutionEvents().size()); + // the execution log for command2 should show an EMIT and a SUCCESS + assertEquals(2, command2.getExecutionEvents().size()); + assertTrue(command2.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command2.getExecutionEvents().contains(HystrixEventType.SUCCESS)); // the execution log for command3 should show it comes from cache - assertEquals(2, command3.getExecutionEvents().size()); // it will include the SUCCESS + RESPONSE_FROM_CACHE + assertEquals(3, command3.getExecutionEvents().size()); // it will include the EMIT + SUCCESS + RESPONSE_FROM_CACHE assertTrue(command3.getExecutionEvents().contains(HystrixEventType.RESPONSE_FROM_CACHE)); assertEquals(2, circuitBreaker.metrics.getRollingCount(HystrixRollingNumberEvent.SUCCESS)); @@ -2401,16 +2459,19 @@ public void testNoRequestCacheViaExecuteUsingSemaphoreIsolation() { // this should also execute because caching is disabled assertTrue(command3.executed); - // the execution log for command1 should show a SUCCESS - assertEquals(1, command1.getExecutionEvents().size()); + // the execution log for command1 should show an EMIT and a SUCCESS + assertEquals(2, command1.getExecutionEvents().size()); + assertTrue(command1.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command1.getExecutionEvents().contains(HystrixEventType.SUCCESS)); - // the execution log for command2 should show a SUCCESS - assertEquals(1, command2.getExecutionEvents().size()); + // the execution log for command2 should show an EMIT and a SUCCESS + assertEquals(2, command2.getExecutionEvents().size()); + assertTrue(command2.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command2.getExecutionEvents().contains(HystrixEventType.SUCCESS)); - // the execution log for command3 should show a SUCCESS - assertEquals(1, command3.getExecutionEvents().size()); + // the execution log for command3 should show an EMIT and a SUCCESS + assertEquals(2, command3.getExecutionEvents().size()); + assertTrue(command3.getExecutionEvents().contains(HystrixEventType.EMIT)); assertTrue(command3.getExecutionEvents().contains(HystrixEventType.SUCCESS)); assertEquals(3, circuitBreaker.metrics.getRollingCount(HystrixRollingNumberEvent.SUCCESS)); @@ -2539,16 +2600,16 @@ public void testRequestCacheOnTimeoutCausesNullPointerException() throws Excepti HystrixObservableCommand[] executeCommands = HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().toArray(new HystrixObservableCommand[] {}); - System.out.println(":executeCommands[0].getExecutionEvents()" + executeCommands[0].getExecutionEvents()); - assertEquals(2, executeCommands[0].getExecutionEvents().size()); + assertEquals(3, executeCommands[0].getExecutionEvents().size()); assertTrue(executeCommands[0].getExecutionEvents().contains(HystrixEventType.FALLBACK_SUCCESS)); + assertTrue(executeCommands[0].getExecutionEvents().contains(HystrixEventType.FALLBACK_EMIT)); assertTrue(executeCommands[0].getExecutionEvents().contains(HystrixEventType.TIMEOUT)); assertTrue(executeCommands[0].getExecutionTimeInMilliseconds() > -1); assertTrue(executeCommands[0].isResponseTimedOut()); assertTrue(executeCommands[0].isResponseFromFallback()); assertFalse(executeCommands[0].isResponseFromCache()); - assertEquals(3, executeCommands[1].getExecutionEvents().size()); // it will include FALLBACK_SUCCESS/TIMEOUT + RESPONSE_FROM_CACHE + assertEquals(4, executeCommands[1].getExecutionEvents().size()); // it will include FALLBACK_SUCCESS/TIMEOUT + RESPONSE_FROM_CACHE assertTrue(executeCommands[1].getExecutionEvents().contains(HystrixEventType.RESPONSE_FROM_CACHE)); assertTrue(executeCommands[1].getExecutionTimeInMilliseconds() == -1); assertTrue(executeCommands[1].isResponseFromCache()); @@ -2556,7 +2617,6 @@ public void testRequestCacheOnTimeoutCausesNullPointerException() throws Excepti assertTrue(executeCommands[1].isResponseFromFallback()); } - // @Test public void testRequestCacheOnTimeoutThrowsException() throws Exception { TestCircuitBreaker circuitBreaker = new TestCircuitBreaker(); @@ -6655,6 +6715,12 @@ public void testExecutionSuccessWithMultipleEvents() { assertEquals(0, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + System.out.println("REQ LOG : " + HystrixRequestLog.getCurrentRequest().getExecutedCommandsAsString()); + assertEquals(2, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.EMIT)); + assertEquals(3, command.getNumberEmissions()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.SUCCESS)); + assertEquals(0, command.getNumberFallbackEmissions()); // semaphore isolated assertFalse(command.isExecutedInThread()); @@ -6684,15 +6750,13 @@ public void testExecutionPartialSuccess() { assertEquals(0, command.builder.metrics.getRollingCount(HystrixRollingNumberEvent.TIMEOUT)); assertEquals(0, command.builder.metrics.getRollingCount(HystrixRollingNumberEvent.SUCCESS)); - // but it will say it is both SUCCESSful and FAILED - assertTrue(command.isSuccessfulExecution()); + assertFalse(command.isSuccessfulExecution()); assertTrue(command.isFailedExecution()); // we will have an exception assertNotNull(command.getFailedExecutionException()); assertTrue(command.getExecutionTimeInMilliseconds() > -1); - assertTrue(command.isSuccessfulExecution()); assertEquals(1, command.builder.metrics.getRollingCount(HystrixRollingNumberEvent.EXCEPTION_THROWN)); assertEquals(0, command.builder.metrics.getRollingCount(HystrixRollingNumberEvent.FALLBACK_REJECTION)); @@ -6706,6 +6770,13 @@ public void testExecutionPartialSuccess() { assertEquals(100, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + System.out.println("REQ LOG : " + HystrixRequestLog.getCurrentRequest().getExecutedCommandsAsString()); + assertEquals(2, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.EMIT)); + assertEquals(3, command.getNumberEmissions()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FAILURE)); + assertEquals(0, command.getNumberFallbackEmissions()); + // semaphore isolated assertFalse(command.isExecutedInThread()); @@ -6735,14 +6806,12 @@ public void testExecutionPartialSuccessWithFallback() { assertEquals(0, command.builder.metrics.getRollingCount(HystrixRollingNumberEvent.TIMEOUT)); assertEquals(0, command.builder.metrics.getRollingCount(HystrixRollingNumberEvent.SUCCESS)); - // but it will say it is both SUCCESSful and FAILED - assertTrue(command.isSuccessfulExecution()); + assertFalse(command.isSuccessfulExecution()); assertTrue(command.isFailedExecution()); assertNotNull(command.getFailedExecutionException()); assertTrue(command.getExecutionTimeInMilliseconds() > -1); - assertTrue(command.isSuccessfulExecution()); assertEquals(0, command.builder.metrics.getRollingCount(HystrixRollingNumberEvent.EXCEPTION_THROWN)); assertEquals(0, command.builder.metrics.getRollingCount(HystrixRollingNumberEvent.FALLBACK_REJECTION)); @@ -6756,6 +6825,14 @@ public void testExecutionPartialSuccessWithFallback() { assertEquals(100, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + System.out.println("REQ LOG : " + HystrixRequestLog.getCurrentRequest().getExecutedCommandsAsString()); + assertEquals(4, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.EMIT)); + assertEquals(3, command.getNumberEmissions()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FAILURE)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_EMIT)); + assertEquals(4, command.getNumberFallbackEmissions()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_SUCCESS)); // semaphore isolated assertFalse(command.isExecutedInThread()); @@ -6785,14 +6862,12 @@ public void testExecutionPartialSuccessWithMoreIntelligentFallback() { assertEquals(0, command.builder.metrics.getRollingCount(HystrixRollingNumberEvent.TIMEOUT)); assertEquals(0, command.builder.metrics.getRollingCount(HystrixRollingNumberEvent.SUCCESS)); - // but it will say it is both SUCCESSful and FAILED - assertTrue(command.isSuccessfulExecution()); + assertFalse(command.isSuccessfulExecution()); assertTrue(command.isFailedExecution()); assertNotNull(command.getFailedExecutionException()); assertTrue(command.getExecutionTimeInMilliseconds() > -1); - assertTrue(command.isSuccessfulExecution()); assertEquals(0, command.builder.metrics.getRollingCount(HystrixRollingNumberEvent.EXCEPTION_THROWN)); assertEquals(0, command.builder.metrics.getRollingCount(HystrixRollingNumberEvent.FALLBACK_REJECTION)); @@ -6806,6 +6881,15 @@ public void testExecutionPartialSuccessWithMoreIntelligentFallback() { assertEquals(100, command.builder.metrics.getHealthCounts().getErrorPercentage()); assertEquals(1, HystrixRequestLog.getCurrentRequest().getAllExecutedCommands().size()); + System.out.println("REQ LOG : " + HystrixRequestLog.getCurrentRequest().getExecutedCommandsAsString()); + assertEquals(4, command.getExecutionEvents().size()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.EMIT)); + assertEquals(3, command.getNumberEmissions()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FAILURE)); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_EMIT)); + assertEquals(1, command.getNumberFallbackEmissions()); + assertTrue(command.getExecutionEvents().contains(HystrixEventType.FALLBACK_SUCCESS)); + // semaphore isolated assertFalse(command.isExecutedInThread());