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

Automatic MDC inheritance with thread pools cases false data printed in the log

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 0.9.27
    • Fix Version/s: 1.1.5
    • Component/s: logback-classic
    • Labels:
      None
    • Environment:

      Applies to all Logback versions, specifically tested with Logback 0.9.27.

      Description

      MDC inheritance when used in conjunction with a thread pool can turn out to be malicious. Consider the following in a web server where each line in the log contains the current user's name.

      1. A web request comes in and processing is started on a thread
      2. Authenticate the user (on original thread)
      3. Put the user name into the MDC (on original thread)
      4. Create some Runnable and pass it to a thread pool to be run in the background (on thread pool thread)

      Let's take a look at the logs that are printed from the Runnable created in step 4.

      Without automatic MDC inheritance (e.g. when using Log4J) these log lines will contain no user name. This can be good or bad, depending on what you want. If you do want the user name in these log lines, you can explicitly transfer the MDC from the originating thread to the thread pool thread. If you don't want to print the user name for background tasks, you are already done. If you have no access to the thread pool or the Runnables, you simply get no MDC information.

      However, if you do have automatic MDC inheritance (as with Logback), the log lines will contain a user name, but not from the originating thread. The thread pool thread will instead inherit its MDC from the first thread that executed a Runnable on it. This can never be what you want. You can correct this by transferring the original MDC manually, or clearing it explicitly inside your Runnable. But if you forget to do this, or you don't have access to the thread pool and the Runnables, you will end up with corrupt data in your logs. The latter can happen if you are using some third-party API that maintains its own thread pool.

      I can see two ways to fix this issue:
      1) Make automatic MDC inhertance configurable from logback.xml. This is not a perfect solution: if you mix code that relies on MDC inheritance with code that relies on no MDC inheritance you will have no good value for this setting.
      2) Remove the automatic MDC inheritance feature altogether. Instead, Logback (or even better: SLF4J) could provide some utility classes to wrap Runnable's and Callable's in something like this:

      class MdcRetainingRunnable implements Runnable {
        private final Map context;
        public MdcRetainingRunnable {
          this.context = MDC.getCopyOfContextMap();
        }
      
        @Override
        public void run() {
          Map originalContext = MDC.getCopyOfContextMap();
          MDC.setContextMap(context);
          try {
            runWithMdc();
          } finally {
            MDC.setContextMap(originalContext);
          }
        }
      
        abstract protected runWithMdc();
      }
      

      I would prefer solution #2 as it provides for the rule of least astonishment.

        Activity

        Hide
        lptr Lóránt Pintér added a comment -

        A possible implementation of an MdcRetention utility class that could wrap Runnables, Callables and Executors with MDC-retaining wrappers.

        Show
        lptr Lóránt Pintér added a comment - A possible implementation of an MdcRetention utility class that could wrap Runnables, Callables and Executors with MDC-retaining wrappers.
        Hide
        lptr Lóránt Pintér added a comment -

        Apparently I was under the wrong impression that Log4J had no MDC inheritance. Alas, this is still a problem.

        Show
        lptr Lóránt Pintér added a comment - Apparently I was under the wrong impression that Log4J had no MDC inheritance. Alas, this is still a problem.
        Hide
        rgoers@apache.org Ralph Goers added a comment -

        I would very much disapprove of option 2 as such a change would break existing applications that upgrade.

        Option 1 isn't practical since the MDC isn't aware of the LoggerContext much less the configuration. As noted, a change in configuration would also break code that assumes the behavior to be one way or another.

        As a practical option the best resolution is to declare this as not a bug and make sure that user's using it in environments with Thread pools are aware of this. It would be helpful if http://logback.qos.ch/manual/mdc.html discussed using the MDC with thread pools. It already documents how the MDC is passed to worker threads.

        Show
        rgoers@apache.org Ralph Goers added a comment - I would very much disapprove of option 2 as such a change would break existing applications that upgrade. Option 1 isn't practical since the MDC isn't aware of the LoggerContext much less the configuration. As noted, a change in configuration would also break code that assumes the behavior to be one way or another. As a practical option the best resolution is to declare this as not a bug and make sure that user's using it in environments with Thread pools are aware of this. It would be helpful if http://logback.qos.ch/manual/mdc.html discussed using the MDC with thread pools. It already documents how the MDC is passed to worker threads.
        Hide
        t0mbeck Thomas Beckmann added a comment -

        We had the same problem and implemented a patch that allows one to choose between inheriting and non-inheriting ThreadLocals.
        Posted as feature request LOGBACK-624.

        Show
        t0mbeck Thomas Beckmann added a comment - We had the same problem and implemented a patch that allows one to choose between inheriting and non-inheriting ThreadLocals. Posted as feature request LOGBACK-624 .
        Hide
        fedotxxl Fedor Belov added a comment -

        Solved this problem using Lóránt Pintér's suggestion. Here is my groovy version:

        abstract class MdcRetainingCallable<V> implements Callable {
            private final Map context
        
            MdcRetainingCallable() {
                this.context = MDC.getCopyOfContextMap()
            }
        
            @Override
            V call() {
                V answer = null
                Map originalContext = MDC.getCopyOfContextMap()
                MDC.setContextMap(context);
        
                try {
                    answer = withMdc();
                } finally {
                    MDC.setContextMap(originalContext);
                }
        
                return answer
            }
        
            abstract protected V withMdc();
        
            static MdcRetainingCallable cast(Closure c) {
                return ([withMdc: c] as MdcRetainingCallable)
            }
        }
        

        When I need to submit task to executorService I do following

        threadPool.submit(MdcRetainingCallable.cast { my_task_code })
        
        Show
        fedotxxl Fedor Belov added a comment - Solved this problem using Lóránt Pintér's suggestion. Here is my groovy version: abstract class MdcRetainingCallable<V> implements Callable { private final Map context MdcRetainingCallable() { this .context = MDC.getCopyOfContextMap() } @Override V call() { V answer = null Map originalContext = MDC.getCopyOfContextMap() MDC.setContextMap(context); try { answer = withMdc(); } finally { MDC.setContextMap(originalContext); } return answer } abstract protected V withMdc(); static MdcRetainingCallable cast (Closure c) { return ([withMdc: c] as MdcRetainingCallable) } } When I need to submit task to executorService I do following threadPool.submit(MdcRetainingCallable. cast { my_task_code })
        Hide
        ntnguyen Nhan Thuan Nguyen added a comment -

        Do we have a resolution for this issue?

        Show
        ntnguyen Nhan Thuan Nguyen added a comment - Do we have a resolution for this issue?
        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:
            lptr Lóránt Pintér
          • Votes:
            13 Vote for this issue
            Watchers:
            11 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: