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

@@ -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();
+}

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"