vrr/qwen-code
2
0
Fork 0
mirror of https://github.com/QwenLM/qwen-code.git synced 2026-08-25 08:33:55 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 17
qwen-code/docs/developers/daemon/19-observability.md
jinye 3378212b5f
feat(cli): correlate daemon logs with OpenTelemetry spans (#9084) 
Co-authored-by: Qwen-Coder <qwen-coder@alibabacloud.com>
2026-08-13 16:33:12 +00:00

253 lines
21 KiB
Markdown
Raw Permalink Blame History

# 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`. Caller `info` / `warn` / `error` records emitted with an active, recording, sampled OTel span include `trace_id` and `span_id`; file records also 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. |
| Web Shell UI | `GET /` (`packages/cli/src/serve/web-shell-static.ts`) | Browser UI served from the bundled Web Shell assets: chat, session list, workspace inspector, and permission UX. On loopback, `http://127.0.0.1:4170/` 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/<sid>/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`.
### 11. Is the daemon under memory pressure?
```bash
curl -s 'http://127.0.0.1:4170/daemon/status' | \
jq '.runtime.memory.pressure'
```
`level` is `normal` / `soft` / `hard` / `critical`, classified from `ratio` —
the worse of `rssRatio` (RSS against detected cgroup/host memory, which is what
the OOM killer watches) and `heapRatio` (V8 heap used against this process's
`heap_size_limit` — the whole heap, not only the old space that
`--max-old-space-size` names). `source` says which one produced it. Check `source` before acting:
`unknown` means the daemon could measure neither side, so `normal` there is the
absence of a reading, not evidence of health. A side is only reported when both
its numerator and its denominator were usable, so `source` is also what tells a
zero `rssBytes` / `heapUsedBytes` apart from a real one.
**`rssRatio` is only as good as its denominator, and
`limits.memory.availableMemorySource` is what grades it.** Under a cgroup
(`constrained`) it is exactly the limit the OOM killer enforces, so the ratio
means what it says. On bare metal (`host`) it is the size of the whole machine,
while the daemon actually dies when the _machine_ runs out — which depends on
every other process on the box. A daemon holding 20% of a 64 GB host beside a
55 GB neighbour reports `level: normal, source: rss` right up until it is
killed. Under `source: 'host'`, read `rssRatio` as a **lower bound** on real
pressure. This is separate from the thresholds being uncalibrated: no threshold
choice fixes a denominator that is measuring the wrong thing.
Two further things this does **not** cover. It is the daemon **root** process only, so
a daemon whose `qwen --acp` children are the ones growing can report `normal`
throughout — read `runtime.memory.children` beside it, which sums the live
children's own RSS (and says via `sampled` how many actually reported).
And nothing remediates: leaving `normal` raises a `daemon_memory_pressure`
warning and changes no behaviour.
Under `--memory-pressure-mode off` every figure above is still reported and the
issue is not raised, so the top-level `status` stays whatever it would have
been. Use `off` while calibrating thresholds against a real workload, or if you
alert on `status` and do not want an uncalibrated signal moving it.
## 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;<br/>QWEN_SERVE_DEBUG=1 + reproduce"]
E -->|no| EW["check /workspace/mcp,<br/>/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 text** whose `trace_id`, `span_id`, `route`, `sessionId`, and `clientId` fields can be searched or extracted with a regular expression. Caller `info` / `warn` / `error` records include trace fields only when the log call runs with an active, recording, sampled OTel span. `raw` and boot records, file-drop summaries, and access-log suppression summaries intentionally omit them. Correlation is best-effort: exporter failure can leave a sampled trace unavailable in the backend. These high-cardinality identifiers are for diagnostic lookup, not metric labels or aggregation. `QWEN_SERVE_DEBUG` stderr logs remain unstructured text.
- **Accepted prompt, continuation, and cancellation mutations have lifecycle logs.** `prompt enqueued`, `continuation enqueued`, and `cancel sent` include `sessionId`, `promptId` when applicable, and `clientId` when supplied; prompt content is not logged. Use a distinct stable client ID for each independent controller. Controllers that intentionally share an ID are indistinguishable in these records.
- **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)
Reference in a new issue View git blame Copy permalink