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

MDC Adapter with configurable InheritableThreadLocal

    Details

    • Type: Improvement
    • Status: Resolved
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 0.9.28
    • Fix Version/s: 1.1.5
    • Component/s: logback-classic
    • Labels:
      None

      Description

      In our application we use a sifting file appender to log bot requests to a different log file than normal user requests. We have several sensor and aggregation threads that are started on different times that also have some logging output.

      My Problem:
      Log statements from request-independent threads are posted to bot.log and main.log on random.

      My Solution:
      I patched the LogbackMDCAdapter to be configureable by a system variable, to disable inheritance of the thread local member "copyOnInheritThreadLocal".
      The patched version defaults to old behavior, so it doesn't change if you do not configure it.
      To disable inheritance of that member, just pass "logback.threadlocal.inherit.copy=false" to the JVM.

      I applied the patch to Version 0.9.28 and tested it with our application. Maybe other logback users also want to configure logback in that way.

      1. LogbackMDCAdapter.java
        6 kB
        Alexander Treptow
      2. LogbackMDCAdapterTest.java
        5 kB
        Alexander Treptow

        Activity

        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited

        Records (see LOGBACK-355 and LOGBACK-489, seem to indicate that logback's MDC behavior is a heritage (pun intended) of log4j. SVN commits for log4j dating back to 2001 show that MDC values were "always" inherited in log4j.

        Contrary to the impression one might get by reading the comments above, the inheritance approach is not completely brain dead. Indeed, if MDC values were not automatically inherited by child threads, the parent thread would have to somehow pass the MDC values to its children. With automatic inheritance, the child threads "only" needs to cull values it does not want to inherit. This may be counter-intuitive for the uninitiated and require some extra code, admittedly increasing accidental complexity.

        In our present predicament, the best I can think of is to stop propagation to child threads for keys with a certain pattern, say a '*' suffix. Example:

          // no propagation to child threads
          MDC.put("activemq.broker*",  brokerName)  
        

        I believe this would nicely address the ActiveMQ case.

        More wholesale approaches, such as disabling MDC inheritance for the whole JVM, may have unintended consequences and are consequently unacceptable in my opinion. Adding MDC values disabling MDC inheritance for child threads as suggested by David Roussel is not much better as there might exist MDC values for which inheritance was expected by some other programmer.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - - edited Records (see LOGBACK-355 and LOGBACK-489 , seem to indicate that logback's MDC behavior is a heritage (pun intended) of log4j . SVN commits for log4j dating back to 2001 show that MDC values were "always" inherited in log4j. Contrary to the impression one might get by reading the comments above, the inheritance approach is not completely brain dead. Indeed, if MDC values were not automatically inherited by child threads, the parent thread would have to somehow pass the MDC values to its children. With automatic inheritance, the child threads "only" needs to cull values it does not want to inherit. This may be counter-intuitive for the uninitiated and require some extra code, admittedly increasing accidental complexity. In our present predicament, the best I can think of is to stop propagation to child threads for keys with a certain pattern, say a '*' suffix. Example: // no propagation to child threads MDC.put( "activemq.broker*" , brokerName) I believe this would nicely address the ActiveMQ case. More wholesale approaches, such as disabling MDC inheritance for the whole JVM, may have unintended consequences and are consequently unacceptable in my opinion. Adding MDC values disabling MDC inheritance for child threads as suggested by David Roussel is not much better as there might exist MDC values for which inheritance was expected by some other programmer.
        Hide
        sarah Sarah added a comment -

        When Log4j was written, and probably when SLF4J & Logback were written, propagating to child threads was probably the right thing to do: it would match the expected/desired behavior for most people. I don't believe this is true anymore. People who are developing applications on the JVM today aren't as likely to be spinning off random threads here and there. Instead, they're quite likely to be using pooled fork-join executors and things like Akka actors.

        In these more modern architectures, MDC inheritance is a disaster: it leaks information and breaks application state in surprising ways unless you override every utility that ever creates its own threads in these ways. Where I work, we have a non-blocking application stack based on Akka (we're using Scala, but it would be just as bad in Java). We looked at patching all the thread pools to clear the MDC on thread start and concluded it was both infeasible and too error prone, so we ended up forking Logback and creating a jar that has no inheritance. It was surprising to us that random threads that had never run a job had Job IDs and User IDs in their MDCs.

        I don't have any data to back this up, but I would guess that this kind of scenario constitutes the majority of new applications that are or will use Logback: MDC inheritance will be a surprising problem rather than a nice feature. (There's also a major asymmetry in the failure modes: leaking information is generally a much more dangerous kind of failure than losing context.)

        I do believe there is a legitimate reason to maintain backwards compatibility here. My suggestion is that the user should be able to plug in a callback object in the Logback config indicating which keys should be propagated to child threads. This could be PropagateAll (legacy behavior), PropagateNone, PropagateRegex. I would suggest that the default should become PropagateNone, for the reasons I describe above, but making it configurable would probably make everybody happy and prevent more people from forking Logback (as my company has done, privately).

        Show
        sarah Sarah added a comment - When Log4j was written, and probably when SLF4J & Logback were written, propagating to child threads was probably the right thing to do: it would match the expected/desired behavior for most people. I don't believe this is true anymore. People who are developing applications on the JVM today aren't as likely to be spinning off random threads here and there. Instead, they're quite likely to be using pooled fork-join executors and things like Akka actors. In these more modern architectures, MDC inheritance is a disaster: it leaks information and breaks application state in surprising ways unless you override every utility that ever creates its own threads in these ways. Where I work, we have a non-blocking application stack based on Akka (we're using Scala, but it would be just as bad in Java). We looked at patching all the thread pools to clear the MDC on thread start and concluded it was both infeasible and too error prone, so we ended up forking Logback and creating a jar that has no inheritance. It was surprising to us that random threads that had never run a job had Job IDs and User IDs in their MDCs. I don't have any data to back this up, but I would guess that this kind of scenario constitutes the majority of new applications that are or will use Logback: MDC inheritance will be a surprising problem rather than a nice feature. (There's also a major asymmetry in the failure modes: leaking information is generally a much more dangerous kind of failure than losing context.) I do believe there is a legitimate reason to maintain backwards compatibility here. My suggestion is that the user should be able to plug in a callback object in the Logback config indicating which keys should be propagated to child threads. This could be PropagateAll (legacy behavior), PropagateNone , PropagateRegex . I would suggest that the default should become PropagateNone , for the reasons I describe above, but making it configurable would probably make everybody happy and prevent more people from forking Logback (as my company has done, privately).
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment -

        The Akka argument is quite convincing. The configurable PropagateX idea is pretty nice as well. Thank you for your valuable feedback Sarah.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - The Akka argument is quite convincing. The configurable PropagateX idea is pretty nice as well. Thank you for your valuable feedback Sarah .
        Hide
        jhuxhorn Joern Huxhorn added a comment -

        Log4j 2 is doing something similar in the Map<String, String> part of their ThreadContext, using ThreadLocal by default but providing the ability to configure the use of InheritableThreadLocal if desired.

        The related issue is LOG4J2-479 - Use of InheritableThreadLocal in Map ThreadContext is dangerous and unhelpful.
        It was fixed during the rc-phase of 2.0.

        Show
        jhuxhorn Joern Huxhorn added a comment - Log4j 2 is doing something similar in the Map<String, String> part of their ThreadContext , using ThreadLocal by default but providing the ability to configure the use of InheritableThreadLocal if desired. The related issue is LOG4J2-479 - Use of InheritableThreadLocal in Map ThreadContext is dangerous and unhelpful . It was fixed during the rc-phase of 2.0.
        Hide
        noreply.ceki@qos.ch Ceki Gulcu added a comment -

        Fixed by commit aa7d584. Given that it has proven to be unhelpful and even dangerous, MDC values are no longer inherited by child values.

        Show
        noreply.ceki@qos.ch Ceki Gulcu added a comment - Fixed by commit aa7d584 . Given that it has proven to be unhelpful and even dangerous, MDC values are no longer inherited by child values.

          People

          • Assignee:
            logback-dev@qos.ch Logback dev list
            Reporter:
            treptow Alexander Treptow
          • Votes:
            15 Vote for this issue
            Watchers:
            16 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: