Proper logging in reactive application - WebFlux

Question

last time I am thinking about proper using logger in our applications. For example, I have a controller which returns a stream of users but in the log, I see the "Fetch Users" log is being logged by another thread than the thread on the processing pipeline but is it a good approach?

@Slf4j
class AwesomeController {
    
    @GetMapping(path = "/users")
    public Flux<User> getUsers() {
        log.info("Fetch users..");
        
        return Flux.just(...)..subscribeOn(Schedulers.newParallel("my-custom"));
    
    }
}

In this case, two threads are used and from my perspective, not a good option, but I can't find good practices with loggers in reactive applications. I think below approach is better because allocation memory is from processing thread but not from spring webflux thread which potential can be blocking but logger.

   @GetMapping(path = "/users")
    public Flux<User> getUsers() {

        return Flux.defer(() -> {
            return Mono.fromCallable(() -> {
                log.info("Fetch users..");
                    .....
            })
        }).subscribeOn(Schedulers.newParallel("my-custom"))
    }

Answer 1

The normal thing to do would be to configure the logger as asynchronous (this usually has to be explicit as per the comments, but all modern logging frameworks support it) and then just include it "normally" (either as a separate line as you have there, or in a side-effect method such as doOnNext() if you want it half way through the reactive chain.)

If you want to be sure that the logger's call isn't blocking, then use BlockHound to make sure (this is never a bad idea anyway.) But in any case, I can't see a use case for your second example there - that makes the code rather difficult to follow with no real advantage.

One final thing to watch out for - remember that if you include the logging statement separately as you have above, rather than as part of the reactive chain, then it'll execute when the method at calltime rather than subscription time. That may not matter in scenarios like this where the two happen near simultaneously, but would be rather confusing if (for example) you're returning a publisher which may be subscribed to multiple times - in that case, you'd only ever see the "Fetch users..." statement once, which isn't obvious when glancing through the code.