tracing/eventpipe/eventsourceerror/eventsourceerror/eventsourceerror failure #80666

Activity

1. tannergooding

   added

   blocking-outerloopBlocking the 'runtime-coreclr outerloop' and 'runtime-libraries-coreclr outerloop' runsBlocking the 'runtime-coreclr outerloop' and 'runtime-libraries-coreclr outerloop' runs

   Known Build ErrorUse this to report build issues in the .NET Helix tabUse this to report build issues in the .NET Helix tab

   on Jan 15, 2023
3. ghost added

   untriagedNew issue has not been triaged by the area ownerNew issue has not been triaged by the area owner

   on Jan 15, 2023
4. jeffschwMSFT

   added

   area-System.Diagnostics.Tracing

   on Jan 16, 2023
6. tommcdon

   removed

   untriagedNew issue has not been triaged by the area ownerNew issue has not been triaged by the area owner

   on Jan 17, 2023
7. tommcdon

   added this to the 8.0.0 milestone on Jan 17, 2023
8. tommcdon

   assigned

   davmason

   on Jan 17, 2023
9. tommcdon commented on Jan 17, 2023

   

   tommcdon

   on Jan 17, 2023

   Member

   More actions

   Test output indicates that the test is crashing with a seg fault and createdump fails either because the process is gone or there is a signing/entitlement issue. @hoyosjs @mikem8361

       tracing/eventpipe/eventsourceerror/eventsourceerror/eventsourceerror.sh [FAIL]
         [createdump] Invalid process id: task_for_pid(15770) FAILED (os/kern) failure (5)
         [createdump] This failure may be because createdump or the application is not properly signed and entitled.
         [createdump] Failure took 0ms
         [createdump] waitpid() returned successfully (wstatus 0000ff00)
         /private/tmp/helix/working/A8400938/w/B79B09BE/e/tracing/eventpipe/eventsourceerror/eventsourceerror/eventsourceerror.sh: line 441: 15770 Segmentation fault: 11  (core dumped) $LAUNCHER $ExePath "${CLRTestExecutionArguments[@]}"
   
10. tommcdon

    added

    os-macosmacOS aka OSXmacOS aka OSX

    on Jan 17, 2023
11. hoyosjs commented on Jan 19, 2023

    

    hoyosjs

    on Jan 19, 2023

    Last edited by hoyosjs

    Member

    More actions

    It's an entitlement issue. The regex is looking for a string that can hit on any osx coreclr crash. Adjusting the string since the issue is also not OSX specific.
12. EgorBo commented on Jan 24, 2023

    

    EgorBo

    on Jan 24, 2023

    Last edited by EgorBo

    Member

    More actions

    Can we disable the test until it's fixed? UPD: #81094
13. jkotas

    added

    disabled-testThe test is disabled in source code against the issueThe test is disabled in source code against the issue

    on Jan 24, 2023
14. jakobbotsch

    removed

    blocking-outerloopBlocking the 'runtime-coreclr outerloop' and 'runtime-libraries-coreclr outerloop' runsBlocking the 'runtime-coreclr outerloop' and 'runtime-libraries-coreclr outerloop' runs

    on Jan 24, 2023
15. 25 remaining items

    Load more

16. JulieLeeMSFT commented on Jul 22, 2024

    

    JulieLeeMSFT

    on Jul 22, 2024

    Member

    More actions

    failed in outerloop: runtime-coreclr outerloop/20240721.3

    Failed configs:

    R2R-CG2 osx x64 Checked no_tiered_compilation @ OSX.1200.Amd64.Open
    coreclr osx x64 Checked no_tiered_compilation @ OSX.1200.Amd64.Open
    - tracing/eventpipe/eventsourceerror/eventsourceerror/eventsourceerror.cmd
    

    Log
17. mdh1418 commented on Jul 23, 2024

    

    mdh1418

    on Jul 23, 2024

    Member

    More actions

    Based solely on the console logs from the recent failures on OSX, it looks like the readerTask does complete, so it's just stopTask that is causing the crash,

    runtime/src/tests/tracing/eventpipe/common/IpcTraceTest.cs

    Line 301 in cb4d8a2

    _eventPipeSession.Stop();

    .

    @davmason , do you happen to recall any recent modifications to the DiagnosticsClient EventPipeSession that could be causing crashes for specifically the eventsourceerror test?
18. stephentoub

    removed

    blocking-clean-ciBlocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms'

    on Jul 23, 2024
19. jkotas commented on Jul 24, 2024

    

    jkotas

    on Jul 24, 2024

    Member

    More actions

    do you happen to recall any recent modifications to the DiagnosticsClient EventPipeSession that could be causing crashes for specifically the eventsourceerror test?

    This issue was opened 1.5 years ago. Based on the symptoms, it is an intermittent crash that can come and go due to unrelated changes in timing, etc.
20. jkotas commented on Jul 25, 2024

    

    jkotas

    on Jul 25, 2024

    Member

    More actions

    The crash happens at this line:

    runtime/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventProvider.cs

    Line 65 in 3ec6286

    EventPipeEventProvider _this = (EventPipeEventProvider)GCHandle.FromIntPtr((IntPtr)callbackContext).Target!;

    We are crashing because the GCHandle was freed already. We are freeing the GCHandle here:

    runtime/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventProvider.cs

    Line 97 in 3ec6286

    _gcHandle.Free();

    .

    I do not see anything in the implementation of EventPipeInternal.DeleteProvider to guarantee there are no callback in flight when it returns. In fact,

    runtime/src/native/eventpipe/ep.c

    Lines 1317 to 1322 in 3ec6286

    	if (enabled ()) {
    	// Save the provider until the end of the tracing session.
    	ep_provider_set_delete_deferred (provider, true);
    	} else {
    	config_delete_provider (ep_config_get (), provider);
    	}

    explicit defers deleting the provider until the end of the tracing session. I think we may need to defer deleting of the GCHandle in a similar way.

    @mdh1418 Does this make sense - could you please take it from here?
21. jkotas

    added

    bug

    on Jul 25, 2024
22. mdh1418 commented on Jul 26, 2024

    

    mdh1418

    on Jul 26, 2024

    Last edited by mdh1418

    Member

    More actions

    Thanks for pinpointing the crash @jkotas!

    After some offline discussions with @noahfalk , I'm seeing that ETW has the behavior of blocking during EventProvider.Dispose() until all already in-flight callbacks are finished, so if any callbacks happen to be initiated ⁠after the EventListenersLock in EventProvider.Dispose(), then this p/invoke will block here at ⁠Interop.Advapi32.EventUnregister until the ETW command releases the ETW lock as described in ⁠the comment.

    Would parity between ETW and EventPipe in that aspect be better than deferring deleting the GC handle, as in having EventPipeEventProviders Disposal blocked by in flight callbacks? Perhaps for EventPipe, we could invoke Unregister under the EventListenersLock since the original reason for not doing so was because of deadlocking with the ETW lock + EventListenersLock. (edit: since having managed locks do different behaviors for ETW/EventPipe would bring inconsistency).
23. jkotas commented on Jul 26, 2024

    

    jkotas

    on Jul 26, 2024

    Last edited by jkotas

    Member

    More actions

    I do not have an opinion. If you think that synchronous blocking would be better, it is fine with me.

    EventPipe, we could invoke Unregister under the EventListenersLock

    I think that the synchronous blocking would have to be in the unmanaged event pipe code. I do not see how you can use locks on the managed side to fix this.
24. noahfalk commented on Jul 26, 2024

    

    noahfalk

    on Jul 26, 2024

    Member

    More actions

    Yeah, I want to do it unmanaged code because I want to match behavior between EtwEventProvider.Unregister() and EventPipeProvider.Unregister(). Both of them invoke a p/invoke to do the unregister work and I am recommending we give those p/invokes identical blocking behavior.
25. dotnet-policy-service

    added

    in-prThere is an active PR which will close this issue when it is mergedThere is an active PR which will close this issue when it is merged

    on Aug 1, 2024
26. mdh1418

    removed

    in-prThere is an active PR which will close this issue when it is mergedThere is an active PR which will close this issue when it is merged

    on Aug 1, 2024
27. mdh1418 commented on Aug 1, 2024

    

    mdh1418

    on Aug 1, 2024

    Member

    More actions

    The attempt to introduce a new lock to coordinate in-flight callbacks with provider disposal broke concurrent callbacks. Still looking to block provider disposal with a weaker blocking behavior
28. dotnet-policy-service

    added

    in-prThere is an active PR which will close this issue when it is mergedThere is an active PR which will close this issue when it is merged

    on Aug 6, 2024
29. mdh1418 commented on Aug 6, 2024

    

    mdh1418

    on Aug 6, 2024

    Member

    More actions

    Signal wait/set blocking implementation: #106040
30. mdh1418

    closed this as completedin #106040on Aug 7, 2024