coverlet: Coverlet fails to write coverage with file locked error

So this is a bit odd, but it only happens during our CI (and it is intermittent). We’re using v1.2 of the vstest collector.

The error we get is this:

Data collector 'XPlat code coverage' message: [coverlet]Coverlet.Collector.Utilities.CoverletDataCollectorException: CoverletCoverageDataCollector: Failed to get coverage result
 ---> System.IO.IOException: The process cannot access the file '/tmp/MySourceProject_8b9f64e1-2aa6-4144-aece-e1ec4323d842' because it is being used by another process.
   at System.IO.FileStream.Init(FileMode mode, FileShare share, String originalPath)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options)
   at System.IO.FileStream..ctor(String path, FileMode mode)
   at Coverlet.Core.Helpers.FileSystem.NewFileStream(String path, FileMode mode) in D:\git\coverletToRelease\src\coverlet.core\Helpers\FileSystem.cs:line 43
   at Coverlet.Core.Coverage.CalculateCoverage() in D:\git\coverletToRelease\src\coverlet.core\Coverage.cs:line 352
   at Coverlet.Core.Coverage.GetCoverageResult() in D:\git\coverletToRelease\src\coverlet.core\Coverage.cs:line 137
   at Coverlet.Collector.DataCollection.CoverageWrapper.GetCoverageResult(Coverage coverage) in D:\git\coverletToRelease\src\coverlet.collector\DataCollection\CoverageWrapper.cs:line 44
   at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in D:\git\coverletToRelease\src\coverlet.collector\DataCollection\CoverageManager.cs:line 91
   --- End of inner exception stack trace ---
   at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in D:\git\coverletToRelease\src\coverlet.collector\DataCollection\CoverageManager.cs:line 96
   at Coverlet.Collector.DataCollection.CoverletCoverageCollector.OnSessionEnd(Object sender, SessionEndEventArgs e) in D:\git\coverletToRelease\src\coverlet.collector\DataCollection\CoverletCoverageCollector.cs:line 148.

What is strange is that after this error message, we see the last test case complete (we use the normal logging verbosity so we see every test case printed). We’re using .net core 3.1, and xunit 2.4.1 if it matters (we use a xunit collection fixture too). It appears that the collection fixture is disposed before the last test’s results are printed whether coverlet succeeds or not, so I’m thinking the last test being printed out after the coverlet error is not an indication that it is actually running after coverlet is blocked.

Some other interesting info about our builds: It is in a docker container, with the test results directory mounted on a volume, so I can’t imagine another process is stepping on any file being used here. We pass a filter into dotnet test because we have a number of expensive tests that we run in parallel by running multiple docker containers with different filters simultaneously.

When running 16.4.0 of the test sdk, we’d often see the error manifest as:

Data collector 'XPlat code coverage' message: [coverlet]Coverlet.Collector.Utilities.CoverletDataCollectorException: CoverletCoverageDataCollector: Failed to get coverage result
 ---> System.IO.EndOfStreamException: Unable to read beyond the end of the stream.
   at System.IO.BinaryReader.InternalRead(Int32 numBytes)
   at Coverlet.Core.Coverage.CalculateCoverage() in D:\git\coverletToRelease\src\coverlet.core\Coverage.cs:line 363
   at Coverlet.Core.Coverage.GetCoverageResult() in D:\git\coverletToRelease\src\coverlet.core\Coverage.cs:line 137
   at Coverlet.Collector.DataCollection.CoverageWrapper.GetCoverageResult(Coverage coverage) in D:\git\coverletToRelease\src\coverlet.collector\DataCollection\CoverageWrapper.cs:line 44
   at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in D:\git\coverletToRelease\src\coverlet.collector\DataCollection\CoverageManager.cs:line 91
   --- End of inner exception stack trace ---
   at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in D:\git\coverletToRelease\src\coverlet.collector\DataCollection\CoverageManager.cs:line 96
   at Coverlet.Collector.DataCollection.CoverletCoverageCollector.OnSessionEnd(Object sender, SessionEndEventArgs e) in D:\git\coverletToRelease\src\coverlet.collector\DataCollection\CoverletCoverageCollector.cs:line 148.

But I’m only seeing the first error I posted with 16.5.0.

About this issue

