Open ehuss opened 1 month ago
Do you have a link to a failed pipeline run?
You can also copy any of the https://github.com/rust-lang-ci/rust/actions/runs/...
links in the logs above (sorry I didn't make them clickable). Just beware the logs get deleted (90 days?).
PR | Failure cause |
---|---|
#128032 | LINK : fatal error LNK1104: cannot open file 'C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-tools\x86_64-pc-windows-msvc\release\deps\miri-bdcbed7500be44cb.exe' |
#128031 (1) | error: failed to remove file `C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage2-tools\x86_64-pc-windows-msvc\release\cargo.exe |
#128031 (2) | LINK : fatal error LNK1104: cannot open file 'C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-rustc\x86_64-pc-windows-msvc\release\deps\rustc_main-4206913879fae405.exe' |
#124895 | LINK : fatal error LNK1104: cannot open file 'C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-rustc\x86_64-pc-windows-msvc\release\deps\rustc_main-cac7a0b14c781d14.exe' |
#128270 | error: failed to remove file `C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage2-tools\x86_64-pc-windows-msvc\release\cargo.exe`, Access is denied (os error 5) |
#128577 | LINK : fatal error LNK1104: cannot open file 'C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-rustc\x86_64-pc-windows-msvc\release\deps\rustc_main-4f38a2f26fa25d5a.exe' |
#128037 (1) | LINK : fatal error LNK1104: cannot open file 'C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-rustc\x86_64-pc-windows-msvc\release\deps\rustc_main-abe621a284360afc.exe' |
#128037 (2) | LINK : fatal error LNK1104: cannot open file 'C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-rustc\x86_64-pc-windows-msvc\release\deps\rustc_main-abe621a284360afc.exe' |
#128936 | error: failed to remove file `C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage2-tools\x86_64-pc-windows-msvc\release\cargo.exe`, Access is denied (os error 5) |
#129054 | error: failed to remove file `C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage2-tools\x86_64-pc-windows-msvc\release\cargo.exe`, Access is denied (os error 5) |
#129066 | std\src\os\windows\process.rs - os::windows::process::CommandExt::raw_attribute (line 330) stdlib test failed which is very weird, called `Result::unwrap()` on an `Err` value: Os { code: 5, kind: PermissionDenied, message: "Access is denied." |
#128742 | LINK : fatal error LNK1104: cannot open file 'C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-rustc\x86_64-pc-windows-msvc\release\deps\rustc_main-abe621a284360afc.exe' |
#128371 | LINK : fatal error LNK1104: cannot open file 'C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-rustc\x86_64-pc-windows-msvc\release\deps\rustc_main-abe621a284360afc.exe' |
#128677 | LINK : fatal error LNK1104: cannot open file 'C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-rustc\x86_64-pc-windows-msvc\release\deps\rustc_main-abe621a284360afc.exe' |
#128982 | error: failed to remove file `C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage2-tools\x86_64-pc-windows-msvc\release\cargo.exe`, Access is denied (os error 5) |
#128722 | error: failed to remove file `C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-tools\x86_64-pc-windows-msvc\release\miri.exe`, Access is denied. (os error 5) |
#129226 | error: failed to remove file `C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-tools\x86_64-pc-windows-msvc\release\miri.exe`, Access is denied. (os error 5) |
#127672 | error: failed to remove file `C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-tools\x86_64-pc-windows-msvc\release\miri.exe`, Access is denied. (os error 5) |
#129304 | LINK : fatal error LNK1104: cannot open file 'C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-rustc\x86_64-pc-windows-msvc\release\deps\rustc_main-ff540feda8314309.exe' |
It seems like a lot of these failures are specifically miri.exe
for whatever reason, especially recently. Could we just adjust bootstrap to skip the rest of the step on MSVC once it gets to the point that it would remove this file? I'm not sure what exactly relies on this.
I'm planning to investigate some of the file removal logic in bootstrap. Working theory is some symlink removal related logic on Windows.
Crosslinking some ongoing Zulip discussion: https://rust-lang.zulipchat.com/#narrow/stream/246057-t-cargo/topic/Cargo.20investigation.3A.20High.20failure.20rate.20in.20rust-lang.20CI
I opened https://github.com/actions/runner-images/issues/10483 to see if GitHub is able to help us out.
I have been looking in to this. So to sum up, the major issue atm is that builds sometimes fail when overwriting a previous build. Specifically removing the old .exe
files that are hard linked into the final artefact directory fails with access denied. The issue appears to affect windows-msvc builders but not windows-gnu. However, there are a number of differences there (not just gnu vs. msvc) so that doesn't necessarily narrow it down as much as you might hope (although it for sure helps).
One suggestion is that a process like vctip.exe
or other msvc telemetry thing could be holding a lock on the file, preventing it from being deleted. I feel I've thoroughly ruled this possibility out by setting opt-out registry entries and even nuking the exes.
The issue is sporadic which does suggest it's the timing of... something... that leads to this problem. Maybe some process does linger in the background a little too long or maybe we've got an issue with multithreading builds. Maybe neither of those things. Anti-malware can interfere with builds while being outside the confines of our job objects so it's always a possible suspect.
I believe jieyouxu's test PR will help in tracking the issue back to its original source. One of my bootstrap workarounds ended up just punting the problem on so that it's hit by Cargo further down the line. We could add workarounds into Cargo too but it would be more useful to go in the opposite direction and look at where the problem starts.
One last thing, testing this has been slow going. I haven't yet replicated it locally and it takes a while in CI to run. So far my attempts at cutting down the code CI runs has reduced the failure rate, which doesn't help when I want it to fail.
Also it might be confirmation bias, but it sure feels like the failure rate is very high on rollups recently (maybe a week?), its at least once if not multiple times it feels like. On try jobs I can also easily obtain the failure by chance, which is good and bad.
There also seems to be multiple issues leading to such a high failure rate:
---- test::example_with_dev_dep stdout ----
running `C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage2-tools\x86_64-pc-windows-msvc\release\cargo.exe test -v`
thread 'test::example_with_dev_dep' panicked at tests\testsuite\test.rs:2451:10:
test failed running `C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage2-tools\x86_64-pc-windows-msvc\release\cargo.exe test -v`
error: process exited with code 101 (expected 0)
--- stdout
--- stderr
[trimmed]
error: couldn't create a temp dir: Access is denied. (os error 5) at path "C:\\a\\_temp\\msys64\\tmp\\rustcAND7yQ"
error: could not compile `foo` (example "ex") due to 1 previous error
Yeah it looks like (https://github.com/rust-lang/rust/pull/129522#issuecomment-2308644138) we can't delete e.g. C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-tools-bin\miri.exe
so we try to paper over it by renaming the executable, but I'm not sure if that's actually mitigating the problem that we can't remove the executable
2024-08-25T03:58:14.0023046Z [DEBUG] copy_link_internal: src=`C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-tools\x86_64-pc-windows-msvc\release\miri.exe`, dst=`C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-tools-bin\miri.exe`
2024-08-25T03:58:14.0025248Z [DEBUG] copy_link_internal: failed to remove file dst=`C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-tools-bin\miri.exe`: Access is denied. (os error 5)
2024-08-25T03:58:14.0032786Z [DEBUG] copy_link_internal: can't delete, so renamed dst=`C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-tools-bin\miri.exe` to tmp_filename=`C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-tools-bin\miri.exe-1724558294002310100`
2024-08-25T03:58:14.0034684Z [DEBUG] copy_link_internal: saving symlink metadata from src=`C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-tools\x86_64-pc-windows-msvc\release\miri.exe`
2024-08-25T03:58:14.0039400Z [DEBUG] copy_link_internal: created hard link src=`C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-tools\x86_64-pc-windows-msvc\release\miri.exe` with dst=`C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage1-tools-bin\miri.exe`
Also it might be confirmation bias, but it sure feels like the failure rate is very high on rollups recently (maybe a week?), its at least once if not multiple times it feels like. On try jobs I can also easily obtain the failure by chance, which is good and bad.
This definitely feels very true - we have to hitting the problem close to 50% of the time at this point, if not more. Doesn't seem to be limited to rollups though, the LLVM bump failed twice with this, my f16 PR failed three times, https://github.com/rust-lang/rust/pull/129295 is at two...
What's really annoying is that I can't repro these issues locally either.
I wonder if it would be possible to run the runner-images scripts in a VM to reproduce the environment https://github.com/actions/runner-images/blob/d72a4523b15eb2e303c1ea5100a23c34d9475f4f/.github/workflows/windows2022.yml.
If this isn't improved by Monday (seems somewhat unlikely), we should see if infra can get in touch with GH to debug this better. (Not really worth hours of your effort trying to work around things they could get actual answers for)
What's really annoying is that I can't repro these issues locally either.
Specifically, it doesn't fail to remove miri.exe locally, so the rename fallback path is never reached anyway
this could be the same underlying issue as https://github.com/rust-lang/cargo/issues/11544 right? cross linking as I have not seen any references to the cargo ticket here yet
I was googling the error message and amusingly most top hits pointed back at the rust project in some way :smile:
this could be the same underlying issue as rust-lang/cargo#11544 right? cross linking as I have not seen any references to the cargo ticket here yet
It could be one of the causes causing one of the issues potentially yes. We're still trying to pin down the root cause for at least miri.exe removal permission denied issues.
Ok so the problem is that deleting a file (ultimately using DeleteFileW
) sometimes returns ERROR_ACCESS_DENIED
. This is a kind of catch-all error that encompasses a number of lower level status code, including (but not limited to):
STATUS_ACCESS_DENIED
STATUS_DELETE_PENDING
STATUS_FILE_RENAMED
STATUS_CANNOT_DELETE
STATUS_FILE_DELETED
In my tests, the underlying error is STATUS_CANNOT_DELETE
. This may be caused by a race issue. Two operations occurring at the same moment may be running into issues. A workaround would be to simply retry the delete if it encounters ERROR_ACCESS_DENIED
. Perhaps a better approach would be to figure out why it's happening in the first place and to stop doing that.
Cargo sets FILE_ATTRIBUTE_NOT_CONTENT_INDEXED on the target dir, but it looks like bootstrap doesn't for the build dir. I hope github doesn't enable indexing on the CI machines, but if they do then maybe that'd help.
I generated a process monitor .pml file. It can opened using procmon64.
However, I'm not yet seeing any obvious cause of the CANNOT DELETE
failure.
Affects my PR #129019 so I thought I'd take a gander at the PML shared here.
There were two CANNOT_DELETE
errors
One of them happened before any miri.exe
started, the other one after the last miri.exe
exited[1] so a process still running cannot be the root cause. Perhaps SysInternals Handles would show if there are any outstanding handles because of the file being open (the antivirus software might be a common guess)?
[1]:
"21:17:51,1536884","miri.exe","3568","Process Start"
"21:17:51,1886089","miri.exe","3568","Process Exit"
"21:17:51,3615827","miri.exe","6804","Process Start"
"21:17:51,3818521","miri.exe","6804","Process Exit"
"21:17:51,4726410","miri.exe","6372","Process Start"
"21:17:51,5007548","miri.exe","6372","Process Exit"
"21:17:51,5249692","miri.exe","6668","Process Start"
"21:17:51,5494028","miri.exe","6668","Process Exit"
"21:17:51,6786187","miri.exe","7952","Process Start"
"21:17:51,6973346","miri.exe","7952","Process Exit"
"21:17:51,9632364","miri.exe","5180","Process Start"
"21:18:13,9631696","miri.exe","5180","Process Exit"
"21:18:14,0437309","miri.exe","5128","Process Start"
"21:18:14,0876072","miri.exe","5128","Process Exit"
"21:18:14,1211076","miri.exe","6800","Process Start"
"21:18:14,1216762","miri.exe","6328","Process Start"
"21:18:15,0257685","miri.exe","6328","Process Exit"
"21:18:15,1537748","miri.exe","6800","Process Exit"
"21:18:15,1994376","miri.exe","4544","Process Start"
"21:18:15,2018318","miri.exe","8096","Process Start"
"21:18:15,2051426","miri.exe","1300","Process Start"
"21:18:15,2079730","miri.exe","5420","Process Start"
"21:18:15,2133517","miri.exe","2372","Process Start"
"21:18:15,2701454","miri.exe","4544","Process Exit"
"21:18:15,3118628","miri.exe","2796","Process Start"
"21:18:15,3503074","miri.exe","1300","Process Exit"
"21:18:15,4034604","miri.exe","2796","Process Exit"
"21:18:15,7402051","miri.exe","2372","Process Exit"
"21:18:15,7543653","miri.exe","5420","Process Exit"
"21:18:19,3894986","miri.exe","8096","Process Exit"
"21:18:19,4346246","miri.exe","2068","Process Start"
"21:18:19,4356985","miri.exe","1352","Process Start"
"21:18:19,4376855","miri.exe","6368","Process Start"
"21:18:19,5038631","miri.exe","2068","Process Exit"
"21:18:19,5141844","miri.exe","1352","Process Exit"
"21:18:19,5419264","miri.exe","6368","Process Exit"
"21:18:19,5427763","miri.exe","5356","Process Start"
"21:18:19,5444759","miri.exe","5556","Process Start"
"21:18:19,5489962","miri.exe","5016","Process Start"
"21:18:19,5517554","miri.exe","2888","Process Start"
"21:18:19,5549944","miri.exe","5320","Process Start"
"21:18:19,7685154","miri.exe","2888","Process Exit"
"21:18:20,0514524","miri.exe","5556","Process Exit"
"21:18:20,8660293","miri.exe","5016","Process Exit"
"21:18:24,0418653","miri.exe","5356","Process Exit"
"21:18:24,0789019","miri.exe","5964","Process Start"
"21:18:24,6157631","miri.exe","5964","Process Exit"
"21:18:26,7219583","miri.exe","5320","Process Exit"
"21:18:26,7639303","miri.exe","1392","Process Start"
"21:18:32,7115392","miri.exe","1392","Process Exit"
"21:18:32,7770281","miri.exe","7100","Process Start"
"21:18:32,7774907","miri.exe","5904","Process Start"
"21:18:32,8308202","miri.exe","7100","Process Exit"
"21:18:32,8607299","miri.exe","8092","Process Start"
"21:18:33,0002956","miri.exe","8092","Process Exit"
"21:18:33,0317539","miri.exe","5364","Process Start"
"21:18:33,3174302","miri.exe","5364","Process Exit"
"21:18:33,3484207","miri.exe","7484","Process Start"
"21:18:34,4177259","miri.exe","5904","Process Exit"
"21:18:34,4790770","miri.exe","7484","Process Exit"
"21:18:34,5161696","miri.exe","6680","Process Start"
"21:18:34,5636373","miri.exe","6680","Process Exit"
"21:18:34,5947541","miri.exe","8024","Process Start"
"21:18:34,6421069","miri.exe","8024","Process Exit"
"21:18:34,8585954","miri.exe","8056","Process Start"
"21:18:34,8779021","miri.exe","8056","Process Exit"
If the Handles tool doesn't reveal anything, a live kernel dump file a PS helper if no GUI installed or Task Manager (right click on the PID 4 and then "create kernel dump") would be the last resort. Goes w/o saying, the kernel dump should be shared if and only if the machine doesn't carry any sensitive information.
If the Handles tool doesn't reveal anything, a live kernel dump file a PS helper if no GUI installed or Task Manager (right click on the PID 4 and then "create kernel dump") would be the last resort. Goes w/o saying, the kernel dump should be shared if and only if the machine doesn't carry any sensitive information.
The CI machines probably have sensitive authorization tokens somewhere in their memory, unfortunately. Though T-infra is pretty diligent about the principle of least privilege, they still need to move some data around to some fairly specific buckets.
We have tried using Handles
(and other methods) with no success. I think we've exhausted what we can do on our end. Any further investigation on the root cause will need to be handled by github. Either they fix it on their end or they tell us we're doing something wrong. In the meantime all we can do is attempt mitigations.
Starting around 2024-06-27, the rust-lang CI has started to encounter a very high failure rate on the MSVC Windows builders (~15% of all builds?). These builders are encountering various filesystems errors, such as "Access is denied", "used by another process", "cannot open file", etc.
Zulip discussion: https://rust-lang.zulipchat.com/#narrow/stream/242791-t-infra/topic/Spurious.20CI.20errors.20on.20x86_64-msvc-ext
The following is a sample of the errors seen:
Starting 2024-07-02, https://github.com/rust-lang/rust/pull/127152 added a mitigation measure in bootstrap to cover the most common culprit of bootstrap attempting to delete an executable. However, there are several other programs that are still having problems, such as rustc itself, the msvc linker, and cargo.
I have tried using
handle.exe
, and the RestartManager API to try to detect if there is another process with an open handle on a file, but no success.I have tried rolling back the source tree to 2024-06-25, and it still reproduces the problem (before we started seeing it in CI).
The last Windows image release before this started was https://github.com/actions/runner-images/releases/tag/win22%2F20240618.1. From what I can tell, this rolled out about 5 days earlier, during which there weren't any failures, but it is difficult to tell if that could be related.
The last stage0 bump was 2024-06-11, several weeks before it started.
https://github.com/actions/runner-images/issues/4086 is a similar issue we've had in the past, though we don't know what the fix was.
From what I can tell, this doesn't seem to be affecting the GNU builders.