2

For some strange reason, the "User not found" log gets outputted twice in the logs of my application, despite calling findUserById only once. I am not sure what causes this problem.

Is there a better way to approach this (logging and throwing an exception)?

Please note that the findById call is of an API.

Edit: It appears that the exception is thrown only once. Also, if I replace Mono.error with Mono.defer, the log is printed twice as well.

public Mono<User> getUser(String id) {
    
    Mono<User> thisIsEmpty = getNoUser(); // Assume that this is empty

    return Mono.defer(() -> thisIsEmpty.switchIfEmpty(Mono.defer(() -> findUserById(id))));
}


public Mono<User> findUserById(String id) {
        log.info("This is printed once.");
        Mono<User> user = repository.findById(id).switchIfEmpty(Mono.error(() -> { // findById is an API call of a library I use
            log.error("User not found (this is printed twice)"); // Gets printed twice
            throw new UserException(MY_ERROR_CODE, 401);
        }));

        user.subscribe(User -> ... // Do something if it is not empty

        return user;
}
Katie
  • 59
  • 7
  • Is the exception thrown twice too? have you checked your log appenders? – Joost Papendorp May 05 '21 at 21:02
  • Thanks for the help @Joost. Interestingly, the exception does not appear twice. However, if I append `.log("user not found")` after the very last `}))` in the code, the exception is thrown twice too, yet the findUserById method is called just once. If I add a print statement on the first line of the findUserById method, it gets called only once though. It's just the tiny part within the Mono.error which is shown twice The logs in all my application appear once, except this one. – Katie May 05 '21 at 21:12
  • Hmm tricky. Having the second exception could mean it _is_ called twice, but that this exception was previously discarded / muffled. Perhaps you could try spying/mocking the logging call to print its trace, thread-data and such. – Joost Papendorp May 05 '21 at 21:54
  • Actually it does appear that the exception is only thrown once now.. In addition, if I replace the Mono.error() with Mono.defer, the same thing happens too (exception thrown once, log thrown twice) :( – Katie May 05 '21 at 22:15

2 Answers2

2

Well, from Mono#error docs:

Create a Mono that terminates with an error immediately after being subscribed to. The Throwable is generated by a Supplier, invoked each time there is a subscription and allowing for lazy instantiation.

First your subscription is here:

user.subscribe(User -> ...

And I assume you have another subscription in code, that uses getUser.

That's why it's printed twice.

Eugene Botyanovsky
  • 861
  • 5
  • 17
  • Thanks for the help @Eugene. getUser is only being called once (this is basically done through a get request indeed). But it shouldn't reach the `user.subscribe(User -> ...` call as I have thrown an exception, right? So what you are saying is that it is basically normal behavior? Is there a way to log it only once though? Note that if I replace mono.error with mono.defer it still gets called twice though. The docs don't say that it gets invoked each time there is a subscription. Or am I missing something? – Katie May 05 '21 at 23:48
  • Something outside service is calling getUser(String id) which will call findUserById, where you have subscribe. So as soon as you do subscribe to mono it will "run it " and you can subcribe to mono many times it will just execute your "stream". If you want to log it once dont subscribe in findUserById – Vova Bilyachat May 06 '21 at 01:52
1

As @Eugene mention your problem is that you probably subscribe twice.

If you want to call it once then your method should be rewriten

public Mono<User> findUserById(String id) {
    log.info("This is printed once.");
    return repository.findById(id)
            .switchIfEmpty(Mono.error(() -> { // findById is an API call of a library I use
                log.error("User not found (this is printed twice)"); // Gets printed twice
                throw new UserException(MY_ERROR_CODE, 401);
            }))
            .flatMap(user-> {
                // do smth here 
                return Mono.just(user);
            });


    return user;
}

Reactive is a bit different so when you return mono it wont be executed until you subscribe to it (or block which you should not do until you must).

So basically what is happening in your case first time you "execute" when you do

user.subscribe(User -> ... // Do something if it is not empty

Second time is probably you have controller which is returning mono and spring boot is subscribing

Also not anything you do inside of you service subscribe wont be sent outside of it. You should use flatMap or any other Reactive operators for that.

Vova Bilyachat
  • 18,765
  • 4
  • 55
  • 80