Threading issue in Logging Application Block?

Topics: Logging Application Block
Mar 20, 2007 at 12:07 AM
Hi All, I just started using the Enterprise Library. I am seeing fairly frequent InvalidOperationException exceptions in the Logging Application Block code. My app has multiple threads using code like this:

using (new Tracer("TraceExecution"))

I trapped one exception in LogWriter.cs in the foreach here:

SecurityPermission(SecurityAction.Demand, Flags = SecurityPermissionFlag.UnmanagedCode)
private bool AddTracingCategories(LogEntry log, bool replacementDone)
// add tracing categories
foreach (string tracingOperation in Trace.CorrelationManager.LogicalOperationStack)
// must take care of logging categories..
if (!log.Categories.Contains(tracingOperation))
if (!replacementDone)
log.Categories = new List<string>(log.Categories);
replacementDone = true;
return replacementDone;

The exception occurs because the collection has changed while iterating through using the foreach.

I don't know whether this means that I have run foul of this thread safety warning in the documentation at ms-help://MS.VSCC.v80/MS.VSIPCC.v80/ms.EntLib.2006Jan/EnterpriseLibraryReference/html/TMicrosoftPracticesEnterpriseLibraryLogging_Tracer.htm :

"Any instance members are not guaranteed to be thread safe."

Any expert out there able to clarify this for me? As it happens, I no longer need the Tracers on more than one thread, so this might 'go away', but now I am curious. Is this a bug, or have I not fully understood the warning?

Thanks in advance

Mar 20, 2007 at 12:08 AM
Oh, what happened to all my fancy tabs?
Mar 20, 2007 at 4:07 PM

Would it be possible to post one of the exact exceptions you're getting, along with the stack trace? This would really help us track down the problem.

Mar 20, 2007 at 7:35 PM
Thanks for taking an interest!

I get this error at line 293 column 46 in LogWriter.cs

System.InvalidOperationException occurred
Message="Collection was modified; enumeration operation may not execute."
at System.Collections.Stack.StackEnumerator.MoveNext()
at Microsoft.Practices.EnterpriseLibrary.Logging.LogWriter.AddTracingCategories(LogEntry log, Boolean replacementDone)

The exception window doesn't list the full call stack so I cut and pasted it from the debugger call stack window. The most recent stack entry is listed as External Code in the debugger. I trimmed a little of the first 2 stack trace entries to remove private information which is why they end with the Title: lines.

External Code
> Microsoft.Practices.EnterpriseLibrary.Logging.dll!Microsoft.Practices.EnterpriseLibrary.Logging.LogWriter.AddTracingCategories(Microsoft.Practices.EnterpriseLibrary.Logging.LogEntry log = {Timestamp: 20/03/2007 7:17:29 PM
Message: End Trace: Activity '4e33436f-0000-0000-0000-000000000000' in method 'PrefilterCommon' at 41834970502294 ticks (elapsed time: 0 seconds)
Category: TraceExecution
Priority: 5
EventId: 1
Severity: Stop

Microsoft.Practices.EnterpriseLibrary.Logging.dll!Microsoft.Practices.EnterpriseLibrary.Logging.LogWriter.Write(Microsoft.Practices.EnterpriseLibrary.Logging.LogEntry log = {Timestamp: 20/03/2007 7:17:29 PM
Message: End Trace: Activity '4e33436f-0000-0000-0000-000000000000' in method 'PrefilterCommon' at 41834970502294 ticks (elapsed time: 0 seconds)
Category: TraceExecution
Priority: 5
EventId: 1
Severity: Stop

Microsoft.Practices.EnterpriseLibrary.Logging.dll!Microsoft.Practices.EnterpriseLibrary.Logging.Tracer.WriteTraceMessage(string message = "End Trace: Activity '4e33436f-0000-0000-0000-000000000000' in method 'PrefilterCommon' at 41834970502294 ticks (elapsed time: 0 seconds)", string entryTitle = "TracerExit", System.Diagnostics.TraceEventType eventType = Stop) Line 252 + 0xd bytes C#
Microsoft.Practices.EnterpriseLibrary.Logging.dll!Microsoft.Practices.EnterpriseLibrary.Logging.Tracer.WriteTraceEndMessage(string entryTitle = "TracerExit") Line 240 + 0x12 bytes C#
Microsoft.Practices.EnterpriseLibrary.Logging.dll!Microsoft.Practices.EnterpriseLibrary.Logging.Tracer.Dispose(bool disposing = true) Line 185 + 0x24 bytes C#
Microsoft.Practices.EnterpriseLibrary.Logging.dll!Microsoft.Practices.EnterpriseLibrary.Logging.Tracer.Dispose() Line 168 + 0xc bytes C#

The debugger call stack then ends in my code where I am exiting a using statement:

using (new Tracer("TraceExecution"))

// The call stack points to this 'return true' in the debugger
return true;

Again, thanks for taking an interest, and also for being so quick!

Mar 21, 2007 at 8:51 PM
Thanks for the extra info Colin. This error is truly strange, as the Trace.CorrelationManager is meant to be tied to a single thread, which means it shouldn't be possible for any other threads to access it. The MSDN docs say this:
  • The CorrelationManager class provides methods used to store a logical operation identity in a thread-bound context and automatically tag each trace event generated by the thread with the stored identity.
Yet it does look like the stack is being changed from underneath you somehow. Based on your understanding if your code, can you think of any explanations on what could be happening?

BTW - your "fancy tabs" probably disappeared as you didn't enclose your code block in double-curly brackets {{ ... }}
Mar 26, 2007 at 12:45 AM
Edited Mar 26, 2007 at 12:45 AM
I have no idea. I am doing some UI Automation event handling on background threads and the fault appears while logging in at least one of those threads.
Apr 1, 2007 at 4:55 AM
We have unfortunately been unable to reproduce this error. Is there any chance you could come up with a minimal reproduction of the problem and send it to us?
Apr 3, 2007 at 9:55 PM
I may be seeing something similar, though the exception is different. The issue I see is rooted at LogEntry.BuildCategoriesCollection where it gets a null category from the stack. This occurs from both the Tracer constructor and Dispose() method:

Unhandled Exception: System.ArgumentNullException: Value cannot be null.
Parameter name: category
at Microsoft.Practices.EnterpriseLibrary.Logging.LogEntry.BuildCategoriesCollection(String category)
at Microsoft.Practices.EnterpriseLibrary.Logging.Tracer.WriteTraceMessage(String message, String entryTitle, TraceEventType eventType)
at Microsoft.Practices.EnterpriseLibrary.Logging.Tracer.WriteTraceStartMessage(String entryTitle)
at Microsoft.Practices.EnterpriseLibrary.Logging.Tracer.Initialize(String operation, IConfigurationSource configurationSource)
at Microsoft.Practices.EnterpriseLibrary.Logging.Tracer..ctor(String operation)

Occassionally, I see a slightly different symptom:

Unhandled Exception: System.InvalidOperationException: Stack empty.
at System.Collections.Stack.Peek()
at Microsoft.Practices.EnterpriseLibrary.Logging.Tracer.WriteTraceEndMessage(String entryTitle)
at Microsoft.Practices.EnterpriseLibrary.Logging.Tracer.Dispose(Boolean disposing)
at Microsoft.Practices.EnterpriseLibrary.Logging.Tracer.Dispose()

I only see this when running multiple threads, and only if there is a listener actively logging the trace events. I'm using the latest EntLib 3.0 CTP release on a dual-core AMD machine.

I've managed to create a small test program to illustrate the problem. Interestingly enough, I had to keep pulling code from my real project until I added the class that uses the Caching application block. The code operates correctly if Tracing is disabled, but fails consistently when enabled. I can provide the test program if it helps.

Jun 19, 2007 at 2:18 PM
Changing line 303 of LogWriter.cs to be

logicalOperationStack = (Stack)GetLogicalOperationStack().Clone();

fixes the Tracer problem. This is on 3.0 RTM (also running on a dual core P4)
Jun 20, 2007 at 8:08 AM
There's a bug report from VS2005 Feb 05 CTP about LogicalOperationStack not being thread safe. The MS reply is that it was fixed for Whidbey RTM.

The problem is caused because the LogicalOperationStack is inherited by a child thread that is started when there are active operations. Consequently 2 threads now share the stack so it is necessary to lock / clone the stack before enumerating it.

The following code demonstrates the problem:

private static bool _loop = true;

private static extern int GetCurrentThreadId();

static void Main(string[] args)
Console.WriteLine("Thread starting thread - press return to stop");
_loop = true;
Thread th = new Thread(RunThread);

_loop = false;

private static void RunThread()
using (new Tracer("General"))
if (_loop)
Thread t = new Thread(RunThread);
Logger.Write(GetCurrentThreadId() + " exiting");

Run it for a while and check the event log - you should see the InvalidOpExceptions being logged.

A work item for this issue has been opened here