How to Debug a Spring WebFlux Application

Debugging a Spring WebFlux application can be a challenging task, especially when dealing with complex reactive streams. Unlike traditional blocking applications, where the stack trace provides a clear indication of the root cause of an issue, reactive applications can be harder to debug. Issues such as blocking code, concurrency problems, and race conditions can all cause subtle bugs that are difficult to diagnose. Scenario When dealing with a bug it’s not always a code-related issue. It could be a set of factors, such as recent refactoring, team changes, hard deadlines and so on. In real life, it’s a common thing to end up troubleshooting large applications made by people who left the company a while back, and you just joined. Knowing a little about a domain and technologies isn't going to make your life easier. In the code example below, I wanted to imagine how a buggy code could look like for a person recently joined a team. Consider debugging this code more like a journey rather than challenge. The root cause could be obvious to find for those who are familiar with Reactive apps. However, some practices down below could be still very helpful to revise. @GetMapping("/greeting/{firstName}/{lastName}") public Mono greeting(@PathVariable String firstName, @PathVariable String lastName) { return Flux.fromIterable(Arrays.asList(firstName, lastName)) .filter(this::wasWorkingNiceBeforeRefactoring) .transform(this::senselessTransformation) .collect(Collectors.joining()) .map(names -> "Hello, " + names); } private boolean wasWorkingNiceBeforeRefactoring(String aName) { // We don't want to greet with John, sorry return !aName.equals("John"); } private Flux senselessTransformation(Flux flux) { return flux .single() .flux() .subscribeOn(Schedulers.parallel()); } So, what this piece of code does is: It prepends “Hello, “ to the names provided as parameters. Your colleague John is telling you that everything works on his laptop. That’s true: > curl localhost:8080/greeting/John/Doe > Hello, Doe But when you run it like , you see the next stacktrace: curl localhost:8080/greeting/Mick/Jagger java.lang.IndexOutOfBoundsException: Source emitted more than one item at reactor.core.publisher.MonoSingle$SingleSubscriber.onNext(MonoSingle.java:134) ~[reactor-core-3.5.5.jar:3.5.5] Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: Error has been observed at the following site(s): *__checkpoint ⇢ Handler com.example.demo.controller.GreetingController#greeting(String, String) [DispatcherHandler] *__checkpoint ⇢ HTTP GET "/greeting/Mick/Jagger" [ExceptionHandlingWebHandler] Original Stack Trace: at java.base/java.util.concurrent.FutureTask.run(FutureTask.java) ~[na:na] (4 internal lines) Nice, neither of the traces leads to a code sample above. All it reveals is that 1) it occurred in the method, and 2) the client performed an `HTTP GET "/greeting/Mick/Jagger GreetingController#greeting .doOnError() First and the easiest thing to try out is to add `.doOnError()` callback to the end of the greeting chain. @GetMapping("/greeting/{firstName}/{lastName}") public Mono greeting(@PathVariable String firstName, @PathVariable String lastName) { return Flux.fromIterable(Arrays.asList(firstName, lastName)) // .doOnError(e -> logger.error("Error while greeting", e)); } Nice try, but logs don't show any improvement. Nonetheless, Reactor's internal stack trace: Here are some ways can/can’t be helpful during debugging: doOnError : You can use to log error messages and provide more context about what went wrong in your reactive stream. This can be especially helpful when debugging issues in a complex stream with many operators. Logging doOnError : can also be used to recover from errors and continue processing the stream. For example, you can use to provide a fallback value or stream in case of an error. Recovery doOnError onErrorResume : most probably won’t provide any better stacktrace except what you already saw in the logs. Don’t rely on it as a good troubleshooter. Debugging doOnError log() Next stop is to replace previously added by method call. As simple as it gets. observes all Reactive Streams signals and traces them into logs under INFO level by default. doOnError() log() log() Let’s see what additional info we see in logs now: We can see what Reactive methods have been called ( , and ). Additionally, knowing which threads (pools) these methods have been called from can be very useful information. However, it is not relevant to our case. onSubscribe request onError About thread pools Thread name stands for . Reactive methods and were executed on IO thread pool (scheduler). These tasks were executed immediately on a thread that submitted them. ctor-http-nio-2 reactor-http-nio-2 onSubscribe() request() By having inside we’ve instructed Reactor to subscribe further elements on another thread pool. That’s the reason why has been executed on thread. .subscribeOn(Schedulers.parallel()) senselessTransformation onError parallel-1 You can read more about thread pool . in this article method allows you to add logging statements to your stream, making it easier to track the flow of data and diagnose issues. If we were having more complex data flow with things like flatMap, subchains, blocking calls, etc., we would benefit much from having it all logged down. It’s a very easy and nice thing for daily use. However, we still don’t know the root cause. log() Hooks.onOperatorDebug() Instruction tells Reactor to enable debug mode for all operators in reactive streams, allowing for more detailed error messages and stack traces. Hooks.onOperatorDebug() According to the official documentation: When errors are observed later on, they will be enriched with a Suppressed Exception detailing the original assembly line stack. Must be called before producers (e.g. Flux.map, Mono.fromCallable) are actually called to intercept the right stack information. The instruction should be called once per runtime. One of the best places would be Configuration or Main classes. For our use case it would be: public Mono greeting(@PathVariable String firstName, @PathVariable String lastName) { Hooks.onOperatorDebug(); return // } By adding we can finally make progress in our investigation. Stacktrace is way more useful: Hooks.onOperatorDebug() And on line 42 we have call. single() Don’t scroll up, the looks next: senselessTransformation private Flux senselessTransformation(Flux flux) { return flux .single() // line 42 .flux() .subscribeOn(Schedulers.parallel()); } That’s the root cause. emits one item from Flux source or signals for a source with more than one element. That means flux in the method emits more than 1 item. By going up in the call hierarchy we see that originally there is a Flux with two elements . single() IndexOutOfBoundsException Flux.fromIterable(Arrays.asList(firstName, lastName)) Filtering method removes an item from a flux when it equals to . That’s the reason why the code works for a college named John. Huh. wasWorkingNiceBeforeRefactoring John can be particularly useful when debugging complex reactive streams, as it provides more detailed information about how the stream is being processed. However, enabling debug mode can impact the performance of your application (due to the populated stack traces), so it should only be used during development and debugging, and not in production. Hooks.onOperatorDebug() Checkpoints To achieve nearly the same effect as gives with minimum performance impact, there is a special operator. It will enable debug mode for that section of the stream, while leaving the rest of the stream unaffected. Hooks.onOperatorDebug() checkpoint() Let’s add two checkpoints after filtering and after transformation: public Mono greeting(@PathVariable String firstName, @PathVariable String lastName) { return Flux.fromIterable(Arrays.asList(firstName, lastName)) .filter(this::wasWorkingNiceBeforeRefactoring) /* new */ .checkpoint("After filtering") .transform(this::senselessTransformation) /* new */ .checkpoint("After transformation") .collect(Collectors.joining()) .map(names -> "Hello, " + names); } Take a look at the logs: This checkpoints breakdown tells us that the error has been observed after our second checkpoint described as . It doesn’t mean that the first checkpoint hasn’t been reached during execution. It was, but the error started to appear only after the second one. That’s why we don’t see . After transformation After filtering You can also see two more checkpoints mentioned in the breakdown, from and . They were reached after the one we set, down to the call hierarchy. DispatcherHandler ExceptionHandlingWebHandler Besides description, you can force Reactor to generate a stacktrace for your checkpoint by adding as the second parameter to method. It’s important to note that the generated stacktrace will lead you to the line with a checkpoint. It won’t populate a stacktrace for the original exception. So it doesn’t make a lot of sense because you can easily find a checkpoint by providing a description. true checkpoint() Conclusion By following these best practices, you can simplify the debugging process and quickly identify and resolve issues in your Spring WebFlux application. Whether you're a seasoned developer or just starting out with reactive programming, these tips will help you improve the quality and reliability of your code, and deliver better experiences for your users.

HackerNoon Mobile

How to Debug a Spring WebFlux Application

Too Long; Didn't Read

@vladimirf

Credibility

RELATED STORIES