diff --git a/README.md b/README.md index 02bf166..d420183 100644 --- a/README.md +++ b/README.md @@ -6,48 +6,42 @@ Structured logging with a simple interface, OTLP export, and auto-instrumented H In priority order: -1. **Works everywhere** — Node.js, Bun, Deno and other server runtimes, plus browsers and React Native. Leans on the common JavaScript surface (global `fetch`), with graceful fallbacks where a runtime lacks an API. -2. **A very easy API** — "just log" must stay trivial. Developers pick it up fast without needing to understand OTLP internals. -3. **Composable** — attach to upstream headers/spans/traces and inherit logs, spans and traces between instances. A chameleon that slots into most setups. -4. **Low footprint for the consumer** — small runtime cost and install weight in the consumer's app. Build/codegen steps in *this* library's own development are fine, as long as they don't carry over to consumers. +1. **Works everywhere** — Node.js, Bun, Deno and other server runtimes, plus browsers and React Native. Built on the common JS surface (global `fetch`), with fallbacks where a runtime lacks an API. +2. **A very easy API** — "just log" stays trivial; no need to learn OTLP internals. +3. **Composable** — inherit context/spans/traces between instances and attach to upstream headers/spans/traces. A chameleon that slots into most setups. +4. **Low footprint for the consumer** — small runtime cost and install weight. This library's own build/codegen steps are fine as long as they don't reach consumers. ## Installation -`npm i @larvit/log` or `yarn add @larvit/log` +`npm i @larvit/log` ## Usage ```javascript import { Log } from "@larvit/log"; -const log = new Log("silly"); // Replace "silly" with the minimum log level you want. Defaults to "info" +const log = new Log("silly"); // minimum level to output; defaults to "info" log.error("Apocalypse! :O"); // stderr log.warn("The chaos is near"); // stderr -log.info("All is well, but this message is important"); // stdout -log.verbose("Extra info, likely good in a production environment"); // stdout -log.debug("A lot of detailed logs to debug your application"); // stdout +log.info("All is well, but important"); // stdout +log.verbose("Good in a production environment"); // stdout +log.debug("Detailed debugging logs"); // stdout log.silly("Open the flood gates!"); // stdout ``` -To clone your log instance: `const log2 = log.clone();`. +Clone an instance: `const log2 = log.clone();`. ### Group your logs -To get tracing, timings, spans etc you can group your logs like this example: +For tracing, timings and spans, group logs under a parent: ```javascript import { Log } from "@larvit/log"; -// Creates an outer log context -const appLog = new Log({ - context: { - "service.name": "foobar" - } -}); +const appLog = new Log({ context: { "service.name": "foobar" } }); -// Just an example on a request/response http handler that you want to log async function myRequestHandler(req, res) { - // Creates an inner log context for this specific request + // Inner context for this specific request const reqLog = new Log({ context: { requestId: crypto.randomUUID() }, parentLog: appLog, @@ -56,23 +50,19 @@ async function myRequestHandler(req, res) { reqLog.info("Incoming request", { url: req.url }); - // ... Here be loads of request handler logic ... + // ... request handler logic ... - // Explicitly tell that this inner log is now ended. - // Without this spans and traces does not get sent. - // end() returns a promise; await it when you need delivery guaranteed - // before the process exits (eg. short-lived scripts). Fire-and-forget - // (just `reqLog.end();`) is fine in long-running processes. + // Ends the span/trace and flushes them (without end() they are never sent). Await when you + // need delivery before the process exits (short-lived scripts); fire-and-forget is fine in + // long-running processes. await reqLog.end(); } - ``` ### Trace outgoing HTTP calls -`log.fetch()` is a drop-in for `fetch()` that automatically creates an OpenTelemetry **client span** -for the call (nested under the log's span) and injects a W3C `traceparent` header, so the downstream -service continues the same trace: +`log.fetch()` is a drop-in for `fetch()` that creates an OpenTelemetry **client span** (nested under +the log's span) and injects a W3C `traceparent` header, so the downstream service continues the trace: ```javascript const reqLog = new Log({ otlpHttpBaseURI: "http://127.0.0.1:4318", parentLog: appLog }); @@ -82,40 +72,36 @@ const res = await reqLog.fetch("https://api.example.com/users", { method: "POST" await reqLog.end(); // flushes the spans (the fetch itself never waits on the OTLP export) ``` -The span records the OTel HTTP semantic-convention attributes (`http.request.method`, `url.full`, +It records the OTel HTTP semantic-convention attributes (`http.request.method`, `url.full`, `url.scheme`, `server.address`/`server.port`, `http.response.status_code`, and `error.type` on -failure — its value is the error's `code`, else its `name`, else `"fetch_error"`). 4xx/5xx responses, -and thrown network errors (which are re-thrown unchanged), mark the span as errored. Instrumentation -never changes the call's result. +failure — its `code`, else `name`, else `"fetch_error"`). 4xx/5xx and thrown network errors +(re-thrown unchanged) mark the span errored; the call's result is never altered. Notes: -- **The span is the only output** — `log.fetch` writes no log line. Without `otlpHttpBaseURI` it just - injects the `traceparent` header (still useful: downstream services continue the trace). -- **Delivery:** the span exports in the background, so the call returns as soon as the response is - ready. `await log.end()` delivers every span started by this log — including a fire-and-forget - `log.fetch()` you never awaited — so a short-lived process can safely exit after `end()`. -- **Errors:** fire-and-forget delivers the *span*, not error handling — exactly like plain `fetch`, a - `log.fetch()` you don't await surfaces a failed request as an unhandled promise rejection. Await it - (or attach a `.catch`) whenever the call can fail. -- **Inputs:** only `string` and `URL` are traced. A `Request` object, or a relative URL with no base - (e.g. in Node), passes straight through to a plain, untraced `fetch` (the call still works). +- **The span is the only output** — no log line. Without `otlpHttpBaseURI` it only injects the + `traceparent` header (downstream still continues the trace). +- **Delivery:** spans export in the background, so the call returns as soon as the response is ready. + `await log.end()` delivers every span, including a fire-and-forget `log.fetch()` you never awaited. +- **Errors:** an un-awaited `log.fetch()` surfaces a failed request as an unhandled rejection, exactly + like plain `fetch`. Await it (or attach `.catch`) whenever the call can fail. +- **Inputs:** only `string` and `URL` are traced. A `Request`, or a relative URL with no base (e.g. in + Node), passes straight through to a plain, untraced `fetch`. **Privacy:** the query string is **dropped** from `url.full` by default (it may carry tokens) and userinfo is always stripped. Opt in with `captureQuery: true` (known-sensitive keys like `Signature` are still redacted). Headers are captured only when allow-listed via `captureRequestHeaders` / -`captureResponseHeaders`; request/response bodies are never captured. These three are an -instance-wide policy (read at call time from the log); `clone()` to vary them. +`captureResponseHeaders`; bodies are never captured. These three are instance-wide (read at call time); +`clone()` to vary them. ### Continue a trace from an incoming request -To join a trace started upstream, pass the incoming `traceparent` header — this log adopts that trace -and nests under the caller's span. Read the current context back with `log.traceparent()` to propagate -it to a non-fetch client: +Pass the incoming `traceparent` header to join an upstream trace (nesting under the caller's span). +Read it back with `log.traceparent()` to propagate to a non-fetch client: ```javascript const reqLog = new Log({ traceparent: req.headers.traceparent }); -// ...later, calling some other client: +// ...later, calling another client: myClient.send({ headers: { traceparent: reqLog.traceparent() } }); ``` @@ -123,144 +109,112 @@ A malformed `traceparent` is ignored (a fresh trace starts), so passing an untru ### Configuration -**Log level only** -`const log = new Log("info");` Will only output error, warn and info logs. This is the default. All possible options: "error", "warn", "info", "verbose", "debug", "silly" and "none". +**Log level only:** `new Log("info")` outputs error/warn/info. Levels: `"error"`, `"warn"`, `"info"`, +`"verbose"`, `"debug"`, `"silly"`, `"none"`. Default `"info"`. + +**All options** (all optional): -**All options** ```javascript const log = new Log({ - // All options is optional - // log.fetch only: include the URL query string on the span (sensitive keys still redacted). - // Default false — the query is dropped, as it may contain tokens. - // Added in 2.3.0 + // Default false. Added in 2.3.0 captureQuery: false, // log.fetch only: header-name allow-lists, recorded as http.request.header.* / - // http.response.header.*. Default: none captured. Instance-wide; clone() to vary per call. - // Added in 2.3.0 + // http.response.header.*. Default none. Instance-wide; clone() to vary. Added in 2.3.0 captureRequestHeaders: ["x-request-id"], captureResponseHeaders: ["x-request-id"], - // Context will be appended as metadata to all log entries - // Default is an empty context - context: { - key: "string", - anotherKey: "string", - }, + // Appended as metadata to every log entry. Default {} + context: { key: "string", anotherKey: "string" }, - // Options are "text" and "json", "text" is the default + // "text" (default) or "json" format: "text", - // Defaults to "info", same as Log level only section above + // Default "info", same as the log-level-only form above logLevel: "info", - // The function that formats the log entry, default is shown here. - // msTimestamp is the Date.now() of the log call (use it instead of new Date() - // so the console, json and OTLP timestamps for one entry all match). + // Formats the log entry; default shown. msTimestamp is the Date.now() of the log call (use it + // instead of new Date() so the console, json and OTLP timestamps for one entry all match). entryFormatter: ({ logLevel, metadata, msTimestamp, msg }) => { return `${logLevel}: ${msg} ${JSON.stringify(metadata)}`; }, - // Open Telemetry additional http headers - // For example: - // { Authorization: "Bearer xxx" } - // Defaults to null - // Added in 1.4.0 + // Extra OTLP HTTP headers, eg. { Authorization: "Bearer xxx" }. Default null. Added in 1.4.0 otlpAdditionalHeaders: null, - // Open Telemetry http endpoint to send spans, traces and logs to. - // For example http://127.0.0.1:4318 - // Defaults to null - // Added in 1.3.0 + // OTLP HTTP endpoint for spans/traces/logs, eg. http://127.0.0.1:4318. Default null. Added in 1.3.0 otlpHttpBaseURI: null, - // OTLP wire format: "http/json" (default) or "http/protobuf". - // Both POST to the same endpoint; protobuf sends Content-Type: application/x-protobuf. - // Use protobuf for collectors that don't accept JSON. - // Added in 2.2.0 + // OTLP wire format: "http/json" (default) or "http/protobuf" (same endpoint, Content-Type + // application/x-protobuf). Use protobuf for collectors that reject JSON. Added in 2.2.0 otlpProtocol: "http/json", - // Group logs together under a specific parent - // Used for spans and traces in Open Telemetry etc. - // Defaults to null, creating no span in otlp - // Added in 1.3.0 + // Group logs under a parent (spans/traces). Default null (no span). Added in 1.3.0 parentLog: new Log(), - // If set to true, append spanName, spanId and traceId to the context output - // Defaults to false - // Added in 1.3.0 + // Append spanName/spanId/traceId to console output. Default false. Added in 1.3.0 printTraceInfo: false, - // Incoming W3C traceparent to adopt: this log joins that trace and nests under that span. - // Ignored if malformed or if parentLog is set. - // Added in 2.3.0 + // Incoming W3C traceparent to adopt (join that trace, nest under its span). Ignored if malformed + // or if parentLog is set. Added in 2.3.0 traceparent: null, - // Use a specific span name. Any log using this log as a parent will be - // grouped under this span name. - // Defaults to be the same as the span id, that is internally generated for each span + // Span name; logs using this log as parent group under it. Defaults to the generated span id. spanName: "my-span", - // Function that will be called to write log levels silly, debug, verbose and info. - // Defaults to console.log + // Writes silly/debug/verbose/info. Default console.log stdout: console.log, - // Function that will be called to write log levels error and warn. - // Defaults to console.error + // Writes error/warn. Default console.error stderr: console.error, }); ``` ### Metadata -`log.info("foo", { hey: "luring" });` --> 2022-09-24T23:40:39Z [info] foo {"hey":"luring"} +`log.info("foo", { hey: "luring" })` → `2022-09-24T23:40:39Z [info] foo {"hey":"luring"}` Values may be `string`, `number`, or `boolean`. OTLP attributes are string-only, so `{ count: 5 }` is sent as `"5"`; the JSON formatter keeps it native (`5`). ## Testing -All tests run inside Docker — dependencies are installed in the container too — so a local run is -identical to CI. Requires Docker; no local `npm install` is needed to run them. +All tests run in Docker (dependencies installed in the container too), so a local run matches CI. +Requires Docker; no local `npm install` needed. -- `npm test` — runs everything: the Node suite and the browser suite. -- `npm run test-docker` — Node suite only. Override the Node version with +- `npm test` — everything: the Node and browser suites. +- `npm run test-docker` — Node suite only. Override the version with `NODE_IMAGE=node:18-bookworm-slim npm run test-docker` (CI runs the full 18–26 matrix this way). -- `npm run test-browser` — the same suite in real Chromium via the official Playwright image. - -The suite is runtime-agnostic: it injects `stdout`/`stderr` and stubs the global `fetch`, so the -exact same tests exercise the console output and the OTLP transport in Node and in the browser. -The container runs `npm run ci` / `ci-browser` internally — run those directly only if you already -have deps installed locally. - -- `npm run test-otlp` — end-to-end OTLP check: exports to a real (pinned) OpenTelemetry Collector and - asserts it parsed both the JSON **and** protobuf output. This validates the hand-built protobuf - encoder against the reference implementation, not just our own decoder. `index.js` is built inside - Docker and the driver runs on the host with plain Node, so — like the suites above — it needs only - Docker, no local `npm install`. See `scripts/run-otlp-tests.mjs` (`OTLP_DEBUG=1` dumps exactly what - the collector received). -- `npm run lint` — eslint over the sources. Linting needs Node 20+ (eslint 10), so CI runs it once - in its own job rather than inside the Node 18–26 test matrix. Needs deps installed locally. +- `npm run test-browser` — the same suite in real Chromium (official Playwright image). +- `npm run test-otlp` — end-to-end export to a pinned OpenTelemetry Collector, asserting it parsed + both the JSON **and** protobuf output (validates the hand-built protobuf encoder against the + reference, not just our own decoder). `OTLP_DEBUG=1` dumps what the collector received. See + `scripts/run-otlp-tests.mjs`. Needs only Docker. +- `npm run lint` — eslint over the sources. Needs Node 20+ (eslint 10) and deps installed locally, so + CI runs it in its own job rather than inside the Node test matrix. + +The suite is runtime-agnostic: it injects `stdout`/`stderr` and stubs the global `fetch`, so the same +tests cover console output and OTLP in Node and the browser. The container runs `npm run ci` / +`ci-browser` internally. ## Releasing Publishing is automated: creating a GitHub release runs the **Publish** workflow -(`.github/workflows/publish.yaml`), which builds, tests, lints and then `npm publish`es. +(`.github/workflows/publish.yaml`) — build, test, lint, then `npm publish`. -One-time setup: add an `NPM_TOKEN` repo secret (Settings → Secrets and variables → Actions) -with an npm automation token that has publish rights to `@larvit/log`. +One-time setup: add an `NPM_TOKEN` repo secret (Settings → Secrets and variables → Actions) — an npm +automation token with publish rights to `@larvit/log`. To cut a release: 1. Add a `## Changelog` entry below for the new version. -2. Bump the version in `package.json` (`npm version ` does this and commits it). +2. Bump the version in `package.json` (`npm version ` does this and commits). Follow semver: breaking changes → major. 3. Merge to `master`. -4. Create a GitHub release with a tag `vX.Y.Z` that matches `package.json` (e.g. `v2.0.0`). - The workflow verifies the tag matches the version and fails the publish if it does not. +4. Create a GitHub release with a tag `vX.Y.Z` that matches `package.json` (the workflow verifies the + tag matches the version and fails the publish otherwise). -The workflow publishes whatever is in `package.json`, so the tag and `package.json` version must agree. To publish manually instead: `npm run build-and-publish`. ## Changelog diff --git a/index.ts b/index.ts index e79fb17..1bc8149 100644 --- a/index.ts +++ b/index.ts @@ -216,44 +216,27 @@ function getRandomBytes(size: number): Uint8Array { return bytes; } -/** - * Generates a random 8-byte span ID as a 16-character hex string. - * - * @returns {string} A valid OTLP span ID - */ +// Random 8-byte span id as 16 hex chars. export function generateSpanId(): string { return bytesToHex(getRandomBytes(8)); } -/** - * Generates a random 16-byte trace ID as a 32-character hex string. - * - * @returns {string} A valid OTLP trace ID - */ +// Random 16-byte trace id as 32 hex chars. export function generateTraceId(): string { const bytes = getRandomBytes(16); - // Ensure version 1 trace ID by setting first byte - bytes[0] = 0x01; + bytes[0] = 0x01; // version 1 trace id return bytesToHex(bytes); } -/** - * Builds a W3C `traceparent` header value (`version-traceId-spanId-flags`) for the given context. - * - * @returns {string} A traceparent header value, sampled by default - */ +// W3C `traceparent` header value (`version-traceId-spanId-flags`); sampled by default. export function formatTraceparent(traceId: string, spanId: string, sampled: boolean = true): string { return `00-${traceId}-${spanId}-${sampled ? "01" : "00"}`; } -/** - * Parses a W3C `traceparent` header. Untrusted input: returns null (rather than throwing) for any - * malformed or all-zero value, so the caller cleanly starts a fresh trace instead of continuing. - * - * @returns {{ flags: string, spanId: string, traceId: string } | null} The parsed parts, or null - */ +// Parses a W3C `traceparent`. Untrusted input: returns null (never throws) for any malformed or +// all-zero value, so the caller cleanly starts a fresh trace instead of continuing. export function parseTraceparent(header: string): { flags: string, spanId: string, traceId: string } | null { const match = /^[0-9a-f]{2}-([0-9a-f]{32})-([0-9a-f]{16})-([0-9a-f]{2})$/.exec(header.trim().toLowerCase()); @@ -285,8 +268,8 @@ function isFetchError(error: unknown): error is FetchError { return typeof error === "object" && error !== null && "message" in error; } -// Resource-level OTLP attributes (service.name + telemetry.sdk.*). Shared by logs and spans so the -// service is identified the same way for both — Grafana/Loki reads service.name from here, not the records. +// Resource-level OTLP attributes (service.name + telemetry.sdk.*), shared by logs and spans. +// Grafana/Loki reads service.name from here, not from the records. function buildResourceAttributes(context: Metadata): OtlpAttribute[] { return [ { key: "service.name", value: { stringValue: String(context["service.name"] || "unnamed-service") } }, @@ -366,9 +349,8 @@ function buildSpanPayload(opts: { } // --- OTLP/HTTP protobuf encoding ------------------------------------------- -// Hand-rolled protobuf wire encoder for the small, frozen OTLP message subset this library emits. -// Zero dependencies keeps the library a single self-contained file that runs in any JS runtime -// (priority: works everywhere). Field numbers below are from the OTLP proto definitions (v1). +// Hand-rolled wire encoder for the small, frozen OTLP subset this library emits — zero deps keeps it +// a single self-contained file that runs anywhere. Field numbers are from the OTLP proto defs (v1). const WIRE_VARINT = 0; const WIRE_FIXED64 = 1; @@ -671,10 +653,9 @@ export class Log implements LogInt { ...conf.context, }; - // Inherit every other setting not explicitly overridden — log level, sinks, OTLP endpoint/ - // protocol/headers, printTraceInfo, etc. — mirroring how the constructor inherits from a - // parentLog. parentLog and spanName are excluded: a clone is its own span, not a child of the - // original. (A manual allow-list here previously dropped OTLP options added after clone existed.) + // Inherit every other setting not overridden (log level, sinks, OTLP config, printTraceInfo…), + // like the constructor does from a parentLog. parentLog/spanName/traceparent are excluded: a + // clone is its own span, not a child. (A manual allow-list here once dropped newer OTLP options.) for (const key of Object.keys(this.conf) as (keyof LogConf)[]) { if (key !== "parentLog" && key !== "spanName" && key !== "traceparent" && conf[key] === undefined) { conf[key] = this.conf[key] as never; @@ -703,14 +684,11 @@ export class Log implements LogInt { return formatTraceparent(this.span.traceId, this.span.spanId); } - // Drop-in `fetch` that auto-creates an OTel CLIENT span for the call (nested under this log's - // span), injects a `traceparent` header, and records the OTel http.* attributes. The span exports - // in the background — the call returns as soon as the response is ready and never waits on the - // OTLP round-trip — but it is registered with end() at call time, so `await log.end()` delivers it - // even when the fetch was not awaited. The span is the only output: no log line is written. - // Instrumentation never changes the call's outcome: only `string`/`URL` inputs are traced; - // anything else (a `Request`, or an unparseable/relative URL with no base) passes straight through - // to a plain, untraced fetch. + // Drop-in `fetch`: auto-creates a CLIENT span (nested under this log's span), injects a + // `traceparent`, records the OTel http.* attributes, and is the only output (no log line). The + // span exports in the background and is registered with end() at call time, so `await log.end()` + // delivers it even when the fetch wasn't awaited. Only `string`/`URL` inputs are traced; anything + // else (a `Request`, or a relative URL with no base) passes through to a plain, untraced fetch. public fetch(input: string | URL, init?: RequestInit): Promise { if (this.ended) { throw new Error("Logging instance is already ended"); @@ -724,8 +702,8 @@ export class Log implements LogInt { return globalThis.fetch(input, init); } - // Register the whole operation (request + span export) synchronously, so a fire-and-forget - // log.fetch() is still delivered by a later await log.end(). + // Register the whole operation synchronously, so a fire-and-forget log.fetch() is still + // delivered by a later await log.end(). let settle!: () => void; this.track(new Promise(resolve => { settle = resolve; })); @@ -734,9 +712,8 @@ export class Log implements LogInt { } private async tracedFetch(url: URL, init: RequestInit | undefined, settle: () => void): Promise { - // Created with safe operations only; everything that can throw (e.g. `new Headers` on a bad - // header name) lives inside the try, so the finally always runs and settles the tracked - // promise — end() can never hang on this fetch. + // childSpan can't throw; everything that can (e.g. `new Headers` on a bad name) is inside the + // try, so finally always settles the tracked promise and end() can never hang on this fetch. const span = this.childSpan(url.host, 3); // CLIENT; name refined below const context: Metadata = { ...this.context }; @@ -788,9 +765,8 @@ export class Log implements LogInt { throw err; } finally { - // Always settle the tracked promise so end() can never hang on this fetch — even if the - // export call itself were to throw synchronously (defense-in-depth; it normally returns a - // promise we resolve via .then once the span is delivered). + // Always settle the tracked promise so end() can never hang on this fetch, even if the + // export call itself throws synchronously (it normally resolves once the span is delivered). try { void this.exportChildSpan(span, context).then(settle, settle); } catch { diff --git a/tap.ts b/tap.ts index 95bf4b7..45c38b2 100644 --- a/tap.ts +++ b/tap.ts @@ -1,8 +1,6 @@ -// Minimal TAP harness that runs identically in Node and browsers (no Node-only deps), -// so the exact same suite can run server-side and in a real browser. Replaces tape/tap-spec. -// -// Node: sets process.exitCode (1 on any failure). Browser: exposes globalThis.__tap so the -// Playwright runner can read the result. TAP lines go to console (captured in both runtimes). +// Minimal TAP harness with no Node-only deps, so the same suite runs in Node and a real browser. +// Node: sets process.exitCode (1 on any failure). Browser: exposes globalThis.__tap for the +// Playwright runner. TAP lines go to console (captured in both runtimes). export type TestFn = (t: Assertions) => void | Promise; @@ -19,8 +17,8 @@ export interface Assertions { throws(cb: () => void, msg?: string): void; } -// A hung async test must fail fast rather than hang the Node run (the browser run also has its own -// Playwright timeout). Keep this comfortably above any real test and below that Playwright timeout. +// A hung async test must fail fast, not hang the run. Keep comfortably above any real test and +// below the Playwright timeout. const TEST_TIMEOUT_MS = 10000; const tests: { cb: TestFn, name: string }[] = []; diff --git a/test.ts b/test.ts index cc217f2..e9f076e 100644 --- a/test.ts +++ b/test.ts @@ -1,4 +1,4 @@ -import { formatTraceparent, generateSpanId, generateTraceId, Log, type LogConf, LogLevels, msgJsonFormatter, parseTraceparent } from "./index.js"; +import { formatTraceparent, generateSpanId, generateTraceId, Log, type LogConf, type LogLevel, LogLevels, msgJsonFormatter, parseTraceparent } from "./index.js"; import test from "./tap.js"; // --- helpers --------------------------------------------------------------- @@ -8,20 +8,14 @@ function isNanoTimestampWithinHour(str: string): boolean { return false; } - const unixTimestamp = Math.round(parseInt(str) / 1000000000); // nanosecond to second - const now = Math.floor(Date.now() / 1000); // millisecond to second - const hourInSeconds = 3600; + const unixTimestamp = Math.round(parseInt(str) / 1000000000); // ns -> s + const now = Math.floor(Date.now() / 1000); - // Check if number is a reasonable Unix timestamp (after 2020-01-01) - if (unixTimestamp > 1577836800) { - return Math.abs(now - unixTimestamp) <= hourInSeconds; - } - - return false; + // A plausible recent Unix timestamp: after 2020-01-01 and within an hour of now. + return unixTimestamp > 1577836800 && Math.abs(now - unixTimestamp) <= 3600; } -// Build a Log whose console output is captured into arrays instead of touching the real console. -// Works in any runtime (no process.stdout patching). +// Build a Log capturing console output into arrays (runtime-agnostic, no process.stdout patching). function capture(conf?: ConstructorParameters[0]) { const stderr: string[] = []; const stdout: string[] = []; @@ -33,23 +27,16 @@ function capture(conf?: ConstructorParameters[0]) { return { log: new Log(opts), stderr, stdout }; } -function okResponse(json: unknown = { partialSuccess: {} }) { - // eslint-disable-next-line id-length -- "ok" mirrors the fetch Response shape the transport reads - return { headers: new Headers(), json: () => Promise.resolve(json), ok: true, status: 200 }; -} - -// A fetch Response stand-in for log.fetch tests, with overridable status/headers. -function fetchResponse(opts: { headers?: Headers, status?: number } = {}) { - const status = opts.status ?? 200; - +// A minimal fetch Response stand-in. Defaults satisfy the OTLP transport (which reads .json()); +// log.fetch tests override status/headers — log.fetch never reads the body. +function response({ headers, json = { partialSuccess: {} }, status = 200 }: { headers?: Headers, json?: unknown, status?: number } = {}) { // eslint-disable-next-line id-length -- "ok" mirrors the fetch Response shape - return { headers: opts.headers ?? new Headers(), json: () => Promise.resolve({}), ok: status < 400, status }; + return { headers: headers ?? new Headers(), json: () => Promise.resolve(json), ok: status < 400, status }; } -// Replace the global fetch with a recording stub. Works in Node and the browser, so the OTLP -// transport can be asserted without a real HTTP server (deterministic, no express dependency). -// The harness restores globalThis.fetch after each test, so callers never restore it themselves. -function stubFetch(responder?: (path: string, body: unknown) => ReturnType | undefined) { +// Replace global fetch with a recording stub (Node + browser), so the OTLP transport is asserted +// without a real server. The harness restores globalThis.fetch after each test. +function stubFetch(responder?: (path: string, body: unknown) => ReturnType | undefined) { const calls: { body: any, contentType: string, headers: any, path: string, rawBody: any, url: string }[] = []; globalThis.fetch = (async (url: string, init: { body: any, headers: Record }) => { @@ -60,16 +47,16 @@ function stubFetch(responder?: (path: string, body: unknown) => ReturnType new Headers(call.headers ?? {}).get(name); -// Locate the exported CLIENT span (kind 3) among the /v1/traces calls — the one log.fetch creates. +// The exported CLIENT span (kind 3) among the /v1/traces calls — the one log.fetch creates. function clientSpan(calls: { body: any, path: string }[]) { for (const call of calls.filter(call => call.path === "/v1/traces")) { const span = call.body.resourceSpans[0].scopeSpans[0].spans[0]; @@ -83,10 +70,9 @@ function clientSpan(calls: { body: any, path: string }[]) { } // --- protobuf decode (test-only, zero-dep) --------------------------------- -// Minimal reader that verifies the hand-rolled OTLP protobuf encoder: it decodes the wire bytes -// back into the shape the JSON transport builds, so the same facts can be asserted. Field numbers -// mirror the OTLP proto definitions. Independent of the encoder (own varint/fixed64 reader), so an -// encoder bug can't be masked by symmetric reuse. +// Independent reader (own varint/fixed64 logic) that decodes the hand-rolled OTLP protobuf back into +// the JSON transport's shape, so an encoder bug can't hide behind symmetric reuse. Field numbers +// mirror the OTLP proto definitions. function pbReadVarint(buf: Uint8Array, pos: number): [bigint, number] { let result = 0n; @@ -185,7 +171,7 @@ function pbDecodeSpans(buf: Uint8Array) { return { resourceAttrs: pbResourceAttrs(resSpan.get(1)![0]), - scopeName: pbStr(pbMsg(scopeSpan.get(1)![0]).get(1)![0]), // ScopeSpans.scope (msg) -> InstrumentationScope.name + scopeName: pbStr(pbMsg(scopeSpan.get(1)![0]).get(1)![0]), // ScopeSpans.scope -> InstrumentationScope.name span: { attributes: (span.get(9) ?? []).map(pbKeyValue), @@ -202,188 +188,96 @@ function pbDecodeSpans(buf: Uint8Array) { // --- console output -------------------------------------------------------- -test("Should log to info.", t => { - const { log, stdout } = capture(); - - log.info("flurp"); - t.strictEqual(stdout[0].substring(19), "Z [\x1b[1;32minf\x1b[0m] flurp", "\"flurp\" is in the inf log output"); - t.end(); -}); - -test("Should log to error.", t => { - const { log, stderr } = capture(); - - log.error("burp"); - t.strictEqual(stderr[0].substring(19), "Z [\x1b[1;31merr\x1b[0m] burp", "\"burp\" is in the err log output"); - t.end(); -}); - -test("Should not print debug by default.", t => { - const { log, stdout } = capture(); - - log.debug("nai"); - t.strictEqual(stdout.length, 0, "debug is not logged at the default level"); - t.end(); -}); - -test("Should print debug when given \"silly\" as level.", t => { - const { log, stdout } = capture("silly"); - - log.debug("wapp"); - t.strictEqual(stdout[0].substring(19), "Z [\x1b[1;35mdeb\x1b[0m] wapp", "\"wapp\" is in the deb log output"); - t.end(); -}); - -test("Print nothing, even on error, when no valid level is set.", t => { - const { log, stderr } = capture("none"); - - log.error("kattbajs"); - t.strictEqual(stderr.length, 0, "Nothing is written at level \"none\""); - t.end(); -}); - -test("Test silly.", t => { - const { log, stdout } = capture("silly"); - - log.silly("kattbajs"); - t.strictEqual(stdout[0].substring(19), "Z [\x1b[1;37msil\x1b[0m] kattbajs"); - t.end(); -}); - -test("Test debug", t => { - const { log, stdout } = capture("debug"); - - log.debug("kattbajs"); - t.strictEqual(stdout[0].substring(19), "Z [\x1b[1;35mdeb\x1b[0m] kattbajs", "Debug level is output to stdout"); - t.end(); -}); - -test("Test verbose", t => { - const { log, stdout } = capture("verbose"); - - log.verbose("kattbajs"); - t.strictEqual(stdout[0].substring(19), "Z [\x1b[1;34mver\x1b[0m] kattbajs"); - t.end(); -}); - -test("Test info", t => { - const { log, stdout } = capture("info"); - - log.info("kattbajs"); - t.strictEqual(stdout[0].substring(19), "Z [\x1b[1;32minf\x1b[0m] kattbajs"); +test("each level writes its colored token to the right stream", t => { + const cases: { level: LogLevel, stream: "stderr" | "stdout", token: string }[] = [ + { level: "error", stream: "stderr", token: "\x1b[1;31merr\x1b[0m" }, + { level: "warn", stream: "stderr", token: "\x1b[1;33mwar\x1b[0m" }, + { level: "info", stream: "stdout", token: "\x1b[1;32minf\x1b[0m" }, + { level: "verbose", stream: "stdout", token: "\x1b[1;34mver\x1b[0m" }, + { level: "debug", stream: "stdout", token: "\x1b[1;35mdeb\x1b[0m" }, + { level: "silly", stream: "stdout", token: "\x1b[1;37msil\x1b[0m" }, + ]; + + for (const { level, stream, token } of cases) { + const cap = capture("silly"); // silly passes every level through the filter + + cap.log[level]("msg"); + t.strictEqual(cap[stream][0]?.substring(19), `Z [${token}] msg`, `${level} -> ${stream} with its token`); + } t.end(); }); -test("Test warn", t => { - const { log, stderr } = capture("warn"); +test("respects the configured log-level threshold", t => { + const def = capture(); // default level is info - log.warn("kattbajs"); - t.strictEqual(stderr[0].substring(19), "Z [\x1b[1;33mwar\x1b[0m] kattbajs"); - t.end(); -}); + def.log.info("x"); + def.log.verbose("x"); + def.log.debug("x"); + t.strictEqual(def.stdout.length, 1, "default level passes info but not verbose/debug"); -test("Test error", t => { - const { log, stderr } = capture("silly"); + const err = capture("error"); - log.error("kattbajs"); - t.strictEqual(stderr[0].substring(19), "Z [\x1b[1;31merr\x1b[0m] kattbajs"); - t.end(); -}); + err.log.silly("x"); + err.log.debug("x"); + err.log.verbose("x"); + err.log.warn("x"); + t.strictEqual(err.stdout.length + err.stderr.length, 0, "everything below error (incl. warn) is suppressed"); + err.log.error("x"); + t.strictEqual(err.stderr.length, 1, "error passes at level error"); -test("Test initializing with options object", t => { - const { log, stderr } = capture({ logLevel: "error" }); + const silly = capture("silly"); - log.error("an error"); - t.strictEqual(stderr[0].substring(19), "Z [\x1b[1;31merr\x1b[0m] an error"); - t.end(); -}); + silly.log.debug("x"); + t.strictEqual(silly.stdout.length, 1, "debug passes at the lowest level"); -test("Default level is info if nothing else is specified", t => { - const { log, stdout } = capture({ logLevel: undefined }); + const none = capture("none"); - log.info("information"); - t.ok(stdout[0].includes(" information"), "info is logged at the default level"); - log.verbose("not logged"); - t.strictEqual(stdout.length, 1, "verbose is not logged at the default level"); + none.log.error("x"); + t.strictEqual(none.stderr.length, 0, "nothing is written at level none, not even error"); t.end(); }); -test("Test only errors are logged if log level is error", t => { - const { log, stderr, stdout } = capture("error"); +test("metadata and context appear in the output", t => { + const meta = capture("info"); - log.silly("kattbajs"); - log.debug("kattbajs"); - log.verbose("kattbajs"); - t.strictEqual(stdout.length, 0, "silly/debug/verbose are not logged at level error"); + meta.log.info("kattbajs", { foo: "bar" }); + t.strictEqual(meta.stdout[0].split(" kattbajs ")[1].trim(), "{\"foo\":\"bar\"}", "metadata is appended"); - log.warn("kattbajs"); - t.strictEqual(stderr.length, 0, "warn is not logged at level error"); + const ctx = capture({ context: { bosse: "bäng", hasse: "luring" } }); - log.error("kattbajs"); - t.ok(stderr[0].includes(" kattbajs"), "error is logged at level error"); - t.end(); -}); - -test("Test with metadata", t => { - const { log, stdout } = capture("info"); - - log.info("kattbajs", { foo: "bar" }); - t.strictEqual(stdout[0].split(" kattbajs ")[1].trim(), "{\"foo\":\"bar\"}", "Metadata is included in output"); - t.end(); -}); - -test("Test with context", t => { - const { log, stdout } = capture({ context: { bosse: "bäng", hasse: "luring" } }); - - log.info("kattbajs", { foo: "bar" }); + ctx.log.info("kattbajs", { foo: "bar" }); t.strictEqual( - stdout[0].split(" kattbajs ")[1].trim(), + ctx.stdout[0].split(" kattbajs ")[1].trim(), "{\"foo\":\"bar\",\"bosse\":\"bäng\",\"hasse\":\"luring\"}", - "Metadata and context are included in output", + "metadata and context are merged into the output", ); t.end(); }); -test("Json stringifyer", t => { +test("json format emits context, metadata, logLevel and msg", t => { const { log, stdout } = capture({ context: { hello: "yo" }, format: "json" }); log.info("bosse", { foo: "frasse" }); const parsed = JSON.parse(stdout[0]); - t.strictEqual(parsed.foo, "frasse", "Metadata foo is \"frasse\""); - t.strictEqual(parsed.hello, "yo", "Context is in the json"); + t.strictEqual(parsed.foo, "frasse", "metadata is in the json"); + t.strictEqual(parsed.hello, "yo", "context is in the json"); t.strictEqual(parsed.logLevel, "info", "logLevel is set"); - t.strictEqual(parsed.msg, "bosse", "msg is set to \"bosse\""); + t.strictEqual(parsed.msg, "bosse", "msg is set"); t.end(); }); -test("Copy instance", t => { - const log = new Log({ context: { foo: "bar" } }); - const newLog = log.clone({ context: { baz: "fu" }, logLevel: "error" }); - const newLog2 = log.clone({ context: { foo: "burp" } }); - - t.strictEqual(JSON.stringify(newLog.context), "{\"foo\":\"bar\",\"baz\":\"fu\"}", "Context is merged in newLog."); - t.strictEqual(JSON.stringify(newLog2.context), "{\"foo\":\"burp\"}", "Context is merged in newLog2."); - t.end(); -}); - -test("msgJsonFormatter does not mutate input and is undefined-safe", t => { +test("msgJsonFormatter keeps native types, does not mutate input, is undefined-safe", t => { const meta = { count: 5, user: "abc" }; const parsed = JSON.parse(msgJsonFormatter({ logLevel: "info", metadata: meta, msg: "hi" })); - t.strictEqual(parsed.user, "abc", "user metadata preserved"); t.strictEqual(parsed.count, 5, "number metadata stays a number in JSON output"); - t.strictEqual(parsed.msg, "hi", "msg present"); - t.strictEqual(parsed.logLevel, "info", "logLevel present"); - t.deepEqual(meta, { count: 5, user: "abc" }, "caller metadata object is NOT mutated"); - - const parsed2 = JSON.parse(msgJsonFormatter({ logLevel: "error", msg: "boom" })); - - t.strictEqual(parsed2.msg, "boom", "undefined metadata does not throw"); + t.deepEqual(meta, { count: 5, user: "abc" }, "caller metadata is not mutated"); + t.doesNotThrow(() => msgJsonFormatter({ logLevel: "error", msg: "boom" }), "undefined metadata does not throw"); t.end(); }); -test("verbose is ranked more severe than debug in OTLP severity", t => { +test("verbose ranks more severe than debug in OTLP severity", t => { t.ok(LogLevels.verbose.severityNumber > LogLevels.debug.severityNumber, "verbose severityNumber > debug severityNumber"); t.end(); }); @@ -405,6 +299,14 @@ test("printTraceInfo appends span/trace info to output", t => { t.end(); }); +test("clone merges context (overrides win)", t => { + const log = new Log({ context: { foo: "bar" } }); + + t.strictEqual(JSON.stringify(log.clone({ context: { baz: "fu" } }).context), "{\"foo\":\"bar\",\"baz\":\"fu\"}", "new keys merge in"); + t.strictEqual(JSON.stringify(log.clone({ context: { foo: "burp" } }).context), "{\"foo\":\"burp\"}", "existing keys are overridden"); + t.end(); +}); + test("clone can downgrade json format to text", t => { const stdout: string[] = []; const textLog = new Log({ format: "json" }).clone({ format: "text", stdout: line => stdout.push(line) }); @@ -415,10 +317,13 @@ test("clone can downgrade json format to text", t => { t.end(); }); -test("clone() inherits OTLP config and printTraceInfo, but keeps its own span", async t => { +test("clone inherits config (OTLP, printTraceInfo, fetch policy) but keeps its own span", async t => { const { calls } = stubFetch(); const stdout: string[] = []; const base = new Log({ + captureQuery: true, + captureRequestHeaders: ["x-req"], + captureResponseHeaders: ["x-resp"], otlpHttpBaseURI: "http://127.0.0.1:4318", otlpProtocol: "http/protobuf", printTraceInfo: true, @@ -431,11 +336,16 @@ test("clone() inherits OTLP config and printTraceInfo, but keeps its own span", child.info("from clone"); await child.end(); - // OTLP endpoint + protocol are inherited: the clone actually exports, and as protobuf. - t.ok(calls.some(call => call.path === "/v1/logs"), "clone exported a log to the inherited OTLP endpoint"); + // OTLP endpoint + protocol inherited: the clone actually exports, as protobuf. + t.ok(calls.some(call => call.path === "/v1/logs"), "clone exports to the inherited OTLP endpoint"); t.ok(calls.length > 0 && calls.every(call => call.contentType === "application/x-protobuf"), "clone inherited otlpProtocol http/protobuf"); - // printTraceInfo is inherited: console output carries span/trace info. + // log.fetch policy inherited. + t.strictEqual(child.conf.captureQuery, true, "captureQuery inherited"); + t.deepEqual(child.conf.captureRequestHeaders, ["x-req"], "request header allow-list inherited"); + t.deepEqual(child.conf.captureResponseHeaders, ["x-resp"], "response header allow-list inherited"); + + // printTraceInfo inherited. t.ok(stdout[0].includes("spanId"), "clone inherited printTraceInfo"); // ...but the clone is its own span, not a child of base. @@ -453,9 +363,7 @@ test("child log does not share its context object with the parent", t => { const parent = new Log({ context: { service: "x" } }); const child = new Log({ parentLog: parent }); - t.notStrictEqual(child.context, parent.context, "child has its own context object"); t.strictEqual(child.context.service, "x", "child inherits parent context values"); - child.context.extra = "y"; t.strictEqual(parent.context.extra, undefined, "child context mutation does not leak to parent"); t.end(); @@ -463,7 +371,7 @@ test("child log does not share its context object with the parent", t => { // --- OTLP transport (fetch-stubbed) ---------------------------------------- -test("end() returns an awaitable promise and OTLP failure is handled without hanging", async t => { +test("end() is awaitable and an OTLP export failure is reported without hanging", async t => { stubFetch(() => { throw new Error("connection refused"); }); const stderr: string[] = []; const log = new Log({ otlpHttpBaseURI: "http://127.0.0.1:1", stderr: line => stderr.push(line) }); @@ -473,8 +381,7 @@ test("end() returns an awaitable promise and OTLP failure is handled without han t.ok(ret && typeof ret.then === "function", "end() returns a thenable"); await ret; - - t.ok(stderr.join("\n").includes("127.0.0.1:1"), "the OTLP export error (incl. endpoint url) is written to stderr"); + t.ok(stderr.join("\n").includes("127.0.0.1:1"), "the export error, incl. the endpoint url, is written to stderr"); t.end(); }); @@ -489,104 +396,74 @@ test("OTLP preserves a base path from otlpHttpBaseURI", async t => { t.end(); }); -test("OLTP simple log", async t => { - const { calls } = stubFetch(); - const log = new Log({ otlpHttpBaseURI: "http://127.0.0.1:4318", stderr: () => {} }); - - log.error("Gir in da house!"); - await log.end(); - - const logsBody: any = calls.find(call => call.path === "/v1/logs")?.body; - const tracesBody: any = calls.find(call => call.path === "/v1/traces")?.body; - - t.ok(logsBody, "a /v1/logs call was made"); - t.ok(tracesBody, "a /v1/traces call was made"); - t.ok(calls.every(call => call.contentType === "application/json"), "default protocol sends JSON content-type"); - - t.strictEqual(logsBody.resourceLogs.length, 1, "Exactly one resourceLog in /v1/logs body"); - t.strictEqual(logsBody.resourceLogs[0].scopeLogs.length, 1, "Exactly one scopeLog in /v1/logs body"); - t.strictEqual(logsBody.resourceLogs[0].scopeLogs[0].logRecords.length, 1, "Exactly one logRecord in /v1/logs body"); - - const logRecord = logsBody.resourceLogs[0].scopeLogs[0].logRecords[0]; - - t.strictEqual(logRecord.body.stringValue, "Gir in da house!", "logRecord.body is correct"); - t.strictEqual(logRecord.severityNumber, 17, "logRecord.severityNumber is correct"); - t.strictEqual(logRecord.severityText, "ERROR", "logRecord.severityText is correct"); - t.notStrictEqual(logRecord.traceId.length, 0, "logRecord.traceId has a non-zero length"); - t.ok(isNanoTimestampWithinHour(logRecord.timeUnixNano), "timeUnixNano is reasonable"); - - t.strictEqual(tracesBody.resourceSpans.length, 1, "Exactly one resourceSpan in /v1/traces body"); - t.strictEqual(tracesBody.resourceSpans[0].scopeSpans.length, 1, "Exactly one scopeSpan in /v1/traces body"); - t.strictEqual(tracesBody.resourceSpans[0].scopeSpans[0].spans.length, 1, "Exactly one span in /v1/traces body"); - - const span = tracesBody.resourceSpans[0].scopeSpans[0].spans[0]; - - t.strictEqual(span.kind, 1, "Span kind is always 1"); - t.strictEqual(typeof span.name, "string", "span.name is a string"); - t.notStrictEqual(span.name.length, 0, "span.name has a non-zero length"); - t.notStrictEqual(span.spanId.length, 0, "span.spanId has a non-zero length"); - t.strictEqual(span.traceId, logRecord.traceId, "span.traceId matches the log traceId"); - t.ok(isNanoTimestampWithinHour(span.endTimeUnixNano), "span.endTimeUnixNano is reasonable"); - t.ok(isNanoTimestampWithinHour(span.startTimeUnixNano), "span.startTimeUnixNano is reasonable"); - t.end(); -}); - -test("OLTP simple log with metadata", async t => { +test("OTLP/JSON exports one log record and one span sharing trace/span ids", async t => { const { calls } = stubFetch(); const log = new Log({ context: { "service.name": "eva-bosse" }, otlpHttpBaseURI: "http://127.0.0.1:4318", spanName: "lur-bert", + stderr: () => {}, }); log.warn("FOo", { active: true, bar: "baz", "lökig knasnyckel | typ": 17 }); await log.end(); - const logsBody: any = calls.find(call => call.path === "/v1/logs")?.body; - const tracesBody: any = calls.find(call => call.path === "/v1/traces")?.body; - const logRecord = logsBody.resourceLogs[0].scopeLogs[0].logRecords[0]; - - t.strictEqual(logRecord.body.stringValue, "FOo", "logRecord.body is correct"); - t.strictEqual(logRecord.severityNumber, 13, "logRecord.severityNumber is correct"); - t.strictEqual(logRecord.severityText, "WARN", "logRecord.severityText is correct"); - t.strictEqual(logRecord.attributes[0].key, "active", "First attribute is active"); - t.strictEqual(logRecord.attributes[0].value.stringValue, "true", "boolean metadata coerced to \"true\""); - t.strictEqual(logRecord.attributes[1].key, "bar", "Second attribute is bar"); - t.strictEqual(logRecord.attributes[1].value.stringValue, "baz", "Second attribute value is baz"); - t.strictEqual(logRecord.attributes[2].key, "lökig knasnyckel | typ", "Third attribute key is correct"); - t.strictEqual(logRecord.attributes[2].value.stringValue, "17", "number metadata coerced to \"17\""); + t.ok(calls.every(call => call.contentType === "application/json"), "default protocol sends JSON"); - // service.name belongs on the log resource (this is what Grafana/Loki reads), not the log record. - const logResourceAttrs = logsBody.resourceLogs[0].resource.attributes; + const logsBody: any = calls.find(call => call.path === "/v1/logs")!.body; + const tracesBody: any = calls.find(call => call.path === "/v1/traces")!.body; + const resourceAttr = (attrs: any[], key: string) => attrs.find(attr => attr.key === key)?.value.stringValue; - t.strictEqual(logResourceAttrs.find((attr: any) => attr.key === "service.name").value.stringValue, "eva-bosse", "log resource service.name is eva-bosse"); - t.strictEqual(logResourceAttrs.find((attr: any) => attr.key === "telemetry.sdk.name").value.stringValue, "@larvit/log", "log resource telemetry.sdk.name is @larvit/log"); - t.notOk(logRecord.attributes.find((attr: any) => attr.key === "service.name"), "service.name is not duplicated in log record attributes"); + // Exactly one resource/scope/record and resource/scope/span. + t.strictEqual(logsBody.resourceLogs.length, 1, "one resourceLog"); + t.strictEqual(logsBody.resourceLogs[0].scopeLogs.length, 1, "one scopeLog"); + t.strictEqual(logsBody.resourceLogs[0].scopeLogs[0].logRecords.length, 1, "one logRecord"); + t.strictEqual(tracesBody.resourceSpans.length, 1, "one resourceSpan"); + t.strictEqual(tracesBody.resourceSpans[0].scopeSpans.length, 1, "one scopeSpan"); + t.strictEqual(tracesBody.resourceSpans[0].scopeSpans[0].spans.length, 1, "one span"); - const traceResource = tracesBody.resourceSpans[0]; - - t.strictEqual(traceResource.resource.attributes.length, 4, "Resource has 4 attributes"); - t.strictEqual(traceResource.resource.droppedAttributesCount, 0, "No attributes dropped"); + const logRecord = logsBody.resourceLogs[0].scopeLogs[0].logRecords[0]; - const findAttr = (key: string) => traceResource.resource.attributes.find((attr: any) => attr.key === key).value.stringValue; + t.strictEqual(logRecord.body.stringValue, "FOo", "log body"); + t.strictEqual(logRecord.severityNumber, 13, "severityNumber is WARN (13)"); + t.strictEqual(logRecord.severityText, "WARN", "severityText is WARN"); + t.ok(isNanoTimestampWithinHour(logRecord.timeUnixNano), "log timeUnixNano is reasonable"); + t.deepEqual( + logRecord.attributes, + [ + { key: "active", value: { stringValue: "true" } }, + { key: "bar", value: { stringValue: "baz" } }, + { key: "lökig knasnyckel | typ", value: { stringValue: "17" } }, + ], + "metadata attributes are coerced to strings, in insertion order", + ); - t.strictEqual(findAttr("service.name"), "eva-bosse", "service.name is eva-bosse"); - t.strictEqual(findAttr("telemetry.sdk.language"), "ecmascript", "telemetry.sdk.language is ecmascript"); - t.strictEqual(findAttr("telemetry.sdk.name"), "@larvit/log", "telemetry.sdk.name is @larvit/log"); - t.ok(/^\d+\.\d+\.\d+/.test(findAttr("telemetry.sdk.version")), "telemetry.sdk.version is a semver (build replaced __version__)"); + // service.name lives on the resource (what Grafana/Loki reads), never duplicated on the record. + t.strictEqual(resourceAttr(logsBody.resourceLogs[0].resource.attributes, "service.name"), "eva-bosse", "service.name on log resource"); + t.notOk(logRecord.attributes.find((attr: any) => attr.key === "service.name"), "service.name not duplicated on the record"); - const scopedSpan = traceResource.scopeSpans[0]; - const span = scopedSpan.spans[0]; + const traceResource = tracesBody.resourceSpans[0]; - t.strictEqual(scopedSpan.scope.name, "lur-bert", "Span scope name is lur-bert"); - t.strictEqual(span.name, "lur-bert", "Span name is lur-bert"); - t.strictEqual(span.traceId, logRecord.traceId, "traceId is the same in trace and log"); - t.strictEqual(span.spanId, logRecord.spanId, "spanId is the same in trace and log"); - t.strictEqual(span.kind, 1, "span kind is 1"); - t.strictEqual(span.attributes.length, 0, "Span attributes is an empty array"); - t.strictEqual(span.status.code, 0, "span status code is 0"); - t.strictEqual(span.links.length, 0, "span links is an empty array"); + t.strictEqual(traceResource.resource.attributes.length, 4, "resource has 4 attributes"); + t.strictEqual(traceResource.resource.droppedAttributesCount, 0, "no dropped resource attributes"); + t.strictEqual(resourceAttr(traceResource.resource.attributes, "service.name"), "eva-bosse", "service.name on span resource"); + t.strictEqual(resourceAttr(traceResource.resource.attributes, "telemetry.sdk.language"), "ecmascript", "telemetry.sdk.language"); + t.strictEqual(resourceAttr(traceResource.resource.attributes, "telemetry.sdk.name"), "@larvit/log", "telemetry.sdk.name"); + t.ok(/^\d+\.\d+\.\d+/.test(resourceAttr(traceResource.resource.attributes, "telemetry.sdk.version")), "telemetry.sdk.version is a real semver (build replaced __version__)"); + + const span = traceResource.scopeSpans[0].spans[0]; + + t.strictEqual(traceResource.scopeSpans[0].scope.name, "lur-bert", "scope name is the span name"); + t.strictEqual(span.name, "lur-bert", "span name"); + t.strictEqual(span.kind, 1, "span kind 1"); + t.strictEqual(span.status.code, 0, "span status is ok"); + t.strictEqual(span.attributes.length, 0, "no span attributes (context held only service.name)"); + t.strictEqual(span.links.length, 0, "span has no links"); t.strictEqual(span.droppedLinksCount, 0, "span has no dropped links"); + t.strictEqual(span.traceId, logRecord.traceId, "span and log share the traceId"); + t.strictEqual(span.spanId, logRecord.spanId, "span and log share the spanId"); + t.ok(isNanoTimestampWithinHour(span.startTimeUnixNano), "span startTimeUnixNano is reasonable"); + t.ok(isNanoTimestampWithinHour(span.endTimeUnixNano), "span endTimeUnixNano is reasonable"); t.end(); }); @@ -640,7 +517,7 @@ test("OTLP protobuf encodes logs and spans on the wire", async t => { t.end(); }); -test("OLTP multiple instances should work independently", async t => { +test("OTLP instances export independently, each with its own service.name", async t => { const { calls } = stubFetch(); const otlp = { otlpHttpBaseURI: "http://127.0.0.1:4318", stderr: () => {} }; @@ -656,19 +533,14 @@ test("OLTP multiple instances should work independently", async t => { t.strictEqual(calls.length, 4, "two log exports + two trace exports"); - for (const call of calls.filter(call => call.path === "/v1/logs")) { - const logRecord = call.body.resourceLogs[0].scopeLogs[0].logRecords[0]; - const serviceName = call.body.resourceLogs[0].resource.attributes.find((attr: any) => attr.key === "service.name").value.stringValue; + const serviceFor = (msg: string) => { + const call = calls.find(call => call.path === "/v1/logs" && call.body.resourceLogs[0].scopeLogs[0].logRecords[0].body.stringValue === msg)!; - if (logRecord.body.stringValue === "rappakalja") { - t.strictEqual(serviceName, "log1", "service.name for rappakalja is log1"); - } else if (logRecord.body.stringValue === "bollhav") { - t.strictEqual(serviceName, "log2", "service.name for bollhav is log2"); - } else { - t.fail(`Unexpected log body: "${logRecord.body.stringValue}"`); - } - } + return call.body.resourceLogs[0].resource.attributes.find((attr: any) => attr.key === "service.name").value.stringValue; + }; + t.strictEqual(serviceFor("rappakalja"), "log1", "first instance keeps its service.name"); + t.strictEqual(serviceFor("bollhav"), "log2", "second instance keeps its service.name"); t.end(); }); @@ -696,31 +568,32 @@ test("parseTraceparent rejects malformed headers", t => { t.end(); }); -test("Log adopts an incoming traceparent (distributed trace continuation)", t => { +test("traceparent adoption: incoming joins; malformed, parentLog and clone do not", t => { const traceId = generateTraceId(); const spanId = generateSpanId(); - const log = new Log({ traceparent: formatTraceparent(traceId, spanId) }); - t.strictEqual(log.span.traceId, traceId, "log joins the incoming trace"); - t.strictEqual(log.span.parentSpanId, spanId, "the incoming span becomes the parent span"); - t.end(); -}); + // An incoming traceparent: join the trace and nest under its span. + const adopted = new Log({ traceparent: formatTraceparent(traceId, spanId) }); -test("Log ignores a malformed traceparent and starts a fresh trace", t => { - let log!: Log; + t.strictEqual(adopted.span.traceId, traceId, "adopts the incoming trace"); + t.strictEqual(adopted.span.parentSpanId, spanId, "nests under the incoming span"); - t.doesNotThrow(() => { log = new Log({ traceparent: "not-a-traceparent" }); }, "malformed traceparent does not throw (untrusted input)"); - t.ok(/^[0-9a-f]{32}$/.test(log.span.traceId), "a fresh traceId is generated"); - t.strictEqual(log.span.parentSpanId, undefined, "no parent span is set"); - t.end(); -}); + // Malformed (untrusted) input is ignored: a fresh trace starts, no throw. + let fresh!: Log; -test("parentLog wins over traceparent", t => { + t.doesNotThrow(() => { fresh = new Log({ traceparent: "not-a-traceparent" }); }, "malformed traceparent does not throw"); + t.notStrictEqual(fresh.span.traceId, traceId, "malformed traceparent starts a fresh trace"); + t.strictEqual(fresh.span.parentSpanId, undefined, "no parent span for a fresh trace"); + + // An in-process parentLog wins over a supplied traceparent. const parent = new Log(); - const child = new Log({ parentLog: parent, traceparent: formatTraceparent(generateTraceId(), generateSpanId()) }); + const child = new Log({ parentLog: parent, traceparent: formatTraceparent(traceId, spanId) }); + + t.strictEqual(child.span.traceId, parent.span.traceId, "parentLog trace wins over the header"); + t.strictEqual(child.span.parentSpanId, parent.span.spanId, "parentLog span is the parent"); - t.strictEqual(child.span.traceId, parent.span.traceId, "in-process parent trace takes precedence"); - t.strictEqual(child.span.parentSpanId, parent.span.spanId, "the parent span is the parent, not the header span"); + // A clone is its own trace, never re-adopting the base's traceparent. + t.notStrictEqual(adopted.clone().span.traceId, adopted.span.traceId, "clone starts its own trace"); t.end(); }); @@ -731,50 +604,34 @@ test("log.traceparent() emits the current span context", t => { t.end(); }); -test("clone() does not re-adopt the traceparent (its own trace)", t => { - const base = new Log({ traceparent: formatTraceparent(generateTraceId(), generateSpanId()) }); - const clone = base.clone(); - - t.notStrictEqual(clone.span.traceId, base.span.traceId, "clone starts its own trace, not the adopted one"); - t.end(); -}); - // --- log.fetch() auto-instrumentation -------------------------------------- -test("log.fetch injects a traceparent and returns the response", async t => { +test("log.fetch traces a successful call and drops the query by default", async t => { const { calls } = stubFetch(); - const log = new Log({ otlpHttpBaseURI: "http://127.0.0.1:4318", stderr: () => {} }); + const log = new Log({ context: { "service.name": "svc" }, otlpHttpBaseURI: "http://127.0.0.1:4318", stderr: () => {} }); - const res = await log.fetch("https://api.test/users"); + const res = await log.fetch("https://api.test:8443/users?token=secret&q=hi", { method: "POST" }); await log.end(); - t.strictEqual(res.status, 200, "the underlying response is returned to the caller"); - - const parsed = parseTraceparent(callHeader(calls.find(call => call.path === "/users")!, "traceparent") ?? ""); - - t.ok(parsed, "outgoing request carries a valid traceparent"); - t.strictEqual(parsed!.traceId, log.span.traceId, "outgoing trace continues this log's trace"); - t.notStrictEqual(parsed!.spanId, log.span.spanId, "a fresh child span id is propagated, not the calling span's"); - t.end(); -}); + t.strictEqual(res.status, 200, "the underlying response is returned"); -test("log.fetch exports a CLIENT span with url.full query dropped by default", async t => { - const { calls } = stubFetch(); - const log = new Log({ context: { "service.name": "svc" }, otlpHttpBaseURI: "http://127.0.0.1:4318", stderr: () => {} }); + // The outgoing request continues this log's trace under a fresh child span. + const sent = parseTraceparent(callHeader(calls.find(call => call.path === "/users")!, "traceparent") ?? ""); - await log.fetch("https://api.test:8443/users?token=secret&q=hi", { method: "POST" }); - await log.end(); + t.strictEqual(sent?.traceId, log.span.traceId, "outgoing request continues this log's trace"); + t.notStrictEqual(sent?.spanId, log.span.spanId, "a fresh child span id is propagated, not the calling span's"); const span = clientSpan(calls); const attr = (key: string) => span.attributes.find((attribute: any) => attribute.key === key)?.value.stringValue; t.strictEqual(span.kind, 3, "client span kind"); - t.strictEqual(span.name, "POST api.test:8443", "low-cardinality span name (method + host)"); - t.strictEqual(span.parentSpanId, log.span.spanId, "fetch span nests under the calling log span"); + t.strictEqual(span.name, "POST api.test:8443", "low-cardinality name (method + host)"); + t.strictEqual(span.parentSpanId, log.span.spanId, "span nests under the calling log span"); + t.strictEqual(span.spanId, sent?.spanId, "the propagated span id is the exported span"); t.strictEqual(attr("http.request.method"), "POST", "method attribute"); - t.strictEqual(attr("url.full"), "https://api.test:8443/users", "url.full has no query string and no userinfo by default"); - t.strictEqual(attr("url.scheme"), "https", "url.scheme attribute"); + t.strictEqual(attr("url.full"), "https://api.test:8443/users", "url.full drops query and userinfo"); + t.strictEqual(attr("url.scheme"), "https", "scheme attribute"); t.strictEqual(attr("server.address"), "api.test", "server.address attribute"); t.strictEqual(attr("server.port"), "8443", "server.port attribute"); t.strictEqual(attr("http.response.status_code"), "200", "status_code attribute"); @@ -797,13 +654,7 @@ test("log.fetch captureQuery keeps the query but redacts known-sensitive keys", }); test("log.fetch captures allow-listed request and response headers only", async t => { - const { calls } = stubFetch(path => { - if (path === "/h") { - return fetchResponse({ headers: new Headers({ "x-resp": "rv", "x-secret": "nope" }) }); - } - - return undefined; - }); + const { calls } = stubFetch(path => path === "/h" ? response({ headers: new Headers({ "x-resp": "rv", "x-secret": "nope" }) }) : undefined); const log = new Log({ captureRequestHeaders: ["x-req"], captureResponseHeaders: ["x-resp"], @@ -824,35 +675,21 @@ test("log.fetch captures allow-listed request and response headers only", async t.end(); }); -test("log.fetch marks 4xx/5xx responses as error spans but still returns them", async t => { +test("log.fetch marks error spans for 4xx and for network failures, propagating each outcome", async t => { const { calls } = stubFetch(path => { - if (path === "/missing") { - return fetchResponse({ status: 404 }); - } + if (path === "/missing") return response({ status: 404 }); + if (path === "/boom") throw Object.assign(new Error("down"), { code: "ECONNREFUSED" }); return undefined; }); const log = new Log({ otlpHttpBaseURI: "http://127.0.0.1:4318", stderr: () => {} }); + // A 4xx is a returned response, not an exception. const res = await log.fetch("https://api.test/missing"); - await log.end(); - - t.strictEqual(res.status, 404, "a 4xx response is still returned (it is not an exception)"); - t.strictEqual(clientSpan(calls).status.code, 2, "span status is ERROR for 4xx"); - t.end(); -}); - -test("log.fetch records error.type and re-throws on a network failure", async t => { - const { calls } = stubFetch(path => { - if (path === "/boom") { - throw Object.assign(new Error("down"), { code: "ECONNREFUSED" }); - } - - return undefined; - }); - const log = new Log({ otlpHttpBaseURI: "http://127.0.0.1:4318", stderr: () => {} }); + t.strictEqual(res.status, 404, "a 4xx response is still returned"); + // A network failure re-throws unchanged. let threw = false; try { @@ -860,15 +697,18 @@ test("log.fetch records error.type and re-throws on a network failure", async t } catch { threw = true; } + t.ok(threw, "the underlying network error propagates to the caller"); await log.end(); - t.ok(threw, "the underlying fetch error propagates to the caller"); - - const span = clientSpan(calls); + const spans = calls.filter(call => call.path === "/v1/traces").map(call => call.body.resourceSpans[0].scopeSpans[0].spans[0]); + const attr = (span: any, key: string) => span.attributes.find((attribute: any) => attribute.key === key)?.value.stringValue; + const span404 = spans.find(span => attr(span, "http.response.status_code") === "404")!; + const spanBoom = spans.find(span => attr(span, "error.type") === "ECONNREFUSED")!; - t.strictEqual(span.status.code, 2, "span status is ERROR"); - t.strictEqual(span.attributes.find((attribute: any) => attribute.key === "error.type").value.stringValue, "ECONNREFUSED", "error.type captured from the error code"); + t.strictEqual(span404.status.code, 2, "the 4xx span is ERROR"); + t.strictEqual(spanBoom.status.code, 2, "the network-failure span is ERROR"); + t.strictEqual(attr(spanBoom, "error.type"), "ECONNREFUSED", "error.type captured from the error code"); t.end(); }); @@ -892,8 +732,7 @@ test("await log.end() drains a fire-and-forget log.fetch span", async t => { await log.end(); - // The span must be delivered by the time end() resolves, even though the fetch was not awaited — - // otherwise a short-lived process would exit before the span is exported. + // The span must be delivered by the time end() resolves, else a short-lived process would exit first. t.strictEqual(clientSpan(calls).name, "GET api.test", "the client span was exported before end() resolved"); t.end(); }); @@ -912,7 +751,6 @@ test("log.fetch with an invalid header rejects but never hangs end()", async t = } // Must resolve, not hang — the tracked promise has to settle even when setup throws. - // (The harness fails the test on a >10s hang.) await log.end(); t.ok(threw, "the setup error propagates to the caller"); @@ -928,16 +766,6 @@ test("log.fetch throws when the log is already ended", async t => { t.end(); }); -test("clone() inherits captureQuery and the header allow-lists", t => { - const base = new Log({ captureQuery: true, captureRequestHeaders: ["x-req"], captureResponseHeaders: ["x-resp"] }); - const clone = base.clone(); - - t.strictEqual(clone.conf.captureQuery, true, "captureQuery inherited"); - t.deepEqual(clone.conf.captureRequestHeaders, ["x-req"], "request header allow-list inherited"); - t.deepEqual(clone.conf.captureResponseHeaders, ["x-resp"], "response header allow-list inherited"); - t.end(); -}); - test("log.fetch works without OTLP, still injecting a traceparent", async t => { const { calls } = stubFetch(); const log = new Log({ stderr: () => {} });