Modular: removes Morgan in favor of custom logging middleware

lib/appFactory.js

@@ -1,6 +1,6 @@
 const express = require('express');
 const path = require('path');
-const logger = require('morgan');
+const { loggingMiddleware } = require('./logger');
 const indexRouter = require('./routes/index');
 const signupRouter = require('./routes/signup');
 const webFingerRouter = require('./routes/webfinger');
@@ -26,7 +26,7 @@ module.exports = function ({ hostIdentity, jwtSecret, account, store, basePath =
 
   app.set('account', account);
 
-  app.use(logger('dev'));
+  app.use(loggingMiddleware);
   app.use(helmet({
     contentSecurityPolicy: {
       directives: {
@@ -73,9 +73,10 @@ module.exports = function ({ hostIdentity, jwtSecret, account, store, basePath =
 
   // error handler
   app.use(function (err, req, res, _next) {
+    const message = err?.message || err?.errors?.find(e => e.message).message || err?.cause?.message || 'indescribable error';
     errorPage(req, res, err.status || 500, {
-      title: shorten(err.message, 30),
-      message: err.message,
+      title: shorten(message, 30),
+      message,
       error: req.app.get('env') === 'development' ? err : {}
     });
   });

lib/logger.js

@@ -90,14 +90,29 @@ function getLogger () {
   return logger;
 }
 
+function loggingMiddleware (req, res, next) {
+  res.logNotes = new Set();
+  res.on('finish', () => {
+    logRequest(req, req.data?.username || req.params?.username || '-', res.statusCode,
+      res._contentLength ?? res.get('Content-Length') ?? '-', Array.from(res.logNotes).join(' '), res.logLevel);
+  });
+  next();
+}
+
 function logRequest (req, username, status, numBytesWritten, logNote, logLevel) {
   let level;
   if (logLevel) {
     level = logLevel;
+  } else if ([502, 504, 507].includes(status)) { // Bad Gateway, Gateway Timeout, Insufficient Storage
+    level = 'error'; // problem with backing store
+  } else if (status === 503) { // Service Unavailable
+    level = 'warning';
   } else if (!status || status >= 500) { // presumably a coding error
     level = 'crit';
-  } else if ([401].includes(status)) { // user authentication is notable
+  } else if ([401, 201].includes(status)) { // user authentication & blob creation are notable
     level = 'notice';
+  } else if (req.originalUrl === '/favicon.ico') { // browsers request this too often
+    level = 'debug';
   } else if (status >= 400) { // client error
     level = 'warning';
   } else if ([302, 307, 308].includes(status)) { // redirects are boring
@@ -110,7 +125,7 @@ function logRequest (req, username, status, numBytesWritten, logNote, logLevel)
 
   const appHost = getOriginator(req);
 
-  let line = `${clientAddress} ${appHost} ${username} ${req.method} ${req.url} ${status} ${numBytesWritten}`;
+  let line = `${clientAddress} ${appHost} ${username} ${req.method} ${req.originalUrl ?? req.url} ${status} ${numBytesWritten}`;
   if (logNote) {
     if (logNote instanceof Error) {
       logNote = logNote.message || logNote.code || logNote.name || logNote.toString();
@@ -120,4 +135,4 @@ function logRequest (req, username, status, numBytesWritten, logNote, logLevel)
   logger.log(level, line);
 }
 
-module.exports = { configureLogger, getLogger, logRequest };
+module.exports = { configureLogger, getLogger, loggingMiddleware, logRequest };

lib/middleware/redirectToSSL.js

@@ -1,6 +1,5 @@
 const isSecureRequest = require('../util/isSecureRequest');
 const { getHost } = require('../util/getHost');
-const { logRequest } = require('../logger');
 
 /** redirects to HTTPS server if needed */
 module.exports = function redirectToSSL (req, res, next) {
@@ -11,6 +10,6 @@ module.exports = function redirectToSSL (req, res, next) {
   const host = getHost(req).split(':')[0] + (req.app.get('httpsPort') ? ':' + req.app.get('httpsPort') : '');
   const newUrl = 'https://' + host + req.url;
 
+  res.logNotes.add('-> ' + newUrl);
   res.redirect(302, newUrl);
-  logRequest(req, '-', 302, 0, '-> ' + newUrl);
 };

lib/middleware/sanityCheckUsername.js

@@ -1,13 +1,10 @@
-const { logRequest } = require('../logger');
-
 /** sanity check of username, to defend against ".." and whatnot */
 module.exports = function sanityCheckUsername (req, res, next) {
   const username = req.params.username || req.data.username || '';
   if (username.length > 0 && !/\/|^\.+$/.test(username) && /[\p{Lu}\p{Ll}\p{Lt}\p{Lo}\p{Nd}]{1,63}/u.test(username)) {
     return next();
   }
 
-  res.status(400).type('text/plain').end();
-
-  logRequest(req, req.data.username, 400, 0, 'invalid user');
+  res.logNotes.add('invalid user');
+  res.status(400).end();
 };

lib/middleware/secureRequest.js

@@ -1,12 +1,11 @@
 const isSecureRequest = require('../util/isSecureRequest');
-const { logRequest } = require('../logger');
 
 /** ensures request is secure, if required */
 module.exports = function secureRequest (req, res, next) {
   if (isSecureRequest(req) || (process.env.NODE_ENV !== 'production' && !req.app.get('forceSSL'))) {
     return next();
   }
 
-  res.status(400).end(); // TODO: add an explanatory message
-  logRequest(req, '-', 400, 0, 'blocked insecure');
+  res.logNotes.add('blocked insecure');
+  res.status(400).type('text/plain').send('The request did not use HTTPS.');
 };

lib/routes/S3_store_handler.js

@@ -2,6 +2,7 @@
 
 /* eslint-env node */
 /* eslint-disable camelcase */
+const errToMessages = require('../util/errToMessages');
 const { createHash } = require('node:crypto');
 const express = require('express');
 const { posix } = require('node:path');
@@ -72,8 +73,8 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ
     }
     getLogger().info(`${endPoint} ${accessKey} has ${users.length} users: ` + users.join(', '));
     getLogger().info(`${endPoint} ${accessKey} has ${numOtherBuckets} buckets that are not accounts (don't end with “${userNameSuffix}”)`);
-  }).catch(err => { // it's really bad if storage can't be reached
-    getLogger().alert('while listing buckets:', err);
+  }).catch(err => { // it's bad if storage can't be reached
+    getLogger().alert(Array.from(errToMessages(err, new Set(['while listing buckets:']))).join(' '));
   });
 
   let pauseUntil = 0; // TODO: actually pause requests until this datetime.  How to test?
@@ -121,8 +122,9 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ
         } else if (['NotModified', '304'].includes(err.name) || err.$metadata?.httpStatusCode === 304) {
           return res.status(304).end();
         } else if (err.name === 'EndResponseError') {
-          getLogger().log(err.logLevel || 'info', err.statusCode, err.message, req.params.username, req.params[0]);
-          return res.status(err.statusCode).end();
+          res.logNotes.add(err.message);
+          res.logLevel = err.logLevel;
+          return res.status(err.statusCode).type('text/plain').send(err.message);
         } else {
           return next(Object.assign(err, { status: 502 }));
         }
@@ -187,8 +189,9 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ
           setPauseUntil(res.get('Retry-After'));
           return next(Object.assign(err, { status: err?.$metadata?.httpStatusCode || 502 }));
         } else if (err.name === 'EndResponseError') {
-          getLogger().log(err.logLevel || 'info', err.statusCode, err.message, req.params.username, req.params[0]);
-          return res.status(err.statusCode).end();
+          res.logNotes.add(err.message);
+          res.logLevel = err.logLevel;
+          return res.status(err.statusCode).type('text/plain').send(err.message);
         } else if (err.name === 'TimeoutError') {
           return res.status(504).end();
         } else if (err.$metadata?.httpStatusCode === 400 || ['400', 'NoSuchBucket'].includes(err.name)) {
@@ -232,10 +235,12 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ
           err.$metadata?.httpStatusCode === 403) {
           res.status(404).end();
         } else if (err.$metadata?.httpStatusCode === 400 || err.name === '400' || /\bBucket\b/.test(err.message)) {
+          errToMessages(err, res.logNotes);
           res.status(400).type('text/plain').send('A parameter value is bad');
         } else if (err.name === 'EndResponseError') {
-          getLogger().log(err.logLevel || 'info', err.statusCode, err.message, req.params.username, req.params[0]);
-          return res.status(err.statusCode).end();
+          res.logNotes.add(err.message);
+          res.logLevel = err.logLevel;
+          return res.status(err.statusCode).type('text/plain').send(err.message);
         } else {
           return next(Object.assign(err, { status: 502 }));
         }
@@ -254,7 +259,7 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ
    * @param {string} params.password
    * @returns {Promise<string>} name of bucket
    */
-  router.createUser = async function createUser (params) {
+  router.createUser = async function createUser (params, logNotes) {
     let { username, email, password } = params;
     username = username.trim();
 
@@ -307,7 +312,7 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ
           }
         }));
       } catch (err) {
-        getLogger().warning('Couldn\'t set bucket to expire old blob versions:', err);
+        errToMessages(err, logNotes.add('Couldn\'t set bucket to expire old blob versions:'));
       }
 
       const config = await core.hashPassword(password, null);
@@ -325,7 +330,6 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ
       if (err.name === 'BucketAlreadyOwnedByYou') {
         throw new Error(`Username “${username}” is already taken`, { cause: err });
       } else {
-        getLogger().error('while creating or configuring bucket', err);
         throw new Error('while creating or configuring bucket: ' + err, { cause: err });
       }
     }
@@ -336,7 +340,7 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ
    * @param username
    * @returns {Promise<number>} number of files deleted
    */
-  router.deleteUser = async function deleteUser (username) {
+  router.deleteUser = async function deleteUser (username, logNotes) {
     let numObjectsDeleted = 0;
     let numObjectsFailedToDelete = 0;
 
@@ -350,7 +354,7 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ
             /* const { DeleteMarker } = */ await s3client.send(new DeleteObjectCommand({ Bucket: bucketName, Key: item.Key, VersionId: item.VersionId }));
             ++numObjectsDeleted;
           } catch (err) {
-            console.warn('while deleting', bucketName, item.Key, item.VersionId, err);
+            errToMessages(err, logNotes.add('while deleting:').add(bucketName).add(item.Key).add(item.VersionId));
             ++numObjectsFailedToDelete;
           }
         }
@@ -402,7 +406,7 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ
    * @returns {Promise<boolean>} true if correct
    * @throws if user doesn't exist, password doesn't match, or any error
    */
-  router.authenticate = async function authenticate ({ username, password }) {
+  router.authenticate = async function authenticate ({ username, password }, logNotes) {
     let storedKey, presentedKey;
     try {
       const bucketName = calcBucketName(username);
@@ -412,9 +416,11 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ
       presentedKey = (await core.hashPassword(password, storedConfig)).key;
     } catch (err) {
       if (err.name === 'NoSuchBucket') {
-        getLogger().info(`attempt to log in with nonexistent user “${username}”`);
+        errToMessages(err, logNotes.add(`attempt to log in with nonexistent user “${username}”`));
+        // can't set log level to 'info'
       } else {
-        getLogger().error(`while validating password for “${username}”:`, err);
+        errToMessages(err, logNotes.add(`while validating password for “${username}”:`));
+        // can't set log level to 'error'
       }
       throw new Error('Password and username do not match');
     }
@@ -570,7 +576,7 @@ module.exports = function (endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SPQQ
       });
       // Upload allows you to pass ContentLength, but then fails for streams longer than about 5.1MB, with a message about XML.
 
-      parallelUpload.on('httpUploadProgress', (progress) => {
+      parallelUpload.on('httpUploadProgress', (progress) => { // TODO: does this add value?
         console.debug(bucketName, s3Path, `part ${progress.part}   ${progress.loaded?.toLocaleString()} / ${progress.total?.toLocaleString()} bytes`);
       });
 

lib/routes/oauth.js

@@ -1,12 +1,12 @@
 /* eslint-env node */
 /* eslint-disable camelcase */
+const errToMessages = require('../util/errToMessages');
 const express = require('express');
 const formOrQueryData = require('../middleware/formOrQueryData');
 const redirectToSSL = require('../middleware/redirectToSSL');
 const sanityCheckUsername = require('../middleware/sanityCheckUsername');
 const secureRequest = require('../middleware/secureRequest');
 const jwt = require('jsonwebtoken');
-const { logRequest, getLogger } = require('../logger');
 const qs = require('querystring');
 
 const accessStrings = { r: 'Read', rw: 'Read/write' };
@@ -31,7 +31,6 @@ module.exports = function (hostIdentity, jwtSecret) {
         username: req.params.username,
         access_strings: accessStrings
       });
-      logRequest(req, req.params.username, 200);
     });
 
   router.post('/',
@@ -44,11 +43,11 @@ module.exports = function (hostIdentity, jwtSecret) {
       const username = locals.username.split('@')[0];
 
       if (locals.deny) {
-        return error(req, res, 'access_denied', 'The user did not grant permission');
+        return error(req, res, 'access_denied', 'The user did not grant permission to');
       }
 
       try {
-        await req.app.get('account').authenticate({ username, password: locals.password });
+        await req.app.get('account').authenticate({ username, password: locals.password }, res.logNotes);
         let redirectOrigin;
         try {
           redirectOrigin = new URL(req.data.redirect_uri).origin;
@@ -69,7 +68,7 @@ module.exports = function (hostIdentity, jwtSecret) {
           jwtSecret,
           { algorithm: 'HS512', issuer: hostIdentity, audience: redirectOrigin, subject: username, expiresIn: '30d' }
         );
-        getLogger().info(`created JWT for ${username} on ${redirectOrigin} w/ scope ${locals.scope}`);
+        res.logNotes.add(`created JWT for ${username} on ${redirectOrigin} w/ scope ${locals.scope}`);
         const args = {
           access_token: token,
           token_type: 'bearer',
@@ -84,8 +83,8 @@ module.exports = function (hostIdentity, jwtSecret) {
         locals.access_strings = accessStrings;
         locals.state = locals.state || '';
 
+        errToMessages(error, res.logNotes);
         res.status(401).render('auth.html', locals);
-        logRequest(req, req.params.username, 401);
       }
     }
   );
@@ -117,24 +116,25 @@ module.exports = function (hostIdentity, jwtSecret) {
 
   function error (req, res, error, error_description) {
     redirect(req, res, { error, error_description },
-      `${req.data.username} ${error_description} ${req.data.client_id}`);
+      `${error_description} ${req.data.client_id}`);
   }
 
   function redirect (req, res, args, logNote) {
     const hash = qs.stringify(args);
     if (req.data.redirect_uri) {
       const location = req.data.redirect_uri + '#' + hash;
-      res.redirect(location);
 
       if (logNote) {
-        logRequest(req, req.data.username || '-', 302, 0, logNote, 'warning');
+        res.logNotes.add(logNote);
+        res.logLevel = 'warning';
       } else {
-        logRequest(req, req.data.username || '-', 302, 0, '-> ' + req.data.redirect_uri, 'notice');
+        res.logNotes.add('-> ' + req.data.redirect_uri);
+        res.logLevel = 'notice';
       }
+      res.redirect(location);
     } else {
+      res.logNotes.add(logNote || args?.error_description || 'no redirect_uri');
       res.status(400).type('text/plain').send(hash);
-      logRequest(req, req.data.username || '-', 400, hash.length,
-        logNote || args?.error_description || 'no redirect_uri');
     }
   }
 

lib/routes/signup.js

@@ -1,8 +1,8 @@
 const express = require('express');
 const router = express.Router();
 const { getHost } = require('../util/getHost');
+const errToMessages = require('../util/errToMessages');
 const errorPage = require('../util/errorPage');
-const { getLogger } = require('../logger');
 
 const DISABLED_LOCALS = { title: 'Forbidden', message: 'Signing up is not allowed currently' };
 const DISABLED_LOG_NOTE = 'signups disabled';
@@ -26,19 +26,20 @@ router.post('/',
   async function (req, res) {
     if (req.app?.locals?.signup) {
       try {
-        const storageName = await req.app?.get('account').createUser(req.body);
-        getLogger().notice(`created storage “${storageName}” for user “${req.body.username}”`);
+        const storageName = await req.app?.get('account').createUser(req.body, res.logNotes);
+        res.logNotes.add(`created storage “${storageName}” for user “${req.body.username}”`);
         res.status(201).render('signup-success.html', {
           title: 'Signup Success',
           params: req.body,
           host: getHost(req)
         });
       } catch (err) {
-        getLogger().error(`while creating user “${req.body?.username}”`, err);
+        errToMessages(err, res.logNotes.add(`while creating user “${req.body?.username}”:`));
+        const errChain = [err, ...(err.errors || []), ...(err.cause ? [err.cause] : []), new Error('indescribable error')];
         res.status(409).render('signup.html', {
           title: 'Signup Failure',
           params: req.body,
-          error: err,
+          error: errChain.find(e => e.message),
           host: getHost(req)
         });
       }