feat(logging): JSON formatter + structured dispatch fields (COW-1035) - #37
Closed
brunota20 wants to merge 1 commit into
Closed
Conversation
Closes the COW-1035 structured-logging audit. The engine now ships
JSON-formatted logs by default, with consistent field shapes across
every dispatch, host call, and order submission. A single `jq` /
Loki / Grafana stream over the engine output reconstructs the full
timeline of any module event.
## Changes
### Formatter
- New `--pretty-logs` CLI flag (parsed in `cli.rs`). When set, the
engine uses the historical 0.1 human-readable formatter; otherwise
emits JSON with flattened event fields + no current-span noise.
- `main.rs` `tracing_subscriber::fmt` builder picks the formatter from
the flag. `EnvFilter` (`RUST_LOG` / `engine.toml::[engine].log_level`)
applies to both.
- `tracing-subscriber` feature set gains `json`.
### Dispatch logs (supervisor.rs)
Every `dispatch_block` and `dispatch_log` invocation now emits a
structured log line:
- `dispatch ok` (DEBUG) on success with `module`, `chain_id`,
`event_kind` ("block" / "log"), `block_number`, `latency_ms`.
- Existing host-error WARN + trap ERROR paths gain the same fields
for cross-correlation.
Live Sepolia validation:
```json
{"timestamp":"2026-06-18T13:56:48.587125Z","level":"DEBUG","message":"dispatch ok",
"module":"price-alert","chain_id":11155111,"event_kind":"block",
"block_number":11087508,"latency_ms":134,"target":"nexum_engine::supervisor"}
{"timestamp":"2026-06-18T13:56:48.857911Z","level":"DEBUG","message":"dispatch ok",
"module":"balance-tracker","chain_id":11155111,"event_kind":"block",
"block_number":11087508,"latency_ms":270,"target":"nexum_engine::supervisor"}
{"timestamp":"2026-06-18T13:56:50.193531Z","level":"DEBUG","message":"dispatch ok",
"module":"stop-loss","chain_id":11155111,"event_kind":"block",
"block_number":11087508,"latency_ms":1335,"target":"nexum_engine::supervisor"}
```
The latency-per-module distribution is now observable per-block:
price-alert ~135 ms (1 eth_call), balance-tracker ~270 ms (2
eth_getBalance), stop-loss ~1.3 s (oracle read + OrderCreation +
cow-api submit + retry classify).
### Host-call logs (pre-existing, kept as-is)
The M1 host backends already emit structured DEBUG with `chain_id`,
`method`, `bytes`, `latency_ms` on every `chain::request` /
`cow-api::submit-order` / `cow-api::request`. The audit confirmed
they already satisfy the COW-1035 contract; no changes needed.
### Runbook ergonomics
`just run-m2` and `just run-m3` pass `--pretty-logs` so the
runbook output samples (M2 + M3 runbooks) keep matching what the
operator sees locally. Production deploys (`cargo run -p
nexum-engine -- --engine-config engine.toml` directly, e.g. from
a Docker entrypoint) get JSON by default.
## Validation
- `cargo test --workspace` -> 154 host tests + 6 doctests passing.
- `cargo clippy --all-targets --workspace -- -D warnings` clean.
- `cargo fmt --all --check` clean.
- Live Sepolia smoke: JSON output captured; per-module dispatch
latencies plausible against expected work per module.
- Pretty-logs flag verified to opt back into the 0.1 formatter.
## What this still doesn't do
- Per-order timeline aggregation (would need a `uid` field on the
stop-loss / twap-monitor submit logs). Currently the order UID
is logged by each module's `host.log` call (module-side) but
not joined with the supervisor dispatch line. Acceptable today;
the JSON shape supports adding the field later without breaking
consumers.
- Trace IDs / spans across the dispatch -> host-call boundary.
Worth a follow-up once Prometheus (COW-1034) lands and we know
the metric labels we want to correlate against.
Linear: COW-1035. Third M4 issue landed; stacks on #36 (COW-1036).
5 tasks
Author
|
Work landed via |
brunota20
added a commit
that referenced
this pull request
Jun 25, 2026
…1034)
Wires `metrics` + `metrics-exporter-prometheus` into the engine.
When `engine.toml::[engine.metrics].enabled = true` the engine binds
a Prometheus HTTP exporter on the configured `bind_addr` (default
`127.0.0.1:9100`) and serves `/metrics`. When disabled, the recorder
is still installed so call sites stay live but no port binds. The
same binary now ships into CI / tests (recorder no-ops) and into
production (full exporter) by flipping one config flag.
## Recording sites instrumented
| Metric | Type | Labels | Site |
|---|---|---|---|
| `shepherd_event_latency_seconds` | summary | module, event_kind | supervisor::dispatch_{block,log} on the OK path |
| `shepherd_module_errors_total` | counter | module, error_kind | supervisor::dispatch_{block,log} on host-error WARN + trap ERROR paths (error_kind = `{:?}` of HostErrorKind, or `"trap"`) |
| `shepherd_chain_request_total` | counter | chain_id, method, outcome | host::impls::chain after every `chain::request` |
| `shepherd_cow_api_submit_total` | counter | chain_id, outcome | host::impls::cow_api after every `cow-api::submit-order` |
Sites match the structured logging audit (COW-1035) so each metric
event has a sibling log line with the same labels for cross-
correlation.
## Live Sepolia scrape
```
# TYPE shepherd_cow_api_submit_total counter
shepherd_cow_api_submit_total{chain_id="11155111",outcome="err"} 2
# TYPE shepherd_chain_request_total counter
shepherd_chain_request_total{chain_id="11155111",method="eth_getBalance",outcome="ok"} 4
shepherd_chain_request_total{chain_id="11155111",method="eth_call",outcome="ok"} 4
# TYPE shepherd_event_latency_seconds summary
shepherd_event_latency_seconds{module="price-alert", event_kind="block",quantile="0.5"} 0.1394
shepherd_event_latency_seconds{module="stop-loss", event_kind="block",quantile="0.5"} 0.9091
shepherd_event_latency_seconds{module="balance-tracker",event_kind="block",quantile="0.5"} 0.2823
```
Quantiles (p50/p90/p95/p99) appear automatically via the default
reservoir sampling. Production SRE can write SLO alerts against
these without any further wiring.
## Config schema
```toml
[engine.metrics]
enabled = false # default
bind_addr = "127.0.0.1:9100"
```
Disabled by default so M3 runbook smoke runs do not bind a port
unintentionally. Operators flip `enabled = true` for production.
## Deferred from issue scope
| Metric | Why deferred |
|---|---|
| `shepherd_module_uptime_seconds` | Needs a per-module start-time tracker on LoadedModule. Easy to add but cluttered the supervisor.rs diff. Worth a follow-up. |
| `shepherd_fuel_consumed` | Requires reading `store.get_fuel()` after each dispatch to compute consumed = DEFAULT - remaining. Mechanical addition, not in this PR to keep scope tight. |
| `shepherd_memory_peak_bytes` | Requires inspecting the wasmtime component's exported Memory instance. Harder; defer until the memory-bomb fixture surfaces a useful baseline. |
| `shepherd_module_restarts_total` | Depends on COW-1033 (supervisor auto-restart) which is not built yet. Wired into restart sites when that lands. |
| `shepherd_module_poisoned` | Depends on COW-1032 (poison pill) for the same reason. |
The 4 metrics shipped here cover the load-bearing observability use
cases (dispatch latency SLO + error rate by kind + per-RPC method
volume + per-orderbook submit outcome). The 5 deferred ones lock in
on top of M4 work that isn't built yet.
## Validation
- `cargo test --workspace` -> 154 host tests + 6 doctests passing.
- `cargo clippy --all-targets --workspace -- -D warnings` clean.
- `cargo fmt --all --check` clean.
- Live Sepolia smoke: enabled the exporter on port 9101, scraped
/metrics via `curl`, confirmed all 4 metrics flowing with correct
labels.
- Recorder no-op path verified: `[engine.metrics].enabled = false`
(the default) does not bind a port; call sites stay silent but
do not panic.
Linear: COW-1034. Fourth M4 issue landed; stacks on #37 (COW-1035).
brunota20
added a commit
that referenced
this pull request
Jun 25, 2026
…1034)
Wires `metrics` + `metrics-exporter-prometheus` into the engine.
When `engine.toml::[engine.metrics].enabled = true` the engine binds
a Prometheus HTTP exporter on the configured `bind_addr` (default
`127.0.0.1:9100`) and serves `/metrics`. When disabled, the recorder
is still installed so call sites stay live but no port binds. The
same binary now ships into CI / tests (recorder no-ops) and into
production (full exporter) by flipping one config flag.
## Recording sites instrumented
| Metric | Type | Labels | Site |
|---|---|---|---|
| `shepherd_event_latency_seconds` | summary | module, event_kind | supervisor::dispatch_{block,log} on the OK path |
| `shepherd_module_errors_total` | counter | module, error_kind | supervisor::dispatch_{block,log} on host-error WARN + trap ERROR paths (error_kind = `{:?}` of HostErrorKind, or `"trap"`) |
| `shepherd_chain_request_total` | counter | chain_id, method, outcome | host::impls::chain after every `chain::request` |
| `shepherd_cow_api_submit_total` | counter | chain_id, outcome | host::impls::cow_api after every `cow-api::submit-order` |
Sites match the structured logging audit (COW-1035) so each metric
event has a sibling log line with the same labels for cross-
correlation.
## Live Sepolia scrape
```
# TYPE shepherd_cow_api_submit_total counter
shepherd_cow_api_submit_total{chain_id="11155111",outcome="err"} 2
# TYPE shepherd_chain_request_total counter
shepherd_chain_request_total{chain_id="11155111",method="eth_getBalance",outcome="ok"} 4
shepherd_chain_request_total{chain_id="11155111",method="eth_call",outcome="ok"} 4
# TYPE shepherd_event_latency_seconds summary
shepherd_event_latency_seconds{module="price-alert", event_kind="block",quantile="0.5"} 0.1394
shepherd_event_latency_seconds{module="stop-loss", event_kind="block",quantile="0.5"} 0.9091
shepherd_event_latency_seconds{module="balance-tracker",event_kind="block",quantile="0.5"} 0.2823
```
Quantiles (p50/p90/p95/p99) appear automatically via the default
reservoir sampling. Production SRE can write SLO alerts against
these without any further wiring.
## Config schema
```toml
[engine.metrics]
enabled = false # default
bind_addr = "127.0.0.1:9100"
```
Disabled by default so M3 runbook smoke runs do not bind a port
unintentionally. Operators flip `enabled = true` for production.
## Deferred from issue scope
| Metric | Why deferred |
|---|---|
| `shepherd_module_uptime_seconds` | Needs a per-module start-time tracker on LoadedModule. Easy to add but cluttered the supervisor.rs diff. Worth a follow-up. |
| `shepherd_fuel_consumed` | Requires reading `store.get_fuel()` after each dispatch to compute consumed = DEFAULT - remaining. Mechanical addition, not in this PR to keep scope tight. |
| `shepherd_memory_peak_bytes` | Requires inspecting the wasmtime component's exported Memory instance. Harder; defer until the memory-bomb fixture surfaces a useful baseline. |
| `shepherd_module_restarts_total` | Depends on COW-1033 (supervisor auto-restart) which is not built yet. Wired into restart sites when that lands. |
| `shepherd_module_poisoned` | Depends on COW-1032 (poison pill) for the same reason. |
The 4 metrics shipped here cover the load-bearing observability use
cases (dispatch latency SLO + error rate by kind + per-RPC method
volume + per-orderbook submit outcome). The 5 deferred ones lock in
on top of M4 work that isn't built yet.
## Validation
- `cargo test --workspace` -> 154 host tests + 6 doctests passing.
- `cargo clippy --all-targets --workspace -- -D warnings` clean.
- `cargo fmt --all --check` clean.
- Live Sepolia smoke: enabled the exporter on port 9101, scraped
/metrics via `curl`, confirmed all 4 metrics flowing with correct
labels.
- Recorder no-op path verified: `[engine.metrics].enabled = false`
(the default) does not bind a port; call sites stay silent but
do not panic.
Linear: COW-1034. Fourth M4 issue landed; stacks on #37 (COW-1035).
brunota20
added a commit
that referenced
this pull request
Jun 25, 2026
…1034)
Wires `metrics` + `metrics-exporter-prometheus` into the engine.
When `engine.toml::[engine.metrics].enabled = true` the engine binds
a Prometheus HTTP exporter on the configured `bind_addr` (default
`127.0.0.1:9100`) and serves `/metrics`. When disabled, the recorder
is still installed so call sites stay live but no port binds. The
same binary now ships into CI / tests (recorder no-ops) and into
production (full exporter) by flipping one config flag.
## Recording sites instrumented
| Metric | Type | Labels | Site |
|---|---|---|---|
| `shepherd_event_latency_seconds` | summary | module, event_kind | supervisor::dispatch_{block,log} on the OK path |
| `shepherd_module_errors_total` | counter | module, error_kind | supervisor::dispatch_{block,log} on host-error WARN + trap ERROR paths (error_kind = `{:?}` of HostErrorKind, or `"trap"`) |
| `shepherd_chain_request_total` | counter | chain_id, method, outcome | host::impls::chain after every `chain::request` |
| `shepherd_cow_api_submit_total` | counter | chain_id, outcome | host::impls::cow_api after every `cow-api::submit-order` |
Sites match the structured logging audit (COW-1035) so each metric
event has a sibling log line with the same labels for cross-
correlation.
## Live Sepolia scrape
```
# TYPE shepherd_cow_api_submit_total counter
shepherd_cow_api_submit_total{chain_id="11155111",outcome="err"} 2
# TYPE shepherd_chain_request_total counter
shepherd_chain_request_total{chain_id="11155111",method="eth_getBalance",outcome="ok"} 4
shepherd_chain_request_total{chain_id="11155111",method="eth_call",outcome="ok"} 4
# TYPE shepherd_event_latency_seconds summary
shepherd_event_latency_seconds{module="price-alert", event_kind="block",quantile="0.5"} 0.1394
shepherd_event_latency_seconds{module="stop-loss", event_kind="block",quantile="0.5"} 0.9091
shepherd_event_latency_seconds{module="balance-tracker",event_kind="block",quantile="0.5"} 0.2823
```
Quantiles (p50/p90/p95/p99) appear automatically via the default
reservoir sampling. Production SRE can write SLO alerts against
these without any further wiring.
## Config schema
```toml
[engine.metrics]
enabled = false # default
bind_addr = "127.0.0.1:9100"
```
Disabled by default so M3 runbook smoke runs do not bind a port
unintentionally. Operators flip `enabled = true` for production.
## Deferred from issue scope
| Metric | Why deferred |
|---|---|
| `shepherd_module_uptime_seconds` | Needs a per-module start-time tracker on LoadedModule. Easy to add but cluttered the supervisor.rs diff. Worth a follow-up. |
| `shepherd_fuel_consumed` | Requires reading `store.get_fuel()` after each dispatch to compute consumed = DEFAULT - remaining. Mechanical addition, not in this PR to keep scope tight. |
| `shepherd_memory_peak_bytes` | Requires inspecting the wasmtime component's exported Memory instance. Harder; defer until the memory-bomb fixture surfaces a useful baseline. |
| `shepherd_module_restarts_total` | Depends on COW-1033 (supervisor auto-restart) which is not built yet. Wired into restart sites when that lands. |
| `shepherd_module_poisoned` | Depends on COW-1032 (poison pill) for the same reason. |
The 4 metrics shipped here cover the load-bearing observability use
cases (dispatch latency SLO + error rate by kind + per-RPC method
volume + per-orderbook submit outcome). The 5 deferred ones lock in
on top of M4 work that isn't built yet.
## Validation
- `cargo test --workspace` -> 154 host tests + 6 doctests passing.
- `cargo clippy --all-targets --workspace -- -D warnings` clean.
- `cargo fmt --all --check` clean.
- Live Sepolia smoke: enabled the exporter on port 9101, scraped
/metrics via `curl`, confirmed all 4 metrics flowing with correct
labels.
- Recorder no-op path verified: `[engine.metrics].enabled = false`
(the default) does not bind a port; call sites stay silent but
do not panic.
Linear: COW-1034. Fourth M4 issue landed; stacks on #37 (COW-1035).
brunota20
added a commit
that referenced
this pull request
Jun 25, 2026
…1034)
Wires `metrics` + `metrics-exporter-prometheus` into the engine.
When `engine.toml::[engine.metrics].enabled = true` the engine binds
a Prometheus HTTP exporter on the configured `bind_addr` (default
`127.0.0.1:9100`) and serves `/metrics`. When disabled, the recorder
is still installed so call sites stay live but no port binds. The
same binary now ships into CI / tests (recorder no-ops) and into
production (full exporter) by flipping one config flag.
## Recording sites instrumented
| Metric | Type | Labels | Site |
|---|---|---|---|
| `shepherd_event_latency_seconds` | summary | module, event_kind | supervisor::dispatch_{block,log} on the OK path |
| `shepherd_module_errors_total` | counter | module, error_kind | supervisor::dispatch_{block,log} on host-error WARN + trap ERROR paths (error_kind = `{:?}` of HostErrorKind, or `"trap"`) |
| `shepherd_chain_request_total` | counter | chain_id, method, outcome | host::impls::chain after every `chain::request` |
| `shepherd_cow_api_submit_total` | counter | chain_id, outcome | host::impls::cow_api after every `cow-api::submit-order` |
Sites match the structured logging audit (COW-1035) so each metric
event has a sibling log line with the same labels for cross-
correlation.
## Live Sepolia scrape
```
# TYPE shepherd_cow_api_submit_total counter
shepherd_cow_api_submit_total{chain_id="11155111",outcome="err"} 2
# TYPE shepherd_chain_request_total counter
shepherd_chain_request_total{chain_id="11155111",method="eth_getBalance",outcome="ok"} 4
shepherd_chain_request_total{chain_id="11155111",method="eth_call",outcome="ok"} 4
# TYPE shepherd_event_latency_seconds summary
shepherd_event_latency_seconds{module="price-alert", event_kind="block",quantile="0.5"} 0.1394
shepherd_event_latency_seconds{module="stop-loss", event_kind="block",quantile="0.5"} 0.9091
shepherd_event_latency_seconds{module="balance-tracker",event_kind="block",quantile="0.5"} 0.2823
```
Quantiles (p50/p90/p95/p99) appear automatically via the default
reservoir sampling. Production SRE can write SLO alerts against
these without any further wiring.
## Config schema
```toml
[engine.metrics]
enabled = false # default
bind_addr = "127.0.0.1:9100"
```
Disabled by default so M3 runbook smoke runs do not bind a port
unintentionally. Operators flip `enabled = true` for production.
## Deferred from issue scope
| Metric | Why deferred |
|---|---|
| `shepherd_module_uptime_seconds` | Needs a per-module start-time tracker on LoadedModule. Easy to add but cluttered the supervisor.rs diff. Worth a follow-up. |
| `shepherd_fuel_consumed` | Requires reading `store.get_fuel()` after each dispatch to compute consumed = DEFAULT - remaining. Mechanical addition, not in this PR to keep scope tight. |
| `shepherd_memory_peak_bytes` | Requires inspecting the wasmtime component's exported Memory instance. Harder; defer until the memory-bomb fixture surfaces a useful baseline. |
| `shepherd_module_restarts_total` | Depends on COW-1033 (supervisor auto-restart) which is not built yet. Wired into restart sites when that lands. |
| `shepherd_module_poisoned` | Depends on COW-1032 (poison pill) for the same reason. |
The 4 metrics shipped here cover the load-bearing observability use
cases (dispatch latency SLO + error rate by kind + per-RPC method
volume + per-orderbook submit outcome). The 5 deferred ones lock in
on top of M4 work that isn't built yet.
## Validation
- `cargo test --workspace` -> 154 host tests + 6 doctests passing.
- `cargo clippy --all-targets --workspace -- -D warnings` clean.
- `cargo fmt --all --check` clean.
- Live Sepolia smoke: enabled the exporter on port 9101, scraped
/metrics via `curl`, confirmed all 4 metrics flowing with correct
labels.
- Recorder no-op path verified: `[engine.metrics].enabled = false`
(the default) does not bind a port; call sites stay silent but
do not panic.
Linear: COW-1034. Fourth M4 issue landed; stacks on #37 (COW-1035).
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What does this PR do?
Closes the COW-1035 structured-logging audit. The engine now ships JSON-formatted logs by default with consistent field shapes across every dispatch, host call, and order submission. A single `jq` / Loki / Grafana stream reconstructs the full timeline of any module event.
Third M4 issue landed.
Changes
Live Sepolia validation
{"timestamp":"2026-06-18T13:56:48.587125Z","level":"DEBUG","message":"dispatch ok", "module":"price-alert","chain_id":11155111,"event_kind":"block", "block_number":11087508,"latency_ms":134,"target":"nexum_engine::supervisor"} {"timestamp":"2026-06-18T13:56:48.857911Z","level":"DEBUG","message":"dispatch ok", "module":"balance-tracker","chain_id":11155111,"event_kind":"block", "block_number":11087508,"latency_ms":270,"target":"nexum_engine::supervisor"} {"timestamp":"2026-06-18T13:56:50.193531Z","level":"DEBUG","message":"dispatch ok", "module":"stop-loss","chain_id":11155111,"event_kind":"block", "block_number":11087508,"latency_ms":1335,"target":"nexum_engine::supervisor"}Per-module dispatch latency now observable: price-alert ~135ms (1 eth_call), balance-tracker ~270ms (2 eth_getBalance), stop-loss ~1.3s (oracle read + OrderCreation + cow-api submit + retry classify).
Breaking changes
Default log format changed from human-readable to JSON. Existing operators who parse log output by-line will need to pass `--pretty-logs` to restore the old format, OR pipe through `jq` to extract the same information. The runbooks already opt into `--pretty-logs`; only direct `cargo run -p nexum-engine` invocations need to add the flag.
Out of scope (deferred)
Testing
AI assistance disclosure
AI Assistance: this change + description was produced by a Claude Code agent (Claude Opus 4.7 1M context). The agent audited the existing logging call sites, ran the JSON output live against Sepolia for verification, and wrote the runbook ergonomics tweaks. A human (Bruno) reviewed and is accountable for the result.
Linear: COW-1035. Stacks on #36 (COW-1036 resource-limit tests).