Log4j 2
  1. Log4j 2
  2. LOG4J2-705

Async logger loses thread context stack for events

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-rc2
    • Fix Version/s: 2.0
    • Component/s: Core
    • Labels:
      None

      Description

      I've enabled the async logger and created some log message with values in thread context stack. However, the logged message does not contain any of these items.

      Looking at the sources, it seems that AsyncLogger.logMessage() needs to clone the stack instead of using ThreadContext.getImmutableStack() (line 260). This is because getImmutableStack() method returns the same stack as original - getting the real one from thread local storage. So when passed to another thread (as async does), the same stack "looks" into different thread and returns empty list. It is even possible to break this "immutable" stack when you create your own appender and use ThreadContext.push() in append() method. This will affect the message being logged.

      Simple solution is to replace getImmutableStack() method in AsyncLogger.logMessage() (line 260) with ThreadContext.cloneStack(). But I'm not sure if this is the right way.

        Activity

        Transition Time In Source Status Execution Times Last Executer Last Execution Date
        Open Open In Progress In Progress
        2d 21h 59m 1 Remko Popma 12/Jul/14 07:29
        In Progress In Progress Resolved Resolved
        4h 53m 1 Remko Popma 12/Jul/14 12:23
        Resolved Resolved Closed Closed
        2d 36m 1 Martin Frydl 14/Jul/14 13:00
        Martin Frydl made changes -
        Status Resolved [ 5 ] Closed [ 6 ]
        Hide
        Martin Frydl added a comment -

        Tested on revision 1610388, works fine. Thanks.

        Show
        Martin Frydl added a comment - Tested on revision 1610388, works fine. Thanks.
        Remko Popma made changes -
        Status In Progress [ 3 ] Resolved [ 5 ]
        Fix Version/s 2.0 [ 12324757 ]
        Resolution Fixed [ 1 ]
        Hide
        Remko Popma added a comment -

        Fixed in revision 1609903.

        Please verify and close.

        Show
        Remko Popma added a comment - Fixed in revision 1609903. Please verify and close.
        Hide
        Remko Popma added a comment - - edited

        I'm surprised this has not been found earlier. This problem has been there from the start...

        The objective of both DefaultThreadContextStack and DefaultThreadContextMap is to be a copy-on-write implementation, the reasoning being that modifications to the map/stack will be rare, and this will allow us to avoid copying the stack/map for every single log event. Each log event is given a stack/map instance obtained with a call to ThreadContext.getImmutableStack() and ThreadContext.getImmutableMap().

        For the map, this method returns the internal immutable map. This is safe because with every modification that map will be replaced with another instance. With the stack we were also returning the internal representation, but as you pointed out, the DefaultThreadContextStack implementation stores the data in a thread-local variable, so instances of this class are not suitable for passing to another thread because that other thread will not be able to access the data.

        The solution is to do something similar as we are doing with the map. The thread-local variable should keep an immutable stack instance that can safely be handed off to other threads. Every time the stack is modified, a new stack instance will be created and stored in the thread-local variable.

        This requires an API change: we need to add a method ThreadContextStack.getImmutableStackOrNull(), analogous to the existing ThreadContextMap.getImmutableMapOrNull() method.

        I doubt many users have custom ThreadContextStack implementations, so I doubt this API change will impact many users (if anyone at all).

        Show
        Remko Popma added a comment - - edited I'm surprised this has not been found earlier. This problem has been there from the start... The objective of both DefaultThreadContextStack and DefaultThreadContextMap is to be a copy-on-write implementation, the reasoning being that modifications to the map/stack will be rare, and this will allow us to avoid copying the stack/map for every single log event. Each log event is given a stack/map instance obtained with a call to ThreadContext.getImmutableStack() and ThreadContext.getImmutableMap() . For the map, this method returns the internal immutable map. This is safe because with every modification that map will be replaced with another instance. With the stack we were also returning the internal representation, but as you pointed out, the DefaultThreadContextStack implementation stores the data in a thread-local variable, so instances of this class are not suitable for passing to another thread because that other thread will not be able to access the data. The solution is to do something similar as we are doing with the map. The thread-local variable should keep an immutable stack instance that can safely be handed off to other threads. Every time the stack is modified, a new stack instance will be created and stored in the thread-local variable. This requires an API change: we need to add a method ThreadContextStack.getImmutableStackOrNull() , analogous to the existing ThreadContextMap.getImmutableMapOrNull() method. I doubt many users have custom ThreadContextStack implementations, so I doubt this API change will impact many users (if anyone at all).
        Hide
        Remko Popma added a comment -

        Your analysis of the problem is correct. The stack contents should not be kept in a ThreadLocal when passing to the appender thread. I'm working on a solution that preserves the current copy-on-write behaviour.

        Show
        Remko Popma added a comment - Your analysis of the problem is correct. The stack contents should not be kept in a ThreadLocal when passing to the appender thread. I'm working on a solution that preserves the current copy-on-write behaviour.
        Remko Popma made changes -
        Status Open [ 1 ] In Progress [ 3 ]
        Martin Frydl made changes -
        Attachment async-context-test.zip [ 12655217 ]
        Hide
        Martin Frydl added a comment - - edited

        Attached a test case - source and config file

        Show
        Martin Frydl added a comment - - edited Attached a test case - source and config file
        Hide
        Remko Popma added a comment -

        Can you please post the full contents of your log4j2.xml configuration file?

        Show
        Remko Popma added a comment - Can you please post the full contents of your log4j2.xml configuration file?
        Remko Popma made changes -
        Field Original Value New Value
        Assignee Remko Popma [ remkop@yahoo.com ]
        Martin Frydl created issue -

          People

          • Assignee:
            Remko Popma
            Reporter:
            Martin Frydl
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development