[Infra] SampleAnalyzerIntegrationTest randomly timeouting in CI

[JanKrivanek]

Context

System.TimeoutException : Test failed due to timeout: process 12042 is active for more than 30 sec.

   at Microsoft.Build.UnitTests.Shared.RunnerUtilities.RunProcessAndGetOutput(String process, String parameters, Boolean& successfulExit, Boolean shellExecute, ITestOutputHelper outputHelper) in /_/src/UnitTests.Shared/RunnerUtilities.cs:line 139
   at Microsoft.Build.UnitTests.Shared.RunnerUtilities.ExecBootstrapedMSBuild(String msbuildParameters, Boolean& successfulExit, Boolean shellExecute, ITestOutputHelper outputHelper) in /_/src/UnitTests.Shared/RunnerUtilities.cs:line 67
   at Microsoft.Build.BuildCheck.UnitTests.EndToEndTests.SampleAnalyzerIntegrationTest(Boolean buildInOutOfProcessNode, Boolean analysisRequested) in /home/vsts/work/1/s/src/BuildCheck.UnitTests/EndToEndTests.cs:line 122
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodBaseInvoker.InvokeDirectByRefWithFewArgs(Object obj, Span`1 copyOfArgs, BindingFlags invokeAttr)

Sample run: https://dev.azure.com/dnceng-public/public/_build/results?buildId=648080&view=ms.vss-test-web.build-test-results-tab&runId=16013174&resultId=100001&paneView=debug

[YuliiaKovalova]

discussed offline: the execution time can be extended for handling it. Please track it for some time if this approach solves the problem

[GangWang01]

After observing 9 runs that failed with this test, the failure only happened to the following test cases. From the output logs attached inline, it looks like within 30 seconds the build check analyzer hadn't finished.

• SampleAnalyzerIntegrationTest(buildInOutOfProcessNode: True, analysisRequested: True) - Fail buildInOutOfProcessNode_True-analysisRequested_True.txt
• SampleAnalyzerIntegrationTest(buildInOutOfProcessNode: False, analysisRequested: True) - Fail buildInOutOfProcessNode_False-analysisRequested_True.txt

Checking with the output log Microsoft.Build.BuildCheck.UnitTests_net8.0_x64.log of fully passed test run, I found there were over 1000 warnings when the analysis was requested. But the warnings except BC0101 couldn't be reproduced locally. This may explain it looks like within 30 seconds the build check analyzer hadn't finished. No idea why CI run has so many extra warnings.

[YuliiaKovalova]

@JanKrivanek , can this fix help with the test performance?
#10084

[JanKrivanek]

Only slightly - it slashes only about a third of currently detected slowdown of the analyzers.
Though the detected slowdown was in range of about 14% - so it's puzzling that the process runs for over 30 second. It would be interesting to see if it fails with about the same or significantly decreased ratio if we increase the timeout to say - 120 seconds. That might bisect between the slowdown and deadlock theory

[JanKrivanek]

Another incidence (after the timeout increasing): https://dev.azure.com/dnceng-public/public/_build/results?buildId=681320&view=ms.vss-test-web.build-test-results-tab&runId=16909114&resultId=100003&paneView=debug

[JanKrivanek]

Might be totally red herring:

The timeouting cases seem to have TerminalLogger used (notice the control sequences):

�[33;1m   Microsoft.Build.BuildCheck.UnitTests: [Long Running Test] 'Microsoft.Build.BuildCheck.UnitTests.EndToEndTests.SampleAnalyzerIntegrationTest', Elapsed: 00:01:02
�[mExecuting [/home/vsts/work/1/s/.dotnet/dotnet /home/vsts/work/1/s/artifacts/bin/bootstrap/net8.0/MSBuild/MSBuild.dll FooBar.csproj /m:1 -nr:False -restore -analyze]
==== OUTPUT ====
�[31;1m    Microsoft.Build.BuildCheck.UnitTests.EndToEndTests.SampleAnalyzerIntegrationTest(buildInOutOfProcessNode: True, analysisRequested: True) [FAIL]
�[m�[37m      System.TimeoutException : Test failed due to timeout: process 11430 is active for more than 120 sec.

Sample full log: TIMEOUT-Microsoft.Build.BuildCheck.UnitTests_net8.0_x64.log

Wherease I do not see those appear in individual test cases for the success cases - sample log: OK-Microsoft.Build.BuildCheck.UnitTests_net8.0_x64.log

Regardless of it being red herring or not - it is strange that TerminalLogger is used in CI. I believe @AR-May was looking into somthing similar

[JaynieBai]

@JanKrivanek and @maridematte I repro this issue with the command "dotnet test ./artifacts/bin/Microsoft.Build.BuildCheck.UnitTests/Debug/net8.0/Microsoft.Build.BuildCheck.UnitTests.dll --filter "FullyQualifiedName~SampleAnalyzerIntegrationTest" randomly
" in linux machine.

Added -v:d with process command to output more info and found the build is stuck in target GetCopyToPublishDirectoryItems

This is build log.txt.

[JanKrivanek]

Perfect!

Can you collect 2 more cases to see if there is any pattern? Plus appart from the diag log it might be helpfull to have binlog as well.

Other than that I unfortunately do not have any idea now about what can bw causing this