diff --git a/lib/npm.js b/lib/npm.js index 407ca9a5a6492..db3559a384bd7 100644 --- a/lib/npm.js +++ b/lib/npm.js @@ -1,12 +1,7 @@ -// The order of the code in this file is relevant, because a lot of things -// require('npm.js'), but also we need to use some of those modules. So, -// we define and instantiate the singleton ahead of loading any modules -// required for its methods. - -// these are all dependencies used in the ctor const EventEmitter = require('events') const { resolve, dirname } = require('path') const Config = require('@npmcli/config') +const log = require('npmlog') // Patch the global fs module here at the app level require('graceful-fs').gracefulify(require('fs')) @@ -37,23 +32,51 @@ const proxyCmds = new Proxy({}, { }, }) +// Timers in progress +const timers = new Map() +// Finished timers +const timings = {} + +const processOnTimeHandler = (name) => { + timers.set(name, Date.now()) +} + +const processOnTimeEndHandler = (name) => { + if (timers.has(name)) { + const ms = Date.now() - timers.get(name) + log.timing(name, `Completed in ${ms}ms`) + timings[name] = ms + timers.delete(name) + } else + log.silly('timing', "Tried to end timer that doesn't exist:", name) +} + const { definitions, flatten, shorthands } = require('./utils/config/index.js') const { shellouts } = require('./utils/cmd-list.js') const usage = require('./utils/npm-usage.js') +const which = require('which') + +const deref = require('./utils/deref-command.js') +const setupLog = require('./utils/setup-log.js') +const cleanUpLogFiles = require('./utils/cleanup-log-files.js') +const getProjectScope = require('./utils/get-project-scope.js') + let warnedNonDashArg = false const _runCmd = Symbol('_runCmd') const _load = Symbol('_load') const _tmpFolder = Symbol('_tmpFolder') const _title = Symbol('_title') + const npm = module.exports = new class extends EventEmitter { constructor () { super() - // TODO make this only ever load once (or unload) in tests - this.timers = require('./utils/perf.js').timers this.started = Date.now() this.command = null this.commands = proxyCmds + this.timings = timings + this.timers = timers + this.perfStart() procLogListener() process.emit('time', 'npm') this.version = require('../package.json').version @@ -67,6 +90,16 @@ const npm = module.exports = new class extends EventEmitter { this.updateNotification = null } + perfStart () { + process.on('time', processOnTimeHandler) + process.on('timeEnd', processOnTimeEndHandler) + } + + perfStop () { + process.off('time', processOnTimeHandler) + process.off('timeEnd', processOnTimeEndHandler) + } + get shelloutCommands () { return shellouts } @@ -317,16 +350,5 @@ const npm = module.exports = new class extends EventEmitter { } }() -// now load everything required by the class methods - -const log = require('npmlog') - -const which = require('which') - -const deref = require('./utils/deref-command.js') -const setupLog = require('./utils/setup-log.js') -const cleanUpLogFiles = require('./utils/cleanup-log-files.js') -const getProjectScope = require('./utils/get-project-scope.js') - if (require.main === module) require('./cli.js')(process) diff --git a/lib/utils/exit-handler.js b/lib/utils/exit-handler.js index c19e83123fad8..95c9655a716cf 100644 --- a/lib/utils/exit-handler.js +++ b/lib/utils/exit-handler.js @@ -1,4 +1,3 @@ -const log = require('npmlog') const os = require('os') const path = require('path') const writeFileAtomic = require('write-file-atomic') @@ -13,8 +12,6 @@ let logFileName let npm // set by the cli let wroteLogFile = false -const timings = {} - const getLogFile = () => { // we call this multiple times, so we need to treat it as a singleton because // the date is part of the name @@ -24,20 +21,13 @@ const getLogFile = () => { return logFileName } -process.on('timing', (name, value) => { - if (timings[name]) - timings[name] += value - else - timings[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() + npm.log.disableProgress() for (const [name, timers] of npm.timers) - log.verbose('unfinished npm timer', name, timers) + npm.log.verbose('unfinished npm timer', name, timers) if (npm.config.loaded && npm.config.get('timing')) { try { @@ -49,7 +39,7 @@ process.on('exit', code => { command: process.argv.slice(2), logfile: getLogFile(), version: npm.version, - ...timings, + ...npm.timings, }) + '\n') const st = fs.lstatSync(path.dirname(npm.config.get('cache'))) @@ -61,14 +51,14 @@ process.on('exit', code => { } if (!code) - log.info('ok') + npm.log.info('ok') else { - log.verbose('code', code) + npm.log.verbose('code', code) if (!exitHandlerCalled) { - log.error('', 'Exit handler never called!') + npm.log.error('', 'Exit handler never called!') console.error('') - log.error('', 'This is an error with npm itself. Please report this error at:') - log.error('', ' ') + npm.log.error('', 'This is an error with npm itself. Please report this error at:') + npm.log.error('', ' ') // TODO this doesn't have an npm.config.loaded guard writeLogFile() } @@ -78,10 +68,10 @@ process.on('exit', code => { writeLogFile() if (wroteLogFile) { // just a line break - if (log.levels[log.level] <= log.levels.error) + if (npm.log.levels[npm.log.level] <= npm.log.levels.error) console.error('') - log.error( + npm.log.error( '', [ 'A complete log of this run can be found in:', @@ -93,121 +83,114 @@ process.on('exit', code => { // these are needed for the tests to have a clean slate in each test case exitHandlerCalled = false wroteLogFile = false - - // actually exit. - process.exit(code) }) -const exit = (code, noLog) => { - log.verbose('exit', code || 0) - if (log.level === 'silent') - noLog = true - - // noLog is true if there was an error, including if config wasn't loaded, so - // this doesn't need a config.loaded guard - if (code && !noLog) - writeLogFile() - - // Exit directly -- nothing in the CLI should still be running in the - // background at this point, and this makes sure anything left dangling - // for whatever reason gets thrown away, instead of leaving the CLI open - process.stdout.write('', () => { - process.exit(code) - }) -} - const exitHandler = (err) => { - log.disableProgress() + npm.log.disableProgress() 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) } - if (exitHandlerCalled) - err = err || new Error('Exit handler called more than once.') - - // only show the notification if it finished before the other stuff we - // were doing. no need to hang on `npm -v` or something. + // only show the notification if it finished. if (typeof npm.updateNotification === 'string') { - const { level } = log - log.level = log.levels.notice - log.notice('', npm.updateNotification) - log.level = level + const { level } = npm.log + npm.log.level = 'notice' + npm.log.notice('', npm.updateNotification) + npm.log.level = level } exitHandlerCalled = true - if (!err) - return exit() - - // if we got a command that just shells out to something else, then it - // will presumably print its own errors and exit with a proper status - // code if there's a problem. If we got an error with a code=0, then... - // something else went wrong along the way, so maybe an npm problem? - const isShellout = npm.shelloutCommands.includes(npm.command) - const quietShellout = isShellout && typeof err.code === 'number' && err.code - if (quietShellout) - return exit(err.code, true) - else if (typeof err === 'string') { - log.error('', err) - return exit(1, true) - } else if (!(err instanceof Error)) { - log.error('weird error', err) - return exit(1, true) - } - if (!err.code) { - const matchErrorCode = err.message.match(/^(?:Error: )?(E[A-Z]+)/) - err.code = matchErrorCode && matchErrorCode[1] - } - - for (const k of ['type', 'stack', 'statusCode', 'pkgid']) { - const v = err[k] - if (v) - log.verbose(k, replaceInfo(v)) + let exitCode + let noLog + + if (err) { + exitCode = 1 + // if we got a command that just shells out to something else, then it + // will presumably print its own errors and exit with a proper status + // code if there's a problem. If we got an error with a code=0, then... + // something else went wrong along the way, so maybe an npm problem? + const isShellout = npm.shelloutCommands.includes(npm.command) + const quietShellout = isShellout && typeof err.code === 'number' && err.code + if (quietShellout) { + exitCode = err.code + noLog = true + } else if (typeof err === 'string') { + noLog = true + npm.log.error('', err) + } else if (!(err instanceof Error)) { + noLog = true + npm.log.error('weird error', err) + } else { + if (!err.code) { + const matchErrorCode = err.message.match(/^(?:Error: )?(E[A-Z]+)/) + err.code = matchErrorCode && matchErrorCode[1] + } + + for (const k of ['type', 'stack', 'statusCode', 'pkgid']) { + const v = err[k] + if (v) + npm.log.verbose(k, replaceInfo(v)) + } + + npm.log.verbose('cwd', process.cwd()) + + const args = replaceInfo(process.argv) + npm.log.verbose('', os.type() + ' ' + os.release()) + npm.log.verbose('argv', args.map(JSON.stringify).join(' ')) + npm.log.verbose('node', process.version) + npm.log.verbose('npm ', 'v' + npm.version) + + for (const k of ['code', 'syscall', 'file', 'path', 'dest', 'errno']) { + const v = err[k] + if (v) + npm.log.error(k, v) + } + + const msg = errorMessage(err, npm) + for (const errline of [...msg.summary, ...msg.detail]) + npm.log.error(...errline) + + if (npm.config.loaded && npm.config.get('json')) { + const error = { + error: { + code: err.code, + summary: messageText(msg.summary), + detail: messageText(msg.detail), + }, + } + console.error(JSON.stringify(error, null, 2)) + } + + if (typeof err.errno === 'number') + exitCode = err.errno + else if (typeof err.code === 'number') + exitCode = err.code + } } + npm.log.verbose('exit', exitCode || 0) - log.verbose('cwd', process.cwd()) - - const args = replaceInfo(process.argv) - log.verbose('', os.type() + ' ' + os.release()) - log.verbose('argv', args.map(JSON.stringify).join(' ')) - log.verbose('node', process.version) - log.verbose('npm ', 'v' + npm.version) - - for (const k of ['code', 'syscall', 'file', 'path', 'dest', 'errno']) { - const v = err[k] - if (v) - log.error(k, v) - } + if (npm.log.level === 'silent') + noLog = true - const msg = errorMessage(err, npm) - for (const errline of [...msg.summary, ...msg.detail]) - log.error(...errline) - - if (npm.config.loaded && npm.config.get('json')) { - const error = { - error: { - code: err.code, - summary: messageText(msg.summary), - detail: messageText(msg.detail), - }, - } - console.error(JSON.stringify(error, null, 2)) - } + // noLog is true if there was an error, including if config wasn't loaded, so + // this doesn't need a config.loaded guard + if (exitCode && !noLog) + writeLogFile() - exit(typeof err.errno === 'number' ? err.errno : typeof err.code === 'number' ? err.code : 1) + // explicitly call process.exit now so we don't hang on things like the + // update notifier, also flush stdout beforehand because process.exit doesn't + // wait for that to happen. + process.stdout.write('', () => process.exit(exitCode)) } const messageText = msg => msg.map(line => line.slice(1).join(' ')).join('\n') const writeLogFile = () => { - if (wroteLogFile) - return - try { let logOutput = '' - log.record.forEach(m => { + npm.log.record.forEach(m => { const p = [m.id, m.level] if (m.prefix) p.push(m.prefix) @@ -230,7 +213,7 @@ const writeLogFile = () => { fs.chownSync(file, st.uid, st.gid) // truncate once it's been written. - log.record.length = 0 + npm.log.record.length = 0 wroteLogFile = true } catch (ex) { diff --git a/lib/utils/perf.js b/lib/utils/perf.js deleted file mode 100644 index b75d3e1d95f83..0000000000000 --- a/lib/utils/perf.js +++ /dev/null @@ -1,24 +0,0 @@ -const log = require('npmlog') -const timers = new Map() - -process.on('time', (name) => { - timers.set(name, Date.now()) -}) - -process.on('timeEnd', (name) => { - if (timers.has(name)) { - const ms = Date.now() - timers.get(name) - process.emit('timing', name, ms) - log.timing(name, `Completed in ${ms}ms`) - 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 = () => { - process.removeAllListeners('time') - process.removeAllListeners('timeEnd') -} diff --git a/lib/utils/update-notifier.js b/lib/utils/update-notifier.js index 23d5cd5f6bb48..14c4fac0d58b3 100644 --- a/lib/utils/update-notifier.js +++ b/lib/utils/update-notifier.js @@ -33,12 +33,6 @@ const checkTimeout = async (npm, duration) => { return t > st.mtime } -const updateTimeout = async npm => { - // best effort, if this fails, it's ok. - // might be using /dev/null as the cache or something weird like that. - await writeFile(lastCheckedFile(npm), '').catch(() => {}) -} - const updateNotifier = async (npm, spec = 'latest') => { // never check for updates in CI, when updating npm already, or opted out if (!npm.config.get('update-notifier') || @@ -118,7 +112,9 @@ const updateNotifier = async (npm, spec = 'latest') => { // only update the notification timeout if we actually finished checking module.exports = async npm => { const notification = await updateNotifier(npm) - // intentional. do not await this. it's a best-effort update. - updateTimeout(npm) + // intentional. do not await this. it's a best-effort update. if this + // fails, it's ok. might be using /dev/null as the cache or something weird + // like that. + writeFile(lastCheckedFile(npm), '').catch(() => {}) npm.updateNotification = notification } diff --git a/tap-snapshots/test/lib/utils/exit-handler.js.test.cjs b/tap-snapshots/test/lib/utils/exit-handler.js.test.cjs index 8cea8ee17e5ea..eb383c104a674 100644 --- a/tap-snapshots/test/lib/utils/exit-handler.js.test.cjs +++ b/tap-snapshots/test/lib/utils/exit-handler.js.test.cjs @@ -6,15 +6,15 @@ */ 'use strict' exports[`test/lib/utils/exit-handler.js TAP handles unknown error > should have expected log contents for unknown error 1`] = ` -0 verbose stack Error: ERROR -1 verbose cwd {CWD} -2 verbose Foo 1.0.0 -3 verbose argv "/node" "{CWD}/test/lib/utils/exit-handler.js" -4 verbose node v1.0.0 -5 verbose npm v1.0.0 -6 error foo code ERROR -7 error foo ERR ERROR -8 error foo ERR ERROR -9 verbose exit 1 +24 verbose stack Error: ERROR +25 verbose cwd {CWD} +26 verbose Foo 1.0.0 +27 verbose argv "/node" "{CWD}/test/lib/utils/exit-handler.js" +28 verbose node v1.0.0 +29 verbose npm v1.0.0 +30 error code ERROR +31 error ERR ERROR +32 error ERR ERROR +33 verbose exit 1 ` diff --git a/test/fixtures/mock-npm.js b/test/fixtures/mock-npm.js index 1de080eb10b4a..e3be10b4b9aa3 100644 --- a/test/fixtures/mock-npm.js +++ b/test/fixtures/mock-npm.js @@ -1,20 +1,19 @@ const npmlog = require('npmlog') -const perf = require('../../lib/utils/perf.js') -perf.reset() const procLog = require('../../lib/utils/proc-log-listener.js') procLog.reset() const realLog = {} -for (const level of ['silly', 'verbose', 'timing', 'notice', 'warn', 'error']) +for (const level in npmlog.levels) realLog[level] = npmlog[level] const { title, execPath } = process const RealMockNpm = (t, otherMocks = {}) => { t.teardown(() => { - for (const level of ['silly', 'verbose', 'timing', 'notice', 'warn', 'error']) + npm.perfStop() + npmlog.record.length = 0 + for (const level in npmlog.levels) npmlog[level] = realLog[level] - perf.reset() procLog.reset() process.title = title process.execPath = execPath @@ -33,9 +32,14 @@ const RealMockNpm = (t, otherMocks = {}) => { }) }) } - for (const level of ['silly', 'verbose', 'timing', 'notice', 'warn', 'error']) { + for (const level in npmlog.levels) { npmlog[level] = (...msg) => { logs.push([level, ...msg]) + + const l = npmlog.level + npmlog.level = 'silent' + realLog[level](...msg) + npmlog.level = l } } npm.output = (...msg) => outputs.push(msg) diff --git a/test/lib/npm.js b/test/lib/npm.js index 291a58955ceed..03bb46d8d8451 100644 --- a/test/lib/npm.js +++ b/test/lib/npm.js @@ -476,3 +476,28 @@ t.test('set process.title', t => { t.end() }) + +t.test('timings', t => { + const { npm, logs } = mockNpm(t) + process.emit('time', 'foo') + process.emit('time', 'bar') + t.match(npm.timers.get('foo'), Number, 'foo timer is a number') + t.match(npm.timers.get('bar'), Number, 'foo timer is a number') + process.emit('timeEnd', 'foo') + process.emit('timeEnd', 'bar') + process.emit('timeEnd', 'baz') + t.match(logs, [ + ['timing', 'foo', /Completed in [0-9]+ms/], + ['timing', 'bar', /Completed in [0-9]+ms/], + [ + 'silly', + 'timing', + "Tried to end timer that doesn't exist:", + 'baz', + ], + ]) + t.notOk(npm.timers.has('foo'), 'foo timer is gone') + t.notOk(npm.timers.has('bar'), 'bar timer is gone') + t.match(npm.timings, { foo: Number, bar: Number }) + t.end() +}) diff --git a/test/lib/utils/exit-handler.js b/test/lib/utils/exit-handler.js index 49e145aebd496..981ac9a32b684 100644 --- a/test/lib/utils/exit-handler.js +++ b/test/lib/utils/exit-handler.js @@ -2,15 +2,12 @@ /* eslint-disable no-global-assign */ const t = require('tap') const EventEmitter = require('events') -const writeFileAtomic = require('write-file-atomic') +const os = require('os') +const fs = require('fs') +const path = require('path') 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 -// to global process and variables defined in the module scope. That makes -// for tests that are very interdependent and their order are important. - // generic error to be used in tests const err = Object.assign(new Error('ERROR'), { code: 'ERROR' }) err.stack = 'Error: ERROR' @@ -25,8 +22,9 @@ const redactCwd = (path) => { t.cleanSnapshot = (str) => redactCwd(str) -// internal modules mocks const cacheFolder = t.testdir({}) +const logFile = path.resolve(cacheFolder, '_logs', 'expecteddate-debug.log') +const timingFile = path.resolve(cacheFolder, '_timing.json') const { npm } = mockNpm(t) @@ -36,49 +34,11 @@ t.before(async () => { npm.config.set('cache', cacheFolder) }) -const npmlog = { - disableProgress: () => null, - log (level, ...args) { - this.record.push({ - id: this.record.length, - level, - message: args.reduce((res, i) => `${res} ${i.message ? i.message : i}`, ''), - prefix: level !== 'verbose' ? 'foo' : '', - }) - }, - error (...args) { - this.log('error', ...args) - }, - info (...args) { - this.log('info', ...args) - }, - level: 'silly', - levels: { - silly: 0, - verbose: 1, - info: 2, - error: 3, - silent: 4, - }, - notice (...args) { - this.log('notice', ...args) - }, - record: [], - verbose (...args) { - this.log('verbose', ...args) - }, -} - -// overrides OS type/release for cross platform snapshots -const os = require('os') -os.type = () => 'Foo' -os.release = () => '1.0.0' - -// bootstrap tap before cutting off process ref -t.test('ok', (t) => { +t.test('bootstrap tap before cutting off process ref', (t) => { t.ok('ok') t.end() }) + // cut off process from script so that it won't quit the test runner // while trying to run through the myriad of cases const _process = process @@ -88,9 +48,11 @@ process = Object.assign( argv: ['/node', ..._process.argv.slice(1)], cwd: _process.cwd, env: _process.env, - exit () {}, - exitCode: 0, version: 'v1.0.0', + exit: (code) => { + process.exitCode = code || process.exitCode || 0 + process.emit('exit', process.exitCode) + }, stdout: { write (_, cb) { cb() } }, @@ -98,19 +60,40 @@ process = Object.assign( hrtime: _process.hrtime, } ) -// needs to put process back in its place -// in order for tap to exit properly + +const osType = os.type +const osRelease = os.release +// overrides OS type/release for cross platform snapshots +os.type = () => 'Foo' +os.release = () => '1.0.0' + +// generates logfile name with mocked date +const _toISOString = Date.prototype.toISOString +Date.prototype.toISOString = () => 'expecteddate' + +const consoleError = console.error +const errors = [] +console.error = (err) => { + errors.push(err) +} t.teardown(() => { + os.type = osType + os.release = osRelease + // needs to put process back in its place in order for tap to exit properly process = _process + Date.prototype.toISOString = _toISOString + console.error = consoleError }) t.afterEach(() => { + errors.length = 0 + npm.log.level = 'silent' // clear out the 'A complete log' message - npmlog.record.length = 0 + npm.log.record.length = 0 + delete process.exitCode }) const mocks = { - npmlog, '../../../lib/utils/error-message.js': (err) => ({ ...err, summary: [['ERR', err.message]], @@ -118,89 +101,43 @@ const mocks = { }), } -let exitHandler = t.mock('../../../lib/utils/exit-handler.js', mocks) +const exitHandler = t.mock('../../../lib/utils/exit-handler.js', mocks) exitHandler.setNpm(npm) -t.test('default exit code', (t) => { - t.plan(1) - - // manually simulate timing handlers - process.emit('timing', 'foo', 1) - process.emit('timing', 'foo', 2) - - // generates logfile name with mocked date - const _toISOString = Date.prototype.toISOString - Date.prototype.toISOString = () => 'expecteddate' - - npmlog.level = 'silent' - const _exit = process.exit - process.exit = (code) => { - t.equal(code, 1, 'should default to error code 1') - } - - // skip console.error logs - const _error = console.error - console.error = () => null - +t.test('exit handler never called - loglevel silent', (t) => { + npm.log.level = 'silent' process.emit('exit', 1) - - t.teardown(() => { - npmlog.level = 'silly' - process.exit = _exit - console.error = _error - Date.prototype.toISOString = _toISOString - }) + const logData = fs.readFileSync(logFile, 'utf8') + t.match(logData, 'Exit handler never called!') + t.match(errors, [''], 'logs one empty string to console.error') + t.end() }) -t.test('handles unknown error', (t) => { - t.plan(2) - - const _toISOString = Date.prototype.toISOString - Date.prototype.toISOString = () => 'expecteddate' - - const sync = writeFileAtomic.sync - writeFileAtomic.sync = (filename, content) => { - t.equal( - redactCwd(filename), - '{CWD}/test/lib/utils/tap-testdir-exit-handler/_logs/expecteddate-debug.log', - 'should use expected log filename' - ) - t.matchSnapshot( - content, - 'should have expected log contents for unknown error' - ) - } - - exitHandler(err) - - t.teardown(() => { - writeFileAtomic.sync = sync - Date.prototype.toISOString = _toISOString - }) +t.test('exit handler never called - loglevel notice', (t) => { + npm.log.level = 'notice' + process.emit('exit', 1) + const logData = fs.readFileSync(logFile, 'utf8') + t.match(logData, 'Exit handler never called!') + t.match(errors, ['', ''], 'logs two empty strings to console.error') t.end() }) -t.test('npm.config not ready', (t) => { - t.plan(1) +t.test('handles unknown error', (t) => { + t.plan(2) - const { npm: unloaded } = mockNpm(t) - const _error = console.error + npm.log.level = 'notice' - t.teardown(() => { - console.error = _error - exitHandler.setNpm(npm) + process.once('timeEnd', (msg) => { + t.equal(msg, 'npm', 'should trigger timeEnd for npm') }) - exitHandler.setNpm(unloaded) - console.error = (msg) => { - t.match( - msg, - /Error: Exit prior to config file resolving./, - 'should exit with config error msg' - ) - } - - exitHandler() + exitHandler(err) + const logData = fs.readFileSync(logFile, 'utf8') + t.matchSnapshot( + logData, + 'should have expected log contents for unknown error' + ) + t.end() }) t.test('fail to write logfile', (t) => { @@ -227,246 +164,164 @@ t.test('console.log output using --json', (t) => { npm.config.set('json', true) t.teardown(() => { - console.error = _error npm.config.set('json', false) }) - const _error = console.error - console.error = (jsonOutput) => { - t.same( - JSON.parse(jsonOutput), - { - error: { - code: 'EBADTHING', // should default error code to E[A-Z]+ - summary: 'Error: EBADTHING Something happened', - detail: 'Error: EBADTHING Something happened', - }, - }, - 'should output expected json output' - ) - } - exitHandler(new Error('Error: EBADTHING Something happened')) + t.same( + JSON.parse(errors[0]), + { + error: { + code: 'EBADTHING', // should default error code to E[A-Z]+ + summary: 'Error: EBADTHING Something happened', + detail: 'Error: EBADTHING Something happened', + }, + }, + 'should output expected json output' + ) }) t.test('throw a non-error obj', (t) => { - t.plan(3) + t.plan(2) const weirdError = { code: 'ESOMETHING', message: 'foo bar', } - const _logError = npmlog.error - npmlog.error = (title, err) => { - t.equal(title, 'weird error', 'should name it a weird error') - t.same(err, weirdError, 'should log given weird error') - } - - const _exit = process.exit - process.exit = (code) => { - t.equal(code, 1, 'should exit with code 1') - } - - exitHandler(weirdError) - - t.teardown(() => { - process.exit = _exit - npmlog.error = _logError + process.once('exit', code => { + t.equal(code, 1, 'exits with exitCode 1') }) + exitHandler(weirdError) + t.match( + npm.log.record.find(r => r.level === 'error'), + { message: 'foo bar' } + ) }) t.test('throw a string error', (t) => { - t.plan(3) - + t.plan(2) const error = 'foo bar' - const _logError = npmlog.error - npmlog.error = (title, err) => { - t.equal(title, '', 'should have an empty name ref') - t.same(err, 'foo bar', 'should log string error') - } - - const _exit = process.exit - process.exit = (code) => { - t.equal(code, 1, 'should exit with code 1') - } - - exitHandler(error) - - t.teardown(() => { - process.exit = _exit - npmlog.error = _logError + process.once('exit', code => { + t.equal(code, 1, 'exits with exitCode 1') }) + exitHandler(error) + t.match( + npm.log.record.find(r => r.level === 'error'), + { message: 'foo bar' } + ) }) t.test('update notification', (t) => { - t.plan(2) - const updateMsg = 'you should update npm!' npm.updateNotification = updateMsg - - const _notice = npmlog.notice - npmlog.notice = (prefix, msg) => { - t.equal(prefix, '', 'should have no prefix') - t.equal(msg, updateMsg, 'should show update message') - } - - exitHandler(err) + npm.log.level = 'silent' t.teardown(() => { - npmlog.notice = _notice delete npm.updateNotification }) + + exitHandler() + t.match( + npm.log.record.find(r => r.level === 'notice'), + { message: 'you should update npm!' } + ) + t.end() }) -t.test('on exit handler', (t) => { - t.plan(2) +t.test('npm.config not ready', (t) => { + t.plan(1) - const _exit = process.exit - process.exit = (code) => { - t.equal(code, 1, 'should default to error code 1') - } + const { npm: unloaded } = mockNpm(t) - process.once('timeEnd', (msg) => { - t.equal(msg, 'npm', 'should trigger timeEnd for npm') + t.teardown(() => { + exitHandler.setNpm(npm) }) - // skip console.error logs - const _error = console.error - console.error = () => null - - process.emit('exit', 1) + exitHandler.setNpm(unloaded) - t.teardown(() => { - console.error = _error - process.exit = _exit - }) + exitHandler() + t.match( + errors[0], + /Error: Exit prior to config file resolving./, + 'should exit with config error msg' + ) + t.end() }) -t.test('it worked', (t) => { - t.plan(2) - - npm.config.set('timing', false) +t.test('timing', (t) => { + npm.config.set('timing', true) t.teardown(() => { - process.exit = _exit - npm.config.set('timing', true) + fs.unlinkSync(timingFile) + npm.config.set('timing', false) }) - const _exit = process.exit - process.exit = (code) => { - process.exit = _exit - t.notOk(code, 'should exit with no code') + exitHandler() + const timingData = JSON.parse(fs.readFileSync(timingFile, 'utf8')) + t.match(timingData, { version: '1.0.0', 'config:load:defaults': Number }) + t.end() +}) - const _info = npmlog.info - npmlog.info = (msg) => { - npmlog.info = _info - t.equal(msg, 'ok', 'should log ok if "it worked"') - } +t.test('timing - with error', (t) => { + npm.config.set('timing', true) - process.emit('exit', 0) - } + t.teardown(() => { + fs.unlinkSync(timingFile) + npm.config.set('timing', false) + }) - exitHandler() + exitHandler(err) + const timingData = JSON.parse(fs.readFileSync(timingFile, 'utf8')) + t.match(timingData, { version: '1.0.0', 'config:load:defaults': Number }) + t.end() }) t.test('uses code from errno', (t) => { t.plan(1) - exitHandler = t.mock('../../../lib/utils/exit-handler.js', mocks) - exitHandler.setNpm(npm) - - npmlog.level = 'silent' - const _exit = process.exit - process.exit = (code) => { - t.equal(code, 127, 'should use set errno') - } - + process.once('exit', code => { + t.equal(code, 127, 'should set exitCode from errno') + }) exitHandler(Object.assign( new Error('Error with errno'), { errno: 127, } )) - - t.teardown(() => { - npmlog.level = 'silly' - process.exit = _exit - }) }) -t.test('uses exitCode as code if using a number', (t) => { +t.test('uses code from number', (t) => { t.plan(1) - exitHandler = t.mock('../../../lib/utils/exit-handler.js', mocks) - exitHandler.setNpm(npm) - - npmlog.level = 'silent' - const _exit = process.exit - process.exit = (code) => { - t.equal(code, 404, 'should use code if a number') - } - + process.once('exit', code => { + t.equal(code, 404, 'should set exitCode from a number') + }) exitHandler(Object.assign( new Error('Error with code type number'), { code: 404, } )) - - t.teardown(() => { - npmlog.level = 'silly' - process.exit = _exit - }) }) t.test('call exitHandler with no error', (t) => { t.plan(1) - - exitHandler = t.mock('../../../lib/utils/exit-handler.js', mocks) - exitHandler.setNpm(npm) - - const _exit = process.exit - process.exit = (code) => { - t.equal(code, undefined, 'should exit with code undefined') - } - - t.teardown(() => { - process.exit = _exit + process.once('exit', code => { + t.equal(code, 0, 'should end up with exitCode 0 (default)') }) - - exitHandler() -}) - -t.test('exit handler called twice', (t) => { - t.plan(2) - - const _verbose = npmlog.verbose - npmlog.verbose = (key, value) => { - t.equal(key, 'stack', 'should log stack in verbose level') - t.match( - value, - /Error: Exit handler called more than once./, - 'should have expected error msg' - ) - npmlog.verbose = _verbose - } - exitHandler() }) 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) }) + exitHandler.setNpm(unloaded) const noStackErr = Object.assign( new Error('Error with no stack'), { @@ -476,85 +331,63 @@ t.test('defaults to log error msg if stack is missing', (t) => { ) delete noStackErr.stack - console.error = (msg) => { - t.equal(msg, 'Error with no stack', 'should use error msg') - } - - exitHandler.setNpm(unloaded) exitHandler(noStackErr) + t.equal(errors[0], 'Error with no stack', 'should use error msg') + t.end() }) t.test('exits cleanly when emitting exit event', (t) => { t.plan(1) - npmlog.level = 'silent' - const _exit = process.exit - process.exit = (code) => { - process.exit = _exit - t.same(code, null, 'should exit with code null') - } - - t.teardown(() => { - process.exit = _exit - npmlog.level = 'silly' - }) - + npm.log.level = 'silent' process.emit('exit') + t.match( + npm.log.record.find(r => r.level === 'info'), + { prefix: 'ok', message: '' } + ) + t.end() }) t.test('do no fancy handling for shellouts', t => { - const { exit } = process const { command } = npm - const { log } = npmlog const LOG_RECORD = [] + npm.command = 'exec' + t.teardown(() => { - npmlog.log = log - process.exit = exit npm.command = command }) - - npmlog.log = function (level, ...args) { - log.call(this, level, ...args) - LOG_RECORD.push(npmlog.record[npmlog.record.length - 1]) - } - - npm.command = 'exec' - - let EXPECT_EXIT = 0 - process.exit = code => { - t.equal(code, EXPECT_EXIT, 'got expected exit code') - EXPECT_EXIT = 0 - } t.beforeEach(() => LOG_RECORD.length = 0) - const loudNoises = () => LOG_RECORD + const loudNoises = () => npm.log.record .filter(({ level }) => ['warn', 'error'].includes(level)) t.test('shellout with a numeric error code', t => { - EXPECT_EXIT = 5 + t.plan(2) + process.once('exit', code => { + t.equal(code, 5, 'got expected exit code') + }) exitHandler(Object.assign(new Error(), { code: 5 })) - t.equal(EXPECT_EXIT, 0, 'called process.exit') - // should log no warnings or errors, verbose/silly is fine. t.strictSame(loudNoises(), [], 'no noisy warnings') - t.end() }) t.test('shellout without a numeric error code (something in npm)', t => { - EXPECT_EXIT = 1 + t.plan(2) + process.once('exit', code => { + t.equal(code, 1, 'got expected exit code') + }) exitHandler(Object.assign(new Error(), { code: 'banana stand' })) - t.equal(EXPECT_EXIT, 0, 'called process.exit') // should log some warnings and errors, because something weird happened t.strictNotSame(loudNoises(), [], 'bring the noise') t.end() }) t.test('shellout with code=0 (extra weird?)', t => { - EXPECT_EXIT = 1 + t.plan(2) + process.once('exit', code => { + t.equal(code, 1, 'got expected exit code') + }) exitHandler(Object.assign(new Error(), { code: 0 })) - t.equal(EXPECT_EXIT, 0, 'called process.exit') - // should log some warnings and errors, because something weird happened t.strictNotSame(loudNoises(), [], 'bring the noise') - t.end() }) t.end() diff --git a/test/lib/utils/perf.js b/test/lib/utils/perf.js deleted file mode 100644 index 840dcb6e32399..0000000000000 --- a/test/lib/utils/perf.js +++ /dev/null @@ -1,38 +0,0 @@ -const t = require('tap') -const logs = [] -const npmlog = require('npmlog') -npmlog.silly = (...msg) => logs.push(['silly', ...msg]) -npmlog.timing = (...msg) => logs.push(['timing', ...msg]) - -t.test('time some stuff', t => { - const timings = {} - process.on('timing', (name, value) => { - timings[name] = (timings[name] || 0) + value - }) - require('../../../lib/utils/perf.js') - process.emit('time', 'foo') - process.emit('time', 'bar') - setTimeout(() => { - process.emit('timeEnd', 'foo') - process.emit('timeEnd', 'bar') - process.emit('time', 'foo') - setTimeout(() => { - process.emit('timeEnd', 'foo') - process.emit('timeEnd', 'baz') - t.match(logs, [ - ['timing', 'foo', /Completed in [0-9]+ms/], - ['timing', 'bar', /Completed in [0-9]+ms/], - ['timing', 'foo', /Completed in [0-9]+ms/], - [ - 'silly', - 'timing', - "Tried to end timer that doesn't exist:", - 'baz', - ], - ]) - t.match(timings, { foo: Number, bar: Number }) - t.equal(timings.foo > timings.bar, true, 'foo should be > bar') - t.end() - }, 100) - }, 100) -})