Runtime: Crossgen2 failure: tracing/eventpipe/reverse/reverse/reverse.sh

[v-haren]

failed in job: runtime-coreclr crossgen2 20200420.1

Error message
~~~
rm: /private/tmp/helix/working/B20C0A0D/w/BBD209FA/e/tracing/eventpipe/reverse/reverse/reverse.dll.rsp: No such file or directory

Return code: 1
Raw output file: /private/tmp/helix/working/B20C0A0D/w/BBD209FA/e/tracing/eventpipe/Reports/tracing.eventpipe/reverse/reverse/reverse.output.txt
Raw output:
BEGIN EXECUTION
in takeLock
Response file: /private/tmp/helix/working/B20C0A0D/w/BBD209FA/e/tracing/eventpipe/reverse/reverse/reverse.dll.rsp
--inputbubble
/private/tmp/helix/working/B20C0A0D/w/BBD209FA/e/tracing/eventpipe/reverse/reverse/IL/reverse.dll
-r:/private/tmp/helix/working/B20C0A0D/w/BBD209FA/e/tracing/eventpipe/reverse/reverse/IL/.dll
-o:/private/tmp/helix/working/B20C0A0D/w/BBD209FA/e/tracing/eventpipe/reverse/reverse/reverse.dll
-r:/tmp/helix/working/B20C0A0D/p/System..dll
-r:/tmp/helix/working/B20C0A0D/p/Microsoft.*.dll
-r:/tmp/helix/working/B20C0A0D/p/mscorlib.dll
--targetarch=x64
-O
Running CrossGen2: /tmp/helix/working/B20C0A0D/p/corerun /tmp/helix/working/B20C0A0D/p/crossgen2/crossgen2.dll @/private/tmp/helix/working/B20C0A0D/w/BBD209FA/e/tracing/eventpipe/reverse/reverse/reverse.dll.rsp
Warning: Method [reverse]Tracing.Tests.ReverseValidation.ReverseValidation+<>c__DisplayClass8_1+<b__1>d.MoveNext() was not compiled because: [TEMPORARY EXCEPTION MESSAGE] FileLoadErrorGeneric: netstandard
Warning: Method [reverse]Tracing.Tests.ReverseValidation.ReverseValidation+<>c__DisplayClass6_0.b__1() was not compiled because: [TEMPORARY EXCEPTION MESSAGE] FileLoadErrorGeneric: netstandard
Warning: Method [reverse]Tracing.Tests.ReverseValidation.ReverseValidation+<>c+<b__9_0>d.MoveNext() was not compiled because: [TEMPORARY EXCEPTION MESSAGE] FileLoadErrorGeneric: netstandard
Warning: Method [reverse]Tracing.Tests.ReverseValidation.ReverseValidation+<>c__DisplayClass5_2.b__3() was not compiled because: [TEMPORARY EXCEPTION MESSAGE] FileLoadErrorGeneric: netstandard
Warning: Method [reverse]Tracing.Tests.ReverseValidation.ReverseValidation+<>c+<b__7_0>d.MoveNext() was not compiled because: [TEMPORARY EXCEPTION MESSAGE] FileLoadErrorGeneric: netstandard
Warning: Method [reverse]Tracing.Tests.ReverseValidation.ReverseValidation+<>c+<b__6_0>d.MoveNext() was not compiled because: [TEMPORARY EXCEPTION MESSAGE] FileLoadErrorGeneric: netstandard
Warning: Method [reverse]Tracing.Tests.ReverseValidation.ReverseValidation+<>c__DisplayClass5_1+<b__2>d.MoveNext() was not compiled because: [TEMPORARY EXCEPTION MESSAGE] FileLoadErrorGeneric: netstandard
Warning: Method [reverse]Tracing.Tests.ReverseValidation.ReverseValidation+<>c__DisplayClass9_0.b__1() was not compiled because: [TEMPORARY EXCEPTION MESSAGE] FileLoadErrorGeneric: netstandard
Warning: Method [reverse]Tracing.Tests.ReverseValidation.ReverseValidation+<>c__DisplayClass8_2.b__3() was not compiled because: [TEMPORARY EXCEPTION MESSAGE] FileLoadErrorGeneric: netstandard
Warning: Method [reverse]Tracing.Tests.ReverseValidation.ReverseValidation+<>c__DisplayClass7_0.b__1() was not compiled because: [TEMPORARY EXCEPTION MESSAGE] FileLoadErrorGeneric: netstandard
Emitting R2R PE file: /private/tmp/helix/working/B20C0A0D/w/BBD209FA/e/tracing/eventpipe/reverse/reverse/reverse.dll
in ReleaseLock
/tmp/helix/working/B20C0A0D/p/corerun reverse.dll ''
0.0s: ::== Running test: TEST_RuntimeIsResilientToServerClosing
0.0s: Server name is '/var/folders/52/pswj9r6x25vf6kvtw66zgbhw0000gy/T/DOTNET_TRACE_TESTS_pc220qgn.qvj'
0.1s: running sub-process: /private/tmp/helix/working/B

