Nested multithread operations tracing

Question

I've a code alike

void ExecuteTraced(Action a, string message)
{
    TraceOpStart(message);
    a();
    TraceOpEnd(message);
}

The callback (a) could call ExecuteTraced again, and, in some cases, asynchronously (via ThreadPool, BeginInvoke, PLINQ etc, so I've no ability to explicitly mark operation scope). I want to trace all operation nested (even if they perform asynchronously). So, I need the ability to get last traced operation inside logical call context (there may be a lot of concurrent threads, so it's impossible to use lastTraced static field).

There're CallContext.LogicalGetData and CallContext.LogicalSetData, but unfortunately, LogicalCallContext propagates changes back to the parent context as EndInvoke() called. Even worse, this may occure at any moment if EndInvoke() was called async. http://stackoverflow.com/questions/883486/endinvoke-changes-current-callcontext-why

Also, there is Trace.CorrelationManager, but it based on CallContext and have all the same troubles.

There's a workaround: use the CallContext.HostContext property which does not propagates back as async operation ended. Also, it does'nt clone, so the value should be immutable - not a problem. Though, it's used by HttpContext and so, workaround is not usable in Asp.Net apps.

The only way I see is to wrap HostContext (if not mine) or entire LogicalCallContext into dynamic and dispatch all calls beside last traced operation.

Help, please!

Answer 1

Ok, I'm answering myself.

Short one: there is no solution.

Slightly detailed:

The problem is, I need a way to store last active operation per each logical context. Tracing code will've no control over execution flow, so it's impossible to pass lastStartedOperation as a parameter. Call context may clone (e.g. if another thread started), so I need to clone the value as context clones.

CallContext.LogicalSetData() suits well, but it merges values into the original context as asynchronous operation ended (in effect, replacing all changes made before EndInvoke called). Theortically, it may occure even asynchronously, giving unpredictable result of CallContext.LogicalGetData().

I say theoretically because simple call a.EndInvoke() inside an asyncCallback does not replace values in the original context. Though, I did not check behavior of remoting calls (and it seems, WCF does not honor CallContext at all). Also, the documentation (old one) says:

The BeginInvoke method passes the CallContext to the server. When EndInvoke method is called, the CallContext is merged back onto the thread. This includes cases where BeginInvoke and EndInvoke are called sequentially and where BeginInvoke is called on one thread and EndInvoke is called on a callback function.

Last version is not so definite:

The BeginInvoke method passes the CallContext to the server. When the EndInvoke method is called, the data contained in the CallContext is copied back onto the thread that called BeginInvoke.

If you digg into framework source, you'll find that values are actually stored inside a hashtable inside LogicalCallContext inside current ExecutionContext of the current thread.

When call context clones (e.g. on BeginInvoke) LogicalCallContext.Clone called. And EndInvoke (at least when called inside original CallContext) calls LogicalCallContext.Merge() replacing old values inside m_Datastore with new ones.

So we need somehow supply the value which will be cloned but not merged back.

LogicalCallContext.Clone() also clones (without merging) content of two private fields, m_RemotingData and m_SecurityData. As the field's types defined as internal, you could not derive from them (even with emit), add property MyNoFlowbackValue and replace m_RemotingData (or another one) field's value with instance of derived class.

Also, field's types are not derived from MBR, so it's impossible to wrap them using transparent proxy.

You could not inherit from LogicalCallContext - it's sealed. (N.B. actually, you could - if using CLR profiling api to replace IL as mock frameworks do. Not a desired solution.)

You could not replace the m_Datastore value, because LogicalCallContext serializes only content of the hashtable, not the hashtable itself.

Last solution is to use CallContext.HostContext. This effectively stores data in the m_hostContext field of the LogicalCallContext. LogicalCallContext.Clone() shares (not clones) the value of m_hostContext, so the value should be immutable. Not a problem though.

And even this fails if HttpContext used, as it sets CallContext.HostContext property replacing your old value. Ironically, HttpContext does not implement ILogicalThreadAffinative, and therefore does not stored as value of the m_hostContext field. It just replaces old value with null.

So, there's no solution and never will be, as CallContext is the part of remoting and remoting is obsolete.

P.S. Thace.CorrelationManager uses CallContext internally and therefore does not work as desired, too. BTW, LogicalCallContext has special workaround to clone CorrelationManager's operation stack on context clone. Sadly, it has not special workaround on merge. Perfect!

P.P.S. The sample:

static void Main(string[] args)
{
    string key = "aaa";
    EventWaitHandle asyncStarted = new AutoResetEvent(false);
    IAsyncResult r = null;

    CallContext.LogicalSetData(key, "Root - op 0");
    Console.WriteLine("Initial: {0}", CallContext.LogicalGetData(key));

    Action a = () =>
    {
        CallContext.LogicalSetData(key, "Async - op 0");
        asyncStarted.Set();
    };
    r = a.BeginInvoke(null, null);

    asyncStarted.WaitOne();
    Console.WriteLine("AsyncOp started: {0}", CallContext.LogicalGetData(key));

    CallContext.LogicalSetData(key, "Root - op 1");
    Console.WriteLine("Current changed: {0}", CallContext.LogicalGetData(key));

    a.EndInvoke(r);
    Console.WriteLine("Async ended: {0}", CallContext.LogicalGetData(key));

    Console.ReadKey();
}