Test failure: tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh

[v-haren]

failed in job: runtime-coreclr crossgen2 20200504.3

Error message

rm: cannot remove '/home/helixbot/work/AD530957/w/A2D708FA/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.dll.rsp': No such file or directory

cmdLine:/home/helixbot/work/AD530957/w/A2D708FA/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh Timed Out

Return code: -100
Raw output file: /home/helixbot/work/AD530957/w/A2D708FA/e/tracing/eventpipe/Reports/tracing.eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.output.txt
Raw output:
BEGIN EXECUTION
in takeLock
Response file: /home/helixbot/work/AD530957/w/A2D708FA/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.dll.rsp
--inputbubble
/home/helixbot/work/AD530957/w/A2D708FA/e/tracing/eventpipe/rundownvalidation/rundownvalidation/IL/rundownvalidation.dll
-r:/home/helixbot/work/AD530957/w/A2D708FA/e/tracing/eventpipe/rundownvalidation/rundownvalidation/IL/.dll
-o:/home/helixbot/work/AD530957/w/A2D708FA/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.dll
-r:/home/helixbot/work/AD530957/p/System..dll
-r:/home/helixbot/work/AD530957/p/Microsoft.*.dll
-r:/home/helixbot/work/AD530957/p/mscorlib.dll
--targetarch=x64
-O
Running CrossGen2: /home/helixbot/work/AD530957/p/corerun /home/helixbot/work/AD530957/p/crossgen2/crossgen2.dll @/home/helixbot/work/AD530957/w/A2D708FA/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.dll.rsp 
Warning: Method [rundownvalidation]Tracing.Tests.RundownValidation.RundownValidation+<>c.<.cctor>b__5_1(EventPipeEventSource) was not compiled because: [TEMPORARY EXCEPTION MESSAGE] FileLoadErrorGeneric: netstandard


Emitting R2R PE file: /home/helixbot/work/AD530957/w/A2D708FA/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.dll
in ReleaseLock
/home/helixbot/work/AD530957/p/corerun rundownvalidation.dll ''
 0.0s: ==TEST STARTING==
 0.1s: Validating clean environment...
 0.2s: Environment was clean.
 0.2s: Started sending sentinel events...
 0.2s: Connecting to EventPipe...
 0.2s: Connected to EventPipe with sessionID '0x7f2ba8000fc0'
 0.2s: Creating EventPipeEventSource...

cmdLine:/home/helixbot/work/AD530957/w/A2D708FA/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh Timed Out
Test Harness Exitcode is : -100
To run the test:
> set CORE_ROOT=/home/helixbot/work/AD530957/p
> /home/helixbot/work/AD530957/w/A2D708FA/e/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh
Expected: True
Actual: False


Stack trace
   at tracing_eventpipe._rundownvalidation_rundownvalidation_rundownvalidation_._rundownvalidation_rundownvalidation_rundownvalidation_sh() in /__w/1/s/artifacts/tests/coreclr/Linux.x64.Checked/TestWrappers/tracing.eventpipe/tracing.eventpipe.XUnitWrapper.cs:line 431

[v-haren]

failed again in job: runtime-coreclr crossgen2 20200621.2

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

Error message

rm: cannot remove '/root/helix/work/workitem/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.dll.rsp': No such file or directory

cmdLine:/root/helix/work/workitem/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh Timed Out

