"Output directory for saved files already exists" despite AltCoverForce set to true

[ffMathy]

Here I am again. Sorry about that, and again - take the time you need.

I get the following error:

C:\Users\mathi.nuget\packages\altcover\7.3.802\build\netstandard2.0\AltCover.targets(65,5): error : Output directory for saved files C:\Users\mathi\source\repos\anonymized.pruner\temp\51b5c84e-1148-4f14-861d-8bc310a7b277\build__Saved already exists [C:\Users\mathi\source\repos\anonymized\src\anonymized.Tests\anonymized.Tests.csproj]

Despite /p:AltCoverForce=true being set in my dotnet test call.

I would also love if AltCover would only do the instrumentation if my original output DLLs changed. That way, it would work quite well with dotnet build's way of not rebuilding if it is not needed (for instance, if only one out of 3 projects have changed their output DLLs, don't build the other two).

[SteveGilham]

While the command parameters are still being assessed, the verbosity level isn't known, so things shown up at that point still get reported -- but there's something more interesting happening here.

You should instead be seeing an MSBuild level warning message of the form

"Directory '$(TargetDir)__Saved' exists from a previous run.  Forcibly deleting it"

given /p:AltCoverForce=true, a directory path corresponding to

<AltCoverOutputDirectory Include="$(TargetDir)__Saved" />

elsewhere in the .targets file.

The fact that your path ends \build__Saved rather than something like \net5.0\__Saved (or even \build\__Saved) suggests that $(TargetDir) is being manipulated from its typical default value between the initial check, and the later instrumentation pass.

There's certainly an issue here in that I'm evaluating $(TargetDir)__Saved at multiple points in the proceedings, rather than once and for all and stashing the value, which may or may not be poor for performance, but definitely makes the assumption that it evaluates the same at every turn.

[SteveGilham]

What happens when you replace the AltCover.targets file in your local copy of v7.3 with this one that evaluates the path just the once and stores it away?

[ffMathy]

Hmmm I see!

Well, I think the steps are quite easy to reproduce then. It happened after I started using "dotnet test - - output somepath" where "somepath" is a path entirely outside the project folder.

[ffMathy]

How do I replace that targets file?

[SteveGilham]

