Repository navigation
feat(continuous-ops): engine operational logging and correlation (XWING-2440) - #137
Conversation
|
[APPROVALNOTIFIER] This PR is APPROVED This pull-request has been approved by: smith-xyz The full list of commands accepted by this bot can be found here. The pull request process is described here DetailsNeeds approval from an approver in each of these files:
Approvers can indicate their approval by writing |
PR Summary by QodoAdd correlated, bounded operational logging to the engine
AI Description
Diagram
High-Level Assessment
Files changed (12)
|
Code Review by QodoResolved findings 1.
|
| def _error(operation: str, error: Exception) -> None: | ||
| print(f"ERROR: {operation} failed ({type(error).__name__})", file=sys.stderr) |
There was a problem hiding this comment.
🟠 Medium
2. Operators no longer see why a command was rejected 🐞 Bug ⚙ Maintainability
_error prints only type(error).__name__, and the lifecycle records log only error_type, so
first-party messages such as `ConfigError("give the command after --, and --repo exactly when the
asset has one"), NotFoundError("<repo> is not in the inventory")` and pack/core YAML validation
errors are no longer shown anywhere. Before this change these were printed as ERROR: {e}. Now
every misconfigured record/claim/diff/startup call prints only something like `ERROR: record
failed (ConfigError)`, and the operator cannot tell which flag, asset, repository or config key is
wrong.
Agent Prompt
## Issue description
The CLI now prints only the exception class name. Actionable first-party error messages (ConfigError, NotFoundError, validation errors) are lost, so operators cannot see what to fix.
## Fix Focus Areas
- src/traust_engine/ops/cli.py[246-247]
- src/traust_engine/ops/cli.py[256-320]
## Recommended Fix
Keep the bounded logging. In `_error`, though, print `str(error)` to stderr for engine-authored `TraustError` subclasses (ConfigError, NotFoundError), because their messages contain no command or credential data. Keep printing only the type for other exceptions. Alternatively, raise these with a bounded, safe `reason` code and print that.
ⓘ Copy this prompt and use it to remediate the issue with your preferred AI generation tools
| try: | ||
| return _passes(args, core, engine, shadow=args.op == "shadow") | ||
| except Exception as error: | ||
| _error("tick", error) | ||
| return 2 |
There was a problem hiding this comment.
🟠 Medium
3. Unexpected crashes leave no traceback to debug 🐞 Bug ◔ Observability
main now catches every Exception at the startup, tick and operation boundaries and records only type(error).__name__ in both stderr and the log, with no exc_info anywhere. Before, only OSError/TraustError were caught and anything else reached the user as a full traceback. Now a programming error (KeyError, AttributeError, a Core bug) in a long-running run loop or in claim shows up only as tick failed (KeyError), with no file, line or message to find the cause.
Agent Prompt
## Issue description
The broad `except Exception` handlers drop the stack trace entirely, so unexpected errors in the engine cannot be diagnosed.
## Fix Focus Areas
- src/traust_engine/ops/cli.py[289-311]
- src/traust_engine/ops/events.py[30-69]
## Recommended Fix
For exceptions that are not expected `TraustError`/`OSError` types, emit a DEBUG-level record (or a separate record) with the frame locations only: file, line and function names from `traceback.extract_tb`, but no exception message or argv. A narrower alternative is to catch only the expected types and let real bugs propagate with their traceback.
ⓘ Copy this prompt and use it to remediate the issue with your preferred AI generation tools
chubirka
left a comment
There was a problem hiding this comment.
Code review: changes required
Reviewed commit 1f280b541df9acd76768e47c6a518d4a5e54349d. Found 1 actionable issue(s); details are attached as inline review comments.
Merge hold: keep this PR in draft with auto-merge disabled until the findings have been addressed and the affected behavior has been re-reviewed. Do not mark ready solely because unrelated CI passes.
| error_type=type(error).__name__, | ||
| ) | ||
| raise | ||
| lifecycle(log, "tick", "completed", started=started, status=status) |
There was a problem hiding this comment.
[P2] Preserve warning severity for unhealthy tick summaries
The replacement tick summary always uses outcome="completed", so lifecycle emits it at INFO even when stale/overdue/unrunnable counts (or run admission withheld/deferred counts) are nonzero. This PR removes the corresponding WARNING calls from Controller and Admission. Consequently an operator using logging.level=WARNING, or a WARNING override for traust_engine, loses the existing alerts that work cannot run or has exceeded its freshness deadline. Keep the single bounded summary, but select WARNING when it contains the conditions that previously generated warnings; use INFO only for healthy ticks.
Evidence: Pinned base 779471d has WARNING emissions for unrunnable assets (controller.py:104), stale subjects (:131), overdue subjects (:173), and withheld/deferred admission (admission.py:101); the PR deletes them. At pinned head, cli.py:129 supplies no level and events.py:45-47 selects INFO for completed outcomes. A real shadow CLI invocation with a fresh SQLite store produced stale={downstream:1}, overdue={downstream:1}, unrunnable=[disabled]. With INFO configured its only tick event was INFO; with WARNING configured the entire log file contained zero events, although the same unhealthy state persisted.
Verification: Executed OperationalLogging-warning-repro.py against the pinned engine/Core/ledger stack with actual CLI, Pack, EngineLoop, and SQLite (no monkeypatches). Both invocations exited 0; INFO recorded engine.startup plus the unhealthy engine.tick; WARNING recorded 0 events. The 52 focused engine tests pass but do not test degraded tick severity.
There was a problem hiding this comment.
Addressed in be03c01 after rebasing onto merged engine #132/#133. The single terminal tick event is now WARNING when stale, overdue, unrunnable, withheld or deferred counts are nonzero, and INFO only when healthy; its status retains bounded counts and asset identifiers. A real SQLite run with a disabled asset and WARNING-only logging, plus shadow and withheld-admission regressions, now prove the warning is visible. The preflight gate remains inside startup before ready; I have kept this PR draft and your CHANGES_REQUESTED review hold pending re-review.
Code Review by Qodo
1.
|
1f280b5 to
be03c01
Compare
|
Review follow-up at |
|
Code review by qodo was updated up to the latest commit be03c01 |
|
Qodo’s new “Observation cleanup leaks a traceback” finding is fixed at |
|
Code review by qodo was updated up to the latest commit 1df5d9e |
Plan:
plans/traust-standardization/0-continuous-ops/27-shaun-engine-operational-logging.mdWhat
e01d420262641615427ecb537a14380c90442219and configuretraust_enginethrough the CLI's existing CoreContext; library imports still configure no handlers0.40.0with changelog and lock metadataReview resolutions
Three independent read-only reviews covered correctness/concurrency, sensitive-data flow and regression/release behavior.
readyis emittedExceptionvalues, emit bounded failure records and return nonzero without printing raw traceback/exception textengine.execution failed/completion_errorevent before re-raising; no execution path disappears between lease and CLI failureVerification
make lint-fixmake test: 191 passed (xdist)make check-release: release metadata valid againstorigin/mainReviewer checks (from the plan)
Quality checklist
Legacy files
Changed tests
tests/test_engine_loop.pytests/test_operational_logging.pycovers output selection, warning-only unhealthy ticks (including a real SQLite pass), failed stdout serialization, observation cleanup failures on run and shadow, bounded DEBUG frame locations, safe CLI errors, correlation reset, heartbeat propagation, secret suppression and startup preflight.Dependencies / stack
e01d420262641615427ecb537a14380c90442219(logging, checkout and preflight APIs; includes Core #321).Context.preflightinside the startup scope, beforeengine.startup outcome=ready, and preserved the merged runner and routing behavior.