feat(log): do not log 'pre' request log unless configured to do so

Author: djMax

config/config.json

@@ -2,7 +2,8 @@
   "$schema": "tsschema://../src/config/schema#ConfigurationSchema",
   "logging": {
     "level": "info",
-    "logRequestBody": "env_switch:LOG_HTTP_REQUESTS"
+    "logRequestBody": "env_switch:LOG_HTTP_REQUESTS",
+    "preLog": "env_switch:HTTP_PRE_LOG"
   },
   "routing": {
     "openapi": true,

package.json

@@ -91,31 +91,31 @@
     "lodash": "^4.17.21",
     "minimist": "^1.2.8",
     "opentelemetry-instrumentation-fetch-node": "^1.1.0",
-    "pino": "^8.16.0",
+    "pino": "^8.16.1",
     "read-pkg-up": "^7.0.1"
   },
   "devDependencies": {
-    "@commitlint/cli": "^18.0.0",
-    "@commitlint/config-conventional": "^18.0.0",
+    "@commitlint/cli": "^18.2.0",
+    "@commitlint/config-conventional": "^18.1.0",
     "@openapi-typescript-infra/coconfig": "^4.2.2",
     "@semantic-release/changelog": "^6.0.3",
-    "@semantic-release/commit-analyzer": "^11.0.0",
+    "@semantic-release/commit-analyzer": "^11.1.0",
     "@semantic-release/exec": "^6.0.3",
     "@semantic-release/git": "^10.0.1",
-    "@semantic-release/release-notes-generator": "^12.0.0",
+    "@semantic-release/release-notes-generator": "^12.1.0",
     "@types/cookie-parser": "^1.4.5",
     "@types/express": "^4.17.20",
     "@types/glob": "^8.1.0",
     "@types/lodash": "^4.14.200",
     "@types/minimist": "^1.2.4",
-    "@types/node": "^20.8.7",
+    "@types/node": "^20.8.10",
     "@types/supertest": "^2.0.15",
-    "@typescript-eslint/eslint-plugin": "^6.8.0",
-    "@typescript-eslint/parser": "^6.8.0",
+    "@typescript-eslint/eslint-plugin": "^6.10.0",
+    "@typescript-eslint/parser": "^6.10.0",
     "coconfig": "^1.0.0",
-    "eslint": "^8.52.0",
+    "eslint": "^8.53.0",
     "eslint-config-prettier": "^9.0.0",
-    "eslint-plugin-import": "^2.28.1",
+    "eslint-plugin-import": "^2.29.0",
     "pino-pretty": "^10.2.3",
     "pinst": "^3.0.0",
     "supertest": "^6.3.3",

src/config/schema.ts

@@ -11,6 +11,9 @@ export interface ConfigurationSchema extends BaseConfitSchema {
     level?: Level;
     logRequestBody?: boolean;
     logResponseBody?: boolean;
+    // Whether to log a "pre" message when request processing starts. Most useful in
+    // situations where there is some problem causing requests to hang
+    preLog?: boolean;
   };
   routing?: {
     openapi?: boolean;

src/express-app/app.ts

@@ -124,7 +124,7 @@ export async function startApp<
     description: 'Duration of HTTP requests in seconds',
   });
 
-  app.use(loggerMiddleware(app, histogram, logging?.logRequestBody, logging?.logResponseBody));
+  app.use(loggerMiddleware(app, histogram, logging));
 
   // Allow the service to add locals, etc. We put this before the body parsers
   // so that the req can decide whether to save the raw request body or not.

src/telemetry/requestLogger.ts

@@ -108,21 +108,20 @@ export function loggerMiddleware<
 >(
   app: ServiceExpress<SLocals>,
   histogram: Histogram,
-  logRequests?: boolean,
-  logResponses?: boolean,
+  config?: ConfigurationSchema['logging'],
 ): RequestHandler {
   const { logger, service } = app.locals;
   return function gblogger(req, res, next) {
     const prefs: LogPrefs = {
       start: process.hrtime(),
-      logRequests,
-      chunks: logResponses ? [] : undefined,
+      logRequests: config?.logRequestBody,
+      chunks: config?.logResponseBody ? [] : undefined,
       logged: false,
     };
 
     (res.locals as WithLogPrefs)[LOG_PREFS] = prefs;
 
-    if (logResponses) {
+    if (config?.logResponseBody) {
       // res is a read-only stream, so the only way to intercept response
       // data is to monkey-patch.
       const oldWrite = res.write;
@@ -141,14 +140,16 @@ export function loggerMiddleware<
       }) as (typeof res)['end'];
     }
 
-    const preLog: Record<string, string | string[] | number | undefined> = {
-      ...getBasicInfo(req),
-      ref: req.headers.referer || undefined,
-      sid: (req as WithIdentifiedSession).session?.id,
-      c: req.headers.correlationid || undefined,
-    };
-    service.getLogFields?.(req as RequestWithApp<SLocals>, preLog);
-    logger.info(preLog, 'pre');
+    if (config?.preLog) {
+      const preLog: Record<string, string | string[] | number | undefined> = {
+        ...getBasicInfo(req),
+        ref: req.headers.referer || undefined,
+        sid: (req as WithIdentifiedSession).session?.id,
+        c: req.headers.correlationid || undefined,
+      };
+      service.getLogFields?.(req as RequestWithApp<SLocals>, preLog);
+      logger.info(preLog, 'pre');
+    }
 
     const logWriter = () => finishLog(app, undefined, req, res, histogram);
     res.on('finish', logWriter);