[
https://issues.apache.org/jira/browse/LOG4NET-562?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15960517#comment-15960517
]
Alexander Houben commented on LOG4NET-562:
------------------------------------------
Hello Husain,
I think the observed behavior lies in the implementation of Parallel.ForEach.
All your assumptions seem correct to me except that Parallel.ForEach does not
execute its actions on a separate thread or separate task each.
If you look at mscorlib with ILSpy and find
System.Threading.Tasks.Parallel.ForEach you'll see that it does some heavy
optimization to find the right ratio of threads/tasks and load.
IMHO it may be reusing a task where your "x-correlation-id" was set (if (i==3))
for other values of i, this is why you are seeing multiple modified log outputs.
cheers,
alex
> LogicalThreadContext is not per Thread
> --------------------------------------
>
> Key: LOG4NET-562
> URL: https://issues.apache.org/jira/browse/LOG4NET-562
> Project: Log4net
> Issue Type: Bug
> Components: Other
> Affects Versions: 2.0.8
> Environment: Windows 10, Visual Studio 17, .NET Framework 4.5.2
> Reporter: Husain Alshehhi
>
> LogicalThreadContext values are spread to many threads when they shouldn't.
> This is an example:
> {code:title=console.cs|borderStyle=solid}
> LogicalThreadContext.Properties["x-corralation-Id"] =
> "original-value";
> var list = new List<int> {1, 2, 3, 4, 5, 6, 7, 8, 9, 0};
> Parallel.ForEach(list, (i) =>
> {
> if (i == 3)
> LogicalThreadContext.Properties["x-corralation-Id"] =
> "modified-value";
> logger.Info($"thread {i}.");
> });
> {code}
> this is the result
> {code:title=badresult.txt|borderStyle=solid}
> {"timestamp":"2017-04-05T12:31:41.117Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 1.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.132Z", "level":"INFO", "x-corralation-Id" :
> "modified-value", "logger":"logger", "message":"thread 3.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" :
> "modified-value", "logger":"logger", "message":"thread 4.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" :
> "modified-value", "logger":"logger", "message":"thread 6.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" :
> "modified-value", "logger":"logger", "message":"thread 8.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" :
> "modified-value", "logger":"logger", "message":"thread 0.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.219Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 7.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.179Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 5.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 2.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.234Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 9.", "data":(null)}
> {code}
> This is what I was expecting:
> {code:title=goodresult.txt|borderStyle=solid}
> {"timestamp":"2017-04-05T12:31:41.117Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 1.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.132Z", "level":"INFO", "x-corralation-Id" :
> "modified-value", "logger":"logger", "message":"thread 3.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 4.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 6.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 8.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.274Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 0.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.219Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 7.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.179Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 5.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.273Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 2.", "data":(null)}
> {"timestamp":"2017-04-05T12:31:41.234Z", "level":"INFO", "x-corralation-Id" :
> "original-value", "logger":"logger", "message":"thread 9.", "data":(null)}
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
