Console logging sometimes causes application to hang

[rocklan]

Does this issue relate to a new feature or an existing bug?

• Bug
• New Feature

What version of Serilog Console Sink is affected by this issue? Please list the related NuGet package.

Serilog.AspNetCore - version 3.1.0
Serilog.Sinks.Console - version 3.1.1

What is the target framework and operating system affected by this issue? Please see target frameworks & net standard matrix.

• netCore 2.0
• netCore 1.0
• 4.7
• 4.6.x
• 4.5.x

Running on windows 10 under IIS, dot net core 2.1.15.

Please describe the current behaviour you are experiencing?

When running my app sometimes my application hangs and stops responding. It's really difficult for me to reproduce. After much debugging I am pretty sure it's the console logger hanging for some reason as I did a memory dump and found 7 threads all sitting on the Serilog.Sinks.Console.dll!Serilog.Sinks.SystemConsole.ConsoleSink.Emit() method.

Removing the

.WriteTo.Console()

line shown below 'fixed' the problem.

Please describe the expected behaviour if the ?

Not hanging :)

If the current behavior is a bug, please provide the steps to reproduce the issue and if possible a minimal demo of the problem
NOTE: A small code sample goes a long way in expediting bug fixes or illustrating an enhancement you are proposing.

I am really sorry I can't provide a minimal set of code to reproduce the issue. I am using Serilog.aspnetcore 3.1.0 and Seq, and my startup code looks like this:

        Log.Logger = new LoggerConfiguration()
            .WriteTo.Console()
            .WriteTo.Seq("serverurl",  "apikey",
                restrictedToMinimumLevel: LogEventLevel.Verbose)
            .MinimumLevel.Verbose()
            .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
            .MinimumLevel.Override("System.Net.Http", LogEventLevel.Warning)
            .Enrich.With(new LogCleaner())
            .CreateLogger();

My log cleaner looks like this:

{
    class LogCleaner : ILogEventEnricher
    {
        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
        {
            // these properties are created by asp.net core, we don't want them

            logEvent.RemovePropertyIfPresent("ActionId");
            logEvent.RemovePropertyIfPresent("ConnectionId");
            logEvent.RemovePropertyIfPresent("CorrelationId");
            logEvent.RemovePropertyIfPresent("EventId");
            logEvent.RemovePropertyIfPresent("RequestId");
            logEvent.RemovePropertyIfPresent("SourceContext");

            logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty("MachineName", Environment.MachineName));
        }
    }

It seems to often happen at machine startup - when Seq is not running. I'm not sure if that's related.

[nblumhardt]

Thanks for the report, Lachlan. Still no ideas, here, but some more data might help uncover some possibilities. Is there any chance you can collect stack traces for the hung threads? Also, is SelfLog configured? And is the app running in a hosting environment that redirects STDOUT or STDERRR?

[jgasiorowski]

Hello, we just had the same issue on our development environment on full .NET Framework console application.
Application in random scenarios seemed to hang. After further investigation we also found that threads are waiting in .Emit(...) method (from source code I can see there is a lock) but one of the threads went deeper in callstack into native IO libraries to write to actual console. Which lead me to this SO answer: https://stackoverflow.com/a/45895662/2892208

And that totally fixed it. Developer/User to just get focus on console window clicked in background which changes the console window title bar and ads a previx like Select {here is the name of you application}. So it means that console now just expects your input and is locked!
Hitting Esc or Enter key on keyboard unlocks the console and logs are getting flushed and applicaiton continues to work. I didn't know about that awesome feature 🥇

[rasmus]

We have verified that this is a problem as well in our production environment.

After inspecting process dumps we could see that several threads was indeed waiting on the lock.

After disabling console logging, the service performance improved significantly.

[nblumhardt]

Thanks for the note, @rasmus - console logging performance can definitely be a bottleneck in some runtime environments. Using Serilog.Sinks.Async can improve console logging performance.

As the original issue here was regarding a hang, and the post above appears to successfully diagnose the cause, I think your scenario is different. If you still hit poor performance after wrapping your console logging in Async(), it may be a good one for a new issue. Thanks!