ExceptionOnStartIsPropagated test failed in CI

[stephentoub]

Build Information

Build: https://dev.azure.com/dnceng-public/cbb18261-c48f-4abb-8651-8cdcb5474649/_build/results?buildId=232981
Build error leg or test failing: Microsoft.Extensions.Hosting.WindowsServiceLifetimeTests.ExceptionOnStartIsPropagated
Pull request: #84556

Error Message

Fill the error message using known issues guidance.

{
  "ErrorMessage": "ExceptionOnStartIsPropagated",
  "BuildRetry": false,
  "ErrorPattern": "",
  "ExcludeConsoleLog": true
}

Failing Configuration
net8.0-windows-Release-x86-CoreCLR_release-Windows.Amd64.Server2022.Open
Exception Message
Half-way through waiting for remote process.
Memory load: 25
Image Name                     PID Services

========================= ======== ============================================

svchost.exe                    860 BrokerInfrastructure, DcomLaunch, PlugPlay,

Power, SystemEventsBroker

svchost.exe                    964 RpcEptMapper, RpcSs

svchost.exe                     72 LSM

svchost.exe                   1036 TermService

svchost.exe                   1064 lmhosts

svchost.exe                   1112 CoreMessagingRegistrar

svchost.exe                   1132 NcbService

svchost.exe                   1240 EventLog

svchost.exe                   1248 vmicheartbeat

svchost.exe                   1260 vmickvpexchange

svchost.exe                   1332 vmicshutdown

svchost.exe                   1380 vmictimesync

svchost.exe                   1472 DispBrokerDesktopSvc

svchost.exe                   1520 FontCache

svchost.exe                   1532 nsi

svchost.exe                   1580 gpsvc

svchost.exe                   1636 Dhcp

svchost.exe                   1644 Winmgmt

svchost.exe                   1668 UmRdpService

svchost.exe                   1728 Schedule

svchost.exe                   1920 NlaSvc

svchost.exe                   1952 CertPropSvc

svchost.exe                   2000 LanmanWorkstation

svchost.exe                   2016 TimeBrokerSvc

svchost.exe                   2036 ProfSvc

svchost.exe                   1416 Themes

svchost.exe                   1400 EventSystem

svchost.exe                   2112 netprofm

svchost.exe                   2152 SessionEnv

svchost.exe                   2188 SENS

svchost.exe                   2280 Dnscache

svchost.exe                   2300 Wcmsvc

svchost.exe                   2340 UserManager

svchost.exe                   2400 ShellHWDetection

svchost.exe                   2448 BFE, mpssvc

svchost.exe                   2512 WinHttpAutoProxySvc

svchost.exe                   2536 hns

svchost.exe                   2624 nvagent

svchost.exe                   2800 NetSetupSvc

svchost.exe                   2896 AppHostSvc

svchost.exe                   2904 CryptSvc

svchost.exe                   2916 DiagTrack

svchost.exe                   2948 iphlpsvc

svchost.exe                   3052 sacsvr

svchost.exe                   3060 RemoteRegistry

svchost.exe                   1768 SysMain     

CallStack
   at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose(Boolean disposing) in /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs:line 224
   at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose() in /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs:line 57
   at Microsoft.Extensions.Hosting.WindowsServiceTester.Dispose(Boolean disposing) in /_/src/libraries/Microsoft.Extensions.Hosting.WindowsServices/tests/WindowsServiceTester.cs:line 147
   at System.ComponentModel.Component.Dispose() in /_/src/libraries/System.ComponentModel.Primitives/src/System/ComponentModel/Component.cs:line 73
   at Microsoft.Extensions.Hosting.WindowsServiceLifetimeTests.ExceptionOnStartIsPropagated() in /_/src/libraries/Microsoft.Extensions.Hosting.WindowsServices/tests/WindowsServiceLifetimeTests.cs:line 82
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs:line 59

Report

Summary

24-Hour Hit Count	7-Day Hit Count	1-Month Count
0	0	0

Known issue validation

Build: 🔎 https://dev.azure.com/dnceng-public/public/_build/results?buildId=323960
Error message validated: ExceptionOnStartIsPropagated
Result validation: ✅ Known issue matched with the provided build.
Validation performed at: 6/28/2023 9:03:34 PM UTC

[stephentoub]

cc: @ericstj

[ghost]

Tagging subscribers to this area: @dotnet/area-extensions-hosting
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Build Information

Build: https://dev.azure.com/dnceng-public/cbb18261-c48f-4abb-8651-8cdcb5474649/_build/results?buildId=232981
Build error leg or test failing: Microsoft.Extensions.Hosting.WindowsServiceLifetimeTests.ExceptionOnStartIsPropagated
Pull request: #84556

Error Message

Fill the error message using known issues guidance.

