From 3252482e0b4c79679ec68dd4d9392d3f7c89ca32 Mon Sep 17 00:00:00 2001 From: Aarnav Tale Date: Wed, 17 Jun 2026 15:58:48 -0400 Subject: [PATCH] feat: switch logging to pino Closes HP-279 --- app/entry.server.tsx | 4 +- app/server/main.ts | 7 ++ app/utils/log.ts | 54 +++++++----- docs/configuration/index.md | 4 + package.json | 4 +- pnpm-lock.yaml | 166 ++++++++++++++++++++++++++++++++++- runtime/http.ts | 21 ++++- tests/unit/utils/log.test.ts | 59 +++++++++++++ 8 files changed, 292 insertions(+), 27 deletions(-) create mode 100644 tests/unit/utils/log.test.ts diff --git a/app/entry.server.tsx b/app/entry.server.tsx index 3f8fb7a..0125eda 100644 --- a/app/entry.server.tsx +++ b/app/entry.server.tsx @@ -7,6 +7,8 @@ import { renderToPipeableStream } from "react-dom/server"; import type { AppLoadContext, EntryContext } from "react-router"; import { ServerRouter } from "react-router"; +import log from "~/utils/log"; + export const streamTimeout = 5_000; export default function handleRequest( request: Request, @@ -52,7 +54,7 @@ export default function handleRequest( // errors encountered during initial shell rendering since they'll // reject and get logged in handleDocumentRequest. if (shellRendered) { - console.error(error); + log.error("server", "Streaming render error: %o", error); } }, }, diff --git a/app/server/main.ts b/app/server/main.ts index 958906f..19eca50 100644 --- a/app/server/main.ts +++ b/app/server/main.ts @@ -57,15 +57,22 @@ const listenFile = listenFilePath } : undefined; +const runtimeLogger = { + info: (message: string, ...args: unknown[]) => log.info("server", message, ...args), + error: (message: string, ...args: unknown[]) => log.error("server", message, ...args), +}; + startHttpServer({ host: config.server.host, port: config.server.port, tls, + logger: runtimeLogger, listenFile, listener: composeListener({ basename: __PREFIX__, staticRoot: clientDir, immutableAssets: true, + logger: runtimeLogger, requestListener, }), onShutdown: dispose, diff --git a/app/utils/log.ts b/app/utils/log.ts index 9704143..6b79b2f 100644 --- a/app/utils/log.ts +++ b/app/utils/log.ts @@ -1,44 +1,58 @@ // MARK: Side-Effects -// This module contains a side-effect because everything running here -// is static and logger is later modified in `app/server/index.ts` to -// disable debug logging if the `HEADPLANE_DEBUG_LOG` specifies as such. +// This module contains a side-effect because log levels are read from +// the environment once at module initialization. + +import pino from "pino"; const levels = ["info", "warn", "error", "debug"] as const; type Category = "server" | "config" | "agent" | "api" | "auth" | "sse"; +type Level = (typeof levels)[number]; export interface Logger extends Record< - (typeof levels)[number], + Level, (category: Category, message: string, ...args: unknown[]) => void > { debugEnabled: boolean; } -const logLevels = getLogLevels(); +const rootLogger = createRootLogger(); export default { - debugEnabled: logLevels.includes("debug"), - debug: (..._: Parameters) => {}, - ...Object.fromEntries( - logLevels.map((level) => [ - level, - (category: Category, message: string, ...args: unknown[]) => { - const date = new Date().toISOString(); - console.log(`${date} [${category}] ${level.toUpperCase()}: ${message}`, ...args); - }, - ]), - ), + debugEnabled: rootLogger.isLevelEnabled("debug"), + info: (category, msg, ...args) => rootLogger.info({ component: category }, msg, ...args), + warn: (category, msg, ...args) => rootLogger.warn({ component: category }, msg, ...args), + error: (category, msg, ...args) => rootLogger.error({ component: category }, msg, ...args), + debug: (category, msg, ...args) => rootLogger.debug({ component: category }, msg, ...args), } as Logger; -function getLogLevels() { +function createRootLogger() { + const options = { + level: getLogLevel(), + timestamp: () => `,"timestamp":"${new Date().toISOString()}"`, + formatters: { + level: (label: string) => ({ level: label }), + }, + } satisfies pino.LoggerOptions; + + if (process.env.NODE_ENV === "test") { + return pino(options); + } + + const destination = pino.destination({ dest: 1, sync: false }); + process.on("exit", () => destination.flushSync()); + return pino(options, destination); +} + +function getLogLevel(): Level { const debugLog = process.env.HEADPLANE_DEBUG_LOG; if (debugLog == null) { - return ["info", "warn", "error"]; + return "info"; } const normalized = debugLog.trim().toLowerCase(); const truthyValues = ["1", "true", "yes", "on"]; if (!truthyValues.includes(normalized)) { - return ["info", "warn", "error"]; + return "info"; } - return ["info", "warn", "error", "debug"]; + return "debug"; } diff --git a/docs/configuration/index.md b/docs/configuration/index.md index 34d393d..33b8759 100644 --- a/docs/configuration/index.md +++ b/docs/configuration/index.md @@ -82,6 +82,10 @@ The path-based secret loading mechanism also works with environment variables. F ## Debugging +Headplane writes server logs as newline-delimited JSON using Pino. Each entry +includes a timestamp, level, component, and message (`msg`) so log aggregation +tools can filter and index it directly. + To enable debug logging, set the **`HEADPLANE_DEBUG_LOG=true`** environment variable. This will enable all debug logs for Headplane, which could fill up log space very quickly. This is not recommended in production environments. diff --git a/package.json b/package.json index cd772ab..42873f0 100644 --- a/package.json +++ b/package.json @@ -7,7 +7,7 @@ "scripts": { "preinstall": "npx only-allow pnpm", "build": "react-router build", - "dev": "HEADPLANE_CONFIG_PATH=./config.example.yaml react-router dev", + "dev": "HEADPLANE_CONFIG_PATH=./config.example.yaml react-router dev | pino-pretty -c", "start": "node build/server/index.js", "typecheck": "react-router typegen && tsgo", "test:unit": "vitest run --project unit", @@ -40,6 +40,7 @@ "js-yaml": "^4.1.1", "lucide-react": "^1.8.0", "mime": "^4.1.0", + "pino": "^10.3.1", "react": "19.2.5", "react-codemirror-merge": "4.25.9", "react-dom": "19.2.5", @@ -66,6 +67,7 @@ "oxfmt": "^0.44.0", "oxlint": "^1.59.0", "oxlint-tsgolint": "^0.20.0", + "pino-pretty": "^13.1.3", "tailwindcss": "^4.2.2", "tailwindcss-animate": "^1.0.7", "testcontainers": "^11.14.0", diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index 5c17e28..8080686 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -74,6 +74,9 @@ importers: mime: specifier: ^4.1.0 version: 4.1.0 + pino: + specifier: ^10.3.1 + version: 10.3.1 react: specifier: 19.2.5 version: 19.2.5 @@ -147,6 +150,9 @@ importers: oxlint-tsgolint: specifier: ^0.20.0 version: 0.20.0 + pino-pretty: + specifier: ^13.1.3 + version: 13.1.3 tailwindcss: specifier: ^4.2.2 version: 4.2.2 @@ -1396,6 +1402,9 @@ packages: cpu: [x64] os: [win32] + '@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'} @@ -2133,6 +2142,10 @@ packages: asynckit@0.4.0: resolution: {integrity: sha512-Oei9OH4tRh0YqU3GxhX79dM/mwVgvbZJaSNaRk+bshkj0S5cfHcgYakreBjrHwatXKbz+IoIdYLxrKim2MjW0Q==} + atomic-sleep@1.0.0: + resolution: {integrity: sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==} + engines: {node: '>=8.0.0'} + b4a@1.7.3: resolution: {integrity: sha512-5Q2mfq2WfGuFp3uS//0s6baOJLMoVduPYVeNmDYxu5OUA1/cBfvr2RIS7vi62LdNj/urk1hfmj867I3qt6uZ7Q==} peerDependencies: @@ -2334,6 +2347,9 @@ packages: color-name@1.1.4: resolution: {integrity: sha512-dOy+3AuW3a2wNbZHIuMZpTcgjGuLU/uBL/ubcZF9OXbDo8ff4O8yVp5Bf0efS8uEoYo5q4Fx7dY9OgQGXgAsQA==} + colorette@2.0.20: + resolution: {integrity: sha512-IfEDxwoWIjkeXL1eXcDiow4UbKjhLdq6/EuSVR9GMN7KVH3r9gQ83e73hsz1Nd1T3ijd5xv1wcWRYO+D6kCI2w==} + combined-stream@1.0.8: resolution: {integrity: sha512-FQN4MRfuJeHf7cBbBMJFXhKSDq+2kAArBlmRBvcvFE5BB1HZKXtSFASDhdlz9zOYwxh8lDdnvmMOe/+5cdoEdg==} engines: {node: '>= 0.8'} @@ -2402,6 +2418,9 @@ packages: resolution: {integrity: sha512-0R9ikRb668HB7QDxT1vkpuUBtqc53YyAwMwGeUFKRojY/NWKvdZ+9UYtRfGmhqNbRkTSVpMbmyhXipFFv2cb/A==} engines: {node: '>= 12'} + dateformat@4.6.3: + resolution: {integrity: sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA==} + debug@4.4.3: resolution: {integrity: sha512-RGwwWnwQvkVfavKVt22FGLw+xYSdzARwm0ru6DhTVA3umU5hZc28V3kO4stgYryrTlLpuvgI9GiijltAjNbcqA==} engines: {node: '>=6.0'} @@ -2692,9 +2711,15 @@ packages: exsolve@1.0.8: resolution: {integrity: sha512-LmDxfWXwcTArk8fUEnOfSZpHOJ6zOMUJKOtFLFqJLoKJetuQG874Uc7/Kki7zFLzYybmZhp1M7+98pfMqeX8yA==} + fast-copy@4.0.3: + resolution: {integrity: sha512-58apWr0GUiDFM8+3afrO6eYwJBn9ZAhDOzG3L+/9llab/haCARS2UIfffmOurYLwbgDRs8n0rfr6qAAPEAuAQw==} + fast-fifo@1.3.2: resolution: {integrity: sha512-/d9sfos4yxzpwkDkuN7k2SqFKtYNmCTzgfEpz82x34IM9/zc8KGxQoXg1liNC/izpRM/MBdt44Nmx41ZWqk+FQ==} + fast-safe-stringify@2.1.1: + resolution: {integrity: sha512-W+KJc2dmILlPplD/H4K9l9LcAHAfPtP6BY84uVLXQ6Evcz9Lcg33Y2z1IVblT6xdY54PXYVHEv+0Wpq8Io6zkA==} + fdir@6.5.0: resolution: {integrity: sha512-tIbYtZbucOs0BRGqPJkshJUYdL+SDH7dVM8gjy+ERp3WAUjLEFJE+02kanyHtwjWOnwrKYBiwAmM0p4kLJAnXg==} engines: {node: '>=12.0.0'} @@ -2796,6 +2821,9 @@ packages: hast-util-whitespace@3.0.0: resolution: {integrity: sha512-88JUN06ipLwsnv+dVn+OIYOvAuvBMy/Qoi6O7mQHxdPXpjy+Cd6xRkWwux7DKO+4sYILtLBRIKgsdpS2gQc7qw==} + help-me@5.0.0: + resolution: {integrity: sha512-7xgomUX6ADmcYzFik0HzAxh/73YlKR9bmFzf51CZwR+b6YtzU2m0u49hQCqV6SvlqIqsaxovfwdvbnsw3b/zpg==} + hookable@5.5.3: resolution: {integrity: sha512-Yc+BQe8SvoXH1643Qez1zqLRmbA5rCL+sSmk6TVos0LWVfNIB7PGncdlId77WzLGSIB5KaWgTaNTs2lNVEI6VQ==} @@ -2886,6 +2914,10 @@ packages: jose@6.2.2: resolution: {integrity: sha512-d7kPDd34KO/YnzaDOlikGpOurfF0ByC2sEV4cANCtdqLlTfBlw2p14O/5d/zv40gJPbIQxfES3nSx1/oYNyuZQ==} + joycon@3.1.1: + resolution: {integrity: sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw==} + engines: {node: '>=10'} + js-base64@3.7.8: resolution: {integrity: sha512-hNngCeKxIUQiEUN3GPJOkz4wF/YvdUdbNL9hsBcMQTkKzboD7T/q3OYOuuPZLUE6dBxSGpwhk5mwuDud7JVAow==} @@ -3246,6 +3278,10 @@ packages: obug@2.1.1: resolution: {integrity: sha512-uTqF9MuPraAQ+IsnPf366RG4cP9RtUi7MLO1N3KEc+wb0a6yKpeL0lmk2IB1jY5KHPAlTc6T/JRdC/YqxHNwkQ==} + 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==} @@ -3312,6 +3348,20 @@ packages: resolution: {integrity: sha512-QP88BAKvMam/3NxH6vj2o21R6MjxZUAd6nlwAS/pnGvN9IVLocLHxGYIzFhg6fUQ+5th6P4dv4eW9jX3DSIj7A==} engines: {node: '>=12'} + pino-abstract-transport@3.0.0: + resolution: {integrity: sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==} + + pino-pretty@13.1.3: + resolution: {integrity: sha512-ttXRkkOz6WWC95KeY9+xxWL6AtImwbyMHrL1mSwqwW9u+vLp/WIElvHvCSDg0xO/Dzrggz1zv3rN5ovTRVowKg==} + hasBin: true + + 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.0: resolution: {integrity: sha512-SIqCzDRg0s9npO5XQ3tNZioRY1uK06lA41ynBC1YmFTmnY6FjUjVt6s4LoADmwoig1qqD0oK8h1p/8mlMx8Oig==} @@ -3333,6 +3383,9 @@ packages: process-nextick-args@2.0.1: resolution: {integrity: sha512-3ouUOpQhtgrbOa17J7+uxOTpITYWaGP7/AhoR3+A+/1e9skrzelGi/dXzEYyvbxubEF6Wn2ypscTKiKJFFn1ag==} + process-warning@5.0.0: + resolution: {integrity: sha512-a39t9ApHNx2L4+HBnQKqxxHNs1r7KF+Intd8Q/g1bUh6q0WIp9voPXJ/x0j+ZL45KF1pJd9+q2jLIRMfvEshkA==} + process@0.11.10: resolution: {integrity: sha512-cdGef/drWFoydD1JsMzuFf8100nZl+GT+yacc2bEced5f9Rjk4z+WtFUTBu9PhOi9j/jfmBPu0mMEY4wIdAF8A==} engines: {node: '>= 0.6.0'} @@ -3360,6 +3413,9 @@ packages: pump@3.0.4: resolution: {integrity: sha512-VS7sjc6KR7e1ukRFhQSY5LM2uBWAUPiOPa/A3mkKmiMwSmRFUITt0xuj+/lesgnCv+dPIEYlkzrcyXgquIHMcA==} + quick-format-unescaped@4.0.4: + resolution: {integrity: sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==} + rc@1.2.8: resolution: {integrity: sha512-y3bGgqKj3QBdxLbLkomlohkvsA8gdAiUQlSBJnBhfn+BPxg4bc62d8TcBW15wavDfgexCgccckhcZvywyQYPOw==} hasBin: true @@ -3428,6 +3484,13 @@ packages: resolution: {integrity: sha512-GDhwkLfywWL2s6vEjyhri+eXmfH6j1L7JE27WhqLeYzoh/A3DBaYGEj2H/HFZCn/kMfim73FXxEJTw06WtxQwg==} engines: {node: '>= 14.18.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==} @@ -3481,12 +3544,19 @@ packages: safe-buffer@5.2.1: resolution: {integrity: sha512-rp3So07KcdmmKbGvgaNxQSJr7bGVSVk5S9Eq1F+ppbRo70+YeaDxkw5Dd8NPN+GD6bjnYm2VuPuCXmpuYvmCXQ==} + safe-stable-stringify@2.5.0: + resolution: {integrity: sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==} + engines: {node: '>=10'} + safer-buffer@2.1.2: resolution: {integrity: sha512-YZo3K82SD7Riyi0E1EQPojLz7kpepnSQI9IyPbHHg1XXXevb5dJI7tpyN2ADxGcQbHG7vcyRHk0cbwqcQriUtg==} scheduler@0.27.0: resolution: {integrity: sha512-eNv+WrVbKu1f3vbYJT/xtiF5syA5HPIMtf9IgY/nKg0sWqzAUEvqY/xm7OcZc/qafLx/iO9FgOmeSAp4v5ti/Q==} + secure-json-parse@4.1.0: + resolution: {integrity: sha512-l4KnYfEyqYJxDwlNVyRfO2E4NTHfMKAWdUuA8J0yve2Dz/E/PdBepY03RvyJpssIpRFwJoCD55wA+mEDs6ByWA==} + semver@6.3.1: resolution: {integrity: sha512-BR7VvDCVHO+q2xBEWskxS6DJE1qRnb7DxzUrogb71CWoSficBxYsiAGd+Kl0mmq/MprG9yArRkyrQxTO6XjMzA==} hasBin: true @@ -3538,6 +3608,9 @@ packages: resolution: {integrity: sha512-HLpt+uLy/pxB+bum/9DzAgiKS8CX1EvbWxI4zlmgGCExImLdiad2iCwXT5Z4c9c3Eq8rP2318mPW2c+QbtjK8A==} engines: {node: '>= 10.0.0', npm: '>= 3.0.0'} + 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'} @@ -3559,6 +3632,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.1.3: resolution: {integrity: sha512-Oo+0REFV59/rz3gfJNKQiBlwfHaSESl1pcGyABQsnnIfWOFt6JNj5gCog2U6MLZ//IGYD+nA8nI+mTShREReaA==} @@ -3614,6 +3691,10 @@ packages: resolution: {integrity: sha512-4gB8na07fecVVkOI6Rs4e7T6NOTki5EmL7TUduTs6bu3EdnSycntVJ4re8kgZA+wx9IueI2Y11bfbgwtzuE0KQ==} engines: {node: '>=0.10.0'} + strip-json-comments@5.0.3: + resolution: {integrity: sha512-1tB5mhVo7U+ETBKNf92xT4hrQa3pm0MZ0PQvuDnWgAAGHDsfp4lPSpiS6psrSiet87wyGPh9ft6wmhOMQ0hDiw==} + engines: {node: '>=14.16'} + style-mod@4.1.3: resolution: {integrity: sha512-i/n8VsZydrugj3Iuzll8+x/00GH2vnYsk1eomD8QiRrSAeW6ItbCQDtfXCeJHd0iwiNagqjQkvpvREEPtW3IoQ==} @@ -3695,6 +3776,10 @@ packages: peerDependencies: typescript: ^5 + 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==} @@ -5138,6 +5223,8 @@ snapshots: '@oxlint/binding-win32-x64-msvc@1.59.0': optional: true + '@pinojs/redact@0.4.0': {} + '@pkgjs/parseargs@0.11.0': optional: true @@ -5840,6 +5927,8 @@ snapshots: asynckit@0.4.0: {} + atomic-sleep@1.0.0: {} + b4a@1.7.3: {} b4a@1.8.0: {} @@ -6040,6 +6129,8 @@ snapshots: color-name@1.1.4: {} + colorette@2.0.20: {} + combined-stream@1.0.8: dependencies: delayed-stream: 1.0.0 @@ -6106,6 +6197,8 @@ snapshots: data-uri-to-buffer@4.0.1: optional: true + dateformat@4.6.3: {} + debug@4.4.3: dependencies: ms: 2.1.3 @@ -6348,8 +6441,12 @@ snapshots: exsolve@1.0.8: {} + fast-copy@4.0.3: {} + fast-fifo@1.3.2: {} + fast-safe-stringify@2.1.1: {} + fdir@6.5.0(picomatch@4.0.4): optionalDependencies: picomatch: 4.0.4 @@ -6468,6 +6565,8 @@ snapshots: dependencies: '@types/hast': 3.0.4 + help-me@5.0.0: {} + hookable@5.5.3: {} hpagent@1.2.0: {} @@ -6541,6 +6640,8 @@ snapshots: jose@6.2.2: {} + joycon@3.1.1: {} + js-base64@3.7.8: optional: true @@ -6794,8 +6895,7 @@ snapshots: dependencies: brace-expansion: 2.0.3 - minimist@1.2.8: - optional: true + minimist@1.2.8: {} minipass@7.1.3: {} @@ -6861,6 +6961,8 @@ snapshots: obug@2.1.1: {} + on-exit-leak-free@2.1.2: {} + once@1.4.0: dependencies: wrappy: 1.0.2 @@ -6962,6 +7064,42 @@ snapshots: picomatch@4.0.4: {} + pino-abstract-transport@3.0.0: + dependencies: + split2: 4.2.0 + + pino-pretty@13.1.3: + dependencies: + colorette: 2.0.20 + dateformat: 4.6.3 + fast-copy: 4.0.3 + fast-safe-stringify: 2.1.1 + help-me: 5.0.0 + joycon: 3.1.1 + minimist: 1.2.8 + on-exit-leak-free: 2.1.2 + pino-abstract-transport: 3.0.0 + pump: 3.0.4 + secure-json-parse: 4.1.0 + sonic-boom: 4.2.1 + strip-json-comments: 5.0.3 + + 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.0.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.0: dependencies: confbox: 0.2.4 @@ -6994,6 +7132,8 @@ snapshots: process-nextick-args@2.0.1: {} + process-warning@5.0.0: {} + process@0.11.10: {} promise-limit@2.7.0: @@ -7039,6 +7179,8 @@ snapshots: end-of-stream: 1.4.5 once: 1.4.0 + quick-format-unescaped@4.0.4: {} + rc@1.2.8: dependencies: deep-extend: 0.6.0 @@ -7121,6 +7263,10 @@ snapshots: readdirp@4.1.2: {} + real-require@0.2.0: {} + + real-require@1.0.0: {} + regex-recursion@6.0.2: dependencies: regex-utilities: 2.3.0 @@ -7202,10 +7348,14 @@ snapshots: safe-buffer@5.2.1: {} + safe-stable-stringify@2.5.0: {} + safer-buffer@2.1.2: {} scheduler@0.27.0: {} + secure-json-parse@4.1.0: {} + semver@6.3.1: {} semver@7.7.4: {} @@ -7260,6 +7410,10 @@ snapshots: ip-address: 10.1.0 smart-buffer: 4.2.0 + sonic-boom@4.2.1: + dependencies: + atomic-sleep: 1.0.0 + source-map-js@1.2.1: {} source-map-support@0.5.21: @@ -7277,6 +7431,8 @@ snapshots: split-ca@1.0.1: {} + split2@4.2.0: {} + sprintf-js@1.1.3: {} ssh-remote-port-forward@1.0.4: @@ -7352,6 +7508,8 @@ snapshots: strip-json-comments@2.0.1: optional: true + strip-json-comments@5.0.3: {} + style-mod@4.1.3: {} superjson@2.2.2: @@ -7519,6 +7677,10 @@ snapshots: dependencies: typescript: 6.0.2 + thread-stream@4.2.0: + dependencies: + real-require: 1.0.0 + tinybench@2.9.0: {} tinyexec@1.1.1: {} diff --git a/runtime/http.ts b/runtime/http.ts index 85e9dd2..cbfa4e7 100644 --- a/runtime/http.ts +++ b/runtime/http.ts @@ -19,16 +19,31 @@ import { import { extname, normalize, resolve, sep } from "node:path"; import mime from "mime"; +import pino from "pino"; export interface Logger { info: (msg: string, ...args: unknown[]) => void; error: (msg: string, ...args: unknown[]) => void; } -// TODO: Replace with Pino! +const runtimeDestination = pino.destination({ dest: 1, sync: false }); +process.on("exit", () => runtimeDestination.flushSync()); + +const runtimePino = pino( + { + base: { service: "headplane" }, + messageKey: "message", + timestamp: () => `,"timestamp":"${new Date().toISOString()}"`, + formatters: { + level: (label) => ({ level: label }), + }, + }, + runtimeDestination, +); + const defaultLogger: Logger = { - info: (msg, ...args) => console.log(`[runtime] ${msg}`, ...args), - error: (msg, ...args) => console.error(`[runtime] ${msg}`, ...args), + info: (msg, ...args) => runtimePino.info({ component: "runtime" }, msg, ...args), + error: (msg, ...args) => runtimePino.error({ component: "runtime" }, msg, ...args), }; export interface StaticOptions { diff --git a/tests/unit/utils/log.test.ts b/tests/unit/utils/log.test.ts new file mode 100644 index 0000000..a14000d --- /dev/null +++ b/tests/unit/utils/log.test.ts @@ -0,0 +1,59 @@ +import { beforeEach, describe, expect, test, vi } from "vitest"; + +const envSnapshot = { ...process.env }; + +async function loadLogger() { + vi.resetModules(); + const mod = await import("~/utils/log"); + return mod.default; +} + +describe("structured logger", () => { + beforeEach(() => { + process.env = { ...envSnapshot }; + vi.restoreAllMocks(); + }); + + test("writes JSON log entries", async () => { + process.env.HEADPLANE_DEBUG_LOG = "false"; + const spy = vi.spyOn(process.stdout, "write").mockImplementation(() => true); + const log = await loadLogger(); + + log.info("server", "Listening on %s://%s:%s", "http", "127.0.0.1", 3000); + + expect(spy).toHaveBeenCalledOnce(); + const entry = JSON.parse(spy.mock.calls[0][0] as string); + expect(entry).toMatchObject({ + level: "info", + component: "server", + msg: "Listening on http://127.0.0.1:3000", + }); + expect(entry.timestamp).toEqual(expect.any(String)); + }); + + test("keeps debug logs disabled by default", async () => { + delete process.env.HEADPLANE_DEBUG_LOG; + const spy = vi.spyOn(process.stdout, "write").mockImplementation(() => true); + const log = await loadLogger(); + + log.debug("api", "GET %s", "/v1/node"); + + expect(log.debugEnabled).toBe(false); + expect(spy).not.toHaveBeenCalled(); + }); + + test("writes debug entries when enabled", async () => { + process.env.HEADPLANE_DEBUG_LOG = "true"; + const spy = vi.spyOn(process.stdout, "write").mockImplementation(() => true); + const log = await loadLogger(); + + log.debug("api", "GET %s", "/v1/node"); + + expect(log.debugEnabled).toBe(true); + expect(JSON.parse(spy.mock.calls[0][0] as string)).toMatchObject({ + level: "debug", + component: "api", + msg: "GET /v1/node", + }); + }); +});