Why is ThreadStatic data being unexpectedly shared between threads?

Question

I have a logging framework that I've written that has the ability to track "logging context". It has a pluggable strategy framework, however the one I use most often is a ThreadStatic variant that keeps track of context in a [ThreadStatic] variable. I've been trying to resolve a problem with logging context in a multi-threaded workflow. The goal is to have all the log entries for all calls across all methods and classes that share a common thread log the same context information. Since each thread should theoretically be getting their own ThreadStatic variable, the idea seemed easy.

public class ThreadStaticLoggingContextStrategy: ILoggingContextStrategy
{
    public ThreadStaticLoggingContextStrategy()
    {
        Debug.WriteLine("[INITIALIZE] A new instance of 'ThreadStaticLoggingContextStrategy' has been created.");
    }

    [ThreadStatic] private LoggingContext _context;

    public LoggingContext GetLoggingContext()
    {
        if (_context == null)
            _context = new LoggingContext();

        return _context;
    }
}

In reality, it seems that ThreadStatic data is actually being SHARED across threads. This goes against everything I understand about threading. I was having a hard time figuring out what the issue was until I threw in an extra log entry that tracked when each thread cleared out thread context (all the threads run on a main loop...at the beginning, if the necessary messages are received, context is initialized, and at the end in a finally clause, its reset.) The following logging is CONSISTENT:

[2011-12-15 16:27:21,233] [DEBUG] [TPI.LTI.Eventing.GroupCreatedNotificationHandler: TPI.LTI.Provisioning.Handlers.GroupCreatedNotificationHandler.WORKDEVELOPMENT.1_Thread: 324]: (ContextId=184e82dd-152b-4bb5-a2c6-3e05b2365c04; TransactionId=1a11130e-e8dd-4fa1-9107-3b46dcb4ffd6; HandlerName=GroupCreatedNotificationHandler; HandlerId=WORKDEVELOPMENT.1) Pushing event for tool '0967e031-398f-437d-8949-2a17fe844df0' to http://tpidev.pearsoncmg.com/tpi/lti/service/event...

[2011-12-15 16:27:21,259] [DEBUG] [TPI.LTI.Facades.LTIFacade: TPI.LTI.Provisioning.Handlers.GroupCreatedNotificationHandler.WORKDEVELOPMENT.1_Thread: 299]: (ContextId=184e82dd-152b-4bb5-a2c6-3e05b2365c04; TransactionId=1a11130e-e8dd-4fa1-9107-3b46dcb4ffd6; HandlerName=GroupCreatedNotificationHandler; HandlerId=WORKDEVELOPMENT.1) Getting LTI Tool Instance for tool instance guid 0967e031-398f-437d-8949-2a17fe844df0:

[2011-12-15 16:27:21,318] [DEBUG] [TPI.LTI.Facades.LTIFacade: TPI.LTI.Provisioning.Handlers.GroupCreatedNotificationHandler.WORKDEVELOPMENT.1_Thread: 299]: (ContextId=184e82dd-152b-4bb5-a2c6-3e05b2365c04; TransactionId=1a11130e-e8dd-4fa1-9107-3b46dcb4ffd6; HandlerName=GroupCreatedNotificationHandler; HandlerId=WORKDEVELOPMENT.1) Found LTI Tool Instance for tool instance guid 0967e031-398f-437d-8949-2a17fe844df0.

[2011-12-15 16:27:21,352] [DEBUG] [TPI.LTI.Facades.TPIFacade: TPI.LTI.Provisioning.Handlers.GroupCreatedNotificationHandler.WORKDEVELOPMENT.1_Thread: 299]: (ContextId=184e82dd-152b-4bb5-a2c6-3e05b2365c04; TransactionId=1a11130e-e8dd-4fa1-9107-3b46dcb4ffd6; HandlerName=GroupCreatedNotificationHandler; HandlerId=WORKDEVELOPMENT.1) Publishing event to TPI at 'http://tpidev.pearsoncmg.com/tpi/lti/service/event'...

[2011-12-15 16:27:21,428] [DEBUG] [TPI.LTI.Eventing.GroupCreatedNotificationHandler: TPI.LTI.Provisioning.Handlers.GroupCreatedNotificationHandler.WORKDEVELOPMENT.2_Thread: 301]: [LOG] Resetting logging Context!!

[2011-12-15 16:27:21,442] [DEBUG] [TPI.LTI.Eventing.GroupCreatedNotificationHandler: TPI.LTI.Provisioning.Handlers.GroupCreatedNotificationHandler.WORKDEVELOPMENT.2_Thread: 299]: No message pending on queue. GroupCreatedNotificationHandler.WORKDEVELOPMENT.2 handler is waiting...

[2011-12-15 16:27:22,282] [DEBUG] [TPI.LTI.Facades.TPIFacade: TPI.LTI.Provisioning.Handlers.GroupCreatedNotificationHandler.WORKDEVELOPMENT.1_Thread: 301]: Event published to TPI.

[2011-12-15 16:27:22,283] [DEBUG] [TPI.LTI.Eventing.GroupCreatedNotificationHandler: TPI.LTI.Provisioning.Handlers.GroupCreatedNotificationHandler.WORKDEVELOPMENT.1_Thread: 301]: Received a response from provider:

You can see that there are two threads in this particular case, 1_Thread and 2_Thread. I've italicized the contextual data that is supposed to be included at the beginning of EVERY log entry for 1_Thread. I've bolded the point in 2_Thread where logging context is reset. After that point, all of 1_Thread's context information is missing. In dozens of tests so far, the context information for all threads is lost after the logging context is reset on another.

Am I misunderstanding ThreadStatic? I've been writing C# code since 2001, and I've never experienced this behavior before. It seems there is a new ThreadLocal<T> class in .NET 4, however I am not sure if that simply used ThreadStatic internally anyway, and would therefor have the same problem, or if it functions differently (and hopefully more reliably.) Any insight into this problem would be GREATLY APPRECIATED! Thanks!

Vino

Please post the code where you're using the ThreadStatic field – Pycno

I actually just did. Its pretty strait forward. The strategy is a singleton, only one exists in the entire application. – Vino

Answer 1

Because that field isn't static. It only applies to static fields.

If this is 4.0, maybe look at ThreadLocal<T>

Archerfish

Answer 2

As @MarcGravell points out your field is not static, which is the cause of your problem.

However, if a consumer were to store the return from GetLoggingContext this value would be available to be shared between threads. I generally try to use any ThreadStatic variables as implementation details of a class, rather than exposing them outside of it.

Weatherproof

Sure, I know that. The GetLoggingContext call is always used to retrieve the context, and it is ONLY called within the logging framework. This piece of code is separated by several degrees from code that actually performs logging, and is a deeply buried implementation detail. I'm not concerned about anyone caching a copy of it locally. You could consider this particular strategy an implementation detail of the logging framework, which boils down to an ILogger interface that all the other programmers actually use. I generally follow the same rule...keep ThreadStatic as an internal detail. – Vino