Closed eerhardt closed 8 months ago
Tagging subscribers to this area: @tarekgh, @tommcdon, @pjanotti See info in area-owners.md if you want to be subscribed.
Author: | eerhardt |
---|---|
Assignees: | - |
Labels: | `area-System.Diagnostics.Tracing` |
Milestone: | - |
Failed again in runtime-coreclr libraries-jitstress 20210525.1
Failed test:
net6.0-windows-Release-x64-CoreCLR_checked-jitstress2_tiered-Windows.10.Amd64.Open
- BasicEventSourceTests.TestsManifestGeneration.Test_EventSource_EtwManifestGenerationRollover
Error message:
Half-way through waiting for remote process.
Memory load: 11
Image Name PID Services
========================= ======== ============================================
svchost.exe 772 BrokerInfrastructure, DcomLaunch, LSM,
PlugPlay, Power, SystemEventsBroker
svchost.exe 832 RpcEptMapper, RpcSs
svchost.exe 956 TermService
svchost.exe 976 Appinfo, CertPropSvc, DsmSvc, gpsvc,
iphlpsvc, lfsvc, ProfSvc, sacsvr, Schedule,
SENS, SessionEnv, ShellHWDetection, Themes,
UserManager, Winmgmt, WpnService, wuauserv
svchost.exe 340 Dhcp, EventLog, lmhosts, TimeBrokerSvc,
vmictimesync
svchost.exe 476 NcbService, PcaSvc, TrkWks, UALSVC,
UmRdpService, vmickvpexchange,
vmicshutdown, WdiSystemHost
svchost.exe 1052 CDPSvc, EventSystem, FontCache, netprofm,
nsi, W32Time, WinHttpAutoProxySvc
svchost.exe 1084 BFE, CoreMessagingRegistrar, DPS, MpsSvc,
pla
svchost.exe 1224 CryptSvc, Dnscache, LanmanWorkstation,
NlaSvc, WinRM
svchost.exe 1260 vmicheartbeat
svchost.exe 1552 Wcmsvc
svchost.exe 2000 AppHostSvc
svchost.exe 2024 LanmanServer
svchost.exe 2032 DiagTrack
svchost.exe 1512 W3SVC, WAS
svchost.exe 2064 StateRepository, tiledatamodelsvc
svchost.exe 3196 CDPUserSvc_6317d, OneSyncSvc_6317d
svchost.exe 784 AppReadiness
Timed out at 5/25/2021 8:14:10 AM after 60000ms waiting for remote process.
Wrote mini dump to: C:\h\w\B12409BB\w\B54909A0\uploads\4628.mfivcd45.ppy.dmp
Process ID: 4628
Handle: 1076
Name: dotnet
MainModule: C:\h\w\B12409BB\p\dotnet.exe
StartTime: 5/25/2021 8:13:07 AM
TotalProcessorTime: 00:00:03.7343750
Threads:
Thread #1 (OS 0x378) [MTA]
[HelperMethodFrame] (System.Threading.Thread.SleepInternal)
System.Threading.Thread.Sleep(Int32)
BasicEventSourceTests.TestsManifestGeneration.<Test_EventSource_EtwManifestGenerationRollover>b__6_0()
[DebuggerU2MCatchHandlerFrame]
[HelperMethodFrame_PROTECTOBJ] (System.RuntimeMethodHandle.InvokeMethod)
System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)
System.Reflection.MethodBase.Invoke(System.Object, System.Object[])
Microsoft.DotNet.RemoteExecutor.Program.Main(System.String[])
Thread #2 (OS 0x838) [Finalizer] [Background]
[DebuggerU2MCatchHandlerFrame]
Stack trace
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 BasicEventSourceTests.TestsManifestGeneration.Test_EventSource_EtwManifestGenerationRollover() in /_/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestsManifestGeneration.Etw.cs:line 81
Is this still an issue? Runfo shows 0 failures in the last month
Removing label because of no occurrences recently
Happened just now in runtimelab regexsrm branch, but the code there is at least a week or two old vs runtime.
@krwq if we don't see instances in a month, and hav e no data to go on or theories, should we simply close?
Failed again in runtime-extra-platforms:
From the console log:
Analysis of the failure from https://github.com/dotnet/runtime/pull/77956:
0:000> !pe
StackTrace (generated):
SP IP Function
0337D8D8 0B1E4349 xunit_assert!Xunit.Assert.True(System.Nullable`1
2. The crash dump collection caused by the test failure is hung:
0:000> k
00 0337cbf8 74623c10 ntdll!NtWaitForMultipleObjects+0xc [d:\rs1.obj.x86fre\minkernel\ntdll\wow6432\objfre\i386\usrstubs.asm @ 821] 01 0337cbf8 74623b08 KERNELBASE!WaitForMultipleObjectsEx+0xf0 [d:\rs1\minkernel\kernelbase\synch.c @ 1551] 02 0337cc14 753c74a2 KERNELBASE!WaitForMultipleObjects+0x18 [d:\rs1\minkernel\kernelbase\synch.c @ 1403] 03 0337d090 753c6ee6 kernel32!WerpReportFaultInternal+0x59d [d:\rs1\onecore\windows\feedback\core\faultrep\lib\faultrep.cpp @ 1104] 04 0337d0ac 7539e699 kernel32!WerpReportFault+0x9b [d:\rs1\onecore\windows\feedback\core\faultrep\lib\faultrep.cpp @ 1400] 05 0337d0b4 746ac6da kernel32!BasepReportFault+0x19 [d:\rs1\base\win32\client\wer.c @ 44] 06 0337d14c 7717d30e KERNELBASE!UnhandledExceptionFilter+0x25a [d:\rs1\minkernel\kernelbase\xcpt.c @ 667] 07 (Inline) -------- ntdll!RtlpThreadExceptionFilter+0x24 [d:\rs1\minkernel\ntdll\rtlstrt.c @ 801] 08 0337f8d4 77141b34 ntdll!__RtlUserThreadStart+0x3b7d4 [d:\rs1\minkernel\ntdll\rtlstrt.c @ 998] 09 0337f8e4 00000000 ntdll!_RtlUserThreadStart+0x1b [d:\rs1\minkernel\ntdll\rtlstrt.c @ 914]
So there are really two problems: EventSource test failure and crash dump collection hang.
Hit this today in a release/7.0
deps update PR: https://github.com/dotnet/runtime/pull/78122
I guess it makes sense to see it there too since the issue has been open since 2021.
Libraries Test Run checked coreclr windows x86 Debug
----- start Fri 11/11/2022 4:14:59.12 =============== To repro directly: =====================================================
pushd C:\h\w\AFF309C7\w\A0660885\e\
"C:\h\w\AFF309C7\p\dotnet.exe" exec --runtimeconfig System.Diagnostics.Tracing.Tests.runtimeconfig.json --depsfile System.Diagnostics.Tracing.Tests.deps.json xunit.console.dll System.Diagnostics.Tracing.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
popd
===========================================================================================================
C:\h\w\AFF309C7\w\A0660885\e>"C:\h\w\AFF309C7\p\dotnet.exe" exec --runtimeconfig System.Diagnostics.Tracing.Tests.runtimeconfig.json --depsfile System.Diagnostics.Tracing.Tests.deps.json xunit.console.dll System.Diagnostics.Tracing.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
Discovering: System.Diagnostics.Tracing.Tests (method display = ClassAndMethod, method display options = None)
Discovered: System.Diagnostics.Tracing.Tests (found 45 of 49 test cases)
Starting: System.Diagnostics.Tracing.Tests (parallel test collections = on, max threads = 4)
BasicEventSourceTests.TestsManifestGeneration.Test_EventSource_EtwManifestGenerationRollover [FAIL]
Half-way through waiting for remote process.
Memory load: 14
Image Name PID Services
========================= ======== ============================================
svchost.exe 752 BrokerInfrastructure, DcomLaunch, LSM,
PlugPlay, Power, SystemEventsBroker
svchost.exe 812 RpcEptMapper, RpcSs
svchost.exe 1000 TermService
svchost.exe 1008 Appinfo, CertPropSvc, DsmSvc, gpsvc,
iphlpsvc, lfsvc, ProfSvc, sacsvr, Schedule,
SENS, SessionEnv, ShellHWDetection, Themes,
UserManager, UsoSvc, Winmgmt, wisvc,
wlidsvc, WpnService, wuauserv
svchost.exe 724 NcbService, PcaSvc, TrkWks, UALSVC,
UmRdpService, vmickvpexchange,
vmicshutdown, WdiSystemHost
svchost.exe 436 BFE, CoreMessagingRegistrar, DPS, MpsSvc,
pla
svchost.exe 720 Dhcp, EventLog, lmhosts, NgcCtnrSvc,
TimeBrokerSvc, vmictimesync
svchost.exe 1144 vmicheartbeat
svchost.exe 1188 CDPSvc, EventSystem, FontCache, netprofm,
nsi, RemoteRegistry, W32Time,
WinHttpAutoProxySvc
svchost.exe 1408 CryptSvc, Dnscache, LanmanWorkstation,
NlaSvc, WinRM
svchost.exe 1416 Wcmsvc
svchost.exe 1960 AppHostSvc
svchost.exe 2004 W3SVC, WAS
svchost.exe 1452 DiagTrack
svchost.exe 1780 StateRepository, tiledatamodelsvc
svchost.exe 2104 LanmanServer
svchost.exe 3128 CDPUserSvc_47e83, OneSyncSvc_47e83
svchost.exe 3912 AppReadiness
svchost.exe 3972 ClipSVC
Timed out at 11/11/2022 4:17:43 AM after 60000ms waiting for remote process.
Wrote mini dump to: C:\h\w\AFF309C7\w\A0660885\uploads\4080.acrt3kbv.nh5.dmp
Process ID: 4080
Handle: 1312
Name: dotnet
MainModule: C:\h\w\AFF309C7\p\dotnet.exe
StartTime: 11/11/2022 4:16:43 AM
TotalProcessorTime: 00:00:07.2187500
Threads:
Thread #1 (OS 0x718) [MTA]
[HelperMethodFrame] (System.Threading.Thread.SleepInternal)
System.Threading.Thread.Sleep(Int32)
BasicEventSourceTests.TestsManifestGeneration.<Test_EventSource_EtwManifestGenerationRollover>b__6_0()
[HelperMethodFrame_PROTECTOBJ] (System.RuntimeMethodHandle.InvokeMethod)
System.Reflection.MethodInvoker.InterpretedInvoke(System.Object, IntPtr*)
System.Reflection.MethodInvoker.Invoke(System.Object, IntPtr*, System.Reflection.BindingFlags)
System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)
System.Reflection.MethodBase.Invoke(System.Object, System.Object[])
Microsoft.DotNet.RemoteExecutor.Program.Main(System.String[])
Thread #2 (OS 0xE94) [Finalizer] [Background]
[DebuggerU2MCatchHandlerFrame]
Stack Trace:
/_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs(224,0): at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose(Boolean disposing)
/_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs(57,0): at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose()
/_/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestsManifestGeneration.Etw.cs(83,0): at BasicEventSourceTests.TestsManifestGeneration.Test_EventSource_EtwManifestGenerationRollover()
at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
/_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs(81,0): at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
Finished: System.Diagnostics.Tracing.Tests
=== TEST EXECUTION SUMMARY ===
System.Diagnostics.Tracing.Tests Total: 46, Errors: 0, Failed: 1, Skipped: 0, Time: 176.253s
----- end Fri 11/11/2022 4:18:12.11 ----- exit code 1 ----------------------------------------------------------
Hit again in a main
unrelated PR: https://github.com/dotnet/runtime/pull/79134
Libraries Test Run release coreclr windows x64 Debug
===========================================================================================================
C:\h\w\AF14098C\w\A0D108B1\e>"C:\h\w\AF14098C\p\dotnet.exe" exec --runtimeconfig System.Diagnostics.Tracing.Tests.runtimeconfig.json --depsfile System.Diagnostics.Tracing.Tests.deps.json xunit.console.dll System.Diagnostics.Tracing.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
Discovering: System.Diagnostics.Tracing.Tests (method display = ClassAndMethod, method display options = None)
Discovered: System.Diagnostics.Tracing.Tests (found 45 of 49 test cases)
Starting: System.Diagnostics.Tracing.Tests (parallel test collections = on, max threads = 2)
Unhandled exception. System.NullReferenceException: Object reference not set to an instance of an object.
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.get_ProviderNameToGuid()
at Microsoft.Diagnostics.Tracing.Session.TraceEventProviders.GetProviderGuidByName(String name)
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.EnableProvider(String providerName, TraceEventLevel providerLevel, UInt64 matchAnyKeywords, TraceEventProviderOptions options)
at BasicEventSourceTests.TestsManifestGeneration.<Test_EventSource_EtwManifestGenerationRollover>b__3_0() in /_/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestsManifestGeneration.Etw.cs:line 98
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
--- End of stack trace from previous location ---
at Microsoft.DotNet.RemoteExecutor.Program.Main(String[] args) in /_/src/Microsoft.DotNet.RemoteExecutor/src/Program.cs:line 97
BasicEventSourceTests.TestsManifestGeneration.Test_EventSource_EtwManifestGenerationRollover [FAIL]
Microsoft.DotNet.RemoteExecutor.RemoteExecutionException : Remote process failed with an unhandled exception.
Stack Trace:
Child exception:
System.NullReferenceException: Object reference not set to an instance of an object.
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.get_ProviderNameToGuid()
at Microsoft.Diagnostics.Tracing.Session.TraceEventProviders.GetProviderGuidByName(String name)
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.EnableProvider(String providerName, TraceEventLevel providerLevel, UInt64 matchAnyKeywords, TraceEventProviderOptions options)
/_/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestsManifestGeneration.Etw.cs(98,0): at BasicEventSourceTests.TestsManifestGeneration.<Test_EventSource_EtwManifestGenerationRollover>b__3_0()
at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
/_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs(59,0): at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
Child process:
System.Diagnostics.Tracing.Tests, Version=8.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51 BasicEventSourceTests.TestsManifestGeneration Void <Test_EventSource_EtwManifestGenerationRollover>b__3_0()
Finished: System.Diagnostics.Tracing.Tests
=== TEST EXECUTION SUMMARY ===
System.Diagnostics.Tracing.Tests Total: 46, Errors: 0, Failed: 1, Skipped: 0, Time: 50.237s
The example from yesterday shows a case that is actually executing logic, but where the disk flushing of ETW is taking > 60 seconds. This test hasn't timed out recently according to Kusto except for in a particular PR. The nullrefs are more interesting, but haven't happened in a while.
Another failure:
BasicEventSourceTests.TestsManifestGeneration.Test_EventSource_EtwManifestGenerationRollover net8.0-windows-Release-arm64-CoreCLR_checked-jitstress1_tiered-Windows.11.Arm64.Open
C:\h\w\A2660923\w\99F008C2\e>set DOTNET_TieredCompilation=1
C:\h\w\A2660923\w\99F008C2\e>set DOTNET_JitStress=1
C:\h\w\A2660923\w\99F008C2\e>set COMPlus
Environment variable COMPlus not defined
C:\h\w\A2660923\w\99F008C2\e>call RunTests.cmd --runtime-path C:\h\w\A2660923\p
----- start Sat 02/18/2023 8:31:51.37 =============== To repro directly: =====================================================
pushd C:\h\w\A2660923\w\99F008C2\e\
"C:\h\w\A2660923\p\dotnet.exe" exec --runtimeconfig System.Diagnostics.Tracing.Tests.runtimeconfig.json --depsfile System.Diagnostics.Tracing.Tests.deps.json xunit.console.dll System.Diagnostics.Tracing.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
popd
===========================================================================================================
C:\h\w\A2660923\w\99F008C2\e>"C:\h\w\A2660923\p\dotnet.exe" exec --runtimeconfig System.Diagnostics.Tracing.Tests.runtimeconfig.json --depsfile System.Diagnostics.Tracing.Tests.deps.json xunit.console.dll System.Diagnostics.Tracing.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
Discovering: System.Diagnostics.Tracing.Tests (method display = ClassAndMethod, method display options = None)
Discovered: System.Diagnostics.Tracing.Tests (found 45 of 49 test cases)
Starting: System.Diagnostics.Tracing.Tests (parallel test collections = on, max threads = 2)
Unhandled exception. System.NullReferenceException: Object reference not set to an instance of an object.
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.get_ProviderNameToGuid()
at Microsoft.Diagnostics.Tracing.Session.TraceEventProviders.GetProviderGuidByName(String name)
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.EnableProvider(String providerName, TraceEventLevel providerLevel, UInt64 matchAnyKeywords, TraceEventProviderOptions options)
at BasicEventSourceTests.TestsManifestGeneration.<Test_EventSource_EtwManifestGenerationRollover>b__3_0() in /_/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestsManifestGeneration.Etw.cs:line 98
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
--- End of stack trace from previous location ---
at Microsoft.DotNet.RemoteExecutor.Program.Main(String[] args) in /_/src/Microsoft.DotNet.RemoteExecutor/src/Program.cs:line 97
BasicEventSourceTests.TestsManifestGeneration.Test_EventSource_EtwManifestGenerationRollover [FAIL]
Microsoft.DotNet.RemoteExecutor.RemoteExecutionException : Remote process failed with an unhandled exception.
Stack Trace:
Child exception:
System.NullReferenceException: Object reference not set to an instance of an object.
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.get_ProviderNameToGuid()
at Microsoft.Diagnostics.Tracing.Session.TraceEventProviders.GetProviderGuidByName(String name)
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.EnableProvider(String providerName, TraceEventLevel providerLevel, UInt64 matchAnyKeywords, TraceEventProviderOptions options)
/_/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestsManifestGeneration.Etw.cs(98,0): at BasicEventSourceTests.TestsManifestGeneration.<Test_EventSource_EtwManifestGenerationRollover>b__3_0()
at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
/_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs(59,0): at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
Child process:
System.Diagnostics.Tracing.Tests, Version=8.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51 BasicEventSourceTests.TestsManifestGeneration Void <Test_EventSource_EtwManifestGenerationRollover>b__3_0()
Finished: System.Diagnostics.Tracing.Tests
=== TEST EXECUTION SUMMARY ===
System.Diagnostics.Tracing.Tests Total: 46, Errors: 0, Failed: 1, Skipped: 0, Time: 58.404s
I'm unsure the Known Build Error text is working properly.
Feb 24th 2023.
Libraries Test Run release coreclr windows x64 Debug
===========================================================================================================
C:\h\w\973D086A\w\AD7309AE\e>"C:\h\w\973D086A\p\dotnet.exe" exec --runtimeconfig System.Diagnostics.Tracing.Tests.runtimeconfig.json --depsfile System.Diagnostics.Tracing.Tests.deps.json xunit.console.dll System.Diagnostics.Tracing.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
Discovering: System.Diagnostics.Tracing.Tests (method display = ClassAndMethod, method display options = None)
Discovered: System.Diagnostics.Tracing.Tests (found 45 of 49 test cases)
Starting: System.Diagnostics.Tracing.Tests (parallel test collections = on, max threads = 2)
Unhandled exception. System.NullReferenceException: Object reference not set to an instance of an object.
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.get_ProviderNameToGuid()
at Microsoft.Diagnostics.Tracing.Session.TraceEventProviders.GetProviderGuidByName(String name)
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.EnableProvider(String providerName, TraceEventLevel providerLevel, UInt64 matchAnyKeywords, TraceEventProviderOptions options)
at BasicEventSourceTests.TestsManifestGeneration.<Test_EventSource_EtwManifestGenerationRollover>b__6_0() in /_/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestsManifestGeneration.Etw.cs:line 100
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 64
--- End of stack trace from previous location ---
at Microsoft.DotNet.RemoteExecutor.Program.Main(String[] args) in /_/src/Microsoft.DotNet.RemoteExecutor/src/Program.cs:line 97
BasicEventSourceTests.TestsManifestGeneration.Test_EventSource_EtwManifestGenerationRollover [FAIL]
Microsoft.DotNet.RemoteExecutor.RemoteExecutionException : Remote process failed with an unhandled exception.
Stack Trace:
Child exception:
System.NullReferenceException: Object reference not set to an instance of an object.
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.get_ProviderNameToGuid()
at Microsoft.Diagnostics.Tracing.Session.TraceEventProviders.GetProviderGuidByName(String name)
at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.EnableProvider(String providerName, TraceEventLevel providerLevel, UInt64 matchAnyKeywords, TraceEventProviderOptions options)
/_/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestsManifestGeneration.Etw.cs(100,0): at BasicEventSourceTests.TestsManifestGeneration.<Test_EventSource_EtwManifestGenerationRollover>b__6_0()
at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
/_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs(64,0): at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
Child process:
System.Diagnostics.Tracing.Tests, Version=7.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51 BasicEventSourceTests.TestsManifestGeneration Void <Test_EventSource_EtwManifestGenerationRollover>b__6_0()
Finished: System.Diagnostics.Tracing.Tests
=== TEST EXECUTION SUMMARY ===
System.Diagnostics.Tracing.Tests Total: 46, Errors: 0, Failed: 1, Skipped: 0, Time: 55.016s
----- end Thu 02/23/2023 22:29:48.76 ----- exit code 1 ----------------------------------------------------------
@tommcdon
I loosened the condition slightly here by removing Rollover from the string since both versions seem to be related and have been reported here previously
Hit in #93186 in non-optional Libraries Test Run checked coreclr windows x86 Debug
leg.
Hit count seems high so pulling this issue back from future to 9.0 - @davmason would you mind taking a look?
Another failure happened today in my PR: https://dev.azure.com/dnceng-public/public/_build/results?buildId=446198&view=ms.vss-test-web.build-test-results-tab&runId=9981784&resultId=141177&paneView=debug
It prints many times the following message
Did not see ManifestData event from SimpleEventSource, test will fail. Additional info:
file name file.etl
total event count 0
total providers 0
Possibly related to resolved issues dotnet/runtime#91769, dotnet/runtime#91304, dotnet/runtime#88027?
Failed in: runtime-coreclr libraries-jitstress 20231110.2
Failed tests:
net9.0-windows-Release-x86-CoreCLR_checked-zapdisable-Windows.10.Amd64.Open
- BasicEventSourceTests.TestsManifestGeneration.Test_EventSource_EtwManifestGenerationRollover
Error message:
Microsoft.DotNet.RemoteExecutor.RemoteExecutionException : Half-way through waiting for remote process.
Memory load: 14
Image Name PID Services
========================= ======== ============================================
svchost.exe 748 BrokerInfrastructure, DcomLaunch, LSM,
PlugPlay, Power, SystemEventsBroker
svchost.exe 812 RpcEptMapper, RpcSs
svchost.exe 964 Appinfo, CertPropSvc, gpsvc, iphlpsvc,
lfsvc, ProfSvc, sacsvr, Schedule, SENS,
SessionEnv, ShellHWDetection, Themes,
UserManager, Winmgmt, WpnService, wuauserv
svchost.exe 984 TermService
svchost.exe 448 NcbService, PcaSvc, TrkWks, UALSVC,
UmRdpService, vmickvpexchange,
vmicshutdown, WdiSystemHost
svchost.exe 536 Dhcp, EventLog, lmhosts, TimeBrokerSvc,
vmictimesync
svchost.exe 1040 BFE, CoreMessagingRegistrar, DPS, MpsSvc,
pla
svchost.exe 1116 CDPSvc, EventSystem, FontCache, netprofm,
nsi, W32Time, WinHttpAutoProxySvc
svchost.exe 1224 vmicheartbeat
svchost.exe 1372 CryptSvc, Dnscache, LanmanWorkstation,
NlaSvc, WinRM
svchost.exe 1384 Wcmsvc
svchost.exe 1976 DiagTrack
svchost.exe 1992 AppHostSvc
svchost.exe 2008 LanmanServer
svchost.exe 1472 W3SVC, WAS
svchost.exe 1624 StateRepository, tiledatamodelsvc
svchost.exe 3696 CDPUserSvc_55745, OneSyncSvc_55745
svchost.exe 5056 SSDPSRV
Timed out at 11/11/2023 8:11:15 AM after 60000ms waiting for remote process.
Wrote mini dump to: C:\h\w\B74B09C9\w\AD800A3C\uploads\3220.2fo4oaet.lwp.dmp
Process ID: 3220
Handle: 1116
Name: dotnet
MainModule: C:\h\w\B74B09C9\p\dotnet.exe
StartTime: 11/11/2023 8:10:15 AM
TotalProcessorTime: 00:00:07.5468750
Threads:
Thread #1 (OS 0x3B4) [MTA]
[HelperMethodFrame] (System.Threading.Thread.SleepInternal)
System.Threading.Thread.Sleep(Int32)
BasicEventSourceTests.TestsManifestGeneration.<Test_EventSource_EtwManifestGenerationRollover>b__3_0()
[HelperMethodFrame_PROTECTOBJ] (System.RuntimeMethodHandle.InvokeMethod)
System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(System.Object, IntPtr*)
System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(System.Object, System.Reflection.BindingFlags)
System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)
Microsoft.DotNet.RemoteExecutor.Program.Main(System.String[])
[InlinedCallFrame]
Thread #2 (OS 0x964) [Finalizer] [Background]
[DebuggerU2MCatchHandlerFrame]
Stack trace:
at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose(Boolean disposing) in /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs:line 225
at BasicEventSourceTests.TestsManifestGeneration.Test_EventSource_EtwManifestGenerationRollover() in /_/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestsManifestGeneration.Etw.cs:line 81
at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
at System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(Object obj, IntPtr* args) in /_/src/coreclr/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.CoreCLR.cs:line 36
at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.cs:line 57
Hit count seems high so pulling this issue back from future to 9.0 - @davmason would you mind taking a look?
@davmason, what is the status of this test failure?
Hit this today.
Libraries Test Run checked coreclr windows x86 Debug
Output:
...
Did not see ManifestData event from SimpleEventSource, test will fail. Additional info:
file name file.etl
total event count 0
total providers 0
Unhandled exception. Xunit.Sdk.TrueException: Assert.True() Failure
Expected: True
Actual: False
at Xunit.Assert.True(Boolean condition) in /_/src/Microsoft.DotNet.XUnitAssert/src/BooleanAsserts.cs:line 97
at BasicEventSourceTests.TestsManifestGeneration.<Test_EventSource_EtwManifestGeneration>b__2_0() in /_/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestsManifestGeneration.Etw.cs:line 73
at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
at System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(Object obj, IntPtr* args) in /_/src/coreclr/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.CoreCLR.cs:line 36
at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.cs:line 57
--- End of stack trace from previous location ---
at Microsoft.DotNet.RemoteExecutor.Program.Main(String[] args) in /_/src/Microsoft.DotNet.RemoteExecutor/src/Program.cs:line 97
BasicEventSourceTests.TestsManifestGeneration.Test_EventSource_EtwManifestGeneration [FAIL]
Microsoft.DotNet.RemoteExecutor.RemoteExecutionException : Remote process failed with an unhandled exception.
Stack Trace:
Child exception:
Xunit.Sdk.TrueException: Assert.True() Failure
Expected: True
Actual: False
/_/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestsManifestGeneration.Etw.cs(73,0): at BasicEventSourceTests.TestsManifestGeneration.<Test_EventSource_EtwManifestGeneration>b__2_0()
at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
/_/src/coreclr/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.CoreCLR.cs(36,0): at System.Reflection.MethodBaseInvoker.InterpretedInvoke_Method(Object obj, IntPtr* args)
/_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodBaseInvoker.cs(57,0): at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr)
Child process:
System.Diagnostics.Tracing.Tests, Version=9.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51 BasicEventSourceTests.TestsManifestGeneration Void <Test_EventSource_EtwManifestGeneration>b__2_0()
Finished: System.Diagnostics.Tracing.Tests
=== TEST EXECUTION SUMMARY ===
System.Diagnostics.Tracing.Tests Total: 46, Errors: 0, Failed: 1, Skipped: 0, Time: 181.599s
----- end Tue 11/28/2023 22:50:29.64 ----- exit code 1 ----------------------------------------------------------
The tests are likely failing because the hardcoded sleeps are not long enough for jitstress, gcstress, or runs on single core machines. Opened #95498 to disable to get off the blocking CI list
@davmason Are those tests tracked by this issue? I think #95389 disabled the two tests being tracked here.
@jakobbotsch There are some older failures on x64, and the timing issue should affect all architectures.
There are tests disabled against this issue: https://github.com/dotnet/runtime/blob/0451127421fe7862f0e8407eafd6052d7ea3b175/src/libraries/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestsManifestGeneration.Etw.cs#L33
The tests should be either re-enabled or deleted.
The test is still failing on win-x86. Example: https://dev.azure.com/dnceng-public/public/_build/results?buildId=524959&view=results I disabled the tests on win-x86 in #95389, but it seems like we ended up losing that. The issue does not seem to be stress related.
Ah, looks like there already is a new open issue #96904 about it, but the known error in it didn't match the case above. I'll adjust that a bit instead.
https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-48790-merge-edcfc19254cd4fb0b6/System.Diagnostics.Tracing.Tests/console.66fb11a3.log?sv=2019-07-07&se=2021-03-18T01%3A00%3A06Z&sr=c&sp=rl&sig=z8YRPOAcP9iOzDQfqW8tDy%2FsDDp%2BP2rxIxvaQmGWTrw%3D
Callstack
``` C:\h\w\BD2109D5\w\9DBE08F2\e>"C:\h\w\BD2109D5\p\dotnet.exe" exec --runtimeconfig System.Diagnostics.Tracing.Tests.runtimeconfig.json --depsfile System.Diagnostics.Tracing.Tests.deps.json xunit.console.dll System.Diagnostics.Tracing.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing Discovering: System.Diagnostics.Tracing.Tests (method display = ClassAndMethod, method display options = None) Discovered: System.Diagnostics.Tracing.Tests (found 39 of 43 test cases) Starting: System.Diagnostics.Tracing.Tests (parallel test collections = on, max threads = 2) BasicEventSourceTests.TestsManifestGeneration.Test_EventSource_EtwManifestGenerationRollover [FAIL] Half-way through waiting for remote process. Memory load: 24 Nombre de imagen PID Servicios ========================= ======== ============================================= svchost.exe 824 PlugPlay svchost.exe 908 BrokerInfrastructure, DcomLaunch, Power, SystemEventsBroker svchost.exe 948 RpcEptMapper, RpcSs svchost.exe 996 LSM svchost.exe 820 CryptSvc svchost.exe 432 AppIDSvc svchost.exe 1080 CoreMessagingRegistrar svchost.exe 1096 TermService svchost.exe 1108 lmhosts svchost.exe 1120 NcbService svchost.exe 1268 vmicheartbeat svchost.exe 1276 vmickvpexchange svchost.exe 1284 vmicshutdown svchost.exe 1340 vmictimesync svchost.exe 1396 DispBrokerDesktopSvc svchost.exe 1480 FontCache svchost.exe 1568 EventLog svchost.exe 1620 nsi svchost.exe 1668 gpsvc svchost.exe 1676 Dhcp svchost.exe 1684 ProfSvc svchost.exe 1720 EventSystem svchost.exe 1728 Themes svchost.exe 1836 SENS svchost.exe 1860 UmRdpService svchost.exe 1892 Schedule svchost.exe 1912 Dnscache svchost.exe 1920 Wcmsvc svchost.exe 1964 NlaSvc svchost.exe 1032 ShellHWDetection svchost.exe 2168 BFE, mpssvc svchost.exe 2180 WinHttpAutoProxySvc svchost.exe 2204 CertPropSvc svchost.exe 2244 netprofm svchost.exe 2292 LanmanWorkstation svchost.exe 2320 TimeBrokerSvc svchost.exe 2452 SessionEnv svchost.exe 2576 UserManager svchost.exe 2696 DiagTrack svchost.exe 2704 Winmgmt svchost.exe 2744 SysMain svchost.exe 2776 TrkWks svchost.exe 2784 W32Time svchost.exe 2896 WinRM svchost.exe 2944 iphlpsvc svchost.exe 2952 WpnService svchost.exe 3012 LanmanServer svchost.exe 3112 UsoSvc svchost.exe 4864 CDPUserSvc_5d640 svchost.exe 4892 WpnUserService_5d640 svchost.exe 5012 TokenBroker svchost.exe 3724 StateRepository svchost.exe 4332 TabletInputService svchost.exe 4592 CDPSvc svchost.exe 3860 pla svchost.exe 4016 Appinfo svchost.exe 7156 PcaSvc svchost.exe 2732 DPS svchost.exe 2884 WdiSystemHost svchost.exe 3504 UALSVC svchost.exe 6236 PrintWorkflowUserSvc_5d640 svchost.exe 6332 StorSvc svchost.exe 716 wuauserv svchost.exe 1580 AppXSvc svchost.exe 3248 ClipSVC svchost.exe 2468 camsvc svchost.exe 1788 NgcCtnrSvc svchost.exe 4328 NetSetupSvc Timed out at 26/02/2021 1:20:11 after 60000ms waiting for remote process. Wrote mini dump to: C:\h\w\BD2109D5\w\9DBE08F2\uploads\1156.adgssf0f.fgj.dmp Process ID: 1156 Handle: 1232 Name: dotnet MainModule: C:\h\w\BD2109D5\p\dotnet.exe StartTime: 26/02/2021 1:19:11 TotalProcessorTime: 00:00:00.5468750 Threads: Thread #1 (OS 0x544) [MTA] [HelperMethodFrame] (System.Threading.Thread.SleepInternal) BasicEventSourceTests.TestsManifestGeneration.Report
Summary
Known issue validation
Build: :mag_right: https://dev.azure.com/dnceng-public/public/_build/results?buildId=524959 Error message validated:
BasicEventSourceTests.TestsManifestGeneration.Test_EventSource_EtwManifestGeneration
Result validation: :white_check_mark: Known issue matched with the provided build. Validation performed at: 1/15/2024 9:11:22 AM UTC