diff --git a/eslint.config.mjs b/eslint.config.mjs index 9100256833..f377cba6c3 100644 --- a/eslint.config.mjs +++ b/eslint.config.mjs @@ -4,6 +4,38 @@ import unusedImports from 'eslint-plugin-unused-imports'; import reactHooks from 'eslint-plugin-react-hooks'; import prettierConfig from 'eslint-config-prettier'; +// Selectors that protect MCP-reachable code from corrupting the JSON-RPC +// stdio frame stream. The MCP-reachable block below uses these directly; +// the lbug-adapter file-specific block must spread them in too because +// ESLint flat config REPLACES (not merges) `no-restricted-syntax` when +// multiple matching configs target the same file. Extracting to a const +// makes the dependency mechanical instead of documentation-enforced. +const mcpStdoutWriteSelectors = [ + { + selector: + "MemberExpression[object.type='MemberExpression'][object.object.name='process'][object.property.name='stdout'][property.name='write']", + message: + 'Direct process.stdout.write is forbidden in MCP-reachable code. Route diagnostics through console.error or process.stderr.write — the MCP stdio transport owns stdout for JSON-RPC frames.', + }, + { + selector: + "CallExpression[callee.type='MemberExpression'][callee.object.type='MemberExpression'][callee.object.object.name='process'][callee.object.property.name='stdout'][callee.property.name='write']", + message: + 'Direct process.stdout.write is forbidden in MCP-reachable code. Route diagnostics through console.error or process.stderr.write — the MCP stdio transport owns stdout for JSON-RPC frames.', + }, + { + // Catches the canonical destructuring shape: + // const { write } = process.stdout; + // (and any other ObjectPattern destructure rooted at process.stdout) + // which would otherwise capture a reference to the original write + // and bypass the sentinel. + selector: + "VariableDeclarator[init.type='MemberExpression'][init.object.name='process'][init.property.name='stdout'] > ObjectPattern", + message: + 'Destructuring process.stdout is forbidden in MCP-reachable code — bypasses the sentinel. Use process.stderr.write for diagnostics.', + }, +]; + export default [ // Global ignores { @@ -59,11 +91,26 @@ export default [ }, }, - // CLI package — allow console.log (it's a CLI tool) + // CLI/server packages — `console.log` IS the contract (CLI tool data output + // on stdout, e.g. `gitnexus query | jq`; server pretty-printed banners). + // Diagnostic logging (`warn`/`error`/`debug`/`info`) goes through pino like + // the rest of the codebase. { files: ['gitnexus/src/cli/**/*.ts', 'gitnexus/src/server/**/*.ts'], rules: { - 'no-console': 'off', + 'no-console': ['error', { allow: ['log'] }], + }, + }, + + // Forcing function for the pino migration. Severity is `error` — the + // codebase-wide migration is complete; new `console.*` in core source + // must fail lint. CLI/server are exempt above (legitimate stdout output). + // Tests, bin scripts, and the logger module itself remain exempt. + { + files: ['gitnexus/src/**/*.ts'], + ignores: ['gitnexus/src/cli/**', 'gitnexus/src/server/**', 'gitnexus/src/core/logger.ts'], + rules: { + 'no-console': 'error', }, }, @@ -84,32 +131,7 @@ export default [ ], rules: { 'no-console': ['error', { allow: ['error'] }], - 'no-restricted-syntax': [ - 'error', - { - selector: - "MemberExpression[object.type='MemberExpression'][object.object.name='process'][object.property.name='stdout'][property.name='write']", - message: - 'Direct process.stdout.write is forbidden in MCP-reachable code. Route diagnostics through console.error or process.stderr.write — the MCP stdio transport owns stdout for JSON-RPC frames.', - }, - { - selector: - "CallExpression[callee.type='MemberExpression'][callee.object.type='MemberExpression'][callee.object.object.name='process'][callee.object.property.name='stdout'][callee.property.name='write']", - message: - 'Direct process.stdout.write is forbidden in MCP-reachable code. Route diagnostics through console.error or process.stderr.write — the MCP stdio transport owns stdout for JSON-RPC frames.', - }, - { - // Catches the canonical destructuring shape: - // const { write } = process.stdout; - // (and any other ObjectPattern destructure rooted at process.stdout) - // which would otherwise capture a reference to the original write - // and bypass the sentinel. - selector: - "VariableDeclarator[init.type='MemberExpression'][init.object.name='process'][init.property.name='stdout'] > ObjectPattern", - message: - 'Destructuring process.stdout is forbidden in MCP-reachable code — bypasses the sentinel. Use process.stderr.write for diagnostics.', - }, - ], + 'no-restricted-syntax': ['error', ...mcpStdoutWriteSelectors], }, }, @@ -129,11 +151,18 @@ export default [ // All close operations must go through safeClose() so the WAL is always // flushed before the connection is released. The sole authorised call site // inside safeClose itself uses an eslint-disable-next-line override. + // + // ESLint flat config REPLACES (not merges) `no-restricted-syntax` when + // multiple matching configs target the same file. lbug-adapter.ts is also + // covered by the MCP-reachable block above, so we spread the shared + // mcpStdoutWriteSelectors here alongside the safeClose selectors. Without + // this, lbug-adapter would silently lose its MCP stdout-write protection. { files: ['gitnexus/src/core/lbug/lbug-adapter.ts'], rules: { 'no-restricted-syntax': [ 'error', + ...mcpStdoutWriteSelectors, { selector: "CallExpression[callee.object.name='conn'][callee.property.name='close']", message: 'Use safeClose() instead of calling conn.close() directly (#1376).', diff --git a/gitnexus/package-lock.json b/gitnexus/package-lock.json index ccc61bc5b2..f4fd4f2d95 100644 --- a/gitnexus/package-lock.json +++ b/gitnexus/package-lock.json @@ -30,6 +30,8 @@ "mnemonist": "^0.40.3", "onnxruntime-node": "^1.24.0", "pandemonium": "^2.4.0", + "pino": "^10.3.1", + "pino-pretty": "^13.1.3", "tree-sitter": "^0.21.1", "tree-sitter-c": "0.21.4", "tree-sitter-c-sharp": "0.23.1", @@ -1579,6 +1581,12 @@ "url": "https://github.com/sponsors/Boshen" } }, + "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/@protobufjs/aspromise": { "version": "1.1.2", "resolved": "https://registry.npmjs.org/@protobufjs/aspromise/-/aspromise-1.1.2.tgz", @@ -2380,6 +2388,15 @@ "js-tokens": "^10.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/balanced-match": { "version": "4.0.4", "resolved": "https://registry.npmjs.org/balanced-match/-/balanced-match-4.0.4.tgz", @@ -2579,6 +2596,12 @@ "integrity": "sha512-dOy+3AuW3a2wNbZHIuMZpTcgjGuLU/uBL/ubcZF9OXbDo8ff4O8yVp5Bf0efS8uEoYo5q4Fx7dY9OgQGXgAsQA==", "license": "MIT" }, + "node_modules/colorette": { + "version": "2.0.20", + "resolved": "https://registry.npmjs.org/colorette/-/colorette-2.0.20.tgz", + "integrity": "sha512-IfEDxwoWIjkeXL1eXcDiow4UbKjhLdq6/EuSVR9GMN7KVH3r9gQ83e73hsz1Nd1T3ijd5xv1wcWRYO+D6kCI2w==", + "license": "MIT" + }, "node_modules/commander": { "version": "14.0.3", "resolved": "https://registry.npmjs.org/commander/-/commander-14.0.3.tgz", @@ -2683,6 +2706,15 @@ "node": ">= 8" } }, + "node_modules/dateformat": { + "version": "4.6.3", + "resolved": "https://registry.npmjs.org/dateformat/-/dateformat-4.6.3.tgz", + "integrity": "sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA==", + "license": "MIT", + "engines": { + "node": "*" + } + }, "node_modules/debug": { "version": "4.4.3", "resolved": "https://registry.npmjs.org/debug/-/debug-4.4.3.tgz", @@ -2806,6 +2838,15 @@ "node": ">= 0.8" } }, + "node_modules/end-of-stream": { + "version": "1.4.5", + "resolved": "https://registry.npmjs.org/end-of-stream/-/end-of-stream-1.4.5.tgz", + "integrity": "sha512-ooEGc6HP26xXq/N+GCGOT0JKCLDGrq2bQUZrQ7gyrJiZANJ/8YDTxTpQBXGMn+WbIQXNVpyWymm7KYVICQnyOg==", + "license": "MIT", + "dependencies": { + "once": "^1.4.0" + } + }, "node_modules/es-define-property": { "version": "1.0.1", "resolved": "https://registry.npmjs.org/es-define-property/-/es-define-property-1.0.1.tgz", @@ -3050,12 +3091,24 @@ "integrity": "sha512-Tpp60P6IUJDTuOq/5Z8cdskzJujfwqfOTkrwIwj7IRISpnkJnT6SyJ4PCPnGMoFjC9ddhal5KVIYtAt97ix05A==", "license": "MIT" }, + "node_modules/fast-copy": { + "version": "4.0.3", + "resolved": "https://registry.npmjs.org/fast-copy/-/fast-copy-4.0.3.tgz", + "integrity": "sha512-58apWr0GUiDFM8+3afrO6eYwJBn9ZAhDOzG3L+/9llab/haCARS2UIfffmOurYLwbgDRs8n0rfr6qAAPEAuAQw==", + "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", "integrity": "sha512-f3qQ9oQy9j2AhBe/H9VC91wLmKBCCU/gDOnKNAYG5hswO7BLKj09Hc5HYNz9cGI++xlpDCIgDaitVs03ATR84Q==", "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", @@ -3416,6 +3469,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/hono": { "version": "4.12.16", "resolved": "https://registry.npmjs.org/hono/-/hono-4.12.16.tgz", @@ -3575,6 +3634,15 @@ "url": "https://github.com/sponsors/panva" } }, + "node_modules/joycon": { + "version": "3.1.1", + "resolved": "https://registry.npmjs.org/joycon/-/joycon-3.1.1.tgz", + "integrity": "sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw==", + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/js-tokens": { "version": "10.0.0", "resolved": "https://registry.npmjs.org/js-tokens/-/js-tokens-10.0.0.tgz", @@ -4183,6 +4251,15 @@ ], "license": "MIT" }, + "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", @@ -4332,6 +4409,79 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "node_modules/pino": { + "version": "10.3.1", + "resolved": "https://registry.npmjs.org/pino/-/pino-10.3.1.tgz", + "integrity": "sha512-r34yH/GlQpKZbU1BvFFqOjhISRo1MNx1tWYsYvmj6KIRHSPMT2+yHOEb1SG6NMvRoHRF0a07kCOox/9yakl1vg==", + "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/pkce-challenge": { "version": "5.0.1", "resolved": "https://registry.npmjs.org/pkce-challenge/-/pkce-challenge-5.0.1.tgz", @@ -4376,6 +4526,22 @@ "node": "^10 || ^12 || >=14" } }, + "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/protobufjs": { "version": "7.5.5", "resolved": "https://registry.npmjs.org/protobufjs/-/protobufjs-7.5.5.tgz", @@ -4413,6 +4579,16 @@ "node": ">= 0.10" } }, + "node_modules/pump": { + "version": "3.0.4", + "resolved": "https://registry.npmjs.org/pump/-/pump-3.0.4.tgz", + "integrity": "sha512-VS7sjc6KR7e1ukRFhQSY5LM2uBWAUPiOPa/A3mkKmiMwSmRFUITt0xuj+/lesgnCv+dPIEYlkzrcyXgquIHMcA==", + "license": "MIT", + "dependencies": { + "end-of-stream": "^1.1.0", + "once": "^1.3.1" + } + }, "node_modules/qs": { "version": "6.14.2", "resolved": "https://registry.npmjs.org/qs/-/qs-6.14.2.tgz", @@ -4428,6 +4604,12 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/quick-format-unescaped": { + "version": "4.0.4", + "resolved": "https://registry.npmjs.org/quick-format-unescaped/-/quick-format-unescaped-4.0.4.tgz", + "integrity": "sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==", + "license": "MIT" + }, "node_modules/range-parser": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/range-parser/-/range-parser-1.2.1.tgz", @@ -4483,6 +4665,15 @@ "rc": "cli.js" } }, + "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/require-directory": { "version": "2.1.1", "resolved": "https://registry.npmjs.org/require-directory/-/require-directory-2.1.1.tgz", @@ -4591,12 +4782,37 @@ ], "license": "MIT" }, + "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", "integrity": "sha512-YZo3K82SD7Riyi0E1EQPojLz7kpepnSQI9IyPbHHg1XXXevb5dJI7tpyN2ADxGcQbHG7vcyRHk0cbwqcQriUtg==", "license": "MIT" }, + "node_modules/secure-json-parse": { + "version": "4.1.0", + "resolved": "https://registry.npmjs.org/secure-json-parse/-/secure-json-parse-4.1.0.tgz", + "integrity": "sha512-l4KnYfEyqYJxDwlNVyRfO2E4NTHfMKAWdUuA8J0yve2Dz/E/PdBepY03RvyJpssIpRFwJoCD55wA+mEDs6ByWA==", + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "BSD-3-Clause" + }, "node_modules/semver": { "version": "7.7.4", "resolved": "https://registry.npmjs.org/semver/-/semver-7.7.4.tgz", @@ -4828,6 +5044,15 @@ "dev": true, "license": "ISC" }, + "node_modules/sonic-boom": { + "version": "4.2.1", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-4.2.1.tgz", + "integrity": "sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==", + "license": "MIT", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, "node_modules/source-map-js": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/source-map-js/-/source-map-js-1.2.1.tgz", @@ -4838,6 +5063,15 @@ "node": ">=0.10.0" } }, + "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/stackback": { "version": "0.0.2", "resolved": "https://registry.npmjs.org/stackback/-/stackback-0.0.2.tgz", @@ -4925,6 +5159,18 @@ "node": ">=18" } }, + "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/tinybench": { "version": "2.9.0", "resolved": "https://registry.npmjs.org/tinybench/-/tinybench-2.9.0.tgz", diff --git a/gitnexus/package.json b/gitnexus/package.json index 6aa5f59b7d..84f7027627 100644 --- a/gitnexus/package.json +++ b/gitnexus/package.json @@ -73,6 +73,8 @@ "mnemonist": "^0.40.3", "onnxruntime-node": "^1.24.0", "pandemonium": "^2.4.0", + "pino": "^10.3.1", + "pino-pretty": "^13.1.3", "tree-sitter": "^0.21.1", "tree-sitter-c": "0.21.4", "tree-sitter-c-sharp": "0.23.1", diff --git a/gitnexus/src/cli/ai-context.ts b/gitnexus/src/cli/ai-context.ts index 1b83963017..41ba6c73e9 100644 --- a/gitnexus/src/cli/ai-context.ts +++ b/gitnexus/src/cli/ai-context.ts @@ -10,6 +10,7 @@ import fs from 'fs/promises'; import path from 'path'; import { fileURLToPath } from 'url'; import { type GeneratedSkillInfo } from './skill-gen.js'; +import { logger } from '../core/logger.js'; // ESM equivalent of __dirname const __filename = fileURLToPath(import.meta.url); @@ -293,7 +294,7 @@ Use GitNexus tools to accomplish this task. installedSkills.push(skill.name); } catch (err) { // Skip on error, don't fail the whole process - console.warn(`Warning: Could not install skill ${skill.name}:`, err); + logger.warn({ err }, `Warning: Could not install skill ${skill.name}:`); } } diff --git a/gitnexus/src/cli/analyze.ts b/gitnexus/src/cli/analyze.ts index 90b8c9a433..175db47e6f 100644 --- a/gitnexus/src/cli/analyze.ts +++ b/gitnexus/src/cli/analyze.ts @@ -26,6 +26,7 @@ import { getMaxFileSizeBannerMessage } from '../core/ingestion/utils/max-file-si import { warnMissingOptionalGrammars } from './optional-grammars.js'; import { glob } from 'glob'; import fs from 'fs/promises'; +import { cliError } from './cli-message.js'; // Capture stderr.write at module load BEFORE anything (LadybugDB native // init, progress bar, console redirection) can monkey-patch it. The @@ -167,7 +168,7 @@ export const analyzeCommand = async (inputPath?: string, options?: AnalyzeOption if (options?.workerTimeout) { const workerTimeoutSeconds = Number(options.workerTimeout); if (!Number.isFinite(workerTimeoutSeconds) || workerTimeoutSeconds < 1) { - console.error(' --worker-timeout must be at least 1 second.\n'); + cliError(' --worker-timeout must be at least 1 second.\n'); process.exitCode = 1; return; } @@ -184,7 +185,7 @@ export const analyzeCommand = async (inputPath?: string, options?: AnalyzeOption if (typeof options?.embeddings === 'string') { const parsed = Number(options.embeddings); if (!Number.isInteger(parsed) || parsed < 0) { - console.error( + cliError( ` --embeddings expects a non-negative integer (got "${options.embeddings}"). ` + `Pass 0 to disable the safety cap, or omit the value to keep the default.\n`, ); @@ -203,7 +204,7 @@ export const analyzeCommand = async (inputPath?: string, options?: AnalyzeOption if (value === undefined) return true; const parsed = Number(value); if (!Number.isInteger(parsed) || parsed <= 0) { - console.error(` ${optionName} must be a positive integer.\n`); + cliError(` ${optionName} must be a positive integer.\n`); process.exitCode = 1; return false; } @@ -234,7 +235,7 @@ export const analyzeCommand = async (inputPath?: string, options?: AnalyzeOption if (options?.embeddingDevice) { const allowed = new Set(['auto', 'cpu', 'dml', 'cuda', 'wasm']); if (!allowed.has(options.embeddingDevice)) { - console.error(' --embedding-device must be one of: auto, cpu, dml, cuda, wasm.\n'); + cliError(' --embedding-device must be one of: auto, cpu, dml, cuda, wasm.\n'); process.exitCode = 1; return; } @@ -330,7 +331,9 @@ export const analyzeCommand = async (inputPath?: string, options?: AnalyzeOption bar.start(100, 0, { phase: 'Initializing...' }); - // Graceful SIGINT handling + // Graceful SIGINT handling. Pino's default destination is `sync: false` + // (buffered) — flush before exit so in-flight records reach stderr. + // See `gitnexus/src/core/logger.ts:flushLoggerSync`. let aborted = false; const sigintHandler = () => { if (aborted) process.exit(1); @@ -339,13 +342,23 @@ export const analyzeCommand = async (inputPath?: string, options?: AnalyzeOption console.log('\n Interrupted — cleaning up...'); closeLbug() .catch(() => {}) - .finally(() => process.exit(130)); + .finally(async () => { + const { flushLoggerSync } = await import('../core/logger.js'); + flushLoggerSync(); + process.exit(130); + }); }; process.on('SIGINT', sigintHandler); - // Route console output through bar.log() to prevent progress bar corruption + // Route console output through bar.log() to prevent progress bar corruption. + // This is a deliberate UI pattern (not a logging concern): analyze runs a + // long-lived progress bar on stdout; any concurrent console.* write would + // overwrite the bar mid-render. We capture originals, swap to barLog for + // the lifetime of the run, and restore on completion/error/SIGINT. const origLog = console.log.bind(console); + // eslint-disable-next-line no-console -- intentional console-routing for progress bar UX const origWarn = console.warn.bind(console); + // eslint-disable-next-line no-console -- intentional console-routing for progress bar UX const origError = console.error.bind(console); let barCurrentValue = 0; const barLog = (...args: any[]) => { @@ -354,7 +367,9 @@ export const analyzeCommand = async (inputPath?: string, options?: AnalyzeOption bar.update(barCurrentValue); }; console.log = barLog; + // eslint-disable-next-line no-console -- intentional console-routing for progress bar UX console.warn = barLog; + // eslint-disable-next-line no-console -- intentional console-routing for progress bar UX console.error = barLog; // Track elapsed time per phase @@ -420,7 +435,9 @@ export const analyzeCommand = async (inputPath?: string, options?: AnalyzeOption clearInterval(elapsedTimer); process.removeListener('SIGINT', sigintHandler); console.log = origLog; + // eslint-disable-next-line no-console -- restoring after intentional progress-bar routing console.warn = origWarn; + // eslint-disable-next-line no-console -- restoring after intentional progress-bar routing console.error = origError; bar.stop(); console.log(' Already up to date\n'); @@ -493,7 +510,9 @@ export const analyzeCommand = async (inputPath?: string, options?: AnalyzeOption process.removeListener('SIGINT', sigintHandler); console.log = origLog; + // eslint-disable-next-line no-console -- restoring after intentional progress-bar routing console.warn = origWarn; + // eslint-disable-next-line no-console -- restoring after intentional progress-bar routing console.error = origError; bar.update(100, { phase: 'Done' }); @@ -518,7 +537,9 @@ export const analyzeCommand = async (inputPath?: string, options?: AnalyzeOption clearInterval(elapsedTimer); process.removeListener('SIGINT', sigintHandler); console.log = origLog; + // eslint-disable-next-line no-console -- restoring after intentional progress-bar routing console.warn = origWarn; + // eslint-disable-next-line no-console -- restoring after intentional progress-bar routing console.error = origError; bar.stop(); @@ -527,14 +548,14 @@ export const analyzeCommand = async (inputPath?: string, options?: AnalyzeOption // Registry name-collision from --name (#829) — surface as an // actionable error rather than a generic stack-trace. if (err instanceof RegistryNameCollisionError) { - console.error(`\n Registry name collision:\n`); - console.error(` "${err.registryName}" is already used by "${err.existingPath}".\n`); - console.error(` Options:`); - console.error(` • Pick a different alias: gitnexus analyze --name `); - console.error( - ` • Allow the duplicate: gitnexus analyze --allow-duplicate-name (leaves "-r ${err.registryName}" ambiguous)`, + cliError( + `\n Registry name collision:\n` + + ` "${err.registryName}" is already used by "${err.existingPath}".\n\n` + + ` Options:\n` + + ` • Pick a different alias: gitnexus analyze --name \n` + + ` • Allow the duplicate: gitnexus analyze --allow-duplicate-name (leaves "-r ${err.registryName}" ambiguous)\n`, + { registryName: err.registryName, existingPath: err.existingPath }, ); - console.error(''); process.exitCode = 1; return; } @@ -574,34 +595,40 @@ export const analyzeCommand = async (inputPath?: string, options?: AnalyzeOption msg.includes('heap out of memory') || msg.includes('JavaScript heap') ) { - console.error(' This error typically occurs on very large repositories.'); - console.error(' Suggestions:'); - console.error(' 1. Add large vendored/generated directories to .gitnexusignore'); - console.error(' 2. Increase Node.js heap: NODE_OPTIONS="--max-old-space-size=16384"'); - console.error(' 3. Increase stack size: NODE_OPTIONS="--stack-size=4096"'); - console.error(''); + cliError( + ` This error typically occurs on very large repositories.\n` + + ` Suggestions:\n` + + ` 1. Add large vendored/generated directories to .gitnexusignore\n` + + ` 2. Increase Node.js heap: NODE_OPTIONS="--max-old-space-size=16384"\n` + + ` 3. Increase stack size: NODE_OPTIONS="--stack-size=4096"\n`, + { recoveryHint: 'large-repo' }, + ); } else if (msg.includes('ERESOLVE') || msg.includes('Could not resolve dependency')) { // Note: the original arborist "Cannot destructure property 'package' of // 'node.target'" crash happens inside npm *before* gitnexus code runs, // so it can't be caught here. This branch handles dependency-resolution // errors that surface at runtime (e.g. dynamic require failures). - console.error(' This looks like an npm dependency resolution issue.'); - console.error(' Suggestions:'); - console.error(' 1. Clear the npm cache: npm cache clean --force'); - console.error(' 2. Update npm: npm install -g npm@latest'); - console.error(' 3. Reinstall gitnexus: npm install -g gitnexus@latest'); - console.error(' 4. Or try npx directly: npx gitnexus@latest analyze'); - console.error(''); + cliError( + ` This looks like an npm dependency resolution issue.\n` + + ` Suggestions:\n` + + ` 1. Clear the npm cache: npm cache clean --force\n` + + ` 2. Update npm: npm install -g npm@latest\n` + + ` 3. Reinstall gitnexus: npm install -g gitnexus@latest\n` + + ` 4. Or try npx directly: npx gitnexus@latest analyze\n`, + { recoveryHint: 'npm-resolution' }, + ); } else if ( msg.includes('MODULE_NOT_FOUND') || msg.includes('Cannot find module') || msg.includes('ERR_MODULE_NOT_FOUND') ) { - console.error(' A required module could not be loaded. The installation may be corrupt.'); - console.error(' Suggestions:'); - console.error(' 1. Reinstall: npm install -g gitnexus@latest'); - console.error(' 2. Clear cache: npm cache clean --force && npx gitnexus@latest analyze'); - console.error(''); + cliError( + ` A required module could not be loaded. The installation may be corrupt.\n` + + ` Suggestions:\n` + + ` 1. Reinstall: npm install -g gitnexus@latest\n` + + ` 2. Clear cache: npm cache clean --force && npx gitnexus@latest analyze\n`, + { recoveryHint: 'module-not-found' }, + ); } process.exitCode = 1; diff --git a/gitnexus/src/cli/clean.ts b/gitnexus/src/cli/clean.ts index 4681508fb3..2bbc32aef1 100644 --- a/gitnexus/src/cli/clean.ts +++ b/gitnexus/src/cli/clean.ts @@ -6,6 +6,7 @@ */ import fs from 'fs/promises'; +import { logger } from '../core/logger.js'; import { findRepo, unregisterRepo, @@ -45,7 +46,7 @@ export const cleanCommand = async (options?: { force?: boolean; all?: boolean }) assertSafeStoragePath(entry); } catch (err) { if (err instanceof UnsafeStoragePathError) { - console.error(`Refusing to clean ${entry.name}: ${err.message}`); + logger.error(`Refusing to clean ${entry.name}: ${err.message}`); continue; } throw err; @@ -56,7 +57,7 @@ export const cleanCommand = async (options?: { force?: boolean; all?: boolean }) await unregisterRepo(entry.path); console.log(`Deleted: ${entry.name} (${entry.storagePath})`); } catch (err) { - console.error(`Failed to delete ${entry.name}:`, err); + logger.error({ err }, `Failed to delete ${entry.name}:`); } } return; @@ -85,6 +86,6 @@ export const cleanCommand = async (options?: { force?: boolean; all?: boolean }) await unregisterRepo(repo.repoPath); console.log(`Deleted: ${repo.storagePath}`); } catch (err) { - console.error('Failed to delete:', err); + logger.error({ err }, 'Failed to delete:'); } }; diff --git a/gitnexus/src/cli/cli-message.ts b/gitnexus/src/cli/cli-message.ts new file mode 100644 index 0000000000..db5f51fab5 --- /dev/null +++ b/gitnexus/src/cli/cli-message.ts @@ -0,0 +1,65 @@ +/** + * CLI message helpers — for user-facing banners, error guidance, and + * recovery hints emitted by `gitnexus` subcommands. + * + * These functions write **plain text** directly to `process.stderr` AND + * tee a structured pino record through the singleton `logger`. Plain text + * preserves the human-readable contract for users running `gitnexus` + * interactively, redirecting to a file, or piping to `cat`/`grep`. The + * structured tee keeps log aggregators happy. + * + * **Use these for:** + * - User-facing banners ("Server listening on http://...:N") + * - Validation errors ("--worker-timeout must be at least 1 second") + * - Recovery hints ("Suggestions: 1. Clear the npm cache, 2. ...") + * - One-line user notices ("No indexed repositories found.") + * + * **Do NOT use these for:** + * - Internal diagnostics (worker progress, retry counts, telemetry) + * — use `logger.info`/`warn`/`error` directly. Internal logs only + * need structured fields, not double-output to stderr. + * - High-volume hot paths — every `cliMessage` call writes twice (raw + * + structured). Acceptable for user-facing messages, wasteful for + * ingestion pipeline events. + * + * Design note: stderr is the right channel even for non-error messages + * because GitNexus CLI tools (`query`, `cypher`, `impact`) emit JSON + * data on stdout for piping (`gitnexus query | jq`). User banners on + * stdout would corrupt that pipeline. + */ +import { logger } from '../core/logger.js'; + +function writeStderr(msg: string): void { + // Direct write — bypassing `console.*` so it cannot be intercepted by + // progress-bar redirection (see `cli/analyze.ts:barLog`) or other + // routing. The structured tee below still goes through the logger so + // log aggregation works either way. + process.stderr.write(msg.endsWith('\n') ? msg : msg + '\n'); +} + +/** + * User-facing informational message. Use for banners, listening URLs, + * and any message the user expects to read in plain text. + */ +export function cliInfo(msg: string, fields?: Record): void { + writeStderr(msg); + logger.info(fields ?? {}, msg); +} + +/** + * User-facing warning. Operator-actionable but non-fatal — `cliWarn` + * indicates the command can still proceed in some form. + */ +export function cliWarn(msg: string, fields?: Record): void { + writeStderr(msg); + logger.warn(fields ?? {}, msg); +} + +/** + * User-facing error. Indicates the command cannot proceed; usually + * paired with a non-zero exit code at the call site. + */ +export function cliError(msg: string, fields?: Record): void { + writeStderr(msg); + logger.error(fields ?? {}, msg); +} diff --git a/gitnexus/src/cli/eval-server.ts b/gitnexus/src/cli/eval-server.ts index cf9013d63e..0819c33e81 100644 --- a/gitnexus/src/cli/eval-server.ts +++ b/gitnexus/src/cli/eval-server.ts @@ -27,6 +27,8 @@ import http from 'http'; import { writeSync } from 'node:fs'; import { LocalBackend } from '../mcp/local/local-backend.js'; +import { logger } from '../core/logger.js'; +import { cliInfo, cliWarn } from './cli-message.js'; export interface EvalServerOptions { port?: string; @@ -332,13 +334,19 @@ export async function evalServerCommand(options?: EvalServerOptions): Promise r.name).join(', ')}`, + logger.info( + { repoCount: repos.length, repos: repos.map((r) => r.name) }, + 'GitNexus eval-server: repos loaded', ); let idleTimer: ReturnType | null = null; @@ -347,7 +355,7 @@ export async function evalServerCommand(options?: EvalServerOptions): Promise { - console.error('GitNexus eval-server: Idle timeout reached, shutting down'); + logger.info({ idleTimeoutSec }, 'GitNexus eval-server: idle timeout reached, shutting down'); await backend.disconnect(); process.exit(0); }, idleTimeoutSec * 1000); @@ -419,16 +427,34 @@ export async function evalServerCommand(options?: EvalServerOptions): Promise { - console.error(`GitNexus eval-server: listening on http://127.0.0.1:${port}`); - console.error(` POST /tool/query — search execution flows`); - console.error(` POST /tool/context — 360-degree symbol view`); - console.error(` POST /tool/impact — blast radius analysis`); - console.error(` POST /tool/cypher — raw Cypher query`); - console.error(` GET /health — health check`); - console.error(` POST /shutdown — graceful shutdown`); + // Plain-text banner for the human watching stderr; structured record + // for log aggregation (split into two so the user sees a real banner + // not `{"level":30,"msg":"...","port":4747,"endpoints":[...]}`). + const bannerLines = [ + `GitNexus eval-server: listening on http://127.0.0.1:${port}`, + ` POST /tool/query — search execution flows`, + ` POST /tool/context — 360-degree symbol view`, + ` POST /tool/impact — blast radius analysis`, + ` POST /tool/cypher — raw Cypher query`, + ` GET /health — health check`, + ` POST /shutdown — graceful shutdown`, + ]; if (idleTimeoutSec > 0) { - console.error(` Auto-shutdown after ${idleTimeoutSec}s idle`); + bannerLines.push(` Auto-shutdown after ${idleTimeoutSec}s idle`); } + cliInfo(bannerLines.join('\n'), { + port, + host: '127.0.0.1', + idleTimeoutSec: idleTimeoutSec > 0 ? idleTimeoutSec : undefined, + endpoints: [ + 'POST /tool/query', + 'POST /tool/context', + 'POST /tool/impact', + 'POST /tool/cypher', + 'GET /health', + 'POST /shutdown', + ], + }); try { // Use fd 1 directly — LadybugDB captures process.stdout (#324) writeSync(1, `GITNEXUS_EVAL_SERVER_READY:${port}\n`); @@ -440,7 +466,7 @@ export async function evalServerCommand(options?: EvalServerOptions): Promise { - console.error('GitNexus eval-server: shutting down...'); + logger.info('GitNexus eval-server: shutting down...'); await backend.disconnect(); server.close(); process.exit(0); diff --git a/gitnexus/src/cli/group.ts b/gitnexus/src/cli/group.ts index eb0dffc3d3..0053099b70 100644 --- a/gitnexus/src/cli/group.ts +++ b/gitnexus/src/cli/group.ts @@ -1,6 +1,7 @@ // gitnexus/src/cli/group.ts import { createRequire } from 'node:module'; import type { Command } from 'commander'; +import { logger } from '../core/logger.js'; const _require = createRequire(import.meta.url); const yaml = _require('js-yaml') as typeof import('js-yaml'); @@ -51,7 +52,7 @@ export function registerGroupCommands(program: Command): void { const groupDir = getGroupDir(getDefaultGitnexusDir(), groupName); const config = await loadGroupConfig(groupDir); if (!(repoPath in config.repos)) { - console.error(`Repo path "${repoPath}" not found in group "${groupName}"`); + logger.error(`Repo path "${repoPath}" not found in group "${groupName}"`); process.exitCode = 1; return; } @@ -239,7 +240,7 @@ export function registerGroupCommands(program: Command): void { const raw = await backend.getGroupService().groupImpact(payload); if (raw && typeof raw === 'object' && 'error' in raw) { - console.error(String((raw as { error: string }).error)); + logger.error(String((raw as { error: string }).error)); process.exitCode = 1; return; } @@ -333,7 +334,7 @@ export function registerGroupCommands(program: Command): void { }); if (raw && typeof raw === 'object' && 'error' in raw) { - console.error(String((raw as { error: string }).error)); + logger.error(String((raw as { error: string }).error)); process.exitCode = 1; return; } diff --git a/gitnexus/src/cli/mcp.ts b/gitnexus/src/cli/mcp.ts index e69ce0eb05..056b12591f 100644 --- a/gitnexus/src/cli/mcp.ts +++ b/gitnexus/src/cli/mcp.ts @@ -41,11 +41,17 @@ export const mcpCommand = async () => { // path runs cleanly with full stack traces. Registering duplicates here // would only produce noisy double-logging on the same exception. - // Now safe to dynamically import the heavy backend modules. Anything - // they emit to stdout during evaluation will route through the sentinel. - const [{ startMCPServer }, { LocalBackend }] = await Promise.all([ + // Dynamically import heavy backend modules AND the pino logger AFTER + // the sentinel installs. The logger is dynamic-imported (rather than + // static) to preserve the leaf-only static-import closure documented at + // the top of this file — `core/logger.js` itself doesn't write to + // stdout at module init, but transitive deps (pino, pino-pretty, the + // worker-thread transport) could in theory, and the import-closure + // regression test enforces the leaf invariant. + const [{ startMCPServer }, { LocalBackend }, { logger }] = await Promise.all([ import('../mcp/server.js'), import('../mcp/local/local-backend.js'), + import('../core/logger.js'), ]); // Missing-optional-grammar warnings are intentionally NOT emitted here. @@ -62,12 +68,15 @@ export const mcpCommand = async () => { const repos = await backend.listRepos(); if (repos.length === 0) { - console.error( + // Operator-actionable but the server still starts and serves; warn-level, + // not error. Tools will discover newly-analyzed repos via lazy refresh. + logger.warn( 'GitNexus: No indexed repos yet. Run `gitnexus analyze` in a git repo — the server will pick it up automatically.', ); } else { - console.error( - `GitNexus: MCP server starting with ${repos.length} repo(s): ${repos.map((r) => r.name).join(', ')}`, + logger.info( + { repoCount: repos.length, repos: repos.map((r) => r.name) }, + 'GitNexus: MCP server starting', ); } diff --git a/gitnexus/src/cli/optional-grammars.ts b/gitnexus/src/cli/optional-grammars.ts index c6e239b563..14f6c3c5ea 100644 --- a/gitnexus/src/cli/optional-grammars.ts +++ b/gitnexus/src/cli/optional-grammars.ts @@ -13,6 +13,7 @@ */ import { createRequire } from 'module'; +import { cliWarn } from './cli-message.js'; const _require = createRequire(import.meta.url); @@ -65,9 +66,14 @@ export function detectMissingOptionalGrammars(): MissingGrammar[] { /could not find|no native build|prebuilds/i.test(msg); if (!looksMissing) { // Present but broken — surface so the user doesn't get a misleading - // "reinstall" recovery message that wouldn't actually help. - console.error( + // "reinstall" recovery message that wouldn't actually help. cliWarn + // writes plain text to stderr AND tees a structured logger.warn + // record; the merged repo-wide ESLint pino-migration rule forbids + // direct `console.error` in CLI code (only `console.log` is allowed + // there for tool-data stdout output). + cliWarn( `GitNexus: optional grammar "${g.name}" is installed but failed to load (${msg.slice(0, 200)}). ${g.extensions.join('/')} files will not be parsed.`, + { grammar: g.name, extensions: g.extensions, error: msg }, ); } missing.push({ name: g.name, extensions: g.extensions }); @@ -92,12 +98,17 @@ export function warnMissingOptionalGrammars(opts?: { const missing = detectMissingOptionalGrammars(); if (missing.length === 0) return; const ctx = opts?.context ? ` [${opts.context}]` : ''; + // Hoist the optional set into a local so the closure below can narrow + // its type; references to `opts?.relevantExtensions` inside `.some()` + // lose the outer null-check narrowing and require a non-null assertion. + const relevantExtensions = opts?.relevantExtensions; for (const g of missing) { - if (opts?.relevantExtensions && !g.extensions.some((e) => opts.relevantExtensions!.has(e))) { + if (relevantExtensions && !g.extensions.some((e) => relevantExtensions.has(e))) { continue; } - console.error( + cliWarn( `GitNexus${ctx}: optional grammar "${g.name}" is unavailable — ${g.extensions.join('/')} files will not be parsed. Reinstall without GITNEXUS_SKIP_OPTIONAL_GRAMMARS=1 (and ensure python3, make, g++) to enable.`, + { grammar: g.name, extensions: g.extensions, context: opts?.context }, ); } } diff --git a/gitnexus/src/cli/remove.ts b/gitnexus/src/cli/remove.ts index 4d2ce0771d..18d2a340d0 100644 --- a/gitnexus/src/cli/remove.ts +++ b/gitnexus/src/cli/remove.ts @@ -27,6 +27,8 @@ */ import fs from 'fs/promises'; +import { logger } from '../core/logger.js'; +import { cliError } from './cli-message.js'; import { readRegistry, resolveRegistryEntry, @@ -51,14 +53,14 @@ export const removeCommand = async (target: string, options?: { force?: boolean // Idempotent: missing target is a no-op warning, not an error. // The `availableNames` hint comes from the error itself so users // can see what they might have meant. - console.warn(`Nothing to remove: ${err.message}`); + logger.warn(`Nothing to remove: ${err.message}`); return; } if (err instanceof RegistryAmbiguousTargetError) { // Duplicate aliases are allowed via --allow-duplicate-name (#829); // refuse to guess which one the user meant — surface the full list // and exit non-zero so scripts don't silently pick the wrong repo. - console.error(`Error: ${err.message}`); + cliError(`Error: ${err.message}`); process.exit(1); } throw err; @@ -86,7 +88,7 @@ export const removeCommand = async (target: string, options?: { force?: boolean assertSafeStoragePath(entry); } catch (err) { if (err instanceof UnsafeStoragePathError) { - console.error(`Error: ${err.message}`); + cliError(`Error: ${err.message}`); process.exit(1); } throw err; @@ -104,7 +106,8 @@ export const removeCommand = async (target: string, options?: { force?: boolean console.log(` Path: ${entry.path}`); console.log(` Storage: ${entry.storagePath}`); } catch (err) { - console.error(`Failed to remove ${entry.name}:`, err); + const msg = err instanceof Error ? err.message : String(err); + cliError(`Failed to remove ${entry.name}: ${msg}`, { err }); process.exit(1); } }; diff --git a/gitnexus/src/cli/serve.ts b/gitnexus/src/cli/serve.ts index 9f03793060..9356b5bab1 100644 --- a/gitnexus/src/cli/serve.ts +++ b/gitnexus/src/cli/serve.ts @@ -1,14 +1,26 @@ import { createServer } from '../server/api.js'; +import { logger, flushLoggerSync } from '../core/logger.js'; +import { cliError } from './cli-message.js'; -// Catch anything that would cause a silent exit +// Catch anything that would cause a silent exit. Pino v10's default +// destination is `sync: false` (SonicBoom buffered) — call +// `flushLoggerSync()` between the log and `process.exit(1)` so the crash +// record is not lost to the unflushed buffer. Worker-thread transports +// (pino-pretty under TTY) handle their own flush on process exit in v10, +// so no separate `pino.final` integration is needed (the API was removed +// in v10 because the transport architecture made it unnecessary). +// +// We pass the Error itself in `{ err }` so pino's built-in err serializer +// captures `type`, `message`, and `stack` as structured fields. process.on('uncaughtException', (err) => { - console.error('\n[gitnexus serve] Uncaught exception:', err.message); - if (process.env.DEBUG) console.error(err.stack); + logger.error({ err }, '[gitnexus serve] Uncaught exception'); + flushLoggerSync(); process.exit(1); }); -process.on('unhandledRejection', (reason: any) => { - console.error('\n[gitnexus serve] Unhandled rejection:', reason?.message || reason); - if (process.env.DEBUG) console.error(reason?.stack); +process.on('unhandledRejection', (reason) => { + const err = reason instanceof Error ? reason : new Error(String(reason)); + logger.error({ err }, '[gitnexus serve] Unhandled rejection'); + flushLoggerSync(); process.exit(1); }); @@ -22,16 +34,26 @@ export const serveCommand = async (options?: { port?: string; host?: string }) = try { await createServer(port, host); } catch (err: any) { - console.error(`\nFailed to start GitNexus server:\n`); - console.error(` ${err.message || err}\n`); if (err.code === 'EADDRINUSE') { - console.error(` Port ${port} is already in use. Either:`); - console.error(` 1. Stop the other process using port ${port}`); - console.error(` 2. Use a different port: gitnexus serve --port 4748\n`); + cliError( + `\nFailed to start GitNexus server:\n` + + ` ${err.message || err}\n\n` + + ` Port ${port} is already in use. Either:\n` + + ` 1. Stop the other process using port ${port}\n` + + ` 2. Use a different port: gitnexus serve --port 4748\n`, + { code: err.code, port, host }, + ); + } else { + cliError(`\nFailed to start GitNexus server:\n ${err.message || err}\n`, { + code: err.code, + port, + host, + }); } if (err.stack && process.env.DEBUG) { - console.error(err.stack); + logger.debug({ stack: err.stack }, 'serve start error stack'); } + flushLoggerSync(); process.exit(1); } }; diff --git a/gitnexus/src/cli/tool.ts b/gitnexus/src/cli/tool.ts index 443f12f4cc..b40ffdd259 100644 --- a/gitnexus/src/cli/tool.ts +++ b/gitnexus/src/cli/tool.ts @@ -17,6 +17,7 @@ import { writeSync } from 'node:fs'; import { LocalBackend } from '../mcp/local/local-backend.js'; +import { cliError } from './cli-message.js'; let _backend: LocalBackend | null = null; @@ -25,7 +26,7 @@ async function getBackend(): Promise { _backend = new LocalBackend(); const ok = await _backend.init(); if (!ok) { - console.error('GitNexus: No indexed repositories found. Run: gitnexus analyze'); + cliError('GitNexus: No indexed repositories found. Run: gitnexus analyze'); process.exit(1); } return _backend; @@ -67,7 +68,7 @@ export async function queryCommand( }, ): Promise { if (!queryText?.trim()) { - console.error('Usage: gitnexus query '); + cliError('Usage: gitnexus query '); process.exit(1); } @@ -93,7 +94,7 @@ export async function contextCommand( }, ): Promise { if (!name?.trim() && !options?.uid) { - console.error('Usage: gitnexus context [--uid ] [--file ]'); + cliError('Usage: gitnexus context [--uid ] [--file ]'); process.exit(1); } @@ -118,7 +119,7 @@ export async function impactCommand( }, ): Promise { if (!target?.trim()) { - console.error('Usage: gitnexus impact [--direction upstream|downstream]'); + cliError('Usage: gitnexus impact [--direction upstream|downstream]'); process.exit(1); } @@ -153,7 +154,7 @@ export async function cypherCommand( }, ): Promise { if (!query?.trim()) { - console.error('Usage: gitnexus cypher '); + cliError('Usage: gitnexus cypher '); process.exit(1); } diff --git a/gitnexus/src/cli/wiki.ts b/gitnexus/src/cli/wiki.ts index ccd1cae4ec..e44566f8f8 100644 --- a/gitnexus/src/cli/wiki.ts +++ b/gitnexus/src/cli/wiki.ts @@ -19,6 +19,7 @@ import { import { WikiGenerator, type WikiOptions } from '../core/wiki/generator.js'; import { resolveLLMConfig, type LLMProvider } from '../core/wiki/llm-client.js'; import { detectCursorCLI } from '../core/wiki/cursor-client.js'; +import { logger } from '../core/logger.js'; export interface WikiCommandOptions { force?: boolean; @@ -583,7 +584,7 @@ export const wikiCommand = async (inputPath?: string, options?: WikiCommandOptio } else { console.log(`\n Error: ${err.message}\n`); if (process.env.GITNEXUS_VERBOSE) { - console.error(err); + logger.error({ err }, 'wiki command failed'); } } process.exitCode = 1; diff --git a/gitnexus/src/config/ignore-service.ts b/gitnexus/src/config/ignore-service.ts index ff61f0eb31..ce1fda9133 100644 --- a/gitnexus/src/config/ignore-service.ts +++ b/gitnexus/src/config/ignore-service.ts @@ -2,6 +2,7 @@ import ignore, { type Ignore } from 'ignore'; import fs from 'fs/promises'; import nodePath from 'path'; import type { Path } from 'path-scurry'; +import { logger } from '../core/logger.js'; const DEFAULT_IGNORE_LIST = new Set([ // Version Control @@ -365,7 +366,7 @@ export const loadIgnoreRules = async ( } catch (err: unknown) { const code = (err as NodeJS.ErrnoException).code; if (code !== 'ENOENT') { - console.warn(` Warning: could not read ${filename}: ${(err as Error).message}`); + logger.warn(` Warning: could not read ${filename}: ${(err as Error).message}`); } } } diff --git a/gitnexus/src/core/embeddings/embedder.ts b/gitnexus/src/core/embeddings/embedder.ts index 993c418839..b37fb45f39 100644 --- a/gitnexus/src/core/embeddings/embedder.ts +++ b/gitnexus/src/core/embeddings/embedder.ts @@ -23,6 +23,7 @@ import { DEFAULT_EMBEDDING_CONFIG, type EmbeddingConfig, type ModelProgress } fr import { isHttpMode, getHttpDimensions, httpEmbed } from './http-client.js'; import { resolveEmbeddingConfig } from './config.js'; import { applyHfEnvOverrides } from './hf-env.js'; +import { logger } from '../logger.js'; /** * Check whether the onnxruntime-node package that @huggingface/transformers @@ -166,7 +167,7 @@ export const initEmbedder = async ( const isDev = process.env.NODE_ENV === 'development'; if (isDev) { - console.error(`🧠 Loading embedding model: ${finalConfig.modelId}`); + logger.info(`🧠 Loading embedding model: ${finalConfig.modelId}`); } const progressCallback = onProgress @@ -192,13 +193,13 @@ export const initEmbedder = async ( for (const device of devicesToTry) { try { if (isDev && device === 'dml') { - console.error('🔧 Trying DirectML (DirectX12) GPU backend...'); + logger.info('🔧 Trying DirectML (DirectX12) GPU backend...'); } else if (isDev && device === 'cuda') { - console.error('🔧 Trying CUDA GPU backend...'); + logger.info('🔧 Trying CUDA GPU backend...'); } else if (isDev && device === 'cpu') { - console.error('🔧 Using CPU backend...'); + logger.info('🔧 Using CPU backend...'); } else if (isDev && device === 'wasm') { - console.error('🔧 Using WASM backend (slower)...'); + logger.info('🔧 Using WASM backend (slower)...'); } embedderInstance = await (pipeline as any)('feature-extraction', finalConfig.modelId, { @@ -221,15 +222,15 @@ export const initEmbedder = async ( : device === 'cuda' ? 'GPU (CUDA)' : device.toUpperCase(); - console.error(`✅ Using ${label} backend`); - console.error('✅ Embedding model loaded successfully'); + logger.info(`✅ Using ${label} backend`); + logger.info('✅ Embedding model loaded successfully'); } return embedderInstance!; } catch (deviceError) { if (isDev && (device === 'cuda' || device === 'dml')) { const gpuType = device === 'dml' ? 'DirectML' : 'CUDA'; - console.error(`⚠️ ${gpuType} not available, falling back to CPU...`); + logger.info(`⚠️ ${gpuType} not available, falling back to CPU...`); } // Continue to next device in list if (device === devicesToTry[devicesToTry.length - 1]) { diff --git a/gitnexus/src/core/embeddings/embedding-pipeline.ts b/gitnexus/src/core/embeddings/embedding-pipeline.ts index 9d4f982818..cc2d38d9b0 100644 --- a/gitnexus/src/core/embeddings/embedding-pipeline.ts +++ b/gitnexus/src/core/embeddings/embedding-pipeline.ts @@ -44,6 +44,7 @@ import { } from '../lbug/schema.js'; import { loadVectorExtension } from '../lbug/lbug-adapter.js'; import { getExactScanLimit } from '../platform/capabilities.js'; +import { logger } from '../logger.js'; const isDev = process.env.NODE_ENV === 'development'; @@ -157,7 +158,7 @@ const queryEmbeddableNodes = async ( } } catch (error) { if (isDev) { - console.error(`Query for ${label} nodes failed:`, error); + logger.warn({ error }, `Query for ${label} nodes failed:`); } } } @@ -212,7 +213,7 @@ const createVectorIndex = async ( return true; } catch (error) { if (isDev) { - console.error('Vector index creation warning:', error); + logger.warn({ error }, 'Vector index creation warning:'); } return false; } @@ -256,7 +257,9 @@ export const runEmbeddingPipeline = async ( try { const vectorAvailable = await ensureVectorExtensionAvailable(); - if (!vectorAvailable && isDev) console.error(vectorUnavailableMessage); + if (!vectorAvailable && isDev) { + logger.warn(vectorUnavailableMessage); + } // Phase 1: Load embedding model onProgress({ @@ -283,7 +286,7 @@ export const runEmbeddingPipeline = async ( }); if (isDev) { - console.error('🔍 Querying embeddable nodes...'); + logger.info('🔍 Querying embeddable nodes...'); } // Phase 2: Query embeddable nodes @@ -325,7 +328,7 @@ export const runEmbeddingPipeline = async ( // (Kuzu forbids SET on vector-indexed properties; DELETE-then-INSERT is the sanctioned pattern) if (staleNodeIds.length > 0) { if (isDev) { - console.error(`🔄 Deleting ${staleNodeIds.length} stale embedding rows for re-embed`); + logger.info(`🔄 Deleting ${staleNodeIds.length} stale embedding rows for re-embed`); } try { await executeWithReusedStatement( @@ -346,7 +349,7 @@ export const runEmbeddingPipeline = async ( } if (isDev) { - console.error( + logger.info( `📦 Incremental embeddings: ${beforeCount} total, ${existingEmbeddings.size} cached, ${staleNodeIds.length} stale, ${nodes.length} to embed`, ); } @@ -355,7 +358,7 @@ export const runEmbeddingPipeline = async ( const totalNodes = nodes.length; if (isDev) { - console.error(`📊 Found ${totalNodes} embeddable nodes`); + logger.info(`📊 Found ${totalNodes} embeddable nodes`); } if (totalNodes === 0) { @@ -442,9 +445,9 @@ export const runEmbeddingPipeline = async ( ); } catch (chunkErr) { if (isDev) { - console.error( + logger.warn( + { chunkErr }, `⚠️ AST chunking failed for ${node.label} "${node.name}" (${node.filePath}), falling back to character-based chunking:`, - chunkErr, ); } chunks = characterChunk(node.content, startLine, endLine, chunkSize, overlap); @@ -482,9 +485,9 @@ export const runEmbeddingPipeline = async ( try { embeddings = await embedBatch(subTexts); } catch (embedErr) { - console.error( + logger.error( + { embedErr }, `❌ embedBatch failed for ${subTexts.length} texts (first: "${subTexts[0]?.substring(0, 80)}..."):`, - embedErr, ); throw embedErr; } @@ -520,7 +523,7 @@ export const runEmbeddingPipeline = async ( }); if (isDev) { - console.error('📇 Creating vector index...'); + logger.info('📇 Creating vector index...'); } const vectorIndexReady = await createVectorIndex(executeQuery); @@ -533,7 +536,7 @@ export const runEmbeddingPipeline = async ( }); if (isDev) { - console.error( + logger.info( `✅ Embedding pipeline complete! (${totalChunks} chunks from ${totalNodes} nodes)`, ); } @@ -547,7 +550,7 @@ export const runEmbeddingPipeline = async ( const errorMessage = error instanceof Error ? error.message : 'Unknown error'; if (isDev) { - console.error('❌ Embedding pipeline error:', error); + logger.error({ error }, '❌ Embedding pipeline error:'); } onProgress({ diff --git a/gitnexus/src/core/group/bridge-db.ts b/gitnexus/src/core/group/bridge-db.ts index ef45d68190..dbf2350bb8 100644 --- a/gitnexus/src/core/group/bridge-db.ts +++ b/gitnexus/src/core/group/bridge-db.ts @@ -11,6 +11,9 @@ import { type LbugConnectionHandle, } from '../lbug/lbug-config.js'; import { dedupeContracts, dedupeCrossLinks } from './normalization.js'; +import { createLogger } from '../logger.js'; + +const bridgeLogger = createLogger('bridge-db', { debugEnvVar: 'GITNEXUS_DEBUG_BRIDGE' }); /** * Sidecar files that LadybugDB creates next to a `bridge.lbug` file. @@ -702,14 +705,10 @@ export async function openBridgeDbReadOnly(groupDir: string): Promise setTimeout(r, delay)); } } - if (process.env.GITNEXUS_DEBUG_BRIDGE) { - console.warn( - `[bridge-db] openBridgeDbReadOnly(${groupDir}) gave up after ` + - `${LBUG_OPEN_RETRY_ATTEMPTS} attempts: ${ - lastErr instanceof Error ? lastErr.message : String(lastErr) - }`, - ); - } + bridgeLogger.debug( + { groupDir, err: lastErr, attempts: LBUG_OPEN_RETRY_ATTEMPTS }, + 'openBridgeDbReadOnly gave up', + ); return null; } diff --git a/gitnexus/src/core/group/extractors/elixir-workspace-extractor.ts b/gitnexus/src/core/group/extractors/elixir-workspace-extractor.ts index 33afcaed9f..7c184ba96b 100644 --- a/gitnexus/src/core/group/extractors/elixir-workspace-extractor.ts +++ b/gitnexus/src/core/group/extractors/elixir-workspace-extractor.ts @@ -4,6 +4,7 @@ import type { CypherExecutor } from '../contract-extractor.js'; import type { GroupManifestLink, ContractRole } from '../types.js'; import { shouldIgnorePath, loadIgnoreRules } from '../../../config/ignore-service.js'; +import { logger } from '../../logger.js'; interface ElixirAppMeta { appName: string; modulePrefix: string; @@ -202,7 +203,7 @@ export async function extractElixirWorkspaceLinks( }; const existing = appsByName.get(manifest.appName); if (existing) { - console.warn( + logger.warn( `[elixir-workspace-extractor] duplicate app "${manifest.appName}" in "${groupPath}" and "${existing.groupPath}" — skipping "${groupPath}"`, ); continue; diff --git a/gitnexus/src/core/group/extractors/go-workspace-extractor.ts b/gitnexus/src/core/group/extractors/go-workspace-extractor.ts index fbdf0e450c..55e8700900 100644 --- a/gitnexus/src/core/group/extractors/go-workspace-extractor.ts +++ b/gitnexus/src/core/group/extractors/go-workspace-extractor.ts @@ -4,6 +4,7 @@ import type { CypherExecutor } from '../contract-extractor.js'; import type { GroupManifestLink, ContractRole } from '../types.js'; import { shouldIgnorePath, loadIgnoreRules } from '../../../config/ignore-service.js'; +import { logger } from '../../logger.js'; interface GoModuleMeta { modulePath: string; groupPath: string; @@ -211,7 +212,7 @@ export async function extractGoWorkspaceLinks( }; const existing = modulesByPath.get(manifest.modulePath); if (existing) { - console.warn( + logger.warn( `[go-workspace-extractor] duplicate module "${manifest.modulePath}" in "${groupPath}" and "${existing.groupPath}" — skipping "${groupPath}"`, ); continue; diff --git a/gitnexus/src/core/group/extractors/grpc-extractor.ts b/gitnexus/src/core/group/extractors/grpc-extractor.ts index b5782d9b34..c08ba7c367 100644 --- a/gitnexus/src/core/group/extractors/grpc-extractor.ts +++ b/gitnexus/src/core/group/extractors/grpc-extractor.ts @@ -5,6 +5,7 @@ import { createIgnoreFilter } from '../../../config/ignore-service.js'; import type { ContractExtractor, CypherExecutor } from '../contract-extractor.js'; import type { ExtractedContract, RepoHandle } from '../types.js'; import { readSafe } from './fs-utils.js'; +import { logger } from '../../logger.js'; import { GRPC_SCAN_GLOB, getPluginForFile, @@ -344,7 +345,7 @@ export function resolveProtoConflict( // services under a fabricated package-qualified contract id. if (winners.length !== 1) { const paths = candidates.map((c) => c.protoPath).join(', '); - console.warn( + logger.warn( `[grpc-extractor] Ambiguous proto resolution for service "${serviceName}" from ${sourceFilePath}: ${winners.length} candidates tied at score ${maxScore} among [${paths}] — skipping canonical contract`, ); return null; diff --git a/gitnexus/src/core/group/extractors/java-workspace-extractor.ts b/gitnexus/src/core/group/extractors/java-workspace-extractor.ts index 66ee35ee59..b6beed71c9 100644 --- a/gitnexus/src/core/group/extractors/java-workspace-extractor.ts +++ b/gitnexus/src/core/group/extractors/java-workspace-extractor.ts @@ -4,6 +4,7 @@ import type { CypherExecutor } from '../contract-extractor.js'; import type { GroupManifestLink, ContractRole } from '../types.js'; import { shouldIgnorePath, loadIgnoreRules } from '../../../config/ignore-service.js'; +import { logger } from '../../logger.js'; interface JavaProjectMeta { groupId: string; artifactId: string; @@ -213,7 +214,7 @@ export async function extractJavaWorkspaceLinks( }; const existing = projectsByKey.get(key); if (existing) { - console.warn( + logger.warn( `[java-workspace-extractor] duplicate artifact "${key}" in "${groupPath}" and "${existing.groupPath}" — skipping "${groupPath}"`, ); continue; diff --git a/gitnexus/src/core/group/extractors/manifest-extractor.ts b/gitnexus/src/core/group/extractors/manifest-extractor.ts index 0c3cd20ca0..2af3db5958 100644 --- a/gitnexus/src/core/group/extractors/manifest-extractor.ts +++ b/gitnexus/src/core/group/extractors/manifest-extractor.ts @@ -1,6 +1,7 @@ import type { ContractType, CrossLink, GroupManifestLink, StoredContract } from '../types.js'; import type { CypherExecutor } from '../contract-extractor.js'; +import { logger } from '../../logger.js'; export interface ManifestExtractResult { contracts: StoredContract[]; crossLinks: CrossLink[]; @@ -303,7 +304,7 @@ export class ManifestExtractor { // fail the whole manifest extraction. Unresolved contracts still // get a synthetic symbolUid below, so cross-impact can proceed. const message = err instanceof Error ? err.message : String(err); - console.warn( + logger.warn( `[manifest-extractor] resolveSymbol failed for ${link.type}:${link.contract} ` + `in ${repoPathKey}: ${message}`, ); diff --git a/gitnexus/src/core/group/extractors/node-workspace-extractor.ts b/gitnexus/src/core/group/extractors/node-workspace-extractor.ts index 05a7c95dd5..aa40ac088c 100644 --- a/gitnexus/src/core/group/extractors/node-workspace-extractor.ts +++ b/gitnexus/src/core/group/extractors/node-workspace-extractor.ts @@ -4,6 +4,7 @@ import type { CypherExecutor } from '../contract-extractor.js'; import type { GroupManifestLink, ContractRole } from '../types.js'; import { shouldIgnorePath, loadIgnoreRules } from '../../../config/ignore-service.js'; +import { logger } from '../../logger.js'; interface PackageMeta { name: string; groupPath: string; @@ -205,7 +206,7 @@ export async function extractNodeWorkspaceLinks( }; const existing = packagesByName.get(manifest.name); if (existing) { - console.warn( + logger.warn( `[node-workspace-extractor] duplicate package name "${manifest.name}" in "${groupPath}" and "${existing.groupPath}" — skipping "${groupPath}"`, ); continue; diff --git a/gitnexus/src/core/group/extractors/python-workspace-extractor.ts b/gitnexus/src/core/group/extractors/python-workspace-extractor.ts index 5930808af1..4453852a63 100644 --- a/gitnexus/src/core/group/extractors/python-workspace-extractor.ts +++ b/gitnexus/src/core/group/extractors/python-workspace-extractor.ts @@ -4,6 +4,7 @@ import type { CypherExecutor } from '../contract-extractor.js'; import type { GroupManifestLink, ContractRole } from '../types.js'; import { shouldIgnorePath, loadIgnoreRules } from '../../../config/ignore-service.js'; +import { logger } from '../../logger.js'; interface PythonPackageMeta { name: string; importName: string; @@ -204,7 +205,7 @@ export async function extractPythonWorkspaceLinks( }; const existing = packagesByImportName.get(manifest.importName); if (existing) { - console.warn( + logger.warn( `[python-workspace-extractor] duplicate package "${manifest.name}" in "${groupPath}" and "${existing.groupPath}" — skipping "${groupPath}"`, ); continue; diff --git a/gitnexus/src/core/group/extractors/rust-workspace-extractor.ts b/gitnexus/src/core/group/extractors/rust-workspace-extractor.ts index c19af07caa..63fe7ea821 100644 --- a/gitnexus/src/core/group/extractors/rust-workspace-extractor.ts +++ b/gitnexus/src/core/group/extractors/rust-workspace-extractor.ts @@ -5,6 +5,7 @@ import type { GroupManifestLink, ContractRole } from '../types.js'; import { shouldIgnorePath } from '../../../config/ignore-service.js'; import { loadIgnoreRules } from '../../../config/ignore-service.js'; +import { logger } from '../../logger.js'; /** * Discover cross-crate contracts in a Rust workspace by reading each * member's `Cargo.toml` dependencies and scanning source files for @@ -224,7 +225,7 @@ export async function extractRustWorkspaceLinks( }; const existing = cratesByName.get(manifest.name); if (existing) { - console.warn( + logger.warn( `[rust-workspace-extractor] duplicate crate name "${manifest.name}" in "${groupPath}" and "${existing.groupPath}" — skipping "${groupPath}"`, ); continue; diff --git a/gitnexus/src/core/group/service.ts b/gitnexus/src/core/group/service.ts index a412ceaa82..de324e70bb 100644 --- a/gitnexus/src/core/group/service.ts +++ b/gitnexus/src/core/group/service.ts @@ -14,6 +14,7 @@ import { } from './group-path-utils.js'; import { getDefaultGitnexusDir, getGroupDir, listGroups, readContractRegistry } from './storage.js'; import { syncGroup } from './sync.js'; +import { logger } from '../logger.js'; import type { ContractRegistry, CrossLink, @@ -170,11 +171,11 @@ async function loadContractRegistryResilient( contracts.push(row); } else { skippedCorrupt++; - console.warn('[group] skipping corrupt contract row in contracts.json'); + logger.warn('[group] skipping corrupt contract row in contracts.json'); } } catch { skippedCorrupt++; - console.warn('[group] skipping corrupt contract row in contracts.json'); + logger.warn('[group] skipping corrupt contract row in contracts.json'); } } } @@ -187,11 +188,11 @@ async function loadContractRegistryResilient( crossLinks.push(row); } else { skippedCorrupt++; - console.warn('[group] skipping corrupt crossLinks row in contracts.json'); + logger.warn('[group] skipping corrupt crossLinks row in contracts.json'); } } catch { skippedCorrupt++; - console.warn('[group] skipping corrupt crossLinks row in contracts.json'); + logger.warn('[group] skipping corrupt crossLinks row in contracts.json'); } } } diff --git a/gitnexus/src/core/group/sync.ts b/gitnexus/src/core/group/sync.ts index 9a77df22a6..7ed065131e 100644 --- a/gitnexus/src/core/group/sync.ts +++ b/gitnexus/src/core/group/sync.ts @@ -16,6 +16,7 @@ import type { CypherExecutor } from './contract-extractor.js'; import { writeContractRegistry } from './storage.js'; import type { ContractRegistry } from './types.js'; +import { logger } from '../logger.js'; export interface SyncOptions { extractorOverride?: | ((repo: RepoHandle) => Promise) @@ -211,7 +212,7 @@ export async function syncGroup(config: GroupConfig, opts?: SyncOptions): Promis allLinks = [...allLinks, ...wsResult.links]; if (opts?.verbose) { for (const s of wsResult.stats) { - console.log( + logger.info( ` workspace-deps: discovered ${s.linkCount} cross-${s.ecosystem.toLowerCase()} links from ${s.projectCount} ${s.ecosystem} projects`, ); } @@ -230,7 +231,7 @@ export async function syncGroup(config: GroupConfig, opts?: SyncOptions): Promis for (const link of allLinks) { const dangling = [link.from, link.to].filter((r) => !knownRepos.has(r)); if (dangling.length > 0) { - console.warn( + logger.warn( `[group/sync] manifest link ${link.type}:${link.contract} references repos not in config.repos: ${dangling.join(', ')} — cross-links will use synthetic UIDs`, ); } @@ -241,7 +242,7 @@ export async function syncGroup(config: GroupConfig, opts?: SyncOptions): Promis autoContracts.push(...manifestResult.contracts); manifestCrossLinks = manifestResult.crossLinks; if (opts?.verbose) { - console.log( + logger.info( ` manifest: ${manifestCrossLinks.length} cross-links from ${allLinks.length} links (${config.links.length} declared + ${allLinks.length - config.links.length} discovered)`, ); } diff --git a/gitnexus/src/core/ingestion/ast-cache.ts b/gitnexus/src/core/ingestion/ast-cache.ts index 65da46ab88..454c60df2e 100644 --- a/gitnexus/src/core/ingestion/ast-cache.ts +++ b/gitnexus/src/core/ingestion/ast-cache.ts @@ -1,6 +1,7 @@ import { LRUCache } from 'lru-cache'; import Parser from 'tree-sitter'; +import { logger } from '../logger.js'; /** * Minimal structural shape consumers need when reading Trees back * through a phase-dependency boundary. Declared here so phases that @@ -49,7 +50,7 @@ export const createASTCache = (maxSize: number = 50): ASTCache => { // will hand freed memory to scope-resolution. (tree as unknown as { delete?: () => void }).delete?.(); } catch (e) { - console.warn('Failed to delete tree from WASM memory', e); + logger.warn({ e }, 'Failed to delete tree from WASM memory'); } }, }); diff --git a/gitnexus/src/core/ingestion/call-processor.ts b/gitnexus/src/core/ingestion/call-processor.ts index 1871d06057..6c59578b05 100644 --- a/gitnexus/src/core/ingestion/call-processor.ts +++ b/gitnexus/src/core/ingestion/call-processor.ts @@ -75,6 +75,7 @@ import { extractReturnTypeName, stripNullable } from './type-extractors/shared.j import type { LiteralTypeInferrer } from './type-extractors/types.js'; import type { SyntaxNode } from './utils/ast-helpers.js'; +import { logger } from '../logger.js'; /** Per-file resolved type bindings for exported symbols. * Populated during call processing, consumed by Phase 14 re-resolution pass. */ export type ExportedTypeMap = Map>; @@ -784,7 +785,7 @@ export const processCalls = async ( const query = new Parser.Query(lang, queryStr); matches = query.matches(tree.rootNode); } catch (queryError) { - console.warn(`Query error for ${file.path}:`, queryError); + logger.warn({ queryError }, `Query error for ${file.path}:`); continue; } @@ -1391,7 +1392,7 @@ export const processCalls = async ( if (skippedByLang && skippedByLang.size > 0) { for (const [lang, count] of skippedByLang.entries()) { - console.warn( + logger.warn( `[ingestion] Skipped ${count} ${lang} file(s) in call processing — ${lang} parser not available.`, ); } diff --git a/gitnexus/src/core/ingestion/cluster-enricher.ts b/gitnexus/src/core/ingestion/cluster-enricher.ts index b20ed2bad9..06cd4d0cd0 100644 --- a/gitnexus/src/core/ingestion/cluster-enricher.ts +++ b/gitnexus/src/core/ingestion/cluster-enricher.ts @@ -7,6 +7,7 @@ import { CommunityNode } from './community-processor.js'; +import { logger } from '../logger.js'; // ============================================================================ // TYPES // ============================================================================ @@ -128,7 +129,7 @@ export const enrichClusters = async ( enrichments.set(community.id, enrichment); } catch (error) { // On error, fallback to heuristic - console.warn(`Failed to enrich cluster ${community.id}:`, error); + logger.warn({ error }, `Failed to enrich cluster ${community.id}:`); enrichments.set(community.id, { name: community.heuristicLabel, keywords: [], @@ -210,7 +211,7 @@ Output JSON array: } } } catch (error) { - console.warn('Batch enrichment failed, falling back to heuristics:', error); + logger.warn({ error }, 'Batch enrichment failed, falling back to heuristics:'); // Fallback for this batch for (const community of batch) { enrichments.set(community.id, { diff --git a/gitnexus/src/core/ingestion/cobol/cobol-copy-expander.ts b/gitnexus/src/core/ingestion/cobol/cobol-copy-expander.ts index 46a33001df..dda135b127 100644 --- a/gitnexus/src/core/ingestion/cobol/cobol-copy-expander.ts +++ b/gitnexus/src/core/ingestion/cobol/cobol-copy-expander.ts @@ -1,3 +1,4 @@ +import { logger } from '../../logger.js'; /** * COBOL COPY statement expansion engine. * @@ -454,7 +455,7 @@ export function expandCopies( if (visited.has(resolvedPath)) { if (!warnedCircular.has(resolvedPath)) { warnedCircular.add(resolvedPath); - console.warn( + logger.warn( `[cobol-copy-expander] Circular COPY detected: ${cs.target} (${resolvedPath}) ` + `includes itself. Skipping expansion.`, ); @@ -464,7 +465,7 @@ export function expandCopies( // Max depth exceeded — keep unexpanded if (depth >= maxDepth) { - console.warn( + logger.warn( `[cobol-copy-expander] Max expansion depth (${maxDepth}) reached for ` + `COPY ${cs.target} in ${srcPath}. Skipping expansion.`, ); @@ -475,7 +476,7 @@ export function expandCopies( if (++totalExpansions > MAX_TOTAL_EXPANSIONS) { if (!warnedCircular.has('__max_total__')) { warnedCircular.add('__max_total__'); - console.warn( + logger.warn( `[cobol-copy-expander] Max total expansions (${MAX_TOTAL_EXPANSIONS}) reached ` + `in ${srcPath}. Skipping further expansions.`, ); diff --git a/gitnexus/src/core/ingestion/filesystem-walker.ts b/gitnexus/src/core/ingestion/filesystem-walker.ts index 71a4046f2b..4d6725e246 100644 --- a/gitnexus/src/core/ingestion/filesystem-walker.ts +++ b/gitnexus/src/core/ingestion/filesystem-walker.ts @@ -5,6 +5,7 @@ import path from 'path'; import { glob } from 'glob'; import { createIgnoreFilter } from '../../config/ignore-service.js'; +import { logger } from '../logger.js'; export interface FileEntry { path: string; content: string; @@ -74,10 +75,10 @@ export const walkRepositoryPaths = async ( if (skippedLarge > 0) { const isDefault = maxFileSizeBytes === DEFAULT_MAX_FILE_SIZE_BYTES; const suffix = isDefault ? ', likely generated/vendored' : ''; - console.warn(` Skipped ${skippedLarge} large files (>${maxFileSizeBytes / 1024}KB${suffix})`); + logger.warn(` Skipped ${skippedLarge} large files (>${maxFileSizeBytes / 1024}KB${suffix})`); if (isVerboseIngestionEnabled()) { for (const p of skippedLargePaths) { - console.warn(` - ${p}`); + logger.warn(` - ${p}`); } } } diff --git a/gitnexus/src/core/ingestion/heritage-processor.ts b/gitnexus/src/core/ingestion/heritage-processor.ts index 12e59a19ac..2c973ad8ec 100644 --- a/gitnexus/src/core/ingestion/heritage-processor.ts +++ b/gitnexus/src/core/ingestion/heritage-processor.ts @@ -34,6 +34,7 @@ import type { ResolutionContext } from './model/resolution-context.js'; import { TIER_CONFIDENCE } from './model/resolution-context.js'; import type { HeritageInfo } from './heritage-types.js'; +import { logger } from '../logger.js'; /** * Derive the heritage-resolution strategy for a language from its * `LanguageProvider`. This is the production wiring that `buildHeritageMap` @@ -237,7 +238,7 @@ export const processHeritage = async ( query = new Parser.Query(treeSitterLang, queryStr); matches = query.matches(tree.rootNode); } catch (queryError) { - console.warn(`Heritage query error for ${file.path}:`, queryError); + logger.warn({ queryError }, `Heritage query error for ${file.path}:`); continue; } @@ -267,7 +268,7 @@ export const processHeritage = async ( if (skippedByLang && skippedByLang.size > 0) { for (const [lang, count] of skippedByLang.entries()) { - console.warn( + logger.warn( `[ingestion] Skipped ${count} ${lang} file(s) in heritage processing — ${lang} parser not available.`, ); } diff --git a/gitnexus/src/core/ingestion/import-processor.ts b/gitnexus/src/core/ingestion/import-processor.ts index b669d27445..03cbed5b79 100644 --- a/gitnexus/src/core/ingestion/import-processor.ts +++ b/gitnexus/src/core/ingestion/import-processor.ts @@ -27,6 +27,7 @@ import type { SyntaxNode } from './utils/ast-helpers.js'; import { isDev } from './utils/env.js'; import { isRegistryPrimary } from './registry-primary-flag.js'; +import { logger } from '../logger.js'; // Type: Map> // Stores all files that a given file imports from export type ImportMap = Map>; @@ -324,14 +325,18 @@ export const processImports = async ( matches = query.matches(tree.rootNode); } catch (queryError: any) { if (isDev) { - console.group(`🔴 Query Error: ${file.path}`); - console.log('Language:', language); - console.log('Query (first 200 chars):', queryStr.substring(0, 200) + '...'); - console.log('Error:', queryError?.message || queryError); - console.log('File content (first 300 chars):', file.content.substring(0, 300)); - console.log('AST root type:', tree.rootNode?.type); - console.log('AST has errors:', tree.rootNode?.hasError); - console.groupEnd(); + logger.error( + { + file: file.path, + language, + err: queryError?.message || queryError, + queryPreview: queryStr.substring(0, 200) + '...', + contentPreview: file.content.substring(0, 300), + astRootType: tree.rootNode?.type, + astHasError: tree.rootNode?.hasError, + }, + 'tree-sitter query error', + ); } if (wasReparsed) (tree as unknown as { delete?: () => void }).delete?.(); @@ -346,7 +351,7 @@ export const processImports = async ( const sourceNode = captureMap['import.source']; if (!sourceNode) { if (isDev) { - console.log(`⚠️ Import captured but no source node in ${file.path}`); + logger.info(`⚠️ Import captured but no source node in ${file.path}`); } return; } @@ -399,14 +404,14 @@ export const processImports = async ( if (skippedByLang && skippedByLang.size > 0) { for (const [lang, count] of skippedByLang.entries()) { - console.warn( + logger.warn( `[ingestion] Skipped ${count} ${lang} file(s) in import processing — ${lang} parser not available.`, ); } } if (isDev) { - console.log( + logger.info( `📊 Import processing complete: ${getResolvedCount()}/${totalImportsFound} imports resolved to graph edges`, ); } @@ -498,7 +503,7 @@ export const processImportsFromExtracted = async ( ); if (isDev) { - console.log( + logger.info( `📊 Import processing (fast path): ${getResolvedCount()}/${totalImportsFound} imports resolved to graph edges`, ); } diff --git a/gitnexus/src/core/ingestion/language-config.ts b/gitnexus/src/core/ingestion/language-config.ts index 682d7b190d..f51ef57c67 100644 --- a/gitnexus/src/core/ingestion/language-config.ts +++ b/gitnexus/src/core/ingestion/language-config.ts @@ -4,6 +4,7 @@ import type { ImportConfigs } from './import-resolvers/types.js'; import { isDev } from './utils/env.js'; +import { logger } from '../logger.js'; // ============================================================================ // LANGUAGE-SPECIFIC CONFIG TYPES // ============================================================================ @@ -82,7 +83,7 @@ export async function loadTsconfigPaths(repoRoot: string): Promise 0) { if (isDev) { - console.log(`📦 Loaded ${aliases.size} path aliases from ${filename}`); + logger.info(`📦 Loaded ${aliases.size} path aliases from ${filename}`); } return { aliases, baseUrl }; } @@ -104,7 +105,7 @@ export async function loadGoModulePath(repoRoot: string): Promise 0) { if (isDev) { - console.log(`📦 Loaded ${targets.size} Swift package targets`); + logger.info(`📦 Loaded ${targets.size} Swift package targets`); } return { targets }; } diff --git a/gitnexus/src/core/ingestion/method-extractors/generic.ts b/gitnexus/src/core/ingestion/method-extractors/generic.ts index 7e15f24587..f02faef359 100644 --- a/gitnexus/src/core/ingestion/method-extractors/generic.ts +++ b/gitnexus/src/core/ingestion/method-extractors/generic.ts @@ -8,6 +8,7 @@ */ import type { SyntaxNode } from '../utils/ast-helpers.js'; +import { logger } from '../../logger.js'; import type { MethodExtractor, MethodExtractorContext, @@ -158,7 +159,7 @@ function findBodies(node: SyntaxNode, bodyNodeSet: Set): SyntaxNode[] { // Fallback: body field exists but its type is not in bodyNodeTypes. // This may indicate a config typo — log for debugging if NODE_ENV is development. if (process.env.NODE_ENV === 'development') { - console.warn( + logger.warn( `[MethodExtractor] body field type '${bodyField.type}' not in bodyNodeTypes for node '${node.type}'`, ); } diff --git a/gitnexus/src/core/ingestion/parsing-processor.ts b/gitnexus/src/core/ingestion/parsing-processor.ts index 86b4199904..8803ec023a 100644 --- a/gitnexus/src/core/ingestion/parsing-processor.ts +++ b/gitnexus/src/core/ingestion/parsing-processor.ts @@ -34,6 +34,7 @@ import { import type { LanguageProvider } from './language-provider.js'; import type { ParsedFile } from 'gitnexus-shared'; import { WorkerPool } from './workers/worker-pool.js'; +import { logger } from '../logger.js'; import type { ParseWorkerResult, ParseWorkerInput, @@ -191,7 +192,7 @@ const processParsingWithWorkers = async ( const summary = Array.from(skippedLanguages.entries()) .map(([lang, count]) => `${lang}: ${count}`) .join(', '); - console.warn(` Skipped unsupported languages: ${summary}`); + logger.warn(` Skipped unsupported languages: ${summary}`); } // Final progress @@ -382,7 +383,7 @@ const processParsingSequential = async ( bufferSize: getTreeSitterBufferSize(parseContent), }); } catch (parseError) { - console.warn(`Skipping unparseable file: ${file.path}`); + logger.warn(`Skipping unparseable file: ${file.path}`); continue; } @@ -408,7 +409,7 @@ const processParsingSequential = async ( query = new Parser.Query(language, queryString); matches = query.matches(tree.rootNode); } catch (queryError) { - console.warn(`Query error for ${file.path}:`, queryError); + logger.warn({ queryError }, `Query error for ${file.path}:`); continue; } @@ -701,7 +702,7 @@ const processParsingSequential = async ( if (skippedByLang && skippedByLang.size > 0) { for (const [lang, count] of skippedByLang.entries()) { - console.warn( + logger.warn( `[ingestion] Skipped ${count} ${lang} file(s) in parsing processing — ${lang} parser not available.`, ); } @@ -742,7 +743,7 @@ export const processParsing = async ( // in scope-resolution with an empty cache and get re-parsed. // Surfacing this in PROF mode prevents silent perf cliffs when // a repo crosses the worker-pool threshold. - console.warn( + logger.warn( `[scope-resolution prof] worker pool engaged for ${files.length} files — cross-phase tree cache will be empty; scope-resolution re-parses.`, ); } @@ -757,7 +758,7 @@ export const processParsing = async ( ); } catch (err) { const message = err instanceof Error ? err.message : String(err); - console.warn('Worker pool parsing stopped; continuing with sequential parser:', message); + logger.warn({ message }, 'Worker pool parsing stopped; continuing with sequential parser:'); reportProgress?.( lastProgress, files.length, diff --git a/gitnexus/src/core/ingestion/pipeline-phases/cobol.ts b/gitnexus/src/core/ingestion/pipeline-phases/cobol.ts index cfe6b6ce29..c9332aabce 100644 --- a/gitnexus/src/core/ingestion/pipeline-phases/cobol.ts +++ b/gitnexus/src/core/ingestion/pipeline-phases/cobol.ts @@ -15,6 +15,7 @@ import { readFileContents } from '../filesystem-walker.js'; import type { StructureOutput } from './structure.js'; import { isDev } from '../utils/env.js'; +import { logger } from '../../logger.js'; export interface CobolOutput { programs: number; paragraphs: number; @@ -47,7 +48,7 @@ export const cobolPhase: PipelinePhase = { const cobolResult = processCobol(ctx.graph, cobolFiles, allPathSet); if (isDev) { - console.log( + logger.info( ` COBOL: ${cobolResult.programs} programs, ${cobolResult.paragraphs} paragraphs, ${cobolResult.sections} sections from ${cobolFiles.length} files`, ); if ( @@ -55,12 +56,12 @@ export const cobolPhase: PipelinePhase = { cobolResult.execCicsBlocks > 0 || cobolResult.entryPoints > 0 ) { - console.log( + logger.info( ` COBOL enriched: ${cobolResult.execSqlBlocks} SQL blocks, ${cobolResult.execCicsBlocks} CICS blocks, ${cobolResult.entryPoints} entry points, ${cobolResult.moves} moves, ${cobolResult.fileDeclarations} file declarations`, ); } if (cobolResult.jclJobs > 0) { - console.log(` JCL: ${cobolResult.jclJobs} jobs, ${cobolResult.jclSteps} steps`); + logger.info(` JCL: ${cobolResult.jclJobs} jobs, ${cobolResult.jclSteps} steps`); } } diff --git a/gitnexus/src/core/ingestion/pipeline-phases/communities.ts b/gitnexus/src/core/ingestion/pipeline-phases/communities.ts index 6a302b8b9f..0e29b6cc27 100644 --- a/gitnexus/src/core/ingestion/pipeline-phases/communities.ts +++ b/gitnexus/src/core/ingestion/pipeline-phases/communities.ts @@ -15,6 +15,7 @@ import type { StructureOutput } from './structure.js'; import { processCommunities, type CommunityDetectionResult } from '../community-processor.js'; import { isDev } from '../utils/env.js'; +import { logger } from '../../logger.js'; export interface CommunitiesOutput { communityResult: CommunityDetectionResult; } @@ -47,7 +48,7 @@ export const communitiesPhase: PipelinePhase = { }); if (isDev) { - console.log( + logger.info( `🏘️ Community detection: ${communityResult.stats.totalCommunities} communities found (modularity: ${communityResult.stats.modularity.toFixed(3)})`, ); } diff --git a/gitnexus/src/core/ingestion/pipeline-phases/cross-file-impl.ts b/gitnexus/src/core/ingestion/pipeline-phases/cross-file-impl.ts index 334ff57df6..5c014ed736 100644 --- a/gitnexus/src/core/ingestion/pipeline-phases/cross-file-impl.ts +++ b/gitnexus/src/core/ingestion/pipeline-phases/cross-file-impl.ts @@ -23,6 +23,7 @@ import { topologicalLevelSort } from '../utils/graph-sort.js'; import type { KnowledgeGraph } from '../../graph/types.js'; import { isDev } from '../utils/env.js'; +import { logger } from '../../logger.js'; /** Max AST trees to keep in LRU cache for cross-file binding propagation. */ const AST_CACHE_CAP = 50; @@ -60,7 +61,7 @@ export async function runCrossFileBindingPropagation( const { levels, cycleCount } = topologicalLevelSort(ctx.importMap); if (isDev && cycleCount > 0) { - console.log(`🔄 ${cycleCount} files in import cycles (processed last in undefined order)`); + logger.info(`🔄 ${cycleCount} files in import cycles (processed last in undefined order)`); } let filesWithGaps = 0; @@ -88,7 +89,7 @@ export async function runCrossFileBindingPropagation( const gapRatio = totalFiles > 0 ? filesWithGaps / totalFiles : 0; if (gapRatio < CROSS_FILE_SKIP_THRESHOLD && filesWithGaps < gapThreshold) { if (isDev) { - console.log( + logger.info( `⏭️ Cross-file re-resolution skipped (${filesWithGaps}/${totalFiles} files, ${(gapRatio * 100).toFixed(1)}% < ${CROSS_FILE_SKIP_THRESHOLD * 100}% threshold)`, ); } @@ -193,7 +194,7 @@ export async function runCrossFileBindingPropagation( if (crossFileResolved >= MAX_CROSS_FILE_REPROCESS) { if (isDev) - console.log(`⚠️ Cross-file re-resolution capped at ${MAX_CROSS_FILE_REPROCESS} files`); + logger.info(`⚠️ Cross-file re-resolution capped at ${MAX_CROSS_FILE_REPROCESS} files`); break; } } @@ -204,7 +205,7 @@ export async function runCrossFileBindingPropagation( const elapsed = Date.now() - crossFileStart; const totalElapsed = Date.now() - pipelineStart; const reResolutionPct = totalElapsed > 0 ? ((elapsed / totalElapsed) * 100).toFixed(1) : '0'; - console.log( + logger.info( `🔗 Cross-file re-resolution: ${crossFileResolved} candidates re-processed` + ` in ${elapsed}ms (${reResolutionPct}% of total ingestion time so far)`, ); diff --git a/gitnexus/src/core/ingestion/pipeline-phases/cross-file.ts b/gitnexus/src/core/ingestion/pipeline-phases/cross-file.ts index e1e907a0bb..3ea604b4dc 100644 --- a/gitnexus/src/core/ingestion/pipeline-phases/cross-file.ts +++ b/gitnexus/src/core/ingestion/pipeline-phases/cross-file.ts @@ -36,6 +36,7 @@ import type { ParseOutput } from './parse.js'; import { runCrossFileBindingPropagation } from './cross-file-impl.js'; import { isDev } from '../utils/env.js'; +import { logger } from '../../logger.js'; export interface CrossFileOutput { /** Number of files re-processed during cross-file propagation. */ filesReprocessed: number; @@ -59,11 +60,11 @@ export const crossFilePhase: PipelinePhase = { if (isDev) { if (bindingAccumulator.totalBindings > 0) { const memKB = Math.round(bindingAccumulator.estimateMemoryBytes() / 1024); - console.log( + logger.info( `📦 BindingAccumulator: ${bindingAccumulator.totalBindings} bindings across ${bindingAccumulator.fileCount} files (~${memKB} KB)`, ); } else if (totalFiles > 0) { - console.log( + logger.info( `📦 BindingAccumulator: EMPTY — 0 bindings across 0 files despite ${totalFiles} parsed files. If the codebase has typed bindings, this indicates an upstream regression.`, ); } diff --git a/gitnexus/src/core/ingestion/pipeline-phases/markdown.ts b/gitnexus/src/core/ingestion/pipeline-phases/markdown.ts index 6b3853b9dc..dd57518c15 100644 --- a/gitnexus/src/core/ingestion/pipeline-phases/markdown.ts +++ b/gitnexus/src/core/ingestion/pipeline-phases/markdown.ts @@ -15,6 +15,7 @@ import { readFileContents } from '../filesystem-walker.js'; import type { StructureOutput } from './structure.js'; import { isDev } from '../utils/env.js'; +import { logger } from '../../logger.js'; export interface MarkdownOutput { /** Number of markdown sections extracted. */ sections: number; @@ -48,7 +49,7 @@ export const markdownPhase: PipelinePhase = { const mdResult = processMarkdown(ctx.graph, mdFiles, allPathSet); if (isDev) { - console.log( + logger.info( ` Markdown: ${mdResult.sections} sections, ${mdResult.links} cross-links from ${mdFiles.length} files`, ); } diff --git a/gitnexus/src/core/ingestion/pipeline-phases/mro.ts b/gitnexus/src/core/ingestion/pipeline-phases/mro.ts index 372ae32b09..c098f2b7bf 100644 --- a/gitnexus/src/core/ingestion/pipeline-phases/mro.ts +++ b/gitnexus/src/core/ingestion/pipeline-phases/mro.ts @@ -15,6 +15,7 @@ import type { StructureOutput } from './structure.js'; import { computeMRO } from '../mro-processor.js'; import { isDev } from '../utils/env.js'; +import { logger } from '../../logger.js'; export interface MROOutput { entries: number; ambiguityCount: number; @@ -42,7 +43,7 @@ export const mroPhase: PipelinePhase = { const mroResult = computeMRO(ctx.graph); if (isDev && mroResult.entries.length > 0) { - console.log( + logger.info( `🔀 MRO: ${mroResult.entries.length} classes analyzed, ${mroResult.ambiguityCount} ambiguities, ${mroResult.overrideEdges} METHOD_OVERRIDES, ${mroResult.methodImplementsEdges} METHOD_IMPLEMENTS`, ); } diff --git a/gitnexus/src/core/ingestion/pipeline-phases/orm.ts b/gitnexus/src/core/ingestion/pipeline-phases/orm.ts index ebdac018ac..4e6021efa7 100644 --- a/gitnexus/src/core/ingestion/pipeline-phases/orm.ts +++ b/gitnexus/src/core/ingestion/pipeline-phases/orm.ts @@ -16,6 +16,7 @@ import type { ExtractedORMQuery } from '../workers/parse-worker.js'; import type { KnowledgeGraph } from '../../graph/types.js'; import { isDev } from '../utils/env.js'; +import { logger } from '../../logger.js'; export interface ORMOutput { edgesCreated: number; modelCount: number; @@ -91,7 +92,7 @@ function processORMQueries( } if (isDev) { - console.log( + logger.info( `ORM dataflow: ${edgesCreated} QUERIES edges, ${modelNodes.size} models (${queries.length} total calls)`, ); } diff --git a/gitnexus/src/core/ingestion/pipeline-phases/parse-impl.ts b/gitnexus/src/core/ingestion/pipeline-phases/parse-impl.ts index 025bdbeb7c..bd39a43301 100644 --- a/gitnexus/src/core/ingestion/pipeline-phases/parse-impl.ts +++ b/gitnexus/src/core/ingestion/pipeline-phases/parse-impl.ts @@ -69,6 +69,7 @@ import { isDev } from '../utils/env.js'; import { synthesizeWildcardImportBindings, needsSynthesis } from './wildcard-synthesis.js'; import { extractORMQueriesInline } from './orm-extraction.js'; +import { logger } from '../../logger.js'; // ── Constants ────────────────────────────────────────────────────────────── /** Max bytes of source content to load per parse chunk. */ @@ -136,7 +137,7 @@ export async function runChunkedParseAndResolve( } } for (const [lang, count] of skippedByLang) { - console.warn( + logger.warn( `Skipping ${count} ${lang} file(s) — ${lang} parser not available (native binding may not have built). Try: npm rebuild tree-sitter-${lang}`, ); } @@ -171,7 +172,7 @@ export async function runChunkedParseAndResolve( if (isDev) { const totalMB = parseableScanned.reduce((s, f) => s + f.size, 0) / (1024 * 1024); - console.log( + logger.info( `📂 Scan: ${totalFiles} paths, ${totalParseable} parseable (${totalMB.toFixed(0)}MB), ${numChunks} chunks @ ${CHUNK_BYTE_BUDGET / (1024 * 1024)}MB budget`, ); } @@ -220,9 +221,9 @@ export async function runChunkedParseAndResolve( } workerPool = createWorkerPool(workerUrl); } catch (err) { - console.warn( + logger.warn( + { err: (err as Error).message }, 'Worker pool creation failed, using sequential fallback:', - (err as Error).message, ); } } @@ -339,7 +340,7 @@ export async function runChunkedParseAndResolve( exportedTypeMap, ); if (isDev && enrichedCount > 0) { - console.log( + logger.info( `🔗 E1: Seeded ${enrichedCount} cross-file receiver types (chunk ${chunkIdx + 1})`, ); } @@ -538,7 +539,7 @@ export async function runChunkedParseAndResolve( const rcStats = ctx.getStats(); const total = rcStats.cacheHits + rcStats.cacheMisses; const hitRate = total > 0 ? ((rcStats.cacheHits / total) * 100).toFixed(1) : '0'; - console.log( + logger.info( `🔍 Resolution cache: ${rcStats.cacheHits} hits, ${rcStats.cacheMisses} misses (${hitRate}% hit rate)`, ); } @@ -554,15 +555,15 @@ export async function runChunkedParseAndResolve( bindingAccumulator.finalize(); const enriched = enrichExportedTypeMap(bindingAccumulator, graph, exportedTypeMap); if (isDev && enriched > 0) { - console.log( + logger.info( `🔗 Worker TypeEnv enrichment: ${enriched} fixpoint-inferred exports added to ExportedTypeMap`, ); } } catch (enrichErr) { if (isDev) { - console.warn( + logger.warn( + { err: (enrichErr as Error).message }, 'Post-fallback finalize/enrich failed during cleanup:', - (enrichErr as Error).message, ); } } @@ -571,7 +572,7 @@ export async function runChunkedParseAndResolve( if (!hasSynthesized) { const synthesized = synthesizeWildcardImportBindings(graph, ctx); if (isDev && synthesized > 0) { - console.log( + logger.info( `🔗 Synthesized ${synthesized} additional wildcard import bindings (Go/Ruby/C++/Swift/Python)`, ); } diff --git a/gitnexus/src/core/ingestion/pipeline-phases/processes.ts b/gitnexus/src/core/ingestion/pipeline-phases/processes.ts index 209906cfba..166faea200 100644 --- a/gitnexus/src/core/ingestion/pipeline-phases/processes.ts +++ b/gitnexus/src/core/ingestion/pipeline-phases/processes.ts @@ -19,6 +19,7 @@ import { processProcesses, type ProcessDetectionResult } from '../process-proces import { generateId } from '../../../lib/utils.js'; import { isDev } from '../utils/env.js'; +import { logger } from '../../logger.js'; export interface ProcessesOutput { processResult: ProcessDetectionResult; } @@ -67,7 +68,7 @@ export const processesPhase: PipelinePhase = { ); if (isDev) { - console.log( + logger.info( `🔄 Process detection: ${processResult.stats.totalProcesses} processes found (${processResult.stats.crossCommunityCount} cross-community)`, ); } @@ -167,7 +168,7 @@ export const processesPhase: PipelinePhase = { } } if (isDev && linked > 0) { - console.log(`🔗 Linked ${linked} Route/Tool nodes to execution flows`); + logger.info(`🔗 Linked ${linked} Route/Tool nodes to execution flows`); } } diff --git a/gitnexus/src/core/ingestion/pipeline-phases/routes.ts b/gitnexus/src/core/ingestion/pipeline-phases/routes.ts index cd0a65f9d3..de3a8ddb88 100644 --- a/gitnexus/src/core/ingestion/pipeline-phases/routes.ts +++ b/gitnexus/src/core/ingestion/pipeline-phases/routes.ts @@ -32,6 +32,7 @@ import { generateId } from '../../../lib/utils.js'; import { readFileContents } from '../filesystem-walker.js'; import { isDev } from '../utils/env.js'; +import { logger } from '../../logger.js'; const EXPO_NAV_PATTERNS = [ /router\.(push|replace|navigate)\(\s*['"`]([^'"`]+)['"`]/g, /]*href=\s*['"`]([^'"`]+)['"`]/g, @@ -174,7 +175,7 @@ export const routesPhase: PipelinePhase = { } if (isDev) { - console.log( + logger.info( `🗺️ Route registry: ${routeRegistry.size} routes${duplicateRoutes > 0 ? ` (${duplicateRoutes} duplicate URLs skipped)` : ''}`, ); } @@ -224,7 +225,7 @@ export const routesPhase: PipelinePhase = { linkedCount++; } if (isDev && linkedCount > 0) { - console.log( + logger.info( `🛡️ Linked ${mwPath} middleware [${mwLabel.join(', ')}] to ${linkedCount} routes`, ); } @@ -290,7 +291,7 @@ export const routesPhase: PipelinePhase = { processNextjsFetchRoutes(ctx.graph, allFetchCalls, routeURLToFile, consumerContents); if (isDev) { - console.log( + logger.info( `🔗 Processed ${allFetchCalls.length} fetch() calls against ${routeRegistry.size} routes`, ); } diff --git a/gitnexus/src/core/ingestion/pipeline-phases/runner.ts b/gitnexus/src/core/ingestion/pipeline-phases/runner.ts index 89543e049d..0bfc45bd4d 100644 --- a/gitnexus/src/core/ingestion/pipeline-phases/runner.ts +++ b/gitnexus/src/core/ingestion/pipeline-phases/runner.ts @@ -15,6 +15,7 @@ import type { PipelinePhase, PipelineContext, PhaseResult } from './types.js'; import { isDev } from '../utils/env.js'; +import { logger } from '../../logger.js'; /** * Validate that the phases form a valid dependency graph (no cycles, all deps present). * Returns phases in topological execution order. @@ -176,7 +177,7 @@ export async function runPipeline( const start = Date.now(); if (isDev) { - console.log(`▶ Phase: ${phase.name}`); + logger.info(`▶ Phase: ${phase.name}`); } // Only expose declared dependencies — prevents hidden coupling to undeclared phases. @@ -220,7 +221,7 @@ export async function runPipeline( }); if (isDev) { - console.log(`✓ Phase: ${phase.name} (${durationMs}ms)`); + logger.info(`✓ Phase: ${phase.name} (${durationMs}ms)`); } } diff --git a/gitnexus/src/core/ingestion/pipeline-phases/tools.ts b/gitnexus/src/core/ingestion/pipeline-phases/tools.ts index 023c8a1aff..32a0ae71fb 100644 --- a/gitnexus/src/core/ingestion/pipeline-phases/tools.ts +++ b/gitnexus/src/core/ingestion/pipeline-phases/tools.ts @@ -16,6 +16,7 @@ import { generateId } from '../../../lib/utils.js'; import { readFileContents } from '../filesystem-walker.js'; import { isDev } from '../utils/env.js'; +import { logger } from '../../logger.js'; export interface ToolDef { name: string; filePath: string; @@ -104,7 +105,7 @@ export const toolsPhase: PipelinePhase = { } if (isDev) { - console.log(`🔧 Tool registry: ${toolDefs.length} tools detected`); + logger.info(`🔧 Tool registry: ${toolDefs.length} tools detected`); } } diff --git a/gitnexus/src/core/ingestion/process-processor.ts b/gitnexus/src/core/ingestion/process-processor.ts index a12378c981..aa744e54da 100644 --- a/gitnexus/src/core/ingestion/process-processor.ts +++ b/gitnexus/src/core/ingestion/process-processor.ts @@ -17,6 +17,7 @@ import { calculateEntryPointScore, isTestFile } from './entry-point-scoring.js'; import { SupportedLanguages } from 'gitnexus-shared'; import { isDev } from './utils/env.js'; +import { logger } from '../logger.js'; // ============================================================================ // CONFIGURATION // ============================================================================ @@ -319,13 +320,13 @@ const findEntryPoints = ( // DEBUG: Log top candidates with new scoring details if (sorted.length > 0 && isDev) { - console.log(`[Process] Top 10 entry point candidates (new scoring):`); + logger.info(`[Process] Top 10 entry point candidates (new scoring):`); sorted.slice(0, 10).forEach((c, i) => { const node = graph.getNode(c.id); const exported = node?.properties.isExported ? '✓' : '✗'; const shortPath = node?.properties.filePath?.split('/').slice(-2).join('/') || ''; - console.log(` ${i + 1}. ${node?.properties.name} [exported:${exported}] (${shortPath})`); - console.log(` score: ${c.score.toFixed(2)} = [${c.reasons.join(' × ')}]`); + logger.info(` ${i + 1}. ${node?.properties.name} [exported:${exported}] (${shortPath})`); + logger.info(` score: ${c.score.toFixed(2)} = [${c.reasons.join(' × ')}]`); }); } diff --git a/gitnexus/src/core/ingestion/scope-extractor-bridge.ts b/gitnexus/src/core/ingestion/scope-extractor-bridge.ts index 1774cefcac..41a50193de 100644 --- a/gitnexus/src/core/ingestion/scope-extractor-bridge.ts +++ b/gitnexus/src/core/ingestion/scope-extractor-bridge.ts @@ -28,6 +28,7 @@ import type { ParsedFile } from 'gitnexus-shared'; import { extract as extractScope } from './scope-extractor.js'; import type { LanguageProvider } from './language-provider.js'; +import { logger } from '../logger.js'; /** Callback used to report scope-extraction warnings to the host (worker or direct). */ export type ScopeBridgeWarn = (message: string) => void; @@ -53,7 +54,7 @@ export function extractParsedFile( err instanceof Error ? err.message : String(err) }`; if (onWarn !== undefined) onWarn(message); - else console.warn(message); + logger.warn(message); return undefined; } } diff --git a/gitnexus/src/core/ingestion/scope-resolution/pipeline/phase.ts b/gitnexus/src/core/ingestion/scope-resolution/pipeline/phase.ts index 5dbb3715fb..c2fda97776 100644 --- a/gitnexus/src/core/ingestion/scope-resolution/pipeline/phase.ts +++ b/gitnexus/src/core/ingestion/scope-resolution/pipeline/phase.ts @@ -38,6 +38,7 @@ import { runScopeResolution } from './run.js'; import { SCOPE_RESOLVERS } from './registry.js'; import { isDev, isSemanticModelValidatorEnabled } from '../../utils/env.js'; +import { logger } from '../../../logger.js'; export interface ScopeResolutionOutput { /** True when at least one language ran. */ readonly ran: boolean; @@ -144,7 +145,7 @@ export const scopeResolutionPhase: PipelinePhase = { resolutionConfig, onWarn: (msg) => { if (isSemanticModelValidatorEnabled()) { - console.warn(`[scope-resolution:${lang}] ${msg}`); + logger.warn(`[scope-resolution:${lang}] ${msg}`); } }, }, @@ -162,7 +163,7 @@ export const scopeResolutionPhase: PipelinePhase = { }); if (isDev) { - console.log( + logger.info( `[scope-resolution:${lang}] ${stats.filesProcessed} files → ${stats.importsEmitted} IMPORTS + ${stats.referenceEdgesEmitted} reference edges (${stats.resolve.unresolved} unresolved sites, ${stats.referenceSkipped} skipped)`, ); } diff --git a/gitnexus/src/core/ingestion/scope-resolution/pipeline/run.ts b/gitnexus/src/core/ingestion/scope-resolution/pipeline/run.ts index b069f0dd17..558c9ef303 100644 --- a/gitnexus/src/core/ingestion/scope-resolution/pipeline/run.ts +++ b/gitnexus/src/core/ingestion/scope-resolution/pipeline/run.ts @@ -41,6 +41,7 @@ import { emitImportEdges } from '../graph-bridge/imports-to-edges.js'; import type { ScopeResolver } from '../contract/scope-resolver.js'; import { buildWorkspaceResolutionIndex } from '../workspace-index.js'; +import { logger } from '../../../logger.js'; interface RunScopeResolutionInput { readonly graph: KnowledgeGraph; /** @@ -279,7 +280,7 @@ export function runScopeResolution( if (PROF) { const tEnd = process.hrtime.bigint(); const ns = (a: bigint, b: bigint): number => Number(b - a) / 1_000_000; - console.warn( + logger.warn( `[scope-resolution prof] extract=${ns(tStart, tExtract).toFixed(0)}ms` + ` finalize=${ns(tExtract, tFinalize).toFixed(0)}ms` + ` propagate=${ns(tFinalize, tPropagate).toFixed(0)}ms` + diff --git a/gitnexus/src/core/ingestion/type-env.ts b/gitnexus/src/core/ingestion/type-env.ts index 998e7a59ea..a38df617b3 100644 --- a/gitnexus/src/core/ingestion/type-env.ts +++ b/gitnexus/src/core/ingestion/type-env.ts @@ -24,6 +24,7 @@ import { import type { SemanticModel } from './model/index.js'; import type { NodeLabel } from 'gitnexus-shared'; +import { logger } from '../logger.js'; /** * Per-file scoped type environment: maps (scope, variableName) → typeName. * Scope-aware: variables inside functions are keyed by function name, @@ -769,7 +770,7 @@ const resolveFixpointBindings = ( if (iter === MAX_FIXPOINT_ITERATIONS - 1 && process.env.GITNEXUS_DEBUG) { const unresolved = pendingItems.length - resolved.size; if (unresolved > 0) { - console.warn( + logger.warn( `[type-env] fixpoint hit iteration cap (${MAX_FIXPOINT_ITERATIONS}), ${unresolved} items unresolved`, ); } diff --git a/gitnexus/src/core/ingestion/utils/max-file-size.ts b/gitnexus/src/core/ingestion/utils/max-file-size.ts index 0c418bfd47..82013783ac 100644 --- a/gitnexus/src/core/ingestion/utils/max-file-size.ts +++ b/gitnexus/src/core/ingestion/utils/max-file-size.ts @@ -1,5 +1,6 @@ import { TREE_SITTER_MAX_BUFFER } from '../constants.js'; +import { logger } from '../../logger.js'; /** Default threshold (512 KB). Files larger than this are skipped by the walker. */ export const DEFAULT_MAX_FILE_SIZE_BYTES = 512 * 1024; @@ -11,7 +12,7 @@ const warned = new Set(); const warnOnce = (key: string, message: string): void => { if (warned.has(key)) return; warned.add(key); - console.warn(message); + logger.warn(message); }; /** diff --git a/gitnexus/src/core/ingestion/workers/parse-worker.ts b/gitnexus/src/core/ingestion/workers/parse-worker.ts index 669465fe27..5c67125622 100644 --- a/gitnexus/src/core/ingestion/workers/parse-worker.ts +++ b/gitnexus/src/core/ingestion/workers/parse-worker.ts @@ -85,6 +85,7 @@ import type { LanguageProvider } from '../language-provider.js'; import type { ParsedFile } from 'gitnexus-shared'; import { extractParsedFile } from '../scope-extractor-bridge.js'; +import { logger } from '../../logger.js'; // ============================================================================ // Types for serializable results // ============================================================================ @@ -1385,7 +1386,7 @@ const processFileGroup = ( if (parentPort) { parentPort.postMessage({ type: 'warning', message }); } else { - console.warn(message); + logger.warn(message); } return; } @@ -1414,7 +1415,7 @@ const processFileGroup = ( bufferSize: getTreeSitterBufferSize(parseContent), }); } catch (err) { - console.warn( + logger.warn( `Failed to parse file ${file.path}: ${err instanceof Error ? err.message : String(err)}`, ); continue; @@ -1427,7 +1428,7 @@ const processFileGroup = ( try { matches = query.matches(tree.rootNode); } catch (err) { - console.warn( + logger.warn( `Query execution failed for ${file.path}: ${err instanceof Error ? err.message : String(err)}`, ); continue; @@ -1447,7 +1448,7 @@ const processFileGroup = ( file.path, (message) => { if (parentPort) parentPort.postMessage({ type: 'warning', message }); - else console.warn(message); + else logger.warn(message); }, tree, ); diff --git a/gitnexus/src/core/ingestion/workers/worker-pool.ts b/gitnexus/src/core/ingestion/workers/worker-pool.ts index d06b2b38cd..2113685676 100644 --- a/gitnexus/src/core/ingestion/workers/worker-pool.ts +++ b/gitnexus/src/core/ingestion/workers/worker-pool.ts @@ -3,6 +3,7 @@ import os from 'node:os'; import fs from 'node:fs'; import { fileURLToPath } from 'node:url'; +import { logger } from '../../logger.js'; export interface WorkerPool { /** * Dispatch items across workers. Items are split into bounded jobs, each job @@ -297,11 +298,18 @@ export const createWorkerPool = ( splitDepth: job.splitDepth + 1, timeoutMs: nextTimeout, }; - console.warn( - `Worker ${workerIndex} parse job idle timeout after ${job.timeoutMs / 1000}s ` + - `(${job.items.length} items, ${job.estimatedBytes} bytes, last progress: ${lastProgress}). ` + - `Splitting into ${first.items.length}/${second.items.length} item jobs with ` + - `${nextTimeout / 1000}s timeout.`, + logger.warn( + { + workerIndex, + timeoutSec: job.timeoutMs / 1000, + items: job.items.length, + estimatedBytes: job.estimatedBytes, + lastProgress, + firstSplitItems: first.items.length, + secondSplitItems: second.items.length, + nextTimeoutSec: nextTimeout / 1000, + }, + `Worker ${workerIndex} parse job idle timeout. Splitting into ${first.items.length}/${second.items.length} item jobs.`, ); // Preserve intuitive retry order; final result order is still enforced by startIndex sort. jobs.unshift(first, second); @@ -310,10 +318,15 @@ export const createWorkerPool = ( const nextAttempt = job.attempt + 1; if (nextAttempt <= poolOptions.maxTimeoutRetries) { - console.warn( - `Worker ${workerIndex} parse job idle timeout after ${job.timeoutMs / 1000}s ` + - `(single item, attempt ${nextAttempt}/${poolOptions.maxTimeoutRetries + 1}). ` + - `Retrying with ${nextTimeout / 1000}s timeout.`, + logger.warn( + { + workerIndex, + timeoutSec: job.timeoutMs / 1000, + attempt: nextAttempt, + maxAttempts: poolOptions.maxTimeoutRetries + 1, + nextTimeoutSec: nextTimeout / 1000, + }, + `Worker ${workerIndex} parse job idle timeout (single item). Retrying with ${nextTimeout / 1000}s timeout.`, ); jobs.unshift({ ...job, @@ -402,7 +415,7 @@ export const createWorkerPool = ( reportProgress(); } else if (msg.type === 'warning') { resetIdleTimer(); - console.warn(msg.message); + logger.warn(msg.message); } else if (msg.type === 'sub-batch-done') { waitingForFlush = true; resetIdleTimer(); diff --git a/gitnexus/src/core/lbug/extension-loader.ts b/gitnexus/src/core/lbug/extension-loader.ts index b925c5f881..582541942c 100644 --- a/gitnexus/src/core/lbug/extension-loader.ts +++ b/gitnexus/src/core/lbug/extension-loader.ts @@ -1,6 +1,7 @@ import { spawn } from 'child_process'; import { fileURLToPath } from 'node:url'; import { LBUG_MAX_DB_SIZE } from './lbug-config.js'; +import { logger } from '../logger.js'; const DEFAULT_EXTENSION_INSTALL_TIMEOUT_MS = 15_000; const EXTENSION_NAME_PATTERN = /^[A-Za-z][A-Za-z0-9_]*$/; @@ -188,7 +189,7 @@ export class ExtensionManager { const policy = opts.policy ?? this.options.policy ?? resolvePolicyFromEnv(); const timeoutMs = opts.installTimeoutMs ?? this.options.installTimeoutMs ?? getExtensionInstallTimeoutMs(); - const warn = this.options.warn ?? console.error; + const warn = this.options.warn ?? ((msg: string) => logger.warn(msg)); if (policy === 'never') { this.markUnavailable(name, label, 'extension install policy is "never"', warn); diff --git a/gitnexus/src/core/lbug/lbug-adapter.ts b/gitnexus/src/core/lbug/lbug-adapter.ts index a4559436a1..2fc12cf960 100644 --- a/gitnexus/src/core/lbug/lbug-adapter.ts +++ b/gitnexus/src/core/lbug/lbug-adapter.ts @@ -24,6 +24,7 @@ import { } from './lbug-config.js'; import { isVectorExtensionSupportedByPlatform } from '../platform/capabilities.js'; +import { logger } from '../logger.js'; // --------------------------------------------------------------------------- // Relationship CSV splitting — extracted for testability (PR #818) // --------------------------------------------------------------------------- @@ -330,7 +331,7 @@ const doInitLbug = async (dbPath: string) => { } catch (err) { const msg = err instanceof Error ? err.message : String(err); if (!msg.includes('already exists')) { - console.error(`[gitnexus:lbug] schema creation warning: ${msg.slice(0, 120)}`); + logger.warn(`⚠️ Schema creation warning: ${msg.slice(0, 120)}`); } } } @@ -683,7 +684,7 @@ export const insertNodeToLbug = async ( return false; } catch (e: any) { // Node may already exist or other error - console.error(`Failed to insert ${label} node:`, e.message); + logger.error({ err: e.message }, `Failed to insert ${label} node:`); return false; } }; @@ -1010,15 +1011,15 @@ export const fetchExistingEmbeddingHashes = async ( const nodeId = r.nodeId ?? r[0]; if (nodeId) map.set(nodeId, STALE_HASH_SENTINEL); } - console.error( - `[gitnexus:embed] ${map.size} nodes in legacy DB (missing chunk-aware columns) — all treated as stale`, + logger.info( + `[embed] ${map.size} nodes in legacy DB (missing chunk-aware columns) — all treated as stale`, ); return map; } catch (fallbackErr: any) { const fallbackMsg = fallbackErr?.message ?? ''; if (isMissingColumnOrTableError(fallbackMsg)) { - console.error( - `[gitnexus:embed] CodeEmbedding table not yet present — full embedding run (${fallbackMsg})`, + logger.info( + `[embed] CodeEmbedding table not yet present — full embedding run (${fallbackMsg})`, ); return undefined; } diff --git a/gitnexus/src/core/logger.ts b/gitnexus/src/core/logger.ts new file mode 100644 index 0000000000..3fd39193bb --- /dev/null +++ b/gitnexus/src/core/logger.ts @@ -0,0 +1,375 @@ +/** + * Centralized structured logger for GitNexus. + * + * Wraps `pino` so the rest of the codebase imports from one place. Pino's + * NDJSON output is structurally log-injection-resistant (CWE-117 / CodeQL + * `js/log-injection`): each record is a single JSON object on its own line, + * with all string field values JSON-escaped. This replaces hand-rolled + * sanitizers (see PR #1329 history) that had recurring edge-case gaps + * (undefined Error.message, U+2028/U+2029, ANSI/C0). + * + * Usage: + * import { logger, createLogger } from '../core/logger.js'; + * logger.warn({ groupDir }, 'msg'); + * const childLogger = createLogger('bridge-db', { debugEnvVar: 'GITNEXUS_DEBUG_BRIDGE' }); + * + * Operator semantics: + * - Default level: 'info' (matches pino default; preserves visibility of + * existing `console.log` migrations) + * - When `opts.debugEnvVar` is set and that env var is truthy at + * createLogger time, that named child logs at level 'debug' + * - Output is NDJSON in production / CI / vitest. pino-pretty is used only + * when stdout is a TTY AND CI is unset AND VITEST is unset, so test + * and pipeline output stay parseable. + * + * Test capture: + * The exported `logger` singleton is a Proxy that forwards every call to a + * lazily-built pino instance. Tests use `_captureLogger()` to redirect that + * inner instance to a memory stream so they can assert on records the + * production code logged. See `gitnexus/test/unit/logger.test.ts` for the + * pattern. + */ +import pino, { type Logger, type LoggerOptions, type DestinationStream } from 'pino'; +import { Writable } from 'node:stream'; +import { createRequire } from 'node:module'; + +export interface CreateLoggerOptions { + /** When set, this env var (truthy at construction time) bumps level to 'debug'. */ + debugEnvVar?: string; + /** Override destination stream — primarily for tests. */ + destination?: DestinationStream; +} + +function isTruthyEnv(value: string | undefined): boolean { + if (!value) return false; + const v = value.toLowerCase(); + return v !== '' && v !== '0' && v !== 'false' && v !== 'no' && v !== 'off'; +} + +function shouldUsePretty(): boolean { + // Logger writes to stderr (fd 2) so CLI data on stdout (fd 1) stays clean. + // Pretty-print only when stderr is a TTY and not in CI/test environments. + return ( + process.stderr.isTTY === true && + !isTruthyEnv(process.env.CI) && + !isTruthyEnv(process.env.VITEST) + ); +} + +/** + * Default pino destination — writes to stderr (fd 2) so CLI commands can + * keep stdout (fd 1) clean for tool data output (#324). Pino defaults to + * stdout; we override here. + * + * `sync: false` (SonicBoom buffered writes) so logger calls don't issue a + * blocking `write(2)` syscall on every record. Hot paths (parse-impl, + * ingestion phases, per-query backend calls) pay the cost without it. + * + * The buffered-write trade-off is record loss on hard exit. We mitigate via: + * - A `process.on('beforeExit')` hook below that calls `flushSync()` on + * normal exits. + * - The exported `flushLoggerSync()` helper, which entry-point shutdown + * handlers (SIGINT/SIGTERM) MUST call before `process.exit(N)` so + * in-flight buffered records still reach stderr. + * - `pino.final(...)` integration in `uncaughtException` / `unhandledRejection` + * handlers (see `gitnexus/src/cli/serve.ts` and `gitnexus/src/server/api.ts`). + * + * Skipped under `VITEST` so vitest's between-test cleanup doesn't fight + * `_captureLogger()`'s lifecycle. Tests use an in-memory destination via + * `_captureLogger()` and never reach this branch. + */ +let _dest: ReturnType | undefined; + +function defaultDestination(): DestinationStream { + if (_dest) return _dest; + _dest = pino.destination({ dest: 2, sync: false }); + return _dest; +} + +/** + * Flush any buffered records on the default destination. Entry-point + * shutdown handlers (`SIGINT` / `SIGTERM`) MUST call this before + * `process.exit(N)` — otherwise async-buffered records are lost on hard + * exit. No-op when the destination hasn't been constructed yet (logger + * module imported but never emitted) or when called from `_captureLogger` + * test mode (tests use an in-memory destination). + */ +export function flushLoggerSync(): void { + if (!_dest) return; + try { + _dest.flushSync(); + } catch { + // Defend against a destination that has already been closed (e.g., + // double-flush on rapid shutdown). Losing the flush attempt is the + // correct trade-off vs. throwing during shutdown. + } +} + +/** + * Idempotent registration: `process.on('beforeExit')` flushes the buffered + * destination before normal exit. Skipped under VITEST to avoid interfering + * with `_captureLogger()`'s lifecycle and vitest's per-worker cleanup. + */ +let _flushHookInstalled = false; +function installFlushHook(): void { + if (_flushHookInstalled) return; + if (isTruthyEnv(process.env.VITEST)) return; + _flushHookInstalled = true; + process.on('beforeExit', () => { + flushLoggerSync(); + }); +} + +/** + * Probe whether `pino-pretty` is resolvable from this module. Cached for + * the lifetime of the process — the resolve cost only happens once, and + * the one-time stderr warning on miss only fires once. + * + * Production installs ship pino-pretty as a runtime dependency (see + * gitnexus/package.json). The probe is the safety net for `--omit=optional`, + * `--no-package-lock` style installs and for any environment where the + * module turns out to be missing for reasons we can't predict — pino's + * own transport-resolution path resolves the target lazily at FIRST log + * write, so without this probe a missing module would throw deep inside + * the pino call site rather than at logger construction. + */ +let _prettyAvailable: boolean | null = null; +const _require = createRequire(import.meta.url); + +function isPrettyAvailable(): boolean { + if (_prettyAvailable !== null) return _prettyAvailable; + try { + _require.resolve('pino-pretty'); + _prettyAvailable = true; + } catch { + _prettyAvailable = false; + // One-time stderr warning so operators learn why TTY output is plain + // NDJSON instead of pretty-printed. Use realStderrWrite-style direct + // write — going through `logger` here would recurse. + process.stderr.write( + '[gitnexus:logger] pino-pretty unavailable; falling back to NDJSON on stderr\n', + ); + } + return _prettyAvailable; +} + +/** + * @internal Test-only reset for the pino-pretty availability cache. Lets + * unit tests exercise both resolve outcomes within the same vitest worker. + */ +export function _resetPrettyAvailableCache(): void { + _prettyAvailable = null; +} + +/** + * Build the pino-pretty transport options. Internal — exported only so unit + * tests can exercise the probe path without going through `shouldUsePretty()` + * (which is structurally false under vitest). + */ +export function _tryBuildPrettyTransport(): LoggerOptions['transport'] | undefined { + if (!isPrettyAvailable()) return undefined; + return { + target: 'pino-pretty', + options: { + // Route to stderr (fd 2) so pretty output doesn't contaminate + // CLI tool data on stdout (fd 1). pino-pretty's default is fd 1, + // which would interleave with `gitnexus query | jq` output. + destination: 2, + colorize: true, + translateTime: 'SYS:HH:MM:ss.l', + ignore: 'pid,hostname', + }, + }; +} + +/** + * Pino accepts `'fatal' | 'error' | 'warn' | 'info' | 'debug' | 'trace' | 'silent'`. + * Anything else is silently ignored at runtime; we narrow here so a typo in + * the env var produces the documented default rather than masking the issue. + */ +const PINO_LEVELS = new Set(['fatal', 'error', 'warn', 'info', 'debug', 'trace', 'silent']); + +function resolveBaseLevel(): string { + const fromEnv = process.env.GITNEXUS_LOG_LEVEL; + if (fromEnv && PINO_LEVELS.has(fromEnv.toLowerCase())) { + return fromEnv.toLowerCase(); + } + return 'info'; +} + +function buildBaseOptions(): LoggerOptions { + const opts: LoggerOptions = { + level: resolveBaseLevel(), + base: undefined, + }; + if (shouldUsePretty()) { + const transport = _tryBuildPrettyTransport(); + if (transport) opts.transport = transport; + } + return opts; +} + +/** + * Create a named child logger. When `opts.destination` is provided it bypasses + * the default stdout sink (useful for test capture). When `opts.debugEnvVar` is + * set and truthy at call time, the child runs at 'debug' level. + */ +export function createLogger(name: string, opts?: CreateLoggerOptions): Logger { + const debugRequested = opts?.debugEnvVar ? isTruthyEnv(process.env[opts.debugEnvVar]) : false; + + if (opts?.destination) { + return pino( + { level: debugRequested ? 'debug' : 'info', base: undefined, name }, + opts.destination, + ); + } + + const base = buildBaseOptions(); + // When using a transport (pino-pretty), pino manages the destination + // internally and we cannot pass one explicitly. When transport is absent, + // route to stderr so stdout stays clean for CLI data output. + let root: Logger; + if (base.transport) { + root = pino({ ...base, level: debugRequested ? 'debug' : base.level }); + } else { + root = pino({ ...base, level: debugRequested ? 'debug' : base.level }, defaultDestination()); + // The default destination is buffered (`sync: false`); register the + // graceful-exit flush hook now that we know the destination will be + // used. Idempotent — runs at most once per process. Skipped under + // VITEST so test cleanup doesn't fight `_captureLogger`. + installFlushHook(); + } + return root.child({ name }); +} + +/* ------------------------------------------------------------------ */ +/* Default singleton (Proxy-backed for test capture) */ +/* ------------------------------------------------------------------ */ + +let _activeDestination: DestinationStream | undefined; +let _cached: Logger | undefined; + +function _getInner(): Logger { + if (_cached) return _cached; + // Always go through createLogger so future defaults (serializers, redaction, + // formatters) apply uniformly. The destination override is honored when set + // by `_captureLogger()` below. + _cached = createLogger( + 'gitnexus', + _activeDestination ? { destination: _activeDestination } : undefined, + ); + return _cached; +} + +/** + * Default singleton logger (`name: 'gitnexus'`). Backed by a Proxy so test + * capture (`_captureLogger()`) can redirect output without breaking modules + * that already imported the singleton at module-load time. + */ +export const logger = new Proxy({} as Logger, { + get(_target, prop) { + const inner = _getInner(); + // Reflect.get keeps symbol-keyed lookups (e.g. Symbol.toPrimitive) intact; + // a `prop as string` cast would silently coerce them to the wrong key. + const value = Reflect.get(inner as object, prop, inner); + if (typeof value === 'function') { + return (value as (...a: unknown[]) => unknown).bind(inner); + } + return value; + }, +}) as Logger; + +/** + * Shape of a parsed pino record. `level`, `time`, and `msg` are always + * present; `name` is set when emitted from a named child logger; arbitrary + * additional fields appear when callers pass a structured first arg. + * + * Exported so test helpers and downstream skills can type-narrow capture + * results without inline `Record` casts. + */ +export interface PinoLogRecord { + level: number; + time: number; + msg: string; + name?: string; + [key: string]: unknown; +} + +/** + * In-memory Writable used by `_captureLogger()` and by tests that build + * their own pino destination. Exported so the shape lives in one place + * (previously duplicated between this module and `logger.test.ts`). + * + * `text()` and `records()` are convenience helpers test code calls. They + * don't appear in production hot paths — only test destinations capture + * here — so the surface is intentionally small. + */ +export class MemoryWritable extends Writable { + chunks: string[] = []; + _write(chunk: Buffer | string, _enc: BufferEncoding, cb: (err?: Error | null) => void): void { + this.chunks.push(typeof chunk === 'string' ? chunk : chunk.toString('utf-8')); + cb(); + } + /** Concatenate every captured write back into a single string. */ + text(): string { + return this.chunks.join(''); + } + /** Parse captured writes as one NDJSON record per non-empty line. */ + records(): PinoLogRecord[] { + return this.text() + .split('\n') + .filter((l) => l.length > 0) + .map((l) => JSON.parse(l) as PinoLogRecord); + } +} + +export interface LoggerCapture { + records(): PinoLogRecord[]; + text(): string; + restore(): void; +} + +/** + * Test helper. Redirects the default `logger` singleton to an in-memory + * stream and returns a capture object plus a restore function. + * + * Pattern: + * let cap: LoggerCapture; + * beforeEach(() => { cap = _captureLogger(); }); + * afterEach(() => { cap.restore(); }); + * it('warns', () => { + * fnUnderTest(); + * expect(cap.records().some(r => r.msg?.includes('clamping'))).toBe(true); + * }); + * + * Not a public API; underscore-prefixed and called only from test code. + * Throws if a previous capture is still active — see the body for context. + */ +export function _captureLogger(): LoggerCapture { + // Guard against double-capture: forgetting `restore()` between two + // `_captureLogger()` calls silently abandoned the previous capture and + // corrupted logger state for the rest of the vitest worker. Throwing here + // surfaces the bug at the moment of misuse instead of as inscrutable + // missing-records assertions in unrelated tests. + if (_activeDestination !== undefined) { + throw new Error( + '_captureLogger: a previous capture is still active — call restore() before starting a new one.', + ); + } + const w = new MemoryWritable(); + _activeDestination = w; + _cached = undefined; + return { + records: () => + w.chunks + .join('') + .split('\n') + .filter((l) => l.length > 0) + .map((l) => JSON.parse(l) as PinoLogRecord), + text: () => w.chunks.join(''), + restore: () => { + _activeDestination = undefined; + _cached = undefined; + }, + }; +} diff --git a/gitnexus/src/core/tree-sitter/parser-loader.ts b/gitnexus/src/core/tree-sitter/parser-loader.ts index 0ec958e365..8057e77957 100644 --- a/gitnexus/src/core/tree-sitter/parser-loader.ts +++ b/gitnexus/src/core/tree-sitter/parser-loader.ts @@ -2,6 +2,7 @@ import Parser from 'tree-sitter'; import { createRequire } from 'node:module'; import { SupportedLanguages } from 'gitnexus-shared'; +import { logger } from '../logger.js'; const _require = createRequire(import.meta.url); /** @@ -175,10 +176,14 @@ const logFailure = (key: string, result: LoadResult): void => { logged.add(key); const message = `[gitnexus] ${result.note} (${result.error.message})`; - // Both severities go to stderr — console.warn writes to stderr too, but - // console.error is the stdout-safe channel we standardize on across - // MCP-reachable code so the ESLint rule covers this directory. - console.error(message); + // Severity routes to the correct pino level. Both go to stderr (pino's + // default destination), so MCP stdio framing is preserved either way — + // the level tag drives log filtering, not channel selection. + if (result.severity === 'error') { + logger.error(message); + } else { + logger.warn(message); + } }; export const resolveLanguageKey = (language: SupportedLanguages, filePath?: string): string => diff --git a/gitnexus/src/core/wiki/cursor-client.ts b/gitnexus/src/core/wiki/cursor-client.ts index 707f8e293c..bf85f4183e 100644 --- a/gitnexus/src/core/wiki/cursor-client.ts +++ b/gitnexus/src/core/wiki/cursor-client.ts @@ -10,6 +10,7 @@ import { spawn, execSync } from 'child_process'; import type { LLMResponse, CallLLMOptions } from './llm-client.js'; +import { logger } from '../logger.js'; export interface CursorConfig { model?: string; workingDirectory?: string; @@ -21,7 +22,7 @@ function isVerbose(): boolean { function verboseLog(...args: unknown[]): void { if (isVerbose()) { - console.log('[cursor-cli]', ...args); + logger.info({ args }, '[cursor-cli]'); } } diff --git a/gitnexus/src/core/wiki/llm-client.ts b/gitnexus/src/core/wiki/llm-client.ts index 6f446be152..f68c2d3e7c 100644 --- a/gitnexus/src/core/wiki/llm-client.ts +++ b/gitnexus/src/core/wiki/llm-client.ts @@ -1,3 +1,4 @@ +import { logger } from '../logger.js'; /** * LLM Client for Wiki Generation * @@ -135,7 +136,7 @@ export async function callLLM( // Warn when using Azure legacy deployment URL without api-version if (azure && !config.apiVersion && config.baseUrl.includes('/deployments/')) { - console.warn( + logger.warn( '[gitnexus] Warning: Azure legacy deployment URL detected but no api-version set. Add --api-version 2024-10-21 or use the v1 API format.', ); } diff --git a/gitnexus/src/mcp/core/embedder.ts b/gitnexus/src/mcp/core/embedder.ts index f506cdeadf..ff3a12fd85 100644 --- a/gitnexus/src/mcp/core/embedder.ts +++ b/gitnexus/src/mcp/core/embedder.ts @@ -15,6 +15,7 @@ import { resolveEmbeddingConfig } from '../../core/embeddings/config.js'; import { applyHfEnvOverrides } from '../../core/embeddings/hf-env.js'; import { silenceStdout, restoreStdout, realStderrWrite } from '../../core/lbug/pool-adapter.js'; +import { logger } from '../../core/logger.js'; // Model config const MODEL_ID = 'Snowflake/snowflake-arctic-embed-xs'; @@ -51,7 +52,7 @@ export const initEmbedder = async (): Promise => { applyHfEnvOverrides(env); const embeddingConfig = resolveEmbeddingConfig(); - console.error('GitNexus: Loading embedding model (first search may take a moment)...'); + logger.info('GitNexus: Loading embedding model (first search may take a moment)...'); const devicesToTry: Array<'dml' | 'cuda' | 'cpu'> = embeddingConfig.device === 'dml' || embeddingConfig.device === 'cuda' @@ -82,7 +83,7 @@ export const initEmbedder = async (): Promise => { restoreStdout(); process.stderr.write = realStderrWrite; } - console.error(`GitNexus: Embedding model loaded (${device})`); + logger.info({ device }, 'GitNexus: Embedding model loaded'); return embedderInstance!; } catch { if (device === 'cpu') throw new Error('Failed to load embedding model'); diff --git a/gitnexus/src/mcp/local/local-backend.ts b/gitnexus/src/mcp/local/local-backend.ts index 68df9feaac..11f7e61f32 100644 --- a/gitnexus/src/mcp/local/local-backend.ts +++ b/gitnexus/src/mcp/local/local-backend.ts @@ -41,6 +41,7 @@ import { } from '../../core/platform/capabilities.js'; import { PhaseTimer } from '../../core/search/phase-timer.js'; import { checkStaleness, checkCwdMatch } from '../../core/git-staleness.js'; +import { logger } from '../../core/logger.js'; // AI context generation is CLI-only (gitnexus analyze) // import { generateAIContextFiles } from '../../cli/ai-context.js'; @@ -164,29 +165,27 @@ const confidenceForRelType = (relType: string | undefined): number => /** Structured error logging for query failures — replaces empty catch blocks */ function logQueryError(context: string, err: unknown): void { const msg = err instanceof Error ? err.message : String(err); - console.error(`GitNexus [${context}]: ${msg}`); + logger.error({ context, err: msg }, 'GitNexus query failed'); } /** - * Structured per-query latency log for production aggregation (#553). + * Per-query latency telemetry for production aggregation (#553). * - * Emitted on stderr — NOT stdout — because the MCP stdio transport uses - * stdout exclusively for JSON-RPC responses (#324), and the CLI e2e test - * `tool output goes to stdout via fd 1` asserts that stdout parses cleanly - * as JSON. Any `console.log` from inside a tool handler would corrupt the - * protocol. Matches the existing `logQueryError` convention above, which - * uses stderr for the same reason. + * Logged at `debug` level — timing is observability/telemetry, not an + * error. Operators wanting per-query timing set `GITNEXUS_LOG_LEVEL=debug` + * (or equivalent). Emitting at `error` level (the original migration + * artifact) caused alerting rules to fire on every successful query and + * inflated stderr noise for every MCP/CLI invocation. * - * The `GitNexus [query:timing] …` prefix keeps lines greppable; the - * `phases` payload is JSON so log-scraping pipelines can parse it - * without custom format knowledge. + * Emitted via the project logger which routes to stderr — never stdout — + * because the MCP stdio transport uses stdout exclusively for JSON-RPC + * responses (#324) and the CLI e2e test `tool output goes to stdout via + * fd 1` asserts stdout parses cleanly as JSON. */ function logQueryTiming(query: string, phases: Record): void { const totalMs = phases.wall ?? Object.values(phases).reduce((a, b) => a + b, 0); const truncated = query.length > 80 ? `${query.slice(0, 80)}…` : query; - console.error( - `GitNexus [query:timing] query=${JSON.stringify(truncated)} totalMs=${totalMs} phases=${JSON.stringify(phases)}`, - ); + logger.debug({ query: truncated, totalMs, phases }, 'GitNexus query timing'); } export interface CodebaseContext { @@ -287,7 +286,7 @@ export class LocalBackend { // If kuzu exists but lbug doesn't, warn so the user knows to re-analyze. const kuzu = await cleanupOldKuzuFiles(storagePath); if (kuzu.found && kuzu.needsReindex) { - console.error( + logger.error( `GitNexus: "${entry.name}" has a stale KuzuDB index. Run: gitnexus analyze ${entry.path}`, ); } @@ -637,7 +636,7 @@ export class LocalBackend { } this.warnedSiblingDrift.add(cacheKey); - console.error(`GitNexus: ${match.hint}`); + logger.error(`GitNexus: ${match.hint}`); } // ─── Tool Dispatch ─────────────────────────────────────────────── @@ -990,7 +989,10 @@ export class LocalBackend { try { bm25Results = await searchFTSFromLbug(query, limit, repo.id); } catch (err: any) { - console.error('GitNexus: BM25/FTS search failed (FTS indexes may not exist) -', err.message); + logger.error( + { err: err.message }, + 'GitNexus: BM25/FTS search failed (FTS indexes may not exist) -', + ); return { results: [], ftsUsed: false }; } @@ -1114,7 +1116,7 @@ export class LocalBackend { // policy. Emitted once per `LocalBackend` instance lifetime to avoid // noisy stderr on hot semantic-search paths (DoD §2.8). this.warnedVectorUnsupported = true; - console.error( + logger.warn( 'GitNexus [query:vector]: VECTOR extension not supported on this platform; using exact scan fallback', ); } diff --git a/gitnexus/src/mcp/server.ts b/gitnexus/src/mcp/server.ts index f7193c4846..5159b12d99 100644 --- a/gitnexus/src/mcp/server.ts +++ b/gitnexus/src/mcp/server.ts @@ -312,7 +312,11 @@ export async function startMCPServer(backend: LocalBackend): Promise { // stray writes even when individual payloads were truncated/suppressed. process.on('exit', () => sentinel.flushSummary()); - // Graceful shutdown helper + // Graceful shutdown helper. Pino's default destination is `sync: false` + // (buffered), so we must `flushLoggerSync()` before `process.exit` — + // otherwise records emitted during disconnect/close are lost. The flush + // is a no-op when the singleton was never used or when running under + // vitest. See `gitnexus/src/core/logger.ts`. let shuttingDown = false; const shutdown = async (exitCode = 0) => { if (shuttingDown) return; @@ -323,6 +327,8 @@ export async function startMCPServer(backend: LocalBackend): Promise { try { await server.close(); } catch {} + const { flushLoggerSync } = await import('../core/logger.js'); + flushLoggerSync(); process.exit(exitCode); }; diff --git a/gitnexus/src/server/api.ts b/gitnexus/src/server/api.ts index a8f784630a..7731907856 100644 --- a/gitnexus/src/server/api.ts +++ b/gitnexus/src/server/api.ts @@ -27,8 +27,6 @@ import { isWriteQuery } from '../core/lbug/pool-adapter.js'; import { NODE_TABLES, type GraphNode, type GraphRelationship } from 'gitnexus-shared'; import { searchFTSFromLbug } from '../core/search/bm25-index.js'; import { hybridSearch } from '../core/search/hybrid-search.js'; -// Embedding imports are lazy (dynamic import) to avoid loading onnxruntime-node -// at server startup — crashes on unsupported Node ABI versions (#89) import { LocalBackend } from '../mcp/local/local-backend.js'; import { mountMCPEndpoints } from './mcp-http.js'; import { fork } from 'child_process'; @@ -36,6 +34,7 @@ import { fileURLToPath, pathToFileURL } from 'url'; import { JobManager } from './analyze-job.js'; import { assertString, escapeRegExp, BadRequestError, createRouteLimiter } from './validation.js'; import { extractRepoName, getCloneDir, cloneOrPull } from './git-clone.js'; +import { logger, flushLoggerSync } from '../core/logger.js'; const _require = createRequire(import.meta.url); const pkg = _require('../../package.json'); @@ -143,7 +142,7 @@ export const resolveWebDistDir = async ( return dir; } catch (err: any) { if (err?.code !== 'ENOENT') { - console.warn(`[serve] could not access web UI dir ${dir}:`, err.message); + logger.warn({ err: err.message }, `[serve] could not access web UI dir ${dir}:`); } } } @@ -1490,7 +1489,7 @@ export const createServer = async (port: number, host: string = '127.0.0.1') => }); }) .catch((err) => { - console.error('backend.init() failed after analyze:', err); + logger.error({ err }, 'backend.init() failed after analyze:'); jobManager.updateJob(job.id, { status: 'failed', error: 'Server failed to reload after analysis. Try again.', @@ -1522,7 +1521,7 @@ export const createServer = async (port: number, host: string = '127.0.0.1') => j.retryCount++; const delay = 1000 * Math.pow(2, j.retryCount - 1); // 1s, 2s const lastErr = stderrChunks.trim().split('\n').pop() || ''; - console.warn( + logger.warn( `Analyze worker crashed (code ${code}), retry ${j.retryCount}/${MAX_WORKER_RETRIES} in ${delay}ms` + (lastErr ? `: ${lastErr}` : ''), ); @@ -1790,7 +1789,7 @@ export const createServer = async (port: number, host: string = '127.0.0.1') => // Global error handler — catch anything the route handlers miss app.use((err: any, _req: express.Request, res: express.Response, _next: express.NextFunction) => { - console.error('Unhandled error:', err); + logger.error({ err }, 'Unhandled error:'); res.status(500).json({ error: 'Internal server error' }); }); @@ -1804,7 +1803,9 @@ export const createServer = async (port: number, host: string = '127.0.0.1') => }); server.on('error', (err) => reject(err)); - // Graceful shutdown — close Express + LadybugDB cleanly + // Graceful shutdown — close Express + LadybugDB cleanly. Pino's default + // destination is `sync: false` (buffered); `flushLoggerSync()` before + // `process.exit` so records emitted during cleanup reach stderr. const shutdown = async () => { console.log('\nShutting down...'); server.close(); @@ -1813,22 +1814,33 @@ export const createServer = async (port: number, host: string = '127.0.0.1') => await cleanupMcp(); await closeLbug(); await backend.disconnect(); + const { flushLoggerSync } = await import('../core/logger.js'); + flushLoggerSync(); process.exit(0); }; process.once('SIGINT', shutdown); process.once('SIGTERM', shutdown); - // Catch-all crash guards (mirrors startMCPServer in mcp/server.ts) + // Catch-all crash guards (mirrors startMCPServer in mcp/server.ts). + // Pino v10's default destination is buffered (`sync: false`) — call + // `flushLoggerSync()` after logging and before triggering shutdown + // so the crash record reaches stderr regardless of how cleanup goes. + // Worker-thread transports (pino-pretty under TTY) handle their own + // flush on process exit in v10. `pino.final` was removed in v10 + // because the new transport architecture made it unnecessary. let shuttingDown = false; process.on('uncaughtException', (err) => { - console.error('GitNexus uncaughtException:', err?.stack || err); + logger.error({ err }, 'GitNexus uncaughtException'); + flushLoggerSync(); if (!shuttingDown) { shuttingDown = true; shutdown().catch(() => {}); } }); - process.on('unhandledRejection', (reason: any) => { - console.error('GitNexus unhandledRejection:', reason?.stack || reason); + process.on('unhandledRejection', (reason: unknown) => { + // Availability-first: log the rejection without exiting. + const err = reason instanceof Error ? reason : new Error(String(reason)); + logger.error({ err }, 'GitNexus unhandledRejection'); }); }); }; diff --git a/gitnexus/src/server/git-clone.ts b/gitnexus/src/server/git-clone.ts index b1f369dd7e..861a166484 100644 --- a/gitnexus/src/server/git-clone.ts +++ b/gitnexus/src/server/git-clone.ts @@ -10,6 +10,7 @@ import path from 'path'; import os from 'os'; import fs from 'fs/promises'; import { isIP } from 'net'; +import { logger } from '../core/logger.js'; /** Root directory for all cloned repositories. Targets must resolve inside this. */ const CLONE_ROOT = path.resolve(path.join(os.homedir(), '.gitnexus', 'repos')); @@ -446,7 +447,7 @@ function runGit(args: string[], cwd?: string): Promise { if (code === 0) resolve(); else { // Log full stderr internally but don't expose it to API callers (SSRF mitigation) - if (stderr.trim()) console.error(`git ${args[0]} stderr: ${stderr.trim()}`); + if (stderr.trim()) logger.error(`git ${args[0]} stderr: ${stderr.trim()}`); reject(new Error(`git ${args[0]} failed (exit code ${code})`)); } }); diff --git a/gitnexus/src/server/mcp-http.ts b/gitnexus/src/server/mcp-http.ts index 0bc086360f..67ec947085 100644 --- a/gitnexus/src/server/mcp-http.ts +++ b/gitnexus/src/server/mcp-http.ts @@ -15,6 +15,7 @@ import { Server } from '@modelcontextprotocol/sdk/server/index.js'; import { createMCPServer } from '../mcp/server.js'; import type { LocalBackend } from '../mcp/local/local-backend.js'; import { randomUUID } from 'crypto'; +import { logger } from '../core/logger.js'; interface MCPSession { server: Server; @@ -87,7 +88,7 @@ export function mountMCPEndpoints(app: Express, backend: LocalBackend): () => Pr app.all('/api/mcp', (req: Request, res: Response) => { void handleMcpRequest(req, res).catch((err: any) => { - console.error('MCP HTTP request failed:', err); + logger.error({ err }, 'MCP HTTP request failed:'); if (res.headersSent) return; res.status(500).json({ jsonrpc: '2.0', diff --git a/gitnexus/test/integration/cli/tool-no-index-stderr.test.ts b/gitnexus/test/integration/cli/tool-no-index-stderr.test.ts new file mode 100644 index 0000000000..baf8178fd6 --- /dev/null +++ b/gitnexus/test/integration/cli/tool-no-index-stderr.test.ts @@ -0,0 +1,122 @@ +/** + * Regression test for the buffered-pino + hard-exit diagnostic-loss bug + * (Codex adversarial review on PR #1336, plan 002). + * + * Symptom before the fix: `gitnexus tool query ` with no indexed + * repos exits non-zero with EMPTY stderr — the `logger.error()` call was + * routed through pino's `sync: false` SonicBoom buffer, and the + * subsequent synchronous `process.exit(1)` killed the process before the + * buffer could drain. Operators saw a silent failure. + * + * The fix routes user-facing CLI diagnostics through `cliError` (in + * `gitnexus/src/cli/cli-message.ts`), which writes plain text directly + * to `process.stderr` AND tees a structured pino record. Direct stderr + * writes don't go through the buffer, so they survive `process.exit`. + * + * This test spawns the built CLI in a child process and asserts the + * diagnostic line reaches stderr before exit. Without the fix it fails; + * with the fix it passes. Characterization-first contract, locked in + * end-to-end against `dist/`. + */ +import { describe, it, expect } from 'vitest'; +import { spawn } from 'node:child_process'; +import path from 'node:path'; +import fs from 'node:fs'; +import os from 'node:os'; +import { fileURLToPath } from 'node:url'; + +const __dirname = path.dirname(fileURLToPath(import.meta.url)); +const REPO_ROOT = path.resolve(__dirname, '..', '..', '..'); +const DIST_CLI = path.join(REPO_ROOT, 'dist', 'cli', 'index.js'); + +const CHILD_TIMEOUT_MS = process.env.CI ? 20_000 : 10_000; + +interface ChildResult { + exitCode: number | null; + stdout: string; + stderr: string; +} + +/** + * Spawn the built `gitnexus` CLI with arguments, wait for exit, and + * return captured streams + exit code. Pin GITNEXUS_HOME to a fresh + * empty temp dir so the LocalBackend init reliably finds zero indexed + * repos. Force NODE_OPTIONS empty to prevent host-environment overrides + * from changing buffer / heap behavior (plan 001 U3 added the buffered + * destination, which is what this test guards against). + */ +function runCli(args: string[]): Promise { + const tmpHome = fs.mkdtempSync(path.join(os.tmpdir(), 'gitnexus-cli-no-index-')); + return new Promise((resolve, reject) => { + const proc = spawn(process.execPath, [DIST_CLI, ...args], { + cwd: REPO_ROOT, + env: { + ...process.env, + GITNEXUS_HOME: tmpHome, + NODE_OPTIONS: '', + // Force NDJSON path: pino-pretty only activates when stderr is a + // TTY and !CI && !VITEST. spawn() pipes stderr, so it's not a + // TTY in this child anyway, but the explicit env is defense-in-depth. + CI: '1', + }, + stdio: ['pipe', 'pipe', 'pipe'], + }); + + const stdoutChunks: Buffer[] = []; + const stderrChunks: Buffer[] = []; + + proc.stdout.on('data', (chunk: Buffer) => stdoutChunks.push(chunk)); + proc.stderr.on('data', (chunk: Buffer) => stderrChunks.push(chunk)); + + const timer = setTimeout(() => { + proc.kill('SIGKILL'); + reject(new Error(`child process exceeded ${CHILD_TIMEOUT_MS}ms timeout`)); + }, CHILD_TIMEOUT_MS); + + proc.on('close', (code) => { + clearTimeout(timer); + // Best-effort cleanup of the empty temp home; ignore errors so they + // don't mask test failures. + try { + fs.rmSync(tmpHome, { recursive: true, force: true }); + } catch { + /* ignore */ + } + resolve({ + exitCode: code, + stdout: Buffer.concat(stdoutChunks).toString('utf8'), + stderr: Buffer.concat(stderrChunks).toString('utf8'), + }); + }); + proc.on('error', (err) => { + clearTimeout(timer); + reject(err); + }); + }); +} + +describe('CLI tool query — diagnostic survives hard exit (plan 002)', () => { + it('emits the no-index diagnostic to stderr before exit code 1', async () => { + if (!fs.existsSync(DIST_CLI)) { + throw new Error( + `dist/cli/index.js missing — run \`npm run build\` first (or use \`npm run test:integration\` which builds via pretest:integration).`, + ); + } + + const result = await runCli(['query', 'whatever']); + + // Without the plan-002 fix, stderr was empty. The diagnostic must be + // visible regardless of how `process.exit(1)` interacts with the + // buffered pino destination. + expect(result.stderr).toContain('No indexed repositories found'); + expect(result.stderr).toContain('gitnexus analyze'); + + // Exit code stays 1 — we're only changing the message channel, not + // the failure semantics. + expect(result.exitCode).toBe(1); + + // Stdout should not carry the diagnostic. CLI tool data is reserved + // for stdout (e.g., `gitnexus query | jq`); diagnostics are stderr. + expect(result.stdout).not.toContain('No indexed repositories found'); + }, 30_000); +}); diff --git a/gitnexus/test/integration/filesystem-walker.test.ts b/gitnexus/test/integration/filesystem-walker.test.ts index accb24e374..2a1257ccc0 100644 --- a/gitnexus/test/integration/filesystem-walker.test.ts +++ b/gitnexus/test/integration/filesystem-walker.test.ts @@ -8,6 +8,7 @@ import { } from '../../src/core/ingestion/filesystem-walker.js'; import { _resetMaxFileSizeWarnings } from '../../src/core/ingestion/utils/max-file-size.js'; +import { _captureLogger } from '../../src/core/logger.js'; describe('filesystem-walker', () => { let tmpDir: string; @@ -328,7 +329,7 @@ describe('filesystem-walker', () => { const BIG_FILE = 'src/big.ts'; const BIG_FILE_BYTES = 600 * 1024; const ORIGINAL_ENV = process.env.GITNEXUS_MAX_FILE_SIZE; - let warnSpy: ReturnType; + let cap: ReturnType; beforeAll(async () => { sizeDir = await fs.mkdtemp(path.join(os.tmpdir(), 'gn-walker-size-test-')); @@ -344,7 +345,7 @@ describe('filesystem-walker', () => { beforeEach(() => { delete process.env.GITNEXUS_MAX_FILE_SIZE; _resetMaxFileSizeWarnings(); - warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + cap = _captureLogger(); }); afterEach(() => { @@ -353,7 +354,7 @@ describe('filesystem-walker', () => { } else { process.env.GITNEXUS_MAX_FILE_SIZE = ORIGINAL_ENV; } - warnSpy.mockRestore(); + cap.restore(); }); it('skips a 600KB file by default', async () => { @@ -375,27 +376,27 @@ describe('filesystem-walker', () => { const files = await walkRepositoryPaths(sizeDir); const paths = files.map((f) => f.path.replace(/\\/g, '/')); expect(paths).not.toContain(BIG_FILE); - const invalidWarnings = warnSpy.mock.calls.filter((c) => - String(c[0]).includes('must be a positive integer'), - ); + const invalidWarnings = cap + .records() + .filter((r) => String(r.msg ?? '').includes('must be a positive integer')); expect(invalidWarnings).toHaveLength(1); }); it('omits the "generated/vendored" suffix when threshold is overridden', async () => { process.env.GITNEXUS_MAX_FILE_SIZE = '1'; await walkRepositoryPaths(sizeDir); - const skipWarnings = warnSpy.mock.calls.filter((c) => String(c[0]).includes('Skipped ')); + const skipWarnings = cap.records().filter((r) => String(r.msg ?? '').includes('Skipped ')); expect(skipWarnings.length).toBeGreaterThan(0); - for (const call of skipWarnings) { - expect(String(call[0])).not.toContain('generated/vendored'); + for (const r of skipWarnings) { + expect(String(r.msg ?? '')).not.toContain('generated/vendored'); } }); it('keeps the "generated/vendored" suffix under the default threshold', async () => { await walkRepositoryPaths(sizeDir); - const skipWarnings = warnSpy.mock.calls.filter((c) => String(c[0]).includes('Skipped ')); + const skipWarnings = cap.records().filter((r) => String(r.msg ?? '').includes('Skipped ')); expect(skipWarnings.length).toBeGreaterThan(0); - expect(String(skipWarnings[0][0])).toContain('generated/vendored'); + expect(String(skipWarnings[0].msg ?? '')).toContain('generated/vendored'); }); }); }); diff --git a/gitnexus/test/integration/worker-pool.test.ts b/gitnexus/test/integration/worker-pool.test.ts index b6e3a023cb..845c1cfbab 100644 --- a/gitnexus/test/integration/worker-pool.test.ts +++ b/gitnexus/test/integration/worker-pool.test.ts @@ -6,13 +6,14 @@ * This is critical for cross-platform CI where vitest runs from src/ * but workers need compiled .js files. */ -import { describe, it, expect, afterEach, vi } from 'vitest'; +import { describe, it, expect, afterEach } from 'vitest'; import { createWorkerPool, WorkerPool } from '../../src/core/ingestion/workers/worker-pool.js'; import { pathToFileURL } from 'node:url'; import path from 'node:path'; import fs from 'node:fs'; import os from 'node:os'; +import { _captureLogger } from '../../src/core/logger.js'; const DIST_WORKER = path.resolve( __dirname, '..', @@ -211,7 +212,7 @@ describe('worker pool integration', () => { `, ); - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + const cap = _captureLogger(); const workerUrl = pathToFileURL(workerPath) as URL; pool = createWorkerPool(workerUrl, 1); @@ -221,9 +222,9 @@ describe('worker pool integration', () => { ]); expect(results).toHaveLength(1); expect(results[0].fileCount).toBe(1); - expect(warnSpy).toHaveBeenCalledWith('warning before result'); + expect(cap.records().some((r) => r.msg === 'warning before result')).toBe(true); } finally { - warnSpy.mockRestore(); + cap.restore(); fs.rmSync(tempDir, { recursive: true, force: true }); } }); @@ -298,7 +299,7 @@ describe('worker pool integration', () => { `, ); - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + const cap = _captureLogger(); pool = createWorkerPool(pathToFileURL(workerPath) as URL, 1, { subBatchIdleTimeoutMs: 500, maxTimeoutRetries: 1, @@ -308,9 +309,12 @@ describe('worker pool integration', () => { try { const results = await pool.dispatch([{ path: 'retry.ts', content: '' }]); expect(results).toEqual([{ fileCount: 1, recovered: true }]); - expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining('Retrying with 2s timeout')); + // 500ms idle timeout × 4 backoff factor = 2000ms = "2s" in the retry log. + expect( + cap.records().some((r) => String(r.msg ?? '').includes('Retrying with 2s timeout')), + ).toBe(true); } finally { - warnSpy.mockRestore(); + cap.restore(); fs.rmSync(tempDir, { recursive: true, force: true }); } }); @@ -337,7 +341,11 @@ describe('worker pool integration', () => { `, ); - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + // Capture pino output AND assert on it: the worker pool should emit a + // warn-level record naming the crash before rejecting, so an operator + // can tell a startup-crash from a stalled-worker rejection. Asserting + // here keeps coverage parity with the prior console.warn spy version. + const cap = _captureLogger(); pool = createWorkerPool(pathToFileURL(workerPath) as URL, 1, { subBatchIdleTimeoutMs: 150, maxTimeoutRetries: 1, @@ -348,8 +356,10 @@ describe('worker pool integration', () => { await expect(pool.dispatch([{ path: 'crash.ts', content: '' }])).rejects.toThrow( /simulated startup crash|exited with code/, ); + const warnRecords = cap.records().filter((r) => Number(r.level) >= 40 /* warn or above */); + expect(warnRecords.length).toBeGreaterThan(0); } finally { - warnSpy.mockRestore(); + cap.restore(); fs.rmSync(tempDir, { recursive: true, force: true }); } }); @@ -383,7 +393,7 @@ describe('worker pool integration', () => { `, ); - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + const cap = _captureLogger(); pool = createWorkerPool(pathToFileURL(workerPath) as URL, 1, { subBatchSize: 2, subBatchIdleTimeoutMs: 150, @@ -411,9 +421,11 @@ describe('worker pool integration', () => { ]); expect(progressCalls).toEqual([...progressCalls].sort((a, b) => a - b)); expect(progressCalls.at(-1)).toBe(4); - expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining('Splitting into 1/1 item jobs')); + expect( + cap.records().some((r) => String(r.msg ?? '').includes('Splitting into 1/1 item jobs')), + ).toBe(true); } finally { - warnSpy.mockRestore(); + cap.restore(); fs.rmSync(tempDir, { recursive: true, force: true }); } }); @@ -479,7 +491,7 @@ describe('worker pool integration', () => { `, ); - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + const cap = _captureLogger(); pool = createWorkerPool(pathToFileURL(workerPath) as URL, 2, { subBatchSize: 2, subBatchIdleTimeoutMs: 150, @@ -505,9 +517,11 @@ describe('worker pool integration', () => { 'tail-a.ts', 'tail-b.ts', ]); - expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining('Splitting into 1/1 item jobs')); + expect( + cap.records().some((r) => String(r.msg ?? '').includes('Splitting into 1/1 item jobs')), + ).toBe(true); } finally { - warnSpy.mockRestore(); + cap.restore(); fs.rmSync(tempDir, { recursive: true, force: true }); } }); @@ -543,7 +557,7 @@ describe('worker pool integration', () => { `, ); - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + const cap = _captureLogger(); // 2 workers but subBatchSize=4 means all 4 items form 1 job; second worker stays idle. pool = createWorkerPool(pathToFileURL(workerPath) as URL, 2, { subBatchSize: 4, @@ -562,9 +576,9 @@ describe('worker pool integration', () => { const allPaths = results.flatMap((r: any) => r.paths); expect(allPaths.sort()).toEqual(['a.ts', 'b.ts', 'c.ts', 'd.ts']); - expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining('Splitting into')); + expect(cap.records().some((r) => String(r.msg ?? '').includes('Splitting into'))).toBe(true); } finally { - warnSpy.mockRestore(); + cap.restore(); fs.rmSync(tempDir, { recursive: true, force: true }); } }, 15_000); diff --git a/gitnexus/test/unit/analyze-embeddings-limit.test.ts b/gitnexus/test/unit/analyze-embeddings-limit.test.ts index 93978ad9d0..6fbc5af569 100644 --- a/gitnexus/test/unit/analyze-embeddings-limit.test.ts +++ b/gitnexus/test/unit/analyze-embeddings-limit.test.ts @@ -44,17 +44,23 @@ describe('analyzeCommand --embeddings [limit] parsing', () => { it.each(['abc', '-1', '1.5', 'NaN', 'Infinity'])( 'rejects invalid --embeddings value %s before analysis starts', async (embeddings) => { - const errorSpy = vi.spyOn(console, 'error').mockImplementation(() => undefined); + // The validator routes through cli-message (`cliError`), which + // writes plain text directly to process.stderr. Spy on the raw + // stderr handle rather than `console.error`, since the migration + // bypasses console entirely. + const stderrSpy = vi.spyOn(process.stderr, 'write').mockImplementation(() => true); const { analyzeCommand } = await import('../../src/cli/analyze.js'); await analyzeCommand(undefined, { embeddings }); expect(process.exitCode).toBe(1); expect(runFullAnalysisMock).not.toHaveBeenCalled(); - const msg = errorSpy.mock.calls[0]?.[0] ?? ''; - expect(msg).toContain('--embeddings expects a non-negative integer'); - expect(msg).toContain(`got "${embeddings}"`); - errorSpy.mockRestore(); + const allWrites = stderrSpy.mock.calls + .map(([chunk]) => (typeof chunk === 'string' ? chunk : chunk.toString())) + .join(''); + expect(allWrites).toContain('--embeddings expects a non-negative integer'); + expect(allWrites).toContain(`got "${embeddings}"`); + stderrSpy.mockRestore(); }, ); diff --git a/gitnexus/test/unit/analyze-worker-timeout.test.ts b/gitnexus/test/unit/analyze-worker-timeout.test.ts index dcf5a9dce4..3ed3a3d5ed 100644 --- a/gitnexus/test/unit/analyze-worker-timeout.test.ts +++ b/gitnexus/test/unit/analyze-worker-timeout.test.ts @@ -39,15 +39,20 @@ describe('analyzeCommand worker timeout validation', () => { it.each(['0', 'abc', '-5', 'Infinity'])( 'rejects invalid --worker-timeout value %s before analysis starts', async (workerTimeout) => { - const errorSpy = vi.spyOn(console, 'error').mockImplementation(() => undefined); + // Import _captureLogger from the SAME module instance analyze.js will + // see — vi.resetModules() in beforeEach invalidates the singleton. + const { _captureLogger } = await import('../../src/core/logger.js'); + const cap = _captureLogger(); const { analyzeCommand } = await import('../../src/cli/analyze.js'); await analyzeCommand(undefined, { workerTimeout }); expect(process.exitCode).toBe(1); - expect(errorSpy).toHaveBeenCalledWith(' --worker-timeout must be at least 1 second.\n'); + expect( + cap.records().some((r) => r.msg === ' --worker-timeout must be at least 1 second.\n'), + ).toBe(true); expect(runFullAnalysisMock).not.toHaveBeenCalled(); - errorSpy.mockRestore(); + cap.restore(); }, ); diff --git a/gitnexus/test/unit/calltool-dispatch.test.ts b/gitnexus/test/unit/calltool-dispatch.test.ts index aa422327be..f8d94d8903 100644 --- a/gitnexus/test/unit/calltool-dispatch.test.ts +++ b/gitnexus/test/unit/calltool-dispatch.test.ts @@ -71,6 +71,7 @@ vi.mock('../../src/mcp/core/embedder.js', () => ({ import { LocalBackend } from '../../src/mcp/local/local-backend.js'; import { listRegisteredRepos, cleanupOldKuzuFiles } from '../../src/storage/repo-manager.js'; +import { _captureLogger } from '../../src/core/logger.js'; import { initLbug, executeQuery, @@ -194,7 +195,7 @@ describe('LocalBackend.callTool', () => { }); it('skips vector index query when VECTOR is unsupported by the platform', async () => { - const consoleError = vi.spyOn(console, 'error').mockImplementation(() => undefined); + const cap = _captureLogger(); platformMocks.isVectorExtensionSupportedByPlatform.mockReturnValue(false); (executeQuery as any).mockImplementation(async (_repoId: string, cypher: string) => { if (cypher.includes('COUNT(*) AS cnt')) return [{ cnt: 1 }]; @@ -217,13 +218,17 @@ describe('LocalBackend.callTool', () => { cypher.includes('e.embedding AS embedding'), ), ).toBe(true); - expect(consoleError).toHaveBeenCalledWith( - expect.stringContaining( - 'GitNexus [query:vector]: VECTOR extension not supported on this platform', - ), - ); + expect( + cap + .records() + .some((r) => + String(r.msg ?? '').includes( + 'GitNexus [query:vector]: VECTOR extension not supported on this platform', + ), + ), + ).toBe(true); } finally { - consoleError.mockRestore(); + cap.restore(); } }); @@ -835,7 +840,7 @@ describe('LocalBackend.resolveRepo', () => { hint: '⚠️ stale sibling clone', }); - const errSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); + const cap = _captureLogger(); try { await backend.init(); @@ -846,13 +851,15 @@ describe('LocalBackend.resolveRepo', () => { await backend.resolveRepo(); await backend.resolveRepo(); - const drift = errSpy.mock.calls.filter((c) => String(c[0]).includes('stale sibling clone')); + const drift = cap + .records() + .filter((r) => String(r.msg ?? '').includes('stale sibling clone')); expect(drift).toHaveLength(1); // checkCwdMatch should also only run once — the cache check // happens BEFORE the shellout-heavy match call. expect(checkCwdMatch).toHaveBeenCalledTimes(1); } finally { - errSpy.mockRestore(); + cap.restore(); (checkCwdMatch as any).mockResolvedValue({ match: 'none' }); } }); diff --git a/gitnexus/test/unit/cli-message.test.ts b/gitnexus/test/unit/cli-message.test.ts new file mode 100644 index 0000000000..321485c378 --- /dev/null +++ b/gitnexus/test/unit/cli-message.test.ts @@ -0,0 +1,99 @@ +/** + * Unit tests for `gitnexus/src/cli/cli-message.ts`. + * + * cli-message is the helper for user-facing CLI banners and error guidance. + * The contract: each call writes plain text to stderr AND emits a + * structured pino record through the singleton logger. + * + * Tests verify both halves of the tee, plus shape contracts (newline + * handling, structured fields, tee survival across messages with + * embedded newlines). + */ +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; +import { cliInfo, cliWarn, cliError } from '../../src/cli/cli-message.js'; +import { _captureLogger, type LoggerCapture } from '../../src/core/logger.js'; + +describe('cli-message — stderr + logger tee', () => { + let cap: LoggerCapture; + let stderrSpy: ReturnType; + + beforeEach(() => { + cap = _captureLogger(); + stderrSpy = vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + }); + + afterEach(() => { + stderrSpy.mockRestore(); + cap.restore(); + }); + + it('cliInfo writes plain text to stderr and emits a structured info record', () => { + cliInfo('hello'); + // Plain stderr write + const stderrCalls = stderrSpy.mock.calls.map(([chunk]) => + typeof chunk === 'string' ? chunk : chunk.toString(), + ); + expect(stderrCalls).toContain('hello\n'); + // Structured logger record + const records = cap.records(); + expect(records.some((r) => r.msg === 'hello' && r.level === 30)).toBe(true); + }); + + it('cliWarn writes to stderr and emits at warn level (40)', () => { + cliWarn('caution'); + const stderrCalls = stderrSpy.mock.calls.map(([chunk]) => + typeof chunk === 'string' ? chunk : chunk.toString(), + ); + expect(stderrCalls).toContain('caution\n'); + const records = cap.records(); + expect(records.some((r) => r.msg === 'caution' && r.level === 40)).toBe(true); + }); + + it('cliError writes to stderr and emits at error level (50) with structured fields', () => { + cliError('boom', { code: 'EADDRINUSE', port: 4747 }); + const stderrCalls = stderrSpy.mock.calls.map(([chunk]) => + typeof chunk === 'string' ? chunk : chunk.toString(), + ); + expect(stderrCalls).toContain('boom\n'); + const records = cap.records(); + const errorRecord = records.find((r) => r.msg === 'boom' && r.level === 50); + expect(errorRecord).toBeDefined(); + expect(errorRecord?.code).toBe('EADDRINUSE'); + expect(errorRecord?.port).toBe(4747); + }); + + it('does not double-newline an already-newlined message', () => { + cliInfo('already-terminated\n'); + const stderrCalls = stderrSpy.mock.calls.map(([chunk]) => + typeof chunk === 'string' ? chunk : chunk.toString(), + ); + // Exactly one trailing \n, not two. + expect(stderrCalls).toContain('already-terminated\n'); + expect(stderrCalls.includes('already-terminated\n\n')).toBe(false); + }); + + it('preserves embedded newlines in multi-line messages (does not split into multiple records)', () => { + cliError('line one\nline two\nline three'); + const stderrCalls = stderrSpy.mock.calls.map(([chunk]) => + typeof chunk === 'string' ? chunk : chunk.toString(), + ); + // The whole multi-line block goes to stderr in one write, with a + // trailing newline appended. + expect(stderrCalls).toContain('line one\nline two\nline three\n'); + // The structured record carries the full message as a single field. + const records = cap.records(); + expect(records.some((r) => r.msg === 'line one\nline two\nline three' && r.level === 50)).toBe( + true, + ); + }); + + it('handles an empty message — stderr gets a bare newline, logger gets msg:""', () => { + cliInfo(''); + const stderrCalls = stderrSpy.mock.calls.map(([chunk]) => + typeof chunk === 'string' ? chunk : chunk.toString(), + ); + expect(stderrCalls).toContain('\n'); + const records = cap.records(); + expect(records.some((r) => r.msg === '' && r.level === 30)).toBe(true); + }); +}); diff --git a/gitnexus/test/unit/group/grpc-extractor.test.ts b/gitnexus/test/unit/group/grpc-extractor.test.ts index a586b5c0d4..b128c6ddfa 100644 --- a/gitnexus/test/unit/group/grpc-extractor.test.ts +++ b/gitnexus/test/unit/group/grpc-extractor.test.ts @@ -1,4 +1,4 @@ -import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; +import { describe, it, expect, beforeEach, afterEach } from 'vitest'; import * as fs from 'node:fs'; import fsp from 'node:fs/promises'; import * as path from 'node:path'; @@ -11,6 +11,7 @@ import { } from '../../../src/core/group/extractors/grpc-extractor.js'; import type { ProtoServiceInfo } from '../../../src/core/group/extractors/grpc-extractor.js'; import type { RepoHandle } from '../../../src/core/group/types.js'; +import { _captureLogger } from '../../../src/core/logger.js'; describe('GrpcExtractor', () => { let tmpDir: string; @@ -797,18 +798,18 @@ describe('resolveProtoConflict', () => { }); it('test_all_zero_tie_returns_null', () => { - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + const cap = _captureLogger(); const candidates = [ makeInfo('pkgA', 'totally/unrelated/a/svc.proto'), makeInfo('pkgB', 'completely/different/b/svc.proto'), ]; const result = resolveProtoConflict('Svc', 'src/main.go', candidates); expect(result).toBeNull(); - warnSpy.mockRestore(); + cap.restore(); }); it('test_positive_score_tie_returns_null', () => { - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + const cap = _captureLogger(); // Both candidates share `src/proto` with the source dir — equal shared runs. const candidates = [ makeInfo('pkgA', 'src/proto/a/svc.proto'), @@ -816,11 +817,11 @@ describe('resolveProtoConflict', () => { ]; const result = resolveProtoConflict('Svc', 'src/proto/main.go', candidates); expect(result).toBeNull(); - warnSpy.mockRestore(); + cap.restore(); }); it('test_three_way_zero_tie_returns_null', () => { - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + const cap = _captureLogger(); const candidates = [ makeInfo('pkgA', 'aaa/svc.proto'), makeInfo('pkgB', 'bbb/svc.proto'), @@ -828,7 +829,7 @@ describe('resolveProtoConflict', () => { ]; const result = resolveProtoConflict('Svc', 'src/main.go', candidates); expect(result).toBeNull(); - warnSpy.mockRestore(); + cap.restore(); }); it('test_unique_winner_among_ties', () => { @@ -843,19 +844,19 @@ describe('resolveProtoConflict', () => { }); it('test_ambiguous_emits_single_warn_with_service_and_paths', () => { - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + const cap = _captureLogger(); const candidates = [ makeInfo('pkgA', 'totally/unrelated/a/svc.proto'), makeInfo('pkgB', 'completely/different/b/svc.proto'), ]; resolveProtoConflict('MyService', 'src/main.go', candidates); - expect(warnSpy).toHaveBeenCalledTimes(1); - const msg = String(warnSpy.mock.calls[0][0]); + expect(cap.records().length).toBe(1); + const msg = String(String(cap.records()[0]?.msg ?? '')); expect(msg).toContain('MyService'); expect(msg).toContain('src/main.go'); expect(msg).toContain('totally/unrelated/a/svc.proto'); expect(msg).toContain('completely/different/b/svc.proto'); - warnSpy.mockRestore(); + cap.restore(); }); }); @@ -879,7 +880,7 @@ describe('GrpcExtractor.extract ambiguous proto resolution', () => { }); it('test_ambiguous_short_name_across_unrelated_protos_yields_no_source_contract', async () => { - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + const cap = _captureLogger(); // Two unrelated proto files defining the same short name `UserService` in // unrelated directories, neither sharing path segments with the Go source. await fsp.mkdir(path.join(tmpDir, 'billing-team', 'proto'), { recursive: true }); @@ -906,8 +907,8 @@ describe('GrpcExtractor.extract ambiguous proto resolution', () => { (c) => c.meta.source === 'go_client' && c.meta.service === 'UserService', ); expect(sourceContracts).toHaveLength(0); - expect(warnSpy).toHaveBeenCalled(); - warnSpy.mockRestore(); + expect(cap.records().length).toBeGreaterThan(0); + cap.restore(); }); }); diff --git a/gitnexus/test/unit/group/rust-workspace-extractor.test.ts b/gitnexus/test/unit/group/rust-workspace-extractor.test.ts index a9e277c361..3dd958ebf2 100644 --- a/gitnexus/test/unit/group/rust-workspace-extractor.test.ts +++ b/gitnexus/test/unit/group/rust-workspace-extractor.test.ts @@ -3,6 +3,7 @@ import fs from 'node:fs/promises'; import path from 'node:path'; import os from 'node:os'; import { extractRustWorkspaceLinks } from '../../../src/core/group/extractors/rust-workspace-extractor.js'; +import { _captureLogger } from '../../../src/core/logger.js'; describe('RustWorkspaceExtractor', () => { let tmpDir: string; @@ -229,19 +230,17 @@ describe('RustWorkspaceExtractor', () => { ['consumer', path.join(tmpDir, 'consumer')], ]); - const warnings: string[] = []; - const origWarn = console.warn; - console.warn = (...args: unknown[]) => { - warnings.push(String(args[0])); - }; + const cap = _captureLogger(); try { const result = await extractRustWorkspaceLinks(repos, repoPaths); - expect(warnings.some((w) => w.includes('duplicate crate name "shared"'))).toBe(true); + expect( + cap.records().some((r) => String(r.msg ?? '').includes('duplicate crate name "shared"')), + ).toBe(true); expect(result.links).toHaveLength(1); expect(result.links[0].from).toBe('a'); } finally { - console.warn = origWarn; + cap.restore(); } }); diff --git a/gitnexus/test/unit/group/sync.test.ts b/gitnexus/test/unit/group/sync.test.ts index 17bd1c45d6..88bc3af2dc 100644 --- a/gitnexus/test/unit/group/sync.test.ts +++ b/gitnexus/test/unit/group/sync.test.ts @@ -3,6 +3,7 @@ import * as fs from 'node:fs'; import * as path from 'node:path'; import * as os from 'node:os'; import { syncGroup, stableRepoPoolId } from '../../../src/core/group/sync.js'; +import { _captureLogger } from '../../../src/core/logger.js'; import type { GroupConfig, StoredContract, @@ -650,9 +651,7 @@ service OrderService { matching: { bm25_threshold: 0.7, embedding_threshold: 0.65, max_candidates_per_step: 3 }, }; - const warnings: string[] = []; - const origWarn = console.warn; - console.warn = (msg: string) => warnings.push(String(msg)); + const cap = _captureLogger(); try { const result = await syncGroup(config, { extractorOverride: async () => [], @@ -664,9 +663,9 @@ service OrderService { expect(result.crossLinks[0].to.symbolUid).toBe( 'manifest::app/dangling::http::POST::/api/missing', ); - expect(warnings.some((w) => w.includes('app/dangling'))).toBe(true); + expect(cap.records().some((r) => String(r.msg ?? '').includes('app/dangling'))).toBe(true); } finally { - console.warn = origWarn; + cap.restore(); } }); diff --git a/gitnexus/test/unit/ignore-service.test.ts b/gitnexus/test/unit/ignore-service.test.ts index de32eb8d99..b4e5cdca18 100644 --- a/gitnexus/test/unit/ignore-service.test.ts +++ b/gitnexus/test/unit/ignore-service.test.ts @@ -1,4 +1,4 @@ -import { describe, it, expect, beforeAll, beforeEach, afterAll, afterEach, vi } from 'vitest'; +import { describe, it, expect, beforeAll, beforeEach, afterAll, afterEach } from 'vitest'; import fs from 'fs/promises'; import path from 'path'; import os from 'os'; @@ -8,6 +8,7 @@ import { loadIgnoreRules, createIgnoreFilter, } from '../../src/config/ignore-service.js'; +import { _captureLogger } from '../../src/core/logger.js'; describe('shouldIgnorePath', () => { describe('version control directories', () => { @@ -574,13 +575,13 @@ describe('loadIgnoreRules — error handling', () => { await fs.writeFile(gitignorePath, 'data/\n'); await fs.chmod(gitignorePath, 0o000); - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + const cap = _captureLogger(); const result = await loadIgnoreRules(tmpDir); // Should still return (null or partial), not throw expect(result).toBeNull(); - expect(warnSpy).toHaveBeenCalledWith(expect.stringContaining('.gitignore')); + expect(cap.records().some((r) => String(r.msg ?? '').includes('.gitignore'))).toBe(true); - warnSpy.mockRestore(); + cap.restore(); await fs.chmod(gitignorePath, 0o644); await fs.unlink(gitignorePath); }, diff --git a/gitnexus/test/unit/logger.test.ts b/gitnexus/test/unit/logger.test.ts new file mode 100644 index 0000000000..7d92d40c5d --- /dev/null +++ b/gitnexus/test/unit/logger.test.ts @@ -0,0 +1,279 @@ +/** + * Unit tests for src/core/logger.ts. + * + * Asserts the wiring rather than re-deriving pino's output format: + * - createLogger returns level-method API + * - debugEnvVar opt promotes level to 'debug' when env truthy + * - destination opt redirects output (test-capture pattern) + * - Error.message === undefined does not throw + * - CR/LF/U+2028/ANSI in field values produce a single NDJSON line + * + * The pretty-printing branch is exercised indirectly: VITEST=true (which + * vitest sets automatically) means shouldUsePretty() returns false, so + * tests run with raw NDJSON — exactly the operator-CI behavior. + */ +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; +import { + createLogger, + logger, + MemoryWritable, + _captureLogger, + _tryBuildPrettyTransport, + _resetPrettyAvailableCache, + flushLoggerSync, +} from '../../src/core/logger.js'; + +describe('createLogger — API surface', () => { + it('returns an object with the standard level methods', () => { + const dest = new MemoryWritable(); + const log = createLogger('test', { destination: dest }); + expect(typeof log.warn).toBe('function'); + expect(typeof log.error).toBe('function'); + expect(typeof log.debug).toBe('function'); + expect(typeof log.info).toBe('function'); + expect(typeof log.fatal).toBe('function'); + expect(typeof log.trace).toBe('function'); + }); + + it('default singleton logger exposes the same API', () => { + expect(typeof logger.warn).toBe('function'); + expect(typeof logger.error).toBe('function'); + }); +}); + +describe('createLogger — debugEnvVar gating', () => { + const ENV = 'TEST_PINO_DEBUG_VAR'; + + beforeEach(() => { + delete process.env[ENV]; + }); + + afterEach(() => { + delete process.env[ENV]; + }); + + it('without debugEnvVar, .debug() emits nothing (default info level)', () => { + const dest = new MemoryWritable(); + const log = createLogger('t', { destination: dest }); + log.debug('should not appear'); + expect(dest.records()).toEqual([]); + }); + + it('with debugEnvVar set but env unset, .debug() emits nothing', () => { + const dest = new MemoryWritable(); + const log = createLogger('t', { debugEnvVar: ENV, destination: dest }); + log.debug('should not appear'); + expect(dest.records()).toEqual([]); + }); + + it('with debugEnvVar set and env truthy, .debug() emits a record', () => { + process.env[ENV] = '1'; + const dest = new MemoryWritable(); + const log = createLogger('t', { debugEnvVar: ENV, destination: dest }); + log.debug({ key: 'value' }, 'debug-msg'); + const records = dest.records() as Array>; + expect(records.length).toBe(1); + expect(records[0].msg).toBe('debug-msg'); + expect(records[0].key).toBe('value'); + expect(records[0].name).toBe('t'); + }); + + it('treats env values "0", "false", "no", "off" as falsy', () => { + for (const falsy of ['0', 'false', 'FALSE', 'no', 'off', '']) { + process.env[ENV] = falsy; + const dest = new MemoryWritable(); + const log = createLogger('t', { debugEnvVar: ENV, destination: dest }); + log.debug('hidden'); + expect(dest.records(), `value=${JSON.stringify(falsy)}`).toEqual([]); + } + }); +}); + +describe('createLogger — structured output safety', () => { + it('captures .warn output as parseable NDJSON in destination', () => { + const dest = new MemoryWritable(); + const log = createLogger('cap', { destination: dest }); + log.warn({ groupDir: '/tmp/x', attempts: 3 }, 'gave up'); + const records = dest.records() as Array>; + expect(records.length).toBe(1); + expect(records[0].msg).toBe('gave up'); + expect(records[0].name).toBe('cap'); + expect(records[0].groupDir).toBe('/tmp/x'); + expect(records[0].attempts).toBe(3); + expect(records[0].level).toBe(40); // pino's numeric warn level + }); + + it('handles Error with undefined message without throwing', () => { + const dest = new MemoryWritable(); + const log = createLogger('cap', { destination: dest }); + const err = new Error('original'); + Object.assign(err, { message: undefined }); + expect(() => log.warn({ err }, 'with bad error')).not.toThrow(); + const records = dest.records(); + expect(records.length).toBe(1); + }); + + it('CR/LF in a string field stays inside one NDJSON record', () => { + const dest = new MemoryWritable(); + const log = createLogger('cap', { destination: dest }); + const evil = '/tmp/group\r\n2026-01-01 [bridge-db] FAKE INJECTED LINE'; + log.warn({ groupDir: evil }, 'msg'); + // Exactly one record. The internal \r\n is JSON-escaped, not a record boundary. + expect(dest.records().length).toBe(1); + // Raw text has trailing newline as record terminator — count of \n == 1. + expect( + dest + .text() + .split('\n') + .filter((l) => l.length > 0).length, + ).toBe(1); + }); + + it('U+2028 / U+2029 in a string field stays inside one NDJSON record', () => { + const dest = new MemoryWritable(); + const log = createLogger('cap', { destination: dest }); + const evil = 'before
after
more'; + log.warn({ field: evil }, 'msg'); + // Same record-count invariant. JSON.parse round-trips the codepoints. + expect(dest.records().length).toBe(1); + const rec = dest.records()[0] as Record; + expect(rec.field).toBe(evil); + }); + + it('ANSI escape sequence in a string field stays inside one NDJSON record', () => { + const dest = new MemoryWritable(); + const log = createLogger('cap', { destination: dest }); + const ansi = 'RED'; + log.warn({ msg2: ansi }, 'msg'); + expect(dest.records().length).toBe(1); + }); +}); + +describe('_captureLogger — lifecycle', () => { + it('captures records emitted via the default logger singleton', () => { + const cap = _captureLogger(); + try { + logger.warn({ k: 'v' }, 'captured'); + const recs = cap.records(); + expect(recs.length).toBe(1); + expect(recs[0].msg).toBe('captured'); + expect(recs[0].k).toBe('v'); + } finally { + cap.restore(); + } + }); + + it('restore() stops further writes from reaching the captured stream', () => { + const cap = _captureLogger(); + logger.warn('first'); + cap.restore(); + // After restore, the singleton routes back to the real (stderr) + // destination. The captured stream should still hold only the first + // record — the second logger.warn must not show up here. + logger.warn('second'); + const recs = cap.records(); + expect(recs.length).toBe(1); + expect(recs[0].msg).toBe('first'); + }); + + it('throws when called twice without restore() — guards against silent state corruption', () => { + const cap = _captureLogger(); + try { + expect(() => _captureLogger()).toThrow(/previous capture is still active/); + } finally { + cap.restore(); + } + }); + + it('can re-capture after restore()', () => { + const cap1 = _captureLogger(); + cap1.restore(); + const cap2 = _captureLogger(); + try { + logger.warn('after-recapture'); + expect(cap2.records().some((r) => r.msg === 'after-recapture')).toBe(true); + } finally { + cap2.restore(); + } + }); +}); + +describe('_tryBuildPrettyTransport — pino-pretty availability probe', () => { + beforeEach(() => { + _resetPrettyAvailableCache(); + }); + + afterEach(() => { + _resetPrettyAvailableCache(); + }); + + it('returns transport options when pino-pretty resolves (the production install path)', () => { + // pino-pretty is a runtime dep (PR #1336 Codex P1 fix), so under any + // normal vitest run the probe should succeed and yield a target + + // destination:2 transport spec. This is the happy path. + const transport = _tryBuildPrettyTransport(); + expect(transport).toBeDefined(); + // Pino accepts a single transport object or a multi-target shape; we + // emit the single-target form, so narrow before asserting. + if (transport && typeof transport === 'object' && 'target' in transport) { + expect(transport.target).toBe('pino-pretty'); + expect(transport.options).toMatchObject({ + destination: 2, + colorize: true, + }); + } else { + throw new Error('expected single-target transport options shape with target=pino-pretty'); + } + }); + + it('memoizes the resolve result — repeat calls do not re-probe', () => { + // Probe once, then again — both should return the same shape and the + // cache should make the second call zero-cost. We can't observe the + // resolve count from outside, but we can assert the second call's + // result is structurally identical and that the warning is not + // double-emitted (covered by the next test). + const first = _tryBuildPrettyTransport(); + const second = _tryBuildPrettyTransport(); + expect(second).toEqual(first); + }); + + it('flushLoggerSync is callable without throwing whether or not the destination has been used', () => { + // The contract: shutdown handlers can call this unconditionally before + // process.exit and it is safe even when no logger has emitted yet. + expect(() => flushLoggerSync()).not.toThrow(); + // After a logger emit, still safe to call. + logger.info('warm the destination'); + expect(() => flushLoggerSync()).not.toThrow(); + }); + + it('emits at most one stderr warning across many calls when pino-pretty is missing', () => { + // Simulate the missing-module path by stubbing process.stderr.write + // and forcing the cache to "not available". This validates the + // one-time-warning contract: 100 calls produce 0 or 1 warning lines, + // never 100. + const stderrSpy = vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + try { + // Inject negative cache state by monkey-patching require.resolve + // would be brittle. Instead, exercise the actual cache: after a + // successful resolve, no warning fires. Then for the missing path, + // we rely on the structural guarantee that warningEmitted state is + // module-level and only one branch can fire it. This test asserts + // the upper bound: even under heavy call volume, stderr writes + // attributable to the probe never exceed 1 per process lifetime. + for (let i = 0; i < 100; i++) { + _tryBuildPrettyTransport(); + } + const probeWarnings = stderrSpy.mock.calls.filter(([chunk]) => { + const s = typeof chunk === 'string' ? chunk : chunk.toString(); + return s.includes('pino-pretty unavailable'); + }); + // pino-pretty IS installed in the test env, so the warning never + // fires. The assertion is "<= 1" rather than "=== 0" so the test + // also passes in a future env where pino-pretty is intentionally + // stripped (the contract still holds). + expect(probeWarnings.length).toBeLessThanOrEqual(1); + } finally { + stderrSpy.mockRestore(); + } + }); +}); diff --git a/gitnexus/test/unit/max-file-size.test.ts b/gitnexus/test/unit/max-file-size.test.ts index 074e148e7c..569b41eab5 100644 --- a/gitnexus/test/unit/max-file-size.test.ts +++ b/gitnexus/test/unit/max-file-size.test.ts @@ -1,4 +1,4 @@ -import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; +import { describe, it, expect, beforeEach, afterEach } from 'vitest'; import { DEFAULT_MAX_FILE_SIZE_BYTES, MAX_FILE_SIZE_UPPER_BOUND_BYTES, @@ -6,15 +6,16 @@ import { getMaxFileSizeBannerMessage, _resetMaxFileSizeWarnings, } from '../../src/core/ingestion/utils/max-file-size.js'; +import { _captureLogger } from '../../src/core/logger.js'; describe('getMaxFileSizeBytes', () => { const ORIGINAL = process.env.GITNEXUS_MAX_FILE_SIZE; - let warnSpy: ReturnType; + let cap: ReturnType; beforeEach(() => { delete process.env.GITNEXUS_MAX_FILE_SIZE; _resetMaxFileSizeWarnings(); - warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + cap = _captureLogger(); }); afterEach(() => { @@ -23,43 +24,43 @@ describe('getMaxFileSizeBytes', () => { } else { process.env.GITNEXUS_MAX_FILE_SIZE = ORIGINAL; } - warnSpy.mockRestore(); + cap.restore(); }); it('returns the default when the env var is unset', () => { expect(getMaxFileSizeBytes()).toBe(DEFAULT_MAX_FILE_SIZE_BYTES); - expect(warnSpy).not.toHaveBeenCalled(); + expect(cap.records().length).toBe(0); }); it('parses a positive integer value as KB', () => { process.env.GITNEXUS_MAX_FILE_SIZE = '1024'; expect(getMaxFileSizeBytes()).toBe(1024 * 1024); - expect(warnSpy).not.toHaveBeenCalled(); + expect(cap.records().length).toBe(0); }); it('clamps values above the tree-sitter ceiling', () => { - // One KB above the 32 MB ceiling. const aboveCeilingKb = MAX_FILE_SIZE_UPPER_BOUND_BYTES / 1024 + 1; process.env.GITNEXUS_MAX_FILE_SIZE = String(aboveCeilingKb); expect(getMaxFileSizeBytes()).toBe(MAX_FILE_SIZE_UPPER_BOUND_BYTES); - expect(warnSpy).toHaveBeenCalledTimes(1); - expect(warnSpy.mock.calls[0][0]).toContain('clamping'); + const records = cap.records(); + expect(records.length).toBe(1); + expect(String(records[0].msg)).toContain('clamping'); }); it.each(['abc', '0', '-512', '1.5', 'NaN', ''])( 'falls back to the default and warns on invalid value %s', (raw) => { if (raw === '') { - // Empty string is treated as unset by the util (raw falsy check). process.env.GITNEXUS_MAX_FILE_SIZE = raw; expect(getMaxFileSizeBytes()).toBe(DEFAULT_MAX_FILE_SIZE_BYTES); - expect(warnSpy).not.toHaveBeenCalled(); + expect(cap.records().length).toBe(0); return; } process.env.GITNEXUS_MAX_FILE_SIZE = raw; expect(getMaxFileSizeBytes()).toBe(DEFAULT_MAX_FILE_SIZE_BYTES); - expect(warnSpy).toHaveBeenCalledTimes(1); - expect(warnSpy.mock.calls[0][0]).toContain('must be a positive integer'); + const records = cap.records(); + expect(records.length).toBe(1); + expect(String(records[0].msg)).toContain('must be a positive integer'); }, ); @@ -68,7 +69,7 @@ describe('getMaxFileSizeBytes', () => { getMaxFileSizeBytes(); getMaxFileSizeBytes(); getMaxFileSizeBytes(); - expect(warnSpy).toHaveBeenCalledTimes(1); + expect(cap.records().length).toBe(1); }); it('warns separately for distinct invalid values', () => { @@ -76,20 +77,20 @@ describe('getMaxFileSizeBytes', () => { getMaxFileSizeBytes(); process.env.GITNEXUS_MAX_FILE_SIZE = 'xyz'; getMaxFileSizeBytes(); - expect(warnSpy).toHaveBeenCalledTimes(2); + expect(cap.records().length).toBe(2); }); it('_resetMaxFileSizeWarnings re-enables warnings after reset', () => { process.env.GITNEXUS_MAX_FILE_SIZE = 'abc'; getMaxFileSizeBytes(); - expect(warnSpy).toHaveBeenCalledTimes(1); + expect(cap.records().length).toBe(1); getMaxFileSizeBytes(); - expect(warnSpy).toHaveBeenCalledTimes(1); + expect(cap.records().length).toBe(1); _resetMaxFileSizeWarnings(); getMaxFileSizeBytes(); - expect(warnSpy).toHaveBeenCalledTimes(2); + expect(cap.records().length).toBe(2); }); it('DEFAULT_MAX_FILE_SIZE_BYTES is 512 KB', () => { @@ -99,12 +100,12 @@ describe('getMaxFileSizeBytes', () => { describe('getMaxFileSizeBannerMessage', () => { const ORIGINAL = process.env.GITNEXUS_MAX_FILE_SIZE; - let warnSpy: ReturnType; + let cap: ReturnType; beforeEach(() => { delete process.env.GITNEXUS_MAX_FILE_SIZE; _resetMaxFileSizeWarnings(); - warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + cap = _captureLogger(); }); afterEach(() => { @@ -113,7 +114,7 @@ describe('getMaxFileSizeBannerMessage', () => { } else { process.env.GITNEXUS_MAX_FILE_SIZE = ORIGINAL; } - warnSpy.mockRestore(); + cap.restore(); }); it('returns null when the env var is unset (default threshold)', () => { diff --git a/gitnexus/test/unit/sequential-language-availability.test.ts b/gitnexus/test/unit/sequential-language-availability.test.ts index f48db5778a..bd0e4d4d6f 100644 --- a/gitnexus/test/unit/sequential-language-availability.test.ts +++ b/gitnexus/test/unit/sequential-language-availability.test.ts @@ -19,6 +19,7 @@ import { createSymbolTable } from '../../src/core/ingestion/model/symbol-table.j import { createResolutionContext } from '../../src/core/ingestion/model/resolution-context.js'; import * as parserLoader from '../../src/core/tree-sitter/parser-loader.js'; +import { _captureLogger } from '../../src/core/logger.js'; describe('sequential native parser availability', () => { beforeEach(() => { vi.clearAllMocks(); @@ -43,7 +44,7 @@ describe('sequential native parser availability', () => { }); it('warns when processImports skips files in verbose mode', async () => { - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + const cap = _captureLogger(); const previous = process.env.GITNEXUS_VERBOSE; process.env.GITNEXUS_VERBOSE = '1'; vi.mocked(parserLoader.isLanguageAvailable).mockReturnValue(false); @@ -58,11 +59,17 @@ describe('sequential native parser availability', () => { ['App.swift'], ); - expect(warnSpy).toHaveBeenCalledWith( - '[ingestion] Skipped 1 swift file(s) in import processing — swift parser not available.', - ); - - warnSpy.mockRestore(); + expect( + cap + .records() + .some( + (r) => + r.msg === + '[ingestion] Skipped 1 swift file(s) in import processing — swift parser not available.', + ), + ).toBe(true); + + cap.restore(); if (previous === undefined) { delete process.env.GITNEXUS_VERBOSE; } else { @@ -86,7 +93,7 @@ describe('sequential native parser availability', () => { }); it('warns when processCalls skips files in verbose mode', async () => { - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + const cap = _captureLogger(); const previous = process.env.GITNEXUS_VERBOSE; process.env.GITNEXUS_VERBOSE = '1'; vi.mocked(parserLoader.isLanguageAvailable).mockReturnValue(false); @@ -98,11 +105,17 @@ describe('sequential native parser availability', () => { createResolutionContext(), ); - expect(warnSpy).toHaveBeenCalledWith( - '[ingestion] Skipped 1 swift file(s) in call processing — swift parser not available.', - ); - - warnSpy.mockRestore(); + expect( + cap + .records() + .some( + (r) => + r.msg === + '[ingestion] Skipped 1 swift file(s) in call processing — swift parser not available.', + ), + ).toBe(true); + + cap.restore(); if (previous === undefined) { delete process.env.GITNEXUS_VERBOSE; } else { @@ -126,7 +139,7 @@ describe('sequential native parser availability', () => { }); it('warns when processHeritage skips files in verbose mode', async () => { - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + const cap = _captureLogger(); const previous = process.env.GITNEXUS_VERBOSE; process.env.GITNEXUS_VERBOSE = '1'; vi.mocked(parserLoader.isLanguageAvailable).mockReturnValue(false); @@ -138,11 +151,17 @@ describe('sequential native parser availability', () => { createResolutionContext(), ); - expect(warnSpy).toHaveBeenCalledWith( - '[ingestion] Skipped 1 swift file(s) in heritage processing — swift parser not available.', - ); - - warnSpy.mockRestore(); + expect( + cap + .records() + .some( + (r) => + r.msg === + '[ingestion] Skipped 1 swift file(s) in heritage processing — swift parser not available.', + ), + ).toBe(true); + + cap.restore(); if (previous === undefined) { delete process.env.GITNEXUS_VERBOSE; } else { @@ -166,7 +185,7 @@ describe('sequential native parser availability', () => { }); it('warns when processParsing skips files in verbose mode', async () => { - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + const cap = _captureLogger(); const previous = process.env.GITNEXUS_VERBOSE; process.env.GITNEXUS_VERBOSE = '1'; vi.mocked(parserLoader.isLanguageAvailable).mockReturnValue(false); @@ -178,11 +197,17 @@ describe('sequential native parser availability', () => { createASTCache(), ); - expect(warnSpy).toHaveBeenCalledWith( - '[ingestion] Skipped 1 swift file(s) in parsing processing — swift parser not available.', - ); - - warnSpy.mockRestore(); + expect( + cap + .records() + .some( + (r) => + r.msg === + '[ingestion] Skipped 1 swift file(s) in parsing processing — swift parser not available.', + ), + ).toBe(true); + + cap.restore(); if (previous === undefined) { delete process.env.GITNEXUS_VERBOSE; } else { diff --git a/gitnexus/test/unit/web-ui-serving.test.ts b/gitnexus/test/unit/web-ui-serving.test.ts index d3f0854227..bd1c7faaf2 100644 --- a/gitnexus/test/unit/web-ui-serving.test.ts +++ b/gitnexus/test/unit/web-ui-serving.test.ts @@ -2,6 +2,7 @@ import path from 'node:path'; import http from 'node:http'; import express from 'express'; import { describe, expect, it, vi, beforeEach } from 'vitest'; +import { _captureLogger } from '../../src/core/logger.js'; const { accessMock } = vi.hoisted(() => ({ accessMock: vi.fn(), @@ -213,7 +214,7 @@ describe('resolveWebDistDir', () => { }); it('warns on non-ENOENT errors but continues', async () => { - const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + const cap = _captureLogger(); accessMock.mockImplementation(async (p: string) => { if (p.includes('primary')) throw Object.assign(new Error('permission denied'), { code: 'EACCES' }); @@ -222,11 +223,16 @@ describe('resolveWebDistDir', () => { }); const result = await resolveWebDistDir('/primary', '/fallback'); expect(result).toBe('/fallback'); - expect(warnSpy).toHaveBeenCalledWith( - expect.stringContaining('could not access web UI dir /primary'), - 'permission denied', - ); - warnSpy.mockRestore(); + expect( + cap + .records() + .some( + (r) => + String(r.msg ?? '').includes('could not access web UI dir /primary') && + r.err === 'permission denied', + ), + ).toBe(true); + cap.restore(); }); it('prefers GITNEXUS_WEB_DIST env var when set', async () => {