Announcement Announcement Module
Collapse
No announcement yet.
log4j MDC information from HandlerInterceptor Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • log4j MDC information from HandlerInterceptor

    I have a custom log4j logger that works fine on development and testing servers but not on production. It's been broken a long time, and I'm at my wit's end. The appender logs to a database, but the MDC information is lost. So...

    We have a custom implementation of HandlerIntercepter that handles servlet requests. I am 100% sure the preHandle method is being called. It packs interesting information into the log4j MDC:

    Code:
    ...
    
    import org.apache.log4j.Logger;
    import org.apache.log4j.MDC;
    import org.springframework.web.servlet.HandlerInterceptor;
    import org.springframework.web.servlet.ModelAndView;
    
    public class RequestInterceptor implements HandlerInterceptor {
      private static final Logger log = Logger.getLogger(RequestInterceptor.class);
    
      public boolean preHandle(HttpServletRequest req, HttpServletResponse res, Object handler) throws Exception {
        String requestURL = req.getRequestURL().toString();
        
        // These are set first, because they are not user-specific.
        MDC.put("remoteIP", req.getRemoteAddr());
        MDC.put("remoteHost", req.getRemoteHost());
        MDC.put("remotePort", req.getRemotePort());
        MDC.put("requestURL", requestURL);
        MDC.put("requestMethod", req.getMethod());
        MDC.put("mime", (req.getContentType() == null) ? "unknown" : req.getContentType());
        
        User user = (User) req.getSession().getAttribute("user");
        if (user == null) {
          // Do some stuff and return...
          // Code after this if block will not be executed in this case.
        }
    
        // These only get set if there is a user (AKA, the above if-statement doesn't evaluate to true).
        MDC.put("personId", user.getPerson().getPersonId());
        MDC.put("userName", user.getUsername());
        MDC.put("fullName", user.getPerson().getFullName());
    
        log.info("Intercepted Request by user " + String.format("%8s", user.getUsername()) + " for " + requestURL);
    
        return true;
      }
    
      ...
    User is an implementation of UserDetails.

    The appender wraps the information in a wrapper object before writing it to the database. The constructor of the wrapper object looks like so:

    Code:
      public LoggingEventWrapper(LoggingEvent event) {
        this.loggingEvent  = event;
        this.personId      = getNonNullValueOrFallBack((Integer) MDC.get("personId"),      -1);        // PERSONID
        this.userName      = getNonNullValueOrFallBack((String)  MDC.get("userName"),      "unknown"); // USERNAME
        this.remoteIP      = getNonNullValueOrFallBack((String)  MDC.get("remoteIP"),      "unknown"); // REMOTEIP
        this.remoteHost    = getNonNullValueOrFallBack((String)  MDC.get("remoteHost"),    "unknown"); // REMOTEHOST
        this.remotePort    = getNonNullValueOrFallBack((Integer) MDC.get("remotePort"),    -1);        // REMOTEPORT
        this.requestURL    = getNonNullValueOrFallBack((String)  MDC.get("requestURL"),    "unknown"); // REQUESTURL
        this.requestMethod = getNonNullValueOrFallBack((String)  MDC.get("requestMethod"), "unknown"); // REQUESTMETHOD
        this.mime          = getNonNullValueOrFallBack((String)  MDC.get("mime"),          "unknown"); // MIME
      }
    
      public static <E> E getNonNullValueOrFallBack(E value, E fallBack) {
        return (value != null) ? value : fallBack;
      }
    My appender is an ansynchronous, multithreaded appender which extends AppenderSkeleton, but I construct the LoggingEventWrapper in the append call, so the MDC.get() calls are in the same thread as the MDC.put() calls, which is essential since they store their information in a ThreadLocal.

    I've also verified two things:
    1. The MDC information is indeed being stored correctly.
    2. The MDC information is not being lost before getting to the appender.

    I verified point two by adding redeploying my application with the following postHandle definition to verify that the MDC information will still present even after the request was completed (and, hence, after any logging calls in my controllers had already returned control from the appender to the application):

    Code:
      public void postHandle(HttpServletRequest req, HttpServletResponse res, Object handler, ModelAndView modelAndView) throws Exception {
        User user = (User) req.getSession().getAttribute("user");
        log.info("postHandle presence of MDC test: " + MDC.get("userName"));
      }
    In summary, the MDC information is there all along, but somehow my appender cannot get to it. Testing places all the right values in the database, and production only stores null in those fields. Unfortunately, I can't debug it because it only happens on production, and I can't duplicate it anywhere else.

    I'm using log4j 1.2.8 on the production server along with a Sun Java 5 JVM running on JBoss 4.0.3SP1. The application is using Spring 2.0.5.

    The only significant difference between the two severs that when I type "java -version" from the command line, testing lists "mixed mode, sharing" after the build number and production lists only "mixed mode".

    This is a really strange bug, and any help would be greatly appreciated.

  • #2
    BTW, I've confirmed that the log4j jars on my testing and production servers are completely identical (bytewise comparison).

    Comment

    Working...
    X