How to calculate request response time in struts interceptor and store mdc

Question

I use spring mvc, struts2, log4j. I use the following code:

import java.util.Map;
import javax.servlet.http.HttpServletRequest;
import org.slf4j.MDC;
import com.opensymphony.xwork2.ActionInvocation;
import com.opensymphony.xwork2.interceptor.Interceptor;
public class RequestTimerInterceptor extends BaseInterceptor implements Interceptor {
    private static final long serialVersionUID = 1L;
    private static final ThreadLocal<Long> REQUEST_DURATION = new ThreadLocal<>();
    private static final String DURATION_KEY = "processingTime";
    @Override
    public String intercept(ActionInvocation invocation) throws Exception {
        HttpServletRequest request = getHttpServletRequest();
    long startTime = System.currentTimeMillis();
    Map<String, String> copyOfContextMap = MDC.getCopyOfContextMap();
    String result;
    try {
        result = invocation.invoke();
    } finally {
        try {
            MDC.setContextMap(copyOfContextMap);
        } catch (Exception e) {
            e.printStackTrace();
        }           
        long endTime = System.currentTimeMillis();
        long processingTime = endTime - startTime;
        REQUEST_DURATION.set(processingTime);
        MDC.put(DURATION_KEY, Long.toString(processingTime));           
    }
        return result;
   }
}

After the result = invocation.invoke(); line, the response time stored in the MDC is not visible in the log that is json in file. without using logback. I am trying to calculate how long it takes to respond to a request and save it to the log as json. log4j I tried to save the MDC before invocation.invoke() and set it again after this line, but it didn't work. Thank you for your guidance:)

Answer 1

Your code doesn't contain a log statement, so you are relying on other interceptors and filters to do the actual logging.

Instead of that you can do the logging yourself in your interceptor, with a code like this one:

private static final Logger logger = LogManager.getLogger();

@Override
public String intercept(ActionInvocation actionInvocation) throws Exception {
    final long startTime = System.currentTimeMillis();
    final ActionContext actionContext = actionInvocation.getInvocationContext();
    final ServletContext servletContext = actionContext.getServletContext();
    final HttpServletRequest request = actionContext.getServletRequest();
    try {
         return actionInvocation.invoke();
    } finally {
        logger.debug(() -> new StringMapMessage()
                .with("app_id", servletContext.getServletContextName())
                .with("RequestMethod", request.getMethod())
                .with("RequestUri", request.getRequestURI())
                .with("processingTime", System.currentTimeMillis() - startTime));
    }
}

To obtain an output as in your comment above:

{"@timestamp":"2024-08-11T07:05:35.865Z","app_id":"SABA","level":"DEBUG","RequestMethod":"POST","RequestURI":"localhost:8443/common/…", "processingTime": "230ms}

use a JSON Template Layout with a map resolver:

<JsonTemplateLayout>
  <EventTemplateAdditionalField key="message" 
                                format="JSON" 
                                value='{"$resolver":"map","flatten":true}'/>
</JsonTemplateLayout>

Remark: In the code above I am using the following Log4j API imports:

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.message.StringMapMessage;