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
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
_______________________________________________
logback-dev mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-dev
