From 9578502bcadd1696346e66cbc0e4d0783021b8c1 Mon Sep 17 00:00:00 2001 From: bendtherules Date: Tue, 21 Apr 2026 19:54:33 +0530 Subject: [PATCH] Add basic logging --- .env.example | 19 ++ .gitignore | 4 + bun.lock | 59 +++- coolify.yaml | 14 + logrotate.conf | 12 + package.json | 5 +- src/agent-tools/evaluateInEngine262.ts | 76 ++++- src/agent-tools/getSectionContent.ts | 216 ++++++++----- src/agent-tools/graphExplorer.ts | 81 +++-- src/agent-tools/reranker.ts | 123 ++++--- src/agent-tools/searchSpecSections.ts | 69 +++- src/lib/embeddings-factory.ts | 3 + src/lib/fireworks-embeddings.ts | 46 ++- src/lib/logger.ts | 424 +++++++++++++++++++++++++ src/lib/tracing.ts | 276 ++++++++++++++++ src/mcp-server-http.ts | 110 ++++--- src/mcp-server-stdio.ts | 86 +++-- 17 files changed, 1385 insertions(+), 238 deletions(-) create mode 100644 coolify.yaml create mode 100644 logrotate.conf create mode 100644 src/lib/logger.ts create mode 100644 src/lib/tracing.ts diff --git a/.env.example b/.env.example index d2d709d..90235dc 100644 --- a/.env.example +++ b/.env.example @@ -39,3 +39,22 @@ ASK262_EMBEDDING_PROVIDER=ollama # Required when running behind a reverse proxy or in production # Example: https://ask262.bendtherules.in or https://your-server.com # MCP_PUBLIC_URL=http://localhost:8081 + +# ============================================================================= +# LOGGING CONFIGURATION +# ============================================================================= + +# Log level: trace, debug, info, warn, error +# HTTP server defaults to 'debug', stdio server defaults to 'info' +# ASK262_LOG_LEVEL=info + +# Directory for log files (optional, defaults to ./logs) +# ASK262_LOG_DIR=./logs + +# Max log file size in MB before rotation (optional, defaults to 100) +# System logrotate handles rotation, this is for reference +# ASK262_LOG_MAX_SIZE=100 + +# Days to keep rotated logs before deletion (optional, defaults to 30) +# Set to 0 to keep forever +# ASK262_LOG_RETENTION_DAYS=30 diff --git a/.gitignore b/.gitignore index 038b8c7..6cd3e5b 100644 --- a/.gitignore +++ b/.gitignore @@ -21,6 +21,10 @@ coverage/ # Test output .idea/ *.log + +# Logs directory +/logs/ +*.jsonl # Optional: package lock files if you prefer not to commit them # package-lock.json # yarn.lock diff --git a/bun.lock b/bun.lock index 8822b1d..e028384 100644 --- a/bun.lock +++ b/bun.lock @@ -12,6 +12,7 @@ "@langchain/openai": "^0.1.0", "@mcp-use/inspector": "^2.1.0", "@modelcontextprotocol/sdk": "^1.0.4", + "@opentelemetry/api": "^1.9.1", "acorn": "^8.16.0", "cheerio": "^1.2.0", "commander": "^14.0.3", @@ -20,6 +21,8 @@ "hono": "^4.12.14", "langchain": "^0.2.0", "ora": "^9.3.0", + "pino": "^10.3.1", + "pino-pretty": "^13.1.3", }, "devDependencies": { "@biomejs/biome": "^2.4.9", @@ -229,6 +232,8 @@ "@paper-design/shaders-react": ["@paper-design/shaders-react@0.0.72", "", { "dependencies": { "@paper-design/shaders": "0.0.72" }, "peerDependencies": { "@types/react": "^18 || ^19", "react": "^18 || ^19" }, "optionalPeers": ["@types/react"] }, "sha512-q6KwquL93ZVNcuSM7pqzW0z/VLjnDVb/NSpYyGJBxf7MEHHCXx37E+zw/Px6RZLt3SGCUerIDDCGCMT385oW0w=="], + "@pinojs/redact": ["@pinojs/redact@0.4.0", "", {}, "sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg=="], + "@posthog/core": ["@posthog/core@1.25.2", "", {}, "sha512-h2FO7ut/BbfwpAXWpwdDHTzQgUo9ibDFEs6ZO+3cI3KPWQt5XwczK1OLAuPprcjm8T/jl0SH8jSFo5XdU4RbTg=="], "@posthog/types": ["@posthog/types@1.369.3", "", {}, "sha512-Ywqvs4513PixR2TIA5O3GMEyK4F65uefwxPfsIUeHr9ruGylyXp00YJ4CEbp8U0DMzCkeF+LsMKVnHgN3pAXcA=="], @@ -475,6 +480,8 @@ "asynckit": ["asynckit@0.4.0", "", {}, "sha512-Oei9OH4tRh0YqU3GxhX79dM/mwVgvbZJaSNaRk+bshkj0S5cfHcgYakreBjrHwatXKbz+IoIdYLxrKim2MjW0Q=="], + "atomic-sleep": ["atomic-sleep@1.0.0", "", {}, "sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ=="], + "balanced-match": ["balanced-match@4.0.4", "", {}, "sha512-BLrgEcRTwX2o6gGxGOCNyMvGSp35YofuYzw9h1IMTRmKqttAZZVU67bdb9Pr2vUHA8+j3i2tJfjO6C6+4myGTA=="], "base64-js": ["base64-js@1.5.1", "", {}, "sha512-AKpaYlHn8t4SVbOHCy+b5+KKgvR4vrsD8vbvrbiQJps7fKDTkjkDry6ji0rUJjC0kzbNePLwzxq8iypo41qeWA=="], @@ -539,6 +546,8 @@ "color-name": ["color-name@1.1.4", "", {}, "sha512-dOy+3AuW3a2wNbZHIuMZpTcgjGuLU/uBL/ubcZF9OXbDo8ff4O8yVp5Bf0efS8uEoYo5q4Fx7dY9OgQGXgAsQA=="], + "colorette": ["colorette@2.0.20", "", {}, "sha512-IfEDxwoWIjkeXL1eXcDiow4UbKjhLdq6/EuSVR9GMN7KVH3r9gQ83e73hsz1Nd1T3ijd5xv1wcWRYO+D6kCI2w=="], + "combined-stream": ["combined-stream@1.0.8", "", { "dependencies": { "delayed-stream": "~1.0.0" } }, "sha512-FQN4MRfuJeHf7cBbBMJFXhKSDq+2kAArBlmRBvcvFE5BB1HZKXtSFASDhdlz9zOYwxh8lDdnvmMOe/+5cdoEdg=="], "comma-separated-tokens": ["comma-separated-tokens@2.0.3", "", {}, "sha512-Fu4hJdvzeylCfQPp9SGWidpzrMs7tTrlu6Vb8XGaRGck8QSNZJJp538Wrb60Lax4fPwR64ViY468OIUTbRlGZg=="], @@ -553,7 +562,7 @@ "content-type": ["content-type@1.0.5", "", {}, "sha512-nTjqfcBFEipKdXCv4YDQWCfmcLZKm81ldF0pAopTvyrFGVbcR6P/VAAd5G7N+0tTr8QqiU0tFadD6FK4NtJwOA=="], - "cookie": ["cookie@1.1.1", "", {}, "sha512-ei8Aos7ja0weRpFzJnEA9UHJ/7XQmqglbRwnf2ATjcB9Wq874VKH9kfjjirM6UhU2/E5fFYadylyhFldcqSidQ=="], + "cookie": ["cookie@0.7.2", "", {}, "sha512-yki5XnKuf750l50uGTllt6kKILY4nQ1eNIQatoXEByZ5dWgnKqbnqmTrBE5B4N7lrMJKQ2ytWMiTO2o0v6Ew/w=="], "cookie-signature": ["cookie-signature@1.2.2", "", {}, "sha512-D76uU73ulSXrD1UXF4KE2TMxVVwhsnCgfAyTg9k8P6KGZjlXKrOLe4dJQKI3Bxi5wjesZoFXJWElNWBjPZMbhg=="], @@ -569,6 +578,8 @@ "csstype": ["csstype@3.2.3", "", {}, "sha512-z1HGKcYy2xA8AGQfwrn0PAy+PB7X/GSj3UVJW9qKyn43xWa+gl5nXmU4qqLMRzWVLFC8KusUX8T/0kCiOYpAIQ=="], + "dateformat": ["dateformat@4.6.3", "", {}, "sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA=="], + "debug": ["debug@4.4.3", "", { "dependencies": { "ms": "^2.1.3" } }, "sha512-RGwwWnwQvkVfavKVt22FGLw+xYSdzARwm0ru6DhTVA3umU5hZc28V3kO4stgYryrTlLpuvgI9GiijltAjNbcqA=="], "decamelize": ["decamelize@1.2.0", "", {}, "sha512-z2S+W9X73hAUUki+N+9Za2lBlun89zigOyGrsax+KUQ6wKW4ZoWpEYBkGhQjwAjjDCkWxhY0VKEhk8wzY7F5cA=="], @@ -611,6 +622,8 @@ "encoding-sniffer": ["encoding-sniffer@0.2.1", "", { "dependencies": { "iconv-lite": "^0.6.3", "whatwg-encoding": "^3.1.1" } }, "sha512-5gvq20T6vfpekVtqrYQsSCFZ1wEg5+wW0/QaZMWkFr6BqD3NfKs0rLCx4rrVlSWJeZb5NBJgVLswK/w2MWU+Gw=="], + "end-of-stream": ["end-of-stream@1.4.5", "", { "dependencies": { "once": "^1.4.0" } }, "sha512-ooEGc6HP26xXq/N+GCGOT0JKCLDGrq2bQUZrQ7gyrJiZANJ/8YDTxTpQBXGMn+WbIQXNVpyWymm7KYVICQnyOg=="], + "enhanced-resolve": ["enhanced-resolve@5.20.1", "", { "dependencies": { "graceful-fs": "^4.2.4", "tapable": "^2.3.0" } }, "sha512-Qohcme7V1inbAfvjItgw0EaxVX5q2rdVEZHRBrEQdRZTssLDGsL8Lwrznl8oQ/6kuTJONLaDcGjkNP247XEhcA=="], "entities": ["entities@4.5.0", "", {}, "sha512-V0hjH4dGPh9Ao5p0MoRY6BVqtwCjhz6vI5LT8AJ55H+4g9/4vbHx1I54fS0XuclLhDHArPQCiMjDxjaL8fPxhw=="], @@ -647,10 +660,14 @@ "express-rate-limit": ["express-rate-limit@8.3.2", "", { "dependencies": { "ip-address": "10.1.0" }, "peerDependencies": { "express": ">= 4.11" } }, "sha512-77VmFeJkO0/rvimEDuUC5H30oqUC4EyOhyGccfqoLebB0oiEYfM7nwPrsDsBL1gsTpwfzX8SFy2MT3TDyRq+bg=="], + "fast-copy": ["fast-copy@4.0.3", "", {}, "sha512-58apWr0GUiDFM8+3afrO6eYwJBn9ZAhDOzG3L+/9llab/haCARS2UIfffmOurYLwbgDRs8n0rfr6qAAPEAuAQw=="], + "fast-deep-equal": ["fast-deep-equal@3.1.3", "", {}, "sha512-f3qQ9oQy9j2AhBe/H9VC91wLmKBCCU/gDOnKNAYG5hswO7BLKj09Hc5HYNz9cGI++xlpDCIgDaitVs03ATR84Q=="], "fast-glob": ["fast-glob@3.3.3", "", { "dependencies": { "@nodelib/fs.stat": "^2.0.2", "@nodelib/fs.walk": "^1.2.3", "glob-parent": "^5.1.2", "merge2": "^1.3.0", "micromatch": "^4.0.8" } }, "sha512-7MptL8U0cqcFdzIzwOTHoilX9x5BrNqye7Z/LuC7kCMRio1EMSyqRK3BEAUD7sXRq4iT4AzTVuZdhgQ2TCvYLg=="], + "fast-safe-stringify": ["fast-safe-stringify@2.1.1", "", {}, "sha512-W+KJc2dmILlPplD/H4K9l9LcAHAfPtP6BY84uVLXQ6Evcz9Lcg33Y2z1IVblT6xdY54PXYVHEv+0Wpq8Io6zkA=="], + "fast-uri": ["fast-uri@3.1.0", "", {}, "sha512-iPeeDKJSWf4IEOasVVrknXpaBV0IApz/gp7S2bb7Z4Lljbl2MGJRqInZiUrQwV16cpzw/D3S5j5Julj/gT52AA=="], "fastq": ["fastq@1.20.1", "", { "dependencies": { "reusify": "^1.0.4" } }, "sha512-GGToxJ/w1x32s/D2EKND7kTil4n8OVk/9mycTc4VDza13lOvpUZTGX3mFSCtV9ksdGBVzvsyAVLM6mHFThxXxw=="], @@ -727,6 +744,8 @@ "hastscript": ["hastscript@9.0.1", "", { "dependencies": { "@types/hast": "^3.0.0", "comma-separated-tokens": "^2.0.0", "hast-util-parse-selector": "^4.0.0", "property-information": "^7.0.0", "space-separated-tokens": "^2.0.0" } }, "sha512-g7df9rMFX/SPi34tyGCyUBREQoKkapwdY/T04Qn9TDWfHhAYt4/I0gMVirzK5wEzeUqIjEB+LXC/ypb7Aqno5w=="], + "help-me": ["help-me@5.0.0", "", {}, "sha512-7xgomUX6ADmcYzFik0HzAxh/73YlKR9bmFzf51CZwR+b6YtzU2m0u49hQCqV6SvlqIqsaxovfwdvbnsw3b/zpg=="], + "highlight.js": ["highlight.js@10.7.3", "", {}, "sha512-tzcUFauisWKNHaRkN4Wjl/ZA07gENAjFl3J/c480dprkGTg5EQstgaNFqBfUqCq54kZRIEcreTsAgF/m2quD7A=="], "highlightjs-vue": ["highlightjs-vue@1.0.0", "", {}, "sha512-PDEfEF102G23vHmPhLyPboFCD+BkMGu+GuJe2d9/eH4FsCwvgBpnc9n0pGE+ffKdph38s6foEZiEjdgHdzp+IA=="], @@ -787,6 +806,8 @@ "jose": ["jose@6.2.2", "", {}, "sha512-d7kPDd34KO/YnzaDOlikGpOurfF0ByC2sEV4cANCtdqLlTfBlw2p14O/5d/zv40gJPbIQxfES3nSx1/oYNyuZQ=="], + "joycon": ["joycon@3.1.1", "", {}, "sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw=="], + "js-tiktoken": ["js-tiktoken@1.0.21", "", { "dependencies": { "base64-js": "^1.5.1" } }, "sha512-biOj/6M5qdgx5TKjDnFT1ymSpM5tbd3ylwDtrQvFQSu0Z7bBYko2dF+W/aUkXUPuk6IVpRxk/3Q2sHOzGlS36g=="], "js-yaml": ["js-yaml@4.1.1", "", { "dependencies": { "argparse": "^2.0.1" }, "bin": { "js-yaml": "bin/js-yaml.js" } }, "sha512-qQKT4zQxXl8lLwBtHMWwaTcGfFOZviOJet3Oy/xmGk2gZH677CJM9EvtfdSkgWcATZhj/55JZ0rmy3myCT5lsA=="], @@ -869,6 +890,8 @@ "minimatch": ["minimatch@10.2.4", "", { "dependencies": { "brace-expansion": "^5.0.2" } }, "sha512-oRjTw/97aTBN0RHbYCdtF1MQfvusSIBQM0IZEgzl6426+8jSC0nF1a/GmnVLpfB9yyr6g6FTqWqiZVbxrtaCIg=="], + "minimist": ["minimist@1.2.8", "", {}, "sha512-2yyAR8qBkN3YuheJanUpWC5U3bb5osDywNB8RzDVlDwDHbocAJveqqj1u8+SVD7jkWT4yvsHCpWqqWqAxb0zCA=="], + "minipass": ["minipass@7.1.3", "", {}, "sha512-tEBHqDnIoM/1rXME1zgka9g6Q2lcoCkxHLuc7ODJ5BxbP5d4c2Z5cGgtXAku59200Cx7diuHTOYfSBD8n6mm8A=="], "minizlib": ["minizlib@3.1.0", "", { "dependencies": { "minipass": "^7.1.2" } }, "sha512-KZxYo1BUkWD2TVFLr0MQoM8vUUigWD3LlD83a/75BqC+4qE0Hb1Vo5v1FgcfaNXvfXzr+5EhQ6ing/CaBijTlw=="], @@ -905,6 +928,8 @@ "ollama": ["ollama@0.5.18", "", { "dependencies": { "whatwg-fetch": "^3.6.20" } }, "sha512-lTFqTf9bo7Cd3hpF6CviBe/DEhewjoZYd9N/uCe7O20qYTvGqrNOFOBDj3lbZgFWHUgDv5EeyusYxsZSLS8nvg=="], + "on-exit-leak-free": ["on-exit-leak-free@2.1.2", "", {}, "sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA=="], + "on-finished": ["on-finished@2.4.1", "", { "dependencies": { "ee-first": "1.1.1" } }, "sha512-oVlzkg3ENAhCk2zdv7IJwd/QUD4z2RxRwpkcGY8psCVcCYZNq4wYnVWALHM+brtuJjePWiYF/ClmuDr8Ch5+kg=="], "once": ["once@1.4.0", "", { "dependencies": { "wrappy": "1" } }, "sha512-lNaJgI+2Q5URQBkccEKHTQOPaXdUxnZZElQTZY0MFUAuaEqe1E+Nyvgdz/aIyNi6Z9MzO5dv1H8n58/GELp3+w=="], @@ -947,6 +972,14 @@ "picomatch": ["picomatch@4.0.4", "", {}, "sha512-QP88BAKvMam/3NxH6vj2o21R6MjxZUAd6nlwAS/pnGvN9IVLocLHxGYIzFhg6fUQ+5th6P4dv4eW9jX3DSIj7A=="], + "pino": ["pino@10.3.1", "", { "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" } }, "sha512-r34yH/GlQpKZbU1BvFFqOjhISRo1MNx1tWYsYvmj6KIRHSPMT2+yHOEb1SG6NMvRoHRF0a07kCOox/9yakl1vg=="], + + "pino-abstract-transport": ["pino-abstract-transport@3.0.0", "", { "dependencies": { "split2": "^4.0.0" } }, "sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg=="], + + "pino-pretty": ["pino-pretty@13.1.3", "", { "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" } }, "sha512-ttXRkkOz6WWC95KeY9+xxWL6AtImwbyMHrL1mSwqwW9u+vLp/WIElvHvCSDg0xO/Dzrggz1zv3rN5ovTRVowKg=="], + + "pino-std-serializers": ["pino-std-serializers@7.1.0", "", {}, "sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw=="], + "pkce-challenge": ["pkce-challenge@5.0.1", "", {}, "sha512-wQ0b/W4Fr01qtpHlqSqspcj3EhBvimsdh0KlHhH8HRZnMsEa0ea2fTULOXOS9ccQr3om+GcGRk4e+isrZWV8qQ=="], "postcss": ["postcss@8.5.10", "", { "dependencies": { "nanoid": "^3.3.11", "picocolors": "^1.1.1", "source-map-js": "^1.2.1" } }, "sha512-pMMHxBOZKFU6HgAZ4eyGnwXF/EvPGGqUr0MnZ5+99485wwW41kW91A4LOGxSHhgugZmSChL5AlElNdwlNgcnLQ=="], @@ -961,18 +994,24 @@ "prismjs": ["prismjs@1.30.0", "", {}, "sha512-DEvV2ZF2r2/63V+tK8hQvrR2ZGn10srHbXviTlcv7Kpzw8jWiNTqbVgjO3IY8RxrrOUF8VPMQQFysYYYv0YZxw=="], + "process-warning": ["process-warning@5.0.0", "", {}, "sha512-a39t9ApHNx2L4+HBnQKqxxHNs1r7KF+Intd8Q/g1bUh6q0WIp9voPXJ/x0j+ZL45KF1pJd9+q2jLIRMfvEshkA=="], + "property-information": ["property-information@7.1.0", "", {}, "sha512-TwEZ+X+yCJmYfL7TPUOcvBZ4QfoT5YenQiJuX//0th53DE6w0xxLEtfK3iyryQFddXuvkIk51EEgrJQ0WJkOmQ=="], "protobufjs": ["protobufjs@7.5.5", "", { "dependencies": { "@protobufjs/aspromise": "^1.1.2", "@protobufjs/base64": "^1.1.2", "@protobufjs/codegen": "^2.0.4", "@protobufjs/eventemitter": "^1.1.0", "@protobufjs/fetch": "^1.1.0", "@protobufjs/float": "^1.0.2", "@protobufjs/inquire": "^1.1.0", "@protobufjs/path": "^1.1.2", "@protobufjs/pool": "^1.1.0", "@protobufjs/utf8": "^1.1.0", "@types/node": ">=13.7.0", "long": "^5.0.0" } }, "sha512-3wY1AxV+VBNW8Yypfd1yQY9pXnqTAN+KwQxL8iYm3/BjKYMNg4i0owhEe26PWDOMaIrzeeF98Lqd5NGz4omiIg=="], "proxy-addr": ["proxy-addr@2.0.7", "", { "dependencies": { "forwarded": "0.2.0", "ipaddr.js": "1.9.1" } }, "sha512-llQsMLSUDUPT44jdrU/O37qlnifitDP+ZwrmmZcoSKyLKvtZxpyV0n2/bD/N4tBAAZ/gJEdZU7KMraoK1+XYAg=="], + "pump": ["pump@3.0.4", "", { "dependencies": { "end-of-stream": "^1.1.0", "once": "^1.3.1" } }, "sha512-VS7sjc6KR7e1ukRFhQSY5LM2uBWAUPiOPa/A3mkKmiMwSmRFUITt0xuj+/lesgnCv+dPIEYlkzrcyXgquIHMcA=="], + "qs": ["qs@6.15.1", "", { "dependencies": { "side-channel": "^1.1.0" } }, "sha512-6YHEFRL9mfgcAvql/XhwTvf5jKcOiiupt2FiJxHkiX1z4j7WL8J/jRHYLluORvc1XxB5rV20KoeK00gVJamspg=="], "query-selector-shadow-dom": ["query-selector-shadow-dom@1.0.1", "", {}, "sha512-lT5yCqEBgfoMYpf3F2xQRK7zEr1rhIIZuceDK6+xRkJQ4NMbHTwXqk4NkwDwQMNqXgG9r9fyHnzwNVs6zV5KRw=="], "queue-microtask": ["queue-microtask@1.2.3", "", {}, "sha512-NuaNSa6flKT5JaSYQzJok04JzTL1CA6aGhv5rfLW3PgqA+M2ChpZQnAC8h8i4ZFkBS8X5RqkDBHA7r4hej3K9A=="], + "quick-format-unescaped": ["quick-format-unescaped@4.0.4", "", {}, "sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg=="], + "range-parser": ["range-parser@1.2.1", "", {}, "sha512-Hrgsx+orqoygnmhFbKaHE6c296J+HTAQXoxEF6gNupROmmGJRoyzfG3ccAveqCBrwr/2yxQ5BVd/GTl5agOwSg=="], "raw-body": ["raw-body@3.0.2", "", { "dependencies": { "bytes": "~3.1.2", "http-errors": "~2.0.1", "iconv-lite": "~0.7.0", "unpipe": "~1.0.0" } }, "sha512-K5zQjDllxWkf7Z5xJdV0/B0WTNqx6vxG70zJE4N0kBs4LovmEYWJzQGxC9bS9RAKu3bgM40lrd5zoLJ12MQ5BA=="], @@ -997,6 +1036,8 @@ "readdirp": ["readdirp@5.0.0", "", {}, "sha512-9u/XQ1pvrQtYyMpZe7DXKv2p5CNvyVwzUB6uhLAnQwHMSgKMBR62lc7AHljaeteeHXn11XTAaLLUVZYVZyuRBQ=="], + "real-require": ["real-require@0.2.0", "", {}, "sha512-57frrGM/OCTLqLOAh0mhVA9VBMHd+9U7Zb2THMGdBUoZVOtGbJzjxsYGDJ3A9AYYCP4hn6y1TVbaOfzWtm5GFg=="], + "redis": ["redis@5.12.1", "", { "dependencies": { "@redis/bloom": "5.12.1", "@redis/client": "5.12.1", "@redis/json": "5.12.1", "@redis/search": "5.12.1", "@redis/time-series": "5.12.1" } }, "sha512-LDsoVvb/CpoV9EN3FXvgvSHNJWuCIzl9MiO3ppOevuGLpSGJhwfQjpEwfFJcQvNSddHADDdZaWx0HnmMxRXG7g=="], "reflect-metadata": ["reflect-metadata@0.2.2", "", {}, "sha512-urBwgfrvVP/eAyXx4hluJivBKzuEbSQs9rKWCrCkbSxNv8mxPcUZKeuoF3Uy4mJl3Lwprp6yy5/39VWigZ4K6Q=="], @@ -1025,10 +1066,14 @@ "safe-buffer": ["safe-buffer@5.2.1", "", {}, "sha512-rp3So07KcdmmKbGvgaNxQSJr7bGVSVk5S9Eq1F+ppbRo70+YeaDxkw5Dd8NPN+GD6bjnYm2VuPuCXmpuYvmCXQ=="], + "safe-stable-stringify": ["safe-stable-stringify@2.5.0", "", {}, "sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA=="], + "safer-buffer": ["safer-buffer@2.1.2", "", {}, "sha512-YZo3K82SD7Riyi0E1EQPojLz7kpepnSQI9IyPbHHg1XXXevb5dJI7tpyN2ADxGcQbHG7vcyRHk0cbwqcQriUtg=="], "scheduler": ["scheduler@0.27.0", "", {}, "sha512-eNv+WrVbKu1f3vbYJT/xtiF5syA5HPIMtf9IgY/nKg0sWqzAUEvqY/xm7OcZc/qafLx/iO9FgOmeSAp4v5ti/Q=="], + "secure-json-parse": ["secure-json-parse@4.1.0", "", {}, "sha512-l4KnYfEyqYJxDwlNVyRfO2E4NTHfMKAWdUuA8J0yve2Dz/E/PdBepY03RvyJpssIpRFwJoCD55wA+mEDs6ByWA=="], + "semver": ["semver@7.7.4", "", { "bin": { "semver": "bin/semver.js" } }, "sha512-vFKC2IEtQnVhpT78h1Yp8wzwrf8CM+MzKMHGJZfBtzhZNycRFnXsHk6E5TxIkkMsgNS7mdX3AGB7x2QM2di4lA=="], "send": ["send@1.2.1", "", { "dependencies": { "debug": "^4.4.3", "encodeurl": "^2.0.0", "escape-html": "^1.0.3", "etag": "^1.8.1", "fresh": "^2.0.0", "http-errors": "^2.0.1", "mime-types": "^3.0.2", "ms": "^2.1.3", "on-finished": "^2.4.1", "range-parser": "^1.2.1", "statuses": "^2.0.2" } }, "sha512-1gnZf7DFcoIcajTjTwjwuDjzuz4PPcY2StKPlsGAQ1+YH20IRVrBaXSWmdjowTJ6u8Rc01PoYOGHXfP1mYcZNQ=="], @@ -1055,12 +1100,16 @@ "slash": ["slash@5.1.0", "", {}, "sha512-ZA6oR3T/pEyuqwMgAKT0/hAv8oAXckzbkmR0UkUosQ+Mc4RxGoJkRmwHgHufaenlyAgE1Mxgpdcrf75y6XcnDg=="], + "sonic-boom": ["sonic-boom@4.2.1", "", { "dependencies": { "atomic-sleep": "^1.0.0" } }, "sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q=="], + "sonner": ["sonner@2.0.7", "", { "peerDependencies": { "react": "^18.0.0 || ^19.0.0 || ^19.0.0-rc", "react-dom": "^18.0.0 || ^19.0.0 || ^19.0.0-rc" } }, "sha512-W6ZN4p58k8aDKA4XPcx2hpIQXBRAgyiWVkYhT7CvK6D3iAu7xjvVyhQHg2/iaKJZ1XVJ4r7XuwGL+WGEK37i9w=="], "source-map-js": ["source-map-js@1.2.1", "", {}, "sha512-UXWMKhLOwVKb728IUtQPXxfYU+usdybtUrK/8uGE8CQMvrhOpwvzDBwj0QhSL7MQc7vIsISBG8VQ8+IDQxpfQA=="], "space-separated-tokens": ["space-separated-tokens@2.0.2", "", {}, "sha512-PEGlAwrG8yXGXRjW32fGbg66JAlOAwbObuqVoJpv/mRgoWDQfgH1wDPvtzWyUSNAXBGSk8h755YDbbcEy3SH2Q=="], + "split2": ["split2@4.2.0", "", {}, "sha512-UcjcJOWknrNkF6PLX83qcHM6KHgVKNkV62Y8a5uYDVv9ydGQVwAHMKqHdJje1VTWpljG0WYpCDhrCdAOYH4TWg=="], + "statuses": ["statuses@2.0.2", "", {}, "sha512-DvEy55V3DB7uknRo+4iOGT5fP1slR8wQohVdknigZPMpMstaKJQWhwiYBACJE3Ul2pTnATihhBYnRhZQHGBiRw=="], "stdin-discarder": ["stdin-discarder@0.3.1", "", {}, "sha512-reExS1kSGoElkextOcPkel4NE99S0BWxjUHQeDFnR8S993JxpPX7KU4MNmO19NXhlJp+8dmdCbKQVNgLJh2teA=="], @@ -1069,6 +1118,8 @@ "strip-ansi": ["strip-ansi@7.2.0", "", { "dependencies": { "ansi-regex": "^6.2.2" } }, "sha512-yDPMNjp4WyfYBkHnjIRLfca1i6KMyGCtsVgoKe/z1+6vukgaENdgGBZt+ZmKPc4gavvEZ5OgHfHdrazhgNyG7w=="], + "strip-json-comments": ["strip-json-comments@5.0.3", "", {}, "sha512-1tB5mhVo7U+ETBKNf92xT4hrQa3pm0MZ0PQvuDnWgAAGHDsfp4lPSpiS6psrSiet87wyGPh9ft6wmhOMQ0hDiw=="], + "supports-color": ["supports-color@7.2.0", "", { "dependencies": { "has-flag": "^4.0.0" } }, "sha512-qpCAvRl9stuOHveKsn7HncJRvv501qIacKzQlO/+Lwxc9+0q2wLyv4Dfvt80/DPn2pqOBsJdDiogXGR9+OvwRw=="], "table-layout": ["table-layout@4.1.1", "", { "dependencies": { "array-back": "^6.2.2", "wordwrapjs": "^5.1.0" } }, "sha512-iK5/YhZxq5GO5z8wb0bY1317uDF3Zjpha0QFFLA8/trAoiLbQD0HUbMesEaxyzUgDxi2QlcbM8IvqOlEjgoXBA=="], @@ -1085,6 +1136,8 @@ "thenify-all": ["thenify-all@1.6.0", "", { "dependencies": { "thenify": ">= 3.1.0 < 4" } }, "sha512-RNxQH/qI8/t3thXJDwcstUO4zeqo64+Uy/+sNVRBx4Xn2OX+OZ9oP+iJnNFqplFra2ZUVeKCSa2oVWi3T4uVmA=="], + "thread-stream": ["thread-stream@4.0.0", "", { "dependencies": { "real-require": "^0.2.0" } }, "sha512-4iMVL6HAINXWf1ZKZjIPcz5wYaOdPhtO8ATvZ+Xqp3BTdaqtAwQkNmKORqcIo5YkQqGXq5cwfswDwMqqQNrpJA=="], + "tinyglobby": ["tinyglobby@0.2.16", "", { "dependencies": { "fdir": "^6.5.0", "picomatch": "^4.0.4" } }, "sha512-pn99VhoACYR8nFHhxqix+uvsbXineAasWm5ojXoN8xEwK5Kd3/TrhNn1wByuD52UxWRLy8pu+kRMniEi6Eq9Zg=="], "to-regex-range": ["to-regex-range@5.0.1", "", { "dependencies": { "is-number": "^7.0.0" } }, "sha512-65P7iz6X5yEr1cwcgvQxbbIw7Uk3gOy5dIdtZ4rDveLqhrdJP+Li/Hx6tyK0NEb+2GCyneCMJiGqrADCSNk8sQ=="], @@ -1237,8 +1290,6 @@ "encoding-sniffer/iconv-lite": ["iconv-lite@0.6.3", "", { "dependencies": { "safer-buffer": ">= 2.1.2 < 3.0.0" } }, "sha512-4fCk79wshMdzMp2rH06qWrJE4iolqLhCUH+OiuIgU++RB0+94NlDL81atO7GX55uUKueo0txHNtvEyI6D7WdMw=="], - "express/cookie": ["cookie@0.7.2", "", {}, "sha512-yki5XnKuf750l50uGTllt6kKILY4nQ1eNIQatoXEByZ5dWgnKqbnqmTrBE5B4N7lrMJKQ2ytWMiTO2o0v6Ew/w=="], - "form-data/mime-types": ["mime-types@2.1.35", "", { "dependencies": { "mime-db": "1.52.0" } }, "sha512-ZDY+bPm5zTTF+YpCrAU9nK0UgICYPT0QtT1NZWFv4s++TNkcgVaT0g6+4R2uI4MjQjzysHB1zxuWL50hzaeXiw=="], "htmlparser2/entities": ["entities@7.0.1", "", {}, "sha512-TWrgLOFUQTH994YUyl1yT4uyavY5nNB5muff+RtWaqNVCAK408b5ZnnbNAUEWLTCpum9w6arT70i1XdQ4UeOPA=="], @@ -1269,6 +1320,8 @@ "parse5/entities": ["entities@6.0.1", "", {}, "sha512-aN97NXWF6AWBTahfVOIrB/NShkzi5H7F9r1s9mD3cDj4Ko5f2qhhVoYMibXF7GlLveb/D2ioWay8lxI97Ven3g=="], + "react-router/cookie": ["cookie@1.1.1", "", {}, "sha512-ei8Aos7ja0weRpFzJnEA9UHJ/7XQmqglbRwnf2ATjcB9Wq874VKH9kfjjirM6UhU2/E5fFYadylyhFldcqSidQ=="], + "table-layout/array-back": ["array-back@6.2.3", "", {}, "sha512-SGDvmg6QTYiTxCBkYVmThcoa67uLl35pyzRHdpCGBOcqFy6BtwnphoFPk7LhJshD+Yk1Kt35WGWeZPTgwR4Fhw=="], "whatwg-encoding/iconv-lite": ["iconv-lite@0.6.3", "", { "dependencies": { "safer-buffer": ">= 2.1.2 < 3.0.0" } }, "sha512-4fCk79wshMdzMp2rH06qWrJE4iolqLhCUH+OiuIgU++RB0+94NlDL81atO7GX55uUKueo0txHNtvEyI6D7WdMw=="], diff --git a/coolify.yaml b/coolify.yaml new file mode 100644 index 0000000..aa00224 --- /dev/null +++ b/coolify.yaml @@ -0,0 +1,14 @@ +# coolify.yaml - Coolify deployment configuration +version: 1 + +services: + - name: ask262 + +cronjobs: + - name: "log-rotation" + schedule: "*/5 * * * *" # Every 5 minutes + command: "logrotate -f /app/logrotate.conf 2>/dev/null || true" + + - name: "log-cleanup" + schedule: "0 0 * * *" # Daily at midnight + command: "find ${ASK262_LOG_DIR:-/app/logs} -name 'ask262.jsonl.*' -mtime +${ASK262_LOG_RETENTION_DAYS:-30} -delete 2>/dev/null || true" diff --git a/logrotate.conf b/logrotate.conf new file mode 100644 index 0000000..585519e --- /dev/null +++ b/logrotate.conf @@ -0,0 +1,12 @@ +# Logrotate configuration for ask262 MCP server +# Rotates logs at 100MB, keeps 10 rotated files, compresses old ones + +${ASK262_LOG_DIR}/ask262.jsonl { + size 100M + rotate 10 + compress + delaycompress + copytruncate + notifempty + missingok +} diff --git a/package.json b/package.json index bed792e..1a27bd7 100644 --- a/package.json +++ b/package.json @@ -58,6 +58,7 @@ "@langchain/openai": "^0.1.0", "@mcp-use/inspector": "^2.1.0", "@modelcontextprotocol/sdk": "^1.0.4", + "@opentelemetry/api": "^1.9.1", "acorn": "^8.16.0", "cheerio": "^1.2.0", "commander": "^14.0.3", @@ -65,7 +66,9 @@ "graphology": "^0.26.0", "hono": "^4.12.14", "langchain": "^0.2.0", - "ora": "^9.3.0" + "ora": "^9.3.0", + "pino": "^10.3.1", + "pino-pretty": "^13.1.3" }, "devDependencies": { "@biomejs/biome": "^2.4.9", diff --git a/src/agent-tools/evaluateInEngine262.ts b/src/agent-tools/evaluateInEngine262.ts index 7a0dc16..ad9f71d 100644 --- a/src/agent-tools/evaluateInEngine262.ts +++ b/src/agent-tools/evaluateInEngine262.ts @@ -9,6 +9,8 @@ import { spawn } from "node:child_process"; import path from "node:path"; import { fileURLToPath } from "node:url"; import { z } from "zod"; +import { LogOperation, logger } from "../lib/logger.js"; +import { withSpan } from "../lib/tracing.js"; // #region Zod schemas (not exported) @@ -232,17 +234,69 @@ export function createEvaluateInEngine262Tool( timeoutMs = DEFAULT_EXECUTION_TIMEOUT_MS, ) { return async ({ code }: EvaluateToolInput): Promise => { - try { - // Execute code in isolated child process - const resultJson = await executeInChildProcess(code, timeoutMs); + const log = await logger.forComponent("engine262-runner"); - // Parse the result - return JSON.parse(resultJson) as EvaluateToolOutput; - } catch (error) { - // Return error result - return { - error: error instanceof Error ? error.message : String(error), - }; - } + log.info(LogOperation.EVALUATE_IN_ENGINE262, { code_length: code.length }); + + // Truncate code for logging if too long (>500 chars) + const codeForLog = + code.length > 500 + ? `${code.substring(0, 500)}... (${code.length - 500} more chars)` + : code; + + // Only the main evaluating_in_engine262 span logs the full code + return await withSpan( + LogOperation.EVALUATING_IN_ENGINE262, + { code: codeForLog, code_length: code.length, timeout_ms: timeoutMs }, + async () => { + const op = log.start(LogOperation.EVALUATING_IN_ENGINE262, { + code: codeForLog, + code_length: code.length, + timeout_ms: timeoutMs, + }); + + try { + // Child operations don't need to log the code - it's in the parent span context + log.debug(LogOperation.SPAWNING_CHILD_PROCESS, { + timeout_ms: timeoutMs, + }); + + // Execute code in isolated child process + const resultJson = await executeInChildProcess(code, timeoutMs); + + // Parse the result + const result = JSON.parse(resultJson) as EvaluateToolOutput; + + if ("error" in result && result.error) { + log.warn(LogOperation.ENGINE262_ABRUPT_COMPLETION, { + error: result.error, + }); + op.end({ status: "error", error: result.error }); + } else { + const successResult = result as EvaluateSuccessOutput; + // op.end logs the final completion with all metrics and duration + op.end({ + status: "success", + important_sections: successResult.importantSections.length, + other_sections: successResult.otherSections.length, + console_entries: successResult.consoleOutput.length, + }); + } + + return result; + } catch (err) { + const error = err instanceof Error ? err : new Error(String(err)); + log.error( + LogOperation.EVALUATING_IN_ENGINE262, + { code_length: code.length }, + error, + ); + op.end({ status: "exception", error: error.message }); + return { + error: error.message, + }; + } + }, + ); }; } diff --git a/src/agent-tools/getSectionContent.ts b/src/agent-tools/getSectionContent.ts index 8f0beaf..aa90f35 100644 --- a/src/agent-tools/getSectionContent.ts +++ b/src/agent-tools/getSectionContent.ts @@ -5,6 +5,8 @@ import type { Table } from "@lancedb/lancedb"; import { z } from "zod"; +import { LogOperation, logger } from "../lib/logger.js"; +import { withSpan } from "../lib/tracing.js"; // #region Zod schemas (not exported) @@ -21,6 +23,8 @@ const sectionDataSchema = z.object({ error: z.string().optional(), sectionTitle: z.string().optional(), childrensectionids: z.array(z.string()).optional(), + partIndex: z.number().optional(), + totalParts: z.number().optional(), }); const getSectionContentOutputSchema = z.object({ @@ -81,95 +85,133 @@ export function createGetSectionContentTool(table: Table) { sectionIds, recursive, }: GetSectionContentInput): Promise => { - const sectionsData = new Map< - string, - { - content: string[]; - title?: string; - childrenSectionIds?: string[]; - } - >(); - const queue: string[] = [...sectionIds]; - const visited = new Set(); + const log = await logger.forComponent("get-section-tool"); - while (queue.length > 0) { - const currentId = queue.shift(); - if (!currentId || visited.has(currentId)) continue; - visited.add(currentId); - - const results = await table - .query() - .where(`sectionid = '${currentId}'`) - .limit(10) - .toArray(); - - // Sort by partindex to maintain order (nulls last for single-part sections) - const sortedResults = results.sort((a: unknown, b: unknown) => { - const aIndex = (a as { partindex?: number }).partindex ?? Infinity; - const bIndex = (b as { partindex?: number }).partindex ?? Infinity; - return aIndex - bIndex; - }); - - for (const result of sortedResults) { - const typedResult = result as { - text?: string; - childrensectionids?: unknown; - sectiontitle?: string; - partindex?: number; - totalparts?: number; - }; - - // Normalize childrensectionids: LanceDB may return an Apache Arrow Vector - // which is iterable but not a plain JS array. - const childrenIds = typedResult.childrensectionids - ? Array.from(typedResult.childrensectionids as Iterable) - : undefined; - - // Get or create section data - let section = sectionsData.get(currentId); - if (!section) { - section = { - content: [], - title: typedResult.sectiontitle, - childrenSectionIds: childrenIds, - }; - sectionsData.set(currentId, section); - } - - if (typedResult.text) { - section.content.push(typedResult.text); - } - - // Add children to queue for recursive fetching only if recursive is true - if (recursive && childrenIds && childrenIds.length > 0) { - queue.push(...childrenIds); - } - } - } - - // Build output array from all requested sections - // Missing sections are included with found: false and error message - const sections = sectionIds.map((id) => { - const data = sectionsData.get(id); - if (data) { - return { - sectionId: id, - content: data.content.join("\n\n"), - found: true, - sectionTitle: data.title, - childrensectionids: data.childrenSectionIds, - }; - } - return { - sectionId: id, - content: "", - found: false, - error: `Section '${id}' not found in database`, - }; + log.info(LogOperation.GET_SECTION_CONTENT, { + section_count: sectionIds.length, + recursive, }); - return { - sections, - }; + return await withSpan( + LogOperation.FETCHING_SECTION_CONTENT, + { section_count: sectionIds.length, recursive }, + async () => { + const op = log.start(LogOperation.FETCHING_SECTION_CONTENT, { + section_ids: sectionIds, + recursive, + }); + + const sectionsData = new Map< + string, + { + content: string[]; + title?: string; + childrenSectionIds?: string[]; + } + >(); + const queue: string[] = [...sectionIds]; + const visited = new Set(); + + try { + while (queue.length > 0) { + const currentId = queue.shift(); + if (!currentId || visited.has(currentId)) continue; + visited.add(currentId); + + const results = await table + .query() + .where(`sectionid = '${currentId}'`) + .limit(10) + .toArray(); + + // Sort by partindex to maintain order (nulls last for single-part sections) + const sortedResults = results.sort((a: unknown, b: unknown) => { + const aIndex = (a as { partindex?: number }).partindex ?? Infinity; + const bIndex = (b as { partindex?: number }).partindex ?? Infinity; + return aIndex - bIndex; + }); + + for (const result of sortedResults) { + const typedResult = result as { + text?: string; + childrensectionids?: unknown; + sectiontitle?: string; + partindex?: number; + totalparts?: number; + }; + + // Normalize childrensectionids: LanceDB may return an Apache Arrow Vector + // which is iterable but not a plain JS array. + const childrenIds = typedResult.childrensectionids + ? Array.from(typedResult.childrensectionids as Iterable) + : undefined; + + // Get or create section data + let section = sectionsData.get(currentId); + if (!section) { + section = { + content: [], + title: typedResult.sectiontitle, + childrenSectionIds: childrenIds, + }; + sectionsData.set(currentId, section); + } + + if (typedResult.text) { + section.content.push(typedResult.text); + } + + // Add children to queue for recursive fetching only if recursive is true + if (recursive && childrenIds && childrenIds.length > 0) { + queue.push(...childrenIds); + } + } + } + + // Build output array from all requested sections + // Missing sections are included with found: false and error message + const sections = sectionIds.map((id) => { + const data = sectionsData.get(id); + if (data) { + return { + sectionId: id, + content: data.content.join("\n\n"), + found: true, + sectionTitle: data.title, + childrensectionids: data.childrenSectionIds, + }; + } + return { + sectionId: id, + content: "", + found: false, + error: `Section '${id}' not found in database`, + }; + }); + + const totalSectionsFetched = sectionsData.size; + const totalContentLength = sections.reduce( + (sum, s) => sum + s.content.length, + 0, + ); + + op.end({ + total_sections: totalSectionsFetched, + total_content_length: totalContentLength, + recursive, + }); + + return { sections }; + } catch (err) { + const error = err instanceof Error ? err : new Error(String(err)); + log.error( + LogOperation.FETCHING_SECTION_CONTENT, + { section_ids: sectionIds }, + error, + ); + throw err; + } + }, + ); }; } diff --git a/src/agent-tools/graphExplorer.ts b/src/agent-tools/graphExplorer.ts index 7eaa14e..6a0eabc 100644 --- a/src/agent-tools/graphExplorer.ts +++ b/src/agent-tools/graphExplorer.ts @@ -6,6 +6,8 @@ import { DynamicStructuredTool } from "@langchain/core/tools"; import type Graph from "graphology"; import { z } from "zod"; +import { LogOperation, logger } from "../lib/logger.js"; +import { withSpan } from "../lib/tracing.js"; const graphExplorerSchema = z.object({ query: z @@ -27,33 +29,68 @@ export function createGraphExplorerTool(graph: Graph) { "Explores structural relationships between specification sections and implementation code (functions). Use this to find which spec section a function implements.", schema: graphExplorerSchema, func: async ({ query }) => { - let nodeId = query; - if (!graph.hasNode(nodeId)) { - if (graph.hasNode(`func-${query}`)) { - nodeId = `func-${query}`; - } - } + const log = await logger.forComponent("graph-explorer"); - if (graph.hasNode(nodeId)) { - const neighbors = graph.neighbors(nodeId); - const nodeAttr = graph.getNodeAttributes(nodeId); + log.info(LogOperation.EXPLORING_GRAPH, { query }); - let result = `Information for ${nodeId} (${nodeAttr.type}):\n`; - if (nodeAttr.title) result += `- Title: ${nodeAttr.title}\n`; - if (nodeAttr.file) result += `- File: ${nodeAttr.file}\n`; - result += `\nConnected parts:\n`; + return await withSpan( + LogOperation.EXPLORING_GRAPH, + { query }, + async () => { + const op = log.start(LogOperation.EXPLORING_GRAPH, { query }); - neighbors.forEach((neighbor: string) => { - const attr = graph.getNodeAttributes(neighbor); - const edges = graph.edges(nodeId, neighbor); - const edgeAttr = graph.getEdgeAttributes(edges[0]); - result += `- ${neighbor} (${attr.type}) via ${edgeAttr.type}${attr.title ? `: ${attr.title}` : ""}\n`; - }); + let nodeId = query; + if (!graph.hasNode(nodeId)) { + if (graph.hasNode(`func-${query}`)) { + nodeId = `func-${query}`; + log.debug(LogOperation.RESOLVING_NODE_ID, { + original: query, + resolved: nodeId, + }); + } + } - return result; - } + if (graph.hasNode(nodeId)) { + const neighbors = graph.neighbors(nodeId); + const nodeAttr = graph.getNodeAttributes(nodeId); - return `No information found in graph for ${query}. Use ask262_search_spec_sections to search text.`; + log.debug(LogOperation.NODE_FOUND, { + node_id: nodeId, + type: nodeAttr.type, + neighbor_count: neighbors.length, + }); + + let result = `Information for ${nodeId} (${nodeAttr.type}):\n`; + if (nodeAttr.title) result += `- Title: ${nodeAttr.title}\n`; + if (nodeAttr.file) result += `- File: ${nodeAttr.file}\n`; + result += `\nConnected parts:\n`; + + neighbors.forEach((neighbor: string) => { + const attr = graph.getNodeAttributes(neighbor); + const edges = graph.edges(nodeId, neighbor); + const edgeAttr = graph.getEdgeAttributes(edges[0]); + result += `- ${neighbor} (${attr.type}) via ${edgeAttr.type}${attr.title ? `: ${attr.title}` : ""}\n`; + }); + + op.end({ + status: "found", + node_id: nodeId, + type: nodeAttr.type, + neighbor_count: neighbors.length, + }); + + return result; + } + + log.warn(LogOperation.NODE_NOT_FOUND, { + query, + attempted_id: nodeId, + }); + op.end({ status: "not_found", query }); + + return `No information found in graph for ${query}. Use ask262_search_spec_sections to search text.`; + }, + ); }, }); } diff --git a/src/agent-tools/reranker.ts b/src/agent-tools/reranker.ts index 022ba7a..9b1d365 100644 --- a/src/agent-tools/reranker.ts +++ b/src/agent-tools/reranker.ts @@ -4,6 +4,8 @@ */ import { RERANKER_MODEL } from "../constants.js"; +import { LogOperation, logger } from "../lib/logger.js"; +import { withSpan } from "../lib/tracing.js"; const OLLAMA_HOST = process.env.OLLAMA_HOST || "http://localhost:11434"; @@ -23,46 +25,91 @@ export async function rerankDocuments( query: string, documents: T[], ): Promise[]> { - try { - const response = await fetch(`${OLLAMA_HOST}/api/rerank`, { - method: "POST", - headers: { "Content-Type": "application/json" }, - body: JSON.stringify({ + const log = await logger.forComponent("reranker"); + + log.info(LogOperation.RERANKING_DOCUMENTS, { + document_count: documents.length, + }); + + return await withSpan( + LogOperation.RERANKING_DOCUMENTS, + { document_count: documents.length }, + async () => { + const op = log.start(LogOperation.RERANKING_DOCUMENTS, { + document_count: documents.length, model: RERANKER_MODEL, - query: query, - documents: documents.map((d) => d.pageContent), - }), - }); + }); - if (!response.ok) { - console.warn( - `Reranker API failed: ${response.statusText}. Returning all documents.`, - ); - return documents.map((doc, i) => ({ - document: doc, - score: 1.0, - index: i, - })); - } + try { + const response = await fetch(`${OLLAMA_HOST}/api/rerank`, { + method: "POST", + headers: { "Content-Type": "application/json" }, + body: JSON.stringify({ + model: RERANKER_MODEL, + query: query, + documents: documents.map((d) => d.pageContent), + }), + }); - const data = await response.json(); - if (!data.results || !Array.isArray(data.results)) { - return documents.map((doc, i) => ({ - document: doc, - score: 1.0, - index: i, - })); - } + if (!response.ok) { + log.warn("reranker_api_failed", { + status: response.status, + statusText: response.statusText, + }); + op.end({ + status: "api_failed", + fallback: true, + document_count: documents.length, + }); + return documents.map((doc, i) => ({ + document: doc, + score: 1.0, + index: i, + })); + } - return data.results.map( - (result: { index: number; relevance_score: number }) => ({ - document: documents[result.index], - score: result.relevance_score, - index: result.index, - }), - ); - } catch (error) { - console.warn(`Reranker error: ${error}. Returning all documents.`); - return documents.map((doc, i) => ({ document: doc, score: 1.0, index: i })); - } + const data = await response.json(); + if (!data.results || !Array.isArray(data.results)) { + log.warn("reranker_invalid_response", { response: data }); + op.end({ + status: "invalid_response", + fallback: true, + document_count: documents.length, + }); + return documents.map((doc, i) => ({ + document: doc, + score: 1.0, + index: i, + })); + } + + // op.end logs the final success with all metrics + op.end({ + status: "success", + results_count: data.results.length, + }); + + return data.results.map( + (result: { index: number; relevance_score: number }) => ({ + document: documents[result.index], + score: result.relevance_score, + index: result.index, + }), + ); + } catch (error) { + const err = error instanceof Error ? error : new Error(String(error)); + log.warn("reranker_error", { error: err.message }); + op.end({ + status: "error", + error: err.message, + fallback: true, + }); + return documents.map((doc, i) => ({ + document: doc, + score: 1.0, + index: i, + })); + } + }, + ); } diff --git a/src/agent-tools/searchSpecSections.ts b/src/agent-tools/searchSpecSections.ts index eb14207..3aba9b0 100644 --- a/src/agent-tools/searchSpecSections.ts +++ b/src/agent-tools/searchSpecSections.ts @@ -6,6 +6,8 @@ import type { Table } from "@lancedb/lancedb"; import type { Embeddings } from "@langchain/core/embeddings"; import { z } from "zod"; +import { LogOperation, logger } from "../lib/logger.js"; +import { withSpan } from "../lib/tracing.js"; // #region Zod schemas (not exported) @@ -72,23 +74,60 @@ export function createSearchSpecSectionsTool( embeddings: Embeddings, ) { return async ({ query }: SearchSpecInput): Promise => { - // Generate embedding for the query - const queryVector = await embeddings.embedQuery(query); + const log = await logger.forComponent("search-tool"); - // Search using LanceDB directly, limit to top 5 results - const results = await table.search(queryVector).limit(5).toArray(); + log.info(LogOperation.SEARCH_SPEC_SECTIONS, { query }); - // Return documents with metadata as structured objects - const output: SearchSpecResult[] = results.map( - (r: Record) => ({ - sectionId: String(r.sectionid || "unknown"), - sectionTitle: String(r.sectiontitle || "unknown"), - vectorDistance: Number(r._distance || 0), - partIndex: (r.partindex as number | undefined) ?? null, - totalParts: (r.totalparts as number | undefined) ?? null, - }), + return await withSpan( + LogOperation.SEARCHING_SPEC_SECTIONS, + { query }, + async () => { + const op = log.start(LogOperation.SEARCHING_SPEC_SECTIONS, { query }); + + const SEARCH_LIMIT = 5; + + try { + // Generate embedding for the query (timed operation) + const embedOp = log.start(LogOperation.GENERATING_EMBEDDING, { + query, + }); + const queryVector = await embeddings.embedQuery(query); + embedOp.end(); + + // Search using LanceDB directly, limit to top results (timed operation) + const searchOp = log.start(LogOperation.QUERYING_LANCEDB, { + query, + limit: SEARCH_LIMIT, + }); + const results = await table + .search(queryVector) + .limit(SEARCH_LIMIT) + .toArray(); + searchOp.end({ results_found: results.length }); + + // Return documents with metadata as structured objects + const output: SearchSpecResult[] = results.map( + (r: Record) => ({ + sectionId: String(r.sectionid || "unknown"), + sectionTitle: String(r.sectiontitle || "unknown"), + vectorDistance: Number(r._distance || 0), + partIndex: (r.partindex as number | undefined) ?? null, + totalParts: (r.totalparts as number | undefined) ?? null, + }), + ); + + op.end({ + results: output.length, + section_ids: output.map((r) => r.sectionId), + }); + + return { results: output }; + } catch (err) { + const error = err instanceof Error ? err : new Error(String(err)); + log.error(LogOperation.SEARCHING_SPEC_SECTIONS, { query }, error); + throw err; + } + }, ); - - return { results: output }; }; } diff --git a/src/lib/embeddings-factory.ts b/src/lib/embeddings-factory.ts index 568e4a1..ff1d014 100644 --- a/src/lib/embeddings-factory.ts +++ b/src/lib/embeddings-factory.ts @@ -66,6 +66,9 @@ export function createEmbeddings(provider?: EmbeddingProvider): Embeddings { } } +// Provider logging is done via console.error to stderr +// Detailed embedding operation logging is in the individual embedding classes + /** * Get the currently configured embedding provider. * diff --git a/src/lib/fireworks-embeddings.ts b/src/lib/fireworks-embeddings.ts index 1b12396..f79b8fd 100644 --- a/src/lib/fireworks-embeddings.ts +++ b/src/lib/fireworks-embeddings.ts @@ -1,4 +1,5 @@ import { Embeddings, type EmbeddingsParams } from "@langchain/core/embeddings"; +import { LogOperation, logger } from "./logger.js"; /** * Interface for FireworksEmbeddings parameters. @@ -97,15 +98,37 @@ export class FireworksEmbeddings extends Embeddings { return []; } + const log = await logger.forComponent("fireworks-embeddings"); + const op = log.start(LogOperation.EMBEDDING_DOCUMENTS, { + total_documents: documents.length, + batch_size: this.batchSize, + model: this.modelName, + }); + const allEmbeddings: number[][] = []; + const totalBatches = Math.ceil(documents.length / this.batchSize); // Process in batches for (let i = 0; i < documents.length; i += this.batchSize) { + const batchNum = Math.floor(i / this.batchSize) + 1; const batch = documents.slice(i, i + this.batchSize); + + log.debug(LogOperation.PROCESSING_EMBEDDING_BATCH, { + batch_num: batchNum, + total_batches: totalBatches, + batch_size: batch.length, + }); + const batchEmbeddings = await this.embedBatchWithRetry(batch); allEmbeddings.push(...batchEmbeddings); } + op.end({ + total_documents: documents.length, + batches: totalBatches, + embeddings_generated: allEmbeddings.length, + }); + return allEmbeddings; } @@ -116,7 +139,15 @@ export class FireworksEmbeddings extends Embeddings { documents: string[], attempt = 1, ): Promise { + const log = await logger.forComponent("fireworks-embeddings"); + try { + log.debug(LogOperation.PROCESSING_EMBEDDING_BATCH, { + batch_size: documents.length, + attempt, + model: this.modelName, + }); + return await this.embedBatch(documents); } catch (error) { // Check if it's a rate limit error (429) @@ -126,13 +157,22 @@ export class FireworksEmbeddings extends Embeddings { if (isRateLimit && attempt < this.maxRetries) { const delay = this.initialRetryDelayMs * 2 ** (attempt - 1); - console.error( - `[Fireworks] Rate limit hit. Waiting ${delay}ms before retry ${attempt}/${this.maxRetries}...`, - ); + log.warn(LogOperation.RETRYING_RATE_LIMIT, { + attempt, + max_retries: this.maxRetries, + delay_ms: delay, + batch_size: documents.length, + }); await sleep(delay); return this.embedBatchWithRetry(documents, attempt + 1); } + log.error( + LogOperation.PROCESSING_EMBEDDING_BATCH, + { batch_size: documents.length, attempt, is_rate_limit: isRateLimit }, + error instanceof Error ? error : new Error(String(error)), + ); + // Fail fast for other errors or if retries exhausted throw error; } diff --git a/src/lib/logger.ts b/src/lib/logger.ts new file mode 100644 index 0000000..8d5b632 --- /dev/null +++ b/src/lib/logger.ts @@ -0,0 +1,424 @@ +/** + * Centralized logging module for Ask262 MCP server. + * + * Provides structured JSON logging with OpenTelemetry-style tracing support. + * Uses Pino for high-performance logging with dual output: + * - File: JSON Lines format for DuckDB querying + * - Console: Pretty-printed for development visibility + * + * @module lib/logger + */ + +import { createWriteStream } from "node:fs"; +import { mkdir } from "node:fs/promises"; +import { join } from "node:path"; +import pino from "pino"; +import pretty from "pino-pretty"; +import { getTraceContext } from "./tracing.js"; + +/** + * Log levels supported by the logger. + */ +export type LogLevel = "trace" | "debug" | "info" | "warn" | "error"; + +/** + * Standardized operation names for logging. + * Using an enum ensures consistency across the codebase. + * + * Tense conventions: + * - Present continuous (-ing) for timed operations that have start/end + * - Past tense for lifecycle events and completion states + * - Tool names for MCP tool invocations (logged at info level) + */ +export enum LogOperation { + // Server lifecycle (past tense for events) + SERVER_STARTED = "server_started", + SERVER_STOPPED = "server_stopped", + + // HTTP handling (present continuous for timed request handling) + HANDLING_MCP_HTTP_REQUEST = "handling_mcp_http_request", + + // MCP Tool invocations (tool names, logged at info level) + SEARCH_SPEC_SECTIONS = "search_spec_sections", + GET_SECTION_CONTENT = "get_section_content", + EVALUATE_IN_ENGINE262 = "evaluate_in_engine262", + + // MCP Tool spans (present continuous tense of tool names) + // Note: These are the same as the timed operation names below for consistency + + // Vector search operations (present continuous) + SEARCHING_SPEC_SECTIONS = "searching_spec_sections", + GENERATING_EMBEDDING = "generating_embedding", + QUERYING_LANCEDB = "querying_lancedb", + + // Section fetch operations (present continuous) + FETCHING_SECTION_CONTENT = "fetching_section_content", + QUERYING_TABLE = "querying_table", + + // Code execution operations (present continuous for timed) + EVALUATING_IN_ENGINE262 = "evaluating_in_engine262", + SPAWNING_CHILD_PROCESS = "spawning_child_process", + // Completion states (engine262 spec terminology - normal/abrupt completion) + ENGINE262_NORMAL_COMPLETION = "engine262_normal_completion", + ENGINE262_ABRUPT_COMPLETION = "engine262_abrupt_completion", + + // Reranking operations (present continuous) + RERANKING_DOCUMENTS = "reranking_documents", + + // Graph exploration (present continuous for actions, past for results) + EXPLORING_GRAPH = "exploring_graph", + RESOLVING_NODE_ID = "resolving_node_id", + NODE_FOUND = "node_found", + NODE_NOT_FOUND = "node_not_found", + + // Embedding batch operations (present continuous) + EMBEDDING_DOCUMENTS = "embedding_documents", + PROCESSING_EMBEDDING_BATCH = "processing_embedding_batch", + RETRYING_RATE_LIMIT = "retrying_rate_limit", +} + +/** + * Numeric log level values (Pino convention). + */ +const LOG_LEVEL_VALUES: Record = { + trace: 10, + debug: 20, + info: 30, + warn: 40, + error: 50, +}; + +/** + * Valid log level strings. + */ +const VALID_LOG_LEVELS: LogLevel[] = [ + "trace", + "debug", + "info", + "warn", + "error", +]; + +/** + * Components that can log in the application. + */ +export type LogComponent = + | "http-server" + | "stdio-server" + | "search-tool" + | "get-section-tool" + | "engine262-runner" + | "reranker" + | "graph-explorer" + | "embeddings-factory" + | "fireworks-embeddings"; + +/** + * Get the file log level from environment. + * HTTP server defaults to 'debug', stdio defaults to 'info'. + * + * @returns The configured file log level + */ +function getFileLogLevel(): LogLevel { + const envLevel = process.env.ASK262_LOG_LEVEL?.toLowerCase(); + if (envLevel && VALID_LOG_LEVELS.includes(envLevel as LogLevel)) { + return envLevel as LogLevel; + } + // Default: debug for HTTP, info for stdio + return "debug"; +} + +/** + * Get the console log level. + * Console shows max('info', file level) - never shows debug. + * + * @returns The calculated console log level + */ +function getConsoleLogLevel(): LogLevel { + const fileLevel = getFileLogLevel(); + const fileLevelValue = LOG_LEVEL_VALUES[fileLevel]; + const infoLevelValue = LOG_LEVEL_VALUES.info; + + // Console level is max of (info, file level) + return fileLevelValue > infoLevelValue ? fileLevel : "info"; +} + +/** + * Get the log directory from environment. + * + * @returns The configured log directory path + */ +function getLogDir(): string { + return process.env.ASK262_LOG_DIR ?? "./logs"; +} + +/** + * Ensure the log directory exists. + * Creates the directory recursively if it doesn't exist. + * + * @throws Error if directory cannot be created + */ +async function ensureLogDir(): Promise { + const logDir = getLogDir(); + try { + await mkdir(logDir, { recursive: true }); + } catch (err) { + const errorMsg = err instanceof Error ? err.message : String(err); + throw new Error( + `Failed to create log directory '${logDir}': ${errorMsg}. ` + + "Check permissions or set ASK262_LOG_DIR to a writable location.", + ); + } +} + +/** + * Fields to redact from logs for security. + */ +const REDACT_FIELDS = [ + "FIREWORKS_API_KEY", + "api_key", + "authorization", + "password", + "secret", + "token", +]; + +/** + * Create the root Pino logger instance. + * + * @returns Configured Pino logger with dual transport + */ +async function createRootLogger(): Promise { + await ensureLogDir(); + + const logDir = getLogDir(); + const logFile = join(logDir, "ask262.jsonl"); + + const fileLevel = getFileLogLevel(); + const consoleLevel = getConsoleLogLevel(); + + // File transport: JSON Lines format, synchronous writes + const fileStream = createWriteStream(logFile, { flags: "a" }); + + // Console transport: Pretty printed + const consoleStream = pretty({ + colorize: true, + translateTime: "SYS:standard", + ignore: "pid,hostname", + }); + + return pino( + { + level: fileLevel, + redact: { + paths: REDACT_FIELDS, + remove: true, + censor: "[REDACTED]", + }, + mixin() { + // Add trace context if available + const traceCtx = getTraceContext(); + if (traceCtx) { + return { + trace_id: traceCtx.traceId, + span_id: traceCtx.spanId, + parent_span_id: traceCtx.parentSpanId, + }; + } + return {}; + }, + formatters: { + level(label: string) { + return { level: label }; + }, + }, + timestamp: () => `,"timestamp":"${new Date().toISOString()}"`, + }, + pino.multistream([ + { stream: fileStream, level: fileLevel }, + { stream: consoleStream, level: consoleLevel }, + ]), + ); +} + +// Singleton root logger instance +let rootLogger: pino.Logger | null = null; + +/** + * Get or create the root logger instance. + * + * @returns The root logger + */ +async function getRootLogger(): Promise { + if (!rootLogger) { + rootLogger = await createRootLogger(); + } + return rootLogger; +} + +/** + * Interface for timed operations. + */ +export interface TimedOperation { + /** + * End the timed operation and log the result. + * + * @param resultAttrs - Additional attributes to log with the result + */ + end(resultAttrs?: Record): void; +} + +/** + * Interface for component-bound loggers. + */ +export interface ComponentLogger { + /** + * Log at trace level. + * + * @param operation - The operation being performed (use LogOperation enum) + * @param attrs - Additional attributes + */ + trace( + operation: LogOperation | string, + attrs?: Record, + ): void; + + /** + * Log at debug level. + * + * @param operation - The operation being performed (use LogOperation enum) + * @param attrs - Additional attributes + */ + debug( + operation: LogOperation | string, + attrs?: Record, + ): void; + + /** + * Log at info level. + * + * @param operation - The operation being performed (use LogOperation enum) + * @param attrs - Additional attributes + */ + info(operation: LogOperation | string, attrs?: Record): void; + + /** + * Log at warn level. + * + * @param operation - The operation being performed (use LogOperation enum) + * @param attrs - Additional attributes + */ + warn(operation: LogOperation | string, attrs?: Record): void; + + /** + * Log at error level. + * + * @param operation - The operation being performed (use LogOperation enum) + * @param attrs - Additional attributes + * @param error - Optional error to include + */ + error( + operation: LogOperation | string, + attrs?: Record, + error?: Error, + ): void; + + /** + * Start a timed operation. + * + * @param operation - The operation name (use LogOperation enum) + * @param attrs - Initial attributes + * @returns Timed operation handle + */ + start( + operation: LogOperation | string, + attrs?: Record, + ): TimedOperation; +} + +/** + * Create a logger bound to a specific component. + * + * @param component - The component name (e.g., 'search-tool') + * @returns Component-bound logger + * + * @example + * ```typescript + * const log = logger.forComponent('search-tool'); + * + * // Simple log + * log.info('vector_search_started', { query: 'how does array.map work' }); + * + * // Timed operation + * const op = log.start('vector_search', { query: 'how does array.map work' }); + * const results = await doSearch(query); + * op.end({ results: results.length }); + * ``` + */ +export async function forComponent( + component: LogComponent, +): Promise { + const root = await getRootLogger(); + + return { + trace(operation: string, attrs?: Record) { + root.trace({ component, operation, ...attrs }); + }, + + debug(operation: string, attrs?: Record) { + root.debug({ component, operation, ...attrs }); + }, + + info(operation: string, attrs?: Record) { + root.info({ component, operation, ...attrs }); + }, + + warn(operation: string, attrs?: Record) { + root.warn({ component, operation, ...attrs }); + }, + + error(operation: string, attrs?: Record, error?: Error) { + if (error) { + root.error({ component, operation, err: error, ...attrs }); + } else { + root.error({ component, operation, ...attrs }); + } + }, + + start(operation: string, attrs?: Record): TimedOperation { + const startTime = performance.now(); + + // Log start + root.debug({ component, operation, status: "started", ...attrs }); + + return { + end(resultAttrs?: Record) { + const durationMs = Math.round(performance.now() - startTime); + root.debug({ + component, + operation, + status: "completed", + duration_ms: durationMs, + ...attrs, + ...resultAttrs, + }); + }, + }; + }, + }; +} + +/** + * Logger factory function. + * + * Use this to get component-bound loggers: + * ```typescript + * const log = await logger.forComponent('search-tool'); + * ``` + */ +export const logger = { + forComponent, +}; + +// Export for direct use in simple cases +export { getRootLogger }; diff --git a/src/lib/tracing.ts b/src/lib/tracing.ts new file mode 100644 index 0000000..9a2a4bd --- /dev/null +++ b/src/lib/tracing.ts @@ -0,0 +1,276 @@ +/** + * OpenTelemetry trace context management for Ask262 MCP server. + * + * Provides AsyncLocalStorage-based context propagation for nested operations, + * enabling automatic parent-child span relationships without manual ID passing. + * + * @module lib/tracing + */ + +import { AsyncLocalStorage } from "node:async_hooks"; +import { randomUUID } from "node:crypto"; +import { SpanStatusCode, trace } from "@opentelemetry/api"; + +/** + * Trace context stored in AsyncLocalStorage. + */ +interface TraceContext { + /** The root trace identifier */ + traceId: string; + /** The current span identifier */ + spanId: string; + /** Parent span identifier (null for root spans) */ + parentSpanId: string | null; + /** Span depth level (0 = root) */ + depth: number; +} + +// AsyncLocalStorage for automatic context propagation +const traceStorage = new AsyncLocalStorage(); + +/** + * Get the current trace context from AsyncLocalStorage. + * + * @returns Current trace context or undefined if not in a trace + */ +function getCurrentContext(): TraceContext | undefined { + return traceStorage.getStore(); +} + +/** + * Generate a unique span ID. + * + * @returns Short span ID (16 hex chars) + */ +function generateSpanId(): string { + return randomUUID().replace(/-/g, "").slice(0, 16); +} + +/** + * Generate a unique trace ID. + * + * @returns Full trace ID (32 hex chars) + */ +function generateTraceId(): string { + return randomUUID().replace(/-/g, ""); +} + +/** + * Create a new trace context for a root operation. + * + * @param traceId - Optional existing trace ID (e.g., from request header) + * @returns New trace context + * + * @example + * ```typescript + * // Create new trace + * const traceCtx = createTraceContext(); + * + * // Or use existing trace ID from request + * const traceCtx = createTraceContext(req.headers['x-request-id'] as string); + * ``` + */ +export function createTraceContext(traceId?: string): TraceContext { + return { + traceId: traceId ?? generateTraceId(), + spanId: generateSpanId(), + parentSpanId: null, + depth: 0, + }; +} + +/** + * Execute a function within a trace context. + * + * This creates a new span and runs the function with that span as the active + * context. Any nested operations will automatically inherit this context. + * + * @param operation - The operation name for the span + * @param attributes - Initial span attributes + * @param fn - The function to execute within the span + * @param traceId - Optional trace ID to use (e.g., from request header) + * @returns Result of the function + * + * @example + * ```typescript + * const result = await withSpan( + * 'mcp_request', + * { tool: 'search-spec-sections' }, + * async () => { + * // All code here has access to the span context + * return await handleRequest(); + * } + * ); + * ``` + */ +export async function withSpan( + operation: string, + attributes: Record = {}, + fn: () => Promise, + traceId?: string, +): Promise { + const parentContext = getCurrentContext(); + const tracer = trace.getTracer("ask262"); + + // Build span context + const spanContext: TraceContext = parentContext + ? { + traceId: parentContext.traceId, + spanId: generateSpanId(), + parentSpanId: parentContext.spanId, + depth: parentContext.depth + 1, + } + : createTraceContext(traceId); + + // Create OTel span for context tracking + const span = tracer.startSpan(operation, { + attributes: { + ...attributes, + "span.depth": spanContext.depth, + }, + }); + + // Store in AsyncLocalStorage for nested calls + return traceStorage.run(spanContext, async () => { + try { + const result = await fn(); + span.setStatus({ code: SpanStatusCode.OK }); + return result; + } catch (err) { + span.setStatus({ + code: SpanStatusCode.ERROR, + message: err instanceof Error ? err.message : String(err), + }); + span.recordException(err instanceof Error ? err : new Error(String(err))); + throw err; + } finally { + span.end(); + } + }); +} + +/** + * Get the current trace ID if in a trace context. + * + * @returns Trace ID or undefined + */ +export function getTraceId(): string | undefined { + return getCurrentContext()?.traceId; +} + +/** + * Get the current span ID if in a trace context. + * + * @returns Span ID or undefined + */ +export function getSpanId(): string | undefined { + return getCurrentContext()?.spanId; +} + +/** + * Get the parent span ID if in a trace context. + * + * @returns Parent span ID or undefined/null + */ +export function getParentSpanId(): string | null | undefined { + return getCurrentContext()?.parentSpanId; +} + +/** + * Create a process-scoped trace context for stdio server. + * + * This creates a single trace ID that persists for the entire process lifetime, + * suitable for stdio transport where there's no natural request boundary. + * + * @returns Process-scoped trace context + * + * @example + * ```typescript + * // At server startup + * const sessionTraceId = createProcessScopedTrace(); + * + * // For each message, use the same trace ID + * await withSpanContext(sessionTraceId, 'mcp_request', async () => { + * // handle message + * }); + * ``` + */ +export function createProcessScopedTrace(): string { + return generateTraceId(); +} + +/** + * Execute a function with a specific trace context. + * + * Similar to withSpan but uses an existing trace ID, useful for stdio + * where you want the same trace ID across multiple operations. + * + * @param traceId - The trace ID to use + * @param operation - The operation name + * @param attributes - Span attributes + * @param fn - The function to execute + * @returns Result of the function + */ +export async function withSpanContext( + traceId: string, + operation: string, + attributes: Record = {}, + fn: () => Promise, +): Promise { + // Check if we're already in a context + const existingContext = getCurrentContext(); + + if (existingContext && existingContext.traceId === traceId) { + // Already in this trace, create child span + return withSpan(operation, attributes, fn); + } + + // Create new root span with this trace ID + const spanContext: TraceContext = { + traceId, + spanId: generateSpanId(), + parentSpanId: null, + depth: 0, + }; + + const tracer = trace.getTracer("ask262"); + const span = tracer.startSpan(operation, { + attributes: { + ...attributes, + "span.depth": 0, + }, + }); + + return traceStorage.run(spanContext, async () => { + try { + const result = await fn(); + span.setStatus({ code: SpanStatusCode.OK }); + return result; + } catch (err) { + span.setStatus({ + code: SpanStatusCode.ERROR, + message: err instanceof Error ? err.message : String(err), + }); + span.recordException(err instanceof Error ? err : new Error(String(err))); + throw err; + } finally { + span.end(); + } + }); +} + +/** + * Trace context for HTTP server requests. + * + * Creates a new trace context for each request, optionally using + * an existing trace ID from request headers. + * + * @param requestId - Optional request ID from headers + * @returns New trace context for this request + */ +export function createHttpTraceContext(requestId?: string): TraceContext { + return createTraceContext(requestId); +} + +// Re-export for convenience +export { getCurrentContext as getTraceContext }; diff --git a/src/mcp-server-http.ts b/src/mcp-server-http.ts index 659d408..417d1ec 100644 --- a/src/mcp-server-http.ts +++ b/src/mcp-server-http.ts @@ -35,6 +35,8 @@ import { } from "./agent-tools/index.js"; import { DEFAULT_PORT, STORAGE_DIR as STORAGE_DIR_REL } from "./constants.js"; import { createEmbeddings } from "./lib/embeddings-factory.js"; +import { LogOperation, logger } from "./lib/logger.js"; +import { withSpan } from "./lib/tracing.js"; // Resolve storage path relative to this script's directory const __filename = fileURLToPath(import.meta.url); @@ -88,11 +90,7 @@ async function createMcpServer() { }, }, async ({ query }) => { - console.log(`[TOOL] ${searchSpecToolName}: query="${query}"`); const result = await searchSpecTool({ query }); - console.log( - `[TOOL] ${searchSpecToolName}: ${result.results.length} results`, - ); return { content: [{ type: "text", text: JSON.stringify(result, null, 2) }], structuredContent: result, @@ -115,17 +113,7 @@ async function createMcpServer() { }, }, async ({ sectionIds, recursive }) => { - console.log( - `[TOOL] ${sectionContentToolName}: sectionIds=[${sectionIds.map((id: string) => `"${id}"`).join(", ")}] recursive=${recursive}`, - ); const result = await getSectionContentTool({ sectionIds, recursive }); - const totalContentLength = result.sections.reduce( - (sum: number, s: { content: string }) => sum + s.content.length, - 0, - ); - console.log( - `[TOOL] ${sectionContentToolName}: ${totalContentLength} chars, ${result.sections.length} sections`, - ); return { content: [{ type: "text", text: JSON.stringify(result, null, 2) }], structuredContent: result, @@ -148,16 +136,8 @@ async function createMcpServer() { }, }, async ({ code }) => { - console.log(`[TOOL] ${evaluateToolName}: code length=${code.length}`); const result = await evaluateTool({ code }); const isError = result.error !== undefined; - if (isError) { - console.log(`[TOOL] ${evaluateToolName}: error - ${result.error}`); - } else { - console.log( - `[TOOL] ${evaluateToolName}: ${result.importantSections.length} important, ${result.otherSections.length} other sections`, - ); - } const text = isError ? result.error : JSON.stringify(result, null, 2); return { content: [{ type: "text", text }], @@ -230,6 +210,9 @@ Key principles: } export async function main() { + // Initialize HTTP server logger + const log = await logger.forComponent("http-server"); + // Create Hono app const app = new Hono(); @@ -269,6 +252,13 @@ export async function main() { // MCP endpoint - handles GET and POST (HEAD is handled by middleware above) // Must be defined BEFORE inspector (which mounts at /) for proper route matching app.on(["GET", "POST"], "/mcp", async (c) => { + // Get client IP from headers or connection + const clientIp = + c.req.header("x-forwarded-for") || c.req.header("x-real-ip") || "unknown"; + + // Get trace ID from request header or create new + const traceId = c.req.header("x-request-id") || undefined; + // Get parsed body from Hono (automatic JSON parsing) let parsedBody: unknown; if (c.req.method === "POST") { @@ -280,20 +270,48 @@ export async function main() { } } - // Create fresh server and transport for each request (stateless mode) - const server = await createMcpServer(); - const transport = new WebStandardStreamableHTTPServerTransport({ - sessionIdGenerator: undefined, // Stateless mode - enableJsonResponse: true, // Use JSON responses instead of SSE streaming - }); - await server.connect(transport); + // Handle request within trace context (passing trace ID from header if available) + return await withSpan( + LogOperation.HANDLING_MCP_HTTP_REQUEST, + { method: c.req.method, client_ip: clientIp }, + async () => { + const op = log.start(LogOperation.HANDLING_MCP_HTTP_REQUEST, { + method: c.req.method, + client_ip: clientIp, + }); - // Use Web Standard handleRequest method - // Hono's c.req.raw is a Web Standard Request - const response = await transport.handleRequest(c.req.raw, { parsedBody }); + try { + // Create fresh server and transport for each request (stateless mode) + const server = await createMcpServer(); + const transport = new WebStandardStreamableHTTPServerTransport({ + sessionIdGenerator: undefined, // Stateless mode + enableJsonResponse: true, // Use JSON responses instead of SSE streaming + }); + await server.connect(transport); - // Return the Web Standard Response directly - return response; + // Use Web Standard handleRequest method + // Hono's c.req.raw is a Web Standard Request + const response = await transport.handleRequest(c.req.raw, { + parsedBody, + }); + + op.end({ status: "success" }); + + // Return the Web Standard Response directly + return response; + } catch (err) { + const error = err instanceof Error ? err : new Error(String(err)); + log.error( + LogOperation.HANDLING_MCP_HTTP_REQUEST, + { status: "error" }, + error, + ); + op.end({ status: "error", error: error.message }); + throw err; + } + }, + traceId, + ); }); // MCP Inspector at root path - auto-connects to /mcp @@ -308,16 +326,32 @@ export async function main() { }); // Start the server - console.log(`Ask262 MCP HTTP Server running on http://0.0.0.0:${PORT}`); - console.log(`MCP endpoint: POST http://0.0.0.0:${PORT}/mcp`); - console.log(`Health check: GET http://0.0.0.0:${PORT}/health`); - console.log(`Mode: Stateless JSON (non-streaming)`); + log.info(LogOperation.SERVER_STARTED, { + port: PORT, + transport: "http", + mode: "stateless-json", + endpoints: ["/mcp", "/health"], + }); + + // Minimal console output for startup visibility + console.error(`Ask262 MCP HTTP Server running on http://0.0.0.0:${PORT}`); + console.error(`MCP endpoint: POST http://0.0.0.0:${PORT}/mcp`); + console.error(`Mode: Stateless JSON (non-streaming)`); serve({ fetch: app.fetch, port: PORT, hostname: "0.0.0.0", // Bind to all interfaces for container/Docker compatibility }); + + // Handle graceful shutdown + const shutdown = (signal: string) => { + log.info(LogOperation.SERVER_STOPPED, { signal }); + process.exit(0); + }; + + process.on("SIGTERM", () => shutdown("SIGTERM")); + process.on("SIGINT", () => shutdown("SIGINT")); } main().catch((error) => { diff --git a/src/mcp-server-stdio.ts b/src/mcp-server-stdio.ts index 97bcdc0..4ca741e 100644 --- a/src/mcp-server-stdio.ts +++ b/src/mcp-server-stdio.ts @@ -36,6 +36,8 @@ import { } from "./agent-tools/index.js"; import { STORAGE_DIR as STORAGE_DIR_REL } from "./constants.js"; import { createEmbeddings } from "./lib/embeddings-factory.js"; +import { LogOperation, logger } from "./lib/logger.js"; +import { createProcessScopedTrace, withSpanContext } from "./lib/tracing.js"; // Resolve storage path relative to this script's directory const __filename = fileURLToPath(import.meta.url); @@ -88,6 +90,17 @@ export interface SearchSpecMCPOutput extends McpToolOutputBase { const embeddings = createEmbeddings(); export async function main() { + // Initialize stdio server logger + const log = await logger.forComponent("stdio-server"); + + // Create process-scoped trace ID for this session + const sessionTraceId = createProcessScopedTrace(); + + log.info(LogOperation.SERVER_STARTED, { + transport: "stdio", + trace_id: sessionTraceId, + }); + // Connect to LanceDB const db = await lancedbSdk.connect(STORAGE_DIR); const table = await db.openTable("spec_vectors"); @@ -124,12 +137,19 @@ export async function main() { }, }, async ({ query }: SearchSpecMCPInput): Promise => { - const result = await searchSpecTool({ query }); - return { - content: [{ type: "text", text: JSON.stringify(result, null, 2) }], - structuredContent: result, - isError: false, - }; + return await withSpanContext( + sessionTraceId, + "vector_search", + { tool: searchSpecToolName, query }, + async () => { + const result = await searchSpecTool({ query }); + return { + content: [{ type: "text", text: JSON.stringify(result, null, 2) }], + structuredContent: result, + isError: false, + }; + }, + ); }, ); @@ -150,12 +170,19 @@ export async function main() { sectionIds, recursive, }: GetSectionContentMCPInput): Promise => { - const result = await getSectionContentTool({ sectionIds, recursive }); - return { - content: [{ type: "text", text: JSON.stringify(result, null, 2) }], - structuredContent: result, - isError: false, - }; + return await withSpanContext( + sessionTraceId, + "section_fetch", + { tool: sectionContentToolName, section_count: sectionIds.length }, + async () => { + const result = await getSectionContentTool({ sectionIds, recursive }); + return { + content: [{ type: "text", text: JSON.stringify(result, null, 2) }], + structuredContent: result, + isError: false, + }; + }, + ); }, ); @@ -173,14 +200,21 @@ export async function main() { }, }, async ({ code }: EvaluateToolMCPInput): Promise => { - const result = await evaluateTool({ code }); - const isError = result.error !== undefined; - const text = isError ? result.error : JSON.stringify(result, null, 2); - return { - content: [{ type: "text", text }], - structuredContent: result, - isError, - }; + return await withSpanContext( + sessionTraceId, + "code_execution", + { tool: evaluateToolName, code_length: code.length }, + async () => { + const result = await evaluateTool({ code }); + const isError = result.error !== undefined; + const text = isError ? result.error : JSON.stringify(result, null, 2); + return { + content: [{ type: "text", text }], + structuredContent: result, + isError, + }; + }, + ); }, ); @@ -248,6 +282,18 @@ Key principles: await server.connect(transport); console.error("Ask262 MCP Server running on stdio"); + + // Handle graceful shutdown + const shutdown = (signal: string) => { + log.info(LogOperation.SERVER_STOPPED, { + signal, + trace_id: sessionTraceId, + }); + process.exit(0); + }; + + process.on("SIGTERM", () => shutdown("SIGTERM")); + process.on("SIGINT", () => shutdown("SIGINT")); } main().catch((error) => {