Long back I had learnt about something called Log MDC, and I was a big fan of it. I was suddenly able to make sense of anything that happens in log files and pin-point to a specific log entry and find what’s right or wrong with it especially when it was about debugging a bug in production.
In 2013 I was commissioned to work on a project that was running through some troubled waters (combination of several things) and almost every week I had to go through several Java Thread Dumps trying to make sense what’s happening in the application to make it stop. Also, there were times when I had to have profilers like AppDynamic, jProfiler, jConsole all hooked up to the application trying to find what’s the issue, and more importantly what’s triggering the issue. jStack was one of the most helpful tools that I had worked with but the thread dumps being bumps had no contextual information that I could work with. I was stuck with seeing 10(s) of dumps with stack traces of what classes are causing the block but there was no information of what’s call and what inputs were causing the issues and it got frustrating very fast. Eventually we found the issues but they were mostly after several rounds of deep debugging the code with variety of data sets.
Once I was done with that project I swore that I will never find myself in that situation again. I Explored ways in which I can use something similar to Log4j’s NDC but have that in threads so that my dumps mean something. And i was able to find that I can change the ThreadName. And my next project I did use that very effectively. I recently came across an article that explains that concept very well. I am not going to rewrite everything they said, so here is a link to their blog post.
So last week I am starting a new project and as I get into coding the framework (using Spring 4.1 and Spring Boot), this is the first class I am writing for the application and ensuring that the filter gets into the code ASAP which not only helps us in post-production but also makes my development logs meaningful.
A copy of the code for both Log4j NDC, and setting up a ThreadName is below.
import java.io.IOException;
import java.text.SimpleDateFormat;
import java.util.Date;
import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.filter.OncePerRequestFilter;
/**
* This is a very Spring opinionated HTTPFilter used for intercepting all requests and decorate the thread name with additional contextual
* information. We have extenced the filter from {@link OncePerRequestFilter} class provided by Spring Framework to ensure that the filter is absolutely
* executd only once per request.
*
* The following information will be added:
* <ul>
* <li>Old Thread name: to ensure that we are not losing any original context with thread names;</li>
* <li>Time when the request was intercepted;</li>
* <li>The RequestURI that proviced information on what RestFUL endpoint was accessed as part of this request;</li>
* <li>A Token that was received in the header. This token is encrypted and does not exposes any confidential information. Also, this token provides
* context which helps during debugging;</li>
* <li>The Payload from the token. This information will be very helpful when we have to debug for issues that may be happening with a call request
* as this holds all the information sent from the called.</li>
* </ul>
*
* This filter will also reset the ThreadName back to it's original name once the processing is complete.
*
* @author Kapil Viren Ahuja
*
*/
public class DecorateThreadNameFilter extends OncePerRequestFilter {
@Override
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
throws ServletException, IOException {
final Logger LOGGER = LoggerFactory.getLogger(DecorateThreadNameFilter.class);
final SimpleDateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
Thread thread = Thread.currentThread();
String threadOriginalName = thread.getName();
String uri = request.getRequestURI();
String time = dateFormat.format(new Date());
String token = request.getHeader("authorization");
try {
thread.setName(String.format("%s StartTime \"%s\" RequestURI \"%s\" Token \"%s\"", threadOriginalName, time, uri, token));
} catch (Exception ex) {
LOGGER.error("Failed to set the thread name.", ex);
// this is an internal filter and an error here should not impact
// the request processing, hence eat the exception
}
try {
filterChain.doFilter(request, response);
} finally {
try {
thread.setName(threadOriginalName);
} catch (Exception ex) {
LOGGER.error("Failed to reset the thread name.", ex);
// this is an internal filter and an error here should not
// impact the request processing, hence eat the exception
}
}
}
}/**
* Generic filter for intercepting all requests and perform the following generic tasks:
*
* <ul>
* <li>Intercepts the request and then pushed the user domain into the session if one exists.</li>
* <li> Pushes a uniquely generated request identifier to the LOG4J NDC context. This identifier will then be prepended
* to all log messages generated using LOG4J. This allows tracing all log messages generated as part of the same
* request; </li>
* <li> Pushes the HTTP session identifier to the LOG4J NDC context. This identifier will then be prepended to all log
* messages generated using LOG4J. This allows tracing all log messages generated as part of the same HTTP session;
* </li>
* <li> Pushes the IP address of the client to the LOG4J NDC context. The IP address will then be prepended to all log
* messages generated using LOG4J. This allows tying back multiple user sessions initiated with the same logon name to
* be correctly tied back to their actual origins. </li>
* </ul>
*/
public class RequestInterceptorFilter implements Filter
{
/**
* <p>
* <ul>
* <li>Initializes the LOG4J NDC context before executing an HTTP requests.</li>
* <li>Pushes the domain into the session</li>
* </ul>
* </p>
*/
public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException
{
HttpServletRequest httpRequest = (HttpServletRequest) request;
if (httpRequest.isRequestedSessionIdFromCookie() && !httpRequest.isRequestedSessionIdValid())
{
// TODO: Need to define an session expiration page and redirect the application to that page
// As of now this is a non-issue as we are handling session expirations on Flex (Front-end) and hence
// no request will come to server in case the session timeout occurs
// HttpServletResponse httpServletResponse = (HttpServletResponse) response;
// httpServletResponse.sendRedirect(httpRequest.getContextPath() + "?expired");
}
else
{
// Create an NDC context string that will be prepended to all log messages written to files.
org.apache.log4j.NDC.push(getContextualInformation(httpRequest));
// Process the chain of filters
chain.doFilter(request, response);
// Clear the NDC context string so that if the thread is reused for another request, a new context string is
// used.
org.apache.log4j.NDC.remove();
}
}
public void init(FilterConfig arg0) throws ServletException
{
}
public void destroy()
{
}
/**
* <p>
* Generates the Contextual information to be put in the log4j's context. This information helps in tracing requests
* </p>
*
* @param httpRequest
* @return
*/
private String getContextualInformation(HttpServletRequest httpRequest)
{
String httpRequestIdentifier = UUID.randomUUID().toString();
String httpSessionIdentifier = httpRequest.getSession().getId();
String clientAddress = httpRequest.getRemoteAddr();
StringBuffer logNDC = new StringBuffer(httpRequestIdentifier + " | " + httpSessionIdentifier + " | " + clientAddress);
String userName = (String)httpRequest.getSession().getAttribute(WebConstants.USERNAME);
if (userName != null)
{
logNDC.append(" | " + userName);
}
String domain = (String)httpRequest.getSession().getAttribute(WebConstants.DOMAIN);
if (domain != null)
{
logNDC.append(" | " + domain);
}
// Create an NDC context string that will be prepended to all log messages written to files.
return logNDC.toString();
}
}| Reference: | Making Thread Dumps Intelligent from our JCG partner Kapil Viren Ahuja at the Scratch Pad blog. |
