Windows service infrequently results in error 1067 on stop operation
zryska opened this issue · 36 comments
Description
.NET 6 published application sometimes crashes on service stop operation. I created a web application from the template and only added the Microsoft.Extensions.Hosting.WindowsServices (version 6.0.0) package and called UseWindowsService() to make sure the application listens for service controller requests.
Here is the code:
using Microsoft.Extensions.Hosting.WindowsServices;
var options = new WebApplicationOptions
{
Args = args,
ContentRootPath = WindowsServiceHelpers.IsWindowsService() ? AppContext.BaseDirectory : default
};
var builder = WebApplication.CreateBuilder(options);
// Add services to the container.
builder.Services.AddRazorPages();
builder.Host.UseWindowsService();
var app = builder.Build();
// Configure the HTTP request pipeline.
if (!app.Environment.IsDevelopment())
{
app.UseExceptionHandler("/Error");
}
app.UseStaticFiles();
app.UseRouting();
app.UseAuthorization();
app.MapRazorPages();
app.Run();Reproduction Steps
Repository with code, script and repro steps: https://github.com/zryska/net6-repro
- Create a new Web application using a template
- Make the changes to add UseWindowsService() call as shown above
- Publish the application as SFD or FDD for win-x64 runtime
- Create a new service using
sc createcommand - Start the service and verify it's running
- Stop the service
- Start the service
- Repeat steps 4 and 5 until the issue is reproduced
It can be done through the services UI or using a script. On my system it usually happens 1 time out of 10 graceful shutdowns - but it isn't deterministic.
When done through services UI the following will be displayed:
Even log => Windows Logs -> System will contain the following message (when done through script or UI):
The .NET6 test service service terminated unexpectedly. It has done this 26 time(s).
Expected behavior
Service stops gracefully every time.
Actual behavior
Non-graceful shutdowns are happening.
Regression?
No response
Known Workarounds
Explicitly assigning value to ServiceName fixes the problem.
builder.Host.UseWindowsService(o => o.ServiceName = "AnyServiceName");
Configuration
.NET version: .NET 6.0.100
OS version: Windows 10 pro build 19044.1348
Architecture: x64
Other information
No response
Tagging subscribers to this area: @dotnet/area-extensions-hosting
See info in area-owners.md if you want to be subscribed.
Issue Details
Description
.NET 6 published application sometimes crashes on service stop operation. I created a web application from the template and only added the Microsoft.Extensions.Hosting.WindowsServices (version 6.0.0) package and called UseWindowsService() to make sure the application listens for service controller requests.
Here is the code:
using Microsoft.Extensions.Hosting.WindowsServices;
var options = new WebApplicationOptions
{
Args = args,
ContentRootPath = WindowsServiceHelpers.IsWindowsService() ? AppContext.BaseDirectory : default
};
var builder = WebApplication.CreateBuilder(options);
// Add services to the container.
builder.Services.AddRazorPages();
builder.Host.UseWindowsService();
var app = builder.Build();
// Configure the HTTP request pipeline.
if (!app.Environment.IsDevelopment())
{
app.UseExceptionHandler("/Error");
}
app.UseStaticFiles();
app.UseRouting();
app.UseAuthorization();
app.MapRazorPages();
app.Run();Reproduction Steps
- Publish the application as SFD or FDD for win-x64 runtime
- Create a new service using
sc createcommand - Start the service and verify it's running
- Stop the service
- Start the service
- Repeat steps 4 and 5 until the issue is reproduced
It can be done through the services UI or using a script. On my system it usually happens 1 time out of 10 graceful shutdowns - but it isn't deterministic.
When done through services UI the following will be displayed:
Even log => Windows Logs -> System will contain the following message (when done through script or UI):
The .NET6 test service service terminated unexpectedly. It has done this 26 time(s).
Expected behavior
Service stops gracefully every time.
Actual behavior
Non-graceful shutdowns are happening.
Regression?
No response
Known Workarounds
No response
Configuration
.NET version: .NET 6.0.100
OS version: Windows 10 pro build 19044.1348
Architecture: x64
Other information
No response
| Author: | zryska |
|---|---|
| Assignees: | - |
| Labels: |
|
| Milestone: | - |
Any chance you can get more information here to narrow down where the problem is? Maybe try getting a crash dump.
https://github.com/dotnet/diagnostics/blob/main/documentation/dotnet-dump-instructions.md
Or adding a try-catch somewhere in your project to try to catch the exception.
Can you attach a Debugger before stopping the service? If you do, does it still crash?
I wasn't able to get a crash dump generated for some reason. Also when I included try-catch block around the main method it didn't catch anything. The application seems to be crashing after it leaves the main method. When I run the same code on Linux just with systemd package instead of WindowsServices the same code works just fine.
Your best bet here is to get more information - what is the stacktrace / message / etc that is causing the process to crash.
The issue is not surfacing when I have debugger attached. Would you be able to give it a try on your end by following the repro steps or is there something else I could provide in terms of repro to make it easier?
I wasn't able to get a crash dump generated for some reason
Was dotnet-dump not working for you? What was the reason?
My understanding was that dotnet-dump allows only to generate a dump at time of executing the collect command. I was using SysInternals ProcDump but it didn't create any crash dump even when service manager reported crash.
This is procdump output from event when service controller reported ungraceful shutdown:
PS C:\Users\zryska\Tools\Procdump> .\procdump64.exe -ma -e WebApplication1.exe
ProcDump v10.11 - Sysinternals process dump utility
Copyright (C) 2009-2021 Mark Russinovich and Andrew Richards
Sysinternals - www.sysinternals.com
Process: WebApplication1.exe (41180)
Process image: C:\Program Files\Test\WebApplication1.exe
CPU threshold: n/a
Performance counter: n/a
Commit threshold: n/a
Threshold seconds: n/a
Hung window check: Disabled
Log debug strings: Disabled
Exception monitor: Unhandled
Exception filter: [Includes]
*
[Excludes]
Terminate monitor: Disabled
Cloning type: Disabled
Concurrent limit: n/a
Avoid outage: n/a
Number of dumps: 1
Dump folder: C:\Users\zryska\Downloads\Procdump\
Dump filename/mask: PROCESSNAME_YYMMDD_HHMMSS
Queue to WER: Disabled
Kill after dump: Disabled
Press Ctrl-C to end monitoring without terminating the process.
[22:27:46] Exception: E0434352.CLR
[22:27:46] Exception: E0434352.CLR
[22:27:46] Exception: E0434352.CLR
[22:27:46] Exception: E0434352.CLR
[22:27:46] Exception: 00000006
[22:27:46] Exception: E0434352.CLR
[22:27:46] Exception: E0434352.CLR
[22:27:47] The process has exited.
[22:27:47] Dump count not reached.
C:\Users\zryska\Downloads\Procdump\
There's no dump files in that folder?
Can you try https://docs.microsoft.com/en-us/windows/win32/wer/collecting-user-mode-dumps? Or possibly https://docs.microsoft.com/en-us/visualstudio/debugger/debug-using-the-just-in-time-debugger?view=vs-2022#BKMK_Enabling?
No. No dumps were created. I should also mention that the main method apparently exists gracefully since in case I add a line of code to create a file before exiting main the file gets created even when the service control manager reports that the application crashed. I was trying the registry approach in the past when I was suspecting that something is wrong in our code application without results but I can give it a try again with the empty WebApplication project.
Look at the event log to se if there's more information.
Hi David, unfortunately the event log doesn't contain anything actionable. The alleged crash event is logged in the system log and there is nothing in the Application log around that time.
Here is the raw event (removed computer name) in case there is something I missed:
- <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
- <System>
<Provider Name="Service Control Manager" Guid="{555908d1-a6d7-4695-8e1e-26931d2012f4}" EventSourceName="Service Control Manager" />
<EventID Qualifiers="49152">7034</EventID>
<Version>0</Version>
<Level>2</Level>
<Task>0</Task>
<Opcode>0</Opcode>
<Keywords>0x8080000000000000</Keywords>
<TimeCreated SystemTime="2021-12-10T08:15:28.6705360Z" />
<EventRecordID>105858</EventRecordID>
<Correlation />
<Execution ProcessID="1632" ThreadID="29084" />
<Channel>System</Channel>
<Computer>ComputerName</Computer>
<Security />
</System>
- <EventData>
<Data Name="param1">.NET6 test service</Data>
<Data Name="param2">7</Data>
<Binary>2E004E0045005400360020007400650073007400200073006500720076006900630065000000</Binary>
</EventData>
</Event>I tried to replicate it on another machine with lower HW specs:
CPU: 4 cores
RAM: 8 GB
OS: Windows 10 Enterprise build: 19042.1348
It still happened but much less frequently. I let the script run for a while and out of 1000 restarts there were just two "crash" events reported in the event log.
For comparison my development machine HW specs:
CPU: 16 cores
RAM: 32 GB
OS: Windows 10 Pro build: 19044.1348
I moved the repro code into a separate repository if it helps: https://github.com/zryska/net6-repro
@zryska use procdump64.exe -mp -t -e 1 -x . "WebApplication1.exe"
I did start it like this many times and usually it ended with first chance exception (TaskCanceledException) which is fine but the output below caught my attention - Access Violation is reported by the tool but curiously no crash dump has been created:
PS C:\Tools\ProcDump> ./procdump64.exe -mp -t -e 1 -x . "C:\Users\zryska\source\repos\net6-repro\TestApp\bin\Release\net6.0\win-x64\publish\TestApp.exe"
ProcDump v10.11 - Sysinternals process dump utility
Copyright (C) 2009-2021 Mark Russinovich and Andrew Richards
Sysinternals - www.sysinternals.com
Process: TestApp.exe (8884)
CPU threshold: n/a
Performance counter: n/a
Commit threshold: n/a
Threshold seconds: n/a
Hung window check: Disabled
Log debug strings: Disabled
Exception monitor: First Chance+Unhandled
Exception filter: [Includes]
*
[Excludes]
Terminate monitor: Enabled
Cloning type: Disabled
Concurrent limit: n/a
Avoid outage: n/a
Number of dumps: 1
Dump folder: .\
Dump filename/mask: PROCESSNAME_YYMMDD_HHMMSS
Queue to WER: Disabled
Kill after dump: Disabled
Press Ctrl-C to end monitoring without terminating the process.
CoreCLR Version: v6.0.0
info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[63]
User profile is available. Using 'C:\Users\zryska\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
info: Microsoft.Hosting.Lifetime[14]
Now listening on: http://localhost:5000
info: Microsoft.Hosting.Lifetime[14]
Now listening on: https://localhost:5001
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: C:\Tools\ProcDump\
^C
info: Microsoft.Hosting.Lifetime[0]
Application is shutting down...
Fatal error. System.AccessViolationException: Attempted to read or write protected memory. This is often an indication that other memory is corrupt.
[21:51:41] Dump count not reached.
@zryska . (which means current working dir) is dump folder location, check C:\Tools\ProcDump
Also procdump is directly running app, so it won't start as a service, so it's something else happening here
You should probably remove -x flag and attach procdump to service (via Start-Process without -Wait) in your script
add -n 100 to write all dumps (not only first)
Right, I was just following the advice and no no hang dumps were created in the folder. I did setup ProcDump to listen for unhandled exceptions before but it didn't yield any results (mentioned in my post from 5 days ago) so I tried to include -t argument to create a hang dump on exit which worked but not sure if it captured anything useful.
I uploaded the dumps to OneDrive: https://1drv.ms/u/s!AheZovM5WWRui6EDvqm7DM4PA0PunA?e=RPaXn1
Recorded event is output of the following run:
PS C:\Tools\ProcDump> ./procdump64.exe -mp -t -e 1 "TestApp.exe"
ProcDump v10.11 - Sysinternals process dump utility
Copyright (C) 2009-2021 Mark Russinovich and Andrew Richards
Sysinternals - www.sysinternals.com
Process: TestApp.exe (21868)
Process image: C:\Program Files\Net6Test\TestApp.exe
CPU threshold: n/a
Performance counter: n/a
Commit threshold: n/a
Threshold seconds: n/a
Hung window check: Disabled
Log debug strings: Disabled
Exception monitor: First Chance+Unhandled
Exception filter: [Includes]
*
[Excludes]
Terminate monitor: Enabled
Cloning type: Disabled
Concurrent limit: n/a
Avoid outage: n/a
Number of dumps: 1
Dump folder: C:\Tools\ProcDump\
Dump filename/mask: PROCESSNAME_YYMMDD_HHMMSS
Queue to WER: Disabled
Kill after dump: Disabled
Press Ctrl-C to end monitoring without terminating the process.
CoreCLR Version: v6.0.0
[21:45:44] Exception: E0434F4D.System.Net.Sockets.SocketException ("The I/O operation has been aborted because of either a thread exit or an application request.")
[21:45:44] Dump 1 initiated: C:\Tools\ProcDump\TestApp.exe_211212_214544.dmp
[21:45:45] Dump 1 complete: 215 MB written in 0.8 seconds
[21:45:45] Dump count reached.
and HangDumps.7z contains set of hang dumps created by ProcDump when ungraceful shutdown was recorded in event log. Looking at timestamps it the last hang dump created was @11:42:48 and even log issue is timestamped @11.42.50 (screenshot is included in the archive). When first chance exceptions were enabled the issue was happening much less frequently since the application took longer time to teardown.
I also reinstalled my PC with clean Windows 11 Pro (OS build: 22000.348) and the issue persist (previously I didn't test with Windows 11). It might be worth giving the repro a try: https://github.com/zryska/net6-repro
I can confirm that running Start-Service Stop-Service loop creates Error entries in system journal
using Microsoft.Extensions.Hosting.WindowsServices;
WebApplication.CreateBuilder(new WebApplicationOptions
{
Args = args,
ContentRootPath = WindowsServiceHelpers.IsWindowsService() ? AppContext.BaseDirectory : default
})
.Host.UseWindowsService().Build().Run();I noticed that this bug item has been labeled with the 7.0.0 milestone. We have our application service set to auto-restart on failures and this bug is significant for us since it affects the reliability of the application upgrade logic - It is preventing us to migrate to .NET 6.
Is there any chance that this gets fixed in .NET 6?
I think folks are still investigating root cause here and proposed fix. If this turns out to be a regression and blocking move to 6.0 that would make it a candidate for servicing. The first step is to understand the issue and make a fix in 7.0 then we can consider for backport.
Did you happen to observe this as a regression from a previous release, and if so, from which release? That could help folks narrow down where the problem might be.
I was able to repro this problem in 6.0, I gave a try with
<PackageReference Include="Microsoft.Extensions.Hosting.WindowsServices" Version="5.0.0" />
and
<PackageReference Include="Microsoft.Extensions.Hosting.WindowsServices" Version="3.1.0" />
And reproduced the same issue. So it seems like this is not a change in the service libraries (M.E.H.WindowsServices, or S.SP.ServiceController) in 5.0 or 6.0. It might be interesting to try the same with other versions of the ASP.NET libraries, which will require some changes to the repro code. I'll give this a try and report back.
Thank you, Eric. It looks like the problem might be linked to the actual runtime. We have been using .NET core 3.1 for a while and haven't seen this issue. I also created .NET core 3.1 based repro that now has been restarted over 1000 times and there are no failures in the log (thus far - I plan to let it run for a while).
I am using:
<PackageReference Include="Microsoft.Extensions.Hosting.WindowsServices" Version="3.1.22" />
I ran into the issue a while back with .NET 5 but I didn't dig deeper due to time constraints, essentially I wasn't sure if the problem isn't rooted in our code.
I was able to repro when targeting net5.0. Here's the app: https://gist.github.com/ericstj/b6e6f93b0ce41c417571636beeacaeb0
It occurred less often, but I still hit it 3 times in 40 tries, so this doesn't appear to be a regression, but may have become more prevalent in 6.0. I can try on 3.1 as well.
It may not be runtime, but it could be in ASP.NET or other Microsoft.Extensions libraries (hosting, etc).
I tried on 3.1 and agree with you that this doesn't seem to repro at all, so likely this was introduced by some change in 5.0.
The problem appears to be an unhandled exception during the call to Stop. It's caused by an empty ServiceName property. Here's the callstack
Exception type: System.ArgumentException
Message: Source property was not set before writing to the event log.
InnerException: <none>
StackTrace (generated):
<none>
StackTraceString: <none>
HResult: 80070057
0:036> !clrstack
OS Thread Id: 0x6508 (36)
Child SP IP Call Site
000000DF38FFF228 00007ffa3977466c [HelperMethodFrame: 000000df38fff228]
000000DF38FFF320 00007ff9ee2b4b1f System.Diagnostics.EventLogInternal.WriteEntry(System.String, System.Diagnostics.EventLogEntryType, Int32, Int16, Byte[]) [/_/src/libraries/System.Diagnostics.EventLog/src/System/Diagnostics/EventLogInternal.cs @ 1301]
000000DF38FFF390 00007ff9ee2afcb7 System.Diagnostics.EventLog.WriteEntry(System.String, System.Diagnostics.EventLogEntryType) [/_/src/libraries/System.Diagnostics.EventLog/src/System/Diagnostics/EventLog.cs @ 987]
000000DF38FFF3D0 00007ff910eb612a System.ServiceProcess.ServiceBase.WriteLogEntry(System.String, System.Diagnostics.EventLogEntryType) [/_/src/libraries/System.ServiceProcess.ServiceController/src/System/ServiceProcess/ServiceBase.cs @ 951]
000000DF38FFF420 00007ff911101ce7 System.ServiceProcess.ServiceBase.DeferredStop() [/_/src/libraries/System.ServiceProcess.ServiceController/src/System/ServiceProcess/ServiceBase.cs @ 519]
000000DF38FFF4A0 00007ff911101c0f System.ServiceProcess.ServiceBase+c__DisplayClass68_0.b__2(System.Object) [/_/src/libraries/System.ServiceProcess.ServiceController/src/System/ServiceProcess/ServiceBase.cs @ 802]
000000DF38FFF4D0 00007ff9546667b9 System.Threading.QueueUserWorkItemCallbackDefaultContext.Execute() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPoolWorkQueue.cs @ 960]
000000DF38FFF500 00007ff9546655de System.Threading.ThreadPoolWorkQueue.Dispatch()
000000DF38FFF590 00007ff95466d22a System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.cs @ 63]
000000DF38FFF6A0 00007ff954651c6f System.Threading.Thread.StartCallback() [/_/src/coreclr/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 105]
000000DF38FFF930 00007ff9707ba243 [DebuggerU2MCatchHandlerFrame: 000000df38fff930]
For me I was able to specify the service name as follows and it fixes the issue:
builder.Host.UseWindowsService(e => e.ServiceName = "EricWebSvc");
I'll see if I can build a theory as to why this wasn't an issue in 3.1.
Correction: this doesn't appear to be unhandled, WriteLogEntry swallows it, but for whatever reason avoiding this exception seems to fix the errors for me.
Thank you, Eric! I noticed this exception being thrown and handled consistently every time so I didn't pay too much attention to it but specifying ServiceName does seem to eliminate ungraceful shutdowns.
I attached the ProcDump to the .NET core 3.1 repro application and the ArgumentException is not being thrown on stop operation. In case of .NET 6 - assigning value to the ServiceName seems like a viable way forward for now - I'll let the script cycle for a while to confirm but so far so good.
I was able to reproduce the ArgumentException on 3.1 as well, my best guess right now is that this is somehow timing related. If have some more cycles I will try to understand more. Glad you're unblocked for now.
There should be some action here for ServiceBase regardless: it shouldn't be calling log when it knows it will fail. It should either avoid using the event log when ServiceName is empty or specify some default value for ServiceName in this case (perhaps it can calculate it or fetch it from SCM?).
Fetching the name from SCM sounds like a good way forward to me - it eliminates potential surprises.
I have been testing our application on .NET 6 today and all looks good functionality-wise - I noticed some increased resource consumption (memory, threads, and handles) compared to .NET core 3.1 but I was doing comparison just on ARM64 platform for now. I'll dig deeper into it and test on other platforms too - needless to say, that it's completely unrelated to this issue :). The workaround certainly does unblock us - thank you again for looking into it!
I opened #62923 to track improving the service name issue.
I was able to find out the root cause here. It's actually a timing bug. The process is exiting (cleanly) before ServiceBase has a change to tell SCM that the service is stopped. The reason that we "fixed" it by setting the service name is that we made the code in front of the service stop go faster and give it a better chance at winning the race.
Here's roughly what's happening. The Run method is waiting on
Which will be unblocked by
That call will advance the main thread to here:
Which will then signal Stopped here:
This sets this event:
And runs StopAsync which just queues up a redundant call to ServiceBase.Stop:
But then falls through back to Run / Main, without actually doing anything to wait on the background thread completing. At this point its a race between the background thread trying to complete the DeferredStop method:
And main falling through and retuning causing the process to exit before background threads complete.
So our fix to set the service name just shortened the time spent in the DeferredStop method and made it more likely to reach the point which it can complete its work and notify SCM.
I was able to prove this theory by artificially increasing the time spent in OnStop. After doing this I had 100% repro of the service terminated unexpectedly error. Then I added a delay in the end of my main routine after Run() to exceed this delay and made the error go away.
I think the fix here is to somehow make it so that ServiceBase will tell SCM that its stopped before Run() is allowed to complete. I haven't yet determined what that the best way to do that might be. I'm not sure how to guarantee that ServiceBase has completed its DeferredStop method.
I believe the only guarantee from ServiceBase that the service stop has completed is when Run(ServiceBase) returns, so I think WindowsServiceLifetime needs to somehow consider this when communicating the end that ultimately unblocks the main thread.
Looks like the inverse of this situation was also seen as a problem: dotnet/extensions#1323
The fix for that issue was what introduced this race condition. dotnet/extensions#2048
The missing piece here is that nothing is holding up main to wait for Run to return. Since it seems like this can't go in StopAsync for the reason @xqrzd mentioned in dotnet/extensions#2048, perhaps we can have the Dispose method wait on Run(ServiceBase) returning. I can imagine from a certain perspective that this is correct behavior for dispose since this is effectively waiting to dispose the background thread.
Since it seems like this can't go in StopAsync for the reason @xqrzd mentioned in dotnet/extensions#2048,
Actually that's not the case any more. In StopAsync we say:
At the time that comment was made, this was true:
https://github.com/dotnet/extensions/blob/86e38007b27f3a464223908075c57f1d7f5ee649/src/Hosting/Hosting/src/Internal/Host.cs#L87-L91
However now, that's no longer true:
runtime/src/libraries/Microsoft.Extensions.Hosting/src/Internal/Host.cs
Lines 144 to 150 in 967250c
That was fixed by #39832 by @WernerMairl.
Now I think we can remove that comment and make this method either wait on Stop() completing, which will set the Service state, or we can add an event that's signaled when ServiceBase.Run() returns and wait on that in WindowsServiceLifetime.StopAsync().
We should prioritize the fix for this and consider backporting to .NET 7.0 and 6.0. The workaround to wait some time before exiting doesn't sufficiently solve the problem, because it doesn't hold up the progress of
Which will dispose the service and make it impossible for the service state to be updated.
@buyaa-n as we discussed, we can try the fix of signaling an in Run when ServiceBase.Run(..) returns, then waiting on this in StopAsync. This will ensure that the service has safely exited.
Keeping open for servicing.
@ericstj would be awesome if this would be backported to .NET 6 and 7. We are currently experiencing this exact problem with one of our applications.
Yes, that’s the plan. Most likely the June release.
If you have the ability to test daily bits you can try the net8.0 package to confirm the fix works for you. That can be restored from
Line 22 in f107b4b
If you are able to try and confirm the fix that helps us ensure we got things right. Thanks!