From f60ed3f918d526848b3958409bfd56f9d88e27df Mon Sep 17 00:00:00 2001 From: ejc3 Date: Sun, 13 Sep 2026 16:27:12 +0000 Subject: [PATCH 1/2] Wait for boot-time apt locks in self-hosted CI jobs A self-hosted runner is a freshly booted instance, and its boot-time apt can still hold a lock when the first job starts. On 2026-09-13 Host-arm64 on #921 (run 34766944283) was assigned 74 s after runner i-09d787d5b03c94b13 launched and failed in "Install dependencies": E: Could not get lock /var/lib/dpkg/lock-frontend. It is held by process 3180 (apt) scripts/ci-apt-get.sh runs apt-get with -o DPkg::Lock::Timeout and retries a failure that reports a held lock until APT_LOCK_WAIT (600 s). Any other failure, or a lock still held at the deadline, returns apt-get's own status. The timeout alone is not enough: measured on an arm64 host with each lock held by another process, install rc=100 in 0.0 s install -o DPkg::Lock::Timeout=30 waited, rc=0 in 11.4 s update rc=100 in 0.8 s update -o DPkg::Lock::Timeout=30 rc=100 in 0.8 s Every apt-get call in a self-hosted job (ci.yml host and host-root, kernels.yml, teardown-evidence.yml, weekly.yml; 24 calls) now goes through the script. Hosted ubuntu-latest jobs are unchanged. Tests (tests/test_ci_workflow_coverage.rs): - self_hosted_apt_calls_wait_for_apt_locks: every apt-get line in a self-hosted job uses ./fcvm/scripts/ci-apt-get.sh from the workspace root, and the walk inspected at least one call. - ci_apt_get_retries_a_held_lock_and_nothing_else: a fake apt-get that reports a held lock twice then succeeds ends in rc 0 after 3 calls, each passing DPkg::Lock::Timeout; another error returns 100 after 1 call; a lock still held at the deadline returns 100. Red without the script and workflow edits: 2 tests run: 0 passed, 2 failed Green with both: 2 tests run: 2 passed Red again, workflow edits reverted: 2 tests run: 1 passed, 1 failed (self_hosted_apt_calls_wait_for_apt_locks) test_ci_workflow_coverage, whole binary: 25 tests run: 25 passed --- .github/workflows/ci.yml | 10 +- .github/workflows/kernels.yml | 24 ++-- .github/workflows/teardown-evidence.yml | 4 +- .github/workflows/weekly.yml | 8 +- scripts/ci-apt-get.sh | 48 ++++++++ tests/test_ci_workflow_coverage.rs | 153 ++++++++++++++++++++++++ 6 files changed, 224 insertions(+), 23 deletions(-) create mode 100755 scripts/ci-apt-get.sh diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index d02576dbf..711e5f81e 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -443,8 +443,8 @@ jobs: shared-key: deps-${{ steps.deps.outputs.fuser }}-${{ steps.deps.outputs.fuse-backend-rs }} - name: Install dependencies run: | - sudo apt-get update - sudo apt-get install -y fuse3 libfuse3-dev libclang-dev clang musl-tools \ + ./fcvm/scripts/ci-apt-get.sh update + ./fcvm/scripts/ci-apt-get.sh install -y fuse3 libfuse3-dev libclang-dev clang musl-tools \ iproute2 iptables passt dnsmasq qemu-utils e2fsprogs parted patch \ podman skopeo busybox-static cpio zstd autoconf automake libtool cmake \ libseccomp-dev nfs-kernel-server \ @@ -699,8 +699,8 @@ jobs: shared-key: deps-${{ steps.deps.outputs.fuser }}-${{ steps.deps.outputs.fuse-backend-rs }} - name: Install dependencies run: | - sudo apt-get update - sudo apt-get install -y fuse3 libfuse3-dev libclang-dev clang musl-tools \ + ./fcvm/scripts/ci-apt-get.sh update + ./fcvm/scripts/ci-apt-get.sh install -y fuse3 libfuse3-dev libclang-dev clang musl-tools \ iproute2 iptables passt dnsmasq qemu-utils e2fsprogs parted patch \ podman skopeo busybox-static cpio zstd autoconf automake libtool cmake \ libseccomp-dev nfs-kernel-server \ @@ -769,7 +769,7 @@ jobs: # exit 125 before any test ran, 2026-08-13). ./fcvm/scripts/runner-podman-hygiene.sh # Install iperf3 for network benchmarks - sudo apt-get update && sudo apt-get install -y iperf3 || true + ./fcvm/scripts/ci-apt-get.sh update && ./fcvm/scripts/ci-apt-get.sh install -y iperf3 || true - name: Create test log directory run: sudo rm -rf /tmp/fcvm-test-logs && mkdir -p /tmp/fcvm-test-logs - name: Clean test data diff --git a/.github/workflows/kernels.yml b/.github/workflows/kernels.yml index 837f1aed3..f6f81422e 100644 --- a/.github/workflows/kernels.yml +++ b/.github/workflows/kernels.yml @@ -62,8 +62,8 @@ jobs: - name: Install build dependencies run: | - sudo apt-get update - sudo apt-get install -y flex bison bc libelf-dev libssl-dev libfuse3-dev libclang-dev clang musl-tools + ./fcvm/scripts/ci-apt-get.sh update + ./fcvm/scripts/ci-apt-get.sh install -y flex bison bc libelf-dev libssl-dev libfuse3-dev libclang-dev clang musl-tools - name: Build fcvm and fc-agent working-directory: fcvm @@ -127,8 +127,8 @@ jobs: - name: Install GitHub CLI run: | if ! command -v gh &> /dev/null; then - sudo apt-get update - sudo apt-get install -y gh + ./fcvm/scripts/ci-apt-get.sh update + ./fcvm/scripts/ci-apt-get.sh install -y gh else echo "GitHub CLI already installed: $(gh --version)" fi @@ -244,8 +244,8 @@ jobs: - name: Install build dependencies run: | - sudo apt-get update - sudo apt-get install -y flex bison bc libelf-dev libssl-dev libfuse3-dev libclang-dev clang musl-tools + ./fcvm/scripts/ci-apt-get.sh update + ./fcvm/scripts/ci-apt-get.sh install -y flex bison bc libelf-dev libssl-dev libfuse3-dev libclang-dev clang musl-tools - name: Build fcvm and fc-agent working-directory: fcvm @@ -286,8 +286,8 @@ jobs: run: | if ! command -v gh &> /dev/null; then echo "Installing GitHub CLI..." - sudo apt-get update - sudo apt-get install -y gh + ./fcvm/scripts/ci-apt-get.sh update + ./fcvm/scripts/ci-apt-get.sh install -y gh else echo "GitHub CLI already installed: $(gh --version)" fi @@ -469,8 +469,8 @@ jobs: - name: Install build dependencies run: | - sudo apt-get update - sudo apt-get install -y flex bison bc libelf-dev libssl-dev libfuse3-dev libclang-dev clang musl-tools + ./fcvm/scripts/ci-apt-get.sh update + ./fcvm/scripts/ci-apt-get.sh install -y flex bison bc libelf-dev libssl-dev libfuse3-dev libclang-dev clang musl-tools - name: Build fcvm and fc-agent working-directory: fcvm @@ -511,8 +511,8 @@ jobs: run: | if ! command -v gh &> /dev/null; then echo "Installing GitHub CLI..." - sudo apt-get update - sudo apt-get install -y gh + ./fcvm/scripts/ci-apt-get.sh update + ./fcvm/scripts/ci-apt-get.sh install -y gh else echo "GitHub CLI already installed: $(gh --version)" fi diff --git a/.github/workflows/teardown-evidence.yml b/.github/workflows/teardown-evidence.yml index 70a4f38b9..2eb5ec26c 100644 --- a/.github/workflows/teardown-evidence.yml +++ b/.github/workflows/teardown-evidence.yml @@ -53,8 +53,8 @@ jobs: rustup show active-toolchain || true - name: Install dependencies run: | - sudo apt-get update - sudo apt-get install -y fuse3 libfuse3-dev libclang-dev clang musl-tools \ + ./fcvm/scripts/ci-apt-get.sh update + ./fcvm/scripts/ci-apt-get.sh install -y fuse3 libfuse3-dev libclang-dev clang musl-tools \ iproute2 iptables passt dnsmasq qemu-utils e2fsprogs parted patch \ podman skopeo busybox-static cpio zstd autoconf automake libtool cmake \ libseccomp-dev dmsetup diff --git a/.github/workflows/weekly.yml b/.github/workflows/weekly.yml index 74283d4db..c19eb050b 100644 --- a/.github/workflows/weekly.yml +++ b/.github/workflows/weekly.yml @@ -56,8 +56,8 @@ jobs: rustup show active-toolchain || true - name: Install dependencies run: | - sudo apt-get update - sudo apt-get install -y fuse3 libfuse3-dev libclang-dev clang musl-tools \ + ./fcvm/scripts/ci-apt-get.sh update + ./fcvm/scripts/ci-apt-get.sh install -y fuse3 libfuse3-dev libclang-dev clang musl-tools \ iproute2 iptables passt dnsmasq qemu-utils e2fsprogs parted patch \ podman skopeo busybox-static cpio zstd autoconf automake libtool cmake \ libseccomp-dev @@ -154,8 +154,8 @@ jobs: echo "$HOME/.cargo/bin" >> $GITHUB_PATH - name: Install dependencies run: | - sudo apt-get update - sudo apt-get install -y fuse3 libfuse3-dev libclang-dev clang musl-tools \ + ./fcvm/scripts/ci-apt-get.sh update + ./fcvm/scripts/ci-apt-get.sh install -y fuse3 libfuse3-dev libclang-dev clang musl-tools \ iproute2 iptables passt dnsmasq qemu-utils e2fsprogs parted patch \ podman skopeo busybox-static cpio zstd autoconf automake libtool cmake \ libseccomp-dev diff --git a/scripts/ci-apt-get.sh b/scripts/ci-apt-get.sh new file mode 100755 index 000000000..86028a353 --- /dev/null +++ b/scripts/ci-apt-get.sh @@ -0,0 +1,48 @@ +#!/usr/bin/env bash +# apt-get for self-hosted CI jobs: wait for another apt process to release its lock instead +# of failing on it. +# +# A self-hosted runner is a freshly booted instance, and its boot-time apt can still hold a +# lock when the first job starts. On 2026-09-13 Host-arm64 on #921 was assigned 74 s after +# its runner launched and failed in "Install dependencies" with +# E: Could not get lock /var/lib/dpkg/lock-frontend. It is held by process 3180 (apt) +# +# DPkg::Lock::Timeout makes `apt-get install` wait for the dpkg frontend lock. It does not +# cover the lists lock that `apt-get update` takes. Measured with each lock held by another +# process: +# install rc=100 in 0.0 s +# install -o DPkg::Lock::Timeout=30 waited, rc=0 in 11.4 s +# update rc=100 in 0.8 s +# update -o DPkg::Lock::Timeout=30 rc=100 in 0.8 s +# So the timeout is passed for the frontend lock, and a failure that reports a held lock is +# retried until APT_LOCK_WAIT seconds have passed. Any other failure, or a lock still held at +# the deadline, returns apt-get's own exit status. Each attempt is one whole apt-get run, so +# there is no window between checking a lock and taking it. +# +# Usage: scripts/ci-apt-get.sh +# APT_GET, SUDO and APT_LOCK_RETRY_S exist for tests/test_ci_workflow_coverage.rs. +set -uo pipefail + +wait_s=${APT_LOCK_WAIT:-600} +retry_s=${APT_LOCK_RETRY_S:-5} +apt_get=${APT_GET:-apt-get} +sudo_cmd=${SUDO-sudo} + +out=$(mktemp) || exit 1 +trap 'rm -f "$out"' EXIT +deadline=$((SECONDS + wait_s)) +attempt=0 +while :; do + attempt=$((attempt + 1)) + left=$((deadline - SECONDS)) + [ "$left" -gt 0 ] || left=1 + $sudo_cmd "$apt_get" -o DPkg::Lock::Timeout="$left" "$@" 2>&1 | tee "$out" + rc=${PIPESTATUS[0]} + [ "$rc" -eq 0 ] && exit 0 + if grep -qE '^E: Could not get lock ' "$out" && [ "$SECONDS" -lt "$deadline" ]; then + echo "ci-apt-get: attempt $attempt found an apt lock held by another process; retrying in ${retry_s}s ($((deadline - SECONDS))s left)" >&2 + sleep "$retry_s" + continue + fi + exit "$rc" +done diff --git a/tests/test_ci_workflow_coverage.rs b/tests/test_ci_workflow_coverage.rs index bdcaeaf82..e7b1b0f0f 100644 --- a/tests/test_ci_workflow_coverage.rs +++ b/tests/test_ci_workflow_coverage.rs @@ -1546,3 +1546,156 @@ fn the_changes_job_emits_every_output_the_matrix_gates_on() { ); } } + +/// Every apt-get call in a self-hosted job goes through `scripts/ci-apt-get.sh`. +/// +/// A self-hosted runner is a freshly booted instance, and its boot-time apt can still hold a +/// lock when the job starts. On 2026-09-13 Host-arm64 on #921 was assigned 74 s after its +/// runner launched and failed in "Install dependencies" with +/// `E: Could not get lock /var/lib/dpkg/lock-frontend. It is held by process 3180 (apt)`. +/// A bare `sudo apt-get` fails on a held lock; the script waits for it. +#[test] +fn self_hosted_apt_calls_wait_for_apt_locks() { + let dir = PathBuf::from(env!("CARGO_MANIFEST_DIR")).join(".github/workflows"); + let entries = + std::fs::read_dir(&dir).unwrap_or_else(|e| panic!("cannot read {}: {e}", dir.display())); + + let mut checked = 0usize; + for entry in entries { + let path = entry.expect("dir entry").path(); + if path.extension().and_then(|e| e.to_str()) != Some("yml") { + continue; + } + let name = path.file_name().unwrap().to_string_lossy().to_string(); + let wf: Value = serde_norway::from_str(&std::fs::read_to_string(&path).unwrap()) + .unwrap_or_else(|e| panic!("{name} is not valid YAML: {e}")); + let Some(jobs) = wf.get("jobs").and_then(Value::as_mapping) else { + continue; + }; + for (job_name, job) in jobs { + let runs_on = job + .get("runs-on") + .map(|v| format!("{v:?}")) + .unwrap_or_default(); + if !runs_on.contains("self-hosted") { + continue; + } + let job_label = job_name.as_str().unwrap_or(""); + let Some(steps) = job.get("steps").and_then(Value::as_sequence) else { + continue; + }; + for step in steps { + let Some(run) = step.get("run").and_then(Value::as_str) else { + continue; + }; + for line in run.lines().map(|l| l.split('#').next().unwrap_or("")) { + if !line.contains("apt-get") { + continue; + } + checked += 1; + assert!( + !line + .replace("./fcvm/scripts/ci-apt-get.sh", "") + .contains("apt-get"), + "{name}: self-hosted job `{job_label}` calls apt-get directly: `{}`. \ + A boot-time apt on a fresh runner can hold the dpkg or lists lock, and \ + apt-get fails on it at once. Use ./fcvm/scripts/ci-apt-get.sh.", + line.trim() + ); + // The path is relative to the workspace root, where `path: fcvm` checks + // the repo out. + assert!( + step.get("working-directory").is_none(), + "{name}: job `{job_label}` calls ./fcvm/scripts/ci-apt-get.sh from a step \ + with a working-directory, where that path does not resolve" + ); + } + } + } + } + assert!( + checked > 0, + "found no apt-get calls in self-hosted jobs to inspect. The walk is broken, and a check \ + that inspects nothing must not report success" + ); +} + +/// `scripts/ci-apt-get.sh` retries a held apt lock until its deadline, and nothing else. +/// +/// Driven with a fake apt-get that records its arguments and plays one outcome per call: +/// `lock` prints apt's held-lock error, `other` prints a different error (both exit 100), +/// and anything else exits 0. +#[test] +fn ci_apt_get_retries_a_held_lock_and_nothing_else() { + use std::os::unix::fs::PermissionsExt; + + let script = PathBuf::from(env!("CARGO_MANIFEST_DIR")).join("scripts/ci-apt-get.sh"); + let dir = std::env::temp_dir().join(format!("fcvm-ci-apt-get-{}", std::process::id())); + std::fs::create_dir_all(&dir).unwrap(); + let fake = dir.join("apt-get"); + std::fs::write( + &fake, + r#"#!/bin/bash +d=$(dirname "$0") +echo "$*" >> "$d/calls" +step=$(sed -n "$(wc -l < "$d/calls")p" "$d/plan") +case "$step" in + lock) echo 'E: Could not get lock /var/lib/apt/lists/lock. It is held by process 3180 (apt)'; exit 100 ;; + other) echo 'E: Unable to locate package no-such-package'; exit 100 ;; + *) exit 0 ;; +esac +"#, + ) + .unwrap(); + std::fs::set_permissions(&fake, std::fs::Permissions::from_mode(0o755)).unwrap(); + + let run = |plan: &[&str], wait_s: &str| -> (i32, Vec) { + let _ = std::fs::remove_file(dir.join("calls")); + std::fs::write(dir.join("plan"), plan.join("\n") + "\n").unwrap(); + let out = std::process::Command::new("bash") + .arg(&script) + .arg("update") + .env("APT_GET", &fake) + .env("SUDO", "") + .env("APT_LOCK_RETRY_S", "0") + .env("APT_LOCK_WAIT", wait_s) + .output() + .expect("bash must be runnable"); + let calls = std::fs::read_to_string(dir.join("calls")) + .unwrap_or_default() + .lines() + .map(str::to_string) + .collect(); + (out.status.code().unwrap_or(-1), calls) + }; + + let (code, calls) = run(&["lock", "lock", "ok"], "60"); + assert_eq!( + code, 0, + "a lock released after two attempts must end in success: {calls:?}" + ); + assert_eq!(calls.len(), 3, "{calls:?}"); + assert!( + calls + .iter() + .all(|c| c.starts_with("-o DPkg::Lock::Timeout=") && c.ends_with(" update")), + "every attempt must pass the dpkg lock timeout and the caller's arguments: {calls:?}" + ); + + let (code, calls) = run(&["other", "ok"], "60"); + assert_eq!( + code, 100, + "a failure that is not a held lock is apt-get's answer: {calls:?}" + ); + assert_eq!(calls.len(), 1, "it must not be retried: {calls:?}"); + + let held = vec!["lock"; 20]; + let (code, calls) = run(&held, "0"); + assert_eq!( + code, 100, + "a lock still held at the deadline must fail with apt-get's status: {calls:?}" + ); + assert_eq!(calls.len(), 1, "{calls:?}"); + + let _ = std::fs::remove_dir_all(&dir); +} From 6be819422e0876f54127baafdc74c623485ea4c4 Mon Sep 17 00:00:00 2001 From: ejc3 Date: Sun, 13 Sep 2026 18:37:40 +0000 Subject: [PATCH 2/2] Stop apt lock retries when a retry sleep crosses the deadline ci-apt-get.sh checked the deadline before each retry sleep, so a sleep that crossed it was followed by one more apt-get attempt, run with DPkg::Lock::Timeout forced to 1 (CodeRabbit on #925). The loop now checks the deadline again after the sleep and returns the last apt-get status. ci_apt_get_retries_a_held_lock_and_nothing_else covers it with APT_LOCK_WAIT=1 and APT_LOCK_RETRY_S=2 against a lock that stays held: one apt-get call, exit 100. Red on the unfixed script: 2 calls ("-o DPkg::Lock::Timeout=1 update" twice) Green with the fix: 1 test run: 1 passed Red again, fix reverted: 1 test run: 0 passed, 1 failed test_ci_workflow_coverage: 25 tests run: 25 passed make lint: exit 0 --- scripts/ci-apt-get.sh | 1 + tests/test_ci_workflow_coverage.rs | 29 +++++++++++++++++++++++++++++ 2 files changed, 30 insertions(+) diff --git a/scripts/ci-apt-get.sh b/scripts/ci-apt-get.sh index 86028a353..80e5d22f7 100755 --- a/scripts/ci-apt-get.sh +++ b/scripts/ci-apt-get.sh @@ -42,6 +42,7 @@ while :; do if grep -qE '^E: Could not get lock ' "$out" && [ "$SECONDS" -lt "$deadline" ]; then echo "ci-apt-get: attempt $attempt found an apt lock held by another process; retrying in ${retry_s}s ($((deadline - SECONDS))s left)" >&2 sleep "$retry_s" + [ "$SECONDS" -lt "$deadline" ] || exit "$rc" continue fi exit "$rc" diff --git a/tests/test_ci_workflow_coverage.rs b/tests/test_ci_workflow_coverage.rs index e7b1b0f0f..76577f428 100644 --- a/tests/test_ci_workflow_coverage.rs +++ b/tests/test_ci_workflow_coverage.rs @@ -1697,5 +1697,34 @@ esac ); assert_eq!(calls.len(), 1, "{calls:?}"); + // A retry sleep that crosses the deadline ends the wait. Checking the deadline only before + // the sleep started one more apt-get after it had passed (CodeRabbit on #925). + let _ = std::fs::remove_file(dir.join("calls")); + std::fs::write(dir.join("plan"), held.join("\n") + "\n").unwrap(); + let out = std::process::Command::new("bash") + .arg(&script) + .arg("update") + .env("APT_GET", &fake) + .env("SUDO", "") + .env("APT_LOCK_RETRY_S", "2") + .env("APT_LOCK_WAIT", "1") + .output() + .expect("bash must be runnable"); + let calls: Vec = std::fs::read_to_string(dir.join("calls")) + .unwrap_or_default() + .lines() + .map(str::to_string) + .collect(); + assert_eq!( + out.status.code(), + Some(100), + "the last apt-get status is returned: {calls:?}" + ); + assert_eq!( + calls.len(), + 1, + "no apt-get attempt may start after the sleep crossed the deadline: {calls:?}" + ); + let _ = std::fs::remove_dir_all(&dir); }