Log4j 2
  1. Log4j 2
  2. LOG4J2-479

Use of InheritableThreadLocal in Map ThreadContext is dangerous and unhelpful

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 2.0-rc1
    • Component/s: None
    • Labels:
      None

      Description

      Described here http://logging.apache.org/log4j/2.x/manual/thread-context.html
      The use of InheritableThreadLocal creates subtle and hard to track bugs while not really adding much useful. It is counterintuitive – I don't see why would anyone expect logging context to be inherited. But it breaks down completely when used with Thread Executors.

        Activity

        Hide
        Remko Popma added a comment -

        Could you elaborate on what problems you think can happen with the current implementation, and when these problems may occur (what may trigger them)?
        Also, do you propose a solution? If so, can you provide more detail?

        Show
        Remko Popma added a comment - Could you elaborate on what problems you think can happen with the current implementation, and when these problems may occur (what may trigger them)? Also, do you propose a solution? If so, can you provide more detail?
        Hide
        MK added a comment -

        Here's the scenario that I ran into:
        I am decorating all web request handlers with some log4j context map values using AOP
        Some of the requests kick off long-running jobs which are executed by a thread pool (ThreadExecutor)
        ThreadExecutor will kick of threads as needed
        So:
        user1 logs in, submits a batch job request
        threadExecutor launches a new thread which inherits the thread context with user1's context map
        user1 logs out
        user2 logs in
        submits a batch job. This batch job is going to be running in the same thread that user1 spawned, which is still annotated with user1's information. Bah.

        As a bonus, notice how when testing with just user1 everything appears to be working correctly.
        Actually, testing with 2 users will also likely work correctly, because 2nd user will start a new thread, also "correctly" annotated.

        It is generally knowns that InheritableThreadLocal does not work with thread pools for that reason.
        I do not really understand under what circumstances inheriting log context to a child thread is the desired behavior.
        As a matter of fact this is not what the ThreadContext.push() does. That stuff is not inherited and all is well.
        So my suggested fix is to just replace InheritableThreadLocal with a regular ThreadLocal. Or at least provide a simple out of the box way of switching.
        Plus both mechanisms should be consistent and the documentation (http://logging.apache.org/log4j/2.x/manual/thread-context.html) has to be fixed. There is a vague paragraph there talking about this problem but offering no sane solution.

        Show
        MK added a comment - Here's the scenario that I ran into: I am decorating all web request handlers with some log4j context map values using AOP Some of the requests kick off long-running jobs which are executed by a thread pool (ThreadExecutor) ThreadExecutor will kick of threads as needed So: user1 logs in, submits a batch job request threadExecutor launches a new thread which inherits the thread context with user1's context map user1 logs out user2 logs in submits a batch job. This batch job is going to be running in the same thread that user1 spawned, which is still annotated with user1's information. Bah. As a bonus, notice how when testing with just user1 everything appears to be working correctly. Actually, testing with 2 users will also likely work correctly, because 2nd user will start a new thread, also "correctly" annotated. It is generally knowns that InheritableThreadLocal does not work with thread pools for that reason. I do not really understand under what circumstances inheriting log context to a child thread is the desired behavior. As a matter of fact this is not what the ThreadContext.push() does. That stuff is not inherited and all is well. So my suggested fix is to just replace InheritableThreadLocal with a regular ThreadLocal. Or at least provide a simple out of the box way of switching. Plus both mechanisms should be consistent and the documentation ( http://logging.apache.org/log4j/2.x/manual/thread-context.html ) has to be fixed. There is a vague paragraph there talking about this problem but offering no sane solution.
        Hide
        Remko Popma added a comment -

        Can you confirm the desired behaviour? In the scenario you described:

        user1 logs in, (any logging in the web request handler thread should use this user's ThreadContext info),
        user1 thread submits a batch job request, threadExecutor launches a new thread which does not inherit any thread context, and
        any logging in thread pool thread should take place without any thread context info.

        Is this what you are trying to achieve?

        One way to accomplish this is to call ThreadContext.clear() at the start of any batch job Runnable or Callable that is submitted to the thread pool. Would that solve the issue?

        Show
        Remko Popma added a comment - Can you confirm the desired behaviour? In the scenario you described: user1 logs in, (any logging in the web request handler thread should use this user's ThreadContext info), user1 thread submits a batch job request, threadExecutor launches a new thread which does not inherit any thread context, and any logging in thread pool thread should take place without any thread context info. Is this what you are trying to achieve? One way to accomplish this is to call ThreadContext.clear() at the start of any batch job Runnable or Callable that is submitted to the thread pool. Would that solve the issue?
        Hide
        MK added a comment -

        Yes, this is the desired behavior and yes, ThreadContext.clear() does what I want, but how am I going to remember to put that line in every possible place where I'm using a thread pool? I'm working on a relatively small code base and can immediately think of 3 completely different thread pools. Shouldn't the logging library be getting out of my way in simple matters like this?

        Show
        MK added a comment - Yes, this is the desired behavior and yes, ThreadContext.clear() does what I want, but how am I going to remember to put that line in every possible place where I'm using a thread pool? I'm working on a relatively small code base and can immediately think of 3 completely different thread pools. Shouldn't the logging library be getting out of my way in simple matters like this?
        Hide
        Remko Popma added a comment -

        Hmm... I'm not sure how to proceed here.

        On the one hand, if an application needs some threads to log with ThreadContext info and some threads to log without ThreadContext info, then it would be reasonable to ask the application to control this. (It knows how to put stuff into the ThreadContext somewhere, so it should know how/when to take stuff out.)

        On the other hand, it is interesting that DefaultThreadContextMap uses an InheritableThreadLocal while DefaultThreadContextStack uses a plain ThreadLocal.

        It seems to me that the map implementation is inheritable on purpose and I hesitate to change this.
        Ralph, can you shed any light on this?

        Show
        Remko Popma added a comment - Hmm... I'm not sure how to proceed here. On the one hand, if an application needs some threads to log with ThreadContext info and some threads to log without ThreadContext info, then it would be reasonable to ask the application to control this. (It knows how to put stuff into the ThreadContext somewhere, so it should know how/when to take stuff out.) On the other hand, it is interesting that DefaultThreadContextMap uses an InheritableThreadLocal while DefaultThreadContextStack uses a plain ThreadLocal . It seems to me that the map implementation is inheritable on purpose and I hesitate to change this. Ralph, can you shed any light on this?
        Hide
        MK added a comment -

        One other thing I want to stress, is that missing thread context is very easy to spot and diagnose – we were initially using DefaultThreadContextStack and immediately knew why some of the decorations were missing.
        But the bug caused by the inheriting thread context is subtle, hard to notice because log lines are decorated and, furthermore, they are decorated correctly while you are developing in a single user environment. That's why I strongly prefer no inheritance of the thread context in this case.

        Show
        MK added a comment - One other thing I want to stress, is that missing thread context is very easy to spot and diagnose – we were initially using DefaultThreadContextStack and immediately knew why some of the decorations were missing. But the bug caused by the inheriting thread context is subtle, hard to notice because log lines are decorated and, furthermore, they are decorated correctly while you are developing in a single user environment. That's why I strongly prefer no inheritance of the thread context in this case.
        Hide
        Ralph Goers added a comment -

        Log4j 1.x used an InheritableThreadLocal for the MDC and a Hashtable with the current thread as the key for the NDC. Since the NDC is a Stack it doesn't make any sense for multiple threads to manipulate it. I believe Logback used to use an InheritableThreadLocal but does something different now that has the same effect (it copies the data from the parent thread). Our implementation is the same is these for compatibility. This means you will get the same behavior when you are using the SLF4J API. However, this issue has been raised a couple of times on the Logback and there are open Jira issues for it. The most logical proposal is one to allow a system property to control whether the child inherits from its parent.

        Show
        Ralph Goers added a comment - Log4j 1.x used an InheritableThreadLocal for the MDC and a Hashtable with the current thread as the key for the NDC. Since the NDC is a Stack it doesn't make any sense for multiple threads to manipulate it. I believe Logback used to use an InheritableThreadLocal but does something different now that has the same effect (it copies the data from the parent thread). Our implementation is the same is these for compatibility. This means you will get the same behavior when you are using the SLF4J API. However, this issue has been raised a couple of times on the Logback and there are open Jira issues for it. The most logical proposal is one to allow a system property to control whether the child inherits from its parent.
        Hide
        MK added a comment -

        I'll take a property

        Show
        MK added a comment - I'll take a property
        Hide
        Nick Williams added a comment - - edited

        In my opinion, we need to take one of two paths:

        1. Remove uses of InheritableThreadLocal completely.
        2. Make a system option to enable use of InheritableThreadLocal, but disable it by default so that values are not inherited unless specifically enabled.

        In applications that use thread pools to spin off long-running processes (and this is a lot of applications), an InheritableThreadLocal is dangerous. Before the thread pool is used for the first time, it is initially empty. It hasn't yet created any threads. If a thread sets the value in an InheritableThreadLocal and then borrows a thread from that pool, the pool will create a thread with the same InheritableThreadLocal values. That thread will then always have that value, even after the application returns it to the pool. Even worse, in a web application multiple applications could share a single thread pool, resulting in information leaking from one application to another.

        Show
        Nick Williams added a comment - - edited In my opinion, we need to take one of two paths: Remove uses of InheritableThreadLocal completely. Make a system option to enable use of InheritableThreadLocal , but disable it by default so that values are not inherited unless specifically enabled. In applications that use thread pools to spin off long-running processes (and this is a lot of applications), an InheritableThreadLocal is dangerous . Before the thread pool is used for the first time, it is initially empty. It hasn't yet created any threads. If a thread sets the value in an InheritableThreadLocal and then borrows a thread from that pool, the pool will create a thread with the same InheritableThreadLocal values. That thread will then always have that value, even after the application returns it to the pool. Even worse, in a web application multiple applications could share a single thread pool, resulting in information leaking from one application to another.
        Hide
        Remko Popma added a comment -

        Ralph, is disabled by default also what you were thinking?

        Show
        Remko Popma added a comment - Ralph, is disabled by default also what you were thinking?
        Hide
        Ralph Goers added a comment -

        Yes.

        Show
        Ralph Goers added a comment - Yes.
        Hide
        Remko Popma added a comment -

        I made changes to DefaultThreadContextMap so that it now uses a plain ThreadLocal by default. InheritableThreadLocal is used if system property isThreadContextMapInheritable has value "true".

        Also updated the Thread Context manual page (http://logging.apache.org/log4j/2.x/manual/thread-context.html ).

        Fixed in revision 1557551.
        Please verify and close.

        Show
        Remko Popma added a comment - I made changes to DefaultThreadContextMap so that it now uses a plain ThreadLocal by default. InheritableThreadLocal is used if system property isThreadContextMapInheritable has value "true" . Also updated the Thread Context manual page ( http://logging.apache.org/log4j/2.x/manual/thread-context.html ). Fixed in revision 1557551. Please verify and close.
        Hide
        Simon Billingsley added a comment -

        The ThreadContext.clear method was removed in 2.0-rc2 it is now called: clearAll
        There are additional clear methods: clearMap and clearStack - I don't know when these were introduced.

        This has caused issues with existing code that was written against 2.0-rc1

        Also, the manual page still mentions using the clear method to clear the stack (in the stack example) when it should be clearStack ?
        http://logging.apache.org/log4j/2.x/manual/thread-context.html

        Show
        Simon Billingsley added a comment - The ThreadContext.clear method was removed in 2.0-rc2 it is now called: clearAll There are additional clear methods: clearMap and clearStack - I don't know when these were introduced. This has caused issues with existing code that was written against 2.0-rc1 Also, the manual page still mentions using the clear method to clear the stack (in the stack example) when it should be clearStack ? http://logging.apache.org/log4j/2.x/manual/thread-context.html
        Hide
        Ralph Goers added a comment -

        clearStack has been around since the ContextStack was added to the ThreadContext - several years now. clear was renamed because it wasn't clear what it cleared. It was renamed clearMap. The clearAll method was added to clear both the stack and map.

        You can expect that these won't change again.

        Thanks for letting us know about the documentation error. We will get that fixed.

        Show
        Ralph Goers added a comment - clearStack has been around since the ContextStack was added to the ThreadContext - several years now. clear was renamed because it wasn't clear what it cleared. It was renamed clearMap. The clearAll method was added to clear both the stack and map. You can expect that these won't change again. Thanks for letting us know about the documentation error. We will get that fixed.

          People

          • Assignee:
            Remko Popma
            Reporter:
            MK
          • Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development