Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

InvokeCodeThatShouldFirEvents_EnsureEventsFired fails on OSX #52710

Closed
eerhardt opened this issue May 13, 2021 · 12 comments · Fixed by #53043
Closed

InvokeCodeThatShouldFirEvents_EnsureEventsFired fails on OSX #52710

eerhardt opened this issue May 13, 2021 · 12 comments · Fixed by #53043
Labels
area-System.Data blocking-clean-ci Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms' bug

Comments

@eerhardt
Copy link
Member

eerhardt commented May 13, 2021

The test has been failing on OSX - 46 times in the past 7 days.

https://runfo.azurewebsites.net/search/tests/?q=started%3A%7E7+definition%3Aruntime+name%3AInvokeCodeThatShouldFirEvents_EnsureEventsFired

Here's an example:

https://dev.azure.com/dnceng/public/_build/results?buildId=1135812&view=logs&j=e36ba317-696d-52ae-17e4-c1550b11ed0e&t=bc5b3adc-f53f-5379-06e0-c27e87afd8be&l=55

https://helix.dot.net/api/2019-06-17/jobs/17bd0db4-2315-4c91-9458-a441149c521d/workitems/System.Data.Common.Tests/console

  Starting:    System.Data.Common.Tests (parallel test collections = on, max threads = 4)
    System.Data.SqlTypes.Tests.SqlStringSortingTest.SqlStringValidComparisonTest(cultureName: "ja-JP", localeId: 1041) [SKIP]
      PlatformDetection.IsIcuGlobalization and cultureName == ja-JP
Process terminated. Assertion failed.
String may not contain null chars
   at System.Diagnostics.Tracing.EventSource.AssertValidString(EventData* data) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 1862
   at System.Diagnostics.Tracing.EventSource.WriteToAllListeners(EventWrittenEventArgs eventCallbackArgs, Int32 eventDataCount, EventData* data) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 2067
   at System.Diagnostics.Tracing.EventSource.WriteEventWithRelatedActivityIdCore(Int32 eventId, Guid* relatedActivityId, Int32 eventDataCount, EventData* data) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 1369
   at System.Diagnostics.Tracing.EventSource.WriteEventCore(Int32 eventId, Int32 eventDataCount, EventData* data) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 1268
   at System.Diagnostics.Tracing.EventSource.WriteEvent(Int32 eventId, Int64 arg1, String arg2) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 1069
   at System.Data.DataCommonEventSource.EnterScope(String message) in /_/src/libraries/System.Data.Common/src/System/Data/Common/DataCommonEventSource.cs:line 76
   at System.Data.DataCommonEventSource.EnterScope[T1,T2](String format, T1 arg1, T2 arg2) in /_/src/libraries/System.Data.Common/src/System/Data/Common/DataCommonEventSource.cs:line 85
   at System.Data.DataTableCollection.Add(DataTable table) in /_/src/libraries/System.Data.Common/src/System/Data/DataTableCollection.cs:line 149
   at System.Data.Tests.DataCommonEventSourceTest.<>c.<InvokeCodeThatShouldFirEvents_EnsureEventsFired>b__0_1() in /_/src/libraries/System.Data.Common/tests/System/Data/DataCommonEventSourceTest.cs:line 28
   at System.Diagnostics.Tracing.TestEventListener.RunWithCallback(Action`1 handler, Action body) in /_/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs:line 111
   at System.Data.Tests.DataCommonEventSourceTest.<>c.<InvokeCodeThatShouldFirEvents_EnsureEventsFired>b__0_0() in /_/src/libraries/System.Data.Common/tests/System/Data/DataCommonEventSourceTest.cs:line 21
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Span`1& arguments, Signature sig, Boolean constructor, Boolean wrapExceptions)
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) in /_/src/coreclr/System.Private.CoreLib/src/System/Reflection/RuntimeMethodInfo.cs:line 417
   at System.Reflection.MethodBase.Invoke(Object obj, Object[] parameters) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodBase.cs:line 53
   at Microsoft.DotNet.RemoteExecutor.Program.Main(String[] args) in /_/src/Microsoft.DotNet.RemoteExecutor/src/Program.cs:line 57
    System.Data.Tests.DataCommonEventSourceTest.InvokeCodeThatShouldFirEvents_EnsureEventsFired [FAIL]
      Half-way through waiting for remote process.
      Timed out at 5/12/2021 4:33:43 PM after 60000ms waiting for remote process.
      	Process ID: 3793
      	Handle: 1156
      	Name: dotnet
      	MainModule: /private/tmp/helix/working/A36408AA/p/dotnet
      	StartTime: 5/12/2021 4:32:42 PM
      	TotalProcessorTime: 00:00:07.1473421
      
      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.Data.Common/tests/System/Data/DataCommonEventSourceTest.cs(17,0): at System.Data.Tests.DataCommonEventSourceTest.InvokeCodeThatShouldFirEvents_EnsureEventsFired()
  Finished:    System.Data.Common.Tests
=== TEST EXECUTION SUMMARY ===
   System.Data.Common.Tests  Total: 11717, Errors: 0, Failed: 1, Skipped: 1, Time: 76.844s

Putting in the System.Diagnostics area since the exception is coming from EventSource code.

Runfo Tracking Issue: system.data.tests.datacommoneventsourcetest.invokecodethatshouldfirevents_ensureeventsfired

Build Definition Kind Run Name Console Core Dump Test Results Run Client
1147902 runtime PR 52998 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1147636 runtime PR 52978 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1147632 runtime PR 52103 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1147564 runtime PR 53012 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1147064 runtime PR 52849 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1147001 runtime PR 52940 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1146937 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1146777 runtime PR 52934 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1146578 runtime PR 52995 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1146556 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1146504 runtime PR 52985 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1145817 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1145743 runtime PR 52897 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1145723 runtime PR 52967 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1145180 runtime PR 50510 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1145104 runtime PR 50894 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1145104 runtime PR 50894 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1144821 runtime PR 52849 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1144643 runtime PR 52941 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1144494 runtime PR 52933 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1144254 runtime PR 43954 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1144254 runtime PR 43954 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1144189 runtime PR 52912 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1144033 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1144027 runtime PR 52927 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1143765 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1143673 runtime PR 52912 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1143604 runtime PR 52907 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1143515 runtime PR 52903 net6.0-windows-Debug-x64-CoreCLR_checked-Windows.10.Amd64.Open console.log core dump runclient.py
1143351 runtime PR 52760 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1143228 runtime PR 52887 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142976 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142945 runtime PR 52288 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142945 runtime PR 52288 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142790 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142693 runtime PR 43954 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142625 runtime PR 52827 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142607 runtime PR 38798 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142541 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142411 runtime PR 51111 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142318 runtime PR 52853 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142234 runtime PR 52288 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142193 runtime PR 43954 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142184 runtime PR 52850 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1142115 runtime PR 52832 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1141968 runtime PR 52822 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1141963 runtime PR 52844 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1141738 runtime PR 52777 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1141599 runtime PR 43954 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1141586 runtime PR 52835 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1141555 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1141482 runtime PR 52833 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1141228 runtime PR 52661 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1140976 runtime PR 43954 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1140953 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1140781 runtime PR 52812 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1140510 runtime PR 52678 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1140480 runtime PR 52720 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1140434 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1140409 runtime PR 52497 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1140337 runtime PR 52800 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1140321 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1140309 runtime PR 52799 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1140296 runtime PR 52798 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1140270 runtime PR 52689 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1139870 runtime PR 52789 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1139785 runtime PR 52786 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1139751 runtime PR 52587 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1139691 runtime PR 52173 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1139599 runtime PR 52776 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1139521 runtime PR 52771 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1139521 runtime PR 52771 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1139521 runtime PR 52771 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1139521 runtime PR 52771 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1139159 runtime PR 52497 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1139140 runtime PR 52678 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1138664 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1138581 runtime PR 52689 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1138274 runtime PR 52406 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1138119 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1138039 runtime PR 51416 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1137703 runtime PR 52668 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1137404 runtime PR 52714 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1137398 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1137306 runtime PR 52709 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1137261 runtime PR 52707 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1137140 runtime PR 52704 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1137085 runtime PR 52648 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1136691 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1136602 runtime PR 52691 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1136549 runtime PR 52690 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1136469 runtime PR 51998 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1136336 runtime PR 52687 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1136313 runtime Rolling net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1136155 runtime PR 52685 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1136090 runtime PR 52515 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1135812 runtime PR 52557 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1135584 runtime PR 52602 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1135407 runtime PR 52661 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py
1134761 runtime PR 52599 net6.0-OSX-Debug-x64-CoreCLR_checked-OSX.1013.Amd64.Open console.log core dump runclient.py

