Core Java

Making Thread Dumps Intelligent

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.

Kapil Viren Ahuja

Kapil Viren Ahuja is a Senior Manager, Technology from SapientNitro’s Gurgaon Office. Kapil is the solution architect working on Digital Marketing Platforms and has worked for accounts including NASCAR, Richemont, Alex and Ani. Kapil has also been the Lead Architect on the SapientNitro’s EngagedNow platform. In his role Kapil is responsible for driving technical solutions and delivery on various projects. Kapil over the course of his 15 years of total experience has worked on several technologies spanning from Enterprise technical stacks to CMS to Experience technologies. Kapil is also an evangelist of new technologies and loves to go beyond the same old day to day work and find new and innovative ways to do the same things more effectively.
Subscribe
Notify of
guest

This site uses Akismet to reduce spam. Learn how your comment data is processed.

0 Comments
Oldest
Newest Most Voted
Inline Feedbacks
View all comments
Back to top button