When running in docker, after `docker stop`, logs are not emitted to console

[williamdenton]

I have an app which I have migrated to net5 from net48. It uses log4net widely, so it made sense to keep using log4net.

I am using this package to configure the HostBuilder and it works - until the process is instructed to shutdown via docker stop which is a SIGTERM signal.

Expected behaviour

Logging continues to be written to the console until the logging system is disposed, which is when the host is disposed, which is after all components have exited.

Observed behaviour

✅ dotnet run then ctrl+c in a normal terminal works ✅ docker run --tty then ctrl+c works 🔴 docker run then docker stop (from another console) does not work

Simple Reproduction:

Files:

net5shutdown.csproj

<Project Sdk="Microsoft.NET.Sdk.Web">
  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFramework>net5.0</TargetFramework>
    <Nullable>enable</Nullable>
  </PropertyGroup>
  <ItemGroup>
    <PackageReference Include="Microsoft.Extensions.Logging.Log4Net.AspNetCore" Version="5.0.4" />
  </ItemGroup>
</Project>

---

log4net.config

<?xml version="1.0" encoding="utf-8" ?>
<log4net>
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
        <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
        </layout>
    </appender>
    <root>
        <level value="ALL"/>
        <appender-ref ref="ConsoleAppender"/>
    </root>
</log4net>

---

program.cs

using System;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;

namespace Net5Shutdown
{
    public class Program
    {
        public static async Task Main()
            => await new HostBuilder()
                .UseConsoleLifetime()
                .ConfigureServices(s => s.AddHostedService<MyBackgroundService>())
                .ConfigureLogging(l=> l.AddLog4Net("log4net.config"))
                .Build()
                .RunAsync();
    }

    public class MyBackgroundService : IHostedService
    {

        readonly ILogger<MyBackgroundService> _logger;

        public MyBackgroundService(ILogger<MyBackgroundService> logger)
        {
            _logger = logger;
        }

        public Task StartAsync(CancellationToken cancellationToken)
        {
            _logger.LogInformation("log=> Started background service");
            Console.WriteLine("Console=> Started background service");
            return Task.CompletedTask;
        }

        public Task StopAsync(CancellationToken cancellationToken)
        {
            _logger.LogInformation("log=> stopped background service");
            Console.WriteLine("Console=> stopped background service");
            return Task.CompletedTask;
        }
    }
}

---

Dockerfile

FROM mcr.microsoft.com/dotnet/sdk:5.0 AS build-env
WORKDIR /app

COPY ./ ./

RUN dotnet publish -c Release -o out

# Build runtime image
FROM mcr.microsoft.com/dotnet/aspnet:5.0
WORKDIR /app
COPY --from=build-env /app/out .
ENTRYPOINT ["dotnet", "net5shutdown.dll"]

---

✅ dotnet run then ctrl+c in a normal terminal works here you can see the ^C and the shutdown messages from the hosted service

➜ dotnet run
2021-09-14 14:34:44,941 [1] INFO  Net5Shutdown.MyBackgroundService [(null)] - log=> Started background service
Console=> Started background service
2021-09-14 14:34:44,957 [1] INFO  Microsoft.Hosting.Lifetime [(null)] - Application started. Press Ctrl+C to shut down.
2021-09-14 14:34:44,959 [1] INFO  Microsoft.Hosting.Lifetime [(null)] - Hosting environment: Production
2021-09-14 14:34:44,959 [1] INFO  Microsoft.Hosting.Lifetime [(null)] - Content root path: /Users/williamdenton/git/williamdenton/net5-shutdown/net5shutdown/bin/Debug/net5.0/
^C2021-09-14 14:34:49,170 [6] INFO  Microsoft.Hosting.Lifetime [(null)] - Application is shutting down...
2021-09-14 14:34:49,171 [4] INFO  Net5Shutdown.MyBackgroundService [(null)] - log=> stopped background service
Console=> stopped background service

---

✅ docker run --tty then ctrl+c works

➜ docker build -t net5shutdown .
...
➜ docker run --tty net5shutdown
2021-09-14 02:56:50,592 [1] INFO  Net5Shutdown.MyBackgroundService [(null)] - log=> Started background service
Console=> Started background service
2021-09-14 02:56:50,641 [1] INFO  Microsoft.Hosting.Lifetime [(null)] - Application started. Press Ctrl+C to shut down.
2021-09-14 02:56:50,650 [1] INFO  Microsoft.Hosting.Lifetime [(null)] - Hosting environment: Production
2021-09-14 02:56:50,650 [1] INFO  Microsoft.Hosting.Lifetime [(null)] - Content root path: /app/
^C2021-09-14 02:56:54,796 [7] INFO  Microsoft.Hosting.Lifetime [(null)] - Application is shutting down...
2021-09-14 02:56:54,803 [5] INFO  Net5Shutdown.MyBackgroundService [(null)] - log=> stopped background service
Console=> stopped background service

---

🔴 docker run then docker stop (from another console) does not work

expected log of log=> stopped background service and Microsoft.Hosting.Lifetime [(null)] - Application is shutting down... is not present

➜ docker run net5shutdown
2021-09-14 02:36:16,064 [1] INFO  Net5Shutdown.MyBackgroundService [(null)] - log=> Started background service
Console=> Started background service
2021-09-14 02:36:16,144 [1] INFO  Microsoft.Hosting.Lifetime [(null)] - Application started. Press Ctrl+C to shut down.
2021-09-14 02:36:16,152 [1] INFO  Microsoft.Hosting.Lifetime [(null)] - Hosting environment: Production
2021-09-14 02:36:16,152 [1] INFO  Microsoft.Hosting.Lifetime [(null)] - Content root path: /app/
Console=> stopped background service

---

swapping the logging system for the simple console log

        public static async Task Main()
            => await new HostBuilder()
                .UseConsoleLifetime()
                .ConfigureServices(s => s.AddHostedService<MyBackgroundService>())
-                .ConfigureLogging(l=> l.AddLog4Net("log4net.config"))
+                .ConfigureLogging(l=> l.AddSimpleConsole())
                .Build()
                .RunAsync();

yields the correct log statements:

➜ docker run net5shutdown      
Console=> Started background service
info: Net5Shutdown.MyBackgroundService[0]
      log=> Started background service
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Production
info: Microsoft.Hosting.Lifetime[0]
      Content root path: /app/
info: Microsoft.Hosting.Lifetime[0]
      Application is shutting down...
Console=> stopped background service
info: Net5Shutdown.MyBackgroundService[0]
      log=> stopped background service

[williamdenton]

there's some discussion on this twitter thread https://twitter.com/willdento/status/1445222796091486209

It seems this issue doesn't affect net6

[huorswords]

Hello @williamdenton ,

My apologies, a lot of work at job last weeks. Cannot review your issue.

I have been reviewing the Twitter thread, and... I can conclude that you found what is happening in .NET 5.0?

Do you think that is there anything that can be changed from this extension to make it work?

Thank you very much.

[williamdenton]

hey @huorswords, i didn't figure out what was happening in net5, but did find that it works ok in net6. It's a mystery as to whether this is an issue with net5 or log4net.

GIven net6 is so close it probably not worth investigating this further.

The tweet you linked above is not a resolution to the issue rather an explanation of why it behaves the way it does for the person i am replying to there which is unrelated to this.

[williamdenton]

ill close this, as its resolved in net6