diff --git a/src/github.rs b/src/github.rs index dd24491c..5393200f 100644 --- a/src/github.rs +++ b/src/github.rs @@ -3,6 +3,7 @@ use std::fmt; use std::process::{Command, Output}; +use std::time::Duration; use anyhow::{Context, Result, bail}; use chrono::{DateTime, Utc}; @@ -669,8 +670,11 @@ impl GitHub { /// here. pub fn checks_on(&self, issue: &IssueUrl, sha: &str) -> Result> { let commit = format!("repos/{}/commits/{sha}", issue.repo_slug()); - let runs = self.gh_api_items(&format!("{commit}/check-runs?per_page=100"), "check_runs")?; - let statuses = self.gh_api_items(&format!("{commit}/status?per_page=100"), "statuses")?; + // CI retries the complete observation, not its individual requests. + let runs = + self.gh_api_items_once(&format!("{commit}/check-runs?per_page=100"), "check_runs")?; + let statuses = + self.gh_api_items_once(&format!("{commit}/status?per_page=100"), "statuses")?; let url = |value: &Value| { value .as_str() @@ -749,11 +753,18 @@ impl GitHub { /// Every item of the `field` list of the GitHub API's `path`, across all its /// pages. fn gh_api_items(&self, path: &str, field: &str) -> Result> { + self.retry_read(&format!("gh api {path}"), || { + self.gh_api_items_once(path, field) + }) + } + + fn gh_api_items_once(&self, path: &str, field: &str) -> Result> { let output = self.output(&["api", "--paginate", "--jq", &format!(".{field}[]"), path])?; if !output.status.success() { - bail!(check_read::ApiFailure { - path: path.to_string(), + bail!(check_read::ReadFailure { + command: format!("gh api {path}"), stderr: String::from_utf8_lossy(&output.stderr).trim().to_string(), + private_status: None, }); } serde_json::Deserializer::from_slice(&output.stdout) @@ -762,16 +773,43 @@ impl GitHub { .with_context(|| format!("gh api {path} returned invalid JSON")) } - /// Run `gh ` and parse its stdout as JSON, failing with gh's stderr if - /// it exits non-zero. + /// Read-only JSON commands get three attempts, separated by one then two + /// seconds, for transient failures only. Mutations use `gh_stdout` or + /// `output_with_input` instead. fn gh_json(&self, args: &[&str]) -> Result { let command = format!("gh {}", args[..2].join(" ")); + self.retry_read(&command, || self.gh_json_once(args, &command)) + } + + fn retry_read(&self, command: &str, mut read: impl FnMut() -> Result) -> Result { + for attempt in 1..=3 { + let error = match read() { + Ok(value) => return Ok(value), + Err(error) => error, + }; + if attempt == 3 || !check_read::is_transient(&error) { + return Err(error); + } + crate::progress::step(format!( + "{command} failed (attempt {attempt}/3): {error:#}; retrying in {attempt}s" + )); + let delay = Duration::from_secs(attempt); + match self.interruption { + Interruption::Ordinary => crate::poll::sleep(delay)?, + Interruption::Completion => std::thread::sleep(delay), + } + } + unreachable!("the third attempt returns success or the last cause") + } + + fn gh_json_once(&self, args: &[&str], command: &str) -> Result { let output = self.output(args)?; if !output.status.success() { - bail!( - "{command} failed: {}", - String::from_utf8_lossy(&output.stderr).trim() - ); + bail!(check_read::ReadFailure { + command: command.to_string(), + stderr: String::from_utf8_lossy(&output.stderr).trim().to_string(), + private_status: None, + }); } serde_json::from_slice(&output.stdout) .with_context(|| format!("{command} returned invalid JSON")) diff --git a/src/github/advisories.rs b/src/github/advisories.rs index 75f90c53..92b2ddcb 100644 --- a/src/github/advisories.rs +++ b/src/github/advisories.rs @@ -5,7 +5,7 @@ use anyhow::{Context, Result, bail}; use serde::Serialize; use serde_json::{Value, json}; -use super::GitHub; +use super::{GitHub, check_read}; use crate::issue::IssueUrl; use crate::labels::{Label, NEEDS_TRIAGE}; use crate::security::reproduction::{FixSize, Reproduction, Severity}; @@ -447,15 +447,8 @@ impl GitHub { ), RecordData::Issue { number, .. } => (format!("repos/{repo}/issues/{number}"), "body"), }; - let output = self.output_with_input(&["api", &path], None)?; - if !output.status.success() { - bail!( - "reading the private record before linking its fix failed ({})", - output.status - ); - } - let current: Value = - serde_json::from_slice(&output.stdout).context("private record is invalid JSON")?; + let current = + self.private_record(&path, "reading the private record before linking its fix")?; let current = current[field] .as_str() .context("the private record has no description")?; @@ -477,6 +470,23 @@ impl GitHub { Ok(()) } + /// Retry only the observation before a private record's mutation. Raw + /// diagnostics stay available to classification, never to progress/errors. + fn private_record(&self, path: &str, operation: &str) -> Result { + self.retry_read(operation, || { + let output = self.output(&["api", path])?; + if !output.status.success() { + bail!(check_read::ReadFailure { + command: operation.to_string(), + stderr: String::from_utf8_lossy(&output.stderr).trim().to_string(), + private_status: Some(output.status), + }); + } + serde_json::from_slice(&output.stdout) + .with_context(|| format!("{operation} returned invalid JSON")) + }) + } + pub fn security_fix_text(&self, issue: &IssueUrl) -> Result { let value = self.issue_view(issue, "title,body")?; let title = value["title"] @@ -599,15 +609,10 @@ impl GitHub { SecurityRecords::issues(Vec::new()), ), }; - let observed = self.output_with_input(&["api", &path], None)?; - if !observed.status.success() { - bail!( - "reading a private Security finding record before its update failed ({})", - observed.status - ); - } - let observed: Value = serde_json::from_slice(&observed.stdout) - .context("reading a private Security finding record returned invalid JSON")?; + let observed = self.private_record( + &path, + "reading a private Security finding record before its update", + )?; let current = storage.decode_state(&observed)?; let (description, untriaged) = match ¤t { RecordData::Advisory { diff --git a/src/github/check_read.rs b/src/github/check_read.rs index 5696963f..cb98a244 100644 --- a/src/github/check_read.rs +++ b/src/github/check_read.rs @@ -1,31 +1,47 @@ -//! Classification for the CI watch's read-only recovery policy. Unknown +//! Classification for GitHub read-only recovery policies. Unknown //! failures remain causal errors, never successful empty observations. use std::fmt; +use std::process::ExitStatus; /// A non-success API response, retaining gh's original diagnostics. This -/// carries evidence only: the CI watch owns whether and when to retry it. +/// carries evidence only: the caller owns whether and when to retry it. #[derive(Debug)] -pub(super) struct ApiFailure { - pub path: String, +pub(super) struct ReadFailure { + pub command: String, pub stderr: String, + /// Private record diagnostics may contain evidence. Classify the raw + /// stderr, but expose only this status in errors and retry progress. + pub private_status: Option, } -impl fmt::Display for ApiFailure { +impl fmt::Display for ReadFailure { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - write!(f, "gh api {} failed: {}", self.path, self.stderr) + match self.private_status { + Some(status) => write!(f, "{} failed ({status})", self.command), + None => write!(f, "{} failed: {}", self.command, self.stderr), + } } } -impl std::error::Error for ApiFailure {} +impl std::error::Error for ReadFailure {} pub(crate) fn is_transient(error: &anyhow::Error) -> bool { if let Some(error) = error.downcast_ref::() { return error.is_eof(); } - let Some(failure) = error.downcast_ref::() else { + let Some(failure) = error.downcast_ref::() else { return false; }; + let stderr = failure.stderr.trim().to_ascii_lowercase(); + // Quota exhaustion belongs to quota-aware deferral, not a short retry. + // gh can report GraphQL quota errors with or without an HTTP status. + if stderr.contains("api rate limit") + || stderr.contains("rate_limited") + || stderr.contains("rate_limit_exceeded") + { + return false; + } // gh reports HTTP status in stderr. Prefer it to incidental prose, so // an authentication or validation failure mentioning EOF stays permanent. if let Some(status) = failure @@ -36,7 +52,6 @@ pub(crate) fn is_transient(error: &anyhow::Error) -> bool { { return status == 429 || (500..600).contains(&status); } - let stderr = failure.stderr.trim().to_ascii_lowercase(); if stderr == "eof" || stderr.ends_with(": eof") { return true; } diff --git a/src/github/execution_tests.rs b/src/github/execution_tests.rs index 6c824708..54698d06 100644 --- a/src/github/execution_tests.rs +++ b/src/github/execution_tests.rs @@ -72,6 +72,393 @@ fn issue() -> IssueUrl { IssueUrl::parse("https://github.com/acme/widgets/issues/7").unwrap() } +#[test] +fn a_transient_private_security_issue_listing_recovers() { + with_recorded_signal( + "github::execution_tests::a_transient_private_security_issue_listing_recovers", + |_| { + let fixture = Fixture::new(""); + fixture.script(&format!( + r#" +if [ "$2" = 'repos/acme/widgets' ]; then + printf '%s' '{{"private":true}}' + exit 0 +fi +case "$*" in + *security-advisories*) + echo 'gh: Not Found (HTTP 404)' >&2 + exit 1 + ;; +esac +echo read >> '{reads}' +if [ ! -f '{failed}' ]; then + touch '{failed}' + echo 'HTTP 504: Gateway Timeout' >&2 + exit 1 +fi +exit 0 +"#, + reads = fixture.path("reads").display(), + failed = fixture.path("failed").display(), + )); + let result = GitHub::new().security_records("acme/widgets"); + assert!( + result.is_ok(), + "private issue listing did not recover: {:?}", + result.err() + ); + assert_eq!( + fs::read_to_string(fixture.path("reads")).unwrap(), + "read\nread\n" + ); + }, + ); +} + +#[test] +fn private_record_reads_recover_without_repeating_the_following_write() { + with_recorded_signal( + "github::execution_tests::private_record_reads_recover_without_repeating_the_following_write", + |_| { + use crate::security::reproduction::{Outcome, Reproduction}; + let fixture = Fixture::new(""); + let value = serde_json::json!({ + "number": 42, "title": "Bound input", "state": "open", + "html_url": "https://github.com/acme/widgets/issues/42", + "labels": [{"name": "needs-triage"}], + "body": "Fingerprint: `bounded`\nAudited commit: `0123456789abcdef0123456789abcdef01234567`\nPrivate evidence.\n", + }); + let record = SecurityRecords::issues(Vec::new()) + .decode_created(value.clone()) + .unwrap(); + let reproduction = Reproduction { + outcome: Outcome::NotReproduced, + notes: "Private reproduction notes.".into(), + test: "bounded_input()".into(), + }; + for operation in ["link", "reproduction"] { + fixture.script(&format!( + r#" +if [ "$2" = '--method' ]; then + echo write >> '{writes}' + cat > '{body}' + echo 'HTTP 504: private mutation evidence' >&2 + exit 1 +fi +echo read >> '{reads}' +if [ ! -f '{failed}' ]; then + touch '{failed}' + echo 'HTTP 504: private read evidence' >&2 + exit 1 +fi +cat <<'JSON' +{value} +JSON +"#, + reads = fixture.path("reads").display(), + writes = fixture.path("writes").display(), + body = fixture.path("body").display(), + failed = fixture.path("failed").display(), + )); + let github = GitHub::new(); + let result = match operation { + "link" => github.link_security_fix("acme/widgets", &record, &issue()), + "reproduction" => { + github.update_security_record("acme/widgets", &record, &reproduction) + } + _ => unreachable!(), + }; + let error = format!("{:#}", result.unwrap_err()); + assert!( + !error.contains("private read evidence") + && !error.contains("private mutation evidence") + ); + assert_eq!( + fs::read_to_string(fixture.path("reads")).unwrap(), + "read\nread\n", + "{operation}: {error}" + ); + assert_eq!( + fs::read_to_string(fixture.path("writes")).unwrap(), + "write\n" + ); + let body = fs::read_to_string(fixture.path("body")).unwrap(); + assert!(body.contains(if operation == "link" { + "Fix Ticket:" + } else { + "Private reproduction notes." + })); + for name in ["reads", "writes", "failed"] { + fs::remove_file(fixture.path(name)).unwrap(); + } + } + }, + ); +} + +#[test] +fn a_transient_issue_read_recovers_without_exposing_the_failure() { + with_recorded_signal( + "github::execution_tests::a_transient_issue_read_recovers_without_exposing_the_failure", + |_| { + let fixture = Fixture::new(""); + fixture.script(&format!( + r#" +echo read >> '{reads}' +if [ ! -f '{failed}' ]; then + touch '{failed}' + echo 'HTTP 504: Gateway Timeout' >&2 + exit 1 +fi +printf '%s' '{{"title":"Recovered"}}' +"#, + reads = fixture.path("reads").display(), + failed = fixture.path("failed").display(), + )); + assert_eq!(GitHub::new().issue_title(&issue()).unwrap(), "Recovered"); + assert_eq!( + fs::read_to_string(fixture.path("reads")).unwrap(), + "read\nread\n" + ); + }, + ); +} + +#[test] +fn permanent_and_quota_read_failures_are_not_retried() { + with_recorded_signal( + "github::execution_tests::permanent_and_quota_read_failures_are_not_retried", + |_| { + let fixture = Fixture::new(""); + for stderr in [ + "HTTP 401: Bad credentials: unexpected EOF", + "HTTP 403: Resource not accessible", + "HTTP 404: Not Found", + "HTTP 422: Validation Failed", + "To get started with GitHub CLI, please run: gh auth login", + "GraphQL: API rate limit exceeded for user ID 123. (HTTP 429)", + "GraphQL: API rate limit already exceeded for user ID 123.", + "GraphQL: RATE_LIMIT_EXCEEDED (HTTP 429)", + "API rate limit exceeded for user ID 123. (HTTP 429)", + ] { + fixture.script(&format!( + "echo read >> '{}'\ncat >&2 <<'ERROR'\n{stderr}\nERROR\nexit 1", + fixture.path("reads").display() + )); + let error = GitHub::new().issue_title(&issue()).unwrap_err(); + assert!(format!("{error:#}").contains(stderr)); + assert_eq!( + fs::read_to_string(fixture.path("reads")).unwrap(), + "read\n", + "{stderr}" + ); + fs::remove_file(fixture.path("reads")).unwrap(); + } + }, + ); +} + +#[test] +fn persistent_read_failures_stop_after_three_attempts_with_the_last_cause() { + with_recorded_signal( + "github::execution_tests::persistent_read_failures_stop_after_three_attempts_with_the_last_cause", + |_| { + let fixture = Fixture::new(""); + // macOS wc pads the count; format the attempt as an integer. + fixture.script(&format!( + "echo read >> '{reads}'\nn=$(wc -l < '{reads}')\necho \"HTTP 504: failure $((n))\" >&2\nexit 1", + reads = fixture.path("reads").display(), + )); + let started = Instant::now(); + let error = GitHub::new().issue_title(&issue()).unwrap_err(); + assert_eq!( + error.to_string(), + "gh issue view failed: HTTP 504: failure 3" + ); + assert_eq!( + fs::read_to_string(fixture.path("reads")).unwrap(), + "read\nread\nread\n" + ); + assert!(started.elapsed() >= Duration::from_secs(3)); + assert!(started.elapsed() < Duration::from_secs(10)); + }, + ); +} + +#[test] +fn interruption_during_read_backoff_starts_no_further_request() { + with_recorded_signal( + "github::execution_tests::interruption_during_read_backoff_starts_no_further_request", + |signal| { + let fixture = Fixture::new(""); + let reads = fixture.path("reads"); + fixture.script(&format!( + "echo read >> '{}'\necho 'HTTP 504: Gateway Timeout' >&2\nexit 1", + reads.display() + )); + let marker = reads.clone(); + let sender = std::thread::spawn(move || { + let deadline = Instant::now() + Duration::from_secs(5); + while !marker.exists() && Instant::now() < deadline { + std::thread::sleep(Duration::from_millis(10)); + } + assert!(marker.exists(), "gh never started"); + std::thread::sleep(Duration::from_millis(250)); + signal_hook::low_level::raise(signal).unwrap(); + }); + let started = Instant::now(); + let result = GitHub::new().issue_title(&issue()); + sender.join().unwrap(); + assert_eq!(result.unwrap_err().to_string(), "interrupted"); + assert_eq!(fs::read_to_string(reads).unwrap(), "read\n"); + assert!(started.elapsed() < Duration::from_secs(2)); + }, + ); +} + +#[test] +fn transient_transport_failures_recover_across_read_only_operations() { + with_recorded_signal( + "github::execution_tests::transient_transport_failures_recover_across_read_only_operations", + |_| { + let fixture = Fixture::new(""); + let github = GitHub::new(); + for (operation, failure, json) in [ + ( + "issues", + "echo 'HTTP 429: Too Many Requests' >&2; exit 1", + "[]", + ), + ( + "pr", + "echo 'read tcp: connection reset by peer' >&2; exit 1", + r#"{"body":"Recovered"}"#, + ), + ("labels", "echo 'EOF' >&2; exit 1", "[]"), + ( + "tickets", + "echo 'HTTP 503: Service Unavailable' >&2; exit 1", + r#"{"data":{"repository":{"issue":{"subIssues":{"nodes":[]}}}}}"#, + ), + ("profile", "printf '{'", r#"{"email":"me@example.com"}"#), + ] { + fixture.script(&format!( + r#" +echo read >> '{reads}' +if [ ! -f '{failed}' ]; then + touch '{failed}' + {failure} +else + printf '%s' '{json}' +fi +"#, + reads = fixture.path("reads").display(), + failed = fixture.path("failed").display(), + )); + match operation { + "issues" => assert!( + github + .open_issues_labelled("acme/widgets", crate::labels::READY_FOR_AGENT) + .unwrap() + .is_empty() + ), + "pr" => assert_eq!(github.pr_body(&issue(), 12).unwrap(), "Recovered"), + "labels" => github.ensure_labels("acme/widgets", &[]).unwrap(), + "tickets" => assert!(github.tickets(&issue()).unwrap().is_empty()), + "profile" => assert_eq!( + github.profile_email().unwrap().as_deref(), + Some("me@example.com") + ), + _ => unreachable!(), + } + assert_eq!( + fs::read_to_string(fixture.path("reads")).unwrap(), + "read\nread\n", + "{operation}" + ); + fs::remove_file(fixture.path("reads")).unwrap(); + fs::remove_file(fixture.path("failed")).unwrap(); + } + }, + ); +} + +#[test] +fn transient_mutation_failures_are_never_retried() { + with_recorded_signal( + "github::execution_tests::transient_mutation_failures_are_never_retried", + |_| { + let fixture = Fixture::new(""); + fixture.script(&format!( + r#" +if [ "$1 $2" = 'label list' ]; then + printf '[]' + exit 0 +fi +echo "$1 $2" >> '{}' +echo 'HTTP 504: Gateway Timeout' >&2 +exit 1 +"#, + fixture.path("mutations").display() + )); + let github = GitHub::new(); + for result in [ + github.close_issue(&issue(), "Done"), + github.set_labels(&issue(), &Labels::default()), + github.ensure_labels("acme/widgets", &[crate::labels::NEEDS_TRIAGE]), + github + .create_issue(&issue(), "Title", "Body", &[]) + .map(drop), + github + .create_draft_pr(&issue(), "issue-7", "main", "Title", "Body") + .map(drop), + github.mark_ready(&issue(), "12"), + github.set_pr_body(&issue(), 12, "Body"), + github.merge(&issue(), 12, "head"), + github.rerun_failed_jobs(&issue(), 123), + ] { + assert!(format!("{:#}", result.unwrap_err()).contains("HTTP 504")); + } + assert_eq!( + fs::read_to_string(fixture.path("mutations")).unwrap(), + "issue close\napi --method\nlabel create\nissue create\npr create\npr ready\napi --method\npr merge\nrun rerun\n" + ); + }, + ); +} + +#[test] +fn completion_read_retries_without_clearing_interruption() { + with_recorded_signal( + "github::execution_tests::completion_read_retries_without_clearing_interruption", + |signal| { + let fixture = Fixture::new(""); + fixture.script(&format!( + r#" +if [ ! -f '{failed}' ]; then + touch '{failed}' + echo 'HTTP 504: Gateway Timeout' >&2 + exit 1 +fi +printf '%s' '{{"title":"Recovered"}}' +"#, + failed = fixture.path("failed").display(), + )); + let github = GitHub::new(); + signal_hook::low_level::raise(signal).unwrap(); + assert_eq!( + github.completion().issue_title(&issue()).unwrap(), + "Recovered" + ); + assert!(interrupt::requested()); + assert_eq!( + github.issue_title(&issue()).unwrap_err().to_string(), + "interrupted" + ); + }, + ); +} + #[test] fn parent_only_interruption_stops_active_github() { with_recorded_signal( @@ -499,8 +886,12 @@ fn check_reads_classify_transport_and_api_failures_without_hiding_diagnostics() ("read tcp: connection reset by peer", true), ("net/http: TLS handshake timeout", true), ("gh: too many requests (HTTP 429)", true), + ("GraphQL: secondary rate limit exceeded (HTTP 429)", true), ("gh: Bad Gateway (HTTP 502)", true), ("gh: service unavailable (HTTP 503)", true), + ("gh: Gateway Timeout (HTTP 504)", true), + ("GraphQL: API rate limit exceeded (HTTP 429)", false), + ("GraphQL: API rate limit already exceeded", false), ("gh: Bad credentials (HTTP 401)", false), ("gh: Resource not accessible (HTTP 403)", false), ("gh: Not Found (HTTP 404)", false), diff --git a/tests/architect_run.rs b/tests/architect_run.rs index 8c7a9c72..f39aaf9b 100644 --- a/tests/architect_run.rs +++ b/tests/architect_run.rs @@ -1377,6 +1377,50 @@ fn the_one_notification(resend: &ResendStandIn) -> (String, String) { (part("subject"), part("text")) } +#[test] +fn a_transient_github_read_recovers_without_a_failure_notification() { + let scenario = scenario(); + scenario.agent_does(AGENT_PUBLISHES_A_TICKET); + let mut github = scenario.gh_state(); + github["fail_next"] = serde_json::json!({ + "call": "issue list", + "times": 1, + "error": "HTTP 504: Gateway Timeout (https://api.github.com/graphql)", + }); + scenario.write_gh_state(&github); + let resend = ResendStandIn::replying(200, ACCEPTED); + + let result = run_with_resend( + &scenario, + &resend, + &["architect", "--plan-only", "--email", "me@example.com"], + ); + + assert_eq!(result.code, Some(0), "stderr: {}", result.stderr); + assert_eq!(result.stdout, format!("{PLAN_URL}\n")); + let retry = "gh issue list failed (attempt 1/3)"; + assert_eq!(result.stderr.matches(retry).count(), 1, "{}", result.stderr); + assert!(result.stderr.contains("HTTP 504")); + let calls = scenario.gh_calls_of("issue", "list"); + assert_eq!( + calls[0], calls[1], + "the failed observation was not repeated" + ); + let (subject, _) = the_one_notification(&resend); + assert_eq!( + subject, + "[thirdshift] acme/widgets Architect run: plan published" + ); + let command_logs = + fs::read_dir(scenario.path("home/.thirdshift/logs/acme/widgets/commands/architect")) + .unwrap(); + let log = command_logs + .map(|entry| entry.unwrap().path()) + .find(|path| path.extension().is_some_and(|ext| ext == "log")) + .unwrap(); + assert!(fs::read_to_string(log).unwrap().contains(retry)); +} + #[test] fn plan_only_sends_one_notification_naming_the_plan() { let scenario = scenario(); diff --git a/tests/fakes/gh.rs b/tests/fakes/gh.rs index 0eeedc70..6dd9fb75 100644 --- a/tests/fakes/gh.rs +++ b/tests/fakes/gh.rs @@ -26,6 +26,7 @@ //! "refuse_merges"?: {"times", "error"}, //! "after_merge"?: "