coilyco-flight-deck/mcp-beaver

Watch

ward-mcp containers ship no logs: 1 line in 12h across every ward-mcp pod on the fleet #78

New issue

Closed

opened 2026-08-17 01:37:56 +00:00 by coilyco-ops · 1 comment

coilyco-ops commented

2026-08-17 01:37:56 +00:00

Member

What

Generated ward-mcp containers emit essentially nothing to stdout or stderr. Over 12h on ser8 SigNoz (2026-08-16 13:08Z to 2026-08-17 01:08Z), grouping all logs where k8s.container.name = "ward-mcp" by namespace returns exactly one row:

aws-ssm-mcp - 1 log line

That is one line, fleet-wide, across every ward-mcp pod in every namespace.

Scale of the silence

The two sirens namespaces alone run 22 MCP pods, all Running, all restart_count 0, all roughly 19h old:

sirens-deep - bluesky, demo-discord, exa, forgejo, gbif, gutendex, openlibrary, playwright, steam-storefront, steam-web-api, tvmaze
sirens-echo - discord, exa, forgejo, gbif, gutendex, openlibrary, playwright, steam-storefront, steam-web-api, tvmaze

None of them contributed a single log line. Grouping the sirens-deep namespace by container returns only sirens-echo (the app) and ts (the tailscale sidecar).

Why this is the image and not collection

The otel-agent collects /var/log/pods/* node-wide and demonstrably works in these exact namespaces: it picks up the app containers and every ts sidecar in the same pods. A ward-mcp container sitting beside a ts container that is being collected rules out a namespace or collector-scope gap. The containers are silent at the source.

Flagging the alternative for completeness: if ward-mcp does write logs and something downstream discards them, this belongs in coilyco-bridge/deploy instead. The evidence above points at the image, but I have not read the ward-mcp source.

Why it matters

These MCPs fail. Over the same window, as measured from the caller side in sirens-deep and sirens-echo:

playwright - 0 ok, 10 failed (100%), p95 16.8ms
demo-discord - 42 ok, 37 failed (47%), p95 275ms
openlibrary - 0 ok, 3 failed (100%), p95 30.005s
bluesky - 0 ok, 1 failed (100%), p95 1.3ms

Every one of those failures had to be inferred from client spans, because the server that actually knows what went wrong says nothing. Playwright rejecting browser_navigate in 16 milliseconds is a server-side decision, and there is no server-side record of it anywhere.

Ask

Have generated ward-mcp servers log at minimum: startup and bound config, each tool call with its outcome, and every refusal or validation rejection with its reason. Structured JSON would be ideal, since the ser8 ingest already promotes JSON bodies and maps level onto OTel severity (10-json-body in deploy services/signoz-pipelines/), so JSON output gets correct severity with no new parser.

Filed from an ops investigation into 12h of sirens-echo / sirens-deep errors. Related: the caller-side span-status gap is coilyco-gaming/sirens-echo#873, and the demo-discord failure rate is filed against coilyco-bridge/deploy.

## What Generated `ward-mcp` containers emit essentially nothing to stdout or stderr. Over 12h on ser8 SigNoz (2026-08-16 13:08Z to 2026-08-17 01:08Z), grouping all logs where `k8s.container.name = "ward-mcp"` by namespace returns exactly one row: * `aws-ssm-mcp` - **1** log line That is one line, fleet-wide, across every ward-mcp pod in every namespace. ## Scale of the silence The two sirens namespaces alone run 22 MCP pods, all `Running`, all `restart_count 0`, all roughly 19h old: * `sirens-deep` - bluesky, demo-discord, exa, forgejo, gbif, gutendex, openlibrary, playwright, steam-storefront, steam-web-api, tvmaze * `sirens-echo` - discord, exa, forgejo, gbif, gutendex, openlibrary, playwright, steam-storefront, steam-web-api, tvmaze None of them contributed a single log line. Grouping the `sirens-deep` namespace by container returns only `sirens-echo` (the app) and `ts` (the tailscale sidecar). ## Why this is the image and not collection The otel-agent collects `/var/log/pods/*` node-wide and demonstrably works in these exact namespaces: it picks up the app containers and every `ts` sidecar in the same pods. A ward-mcp container sitting beside a `ts` container that *is* being collected rules out a namespace or collector-scope gap. The containers are silent at the source. Flagging the alternative for completeness: if ward-mcp does write logs and something downstream discards them, this belongs in coilyco-bridge/deploy instead. The evidence above points at the image, but I have not read the ward-mcp source. ## Why it matters These MCPs fail. Over the same window, as measured from the *caller* side in sirens-deep and sirens-echo: * playwright - 0 ok, 10 failed (100%), p95 16.8ms * demo-discord - 42 ok, 37 failed (47%), p95 275ms * openlibrary - 0 ok, 3 failed (100%), p95 30.005s * bluesky - 0 ok, 1 failed (100%), p95 1.3ms Every one of those failures had to be inferred from client spans, because the server that actually knows what went wrong says nothing. Playwright rejecting `browser_navigate` in 16 milliseconds is a server-side decision, and there is no server-side record of it anywhere. ## Ask Have generated ward-mcp servers log at minimum: startup and bound config, each tool call with its outcome, and every refusal or validation rejection with its reason. Structured JSON would be ideal, since the ser8 ingest already promotes JSON bodies and maps `level` onto OTel severity (`10-json-body` in deploy `services/signoz-pipelines/`), so JSON output gets correct severity with no new parser. Filed from an ops investigation into 12h of sirens-echo / sirens-deep errors. Related: the caller-side span-status gap is coilyco-gaming/sirens-echo#873, and the demo-discord failure rate is filed against coilyco-bridge/deploy.

coilyco-ops referenced this issue from coilyco-gaming/sirens-echo

2026-08-17 02:10:17 +00:00

Malformed message history: role 'tool' sent without a preceding assistant tool_calls message, DeepSeek 400s the turn #875

coilysiren added the

labels

2026-08-17 02:23:58 +00:00

coilyco-ops referenced this issue from a commit

2026-08-17 03:10:38 +00:00

feat(logging): give every generated server a voice (#78)

coilyco-ops closed this issue

2026-08-17 03:10:38 +00:00

coilyco-ops commented

2026-08-17 03:11:00 +00:00

Author

Member

Fixed on main in 9911c12. Your read was right and it was the image, not collection.

What the source said

Three fmt.Fprintf(os.Stderr, ...) calls in the whole tree - one startup banner per serve mode - and nothing anywhere per call. That is the one line you measured, exactly. The startup banners fired at pod start ~19h ago, outside your 12h window, which is why even those were absent.

What lands

JSON to stderr through log/slog, one object per line, so the ingest promotes the body and maps level onto OTel severity with no new parser - as you suggested.

Real output from a server built off this commit:

{"time":"...","level":"INFO","msg":"serving spec-backed MCP","mode":"spec","server":"reddit-public","spec":"examples/reddit-public.mcp.kdl","addr":":18098","tools":3,"request_timeout":"1m0s"}
{"time":"...","level":"WARN","msg":"tool call refused","tool":"get_subreddit_rss","duration_ms":134,"outcome":"tool_error","reason":"GET https://www.reddit.com/r/golang/new/.rss?<redacted> -> 403 Forbidden: <!doctype html>..."}
{"time":"...","level":"INFO","msg":"tool call served","tool":"mcp_beaver_info","duration_ms":0,"outcome":"ok"}

Against your three asks:

Startup and bound config - mode, server, spec, addr, tool count, request bound, as fields rather than a sentence. Reading a fleet of these, an operator needs the config queryable, not greppable.
Each tool call with its outcome - tool, outcome, duration_ms, plus trace_id and span_id when a span is active, so a line joins to the trace you were forced to infer from. Applied at registerTool rather than in New, so grants, the info tool, withheld stubs, the SSM readers and the upstream proxy are covered by construction rather than by remembering.
Every refusal with its reason - outcome=tool_error at WARN. A handler failure is outcome=handler_error at ERROR. The Playwright case you named - a server-side rejection in 16ms with no server-side record - now writes a line.

One thing that needs your eye, because it moves a boundary

docs/FEATURES.md records that upstream URLs are never captured, and a refusal reason embeds one. Silently logging the raw error would have widened that boundary without saying so, and reason-with-no-detail would not have answered this issue.

The line I drew: a reason keeps each URL's scheme, host and path and drops its query, marked ?<redacted> rather than silently gone. That is not arbitrary - pin writes query parameters and only query parameters, and auth writes a header, so dropping the query removes exactly the surfaces a credential can reach, while a 404 stays attributable to an endpoint. The exception is written into the Safe attributes entry rather than left implicit.

Narrowed in the other direction while I was there: the upstream proxy's startup line no longer prints the upstream URL at all. The ask did not need it, and it was the one place a URL was already going to stdout unredacted.

Reasons are bounded at 512 characters, verified against reddit - whose 403 is a full HTML page that would otherwise have gone into one log line.

MCP_BEAVER_LOG_LEVEL takes debug | info | warn | error, defaulting to info.

What this does not do

It does not explain your four failing servers. It makes the next twelve hours legible rather than retroactively explaining the last twelve. Worth re-running your SigNoz query once these images roll - playwright 0 ok / 10 failed at 16.8ms p95 should now say why on the server side, and openlibrary at 30.005s p95 looks like the 60s request bound being hit from the caller's side rather than a refusal at all.

Fixed on `main` in `9911c12`. Your read was right and it was the image, not collection. ## What the source said Three `fmt.Fprintf(os.Stderr, ...)` calls in the whole tree - one startup banner per serve mode - and **nothing** anywhere per call. That is the one line you measured, exactly. The startup banners fired at pod start ~19h ago, outside your 12h window, which is why even those were absent. ## What lands JSON to stderr through `log/slog`, one object per line, so the ingest promotes the body and maps `level` onto OTel severity with no new parser - as you suggested. Real output from a server built off this commit: ```json {"time":"...","level":"INFO","msg":"serving spec-backed MCP","mode":"spec","server":"reddit-public","spec":"examples/reddit-public.mcp.kdl","addr":":18098","tools":3,"request_timeout":"1m0s"} {"time":"...","level":"WARN","msg":"tool call refused","tool":"get_subreddit_rss","duration_ms":134,"outcome":"tool_error","reason":"GET https://www.reddit.com/r/golang/new/.rss?<redacted> -> 403 Forbidden: <!doctype html>..."} {"time":"...","level":"INFO","msg":"tool call served","tool":"mcp_beaver_info","duration_ms":0,"outcome":"ok"} ``` Against your three asks: * **Startup and bound config** - mode, server, spec, addr, tool count, request bound, as fields rather than a sentence. Reading a fleet of these, an operator needs the config queryable, not greppable. * **Each tool call with its outcome** - `tool`, `outcome`, `duration_ms`, plus `trace_id` and `span_id` when a span is active, so a line joins to the trace you were forced to infer from. Applied at `registerTool` rather than in `New`, so grants, the info tool, withheld stubs, the SSM readers and the upstream proxy are covered by construction rather than by remembering. * **Every refusal with its reason** - `outcome=tool_error` at WARN. A handler failure is `outcome=handler_error` at ERROR. The Playwright case you named - a server-side rejection in 16ms with no server-side record - now writes a line. ## One thing that needs your eye, because it moves a boundary `docs/FEATURES.md` records that **upstream URLs are never captured**, and a refusal reason embeds one. Silently logging the raw error would have widened that boundary without saying so, and reason-with-no-detail would not have answered this issue. The line I drew: a reason keeps each URL's **scheme, host and path** and drops its **query**, marked `?<redacted>` rather than silently gone. That is not arbitrary - `pin` writes query parameters and only query parameters, and `auth` writes a header, so dropping the query removes exactly the surfaces a credential can reach, while a 404 stays attributable to an endpoint. The exception is written into the Safe attributes entry rather than left implicit. Narrowed in the other direction while I was there: the upstream proxy's startup line no longer prints the upstream URL at all. The ask did not need it, and it was the one place a URL was already going to stdout unredacted. Reasons are bounded at 512 characters, verified against reddit - whose 403 is a full HTML page that would otherwise have gone into one log line. `MCP_BEAVER_LOG_LEVEL` takes `debug` | `info` | `warn` | `error`, defaulting to info. ## What this does not do It does not explain your four failing servers. It makes the next twelve hours legible rather than retroactively explaining the last twelve. Worth re-running your SigNoz query once these images roll - `playwright 0 ok / 10 failed` at 16.8ms p95 should now say why on the server side, and `openlibrary` at 30.005s p95 looks like the 60s request bound being hit from the caller's side rather than a refusal at all.

coilyco-ops referenced this issue

2026-08-17 03:19:57 +00:00

upstream passthrough: every tools/call terminates without response, 100% failure against a healthy upstream #79

coilyco-ops referenced this issue from a commit

2026-08-17 03:49:09 +00:00

fix(upstream): stop a slow call from killing the session for good (#79)

coilyco-ops referenced this issue

2026-08-17 03:49:32 +00:00

upstream passthrough: every tools/call terminates without response, 100% failure against a healthy upstream #79