The file will be in %USERPROFILE%\.nuget\packages\altcover\7.3.802\build\netstandard2.0 (unless you've pointed your NuGet cache somewhere nonstandard) -- download the raw from GitHub and copy it over the current one (or move the current one somewhere safe, and drop the new one where the old one was).

[SteveGilham]

As to the other issue, of not re-instrumenting, the current tie-up with dotnet test saves the as-built files into the $(TargetDir)__Saved folder, puts the instrumented files and the recorder into $(TargetDir), lets the test run against $(TargetPath), and then wipes that folder and moves the originals back so everything can carry on as if the files hadn't been tampered with.

This is what coverlet does and I just followed that pattern, and it is what blocks doing incremental instrumentation -- because the instrumented files don't hang around between runs.

Having now stopped and thought about it, I can avoid that copying/copying back wrapper by changing the parameters to the VSTestTask step to point at an instrumented version in a different folder. That would allow the files to persist without interfering with other build processes, and make it meaningful to start thinking of how to do incremental instrumentation -- and I have some ideas along those lines already.

[ffMathy]

I'll try the targets file tomorrow.

As for incremental Instrumentation, what if it would just be possible to not replace the files back to normal again (a specific mode that could be activated), and then compare an MD5 checksum of the files (or their modified date) to see if specific DLLs have changed?

That would be easier to implement perhaps, and it would allow for AltCover to play along with dotnet test's existing incremental build feature without adding too much extra code.

When I build the project via Pruner, I deliberately build to another directory to avoid files being in use. This is a great opportunity to also just leave the saved instrumented files there, and then only instrument if existing ones are outdated.

If course I realize it's a bit niche.

[SteveGilham]

Having realised how I can avoid doing the copy/copy back dance, which is a bit of a kludge, implemented only for the benefit of vanilla dotnet test, I shall do that anyway. I shall have to consider what to do with AltCoverForce-based messages, and the one reported at this start of this thread for the moment.

I already use a hash of the source assembly as a key in the instrumentation calls, so it will be just a matter of surfacing that so it can be easily checked before processing. I'd also want to bake in a representation of the relevant parameters (filters and such) used, to check if the instrumentation demands had changed as well.

[ffMathy]

That sounds awesome!

[SteveGilham]

This is being an interesting and fun issue -- it's given me a reason to go back and look at some very early, nigh buried, assumptions, and re-evaluate them. For example, the whole /p:AltCoverForce thing and the "Output directory for saved files" message are only there in the first place so that the integrity of the as-built files is maintained through the copy/copy-back -- remove the copy/copy-back (from the dotnet test route at least), and their raison d'etre goes away there too.

In particular, it means that there's no need to clear up the instrumented files in the dotnet test targets file, so no need to add any new logic in the actual program -- meaning incremental instrumentation can become transparent, rather than having to have an explicit opt-in.

[ffMathy]

Very interesting! Reasonable thinking.

Just to make sure I understand it correctly - you're getting rid of the whole "save instrumented assembly and swap it back afterwards" functionality?

Because that sounds great IMO.

[SteveGilham]

I'm not removing the functionality (the command line will still have the --inplace flag as an opt-in, for example) -- just hardcoding it to be "off" in the AltCover.targets file where everything integrates with dotnet test.

Here's a better AltCover.targets to play with.

[ffMathy]

The latest targets file produces this error:

System.IO.IOException: The process cannot access the file 'C:\Users\mathi\source\repos\anonymized_backend\.pruner\temp\51b5c84e-1148-4f14-861d-8bc310a7b277\build\__Instrumented\anonymized.BusinessLogic.dll' 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, FileAccess access, FileShare share)
   at System.IO.File.Open(String path, FileMode mode, FileAccess access)
   at AltCover.Instrument.I.write@332-1(AssemblyDefinition a, String p, WriterParameters pk) in C:\projects\altcover\AltCover.Engine\Instrument.fs:line 333
   at AltCover.Instrument.I.writeAssembly(AssemblyDefinition assembly, String path) in C:\projects\altcover\AltCover.Engine\Instrument.fs:line 338
   at AltCover.Instrument.I.writeAssemblies(AssemblyDefinition definition, String file, IEnumerable`1 targets, FSharpFunc`2 sink) in C:\projects\altcover\AltCover.Engine\Instrument.fs:line 598
   at AltCover.Instrument.I.visitAfterAssembly[a](a state, AssemblyDefinition assembly, FSharpList`1 paths) in C:\projects\altcover\AltCover.Engine\Instrument.fs:line 710
   at AltCover.Instrument.I.instrumentationVisitorWrapper(FSharpFunc`2 core, InstrumentContext state, Node node) in C:\projects\altcover\AltCover.Engine\Instrument.fs:line 793
   at AltCover.Visitor.stateful@1110-1.Invoke(T node) in C:\projects\altcover\AltCover.Engine\Visitor.fs:line 1112
   at Microsoft.FSharp.Primitives.Basics.List.mapToFreshConsTail[a,b](FSharpList`1 cons, FSharpFunc`2 f, FSharpList`1 x) in F:\workspace\_work\1\s\src\fsharp\FSharp.Core\local.fs:line 241
   at Microsoft.FSharp.Primitives.Basics.List.map[T,TResult](FSharpFunc`2 mapping, FSharpList`1 x) in F:\workspace\_work\1\s\src\fsharp\FSharp.Core\local.fs:line 247
   at Microsoft.FSharp.Collections.SeqModule.Fold[T,TState](FSharpFunc`2 folder, TState state, IEnumerable`1 source) in F:\workspace\_work\1\s\src\fsharp\FSharp.Core\seq.fs:line 731
   at AltCover.Visitor.visit(IEnumerable`1 visitors, IEnumerable`1 assemblies) in C:\projects\altcover\AltCover.Engine\Visitor.fs:line 1100
   at AltCover.Main.I.result@486.Invoke(Unit unitVar0) in C:\projects\altcover\AltCover.Engine\Main.fs:line 504
   at AltCover.CommandLine.I.doPathOperation[a](FSharpFunc`2 f, a defaultValue, Boolean store) in C:\projects\altcover\AltCover.Engine\CommandLine.fs:line 206
