project-system icon indicating copy to clipboard operation
project-system copied to clipboard

Published 20 hours ago • verified publisher icon dotnet

Bump xunit to 2.9.0

Open drewnoakes opened this issue 1 year ago • 15 comments
trafficstars

Increases package versions. I'm hopeful this will make unit test discovery quicker in the solution.

Also fixes compile issues due to changes in xUnit's APIs, and addresses all diagnostics logged via new capabilities in xUnit's analyzers.

Microsoft Reviewers: Open in CodeFlow

drewnoakes avatar May 01 '24 04:05 drewnoakes

/azp run

drewnoakes avatar May 02 '24 05:05 drewnoakes

Azure Pipelines successfully started running 1 pipeline(s).

azure-pipelines[bot] avatar May 02 '24 05:05 azure-pipelines[bot]

/azp run

drewnoakes avatar May 20 '24 01:05 drewnoakes

Azure Pipelines successfully started running 1 pipeline(s).

azure-pipelines[bot] avatar May 20 '24 01:05 azure-pipelines[bot]

The build is timing out while running tests. Here you can see the last thing it did before being cancelled.

  5:24>Project "D:\a\_work\1\s\tests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.csproj" (5:24) is building "D:\a\_work\1\s\tests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.csproj" (5:25) on node 3 (Test target(s)).
     5>TestCore:
         Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests -> Running tests...
         dotnet test --verbosity quiet --nologo --logger "trx;logfilename=D:\a\_work\1\s\artifacts\Debug\TestResults\net472\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll.trx" --logger "html;logfilename=D:\a\_work\1\s\artifacts\Debug\TestResults\net472\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll.html" D:\a\_work\1\s\artifacts\Debug\bin\UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\net472\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll
         Starting test execution, please wait...
         A total of 1 test files matched the specified pattern.
##[error]The Operation will be canceled. The next steps may not contain expected logs.
Attempting to cancel the build...

Locally, these net472 tests in Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests pass.

Locally, net8.0 tests fail with the below, but that might be unrelated as the CI failures are on net472.