Displaying 100 of 133 results

Build Result Summary

Day Hit Count Week Hit Count Month Hit Count
11 75 125
@eerhardt eerhardt added area-System.Diagnostics blocking-clean-ci Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms' labels May 13, 2021
@ghost
Copy link

ghost commented May 13, 2021

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

Issue Details

The test has been failing on OSX - 46 times in the past 7 days.

https://runfo.azurewebsites.net/search/tests/?q=started%3A%7E7+definition%3Aruntime+name%3AInvokeCodeThatShouldFirEvents_EnsureEventsFired

Here's an example:

https://dev.azure.com/dnceng/public/_build/results?buildId=1135812&view=logs&j=e36ba317-696d-52ae-17e4-c1550b11ed0e&t=bc5b3adc-f53f-5379-06e0-c27e87afd8be&l=55

https://helix.dot.net/api/2019-06-17/jobs/17bd0db4-2315-4c91-9458-a441149c521d/workitems/System.Data.Common.Tests/console

  Starting:    System.Data.Common.Tests (parallel test collections = on, max threads = 4)
    System.Data.SqlTypes.Tests.SqlStringSortingTest.SqlStringValidComparisonTest(cultureName: "ja-JP", localeId: 1041) [SKIP]
      PlatformDetection.IsIcuGlobalization and cultureName == ja-JP
Process terminated. Assertion failed.
String may not contain null chars
   at System.Diagnostics.Tracing.EventSource.AssertValidString(EventData* data) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 1862
   at System.Diagnostics.Tracing.EventSource.WriteToAllListeners(EventWrittenEventArgs eventCallbackArgs, Int32 eventDataCount, EventData* data) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 2067
   at System.Diagnostics.Tracing.EventSource.WriteEventWithRelatedActivityIdCore(Int32 eventId, Guid* relatedActivityId, Int32 eventDataCount, EventData* data) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 1369
   at System.Diagnostics.Tracing.EventSource.WriteEventCore(Int32 eventId, Int32 eventDataCount, EventData* data) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 1268
   at System.Diagnostics.Tracing.EventSource.WriteEvent(Int32 eventId, Int64 arg1, String arg2) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 1069
   at System.Data.DataCommonEventSource.EnterScope(String message) in /_/src/libraries/System.Data.Common/src/System/Data/Common/DataCommonEventSource.cs:line 76
   at System.Data.DataCommonEventSource.EnterScope[T1,T2](String format, T1 arg1, T2 arg2) in /_/src/libraries/System.Data.Common/src/System/Data/Common/DataCommonEventSource.cs:line 85
   at System.Data.DataTableCollection.Add(DataTable table) in /_/src/libraries/System.Data.Common/src/System/Data/DataTableCollection.cs:line 149
   at System.Data.Tests.DataCommonEventSourceTest.<>c.<InvokeCodeThatShouldFirEvents_EnsureEventsFired>b__0_1() in /_/src/libraries/System.Data.Common/tests/System/Data/DataCommonEventSourceTest.cs:line 28
   at System.Diagnostics.Tracing.TestEventListener.RunWithCallback(Action`1 handler, Action body) in /_/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs:line 111
   at System.Data.Tests.DataCommonEventSourceTest.<>c.<InvokeCodeThatShouldFirEvents_EnsureEventsFired>b__0_0() in /_/src/libraries/System.Data.Common/tests/System/Data/DataCommonEventSourceTest.cs:line 21
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Span`1& arguments, Signature sig, Boolean constructor, Boolean wrapExceptions)
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) in /_/src/coreclr/System.Private.CoreLib/src/System/Reflection/RuntimeMethodInfo.cs:line 417
   at System.Reflection.MethodBase.Invoke(Object obj, Object[] parameters) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodBase.cs:line 53
   at Microsoft.DotNet.RemoteExecutor.Program.Main(String[] args) in /_/src/Microsoft.DotNet.RemoteExecutor/src/Program.cs:line 57
    System.Data.Tests.DataCommonEventSourceTest.InvokeCodeThatShouldFirEvents_EnsureEventsFired [FAIL]
      Half-way through waiting for remote process.
      Timed out at 5/12/2021 4:33:43 PM after 60000ms waiting for remote process.
      	Process ID: 3793
      	Handle: 1156
      	Name: dotnet
      	MainModule: /private/tmp/helix/working/A36408AA/p/dotnet
      	StartTime: 5/12/2021 4:32:42 PM
      	TotalProcessorTime: 00:00:07.1473421
      
      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.Data.Common/tests/System/Data/DataCommonEventSourceTest.cs(17,0): at System.Data.Tests.DataCommonEventSourceTest.InvokeCodeThatShouldFirEvents_EnsureEventsFired()
  Finished:    System.Data.Common.Tests
