Micronaut-core: CircuitBreaker annotation doesn't appear threadsafe

Created on 21 Oct 2020 · 2Comments · Source: micronaut-projects/micronaut-core

Using the @CircuitBreaker annotation appears to break when multiple threads are operating against the same annotated method and calls succeed that occur after the call that threw an exception (opened the circuit). In essence, if several threads are operating concurrently on an annotated method and the first one throws an exception, but the remaining ones succeed, circuit breaking behavior appears to break. The circuit opened event is successfully fired, however, calls to the circuit broken method continue to operate normally (not rethrowing the previous exception for the configured open state time - default 20s). Additionally, as a result, a circuit closed event is never fired either.

We've provided a sample application that reproduces the issue consistently. This application has a dummy worker service with a circuit breaker method that will throw an exception every 20th execution to cause a circuit open event to occur. However, because the method immediately returns with the exception, it completes before the other concurrent tasks do, demonstrating the issue. If you introduce a sleep just before throwing the exception (ServiceThatCircuitBreaks.java, line 22) that is longer than the 2000ms configured for tasks operating successfully (ServiceThatCircuitBreaks.java, line 25), e.g. 5000, you will see the problem no longer occurs (since the failing/circuit breaking thread occurs last in that block of tasks).

Task List

[X] Steps to reproduce provided
[ ] Stacktrace (if present) provided
[X] Example that reproduces the problem uploaded to Github
[X] Full description of the issue provided (see below)

Steps to Reproduce

Unzip the provided Micronaut 2.1.1 application
Run ./gradlew run
Observe the logging as shown below:

Notice how calls after number 20 continue to operate normally after the circuit open event was thrown:

> Task :run
11:06:56.824 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:06:56.831 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:06:56.845 [scheduled-executor-thread-5] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 1
11:06:56.847 [scheduled-executor-thread-6] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 2
11:06:56.847 [scheduled-executor-thread-4] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 3
11:06:56.847 [scheduled-executor-thread-2] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 4
11:06:56.847 [scheduled-executor-thread-3] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 5
11:06:58.688 [main] INFO  io.micronaut.runtime.Micronaut - Startup completed in 2863ms. Server Running: http://localhost:8080
11:06:58.848 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:06:58.848 [scheduled-executor-thread-3] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 6
11:06:58.849 [scheduled-executor-thread-5] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 7
11:06:58.849 [scheduled-executor-thread-6] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 8
11:06:58.849 [scheduled-executor-thread-4] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 9
11:06:58.849 [scheduled-executor-thread-2] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 10
11:06:58.849 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:07:00.850 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:07:00.850 [scheduled-executor-thread-7] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 11
11:07:00.850 [scheduled-executor-thread-9] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 12
11:07:00.850 [scheduled-executor-thread-8] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 13
11:07:00.850 [scheduled-executor-thread-10] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 14
11:07:00.850 [scheduled-executor-thread-11] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 15
11:07:00.850 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:07:02.850 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:07:02.850 [scheduled-executor-thread-3] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 16
11:07:02.850 [scheduled-executor-thread-4] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 17
11:07:02.850 [scheduled-executor-thread-2] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 18
11:07:02.851 [scheduled-executor-thread-5] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 19
11:07:02.851 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:07:02.851 [scheduled-executor-thread-6] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 20
11:07:02.853 [scheduled-executor-thread-6] INFO  cb.app.CircuitOpenEventListener - circuit open event: void circuitBreakingMethod()
11:07:02.853 [scheduled-executor-thread-6] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:07:07.853 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:07:07.853 [scheduled-executor-thread-12] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 21
11:07:07.853 [scheduled-executor-thread-13] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 22
11:07:07.853 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:07:07.853 [scheduled-executor-thread-14] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 23
11:07:07.853 [scheduled-executor-thread-15] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 24
11:07:07.853 [scheduled-executor-thread-22] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 25
11:07:09.853 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:07:09.853 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:07:09.853 [scheduled-executor-thread-9] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 26
11:07:09.853 [scheduled-executor-thread-10] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 27
11:07:09.853 [scheduled-executor-thread-11] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 28
11:07:09.853 [scheduled-executor-thread-7] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 29
11:07:09.853 [scheduled-executor-thread-8] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 30

Now notice how the circuit opened event is honored after the 20th call when the offending thread is delayed longer than the others:

> Task :run
11:42:48.689 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:42:48.693 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:42:48.707 [scheduled-executor-thread-4] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 1
11:42:48.709 [scheduled-executor-thread-5] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 2
11:42:48.709 [scheduled-executor-thread-2] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 3
11:42:48.709 [scheduled-executor-thread-3] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 4
11:42:48.709 [scheduled-executor-thread-6] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 5
11:42:50.146 [main] INFO  io.micronaut.runtime.Micronaut - Startup completed in 2495ms. Server Running: http://localhost:8080
11:42:50.710 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:42:50.710 [scheduled-executor-thread-5] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 6
11:42:50.710 [scheduled-executor-thread-6] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 7
11:42:50.711 [scheduled-executor-thread-4] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 8
11:42:50.711 [scheduled-executor-thread-3] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 9
11:42:50.711 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:42:50.711 [scheduled-executor-thread-2] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 10
11:42:52.712 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:42:52.712 [scheduled-executor-thread-7] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 11
11:42:52.712 [scheduled-executor-thread-8] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 12
11:42:52.712 [scheduled-executor-thread-9] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 13
11:42:52.712 [scheduled-executor-thread-10] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 14
11:42:52.712 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:42:52.712 [scheduled-executor-thread-14] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 15
11:42:54.712 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:42:54.712 [scheduled-executor-thread-6] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 16
11:42:54.712 [scheduled-executor-thread-5] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 17
11:42:54.713 [scheduled-executor-thread-17] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 18
11:42:54.713 [scheduled-executor-thread-4] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 19
11:42:54.713 [scheduled-executor-thread-3] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 20
11:42:54.713 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:42:59.716 [scheduled-executor-thread-3] INFO  cb.app.CircuitOpenEventListener - circuit open event: void circuitBreakingMethod()
11:42:59.716 [scheduled-executor-thread-3] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:04.716 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:43:04.716 [scheduled-executor-thread-12] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:04.716 [scheduled-executor-thread-13] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:04.716 [scheduled-executor-thread-11] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:04.716 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:43:04.716 [scheduled-executor-thread-23] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:04.716 [scheduled-executor-thread-15] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:09.717 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:43:09.717 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:43:09.717 [scheduled-executor-thread-8] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:09.717 [scheduled-executor-thread-7] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:09.717 [scheduled-executor-thread-9] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:09.717 [scheduled-executor-thread-10] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:09.717 [scheduled-executor-thread-14] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:14.719 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:43:14.719 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:43:14.719 [scheduled-executor-thread-2] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:14.719 [scheduled-executor-thread-18] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:14.719 [scheduled-executor-thread-19] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:14.719 [scheduled-executor-thread-20] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:14.719 [scheduled-executor-thread-21] INFO  cb.app.TaskThatCircuitBreaks - IllegalStateException caught!
11:43:19.719 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:43:19.719 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:43:19.719 [scheduled-executor-thread-17] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 21
11:43:19.719 [scheduled-executor-thread-4] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 22
11:43:19.719 [scheduled-executor-thread-5] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 23
11:43:19.719 [scheduled-executor-thread-6] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 24
11:43:19.719 [scheduled-executor-thread-3] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 25
11:43:21.720 [scheduled-executor-thread-5] INFO  cb.app.CircuitClosedEventListener - circuit closed event: void circuitBreakingMethod()
11:43:21.720 [scheduled-executor-thread-6] INFO  cb.app.CircuitClosedEventListener - circuit closed event: void circuitBreakingMethod()
11:43:21.720 [scheduled-executor-thread-4] INFO  cb.app.CircuitClosedEventListener - circuit closed event: void circuitBreakingMethod()
11:43:21.720 [scheduled-executor-thread-3] INFO  cb.app.CircuitClosedEventListener - circuit closed event: void circuitBreakingMethod()
11:43:21.720 [scheduled-executor-thread-17] INFO  cb.app.CircuitClosedEventListener - circuit closed event: void circuitBreakingMethod()
11:43:21.721 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks scheduling 5 tasks
11:43:21.721 [scheduled-executor-thread-1] INFO  cb.app.TaskCreatorService - createTasks blocking
11:43:21.721 [scheduled-executor-thread-22] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 26
11:43:21.721 [scheduled-executor-thread-15] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 27
11:43:21.721 [scheduled-executor-thread-16] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 28
11:43:21.721 [scheduled-executor-thread-24] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 29
11:43:21.721 [scheduled-executor-thread-13] INFO  cb.app.ServiceThatCircuitBreaks - circuitBreakingMethod called: 30

Expected Behaviour

1 of 2 things should occur:

If concurrent calls succeed after one fails and fires a circuit open event, they should close the circuit and fire circuit closed events.
Allow concurrent calls to succeed, but subsequent calls should re-throw the previous exception and honor the configured circuit open timeout before attempting the partially open state.

Actual Behaviour

A circuit opened event is fired, concurrent calls succeed and subsequent calls are allowed to execute normally even though the circuit was reported open, and a circuit closed event is never fired.

Environment Information

Operating System: Windows 10 (but we've also observed the behavior in various Linux environments, too)
Micronaut Version: 2.1.1 (also observed in 2.1.0, 2.0.0, and 1.2.0)
JDK Version: OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.8+10)