Avoid double flush hit files for collectors #835

MarcoRossignoli · 2020-05-05T15:07:16Z

Fixes #736

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 when process exits of host process re-flush the file and so invalid concurrent access.
This PR add a boolean field called FlushHitFile default true that will be set to false after in process collector flush. This new field is used inside UnloadModule , in case of collectors usage we won't have double flush due to process exits callback.

In my local test with tracking log enabled works as expected

Log before

DummyApp.dll_tracker_flushOnProcessExits.txt

Log after

DummyApp.dll_tracker_newVersion.txt

This is also compatible with netfx app domains, btw at the moment collectors does not support netfx.

cc: @ViktorHofer @abe545 @tonerdo

MarcoRossignoli · 2020-05-05T15:10:20Z

We're in the middle of repo move we don't have CI yet...I'd like to wait to merge. But if someone wants clone pack and test package could be great.

ViktorHofer · 2020-05-06T12:28:17Z

Just built this locally and tried it out in dotnet/runtime and now I get IOExceptions constantly on every run:

C:\git\runtime4\src\libraries\System.Text.RegularExpressions\tests>dotnet test -f net5.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\net5.0-Debug\TestUtilities.dll
  System.Text.RegularExpressions.Tests -> C:\git\runtime4\artifacts\bin\System.Text.RegularExpressions.Tests\net5.0-Debug\System.Text.RegularExpressions.Tests.dll
Test run for C:\git\runtime4\artifacts\bin\System.Text.RegularExpressions.Tests\net5.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.
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_9b555172-552d-4028-bbee-e85c706e6ab0' 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\coverlet\src\coverlet.core\Helpers\FileSystem.cs:line 43
   at Coverlet.Core.Coverage.CalculateCoverage() in C:\git\coverlet\src\coverlet.core\Coverage.cs:line 356
   at Coverlet.Core.Coverage.GetCoverageResult() in C:\git\coverlet\src\coverlet.core\Coverage.cs:line 139
   at Coverlet.Collector.DataCollection.CoverageWrapper.GetCoverageResult(Coverage coverage) in C:\git\coverlet\src\coverlet.collector\DataCollection\CoverageWrapper.cs:line 45
   at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in C:\git\coverlet\src\coverlet.collector\DataCollection\CoverageManager.cs:line 93
   --- End of inner exception stack trace ---
   at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in C:\git\coverlet\src\coverlet.collector\DataCollection\CoverageManager.cs:line 98
   at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageReports() in C:\git\coverlet\src\coverlet.collector\DataCollection\CoverageManager.cs:line 81
   at Coverlet.Collector.DataCollection.CoverletCoverageCollector.OnSessionEnd(Object sender, SessionEndEventArgs e) in C:\git\coverlet\src\coverlet.collector\DataCollection\CoverletCoverageCollector.cs:line 161.
Results File: C:\git\runtime4\artifacts\bin\System.Text.RegularExpressions.Tests\net5.0-Debug\TestResults\vihofer_DESKTOP-803H9R0_2020-05-06_14_26_34.trx
Html test results file : C:\git\runtime4\artifacts\bin\System.Text.RegularExpressions.Tests\net5.0-Debug\TestResults\TestResult_vihofer_DESKTOP-803H9R0_20200506_142650.html

Test Run Successful.
Total tests: 7260
     Passed: 7260
 Total time: 17.3856 Seconds

MarcoRossignoli · 2020-05-06T13:27:15Z

Can you enable tracker logs it's not expected(if dll is used only by one session) https://github.com/coverlet-coverage/coverlet/blob/master/Documentation/Troubleshooting.md#enable-injected-tracker-log

ViktorHofer · 2020-05-06T14:48:14Z

Ok the crashes don't repro for me anymore...

Anyway here are the hitlogs:
TrackersHitsLog.zip

MarcoRossignoli · 2020-05-06T14:49:56Z

I need also the file near System.Text.RegularExpressions.dll called System.Text.RegularExpressions.dll_tracker.txt

ViktorHofer · 2020-05-06T14:53:33Z

Sure: System.Text.RegularExpressions.dll_tracker.txt