=== TEST EXECUTION SUMMARY ===
   System.Data.Common.Tests  Total: 11717, Errors: 0, Failed: 1, Skipped: 1, Time: 76.844s

Putting in the System.Diagnostics area since the exception is coming from EventSource code.

Author: eerhardt
Assignees: -
Labels:

area-System.Diagnostics, blocking-clean-ci

Milestone: -

@dotnet-issue-labeler dotnet-issue-labeler bot added the untriaged New issue has not been triaged by the area owner label May 13, 2021
@VincentBu
Copy link
Contributor

Failed again in runtime 20210513.81

Failed test:

net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open

- System.Data.Tests.DataCommonEventSourceTest.InvokeCodeThatShouldFirEvents_EnsureEventsFired

Error message:

Half-way through waiting for remote process.
Timed out at 5/13/2021 3:30:58 PM after 60000ms waiting for remote process.
Process ID: 85307
Handle: 1048
Name: dotnet
MainModule: /private/tmp/helix/working/AAE40921/p/dotnet
StartTime: 5/13/2021 3:29:58 PM
TotalProcessorTime: 00:00:03.7625373


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 System.Data.Tests.DataCommonEventSourceTest.InvokeCodeThatShouldFirEvents_EnsureEventsFired() in /_/src/libraries/System.Data.Common/tests/System/Data/DataCommonEventSourceTest.cs:line 17

@tommcdon
Copy link
Member

@MihaZupan possibly related to #52602?
cc @josalem

@MihaZupan MihaZupan added the bug label May 14, 2021
@MihaZupan
Copy link
Member

As a part of optimizing the in-process consumption of EventSource events, a bunch of asserts were added to flag incorrect parameters/data being passed to said events.

In this case, this is a bug in DataCommonEventSource.
The assertion is getting hit when calling DataCommonEventSource.EnterScope(String message).

[Event(EnterScopeId, Level = EventLevel.Verbose)]
internal long EnterScope(string message)
{
long scopeId = 0;
if (Log.IsEnabled())
{
scopeId = Interlocked.Increment(ref s_nextScopeId);
WriteEvent(EnterScopeId, scopeId, message);
}
return scopeId;
}

All EventSource Event methods have to match the events they emit to the method signature.

In this case, EnterScope accepts a single string parameter, but calls into

protected unsafe void WriteEvent(int eventId, long arg1, string? arg2)

which accepts two parameters.

So before the changes in EventSource, this led to silent data corruption, now it's hitting an assert.

@josalem
Copy link
Contributor

josalem commented May 14, 2021

Good catch @MihaZupan. This should be a quick fix of just marking the public method as [NonEvent] and have it then call a new event method that takes the correct number of args.

