diff --git a/eslint.config.mjs b/eslint.config.mjs index d647d0f2af..c95fe2b141 100644 --- a/eslint.config.mjs +++ b/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.", + }], + }, }]; diff --git a/lib/auth/streamingV4/V4Transform.js b/lib/auth/streamingV4/V4Transform.js index e18d20e14f..bc1407faf5 100644 --- a/lib/auth/streamingV4/V4Transform.js +++ b/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; diff --git a/lib/auth/streamingV4/trailingChecksumTransform.js b/lib/auth/streamingV4/trailingChecksumTransform.js index 48870c80e7..0805ae8ae4 100644 --- a/lib/auth/streamingV4/trailingChecksumTransform.js +++ b/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 diff --git a/tests/unit/helpers.js b/tests/unit/helpers.js index a8f1f594c4..b886a31ef2 100644 --- a/tests/unit/helpers.js +++ b/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, diff --git a/tests/unit/utils/requestLoggerBuffering.js b/tests/unit/utils/requestLoggerBuffering.js new file mode 100644 index 0000000000..1340f631c2 --- /dev/null +++ b/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'); + }); +});