[logback-dev] [JIRA] Updated: (LBCLASSIC-272) Automatic MDC inheritance with thread pools cases false data printed in the log

[Lóránt Pintér (JIRA)]

     [ http://jira.qos.ch/browse/LBCLASSIC-272?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Lóránt Pintér updated LBCLASSIC-272:
------------------------------------

    Attachment: mdc-test.zip

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

> Automatic MDC inheritance with thread pools cases false data printed in the log
> -------------------------------------------------------------------------------
>
>                 Key: LBCLASSIC-272
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-272
>             Project: logback-classic
>          Issue Type: Bug
>          Components: Other
>    Affects Versions: 0.9.27
>         Environment: Applies to all Logback versions, specifically tested with Logback 0.9.27.
>            Reporter: Lóránt Pintér
>            Assignee: Logback dev list
>         Attachments: mdc-test.zip
>
>
> 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:
> {code}
> 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();
> }
> {code}
> I would prefer solution #2 as it provides for the rule of least astonishment.

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira