Improve log formatting

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<boolean> {
         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<boolean> {
   } 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<boolean> {
   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<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"] } },
   });
 
   buildOnce();

deno.jsonc

@@ -1,6 +1,6 @@
 {
   "name": "@udibo/react-app",
-  "version": "0.21.0",
+  "version": "0.22.0",
   "exports": {
     ".": "./mod.tsx",
     "./build": "./build.ts",

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<number, ServerSentEventTarget>();
 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();

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"] },
   },
 });

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<AppState>()
     } 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 },
+      );
     }
   });

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"] } },
   });
 }

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;
+}