[FIXED] SpringBoot MDC only for the next log

Issue

Small question regarding SpringBoot application, and MDC logs please.

I have a very simple SpringBoot web handler:

  @GetMapping(path = "/mdcOnlyToThisLogPlease")
    public Mono<String> mdcOnlyToThisLogPlease(@RequestBody Book book) {
        MDC.setContextMap(Map.of("bookName", book.getTitle(), "bookAuthor", book.getAuthor()));
        LOGGER.info("I would like to have a log with bookName and bookValue as first level key for the MDC Json log, and only for this log please");
        return bookService.doSomething(book.getTitle(), book.getAuthor());
    }

Here, I would like to log as first level keys in the json the title and author of the book, I would like to get this:

{ 
    @timestamp:  2022-02-22T02:22:22.222Z 
    @version:  1 
    bookName: someName
    bookAuthor: someAuthor
    level:  INFO 
    level_value:  20000 
    logger_name:  MyClass 
    message: I would like to have a log with bookName and bookValue as first level key for the MDC Json log, and only for this log please
    spanId:  e58ad767e34525de 
    thread_name:  reactor-http-epoll-1 
    traceId:  ccf32f0b5d210aa2 
}

And I thought this piece of code would do just that. Unfortunately, it is also logging the keys, for each and every logs that comes after!

For instance, I see also in the logs from bookService.doSomething(), health check logs, and many more...

{
    @timestamp:  2022-05-02T04:31:30.648Z 
    @version:  1 
    bookName: someName
    bookAuthor: someAuthor
    level:  INFO 
    level_value:  20000 
    logger_name:  reactor.netty.http.server.AccessLog 
    message:  0:0:0:0:0:0:0:1%0 - - [02/May/2022:04:31:30 +0000] "GET /health/readiness HTTP/2.0" 200 5088 19 
    thread_name:  reactor-http-epoll-1 
}

{
    @timestamp:  2022-05-02T04:33:30.648Z 
    @version:  1 
    bookName: someName
    bookAuthor: someAuthor
    level:  INFO 
    level_value:  20000 
    logger_name:  bookService 
    message:  Log from book service. I do not wish to see bookName and bookAuthor as keys
    thread_name:  reactor-http-epoll-1 
}

{ 
    @timestamp:  2022-05-02T04:40:48.742Z 
    @version:  1 
    bookName: someName
    bookAuthor: someAuthor
    level:  INFO 
    level_value:  20000 
    logger_name:  reactor.netty.http.server.AccessLog 
    message:  0:0:0:0:0:0:0:1%0 - - [02/May/2022:04:40:48 +0000] "GET /health/liveness HTTP/2.0" 200 5088 25 
    thread_name:  reactor-http-epoll-1 
}

May I ask how to add the keys, but only for the next / the one log please?

Thank you

Solution

Assuming you're using the SLF4J MDC-

For a single key-value pair at a time, the MDC comes with MDCCloseable, which allows you to take advantage of the try-with-resources block:

log.info("This will be logged without myKey, myValue");
try (MDC.MDCCloseable ignored = MDC.putCloseable("myKey", "myValue")) {
    log.info("This will be logged with myKey, myValue");
}
log.info("This will be logged without myKey, myValue");

In this form, the entry you put in MDC.putCloseable(...) will be removed automatically at the end of the block. See the Javadocs.

Unfortunately, there is no similarly convenient method for doing multiple entries at once. It's possible to nest multiple try-with-resources/MDC.putCloseable() blocks, but doing so can make the code messy.

Luckily, it isn't too hard to write your own, just implement Closeable and keep track of the keys you enter into the MDC:

// MDCCloseableMap.java
public class MDCCloseableMap implements Closeable {
    private final Set<String> keys;

    public MDCCloseableMap(Map<String, String> entries) {
        this.keys = Collections.unmodifiableSet(entries.keySet());
        entries.forEach(MDC::put);
    }

    @Override
    public void close() {
        keys.forEach(MDC::remove);
    }
}

Which you can then use in the same way:

log.info("This will be logged without myKeys, myValues");
Map<String, String> myEntries = Map.of("myKey1", "myValue1", "myKey2", "myValue2");
try (MDCCloseableMap ignored = new MDCCloseableMap(myEntries)) {
    log.info("This will be logged with myKeys, myValues");
}
log.info("This will be logged without myKeys, myValues");

Answered By - Knox
Answer Checked By - Gilberto Lyons (JavaFixing Admin)