@ghost
Copy link

ghost commented May 14, 2021

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

Issue Details

The test has been failing on OSX - 46 times in the past 7 days.

https://runfo.azurewebsites.net/search/tests/?q=started%3A%7E7+definition%3Aruntime+name%3AInvokeCodeThatShouldFirEvents_EnsureEventsFired

Here's an example:

https://dev.azure.com/dnceng/public/_build/results?buildId=1135812&view=logs&j=e36ba317-696d-52ae-17e4-c1550b11ed0e&t=bc5b3adc-f53f-5379-06e0-c27e87afd8be&l=55

https://helix.dot.net/api/2019-06-17/jobs/17bd0db4-2315-4c91-9458-a441149c521d/workitems/System.Data.Common.Tests/console

  Starting:    System.Data.Common.Tests (parallel test collections = on, max threads = 4)
    System.Data.SqlTypes.Tests.SqlStringSortingTest.SqlStringValidComparisonTest(cultureName: "ja-JP", localeId: 1041) [SKIP]
      PlatformDetection.IsIcuGlobalization and cultureName == ja-JP
Process terminated. Assertion failed.
String may not contain null chars
   at System.Diagnostics.Tracing.EventSource.AssertValidString(EventData* data) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 1862
   at System.Diagnostics.Tracing.EventSource.WriteToAllListeners(EventWrittenEventArgs eventCallbackArgs, Int32 eventDataCount, EventData* data) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 2067
   at System.Diagnostics.Tracing.EventSource.WriteEventWithRelatedActivityIdCore(Int32 eventId, Guid* relatedActivityId, Int32 eventDataCount, EventData* data) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 1369
   at System.Diagnostics.Tracing.EventSource.WriteEventCore(Int32 eventId, Int32 eventDataCount, EventData* data) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 1268
   at System.Diagnostics.Tracing.EventSource.WriteEvent(Int32 eventId, Int64 arg1, String arg2) in /_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs:line 1069
   at System.Data.DataCommonEventSource.EnterScope(String message) in /_/src/libraries/System.Data.Common/src/System/Data/Common/DataCommonEventSource.cs:line 76
   at System.Data.DataCommonEventSource.EnterScope[T1,T2](String format, T1 arg1, T2 arg2) in /_/src/libraries/System.Data.Common/src/System/Data/Common/DataCommonEventSource.cs:line 85
   at System.Data.DataTableCollection.Add(DataTable table) in /_/src/libraries/System.Data.Common/src/System/Data/DataTableCollection.cs:line 149
   at System.Data.Tests.DataCommonEventSourceTest.<>c.<InvokeCodeThatShouldFirEvents_EnsureEventsFired>b__0_1() in /_/src/libraries/System.Data.Common/tests/System/Data/DataCommonEventSourceTest.cs:line 28
   at System.Diagnostics.Tracing.TestEventListener.RunWithCallback(Action`1 handler, Action body) in /_/src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs:line 111
   at System.Data.Tests.DataCommonEventSourceTest.<>c.<InvokeCodeThatShouldFirEvents_EnsureEventsFired>b__0_0() in /_/src/libraries/System.Data.Common/tests/System/Data/DataCommonEventSourceTest.cs:line 21
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Span`1& arguments, Signature sig, Boolean constructor, Boolean wrapExceptions)
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) in /_/src/coreclr/System.Private.CoreLib/src/System/Reflection/RuntimeMethodInfo.cs:line 417
   at System.Reflection.MethodBase.Invoke(Object obj, Object[] parameters) in /_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodBase.cs:line 53
   at Microsoft.DotNet.RemoteExecutor.Program.Main(String[] args) in /_/src/Microsoft.DotNet.RemoteExecutor/src/Program.cs:line 57
    System.Data.Tests.DataCommonEventSourceTest.InvokeCodeThatShouldFirEvents_EnsureEventsFired [FAIL]
      Half-way through waiting for remote process.
      Timed out at 5/12/2021 4:33:43 PM after 60000ms waiting for remote process.
      	Process ID: 3793
      	Handle: 1156
      	Name: dotnet
      	MainModule: /private/tmp/helix/working/A36408AA/p/dotnet
      	StartTime: 5/12/2021 4:32:42 PM
      	TotalProcessorTime: 00:00:07.1473421
      
      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.Data.Common/tests/System/Data/DataCommonEventSourceTest.cs(17,0): at System.Data.Tests.DataCommonEventSourceTest.InvokeCodeThatShouldFirEvents_EnsureEventsFired()
  Finished:    System.Data.Common.Tests