{
  "ErrorMessage": "ExceptionOnStartIsPropagated",
  "BuildRetry": false,
  "ErrorPattern": "",
  "ExcludeConsoleLog": false
}

Failing Configuration
net8.0-windows-Release-x86-CoreCLR_release-Windows.Amd64.Server2022.Open
Exception Message
Half-way through waiting for remote process.
Memory load: 25
Image Name                     PID Services

========================= ======== ============================================

svchost.exe                    860 BrokerInfrastructure, DcomLaunch, PlugPlay,

Power, SystemEventsBroker

svchost.exe                    964 RpcEptMapper, RpcSs

svchost.exe                     72 LSM

svchost.exe                   1036 TermService

svchost.exe                   1064 lmhosts

svchost.exe                   1112 CoreMessagingRegistrar

svchost.exe                   1132 NcbService

svchost.exe                   1240 EventLog

svchost.exe                   1248 vmicheartbeat

svchost.exe                   1260 vmickvpexchange

svchost.exe                   1332 vmicshutdown

svchost.exe                   1380 vmictimesync

svchost.exe                   1472 DispBrokerDesktopSvc

svchost.exe                   1520 FontCache

svchost.exe                   1532 nsi

svchost.exe                   1580 gpsvc

svchost.exe                   1636 Dhcp

svchost.exe                   1644 Winmgmt

svchost.exe                   1668 UmRdpService

svchost.exe                   1728 Schedule

svchost.exe                   1920 NlaSvc

svchost.exe                   1952 CertPropSvc

svchost.exe                   2000 LanmanWorkstation

svchost.exe                   2016 TimeBrokerSvc

svchost.exe                   2036 ProfSvc

svchost.exe                   1416 Themes

svchost.exe                   1400 EventSystem

svchost.exe                   2112 netprofm

svchost.exe                   2152 SessionEnv

svchost.exe                   2188 SENS

svchost.exe                   2280 Dnscache

svchost.exe                   2300 Wcmsvc

svchost.exe                   2340 UserManager

svchost.exe                   2400 ShellHWDetection

svchost.exe                   2448 BFE, mpssvc

svchost.exe                   2512 WinHttpAutoProxySvc

svchost.exe                   2536 hns

svchost.exe                   2624 nvagent

svchost.exe                   2800 NetSetupSvc

svchost.exe                   2896 AppHostSvc

svchost.exe                   2904 CryptSvc

svchost.exe                   2916 DiagTrack

svchost.exe                   2948 iphlpsvc

svchost.exe                   3052 sacsvr

svchost.exe                   3060 RemoteRegistry

svchost.exe                   1768 SysMain     

CallStack
   at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose(Boolean disposing) in /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs:line 224
   at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose() in /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs:line 57
   at Microsoft.Extensions.Hosting.WindowsServiceTester.Dispose(Boolean disposing) in /_/src/libraries/Microsoft.Extensions.Hosting.WindowsServices/tests/WindowsServiceTester.cs:line 147
   at System.ComponentModel.Component.Dispose() in /_/src/libraries/System.ComponentModel.Primitives/src/System/ComponentModel/Component.cs:line 73
   at Microsoft.Extensions.Hosting.WindowsServiceLifetimeTests.ExceptionOnStartIsPropagated() in /_/src/libraries/Microsoft.Extensions.Hosting.WindowsServices/tests/WindowsServiceLifetimeTests.cs:line 82
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs:line 59

Author:	stephentoub
Assignees:	-
Labels:	blocking-clean-ci, untriaged, area-Extensions-Hosting, Known Build Error
Milestone:	-

[ericstj]

Most of the failures listed here were not the same as @stephentoub's OP issue. Many were due to the test running on a platform that didn't support RemoteExecutor (not part of default platform set) which was fixed in #84552.

I was able to pull down @stephentoub's test failure and dump with:

runfo get-helix-payload -j 4248a943-5561-4089-8b71-74bd05dc0faf -w Microsoft.Extensions.Hosting.WindowsServices.Tests -x -o .\

The test was inside the service dispatcher, which I would imagine would mean the service as Started.

09F0FCB8 73e1716f [DebuggerU2MCatchHandlerFrame: 09f0fcb8] 
0:000> !dumpasync
Statistics:
      MT    Count    TotalSize Class Name
09f86130        1           72 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions+<WaitForShutdownAsync>d__5, Microsoft.Extensions.Hosting.Abstractions]]
0968d1d8        1           80 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions+<RunAsync>d__4, Microsoft.Extensions.Hosting.Abstractions]]
Total 2 objects
 Address       MT     Size      State Description
03b7958c 0968d1d8       80          1 Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions+<RunAsync>d__4
03b8c898 09f86130       72          0 Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions+<WaitForShutdownAsync>d__5

So waiting here:

runtime/src/libraries/Microsoft.Extensions.Hosting.Abstractions/src/HostingAbstractionsHostExtensions.cs

