Include unhandled exceptions in request log (#80)

* Include unhandled exceptions in request log

* Get Sentry event ID

Author: itssimon

src/common/requestLogger.ts

@@ -6,6 +6,11 @@ import { IncomingHttpHeaders, OutgoingHttpHeaders } from "http";
 import { tmpdir } from "os";
 import { join } from "path";
 
+import { getSentryEventId } from "./sentry.js";
+import {
+  truncateExceptionMessage,
+  truncateExceptionStackTrace,
+} from "./serverErrorCounter.js";
 import TempGzipFile from "./tempGzipFile.js";
 
 const MAX_BODY_SIZE = 50_000; // 50 KB (uncompressed)
@@ -72,6 +77,7 @@ export type RequestLoggingConfig = {
   logRequestBody: boolean;
   logResponseHeaders: boolean;
   logResponseBody: boolean;
+  logException: boolean;
   maskQueryParams: RegExp[];
   maskHeaders: RegExp[];
   maskRequestBodyCallback?: (request: Request) => Buffer | null | undefined;
@@ -90,6 +96,7 @@ const DEFAULT_CONFIG: RequestLoggingConfig = {
   logRequestBody: false,
   logResponseHeaders: true,
   logResponseBody: false,
+  logException: true,
   maskQueryParams: [],
   maskHeaders: [],
   excludePaths: [],
@@ -168,7 +175,7 @@ export default class RequestLogger {
     return headers.map(([k, v]) => [k, this.shouldMaskHeader(k) ? MASKED : v]);
   }
 
-  logRequest(request: Request, response: Response) {
+  logRequest(request: Request, response: Response, error?: Error) {
     if (!this.enabled || this.suspendUntil !== null) return;
 
     const url = new URL(request.url);
@@ -248,6 +255,15 @@ export default class RequestLogger {
       uuid: randomUUID(),
       request: skipEmptyValues(request),
       response: skipEmptyValues(response),
+      exception:
+        error && this.config.logException
+          ? {
+              type: error.name,
+              message: truncateExceptionMessage(error.message),
+              stacktrace: truncateExceptionStackTrace(error.stack || ""),
+              sentryEventId: getSentryEventId(),
+            }
+          : null,
     };
     [item.request.body, item.response.body].forEach((body) => {
       if (body) {

src/common/sentry.ts

@@ -0,0 +1,22 @@
+import type * as Sentry from "@sentry/node";
+
+let sentry: typeof Sentry | undefined;
+
+// Initialize Sentry when the module is loaded
+(async () => {
+  try {
+    sentry = await import("@sentry/node");
+  } catch (e) {
+    // Sentry SDK is not installed, ignore
+  }
+})();
+
+/**
+ * Returns the last Sentry event ID if available
+ */
+export function getSentryEventId(): string | undefined {
+  if (sentry && sentry.lastEventId) {
+    return sentry.lastEventId();
+  }
+  return undefined;
+}

src/common/serverErrorCounter.ts

@@ -1,6 +1,6 @@
-import type * as Sentry from "@sentry/node";
 import { createHash } from "crypto";
 
+import { getSentryEventId } from "./sentry.js";
 import { ConsumerMethodPath, ServerError, ServerErrorsItem } from "./types.js";
 
 const MAX_MSG_LENGTH = 2048;
@@ -10,13 +10,11 @@ export default class ServerErrorCounter {
   private errorCounts: Map<string, number>;
   private errorDetails: Map<string, ConsumerMethodPath & ServerError>;
   private sentryEventIds: Map<string, string>;
-  private sentry: typeof Sentry | undefined;
 
   constructor() {
     this.errorCounts = new Map();
     this.errorDetails = new Map();
     this.sentryEventIds = new Map();
-    this.tryImportSentry();
   }
 
   public addServerError(serverError: ConsumerMethodPath & ServerError) {
@@ -25,7 +23,11 @@ export default class ServerErrorCounter {
       this.errorDetails.set(key, serverError);
     }
     this.errorCounts.set(key, (this.errorCounts.get(key) || 0) + 1);
-    this.captureSentryEventId(key);
+
+    const sentryEventId = getSentryEventId();
+    if (sentryEventId) {
+      this.sentryEventIds.set(key, sentryEventId);
+    }
   }
 
   public getAndResetServerErrors() {
@@ -38,8 +40,8 @@ export default class ServerErrorCounter {
           method: serverError.method,
           path: serverError.path,
           type: serverError.type,
-          msg: this.getTruncatedMessage(serverError.msg),
-          traceback: this.getTruncatedStack(serverError.traceback),
+          msg: truncateExceptionMessage(serverError.msg),
+          traceback: truncateExceptionStackTrace(serverError.traceback),
           sentry_event_id: this.sentryEventIds.get(key) || null,
           error_count: count,
         });
@@ -61,48 +63,30 @@ export default class ServerErrorCounter {
     ].join("|");
     return createHash("md5").update(hashInput).digest("hex");
   }
+}
 
-  private getTruncatedMessage(msg: string) {
-    msg = msg.trim();
-    if (msg.length <= MAX_MSG_LENGTH) {
-      return msg;
-    }
-    const suffix = "... (truncated)";
-    const cutoff = MAX_MSG_LENGTH - suffix.length;
-    return msg.substring(0, cutoff) + suffix;
-  }
-
-  private getTruncatedStack(stack: string) {
-    const suffix = "... (truncated) ...";
-    const cutoff = MAX_STACKTRACE_LENGTH - suffix.length;
-    const lines = stack.trim().split("\n");
-    const truncatedLines: string[] = [];
-    let length = 0;
-    for (const line of lines) {
-      if (length + line.length + 1 > cutoff) {
-        truncatedLines.push(suffix);
-        break;
-      }
-      truncatedLines.push(line);
-      length += line.length + 1;
-    }
-    return truncatedLines.join("\n");
-  }
-
-  private captureSentryEventId(serverErrorKey: string) {
-    if (this.sentry && this.sentry.lastEventId) {
-      const eventId = this.sentry.lastEventId();
-      if (eventId) {
-        this.sentryEventIds.set(serverErrorKey, eventId);
-      }
-    }
+export function truncateExceptionMessage(msg: string) {
+  if (msg.length <= MAX_MSG_LENGTH) {
+    return msg;
   }
+  const suffix = "... (truncated)";
+  const cutoff = MAX_MSG_LENGTH - suffix.length;
+  return msg.substring(0, cutoff) + suffix;
+}
 
-  private async tryImportSentry() {
-    try {
-      this.sentry = await import("@sentry/node");
-    } catch (e) {
-      // Sentry SDK is not installed, ignore
+export function truncateExceptionStackTrace(stack: string) {
+  const suffix = "... (truncated) ...";
+  const cutoff = MAX_STACKTRACE_LENGTH - suffix.length;
+  const lines = stack.trim().split("\n");
+  const truncatedLines: string[] = [];
+  let length = 0;
+  for (const line of lines) {
+    if (length + line.length + 1 > cutoff) {
+      truncatedLines.push(suffix);
+      break;
     }
+    truncatedLines.push(line);
+    length += line.length + 1;
   }
+  return truncatedLines.join("\n");
 }

src/express/middleware.ts

@@ -143,6 +143,7 @@ const getMiddleware = (app: Express | Router, client: ApitallyClient) => {
                 size: Number(res.get("content-length")),
                 body: convertBody(res.locals.body, res.get("content-type")),
               },
+              res.locals.serverError,
             );
           }
         } catch (error) {

src/fastify/plugin.ts

@@ -156,6 +156,7 @@ const apitallyPlugin: FastifyPluginAsync<ApitallyConfig> = async (
               reply.getHeader("content-type")?.toString(),
             ),
           },
+          reply.serverError,
         );
       }
     }

src/hono/middleware.ts

@@ -111,6 +111,7 @@ const getMiddleware = (client: ApitallyClient): MiddlewareHandler => {
           size: responseSize,
           body: responseBody,
         },
+        c.error,
       );
     }
     c.res = response;

src/koa/middleware.ts

@@ -23,13 +23,15 @@ const getMiddleware = (client: ApitallyClient) => {
     }
     let path: string | undefined;
     let statusCode: number | undefined;
+    let serverError: Error | undefined;
     const startTime = performance.now();
     try {
       await next();
     } catch (error: any) {
       path = getPath(ctx);
       statusCode = error.statusCode || error.status || 500;
       if (path && statusCode === 500 && error instanceof Error) {
+        serverError = error;
         client.serverErrorCounter.addServerError({
           consumer: getConsumer(ctx)?.identifier,
           method: ctx.request.method,
@@ -90,6 +92,7 @@ const getMiddleware = (client: ApitallyClient) => {
               ctx.response.get("content-type"),
             ),
           },
+          serverError,
         );
       }
     }

tests/common/requestLogger.test.ts

@@ -45,6 +45,7 @@ describe("Request logger", () => {
           size: 4,
           body: Buffer.from("test"),
         },
+        new Error("test"),
       );
     }
 
@@ -70,6 +71,8 @@ describe("Request logger", () => {
     expect(atob(items[0].request.body)).toBe("test");
     expect(items[0].response.statusCode).toBe(200);
     expect(atob(items[0].response.body)).toBe("test");
+    expect(items[0].exception.type).toBe("Error");
+    expect(items[0].exception.message).toBe("test");
   });
 
   it("Log exclusions", async () => {