Repository navigation
feat(sync): write a backend's own log lines to the worker log - #44
Conversation
An MCP server that declares the `logging` capability sends its log as `notifications/message` on stdout. The stdio client read those lines and dropped them, because it only handled responses, so a backend's own account of a failure never reached the log. McpSession now hands each one to an `onLog` option. The level is mapped from MCP's eight onto debug/info/warn/error, `data` that is not a string is written as JSON, and the line is flattened to one line and capped at 2000 characters. A notification can arrive before the initialize reply. The provider passes the lines to a new optional `IndexRequest.log`, and the worker writes them as `[<provider>:<level>] message`, to the log file and to the terminal echo that `sync`, `drain` and `once` already print. Two related fixes to the read loop: a message that has a `method` is never taken as a response, whatever id it carries, and a bare JSON value such as `null` on stdout no longer throws out of the data handler.
|
Navigate logical layers of code changes, visualize relationships, and explore their blast radius. Warning Review limit reached
Reviews can continue after your included limit without a manual trigger. An admin must approve usage-based billing. Next included review available in 32 minutes. View limit detailsLimit details: You’ve used the included review currently available. Your 83 included PR review attempts over the past 7 days set your current allowance at 1 review per hour. Enable usage-based reviews in Billing to review now. Otherwise, wait until the next included review is available. Review configuration: ⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Advanced Run ID: 📒 Files selected for processing (1)
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Advanced Run ID: 📒 Files selected for processing (12)
Included review availability: 0 reviews are currently available. Your included PR review attempts over the past 7 days set your current allowance at 1 review per hour. 📝 WalkthroughWalkthroughMCP ChangesBackend Log Forwarding
Priority: ➖ Normal Estimated code review effort: 3 (Moderate) | ~20 minutes Change: Feature Sequence Diagram(s)sequenceDiagram
participant MCPBackend
participant McpSession
participant McpIndexProvider
participant Worker
participant CommandOutput
MCPBackend->>McpSession: notifications/message
McpSession->>McpIndexProvider: normalized log message
McpIndexProvider->>Worker: log line through IndexRequest.log
Worker->>CommandOutput: provider-and-level tagged entry
Merge Risk: ⚪ Minimal · up to Backend logs are forwarded during indexing, including messages sent before initialization. No actionable issue remains on the supplied evidence; the change is ready for normal merge checks. 🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✨ Finishing Touches 💡 1🛠️ Fix failing CI checks 💡
📝 Generate docstrings
🧪 Generate unit tests (beta)
Comment |
The shell dies before its server, so the server is re-parented and reaped by init on init's schedule. Until then its pid still answers `kill(pid, 0)`, and the test's last assertion failed on Linux runners now and then, on main as well as on branches. Poll for up to a second first, as the forwarding-launcher test beside it already does.
What was wrong
A backend that declares the MCP
loggingcapability sends its log asnotifications/messageon stdout.McpSession's read loop only handled messages with a numericid(responses) and dropped everything else, so those lines were read and thrown away. They include the lines that explain a failed sync: a storage error's reason, a warning about a file, how far indexing got. SocratiCode started sending every log line this way in 1.15.0, and it sends some of them before it answersinitialize.Two more problems in the same read loop:
idwas taken as a response, even one with amethod. A notification or server request carrying the id of a pending call resolved that call with an empty result. The tool then looked like it had succeeded with no text.null, threw out of thedatahandler. On currentmainthis is an uncaught exception (Cannot read properties of null (reading 'id')), checked below.What this does
mcp.ts: adds a newonLogoption toMcpClientOptions. Eachnotifications/messagegoes throughparseLogMessageinto{ level, logger?, text }:debug;info(andnotice);warn(warning);error(andcritical,alert,emergency). A level it does not recognise is logged asinfo. Dropping the line would lose it, and guessing a higher level would raise false alarms. Levels are matched case-insensitively.data. A string is kept as sent. Anything else is written withJSON.stringify. The result is flattened to one line, with line breaks becoming|, the same way the worker already flattens a parked error. It is capped at 2,000 characters with… [N more chars]at the end, and never cuts a surrogate pair in half.methodis never taken as a response. A bare JSON value is skipped. Other notifications and server requests are ignored, as before.provider.ts:IndexRequestgets an optionallog?: (line: BackendLogLine) => void, withBackendLogLevel = "debug" | "info" | "warn" | "error". Both types are exported. The field is optional, so existing custom providers still compile and behave as before.McpIndexProvider.indexpassesreq.logthrough to the session. The backend'sloggername goes in front of the message only when it differs from the provider'sname, since the label already shows the provider.worker.tswrites each line with the existingLogger.tag, as[<provider>:<level>] <message>. It therefore goes wherever the worker log already goes: the rotated log file always, and also stdout forsync,drainandonce, which already echo the log. That covers both a script that capturessync's output and the log a hook-drivendrainleaves behind.Example, from the end-to-end run below (the path is shortened):
Default verbosity: forward everything the backend sends
codeindex-sync has no verbosity setting.
Loggerhas no levels, and the CLI has no--verboseor--quiet. So nothing is filtered here, and nologging/setLevelis sent. The backend already filters by its own configured level (SocratiCode:SOCRATICODE_LOG_LEVEL, defaultinfo), and that setting already lives in the provider'senvblock. A second filter here would mean two settings that have to agree, and adebuglevel set on the backend would be dropped here without any sign. The docs now say how to quiet it (SOCRATICODE_LOG_LEVEL=warn) and point out that the log rotates at 2 MB, keeping one previous file.Scope
Only index runs, which are the worker path, carry
log.list,doctor,status,cleanupandclaimhave no worker log and still drop backend log lines. Routing those to the terminal would be a separate decision about interactive output.Docs
docs/extending.md: what happens to a backend's log (mapping, flattening, cap, no filtering), andreq.logfor custom providers.docs/socraticode.md: a troubleshooting entry for reading the[socraticode:…]lines and quieting them.README.md: one sentence in the "log is the diagnostic" bullet.CHANGELOG.mdis not touched, because release-please writes it.What I ran
npm run lint,npm run typecheck,npm run build,npm test: 444 passed, 4 skipped (the skipped ones are the Qdrant integration suite, which needs a live store). Baseline onmainwas 428 passed, 4 skipped.New tests:
test/mcp.test.ts, run against the existing stub server:initializereply is delivered, and the handshake still completes;data(object, number,null,false, array) and multi-line strings;null,42, a bare string and an array on stdout,notifications/messagewith no params, string params, array params, no data, or blank data, a notification carrying the pending call'sid, a server request with thatid, andnotifications/progress. The call still gets its real reply.onLog;parseLogMessageunit tests.test/provider-backend-log.test.ts: lines from start-up, the call and shutdown reachreq.log; the logger-name prefix rule; a failed run still carries the logged reason.test/worker.test.ts: lines land in the log file as[backend:info]and[backend:error], between[start]and[give-up].test/cli.test.ts:syncagainst a stub backend prints[stub:warn]and[stub:info]lines, including one sent beforeinitialize, to stdout and writes them tosync.log.Each guard disabled in turn, full suite run, then restored. What went red:
notifications/messagetoonLogmethodis never a responsecarries on answering calls…(expected '' to be 'ok')carries on answering calls…(TypeError: Cannot read properties of null (reading 'method'), call hung to timeout)try/catcharound the sinksurvives a log sink that throws(call hung to timeout)writes data that is not a string as JSON, on one line,keeps the logger's name, on one bounded linecaps an absurdly long line…,keeps the logger's name…,never cuts a character in halfnever cuts a character in halfcritical→errormaps MCP's eight levels onto debug, info, warn and errorlogs a line whose level it does not recognise as info…carries on answering calls…,is null for params that carry nothing to logdata→ no lineis null for params that carry nothing to loglogonLogThe
nullcrash on currentmain: I droveorigin/main'sMcpSessionagainst a stub that writesnullbefore its reply. Result:UNCAUGHT: Cannot read properties of null (reading 'id').End to end with real SocratiCode 1.15.0. I ran
codeindex-sync syncfrom a scratch HOME against the realsocraticodebinary, withQDRANT_MODE=externaland Qdrant and Ollama pointed at a closed loopback port, so nothing was written anywhere. I setEXTENSION_LANGUAGE_MAPto an invalid entry to get a real warning.main), stdout andsync.loghold only[start]and[give-up] … Cannot reach external Qdrant.[socraticode:warn] EXTENSION_LANGUAGE_MAP: …and[socraticode:info] Auto-resume: disabled …, both sent before theinitializereply. They also carryChecking external Qdrant …,Waiting for Qdrant to be ready …, and the two graceful-shutdown lines.onceanddrainprinted the same 7 lines.doctorprinted none.SOCRATICODE_LOG_LEVEL=warncut the stream down to the one warning, which the docs' advice relies on.What I could not verify
infolines a large reindex produces. From SocratiCode's source, it logs per changed file and per batch checkpoint atinfo, so a big reindex could use a noticeable share of the 2 MB log. The docs point toSOCRATICODE_LOG_LEVEL=warnfor that.Summary by CodeRabbit
sync,drain, andonce, with provider and severity labels.