MoveDirectory fails intermittently (Razor projects)

[duncanp-sonar]

Description

See this community thread: https://community.sonarsource.com/t/error-msb4018-the-movedirectory-task-failed-unexpectedly-system-io-ioexception-cannot-create-a-file-when-that-file-already-exists/52100

The underlying cause is not clear. The error occurs intermittently when processing projects that have Razor files.

The error occurs on a self-hosted build agent (-> perhaps the files are not being cleaned up correctly between runs?)

Repro steps

See the community thread.

Expected behavior

Analysis succeeds.

Actual behavior

IO exceptions occur intermittently.

Notes

Razor projects call the compiler twice: the first to compile the "normal" source, the second to compile the Razor source.
The processing does the following (TODO - confirm):

1. normal compile runs producing "normal" analysis results
2. the results directory is renamed to "xxx.tmp"
3. Razor compile runs producing Razor analysis results
4. the results directorry is renamed to "xxx.Razor"
5. "xxx.tmp" is renamed back to "xxx"

We don't need to do all of this copying about - the directory names are internal, so we could get away with just renaming the original "source" analysis directory.

See also #1063. The errors are in our custom task, which could be replaced by standard MSBuild tasks (although that might not fix this current issue).

Call stack

Note: there are two separate errors on two different projects in the log excerpt below:

1. ##[error]C:\tfs\Agent\_work\3\.sonarqube\bin\targets\SonarQube.Integration.targets(418,5): Error MSB4018: The "MoveDirectory" task failed unexpectedly. System.IO.IOException: Cannot create a file when that file already exists.

This occurs in SonarFinishRazorProjectCodeAnalysis when trying to move the "source" analysis files back to the original location.

and

2. ##[error]C:\tfs\Agent\_work\3\.sonarqube\bin\targets\SonarQube.Integration.targets(404,5): Error : The destination directory is invalid.

This occurs in SonarPrepareRazorProjectCodeAnalysis when trying to move the "source" analysis output to a temporary directory.
Looking at the code, the error seems to indicate that the temporary directory already exists.

##[error]C:\tfs\Agent_work\3.sonarqube\bin\targets\SonarQube.Integration.targets

