Block infinite loop between System.Diagnostics calls from .Net's logging code, and System.Diagnostics->ILogger listener

Question

I have a large >10 year old web app which I'm gradually upgrading to Entity Framework 7, .Net 7 and ASP.Net Core. I'm in the middle of this big piece of tech debt payoff. I think (hope) I'm about 80% done... So there's only the other 80% to do :-).

One unexpected migration step I just ran into, is that System.Diagnostics.Trace doesn't work with the modernized ILogger logging/tracing infrastructure in .NetCore/Asp.NetCore. I have 100s of System.Diagnostics.Trace calls spread across all the projects involed in this solution, and across several layers of business logic classes. I would prefer to avoid figuring out how to pass the ILogger objects around through dependency injection and (I'm guessing this'll be required in some places) changing new/create calls and constructors to pass it in.

So I found a promising approach to be able to postpone the migrating from System.Diagnostics to ILogger. Thanks to a few people who blazed this trail before me, there are some great ideas: https://www.codeproject.com/Articles/5255953/Use-Trace-and-TraceSource-in-NET-Core-Logging and https://khalidabuhakmeh.com/logging-trace-output-using-ilogger-in-dotnet-applications

I went with this approach, creating a TraceListener which I add to System.Diagnostics.Trace, and which sends all the logging calls to an ILogger.

    // Set up trace/debug logging.
    IServiceCollection serviceCollection = builder.Services.AddLogging(iLoggingBuilder =>
    {
        iLoggingBuilder
        //.ClearProviders()
        //.AddConsole()
        //.AddEventLog()
        //.AddEventSourceLogger()
   .AddConfiguration(builder.Configuration.GetSection("Logging"));
});

...

    // Make the Asp.Net Core Logging framework listen to what comes from the System.Diagnostics.Trace framework, since that old tracing framework is what our DB+Model project uses.
    ILogger<Program> logger = app.Services.GetRequiredService<ILogger<Program>>();
    //ILogger<Program> logger = app.Services.GetService<ILoggerFactory>().CreateLogger<Program>();
    Trace.Listeners.Clear();
    Trace.Listeners.Add(new LoggerTraceListener(logger));

The LoggerTraceListener implementation I have is very similar to what is shared here: https://www.codeproject.com/Articles/5255953/Use-Trace-and-TraceSource-in-NET-Core-Logging

That works great. Except... Inside the Microsoft.Extensions.Logging code in .Net Core, the logging framework calls System.Diagnostics for its own logging. This results in an infinite loop. Every call I make to System.Diagnostics, is passed on to ILogger, and once it gets to Microsoft.Extensions.Logging, another System.Diagnostics call is made, which ends up back in my TraceListener.

I can fix this with a big hammer: adding ".ClearProviders()" as I set up the ILoggingBuilder. I can add back some of the default providers. If I leave ".AddDebug()" out, the logging from Microsoft.Extensions.Logging stops, so the issue is resolved. But I'd hate to stop all Debug logging - who knows what other parts of .Net and ASP.Net Core uses this. I'll become blind to some perhaps useful debug logging in the future. I'd rather avoid that. I've tried stopping the loop by setting the appsettings.json logging level for Microsoft.Extensions.Logging to "Error", but it seems that only filters what is written out to the log, and doesn't stop the looping.

What could I do to stop the calls from Microsoft.Extensions.Logging from proceeding when those calls reach the methods in LoggerTraceListener? Is there another approach that'll fix this more reliably? Or should I just resign to the fact that I need to add the System.Diagnostics->ILogger migration work to the long list of tech debt payoff I'm chewing through?

Update 1: I tried two new approaches, still without success. One was to try the System.Diagnostics TraceFilter. Perhaps I could filter out the logging calls which cause the infinite loop? But that didn't work out. The TraceFilter for some reason doesn't get invoked on Trace.Write and WriteLine calls. Then I tried looking up the callstack when the calls get to LoggerTraceListener. That'll probably work. But it'll cause a significant perf issue. For every trace call throughout the codebase, I'd then be walking the callstack... Not a good idea.

Update 2: I gave up on trying to keep the System.Diagnostics.Trace calls unchanged in this code base. I started injecting and propagating ILogger instead. It's painful, especially lots of classes down in other projects can't be handled with dependency injection (without terrible 'separation of concern' impact), so I ended up passing an ILogger object around with the 'wrong' <T>.

Answer 1

I solved this problem by adding the _processing flag. This prevents calling "WriteLine()" again from other providers when I call _defaultLogger.LogInformation(_builder.ToString()).

using System;
using System.Collections.Concurrent;
using System.Diagnostics;
using System.Text;
using System.Threading;
using Microsoft.Extensions.Logging;

namespace Core.Hosting.Logging;

public class LoggerTraceListener : TraceListener
{
    private readonly ILoggerFactory _loggerFactory;
    private readonly ILogger _defaultLogger;
    private readonly ConcurrentDictionary<string, ILogger> _loggers = new();
    private readonly StringBuilder _builder = new();
    private object _lock = new();
    private int _processing;

    public LoggerTraceListener(ILoggerFactory loggerFactory)
    {
        _loggerFactory = loggerFactory ?? throw new ArgumentNullException(nameof(loggerFactory));
        _defaultLogger = loggerFactory.CreateLogger(nameof(LoggerTraceListener));
        Filter = new EventTypeFilter(SourceLevels.Information);
    }

    
    public override void TraceEvent(
        TraceEventCache eventCache,
        string source,
        TraceEventType eventType,
        int id,
        string message
    )
    {
        var logger = _loggers.GetOrAdd(
            source,
            static (s, factory) => factory.CreateLogger(s),
            _loggerFactory
        );

        lock (_lock)
        {
            Interlocked.CompareExchange(ref _processing, 1, 0);
            logger.Log(MapLevel(eventType), message);
            Interlocked.Exchange(ref _processing, 0);
        }
    }

    public override void TraceEvent(
        TraceEventCache eventCache,
        string source,
        TraceEventType eventType,
        int id,
        string format,
        params object[] args
    )
    {
        var logger = _loggers.GetOrAdd(
            source,
            static (s, factory) => factory.CreateLogger(s),
            _loggerFactory
        );

        lock (_lock)
        {
            Interlocked.CompareExchange(ref _processing, 1, 0);
            logger.Log(MapLevel(eventType), format, args ?? Array.Empty<object>());
            Interlocked.Exchange(ref _processing, 0);
        }
    }

    public override void Write(string message)
    {
        _builder.Append(message);
    }

    public override void WriteLine(string message)
    {
        if (SkipMessage(message))
            return;

        if (Interlocked.CompareExchange(ref _processing, 1, 0) == 1)
            return;

        lock (_lock)
        {
            _builder.AppendLine(message);
            _defaultLogger.LogInformation(_builder.ToString());
            _builder.Clear();
            Interlocked.Exchange(ref _processing, 0);
        }
    }

    private static bool SkipMessage(string message) =>
        string.IsNullOrWhiteSpace(message) ||
        message.StartsWith("Microsoft.Hosting.") ||
        message.StartsWith("CoreWCF.Channels.");

    private LogLevel MapLevel(TraceEventType eventType) =>
        eventType switch
        {
            TraceEventType.Verbose => LogLevel.Debug,
            TraceEventType.Information => LogLevel.Information,
            TraceEventType.Critical => LogLevel.Critical,
            TraceEventType.Error => LogLevel.Error,
            TraceEventType.Warning => LogLevel.Warning,
            _ => LogLevel.Trace
        };
}