Repository navigation
docs(logging): add contributor logging guidelines #1758
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Merged
Merged
Changes from all commits
Commits
File filter
Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Large diffs are not rendered by default.
Oops, something went wrong.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,147 @@ | ||
| # Logging Guidelines | ||
|
|
||
| How NeuroLink logs, and what a contributor has to get right. This documents the | ||
| convention the codebase already follows — it is not a proposal to change it. | ||
|
|
||
| ## The logger | ||
|
|
||
| Import the shared logger. Never call `console.*` in `src/`: ESLint's | ||
| `no-console` rule fails the build for `console.log`, and the exceptions for | ||
| `warn`/`error`/`info` exist for a handful of legacy call sites, not as an | ||
| invitation. | ||
|
|
||
| ```typescript | ||
| import { logger } from "../utils/logger.js"; | ||
| ``` | ||
|
|
||
| There is one logger for the whole process. `logger.setEventEmitter()` attaches | ||
| the process-wide sink; per-instance events reach a worker only through its | ||
| `onLog` bridge (see [per-instance routing](#per-instance-routing) below). | ||
|
|
||
| ## Levels | ||
|
|
||
| | Level | Use for | | ||
| | ------- | ------------------------------------------------------------------------------------------------------------------------------------------ | | ||
| | `debug` | Routine operation: request construction, cache hits, resolution steps, internal state. The default for anything that fires per request. | | ||
| | `info` | Events an operator would want in a quiet log: a server binding, a provider registering, an MCP server connecting. Not per-request chatter. | | ||
| | `warn` | Something recoverable happened and the code carried on: a retry, a fallback, a deprecated option, a degraded capability. | | ||
| | `error` | An operation failed, or a failure was swallowed and the caller will not see it. | | ||
|
|
||
| `logger.always()` bypasses level filtering and writes to the console | ||
| unconditionally. It is **CLI output**, not logging — user-facing text that must | ||
| appear regardless of `--debug`. Of ~2,260 call sites, ~2,150 are in `src/cli/`. | ||
| Do not reach for it in `src/lib/`. | ||
|
|
||
| ### Nothing below `error` is visible by default | ||
|
|
||
| `shouldLog()` suppresses every level except `error` unless debug mode is on | ||
| (`--debug`, or `NEUROLINK_DEBUG=true`). `NEUROLINK_LOG_LEVEL` then sets the | ||
| floor within debug mode. Two consequences worth internalising: | ||
|
|
||
| - A `debug` log is not emitted in a normal run, but its arguments are still | ||
| evaluated. Prefer `debug` over silence. | ||
| - A condition a user must act on cannot be reported at `warn` alone — they will | ||
| never see it. Either raise it to `error` or surface it on the result object. | ||
|
|
||
| ### Choosing between `warn` and `debug` | ||
|
|
||
| The common mistake is logging an ordinary outcome at `warn`. If a branch is | ||
| reached on a healthy request, it is `debug`, however unwelcome it looks locally. | ||
| `FileDetector` is the worked example: a detection that lands below the | ||
| confidence threshold is the normal case for most files, so it logs at `debug` | ||
| and says so in a comment. A detection where _no_ strategy identified a type at | ||
| all is a genuine failure, and logs at `error`. | ||
|
|
||
| ## Format | ||
|
|
||
| Pass a message and a structured data object. The message is a constant; the | ||
| variables go in the object, where a log consumer can index them. | ||
|
|
||
| ```typescript | ||
| // Good | ||
| logger.debug("[OpenAI] Request built", { | ||
| provider: this.providerName, | ||
| model, | ||
| toolCount: tools.length, | ||
| }); | ||
|
|
||
| // Avoid — nothing downstream can filter on this | ||
| logger.debug(`[OpenAI] Built request for ${model} with ${tools.length} tools`); | ||
| ``` | ||
|
|
||
| Prefix the message with the emitting component in brackets — `[NeuroLink]`, | ||
| `[OpenAI]`, `[FileDetector]`, `[MCP]`. Grepping a debug run is how most of this | ||
| gets read. | ||
|
|
||
| Template literals are not banned, and a short one carrying a single value is | ||
| fine. What matters is that a value a consumer would want to filter on ends up in | ||
| the data object rather than baked into the message string. | ||
|
|
||
| ## Guard expensive serialization | ||
|
|
||
| `logger.debug(...)` evaluates its arguments before `shouldLog()` ever runs, so a | ||
| `JSON.stringify` of a large payload costs full price on every request even when | ||
| nothing is logged. Guard it: | ||
|
|
||
| ```typescript | ||
| if (logger.shouldLog("debug")) { | ||
| logger.debug("[Provider] Full response", { | ||
| body: safeDebugSerialize(response), | ||
| }); | ||
| } | ||
| ``` | ||
|
|
||
| The guard is only needed for work that is expensive to produce. Passing an | ||
| object you already hold is free — the logger does not serialize it unless it | ||
| emits. | ||
|
|
||
| ## Never log secrets | ||
|
|
||
| API keys, tokens, credentials, presigned URL query strings, user prompt content | ||
| and absolute host paths must not reach a log or a thrown error message. | ||
| `src/lib/utils/logSanitize.ts` has the helpers, and they are the reason several | ||
| past leaks are closed: | ||
|
|
||
| | Helper | Use for | | ||
| | --------------------------- | ------------------------------------------------------------------------------------------ | | ||
| | `redactUrlForError(url)` | A URL in a log or error — strips query and fragment, so a presigned token cannot survive. | | ||
| | `redactUrlCredentials` | A URL that may carry `user:password@`. | | ||
| | `redactPathFromMessage` | A filesystem path in a message. | | ||
| | `sanitizeErrorCause` | An error from Node/undici — these embed the full request URL or path in their own message. | | ||
| | `sanitizeHeaders` | A header bag before logging it. | | ||
| | `sanitizeRecord` | An arbitrary object, with string truncation. | | ||
| | `safeDebugSerialize` | A large value in a debug log, length-capped. | | ||
| | `transformParamsForLogging` | Tool-call parameters before logging them (this one lives in `transformationUtils.ts`). | | ||
|
|
||
| The rule for errors is the same as for logs: an error message is read by more | ||
| people than a log line, not fewer. | ||
|
|
||
| ## Per-instance routing | ||
|
|
||
| The logger routes per instance, so a worker's `onLog` bridge | ||
| (`NeuroLink.createWorkerInstance({ onLog })`) receives only that worker's own | ||
| events, not everything in the process. The SDK entry points — `generate`, | ||
| `stream`, `generateText` — run their bodies inside an `AsyncLocalStorage` | ||
| scope carrying the instance's id, so a log call anywhere beneath them is | ||
| attributed without threading an instance through every call site. Two things | ||
| sit outside the scope by construction: logs emitted while a consumer drains a | ||
| returned stream (iteration runs in the consumer's context), and logs emitted | ||
| outside any call — construction, background MCP reconnects, module init — | ||
| which stay unattributed rather than being charged to an arbitrary instance. | ||
|
|
||
| `WorkerInstanceOptions.onLog`'s JSDoc (`src/lib/types/isolatedAgent.ts`) is | ||
| the authoritative description of this behaviour; check it before relying on | ||
| the routing in a new integration. | ||
|
|
||
| A process-wide sink installed with `logger.setEventEmitter()` still receives | ||
| everything either way. | ||
|
|
||
| ## Checklist for a new log call | ||
|
|
||
| - Level matches the table above, and a routine branch is `debug`. | ||
| - Message is a constant with a `[Component]` prefix; variables are in the data | ||
| object. | ||
| - Anything expensive to build is behind `logger.shouldLog("debug")`. | ||
| - No key, token, credential, prompt body, presigned URL or absolute host path | ||
| in either the message or the data — run it through `logSanitize.ts` if in | ||
| doubt. | ||
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,160 @@ | ||
| #!/usr/bin/env tsx | ||
| import "dotenv/config"; | ||
|
|
||
| /** | ||
| * Continuous Test Suite — Logging Guidelines doc accuracy | ||
| * | ||
| * `docs/development/logging-guidelines.md` documents the logger's | ||
| * "Per-instance routing": a log call inside one instance's scope reaches only | ||
| * that instance's sinks, a worker's `onLog` bridge | ||
| * (`NeuroLink.createWorkerInstance({ onLog })`) receives only that worker's | ||
| * own events, logs emitted outside any call stay unattributed, and a | ||
| * process-wide sink (`logger.setEventEmitter`) still receives everything. | ||
| * | ||
| * The suite checks that behaviour against the built SDK's public `logger` and | ||
| * `NeuroLink`, then checks that the guide states it. Every "did not receive" | ||
| * assertion is paired with a sink that must have received the same event, so | ||
| * a probe that never fired cannot pass as isolation. | ||
| * | ||
| * Run: pnpm run build && npx tsx test/continuous-test-suite-logging-guidelines.ts | ||
| * pnpm run test:logging-guidelines | ||
| */ | ||
|
|
||
| import { readFileSync } from "node:fs"; | ||
| import { dirname, resolve } from "node:path"; | ||
| import { fileURLToPath } from "node:url"; | ||
|
|
||
| import { NeuroLink, logger } from "../dist/index.js"; | ||
| import { assert, defineSuite } from "./helpers/harness.js"; | ||
| import { assertDistFresh } from "./helpers/distFreshness.js"; | ||
|
|
||
| // Fail loudly rather than silently testing a stale build (see distFreshness.ts). | ||
| assertDistFresh(); | ||
|
|
||
| const { test, runSuite } = defineSuite("Logging Guidelines doc accuracy", { | ||
| offline: true, | ||
| }); | ||
|
|
||
| const REPO_ROOT = resolve(dirname(fileURLToPath(import.meta.url)), ".."); | ||
| const GUIDE_PATH = resolve(REPO_ROOT, "docs/development/logging-guidelines.md"); | ||
|
|
||
| /** A sink that records the message of every `log-event` it receives. */ | ||
| function recorder(): { | ||
| sink: { emit: (event: string, ...args: unknown[]) => boolean }; | ||
| saw: (marker: string) => boolean; | ||
| } { | ||
| const messages: string[] = []; | ||
| return { | ||
| sink: { | ||
| emit: (event, payload) => { | ||
| if ( | ||
| event === "log-event" && | ||
| typeof payload === "object" && | ||
| payload !== null && | ||
| "message" in payload && | ||
| typeof payload.message === "string" | ||
| ) { | ||
| messages.push(payload.message); | ||
| } | ||
| return true; | ||
| }, | ||
| }, | ||
| saw: (marker) => messages.some((m) => m.includes(marker)), | ||
| }; | ||
| } | ||
|
|
||
| /** The "## Per-instance routing" section's body, up to the next `## ` heading. */ | ||
| function readPerInstanceRoutingSection(): string { | ||
| const md = readFileSync(GUIDE_PATH, "utf8"); | ||
| const start = md.indexOf("## Per-instance routing"); | ||
| assert(start !== -1, "guide is missing a '## Per-instance routing' section"); | ||
| const rest = md.slice(start + "## Per-instance routing".length); | ||
| const nextHeading = rest.indexOf("\n## "); | ||
| return rest.slice(0, nextHeading === -1 ? undefined : nextHeading); | ||
| } | ||
|
|
||
| await runSuite(async () => { | ||
| await test("a log call inside one instance's scope reaches only that instance's sinks", () => { | ||
| const global = recorder(); | ||
| const a = recorder(); | ||
| const b = recorder(); | ||
| const idA = `guide-probe-a-${process.pid}`; | ||
| const idB = `guide-probe-b-${process.pid}`; | ||
| logger.setEventEmitter(global.sink); | ||
| logger.addScopedEventEmitter(idA, a.sink); | ||
| logger.addScopedEventEmitter(idB, b.sink); | ||
| try { | ||
| const marker = `scoped-probe-${Date.now()}`; | ||
| // error is always emitted regardless of NEUROLINK_DEBUG, so the probe | ||
| // does not depend on log-level configuration. | ||
| logger.runInInstanceScope(idA, () => logger.error(`[Test] ${marker}`)); | ||
| assert( | ||
| global.saw(marker), | ||
| "precondition: the process-wide sink must receive the probe", | ||
| ); | ||
| assert( | ||
| a.saw(marker), | ||
| "the scoped instance's own sink did not receive it", | ||
| ); | ||
| assert( | ||
| !b.saw(marker), | ||
| "a sibling instance's sink received another instance's log", | ||
| ); | ||
| } finally { | ||
| logger.removeScopedEventEmitter(idA, a.sink); | ||
| logger.removeScopedEventEmitter(idB, b.sink); | ||
| logger.clearEventEmitter(global.sink); | ||
| } | ||
| }); | ||
|
|
||
| await test("an unscoped log reaches the process-wide sink but no worker's onLog bridge", async () => { | ||
| const host = new NeuroLink(); | ||
| const global = recorder(); | ||
| const heardByA: string[] = []; | ||
| const heardByB: string[] = []; | ||
| const workerA = host.createWorkerInstance({ | ||
| logTag: "probe-A", | ||
| onLog: (event) => heardByA.push(event.message), | ||
| }); | ||
| const workerB = host.createWorkerInstance({ | ||
| logTag: "probe-B", | ||
| onLog: (event) => heardByB.push(event.message), | ||
| }); | ||
| logger.setEventEmitter(global.sink); | ||
| try { | ||
| const marker = `unscoped-probe-${Date.now()}`; | ||
| logger.error(`[Test] ${marker}`); | ||
| assert( | ||
| global.saw(marker), | ||
| "precondition: the process-wide sink must receive the probe", | ||
| ); | ||
| assert( | ||
| !heardByA.some((m) => m.includes(marker)) && | ||
| !heardByB.some((m) => m.includes(marker)), | ||
| "an unattributed log was forwarded to a worker's onLog bridge", | ||
| ); | ||
| } finally { | ||
| logger.clearEventEmitter(global.sink); | ||
| await workerA.dispose?.(); | ||
| await workerB.dispose?.(); | ||
| await host.dispose?.(); | ||
| } | ||
| }); | ||
|
|
||
| await test("the guide states per-instance routing and points at its source of truth", () => { | ||
| const section = readPerInstanceRoutingSection(); | ||
| assert( | ||
| /receives only that worker's own\s+events/.test(section), | ||
| "the Per-instance routing section no longer states what a worker's onLog bridge receives", | ||
| ); | ||
| assert( | ||
| /WorkerInstanceOptions\.onLog/.test(section) && | ||
| /isolatedAgent\.ts/.test(section), | ||
| "the section does not point at WorkerInstanceOptions.onLog's JSDoc (src/lib/types/isolatedAgent.ts)", | ||
| ); | ||
| assert( | ||
| !/not what ships today|until that lands/.test(section), | ||
| "the section still describes per-instance routing as unshipped", | ||
| ); | ||
| }); | ||
| }); |
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Uh oh!
There was an error while loading. Please reload this page.