Separate method logging in Java / logback

Bart writing some logs

Task

Let's say we wanted to log each method of a certain Java class differently:

Each method has its own log file,
... your log format,
... its minimum level of logging,
we expand the log format with our own % ,
ability to update this configuration on the fly.

This article shows how to fulfill these requirements. In order to maintain simplicity, separation of logging is performed only by methods; in reality, you might want to have a hierarchical qualifying config, like → → → ... A link to the full source code will be below.

Client code

  class ThingService { log = LoggerFactory.getLogger(); getThing() { log.debug("getThing..."); // => one.log } listThings() { log.debug("listThings..."); // => another.log } }

Logback

For the implementation, a solid "logback" logging library was selected, which provides interesting possibilities for customization:

 ch.qos.logback:logback-classic:1.2.3

It is configured both from an XML config and directly from Java, approaches can be combined:

  public void configureLogback() throws JoranException { LoggerContext lc = LoggerFactory.getILoggerFactory(); lc.reset(); // reset prev config JoranConfigurator configurator = new JoranConfigurator(); configurator.setContext(lc); configurator.doConfigure("config.xml"); // any data source StatusPrinter.printInCaseOfErrorsOrWarnings(lc); //   : Logger root = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); root.setLevel(Level.INFO); //  }

Briefly about logging:

The programmer pulls the logger ,
The logger pulls the appenders assigned to him,
The appender thinks and calls the encoder ,
The encoder formats exactly one line of the log,
To do this, he pulls a chain of converters , each of which reveals its % ,
Success.

For simplicity, a pure Java configuration was chosen. Everything is pretty obvious here if you keep in mind the XML config. The main task is to create your own appender / encoder and register them - they will be called by the logback from their bowels. Almost every object you create must be remembered to start using the start() method. Abstract example:

  Logger rootLogger = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); LoggerContext lc = rootLogger.getLoggerContext(); lc.reset(); // reset prev config var encoder = new PatternLayoutEncoder(); encoder.setContext(lc); encoder.setPattern("%-5level %message%n"); encoder.start(); var appender = new ConsoleAppender<ILoggingEvent>(); appender.setContext(lc); appender.setEncoder(encoder); appender.start(); rootLogger.setLevel(Level.DEBUG); rootLogger.addAppender(appender);

Separate logged methods from each other

So that the logback can distinguish one method from another, before calling the method, save its name in ThreadLocal Mapped Diagnostic Context. Further, during analysis, we don’t get these values directly from the MDC class, since the logging code will be executed in another thread and this data will not be there - we get them through ILoggingEvent.getMDCPropertyMap() .

In the general case, as vooft correctly noted, you need to support the call stack and not overwrite the MDC value, but return it to the previous frame, which is done through the introduction of a new ThreadLocal . Schematic example:

  try { MDC.put(MDC_KEY_METHOD, currentMethod); // 1.  currentMethod    // 2.    // 3.       AOP, . } finally { String previousMethod = //     MDC.put(previousMethod); }

Own log file for each method

Create and do not forget to register your own appender:

  class MultiAppender extends AppenderBase<ILoggingEvent> { @Override protected void append(ILoggingEvent event) { method = event.getMDCPropertyMap().get(MDC_KEY_METHOD); Appender appender = getOrCreateAppender(method); appender.doAppend(event); }

He himself does almost nothing, only delegates logging to a pack of real file appenders, one for each method. Delegated to one, the most suitable. "Real" appenders are created on demand, as follows:

  fileAppender = new FileAppender<ILoggingEvent>(); fileAppender.setContext(lc); fileAppender.setAppend(false); fileAppender.setEncoder(getOrCreateEncoderByMethod(lc, method)); fileAppender.setFile(logFileByMethod.get(method)); fileAppender.start();

Own format for each method

To do this, keep the cache of auto-created objects of the Encoder type:

  Map<String, String> patternByMethod = new HashMap<>(); //  ;  Encoder getOrCreateEncoderByMethod(LoggerContext lc, String method) { String pattern = patternByMethod.get(method); encoder = new PatternLayoutEncoder(); encoder.setContext(lc); encoder.setPattern(pattern); encoder.start(); return encoder; }

Each method has its own level of logging

MultiAppender add a check to the MultiAppender class: if the event level MultiAppender threshold specified for the method, only then we log it:

  Map<String, Level> levelByMethod = new HashMap<>(); protected void append(ILoggingEvent event) { Level minLevel = levelByMethod.get(methodName); if (event.getLevel().levelInt >= minLevel.levelInt) { appender.doAppend(event); }

In principle, this logic can be put into the filter.

Extending the format with your variables

In order not to fence your garden, but to take advantage of the proven infrastructure of the log-back, you need to define your converter class, which must be entirely public so that it can be instantiated from the outside. If you need MDC , take it from the event. The %custom variable handler starts here:

  public class CustomConverter extends ClassicConverter { public String convert(ILoggingEvent event) { // mdc = event.getMDCPropertyMap(); return "variable-expanded"; } }

During the general configuration process, register the handler:

  void configurePatterns(LoggerContext lc) { Map<String, String> rules = lc.getObject(CoreConstants.PATTERN_RULE_REGISTRY); if (rules == null) { rules = new HashMap<String, String>(); lc.putObject(CoreConstants.PATTERN_RULE_REGISTRY, rules); } rules.put("custom", CustomConverter.class.getName()); }

And we will use, as an encoder, for example, PatternLayoutEncoder , which will pick it all up. In this case, the %custom variable will expand to the string "variable-expanded" .

Config update on the fly

There is such an opportunity out of the box: it is enough to call the configurator function again, not forgetting to do LoggerContext::reset() and clear the accumulated cache.

Multithreading

If the method configured by us brings new threads to life, then, of course, the specified logging rules will not apply to them - thread local'y will not appear by themselves in the new thread. So, if you want to apply the method settings to a new stream, you have to copy the MDC there:

  Map<String, String> mdcOrig = MDC.getCopyOfContextMap(); ExecutorService es = Executors.newFixedThreadPool(1); es.submit(() -> threadWorker(mdcOrig)); void threadWorker(Map<String, String> parentMdc) { MDC.setContextMap(parentMdc); log.error("expected to appear in method2*.log"); }