Race condition building 4.23?

Development Programming & Scripting C++
, , ,
1

Hey, we’ve been running with 4.22 for a while without issue but I’m having an odd problem building the 4.23 UE4 engine source. I could swear the problem is a race condition, possibly made evident by heavier use of .NET in 4.23? It seems to involve projects being built in parallel that contend for write access to this file:

\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt

Error MSB3491 Could not write lines to file … because it is being used by another process.

It appears to be some kind of shared code for .NET projects. Looks like Visual Studio (19 for Windows) was building UnrealFileServer and UnrealInsights in parallel) Building again makes the problem go away. Happens maybe 10%-20% of the time on my machine during clean full builds.

2

Additional data point on this: I believe the problem occurs during full REBUILDS of the engine, and not clean full builds as I mentioned above. I suspect multiple projects are attempting to rebuild the DotNETCommon shared library in parallel, and that is the cause of the race condition. Additional projects added in 4.23 that use this shared library have made the problem more likely to occur.

3

Sorry to keep updating this, but I discovered some additional info: I think the root of this problem is “Clean.bat” which is called when the engine is forced to rebuild. If you look at what Clean.bat does, it wants to use UnrealBuildTool.exe, so it manually issues a request to build UnrealBuildTool, like this:

if not exist Programs\UnrealBuildTool\UnrealBuildTool.csproj goto NoProjectFile
%MSBUILD_EXE% /nologo /verbosity:quiet Programs\UnrealBuildTool\UnrealBuildTool.csproj /property:Configuration=Development /property:Platform=AnyCPU
if errorlevel 1 goto Error_UBTCompileFailed

But you cannot do this! UnrealBuildTool is a dependency of this build, it must be properly built as a dependency, not built as a side effect of this batch file. Doing it this way causes many requests to build UnrealBuildTool, and if the timing is just right, it hits a fatal contention conflict on the DotNET file I mentioned above.

Am I right about this? Would be nice to get independent confirmation from some other team.

4

Ok, after more attempts than I care to admit, I got a repro while running ProcessMonitor watching the FileListAbsolute.txt file mentioned above. If you look at the sharing violation, you can see two processes both wanted to write that file at the same time. These processes are builds of UnrealBuildTool which uses DotNETCommon. These builds were spawned by Clean.bat.

I think the problem may be Clean.bat is designed for two use cases, one inside structured builds and one outside in a standalone environment. It looks like it needs to be rewritten to not try to do its own build of UnrealBuildTool during builds, and instead accept UnrealBuildTool as a prebuilt dependency.

So, to repro this issue: Do a “Clean Solution” of the big UE4 solution, the entire 4.23 engine. Then do “Rebuild Solution”. Very quickly in the build you may (clean and rebuild again if not) see warnings about shared code not being accessible because another process was using it. Rarely you will see a fatal error on FileListAbsolute.txt. Took me at least 20 tries today to see the problem.

“2:30:45.1064449 PM”,“MSBuild.exe”,“10920”,“CreateFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“Desired Access: Generic Read, Disposition: Open, Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File, Open No Recall, Attributes: n/a, ShareMode: Read, AllocationSize: n/a, OpenResult: Opened”
“2:30:45.1065826 PM”,“MSBuild.exe”,“10920”,“QueryEAFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“”
“2:30:45.1067984 PM”,“MSBuild.exe”,“4384”,“CreateFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened”
“2:30:45.1068246 PM”,“MSBuild.exe”,“4384”,“QueryNetworkOpenInformationFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“CreationTime: 9/19/2019 6:36:55 PM, LastAccessTime: 9/20/2019 2:30:45 PM, LastWriteTime: 9/20/2019 2:30:45 PM, ChangeTime: 9/20/2019 2:30:45 PM, AllocationSize: 4096, EndOfFile: 557, FileAttributes: A”
“2:30:45.1068391 PM”,“MSBuild.exe”,“4384”,“CloseFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“”
“2:30:45.1070198 PM”,“MSBuild.exe”,“4384”,“CreateFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“Desired Access: Generic Read, Disposition: Open, Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File, Open No Recall, Attributes: n/a, ShareMode: Read, AllocationSize: n/a, OpenResult: Opened”
“2:30:45.1070999 PM”,“MSBuild.exe”,“4384”,“QueryEAFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“”
“2:30:45.1072274 PM”,“MSBuild.exe”,“10920”,“ReadFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“Offset: 0, Length: 557, Priority: Normal”
“2:30:45.1072714 PM”,“MSBuild.exe”,“10920”,“ReadFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“END OF FILE”,“Offset: 557, Length: 4,096”
“2:30:45.1073079 PM”,“MSBuild.exe”,“10920”,“CloseFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“”
“2:30:45.1076628 PM”,“MSBuild.exe”,“4384”,“ReadFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“Offset: 0, Length: 557, Priority: Normal”
“2:30:45.1077064 PM”,“MSBuild.exe”,“4384”,“ReadFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“END OF FILE”,“Offset: 557, Length: 4,096”
“2:30:45.1077302 PM”,“MSBuild.exe”,“4384”,“CloseFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“”
“2:30:45.1111676 PM”,“MSBuild.exe”,“10920”,“CreateFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“Desired Access: Generic Write, Read Attributes, Disposition: OverwriteIf, Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File, Open No Recall, Attributes: n/a, ShareMode: Read, AllocationSize: 0, OpenResult: Overwritten”
“2:30:45.1114882 PM”,“MSBuild.exe”,“10920”,“WriteFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“Offset: 0, Length: 707, Priority: Normal”
“2:30:45.1115128 PM”,“MSBuild.exe”,“4384”,“CreateFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SHARING VIOLATION”,“Desired Access: Generic Write, Read Attributes, Disposition: OverwriteIf, Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File, Open No Recall, Attributes: n/a, ShareMode: Read, AllocationSize: 0”
“2:30:45.1115862 PM”,“MSBuild.exe”,“10920”,“CloseFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“”
“2:30:45.1273110 PM”,“MSBuild.exe”,“4384”,“CreateFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“Desired Access: Generic Write, Read Attributes, Disposition: OverwriteIf, Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File, Open No Recall, Attributes: n/a, ShareMode: Read, AllocationSize: 0, OpenResult: Overwritten”
“2:30:45.1275762 PM”,“MSBuild.exe”,“4384”,“WriteFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“Offset: 0, Length: 707, Priority: Normal”
“2:30:45.1276513 PM”,“MSBuild.exe”,“4384”,“CloseFile”,“\Engine\Source\Programs\DotNETCommon\DotNETUtilities\obj\Development\DotNETUtilities.csproj.FileListAbsolute.txt”,“SUCCESS”,“”

5

No traction on this… does Unreal 4 have an actual bug report system where I can submit this?

6

Just FYI, Unreal Engine does have a bug report system. I submitted the information above and Epic has confirmed this is indeed a bug and they are working on fixing it. No ETA.

If you are unlucky enough to encounter this problem a lot, here is a hack workaround that makes the race condition far less common, in “Clean.bat”:

rem ## If this is an installed build, we don’t need to rebuild UBT. Go straight to cleaning.
if exist …\Build\InstalledBuild.txt goto ReadyToClean
if exist …..\Engine\Binaries\DotNET\UnrealBuildTool.exe goto ReadyToClean <– Add this line