Memory leak in web.filter.Log4jNestedDiagnosticContextFilter and web.context.request.Log4jNestedDiagnosticContextInterceptor, because never calling org.apache.log4j.NDC.remove() [SPR-5103]

[spring-issuemaster]

Attila Király opened SPR-5103 and commented

Using org.springframework.web.filter.Log4jNestedDiagnosticContextFilter or org.springframework.web.context.request.Log4jNestedDiagnosticContextInterceptor can easily lead to severe memory leak.

These classes use org.apache.log4j.NDC (http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/NDC.html) to store thread specific logging data (like url, client info).

NDC holds these diagnostic information in a static Hashtable. The entries in these table have the current Thread as key and a Stack as value. Calling NDC's push() can create a new entry in the table if there were none, and push the parameter into the Stack. However pop() only removes elements from the Stack, and does not remove the whole entry. That's why NDC's api states that users should call NDC.remove(), to remove the entry from the static Hashtable.
However Spring is not calling that method (only push, pop). This is the reason why a reference is kept in the entries key to the Thread objects and this leads to OutOfMemory pretty fast (application servers with Thread pooling could be not affected but those creating new Thread objects are).

Log4j api says that the best place to call NDC.remove(), would be at the end of the Thread run, but thats not configable in case of an application server.

So there could be more possibility to fix this:

1. Never call NDC.remove() but state in the api that user should be aware of this.
2. Call NDC.remove() always (this is not appropiate for those who use NDC before Log4jNestedDiagnosticContextFilter too).
3. Call NDC.remove() if NDC.getDepth() returns the same in beforeRequest, afterRequest (could still lead to memory leak, if someone uses push without a pairing pop).
4. Make it configable in the filter if it should call NDC.remove() or not (making the removal the default option).
5. Make a cleaning thread and call NDC.remove() there because NDC.remove() removes all not alive Thread objects also from the Hashtable (this could be an overkill for this).

---

Affects: 2.5.5

[spring-issuemaster]

Attila Király commented

By 3. I made a mistake. It should have been:
3. Call NDC.remove() if NDC.getDepth() returns 0 (could still lead to memory leak, if someone uses push without a pairing pop).

[spring-issuemaster]

Juergen Hoeller commented

Frankly, I think Log4J's NDC facility is a bit mis-designed there, since it could automatically remove the entry when no elements are left for a given thread. It could also use weak references, I suppose...

Anyway, we'll try to work around this from Spring's side. Fortunately those Log4jNestedDiagnosticContextFilter/Interceptor classes are completely optional, which is why I don't consider this as critical from the framework's perspective.

Juergen

[spring-issuemaster]

Attila Király commented

I agree with you that this would be best fixed in log4j however there are several reasons why this won't happen in the near future.

There was already a patch to rewrite NDC with ThreadLocal-s instead of the static Hashtable. It was planned to be released with the 1.3 version, however that version got abandoned and they focus now for the 2.0. https://issues.apache.org/bugzilla/show_bug.cgi?id=25890

Log4j is not planing to modify the 1.2 branch with new enchantments only with bug fixes / small modifications. So they are not going to modify the current behaviour to remove the entry when the stack gets empty because it could affect performance when lot of push/pop is done. https://issues.apache.org/bugzilla/show_bug.cgi?id=45660

[spring-issuemaster]

Juergen Hoeller commented

We're simply calling "NDC.remove()" if "NDC.getDepth() == 0" after the pop() call now. This should be a good compromise, cleaning up after proper push/pop pairs.

Juergen