Add flags for logging slow requests (#296)

* Add flags for logging slow requests

* Respond to review

src/expressServer.ts

@@ -76,6 +76,12 @@ export function setupEnvironment(): void {
 export type AddRoutes = (router: Router, options?: Partial<FernsRouterOptions<any>>) => void;
 
 const logRequestsFinished = function (req: any, res: any, startTime: [number, number]) {
+  const options = (req.loggingOptions ?? {}) as LoggingOptions;
+
+  const slowReadMs = options.logSlowRequestsReadMs ?? SLOW_READ_MAX;
+  const slowWriteMs = options.logSlowRequestsWriteMs ?? SLOW_WRITE_MAX;
+
+  // TODO: hrtime is legacy. Use process.hrtime.bigint() instead.
   const diff = process.hrtime(startTime);
   const diffInMs = Math.round(diff[0] * 1000 + diff[1] * 0.000001);
   let pathName = "unknown";
@@ -89,22 +95,24 @@ const logRequestsFinished = function (req: any, res: any, startTime: [number, nu
   if (!Boolean(process.env.DISABLE_LOG_ALL_REQUESTS)) {
     logger.debug(`${req.method} -> ${req.originalUrl} ${res.statusCode} ${`${diffInMs}ms`}`);
   }
-  if (diffInMs > SLOW_READ_MAX && req.method === "GET") {
-    logger.warn(
-      `Slow GET request, ${JSON.stringify({
-        requestTime: diffInMs,
-        pathName,
-        url: req.originalUrl,
-      })}`
-    );
-  } else if (diffInMs > SLOW_WRITE_MAX) {
-    logger.warn(
-      `Slow write request ${JSON.stringify({
-        requestTime: diffInMs,
-        pathName,
-        url: req.originalUrl,
-      })}`
-    );
+  if (options.logSlowRequests) {
+    if (diffInMs > slowReadMs && req.method === "GET") {
+      logger.warn(
+        `Slow GET request, ${JSON.stringify({
+          requestTime: diffInMs,
+          pathName,
+          url: req.originalUrl,
+        })}`
+      );
+    } else if (diffInMs > slowWriteMs) {
+      logger.warn(
+        `Slow write request ${JSON.stringify({
+          requestTime: diffInMs,
+          pathName,
+          url: req.originalUrl,
+        })}`
+      );
+    }
   }
 };
 
@@ -174,7 +182,9 @@ interface InitializeRoutesOptions {
   // Whether requests should be logged. In production, you may want to disable this if using another
   // logger (e.g. Google Cloud).
   logRequests?: boolean;
+  // Whether to ignore certain traces when logging to Sentry.
   ignoreTraces?: string[];
+  loggingOptions?: LoggingOptions;
 }
 
 function initializeRoutes(
@@ -195,6 +205,12 @@ function initializeRoutes(
     },
   });
 
+  // Store the logging options on the request so we can access them later.
+  app.use((req, _, next) => {
+    (req as any).loggingOptions = options.loggingOptions;
+    next();
+  });
+
   // TODO: Log a warning when we hit the array limit.
   app.set("query parser", (str: string) => qs.parse(str, {arrayLimit: options.arrayLimit ?? 200}));
 
@@ -294,6 +310,7 @@ export function setupServer(options: SetupServerOptions) {
       corsOrigin: options.corsOrigin,
       addMiddleware: options.addMiddleware,
       ignoreTraces: options.ignoreTraces,
+      loggingOptions: options.loggingOptions,
     });
   } catch (e) {
     logger.error(`Error initializing routes: ${e}`);

src/logger.ts

@@ -80,6 +80,12 @@ export interface LoggingOptions {
   showConsoleTimestamps?: boolean;
   logDirectory?: string;
   logRequests?: boolean;
+  // Whether to log when requests are slow.
+  logSlowRequests?: boolean;
+  // The threshold in ms for logging slow requests. Defaults to 200ms for read requests.
+  logSlowRequestsReadMs?: number;
+  // The threshold in ms for logging slow requests. Defaults to 500ms for write requests.
+  logSlowRequestsWriteMs?: number;
 }
 
 export function setupLogging(options?: LoggingOptions) {