Статьи

Делаем дампы умными

Декабрь 10, 2017

Давным-давно я узнал о чем-то, называемом Log MDC , и я был его большим поклонником. Я внезапно смог разобраться во всем, что происходит в файлах журналов, и точно определить конкретную запись в журнале и выяснить, что с ней правильно или неправильно, особенно когда речь шла об устранении ошибки в работе.

В 2013 году мне поручили работать над проектом, который выполнялся в трудных водах (сочетание нескольких вещей), и почти каждую неделю мне приходилось проходить несколько дампов Java Thread, чтобы понять, что происходит в приложении, чтобы остановить его. Кроме того, были времена, когда мне приходилось иметь профилировщики, такие как AppDynamic, jProfiler, jConsole, все они были подключены к приложению, пытающемуся найти причину проблемы и, что более важно, причину возникновения проблемы. jStack был одним из самых полезных инструментов, с которыми я работал, но дампы потоков, являющиеся ударами, не имели контекстной информации, с которой я мог бы работать. Я застрял, увидев 10 (s) дампов со следами стека о том, какие классы вызывают блок, но не было информации о том, что вызывает и какие входные данные вызывали проблемы, и это очень быстро расстраивало.В конце концов мы нашли проблемы, но они были в основном после нескольких раундов глубокой отладки кода с различными наборами данных.

Когда я закончил с этим проектом, я поклялся, что больше никогда не попаду в такую ​​ситуацию. Я исследовал способы, которыми я могу использовать что-то похожее на NDC Log4j, но иметь это в потоках, чтобы мои дампы что-то значили. И я смог найти, что я могу изменить ThreadName. И в моем следующем проекте я использовал это очень эффективно. Недавно я наткнулся на статью, которая очень хорошо объясняет эту концепцию. Я не собираюсь переписывать все, что они сказали, поэтому вот ссылка на их пост в блоге .

Итак, на прошлой неделе я начинаю новый проект, и когда я приступаю к кодированию инфраструктуры (используя Spring 4.1 и Spring Boot), это первый класс, который я пишу для приложения, и гарантирующий, что фильтр попадет в код как можно скорее, что не только помогает нам в пост-продакшн, но также делает мои журналы разработки значимыми.

Копия кода как для Log4j NDC, так и для настройки ThreadName приведена ниже.

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();
    }
}
view raw

29
Share: