Logging multiple threads with nlog

Question

I use nlog logger in my project.

My program generates xml files based on data which i getting from sql server. I'm doing this with PLINQ. But also i have to log tracing info to be able make some investigations on exceptional cases on prod environment.

Result logs looks awful, when it came from multiple threads. For example:

Operation 1 started
Deserializing XXX
Operation 2 started
Deserializing XXX finished with status X
Filling XXX with data from Z
Deserializing YYY....

And its just for degree of parallelism 2.

I'd like to see result like this:

Operation 1 started
Deserializing XXX
Deserializing XXX finished with status X
Filling XXX with data from Z
Operation 1 finished
Operation 2 started    
Deserializing YYY....

I see some solutions, but they're not looking good enough:

1. Save logging data to some buffer and flush it when parallel task ends - I will be ought to pass context to all inner methods (looks terrible!).

2. Add some kind of prefix to logging message to help getting context for some messages - i have to pass prefix to every inner message (also looks terrible).

Is there some clean solutions for this problem?

Answer 1

In NLog config files, there is the ${threadid} syntax. Use it like this:

<target name="file" xsi:type="File"
     layout="${longdate} [${threadid}] ${level:uppercase=true} ${message} ${exception:format=tostring}"
     fileName="${basedir}/logs/log.txt"
     archiveFileName="${basedir}/logs/log.{#####}.txt"
     archiveAboveSize="10485760"
     archiveNumbering="Sequence"
     concurrentWrites="true"
     keepFileOpen="false" />

More info:
https://github.com/NLog/NLog/wiki/ThreadId-Layout-Renderer

I used it in production and generally it works. It is not perfect, but all operations (which I logged) is in sequence and this threadid describe which operation is in which ThreadId.