From b8f056060fb02651def2d22ca92e5a405228950d Mon Sep 17 00:00:00 2001 From: Mohamed Boudra Date: Thu, 15 Jan 2026 17:16:01 +0700 Subject: [PATCH] feat(server): migrate all logging to pino - Add pino with pino-pretty for structured logging - Create root logger in index.ts with child loggers per module - Support log level via PASEO_LOG env var and config.json - Support log format (pretty/json) via PASEO_LOG_FORMAT and config.json - Replace all console.* in runtime code with appropriate log levels - Scripts use process.stdout/stderr for output - Error logging uses correct pattern: logger.error({ err }, msg) --- package-lock.json | 238 ++++++- packages/server/package.json | 2 + packages/server/scripts/dev-runner.ts | 8 +- .../server/scripts/process-conversation.ts | 12 +- .../server/scripts/test-codex-mcp-agents.ts | 15 +- .../scripts/test-codex-mcp-basic-auth.ts | 15 +- .../server/scripts/test-codex-mcp-bearer.ts | 15 +- .../scripts/test-codex-mcp-http-headers.ts | 15 +- .../server/scripts/test-codex-mcp-http.ts | 15 +- .../server/scripts/test-codex-mcp-servers.ts | 23 +- .../server/scripts/verify-codex-mcp-config.ts | 8 +- .../server/src/client/daemon-client-v2.ts | 5 +- .../src/poc-commands/commands-poc.test.ts | 9 - .../investigate-command-output.ts | 54 +- packages/server/src/poc-commands/run-poc.ts | 48 +- .../server/src/server/agent/agent-manager.ts | 27 +- .../src/server/agent/agent-mcp.e2e.test.ts | 2 +- .../server/src/server/agent/agent-registry.ts | 11 +- .../server/src/server/agent/mcp-server.ts | 50 +- .../server/src/server/agent/model-resolver.ts | 9 +- .../agent/opencode-reasoning.e2e.test.ts | 33 +- .../claude-agent-commands.e2e.test.ts | 1 - .../providers/claude-agent-commands.test.ts | 14 - .../agent/providers/claude-agent.test.ts | 5 +- .../server/agent/providers/claude-agent.ts | 13 +- .../providers/claude-sdk-behavior.test.ts | 30 - .../server/agent/providers/codex-mcp-agent.ts | 18 +- .../server/agent/providers/opencode-agent.ts | 5 +- packages/server/src/server/agent/stt-debug.ts | 5 +- .../server/src/server/agent/stt-manager.ts | 26 +- .../server/src/server/agent/stt-openai.ts | 39 +- .../server/src/server/agent/tts-manager.ts | 56 +- .../server/src/server/agent/tts-openai.ts | 19 +- .../server/agent/wait-for-agent-tracker.ts | 10 +- packages/server/src/server/bootstrap.ts | 72 ++- packages/server/src/server/daemon.e2e.test.ts | 155 ++--- packages/server/src/server/index.ts | 22 +- packages/server/src/server/logger.test.ts | 109 ++++ packages/server/src/server/logger.ts | 62 ++ .../server/src/server/persisted-config.ts | 26 +- .../server/src/server/persistence-hooks.ts | 5 +- packages/server/src/server/persistence.ts | 39 +- .../server/src/server/push/push-service.ts | 16 +- .../server/src/server/push/token-store.ts | 8 +- packages/server/src/server/session.ts | 582 +++++++++--------- .../server/src/server/websocket-server.ts | 84 ++- .../src/services/agent-title-generator.ts | 11 +- packages/server/src/tasks/cli.ts | 116 ++-- 48 files changed, 1275 insertions(+), 887 deletions(-) create mode 100644 packages/server/src/server/logger.test.ts create mode 100644 packages/server/src/server/logger.ts diff --git a/package-lock.json b/package-lock.json index 250c955c3..42e127cc8 100644 --- a/package-lock.json +++ b/package-lock.json @@ -6335,6 +6335,12 @@ "resolved": "packages/website", "link": true }, + "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==", + "license": "MIT" + }, "node_modules/@pkgjs/parseargs": { "version": "0.11.0", "resolved": "https://registry.npmjs.org/@pkgjs/parseargs/-/parseargs-0.11.0.tgz", @@ -10053,6 +10059,15 @@ "node": ">= 4.0.0" } }, + "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==", + "license": "MIT", + "engines": { + "node": ">=8.0.0" + } + }, "node_modules/available-typed-arrays": { "version": "1.0.7", "resolved": "https://registry.npmjs.org/available-typed-arrays/-/available-typed-arrays-1.0.7.tgz", @@ -11069,6 +11084,12 @@ "simple-swizzle": "^0.2.2" } }, + "node_modules/colorette": { + "version": "2.0.20", + "resolved": "https://registry.npmjs.org/colorette/-/colorette-2.0.20.tgz", + "integrity": "sha512-IfEDxwoWIjkeXL1eXcDiow4UbKjhLdq6/EuSVR9GMN7KVH3r9gQ83e73hsz1Nd1T3ijd5xv1wcWRYO+D6kCI2w==", + "license": "MIT" + }, "node_modules/colorjs.io": { "version": "0.6.0-alpha.1", "resolved": "https://registry.npmjs.org/colorjs.io/-/colorjs.io-0.6.0-alpha.1.tgz", @@ -11487,7 +11508,6 @@ "version": "4.6.3", "resolved": "https://registry.npmjs.org/dateformat/-/dateformat-4.6.3.tgz", "integrity": "sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA==", - "dev": true, "license": "MIT", "engines": { "node": "*" @@ -12390,6 +12410,15 @@ "node": ">=0.10.0" } }, + "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==", + "license": "MIT", + "dependencies": { + "once": "^1.4.0" + } + }, "node_modules/enhanced-resolve": { "version": "5.18.4", "resolved": "https://registry.npmjs.org/enhanced-resolve/-/enhanced-resolve-5.18.4.tgz", @@ -14207,6 +14236,12 @@ "integrity": "sha512-LmDxfWXwcTArk8fUEnOfSZpHOJ6zOMUJKOtFLFqJLoKJetuQG874Uc7/Kki7zFLzYybmZhp1M7+98pfMqeX8yA==", "license": "MIT" }, + "node_modules/fast-copy": { + "version": "4.0.2", + "resolved": "https://registry.npmjs.org/fast-copy/-/fast-copy-4.0.2.tgz", + "integrity": "sha512-ybA6PDXIXOXivLJK/z9e+Otk7ve13I4ckBvGO5I2RRmBU1gMHLVDJYEuJYhGwez7YNlYji2M2DvVU+a9mSFDlw==", + "license": "MIT" + }, "node_modules/fast-deep-equal": { "version": "3.1.3", "resolved": "https://registry.npmjs.org/fast-deep-equal/-/fast-deep-equal-3.1.3.tgz", @@ -14263,6 +14298,12 @@ "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==", + "license": "MIT" + }, "node_modules/fast-uri": { "version": "3.1.0", "resolved": "https://registry.npmjs.org/fast-uri/-/fast-uri-3.1.0.tgz", @@ -15188,6 +15229,12 @@ "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==", + "license": "MIT" + }, "node_modules/hermes-estree": { "version": "0.29.1", "resolved": "https://registry.npmjs.org/hermes-estree/-/hermes-estree-0.29.1.tgz", @@ -16387,6 +16434,15 @@ "dev": true, "license": "MIT" }, + "node_modules/joycon": { + "version": "3.1.1", + "resolved": "https://registry.npmjs.org/joycon/-/joycon-3.1.1.tgz", + "integrity": "sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw==", + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/js-tokens": { "version": "4.0.0", "resolved": "https://registry.npmjs.org/js-tokens/-/js-tokens-4.0.0.tgz", @@ -18299,6 +18355,15 @@ "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==", + "license": "MIT", + "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", @@ -18818,6 +18883,79 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "node_modules/pino": { + "version": "10.2.0", + "resolved": "https://registry.npmjs.org/pino/-/pino-10.2.0.tgz", + "integrity": "sha512-NFnZqUliT+OHkRXVSf8vdOr13N1wv31hRryVjqbreVh/SDCNaI6mnRDDq89HVRCbem1SAl7yj04OANeqP0nT6A==", + "license": "MIT", + "dependencies": { + "@pinojs/redact": "^0.4.0", + "atomic-sleep": "^1.0.0", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^3.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": "^4.0.0" + }, + "bin": { + "pino": "bin.js" + } + }, + "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==", + "license": "MIT", + "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==", + "license": "MIT", + "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/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==", + "license": "MIT", + "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==", + "license": "MIT" + }, "node_modules/pirates": { "version": "4.0.7", "resolved": "https://registry.npmjs.org/pirates/-/pirates-4.0.7.tgz", @@ -19080,6 +19218,22 @@ "node": "^14.17.0 || ^16.13.0 || >=18.0.0" } }, + "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" + } + ], + "license": "MIT" + }, "node_modules/progress": { "version": "2.0.3", "resolved": "https://registry.npmjs.org/progress/-/progress-2.0.3.tgz", @@ -19162,6 +19316,16 @@ "node": ">= 0.10" } }, + "node_modules/pump": { + "version": "3.0.3", + "resolved": "https://registry.npmjs.org/pump/-/pump-3.0.3.tgz", + "integrity": "sha512-todwxLMY7/heScKmntwQG8CXVkWUOdYxIvY2s0VWAAMh/nd8SoYiRaKjlr7+iCs984f2P8zvrfWcDDYVb73NfA==", + "license": "MIT", + "dependencies": { + "end-of-stream": "^1.1.0", + "once": "^1.3.1" + } + }, "node_modules/punycode": { "version": "2.3.1", "resolved": "https://registry.npmjs.org/punycode/-/punycode-2.3.1.tgz", @@ -19243,6 +19407,12 @@ ], "license": "MIT" }, + "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==", + "license": "MIT" + }, "node_modules/range-parser": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/range-parser/-/range-parser-1.2.1.tgz", @@ -19917,6 +20087,15 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "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==", + "license": "MIT", + "engines": { + "node": ">= 12.13.0" + } + }, "node_modules/recast": { "version": "0.23.11", "resolved": "https://registry.npmjs.org/recast/-/recast-0.23.11.tgz", @@ -20447,6 +20626,15 @@ "url": "https://github.com/sponsors/ljharb" } }, + "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==", + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/safer-buffer": { "version": "2.1.2", "resolved": "https://registry.npmjs.org/safer-buffer/-/safer-buffer-2.1.2.tgz", @@ -20465,6 +20653,22 @@ "integrity": "sha512-NlHwttCI/l5gCPR3D1nNXtWABUmBwvZpEQiD4IXSbIDq8BzLIK/7Ir5gTFSGZDUu37K5cMNp0hFtzO38sC7gWA==", "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" + } + ], + "license": "BSD-3-Clause" + }, "node_modules/semver": { "version": "6.3.1", "resolved": "https://registry.npmjs.org/semver/-/semver-6.3.1.tgz", @@ -21281,6 +21485,15 @@ "node": ">=8.0.0" } }, + "node_modules/sonic-boom": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-4.2.0.tgz", + "integrity": "sha512-INb7TM37/mAcsGmc9hyyI6+QR3rR1zVRu36B0NeGXKnOOLiZOfER5SA+N7X7k3yUYRzLWafduTDvJAfDswwEww==", + "license": "MIT", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, "node_modules/source-map": { "version": "0.5.7", "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.5.7.tgz", @@ -21340,6 +21553,15 @@ "node": ">=6" } }, + "node_modules/split2": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/split2/-/split2-4.2.0.tgz", + "integrity": "sha512-UcjcJOWknrNkF6PLX83qcHM6KHgVKNkV62Y8a5uYDVv9ydGQVwAHMKqHdJje1VTWpljG0WYpCDhrCdAOYH4TWg==", + "license": "ISC", + "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", @@ -22017,6 +22239,18 @@ "node": ">=14.15.0" } }, + "node_modules/thread-stream": { + "version": "4.0.0", + "resolved": "https://registry.npmjs.org/thread-stream/-/thread-stream-4.0.0.tgz", + "integrity": "sha512-4iMVL6HAINXWf1ZKZjIPcz5wYaOdPhtO8ATvZ+Xqp3BTdaqtAwQkNmKORqcIo5YkQqGXq5cwfswDwMqqQNrpJA==", + "license": "MIT", + "dependencies": { + "real-require": "^0.2.0" + }, + "engines": { + "node": ">=20" + } + }, "node_modules/throat": { "version": "5.0.0", "resolved": "https://registry.npmjs.org/throat/-/throat-5.0.0.tgz", @@ -24453,6 +24687,8 @@ "express-basic-auth": "^1.2.1", "mnemonic-id": "^3.2.7", "openai": "^4.20.0", + "pino": "^10.2.0", + "pino-pretty": "^13.1.3", "playwright": "^1.56.1", "tiny-invariant": "^1.3.3", "uuid": "^9.0.1", diff --git a/packages/server/package.json b/packages/server/package.json index 482a9779f..ba4540299 100644 --- a/packages/server/package.json +++ b/packages/server/package.json @@ -39,6 +39,8 @@ "express-basic-auth": "^1.2.1", "mnemonic-id": "^3.2.7", "openai": "^4.20.0", + "pino": "^10.2.0", + "pino-pretty": "^13.1.3", "playwright": "^1.56.1", "tiny-invariant": "^1.3.3", "uuid": "^9.0.1", diff --git a/packages/server/scripts/dev-runner.ts b/packages/server/scripts/dev-runner.ts index 4ac81edf3..4cbf4ce9b 100644 --- a/packages/server/scripts/dev-runner.ts +++ b/packages/server/scripts/dev-runner.ts @@ -29,12 +29,12 @@ function spawnServer() { // Restart on: explicit restart request, or any non-zero exit (crash) if (restarting || (code !== 0 && code !== null)) { restarting = false; - console.warn(`[DevRunner] Server exited (${exitDescriptor}). Restarting...`); + process.stderr.write(`[DevRunner] Server exited (${exitDescriptor}). Restarting...\n`); spawnServer(); return; } - console.warn(`[DevRunner] Server exited (${exitDescriptor}). Shutting down.`); + process.stderr.write(`[DevRunner] Server exited (${exitDescriptor}). Shutting down.\n`); process.exit(0); }); } @@ -45,7 +45,7 @@ function restartServer() { } restarting = true; - console.warn("[DevRunner] Restart requested. Stopping current server..."); + process.stderr.write("[DevRunner] Restart requested. Stopping current server...\n"); child.kill("SIGTERM"); } @@ -59,5 +59,5 @@ function forwardSignal(signal: NodeJS.Signals) { process.on("SIGINT", () => forwardSignal("SIGINT")); process.on("SIGTERM", () => forwardSignal("SIGTERM")); -console.log("[DevRunner] Starting server with tsx (explicit restarts only)"); +process.stdout.write("[DevRunner] Starting server with tsx (explicit restarts only)\n"); spawnServer(); diff --git a/packages/server/scripts/process-conversation.ts b/packages/server/scripts/process-conversation.ts index 89261b7cb..b15859d85 100644 --- a/packages/server/scripts/process-conversation.ts +++ b/packages/server/scripts/process-conversation.ts @@ -7,24 +7,24 @@ async function processConversation() { const conversationPath = ".debug.conversations/ce44c79a-0689-4210-8e00-72c0a627406d-2.json"; - console.log("Loading conversation from:", conversationPath); + process.stdout.write(`Loading conversation from: ${conversationPath}\n`); const conversationData: any = JSON.parse( readFileSync(conversationPath, "utf-8") ); - console.log( - `\nLoaded conversation ${conversationData.conversationId} with ${conversationData.messages.length} messages\n` + process.stdout.write( + `\nLoaded conversation ${conversationData.conversationId} with ${conversationData.messages.length} messages\n\n` ); const result = await standardizePrompt({ prompt: conversationData.messages, }); - console.log("Standardized prompt result:"); - console.log(inspect(result, { depth: null, colors: true })); + process.stdout.write("Standardized prompt result:\n"); + process.stdout.write(inspect(result, { depth: null, colors: true }) + "\n"); } catch (error) { - console.error("Error processing conversation:", error); + process.stderr.write(`Error processing conversation: ${error}\n`); process.exit(1); } } diff --git a/packages/server/scripts/test-codex-mcp-agents.ts b/packages/server/scripts/test-codex-mcp-agents.ts index 7e267da3e..254d62665 100644 --- a/packages/server/scripts/test-codex-mcp-agents.ts +++ b/packages/server/scripts/test-codex-mcp-agents.ts @@ -30,7 +30,7 @@ async function main() { (data) => { const event = (data.params as { msg: unknown }).msg as { type?: string }; if (event.type === "mcp_startup_update" || event.type === "mcp_startup_complete") { - console.log("MCP Event:", JSON.stringify(event, null, 2)); + process.stdout.write("MCP Event: " + JSON.stringify(event, null, 2) + "\n"); } } ); @@ -38,7 +38,7 @@ async function main() { await client.connect(transport); // Use correct route (/mcp/agents) and bearer token env var - console.log("\n=== Testing HTTP MCP server with correct route and bearer token ===\n"); + process.stdout.write("\n=== Testing HTTP MCP server with correct route and bearer token ===\n\n"); try { const result = await client.callTool({ @@ -58,18 +58,21 @@ async function main() { } }, undefined, { timeout: 60000 }); - console.log("\n=== RESULT ==="); + process.stdout.write("\n=== RESULT ===\n"); const content = (result as { content: { text?: string }[] }).content; for (const item of content) { if (item.text) { - console.log(item.text); + process.stdout.write(item.text + "\n"); } } } catch (error) { - console.error("Error:", error); + process.stderr.write("Error: " + String(error) + "\n"); } await client.close(); } -main().catch(console.error); +main().catch((error) => { + process.stderr.write(String(error) + "\n"); + process.exitCode = 1; +}); diff --git a/packages/server/scripts/test-codex-mcp-basic-auth.ts b/packages/server/scripts/test-codex-mcp-basic-auth.ts index 5311c6516..9e0865c06 100644 --- a/packages/server/scripts/test-codex-mcp-basic-auth.ts +++ b/packages/server/scripts/test-codex-mcp-basic-auth.ts @@ -27,7 +27,7 @@ async function main() { (data) => { const event = (data.params as { msg: unknown }).msg as { type?: string }; if (event.type === "mcp_startup_update" || event.type === "mcp_startup_complete") { - console.log("MCP Event:", JSON.stringify(event, null, 2)); + process.stdout.write("MCP Event: " + JSON.stringify(event, null, 2) + "\n"); } } ); @@ -35,7 +35,7 @@ async function main() { await client.connect(transport); // Try passing MCP server config via the config parameter with headers - console.log("\n=== Testing HTTP MCP server with basic auth in config ===\n"); + process.stdout.write("\n=== Testing HTTP MCP server with basic auth in config ===\n\n"); try { // Create base64 encoded credentials @@ -61,18 +61,21 @@ async function main() { } }, undefined, { timeout: 60000 }); - console.log("\n=== RESULT ==="); + process.stdout.write("\n=== RESULT ===\n"); const content = (result as { content: { text?: string }[] }).content; for (const item of content) { if (item.text) { - console.log(item.text); + process.stdout.write(item.text + "\n"); } } } catch (error) { - console.error("Error:", error); + process.stderr.write("Error: " + String(error) + "\n"); } await client.close(); } -main().catch(console.error); +main().catch((error) => { + process.stderr.write(String(error) + "\n"); + process.exitCode = 1; +}); diff --git a/packages/server/scripts/test-codex-mcp-bearer.ts b/packages/server/scripts/test-codex-mcp-bearer.ts index efbec1229..e3c1eec58 100644 --- a/packages/server/scripts/test-codex-mcp-bearer.ts +++ b/packages/server/scripts/test-codex-mcp-bearer.ts @@ -30,7 +30,7 @@ async function main() { (data) => { const event = (data.params as { msg: unknown }).msg as { type?: string }; if (event.type === "mcp_startup_update" || event.type === "mcp_startup_complete") { - console.log("MCP Event:", JSON.stringify(event, null, 2)); + process.stdout.write("MCP Event: " + JSON.stringify(event, null, 2) + "\n"); } } ); @@ -38,7 +38,7 @@ async function main() { await client.connect(transport); // Try passing MCP server config with bearer_token_env_var - console.log("\n=== Testing HTTP MCP server with bearer_token_env_var ===\n"); + process.stdout.write("\n=== Testing HTTP MCP server with bearer_token_env_var ===\n\n"); try { const result = await client.callTool({ @@ -58,18 +58,21 @@ async function main() { } }, undefined, { timeout: 60000 }); - console.log("\n=== RESULT ==="); + process.stdout.write("\n=== RESULT ===\n"); const content = (result as { content: { text?: string }[] }).content; for (const item of content) { if (item.text) { - console.log(item.text); + process.stdout.write(item.text + "\n"); } } } catch (error) { - console.error("Error:", error); + process.stderr.write("Error: " + String(error) + "\n"); } await client.close(); } -main().catch(console.error); +main().catch((error) => { + process.stderr.write(String(error) + "\n"); + process.exitCode = 1; +}); diff --git a/packages/server/scripts/test-codex-mcp-http-headers.ts b/packages/server/scripts/test-codex-mcp-http-headers.ts index e1aaa4670..a054cab0b 100644 --- a/packages/server/scripts/test-codex-mcp-http-headers.ts +++ b/packages/server/scripts/test-codex-mcp-http-headers.ts @@ -28,7 +28,7 @@ async function main() { (data) => { const event = (data.params as { msg: unknown }).msg as { type?: string }; if (event.type === "mcp_startup_update" || event.type === "mcp_startup_complete") { - console.log("MCP Event:", JSON.stringify(event, null, 2)); + process.stdout.write("MCP Event: " + JSON.stringify(event, null, 2) + "\n"); } } ); @@ -36,7 +36,7 @@ async function main() { await client.connect(transport); // Test using http_headers with Authorization - console.log("\n=== Testing HTTP MCP server with http_headers and Authorization ===\n"); + process.stdout.write("\n=== Testing HTTP MCP server with http_headers and Authorization ===\n\n"); try { const result = await client.callTool({ @@ -58,18 +58,21 @@ async function main() { } }, undefined, { timeout: 60000 }); - console.log("\n=== RESULT ==="); + process.stdout.write("\n=== RESULT ===\n"); const content = (result as { content: { text?: string }[] }).content; for (const item of content) { if (item.text) { - console.log(item.text); + process.stdout.write(item.text + "\n"); } } } catch (error) { - console.error("Error:", error); + process.stderr.write("Error: " + String(error) + "\n"); } await client.close(); } -main().catch(console.error); +main().catch((error) => { + process.stderr.write(String(error) + "\n"); + process.exitCode = 1; +}); diff --git a/packages/server/scripts/test-codex-mcp-http.ts b/packages/server/scripts/test-codex-mcp-http.ts index 7ed0350d4..485974e05 100644 --- a/packages/server/scripts/test-codex-mcp-http.ts +++ b/packages/server/scripts/test-codex-mcp-http.ts @@ -23,7 +23,7 @@ async function main() { (data) => { const event = (data.params as { msg: unknown }).msg as { type?: string }; if (event.type === "mcp_startup_update" || event.type === "mcp_startup_complete") { - console.log("MCP Event:", JSON.stringify(event, null, 2)); + process.stdout.write("MCP Event: " + JSON.stringify(event, null, 2) + "\n"); } } ); @@ -31,7 +31,7 @@ async function main() { await client.connect(transport); // Try passing MCP server config via the config parameter with HTTP URL - console.log("\n=== Testing HTTP MCP server config (agent-control style) ===\n"); + process.stdout.write("\n=== Testing HTTP MCP server config (agent-control style) ===\n\n"); try { const result = await client.callTool({ @@ -51,18 +51,21 @@ async function main() { } }, undefined, { timeout: 60000 }); - console.log("\n=== RESULT ==="); + process.stdout.write("\n=== RESULT ===\n"); const content = (result as { content: { text?: string }[] }).content; for (const item of content) { if (item.text) { - console.log(item.text); + process.stdout.write(item.text + "\n"); } } } catch (error) { - console.error("Error:", error); + process.stderr.write("Error: " + String(error) + "\n"); } await client.close(); } -main().catch(console.error); +main().catch((error) => { + process.stderr.write(String(error) + "\n"); + process.exitCode = 1; +}); diff --git a/packages/server/scripts/test-codex-mcp-servers.ts b/packages/server/scripts/test-codex-mcp-servers.ts index c20c1fbc4..cd9511f8b 100644 --- a/packages/server/scripts/test-codex-mcp-servers.ts +++ b/packages/server/scripts/test-codex-mcp-servers.ts @@ -28,18 +28,18 @@ async function main() { item?: { type?: string }; }; if (event.type === "turn.started") { - console.log("\n=== TURN STARTED ==="); + process.stdout.write("\n=== TURN STARTED ===\n"); } else if (event.type === "agent_message") { - console.log("Agent:", event.data?.text || event.text); + process.stdout.write("Agent: " + (event.data?.text || event.text) + "\n"); } else if (event.type === "mcp_tool_call") { - console.log("MCP Tool Call:", JSON.stringify(event.data)); + process.stdout.write("MCP Tool Call: " + JSON.stringify(event.data) + "\n"); } else if (event.type === "thread.item") { const item = event.data?.item || event.item; if (item?.type === "mcp_tool_call") { - console.log("MCP Tool from thread:", JSON.stringify(item)); + process.stdout.write("MCP Tool from thread: " + JSON.stringify(item) + "\n"); } } else { - console.log("Event:", event.type); + process.stdout.write("Event: " + event.type + "\n"); } } ); @@ -47,7 +47,7 @@ async function main() { await client.connect(transport); // Try passing MCP server config via the config parameter - console.log("\n=== Testing dynamic MCP server config ===\n"); + process.stdout.write("\n=== Testing dynamic MCP server config ===\n\n"); try { const result = await client.callTool({ @@ -67,18 +67,21 @@ async function main() { } }, undefined, { timeout: 60000 }); - console.log("\n=== RESULT ==="); + process.stdout.write("\n=== RESULT ===\n"); const content = (result as { content: { text?: string }[] }).content; for (const item of content) { if (item.text) { - console.log(item.text); + process.stdout.write(item.text + "\n"); } } } catch (error) { - console.error("Error:", error); + process.stderr.write("Error: " + String(error) + "\n"); } await client.close(); } -main().catch(console.error); +main().catch((error) => { + process.stderr.write(String(error) + "\n"); + process.exitCode = 1; +}); diff --git a/packages/server/scripts/verify-codex-mcp-config.ts b/packages/server/scripts/verify-codex-mcp-config.ts index e88c7c8cb..5a0a53fe9 100644 --- a/packages/server/scripts/verify-codex-mcp-config.ts +++ b/packages/server/scripts/verify-codex-mcp-config.ts @@ -4,8 +4,8 @@ import { buildPaseoDaemonConfigFromEnv } from "../src/server/config.js"; const config = buildPaseoDaemonConfigFromEnv(); -console.log("=== agentControlMcp config ==="); -console.log(JSON.stringify(config.agentControlMcp, null, 2)); +process.stdout.write("=== agentControlMcp config ===\n"); +process.stdout.write(JSON.stringify(config.agentControlMcp, null, 2) + "\n"); // Simulate what buildCodexMcpConfig does const mcpServers: Record = {}; @@ -23,5 +23,5 @@ mcpServers["playwright"] = { args: ["@playwright/mcp", "--headless", "--isolated"], }; -console.log("\n=== Built MCP servers config ==="); -console.log(JSON.stringify(mcpServers, null, 2)); +process.stdout.write("\n=== Built MCP servers config ===\n"); +process.stdout.write(JSON.stringify(mcpServers, null, 2) + "\n"); diff --git a/packages/server/src/client/daemon-client-v2.ts b/packages/server/src/client/daemon-client-v2.ts index bfaaa87dc..f02ca4d70 100644 --- a/packages/server/src/client/daemon-client-v2.ts +++ b/packages/server/src/client/daemon-client-v2.ts @@ -8,6 +8,7 @@ import { SessionInboundMessageSchema, WSOutboundMessageSchema, } from "../shared/messages.js"; +import { getRootLogger } from "../server/logger.js"; import type { AgentStreamEventPayload, AgentSnapshotPayload, @@ -39,6 +40,8 @@ import type { } from "../server/agent/agent-sdk-types.js"; import { getAgentProviderDefinition } from "../server/agent/provider-manifest.js"; +const logger = getRootLogger().child({ module: "daemon-client" }); + export type DaemonTransport = { send: (data: string) => void; close: (code?: number, reason?: string) => void; @@ -1409,7 +1412,7 @@ export class DaemonClientV2 { const parsed = WSOutboundMessageSchema.safeParse(parsedJson); if (!parsed.success) { const msgType = (parsedJson as { message?: { type?: string } })?.message?.type ?? "unknown"; - console.warn(`[DaemonClientV2] Message validation failed for "${msgType}":`, parsed.error.message); + logger.warn({ msgType, error: parsed.error.message }, "Message validation failed"); return; } diff --git a/packages/server/src/poc-commands/commands-poc.test.ts b/packages/server/src/poc-commands/commands-poc.test.ts index 79fe79a51..f78c713f2 100644 --- a/packages/server/src/poc-commands/commands-poc.test.ts +++ b/packages/server/src/poc-commands/commands-poc.test.ts @@ -53,15 +53,6 @@ describe("Claude Agent SDK Commands POC", () => { // Should be an array expect(Array.isArray(commands)).toBe(true); - // Log what we found - console.log(`[Test] Found ${commands.length} commands:`); - commands.slice(0, 10).forEach((cmd) => { - console.log(` - /${cmd.name}: ${cmd.description} [${cmd.argumentHint}]`); - }); - if (commands.length > 10) { - console.log(` ... and ${commands.length - 10} more`); - } - // Verify structure if (commands.length > 0) { const firstCommand = commands[0]; diff --git a/packages/server/src/poc-commands/investigate-command-output.ts b/packages/server/src/poc-commands/investigate-command-output.ts index b837e0a0f..bb25c0387 100644 --- a/packages/server/src/poc-commands/investigate-command-output.ts +++ b/packages/server/src/poc-commands/investigate-command-output.ts @@ -57,9 +57,9 @@ class Pushable implements AsyncIterable { } async function investigateCommand(commandName: string): Promise { - console.log(`\n${"=".repeat(60)}`); - console.log(`Investigating: /${commandName}`); - console.log("=".repeat(60)); + process.stdout.write(`\n${"=".repeat(60)}\n`); + process.stdout.write(`Investigating: /${commandName}\n`); + process.stdout.write(`${"=".repeat(60)}\n`); const input = new Pushable(); @@ -89,70 +89,70 @@ async function investigateCommand(commandName: string): Promise { let messageCount = 0; for await (const message of claudeQuery) { messageCount++; - console.log(`\n--- Message ${messageCount} ---`); - console.log(`Type: ${message.type}`); + process.stdout.write(`\n--- Message ${messageCount} ---\n`); + process.stdout.write(`Type: ${message.type}\n`); // Log the full structure based on type switch (message.type) { case "system": - console.log(`Subtype: ${message.subtype}`); + process.stdout.write(`Subtype: ${message.subtype}\n`); if (message.subtype === "init") { - console.log(`Session: ${message.session_id}`); - console.log(`Model: ${message.model}`); + process.stdout.write(`Session: ${message.session_id}\n`); + process.stdout.write(`Model: ${message.model}\n`); } break; case "user": - console.log(`User message content:`, JSON.stringify(message.message?.content, null, 2)); + process.stdout.write(`User message content: ${JSON.stringify(message.message?.content, null, 2)}\n`); break; case "assistant": - console.log(`Assistant message content:`); + process.stdout.write("Assistant message content:\n"); const content = message.message?.content; if (Array.isArray(content)) { for (const block of content) { - console.log(` Block type: ${block.type}`); + process.stdout.write(` Block type: ${block.type}\n`); if (block.type === "text") { - console.log(` Text: ${block.text}`); + process.stdout.write(` Text: ${block.text}\n`); } else if (block.type === "tool_use") { - console.log(` Tool: ${block.name}`); - console.log(` Input: ${JSON.stringify(block.input, null, 2)}`); + process.stdout.write(` Tool: ${block.name}\n`); + process.stdout.write(` Input: ${JSON.stringify(block.input, null, 2)}\n`); } else { - console.log(` Full block: ${JSON.stringify(block, null, 2)}`); + process.stdout.write(` Full block: ${JSON.stringify(block, null, 2)}\n`); } } } else { - console.log(` Content: ${JSON.stringify(content, null, 2)}`); + process.stdout.write(` Content: ${JSON.stringify(content, null, 2)}\n`); } break; case "stream_event": - console.log(`Stream event type: ${message.event?.type}`); + process.stdout.write(`Stream event type: ${message.event?.type}\n`); if (message.event?.type === "content_block_delta") { const delta = message.event.delta; if (delta?.type === "text_delta") { - console.log(` Text delta: ${delta.text}`); + process.stdout.write(` Text delta: ${delta.text}\n`); } } break; case "result": - console.log(`Result subtype: ${message.subtype}`); + process.stdout.write(`Result subtype: ${message.subtype}\n`); if ("errors" in message && message.errors) { - console.log(`Errors: ${JSON.stringify(message.errors)}`); + process.stdout.write(`Errors: ${JSON.stringify(message.errors)}\n`); } // Check for any other properties const resultKeys = Object.keys(message).filter(k => !["type", "subtype"].includes(k)); if (resultKeys.length > 0) { - console.log(`Other result properties: ${resultKeys.join(", ")}`); + process.stdout.write(`Other result properties: ${resultKeys.join(", ")}\n`); for (const key of resultKeys) { - console.log(` ${key}: ${JSON.stringify((message as any)[key], null, 2)}`); + process.stdout.write(` ${key}: ${JSON.stringify((message as any)[key], null, 2)}\n`); } } break; default: - console.log(`Full message: ${JSON.stringify(message, null, 2)}`); + process.stdout.write(`Full message: ${JSON.stringify(message, null, 2)}\n`); } if (message.type === "result") { @@ -160,7 +160,7 @@ async function investigateCommand(commandName: string): Promise { } } - console.log(`\nTotal messages received: ${messageCount}`); + process.stdout.write(`\nTotal messages received: ${messageCount}\n`); } finally { input.end(); @@ -169,7 +169,7 @@ async function investigateCommand(commandName: string): Promise { } async function main() { - console.log("=== Command Output Investigation ===\n"); + process.stdout.write("=== Command Output Investigation ===\n\n"); // Test /context - a local command that shows context info await investigateCommand("context"); @@ -180,10 +180,10 @@ async function main() { // Test /prompt-engineer - a SKILL (not a local command) await investigateCommand("prompt-engineer"); - console.log("\n=== Investigation Complete ==="); + process.stdout.write("\n=== Investigation Complete ===\n"); } main().catch((error) => { - console.error("Fatal error:", error); + process.stderr.write(`Fatal error: ${error}\n`); process.exit(1); }); diff --git a/packages/server/src/poc-commands/run-poc.ts b/packages/server/src/poc-commands/run-poc.ts index 2c6e96081..bf3c4e162 100644 --- a/packages/server/src/poc-commands/run-poc.ts +++ b/packages/server/src/poc-commands/run-poc.ts @@ -104,7 +104,7 @@ async function listAvailableCommands(): Promise { } async function executeCommand(commandName: string): Promise { - console.log(`\n=== Executing command: /${commandName} ===`); + process.stdout.write(`\n=== Executing command: /${commandName} ===\n`); // For command execution, we need a proper input stream const input = new Pushable(); @@ -136,12 +136,12 @@ async function executeCommand(commandName: string): Promise { // Iterate the query to process the command let gotSystemInit = false; for await (const message of claudeQuery) { - console.log(` [${message.type}]`, message.type === "system" ? message.subtype : ""); + process.stdout.write(` [${message.type}] ${message.type === "system" ? message.subtype : ""}\n`); if (message.type === "system" && message.subtype === "init") { gotSystemInit = true; - console.log(" Session:", message.session_id); - console.log(" Model:", message.model); + process.stdout.write(` Session: ${message.session_id}\n`); + process.stdout.write(` Model: ${message.model}\n`); } if (message.type === "assistant") { @@ -149,14 +149,14 @@ async function executeCommand(commandName: string): Promise { if (Array.isArray(content)) { for (const block of content) { if (block.type === "text") { - console.log(" Response:", block.text.slice(0, 200) + (block.text.length > 200 ? "..." : "")); + process.stdout.write(` Response: ${block.text.slice(0, 200)}${block.text.length > 200 ? "..." : ""}\n`); } } } } if (message.type === "result") { - console.log(" Result:", message.subtype); + process.stdout.write(` Result: ${message.subtype}\n`); break; } } @@ -167,48 +167,48 @@ async function executeCommand(commandName: string): Promise { } async function main() { - console.log("=== Claude Agent SDK Commands POC ===\n"); + process.stdout.write("=== Claude Agent SDK Commands POC ===\n\n"); // PART 1: List available commands using supportedCommands() - console.log("=== Part 1: List Available Commands ===\n"); + process.stdout.write("=== Part 1: List Available Commands ===\n\n"); try { const commands = await listAvailableCommands(); - console.log(`Found ${commands.length} commands:\n`); + process.stdout.write(`Found ${commands.length} commands:\n\n`); commands.forEach((cmd, index) => { - console.log(` ${index + 1}. /${cmd.name}`); - console.log(` Description: ${cmd.description}`); + process.stdout.write(` ${index + 1}. /${cmd.name}\n`); + process.stdout.write(` Description: ${cmd.description}\n`); if (cmd.argumentHint) { - console.log(` Arguments: ${cmd.argumentHint}`); + process.stdout.write(` Arguments: ${cmd.argumentHint}\n`); } - console.log(""); + process.stdout.write("\n"); }); // PART 2: Demonstrate command execution (optional - uncomment to test) // Commands are just prompts sent with / prefix - console.log("=== Part 2: Command Execution Explanation ==="); - console.log(""); - console.log("Commands are executed by sending them as prompts with / prefix."); - console.log("For example, to execute the 'help' command:"); - console.log(' 1. Create a user message with content: "/help"'); - console.log(" 2. Push it to the input stream"); - console.log(" 3. Iterate the query to receive responses"); - console.log(""); + process.stdout.write("=== Part 2: Command Execution Explanation ===\n"); + process.stdout.write("\n"); + process.stdout.write("Commands are executed by sending them as prompts with / prefix.\n"); + process.stdout.write("For example, to execute the 'help' command:\n"); + process.stdout.write(' 1. Create a user message with content: "/help"\n'); + process.stdout.write(" 2. Push it to the input stream\n"); + process.stdout.write(" 3. Iterate the query to receive responses\n"); + process.stdout.write("\n"); // Actually execute a command to demonstrate it works: // Using "context" as it's fast and doesn't require arguments await executeCommand("context"); } catch (error) { - console.error("ERROR:", error); + process.stderr.write(`ERROR: ${error}\n`); process.exit(1); } - console.log("=== POC Complete ==="); + process.stdout.write("=== POC Complete ===\n"); } main().catch((error) => { - console.error("Fatal error:", error); + process.stderr.write(`Fatal error: ${error}\n`); process.exit(1); }); diff --git a/packages/server/src/server/agent/agent-manager.ts b/packages/server/src/server/agent/agent-manager.ts index cd4f7c0f7..49d1dd0e7 100644 --- a/packages/server/src/server/agent/agent-manager.ts +++ b/packages/server/src/server/agent/agent-manager.ts @@ -4,6 +4,9 @@ import { AGENT_LIFECYCLE_STATUSES, type AgentLifecycleStatus, } from "../../shared/agent-lifecycle.js"; +import { getRootLogger } from "../logger.js"; + +const logger = getRootLogger().child({ module: "agent", component: "agent-manager" }); import type { AgentCapabilityFlags, @@ -268,9 +271,9 @@ export class AgentManager { }); descriptors.push(...entries); } catch (error) { - console.warn( - `[AgentManager] Failed to list persisted agents for provider '${provider}':`, - error + logger.warn( + { err: error, provider }, + "Failed to list persisted agents for provider" ); } } @@ -355,9 +358,9 @@ export class AgentManager { try { await existing.session.close(); } catch (error) { - console.warn( - `[AgentManager] Failed to close previous session for agent ${agentId} during refresh:`, - error + logger.warn( + { err: error, agentId }, + "Failed to close previous session during refresh" ); } @@ -546,9 +549,9 @@ export class AgentManager { try { await agent.session.interrupt(); } catch (error) { - console.error( - `[AgentManager] Failed to interrupt session for agent ${agentId}:`, - error + logger.error( + { err: error, agentId }, + "Failed to interrupt session" ); } @@ -558,9 +561,9 @@ export class AgentManager { await pendingRun.return(undefined as unknown as AgentStreamEvent); return true; } catch (error) { - console.error( - `[AgentManager] Failed to cancel run for agent ${agentId}:`, - error + logger.error( + { err: error, agentId }, + "Failed to cancel run" ); throw error; } diff --git a/packages/server/src/server/agent/agent-mcp.e2e.test.ts b/packages/server/src/server/agent/agent-mcp.e2e.test.ts index e4497929a..aaca4c479 100644 --- a/packages/server/src/server/agent/agent-mcp.e2e.test.ts +++ b/packages/server/src/server/agent/agent-mcp.e2e.test.ts @@ -464,7 +464,7 @@ describe("agent MCP end-to-end", () => { throw new Error(`send_agent_prompt should interrupt running agent, but got: ${errorText}`); } // Other errors are OK - the main test is that we don't get "already has an active run" - console.log(`send_agent_prompt returned error (not "already has an active run"): ${errorText}`); + } else { const secondPromptPayload = getStructuredContent(secondPromptResult); expect(secondPromptPayload).toBeTruthy(); diff --git a/packages/server/src/server/agent/agent-registry.ts b/packages/server/src/server/agent/agent-registry.ts index 32326ec60..a7ba97583 100644 --- a/packages/server/src/server/agent/agent-registry.ts +++ b/packages/server/src/server/agent/agent-registry.ts @@ -2,6 +2,9 @@ import { randomUUID } from "node:crypto"; import { promises as fs } from "node:fs"; import path from "node:path"; import { z } from "zod"; +import { getRootLogger } from "../logger.js"; + +const logger = getRootLogger().child({ module: "agent", component: "agent-registry" }); import { AgentStatusSchema } from "../messages.js"; import { toStoredAgentRecord } from "./agent-projections.js"; @@ -96,7 +99,7 @@ export class AgentRegistry { this.cache.clear(); return []; } - console.error("[AgentRegistry] Failed to load agents:", error); + logger.error({ err: error }, "Failed to load agents"); this.loaded = true; this.cache.clear(); return []; @@ -182,7 +185,7 @@ export class AgentRegistry { records.push(record); this.cache.set(record.id, record); } catch (error) { - console.error("[AgentRegistry] Skipping invalid record:", error); + logger.error({ err: error }, "Skipping invalid record"); } } return records; @@ -200,9 +203,7 @@ export class AgentRegistry { try { this.cache.clear(); const records = this.parseRecords(candidate); - console.warn( - "[AgentRegistry] Recovered corrupted agents.json payload; rewrote sanitized copy" - ); + logger.warn("Recovered corrupted agents.json payload; rewrote sanitized copy"); const sanitizedPayload = JSON.stringify(records, null, 2); await writeFileAtomically(this.filePath, sanitizedPayload); return records; diff --git a/packages/server/src/server/agent/mcp-server.ts b/packages/server/src/server/agent/mcp-server.ts index 62a21a0e7..fae4cac8e 100644 --- a/packages/server/src/server/agent/mcp-server.ts +++ b/packages/server/src/server/agent/mcp-server.ts @@ -3,6 +3,10 @@ import { z } from "zod"; import { homedir } from "node:os"; import { resolve } from "node:path"; import { ensureValidJson } from "../json-utils.js"; +import { getRootLogger } from "../logger.js"; + +const logger = getRootLogger().child({ module: "agent", component: "mcp-server" }); + import type { AgentPromptInput, AgentProvider, @@ -184,9 +188,9 @@ function startAgentRun( // Events are broadcast via AgentManager subscribers. } } catch (error) { - console.error( - `[Agent MCP] Agent stream failed for ${agentId}:`, - error + logger.error( + { err: error, agentId }, + "Agent stream failed" ); } })(); @@ -225,9 +229,9 @@ async function resolveAgentTitle( const record = await agentRegistry.get(agentId); return record?.title ?? null; } catch (error) { - console.error( - `[Agent MCP] Failed to load agent title for ${agentId}:`, - error + logger.error( + { err: error, agentId }, + "Failed to load agent title" ); return null; } @@ -435,9 +439,9 @@ export async function createAgentMcpServer( try { agentManager.recordUserMessage(snapshot.id, initialPrompt); } catch (error) { - console.error( - `[Agent MCP] Failed to record initial prompt for ${snapshot.id}:`, - error + logger.error( + { err: error, agentId: snapshot.id }, + "Failed to record initial prompt" ); } @@ -471,9 +475,9 @@ export async function createAgentMcpServer( return response; } } catch (error) { - console.error( - `[Agent MCP] Failed to run initial prompt for ${snapshot.id}:`, - error + logger.error( + { err: error, agentId: snapshot.id }, + "Failed to run initial prompt" ); } } else { @@ -616,14 +620,16 @@ export async function createAgentMcpServer( } if (snapshot.lifecycle === "running" || snapshot.pendingRun) { - console.log( - `[Agent MCP] Interrupting active run for ${agentId} before sending new prompt` + logger.debug( + { agentId }, + "Interrupting active run before sending new prompt" ); try { const cancelled = await agentManager.cancelAgentRun(agentId); if (!cancelled) { - console.warn( - `[Agent MCP] Agent ${agentId} reported running but no active run was cancelled` + logger.warn( + { agentId }, + "Agent reported running but no active run was cancelled" ); } // Also cancel any pending wait_for_agent calls for this agent @@ -647,9 +653,9 @@ export async function createAgentMcpServer( await new Promise((resolve) => setTimeout(resolve, pollIntervalMs)); } } catch (error) { - console.error( - `[Agent MCP] Failed to interrupt agent ${agentId}:`, - error + logger.error( + { err: error, agentId }, + "Failed to interrupt agent" ); throw error; } @@ -662,9 +668,9 @@ export async function createAgentMcpServer( try { agentManager.recordUserMessage(agentId, prompt); } catch (error) { - console.error( - `[Agent MCP] Failed to record user message for ${agentId}:`, - error + logger.error( + { err: error, agentId }, + "Failed to record user message" ); } diff --git a/packages/server/src/server/agent/model-resolver.ts b/packages/server/src/server/agent/model-resolver.ts index 03850f921..0f46d9dc5 100644 --- a/packages/server/src/server/agent/model-resolver.ts +++ b/packages/server/src/server/agent/model-resolver.ts @@ -1,6 +1,9 @@ import { fetchProviderModels } from "./provider-registry.js"; import type { AgentProvider } from "./agent-sdk-types.js"; import { expandTilde } from "../../utils/path.js"; +import { getRootLogger } from "../logger.js"; + +const logger = getRootLogger().child({ module: "agent", component: "model-resolver" }); type ResolveAgentModelOptions = { provider: AgentProvider; @@ -23,9 +26,9 @@ export async function resolveAgentModel( const preferred = models.find((model) => model.isDefault) ?? models[0]; return preferred?.id; } catch (error) { - console.warn( - `[AgentModelResolver] Failed to resolve default model for ${options.provider}:`, - error + logger.warn( + { err: error, provider: options.provider }, + "Failed to resolve default model" ); return undefined; } diff --git a/packages/server/src/server/agent/opencode-reasoning.e2e.test.ts b/packages/server/src/server/agent/opencode-reasoning.e2e.test.ts index 3216a5b12..87320ccbc 100644 --- a/packages/server/src/server/agent/opencode-reasoning.e2e.test.ts +++ b/packages/server/src/server/agent/opencode-reasoning.e2e.test.ts @@ -51,9 +51,7 @@ describe("OpenCode reasoning events (e2e)", () => { expect(agent.id).toBeTruthy(); - console.log("\n=== GPT-5 NANO E2E REASONING DEBUG ===\n"); - console.log(`Agent ID: ${agent.id}`); - console.log(`Agent status: ${agent.status}`); + // Send a message that should trigger reasoning await ctx.client.sendMessage(agent.id, "What is 2+2? Think step by step."); @@ -61,16 +59,14 @@ describe("OpenCode reasoning events (e2e)", () => { // Wait for agent to complete const finalState = await ctx.client.waitForAgentIdle(agent.id, 120_000); - console.log(`\nFinal status: ${finalState.status}`); - console.log(`Total events captured: ${allEvents.length}`); // Log all events - console.log("\n=== ALL EVENTS ===\n"); + for (let i = 0; i < allEvents.length; i++) { const { event, timestamp } = allEvents[i]; - console.log(`[EVENT ${i + 1}] timestamp=${timestamp} type=${event.type}`); - console.log(JSON.stringify(event, null, 2)); - console.log("---"); + + + } // Group by type @@ -78,9 +74,9 @@ describe("OpenCode reasoning events (e2e)", () => { for (const { event } of allEvents) { byType.set(event.type, (byType.get(event.type) ?? 0) + 1); } - console.log("\n=== EVENTS BY TYPE ==="); + for (const [type, count] of byType) { - console.log(` ${type}: ${count}`); + } // Check timeline events breakdown @@ -93,24 +89,24 @@ describe("OpenCode reasoning events (e2e)", () => { itemTypes.set(event.item.type, (itemTypes.get(event.item.type) ?? 0) + 1); } } - console.log("\n=== TIMELINE ITEM TYPES ==="); + for (const [type, count] of itemTypes) { - console.log(` ${type}: ${count}`); + } // Find reasoning events const reasoningEvents = timelineEvents.filter( ({ event }) => event.type === "timeline" && event.item.type === "reasoning" ); - console.log(`\nReasoning events: ${reasoningEvents.length}`); + for (const { event } of reasoningEvents.slice(0, 5)) { if (event.type === "timeline") { - console.log("Sample reasoning:", JSON.stringify(event.item, null, 2)); + } } // Check for duplicate consecutive events - console.log("\n=== DUPLICATE CHECK ==="); + let duplicateCount = 0; for (let i = 1; i < allEvents.length; i++) { const prev = allEvents[i - 1]; @@ -118,13 +114,10 @@ describe("OpenCode reasoning events (e2e)", () => { if (JSON.stringify(prev.event) === JSON.stringify(curr.event)) { duplicateCount++; if (duplicateCount <= 5) { - console.log(`Duplicate at index ${i}:`, JSON.stringify(curr.event, null, 2)); + } } } - console.log(`Total duplicates: ${duplicateCount}`); - - console.log("\n=== END DEBUG ===\n"); // HARD ASSERT: Agent completed expect(finalState.status).toBe("idle"); diff --git a/packages/server/src/server/agent/providers/claude-agent-commands.e2e.test.ts b/packages/server/src/server/agent/providers/claude-agent-commands.e2e.test.ts index 11193d9fb..2f8957c1c 100644 --- a/packages/server/src/server/agent/providers/claude-agent-commands.e2e.test.ts +++ b/packages/server/src/server/agent/providers/claude-agent-commands.e2e.test.ts @@ -48,7 +48,6 @@ describe("claude agent commands E2E", () => { const commandNames = result.commands.map((c) => c.name); // These are skills that come from CLAUDE.md configurations // At minimum we should have some commands available - console.log("Available commands:", commandNames); expect(commandNames.length).toBeGreaterThan(0); }, 120000); diff --git a/packages/server/src/server/agent/providers/claude-agent-commands.test.ts b/packages/server/src/server/agent/providers/claude-agent-commands.test.ts index 2e83473da..eb7442927 100644 --- a/packages/server/src/server/agent/providers/claude-agent-commands.test.ts +++ b/packages/server/src/server/agent/providers/claude-agent-commands.test.ts @@ -52,11 +52,6 @@ describe("ClaudeAgentSession Commands", () => { // Should have at least some built-in commands expect(commands.length).toBeGreaterThan(0); - console.log(`[Test] Found ${commands.length} commands:`); - commands.slice(0, 5).forEach((cmd) => { - console.log(` - /${cmd.name}: ${cmd.description}`); - }); - await session.close(); }, 30000); @@ -91,9 +86,6 @@ describe("ClaudeAgentSession Commands", () => { // The exact commands depend on what skills are configured expect(commands.length).toBeGreaterThan(0); - // Log all available commands for debugging - console.log(`[Test] Available commands: ${commandNames.join(", ")}`); - await session.close(); }, 30000); }); @@ -111,7 +103,6 @@ describe("ClaudeAgentSession Commands", () => { // Execute one of the available commands const firstCommand = commands[0]; - console.log(`[Test] Executing command: /${firstCommand.name}`); const result = await session.executeCommand!(firstCommand.name); // Should return a result object @@ -119,8 +110,6 @@ describe("ClaudeAgentSession Commands", () => { expect(typeof result.text).toBe("string"); // Note: Some commands may return empty text (e.g., plugin descriptions) - console.log(`[Test] Command /${firstCommand.name} result (first 200 chars): ${result.text.slice(0, 200)}...`); - await session.close(); }, 60000); @@ -138,8 +127,6 @@ describe("ClaudeAgentSession Commands", () => { expect(result.text.length).toBeGreaterThan(0); expect(result.text).toContain("Context"); - console.log(`[Test] Command /context result: ${result.text.slice(0, 300)}...`); - await session.close(); }, 60000); @@ -158,7 +145,6 @@ describe("ClaudeAgentSession Commands", () => { // Timeline may or may not have items depending on command execution // Just verify the structure is correct - console.log(`[Test] Timeline has ${result.timeline.length} items`); await session.close(); }, 60000); diff --git a/packages/server/src/server/agent/providers/claude-agent.test.ts b/packages/server/src/server/agent/providers/claude-agent.test.ts index 1e4a59843..279c099b9 100644 --- a/packages/server/src/server/agent/providers/claude-agent.test.ts +++ b/packages/server/src/server/agent/providers/claude-agent.test.ts @@ -145,8 +145,8 @@ async function startAgentMcpServer(): Promise { agentMcpTransports.delete(transport.sessionId); } }; - transport.onerror = (error) => { - console.error("[Agent MCP] Transport error:", error); + transport.onerror = () => { + // Ignore errors in test }; await agentMcpServer.connect(transport); @@ -187,7 +187,6 @@ async function startAgentMcpServer(): Promise { await transport.handleRequest(req, res, req.body); } catch (error) { - console.error("[Agent MCP] Failed to handle request:", error); if (!res.headersSent) { res.status(500).json({ jsonrpc: "2.0", diff --git a/packages/server/src/server/agent/providers/claude-agent.ts b/packages/server/src/server/agent/providers/claude-agent.ts index 055d43fd6..fb4b79c68 100644 --- a/packages/server/src/server/agent/providers/claude-agent.ts +++ b/packages/server/src/server/agent/providers/claude-agent.ts @@ -20,6 +20,9 @@ import { type SDKSystemMessage, type SDKUserMessage, } from "@anthropic-ai/claude-agent-sdk"; +import { getRootLogger } from "../../logger.js"; + +const logger = getRootLogger().child({ module: "agent", provider: "claude" }); import type { AgentCapabilityFlags, @@ -549,7 +552,7 @@ class ClaudeAgentSession implements AgentSession { this.turnCancelRequested = true; // Store the interrupt promise so processPrompt can await it before calling query.next() this.pendingInterruptPromise = this.interruptActiveTurn().catch((error) => { - console.warn("[ClaudeAgentSession] Failed to interrupt during cancel:", error); + logger.warn({ err: error }, "Failed to interrupt during cancel"); }); // Push turn_canceled before ending the queue so consumers get proper lifecycle signals queue.push({ @@ -572,7 +575,7 @@ class ClaudeAgentSession implements AgentSession { const forwardPromise = this.forwardPromptEvents(sdkMessage, queue, turnId); this.activeTurnPromise = forwardPromise; forwardPromise.catch((error) => { - console.error("[ClaudeAgentSession] Unexpected error in forwardPromptEvents:", error); + logger.error({ err: error }, "Unexpected error in forwardPromptEvents"); }); try { @@ -807,7 +810,7 @@ class ClaudeAgentSession implements AgentSession { }, settingSources: ["user", "project"], stderr: (data: string) => { - console.error("[ClaudeAgentSDK]", data.trim()); + logger.error({ stderr: data.trim() }, "Claude Agent SDK stderr"); }, env: { ...process.env, @@ -1019,7 +1022,7 @@ class ClaudeAgentSession implements AgentSession { this.query = null; this.input = null; } catch (error) { - console.warn("[ClaudeAgentSession] Failed to interrupt active turn:", error); + logger.warn({ err: error }, "Failed to interrupt active turn"); } } @@ -1097,7 +1100,7 @@ class ClaudeAgentSession implements AgentSession { this.persistence = null; // Capture actual model from SDK init message (not just the configured model) if (message.model) { - console.log(`[ClaudeAgentSession] Captured model from SDK init: ${message.model}`); + logger.debug({ model: message.model }, "Captured model from SDK init"); this.lastOptionsModel = message.model; // Invalidate cached runtime info so it picks up the new model this.cachedRuntimeInfo = null; diff --git a/packages/server/src/server/agent/providers/claude-sdk-behavior.test.ts b/packages/server/src/server/agent/providers/claude-sdk-behavior.test.ts index 5cebf134b..70f848e9a 100644 --- a/packages/server/src/server/agent/providers/claude-sdk-behavior.test.ts +++ b/packages/server/src/server/agent/providers/claude-sdk-behavior.test.ts @@ -73,15 +73,11 @@ describe("Claude SDK direct behavior", () => { preset: "claude_code", }, settingSources: ["user", "project"], - stderr: (data: string) => { - console.error("[SDK stderr]", data.trim()); - }, }, }); try { // Send first message - console.log("[SDK] Sending MSG1"); input.push({ type: "user", message: { role: "user", content: "Say exactly: MESSAGE_ONE" }, @@ -93,54 +89,32 @@ describe("Claude SDK direct behavior", () => { const msg1Events: SDKMessage[] = []; for await (const event of q) { msg1Events.push(event); - console.log("[SDK] MSG1 event:", event.type); if (event.type === "assistant") { // Push MSG2 BEFORE interrupt (like our wrapper does when a new message comes in) - console.log("[SDK] Pushing MSG2 before interrupt..."); input.push({ type: "user", message: { role: "user", content: "Say exactly: MESSAGE_TWO" }, parent_tool_use_id: null, session_id: "", }); - console.log("[SDK] Calling interrupt()..."); await q.interrupt(); - console.log("[SDK] interrupt() returned"); break; } if (event.type === "result") { - console.log("[SDK] MSG1 completed before interrupt"); break; } } - console.log("[SDK] MSG1 events:", msg1Events.length); - // MSG2 was already pushed before interrupt - console.log("[SDK] About to call q.next() for MSG2..."); const msg2Events: SDKMessage[] = []; for await (const event of q) { msg2Events.push(event); - let detail = ""; - if (event.type === "assistant" && "message" in event && event.message?.content) { - const content = event.message.content; - if (Array.isArray(content)) { - for (const block of content) { - if (block.type === "text" && block.text) { - detail = `"${block.text.substring(0, 50)}"`; - } - } - } - } - console.log("[SDK] MSG2 event:", event.type, detail); - if (event.type === "result") { break; } } - console.log("[SDK] MSG2 loop finished"); // Analyze response let responseText = ""; @@ -157,10 +131,6 @@ describe("Claude SDK direct behavior", () => { } } - console.log("[SDK] MSG2 response:", responseText); - console.log("[SDK] Mentions 'one':", responseText.toLowerCase().includes("one")); - console.log("[SDK] Mentions 'two':", responseText.toLowerCase().includes("two")); - const sawResult = msg2Events.some((event) => event.type === "result"); // The SDK may short-circuit after interrupt without a result event. expect(sawResult || responseText.length === 0).toBe(true); diff --git a/packages/server/src/server/agent/providers/codex-mcp-agent.ts b/packages/server/src/server/agent/providers/codex-mcp-agent.ts index d7abf3279..b7db225c1 100644 --- a/packages/server/src/server/agent/providers/codex-mcp-agent.ts +++ b/packages/server/src/server/agent/providers/codex-mcp-agent.ts @@ -14,6 +14,9 @@ import { Client } from "@modelcontextprotocol/sdk/client/index.js"; import { StdioClientTransport } from "@modelcontextprotocol/sdk/client/stdio.js"; import { ElicitRequestSchema, type ElicitResult } from "@modelcontextprotocol/sdk/types.js"; import { z } from "zod"; +import { getRootLogger } from "../../logger.js"; + +const logger = getRootLogger().child({ module: "agent", provider: "codex" }); import type { AgentCapabilityFlags, @@ -2377,8 +2380,9 @@ async function replaceInlineImageData(promptText: string): Promise { if (matches.length === 0) { return promptText; } - console.info( - `[CodexAgentSession] Replacing ${matches.length} inline image data URL(s) with temp files.` + logger.debug( + { count: matches.length }, + "Replacing inline image data URLs with temp files" ); let output = ""; let lastIndex = 0; @@ -2393,9 +2397,7 @@ async function replaceInlineImageData(promptText: string): Promise { output += filePath; } catch (error) { const message = error instanceof Error ? error.message : String(error); - console.warn( - `[CodexAgentSession] Failed to replace inline image data URL: ${message}` - ); + logger.warn({ message }, "Failed to replace inline image data URL"); output += fullMatch; } lastIndex = matchIndex + fullMatch.length; @@ -4845,9 +4847,9 @@ async function loadCodexPersistedTimeline( const timeline = await parseRolloutFile(rolloutFile); return timeline.slice(0, PERSISTED_TIMELINE_LIMIT); } catch (error) { - console.warn( - `[CodexMcpAgentSession] Failed to load persisted timeline for ${sessionId}:`, - error + logger.warn( + { err: error, sessionId }, + "Failed to load persisted timeline" ); return []; } diff --git a/packages/server/src/server/agent/providers/opencode-agent.ts b/packages/server/src/server/agent/providers/opencode-agent.ts index ad4931677..8c343ae9d 100644 --- a/packages/server/src/server/agent/providers/opencode-agent.ts +++ b/packages/server/src/server/agent/providers/opencode-agent.ts @@ -1,6 +1,9 @@ import { spawn, type ChildProcess } from "node:child_process"; import { createOpencodeClient, type OpencodeClient } from "@opencode-ai/sdk/v2/client"; import net from "node:net"; +import { getRootLogger } from "../../logger.js"; + +const logger = getRootLogger().child({ module: "agent", provider: "opencode" }); import type { AgentCapabilityFlags, @@ -138,7 +141,7 @@ export class OpenCodeServerManager { }); this.server.stderr?.on("data", (data: Buffer) => { - console.error("[OpenCode Server]", data.toString().trim()); + logger.error({ stderr: data.toString().trim() }, "OpenCode server stderr"); }); this.server.on("error", (error) => { diff --git a/packages/server/src/server/agent/stt-debug.ts b/packages/server/src/server/agent/stt-debug.ts index c278dbd5c..18a5cf68d 100644 --- a/packages/server/src/server/agent/stt-debug.ts +++ b/packages/server/src/server/agent/stt-debug.ts @@ -1,6 +1,9 @@ import { mkdir, writeFile } from "fs/promises"; import { join, resolve } from "path"; import { inferAudioExtension, sanitizeForFilename } from "./audio-utils.js"; +import { getRootLogger } from "../logger.js"; + +const logger = getRootLogger().child({ module: "agent", component: "stt-debug" }); const debugDir = process.env.STT_DEBUG_AUDIO_DIR ? resolve(process.env.STT_DEBUG_AUDIO_DIR) @@ -24,7 +27,7 @@ export async function maybePersistDebugAudio( } if (!announced) { - console.log(`[STT][Debug] Raw audio capture enabled at ${debugDir}`); + logger.info({ debugDir }, "Raw audio capture enabled"); announced = true; } diff --git a/packages/server/src/server/agent/stt-manager.ts b/packages/server/src/server/agent/stt-manager.ts index ea03b77b4..b1a61f59e 100644 --- a/packages/server/src/server/agent/stt-manager.ts +++ b/packages/server/src/server/agent/stt-manager.ts @@ -1,5 +1,6 @@ import { transcribeAudio, type TranscriptionResult } from "./stt-openai.js"; import { maybePersistDebugAudio } from "./stt-debug.js"; +import { getRootLogger } from "../logger.js"; interface TranscriptionMetadata { agentId?: string; @@ -19,9 +20,11 @@ export interface SessionTranscriptionResult extends TranscriptionResult { */ export class STTManager { private readonly sessionId: string; + private readonly logger; constructor(sessionId: string) { this.sessionId = sessionId; + this.logger = getRootLogger().child({ module: "agent", component: "stt-manager", sessionId }); } /** @@ -32,9 +35,9 @@ export class STTManager { format: string, metadata?: TranscriptionMetadata ): Promise { - const context = metadata?.label ? ` (${metadata.label})` : ""; - console.log( - `[STT-Manager ${this.sessionId}] Transcribing ${audio.length} bytes of ${format} audio${context}` + this.logger.debug( + { bytes: audio.length, format, label: metadata?.label }, + "Transcribing audio" ); let debugRecordingPath: string | null = null; @@ -47,18 +50,16 @@ export class STTManager { format, }); } catch (error) { - console.warn( - `[STT-Manager ${this.sessionId}] Failed to persist debug audio:`, - error - ); + this.logger.warn({ err: error }, "Failed to persist debug audio"); } const result = await transcribeAudio(audio, format); // Filter out low-confidence transcriptions (non-speech sounds) if (result.isLowConfidence) { - console.log( - `[STT-Manager ${this.sessionId}] Filtered low-confidence transcription (likely non-speech): "${result.text}" (avg logprob: ${result.avgLogprob?.toFixed(2)})` + this.logger.debug( + { text: result.text, avgLogprob: result.avgLogprob }, + "Filtered low-confidence transcription (likely non-speech)" ); // Return empty text to ignore this transcription @@ -71,10 +72,9 @@ export class STTManager { }; } - console.log( - `[STT-Manager ${this.sessionId}] Transcription complete: "${result.text}"${ - result.avgLogprob !== undefined ? ` (avg logprob: ${result.avgLogprob.toFixed(2)})` : "" - }` + this.logger.debug( + { text: result.text, avgLogprob: result.avgLogprob }, + "Transcription complete" ); return { diff --git a/packages/server/src/server/agent/stt-openai.ts b/packages/server/src/server/agent/stt-openai.ts index fd3e10ffc..910b84bb4 100644 --- a/packages/server/src/server/agent/stt-openai.ts +++ b/packages/server/src/server/agent/stt-openai.ts @@ -4,6 +4,9 @@ import { join } from "path"; import { tmpdir } from "os"; import { v4 } from "uuid"; import { inferAudioExtension } from "./audio-utils.js"; +import { getRootLogger } from "../logger.js"; + +const logger = getRootLogger().child({ module: "agent", provider: "openai", component: "stt" }); export interface STTConfig { apiKey: string; @@ -58,7 +61,7 @@ export function initializeSTT(sttConfig: STTConfig): void { openaiClient = new OpenAI({ apiKey: sttConfig.apiKey, }); - console.log("✓ STT (OpenAI Whisper) initialized"); + logger.info({ model: sttConfig.model || "whisper-1" }, "STT (OpenAI Whisper) initialized"); } export async function transcribeAudio( @@ -81,8 +84,9 @@ export async function transcribeAudio( tempFilePath = join(tmpdir(), `audio-${v4()}.${ext}`); await writeFile(tempFilePath, audioBuffer); - console.log( - `[STT] Transcribing audio file: ${tempFilePath} (${audioBuffer.length} bytes)` + logger.debug( + { tempFilePath, bytes: audioBuffer.length }, + "Transcribing audio file" ); // Call OpenAI Whisper API @@ -126,24 +130,21 @@ export async function transcribeAudio( isLowConfidence = avgLogprob < confidenceThreshold; if (isLowConfidence) { - console.log( - `[STT] Low confidence transcription detected (avg: ${avgLogprob.toFixed( - 2 - )}, threshold: ${confidenceThreshold}): "${response.text}"` - ); - console.log( - `[STT] Token logprobs:`, - logprobs.map((t) => `${t.token}:${t.logprob.toFixed(2)}`).join(", ") + logger.debug( + { + avgLogprob, + threshold: confidenceThreshold, + text: response.text, + tokenLogprobs: logprobs.map((t) => `${t.token}:${t.logprob.toFixed(2)}`).join(", ") + }, + "Low confidence transcription detected" ); } } - console.log( - `[STT] Transcription complete in ${duration}ms: "${response.text}"${ - avgLogprob !== undefined - ? ` (avg logprob: ${avgLogprob.toFixed(2)})` - : "" - }` + logger.debug( + { duration, text: response.text, avgLogprob }, + "Transcription complete" ); return { @@ -158,7 +159,7 @@ export async function transcribeAudio( : undefined, }; } catch (error: any) { - console.error("[STT] Transcription error:", error); + logger.error({ err: error }, "Transcription error"); throw new Error(`STT transcription failed: ${error.message}`); } finally { // Clean up temporary file @@ -166,7 +167,7 @@ export async function transcribeAudio( try { await unlink(tempFilePath); } catch (cleanupError) { - console.warn(`[STT] Failed to clean up temp file: ${tempFilePath}`); + logger.warn({ tempFilePath }, "Failed to clean up temp file"); } } } diff --git a/packages/server/src/server/agent/tts-manager.ts b/packages/server/src/server/agent/tts-manager.ts index 8973bfa9c..402d9fafe 100644 --- a/packages/server/src/server/agent/tts-manager.ts +++ b/packages/server/src/server/agent/tts-manager.ts @@ -1,6 +1,7 @@ import { v4 as uuidv4 } from "uuid"; import { synthesizeSpeech } from "./tts-openai.js"; import type { SessionOutboundMessage } from "../messages.js"; +import { getRootLogger } from "../logger.js"; interface PendingPlayback { resolve: () => void; @@ -15,10 +16,10 @@ interface PendingPlayback { */ export class TTSManager { private pendingPlaybacks: Map = new Map(); - private readonly sessionId: string; + private readonly logger; constructor(sessionId: string) { - this.sessionId = sessionId; + this.logger = getRootLogger().child({ module: "agent", component: "tts-manager", sessionId }); } /** @@ -32,9 +33,7 @@ export class TTSManager { isRealtimeMode: boolean ): Promise { if (abortSignal.aborted) { - console.log( - `[TTS-Manager ${this.sessionId}] Aborted before generating audio` - ); + this.logger.debug("Aborted before generating audio"); return; } @@ -42,9 +41,7 @@ export class TTSManager { const { stream, format } = await synthesizeSpeech(text); if (abortSignal.aborted) { - console.log( - `[TTS-Manager ${this.sessionId}] Aborted after generating audio` - ); + this.logger.debug("Aborted after generating audio"); return; } @@ -74,9 +71,7 @@ export class TTSManager { }; onAbort = () => { - console.log( - `[TTS-Manager ${this.sessionId}] Aborted while waiting for playback` - ); + this.logger.debug("Aborted while waiting for playback"); pendingPlayback.streamEnded = true; pendingPlayback.pendingChunks = 0; this.pendingPlaybacks.delete(audioId); @@ -96,9 +91,7 @@ export class TTSManager { while (true) { if (abortSignal.aborted) { - console.log( - `[TTS-Manager ${this.sessionId}] Aborted during stream emission` - ); + this.logger.debug("Aborted during stream emission"); break; } @@ -122,10 +115,9 @@ export class TTSManager { }, }); - console.log( - `[TTS-Manager ${this.sessionId}] ${new Date().toISOString()} Sent audio chunk ${chunkId}${ - next.done ? " (last)" : "" - }` + this.logger.debug( + { chunkId, isLastChunk: next.done }, + "Sent audio chunk" ); chunkIndex += 1; @@ -149,14 +141,9 @@ export class TTSManager { await playbackPromise; } catch (error) { if (abortSignal.aborted) { - console.log( - `[TTS-Manager ${this.sessionId}] Audio stream closed after abort` - ); + this.logger.debug("Audio stream closed after abort"); } else { - console.error( - `[TTS-Manager ${this.sessionId}] Error streaming audio`, - error - ); + this.logger.error({ err: error }, "Error streaming audio"); this.pendingPlaybacks.delete(audioId); pendingPlayback.reject(error as Error); throw error; @@ -172,11 +159,7 @@ export class TTSManager { return; } - console.log( - `[TTS-Manager ${ - this.sessionId - }] ${new Date().toISOString()} Audio ${audioId} playback confirmed` - ); + this.logger.debug({ audioId }, "Audio playback confirmed"); } /** @@ -190,9 +173,7 @@ export class TTSManager { const pending = this.pendingPlaybacks.get(audioId); if (!pending) { - console.warn( - `[TTS-Manager ${this.sessionId}] Received confirmation for unknown audio ID: ${chunkId}` - ); + this.logger.warn({ chunkId }, "Received confirmation for unknown audio ID"); return; } @@ -212,16 +193,15 @@ export class TTSManager { return; } - console.log( - `[TTS-Manager ${this.sessionId}] Cancelling ${this.pendingPlaybacks.size} pending playback(s): ${reason}` + this.logger.debug( + { count: this.pendingPlaybacks.size, reason }, + "Cancelling pending playbacks" ); for (const [audioId, pending] of this.pendingPlaybacks.entries()) { pending.resolve(); this.pendingPlaybacks.delete(audioId); - console.log( - `[TTS-Manager ${this.sessionId}] Cleared pending playback ${audioId}` - ); + this.logger.debug({ audioId }, "Cleared pending playback"); } } diff --git a/packages/server/src/server/agent/tts-openai.ts b/packages/server/src/server/agent/tts-openai.ts index d5d113ea2..b66af3ee5 100644 --- a/packages/server/src/server/agent/tts-openai.ts +++ b/packages/server/src/server/agent/tts-openai.ts @@ -1,5 +1,8 @@ import OpenAI from "openai"; import { Readable } from "stream"; +import { getRootLogger } from "../logger.js"; + +const logger = getRootLogger().child({ module: "agent", provider: "openai", component: "tts" }); export interface TTSConfig { apiKey: string; @@ -26,8 +29,9 @@ export function initializeTTS(ttsConfig: TTSConfig): void { openaiClient = new OpenAI({ apiKey: ttsConfig.apiKey, }); - console.log( - `✓ TTS (OpenAI) initialized with voice: ${config.voice}, model: ${config.model}, format: ${config.responseFormat}` + logger.info( + { voice: config.voice, model: config.model, format: config.responseFormat }, + "TTS (OpenAI) initialized" ); } @@ -45,10 +49,9 @@ export async function synthesizeSpeech( const startTime = Date.now(); try { - console.log( - `[TTS] Synthesizing speech: "${text.substring(0, 50)}${ - text.length > 50 ? "..." : "" - }"` + logger.debug( + { textLength: text.length, preview: text.substring(0, 50) }, + "Synthesizing speech" ); // Call OpenAI TTS API with streaming @@ -63,14 +66,14 @@ export async function synthesizeSpeech( const audioStream = response.body as unknown as Readable; const duration = Date.now() - startTime; - console.log(`[TTS] Speech synthesis stream ready in ${duration}ms`); + logger.debug({ duration }, "Speech synthesis stream ready"); return { stream: audioStream, format: config.responseFormat || "mp3", }; } catch (error: any) { - console.error("[TTS] Speech synthesis error:", error); + logger.error({ err: error }, "Speech synthesis error"); throw new Error(`TTS synthesis failed: ${error.message}`); } } diff --git a/packages/server/src/server/agent/wait-for-agent-tracker.ts b/packages/server/src/server/agent/wait-for-agent-tracker.ts index bc4776364..cea4848ca 100644 --- a/packages/server/src/server/agent/wait-for-agent-tracker.ts +++ b/packages/server/src/server/agent/wait-for-agent-tracker.ts @@ -1,3 +1,7 @@ +import { getRootLogger } from "../logger.js"; + +const logger = getRootLogger().child({ module: "agent", component: "wait-for-agent-tracker" }); + export type WaitForAgentCanceler = (agentId: string, reason?: string) => boolean; /** @@ -37,9 +41,9 @@ export class WaitForAgentTracker { try { cancel(reason); } catch (error) { - console.warn( - `[WaitForAgentTracker] Cancel callback failed for ${agentId}:`, - error + logger.warn( + { err: error, agentId }, + "Cancel callback failed" ); } } diff --git a/packages/server/src/server/bootstrap.ts b/packages/server/src/server/bootstrap.ts index e869b694b..d5e94fe9d 100644 --- a/packages/server/src/server/bootstrap.ts +++ b/packages/server/src/server/bootstrap.ts @@ -6,6 +6,7 @@ import { stat } from "fs/promises"; import { randomUUID } from "node:crypto"; import { StreamableHTTPServerTransport } from "@modelcontextprotocol/sdk/server/streamableHttp.js"; import { isInitializeRequest } from "@modelcontextprotocol/sdk/types.js"; +import { getRootLogger } from "./logger.js"; type ListenTarget = | { type: "tcp"; host: string; port: number } @@ -96,6 +97,8 @@ export interface PaseoDaemon { export async function createPaseoDaemon( config: PaseoDaemonConfig ): Promise { + const logger = getRootLogger().child({ module: "bootstrap" }); + const agentMcpRoute = config.agentMcpRoute; const basicAuthUsers = config.auth.basicUsers; const staticDir = config.staticDir; @@ -176,8 +179,8 @@ export async function createPaseoDaemon( try { const conversations = await listConversations(); res.json(conversations); - } catch (error) { - console.error("[API] Failed to list conversations:", error); + } catch (err) { + logger.error({ err }, "Failed to list conversations"); res.status(500).json({ error: "Failed to list conversations" }); } }); @@ -187,8 +190,8 @@ export async function createPaseoDaemon( const { id } = req.params; await deleteConversation(id); res.json({ success: true }); - } catch (error) { - console.error("[API] Failed to delete conversation:", error); + } catch (err) { + logger.error({ err }, "Failed to delete conversation"); res.status(500).json({ error: "Failed to delete conversation" }); } }); @@ -226,8 +229,8 @@ export async function createPaseoDaemon( res.setHeader("Content-Length", entry.size.toString()); const stream = createReadStream(entry.absolutePath); - stream.on("error", (error) => { - console.error("[API] Failed to stream download:", error); + stream.on("error", (err) => { + logger.error({ err }, "Failed to stream download"); if (!res.headersSent) { res.status(500).json({ error: "Failed to read file" }); } else { @@ -235,8 +238,8 @@ export async function createPaseoDaemon( } }); stream.pipe(res); - } catch (error) { - console.error("[API] Failed to download file:", error); + } catch (err) { + logger.error({ err }, "Failed to download file"); if (!res.headersSent) { res.status(404).json({ error: "File not found" }); } @@ -257,8 +260,8 @@ export async function createPaseoDaemon( attachAgentRegistryPersistence(agentManager, agentRegistry); const persistedRecords = await agentRegistry.list(); - console.log( - `✓ Agent registry loaded (${persistedRecords.length} record${persistedRecords.length === 1 ? "" : "s"}); agents will initialize on demand` + logger.info( + `Agent registry loaded (${persistedRecords.length} record${persistedRecords.length === 1 ? "" : "s"}); agents will initialize on demand` ); const agentMcpTransports: AgentMcpTransportMap = new Map(); @@ -275,11 +278,11 @@ export async function createPaseoDaemon( sessionIdGenerator: () => randomUUID(), onsessioninitialized: (sessionId) => { agentMcpTransports.set(sessionId, transport); - console.log(`[Agent MCP] Session initialized: ${sessionId}`); + logger.debug({ sessionId }, "Agent MCP session initialized"); }, onsessionclosed: (sessionId) => { agentMcpTransports.delete(sessionId); - console.log(`[Agent MCP] Session closed: ${sessionId}`); + logger.debug({ sessionId }, "Agent MCP session closed"); }, enableDnsRebindingProtection: true, allowedHosts, @@ -289,8 +292,8 @@ export async function createPaseoDaemon( agentMcpTransports.delete(transport.sessionId); } }; - transport.onerror = (error) => { - console.error("[Agent MCP] Transport error:", error); + transport.onerror = (err) => { + logger.error({ err }, "Agent MCP transport error"); }; await agentMcpServer.connect(transport); @@ -300,13 +303,16 @@ export async function createPaseoDaemon( const handleAgentMcpRequest: express.RequestHandler = async (req, res) => { if (config.mcpDebug) { - console.log("[Agent MCP] request", { - method: req.method, - url: req.originalUrl, - sessionId: req.header("mcp-session-id"), - authorization: req.header("authorization"), - body: req.body, - }); + logger.debug( + { + method: req.method, + url: req.originalUrl, + sessionId: req.header("mcp-session-id"), + authorization: req.header("authorization"), + body: req.body, + }, + "Agent MCP request" + ); } try { const sessionId = req.header("mcp-session-id"); @@ -346,8 +352,8 @@ export async function createPaseoDaemon( } await transport.handleRequest(req as any, res as any, req.body); - } catch (error) { - console.error("[Agent MCP] Failed to handle request:", error); + } catch (err) { + logger.error({ err }, "Failed to handle Agent MCP request"); if (!res.headersSent) { res.status(500).json({ jsonrpc: "2.0", @@ -364,7 +370,7 @@ export async function createPaseoDaemon( app.post(agentMcpRoute, handleAgentMcpRequest); app.get(agentMcpRoute, handleAgentMcpRequest); app.delete(agentMcpRoute, handleAgentMcpRequest); - console.log(`✓ Agent MCP server mounted at ${agentMcpRoute}`); + logger.info({ route: agentMcpRoute }, "Agent MCP server mounted"); const wsServer = new VoiceAssistantWebSocketServer( httpServer, @@ -380,7 +386,7 @@ export async function createPaseoDaemon( const openaiApiKey = config.openai?.apiKey; if (openaiApiKey) { - console.log("✓ OpenAI client initialized"); + logger.info("OpenAI client initialized"); const sttApiKey = config.openai?.stt?.apiKey ?? openaiApiKey; if (sttApiKey) { @@ -405,9 +411,7 @@ export async function createPaseoDaemon( initializeTitleGenerator(openaiApiKey); } else { - console.warn( - "⚠ OPENAI_API_KEY not set - LLM, STT, and TTS features will not work" - ); + logger.warn("OPENAI_API_KEY not set - LLM, STT, and TTS features will not work"); } const start = async () => { @@ -419,11 +423,12 @@ export async function createPaseoDaemon( const onListening = () => { httpServer.off("error", onError); if (listenTarget.type === "tcp") { - console.log( - `✓ Server listening on http://${listenTarget.host}:${listenTarget.port}` + logger.info( + { host: listenTarget.host, port: listenTarget.port }, + `Server listening on http://${listenTarget.host}:${listenTarget.port}` ); } else { - console.log(`✓ Server listening on ${listenTarget.path}`); + logger.info({ path: listenTarget.path }, `Server listening on ${listenTarget.path}`); } resolve(); }; @@ -465,12 +470,13 @@ export async function createPaseoDaemon( } async function closeAllAgents(agentManager: AgentManager): Promise { + const logger = getRootLogger().child({ module: "bootstrap" }); const agents = agentManager.listAgents(); for (const agent of agents) { try { await agentManager.closeAgent(agent.id); - } catch (error) { - console.error(`[Agents] Failed to close agent ${agent.id}:`, error); + } catch (err) { + logger.error({ err, agentId: agent.id }, "Failed to close agent"); } } } diff --git a/packages/server/src/server/daemon.e2e.test.ts b/packages/server/src/server/daemon.e2e.test.ts index 135aadf83..2a4a7fa08 100644 --- a/packages/server/src/server/daemon.e2e.test.ts +++ b/packages/server/src/server/daemon.e2e.test.ts @@ -2177,10 +2177,8 @@ describe("daemon E2E", () => { // Concatenate all chunks to form the complete response const fullResponse = assistantChunks.join(""); - console.log("[STREAMING TEXT INTEGRITY TEST]"); - console.log("Number of chunks:", assistantChunks.length); - console.log("Full response:", JSON.stringify(fullResponse)); - console.log("Individual chunks:", assistantChunks.map((c, i) => `[${i}]: ${JSON.stringify(c)}`).join("\n")); + + // CRITICAL ASSERTION 1: Response should not be empty expect(fullResponse.length).toBeGreaterThan(0); @@ -2218,7 +2216,7 @@ describe("daemon E2E", () => { for (const pattern of garbledPatterns) { const match = fullResponse.match(pattern); if (match) { - console.log("Found potential garbled text:", match[0]); + } // Note: We log but don't fail on these patterns as they might occur in valid text // The real test is whether the response is semantically coherent @@ -2266,7 +2264,7 @@ describe("daemon E2E", () => { expect(agent.provider).toBe("claude"); // === MESSAGE 1: Establish conversation context === - console.log("[LONG-RUNNING TEST] Sending message 1..."); + await ctx.client.sendMessage( agent.id, "Remember the number 42. Just confirm you remember it." @@ -2275,11 +2273,10 @@ describe("daemon E2E", () => { let state = await ctx.client.waitForAgentIdle(agent.id, 120000); expect(state.status).toBe("idle"); expect(state.lastError).toBeUndefined(); - console.log("[LONG-RUNNING TEST] Message 1 complete"); // === MESSAGE 2: Build on conversation === ctx.client.clearMessageQueue(); // Clear queue to isolate message 2 - console.log("[LONG-RUNNING TEST] Sending message 2..."); + await ctx.client.sendMessage( agent.id, "Now remember the word 'elephant'. Just confirm you remember both the number and the word." @@ -2288,12 +2285,11 @@ describe("daemon E2E", () => { state = await ctx.client.waitForAgentIdle(agent.id, 120000); expect(state.status).toBe("idle"); expect(state.lastError).toBeUndefined(); - console.log("[LONG-RUNNING TEST] Message 2 complete"); // === MESSAGE 3: This is where the bug was reported to manifest === // Clear queue so we can capture streaming chunks for message 3 only ctx.client.clearMessageQueue(); - console.log("[LONG-RUNNING TEST] Sending message 3 (testing streaming integrity)..."); + await ctx.client.sendMessage( agent.id, "Write a complete sentence using both the number (42) and the word (elephant) you remembered. The sentence should be grammatically correct English." @@ -2302,7 +2298,6 @@ describe("daemon E2E", () => { state = await ctx.client.waitForAgentIdle(agent.id, 120000); expect(state.status).toBe("idle"); expect(state.lastError).toBeUndefined(); - console.log("[LONG-RUNNING TEST] Message 3 complete"); // Collect all assistant_message timeline events from message 3 const queue = ctx.client.getMessageQueue(); @@ -2321,18 +2316,15 @@ describe("daemon E2E", () => { } } - console.log("[LONG-RUNNING TEST] Collected", assistantChunks.length, "chunks"); - // Should have received at least one assistant message chunk expect(assistantChunks.length).toBeGreaterThan(0); // Concatenate all chunks to form the complete response const fullResponse = assistantChunks.join(""); - console.log("[LONG-RUNNING TEST] Full response:", JSON.stringify(fullResponse)); - console.log("[LONG-RUNNING TEST] Chunks:"); + for (let i = 0; i < assistantChunks.length; i++) { - console.log(` [${i}]: ${JSON.stringify(assistantChunks[i])}`); + } // CRITICAL ASSERTION 1: Response should contain expected content @@ -2340,8 +2332,6 @@ describe("daemon E2E", () => { const containsNumber = lowerResponse.includes("42"); const containsWord = lowerResponse.includes("elephant"); - console.log("[LONG-RUNNING TEST] Contains '42':", containsNumber); - console.log("[LONG-RUNNING TEST] Contains 'elephant':", containsWord); expect(containsNumber).toBe(true); expect(containsWord).toBe(true); @@ -2363,7 +2353,7 @@ describe("daemon E2E", () => { if (currentEndsWithLetter && nextStartsWithLetter) { // This could be legitimate (word continues) or a split issue // Log for debugging - console.log(`[LONG-RUNNING TEST] Adjacent letter chunks: "${current.slice(-10)}" + "${next.slice(0, 10)}"`); + } } @@ -2382,7 +2372,7 @@ describe("daemon E2E", () => { // Check for improperly concatenated words (very long "words" that shouldn't exist) const suspiciouslyLongWords = words.filter(w => w.length > 20); if (suspiciouslyLongWords.length > 0) { - console.log("[LONG-RUNNING TEST] Suspiciously long words:", suspiciouslyLongWords); + } // Allow some technical words but flag excessive length expect(suspiciouslyLongWords.filter(w => w.length > 30).length).toBe(0); @@ -2415,7 +2405,6 @@ describe("daemon E2E", () => { // === STEP 1: Run external codex exec with a memorable number === // We use spawn so we can send input and capture output - console.log("[EXTERNAL SESSION TEST] Spawning external codex exec..."); // Use a memorable number that we'll ask about later const magicNumber = 69; @@ -2445,32 +2434,30 @@ describe("daemon E2E", () => { codexProcess.stdout.on("data", (data: Buffer) => { const text = data.toString(); codexOutput += text; - console.log("[EXTERNAL SESSION TEST] stdout:", text); // Look for session ID in output // Format: "session id: 019b5ea3-25d5-7202-bd06-6b1db405e505" const match = text.match(/session id:\s*([0-9a-f-]+)/i); if (match) { sessionId = match[1]; - console.log("[EXTERNAL SESSION TEST] Captured session ID:", sessionId); + } }); codexProcess.stderr.on("data", (data: Buffer) => { const text = data.toString(); - console.log("[EXTERNAL SESSION TEST] stderr:", text); // Session ID might also appear in stderr const match = text.match(/session id:\s*([0-9a-f-]+)/i); if (match && !sessionId) { sessionId = match[1]; - console.log("[EXTERNAL SESSION TEST] Captured session ID from stderr:", sessionId); + } }); codexProcess.on("close", (code) => { clearTimeout(timeout); - console.log("[EXTERNAL SESSION TEST] codex exec exited with code:", code); + if (code === 0 || sessionId) { resolve(); } else { @@ -2484,12 +2471,9 @@ describe("daemon E2E", () => { }); }); - console.log("[EXTERNAL SESSION TEST] Full output:", codexOutput); - // Verify we captured the session ID expect(sessionId).not.toBeNull(); expect(sessionId).toMatch(/^[0-9a-f-]+$/); - console.log("[EXTERNAL SESSION TEST] Session ID:", sessionId); // === STEP 2: Find the transcript file for this session === // Codex stores transcripts at ~/.codex/sessions/**/*-{sessionId}.jsonl @@ -2497,8 +2481,6 @@ describe("daemon E2E", () => { const actualCodexHome = path.join(process.env.HOME || "", ".codex"); const sessionsDir = path.join(actualCodexHome, "sessions"); - console.log("[EXTERNAL SESSION TEST] Looking for transcript in:", sessionsDir); - // Find the transcript file function findTranscriptFile(dir: string, targetSessionId: string): string | null { try { @@ -2519,7 +2501,6 @@ describe("daemon E2E", () => { } const transcriptFile = findTranscriptFile(sessionsDir, sessionId!); - console.log("[EXTERNAL SESSION TEST] Found transcript file:", transcriptFile); // Verify transcript file exists expect(transcriptFile).not.toBeNull(); @@ -2527,11 +2508,10 @@ describe("daemon E2E", () => { // Read and verify transcript has content const transcriptContent = readFileSync(transcriptFile!, "utf-8"); - console.log("[EXTERNAL SESSION TEST] Transcript size:", transcriptContent.length, "bytes"); + expect(transcriptContent.length).toBeGreaterThan(0); // === STEP 3: Import this session into the daemon === - console.log("[EXTERNAL SESSION TEST] Creating daemon agent with experimental_resume..."); const agent = await ctx.client.createAgent({ provider: "codex", @@ -2547,10 +2527,9 @@ describe("daemon E2E", () => { expect(agent.id).toBeTruthy(); expect(agent.status).toBe("idle"); - console.log("[EXTERNAL SESSION TEST] Created agent:", agent.id); // === STEP 4: Ask the daemon agent about the number === - console.log("[EXTERNAL SESSION TEST] Asking about the remembered number..."); + ctx.client.clearMessageQueue(); await ctx.client.sendMessage( @@ -2581,7 +2560,6 @@ describe("daemon E2E", () => { } const fullResponse = assistantMessages.join(""); - console.log("[EXTERNAL SESSION TEST] Agent response:", JSON.stringify(fullResponse)); // CRITICAL ASSERTION: The response should contain the magic number // This proves the daemon agent successfully loaded the external session's context @@ -2793,7 +2771,7 @@ describe("daemon E2E", () => { const magicNumber = 69; // === STEP 1: Create Claude agent and have it remember a number === - console.log("[CLAUDE PERSISTENCE TEST] Creating Claude agent..."); + const agent = await ctx.client.createAgent({ provider: "claude", cwd, @@ -2804,10 +2782,9 @@ describe("daemon E2E", () => { expect(agent.id).toBeTruthy(); expect(agent.status).toBe("idle"); expect(agent.provider).toBe("claude"); - console.log("[CLAUDE PERSISTENCE TEST] Created agent:", agent.id); // === STEP 2: Ask it to remember the number === - console.log("[CLAUDE PERSISTENCE TEST] Asking to remember number..."); + await ctx.client.sendMessage( agent.id, `Remember this number: ${magicNumber}. Just confirm you've remembered it and reply with a single short sentence.` @@ -2833,7 +2810,7 @@ describe("daemon E2E", () => { } } const confirmationResponse = confirmationMessages.join(""); - console.log("[CLAUDE PERSISTENCE TEST] Confirmation response:", JSON.stringify(confirmationResponse)); + expect(confirmationResponse.length).toBeGreaterThan(0); // === STEP 3: Get persistence handle and delete agent === @@ -2841,24 +2818,21 @@ describe("daemon E2E", () => { const persistence = afterRemember.persistence; expect(persistence?.provider).toBe("claude"); expect(persistence?.sessionId).toBeTruthy(); - console.log("[CLAUDE PERSISTENCE TEST] Got persistence handle:", persistence?.sessionId); // Delete the agent await ctx.client.deleteAgent(agent.id); - console.log("[CLAUDE PERSISTENCE TEST] Deleted agent"); // === STEP 4: Resume the agent using persistence handle === - console.log("[CLAUDE PERSISTENCE TEST] Resuming agent..."); + ctx.client.clearMessageQueue(); const resumedAgent = await ctx.client.resumeAgent(persistence!); expect(resumedAgent.id).toBeTruthy(); expect(resumedAgent.status).toBe("idle"); expect(resumedAgent.provider).toBe("claude"); - console.log("[CLAUDE PERSISTENCE TEST] Resumed agent:", resumedAgent.id); // === STEP 5: Ask about the remembered number === - console.log("[CLAUDE PERSISTENCE TEST] Asking about remembered number..."); + ctx.client.clearMessageQueue(); await ctx.client.sendMessage( resumedAgent.id, @@ -2885,7 +2859,6 @@ describe("daemon E2E", () => { } } const fullResponse = recallMessages.join(""); - console.log("[CLAUDE PERSISTENCE TEST] Recall response:", JSON.stringify(fullResponse)); // CRITICAL ASSERTION: The response should contain the magic number // This proves the Claude agent successfully preserved conversation context @@ -2917,7 +2890,6 @@ describe("daemon E2E", () => { expect(agent.provider).toBe("claude"); // === MESSAGE 1: Start a long-running prompt that will be interrupted === - console.log("[RACE CONDITION TEST] Sending message 1 (will be interrupted)..."); // Record queue position BEFORE message 1 to find the cutoff point later const msg1StartPosition = ctx.client.getMessageQueue().length; @@ -2935,11 +2907,9 @@ describe("daemon E2E", () => { // === MESSAGE 2: Immediately send another message to interrupt === // This triggers the race condition where Turn 2's forwardPromptEvents // resets streamedAssistantTextThisTurn while Turn 1 is still reading it - console.log("[RACE CONDITION TEST] Sending message 2 (interrupting turn 1)..."); // Record queue position BEFORE message 2 to find message 2 chunks const msg2StartPosition = ctx.client.getMessageQueue().length; - console.log("[RACE CONDITION TEST] Queue position before msg2:", msg2StartPosition); await ctx.client.sendMessage( agent.id, @@ -2948,7 +2918,7 @@ describe("daemon E2E", () => { // Wait for Turn 2 to complete - use a manual polling approach // We need to wait for: running -> idle (after msg2's user_message) - console.log("[RACE CONDITION TEST] Waiting for agent to become idle after msg2..."); + const maxWaitMs = 120000; const pollIntervalMs = 500; const startTime = Date.now(); @@ -2987,7 +2957,7 @@ describe("daemon E2E", () => { } if (sawIdleAfterRunning) { - console.log("[RACE CONDITION TEST] Agent became idle/error after msg2:", lastState?.status); + break; } await new Promise(resolve => setTimeout(resolve, pollIntervalMs)); @@ -2996,26 +2966,25 @@ describe("daemon E2E", () => { expect(lastState).not.toBeNull(); expect(lastState!.status).toBe("idle"); expect(lastState!.lastError).toBeUndefined(); - console.log("[RACE CONDITION TEST] Message 2 complete"); // Collect assistant_message chunks from message 2 only (after msg2StartPosition) const queue = ctx.client.getMessageQueue(); const assistantChunks: string[] = []; // Debug: dump all events from queue - console.log("[RACE CONDITION TEST] Full queue dump (all events):"); + for (let i = 0; i < queue.length; i++) { const m = queue[i]; if (m.type === "agent_stream" && m.payload.agentId === agent.id) { const event = m.payload.event; if (event.type === "timeline") { const item = event.item; - console.log(` [${i}] (${i >= msg2StartPosition ? "msg2" : "msg1"}): timeline/${item.type}`, item.type === "assistant_message" || item.type === "user_message" ? JSON.stringify((item as any).text?.substring(0, 50)) : ""); + } else { - console.log(` [${i}] (${i >= msg2StartPosition ? "msg2" : "msg1"}): ${event.type}`, (event as any).error || ""); + } } else if (m.type === "agent_state" && m.payload.id === agent.id) { - console.log(` [${i}] (${i >= msg2StartPosition ? "msg2" : "msg1"}): agent_state -> ${m.payload.status}`, m.payload.lastError || ""); + } } @@ -3034,7 +3003,7 @@ describe("daemon E2E", () => { const item = m.payload.event.item; if (item.type === "user_message" && (item.text as string)?.includes("Hello world")) { foundMsg2UserMessage = true; - console.log("[RACE CONDITION TEST] Found message 2 user prompt"); + } // Collect assistant messages after we found the user message if (foundMsg2UserMessage && item.type === "assistant_message" && item.text) { @@ -3043,10 +3012,9 @@ describe("daemon E2E", () => { } } - console.log("[RACE CONDITION TEST] Collected", assistantChunks.length, "chunks"); - console.log("[RACE CONDITION TEST] Chunks:"); + for (let i = 0; i < assistantChunks.length; i++) { - console.log(` [${i}]: ${JSON.stringify(assistantChunks[i])}`); + } // Should have received at least one assistant message chunk @@ -3054,7 +3022,6 @@ describe("daemon E2E", () => { // Concatenate all chunks const fullResponse = assistantChunks.join(""); - console.log("[RACE CONDITION TEST] Full response:", JSON.stringify(fullResponse)); // CRITICAL ASSERTION: Response should contain coherent text // If there's a race condition with flag corruption, we might get: @@ -3065,7 +3032,7 @@ describe("daemon E2E", () => { // Check for basic coherence - should have recognizable words const wordPattern = /\b[a-zA-Z]+\b/g; const words = fullResponse.match(wordPattern) || []; - console.log("[RACE CONDITION TEST] Words found:", words.length); + expect(words.length).toBeGreaterThan(0); // Check for UTF-8 corruption @@ -3077,7 +3044,7 @@ describe("daemon E2E", () => { // Check for suspiciously long "words" that indicate missing spaces/garbling const suspiciouslyLongWords = words.filter(w => w.length > 30); if (suspiciouslyLongWords.length > 0) { - console.log("[RACE CONDITION TEST] Suspiciously long words:", suspiciouslyLongWords); + } expect(suspiciouslyLongWords.length).toBe(0); @@ -3093,8 +3060,8 @@ describe("daemon E2E", () => { lowerResponse.includes("babbage"); if (containsComputingContent) { - console.log("[RACE CONDITION TEST] ERROR: Response contains content from message 1!"); - console.log("[RACE CONDITION TEST] This indicates the race condition: message 2 was sent but message 1's response was returned"); + + } // This MUST fail if we got message 1's response instead of message 2's expect(containsComputingContent).toBe(false); @@ -3121,7 +3088,7 @@ describe("daemon E2E", () => { expect(agent.id).toBeTruthy(); // Start a long-running tool call (sleep command) - console.log("[TOOL INTERRUPT TEST] Sending message 1 with long sleep command..."); + const msg1StartPosition = ctx.client.getMessageQueue().length; await ctx.client.sendMessage( @@ -3130,7 +3097,7 @@ describe("daemon E2E", () => { ); // Wait for the tool call to start (agent should be running and we should see the bash tool) - console.log("[TOOL INTERRUPT TEST] Waiting for tool call to start..."); + let sawToolCall = false; const toolWaitStart = Date.now(); while (Date.now() - toolWaitStart < 30000) { @@ -3146,7 +3113,7 @@ describe("daemon E2E", () => { const tc = m.payload.event.item; if (tc.name?.toLowerCase().includes("bash") || tc.name?.toLowerCase().includes("shell")) { sawToolCall = true; - console.log("[TOOL INTERRUPT TEST] Tool call started:", tc.name); + break; } } @@ -3158,7 +3125,7 @@ describe("daemon E2E", () => { expect(sawToolCall).toBe(true); // Now send an interrupting message while the tool is running - console.log("[TOOL INTERRUPT TEST] Sending message 2 to interrupt..."); + const msg2StartPosition = ctx.client.getMessageQueue().length; await ctx.client.sendMessage( @@ -3167,7 +3134,7 @@ describe("daemon E2E", () => { ); // Track state transitions - console.log("[TOOL INTERRUPT TEST] Monitoring state transitions..."); + const stateTransitions: Array<{ status: string; timestamp: number; lastError?: string }> = []; const monitorStart = Date.now(); @@ -3183,7 +3150,7 @@ describe("daemon E2E", () => { timestamp: Date.now() - monitorStart, lastError: m.payload.lastError, }); - console.log(`[TOOL INTERRUPT TEST] State: ${m.payload.status} at ${Date.now() - monitorStart}ms`, m.payload.lastError || ""); + } } } @@ -3198,14 +3165,11 @@ describe("daemon E2E", () => { await new Promise(r => setTimeout(r, 200)); } - console.log("[TOOL INTERRUPT TEST] State transitions:", JSON.stringify(stateTransitions, null, 2)); - // Verify we got proper state transitions expect(stateTransitions.length).toBeGreaterThan(0); // Check if we ended in idle (success) or error const finalState = stateTransitions[stateTransitions.length - 1]; - console.log("[TOOL INTERRUPT TEST] Final state:", finalState); // Look for the response to message 2 const queue = ctx.client.getMessageQueue(); @@ -3229,8 +3193,6 @@ describe("daemon E2E", () => { } } - console.log("[TOOL INTERRUPT TEST] Found user message 2:", foundMsg2User); - console.log("[TOOL INTERRUPT TEST] Assistant messages after msg2:", assistantMessages); // The key assertion: agent should have responded to message 2 if (finalState.status === "idle") { @@ -3258,7 +3220,7 @@ describe("daemon E2E", () => { expect(agent.id).toBeTruthy(); // Send 3 messages in rapid succession without waiting - console.log("[RAPID MSG TEST] Sending 3 messages rapidly..."); + const startPosition = ctx.client.getMessageQueue().length; const msg1 = "Say: MESSAGE_ONE"; @@ -3285,32 +3247,30 @@ describe("daemon E2E", () => { // Send all 3 messages await ctx.client.sendMessage(agent.id, msg1); - console.log("[RAPID MSG TEST] MSG1 sent, waiting briefly..."); + await new Promise(r => setTimeout(r, 100)); await ctx.client.sendMessage(agent.id, msg2); - console.log("[RAPID MSG TEST] MSG2 sent, waiting briefly..."); + await new Promise(r => setTimeout(r, 100)); await ctx.client.sendMessage(agent.id, msg3); - console.log("[RAPID MSG TEST] MSG3 sent"); // First, wait until all 3 user messages are recorded - console.log("[RAPID MSG TEST] Waiting for all 3 user messages to be recorded..."); + const userMsgWaitStart = Date.now(); while (Date.now() - userMsgWaitStart < 30000) { const count = countUserMessages(); - console.log(`[RAPID MSG TEST] User message count: ${count}`); + if (count >= 3) break; await new Promise(r => setTimeout(r, 200)); } const finalUserMsgCount = countUserMessages(); - console.log(`[RAPID MSG TEST] Final user message count: ${finalUserMsgCount}`); // Now wait for agent to become idle after processing all 3 messages // We need to see at least 3 running transitions to know all messages were processed - console.log("[RAPID MSG TEST] Waiting for agent to finish processing all messages..."); + const waitStart = Date.now(); let runningCount = 0; let finalState: AgentSnapshotPayload | null = null; @@ -3338,8 +3298,6 @@ describe("daemon E2E", () => { await new Promise(r => setTimeout(r, 500)); } - console.log("[RAPID MSG TEST] Final state:", finalState?.status, finalState?.lastError); - console.log("[RAPID MSG TEST] Total running transitions:", runningCount); // Analyze what happened const queue = ctx.client.getMessageQueue(); @@ -3367,10 +3325,8 @@ describe("daemon E2E", () => { } } - console.log("[RAPID MSG TEST] User messages recorded:", userMessages.length, userMessages); - console.log("[RAPID MSG TEST] Assistant messages:", assistantMessages.length, JSON.stringify(assistantMessages)); - console.log("[RAPID MSG TEST] State changes:", stateChanges.join(" -> ")); - console.log("[RAPID MSG TEST] Total queue items since start:", queue.length - startPosition); + + // All 3 user messages should have been recorded expect(userMessages.length).toBe(3); @@ -3380,7 +3336,6 @@ describe("daemon E2E", () => { // The last turn should have completed successfully (not failed due to race condition) const lastResponse = assistantMessages[assistantMessages.length - 1]?.toLowerCase() || ""; - console.log("[RAPID MSG TEST] Last response:", lastResponse); // Verify we got a proper turn_completed event (not turn_failed from race condition) const turnCompletedEvents = queue.filter((m, i) => @@ -3395,8 +3350,7 @@ describe("daemon E2E", () => { m.payload.agentId === agent.id && m.payload.event.type === "turn_failed" ); - console.log("[RAPID MSG TEST] Turn completed events:", turnCompletedEvents.length); - console.log("[RAPID MSG TEST] Turn failed events:", turnFailedEvents.length); + // The final turn should complete successfully, not fail expect(turnCompletedEvents.length).toBeGreaterThan(0); @@ -3405,7 +3359,7 @@ describe("daemon E2E", () => { // The response should mention "three" since that was the last message sent const combinedResponse = assistantMessages.join(" ").toLowerCase(); - console.log("[RAPID MSG TEST] Combined response:", combinedResponse); + expect(combinedResponse).toContain("three"); await ctx.client.deleteAgent(agent.id); @@ -3446,16 +3400,7 @@ describe("daemon E2E", () => { // Helper to log tool call structure in a consistent format function logToolCall(prefix: string, tc: AgentTimelineItem): void { if (tc.type !== "tool_call") return; - console.log( - `[${prefix}]`, - JSON.stringify({ - name: tc.name, - callId: tc.callId, - status: tc.status, - hasInput: tc.input !== undefined, - hasOutput: tc.output !== undefined, - }) - ); + } test( diff --git a/packages/server/src/server/index.ts b/packages/server/src/server/index.ts index 3f35d34a2..070ca7913 100644 --- a/packages/server/src/server/index.ts +++ b/packages/server/src/server/index.ts @@ -7,30 +7,34 @@ dotenv.config({ path: path.resolve(__dirname, "../../.env") }); import { createPaseoDaemon } from "./bootstrap.js"; import { loadConfig } from "./config.js"; import { resolvePaseoHome } from "./paseo-home.js"; +import { createRootLogger } from "./logger.js"; +import { loadPersistedConfig } from "./persisted-config.js"; async function main() { const paseoHome = resolvePaseoHome(); + const persistedConfig = loadPersistedConfig(paseoHome); + const logger = createRootLogger(persistedConfig); const config = loadConfig(paseoHome); const daemon = await createPaseoDaemon(config); await daemon.start(); const handleShutdown = async (signal: string) => { - console.log(`\n${signal} received, shutting down gracefully...`); + logger.info(`${signal} received, shutting down gracefully...`); const forceExit = setTimeout(() => { - console.log("Forcing shutdown - HTTP server didn't close in time"); + logger.warn("Forcing shutdown - HTTP server didn't close in time"); process.exit(1); }, 10000); try { await daemon.stop(); clearTimeout(forceExit); - console.log("Server closed"); + logger.info("Server closed"); process.exit(0); - } catch (error) { + } catch (err) { clearTimeout(forceExit); - console.error("Shutdown failed:", error); + logger.error({ err }, "Shutdown failed"); process.exit(1); } }; @@ -39,7 +43,11 @@ async function main() { process.on("SIGINT", () => handleShutdown("SIGINT")); } -main().catch((error) => { - console.error("Failed to start server:", error); +main().catch((err) => { + // Logger might not be initialized yet, so we need to handle this specially + const paseoHome = resolvePaseoHome(); + const persistedConfig = loadPersistedConfig(paseoHome); + const logger = createRootLogger(persistedConfig); + logger.error({ err }, "Failed to start server"); process.exit(1); }); diff --git a/packages/server/src/server/logger.test.ts b/packages/server/src/server/logger.test.ts new file mode 100644 index 000000000..dc9c945d8 --- /dev/null +++ b/packages/server/src/server/logger.test.ts @@ -0,0 +1,109 @@ +import { describe, it, expect, beforeEach, afterEach } from "vitest"; +import { resolveLogConfig } from "./logger.js"; +import type { PersistedConfig } from "./persisted-config.js"; + +describe("resolveLogConfig", () => { + const originalEnv = process.env; + + beforeEach(() => { + process.env = { ...originalEnv }; + delete process.env.PASEO_LOG; + delete process.env.PASEO_LOG_FORMAT; + }); + + afterEach(() => { + process.env = originalEnv; + }); + + it("returns defaults when no config or env vars", () => { + const result = resolveLogConfig(undefined); + expect(result).toEqual({ level: "info", format: "pretty" }); + }); + + it("uses config.json values over defaults", () => { + const config: PersistedConfig = { + log: { + level: "debug", + format: "json", + }, + }; + const result = resolveLogConfig(config); + expect(result).toEqual({ level: "debug", format: "json" }); + }); + + it("uses env PASEO_LOG over config.json level", () => { + process.env.PASEO_LOG = "warn"; + const config: PersistedConfig = { + log: { + level: "debug", + format: "json", + }, + }; + const result = resolveLogConfig(config); + expect(result).toEqual({ level: "warn", format: "json" }); + }); + + it("uses env PASEO_LOG_FORMAT over config.json format", () => { + process.env.PASEO_LOG_FORMAT = "pretty"; + const config: PersistedConfig = { + log: { + level: "debug", + format: "json", + }, + }; + const result = resolveLogConfig(config); + expect(result).toEqual({ level: "debug", format: "pretty" }); + }); + + it("env vars override both config.json and defaults", () => { + process.env.PASEO_LOG = "error"; + process.env.PASEO_LOG_FORMAT = "json"; + const config: PersistedConfig = { + log: { + level: "info", + format: "pretty", + }, + }; + const result = resolveLogConfig(config); + expect(result).toEqual({ level: "error", format: "json" }); + }); + + it("handles partial config - level only", () => { + const config: PersistedConfig = { + log: { + level: "warn", + }, + }; + const result = resolveLogConfig(config); + expect(result).toEqual({ level: "warn", format: "pretty" }); + }); + + it("handles partial config - format only", () => { + const config: PersistedConfig = { + log: { + format: "json", + }, + }; + const result = resolveLogConfig(config); + expect(result).toEqual({ level: "info", format: "json" }); + }); + + it("handles empty log object in config", () => { + const config: PersistedConfig = { + log: {}, + }; + const result = resolveLogConfig(config); + expect(result).toEqual({ level: "info", format: "pretty" }); + }); + + it("supports all log levels", () => { + const levels: Array<"trace" | "debug" | "info" | "warn" | "error" | "fatal"> = + ["trace", "debug", "info", "warn", "error", "fatal"]; + + for (const level of levels) { + process.env.PASEO_LOG = level; + const result = resolveLogConfig(undefined); + expect(result.level).toBe(level); + } + }); +}); diff --git a/packages/server/src/server/logger.ts b/packages/server/src/server/logger.ts new file mode 100644 index 000000000..a9f9f20ee --- /dev/null +++ b/packages/server/src/server/logger.ts @@ -0,0 +1,62 @@ +import pino from "pino"; +import type { PersistedConfig } from "./persisted-config.js"; + +export type LogLevel = "trace" | "debug" | "info" | "warn" | "error" | "fatal"; +export type LogFormat = "pretty" | "json"; + +export interface ResolvedLogConfig { + level: LogLevel; + format: LogFormat; +} + +export function resolveLogConfig( + persistedConfig: PersistedConfig | undefined +): ResolvedLogConfig { + const envLevel = process.env.PASEO_LOG as LogLevel | undefined; + const envFormat = process.env.PASEO_LOG_FORMAT as LogFormat | undefined; + + const level: LogLevel = + envLevel ?? persistedConfig?.log?.level ?? "info"; + const format: LogFormat = + envFormat ?? persistedConfig?.log?.format ?? "pretty"; + + return { level, format }; +} + +let rootLogger: pino.Logger | undefined; + +export function createRootLogger( + persistedConfig: PersistedConfig | undefined +): pino.Logger { + const config = resolveLogConfig(persistedConfig); + + const transport = + config.format === "pretty" + ? { + target: "pino-pretty", + options: { + colorize: true, + singleLine: true, + ignore: "pid,hostname", + }, + } + : undefined; + + rootLogger = pino({ + level: config.level, + transport, + }); + + return rootLogger; +} + +export function getRootLogger(): pino.Logger { + if (!rootLogger) { + throw new Error("Root logger not initialized. Call createRootLogger first."); + } + return rootLogger; +} + +export function createChildLogger(name: string): pino.Logger { + return getRootLogger().child({ name }); +} diff --git a/packages/server/src/server/persisted-config.ts b/packages/server/src/server/persisted-config.ts index db6724747..088d08810 100644 --- a/packages/server/src/server/persisted-config.ts +++ b/packages/server/src/server/persisted-config.ts @@ -1,6 +1,7 @@ import { existsSync, readFileSync, writeFileSync } from "node:fs"; import path from "node:path"; import { z } from "zod"; +import { getRootLogger } from "./logger.js"; const PersistedConfigSchema = z.object({ listen: z.string().optional(), @@ -9,6 +10,14 @@ const PersistedConfigSchema = z.object({ allowedOrigins: z.array(z.string()).default([]), }) .default({}), + log: z + .object({ + level: z + .enum(["trace", "debug", "info", "warn", "error", "fatal"]) + .optional(), + format: z.enum(["pretty", "json"]).optional(), + }) + .optional(), }); export type PersistedConfig = z.infer; @@ -19,11 +28,21 @@ function getConfigPath(paseoHome: string): string { return path.join(paseoHome, CONFIG_FILENAME); } +function getLogger() { + try { + return getRootLogger().child({ module: "config" }); + } catch { + // Root logger not initialized yet, return null + return null; + } +} + export function loadPersistedConfig(paseoHome: string): PersistedConfig { + const logger = getLogger(); const configPath = getConfigPath(paseoHome); if (!existsSync(configPath)) { - console.log(`[Config] No config file at ${configPath}, using defaults`); + logger?.info(`No config file at ${configPath}, using defaults`); return PersistedConfigSchema.parse({}); } @@ -51,7 +70,7 @@ export function loadPersistedConfig(paseoHome: string): PersistedConfig { throw new Error(`[Config] Invalid config in ${configPath}:\n${issues}`); } - console.log(`[Config] Loaded from ${configPath}`); + logger?.info(`Loaded from ${configPath}`); return result.data; } @@ -59,6 +78,7 @@ export function savePersistedConfig( paseoHome: string, config: PersistedConfig ): void { + const logger = getLogger(); const configPath = getConfigPath(paseoHome); const result = PersistedConfigSchema.safeParse(config); @@ -71,7 +91,7 @@ export function savePersistedConfig( try { writeFileSync(configPath, JSON.stringify(result.data, null, 2) + "\n"); - console.log(`[Config] Saved to ${configPath}`); + logger?.info(`Saved to ${configPath}`); } catch (err) { const message = err instanceof Error ? err.message : String(err); throw new Error(`[Config] Failed to write ${configPath}: ${message}`); diff --git a/packages/server/src/server/persistence-hooks.ts b/packages/server/src/server/persistence-hooks.ts index 389764588..0d73064ec 100644 --- a/packages/server/src/server/persistence-hooks.ts +++ b/packages/server/src/server/persistence-hooks.ts @@ -7,6 +7,9 @@ import type { AgentRegistry, StoredAgentRecord, } from "./agent/agent-registry.js"; +import { getRootLogger } from "./logger.js"; + +const logger = getRootLogger().child({ module: "persistence" }); type AgentRegistryPersistence = Pick; type AgentManagerStateSource = Pick; @@ -28,7 +31,7 @@ export function attachAgentRegistryPersistence( return; } void registry.applySnapshot(event.agent).catch((error) => { - console.error("[AgentRegistry] Failed to persist agent snapshot:", error); + logger.error({ err: error, agentId: event.agent.id }, "Failed to persist agent snapshot"); }); }); diff --git a/packages/server/src/server/persistence.ts b/packages/server/src/server/persistence.ts index 703aac24a..d19d1f771 100644 --- a/packages/server/src/server/persistence.ts +++ b/packages/server/src/server/persistence.ts @@ -2,6 +2,9 @@ import { readFile, writeFile, readdir, unlink, mkdir, stat } from "fs/promises"; import { join } from "path"; import type { ModelMessage } from "@ai-sdk/provider-utils"; import { standardizePrompt } from "ai/internal"; +import { getRootLogger } from "./logger.js"; + +const logger = getRootLogger().child({ module: "persistence" }); const CONVERSATIONS_DIR = join(process.cwd(), "conversations"); @@ -44,13 +47,14 @@ export async function saveConversation( }; await writeFile(filepath, JSON.stringify(data, null, 2), "utf-8"); - console.log( - `[Persistence] Saved conversation ${conversationId} (${messages.length} messages)` + logger.info( + { conversationId, messageCount: messages.length }, + "Saved conversation" ); } catch (error) { - console.error( - `[Persistence] Failed to save conversation ${conversationId}:`, - error + logger.error( + { err: error, conversationId }, + "Failed to save conversation" ); throw error; } @@ -70,7 +74,7 @@ export async function loadConversation( try { await stat(filepath); } catch { - console.log(`[Persistence] Conversation ${conversationId} not found`); + logger.debug({ conversationId }, "Conversation not found"); return null; } @@ -83,15 +87,16 @@ export async function loadConversation( prompt: data.messages, }); - console.log( - `[Persistence] Loaded conversation ${conversationId} (${data.messageCount} messages)` + logger.info( + { conversationId, messageCount: data.messageCount }, + "Loaded conversation" ); return result.messages as ModelMessage[]; } catch (error) { - console.error( - `[Persistence] Failed to load conversation ${conversationId}:`, - error + logger.error( + { err: error, conversationId }, + "Failed to load conversation" ); return null; } @@ -121,7 +126,7 @@ export async function listConversations(): Promise { messageCount: data.messageCount, }); } catch (error) { - console.error(`[Persistence] Failed to read conversation ${file}:`, error); + logger.error({ err: error, file }, "Failed to read conversation"); // Skip invalid files } } @@ -131,7 +136,7 @@ export async function listConversations(): Promise { return conversations; } catch (error) { - console.error("[Persistence] Failed to list conversations:", error); + logger.error({ err: error }, "Failed to list conversations"); return []; } } @@ -143,11 +148,11 @@ export async function deleteConversation(conversationId: string): Promise try { const filepath = join(CONVERSATIONS_DIR, `${conversationId}.json`); await unlink(filepath); - console.log(`[Persistence] Deleted conversation ${conversationId}`); + logger.info({ conversationId }, "Deleted conversation"); } catch (error) { - console.error( - `[Persistence] Failed to delete conversation ${conversationId}:`, - error + logger.error( + { err: error, conversationId }, + "Failed to delete conversation" ); throw error; } diff --git a/packages/server/src/server/push/push-service.ts b/packages/server/src/server/push/push-service.ts index 652a6acb8..b1d726dd2 100644 --- a/packages/server/src/server/push/push-service.ts +++ b/packages/server/src/server/push/push-service.ts @@ -1,5 +1,8 @@ +import { getRootLogger } from "../logger.js"; import type { PushTokenStore } from "./token-store.js"; +const logger = getRootLogger().child({ module: "push", component: "push-service" }); + interface PushPayload { title: string; body: string; @@ -71,8 +74,9 @@ export class PushService { }); if (!response.ok) { - console.error( - `[PushService] Expo push API error: ${response.status} ${response.statusText}` + logger.error( + { status: response.status, statusText: response.statusText }, + "Expo push API error" ); return; } @@ -80,7 +84,7 @@ export class PushService { const result = (await response.json()) as { data: ExpoPushTicket[] }; this.handleTickets(messages, result.data); } catch (error) { - console.error("[PushService] Failed to send push notifications:", error); + logger.error({ err: error }, "Failed to send push notifications"); } } @@ -93,9 +97,9 @@ export class PushService { const message = messages[i]; if (ticket.status === "error") { - console.error( - `[PushService] Push failed for token: ${ticket.message}`, - ticket.details + logger.error( + { token: message.to, message: ticket.message, details: ticket.details }, + "Push failed for token" ); // Remove invalid tokens diff --git a/packages/server/src/server/push/token-store.ts b/packages/server/src/server/push/token-store.ts index 75601fbbf..0b2395cab 100644 --- a/packages/server/src/server/push/token-store.ts +++ b/packages/server/src/server/push/token-store.ts @@ -1,3 +1,7 @@ +import { getRootLogger } from "../logger.js"; + +const logger = getRootLogger().child({ module: "push", component: "token-store" }); + /** * Simple in-memory store for Expo push tokens. * Tokens are used to send push notifications when all clients are stale. @@ -7,13 +11,13 @@ export class PushTokenStore { addToken(token: string): void { this.tokens.add(token); - console.log(`[PushTokenStore] Added token (total: ${this.tokens.size})`); + logger.debug({ total: this.tokens.size }, "Added token"); } removeToken(token: string): void { const deleted = this.tokens.delete(token); if (deleted) { - console.log(`[PushTokenStore] Removed token (total: ${this.tokens.size})`); + logger.debug({ total: this.tokens.size }, "Removed token"); } } diff --git a/packages/server/src/server/session.ts b/packages/server/src/server/session.ts index 06d5ad2c5..6fb00459e 100644 --- a/packages/server/src/server/session.ts +++ b/packages/server/src/server/session.ts @@ -69,6 +69,9 @@ import { validateBranchSlug, } from "../utils/worktree.js"; import { expandTilde } from "../utils/path.js"; +import { getRootLogger } from "./logger.js"; + +const logger = getRootLogger().child({ module: "session" }); type AgentMcpClientConfig = { agentMcpUrl: string; @@ -159,8 +162,9 @@ function coerceAgentProvider(value: string, agentId?: string): AgentProvider { if (isValidAgentProvider(value)) { return value; } - console.warn( - `[Session] Unknown provider '${value}' for agent ${agentId ?? "unknown"}; defaulting to '${DEFAULT_AGENT_PROVIDER}'` + logger.warn( + { value, agentId, defaultProvider: DEFAULT_AGENT_PROVIDER }, + `Unknown provider '${value}' for agent ${agentId ?? "unknown"}; defaulting to '${DEFAULT_AGENT_PROVIDER}'` ); return DEFAULT_AGENT_PROVIDER; } @@ -173,13 +177,14 @@ function toAgentPersistenceHandle( } const provider = handle.provider; if (!isValidAgentProvider(provider)) { - console.warn( - `[Session] Ignoring persistence handle with unknown provider '${provider}'` + logger.warn( + { provider }, + `Ignoring persistence handle with unknown provider '${provider}'` ); return null; } if (!handle.sessionId) { - console.warn("[Session] Ignoring persistence handle missing sessionId"); + logger.warn("Ignoring persistence handle missing sessionId"); return null; } return { @@ -199,6 +204,7 @@ export class Session { private readonly clientId: string; private readonly conversationId: string; private readonly onMessage: (msg: SessionOutboundMessage) => void; + private readonly sessionLogger: ReturnType; // State machine private abortController: AbortController; @@ -263,12 +269,14 @@ export class Session { this.agentRegistry = agentRegistry; this.agentMcpConfig = agentMcpConfig; this.abortController = new AbortController(); + this.sessionLogger = logger.child({ clientId: this.clientId, conversationId: this.conversationId }); // Initialize conversation history if (options?.initialMessages) { this.messages = options.initialMessages; - console.log( - `[Session ${this.clientId}] Restored conversation ${this.conversationId} with ${this.messages.length} messages` + this.sessionLogger.info( + { messageCount: this.messages.length }, + `Restored conversation with ${this.messages.length} messages` ); } @@ -280,9 +288,7 @@ export class Session { void this.initializeAgentMcp(); this.subscribeToAgentEvents(); - console.log( - `[Session ${this.clientId}] Created with conversation ${this.conversationId}` - ); + this.sessionLogger.info("Session created"); } /** @@ -347,15 +353,17 @@ export class Session { return; } - console.log( - `[Session ${this.clientId}] Interrupting active run for agent ${agentId}` + this.sessionLogger.info( + { agentId }, + `Interrupting active run for agent ${agentId}` ); try { const cancelled = await this.agentManager.cancelAgentRun(agentId); if (!cancelled) { - console.warn( - `[Session ${this.clientId}] Agent ${agentId} reported running but no active run was cancelled` + this.sessionLogger.warn( + { agentId }, + `Agent ${agentId} reported running but no active run was cancelled` ); } @@ -375,9 +383,9 @@ export class Session { await new Promise((resolve) => setTimeout(resolve, pollIntervalMs)); } } catch (error) { - console.error( - `[Session ${this.clientId}] Failed to interrupt agent ${agentId}:`, - error + this.sessionLogger.error( + { err: error, agentId }, + `Failed to interrupt agent ${agentId}` ); throw error; } @@ -387,8 +395,9 @@ export class Session { * Start streaming an agent run and forward results via the websocket broadcast */ private startAgentStream(agentId: string, prompt: AgentPromptInput): void { - console.log( - `[Session ${this.clientId}] Starting agent stream for ${agentId}` + this.sessionLogger.info( + { agentId }, + `Starting agent stream for ${agentId}` ); let iterator: AsyncGenerator; @@ -417,9 +426,9 @@ export class Session { ): void { const message = error instanceof Error ? error.message : typeof error === "string" ? error : "Unknown error"; - console.error( - `[Session ${this.clientId}] ${context} for agent ${agentId}:`, - error + this.sessionLogger.error( + { err: error, agentId, context }, + `${context} for agent ${agentId}` ); this.emit({ type: "activity_log", @@ -454,13 +463,14 @@ export class Session { this.agentTools = (await this.agentMcpClient.tools()) as ToolSet; const agentToolCount = Object.keys(this.agentTools ?? {}).length; - console.log( - `[Session ${this.clientId}] Agent MCP initialized with ${agentToolCount} tools` + this.sessionLogger.info( + { agentToolCount }, + `Agent MCP initialized with ${agentToolCount} tools` ); } catch (error) { - console.error( - `[Session ${this.clientId}] Failed to initialize Agent MCP:`, - error + this.sessionLogger.error( + { err: error }, + "Failed to initialize Agent MCP" ); } } @@ -487,10 +497,10 @@ export class Session { } as const; const itemType = event.event.type === "timeline" ? event.event.item.type : undefined; - const logMessage = itemType - ? `[SERVER AGENT_STREAM] timestamp=${Date.now()} agentId=${event.agentId} eventType=${event.event.type} itemType=${itemType}` - : `[SERVER AGENT_STREAM] timestamp=${Date.now()} agentId=${event.agentId} eventType=${event.event.type}`; - console.log(logMessage); + this.sessionLogger.debug( + { timestamp: Date.now(), agentId: event.agentId, eventType: event.event.type, itemType }, + "Agent stream event" + ); this.emit({ type: "agent_stream", payload, @@ -624,9 +634,9 @@ export class Session { payload, }); } catch (error) { - console.error( - `[Session ${this.clientId}] Failed to emit agent state:`, - error + this.sessionLogger.error( + { err: error }, + "Failed to emit agent state" ); } } @@ -642,9 +652,9 @@ export class Session { this.agentTitleCache.set(agentId, title); return title; } catch (error) { - console.error( - `[Session ${this.clientId}] Failed to load registry record for agent ${agentId}:`, - error + this.sessionLogger.error( + { err: error, agentId }, + `Failed to load registry record for agent ${agentId}` ); return null; } @@ -680,8 +690,9 @@ export class Session { ACTIVE_TITLE_GENERATIONS.add(agentId); try { - console.log( - `[Session ${this.clientId}] Generating title for agent ${agentId}` + this.sessionLogger.debug( + { agentId }, + `Generating title for agent ${agentId}` ); const title = await generateAgentTitle(timeline, snapshot.cwd); await this.agentRegistry.setTitle(agentId, title); @@ -689,9 +700,9 @@ export class Session { const latest = this.agentManager.getAgent(agentId) ?? snapshot; await this.forwardAgentState(latest); } catch (error) { - console.error( - `[Session ${this.clientId}] Failed to generate title for agent ${agentId}:`, - error + this.sessionLogger.error( + { err: error, agentId }, + `Failed to generate title for agent ${agentId}` ); } finally { ACTIVE_TITLE_GENERATIONS.delete(agentId); @@ -830,9 +841,9 @@ export class Session { break; } } catch (error: any) { - console.error( - `[Session ${this.clientId}] Error handling message:`, - error + this.sessionLogger.error( + { err: error }, + "Error handling message" ); this.emit({ type: "activity_log", @@ -882,9 +893,9 @@ export class Session { }, }); } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to list conversations:`, - error + this.sessionLogger.error( + { err: error }, + "Failed to list conversations" ); this.emit({ type: "activity_log", @@ -915,13 +926,14 @@ export class Session { requestId, }, }); - console.log( - `[Session ${this.clientId}] Deleted conversation ${conversationId}` + this.sessionLogger.info( + { conversationId }, + `Deleted conversation ${conversationId}` ); } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to delete conversation ${conversationId}:`, - error + this.sessionLogger.error( + { err: error, conversationId }, + `Failed to delete conversation ${conversationId}` ); this.emit({ type: "delete_conversation_response", @@ -940,9 +952,7 @@ export class Session { reason?: string ): Promise { if (restartRequested) { - console.log( - `[Session ${this.clientId}] Restart already requested, ignoring duplicate` - ); + this.sessionLogger.debug("Restart already requested, ignoring duplicate"); return; } @@ -956,7 +966,7 @@ export class Session { } payload.requestId = requestId; - console.warn(`[Session ${this.clientId}] Restart requested via websocket`); + this.sessionLogger.warn({ reason }, "Restart requested via websocket"); this.emit({ type: "status", payload, @@ -979,25 +989,26 @@ export class Session { agentId: string, requestId: string ): Promise { - console.log( - `[Session ${this.clientId}] Deleting agent ${agentId} from registry` + this.sessionLogger.info( + { agentId }, + `Deleting agent ${agentId} from registry` ); try { await this.agentManager.closeAgent(agentId); } catch (error: any) { - console.warn( - `[Session ${this.clientId}] Failed to close agent ${agentId} during delete:`, - error + this.sessionLogger.warn( + { err: error, agentId }, + `Failed to close agent ${agentId} during delete` ); } try { await this.agentRegistry.remove(agentId); } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to remove agent ${agentId} from registry:`, - error + this.sessionLogger.error( + { err: error, agentId }, + `Failed to remove agent ${agentId} from registry` ); } @@ -1016,10 +1027,9 @@ export class Session { */ private handleSetRealtimeMode(enabled: boolean): void { this.isRealtimeMode = enabled; - console.log( - `[Session ${this.clientId}] Realtime mode ${ - enabled ? "enabled" : "disabled" - }` + this.sessionLogger.info( + { enabled }, + `Realtime mode ${enabled ? "enabled" : "disabled"}` ); } @@ -1032,10 +1042,9 @@ export class Session { messageId?: string, images?: Array<{ data: string; mimeType: string }> ): Promise { - console.log( - `[Session ${ - this.clientId - }] Sending text to agent ${agentId}: ${text.substring(0, 50)}...${images && images.length > 0 ? ` with ${images.length} image attachment(s)` : ''}` + this.sessionLogger.info( + { agentId, textPreview: text.substring(0, 50), imageCount: images?.length ?? 0 }, + `Sending text to agent ${agentId}${images && images.length > 0 ? ` with ${images.length} image attachment(s)` : ''}` ); try { @@ -1065,9 +1074,9 @@ export class Session { try { this.agentManager.recordUserMessage(agentId, text, { messageId }); } catch (error) { - console.error( - `[Session ${this.clientId}] Failed to record user message for agent ${agentId}:`, - error + this.sessionLogger.error( + { err: error, agentId }, + `Failed to record user message for agent ${agentId}` ); } @@ -1085,9 +1094,7 @@ export class Session { // agentId is required for auto_run mode if (shouldAutoRun && !agentId) { - console.error( - `[Session ${this.clientId}] agentId is required for auto_run mode` - ); + this.sessionLogger.error("agentId is required for auto_run mode"); return; } @@ -1100,15 +1107,17 @@ export class Session { // For now, we'll process each audio segment immediately // In the future, we might want to buffer chunks similar to realtime audio if (!isLast) { - console.log( - `[Session ${this.clientId}] Buffering agent audio chunk for agent ${logAgentId}` + this.sessionLogger.debug( + { agentId: logAgentId }, + `Buffering agent audio chunk for agent ${logAgentId}` ); // TODO: Implement buffering if needed return; } - console.log( - `[Session ${this.clientId}] Transcribing audio for agent ${logAgentId}` + this.sessionLogger.debug( + { agentId: logAgentId }, + `Transcribing audio for agent ${logAgentId}` ); try { @@ -1121,14 +1130,16 @@ export class Session { const transcriptText = result.text.trim(); if (!transcriptText) { - console.log( - `[Session ${this.clientId}] Empty transcription for agent ${logAgentId}, ignoring` + this.sessionLogger.debug( + { agentId: logAgentId }, + `Empty transcription for agent ${logAgentId}, ignoring` ); return; } - console.log( - `[Session ${this.clientId}] Transcribed audio for agent ${logAgentId}: ${transcriptText}` + this.sessionLogger.info( + { agentId: logAgentId, transcriptText }, + `Transcribed audio for agent ${logAgentId}` ); // Emit transcription result to client with requestId @@ -1148,8 +1159,9 @@ export class Session { }); if (!shouldAutoRun) { - console.log( - `[Session ${this.clientId}] Completed transcription for agent ${logAgentId} (requestId: ${requestId})` + this.sessionLogger.info( + { agentId: logAgentId, requestId }, + `Completed transcription for agent ${logAgentId} (requestId: ${requestId})` ); return; } @@ -1182,21 +1194,22 @@ export class Session { try { this.agentManager.recordUserMessage(validAgentId, transcriptText); } catch (recordError) { - console.error( - `[Session ${this.clientId}] Failed to record transcribed user message for agent ${validAgentId}:`, - recordError + this.sessionLogger.error( + { err: recordError, agentId: validAgentId }, + `Failed to record transcribed user message for agent ${validAgentId}` ); } // Send transcribed text to agent this.startAgentStream(validAgentId, transcriptText); - console.log( - `[Session ${this.clientId}] Sent transcribed text to agent ${validAgentId}` + this.sessionLogger.info( + { agentId: validAgentId }, + `Sent transcribed text to agent ${validAgentId}` ); } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to process audio for agent ${logAgentId}:`, - error + this.sessionLogger.error( + { err: error, agentId: logAgentId }, + `Failed to process audio for agent ${logAgentId}` ); this.emit({ type: "activity_log", @@ -1218,8 +1231,9 @@ export class Session { agentId: string, requestId: string ): Promise { - console.log( - `[Session ${this.clientId}] Initializing agent ${agentId} on demand` + this.sessionLogger.info( + { agentId }, + `Initializing agent ${agentId} on demand` ); try { @@ -1239,13 +1253,14 @@ export class Session { }, }); - console.log( - `[Session ${this.clientId}] Agent ${agentId} initialized with ${timelineSize} timeline item(s); status=${snapshot.lifecycle}` + this.sessionLogger.info( + { agentId, timelineSize, status: snapshot.lifecycle }, + `Agent ${agentId} initialized with ${timelineSize} timeline item(s); status=${snapshot.lifecycle}` ); } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to initialize agent ${agentId}:`, - error + this.sessionLogger.error( + { err: error, agentId }, + `Failed to initialize agent ${agentId}` ); this.emit({ type: "initialize_agent_request", @@ -1265,8 +1280,9 @@ export class Session { msg: Extract ): Promise { const { config, worktreeName, requestId, initialPrompt, git, images } = msg; - console.log( - `[Session ${this.clientId}] Creating agent in ${config.cwd} (${config.provider})${ + this.sessionLogger.info( + { cwd: config.cwd, provider: config.provider, worktreeName }, + `Creating agent in ${config.cwd} (${config.provider})${ worktreeName ? ` with worktree ${worktreeName}` : "" }` ); @@ -1309,9 +1325,9 @@ export class Session { images ); } catch (promptError) { - console.error( - `[Session ${this.clientId}] Failed to run initial prompt for agent ${snapshot.id}:`, - promptError + this.sessionLogger.error( + { err: promptError, agentId: snapshot.id }, + `Failed to run initial prompt for agent ${snapshot.id}` ); this.emit({ type: "activity_log", @@ -1336,13 +1352,14 @@ export class Session { }); } - console.log( - `[Session ${this.clientId}] Created agent ${snapshot.id} (${snapshot.provider})` + this.sessionLogger.info( + { agentId: snapshot.id, provider: snapshot.provider }, + `Created agent ${snapshot.id} (${snapshot.provider})` ); } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to create agent:`, - error + this.sessionLogger.error( + { err: error }, + "Failed to create agent" ); if (requestId) { this.emit({ @@ -1371,9 +1388,7 @@ export class Session { ): Promise { const { handle, overrides, requestId } = msg; if (!handle) { - console.warn( - `[Session ${this.clientId}] Resume request missing persistence handle` - ); + this.sessionLogger.warn("Resume request missing persistence handle"); this.emit({ type: "activity_log", payload: { @@ -1385,8 +1400,9 @@ export class Session { }); return; } - console.log( - `[Session ${this.clientId}] Resuming agent ${handle.sessionId} (${handle.provider})` + this.sessionLogger.info( + { sessionId: handle.sessionId, provider: handle.provider }, + `Resuming agent ${handle.sessionId} (${handle.provider})` ); try { const snapshot = await this.agentManager.resumeAgent( @@ -1409,9 +1425,9 @@ export class Session { }); } } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to resume agent:`, - error + this.sessionLogger.error( + { err: error }, + "Failed to resume agent" ); this.emit({ type: "activity_log", @@ -1429,8 +1445,9 @@ export class Session { msg: Extract ): Promise { const { agentId, requestId } = msg; - console.log( - `[Session ${this.clientId}] Refreshing agent ${agentId} from persistence` + this.sessionLogger.info( + { agentId }, + `Refreshing agent ${agentId} from persistence` ); try { @@ -1478,9 +1495,9 @@ export class Session { }); } } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to refresh agent ${agentId}:`, - error + this.sessionLogger.error( + { err: error, agentId }, + `Failed to refresh agent ${agentId}` ); this.emit({ type: "activity_log", @@ -1495,8 +1512,9 @@ export class Session { } private async handleCancelAgentRequest(agentId: string): Promise { - console.log( - `[Session ${this.clientId}] Cancel request received for agent ${agentId}` + this.sessionLogger.info( + { agentId }, + `Cancel request received for agent ${agentId}` ); try { @@ -1545,8 +1563,9 @@ export class Session { ); } - console.log( - `[Session ${this.clientId}] Creating worktree '${ + this.sessionLogger.info( + { worktreeSlug: normalized.worktreeSlug ?? targetBranch, branch: targetBranch }, + `Creating worktree '${ normalized.worktreeSlug ?? targetBranch }' for branch ${targetBranch}` ); @@ -1648,9 +1667,9 @@ export class Session { }, }); } catch (error) { - console.error( - `[Session ${this.clientId}] Failed to list models for ${msg.provider}:`, - error + this.sessionLogger.error( + { err: error, provider: msg.provider }, + `Failed to list models for ${msg.provider}` ); this.emit({ type: "list_provider_models_response", @@ -1824,19 +1843,21 @@ export class Session { agentId: string, modeId: string ): Promise { - console.log( - `[Session ${this.clientId}] Setting agent ${agentId} mode to ${modeId}` + this.sessionLogger.info( + { agentId, modeId }, + `Setting agent ${agentId} mode to ${modeId}` ); try { await this.agentManager.setAgentMode(agentId, modeId); - console.log( - `[Session ${this.clientId}] Agent ${agentId} mode set to ${modeId}` + this.sessionLogger.info( + { agentId, modeId }, + `Agent ${agentId} mode set to ${modeId}` ); } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to set agent mode:`, - error + this.sessionLogger.error( + { err: error, agentId, modeId }, + "Failed to set agent mode" ); this.emit({ type: "activity_log", @@ -1856,8 +1877,9 @@ export class Session { */ private async handleClearAgentAttention(agentId: string | string[]): Promise { const agentIds = Array.isArray(agentId) ? agentId : [agentId]; - console.log( - `[Session ${this.clientId}] Clearing attention for ${agentIds.length} agent(s): ${agentIds.join(", ")}` + this.sessionLogger.debug( + { agentIds }, + `Clearing attention for ${agentIds.length} agent(s): ${agentIds.join(", ")}` ); try { @@ -1865,9 +1887,9 @@ export class Session { agentIds.map((id) => this.agentManager.clearAgentAttention(id)) ); } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to clear agent attention:`, - error + this.sessionLogger.error( + { err: error, agentIds }, + "Failed to clear agent attention" ); // Don't throw - this is not critical } @@ -1882,7 +1904,7 @@ export class Session { lastActivityAt: string; appVisible: boolean; }): void { - console.log(`[Session ${this.clientId}] handleClientHeartbeat`, msg); + this.sessionLogger.debug({ heartbeat: msg }, "Client heartbeat"); this.clientActivity = { deviceType: msg.deviceType, focusedAgentId: msg.focusedAgentId, @@ -1896,15 +1918,16 @@ export class Session { */ private handleRegisterPushToken(token: string): void { this.pushTokenStore.addToken(token); - console.log(`[Session ${this.clientId}] Registered push token`); + this.sessionLogger.info("Registered push token"); } /** * Handle list commands request for an agent */ private async handleListCommandsRequest(agentId: string, requestId: string): Promise { - console.log( - `[Session ${this.clientId}] Handling list commands request for agent ${agentId}` + this.sessionLogger.debug( + { agentId }, + `Handling list commands request for agent ${agentId}` ); try { @@ -1950,9 +1973,9 @@ export class Session { }, }); } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to list commands:`, - error + this.sessionLogger.error( + { err: error, agentId }, + "Failed to list commands" ); this.emit({ type: "list_commands_response", @@ -1974,19 +1997,21 @@ export class Session { requestId: string, response: AgentPermissionResponse ): Promise { - console.log( - `[Session ${this.clientId}] Handling permission response for agent ${agentId}, request ${requestId}` + this.sessionLogger.debug( + { agentId, requestId }, + `Handling permission response for agent ${agentId}, request ${requestId}` ); try { await this.agentManager.respondToPermission(agentId, requestId, response); - console.log( - `[Session ${this.clientId}] Permission response forwarded to agent ${agentId}` + this.sessionLogger.debug( + { agentId }, + `Permission response forwarded to agent ${agentId}` ); } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to respond to permission:`, - error + this.sessionLogger.error( + { err: error, agentId, requestId }, + "Failed to respond to permission" ); this.emit({ type: "activity_log", @@ -2005,8 +2030,9 @@ export class Session { * Handle git diff request for an agent */ private async handleGitDiffRequest(agentId: string, requestId: string): Promise { - console.log( - `[Session ${this.clientId}] Handling git diff request for agent ${agentId}` + this.sessionLogger.debug( + { agentId }, + `Handling git diff request for agent ${agentId}` ); try { @@ -2071,13 +2097,14 @@ export class Session { }, }); - console.log( - `[Session ${this.clientId}] Git diff for agent ${agentId} completed (${combinedDiff.length} bytes)` + this.sessionLogger.debug( + { agentId, diffBytes: combinedDiff.length }, + `Git diff for agent ${agentId} completed (${combinedDiff.length} bytes)` ); } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to get git diff for agent ${agentId}:`, - error + this.sessionLogger.error( + { err: error, agentId }, + `Failed to get git diff for agent ${agentId}` ); this.emit({ type: "git_diff_response", @@ -2098,8 +2125,9 @@ export class Session { agentId: string, requestId: string ): Promise { - console.log( - `[Session ${this.clientId}] Handling highlighted diff request for agent ${agentId}` + this.sessionLogger.debug( + { agentId }, + `Handling highlighted diff request for agent ${agentId}` ); // Maximum lines changed before we skip showing the diff content @@ -2275,13 +2303,14 @@ export class Session { }, }); - console.log( - `[Session ${this.clientId}] Highlighted diff for agent ${agentId} completed (${allFiles.length} files)` + this.sessionLogger.debug( + { agentId, fileCount: allFiles.length }, + `Highlighted diff for agent ${agentId} completed (${allFiles.length} files)` ); } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to get highlighted diff for agent ${agentId}:`, - error + this.sessionLogger.error( + { err: error, agentId }, + `Failed to get highlighted diff for agent ${agentId}` ); this.emit({ type: "highlighted_diff_response", @@ -2303,8 +2332,9 @@ export class Session { ): Promise { const { agentId, path: requestedPath = ".", mode, requestId } = request; - console.log( - `[Session ${this.clientId}] Handling file explorer request for agent ${agentId} (${mode} ${requestedPath})` + this.sessionLogger.debug( + { agentId, mode, path: requestedPath }, + `Handling file explorer request for agent ${agentId} (${mode} ${requestedPath})` ); try { @@ -2365,9 +2395,9 @@ export class Session { }); } } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to fulfill file explorer request for agent ${agentId}:`, - error + this.sessionLogger.error( + { err: error, agentId, path: requestedPath }, + `Failed to fulfill file explorer request for agent ${agentId}` ); this.emit({ type: "file_explorer_response", @@ -2392,8 +2422,9 @@ export class Session { ): Promise { const { agentId, path: requestedPath, requestId } = request; - console.log( - `[Session ${this.clientId}] Handling file download token request for agent ${agentId} (${requestedPath})` + this.sessionLogger.debug( + { agentId, path: requestedPath }, + `Handling file download token request for agent ${agentId} (${requestedPath})` ); try { @@ -2445,9 +2476,9 @@ export class Session { }, }); } catch (error: any) { - console.error( - `[Session ${this.clientId}] Failed to issue download token for agent ${agentId}:`, - error + this.sessionLogger.error( + { err: error, agentId, path: requestedPath }, + `Failed to issue download token for agent ${agentId}` ); this.emit({ type: "file_download_token_response", @@ -2493,13 +2524,14 @@ export class Session { }, }); - console.log( - `[Session ${this.clientId}] Sent session state: ${agents.length} agents` + this.sessionLogger.debug( + { agentCount: agents.length }, + `Sent session state: ${agents.length} agents` ); } catch (error) { - console.error( - `[Session ${this.clientId}] Failed to send session state:`, - error + this.sessionLogger.error( + { err: error }, + "Failed to send session state" ); } } @@ -2532,11 +2564,9 @@ export class Session { // Wait for aborted stream to finish cleanup (save partial response) if (this.currentStreamPromise) { - console.log( - `[Session ${this.clientId}] Waiting for aborted stream to finish cleanup` - ); + this.sessionLogger.debug("Waiting for aborted stream to finish cleanup"); await this.currentStreamPromise; - console.log(`[Session ${this.clientId}] Aborted stream finished cleanup`); + this.sessionLogger.debug("Aborted stream finished cleanup"); } // Emit user message activity log @@ -2581,8 +2611,9 @@ export class Session { // If the format changes mid-stream, flush what we have first if (this.audioBuffer.isPCM !== isPCMChunk) { - console.log( - `[Session ${this.clientId}] Audio format changed mid-stream (${this.audioBuffer.isPCM ? "pcm" : this.audioBuffer.format} → ${chunkFormat}), flushing current buffer` + this.sessionLogger.debug( + { oldFormat: this.audioBuffer.isPCM ? "pcm" : this.audioBuffer.format, newFormat: chunkFormat }, + `Audio format changed mid-stream, flushing current buffer` ); const finalized = this.finalizeBufferedAudio(); if (finalized) { @@ -2604,22 +2635,19 @@ export class Session { this.audioBuffer.totalPCMBytes += chunkBuffer.length; } - console.log( - `[Session ${this.clientId}] Buffered audio chunk (${chunkBuffer.length} bytes, chunks: ${this.audioBuffer.chunks.length}${this.audioBuffer.isPCM ? `, PCM bytes: ${this.audioBuffer.totalPCMBytes}` : ""})` + this.sessionLogger.debug( + { bytes: chunkBuffer.length, chunks: this.audioBuffer.chunks.length, pcmBytes: this.audioBuffer.totalPCMBytes }, + `Buffered audio chunk (${chunkBuffer.length} bytes, chunks: ${this.audioBuffer.chunks.length}${this.audioBuffer.isPCM ? `, PCM bytes: ${this.audioBuffer.totalPCMBytes}` : ""})` ); // In realtime mode, only process audio when the user has finished speaking (isLast = true) // This prevents partial transcriptions from being sent to the LLM if (this.isRealtimeMode) { if (!msg.isLast) { - console.log( - `[Session ${this.clientId}] Realtime mode: buffering audio, waiting for speech end` - ); + this.sessionLogger.debug("Realtime mode: buffering audio, waiting for speech end"); return; } - console.log( - `[Session ${this.clientId}] Realtime mode: speech ended, processing complete audio` - ); + this.sessionLogger.debug("Realtime mode: speech ended, processing complete audio"); } // In non-realtime mode, use streaming threshold to process chunks @@ -2628,7 +2656,7 @@ export class Session { this.audioBuffer.isPCM && this.audioBuffer.totalPCMBytes >= MIN_STREAMING_SEGMENT_BYTES; - if (!msg.isLast && !reachedStreamingThreshold) { + if (!msg.isLast && reachedStreamingThreshold) { return; } @@ -2639,14 +2667,16 @@ export class Session { } if (!msg.isLast && reachedStreamingThreshold) { - console.log( - `[Session ${this.clientId}] Minimum chunk duration reached (~${MIN_STREAMING_SEGMENT_DURATION_MS}ms, ${ + this.sessionLogger.debug( + { minDuration: MIN_STREAMING_SEGMENT_DURATION_MS, pcmBytes: bufferedState?.totalPCMBytes ?? 0 }, + `Minimum chunk duration reached (~${MIN_STREAMING_SEGMENT_DURATION_MS}ms, ${ bufferedState?.totalPCMBytes ?? 0 } PCM bytes) – triggering STT` ); } else { - console.log( - `[Session ${this.clientId}] Complete audio segment (${finalized.audio.length} bytes, ${bufferedState?.chunks.length ?? 0} chunk(s))` + this.sessionLogger.debug( + { audioBytes: finalized.audio.length, chunks: bufferedState?.chunks.length ?? 0 }, + `Complete audio segment (${finalized.audio.length} bytes, ${bufferedState?.chunks.length ?? 0} chunk(s))` ); } @@ -2692,8 +2722,9 @@ export class Session { this.pendingAudioSegments.length === 0; if (shouldBuffer) { - console.log( - `[Session ${this.clientId}] Buffering audio segment (phase: ${this.processingPhase})` + this.sessionLogger.debug( + { phase: this.processingPhase }, + `Buffering audio segment (phase: ${this.processingPhase})` ); this.pendingAudioSegments.push({ audio, @@ -2708,8 +2739,9 @@ export class Session { audio, format, }); - console.log( - `[Session ${this.clientId}] Processing ${this.pendingAudioSegments.length} buffered segments together` + this.sessionLogger.debug( + { segmentCount: this.pendingAudioSegments.length }, + `Processing ${this.pendingAudioSegments.length} buffered segments together` ); const pendingSegments = [...this.pendingAudioSegments]; @@ -2752,9 +2784,7 @@ export class Session { const transcriptText = result.text.trim(); if (!transcriptText) { - console.log( - `[Session ${this.clientId}] Empty transcription (false positive), not aborting` - ); + this.sessionLogger.debug("Empty transcription (false positive), not aborting"); this.setPhase("idle"); this.clearSpeechInProgress("empty transcription"); return; @@ -2765,9 +2795,7 @@ export class Session { // Wait for aborted stream to finish cleanup (save partial response) if (this.currentStreamPromise) { - console.log( - `[Session ${this.clientId}] Waiting for aborted stream to finish cleanup` - ); + this.sessionLogger.debug("Waiting for aborted stream to finish cleanup"); await this.currentStreamPromise; } @@ -2848,9 +2876,7 @@ export class Session { modeAtGeneration ); } else if (enableTTS && this.speechInProgress) { - console.log( - `[Session ${this.clientId}] Skipping TTS chunk while speech in progress` - ); + this.sessionLogger.debug("Skipping TTS chunk while speech in progress"); } // Emit activity log @@ -2882,17 +2908,13 @@ export class Session { // Wait for agent MCP to initialize if needed if (!this.agentTools) { - console.log( - `[Session ${this.clientId}] Waiting for agent MCP initialization...` - ); + this.sessionLogger.debug("Waiting for agent MCP initialization..."); const startTime = Date.now(); while (!this.agentTools && Date.now() - startTime < 5000) { await new Promise((resolve) => setTimeout(resolve, 100)); } if (!this.agentTools) { - console.log( - `[Session ${this.clientId}] Agent MCP tools unavailable; continuing with default tool set` - ); + this.sessionLogger.info("Agent MCP tools unavailable; continuing with default tool set"); } } @@ -2913,8 +2935,9 @@ export class Session { const newMessages = event.response.messages; if (newMessages.length > 0) { this.messages.push(...newMessages); - console.log( - `[Session ${this.clientId}] onFinish - saved message with ${newMessages.length} steps` + this.sessionLogger.debug( + { messageCount: newMessages.length }, + `onFinish - saved message with ${newMessages.length} steps` ); } @@ -2922,9 +2945,9 @@ export class Session { try { await saveConversation(this.conversationId, this.messages); } catch (error) { - console.error( - `[Session ${this.clientId}] Failed to persist conversation:`, - error + this.sessionLogger.error( + { err: error }, + "Failed to persist conversation" ); // Don't break conversation flow on persistence errors } @@ -2947,8 +2970,9 @@ export class Session { // Wait for pending TTS before executing tool if (pendingTTS) { - console.log( - `[Session ${this.clientId}] Waiting for TTS before executing ${chunk.toolName}` + this.sessionLogger.debug( + { toolName: chunk.toolName }, + `Waiting for TTS before executing ${chunk.toolName}` ); await pendingTTS; } @@ -3010,7 +3034,7 @@ export class Session { } }, onError: async (error) => { - console.error(error); + this.sessionLogger.error({ err: error }, "Stream error"); this.emit({ type: "activity_log", @@ -3078,9 +3102,9 @@ export class Session { try { await pendingTTS; } catch (ttsError) { - console.error( - `[Session ${this.clientId}] TTS playback failed (message already saved):`, - ttsError + this.sessionLogger.error( + { err: ttsError }, + "TTS playback failed (message already saved)" ); } } @@ -3108,9 +3132,7 @@ export class Session { // Don't re-throw abort errors (they're expected during interruptions) if (isAbortError) { - console.log( - `[Session ${this.clientId}] Stream aborted (partial response saved)` - ); + this.sessionLogger.debug("Stream aborted (partial response saved)"); return; } @@ -3154,9 +3176,9 @@ export class Session { isBase64 = false; } } catch (error) { - console.error( - `[Session ${this.clientId}] Failed to resolve artifact source:`, - error + this.sessionLogger.error( + { err: error }, + "Failed to resolve artifact source" ); content = `[Error: ${ error instanceof Error ? error.message : String(error) @@ -3193,20 +3215,19 @@ export class Session { * Handle abort request from client */ private async handleAbort(): Promise { - console.log( - `[Session ${this.clientId}] Abort request, phase: ${this.processingPhase}` + this.sessionLogger.info( + { phase: this.processingPhase }, + `Abort request, phase: ${this.processingPhase}` ); if (this.processingPhase === "llm") { // Already in LLM phase - abort and wait for cleanup this.abortController.abort(); - console.log(`[Session ${this.clientId}] Aborted LLM processing`); + this.sessionLogger.debug("Aborted LLM processing"); // Wait for stream to finish saving partial response if (this.currentStreamPromise) { - console.log( - `[Session ${this.clientId}] Waiting for stream cleanup after abort` - ); + this.sessionLogger.debug("Waiting for stream cleanup after abort"); await this.currentStreamPromise; } @@ -3218,9 +3239,7 @@ export class Session { this.clearBufferTimeout(); } else if (this.processingPhase === "transcribing") { // Still in STT phase - we'll buffer the next audio - console.log( - `[Session ${this.clientId}] Will buffer next audio (currently transcribing)` - ); + this.sessionLogger.debug("Will buffer next audio (currently transcribing)"); // Phase stays as 'transcribing', handleAudioChunk will handle buffering } // If idle, nothing to do @@ -3246,21 +3265,21 @@ export class Session { const hadActiveStream = Boolean(this.currentStreamPromise); this.speechInProgress = true; - console.log( - `[Session ${this.clientId}] Realtime speech chunk detected – aborting playback and LLM` - ); + this.sessionLogger.debug("Realtime speech chunk detected – aborting playback and LLM"); this.ttsManager.cancelPendingPlaybacks("realtime speech detected"); if (this.pendingAudioSegments.length > 0) { - console.log( - `[Session ${this.clientId}] Dropping ${this.pendingAudioSegments.length} buffered audio segment(s) due to realtime speech` + this.sessionLogger.debug( + { segmentCount: this.pendingAudioSegments.length }, + `Dropping ${this.pendingAudioSegments.length} buffered audio segment(s) due to realtime speech` ); this.pendingAudioSegments = []; } if (this.audioBuffer) { - console.log( - `[Session ${this.clientId}] Clearing partial audio buffer (${this.audioBuffer.chunks.length} chunk(s)${ + this.sessionLogger.debug( + { chunks: this.audioBuffer.chunks.length, pcmBytes: this.audioBuffer.totalPCMBytes }, + `Clearing partial audio buffer (${this.audioBuffer.chunks.length} chunk(s)${ this.audioBuffer.isPCM ? `, ${this.audioBuffer.totalPCMBytes} PCM bytes` : "" @@ -3275,13 +3294,10 @@ export class Session { await this.handleAbort(); const latencyMs = Date.now() - chunkReceivedAt; - console.log("[Telemetry] barge_in.llm_abort_latency", { - latencyMs, - conversationId: this.conversationId, - phaseBeforeAbort, - hadActiveStream, - timestamp: new Date().toISOString(), - }); + this.sessionLogger.debug( + { latencyMs, phaseBeforeAbort, hadActiveStream }, + "[Telemetry] barge_in.llm_abort_latency" + ); } /** @@ -3293,8 +3309,9 @@ export class Session { } this.speechInProgress = false; - console.log( - `[Session ${this.clientId}] Speech turn complete (${reason}) – resuming TTS` + this.sessionLogger.debug( + { reason }, + `Speech turn complete (${reason}) – resuming TTS` ); } @@ -3312,7 +3329,7 @@ export class Session { */ private setPhase(phase: ProcessingPhase): void { this.processingPhase = phase; - console.log(`[Session ${this.clientId}] Phase: ${phase}`); + this.sessionLogger.debug({ phase }, `Phase: ${phase}`); } /** @@ -3322,9 +3339,7 @@ export class Session { this.clearBufferTimeout(); this.bufferTimeout = setTimeout(async () => { - console.log( - `[Session ${this.clientId}] Buffer timeout reached, processing pending segments` - ); + this.sessionLogger.debug("Buffer timeout reached, processing pending segments"); if (this.pendingAudioSegments.length > 0) { const segments = [...this.pendingAudioSegments]; @@ -3373,13 +3388,14 @@ export class Session { }; await writeFile(filepath, inspect(dump, { depth: null }), "utf-8"); - console.log( - `[Session ${this.clientId}] Dumped conversation to ${filepath}` + this.sessionLogger.debug( + { filepath }, + `Dumped conversation to ${filepath}` ); } catch (error) { - console.error( - `[Session ${this.clientId}] Failed to dump conversation:`, - error + this.sessionLogger.error( + { err: error }, + "Failed to dump conversation" ); } } @@ -3388,7 +3404,7 @@ export class Session { * Clean up session resources */ public async cleanup(): Promise { - console.log(`[Session ${this.clientId}] Cleaning up`); + this.sessionLogger.info("Cleaning up"); if (this.unsubscribeAgentEvents) { this.unsubscribeAgentEvents(); @@ -3413,11 +3429,11 @@ export class Session { if (this.agentMcpClient) { try { await this.agentMcpClient.close(); - console.log(`[Session ${this.clientId}] Agent MCP client closed`); + this.sessionLogger.debug("Agent MCP client closed"); } catch (error) { - console.error( - `[Session ${this.clientId}] Failed to close Agent MCP client:`, - error + this.sessionLogger.error( + { err: error }, + "Failed to close Agent MCP client" ); } this.agentMcpClient = null; diff --git a/packages/server/src/server/websocket-server.ts b/packages/server/src/server/websocket-server.ts index eadad0613..adfcc176f 100644 --- a/packages/server/src/server/websocket-server.ts +++ b/packages/server/src/server/websocket-server.ts @@ -16,6 +16,9 @@ import type { AgentProvider } from "./agent/agent-sdk-types.js"; import { DownloadTokenStore } from "./file-download/token-store.js"; import { PushTokenStore } from "./push/token-store.js"; import { PushService } from "./push/push-service.js"; +import { getRootLogger } from "./logger.js"; + +const logger = getRootLogger().child({ module: "websocket-server" }); type AgentMcpClientConfig = { agentMcpUrl: string; @@ -68,7 +71,7 @@ export class VoiceAssistantWebSocketServer { if (!origin || allowedOrigins.has(origin)) { callback(true); } else { - console.warn(`[WebSocket] Rejected connection from origin: ${origin}`); + logger.warn({ origin }, "Rejected connection from origin"); callback(false, 403, "Origin not allowed"); } }, @@ -82,7 +85,7 @@ export class VoiceAssistantWebSocketServer { this.broadcastAgentAttention(params); }); - console.log("✓ WebSocket server initialized on /ws"); + logger.info("WebSocket server initialized on /ws"); } /** @@ -99,19 +102,16 @@ export class VoiceAssistantWebSocketServer { // Load conversation if ID provided let initialMessages = null; if (conversationId) { - console.log( - `[WS] Client requesting conversation ${conversationId}` - ); + logger.debug({ conversationId }, "Client requesting conversation"); initialMessages = await loadConversation(conversationId); if (initialMessages) { - console.log( - `[WS] Loaded conversation ${conversationId} with ${initialMessages.length} messages` + logger.debug( + { conversationId, messageCount: initialMessages.length }, + "Loaded conversation" ); } else { - console.log( - `[WS] Conversation ${conversationId} not found, starting fresh` - ); + logger.debug({ conversationId }, "Conversation not found, starting fresh"); } } @@ -136,10 +136,9 @@ export class VoiceAssistantWebSocketServer { this.sessions.set(ws, session); this.conversationIdToWs.set(session.getConversationId(), ws); - console.log( - `[WS] Client connected: ${clientId} with conversation ${session.getConversationId()} (total: ${ - this.sessions.size - })` + logger.info( + { clientId, conversationId: session.getConversationId(), totalSessions: this.sessions.size }, + "Client connected" ); // Don't send initial state here - client will request it via load_conversation_request @@ -155,10 +154,9 @@ export class VoiceAssistantWebSocketServer { const session = this.sessions.get(ws); if (!session) return; - console.log( - `[WS] Client disconnected: ${clientId} (total: ${ - this.sessions.size - 1 - })` + logger.info( + { clientId, totalSessions: this.sessions.size - 1 }, + "Client disconnected" ); // Clean up session @@ -168,15 +166,13 @@ export class VoiceAssistantWebSocketServer { this.sessions.delete(ws); this.conversationIdToWs.delete(session.getConversationId()); - console.log(`[WS] Conversation ${session.getConversationId()} deleted`); + logger.debug({ conversationId: session.getConversationId() }, "Conversation deleted"); }); // Set up error handler ws.on("error", async (error) => { - // Safe error logging - const errorMessage = error instanceof Error ? error.message : "Unknown error"; - const errorStack = error instanceof Error ? error.stack : undefined; - console.error(`[WS] Client error:`, { message: errorMessage, stack: errorStack }); + const err = error instanceof Error ? error : new Error(String(error)); + logger.error({ err }, "Client error"); const session = this.sessions.get(ws); if (!session) return; @@ -210,7 +206,7 @@ export class VoiceAssistantWebSocketServer { sessionMessageType: message.message.type, } : {}), }; - console.log(`[WS] Received message:`, messageSummary); + logger.debug(messageSummary, "Received message"); // Handle WebSocket-level messages switch (message.type) { @@ -219,7 +215,7 @@ export class VoiceAssistantWebSocketServer { return; case "recording_state": - console.log(`[WS] Recording state: ${message.isRecording}`); + logger.debug({ isRecording: message.isRecording }, "Recording state"); return; case "session": @@ -228,27 +224,25 @@ export class VoiceAssistantWebSocketServer { if (sessionMessage) { // Debug: Log create_agent_request details if (sessionMessage.type === "create_agent_request") { - console.log("[WS] create_agent_request details:", { + logger.debug({ cwd: sessionMessage.config.cwd, initialMode: sessionMessage.config.modeId, worktreeName: sessionMessage.worktreeName, requestId: sessionMessage.requestId, - }); + }, "create_agent_request details"); } - + const session = this.sessions.get(ws); if (session) { await session.handleMessage(sessionMessage); } else { - console.error("[WS] No session found for client"); + logger.error("No session found for client"); } } return; } } catch (error) { - // Safe error logging - avoid crashing on large/circular objects - const errorMessage = error instanceof Error ? error.message : "Unknown error"; - const errorStack = error instanceof Error ? error.stack : undefined; + const err = error instanceof Error ? error : new Error(String(error)); let rawPayload: string | null = null; let parsedPayload: unknown = null; @@ -269,7 +263,8 @@ export class VoiceAssistantWebSocketServer { } catch (payloadError) { rawPayload = rawPayload ?? ""; parsedPayload = parsedPayload ?? rawPayload; - console.error("[WS] Failed to decode raw payload:", payloadError); + const payloadErr = payloadError instanceof Error ? payloadError : new Error(String(payloadError)); + logger.error({ err: payloadErr }, "Failed to decode raw payload"); } const trimmedRawPayload = @@ -277,12 +272,11 @@ export class VoiceAssistantWebSocketServer { ? `${rawPayload.slice(0, 2000)}... (truncated)` : rawPayload; - console.error("[WS] Failed to parse/handle message:", { - message: errorMessage, - stack: errorStack, + logger.error({ + err, rawPayload: trimmedRawPayload, parsedPayload, - }); + }, "Failed to parse/handle message"); // Send error to client this.sendToClient( ws, @@ -290,7 +284,7 @@ export class VoiceAssistantWebSocketServer { type: "status", payload: { status: "error", - message: `Invalid message: ${errorMessage}`, + message: `Invalid message: ${err.message}`, }, }) ); @@ -356,20 +350,20 @@ export class VoiceAssistantWebSocketServer { } { const activity = session.getClientActivity(); if (!activity) { - console.log("[WS] getClientActivityState: no activity for session"); + logger.debug("getClientActivityState: no activity for session"); return { deviceType: null, focusedAgentId: null, isStale: true, appVisible: false }; } const now = Date.now(); const ageMs = now - activity.lastActivityAt.getTime(); const isStale = ageMs >= this.ACTIVITY_THRESHOLD_MS; - console.log("[WS] getClientActivityState", { + logger.debug({ deviceType: activity.deviceType, focusedAgentId: activity.focusedAgentId, lastActivityAt: activity.lastActivityAt.toISOString(), ageMs, isStale, appVisible: activity.appVisible, - }); + }, "getClientActivityState"); return { deviceType: activity.deviceType, focusedAgentId: activity.focusedAgentId, @@ -481,19 +475,19 @@ export class VoiceAssistantWebSocketServer { const allStates = clientEntries.map((e) => e.state); - console.log("[WS] broadcastAgentAttention", { + logger.debug({ agentId: params.agentId, reason: params.reason, clientCount: clientEntries.length, allStates, - }); + }, "broadcastAgentAttention"); // Check if all clients are stale - if so, send push notification const allClientsStale = allStates.every((state) => state.isStale); - console.log("[WS] allClientsStale:", allClientsStale); + logger.debug({ allClientsStale }, "Client staleness check"); if (allClientsStale) { const tokens = this.pushTokenStore.getAllTokens(); - console.log("[WS] Sending push notification, tokens:", tokens.length); + logger.info({ tokenCount: tokens.length }, "Sending push notification"); if (tokens.length > 0) { void this.pushService.sendPush(tokens, { title: "Agent needs attention", diff --git a/packages/server/src/services/agent-title-generator.ts b/packages/server/src/services/agent-title-generator.ts index eeaf81671..885f6a600 100644 --- a/packages/server/src/services/agent-title-generator.ts +++ b/packages/server/src/services/agent-title-generator.ts @@ -3,12 +3,15 @@ import { createOpenAI } from "@ai-sdk/openai"; import { z } from "zod"; import type { AgentTimelineItem } from "../server/agent/agent-sdk-types.js"; import { curateAgentActivity } from "../server/agent/activity-curator.js"; +import { getRootLogger } from "../server/logger.js"; + +const logger = getRootLogger().child({ module: "agent-title-generator" }); let openai: ReturnType | null = null; export function initializeTitleGenerator(apiKey: string): void { openai = createOpenAI({ apiKey }); - console.log("✓ Agent title generator initialized"); + logger.info("Agent title generator initialized"); } export function isTitleGeneratorInitialized(): boolean { @@ -56,11 +59,11 @@ ${activityContext}`, temperature: 0.7, }); - console.log(`[TitleGenerator] Generated title: "${object.title}"`); + logger.debug({ title: object.title }, "Generated agent title"); return object.title; - } catch (error: any) { - console.error("[TitleGenerator] Failed to generate title:", error); + } catch (err) { + logger.error({ err }, "Failed to generate agent title"); return "New Agent"; } } diff --git a/packages/server/src/tasks/cli.ts b/packages/server/src/tasks/cli.ts index a1e8feb62..dca56b655 100644 --- a/packages/server/src/tasks/cli.ts +++ b/packages/server/src/tasks/cli.ts @@ -106,7 +106,7 @@ program acceptanceCriteria: opts.accept, }); - console.log(task.id); + process.stdout.write(`${task.id}\n`); }); program @@ -129,7 +129,7 @@ program const deps = t.deps.length ? ` <- [${t.deps.join(", ")}]` : ""; const assignee = t.assignee ? ` @${t.assignee}` : ""; const parent = t.parentId ? ` ^${t.parentId}` : ""; - console.log(`${t.id} [${t.status}] ${t.title}${assignee}${parent}${deps}`); + process.stdout.write(`${t.id} [${t.status}] ${t.title}${assignee}${parent}${deps}\n`); } }); @@ -139,7 +139,7 @@ program .action(async (id) => { const task = await store.get(id); if (!task) { - console.error(`Task not found: ${id}`); + process.stderr.write(`Task not found: ${id}\n`); process.exit(1); } @@ -148,44 +148,44 @@ program // Print ancestors first (root to immediate parent) if (ancestors.length > 0) { - console.log("# Parent Context\n"); + process.stdout.write("# Parent Context\n\n"); for (const ancestor of ancestors.reverse()) { - console.log(`## ${ancestor.title} (${ancestor.id}) [${ancestor.status}]`); + process.stdout.write(`## ${ancestor.title} (${ancestor.id}) [${ancestor.status}]\n`); if (ancestor.body) { - console.log(`\n${ancestor.body}`); + process.stdout.write(`\n${ancestor.body}\n`); } - console.log(""); + process.stdout.write("\n"); } - console.log("---\n"); + process.stdout.write("---\n\n"); } // Print current task - console.log(`# ${task.title}\n`); - console.log(`id: ${task.id}`); - console.log(`status: ${task.status}`); - console.log(`created: ${task.created}`); + process.stdout.write(`# ${task.title}\n\n`); + process.stdout.write(`id: ${task.id}\n`); + process.stdout.write(`status: ${task.status}\n`); + process.stdout.write(`created: ${task.created}\n`); if (task.assignee) { - console.log(`assignee: ${task.assignee}`); + process.stdout.write(`assignee: ${task.assignee}\n`); } if (task.parentId) { - console.log(`parent: ${task.parentId}`); + process.stdout.write(`parent: ${task.parentId}\n`); } if (task.deps.length) { - console.log(`deps: [${task.deps.join(", ")}]`); + process.stdout.write(`deps: [${task.deps.join(", ")}]\n`); } if (task.body) { - console.log(`\n${task.body}`); + process.stdout.write(`\n${task.body}\n`); } if (task.acceptanceCriteria.length) { - console.log("\n## Acceptance Criteria\n"); + process.stdout.write("\n## Acceptance Criteria\n\n"); for (const criterion of task.acceptanceCriteria) { - console.log(`- [ ] ${criterion}`); + process.stdout.write(`- [ ] ${criterion}\n`); } } if (task.notes.length) { - console.log("\n## Notes"); + process.stdout.write("\n## Notes\n"); for (const note of task.notes) { - console.log(`\n**${note.timestamp}**\n${note.content}`); + process.stdout.write(`\n**${note.timestamp}**\n${note.content}\n`); } } }); @@ -198,7 +198,7 @@ program const tasks = await store.getReady(opts.scope); for (const t of tasks) { const assignee = t.assignee ? ` @${t.assignee}` : ""; - console.log(`${t.id} ${t.title}${assignee}`); + process.stdout.write(`${t.id} ${t.title}${assignee}\n`); } }); @@ -209,7 +209,7 @@ program .action(async (opts) => { const tasks = await store.getBlocked(opts.scope); for (const t of tasks) { - console.log(`${t.id} ${t.title} <- [${t.deps.join(", ")}]`); + process.stdout.write(`${t.id} ${t.title} <- [${t.deps.join(", ")}]\n`); } }); @@ -220,7 +220,7 @@ program .action(async (opts) => { const tasks = await store.getClosed(opts.scope); for (const t of tasks) { - console.log(`${t.id} ${t.title}`); + process.stdout.write(`${t.id} ${t.title}\n`); } }); @@ -230,7 +230,7 @@ program .action(async (id) => { const root = await store.get(id); if (!root) { - console.error(`Task not found: ${id}`); + process.stderr.write(`Task not found: ${id}\n`); process.exit(1); } @@ -241,8 +241,8 @@ program // Print a task line with optional dependency info const printTask = (task: Task, prefix: string, connector: string) => { const assignee = task.assignee ? ` @${task.assignee}` : ""; - console.log( - `${prefix}${connector}${task.id} [${task.status}] ${task.title}${assignee}` + process.stdout.write( + `${prefix}${connector}${task.id} [${task.status}] ${task.title}${assignee}\n` ); // Print dependencies on next line with arrow if (task.deps.length > 0) { @@ -253,13 +253,13 @@ program }) .join(", "); const depPrefix = prefix + (connector === "└── " ? " " : "│ "); - console.log(`${depPrefix}→ depends on: ${depNames}`); + process.stdout.write(`${depPrefix}→ depends on: ${depNames}\n`); } }; // Print root task const rootAssignee = root.assignee ? ` @${root.assignee}` : ""; - console.log(`${root.id} [${root.status}] ${root.title}${rootAssignee}`); + process.stdout.write(`${root.id} [${root.status}] ${root.title}${rootAssignee}\n`); if (root.deps.length > 0) { const depNames = root.deps .map((depId) => { @@ -267,7 +267,7 @@ program return dep ? `${dep.title} (${depId})` : depId; }) .join(", "); - console.log(`→ depends on: ${depNames}`); + process.stdout.write(`→ depends on: ${depNames}\n`); } // Recursively print children (hierarchy) @@ -292,7 +292,7 @@ program .description("Add dependency (id depends on dep-id)") .action(async (id, depId) => { await store.addDep(id, depId); - console.log(`Added: ${id} -> ${depId}`); + process.stdout.write(`Added: ${id} -> ${depId}\n`); }); program @@ -300,7 +300,7 @@ program .description("Remove dependency") .action(async (id, depId) => { await store.removeDep(id, depId); - console.log(`Removed: ${id} -> ${depId}`); + process.stdout.write(`Removed: ${id} -> ${depId}\n`); }); program @@ -313,7 +313,7 @@ program .action(async (id, opts) => { const task = await store.get(id); if (!task) { - console.error(`Task not found: ${id}`); + process.stderr.write(`Task not found: ${id}\n`); process.exit(1); } @@ -337,14 +337,14 @@ program } if (Object.keys(changes).length === 0 && opts.accept.length === 0) { - console.error("No changes specified"); + process.stderr.write("No changes specified\n"); process.exit(1); } if (Object.keys(changes).length > 0) { await store.update(id, changes); } - console.log(`Updated: ${id}`); + process.stdout.write(`Updated: ${id}\n`); }); program @@ -354,20 +354,20 @@ program .option("--root", "Make this a root task (remove parent)") .action(async (id, opts) => { if (!opts.parent && !opts.root) { - console.error("Must specify --parent or --root"); + process.stderr.write("Must specify --parent or --root\n"); process.exit(1); } if (opts.parent && opts.root) { - console.error("Cannot specify both --parent and --root"); + process.stderr.write("Cannot specify both --parent and --root\n"); process.exit(1); } await store.setParent(id, opts.root ? null : opts.parent); if (opts.root) { - console.log(`${id} is now a root task`); + process.stdout.write(`${id} is now a root task\n`); } else { - console.log(`${id} moved to parent ${opts.parent}`); + process.stdout.write(`${id} moved to parent ${opts.parent}\n`); } }); @@ -377,19 +377,19 @@ program .action(async (id) => { const task = await store.get(id); if (!task) { - console.error(`Task not found: ${id}`); + process.stderr.write(`Task not found: ${id}\n`); process.exit(1); } const children = await store.getChildren(id); if (children.length === 0) { - console.log("No children"); + process.stdout.write("No children\n"); return; } for (const child of children) { const assignee = child.assignee ? ` @${child.assignee}` : ""; - console.log(`${child.id} [${child.status}] ${child.title}${assignee}`); + process.stdout.write(`${child.id} [${child.status}] ${child.title}${assignee}\n`); } }); @@ -398,7 +398,7 @@ program .description("Add a timestamped note") .action(async (id, content) => { await store.addNote(id, content); - console.log("Note added"); + process.stdout.write("Note added\n"); }); program @@ -406,7 +406,7 @@ program .description("Mark draft as open (actionable)") .action(async (id) => { await store.open(id); - console.log(`${id} -> open`); + process.stdout.write(`${id} -> open\n`); }); program @@ -414,7 +414,7 @@ program .description("Mark as in progress") .action(async (id) => { await store.start(id); - console.log(`${id} -> in_progress`); + process.stdout.write(`${id} -> in_progress\n`); }); program @@ -423,7 +423,7 @@ program .description("Mark as done") .action(async (id) => { await store.close(id); - console.log(`${id} -> done`); + process.stdout.write(`${id} -> done\n`); }); program @@ -431,7 +431,7 @@ program .description("Mark as failed (catastrophically stuck)") .action(async (id) => { await store.fail(id); - console.log(`${id} -> failed`); + process.stdout.write(`${id} -> failed\n`); }); // Agent runner @@ -741,7 +741,7 @@ function getLogFile(): string { function log(logFile: string, message: string): void { const timestamp = new Date().toISOString(); appendFileSync(logFile, `[${timestamp}] ${message}\n`); - console.log(`[${timestamp}] ${message}`); + process.stdout.write(`[${timestamp}] ${message}\n`); } function parseJudgeVerdict(output: string): "DONE" | "NOT_DONE" | null { @@ -767,13 +767,13 @@ program const watchMode = opts.watch; const logFile = getLogFile(); - console.log("Task Runner started (planner/worker/judge loop)"); - console.log(`Planner: ${enablePlanner ? `${plannerModel} (replan every ${replanInterval} tasks)` : "disabled"}`); - console.log(`Judge: ${judgeModel}`); - console.log(`Max iterations: ${maxIterations === 0 ? "unlimited" : maxIterations}`); - if (scopeId) console.log(`Scope: ${scopeId}`); - console.log(`Log: ${logFile}`); - console.log(""); + process.stdout.write("Task Runner started (planner/worker/judge loop)\n"); + process.stdout.write(`Planner: ${enablePlanner ? `${plannerModel} (replan every ${replanInterval} tasks)` : "disabled"}\n`); + process.stdout.write(`Judge: ${judgeModel}\n`); + process.stdout.write(`Max iterations: ${maxIterations === 0 ? "unlimited" : maxIterations}\n`); + if (scopeId) process.stdout.write(`Scope: ${scopeId}\n`); + process.stdout.write(`Log: ${logFile}\n`); + process.stdout.write("\n"); log(logFile, `Started with planner=${enablePlanner ? plannerModel : "disabled"} replan=${replanInterval} judge=${judgeModel} maxIter=${maxIterations} scope=${scopeId || "all"}`); @@ -928,19 +928,19 @@ program await runTaskLoop(); if (watchMode) { - console.log("💤 Waiting for new tasks..."); + process.stdout.write("💤 Waiting for new tasks...\n"); while (true) { await new Promise((r) => setTimeout(r, 5000)); const ready = await store.getReady(scopeId); if (ready.length > 0) { await runTaskLoop(); - console.log("💤 Waiting for new tasks..."); + process.stdout.write("💤 Waiting for new tasks...\n"); } } } - console.log(""); - console.log(`All tasks complete. (${new Date().toISOString()})`); + process.stdout.write("\n"); + process.stdout.write(`All tasks complete. (${new Date().toISOString()})\n`); log(logFile, "All tasks complete"); });