fix(engine): drop tracebacks from warning logs on handled fail-open paths - #367
Conversation
…aths When a validator-triggered agent re-run fails, the engine correctly fails open and keeps the original output, but logged the warning with exc_info=True, so the normal CLI output showed a full Python traceback even though the workflow continued successfully. The warning is now concise (exception type and message), with the full traceback kept at DEBUG level. The same pattern is applied to the other handled fail-open paths: the validator call itself (engine/validator.py and workflow.py), session-ID collection for checkpoints, checkpoint save, and checkpoint rotation listing. Event-callback errors in hermes and _event_format move to logger.debug, matching the existing convention in claude_agent_sdk and _pydantic_ai. The regression test now asserts there is no traceback at WARNING level and that it remains available at DEBUG level. Closes microsoft#357
jrob5756
left a comment
There was a problem hiding this comment.
Solid, well-scoped fix! The concise-warning/debug-traceback split is applied consistently, cancellation still propagates everywhere, and the hermes/_event_format downgrade actually closes an existing parity gap with claude_agent_sdk and _pydantic_ai rather than opening one. A couple of small suggestions below, nothing blocking at all.
| logger.warning("Failed to list checkpoints for %s", action, exc_info=True) | ||
| except Exception as exc: | ||
| logger.warning( | ||
| "Failed to list checkpoints for %s (%s: %s)", action, type(exc).__name__, exc |
There was a problem hiding this comment.
This message only carries action ("rotation"/"cleanup"), not which run or workflow failed. Since a failure here means checkpoints silently pile up over time, it'd help to include run_id or workflow_path at WARNING level so this is actionable without turning on DEBUG.
| "Failed to list checkpoints for %s (%s: %s)", action, type(exc).__name__, exc | |
| "Failed to list checkpoints for %s (run_id=%s, workflow=%s) (%s: %s)", | |
| action, | |
| run_id, | |
| workflow_path, | |
| type(exc).__name__, | |
| exc, |
There was a problem hiding this comment.
Done in 54d4a60 — the WARNING now names both run_id and workflow_path:
Failed to list checkpoints for rotation (run_id=run-42, workflow=/path/to/wf.yaml) (OSError: disk gone)
Also added test_listing_failure_logs_run_context_and_debug_traceback in TestRotatePeriodicCheckpoints asserting the WARNING carries the run context and that the traceback is DEBUG-only.
| logger.warning("Failed to save checkpoint", exc_info=True) | ||
| except Exception as exc: | ||
| logger.warning("Failed to save checkpoint (%s: %s)", type(exc).__name__, exc) | ||
| logger.debug("Checkpoint save traceback", exc_info=True) |
There was a problem hiding this comment.
This site (and _delete_periodic_checkpoints below) already has a behavioral test for the failure path (test_never_raises_on_failure), but nothing pins the new logging contract the way test_rerun_failure_keeps_original_no_double_count_and_emits_event does for the validator re-run. Worth extending with the same caplog pattern so a future refactor can't quietly put exc_info=True back on the warning.
There was a problem hiding this comment.
Done in 54d4a60 — added two caplog tests in tests/test_engine/test_checkpoint.py mirroring the validator re-run pattern:
test_save_checkpoint_failure_logs_concise_warning_and_debug_traceback(TestSaveCheckpoint) — pinssave_checkpoint's fail-open path: exactly one WARNING withexc_info is None, asserts the exception type (FileNotFoundError) appears in the message, and a DEBUG record withexc_infopresent.test_listing_failure_logs_run_context_and_debug_traceback(TestRotatePeriodicCheckpoints) — same contract for the rotation/cleanup listing failure, plus assertions thatrun_idand the workflow path appear in the WARNING text.
| type(exc).__name__, | ||
| exc, | ||
| ) | ||
| logger.debug("Validator call traceback for agent '%s'", agent.name, exc_info=True) |
There was a problem hiding this comment.
This is the closest sibling to the workflow.py re-run path that already has a caplog regression test — same message-formatting pattern, same risk of a copy/paste slip going untested. A quick caplog assertion here (WARNING has no exc_info, DEBUG does) would close the gap cheaply.
There was a problem hiding this comment.
Done in 54d4a60 — added test_provider_error_logs_concise_warning_and_debug_traceback in tests/test_engine/test_validator.py::TestValidatorValidate with the same caplog shape as the workflow.py re-run test: AsyncMock(side_effect=RuntimeError("boom")), asserts exactly one WARNING with exc_info is None containing "Validator call failed", "RuntimeError", "boom", and the agent name, plus a DEBUG record with exc_info present. A copy/paste slip reintroducing exc_info=True on the WARNING now fails this test.
…checkpoint warnings Address review feedback on PR microsoft#367: - Include run_id and workflow_path in the checkpoint rotation/cleanup listing-failure WARNING so a silent checkpoint leak is actionable without turning on DEBUG. - Add caplog regression tests for save_checkpoint and rotate_periodic_checkpoints asserting the new contract: exactly one concise WARNING without exc_info, full traceback only at DEBUG level. - Add the matching caplog test for engine/validator.py's provider-error fail-open path so a future refactor can't quietly reintroduce exc_info=True on the WARNING.
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #367 +/- ##
=======================================
Coverage ? 90.86%
=======================================
Files ? 95
Lines ? 14794
Branches ? 0
=======================================
Hits ? 13442
Misses ? 1352
Partials ? 0 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
Summary
Fixes #357.
When a semantic validator rejects an agent output and the validator-triggered primary re-run fails, Conductor correctly fails open and keeps the original output — but logged the warning with
exc_info=True, so users saw a full Python traceback at WARNING level even though the workflow continued successfully. This made a handled validator recovery failure look like an unhandled workflow crash.The warning is now concise (exception type and message included), and the full traceback is kept at DEBUG level for diagnosis.
Changes
engine/workflow.py—_apply_validator: the re-run fail-open path (the exact scenario from the issue) now logs a concise warning withoutexc_info; the traceback moves tologger.debug(..., exc_info=True).logger.warning(..., exc_info=True)on fail-open paths:engine/validator.pyandengine/workflow.py— validator call failure / timeout (also documented fail-open behavior, seedocs/workflow-syntax.md)engine/workflow.py— provider session-ID collection for checkpointsengine/checkpoint.py— checkpoint save failure and rotation/cleanup listing failureproviders/hermes.pyandproviders/_event_format.py: event-callback errors move fromlogger.warning(..., exc_info=True)tologger.debug(..., exc_info=True), matching the existing convention inclaude_agent_sdk.py::_safe_callbackand_pydantic_ai/events.py(provider parity).No documentation or frontend changes were needed:
docs/workflow-syntax.mdalready describes validator fail-open as "treated as a pass (with a logged warning)", and thererun_erroredevent handling in the dashboard is unchanged.Test plan
test_rerun_failure_keeps_original_no_double_count_and_emits_eventwithcaplogassertions: exactly one WARNING record (noexc_info, message contains the exception type and text), and the traceback present at DEBUG level.ruff checkandty checkclean on all touched files (remaining diagnostics pre-exist onmain).