Line 69 in 018a37b

await host.WaitForShutdownAsync(token).ConfigureAwait(false);

and here

runtime/src/libraries/Microsoft.Extensions.Hosting.Abstractions/src/HostingAbstractionsHostExtensions.cs

Line 107 in 018a37b

await waitForStop.Task.ConfigureAwait(false);

The service status is running:

0:004> !DumpVC /d 076dee98 03b78944
Name:        Interop+Advapi32+SERVICE_STATUS
MethodTable: 076dee98
EEClass:     0774e358
Size:        36(0x24) bytes
File:        C:\h\w\95CF08EA\w\C2450A2C\e\System.ServiceProcess.ServiceController.dll
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
038ab574  400016e        0         System.Int32  1 instance       16 serviceType
038ab574  400016f        4         System.Int32  1 instance        4 currentState
038ab574  4000170        8         System.Int32  1 instance        5 controlsAccepted
038ab574  4000171        c         System.Int32  1 instance        0 win32ExitCode
038ab574  4000172       10         System.Int32  1 instance        0 serviceSpecificExitCode
038ab574  4000173       14         System.Int32  1 instance        0 checkPoint
038ab574  4000174       18         System.Int32  1 instance        0 waitHint

What's interesting though, is that the service that's running is actually not ExceptionOnStartIsPropagated, it's

02D7ED38 03b6a354 System.String    <CanCreateService>b__2_0
02D7ED3C 03b6a2d8 System.String    Microsoft.Extensions.Hosting.UseWindowsServiceTests+<>c
02D7ED40 03b6a1e0 System.String    Microsoft.Extensions.Hosting.WindowsServices.Tests, Version=8.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60

Now that test can run concurrently, since it's in another test class, but it should always create a different service - since the service name is determined by the calling method name. One thing that could happen is process ID recycling.

runtime/src/libraries/Microsoft.Extensions.Hosting.WindowsServices/tests/WindowsServiceTester.cs

Lines 40 to 45 in 7a57f6d

	var statusEx = QueryServiceStatusEx();
	try
	{
	_remoteInvokeHandle.Process = Process.GetProcessById(statusEx.dwProcessId);
	// fetch the process handle so that we can get the exit code later.
	var _ = _remoteInvokeHandle.Process.SafeHandle;

So if the process for ExceptionOnStartIsPropagated exited and a new process was created with the same ID before we could grab the handle, we could be tracking a different process than the one launched for the test case. However that wouldn't explain the process stuck in running case for that long -- since the CanCreateService test should proceed to stopped state as soon as it's up and running, and according to the log, all other tests passed:

   Microsoft.Extensions.Hosting.WindowsServices.Tests  Total: 12, Errors: 0, Failed: 1, Skipped: 0, Time: 109.919s

[ericstj]

All failures here are

System.ComponentModel.Win32Exception : Access is denied.
   at System.Diagnostics.ProcessManager.OpenProcess(Int32 processId, Int32 access, Boolean throwIfExited) in /_/src/libraries/System.Diagnostics.Process/src/System/Diagnostics/ProcessManager.Windows.cs:line 252
   at System.Diagnostics.Process.GetProcessHandle(Int32 access, Boolean throwIfExited) in /_/src/libraries/System.Diagnostics.Process/src/System/Diagnostics/Process.Windows.cs:line 787
   at System.Diagnostics.Process.WaitForExitCore(Int32 milliseconds) in /_/src/libraries/System.Diagnostics.Process/src/System/Diagnostics/Process.Windows.cs:line 167
   at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose(Boolean disposing) in /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs:line 110
   at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose() in /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs:line 55
   at Microsoft.Extensions.Hosting.WindowsServiceTester.Dispose(Boolean disposing) in /_/src/libraries/Microsoft.Extensions.Hosting.WindowsServices/tests/WindowsServiceTester.cs:line 147
   at System.ComponentModel.Component.Dispose() in /_/src/libraries/System.ComponentModel.Primitives/src/System/ComponentModel/Component.cs:line 73
   at Microsoft.Extensions.Hosting.WindowsServiceLifetimeTests.ExceptionOnStartIsPropagated() in /_/src/libraries/Microsoft.Extensions.Hosting.WindowsServices/tests/WindowsServiceLifetimeTests.cs:line 85
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.cs:line 57

I'd bet that these cases the process is in the middle shutting down by the time we try to get its handle. I bet we could avoid this by either delaying start - or introducing a cross-process message like a global mutex to tell the process when it's ok to throw.

[jeffschwMSFT]

removing blocking-clean-ci as it has not failed in 30 days

24-Hour Hit Count	7-Day Hit Count	1-Month Count
0	0	0

[ericstj]

I don't believe this is hit at all anymore after the fix to not run in environments that don't support remote executor. Closing this out.