From 103c8c3ef3ba7ff0483557f32eebc4c6298285e3 Mon Sep 17 00:00:00 2001 From: Gar Date: Fri, 25 Jun 2021 16:23:25 -0700 Subject: [PATCH] chore(exit): log any un-ended timings It will be helpful to us when debugging the "exit handler never called" bugs to know which timings were started but not ended. Tests moved to use real npm. PR-URL: https://github.com/npm/cli/pull/3479 Credit: @wraithgar Close: #3479 Reviewed-by: @ruyadorno --- lib/base-command.js | 1 - lib/npm.js | 2 +- lib/utils/exit-handler.js | 13 +++-- lib/utils/perf.js | 11 +++-- test/lib/utils/exit-handler.js | 89 ++++++++++++++++------------------ 5 files changed, 59 insertions(+), 57 deletions(-) diff --git a/lib/base-command.js b/lib/base-command.js index 4077733a934b..870c69acc492 100644 --- a/lib/base-command.js +++ b/lib/base-command.js @@ -75,7 +75,6 @@ class BaseCommand { } async setWorkspaces (filters) { - // TODO npm guards workspaces/global mode so we should use this.npm.prefix? const ws = await getWorkspaces(filters, { path: this.npm.localPrefix }) this.workspaces = ws this.workspaceNames = [...ws.keys()] diff --git a/lib/npm.js b/lib/npm.js index 7046a84d0bcf..407ca9a5a649 100644 --- a/lib/npm.js +++ b/lib/npm.js @@ -50,7 +50,7 @@ const npm = module.exports = new class extends EventEmitter { constructor () { super() // TODO make this only ever load once (or unload) in tests - require('./utils/perf.js') + this.timers = require('./utils/perf.js').timers this.started = Date.now() this.command = null this.commands = proxyCmds diff --git a/lib/utils/exit-handler.js b/lib/utils/exit-handler.js index 931527704b9b..c19e83123fad 100644 --- a/lib/utils/exit-handler.js +++ b/lib/utils/exit-handler.js @@ -32,9 +32,14 @@ process.on('timing', (name, value) => { }) process.on('exit', code => { + // process.emit is synchronous, so the timeEnd handler will run before the + // unfinished timer check below process.emit('timeEnd', 'npm') log.disableProgress() - if (npm.config && npm.config.loaded && npm.config.get('timing')) { + for (const [name, timers] of npm.timers) + log.verbose('unfinished npm timer', name, timers) + + if (npm.config.loaded && npm.config.get('timing')) { try { const file = path.resolve(npm.config.get('cache'), '_timing.json') const dir = path.dirname(npm.config.get('cache')) @@ -69,7 +74,7 @@ process.on('exit', code => { } } // In timing mode we always write the log file - if (npm.config && npm.config.loaded && npm.config.get('timing') && !wroteLogFile) + if (npm.config.loaded && npm.config.get('timing') && !wroteLogFile) writeLogFile() if (wroteLogFile) { // just a line break @@ -113,7 +118,7 @@ const exit = (code, noLog) => { const exitHandler = (err) => { log.disableProgress() - if (!npm.config || !npm.config.loaded) { + if (!npm.config.loaded) { // logging won't work unless we pretend that it's ready err = err || new Error('Exit prior to config file resolving.') console.error(err.stack || err.message) @@ -180,7 +185,7 @@ const exitHandler = (err) => { for (const errline of [...msg.summary, ...msg.detail]) log.error(...errline) - if (npm.config && npm.config.get('json')) { + if (npm.config.loaded && npm.config.get('json')) { const error = { error: { code: err.code, diff --git a/lib/utils/perf.js b/lib/utils/perf.js index 4961054d909a..b75d3e1d95f8 100644 --- a/lib/utils/perf.js +++ b/lib/utils/perf.js @@ -1,20 +1,21 @@ const log = require('npmlog') -const timings = new Map() +const timers = new Map() process.on('time', (name) => { - timings.set(name, Date.now()) + timers.set(name, Date.now()) }) process.on('timeEnd', (name) => { - if (timings.has(name)) { - const ms = Date.now() - timings.get(name) + if (timers.has(name)) { + const ms = Date.now() - timers.get(name) process.emit('timing', name, ms) log.timing(name, `Completed in ${ms}ms`) - timings.delete(name) + timers.delete(name) } else log.silly('timing', "Tried to end timer that doesn't exist:", name) }) +exports.timers = timers // for tests /* istanbul ignore next */ exports.reset = () => { diff --git a/test/lib/utils/exit-handler.js b/test/lib/utils/exit-handler.js index 06014b67a975..49e145aebd49 100644 --- a/test/lib/utils/exit-handler.js +++ b/test/lib/utils/exit-handler.js @@ -1,8 +1,10 @@ /* eslint-disable no-extend-native */ /* eslint-disable no-global-assign */ +const t = require('tap') const EventEmitter = require('events') const writeFileAtomic = require('write-file-atomic') -const t = require('tap') + +const { real: mockNpm } = require('../../fixtures/mock-npm') // NOTE: Although these unit tests may look like the rest on the surface, // they are in fact very special due to the amount of things hooking directly @@ -25,23 +27,14 @@ t.cleanSnapshot = (str) => redactCwd(str) // internal modules mocks const cacheFolder = t.testdir({}) -const config = { - values: { - cache: cacheFolder, - timing: true, - }, - loaded: true, - updateNotification: null, - get (key) { - return this.values[key] - }, -} -const npm = { - version: '1.0.0', - config, - shelloutCommands: ['exec', 'run-script'], -} +const { npm } = mockNpm(t) + +t.before(async () => { + npm.version = '1.0.0' + await npm.load() + npm.config.set('cache', cacheFolder) +}) const npmlog = { disableProgress: () => null, @@ -190,9 +183,15 @@ t.test('handles unknown error', (t) => { t.test('npm.config not ready', (t) => { t.plan(1) - config.loaded = false - + const { npm: unloaded } = mockNpm(t) const _error = console.error + + t.teardown(() => { + console.error = _error + exitHandler.setNpm(npm) + }) + + exitHandler.setNpm(unloaded) console.error = (msg) => { t.match( msg, @@ -202,25 +201,20 @@ t.test('npm.config not ready', (t) => { } exitHandler() - - t.teardown(() => { - console.error = _error - config.loaded = true - }) }) t.test('fail to write logfile', (t) => { t.plan(1) + t.teardown(() => { + npm.config.set('cache', cacheFolder) + }) + const badDir = t.testdir({ _logs: 'is a file', }) - config.values.cache = badDir - - t.teardown(() => { - config.values.cache = cacheFolder - }) + npm.config.set('cache', badDir) t.doesNotThrow( () => exitHandler(err), @@ -231,7 +225,11 @@ t.test('fail to write logfile', (t) => { t.test('console.log output using --json', (t) => { t.plan(1) - config.values.json = true + npm.config.set('json', true) + t.teardown(() => { + console.error = _error + npm.config.set('json', false) + }) const _error = console.error console.error = (jsonOutput) => { @@ -249,11 +247,6 @@ t.test('console.log output using --json', (t) => { } exitHandler(new Error('Error: EBADTHING Something happened')) - - t.teardown(() => { - console.error = _error - delete config.values.json - }) }) t.test('throw a non-error obj', (t) => { @@ -354,7 +347,12 @@ t.test('on exit handler', (t) => { t.test('it worked', (t) => { t.plan(2) - config.values.timing = false + npm.config.set('timing', false) + + t.teardown(() => { + process.exit = _exit + npm.config.set('timing', true) + }) const _exit = process.exit process.exit = (code) => { @@ -370,11 +368,6 @@ t.test('it worked', (t) => { process.emit('exit', 0) } - t.teardown(() => { - process.exit = _exit - config.values.timing = true - }) - exitHandler() }) @@ -466,6 +459,14 @@ t.test('exit handler called twice', (t) => { t.test('defaults to log error msg if stack is missing', (t) => { t.plan(1) + const { npm: unloaded } = mockNpm(t) + const _error = console.error + + t.teardown(() => { + console.error = _error + exitHandler.setNpm(npm) + }) + const noStackErr = Object.assign( new Error('Error with no stack'), { @@ -475,15 +476,11 @@ t.test('defaults to log error msg if stack is missing', (t) => { ) delete noStackErr.stack - npm.config.loaded = false - - const _error = console.error console.error = (msg) => { - console.error = _error - npm.config.loaded = true t.equal(msg, 'Error with no stack', 'should use error msg') } + exitHandler.setNpm(unloaded) exitHandler(noStackErr) })