[JIRA] Created: (LBCLASSIC-272) Automatic MDC inheritance with thread pools cases false data printed in the log
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
[ http://jira.qos.ch/browse/LBCLASSIC-272?page=com.atlassian.jira.plugin.syste... ] 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
[ http://jira.qos.ch/browse/LBCLASSIC-272?page=com.atlassian.jira.plugin.syste... ] Lóránt Pintér commented on LBCLASSIC-272: ----------------------------------------- Apparently I was under the wrong impression that Log4J had no MDC inheritance. Alas, this is still a problem.
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
[ http://jira.qos.ch/browse/LBCLASSIC-272?page=com.atlassian.jira.plugin.syste... ] Ralph Goers commented on LBCLASSIC-272: --------------------------------------- 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.
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
participants (3)
-
Lóránt Pintér (JIRA) -
Ralph Goers (JIRA)
-
Thomas Beckmann (JIRA)