From 16550ec8bb7810ccc36c36cbaab5542e4ad66dae Mon Sep 17 00:00:00 2001 From: mifi Date: Fri, 21 Aug 2026 11:20:24 -0300 Subject: [PATCH] feat: now supports `async` functions for logging data - `logger.debug('message', async () => ({ asyncReturn: await asyncFn() }))` is now supported - NOTE: this may result in logging occurring out of band for these calls if other events fire befor they settle Update CI labels to direct jobs to correct servers --- .prettierrc.json | 2 +- .woodpecker/bootstrap.yaml | 57 ---------------------------------- .woodpecker/ci.yaml | 3 ++ .woodpecker/publish.yaml | 3 ++ CHANGELOG.md | 5 ++- README.md | 5 +++ package.json | 1 + src/constants.ts | 33 ++++++++++++++++++++ src/logger.ts | 63 ++++++++++++++++++++++++++++++-------- src/sinks/console.ts | 8 +++-- src/sinks/sentry.ts | 1 + src/types.ts | 23 +++++++++++--- test/console.test.ts | 40 ++++++++++++++++++++++++ test/logger.test.ts | 37 ++++++++++++++++++++++ test/sentry.test.ts | 15 +++++++++ tsconfig.json | 3 +- 16 files changed, 217 insertions(+), 82 deletions(-) delete mode 100644 .woodpecker/bootstrap.yaml create mode 100644 src/constants.ts create mode 100644 test/console.test.ts diff --git a/.prettierrc.json b/.prettierrc.json index 5bf898c..7120640 100644 --- a/.prettierrc.json +++ b/.prettierrc.json @@ -1 +1 @@ -{ "singleQuote": false, "tabWidth": 4, "trailingComma": "all", "printWidth": 100 } +{ "singleQuote": false, "tabWidth": 4, "trailingComma": "all", "printWidth": 100, "semi": true } diff --git a/.woodpecker/bootstrap.yaml b/.woodpecker/bootstrap.yaml deleted file mode 100644 index 836d579..0000000 --- a/.woodpecker/bootstrap.yaml +++ /dev/null @@ -1,57 +0,0 @@ -# One-time bootstrap for the v0.9.1 tag, whose original tag workflow failed before publishing. -when: - - event: manual - -steps: - publish-v0-9-1: - image: node:24-bookworm-slim - environment: - NPM_TOKEN: - from_secret: gitea_package_token - commands: - - corepack enable - - corepack prepare pnpm@11.0.0 --activate - - apt-get update && apt-get install --yes --no-install-recommends ca-certificates git - - pnpm install --frozen-lockfile - - test "$(node -p \"require('./package.json').version\")" = "0.9.1" - - git rev-parse --verify refs/tags/v0.9.1 - - pnpm check - - pnpm test - - pnpm build - - npm config set @mifi:registry https://git.mifi.dev/api/packages/mifi/npm/ - - npm config set -- //git.mifi.dev/api/packages/mifi/npm/:_authToken "$NPM_TOKEN" - - pnpm publish --no-git-checks - - notify-bootstrap-failure: - image: curlimages/curl:8.14.1 - depends_on: [publish-v0-9-1] - environment: - MATTERMOST_BOT_ACCESS_TOKEN: - from_secret: mattermost_bot_access_token - MATTERMOST_CHANNEL_ID: - from_secret: mattermost_pushes_channel_id - MATTERMOST_POST_API_URL: - from_secret: mattermost_post_api_url - commands: - - | - BODY=$(printf '{"channel_id":"%s","message":"[%s - Build #%s] Package bootstrap failure 💩"}' "$MATTERMOST_CHANNEL_ID" "$CI_REPO" "$CI_PIPELINE_NUMBER") - curl --fail --show-error --silent --request POST --header 'Content-Type: application/json' --header "Authorization: Bearer $MATTERMOST_BOT_ACCESS_TOKEN" --data "$BODY" "$MATTERMOST_POST_API_URL" - when: - - status: [failure] - - notify-bootstrap-success: - image: curlimages/curl:8.14.1 - depends_on: [publish-v0-9-1] - environment: - MATTERMOST_BOT_ACCESS_TOKEN: - from_secret: mattermost_bot_access_token - MATTERMOST_CHANNEL_ID: - from_secret: mattermost_pushes_channel_id - MATTERMOST_POST_API_URL: - from_secret: mattermost_post_api_url - commands: - - | - BODY=$(printf '{"channel_id":"%s","message":"[%s - Build #%s] Package bootstrap success 🎉"}' "$MATTERMOST_CHANNEL_ID" "$CI_REPO" "$CI_PIPELINE_NUMBER") - curl --fail --show-error --silent --request POST --header 'Content-Type: application/json' --header "Authorization: Bearer $MATTERMOST_BOT_ACCESS_TOKEN" --data "$BODY" "$MATTERMOST_POST_API_URL" - when: - - status: [success] diff --git a/.woodpecker/ci.yaml b/.woodpecker/ci.yaml index 1bdc649..cd98d36 100644 --- a/.woodpecker/ci.yaml +++ b/.woodpecker/ci.yaml @@ -3,6 +3,9 @@ when: - event: push branch: main +labels: + performance: low + steps: verify: image: node:24-bookworm-slim diff --git a/.woodpecker/publish.yaml b/.woodpecker/publish.yaml index d013fe2..04a4169 100644 --- a/.woodpecker/publish.yaml +++ b/.woodpecker/publish.yaml @@ -6,6 +6,9 @@ when: depends_on: - ci +labels: + performance: high + clone: git: image: woodpeckerci/plugin-git diff --git a/CHANGELOG.md b/CHANGELOG.md index 7476fb4..82d252a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,10 +1,9 @@ ## [1.0.1](https://git.mifi.dev/mifi/logger/compare/v1.0.0...v1.0.1) (2026-08-07) - ### Bug Fixes -* **sentry:** widen SentryLike so official SDKs assign without adapters ([9f6f6e4](https://git.mifi.dev/mifi/logger/commit/9f6f6e4df52449a84111656a939fda5f59816ea5)) -* **sentry:** widen SentryLike so official SDKs assign without adapters ([3c468db](https://git.mifi.dev/mifi/logger/commit/3c468dbf44caf119b4ff769cbc158a4c3d9f6c54)) +- **sentry:** widen SentryLike so official SDKs assign without adapters ([9f6f6e4](https://git.mifi.dev/mifi/logger/commit/9f6f6e4df52449a84111656a939fda5f59816ea5)) +- **sentry:** widen SentryLike so official SDKs assign without adapters ([3c468db](https://git.mifi.dev/mifi/logger/commit/3c468dbf44caf119b4ff769cbc158a4c3d9f6c54)) # [1.0.0](https://git.mifi.dev/mifi/logger/compare/v0.10.0...v1.0.0) (2026-08-07) diff --git a/README.md b/README.md index 2183ae7..dbd4694 100644 --- a/README.md +++ b/README.md @@ -196,8 +196,13 @@ Any function passed **after** the first argument is invoked only if the event is ```ts logger.debug("state", () => buildHugeSnapshot()); // skipped when debug is suppressed +logger.debug("response", async () => ({ data: await res.json(), url })); ``` +Top-level thenables (including Promises returned from lazy factories, or a Promise passed directly as an argument) are settled before sinks run. The log call stays fire-and-forget (`void`). Settled events set `LogEvent.async`, and the console sink renders an `[async]` label suffix. Nested promises inside plain objects are not walked — compose them inside the async factory. Async emits may appear out of order relative to sync logs. + +Rejection reasons replace rejected thenables in that argument slot; other arguments still emit. + ## Releases Woodpecker verifies pull requests and `main`, reports CI to Mattermost, then automatically releases from Conventional Commits merged to `main`. It updates `package.json` and `CHANGELOG.md`, creates a `vX.Y.Z` tag, and publishes to the private `@mifi` registry. diff --git a/package.json b/package.json index ec92a3e..9dfea22 100644 --- a/package.json +++ b/package.json @@ -37,6 +37,7 @@ "format": "prettier --write .", "format:check": "prettier --check .", "lint": "oxlint src test", + "lint:fix": "oxlint src test --fix", "test": "vitest run", "test:watch": "vitest", "pack:check": "pnpm pack --pack-destination .artifacts", diff --git a/src/constants.ts b/src/constants.ts new file mode 100644 index 0000000..3e93ba7 --- /dev/null +++ b/src/constants.ts @@ -0,0 +1,33 @@ +/** + * Severity threshold for log filtering, ordered from most to least verbose. + * + * | Level | Meaning | + * |-----------|----------------------------------------------| + * | `trace` | Extremely detailed diagnostics | + * | `debug` | Development diagnostics | + * | `info` | Routine operational messages | + * | `warn` | Unexpected but recoverable conditions | + * | `error` | Failures that need attention | + * | `silent` | Suppresses all console-bound output | + * + * A logger emits events at or above its configured threshold (e.g. `warn` + * allows `warn` and `error`). + */ +export enum LogLevel { + TRACE = "trace", + DEBUG = "debug", + INFO = "info", + WARN = "warn", + ERROR = "error", + SILENT = "silent", +} + +/** + * Deployment stage used to pick a default log level when none is configured + * explicitly or via runtime overrides. + */ +export enum LoggerEnvironment { + DEVELOPMENT = "development", + STAGING = "staging", + PRODUCTION = "production", +} diff --git a/src/logger.ts b/src/logger.ts index 4138889..f6d66dc 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -1,7 +1,6 @@ import { createConsoleSink } from "./sinks/console"; import type { LogCallOptions, - LogData, LogEvent, Logger, LoggerEnvironment, @@ -178,16 +177,41 @@ function namespaceMatches(namespace: string | undefined, filters: readonly strin /** * Evaluates lazy log arguments: every argument after the first that is a * zero-arg function is invoked; earlier arguments and non-functions are kept. + * Returned thenables are left as-is for {@link settleArguments}. * * @param arguments_ - Raw call arguments (message first, then optional data). - * @returns Arguments with lazy factories resolved to their return values. + * @returns Arguments with lazy factories invoked (may still contain thenables). */ function evaluate(arguments_: readonly unknown[]): readonly unknown[] { return arguments_.map((argument, index) => - index > 0 && typeof argument === "function" ? (argument as () => LogData)() : argument, + index > 0 && typeof argument === "function" ? (argument as () => unknown)() : argument, ); } +/** Duck-type check for Promise-like values. */ +function isThenable(value: unknown): value is PromiseLike { + return ( + value !== null && + (typeof value === "object" || typeof value === "function") && + typeof (value as { then?: unknown }).then === "function" + ); +} + +/** + * Settles top-level thenables in evaluated arguments. + * Fulfilled values replace the thenable; rejection reasons replace rejected ones. + */ +async function settleArguments(arguments_: readonly unknown[]): Promise { + const settled = await Promise.allSettled( + arguments_.map((argument) => (isThenable(argument) ? argument : Promise.resolve(argument))), + ); + return settled.map((result) => (result.status === "fulfilled" ? result.value : result.reason)); +} + +function hasThenable(arguments_: readonly unknown[]): boolean { + return arguments_.some(isThenable); +} + /** * Resolves Sentry sink options from `options.sentry` or a Sentry sink in `sinks`. * Development always yields `undefined` (nothing is sent to Sentry). @@ -224,6 +248,8 @@ function resolveSentrySinkOptions( * * Functions passed after the first argument are evaluated lazily — only when * the event is emitted — so expensive snapshots stay cheap when suppressed. + * Async factories and top-level Promises are settled before sinks run + * (fire-and-forget); such events set {@link LogEvent.async}. * * @param options - Logger configuration. See {@link LoggerOptions}. * @returns A {@link Logger} instance. @@ -239,6 +265,7 @@ function resolveSentrySinkOptions( * * logger.error("Request failed", error); * logger.debug("skipped in production", () => hugeObject()); + * logger.debug("response", async () => ({ data: await res.json() })); * logger.warn("investigate", { id: 1 }, { sentry: true }); * ``` */ @@ -269,6 +296,9 @@ export function createLogger(options: LoggerOptions): Logger { levelRank(level) >= levelRank(threshold) && (!runtimeOverride?.namespaces.length || namespaceMatches(namespace, runtimeOverride.namespaces)); + const deliver = (event: LogEvent) => { + sinks.forEach((sink) => sink.emit(event)); + }; const emit = (level: Exclude, arguments_: readonly unknown[]) => { const split = splitLogCallArguments(arguments_); const sendToConsole = enabled(level); @@ -281,17 +311,26 @@ export function createLogger(options: LoggerOptions): Logger { (Boolean(sentrySinkOptions?.logs) && levelRank(level) >= levelRank(sentrySinkOptions.logLevel))); if (!sendToConsole && !sendToSentryIssue && !sendToSentryLogs) return; - const event: LogEvent = { + const timestamp = new Date(); + const evaluated = evaluate(split.arguments); + const base = { level, namespace, - arguments: evaluate(split.arguments), - timestamp: new Date(), + timestamp, environment: options.environment, sendToSentryLogs, sendToSentryIssue, sendToConsole, }; - sinks.forEach((sink) => sink.emit(event)); + if (!hasThenable(evaluated)) { + deliver({ ...base, arguments: evaluated }); + return; + } + void settleArguments(evaluated) + .then((settled) => deliver({ ...base, arguments: settled, async: true })) + .catch(() => { + /* allSettled absorbs rejections; defensive against unexpected throw */ + }); }; const consoleMethod = ( method: keyof Console | "profile" | "profileEnd", @@ -301,11 +340,11 @@ export function createLogger(options: LoggerOptions): Logger { if (!enabled(level)) return; const console_ = globalThis.console as Console & Record; const fn = console_[method]; - if (typeof fn === "function") - (fn as (...items: unknown[]) => void).apply( - console_, - Array.from(prefix(namespace, evaluate(arguments_))), - ); + if (typeof fn !== "function") return; + (fn as (...items: unknown[]) => void).apply( + console_, + Array.from(prefix(namespace, evaluate(arguments_))), + ); }; const api: Logger = { namespace, diff --git a/src/sinks/console.ts b/src/sinks/console.ts index 7f8acae..01eb3ae 100644 --- a/src/sinks/console.ts +++ b/src/sinks/console.ts @@ -33,7 +33,8 @@ function supportsAnsi(): boolean { * * - Skips events where `sendToConsole` is `false`. * - Maps `trace` to `console.debug`. - * - Prefixes a styled namespace label (`[A][B]` or `[LOG]`). + * - Prefixes a styled namespace label (`[A][B]` or `[LOG]`), plus `[async]` + * when {@link LogEvent.async} is set. * - Uses CSS `%c` styling in browsers and ANSI colors on Node TTYs. * - Node `error` level uses `console.error` (stderr). * @@ -55,7 +56,10 @@ export function createConsoleSink(): LogSink { const console_ = globalThis.console as Console & Record; const fn = console_[method]; if (typeof fn !== "function") return; - const label = event.namespace ? `[${event.namespace.split(":").join("][")}]` : "[LOG]"; + const labelBase = event.namespace + ? `[${event.namespace.split(":").join("][")}]` + : "[LOG]"; + const label = event.async ? `${labelBase}[async]` : labelBase; const arguments_ = isBrowser() ? [`%c${label}`, BROWSER_STYLE_BY_LEVEL[event.level], ...event.arguments] : supportsAnsi() diff --git a/src/sinks/sentry.ts b/src/sinks/sentry.ts index 1ce182b..c654fd1 100644 --- a/src/sinks/sentry.ts +++ b/src/sinks/sentry.ts @@ -147,6 +147,7 @@ export function toSentryLogPayload(event: LogEvent): { event.arguments.filter((item) => typeof item === "string").join(" ") || "Log event"; const attributes: Record = {}; if (event.namespace) attributes["logger.namespace"] = event.namespace; + if (event.async) attributes.async = true; for (const item of event.arguments) { if (!item || typeof item !== "object" || item instanceof Error || Array.isArray(item)) continue; diff --git a/src/types.ts b/src/types.ts index bbf7fcb..cce5b8b 100644 --- a/src/types.ts +++ b/src/types.ts @@ -1,3 +1,5 @@ +import { LogLevel as LogLevelEnum, LoggerEnvironment as LoggerEnvironmentEnum } from "./constants"; + /** * Severity threshold for log filtering, ordered from most to least verbose. * @@ -13,7 +15,7 @@ * A logger emits events at or above its configured threshold (e.g. `warn` * allows `warn` and `error`). */ -export type LogLevel = "trace" | "debug" | "info" | "warn" | "error" | "silent"; +export type LogLevel = `${LogLevelEnum}`; /** * Deployment stage used to pick a default log level when none is configured @@ -24,20 +26,23 @@ export type LogLevel = "trace" | "debug" | "info" | "warn" | "error" | "silent"; * - `staging` → `warn` * - `production` → `error` */ -export type LoggerEnvironment = "development" | "staging" | "production"; +export type LoggerEnvironment = `${LoggerEnvironmentEnum}`; /** * A value passed as a log argument after the message. * * Prefer a zero-argument function for expensive payloads: it is only invoked * when the event is actually emitted, so suppressed logs avoid the work. + * The factory may be `async` or otherwise return a `Promise`; top-level + * thenables are settled before sinks see the event (fire-and-forget). * * @example * ```ts * logger.debug("state", () => expensiveSnapshot()); + * logger.debug("response", async () => ({ data: await res.json() })); * ``` */ -export type LogData = unknown | (() => unknown); +export type LogData = unknown | (() => unknown | Promise); /** * Per-call options for `trace` / `debug` / `log` / `info` / `warn` / `error` @@ -73,10 +78,13 @@ export interface LogEvent { namespace?: string; /** * Evaluated arguments for the event (call options already stripped). - * Lazy `() => unknown` functions have already been invoked. + * Lazy factories have been invoked and top-level thenables settled; + * rejection reasons appear in place of rejected thenables. */ arguments: readonly unknown[]; - /** Wall-clock time when the event was created. */ + /** + * Wall-clock time when the log call was made (before awaiting thenables). + */ timestamp: Date; /** Deployment stage from {@link LoggerOptions.environment}. */ environment: LoggerEnvironment; @@ -95,6 +103,11 @@ export interface LogEvent { * should be rendered by console-oriented sinks. */ sendToConsole: boolean; + /** + * `true` when emit was deferred to settle top-level thenables. + * Omitted for fully synchronous emits. Console sinks render `[async]`. + */ + async?: boolean; } /** diff --git a/test/console.test.ts b/test/console.test.ts new file mode 100644 index 0000000..e7cafe5 --- /dev/null +++ b/test/console.test.ts @@ -0,0 +1,40 @@ +import { afterEach, describe, expect, it, vi } from "vitest"; +import { createConsoleSink } from "../src/index"; +import type { LogEvent } from "../src/index"; + +function event(overrides: Partial = {}): LogEvent { + return { + level: "debug", + namespace: "API", + arguments: ["hello"], + timestamp: new Date(), + environment: "development", + sendToSentryLogs: false, + sendToSentryIssue: false, + sendToConsole: true, + ...overrides, + }; +} + +describe("createConsoleSink", () => { + afterEach(() => { + vi.restoreAllMocks(); + }); + + it("appends [async] to the namespace label when event.async is set", () => { + const debug = vi.spyOn(console, "debug").mockImplementation(() => undefined); + createConsoleSink().emit(event({ async: true })); + expect(debug).toHaveBeenCalled(); + const first = debug.mock.calls[0]?.[0]; + expect(String(first)).toContain("[API][async]"); + }); + + it("omits [async] for synchronous events", () => { + const debug = vi.spyOn(console, "debug").mockImplementation(() => undefined); + createConsoleSink().emit(event()); + expect(debug).toHaveBeenCalled(); + const first = debug.mock.calls[0]?.[0]; + expect(String(first)).toContain("[API]"); + expect(String(first)).not.toContain("[async]"); + }); +}); diff --git a/test/logger.test.ts b/test/logger.test.ts index 51b25ab..0c4c377 100644 --- a/test/logger.test.ts +++ b/test/logger.test.ts @@ -40,6 +40,43 @@ describe("createLogger", () => { expect(expensive).toHaveBeenCalledTimes(1); expect(destination.events).toHaveLength(1); expect(destination.events[0]?.arguments).toEqual(["kept", { huge: "snapshot" }]); + expect(destination.events[0]?.async).toBeUndefined(); + }); + + it("never starts suppressed async lazy factories", () => { + const destination = sink(); + const expensive = vi.fn(async () => ({ huge: "snapshot" })); + const logger = createLogger({ environment: "production", sinks: [destination.sink] }); + logger.debug("ignored", expensive); + expect(expensive).not.toHaveBeenCalled(); + expect(destination.events).toHaveLength(0); + }); + + it("settles async lazy factories before emitting and sets async", async () => { + const destination = sink(); + const factory = vi.fn(async () => ({ data: 1 })); + const logger = createLogger({ environment: "development", sinks: [destination.sink] }); + logger.debug("response", factory); + expect(factory).toHaveBeenCalledTimes(1); + expect(destination.events).toHaveLength(0); + await vi.waitFor(() => expect(destination.events).toHaveLength(1)); + expect(destination.events[0]).toMatchObject({ + arguments: ["response", { data: 1 }], + async: true, + }); + }); + + it("unwraps direct Promise arguments and keeps rejection reasons", async () => { + const destination = sink(); + const reason = new Error("boom"); + const logger = createLogger({ environment: "development", sinks: [destination.sink] }); + logger.error("failed", { id: 1 }, Promise.reject(reason)); + expect(destination.events).toHaveLength(0); + await vi.waitFor(() => expect(destination.events).toHaveLength(1)); + expect(destination.events[0]).toMatchObject({ + arguments: ["failed", { id: 1 }, reason], + async: true, + }); }); it("applies session namespace filtering to namespace descendants", () => { diff --git a/test/sentry.test.ts b/test/sentry.test.ts index 49e7637..37f367b 100644 --- a/test/sentry.test.ts +++ b/test/sentry.test.ts @@ -66,6 +66,21 @@ describe("toSentryLogPayload", () => { }, }); }); + + it("includes async when the event was deferred for thenables", () => { + expect( + toSentryLogPayload({ + level: "debug", + arguments: ["response"], + timestamp: new Date(), + environment: "development", + sendToSentryLogs: true, + sendToSentryIssue: false, + sendToConsole: true, + async: true, + }).attributes, + ).toEqual({ async: true }); + }); }); describe("createSentrySink", () => { diff --git a/tsconfig.json b/tsconfig.json index d1313c5..9025172 100644 --- a/tsconfig.json +++ b/tsconfig.json @@ -6,8 +6,7 @@ "strict": true, "declaration": true, "verbatimModuleSyntax": true, - "skipLibCheck": true, - "ignoreDeprecations": "6.0" + "skipLibCheck": true }, "include": ["src", "test", "tsup.config.ts", "vitest.config.ts"] }