Actually the issue happened again for that run:

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_43350368-ef90-4e34-b68d-e3eba011120a' 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\coverlet\src\coverlet.core\Helpers\FileSystem.cs:line 43
   at Coverlet.Core.Coverage.CalculateCoverage() in C:\git\coverlet\src\coverlet.core\Coverage.cs:line 356
   at Coverlet.Core.Coverage.GetCoverageResult() in C:\git\coverlet\src\coverlet.core\Coverage.cs:line 139
   at Coverlet.Collector.DataCollection.CoverageWrapper.GetCoverageResult(Coverage coverage) in C:\git\coverlet\src\coverlet.collector\DataCollection\CoverageWrapper.cs:line 45
   at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in C:\git\coverlet\src\coverlet.collector\DataCollection\CoverageManager.cs:line 93
   --- End of inner exception stack trace ---
   at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageResult() in C:\git\coverlet\src\coverlet.collector\DataCollection\CoverageManager.cs:line 98
   at Coverlet.Collector.DataCollection.CoverageManager.GetCoverageReports() in C:\git\coverlet\src\coverlet.collector\DataCollection\CoverageManager.cs:line 81
   at Coverlet.Collector.DataCollection.CoverletCoverageCollector.OnSessionEnd(Object sender, SessionEndEventArgs e) in C:\git\coverlet\src\coverlet.collector\DataCollection\CoverletCoverageCollector.cs:line 161.

MarcoRossignoli · 2020-05-06T19:08:51Z

@ViktorHofer I cloned fresh repo of dotnet/runtime and ran

c:\git\runtime (master -> origin)
λ dotnet test -f net5.0 /p:Coverage=true src\libraries\System.Text.RegularExpressions\tests\

Updated Nuget.config and Versions.props with my local(I see nuget package copied on my local cache as expected) and enabled set COVERLET_ENABLETRACKERLOG=1 but I cannot get tracker logging, can you tell me how to verify that I'm using collectors?

ViktorHofer · 2020-05-06T19:13:29Z

These files are in the include directory which should be under artifacts/bin/testhost/net5.0.../shared/.../

MarcoRossignoli · 2020-05-06T19:44:25Z

no luck, maybe something related to env vars setup(did test with another project and it works on another console)?

ViktorHofer · 2020-05-06T20:25:07Z

Try add the env var here: https://github.com/dotnet/runtime/blob/5abde010ed0a53f196bba11cd18e839e9a0ce5fa/eng/testing/.runsettings#L21 and rebuild the test project.

tonerdo · 2020-05-07T23:23:48Z

/azp run

azure-pipelines · 2020-05-07T23:23:56Z

Azure Pipelines successfully started running 1 pipeline(s).

MarcoRossignoli · 2020-05-08T07:43:19Z

/azp run

azure-pipelines · 2020-05-08T07:43:28Z

Azure Pipelines successfully started running 1 pipeline(s).

ViktorHofer · 2020-05-08T10:08:20Z

@MarcoRossignoli wasn't the error before you re-run the actual error that you are trying to fix with this?

MarcoRossignoli · 2020-05-08T11:46:41Z

Yes I have to investigate doesn't make sense, msbuild should not use that new flag, so I need to understand who is locking file and if we're locking ourselves

MarcoRossignoli · 2020-05-09T13:52:27Z

@ViktorHofer maybe I found the issue, the fix on this PR should be ok, the problem is that in-process collectors is not inject by vstest you can show that using --diag:log.txt at the end of commandline, in file log.host* I cannot see correct injected runsettings.
So no flush is called and sometime(random) we lose last hits refresh because host close before or in the middle of flush(process exits) and also we have a race between host close and get coverage.
Now, we need to understand why in-proc is not injected.
Inside log host I expect something like:

<RunSettings>
  <RunConfiguration>
    <ResultsDirectory>C:\\git\\coverlet\\Documentation\\Examples\\VSTest\\HelloWorld\\XUnitTestProject1\\TestResults</ResultsDirectory>
    <TargetPlatform>X64</TargetPlatform>
    <TargetFrameworkVersion>.NETCoreApp,Version=v3.1</TargetFrameworkVersion>
    <TestAdaptersPaths>C:\\Users\\Marco\\.nuget\\packages\\coverlet.collector\\1.2.1\\build\\netstandard1.0\\</TestAdaptersPaths>
    <DesignMode>False</DesignMode>
    <CollectSourceInformation>False</CollectSourceInformation>
  </RunConfiguration>
  <DataCollectionRunSettings>
    <DataCollectors>
      <DataCollector friendlyName="XPlat Code Coverage" enabled="True" />
    </DataCollectors>
  </DataCollectionRunSettings>
  <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="C:\\Users\\Marco\\.nuget\\packages\\coverlet.collector\\1.2.1\\build\\netstandard1.0\\coverlet.collector.dll" />
    </InProcDataCollectors>
  </InProcDataCollectionRunSettings>
  <LoggerRunSettings>
    <Loggers>
      <Logger friendlyName="Console" uri="logger://microsoft/TestPlatform/ConsoleLogger/v1" assemblyQualifiedName="Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger, vstest.console, Version=15.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a" codeBase="C:\\Program Files\\dotnet\\sdk\\3.1.201\\vstest.console.dll" enabled="True" />
    </Loggers>
  </LoggerRunSettings>
