Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-1189

AccessEvent clears attributes on jetty recycled requests

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 1.1.6
    • Fix Version/s: 1.1.10
    • Component/s: logback-access
    • Labels:
      None
    • Environment:

      In combination with jetty9 for access logs.

      Description

      Jetty recycles its request objects, clearing its attributes maps amongst others, to make them ready for next request. This make it fail when trying to put request attributes into access log using patterns with "%reqAttribute{}" in them.

      Now, there has been some work to try and circumvent this via this PR https://github.com/qos-ch/logback/pull/240 which copies the request attributes into a local "attributeMap" instance and the method AccessEvent.getAttribute properly uses this if non-null.

      But, problem is that "AccessEvent.prepareForDeferredProcessing" is called twice - once when appended by request thread, and then again by async worker thread here https://github.com/qos-ch/logback/blob/master/logback-core/src/main/java/ch/qos/logback/core/OutputStreamAppender.java#L205
      And because "AccessEvent.prepareForDeferredProcessing" unconditionally clears the local map, the request attributes are lost (if and when jetty get to recycle before async appender appends).
      This happens in my code, but I can see others have hit the same issue here https://github.com/logstash/logstash-logback-encoder/issues/94 too.

      I believe this is the problematic code (https://github.com/qos-ch/logback/blob/master/logback-access/src/main/java/ch/qos/logback/access/spi/AccessEvent.java#L368-L385):

          private void copyAttributeMap() {
      
              if (httpRequest == null) {
                  return;
              }
      
              attributeMap = new HashMap<String, Object>();
      
              Enumeration<String> names = httpRequest.getAttributeNames();
              while (names.hasMoreElements()) {
                  String name = names.nextElement();
      
                  Object value = httpRequest.getAttribute(name);
                  if (shouldCopyAttribute(name, value)) {
                      attributeMap.put(name, value);
                  }
              }
          }
      

      A recycled request is not nullified in the AccessEvent, so this code:

              if (httpRequest == null) {
                  return;
              }
      
              attributeMap = new HashMap<String, Object>();
      

      will clear the local map.

      I propose adding an extra check if "attributeMap" is not-null, to fix the problem, like this:

          private void copyAttributeMap() {
      
              if (httpRequest == null) {
                  return;
              }
      
              // already set - mimicks what getAttribute is doing
              if (attributeMap != null) {
                  return;
              }
      
              attributeMap = new HashMap<String, Object>();
      
              Enumeration<String> names = httpRequest.getAttributeNames();
              while (names.hasMoreElements()) {
                  String name = names.nextElement();
      
                  Object value = httpRequest.getAttribute(name);
                  if (shouldCopyAttribute(name, value)) {
                      attributeMap.put(name, value);
                  }
              }
          }
      

        Attachments

          Activity

            People

            • Assignee:
              ceki Ceki Gülcü
              Reporter:
              polesen Per Olesen
            • Votes:
              1 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: