AZ-266: schema-compliant JSON logging entrypoint, level normalisation, handler-topology guard, format-error fallback (log_record_schema v1.0.0). AZ-269: env > YAML > defaults config loader, frozen Config dataclass, missing-var fail-fast with pointer to .env.example, component-block registry. AZ-277: GTSAM-backed SE3Utils (matrix<->SE3 + exp/log/adjoint) with strict orthogonality, dtype, and bottom-row contract enforcement. AZ-280: atomicwrites-backed write_atomic + independent verify + order-deterministic aggregate_hash; sidecar format strictness. pyproject.toml pins gtsam>=4.2,<5.0 and atomicwrites>=1.4,<2.0 (named-backend deps per the AZ-277 / AZ-280 contracts). 139 unit tests pass (44 new). Review verdict: PASS_WITH_WARNINGS; findings are perf-NFR + journald deferrals, no blocking issues. Co-authored-by: Cursor <cursoragent@cursor.com>
6.9 KiB
Shared Structured Logging Module
Task: AZ-266_log_module
Name: Shared Logging Module
Description: Provide the get_logger(component_id) entrypoint, a stable JSON formatter that emits records matching the log_record_schema contract, and the stdout / journald handlers used by Tier-1 and Tier-2 deployments.
Complexity: 3 points
Dependencies: AZ-263_initial_structure
Component: shared.logging (cross-cutting; epic AZ-245 / E-CC-LOG)
Tracker: AZ-266
Epic: AZ-245 (E-CC-LOG)
Problem
Every onboard component must emit structured JSON logs at DEBUG / INFO / WARN / ERROR with a stable, machine-parseable shape so post-flight analysis (FDR tooling, blackbox scenario checks, traceability matrix verification) can correlate events across components. Without one shared logger, format drift is guaranteed within a few weeks of parallel component development.
Outcome
- A single
get_logger(component_id)call is the only logging entrypoint any onboard module ever uses. - Every emitted record is a single-line JSON object whose key set, key order, and value types match the
log_record_schemacontract version 1.0.0. - Tier-1 deployments capture logs via Docker stdout; Tier-2 deployments capture logs via journald — switched by config, not by code.
Scope
Included
get_logger(component_id: str) -> Loggerfactory backed by Python stdliblogging.- A JSON formatter that emits the schema's 8 fields in the contract-mandated order, regardless of construction order. Implementation may use
python-json-loggerororjson-backed formatter — whichever is already pinned in the project's lockfile from AZ-263. - A stdout handler for Tier-1 (Docker) and a journald handler for Tier-2 (Jetson). Selection is config-driven via the structured-logging entry of the cross-cutting config epic (AZ-246 / E-CC-CONF).
- Per-frame structured-logging helpers for the documented per-component shapes referenced in epic AZ-245 (
vio.tick,vpr.query, etc.) so component code can emit one-liner logs without rebuilding the kv dict. - Public interface contract published at
_docs/02_document/contracts/shared_logging/log_record_schema.md.
Excluded
- The FDR bridge that forwards ERROR + WARN records into the Flight Data Recorder — owned by the next task (
03_fdr_log_bridge, parented to the same epic). - Per-component log call sites (each component epic owns its own logging call sites).
- Log schema versioning beyond 1.0.0 — handled by future change-log entries on the contract file.
Acceptance Criteria
AC-1: Single logger entrypoint
Given any onboard Python module that imports the shared logging package
When the module calls get_logger("c2_vpr")
Then it receives a Logger whose every record passes the schema contract test (no other logger configuration is required by the caller)
AC-2: Field order is stable
Given a logger configured with the JSON formatter
When a component calls logger.info(msg, extra={"frame_id": 42, "kind": "vpr.query", "kv": {...}})
Then the emitted bytes parse as a single-line JSON object whose keys appear in the order ts, level, component, frame_id, kind, msg, kv, exc, regardless of the order the caller passed the fields
AC-3: Level normalisation
Given a logger receiving a record at level WARNING (Python stdlib name)
When the formatter emits the JSON record
Then the level field reads WARN (per contract), not WARNING
AC-4: Handler topology selection
Given the structured-logging config block selects tier=1 (or tier=2)
When runtime_root.py initialises logging
Then exactly one stdout handler (or journald handler) is attached, with no duplicate handlers and no handler from the wrong tier
AC-5: Non-frame records omit frame_id
Given a startup or shutdown log call that does not pass a frame_id
When the record is emitted
Then frame_id appears as JSON null (never as a synthesised value, never absent from the key list)
Non-Functional Requirements
Performance
- Per-record formatter latency p99 ≤ 0.2 ms on Tier-2 (Jetson Orin Nano Super) for a record with
len(kv) ≤ 8scalar entries. Validated by a microbenchmark in unit tests. - DEBUG records on the steady-state hot path allocate at most one new string (the formatted JSON line); no transient dict copies of
kvare permitted.
Reliability
- Formatter never raises into the caller. A serialisation failure logs an internal
WARNwithkind="log.format_error"and drops the offending record'skvpayload (replaces with{"_format_error": "<reason>"}); the rest of the record is still emitted. - No global mutable state outside the standard
loggingmodule's own logger registry; multipleget_logger("c2_vpr")calls return the same cachedLoggerinstance.
Unit Tests
| AC Ref | What to Test | Required Outcome |
|---|---|---|
| AC-1 | get_logger("c2_vpr") returns a Logger with the JSON formatter attached |
Logger instance present; formatter produces valid contract record |
| AC-2 | Emit a record with kwargs in shuffled order | Parsed JSON keys appear in the contract's mandated order |
| AC-3 | Log at logging.WARNING level |
Emitted JSON level field equals "WARN" |
| AC-4 | Initialise logging twice with the same tier-1 config | Exactly one stdout handler attached; no duplicates |
| AC-5 | Log a startup INFO without frame_id |
Emitted JSON contains "frame_id": null |
| NFR-perf | Microbenchmark formatter on a record with 8 scalar kv entries | p99 ≤ 0.2 ms over 10k iterations |
| NFR-reliability | Pass a non-JSON-serialisable object in kv (e.g. a class instance) |
Formatter emits the record with kv={"_format_error": "..."}; caller does not see an exception |
Constraints
- Public interface frozen by
_docs/02_document/contracts/shared_logging/log_record_schema.mdv1.0.0 — any change requires a contract version bump. - Stdlib
loggingis the only allowed underlying logging mechanism (per epic AZ-245 architecture note: "no third-party log aggregator"). - No new dependency beyond what AZ-263 / E-BOOT already pinned in
pyproject.toml.
Risks & Mitigation
Risk 1: Formatter performance regression
- Risk: Naïve
json.dumpson each record exceeds the 0.2 ms p99 budget on Jetson. - Mitigation: Bench against
orjson-backed formatter as a fallback if stdlibjsonmisses budget; choice is reversible because the contract is the public surface, not the formatter implementation.
Risk 2: Handler duplication on hot-reload
- Risk: Re-initialising logging during integration tests stacks duplicate handlers, multiplying every emitted record.
- Mitigation:
get_loggerchecks for existing handlers on the named logger before adding new ones; integration test fixture asserts handler count after teardown.
Contract
This task produces the contract at _docs/02_document/contracts/shared_logging/log_record_schema.md.
Consumers MUST read that file — not this task spec — to discover the interface.