From 890357f92fe9b8a1444d7280d30f08b8b1c11539 Mon Sep 17 00:00:00 2001 From: Sergey Krutsko Date: Mon, 20 Oct 2014 14:47:17 +0300 Subject: [PATCH 1/3] Hook execution sequence issue --- .../src/main/java/com/netflix/hystrix/HystrixCommand.java | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixCommand.java b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixCommand.java index c12754d87..5a723228c 100755 --- a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixCommand.java +++ b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixCommand.java @@ -1976,6 +1976,10 @@ public void cleanup() { ConfigurationManager.getConfigInstance().clear(); } + private static void recordHookCall(StringBuilder sequenceRecorder, String methodName) { + sequenceRecorder.append(methodName).append(" - "); + } + /** * Test a successful command execution. */ From a6bb9fbf7e4019124f526bcb3a6b37201a3896ee Mon Sep 17 00:00:00 2001 From: Sergey Krutsko Date: Mon, 20 Oct 2014 15:02:30 +0300 Subject: [PATCH 2/3] Unit tests to reproduce Hook execution sequence issue. --- .../com/netflix/hystrix/HystrixCommand.java | 66 +++++++++++++++++++ 1 file changed, 66 insertions(+) diff --git a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixCommand.java b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixCommand.java index 5a723228c..45229a11a 100755 --- a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixCommand.java +++ b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixCommand.java @@ -5345,6 +5345,9 @@ public void testExecutionHookSuccessfulCommand() { assertEquals(1, command.builder.executionHook.threadStart.get()); assertEquals(1, command.builder.executionHook.threadComplete.get()); + // expected hook execution sequence + assertEquals("onStart - onThreadStart - onRunStart - onRunSuccess - onThreadComplete - onComplete - ", command.builder.executionHook.executionSequence.toString()); + /* test with queue() */ command = new SuccessfulTestCommand(); try { @@ -5377,6 +5380,9 @@ public void testExecutionHookSuccessfulCommand() { // thread execution assertEquals(1, command.builder.executionHook.threadStart.get()); assertEquals(1, command.builder.executionHook.threadComplete.get()); + + // expected hook execution sequence + assertEquals("onStart - onThreadStart - onRunStart - onRunSuccess - onThreadComplete - onComplete - ", command.builder.executionHook.executionSequence.toString()); } /** @@ -5429,6 +5435,9 @@ public void testExecutionHookSuccessfulCommandViaFireAndForget() { // thread execution assertEquals(1, command.builder.executionHook.threadStart.get()); assertEquals(1, command.builder.executionHook.threadComplete.get()); + + // expected hook execution sequence + assertEquals("onStart - onThreadStart - onRunStart - onRunSuccess - onThreadComplete - onComplete - ", command.builder.executionHook.executionSequence.toString()); } /** @@ -5475,6 +5484,9 @@ public void testExecutionHookSuccessfulCommandWithMultipleGetsOnFuture() { // thread execution assertEquals(1, command.builder.executionHook.threadStart.get()); assertEquals(1, command.builder.executionHook.threadComplete.get()); + + // expected hook execution sequence + assertEquals("onStart - onThreadStart - onRunStart - onRunSuccess - onThreadComplete - onComplete - ", command.builder.executionHook.executionSequence.toString()); } /** @@ -5518,6 +5530,9 @@ public void testExecutionHookRunFailureWithoutFallback() { assertEquals(1, command.builder.executionHook.threadStart.get()); assertEquals(1, command.builder.executionHook.threadComplete.get()); + // expected hook execution sequence + assertEquals("onStart - onThreadStart - onRunStart - onRunError - onFallbackStart - onFallbackError - onError - onThreadComplete - onComplete - ", command.builder.executionHook.executionSequence.toString()); + /* test with queue() */ command = new UnknownFailureTestCommandWithoutFallback(); try { @@ -5554,6 +5569,9 @@ public void testExecutionHookRunFailureWithoutFallback() { assertEquals(1, command.builder.executionHook.threadStart.get()); assertEquals(1, command.builder.executionHook.threadComplete.get()); + // expected hook execution sequence + assertEquals("onStart - onThreadStart - onRunStart - onRunError - onFallbackStart - onFallbackError - onError - onThreadComplete - onComplete - ", command.builder.executionHook.executionSequence.toString()); + } /** @@ -5590,6 +5608,9 @@ public void testExecutionHookRunFailureWithFallback() { assertEquals(1, command.builder.executionHook.threadStart.get()); assertEquals(1, command.builder.executionHook.threadComplete.get()); + // expected hook execution sequence + assertEquals("onStart - onThreadStart - onRunStart - onRunError - onFallbackStart - onFallbackSuccess - onThreadComplete - onComplete - ", command.builder.executionHook.executionSequence.toString()); + /* test with queue() */ command = new KnownFailureTestCommandWithFallback(new TestCircuitBreaker()); try { @@ -5622,6 +5643,9 @@ public void testExecutionHookRunFailureWithFallback() { // thread execution assertEquals(1, command.builder.executionHook.threadStart.get()); assertEquals(1, command.builder.executionHook.threadComplete.get()); + + // expected hook execution sequence + assertEquals("onStart - onThreadStart - onRunStart - onRunError - onFallbackStart - onFallbackSuccess - onThreadComplete - onComplete - ", command.builder.executionHook.executionSequence.toString()); } /** @@ -5665,6 +5689,9 @@ public void testExecutionHookRunFailureWithFallbackFailure() { assertEquals(1, command.builder.executionHook.threadStart.get()); assertEquals(1, command.builder.executionHook.threadComplete.get()); + // expected hook execution sequence + assertEquals("onStart - onThreadStart - onRunStart - onRunError - onFallbackStart - onFallbackError - onError - onThreadComplete - onComplete - ", command.builder.executionHook.executionSequence.toString()); + /* test with queue() */ command = new KnownFailureTestCommandWithFallbackFailure(); try { @@ -5700,6 +5727,9 @@ public void testExecutionHookRunFailureWithFallbackFailure() { // thread execution assertEquals(1, command.builder.executionHook.threadStart.get()); assertEquals(1, command.builder.executionHook.threadComplete.get()); + + // expected hook execution sequence + assertEquals("onStart - onThreadStart - onRunStart - onRunError - onFallbackStart - onFallbackError - onError - onThreadComplete - onComplete - ", command.builder.executionHook.executionSequence.toString()); } /** @@ -5748,6 +5778,9 @@ public void testExecutionHookTimeoutWithoutFallback() { // ignore } assertEquals(1, command.builder.executionHook.threadComplete.get()); + + // expected hook execution sequence + assertEquals("onStart - onThreadStart - onRunStart - onFallbackStart - onFallbackError - onError - onRunSuccess - onThreadComplete - onComplete - ", command.builder.executionHook.executionSequence.toString()); } /** @@ -5793,6 +5826,9 @@ public void testExecutionHookTimeoutWithFallback() { // ignore } assertEquals(1, command.builder.executionHook.threadComplete.get()); + + // expected hook execution sequence + assertEquals("onStart - onThreadStart - onRunStart - onFallbackStart - onFallbackSuccess - onRunSuccess - onThreadComplete - onComplete - ", command.builder.executionHook.executionSequence.toString()); } /** @@ -5845,6 +5881,9 @@ public void testExecutionHookRejectedWithFallback() { // thread execution assertEquals(0, command.builder.executionHook.threadStart.get()); assertEquals(0, command.builder.executionHook.threadComplete.get()); + + // expected hook execution sequence + assertEquals("onStart - onFallbackStart - onFallbackSuccess - onComplete - ", command.builder.executionHook.executionSequence.toString()); } /** @@ -5890,6 +5929,9 @@ public void testExecutionHookShortCircuitedWithFallbackViaQueue() { // thread execution assertEquals(0, command.builder.executionHook.threadStart.get()); assertEquals(0, command.builder.executionHook.threadComplete.get()); + + // expected hook execution sequence + assertEquals("onStart - onFallbackStart - onFallbackError - onError - onComplete - ", command.builder.executionHook.executionSequence.toString()); } /** @@ -5935,6 +5977,9 @@ public void testExecutionHookShortCircuitedWithFallbackViaExecute() { // thread execution assertEquals(0, command.builder.executionHook.threadStart.get()); assertEquals(0, command.builder.executionHook.threadComplete.get()); + + // expected hook execution sequence + assertEquals("onStart - onFallbackStart - onFallbackError - onError - onComplete - ", command.builder.executionHook.executionSequence.toString()); } /** @@ -5973,6 +6018,9 @@ public void testExecutionHookSuccessfulCommandWithSemaphoreIsolation() { assertEquals(0, command.builder.executionHook.threadStart.get()); assertEquals(0, command.builder.executionHook.threadComplete.get()); + // expected hook execution sequence + assertEquals("onStart - onRunStart - onRunSuccess - onComplete - ", command.builder.executionHook.executionSequence.toString()); + /* test with queue() */ command = new TestSemaphoreCommand(new TestCircuitBreaker(), 1, 10); try { @@ -6007,6 +6055,9 @@ public void testExecutionHookSuccessfulCommandWithSemaphoreIsolation() { // thread execution assertEquals(0, command.builder.executionHook.threadStart.get()); assertEquals(0, command.builder.executionHook.threadComplete.get()); + + // expected hook execution sequence + assertEquals("onStart - onRunStart - onRunSuccess - onComplete - ", command.builder.executionHook.executionSequence.toString()); } /** @@ -6055,6 +6106,9 @@ public void testExecutionHookFailureWithSemaphoreIsolation() { // thread execution assertEquals(0, command.builder.executionHook.threadStart.get()); assertEquals(0, command.builder.executionHook.threadComplete.get()); + + // expected hook execution sequence + assertEquals("onStart - onFallbackStart - onFallbackError - onError - onComplete - ", command.builder.executionHook.executionSequence.toString()); } /** @@ -7093,11 +7147,13 @@ public String getCollapserPropertiesCacheKey(HystrixCollapserKey collapserKey, c private static class TestExecutionHook extends HystrixCommandExecutionHook { + StringBuilder executionSequence = new StringBuilder(); AtomicInteger startExecute = new AtomicInteger(); @Override public void onStart(HystrixCommand commandInstance) { super.onStart(commandInstance); + recordHookCall(executionSequence, "onStart"); startExecute.incrementAndGet(); } @@ -7106,6 +7162,7 @@ public void onStart(HystrixCommand commandInstance) { @Override public T onComplete(HystrixCommand commandInstance, T response) { endExecuteSuccessResponse = response; + recordHookCall(executionSequence, "onComplete"); return super.onComplete(commandInstance, response); } @@ -7116,6 +7173,7 @@ public T onComplete(HystrixCommand commandInstance, T response) { public Exception onError(HystrixCommand commandInstance, FailureType failureType, Exception e) { endExecuteFailureException = e; endExecuteFailureType = failureType; + recordHookCall(executionSequence, "onError"); return super.onError(commandInstance, failureType, e); } @@ -7124,6 +7182,7 @@ public Exception onError(HystrixCommand commandInstance, FailureType fail @Override public void onRunStart(HystrixCommand commandInstance) { super.onRunStart(commandInstance); + recordHookCall(executionSequence, "onRunStart"); startRun.incrementAndGet(); } @@ -7132,6 +7191,7 @@ public void onRunStart(HystrixCommand commandInstance) { @Override public T onRunSuccess(HystrixCommand commandInstance, T response) { runSuccessResponse = response; + recordHookCall(executionSequence, "onRunSuccess"); return super.onRunSuccess(commandInstance, response); } @@ -7140,6 +7200,7 @@ public T onRunSuccess(HystrixCommand commandInstance, T response) { @Override public Exception onRunError(HystrixCommand commandInstance, Exception e) { runFailureException = e; + recordHookCall(executionSequence, "onRunError"); return super.onRunError(commandInstance, e); } @@ -7148,6 +7209,7 @@ public Exception onRunError(HystrixCommand commandInstance, Exception e) @Override public void onFallbackStart(HystrixCommand commandInstance) { super.onFallbackStart(commandInstance); + recordHookCall(executionSequence, "onFallbackStart"); startFallback.incrementAndGet(); } @@ -7156,6 +7218,7 @@ public void onFallbackStart(HystrixCommand commandInstance) { @Override public T onFallbackSuccess(HystrixCommand commandInstance, T response) { fallbackSuccessResponse = response; + recordHookCall(executionSequence, "onFallbackSuccess"); return super.onFallbackSuccess(commandInstance, response); } @@ -7164,6 +7227,7 @@ public T onFallbackSuccess(HystrixCommand commandInstance, T response) { @Override public Exception onFallbackError(HystrixCommand commandInstance, Exception e) { fallbackFailureException = e; + recordHookCall(executionSequence, "onFallbackError"); return super.onFallbackError(commandInstance, e); } @@ -7172,6 +7236,7 @@ public Exception onFallbackError(HystrixCommand commandInstance, Exceptio @Override public void onThreadStart(HystrixCommand commandInstance) { super.onThreadStart(commandInstance); + recordHookCall(executionSequence, "onThreadStart"); threadStart.incrementAndGet(); } @@ -7180,6 +7245,7 @@ public void onThreadStart(HystrixCommand commandInstance) { @Override public void onThreadComplete(HystrixCommand commandInstance) { super.onThreadComplete(commandInstance); + recordHookCall(executionSequence, "onThreadComplete"); threadComplete.incrementAndGet(); } From 194966ee41732220ec2b07e2f9acf3723d33a081 Mon Sep 17 00:00:00 2001 From: Sergey Krutsko Date: Mon, 27 Oct 2014 21:27:44 +0300 Subject: [PATCH 3/3] Unit tests to reproduce Hook execution sequence issue. testExecutionHookFailedOnHystrixBadRequestWithSemaphoreIsolation --- .../com/netflix/hystrix/HystrixCommand.java | 101 ++++++++++++++++++ 1 file changed, 101 insertions(+) diff --git a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixCommand.java b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixCommand.java index 45229a11a..824076c6f 100755 --- a/hystrix-core/src/main/java/com/netflix/hystrix/HystrixCommand.java +++ b/hystrix-core/src/main/java/com/netflix/hystrix/HystrixCommand.java @@ -6111,6 +6111,51 @@ public void testExecutionHookFailureWithSemaphoreIsolation() { assertEquals("onStart - onFallbackStart - onFallbackError - onError - onComplete - ", command.builder.executionHook.executionSequence.toString()); } + /** + * Execution hook on fail with HystrixBadRequest exception + */ + @Test + public void testExecutionHookFailedOnHystrixBadRequestWithSemaphoreIsolation() { + + TestSemaphoreCommandFailWithHystrixBadRequestException command = new TestSemaphoreCommandFailWithHystrixBadRequestException(new TestCircuitBreaker(), 1, 10); + try { + command.execute(); + fail("we expect a failure"); + } catch (Exception e) { + // expected + } + + assertFalse(command.isExecutedInThread()); + + // the run() method should run as we're not short-circuited or rejected + assertEquals(1, command.builder.executionHook.startRun.get()); + // we expect a successful response from run() + assertNull(command.builder.executionHook.runSuccessResponse); + // we expect an exception + assertNotNull(command.builder.executionHook.runFailureException); + + // the fallback() method should not be run as we were successful + assertEquals(0, command.builder.executionHook.startFallback.get()); + // null since it didn't run + assertNull(command.builder.executionHook.fallbackSuccessResponse); + // null since it didn't run + assertNull(command.builder.executionHook.fallbackFailureException); + + // the execute() method was used + assertEquals(1, command.builder.executionHook.startExecute.get()); + // we should not have a response from execute() + assertNull(command.builder.executionHook.endExecuteSuccessResponse); + // we should not have an exception since run() succeeded + assertNull(command.builder.executionHook.endExecuteFailureException); + + // thread execution + assertEquals(0, command.builder.executionHook.threadStart.get()); + assertEquals(0, command.builder.executionHook.threadComplete.get()); + + // expected hook execution sequence + assertEquals("onStart - onRunStart - onRunError - onError - ", command.builder.executionHook.executionSequence.toString()); + } + /** * Test a command execution that fails but has a fallback. */ @@ -6437,6 +6482,32 @@ protected Boolean run() { } + /** + * Failed execution - fallback implementation successfully returns value. + */ + private static class KnownHystrixBadRequestFailureTestCommandWithoutFallback extends TestHystrixCommand { + + public KnownHystrixBadRequestFailureTestCommandWithoutFallback(TestCircuitBreaker circuitBreaker) { + super(testPropsBuilder().setCircuitBreaker(circuitBreaker).setMetrics(circuitBreaker.metrics)); + } + + public KnownHystrixBadRequestFailureTestCommandWithoutFallback(TestCircuitBreaker circuitBreaker, boolean fallbackEnabled) { + super(testPropsBuilder().setCircuitBreaker(circuitBreaker).setMetrics(circuitBreaker.metrics) + .setCommandPropertiesDefaults(HystrixCommandProperties.Setter.getUnitTestPropertiesSetter().withFallbackEnabled(fallbackEnabled))); + } + + @Override + protected Boolean run() { + System.out.println("*** simulated failed with HystrixBadRequestException ***"); + throw new HystrixBadRequestException("we failed with a simulated issue"); + } + + @Override + protected Boolean getFallback() { + return false; + } + } + /** * Failed execution - fallback implementation successfully returns value. */ @@ -6857,6 +6928,36 @@ protected Boolean run() { } } + /** + * The run() will take time. No fallback implementation. + */ + private static class TestSemaphoreCommandFailWithHystrixBadRequestException extends TestHystrixCommand { + + private final long executionSleep; + + private TestSemaphoreCommandFailWithHystrixBadRequestException(TestCircuitBreaker circuitBreaker, int executionSemaphoreCount, long executionSleep) { + super(testPropsBuilder().setCircuitBreaker(circuitBreaker).setMetrics(circuitBreaker.metrics) + .setCommandPropertiesDefaults(HystrixCommandProperties.Setter.getUnitTestPropertiesSetter() + .withExecutionIsolationStrategy(ExecutionIsolationStrategy.SEMAPHORE) + .withExecutionIsolationSemaphoreMaxConcurrentRequests(executionSemaphoreCount))); + this.executionSleep = executionSleep; + } + + private TestSemaphoreCommandFailWithHystrixBadRequestException(TestCircuitBreaker circuitBreaker, TryableSemaphore semaphore, long executionSleep) { + super(testPropsBuilder().setCircuitBreaker(circuitBreaker).setMetrics(circuitBreaker.metrics) + .setCommandPropertiesDefaults(HystrixCommandProperties.Setter.getUnitTestPropertiesSetter() + .withExecutionIsolationStrategy(ExecutionIsolationStrategy.SEMAPHORE)) + .setExecutionSemaphore(semaphore)); + this.executionSleep = executionSleep; + } + + @Override + protected Boolean run() { + System.out.print("*** simulated failed execution ***"); + throw new HystrixBadRequestException("we failed with a simulated issue"); + } + } + /** * Semaphore based command that allows caller to use latches to know when it has started and signal when it * would like the command to finish