It shows up as “Permission denied” errors in the log, but inspecting the workspace reveals that the problematic files simply do not exist.
We have tried various combinations of UbaCacheServer and other related UBA binaries from 5.6.0 release up to latest from //UE5/Release-5.7.
For now, the workaround is to modify UBT’s code to skip load cache providers when SA mode is detected. There is no way to affect BuildMachineCacheProviders setting from commandline or environment variable.
That is the code that says that this action produce this .pchast file.
This is also the information uba uses when knowing what to upload to the cache server… if it doesn’t add this file here, then the cache entry will not have the file and you will see a scenario where downloading the cached result of this action will miss this file.
(also, if this is the bug and you fix it, then you would need to wipe your cache server or touch some file included in the pch to make sure you get new entries)
We’re only using MSVC for static analysis at the moment. These are Windows agents with `-Analyzer=Default`.
It’s unclear if the PCH files are not being downloaded, or something causes them to be deleted or cleaned up unexpectedly. They are definitely being uploaded, and correctly, as the same build step usually succeeds. I don’t think I’ve ever seen it fail on a retry, even on the same machine.
I’ve attached partial Horde logs for a bad and good SA run on the same CL. These were done days apart.
It has the stink of a race condition, but I haven’t dug into it much further. I have also been unsuccessful in intentionally reproducing it.
hmm, that is very strange. I wonder if it is possible for the cache client to fail to write a file silently or something. I have never heard of a similar issue before and the epic farm is doing these things 1000s of times per day.
Unfortunately I think this is one of those things where we will need to add a bunch of custom logging to be able to narrow down where this could go wrong. Let’s break it down.
We see the “SharedPCH.UnrealEd.Project.ValApi.ValExpApi.Cpp20.cpp [Cache]” in the log. That means at least that the code went through the uba CacheClient. Do you think you can open the .uba file in visualizer and hover over the pch action and check the stats there.. it should show number of files downloaded and total bytes… a pch like this seems to contain a ton of files In my case 6 of them. a .obj, a .pch, a .pchast, a .json and two .sarif. (those .pchast are huge!). in that failed build.. do you have any of the other files?
The function CacheClient::FetchFile in UbaCacheClient.cpp is the interesting one. I guess we will need to add logging in that one to see what is being requested. When looking at the code I realize we downgrade the logging (errors and warnings to info) because we don’t want a failed cache step to fail the build.. maybe there is something hidden in the logs that could reveal something. The partial logs, are those the actual log-file or copy-pasted from screen? The logs on disk (attached in horde) contains more information that the ones in “view log” in the horde interface
I’ve been looking through the code to see if I can see any way where it could return true (successful cache hit) without actually succeeding but things look correct. So the things to narrow down are
Does the cache entry in the cache server have all the files. Checking so .uba visualizer is showing 6 files is a good step.
Check the attached log in horde for clues (not the one showing when pressing “view log”
See if any of the other files from that cache entry exists on disk.
Attaching the most recent failing Trace.uba I have.
I’ve reproduced the headless build agents as best I can locally, but haven’t figured out what code changes trigger that particular pattern of analysis jobs.
(unrelated, you should disable ntfs last access tracking on this machine and others to save yourself some performance.. you can see in the visualizer view that it is enabled)
I’ve been trying to repro your setup without success :-/
I think you will need to add log entries to the code so we can gather more information.
search for this in UbaCacheClient:
DowngradedLogger logger(m_connected, m_logger.m_writer, TC("UbaCacheClientDownload"));
bool writeCompressed = m_session.ShouldStoreIntermediateFilesCompressed() && g_globalRules.FileCanBeCompressed(path);
if (!fetcher.RetrieveFile(logger, m_client, casKey, path.data, writeCompressed, nullptr, attributes))
return logger.Debug(TC("Failed to download cache output %s for %s"), path.data, info.GetDescription()).ToFalse();
you can add
m_logger.Info(TC("DOWNLOADED FILE %s for %s"), path.data, info.GetDescription());and maybe some more info if you want… changed that logger.Debug to m_logger.Warning or something.
I think this turned out to be a race with our anti-malware software afterall.
Some unrelated change made the issue appear frequently against regular compilation builds, which prompted us to tweak the anti-malware settings. I’ve not seen the issue crop up since.
ok, good to hear… uba actually has a couple retries on permission denied because of similar issues with what seems to be antivirus.. maybe I should try to find the code path to this one and verify so it can retry
In my case 6 of them. a .obj, a .pch, a .pchast, a .json and two .sarif. (those .pchast are huge!). in that failed build.. do you have any of the other files?