Original URL
State: closed
Created 4 years ago
Comments: 60 (2 by maintainers)

Most upvoted comments

I really appreciate your help @MarcoRossignoli! Here is the repository: https://github.com/namely/CoverletErrorRepro

abe545 on Feb 28, 2020

If you can generate a repro would be great…I need to understand all the implication of my patches because tracker is a “sensible” component. For now use my branch patch if you can and I’ll do more investigation(busy weeks at the moment so I won’t merge to master soon). But I think this is definely a bug.

MarcoRossignoli on Feb 26, 2020

Ah, @MarcoRossignoli that was in the gist:

[2020-02-21T07:23:46.2623509Z P:80 T:4]Unload called for '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/PayrollSteps.Core.dll' FlushType: InProcessCollectorFlush
[2020-02-21T07:23:46.2626545Z P:80 T:4]Flushing hit file '/tmp/PayrollSteps.Core_5da02297-149d-458b-a477-3a6dd6bf832e'
[2020-02-21T07:23:46.2627689Z P:80 T:4]Writing 61433 new hits
[2020-02-21T07:23:46.2924479Z P:80 T:4]Hit file '/tmp/PayrollSteps.Core_5da02297-149d-458b-a477-3a6dd6bf832e' flushed, size 245736

abe545 on Feb 26, 2020

@abe545 can you attach tracker logs?

MarcoRossignoli on Feb 26, 2020

Actually is a “log bug” inside vstest to me…that log is always emitted…it doesn’t check if event was signaled or not

https://github.com/microsoft/vstest/blob/462d3674c29310be0efa8f5db04d5fe058ac0858/src/Microsoft.TestPlatform.CrossPlatEngine/Client/ProxyOperationManager.cs#L201-L233

cc: @nohwnd

MarcoRossignoli on Feb 26, 2020

It is unclear to me if this is a real solution, or not, as I’m sure there is a good reason to register that event handler.

This is correct…I mean if I’m using collector and I’m on .net core process exits is “unuseful” because inproc collector flush data correctly. BTW if I’m using collector with .net framework(unsupported at the moment but maybe we’ll fix…collector is compiled for netcoreapp2.1 and not standard…I’m waiting info from vstest on that, they wrote coverlet collector we only did a review) I could have domain…so I could “append new hits” on every domain unload.

The solution should be if I’m using collectors and:

If I’m on .net core runtime and have called “Unload”, unsubscribe from appdomain and appexit
If I’m on .net framework and have called “Unload” the first call should unsubscribe process exit but keep domainunload.

I don’t understand why my “synch” fix fails…process exit unload should wait if GetCoverage is “using” hits file and if process will be killed won’t be a problem…nobody will read that hits file when GetCoverage will release mutex…

Can you retry with my branch patch and understand which is the “real exception” thrown inside GetCoverage?

MarcoRossignoli on Feb 25, 2020

@abe545 yep…but that is expected…if for some reason unload is called more than one time that error is a “benign error”. Btw I’ve got a suspect…could be a timing issue…at the moment we subscribe to 2 event…process exit and app domain unload https://github.com/tonerdo/coverlet/blob/master/src/coverlet.core/Instrumentation/ModuleTrackerTemplate.cs#L36

Domain unload is for .net framework and so it’s expected error above, but is not expected on .net core. But I think that:

out proc collector call inproc collector that run unload
out of proc collector call CalculateCoverage and access to hit file
at same time host process is killed and process exit run calling write hits, this generage error for step 2.

Can you try to dotnet pack this test branch and run coverage with generated packages? https://github.com/MarcoRossignoli/coverlet/tree/issue_736

I added sync access to hit file also during CalculateCoverage…if after unload called by outofproc collector host process is killed it doesn’t write on file thank’s to mutex, the same acquired by module tracker https://github.com/tonerdo/coverlet/blob/master/src/coverlet.core/Instrumentation/ModuleTrackerTemplate.cs#L86

MarcoRossignoli on Feb 24, 2020

Can you attach also “host” log(where inproc collector is injected)? And also enable tracker? https://github.com/tonerdo/coverlet/blob/master/Documentation/Troubleshooting.md#enable-injected-tracker-log To undestand if for some reason hit file is read when someone wants to persist-hit on the same.

MarcoRossignoli on Feb 21, 2020