Return code: -100
Raw output file: /root/helix/work/workitem/tracing/eventpipe/Reports/tracing.eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.output.txt
Raw output:
BEGIN EXECUTION
in takeLock
Response file: /root/helix/work/workitem/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.dll.rsp
--inputbubble
/root/helix/work/workitem/tracing/eventpipe/rundownvalidation/rundownvalidation/IL/rundownvalidation.dll
-r:/root/helix/work/workitem/tracing/eventpipe/rundownvalidation/rundownvalidation/IL/.dll
-o:/root/helix/work/workitem/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.dll
-r:/root/helix/work/correlation/System..dll
-r:/root/helix/work/correlation/Microsoft.*.dll
-r:/root/helix/work/correlation/mscorlib.dll
--targetarch:arm64
-O
Running CrossGen2: dotnet /root/helix/work/correlation/crossgen2/crossgen2.dll @/root/helix/work/workitem/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.dll.rsp 
Warning: Method [rundownvalidation]Tracing.Tests.RundownValidation.RundownValidation+<>c.<.cctor>b__5_1(EventPipeEventSource) was not compiled because: [TEMPORARY EXCEPTION MESSAGE] FileLoadErrorGeneric: netstandard
Emitting R2R PE file: /root/helix/work/workitem/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.dll
in ReleaseLock
/root/helix/work/correlation/corerun rundownvalidation.dll ''
 0.0s: ==TEST STARTING==
 0.2s: Validating clean environment...
 0.3s: Environment was clean.
 0.4s: Started sending sentinel events...
 0.4s: Connecting to EventPipe...
 0.8s: Connected to EventPipe with sessionID '0x7ef8008f60'
 0.8s: Creating EventPipeEventSource...

cmdLine:/root/helix/work/workitem/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh Timed Out
Test Harness Exitcode is : -100
To run the test:
> set CORE_ROOT=/root/helix/work/correlation
> /root/helix/work/workitem/tracing/eventpipe/rundownvalidation/rundownvalidation/rundownvalidation.sh
Expected: True
Actual: False


Stack trace
   at tracing_eventpipe._rundownvalidation_rundownvalidation_rundownvalidation_._rundownvalidation_rundownvalidation_rundownvalidation_sh() in /__w/1/s/artifacts/tests/coreclr/Linux.arm64.Checked/TestWrappers/tracing.eventpipe/tracing.eventpipe.XUnitWrapper.cs:line 625

[ghost]

Tagging subscribers to this area: @tommcdon
See info in area-owners.md if you want to be subscribed.

[davidwrighton]

I believe this is a manifestation of #1892

[tommcdon]

@josalem

[josalem]

@davidwrighton do you have more insight as to why you think it is #1892? I would be surprised if that were happening here. I think this might be unrelated/different. The hang appears to be happening during the construction of EventPipeEventSource after a session has already been started. The config lock for EventPipe shouldn't be held at this point in the process since EventPipe::Enable should have already returned. Notably, the constructor for EventPipeEventSource won't return until data starts following, so if the runtime is hung somewhere, we wouldn't progress past this point. Is there any reason we don't have a timeout dump with this test? I don't have an ARM64 Linux machine to test this with, but I will see if I can find something.

[davidwrighton]

Ah, I thought from the writeline that the stop was at event pipe creation. In any case, I can't repro it, and have no dumps to work from.

[davidwrighton]

Also, I was attempting to reproduce the failure on my X64 machine. The same faults have been seen on Arm64 and X64 test passes.

[josalem]

I found a Raspberry Pi2 that I'm going to try to run the test on and see if I can get it to repro. Based on the symptoms, it looks like the EventPipeEventSource constructor isn't progressing. I looked back through the history of this test in the crossgen2 runs and found mostly passing tests, with a couple crossgen failures back in June:

• https://dev.azure.com/dnceng/public/_build/results?buildId=697063&view=ms.vss-test-web.build-test-results-tab&runId=21608296&resultId=102104&paneView=attachments
• https://dev.azure.com/dnceng/public/_build/results?buildId=697063&view=ms.vss-test-web.build-test-results-tab&runId=21608288&resultId=100905&paneView=attachments
• https://dev.azure.com/dnceng/public/_build/results?buildId=697595&view=ms.vss-test-web.build-test-results-tab&runId=21620320&resultId=103172&paneView=attachments
• https://dev.azure.com/dnceng/public/_build/results?buildId=697595&view=ms.vss-test-web.build-test-results-tab&runId=21620320&resultId=101517&paneView=attachments

Could those failures have any relation to a hang in execution?

[davidwrighton]

Assertions can cause all sorts of hilarity. Let me know what you find.

[tommcdon]

We unable to repro and according to the test history in AzDO there have been no event pipe related failures in this test since June, so closing.