Add pino logging (#3652)

* Add pino and related dependencies for logging

* Add pino and replace morgan with pino-http

* Address bunyan/pino interchangeability issues

* Use request logger in access-helpers middleware

packages/server/__tests__/lib/access-helpers.test.js

@@ -91,6 +91,8 @@ describe('Acces Helper Module', () => {
                     'user-agent': 'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36 Edg/117.0.2045.47 OneOutlook/1.2023.927.100',
                     'x-native-host': 'OneOutlook/1.2023.927.100',
                 },
+                // fake logging middleware:
+                log: { info: () => {} },
             };
             await isMicrosoftSafeLinksRequest(requestFake, resFake, nextFake);
             expect(resFake.json.calledOnceWith({ message: 'Success' })).to.equal(true);

packages/server/package.json

@@ -82,6 +82,8 @@
     "pdf-lib": "^1.16.0",
     "pg": "^8.7.1",
     "pg-types": "4.0.0",
+    "pino": "^9.5.0",
+    "pino-http": "^10.3.0",
     "ssf": "^0.11.2",
     "ts-invariant": "0.10.3",
     "uuid": "^8.3.2",
@@ -111,6 +113,7 @@
     "nodemon": "2.0.15",
     "nyc": "^15.1.0",
     "openapi-types": "^12.0.2",
+    "pino-pretty": "^11.3.0",
     "prettier": "2.6.1",
     "rewire": "^6.0.0",
     "sinon": "^14.0.0",

packages/server/src/arpa_reporter/configure.js

@@ -2,8 +2,8 @@ const bodyParser = require('body-parser');
 const cookieParser = require('cookie-parser');
 const express = require('express');
 const history = require('connect-history-api-fallback');
-const morgan = require('morgan');
 const { resolve } = require('path');
+const { log, createLoggerMiddleware } = require('../lib/logging');
 
 const environment = require('./environment');
 const agenciesRoutes = require('./routes/agencies');
@@ -32,9 +32,7 @@ function configureApiRoutes(app) {
 }
 
 function configureApp(app, options = {}) {
-    if (!options.disableRequestLogging) {
-        app.use(morgan('common'));
-    }
+    app.use(createLoggerMiddleware(log, options));
     app.use(bodyParser.json());
     app.use(cookieParser(environment.COOKIE_SECRET));
 

packages/server/src/arpa_reporter/lib/audit-report.js

@@ -4,7 +4,7 @@ const moment = require('moment');
 const { v4 } = require('uuid');
 const XLSX = require('xlsx');
 const { PutObjectCommand } = require('@aws-sdk/client-s3');
-const { log } = require('../../lib/logging');
+const { bunyanLogger: log } = require('../../lib/logging');
 const aws = require('../../lib/gost-aws');
 const { EXPENDITURE_CATEGORIES, currencyNumeric, ec } = require('./format');
 

packages/server/src/arpa_reporter/services/generate-arpa-report.js

@@ -8,7 +8,7 @@ const aws = require('../../lib/gost-aws');
 
 const { getUser } = require('../../db');
 const { applicationSettings } = require('../db/settings');
-const { log } = require('../../lib/logging');
+const { bunyanLogger: log } = require('../../lib/logging');
 const { listRecipientsForReportingPeriod } = require('../db/arpa-subrecipients');
 const { getTemplate } = require('./get-template');
 const email = require('../../lib/email');

packages/server/src/configure.js

@@ -4,9 +4,9 @@ require('express-async-errors');
 const express = require('express');
 const bodyParser = require('body-parser');
 const cookieParser = require('cookie-parser');
-const morgan = require('morgan');
 const history = require('connect-history-api-fallback');
 const { resolve } = require('path');
+const { log, createLoggerMiddleware } = require('./lib/logging');
 const { configureApiRoutes: configureArpaReporterApiRoutes } = require('./arpa_reporter/configure');
 const { requestProviderMiddleware } = require('./arpa_reporter/use-request');
 
@@ -27,21 +27,7 @@ function configureApiRoutes(app) {
 }
 
 function configureApp(app, options = {}) {
-    app.use(morgan('common', {
-        skip: (req) => {
-            // Render hits the health check path extremely often, so don't clutter logs with it.
-            if (req.originalUrl === '/api/health') {
-                return true;
-            }
-
-            // We disable request logging during API tests because it makes the Mocha test output noisy
-            if (options.disableRequestLogging) {
-                return true;
-            }
-
-            return false;
-        },
-    }));
+    app.use(createLoggerMiddleware(log, options));
     app.use(cookieParser(process.env.COOKIE_SECRET));
     app.use(bodyParser.json());
     app.use(bodyParser.urlencoded({ extended: true }));

packages/server/src/lib/access-helpers.js

@@ -1,6 +1,5 @@
 const tracer = require('dd-trace');
 const { getUser, inTenant } = require('../db');
-const { log } = require('./logging');
 
 const USDR_TENANT_ID = 1;
 const USDR_AGENCY_ID = 0;
@@ -150,7 +149,7 @@ async function isMicrosoftSafeLinksRequest(req, res, next) {
     const userAgent = req.headers['user-agent'] || '';
     const nativeHost = req.headers['x-native-host'] || '';
     if (userAgent.toLowerCase().includes('oneoutlook') || nativeHost.toLowerCase().includes('oneoutlook')) {
-        log.info({
+        req.log.info({
             'user-agent': userAgent,
             'native-host': nativeHost,
             headers: Object.keys(req.headers),

packages/server/src/lib/logging.js

@@ -1,5 +1,8 @@
 const tracer = require('dd-trace').init(); // eslint-disable-line no-unused-vars
+const { randomUUID } = require('node:crypto');
 const bunyan = require('bunyan');
+const { pino } = require('pino');
+const { pinoHttp } = require('pino-http');
 
 // Default to INFO logs and above, unless a valid level name is provided by $LOG_LEVEL.
 const logLevel = bunyan.levelFromName[(process.env.LOG_LEVEL || '').toLowerCase()] || bunyan.levelFromName.info;
@@ -13,9 +16,59 @@ if (process.env.LOG_SRC_ENABLED === 'true' || process.env.LOG_SRC_ENABLED === '1
     logSrc = false;
 }
 
-module.exports.log = bunyan.createLogger({
-    name: process.env.LOG_NAME || 'gost',
-    level: logLevel,
-    src: logSrc,
-    serializers: { err: bunyan.stdSerializers.err },
-});
+/**
+ * Creates a new pino logger with standard configuration defaults
+ * @returns pino
+ */
+function createLogger(options = {}) {
+    return pino({
+        name: process.env.LOG_NAME || 'gost',
+        level: (process.env.LOG_LEVEL || 'info').toLowerCase(),
+        formatters: {
+            level(level) {
+                return { level };
+            },
+        },
+        ...options,
+    });
+}
+
+function createLoggerMiddleware(logger, appOptions = {}) {
+    return pinoHttp({
+        logger,
+        autoLogging: {
+            ignore: (req) => {
+                // Don't output auto-logs for health checks
+                if (req.originalUrl === '/api/health') {
+                    return true;
+                }
+                // Disable if explicitly requested, such as during tests
+                if (appOptions?.disableRequestLogging) {
+                    return true;
+                }
+                return false;
+            },
+        },
+        genReqId: (req) => (req.id ?? req.headers['x-amzn-trace-id'] ?? req.headers['x-request-id'] ?? randomUUID()),
+        serializers: {
+            req: (req) => {
+                const queryStart = req.url.lastIndexOf('?');
+                const path = queryStart > -1 ? req.url.substring(0, queryStart) : req.url;
+                return { id: req.id, method: req.method, path };
+            },
+            res: (res) => ({ statusCode: res.statusCode }),
+        },
+    });
+}
+
+module.exports = {
+    createLogger,
+    createLoggerMiddleware,
+    log: createLogger(),
+    bunyanLogger: bunyan.createLogger({
+        name: process.env.LOG_NAME || 'gost',
+        level: logLevel,
+        src: logSrc,
+        serializers: { err: bunyan.stdSerializers.err },
+    }),
+};