=== TEST EXECUTION SUMMARY ===
   System.Data.Common.Tests  Total: 11717, Errors: 0, Failed: 1, Skipped: 1, Time: 76.844s

Putting in the System.Diagnostics area since the exception is coming from EventSource code.

Author: eerhardt
Assignees: -
Labels:

area-System.Data, area-System.Diagnostics, blocking-clean-ci, bug, untriaged

Milestone: -

@MihaZupan
Copy link
Member

In this case, the correct way to log such an event would be something like:

[NonEvent]
internal long EnterScope(string message)
{
    long scopeId = 0; 
    if (Log.IsEnabled()) // Depending on how perf sensitive this is, consider checking IsEnabled(verbose)
    { 
        scopeId = Interlocked.Increment(ref s_nextScopeId); 
        EnterScope(scopeId, message); 
    } 
    return scopeId; 
}

[Event(EnterScopeId, Level = EventLevel.Verbose)]
private void EnterScope(long scopeId, string message) => WriteEvent(EnterScopeId, scopeId, message);

@ViktorHofer
Copy link
Member

Another one here:

Half-way through waiting for remote process.
Timed out at 5/19/2021 8:01:45 AM after 60000ms waiting for remote process.
Process ID: 64849
Handle: 1004
Name: dotnet
MainModule: /private/tmp/helix/working/AAB40941/p/dotnet
StartTime: 5/19/2021 8:00:45 AM
TotalProcessorTime: 00:00:08.8093335
 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 System.Data.Tests.DataCommonEventSourceTest.InvokeCodeThatShouldFirEvents_EnsureEventsFired() in /_/src/libraries/System.Data.Common/tests/System/Data/DataCommonEventSourceTest.cs:line 17

https://dev.azure.com/dnceng/public/_build/results?buildId=1145743&view=ms.vss-test-web.build-test-results-tab&runId=34693304&resultId=157875&paneView=debug

@VincentBu
Copy link
Contributor

Failed again in runtime 20210519.81

Failed test:

net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open

- System.Data.Tests.DataCommonEventSourceTest.InvokeCodeThatShouldFirEvents_EnsureEventsFired

Error message:

Half-way through waiting for remote process.
Timed out at 5/19/2021 4:40:52 PM after 60000ms waiting for remote process.
Process ID: 43698
Handle: 1036
Name: dotnet
MainModule: /private/tmp/helix/working/ADE00929/p/dotnet
StartTime: 5/19/2021 4:39:51 PM
TotalProcessorTime: 00:00:02.2015149


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 System.Data.Tests.DataCommonEventSourceTest.InvokeCodeThatShouldFirEvents_EnsureEventsFired() in /_/src/libraries/System.Data.Common/tests/System/Data/DataCommonEventSourceTest.cs:line 17

@AndyAyersMS
Copy link
Member

Can we get this test disabled while we're sorting through the issues?

@hoyosjs
Copy link
Member

hoyosjs commented May 20, 2021

Turned this into a tracking issue. There were 82 hits over a week (!), largely in macOS. I will be disabling this test.

@hoyosjs
Copy link
Member

hoyosjs commented May 20, 2021

cc: @aik-jahoda

@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label May 20, 2021
@ghost ghost closed this as completed in #53043 May 21, 2021
@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label May 21, 2021
@ghost ghost locked as resolved and limited conversation to collaborators Jun 20, 2021
This issue was closed.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
area-System.Data blocking-clean-ci Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms' bug
Projects
None yet
Development

Successfully merging a pull request may close this issue.

8 participants