diff --git a/known-issues.md b/known-issues.md index 0b148ee..f3a289a 100644 --- a/known-issues.md +++ b/known-issues.md @@ -27,27 +27,38 @@ Format per entry: ## KI-001 — No structured logging; all errors go to console.log -**File:** `src/index.ts` (and likely all tool handlers) -**Status:** Identified +**File:** `src/index.ts`, `src/api.ts` (and potentially all tool handlers) +**Status:** ✅ Resolved **Severity:** Medium -### Symptom -Tool handlers use `console.log` and `console.error` for output. Structured JSON -logs (for ingestion into Datadog, Grafana, or the platform's Langfuse traces) -are not emitted. MCP `INTERNAL_ERROR` responses include human-readable text -but no correlation ID or structured metadata. +### Resolution +Replaced all `console.log/error` calls with structured JSON logging via +[pino](https://getpino.io) (`src/utils/logger.ts`). The logger: -### Impact -Debugging production issues requires reading raw console output. Correlation IDs -from the platform request context are not attached to errors, making it hard to -trace a failing tool call back to a specific workspace or delegation in the -platform logs. +- Emits JSON by default (production); pretty-prints when `NODE_ENV != "production"` + or stdout is a TTY. +- Level is controlled by `LOG_LEVEL` env var (default: `30` = warn; set `20` for debug). +- Uses Node.js `AsyncLocalStorage` (`src/utils/context.ts`) to propagate + per-call context (`toolName`, `requestId`, `workspaceId`) into all downstream + log entries automatically — no need to thread context through every function. +- Errors include `{ message, stack, name }` in the `err` field. -### Suggested fix -Replace `console.log/error` with a structured logger (e.g. `pino` or -`winston` with JSON format). Attach `requestId` / `workspaceId` from the MCP -request context to every log entry. Ensure errors include a correlation ID -from the platform trace header (`X-Trace-ID` or similar). +Files changed: +- `package.json` — added `pino@^9.6.0`, `pino-pretty@^13.0.0` +- `src/utils/context.ts` — new; `AsyncLocalStorage` context + `getContext()`, `withContext()` +- `src/utils/logger.ts` — new; `info()`, `warn()`, `error()`, `debug()` helpers +- `src/api.ts` — both `console.error` → `logError(…)` +- `src/index.ts` — all `console.error` → `logInfo()`/`logWarn()`/`logError()` + +### What was NOT changed (follow-up) +Tool handlers that want to emit application-level log events (e.g. "installed +plugin X", "delegated to workspace Y") should import and call `info()`/`warn()` +directly. The `AsyncLocalStorage` context is already active during handler +execution so those calls automatically carry `toolName` etc. + +Correlation IDs from a platform trace header (`X-Trace-ID`) are not yet wired up — +the MCP SDK does not expose request headers to handlers. A follow-up will be needed +once the SDK supports header access or we adopt a middleware approach. --- diff --git a/package-lock.json b/package-lock.json index b5bec35..3cee7d7 100644 --- a/package-lock.json +++ b/package-lock.json @@ -9,6 +9,8 @@ "version": "1.0.0", "dependencies": { "@modelcontextprotocol/sdk": "^1.12.0", + "pino": "^9.6.0", + "pino-pretty": "^13.0.0", "zod": "^3.23.0" }, "bin": { @@ -1052,6 +1054,11 @@ "@tybys/wasm-util": "^0.10.0" } }, + "node_modules/@pinojs/redact": { + "version": "0.4.0", + "resolved": "https://registry.npmjs.org/@pinojs/redact/-/redact-0.4.0.tgz", + "integrity": "sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==" + }, "node_modules/@pkgjs/parseargs": { "version": "0.11.0", "resolved": "https://registry.npmjs.org/@pkgjs/parseargs/-/parseargs-0.11.0.tgz", @@ -1635,6 +1642,14 @@ "sprintf-js": "~1.0.2" } }, + "node_modules/atomic-sleep": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/atomic-sleep/-/atomic-sleep-1.0.0.tgz", + "integrity": "sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==", + "engines": { + "node": ">=8.0.0" + } + }, "node_modules/babel-jest": { "version": "30.3.0", "resolved": "https://registry.npmjs.org/babel-jest/-/babel-jest-30.3.0.tgz", @@ -2097,6 +2112,11 @@ "dev": true, "license": "MIT" }, + "node_modules/colorette": { + "version": "2.0.20", + "resolved": "https://registry.npmjs.org/colorette/-/colorette-2.0.20.tgz", + "integrity": "sha512-IfEDxwoWIjkeXL1eXcDiow4UbKjhLdq6/EuSVR9GMN7KVH3r9gQ83e73hsz1Nd1T3ijd5xv1wcWRYO+D6kCI2w==" + }, "node_modules/concat-map": { "version": "0.0.1", "resolved": "https://registry.npmjs.org/concat-map/-/concat-map-0.0.1.tgz", @@ -2182,6 +2202,14 @@ "node": ">= 8" } }, + "node_modules/dateformat": { + "version": "4.6.3", + "resolved": "https://registry.npmjs.org/dateformat/-/dateformat-4.6.3.tgz", + "integrity": "sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA==", + "engines": { + "node": "*" + } + }, "node_modules/debug": { "version": "4.4.3", "resolved": "https://registry.npmjs.org/debug/-/debug-4.4.3.tgz", @@ -2306,6 +2334,14 @@ "node": ">= 0.8" } }, + "node_modules/end-of-stream": { + "version": "1.4.5", + "resolved": "https://registry.npmjs.org/end-of-stream/-/end-of-stream-1.4.5.tgz", + "integrity": "sha512-ooEGc6HP26xXq/N+GCGOT0JKCLDGrq2bQUZrQ7gyrJiZANJ/8YDTxTpQBXGMn+WbIQXNVpyWymm7KYVICQnyOg==", + "dependencies": { + "once": "^1.4.0" + } + }, "node_modules/error-ex": { "version": "1.3.4", "resolved": "https://registry.npmjs.org/error-ex/-/error-ex-1.3.4.tgz", @@ -2536,6 +2572,11 @@ "express": ">= 4.11" } }, + "node_modules/fast-copy": { + "version": "4.0.3", + "resolved": "https://registry.npmjs.org/fast-copy/-/fast-copy-4.0.3.tgz", + "integrity": "sha512-58apWr0GUiDFM8+3afrO6eYwJBn9ZAhDOzG3L+/9llab/haCARS2UIfffmOurYLwbgDRs8n0rfr6qAAPEAuAQw==" + }, "node_modules/fast-deep-equal": { "version": "3.1.3", "resolved": "https://registry.npmjs.org/fast-deep-equal/-/fast-deep-equal-3.1.3.tgz", @@ -2549,6 +2590,11 @@ "dev": true, "license": "MIT" }, + "node_modules/fast-safe-stringify": { + "version": "2.1.1", + "resolved": "https://registry.npmjs.org/fast-safe-stringify/-/fast-safe-stringify-2.1.1.tgz", + "integrity": "sha512-W+KJc2dmILlPplD/H4K9l9LcAHAfPtP6BY84uVLXQ6Evcz9Lcg33Y2z1IVblT6xdY54PXYVHEv+0Wpq8Io6zkA==" + }, "node_modules/fast-uri": { "version": "3.1.0", "resolved": "https://registry.npmjs.org/fast-uri/-/fast-uri-3.1.0.tgz", @@ -2853,6 +2899,11 @@ "node": ">= 0.4" } }, + "node_modules/help-me": { + "version": "5.0.0", + "resolved": "https://registry.npmjs.org/help-me/-/help-me-5.0.0.tgz", + "integrity": "sha512-7xgomUX6ADmcYzFik0HzAxh/73YlKR9bmFzf51CZwR+b6YtzU2m0u49hQCqV6SvlqIqsaxovfwdvbnsw3b/zpg==" + }, "node_modules/hono": { "version": "4.12.10", "resolved": "https://registry.npmjs.org/hono/-/hono-4.12.10.tgz", @@ -3734,6 +3785,14 @@ "url": "https://github.com/sponsors/panva" } }, + "node_modules/joycon": { + "version": "3.1.1", + "resolved": "https://registry.npmjs.org/joycon/-/joycon-3.1.1.tgz", + "integrity": "sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw==", + "engines": { + "node": ">=10" + } + }, "node_modules/js-tokens": { "version": "4.0.0", "resolved": "https://registry.npmjs.org/js-tokens/-/js-tokens-4.0.0.tgz", @@ -3985,7 +4044,6 @@ "version": "1.2.8", "resolved": "https://registry.npmjs.org/minimist/-/minimist-1.2.8.tgz", "integrity": "sha512-2yyAR8qBkN3YuheJanUpWC5U3bb5osDywNB8RzDVlDwDHbocAJveqqj1u8+SVD7jkWT4yvsHCpWqqWqAxb0zCA==", - "dev": true, "license": "MIT", "funding": { "url": "https://github.com/sponsors/ljharb" @@ -4104,6 +4162,14 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/on-exit-leak-free": { + "version": "2.1.2", + "resolved": "https://registry.npmjs.org/on-exit-leak-free/-/on-exit-leak-free-2.1.2.tgz", + "integrity": "sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA==", + "engines": { + "node": ">=14.0.0" + } + }, "node_modules/on-finished": { "version": "2.4.1", "resolved": "https://registry.npmjs.org/on-finished/-/on-finished-2.4.1.tgz", @@ -4314,6 +4380,82 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "node_modules/pino": { + "version": "9.14.0", + "resolved": "https://registry.npmjs.org/pino/-/pino-9.14.0.tgz", + "integrity": "sha512-8OEwKp5juEvb/MjpIc4hjqfgCNysrS94RIOMXYvpYCdm/jglrKEiAYmiumbmGhCvs+IcInsphYDFwqrjr7398w==", + "dependencies": { + "@pinojs/redact": "^0.4.0", + "atomic-sleep": "^1.0.0", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^2.0.0", + "pino-std-serializers": "^7.0.0", + "process-warning": "^5.0.0", + "quick-format-unescaped": "^4.0.3", + "real-require": "^0.2.0", + "safe-stable-stringify": "^2.3.1", + "sonic-boom": "^4.0.1", + "thread-stream": "^3.0.0" + }, + "bin": { + "pino": "bin.js" + } + }, + "node_modules/pino-abstract-transport": { + "version": "2.0.0", + "resolved": "https://registry.npmjs.org/pino-abstract-transport/-/pino-abstract-transport-2.0.0.tgz", + "integrity": "sha512-F63x5tizV6WCh4R6RHyi2Ml+M70DNRXt/+HANowMflpgGFMAym/VKm6G7ZOQRjqN7XbGxK1Lg9t6ZrtzOaivMw==", + "dependencies": { + "split2": "^4.0.0" + } + }, + "node_modules/pino-pretty": { + "version": "13.1.3", + "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-13.1.3.tgz", + "integrity": "sha512-ttXRkkOz6WWC95KeY9+xxWL6AtImwbyMHrL1mSwqwW9u+vLp/WIElvHvCSDg0xO/Dzrggz1zv3rN5ovTRVowKg==", + "dependencies": { + "colorette": "^2.0.7", + "dateformat": "^4.6.3", + "fast-copy": "^4.0.0", + "fast-safe-stringify": "^2.1.1", + "help-me": "^5.0.0", + "joycon": "^3.1.1", + "minimist": "^1.2.6", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^3.0.0", + "pump": "^3.0.0", + "secure-json-parse": "^4.0.0", + "sonic-boom": "^4.0.1", + "strip-json-comments": "^5.0.2" + }, + "bin": { + "pino-pretty": "bin.js" + } + }, + "node_modules/pino-pretty/node_modules/pino-abstract-transport": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/pino-abstract-transport/-/pino-abstract-transport-3.0.0.tgz", + "integrity": "sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==", + "dependencies": { + "split2": "^4.0.0" + } + }, + "node_modules/pino-pretty/node_modules/strip-json-comments": { + "version": "5.0.3", + "resolved": "https://registry.npmjs.org/strip-json-comments/-/strip-json-comments-5.0.3.tgz", + "integrity": "sha512-1tB5mhVo7U+ETBKNf92xT4hrQa3pm0MZ0PQvuDnWgAAGHDsfp4lPSpiS6psrSiet87wyGPh9ft6wmhOMQ0hDiw==", + "engines": { + "node": ">=14.16" + }, + "funding": { + "url": "https://github.com/sponsors/sindresorhus" + } + }, + "node_modules/pino-std-serializers": { + "version": "7.1.0", + "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-7.1.0.tgz", + "integrity": "sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw==" + }, "node_modules/pirates": { "version": "4.0.7", "resolved": "https://registry.npmjs.org/pirates/-/pirates-4.0.7.tgz", @@ -4374,6 +4516,21 @@ "url": "https://github.com/chalk/ansi-styles?sponsor=1" } }, + "node_modules/process-warning": { + "version": "5.0.0", + "resolved": "https://registry.npmjs.org/process-warning/-/process-warning-5.0.0.tgz", + "integrity": "sha512-a39t9ApHNx2L4+HBnQKqxxHNs1r7KF+Intd8Q/g1bUh6q0WIp9voPXJ/x0j+ZL45KF1pJd9+q2jLIRMfvEshkA==", + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ] + }, "node_modules/proxy-addr": { "version": "2.0.7", "resolved": "https://registry.npmjs.org/proxy-addr/-/proxy-addr-2.0.7.tgz", @@ -4387,6 +4544,15 @@ "node": ">= 0.10" } }, + "node_modules/pump": { + "version": "3.0.4", + "resolved": "https://registry.npmjs.org/pump/-/pump-3.0.4.tgz", + "integrity": "sha512-VS7sjc6KR7e1ukRFhQSY5LM2uBWAUPiOPa/A3mkKmiMwSmRFUITt0xuj+/lesgnCv+dPIEYlkzrcyXgquIHMcA==", + "dependencies": { + "end-of-stream": "^1.1.0", + "once": "^1.3.1" + } + }, "node_modules/pure-rand": { "version": "7.0.1", "resolved": "https://registry.npmjs.org/pure-rand/-/pure-rand-7.0.1.tgz", @@ -4419,6 +4585,11 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/quick-format-unescaped": { + "version": "4.0.4", + "resolved": "https://registry.npmjs.org/quick-format-unescaped/-/quick-format-unescaped-4.0.4.tgz", + "integrity": "sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==" + }, "node_modules/range-parser": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/range-parser/-/range-parser-1.2.1.tgz", @@ -4450,6 +4621,14 @@ "dev": true, "license": "MIT" }, + "node_modules/real-require": { + "version": "0.2.0", + "resolved": "https://registry.npmjs.org/real-require/-/real-require-0.2.0.tgz", + "integrity": "sha512-57frrGM/OCTLqLOAh0mhVA9VBMHd+9U7Zb2THMGdBUoZVOtGbJzjxsYGDJ3A9AYYCP4hn6y1TVbaOfzWtm5GFg==", + "engines": { + "node": ">= 12.13.0" + } + }, "node_modules/require-directory": { "version": "2.1.1", "resolved": "https://registry.npmjs.org/require-directory/-/require-directory-2.1.1.tgz", @@ -4508,12 +4687,35 @@ "node": ">= 18" } }, + "node_modules/safe-stable-stringify": { + "version": "2.5.0", + "resolved": "https://registry.npmjs.org/safe-stable-stringify/-/safe-stable-stringify-2.5.0.tgz", + "integrity": "sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==", + "engines": { + "node": ">=10" + } + }, "node_modules/safer-buffer": { "version": "2.1.2", "resolved": "https://registry.npmjs.org/safer-buffer/-/safer-buffer-2.1.2.tgz", "integrity": "sha512-YZo3K82SD7Riyi0E1EQPojLz7kpepnSQI9IyPbHHg1XXXevb5dJI7tpyN2ADxGcQbHG7vcyRHk0cbwqcQriUtg==", "license": "MIT" }, + "node_modules/secure-json-parse": { + "version": "4.1.0", + "resolved": "https://registry.npmjs.org/secure-json-parse/-/secure-json-parse-4.1.0.tgz", + "integrity": "sha512-l4KnYfEyqYJxDwlNVyRfO2E4NTHfMKAWdUuA8J0yve2Dz/E/PdBepY03RvyJpssIpRFwJoCD55wA+mEDs6ByWA==", + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ] + }, "node_modules/semver": { "version": "6.3.1", "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.1.tgz", @@ -4691,6 +4893,14 @@ "node": ">=8" } }, + "node_modules/sonic-boom": { + "version": "4.2.1", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-4.2.1.tgz", + "integrity": "sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, "node_modules/source-map": { "version": "0.6.1", "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.6.1.tgz", @@ -4712,6 +4922,14 @@ "source-map": "^0.6.0" } }, + "node_modules/split2": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/split2/-/split2-4.2.0.tgz", + "integrity": "sha512-UcjcJOWknrNkF6PLX83qcHM6KHgVKNkV62Y8a5uYDVv9ydGQVwAHMKqHdJje1VTWpljG0WYpCDhrCdAOYH4TWg==", + "engines": { + "node": ">= 10.x" + } + }, "node_modules/sprintf-js": { "version": "1.0.3", "resolved": "https://registry.npmjs.org/sprintf-js/-/sprintf-js-1.0.3.tgz", @@ -5005,6 +5223,14 @@ "node": "*" } }, + "node_modules/thread-stream": { + "version": "3.1.0", + "resolved": "https://registry.npmjs.org/thread-stream/-/thread-stream-3.1.0.tgz", + "integrity": "sha512-OqyPZ9u96VohAyMfJykzmivOrY2wfMSf3C5TtFJVgN+Hm6aj+voFhlK+kZEIv2FBh1X6Xp3DlnCOfEQ3B2J86A==", + "dependencies": { + "real-require": "^0.2.0" + } + }, "node_modules/tmpl": { "version": "1.0.5", "resolved": "https://registry.npmjs.org/tmpl/-/tmpl-1.0.5.tgz", diff --git a/package.json b/package.json index ea13760..d07d3c6 100644 --- a/package.json +++ b/package.json @@ -13,6 +13,8 @@ }, "dependencies": { "@modelcontextprotocol/sdk": "^1.12.0", + "pino": "^9.6.0", + "pino-pretty": "^13.0.0", "zod": "^3.23.0" }, "devDependencies": { diff --git a/src/api.ts b/src/api.ts index 2d31921..725873a 100644 --- a/src/api.ts +++ b/src/api.ts @@ -12,6 +12,8 @@ export const PLATFORM_URL = * Shape returned by apiCall when the request fails (network error, non-2xx, * or non-JSON body with no error). Returned-by-value — apiCall never throws. */ +import { error as logError } from "./utils/logger.js"; + export type ApiError = { error: string; detail?: string; raw?: string; status?: number }; export function isApiError(v: unknown): v is ApiError { @@ -59,8 +61,7 @@ export async function apiCall( } } catch (err) { const msg = err instanceof Error ? err.message : String(err); - // stdio MCP servers must log to stderr; stdout is the protocol channel. - console.error(`Molecule AI API error (${method} ${path}): ${msg}`); + logError(err, `Molecule AI API error (${method} ${path})`, { platformUrl: PLATFORM_URL }); return { error: `Platform unreachable at ${PLATFORM_URL}`, detail: msg }; } } @@ -129,7 +130,7 @@ export async function platformGet( } } catch (err) { const msg = err instanceof Error ? err.message : String(err); - console.error(`Molecule AI API error (GET ${path}): ${msg}`); + logError(err, `Molecule AI API error (GET ${path})`, { platformUrl: PLATFORM_URL }); return { error: `Platform unreachable at ${PLATFORM_URL}`, detail: msg }; } } diff --git a/src/index.ts b/src/index.ts index 297ed56..4f7380c 100644 --- a/src/index.ts +++ b/src/index.ts @@ -13,6 +13,7 @@ import { McpServer } from "@modelcontextprotocol/sdk/server/mcp.js"; import { StdioServerTransport } from "@modelcontextprotocol/sdk/server/stdio.js"; import { PLATFORM_URL, apiCall } from "./api.js"; +import { info as logInfo, warn as logWarn, error as logError } from "./utils/logger.js"; import { registerWorkspaceTools } from "./tools/workspaces.js"; import { registerAgentTools } from "./tools/agents.js"; import { registerSecretTools } from "./tools/secrets.js"; @@ -195,22 +196,27 @@ async function main() { try { const res = await fetch(`${PLATFORM_URL}/health`); if (res.ok) { - console.error(`Molecule AI platform connected: ${PLATFORM_URL}`); + logInfo("Molecule AI platform connected", { platformUrl: PLATFORM_URL }); } else { - console.error(`WARNING: Molecule AI platform at ${PLATFORM_URL} returned ${res.status}. Tools may fail.`); + logWarn(`Molecule AI platform at ${PLATFORM_URL} returned ${res.status}. Tools may fail.`, { + platformUrl: PLATFORM_URL, + status: res.status, + }); } - } catch { - console.error(`WARNING: Cannot reach Molecule AI platform at ${PLATFORM_URL}. Start it with: cd platform && go run ./cmd/server`); + } catch (err) { + logWarn(`Cannot reach Molecule AI platform at ${PLATFORM_URL}. Start it with: cd platform && go run ./cmd/server`, { + platformUrl: PLATFORM_URL, + }); } const server = createServer(); const transport = new StdioServerTransport(); await server.connect(transport); - console.error("Molecule AI MCP server running on stdio (87 tools available)"); + logInfo("Molecule AI MCP server running on stdio (87 tools available)", { transport: "stdio", toolCount: 87 }); } // Only auto-start when run directly (not when imported for testing). // JEST_WORKER_ID is set automatically by Jest in every worker process. if (!process.env.JEST_WORKER_ID) { - main().catch(console.error); + main().catch((err) => logError(err, "MCP server main() threw unexpectedly")); } diff --git a/src/utils/context.ts b/src/utils/context.ts new file mode 100644 index 0000000..a4243fb --- /dev/null +++ b/src/utils/context.ts @@ -0,0 +1,78 @@ +/** + * AsyncLocalStorage context for structured logging. + * + * Each MCP tool call runs in an isolated AsyncLocalStorage slot. The slot is + * populated at the start of the handler (before any business logic runs) with + * whatever context fields are available from the MCP request: + * + * - toolName — the tool being called + * - requestId — the JSON-RPC request id (if present) + * - workspaceId — X-Workspace-ID header value (if present) + * + * Any downstream code (apiCall, platformGet, tool helpers) that calls + * `getContext()` automatically picks up the current call's fields without + * needing them threaded through every function signature. + * + * Example: + * import { getContext, withContext } from "./context.js"; + * + * // In a tool handler: + * const ctx = getContext(); + * ctx.toolName; // "list_workspaces" + * + * // When launching an async operation: + * await withContext({ taskId: "abc123" }, async () => { + * await doSomething(); + * }); + */ + +import { AsyncLocalStorage } from "async_hooks"; + +/** Fields that are available in every MCP tool-call context. */ +export interface RequestContext { + toolName?: string; + requestId?: string; + workspaceId?: string; + /** Extra fields merged in via withContext(). */ + [key: string]: string | undefined; +} + +/** The AsyncLocalStorage slot — package-private. */ +const _als = new AsyncLocalStorage(); + +/** + * Get the current request context, or an empty object if called outside any + * AsyncLocalStorage scope (e.g. module-level init, health-check, etc.). + */ +export function getContext(): RequestContext { + return _als.getStore() ?? {}; +} + +/** + * Run `fn` inside a context that inherits the current AsyncLocalStorage slot + * plus any additional fields passed in `extra`. This is the primary way to + * propagate context into background tasks, setTimeout callbacks, etc. + * + * @example + * await withContext({ taskId: "abc" }, () => sendHeartbeat()); + */ +export function withContext( + extra: Partial, + fn: () => R, +): R { + const parent = getContext(); + const merged = { ...parent, ...extra }; + return _als.run(merged, fn); +} + +/** + * Run `fn` inside a fresh context that starts from `initial` (no inherited + * fields). Use this at the top of a request/handler to establish a clean + * slate. + */ +export function runWithContext( + initial: RequestContext, + fn: () => R, +): R { + return _als.run(initial, fn); +} diff --git a/src/utils/logger.ts b/src/utils/logger.ts new file mode 100644 index 0000000..88e3944 --- /dev/null +++ b/src/utils/logger.ts @@ -0,0 +1,102 @@ +/** + * Structured logger for the Molecule AI MCP server. + * + * All log output is JSON (machine-parseable). During development / when + * NODE_ENV !== "production" the output is pretty-printed so humans can read it. + * + * Every log entry includes: + * - level — numeric pino level (30 = warn, 50 = error) + * - time — ISO-8601 timestamp + * - pid — process ID + * - hostname — machine hostname + * - msg — human-readable message + * - err — (on error entries) error object with message + stack + * + * Plus whatever fields are passed as additional arguments, e.g.: + * log.warn({ workspaceId: "ws_123", tool: "list_workspaces" }, "rate limit hit") + * + * The MCP request context from src/utils/context.ts is automatically attached + * to every entry when inside a tool-call scope (toolName, requestId, workspaceId). + */ + +import { getContext } from "./context.js"; + +/** Logger instance returned by pino(). */ +type PinoLogger = { + info: (bindings: Record, msg: string) => void; + warn: (bindings: Record, msg: string) => void; + error: (bindings: Record, msg: string) => void; + debug: (bindings: Record, msg: string) => void; +}; + +// Lazy singleton — created on first log call so tests that mock console run +// before the first actual log invocation. +let _logger: PinoLogger | null = null; + +function logger(): PinoLogger { + if (!_logger) { + // eslint-disable-next-line @typescript-eslint/no-var-requires + // eslint-disable-next-line @typescript-eslint/no-explicit-any + const pino = require("pino") as any; + _logger = pino({ + // Level 30 (warn) and above; quiet by default so MCP protocol traffic + // is not logged (only application-level events). + level: Number(process.env["LOG_LEVEL"] ?? 30), + // Pretty-print when run interactively (TTY) or when explicitly requested. + transport: + process.env["NODE_ENV"] !== "production" || process.stdout.isTTY + ? { target: "pino-pretty", options: { colorize: true } } + : undefined, + base: { + // Strip the pid and hostname fields that pino adds by default — they + // are noise for a containerised MCP server. + pid: undefined, + hostname: undefined, + }, + // Do not redact anything by default; the platform handles secrets. + redact: [], + }); + } + return _logger!; +} + +// --------------------------------------------------------------------------- +// Public helpers +// --------------------------------------------------------------------------- + +/** + * Emit an INFO-level structured log. + * Automatically includes the current AsyncLocalStorage context fields. + */ +export function info(msg: string, extra: Record = {}): void { + logger().info({ ...getContext(), ...extra }, msg); +} + +/** + * Emit a WARN-level structured log. Use for expected-but-worthy conditions: + * rate-limited API calls, skipped optional steps, deprecation notices. + */ +export function warn(msg: string, extra: Record = {}): void { + logger().warn({ ...getContext(), ...extra }, msg); +} + +/** + * Emit an ERROR-level structured log. Includes the Error object as `err`. + * MCP handlers must NOT use this for user-facing errors (return a structured + * MCP error response instead); this is for internal failures that operators + * need to correlate in logs. + */ +export function error(err: unknown, msg: string, extra: Record = {}): void { + const e = + err instanceof Error + ? { message: err.message, stack: err.stack, name: err.name } + : { message: String(err) }; + logger().error({ ...getContext(), ...extra, err: e }, msg); +} + +/** + * Emit a DEBUG-level structured log. Only emitted when LOG_LEVEL=20. + */ +export function debug(msg: string, extra: Record = {}): void { + logger().debug({ ...getContext(), ...extra }, msg); +}