</RunSettings>

In case of core runtime test

<RunSettings>
  <RunConfiguration>
    <TestSessionTimeout>300000</TestSessionTimeout>
    <ResultsDirectory>C:\\git\\runtime\\artifacts\\bin\\System.Text.RegularExpressions.Tests\\net5.0-Debug\\TestResults\\</ResultsDirectory>
    <SolutionDirectory>.\\</SolutionDirectory>
    <MaxCpuCount>0</MaxCpuCount>
    <TargetPlatform>X64</TargetPlatform>
    <DisableParallelization>false</DisableParallelization>
    <DisableAppDomain>false</DisableAppDomain>
    <TestCaseFilter>category!=OuterLoop&amp;category!=failing</TestCaseFilter>
    <DotNetHostPath>C:\\git\\runtime\\artifacts\\bin\\testhost\\net5.0-Windows_NT-Debug-x64\\dotnet.exe</DotNetHostPath>
    <EnvironmentVariables>
      <DEVPATH>C:\\git\\runtime\\artifacts\\bin\\testhost\\net5.0-Windows_NT-Debug-x64\\</DEVPATH>
    </EnvironmentVariables>
    <TargetFrameworkVersion>.NETCoreApp,Version=v5.0</TargetFrameworkVersion>
    <InIsolation>true</InIsolation>
    <TestAdaptersPaths>C:\\Users\\Marco\\.nuget\\packages\\coverlet.collector\\1.3.0-preview.16.g6316f5fc24\\build\\netstandard1.0\\;C:\\Users\\Marco\\.nuget\\packages\\microsoft.codecoverage\\16.5.0\\build\\netstandard1.0\\</TestAdaptersPaths>
    <DesignMode>False</DesignMode>
    <CollectSourceInformation>False</CollectSourceInformation>
  </RunConfiguration>
  <LoggerRunSettings>
    <Loggers>
      <Logger friendlyName="trx" enabled="True" />
      <Logger friendlyName="html" enabled="True" />
      <Logger friendlyName="console" assemblyQualifiedName="Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger, vstest.console, Version=15.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a" codeBase="C:\\git\\runtime\\.dotnet\\sdk\\5.0.100-preview.5.20228.8\\vstest.console.dll" enabled="True">
        <Configuration>
          <Verbosity>Minimal</Verbosity>
        </Configuration>
      </Logger>
    </Loggers>
  </LoggerRunSettings>
  <DataCollectionRunSettings>
    <DataCollectors>
      <DataCollector friendlyName="XPlat code coverage" enabled="true">
        <Configuration>
          <Include>[System.Text.RegularExpressions]*</Include>
          <ExcludeByFile>C:\\git\\runtime\\src\\libraries\\Common\\src\\System\\SR.*,C:\\git\\runtime\\src\\libraries\\Common\\src\\System\\NotImplemented.cs</ExcludeByFile>
          <IncludeDirectory>C:\\git\\runtime\\artifacts\\bin\\testhost\\net5.0-Windows_NT-Debug-x64\\shared\\Microsoft.NETCore.App\\5.0.0</IncludeDirectory>
          <Format>opencover</Format>
          <SingleHit>false</SingleHit>
          <UseSourceLink>true</UseSourceLink>
          <IncludeTestAssembly>false</IncludeTestAssembly>
        </Configuration>
      </DataCollector>
      <DataCollector friendlyName="blame" enabled="true" />
    </DataCollectors>
  </DataCollectionRunSettings>
  <RunSettingsDirectory>C:\\git\\runtime\\artifacts\\bin\\System.Text.RegularExpressions.Tests\\net5.0-Debug</RunSettingsDirectory>
</RunSettings>

Can you tell which version of Microsoft.NET.Test.Sdk is used?I could try to rebase vstest repo and live debug to understand why runsettings is not rewrote correctly this is the main part in vstest repo https://github.com/microsoft/vstest/blob/57527561e6342aaaaca4012dc14d25ad08c0a326/src/vstest.console/Processors/CollectArgumentProcessor.cs#L235

MarcoRossignoli · 2020-05-09T16:40:22Z

