I am writing a web Rest web service using Spring Boot.
I want to log time taken by my webservice to process request. Also I want to log headers,method and URI called.
I have done similar in my jersey web service few months back using ContainerRequestFilter and ContainerResponseFilter filter() method.
Also, AOP is Better or Filter?
Have you tried with a basic filter like this?
import java.io.IOException;
import javax.servlet.*;
import javax.servlet.annotation.WebFilter;
import javax.servlet.http.HttpServletRequest;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
@Component
@WebFilter("/*")
public class StatsFilter implements Filter {
private static final Logger LOGGER = LoggerFactory.getLogger(StatsFilter.class);
@Override
public void init(FilterConfig filterConfig) throws ServletException {
// empty
}
@Override
public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain) throws IOException, ServletException {
long time = System.currentTimeMillis();
try {
chain.doFilter(req, resp);
} finally {
time = System.currentTimeMillis() - time;
LOGGER.trace("{}: {} ms ", ((HttpServletRequest) req).getRequestURI(), time);
}
}
@Override
public void destroy() {
// empty
}
}
EDITED: (Thanks @suren-aznauryan)
Now, It uses Instant and Duration and avoids System.currentTimeMillis().
import java.io.IOException;
import java.time.Duration;
import java.time.Instant;
import javax.servlet.*;
import javax.servlet.annotation.WebFilter;
import javax.servlet.http.HttpServletRequest;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
@Component
@WebFilter("/*")
public class StatsFilter implements Filter {
private static final Logger LOGGER = LoggerFactory.getLogger(StatsFilter.class);
@Override
public void init(FilterConfig filterConfig) throws ServletException {
// empty
}
@Override
public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain) throws IOException, ServletException {
Instant start = Instant.now();
try {
chain.doFilter(req, resp);
} finally {
Instant finish = Instant.now();
long time = Duration.between(start, finish).toMillis();
LOGGER.trace("{}: {} ms ", ((HttpServletRequest) req).getRequestURI(), time);
}
}
@Override
public void destroy() {
// empty
}
}
Spring boot :logging interceptor
public class ApiLogger extends HandlerInterceptorAdapter {
private static final Logger logger = LoggerFactory
.getLogger(ApiLogger.class);
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
String requestId = UUID.randomUUID().toString();
log(request,response, requestId);
long startTime = System.currentTimeMillis();
request.setAttribute("startTime", startTime);
request.setAttribute("requestId", requestId);
return true;
}
@Override
public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
super.afterCompletion(request, response, handler, ex);
long startTime = (Long)request.getAttribute("startTime");
long endTime = System.currentTimeMillis();
long executeTime = endTime - startTime;
logger.info("requestId {}, Handle :{} , request take time: {}",request.getAttribute("requestId"), handler, executeTime);
}
private void log(HttpServletRequest request, HttpServletResponse response, String requestId) {
logger.info("requestId {}, host {} HttpMethod: {}, URI : {}",requestId, request.getHeader("host"),
request.getMethod(), request.getRequestURI() );
}
}
register interceptor :
@Configuration
@EnableWebMvc
public class AppConfig extends WebMvcConfigurerAdapter {
@Override
public void addInterceptors(InterceptorRegistry registry) {
registry.addInterceptor(new ApiLogger()).addPathPatterns("/api/v1/*");
}
}
Answer by David is correct - filter is a good way to implement such functionality in Spring Boot.
Spring Boot has a built-in endpoint which returns the information about last 100 requests like shown below:
[{
"timestamp": 1394343677415,
"info": {
"method": "GET",
"path": "/trace",
"headers": {
"request": {
"Accept": "text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8",
"Connection": "keep-alive",
"Accept-Encoding": "gzip, deflate",
"User-Agent": "Mozilla/5.0 Gecko/Firefox",
"Accept-Language": "en-US,en;q=0.5",
"Cookie": "_ga=GA1.1.827067509.1390890128; ..."
"Authorization": "Basic ...",
"Host": "localhost:8080"
},
"response": {
"Strict-Transport-Security": "max-age=31536000 ; includeSubDomains",
"X-Application-Context": "application:8080",
"Content-Type": "application/json;charset=UTF-8",
"status": "200"
}
}
}
},{
"timestamp": 1394343684465,
...
}]
If your application is calling another services or querying the database consider using Sniffy for profiling - it will show you not only time spent on your server but also time spent in calling downstream systems. See a live demo here (Check the black widget in top bottom corner).
Disclaimer: I'm the author of Sniffy
