Adding user info to log entries in a multi-user app using Mapped Diagnostic Context
Have you ever been in the situation where you were looking at one of your production log files and had a hard time seeing what log entries belonged to what requests? In a multi-user web application many requests are handled in parallel, so without additional context it becomes almost impossible to see how a single user is interacting with your application.
Similarly, when someone reports a problem with the application you can’t really tell what to look for: how do you know that some error in the log was actually caused by the user reporting the issue?
The good news is that there’s an easy solution to this problem, that has been around for a long time already and is very easy to add to your existing applications: use a Mapped Diagnostic Context
MDC explained
By now, you’re either saying “duh, I’ve been doing that for ages” or “what the hell is an MDC?”. In my experience as a consultant, a surprising number of people fall in the latter category; if you do as well, then this new “from the trenches” blog is for you.
MDC stands for Mapped Diagnostic Context, and is a feature that is offered by both plain Log4J and SLF4J with Logback or Log4J as the backing logging framework. It is a map that holds String values keyed by Strings, which is associated with the current thread (using a ThreadLocal).
In your code, you can add entries to the MDC; typically these represent info about the context of the current request, like the username or IP address. In your log pattern that you use for logging, you can access these values using the key under which they were put in the MDC.
I’ll illustrate this with a practical example of how this can be used within a Spring Security-based application.
Example
A common component to hold the code that populates your MDC is a servlet filter. That filter needs to obtain the info you’d like to add to your log entries, like the current user’s name, from somewhere.
This is how you can do that when using Spring Security:
import org.slf4j.MDC;
import org.springframework.security.core.Authentication;
import org.springframework.security.core.context.SecurityContextHolder;
import javax.servlet.*;
import java.io.IOException;
public class MDCFilter implements Filter {
@Override
public void init(FilterConfig filterConfig) throws ServletException {
}
@Override
public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain)
throws IOException, ServletException {
Authentication authentication =
SecurityContextHolder.getContext().getAuthentication();
if (authentication != null) {
MDC.put("userName", authentication.getName());
}
try {
chain.doFilter(req, resp);
} finally {
if (authentication != null) {
MDC.remove("userName");
}
}
}
@Override
public void destroy() {
}
}
In this example we’re using SLF4J. If your code uses Log4J directly, the code stays the same; only the import changes.
You now add this filter to your web application. The regular way to that is in the web.xml. Make sure to place the filter-mapping for this filter below the filter-mapping for Spring-Security, otherwise the security context won’t be populated yet when the doFilter method is executed!
<filter>
<filter-name>springSecurityFilterChain</filter-name>
<filter-class>
org.springframework.web.filter.DelegatingFilterProxy
</filter-class>
</filter>
<filter>
<filter-name>mdcFilter</filter-name>
<filter-class>com.example.web.MDCFilter</filter-class>
</filter>
<filter-mapping>
<filter-name>springSecurityFilterChain</filter-name>
<url-pattern>/*</url-pattern>
</filter-mapping>
<filter-mapping>
<filter-name>mdcFilter</filter-name>
<url-pattern>/*</url-pattern>
</filter-mapping>
An alternative when using Spring Security is to add the filter to the Spring Security filter chain. One benefit of that approach is that the MDC context becomes available as soon as possible, so that logging produced by later Spring Security filters includes the username. Another is that it automatically turns your filter into a Spring-managed bean, so it can benefit from dependency injection, AOP, etc. (for doing this with filters registered in the web.xml, have a look at Spring’s DelegatingFilterProxy).
<security:http use-expressions="true">
<!-- all sorts of config here, skipped for this example
...
-->
<security:intercept-url pattern="/**" access="isAuthenticated()" />
<security:custom-filter ref="mdcFilter"
after="SECURITY_CONTEXT_FILTER"/>
</security:http>
<bean id="mdcFilter" class="com.example.web.MDCFilter"/>
Finally, you need to configure your log pattern to include the username. In both Logback and Log4J this is done using the %X{key} syntax. Here’s an example for a Log4J PatternLayout:
%d [%15.15t] %-5p %-30.30c{3} %10X{userName} - %m%n
When you now run your app, your logging will include the userName for every entry executed within the context of a user request.
For another example of a servlet filter adding entries to the MDC, look at the MDCInsertingServletFilter that ships with Logback.
Apart from servlet filters, some other places where you can easily add some data to the MDC are other interceptors and aspects: basically anything that’s cross-cutting in nature. When not building a web-based application, any other type of endpoint or dispatching component that’s involved in handling client requests would be a natural candidate.
What about NDC?
Just so you know, Log4J has an NDC (Nested Diagnostic Context) in addition to an MDC as well. The NDC acts like a stack where you can push values on top of, rather than putting them under a key. You can print the NDC contents in your log entries by using the %x placeholder (note the lowercase x, where MDC uses uppercase).
I typically prefer MDC: you can add multiple keys and leave it to whoever happens to configure your logging pattern to decide what to actually include, even changing this at runtime or varying it between logging files (lots of applications use more than one log file). Also, SLF4J doesn’t have an NDC, so you’re tying your code to Log4J by using it.
Consequences of MDC being ThreadLocal-based
Before the thread is reused to process another request, you should remove the entries you put in there so that they’re not inadvertently picked up by the next user of the thread. It’s usually best to do this in a finally clause as shown in the above example, so that cleanup happens even in the event of an exception being thrown.
Propagating MDC contents to other threads happens automatically for child threads (UPDATE: this not true anymore for Logback starting with version 1.1.5), but not when you’re using threads obtained from e.g. a thread pool. That means that you lose the MDC info when you’re running some asynchronous task.
If you’d like the MDC contents to be available from worker threads, then make sure that you propagate the MDC contents to those threads before running your tasks. SLF4J’s MDC has a getCopyOfContextMap() method for this particular purpose. One possible approach for this is to use a dedicated Runnable subclass:
public abstract class MdcPropagatingRunnable implements Runnable {
private final Map mdcContext = MDC.getCopyOfContextMap();
@Override
public final void run() {
if (mdcContext != null) {
MDC.setContextMap(mdcContext);
}
try {
runWithMdc();
} finally {
MDC.clear();
}
}
protected abstract void runWithMdc();
}
Note that ThreadLocal context propagation is a common concern: for example, Spring Security has just added a bunch of code to enable this for SecurityContexts in their latest version (see Rob Winch’s excellent blog post).
Conclusion
Adding MDC-based contextual user info to my log statements is something that I do in all of my web applications. It’s very easy and quick to set up, but it can save you a huge amount of time when looking into a production issue. Also, nowadays log files are often used for analytical purposes as well: adding something like an IP address to all your log entries can reveal very valuable information about e.g. what users are accessing what type of functionality in your applications. Just add some entries that you can easily obtain and might be useful and then document the available keys in your log config files, so that people will know what they can add to their pattern layout.
