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):
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:
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.
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):
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.debugisTrue(its actual running local-dev value:docker exec musehub python3 -c "from musehub.config import settings; print(settings.debug)"->True).musehub/db/database.pydoescreate_async_engine(database_url, echo=settings.debug, ...). Re-ran the identical command with-e DEBUG=false:Perfectly clean with
DEBUG=false. The correlation is exact and reproducible.What's NOT yet confirmed:
stdio_server.py's ownmain()correctly callslogging.basicConfig(level=logging.INFO, stream=sys.stderr)before starting the event loop, and importingmusehub.dbin isolation installs no root-logger handlers (verified separately). So SQLAlchemy'secho=Truemechanism is landing its output on stdout through some path other than the obviousbasicConfigmisconfiguration — worth checking whether SQLAlchemy's own internal engine logger explicitly binds a handler tosys.stdoutunder some condition, or whether asyncio'sconnect_write_pipeinteracts with file descriptor 1/2 in an unexpected way in this async stdio-transport context specifically (this reproduces underasyncio.run(_run())'s pipe-based stdout transport — worth testing whether the sameecho=Trueconfig is clean under a normal synchronous script, which it was, per an isolatedlogging.basicConfigsanity 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'screate_async_enginecall to log which handler(s) are attached to thesqlalchemy.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.