TargetSite = 
Microsoft.Win32.SafeHandles.SafeFileHandle ValidateFileHandle(Microsoft.Win32.SafeHandles.SafeFileHandle)
Data = 
seq []
InnerException = 
<null>
HelpLink = 
<null>
Source = 
"System.Private.CoreLib"
HResult = 
-2147024864

[ffMathy]

Now, that's a bit funny, because I know the file is not being used by anyone else. It's a separate directory, and after the process is done, I can delete it, verifying that it isn't being used.

The structure is:

• Anonymous - references Anonymous.BusinessLogic
• Anonymous.Tests - references Anonymous
• Anonymous.BusinessLogic
• Anonymous.BusinessLogic.Tests - references Anonymous.BusinessLogic and Anonymous.Tests

[SteveGilham]

So, this is happening when an instrumented assembly is being written. What has changed is that previously, at his point, there'd be no pre-existing file of the same name; now, on a second and subsequent pass, the file will exist to be overwritten.

My first guess is that it is possible that in the same way that the memory of a deleted file persists for a short while, interfering with recursive tree deletes, an execute lock may linger on a current file. Without the delay involved in copying back and deleting the save directory, then creating a new directory and copying the new build, it's possible that a tight loop may execute fast enough to overlap that memory of a lock.

I shall have to experiment on that.

[SteveGilham]

For the moment, while I work on the rest of this, yesterday's .targets file should work around just the error message issue cause by specifying an explicit output path.

[ffMathy]

Yeah that must explain why the error is indeed different now.

That makes sense! Although I can't verify it due to the other error.

And my simple project can't reproduce it. Only the NDA covered one can 🙄

[ffMathy]

@SteveGilham look at the GIF here: https://github.com/pruner/cli

AltCover made that possible! 🙏👍

[SteveGilham]

Release v7.3.805 deals with the headline issue here; work on making instrumentation incremental continues.

[ffMathy]

@SteveGilham still experiencing the main issue unfortunately, with the latest build from NuGet.

[SteveGilham]

Can you provide a simple repro? I've not been able to provoke this behaviour.

[ffMathy]

Unfortunately not 😞 the project where it happens on is under NDA.

Here are the logs:

       "C:\Users\mathi\source\repos\Anonymized_backend\src\Anonymized.sln" (VSTest target) (1:2) ->
       "C:\Users\mathi\source\repos\Anonymized_backend\src\Anonymized.Tests\Anonymized.Tests.csproj" (VSTest target) (7:6) ->
       (AltCoverRunPreparation target) ->
         C:\Users\mathi\.nuget\packages\altcover\7.3.805\build\netstandard2.0\AltCover.targets(63,5): error :  [C:\Users\mathi\source\repos\Anonymized_backend\src\Anonymized.Tests\Anonymized.Tests.csproj]
       C:\Users\mathi\.nuget\packages\altcover\7.3.805\build\netstandard2.0\AltCover.targets(63,5): error : ERROR *** Instrumentation phase failed [C:\Users\mathi\source\repos\Anonymized_backend\src\Anonymized.Tests\Anonymized.Tests.csproj]
       C:\Users\mathi\.nuget\packages\altcover\7.3.805\build\netstandard2.0\AltCover.targets(63,5): error :  [C:\Users\mathi\source\repos\Anonymized_backend\src\Anonymized.Tests\Anonymized.Tests.csproj]
       C:\Users\mathi\.nuget\packages\altcover\7.3.805\build\netstandard2.0\AltCover.targets(63,5): error :  [C:\Users\mathi\source\repos\Anonymized_backend\src\Anonymized.Tests\Anonymized.Tests.csproj]
         C:\Users\mathi\.nuget\packages\altcover\7.3.805\build\netstandard2.0\AltCover.targets(63,5): error : The process cannot access the file 'C:\Users\mathi\source\repos\Anonymized_backend\.pruner\temp\51b5c84e-1148-4f14-861d-8bc310a7b277\build\__Instrumented\Anonymized.BusinessLogic.dll' because it is being used by another process. [C:\Users\mathi\source\repos\Anonymized_backend\src\Anonymized.Tests\Anonymized.Tests.csproj]
         C:\Users\mathi\.nuget\packages\altcover\7.3.805\build\netstandard2.0\AltCover.targets(63,5): error :  [C:\Users\mathi\source\repos\Anonymized_backend\src\Anonymized.Tests\Anonymized.Tests.csproj]
       C:\Users\mathi\.nuget\packages\altcover\7.3.805\build\netstandard2.0\AltCover.targets(63,5): error : Details written to C:\Users\mathi\source\repos\Anonymized_backend\.pruner\temp\51b5c84e-1148-4f14-861d-8bc310a7b277\build\__Instrumented\AltCover-2021-01-04--15-06-52.log [C:\Users\mathi\source\repos\Anonymized_backend\src\Anonymized.Tests\Anonymized.Tests.csproj]

    630 Warning(s)
    3 Error(s)