StreamJsonRpc.RemoteInvocationException: Value cannot be null.
Parameter name: versionRange
   at Microsoft.ServiceHub.Framework.ServiceJsonRpcDescriptor.LocalProxyGeneration.<>c__DisplayClass40_0`1.<ReturnedTaskOfTHelperAsync>b__0(Task`1 _)
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.VisualStudio.TestWindow.Controller.NuGetService.<GetReferencedNuGetPackagesAsync>d__5.MoveNext()
RPC server exception:
System.ArgumentNullException: Value cannot be null.
Parameter name: versionRange
      at NuGet.PackageManagement.VisualStudio.Utility.ProjectInstalledPackage..ctor(VersionRange versionRange, PackageIdentity installedPackage)
      at NuGet.PackageManagement.VisualStudio.Utility.GetPackageReferenceUtility.UpdateResolvedVersion(LibraryDependency projectLibrary, NuGetFramework targetFramework, IList`1 targets, Dictionary`2 installedPackages)
      at NuGet.PackageManagement.VisualStudio.PackageReferenceProject`2.<>c__DisplayClass48_0.<GetPackageReferences>b__1(LibraryDependency library)
      at System.Linq.Enumerable.WhereSelectListIterator`2.MoveNext()
      at System.Linq.Enumerable.<SelectManyIterator>d__17`2.MoveNext()
      at System.Linq.Lookup`2.Create[TSource](IEnumerable`1 source, Func`2 keySelector, Func`2 elementSelector, IEqualityComparer`1 comparer)
      at System.Linq.GroupedEnumerable`3.GetEnumerator()
      at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
      at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
      at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
      at NuGet.PackageManagement.VisualStudio.PackageReferenceProject`2.<GetInstalledAndTransitivePackagesAsync>d__43.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
      at NuGet.PackageManagement.VisualStudio.PackageReferenceProject`2.<GetInstalledAndTransitivePackagesAsync>d__42.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
      at NuGet.VisualStudio.Implementation.Extensibility.NuGetProjectService.<GetInstalledPackagesAsync>d__6.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
      at NuGet.VisualStudio.Implementation.Extensibility.NuGetProjectService.<GetInstalledPackagesAsync>d__5.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at NuGet.VisualStudio.Implementation.Extensibility.NuGetProjectService.<GetInstalledPackagesAsync>d__5.MoveNext()

drewnoakes avatar May 20 '24 02:05 drewnoakes

I'm not sure how to progress this. The test run hangs, so is killed, and no results are published. We only know which assembly is seeing the hang.

@smitpatel @haileymck do either of you know whether there's a way to have .trx files published even if the run is cancelled? Or is there some other diagnostic data we might be able to get? For example, perhaps the code's stuck on a Debug.Fail popup or similar (though during tests there's usually a trace listener that converts these dialogs into exceptions).

drewnoakes avatar May 20 '24 03:05 drewnoakes

I've pushed a change that'll increase the log level from quiet to diagnostic.

drewnoakes avatar May 20 '24 03:05 drewnoakes

That didn't give much more of value:

2024-05-20T04:34:05.1327807Z   5:24>Project "D:\a\_work\1\s\tests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.csproj" (5:24) is building "D:\a\_work\1\s\tests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.csproj" (5:25) on node 2 (Test target(s)).
2024-05-20T04:34:05.1329661Z      5>TestCore:
2024-05-20T04:34:05.1330489Z          Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests -> Running tests...
2024-05-20T04:34:05.1331806Z          dotnet test --verbosity diagnostic --nologo --logger "trx;logfilename=D:\a\_work\1\s\artifacts\Debug\TestResults\net472\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll.trx" --logger "html;logfilename=D:\a\_work\1\s\artifacts\Debug\TestResults\net472\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll.html" D:\a\_work\1\s\artifacts\Debug\bin\UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\net472\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll
2024-05-20T04:34:06.5864159Z      4>TestCore:
2024-05-20T04:34:06.5864499Z          Starting test execution, please wait...
2024-05-20T04:34:06.5864714Z      5>TestCore:
2024-05-20T04:34:06.5865741Z          Starting test execution, please wait...
2024-05-20T04:34:07.1162673Z      4>TestCore:
2024-05-20T04:34:07.1163661Z          A total of 1 test files matched the specified pattern.
2024-05-20T04:34:07.1164646Z      5>TestCore:
2024-05-20T04:34:07.1165095Z          A total of 1 test files matched the specified pattern.
2024-05-20T04:34:10.2894527Z      4>TestCore:
2024-05-20T04:34:10.2894801Z          
2024-05-20T04:34:10.2951879Z          Passed!  - Failed:     0, Passed:   168, Skipped:     0, Total:   168, Duration: 281 ms - Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests.dll (net472)
2024-05-20T04:34:10.3982872Z          Results File: D:\a\_work\1\s\artifacts\Debug\TestResults\net472\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests.dll.trx
2024-05-20T04:34:10.5592436Z          Html test results file : D:\a\_work\1\s\artifacts\Debug\TestResults\net472\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests.dll.html
2024-05-20T04:34:10.5892500Z          Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests -> Tests succeeded
2024-05-20T04:34:10.5902013Z      4>Done Building Project "D:\a\_work\1\s\tests\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests.csproj" (Test target(s)).
2024-05-20T04:34:11.2382585Z      5>TestCore:
2024-05-20T04:34:11.2387935Z          [xUnit.net 00:00:02.43]     WhenAddingAnItem_TheReturnedItemHasAllTheExpectedMetadata [SKIP]
2024-05-20T04:34:11.2701932Z            Skipped WhenAddingAnItem_TheReturnedItemHasAllTheExpectedMetadata [1 ms]
2024-05-20T04:34:15.2955066Z          [xUnit.net 00:00:06.49]     IsCycleDetectedAsync(sequence: "ABCABCABC", isCycleDetected: True) [SKIP]
2024-05-20T04:34:15.3156186Z            Skipped IsCycleDetectedAsync(sequence: "ABCABCABC", isCycleDetected: True) [1 ms]

~15 min pause...

2024-05-20T04:49:52.7298386Z ##[error]The Operation will be canceled. The next steps may not contain expected logs.
2024-05-20T04:49:52.7421616Z Attempting to cancel the build...
2024-05-20T04:49:52.7565817Z      1>Done Building Project "D:\a\_work\1\s\eng\Build.proj" (default targets) -- FAILED.
2024-05-20T04:49:52.7566405Z      2>Done Building Project "D:\a\_work\1\s\artifacts\Build.sln" (Restore;Build;Test;Pack target(s)) -- FAILED.
2024-05-20T04:49:52.7899205Z      5>Done Building Project "D:\a\_work\1\s\tests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.csproj" (Test target(s)) -- FAILED.
2024-05-20T04:49:52.7922982Z      5>D:\a\_work\1\s\eng\imports\UnitTests.targets(46,5): warning MSB5021: Terminating the task executable "cmd" and its child processes because the build was canceled. [D:\a\_work\1\s\tests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.csproj::TargetFramework=net472]
2024-05-20T04:49:52.8432494Z      5>Done Building Project "D:\a\_work\1\s\tests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.csproj" (Test target(s)) -- FAILED.
2024-05-20T04:49:53.0104792Z 
2024-05-20T04:49:53.0105559Z Build FAILED.

Splitting that out by project:

2024-05-20T04:34:05.1290221Z      2>Project "D:\a\_work\1\s\artifacts\Build.sln" (2) is building "D:\a\_work\1\s\tests\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests.csproj" (4:7) on node 3 (Test target(s)).
2024-05-20T04:34:05.1291485Z      4>TestCore:
2024-05-20T04:34:05.1292401Z          Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests -> Running tests...
2024-05-20T04:34:05.1292751Z          Creating directory "D:\a\_work\1\s\artifacts\Debug\TestResults\net472\".
2024-05-20T04:34:05.1295397Z          dotnet test --verbosity diagnostic --nologo --logger "trx;logfilename=D:\a\_work\1\s\artifacts\Debug\TestResults\net472\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests.dll.trx" --logger "html;logfilename=D:\a\_work\1\s\artifacts\Debug\TestResults\net472\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests.dll.html" D:\a\_work\1\s\artifacts\Debug\bin\UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests\net472\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests.dll
2024-05-20T04:34:06.5864159Z      4>TestCore:
2024-05-20T04:34:06.5864499Z          Starting test execution, please wait...
2024-05-20T04:34:07.1162673Z      4>TestCore:
2024-05-20T04:34:07.1163661Z          A total of 1 test files matched the specified pattern.
2024-05-20T04:34:10.2894527Z      4>TestCore:
2024-05-20T04:34:10.2894801Z          
2024-05-20T04:34:10.2951879Z          Passed!  - Failed:     0, Passed:   168, Skipped:     0, Total:   168, Duration: 281 ms - Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests.dll (net472)
2024-05-20T04:34:10.3982872Z          Results File: D:\a\_work\1\s\artifacts\Debug\TestResults\net472\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests.dll.trx
2024-05-20T04:34:10.5592436Z          Html test results file : D:\a\_work\1\s\artifacts\Debug\TestResults\net472\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests.dll.html
2024-05-20T04:34:10.5892500Z          Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests -> Tests succeeded
2024-05-20T04:34:10.5902013Z      4>Done Building Project "D:\a\_work\1\s\tests\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.TestServices.UnitTests.csproj" (Test target(s)).

Those tests all passed in about five seconds. We can see what a full run is supposed to resemble.

The following test hangs at the end of this log:

2024-05-20T04:34:05.1327807Z   5:24>Project "D:\a\_work\1\s\tests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.csproj" (5:24) is building "D:\a\_work\1\s\tests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.csproj" (5:25) on node 2 (Test target(s)).
2024-05-20T04:34:05.1329661Z      5>TestCore:
2024-05-20T04:34:05.1330489Z          Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests -> Running tests...
2024-05-20T04:34:05.1331806Z          dotnet test --verbosity diagnostic --nologo --logger "trx;logfilename=D:\a\_work\1\s\artifacts\Debug\TestResults\net472\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll.trx" --logger "html;logfilename=D:\a\_work\1\s\artifacts\Debug\TestResults\net472\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll.html" D:\a\_work\1\s\artifacts\Debug\bin\UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\net472\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll
2024-05-20T04:34:06.5864714Z      5>TestCore:
2024-05-20T04:34:06.5865741Z          Starting test execution, please wait...
2024-05-20T04:34:07.1164646Z      5>TestCore:
2024-05-20T04:34:07.1165095Z          A total of 1 test files matched the specified pattern.
2024-05-20T04:34:11.2382585Z      5>TestCore:
2024-05-20T04:34:11.2387935Z          [xUnit.net 00:00:02.43]     WhenAddingAnItem_TheReturnedItemHasAllTheExpectedMetadata [SKIP]
2024-05-20T04:34:11.2701932Z            Skipped WhenAddingAnItem_TheReturnedItemHasAllTheExpectedMetadata [1 ms]
2024-05-20T04:34:15.2955066Z          [xUnit.net 00:00:06.49]     IsCycleDetectedAsync(sequence: "ABCABCABC", isCycleDetected: True) [SKIP]
2024-05-20T04:34:15.3156186Z            Skipped IsCycleDetectedAsync(sequence: "ABCABCABC", isCycleDetected: True) [1 ms]

drewnoakes avatar May 20 '24 21:05 drewnoakes

I don't think trx will be generated if the test run is terminated.

smitpatel avatar May 20 '24 21:05 smitpatel

@smitpatel. Makes sense. The log says it generated a binlog, but the run says there are no artifacts. Is it available somewhere? If not, can we make a change to capture the binlog even in case of failure like this?

drewnoakes avatar May 20 '24 22:05 drewnoakes

Our current pipeline is configured to capture logs even when a step fails. It publishes all test results, artifacts. Issue here is that whole job is terminated on timeout so azdo doesn't allow to run any steps after that at all. I am not sure if that is any direct way to achieve it.

smitpatel avatar May 20 '24 22:05 smitpatel

I can repro the hang locally:

project-system\artifacts
$ dotnet test --verbosity diagnostic --nologo --logger "trx;logfilename=Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll.trx" --logger "html;logfilename=Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll.html" "Debug\bin\UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\net472\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll"
Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
[xUnit.net 00:00:02.99]     IsCycleDetectedAsync(sequence: "ABCABCABC", isCycleDetected: True) [SKIP]
  Skipped IsCycleDetectedAsync(sequence: "ABCABCABC", isCycleDetected: True) [1 ms]
[xUnit.net 00:00:04.09]     WhenAddingAnItem_TheReturnedItemHasAllTheExpectedMetadata [SKIP]
  Skipped WhenAddingAnItem_TheReturnedItemHasAllTheExpectedMetadata [1 ms]

Surprisingly, using verbosity normal produces more output than diagnostic:

$ dotnet test --verbosity diagnostic --nologo -l "console;verbosity=normal" "Debug\bin\UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\net472\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll"

Comparing the successful tests before/after the changes in this PR, we can see that the following tests are not completing in the newer version of xunit:

image

The tests are hanging and these are concurrency-related tests. We recently changed the synchronisation primitive in use (to ReentrantSemaphore), which may be the root cause.

Regardless, I added timeouts to OnceInitializedOnceDisposedUnderLockAsyncTests to prevent indefinite hangs in those tests. This should allow us to see unit test results in CI. The tests continue to pass in the VS test runner.

drewnoakes avatar Jul 20 '24 01:07 drewnoakes

That seems to have fixed the hang.

Changing the test fixture to run tests serially rather than in parallel shows there's still a failure (though in only one test now):

❯ dotnet test --verbosity diagnostic --nologo -l "console;verbosity=normal" "Debug\bin\UnitTests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\net472\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests.dll" --filter "FullyQualifiedName~OnceInitializedOnceDisposedUnderLockAsyncTests"
Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.8.2+699d445a1a (64-bit .NET Framework 4.8.9256.0)
[xUnit.net 00:00:00.37]   Discovering: Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests
[xUnit.net 00:00:00.78]   Discovered:  Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests
[xUnit.net 00:00:00.79]   Starting:    Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests
  Passed ExecuteUnderLockAsyncOfT_NullAsAction_ThrowsArgumentNullException [16 ms]
  Passed ExecuteUnderLockAsyncOfT_WithNoContention_ExecutesAction [40 ms]
  Passed ExecuteUnderLockAsync_WhenPassedCancelledToken_DoesNotExecuteAction [9 ms]
  Passed ExecuteUnderLockAsync_WhenDisposed_ThrowsOperationCanceled [12 ms]
  Passed ExecuteUnderLockAsync_AvoidsOverlappingActionsWithExecuteUnderLockAsyncOfT [84 ms]
  Passed ExecuteUnderLockAsync_AvoidsOverlappingWithDispose [64 ms]
  Passed ExecuteUnderLockAsyncOfT_WhenPassedCancelledToken_DoesNotExecuteAction [2 ms]
  Passed ExecuteUnderLockAsyncOfT_AvoidsOverlappingActionsWithExecuteUnderLockAsync [59 ms]
  Passed ExecuteUnderLockAsyncOfT_AvoidsOverlappingWithDispose [76 ms]
  Passed ExecuteUnderLockAsync_NullAsAction_ThrowsArgumentNullException [1 ms]
  Passed ExecuteUnderLockAsyncOfT_WhenDisposed_ThrowsOperationCancelled [1 ms]
  Passed DisposeAsync_DoesNotThrow [1 ms]
[xUnit.net 00:00:31.38]     ExecuteUnderLockAsyncOfT_AvoidsOverlappingActions [FAIL]
[xUnit.net 00:00:31.38]       System.TimeoutException : The operation has timed out.
[xUnit.net 00:00:31.38]       Stack Trace:
[xUnit.net 00:00:31.38]            at Microsoft.VisualStudio.Threading.TplExtensions.<WithTimeout>d__5.MoveNext()
[xUnit.net 00:00:31.38]         --- End of stack trace from previous location where exception was thrown ---
[xUnit.net 00:00:31.38]            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
[xUnit.net 00:00:31.38]            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[xUnit.net 00:00:31.38]            at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
[xUnit.net 00:00:31.38]         C:\dev\project-system\tests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\ProjectSystem\OnceInitializedOnceDisposedUnderLockAsyncTests.cs(378,0): at Microsoft.VisualStudio.ProjectSystem.OnceInitializedOnceDisposedUnderLockAsyncTests.<AssertNoOverlap>d__19.MoveNext()
[xUnit.net 00:00:31.38]         --- End of stack trace from previous location where exception was thrown ---
[xUnit.net 00:00:31.38]            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
[xUnit.net 00:00:31.38]            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[xUnit.net 00:00:31.38]            at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
[xUnit.net 00:00:31.38]         C:\dev\project-system\tests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\ProjectSystem\OnceInitializedOnceDisposedUnderLockAsyncTests.cs(171,0): at Microsoft.VisualStudio.ProjectSystem.OnceInitializedOnceDisposedUnderLockAsyncTests.<ExecuteUnderLockAsyncOfT_AvoidsOverlappingActions>d__9.MoveNext()
[xUnit.net 00:00:31.38]         --- End of stack trace from previous location where exception was thrown ---
[xUnit.net 00:00:31.38]            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
[xUnit.net 00:00:31.38]            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[xUnit.net 00:00:31.38]         --- End of stack trace from previous location where exception was thrown ---
[xUnit.net 00:00:31.38]            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
[xUnit.net 00:00:31.38]            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[xUnit.net 00:00:31.38]         --- End of stack trace from previous location where exception was thrown ---
[xUnit.net 00:00:31.38]            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
[xUnit.net 00:00:31.38]            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
  Failed ExecuteUnderLockAsyncOfT_AvoidsOverlappingActions [30 s]
  Error Message:
   System.TimeoutException : The operation has timed out.
  Stack Trace:
     at Microsoft.VisualStudio.Threading.TplExtensions.<WithTimeout>d__5.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Microsoft.VisualStudio.ProjectSystem.OnceInitializedOnceDisposedUnderLockAsyncTests.<AssertNoOverlap>d__19.MoveNext() in C:\dev\project-system\tests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\ProjectSystem\OnceInitializedOnceDisposedUnderLockAsyncTests.cs:line 378
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Microsoft.VisualStudio.ProjectSystem.OnceInitializedOnceDisposedUnderLockAsyncTests.<ExecuteUnderLockAsyncOfT_AvoidsOverlappingActions>d__9.MoveNext() in C:\dev\project-system\tests\Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests\ProjectSystem\OnceInitializedOnceDisposedUnderLockAsyncTests.cs:line 171
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
[xUnit.net 00:00:31.44]   Finished:    Microsoft.VisualStudio.ProjectSystem.Managed.UnitTests
  Passed ExecuteUnderLockAsyncOfT_PassesCancellationTokenToAction [1 ms]
  Passed ExecuteUnderLockAsync_AvoidsOverlappingActions [53 ms]
  Passed ExecuteUnderLockAsync_CanBeNested [1 ms]
  Passed ExecuteUnderLockAsync_PassesCancellationTokenToAction [1 ms]
  Passed ExecuteUnderLockAsyncOfT_CanBeNested [1 ms]
  Passed ExecuteUnderLockAsync_WithNoContention_ExecutesAction [1 ms]

Test Run Failed.
Total tests: 19
     Passed: 18
     Failed: 1
 Total time: 32.0860 Seconds

The single failure occurs in ExecuteUnderLockAsyncOfT_AvoidsOverlappingActions, so that's where I'll focus attention next.

It's surprising to me that this passes in VS, but not on the command line.

We need to be able to run these tests in parallel too, as this code in particular shouldn't require isolation.

drewnoakes avatar Jul 20 '24 01:07 drewnoakes

Changing the ReentrantSemaphore mode from Stack to Freeform doesn't change the outcome.

drewnoakes avatar Jul 20 '24 01:07 drewnoakes

Since #9498, we can try and bump Verify as well.

drewnoakes avatar Jul 23 '24 03:07 drewnoakes