CLDSRV-982: Guard against storing a request logger on a long-lived object

eslint.config.mjs

@@ -74,4 +74,26 @@ export default [...compat.extends('@scality/scality'), {
         "promise/prefer-await-to-then": "warn",
         "n/callback-return": "warn",
     },
+}, {
+    // A werelogs RequestLogger buffers every entry it is handed in
+    // RequestLogger.entries and only flushes when something logs at or above
+    // the dump threshold ('error'). That is safe for the duration of one
+    // request and a memory leak for anything that outlives it: a background
+    // timer logging through a stored RequestLogger grows it until the process
+    // restarts, and a single error-level write then dumps the whole buffer to
+    // the log at once.
+    files: ["lib/**/*.js"],
+
+    rules: {
+        "no-restricted-syntax": ["error", {
+            selector:
+                "AssignmentExpression[left.object.type='ThisExpression']"
+                + "[right.type='Identifier'][right.name=/^_?log(ger)?$/]",
+            message:
+                "Do not store a logger on an object. If the object outlives the request, "
+                + "require lib/utilities/logger and use that instead - it writes through "
+                + "rather than buffering. If the object really is per-request (a stream "
+                + "transform, say), disable this rule on the line and say why.",
+        }],
+    },
 }];

lib/auth/streamingV4/V4Transform.js

@@ -31,6 +31,9 @@ class V4Transform extends Transform {
         const { accessKey, signatureFromRequest, region, scopeDate, timestamp,
             credentialScope } = streamingV4Params;
         super({});
+        // This transform is constructed per request and destroyed with it,
+        // so holding the request logger cannot outlive the request.
+        // eslint-disable-next-line no-restricted-syntax
         this.log = log;
         this.errCb = errCb;
         this.accessKey = accessKey;

lib/auth/streamingV4/trailingChecksumTransform.js

@@ -15,6 +15,9 @@ class TrailingChecksumTransform extends Transform {
      */
     constructor(log) {
         super({});
+        // This transform is constructed per request and destroyed with it,
+        // so holding the request logger cannot outlive the request.
+        // eslint-disable-next-line no-restricted-syntax
         this.log = log;
         this.chunkSizeBuffer = Buffer.alloc(0);
         this.bytesToDiscard = 0; // when trailing \r\n are present, we discard them but they can be in different chunks

tests/unit/helpers.js

@@ -1,6 +1,7 @@
 const crypto = require('crypto');
 const assert = require('assert');
 const { storage } = require('arsenal');
+const { Werelogs } = require('werelogs');
 
 const AuthInfo = require('arsenal').auth.AuthInfo;
 const { RequestContext } = require('arsenal').policies;
@@ -521,6 +522,36 @@ function createRequestContext(apiMethod, request) {
         '127.0.0.1', false, apiMethod, 's3');
 }
 
+/**
+ * A real werelogs RequestLogger.
+ *
+ * DummyRequestLogger records calls but has no entries buffer, so it cannot
+ * show what werelogs actually does with the entries it is handed - which is
+ * how real leaks have gone unnoticed. Use this wherever a test needs to
+ * observe buffering, and assert with bufferedEntryCount().
+ *
+ * @param {object} [options] - level, dump and name overrides
+ * @returns {object} a werelogs RequestLogger
+ */
+function makeRealRequestLogger(options = {}) {
+    const werelogs = new Werelogs({
+        level: options.level || 'info',
+        dump: options.dump || 'error',
+    });
+    return new werelogs.Logger(options.name || 'test').newRequestLogger();
+}
+
+/**
+ * How many log entries werelogs is currently holding in memory for a request
+ * logger. A count that grows without bound is a leak.
+ *
+ * @param {object} log - a werelogs RequestLogger
+ * @returns {number} buffered entry count
+ */
+function bufferedEntryCount(log) {
+    return Array.isArray(log.entries) ? log.entries.length : 0;
+}
+
 module.exports = {
     testsRangeOnEmptyFile,
     makeid,
@@ -529,6 +560,8 @@ module.exports = {
     createAlteredRequest,
     cleanup,
     DummyRequestLogger,
+    makeRealRequestLogger,
+    bufferedEntryCount,
     makeAuthInfo,
     WebsiteConfig,
     CorsConfigTester,

tests/unit/utils/requestLoggerBuffering.js

@@ -0,0 +1,67 @@
+const assert = require('assert');
+
+const { makeRealRequestLogger, bufferedEntryCount } = require('../helpers');
+// lib/utilities/logger initializes Config on load; the unit environment
+// (CI=true, S3BACKEND=mem) is set before mocha loads any test file, so this
+// is safe at the top level, same as every test that pulls in helpers.
+const serverLogger = require('../../../lib/utilities/logger');
+
+/**
+ * Pins the werelogs RequestLogger behaviour that the no-restricted-syntax rule
+ * in eslint.config.mjs exists to protect against.
+ *
+ * A RequestLogger keeps every entry it is handed and only flushes when
+ * something logs at or above the dump threshold. That is deliberate - it lets
+ * an error carry the whole backstory of its request - and it is safe precisely
+ * because the logger is discarded when the request ends.
+ *
+ * Store one on an object that outlives the request and the buffer grows until
+ * the process restarts, and a single error-level write then dumps all of it
+ * at once. If werelogs ever changes this contract, these assertions are how
+ * we find out.
+ */
+describe('werelogs RequestLogger buffering', () => {
+    it('should buffer entries that are below the log level and never emitted', () => {
+        const log = makeRealRequestLogger({ level: 'info', dump: 'error' });
+
+        for (let i = 0; i < 100; i++) {
+            log.debug('background chatter', { i });
+        }
+
+        assert.strictEqual(bufferedEntryCount(log), 100,
+            'debug entries are retained even though logLevel info drops them from output');
+    });
+
+    it('should keep buffering without bound while nothing reaches the dump threshold', () => {
+        const log = makeRealRequestLogger({ level: 'info', dump: 'error' });
+
+        log.debug('one');
+        log.trace('two');
+        log.info('three');
+        log.warn('four');
+
+        assert.strictEqual(bufferedEntryCount(log), 4,
+            'trace through warn are all buffered; only error drains');
+    });
+
+    it('should flush the whole buffer on a single error-level write', () => {
+        const log = makeRealRequestLogger({ level: 'info', dump: 'error' });
+
+        for (let i = 0; i < 100; i++) {
+            log.debug('background chatter', { i });
+        }
+        assert.strictEqual(bufferedEntryCount(log), 100);
+
+        log.error('something failed');
+
+        assert.strictEqual(bufferedEntryCount(log), 0,
+            'one error emits every buffered entry at once and empties the buffer');
+    });
+
+    it('should give the plain server logger no buffer at all', () => {
+        // a werelogs Logger, not a RequestLogger: it writes through and drops
+        // sub-level entries. This is what long-lived objects must use.
+        assert.strictEqual(serverLogger.entries, undefined,
+            'the server logger must not accumulate entries');
+    });
+});