Skip to content

Commit 7f200e8

Browse files
borisbatclaude
andcommitted
MCP stdio audit fixes: daslib/logger + popen_argv_pipe + stdin isolation
Closes the stdio-leak audit thread that started from MCP server hangs. Every byte the MCP child process writes is now contained; every byte of the parent's stdin is unreachable to children. daslib/logger (new) - JSON Lines structured logger for daslang tools (MCP, daslang-live, etc). One JSON object per line to {get_das_root()}/logs/<name>.log with ISO 8601 UTC timestamp, level name, dotted category, message, optional fields object. All public API prefixed (logger_init, logger_info, logger_warning, logger_set_min_level, logger_install_hook, ...) so short verbs don't collide unqualified. - logger_install_hook() registers a global DapiDebugAgent that diverts print() / to_log() into the log file -- critical for stdio-transport processes where any accidental stdout write corrupts JSON-RPC framing. One install covers main + every new_thread worker. src/builtin/module_builtin_fio.cpp - Add iso8601_now() builtin (UTC, ms precision, ISO 8601). Used by daslib/logger; also generally useful. - Add popen_argv_pipe() builtin -- bidirectional subprocess pipes (writable stdin + readable stdout). Same shell-bypass semantics as popen_argv. - Harden popen_argv: explicitly isolate child stdin from parent. Windows: open NUL for read, pass as STARTUPINFO.hStdInput. Linux: open /dev/null, dup2(STDIN_FILENO) in child. Prevents a child from silently consuming bytes intended for the parent's JSON-RPC input. include/daScript/simulate/aot_builtin_{fio,time}.h - AOT-side declarations for the two new builtins so generated .cpp links. utils/mcp/* (MCP migration) - main.das + protocol.das: replace bespoke log_open/log_write/log_path infrastructure with daslib/logger. Dotted categories (mcp / mcp.req / mcp.res / mcp.tool / mcp.live / mcp.heap). - tools/live.das: replace two system() calls (powershell launcher, chmod+sh wrapper) with run_and_capture / popen_argv. system() inherited MCP's stdio; any launcher chatter (PowerShell errors, COM messages) would corrupt JSON-RPC. Output now captured + logged. daslib/command_line.das - Add missing `module command_line shared public` declaration. Without it, daslang's AOT codegen emitted only an empty stub for the module, triggering error[50101] hash desync when anything required it under AOT. This unblocks AOT for any future test/utility that uses get_das_exe. Tests - tests/daslib/test_logger.das -- 6 [test] / 12 subtests: JSON Lines write, level filter, dotted-category prefix override, JSON escaping + round-trip, fields serialization, no-op when unconfigured. - tests/mcp/test_mcp_jsonrpc.das -- spawns daslang.exe utils/mcp/main.das via popen_argv_pipe, drives initialize / tools/list / tools/call / method-not-found through JSON-RPC. Multi-chunk read loop for >16KB responses. - tests/mcp/test_popen_argv_pipe.das -- unit tests for the new builtin (echo round-trip, exit code propagation, stdin-EOF-after-block). - tests/fio/popen_argv.das -- new test confirming child stdin isolation (spawn echo fixture, no input -> exits cleanly, no output). - All new test dirs registered in tests/aot/CMakeLists.txt. Docs - daslib/logger added to das2rst.das with 5 groups (Setup / Level filters / Output control / Log calls / Stdout hook) + handmade module-logger.rst + sec_io.rst toctree entry. - iso8601_now categorized under "Time and date"; popen_argv_pipe under "OS specific routines" in builtin/fio doc groups. Handmade descriptions for both. - skills/daslib_modules.md updated with logger entry. Verified locally - Interpreter test suite: 9079 tests, 9073 passed (6 skipped). - AOT test suite: 8423 tests, 8417 passed (6 skipped). - Lint: 0 issues across all changed .das files. - Format: all changed .das files already-formatted. - Sphinx HTML build: build succeeded, no warnings. - MCP server smoke: starts, logs JSON Lines, exits cleanly on stdin EOF. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
1 parent 4d83c4f commit 7f200e8

22 files changed

Lines changed: 1222 additions & 69 deletions

.gitignore

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -140,3 +140,4 @@ build-ubsan/.ninja_log
140140
doc/sphinx-build-latex/environment.pickle
141141
opencode.json
142142
test-results/
143+
logs/

daslib/command_line.das

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,8 @@
11
options gen2
22
options no_unused_function_arguments = false
33

4+
module command_line shared public
5+
46
//! Command-line utilities for daslang scripts and standalone executables.
57
//! Provides functions for locating the daslang interpreter, which is essential
68
//! when a script or standalone executable needs to spawn daslang subprocesses.

daslib/logger.das

