Problems with MDC's inheritance
Hi, AFAIK, Log4J's MDC had no inheritance between threads -- this is a new feature introduced in Logback. However, when you are using thread pools, this new feature can cause a lot of trouble, especially when moving to Logback from a different logging system. Consider the following situation: you have a web application where you use the MDC to keep track of which user is logged in. You do certain things on the request processing thread. There are other certain things that you want to execute "in the background". You want to print the originating user's name in the logs for both "foreground" and "background" tasks. In such a case the Runnable's you place on the thread pool's queue need to take care of retaining the MDC from the originating thread. If you do this, and do this in every instance, no problem. However, it happens that you forget to do this. In such a case, with Log4J's non-inherited MDC, you would get no user name printed in the logs for background tasks, because your thread pool threads would not have anything in the MDC. That's not a good situation, but at least you can spot that there's something missing. OTOH, if you forget to retain the MDC manually with Logback, instead of no data you get false data in the logs. This is because thread pool threads are going to be created with random parent threads. These thread pool threads will then inherit the MDC from these threads, and *keep* the MDC. So future Runnables passed to these threads will print their starting thread's username. False data is worse than no data, so it would be nice to avoid this. Is there a way to make Logback's MDC inheritance configuratble? Like, in logback.xml you could set if you wanted to use InheritableThreadLocals or not. If that doesn't work, it might even be better to have no inheritance at all. What do you think? Regards, Lorant
Hello,
False data is worse than no data, so it would be nice to avoid this. Is
I've been bitten by this as well and agree that inheritance as the default is rather dangerous, especially because using thread pools is considered good practice and thus quite common. Regards, -Matthias -- For a successful technology, reality must take precedence over public relations, for nature cannot be fooled. (R.P. Feynman)
On the other hand it is quite handy for non-pooled threads. The MDC may contain information which is complex to create and unrelated to the code creating the threads. I did not know about inheritance a few months ago, so I was prepared to make a mess by passing unrelated information deep in a call chain. It was quite a nice surprise that MDC data automagically appeared in the log files because of the inheritance. On 2011.05.31. 0:47, Matthias Treydte wrote:
Hello,
False data is worse than no data, so it would be nice to avoid this. Is I've been bitten by this as well and agree that inheritance as the default is rather dangerous, especially because using thread pools is considered good practice and thus quite common.
Regards, -Matthias
Hello,
call chain. It was quite a nice surprise that MDC data automagically appeared in the log files because of the inheritance.
I absolutely agree it's a nice feature and helps to keep the code clean, just as it did for you. But I also think that Lóránt's and my objections are valid as well, if not simply because thread pools are so common. So having the possibility to turn it on/off would be pretty helpful. I think the "wrong data is worse than no data" argument is pretty strong. Kind regards, -Matthias -- For a successful technology, reality must take precedence over public relations, for nature cannot be fooled. (R.P. Feynman)
Hm, there's more trouble here then what first meets the eye. Originally I thought that malicious MDC inheritance caused problems only if you were careless, and forgot to either clear or retain the MDC information when switching threads. But there are situations when you don't have any kind of control over the ThreadPool, or the Runnables and Callables that get executed on it. Think of a third-party library that uses a java.util.Timer or java.util.concurrent.ThreadPoolExecutor behind an API that exposes none of the threading logic, so you don't have a way to call MDC.setContextMap() anywhere. In this case you will end up with polluted MDCs everywhere. I've created an issue for this: http://jira.qos.ch/browse/LBCLASSIC-272 <http://jira.qos.ch/browse/LBCLASSIC-272>Lorant On Tue, May 31, 2011 at 10:52, Matthias Treydte <waldheinz@gmail.com> wrote:
Hello,
call chain. It was quite a nice surprise that MDC data automagically appeared in the log files because of the inheritance.
I absolutely agree it's a nice feature and helps to keep the code clean, just as it did for you. But I also think that Lóránt's and my objections are valid as well, if not simply because thread pools are so common. So having the possibility to turn it on/off would be pretty helpful. I think the "wrong data is worse than no data" argument is pretty strong.
Kind regards, -Matthias
-- For a successful technology, reality must take precedence over public relations, for nature cannot be fooled. (R.P. Feynman) _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user
participants (3)
-
Hontvári József Levente -
Lóránt Pintér -
Matthias Treydte