Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

chore(refactor): refactor exit handler and tests #3482

Merged
merged 1 commit into from Jul 12, 2021
Merged

chore(refactor): refactor exit handler and tests #3482

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
60 changes: 41 additions & 19 deletions lib/npm.js
View file
Open in desktop
@@ -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'))
Expand Down Expand Up @@ -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()
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this is a great intermediate step to avoid the singleton issue 🎉

procLogListener()
process.emit('time', 'npm')
this.version = require('../package.json').version
Expand All @@ -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
}
Expand Down Expand Up @@ -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)
207 changes: 95 additions & 112 deletions lib/utils/exit-handler.js
View file
Open in desktop
@@ -1,4 +1,3 @@
const log = require('npmlog')
const os = require('os')
const path = require('path')
const writeFileAtomic = require('write-file-atomic')
Expand All @@ -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
Expand All @@ -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
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👏 thank you for calling this out, it's a super nice reminder!

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 {
Expand All @@ -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')))
Expand All @@ -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('', ' <https://github.com/npm/cli/issues>')
npm.log.error('', 'This is an error with npm itself. Please report this error at:')
npm.log.error('', ' <https://github.com/npm/cli/issues>')
// TODO this doesn't have an npm.config.loaded guard
writeLogFile()
}
Expand All @@ -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:',
Expand All @@ -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)
Expand All @@ -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) {

Expand Down