diff --git a/docs/content/using-npm/config.md b/docs/content/using-npm/config.md index 2b05c842f1190..2de35fa2a46c3 100644 --- a/docs/content/using-npm/config.md +++ b/docs/content/using-npm/config.md @@ -1707,12 +1707,11 @@ particular, use care when overriding this setting for public packages. * Default: false * Type: Boolean -If true, writes a debug log to `logs-dir` and timing information to -`_timing.json` in the cache, even if the command completes successfully. -`_timing.json` is a newline delimited list of JSON objects. +If true, writes timing information to a process specific json file in the +cache or `logs-dir`. The file name ends with `-timing.json`. You can quickly view it with this [json](https://npm.im/json) command line: -`npm exec -- json -g < ~/.npm/_timing.json`. +`cat ~/.npm/_logs/*-timing.json | npm exec -- json -g`. diff --git a/docs/content/using-npm/logging.md b/docs/content/using-npm/logging.md index d699c8dca6ccc..e52c19004d542 100644 --- a/docs/content/using-npm/logging.md +++ b/docs/content/using-npm/logging.md @@ -12,8 +12,7 @@ The `npm` CLI has various mechanisms for showing different levels of information All logs are written to a debug log, with the path to that file printed if the execution of a command fails. -The default location of the logs directory is a directory named `_logs` inside the npm cache. This can be changed -with the `logs-dir` config option. +The default location of the logs directory is a directory named `_logs` inside the npm cache. This can be changed with the `logs-dir` config option. Log files will be removed from the `logs-dir` when the number of log files exceeds `logs-max`, with the oldest logs being deleted first. @@ -62,9 +61,10 @@ The [`--timing` config](/using-npm/config#timing) can be set which does two things: 1. Always shows the full path to the debug log regardless of command exit status -1. Write timing information to a timing file in the cache or `logs-dir` +1. Write timing information to a process specific timing file in the cache or `logs-dir` -This file is a newline delimited list of JSON objects that can be inspected to see timing data for each task in a `npm` CLI run. +This file contains a `timers` object where the keys are an identifier for the +portion of the process being timed and the value is the number of milliseconds it took to complete. ### Registry Response Headers diff --git a/lib/npm.js b/lib/npm.js index b116ec5cc68a4..a178dca727e30 100644 --- a/lib/npm.js +++ b/lib/npm.js @@ -18,9 +18,11 @@ const replaceInfo = require('./utils/replace-info.js') const updateNotifier = require('./utils/update-notifier.js') const pkg = require('../package.json') const cmdList = require('./utils/cmd-list.js') +const runId = require('./utils/run-id.js') let warnedNonDashArg = false const _load = Symbol('_load') +const RUN_ID = runId() class Npm extends EventEmitter { static get version () { @@ -38,9 +40,10 @@ class Npm extends EventEmitter { #argvClean = [] #chalk = null - #logFile = new LogFile() + #logFile = new LogFile({ id: RUN_ID }) #display = new Display() #timers = new Timers({ + id: RUN_ID, start: 'npm', listener: (name, ms) => { const args = ['timing', name, `Completed in ${ms}ms`] @@ -207,10 +210,6 @@ class Npm extends EventEmitter { writeTimingFile () { this.#timers.writeFile({ command: this.#argvClean, - // We used to only ever report a single log file - // so to be backwards compatible report the last logfile - // XXX: remove this in npm 9 or just keep it forever - logfile: this.logFiles[this.logFiles.length - 1], logfiles: this.logFiles, version: this.version, }) @@ -298,7 +297,7 @@ class Npm extends EventEmitter { this.time('npm:load:timers', () => this.#timers.load({ - dir: this.config.get('timing') ? this.timingDir : null, + dir: this.config.get('timing') ? this.logsDir : null, }) ) @@ -376,11 +375,6 @@ class Npm extends EventEmitter { return this.#timers.file } - get timingDir () { - // XXX(npm9): make this always in logs-dir - return this.config.get('logs-dir') || this.cache - } - get cache () { return this.config.get('cache') } diff --git a/lib/utils/config/definitions.js b/lib/utils/config/definitions.js index fc39bddc70a42..ae38efc32b5ae 100644 --- a/lib/utils/config/definitions.js +++ b/lib/utils/config/definitions.js @@ -2062,13 +2062,11 @@ define('timing', { default: false, type: Boolean, description: ` - If true, writes a debug log to \`logs-dir\` and timing information - to \`_timing.json\` in the cache, even if the command completes - successfully. \`_timing.json\` is a newline delimited list of JSON - objects. + If true, writes timing information to a process specific json file in + the cache or \`logs-dir\`. The file name ends with \`-timing.json\`. You can quickly view it with this [json](https://npm.im/json) command - line: \`npm exec -- json -g < ~/.npm/_timing.json\`. + line: \`cat ~/.npm/_logs/*-timing.json | npm exec -- json -g\`. `, }) diff --git a/lib/utils/display.js b/lib/utils/display.js index a19f72297e838..b23b2467ff4e6 100644 --- a/lib/utils/display.js +++ b/lib/utils/display.js @@ -3,11 +3,6 @@ const npmlog = require('npmlog') const log = require('./log-shim.js') const { explain } = require('./explain-eresolve.js') -const _logHandler = Symbol('logHandler') -const _eresolveWarn = Symbol('eresolveWarn') -const _log = Symbol('log') -const _npmlog = Symbol('npmlog') - class Display { constructor () { // pause by default until config is loaded @@ -16,11 +11,11 @@ class Display { } on () { - process.on('log', this[_logHandler]) + process.on('log', this.#logHandler) } off () { - process.off('log', this[_logHandler]) + process.off('log', this.#logHandler) // Unbalanced calls to enable/disable progress // will leave change listeners on the tracker // This pretty much only happens in tests but @@ -72,16 +67,16 @@ class Display { } log (...args) { - this[_logHandler](...args) + this.#logHandler(...args) } - [_logHandler] = (level, ...args) => { + #logHandler = (level, ...args) => { try { - this[_log](level, ...args) + this.#log(level, ...args) } catch (ex) { try { // if it crashed once, it might again! - this[_npmlog]('verbose', `attempt to log ${inspect(args)} crashed`, ex) + this.#npmlog('verbose', `attempt to log ${inspect(args)} crashed`, ex) } catch (ex2) { // eslint-disable-next-line no-console console.error(`attempt to log ${inspect(args)} crashed`, ex, ex2) @@ -89,13 +84,13 @@ class Display { } } - [_log] (...args) { - return this[_eresolveWarn](...args) || this[_npmlog](...args) + #log (...args) { + return this.#eresolveWarn(...args) || this.#npmlog(...args) } // Explicitly call these on npmlog and not log shim // This is the final place we should call npmlog before removing it. - [_npmlog] (level, ...args) { + #npmlog (level, ...args) { npmlog[level](...args) } @@ -103,13 +98,13 @@ class Display { // log.warn() method so that when we see a peerDep override // explanation from Arborist, we can replace the object with a // highly abbreviated explanation of what's being overridden. - [_eresolveWarn] (level, heading, message, expl) { + #eresolveWarn (level, heading, message, expl) { if (level === 'warn' && heading === 'ERESOLVE' && expl && typeof expl === 'object' ) { - this[_npmlog](level, heading, message) - this[_npmlog](level, '', explain(expl, log.useColor(), 2)) + this.#npmlog(level, heading, message) + this.#npmlog(level, '', explain(expl, log.useColor(), 2)) // Return true to short circuit other log in chain return true } diff --git a/lib/utils/log-file.js b/lib/utils/log-file.js index d62329c8551e2..a18eb2878f0be 100644 --- a/lib/utils/log-file.js +++ b/lib/utils/log-file.js @@ -7,18 +7,11 @@ const MiniPass = require('minipass') const fsMiniPass = require('fs-minipass') const fs = require('@npmcli/fs') const log = require('./log-shim') +const runId = require('./run-id') const padZero = (n, length) => n.toString().padStart(length.toString().length, '0') const globify = pattern => pattern.split('\\').join('/') -const _logHandler = Symbol('logHandler') -const _formatLogItem = Symbol('formatLogItem') -const _getLogFilePath = Symbol('getLogFilePath') -const _openLogFile = Symbol('openLogFile') -const _cleanLogs = Symbol('cleanlogs') -const _endStream = Symbol('endStream') -const _isBuffered = Symbol('isBuffered') - class LogFiles { // If we write multiple log files we want them all to have the same // identifier for sorting and matching purposes @@ -46,19 +39,16 @@ class LogFiles { #files = [] constructor ({ + id = runId(), maxLogsPerFile = 50_000, maxFilesPerProcess = 5, } = {}) { - this.#logId = LogFiles.logId(new Date()) + this.#logId = id this.#MAX_LOGS_PER_FILE = maxLogsPerFile this.#MAX_FILES_PER_PROCESS = maxFilesPerProcess this.on() } - static logId (d) { - return d.toISOString().replace(/[.:]/g, '_') - } - static format (count, level, title, ...args) { let prefix = `${count} ${level}` if (title) { @@ -75,12 +65,12 @@ class LogFiles { on () { this.#logStream = new MiniPass() - process.on('log', this[_logHandler]) + process.on('log', this.#logHandler) } off () { - process.off('log', this[_logHandler]) - this[_endStream]() + process.off('log', this.#logHandler) + this.#endStream() } load ({ dir, logsMax = Infinity } = {}) { @@ -100,7 +90,7 @@ class LogFiles { // set that as the new log logstream for future writes // if logs max is 0 then the user does not want a log file if (this.#logsMax > 0) { - const initialFile = this[_openLogFile]() + const initialFile = this.#openLogFile() if (initialFile) { this.#logStream = this.#logStream.pipe(initialFile) } @@ -109,29 +99,29 @@ class LogFiles { // Kickoff cleaning process, even if we aren't writing a logfile. // This is async but it will always ignore the current logfile // Return the result so it can be awaited in tests - return this[_cleanLogs]() + return this.#cleanLogs() } log (...args) { - this[_logHandler](...args) + this.#logHandler(...args) } get files () { return this.#files } - get [_isBuffered] () { + get #isBuffered () { return this.#logStream instanceof MiniPass } - [_endStream] (output) { + #endStream (output) { if (this.#logStream) { this.#logStream.end(output) this.#logStream = null } } - [_logHandler] = (level, ...args) => { + #logHandler = (level, ...args) => { // Ignore pause and resume events since we // write everything to the log file if (level === 'pause' || level === 'resume') { @@ -143,9 +133,9 @@ class LogFiles { return } - const logOutput = this[_formatLogItem](level, ...args) + const logOutput = this.#formatLogItem(level, ...args) - if (this[_isBuffered]) { + if (this.#isBuffered) { // Cant do anything but buffer the output if we dont // have a file stream yet this.#logStream.write(logOutput) @@ -155,29 +145,29 @@ class LogFiles { // Open a new log file if we've written too many logs to this one if (this.#fileLogCount >= this.#MAX_LOGS_PER_FILE) { // Write last chunk to the file and close it - this[_endStream](logOutput) + this.#endStream(logOutput) if (this.#files.length >= this.#MAX_FILES_PER_PROCESS) { // but if its way too many then we just stop listening this.off() } else { // otherwise we are ready for a new file for the next event - this.#logStream = this[_openLogFile]() + this.#logStream = this.#openLogFile() } } else { this.#logStream.write(logOutput) } } - [_formatLogItem] (...args) { + #formatLogItem (...args) { this.#fileLogCount += 1 return LogFiles.format(this.#totalLogCount++, ...args) } - [_getLogFilePath] (count = '') { + #getLogFilePath (count = '') { return path.resolve(this.#dir, `${this.#logId}-debug-${count}.log`) } - [_openLogFile] () { + #openLogFile () { // Count in filename will be 0 indexed const count = this.#files.length @@ -186,7 +176,7 @@ class LogFiles { // 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 f = this[_getLogFilePath](padZero(count, this.#MAX_FILES_PER_PROCESS)) + const f = this.#getLogFilePath(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 @@ -210,7 +200,7 @@ class LogFiles { } } - async [_cleanLogs] () { + async #cleanLogs () { // module to clean out the old log files // this is a best-effort attempt. if a rm fails, we just // log a message about it and move on. We do return a @@ -218,7 +208,7 @@ class LogFiles { // just for the benefit of testing this function properly. try { - const logPath = this[_getLogFilePath]() + const logPath = this.#getLogFilePath() const logGlob = path.join(path.dirname(logPath), path.basename(logPath) // tell glob to only match digits .replace(/\d/g, '[0123456789]') diff --git a/lib/utils/run-id.js b/lib/utils/run-id.js new file mode 100644 index 0000000000000..b0996eef61bb5 --- /dev/null +++ b/lib/utils/run-id.js @@ -0,0 +1,5 @@ +module.exports = (d = new Date()) => { + return d.toISOString().replace(/[.:]/g, '_') + +} + diff --git a/lib/utils/timers.js b/lib/utils/timers.js index 3336c3b519259..9ad92ee5d6646 100644 --- a/lib/utils/timers.js +++ b/lib/utils/timers.js @@ -2,10 +2,7 @@ const EE = require('events') const { resolve } = require('path') const fs = require('@npmcli/fs') const log = require('./log-shim') - -const _timeListener = Symbol('timeListener') -const _timeEndListener = Symbol('timeEndListener') -const _init = Symbol('init') +const runId = require('./run-id') // This is an event emiiter but on/off // only listen on a single internal event that gets @@ -13,17 +10,19 @@ const _init = Symbol('init') class Timers extends EE { file = null + #id = null #unfinished = new Map() #finished = {} #onTimeEnd = Symbol('onTimeEnd') #initialListener = null #initialTimer = null - constructor ({ listener = null, start = 'npm' } = {}) { + constructor ({ id = runId(), listener = null, start = 'npm' } = {}) { super() + this.#id = id this.#initialListener = listener this.#initialTimer = start - this[_init]() + this.#init() } get unfinished () { @@ -34,7 +33,7 @@ class Timers extends EE { return this.#finished } - [_init] () { + #init () { this.on() if (this.#initialListener) { this.on(this.#initialListener) @@ -47,8 +46,8 @@ class Timers extends EE { if (listener) { super.on(this.#onTimeEnd, listener) } else { - process.on('time', this[_timeListener]) - process.on('timeEnd', this[_timeEndListener]) + process.on('time', this.#timeListener) + process.on('timeEnd', this.#timeEndListener) } } @@ -57,8 +56,8 @@ class Timers extends EE { super.off(this.#onTimeEnd, listener) } else { this.removeAllListeners(this.#onTimeEnd) - process.off('time', this[_timeListener]) - process.off('timeEnd', this[_timeEndListener]) + process.off('time', this.#timeListener) + process.off('timeEnd', this.#timeEndListener) } } @@ -74,11 +73,11 @@ class Timers extends EE { load ({ dir } = {}) { if (dir) { - this.file = resolve(dir, '_timing.json') + this.file = resolve(dir, `${this.#id}-timing.json`) } } - writeFile (fileData) { + writeFile (metadata) { if (!this.file) { return } @@ -87,20 +86,20 @@ class Timers extends EE { const globalStart = this.started const globalEnd = this.#finished.npm || Date.now() const content = { - ...fileData, - ...this.#finished, + metadata: { + id: this.#id, + ...metadata + }, + timers: this.#finished, // add any unfinished timers with their relative start/end - unfinished: [...this.#unfinished.entries()].reduce((acc, [name, start]) => { + unfinishedTimers: [...this.#unfinished.entries()].reduce((acc, [name, start]) => { acc[name] = [start - globalStart, globalEnd - globalStart] return acc }, {}), } - // we append line delimited json to this file...forever - // XXX: should we also write a process specific timing file? - // with similar rules to the debug log (max files, etc) fs.withOwnerSync( this.file, - () => fs.appendFileSync(this.file, JSON.stringify(content) + '\n'), + () => fs.writeFileSync(this.file, JSON.stringify(content) + '\n'), { owner: 'inherit' } ) } catch (e) { @@ -109,11 +108,11 @@ class Timers extends EE { } } - [_timeListener] = (name) => { + #timeListener = (name) => { this.#unfinished.set(name, Date.now()) } - [_timeEndListener] = (name) => { + #timeEndListener = (name) => { if (this.#unfinished.has(name)) { const ms = Date.now() - this.#unfinished.get(name) this.#finished[name] = ms diff --git a/tap-snapshots/test/lib/utils/config/definitions.js.test.cjs b/tap-snapshots/test/lib/utils/config/definitions.js.test.cjs index ddf2396a6fe00..df9313270d056 100644 --- a/tap-snapshots/test/lib/utils/config/definitions.js.test.cjs +++ b/tap-snapshots/test/lib/utils/config/definitions.js.test.cjs @@ -1762,12 +1762,11 @@ exports[`test/lib/utils/config/definitions.js TAP > config description for timin * Default: false * Type: Boolean -If true, writes a debug log to \`logs-dir\` and timing information to -\`_timing.json\` in the cache, even if the command completes successfully. -\`_timing.json\` is a newline delimited list of JSON objects. +If true, writes timing information to a process specific json file in the +cache or \`logs-dir\`. The file name ends with \`-timing.json\`. You can quickly view it with this [json](https://npm.im/json) command line: -\`npm exec -- json -g < ~/.npm/_timing.json\`. +\`cat ~/.npm/_logs/*-timing.json | npm exec -- json -g\`. ` exports[`test/lib/utils/config/definitions.js TAP > config description for tmp 1`] = ` diff --git a/tap-snapshots/test/lib/utils/config/describe-all.js.test.cjs b/tap-snapshots/test/lib/utils/config/describe-all.js.test.cjs index 2c51efec54afe..89ca7c952b182 100644 --- a/tap-snapshots/test/lib/utils/config/describe-all.js.test.cjs +++ b/tap-snapshots/test/lib/utils/config/describe-all.js.test.cjs @@ -1580,12 +1580,11 @@ particular, use care when overriding this setting for public packages. * Default: false * Type: Boolean -If true, writes a debug log to \`logs-dir\` and timing information to -\`_timing.json\` in the cache, even if the command completes successfully. -\`_timing.json\` is a newline delimited list of JSON objects. +If true, writes timing information to a process specific json file in the +cache or \`logs-dir\`. The file name ends with \`-timing.json\`. You can quickly view it with this [json](https://npm.im/json) command line: -\`npm exec -- json -g < ~/.npm/_timing.json\`. +\`cat ~/.npm/_logs/*-timing.json | npm exec -- json -g\`. diff --git a/test/fixtures/mock-npm.js b/test/fixtures/mock-npm.js index 330c341474da3..72cfa4b0c4beb 100644 --- a/test/fixtures/mock-npm.js +++ b/test/fixtures/mock-npm.js @@ -174,8 +174,8 @@ const LoadMockNpm = async (t, { .join('\n') }, timingFile: async () => { - const data = await fs.readFile(path.resolve(dirs.cache, '_timing.json'), 'utf8') - return JSON.parse(data) // XXX: this fails if multiple timings are written + const data = await fs.readFile(npm.timingFile, 'utf8') + return JSON.parse(data) }, } } diff --git a/test/lib/npm.js b/test/lib/npm.js index 135a02cc98a3d..2bf7f426db409 100644 --- a/test/lib/npm.js +++ b/test/lib/npm.js @@ -513,19 +513,23 @@ t.test('timings', async t => { process.emit('timeEnd', 'foo') process.emit('time', 'bar') npm.writeTimingFile() - t.equal(npm.timingFile, join(cache, '_timing.json')) + t.match(npm.timingFile, cache) + t.match(npm.timingFile, /-timing.json$/) const timings = await timingFile() t.match(timings, { - command: [], - logfile: String, - logfiles: [String], - version: String, - unfinished: { + metadata: { + command: [], + logfiles: [String], + version: String, + }, + unfinishedTimers: { bar: [Number, Number], npm: [Number, Number], }, - foo: Number, - 'npm:load': Number, + timers: { + foo: Number, + 'npm:load': Number, + }, }) }) diff --git a/test/lib/utils/exit-handler.js b/test/lib/utils/exit-handler.js index 23942cca1c078..de4ce61aaa6af 100644 --- a/test/lib/utils/exit-handler.js +++ b/test/lib/utils/exit-handler.js @@ -326,7 +326,7 @@ t.test('timing with no error', async (t) => { t.match(msg, /Timing info written to:/) t.match( - timingFileData, + timingFileData.timers, Object.keys(npm.finishedTimers).reduce((acc, k) => { acc[k] = Number return acc @@ -334,11 +334,14 @@ t.test('timing with no error', async (t) => { ) t.strictSame(npm.unfinishedTimers, new Map()) t.match(timingFileData, { - command: [], - version: '1.0.0', - npm: Number, - logfile: String, - logfiles: [String], + metadata: { + command: [], + version: '1.0.0', + logfiles: [String], + }, + timers: { + npm: Number, + }, }) }) @@ -356,12 +359,15 @@ t.test('unfinished timers', async (t) => { t.equal(process.exitCode, 0) t.match(npm.unfinishedTimers, new Map([['foo', Number], ['bar', Number]])) t.match(timingFileData, { - command: [], - version: '1.0.0', - npm: Number, - logfile: String, - logfiles: [String], - unfinished: { + metadata: { + command: [], + version: '1.0.0', + logfiles: [String], + }, + timers: { + npm: Number, + }, + unfinishedTimers: { foo: [Number, Number], bar: [Number, Number], }, diff --git a/test/lib/utils/log-file.js b/test/lib/utils/log-file.js index ce6f0bf4cf51f..3c7bb3fe8324a 100644 --- a/test/lib/utils/log-file.js +++ b/test/lib/utils/log-file.js @@ -6,6 +6,7 @@ const os = require('os') const fsMiniPass = require('fs-minipass') const rimraf = require('rimraf') const LogFile = require('../../../lib/utils/log-file.js') +const runId = require('../../../lib/utils/run-id.js') const { cleanCwd } = require('../../fixtures/clean-snapshot') t.cleanSnapshot = (path) => cleanCwd(path) @@ -19,7 +20,7 @@ const makeOldLogs = (count, oldStyle) => { return range(oldStyle ? count : (count / 2)).reduce((acc, i) => { const cloneDate = new Date(d.getTime()) cloneDate.setSeconds(i) - const dateId = LogFile.logId(cloneDate) + const dateId = runId(cloneDate) if (oldStyle) { acc[`${dateId}-debug.log`] = 'hello' } else { diff --git a/test/lib/utils/timers.js b/test/lib/utils/timers.js index 30e54700c63a9..259ecd5dd4893 100644 --- a/test/lib/utils/timers.js +++ b/test/lib/utils/timers.js @@ -68,17 +68,17 @@ t.test('finish unstarted timer', async (t) => { }) t.test('writes file', async (t) => { - const { timers } = mockTimers(t) + const { timers } = mockTimers(t, { id: 'TIMING_FILE' }) const dir = t.testdir() process.emit('time', 'foo') process.emit('timeEnd', 'foo') timers.load({ dir }) timers.writeFile({ some: 'data' }) - const data = JSON.parse(fs.readFileSync(resolve(dir, '_timing.json'))) + const data = JSON.parse(fs.readFileSync(resolve(dir, 'TIMING_FILE-timing.json'))) t.match(data, { - some: 'data', - foo: Number, - unfinished: { + metadata: { some: 'data' }, + timers: { foo: Number }, + unfinishedTimers: { npm: [Number, Number], }, })