gabriel / musehub public
Open #208 Bug
filed by gabriel human · 33 days ago

MCP stdio transport: SQLAlchemy echo (DEBUG=true) floods stdout with SQL text, corrupting the JSON-RPC stream

0 Anchors
— Blast radius
— Churn 30d
0 Proposals
No description provided.
◎ Activity1
●
gabriel opened this issue 33 days ago
○
gabriel 33 days ago

Confirmed while building Episode 16 ("Muse + MCP") demo material. Severe: breaks the stdio JSON-RPC protocol for any real MCP client, under this project's own default local-dev configuration.

Repro (exact command from docs/reference/mcp.md's own Cursor IDE integration example):

echo '{"jsonrpc":"2.0","id":1,"method":"initialize","params":{"protocolVersion":"2025-11-25","capabilities":{}}}' \
  | docker exec -i musehub python3 -m musehub.mcp.stdio_server \
  >/tmp/stdout.log 2>/tmp/stderr.log

wc -l /tmp/stdout.log   # -> 2141 lines
head -3 /tmp/stdout.log
# 2026-09-12 20:06:54,525 INFO sqlalchemy.engine.Engine select pg_catalog.version()
# 2026-09-12 20:06:54,525 INFO sqlalchemy.engine.Engine [raw sql] ()
# ...

The one real JSON-RPC response line is buried somewhere in the middle of ~2140 lines of raw SQL debug text on stdout. Any client following the docs' own instructions — "Reads newline-delimited JSON-RPC 2.0 messages from stdin... writes JSON-RPC 2.0 responses to stdout... logs diagnostic messages to stderr" — would fail to parse nearly every line it receives.

Confirmed root cause (correlation, not yet the exact internal mechanism): this container's settings.debug is True (its actual running local-dev value: docker exec musehub python3 -c "from musehub.config import settings; print(settings.debug)" -> True). musehub/db/database.py does create_async_engine(database_url, echo=settings.debug, ...). Re-ran the identical command with -e DEBUG=false:

echo '...' | docker exec -i -e DEBUG=false musehub python3 -m musehub.mcp.stdio_server \
  >/tmp/stdout2.log 2>/tmp/stderr2.log
wc -l /tmp/stdout2.log   # -> 1 line (the real, valid JSON-RPC response)
wc -l /tmp/stderr2.log   # -> 5 lines (correct diagnostics)

Perfectly clean with DEBUG=false. The correlation is exact and reproducible.

What's NOT yet confirmed: stdio_server.py's own main() correctly calls logging.basicConfig(level=logging.INFO, stream=sys.stderr) before starting the event loop, and importing musehub.db in isolation installs no root-logger handlers (verified separately). So SQLAlchemy's echo=True mechanism is landing its output on stdout through some path other than the obvious basicConfig misconfiguration — worth checking whether SQLAlchemy's own internal engine logger explicitly binds a handler to sys.stdout under some condition, or whether asyncio's connect_write_pipe interacts with file descriptor 1/2 in an unexpected way in this async stdio-transport context specifically (this reproduces under asyncio.run(_run())'s pipe-based stdout transport — worth testing whether the same echo=True config is clean under a normal synchronous script, which it was, per an isolated logging.basicConfig sanity check that behaved correctly).

Why this matters for the exact audience the docs target: the stdio transport is explicitly documented as "the local dev and Cursor IDE transport" — i.e. the audience most likely to be running with DEBUG=true (or whatever the project's own default local dev value is) is exactly the audience this breaks for.

Suggested starting point for whoever picks this up: instrument musehub/db/database.py's create_async_engine call to log which handler(s) are attached to the sqlalchemy.engine.Engine.* logger right after engine creation, specifically inside the async stdio server process (vs. a plain sync script) to isolate whether the asyncio pipe transport setup is the differentiator.

Deferred per usual until after the season wraps.