NLog: How to indent scopes and use scope headline?

Question

How can I enable the following in NLog that produces the shown output:

using (_logger.BeginScope("Starting processing"))
{
    _logger.LogInformation("Algorithm1 Initalized");
    _logger.LogInformation("Algorithm2 Initalized");

    using (_logger.BeginScope("Algorithm 1 running"))
    {
        for (int i=0; i<5; i++)
        _logger.LogInformation($"Algorithm1 progress {i}");
    }

    using (_logger.BeginScope("Algorithm 2 running"))
    {
        for (int i = 0; i < 5; i++)
            _logger.LogInformation($"Algorithm2 progress {i}");
    }
}

The output I'd like to have is this:

    Starting processing
        Algorithm1 Initialized
        Algorithm2 Initialized  
        Algorithm 1 running
            Algorithm1 0
            Algorithm1 1
            Algorithm1 2
            Algorithm1 3
            Algorithm1 4
        Algorithm 1 finished in 10secs
        Algorithm 2 running
            Algorithm2 0
            Algorithm2 1
            Algorithm2 2
            Algorithm2 3
            Algorithm2 4
        Algorithm 2 finished in 10secs
    Processing Finished

Explanation: For each scope I want to create a headline (e.g "Starting processing") that records the time the scope was created. Additionally when the scope ends, I want to output a footer that also reports the duration the scope was "open".

The closing footer is not written in the code example above, because I don't know how to do it. I could create my own BeginScope IDisposable that simply wraps the dispose, but maybe there is a better way?

Additionally, I want to indent all text according to the depth of the scope.

I have found the ${scopetiming} and ${scopecontext}, but I honestly don't know how to apply them.

Any help would be appreciated ;-)

Jehiel

Right now I don't think NLog has the ability to indent/pad based on current NLog ScopeContext. You are wellcome to create a feature-request here: github.com/NLog/NLog/issues (And maybe even a pull-request that implements the feature) – Burgrave

Created proof-of-concept pull-request - github.com/NLog/NLog/pull/5086 – Burgrave

NLog 5.0.5 has been released with ${scopeindent} - nuget.org/packages/NLog/5.0.5#release-body-tab – Burgrave

If explicit scope-timing is not super important (Ex. use ${processtime} instead), then you can also consider just using class-namespaces and inner-classes together with NLog.LogManager.GetCurrentClassLogger() and ${logger}. See also: https://mcmap.net/q/1176288/-nlog-feature-question-can-the-stack-depth-be-taken-into-account-while-writing-logs – Burgrave

Answer 1

With NLog 5.0.5 then you can use ${scopeindent}

    ${scopeindent}${message}

Then create this custom extension method for Microsoft ILogger:

public static class ILoggerExtensions
{
    public static TimingScope BeginTimedScope(this ILogger logger, string scopeName)
    {
        return new TimingScope(logger, scopeName);
    }

    public struct TimingScope : IDisposable
    {
        public readonly ILogger Logger;
        public readonly IDisposable LoggerScope;
        public readonly string ScopeName;
        public readonly long StopWatchStart;

        public TimingScope(ILogger logger, string scopeName)
        {
            Logger = logger;
            ScopeName = scopeName;
            Logger.Information("{0} Running", ScopeName);
            LoggerScope = Logger.BeginScope(ScopeName);
            StopWatchStart = Stopwatch.GetTimestamp();
        }

        public void Dispose()
        {
            var ticks = Stopwatch.GetTimestamp() - StopWatchStart;
            double milliseconds = (ticks / Stopwatch.Frequency) * 1000.0;
            LoggerScope?.Dispose();
            Logger.Information("{0} Completed in {1} ms", ScopeName, (long)milliseconds);
        }
    }
}

Burgrave

Awesome. Thanks for your help and the presented code. I'm (was) currently not really experienced at writing a layout renderer and haven't had time to look in it. But with that examples I feel confident to be able to. – Jehiel