feat(observability): structured logging, tracing, and debug tooling - #62
feat(observability): structured logging, tracing, and debug tooling#62dylanneve1 wants to merge 17 commits into
Conversation
There was a problem hiding this comment.
Pull request overview
Adds an observability layer to Talon: structured logging (with runtime controls), span-style tracing with async parent/child linkage, and a debug surface exposed via HTTP endpoints and CLI commands.
Changes:
- Implemented OpenTelemetry-inspired spans with
AsyncLocalStorage, persistence to JSONL, and automatic span metrics emission. - Expanded pino-based logging with runtime log levels, namespace filtering, child loggers, an in-memory recent-log buffer, and a dedicated warn+
errors.log. - Added
/debug/*HTTP endpoints andtalon debug/talon errorsCLI tooling; instrumented core subsystems with spans + metrics.
Reviewed changes
Copilot reviewed 17 out of 17 changed files in this pull request and generated 9 comments.
Show a summary per file
| File | Description |
|---|---|
| src/util/trace.ts | Adds span tracing (ALS context, ring buffer, JSONL persistence, span metrics). |
| src/util/paths.ts | Introduces ~/.talon/errors.log path. |
| src/util/log.ts | Adds runtime level control, namespace filter, child loggers, error-only log, in-memory recent logs. |
| src/util/debug.ts | Builds aggregated runtime debug snapshots for /debug/state and CLI. |
| src/core/gateway.ts | Wraps actions in spans + metrics; exposes /debug/* endpoints incl. runtime log-level changes. |
| src/core/dispatcher.ts | Adds request correlation via child logger + spans and dispatcher metrics. |
| src/core/plugin.ts | Adds plugin load summary + action latency/error metrics. |
| src/core/cron.ts | Adds cron job spans + latency/error metrics. |
| src/core/dream.ts | Adds dream spans + status counters. |
| src/core/heartbeat.ts | Adds heartbeat spans + status counters. |
| src/backend/claude-sdk/handler.ts | Annotates active span with backend/model/session/tooling metadata. |
| src/cli.ts | Adds talon errors and talon debug (state/metrics/spans/log-level) + generalized tailing. |
| src/tests/trace-spans.test.ts | Adds unit tests for span behavior (nesting, error capture, ring buffer). |
| src/tests/log.test.ts | Updates log tests for stack capture behavior. |
| src/tests/log-init.test.ts | Updates log init tests for new log targets/child API. |
| src/tests/log-extras.test.ts | Adds tests for new logging APIs (childLogger, namespaces, level controls, recent logs). |
| src/tests/dispatcher.test.ts | Updates mocks for new dispatcher logging API usage. |
Comments suppressed due to low confidence (1)
src/core/gateway.ts:372
- The debug endpoints (including
POST /debug/log-level) are exposed on 127.0.0.1 without any authentication or CSRF mitigation. A local untrusted process—or a browser page using a “simple” cross-origin request—could potentially toggle log levels or scrape logs/metrics. Consider gating these routes behind an opt-in env flag, requiring a shared secret header, and/or rejecting requests with missing/invalid Origin/Host when running with an HTTP frontend.
await this.handleSetLogLevel(req, res);
return;
}
if (req.method !== "POST" || req.url !== "/action") {
res.writeHead(404);
res.end("Not found");
return;
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 19 out of 19 changed files in this pull request and generated 8 comments.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 19 out of 19 changed files in this pull request and generated 6 comments.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
- log.ts: gate pushRecent behind isLevelEnabled for info/warn/error/fatal (both root and child loggers) so lowering the runtime level actually reduces in-memory buffer growth. - trace.ts: replace Array#shift() with a proper fixed-size circular buffer so span recording stays O(1) under high span volume. - metrics.ts: reject absurdly long (>200 char) raw labels up front and clarify the docstring so behavior matches documentation. - plugin.ts: promote the metrics dynamic import to a static import — cached or not, the await was on every handlePluginAction hot path. - gateway.ts: validate /debug/logs level query param against the allowed set, returning 400 on anything else. - debug.ts: drop the stale "dynamic imports" note from the header comment — the module uses plain static imports. - trace-spans.test.ts: mock util/log.js so importing trace.ts does not trigger real pino/file transport initialization under the user home. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 21 out of 21 changed files in this pull request and generated 2 comments.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 21 out of 21 changed files in this pull request and generated 4 comments.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 21 out of 21 changed files in this pull request and generated 2 comments.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
Addresses the last of the PR #62 review feedback: - log.test.ts / log-extras.test.ts: pin TALON_LOG_LEVEL=trace and clear TALON_DEBUG / TALON_QUIET before the dynamic `import("../util/log.js")`. log.ts reads these at module-init time, so a CI machine that happens to set TALON_LOG_LEVEL=warn would silently flake the log()/logDebug() assertions without them. - gateway-retry.test.ts: the core/gateway module now static-imports setLogLevel/getLogLevel/getRecentLogs from util/log and several extra watchdog helpers. ESM module resolution throws on any unprovided export even if the test doesn't exercise that path, so add them defensively. 1402 tests still passing.
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 22 out of 22 changed files in this pull request and generated 4 comments.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 22 out of 22 changed files in this pull request and generated 1 comment.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
Four Copilot comments from the latest review: 1. log.ts: recentBuffer used Array#shift() — O(n) per log line on the default "trace" path. Switched to a fixed-size circular buffer (same pattern as trace.ts's span ring): O(1) insert, snapshot rebuilt oldest-to-newest for getRecentLogs(). 2. gateway.ts handleSetLogLevel: unbounded request-body read before JSON.parse could be used for memory-pressure DoS from a local client. Added a 4KB cap, early-reject on oversized Content-Length, and 413 response if the stream exceeds the cap mid-body. Also split out the setLogLevel throw into its own catch so invalid levels return 400 *without* changing the current level — tested explicitly. 3. gateway-http.test.ts: added coverage for POST /debug/log-level with an invalid level (asserts 400 + state unchanged) and an oversized body (asserts 413). Had to teach the mocked setLogLevel to actually throw on unknown levels so the gateway's 400 path is exercised. 4. cli.ts debug metrics: the Histograms header hardcoded "ms" but the registry now also records non-time histograms (e.g. tokens.input / tokens.output). Made the header unit-agnostic and append "ms" per-row only when the key ends in ".ms". 1404 tests passing, typecheck + lint clean.
Round-3 Copilot feedback on PR #62 flagged the Content-Length parsing: Node typed headers can be string | string[] and the previous read assumed a bare string. Also, when the stream-time 413 fires, keeping the already-buffered chunks pinned in memory defeats part of the cap. - Normalize Content-Length: handle the string[] case defensively and only treat it as advisory (header may be missing, fabricated, or absent on chunked transfers). - On oversize during streaming: clear the chunk buffer and req.destroy() so the connection stops feeding us bytes. - Factored the 413 response into a tooLarge() helper for readability. No behavior change for normal bodies (~20 bytes of JSON). 1404 tests still passing.
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 25 out of 25 changed files in this pull request and generated 5 comments.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
|
Addressed in 8879dbe. Four concerns in this round: 1. Poisoned-payload resilience (log.ts:499, trace.ts:217) — added 2. Falsy err dropped (log.ts:388) — switched from 3. Docstring stale (log.ts:13) — added 4. Content-Length 413 didn't drain (gateway.ts:363) — added 18 new json-safe tests, plus new coverage in log-extras (falsy err, cyclic/BigInt extra) and trace-spans (cyclic/BigInt/fn attrs + cyclic event attrs, all JSON-safe). Full suite: 1427 passing, typecheck clean. |
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 27 out of 27 changed files in this pull request and generated 1 comment.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
|
|
||
| // Error — expose message/name/stack explicitly, stack length-capped. | ||
| if (value instanceof Error) { | ||
| const stack = | ||
| typeof value.stack === "string" | ||
| ? value.stack.length > o.maxString | ||
| ? value.stack.slice(0, o.maxString) + "…" | ||
| : value.stack | ||
| : undefined; | ||
| return { name: value.name, message: value.message, stack }; | ||
| } | ||
|
|
||
| // Date — ISO string is round-trippable and compact. | ||
| if (value instanceof Date) { | ||
| return Number.isNaN(value.getTime()) | ||
| ? "[Invalid Date]" | ||
| : value.toISOString(); | ||
| } | ||
|
|
There was a problem hiding this comment.
The cycle detection uses a WeakSet that is shared across the whole traversal and never removes objects on unwind. That will mark repeated references (e.g. {a: shared, b: shared}) as "[circular]" on the second occurrence even when there is no cycle, which can make snapshots misleading vs the doc comment’s “circular references” claim. Consider tracking only the current recursion stack (add before descending, delete after) or using a WeakMap memoization approach to distinguish true cycles from shared subtrees.
| // Error — expose message/name/stack explicitly, stack length-capped. | |
| if (value instanceof Error) { | |
| const stack = | |
| typeof value.stack === "string" | |
| ? value.stack.length > o.maxString | |
| ? value.stack.slice(0, o.maxString) + "…" | |
| : value.stack | |
| : undefined; | |
| return { name: value.name, message: value.message, stack }; | |
| } | |
| // Date — ISO string is round-trippable and compact. | |
| if (value instanceof Date) { | |
| return Number.isNaN(value.getTime()) | |
| ? "[Invalid Date]" | |
| : value.toISOString(); | |
| } | |
| try { | |
| // Error — expose message/name/stack explicitly, stack length-capped. | |
| if (value instanceof Error) { | |
| const stack = | |
| typeof value.stack === "string" | |
| ? value.stack.length > o.maxString | |
| ? value.stack.slice(0, o.maxString) + "…" | |
| : value.stack | |
| : undefined; | |
| return { name: value.name, message: value.message, stack }; | |
| } | |
| // Date — ISO string is round-trippable and compact. | |
| if (value instanceof Date) { | |
| return Number.isNaN(value.getTime()) | |
| ? "[Invalid Date]" | |
| : value.toISOString(); | |
| } |
- util/log: log levels, child loggers, request IDs, namespace filter,
in-memory ring buffer, and a dedicated errors.log (warn+) for
long-term error retention
- util/trace: OpenTelemetry-inspired spans with AsyncLocalStorage parent
linking, daily spans-YYYY-MM-DD.jsonl persistence, and automatic
histogram/counter emission on span end
- util/debug: unified snapshot aggregator for process, bots, queues,
sessions, logs, errors, metrics, and spans
- core: instrument dispatcher, gateway, plugin, cron, dream, and
heartbeat with spans, child loggers, and metrics
- backend/claude-sdk: annotate active span with query metadata
- gateway: /debug/{state,metrics,spans,logs,errors,log-level} endpoints
and runtime POST /debug/log-level
- cli: talon errors, talon debug {state,metrics,spans,errors,log-level}
Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
CodeQL flagged js/stack-trace-exposure on the /debug/* and POST /debug/log-level handlers — raw err.message was returned to the HTTP response. Log the error server-side and return a generic message. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
- log: transport targets are open (level:trace) and logger.level is the
sole runtime gate — setLogLevel() now actually raises verbosity
at runtime instead of being capped at the startup level. errors.log
stays warn+.
- log: TALON_DEBUG namespace filter no longer suppresses info/warn+
(only debug/trace). Comment now matches behavior.
- log: childLogger lines now land in the in-memory ring buffer with
their bound component (previously showed up as "?" at best, and in
practice weren't captured at all because the root-logger wrap didn't
see child-logger calls). Root helpers (log/logError/...) push
explicitly too, and the pino method wrap is removed — one capture
per call instead of two in tests and zero in prod.
- trace: spans-*.jsonl persistence is opt-in via TALON_TRACE_PERSIST=1
so hot paths (dispatcher, gateway) don't pay a blocking
appendFileSync on every span end. In-memory spans remain available
via /debug/spans.
- metrics: sanitizeMetricLabel() buckets untrusted action/plugin names
(lowercase, [a-z0-9_] only, 40-char cap, empty→"unknown") so
malformed input can't exhaust MAX_METRIC_KEYS.
- gateway: apply sanitizer to `action` in metric keys; clamp
/debug/{spans,logs,errors} `limit` query param to a positive finite
integer (NaN/negative no longer returns the full buffer).
- gateway: use logError instead of raw err.message in debug responses
(defense-in-depth after the earlier stack-trace-exposure fix).
- plugin: same sanitizer for plugin/action metric keys.
- cli: `talon debug spans` clamps parsed limit to a positive integer.
tailFile handles empty/whitespace-only files without skipping the
first appended line.
Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
- log.ts: gate pushRecent behind isLevelEnabled for info/warn/error/fatal (both root and child loggers) so lowering the runtime level actually reduces in-memory buffer growth. - trace.ts: replace Array#shift() with a proper fixed-size circular buffer so span recording stays O(1) under high span volume. - metrics.ts: reject absurdly long (>200 char) raw labels up front and clarify the docstring so behavior matches documentation. - plugin.ts: promote the metrics dynamic import to a static import — cached or not, the await was on every handlePluginAction hot path. - gateway.ts: validate /debug/logs level query param against the allowed set, returning 400 on anything else. - debug.ts: drop the stale "dynamic imports" note from the header comment — the module uses plain static imports. - trace-spans.test.ts: mock util/log.js so importing trace.ts does not trigger real pino/file transport initialization under the user home. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
- gateway-http.test.ts: add 9 tests for /debug/state, /debug/metrics, /debug/spans, /debug/logs (valid + invalid level), /debug/log-level (GET + POST + missing-body 400), and unknown /debug/* 404. Extend existing mocks (util/log, util/watchdog) so buildDebugSnapshot and the log-level handlers resolve against real exports. - dispatcher.ts: drop unused logDebug import. - reload-plugins.test.ts: add currentSpan to the trace.js mock so handler.ts's new named import resolves when that module is loaded by the test's dynamic import. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
…ing logs - log.ts: keep pino's logger.level at "trace" and remove level gates from warn/error/fatal wrappers so errors.log always captures warn+ regardless of the user-facing level. Matches the retention claim in the comment. - dispatcher.ts: switch sendTyping failure logs from the root logWarn() to logCtx.warn() so the reqId/chatId bindings are included for correlation. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
…ilent level, tail recovery - log.ts: honor "silent" level by short-circuiting warn/error/fatal wrappers (previously only trace/debug/info gated, so "silent" wasn't silent). - trace.ts: freeze the SpanRecord stored in the ring buffer and make setAttribute/setAttributes/addEvent/setStatus no-ops after end(); cache the first end() result so repeat calls return it instead of fabricating. - gateway.ts: replace per-request dynamic imports in handleDebug() with static top-level imports (getMetrics, getRecentSpans, getRecentLogs, getRecentErrors) — the modules were already loaded elsewhere. - cli.ts: reset tailFile's lastSize when the watched file shrinks so tailing survives log rotation / truncation instead of stalling forever. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>
Addresses the last of the PR #62 review feedback: - log.test.ts / log-extras.test.ts: pin TALON_LOG_LEVEL=trace and clear TALON_DEBUG / TALON_QUIET before the dynamic `import("../util/log.js")`. log.ts reads these at module-init time, so a CI machine that happens to set TALON_LOG_LEVEL=warn would silently flake the log()/logDebug() assertions without them. - gateway-retry.test.ts: the core/gateway module now static-imports setLogLevel/getLogLevel/getRecentLogs from util/log and several extra watchdog helpers. ESM module resolution throws on any unprovided export even if the test doesn't exercise that path, so add them defensively. 1402 tests still passing.
Four Copilot comments from the latest review: 1. log.ts: recentBuffer used Array#shift() — O(n) per log line on the default "trace" path. Switched to a fixed-size circular buffer (same pattern as trace.ts's span ring): O(1) insert, snapshot rebuilt oldest-to-newest for getRecentLogs(). 2. gateway.ts handleSetLogLevel: unbounded request-body read before JSON.parse could be used for memory-pressure DoS from a local client. Added a 4KB cap, early-reject on oversized Content-Length, and 413 response if the stream exceeds the cap mid-body. Also split out the setLogLevel throw into its own catch so invalid levels return 400 *without* changing the current level — tested explicitly. 3. gateway-http.test.ts: added coverage for POST /debug/log-level with an invalid level (asserts 400 + state unchanged) and an oversized body (asserts 413). Had to teach the mocked setLogLevel to actually throw on unknown levels so the gateway's 400 path is exercised. 4. cli.ts debug metrics: the Histograms header hardcoded "ms" but the registry now also records non-time histograms (e.g. tokens.input / tokens.output). Made the header unit-agnostic and append "ms" per-row only when the key ends in ".ms". 1404 tests passing, typecheck + lint clean.
Round-3 Copilot feedback on PR #62 flagged the Content-Length parsing: Node typed headers can be string | string[] and the previous read assumed a bare string. Also, when the stream-time 413 fires, keeping the already-buffered chunks pinned in memory defeats part of the cap. - Normalize Content-Length: handle the string[] case defensively and only treat it as advisory (header may be missing, fabricated, or absent on chunked transfers). - On oversize during streaming: clear the chunk buffer and req.destroy() so the connection stops feeding us bytes. - Factored the 413 response into a tooLarge() helper for readability. No behavior change for normal bodies (~20 bytes of JSON). 1404 tests still passing.
Four Copilot comments:
1. trace.ts recentSpans was typed `SpanRecord[]` but holds undefined
slots (after resetSpans and in the unfilled portion of a fresh ring),
which forced a cast and made the type a lie. Switched to
`(SpanRecord | undefined)[]` and added a type guard in
getRecentSpans so the public return type stays clean.
2. Span auto-metrics (`span.${name}.ms`, `span.${name}.${status}`)
were using the raw span name, but span names come from user code
(plugins, tests, etc.) and can be dynamic. Ran the name through
sanitizeMetricLabel() before it goes into a metric key to prevent
high-cardinality blowouts of MAX_METRIC_KEYS.
3. sanitizeMetricLabel was typed `(raw: string)` but the body already
handled non-string input. Switched to `unknown` so callers don't
need unsafe casts and the signature matches the intent ("untrusted
label").
4. handleSetLogLevel oversized-path used `req.destroy()`, which tears
down the underlying socket and can hand the client an ECONNRESET
instead of the 413 JSON. Switched to `req.resume()` after sending
413, so HTTP completes cleanly while the oversize body is drained
and discarded.
1404 tests passing.
PR #62 round-5 review flagged three test files whose ../util/log.js mocks still only export the legacy log/logError/logWarn/logDebug quartet. Since core/gateway statically imports setLogLevel/getLogLevel/getRecentLogs for the /debug/* routes, ESM resolution throws "module does not provide an export" at import time even when the test doesn't exercise that path. Updated mocks: - gateway-context.test.ts - gateway-withRetry-extended.test.ts - teams-frontend.test.ts Added a currentLevel state-tracking setLogLevel so any future tests that do exercise the debug endpoints can rely on the same behavior the real module provides. 1404 tests still passing.
…drain Round 5 review pass. Four reviewer concerns addressed: 1. **Log/trace debug endpoints couldn't survive poisoned payloads.** Plugins can pass anything — BigInts, circular refs, functions, unbounded Buffers — through `childLogger(...).info(msg, extra)` and `span.setAttribute(...)`. JSON.stringify on the resulting records would then throw, killing /debug/logs, /debug/state, /debug/spans, and the spans-YYYY-MM-DD.jsonl append path. Added src/util/json-safe.ts which normalizes any unknown into a JSON-safe tree: cycles → "[circular]", BigInt → "<n>n", NaN/Infinity → strings, Errors expanded to name/message/stack, Dates → ISO, Map/Set flattened, functions/symbols stringified, arrays and objects length-capped, recursion depth-bounded. Both log.ts (ring-buffer capture of `extra`) and trace.ts (span attrs + event attrs at end()-time) run their untrusted values through it before storage. 2. **Child-logger dropped falsy err values.** `err ? String(err) : undefined` silently swallowed 0 / "" / false. Switched to `err !== undefined` so intentionally-falsy errors still land in the ring buffer, matching errMsg()'s behaviour at the top level. 3. **TALON_LOG_LEVEL docstring was out of date.** Added "silent" to the listed values — it's already a valid LogLevel and accepted by /debug/log-level. 4. **Content-Length early 413 didn't drain.** The header-based rejection returned without consuming the body, leaving the socket paused with unread data. Cheap but measurable backpressure target. Added a `req.resume()` mirroring the streaming oversize path. Tests: new json-safe.test.ts (18 cases covering every branch), plus extra cases in log-extras.test.ts (falsy err capture, cyclic/BigInt extra) and trace-spans.test.ts (cyclic/BigInt/fn attrs + cyclic event attrs all JSON-safe), and a gateway-http 413-then-healthy-followup check. Full suite: 1427 passing.
2e65253 to
537d9f7
Compare
|
Heartbeat #169 rebase — branch was CONFLICTING against main ( Conflicts resolved:
Verification:
New head: |
|
CI green after rebase ✅ (heartbeat #171 catch) All 15 checks passed on
This branch has been open since April 17 (21 days). It's now on current main and fully green. Ready for review whenever you have bandwidth. |
Summary
reqId/chatIdbindings, namespace filter, in-memory ring buffer, and a dedicated~/.talon/errors.log(warn+) that isn't diluted by info logs.AsyncLocalStorageparent linking. Spans persist to~/.talon/data/traces/spans-YYYY-MM-DD.jsonland auto-emitspan.<name>.mshistograms +span.<name>.<status>counters.util/debug.tssnapshot aggregator powering/debug/{state,metrics,spans,logs,errors,log-level}HTTP endpoints (with runtimePOST /debug/log-level) and atalon debugCLI (state|metrics|spans|errors|log-level), plustalon errorsto tail the new errors log.dispatcher,gateway,plugin,cron,dream,heartbeat, andbackend/claude-sdk— spans, per-action metrics, and span annotations for query metadata (model, tokens, cache hits, tool calls).Test plan
npm test(1387/1388 pass; 1 preexisting Windows symlink failure unrelated)npm run typechecknpm run lint(warnings only, none in new code)/debug/stateand/debug/spans, flip log level viaPOST /debug/log-level~/.talon/errors.logonly contains warn+ records after normal traffictalon debug spans 20andtalon errors --tail 100🤖 Generated with Claude Code