From 08c663931ec1f56d777ffdb38f94926b9eac13ef Mon Sep 17 00:00:00 2001 From: Luke Karrys Date: Mon, 6 Dec 2021 20:44:06 -0700 Subject: [PATCH] fix: dont warn on error cleaning individual log files Closes: #4128 This also refactors the logic for cleaning log files to use the `ignore` option from `glob` to not clean current log files instead of relying on updating the `logs-max` count. I also discovered a bug where we weren't cleaning log files written with the old naming convention, so this fixes that as well. PR-URL: https://github.com/npm/cli/pull/4134 Credit: @lukekarrys Close: #4134 Reviewed-by: @wraithgar --- lib/utils/log-file.js | 43 +++++++++++++++++--------------------- test/lib/utils/log-file.js | 25 ++++++++++++++++++---- 2 files changed, 40 insertions(+), 28 deletions(-) diff --git a/lib/utils/log-file.js b/lib/utils/log-file.js index b37fd23e079c0..0bf1e0054ea2b 100644 --- a/lib/utils/log-file.js +++ b/lib/utils/log-file.js @@ -8,6 +8,8 @@ const fsMiniPass = require('fs-minipass') const log = require('./log-shim') const withChownSync = require('./with-chown-sync') +const padZero = (n, length) => n.toString().padStart(length.toString().length, '0') + const _logHandler = Symbol('logHandler') const _formatLogItem = Symbol('formatLogItem') const _getLogFilePath = Symbol('getLogFilePath') @@ -34,7 +36,7 @@ class LogFiles { // here for infinite loops that still log. This is also partially handled // by the config.get('max-files') option, but this is a failsafe to // prevent runaway log file creation - #MAX_LOG_FILES_PER_PROCESS = null + #MAX_FILES_PER_PROCESS = null #fileLogCount = 0 #totalLogCount = 0 @@ -48,7 +50,7 @@ class LogFiles { } = {}) { this.#logId = LogFiles.logId(new Date()) this.#MAX_LOGS_PER_FILE = maxLogsPerFile - this.#MAX_LOG_FILES_PER_PROCESS = maxFilesPerProcess + this.#MAX_FILES_PER_PROCESS = maxFilesPerProcess this.on() } @@ -56,10 +58,6 @@ class LogFiles { return d.toISOString().replace(/[.:]/g, '_') } - static fileName (prefix, suffix) { - return `${prefix}-debug-${suffix}.log` - } - static format (count, level, title, ...args) { let prefix = `${count} ${level}` if (title) { @@ -149,7 +147,7 @@ class LogFiles { if (this.#fileLogCount >= this.#MAX_LOGS_PER_FILE) { // Write last chunk to the file and close it this[_endStream](logOutput) - if (this.#files.length >= this.#MAX_LOG_FILES_PER_PROCESS) { + if (this.#files.length >= this.#MAX_FILES_PER_PROCESS) { // but if its way too many then we just stop listening this.off() } else { @@ -166,23 +164,21 @@ class LogFiles { return LogFiles.format(this.#totalLogCount++, ...args) } - [_getLogFilePath] (prefix, suffix) { - return path.resolve(this.#dir, LogFiles.fileName(prefix, suffix)) + [_getLogFilePath] (prefix, suffix, sep = '-') { + return path.resolve(this.#dir, prefix + sep + 'debug' + sep + suffix + '.log') } [_openLogFile] () { // Count in filename will be 0 indexed const count = this.#files.length - // Pad with zeros so that our log files are always sorted properly - // We never want to write files ending in `-9.log` and `-10.log` because - // log file cleaning is done by deleting the oldest so in this example - // `-10.log` would be deleted next - const countDigits = this.#MAX_LOG_FILES_PER_PROCESS.toString().length - try { const logStream = withChownSync( - this[_getLogFilePath](this.#logId, count.toString().padStart(countDigits, '0')), + // Pad with zeros so that our log files are always sorted properly + // We never want to write files ending in `-9.log` and `-10.log` because + // log file cleaning is done by deleting the oldest so in this example + // `-10.log` would be deleted next + this[_getLogFilePath](this.#logId, padZero(count, this.#MAX_FILES_PER_PROCESS)), // Some effort was made to make the async, but we need to write logs // during process.on('exit') which has to be synchronous. So in order // to never drop log messages, it is easiest to make it sync all the time @@ -214,14 +210,13 @@ class LogFiles { return } - // Add 1 to account for the current log file and make - // minimum config 0 so current log file is never deleted - // XXX: we should make a separate documented option to - // disable log file writing - const max = Math.max(this.#logsMax, 0) + 1 try { - const files = await glob(this[_getLogFilePath]('*', '*')) - const toDelete = files.length - max + // Handle the old (prior to 8.2.0) log file names which did not have an counter suffix + // so match by anything after `-debug` and before `.log` (including nothing) + const logGlob = this[_getLogFilePath]('*-', '*', '') + // Always ignore the currently written files + const files = await glob(logGlob, { ignore: this.#files }) + const toDelete = files.length - this.#logsMax if (toDelete <= 0) { return @@ -233,7 +228,7 @@ class LogFiles { try { await rimraf(file) } catch (e) { - log.warn('logfile', 'error removing log file', file, e) + log.silly('logfile', 'error removing log file', file, e) } } } catch (e) { diff --git a/test/lib/utils/log-file.js b/test/lib/utils/log-file.js index adc1a2e03ff3d..007ce221b0940 100644 --- a/test/lib/utils/log-file.js +++ b/test/lib/utils/log-file.js @@ -12,15 +12,20 @@ t.cleanSnapshot = (path) => cleanCwd(path) const last = arr => arr[arr.length - 1] const range = (n) => Array.from(Array(n).keys()) -const makeOldLogs = (count) => { +const makeOldLogs = (count, oldStyle) => { const d = new Date() d.setHours(-1) d.setSeconds(0) - return range(count / 2).reduce((acc, i) => { + return range(oldStyle ? count : (count / 2)).reduce((acc, i) => { const cloneDate = new Date(d.getTime()) cloneDate.setSeconds(i) - acc[LogFile.fileName(LogFile.logId(cloneDate), 0)] = 'hello' - acc[LogFile.fileName(LogFile.logId(cloneDate), 1)] = 'hello' + const dateId = LogFile.logId(cloneDate) + if (oldStyle) { + acc[`${dateId}-debug.log`] = 'hello' + } else { + acc[`${dateId}-debug-0.log`] = 'hello' + acc[`${dateId}-debug-1.log`] = 'hello' + } return acc }, {}) } @@ -247,6 +252,18 @@ t.test('glob error', async t => { t.match(last(logs).content, /error cleaning log files .* bad glob/) }) +t.test('cleans old style logs too', async t => { + const logsMax = 5 + const oldLogs = 10 + const { readLogs } = await loadLogFile(t, { + logsMax, + testdir: makeOldLogs(oldLogs, false), + }) + + const logs = await readLogs() + t.equal(logs.length, logsMax + 1) +}) + t.test('rimraf error', async t => { const logsMax = 5 const oldLogs = 10