feat: api logging by pino (#1865)

experiemental

packages/api/hono.ts

@@ -8,10 +8,12 @@ import { testCredentialsHandler } from '@documenso/lib/server-only/public-api/te
 import { listDocumentsHandler } from '@documenso/lib/server-only/webhooks/zapier/list-documents';
 import { subscribeHandler } from '@documenso/lib/server-only/webhooks/zapier/subscribe';
 import { unsubscribeHandler } from '@documenso/lib/server-only/webhooks/zapier/unsubscribe';
+// This is a bit nasty. Todo: Extract
+import type { HonoEnv } from '@documenso/remix/server/router';
 
 // This is bad, ts-router will be created on each request.
 // But don't really have a choice here.
-export const tsRestHonoApp = new Hono();
+export const tsRestHonoApp = new Hono<HonoEnv>();
 
 tsRestHonoApp
   .get('/openapi', (c) => c.redirect('https://openapi-v1.documenso.com'))

packages/api/v1/middleware/authenticated.ts

@@ -5,6 +5,7 @@ import { AppError, AppErrorCode } from '@documenso/lib/errors/app-error';
 import { getApiTokenByToken } from '@documenso/lib/server-only/public-api/get-api-token-by-token';
 import type { ApiRequestMetadata } from '@documenso/lib/universal/extract-request-metadata';
 import { extractRequestMetadata } from '@documenso/lib/universal/extract-request-metadata';
+import { logger } from '@documenso/lib/utils/logger';
 
 type B = {
   // appRoute: any;
@@ -62,6 +63,17 @@ export const authenticatedMiddleware = <
         },
       };
 
+      // Todo: Get from Hono context instead.
+      logger.info({
+        ipAddress: metadata.requestMetadata.ipAddress,
+        userAgent: metadata.requestMetadata.userAgent,
+        auth: 'api',
+        source: 'apiV1',
+        path: request.url,
+        userId: apiToken.user.id,
+        apiTokenId: apiToken.id,
+      });
+
       return await handler(
         {
           ...args,

packages/lib/package.json

@@ -27,7 +27,6 @@
     "@lingui/core": "^5.2.0",
     "@lingui/macro": "^5.2.0",
     "@lingui/react": "^5.2.0",
-    "jose": "^6.0.0",
     "@noble/ciphers": "0.4.0",
     "@noble/hashes": "1.3.2",
     "@node-rs/bcrypt": "^1.10.0",
@@ -37,6 +36,7 @@
     "@vvo/tzdb": "^6.117.0",
     "csv-parse": "^5.6.0",
     "inngest": "^3.19.13",
+    "jose": "^6.0.0",
     "kysely": "0.26.3",
     "luxon": "^3.4.0",
     "micro": "^10.0.1",
@@ -44,6 +44,8 @@
     "oslo": "^0.17.0",
     "pdf-lib": "^1.17.1",
     "pg": "^8.11.3",
+    "pino": "^9.7.0",
+    "pino-pretty": "^13.0.0",
     "playwright": "1.52.0",
     "posthog-js": "^1.245.0",
     "posthog-node": "^4.17.0",
@@ -59,4 +61,4 @@
     "@types/luxon": "^3.3.1",
     "@types/pg": "^8.11.4"
   }
-}
+}

packages/lib/utils/logger-legacy.ts

@@ -0,0 +1,112 @@
+import Honeybadger from '@honeybadger-io/js';
+
+import { env } from './env';
+
+export const buildLogger = () => {
+  if (env('NEXT_PRIVATE_LOGGER_HONEY_BADGER_API_KEY')) {
+    return new HoneybadgerLogger();
+  }
+
+  return new DefaultLogger();
+};
+
+interface LoggerDescriptionOptions {
+  method?: string;
+  path?: string;
+  context?: Record<string, unknown>;
+
+  /**
+   * The type of log to be captured.
+   *
+   * Defaults to `info`.
+   */
+  level?: 'info' | 'error' | 'critical';
+}
+
+/**
+ * Basic logger implementation intended to be used in the server side for capturing
+ * explicit errors and other logs.
+ *
+ * Not intended to capture the request and responses.
+ */
+interface Logger {
+  log(message: string, options?: LoggerDescriptionOptions): void;
+
+  error(error: Error, options?: LoggerDescriptionOptions): void;
+}
+
+class DefaultLogger implements Logger {
+  log(_message: string, _options?: LoggerDescriptionOptions) {
+    // Do nothing.
+  }
+
+  error(_error: Error, _options?: LoggerDescriptionOptions): void {
+    // Do nothing.
+  }
+}
+
+class HoneybadgerLogger implements Logger {
+  constructor() {
+    if (!env('NEXT_PRIVATE_LOGGER_HONEY_BADGER_API_KEY')) {
+      throw new Error('NEXT_PRIVATE_LOGGER_HONEY_BADGER_API_KEY is not set');
+    }
+
+    Honeybadger.configure({
+      apiKey: env('NEXT_PRIVATE_LOGGER_HONEY_BADGER_API_KEY'),
+    });
+  }
+
+  /**
+   * Honeybadger doesn't really have a non-error logging system.
+   */
+  log(message: string, options?: LoggerDescriptionOptions) {
+    const { context = {}, level = 'info' } = options || {};
+
+    try {
+      Honeybadger.event({
+        message,
+        context: {
+          level,
+          ...context,
+        },
+      });
+    } catch (err) {
+      console.error(err);
+
+      // Do nothing.
+    }
+  }
+
+  error(error: Error, options?: LoggerDescriptionOptions): void {
+    const { context = {}, level = 'error', method, path } = options || {};
+
+    // const tags = [`level:${level}`];
+    const tags = [];
+
+    let errorMessage = error.message;
+
+    if (method) {
+      tags.push(`method:${method}`);
+
+      errorMessage = `[${method}]: ${error.message}`;
+    }
+
+    if (path) {
+      tags.push(`path:${path}`);
+    }
+
+    try {
+      Honeybadger.notify(errorMessage, {
+        context: {
+          level,
+          ...context,
+        },
+        tags,
+      });
+    } catch (err) {
+      console.error(err);
+
+      // Do nothing.
+    }
+  }
+}

packages/lib/utils/logger.ts

@@ -1,112 +1,27 @@
-import Honeybadger from '@honeybadger-io/js';
+import { pino } from 'pino';
 
-import { env } from './env';
+// const transports: TransportTargetOptions[] = [];
 
-export const buildLogger = () => {
-  if (env('NEXT_PRIVATE_LOGGER_HONEY_BADGER_API_KEY')) {
-    return new HoneybadgerLogger();
-  }
+// if (env('NEXT_PRIVATE_LOGGING_DEV')) {
+// transports.push({
+//   target: 'pino-pretty',
+//   level: 'info',
+// });
+// }
 
-  return new DefaultLogger();
-};
+// const loggingFilePath = env('NEXT_PRIVATE_LOGGING_FILE_PATH');
 
-interface LoggerDescriptionOptions {
-  method?: string;
-  path?: string;
-  context?: Record<string, unknown>;
+// if (loggingFilePath) {
+//   transports.push({
+//     target: 'pino/file',
+//     level: 'info',
+//     options: {
+//       destination: loggingFilePath,
+//       mkdir: true,
+//     },
+//   });
+// }
 
-  /**
-   * The type of log to be captured.
-   *
-   * Defaults to `info`.
-   */
-  level?: 'info' | 'error' | 'critical';
-}
-
-/**
- * Basic logger implementation intended to be used in the server side for capturing
- * explicit errors and other logs.
- *
- * Not intended to capture the request and responses.
- */
-interface Logger {
-  log(message: string, options?: LoggerDescriptionOptions): void;
-
-  error(error: Error, options?: LoggerDescriptionOptions): void;
-}
-
-class DefaultLogger implements Logger {
-  log(_message: string, _options?: LoggerDescriptionOptions) {
-    // Do nothing.
-  }
-
-  error(_error: Error, _options?: LoggerDescriptionOptions): void {
-    // Do nothing.
-  }
-}
-
-class HoneybadgerLogger implements Logger {
-  constructor() {
-    if (!env('NEXT_PRIVATE_LOGGER_HONEY_BADGER_API_KEY')) {
-      throw new Error('NEXT_PRIVATE_LOGGER_HONEY_BADGER_API_KEY is not set');
-    }
-
-    Honeybadger.configure({
-      apiKey: env('NEXT_PRIVATE_LOGGER_HONEY_BADGER_API_KEY'),
-    });
-  }
-
-  /**
-   * Honeybadger doesn't really have a non-error logging system.
-   */
-  log(message: string, options?: LoggerDescriptionOptions) {
-    const { context = {}, level = 'info' } = options || {};
-
-    try {
-      Honeybadger.event({
-        message,
-        context: {
-          level,
-          ...context,
-        },
-      });
-    } catch (err) {
-      console.error(err);
-
-      // Do nothing.
-    }
-  }
-
-  error(error: Error, options?: LoggerDescriptionOptions): void {
-    const { context = {}, level = 'error', method, path } = options || {};
-
-    // const tags = [`level:${level}`];
-    const tags = [];
-
-    let errorMessage = error.message;
-
-    if (method) {
-      tags.push(`method:${method}`);
-
-      errorMessage = `[${method}]: ${error.message}`;
-    }
-
-    if (path) {
-      tags.push(`path:${path}`);
-    }
-
-    try {
-      Honeybadger.notify(errorMessage, {
-        context: {
-          level,
-          ...context,
-        },
-        tags,
-      });
-    } catch (err) {
-      console.error(err);
-
-      // Do nothing.
-    }
-  }
-}
+export const logger = pino({
+  level: 'info',
+});

packages/trpc/server/context.ts

@@ -1,14 +1,17 @@
 import type { Session } from '@prisma/client';
 import type { Context } from 'hono';
+import type { Logger } from 'pino';
 import { z } from 'zod';
 
 import type { SessionUser } from '@documenso/auth/server/lib/session/session';
 import { getOptionalSession } from '@documenso/auth/server/lib/utils/get-session';
 import type { ApiRequestMetadata } from '@documenso/lib/universal/extract-request-metadata';
 import { extractRequestMetadata } from '@documenso/lib/universal/extract-request-metadata';
+// This is a bit nasty. Todo: Extract
+import type { HonoEnv } from '@documenso/remix/server/router';
 
 type CreateTrpcContextOptions = {
-  c: Context;
+  c: Context<HonoEnv>;
   requestSource: 'app' | 'apiV1' | 'apiV2';
 };
 
@@ -19,6 +22,7 @@ export const createTrpcContext = async ({
   const { session, user } = await getOptionalSession(c);
 
   const req = c.req.raw;
+  const logger = c.get('logger');
 
   const metadata: ApiRequestMetadata = {
     requestMetadata: extractRequestMetadata(req),
@@ -36,6 +40,7 @@ export const createTrpcContext = async ({
 
   if (!session || !user) {
     return {
+      logger,
       session: null,
       user: null,
       teamId,
@@ -45,6 +50,7 @@ export const createTrpcContext = async ({
   }
 
   return {
+    logger,
     session,
     user,
     teamId,
@@ -66,4 +72,5 @@ export type TrpcContext = (
   teamId: number | undefined;
   req: Request;
   metadata: ApiRequestMetadata;
+  logger: Logger;
 };

packages/trpc/server/trpc.ts

@@ -65,7 +65,13 @@ const t = initTRPC
 /**
  * Middlewares
  */
-export const authenticatedMiddleware = t.middleware(async ({ ctx, next }) => {
+export const authenticatedMiddleware = t.middleware(async ({ ctx, next, path }) => {
+  const logger = ctx.logger.child({
+    path,
+    auth: ctx.metadata.auth,
+    source: ctx.metadata.source,
+  });
+
   const authorizationHeader = ctx.req.headers.get('authorization');
 
   // Taken from `authenticatedMiddleware` in `@documenso/api/v1/middleware/authenticated.ts`.
@@ -79,6 +85,11 @@ export const authenticatedMiddleware = t.middleware(async ({ ctx, next }) => {
 
     const apiToken = await getApiTokenByToken({ token });
 
+    logger.info({
+      userId: apiToken.user.id,
+      apiTokenId: apiToken.id,
+    });
+
     return await next({
       ctx: {
         ...ctx,
@@ -111,6 +122,11 @@ export const authenticatedMiddleware = t.middleware(async ({ ctx, next }) => {
     });
   }
 
+  logger.info({
+    userId: ctx.user.id,
+    apiTokenId: null,
+  });
+
   return await next({
     ctx: {
       ...ctx,

packages/trpc/utils/trpc-error-handler.ts

@@ -1,7 +1,7 @@
 import type { ErrorHandlerOptions } from '@trpc/server/unstable-core-do-not-import';
 
 import { AppError, AppErrorCode } from '@documenso/lib/errors/app-error';
-import { buildLogger } from '@documenso/lib/utils/logger';
+import { buildLogger } from '@documenso/lib/utils/logger-legacy';
 
 const logger = buildLogger();