fix(reqLogger): prevent destroyed socket race

Author: jasisk

src/telemetry/requestLogger.ts

@@ -1,16 +1,27 @@
-import type { RequestHandler, Request, Response, ErrorRequestHandler } from 'express';
-import { getClientIp } from 'request-ip';
-import type { Histogram } from '@opentelemetry/api';
-import cleanStack from 'clean-stack';
+import type {
+  RequestHandler,
+  Request,
+  Response,
+  ErrorRequestHandler,
+} from "express";
+import { getClientIp } from "request-ip";
+import type { Histogram } from "@opentelemetry/api";
+import cleanStack from "clean-stack";
 
-import { ServiceError } from '../error.js';
-import type { AnyServiceLocals, RequestWithApp, ServiceExpress, ServiceLocals } from '../types.js';
-import type { ServiceHandler } from '../express-app/types.js';
-import type { ConfigurationSchema } from '../config/schema.js';
-import { getNodeEnv } from '../env.js';
+import { ServiceError } from "../error.js";
+import type {
+  AnyServiceLocals,
+  RequestWithApp,
+  ServiceExpress,
+  ServiceLocals,
+} from "../types.js";
+import type { ServiceHandler } from "../express-app/types.js";
+import type { ConfigurationSchema } from "../config/schema.js";
+import { getNodeEnv } from "../env.js";
 
-const LOG_PREFS = Symbol('Logging information');
-const LOGGED_SEMAPHORE = Symbol('Logged semaphore');
+const LOG_PREFS = Symbol("Logging information");
+const LOGGED_SEMAPHORE = Symbol("Logged semaphore");
+const SUCCESS_SEMAPHORE = Symbol("Response finished semaphore");
 
 interface LogPrefs {
   start: [number, number];
@@ -38,12 +49,12 @@ function getBasicInfo(req: Request): [string, Record<string, string | number>] {
   const url = req.originalUrl || req.url;
 
   const preInfo: Record<string, string> = {
-    ip: getClientIp(req) || '',
+    ip: getClientIp(req) || "",
     m: req.method,
   };
 
-  if (req.headers['user-agent']) {
-    preInfo.ua = req.headers['user-agent'];
+  if (req.headers["user-agent"]) {
+    preInfo.ua = req.headers["user-agent"];
   }
 
   const sessionReq = req as WithIdentifiedSession;
@@ -54,7 +65,9 @@ function getBasicInfo(req: Request): [string, Record<string, string | number>] {
   return [url, preInfo];
 }
 
-function finishLog<SLocals extends AnyServiceLocals = ServiceLocals<ConfigurationSchema>>(
+function finishLog<
+  SLocals extends AnyServiceLocals = ServiceLocals<ConfigurationSchema>,
+>(
   app: ServiceExpress<SLocals>,
   error: Error | undefined,
   req: Request,
@@ -80,20 +93,22 @@ function finishLog<SLocals extends AnyServiceLocals = ServiceLocals<Configuratio
   }
   const [url, preInfo] = getBasicInfo(req);
 
-  let responseType = 'finished';
+  let responseType = "unknown";
 
   // ts warning is known and incorrect—`aborted` is a subset of `destroyed`
-  if (req.aborted) {
-    responseType = 'aborted';
+  if (res[SUCCESS_SEMAPHORE]) {
+    responseType = "finished";
+  } else if (req.aborted) {
+    responseType = "aborted";
   } else if (req.destroyed) {
-    responseType = 'destroyed';
+    responseType = "destroyed";
   } else if (error) {
-    responseType = 'errored';
+    responseType = "errored";
   }
 
   const endLog: Record<string, string | string[] | number | undefined> = {
     ...preInfo,
-    t: 'req',
+    t: "req",
     r: responseType,
     s: (error as ErrorWithStatus)?.status || res.statusCode || 0,
     dur,
@@ -125,21 +140,22 @@ function finishLog<SLocals extends AnyServiceLocals = ServiceLocals<Configuratio
   if (prefs.logRequests) {
     endLog.h = JSON.stringify(req.headers);
     if (Buffer.isBuffer(req.body)) {
-      endLog.b = req.body.toString('base64');
-    } else if (typeof req.body !== 'string') {
+      endLog.b = req.body.toString("base64");
+    } else if (typeof req.body !== "string") {
       endLog.b = JSON.stringify(req.body);
     } else if (req.body) {
       endLog.b = req.body;
     }
   }
 
   if (prefs.chunks?.length) {
-    const bodyString = Buffer.concat(prefs.chunks).toString('utf8');
+    const bodyString = Buffer.concat(prefs.chunks).toString("utf8");
     if (bodyString) {
       endLog.resBody = bodyString;
     }
   }
-  const msg = service.getLogFields?.(req as RequestWithApp<SLocals>, endLog) || url;
+  const msg =
+    service.getLogFields?.(req as RequestWithApp<SLocals>, endLog) || url;
   if (unexpectedError) {
     logger.error(endLog, msg);
   } else {
@@ -154,14 +170,17 @@ export function loggerMiddleware<
 >(
   app: ServiceExpress<SLocals>,
   histogram: Histogram,
-  config?: ConfigurationSchema['logging'],
+  config?: ConfigurationSchema["logging"],
 ): RequestHandler {
-  const nonProd = getNodeEnv() !== 'production';
+  const nonProd = getNodeEnv() !== "production";
   const { logger, service } = app.locals;
   return function serviceLogger(req, res, next) {
     const logResponse =
-      config?.logResponseBody || (nonProd && req.headers['x-log']?.includes('res'));
-    const logRequest = config?.logRequestBody || (nonProd && req.headers['x-log']?.includes('req'));
+      config?.logResponseBody ||
+      (nonProd && req.headers["x-log"]?.includes("res"));
+    const logRequest =
+      config?.logRequestBody ||
+      (nonProd && req.headers["x-log"]?.includes("req"));
     const prefs: LogPrefs = {
       start: process.hrtime(),
       logRequests: logRequest,
@@ -176,44 +195,57 @@ export function loggerMiddleware<
       // data is to monkey-patch.
       const oldWrite = res.write;
       const oldEnd = res.end;
-      res.write = ((...args: Parameters<(typeof res)['write']>) => {
+      res.write = ((...args: Parameters<(typeof res)["write"]>) => {
         if (prefs.chunks) {
-          prefs.chunks.push(Buffer.isBuffer(args[0]) ? args[0] : Buffer.from(args[0] as string));
+          prefs.chunks.push(
+            Buffer.isBuffer(args[0]) ? args[0] : Buffer.from(args[0] as string),
+          );
         }
-        return (oldWrite as (typeof res)['write']).apply(res, args);
-      }) as (typeof res)['write'];
-      res.end = ((...args: Parameters<(typeof res)['end']>) => {
+        return (oldWrite as (typeof res)["write"]).apply(res, args);
+      }) as (typeof res)["write"];
+      res.end = ((...args: Parameters<(typeof res)["end"]>) => {
         if (args[0] && prefs.chunks) {
-          prefs.chunks.push(Buffer.isBuffer(args[0]) ? args[0] : Buffer.from(args[0] as string));
+          prefs.chunks.push(
+            Buffer.isBuffer(args[0]) ? args[0] : Buffer.from(args[0] as string),
+          );
         }
         return oldEnd.apply(res, args);
-      }) as (typeof res)['end'];
+      }) as (typeof res)["end"];
     }
 
     if (config?.preLog) {
       const [url, preInfo] = getBasicInfo(req);
       const preLog: Record<string, string | string[] | number | undefined> = {
         ...preInfo,
-        t: 'pre',
+        t: "pre",
         ref: req.headers.referer || undefined,
         sid: (req as WithIdentifiedSession).session?.id,
         c: req.headers.correlationid || undefined,
       };
-      const msg = service.getLogFields?.(req as RequestWithApp<SLocals>, preLog) || url;
+      const msg =
+        service.getLogFields?.(req as RequestWithApp<SLocals>, preLog) || url;
       logger.info(preLog, msg);
     }
 
     const logWriter = (err?: Error) => finishLog(app, err, req, res, histogram);
-    res.on('finish', logWriter);
-    res.on('close', logWriter);
-    res.on('error', logWriter);
+    res.on("finish", (err?: Error) => {
+      res[SUCCESS_SEMAPHORE] = true;
+      logWriter(err);
+    });
+    res.on("close", logWriter);
+    res.on("error", logWriter);
     next();
   };
 }
 
 export function errorHandlerMiddleware<
   SLocals extends AnyServiceLocals = ServiceLocals<ConfigurationSchema>,
->(app: ServiceExpress<SLocals>, histogram: Histogram, unnest?: boolean, returnError?: boolean) {
+>(
+  app: ServiceExpress<SLocals>,
+  histogram: Histogram,
+  unnest?: boolean,
+  returnError?: boolean,
+) {
   const svcErrorHandler: ErrorRequestHandler = (error, req, res, next) => {
     let loggable: Partial<ServiceError> = error;
     const body = error.response?.body || error.body;
@@ -249,11 +281,15 @@ export function errorHandlerMiddleware<
 
 export function notFoundMiddleware() {
   const serviceNotFoundHandler: ServiceHandler = (req, res, next) => {
-    const error = new ServiceError(req.app, `Cannot ${req.method} ${req.path}`, {
-      status: 404,
-      code: 'NotFound',
-      domain: 'http',
-    });
+    const error = new ServiceError(
+      req.app,
+      `Cannot ${req.method} ${req.path}`,
+      {
+        status: 404,
+        code: "NotFound",
+        domain: "http",
+      },
+    );
     next(error);
   };
   return serviceNotFoundHandler as RequestHandler;