29

In my Production code, I am getting errors in my logs when a Mono times out.
I have managed to recreate these errors with the following code:

@Test
public void testScheduler() {
    Mono<String> callableMethod1 = callableMethod();
    callableMethod1.block();

    Mono<String> callableMethod2 = callableMethod();
    callableMethod2.block();
}

private Mono<String> callableMethod() {
    return Mono.fromCallable(() -> {
        Thread.sleep(60);
        return "Success";
    })
            .subscribeOn(Schedulers.elastic())
            .timeout(Duration.ofMillis(50))
            .onErrorResume(throwable -> Mono.just("Timeout"));
}

In the Mono.fromCallable I am making a blocking call using a third-party library. When this call times out, I get errors similar to

reactor.core.publisher.Operators - Operator called default onErrorDropped
reactor.core.publisher.Operators - Scheduler worker in group main failed with an uncaught exception

These errors also seem to be intermittent, sometimes when I run the code provided I get no errors at all. However when I repeat the call in a loop of say 10, I consistently get them.

Brian Clozel
  • 56,583
  • 15
  • 167
  • 176
athom
  • 1,428
  • 4
  • 13
  • 26
  • 1
    what is the question? – Brian Clozel Jul 23 '18 at 17:19
  • 2
    The question is why does this error happen, and what can I do to get rid of them. It does not seem to affect the code, but I was wondering if this is pointing to something missing in my code – athom Jul 23 '18 at 22:34
  • Have a look at the "Dropping Hooks" section, this might help you to figure out why the onErrorDropped hook is called in your case: https://github.com/reactor/reactor-core/blob/master/src/docs/asciidoc/advancedFeatures.adoc#dropping-hooks – rival Sep 07 '18 at 08:16
  • 1
    @rival the link is broken. – axiopisty Jan 03 '19 at 00:53

1 Answers1

37

Question: Why does this error happen?

Answer:

When the duration given to the timeout() operator has passed, it throws a TimeoutException. That results in the following outcomes:

  1. An onError signal is sent to the main reactive chain. As a result, the main execution is resumed and the process moves on (i.e., onErrorResume() is executed).

  2. Shortly after outcome #1, the async task defined within fromCallable() is interrupted, which triggers a 2nd exception (InterruptedException). The main reactive chain can no longer handle this InterruptedException because the TimeoutException happened first and already caused the main reactive chain to resume (Note: this behavior of not generating a 2nd onError signal conforms with the Reactive Stream Specification -> Publisher #7).

Since the 2nd exception (InterruptedException) can't be handled gracefully by the main chain, Reactor logs it at error level to let us know an unexpected exception occurred.

Question: How do I get rid of them?

Short Answer: Use Hooks.onErrorDropped() to change the log level:

    Logger logger = Logger.getLogger(this.getClass().getName());
    @Test
    public void test() {
        Hooks.onErrorDropped(error -> {
            logger.log(Level.WARNING, "Exception happened:", error);
        });

        Mono.fromCallable(() -> {
            Thread.sleep(60);
            return "Success";
        })
         .subscribeOn(Schedulers.elastic())
         .timeout(Duration.ofMillis(50))
         .onErrorResume(throwable -> Mono.just("Timeout"))
         .doOnSuccess(result -> logger.info("Result: " + result))
         .block();
     }

Long Answer: If your use-case allows, you could handle the exception happening within fromCallable() so that the only exception affecting the main chain is the TimeoutException. In that case, the onErrorDropped() wouldn't happen in the first place.

@Test
public void test() {
    Mono.fromCallable(() -> {
        try {
            Thread.sleep(60);
        } catch (InterruptedException ex) {
            //release resources, rollback actions, etc
            logger.log(Level.WARNING, "Something went wrong...", ex);
        }
        return "Success";
    })
     .subscribeOn(Schedulers.elastic())
     .timeout(Duration.ofMillis(50))
     .onErrorResume(throwable -> Mono.just("Timeout"))
     .doOnSuccess(result -> logger.info("Result: " + result))
     .block();
}

Extra References:

lsantsan
  • 594
  • 7
  • 6