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.
Hi Abraham, some notes
When running 16.4.0 of the test sdk, we'd often see the error manifest as:
It's ok and expected, until sdk 16.5.0 there was a bug inside vstest and coverlet collection greater than 1.0.0 weren't loaded https://github.com/tonerdo/coverlet/blob/master/Documentation/KnowIssues.md#2-upgrade-coverletcollector-to-version--100
So here you're hitting the above issue.
The process cannot access the file
Are you running test on solution file(or repo root) or are you running dotnet test on every test project?If you're running from sln can you try with one dotnet test for every test csproj?
I saw this issue another time on big solutions where for some reason parallel tests locked hit file, as if the same instrumented lib was used in different process and so same file is used https://github.com/tonerdo/coverlet/blob/master/src/coverlet.core/Instrumentation/Instrumenter.cs#L239
I'm running it on the csproj file directly with this command:
dotnet test ./MyTestProject/MyTestProject.csproj --configuration Release --no-build -v n --collect:"XPlat Code Coverage" --settings coverlet.runsettings --filter "Feature=Foo"
I then have various test classes that use xunit traits:
[Trait("Feature", "Foo")]
public class SomeFeature { ... }
Also, I forgot to mention, I pass it this runsettings file:
<?xml version="1.0" encoding="utf-8" ?>
<RunSettings>
<DataCollectionRunSettings>
<DataCollectors>
<DataCollector friendlyName="XPlat code coverage">
<Configuration>
<Format>lcov</Format>
<Exclude>[xunit*]*</Exclude>
<ExcludeByFile>/app/gen/Namely.*.Grpc/*</ExcludeByFile>
</Configuration>
</DataCollector>
</DataCollectors>
</DataCollectionRunSettings>
</RunSettings>
I'm currently trying to create a repro case, but am struggling. One thing I'm noticing in my real project is that this is logged before the last test's result (whether coverlet fails or not):
[xUnit.net 00:06:54.88] Finished: MyTestProject
Update
This strange ordering of the finished message doesn't always happen after I updated my base docker images to the latest 3.1.2 image 馃し鈥嶁檪
And it gets slightly more frustrating: I witnessed a test run fail to generate coverage with the same error on one of my projects that does not use filters or xunit fixtures/collections, but otherwise the setup is identical: running in docker, using latest coverlet + .net sdk + xunit.
So interestingly, I'm now consistently getting the failure for a specific set of filters - If I run this locally within a docker-compose, I get the same issue. I thought it might be the parallel containers' volume mounts somehow stepping on each other, but I see the error even when this is the only container executing. I'll continue to try to repro this in a shareable manner.
Does it happen out of container?
Another test we can do, can you generate logs using --diag:log.txt https://github.com/tonerdo/coverlet/blob/master/Documentation/Troubleshooting.md#collectors-integration
I haven't witnessed it outside the container. I'll generate the logs and report back.
@MarcoRossignoli thank you for your help on this! I think I found the culprit:
System.IO.IOException : The configured user limit (128) on the number of inotify instances has been reached, or the per-process limit on the number of open file descriptors has been reached.
So we were using the default asp.net host (and running tests against the test server). This by default adds 2 watched json files for the application configuration. By taking full control of the host being built, I was able to at least intermittently get the coverage working again.
This is seemingly a race condition between xunit parallelized collections - on my PC that I've given more resources to docker, I was getting test failures with the above error also. So it seems like the file handles opened by asp.net were hitting a limit, and we were lucky it wasn't failing tests also in our CI.
Was on logs that message?
They were... but sadly I hard deleted the logs as I was trying to investigate my issue.
I've updated how we create the config to not watch the json files, and I'm still seeing the original hits file error in another filtered project, but not the user limit error.
but not the user limit error.
Some other strange infos from logs?
I didn't see anything obviously wrong, but here is the the collector logs:
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.565, 40768041605418, datacollector.dll, DataCollectorMain.Run: Starting data collector run with args: --port,46037,--parentprocessid,48,--diag,/app/coverletlogs/log-paychecks.datacollector.20-02-20_06-07-53_48147_4.txt,--tracelevel,4
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.577, 40768047486944, datacollector.dll, DataCollector: Monitoring parent process with id: '48'
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.599, 40768068596128, datacollector.dll, Trying to connect to server on socket : 127.0.0.1:46037
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.612, 40768081659720, datacollector.dll, SocketCommunicationManager : SetupClientAsync : Attempting to connect to the server.
TpTrace Information: 0 : 61, 5, 2020/02/20, 06:07:53.626, 40768096147895, datacollector.dll, Connected to the server successfully
TpTrace Information: 0 : 61, 5, 2020/02/20, 06:07:53.627, 40768096890304, datacollector.dll, Using the buffer size of 16384 bytes
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.714, 40768184173607, datacollector.dll, DataCollector: Start Request Processing.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.720, 40768190012990, datacollector.dll, DataCollectionRequestHandler.ProcessRequests : Datacollector received message: (DataCollection.BeforeTestRunStart) -> {
"SettingsXml": "<RunSettings><DataCollectionRunSettings><DataCollectors><DataCollector friendlyName=\"XPlat code coverage\" enabled=\"True\"><Configuration><Format>lcov</Format><Exclude>[xunit*]*</Exclude><ExcludeByFile>/app/gen/Namely.*.Grpc/*</ExcludeByFile></Configuration></DataCollector></DataCollectors></DataCollectionRunSettings><RunSettingsDirectory>/app/test</RunSettingsDirectory><RunConfiguration><ResultsDirectory>/coverage/paychecks</ResultsDirectory><TargetPlatform>X64</TargetPlatform><TargetFrameworkVersion>.NETCoreApp,Version=v3.1</TargetFrameworkVersion><TestAdaptersPaths>/root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/;/root/.nuget/packages/microsoft.codecoverage/16.5.0/build/netstandard1.0/;/usr/share/dotnet/sdk/3.1.102/Extensions</TestAdaptersPaths><DesignMode>False</DesignMode><CollectSourceInformation>False</CollectSourceInformation></RunConfiguration><InProcDataCollectionRunSettings><InProcDataCollectors><InProcDataCollector assemblyQualifiedName=\"Coverlet.Collector.DataCollection.CoverletInProcDataCollector, coverlet.collector, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null\" friendlyName=\"XPlat Code Coverage\" enabled=\"True\" codebase=\"coverlet.collector.dll\" /></InProcDataCollectors></InProcDataCollectionRunSettings><LoggerRunSettings><Loggers><Logger friendlyName=\"Console\" assemblyQualifiedName=\"Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger, vstest.console, Version=15.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a\" codeBase=\"/usr/share/dotnet/sdk/3.1.102/vstest.console.dll\" enabled=\"True\"><Configuration><Verbosity>normal</Verbosity></Configuration></Logger></Loggers></LoggerRunSettings></RunSettings>",
"Sources": [
"/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/PayrollSteps.Api.Test.dll"
]
}
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.835, 40768304923678, datacollector.dll, TestPluginCache: Update extensions started. Skip filter = False
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.837, 40768306755811, datacollector.dll, TestPluginCache: Using directories for assembly resolution '/root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0,/root/.nuget/packages/microsoft.codecoverage/16.5.0/build/netstandard1.0,/usr/share/dotnet/sdk/3.1.102/Extensions'.
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.838, 40768307509053, datacollector.dll, TestPluginCache: Updated the available extensions to '/root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/coverlet.collector.dll,/root/.nuget/packages/microsoft.codecoverage/16.5.0/build/netstandard1.0/Microsoft.VisualStudio.TraceDataCollector.dll,/usr/share/dotnet/sdk/3.1.102/Extensions/Microsoft.TestPlatform.Extensions.BlameDataCollector.dll,/usr/share/dotnet/sdk/3.1.102/Extensions/Microsoft.TestPlatform.Extensions.EventLogCollector.dll'.
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.857, 40768327016204, datacollector.dll, TestPluginCache.DiscoverTestExtensions: finding test extensions in assemblies endswith: Collector.dll TPluginInfo: Microsoft.VisualStudio.TestPlatform.Common.DataCollector.DataCollectorConfig TExtension: Microsoft.VisualStudio.TestPlatform.ObjectModel.DataCollection.DataCollector
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.858, 40768328076029, datacollector.dll, TestPluginCache.GetExtensionPaths: Filtered extension paths: /root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/coverlet.collector.dll
/root/.nuget/packages/microsoft.codecoverage/16.5.0/build/netstandard1.0/Microsoft.VisualStudio.TraceDataCollector.dll
/usr/share/dotnet/sdk/3.1.102/Extensions/Microsoft.TestPlatform.Extensions.BlameDataCollector.dll
/usr/share/dotnet/sdk/3.1.102/Extensions/Microsoft.TestPlatform.Extensions.EventLogCollector.dll
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.859, 40768328734479, datacollector.dll, TestPluginCache.GetExtensionPaths: Added default extension paths:
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.860, 40768329604070, datacollector.dll, TestPluginCache.GetExtensionPaths: Added unfilterableExtensionPaths:
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.861, 40768331047070, datacollector.dll, AssemblyResolver.ctor: Creating AssemblyResolver with searchDirectories /root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0,/root/.nuget/packages/microsoft.codecoverage/16.5.0/build/netstandard1.0,/usr/share/dotnet/sdk/3.1.102/Extensions,/usr/share/dotnet/sdk/3.1.102
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.863, 40768333067704, datacollector.dll, TestPluginCache.DiscoverTestExtensions: Discovering the extensions using extension path.
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.864, 40768333983879, datacollector.dll, TestPluginCache.GetExtensionPaths: Filtered extension paths: /root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/coverlet.collector.dll
/root/.nuget/packages/microsoft.codecoverage/16.5.0/build/netstandard1.0/Microsoft.VisualStudio.TraceDataCollector.dll
/usr/share/dotnet/sdk/3.1.102/Extensions/Microsoft.TestPlatform.Extensions.BlameDataCollector.dll
/usr/share/dotnet/sdk/3.1.102/Extensions/Microsoft.TestPlatform.Extensions.EventLogCollector.dll
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.865, 40768334644496, datacollector.dll, TestPluginCache.GetExtensionPaths: Added default extension paths:
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.865, 40768335406837, datacollector.dll, TestPluginCache.GetExtensionPaths: Added unfilterableExtensionPaths:
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.866, 40768336256062, datacollector.dll, TestPluginCache.DiscoverTestExtensions: Discovering the extensions using allExtensionPaths: /root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/coverlet.collector.dll
/root/.nuget/packages/microsoft.codecoverage/16.5.0/build/netstandard1.0/Microsoft.VisualStudio.TraceDataCollector.dll
/usr/share/dotnet/sdk/3.1.102/Extensions/Microsoft.TestPlatform.Extensions.BlameDataCollector.dll
/usr/share/dotnet/sdk/3.1.102/Extensions/Microsoft.TestPlatform.Extensions.EventLogCollector.dll
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.867, 40768337212646, datacollector.dll, AssemblyResolver.AddSearchDirectories: Adding more searchDirectories /root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0,/usr/share/dotnet/sdk/3.1.102
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.868, 40768337980729, datacollector.dll, AssemblyResolver.AddSearchDirectories: Adding more searchDirectories /root/.nuget/packages/microsoft.codecoverage/16.5.0/build/netstandard1.0,/usr/share/dotnet/sdk/3.1.102
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.869, 40768338746537, datacollector.dll, AssemblyResolver.AddSearchDirectories: Adding more searchDirectories /usr/share/dotnet/sdk/3.1.102/Extensions,/usr/share/dotnet/sdk/3.1.102
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.870, 40768339597929, datacollector.dll, AssemblyResolver.AddSearchDirectories: Adding more searchDirectories /usr/share/dotnet/sdk/3.1.102/Extensions,/usr/share/dotnet/sdk/3.1.102
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.871, 40768340873554, datacollector.dll, AssemblyResolver.OnResolve: coverlet.collector: Resolving assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.872, 40768342193487, datacollector.dll, AssemblyResolver.OnResolve: Resolved assembly: coverlet.collector, from path: /root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/coverlet.collector.dll
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.873, 40768343483413, datacollector.dll, AssemblyResolver.OnResolve: coverlet.core: Resolving assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.875, 40768344691221, datacollector.dll, AssemblyResolver.OnResolve: Resolved assembly: coverlet.core, from path: /root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/coverlet.core.dll
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.877, 40768347228604, datacollector.dll, AssemblyResolver.OnResolve: Microsoft.VisualStudio.TraceDataCollector: Resolving assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.878, 40768348475521, datacollector.dll, AssemblyResolver.OnResolve: Resolved assembly: Microsoft.VisualStudio.TraceDataCollector, from path: /root/.nuget/packages/microsoft.codecoverage/16.5.0/build/netstandard1.0/Microsoft.VisualStudio.TraceDataCollector.dll
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.880, 40768350296171, datacollector.dll, AssemblyResolver.OnResolve: Microsoft.TestPlatform.Extensions.BlameDataCollector: Resolving assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.882, 40768351495638, datacollector.dll, AssemblyResolver.OnResolve: Resolved assembly: Microsoft.TestPlatform.Extensions.BlameDataCollector, from path: /usr/share/dotnet/sdk/3.1.102/Extensions/Microsoft.TestPlatform.Extensions.BlameDataCollector.dll
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.883, 40768352822613, datacollector.dll, AssemblyResolver.OnResolve: Microsoft.TestPlatform.Extensions.EventLogCollector: Resolving assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.884, 40768354027821, datacollector.dll, AssemblyResolver.OnResolve: Resolved assembly: Microsoft.TestPlatform.Extensions.EventLogCollector, from path: /usr/share/dotnet/sdk/3.1.102/Extensions/Microsoft.TestPlatform.Extensions.EventLogCollector.dll
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.886, 40768356347021, datacollector.dll, TestPluginCache: Discovered the extensions using extension path '/root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/coverlet.collector.dll,/root/.nuget/packages/microsoft.codecoverage/16.5.0/build/netstandard1.0/Microsoft.VisualStudio.TraceDataCollector.dll,/usr/share/dotnet/sdk/3.1.102/Extensions/Microsoft.TestPlatform.Extensions.BlameDataCollector.dll,/usr/share/dotnet/sdk/3.1.102/Extensions/Microsoft.TestPlatform.Extensions.EventLogCollector.dll'.
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.887, 40768357329930, datacollector.dll, TestPluginCache: Discoverers are ''.
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.888, 40768358165830, datacollector.dll, TestPluginCache: Executors are ''.
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.889, 40768359064021, datacollector.dll, TestPluginCache: Setting providers are ''.
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.890, 40768360024830, datacollector.dll, TestPluginCache: Loggers are ''.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.893, 40768362841822, datacollector.dll, TestPluginManager.CreateTestExtension: Attempting to load test extension: Coverlet.Collector.DataCollection.CoverletCoverageCollector
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.898, 40768367567863, datacollector.dll, [coverlet]Initializing CoverletCoverageDataCollector with configuration: '<Configuration><Format>lcov</Format><Exclude>[xunit*]*</Exclude><ExcludeByFile>/app/gen/Namely.*.Grpc/*</ExcludeByFile><Framework>.NETCoreApp,Version=v3.1</Framework></Configuration>'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.900, 40768369712430, datacollector.dll, [coverlet]CoverletCoverageDataCollector: SessionStart received
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.901, 40768371128239, datacollector.dll, [coverlet]CoverletCoverageDataCollector: TestModules: '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/PayrollSteps.Api.Test.dll'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.906, 40768375639455, datacollector.dll, [coverlet]CoverletCoverageDataCollector: Initializing coverlet process with settings: "TestModule: '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/PayrollSteps.Api.Test.dll', IncludeFilters: '', IncludeDirectories: '', ExcludeFilters: '[coverlet.*]*,[xunit*]*', ExcludeSourceFiles: '/app/gen/Namely.*.Grpc/*', ExcludeAttributes: '', MergeWith: '', UseSourceLink: 'False'SingleHit: 'False'IncludeTestAssembly: 'False'"
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.909, 40768379089980, datacollector.dll, AssemblyResolver.OnResolve: Microsoft.Extensions.DependencyInjection: Resolving assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.910, 40768380379581, datacollector.dll, AssemblyResolver.OnResolve: Resolved assembly: Microsoft.Extensions.DependencyInjection, from path: /root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/Microsoft.Extensions.DependencyInjection.dll
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.911, 40768381196522, datacollector.dll, AssemblyResolver.OnResolve: Microsoft.Extensions.DependencyInjection.Abstractions: Resolving assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.912, 40768382218322, datacollector.dll, AssemblyResolver.OnResolve: Resolved assembly: Microsoft.Extensions.DependencyInjection.Abstractions, from path: /root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/Microsoft.Extensions.DependencyInjection.Abstractions.dll
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.958, 40768428203007, datacollector.dll, [coverlet]Excluded module filter '[coverlet.*]*'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.959, 40768429211157, datacollector.dll, [coverlet]Excluded module filter '[xunit*]*'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.960, 40768430102416, datacollector.dll, [coverlet]Excluded source files filter '/app/gen/Namely.*.Grpc/*'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.971, 40768441266058, datacollector.dll, [coverlet]Excluded module: '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/xunit.assert.dll'
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.973, 40768443237508, datacollector.dll, AssemblyResolver.OnResolve: Microsoft.Extensions.FileSystemGlobbing: Resolving assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:53.975, 40768444569466, datacollector.dll, AssemblyResolver.OnResolve: Resolved assembly: Microsoft.Extensions.FileSystemGlobbing, from path: /root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/Microsoft.Extensions.FileSystemGlobbing.dll
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:53.999, 40768468916409, datacollector.dll, [coverlet]Unable to instrument module: /app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/Humanizer.dll, embedded pdb without local source files, [d:\a\1\s\src\Humanizer\obj\Release\netstandard2.0\Humanizer.Version.cs]
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:54.000, 40768470452792, datacollector.dll, [coverlet]Excluded module: '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/xunit.runner.utility.netcoreapp10.dll'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:54.002, 40768471754309, datacollector.dll, [coverlet]Excluded module: '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/xunit.abstractions.dll'
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:54.011, 40768481053643, datacollector.dll, AssemblyResolver.OnResolve: Mono.Cecil: Resolving assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:54.012, 40768482416801, datacollector.dll, AssemblyResolver.OnResolve: Resolved assembly: Mono.Cecil, from path: /root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/Mono.Cecil.dll
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:54.033, 40768503237277, datacollector.dll, AssemblyResolver.OnResolve: Microsoft.Extensions.DependencyModel: Resolving assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:54.035, 40768504833135, datacollector.dll, AssemblyResolver.OnResolve: Resolved assembly: Microsoft.Extensions.DependencyModel, from path: /root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/Microsoft.Extensions.DependencyModel.dll
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:54.143, 40768613189439, datacollector.dll, AssemblyResolver.OnResolve: Mono.Cecil.Rocks: Resolving assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:54.145, 40768614820397, datacollector.dll, AssemblyResolver.OnResolve: Resolved assembly: Mono.Cecil.Rocks, from path: /root/.nuget/packages/coverlet.collector/1.2.0/build/netstandard1.0/Mono.Cecil.Rocks.dll
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.165, 40770635274945, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.Uploads.Grpc/ServiceGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.167, 40770636896370, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.TaxParams.Grpc/TaxParamsGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.167, 40770637483320, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.Releaseflags.Grpc/ServiceGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.168, 40770638125412, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.Proration.Grpc/ServiceGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.169, 40770638624287, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.PdfFormGeneration.Grpc/PdfFormGenerationGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.169, 40770639344921, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.PayrollProcessingDispatcher.Grpc/PayrollProcessingDispatcherGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.170, 40770639964479, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.Payroll.Grpc/ServiceGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.171, 40770640594329, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.Hcm.Grpc/ServiceGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.171, 40770641371621, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.Employment.Grpc/EmploymentReaderServiceGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.172, 40770641979479, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.Employment.Grpc/EmploymentWriterServiceGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.173, 40770642509229, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.Compensation.Grpc/ServiceGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.173, 40770643196062, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.Companies.Grpc/ServiceGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.174, 40770643755496, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.AddressValidator.Grpc/AddressValidatorGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.174, 40770644337571, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.Address.Grpc/ServiceGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.175, 40770644967637, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.Deductions.Grpc/DeductionsGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.176, 40770645934621, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.Paycycles.Grpc/ServiceGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.177, 40770646526554, datacollector.dll, [coverlet]Excluded source file: '/app/gen/Namely.PayCyclesConfiguration.Grpc/ServiceGrpc.cs'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.177, 40770647420412, datacollector.dll, [coverlet]Instrumented module: '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/PayrollSteps.Core.dll'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.180, 40770649824113, datacollector.dll, [coverlet]Unable to instrument module: /app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/Pipelines.Sockets.Unofficial.dll, embedded pdb without local source files, [C:\Code\Pipelines.Sockets.Unofficial\src\Pipelines.Sockets.Unofficial\ConnectionAbortedException.cs]
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.182, 40770651876921, datacollector.dll, [coverlet]Unable to instrument module: /app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/Dapper.dll, embedded pdb without local source files, [C:\projects\dapper\Dapper\obj\Release\netstandard2.0\Dapper.Version.cs]
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.211, 40770681035814, datacollector.dll, [coverlet]Excluded module: '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/xunit.execution.dotnet.dll'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.212, 40770682471772, datacollector.dll, [coverlet]Unable to instrument module: /app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/System.Interactive.Async.dll, embedded pdb without local source files, [D:\a\1\s\Ix.NET\Source\System.Interactive.Async\TaskExt.cs]
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.213, 40770683360430, datacollector.dll, [coverlet]Excluded module: '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/xunit.runner.reporters.netcoreapp10.dll'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.214, 40770684247247, datacollector.dll, [coverlet]Excluded module: '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/xunit.core.dll'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.218, 40770687554881, datacollector.dll, [coverlet]Unable to instrument module: /app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/StackExchange.Redis.dll, embedded pdb without local source files, [C:\projects\stackexchange-redis\src\StackExchange.Redis\BufferReader.cs]
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:56.219, 40770688754131, datacollector.dll, [coverlet]Excluded module: '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/xunit.runner.visualstudio.dotnetcore.testadapter.dll'
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:07:57.093, 40771563039587, datacollector.dll, [coverlet]Instrumented module: '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/Namely.PayCyclesConfiguration.Shared.dll'
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:57.101, 40771571178779, datacollector.dll, DataCollectionRequestHandler.ProcessRequests : DataCollection started.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:07:57.192, 40771661734182, datacollector.dll, DataCollectionRequestHandler.ProcessRequests : Datacollector received message: (DataCollection.TestHostLaunched) -> {
"ProcessId": 80
}
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:17:28.144, 41342614504818, datacollector.dll, DataCollectionRequestHandler.ProcessRequests : Datacollector received message: (DataCollection.AfterTestRunEnd) -> false
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:17:28.153, 41342622719843, datacollector.dll, [coverlet]CoverletCoverageDataCollector: SessionEnd received
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:17:28.175, 41342644687785, datacollector.dll, AssemblyResolver.OnResolve: coverlet.collector.resources: Resolving assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:17:28.176, 41342645961243, datacollector.dll, AssemblyResolver.OnResolve: coverlet.collector.resources: Failed to load assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:17:28.177, 41342647125393, datacollector.dll, AssemblyResolver.OnResolve: coverlet.collector.resources: Resolving assembly.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:17:28.178, 41342647928576, datacollector.dll, AssemblyResolver.OnResolve: coverlet.collector.resources: Resolved from cache.
TpTrace Warning: 0 : 61, 1, 2020/02/20, 06:17:28.191, 41342661101693, datacollector.dll, Data collector 'datacollector://microsoft/CoverletCodeCoverage/1.0' logged the following warning: [coverlet]Coverlet.Collector.Utilities.CoverletDataCollectorException: CoverletCoverageDataCollector: Failed to get coverage result
---> System.IO.IOException: The process cannot access the file '/tmp/PayrollSteps.Core_5073676f-963e-4708-b743-93afbcfe1425' 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
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:17:28.195, 41342664821210, datacollector.dll, [coverlet]CoverletCoverageDataCollector: Disposing
TpTrace Error: 0 : 61, 1, 2020/02/20, 06:17:28.199, 41342669248902, datacollector.dll, DataCollectionAttachmentManager.GetAttachments: Fail to get attachments: System.Collections.Generic.KeyNotFoundException: The given key 'Microsoft.VisualStudio.TestPlatform.ObjectModel.DataCollection.DataCollectionContext' was not present in the dictionary.
at System.Collections.Generic.Dictionary`2.get_Item(TKey key)
at Microsoft.VisualStudio.TestPlatform.Common.DataCollector.DataCollectionAttachmentManager.GetAttachments(DataCollectionContext dataCollectionContext)
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:17:28.200, 41342670445552, datacollector.dll, DataCollectionManager.CleanupPlugins: CleanupPlugins called
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:17:28.201, 41342671418493, datacollector.dll, DataCollectionManager.CleanupPlugins: Cleaning up 1 plugins
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:17:28.203, 41342673476068, datacollector.dll, dataCollectorInfo.DisposeDataCollector: calling Dispose() on Coverlet.Collector.DataCollection.CoverletCoverageCollector
TpTrace Verbose: 0 : 61, 1, 2020/02/20, 06:17:28.204, 41342674313052, datacollector.dll, [coverlet]CoverletCoverageDataCollector: Disposing
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:17:28.206, 41342675651077, datacollector.dll, DataCollectionManager.CleanupPlugins: CleanupPlugins finished
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:17:28.215, 41342684807085, datacollector.dll, DataCollectionRequestHandler.ProcessRequests : Session End message received from server. Closing the connection.
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:17:28.238, 41342708288552, datacollector.dll, Closing the connection !
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:17:28.240, 41342710045285, datacollector.dll, DataCollectionRequestHandler.ProcessRequests : DataCollection completed
TpTrace Information: 0 : 61, 1, 2020/02/20, 06:17:28.241, 41342711259810, datacollector.dll, Program.Main: exiting datacollector process.
TpTrace Information: 0 : 61, 20, 2020/02/20, 06:17:28.417, 41342886959036, datacollector.dll, DataCollector: ParentProcess '48' Exited.
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 I added them to this gist: https://gist.github.com/abe545/892b1183ec15b22cc5df80cc7d70652d
I didn't spot any other references to that hits file than the exceptions, but maybe I don't know what I'm actually looking for.
I'm working on getting the tracker hits now
Okay, I updated the gist with the tracker files. Looks like the tracker is trying to unload the dll 2 times, and the second time is where it is failing to write the hits file:
[2/20/2020 9:23:23 AM 4]Unload called for '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/PayrollSteps.Core.dll'
[2/20/2020 9:23:23 AM 4]Flushing hit file '/tmp/PayrollSteps.Core_c4f6b0d8-8eb6-4cfe-9812-1d1f875d5b77'
[2/20/2020 9:23:23 AM 4]Hit file '/tmp/PayrollSteps.Core_c4f6b0d8-8eb6-4cfe-9812-1d1f875d5b77' flushed, size 246000
[2/20/2020 9:23:23 AM 2]Unload called for '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/PayrollSteps.Core.dll'
[2/20/2020 9:23:23 AM 2]Flushing hit file '/tmp/PayrollSteps.Core_c4f6b0d8-8eb6-4cfe-9812-1d1f875d5b77'
@abe545 can you try to generate same log with master version?I added process id to tracker log on master https://github.com/tonerdo/coverlet/blob/master/src/coverlet.core/Instrumentation/ModuleTrackerTemplate.cs#L186
So we can be sure that there is "another" process that unloads lib and not another thread of same process.
This is the guide for nightly https://github.com/tonerdo/coverlet/blob/master/Documentation/ConsumeNightlyBuild.md
Thank's a lot for you help on debugging this issue...without a repro or a complete source is complex....you can also try to attach live to understand from where that dll is loaded, if it's shared between two process...but I don't know if works inside a container https://github.com/tonerdo/coverlet/blob/master/Documentation/Troubleshooting.md#enable-collector-instrumentation-debugging
I expect more than one unload for a multidomain process(.net framework)...but you're on core and domain does not exists.
@MarcoRossignoli I'll give it a shot. And thank you for all your help with this! I really did try to create a repro that I could share, but unfortunately was unable to isolate it. I'm sure it is something funky we're doing in some of these tests, as it doesn't happen in some filtered test runs, always happens in others, and occasionally happens in still more.
@MarcoRossignoli this is the hits file after using the nightly:
[2/20/2020 4:48:53 PM P:74 T:5]Unload called for '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/PayrollSteps.Core.dll'
[2/20/2020 4:48:53 PM P:74 T:5]Flushing hit file '/tmp/PayrollSteps.Core_fbfbf202-a9ad-417b-b813-696d7a409356'
[2/20/2020 4:48:53 PM P:74 T:5]Hit file '/tmp/PayrollSteps.Core_fbfbf202-a9ad-417b-b813-696d7a409356' flushed, size 245736
[2/20/2020 4:48:53 PM P:74 T:2]Unload called for '/app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/PayrollSteps.Core.dll'
[2/20/2020 4:48:53 PM P:74 T:2]Flushing hit file '/tmp/PayrollSteps.Core_fbfbf202-a9ad-417b-b813-696d7a409356'
[2/20/2020 4:48:53 PM P:74 T:2]Failed to create new hits file '/tmp/PayrollSteps.Core_fbfbf202-a9ad-417b-b813-696d7a409356'
System.IO.IOException: The file '/tmp/PayrollSteps.Core_fbfbf202-a9ad-417b-b813-696d7a409356' already exists.
at Interop.ThrowExceptionForIoErrno(ErrorInfo errorInfo, String path, Boolean isDirectory, Func`2 errorRewriter)
at Microsoft.Win32.SafeHandles.SafeFileHandle.Open(String path, OpenFlags flags, Int32 mode)
at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options)
at Coverlet.Core.Instrumentation.Tracker.PayrollSteps.Core_fbfbf202-a9ad-417b-b813-696d7a409356.UnloadModule(Object , EventArgs )
[2/20/2020 4:48:53 PM P:74 T:2]Current hits found '61433'
If I understand this correctly, it is 2 different threads in the same process trying to write the file?
@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:
1) out proc collector call inproc collector that run unload
2) out of proc collector call CalculateCoverage and access to hit file
3) 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
Okay, so the result is that that the error is still in the hits file (this makes sense), but then it bombs with:
System.Threading.AbandonedMutexException: The wait completed due to an abandoned mutex.
at System.Threading.WaitHandle.WaitOneNoCheck(Int32 millisecondsTimeout)
at System.Threading.WaitHandle.WaitOne()
at Coverlet.Core.Coverage.CalculateCoverage() in C:\code\coverlet\src\coverlet.core\Coverage.cs:line 333
at Coverlet.Core.Coverage.GetCoverageResult() in C:\code\coverlet\src\coverlet.core\Coverage.cs:line 136
at Coverlet.Collector.DataCollection.CoverageWrapper.GetCoverageResult(Coverage coverage) in C:\code\coverlet\src\coverlet.collector\DataCollection\CoverageWrapper.cs:line 44
at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in C:\code\coverlet\src\coverlet.collector\DataCollection\CoverageManager.cs:line 91 --- End of inner exception stack trace ---
at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in C:\code\coverlet\src\coverlet.collector\DataCollection\CoverageManager.cs:line 96 at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageReports() in C:\code\coverlet\src\coverlet.collector\DataCollection\CoverageManager.cs:line 79 at Coverlet.Collector.DataCollection.CoverletCoverageCollector.OnSessionEnd(Object sender, SessionEndEventArgs e) in C:\code\coverlet\src\coverlet.collector\DataCollection\CoverletCoverageCollector.cs:line 148.
I'm going to mess around with coverlet locally to see if I can output better errors, now that I have it setup to use the locally packed nuget.
So seem the issue is not tracker vs getcoverage the mutex is out of finally on purpose, another test to definitely understand if it's a Coverlet issue(coverlet self lock files) is to remove the subscription to appdomain a appexit in tracker, so only collector will call unload and we will sure that there is "another process"(out of mutex lock) that for some reason lock file (mutex should synchronize all processes that touch that hit file)
The other thing I saw was this in the main log file:
TpTrace Verbose: 0 : 44, 13, 2020/02/21, 01:14:27.708, 109562178304076, vstest.console.dll, TestRequestSender.EndSession: Sending end session.
TpTrace Warning: 0 : 44, 13, 2020/02/21, 01:14:27.809, 109562279409188, vstest.console.dll, ProxyOperationManager: Timed out waiting for test host to exit. Will terminate process.
Any idea how long it waits? Looks like 100ms?
So I added more logging, and the block of code that fails to complete is this:
https://github.com/tonerdo/coverlet/blob/master/src/coverlet.core/Instrumentation/ModuleTrackerTemplate.cs#L111-L138
In my tests, it is trying to update a file with 61,433 entries, and I guess that is taking longer than the test runner is willing to wait?
I'm going to try it without the AppDomain.CurrentDomain.DomainUnload handler, and I'll report back.
@MarcoRossignoli so not registering the DomainUnload event handler did not change anything.
However, not registering the ProcessExit event handler solved the problem. The coverage file was written successfully, and I think it is fully populated (tbh I don't have a way to tell for sure, as I don't really know what I'm looking at).
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.
@MarcoRossignoli so not registering the DomainUnload event handler did not change anything.
However, not registering the ProcessExit event handler solved the problem. The coverage file was written successfully, and I think it is fully populated (tbh I don't have a way to tell for sure, as I don't really know what I'm looking at).
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.
@MarcoRossignoli so not registering the DomainUnload event handler did not change anything.
Expected...we're on .net core
However, not registering the ProcessExit event handler solved the problem.
Expected in part...file is flushed when inproc collector is called and second time when process exit(thank's to subscribe) but it's unexpected that GetCoverage fails if I'm in synch between process/threads(mutex)...my branch test should resolve that
Any idea how long it waits? Looks like 100ms?
@abe545 if you're using collector timeout it's not an issue...was an issue on msbuild/.net tool, we added collector use for THAT specific problem...and yes host process is killed when tests ends after 100millisecond if it doesn't return to "parent" process.
https://github.com/tonerdo/coverlet/blob/master/Documentation/KnownIssues.md#1-vstest-stops-process-execution-earlydotnet-test read all this issue and you'll find vstest team explanation.
So if you use a collector Unload(write hits) will be surely done before process kill because workflow of vstest is
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:
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?
@abe545 can you retry with this new version https://github.com/MarcoRossignoli/coverlet/tree/issue_736 (fetch,pull,re-pack)?
@MarcoRossignoli so I'm still using your branch (with additional logging that I added), so I'm not sure what you'd like me to try. The mutex has not yet been released when we try to acquire it in the ModuleTrackerTemplate.UnloadModule - which is called 2x for some reason.
I'm using the collector, so the 100ms timeout is still clearly an issue in my setup, as the code in the Coverage.CalculateCoverage is taking > 100ms to re-write the file. I added log statements that occur every 100 iterations of the collector that writes the hits file, and it got through 14,800 before it stops logging, and coverlet reports this error in the main log + on the command line:
Data collector 'XPlat code coverage' message: [coverlet]Coverlet.Collector.Utilities.CoverletDataCollectorException: CoverletCoverageDataCollector: Failed to get coverage result
---> System.Threading.AbandonedMutexException: The wait completed due to an abandoned mutex.
at System.Threading.WaitHandle.WaitOneNoCheck(Int32 millisecondsTimeout)
at System.Threading.WaitHandle.WaitOne()
at Coverlet.Core.Coverage.CalculateCoverage() in C:\code\coverlet\src\coverlet.core\Coverage.cs:line 333
at Coverlet.Core.Coverage.GetCoverageResult() in C:\code\coverlet\src\coverlet.core\Coverage.cs:line 136
at Coverlet.Collector.DataCollection.CoverageWrapper.GetCoverageResult(Coverage coverage) in C:\code\coverlet\src\coverlet.collector\DataCollection\CoverageWrapper.cs:line 44
at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in C:\code\coverlet\src\coverlet.collector\DataCollection\CoverageManager.cs:line 91 --- End of inner exception stack trace ---
at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in C:\code\coverlet\src\coverlet.collector\DataCollection\CoverageManager.cs:line 96 at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageReports() in C:\code\coverlet\src\coverlet.collector\DataCollection\CoverageManager.cs:line 79 at Coverlet.Collector.DataCollection.CoverletCoverageCollector.OnSessionEnd(Object sender, SessionEndEventArgs e) in C:\code\coverlet\src\coverlet.collector\DataCollection\CoverletCoverageCollector.cs:line 148.
Sorry, ran this/wrote my comment between your two comments. I'll try with the above.
No worries, let me know
@MarcoRossignoli so the runner exited successfully, and generated the coverage. I do still see this in logs, which is suspicious to me if the in proc collector is supposed to be allowed to finish:
TpTrace Verbose: 0 : 44, 12, 2020/02/21, 07:23:46.349, 131720818729739, vstest.console.dll, TestRequestSender.EndSession: Sending end session.
TpTrace Warning: 0 : 44, 12, 2020/02/21, 07:23:46.451, 131720921195084, vstest.console.dll, ProxyOperationManager: Timed out waiting for test host to exit. Will terminate process.
Actually is a "log bug" inside vstest to me...that log is always emitted...it doesn't check if event was signaled or not
cc: @nohwnd
@abe545 can you attach tracker logs?
@abe545 can you attach tracker logs?
@MarcoRossignoli here you go: https://gist.github.com/abe545/1056bb31a23b550d9d545544f3716639
I mean set COVERLET_ENABLETRACKERLOG=1 and attach file
I mean set
COVERLET_ENABLETRACKERLOG=1and attach file
These logs were generated with that environment variable set to that value. Is there a specific file you're looking for?
This is the relevant part of my docker-compose.yml I used to run the tests, and get the logs out:
test-paychecks:
build:
context: .
entrypoint: /bin/bash -c
command: [
"dotnet test /app/test/PayrollSteps.Api.Test/PayrollSteps.Api.Test.csproj --configuration Release --no-build -v n --collect:\"XPlat Code Coverage\" --settings /app/test/coverlet.runsettings -r /coverage/paychecks --filter \"Feature=paychecks\" --diag:log-paychecks.txt ; cp /app/test/PayrollSteps.Api.Test/bin/Release/netcoreapp3.1/*.txt /app/trackerhits"
]
environment:
COVERLET_ENABLETRACKERLOG: "1"
volumes:
- ./coverage/paychecks:/coverage/paychecks
- ./coverletlogs:/app/coverletlogs/
- ./coverletlogs/trackerhits:/app/trackerhits
A note about the dockerfile - we build it in release mode in a previous stage, so we can use --no-build --verbosity Normal (-v n above) so we get more information about the test run.
Re-reading the documentation for that env var, I'm guessing you're looking for a file in the TrackerHitsLog folder. I'll try to get it out of the container.
I'd like to see the log message for tracker to be sure you're using patched version...should see this log https://github.com/MarcoRossignoli/coverlet/blob/issue_736/src/coverlet.core/Instrumentation/ModuleTrackerTemplate.cs#L112 with flush type InProcessCollectorFlush
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
Since I built this locally from your branch, I did update the logger to output the time in a more verbose manner:
File.AppendAllText(Path.Combine(Path.GetDirectoryName(location), Path.GetFileName(location) + "_tracker.txt"), $"[{DateTime.UtcNow.ToString("o")} P:{Process.GetCurrentProcess().Id} T:{Thread.CurrentThread.ManagedThreadId}]{logText}{Environment.NewLine}");
Ah, @MarcoRossignoli that was in the gist
Ah ok missed that so it seems to work...do you see error or the fix seem a good idea?
I don't see any errors anymore. As far as I can tell, this fixes the issues I'm having. Thanks again for your help!
If you still would like a repro, I think I could do it by generating a very large file (on the order of 20K lines) of meaningless code that is executed under a test... That should result in the same behavior of the file being written 2x, and the second taking > 100ms
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 I've been able to partially reproduce this issue in a dummy repo - ultimately coverlet succeeds in this project, so I'm not sure if it is useful. It produces the following behavior:
Like I said, I'm not sure how useful this is since coverlet finishes successfully, but let me know if you'd like me to share it.
Put here the link and feel free to stop to invest time you did a lot of test and I don't want to "take" your time more than this...we understood the issue, now I need only to understand if remove process exit for collector is a good idea or not...because today we have a lot of user that upgrades to for instance collector 1.2.0 but doesn't upgrade test sdk...with the fix this lead to "no hit files generated"(https://github.com/tonerdo/coverlet/blob/master/Documentation/KnownIssues.md#2-upgrade-coverletcollector-to-version--100).
I need to understand if it's good or not(with process exits we have always a generated file, even if it's not "expected").
Thank's a lot for all your support!
I really appreciate your help @MarcoRossignoli! Here is the repository: https://github.com/namely/CoverletErrorRepro
Thanks!
@MarcoRossignoli I was just thinking about this - what if the file wasn't generated if it already exists? Right now, if the file doesn't exist, it will be rewritten one line at a time, and this seems particularly slow. I'm not entirely sure if I'm correct with this assumption, but it seems like that is just re-writing the data that already exists in the file... If it doesn't open the hits file to rewrite it, I'm pretty sure it would fix my issue. In fact, I'm going to try that tomorrow morning, and I'll get back to you if it works.
I'm not entirely sure if I'm correct with this assumption
At the moment file is created if doesn't exists under a mutex https://github.com/tonerdo/coverlet/blob/master/src/coverlet.core/Instrumentation/ModuleTrackerTemplate.cs#L86
But if file exists the new hit is "added" to existing files. This is needed because we could have more than one app domain(on .net framework) so we need to keep this behaviour(if I understood well what you mean).
I'm not entirely sure if I'm correct with this assumption
At the moment file is created if doesn't exists under a mutex https://github.com/tonerdo/coverlet/blob/master/src/coverlet.core/Instrumentation/ModuleTrackerTemplate.cs#L86
But if file exists the new hit is "added" to existing files. This is needed because we could have more than one app domain(on .net framework) so we need to keep this behaviour(if I understood well what you mean).
If it is only needed for the full framework, we could skip it for .net core? And sorry, I didn't have time to test it yesterday, but will hopefully get a chance today.
If it is only needed for the full framework, we could skip it for .net core? And sorry, I didn't have time to test it yesterday, but will hopefully get a chance today.
We should/could...and this is a concern to me...until today we did't differentiate two run-times...indeed my patch does that if you take a look.
So if something goes wrong here(and we have only test that cover .net core use cases) will be a pain for users.
@MarcoRossignoli We are seeing the same issue in dotnet/runtime locally:
coverlet.collectors: 1.2.1
Microsoft.NET.Test.Sdk: 16.7.0-preview-20200429-01
C:\git\runtime4\src\libraries\System.Text.RegularExpressions\tests>dotnet test -f netcoreapp5.0 /p:Coverage=true
Microsoft (R) Build Engine version 16.7.0-preview-20251-04+8e4c57314 for .NET
Copyright (C) Microsoft Corporation. All rights reserved.
Determining projects to restore...
All projects are up-to-date for restore.
TestUtilities -> C:\git\runtime4\artifacts\bin\TestUtilities\netcoreapp5.0-Debug\TestUtilities.dll
System.Text.RegularExpressions.Tests -> C:\git\runtime4\artifacts\bin\System.Text.RegularExpressions.Tests\netcoreapp5.0-Debug\System.Text.RegularExpressions.Tests.dll
Test run for C:\git\runtime4\artifacts\bin\System.Text.RegularExpressions.Tests\netcoreapp5.0-Debug\System.Text.RegularExpressions.Tests.dll(.NETCoreApp,Version=v5.0)
Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
[xUnit.net 00:00:01.27] System.Text.RegularExpressions.Tests: Non-serializable data ('System.Object[]') found for 'System.Text.RegularExpressions.Tests.RegexConstructorTests.Ctor'; falling back to single test case.
[xUnit.net 00:00:01.41] System.Text.RegularExpressions.Tests: Non-serializable data ('System.Object[]') found for 'System.Text.RegularExpressions.Tests.RegexMatchTests.Match_Advanced'; falling back to single test case.
[xUnit.net 00:00:01.42] System.Text.RegularExpressions.Tests: Non-serializable data ('System.Object[]') found for 'System.Text.RegularExpressions.Tests.RegexMultipleMatchTests.Matches'; falling back to single test case.
[xUnit.net 00:00:01.44] System.Text.RegularExpressions.Tests: Non-serializable data ('System.Object[]') found for 'System.Text.RegularExpressions.Tests.RegexReplaceTests.Replace_MatchEvaluator_Test'; falling back to single test case.
[xUnit.net 00:00:01.64] System.Text.RegularExpressions.Tests: Non-serializable data ('System.Object[]') found for 'System.Text.RegularExpressions.Tests.RegexCompilationInfoTests.Ctor_ValidArguments_CheckProperties'; falling back to single test case.
[xUnit.net 00:00:01.64] System.Text.RegularExpressions.Tests: Non-serializable data ('System.Object[]') found for 'System.Text.RegularExpressions.Tests.RegexCompilationInfoTests.MatchTimeout_GetSet_Throws'; falling back to single test case.
[xUnit.net 00:00:01.64] System.Text.RegularExpressions.Tests: Non-serializable data ('System.Object[]') found for 'System.Text.RegularExpressions.Tests.RegexCompilationInfoTests.MatchTimeout_GetSet_Success'; falling back to single test case.
[xUnit.net 00:00:16.24] System.Text.RegularExpressions.Tests: Skipping test case with duplicate ID 'b980efc2e49199eb1830a54425d556e93546291a' ('System.Text.RegularExpressions.Tests.RegexGroupTests.Groups(cultureName: null, pattern: "(cat)(\\c[*)(dog)", input: "asdlkcat\x1bdogiwod", options: None, expectedGroups: ["cat\x1bdog", "cat", "\x1b", "dog"])' and 'System.Text.RegularExpressions.Tests.RegexGroupTests.Groups(cultureName: null, pattern: "(cat)(\\c[*)(dog)", input: "asdlkcat\x1bdogiwod", options: None, expectedGroups: ["cat\x1bdog", "cat", "\x1b", "dog"])')
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 'C:\Users\vihofer\AppData\Local\Temp\System.Text.RegularExpressions_31d2b5e9-3002-4998-bb30-3bd531e6090c' because it is being used by another process.
at System.IO.FileStream.ValidateFileHandle(SafeFileHandle fileHandle)
at System.IO.FileStream.CreateFileOpenHandle(FileMode mode, FileShare share, FileOptions options)
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 c:\git\coverletToRelease\src\coverlet.core\Helpers\FileSystem.cs:line 43
at Coverlet.Core.Coverage.CalculateCoverage() in c:\git\coverletToRelease\src\coverlet.core\Coverage.cs:line 352
at Coverlet.Core.Coverage.GetCoverageResult() in c:\git\coverletToRelease\src\coverlet.core\Coverage.cs:line 135
at Coverlet.Collector.DataCollection.CoverageWrapper.GetCoverageResult(Coverage coverage) in c:\git\coverletToRelease\src\coverlet.collector\DataCollection\CoverageWrapper.cs:line 44
at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in c:\git\coverletToRelease\src\coverlet.collector\DataCollection\CoverageManager.cs:line 91
--- End of inner exception stack trace ---
at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in c:\git\coverletToRelease\src\coverlet.collector\DataCollection\CoverageManager.cs:line 96
at Coverlet.Collector.DataCollection.CoverletCoverageCollector.OnSessionEnd(Object sender, SessionEndEventArgs e) in c:\git\coverletToRelease\src\coverlet.collector\DataCollection\CoverletCoverageCollector.cs:line 153.
Results File: C:\git\runtime4\artifacts\bin\System.Text.RegularExpressions.Tests\netcoreapp5.0-Debug\TestResults\vihofer_DESKTOP-803H9R0_2020-05-05_11_24_34.trx
Html test results file : C:\git\runtime4\artifacts\bin\System.Text.RegularExpressions.Tests\netcoreapp5.0-Debug\TestResults\TestResult_vihofer_DESKTOP-803H9R0_20200505_112454.html
cc @nohwnd in case this is data collector VSTest related.
cc @nohwnd in case this is data collector VSTest related.
Not I know where is the problem, happened very few time, there is a race related to process exit of test host and get coverage result of out of proc collector
Where would be the right place to fix the race? In VSTest or here in coverlet?
Coverlet for what I understood
I've an idea non too invasive fix in mind, I'll try asap.
TL; DR;
When collectors was created we didn't take into account the ProcessExit callback. So sometime happens that in proc collector flush and meanwhile out of proc one try to load hits file and process exits of host process re-flush the file and so race.
We need to add a flag to tracker like flush and when in proc collector flush set this flag to false, this flag will be evaluated during process exists, or something like that.
Just to let you guys know, I have had similar problems (on windows) and traced them back to McAfee Endpoint Security 10.7. After uninstalling McAfee, everything went well. Also a downgrade to McAfee 10.6 should do the trick, will let you know when I can confirm that.
Edit: Also McAfee 10.6 seems to block coverlet most of the time. Not recompiling and executing the tests a few times seems to help. As I am probably unable to get rid of McAfee, I will settle for report generation within the CI chain that runs elsewhere and doesn't have that problem.
That could be another reason thanks.