I created a very simple web application. In it any calls to URLs ending in ".do" reach the below servlet :
If I hit the servlet than the logs would display the below:
One way to solve the problem would be to add some unique id in all the log messages - say a sessionId. But what if we do not have access to this value in lets say our Business classes? Passing the sessionId around as a parameter to simply make logging user specific would not be a very clean solution.
The other end would be to have separate appenders for each user. Than every request's logs would be redirected to different files. As a solution I do not know if any Log library supports this out of the box. Even if it did, I don't think anybody would ever approve such a solution.
Log libraries have come up with a very elegant solution. They have bound a simple map of unique values to the thread executing the code. Whenever the logger logs a message, the unique values for this message are simply lifted from the thread and placed in the log. Elegant and powerful, reminds me of Hibernate's association of sessions to the executing thread.
To test the above, I modified my filter :
public class SimpleServlet extends HttpServlet { private static final Logger logger = LoggerFactory.getLogger(SimpleServlet.class); @Override protected void doGet(HttpServletRequest req, HttpServletResponse resp)throws ServletException, IOException { logger.info("Request received at time {}", DateFormat.getDateInstance().format(new Date())); RequestDispatcher dispatcher = req.getRequestDispatcher("result.jsp"); dispatcher.forward(req, resp); } }The jsp file is as below:
<%@page import="java.util.Date, java.text.DateFormat"%> <%@page import="org.slf4j.Logger, org.slf4j.LoggerFactory"%> <%@page contentType="text/html; charset=ISO-8859-1" pageEncoding="ISO-8859-1"%> <html> <%! private static final Logger logger = LoggerFactory.getLogger("jsp"); private void logRequest() { logger.info("Request received at time {}",
DateFormat.getDateInstance().format(new Date())); } %> <body> <% logRequest(); %> Request has been handled ! </body> </html>I have also added a filter to monitor the servlet:
public class SimpleFilter implements Filter { private static final Logger logger = LoggerFactory.getLogger(SimpleFilter.class); @Override public void doFilter(ServletRequest req, ServletResponse resp, FilterChain filterChain) throws IOException, ServletException { logger.info("Request received at time {}", DateFormat.getDateInstance().format(new Date())); filterChain.doFilter(req, resp); } //other code }As seen the focus is to simply log the processing of all requests. The loggers I have used are a part of the Logback API.
If I hit the servlet than the logs would display the below:
12:06:56.317 INFO c.f.SimpleFilter - Request received at time Nov 22, 2013 12:06:56.328 INFO c.s.SimpleServlet - Request received at time Nov 22, 2013 12:06:57.140 INFO jsp - Request received at time Nov 22, 2013Now Imagine this was our real app and we wanted to see how the requests were processed for our users. In case of multiple requests, it would be very difficult to know which logs pertain to which user.
One way to solve the problem would be to add some unique id in all the log messages - say a sessionId. But what if we do not have access to this value in lets say our Business classes? Passing the sessionId around as a parameter to simply make logging user specific would not be a very clean solution.
The other end would be to have separate appenders for each user. Than every request's logs would be redirected to different files. As a solution I do not know if any Log library supports this out of the box. Even if it did, I don't think anybody would ever approve such a solution.
Log libraries have come up with a very elegant solution. They have bound a simple map of unique values to the thread executing the code. Whenever the logger logs a message, the unique values for this message are simply lifted from the thread and placed in the log. Elegant and powerful, reminds me of Hibernate's association of sessions to the executing thread.
To test the above, I modified my filter :
public void doFilter(ServletRequest req, ServletResponse resp, FilterChain filterChain) throws IOException, ServletException { org.slf4j.MDC.put("sessionId", ((HttpServletRequest)req).getSession().getId()); //earlier code }As my filter is the first on the request thread, I update the MDC with the sessionId. (Note: the MDC methods are static.) Do we now need to modify all our log messages so as to include this value ? No. We simply change the log format in our appender:
<appender name="stdout" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{HH:mm:ss.SSS} %-5level %X{sessionId} %logger{5} - %msg%n </pattern> </encoder> </appender>As seen above the pattern has a field %X{sessionId}. Accordingly the new logs are:
12:15:48.364 INFO 0E1BF0AEA01577989F4046FC2A534375 c.f.SimpleFilter - Request received at time Nov 22, 2013 12:15:48.366 INFO 0E1BF0AEA01577989F4046FC2A534375 c.s.SimpleServlet - Request received at time Nov 22, 2013 12:15:48.399 INFO 0E1BF0AEA01577989F4046FC2A534375 jsp - Request received at time Nov 22, 2013What if this value was not present ? I added a simple log statement in my filter's init method:
public void init(FilterConfig filterConfig) throws ServletException { logger.debug("Filter has been initialized"); }At server start up there in no sessionId associated with any thread: The log for the above is :
12:17:18.337 DEBUG c.f.SimpleFilter - Filter has been initializedNo Exceptions, no null value - This kind of scenario has been handled by the Logback team. For further details on the MDC check this awesome tutorial by the logback team.
No comments:
Post a Comment