Details
-
Bug
-
Resolution: Fixed
-
Major
-
1.1.6
-
None
-
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); } } }