Lines changed: 334 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,334 @@
1+
options gen2
2+
options indenting = 4
3+
options no_global_variables = false
4+
options no_unused_block_arguments = false
5+
options no_unused_function_arguments = false
6+
7+
module logger shared public
8+
9+
//! Structured logging for daslang tools.
10+
//!
11+
//! Writes one JSON object per line ("JSON Lines" / ``ndjson``) to
12+
//! ``{get_das_root()}/logs/<name>.log``. Reuses the runtime ``LOG_TRACE`` /
13+
//! ``LOG_DEBUG`` / ``LOG_INFO`` / ``LOG_WARNING`` / ``LOG_ERROR`` /
14+
//! ``LOG_CRITICAL`` levels. Each record carries an ISO 8601 UTC timestamp
15+
//! (millisecond precision), level name, category, message, and optional
16+
//! ``fields`` object.
17+
//!
18+
//! All public names carry the ``logger_`` prefix — short verbs like
19+
//! ``flush`` / ``close`` / ``info`` / ``debug`` would collide with user
20+
//! code when called unqualified. The intended call shape is
21+
//! ``logger_info("mcp.tool", "...")``, not ``logger::info(...)``.
22+
//!
23+
//! **Categories** are free-form strings; the convention is dotted
24+
//! hierarchy from tool name down to subsystem:
25+
//!
26+
//! - ``"mcp"`` — top-level events for the MCP server
27+
//! - ``"mcp.req"`` / ``"mcp.res"`` — JSON-RPC request / response framing
28+
//! - ``"mcp.tool"`` — tool dispatch (start / complete / error)
29+
//! - ``"mcp.live"``, ``"mcp.live.launch"`` — live-reload subsystem
30+
//! - ``"mcp.heap"`` — heap-collection ticks
31+
//!
32+
//! Filters apply at the most-specific dotted prefix:
33+
//! :func:`logger_set_category_level` ``("mcp.live", LOG_DEBUG)`` enables
34+
//! debug for ``"mcp.live"``, ``"mcp.live.launch"``, etc. — anything else
35+
//! stays at the global :func:`logger_set_min_level`.
36+
//!
37+
//! :func:`logger_install_hook` plugs a GLOBAL debug agent into the runtime
38+
//! so accidental ``print()`` / ``to_log()`` calls are diverted into the
39+
//! log file instead of stdout/stderr — important for stdio-transport
40+
//! processes (MCP server, language servers) where any stdout write
41+
//! corrupts the wire format. One install covers every Context including
42+
//! future ``new_thread`` workers.
43+
44+
require daslib/json public
45+
require daslib/fio public
46+
require strings
47+
require daslib/jsonrpc
48+
require daslib/debugger
49+
require daslib/rtti
50+
51+
// ── State (per-Context) ──────────────────────────────────────────────
52+
53+
var private log_file : FILE const? = null
54+
var private log_path : string
55+
var private log_name : string
56+
var private log_open_attempted = false
57+
var private log_open_failed = false
58+
var private log_min_level = LOG_INFO
59+
var private log_category_overrides : table<string; int>
60+
var private log_fallback_to_stderr = true
61+
62+
// ── Internal helpers ─────────────────────────────────────────────────
63+
64+
def private level_name(level : int) : string {
65+
return "critical" if (level >= LOG_CRITICAL)
66+
return "error" if (level >= LOG_ERROR)
67+
return "warning" if (level >= LOG_WARNING)
68+
return "info" if (level >= LOG_INFO)
69+
return "debug" if (level >= LOG_DEBUG)
70+
return "trace"
71+
}
72+
73+
// Resolve filter level for a category. Most-specific dotted prefix wins —
74+
// "mcp.live.foo" first looks up the full path, then "mcp.live", then "mcp",
75+
// before falling back to the global min level.
76+
def private resolve_level(category : string) : int {
77+
var probe = category
78+
while (true) {
79+
if (key_exists(log_category_overrides, probe)) return log_category_overrides[probe]
80+
let dot = probe |> rfind(".")
81+
break if (dot < 0)
82+
probe = probe |> slice(0, dot)
83+
}
84+
return log_min_level
85+
}
86+
87+
def private should_log(level : int; category : string) : bool {
88+
return level >= resolve_level(category)
89+
}
90+
91+
def private ensure_dir(path : string) {
92+
let dir = dir_name(path)
93+
return if (empty(dir))
94+
let st = stat(dir)
95+
return if (st.is_valid && st.is_dir)
96+
mkdir(dir)
97+
}
98+
99+
def private ensure_open() {
100+
return if (log_file != null || log_open_failed || empty(log_path))
101+
log_open_attempted = true
102+
ensure_dir(log_path)
103+
log_file = fopen(log_path, "ab")
104+
if (log_file == null) {
105+
log_open_failed = true
106+
}
107+
}
108+
109+
// JSON-encode the four fixed fields directly into the writer, then append
110+
// the optional `fields` object via daslib/json's public `write_json` (no
111+
// json_boost reflection — fast path).
112+
def private write_record(var w : StringBuilderWriter; ts, lvl, cat, msg : string; fields : JsonValue?) {
113+
w |> write("\{\"ts\":\"")
114+
write_escape_string(w, ts)
115+
w |> write("\",\"level\":\"")
116+
write_escape_string(w, lvl)
117+
w |> write("\",\"cat\":\"")
118+
write_escape_string(w, cat)
119+
w |> write("\",\"msg\":\"")
120+
write_escape_string(w, msg)
121+
if (fields != null) {
122+
w |> write("\",\"fields\":")
123+
// write_json always pretty-prints (depth=0 still inserts \n/\t between
124+
// elements). One JSON object per line is load-bearing for JSON Lines,
125+
// so flatten via the jsonrpc framing helper (preserves whitespace
126+
// inside string literals).
127+
w |> write(compact_json_whitespace(write_json(fields)))
128+
w |> write("}\n")
129+
} else {
130+
w |> write("\"}\n")
131+
}
132+
}
133+
134+
def private emit(level : int; category, message : string; fields : JsonValue?) {
135+
return if (!should_log(level, category))
136+
ensure_open()
137+
let line = build_string() $(var w) {
138+
write_record(w, iso8601_now(), level_name(level), category, message, fields)
139+
}
140+
if (log_file != null) {
141+
fwrite(log_file, line)
142+
fflush(log_file)
143+
return
144+
}
145+
// Open failed (or path never set). stderr is always safe — it isn't the
146+
// JSON-RPC channel for stdio-transport servers, so a tail fallback can't
147+
// corrupt protocol framing.
148+
if (log_fallback_to_stderr) {
149+
fwrite(fstderr(), line)
150+
}
151+
}
152+
153+
// ── Public configuration ─────────────────────────────────────────────
154+
//
155+
// All public names carry the ``logger_`` prefix on purpose. Short verbs
156+
// like ``flush`` / ``close`` / ``info`` / ``debug`` collide with user
157+
// code when callers ``require daslib/logger`` and reach for the
158+
// unqualified form. The prefix keeps the call sites readable
159+
// (``logger_info("foo", "bar")``) without forcing ``logger::`` everywhere.
160+
161+
def logger_set_name(name : string) {
162+
//! Configure the log file as ``{get_das_root()}/logs/<name>.log``.
163+
//! Re-opens if the path changes; closes the previous handle. Each
164+
//! Context tracks its own state — call once per context.
165+
let new_path = path_join(get_das_root(), "logs/{name}.log")
166+
logger_set_path(new_path)
167+
log_name = name
168+
}
169+
170+
def logger_set_path(path : string) {
171+
//! Override the log file path explicitly. Pass an absolute path or a
172+
//! path relative to the current working directory.
173+
if (path == log_path) return
174+
if (log_file != null) {
175+
fclose(log_file)
176+
log_file = null
177+
}
178+
log_path = path
179+
// Clear logical name so logger_get_name() matches the doc claim:
180+
// "empty if the path was set directly". logger_set_name() restores
181+
// log_name immediately after it calls us, so that path still works.
182+
log_name = ""
183+
log_open_attempted = false
184+
log_open_failed = false
185+
}
186+
187+
def logger_get_path() : string {
188+
//! Returns the currently configured log file path (empty if unset).
189+
return log_path
190+
}
191+
192+
def logger_get_name() : string {
193+
//! Returns the logical name passed to :func:`logger_set_name`
194+
//! (empty if the path was set directly via :func:`logger_set_path`).
195+
return log_name
196+
}
197+
198+
def logger_set_min_level(level : int) {
199+
//! Global minimum level. Records below this are dropped before
200+
//! formatting. Default ``LOG_INFO``.
201+
log_min_level = level
202+
}
203+
204+
def logger_get_min_level() : int {
205+
//! Returns the currently configured global minimum level.
206+
return log_min_level
207+
}
208+
209+
def logger_set_category_level(category : string; level : int) {
210+
//! Override the level filter for one category. Dotted prefix
211+
//! matching: an override on ``"mcp.live"`` applies to ``"mcp.live"``,
212+
//! ``"mcp.live.foo"``, ``"mcp.live.bar"`` (unless they have their own
213+
//! more specific override).
214+
log_category_overrides[category] = level
215+
}
216+
217+
def logger_clear_category_levels() {
218+
//! Remove all per-category overrides.
219+
log_category_overrides |> clear
220+
}
221+
222+
def logger_set_stderr_fallback(enabled : bool) {
223+
//! Enable / disable writing to stderr when the log file can't be
224+
//! opened. Defaults to true; set to false for strict stdio-transport
225+
//! servers that must NEVER write to either stream on file failure.
226+
log_fallback_to_stderr = enabled
227+
}
228+
229+
// ── Log calls ────────────────────────────────────────────────────────
230+
231+
def logger_log(level : int; category, message : string; fields : JsonValue? = null) {
232+
//! Generic log entry. Prefer the named-level helpers below.
233+
emit(level, category, message, fields)
234+
}
235+
236+
def logger_trace(category, message : string; fields : JsonValue? = null) {
237+
//! Verbose trace-level record. ``LOG_TRACE``.
238+
emit(LOG_TRACE, category, message, fields)
239+
}
240+
241+
def logger_debug(category, message : string; fields : JsonValue? = null) {
242+
//! Debug-level record. ``LOG_DEBUG``.
243+
emit(LOG_DEBUG, category, message, fields)
244+
}
245+
246+
def logger_info(category, message : string; fields : JsonValue? = null) {
247+
//! Informational record. ``LOG_INFO`` — the default level.
248+
emit(LOG_INFO, category, message, fields)
249+
}
250+
251+
def logger_warning(category, message : string; fields : JsonValue? = null) {
252+
//! Warning record. ``LOG_WARNING``.
253+
emit(LOG_WARNING, category, message, fields)
254+
}
255+
256+
def logger_error(category, message : string; fields : JsonValue? = null) {
257+
//! Error record. ``LOG_ERROR``.
258+
emit(LOG_ERROR, category, message, fields)
259+
}
260+
261+
def logger_critical(category, message : string; fields : JsonValue? = null) {
262+
//! Critical / fatal record. ``LOG_CRITICAL``.
263+
emit(LOG_CRITICAL, category, message, fields)
264+
}
265+
266+
// ── Lifecycle ────────────────────────────────────────────────────────
267+
268+
def logger_flush() {
269+
//! Explicit flush. Each write already flushes; only useful if you
270+
//! disable auto-flush in a fork.
271+
if (log_file != null) {
272+
fflush(log_file)
273+
}
274+
}
275+
276+
def logger_close() {
277+
//! Close the log file. Subsequent writes will lazy-reopen.
278+
if (log_file != null) {
279+
fclose(log_file)
280+
log_file = null
281+
}
282+
log_open_attempted = false
283+
log_open_failed = false
284+
}
285+
286+
// ── Debug-agent hook ─────────────────────────────────────────────────
287+
//
288+
// Intercepts ``Context::to_out`` (the underlying mechanism behind ``print``
289+
// and ``to_log``) and routes every message into the configured log file
290+
// instead of stdout/stderr. Critical for stdio-transport processes — MCP
291+
// servers, language servers, anything where stdout is the wire format.
292+
//
293+
// Registered as a GLOBAL debug agent (not thread-local) under the
294+
// ``"daslib_logger"`` category. One install covers every Context that
295+
// later spawns; ``new_thread`` workers don't need to re-install. The
296+
// agent's ``onLog`` is dispatched into its installing Context, which
297+
// owns the log file handle — cross-context invocations route writes
298+
// through that single handle.
299+
300+
let private LOGGER_AGENT_CATEGORY = "daslib_logger"
301+
302+
class private LogHookAgent : DapiDebugAgent {
303+
def override onLog(context : Context?; at : LineInfo const?; level : int; text : string#) : bool {
304+
// Fail-open when logging isn't configured — let the default
305+
// stdout/stderr path through instead of swallowing silently.
306+
// Makes accidental "hook before logger_set_name" calls harmless
307+
// rather than blackholing every print().
308+
if (empty(log_path) && !log_fallback_to_stderr) return false
309+
var fields : JsonValue? = null
310+
if (at != null && at.fileInfo != null) {
311+
fields = JV({"at" => JV("{at.fileInfo.name}:{at.line}")})
312+
}
313+
emit(level, "runtime", string(text), fields)
314+
return true
315+
}
316+
}
317+
318+
def logger_install_hook() {
319+
//! Install a global debug agent that diverts ``print`` and
320+
//! ``to_log`` (from any Context, current or future) into the
321+
//! configured log file. Idempotent — safe to call from every
322+
//! module's [init], from MCP main, etc. Worker threads spawned via
323+
//! ``new_thread`` inherit the hook automatically; no per-context
324+
//! re-install needed.
325+
return if (has_debug_agent_context(LOGGER_AGENT_CATEGORY))
326+
install_new_debug_agent(new LogHookAgent(), LOGGER_AGENT_CATEGORY)
327+
}
328+
329+
def logger_init(name : string) {
330+
//! Convenience: ``logger_set_name(name)`` + ``logger_install_hook()``.
331+
//! The common-case one-liner for tools that want both behaviors.
332+
logger_set_name(name)
333+
logger_install_hook()
334+
}

0 commit comments

Comments
 (0)