# Observability & Debugging ## Overview `qwen serve` currently ships with **OpenTelemetry span instrumentation**, **structured file logs** (`DaemonLogger`), **per-request access logs**, debug stderr logs, structured preflight cells, and an in-memory permission audit ring. This page is a practical guide to the current observability surface and the gaps to remember during triage. ## What exists today | Surface | Location | Purpose | | ------------------------------------------- | ---------------------------------------------- | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | | `QWEN_SERVE_DEBUG` stderr logs | `bridge.ts` and call sites | Env values `1` / `true` / `on` / `yes` (case-insensitive) print `qwen serve debug: ...` lines to stderr. | | OpenTelemetry span instrumentation | `server.ts` `daemonTelemetryMiddleware` | Classified daemon API requests that reach the telemetry middleware are wrapped in `withDaemonRequestSpan`; attributes include canonical route, workspace hash when resolved, sessionId, clientId, and status code. Permission routes have dedicated spans. Prompt lifecycle is traced end-to-end. Configuration lives in `settings.json` `telemetry`. | | OpenTelemetry daemon perf metrics | `telemetry/*event-loop-lag*`, `daemon-metrics` | Event loop lag gauges for daemon and ACP child processes, plus daemon-child pipe message byte histograms. | | `DaemonLogger` structured file logs | `serve/daemon-logger.ts` | Appends to a stable, size-rotated `daemon.log`. File records include `runId` and PID. Boot prints the selected stable/fallback path; full status exposes health, issues, and file-copy loss counters. | | Per-request access-log middleware | `server/access-log.ts` | Logs method/path, status, duration, session, and first raw client ID after each request. A 60-token burst / 2-per-second bucket aggregates excess traffic into five fixed status counters. Health, heartbeat, and successful SSE exclusions remain. | | `/health` | `server.ts` route | Liveness probe; `?deep=1` returns extended details. | | `/capabilities` | `server.ts` route | Preflight feature discovery. See [`11-capabilities-versioning.md`](./11-capabilities-versioning.md). | | `/workspace/preflight` | Route -> `DaemonStatusProvider` | Structured readiness cells: Node version, CLI entry, ripgrep, git, npm, plus ACP-level cells once a child is alive. | | `/workspace/env` | Route -> `DaemonStatusProvider` | Daemon process env snapshot. Secret env vars report only presence; proxy URL credentials are stripped. | | `/workspace/mcp` | Route -> bridge extMethod | Pool, budget, and refusal snapshot. | | `/workspace/skills`, `/workspace/providers` | Routes | ACP-side live snapshots; return empty idle data when no session exists. | | Per-session SSE | `GET /session/:id/events` | Real-time event stream. | | `/demo` debug console | `GET /demo` (`packages/cli/src/serve/demo.ts`) | Browser-accessible single-page console: chat, event log, workspace inspector, and permission UX. On loopback, `http://127.0.0.1:4170/demo` is the quickest end-to-end validation path without writing SDK code. Registration rules are in [`02-serve-runtime.md`](./02-serve-runtime.md). | | `PermissionAuditRing` | `permission-audit.ts` | In-memory FIFO of 512 permission decisions. | | Mediator `decisionReason` audit | `permissionMediator.ts` | Internal structured record explaining why a permission request resolved the way it did. | ## What does not exist today - **No Prometheus / metrics endpoint.** OTel metrics can be exported, but the daemon does not expose a Prometheus scrape endpoint. - **No external audit sink for `PermissionAuditRing`.** The ring exists, but fan-out hooks to SIEM or external storage are not wired. ## Debugging recipes ### 1. Is the daemon alive? ```bash curl -s http://127.0.0.1:4170/health # {"status":"ok"} curl -s 'http://127.0.0.1:4170/health?deep=1' | jq # {"status":"ok","workspaceCount":N,"sessions":N,...} ``` Deep health totals all managed workspace runtimes, including runtimes still draining. It is an informational counter snapshot, not per-workspace readiness; use `/daemon/status` when individual workspace or transport diagnostics matter. A 401 on loopback means `--require-auth` is likely enabled. Use `QWEN_SERVE_DEBUG=1` at startup to see boot logs. ### 2. Which features are advertised? ```bash curl -s http://127.0.0.1:4170/capabilities | jq ``` Check `mcp_workspace_pool` (F2 pool on?), `require_auth` (hardened?), `permission_mediation.modes` (supported policies), and `policy.permission` (active policy). ### 3. Is daemon-host readiness healthy? ```bash curl -s http://127.0.0.1:4170/workspace/preflight | jq ``` `status: 'not_started'` cells are ACP-level and populate only after the first session attaches. `status: 'fail'` cells include a closed `errorKind`; render structured remediation from [`18-error-taxonomy.md`](./18-error-taxonomy.md). ### 4. Tail a session SSE stream ```bash curl -N -H 'Accept: text/event-stream' \ -H 'Authorization: Bearer XYZ' \ -H 'X-Qwen-Client-Id: debug-tail' \ -H 'Last-Event-ID: 0' \ 'http://127.0.0.1:4170/session//events' ``` `-N` disables curl output buffering. `Last-Event-ID: 0` requests replay for ring events with `id > 0`. ### 5. Why did a permission request resolve this way? `PermissionAuditRing` is in-memory and has no HTTP surface today. Enable `QWEN_SERVE_DEBUG=1` and reproduce; the mediator prints structured lines for each vote and decision, including `decisionReason.type`. A later PR can expose the ring through HTTP. ### 6. Which consumer is slow? `slow_client_warning` fires once per overflow episode when the queue reaches 75%. Subscribe to the session SSE stream and look for the synthetic frame; payload includes `queueSize`, `maxQueued`, and `lastEventId`. Repeated warnings point at a stuck consumer, usually a blocked SDK `for await` loop. ### 7. Why was an MCP server refused? Combine `/workspace/mcp` per-cell `disabledReason: 'budget'`, the `refusedServerNames` list, and `mcp_child_refused_batch` SSE events. Compare them with `/capabilities` `mcp_guardrails.modes` (`enforce` active?) and the live `--mcp-client-budget` state visible through `getReservedSlots()`. ### 8. The daemon will not shut down The first signal triggers graceful shutdown (see [`02-serve-runtime.md`](./02-serve-runtime.md)). If it hangs past 10s, check: - ACP child process did not respond to graceful close. - Long SSE connections kept HTTP `server.close()` open past `SHUTDOWN_FORCE_CLOSE_MS` (5s). A **second** SIGTERM/SIGINT intentionally triggers `bridge.killAllSync()` + `process.exit(1)`. ### 9. Is the daemon event loop, prompt queue, or ACP pipe overloaded? `GET /daemon/status` may include `runtime.perf` when the production daemon runtime injects the perf snapshot provider: ```json { "runtime": { "perf": { "eventLoop": { "meanMs": 1.2, "p50Ms": 1.0, "p99Ms": 9.5, "maxMs": 25 }, "promptQueueWait": { "count": 3, "meanMs": 12.5, "maxMs": 35, "lastMs": 4 }, "pipe": { "inbound": { "count": 42, "totalBytes": 100000, "maxBytes": 12000 }, "outbound": { "count": 41, "totalBytes": 90000, "maxBytes": 11000 } } } } } ``` The status payload is daemon-only. `promptQueueWait` summarizes prompt FIFO queue wait samples observed in the daemon process. ACP child event loop lag is intentionally not aggregated into `/daemon/status`; it is visible through OTel gauge `qwen-code.acp.event_loop.lag` and through stderr stall lines forwarded into daemon logs. ### 10. Did file logging degrade or lose records? Use full daemon status: ```bash curl -s 'http://127.0.0.1:4170/daemon/status?detail=full' | \ jq '{status, issues, daemon: {runId: .daemon.runId, logMode: .daemon.logMode, logHealth: .daemon.logHealth, logPath: .daemon.logPath, logIssues: .daemon.logIssues, droppedRecords: .daemon.logDroppedRecords, droppedBytes: .daemon.logDroppedBytes}}' ``` `stable` is the normal owner, `fallback` means another daemon owns the stable family, and `stderr-only` means file logging is disabled or unavailable. `fallback/ok` is expected under intentional concurrency. A `daemon_log_degraded` warning contains no path; request full detail for the actual path and logger issue codes. Use `runId` to separate restarts inside the stable file. New OTel metric names: - `qwen-code.daemon.event_loop.lag`, gauge in milliseconds with `stat=mean|p50|p99|max`. - `qwen-code.acp.event_loop.lag`, gauge in milliseconds with `stat=mean|p50|p99|max`. - `qwen-code.daemon.prompt.queue_wait`, histogram in milliseconds. - `qwen-code.daemon.pipe.message_bytes`, histogram in bytes with `direction=inbound|outbound`. ## Flow ### Typical triage flow ```mermaid flowchart TD A[User reports issue] --> B{daemon alive?} B -->|no| BD[check process; check boot logs] B -->|yes| C{capabilities match expectations?} C -->|no| CD["check --require-auth, QWEN_SERVE_NO_MCP_POOL, settings.json"] C -->|yes| D{preflight all green?} D -->|no| DD["fix the errorKind cell"] D -->|yes| E{issue is session-specific?} E -->|yes| ES["tail SSE for that session;
QWEN_SERVE_DEBUG=1 + reproduce"] E -->|no| EW["check /workspace/mcp,
/workspace/env"] ``` ## State and lifecycle - `QWEN_SERVE_DEBUG` is read on every check through `isServeDebugMode()` from `debug-mode.ts`; toggling it does not require restart. Boot logs are not available unless the env was set at boot. - `PermissionAuditRing` is bounded at 512 FIFO entries; older records are silently dropped. - `DaemonStatusProvider` rebuilds cells per request and does not cache; avoid unnecessary high-frequency polling. ## Dependencies - `process.stderr.write` for debug stderr. - `DaemonLogger` for structured file logs. - OpenTelemetry SDK through `initializeTelemetry` and `createDaemonBridgeTelemetry`. - `node:perf_hooks.monitorEventLoopDelay` for daemon and ACP event loop lag gauges. - `node:process` for env and signal inspection. ## Configuration | Knob | Effect | | ------------------------------- | -------------------------------------------------------------------------------------------- | | `QWEN_SERVE_DEBUG` | Enables verbose stderr logs. See [`17-configuration.md`](./17-configuration.md). | | `settings.json` `telemetry` | Controls OTel behavior: `enabled`, `otlpEndpoint`, `otlpProtocol`, and per-signal endpoints. | | `DaemonLogger` log path | Stable `debug/daemon/daemon.log`, or a run-specific fallback selected at boot. | | `PermissionAuditRing` size | Hard-coded to 512 today. | | `slow_client_warning` threshold | `0.75` / `0.375`, hard-coded in `eventBus.ts`. | ## Caveats and known limits - **DaemonLogger file logs are structured** and can be filtered by `route`, `sessionId`, and `clientId`. `QWEN_SERVE_DEBUG` stderr logs remain unstructured text. - **DaemonLogger retention is size based, not age based.** The active file and four archives are bounded per family; live fallback owners are never deleted. - **Access summaries are intentional loss accounting.** A WARN `access logs suppressed` represents individual access records omitted from both stderr and file; it does not indicate dropped HTTP requests. - **External logrotate must not mutate the active family.** Use a shipper that reads/copies and reopens the stable pathname after replacement. - **OpenTelemetry spans include per-request correlation.** Classified daemon API requests that pass bearer authentication, rate limiting, and body parsing carry canonical route, sessionId, clientId, and (when uniquely resolved) `qwen-code.workspace.hash` attributes. Requests rejected by an earlier middleware gate do not have these request spans. - **HTTP metrics are daemon-global.** OpenTelemetry HTTP request metrics and the Web Shell status metrics ring do not include a workspace dimension. A successful session SSE connection has a request span but is excluded from ordinary request count/duration metrics because its lifetime is not request latency; failed SSE handshakes are counted normally. - **`runtime.perf` is daemon-only.** Child event loop lag is not reported there by design; use OTel or forwarded stderr stall warnings for ACP child stalls. - **ACP-level `/workspace/preflight` cells require a live session.** On an idle daemon, auth / MCP / skills / providers may show `status: 'not_started'`; this is expected. - **`/workspace/env` only reports secret presence, not values.** Do not expose the response where the mere presence of a secret is sensitive. - **The audit ring is process-local** and history is lost on daemon restart. - **No load-test recipe is documented here.** The performance baseline lives on the `test/perf-daemon-baseline` branch. ## References - `packages/cli/src/serve/daemon-status-provider.ts` - `packages/cli/src/serve/daemon-logger.ts` (`DaemonLogger`, `buildDaemonLogLine`) - `packages/cli/src/serve/debug-mode.ts` (`isServeDebugMode`) - `packages/acp-bridge/src/permissionMediator.ts` (`PermissionDecisionReason`) - `packages/cli/src/serve/server.ts` (`daemonTelemetryMiddleware`, access-log middleware) - Configuration: [`17-configuration.md`](./17-configuration.md) - Error taxonomy: [`18-error-taxonomy.md`](./18-error-taxonomy.md) - User operations guide: [`../../users/qwen-serve.md`](../../users/qwen-serve.md)