2021-10-13T16:56:14.9148716Z Build FAILED.
2021-10-13T16:56:14.9305520Z 
2021-10-13T16:56:14.9328080Z        "C:\tfs\Agent\_work\3\s\Source\MySolution.sln" (default target) (1) ->
2021-10-13T16:56:14.9351133Z        "C:\tfs\Agent\_work\3\s\Source\WebServices\Template\MyProject\MyProject.csproj" (default target) (61) ->
2021-10-13T16:56:14.9351678Z        (SonarFinishRazorProjectCodeAnalysis target) -> 
2021-10-13T16:56:14.9352338Z          C:\tfs\Agent\_work\3\.sonarqube\bin\targets\SonarQube.Integration.targets(418,5): error MSB4018: The "MoveDirectory" task failed unexpectedly. [C:\tfs\Agent\_work\3\s\Source\WebServices\Template\MyProject\MyProject.csproj]
2021-10-13T16:56:14.9353500Z        C:\tfs\Agent\_work\3\.sonarqube\bin\targets\SonarQube.Integration.targets(418,5): error MSB4018: System.IO.IOException: Cannot create a file when that file already exists. [C:\tfs\Agent\_work\3\s\Source\WebServices\Template\MyProject\MyProject.csproj]
2021-10-13T16:56:14.9356528Z        C:\tfs\Agent\_work\3\.sonarqube\bin\targets\SonarQube.Integration.targets(418,5): error MSB4018:  [C:\tfs\Agent\_work\3\s\Source\WebServices\Template\MyProject\MyProject.csproj]
2021-10-13T16:56:14.9357681Z        C:\tfs\Agent\_work\3\.sonarqube\bin\targets\SonarQube.Integration.targets(418,5): error MSB4018:    at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath) [C:\tfs\Agent\_work\3\s\Source\WebServices\Template\MyProject\MyProject.csproj]
2021-10-13T16:56:14.9359214Z        C:\tfs\Agent\_work\3\.sonarqube\bin\targets\SonarQube.Integration.targets(418,5): error MSB4018:    at System.IO.Directory.InternalMove(String sourceDirName, String destDirName, Boolean checkHost) [C:\tfs\Agent\_work\3\s\Source\WebServices\Template\MyProject\MyProject.csproj]
2021-10-13T16:56:14.9361067Z        C:\tfs\Agent\_work\3\.sonarqube\bin\targets\SonarQube.Integration.targets(418,5): error MSB4018:    at SonarScanner.MSBuild.Tasks.MoveDirectory.Execute() [C:\tfs\Agent\_work\3\s\Source\WebServices\Template\MyProject\MyProject.csproj]
2021-10-13T16:56:14.9364658Z        C:\tfs\Agent\_work\3\.sonarqube\bin\targets\SonarQube.Integration.targets(418,5): error MSB4018:    at Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute() [C:\tfs\Agent\_work\3\s\Source\WebServices\Template\MyProject\MyProject.csproj]
2021-10-13T16:56:14.9366184Z        C:\tfs\Agent\_work\3\.sonarqube\bin\targets\SonarQube.Integration.targets(418,5): error MSB4018:    at Microsoft.Build.BackEnd.TaskBuilder.<ExecuteInstantiatedTask>d__26.MoveNext() [C:\tfs\Agent\_work\3\s\Source\WebServices\Template\MyProject\MyProject.csproj]
2021-10-13T16:56:14.9367045Z 
2021-10-13T16:56:14.9367241Z 
2021-10-13T16:56:14.9367671Z        "C:\tfs\Agent\_work\3\s\Source\MySolution.sln" (default target) (1) ->
2021-10-13T16:56:14.9368283Z        "C:\tfs\Agent\_work\3\s\Source\WebServices\Localization\MyCompany.Localization\MyCompany.Localization.csproj" (default target) (58) ->
2021-10-13T16:56:14.9368858Z        (SonarPrepareRazorProjectCodeAnalysis target) -> 
2021-10-13T16:56:14.9369605Z          C:\tfs\Agent\_work\3\.sonarqube\bin\targets\SonarQube.Integration.targets(404,5): error : . [C:\tfs\Agent\_work\3\s\Source\WebServices\Localization\MyCompany.Localization\MyCompany.Localization.csproj]
2021-10-13T16:56:14.9370175Z 
2021-10-13T16:56:14.9370482Z     0 Warning(s)
2021-10-13T16:56:14.9370790Z     2 Error(s)
2021-10-13T16:56:14.9370990Z 

Known workarounds

None.

Related information

• SonarScanner for MSBuild version: v5.3.1
• SonarQube server version: N/A
• Languages in your solution: C#.

[grpatter]

Just adding that we're currently experience this issue in AzDO with the following;

SonarScanner for MSBuild version: v5.3.2
SonarQube server version: N/A
Languages in your solution: C#, using Razor

We see this at both lines 418 and 404 of SonarQube.Integration.targets:
##[error]d:\_wf\03\15\.sonarqube\bin\targets\SonarQube.Integration.targets(418,5): Error MSB4018: The "MoveDirectory" task failed unexpectedly.
and
##[error]d:\_wf\03\15\.sonarqube\bin\targets\SonarQube.Integration.targets(404,5): Error : The destination directory is invalid.

with the final message

d:_wf\03\15.sonarqube\bin\targets\SonarQube.Integration.targets(418,5): error MSB4018: The "MoveDirectory" task failed unexpectedly. [d:_wf\03\15\s\XXX\src\XXX.Modules\XXX.YYY\XXX.YYY.csproj]
d:_wf\03\15.sonarqube\bin\targets\SonarQube.Integration.targets(418,5): error MSB4018: System.IO.IOException: Cannot create 'd:_wf\03\15.sonarqube\out\141' because a file or directory with the same name already exists. [d:_wf\03\15\s\XXX\src\XXX.Modules\XXX.YYY\XXX.YYY.csproj]

[andrei-epure-sonarsource]

@grpatter

• would you happen to have a small reproducer project?
• do you use self-hosted agents?
• does it happen intermittently or all the time?
• what MSBuild and Scanner for .NET versions are you using?

[andrei-epure-sonarsource]

