Non-Static Slf4j MDC Pattern

Question

Within my system I have a series of complex actors that are able to manage their own state. For illustration purposes let's pretend that it's a car:

class Car {
    private String registrationPlate;
    private int gear;

    public void gearUp() {
       int oldGear = gear++;
       log.info("Changed gear from {} to {} for vehicle {}", oldGear, gear, registrationPlate);
    }
}

Whenever I change gear (or any other state) I would like to add some commentary to the log file. Given there are a number of cars in my system, it's critical that the registration plate of the affected car is written out with any log entry.

The above code assumes the developer always remembers to include the registration plate in the log entry. In reality, this is too often forgotten by the developers and we end up with log entries with this detail omitted, which makes tracing events in the logs impossible -- as you don't know which "car" took the logged action.

---

The concept of the Mapped Diagnostic Context seems to fit my brief exactly; I want to attach some additional metadata to every line written-out to the logs, great!

However, in reality the implementation isn't very useful to me. The MDC is assumed to be some static thread-specific context (facilitated internally by ThreadLocal).

Given my system is multithreaded, and each Car may end up performing an action on any number of threads in a pool. Thus the burden on the developer has just increased:

    public void gearUp() {
       int oldGear = gear++;
       MDC.put("registrationPlate", registrationPlate);
       log.info("Changed gear from {} to {}", oldGear, gear);
       MDC.clear();
    }

Heaven forbid they forget to call MDC.clear(), otherwise the next invocation of the logger from that thread could be attached to the wrong car (if the next logging statement has also forgotten MDC.put("registrationPlate", ...))

---

What I really need is a logger that is MDC-specific. This would be my fanciful idea of an API that would facilitate that:

private final Logger logger;

public Car(String registrationPlate) {
    this.registrationPlate = registrationPlate;

    this.logger = LoggerFactory.buildLogger(this)
        .withContext("registrationPlate", registrationPlate)
        .build();
}

I'd really rather not build this myself, it seems like a feature that should be available to me already. What alternatives have I overlooked?

Answer 1

The MDC is really designed for giving the context of something thread-based (like which user request a web site is servicing), so while you might be able to get it to do what you want (and I've twisted it at times to handle things that it wasn't really designed for), I don't think it's really what you're looking for.

It appears that you're actually looking for having each instance of the class have its own logger. Well, one approach is to actually just do that, with your instance name actually used as part of the logger name:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Car {
    private final Logger logger;
    private final String registrationNumber;

    public Car(final String registrationNumber) {
        this.registrationNumber = registrationNumber;
        logger = LoggerFactory.getLogger("example.car." + registrationNumber);
    }

    public void logSomething() {
        logger.info("Logging something here");
    }
}

It's a little odd, as we're used to logger names always being the same thing as the class that's being logged, and while that's a useful convention, I think it's fine to tweak it if the specific things you're looking to log don't quite line up the same way. This might not work well if you're logging with abbreviated logger names (like Logback uses if you give a length argument to %c, where segments other than the last one can be abbreviated to a single character), but if your logging configuration is set up to use complete logger names, this should give you what I think you're looking for.

The only other approach I think could work would be doing something with Markers, where you create a new marker for each class instance. That might work just as well, and Logback at least lets you include the Marker as part of the pattern, though it would require the developer remember to use the Marker on each log entry. It might be worth exploring as another option.

(My code in this answer, such as it is, I hereby dedicate to the public domain.)