TraceSource & Shared Trace Listener bug

Hi!

I have found the following problem in TraceSource.

If I use several instances of TraceSource with one shared listener, and threads try to write their first event into TraceSource simultaniously, then several TraceListeners are created.

i.e.: I have multithreading application which works in the following way:

1. First thread creates 2 TraceSource's with name "Name1" and "Name2".

2. First thread creates second and third threads, and run them.

3. Second thread writes an event into first TraceSource.

4. Third thread writes an event into second TraceSource at the same moment as second thread.

After that both threads create TraceListener. I use my own TraceListener - MyTraceListener derived from XmlWriterTraceListener and I can catch both threads in MyTraceListener constructor.

If threads are not so fast and write their events into TraceSources successively, only one MyTraceListener is created.

Is there good workaroung

I used .NET reflector and found, that TraceSource really doesn't do anything to avoid this.

As per the documentation instance members of TraceSource are not thread safe. Therefore any time you attempt to access instance members of the class on multiple threads you must lock them first. This is pretty standard across the entire framework.

Therefore this is not a bug but rather a race condition in your code that you need to resolve.

Michael Taylor - 12/15/06

Yes, I know, that TraceSource instance members are NOT thread safe. But I don't access to instance members by several threads. I create 2 TraceSource's. And the first thread access the first TraceSource instance, the second thread access the second TraceSource instance.

I use the following config file:

<system.diagnostics>

<sources>

<source name="Infrastructure.DiagnosticsUnitTests.Multithreading"

switchValue="Error">

<listeners>

<add name="MyXmlListener" />

</listeners>

</source>

<source name="Infrastructure.DiagnosticsUnitTests.Multithreading1"

switchValue="Error">

<listeners>

<add name="MyXmlListener" />

</listeners>

</source>

</sources>

<sharedListeners>

<add name="MyXmlListener"

type="Infrastructure.Diagnostics.CyclicTraceListener,Infrastructure.Diagnostics"

initializeData=".\Multithreading\Trace.e2e" />

</sharedListeners>

</system.diagnostics>

You should only have one listener for each shared listener. This is the correct behavior. Imagine if you had a separate instance for each source. If you were to use a TextWriterTraceListener in the shared listeners collection then you'd end up continually overwriting the logs from another source. The fact that you normally get two listeners is a problem. You can verify that you should only have one shared listener by invoking the sources within the same thread.

Now the problem arises deep within the subsystem when it loads your source. The source has an associated listener so it'll try to load the listener. Since the listener does not specify a type it is a shared listener. That means the subsystem will go to the shared listeners collection (of which there is only one) and try to find the named listener there. It will find the named listener. Now it asks the named listener for an instance of the listener class so it can associate it with the source.

Within the method it'll first see if the listener has already been created and, if not, create it. The TS problem comes in the fact that this method nor its caller is static and therefore is not TS. Therefore it is possible for multiple threads attempting to use the same shared listener to create the listener multiple times. Therefore even though you are not using the same source on multiple threads you are still trying to use the same listener on multiple threads. Listeners themselves must be thread safe for logging information but the creation process is not thread safe.

Is there a workaround Yes and no. Ultimately it would be nice if the shared listener collection was made TS. This would require a change in the framework as it currently isn't. A coding work around is to ensure that the source listeners are created in a thread-safe manner.

A final question that you might ask is whether the subsystem is smart enough to realize after it created the listener but before it assigned the listener to its internal property that it already existed (often done in TS environments). The answer is no. Once it realizes the listener does not exist yet it'll create it and then store itself internally in an un-TS manner. Again it is an instance method so it isn't required to be TS.

Michael Taylor - 12/18/06

Ok, I really want all TraceSources to create only one shared TraceListener. TraceListeners are not required to be TS, so MyTraceListener is not required to be TS also. And so it's responsibility of TraceSource to create only one shared TraceListener. But TraceSource.Initialize private method doesn't provide this. It locks only itself. It's that bug which I said about in my post.

May be it'll be better, if it also locks DiagnosticsConfiguration.Sources variable. But it's only assumption. I hope MS will fix it.

In my project I have many components which are supposed to use standard TraceSource configured via config file. I see atleast 2 solutions.

1. Create my own TraceSource and override part of base TraceSource functionality.

2. At the beging of initialization create temporary TraceSource, walk through config file and add all shared trace listeners to it.

Both solutions don't seem good. And I hope to find another one or to get hotfix from MS:).

I would tend to disagree. Locking a shared list within an instance method is going to cause performance issues.

Instead, if I were MS (which I'm not), I would recommend that the GetRuntimeObject method of the ListenerElement (which is ultimately responsible for finding and hooking up listeners to the source) take a lock on itself (or a private field) after it realizes that it hasn't created the listener instance yet.

public TraceListener GetRuntimeObject ( )
{
if (_runtimeObject != null)
return (TraceListener)_runtimeObject;

//Lock the object so we can change it (or use a private field lock)
lock(this)
{
//Check again as someone might have already created it
if (_runtimeObject != null)
return (TraceListener)_runtimeObject;

//Do work
...
};

return (TraceListener)_runtimeObject;
}

The above method would avoid creating an extra listener instance but would block any callers while the creation occurred. It would however be TS. However since the actual method is not required to be TS then MS was justified in not making it that way. They probably didn't think about the fact that shared listeners in multiple threads could cause a problem. Perhaps they'll remedy this in a SP. It is technically a problem in any listener configured through a configuration file that could be used in multiple threads. I'd recommend reporting this as a bug to MS using the standard issue reporting options available to you.

Michael Taylor - 12/19/06

Yes, I agree. ListenerElement.GetRuntimeObject method should have such lock. And this solution have better performance. But my idea isn't bad because TraceSource.Initialize method body is not accessed very often, only once per TraceSource instance.

I've submitted the bug to MS, so will wait for answer from them.