From 9dbee59746125a0a1f9e066e813644e780c54919 Mon Sep 17 00:00:00 2001
From: Jose Bolos <joseluisbolos@gmail.com>
Date: Mon, 7 Mar 2022 18:35:25 +0000
Subject: [PATCH] Add request logging using morgan

This commit adds request logging to the app using morgan.

Every request will now be logged not one but twice: one when the request is received, and a second time when the response is sent.

The response logging also prints out the time elapsed in processing the request, which will be useful to debug performance issues (calls to the dashboard home are currently taking 4 - 15s on a populated database).

The new code uses a tiny middleware that uses nanoid to generate a random request id that can be used to match requests in the logs.

This logging will help us determine which requests are successful, which requests are slow, and establish what requests may have contributed to causing an application crash, making future debugging easier.
---
 app.js       | 30 ++++++++++++++++++++++++++++++
 package.json |  2 ++
 2 files changed, 32 insertions(+)

diff --git a/app.js b/app.js
index f95024d..fc9a427 100644
--- a/app.js
+++ b/app.js
@@ -20,6 +20,8 @@ const createClient = require('pa11y-webservice-client-node');
 const EventEmitter = require('events').EventEmitter;
 const express = require('express');
 const hbs = require('express-hbs');
+const morgan = require('morgan');
+const {nanoid} = require('nanoid');
 const http = require('http');
 const pkg = require('./package.json');
 
@@ -68,6 +70,24 @@ function loadMiddleware(app) {
 	// Compression
 	app.express.use(compression());
 
+	// Adds an ID to every request, used later for logging
+	app.express.use(addRequestId);
+
+	// Logging middleware
+	morgan.token('id', request => {
+		return request.id;
+	});
+
+	// Log the start of all HTTP requests
+	const startLog = '[:date[iso] #:id] Started :method :url for :remote-addr';
+	// Immediate: true is required to log the request
+	//  before the response happens
+	app.express.use(morgan(startLog, {immediate: true}));
+
+	// Log the end of all HTTP requests
+	const endLog = '[:date[iso] #:id] Completed :status :res[content-length] in :response-time ms';
+	app.express.use(morgan(endLog));
+
 	// Public files
 	app.express.use(express.static(`${__dirname}/public`, {
 		maxAge: (process.env.NODE_ENV === 'production' ? 604800000 : 0)
@@ -164,3 +184,13 @@ function loadErrorHandling(app, config, callback) {
 		callback(error, app);
 	});
 }
+
+// Express middleware
+function addRequestId(request, response, next) {
+	// Create a random request (nano)id, 10 characters long
+	// Nano ids are [0-9A-Za-z_-] so chance of collision is 1 in 64^10
+	// If a site has so much traffic that this chance is too high
+	//  we probably have worse things to worry about
+	request.id = nanoid(10);
+	next();
+}
diff --git a/package.json b/package.json
index db19a12..4bfe1c5 100644
--- a/package.json
+++ b/package.json
@@ -31,6 +31,8 @@
     "http-headers": "~3.0.2",
     "kleur": "~4.1.4",
     "moment": "~2.29.1",
+    "morgan": "~1.10.0",
+    "nanoid": "~3.3.1",
     "pa11y-webservice": "~4.0.0",
     "pa11y-webservice-client-node": "~3.0.0",
     "underscore": "~1.13.1"