[ffMathy]

These are the arguments that were passed to dotnet test: --settings C:\Users\mathi\source\repos\Anonymized_backend\.pruner\temp\51b5c84e-1148-4f14-861d-8bc310a7b277\runsettings.settings /p:AltCover=true /p:AltCoverCallContext=[TestMethod]|[Test]|[Fact]|[Theory] /p:AltCoverForce=true /p:AltCoverXmlReport=coverage.xml.tmp.pruner /p:AltCoverSummaryFormat=N /p:AltCoverLocalSource=true /p:AltCoverVerbosity=Info --logger trx;LogFileName=../summary.trx.tmp.pruner --logger console;verbosity=detailed --verbosity normal --output C:\Users\mathi\source\repos\Anonymized_backend\.pruner\temp\51b5c84e-1148-4f14-861d-8bc310a7b277\build

[ffMathy]

Is this due to one of the test projects referencing another test project perhaps?

[SteveGilham]

A simple repro means a cut down case with only the minimum amount of stub code to necessary provoke the issue. Not the case where it is simple for you to reproduce the issue (because it's the complete system you saw it in).

[ffMathy]

Then it'll take quite some time before I can get back to this unfortunately. I'll see what I can do within the next couple of months.

In the meantime, if it's of any use, here's additional log data:

System.IO.IOException: The process cannot access the file 'C:\Users\mathi\source\repos\Anonymized_backend\.pruner\temp\51b5c84e-1148-4f14-861d-8bc310a7b277\build\__Instrumented\Anonymized.BusinessLogic.dll' 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, FileAccess access, FileShare share)
   at System.IO.File.Open(String path, FileMode mode, FileAccess access)
   at AltCover.Instrument.I.write@329-1(AssemblyDefinition a, String p, WriterParameters pk) in C:\projects\altcover\AltCover.Engine\Instrument.fs:line 330
   at AltCover.Instrument.I.writeAssembly(AssemblyDefinition assembly, String path) in C:\projects\altcover\AltCover.Engine\Instrument.fs:line 335
   at AltCover.Instrument.I.writeAssemblies(AssemblyDefinition definition, String file, IEnumerable`1 targets, FSharpFunc`2 sink) in C:\projects\altcover\AltCover.Engine\Instrument.fs:line 594
   at AltCover.Instrument.I.visitAfterAssembly(InstrumentContext state, AssemblyEntry assembly) in C:\projects\altcover\AltCover.Engine\Instrument.fs:line 704
   at AltCover.Instrument.I.instrumentationVisitorWrapper(FSharpFunc`2 core, InstrumentContext state, Node node) in C:\projects\altcover\AltCover.Engine\Instrument.fs:line 786
   at AltCover.Visitor.stateful@1166-1.Invoke(T node) in C:\projects\altcover\AltCover.Engine\Visitor.fs:line 1168
   at Microsoft.FSharp.Primitives.Basics.List.mapToFreshConsTail[a,b](FSharpList`1 cons, FSharpFunc`2 f, FSharpList`1 x) in F:\workspace\_work\1\s\src\fsharp\FSharp.Core\local.fs:line 241
   at Microsoft.FSharp.Primitives.Basics.List.map[T,TResult](FSharpFunc`2 mapping, FSharpList`1 x) in F:\workspace\_work\1\s\src\fsharp\FSharp.Core\local.fs:line 247
   at Microsoft.FSharp.Collections.SeqModule.Fold[T,TState](FSharpFunc`2 folder, TState state, IEnumerable`1 source) in F:\workspace\_work\1\s\src\fsharp\FSharp.Core\seq.fs:line 731
   at AltCover.Visitor.visit(IEnumerable`1 visitors, IEnumerable`1 assemblies) in C:\projects\altcover\AltCover.Engine\Visitor.fs:line 1156
   at AltCover.Main.I.result@482.Invoke(Unit unitVar0) in C:\projects\altcover\AltCover.Engine\Main.fs:line 500
   at AltCover.CommandLine.I.doPathOperation[a](FSharpFunc`2 f, a defaultValue, Boolean store) in C:\projects\altcover\AltCover.Engine\CommandLine.fs:line 206
TargetSite = 
Microsoft.Win32.SafeHandles.SafeFileHandle ValidateFileHandle(Microsoft.Win32.SafeHandles.SafeFileHandle)
Data = 
seq []
InnerException = 
<null>
HelpLink = 
<null>
Source = 
"System.Private.CoreLib"
HResult = 
-2147024864

[SteveGilham]

OK, so this is the new error "System.IO.IOException: The process cannot access the file [something instrumented] because it is being used by another process." while trying to write the newly re-instrumented code. This would have to be the previous test process still not having relinquished the assembly (or at least it's unlikely than anything else would be executing that particular copy of the assembly). It's nothing simple -- running a simple test case in quick succession from a .bat file doesn't provoke the issue, for example.

I'm thinking that something in the system under test is spinning up something long lived using that assembly (maybe an external process), and not shutting it down when the test process exits.

The quick and easy remedy is of course to instrument to a new place every time -- but that means saying goodbye to incremental instrumentation even in cases when we don't want to replace the file that's being locked. The next best would be some sort of back off and retry -- but that means some arbitrary decision about how long to wait before giving up. Actively unlocking the files -- that way elevated privilege requirements lie.

[ffMathy]

I like the back off and retry. Perhaps we could use Polly for it?

We don't have any tests doing anything fancy at the moment. The tests are very simple.

I think Coverlet ran into this issue too recently, because of a bug with how the .NET Test Host manages its processes. I think they ended up combining an external and in-memory data collector to get around it.

[SteveGilham]

I don't see the need for anything more complicated for back-off and retry than

let rec safeOpenFile path = 
  try 
   File.Open path
 with
 | :? SecurityException _ ->
  Thread.Sleep(1000)
  safeOpenFile path

possibly with some arbitrary depth of recursion cut-off, possibly with increasing the back-off interval at each go-around.

I don't think that this can be quite the same problem as the coverlet one you cite, as this happens in the instrumentation phase, well after any previous collection phase has completed. The individual dotnet test process is like

1. Instrumentation task
2. Test task, with data collector to dump results
3. Collection task reading results from test task to update coverage file

and this issue is that (2) doesn't give the impression of having completed by the time the next (1) happens.

[ffMathy]

Fair enough. That makes sense.

Do you intent to implement the back-off and retry then? :pray:

[SteveGilham]

I've just had a thought here -- are you running a solution level dotnet test against a single output directory with all the solution build artefacts in it? That could lead to multiple concurrent instrumentations happening all to the same output location, and would also have caused the "directory already exists" message in previous releases.

[ffMathy]

Yes, that's exactly what I am doing :+1: 🙌

[ffMathy]

How do we solve that though? 🤔

[SteveGilham]

Quick and dirty -- have each test project instrument to its own folder. More sophisticated -- incremental instrumentation phase 1 : if the file exists and comes from the same source as the about-to-be-written one, then skip the write, otherwise mutex lock on the file path, so concurrent writes don't happen

[ffMathy]

I think the "quick and dirty" approach does the job here. The overhead should be minimal, and it doesn't introduce new issues accidentally (low complexity).

[ffMathy]

What are your thoughts?

[SteveGilham]

This version of the targets file is the quick and dirty fix; you can patch over your current install to try it out.

[ffMathy]

It seems to work! 🙌

[SteveGilham]

Released as v7.3.806.