twitter / finatra

Fast, testable, Scala services built on TwitterServer and Finagle
https://twitter.github.io/finatra/
Apache License 2.0
2.27k stars 408 forks source link

MDC logging weird behaviour #453

Closed bogdangherca closed 6 years ago

bogdangherca commented 6 years ago

Hey folks,

I've just integrated LoggingMDCfilter into our finatra server and it works well in most of our scenarios, but I've noticed something surprising in a specific situation.

We're using java and the below sequential composition scenario is quite often:

userService.getUserById(id)
   .flatMap(user -> otherService.getUserPreferences(user))
   .flatMap(userPref -> another.sendNotification(userPref))
   .flatMap(notificationEvent -> eventService.registerEvent(notificationEvent));

After adding the LoggingMDCfilter according to your documentation, I'm adding the authenticated user to the mdc context like this:

userService.getUserById(id)
   .map(user -> {
        MDC.put("user_id", user.getId())
        logger.info("test"); -> I have the mdc context here when logging
        return user;  -> after returning the mdc context is null
    })
   .flatMap(user -> otherService.getUserPreferences(user))
   ...

I'm not sure why the mdc context is not propagated in this specific scenario. Also, the thing that surprised me the most is that if I do something like below, everything works like a charm:

// put a random attribute in the context
MDC.put("anything", "doesn't matter");
userService.getUserById(id)
   .map(user -> {
        MDC.put("user_id", user.getId())
        logger.info("test"); -> I have the mdc context here when logging
        return user;
    })
   // will have the user_id on the context whenever I log below
   .flatMap(user -> otherService.getUserPreferences(user))
   ...

Any ideas why this might be happening? It may be that I'm using this in an unexpected way, any ideas or suggestions are highly appreciated.

Thanks, Bogdan.

cacoco commented 6 years ago

@bogdangherca hmm, that is odd. We'll take a look, thanks for the issue!

bogdangherca commented 6 years ago

@cacoco: Thanks for the quick response. Regarding our dependencies version we're using:

If you need any additional details, just let me know.

cacoco commented 6 years ago

@bogdangherca I've tracked down the issue and should have a fix shortly. Thanks for the report!

bogdangherca commented 6 years ago

@cacoco: great news, thank you!

cacoco commented 6 years ago

@bogdangherca a fix for this was merged in 37e1e77dfc2399635f65d81e82ea3026491b885c. Thanks!