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) })