Bound the BEP artifact-upload wait with a timeout (#2843)
### Description
Adds a `timeout` parameter to `execute_command()`, passed through to
`subprocess.run`. `upload_test_logs_from_bep()` uses it on the
`bazelci-agent artifact upload` call with a 2 hour limit; on timeout the
process is killed, the failure is logged, and the function returns
without re-raising, since the build's pass/fail result is already
decided by `bazel test` before this step runs -- a killed upload only
loses debug artifacts, not the build outcome. The same timeout is
applied to the `java.log` upload in the same function, which had the
same unbounded `execute_command()` call.
The 2 hour value is an estimate, not a measurement. The only
normal-runtime data available is from rules_scala itself (macOS
`test_rules_scala`: 40-55 min); other projects on this shared fleet may
run longer, worth confirming with maintainers before treating this as
final. A real fix inside `bazelci-agent` itself (detecting that the
writer process died) needs a new agent release; out of scope here.
### Motivation
[rules_scala#1906](https://github.com/bazel-contrib/rules_scala/issues/1906)
found jobs that stall inside `upload_test_logs_from_bep()` until
Buildkite's 8 hour step timeout kills them. This stays invisible because
the build still ends up green (a fast retry on some builds, `soft_fail`
on others), so the job burns most of 8 hours doing nothing and nobody
notices.
The exact hang mechanism inside `bazelci-agent` remains unverified --
the leading theory (bazel exits before writing `lastMessage`, so the
agent waits forever) failed to reproduce with the real binaries. That's
why this bounds the wait from the outside instead of targeting a
specific mechanism.
---------
Co-authored-by: bor-p-s <bpapevis@virtusity.com>
diff --git a/buildkite/bazelci.py b/buildkite/bazelci.py
index 1ca70dc..17c9352 100755
--- a/buildkite/bazelci.py
+++ b/buildkite/bazelci.py
@@ -731,6 +731,7 @@
_TEST_BEP_FILE = "test_bep.json"
_BUILD_BEP_FILE = "build_bep.json"
+_BEP_UPLOAD_TIMEOUT_SECONDS = 2 * 60 * 60
_SHARD_RE = re.compile(r"(.+) \(shard (\d+)\)")
_SLOWEST_N_TARGETS = 20
@@ -1766,7 +1767,11 @@
upload_corrupted_outputs(capture_corrupted_outputs_dir_test, tmpdir)
output_base = get_output_base(bazel_binary)
try:
- upload_log_file(os.path.join(output_base, "java.log"), tmpdir)
+ upload_log_file(
+ os.path.join(output_base, "java.log"),
+ tmpdir,
+ timeout=_BEP_UPLOAD_TIMEOUT_SECONDS,
+ )
except Exception as ex:
eprint(f"Failed to upload java.log: {ex}")
job_url = f"{os.getenv('BUILDKITE_BUILD_URL')}#{os.getenv('BUILDKITE_JOB_ID')}"
@@ -3072,26 +3077,32 @@
return
bazelci_agent_binary = download_bazelci_agent(tmpdir)
- execute_command(
- [
- bazelci_agent_binary,
- "artifact",
- "upload",
- "--debug", # Force BEP upload for non-flaky failures
- "--mode=buildkite",
- "--build_event_json_file={}".format(bep_file),
- ]
- + (["--monitor_flaky_tests"] if monitor_flaky_tests else [])
- )
+ try:
+ execute_command(
+ [
+ bazelci_agent_binary,
+ "artifact",
+ "upload",
+ "--debug", # Force BEP upload for non-flaky failures
+ "--mode=buildkite",
+ "--build_event_json_file={}".format(bep_file),
+ ]
+ + (["--monitor_flaky_tests"] if monitor_flaky_tests else []),
+ timeout=_BEP_UPLOAD_TIMEOUT_SECONDS,
+ )
+ except subprocess.TimeoutExpired as e:
+ eprint("Uploading test logs from BEP timed out: {}".format(e))
-def upload_log_file(log_file_path, tmpdir):
+def upload_log_file(log_file_path, tmpdir, timeout=None):
if local_run_only():
return
if not os.path.exists(log_file_path):
return
print_collapsed_group(f":gcloud: Uploading log file: {log_file_path}")
- execute_command(["buildkite-agent", "artifact", "upload", log_file_path], cwd=tmpdir)
+ execute_command(
+ ["buildkite-agent", "artifact", "upload", log_file_path], cwd=tmpdir, timeout=timeout
+ )
def upload_corrupted_outputs(capture_corrupted_outputs_dir, tmpdir):
@@ -3132,6 +3143,7 @@
capture_stderr=False,
suppress_stdout=False,
env=os.environ,
+ timeout=None,
):
if print_output:
eprint(" ".join(args))
@@ -3148,6 +3160,7 @@
stderr=(
subprocess.PIPE if capture_stderr else None
), # capture_stderr=True when we want exceptions to contain stderr
+ timeout=timeout,
).returncode
diff --git a/buildkite/bazelci_test.py b/buildkite/bazelci_test.py
index 141d055..d3b7aca 100755
--- a/buildkite/bazelci_test.py
+++ b/buildkite/bazelci_test.py
@@ -750,6 +750,22 @@
self.assertIn(["git", "reset", "origin/35.x", "--hard"], executed_commands)
+class ExecuteCommandTimeout(unittest.TestCase):
+ def test_execute_command_raises_on_timeout(self):
+ with self.assertRaises(bazelci.subprocess.TimeoutExpired):
+ bazelci.execute_command(["sleep", "5"], timeout=0.2)
+
+ def test_upload_test_logs_from_bep_does_not_raise_on_timeout(self):
+ with mock.patch.object(
+ bazelci, "download_bazelci_agent", return_value="bazelci-agent"
+ ), mock.patch.object(
+ bazelci,
+ "execute_command",
+ side_effect=bazelci.subprocess.TimeoutExpired(cmd="bazelci-agent", timeout=7200),
+ ):
+ bazelci.upload_test_logs_from_bep("bep.json", "/tmp", monitor_flaky_tests=False)
+
+
if __name__ == "__main__":
unittest.main()