Stack trace
at tracing_eventpipe._reverse_reverse_reverse_._reverse_reverse_reverse_sh() in /Users/runner/runners/2.166.3/work/1/s/artifacts/tests/coreclr/OSX.x64.Checked/TestWrappers/tracing.eventpipe/tracing.eventpipe.XUnitWrapper.cs:line 334
~~~

[v-haren]

failed again in job: runtime-coreclr outerloop 20200510.5

failed test: tracing/eventpipe/reverse/reverse/reverse.sh

Error message
~~~
Return code: 1
Raw output file: /private/tmp/helix/working/B018091C/w/B9410A0E/e/tracing/eventpipe/Reports/tracing.eventpipe/reverse/reverse/reverse.output.txt
Raw output:
BEGIN EXECUTION
/tmp/helix/working/B018091C/p/corerun reverse.dll ''
0.0s: ::== Running test: TEST_RuntimeIsResilientToServerClosing
0.1s: Server name is '/var/folders/19/2fnchf3x2vng_n9fx9ktyhk80000gy/T/DOTNET_TRACE_TESTS_grgoqgj1.5ab'
0.3s: running sub-process: /private/tmp/helix/working/B018091C/p/corerun /private/tmp/helix/working/B018091C/w/B9410A0E/e/tracing/eventpipe/reverse/reverse/reverse.dll 0
0.5s: subprocess started: True
0.5s: subprocess PID: 35537
1.4s: Waiting for connection
1.7s: Got a connection
1.9s: { Magic=System.Byte[]; ClrInstanceId=1b8c4e20-56dc-9db6-84e2-0f779dd9213d; ProcessId=35537; Unused=0; }
1.9s: Waiting for connection
1.9s: Got a connection
1.9s: { Magic=System.Byte[]; ClrInstanceId=1b8c4e20-56dc-9db6-84e2-0f779dd9213d; ProcessId=35537; Unused=0; }
1.9s: Waiting for connection
1.9s: Got a connection
1.9s: { Magic=System.Byte[]; ClrInstanceId=1b8c4e20-56dc-9db6-84e2-0f779dd9213d; ProcessId=35537; Unused=0; }
1.9s: Waiting for connection
2.0s: Got a connection
2.0s: { Magic=System.Byte[]; ClrInstanceId=1b8c4e20-56dc-9db6-84e2-0f779dd9213d; ProcessId=35537; Unused=0; }
2.0s: Test passed: True
2.0s:
2.0s: ::== Running test: TEST_RuntimeConnectsToExistingServer
2.0s: Waiting for connection
2.0s: Server name is /var/folders/19/2fnchf3x2vng_n9fx9ktyhk80000gy/T/DOTNET_TRACE_TESTS_qwtwvpmw.2mm
2.0s: running sub-process: /private/tmp/helix/working/B018091C/p/corerun /private/tmp/helix/working/B018091C/w/B9410A0E/e/tracing/eventpipe/reverse/reverse/reverse.dll 0
2.0s: subprocess started: True
2.0s: subprocess PID: 35545
2.1s: Got a connection
2.2s: { Magic=System.Byte[]; ClrInstanceId=ea33427d-0635-1cc6-8b82-2c8ca0a2cf6d; ProcessId=35545; Unused=0; }
2.2s: Test passed: True
2.2s:
2.2s: ::== Running test: TEST_CanConnectServerAndClientAtSameTime
2.2s: Server name is '/var/folders/19/2fnchf3x2vng_n9fx9ktyhk80000gy/T/DOTNET_TRACE_TESTS_a3aie4ue.4x5'
2.2s: running sub-process: /private/tmp/helix/working/B018091C/p/corerun /private/tmp/helix/working/B018091C/w/B9410A0E/e/tracing/eventpipe/reverse/reverse/reverse.dll 0
2.2s: subprocess started: True
2.2s: subprocess PID: 35546
2.3s: Waiting for reverse connection
2.3s: Got reverse connection
2.3s: { Magic=System.Byte[]; ClrInstanceId=daa64d90-baf0-18d1-b6f6-0606be76842c; ProcessId=35546; Unused=0; }
2.4s: Starting EventPipeSession over standard connection
2.5s: Started EventPipeSession over standard connection with session id: 0x7fa78fd477a0
3.0s: Stopping EventPipeSession over standard connection
3.3s: Stopped EventPipeSession over standard connection
3.3s: Test passed: True
3.3s:
3.3s: ::== Running test: TEST_ServerWorksIfClientDoesntAccept
3.3s: Server name is '/var/folders/19/2fnchf3x2vng_n9fx9ktyhk80000gy/T/DOTNET_TRACE_TESTS_kpjhecj5.ab2'
3.3s: running sub-process: /private/tmp/helix/working/B018091C/p/corerun /private/tmp/helix/working/B018091C/w/B9410A0E/e/tracing/eventpipe/reverse/reverse/reverse.dll 0
3.4s: subprocess started: True
3.4s: subprocess PID: 35547
3.4s: Starting EventPipeSession over standard connection
3.7s: System.Net.Internals.SocketExceptionFactory+ExtendedSocketException (61): Connection refused /var/folders/19/2fnchf3x2vng_n9fx9ktyhk80000gy/T/dotnet-diagnostic-35547-1589046231-socket
at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress) in //src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs:line 4442
at System.Net.Sockets.Socket.Connect(EndPoint remoteEP) in //src/libraries/System.Net.Sockets/src/System/Net/Sockets/Socket.cs:line 901
at Microsoft.Diagnostics.Tools.RuntimeClient.DiagnosticsIpc.IpcClient.GetTransport(Int32 processI

Stack trace
at tracing_eventpipe._reverse_reverse_reverse_._reverse_reverse_reverse_sh() in /Users/runner/runners/2.166.4/work/1/s/artifacts/tests/coreclr/OSX.x64.Checked/TestWrappers/tracing.eventpipe/tracing.eventpipe.XUnitWrapper.cs:line 722
~~~

[am11]

Happened again OSX build; console log.

[safern]

Happened again in: https://dev.azure.com/dnceng/public/_build/results?buildId=661003&view=logs&j=9eaa4d7e-225e-55b8-2a77-e1ac7e76d448&t=f70528f6-0b93-5c49-dfc7-de8b842ee9d6&l=53

https://helix.dot.net/api/2019-06-17/jobs/22a3504d-c12f-4136-a2ac-357c4e620e92/workitems/PayloadGroup0/console

[mangod9]

I am guessing the CI failures are not related to crossgen2, and possibly a different issue which should be assigned to the Tracing team.

[safern]

@mangod9 do you know who the tracing team would be so that we can loop them in?

[mangod9]

@tommcdon ^^

[tommcdon]

@josalem

[josalem]

Taking a look

[josalem]

Couldn't repro locally, but I created a PR to enhance this suite of tests. I'm hoping that if the tests fail again, we should be able to easily identify what went wrong. The Connection Refused exception sounds like the subprocess may have died prematurely causing this exception externally. The timeout, I'm not sure about.

[josalem]

Rereading the logs posted above, I think there are actually 3 different issues in this one issue. The initial comment at the top has error output from crossgen2 and looks as though crossgen failed to R2R the test binary. The other 2 errors appear to be a timeout and an exception that should have more information if they happen again under the PR I linked.

[mangod9]

Yeah correct, the original crossgen2 issue is unrelated and shouldnt be affecting CI. If this repros a new issue should be created so they could be tracked separately. Thx.

[safern]

Happened again: https://helix.dot.net/api/2019-06-17/jobs/24babe78-7797-4a21-b7d0-6157ef54bf62/workitems/PayloadGroup0/console

Any update on this?

[josalem]

@safern I took a look at the log and it looks like something timed out the wait for a reverse server connection. The timeout was 30 seconds I believe. I'm going to spin this into a different issue, as I think there are too many things being tracked in here. I'll post any findings in the new issue.

[mangod9]

Thanks for creating a new issue @josalem. I have moved the blocking-clean-ci over to it, since the original crossgen2 issue is probably different.

[nattress]

This test has run fine in Crossgen2 runs so I believe we fixed whatever CG2-specific issue we had some time ago.