runtime: CoreCLR's CNTRL_SHUTDOWN_EVENT handler prevents graceful exit of services during system shutdown

This one is actually different than the error 1067 issue. In that case the service process was exiting before completing ServiceBase’s OnStop method which is what notified SCM that the service cleanly stopped. In that case it would run all ApplicationStopping and ApplicationStopped.

In this case the machine is shutting down. I was looking at a similar issue internally and found that the problem was actually due to https://github.com/dotnet/runtime/pull/41101. During a shutdown a service will first receive a CNTRL_SHUTDOWN_EVENT. The default is to do nothing for a service process per https://learn.microsoft.com/en-us/windows/console/handlerroutine#remarks, but that was changed for .NET processes in https://github.com/dotnet/runtime/pull/41101.

I was able to workaround this by adding ConsoleControlHandler that cancels other handlers when seeing CNTRL_SHUTDOWN_EVENT - stopping the runtime’s handler from shutting down the process and letting the service exit normally. In .NET 6.0 you can do this with a one-liner:

    using var registration = PosixSignalRegistration.Create(PosixSignal.SIGTERM, (context) => context.Cancel = true);

Just make sure that registration stays alive for the entire duration of the service - I put it in the Main() routine.

We should look into adding something like this to ServiceBase – or having the runtime try to avoid handling CNTRL_SHUTDOWN_EVENT for services.

believe there is a workaround in place to help with this issue? Will mark it for 9 to determine the feasibility of the fix.

This issue did help us discover the shutdown problem with CoreCLR’s CNTRL_SHUTDOWN_EVENT which I mentioned here: https://github.com/dotnet/runtime/issues/83093#issuecomment-1470814801.

We’ve seen other reports of this same problem, so I’d like to keep this issue open to track a fix for that in CoreCLR. @janvorli was looking into a fix for that.

Right, so I think that things have gone really clearer for me with this.

Part of the problem is that I was trying to use the backgroundservice in a way its not meant to be used.

So:

• If ExecuteAsync has a loop, it not necessarily will be fully finished when the service is ending.
• StopAsync is called at the end, but whatever happens in it might already be unloaded or unavailable.
• StopAsync shouldn’t have long tasks in it.

I have modified how I do the logging, and seems to be working fine now.

Thanks a lot @ericstj for your help through this.

If we all are ok, I am good to close this issue.

@gkapellmann I took a look at your repro. I was able to find out what was wrong by using Time-Travel debugging and examining the behavior at shutdown.

The PosixSignalRegistration workaround helped in that it did prevent the runtime from disabling exception handling, but the problem was there was still an unhandled exception in the logger:

(3/17/2023 9:24:59 AM) .ctor> Constructor...
(3/17/2023 9:24:59 AM) StartAsync> StartAsync...
(3/17/2023 9:24:59 AM) ExecuteAsync> Start of ExecuteAsync...
(3/17/2023 9:25:07 AM) StopAsync> StopAsync...
(3/17/2023 9:25:07 AM) StopAsync> System.AggregateException: An error occurred while writing to logger(s). (The interface is unknown.)
 ---> System.ComponentModel.Win32Exception (1717): The interface is unknown.
   at System.Diagnostics.EventLogInternal.InternalWriteEvent(UInt32 eventID, UInt16 category, EventLogEntryType type, String[] strings, Byte[] rawData, String currentMachineName)
   at System.Diagnostics.EventLogInternal.WriteEvent(EventInstance instance, Byte[] data, Object[] values)
   at System.Diagnostics.EventLog.WriteEvent(EventInstance instance, Byte[] data, Object[] values)
   at System.Diagnostics.EventLog.WriteEvent(EventInstance instance, Object[] values)
   at Microsoft.Extensions.Logging.EventLog.WindowsEventLog.WriteEntry(String message, EventLogEntryType type, Int32 eventID, Int16 category)
   at Microsoft.Extensions.Logging.EventLog.EventLogLogger.WriteMessage(String message, EventLogEntryType eventLogEntryType, Int32 eventId)
   at Microsoft.Extensions.Logging.EventLog.EventLogLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at Microsoft.Extensions.Logging.Logger.<Log>g__LoggerLog|13_0[TState](LogLevel logLevel, EventId eventId, ILogger logger, Exception exception, Func`3 formatter, List`1& exceptions, TState& state)
   --- End of inner exception stack trace ---
   at Microsoft.Extensions.Logging.Logger.ThrowLoggingError(List`1 exceptions)
   at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at Microsoft.Extensions.Logging.Logger`1.Microsoft.Extensions.Logging.ILogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at Microsoft.Extensions.Logging.LoggerExtensions.Log(ILogger logger, LogLevel logLevel, EventId eventId, Exception exception, String message, Object[] args)
   at Microsoft.Extensions.Logging.LoggerExtensions.Log(ILogger logger, LogLevel logLevel, String message, Object[] args)
   at Microsoft.Extensions.Logging.LoggerExtensions.LogInformation(ILogger logger, String message, Object[] args)
   at TestService.Worker.StopAsync(CancellationToken cancellationToken) in C:\scratch\SimpleWinService_dotnet\VeroTest-WinService\Worker.cs:line 45

This was preventing you from running your SaveCurrentLog method. I was able to workaround that by wrapping the call to _logger.LogInformation in your stopasync with a try/catch.

I’ll take a deeper look at this to see why it’s happening. Could be that this is normal during shutdown. Could be that a handle got disposed out from under the logger.

Ideally we don’t do this only in ServiceBase since that wouldn’t fix cases where folks were implementing services themselves without using ServiceBase. Instead we should try to replicate whatever the OS does in the default control handler to distinguish between normal console processes and services.

Looks similar to https://github.com/dotnet/runtime/issues/62579 and https://github.com/dotnet/runtime/issues/81274, @gkapellmann could you try the workaround mentioned and let us know if that helps your issue? The workaround is for unblocking you for short term, if you could let us know how it goes, it would be a useful data for to the team to find appropriate fix.