From faba083606790d63c2ac50b1fbdf0ebf0da6ac86 Mon Sep 17 00:00:00 2001 From: bor-p-s Date: Tue, 8 Sep 2026 10:19:53 +0200 Subject: [PATCH 1/2] Bound BEP artifact-upload wait with a timeout --- buildkite/bazelci.py | 41 ++++-- buildkite/bazelci_test.py | 16 +++ .../2026-08-13-bep-upload-timeout-design.md | 121 ++++++++++++++++++ 3 files changed, 164 insertions(+), 14 deletions(-) create mode 100644 docs/superpowers/specs/2026-08-13-bep-upload-timeout-design.md diff --git a/buildkite/bazelci.py b/buildkite/bazelci.py index 1ca70dcc77..17c935220c 100755 --- a/buildkite/bazelci.py +++ b/buildkite/bazelci.py @@ -731,6 +731,7 @@ def get_docker_image(image_name, is_arm64=False): _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 @@ def PrepareRepoInCwd(print_cmd_groups, initial_setup=False): 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 @@ def upload_test_logs_from_bep(bep_file, tmpdir, monitor_flaky_tests): 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 @@ def execute_command( capture_stderr=False, suppress_stdout=False, env=os.environ, + timeout=None, ): if print_output: eprint(" ".join(args)) @@ -3148,6 +3160,7 @@ def execute_command( 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 141d0552eb..d3b7acae69 100755 --- a/buildkite/bazelci_test.py +++ b/buildkite/bazelci_test.py @@ -750,6 +750,22 @@ def fake_execute(args, print_output=True, suppress_stdout=False): 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() diff --git a/docs/superpowers/specs/2026-08-13-bep-upload-timeout-design.md b/docs/superpowers/specs/2026-08-13-bep-upload-timeout-design.md new file mode 100644 index 0000000000..73cc8818ae --- /dev/null +++ b/docs/superpowers/specs/2026-08-13-bep-upload-timeout-design.md @@ -0,0 +1,121 @@ +# BEP upload timeout + +## Problem + +`upload_test_logs_from_bep()` runs on a background thread concurrent with +`bazel test`, following the BEP JSON file until it sees a `lastMessage` event +and then uploading it (and any failed/flaky test logs) via `bazelci-agent +artifact upload`. `bazelci.py:1671` (`future.result()`) waits on that thread +unconditionally. + +The exact hang mechanism inside `bazelci-agent` is **not confirmed** — flagging +this explicitly since an earlier version of this doc overstated it as settled. + +What's actually verified (rules_scala build 6444, logs from all four +platforms): `bazel test` fails instantly on an unrecognized flag +(`--local_extra_resources=bazel_instance=1`, from an experimental +"do not merge" branch), and the very next line launches `bazelci-agent +artifact upload`, which then produces no further output for the full 8-hour +step timeout (`bazelci.py:3104`) before being killed externally. + +The obvious theory — bazel dies before writing `lastMessage` to the BEP file, +so `follow()` (`agent/src/utils/follow.rs:36-39`) polls forever waiting for +bytes that never arrive — does **not** hold up under direct reproduction. +Running the same bazel 9.2.0 + bazelci-agent 0.2.7 binaries with the same +flag and the same file-creation race as `bazelci.py`, `bazel` exits in under +a second, but the BEP file still ends with a proper `lastMessage:true` line, +and the agent reaches `buildkite-agent artifact upload ` within a +second too — the opposite of what the theory predicts. Whatever the real +production job actually gets stuck on remains open; something differs +between the repro and the real hang that hasn't been identified. + +Two follow-up theories were also tested and ruled out, rather than left +unexamined: +- **Output buffering hiding a real hang**: maybe the agent does reach + `buildkite-agent artifact upload ` in production and hangs + there, but Rust's stdout is block-buffered when piped to a non-tty, so the + print never surfaces before the process is killed. Reproduced with the + real 0.2.7 binary, a stub `buildkite-agent` that sleeps forever, and the + pipe read directly (not via a blocking `readline()`): the upload-call print + reaches the pipe in under a second, well before the process is still + hanging 5+ seconds later. If the same thing happened in production, the + print should have shown up in the Buildkite log — it didn't. Ruled out. +- **`buildkite-agent`/network broadly down on that machine**: in the same + hung job, a separate `buildkite-agent artifact upload` call for `java.log` + (issued directly from `bazelci.py`, not through the Rust agent) succeeded + around the same time — so the CLI and network were working on that + machine at that moment. Weakens a generic "infra was down" explanation. + +This is exactly why the fix below doesn't try to address a specific +mechanism inside the agent: it bounds the wait from the outside, which works +regardless of what turns out to be the actual cause. + +## Non-goals + +- Fixing the agent itself (`agent/src/artifact/upload.rs`, + `agent/src/utils/follow.rs`) to detect that the writer process died. Real + root-cause fix, but needs a new agent release and version bump + (`bazelci.py:1939` pins `0.2.7`). Mention as a follow-up in the PR, don't + implement now. +- Per-project/per-task timeout overrides. `bazelci.py` is shared by every + project on this Buildkite fleet; a configurable override is a reasonable + future improvement but out of scope here. + +## Design + +Bound the one subprocess call that can hang, using `subprocess.run`'s own +`timeout` kwarg — no new mechanism needed: + +- `execute_command()` gets a new `timeout=None` parameter, passed through to + `subprocess.run(..., timeout=timeout)`. +- `upload_test_logs_from_bep()` wraps only the `bazelci-agent artifact + upload` call (not `download_bazelci_agent`, which is an unrelated short + binary download) with a new module constant: + `_BEP_UPLOAD_TIMEOUT_SECONDS = 2 * 60 * 60` (2 hours). +- On `subprocess.TimeoutExpired`, log via `eprint` and return normally + (don't re-raise). + +`subprocess.run(timeout=N)` kills the child process itself on expiry, so no +change is needed to the `with ThreadPoolExecutor(): ... future.result()` +block at `bazelci.py:1629-1671` — the thread function now always returns +within 2 hours, so the executor's `shutdown(wait=True)` and `future.result()` +resolve promptly. + +`upload_log_file()` also gets the same `timeout` passthrough, applied only +at its `java.log` call site (`bazelci.py:1654`, same function, same +`buildkite-agent artifact upload` defect class as the fix above, already +wrapped in its own `try/except`). Other `upload_log_file()` callers are +unaffected (default `timeout=None`). + +### Timeout value + +2 hours, picked as a margin over normal runtime versus the existing global +8-hour step timeout (`bazelci.py:3104`) — the only number that applies +uniformly to every project on this shared fleet, since a killed upload here +doesn't fail the build (bazel's pass/fail verdict is already decided before +this step runs; only debug artifacts are lost). Not validated against other +projects' normal runtimes — call this out to the repo maintainers when +posting the fix. + +### Error visibility + +Log-only (`eprint`), no Buildkite annotation. Less code; matches the low +severity of the failure (lost debug artifacts, not a build failure). + +## Testing + +Two unit tests in `bazelci_test.py`: +1. `execute_command` with a real hanging subprocess and a short timeout + raises `TimeoutExpired`. +2. `upload_test_logs_from_bep`, with `execute_command` mocked to raise + `TimeoutExpired`, does not propagate the exception. + +## Rollout + +Post the fix to `bazelbuild/continuous-integration`. Mention in the PR: +that the exact hang mechanism inside `bazelci-agent` is still unverified +(the leading theory was tested by direct reproduction and didn't hold up — +see Problem section), that the fix is deliberately symptom-level because of +that, the 2-hour value as a starting point pending confirmation from +maintainers about other projects' normal runtimes, and an agent-side +investigation/fix as a possible follow-up once the real mechanism is found. From 72dba96571a21f151295bbf8d7a2fa9bf06df095 Mon Sep 17 00:00:00 2001 From: bor-p-s Date: Wed, 9 Sep 2026 12:25:26 +0200 Subject: [PATCH 2/2] Remove design doc from the PR --- .../2026-08-13-bep-upload-timeout-design.md | 121 ------------------ 1 file changed, 121 deletions(-) delete mode 100644 docs/superpowers/specs/2026-08-13-bep-upload-timeout-design.md diff --git a/docs/superpowers/specs/2026-08-13-bep-upload-timeout-design.md b/docs/superpowers/specs/2026-08-13-bep-upload-timeout-design.md deleted file mode 100644 index 73cc8818ae..0000000000 --- a/docs/superpowers/specs/2026-08-13-bep-upload-timeout-design.md +++ /dev/null @@ -1,121 +0,0 @@ -# BEP upload timeout - -## Problem - -`upload_test_logs_from_bep()` runs on a background thread concurrent with -`bazel test`, following the BEP JSON file until it sees a `lastMessage` event -and then uploading it (and any failed/flaky test logs) via `bazelci-agent -artifact upload`. `bazelci.py:1671` (`future.result()`) waits on that thread -unconditionally. - -The exact hang mechanism inside `bazelci-agent` is **not confirmed** — flagging -this explicitly since an earlier version of this doc overstated it as settled. - -What's actually verified (rules_scala build 6444, logs from all four -platforms): `bazel test` fails instantly on an unrecognized flag -(`--local_extra_resources=bazel_instance=1`, from an experimental -"do not merge" branch), and the very next line launches `bazelci-agent -artifact upload`, which then produces no further output for the full 8-hour -step timeout (`bazelci.py:3104`) before being killed externally. - -The obvious theory — bazel dies before writing `lastMessage` to the BEP file, -so `follow()` (`agent/src/utils/follow.rs:36-39`) polls forever waiting for -bytes that never arrive — does **not** hold up under direct reproduction. -Running the same bazel 9.2.0 + bazelci-agent 0.2.7 binaries with the same -flag and the same file-creation race as `bazelci.py`, `bazel` exits in under -a second, but the BEP file still ends with a proper `lastMessage:true` line, -and the agent reaches `buildkite-agent artifact upload ` within a -second too — the opposite of what the theory predicts. Whatever the real -production job actually gets stuck on remains open; something differs -between the repro and the real hang that hasn't been identified. - -Two follow-up theories were also tested and ruled out, rather than left -unexamined: -- **Output buffering hiding a real hang**: maybe the agent does reach - `buildkite-agent artifact upload ` in production and hangs - there, but Rust's stdout is block-buffered when piped to a non-tty, so the - print never surfaces before the process is killed. Reproduced with the - real 0.2.7 binary, a stub `buildkite-agent` that sleeps forever, and the - pipe read directly (not via a blocking `readline()`): the upload-call print - reaches the pipe in under a second, well before the process is still - hanging 5+ seconds later. If the same thing happened in production, the - print should have shown up in the Buildkite log — it didn't. Ruled out. -- **`buildkite-agent`/network broadly down on that machine**: in the same - hung job, a separate `buildkite-agent artifact upload` call for `java.log` - (issued directly from `bazelci.py`, not through the Rust agent) succeeded - around the same time — so the CLI and network were working on that - machine at that moment. Weakens a generic "infra was down" explanation. - -This is exactly why the fix below doesn't try to address a specific -mechanism inside the agent: it bounds the wait from the outside, which works -regardless of what turns out to be the actual cause. - -## Non-goals - -- Fixing the agent itself (`agent/src/artifact/upload.rs`, - `agent/src/utils/follow.rs`) to detect that the writer process died. Real - root-cause fix, but needs a new agent release and version bump - (`bazelci.py:1939` pins `0.2.7`). Mention as a follow-up in the PR, don't - implement now. -- Per-project/per-task timeout overrides. `bazelci.py` is shared by every - project on this Buildkite fleet; a configurable override is a reasonable - future improvement but out of scope here. - -## Design - -Bound the one subprocess call that can hang, using `subprocess.run`'s own -`timeout` kwarg — no new mechanism needed: - -- `execute_command()` gets a new `timeout=None` parameter, passed through to - `subprocess.run(..., timeout=timeout)`. -- `upload_test_logs_from_bep()` wraps only the `bazelci-agent artifact - upload` call (not `download_bazelci_agent`, which is an unrelated short - binary download) with a new module constant: - `_BEP_UPLOAD_TIMEOUT_SECONDS = 2 * 60 * 60` (2 hours). -- On `subprocess.TimeoutExpired`, log via `eprint` and return normally - (don't re-raise). - -`subprocess.run(timeout=N)` kills the child process itself on expiry, so no -change is needed to the `with ThreadPoolExecutor(): ... future.result()` -block at `bazelci.py:1629-1671` — the thread function now always returns -within 2 hours, so the executor's `shutdown(wait=True)` and `future.result()` -resolve promptly. - -`upload_log_file()` also gets the same `timeout` passthrough, applied only -at its `java.log` call site (`bazelci.py:1654`, same function, same -`buildkite-agent artifact upload` defect class as the fix above, already -wrapped in its own `try/except`). Other `upload_log_file()` callers are -unaffected (default `timeout=None`). - -### Timeout value - -2 hours, picked as a margin over normal runtime versus the existing global -8-hour step timeout (`bazelci.py:3104`) — the only number that applies -uniformly to every project on this shared fleet, since a killed upload here -doesn't fail the build (bazel's pass/fail verdict is already decided before -this step runs; only debug artifacts are lost). Not validated against other -projects' normal runtimes — call this out to the repo maintainers when -posting the fix. - -### Error visibility - -Log-only (`eprint`), no Buildkite annotation. Less code; matches the low -severity of the failure (lost debug artifacts, not a build failure). - -## Testing - -Two unit tests in `bazelci_test.py`: -1. `execute_command` with a real hanging subprocess and a short timeout - raises `TimeoutExpired`. -2. `upload_test_logs_from_bep`, with `execute_command` mocked to raise - `TimeoutExpired`, does not propagate the exception. - -## Rollout - -Post the fix to `bazelbuild/continuous-integration`. Mention in the PR: -that the exact hang mechanism inside `bazelci-agent` is still unverified -(the leading theory was tested by direct reproduction and didn't hold up — -see Problem section), that the fix is deliberately symptom-level because of -that, the 2-hour value as a starting point pending confirmation from -maintainers about other projects' normal runtimes, and an agent-side -investigation/fix as a possible follow-up once the real mechanism is found.