Friday, 24 November 2017

"activity GUID" or "entire web request GUID" in Web.API + NLog logging activities

What if your legacy project uses your custom LOGGER class as a singleton and you want mark log messages with Request GUID to be able determine whole scope of logs for specific HTTP request?

Nowadays we using async/await and can't use Thread.ManagedThreadId in nlog messages cause threads can be different according to threads switching.

In case of singleton LOGGER task looks impossible, but there is a new feature in NLOG which solve this. All you need is to use tracing correlation id

protected void Application_BeginRequest(object sender, EventArgs e)
{
    Trace.CorrelationManager.ActivityId = Guid.NewGuid();
}

How it works?

Here there is some disassembled code

namespace System.Diagnostics {
    public class CorrelationManager {
        private const string transactionSlotName 
           = "System.Diagnostics.Trace.CorrelationManagerSlot";
        private const string activityIdSlotName 
           = "E2ETrace.ActivityID";
        
        internal CorrelationManager() { }
 
        public Guid ActivityId {
            get {
                Object id = CallContext.LogicalGetData(activityIdSlotName);
                if (id != null)
                    return (Guid) id;
                else
                    return Guid.Empty;
            }
            set {
                CallContext.LogicalSetData(activityIdSlotName, value);
            }
        }
     .....
   }
}


namespace System.Runtime.Remoting.Messaging{    
    [System.Security.SecurityCritical]  // auto-generated_required
    [Serializable]
    [System.Runtime.InteropServices.ComVisible(true)]
    public sealed class CallContext
    {
        private CallContext()
        {
        }

        ....
        
        public static void LogicalSetData(String name, Object data)
        {
            ExecutionContext ec 
              = Thread.CurrentThread.GetMutableExecutionContext();
            ec.IllogicalCallContext.FreeNamedDataSlot(name);
            ec.LogicalCallContext.SetData(name, data);
        }
   
        .....
    }
}


And finally we have

    [ClassInterface(ClassInterfaceType.None)]
    [ComDefaultInterface(typeof(_Thread))]
    [System.Runtime.InteropServices.ComVisible(true)]
    public sealed class Thread : CriticalFinalizerObject, _Thread
    {
        ......

        [SecurityCritical]
        [ReliabilityContract(Consistency.WillNotCorruptState, Cer.MayFail)]
        internal ExecutionContext GetMutableExecutionContext()
        {
            Contract.Assert(Thread.CurrentThread == this);
#if DEBUG
            Contract.Assert(!m_ForbidExecutionContextMutation);
#endif
            if (m_ExecutionContext == null)
            {
                m_ExecutionContext = new ExecutionContext();
            }
            else if (!ExecutionContextBelongsToCurrentScope)
            {
                ExecutionContext copy = 
                    m_ExecutionContext.CreateMutableCopy();
                m_ExecutionContext = copy;
            }
 
            ExecutionContextBelongsToCurrentScope = true;
            return m_ExecutionContext;
        }
         
        ...... 
    }


Here we can see mutable ExecutionContext concept. The same way it works for principles (IPrinciple interface which is stored in thread). So, we can see that approach works in async/await environment.

internal static IPrincipal Principal
{
    [System.Security.SecurityCritical]  // auto-generated
    get
    {
         return Thread.CurrentThread.GetExecutionContextReader()
               .LogicalCallContext.Principal;
    }
 
    [System.Security.SecurityCritical]  // auto-generated
    set
    {
         Thread.CurrentThread.GetMutableExecutionContext()
               .LogicalCallContext.Principal = value;
    }
}

No comments:

Post a Comment