From 18e894301c742f60151b9ebf56486ea6eb4b72e3 Mon Sep 17 00:00:00 2001 From: Benoit TRAVERS Date: Sun, 16 Aug 2026 16:37:00 +0200 Subject: [PATCH 1/2] feat(observability): a strict Logger port, correlated with the kernel's units MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit @btravstack/observability is the eighth package: observability for the kernel, starting with logging. Named for the whole because logs, traces and metrics share a correlation id, a resource, a config slice and a flush-on-shutdown lifecycle — splitting them would duplicate all four. Logger is a di port over a deliberately strict interface, and every difference from NestJS's logger is a defect it does not have: a port rather than a class you new (no static, no useLogger reaching past DI), with(attributes) returning a new logger rather than setContext mutating the one every caller shares, a flat record of scalars rather than any varargs, a dedicated cause channel, six fixed levels, one argument order across all six methods, and a guarantee that a log call cannot throw. createLogger reads currentUnit() per call, so every line written inside a unit carries its traceId, unitId and tenantId with nothing threaded through the call stack. observability({ sink?, level? }) provides Logger and LoggerConfig, bound from LOG_LEVEL and validated once — a level outside the six is a ConfigInvalid, exit 78, not a silent fallback. jsonSink is the default (one JSON object per line on stdout, no runtime dependency); pinoSink lives behind the /pino subpath with pino as an optional peer. kernelEvents(logger) puts the kernel's nine lifecycle events in the same stream, each event's fields kept as attributes. The examples consume it: order-application no longer declares its own Logger port, each composition root imports observability(), and order-api's main.ts shows the onEvent wiring — with the reason that logger is built by hand. Traces and metrics are not here yet; their shape is recorded in packages/observability/CLAUDE.md. --- .changeset/observability.md | 37 ++ CLAUDE.md | 193 ++++++-- docs/.vitepress/config.ts | 3 + docs/api/index.md | 10 +- docs/examples/order-amqp-worker.md | 32 +- docs/examples/order-api.md | 60 ++- docs/examples/order-application.md | 45 +- docs/examples/order-temporal-worker.md | 19 +- docs/explanation/ambient-vs-context.md | 21 +- docs/explanation/design-decisions.md | 24 + docs/explanation/nothing-throws.md | 12 +- docs/explanation/starters.md | 24 +- docs/explanation/why-start.md | 15 +- docs/how-to/consume-amqp-messages.md | 19 +- docs/how-to/log-and-correlate.md | 275 +++++++++++ docs/how-to/open-a-per-request-scope.md | 34 +- docs/how-to/read-the-ambient-unit.md | 84 ++-- docs/how-to/run-a-temporal-worker.md | 22 +- docs/how-to/serve-orpc-over-http.md | 37 +- docs/how-to/test-an-application.md | 119 +++-- docs/index.md | 6 +- docs/reference/amqp.md | 15 +- docs/reference/glossary.md | 31 +- docs/reference/http.md | 9 +- docs/reference/observability.md | 435 ++++++++++++++++++ docs/reference/packages.md | 83 ++-- docs/reference/testing.md | 51 +- docs/scripts/build-api.ts | 11 +- docs/tutorial/getting-started.md | 2 + docs/typedoc.observability.json | 10 + examples/README.md | 18 +- examples/order-amqp-worker/README.md | 15 +- examples/order-amqp-worker/package.json | 1 + .../src/amqp-runtime.spec.ts | 38 +- examples/order-amqp-worker/src/handlers.ts | 11 +- examples/order-amqp-worker/src/module.ts | 8 +- .../src/needs-gate.test-d.ts | 12 +- .../order-amqp-worker/src/outbox-relay.ts | 29 +- .../order-amqp-worker/src/test-fixtures.ts | 61 ++- examples/order-api/README.md | 40 +- examples/order-api/package.json | 1 + examples/order-api/src/api.spec.ts | 22 +- examples/order-api/src/main.ts | 27 +- examples/order-api/src/module.ts | 12 +- examples/order-api/src/needs-gate.test-d.ts | 9 +- examples/order-api/src/request-scope.ts | 6 +- examples/order-api/src/test-fixtures.ts | 68 ++- examples/order-application/README.md | 53 ++- examples/order-application/package.json | 3 +- examples/order-application/src/index.ts | 1 - examples/order-application/src/logger.ts | 23 - examples/order-application/src/module.ts | 24 +- .../src/needs-gate.test-d.ts | 19 +- .../order-application/src/place-order.spec.ts | 20 +- examples/order-application/src/ports.ts | 5 - .../order-application/src/test-fixtures.ts | 45 +- examples/order-application/src/use-cases.ts | 5 +- examples/order-infrastructure/README.md | 9 +- examples/order-temporal-worker/README.md | 9 +- examples/order-temporal-worker/package.json | 1 + .../order-temporal-worker/src/fulfillment.ts | 9 +- examples/order-temporal-worker/src/module.ts | 8 +- .../src/temporal-runtime.spec.ts | 19 +- .../src/test-fixtures.ts | 41 +- packages/core/CLAUDE.md | 8 +- packages/observability/CLAUDE.md | 165 +++++++ packages/observability/LICENSE | 21 + packages/observability/README.md | 103 +++++ packages/observability/package.json | 93 ++++ packages/observability/src/config.ts | 38 ++ packages/observability/src/index.ts | 7 + packages/observability/src/json-sink.spec.ts | 129 ++++++ packages/observability/src/json-sink.ts | 68 +++ packages/observability/src/logger.spec.ts | 194 ++++++++ packages/observability/src/logger.ts | 175 +++++++ .../observability/src/observability.spec.ts | 173 +++++++ packages/observability/src/observability.ts | 116 +++++ packages/observability/src/pino.spec.ts | 81 ++++ packages/observability/src/pino.ts | 40 ++ packages/observability/src/test-fixtures.ts | 166 +++++++ packages/observability/src/vitest.d.ts | 1 + packages/observability/tsconfig.json | 11 + packages/observability/vitest.config.ts | 15 + pnpm-lock.yaml | 158 ++++++- pnpm-workspace.yaml | 1 + turbo.json | 1 + 86 files changed, 3671 insertions(+), 503 deletions(-) create mode 100644 .changeset/observability.md create mode 100644 docs/how-to/log-and-correlate.md create mode 100644 docs/reference/observability.md create mode 100644 docs/typedoc.observability.json delete mode 100644 examples/order-application/src/logger.ts create mode 100644 packages/observability/CLAUDE.md create mode 100644 packages/observability/LICENSE create mode 100644 packages/observability/README.md create mode 100644 packages/observability/package.json create mode 100644 packages/observability/src/config.ts create mode 100644 packages/observability/src/index.ts create mode 100644 packages/observability/src/json-sink.spec.ts create mode 100644 packages/observability/src/json-sink.ts create mode 100644 packages/observability/src/logger.spec.ts create mode 100644 packages/observability/src/logger.ts create mode 100644 packages/observability/src/observability.spec.ts create mode 100644 packages/observability/src/observability.ts create mode 100644 packages/observability/src/pino.spec.ts create mode 100644 packages/observability/src/pino.ts create mode 100644 packages/observability/src/test-fixtures.ts create mode 100644 packages/observability/src/vitest.d.ts create mode 100644 packages/observability/tsconfig.json create mode 100644 packages/observability/vitest.config.ts diff --git a/.changeset/observability.md b/.changeset/observability.md new file mode 100644 index 0000000..fea1aa9 --- /dev/null +++ b/.changeset/observability.md @@ -0,0 +1,37 @@ +--- +"@btravstack/observability": minor +--- + +**`@btravstack/observability`** — observability for the kernel, starting with +logging. + +`Logger` is a di port over a deliberately strict interface, and every +difference from NestJS's logger is a defect it does not have: a port rather +than a class you `new` (no static instance, no `useLogger` reaching past DI), +`with(attributes)` returning a new logger rather than `setContext` mutating the +one every caller shares, a flat record of scalars rather than `any` varargs, a +dedicated `cause` channel (an `Error`'s `message` and `stack` are +non-enumerable, so `JSON.stringify` alone drops exactly the part worth +keeping), six fixed levels, and a guarantee that a log call cannot throw — a +broken sink is swallowed rather than becoming an outage. + +- **Correlation is not the caller's job.** `createLogger` reads + `currentUnit()` **per call**, so every line written inside a unit carries its + `traceId`, `unitId` and `tenantId` — one application-scope logger, correct + for every request, with nothing threaded through the call stack. +- **`observability({ sink?, level? })`** provides `Logger` and `LoggerConfig`, + bound from `LOG_LEVEL` (default `info`) and validated once: a level outside + the six is a `ConfigInvalid` naming the variable, exit `78` under `runMain`, + rather than a silent fallback. +- **`jsonSink`** is the default — one JSON object per line on stdout, no + runtime dependency — with the unit's ids as top-level fields a log backend + indexes. **`pinoSink`** lives behind the `@btravstack/observability/pino` + subpath, with `pino` as an optional peer; the level filter stays this + package's, so there is one filter in the process. +- **`kernelEvents(logger)`** turns the kernel's nine lifecycle events into log + lines in that same stream, keeping each event's fields as attributes — pass + it as `StartOptions.onEvent`. + +Traces and metrics are not here yet; the package is named for the whole because +logs, traces and metrics share a correlation id, a resource, a config slice and +a flush-on-shutdown lifecycle. diff --git a/CLAUDE.md b/CLAUDE.md index 49cd569..4229bc6 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -19,16 +19,20 @@ already-proven graph is constructed and torn down, and nothing more. Nothing throws to callers: every fallible operation returns an [`unthrown`](https://github.com/btravstack/unthrown) `Result`. -pnpm workspace + turbo monorepo. `packages/` holds seven published packages, +pnpm workspace + turbo monorepo. `packages/` holds eight published packages, `di` (the container), `config` (configuration from the environment, as providers), `core` (the kernel), `testing` (the test harness — `bootFixture`, -`tapped`, the in-memory runtime, the fake clock; peers on `core`), `http` +`tapped`, the in-memory runtime, the fake clock; peers on `core`), +`observability` (the logging starter — a `Logger` port correlated with the +ambient unit, a JSON sink, the kernel's events as lines), `http` (the HTTP starter — oRPC), `temporal` (the Temporal starter) and `amqp` (the AMQP starter). `di` was its own repository until it was merged here **with its history**; it is the one package that depends on nothing else in this workspace, and the dependencies run `core` → `config` → `di`, never -back, with `testing` and the three starters on `core`. Its own spec is -`packages/di/CLAUDE.md`; the harness's is `packages/testing/CLAUDE.md`. +back, with `testing`, `observability` and the three transport starters on +`core`. Its own spec is `packages/di/CLAUDE.md`; the harness's is +`packages/testing/CLAUDE.md`; the logging starter's is +`packages/observability/CLAUDE.md`. `examples/` holds ten private ones — a clean-architecture application (`order-domain` → `order-application` → `order-infrastructure`) booted under three runtimes (`order-api`, `order-temporal-worker`, `order-amqp-worker`), @@ -112,8 +116,14 @@ hook). User-facing changes need a changeset. not this one. A repository pulled from an ambient store is the untestable coupling; a tenant id read by the Postgres adapter is not. Legitimate readers are - infrastructure adapters only (logger, OTel exporter, database adapter); - application code reading the store is meant to be a lint error, in the spirit + infrastructure adapters only (logger, OTel exporter, database adapter), and + the logger is no longer hypothetical: `@btravstack/observability`'s + `createLogger` reads `currentUnit()` **per call** and stamps `unitId` / + `traceId` / `tenantId` on every line, so an application writes + `logger.info("placing an order", { orderId, quantity })` and mentions + correlation nowhere. Per call, not at construction, is the load-bearing + half — one logger is built per scope and every unit has its own record. + Application code reading the store is meant to be a lint error, in the spirit of `unthrown/no-catch-all-pattern` stating unthrown's own default. **That rule does not exist yet** — it needs a way to identify an adapter, a convention this stack has not established — so today it is a documented @@ -520,7 +530,8 @@ use) => Promise` (vitest's fixture protocol, hence no vitest import or `boot: bootFixture(...)` its `serve` fixtures build on. - **`tapped(module, ports)`** → `{ module, services() }` (`ServicesOf

`). `start` hands the application context to the runtime alone, so a test that - wants the very `Logger` the use cases write to has no `ctx.get`; `tapped` + wants the very `OrderRepository` the use cases wrote through has no + `ctx.get`; `tapped` composes one more provider (`Tap`, `Port("@btravstack/testing/Tap")` declared once and never exported — two taps in one graph are di's duplicate-provider defect, and one per application is the case; the id is @@ -532,7 +543,10 @@ use) => Promise` (vitest's fixture protocol, hence no vitest import or site); **`services()` throws** before the graph is built — reading a tap nobody booted is a bug in the test, not an `undefined` an assertion could swallow. What `order-api`, `order-temporal-worker` and `order-amqp-worker` - hand-rolled as `LoggerTap` / `ServicesTap` providers. + hand-rolled as `LoggerTap` / `ServicesTap` providers. **Log lines no longer + need it**: `observability({ sink })` is a value the composition takes, so + the two worker examples tap only their services and `order-api` taps + nothing at all — a spec reads `Line` values back through its own sink. - **`withApp(module, options, use)`** — start, hand to `use`, stop again whatever `use` does. `signals` and `probes` are **forced off** whatever the caller passes; a test needing the real probe server calls `start` directly. @@ -563,6 +577,79 @@ never, never>` providing the runtime on **`TestRuntimePort`** (its port, real macrotask at each end so a test can trigger a shutdown and advance in the very next statement without racing the kernel arming its next sleep. +### `@btravstack/observability` + +Logging, as a starter. The package is named for the whole of observability +because logs, traces and metrics share a correlation id, a resource, a config +slice and a flush-on-shutdown lifecycle; **traces and metrics are not here +yet** and must never be described as shipped. Its own spec is +`packages/observability/CLAUDE.md`, which holds the argument in full and the +deferred shape. + +- **`Logger`** — `Port("Logger")`, the **framework's** port + rather than each application's, because the framework logs too + (`kernelEvents`) and one port has to serve both. `LoggerService` is + `log(level, message, attributes?, cause?)`, one method per level + (`trace`/`debug`/`info`/`warn` take `(message, attributes?)`; + `error`/`fatal` take `(message, cause?, attributes?)` — the failure second, + because that is the argument a caller of those two always has), `with` and + `isEnabled`. Six differences from NestJS's `Logger`, each a defect this + shape does not have: a port rather than a class you `new`; `with` returning + a value rather than `setContext` mutating the shared instance; `Attributes` + a flat record of scalars rather than `any` varargs; a dedicated `cause`; + it cannot throw; and correlation is the implementation's job. Every method + is synchronous `void` — this package's Thesis #6 exemption, since a log call + is fire-and-forget and a lost line is not a modeled error. +- **`Level` / `LEVELS` / `Attributes`** — six levels, ordered, exported as an + array so `LOG_LEVEL` validates against one list; `Attributes` is + `Readonly>`. +- **`createLogger(sink, level?)`** — the implementation. `currentUnit()` is + read **per call** (capturing it would stamp the first unit's trace id on + every line thereafter), a line below `level` never reaches the sink, and + every write is wrapped in a `try` that swallows, because a logger that + throws turns an observability fault into an outage. +- **`Line` / `Sink`** — `{ level, message, attributes, cause, time, unit }`, + where `unit` is `undefined` outside a unit and + `{ unitId, traceId, tenantId? }` inside one. A `Sink` is + `(line: Line) => void` and is allowed to throw; `createLogger` is what makes + that safe. +- **`jsonSink(stream?)`** — the default: one JSON object per line on + `process.stdout`. The unit's ids are spread at the **top level**, not nested + under `unit`, because `traceId` is the field an operator searches; a + caller's attribute can never overwrite one of those or `level`/`message`/ + `time` (spread order); an `Error` `cause` is normalised to + `{ name, message, stack, cause }` and walked up to four levels, the same + rule and the same reason as the kernel's `stderrSink`; a payload + `JSON.stringify` refuses falls back to `"[unserialisable]"`. +- **`observability({ sink?, level? })`** — the starter, a + `Module`. `level` **pins** + through `Config.pinned` (explicit > env > default, per field). An + application that wants its own implementation provides `Logger` itself and + does not import this. +- **`LoggerConfig` / `logLevel({ default? })`** — `{ level }`, bound through + `Config.provider` from `LOG_LEVEL` (default `info`). A value outside the six + is a `ConfigInvalid` naming the variable and the set — `startFailed`, exit + `78`, before a line is written — rather than a silent fallback. `logLevel` + is that field alone, for an application composing its own schema. +- **`kernelEvents(logger)`** — the kernel's nine events as an `EventSink` for + `StartOptions.onEvent`. The mapping is deliberate: `startFailed` and + `uncaught` are `error` and carry their `cause`; `teardownError` is `warn` + (the application is already stopping and the exit code says `2`) and does + **not** carry its cause, only `{ event, port }`; everything else is `info`. + Each event's own fields become attributes, and every line carries `event`. + The logger is a **parameter**, not resolved from the graph: `building` is + emitted while the graph is still being built, so the sink cannot come from + the context it is watching — which is why `examples/order-api/src/main.ts` + passes `kernelEvents(createLogger(jsonSink()))` by hand, a second logger, + deliberately, and the only one the framework asks anybody to construct. It + reads no `LOG_LEVEL` for the same reason. +- **`pinoSink(logger)`** — the `@btravstack/observability/pino` subpath, with + `pino` an **optional** peer. The level filter stays **ours** — `createLogger` + has already decided the line is worth writing — so pino is configured at + `trace`, one filter in the process, and it is the one `LOG_LEVEL` validated. + The cause goes over as `err`, which pino's own serialiser renders with the + stack. + ### `@btravstack/http`, `@btravstack/temporal` and `@btravstack/amqp` Their public surfaces live in `packages/http/CLAUDE.md`, @@ -732,13 +819,19 @@ namespace }` back off `Serving.info`. The Worker's lifecycle, the unit per `StockService` and `ShippingService` — closures over the services, no context read at call time — and the composition root is `TemporalModule("OrderTemporalWorker")({ contract, activities: -orderActivities, workflows, imports })`, the sugar importing the starter; - the connection and `TEMPORAL_*` come from the starter. `order-amqp-worker` is +orderActivities, workflows, imports: [Application, Persistence, Fulfillment, +observability()] })`, the sugar importing the starter; + the connection and `TEMPORAL_*` come from the starter, and `LOG_LEVEL` and + the `Logger` the saga's stand-in services write to come from + `observability()`. `order-amqp-worker` is the same shape (`orderHandlers = AmqpHandlers(orderContract)([Logger], { sync })`, - `AmqpModule("OrderAmqpWorker")({ contract, handlers: orderHandlers, … })`), + `AmqpModule("OrderAmqpWorker")({ contract, handlers: orderHandlers, imports: +[Application, Persistence, observability()], … })`), with its outbox relay a resourceful provider of its own rather than - something layered onto the runtime. Both are also where **honouring the + something layered onto the runtime — the relay is also the one place in the + examples that logs a **failure**, `logger.error(message, cause, { eventId })` + down each of its three arms. Both are also where **honouring the kernel's deadline through the ambient record** is worked: neither middleware injects anything into the call — `next()` unchanged — so `currentUnit()?.signal` is the only route to it, and what each answers when @@ -755,14 +848,24 @@ sync })`, `FindOrder`, so oRPC's context stays empty and nothing is located from a context at call time, never a module-level singleton — and **`HttpModule("OrderApi")({ router: orderRouter, imports: [Application, -Persistence], exports: [Logger] })`** is the whole composition root — the +Persistence, observability()], exports: [Logger] })`** is the whole + composition root — the sugar imports `http()`, provides the router on the starter's `HttpRouterPort` and exports `HttpRuntime`: `OrderApi` is a constant, `PORT`/`HOST` come from the - environment inside the graph, the router is mounted under `/rpc`. `RequestModule` rides `StartOptions.unit` so + environment inside the graph, the router is mounted under `/rpc`. + `observability()` is what provides the `Logger` the interactors and the + request scope write to, and `Logger` is in `exports` because `RequestModule` + reads it out of the application scope. `RequestModule` rides + `StartOptions.unit` so the per-request fork is the kernel's. There is no `runtime`, `needs`, - `handler`, `port` or env-reading to spell anywhere: `main.ts` is `await -runMain(OrderApi, { unit: RequestModule })`. Each procedure is a plain + `handler`, `port` or env-reading to spell anywhere. It is also the **one** + `main.ts` that is not a single line: it passes + `onEvent: kernelEvents(createLogger(jsonSink()))` so the kernel's nine events + land in the application's own stream, with the logger built by hand because + `building` is emitted while the graph still is. The other two stay one line + — the kernel's stderr sink is a fine default and this is the upgrade, not + the requirement. Each procedure is a plain `Result`-returning function typed by the contract (`@unthrown/orpc`'s `.result()` handler, attached by `HttpRouter(orderContract)`). It reads `port` back off @@ -795,11 +898,17 @@ runMain(OrderApi, { unit: RequestModule })`. Each procedure is a plain so a consumer still installs one copy of it themselves. `di` itself peers on `unthrown` and depends on nothing; `config` peers on `di` and `unthrown`; `core` peers on all three; `testing` peers on all four (and not on - `vitest` — `bootFixture` is a plain function in vitest's fixture shape). A + `vitest` — `bootFixture` is a plain function in vitest's fixture shape); + `observability` peers on all four too and has **no runtime dependency of its + own** — the default sink is `JSON.stringify` and a `write`. A **starter** is the exception by definition: `@btravstack/http` peers on `@orpc/server`, `@orpc/contract` and `@unthrown/orpc` — peers, not dependencies, so an application holds one - copy of each. + copy of each. `@btravstack/observability` carries the family's one + **optional** peer, `pino`, needed only by the + `@btravstack/observability/pino` subpath: a consumer that never imports it + never installs it, and the package's own `tsdown` build emits `src/pino.ts` + as a second entry point for exactly that. - **`packages/core`'s specs use `@btravstack/testing`, which peers on core — and it is NOT a devDependency of core**, because that would be a package-graph cycle turbo refuses. Instead: `packages/core/tsconfig.json` @@ -813,14 +922,14 @@ runMain(OrderApi, { unit: RequestModule })`. Each procedure is a plain `@btravstack/core#typecheck` an explicit edge on `@btravstack/testing#build`; `knip.json` ignores the dependency for `packages/core`. Four places; a change to one is a change to all. -- `declarationMap: false` on all seven published packages — the published +- `declarationMap: false` on all eight published packages — the published tarball has no `src/`, so maps would be dead ends. - **Relative imports carry `.js`.** `moduleResolution: NodeNext` plus `verbatimModuleSyntax`, both inherited from `@btravstack/tsconfig/base.json` — an external package under `node_modules`, so this is the one convention here the repo itself cannot show you. `import { x } from "./units"` fails `pnpm typecheck` with TS2835. -- All seven published packages claim `engines: { node: ">=20" }` while the root +- All eight published packages claim `engines: { node: ">=20" }` while the root claims `>=22.19`. The divergence is **deliberate**: the root floor is the dev toolchain's, a package's is a compatibility promise to consumers. Do not align them for tidiness — raising a published floor is a breaking change. @@ -845,7 +954,10 @@ runMain(OrderApi, { unit: RequestModule })`. Each procedure is a plain defects `run-main.spec.ts`, `drain.spec.ts` and `with-app.spec.ts` mint — `Defect` has no public constructor, so a throw inside a combinator is the only way — plus `with-app.spec.ts`'s stand-in for a failing `expect`): five - in `packages/core/src`, eight in `packages/testing/src`. `no-get-or-throw` is switched off for the `**/*.spec.ts` **and + in `packages/core/src`, eight in `packages/testing/src`, two in + `packages/observability/src` (`test-fixtures.ts`'s `Recorder.only()`, a loud + fixture guard, and `logger.spec.ts`'s throwing sink, which is the subject + under test). `no-get-or-throw` is switched off for the `**/*.spec.ts` **and `**/test-fixtures.ts`** globs through an `overrides` entry — the exemption the rule's own diagnostic prescribes, since `getOrThrow()` is the right tool in a test, and a fixture module is test code that merely does not end in @@ -863,9 +975,9 @@ runMain(OrderApi, { unit: RequestModule })`. Each procedure is a plain a plausible "simplification" (the `teardownErrors` aliasing, the `ready()` latch, the monotonic `completed`), which is what the surviving comments are. - Conventional commits (`feat:`, `fix:`, `docs:`, `test:`, `chore:`). -- Coverage thresholds are 100% lines/functions on `packages/core` and on - `packages/testing`, with each package's `test-fixtures.ts` (test code, per - the Test conventions) excluded. +- Coverage thresholds are 100% lines/functions on `packages/core`, + `packages/testing` and `packages/observability`, with each package's + `test-fixtures.ts` (test code, per the Test conventions) excluded. - Test mechanics: `@unthrown/vitest`'s matchers are registered via `setupFiles` (`toBeOk`, `toBeOkWith`, `toBeErrTagged`, …). Timing is asserted through `createFakeClock`, never a real `setTimeout` — a kernel whose own tests are @@ -883,7 +995,7 @@ runMain(OrderApi, { unit: RequestModule })`. Each procedure is a plain `packages/http/CLAUDE.md`, `packages/temporal/CLAUDE.md` or `packages/amqp/CLAUDE.md`, whichever is where that package's public surface lives — or `packages/di/CLAUDE.md` for the container. There are - **eight** `CLAUDE.md` files; naming the wrong one is how the last drift + **nine** `CLAUDE.md` files; naming the wrong one is how the last drift happened. ## Documentation site @@ -899,11 +1011,12 @@ was folded in here when the container was merged; nothing under - **TypeDoc runs from `docs/`, not from the packages** — it needs its own TypeScript (`catalog:typedoc` pins 6.0.3; 7.x is the native port and ships - no `typescript.js`). One `typedoc..json` per package — seven — points + no `typescript.js`). One `typedoc..json` per package — eight — points at that package's `src/index.ts` (core's one entry point; the doubles are - `typedoc.testing.json`'s) and writes straight into `api//` - (gitignored; `docs/api/index.md` is the one committed file there); - `scripts/build-api.ts` runs the seven concurrently. + `typedoc.testing.json`'s, and `typedoc.observability.json` names two entry + points, `src/index.ts` and `src/pino.ts`) and writes straight into + `api//` (gitignored; `docs/api/index.md` is the one committed file + there); `scripts/build-api.ts` runs the eight concurrently. The package list is repeated in four places that must stay in sync: the configs, `build-api.ts`, `@btravstack/docs#build`'s `dependsOn` in `turbo.json` (explicit `#build` edges — the site does not _depend_ on @@ -919,7 +1032,10 @@ was folded in here when the container was merged; nothing under - **Every TypeScript sample on the site was compiled when written** — in a scratch file inside the workspace whose dependencies it needs (`packages/core/src/` for kernel/di/config samples, `examples/order-api/src/` - for HTTP, the two worker examples for Temporal and AMQP), then deleted. The + for HTTP and for `@btravstack/observability`, the two worker examples for + Temporal and AMQP), then deleted. The one sample that cannot be compiled + that way is `pinoSink`'s — no example workspace installs `pino` — and it is + held by `packages/observability/src/pino.spec.ts` instead. The kernel-only samples are additionally held by `packages/core/src/docs-examples.test-d.ts`; the starters' are not (see Deferred). A sample edited on the site is re-compiled the same way. @@ -1059,13 +1175,22 @@ A sixth rule is about production code that tests keep honest: costs ~3.5 s per test job, not correctness. - The `@btravstack/oxlint` rule banning `currentUnit()` outside infrastructure adapters (Thesis #2) — it needs a way to identify an adapter. -- **A `docs-examples.test-d.ts` for `@btravstack/http`, `@btravstack/temporal` and - `@btravstack/amqp`.** `packages/core`'s exists precisely so its README and +- **Traces and metrics in `@btravstack/observability`.** The package is named + for the whole because logs, traces and metrics share a correlation id, a + resource, a config slice and a flush-on-shutdown lifecycle; only the logging + half ships. The shape the rest will take — `Tracer`/`Meter` ports, the OTel + `NodeSDK` as a resourceful provider whose `release` flushes, a span per unit + through `StartOptions.unit`, W3C `traceparent` feeding `UnitMeta.traceId` in + the three transport starters — and the auto-instrumentation constraint that + will not go away are in `packages/observability/CLAUDE.md`. Never describe + them as shipped. +- **A `docs-examples.test-d.ts` for `@btravstack/http`, `@btravstack/temporal`, + `@btravstack/amqp` and `@btravstack/observability`.** `packages/core`'s exists precisely so its README and the kernel-only pages of the documentation site cannot drift from `runtime.ts` / `drain.ts` without failing `pnpm typecheck`; the three - runtime packages' README and site samples have no such gate — they were + four other packages' README and site samples have no such gate — they were compiled by hand in a scratch file inside the matching example workspace - when written, and by nothing since. Deliberately not built — three + when written, and by nothing since. Deliberately not built — four packages' worth of samples still did not justify the harness. Add it the next time one of those samples is found to have drifted, the same way this gap itself was found. diff --git a/docs/.vitepress/config.ts b/docs/.vitepress/config.ts index 6593b4e..a09a20f 100644 --- a/docs/.vitepress/config.ts +++ b/docs/.vitepress/config.ts @@ -22,6 +22,7 @@ const GUIDE_SIDEBAR = [ text: "How-to guides", items: [ { text: "Configure from the environment", link: "/how-to/configure-from-the-environment" }, + { text: "Log and correlate", link: "/how-to/log-and-correlate" }, { text: "Serve an oRPC contract over HTTP", link: "/how-to/serve-orpc-over-http" }, { text: "Run a Temporal worker", link: "/how-to/run-a-temporal-worker" }, { text: "Consume AMQP messages", link: "/how-to/consume-amqp-messages" }, @@ -66,6 +67,7 @@ const GUIDE_SIDEBAR = [ { text: "Probes", link: "/reference/core/probes" }, ], }, + { text: "@btravstack/observability", link: "/reference/observability" }, { text: "@btravstack/testing", link: "/reference/testing" }, { text: "@btravstack/http", link: "/reference/http" }, { text: "@btravstack/temporal", link: "/reference/temporal" }, @@ -202,6 +204,7 @@ export default defineConfig({ { text: "@btravstack/di", link: "/api/di/" }, { text: "@btravstack/config", link: "/api/config/" }, { text: "@btravstack/core", link: "/api/core/" }, + { text: "@btravstack/observability", link: "/api/observability/" }, { text: "@btravstack/testing", link: "/api/testing/" }, { text: "@btravstack/http", link: "/api/http/" }, { text: "@btravstack/temporal", link: "/api/temporal/" }, diff --git a/docs/api/index.md b/docs/api/index.md index 0886caf..01b116b 100644 --- a/docs/api/index.md +++ b/docs/api/index.md @@ -8,7 +8,8 @@ description: The generated reference for every published package — each export Generated from the source with [TypeDoc](https://typedoc.org/) at build time — every exported symbol, with its signature and TSDoc. One page per package, following the dependency direction: `di` → `config` → `core`, then the test -harness and the three starters on top of `core`. +harness, the observability starter and the three transport starters on top of +`core`. - **[`@btravstack/di`](/api/di/)** — `Port` (and `Port.many`), `Provider`, `Module` (`Module.scoped`, `Module.forkScope`), `Context`, and the type @@ -30,6 +31,13 @@ harness and the three starters on top of `core`. `withApp`, `testRuntime`, `TestRuntimePort`, `createFakeClock`, and the types `Boot`, `BootDefaults`, `ServicesOf`, `TestRuntime`, `TestRuntimeInfo`, `SubmittedUnit`, `FakeClock`. +- **[`@btravstack/observability`](/api/observability/)** — **two entry + points**. The main one: the `Logger` and `LoggerConfig` ports, + `createLogger`, `jsonSink`, `observability`, `logLevel`, `kernelEvents`, + `LEVELS`, and the types `LoggerService`, `LoggerSettings`, `Level`, + `Attributes`, `Line`, `Sink`, `ObservabilityOptions`. The + `@btravstack/observability/pino` subpath carries `pinoSink` alone, so `pino` + stays an optional peer. - **[`@btravstack/http`](/api/http/)** — `HttpModule`, `HttpRouter`, `http`, the ports `HttpRuntime` and `HttpConfig`, and the types `HttpModuleOptions`, `HttpOptions`, `HttpInfo`. diff --git a/docs/examples/order-amqp-worker.md b/docs/examples/order-amqp-worker.md index b703e3c..04e9ab2 100644 --- a/docs/examples/order-amqp-worker.md +++ b/docs/examples/order-amqp-worker.md @@ -42,7 +42,9 @@ publisher does not know it exists. handlers port, typed for the contract — its service the record the contract wants, `WorkerInferHandlers`, no injected context; no class, no name, since a consumer serves one handlers record — so the handler is built -from what it declares like any use case: +from what it declares like any use case, `Logger` here being +[`@btravstack/observability`](/reference/observability)'s port rather than one +this example writes: ```ts export const orderHandlers = AmqpHandlers(orderContract)([Logger], { @@ -58,8 +60,12 @@ export const orderHandlers = AmqpHandlers(orderContract)([Logger], { } logger.info( payload === null - ? `order ${id} is gone — notifying` - : `order ${id} placed — notifying (${payload.quantity} items)`, + ? "order gone — notifying" + : "order placed — notifying", + { + orderId: id, + ...(payload === null ? {} : { quantity: payload.quantity }), + }, ); return OkAsync(); }, @@ -151,13 +157,16 @@ the runtime's `stop`). `drain` stays the consumer's alone — draining means export const OrderAmqpWorker = AmqpModule("OrderAmqpWorker")({ contract: orderContract, handlers: orderHandlers, - imports: [ApplicationModule, PersistenceModule], + imports: [ApplicationModule, PersistenceModule, observability()], provides: [relayConfig, outboxRelay], exports: [PlaceOrder, OrderRepository, Outbox, Logger], }); ``` -The same application pair, the starter over `orderHandlers`, and both halves +The same application pair, the starter over `orderHandlers`, +[`observability()`](/reference/observability) for the `Logger` both halves +write to — `LOG_LEVEL`, JSON per line on stdout, every consumer line +correlated with the delivery's own unit — and both halves of the outbox pattern in one graph. The exports are the writer's surface — what a writer in the same process places and cancels through, and what the specs tap. `main.ts` is `await runMain(OrderAmqpWorker);`. @@ -204,10 +213,14 @@ await use(async (module, options) => { ``` Every app is stopped by `boot`'s teardown when the test ends. The `tapped` -fixture is `tapped(OrderAmqpWorker, [PlaceOrder, OrderRepository, Outbox, -Logger])`: the writer the spec places orders through, the outbox it asserts -against and the logger the consumer writes to — the very instances the -running app uses, not fresh ones. +fixture composes the root's own shape with `observability({ sink })` and taps +the services on top of it — +`tapped(recording, [PlaceOrder, OrderRepository, Outbox])`: the writer the +spec places orders through and the outbox it asserts against are the very +instances the running app uses, not fresh ones, while the consumer's own lines +need no tap at all — the sink hands them over as `Line` values, so the +assertions read `{ message, orderId, quantity }` rather than a formatted +sentence. Five specs, each a fact crossing the outbox, the broker and the queue: a committed write comes back as the consumer's notification, with the write @@ -241,6 +254,7 @@ const HandlerlessAmqp = Module("HandlerlessAmqp")({ imports: [ ApplicationModule, PersistenceModule, + observability(), amqp({ contract: orderContract }), ], exports: [AmqpRuntime, PlaceOrder, Logger], diff --git a/docs/examples/order-api.md b/docs/examples/order-api.md index d7a117c..9bd65cf 100644 --- a/docs/examples/order-api.md +++ b/docs/examples/order-api.md @@ -1,6 +1,6 @@ --- title: Order API example -description: The HTTP deployment — HttpRouter over the order contract with one exhaustive triage from domain Err to ORPCError, HttpModule as the whole composition root, RequestModule forked per request, a one-line main.ts, and the three compile-time gates pinned by needs-gate.test-d.ts. +description: The HTTP deployment — HttpRouter over the order contract with one exhaustive triage from domain Err to ORPCError, HttpModule as the whole composition root, RequestModule forked per request, a main.ts that is one runMain call with the kernel's events on the application's own logger, and the three compile-time gates pinned by needs-gate.test-d.ts. --- # Order API (HTTP) @@ -87,7 +87,7 @@ than a fallback. ```ts export const OrderApi = HttpModule("OrderApi")({ router: orderRouter, - imports: [ApplicationModule, PersistenceModule], + imports: [ApplicationModule, PersistenceModule, observability()], exports: [Logger], }); ``` @@ -95,21 +95,33 @@ export const OrderApi = HttpModule("OrderApi")({ `HttpModule` imports the starter (`http()` — `HttpRuntime`, `HttpConfig` bound from `PORT` / `HOST`, the router mounted under `/rpc`, needing the router the root provides), provides `orderRouter` and exports `HttpRuntime`, and returns -exactly the module `Module("OrderApi")({...})` would have. `Logger` is exported -for the request scope below. It is a **constant**: configuration is read inside -the graph from the `Env` port the kernel provides, so nothing is passed in from -`main.ts`, and a spec boots this very module with `env: { PORT: "0", HOST: -"127.0.0.1" }`. +exactly the module `Module("OrderApi")({...})` would have. +[`observability()`](/reference/observability) brings the `Logger` the +interactors and the request scope write to — bound from `LOG_LEVEL`, one JSON +object per line on stdout, every line carrying the unit's trace id — and +`Logger` is exported for the request scope below. It is a **constant**: +configuration is read inside the graph from the `Env` port the kernel provides, +so nothing is passed in from `main.ts`, and a spec boots this very module with +`env: { PORT: "0", HOST: "127.0.0.1" }`. `main.ts` is one statement: ```ts -await runMain(OrderApi, { unit: RequestModule }); +await runMain(OrderApi, { + unit: RequestModule, + onEvent: kernelEvents(createLogger(jsonSink())), +}); ``` -The process reads `PORT` (default `3000`), `HOST` (default `0.0.0.0`) and -`PROBE_PORT` (default `9000`) — inside the graph — and a malformed one is a -`startFailed` event and exit `78`. +The process reads `PORT` (default `3000`), `HOST` (default `0.0.0.0`), +`LOG_LEVEL` (default `info`) and `PROBE_PORT` (default `9000`) — inside the +graph — and a malformed one is a `startFailed` event and exit `78`. +`kernelEvents` puts the kernel's nine lifecycle events in the same stream and +the same shape as the application's own lines, instead of the default JSON on +stderr; the logger there is built by hand because `building` is emitted while +the graph still is, so a sink taken out of the context it is watching would +have nothing to write the two events that matter most with. See +[Log and correlate](/how-to/log-and-correlate). ## A request scope over the application scope @@ -130,7 +142,9 @@ export const RequestModule = Module("Request")({ const startedAt = Date.now(); return { finish: () => - logger.info(`request finished in ${Date.now() - startedAt}ms`), + logger.info("request finished", { + durationMs: Date.now() - startedAt, + }), }; }, onStop: (span) => span.finish(), @@ -153,7 +167,9 @@ wraps it in `serve`, where every spec starts, real composition root included: ```ts export const it = test.extend({ - boot: bootFixture({ env: { PORT: "0", HOST: "127.0.0.1" } }), + boot: bootFixture({ + env: { PORT: "0", HOST: "127.0.0.1", LOG_LEVEL: "fatal" }, + }), serve: async ({ boot }, use) => { await use((module, options) => @@ -166,11 +182,15 @@ export const it = test.extend({ `boot` brings a test's defaults (`signals: false`, `probes: false`, `preDrainDelayMs: 0`, a silent sink) and stops every app it started when the -test ends; `serve` adds the per-request `RequestModule`. The port comes back +test ends; `serve` adds the per-request `RequestModule`, and `LOG_LEVEL: +"fatal"` keeps the real root — whose sink is the production `jsonSink()` on +stdout — out of the runner's own output. The port comes back from `Serving.info` through `app.runtimeInfo()` — the kernel's own channel for it — and the client is built from the contract alone. Where a spec needs -the very `Logger` the use cases wrote to, `tapped(OrderApi, [Logger])` -hands back the instance the running graph holds. The suite then pins what matters: a `DuplicateOrder` arrives as an +the lines the running graph wrote, the seam is +`observability({ sink })`: the `recording` fixture composes the root's shape +with a sink that keeps every `Line`, so an assertion reads `line.unit.traceId` +as a field rather than parsing a prefix out of a string. The suite then pins what matters: a `DuplicateOrder` arrives as an `Err` holding an inferable `CONFLICT`, a value the client matches by code, not a thrown 500: @@ -188,7 +208,8 @@ expect(conflict).toBeErrWith( An unmodeled repository failure collapses to `INTERNAL_SERVER_ERROR` without leaking its message, and the process keeps serving afterwards; each call runs in its own unit with its own trace id (two calls, four log lines, two distinct -ids, never `[-]`); a call held open in the repository finishes during a drain +`line.unit.traceId`s, none written outside a unit); a call held open in the +repository finishes during a drain and is counted `completed`, one still hung at a zero deadline is counted `abandoned`; `/livez` and `/readyz` answer while serving, and readiness goes false before liveness during the drain. @@ -209,7 +230,7 @@ on arity. ```ts const RouterlessApi = Module("RouterlessApi")({ - imports: [ApplicationModule, PersistenceModule, http()], + imports: [ApplicationModule, PersistenceModule, observability(), http()], exports: [HttpRuntime, Logger], }); @@ -231,7 +252,8 @@ const _unitUnmet = start(UnloggedApi, { ...options, unit: RequestModule }); The `unit` half, in both directions: `start(OrderApi, { unit: RequestModule })` is an ordinary call because `OrderApi` exports the `Logger` the fork reads, -and `UnloggedApi` — runtime and router present, `Logger` not exported — is +and `UnloggedApi` — runtime and router present, `observability()` imported so +the port exists in the graph, `Logger` simply not exported — is rejected by the unit arm alone. ## Where to go next diff --git a/docs/examples/order-application.md b/docs/examples/order-application.md index 9f06b20..e64cc25 100644 --- a/docs/examples/order-application.md +++ b/docs/examples/order-application.md @@ -89,9 +89,12 @@ export class OrderRepository extends Port("OrderRepository")<{ Beside it: `Outbox` (the read side of the transactional outbox — `pending` and `markPublished`, both `E = never`, because a database that will not answer is a defect, not a domain outcome), `StockService` and -`ShippingService` (the two fulfillment ports the saga orchestrates), `Logger`, -and the two use-case ports `PlaceOrder` and `FindOrder`. The interactors are -classes provided with di's `class` arm: +`ShippingService` (the two fulfillment ports the saga orchestrates), and the +two use-case ports `PlaceOrder` and `FindOrder`. The `Logger` the interactors +write to is **not** declared here: it is +[`@btravstack/observability`](/reference/observability)'s port, imported like +any other dependency. The interactors are classes provided with di's `class` +arm: ```ts export const placeOrderProvider = Provider(PlaceOrder)( @@ -102,25 +105,31 @@ export const placeOrderProvider = Provider(PlaceOrder)( ); ``` -The module provides everything **except** `OrderRepository`: +The module provides neither `OrderRepository` nor `Logger`: ```ts export const ApplicationModule = Module("Application")({ - provides: [loggerProvider, placeOrderProvider, findOrderProvider], - exports: [PlaceOrder, FindOrder, Logger], + provides: [placeOrderProvider, findOrderProvider], + exports: [PlaceOrder, FindOrder], }); ``` -Both interactors depend on it and nothing here satisfies it, so di propagates -it as an unmet need. That is what makes this layer testable with no database -at all — its specs provide a stub repository from a `TestModule` — and it is -what makes the layering a compile error rather than a convention (see the type -tests below). - -The one kernel touchpoint is `logger.ts`, which reads `currentUnit()` fresh on -every call so each line carries the trace id of the unit that wrote it — +`PlaceOrderInteractor` depends on both and nothing here satisfies either, so di +propagates both as unmet needs — the repository because the layer below fills +it, the logger because the framework does, and there is nothing to re-export in +either direction. That is what makes this layer testable with no database at +all — its specs provide a stub repository from a `TestModule` that imports +`observability({ sink, level: "trace" })` — and it is what makes the layering a +compile error rather than a convention (see the type tests below). + +There is no kernel touchpoint left here. The log calls are structured — +`this.#logger.info("placing an order", { orderId: id, quantity })`, a constant +message with the ids as fields — and correlation is not this layer's job: +`@btravstack/observability`'s implementation reads `currentUnit()` fresh on +every call, so each line carries the trace id of the unit that wrote it — data from the ambient store, never a capability (see -[Ambient data, injected capabilities](/explanation/ambient-vs-context)). +[Ambient data, injected capabilities](/explanation/ambient-vs-context) and +[Log and correlate](/how-to/log-and-correlate)). ## The infrastructure: P-codes stop here @@ -249,8 +258,10 @@ const _unwired = Module.scoped(ApplicationModule, (ctx) => ); ``` -The positive half composes `ApplicationModule` with a stub repository and -calls `Module.scoped` as an ordinary two-argument call. The three deployment +The positive half composes `ApplicationModule` with a stub repository and a +`Provider(Logger)({ value: createLogger(() => {}) })` — the starter is the +default, not the only way — and calls `Module.scoped` as an ordinary +two-argument call. The three deployment pages carry the other kind — `start`'s gate. ## Where to go next diff --git a/docs/examples/order-temporal-worker.md b/docs/examples/order-temporal-worker.md index 46cc84c..3b73448 100644 --- a/docs/examples/order-temporal-worker.md +++ b/docs/examples/order-temporal-worker.md @@ -147,11 +147,19 @@ export const OrderTemporalWorker = TemporalModule("OrderTemporalWorker")({ workflows: { workflowsPath: workflowsPathFromURL(import.meta.url, "./workflows.js"), }, - imports: [ApplicationModule, PersistenceModule, FulfillmentModule], + imports: [ + ApplicationModule, + PersistenceModule, + FulfillmentModule, + observability(), + ], }); ``` The same `ApplicationModule` + `PersistenceModule` pair as the API, plus +[`observability()`](/reference/observability) — the `Logger` the use case and +the stand-ins write to, bound from `LOG_LEVEL`, JSON per line on stdout, every +line carrying the activity attempt's own trace id — and `FulfillmentModule` — the two external services as in-memory stand-ins that say yes to anything the drain still has time for, because what this deployment demonstrates is the orchestration; the specs swap in twins that say no. @@ -168,7 +176,7 @@ arrange: (orderId) => ), ), ) - : (logger.info(`arranged shipping for order ${orderId}`), OkAsync()), + : (logger.info("arranged shipping", { orderId }), OkAsync()), ``` An adapter is where reading the ambient record is legitimate, and here it is @@ -221,8 +229,11 @@ const app = boot(worker, { env: { TEMPORAL_ADDRESS: testEnv.address } }); ``` The stub deployments (`fulfilling`, `outOfStock`, `noShipping`) are each a -`tapped(rootWith(fulfillment), [OrderRepository, Logger])`, so a spec reads -the database through the very repository the saga used. +`tapped(rootWith(fulfillment, sink), [OrderRepository])`, so a spec reads the +database through the very repository the saga used. The log lines need no tap +at all: `rootWith` composes `observability({ sink })`, so `lines()` hands back +the saga's own `Line` values — `{ message, orderId, quantity }` as fields, and +the trace id already on each one. Four specs: the saga fulfills in order; a stock refusal walks the placement back; a shipping refusal releases the reservation and then cancels, in that diff --git a/docs/explanation/ambient-vs-context.md b/docs/explanation/ambient-vs-context.md index 8ad5181..53c1e0f 100644 --- a/docs/explanation/ambient-vs-context.md +++ b/docs/explanation/ambient-vs-context.md @@ -113,17 +113,28 @@ standing in for the other. Legitimate readers are **infrastructure adapters only** — the logger, the OpenTelemetry exporter, the database adapter. They sit at the edge, they are already coupled to the process they run in, and annotating their output with -the current unit is their job: +the current unit is their job. + +The logger is no longer a hypothesis about that rule: it is +[`@btravstack/observability`](/reference/observability), and +`createLogger` is the reference reading of the record — ```ts -const log = (message: string): void => { +const write = (level, message, attributes, cause) => { + if (severity(level) < floor) return; const unit = currentUnit(); - process.stderr.write( - `${JSON.stringify({ message, traceId: unit?.traceId })}\n`, - ); + sink({ level, message, attributes, cause, time: Date.now(), unit }); }; ``` +— read **per call**, never captured at construction. That detail is the whole +reason the rule is worth having: one logger is built per scope, every unit the +kernel opens has its own record, and a captured one would stamp the first +unit's trace id on every line thereafter. Application code depending on +`Logger` writes `logger.info("placing an order", { orderId, quantity })` and +never mentions correlation; the adapter underneath is the only thing that +reads the store. + Application code — a use case, a domain service — is not meant to call `currentUnit()`. If a use case needs the tenant, the tenant is an argument or a port, declared like everything else it depends on. The store is for the code diff --git a/docs/explanation/design-decisions.md b/docs/explanation/design-decisions.md index f349410..bde6aa8 100644 --- a/docs/explanation/design-decisions.md +++ b/docs/explanation/design-decisions.md @@ -142,6 +142,30 @@ what the starter consumes. `Config.provider("Name")(schema)` keeps its name on purpose: several config slices per application is normal, and the name is what `ConfigInvalid` prints. +## The logger is a port, and the package is named for observability + +`Logger` is a di port over a deliberately narrow service — `with` returns a +new logger, `Attributes` is a flat record of scalars, a failure has its own +`cause` channel, there are six levels and no more, and a log call cannot +throw. It is the **framework's** port rather than each application's, because +the framework logs too (`kernelEvents`) and one port has to serve both. The +package is `@btravstack/observability`, not `@btravstack/logger`, because +logs, traces and metrics share a correlation id, a resource, a configuration +slice and a flush-on-shutdown lifecycle; two packages would duplicate all +four, and the second would end up depending on the first. **Traces and metrics +are not shipped** — the name is the seam, not a claim. + +It rules out a `@btravstack/logger` package that a tracing package would then +have to import; a class you `new`, with the static instance and the +`useLogger` escape hatch that reach past DI; `any` varargs and printf, and +with them a logger that stringifies whatever it is handed — which is how a log +call becomes the thing that throws; a mutable `setContext`, whose one instance +two request scopes interleave; and a vitest-style global that a test cannot +replace by composing a different module. Correlation is ruled **in** on the +same grounds: `createLogger` reads `currentUnit()` per call, so no signature +anywhere carries a trace id. See +[`@btravstack/observability`](/reference/observability). + ## `Config` is a hand-rolled Standard Schema `Config.object` speaks Standard Schema v1 so any `zod` / `valibot` / `arktype` diff --git a/docs/explanation/nothing-throws.md b/docs/explanation/nothing-throws.md index 70236c3..5110595 100644 --- a/docs/explanation/nothing-throws.md +++ b/docs/explanation/nothing-throws.md @@ -168,8 +168,16 @@ all — a circular object — falls back to `"[unserialisable]"` rather than throwing, because a throwing sink is swallowed (a broken reporter must not take the process down mid-shutdown), and the crash would then be reported nowhere. -An observability package binding a logger and OpenTelemetry to `KernelEvent` -is planned; the kernel is where the events come from, not where they go. +That the events go somewhere else is the point of the seam. +[`@btravstack/observability`](/reference/observability) ships the logging half +of it: `kernelEvents(logger)` is an `EventSink` that writes each event as a log +line on the application's own logger — `startFailed` and `uncaught` at `error` +carrying their cause, `teardownError` at `warn`, the rest at `info`, with each +event's own fields as attributes — so `serving` lands next to the request that +was in flight when it did instead of in a second stream with a second shape. +The OpenTelemetry half is not written. The kernel is unchanged either way: it +is where the events come from, not where they go, and it still takes no logger +dependency. ## Where to go next diff --git a/docs/explanation/starters.md b/docs/explanation/starters.md index 486ed68..0862ba1 100644 --- a/docs/explanation/starters.md +++ b/docs/explanation/starters.md @@ -23,8 +23,19 @@ the idea: `spring-boot-starter-web` does not offer you a choice of servlet containers on day one, it brings Tomcat and a sane configuration, and you change what your deployment needs. -Three ship — `@btravstack/http`, `@btravstack/temporal`, `@btravstack/amqp` — -and they are deliberately the same shape. +Three transport starters ship — `@btravstack/http`, `@btravstack/temporal`, +`@btravstack/amqp` — and they are deliberately the same shape. + +A fourth, [`@btravstack/observability`](/reference/observability), is a starter +in every sense but the runtime: `observability()` is a module that brings the +default behaviour for the standard case (a `Logger` correlated with the +ambient unit, one JSON object per line on stdout), is opinionated about the +one way it is done (a strict port, six levels, a `cause` channel, no printf), +binds its own slice of the environment (`LOG_LEVEL` onto `LoggerConfig`), and +takes one argument — `sink` — where a deployment differs. It provides no +`RuntimePort`, so a process still boots exactly one runtime; a graph can hold +`observability()` and a transport starter side by side because only one of +them answers the port the kernel resolves. ## One way, and why @@ -54,7 +65,8 @@ starter. What differs between deployments is the environment, and a starter binds its own slice of it. `http()` binds `PORT` and `HOST` onto `HttpConfig`, `temporal()` binds `TEMPORAL_ADDRESS` and `TEMPORAL_NAMESPACE` onto -`TemporalConfig`, `amqp()` binds `AMQP_URL` onto `AmqpConfig` — each through +`TemporalConfig`, `amqp()` binds `AMQP_URL` onto `AmqpConfig`, +`observability()` binds `LOG_LEVEL` onto `LoggerConfig` — each through `Config.provider` reading the `Env` port the kernel provides, validated once as the graph is built, and each a modeled `ConfigInvalid` naming its variables when wrong. An application binds whatever else it needs onto ports of its own @@ -79,11 +91,15 @@ spelled once. From [`examples/order-api`](/examples/order-api): ```ts export const OrderApi = HttpModule("OrderApi")({ router: orderRouter, - imports: [ApplicationModule, PersistenceModule], + imports: [ApplicationModule, PersistenceModule, observability()], exports: [Logger], }); ``` +`observability()` is an ordinary import beside the application's own modules, +which is the point: a starter with no sugar of its own is still a starter, and +`Logger` is exported here only because the per-request module reads it. + The kernel and both gates see nothing new — `OrderApi` is a `Module`, and `await runMain(OrderApi, { unit: RequestModule })` is the whole `main.ts`. The plain starter (`http()`, `temporal({...})`, `amqp({...})`) stays diff --git a/docs/explanation/why-start.md b/docs/explanation/why-start.md index c5e17a4..5c4eb95 100644 --- a/docs/explanation/why-start.md +++ b/docs/explanation/why-start.md @@ -56,12 +56,15 @@ drain, the exit code — which is precisely the part an effect system leaves to you. **Not a framework.** There is no router, no ORM, no validation layer, no -logger, no middleware chain in the kernel. Transports arrive as -[starters](/explanation/starters) — `@btravstack/http`, `@btravstack/temporal`, -`@btravstack/amqp` — each a module that provides a runtime on a port the -kernel resolves. A starter is opinionated about its one transport and brings -nothing else. The kernel's public surface is small enough to hold in your -head, and it is meant to stay that way. +logger, no middleware chain **in the kernel**. Everything of that kind arrives +as a [starter](/explanation/starters) — `@btravstack/http`, +`@btravstack/temporal` and `@btravstack/amqp`, each a module that provides a +runtime on a port the kernel resolves, and +[`@btravstack/observability`](/reference/observability), which provides a +`Logger` and no runtime at all. A starter is opinionated about its one concern +and brings nothing else; the kernel still takes no logger dependency and emits +[events](/reference/core/events) instead. Its public surface is small enough +to hold in your head, and it is meant to stay that way. ## What a hand-rolled `main.ts` gets wrong diff --git a/docs/how-to/consume-amqp-messages.md b/docs/how-to/consume-amqp-messages.md index dadb8bb..dec3467 100644 --- a/docs/how-to/consume-amqp-messages.md +++ b/docs/how-to/consume-amqp-messages.md @@ -39,7 +39,7 @@ the package installs opens the unit and calls `next()` unchanged: ```ts import { AmqpHandlers } from "@btravstack/amqp"; import { orderContract } from "@btravstack/example-order-amqp-contract"; -import { Logger } from "@btravstack/example-order-application"; +import { Logger } from "@btravstack/observability"; import { OkAsync } from "unthrown"; export const orderHandlers = AmqpHandlers(orderContract)([Logger], { @@ -48,8 +48,12 @@ export const orderHandlers = AmqpHandlers(orderContract)([Logger], { const { id, payload } = message.payload; logger.info( payload === null - ? `order ${id} is gone — notifying` - : `order ${id} placed — notifying (${payload.quantity} items)`, + ? "order gone — notifying" + : "order placed — notifying", + { + orderId: id, + ...(payload === null ? {} : { quantity: payload.quantity }), + }, ); return OkAsync(); }, @@ -114,12 +118,12 @@ import { AmqpModule } from "@btravstack/amqp"; import { orderContract } from "@btravstack/example-order-amqp-contract"; import { ApplicationModule, - Logger, OrderRepository, Outbox, PlaceOrder, } from "@btravstack/example-order-application"; import { PersistenceModule } from "@btravstack/example-order-infrastructure"; +import { Logger, observability } from "@btravstack/observability"; import { orderHandlers } from "./handlers.js"; import { outboxRelay, relayConfig } from "./outbox-relay.js"; @@ -127,7 +131,7 @@ import { outboxRelay, relayConfig } from "./outbox-relay.js"; export const OrderAmqpWorker = AmqpModule("OrderAmqpWorker")({ contract: orderContract, handlers: orderHandlers, - imports: [ApplicationModule, PersistenceModule], + imports: [ApplicationModule, PersistenceModule, observability()], provides: [relayConfig, outboxRelay], exports: [PlaceOrder, OrderRepository, Outbox, Logger], }); @@ -135,7 +139,10 @@ export const OrderAmqpWorker = AmqpModule("OrderAmqpWorker")({ `AmqpModule` is `Module(name)({...})` plus `contract` and `handlers`: it imports `amqp({ contract })`, provides the handlers and exports -`AmqpRuntime`. The record is checked against the contract at +`AmqpRuntime`. [`observability()`](/reference/observability) is the other +starter in that list — the `Logger` the handlers and the relay write to, bound +from `LOG_LEVEL`, JSON per line on stdout, every line carrying the delivery's +own unit. The record is checked against the contract at `AmqpHandlers(contract)(…)` — a record missing a consumer, or naming one the contract does not declare, fails to typecheck there rather than on the first delivery, silently to the DLQ — and `handlers` is typed against the module's diff --git a/docs/how-to/log-and-correlate.md b/docs/how-to/log-and-correlate.md new file mode 100644 index 0000000..967ba29 --- /dev/null +++ b/docs/how-to/log-and-correlate.md @@ -0,0 +1,275 @@ +--- +title: Log and correlate +description: Add @btravstack/observability, log structured attributes from a use case, read a line back, raise the level from the environment, swap in pino, and put the kernel's own events in the same stream. +--- + +# Log and correlate + +> **How-to.** Get structured lines out of your application, each one stamped +> with the unit that wrote it, without threading a trace id through a single +> signature. For the full surface, see +> [`@btravstack/observability`](/reference/observability); for _why_ a trace id +> may be ambient and a repository may not, see +> [Ambient data, injected capabilities](/explanation/ambient-vs-context). + +You want `logger.info("placing an order", { orderId, quantity })` in a use +case, and the resulting line to carry the request's trace id in production, in +a worker, and in a test — with nothing in the use case knowing any of that +happened. The recipe is one import. + +## Recipe + +1. `pnpm add @btravstack/observability` (its peers are the ones you already + have: `@btravstack/core`, `@btravstack/config`, `@btravstack/di`, + `unthrown`). +2. Add `observability()` to the composition root's `imports`. +3. Depend on `Logger` from any provider that writes lines. +4. Export `Logger` if anything outside the root reads it — a + `StartOptions.unit` module, a test. + +```ts +import { Module, Provider } from "@btravstack/di"; +import { HttpModule } from "@btravstack/http"; +import { Logger, observability } from "@btravstack/observability"; + +export const OrderApi = HttpModule("OrderApi")({ + router: orderRouter, + imports: [ApplicationModule, PersistenceModule, observability()], + exports: [Logger], +}); +``` + +That is the whole of it. `LOG_LEVEL` is read inside the graph, the default +sink writes one JSON object per line on stdout, and every line written inside +a unit carries that unit's ids. + +## Log from a use case + +`Logger` is an ordinary port, so it arrives the ordinary way — in the +dependency array, never from a global or an ambient read: + +```ts +class PlaceOrderInteractor { + readonly #repository: ServiceOf; + readonly #logger: ServiceOf; + + constructor( + repository: ServiceOf, + logger: ServiceOf, + ) { + this.#repository = repository; + this.#logger = logger; + } + + execute(id: string, quantity: number) { + this.#logger.info("placing an order", { orderId: id, quantity }); + return placeOrder(id, quantity) + .toAsync() + .flatMap((order) => this.#repository.save(order)); + } +} + +export const placeOrderProvider = Provider(PlaceOrder)( + [OrderRepository, Logger], + { class: PlaceOrderInteractor }, +); +``` + +**The message is a constant and the ids are fields.** That is what makes a +line groupable in the system that receives it: `message: "placing an order"` +finds every placement, `orderId: "o-1"` finds one. A rendered sentence — +`` `placing order ${id}` `` — is neither. + +Attributes are flat scalars (`string | number | boolean | undefined`), and a +failure has a channel of its own — the third argument of **every** method, so +a retryable failure can be a `warn` and still say why: + +```ts +logger.warn( + "publishing an outbox event failed, will retry", + { eventId: event.id }, + cause, +); +``` + +Pass the failure as `cause`, never as an attribute: an `Error`'s `message` and +`stack` are non-enumerable, so `JSON.stringify` alone drops exactly the part +worth keeping. The sink is what normalises it. + +For a set of attributes every line in a scope should carry, `with` returns a +**new** logger rather than mutating the one every caller shares: + +```ts +const scoped = logger.with({ component: "outbox-relay" }); +``` + +## Read a line + +Nothing in the use case mentions correlation, and the line has it anyway — +`createLogger` reads [`currentUnit()`](/how-to/read-the-ambient-unit) on every +call, so one application-scope logger is correct for every request: + +```json +{ + "orderId": "o-1", + "quantity": 2, + "time": "2026-08-16T09:41:02.113Z", + "level": "info", + "message": "placing an order", + "unitId": "0f2a…", + "traceId": "b41e…" +} +``` + +`traceId` is the field to search on: `@btravstack/http` fills it from +`x-request-id`, `@btravstack/temporal` from the workflow id (stable across +retries) and `@btravstack/amqp` from the message id, so a line logged here +joins a trace that started outside the process. `unitId` is minted per unit and +always unique. Outside a unit — a startup line, a spec that boots no kernel — +neither field is on the line at all. + +A caller's attribute can never overwrite `level`, `message`, `time` or the +correlation, whatever it is named. + +## Raise the level + +```sh +LOG_LEVEL=debug node dist/main.js +``` + +Six levels, in order: `trace`, `debug`, `info`, `warn`, `error`, `fatal`. +Default `info`. A value outside the six is a **startup failure** — a +`ConfigInvalid` naming the variable and the set, reported as a `startFailed` +event and [exit code `78`](/reference/core/exit-codes), before a line is +written. A deployment that meant `debug` and typed `verbose` is told, rather +than quietly under-logged for a week. + +To pin the level from code instead — a CLI, a test — pass it, and the +environment is not read for that field: + +```ts +observability({ level: "debug" }); +``` + +For a payload expensive enough to be worth not building, ask first: + +```ts +if (logger.isEnabled("debug")) { + logger.debug("payload", { body: JSON.stringify(payload) }); +} +``` + +## Swap in pino + +The default sink has no dependencies and does a `JSON.stringify` per line. If +that shows up in a profile, `pino` is an **optional** peer behind a subpath: + +```sh +pnpm add pino +``` + +```ts +import pino from "pino"; +import { observability } from "@btravstack/observability"; +import { pinoSink } from "@btravstack/observability/pino"; + +observability({ sink: pinoSink(pino({ level: "trace" })) }); +``` + +Configure pino at `trace`. **The level filter stays this package's** — a line +below `LOG_LEVEL` never reaches a sink — so there is one filter in the +process, and it is the one validated at startup. The attributes and the unit's +ids ride as pino fields; the cause goes over as `err`, which pino's own +serialiser renders with the stack. + +## Put the kernel's events in the same stream + +The kernel emits [nine lifecycle events](/reference/core/events) and its +default sink writes JSON to stderr — right for a process with no logger, wrong +for one with: two streams, two shapes, two sets of fields to search. +`kernelEvents` is the adapter between them: + +```ts +import { runMain } from "@btravstack/core"; +import { + createLogger, + jsonSink, + kernelEvents, +} from "@btravstack/observability"; + +await runMain(OrderApi, { + unit: RequestModule, + onEvent: kernelEvents(createLogger(jsonSink())), +}); +``` + +`serving` now lands next to the request that was in flight when it did, and a +drain's numbers arrive as `inFlightAtStart` / `completed` / `abandoned` +attributes rather than inside a sentence. `startFailed` and `uncaught` are +`error` lines carrying their cause; `teardownError` is a `warn`, because the +application is already stopping and the exit code already says `2`. + +::: warning Build this logger by hand +It is the one logger the framework asks anybody to construct, and it has to +be: `building` is emitted **while the graph is still being built**, and +`startFailed` when it never finished, so a sink resolved from the context it +is watching would have nothing to write the two events that matter most with. +It reads no `LOG_LEVEL` for the same reason, and logs at the default `info`. +::: + +`examples/order-api/src/main.ts` wires exactly this; the other two example +`main.ts` files stay a single line, because the kernel's stderr sink is a fine +default and this is the upgrade, not the requirement. + +## Provide your own `Logger` + +`observability()` is the default, not the only way. A test that wants silence, +or an application with a logger of its own, provides the port directly and +nothing else in the graph can tell: + +```ts +Provider(Logger)({ value: createLogger(() => {}) }); +``` + +More usefully, keep the shipped implementation and replace only the +**destination** — a `Sink` is a plain function, so the lines come back as +values: + +```ts +const lines: Line[] = []; + +const RecordingApi = HttpModule("RecordingApi")({ + router: orderRouter, + imports: [ + ApplicationModule, + PersistenceModule, + observability({ sink: (line) => lines.push(line), level: "trace" }), + ], + exports: [Logger], +}); +``` + +That is what the example suites do. A spec then asserts on the line's +**fields** — `line.attributes.orderId`, `line.unit?.traceId` — instead of +matching a substring, and `level: "trace"` is pinned so the environment cannot +silence the very thing the test is reading. The roots a spec boots only to +exercise a transport pass a no-op sink instead, so a test run is not also a +log dump. + +::: tip Booting without the kernel +`observability()` binds its level from the `Env` port `start` provides. A +kernel-free `Module.scoped` has no `start`, so provide an empty one: +`Provider(Env)({ value: {} })`. That is the only ceremony the real logger +costs a spec, and it buys the very implementation the deployments run. +::: + +## See also + +- [`@btravstack/observability`](/reference/observability) — every export, the + `Line` contract and the full `kernelEvents` table. +- [Read the ambient unit from an adapter](/how-to/read-the-ambient-unit) — the + record the logger reads, and who else may read it. +- [Configure from the environment](/how-to/configure-from-the-environment) — + how `LOG_LEVEL` is bound, and what a bad one costs. +- [Test an application](/how-to/test-an-application) — the fixtures the + recording sink above belongs to. diff --git a/docs/how-to/open-a-per-request-scope.md b/docs/how-to/open-a-per-request-scope.md index 895008f..24c9d38 100644 --- a/docs/how-to/open-a-per-request-scope.md +++ b/docs/how-to/open-a-per-request-scope.md @@ -33,7 +33,7 @@ request took: ```ts import { Module, Port, Provider } from "@btravstack/di"; -import { Logger } from "@btravstack/example-order-application"; +import { Logger } from "@btravstack/observability"; export class RequestSpan extends Port("RequestSpan")<{ readonly finish: () => void; @@ -46,7 +46,9 @@ export const RequestModule = Module("Request")({ const startedAt = Date.now(); return { finish: () => - logger.info(`request finished in ${Date.now() - startedAt}ms`), + logger.info("request finished", { + durationMs: Date.now() - startedAt, + }), }; }, onStop: (span) => span.finish(), @@ -56,8 +58,9 @@ export const RequestModule = Module("Request")({ }); ``` -`Logger` is application-scoped: the fork **reads** it from the parent, it does -not rebuild it. `onStop` puts `Scope` in the module's needs, and only a fork +`Logger` is [`@btravstack/observability`](/reference/observability)'s port, +provided at application scope by the `observability()` the composition root +imports: the fork **reads** it from the parent, it does not rebuild it. `onStop` puts `Scope` in the module's needs, and only a fork (or `Module.scoped`) opens one — so the teardown cannot be forgotten. Its type is `Module`. @@ -65,14 +68,24 @@ is `Module`. ```ts import { runMain } from "@btravstack/core"; +import { + createLogger, + jsonSink, + kernelEvents, +} from "@btravstack/observability"; import { OrderApi } from "./module.js"; import { RequestModule } from "./request-scope.js"; -await runMain(OrderApi, { unit: RequestModule }); +await runMain(OrderApi, { + unit: RequestModule, + onEvent: kernelEvents(createLogger(jsonSink())), +}); ``` -That is the whole of `examples/order-api/src/main.ts`. From here the kernel +That is the whole of `examples/order-api/src/main.ts` — `onEvent` being the +separate matter of putting the kernel's own events in the same stream, covered +in [Log and correlate](/how-to/log-and-correlate). From here the kernel forks `RequestModule` around **every unit**: built as the unit opens, torn down as it closes, inside `registry.run` — so the unit is not counted closed until the fork is, and a drain waits for the teardown too. @@ -110,7 +123,7 @@ fails on arity with `UNSATISFIED UNIT NEEDS`: ```ts const UnloggedApi = Module("UnloggedApi")({ - imports: [ApplicationModule, PersistenceModule, http()], + imports: [ApplicationModule, PersistenceModule, observability(), http()], provides: [orderRouter], exports: [HttpRuntime], }); @@ -119,9 +132,11 @@ const UnloggedApi = Module("UnloggedApi")({ const unitUnmet = start(UnloggedApi, { ...options, unit: RequestModule }); ``` -That is why `OrderApi` exports `Logger` next to `HttpRuntime`: +The port exists in that graph — `observability()` provides it — but exporting +is what the gate reads, and `UnloggedApi` does not. That is why `OrderApi` +exports `Logger` next to `HttpRuntime`: `HttpModule("OrderApi")({ router: orderRouter, imports: [ApplicationModule, -PersistenceModule], exports: [Logger] })`. +PersistenceModule, observability()], exports: [Logger] })`. ::: warning `RuntimeHost.ctx` is the application context A unit-provided port exists only while a unit is open, and reaches a runtime @@ -168,5 +183,6 @@ being the application context — see [Modules](/reference/di/modules) and - [start and StartOptions](/reference/core/start) — the `unit` option and the three gate arms. - [Read the ambient unit from an adapter](/how-to/read-the-ambient-unit) — what `currentUnit()` gives a teardown log line. +- [Log and correlate](/how-to/log-and-correlate) — the `Logger` this fork reads, and the trace id it stamps. - [Serve an oRPC contract over HTTP](/how-to/serve-orpc-over-http) — the composition root this scope rides on. - [Order API (HTTP)](/examples/order-api) — the example. diff --git a/docs/how-to/read-the-ambient-unit.md b/docs/how-to/read-the-ambient-unit.md index ec17cf7..fcbaaf3 100644 --- a/docs/how-to/read-the-ambient-unit.md +++ b/docs/how-to/read-the-ambient-unit.md @@ -59,53 +59,65 @@ a way to identify an adapter, which this stack has not established — so today this is a convention, held by review, not an enforcement. ::: -## Recipe: a logger that stamps the trace id +## The logger is already written -Read the record at **call time**, never at construction: one logger is built +The canonical reader ships: +[`@btravstack/observability`](/reference/observability). Import +`observability()` next to your application and every line an application +writes carries the unit it was written in, with nothing in the application +mentioning correlation: + +```ts +logger.info("placing an order", { orderId: id, quantity }); +``` + +```json +{ + "orderId": "o-1", + "quantity": 2, + "time": "2026-08-16T09:41:02.113Z", + "level": "info", + "message": "placing an order", + "unitId": "0f2a…", + "traceId": "b41e…" +} +``` + +`examples/order-api/src/api.spec.ts` asserts that two calls produce four lines +carrying two distinct trace ids, and none written outside a unit — which is +how the convention is kept honest against the real HTTP runtime. Reach for the +recipe below only for an adapter of your own: an exporter, a database adapter, +a second destination. + +## Recipe: an adapter of your own + +Read the record at **call time**, never at construction: one adapter is built per scope, but each unit has its own record. ```ts import { currentUnit } from "@btravstack/core"; import { Port, Provider } from "@btravstack/di"; -class Logger extends Port("Logger")<{ - readonly info: (message: string) => void; +class Audit extends Port("Audit")<{ + readonly record: (action: string) => void; }> {} -const loggerProvider = Provider(Logger)({ +const auditProvider = Provider(Audit)({ sync: () => ({ - info: (message: string) => { + record: (action: string) => { const unit = currentUnit(); process.stderr.write( - `${JSON.stringify({ message, traceId: unit?.traceId, tenantId: unit?.tenantId })}\n`, + `${JSON.stringify({ action, traceId: unit?.traceId, tenantId: unit?.tenantId })}\n`, ); }, }), }); ``` -That is exactly what `examples/order-application/src/logger.ts` does — the -single kernel touchpoint in that layer, and the logger every use case writes -to: - -```ts -export const loggerProvider = Provider(Logger)({ - sync: () => { - const lines: string[] = []; - return { - info: (message: string) => { - lines.push(`[${currentUnit()?.traceId ?? "-"}] ${message}`); - }, - lines: () => lines, - }; - }, -}); -``` - -Outside a unit — the package's own specs, a startup log — there is no record -and the line reads `[-]`. `examples/order-api/src/api.spec.ts` asserts two -calls produce two distinct trace ids and never `[-]`, which is how the -convention is kept honest against the real HTTP runtime. +That is what `createLogger` does, minus the level filter and the `try` that +makes a broken destination survivable. Outside a unit — a package's own specs, +a startup line — `currentUnit()` is `undefined`, and the fields are simply +absent. A unit-scoped finaliser runs **while the unit is still open**, so a `StartOptions.unit` module's `onStop` logging "request finished" carries the @@ -148,7 +160,15 @@ export const orderHandlers = AmqpHandlers(orderContract)([Logger], { ), ); } - logger.info(`order ${id} placed — notifying`); + logger.info( + payload === null + ? "order gone — notifying" + : "order placed — notifying", + { + orderId: id, + ...(payload === null ? {} : { quantity: payload.quantity }), + }, + ); return OkAsync(); }, }), @@ -172,7 +192,7 @@ Provider(ShippingService)([Logger], { ), ), ) - : (logger.info(`arranged shipping for order ${orderId}`), OkAsync()), + : (logger.info("arranged shipping", { orderId }), OkAsync()), }), }); ``` @@ -207,3 +227,5 @@ an id they already hold. A runtime of your own follows the same rule — see `StartOptions.unit` module whose teardown logs under the unit's trace id. - [Write a runtime](/how-to/write-a-runtime) — the `UnitMeta` a runtime submits, and why `id` must be unique. +- [Log and correlate](/how-to/log-and-correlate) — the shipped reader of this + record, end to end. diff --git a/docs/how-to/run-a-temporal-worker.md b/docs/how-to/run-a-temporal-worker.md index 4b38c4d..2570cbb 100644 --- a/docs/how-to/run-a-temporal-worker.md +++ b/docs/how-to/run-a-temporal-worker.md @@ -107,6 +107,7 @@ may re-run has to answer the same both times. import { ApplicationModule } from "@btravstack/example-order-application"; import { PersistenceModule } from "@btravstack/example-order-infrastructure"; import { orderContract } from "@btravstack/example-order-temporal-contract"; +import { observability } from "@btravstack/observability"; import { TemporalModule } from "@btravstack/temporal"; import { workflowsPathFromURL } from "@temporal-contract/worker/worker"; @@ -119,13 +120,21 @@ export const OrderTemporalWorker = TemporalModule("OrderTemporalWorker")({ workflows: { workflowsPath: workflowsPathFromURL(import.meta.url, "./workflows.js"), }, - imports: [ApplicationModule, PersistenceModule, FulfillmentModule], + imports: [ + ApplicationModule, + PersistenceModule, + FulfillmentModule, + observability(), + ], }); ``` `TemporalModule` is `Module(name)({...})` plus the starter's fields: it imports `temporal({ contract, workflows, … })`, provides the activities and -exports `TemporalRuntime`. The starter's runtime provider depends on its +exports `TemporalRuntime`. [`observability()`](/reference/observability) is the +other starter in the list — the `Logger` the use case and the fulfillment +services write to, bound from `LOG_LEVEL`, JSON per line on stdout, every line +carrying the activity attempt's own trace id. The starter's runtime provider depends on its activities port through di, so a root whose imports do not cover what the provider declared (`FulfillmentModule` here) is refused at `start` — di's gate; a root with no starter fails on arity (`NO RUNTIME`). `activities` is @@ -173,7 +182,12 @@ export const Pinned = TemporalModule("OrderTemporalWorkerLocal")({ address: "127.0.0.1:7233", gracePeriod: "5 seconds", forceAfter: "15 seconds", - imports: [ApplicationModule, PersistenceModule, FulfillmentModule], + imports: [ + ApplicationModule, + PersistenceModule, + FulfillmentModule, + observability(), + ], }); ``` @@ -249,7 +263,7 @@ arrange: (orderId) => ), ), ) - : (logger.info(`arranged shipping for order ${orderId}`), OkAsync()), + : (logger.info("arranged shipping", { orderId }), OkAsync()), ``` Failing as a **defect** is deliberate: the platform retries that attempt on diff --git a/docs/how-to/serve-orpc-over-http.md b/docs/how-to/serve-orpc-over-http.md index c6e00e9..a234961 100644 --- a/docs/how-to/serve-orpc-over-http.md +++ b/docs/how-to/serve-orpc-over-http.md @@ -125,18 +125,16 @@ oRPC's context stays empty: what a procedure needs, the provider declared. ## Step 3 — the composition root ```ts -import { - ApplicationModule, - Logger, -} from "@btravstack/example-order-application"; +import { ApplicationModule } from "@btravstack/example-order-application"; import { PersistenceModule } from "@btravstack/example-order-infrastructure"; import { HttpModule } from "@btravstack/http"; +import { Logger, observability } from "@btravstack/observability"; import { orderRouter } from "./router.js"; export const OrderApi = HttpModule("OrderApi")({ router: orderRouter, - imports: [ApplicationModule, PersistenceModule], + imports: [ApplicationModule, PersistenceModule, observability()], exports: [Logger], }); ``` @@ -147,12 +145,18 @@ exactly the module the hand-written form would: ```ts Module("OrderApi")({ - imports: [ApplicationModule, PersistenceModule, http()], + imports: [ApplicationModule, PersistenceModule, observability(), http()], provides: [orderRouter], exports: [HttpRuntime, Logger], }); ``` +[`observability()`](/reference/observability) is the other starter here: it +brings the `Logger` the use cases and the request scope write to, bound from +`LOG_LEVEL`, one JSON object per line on stdout, every line carrying the +trace id of the unit `http()` opened around the request. It is exported +because the per-request `RequestModule` reads it. + Two gates hold at compile time. A root that forgets the starter exports no runtime port and `start` fails on arity (`NO RUNTIME`). A root that imports `http()` without providing the router carries an unmet need — the starter's @@ -163,18 +167,30 @@ the module. ```ts import { runMain } from "@btravstack/core"; +import { + createLogger, + jsonSink, + kernelEvents, +} from "@btravstack/observability"; import { OrderApi } from "./module.js"; import { RequestModule } from "./request-scope.js"; -await runMain(OrderApi, { unit: RequestModule }); +await runMain(OrderApi, { + unit: RequestModule, + onEvent: kernelEvents(createLogger(jsonSink())), +}); ``` That is the whole process. `PORT` (default `3000`), `HOST` (default -`0.0.0.0`) and the kernel's `PROBE_PORT` are read inside the graph from the +`0.0.0.0`), `LOG_LEVEL` (default `info`) and the kernel's `PROBE_PORT` are +read inside the graph from the `Env` port; a malformed one is a `ConfigInvalid`, reported as `startFailed` and exit `78`. `RequestModule` is optional — see -[Open a per-request scope](/how-to/open-a-per-request-scope). +[Open a per-request scope](/how-to/open-a-per-request-scope) — and so is +`onEvent`, which puts the kernel's own lifecycle events in the application's +stream rather than the default JSON on stderr; see +[Log and correlate](/how-to/log-and-correlate). ## Options @@ -235,6 +251,9 @@ Every request is a unit with a minted `id: randomUUID()`. A non-blank inbound `x-request-id` header becomes the unit's `traceId`, so a line logged by an adapter that reads `currentUnit()` joins a trace that started outside the process; a blank header is ignored rather than winning over the minted id. +`observability()`'s logger reads that record per call, so every line written +under the request already carries it — see +[Log and correlate](/how-to/log-and-correlate). ## See also diff --git a/docs/how-to/test-an-application.md b/docs/how-to/test-an-application.md index e53f28d..e32ed5b 100644 --- a/docs/how-to/test-an-application.md +++ b/docs/how-to/test-an-application.md @@ -15,7 +15,8 @@ Everything you need is in `@btravstack/testing`, a dev dependency (`pnpm add -D @btravstack/testing`) that peers on `@btravstack/core`, `@btravstack/config`, `@btravstack/di` and `unthrown` — the copies your application already holds. Five tools: `bootFixture` boots and stops inside a -vitest fixture, `tapped` reaches a service of a running graph, `withApp` +vitest fixture, `tapped` reaches a service of a running graph (its lines come +back through `observability({ sink })` instead), `withApp` starts and stops around a callback, `testRuntime` stands in for a transport, `createFakeClock` moves time when you say so. @@ -74,36 +75,83 @@ asserting. ## Reach a running service with `tapped` `start` hands the application context to the runtime alone, so a spec has no -`ctx.get` to reach the very `Logger` the use cases wrote to. `tapped(module, +`ctx.get` to reach the very `OrderRepository` the running graph writes +through. `tapped(module, [Port, …])` composes one more provider around the module and hands back what it was built with; boot `tap.module` in place of the module and read `tap.services()` afterwards: ```ts -it("logs each request under its own trace id", async ({ boot }) => { - // GIVEN the real graph, tapped on the very Logger it holds - const tap = tapped(OrderApi, [Logger]); - const app = boot(tap.module, { unit: RequestModule }); - const info = (await app.runtimeInfo()).get(); - const client = createOrderApiClient(`http://127.0.0.1:${info?.port}`); - - // WHEN two calls are served +it("broadcasts every committed write, end to end", async ({ serve }) => { + // GIVEN the real graph, tapped on the writer the spec places orders through + const tap = tapped(OrderAmqpWorker, [PlaceOrder, OrderRepository, Outbox]); + await serve(tap.module); + const [placeOrder] = tap.services(); + + // WHEN an order is placed — one ordinary write, no publish in sight + // THEN it is the very instance the relay sweeps, so the fact crosses the + // outbox, the broker and the queue + await expect(placeOrder.execute("o-1", 2)).toBeOkWith( + expect.objectContaining({ id: "o-1" }), + ); +}); +``` + +The gate refuses a port the module does not export (`NOT EXPORTED`, at the +call site), and `services()` throws if read before the graph is built — a +bug in the test, kept loud rather than answered with an `undefined`. + +## Read a running graph's log lines with a sink + +A tap is the wrong tool for this, and `examples/order-api` uses none: +`@btravstack/observability`'s `observability({ sink })` is the seam. The sink +is a value the composition takes, so what a spec gets back is the `Line` +itself — `unit.traceId` as a field rather than a prefix parsed out of a +string. Compose the root's own shape with a recording sink, and boot that: + +```ts +const lines: Line[] = []; + +const recordingApi = HttpModule("RecordingApi")({ + router: orderRouter, + imports: [ + ApplicationModule, + PersistenceModule, + // Pinned rather than bound: the fixture's `LOG_LEVEL` silences the real + // root, and this root exists to be read. + observability({ sink: (line) => lines.push(line), level: "trace" }), + ], + exports: [Logger], +}); + +it("runs each call in its own unit, with its own trace id", async ({ + serve, + clientFor, +}) => { + // GIVEN the real graph's composition, recording every line its logger writes + const client = await clientFor(serve(recordingApi)); + + // WHEN two calls are served — chained, so neither `Result` is dropped const served = await client.orders .place({ id: "o-1", quantity: 1 }) .flatMap(() => client.orders.place({ id: "o-2", quantity: 1 })); - // THEN the lines carry two distinct trace ids - const [logger] = tap.services(); - const traces = logger - .lines() - .map((line) => line.slice(0, line.indexOf("]") + 1)); - expect(served.map(() => new Set(traces).size)).toBeOkWith(2); + // THEN four lines, two distinct trace ids, none written outside a unit + const traced = served.map(() => ({ + lines: lines.length, + distinct: new Set(lines.map((line) => line.unit?.traceId)).size, + outOfUnit: lines.filter((line) => line.unit === undefined).length, + })); + + expect(traced).toBeOkWith({ lines: 4, distinct: 2, outOfUnit: 0 }); }); ``` -The gate refuses a port the module does not export (`NOT EXPORTED`, at the -call site), and `services()` throws if read before the graph is built — a -bug in the test, kept loud rather than answered with an `undefined`. +A parallel root rather than `OrderApi` itself, because nothing can be layered +over a graph that already provides `Logger`. Give the fixture's own `env` a +`LOG_LEVEL: "fatal"` so the real root — whose sink is the production +`jsonSink()` on stdout — does not write into the runner's output. See +[Log and correlate](/how-to/log-and-correlate). ## A one-off with `withApp` @@ -210,30 +258,38 @@ the example's own fixtures on top of `boot`: ```ts export const it = test.extend({ - boot: bootFixture({ env: { PORT: "0", HOST: "127.0.0.1" } }), + boot: bootFixture({ + env: { PORT: "0", HOST: "127.0.0.1", LOG_LEVEL: "fatal" }, + }), serve: async ({ boot }, use) => { await use((module, options) => boot(module, { unit: RequestModule, ...options }), ); }, - // …clientFor, probesFor, statusOf, api, unmodelled, gate, tapped + // …clientFor, probesFor, statusOf, api, unmodelled, gate, recording }); ``` `serve` is `boot` with `RequestModule` forked around every request, so its shutdown is still the fixture's; `clientFor` builds the oRPC client from -`runtimeInfo()`; and `tapped` is the example's tap on the real root: +`runtimeInfo()`; and `recording` is the real root's composition with a +recording sink in place of stdout: ```ts -const tappedApi = () => { - const tap = tapped(OrderApi, [Logger]); +const recordingApi = () => { + const recorder = recorderOf(); return { - api: tap.module, - traces: (): readonly string[] => { - const [logger] = tap.services(); - return logger.lines().map((line) => line.slice(0, line.indexOf("]") + 1)); - }, + api: HttpModule("RecordingApi")({ + router: orderRouter, + imports: [ + ApplicationModule, + PersistenceModule, + observability({ sink: recorder.sink, level: "trace" }), + ], + exports: [Logger], + }), + lines: recorder.lines, }; }; ``` @@ -242,8 +298,9 @@ const tappedApi = () => { to prove `completed: 1` and `abandoned: 1` against the real HTTP runtime (see [Swap an adapter for tests](/how-to/swap-an-adapter)). The other two examples follow the same shape — `boot: bootFixture()`, a `serve` that adds the -transport's own environment, `tapped` over the services the specs assert -through — and pay a fixture cost, stated in their READMEs: +transport's own environment, `tapped` over the **services** the specs assert +through and `observability({ sink })` for the lines — and pay a fixture cost, +stated in their READMEs: `order-temporal-worker` runs a real Worker against `@temporalio/testing`'s **time-skipping test server**, a local binary downloaded once into `.cache/temporal-test-server` (network on a cold cache only); diff --git a/docs/index.md b/docs/index.md index 2898643..1a86f0e 100644 --- a/docs/index.md +++ b/docs/index.md @@ -109,7 +109,7 @@ Beat two is the whole point — see [Draining, in three beats](/explanation/drai ## Packages -Seven packages, one dependency direction — `core` → `config` → `di`, every +Eight packages, one dependency direction — `core` → `config` → `di`, every starter on top of `core`, and a test harness beside them. Details and install lines in [Packages and install](/reference/packages). @@ -119,6 +119,10 @@ lines in [Packages and install](/reference/packages). `Config.object`, `Config.provider`, the `Env` port, `ConfigInvalid`. - **`@btravstack/core`** — the kernel: `start`, `runMain`, the lifecycle state machine, the unit registry and the `Runtime` contract. +- **`@btravstack/observability`** — logging, as a starter: a strict `Logger` + port stamped with the ambient unit's trace id, a dependency-free JSON sink, + pino behind a subpath, and the kernel's own events as lines in the same + stream. Traces and metrics are not here yet. - **`@btravstack/http`** — the HTTP starter: an oRPC contract served over `node:http`, one unit per request, `HttpRouter` and `HttpModule`. - **`@btravstack/temporal`** — the Temporal worker starter: one unit per diff --git a/docs/reference/amqp.md b/docs/reference/amqp.md index b863ffd..5c08512 100644 --- a/docs/reference/amqp.md +++ b/docs/reference/amqp.md @@ -66,12 +66,17 @@ The worked composition root, from `examples/order-amqp-worker/src/module.ts`: export const OrderAmqpWorker = AmqpModule("OrderAmqpWorker")({ contract: orderContract, handlers: orderHandlers, - imports: [ApplicationModule, PersistenceModule], + imports: [ApplicationModule, PersistenceModule, observability()], provides: [relayConfig, outboxRelay], exports: [PlaceOrder, OrderRepository, Outbox, Logger], }); ``` +[`observability()`](/reference/observability) is a second starter, not this +package's business: it brings the `Logger` the handlers and the relay write +to, bound from `LOG_LEVEL`, JSON per line on stdout, every line carrying the +delivery's own unit. + ## `AmqpHandlers(contract)` The first call fixes the contract type (the value is otherwise unused) and @@ -97,8 +102,12 @@ export const orderHandlers = AmqpHandlers(orderContract)([Logger], { const { id, payload } = message.payload; logger.info( payload === null - ? `order ${id} is gone — notifying` - : `order ${id} placed — notifying (${payload.quantity} items)`, + ? "order gone — notifying" + : "order placed — notifying", + { + orderId: id, + ...(payload === null ? {} : { quantity: payload.quantity }), + }, ); return OkAsync(); }, diff --git a/docs/reference/glossary.md b/docs/reference/glossary.md index 3101811..4e85bf8 100644 --- a/docs/reference/glossary.md +++ b/docs/reference/glossary.md @@ -99,15 +99,32 @@ runs a callback, and closes it on every path, running finalisers in reverse. `Scope` is also the phantom need an `acquire`/`release` provider adds. See [Scopes and resource safety](/explanation/scopes-and-resources). -**starter** — A package that brings a runtime and its defaults for the standard case, in -the Spring Boot sense: `@btravstack/http`, `@btravstack/temporal`, -`@btravstack/amqp`, each with a module sugar and a port-and-provider sugar. See -[Starters](/explanation/starters). +**sink** — Two of them, and they are not the same thing. An **`EventSink`** takes a +`KernelEvent` (`stderrSink` is the default); a **`Sink`** takes a `Line` +(`jsonSink` is the default, `pinoSink` the alternative). `kernelEvents(logger)` +is the adapter that makes the first out of the second. Neither may take the +process down: a throwing one is swallowed. See [Kernel +events](/reference/core/events) and +[@btravstack/observability](/reference/observability). + +**starter** — A package that brings one concern's defaults for the standard case, in the +Spring Boot sense: `@btravstack/http`, `@btravstack/temporal` and +`@btravstack/amqp` each bring a runtime, a module sugar and a +port-and-provider sugar; `@btravstack/observability` brings a `Logger` and no +runtime. See [Starters](/explanation/starters). + +**structured logging** — A line whose message is a constant and whose facts are fields — `info("placing +an order", { orderId, quantity })`, not a rendered sentence — so the receiving +system groups by message and filters by field. `Attributes` is flat and +scalar for that reason, and the ambient unit's ids are added by the +implementation rather than by the caller. See [Log and +correlate](/how-to/log-and-correlate). **trace id** — `UnitRecord.traceId` — the correlation id, defaulting to `UnitMeta.id`, -which a runtime may supply from outside the process (a `traceparent` header, -a message property). Why `UnitMeta.id` must be unique per unit. See -[The Runtime contract](/reference/core/runtime). +which a runtime may supply from outside the process (an `x-request-id` header, +a message id, a workflow id). Why `UnitMeta.id` must be unique per unit. It is +the field `@btravstack/observability`'s logger stamps on every line without +the caller naming it. See [The Runtime contract](/reference/core/runtime). **unit / unit of work** — One piece of work a runtime submits through `host.run(meta, work)`: an HTTP request, an activity attempt, a delivery. The kernel counts it towards the diff --git a/docs/reference/http.md b/docs/reference/http.md index ccad4aa..3a9e0f7 100644 --- a/docs/reference/http.md +++ b/docs/reference/http.md @@ -59,14 +59,17 @@ The worked composition root, from `examples/order-api/src/module.ts`: ```ts export const OrderApi = HttpModule("OrderApi")({ router: orderRouter, - imports: [ApplicationModule, PersistenceModule], + imports: [ApplicationModule, PersistenceModule, observability()], exports: [Logger], }); ``` That is exactly the module -`Module("OrderApi")({ imports: [ApplicationModule, PersistenceModule, http()], provides: [orderRouter], exports: [HttpRuntime, Logger] })` -would have declared. +`Module("OrderApi")({ imports: [ApplicationModule, PersistenceModule, observability(), http()], provides: [orderRouter], exports: [HttpRuntime, Logger] })` +would have declared. [`observability()`](/reference/observability) is a second +starter, not this package's business: it brings the `Logger` the application +writes to, bound from `LOG_LEVEL`, JSON per line on stdout, every line +carrying the trace id of the unit this runtime opened. ## `HttpRouter(contract)(deps, { sync })` diff --git a/docs/reference/observability.md b/docs/reference/observability.md new file mode 100644 index 0000000..1bc45b2 --- /dev/null +++ b/docs/reference/observability.md @@ -0,0 +1,435 @@ +--- +title: "@btravstack/observability" +description: The complete surface of @btravstack/observability — the Logger port, createLogger, jsonSink, pinoSink, the observability starter, LOG_LEVEL and kernelEvents. +--- + +# @btravstack/observability + +> **Reference.** A complete, structured description of +> `@btravstack/observability`: the `Logger` port and its service, the default +> implementation, the `Line`/`Sink` contract, the two sinks, the starter and +> the `LOG_LEVEL` field, and the kernel-event adapter. For the task, see +> [Log and correlate](/how-to/log-and-correlate); for the generated +> signatures, see the [API reference](/api/observability/). + +Logging, today. The package is named for the whole of observability because +logs, traces and metrics share a correlation id, a resource, a configuration +slice and a flush-on-shutdown lifecycle — splitting them across two packages +would duplicate all four. **Traces and metrics are not here yet.** + +## Install + +```sh +pnpm add @btravstack/observability @btravstack/core @btravstack/config @btravstack/di unthrown +``` + +Those four are peers. `pino` is an **optional** peer, needed only if you +import the `@btravstack/observability/pino` subpath: + +```sh +pnpm add pino +``` + +The package itself has no runtime dependencies: the default sink is +`JSON.stringify` and a `write`, for the same reason `Config` is a hand-rolled +Standard Schema. + +## `Logger` and `LoggerService` + +```ts +class Logger extends Port("Logger") {} + +type LoggerService = { + readonly log: ( + level: Level, + message: string, + attributes?: Attributes, + cause?: unknown, + ) => void; + readonly trace: ( + message: string, + attributes?: Attributes, + cause?: unknown, + ) => void; + readonly debug: ( + message: string, + attributes?: Attributes, + cause?: unknown, + ) => void; + readonly info: ( + message: string, + attributes?: Attributes, + cause?: unknown, + ) => void; + readonly warn: ( + message: string, + attributes?: Attributes, + cause?: unknown, + ) => void; + readonly error: ( + message: string, + attributes?: Attributes, + cause?: unknown, + ) => void; + readonly fatal: ( + message: string, + attributes?: Attributes, + cause?: unknown, + ) => void; + readonly with: (attributes: Attributes) => LoggerService; + readonly isEnabled: (level: Level) => boolean; +}; +``` + +`Logger` is a di port like any other: a provider binds it, a dependency array +names it, a test provides its own. It is the **framework's** port rather than +each application's, because the framework itself logs — `kernelEvents` below — +and an application-declared port could not serve both. + +**Every method takes the same three arguments in the same order**, and every +level can carry a failure. The first draft did not: `error(message, cause, +attributes)` read better at the one call site that always has a cause, and it +cost twice — a caller had to remember which arm it was in, and `warn` had +nowhere to put a cause, so a retryable failure (a broker refusing a publish, +which the next sweep takes) was logged at `error` purely to keep its reason. +A failure is not a property of severity. The cost of uniformity is +`logger.error("boom", undefined, cause)` for a failure with nothing else to +say, which is rare: a line worth writing almost always has an id to write with +it. + +Every method returns `void` and none of them is an `AsyncResult`. A log call +is fire-and-forget by definition — a caller who awaited it would be waiting on +I/O to decide nothing — and this is the package's exemption from the rule that +[every async surface returns a `Result`](/explanation/nothing-throws). + +### Why the interface is strict + +Each row is a defect this shape does not have, and together they are the +package's whole argument: + +| Decision | What it rules out | +| ------------------------------------------- | ----------------------------------------------------------------------------------------------------------- | +| A **port**, never a class you `new` | A static instance, a `useLogger` reaching past DI, a global a test cannot replace | +| `with(attributes)` returns a **new** logger | `setContext` mutating the instance every caller shares, so two scopes interleave each other's context | +| `Attributes` is a flat record of scalars | `any` varargs, printf, and a logger that stringifies whatever it is handed — which is how a log call throws | +| A failure goes in **`cause`** | `JSON.stringify(error)` rendering `{}`: an `Error`'s `message` and `stack` are non-enumerable | +| It **cannot throw** | An observability fault becoming an outage; `createLogger` swallows a broken sink | +| Six levels, fixed | `LOG_LEVEL` validated against a set at startup, and `isEnabled` a comparison rather than a lookup | +| Correlation is the implementation's job | A trace id threaded through every signature to reach the one place that writes it out | + +## `Level`, `LEVELS` and `Attributes` + +```ts +type Level = "trace" | "debug" | "info" | "warn" | "error" | "fatal"; +const LEVELS: readonly Level[]; + +type Attributes = Readonly< + Record +>; +``` + +`LEVELS` is the six in order, least severe first — what `isEnabled` compares +through, what `logLevel` validates against, and what a future OpenTelemetry +bridge maps to severity numbers without a table of synonyms. There is no +`silly`, no `verbose` and no caller-defined addition. + +`Attributes` is flat and scalar deliberately. A nested object is where a +field's name stops being stable across lines (`user.id` on one, `user: { id }` +on another), and an `unknown` value is where a logger starts stringifying +whatever it is handed. Anything else is the caller's to render; a failure has +a channel of its own. + +## `createLogger(sink, level?)` + +```ts +createLogger(sink: Sink, level: Level = "info"): LoggerService; +``` + +The implementation. Two details are load-bearing: + +- **`currentUnit()` is read per call**, not captured at construction. One + logger is built per scope and every unit the kernel opens has its own + record, so a captured one would stamp the first unit's trace id on every + line thereafter. This is what makes a single application-scope logger + correct for every request. +- **Every write is wrapped.** A sink that throws is swallowed here — there is + nowhere left to report a broken reporter to, and a logger that takes the + process down is worse than a line nobody sees. + +`with(attributes)` layers attributes on top of this logger's and shares the +sink, so a child costs one object. A **call's** attribute wins over the +layered one; nothing mutates. + +A line below `level` is dropped before the sink is called and before +`currentUnit()` is read. + +## `Line` and `Sink` + +```ts +type Line = { + readonly level: Level; + readonly message: string; + readonly attributes: Attributes; + readonly cause: unknown; + readonly time: number; // milliseconds since the epoch, stamped at the write + readonly unit: + | { + readonly unitId: string; + readonly traceId: string; + readonly tenantId?: string; + } + | undefined; +}; + +type Sink = (line: Line) => void; +``` + +`unit` is what [`currentUnit()`](/how-to/read-the-ambient-unit) carried, or +`undefined` outside a unit — a startup line, a package's own specs. `tenantId` +is present only when the runtime supplied one; no shipped starter does. +`deadline` and `signal` are on the ambient record but not on the line: they +are for code that must act on them, not for a log backend. + +A `Sink` is allowed to throw. `createLogger` is what makes that safe, which is +why a sink is a plain function with no error channel of its own. + +## `jsonSink(stream?)` + +```ts +jsonSink(stream?: { readonly write: (chunk: string) => unknown }): Sink; +``` + +The default: one JSON object per line, `process.stdout` unless a stream is +given. The shape every log backend already reads, and the same one the +kernel's `stderrSink` writes its events in. + +```json +{ + "orderId": "o-1", + "quantity": 2, + "time": "2026-08-16T09:41:02.113Z", + "level": "info", + "message": "placing an order", + "unitId": "3f9c…", + "traceId": "b41e…" +} +``` + +Three rules: + +- **The unit's ids are spread at the top level**, not nested under `unit`. A + log backend indexes fields, and `traceId` is the field an operator searches. +- **A caller's attribute can never overwrite one of them**, nor `level`, + `message` or `time`. An `attributes: { level: "info" }` that could rewrite + the severity is how a log stream stops being trustworthy. +- **`cause` is normalised**, not stringified: an `Error` becomes + `{ name, message, stack, cause }` and the `cause` chain is walked up to four + levels. `JSON.stringify` skips non-enumerable properties, so a bare `Error` + would render the line that exists to carry a failure as `{}` — the same rule, + and the same reason, as the kernel's `stderrSink`. + +A payload `JSON.stringify` refuses outright — a circular value reaching in +through `cause` is the plausible one — falls back to the time, level, message +and `cause: "[unserialisable]"` rather than costing the line. + +## `observability(options?)` + +```ts +observability(options?: ObservabilityOptions): + Module; + +type ObservabilityOptions = { + readonly sink?: Sink; // default: jsonSink() + readonly level?: Level; // pins LOG_LEVEL +}; +``` + +The starter: a module providing the application's `Logger` and the +`LoggerConfig` it was built from, both exported. Import it next to the +application and export `Logger` if anything outside the root reads it — +`StartOptions.unit`'s module, a test: + +```ts +export const OrderApi = HttpModule("OrderApi")({ + router: orderRouter, + imports: [ApplicationModule, PersistenceModule, observability()], + exports: [Logger], +}); +``` + +It needs `Env`, which `start` provides to every graph it boots; outside the +kernel, provide it yourself with `Provider(Env)({ value: {} })`. Its error +channel is `ConfigInvalid`, which is how a bad `LOG_LEVEL` reaches +[exit code `78`](/reference/core/exit-codes). + +`level` **pins** the way every starter's options pin — `Config.pinned`, +precedence explicit > environment > default, per field. `sink` replaces the +destination and nothing else; the level filter stays this package's. + +An application that wants its own implementation entirely does not import +this module and provides `Logger` itself. Nothing else in the graph can tell. + +## `LoggerConfig` and `LOG_LEVEL` + +```ts +class LoggerConfig extends Port("LoggerConfig") {} +type LoggerSettings = { readonly level: Level }; +``` + +One variable today, bound through `Config.provider` like any other slice: + +| Variable | Field | Default | Invalid | +| ----------- | -------------------------------- | ------- | ---------------------------------------------------------------------- | +| `LOG_LEVEL` | one of the six levels, no others | `info` | `must be one of trace, debug, info, warn, error, fatal, got "verbose"` | + +A value outside the six is a `ConfigInvalid` naming the variable and the set — +reported as a `startFailed` event and **exit `78`** under `runMain`, before a +line is written — rather than a silent fallback: a deployment that meant +`debug` and typed `verbose` should be told, not quietly under-logged for a +week. + +It is built on `Config.string`, so it inherits the semantics every other +variable has: an **unset** variable takes the default, a **set-but-blank** one +is an error. See [`@btravstack/config`](/reference/config). + +### `logLevel(options?)` + +```ts +logLevel(options?: { readonly default?: Level }): ConfigField; +``` + +That field on its own, exported so an application composing its own schema +reuses the validation rather than re-deriving it: + +```ts +const appConfig = Config.provider("AppConfig")( + Config.object({ + level: logLevel({ default: "debug" }), + region: Config.string("REGION"), + }), +); +``` + +## `kernelEvents(logger)` + +```ts +kernelEvents(logger: LoggerService): EventSink; +``` + +The kernel's [nine lifecycle events](/reference/core/events) as log lines on +`logger`, for `StartOptions.onEvent`. The kernel's own default writes JSON to +stderr, which is right for a process with no logger and wrong for one with: +two streams, two shapes, two sets of fields to search. + +The mapping is deliberate rather than mechanical. Each event's own fields +become **attributes**, so a drain is queryable by field rather than parsed out +of a sentence: + +| Event | Level | Message | Attributes besides `event` | Carries `cause` | +| --------------- | ------- | ------------------------------------------------------- | ------------------------------------------- | --------------- | +| `building` | `info` | `building` | — | — | +| `startFailed` | `error` | `the application failed to start` | — | yes | +| `serving` | `info` | `serving` | `runtime` | — | +| `draining` | `info` | `draining` | `inFlight` | — | +| `drained` | `info` | `drained` | `inFlightAtStart`, `completed`, `abandoned` | — | +| `stopping` | `info` | `stopping` | — | — | +| `exited` | `info` | `exited` | — | — | +| `teardownError` | `warn` | `a finaliser failed while the application was stopping` | `port` | yes | +| `uncaught` | `error` | `an uncaught exception stopped the application` | — | yes | + +Every line carries `event` — the event's own `type` — as an attribute, so one +query finds the transitions whatever the message says. `startFailed` and +`uncaught` are errors because they carry a cause and are what an operator is +paged for; `teardownError` is a warning because the application is already +stopping and [the exit code](/reference/core/exit-codes) already says `2`. + +::: warning The logger is a parameter, not a resolved port +`building` is emitted **while the graph is still being built**, and +`startFailed` when it never finished — so a sink taken out of the context it +is watching would have nothing to write the two events that matter most with. +That is why an application wiring this constructs a logger by hand in +`main.ts`, a second one deliberately, and the only one the framework asks +anybody to construct. +::: + +```ts +await runMain(OrderApi, { + unit: RequestModule, + onEvent: kernelEvents(createLogger(jsonSink())), +}); +``` + +That logger reads no `LOG_LEVEL` — the binding lives in the graph it is +watching — so it logs at the default `info`. + +## `pinoSink(logger)` + +```ts +import { pinoSink } from "@btravstack/observability/pino"; + +pinoSink(logger: import("pino").Logger): Sink; +``` + +A `Sink` over a pino logger, behind a subpath so `pino` can be an **optional** +peer: a consumer that never imports it never installs it. + +```ts +import pino from "pino"; +import { observability } from "@btravstack/observability"; +import { pinoSink } from "@btravstack/observability/pino"; + +observability({ sink: pinoSink(pino({ level: "trace" })) }); +``` + +Configure pino at `trace`. **The level filter stays this package's**: +`createLogger` has already decided the line is worth writing by the time a +sink sees it, so one filter is in the process, and it is the one `LOG_LEVEL` +validated at startup. Two filters that can disagree is the failure this +avoids. + +The attributes and the unit's ids ride as pino **fields**, not as a message +prefix, so they stay indexable; the cause is handed over as `err`, which +pino's own serialiser renders with the stack. Each of the six levels maps onto +pino's own method of the same name — `10` through `60` — so no level of ours +collapses into another. + +## Summary of exports + +| Export | Kind | +| ---------------------- | ------------------------------------------------- | +| `Logger` | port | +| `LoggerService` | type — the service behind it | +| `LoggerConfig` | port — `{ level }`, bound from `LOG_LEVEL` | +| `LoggerSettings` | type | +| `Level` / `LEVELS` | type / value — the six, in order | +| `Attributes` | type | +| `Line` / `Sink` | type — what an implementation hands a destination | +| `createLogger` | value — the implementation | +| `jsonSink` | value — the default sink | +| `observability` | value — the starter | +| `ObservabilityOptions` | type | +| `logLevel` | value — the `LOG_LEVEL` field alone | +| `kernelEvents` | value — the kernel's `EventSink` over a logger | +| `pinoSink` | value — `@btravstack/observability/pino` only | + +## What it does not do + +- **No traces and no metrics yet.** The shape they will take — `Tracer` / + `Meter` ports, the OpenTelemetry `NodeSDK` as a resourceful provider whose + `release` flushes, a span per unit through `StartOptions.unit`, W3C + `traceparent` feeding `UnitMeta.traceId` — is recorded in the package's own + spec. Nothing of it ships. +- **No transport, no rotation, no batching.** A sink is a function; a + deployment that wants any of those brings pino, or writes eleven lines of + its own. +- **No `Result` on a log call.** Delivery is the implementation's problem, and + a lost line is not a modeled error. + +## See also + +- [Log and correlate](/how-to/log-and-correlate) — the task, end to end. +- [Read the ambient unit from an adapter](/how-to/read-the-ambient-unit) — + the record the logger reads, and who else may read it. +- [Kernel events](/reference/core/events) — the nine `kernelEvents` maps. +- [Configure from the environment](/how-to/configure-from-the-environment) — + how `LOG_LEVEL` is bound, and what a bad one costs. diff --git a/docs/reference/packages.md b/docs/reference/packages.md index 63aa823..7e720af 100644 --- a/docs/reference/packages.md +++ b/docs/reference/packages.md @@ -1,33 +1,36 @@ --- title: Packages and install -description: The seven published packages, who peers on what, and one install command per kind of deployment. +description: The eight published packages, who peers on what, and one install command per kind of deployment. --- # Packages and install -> **Reference.** The seven published packages, their peer-dependency matrix and the +> **Reference.** The eight published packages, their peer-dependency matrix and the > install command for each kind of deployment. For _why_ everything is a peer > dependency, see [Peer dependencies](/explanation/peer-dependencies); for what > a starter is, see [Starters](/explanation/starters). ## The packages -| Package | What it is | Reference | -| ---------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | -| `@btravstack/di` | The container: ports as the vocabulary, providers bound at one edge, modules that declare their imports and exports. Depends on nothing. | [Ports](/reference/di/ports), [Providers](/reference/di/providers), [Modules](/reference/di/modules), [Entry points](/reference/di/entry-points), [Wiring defects](/reference/di/wiring-defects) | -| `@btravstack/config` | Configuration the twelve-factor way: `Env` as a port, typed fields bound from it through a schema, `ConfigInvalid` naming every fault. | [@btravstack/config](/reference/config) | -| `@btravstack/core` | The kernel: boot a module into a running process with one runtime, drain on SIGTERM, close the scope on every path, decide the exit code. | [start](/reference/core/start), [RunningApp](/reference/core/running-app), [Runtime](/reference/core/runtime), [Exit codes](/reference/core/exit-codes) | -| `@btravstack/http` | The HTTP starter: oRPC over `node:http`, one unit per request, `PORT`/`HOST` bound onto `HttpConfig`. | [@btravstack/http](/reference/http) | -| `@btravstack/temporal` | The Temporal starter: a Worker as the runtime, one unit per activity attempt, a drain that honours the kernel's deadline. | [@btravstack/temporal](/reference/temporal) | -| `@btravstack/amqp` | The AMQP starter: the handlers as a port, one unit per delivery, ack/nack/dead-letter routed by the contract. | [@btravstack/amqp](/reference/amqp) | -| `@btravstack/testing` | The test harness, a **dev dependency**: `bootFixture` boots and stops inside a vitest fixture, `tapped` reaches a running service, plus `withApp`, `testRuntime`, `createFakeClock`. | [@btravstack/testing](/reference/testing) | +| Package | What it is | Reference | +| --------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | +| `@btravstack/di` | The container: ports as the vocabulary, providers bound at one edge, modules that declare their imports and exports. Depends on nothing. | [Ports](/reference/di/ports), [Providers](/reference/di/providers), [Modules](/reference/di/modules), [Entry points](/reference/di/entry-points), [Wiring defects](/reference/di/wiring-defects) | +| `@btravstack/config` | Configuration the twelve-factor way: `Env` as a port, typed fields bound from it through a schema, `ConfigInvalid` naming every fault. | [@btravstack/config](/reference/config) | +| `@btravstack/core` | The kernel: boot a module into a running process with one runtime, drain on SIGTERM, close the scope on every path, decide the exit code. | [start](/reference/core/start), [RunningApp](/reference/core/running-app), [Runtime](/reference/core/runtime), [Exit codes](/reference/core/exit-codes) | +| `@btravstack/observability` | Logging, as a starter: a strict `Logger` port correlated with the ambient unit, a dependency-free JSON sink, pino behind a subpath, the kernel's events as lines. Traces and metrics are not here yet. | [@btravstack/observability](/reference/observability) | +| `@btravstack/http` | The HTTP starter: oRPC over `node:http`, one unit per request, `PORT`/`HOST` bound onto `HttpConfig`. | [@btravstack/http](/reference/http) | +| `@btravstack/temporal` | The Temporal starter: a Worker as the runtime, one unit per activity attempt, a drain that honours the kernel's deadline. | [@btravstack/temporal](/reference/temporal) | +| `@btravstack/amqp` | The AMQP starter: the handlers as a port, one unit per delivery, ack/nack/dead-letter routed by the contract. | [@btravstack/amqp](/reference/amqp) | +| `@btravstack/testing` | The test harness, a **dev dependency**: `bootFixture` boots and stops inside a vitest fixture, `tapped` reaches a running service, plus `withApp`, `testRuntime`, `createFakeClock`. | [@btravstack/testing](/reference/testing) | The dependency direction is **`core` → `config` → `di`**, never back. `di` depends on nothing in this workspace; `config` peers on `di`; `core` peers on -both; each starter peers on all three plus its own transport library; -`testing` peers on `core`, `config` and `di` and is installed as a dev -dependency, so a production bundle never pulls a fake in. Nothing here depends -on a runtime package: the kernel knows nothing about HTTP, AMQP or Temporal. +both; each starter peers on all three plus its own transport library — +`observability` is a starter with no transport library at all, so its three +peers are the only ones that are not optional; `testing` peers on `core`, +`config` and `di` and is installed as a dev dependency, so a production bundle +never pulls a fake in. Nothing here depends on a runtime package: the kernel +knows nothing about HTTP, AMQP or Temporal. The `examples/` workspaces (`order-api`, `order-temporal-worker`, `order-amqp-worker` and the rest) are **consumers, not fixtures**: they install @@ -41,18 +44,21 @@ third-party library a starter drives. An application installs each of them once, so `di`'s port identity and `unthrown`'s `isResult` compare against a single copy. -| Package | Peers on | -| ---------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| `@btravstack/di` | `unthrown` | -| `@btravstack/config` | `@btravstack/di`, `unthrown` | -| `@btravstack/core` | `@btravstack/config`, `@btravstack/di`, `unthrown` | -| `@btravstack/http` | `@btravstack/core`, `@btravstack/config`, `@btravstack/di`, `unthrown`, `@orpc/server`, `@orpc/contract`, `@unthrown/orpc` | -| `@btravstack/temporal` | `@btravstack/core`, `@btravstack/config`, `@btravstack/di`, `unthrown`, `@temporalio/worker`, `@temporalio/activity`, `@temporalio/common`, `@temporal-contract/worker`, `@temporal-contract/contract` | -| `@btravstack/amqp` | `@btravstack/core`, `@btravstack/config`, `@btravstack/di`, `unthrown`, `@amqp-contract/worker`, `@opentelemetry/api` | -| `@btravstack/testing` | `@btravstack/core`, `@btravstack/config`, `@btravstack/di`, `unthrown` — and **not** `vitest`: `bootFixture` is a plain `(ctx, use) => Promise`, vitest's fixture protocol met without the import | - -`@btravstack/core`, `@btravstack/config`, `@btravstack/di` and -`@btravstack/testing` have **no runtime dependencies** beyond `node:` builtins. `@btravstack/amqp` peers on +| Package | Peers on | +| --------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `@btravstack/di` | `unthrown` | +| `@btravstack/config` | `@btravstack/di`, `unthrown` | +| `@btravstack/core` | `@btravstack/config`, `@btravstack/di`, `unthrown` | +| `@btravstack/observability` | `@btravstack/core`, `@btravstack/config`, `@btravstack/di`, `unthrown` — and `pino`, the family's one **optional** peer, needed only by the `@btravstack/observability/pino` subpath | +| `@btravstack/http` | `@btravstack/core`, `@btravstack/config`, `@btravstack/di`, `unthrown`, `@orpc/server`, `@orpc/contract`, `@unthrown/orpc` | +| `@btravstack/temporal` | `@btravstack/core`, `@btravstack/config`, `@btravstack/di`, `unthrown`, `@temporalio/worker`, `@temporalio/activity`, `@temporalio/common`, `@temporal-contract/worker`, `@temporal-contract/contract` | +| `@btravstack/amqp` | `@btravstack/core`, `@btravstack/config`, `@btravstack/di`, `unthrown`, `@amqp-contract/worker`, `@opentelemetry/api` | +| `@btravstack/testing` | `@btravstack/core`, `@btravstack/config`, `@btravstack/di`, `unthrown` — and **not** `vitest`: `bootFixture` is a plain `(ctx, use) => Promise`, vitest's fixture protocol met without the import | + +`@btravstack/core`, `@btravstack/config`, `@btravstack/di`, +`@btravstack/testing` and `@btravstack/observability` have **no runtime +dependencies** beyond `node:` builtins — the default log sink is +`JSON.stringify` and a `write`. `@btravstack/amqp` peers on `@opentelemetry/api` because `@amqp-contract/worker` imports it unconditionally; `@amqp-contract/contract` is deliberately not in its list. @@ -93,6 +99,12 @@ pnpm add @btravstack/amqp @btravstack/core @btravstack/config @btravstack/di unt pnpm add @btravstack/core @btravstack/config @btravstack/di unthrown ``` +```sh [Logging] +pnpm add @btravstack/observability @btravstack/core @btravstack/config @btravstack/di unthrown +# and, only for the /pino subpath: +pnpm add pino +``` + ```sh [Testing] pnpm add -D @btravstack/testing ``` @@ -114,12 +126,15 @@ yet. The commands above are what they will be once it has. ## Entry points -| Specifier | Contents | -| --------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| `@btravstack/core` | `start`, `runMain`, `RuntimePort`, `RuntimeStartFailed`, `currentUnit`, `systemClock`, `stderrSink` and the types — see [start](/reference/core/start) | -| `@btravstack/testing` | `bootFixture`, `tapped`, `withApp`, `testRuntime`, `TestRuntimePort`, `createFakeClock` and the types — a package of its own, so a production bundle never pulls the fakes in; see [@btravstack/testing](/reference/testing) | -| `@btravstack/config` | `Env`, `Config`, `ConfigInvalid`, `ConfigFieldInvalid` and the types — see [@btravstack/config](/reference/config) | -| `@btravstack/di` | `Port`, `Provider`, `Module`, `Context` and the types — see [Ports](/reference/di/ports) | +| Specifier | Contents | +| -------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `@btravstack/core` | `start`, `runMain`, `RuntimePort`, `RuntimeStartFailed`, `currentUnit`, `systemClock`, `stderrSink` and the types — see [start](/reference/core/start) | +| `@btravstack/testing` | `bootFixture`, `tapped`, `withApp`, `testRuntime`, `TestRuntimePort`, `createFakeClock` and the types — a package of its own, so a production bundle never pulls the fakes in; see [@btravstack/testing](/reference/testing) | +| `@btravstack/config` | `Env`, `Config`, `ConfigInvalid`, `ConfigFieldInvalid` and the types — see [@btravstack/config](/reference/config) | +| `@btravstack/di` | `Port`, `Provider`, `Module`, `Context` and the types — see [Ports](/reference/di/ports) | +| `@btravstack/observability` | `Logger`, `createLogger`, `jsonSink`, `observability`, `LoggerConfig`, `logLevel`, `kernelEvents`, `LEVELS` and the types — see [@btravstack/observability](/reference/observability) | +| `@btravstack/observability/pino` | `pinoSink` alone, so `pino` stays an optional peer a consumer that never imports this never installs | -All seven packages ship dual CJS/ESM builds with `.d.ts` files and no source +All eight packages ship dual CJS/ESM builds with `.d.ts` files and no source maps (the tarball carries no `src/`, so a map would be a dead end). +`@btravstack/observability` is the only one with a second entry point. diff --git a/docs/reference/testing.md b/docs/reference/testing.md index 41c035d..7425bb5 100644 --- a/docs/reference/testing.md +++ b/docs/reference/testing.md @@ -104,30 +104,53 @@ type ServicesOf

= { ``` Read services out of a booted application. `start` hands the application -context to the runtime alone, so a test that wants the very `Logger` the use -cases write to — not a fresh one — has nothing to `ctx.get` it with. `tapped` -composes one more provider around `module`, depending on `ports`, and -remembers what it was built with. +context to the runtime alone, so a test that wants the very `OrderRepository` +the running graph writes through — not a fresh one — has nothing to `ctx.get` +it with. `tapped` composes one more provider around `module`, depending on +`ports`, and remembers what it was built with. -| Member | Semantics | -| ------------ | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| `module` | A `Module` exporting **exactly what `module` exports** — the kernel still finds the runtime, the gate still sees the same `X`. Boot this one instead of `module`. | -| `services()` | The service instances behind `ports`, in order, as a tuple typed by `ServicesOf

` (`const [logger] = tap.services()`). **Throws** before the graph has been built: reading a tap nobody booted is a bug in the test, not a modeled outcome, so it is loud rather than an `undefined`. | -| `...gate` | Phantom, at the call site: `NOT EXPORTED` names any port `module` does not export. An application-scope service is the only thing there is to tap; a unit-scoped port exists only while a unit is open. | +| Member | Semantics | +| ------------ | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `module` | A `Module` exporting **exactly what `module` exports** — the kernel still finds the runtime, the gate still sees the same `X`. Boot this one instead of `module`. | +| `services()` | The service instances behind `ports`, in order, as a tuple typed by `ServicesOf

` (`const [repository] = tap.services()`). **Throws** before the graph has been built: reading a tap nobody booted is a bug in the test, not a modeled outcome, so it is loud rather than an `undefined`. | +| `...gate` | Phantom, at the call site: `NOT EXPORTED` names any port `module` does not export. An application-scope service is the only thing there is to tap; a unit-scoped port exists only while a unit is open. | The tap provider is not exported and nothing resolves it; di builds every provider in a graph, exported or not, which is what makes the capture work. Its port is declared once, so two `tapped` modules in one graph are di's duplicate-provider defect at build — one tap per application is the shape. +A tap is for the **services** a spec drives or asserts against. +`examples/order-amqp-worker` taps the writer it places orders through and the +outbox it reads back, on a root composed to record what its logger wrote: + ```ts -const tap = tapped(OrderApi, [Logger]); -const app = boot(tap.module, { unit: RequestModule }); -await client.orders.place({ id: "o-1", quantity: 2 }); -const [logger] = tap.services(); -expect(logger.lines()).toHaveLength(2); +const lines: Line[] = []; +const recording = AmqpModule("RecordingAmqpWorker")({ + contract: orderContract, + handlers: orderHandlers, + imports: [ + ApplicationModule, + PersistenceModule, + observability({ sink: (line) => lines.push(line) }), + ], + provides: [relayConfig, outboxRelay], + exports: [PlaceOrder, OrderRepository, Outbox], +}); + +const tap = tapped(recording, [PlaceOrder, OrderRepository, Outbox]); +const app = await serve(tap.module); +const [placeOrder, repository, outbox] = tap.services(); ``` +Log lines are **not** what a tap is for, and `examples/order-api` no longer +uses one at all: [`observability({ sink })`](/reference/observability) is the +seam a spec reads a running graph's lines through, and what comes back is the +`Line` itself — `unit.traceId` as a field rather than a prefix parsed out of a +string. A sink is a value the composition takes, so nothing has to be reached +for inside the graph. See +[Log and correlate](/how-to/log-and-correlate). + ## `withApp(module, options, use)` ```ts diff --git a/docs/scripts/build-api.ts b/docs/scripts/build-api.ts index fbcaf9f..817fe86 100644 --- a/docs/scripts/build-api.ts +++ b/docs/scripts/build-api.ts @@ -24,7 +24,16 @@ const TYPEDOC = join( // Keep in sync with the `typedoc..json` files beside this script, with // `@btravstack/docs#build`'s `dependsOn` in the root `turbo.json`, and with the // `/api/` sidebar in `.vitepress/config.ts`. -const packages: readonly string[] = ["di", "config", "core", "testing", "http", "temporal", "amqp"]; +const packages: readonly string[] = [ + "di", + "config", + "core", + "testing", + "observability", + "http", + "temporal", + "amqp", +]; const results = await Promise.allSettled( packages.map(async (name) => { diff --git a/docs/tutorial/getting-started.md b/docs/tutorial/getting-started.md index 107aeea..f28ff87 100644 --- a/docs/tutorial/getting-started.md +++ b/docs/tutorial/getting-started.md @@ -245,6 +245,8 @@ numbers are `preDrainDelayMs` and `drainTimeoutMs` on runtime per process. - [Configure from the environment](/how-to/configure-from-the-environment) — bind your own configuration slice the way the starter binds `PORT`. +- [Log and correlate](/how-to/log-and-correlate) — `observability()` next to + the starter, and the kernel events above as lines in the same stream. - [Test an application](/how-to/test-an-application) — `bootFixture` from `@btravstack/testing`, and booting `App` on port `0`. - [Why start?](/explanation/why-start) — the theses this lesson quietly diff --git a/docs/typedoc.observability.json b/docs/typedoc.observability.json new file mode 100644 index 0000000..330ea7b --- /dev/null +++ b/docs/typedoc.observability.json @@ -0,0 +1,10 @@ +{ + "extends": "@btravstack/typedoc/base.json", + "name": "@btravstack/observability", + "entryPoints": [ + "../packages/observability/src/index.ts", + "../packages/observability/src/pino.ts" + ], + "tsconfig": "../packages/observability/tsconfig.json", + "out": "api/observability" +} diff --git a/examples/README.md b/examples/README.md index 5bff70b..cc5a51e 100644 --- a/examples/README.md +++ b/examples/README.md @@ -15,8 +15,8 @@ calls `start`. | Package | Layer | Shows | | ------------------------------------------------------ | --------- | ------------------------------------------------------------------------------------------------------------------------------------------------------- | | [`order-domain`](./order-domain) | domain | Entities and rules with no dependencies at all: branded fields, an `Entity.invariant` re-checked on every path, failures as values. | -| [`order-application`](./order-application) | use cases | Ports declared by the caller, interactors, and an `ApplicationModule` whose `OrderRepository` is deliberately an **unmet need**. | -| [`order-infrastructure`](./order-infrastructure) | adapters | A Prisma-backed repository over in-memory SQLite, translating P-codes into the domain's vocabulary and closing the application's one need. | +| [`order-application`](./order-application) | use cases | Ports declared by the caller, interactors, and an `ApplicationModule` whose `OrderRepository` and `Logger` are deliberately **unmet needs**. | +| [`order-infrastructure`](./order-infrastructure) | adapters | A Prisma-backed repository over in-memory SQLite, translating P-codes into the domain's vocabulary and closing the application's repository need. | | [`order-api-contract`](./order-api-contract) | contract | The oRPC contract on its own — wire shapes and declared error codes — taken by the server that implements it **and** by any client. | | [`order-api`](./order-api) | runtime | The first deployment: an oRPC router as a provider, served by the `http()` and `orpc()` starters, and `Result` → `ORPCError`. | | [`order-temporal-contract`](./order-temporal-contract) | contract | The Temporal contract on its own — one workflow, five activities, four declared `nonRetryable` errors — read by the worker, the sandbox and the client. | @@ -164,7 +164,7 @@ one runtime): `order-api`'s `orderRouter = HttpRouter(orderContract)([PlaceOrder FindOrder], { sync: (place, find) => ({ orders: { place: …, find: … } }) })`; `order-temporal-worker`'s `orderActivities = TemporalActivities(orderContract)([…four ports…], { sync })`; `order-amqp-worker`'s `orderHandlers = AmqpHandlers(orderContract)([Logger], -{ sync })` — di's own `Provider(port)(deps, arm)` on that port, typed by the +{ sync })`, on `@btravstack/observability`'s port — di's own `Provider(port)(deps, arm)` on that port, typed by the contract, and each composition root the matching `HttpModule` / `TemporalModule` / `AmqpModule` taking the provider. No starter declares a `needs` any more — all three runtimes are `Runtime` @@ -221,10 +221,14 @@ The three deployment suites test through [`@btravstack/testing`](../packages/testing), the way an application would: each `src/test-fixtures.ts` has a `boot` fixture — `bootFixture(...)`, which its `serve` builds on — so every app a test starts is stopped when the test -ends, on every exit path, and `tapped(module, [Logger, …])` hands back the -very services the running app was built with (the logger the use cases wrote -to, the repository the compensation assertions read through) instead of a -provider written into each suite to reach them. +ends, on every exit path, and `tapped(module, [OrderRepository, …])` hands back +the very services the running app was built with (the repository the +compensation assertions read through, the writer the relay sweeps) instead of a +provider written into each suite to reach them. Log lines need no tap at all: +every deployment composes `@btravstack/observability`'s `observability()`, and +a spec swaps the default stdout sink for a recorder — so what a handler said +comes back as a `Line`, and the assertions read `attributes.orderId` and +`unit.traceId` as fields. Where a guarantee is compile-time only — an unmet port, a runtime's `needs` — the assertion is a `@ts-expect-error` in a `*.test-d.ts` file, checked by `tsc` diff --git a/examples/order-amqp-worker/README.md b/examples/order-amqp-worker/README.md index 69ef53f..4ea97dc 100644 --- a/examples/order-amqp-worker/README.md +++ b/examples/order-amqp-worker/README.md @@ -14,7 +14,7 @@ binding its own queue to the `orders` exchange needs it and needs none of this. ``` src/handlers.ts the consuming half: orderHandlers, a provider on the starter's handlers port, built by AmqpHandlers from Logger src/outbox-relay.ts the publishing half: sweep the outbox, publish, mark sent — a resourceful provider -src/module.ts OrderAmqpWorker — the composition root, an AmqpModule, a constant +src/module.ts OrderAmqpWorker — the composition root, an AmqpModule importing observability(), a constant src/main.ts the process: runMain(OrderAmqpWorker), and nothing else src/test-fixtures.ts boot / serve / tapped, as Vitest fixtures, against a real RabbitMQ — boot and tapped from @btravstack/testing ``` @@ -58,7 +58,10 @@ handlers: orderHandlers, imports, provides, exports })` — a `Module(...)` that also takes the handlers provider: under the hood it imports the starter (`amqp({ contract: orderContract })`, the runtime on `AmqpRuntime` and the broker on `AmqpConfig`), provides `orderHandlers`, and -exports `AmqpRuntime` for `start` to resolve. There is no `needs`, no +exports `AmqpRuntime` for `start` to resolve. It also imports +`observability()`, the starter that provides the `Logger` both halves write to +— `LOG_LEVEL` from the environment, JSON on stdout, and every consumer line +carrying the delivery's own unit. There is no `needs`, no `context.ctx.get(...)`, and no port declared here over `RuntimePort` — the package ships it. @@ -100,6 +103,7 @@ the sugar cannot leave the handlers out). | `AMQP_URL` | `amqp://127.0.0.1:5672` | the broker (`AmqpConfig`), consumer and relay | | `PROBE_PORT` | `9000` | `/livez` / `/readyz` | | `OUTBOX_POLL_MS` | `200` | the relay's idle sleep (`RelayConfig`) | +| `LOG_LEVEL` | `info` | the `Logger`'s floor (`LoggerConfig`) | `OUTBOX_POLL_MS=0` is rejected at boot — a relay that never sleeps is a busy loop — and so is anything above `60000`. A bad value, or an empty one, is a @@ -124,9 +128,12 @@ pnpm --filter @btravstack/example-order-amqp-worker typecheck # the needs gate The fixtures are [`@btravstack/testing`](../../packages/testing)'s: `serve` boots the worker against the test's own vhost through the `boot` fixture, so it is stopped when the test ends, and `tapped` hands back the very -`PlaceOrder`, `OrderRepository`, `Outbox` and `Logger` the running app was +`PlaceOrder`, `OrderRepository` and `Outbox` the running app was built with — the writer the spec places orders through is the one the relay -sweeps. +sweeps. The consumer's own lines need no tap: the fixture composes the root's +shape with `observability({ sink })`, so what the notifier said arrives as +`Line` values and the assertions read `{ message, orderId, quantity }` rather +than a formatted sentence. ## What this deployment deliberately is not diff --git a/examples/order-amqp-worker/package.json b/examples/order-amqp-worker/package.json index 0ebbb88..f56fbfe 100644 --- a/examples/order-amqp-worker/package.json +++ b/examples/order-amqp-worker/package.json @@ -24,6 +24,7 @@ "@btravstack/example-order-amqp-contract": "workspace:*", "@btravstack/example-order-application": "workspace:*", "@btravstack/example-order-infrastructure": "workspace:*", + "@btravstack/observability": "workspace:*", "@opentelemetry/api": "catalog:", "unthrown": "catalog:" }, diff --git a/examples/order-amqp-worker/src/amqp-runtime.spec.ts b/examples/order-amqp-worker/src/amqp-runtime.spec.ts index 87b6c9e..4b27a74 100644 --- a/examples/order-amqp-worker/src/amqp-runtime.spec.ts +++ b/examples/order-amqp-worker/src/amqp-runtime.spec.ts @@ -1,22 +1,24 @@ +import type { Line } from "@btravstack/observability"; import { describe, expect } from "vitest"; import { it } from "./test-fixtures.js"; /** - * The notification lines, with the message unit's `[trace]` prefix stripped — - * what the consumer said is the assertion; that the middleware traced it is - * the package's own concern. + * The notification lines as `{ message, ...attributes }` — what the consumer + * said, and about which order. The `unit` every line also carries is the + * package's own concern, not this suite's, so it is projected away rather + * than parsed out of a string. */ -const notifications = (lines: readonly string[]): readonly string[] => +const notifications = (lines: readonly Line[]) => lines - .filter((line) => line.includes("notifying")) - .map((line) => line.slice(line.indexOf("]") + 2)); + .filter((line) => line.message.includes("notifying")) + .map((line) => ({ message: line.message, ...line.attributes })); describe("the broadcast deployment", () => { it("broadcasts every committed write, end to end", async ({ serve, tapped }) => { // GIVEN the app serving: relay sweeping the outbox, consumer on the queue await serve(tapped.module); - const { placeOrder, logger } = tapped.services(); + const { placeOrder } = tapped.services(); // WHEN an order is placed — one ordinary write, no publish in sight await expect(placeOrder.execute("o-1", 2)).toBeOkWith(expect.objectContaining({ id: "o-1" })); @@ -24,9 +26,8 @@ describe("the broadcast deployment", () => { // THEN the fact crosses the outbox, the broker and the queue, and the // consumer reacts — the write-side never spoke AMQP await expect - .poll(() => notifications(tapped.services().logger.lines()), { timeout: 5_000 }) - .toContain("order o-1 placed — notifying (2 items)"); - void logger; + .poll(() => notifications(tapped.lines()), { timeout: 5_000 }) + .toContainEqual({ message: "order placed — notifying", orderId: "o-1", quantity: 2 }); }); it("marks relayed events published, exactly once each", async ({ serve, tapped }) => { @@ -37,8 +38,8 @@ describe("the broadcast deployment", () => { // WHEN the relay has swept it await expect - .poll(() => notifications(tapped.services().logger.lines()), { timeout: 5_000 }) - .toContain("order o-2 placed — notifying (1 items)"); + .poll(() => notifications(tapped.lines()), { timeout: 5_000 }) + .toContainEqual({ message: "order placed — notifying", orderId: "o-2", quantity: 1 }); // THEN nothing is left pending — the next sweep has nothing to re-publish await expect(outbox.pending(10)).toBeOkWith([]); @@ -56,10 +57,10 @@ describe("the broadcast deployment", () => { // THEN the notifications arrive in the same order: the relay publishes by // outbox id, the queue preserves it, the consumer is sequential await expect - .poll(() => notifications(tapped.services().logger.lines()), { timeout: 5_000 }) + .poll(() => notifications(tapped.lines()), { timeout: 5_000 }) .toEqual([ - "order o-3 placed — notifying (1 items)", - "order o-4 placed — notifying (1 items)", + { message: "order placed — notifying", orderId: "o-3", quantity: 1 }, + { message: "order placed — notifying", orderId: "o-4", quantity: 1 }, ]); }); @@ -79,8 +80,11 @@ describe("the broadcast deployment", () => { // it was, then that it is gone. Without the tombstone a reader keeping its // own copy would hold a cancelled order forever. await expect - .poll(() => notifications(tapped.services().logger.lines()), { timeout: 5_000 }) - .toEqual(["order o-6 placed — notifying (2 items)", "order o-6 is gone — notifying"]); + .poll(() => notifications(tapped.lines()), { timeout: 5_000 }) + .toEqual([ + { message: "order placed — notifying", orderId: "o-6", quantity: 2 }, + { message: "order gone — notifying", orderId: "o-6" }, + ]); }); it("is a broadcast: a subscriber this repo never heard of receives it too", async ({ diff --git a/examples/order-amqp-worker/src/handlers.ts b/examples/order-amqp-worker/src/handlers.ts index d569efa..ed3c82a 100644 --- a/examples/order-amqp-worker/src/handlers.ts +++ b/examples/order-amqp-worker/src/handlers.ts @@ -2,7 +2,7 @@ import { RetryableError } from "@amqp-contract/worker"; import { AmqpHandlers } from "@btravstack/amqp"; import { currentUnit } from "@btravstack/core"; import { orderContract } from "@btravstack/example-order-amqp-contract"; -import { Logger } from "@btravstack/example-order-application"; +import { Logger } from "@btravstack/observability"; import { ErrAsync, OkAsync } from "unthrown"; /** @@ -44,11 +44,10 @@ export const orderHandlers = AmqpHandlers(orderContract)([Logger], { new RetryableError(`the drain deadline passed before order ${id} was notified`), ); } - logger.info( - payload === null - ? `order ${id} is gone — notifying` - : `order ${id} placed — notifying (${payload.quantity} items)`, - ); + logger.info(payload === null ? "order gone — notifying" : "order placed — notifying", { + orderId: id, + ...(payload === null ? {} : { quantity: payload.quantity }), + }); return OkAsync(); }, }), diff --git a/examples/order-amqp-worker/src/module.ts b/examples/order-amqp-worker/src/module.ts index 8244231..28234ac 100644 --- a/examples/order-amqp-worker/src/module.ts +++ b/examples/order-amqp-worker/src/module.ts @@ -2,12 +2,12 @@ import { AmqpModule } from "@btravstack/amqp"; import { orderContract } from "@btravstack/example-order-amqp-contract"; import { ApplicationModule, - Logger, OrderRepository, Outbox, PlaceOrder, } from "@btravstack/example-order-application"; import { PersistenceModule } from "@btravstack/example-order-infrastructure"; +import { Logger, observability } from "@btravstack/observability"; import { orderHandlers } from "./handlers.js"; import { outboxRelay, relayConfig } from "./outbox-relay.js"; @@ -19,7 +19,9 @@ import { outboxRelay, relayConfig } from "./outbox-relay.js"; * which imports the starter over `orderHandlers`, provides it, and exports * `AmqpRuntime` for `start` to resolve; the outbox relay sits next to it as a * resourceful provider: both halves of the outbox pattern in one graph, each - * built by di from the services it declares. + * built by di from the services it declares. `observability()` provides the + * `Logger` the consumer and the relay write to — `LOG_LEVEL`, JSON on stdout, + * every line correlated with the delivery's own unit. * * The exports are this deployment's own selection: `PlaceOrder` / * `OrderRepository` / `Outbox` / `Logger` are the writer's surface — what a @@ -37,7 +39,7 @@ import { outboxRelay, relayConfig } from "./outbox-relay.js"; export const OrderAmqpWorker = AmqpModule("OrderAmqpWorker")({ contract: orderContract, handlers: orderHandlers, - imports: [ApplicationModule, PersistenceModule], + imports: [ApplicationModule, PersistenceModule, observability()], provides: [relayConfig, outboxRelay], exports: [PlaceOrder, OrderRepository, Outbox, Logger], }); diff --git a/examples/order-amqp-worker/src/needs-gate.test-d.ts b/examples/order-amqp-worker/src/needs-gate.test-d.ts index def2e66..4a5e937 100644 --- a/examples/order-amqp-worker/src/needs-gate.test-d.ts +++ b/examples/order-amqp-worker/src/needs-gate.test-d.ts @@ -15,8 +15,9 @@ import { AmqpRuntime, amqp } from "@btravstack/amqp"; import { start } from "@btravstack/core"; import { Module } from "@btravstack/di"; import { orderContract } from "@btravstack/example-order-amqp-contract"; -import { ApplicationModule, Logger, PlaceOrder } from "@btravstack/example-order-application"; +import { ApplicationModule, PlaceOrder } from "@btravstack/example-order-application"; import { PersistenceModule } from "@btravstack/example-order-infrastructure"; +import { Logger, observability } from "@btravstack/observability"; import { orderHandlers } from "./handlers.js"; import { OrderAmqpWorker } from "./module.js"; @@ -30,7 +31,7 @@ const _wired = start(OrderAmqpWorker, options); // The same graph without `amqp()`: nothing declared over `RuntimePort` is // exported, so there is no runtime for `start` to resolve. const RuntimelessAmqp = Module("RuntimelessAmqp")({ - imports: [ApplicationModule, PersistenceModule], + imports: [ApplicationModule, PersistenceModule, observability()], exports: [PlaceOrder, Logger], }); @@ -44,7 +45,12 @@ const _noRuntime = start(RuntimelessAmqp, options); // with the `amqp()` primitive rather than `AmqpModule`, since the sugar cannot // leave the handlers out — that is what it is for. const HandlerlessAmqp = Module("HandlerlessAmqp")({ - imports: [ApplicationModule, PersistenceModule, amqp({ contract: orderContract })], + imports: [ + ApplicationModule, + PersistenceModule, + observability(), + amqp({ contract: orderContract }), + ], exports: [AmqpRuntime, PlaceOrder, Logger], }); diff --git a/examples/order-amqp-worker/src/outbox-relay.ts b/examples/order-amqp-worker/src/outbox-relay.ts index 5130a1c..4f2c793 100644 --- a/examples/order-amqp-worker/src/outbox-relay.ts +++ b/examples/order-amqp-worker/src/outbox-relay.ts @@ -3,7 +3,8 @@ import { AmqpConfig } from "@btravstack/amqp"; import { Config } from "@btravstack/config"; import { Port, Provider, type ServiceOf } from "@btravstack/di"; import { orderContract } from "@btravstack/example-order-amqp-contract"; -import { Logger, Outbox } from "@btravstack/example-order-application"; +import { Outbox } from "@btravstack/example-order-application"; +import { Logger } from "@btravstack/observability"; import { ErrAsync, P, TaggedError, fromSafePromise, type AsyncResult } from "unthrown"; /** @@ -108,14 +109,22 @@ const startOutboxRelay = ( published.push(event.id); }, errCases: (matcher) => - matcher.with(P.tag("@amqp-contract/MessageValidationError"), () => { - logger.info( - `outbox event ${event.id} does not fit the contract; left pending`, + matcher.with(P.tag("@amqp-contract/MessageValidationError"), (error) => { + logger.error( + "an outbox event does not fit the contract; left pending", + { eventId: event.id }, + error, ); }), defect: (cause) => { - logger.info( - `publishing outbox event ${event.id} failed, will retry: ${String(cause)}`, + // `warn`, not `error`: the broker refusing a publish is + // retryable and the next sweep takes it — and a warning + // carries its cause like any other line, which is what the + // uniform `(message, attributes, cause)` is for. + logger.warn( + "publishing an outbox event failed, will retry", + { eventId: event.id }, + cause, ); }, }); @@ -126,14 +135,18 @@ const startOutboxRelay = ( // `E = never`: the untouched builder is already exhaustive. errCases: (matcher) => matcher, defect: (cause) => { - logger.info(`marking outbox events published failed: ${String(cause)}`); + logger.error( + "marking outbox events published failed", + { count: published.length }, + cause, + ); }, }); } }, errCases: (matcher) => matcher, defect: (cause) => { - logger.info(`reading the outbox failed, will retry: ${String(cause)}`); + logger.warn("reading the outbox failed, will retry", undefined, cause); }, }); }; diff --git a/examples/order-amqp-worker/src/test-fixtures.ts b/examples/order-amqp-worker/src/test-fixtures.ts index 3a94b57..15b436e 100644 --- a/examples/order-amqp-worker/src/test-fixtures.ts +++ b/examples/order-amqp-worker/src/test-fixtures.ts @@ -1,14 +1,23 @@ import { it as amqpIt } from "@amqp-contract/testing"; import type { AmqpTestFixtures } from "@amqp-contract/testing/extension"; -import type { AmqpInfo, AmqpRuntime } from "@btravstack/amqp"; +import { AmqpModule, type AmqpInfo, type AmqpRuntime } from "@btravstack/amqp"; import type { Env } from "@btravstack/config"; import type { RunningApp } from "@btravstack/core"; import type { Module, Scope } from "@btravstack/di"; -import { Logger, OrderRepository, Outbox, PlaceOrder } from "@btravstack/example-order-application"; +import { orderContract } from "@btravstack/example-order-amqp-contract"; +import { + ApplicationModule, + OrderRepository, + Outbox, + PlaceOrder, +} from "@btravstack/example-order-application"; +import { PersistenceModule } from "@btravstack/example-order-infrastructure"; +import { observability, type Line } from "@btravstack/observability"; import { bootFixture, tapped, type Boot } from "@btravstack/testing"; import type { TestAPI } from "vitest"; -import { OrderAmqpWorker } from "./module.js"; +import { orderHandlers } from "./handlers.js"; +import { outboxRelay, relayConfig } from "./outbox-relay.js"; type App = RunningApp; @@ -19,7 +28,7 @@ type App = RunningApp; * exports. `AmqpRuntime` is what `start` resolves; the rest is the writer's * surface, which the tap below reads. */ -type AmqpPorts = AmqpRuntime | PlaceOrder | OrderRepository | Outbox | Logger; +type AmqpPorts = AmqpRuntime | PlaceOrder | OrderRepository | Outbox; type ServeOptions = { readonly drainTimeoutMs: number }; @@ -29,20 +38,39 @@ type Serve = ( ) => Promise>; /** - * `start` hands the application context to the runtime alone, so a spec cannot - * reach the services the way `Module.scoped` can. `@btravstack/testing`'s - * `tapped` captures the very instances the running app uses — the writer the - * spec places orders through (the same database the relay sweeps, which for - * `:memory:` SQLite is the whole point), the outbox it asserts against, and - * the logger the consumer writes its notification lines to. + * The composition root's own shape, with a recording sink in place of stdout — + * a parallel root rather than `OrderAmqpWorker` itself because nothing can be + * layered over a graph that already provides `Logger`, and + * `observability({ sink })` is the seam. What the consumer said comes back as + * `Line` values, so no tap is needed for it at all. + * + * `start` hands the application context to the runtime alone, so a spec still + * cannot reach the *services* the way `Module.scoped` can: + * `@btravstack/testing`'s `tapped` captures the very instances the running app + * uses — the writer the spec places orders through (the same database the + * relay sweeps, which for `:memory:` SQLite is the whole point) and the outbox + * it asserts against. */ const tappedAmqp = () => { - const tap = tapped(OrderAmqpWorker, [PlaceOrder, OrderRepository, Outbox, Logger]); + const lines: Line[] = []; + const recording = AmqpModule("RecordingAmqpWorker")({ + contract: orderContract, + handlers: orderHandlers, + imports: [ + ApplicationModule, + PersistenceModule, + observability({ sink: (line) => lines.push(line) }), + ], + provides: [relayConfig, outboxRelay], + exports: [PlaceOrder, OrderRepository, Outbox], + }); + const tap = tapped(recording, [PlaceOrder, OrderRepository, Outbox]); return { module: tap.module, + lines: (): readonly Line[] => lines, services: () => { - const [placeOrder, repository, outbox, logger] = tap.services(); - return { placeOrder, repository, outbox, logger }; + const [placeOrder, repository, outbox] = tap.services(); + return { placeOrder, repository, outbox }; }, }; }; @@ -53,9 +81,10 @@ export type AmqpFixtures = { /** Boots an app against this test's own vhost, through `boot` — so its shutdown is the fixture's. */ readonly serve: Serve; /** - * The composition root, plus a tap on the very service instances it runs. - * `serve` points it at this test's own vhost — its relay publishes to, and - * its consumer reads from, a broker no other test shares. + * The composition root's shape, plus a tap on the very service instances it + * runs and every line its logger wrote. `serve` points it at this test's own + * vhost — its relay publishes to, and its consumer reads from, a broker no + * other test shares. */ readonly tapped: ReturnType; }; diff --git a/examples/order-api/README.md b/examples/order-api/README.md index 9aad583..6a81788 100644 --- a/examples/order-api/README.md +++ b/examples/order-api/README.md @@ -13,8 +13,8 @@ src/router.ts the implementation as a provider, and the one place a doma src/request-scope.ts RequestModule — passed as StartOptions.unit; the kernel forks it per request src/client.ts an AsyncResult client for the same contract src/module.ts OrderApi — the composition root, HttpModule("OrderApi")({ router: orderRouter, … }) -src/main.ts the process: runMain(OrderApi, { unit: RequestModule }) -src/test-fixtures.ts boot / serve / clientFor / gate / tapped, as Vitest fixtures — boot and tapped from @btravstack/testing +src/main.ts the process: runMain(OrderApi, { unit: RequestModule, onEvent: kernelEvents(…) }) +src/test-fixtures.ts boot / serve / clientFor / gate / recording, as Vitest fixtures — boot from @btravstack/testing ``` ## The two channels survive the wire @@ -82,7 +82,7 @@ also knows about it: ```ts export const OrderApi = HttpModule("OrderApi")({ router: orderRouter, - imports: [ApplicationModule, PersistenceModule], + imports: [ApplicationModule, PersistenceModule, observability()], exports: [Logger], }); ``` @@ -91,8 +91,12 @@ export const OrderApi = HttpModule("OrderApi")({ (`http()` — the whole surface), provides the router and exports `HttpRuntime`, and returns exactly the di module `Module("OrderApi")({ imports: [ApplicationModule, PersistenceModule, -http()], provides: [orderRouter], exports: [HttpRuntime, -Logger] })` would have. The runtime provider depends on the router port +observability(), http()], provides: [orderRouter], exports: [HttpRuntime, +Logger] })` would have. `observability()` is the starter that provides the +`Logger` the use cases and the request scope write to — `LOG_LEVEL` bound from +the environment, one JSON object per line on stdout, and every line stamped +with the unit the runtime opened around it. It is exported because the +per-request `RequestModule` reads it. The runtime provider depends on the router port through di, so even the transport wiring exists because the composition root said so — a composition that imports the starter without providing `orderRouter` carries an unmet need @@ -155,11 +159,13 @@ Every helper they need is a Vitest fixture in `src/test-fixtures.ts`, so the spe opens on `describe` and each test names its dependencies in its own parameter list. Shutting an app down is the `boot` fixture's job — [`@btravstack/testing`](../../packages/testing)'s `bootFixture({ env: { PORT: -"0", HOST: "127.0.0.1" } })`, which `serve` builds on — which is why no test +"0", HOST: "127.0.0.1", LOG_LEVEL: "fatal" } })`, which `serve` builds on — which is why no test here has a `try`/`finally`: fixture cleanup runs even when the body fails, and a -shutdown that blows up (a `Defect` on `exited`) fails the test. `tapped`, from -the same package, hands back the very `Logger` the use cases wrote to, so the -trace assertions read the running app's own lines. +shutdown that blows up (a `Defect` on `exited`) fails the test. The lines the +running app writes come back through `observability({ sink })` — the same seam +a deployment swaps for pino — so the trace assertions read `line.unit.traceId` +as a field instead of parsing a prefix out of a string, and the stub roots pass +a no-op sink so a spec run is not also a log dump. ```ts it("lets an in-flight call finish while draining", async ({ serve, clientFor, gate }) => { @@ -177,11 +183,25 @@ it got back from `runtimeInfo()`. `src/main.ts` is the process itself, and it is one call: ```ts -await runMain(OrderApi, { unit: RequestModule }); +await runMain(OrderApi, { + unit: RequestModule, + onEvent: kernelEvents(createLogger(jsonSink())), +}); ``` +`onEvent` puts the kernel's nine lifecycle events in the same stream as the +application's own lines, instead of the kernel's default JSON on stderr — one +shape, one set of fields, one thing to search. The logger there is built **by +hand** rather than resolved from the graph, and it has to be: `building` is +emitted while the graph is still being constructed and `startFailed` when it +never finished, so a sink taken out of the context it is watching would have +nothing to write the two events that matter most with. This is the one example +that wires it, so the pattern is visible once; the other two `main.ts` files +stay a single line. + Configuration is read **inside the graph**: `http()` binds `PORT` (default `3000`) and `HOST` (default `0.0.0.0`) from the `Env` port the kernel provides, +`observability()` binds `LOG_LEVEL` (default `info`), and the kernel binds its own `PROBE_PORT` (default `9000`). A malformed value — `PORT=abc`, `PORT=` — is a `ConfigInvalid` the kernel reports as a `startFailed` event and exit code `78`, sysexits(3)'s `EX_CONFIG`; nothing in diff --git a/examples/order-api/package.json b/examples/order-api/package.json index eea6021..d000be2 100644 --- a/examples/order-api/package.json +++ b/examples/order-api/package.json @@ -23,6 +23,7 @@ "@btravstack/example-order-domain": "workspace:*", "@btravstack/example-order-infrastructure": "workspace:*", "@btravstack/http": "workspace:*", + "@btravstack/observability": "workspace:*", "@orpc/client": "catalog:", "@orpc/contract": "catalog:", "@unthrown/orpc": "catalog:", diff --git a/examples/order-api/src/api.spec.ts b/examples/order-api/src/api.spec.ts index 4ef0315..54a2a85 100644 --- a/examples/order-api/src/api.spec.ts +++ b/examples/order-api/src/api.spec.ts @@ -177,10 +177,10 @@ describe("order-api", () => { it("runs each call in its own unit, with its own trace id", async ({ serve, clientFor, - tapped, + recording, }) => { - // GIVEN the real graph with the very `Logger` instance the use cases write to - const client = await clientFor(serve(tapped.api)); + // GIVEN the real graph's composition, recording every line its logger writes + const client = await clientFor(serve(recording.api)); // WHEN two calls are served — chained, so neither `Result` is dropped const served = await client.orders @@ -188,16 +188,18 @@ describe("order-api", () => { .flatMap(() => client.orders.place({ id: "o-2", quantity: 1 })); // THEN two calls, two interactor lines plus two request-scope teardown - // lines, carrying two distinct trace ids and never the out-of-unit `[-]` + // lines, carrying two distinct trace ids and never one written outside a + // unit — read off the line's own `unit` field, which is what the logger + // stamps from `currentUnit()` per call const traced = served - .map(() => tapped.traces()) - .map((traces) => ({ - lines: traces.length, - distinct: new Set(traces).size, - outOfUnit: traces.filter((trace) => trace === "[-]"), + .map(() => recording.lines()) + .map((lines) => ({ + lines: lines.length, + distinct: new Set(lines.map((line) => line.unit?.traceId)).size, + outOfUnit: lines.filter((line) => line.unit === undefined).length, })); - expect(traced).toBeOkWith({ lines: 4, distinct: 2, outOfUnit: [] }); + expect(traced).toBeOkWith({ lines: 4, distinct: 2, outOfUnit: 0 }); }); it("lets an in-flight call finish while draining", async ({ serve, clientFor, gate }) => { diff --git a/examples/order-api/src/main.ts b/examples/order-api/src/main.ts index f119857..10c0218 100644 --- a/examples/order-api/src/main.ts +++ b/examples/order-api/src/main.ts @@ -1,4 +1,5 @@ import { runMain } from "@btravstack/core"; +import { createLogger, jsonSink, kernelEvents } from "@btravstack/observability"; import { OrderApi } from "./module.js"; import { RequestModule } from "./request-scope.js"; @@ -6,16 +7,34 @@ import { RequestModule } from "./request-scope.js"; /** * The whole process, in one call: build the graph, serve it, and turn the exit * report into a process exit code. The process reads `PORT` (default `3000`), - * `HOST` (default `0.0.0.0`) and `PROBE_PORT` (default `9000`) from the - * environment — inside the graph, not here — and a malformed one is the - * kernel's to report: a `startFailed` event and exit code `78`. + * `HOST` (default `0.0.0.0`), `LOG_LEVEL` (default `info`) and `PROBE_PORT` + * (default `9000`) from the environment — inside the graph, not here — and a + * malformed one is the kernel's to report: a `startFailed` event and exit code + * `78`. * * `RequestModule` is forked around every request by the kernel: `RequestSpan` * is built as the request opens and torn down as it closes, reading `Logger` * out of the application scope. The handler never sees the fork happen. * + * `onEvent` puts the kernel's own lifecycle events in the same stream as the + * application's lines — one shape, one set of fields, one thing to search — + * instead of the kernel's default JSON on stderr. The logger here is built by + * hand rather than resolved from the graph, and it has to be: `building` is + * emitted while the graph is still being constructed, and a `startFailed` is + * emitted when it never finished, so an `onEvent` that resolved its sink out + * of the context it is watching would have nothing to write the two events + * that matter most with. It is the same `jsonSink()` the graph's own `Logger` + * defaults to, so the two streams interleave cleanly; only the `LOG_LEVEL` + * binding is out of reach, which is why this one logs at the default level. + * Shown here once — the other two `main.ts` files stay a single line, because + * the kernel's own stderr sink is a fine default and this is the upgrade, not + * the requirement. + * * Typechecked by the gate, not executed by it. The example packages are * source-only — no build step, `main` pointing straight at `src/` — so there is * no compiled entry for `node` to run, and every spec drives `start` directly. */ -await runMain(OrderApi, { unit: RequestModule }); +await runMain(OrderApi, { + unit: RequestModule, + onEvent: kernelEvents(createLogger(jsonSink())), +}); diff --git a/examples/order-api/src/module.ts b/examples/order-api/src/module.ts index eb07fca..9aa6a73 100644 --- a/examples/order-api/src/module.ts +++ b/examples/order-api/src/module.ts @@ -1,6 +1,7 @@ -import { ApplicationModule, Logger } from "@btravstack/example-order-application"; +import { ApplicationModule } from "@btravstack/example-order-application"; import { PersistenceModule } from "@btravstack/example-order-infrastructure"; import { HttpModule } from "@btravstack/http"; +import { Logger, observability } from "@btravstack/observability"; import { orderRouter } from "./router.js"; @@ -8,8 +9,11 @@ import { orderRouter } from "./router.js"; * The composition root, and the only file in the example that knows the three * halves exist. `ApplicationModule` leaves `OrderRepository` unmet; * `PersistenceModule` provides it; `orderRouter` provides the oRPC router as a - * service that declares the two use cases its procedures call; and - * `http()` is the whole transport — the runtime on `HttpRuntime`, bound from + * service that declares the two use cases its procedures call; + * `observability()` provides the `Logger` the interactors and the request + * scope write to, bound from `LOG_LEVEL` and writing one JSON object per line + * on stdout; and `http()` is the whole transport — the runtime on + * `HttpRuntime`, bound from * `PORT` and `HOST` in the environment, and the router mounted under `/rpc`, * needing the router the root provides. Importing them is what closes di's * arity gate (a composition without the router provider does not compile — @@ -27,6 +31,6 @@ import { orderRouter } from "./router.js"; */ export const OrderApi = HttpModule("OrderApi")({ router: orderRouter, - imports: [ApplicationModule, PersistenceModule], + imports: [ApplicationModule, PersistenceModule, observability()], exports: [Logger], }); diff --git a/examples/order-api/src/needs-gate.test-d.ts b/examples/order-api/src/needs-gate.test-d.ts index e143a34..2add608 100644 --- a/examples/order-api/src/needs-gate.test-d.ts +++ b/examples/order-api/src/needs-gate.test-d.ts @@ -10,9 +10,10 @@ import { start } from "@btravstack/core"; * this package's `test:types` script, never executed. */ import { Module } from "@btravstack/di"; -import { ApplicationModule, Logger } from "@btravstack/example-order-application"; +import { ApplicationModule } from "@btravstack/example-order-application"; import { PersistenceModule } from "@btravstack/example-order-infrastructure"; import { HttpRuntime, http } from "@btravstack/http"; +import { Logger, observability } from "@btravstack/observability"; import { OrderApi } from "./module.js"; import { RequestModule } from "./request-scope.js"; @@ -27,7 +28,7 @@ const _wired = start(OrderApi, options); // The same graph without `http(...)`: nothing declared over `RuntimePort` is // exported, so there is no runtime for `start` to resolve. const RuntimelessApi = Module("RuntimelessApi")({ - imports: [ApplicationModule, PersistenceModule], + imports: [ApplicationModule, PersistenceModule, observability()], provides: [orderRouter], exports: [Logger], }); @@ -43,7 +44,7 @@ const _missingRuntime = start(RuntimelessApi, options); // as an unmet need — di's gate, not the kernel's, and it rejects the module // at `start` rather than at arity. const RouterlessApi = Module("RouterlessApi")({ - imports: [ApplicationModule, PersistenceModule, http()], + imports: [ApplicationModule, PersistenceModule, observability(), http()], exports: [HttpRuntime, Logger], }); @@ -60,7 +61,7 @@ const _withUnit = start(OrderApi, { ...options, unit: RequestModule }); // has its runtime and router but does not export `Logger`, so only the unit // half of the gate can be what rejects the call. const UnloggedApi = Module("UnloggedApi")({ - imports: [ApplicationModule, PersistenceModule, http()], + imports: [ApplicationModule, PersistenceModule, observability(), http()], provides: [orderRouter], exports: [HttpRuntime], }); diff --git a/examples/order-api/src/request-scope.ts b/examples/order-api/src/request-scope.ts index 30df531..2203e60 100644 --- a/examples/order-api/src/request-scope.ts +++ b/examples/order-api/src/request-scope.ts @@ -1,5 +1,5 @@ import { Module, Port, Provider } from "@btravstack/di"; -import { Logger } from "@btravstack/example-order-application"; +import { Logger } from "@btravstack/observability"; /** * A service that exists for the length of one request and is torn down with it. @@ -24,7 +24,9 @@ export const RequestModule = Module("Request")({ Provider(RequestSpan)([Logger], { sync: (logger) => { const startedAt = Date.now(); - return { finish: () => logger.info(`request finished in ${Date.now() - startedAt}ms`) }; + return { + finish: () => logger.info("request finished", { durationMs: Date.now() - startedAt }), + }; }, onStop: (span) => span.finish(), }), diff --git a/examples/order-api/src/test-fixtures.ts b/examples/order-api/src/test-fixtures.ts index 0cb5ac4..d946ca2 100644 --- a/examples/order-api/src/test-fixtures.ts +++ b/examples/order-api/src/test-fixtures.ts @@ -3,10 +3,12 @@ import assert from "node:assert/strict"; import type { Env } from "@btravstack/config"; import type { RunningApp, StartOptions } from "@btravstack/core"; import { Module, Provider, type Scope, type ServiceOf } from "@btravstack/di"; -import { ApplicationModule, Logger, OrderRepository } from "@btravstack/example-order-application"; +import { ApplicationModule, OrderRepository } from "@btravstack/example-order-application"; import { placeOrder, type Order } from "@btravstack/example-order-domain"; +import { PersistenceModule } from "@btravstack/example-order-infrastructure"; import { HttpModule, type HttpInfo, type HttpRuntime } from "@btravstack/http"; -import { bootFixture, tapped, type Boot } from "@btravstack/testing"; +import { Logger, observability, type Line, type Sink } from "@btravstack/observability"; +import { bootFixture, type Boot } from "@btravstack/testing"; import { fromSafePromise, OkAsync } from "unthrown"; import { test } from "vitest"; @@ -23,33 +25,55 @@ const persistenceOf = (repository: ServiceOf) => exports: [OrderRepository], }); +/** A sink that keeps what it was given, so a spec asserts on the line's fields rather than on a string. */ +const recorderOf = () => { + const lines: Line[] = []; + return { sink: (line: Line) => lines.push(line), lines: (): readonly Line[] => lines }; +}; + /** * A composition root shaped like the real one but with the repository swapped: * same `ApplicationModule`, same `HttpModule` sugar — unpinned, so `serve`'s * `env` is what binds it to an ephemeral loopback port — same exports, so - * the transport under test is unchanged. + * the transport under test is unchanged. The sink defaults to a no-op: these + * roots are booted to exercise the transport, and the real `jsonSink()` would + * put the application's lines in the test runner's own output. */ -const apiWith = (repository: ServiceOf) => +const apiWith = (repository: ServiceOf, sink: Sink = () => {}) => HttpModule("StubApi")({ router: orderRouter, - imports: [ApplicationModule, persistenceOf(repository)], + imports: [ApplicationModule, persistenceOf(repository), observability({ sink })], exports: [Logger], }); /** - * `start` hands the application context to the runtime alone, so a spec cannot - * reach `Logger` the way `Module.scoped` can. `@btravstack/testing`'s `tapped` - * hands back the very `Logger` service instance the use cases and the request - * scope write to, once the graph is built. + * The real root's composition with a recording sink in place of stdout. + * + * `observability({ sink })` IS the seam a spec reads the running graph's lines + * through, which is why the `tapped(OrderApi, [Logger])` this replaces is + * gone: the old placeholder port could only be read back because it kept its + * own array, and reaching into the graph for that instance was the price. A + * sink is a value the composition takes, so what comes back is the `Line` + * itself — `unit.traceId` as a field, not a prefix parsed out of a string. + * A parallel root rather than `OrderApi` itself for the same reason + * `apiWith` is one: nothing can be layered over a graph that already provides + * `Logger`. */ -const tappedApi = () => { - const tap = tapped(OrderApi, [Logger]); +const recordingApi = () => { + const recorder = recorderOf(); return { - api: tap.module, - traces: (): readonly string[] => { - const [logger] = tap.services(); - return logger.lines().map((line) => line.slice(0, line.indexOf("]") + 1)); - }, + api: HttpModule("RecordingApi")({ + router: orderRouter, + // `level` pinned rather than bound: `boot`'s `LOG_LEVEL` silences the + // real root, and this root exists to be read. + imports: [ + ApplicationModule, + PersistenceModule, + observability({ sink: recorder.sink, level: "trace" }), + ], + exports: [Logger], + }), + lines: recorder.lines, }; }; @@ -133,7 +157,8 @@ export type ApiFixtures = { readonly api: typeof OrderApi; readonly unmodelled: ReturnType; readonly gate: ReturnType; - readonly tapped: ReturnType; + /** The real root's composition, plus everything its logger wrote. */ + readonly recording: ReturnType; }; /** @@ -145,7 +170,10 @@ const originOf = async (app: RunningApp): Promise => `http://127.0.0.1:${await portOf(app)}`; export const it = test.extend({ - boot: bootFixture({ env: { PORT: "0", HOST: "127.0.0.1" } }), + // `LOG_LEVEL: "fatal"` is what keeps the real `OrderApi` — whose sink is the + // production `jsonSink()` on stdout — from writing its lines into the + // runner's own output. The roots a spec reads back pin their level instead. + boot: bootFixture({ env: { PORT: "0", HOST: "127.0.0.1", LOG_LEVEL: "fatal" } }), serve: async ({ boot }, use) => { await use((module, options) => boot(module, { unit: RequestModule, ...options })); @@ -186,7 +214,7 @@ export const it = test.extend({ }, // oxlint-disable-next-line no-empty-pattern -- see above - tapped: async ({}, use) => { - await use(tappedApi()); + recording: async ({}, use) => { + await use(recordingApi()); }, }); diff --git a/examples/order-application/README.md b/examples/order-application/README.md index 0babd34..5aac431 100644 --- a/examples/order-application/README.md +++ b/examples/order-application/README.md @@ -5,9 +5,8 @@ rules into operations — "place an order", "find an order" — and declares, as `@btravstack/di` ports, what it needs the outside world to supply. ``` -src/ports.ts OrderRepository, Logger, PlaceOrder, FindOrder +src/ports.ts OrderRepository, Outbox, StockService, ShippingService, PlaceOrder, FindOrder src/use-cases.ts the interactors, and their providers -src/logger.ts the Logger adapter — the one kernel touchpoint src/module.ts ApplicationModule src/test-fixtures.ts the stub repository and TestModule, as Vitest fixtures ``` @@ -30,13 +29,15 @@ these terms, and no database code can widen what the use cases have to handle. ```ts export const ApplicationModule = Module("Application")({ - provides: [loggerProvider, placeOrderProvider, findOrderProvider], - exports: [PlaceOrder, FindOrder, Logger], + provides: [placeOrderProvider, findOrderProvider], + exports: [PlaceOrder, FindOrder], }); ``` Both interactors depend on `OrderRepository` and nothing here provides it, so di -propagates it as an unmet _need_. `Module.scoped(ApplicationModule, …)` is +propagates it as an unmet _need_. `Logger` is the second one, for the same +reason and from the other direction: it is `@btravstack/observability`'s port, +not this layer's, so there is nothing here to provide and nothing to re-export. `Module.scoped(ApplicationModule, …)` is therefore a compile error — di's gate turns the module's remaining needs into a required argument naming them (`src/needs-gate.test-d.ts` pins both directions). The hole is not documentation; it is the type. An infrastructure module fills @@ -49,33 +50,37 @@ provides a stub repository from a module declared alongside the spec, and inject it as a Vitest fixture: ```ts -const TestModule = Module("Test")({ - imports: [ApplicationModule], - provides: [stubRepository], - exports: [PlaceOrder, FindOrder, Logger], -}); +const testModuleWith = (sink: Sink) => + Module("Test")({ + imports: [ApplicationModule, observability({ sink, level: "trace" })], + provides: [stubRepository, Provider(Env)({ value: {} })], + exports: [PlaceOrder, FindOrder], + }); ``` Five specs cover placement, persistence, the duplicate path, the domain rule and -the log line — with no Prisma, no HTTP and no kernel booted. - -## The single kernel touchpoint +the log line — with no Prisma, no HTTP and no kernel booted. `observability()` +binds its level from the `Env` port `start` normally provides, so a kernel-free +spec provides an empty one itself; the `sink` is the seam a spec reads lines +back through. -`src/logger.ts` imports exactly one thing from `@btravstack/core`: +## Logging is attributes, not sentences ```ts -import { currentUnit } from "@btravstack/core"; +this.#logger.info("placing an order", { orderId: id, quantity }); ``` -One `Logger` is constructed per scope, but the kernel opens a _unit_ per request -or per job, each with its own trace id. Reading `currentUnit()` fresh inside -`info` — rather than capturing it at construction — is what makes each line -attributable to the unit that wrote it. Outside a unit (this package's specs, -for instance) there is none, and the line reads `[-]`. - -Nothing else here knows the kernel exists: the use cases, the ports and the -module are all plain di, and the layer runs unchanged under a test runner, an -HTTP server or a worker. +The message is a constant and the ids are fields, which is what makes a line +groupable in the system that receives it — and what lets the spec assert +`attributes: { orderId: "o-1", quantity: 2 }` rather than match a substring. +Correlation is not this layer's job either: `@btravstack/observability`'s logger +reads `currentUnit()` on every call, so each line carries the trace id of +whatever unit the runtime opened around it. In these specs there is no unit, so +`line.unit` is `undefined` — which the spec asserts. + +Nothing here knows the kernel exists: the use cases, the ports and the module +are all plain di, and the layer runs unchanged under a test runner, an HTTP +server or a worker. ## Running it diff --git a/examples/order-application/package.json b/examples/order-application/package.json index b4631e8..7e0ceff 100644 --- a/examples/order-application/package.json +++ b/examples/order-application/package.json @@ -15,12 +15,13 @@ "typecheck": "tsc --noEmit && tsc --noEmit -p tsconfig.test-d.json" }, "dependencies": { - "@btravstack/core": "workspace:*", "@btravstack/di": "workspace:*", "@btravstack/example-order-domain": "workspace:*", + "@btravstack/observability": "workspace:*", "unthrown": "catalog:" }, "devDependencies": { + "@btravstack/config": "workspace:*", "@btravstack/tsconfig": "catalog:", "@types/node": "catalog:", "@unthrown/vitest": "catalog:", diff --git a/examples/order-application/src/index.ts b/examples/order-application/src/index.ts index 688652a..2006159 100644 --- a/examples/order-application/src/index.ts +++ b/examples/order-application/src/index.ts @@ -1,7 +1,6 @@ export { ApplicationModule } from "./module.js"; export { FindOrder, - Logger, OrderRepository, Outbox, PlaceOrder, diff --git a/examples/order-application/src/logger.ts b/examples/order-application/src/logger.ts deleted file mode 100644 index 7662091..0000000 --- a/examples/order-application/src/logger.ts +++ /dev/null @@ -1,23 +0,0 @@ -import { currentUnit } from "@btravstack/core"; -import { Provider } from "@btravstack/di"; - -import { Logger } from "./ports.js"; - -/** - * The single kernel touchpoint in this layer. `currentUnit()` is read fresh on - * every call rather than captured at construction: one `Logger` is built per - * scope, but each unit the kernel opens has its own trace id, so reading it - * later is what makes the lines attributable. Outside a unit — this package's - * own specs, for instance — there is none, and the line reads `[-]`. - */ -export const loggerProvider = Provider(Logger)({ - sync: () => { - const lines: string[] = []; - return { - info: (message: string) => { - lines.push(`[${currentUnit()?.traceId ?? "-"}] ${message}`); - }, - lines: () => lines, - }; - }, -}); diff --git a/examples/order-application/src/module.ts b/examples/order-application/src/module.ts index 1637372..4295b15 100644 --- a/examples/order-application/src/module.ts +++ b/examples/order-application/src/module.ts @@ -1,17 +1,23 @@ import { Module } from "@btravstack/di"; -import { loggerProvider } from "./logger.js"; -import { FindOrder, Logger, PlaceOrder } from "./ports.js"; +import { FindOrder, PlaceOrder } from "./ports.js"; import { findOrderProvider, placeOrderProvider } from "./use-cases.js"; /** - * `OrderRepository` is deliberately absent from `provides`: both interactors - * depend on it and nothing here satisfies it, so di propagates it as an unmet - * need. `Module.scoped(ApplicationModule, …)` therefore does not compile — an - * importing module must provide a repository first. That arity error is the - * layering, enforced by the compiler rather than by convention. + * `OrderRepository` and `Logger` are deliberately absent from `provides`: the + * interactors depend on them and nothing here satisfies them, so di propagates + * both as unmet needs. `Module.scoped(ApplicationModule, …)` therefore does not + * compile — an importing module must provide a repository and a logger first. + * That arity error is the layering, enforced by the compiler rather than by + * convention. + * + * The logger is `@btravstack/observability`'s port, not one this layer + * declares: a composition root imports `observability()` and the lines this + * layer writes come out correlated with whatever unit the runtime opened. + * There is nothing to provide here and nothing to re-export — the port belongs + * to the framework, exactly like `OrderRepository` belongs to this layer. */ export const ApplicationModule = Module("Application")({ - provides: [loggerProvider, placeOrderProvider, findOrderProvider], - exports: [PlaceOrder, FindOrder, Logger], + provides: [placeOrderProvider, findOrderProvider], + exports: [PlaceOrder, FindOrder], }); diff --git a/examples/order-application/src/needs-gate.test-d.ts b/examples/order-application/src/needs-gate.test-d.ts index 4d54c4c..86c581d 100644 --- a/examples/order-application/src/needs-gate.test-d.ts +++ b/examples/order-application/src/needs-gate.test-d.ts @@ -1,14 +1,15 @@ /** * The compile-time half of the layering: `ApplicationModule` declares - * `OrderRepository` as an unmet need, so di's phantom rest-tuple gate makes - * scoping it a call-site arity error until an outer module provides one. - * Type-checked by this package's `test:types` script, never executed. + * `OrderRepository` and `Logger` as unmet needs, so di's phantom rest-tuple + * gate makes scoping it a call-site arity error until an outer module provides + * them. Type-checked by this package's `test:types` script, never executed. */ import { Module, Provider } from "@btravstack/di"; import { DuplicateOrder, OrderNotFound, type Order } from "@btravstack/example-order-domain"; +import { Logger, createLogger } from "@btravstack/observability"; import { ErrAsync } from "unthrown"; -import { ApplicationModule, FindOrder, Logger, OrderRepository, PlaceOrder } from "./index.js"; +import { ApplicationModule, FindOrder, OrderRepository, PlaceOrder } from "./index.js"; // Negative: nothing provides `OrderRepository`, so the gate becomes a required // two-element tuple and the call is an arity error naming the unmet need. @@ -25,10 +26,14 @@ const Wired = Module("Wired")({ remove: (id: string) => ErrAsync(new OrderNotFound({ id })), }, }), + // The logger without the starter: `observability()` is the default, not + // the only way — an application that wants its own provides `Logger` + // itself, and nothing else in the graph can tell. + Provider(Logger)({ value: createLogger(() => {}) }), ], - exports: [PlaceOrder, FindOrder, Logger], + exports: [PlaceOrder, FindOrder], }); -// Positive: with a repository in scope the need is discharged, and this is an -// ordinary two-argument call. +// Positive: with a repository and a logger in scope both needs are discharged, +// and this is an ordinary two-argument call. const _wired = Module.scoped(Wired, (ctx) => ctx.get(FindOrder).execute("o-1")); diff --git a/examples/order-application/src/place-order.spec.ts b/examples/order-application/src/place-order.spec.ts index 021135b..c1e1dfe 100644 --- a/examples/order-application/src/place-order.spec.ts +++ b/examples/order-application/src/place-order.spec.ts @@ -1,7 +1,7 @@ import { Module } from "@btravstack/di"; import { describe, expect } from "vitest"; -import { FindOrder, Logger, PlaceOrder } from "./index.js"; +import { FindOrder, PlaceOrder } from "./index.js"; import { it } from "./test-fixtures.js"; describe("PlaceOrder", () => { @@ -40,18 +40,26 @@ describe("PlaceOrder", () => { expect(result).toBeErrTagged("InvalidQuantity", { id: "o-1", quantity: 0 }); }); - it("writes a log line naming the order", async ({ testModule }) => { + it("writes a log line carrying the order as fields", async ({ testModule, recorder }) => { // GIVEN a successful placement - // WHEN the logger is read back + // WHEN the sink the graph's logger writes to is read back const result = await Module.scoped(testModule, (ctx) => ctx .get(PlaceOrder) .execute("o-1", 2) - .map(() => ctx.get(Logger).lines()), + .map(() => recorder.lines()), ); - // THEN the line names the order, with no unit to take a trace id from - expect(result).toBeOkWith(["[-] placing order o-1 (quantity 2)"]); + // THEN the ids are queryable attributes rather than words in a sentence, + // and there is no unit here to take a trace id from + expect(result).toBeOkWith([ + expect.objectContaining({ + level: "info", + message: "placing an order", + attributes: { orderId: "o-1", quantity: 2 }, + unit: undefined, + }), + ]); }); }); diff --git a/examples/order-application/src/ports.ts b/examples/order-application/src/ports.ts index 1f61a66..55df7e3 100644 --- a/examples/order-application/src/ports.ts +++ b/examples/order-application/src/ports.ts @@ -75,11 +75,6 @@ export class ShippingService extends Port("ShippingService")<{ readonly arrange: (orderId: string) => AsyncResult; }> {} -export class Logger extends Port("Logger")<{ - readonly info: (message: string) => void; - readonly lines: () => readonly string[]; -}> {} - export class PlaceOrder extends Port("PlaceOrder")<{ readonly execute: ( id: string, diff --git a/examples/order-application/src/test-fixtures.ts b/examples/order-application/src/test-fixtures.ts index 4a49329..939da09 100644 --- a/examples/order-application/src/test-fixtures.ts +++ b/examples/order-application/src/test-fixtures.ts @@ -1,16 +1,19 @@ +import { Env } from "@btravstack/config"; import { Module, Provider } from "@btravstack/di"; import { DuplicateOrder, OrderNotFound, type Order } from "@btravstack/example-order-domain"; +import { observability, type Line, type Sink } from "@btravstack/observability"; import { ErrAsync, OkAsync } from "unthrown"; import { test } from "vitest"; -import { ApplicationModule, FindOrder, Logger, OrderRepository, PlaceOrder } from "./index.js"; +import { ApplicationModule, FindOrder, OrderRepository, PlaceOrder } from "./index.js"; /** * The whole point of the layer split: the use cases run against a stub * repository provided by a module that exists only in this file. No database, * no HTTP, no kernel — the application layer is exercised with the * infrastructure hole still open, and `TestModule` compiles only because - * providing `OrderRepository` is what closes `ApplicationModule`'s one need. + * providing `OrderRepository` (and importing a logger) is what closes + * `ApplicationModule`'s two needs. */ const stubRepository = Provider(OrderRepository)({ sync: () => { @@ -30,20 +33,40 @@ const stubRepository = Provider(OrderRepository)({ }, }); -const TestModule = Module("Test")({ - imports: [ApplicationModule], - provides: [stubRepository], - exports: [PlaceOrder, FindOrder, Logger], -}); +/** + * `observability()` binds its level from the `Env` port, which `start` + * provides to every graph it boots — and there is no `start` here, so this + * module provides an empty one itself. That is the only ceremony the real + * logger costs a kernel-free spec, and it buys the very implementation the + * deployments run. + */ +const testModuleWith = (sink: Sink) => + Module("Test")({ + imports: [ApplicationModule, observability({ sink, level: "trace" })], + provides: [stubRepository, Provider(Env)({ value: {} })], + exports: [PlaceOrder, FindOrder], + }); + +/** A sink that keeps what it was given, so a spec asserts on the line's fields rather than on a string. */ +const recorderOf = () => { + const lines: Line[] = []; + return { sink: (line: Line) => lines.push(line), lines: (): readonly Line[] => lines }; +}; export type ApplicationFixtures = { - /** `ApplicationModule` with its one unmet need closed by an in-memory stub. */ - readonly testModule: typeof TestModule; + /** Everything the graph's logger wrote during this test. */ + readonly recorder: ReturnType; + /** `ApplicationModule` with both its needs closed: an in-memory stub, and the observability starter. */ + readonly testModule: ReturnType; }; export const it = test.extend({ // oxlint-disable-next-line no-empty-pattern -- Vitest fixtures require a destructuring pattern; this one depends on no other fixture - testModule: async ({}, use) => { - await use(TestModule); + recorder: async ({}, use) => { + await use(recorderOf()); + }, + + testModule: async ({ recorder }, use) => { + await use(testModuleWith(recorder.sink)); }, }); diff --git a/examples/order-application/src/use-cases.ts b/examples/order-application/src/use-cases.ts index f1bd249..182ba81 100644 --- a/examples/order-application/src/use-cases.ts +++ b/examples/order-application/src/use-cases.ts @@ -6,9 +6,10 @@ import { type Order, type OrderNotFound, } from "@btravstack/example-order-domain"; +import { Logger } from "@btravstack/observability"; import type { AsyncResult } from "unthrown"; -import { FindOrder, Logger, OrderRepository, PlaceOrder } from "./ports.js"; +import { FindOrder, OrderRepository, PlaceOrder } from "./ports.js"; class PlaceOrderInteractor { readonly #repository: ServiceOf; @@ -20,7 +21,7 @@ class PlaceOrderInteractor { } execute(id: string, quantity: number): AsyncResult { - this.#logger.info(`placing order ${id} (quantity ${quantity})`); + this.#logger.info("placing an order", { orderId: id, quantity }); return placeOrder(id, quantity) .toAsync() .flatMap((order) => this.#repository.save(order)); diff --git a/examples/order-infrastructure/README.md b/examples/order-infrastructure/README.md index 4e59d62..451989e 100644 --- a/examples/order-infrastructure/README.md +++ b/examples/order-infrastructure/README.md @@ -127,11 +127,16 @@ root imports both halves and the graph is closed: ```ts const AppModule = Module("App")({ - imports: [ApplicationModule, PersistenceModule], - exports: [PlaceOrder, FindOrder, Logger], + imports: [ApplicationModule, PersistenceModule, observability()], + exports: [PlaceOrder, FindOrder], }); ``` +`observability()` closes `ApplicationModule`'s other need, the `Logger` the +interactors write to — `PersistenceModule` fills the repository hole, the +observability starter fills the logging one, and neither layer knows the other +exists. + The database provider takes di's `acquire`/`release` arm, so the module carries a `Scope` need that only `Module.scoped` discharges — forgetting the scope is a compile error, and closing it disconnects a real client. The spec proves that by diff --git a/examples/order-temporal-worker/README.md b/examples/order-temporal-worker/README.md index 26bbe81..880c970 100644 --- a/examples/order-temporal-worker/README.md +++ b/examples/order-temporal-worker/README.md @@ -109,6 +109,7 @@ kernel for `PROBE_PORT` — never by `main.ts`. A blank or malformed value is a | `TEMPORAL_ADDRESS` | `127.0.0.1:7233` | the Temporal service | | `TEMPORAL_NAMESPACE` | `default` | must not be blank | | `PROBE_PORT` | `9000` | `/livez` / `/readyz` | +| `LOG_LEVEL` | `info` | the `Logger`'s floor | The specs boot the same `TemporalModule` sugar with `env: { TEMPORAL_ADDRESS }` pointing at the time-skipping server, so every test opens and closes a @@ -131,8 +132,12 @@ pnpm --filter @btravstack/example-order-temporal-worker typecheck # the needs The fixtures are [`@btravstack/testing`](../../packages/testing)'s: `serve` boots the worker through the `boot` fixture, so it is stopped when the test ends, and `fulfilling` / `outOfStock` / `noShipping` are `tapped` compositions -whose `services()` hand back the very `OrderRepository` and `Logger` the -running deployment holds — how the compensation specs read the state back. +whose `services()` hand back the very `OrderRepository` the running deployment +holds — how the compensation specs read the state back. Each also composes +`observability({ sink })`, so `lines()` is the saga's own log: the step +assertions read `{ message, orderId, quantity }` as fields, and the activity +trace id every line carries is the runtime's business rather than something to +strip out of a string. ## What this deployment deliberately is not diff --git a/examples/order-temporal-worker/package.json b/examples/order-temporal-worker/package.json index 4c5b7ca..4100dd5 100644 --- a/examples/order-temporal-worker/package.json +++ b/examples/order-temporal-worker/package.json @@ -22,6 +22,7 @@ "@btravstack/example-order-domain": "workspace:*", "@btravstack/example-order-infrastructure": "workspace:*", "@btravstack/example-order-temporal-contract": "workspace:*", + "@btravstack/observability": "workspace:*", "@btravstack/temporal": "workspace:*", "@temporal-contract/client": "catalog:", "@temporal-contract/worker": "catalog:", diff --git a/examples/order-temporal-worker/src/fulfillment.ts b/examples/order-temporal-worker/src/fulfillment.ts index 88768ff..1d712cf 100644 --- a/examples/order-temporal-worker/src/fulfillment.ts +++ b/examples/order-temporal-worker/src/fulfillment.ts @@ -1,6 +1,7 @@ import { currentUnit } from "@btravstack/core"; import { Module, Provider } from "@btravstack/di"; -import { Logger, ShippingService, StockService } from "@btravstack/example-order-application"; +import { ShippingService, StockService } from "@btravstack/example-order-application"; +import { Logger } from "@btravstack/observability"; import { OkAsync, fromSafePromise } from "unthrown"; /** @@ -32,11 +33,11 @@ export const FulfillmentModule = Module("Fulfillment")({ Provider(StockService)([Logger], { sync: (logger) => ({ reserve: (orderId, quantity) => { - logger.info(`reserved ${quantity} items for order ${orderId}`); + logger.info("reserved stock", { orderId, quantity }); return OkAsync(); }, release: (orderId) => { - logger.info(`released the reservation for order ${orderId}`); + logger.info("released the reservation", { orderId }); return OkAsync(); }, }), @@ -52,7 +53,7 @@ export const FulfillmentModule = Module("Fulfillment")({ ), ), ) - : (logger.info(`arranged shipping for order ${orderId}`), OkAsync()), + : (logger.info("arranged shipping", { orderId }), OkAsync()), }), }), ], diff --git a/examples/order-temporal-worker/src/module.ts b/examples/order-temporal-worker/src/module.ts index ae103f4..b1ebc27 100644 --- a/examples/order-temporal-worker/src/module.ts +++ b/examples/order-temporal-worker/src/module.ts @@ -1,6 +1,7 @@ import { ApplicationModule } from "@btravstack/example-order-application"; import { PersistenceModule } from "@btravstack/example-order-infrastructure"; import { orderContract } from "@btravstack/example-order-temporal-contract"; +import { observability } from "@btravstack/observability"; import { TemporalModule } from "@btravstack/temporal"; import { workflowsPathFromURL } from "@temporal-contract/worker/worker"; @@ -10,7 +11,10 @@ import { FulfillmentModule } from "./fulfillment.js"; /** * The composition root of the orchestration deployment. `ApplicationModule` * and `PersistenceModule` are booted here unchanged — the same pair every - * other deployment composes — plus `FulfillmentModule`, the two external + * other deployment composes — plus `observability()`, the `Logger` the use + * case and the fulfillment stand-ins write to (`LOG_LEVEL`, JSON on stdout, + * every line carrying the activity attempt's own trace id), and + * `FulfillmentModule`, the two external * services only this deployment orchestrates; `orderActivities`, the saga's * activities as a service on the starter's own activities port; and `TemporalModule`, the * sugar that imports the starter (`temporal()`, the runtime itself on @@ -37,5 +41,5 @@ export const OrderTemporalWorker = TemporalModule("OrderTemporalWorker")({ contract: orderContract, activities: orderActivities, workflows: { workflowsPath: workflowsPathFromURL(import.meta.url, "./workflows.js") }, - imports: [ApplicationModule, PersistenceModule, FulfillmentModule], + imports: [ApplicationModule, PersistenceModule, FulfillmentModule, observability()], }); diff --git a/examples/order-temporal-worker/src/temporal-runtime.spec.ts b/examples/order-temporal-worker/src/temporal-runtime.spec.ts index 7fdb628..8a66ac0 100644 --- a/examples/order-temporal-worker/src/temporal-runtime.spec.ts +++ b/examples/order-temporal-worker/src/temporal-runtime.spec.ts @@ -22,18 +22,19 @@ describe("the fulfillment saga", () => { }), ).toBeOkWith({ id: "o-1", quantity: 2 }); - // AND the journey ran in the declared order, each step a log line — the - // `[workflowId]` prefix is the activity unit's trace, stripped here - // because the order of the steps is the assertion, not the tracing - const { repository, logger } = fulfilling.services(); - expect(logger.lines().map((line) => line.slice(line.indexOf("]") + 2))).toEqual([ - "placing order o-1 (quantity 2)", - "reserved 2 items for order o-1", - "arranged shipping for order o-1", + // AND the journey ran in the declared order, each step a log line whose + // order id is a field rather than a word — the trace id every line also + // carries is the runtime's business, not this assertion's + expect( + fulfilling.lines().map((line) => ({ message: line.message, ...line.attributes })), + ).toEqual([ + { message: "placing an order", orderId: "o-1", quantity: 2 }, + { message: "reserved stock", orderId: "o-1", quantity: 2 }, + { message: "arranged shipping", orderId: "o-1" }, ]); // AND the placement is durably there - await expect(repository.find("o-1")).toBeOkWith( + await expect(fulfilling.services().repository.find("o-1")).toBeOkWith( expect.objectContaining({ id: "o-1", quantity: 2 }), ); }); diff --git a/examples/order-temporal-worker/src/test-fixtures.ts b/examples/order-temporal-worker/src/test-fixtures.ts index 6919bf3..f0a1b5a 100644 --- a/examples/order-temporal-worker/src/test-fixtures.ts +++ b/examples/order-temporal-worker/src/test-fixtures.ts @@ -1,12 +1,11 @@ import { mkdirSync } from "node:fs"; import { fileURLToPath } from "node:url"; -import type { ConfigInvalid } from "@btravstack/config"; +import type { ConfigInvalid, Env } from "@btravstack/config"; import type { RunningApp } from "@btravstack/core"; import { Module, Provider, type Scope, type ServiceOf } from "@btravstack/di"; import { ApplicationModule, - Logger, OrderRepository, PlaceOrder, ShippingService, @@ -15,6 +14,7 @@ import { import { OutOfStock, ShippingUnavailable } from "@btravstack/example-order-domain"; import { PersistenceModule } from "@btravstack/example-order-infrastructure"; import { orderContract, type OrderContract } from "@btravstack/example-order-temporal-contract"; +import { observability, type Line, type Sink } from "@btravstack/observability"; import { TemporalModule, type TemporalInfo, type TemporalUnreachable } from "@btravstack/temporal"; import { bootFixture, tapped, type Boot } from "@btravstack/testing"; import { TypedClient, type ContractClient } from "@temporal-contract/client"; @@ -71,40 +71,43 @@ type Deployment = { * own exports. */ type Serve = ( - module: Module, + module: Module, ) => Promise>; /** * The application half of a root shaped like the real one, with this test's * fulfillment module swapped in: same `ApplicationModule`, same - * `PersistenceModule`, so the orchestration under test is unchanged and only - * the external services' answers differ. It exports what `orderActivities` - * closes over, plus `Logger` for the tap below; the sugar joins in `serve`, + * `PersistenceModule`, same `observability()` — so the orchestration under + * test is unchanged and only the external services' answers differ, and the + * lines the saga writes land in `sink` instead of the runner's stdout. It + * exports what `orderActivities` closes over; the sugar joins in `serve`, * which is where the per-test queue and the memoised bundle are known. */ -const rootWith = (fulfillment: typeof FulfillmentModule) => +const rootWith = (fulfillment: typeof FulfillmentModule, sink: Sink) => Module("StubTemporal")({ - imports: [ApplicationModule, PersistenceModule, fulfillment], - exports: [PlaceOrder, OrderRepository, StockService, ShippingService, Logger], + imports: [ApplicationModule, PersistenceModule, fulfillment, observability({ sink })], + exports: [PlaceOrder, OrderRepository, StockService, ShippingService], }); /** * `start` hands the application context to the runtime alone, so a spec cannot * reach the services the way `Module.scoped` can. `@btravstack/testing`'s - * `tapped` captures the very instances the running app uses — the repository - * the compensation assertions read through, and the logger the stub services - * write to. + * `tapped` captures the very repository instance the running app uses, which + * the compensation assertions read through; the log lines need no tap at all — + * `observability({ sink })` hands them over as values. */ const deployment = (fulfillment: typeof FulfillmentModule) => { - const tap = tapped(rootWith(fulfillment), [OrderRepository, Logger]); + const lines: Line[] = []; + const tap = tapped( + rootWith(fulfillment, (line) => lines.push(line)), + [OrderRepository], + ); return { module: tap.module, - services: (): { - readonly repository: ServiceOf; - readonly logger: ServiceOf; - } => { - const [repository, logger] = tap.services(); - return { repository, logger }; + lines: (): readonly Line[] => lines, + services: (): { readonly repository: ServiceOf } => { + const [repository] = tap.services(); + return { repository }; }, }; }; diff --git a/packages/core/CLAUDE.md b/packages/core/CLAUDE.md index 94732ae..67b9c28 100644 --- a/packages/core/CLAUDE.md +++ b/packages/core/CLAUDE.md @@ -108,7 +108,13 @@ Beyond the nine: backwards and reports nothing"_ and _"treats re-entering the same phase as a no-op"_. - **A throwing event sink cannot take the process down mid-shutdown.** - `events.spec.ts` → _"swallows a throwing sink"_. + `events.spec.ts` → _"swallows a throwing sink"_. `safeSink` is what + guarantees it, and it stays load-bearing even though the sink most + applications now pass — `@btravstack/observability`'s `kernelEvents(logger)` + — cannot throw on its own account, since `createLogger` swallows a broken + destination for the same reason one layer down. The kernel takes no logger + dependency and must not grow one: `onEvent` is the seam, and that package + is a consumer of it like any other. - **A construction failure keeps the module's own error type.** `start.spec.ts` → _"reports a construction failure without wrapping the module's own error"_. - **`probePort()` can never hang.** The deferred is settled on every route out diff --git a/packages/observability/CLAUDE.md b/packages/observability/CLAUDE.md new file mode 100644 index 0000000..0304562 --- /dev/null +++ b/packages/observability/CLAUDE.md @@ -0,0 +1,165 @@ +# packages/observability + +The observability package's public surface. The root `CLAUDE.md` is the +authoritative spec for the kernel and the conventions; this file holds what +only matters when you are working under `packages/observability/`. Keep it in +sync with the code in the same commit, and with `README.md` — the package +ships no `docs-examples.test-d.ts`, so nothing else compiles these claims. + +## What this is, and what it is not yet + +Logging, today. The package is named for the whole of observability because +logs, traces and metrics share a correlation id, a resource, a config slice +and a flush-on-shutdown lifecycle — splitting them across two packages would +duplicate all four, and the second would end up depending on the first. Traces +and metrics are **not here yet**; the shape they will take is in +_Deferred, deliberately_ at the end of this file. Do not describe them as +shipped. + +## Public surface + +- **`Logger`** (`logger.ts`) — `Port("Logger")` over `LoggerService`: + `log(level, message, attributes?, cause?)`, one method per level with the + **same three arguments in the same order** — `(message, attributes?, +cause?)` — plus `with(attributes)` and `isEnabled(level)`. The uniformity + was a correction: `error(message, cause, attributes)` read better at the one + call site that always has a cause, made every other site remember which arm + it was in, and left `warn` with nowhere to put one — so a retryable failure + (a broker refusing a publish, which the next sweep takes) had to be logged + at `error` purely to keep its reason, and `kernelEvents`' `teardownError` + arm silently dropped the finaliser's error. A failure is not a property of + severity. The cost is `logger.error("boom", undefined, cause)` for a failure + with nothing else to say; a line worth writing almost always has an id to + write with it. It is the framework's port, not + the application's: the framework itself logs (see `kernelEvents`), so an + application-declared port could not serve both, and every application + declaring the same port by hand was the copy-paste the `Env` port removed for + configuration. +- **Six differences from NestJS's `Logger`**, each a defect this shape does not + have, and the reason the port looks the way it does: a port rather than a + class you `new` (no static, no `useLogger` reaching past DI); `with` returns + a value rather than `setContext` mutating the instance every caller shares; + `Attributes` is a flat record of scalars rather than `any` varargs; a failure + has its own `cause` channel; it cannot throw; and correlation is the + implementation's job, not the caller's. Keep that list in the port's TSDoc — + it is the package's whole argument. +- **`Level` / `LEVELS`** — `trace | debug | info | warn | error | fatal`, + ordered, exported as an array so `logLevel` validates against one list and a + future OTel bridge maps severities without a table of synonyms. +- **`Attributes`** — `Readonly>`. Flat and scalar deliberately: a nested object is where a field + name stops being stable across lines, and an `unknown` value is where a + logger starts stringifying whatever it is handed — which is how a log call + becomes the thing that throws. +- **`createLogger(sink, level?)`** — the implementation. Two load-bearing + details: `currentUnit()` is read **per call** (one logger per scope, a + record per unit — capturing it at construction would stamp the first unit's + trace id on every line thereafter), and every write is wrapped in a `try` that + swallows, because a logger that throws turns an observability fault into an + outage. `with` layers attributes and shares the sink, so a child costs one + object. +- **`Line` / `Sink`** — what an implementation hands a destination: + `{ level, message, attributes, cause, time, unit }`, where `unit` is + `undefined` outside a unit and `{ unitId, traceId, tenantId? }` inside one. + A `Sink` is `(line: Line) => void` and is allowed to throw — `createLogger` + is what makes that safe. +- **`jsonSink(stream?)`** (`json-sink.ts`) — the default: one JSON object per + line on `process.stdout`. The caller's attributes are spread **first** and + the line's own fields after them, which is what makes the precedence true: + a caller's `{ level: "info" }` can never rewrite an `error` line's severity, + nor its `traceId`. The unit's ids are spread at the **top level**, not + nested under `unit`: `traceId` is the field an operator searches. and `renderCause` walks `Error.cause` up to four levels because an + `Error`'s `message` and `stack` are non-enumerable and a bare + `JSON.stringify` renders the line that exists to carry a failure as `{}` — + the same rule, and the same reason, as the kernel's `stderrSink`. A payload + `JSON.stringify` refuses outright falls back to the message and its severity + rather than costing the line. +- **`observability({ sink?, level? })`** (`observability.ts`) — the starter: + a `Module` providing the logger + and the configuration it was built from. `level` **pins** the way every + starter's options pin (explicit > env > default, through `Config.pinned`). +- **`LoggerConfig`** — `{ level }`, bound through `Config.provider` from + `LOG_LEVEL` (default `info`). A value outside the six is a `ConfigInvalid` + naming the variable and the set — exit `78` under `runMain`, before a line is + written — rather than a silent fallback: a deployment that meant `debug` and + typed `verbose` should be told, not quietly under-logged for a week. +- **`logLevel({ default? })`** (`config.ts`) — that field on its own, exported + so an application composing its own schema can reuse the validation rather + than re-deriving it. +- **`kernelEvents(logger)`** — the kernel's `EventSink` over the logger, for + `StartOptions.onEvent`. The mapping is deliberate, not mechanical: + `startFailed` and `uncaught` are `error` (they carry a cause and are what an + operator is paged for), `teardownError` is `warn` (the application is already + stopping and the exit code says so), everything else is `info`. Each event's + own fields become **attributes** — `draining` keeps `inFlight`, `drained` + keeps the three report numbers — so a drain is queryable by field rather than + parsed out of a sentence. The logger is a **parameter**, not resolved from + the graph: `building` is emitted while the graph is still being built, so the + sink cannot come from the context it is watching. That is also why an + application wiring this passes `createLogger(jsonSink())` by hand in + `main.ts` — a second logger, deliberately, and the only one the framework + asks anybody to construct. +- **`pinoSink(logger)`** (`pino.ts`, the `@btravstack/observability/pino` + subpath) — a `Sink` over a pino logger, for a deployment where the default + sink's `JSON.stringify` per line shows up in a profile. `pino` is an + **optional** peer: a consumer that never imports the subpath never installs + it. The level filter stays **ours** — `createLogger` has already decided the + line is worth writing by the time a sink sees it — so pino is configured at + `trace` in the docs and the spec, one filter in the process, and it is the + one `LOG_LEVEL` validated. The cause is handed over as `err`, which pino's + own serialiser renders with the stack. + +## Specs + +`vitest run --coverage`, 100% lines/functions like every other package, 26 +tests across four files: + +- `logger.spec.ts` (8) — the surface (one line per level, at its own severity), + the level floor and `isEnabled`, the cause channel, `with` layering **and not + mutating** (the defect a mutable `setContext` has, asserted rather than + asserted about), a call's attribute winning over a child's, a throwing sink + swallowed, no `unit` outside a unit, the ambient record inside one, and the + tenant a runtime supplied. +- `json-sink.spec.ts` (5) — the line shape and the trailing newline, an + `Error`'s `message`/`stack`/`cause` chain surviving, a caller's attribute not + rewriting `level`/`message`/`traceId`, a circular payload falling back to + `[unserialisable]`, and the default stream being `process.stdout` (captured + with a spy — read `mock.calls` **before** `mockRestore`, which clears them). +- `observability.spec.ts` (8) — the level bound from the environment and + filtering the graph's own logger, `ConfigInvalid` for a level outside the + six, a pinned level beating the environment, and the five `kernelEvents` + mappings. +- `pino.spec.ts` (3) — fields pino can index, the `err` serialiser, and every + level mapping onto pino's own numeric severity (`10`…`60`), so no level of + ours silently collapses into another. + +`test-fixtures.ts` carries a `Recorder` (the sink a spec asserts on), a +`Written` stream, `loggerAt(level)`, a `unitLogging` module for +`StartOptions.unit` — the only code that genuinely runs **inside** the kernel's +ambient record, since a test body does not — and a `tenantApp` whose +hand-rolled runtime opens a unit with a `tenantId`, which no shipped runtime +sets. + +## Dependencies + +Peers: `@btravstack/core`, `@btravstack/config`, `@btravstack/di`, `unthrown`, +and `pino` as an **optional** one. The package itself has no runtime +dependencies — the default sink is `JSON.stringify` and a `write`, for the same +reason `Config` is a hand-rolled Standard Schema. + +## Deferred, deliberately + +- **Traces and metrics.** The shape: `Tracer`/`Meter` ports, the OTel + `NodeSDK` as a **resourceful** provider whose `release` flushes — the kernel + closes the scope on every exit path, so a lost span becomes a + `teardownError` and exit `2` rather than silence — a span per unit as a + `StartOptions.unit` provider (the kernel already tears that down inside the + unit's ambient record, so no kernel change is needed), an OTel appender as a + `Sink`, and W3C `traceparent` propagation feeding `UnitMeta.traceId` in the + three transport starters (`@btravstack/http` reads `x-request-id` today). +- **A constraint that will not go away**: OTel _auto_-instrumentation + (`@opentelemetry/auto-instrumentations-node/register`) must be preloaded + before the instrumented libraries are imported, so it cannot be DI-provided. + The package will ship manual instrumentation for what this stack owns and + document the `--import` preload for third-party libraries; do not try to + wire auto-instrumentation into a provider. diff --git a/packages/observability/LICENSE b/packages/observability/LICENSE new file mode 100644 index 0000000..e389328 --- /dev/null +++ b/packages/observability/LICENSE @@ -0,0 +1,21 @@ +MIT License + +Copyright (c) 2026 Benoit TRAVERS + +Permission is hereby granted, free of charge, to any person obtaining a copy +of this software and associated documentation files (the "Software"), to deal +in the Software without restriction, including without limitation the rights +to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +copies of the Software, and to permit persons to whom the Software is +furnished to do so, subject to the following conditions: + +The above copyright notice and this permission notice shall be included in all +copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE +SOFTWARE. diff --git a/packages/observability/README.md b/packages/observability/README.md new file mode 100644 index 0000000..565c868 --- /dev/null +++ b/packages/observability/README.md @@ -0,0 +1,103 @@ +# @btravstack/observability + +> Observability for [`@btravstack/core`](../core), starting with logging: a +> **strict** `Logger` port — no `any`, no printf, no mutable context, no static +> instance — a default implementation that stamps every line with the ambient +> unit's trace id, a dependency-free JSON sink, pino behind a subpath, and the +> kernel's nine lifecycle events as log lines in the same stream. + +📖 **[Documentation](https://btravstack.github.io/start/reference/observability)** · +[How-to](https://btravstack.github.io/start/how-to/log-and-correlate) · +[API Reference](https://btravstack.github.io/start/api/observability/) + +```sh +pnpm add @btravstack/observability @btravstack/core @btravstack/config @btravstack/di unthrown +``` + +Those four are peers. `pino` is an **optional** peer, needed only if you import +`@btravstack/observability/pino`. Node `>=20`. Not yet published: this +repository has not cut a release yet. + +## A worked example + +```ts +import { runMain } from "@btravstack/core"; +import { + Logger, + createLogger, + jsonSink, + kernelEvents, + observability, +} from "@btravstack/observability"; +import { Module, Provider } from "@btravstack/di"; + +// The application depends on the port, like any other service. +const placeOrder = Provider(PlaceOrder)([OrderRepository, Logger], { + sync: (orders, logger) => ({ + execute: (id, quantity) => + orders + .save({ id, quantity }) + .tap(() => logger.info("order placed", { id, quantity })), + }), +}); + +// The starter provides it. `LOG_LEVEL` is read inside the graph and validated +// once — `verbose` is a startup failure naming the variable, not a silent +// fallback to `info`. +const OrderApi = HttpModule("OrderApi")({ + router: orderRouter, + imports: [ApplicationModule, PersistenceModule, observability()], + exports: [Logger], +}); + +// The kernel's own events, in the same stream and the same shape. The logger +// here is built by hand because `building` is emitted while the graph still +// is: the sink cannot come from the context it is watching. +await runMain(OrderApi, { onEvent: kernelEvents(createLogger(jsonSink())) }); +``` + +Every line written inside a unit carries that unit's `traceId`, `unitId` and +`tenantId` — the logger reads `currentUnit()` **per call**, so one +application-scope logger is correct for every request without a single +argument threaded through the call stack. + +```json +{ + "orderId": "o-1", + "time": "2026-08-16T09:41:02.113Z", + "level": "info", + "message": "order placed", + "unitId": "u-7", + "traceId": "3f9c…" +} +``` + +## What makes the interface strict + +| Decision | Why | +| ---------------------------------------- | ------------------------------------------------------------------------------------------------------------------- | +| A **port**, never a class or a static | A test provides its own; there is no global to reach past DI with | +| `with(attributes)` returns a logger | Nothing mutates: two scopes cannot interleave each other's context | +| `Attributes` is a flat record of scalars | The shape a log backend indexes; no `any`, no printf, no stringifying whatever it is handed | +| A failure goes in `cause` | An `Error`'s `message` and `stack` are non-enumerable — `JSON.stringify` alone drops exactly the part worth keeping | +| It cannot throw | A broken sink is swallowed: an observability fault must not become an outage | +| Six levels, fixed | `LOG_LEVEL` is validated at startup, and `isEnabled` is a comparison | + +## Swapping the implementation + +`observability({ sink })` replaces the destination; providing `Logger` +yourself replaces everything. For a deployment that wants pino's throughput: + +```ts +import pino from "pino"; +import { pinoSink } from "@btravstack/observability/pino"; + +observability({ sink: pinoSink(pino()) }); +``` + +The level filter stays this package's — `LOG_LEVEL`, validated once — so there +is one filter in the process rather than two that can disagree. + +## License + +[MIT](./LICENSE) © Benoit TRAVERS diff --git a/packages/observability/package.json b/packages/observability/package.json new file mode 100644 index 0000000..2271754 --- /dev/null +++ b/packages/observability/package.json @@ -0,0 +1,93 @@ +{ + "name": "@btravstack/observability", + "version": "0.0.0", + "description": "Observability for @btravstack/core: a strict Logger port correlated with the kernel's units, a dependency-free JSON sink, and the lifecycle events as log lines", + "keywords": [ + "dependency-injection", + "logger", + "logging", + "observability", + "opentelemetry", + "structured-logging", + "typescript", + "unthrown" + ], + "homepage": "https://github.com/btravstack/start#readme", + "bugs": { + "url": "https://github.com/btravstack/start/issues" + }, + "license": "MIT", + "author": "Benoit TRAVERS ", + "repository": { + "type": "git", + "url": "https://github.com/btravstack/start.git", + "directory": "packages/observability" + }, + "files": [ + "dist" + ], + "type": "module", + "sideEffects": false, + "main": "./dist/index.cjs", + "module": "./dist/index.mjs", + "types": "./dist/index.d.cts", + "exports": { + ".": { + "import": { + "types": "./dist/index.d.mts", + "default": "./dist/index.mjs" + }, + "require": { + "types": "./dist/index.d.cts", + "default": "./dist/index.cjs" + } + }, + "./pino": { + "import": { + "types": "./dist/pino.d.mts", + "default": "./dist/pino.mjs" + }, + "require": { + "types": "./dist/pino.d.cts", + "default": "./dist/pino.cjs" + } + }, + "./package.json": "./package.json" + }, + "scripts": { + "build": "tsdown src/index.ts src/pino.ts --format cjs,esm --dts --clean", + "dev": "tsdown src/index.ts src/pino.ts --format cjs,esm --dts --watch", + "test": "vitest run --coverage", + "typecheck": "tsc --noEmit" + }, + "devDependencies": { + "@btravstack/config": "workspace:*", + "@btravstack/core": "workspace:*", + "@btravstack/di": "workspace:*", + "@btravstack/testing": "workspace:*", + "@btravstack/tsconfig": "catalog:", + "@types/node": "catalog:", + "@unthrown/vitest": "catalog:", + "@vitest/coverage-v8": "catalog:", + "pino": "catalog:", + "tsdown": "catalog:", + "typescript": "catalog:", + "unthrown": "catalog:", + "vitest": "catalog:" + }, + "peerDependencies": { + "@btravstack/config": "workspace:^", + "@btravstack/core": "workspace:^", + "@btravstack/di": "^0.1.0", + "pino": "^10", + "unthrown": "^5.0.0" + }, + "peerDependenciesMeta": { + "pino": { + "optional": true + } + }, + "engines": { + "node": ">=20" + } +} diff --git a/packages/observability/src/config.ts b/packages/observability/src/config.ts new file mode 100644 index 0000000..64a5620 --- /dev/null +++ b/packages/observability/src/config.ts @@ -0,0 +1,38 @@ +import { Config, ConfigFieldInvalid, type ConfigField } from "@btravstack/config"; +import { Err, Ok } from "unthrown"; + +import { LEVELS, type Level } from "./logger.js"; + +/** + * `LOG_LEVEL`, as a `ConfigField` of the six levels and nothing else. + * + * A value outside the set is a `ConfigInvalid` naming the variable — exit + * `78` under `runMain`, before a line is written — rather than a silent + * fallback to `info`: a deployment that meant `debug` and typed `verbose` + * should be told, not quietly under-logged for a week. Built on + * `Config.string`, so it inherits the semantics every other variable has: an + * unset variable takes the default, a set-but-blank one is an error. + */ +export const logLevel = (options: { readonly default?: Level } = {}): ConfigField => { + const text = Config.string("LOG_LEVEL", { default: options.default ?? "info" }); + return { + variable: text.variable, + parse: (raw) => + text.parse(raw).flatMap((value) => + LEVELS.includes(value as Level) + ? Ok(value as Level) + : Err( + new ConfigFieldInvalid({ + reason: `must be one of ${LEVELS.join(", ")}, got ${JSON.stringify(value)}`, + }), + ), + ), + }; +}; + +/** What `observability()` binds from the environment. */ +export type LoggerSettings = { readonly level: Level }; + +/** The schema `observability()` binds `LoggerConfig` through — one field today, and the place a second one lands. */ +export const loggerSchema = (level: Level | undefined) => + Config.object({ level: Config.pinned(level, logLevel()) }); diff --git a/packages/observability/src/index.ts b/packages/observability/src/index.ts new file mode 100644 index 0000000..49ca88f --- /dev/null +++ b/packages/observability/src/index.ts @@ -0,0 +1,7 @@ +export { logLevel } from "./config.js"; +export type { LoggerSettings } from "./config.js"; +export { jsonSink } from "./json-sink.js"; +export { LEVELS, Logger, createLogger } from "./logger.js"; +export type { Attributes, Level, Line, LoggerService, Sink } from "./logger.js"; +export { LoggerConfig, kernelEvents, observability } from "./observability.js"; +export type { ObservabilityOptions } from "./observability.js"; diff --git a/packages/observability/src/json-sink.spec.ts b/packages/observability/src/json-sink.spec.ts new file mode 100644 index 0000000..1e9f080 --- /dev/null +++ b/packages/observability/src/json-sink.spec.ts @@ -0,0 +1,129 @@ +import { describe, expect, vi } from "vitest"; + +import { jsonSink } from "./json-sink.js"; +import { it } from "./test-fixtures.js"; + +const lineOf = (written: { readonly chunks: () => readonly string[] }): Record => + JSON.parse(written.chunks().join("")) as Record; + +describe("the JSON sink", () => { + it("writes one object per line, correlation fields at the top level", ({ written }) => { + // GIVEN a sink over a stream that keeps what it is given + const sink = jsonSink(written); + + // WHEN a line written inside a unit reaches it + sink({ + level: "info", + message: "order placed", + attributes: { orderId: "o-1" }, + cause: undefined, + time: Date.UTC(2026, 7, 16), + unit: { unitId: "u-1", traceId: "t-1", tenantId: "acme" }, + }); + + // THEN the ids are fields an operator can search, not a message prefix + expect({ line: lineOf(written), newline: written.chunks().join("").endsWith("\n") }).toEqual({ + line: { + time: "2026-08-16T00:00:00.000Z", + level: "info", + message: "order placed", + orderId: "o-1", + unitId: "u-1", + traceId: "t-1", + tenantId: "acme", + }, + newline: true, + }); + }); + + it("keeps an Error's message and stack, which JSON.stringify drops", ({ written }) => { + // GIVEN a failure wrapping another + const cause = new Error("could not connect", { cause: new Error("ECONNREFUSED") }); + + // WHEN it is written + jsonSink(written)({ + level: "error", + message: "the relay stopped", + attributes: {}, + cause, + time: 0, + unit: undefined, + }); + + // THEN both levels survive, with the parts a bare stringify would lose + expect(lineOf(written)["cause"]).toEqual({ + name: "Error", + message: "could not connect", + stack: expect.stringContaining("could not connect"), + cause: { name: "Error", message: "ECONNREFUSED", stack: expect.any(String) }, + }); + }); + + it("refuses to let a caller's attribute rewrite the severity", ({ written }) => { + // GIVEN attributes that name the fields the sink owns + jsonSink(written)({ + level: "error", + message: "the real message", + attributes: { level: "info", message: "spoofed", traceId: "forged" }, + cause: undefined, + time: 0, + unit: { unitId: "u-1", traceId: "t-1" }, + }); + + // WHEN the line is read back + // THEN the line's own severity, message and correlation won + expect(lineOf(written)).toEqual( + expect.objectContaining({ level: "error", message: "the real message", traceId: "t-1" }), + ); + }); + + it("keeps the message when the payload cannot be serialised at all", ({ written }) => { + // GIVEN a cause that is circular — what `JSON.stringify` refuses outright + const circular: { self?: unknown } = {}; + circular.self = circular; + + // WHEN it is written + jsonSink(written)({ + level: "warn", + message: "kept", + attributes: {}, + cause: circular, + time: 0, + unit: undefined, + }); + + // THEN the line survives without the part that could not be rendered, + // rather than the sink throwing and the line being lost entirely + expect(lineOf(written)).toEqual({ + time: "1970-01-01T00:00:00.000Z", + level: "warn", + message: "kept", + cause: "[unserialisable]", + }); + }); + + it("defaults to stdout, so a process that configures nothing still logs", () => { + // GIVEN the sink with no stream given, and stdout captured + const written = vi.spyOn(process.stdout, "write").mockReturnValue(true); + + // WHEN a line is written + jsonSink()({ + level: "info", + message: "to stdout", + attributes: {}, + cause: undefined, + time: 0, + unit: undefined, + }); + // Captured before the spy is restored: `mockRestore` clears the record + // along with the stub. + const chunk = written.mock.calls.at(0)?.at(0); + written.mockRestore(); + + // THEN it went to the process's own stream — logs are stdout by default, + // where a container runtime already collects them + expect(chunk).toBe( + `${JSON.stringify({ time: "1970-01-01T00:00:00.000Z", level: "info", message: "to stdout" })}\n`, + ); + }); +}); diff --git a/packages/observability/src/json-sink.ts b/packages/observability/src/json-sink.ts new file mode 100644 index 0000000..c7e3ce3 --- /dev/null +++ b/packages/observability/src/json-sink.ts @@ -0,0 +1,68 @@ +import type { Line, Sink } from "./logger.js"; + +/** + * An `Error`'s `message` and `stack` are **non-enumerable**, so + * `JSON.stringify` renders a thrown one as `{}` — the line that exists to + * carry a failure would carry nothing. The kernel's `stderrSink` normalises + * the same way for the same reason; this is that rule applied to a log line, + * and it walks `cause` chains so a wrapped failure keeps its origin. + */ +const renderCause = (cause: unknown, depth = 0): unknown => { + if (!(cause instanceof Error)) return cause; + return { + name: cause.name, + message: cause.message, + stack: cause.stack, + // Bounded: an error whose `cause` points back at itself is rare and fatal + // to a renderer that follows it, and four levels is more than any real + // wrap depth. + ...(cause.cause === undefined || depth >= 4 + ? {} + : { cause: renderCause(cause.cause, depth + 1) }), + }; +}; + +/** + * One JSON object per line on `stream`, the shape every log backend already + * reads and the same one the kernel's `stderrSink` writes its events in. + * + * The field order is deliberate — `time`, `level`, `message`, then the + * correlation, then the caller's own attributes — because a human reading a + * raw line reads it left to right, and a machine does not care. The unit's + * ids are spread at the top level rather than nested under `unit`: a log + * backend indexes fields, and `traceId` is the field an operator searches. + * + * A caller's attribute never overwrites one of those: the correlation is what + * makes the line attributable, and an `attributes: { level: "…" }` that could + * rewrite the severity is how a log stream stops being trustworthy. + */ +export const jsonSink = + (stream: { readonly write: (chunk: string) => unknown } = process.stdout): Sink => + (line: Line) => { + const { level, message, attributes, cause, time, unit } = line; + const rendered = { + ...attributes, + time: new Date(time).toISOString(), + level, + message, + ...(unit === undefined ? {} : unit), + ...(cause === undefined ? {} : { cause: renderCause(cause) }), + }; + stream.write(`${safeStringify(rendered)}\n`); + }; + +// A payload `JSON.stringify` refuses — a circular attribute value reaching in +// through `cause` is the plausible one — must not cost the line. The message +// and its severity survive; the part that could not be rendered says so. +const safeStringify = (rendered: Record): string => { + try { + return JSON.stringify(rendered); + } catch { + return JSON.stringify({ + time: rendered["time"], + level: rendered["level"], + message: rendered["message"], + cause: "[unserialisable]", + }); + } +}; diff --git a/packages/observability/src/logger.spec.ts b/packages/observability/src/logger.spec.ts new file mode 100644 index 0000000..888b0a6 --- /dev/null +++ b/packages/observability/src/logger.spec.ts @@ -0,0 +1,194 @@ +import { Ok } from "unthrown"; +import { describe, expect, vi } from "vitest"; + +import { createLogger } from "./logger.js"; +import { it } from "./test-fixtures.js"; + +describe("the logger", () => { + it("writes the level, the message and the caller's attributes", ({ loggerAt, recorder }) => { + // GIVEN a logger at the default level + const logger = loggerAt(); + + // WHEN a line is written + logger.info("order placed", { orderId: "o-1", quantity: 2 }); + + // THEN the sink sees all of it, outside a unit + expect(recorder.only()).toEqual({ + level: "info", + message: "order placed", + attributes: { orderId: "o-1", quantity: 2 }, + cause: undefined, + time: expect.any(Number), + unit: undefined, + }); + }); + + it("drops a line below its level, and keeps one at it", ({ loggerAt, recorder }) => { + // GIVEN a logger raised to `warn` + const logger = loggerAt("warn"); + + // WHEN one line below the floor and one at it are written + logger.info("ignored"); + logger.warn("kept"); + + // THEN only the second survives, and `isEnabled` said so in advance + expect({ + levels: recorder.lines().map((line) => line.level), + info: logger.isEnabled("info"), + warn: logger.isEnabled("warn"), + }).toEqual({ levels: ["warn"], info: false, warn: true }); + }); + + it("writes one line per level, at the level its name says", ({ loggerAt, recorder }) => { + // GIVEN a logger that keeps everything + const logger = loggerAt("trace"); + const cause = new Error("boom"); + + // WHEN every level is written through its own method + logger.trace("t"); + logger.debug("d"); + logger.info("i"); + logger.warn("w"); + logger.error("e", undefined, cause); + logger.fatal("f", undefined, cause); + + // THEN each lands at its own severity, and only the two failure levels + // carry a cause — the shape of the surface, asserted once + expect( + recorder.lines().map((line) => ({ level: line.level, hasCause: line.cause !== undefined })), + ).toEqual([ + { level: "trace", hasCause: false }, + { level: "debug", hasCause: false }, + { level: "info", hasCause: false }, + { level: "warn", hasCause: false }, + { level: "error", hasCause: true }, + { level: "fatal", hasCause: true }, + ]); + }); + + it("carries a failure on its own channel, not stringified into the message", ({ + loggerAt, + recorder, + }) => { + // GIVEN a logger and a failure + const logger = loggerAt(); + const cause = new Error("the database is on fire"); + + // WHEN it is logged + logger.error("could not save the order", { orderId: "o-1" }, cause); + + // THEN the message stays the message and the cause stays the cause + expect(recorder.only()).toEqual( + expect.objectContaining({ + level: "error", + message: "could not save the order", + attributes: { orderId: "o-1" }, + cause, + }), + ); + }); + + it("layers attributes with `with`, and never mutates the logger it came from", ({ + loggerAt, + recorder, + }) => { + // GIVEN a logger and a child carrying more + const parent = loggerAt(); + const child = parent.with({ component: "relay" }); + + // WHEN both write, the child adding one of its own + child.info("child", { step: 1 }); + parent.info("parent"); + + // THEN the child's attributes are layered and the parent never saw them — + // the defect a mutable `setContext` has, asserted rather than asserted about + expect(recorder.lines().map((line) => line.attributes)).toEqual([ + { component: "relay", step: 1 }, + {}, + ]); + }); + + it("lets a call's own attribute win over the child's, for the same key", ({ + loggerAt, + recorder, + }) => { + // GIVEN a child logger carrying a component + const logger = loggerAt().with({ component: "relay" }); + + // WHEN a call names the same key + logger.info("overridden", { component: "sweeper" }); + + // THEN the nearest one wins + expect(recorder.only().attributes).toEqual({ component: "sweeper" }); + }); + + it("swallows a sink that throws, rather than taking the caller down with it", () => { + // GIVEN a logger whose sink is broken + const logger = createLogger(() => { + // oxlint-disable-next-line unthrown/no-throw -- the throw IS the subject under test: a broken sink must not reach the caller + throw new Error("the log transport is gone"); + }); + + // WHEN it writes + // THEN the call returns: a logging fault is not an outage + expect(() => logger.log("fatal", "still fine")).not.toThrow(); + }); + + it("carries the unit's tenant when the runtime supplied one, and omits it otherwise", ({ + loggerAt, + recorder, + }) => { + // GIVEN a logger, and a line written outside any unit + loggerAt().info("no unit"); + + // WHEN the record is read back + // THEN there is no `unit` at all — the field is absent rather than a set + // of empty strings, so a log backend's `traceId` facet stays honest + expect(recorder.only().unit).toBeUndefined(); + }); + + it("carries the tenant a runtime supplied, alongside the ids the kernel mints", async ({ + boot, + recorder, + tenantApp, + }) => { + // GIVEN an application whose runtime opens its unit with a tenant + boot(tenantApp("acme", { sink: recorder.sink })); + await vi.waitUntil(() => recorder.lines().length > 0); + + // WHEN the line it logged inside that unit is read back + // THEN the tenant rides with the ids, for a deployment that has one + expect(recorder.only().unit).toEqual({ + unitId: expect.any(String), + traceId: "unit-1", + tenantId: "acme", + }); + }); + + it("stamps a line written inside a unit with that unit's own record", async ({ + app, + boot, + recorder, + unitLogging, + }) => { + // GIVEN a booted application whose per-unit module logs as it is built — + // the shape a request-scoped span has, and the only code that genuinely + // runs inside the kernel's ambient record + const { module, runtime } = app({ sink: recorder.sink }); + boot(module, { unit: unitLogging }); + await runtime.untilStarted(); + + // WHEN one unit opens and settles + const unit = runtime.submit(); + unit.settle(Ok("done")); + await unit.result; + + // THEN the line carries that unit's ids, and the logger was the graph's own + expect(recorder.only()).toEqual( + expect.objectContaining({ + message: "inside the unit", + unit: { unitId: expect.any(String), traceId: expect.any(String) }, + }), + ); + }); +}); diff --git a/packages/observability/src/logger.ts b/packages/observability/src/logger.ts new file mode 100644 index 0000000..d684203 --- /dev/null +++ b/packages/observability/src/logger.ts @@ -0,0 +1,175 @@ +import { currentUnit } from "@btravstack/core"; +import { Port } from "@btravstack/di"; + +/** + * The severity of one line, and the whole of the set: six levels, ordered, + * with no `silly`, no `verbose` and no caller-defined additions. A fixed set + * is what lets `LOG_LEVEL` be validated at startup, `isEnabled` be a + * comparison rather than a lookup, and a future OpenTelemetry bridge map each + * one to a severity number without a table of synonyms. + */ +export type Level = "trace" | "debug" | "info" | "warn" | "error" | "fatal"; + +/** The levels in order, least severe first — what `isEnabled` compares through. */ +export const LEVELS: readonly Level[] = ["trace", "debug", "info", "warn", "error", "fatal"]; + +/** + * What a line carries besides its message: a flat record of scalars. + * + * Flat and scalar on purpose. A structured line is queried by field in the + * system that receives it, and a nested object is where a field's name stops + * being stable (`user.id` on one line, `user: { id }` on another); an + * `unknown` value is where a logger starts stringifying whatever it is + * handed, which is how a log call becomes the thing that throws. Anything + * else is the caller's to render — and a failure has a channel of its own, + * `cause`, which the implementation normalises. + */ +export type Attributes = Readonly>; + +/** + * The application's logger, as a port. + * + * Deliberately unlike NestJS's `Logger`, and each difference is a defect + * this shape does not have: + * + * - **A port, not a class.** Nothing is `new`ed, nothing is static, and + * nothing is global: a test provides its own, and `Provider(Logger)` is the + * only way one is bound. There is no `useLogger` to reach past DI with. + * - **`with` returns a logger; it never mutates.** Nest's `setContext` writes + * to the instance every caller shares, so two request scopes racing it + * interleave each other's context. A child here is a value. + * - **One argument order, and every level can carry a failure.** Six methods, + * one shape: `(message, attributes?, cause?)`. A logger whose `error` took + * its cause second and whose `warn` took none at all made a caller remember + * which arm it was in, and pushed every retryable failure up to `error` to + * keep its reason. + * - **No `any`, and no printf.** `Attributes` is a flat record of scalars — + * the shape a log backend can index — and a failure goes in `cause`, which + * the implementation normalises (an `Error`'s `message` and `stack` are + * non-enumerable, so `JSON.stringify` alone loses exactly the part worth + * keeping). + * - **It cannot throw.** A logger that throws turns an observability problem + * into an outage; every implementation this package ships swallows its own + * failures, the same rule the kernel's `safeSink` applies to an event sink. + * - **Correlation is not the caller's job.** The default implementation reads + * `currentUnit()` per call, so every line inside a unit carries its + * `traceId` — and reading it *per call* rather than at construction is what + * makes one application-scope logger correct for every unit. + * + * Synchronous `void`, not an `AsyncResult`: a log call is fire-and-forget by + * definition — a caller who awaited it would be waiting on I/O to decide + * nothing — and this package's thesis-6 exemption is exactly that. Delivery is + * the implementation's problem, and a lost line is not a modeled error. + */ +export class Logger extends Port("Logger") {} + +/** + * Every method takes the same three arguments in the same order, including the + * six that name their own level: `(message, attributes?, cause?)`. + * + * Uniform on purpose, and it was not at first. `error(message, cause, + * attributes)` read better at the call site that always has a cause and made + * every OTHER call site remember which arm it was in — and it left `warn` with + * nowhere to put one, so a retryable failure (a broker that refused a publish, + * which comes back) had to be logged at `error` purely to keep the reason. + * A failure is not a property of severity: an `info` line reporting a recovered + * fault carries one too. The cost is `logger.error("boom", undefined, cause)` + * for a failure with nothing else to say, which is rare — a line worth writing + * almost always has an id to write with it. + */ +export type LoggerService = { + readonly log: (level: Level, message: string, attributes?: Attributes, cause?: unknown) => void; + readonly trace: (message: string, attributes?: Attributes, cause?: unknown) => void; + readonly debug: (message: string, attributes?: Attributes, cause?: unknown) => void; + readonly info: (message: string, attributes?: Attributes, cause?: unknown) => void; + readonly warn: (message: string, attributes?: Attributes, cause?: unknown) => void; + /** `cause` is the failure itself — an `Error`, an `unthrown` `Err`'s error, a rejected value. */ + readonly error: (message: string, attributes?: Attributes, cause?: unknown) => void; + readonly fatal: (message: string, attributes?: Attributes, cause?: unknown) => void; + /** A logger carrying `attributes` on every line it writes, on top of this one's. Never mutates this one. */ + readonly with: (attributes: Attributes) => LoggerService; + /** Whether a line at `level` would be written — for a payload expensive enough to be worth not building. */ + readonly isEnabled: (level: Level) => boolean; +}; + +/** One line, as the implementation hands it to a {@link Sink}: the message, its severity, and everything known about it. */ +export type Line = { + readonly level: Level; + readonly message: string; + readonly attributes: Attributes; + readonly cause: unknown; + /** Milliseconds since the epoch, stamped when the line was written. */ + readonly time: number; + /** What `currentUnit()` carried, or `undefined` outside a unit. */ + readonly unit: + | { readonly unitId: string; readonly traceId: string; readonly tenantId?: string } + | undefined; +}; + +/** Where a line goes. Given a {@link Line}, writes it — and never throws, which `createLogger` guarantees on its behalf. */ +export type Sink = (line: Line) => void; + +const severity = (level: Level): number => LEVELS.indexOf(level); + +/** + * A logger over `sink`, filtered at `level` and correlated with the ambient + * unit. + * + * The correlation is read **per call**, not captured: one logger is built per + * scope and every unit the kernel opens has its own record, so a logger that + * captured it at construction would stamp the wrong trace id on every line but + * the first. `with` layers attributes and nothing else, so a child costs one + * object and shares the sink. + * + * Every path is wrapped: a sink that throws is swallowed here, because a + * logger that takes the process down is worse than a line nobody sees. + */ +export const createLogger = (sink: Sink, level: Level = "info"): LoggerService => { + const floor = severity(level); + + const build = (base: Attributes): LoggerService => { + const write = ( + lineLevel: Level, + message: string, + attributes: Attributes | undefined, + cause: unknown, + ): void => { + if (severity(lineLevel) < floor) return; + const unit = currentUnit(); + try { + sink({ + level: lineLevel, + message, + attributes: attributes === undefined ? base : { ...base, ...attributes }, + cause, + time: Date.now(), + unit: + unit === undefined + ? undefined + : { + unitId: unit.unitId, + traceId: unit.traceId, + ...(unit.tenantId === undefined ? {} : { tenantId: unit.tenantId }), + }, + }); + } catch { + // deliberately swallowed: see the port's TSDoc — a broken sink must + // not become an outage, and there is nowhere left to report it to. + } + }; + + return { + log: (lineLevel, message, attributes, cause) => write(lineLevel, message, attributes, cause), + trace: (message, attributes, cause) => write("trace", message, attributes, cause), + debug: (message, attributes, cause) => write("debug", message, attributes, cause), + info: (message, attributes, cause) => write("info", message, attributes, cause), + warn: (message, attributes, cause) => write("warn", message, attributes, cause), + error: (message, attributes, cause) => write("error", message, attributes, cause), + fatal: (message, attributes, cause) => write("fatal", message, attributes, cause), + with: (attributes) => build({ ...base, ...attributes }), + isEnabled: (lineLevel) => severity(lineLevel) >= floor, + }; + }; + + return build({}); +}; diff --git a/packages/observability/src/observability.spec.ts b/packages/observability/src/observability.spec.ts new file mode 100644 index 0000000..1c3f3fa --- /dev/null +++ b/packages/observability/src/observability.spec.ts @@ -0,0 +1,173 @@ +import { start } from "@btravstack/core"; +import { tapped } from "@btravstack/testing"; +import { describe, expect } from "vitest"; + +import { Logger } from "./logger.js"; +import { kernelEvents } from "./observability.js"; +import { LoggerConfig } from "./observability.js"; +import { it } from "./test-fixtures.js"; + +describe("the observability starter", () => { + it("binds the level from the environment, and every logger in the graph filters at it", async ({ + app, + boot, + recorder, + }) => { + // GIVEN an application booted with LOG_LEVEL raised + const { module, runtime } = app({ sink: recorder.sink }); + const tap = tapped(module, [Logger, LoggerConfig]); + boot(tap.module, { env: { LOG_LEVEL: "error" } }); + await runtime.untilStarted(); + const [logger, config] = tap.services(); + + // WHEN a line below that level and one at it are written + logger.info("dropped"); + logger.error("kept"); + + // THEN the graph's logger is the configured one + expect({ level: config.level, written: recorder.lines().map((line) => line.message) }).toEqual({ + level: "error", + written: ["kept"], + }); + }); + + it("fails startup with ConfigInvalid when LOG_LEVEL is not a level", async ({ app }) => { + // GIVEN an application whose environment names a level that does not exist + const { module } = app(); + + // WHEN it is booted — `start` directly, since this app never serves + const exited = await start(module, { + env: { LOG_LEVEL: "verbose" }, + signals: false, + probes: false, + onEvent: () => {}, + }).exited; + + // THEN it is a modeled ConfigInvalid naming the variable and the set, + // which `runMain` turns into exit 78 — not a silent fallback to `info` + expect(exited).toBeErrTagged("ConfigInvalid", { + port: "LoggerConfig", + issues: [ + { + message: expect.stringContaining("must be one of trace, debug, info, warn, error, fatal"), + path: ["LOG_LEVEL"], + }, + ], + }); + }); + + it("pins the level over the environment when a caller supplies one", async ({ + app, + boot, + recorder, + }) => { + // GIVEN a composition that pins `fatal`, and an environment that says `trace` + const { module, runtime } = app({ sink: recorder.sink, level: "fatal" }); + const tap = tapped(module, [LoggerConfig]); + boot(tap.module, { env: { LOG_LEVEL: "trace" } }); + await runtime.untilStarted(); + + // WHEN the bound configuration is read + // THEN explicit beat environment, per field, as every starter's pins do + expect(tap.services().at(0)).toEqual({ level: "fatal" }); + }); +}); + +describe("the kernel's events as log lines", () => { + it("writes each lifecycle event once, with its own fields", async ({ + app, + boot, + recorder, + loggerAt, + }) => { + // GIVEN an application whose `onEvent` is the logger's adapter + const { module, runtime } = app({ sink: recorder.sink }); + const events = kernelEvents(loggerAt("trace")); + const running = boot(module, { onEvent: events }); + await runtime.untilStarted(); + + // WHEN the application stops + running.stop(); + await running.exited; + + // THEN the transitions are lines, in order, each carrying its event name + expect( + recorder.lines().map((line) => ({ level: line.level, event: line.attributes["event"] })), + ).toEqual([ + { level: "info", event: "building" }, + { level: "info", event: "serving" }, + { level: "info", event: "stopping" }, + { level: "info", event: "exited" }, + ]); + }); + + it("logs a startup failure as an error, carrying its cause", ({ loggerAt, recorder }) => { + // GIVEN the adapter over a recording logger + const cause = new Error("port in use"); + + // WHEN a `startFailed` event reaches it + kernelEvents(loggerAt("trace"))({ type: "startFailed", cause }); + + // THEN it is an error line whose cause survives for the sink to render + expect(recorder.only()).toEqual( + expect.objectContaining({ + level: "error", + message: "the application failed to start", + cause, + attributes: { event: "startFailed" }, + }), + ); + }); + + it("logs an uncaught exception as an error", ({ loggerAt, recorder }) => { + // GIVEN the adapter and a crash + const cause = new Error("boom"); + + // WHEN the kernel reports it + kernelEvents(loggerAt("trace"))({ type: "uncaught", cause }); + + // THEN the line names the crash and carries it + expect(recorder.only()).toEqual( + expect.objectContaining({ level: "error", cause, attributes: { event: "uncaught" } }), + ); + }); + + it("logs a failed finaliser as a warning, naming the port AND why it failed", ({ + loggerAt, + recorder, + }) => { + // GIVEN the adapter and a finaliser that blew up + const cause = new Error("closed twice"); + + // WHEN the teardown error reaches it + kernelEvents(loggerAt("trace"))({ type: "teardownError", port: "Database", cause }); + + // THEN it is a warning — the exit code already carries the severity — and + // it keeps the reason, which is the whole point of every level taking a + // cause rather than just `error` and `fatal` + expect(recorder.only()).toEqual( + expect.objectContaining({ + level: "warn", + cause, + attributes: { event: "teardownError", port: "Database" }, + }), + ); + }); + + it("keeps the drain's numbers as attributes rather than a rendered sentence", ({ + loggerAt, + recorder, + }) => { + // GIVEN the adapter + // WHEN a drain is reported + const events = kernelEvents(loggerAt("trace")); + events({ type: "draining", inFlight: 3 }); + events({ type: "drained", report: { inFlightAtStart: 3, completed: 2, abandoned: 1 } }); + + // THEN both lines are queryable by field, which a message never is + expect(recorder.lines().map((line) => line.attributes)).toEqual([ + { event: "draining", inFlight: 3 }, + { event: "drained", inFlightAtStart: 3, completed: 2, abandoned: 1 }, + ]); + }); +}); diff --git a/packages/observability/src/observability.ts b/packages/observability/src/observability.ts new file mode 100644 index 0000000..2548357 --- /dev/null +++ b/packages/observability/src/observability.ts @@ -0,0 +1,116 @@ +import { Config, type ConfigInvalid, type Env } from "@btravstack/config"; +import type { EventSink, KernelEvent } from "@btravstack/core"; +import { Module, Port, Provider } from "@btravstack/di"; + +import { loggerSchema, type LoggerSettings } from "./config.js"; +import { jsonSink } from "./json-sink.js"; +import { createLogger, type Level, type LoggerService, type Sink } from "./logger.js"; +import { Logger } from "./logger.js"; + +/** + * What the graph bound from the environment: the level every logger in it + * filters at. A port of its own, like a starter's `HttpConfig`, so anything + * that wants to know reads it rather than re-deriving it. + */ +export class LoggerConfig extends Port("LoggerConfig") {} + +export type ObservabilityOptions = { + /** + * Where lines go. Default: one JSON object per line on `stdout` — + * dependency-free, and the shape every log backend already reads. The + * `@btravstack/observability/pino` subpath is the same seam for a + * deployment that wants pino's throughput. + */ + readonly sink?: Sink; + /** Pins the level instead of reading `LOG_LEVEL` — a test's `"fatal"`, a CLI's `"debug"`. */ + readonly level?: Level; +}; + +/** + * The observability starter: a module providing the application's `Logger` + * and the `LoggerConfig` it was built from. + * + * Import it next to the application and export `Logger` — that is the whole + * of it. Every line carries the ambient unit's `traceId` because the logger + * reads `currentUnit()` per call, so a request's lines are attributable + * without a single argument threaded through the call stack, and without the + * mutable per-instance context that makes that trick unsafe elsewhere. + * + * An application that wants its own implementation provides `Logger` itself + * and does not import this module; one that wants this implementation with a + * different destination passes a `sink`. Both are the same seam a starter + * always offers: the default behaviour is here, and it is one argument to + * replace. + */ +export const observability = ( + options: ObservabilityOptions = {}, +): Module => + Module("Observability")({ + provides: [ + Config.provider(LoggerConfig)(loggerSchema(options.level)), + Provider(Logger)([LoggerConfig], { + sync: (config) => createLogger(options.sink ?? jsonSink(), config.level), + }), + ], + exports: [Logger, LoggerConfig], + }); + +/** + * The kernel's nine lifecycle events, as log lines on `logger`. + * + * `StartOptions.onEvent` takes a sink and the kernel's default writes JSON to + * stderr, which is correct for a process with no logger and wrong for one + * with: two streams, two shapes, two sets of fields to search. This is the + * adapter between them — pass it as `onEvent` and `serving` lands next to the + * request that was in flight when it did. + * + * The mapping is deliberate rather than mechanical. `startFailed` and + * `uncaught` are `error`: they carry a cause and they are what an operator is + * paged for. `teardownError` is `warn` — the application is already stopping + * and the exit code says so — and everything else is `info`, one line per + * transition. The event's own fields become attributes, so `draining` keeps + * its `inFlight` count and `drained` its report. + * + * The logger is passed in rather than resolved: this runs before the graph + * exists (`building` is emitted while it is still being built), so it cannot + * come from the context it is watching. + */ +export const kernelEvents = + (logger: LoggerService): EventSink => + (event: KernelEvent) => { + switch (event.type) { + case "startFailed": + logger.error("the application failed to start", { event: event.type }, event.cause); + return; + case "uncaught": + logger.error( + "an uncaught exception stopped the application", + { event: event.type }, + event.cause, + ); + return; + case "teardownError": + logger.warn( + "a finaliser failed while the application was stopping", + { event: event.type, port: event.port }, + event.cause, + ); + return; + case "serving": + logger.info("serving", { event: event.type, runtime: event.runtime }); + return; + case "draining": + logger.info("draining", { event: event.type, inFlight: event.inFlight }); + return; + case "drained": + logger.info("drained", { + event: event.type, + inFlightAtStart: event.report.inFlightAtStart, + completed: event.report.completed, + abandoned: event.report.abandoned, + }); + return; + default: + logger.info(event.type, { event: event.type }); + } + }; diff --git a/packages/observability/src/pino.spec.ts b/packages/observability/src/pino.spec.ts new file mode 100644 index 0000000..95b053f --- /dev/null +++ b/packages/observability/src/pino.spec.ts @@ -0,0 +1,81 @@ +import pino from "pino"; +import { describe, expect } from "vitest"; + +import { pinoSink } from "./pino.js"; +import { it } from "./test-fixtures.js"; + +describe("the pino sink", () => { + it("writes the message and the correlation as fields pino can index", ({ written }) => { + // GIVEN a pino logger over a stream this spec keeps, at pino's own floor — + // the level filter is `createLogger`'s, so pino must not add a second one + const sink = pinoSink(pino({ level: "trace" }, written)); + + // WHEN a line written inside a unit reaches it + sink({ + level: "info", + message: "order placed", + attributes: { orderId: "o-1" }, + cause: undefined, + time: 0, + unit: { unitId: "u-1", traceId: "t-1" }, + }); + + // THEN pino's own line carries every field, and the message where pino + // puts it + expect(JSON.parse(written.chunks().join("")) as Record).toEqual( + expect.objectContaining({ + msg: "order placed", + orderId: "o-1", + unitId: "u-1", + traceId: "t-1", + }), + ); + }); + + it("hands a failure to pino as `err`, whose serialiser keeps the stack", ({ written }) => { + // GIVEN a pino logger and a failure + const sink = pinoSink(pino({ level: "trace" }, written)); + + // WHEN an error line reaches it + sink({ + level: "error", + message: "could not save", + attributes: {}, + cause: new Error("the database is on fire"), + time: 0, + unit: undefined, + }); + + // THEN the parts a bare JSON.stringify drops are on the line + expect( + (JSON.parse(written.chunks().join("")) as { readonly err: Record }).err, + ).toEqual( + expect.objectContaining({ + type: "Error", + message: "the database is on fire", + stack: expect.any(String), + }), + ); + }); + + it("maps every level onto pino's own, including trace and fatal", ({ written }) => { + // GIVEN a pino logger keeping everything + const sink = pinoSink(pino({ level: "trace" }, written)); + + // WHEN one line per level is written + for (const level of ["trace", "debug", "info", "warn", "error", "fatal"] as const) { + sink({ level, message: level, attributes: {}, cause: undefined, time: 0, unit: undefined }); + } + + // THEN pino recorded each at its own numeric severity — no level of ours + // silently collapses into another + expect( + written + .chunks() + .join("") + .trim() + .split("\n") + .map((line) => (JSON.parse(line) as { readonly level: number }).level), + ).toEqual([10, 20, 30, 40, 50, 60]); + }); +}); diff --git a/packages/observability/src/pino.ts b/packages/observability/src/pino.ts new file mode 100644 index 0000000..4d100cd --- /dev/null +++ b/packages/observability/src/pino.ts @@ -0,0 +1,40 @@ +import type { Logger as PinoLogger } from "pino"; + +import type { Line, Sink } from "./logger.js"; + +/** + * A {@link Sink} over a pino logger — the subpath a deployment reaches for + * when the default JSON sink's `JSON.stringify` per line is the thing showing + * up in a profile. `pino` is an **optional** peer: install it, import + * `@btravstack/observability/pino`, and pass the sink; a consumer that never + * imports this file never needs it. + * + * ```ts + * import pino from "pino"; + * import { observability } from "@btravstack/observability"; + * import { pinoSink } from "@btravstack/observability/pino"; + * + * observability({ sink: pinoSink(pino()) }); + * ``` + * + * The level filter stays **ours**: `createLogger` has already decided the + * line is worth writing by the time a sink sees it, so pino is configured at + * `trace` here — one filter in the process, and it is the one `LOG_LEVEL` + * validated at startup. `fatal` and `trace` map to pino's own; the ambient + * unit's ids ride as fields, not as a message prefix, so they stay indexable. + */ +export const pinoSink = + (logger: PinoLogger): Sink => + (line: Line) => { + const { level, message, attributes, cause, unit } = line; + const fields = { + ...attributes, + ...(unit === undefined ? {} : unit), + // pino renders `err` through its own error serialiser, which keeps the + // non-enumerable `message` and `stack` a bare `JSON.stringify` drops. + ...(cause === undefined ? {} : { err: cause }), + }; + // A sink never throws: `createLogger` swallows what escapes here, and a + // pino transport that has closed under a shutdown is the case that would. + logger[level](fields, message); + }; diff --git a/packages/observability/src/test-fixtures.ts b/packages/observability/src/test-fixtures.ts new file mode 100644 index 0000000..710ad7b --- /dev/null +++ b/packages/observability/src/test-fixtures.ts @@ -0,0 +1,166 @@ +import { RuntimePort, type Runtime } from "@btravstack/core"; +import { Module, Port, Provider } from "@btravstack/di"; +import { bootFixture, testRuntime, TestRuntimePort, type Boot } from "@btravstack/testing"; +import { Ok, OkAsync } from "unthrown"; +import { test } from "vitest"; + +import { Logger, createLogger, type Level, type Line, type LoggerService } from "./logger.js"; +import { LoggerConfig, observability, type ObservabilityOptions } from "./observability.js"; + +/** A sink that keeps what it was given, so a spec asserts on the line rather than on a stream. */ +export type Recorder = { + readonly sink: (line: Line) => void; + readonly lines: () => readonly Line[]; + /** The one line written, asserted here so a test body cannot pass on an empty capture. */ + readonly only: () => Line; +}; + +const recorderOf = (): Recorder => { + const lines: Line[] = []; + return { + sink: (line) => lines.push(line), + lines: () => lines, + only: () => { + const [first] = lines; + if (first === undefined || lines.length !== 1) { + // oxlint-disable-next-line unthrown/no-throw -- a fixture read before the line it exists to capture is a broken test, and the loudest possible answer is the right one + throw new Error(`expected exactly one line, got ${lines.length}`); + } + return first; + }, + }; +}; + +/** A stream that keeps what was written to it, for the sinks that write text. */ +export type Written = { + readonly write: (chunk: string) => void; + readonly chunks: () => readonly string[]; +}; + +const writtenOf = (): Written => { + const chunks: string[] = []; + return { write: (chunk) => chunks.push(chunk), chunks: () => chunks }; +}; + +/** A service the spec resolves out of a booted graph, so the logger under test is the graph's own. */ +export class Greeting extends Port("ObservabilityFixtureGreeting")<{ readonly text: string }> {} + +/** A port a unit module provides, so a spec has code that genuinely runs inside the kernel's ambient record. */ +export class UnitSpan extends Port("ObservabilityFixtureUnitSpan")<{ readonly opened: true }> {} + +/** + * A runtime that opens one unit **with a tenant** and logs inside it. + * + * No shipped runtime sets `UnitMeta.tenantId` — it is there for a + * multi-tenant deployment to supply — so a hand-rolled one is the only way to + * prove the logger carries it, and it doubles as the smallest example of a + * runtime declaring a `need`. + */ +class TenantRuntime extends RuntimePort> {} + +const tenantRuntimeModule = (tenantId: string) => + Module("TenantRuntime")({ + provides: [ + Provider(TenantRuntime)({ + value: { + name: "tenant", + needs: [Logger], + start: (host) => { + void host.run({ kind: "tenanted", id: "unit-1", tenantId }, (ctx) => { + ctx.get(Logger).info("inside a tenant's unit"); + return Ok(undefined); + }); + return OkAsync({ drain: () => OkAsync(), stop: () => OkAsync() }); + }, + }, + }), + ], + exports: [TenantRuntime], + }); + +export type ObservabilityFixtures = { + readonly boot: Boot; + readonly recorder: Recorder; + readonly written: Written; + /** A logger over `recorder`, at `level` — the unit-level subject. */ + readonly loggerAt: (level?: Level) => LoggerService; + /** + * The starter as an application composes it, next to an in-memory runtime, + * plus the runtime itself so a spec can hold a unit open and log inside it. + */ + /** A `StartOptions.unit` module that logs as it is built — inside the unit, through the application's own `Logger`. */ + readonly unitLogging: Module; + /** An application whose runtime opens one unit carrying a tenant, and logs inside it. */ + readonly tenantApp: ( + tenantId: string, + options?: ObservabilityOptions, + ) => Module; + readonly app: (options?: ObservabilityOptions) => { + readonly module: Module; + readonly runtime: ReturnType; + }; +}; + +export const it = test.extend({ + boot: bootFixture(), + + // oxlint-disable-next-line no-empty-pattern -- Vitest fixtures require a destructuring pattern; this one depends on no other fixture + recorder: async ({}, use) => { + await use(recorderOf()); + }, + + // oxlint-disable-next-line no-empty-pattern -- see above + written: async ({}, use) => { + await use(writtenOf()); + }, + + loggerAt: async ({ recorder }, use) => { + await use((level) => createLogger(recorder.sink, level)); + }, + + // oxlint-disable-next-line no-empty-pattern -- see above + unitLogging: async ({}, use) => { + await use( + Module("UnitLogging")({ + provides: [ + Provider(UnitSpan)([Logger], { + sync: (logger) => { + logger.info("inside the unit"); + return { opened: true }; + }, + }), + ], + exports: [UnitSpan], + }), + ); + }, + + // oxlint-disable-next-line no-empty-pattern -- see above + tenantApp: async ({}, use) => { + await use( + (tenantId, options = {}) => + Module("TenantApp")({ + imports: [tenantRuntimeModule(tenantId), observability(options)], + exports: [Logger, TenantRuntime], + }) as unknown as Module, + ); + }, + + // oxlint-disable-next-line no-empty-pattern -- see above + app: async ({}, use) => { + await use((options = {}) => { + const runtime = testRuntime(); + return { + runtime, + module: Module("ObservabilityApp")({ + imports: [runtime.module, observability(options)], + provides: [Provider(Greeting)({ value: { text: "hello" } })], + exports: [Logger, LoggerConfig, Greeting, TestRuntimePort], + // The starter's own `ConfigInvalid` and `Env` are discharged by the + // kernel and asserted by the spec that boots a bad `LOG_LEVEL`; + // spelling them here would put them in every fixture's signature. + }) as unknown as Module, + }; + }); + }, +}); diff --git a/packages/observability/src/vitest.d.ts b/packages/observability/src/vitest.d.ts new file mode 100644 index 0000000..ad36daf --- /dev/null +++ b/packages/observability/src/vitest.d.ts @@ -0,0 +1 @@ +import type {} from "@unthrown/vitest"; diff --git a/packages/observability/tsconfig.json b/packages/observability/tsconfig.json new file mode 100644 index 0000000..92efc4b --- /dev/null +++ b/packages/observability/tsconfig.json @@ -0,0 +1,11 @@ +{ + "extends": "@btravstack/tsconfig/base.json", + "compilerOptions": { + "outDir": "./dist", + "rootDir": "./src", + "declarationMap": false, + "types": ["node"] + }, + "include": ["src/**/*"], + "exclude": ["node_modules", "dist"] +} diff --git a/packages/observability/vitest.config.ts b/packages/observability/vitest.config.ts new file mode 100644 index 0000000..05e0cc0 --- /dev/null +++ b/packages/observability/vitest.config.ts @@ -0,0 +1,15 @@ +import { defineConfig } from "vitest/config"; + +export default defineConfig({ + test: { + environment: "node", + include: ["src/**/*.spec.ts"], + setupFiles: ["@unthrown/vitest"], + coverage: { + provider: "v8", + include: ["src/**/*.ts"], + exclude: ["src/**/*.spec.ts", "src/test-fixtures.ts"], + thresholds: { lines: 100, functions: 100 }, + }, + }, +}); diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index b917f27..555d9f6 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -126,6 +126,9 @@ catalogs: oxlint: specifier: 1.77.0 version: 1.77.0 + pino: + specifier: 10.3.1 + version: 10.3.1 prisma: specifier: 7.9.1 version: 7.9.1 @@ -323,6 +326,9 @@ importers: '@btravstack/example-order-infrastructure': specifier: workspace:* version: link:../order-infrastructure + '@btravstack/observability': + specifier: workspace:* + version: link:../../packages/observability '@opentelemetry/api': specifier: 'catalog:' version: 1.9.1 @@ -378,6 +384,9 @@ importers: '@btravstack/http': specifier: workspace:* version: link:../../packages/http + '@btravstack/observability': + specifier: workspace:* + version: link:../../packages/observability '@orpc/client': specifier: 'catalog:' version: 2.0.0-beta.23(@opentelemetry/api@1.9.1) @@ -443,19 +452,22 @@ importers: examples/order-application: dependencies: - '@btravstack/core': - specifier: workspace:* - version: link:../../packages/core '@btravstack/di': specifier: workspace:* version: link:../../packages/di '@btravstack/example-order-domain': specifier: workspace:* version: link:../order-domain + '@btravstack/observability': + specifier: workspace:* + version: link:../../packages/observability unthrown: specifier: 'catalog:' version: 5.5.0 devDependencies: + '@btravstack/config': + specifier: workspace:* + version: link:../../packages/config '@btravstack/tsconfig': specifier: 'catalog:' version: 0.2.0 @@ -600,6 +612,9 @@ importers: '@btravstack/example-order-temporal-contract': specifier: workspace:* version: link:../order-temporal-contract + '@btravstack/observability': + specifier: workspace:* + version: link:../../packages/observability '@btravstack/temporal': specifier: workspace:* version: link:../../packages/temporal @@ -842,6 +857,48 @@ importers: specifier: 'catalog:' version: 4.1.10(@opentelemetry/api@1.9.1)(@types/node@26.1.2)(@vitest/coverage-v8@4.1.10)(jiti@2.7.0)(terser@5.50.0)(tsx@4.23.5)(yaml@2.9.0) + packages/observability: + devDependencies: + '@btravstack/config': + specifier: workspace:* + version: link:../config + '@btravstack/core': + specifier: workspace:* + version: link:../core + '@btravstack/di': + specifier: workspace:* + version: link:../di + '@btravstack/testing': + specifier: workspace:* + version: link:../testing + '@btravstack/tsconfig': + specifier: 'catalog:' + version: 0.2.0 + '@types/node': + specifier: 'catalog:' + version: 26.1.2 + '@unthrown/vitest': + specifier: 'catalog:' + version: 5.5.0(unthrown@5.5.0)(vitest@4.1.10) + '@vitest/coverage-v8': + specifier: 'catalog:' + version: 4.1.10(vitest@4.1.10) + pino: + specifier: 'catalog:' + version: 10.3.1 + tsdown: + specifier: 'catalog:' + version: 0.22.14(oxc-resolver@11.24.2)(tsx@4.23.5)(typescript@7.0.2) + typescript: + specifier: 'catalog:' + version: 7.0.2 + unthrown: + specifier: 'catalog:' + version: 5.5.0 + vitest: + specifier: 'catalog:' + version: 4.1.10(@opentelemetry/api@1.9.1)(@types/node@26.1.2)(@vitest/coverage-v8@4.1.10)(jiti@2.7.0)(terser@5.50.0)(tsx@4.23.5)(yaml@2.9.0) + packages/temporal: devDependencies: '@btravstack/config': @@ -2350,6 +2407,9 @@ packages: resolution: {integrity: sha512-Ypt8KeRYw+4jUtlPirfcHWMrn5ms12VrrFPD+Mds477/7tJxG1Kcz2Yrg2nVcTQEUx/GdlhS+BUg1kmxNm04Ug==} engines: {node: ^12.22.0 || ^14.17.0 || >=16.0.0} + '@pinojs/redact@0.4.0': + resolution: {integrity: sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==} + '@pkgjs/parseargs@0.11.0': resolution: {integrity: sha512-+1VkjdD0QBLPodGrJUeqarH8VAIvQODIbwh9XpP5Syisf7YoQgsJKPNFoqqLQlu+VQ/tVSshMR6loPMn8U+dPg==} engines: {node: '>=14'} @@ -3725,6 +3785,10 @@ packages: async@3.2.6: resolution: {integrity: sha512-htCUDlxyyCLMgaM3xXg0C0LW2xqfuQ6p05pCEIsXuyQ+a1koYKTuBMzRNwmybfLgvJDMd0r1LTn4+E0Ti6C2AA==} + atomic-sleep@1.0.0: + resolution: {integrity: sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==} + engines: {node: '>=8.0.0'} + aws-ssl-profiles@1.1.2: resolution: {integrity: sha512-NZKeq9AfyQvEeNlN0zSYAaWrmBffJh3IELMZfRpJVWgrpEbtEpnjvzqBPf+mxoI287JohRDoa+/nsfqqiZmF6g==} engines: {node: '>= 6.0.0'} @@ -4854,6 +4918,10 @@ packages: ohash@2.0.11: resolution: {integrity: sha512-RdR9FQrFwNBNXAr4GixM8YaRZRJ5PUWbKYbE5eOsrwAjJW0q2REGcf79oYPsLyskQCZG1PLN+S/K1V00joZAoQ==} + on-exit-leak-free@2.1.2: + resolution: {integrity: sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA==} + engines: {node: '>=14.0.0'} + once@1.4.0: resolution: {integrity: sha512-lNaJgI+2Q5URQBkccEKHTQOPaXdUxnZZElQTZY0MFUAuaEqe1E+Nyvgdz/aIyNi6Z9MzO5dv1H8n58/GELp3+w==} @@ -4970,6 +5038,16 @@ packages: resolution: {integrity: sha512-uB80kBFb/tfd68bVleG9T5GGsGPjJrLAUpR5PZIrhBnIaRTQRjqdJSsIKkOP6OAIFbj7GOrcudc5pNjZ+geV2g==} engines: {node: '>=6'} + pino-abstract-transport@3.0.0: + resolution: {integrity: sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==} + + pino-std-serializers@7.1.0: + resolution: {integrity: sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw==} + + pino@10.3.1: + resolution: {integrity: sha512-r34yH/GlQpKZbU1BvFFqOjhISRo1MNx1tWYsYvmj6KIRHSPMT2+yHOEb1SG6NMvRoHRF0a07kCOox/9yakl1vg==} + hasBin: true + pkg-types@2.3.1: resolution: {integrity: sha512-y+ichcgc2LrADuhLNAx8DFjVfgz91pRxfZdI3UDhxHvcVEZsenLO+7XaU5vOp0u/7V/wZ+plyuQxtrDlZJ+yeg==} @@ -5016,6 +5094,9 @@ packages: process-nextick-args@2.0.1: resolution: {integrity: sha512-3ouUOpQhtgrbOa17J7+uxOTpITYWaGP7/AhoR3+A+/1e9skrzelGi/dXzEYyvbxubEF6Wn2ypscTKiKJFFn1ag==} + process-warning@5.1.0: + resolution: {integrity: sha512-jQSaVHsPgtyw60e1rQ/A+/ArPEj/S8pS/vFnyGa/gYFXrKk/6RuDkoqVDQ5NI5MmS01698ltlAk0NoDBNLujRw==} + process@0.11.10: resolution: {integrity: sha512-cdGef/drWFoydD1JsMzuFf8100nZl+GT+yacc2bEced5f9Rjk4z+WtFUTBu9PhOi9j/jfmBPu0mMEY4wIdAF8A==} engines: {node: '>= 0.6.0'} @@ -5060,6 +5141,9 @@ packages: queue-microtask@1.2.3: resolution: {integrity: sha512-NuaNSa6flKT5JaSYQzJok04JzTL1CA6aGhv5rfLW3PgqA+M2ChpZQnAC8h8i4ZFkBS8X5RqkDBHA7r4hej3K9A==} + quick-format-unescaped@4.0.4: + resolution: {integrity: sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==} + radash@12.1.1: resolution: {integrity: sha512-h36JMxKRqrAxVD8201FrCpyeNuUY9Y5zZwujr20fFO77tpUtGa6EZzfKw/3WaiBX95fq7+MpsuMLNdSnORAwSA==} engines: {node: '>=14.18.0'} @@ -5093,6 +5177,13 @@ packages: resolution: {integrity: sha512-Kko+Y5XQ6fM+Ce3dq3m9YGxnacYZYl9cA1wZjaF3Vbry2L3i1qVg8+CAgNPsXRArPMUMCaOR7oa9Nqntc43JKA==} engines: {node: '>= 20.19.0'} + real-require@0.2.0: + resolution: {integrity: sha512-57frrGM/OCTLqLOAh0mhVA9VBMHd+9U7Zb2THMGdBUoZVOtGbJzjxsYGDJ3A9AYYCP4hn6y1TVbaOfzWtm5GFg==} + engines: {node: '>= 12.13.0'} + + real-require@1.0.0: + resolution: {integrity: sha512-P4nbQYQfePJxRSmY+v/KINxVucm4NF3p3s7pJveMTtom52FR4YGltUQLB8idDXwDDWW+eYrWDFbuzUnjoWHF7g==} + regex-recursion@6.0.2: resolution: {integrity: sha512-0YCaSCq2VRIebiaUviZNs0cBz1kg5kVS2UKUfNIx8YVs1cN3AV7NTctO5FOKBA+UT2BPJIWZauYHPqJODG50cg==} @@ -5187,6 +5278,10 @@ packages: resolution: {integrity: sha512-mOSBvHGDZMuIEZMdOz/aCEYDCv0E7nfcNsIhUF+/P+xC7Hyf3FkvymqgPbg9D1EdSGu+uKbJgy09K/RKKc7kJA==} hasBin: true + safe-stable-stringify@2.5.0: + resolution: {integrity: sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==} + engines: {node: '>=10'} + safer-buffer@2.1.2: resolution: {integrity: sha512-YZo3K82SD7Riyi0E1EQPojLz7kpepnSQI9IyPbHHg1XXXevb5dJI7tpyN2ADxGcQbHG7vcyRHk0cbwqcQriUtg==} @@ -5237,6 +5332,9 @@ packages: resolution: {integrity: sha512-kCZr2V3ch9i00x8zXRhjUNVcjG9ijES5dDudkXvUVCT5QlJNQWElSJdZqyPemffHoLNUYwOcou0Fy+ojN0uHSQ==} engines: {node: '>= 18'} + sonic-boom@4.2.1: + resolution: {integrity: sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==} + source-map-js@1.2.1: resolution: {integrity: sha512-UXWMKhLOwVKb728IUtQPXxfYU+usdybtUrK/8uGE8CQMvrhOpwvzDBwj0QhSL7MQc7vIsISBG8VQ8+IDQxpfQA==} engines: {node: '>=0.10.0'} @@ -5271,6 +5369,10 @@ packages: split-ca@1.0.1: resolution: {integrity: sha512-Q5thBSxp5t8WPTTJQS59LrGqOZqOsrhDGDVm8azCqIBjSBd7nd9o2PM+mDulQQkh8h//4U6hFZnc/mul8t5pWQ==} + split2@4.2.0: + resolution: {integrity: sha512-UcjcJOWknrNkF6PLX83qcHM6KHgVKNkV62Y8a5uYDVv9ydGQVwAHMKqHdJje1VTWpljG0WYpCDhrCdAOYH4TWg==} + engines: {node: '>= 10.x'} + sprintf-js@1.0.3: resolution: {integrity: sha512-D9cPgkvLlV3t3IzL0D0YLvGA9Ahk4PcvVwUbN0dSGr1aP0Nrt4AEnTUbuGvquEC0mA64Gqt1fzirlRs5ibXx8g==} @@ -5408,6 +5510,10 @@ packages: peerDependencies: tslib: ^2 + thread-stream@4.2.0: + resolution: {integrity: sha512-e2zZ96wSChazBsbENf/Pcm/4swHt2cEKQ92rhUjkL9GCKiTDJIaTBenjE/m9DXi0QBmTMDkFDdOomUy20A1tDQ==} + engines: {node: '>=20'} + tinybench@2.9.0: resolution: {integrity: sha512-0+DUvqWMValLmha6lr4kD8iAMK1HzV0/aKnCtWb9v9641TnP/MFb7Pc2bxoxQjTXAErryXVgUOfv2YqNllqGeg==} @@ -7011,6 +7117,8 @@ snapshots: '@oxlint/plugins@1.78.0': {} + '@pinojs/redact@0.4.0': {} + '@pkgjs/parseargs@0.11.0': optional: true @@ -8308,6 +8416,8 @@ snapshots: async@3.2.6: {} + atomic-sleep@1.0.0: {} + aws-ssl-profiles@1.1.2: {} b4a@1.8.1: {} @@ -9352,6 +9462,8 @@ snapshots: ohash@2.0.11: {} + on-exit-leak-free@2.1.2: {} + once@1.4.0: dependencies: wrappy: 1.0.2 @@ -9515,6 +9627,26 @@ snapshots: pify@4.0.1: {} + pino-abstract-transport@3.0.0: + dependencies: + split2: 4.2.0 + + pino-std-serializers@7.1.0: {} + + pino@10.3.1: + dependencies: + '@pinojs/redact': 0.4.0 + atomic-sleep: 1.0.0 + on-exit-leak-free: 2.1.2 + pino-abstract-transport: 3.0.0 + pino-std-serializers: 7.1.0 + process-warning: 5.1.0 + quick-format-unescaped: 4.0.4 + real-require: 0.2.0 + safe-stable-stringify: 2.5.0 + sonic-boom: 4.2.1 + thread-stream: 4.2.0 + pkg-types@2.3.1: dependencies: confbox: 0.2.4 @@ -9568,6 +9700,8 @@ snapshots: process-nextick-args@2.0.1: {} + process-warning@5.1.0: {} + process@0.11.10: {} promise-breaker@6.0.0: {} @@ -9620,6 +9754,8 @@ snapshots: queue-microtask@1.2.3: {} + quick-format-unescaped@4.0.4: {} + radash@12.1.1: {} rc9@3.0.1: @@ -9671,6 +9807,10 @@ snapshots: readdirp@5.1.1: {} + real-require@0.2.0: {} + + real-require@1.0.0: {} + regex-recursion@6.0.2: dependencies: regex-utilities: 2.3.0 @@ -9785,6 +9925,8 @@ snapshots: dependencies: ret: 0.5.0 + safe-stable-stringify@2.5.0: {} + safer-buffer@2.1.2: {} schema-utils@4.3.3: @@ -9833,6 +9975,10 @@ snapshots: smol-toml@1.8.0: {} + sonic-boom@4.2.1: + dependencies: + atomic-sleep: 1.0.0 + source-map-js@1.2.1: {} source-map-loader@5.0.0(webpack@5.109.2(@swc/core@1.15.47)): @@ -9861,6 +10007,8 @@ snapshots: split-ca@1.0.1: {} + split2@4.2.0: {} + sprintf-js@1.0.3: {} sqlstring@2.3.3: {} @@ -10054,6 +10202,10 @@ snapshots: dependencies: tslib: 2.8.1 + thread-stream@4.2.0: + dependencies: + real-require: 1.0.0 + tinybench@2.9.0: {} tinyexec@1.3.0: {} diff --git a/pnpm-workspace.yaml b/pnpm-workspace.yaml index a238964..240ee61 100644 --- a/pnpm-workspace.yaml +++ b/pnpm-workspace.yaml @@ -67,6 +67,7 @@ catalog: lefthook: 2.1.10 oxfmt: 0.62.0 oxlint: 1.77.0 + pino: 10.3.1 prisma: 7.9.1 tsdown: 0.22.14 tsx: 4.23.5 diff --git a/turbo.json b/turbo.json index 5b00c35..bdab011 100644 --- a/turbo.json +++ b/turbo.json @@ -36,6 +36,7 @@ "@btravstack/config#build", "@btravstack/core#build", "@btravstack/testing#build", + "@btravstack/observability#build", "@btravstack/http#build", "@btravstack/temporal#build", "@btravstack/amqp#build" From 1825fe7a24507f17bb9327fcd0908b47c0d34c0e Mon Sep 17 00:00:00 2001 From: Benoit TRAVERS Date: Sun, 16 Aug 2026 16:47:56 +0200 Subject: [PATCH 2/2] docs(observability): align the sink's TSDoc with its precedence, and inline a port union MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - json-sink.ts said the sink's fields come first; they come last, and that IS the precedence a caller cannot forge — say that instead - the level spec's comment predated the uniform signature: a cause appears where the call supplied one, at every level - root CLAUDE.md still said teardownError drops its cause; it carries it, and that was the point of the change - examples/order-amqp-worker: spell the port union inline, as order-temporal-worker's fixture already does --- CLAUDE.md | 8 +++++--- examples/order-amqp-worker/src/test-fixtures.ts | 12 ++++++------ packages/observability/src/json-sink.ts | 16 ++++++++-------- packages/observability/src/logger.spec.ts | 4 ++-- 4 files changed, 21 insertions(+), 19 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 4229bc6..ce85124 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -633,9 +633,11 @@ deferred shape. is that field alone, for an application composing its own schema. - **`kernelEvents(logger)`** — the kernel's nine events as an `EventSink` for `StartOptions.onEvent`. The mapping is deliberate: `startFailed` and - `uncaught` are `error` and carry their `cause`; `teardownError` is `warn` - (the application is already stopping and the exit code says `2`) and does - **not** carry its cause, only `{ event, port }`; everything else is `info`. + `uncaught` are `error`; `teardownError` is `warn` (the application is + already stopping and the exit code says `2`). All three carry their `cause` + — every level takes one, which is what the uniform `(message, attributes?, +cause?)` bought: a warning that could not say _why_ a finaliser failed was + the first draft's bug. Everything else is `info`. Each event's own fields become attributes, and every line carries `event`. The logger is a **parameter**, not resolved from the graph: `building` is emitted while the graph is still being built, so the sink cannot come from diff --git a/examples/order-amqp-worker/src/test-fixtures.ts b/examples/order-amqp-worker/src/test-fixtures.ts index 15b436e..c8399d0 100644 --- a/examples/order-amqp-worker/src/test-fixtures.ts +++ b/examples/order-amqp-worker/src/test-fixtures.ts @@ -21,19 +21,19 @@ import { outboxRelay, relayConfig } from "./outbox-relay.js"; type App = RunningApp; +type ServeOptions = { readonly drainTimeoutMs: number }; + /** * `X` is pinned to the ports the composition root exports rather than left * generic: `start`'s gate is a phantom rest parameter proven at the call site, * and no proof is available inside a helper generic in the module's own * exports. `AmqpRuntime` is what `start` resolves; the rest is the writer's - * surface, which the tap below reads. + * surface, which the tap below reads. Spelled inline, like + * `order-temporal-worker`'s: an alias for a port union reads like a domain + * concept and is neither — the list IS the meaning. */ -type AmqpPorts = AmqpRuntime | PlaceOrder | OrderRepository | Outbox; - -type ServeOptions = { readonly drainTimeoutMs: number }; - type Serve = ( - module: Module, + module: Module, options?: ServeOptions, ) => Promise>; diff --git a/packages/observability/src/json-sink.ts b/packages/observability/src/json-sink.ts index c7e3ce3..35a3a83 100644 --- a/packages/observability/src/json-sink.ts +++ b/packages/observability/src/json-sink.ts @@ -26,15 +26,15 @@ const renderCause = (cause: unknown, depth = 0): unknown => { * One JSON object per line on `stream`, the shape every log backend already * reads and the same one the kernel's `stderrSink` writes its events in. * - * The field order is deliberate — `time`, `level`, `message`, then the - * correlation, then the caller's own attributes — because a human reading a - * raw line reads it left to right, and a machine does not care. The unit's - * ids are spread at the top level rather than nested under `unit`: a log - * backend indexes fields, and `traceId` is the field an operator searches. + * The caller's attributes are spread **first** and the line's own fields + * after them, and that order is the precedence: an `attributes: { level: + * "info" }` cannot rewrite an `error` line's severity, nor its `traceId`, + * because the sink writes those last. A stream where a caller can forge the + * severity is a stream nobody can trust. * - * A caller's attribute never overwrites one of those: the correlation is what - * makes the line attributable, and an `attributes: { level: "…" }` that could - * rewrite the severity is how a log stream stops being trustworthy. + * The unit's ids are spread at the top level rather than nested under `unit`: + * a log backend indexes fields, and `traceId` is the field an operator + * searches. */ export const jsonSink = (stream: { readonly write: (chunk: string) => unknown } = process.stdout): Sink => diff --git a/packages/observability/src/logger.spec.ts b/packages/observability/src/logger.spec.ts index 888b0a6..be7f583 100644 --- a/packages/observability/src/logger.spec.ts +++ b/packages/observability/src/logger.spec.ts @@ -52,8 +52,8 @@ describe("the logger", () => { logger.error("e", undefined, cause); logger.fatal("f", undefined, cause); - // THEN each lands at its own severity, and only the two failure levels - // carry a cause — the shape of the surface, asserted once + // THEN each lands at its own severity, and a cause appears exactly where + // the call supplied one — every level can carry one; these two did expect( recorder.lines().map((line) => ({ level: line.level, hasCause: line.cause !== undefined })), ).toEqual([