Useful logging mechanism: Log Markers

In my previous post, I showed a simple example about MDC. In this post, I discuss the use of log markers (http://logback.qos.ch/manual/filters.html). Like MDC filters, marker filters are also "turbo filters" in Logback. Both these filters get triggered after a log event is created but before the log appender(s) are invoked. So they are a good choice for high-performance logging. While MDC filters are ideal to trace the path of a request, log marker filters are good for logging certain use cases.

Suppose we want to log the stack trace for user authentication failures (incorrect userid, incorrect password, account locked, db failure, etc) . Typically, the stack traces are logged in DEBUG level so they don't fill your production logs. So what we want is the ability to log the stack trace only for user authentication failures.

Log markers come handy here. You can use a log marker (say LOG_STACKTRACE_USER_AUTH_FAILURE) like this:

Marker logMarker = MarkerFactory.getMarker(LOG_STACKTRACE_USER_AUTH_FAILURE);
log.debug(logMarker, exception);

And in your logback.xml:

 <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
    <Marker>LOG_STACKTRACE_USER_AUTH_FAILURE</Marker>
    <OnMatch>ACCEPT</OnMatch>
  </turboFilter>

Irrespective of the global logger level you may defined*, this will allow your software to log stack trace to an appender when a log event with a marker called "LOG_STACKTRACE_USER_AUTH_FAILURE" is created.

* This behaviour is particular to ch.qos.logback.classic.turbo.MarkerFilter implementation.

Here is a good stackoverflow discussion on uses for MDC and log markers: http://stackoverflow.com/questions/4165558/best-practices-for-using-markers-in-slf4j-logback

Useful logging mechanism: Mapped Diagnostic Context (MDC) in Logback

Quite often, enterprise-level web applications need to log sufficient information for troubleshooting problems but logging can be resource intensive and log analysis can be time consuming, especially if the application in question is deployed in production serving high volume of requests. Mapped Diagnostic Context (MDC)  in Logback is a useful logging mechanism that gives us the ability to select what to log. In this post, I describe a simple use case to demonstrate its usefulness.

If you are using Maven, you need the following dependencies in your pom.xml for this demo:

<dependency>

 <groupId>org.slf4j</groupId>

 <artifactId>slf4j-api</artifactId>

 <version>1.7.5</version>

</dependency>

<dependency>

 <groupId>ch.qos.logback</groupId>

 <artifactId>logback-core</artifactId>

 <version>1.0.13</version>

</dependency>

<dependency>

 <groupId>ch.qos.logback</groupId>

 <artifactId>logback-classic</artifactId>

 <version>1.0.13</version>

</dependency>

In the following example, we would like "Starting app" and "Finishing app" statements to be logged. We would also like to log "Hello Parthy" but not "Hello Fred", both of which are DEBUG-level log statements. 

Using MDC:

    public static void main( String[] args )

  {

        Logger logger = LoggerFactory.getLogger("personal.tests.logback");

        

        logger.info("Starting app.");

        String username = "Parthy";

        MDC.put("username",  username);

        logger.debug("Hello {}", username);

        MDC.remove("username");

        username = "Fred";

        MDC.put("username",  username);

        logger.debug("Hello {}", username);

        MDC.remove("username");

        

        logger.info("Finishing app.");

  }

logback.xml (using MDCFilter that is shipped with logback):

<configuration>

 <turboFilter class="ch.qos.logback.classic.turbo.MDCFilter">

  <MDCKey>username</MDCKey>

  <Value>parthy</Value>

  <OnMatch>ACCEPT</OnMatch>

 </turboFilter>

 <appender name="console" class="ch.qos.logback.core.ConsoleAppender">

  <encoder>

   <pattern>%date [%thread] %-5level %logger - %msg%n</pattern>

  </encoder>

 </appender>

 <root level="INFO">

  <appender-ref ref="console" />

 </root>

</configuration>

Setting the OnMatch value in the turboFilter to DENY will prevent "Hello Parthy" getting logged. In this case, "Hello Fred" will also not be logged because the root logger level is INFO and "Hello Fred" is logged at DEBUG level.

To use MDC effectively, developers should put the customer support hat and ask how can I trace an individual request amidst tens or hundreds of thousands of request with minimal noise in the logs. Find out how requests are identified (request id, session id, user name etc) and use those as MDC keys. You might say that such filtering is CPU intensive. Actually, logback's turboFilter is intended for high performance.

Interested? Read more here: http://logback.qos.ch/manual/filters.html