From a76f2e863ddb0202c213d97eef646554e447d394 Mon Sep 17 00:00:00 2001 From: Ben Wilson Date: Sat, 10 Oct 2026 13:26:40 -0600 Subject: [PATCH 1/2] Make bot failure analysis resumable and group by leaf errors MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Retry GitHub requests on ConnectionError/Timeout with backoff; HTTP errors are unchanged. - Decode job logs as UTF-8 (they were decoded as latin-1, so the ❌/✅ summary lines never matched). - Cache raw logs in /raw_logs/ keyed by job id and reuse them on rerun. - Emit one event per failed question from its 'Error while processing question url' line, grouped by the leaf errors nested inside it. Wrapper tracebacks are only used for jobs without question-level errors. - Report per-bot failed-job and failed-question ratios. Co-Authored-By: Claude Opus 5.5 --- .../test_analyze_bot_run_failures.py | 386 +++++++++++++++- scripts/skills/analyze_bot_failures/SKILL.md | 12 +- .../analyze_bot_run_failures.py | 420 +++++++++++++++--- 3 files changed, 758 insertions(+), 60 deletions(-) diff --git a/code_tests/unit_tests/test_analyze_bot_run_failures.py b/code_tests/unit_tests/test_analyze_bot_run_failures.py index 3c03402e..bfd52323 100644 --- a/code_tests/unit_tests/test_analyze_bot_run_failures.py +++ b/code_tests/unit_tests/test_analyze_bot_run_failures.py @@ -1,10 +1,29 @@ +from pathlib import Path + +import pytest +import requests + +from scripts.skills.analyze_bot_failures import analyze_bot_run_failures from scripts.skills.analyze_bot_failures.analyze_bot_run_failures import ( + GITHUB_RETRY_DELAYS_SECONDS, + JobAnalysis, + build_report, + extract_leaf_errors, + github_get, group_failures, + load_or_download_job_log, normalize_message_to_signature, parse_failures_from_log, + parse_questions_attempted, ) GH_PREFIX = "2026-06-11T17:13:45.1234567Z " +PYTHON_ERROR_PREFIX = ( + "2026-06-11 17:13:45,123 - forecasting_tools.forecast_bots.forecast_bot - ERROR - " +) +QUESTION_URL = "https://www.metaculus.com/questions/44722" +OTHER_QUESTION_URL = "https://www.metaculus.com/questions/44999" +SUMMARY_STATS_LINE = "Stats for passing reports:" TRACEBACK_LOG = ( f"{GH_PREFIX}2026-06-11 17:13:40,100 - root - INFO - Running bot METAC_GPT_5_5_HIGH with 3 questions\n" @@ -25,6 +44,52 @@ f"{GH_PREFIX}The operation was canceled.\n" ) +ALL_PREDICTIONS_FAILED_NESTED_MESSAGE = r"""1 sub-exceptions -> All 1 research reports/predictions failed: Errors: ['ExceptionGroup: 2 sub-exceptions -> Error while running research and predictions: Errors: [\'BadRequestError: litellm.BadRequestError: OpenrouterException - {"error":{"code":400,"metadata":{"raw":"{\\\\"message\\\\":\\\\"The request was rejected because it was considered high risk\\\\"}"}},"request_id":"req_011AAA"}\', \'BadRequestError: litellm.BadRequestError: OpenrouterException - {"error":{"code":400,"metadata":{"raw":"{\\\\"message\\\\":\\\\"The request was rejected because it was considered high risk\\\\"}"}},"request_id":"req_011BBB"}\'] (2 sub-exceptions)'] (1 sub-exception)""" + +PARTIAL_FAILURE_NESTED_MESSAGE = r"""Expected at least 2.5 successful predictions, but only got 1. Errors encountered: ['Timeout: litellm.Timeout: AnthropicException - litellm.Timeout: Connection timed out. Timeout passed=60.0, time taken=60.1 seconds', "AssertionError: Answer is not a string and is of type: . Answer: None. Finish reason: content_filter", 'Timeout: litellm.Timeout: AnthropicException - litellm.Timeout: Connection timed out. Timeout passed=60.0, time taken=61.3 seconds']""" + +VALIDATION_LEAF_AT_FIRST_NESTING_LEVEL = r"""Expected at least 2.5 successful predictions, but only got 2. Errors encountered: ["ValidationError: 1 validation error for NumericDistribution\n Value error, No declared percentiles are within the range of the question +/- 25.0%. Lower bound: 0.0 [type=value_error, input_value={'declared_percentiles': [1, 2]}, input_type=dict]\n For further information visit https://errors.pydantic.dev/2.13/v/value_error"]""" + +VALIDATION_LEAF_AT_SECOND_NESTING_LEVEL = r"""1 sub-exceptions -> All 1 research reports/predictions failed: Errors: ['ExceptionGroup: 1 sub-exceptions -> Error while running research and predictions: Errors: ["ValidationError: 1 validation error for NumericDistribution\\n Value error, No declared percentiles are within the range of the question +/- 25.0%. Lower bound: 5.0 [type=value_error, input_value={\'declared_percentiles\': [3]}, input_type=dict]\\n For further information visit https://errors.pydantic.dev/2.13/v/value_error"] (1 sub-exception)'] (1 sub-exception)""" + + +def make_log(*lines: str) -> str: + return "".join(f"{GH_PREFIX}{line}\n" for line in lines) + + +def make_question_error_line(question_url: str, nested_message: str) -> str: + return f"{PYTHON_ERROR_PREFIX}Error while processing question url: '{question_url}': {nested_message}" + + +def make_failed_summary_line(question_url: str, wrapped_message: str) -> str: + return ( + f"❌ Exception: RuntimeError | Message: Error while processing question url: " + f"'{question_url}': {wrapped_message}" + ) + + +def make_succeeded_summary_line(question_url: str) -> str: + return f"✅ URL: {question_url} | Minor Errors: 0" + + +def leaf_list_message(*leaf_errors: str) -> str: + return f"Expected at least 2.5 successful predictions, but only got 0. Errors encountered: {list(leaf_errors)}" + + +def parse_job_log(log_text: str) -> list[analyze_bot_run_failures.FailureEvent]: + return parse_failures_from_log( + log_text, "bot_a", 111, "bot_a / run_bot", "http://job-url" + ) + + +def make_response(status_code: int, body: bytes) -> requests.Response: + response = requests.Response() + response.status_code = status_code + response._content = body + response.headers["Content-Type"] = "text/plain" + response.url = "https://api.github.com/repos/owner/repo/actions/jobs/1/logs" + return response + def test_parses_traceback_failure_with_question_url_and_repo_frame() -> None: events = parse_failures_from_log( @@ -45,7 +110,8 @@ def test_parses_traceback_failure_with_question_url_and_repo_frame() -> None: == "forecasting_tools/forecast_bots/forecast_bot.py" ) assert event.deepest_repo_frame.line_number == 341 - assert "Traceback (most recent call last):" in (event.traceback_text or "") + assert "Traceback (most recent call last):" in (event.context_text or "") + assert not event.is_question_failure def test_falls_back_to_short_summary_lines() -> None: @@ -63,7 +129,7 @@ def test_falls_back_to_log_tail_when_nothing_parseable() -> None: ) assert len(events) == 1 assert events[0].exception_type == "UnparsedFailure" - assert "The operation was canceled." in (events[0].traceback_text or "") + assert "The operation was canceled." in (events[0].context_text or "") def test_grouping_normalizes_urls_and_numbers() -> None: @@ -87,3 +153,319 @@ def test_grouping_normalizes_urls_and_numbers() -> None: assert len(groups) == 1 assert len(groups[0].events) == 2 assert {event.bot_name for event in groups[0].events} == {"BOT_A", "BOT_B"} + + +def test_question_error_line_yields_leaf_error_from_nested_exception_groups() -> None: + events = parse_job_log( + make_log( + make_question_error_line( + QUESTION_URL, ALL_PREDICTIONS_FAILED_NESTED_MESSAGE + ) + ) + ) + assert len(events) == 1 + event = events[0] + assert event.is_question_failure + assert event.question_url == QUESTION_URL + assert event.exception_type == "BadRequestError" + assert event.leaf_error_counts == {"BadRequestError": 2} + assert event.message.startswith("litellm.BadRequestError: OpenrouterException") + assert event.message.endswith('"request_id":"req_011AAA"}') + assert '"message":"The request was rejected' in event.message + assert "content_filter" in event.categories + + +def test_representative_leaf_is_the_most_common_one() -> None: + events = parse_job_log( + make_log(make_question_error_line(QUESTION_URL, PARTIAL_FAILURE_NESTED_MESSAGE)) + ) + assert len(events) == 1 + assert events[0].exception_type == "Timeout" + assert events[0].leaf_error_counts == {"Timeout": 2, "AssertionError": 1} + assert "timeout" in events[0].categories + + +def test_leaf_message_stops_at_its_closing_quote() -> None: + leaf_errors = extract_leaf_errors(PARTIAL_FAILURE_NESTED_MESSAGE) + assert [leaf.exception_type for leaf in leaf_errors] == [ + "Timeout", + "AssertionError", + "Timeout", + ] + assert leaf_errors[1].message == ( + "Answer is not a string and is of type: . " + "Answer: None. Finish reason: content_filter" + ) + assert leaf_errors[2].message.endswith("time taken=61.3 seconds") + + +def test_same_leaf_at_different_nesting_levels_shares_a_signature() -> None: + first_level_leaf = extract_leaf_errors(VALIDATION_LEAF_AT_FIRST_NESTING_LEVEL)[0] + second_level_leaf = extract_leaf_errors(VALIDATION_LEAF_AT_SECOND_NESTING_LEVEL)[0] + first_signature = normalize_message_to_signature( + first_level_leaf.exception_type, first_level_leaf.message + ) + second_signature = normalize_message_to_signature( + second_level_leaf.exception_type, second_level_leaf.message + ) + assert first_signature == second_signature + assert "No declared percentiles are within the range" in first_signature + assert "input_value" not in first_signature + + +def test_wrapper_tracebacks_are_not_counted_when_question_errors_exist() -> None: + log_text = make_log( + "2026-06-11 17:13:40,100 - __main__ - INFO - Running bot METAC_BOT_A with 2 questions", + make_question_error_line(QUESTION_URL, PARTIAL_FAILURE_NESTED_MESSAGE), + make_succeeded_summary_line(OTHER_QUESTION_URL), + make_failed_summary_line(QUESTION_URL, "ValueError - Expected at least 2.5"), + SUMMARY_STATS_LINE, + f"{PYTHON_ERROR_PREFIX}Exception occurred during forecasting:", + "Traceback (most recent call last):", + ' File "/home/runner/work/forecasting-tools/forecasting-tools/forecasting_tools/forecast_bots/forecast_bot.py", line 440, in _handle_errors', + "ValueError: Expected at least 2.5 successful predictions, but only got 1.", + "Traceback (most recent call last):", + ' File "/home/runner/work/forecasting-tools/forecasting-tools/run_bots.py", line 197, in configure_and_run_bot', + "RuntimeError: 1 errors occurred while forecasting: [RuntimeError('...')]", + ) + events = parse_job_log(log_text) + assert len(events) == 1 + assert events[0].is_question_failure + assert parse_questions_attempted(log_text) == 2 + + +def test_retried_question_keeps_only_its_final_error() -> None: + timeout_message = leaf_list_message("Timeout: litellm.Timeout: timed out") + validation_message = leaf_list_message("ValidationError: bad percentiles") + events = parse_job_log( + make_log( + make_question_error_line(QUESTION_URL, timeout_message), + make_question_error_line(QUESTION_URL, validation_message), + make_failed_summary_line(QUESTION_URL, "ValueError - Expected"), + SUMMARY_STATS_LINE, + ) + ) + assert [event.exception_type for event in events] == ["ValidationError"] + + +def test_question_that_succeeded_on_retry_is_not_a_failure() -> None: + events = parse_job_log( + make_log( + make_question_error_line( + QUESTION_URL, leaf_list_message("Timeout: litellm.Timeout: timed out") + ), + make_question_error_line( + OTHER_QUESTION_URL, leaf_list_message("NotFoundError: No endpoints") + ), + make_succeeded_summary_line(QUESTION_URL), + make_failed_summary_line(OTHER_QUESTION_URL, "ValueError - Expected"), + SUMMARY_STATS_LINE, + ) + ) + assert [event.question_url for event in events] == [OTHER_QUESTION_URL] + assert events[0].categories == ["model_not_found"] + + +def test_no_question_failures_when_summary_shows_every_retry_succeeded() -> None: + events = parse_job_log( + make_log( + make_question_error_line( + QUESTION_URL, leaf_list_message("Timeout: litellm.Timeout: timed out") + ), + make_succeeded_summary_line(QUESTION_URL), + SUMMARY_STATS_LINE, + ) + ) + assert not any(event.is_question_failure for event in events) + + +def test_group_subquestions_sharing_a_url_count_separately() -> None: + events = parse_job_log( + make_log( + make_question_error_line( + QUESTION_URL, leaf_list_message("NotFoundError: No endpoints") + ), + make_question_error_line( + QUESTION_URL, leaf_list_message("NotFoundError: No endpoints") + ), + make_failed_summary_line(QUESTION_URL, "ValueError - Expected"), + make_failed_summary_line(QUESTION_URL, "ValueError - Expected"), + SUMMARY_STATS_LINE, + ) + ) + assert len(events) == 2 + + +def test_keeps_every_question_error_when_summary_is_missing() -> None: + events = parse_job_log( + make_log( + make_question_error_line( + QUESTION_URL, leaf_list_message("NotFoundError: No endpoints") + ), + make_question_error_line( + OTHER_QUESTION_URL, leaf_list_message("NotFoundError: No endpoints") + ), + "##[error]The operation was canceled.", + ) + ) + assert len(events) == 2 + + +def test_question_error_without_leaves_uses_the_wrapped_exception_type() -> None: + message = "All predictions must have the same option names, but {'A'} != ['A', 'B']" + events = parse_job_log( + make_log( + make_question_error_line(QUESTION_URL, message), + make_failed_summary_line(QUESTION_URL, f"ValueError - {message}"), + SUMMARY_STATS_LINE, + ) + ) + assert len(events) == 1 + assert events[0].exception_type == "ValueError" + assert events[0].message == message + assert events[0].leaf_error_counts == {} + + +def test_questions_attempted_is_none_without_running_bot_line() -> None: + assert parse_questions_attempted(UNPARSABLE_LOG) is None + + +def test_bot_summary_reports_job_and_question_ratios(tmp_path: Path) -> None: + job_with_two_failures = JobAnalysis( + bot_name="bot_a", + run_id=1, + job_url="http://job-1", + log_path="run1.log", + events=parse_job_log( + make_log( + make_question_error_line( + QUESTION_URL, leaf_list_message("NotFoundError: No endpoints") + ), + make_question_error_line( + OTHER_QUESTION_URL, leaf_list_message("NotFoundError: No endpoints") + ), + ) + ), + questions_attempted=5, + ) + job_with_one_failure = JobAnalysis( + bot_name="bot_a", + run_id=2, + job_url="http://job-2", + log_path="run2.log", + events=parse_job_log( + make_log( + make_question_error_line( + QUESTION_URL, leaf_list_message("NotFoundError: No endpoints") + ) + ) + ), + questions_attempted=3, + ) + report_path = build_report( + [job_with_two_failures, job_with_one_failure], {"bot_a": 4}, tmp_path + ) + report_text = Path(report_path).read_text(encoding="utf-8") + assert "| bot_a | 2/4 (50%) | 3/8 (38%) | 0 |" in report_text + assert "[3x] NotFoundError" in report_text + + +def test_github_get_retries_network_errors_and_decodes_logs_as_utf8( + monkeypatch: pytest.MonkeyPatch, +) -> None: + queued_outcomes: list[Exception | requests.Response] = [ + requests.ConnectionError("No route to host"), + requests.Timeout("Read timed out"), + make_response(200, "❌ Exception: ValueError".encode("utf-8")), + ] + request_count = 0 + + def fake_get(*args: object, **kwargs: object) -> requests.Response: + nonlocal request_count + request_count += 1 + outcome = queued_outcomes.pop(0) + if isinstance(outcome, Exception): + raise outcome + return outcome + + sleep_durations: list[float] = [] + monkeypatch.setattr(analyze_bot_run_failures.requests, "get", fake_get) + monkeypatch.setattr(analyze_bot_run_failures.time, "sleep", sleep_durations.append) + + log_text = github_get( + "/repos/owner/repo/actions/jobs/1/logs", "token", as_text=True + ) + + assert log_text == "❌ Exception: ValueError" + assert request_count == 3 + assert sleep_durations == GITHUB_RETRY_DELAYS_SECONDS[:2] + + +def test_github_get_raises_after_exhausting_retries( + monkeypatch: pytest.MonkeyPatch, +) -> None: + request_count = 0 + + def always_unreachable(*args: object, **kwargs: object) -> requests.Response: + nonlocal request_count + request_count += 1 + raise requests.ConnectionError("No route to host") + + monkeypatch.setattr(analyze_bot_run_failures.requests, "get", always_unreachable) + monkeypatch.setattr(analyze_bot_run_failures.time, "sleep", lambda seconds: None) + + with pytest.raises(requests.ConnectionError): + github_get("/repos/owner/repo/actions/runs/1/jobs", "token") + assert request_count == len(GITHUB_RETRY_DELAYS_SECONDS) + 1 + + +def test_github_get_does_not_retry_http_errors( + monkeypatch: pytest.MonkeyPatch, +) -> None: + request_count = 0 + + def not_found(*args: object, **kwargs: object) -> requests.Response: + nonlocal request_count + request_count += 1 + return make_response(404, b"The specified blob does not exist.") + + monkeypatch.setattr(analyze_bot_run_failures.requests, "get", not_found) + monkeypatch.setattr(analyze_bot_run_failures.time, "sleep", lambda seconds: None) + + with pytest.raises(requests.HTTPError): + github_get("/repos/owner/repo/actions/jobs/1/logs", "token", as_text=True) + assert request_count == 1 + + +def test_reuses_cached_log_without_downloading( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + log_path = tmp_path / "run1_job2_bot_a.log" + log_path.write_text("cached ❌ log", encoding="utf-8") + + def fail_if_downloaded(repo: str, job_id: int, token: str) -> str: + raise AssertionError("cached log should not be downloaded again") + + monkeypatch.setattr( + analyze_bot_run_failures, "download_job_log", fail_if_downloaded + ) + assert load_or_download_job_log("owner/repo", 2, "token", log_path) == ( + "cached ❌ log" + ) + + +def test_downloads_and_caches_missing_log( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + monkeypatch.setattr( + analyze_bot_run_failures, + "download_job_log", + lambda repo, job_id, token: "fresh ❌ log", + ) + log_path = tmp_path / "run1_job2_bot_a.log" + + assert load_or_download_job_log("owner/repo", 2, "token", log_path) == ( + "fresh ❌ log" + ) + assert log_path.read_text(encoding="utf-8") == "fresh ❌ log" + assert list(tmp_path.iterdir()) == [log_path] diff --git a/scripts/skills/analyze_bot_failures/SKILL.md b/scripts/skills/analyze_bot_failures/SKILL.md index caf964b7..bf76885c 100644 --- a/scripts/skills/analyze_bot_failures/SKILL.md +++ b/scripts/skills/analyze_bot_failures/SKILL.md @@ -20,14 +20,14 @@ Useful options: - `--run-id ` to analyze one specific run - `--max-runs ` cap on runs fetched (default 50) -Output goes to `logs/workflow_failure_analysis//`: -- `report.md` — counts by category/bot/question, plus failure groups (deduped by normalized signature) with an example message, traceback, and the deepest repo code frame -- `failures.json` — every parsed failure with full messages and signatures (machine-readable) -- `raw_logs/run_.log` — complete raw log of each failed job +Output goes to `logs/workflow_failure_analysis/`: +- `/report.md` — counts by category/question, a per-bot table (failed jobs / jobs in analyzed runs, failed questions / questions attempted), plus failure groups (deduped by normalized signature) with an example message and full error or traceback +- `/failures.json` — every parsed failure with full messages and signatures (machine-readable) +- `raw_logs/run_job_.log` — complete raw log of each failed job. Shared across analyses: rerunning with the same `--output-dir` (e.g. after a crash) reuses these instead of downloading again ## Step 2: Read the report, then verify against raw logs -Read `report.md` first. The parser extracts full tracebacks when present (falling back to `❌ Exception: ... | Message: ...` summary lines, then to the raw log tail), so each failure group usually includes a "deepest repo frame" — the last traceback frame inside this repo rather than a dependency — which is the first place to look in the code. Still **spot-check 2-3 raw logs** for the most frequent signatures to see surrounding context (retry attempts, which LLM call failed). Failures of type `UnparsedFailure` mean nothing parseable was found — the job likely failed at the infrastructure level (poetry install failures, token resolution, job-level timeout at 55 min, cancellation) — read their raw logs directly. +Read `report.md` first. Each failed question is one event, taken from its `Error while processing question url: ...` log line and grouped by the innermost (leaf) errors nested in it, e.g. a litellm `NotFoundError` or a `NumericDistribution` `ValidationError`. A group's "Leaf errors" line shows the mix when one question's predictions failed in different ways. Only jobs with no per-question error lines fall back to tracebacks (with a "deepest repo frame", the last traceback frame inside this repo), then `❌ Exception: ... | Message: ...` summary lines, then the raw log tail. Still **spot-check 2-3 raw logs** for the most frequent signatures to see surrounding context (retry attempts, which LLM call failed). Failures of type `UnparsedFailure` mean nothing parseable was found — the job likely failed at the infrastructure level (poetry install failures, token resolution, job-level timeout at 55 min, cancellation) — read their raw logs directly. Jobs listed as "Could not download log" with a 404 had no logs (usually jobs that failed to be acquired by a runner). ## Step 3: Triage — transient noise vs real bug @@ -36,7 +36,7 @@ Likely transient (usually not worth fixing, just note frequency): - Occasional timeouts that succeeded on the in-run retry (`run_bots.py` retries reports whose error contains "TimeoutError") Likely real bugs (investigate the code): -- The same bot failing across most runs (config/model-name/credentials issue in its `RunBotConfig` in `run_bots.py`) +- The same bot failing across most runs, i.e. a high failed-jobs ratio in the per-bot table (config/model-name/credentials issue in its `RunBotConfig` in `run_bots.py`). A high failed-questions ratio means the bot fails on most questions rather than one bad question - Structured-output or validation errors clustering on one question type (binary/MC/numeric/group) — points at parsing or prompt code - Prediction validation errors (probabilities out of bounds, CDF/percentile issues) — points at report data models - The same question ID recurring across bots/runs — candidate for `POST_IDS_TO_SKIP` or `POST_IDS_TO_NOT_RAISE_ERRORS_FOR` in `run_bots.py` diff --git a/scripts/skills/analyze_bot_failures/analyze_bot_run_failures.py b/scripts/skills/analyze_bot_failures/analyze_bot_run_failures.py index 65670038..7661eee6 100644 --- a/scripts/skills/analyze_bot_failures/analyze_bot_run_failures.py +++ b/scripts/skills/analyze_bot_failures/analyze_bot_run_failures.py @@ -6,6 +6,9 @@ unauthenticated requests even on public repos). The token is resolved from the GITHUB_TOKEN env var, then from `gh auth token`. +Raw logs are cached in /raw_logs/ keyed by job id, so rerunning with +the same --output-dir reuses logs that were already downloaded. + Example usage: poetry run python scripts/skills/analyze_bot_failures/analyze_bot_run_failures.py --since 2d poetry run python scripts/skills/analyze_bot_failures/analyze_bot_run_failures.py --run-id 27362307940 @@ -18,7 +21,9 @@ import re import subprocess import sys -from dataclasses import dataclass +import time +from collections import Counter +from dataclasses import dataclass, field from datetime import datetime, timedelta, timezone from pathlib import Path @@ -31,6 +36,8 @@ DEFAULT_WORKFLOW = "run-bot-aib-tournament.yaml" DEFAULT_OUTPUT_DIR = Path("logs/workflow_failure_analysis") LOG_TAIL_LINES_FOR_UNPARSED_FAILURES = 60 +REPORT_SUMMARY_STATS_LINE = "Stats for passing reports" +GITHUB_RETRY_DELAYS_SECONDS = [5, 15, 45] ERROR_CATEGORY_PATTERNS: dict[str, list[str]] = { "timeout": [r"TimeoutError", r"timed?[\s_-]?out", r"Timeout"], @@ -50,6 +57,7 @@ r"insufficient[\s_-]?credits", r"API key", ], + "model_not_found": [r"NotFoundError", r"No endpoints found", r"not_found_error"], "bad_request_or_model_refusal": [ r"\b400\b", r"BadRequestError", @@ -57,6 +65,7 @@ r"refus", r"content[\s_-]?policy", ], + "content_filter": [r"content[\s_-]?filter", r"considered high risk"], "structured_output_parsing": [ r"structure[d]?[\s_-]?output", r"ValidationError", @@ -64,6 +73,7 @@ r"Failed to parse", r"pydantic", ], + "empty_llm_response": [r"Answer is not a string"], "prediction_validation": [ r"probabilit(y|ies).{0,80}(sum|bound|range|between)", r"out of bounds", @@ -83,7 +93,7 @@ ], } -QUESTION_URL_PATTERN = re.compile(r"https://www\.metaculus\.com/questions/\d+/") +QUESTION_URL_PATTERN = re.compile(r"https://www\.metaculus\.com/questions/\d+/?") GH_TIMESTAMP_PREFIX_PATTERN = re.compile( r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d+Z\s?" ) @@ -91,6 +101,25 @@ FAILED_FORECAST_LINE_PATTERN = re.compile( r"❌ Exception: (?P\w+) \| Message: (?P.*)" ) +QUESTION_ERROR_LINE_PATTERN = re.compile( + r" - ERROR - Error while processing question url: '(?P[^']+)': " + r"(?P.*)" +) +WRAPPED_QUESTION_EXCEPTION_PATTERN = re.compile( + r"Error while processing question url: '(?P[^']+)': " + r"(?P\w+) - " +) +FAILED_QUESTION_SUMMARY_LINE_PATTERN = re.compile( + r"❌ Exception: \w+ \| Message: .*?" + r"Error while processing question url: '(?P[^']+)'" +) +QUESTIONS_ATTEMPTED_LINE_PATTERN = re.compile( + r"Running bot \S+ with (?P\d+) questions" +) +NESTED_ERROR_ITEM_START_PATTERN = re.compile( + r"(?:\[|, )(?P\\*['\"])" + r"(?P(?=[A-Z])\w*(?:Error|Exception|Timeout|ExceptionGroup)): " +) TRACEBACK_FRAME_PATTERN = re.compile( r'File "(?P[^"]+)", line (?P\d+)' ) @@ -106,6 +135,12 @@ class RepoFrame: line_number: int +@dataclass +class LeafError: + exception_type: str + message: str + + @dataclass class FailureEvent: bot_name: str @@ -116,8 +151,10 @@ class FailureEvent: message: str categories: list[str] question_url: str | None - traceback_text: str | None + context_text: str | None deepest_repo_frame: RepoFrame | None + is_question_failure: bool = False + leaf_error_counts: dict[str, int] = field(default_factory=dict) @dataclass @@ -133,6 +170,11 @@ class JobAnalysis: job_url: str log_path: str events: list[FailureEvent] + questions_attempted: int | None + + @property + def failed_question_count(self) -> int: + return sum(1 for event in self.events if event.is_question_failure) def resolve_github_token() -> str: @@ -151,20 +193,38 @@ def resolve_github_token() -> str: ) +def get_with_network_retries( + url: str, headers: dict, params: dict | None +) -> requests.Response: + for retry_delay_seconds in GITHUB_RETRY_DELAYS_SECONDS: + try: + return requests.get(url, headers=headers, params=params, timeout=60) + except (requests.ConnectionError, requests.Timeout) as network_error: + logger.warning( + f"Network error requesting {url}: {network_error}. " + f"Retrying in {retry_delay_seconds}s" + ) + time.sleep(retry_delay_seconds) + return requests.get(url, headers=headers, params=params, timeout=60) + + def github_get( path: str, token: str, params: dict | None = None, as_text: bool = False ) -> dict | str: - response = requests.get( + response = get_with_network_retries( f"{GITHUB_API}{path}", headers={ "Authorization": f"Bearer {token}", "Accept": "application/vnd.github+json", }, params=params, - timeout=60, ) response.raise_for_status() - return response.text if as_text else response.json() + if not as_text: + return response.json() + # Log downloads come back without a charset, which requests decodes as latin-1 + response.encoding = "utf-8" + return response.text def parse_since_to_datetime(since: str) -> datetime: @@ -204,22 +264,23 @@ def list_workflow_runs( return runs[:max_runs] -def list_failed_jobs(repo: str, run_id: int, token: str) -> list[dict]: +def list_run_jobs(repo: str, run_id: int, token: str) -> list[dict]: jobs: list[dict] = [] page = 1 + page_size = 100 while True: data = github_get( f"/repos/{repo}/actions/runs/{run_id}/jobs", token, - params={"per_page": 100, "page": page, "filter": "latest"}, + params={"per_page": page_size, "page": page, "filter": "latest"}, ) assert isinstance(data, dict) page_jobs = data.get("jobs", []) - if not page_jobs: - break jobs.extend(page_jobs) + if len(page_jobs) < page_size: + break page += 1 - return [job for job in jobs if job.get("conclusion") == "failure"] + return jobs def download_job_log(repo: str, job_id: int, token: str) -> str: @@ -230,6 +291,16 @@ def download_job_log(repo: str, job_id: int, token: str) -> str: return log_text +def load_or_download_job_log(repo: str, job_id: int, token: str, log_path: Path) -> str: + if log_path.exists(): + return log_path.read_text(encoding="utf-8") + log_text = download_job_log(repo, job_id, token) + partial_path = log_path.with_suffix(".partial") + partial_path.write_text(log_text, encoding="utf-8") + partial_path.replace(log_path) + return log_text + + def strip_github_timestamps(log_text: str) -> str: return "\n".join( GH_TIMESTAMP_PREFIX_PATTERN.sub("", line) for line in log_text.splitlines() @@ -306,6 +377,135 @@ def extract_question_url(text: str) -> str | None: return url_match.group(0) if url_match else None +def unescape_nested_repr(text: str) -> str: + with_newlines = re.sub(r"\\+n", "\n", text) + return re.sub(r"\\+(?=['\"])", "", with_newlines) + + +def extract_leaf_errors(nested_message: str) -> list[LeafError]: + """ + Errors are nested as `'ErrorType: message'` items of repr'd lists, with one + more level of quote escaping per level of nesting. A leaf ends at the next + quote of its own escaping level that closes a list item. + """ + leaf_errors: list[LeafError] = [] + last_leaf_end = 0 + for item_match in NESTED_ERROR_ITEM_START_PATTERN.finditer(nested_message): + exception_type = item_match.group("exception_type") + if item_match.start() < last_leaf_end or exception_type.endswith( + "ExceptionGroup" + ): + continue + closing_quote_pattern = re.compile( + r"(? LeafError: + signatures = [ + normalize_message_to_signature(leaf.exception_type, leaf.message) + for leaf in leaf_errors + ] + most_common_signature = Counter(signatures).most_common(1)[0][0] + return leaf_errors[signatures.index(most_common_signature)] + + +def find_matches(log_lines: list[str], pattern: re.Pattern[str]) -> list[re.Match[str]]: + matches = [] + for line in log_lines: + line_match = pattern.search(line) + if line_match: + matches.append(line_match) + return matches + + +def select_final_question_error_matches( + error_matches: list[re.Match[str]], final_failure_count_by_url: Counter[str] +) -> list[re.Match[str]]: + remaining_failures_by_url = Counter(final_failure_count_by_url) + selected_matches = [] + for error_match in reversed(error_matches): + question_url = error_match.group("question_url") + if remaining_failures_by_url[question_url] > 0: + selected_matches.append(error_match) + remaining_failures_by_url[question_url] -= 1 + return list(reversed(selected_matches)) + + +def parse_question_failure_events( + log_lines: list[str], bot_name: str, run_id: int, job_name: str, job_url: str +) -> list[FailureEvent]: + """ + One event per question report that ended in failure. Error lines alone can + over-count (run_bots retries timeouts), so when the report summary was logged + its ❌ lines set how many failures each URL had, and the latest that many error + lines are kept. Counting is per URL occurrence because group subquestions share + a URL. Without a summary (e.g. job cancelled) every error line counts. + """ + error_matches = find_matches(log_lines, QUESTION_ERROR_LINE_PATTERN) + final_failure_count_by_url = Counter( + summary_match.group("question_url") + for summary_match in find_matches( + log_lines, FAILED_QUESTION_SUMMARY_LINE_PATTERN + ) + ) + report_summary_was_logged = any( + line.startswith(REPORT_SUMMARY_STATS_LINE) for line in log_lines + ) + if report_summary_was_logged: + error_matches = select_final_question_error_matches( + error_matches, final_failure_count_by_url + ) + wrapped_exception_type_by_url = { + wrapped_match.group("question_url"): wrapped_match.group("exception_type") + for wrapped_match in find_matches(log_lines, WRAPPED_QUESTION_EXCEPTION_PATTERN) + } + events = [] + for error_match in error_matches: + question_url = error_match.group("question_url") + nested_message = error_match.group("nested_message") + leaf_errors = extract_leaf_errors(nested_message) + if leaf_errors: + representative_leaf = pick_representative_leaf(leaf_errors) + exception_type = representative_leaf.exception_type + message = representative_leaf.message + else: + exception_type = wrapped_exception_type_by_url.get( + question_url, "UnknownException" + ) + message = nested_message + events.append( + FailureEvent( + bot_name=bot_name, + run_id=run_id, + job_name=job_name, + job_url=job_url, + exception_type=exception_type, + message=message, + categories=categorize_error(f"{exception_type} {message}"), + question_url=question_url, + context_text=nested_message, + deepest_repo_frame=None, + is_question_failure=True, + leaf_error_counts=dict( + Counter(leaf.exception_type for leaf in leaf_errors) + ), + ) + ) + return events + + def parse_traceback_failure_events( log_lines: list[str], bot_name: str, run_id: int, job_name: str, job_url: str ) -> list[FailureEvent]: @@ -324,7 +524,7 @@ def parse_traceback_failure_events( categories=categorize_error(f"{exception_type} {message}"), question_url=extract_question_url(message) or extract_question_url(traceback_text), - traceback_text=traceback_text, + context_text=traceback_text, deepest_repo_frame=extract_deepest_repo_frame(block_lines), ) ) @@ -344,7 +544,7 @@ def parse_short_summary_failure_events( is_new_section = ( "✅" in continuation_line or "❌" in continuation_line - or continuation_line.startswith("Stats for passing reports") + or continuation_line.startswith(REPORT_SUMMARY_STATS_LINE) or continuation_line.startswith("----") or PYTHON_LOG_RECORD_PATTERN.match(continuation_line) ) @@ -363,7 +563,7 @@ def parse_short_summary_failure_events( message=message, categories=categorize_error(f"{exception_type} {message}"), question_url=extract_question_url(message), - traceback_text=None, + context_text=None, deepest_repo_frame=None, ) ) @@ -383,11 +583,11 @@ def make_unparsed_failure_event( message=( "No traceback or per-question failure line found. The job likely failed " "at the infrastructure level (setup, token resolution, job cancellation/" - "timeout) or the log format changed. Log tail attached as traceback_text." + "timeout) or the log format changed. Log tail attached as context_text." ), categories=categorize_error(log_tail), question_url=None, - traceback_text=log_tail, + context_text=log_tail, deepest_repo_frame=None, ) @@ -396,9 +596,13 @@ def parse_failures_from_log( log_text: str, bot_name: str, run_id: int, job_name: str, job_url: str ) -> list[FailureEvent]: log_lines = strip_github_timestamps(log_text).splitlines() - events = parse_traceback_failure_events( + events = parse_question_failure_events( log_lines, bot_name, run_id, job_name, job_url ) + if not events: + events = parse_traceback_failure_events( + log_lines, bot_name, run_id, job_name, job_url + ) if not events: events = parse_short_summary_failure_events( log_lines, bot_name, run_id, job_name, job_url @@ -410,11 +614,24 @@ def parse_failures_from_log( return events +def parse_questions_attempted(log_text: str) -> int | None: + line_match = QUESTIONS_ATTEMPTED_LINE_PATTERN.search(log_text) + return int(line_match.group("question_count")) if line_match else None + + def normalize_message_to_signature(exception_type: str, message: str) -> str: - no_urls = QUESTION_URL_PATTERN.sub("", message) - no_request_ids = re.sub(r"(req|chatcmpl|gen)-[\w-]+", "", no_urls) + no_pydantic_input = re.sub( + r"\[type=\w+, input_value=.*?, input_type=\w+\]", "", message + ) + no_pydantic_links = re.sub( + r"For further information visit \S+", "", no_pydantic_input + ) + no_urls = QUESTION_URL_PATTERN.sub("", no_pydantic_links) + no_request_ids = re.sub(r"\b(req|chatcmpl|gen)[-_][\w-]+", "", no_urls) no_numbers = re.sub(r"\d+", "", no_request_ids) - return f"{exception_type}: {no_numbers[:300]}" + no_list_contents = re.sub(r"\[[^\[\]]*\]", "[...]", no_numbers) + collapsed_whitespace = re.sub(r"\s+", " ", no_list_contents).strip() + return f"{exception_type}: {collapsed_whitespace[:300]}" def group_failures(events: list[FailureEvent]) -> list[FailureGroup]: @@ -446,35 +663,109 @@ def truncate_text(text: str, max_length: int) -> str: def build_failure_group_section(group: FailureGroup) -> list[str]: example = group.events[0] - bots_affected = sorted({event.bot_name for event in group.events}) + bot_counts = count_by([event.bot_name for event in group.events]) section_lines = [ f"### [{len(group.events)}x] {example.exception_type} | " f"categories={','.join(example.categories)}", - f"Bots affected: {', '.join(bots_affected)}", + "Bots affected: " + + ", ".join(f"{bot_name} ({count})" for bot_name, count in bot_counts), ] + leaf_error_counts: Counter[str] = Counter() + for event in group.events: + leaf_error_counts.update(event.leaf_error_counts) + if leaf_error_counts: + section_lines.append( + "Leaf errors across these questions: " + + ", ".join( + f"{count}x {exception_type}" + for exception_type, count in leaf_error_counts.most_common() + ) + ) if example.deepest_repo_frame: section_lines.append( f"Deepest repo frame: `{example.deepest_repo_frame.file_path}:" f"{example.deepest_repo_frame.line_number}`" ) section_lines.append(f"\n```\n{truncate_text(example.message, 2000)}\n```\n") - if example.traceback_text: + if example.context_text: section_lines.append( - f"
Example traceback / log tail\n\n" - f"```\n{truncate_text(example.traceback_text, 3000)}\n```\n\n
\n" + f"
Example full error / traceback / log tail\n\n" + f"```\n{truncate_text(example.context_text, 3000)}\n```\n\n
\n" ) return section_lines -def build_report(job_analyses: list[JobAnalysis], output_dir: Path) -> str: +def format_ratio(numerator: int, denominator: int) -> str: + if denominator == 0: + return f"{numerator}/unknown" + return f"{numerator}/{denominator} ({numerator / denominator:.0%})" + + +def build_bot_summary_lines( + job_analyses: list[JobAnalysis], total_jobs_by_bot: dict[str, int] +) -> list[str]: + analyses_by_bot: dict[str, list[JobAnalysis]] = {} + for analysis in job_analyses: + analyses_by_bot.setdefault(analysis.bot_name, []).append(analysis) + + summary_lines = [ + "\n## Failures by bot\n", + "- **Failed jobs / jobs in analyzed runs**: analyzed runs are those with at " + "least one failed job, so runs where every bot passed are not counted.", + "- **Failed questions / questions attempted**: only failed jobs are " + "downloaded, so this is the share of questions that failed *within failed " + "jobs* (low = one bad question, high = bot broken), not the bot's overall " + "question failure rate. Attempts come from the `Running bot X with N " + "questions` log line.\n", + "| Bot | Failed jobs / jobs in analyzed runs | Failed questions / questions " + "attempted | Failed jobs without question-level errors |", + "|---|---|---|---|", + ] + sorted_bots = sorted( + analyses_by_bot.items(), key=lambda bot_item: (-len(bot_item[1]), bot_item[0]) + ) + for bot_name, bot_analyses in sorted_bots: + analyses_with_known_attempts = [ + analysis + for analysis in bot_analyses + if analysis.questions_attempted is not None + ] + failed_questions = sum( + analysis.failed_question_count for analysis in analyses_with_known_attempts + ) + questions_attempted = sum( + analysis.questions_attempted or 0 + for analysis in analyses_with_known_attempts + ) + jobs_without_question_errors = sum( + 1 for analysis in bot_analyses if analysis.failed_question_count == 0 + ) + summary_lines.append( + f"| {bot_name} " + f"| {format_ratio(len(bot_analyses), total_jobs_by_bot.get(bot_name, 0))} " + f"| {format_ratio(failed_questions, questions_attempted)} " + f"| {jobs_without_question_errors} |" + ) + return summary_lines + + +def build_report( + job_analyses: list[JobAnalysis], + total_jobs_by_bot: dict[str, int], + report_dir: Path, +) -> str: all_events = [event for analysis in job_analyses for event in analysis.events] + question_events = [event for event in all_events if event.is_question_failure] groups = group_failures(all_events) report_lines = [ "# Bot Workflow Failure Report", f"\nGenerated: {datetime.now(timezone.utc).isoformat()}", f"\nFailed jobs analyzed: {len(job_analyses)}", - f"Individual failures parsed: {len(all_events)}", + f"Failed questions (one event each, grouped by leaf error): " + f"{len(question_events)}", + f"Other failure events (from jobs without question-level errors): " + f"{len(all_events) - len(question_events)}", f"Unique failure signatures: {len(groups)}", "\n## Failures by category\n", ] @@ -484,9 +775,7 @@ def build_report(job_analyses: list[JobAnalysis], output_dir: Path) -> str: for category, count in count_by(category_occurrences): report_lines.append(f"- {category}: {count}") - report_lines.append("\n## Failures by bot\n") - for bot_name, count in count_by([event.bot_name for event in all_events]): - report_lines.append(f"- {bot_name}: {count}") + report_lines.extend(build_bot_summary_lines(job_analyses, total_jobs_by_bot)) question_urls = [event.question_url for event in all_events if event.question_url] if question_urls: @@ -510,17 +799,23 @@ def build_report(job_analyses: list[JobAnalysis], output_dir: Path) -> str: ) else "" ) + questions_attempted_text = ( + analysis.questions_attempted + if analysis.questions_attempted is not None + else "unknown" + ) report_lines.append( f"- **{analysis.bot_name}** (run {analysis.run_id}): " - f"{len(analysis.events)} failures parsed | " + f"{analysis.failed_question_count}/{questions_attempted_text} questions " + f"failed, {len(analysis.events)} failure events | " f"[job link]({analysis.job_url}) | raw log: `{analysis.log_path}`" f"{unparsed_note}" ) - report_path = output_dir / "report.md" - report_path.write_text("\n".join(report_lines)) + report_path = report_dir / "report.md" + report_path.write_text("\n".join(report_lines), encoding="utf-8") - json_path = output_dir / "failures.json" + json_path = report_dir / "failures.json" json_path.write_text( json.dumps( [ @@ -532,6 +827,8 @@ def build_report(job_analyses: list[JobAnalysis], output_dir: Path) -> str: "exception_type": event.exception_type, "categories": event.categories, "question_url": event.question_url, + "is_question_failure": event.is_question_failure, + "leaf_error_counts": event.leaf_error_counts, "signature": normalize_message_to_signature( event.exception_type, event.message ), @@ -546,38 +843,46 @@ def build_report(job_analyses: list[JobAnalysis], output_dir: Path) -> str: for event in all_events ], indent=2, - ) + ), + encoding="utf-8", ) return str(report_path) -def analyze_failed_jobs_for_run( - repo: str, run: dict, token: str, raw_logs_dir: Path +def analyze_failed_jobs( + repo: str, run_id: int, failed_jobs: list[dict], token: str, raw_logs_dir: Path ) -> list[JobAnalysis]: - failed_jobs = list_failed_jobs(repo, run["id"], token) - logger.info( - f"Run {run['id']} ({run['created_at']}): {len(failed_jobs)} failed jobs" - ) job_analyses: list[JobAnalysis] = [] for job in failed_jobs: bot_name = extract_bot_name(job["name"]) - log_path = raw_logs_dir / f"run{run['id']}_{sanitize_filename(bot_name)}.log" + log_path = ( + raw_logs_dir + / f"run{run_id}_job{job['id']}_{sanitize_filename(bot_name)}.log" + ) try: - log_text = download_job_log(repo, job["id"], token) + log_text = load_or_download_job_log(repo, job["id"], token, log_path) except requests.HTTPError as http_error: logger.warning(f"Could not download log for job {job['id']}: {http_error}") continue - log_path.write_text(log_text) events = parse_failures_from_log( - log_text, bot_name, run["id"], job["name"], job["html_url"] + log_text, bot_name, run_id, job["name"], job["html_url"] ) + questions_attempted = parse_questions_attempted(log_text) + if questions_attempted is None and any( + event.is_question_failure for event in events + ): + logger.warning( + f"No 'Running bot ... with N questions' line in {log_path}, so its " + "failed questions are left out of the per-bot question ratio" + ) job_analyses.append( JobAnalysis( bot_name=bot_name, - run_id=run["id"], + run_id=run_id, job_url=job["html_url"], log_path=str(log_path), events=events, + questions_attempted=questions_attempted, ) ) return job_analyses @@ -609,21 +914,32 @@ def analyze_runs( ) timestamp = datetime.now(timezone.utc).strftime("%Y%m%d_%H%M%S") - analysis_dir = output_dir / timestamp - raw_logs_dir = analysis_dir / "raw_logs" + report_dir = output_dir / timestamp + raw_logs_dir = output_dir / "raw_logs" + report_dir.mkdir(parents=True, exist_ok=True) raw_logs_dir.mkdir(parents=True, exist_ok=True) job_analyses: list[JobAnalysis] = [] - for run in runs: + total_jobs_by_bot: Counter[str] = Counter() + for run_index, run in enumerate(runs, start=1): assert isinstance(run, dict) - job_analyses.extend(analyze_failed_jobs_for_run(repo, run, token, raw_logs_dir)) + jobs = list_run_jobs(repo, run["id"], token) + total_jobs_by_bot.update(extract_bot_name(job["name"]) for job in jobs) + failed_jobs = [job for job in jobs if job.get("conclusion") == "failure"] + logger.info( + f"[{run_index}/{len(runs)}] Run {run['id']} ({run['created_at']}): " + f"{len(failed_jobs)} of {len(jobs)} jobs failed" + ) + job_analyses.extend( + analyze_failed_jobs(repo, run["id"], failed_jobs, token, raw_logs_dir) + ) if not job_analyses: logger.info("No failed jobs found in the selected window.") - report_path = build_report(job_analyses, analysis_dir) + report_path = build_report(job_analyses, total_jobs_by_bot, report_dir) logger.info(f"Report written to {report_path}") - logger.info(f"Raw logs saved under {raw_logs_dir}") + logger.info(f"Raw logs cached under {raw_logs_dir}") return report_path From 9c2ba126281db90467b6090e0af554bbc1dc67fc Mon Sep 17 00:00:00 2001 From: Ben Wilson Date: Sat, 10 Oct 2026 15:54:29 -0600 Subject: [PATCH 2/2] Count no-log failed jobs and only completed jobs in per-bot ratios - Failed jobs per bot come from the job listing, so jobs whose log 404s still count. - Jobs of in-progress runs that have not finished are left out of the denominator. - Test analyze_runs end to end with GitHub calls stubbed. - count_by uses Counter.most_common; docstring no longer names another file's behavior. Co-Authored-By: Claude Opus 5.5 --- .../test_analyze_bot_run_failures.py | 118 +++++++++++++++++- .../analyze_bot_run_failures.py | 39 ++++-- 2 files changed, 143 insertions(+), 14 deletions(-) diff --git a/code_tests/unit_tests/test_analyze_bot_run_failures.py b/code_tests/unit_tests/test_analyze_bot_run_failures.py index bfd52323..372d44a3 100644 --- a/code_tests/unit_tests/test_analyze_bot_run_failures.py +++ b/code_tests/unit_tests/test_analyze_bot_run_failures.py @@ -363,13 +363,129 @@ def test_bot_summary_reports_job_and_question_ratios(tmp_path: Path) -> None: questions_attempted=3, ) report_path = build_report( - [job_with_two_failures, job_with_one_failure], {"bot_a": 4}, tmp_path + [job_with_two_failures, job_with_one_failure], + {"bot_a": 2}, + {"bot_a": 4}, + tmp_path, ) report_text = Path(report_path).read_text(encoding="utf-8") assert "| bot_a | 2/4 (50%) | 3/8 (38%) | 0 |" in report_text assert "[3x] NotFoundError" in report_text +def test_analyze_runs_counts_jobs_without_logs_and_skips_unfinished_jobs( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + jobs_by_run_id = { + 1: [ + { + "id": 11, + "name": "bot_a / run_bot", + "status": "completed", + "conclusion": "failure", + "html_url": "http://job-11", + }, + { + "id": 12, + "name": "bot_b / run_bot", + "status": "completed", + "conclusion": "failure", + "html_url": "http://job-12", + }, + { + "id": 13, + "name": "bot_c / run_bot", + "status": "completed", + "conclusion": "failure", + "html_url": "http://job-13", + }, + ], + 2: [ + { + "id": 21, + "name": "bot_a / run_bot", + "status": "completed", + "conclusion": "success", + "html_url": "http://job-21", + }, + { + "id": 22, + "name": "bot_b / run_bot", + "status": "in_progress", + "conclusion": None, + "html_url": "http://job-22", + }, + { + "id": 23, + "name": "bot_c / run_bot", + "status": "completed", + "conclusion": "failure", + "html_url": "http://job-23", + }, + ], + } + downloaded_log_paths: list[Path] = [] + + def fake_load_or_download( + repo: str, job_id: int, token: str, log_path: Path + ) -> str: + if job_id != 11: + raise requests.HTTPError( + "404 Client Error: The specified blob does not exist." + ) + downloaded_log_paths.append(log_path) + return make_log( + "2026-06-11 17:13:40,100 - __main__ - INFO - Running bot METAC_BOT_A with 3 questions", + make_question_error_line( + QUESTION_URL, leaf_list_message("NotFoundError: No endpoints") + ), + ) + + monkeypatch.setattr( + analyze_bot_run_failures, "resolve_github_token", lambda: "token" + ) + monkeypatch.setattr( + analyze_bot_run_failures, + "list_workflow_runs", + lambda repo, workflow, token, since, max_runs: [ + { + "id": 1, + "created_at": "t1", + "status": "completed", + "conclusion": "failure", + }, + { + "id": 2, + "created_at": "t2", + "status": "completed", + "conclusion": "failure", + }, + ], + ) + monkeypatch.setattr( + analyze_bot_run_failures, + "list_run_jobs", + lambda repo, run_id, token: jobs_by_run_id[run_id], + ) + monkeypatch.setattr( + analyze_bot_run_failures, "load_or_download_job_log", fake_load_or_download + ) + + report_path = analyze_bot_run_failures.analyze_runs( + repo="owner/repo", + workflow="workflow.yaml", + since="1d", + max_runs=10, + output_dir=tmp_path, + ) + + report_text = Path(report_path).read_text(encoding="utf-8") + assert downloaded_log_paths == [tmp_path / "raw_logs" / "run1_job11_bot_a.log"] + assert "| bot_c | 2/2 (100%) | 0/unknown | 0 |" in report_text + assert "| bot_a | 1/2 (50%) | 1/3 (33%) | 0 |" in report_text + assert "| bot_b | 1/1 (100%) | 0/unknown | 0 |" in report_text + + def test_github_get_retries_network_errors_and_decodes_logs_as_utf8( monkeypatch: pytest.MonkeyPatch, ) -> None: diff --git a/scripts/skills/analyze_bot_failures/analyze_bot_run_failures.py b/scripts/skills/analyze_bot_failures/analyze_bot_run_failures.py index 7661eee6..020caa16 100644 --- a/scripts/skills/analyze_bot_failures/analyze_bot_run_failures.py +++ b/scripts/skills/analyze_bot_failures/analyze_bot_run_failures.py @@ -448,7 +448,7 @@ def parse_question_failure_events( ) -> list[FailureEvent]: """ One event per question report that ended in failure. Error lines alone can - over-count (run_bots retries timeouts), so when the report summary was logged + over-count when a question is retried, so when the report summary was logged its ❌ lines set how many failures each URL had, and the latest that many error lines are kept. Counting is per URL occurrence because group subquestions share a URL. Without a summary (e.g. job cancelled) every error line counts. @@ -651,10 +651,7 @@ def sanitize_filename(name: str) -> str: def count_by(items: list[str]) -> list[tuple[str, int]]: - counts: dict[str, int] = {} - for item in items: - counts[item] = counts.get(item, 0) + 1 - return sorted(counts.items(), key=lambda pair: -pair[1]) + return Counter(items).most_common() def truncate_text(text: str, max_length: int) -> str: @@ -702,7 +699,9 @@ def format_ratio(numerator: int, denominator: int) -> str: def build_bot_summary_lines( - job_analyses: list[JobAnalysis], total_jobs_by_bot: dict[str, int] + job_analyses: list[JobAnalysis], + failed_jobs_by_bot: dict[str, int], + total_jobs_by_bot: dict[str, int], ) -> list[str]: analyses_by_bot: dict[str, list[JobAnalysis]] = {} for analysis in job_analyses: @@ -711,7 +710,9 @@ def build_bot_summary_lines( summary_lines = [ "\n## Failures by bot\n", "- **Failed jobs / jobs in analyzed runs**: analyzed runs are those with at " - "least one failed job, so runs where every bot passed are not counted.", + "least one failed job, so runs where every bot passed are not counted. Only " + "completed jobs count, and failed jobs include ones whose log could not be " + "downloaded.", "- **Failed questions / questions attempted**: only failed jobs are " "downloaded, so this is the share of questions that failed *within failed " "jobs* (low = one bad question, high = bot broken), not the bot's overall " @@ -722,9 +723,10 @@ def build_bot_summary_lines( "|---|---|---|---|", ] sorted_bots = sorted( - analyses_by_bot.items(), key=lambda bot_item: (-len(bot_item[1]), bot_item[0]) + failed_jobs_by_bot.items(), key=lambda bot_item: (-bot_item[1], bot_item[0]) ) - for bot_name, bot_analyses in sorted_bots: + for bot_name, failed_job_count in sorted_bots: + bot_analyses = analyses_by_bot.get(bot_name, []) analyses_with_known_attempts = [ analysis for analysis in bot_analyses @@ -742,7 +744,7 @@ def build_bot_summary_lines( ) summary_lines.append( f"| {bot_name} " - f"| {format_ratio(len(bot_analyses), total_jobs_by_bot.get(bot_name, 0))} " + f"| {format_ratio(failed_job_count, total_jobs_by_bot.get(bot_name, 0))} " f"| {format_ratio(failed_questions, questions_attempted)} " f"| {jobs_without_question_errors} |" ) @@ -751,6 +753,7 @@ def build_bot_summary_lines( def build_report( job_analyses: list[JobAnalysis], + failed_jobs_by_bot: dict[str, int], total_jobs_by_bot: dict[str, int], report_dir: Path, ) -> str: @@ -775,7 +778,9 @@ def build_report( for category, count in count_by(category_occurrences): report_lines.append(f"- {category}: {count}") - report_lines.extend(build_bot_summary_lines(job_analyses, total_jobs_by_bot)) + report_lines.extend( + build_bot_summary_lines(job_analyses, failed_jobs_by_bot, total_jobs_by_bot) + ) question_urls = [event.question_url for event in all_events if event.question_url] if question_urls: @@ -920,12 +925,18 @@ def analyze_runs( raw_logs_dir.mkdir(parents=True, exist_ok=True) job_analyses: list[JobAnalysis] = [] + failed_jobs_by_bot: Counter[str] = Counter() total_jobs_by_bot: Counter[str] = Counter() for run_index, run in enumerate(runs, start=1): assert isinstance(run, dict) jobs = list_run_jobs(repo, run["id"], token) - total_jobs_by_bot.update(extract_bot_name(job["name"]) for job in jobs) + total_jobs_by_bot.update( + extract_bot_name(job["name"]) + for job in jobs + if job.get("status") == "completed" + ) failed_jobs = [job for job in jobs if job.get("conclusion") == "failure"] + failed_jobs_by_bot.update(extract_bot_name(job["name"]) for job in failed_jobs) logger.info( f"[{run_index}/{len(runs)}] Run {run['id']} ({run['created_at']}): " f"{len(failed_jobs)} of {len(jobs)} jobs failed" @@ -937,7 +948,9 @@ def analyze_runs( if not job_analyses: logger.info("No failed jobs found in the selected window.") - report_path = build_report(job_analyses, total_jobs_by_bot, report_dir) + report_path = build_report( + job_analyses, failed_jobs_by_bot, total_jobs_by_bot, report_dir + ) logger.info(f"Report written to {report_path}") logger.info(f"Raw logs cached under {raw_logs_dir}") return report_path