2

I have a Filter set up in my Spring Boot app to add some information to the MDC:

@Component
public class LogFilter implements Filter {

    @Override
    public void init(FilterConfig var1) throws ServletException {}

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {

        try {
            MDC.put("tag", "Some information);
            chain.doFilter(request, response);
        } finally {
            MDC.clear();
        }
    }
    @Override
    public void destroy() { }
}

This works fine for most of my application, but for certain operations where a thread is spawned, this filter is not picking up those messages.

For example, in the block below, the callback methods occur in a separate thread, so the first log.info call is getting picked up by my LogFilter, but the log.info and log.error in my callbacks aren't.

private void publishMessage(String message) {
    log.info("Message received. Sending to Kafka topic");
    CompletableFuture<ListenableFuture<SendResult<String, String>>> future = CompletableFuture.supplyAsync(() -> kafkaTemplate.send("myTopic", message));

    try {
        future.get().addCallback(new ListenableFutureCallback<SendResult<String, String>>() {

            @Override
            public void onSuccess(SendResult<String, String> result) {
                log.info("Kafka topic " + myTopic + " published to successfully");
            }

            @Override
            public void onFailure(Throwable ex) {
                log.error("Kafka error: " + ex.getMessage());
            }
        });
        } catch (Exception e) {
            log.error("Kafka has failed you for the last time");
        }
    }

In general, it seems like any log event that doesn't occur in one of the http-nio-8080-exec-X threads bypasses LogFilter. What am I doing wrong?

Things I've tried that haven't worked:

  1. Having LogFilter extend GenericFilterBean, use @Bean instead of @Component, and then registering that bean with FilterRegistrationBean in my main Application class
  2. Using @WebFilter(urlPatterns = {"/*"}, description = "MDC Filter") and/or @ServletComponentScan
J_Stan
  • 473
  • 1
  • 5
  • 14

1 Answers1

1

MDC context is only available for the current running thread but your callback will be called within a different thread.

one way to deal with it is to implement ListenableFutureCallback:

private static class MyListenableFutureCallback
              implements ListenableFutureCallback<SendResult<String, String>> {

            private Map<String,String> contextMap = MDC.getCopyOfContextMap();

            @Override
            public void onSuccess(SendResult<String, String> result) {
                MDC.setContextMap(contextMap); //add MDC context here
                log.info("Kafka topic " + myTopic + " published to successfully");
            }

            @Override
            public void onFailure(Throwable ex) {
                MDC.setContextMap(contextMap); //add MDC context here
                log.error("Kafka error: " + ex.getMessage());
            }
    }

and finally:

future.get().addCallback(new MyListenableFutureCallback()).

a more consistant way of doing this is described Here

stacker
  • 4,317
  • 2
  • 10
  • 24
  • This would definitely fix my threads, but is there any way to get the MDC to be picked up by threads spawned by a library? For example, `kafkaTemplate.send()` will spawn threads and those log events won't contain `tag` either. – J_Stan Jan 15 '19 at 21:33
  • I'm not sure the other solution solves my issue as I'm not using `ThreadPoolExecutor`, nor am I understanding how to hook this up in a spring boot application – J_Stan Jan 15 '19 at 21:54
  • I don't know if only declaring your taskExecutor as @Bean is enough or not, are you using spring kafka? – stacker Jan 15 '19 at 22:04
  • Yeah we're using spring-kafka. In any case, modifying the MDC it seeming to be overkill given the information I'm trying to send is static. I think modifying our GELF appender in logback should be sufficient – J_Stan Jan 16 '19 at 16:43