@ViktorHofer some step forward with this branch version and this command seems work, trying to understand what inside runsettings break in-proc collector injection.

dotnet test -f net5.0 --collect:"XPlat Code Coverage" src\libraries\System.Text.RegularExpressions\tests\

reports seem stable but not perfect there are 2 seq point difference sometimes, I don't know why at the moment(I'm again on in-proc collector issue), could be related to some "non deterministic" path test?

  <Summary numSequencePoints="10603" visitedSequencePoints="10304" numBranchPoints="5022" visitedBranchPoints="4685" sequenceCoverage="97.18" branchCoverage="93.28" maxCyclomaticComplexity="5519" minCyclomaticComplexity="5519" visitedClasses="55" numClasses="55" visitedMethods="810" numMethods="820" />
  <Summary numSequencePoints="10603" visitedSequencePoints="10306" numBranchPoints="5022" visitedBranchPoints="4686" sequenceCoverage="97.19" branchCoverage="93.3" maxCyclomaticComplexity="5519" minCyclomaticComplexity="5519" visitedClasses="55" numClasses="55" visitedMethods="810" numMethods="820" />
  <Summary numSequencePoints="10603" visitedSequencePoints="10306" numBranchPoints="5022" visitedBranchPoints="4686" sequenceCoverage="97.19" branchCoverage="93.3" maxCyclomaticComplexity="5519" minCyclomaticComplexity="5519" visitedClasses="55" numClasses="55" visitedMethods="810" numMethods="820" />
  <Summary numSequencePoints="10603" visitedSequencePoints="10304" numBranchPoints="5022" visitedBranchPoints="4685" sequenceCoverage="97.18" branchCoverage="93.28" maxCyclomaticComplexity="5519" minCyclomaticComplexity="5519" visitedClasses="55" numClasses="55" visitedMethods="810" numMethods="820" />

avoid double flush hit files for collectors

96f42a0

MarcoRossignoli added bug Something isn't working driver-collectors Issue related to collectors driver labels May 5, 2020

MarcoRossignoli added 2 commits May 5, 2020 17:19

fix test

1ce2fb4

nit: cleanup

9c542cf

ViktorHofer mentioned this pull request May 6, 2020

Coverage results aren't stable #834

Closed

MarcoRossignoli changed the title ~~Avoid double flush hit files for collectors~~ [WIP]Avoid double flush hit files for collectors May 8, 2020

MarcoRossignoli added the * NO MERGE * The PR is not ready for merge yet (see discussion for detailed reasons) label May 8, 2020

MarcoRossignoli marked this pull request as draft May 8, 2020 15:25

MarcoRossignoli changed the title ~~[WIP]Avoid double flush hit files for collectors~~ Avoid double flush hit files for collectors May 8, 2020

fix log

6316f5f

imrpove logging

81e92c1

Avoid double flush hit files for collectors #835

Avoid double flush hit files for collectors #835

Uh oh!

Conversation

MarcoRossignoli commented May 5, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

MarcoRossignoli commented May 5, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ViktorHofer commented May 6, 2020

Uh oh!

MarcoRossignoli commented May 6, 2020

Uh oh!

ViktorHofer commented May 6, 2020

Uh oh!

MarcoRossignoli commented May 6, 2020

Uh oh!

ViktorHofer commented May 6, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

MarcoRossignoli commented May 6, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ViktorHofer commented May 6, 2020

Uh oh!

MarcoRossignoli commented May 6, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ViktorHofer commented May 6, 2020

Uh oh!

tonerdo commented May 7, 2020

Uh oh!

azure-pipelines bot commented May 7, 2020

Uh oh!

MarcoRossignoli commented May 8, 2020

Uh oh!

azure-pipelines bot commented May 8, 2020

Uh oh!

ViktorHofer commented May 8, 2020

Uh oh!

MarcoRossignoli commented May 8, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

MarcoRossignoli commented May 9, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

MarcoRossignoli commented May 9, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

MarcoRossignoli commented May 5, 2020 •

edited

Loading

MarcoRossignoli commented May 5, 2020 •

edited

Loading

ViktorHofer commented May 6, 2020 •

edited

Loading

MarcoRossignoli commented May 6, 2020 •

edited

Loading

MarcoRossignoli commented May 6, 2020 •

edited

Loading

MarcoRossignoli commented May 8, 2020 •

edited

Loading

MarcoRossignoli commented May 9, 2020 •

edited

Loading

MarcoRossignoli commented May 9, 2020 •

edited

Loading