@duncanp-sonar my naive approach to reproduce was to re-do the analysis multiple times on the same build machine (in case there was a problem with clean-up).

I wasn't able to reproduce although I tried with various NET 5 web apps (see here and squidex).

[grpatter]

@grpatter

* would you happen to have a small reproducer project?

I do, shared with @fan-yang-sonarsource and @joe-tingsanchali-sonarsource - but I can add you directly as well.

* do you use self-hosted agents?

We use a mix in our ADO

* does it happen intermittently or all the time?

Intermittently, about 10% of the time from the statistics we currently have.

* what MSBuild and Scanner for .NET versions are you using?

This is different across projects, but for the one I was able to reproduce we are using MSBuild .NET core v3.1.416. I'm not sure how to tell exactly which plugin version we're using, but it should be latest provided by ADO. We're using these step task templates; SonarQubePrepare@4, SonarQubeAnalyze@4, SonarQubePublish@4. Is there a way to get more detailed info on this?

@andrei-epure-sonarsource - responses in-line. You can also check your internal jira service desk ticket SUPPORT-28422 for a full log/yaml dump.

[fan-yang-sonarsource]

@grpatter I will reach out to @andrei-epure-sonarsource and be synced with him.

[andrei-epure-sonarsource]

Thanks a lot @grpatter for creating this reproducer. You are awesome. I was able to reproduce the problem after running the build 6 times on it.

The problem is a race condition created when the folder NNN gets renamed to NNN.Razor before the Razor compilation of a project. In the reproducer, two projects end up having the same NNN folder inside the .sonarqube folder. That is because when assigning a new Unique Folder ID, the Scanner for .NET verifies all the existing folders and increments. When renaming the folder, a race condition gets created (the NNN folder gets renamed, and that ID is ready to be picked up by a different project build).

There are possible fixes:

1. when creating the unique number, verify also the folders "NNN.*" ("NNN.tmp", "NNN.Razor")
2. don't rename the folder, just move it's contents - like this for a project that started the build, the folder will always be present and only its contents will change (as suggested by @duncanp-sonar in this comment)
3. change the logic for multiple compilations altogether

IMO the second option is better.

I will present the timeline from the reproducer. For brevity I removed the Orchard. prefix from the csproj names.

The first project (Shortcodes.csproj) with 2211 renames 2211 to 2211.Razor.

Target Name=SonarFinishRazorProjectCodeAnalysis Project=Shortcodes.csproj
    Moving directory <PATH>\.sonarqube\out\2211 to <PATH>\.sonarqube\out\2211.Razor.
Start: 2022-01-20 11:56:23.6148210
End: 2022-01-20 11:56:23.6161452

The second project (Html.csproj) attempts to take 2211 at the same time

Target Name=SonarCreateProjectSpecificDirs Project=Html.csproj
  MakeUniqueDir
            ProjectSpecificOutDir = <PATH>\.sonarqube\out\2211
            UniqueName = 2211
Start: 2022-01-20 11:56:23.4296925
End: 2022-01-20 11:56:23.6179410

And the first project will finish the move

Target Name=SonarFinishRazorProjectCodeAnalysis Project=Shortcodes.csproj
Moving directory <PATH>\.sonarqube\out\2211 to <PATH>\.sonarqube\out\2211.Razor.
Moving directory <PATH>\.sonarqube\out\2211.tmp to <PATH>\.sonarqube\out\2211.
Start: 2022-01-20 11:56:23.6148210
End: 2022-01-20 11:56:23.6161452

The race happens somewhere between 11:56:23.4296925 and 11:56:23.6179410, and probably the contents of the folders get messed up. In any case, 2211.Razor. contains the metadata for Shortcodes.csproj.

And the second project fails because 2211.Razor is already present.

Target Name=SonarFinishRazorProjectCodeAnalysis Project=Html.csproj
MoveDirectory
    Parameters
        SourceDirectory = <PATH>\.sonarqube\out\2211
        DestinationDirectory = <PATH>\.sonarqube\out\2211.Razor
    Errors
        <PATH>\.sonarqube\bin\targets\SonarQube.Integration.targets(417,5): The destination directory is invalid.
Start: 2022-01-20 11:57:13.0055989
End: 2022-01-20 11:57:13.0059859