Could not write lines to file Microsoft.NET.HostModel.ComHost.Tests

[jkotas]

Intermittent build error hit by Installer Build and Test coreclr windows_x64 Release in CI:

022-06-19T18:00:25.9981639Z   Running tests: D:\a\_work\1\s\artifacts\bin\AppHost.Bundle.Tests\Release\net7.0\AppHost.Bundle.Tests.dll [net7.0|x64]
2022-06-19T18:00:26.8040811Z   Running tests: D:\a\_work\1\s\artifacts\bin\Microsoft.NET.HostModel.AppHost.Tests\Release\net7.0\Microsoft.NET.HostModel.AppHost.Tests.dll [net7.0|x64]
2022-06-19T18:00:27.0021440Z   Running tests: D:\a\_work\1\s\artifacts\bin\Microsoft.NET.HostModel.ComHost.Tests\Release\net7.0\Microsoft.NET.HostModel.ComHost.Tests.dll [net7.0|x64]
2022-06-19T18:00:41.7216702Z   Tests succeeded: D:\a\_work\1\s\artifacts\bin\Microsoft.NET.HostModel.AppHost.Tests\Release\net7.0\Microsoft.NET.HostModel.AppHost.Tests.dll [net7.0|x64]
2022-06-19T18:01:10.6831061Z D:\a\_work\1\s\.packages\microsoft.dotnet.arcade.sdk\7.0.0-beta.22310.1\tools\VSTest.targets(55,5): error MSB3491: Could not write lines to file "D:\a\_work\1\s\artifacts\log\Release\Microsoft.NET.HostModel.ComHost.Tests_net7.0_x64.log". The process cannot access the file 'D:\a\_work\1\s\artifacts\log\Release\Microsoft.NET.HostModel.ComHost.Tests_net7.0_x64.log' because it is being used by another process. [D:\a\_work\1\s\src\installer\tests\Microsoft.NET.HostModel.Tests\Microsoft.NET.HostModel.ComHost.Tests\Microsoft.NET.HostModel.ComHost.Tests.csproj]
2022-06-19T18:01:10.7438162Z ##[error].packages\microsoft.dotnet.arcade.sdk\7.0.0-beta.22310.1\tools\VSTest.targets(55,5): error MSB3491: (NETCORE_ENGINEERING_TELEMETRY=Build) Could not write lines to file "D:\a\_work\1\s\artifacts\log\Release\Microsoft.NET.HostModel.ComHost.Tests_net7.0_x64.log". The process cannot access the file 'D:\a\_work\1\s\artifacts\log\Release\Microsoft.NET.HostModel.ComHost.Tests_net7.0_x64.log' because it is being used by another process.
2022-06-19T18:01:10.7456526Z   Running tests: D:\a\_work\1\s\artifacts\bin\Microsoft.NET.HostModel.Bundle.Tests\Release\net7.0\Microsoft.NET.HostModel.Bundle.Tests.dll [net7.0|x64]
2022-06-19T18:12:12.3099944Z   Tests succeeded: D:\a\_work\1\s\artifacts\bin\Microsoft.NET.HostModel.Bundle.Tests\Release\net7.0\Microsoft.NET.HostModel.Bundle.Tests.dll [net7.0|x64]

{
  "ErrorMessage": "error MSB3491: Could not write lines to file \"D:\\a\\_work\\1\\s\\artifacts\\log\\Release\\Microsoft.NET.HostModel.ComHost.Tests_net7.0_x64.log\"",
  "BuildRetry": false
}

Report

Build	Definition	Step Name	Console log
1896046	dotnet/runtime	Build	Log
1894514	dotnet/runtime	Build	Log
1893340	dotnet/runtime	Build	Log
1891752	dotnet/runtime	Build	Log
1890865	dotnet/runtime	Build	Log
1886297	dotnet/runtime	Build	Log
1886561	dotnet/runtime	Build	Log
1886741	dotnet/runtime	Build	Log
1886981	dotnet/runtime	Build	Log
1892083	dotnet/runtime	Build	Log
1892899	dotnet/runtime	Build	Log
1892886	dotnet/runtime	Build	Log
1893235	dotnet/runtime	Build	Log
1893112	dotnet/runtime	Build	Log
1893373	dotnet/runtime	Build	Log
1894291	dotnet/runtime	Build	Log
1894338	dotnet/runtime	Build	Log
1894384	dotnet/runtime	Build	Log
1894521	dotnet/runtime	Build	Log
1894760	dotnet/runtime	Build	Log
1895037	dotnet/runtime	Build	Log
1895247	dotnet/runtime	Build	Log
1895305	dotnet/runtime	Build	Log
1896134	dotnet/runtime	Build	Log
1896006	dotnet/runtime	Build	Log
1896299	dotnet/runtime	Build	Log
1885715	dotnet/runtime	Build	Log
1884639	dotnet/runtime	Build	Log
1884836	dotnet/runtime	Build	Log

Summary

24-Hour Hit Count	7-Day Hit Count	1-Month Count
0	22	29

[ghost]

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

Issue Details

---

Intermittent build error hit by Installer Build and Test coreclr windows_x64 Release in CI:

