[slf4j-dev] NDC Rehabilitation

[Michael Wooten]

I originally opened SLF4J-522 to add a contains() method to the NDC class.
I also opened a pull request on Github and had a brief discussion with Ceki
on how I was using NDC vs. MDC.

My reason for adding the contains() method was I was attempting to
implement a library that offered similar functionality to how MDC behaves,
specifically with how MDCCloseable can be used to provide a scope for a
context. If an existing value already existed in the NDC, I did not want to
add it again, and did not want to remove it. For another project, I
originally implemented this by directly interfacing with the Log4J
ThreadContext, but I would like to implement this using only SLF4J.

There has been a trend away from nested diagnostic contexts to mapped ones,
which for most cases makes perfect sense. I tend to use both for logging,
but for different reasons. Obviously MDC is used to tag information
pertinent to a specific instance (like a user ID, order ID, etc.). I tend
to think of the mapped context as "what did we get at this logging
statement". I typically use the nested context to push identifiers for the
different parts of the system, which often correspond to different service
layers. I treat the NDC as "how did we get to this logging statement". I
often find it useful to know the path through the system to commonly used
code, especially if it does not result in an Exception and stack trace. For
instance, the NDC [ORDERS_ENDPOINT ORDER_RETURN USER_DAO] would likely be
logged in a User DAO, but also indicates it was part of an order return.
The NDC [USERS_ENDPOINT REGISTRATION USER_DAO] may be logged from the same
statement, but indicates that it was part of a user registration request.

I would like to propose several changes for NDC, but would also address
several existing tickets in JIRA.

1. Move the NDC class from slf4j-ext to slf4j-api (SLF4J-447).
2. Update NDC to include new methods:
  a. String peek() - Returns the top context without removing it.
  b. boolean contains(String) - Returns whether the context stack contains
the provided context (SLF4J-522)
  c. void clear() - Clears the complete context stack (SLF4J-244)
3. Update NDC to use a NDCAdapater similar to how MDC and MDCAdapter works.
4. Include a default NOPNDCAdapter that does nothing.

I would also like to additionally propose several other improvements that
affect both NDC and MDC. I would like to propose a ScopedLoggingContext
class that implements Closeable that would remove potentially multiple MDC
and NDC entries for a specific scope. I have implemented this before using
a LoggingContext.Builder class that could be configured to add multiple
entries to the NDC and MDC contexts. The class included both static and
instance methods for updating the context and were meant to be chainable.
It also implemented the Supplier interface and would only update the
context when get() was called on it.

Example:
import static ...ScopedLoggingContext.Builder.nestedContext;

try (Closeable c = nestedContext("REGISTRATION").mappedContext("ORDER_ID",
order.getId()).mappedContext("USER_ID", order.getUserId()).get()) {
  logger.info("Logged with NDC and MDC values.");
}

This allows for the same try-with-resources block to add multiple nested or
mapped context values and then remove them when the context is auto-closed.

In the approach I implemented before, there were special semantics for
values already on the NDC or MDC. For our purposes, the NDC did not allow
for duplicate contexts (i.e. "[USER ORDERS USER]"). This may not be the
case for others, and such a context may be useful. Also, our behavior for
MDC was specified as if there was an existing MDC context value, it would
be overwritten, but not removed from the context and its original value not
restored. In our case this was beneficial since at some points a USER_ID
context may be null and then later populated and it was beneficial for the
same USER_ID to propagate to future logging statements. I understand that
SLF4J-472 addresses the idea of the previous value being restored when the
context is closed, and perhaps this is a behavior that could be toggled. In
either case, I believe the current implementation of MDCCloseable could
potentially be destructive if a nested context updated the same key value.

try (MDC.MDCCloseable c1 = MDC.putCloseable("testKey", "value1")) {
    logger.info("Log message with context testKey=value1");
    try (MDC.MDCCloseable c2 = MDC.putCloseable("testKey", "value2")) {
        logger.info("Log message with context testKey=value2");
    }
    logger.info("Log message without context testKey");
}

I would be willing to port my current work to SLF4J and post a PR if there
is interest. Is there any interest in reviving and updating the nested
diagnostic context? Is there any interest in being able to remove multiple
context values (either from MDC or NDC) from a Closeable constructed via a
Builder? If so, what should the behaviors be for duplicate context values?

Thank you for any consideration, thoughts, or input on this suggestion.

-Michael
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/slf4j-dev/attachments/20210925/a62e78d4/attachment.html>