From 80759a66549978f55b489b82649197ef0ef34e98 Mon Sep 17 00:00:00 2001 From: Kyle June Date: Sun, 28 Jul 2024 20:28:14 -0400 Subject: [PATCH] Improve log formatting --- build.ts | 79 +++++++++++++++++++++++------------------ deno.jsonc | 2 +- dev.ts | 20 +++++++++-- example/log.ts | 12 ++++--- example/routes/main.ts | 11 +++--- example/routes/main.tsx | 8 ++++- mod.tsx | 78 ++++++++++++++++++++++++++++++++++++++++ 7 files changed, 160 insertions(+), 50 deletions(-) diff --git a/build.ts b/build.ts index 3e3655b..b1da4f4 100644 --- a/build.ts +++ b/build.ts @@ -60,8 +60,7 @@ import * as path from "@std/path/posix"; import * as esbuild from "esbuild"; import { denoPlugins } from "@luca/esbuild-deno-loader"; -import { isProduction, isTest } from "./mod.tsx"; -import type { RouteFile } from "./client.tsx"; +import { isDevelopment, isProduction, isTest, logFormatter } from "./mod.tsx"; import { ROUTE_PARAM, ROUTE_WILDCARD, routePathFromName } from "./server.tsx"; import { getLogger } from "./log.ts"; @@ -88,6 +87,7 @@ const TEST_PATH = /(\.|_)test(\.(?:js|jsx|ts|tsx))$/; const IGNORE_PATH = /(\/|\\)_[^\/\\]*(\.(?:js|jsx|ts|tsx))$/; const ROUTE_PATH = /(\.(?:js|jsx|ts|tsx))$/; const REACT_EXT = /(\.(?:jsx|tsx))$/; +const ERROR_FALLBACK_EXPORT = /export\s+const\s+ErrorFallback\s*=/g; function addFileToDir(route: Route, name: string, ext: string) { const isReactFile = REACT_EXT.test(ext); @@ -198,11 +198,9 @@ async function routeFileData( ); } else { const mainPath = path.join(relativePath, main.react); - const mainMod = (await import( - path.toFileUrl(path.join(routesUrl, mainPath)).toString() - )) as RouteFile; + const mainMod = await Deno.readTextFile(path.join(routesUrl, mainPath)); importLines.push(`import * as $${routeId++} from "./${mainPath}";`); - if (mainMod.ErrorFallback) { + if (ERROR_FALLBACK_EXPORT.test(mainMod)) { importLines.push( `const $${routeId} = withErrorBoundary($${routeId - 1}.default, {`, ` FallbackComponent: $${routeId - 1}.ErrorFallback,`, @@ -572,6 +570,25 @@ export function getBuildOptions( }; } +function postBuild(success: boolean, error: Error | null) { + performance.mark("buildEnd"); + const duration = + performance.measure("build", "buildStart", "buildEnd").duration; + const routesDuration = + performance.measure("esbuild", "routesStart", "esbuildStart").duration; + const esbuildDuration = + performance.measure("esbuild", "esbuildStart", "buildEnd").duration; + const message = `Build ${success ? "completed" : "failed"} in ${ + Math.round(duration) + } ms`; + const data = { duration, esbuildDuration, routesDuration }; + if (success) { + getLogger().info(message, data); + } else { + getLogger().error(message, error, data); + } +} + /** * Builds the application and all of it's routes. * @@ -619,12 +636,14 @@ export async function build(options: BuildOptions = {}): Promise { sourcemap: "linked", }; + performance.mark("routesStart"); await buildRoutes(routesUrl); const esbuildPlugins = options.esbuildPlugins ?? []; if (context) { throw new Error("Build already in progress"); } + performance.mark("esbuildStart"); context = await esbuild.context({ plugins: [ ...denoPlugins({ configPath }), @@ -647,22 +666,7 @@ export async function build(options: BuildOptions = {}): Promise { } catch (_error) { error = _error; } finally { - performance.mark("buildEnd"); - const measure = performance.measure("build", "buildStart", "buildEnd"); - getLogger()[success ? "info" : "error"]( - `Build ${success ? "completed" : "failed"} in ${ - Math.round(measure.duration) - } ms`, - ); - const message = `Build ${success ? "completed" : "failed"} in ${ - Math.round(measure.duration) - } ms`; - const data = { duration: measure.duration }; - if (success) { - getLogger().info(message, data); - } else { - getLogger().error(message, error, data); - } + postBuild(success, error); } return success; @@ -682,23 +686,15 @@ export async function rebuild(): Promise { let success = false; let error: Error | null = null; try { + performance.mark("routesStart"); await buildRoutes(routesUrl); + performance.mark("esbuildStart"); await context.rebuild(); success = true; } catch (_error) { error = _error; } finally { - performance.mark("buildEnd"); - const measure = performance.measure("build", "buildStart", "buildEnd"); - const message = `Build ${success ? "completed" : "failed"} in ${ - Math.round(measure.duration) - } ms`; - const data = { duration: measure.duration }; - if (success) { - getLogger().info(message, data); - } else { - getLogger().error(message, error, data); - } + postBuild(success, error); } return success; @@ -721,6 +717,7 @@ export async function stop() { * This function can be used in a build script like the following: * ```ts * import { buildOnce, type BuildOptions } from "@udibo/react-app/build"; + * import { logFormatter } from "@udibo/react-app"; * import * as log from "@std/log"; * * export const buildOptions: BuildOptions = { @@ -729,8 +726,14 @@ export async function stop() { * * if (import.meta.main) { * // You can enable build script logging here or in a separate file that you import into this file. + * const level = isDevelopment() ? "DEBUG" : "INFO"; * log.setup({ - * loggers: { "react-app": { level: "INFO", handlers: ["default"] } }, + * handlers: { + * default: new log.ConsoleHandler(level, { + * formatter: logFormatter, + * }), + * }, + * loggers: { "react-app": { level, handlers: ["default"] } }, * }); * * buildOnce(buildOptions); @@ -746,8 +749,14 @@ export async function buildOnce(options: BuildOptions = {}): Promise { } if (import.meta.main) { + const level = isDevelopment() ? "DEBUG" : "INFO"; log.setup({ - loggers: { "react-app": { level: "INFO", handlers: ["default"] } }, + handlers: { + default: new log.ConsoleHandler(level, { + formatter: logFormatter, + }), + }, + loggers: { "react-app": { level, handlers: ["default"] } }, }); buildOnce(); diff --git a/deno.jsonc b/deno.jsonc index 4f02648..d318dd9 100644 --- a/deno.jsonc +++ b/deno.jsonc @@ -1,6 +1,6 @@ { "name": "@udibo/react-app", - "version": "0.21.0", + "version": "0.22.0", "exports": { ".": "./mod.tsx", "./build": "./build.ts", diff --git a/dev.ts b/dev.ts index 12677fd..d1684ab 100644 --- a/dev.ts +++ b/dev.ts @@ -18,14 +18,21 @@ * If the default configuration settings are insufficient for your application, you can create a custom dev script like shown below: * ```ts * import { startDev } from "@udibo/react-app/dev"; + * import { logFormatter } from "@udibo/react-app"; * import * as log from "@std/log"; * * // Import the build options from the build script * import { buildOptions } from "./build.ts"; * * // You can enable dev script logging here or in a separate file that you import into this file. + * const level = isDevelopment() ? "DEBUG" : "INFO"; * log.setup({ - * loggers: { "react-app": { level: "INFO", handlers: ["default"] } }, + * handlers: { + * default: new log.ConsoleHandler(level, { + * formatter: logFormatter, + * }), + * }, + * loggers: { "react-app": { level, handlers: ["default"] } }, * }); * * startDev({ @@ -55,10 +62,11 @@ import { type ServerSentEventTarget, } from "@oak/oak"; -import { isTest } from "./env.ts"; +import { isDevelopment, isTest } from "./env.ts"; import { getLogger } from "./log.ts"; import { build, getBuildOptions, rebuild } from "./build.ts"; import type { BuildOptions } from "./build.ts"; +import { logFormatter } from "./mod.tsx"; const sessions = new Map(); let nextSessionId = 0; @@ -299,8 +307,14 @@ export function startDev(options: DevOptions = {}): void { } if (import.meta.main) { + const level = isDevelopment() ? "DEBUG" : "INFO"; log.setup({ - loggers: { "react-app": { level: "INFO", handlers: ["default"] } }, + handlers: { + default: new log.ConsoleHandler(level, { + formatter: logFormatter, + }), + }, + loggers: { "react-app": { level, handlers: ["default"] } }, }); startDev(); diff --git a/example/log.ts b/example/log.ts index 0018576..fef294c 100644 --- a/example/log.ts +++ b/example/log.ts @@ -1,10 +1,14 @@ import * as log from "@std/log"; +import { isDevelopment, logFormatter } from "@udibo/react-app"; +const level = isDevelopment() ? "DEBUG" : "INFO"; log.setup({ + handlers: { + default: new log.ConsoleHandler(level, { + formatter: logFormatter, + }), + }, loggers: { - "react-app": { - level: "INFO", - handlers: ["default"], - }, + "react-app": { level, handlers: ["default"] }, }, }); diff --git a/example/routes/main.ts b/example/routes/main.ts index 65bd6db..ddcefdb 100644 --- a/example/routes/main.ts +++ b/example/routes/main.ts @@ -1,4 +1,5 @@ import { Router } from "@udibo/react-app/server"; +import * as log from "@std/log"; import type { AppState } from "../state.ts"; @@ -11,11 +12,9 @@ export default new Router() } finally { const dt = Date.now() - start; response.headers.set("X-Response-Time", `${dt}ms`); - console.log({ - status: response.status, - method: request.method, - href: request.url.href, - responseTime: dt, - }); + log.info( + `${request.method} ${request.url.href}`, + { status: response.status, responseTime: dt }, + ); } }); diff --git a/example/routes/main.tsx b/example/routes/main.tsx index 63bb95b..0c022c6 100644 --- a/example/routes/main.tsx +++ b/example/routes/main.tsx @@ -6,6 +6,7 @@ import { Helmet, isBrowser, isDevelopment, + logFormatter, } from "@udibo/react-app"; import * as log from "@std/log"; @@ -14,7 +15,12 @@ import { Loading } from "../components/loading.tsx"; if (isBrowser()) { const level = isDevelopment() ? "DEBUG" : "INFO"; log.setup({ - handlers: { default: new log.ConsoleHandler(level, { useColors: false }) }, + handlers: { + default: new log.ConsoleHandler(level, { + formatter: logFormatter, + useColors: false, + }), + }, loggers: { "react-app": { level, handlers: ["default"] } }, }); } diff --git a/mod.tsx b/mod.tsx index 0c03576..9753d76 100644 --- a/mod.tsx +++ b/mod.tsx @@ -7,6 +7,8 @@ const reactHelmetAsyncFixed = reactHelmetAsync; const helmet = reactHelmetAsyncFixed.default ?? reactHelmetAsync; export const Helmet = helmet.Helmet; +import type { LogRecord } from "@std/log"; +import { HttpError } from "./error.tsx"; export { getEnvironment, @@ -43,3 +45,79 @@ export function useInitialState< >(): AppState { return useContext(InitialStateContext) as AppState; } + +/** + * A log formatter function that can be used for formatting log messages from your application. + * + * With this formatter, you can log messages with additional context. + * If there is an error, it should be passed as the argument after the message. + * The last argument should be an object that contains additional context. + * All internal log messages are generated using that call signature style. + * + * Below is an example of how to use this formatter with the `@std/log` module: + * ```ts + * import { HttpError, logFormatter } from "@udibo/react-app"; + * import * as log from "@std/log"; + * + * const level = isDevelopment() ? "DEBUG" : "INFO"; + * log.setup({ + * handlers: { + * default: new log.ConsoleHandler(level, { + * formatter: logFormatter, + * }), + * }, + * loggers: { "react-app": { level, handlers: ["default"] } }, + * }); + * + * log.info("example", { a: 1, b: "x" }); + * // 2024-07-28T23:48:02.435Z INFO: example {"a":1,"b":"x"} + * log.warn("example", { a: 1, b: "x" }); + * // 2024-07-28T23:48:02.435Z WARN: example {"a":1,"b":"x"} + * const errors = [ + * new Error("Something went wrong"), + * new HttpError(500, "Something went wrong"), + * ]; + * log.error("regular error", errors[0], { a: 1, b: "x" }); + * // 2024-07-28T23:48:02.435Z ERROR: regular error {"name":"Error","message":"Something went wrong","stack":"@http://localhost:9000/build/_main.js:1:10808\n"} {"a":1,"b":"x"} + * log.error("http error", errors[1], { a: 1, b: "x" }); + * // 2024-07-28T23:48:02.435Z ERROR: http error {"name":"InternalServerError","message":"Something went wrong","status":500,"expose":false,"stack":"_HttpError@http://localhost:9000/build/chunk-6ZBSCUFP.js:160:9589\n@http://localhost:9000/build/_main.js:1:10842\n"} {"a":1,"b":"x"} + * log.critical("regular error", errors[0], { a: 1, b: "x" }); + * // 2024-07-28T23:48:02.435Z CRITICAL: regular error {"name":"Error","message":"Something went wrong","stack":"@http://localhost:9000/build/_main.js:1:10808\n"} {"a":1,"b":"x"} + * log.critical("http error", errors[1], { a: 1, b: "x" }); + * // 2024-07-28T23:48:02.435Z CRITICAL: http error {"name":"InternalServerError","message":"Something went wrong","status":500,"expose":false,"stack":"_HttpError@http://localhost:9000/build/chunk-6ZBSCUFP.js:160:9589\n@http://localhost:9000/build/_main.js:1:10842\n"} {"a":1,"b":"x"} + * ``` + * + * @param logRecord A record of a log message. + * @returns Formatted log message + */ +export function logFormatter(logRecord: LogRecord): string { + const { msg, levelName, datetime, args } = logRecord; + let message = `${datetime.toISOString()} ${levelName}: ${msg}`; + let data = args[0]; + if (data instanceof Error) { + const error = data; + data = args[1]; + if (error instanceof HttpError) { + const errorJSON = HttpError.json(error); + errorJSON.expose = (error as HttpError)?.expose; + if (!errorJSON.expose) { + errorJSON.message = error.message; + } + errorJSON.stack = error.stack; + message += ` ${JSON.stringify(errorJSON)}`; + } else { + const errorJSON = { + name: error.name, + message: error.message, + stack: error.stack, + }; + message += ` ${JSON.stringify(errorJSON)}`; + } + } + + if (data) { + message += ` ${JSON.stringify(data)}`; + } + + return message; +}