Search code examples
c#log4nettracenlog

Correlating log messages within scope


I would like to correlate logging messages using a logging scope. I'm looking for an implementation for log4net, NLog, or System.Diagnostics.Trace. Below is a basic implementation that demonstrates the concept. The output from the program is this:

First level: Logging in the run method
First level: Logging one level down
Second scope: Another message
First level: Back from scope

Is there a more robust/general/proven/easy-to-use-with-some-framework version of what is done below?

class Program
{
    private static readonly Log Log = new Log();

    private static void Main()
    {
        using (new LoggingScope("First level"))
        {
            Run();
        }
    }

    private static void Run()
    {
        Log.Info("Logging in the run method");
        Run2();
    }

    private static void Run2()
    {
        Log.Info("Logging one level down");
        using (new LoggingScope("Second scope"))
        {
            Log.Info("Another message");
        }

        Log.Info("Back from scope");
    }
}

internal class Log
{
    static Log()
    {
        CurrentScope = new Stack<string>();
    }

    private static Stack<string> CurrentScope { get; set; }

    public static void PushScope(string name)
    {
        CurrentScope.Push(name);
    }

    public static void PopScope()
    {
        CurrentScope.Pop();
    }

    public void Info(string message)
    {
        var currentScope = CurrentScope.Count == 0 ? string.Empty : CurrentScope.Peek();
        Console.WriteLine("{0}: {1}", currentScope, message);
    }
}

internal class LoggingScope : IDisposable
{
    private readonly string _name;

    public LoggingScope(string id)
    {
        _name = Guid.NewGuid().ToString();
        Log.PushScope(id);
        CallContext.SetData(_name, id);
    }

    public void Dispose()
    {
        Log.PopScope();
        CallContext.FreeNamedDataSlot(_name);
    }
}

Solution

  • You are looking for nested diagnostic context (NDC):

        Log.Info("Logging one level down");
        using(ThreadContext.Stacks["NDC"].Push( requestid))
        {
            Log.Info("Another message");
        }
        Log.Info("Back from scope");
    

    To get the scope in your log output use %property{NDC} in your conversion pattern:

        <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
    

    log4net.ThreadContext.Stacks (404)

    log4net.NDC (deprecated) (404)