022-06-19T18:00:25.9981639Z   Running tests: D:\a\_work\1\s\artifacts\bin\AppHost.Bundle.Tests\Release\net7.0\AppHost.Bundle.Tests.dll [net7.0|x64]
2022-06-19T18:00:26.8040811Z   Running tests: D:\a\_work\1\s\artifacts\bin\Microsoft.NET.HostModel.AppHost.Tests\Release\net7.0\Microsoft.NET.HostModel.AppHost.Tests.dll [net7.0|x64]
2022-06-19T18:00:27.0021440Z   Running tests: D:\a\_work\1\s\artifacts\bin\Microsoft.NET.HostModel.ComHost.Tests\Release\net7.0\Microsoft.NET.HostModel.ComHost.Tests.dll [net7.0|x64]
2022-06-19T18:00:41.7216702Z   Tests succeeded: D:\a\_work\1\s\artifacts\bin\Microsoft.NET.HostModel.AppHost.Tests\Release\net7.0\Microsoft.NET.HostModel.AppHost.Tests.dll [net7.0|x64]
2022-06-19T18:01:10.6831061Z D:\a\_work\1\s\.packages\microsoft.dotnet.arcade.sdk\7.0.0-beta.22310.1\tools\VSTest.targets(55,5): error MSB3491: Could not write lines to file "D:\a\_work\1\s\artifacts\log\Release\Microsoft.NET.HostModel.ComHost.Tests_net7.0_x64.log". The process cannot access the file 'D:\a\_work\1\s\artifacts\log\Release\Microsoft.NET.HostModel.ComHost.Tests_net7.0_x64.log' because it is being used by another process. [D:\a\_work\1\s\src\installer\tests\Microsoft.NET.HostModel.Tests\Microsoft.NET.HostModel.ComHost.Tests\Microsoft.NET.HostModel.ComHost.Tests.csproj]
2022-06-19T18:01:10.7438162Z ##[error].packages\microsoft.dotnet.arcade.sdk\7.0.0-beta.22310.1\tools\VSTest.targets(55,5): error MSB3491: (NETCORE_ENGINEERING_TELEMETRY=Build) Could not write lines to file "D:\a\_work\1\s\artifacts\log\Release\Microsoft.NET.HostModel.ComHost.Tests_net7.0_x64.log". The process cannot access the file 'D:\a\_work\1\s\artifacts\log\Release\Microsoft.NET.HostModel.ComHost.Tests_net7.0_x64.log' because it is being used by another process.
2022-06-19T18:01:10.7456526Z   Running tests: D:\a\_work\1\s\artifacts\bin\Microsoft.NET.HostModel.Bundle.Tests\Release\net7.0\Microsoft.NET.HostModel.Bundle.Tests.dll [net7.0|x64]
2022-06-19T18:12:12.3099944Z   Tests succeeded: D:\a\_work\1\s\artifacts\bin\Microsoft.NET.HostModel.Bundle.Tests\Release\net7.0\Microsoft.NET.HostModel.Bundle.Tests.dll [net7.0|x64]

Author:	jkotas
Assignees:	-
Labels:	area-HostModel, untriaged
Milestone:	-

[jkotas]

Failed in #70956. Log https://dev.azure.com/dnceng/9ee6d478-d288-47f7-aacc-f6e6d082ae6d/_apis/build/builds/1833271/logs/1442

[jkotas]

Failed in #70944. Log https://dev.azure.com/dnceng/9ee6d478-d288-47f7-aacc-f6e6d082ae6d/_apis/build/builds/1832671/logs/2290

[agocke]

@elinor-fung Could this be caused by recent changes?

[elinor-fung]

We did switch to the arcade infrastructure for using dotnet test (#69340).

We just rely on that infrastructure to redirect the output to a log file:
https://github.com/dotnet/arcade/blob/e7ede87875f41a9b3df898ae08da5ebc96e24f56/src/Microsoft.DotNet.Arcade.Sdk/tools/VSTest.targets#L30

And then append more information to the file after running the command (which is where it is failing):
https://github.com/dotnet/arcade/blob/e7ede87875f41a9b3df898ae08da5ebc96e24f56/src/Microsoft.DotNet.Arcade.Sdk/tools/VSTest.targets#L55

I'm not sure why the file would still be in use after the Exec finishes.

[elinor-fung]

Related: dotnet/sdk#10062

It'd be good to figure out why it is happening, but maybe it could be mitigated by using ConsoleOutput to capture the output (instead of the > redirect) when running the test command and then writing all the lines in one shot.
https://github.com/dotnet/arcade/blob/e7ede87875f41a9b3df898ae08da5ebc96e24f56/src/Microsoft.DotNet.Arcade.Sdk/tools/VSTest.targets#L43-L50

[eerhardt]

Happened here as well: https://dev.azure.com/dnceng/public/_build/results?buildId=1839229&view=logs&j=e36cdb78-1b23-5f53-5d15-e931194c7d32&t=5f3cc2c3-b299-5f57-0006-9e48b00ce7cd&l=735

[agocke]

I'm trying to take a look locally and see if we can find a solution

[danmoseley]

It'd be good to figure out why it is happening, but maybe it could be mitigated by using ConsoleOutput to capture the output (instead of the > redirect) when running the test command and then writing all the lines in one shot.

Another option perhaps is to write the command to the file first, then change the > to >> when subsequently writing the test output. Or, run Exec once, adding an extra line in the command that writes the output.

[agocke]

Since any change would likely have to be made in Arcade, I've filed dotnet/arcade#9864

[karelz]

dotnet/arcade#9864 has a fix, so waiting for it to propagate into runtime repo ...

[MattGal]

dotnet/arcade#9864 has a fix, so waiting for it to propagate into runtime repo ...

Fix is propagated and I'm watching it; will port to other branches if it hasn't reproduced by tomorrow.

[agocke]

It looks like this is working well, no failures since Thursday.