Test failure: System.Net.Security.Tests.LoggingTest / EventSource_EventsRaisedAsExpected (60s timeout)

[CIPop]

History of failures (since 2017/5)

Day	Build	OS
8/21	20170821.03	OSX10.12

Original history

https://ci.dot.net/job/dotnet_corefx/job/master/job/outerloop_netcoreapp_osx_debug_prtest/39/consoleFull

Example:
System.Net.Security.Tests.LoggingTest.EventSource_EventsRaisedAsExpected (from (empty))

Stacktrace

MESSAGE:
Timed out after 60000ms waiting for remote process 97944\nExpected: True\nActual: False
+++++++++++++++++++
STACK TRACE:
at System.Diagnostics.RemoteExecutorTestBase.RemoteInvokeHandle.Dispose() in /Users/dotnet-bot/j/workspace/dotnet_corefx/master/outerloop_netcoreapp_osx_debug_prtest/src/Common/tests/System/Diagnostics/RemoteExecutorTestBase.cs:line 214 at System.Net.Security.Tests.LoggingTest.EventSource_EventsRaisedAsExpected() in /Users/dotnet-bot/j/workspace/dotnet_corefx/master/outerloop_netcoreapp_osx_debug_prtest/src/System.Net.Security/tests/FunctionalTests/LoggingTest.cs:line 31

Console log:
log.txt

[CIPop]

Same failure as in:

#21206; #21822; #20319; #20323; #20392

@stephentoub I couldn't find anything interesting in the log (maybe I'm not searching for the right keyword?)
I've attached the full log in the description.

[stephentoub]

I couldn't find anything interesting in the log (maybe I'm not searching for the right keyword?)

This is a hang rather than a crash, so I wouldn't expect to find much of interest in the log (no different than if the test code in the parent process itself hung). The hang is just happening in the child process, and so the parent process is timing out waiting for it. Or at least that's generally what such a failure means.

[CIPop]

Makes sense. I have some ideas:

1. Do you think we could always convert EventSource logs to Console outputs in order to see what was happening when it hangs? (The slowdown might be problematic.)
2. We could try to crash the child process from within using a Debug.Fail and produce a full-memory dump to check the remote process state.
3. We could also attempt to crash the remote process from the parent (we should have the required privileges to call MinidumpWriteDump)

[stephentoub]

Do you think we could always convert EventSource logs to Console outputs in order to see what was happening when it hangs? (The slowdown might be problematic.)

We could certainly do it for a specific test; that's not a problem. Just add https://github.com/dotnet/corefx/blob/bffef76f6af208e2042a2f27bc081ee908bb390b/src/Common/tests/System/Diagnostics/Tracing/ConsoleEventListener.cs#L9 to the project and wrap the body of the test with code like:

using (new ConsoleEventListener())
{
    ... // test goes here
}

We could try to crash the child process from within using a Debug.Fail and produce a full-memory dump to check the remote process state.

A while back I implemented support in RemoteInvoke for using ClrMd to dump relevant data from the remote process, e.g. the call stacks, but I couldn't check it in as the ClrMd NuGet doesn't currently support .NET Core. @leculver may have an update on if/when that'll work.

[v-haren]

failed again: https://ci.dot.net/job/dotnet_corefx/job/master/job/outerloop_netcoreapp_win7_release/108/testReport/System.Net.Security.Tests/LoggingTest/EventSource_EventsRaisedAsExpected/

[KristinXie1]

failed again in CI: https://ci.dot.net/job/dotnet_corefx/job/master/job/outerloop_netcoreapp_win7_release/168/testReport/System.Net.Http.Functional.Tests/ManagedHandler_DiagnosticsTest/SendAsync_ExpectedDiagnosticCancelledLogging/

[adityamandaleeka]

Another instance:

14:57:17      System.Net.Security.Tests.LoggingTest.EventSource_EventsRaisedAsExpected [FAIL]
14:57:17         Timed out after 60000ms waiting for remote process 12429
14:57:17         Expected: True
14:57:17         Actual:   False

CI link:
https://ci3.dot.net/job/dotnet_corefx/job/release_uwp6.0/job/osx-TGroup_netcoreapp+CGroup_Debug+AGroup_x64+TestOuter_false_prtest/102/consoleFull

[karelz]

I haven't seen another hit after 2017/8 - in duplicates or official test runs in Helix (see updated top post).
Closing. Please reopen if it happens again.