diff --git a/cron/scheduler_delivery.py b/cron/scheduler_delivery.py index dc58dbc4f6..600f03ea9f 100644 --- a/cron/scheduler_delivery.py +++ b/cron/scheduler_delivery.py @@ -653,25 +653,38 @@ def _get_bot_chat_delivery_timeout() -> int: return 600 -_BOT_CHAT_STREAM_TAIL = 500 +_BOT_CHAT_STDERR_TAIL = 500 +# stdout is the model's answer; only a short tail is persisted (jobs.json / ledger). +_BOT_CHAT_STDOUT_TAIL = 200 +_BOT_CHAT_BANNER_PREFIXES = ("Resumed session", "session_id:") def _format_failure_streams(result) -> str: - """Labeled stderr+stdout tails for a failed delivery turn ("": none). + """Exit code plus labeled, redacted stderr/stdout tails for a failed delivery turn. - ``-Q`` reports the resume banner and ``session_id:`` on stderr while the - response rides stdout, so ``stderr or stdout`` discards half the signal — - and when stderr is empty and stdout holds only the banner, the recorded - error carries zero diagnostics (#104056). Both tails are kept, capped. + ``-Q`` reports the resume banner and ``session_id:`` while the response + rides stdout, so ``stderr or stdout`` discarded half the signal — and when + stderr is empty and stdout holds only the banner, the recorded error + carried zero diagnostics (#104056). The banner lines are dropped from the + stdout tail so what remains is the reason; the exit code is always named. + The text lands in ``last_delivery_error`` on disk, so it is scrubbed like + ``cron.incidents`` / ``cron.delivery_queue`` scrub their persisted errors. """ + from agent.redact import redact_sensitive_text + err = (getattr(result, "stderr", None) or "").strip() out = (getattr(result, "stdout", None) or "").strip() - parts = [] + parts = [f"exit code {getattr(result, 'returncode', '?')}"] if err: - parts.append(f"stderr: {err[-_BOT_CHAT_STREAM_TAIL:]}") + parts.append(f"stderr: {err[-_BOT_CHAT_STDERR_TAIL:]}") if out: - parts.append(f"stdout: {out[-_BOT_CHAT_STREAM_TAIL:]}") - return " | ".join(parts) + kept = "\n".join( + line for line in out.splitlines() + if line.strip() and not line.strip().lstrip("↻ ").startswith(_BOT_CHAT_BANNER_PREFIXES)) + parts.append( + f"stdout: {kept[-_BOT_CHAT_STDOUT_TAIL:]}" if kept + else "stdout was only the resume banner") + return redact_sensitive_text(" | ".join(parts), force=True, redact_url_credentials=True) def _deliver_to_bot_chat(job: dict, content: str, profile: str, *, deferred: Optional[dict] = None) -> Optional[str]: @@ -807,12 +820,12 @@ def _deliver_to_bot_chat(job: dict, content: str, profile: str, *, deferred: Opt if result.returncode != 0: tail = _format_failure_streams(result) logger.warning( - "Job '%s': bot-chat delivery to profile '%s' failed (exit %s) at %s%s", - job_id, profile_label, result.returncode, home, f": {tail}" if tail else "") + "Job '%s': bot-chat delivery to profile '%s' failed at %s: %s", + job_id, profile_label, home, tail) return ( f"Hermes could not deliver this result to Bot Chat (profile '{profile_label}'). " "The result is saved; run `hermes cron runs` to see it, or `hermes doctor` if this keeps happening" - + (f". Details: {tail}" if tail else "")) + f". Details: {tail}") logger.info("Job '%s': delivered to Bot Chat of profile '%s'", job_id, profile_label) return None except subprocess.TimeoutExpired: diff --git a/tests/cron/test_cron_bot_chat_delivery.py b/tests/cron/test_cron_bot_chat_delivery.py index 4ae3f676cc..10db89d725 100644 --- a/tests/cron/test_cron_bot_chat_delivery.py +++ b/tests/cron/test_cron_bot_chat_delivery.py @@ -169,20 +169,39 @@ def test_deliver_failure_reports_both_streams_labeled(): assert "stdout: banner out" in err -def test_deliver_failure_stdout_only_when_stderr_empty(): +def test_deliver_failure_banner_only_stdout_names_exit_code_not_banner(): """The reported shape: empty stderr, stdout holding only the resume - banner — the recorded error must still carry it (#104056).""" - banner = 'Resumed session 20260905_121420_8084c7 "Bot Chat" (1 user message, 1 total messages)' + banner — the recorded error must say what happened (exit code, banner-only + stdout) instead of echoing the banner as if it were a reason (#104056).""" + banner = ('↻ Resumed session 20260905_121420_8084c7 "Bot Chat" (1 user message, 1 total messages)' + '\n\nsession_id: 20260905_121420_8084c7') with mock.patch.object( sched.subprocess, "run", return_value=_completed(returncode=1, stdout=banner, stderr=""), ), mock.patch.object(sched_delivery.shutil, "which", return_value="/usr/bin/hermes"): err = _deliver_to_bot_chat({"id": "j1", "name": "n"}, "out", "") assert err is not None - assert "stdout: " + banner in err + assert "exit code 1" in err + assert "stdout was only the resume banner" in err + assert "Resumed session" not in err assert "stderr:" not in err +def test_deliver_failure_persisted_stdout_tail_is_short_and_redacted(): + """``last_delivery_error`` lands in jobs.json / the ledger: the model's + answer on stdout is capped to a short tail and secrets are scrubbed.""" + answer = "x" * 5000 + "\nToken: sk-ant-api03-" + "A" * 80 + " done" + with mock.patch.object( + sched.subprocess, "run", + return_value=_completed(returncode=1, stdout=answer, stderr="boom-err"), + ), mock.patch.object(sched_delivery.shutil, "which", return_value="/usr/bin/hermes"): + err = _deliver_to_bot_chat({"id": "j1", "name": "n"}, "out", "") + assert err is not None + stdout_part = err.split("stdout: ", 1)[1] + assert len(stdout_part) <= 200 + assert "sk-ant-api03-" + "A" * 80 not in err + + def test_deliver_timeout_returns_error_string(): with mock.patch.object( sched.subprocess, "run",