Modular server: improves logging

Author: DougReeder

bin/www

@@ -1,15 +1,14 @@
 #!/usr/bin/env node
 
-const http = require('http');
-const fs = require("fs");
-const path = require("path");
+const http = require('node:http');
+const fs = require("node:fs");
+const path = require("node:path");
 const {ArgumentParser} = require("argparse");
-const { stat } = require('node:fs/promises');
 const appFactory = require('../lib/appFactory');
 const {configureLogger, getLogger} = require("../lib/logger");
 const S3StoreRouter = require("../lib/routes/S3_store_router");
-const process = require("process");
-const https = require("https");
+const process = require("node:process");
+const https = require("node:https");
 const errToMessages = require("../lib/util/errToMessages");
 
 const SSL_CIPHERS = 'ECDHE-RSA-AES256-SHA384:AES256-SHA256:RC4-SHA:RC4:HIGH:!MD5:!aNULL:!EDH:!AESGCM';
@@ -82,7 +81,10 @@ async function start(network) {
 
   if (conf.trust_proxy) {
     app.set('trust proxy', conf.trust_proxy);
+  } else if (process.env.NODE_ENV === 'production') {
+    app.set('trust proxy', 'loopback'); // required for secure cookies + session
   }
+  getLogger().info(`trust proxy: ${app.get('trust proxy')}`);
 
   app.locals.title = "Modular Armadietto";
   // Before rendering, `locals.host` should be set to `getHost(req)`
@@ -222,7 +224,10 @@ function clientError (err, socket) {
     message = 'Bad Request';
   }
   const logNotes = errToMessages(err, new Set([message]));
-  getLogger().warning(`- - - - - ${status} - “${Array.from(logNotes).join(' ')}”`);
+  if (Number.isFinite(err.bytesParsed)) {
+    logNotes.add(`${err.bytesParsed} bytes parsed`);
+  }
+  getLogger().warning(`${socket.address?.()?.address || '-'} - - - - ${status} - «${Array.from(logNotes).join(' ')}»`);
 
   if (err.code !== 'ECONNRESET' && socket.writable) {
     socket.end(`HTTP/1.1 ${status} ${message}\r\n\r\n`);

lib/appFactory.js

@@ -42,6 +42,7 @@ module.exports = async function ({ hostIdentity, jwtSecret, accountMgr, storeRou
 
   if (process.env.NODE_ENV === 'production') {
     app.use(rateLimiterMiddleware);
+    getLogger().info('rateLimiterMiddleware enabled');
   }
 
   // web browsers ask for this way too often, so doesn't log this
@@ -140,10 +141,6 @@ module.exports = async function ({ hostIdentity, jwtSecret, accountMgr, storeRou
     saveUninitialized: false,
     name: 'id'
   });
-  if (process.env.NODE_ENV === 'production' && !app.get('trust proxy')) {
-    app.set('trust proxy', 'loopback'); // required for secure cookies
-  }
-  getLogger().info(`trust proxy: ${app.get('trust proxy')}`);
 
   app.use([`${basePath}/`, `${basePath}/oauth`, `${basePath}/account`, `${basePath}/admin`], memorySession);
 

lib/middleware/rateLimiterMiddleware.js

@@ -8,6 +8,8 @@
 // the capacity of all the instances. (Rate-limits are enforced
 // per-instance.)
 
+const { debuglog } = require('node:util');
+const { loggingMiddleware } = require('../logger');
 const { RateLimiterMemory, BurstyRateLimiter } = require('rate-limiter-flexible');
 
 const POINTS_AUTH_REQUEST = 1;
@@ -20,6 +22,8 @@ const SUSTAINED_POINTS_PER_SEC = 8 * POINTS_UNAUTH_REQUEST;
 
 // remotestorage.js appears to keep requesting until 10 failures
 
+const debugEnabled = debuglog('ratelimiter').enabled;
+
 const rateLimiterSustained = new RateLimiterMemory({
   points: SUSTAINED_POINTS_PER_SEC,
   duration: 1
@@ -76,7 +80,10 @@ const rateLimiterMiddleware = async (req, res, next) => {
     await rateLimiter.consume(req.ip, POINTS_UNAUTH_REQUEST);
     next();
   } catch (err) {
-    // await new Promise(resolve => loggingMiddleware(req, res, resolve));
+    if (debugEnabled) {
+      await new Promise(resolve => loggingMiddleware(req, res, resolve));
+      res.logNotes.add(`consumedPoints=${err.consumedPoints} msBeforeNext=${err.msBeforeNext}`);
+    }
     res.set({ 'Retry-After': Math.ceil(err.msBeforeNext / 1000) });
     res.status(429).end();
   }

lib/routes/S3_store_router.js

@@ -176,6 +176,7 @@ module.exports = function ({ endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SP
               if (req.get('If-None-Match') && stripQuotes(req.get('If-None-Match')) === digest) {
                 return res.status(304).end();
               } else if (req.get('If-Match') && stripQuotes(req.get('If-Match')) !== digest) {
+                res.logNotes.add(`If-Match:${req.get('If-Match')} actually ${digest}`);
                 return res.status(412).end();
               }
               res.set('ETag', normalizeETag(`"${digest}"`));
@@ -523,11 +524,11 @@ module.exports = function ({ endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SP
           res.logNotes.add(currentETag);
           res.status(412).end(); return;
         } else if (req.get('If-None-Match') && req.get('If-None-Match') === currentETag) {
-          res.logNotes.add('If-None-Match:' + req.get('If-None-Match'));
+          res.logNotes.add(`version ${currentETag} is already here`);
+          res.logLevel = 'info';
           res.status(412).end(); return;
         } else if (req.get('If-Match') && req.get('If-Match') !== currentETag) {
-          res.logNotes.add('If-Match:' + req.get('If-Match'));
-          res.logNotes.add(currentETag);
+          res.logNotes.add(`If-Match:${req.get('If-Match')} actually ${currentETag}`);
           res.status(412).end(); return;
         } // else unconditional
 
@@ -638,12 +639,10 @@ module.exports = function ({ endPoint = 'play.min.io', accessKey = 'Q3AM3UQ867SP
           // And we have the info to check this.
           currentETag = normalizeETag(keys?.[0]?.ETag);
           if (req.get('If-Match') && req.get('If-Match') !== currentETag) {
-            res.logNotes.add('If-Match:' + req.get('If-Match'));
-            res.logNotes.add(currentETag);
+            res.logNotes.add(`If-Match:${req.get('If-Match')} actually ${currentETag}`);
             return res.status(412).end();
           } else if (req.get('If-None-Match') && req.get('If-None-Match') === currentETag) {
             res.logNotes.add('If-None-Match:' + req.get('If-None-Match'));
-            res.logNotes.add(currentETag);
             return res.status(412).end();
           }
 

lib/util/errToMessages.js

@@ -1,3 +1,5 @@
+const { getSystemErrorName } = require('node:util');
+
 /**
  * Extracts & de-dupes payloads of error tree, for terse logging
  * @param {Error} err
@@ -19,7 +21,7 @@ module.exports = function errToMessages (err, messages) {
       if (err.code && !Array.from(messages).some(msg => typeof msg === 'string' && msg?.includes(err.code))) {
         messages.add(err.code);
       }
-      const errno = err.errno ? String(err.errno) : '';
+      const errno = err.errno ? getSystemErrorName(err.errno) : '';
       if (errno && !Array.from(messages).some(msg => typeof msg === 'string' && msg?.includes(errno))) {
         messages.add(errno);
       }