gabriel / musehub public
test_stdio_sql_echo.py python
133 lines 5.9 KB
Raw
sha256:71af3895204576a6667c619af9df11ac35f47c40f8a3dbcbde64540cf544f301 fix: SQLAlchemy echo=True floods MCP stdio's stdout with ra… Sonnet 5 minor ⚠ breaking 1 day ago
1 """TDD — musehub#208: SQLAlchemy echo=True floods MCP stdio's stdout with raw SQL.
2
3 Root cause: ``musehub/db/database.py::init_db()`` creates the async engine
4 with ``echo=settings.debug``. SQLAlchemy's own ``InstanceLogger.__init__``
5 (``sqlalchemy/log.py``) installs a hardcoded ``logging.StreamHandler(sys.stdout)``
6 on the engine's logger whenever ``echo`` is truthy and that logger has no
7 handlers yet — this has nothing to do with ``stdio_server.py``'s own
8 ``logging.basicConfig(stream=sys.stderr)`` call, which only configures the
9 *root* logger, not the uniquely-named per-engine child logger SQLAlchemy
10 creates. Under this project's default local-dev config (``DEBUG=true``),
11 every SQL statement gets written directly to stdout — the exact byte
12 stream the stdio MCP transport uses as its JSON-RPC wire protocol.
13
14 Fix: ``init_db()`` gains an ``echo`` override parameter; the stdio
15 transport passes ``echo=False`` unconditionally, regardless of
16 ``settings.debug`` — stdio's wire protocol correctness can never depend
17 on a debug flag someone else sets for an unrelated (HTTP) transport.
18 """
19 from __future__ import annotations
20
21 from unittest.mock import AsyncMock, MagicMock, patch
22
23 import pytest
24
25
26 @pytest.mark.asyncio
27 class TestInitDbEchoOverride:
28 async def test_default_uses_settings_debug_true(self) -> None:
29 from musehub.db import database as db_module
30
31 with (
32 patch.object(db_module.settings, "debug", True),
33 patch.object(db_module.settings, "database_url", "postgresql+asyncpg://u:p@h/d"),
34 patch.object(db_module.settings, "slow_query_threshold_ms", 0),
35 patch(
36 "musehub.db.database.create_async_engine",
37 return_value=MagicMock(sync_engine=MagicMock()),
38 ) as mock_create,
39 patch("musehub.db.database.async_sessionmaker"),
40 patch("musehub.db.schema_check.assert_schema_matches_orm", new_callable=AsyncMock),
41 ):
42 await db_module.init_db()
43 assert mock_create.call_args.kwargs["echo"] is True
44
45 async def test_default_uses_settings_debug_false(self) -> None:
46 from musehub.db import database as db_module
47
48 with (
49 patch.object(db_module.settings, "debug", False),
50 patch.object(db_module.settings, "database_url", "postgresql+asyncpg://u:p@h/d"),
51 patch.object(db_module.settings, "slow_query_threshold_ms", 0),
52 patch(
53 "musehub.db.database.create_async_engine",
54 return_value=MagicMock(sync_engine=MagicMock()),
55 ) as mock_create,
56 patch("musehub.db.database.async_sessionmaker"),
57 patch("musehub.db.schema_check.assert_schema_matches_orm", new_callable=AsyncMock),
58 ):
59 await db_module.init_db()
60 assert mock_create.call_args.kwargs["echo"] is False
61
62 async def test_echo_override_forces_false_even_when_debug_true(self) -> None:
63 """The actual regression guard: an explicit echo=False override must
64 win over settings.debug=True."""
65 from musehub.db import database as db_module
66
67 with (
68 patch.object(db_module.settings, "debug", True),
69 patch.object(db_module.settings, "database_url", "postgresql+asyncpg://u:p@h/d"),
70 patch.object(db_module.settings, "slow_query_threshold_ms", 0),
71 patch(
72 "musehub.db.database.create_async_engine",
73 return_value=MagicMock(sync_engine=MagicMock()),
74 ) as mock_create,
75 patch("musehub.db.database.async_sessionmaker"),
76 patch("musehub.db.schema_check.assert_schema_matches_orm", new_callable=AsyncMock),
77 ):
78 await db_module.init_db(echo=False)
79 assert mock_create.call_args.kwargs["echo"] is False
80
81 async def test_echo_override_forces_true_even_when_debug_false(self) -> None:
82 from musehub.db import database as db_module
83
84 with (
85 patch.object(db_module.settings, "debug", False),
86 patch.object(db_module.settings, "database_url", "postgresql+asyncpg://u:p@h/d"),
87 patch.object(db_module.settings, "slow_query_threshold_ms", 0),
88 patch(
89 "musehub.db.database.create_async_engine",
90 return_value=MagicMock(sync_engine=MagicMock()),
91 ) as mock_create,
92 patch("musehub.db.database.async_sessionmaker"),
93 patch("musehub.db.schema_check.assert_schema_matches_orm", new_callable=AsyncMock),
94 ):
95 await db_module.init_db(echo=True)
96 assert mock_create.call_args.kwargs["echo"] is True
97
98
99 @pytest.mark.asyncio
100 class TestStdioServerForcesEchoOff:
101 async def test_stdio_run_calls_init_db_with_echo_false(self) -> None:
102 """musehub#208's actual fix target: the stdio transport's own
103 startup must never let settings.debug leak SQL onto stdout."""
104 from musehub.mcp import stdio_server
105
106 import asyncio
107
108 mock_init_db = AsyncMock()
109 loop = asyncio.get_event_loop()
110 real_stream_reader = asyncio.StreamReader
111
112 async def _fake_connect_read_pipe(protocol_factory, pipe):
113 protocol = protocol_factory()
114 protocol.connection_made(MagicMock())
115 return MagicMock(), protocol
116
117 async def _fake_connect_write_pipe(protocol_factory, pipe):
118 return MagicMock(), protocol_factory()
119
120 def _capture_reader(*a, **kw):
121 r = real_stream_reader()
122 r.feed_eof()
123 return r
124
125 with (
126 patch.object(loop, "connect_read_pipe", side_effect=_fake_connect_read_pipe),
127 patch.object(loop, "connect_write_pipe", side_effect=_fake_connect_write_pipe),
128 patch("musehub.db.init_db", mock_init_db),
129 patch("asyncio.StreamReader", side_effect=_capture_reader),
130 ):
131 await stdio_server._run()
132
133 mock_init_db.assert_awaited_once_with(echo=False)
File History 1 commit
sha256:71af3895204576a6667c619af9df11ac35f47c40f8a3dbcbde64540cf544f301 fix: SQLAlchemy echo=True floods MCP stdio's stdout with ra… Sonnet 5 minor ⚠ 1 day ago