You can use either a Servlet Filter or a Spring Interceptor. Here is an example from one of my applications using an Interceptor wired into the WebMvcConfigurerAdapter in the addInterceptors method similar to what is shown in Spring Boot Adding Http Request Interceptors.
/**
* Log endpoint calls with response times. Set reduced logging level based on endpoint mapping (see log4j2.xml)
*/
public class LoggingInterceptor extends HandlerInterceptorAdapter {
private static final Logger LOGGER = LogManager.getLogger();
private final String START_TIME = "startTime";
private final String ENDPOINT_MAPPING = "endpointMapping";
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
ThreadContext.put(START_TIME, System.nanoTime() + "");
ThreadContext.put(ENDPOINT_MAPPING, getEndpointMapping(handler));
LOGGER.info("Handling request - " + getEndpoint(request) + " method: " + request.getMethod() + "Media Type: " + request.getHeader("Accepts"));
return true;
}
@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) {
Long startTime = Long.parseLong(ThreadContext.get(START_TIME), 10);
Long endTime = System.nanoTime();
ThreadContext.clearAll();
LOGGER.info("Completed request " + getEndpoint(request)
+ " - Response: HTTP " + response.getStatus() + " in " + ((endTime-startTime)/1000000) + "ms");
}
public String getEndpoint(HttpServletRequest request) {
return request.getMethod() + " " + request.getRequestURI();
}
//Determines the endpoint based on the Spring annotation of given handler method.
//Does not include additional path from Controller class annotations however.
public String getEndpointMapping(Object handler) {
if (handler instanceof HandlerMethod) {
HandlerMethod handlerMethod = (HandlerMethod) handler;
Method method = handlerMethod.getMethod();
if (method == null) {
return "";
}
GetMapping get = method.getAnnotation(GetMapping.class);
if (get != null) {
return "GET " + firstValue(get.value());
}
PostMapping post = method.getAnnotation(PostMapping.class);
if (post != null) {
return "POST " + firstValue(post.value());
}
PutMapping put = method.getAnnotation(PutMapping.class);
if (put != null) {
return "PUT " + firstValue(put.value());
}
DeleteMapping delete = method.getAnnotation(DeleteMapping.class);
if (delete != null) {
return "DELETE " + firstValue(delete.value());
}
PatchMapping patch = method.getAnnotation(PatchMapping.class);
if (patch != null) {
return "PATCH " + firstValue(patch.value());
}
RequestMapping generic = method.getAnnotation(RequestMapping.class);
if (generic != null) {
return firstValue(generic.method()) + " " + firstValue(generic.value());
}
}
return "";
}
private <T> String firstValue(T[] values) {
if (values == null || values.length == 0 || values[0] == null) {
return "";
}
return values[0].toString();
}
}
The pattern used for the message is
"%d [%t] %-5p %X{loginId, userId, ipAddress, accountNumber} %C{1}.%M:%L - %m%n"
The resulting output is
2021-03-08 23:29:38,567 [http-nio-8091-exec-178] INFO {} LoggingInterceptor.preHandle:33 - Handling request - GET /service/v1/dosomething method: GET Media Type: null
2021-03-08 23:29:38,617 [http-nio-8091-exec-178] INFO {} LoggingInterceptor.afterCompletion:42 - Completed request GET /service/v1/dosomething - Response: HTTP 200 in 50ms
If you want an even more flexible way to display the time see how Log4j Audit does it in its RequestContextFilter which uses ElapsedUtil to format the elapsed time.
Using a Filter has an advantage over the Interceptor in that it can calculate the time in a local variable instead of requiring the use of a ThreadLocal as the Interceptor does.
