Table of contents

• Introduction
• Basic filter
• Add the username to the filter
• Add the username to all logs
• Conclusion

Introduction

Logging is very valuable for backend applications. It can help monitor, troubleshoot and optimize your application. A lot can be said on this subject: what to log, when to log, what logging levels to use (debug, info, warn, etc), and so on. In this article, I will focus on logging of web requests and will share some tips on how to do so in a Spring Boot application.

One of the first technical component I add to a new project is an access log filter. It is a filter that intercepts all web requests and logs a summary when they have been processed. Actually, I often add this kind of component to existing projects since few of them already have one.

Basic filter

I will first share a basic access log filter that logs the HTTP URL and verb (GET, POST, etc), the response status (200, 404, etc) and the request processing duration in msec. The code is:

@Component
// Use a high priority to measure the whole request
@Order(Ordered.HIGHEST_PRECEDENCE + 10)
public class AccessLogFilter implements Filter {

    private static final Logger LOGGER = LoggerFactory.getLogger(AccessLogFilter.class);

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
        HttpServletRequest request = (HttpServletRequest) servletRequest;
        HttpServletResponse response = (HttpServletResponse) servletResponse;

        long duration = -System.currentTimeMillis();

        try {
            filterChain.doFilter(servletRequest, servletResponse);
        } finally {
            duration += System.currentTimeMillis();

            // E.g. "GET", "POST", etc
            String httpMethod = request.getMethod();

            // E.g. "/foo/bar?acme=12"
            String url = request.getRequestURI();
            String queryString = request.getQueryString();
            if (queryString != null) {
                url += '?' + queryString;
            }

            // E.g. 200, 404, etc
            int status = response.getStatus();

            LOGGER.info("Served {} '{}' as {} in {} ms", httpMethod, url, status, duration);
        }
    }
}

A truncated (the timestamp and some other log elements were removed for brevity) sample output is:

INFO com.adeliosys.sample.AccessLogFilter     : Served GET '/date' as 200 in 1 ms

The implementation is quite straightforward. The data to log are extracted from the HttpServletRequest and HttpServletResponse objects. The logging happens in a try/finally block to get the log even if an exception is raised. Note that we use a high priority filter (thanks to the @Order annotation) to make sure that the whole request is measured.

Add the username to the filter

In this second step, we will improve the filter log message by adding the username. This is a bit more complicated than it first seems. The username is actually only available within the scope of the Spring Security filter chain. And because our access log filter uses a higher priority (in order to measure the whole request processing) it does not have access to that username. We could lower the priority of AccessLogFilter, but the duration would become less representative. Instead, a possible solution is to add a second filter, UsernameExtractionFilter after the Spring Security filter chain, that extracts the username and makes it available to the access log filter through a ThreadLocal.

If you don't know ThreadLocal, it is a standard Java class that is used to store contextual information for the current thread. It is used by many frameworks, including Spring, to store information about the current transaction, the current security context, etc.

The second filter is:

@Component
// Use a priority lower than the Spring Security filter chain
@Order(SecurityProperties.DEFAULT_FILTER_ORDER + 10)
public class UsernameExtractionFilter implements Filter {

    private static final ThreadLocal<String> usernameThreadLocal = new ThreadLocal<>();

    public static String getCurrentUsername() {
        return usernameThreadLocal.get();
    }

    public static void clearCurrentUsername() {
        usernameThreadLocal.remove();
    }

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
        String username = SecurityContextHolder.getContext().getAuthentication().getName();
        usernameThreadLocal.set(username);
        filterChain.doFilter(servletRequest, servletResponse);
    }
}

The username is extracted from the current Spring Security context and stored in our ThreadLocal. An adequate priority is used in @Order to make sure that the second filter is executed after the Spring Security filter chain.

The end of the doFilter method of AccessLogFilter is slightly modified:

// Get the current username, then clear the thread local
String username = UsernameExtractionFilter.getCurrentUsername();
UsernameExtractionFilter.clearCurrentUsername();

LOGGER.info("Served {} '{}' to {} as {} in {} ms", httpMethod, url, username, status, duration);

The username is retrieved from UsernameExtractionFilter, added to the log message and the ThreadLocal is cleared when done, to make sure that the username does not leak to another web request.

A truncated sample output for an authenticated user is:

INFO com.adeliosys.sample.AccessLogFilter     : Served GET '/date' to 'john.doe' as 200 in 2 ms

A truncated sample output for an anonymous user is:

INFO com.adeliosys.sample.AccessLogFilter     : Served GET '/date' to 'anonymousUser' as 200 in 2 ms

The anonymousUser username is generated by Spring Security when no user is authenticated.

Add the username to all logs

At this point the username is present in the AccessLogFilter log message, but not in other log messages, for example:

INFO com.adeliosys.sample.SampleController    : Returning the date
INFO com.adeliosys.sample.AccessLogFilter     : Served GET '/date' to 'john.doe' as 200 in 2 ms

We could prefer the username to be present in all log messages. To do so, we use a different UsernameExtractionFilter. The ThreadLocal is not needed anymore. Instead, we use SLF4J MDC (Mapped Diagnostic Context). MDC is a solution to add contextual information to log messages, in our case the username.

UsernameExtractionFilter now stores the username in MDC under the arbitrary user key and between brackets (this is a personal design choice):

@Component
@Order(SecurityProperties.DEFAULT_FILTER_ORDER + 10) // Use a priority lower than the Spring Security filter chain
public class UsernameExtractionFilter implements Filter {

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
        String username = SecurityContextHolder.getContext().getAuthentication().getName();
        MDC.put("user", '[' + username + "] ");
        filterChain.doFilter(servletRequest, servletResponse);
    }
}

The AccessLogFilter is also slightly modified, the end of the doFilter method becomes:

LOGGER.info("Served {} '{}' as {} in {} ms", httpMethod, url, status, duration);

// Make sure that the username does not leak to other requests
MDC.clear();

The username is no longer logged in AccessLogFilter and we make sure that the MDC is cleared at the end of the web request.

We also need to modify the logging configuration to use the user value. This is supported by the %X{user} syntax and can be used in the logback.xml configuration file or simply in the application.yml file as shown in the next extract (look for %X{user} at the end of the configuration parameter value):

logging:
  pattern:
    console: "%clr(%d{${LOG_DATEFORMAT_PATTERN:yyyy-MM-dd'T'HH:mm:ss.SSSXXX}}){faint} %clr(${LOG_LEVEL_PATTERN:%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %X{user}%m%n${LOG_EXCEPTION_CONVERSION_WORD:%wEx}"

I chose to display the username right before the business message, but you can use %X{user} wherever you like in the logging pattern.

Now you may wonder why I chose to wrap the username by brackets using code rather than configuration. It is simply to prevent empty brackets, i.e. [], in logs that do not use our filters, such as application startup logs.

A truncated sample output for an authenticated user is:

INFO com.adeliosys.sample.SampleController    : [john.doe] Returning the current date
INFO com.adeliosys.sample.AccessLogFilter     : [john.doe] Served GET '/date' as 200 in 2 ms

A truncated sample output for an anonymous user is:

INFO com.adeliosys.sample.SampleController    : [anonymousUser] Returning the current date
INFO com.adeliosys.sample.AccessLogFilter     : [anonymousUser] Served GET '/date' as 200 in 2 ms

Of course, we can add other values to MDC. For example if we generate a unique identifier for each request, we can execute MDC.put("requestId", currentRequestId) in the code and use %X{requestId} in the logging configuration.

Conclusion

In this article, I showed how to develop a simple but useful access log filter. I also showed two different ways to log the current username, one for the access log filter only and one for all logs.

A sample project is available in GitHub, see access-log-filter.