Wednesday, March 16, 2011

Agile troubleshooting: LoggingFilter to log all requests

I have posted before about logMonitor and its role in an agile development team.

Being able to use the logs in a proactive way requires though something else: As a developer you must understand as soon as possible the specific test case to be able to recreate the issue in your development environment.

You need to make sure you can separate from the log traces those pieces related to the session where the error was found and that within the traces you can actually see the received request.

Here is how in a typical J2EE container you will do it:

Log the session

The session id is that parameter you cannot forget to log. For example with log4j you would use something like %X{sessionId}
log4j.appender.logfile.layout.ConversionPattern=%d %p [%c] - %X{sessionId} %m%n

For this to work you will need to use the below from your Java code:
MDC.put("sessionId", httpRequest.getSession().getId());

Log the request

The below class is a J2EE filter that will log the complete URL/URI including parameters. Both POST and GET parameters are logged which means the URL(s) could be used to recreate the whole test case.
package com.nestorurquiza.web.filter;

import java.io.IOException;
import java.util.Arrays;
import java.util.Map;

import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.FilterConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.http.HttpServletRequest;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

public final class LoggingFilter implements Filter {

    private static final Logger log = LoggerFactory
            .getLogger(LoggingFilter.class);
    //Must be ordered!
    private static final String[] ORDERED_EXCLUDED_PARAMETERS = new String[]{"password", "card_number"};

    public void doFilter(ServletRequest request, ServletResponse response,
            FilterChain chain) throws IOException, ServletException {
        
        HttpServletRequest httpRequest = (HttpServletRequest) request;
        MDC.put("sessionId", httpRequest.getSession().getId());
        String uri = httpRequest.getRequestURI();
        if(! uri.contains(".")) {
            String remoteAddress = request.getRemoteAddr();
            String requestedResourceAsHttpGet = getRequestedResourceAsHttpGet(httpRequest);
            log.info(requestedResourceAsHttpGet + " " + remoteAddress);
        }
        chain.doFilter(request, response);
    }

    public void destroy() {
    }

    public void init(FilterConfig filterConfig) {
    }

    private String getRequestedResourceAsHttpGet(HttpServletRequest httpRequest) {
        StringBuffer sb = new StringBuffer();
        String uri = httpRequest.getRequestURI();
        sb.append(uri);

        Map<String, String[]> parameters = httpRequest.getParameterMap();

        for (String key : parameters.keySet()) {
            String[] values = parameters.get(key);
            if (values != null) {
                for (String token : values) {
                    if (sb.indexOf("?") < 0) {
                        sb.append('?');
                    }
                    sb.append('&' + key + '=');
                    if(!isExcluded(key)) {
                        sb.append(token);
                    }
                }
            }
        }
        return sb.toString();
    }
    
    private boolean isExcluded(String s) {
        int index = Arrays.binarySearch(ORDERED_EXCLUDED_PARAMETERS, s);
        return index > 0;
    }
}

Obtaining the test case from logs

Just a simple grep by sessionId and LoggingFilter will do the trick
grep 4AB145AC791D2711119A6FFCCC6A85BC my-app.log | grep LoggingFilter

No comments:

Followers