diff --git a/lib/cli/exit-handler.js b/lib/cli/exit-handler.js index 7d81e79356748..5866c46b57c5f 100644 --- a/lib/cli/exit-handler.js +++ b/lib/cli/exit-handler.js @@ -1,4 +1,4 @@ -const { log, output, time, META } = require('proc-log') +const { log, output, META } = require('proc-log') const errorMessage = require('../utils/error-message.js') const { redactLog: replaceInfo } = require('@npmcli/redact') @@ -7,19 +7,8 @@ let exitHandlerCalled = false let showLogFileError = false process.on('exit', code => { - // process.emit is synchronous, so the timeEnd handler will run before the - // unfinished timer check below - time.end('npm') - const hasLoadedNpm = npm?.config.loaded - // Unfinished timers can be read before config load - if (npm) { - for (const [name, timer] of npm.unfinishedTimers) { - log.silly('unfinished npm timer', name, timer) - } - } - if (!code) { log.info('ok') } else { @@ -31,65 +20,14 @@ process.on('exit', code => { log.error('', 'Exit handler never called!') log.error('', 'This is an error with npm itself. Please report this error at:') log.error('', ' ') - - if (!npm || !npm.silent) { - // eslint-disable-next-line no-console - console.error('') - } - + // eslint-disable-next-line no-console + console.error('') showLogFileError = true } // npm must be loaded to know where the log file was written if (hasLoadedNpm) { - // write the timing file now, this might do nothing based on the configs set. - // we need to call it here in case it errors so we dont tell the user - // about a timing file that doesn't exist - npm.finish() - - const logsDir = npm.logsDir - const logFiles = npm.logFiles - - const timingDir = npm.timingDir - const timingFile = npm.timingFile - - const timing = npm.config.get('timing') - const logsMax = npm.config.get('logs-max') - - // Determine whether to show log file message and why it is - // being shown since in timing mode we always show the log file message - const logMethod = showLogFileError ? 'error' : timing ? 'info' : null - - if (logMethod) { - // just a line break, will be ignored in silent mode - output.error('') - - const message = [] - - if (timingFile) { - message.push(`Timing info written to: ${timingFile}`) - } else if (timing) { - message.push( - `The timing file was not written due to an error writing to the directory: ${timingDir}` - ) - } - - if (logFiles.length) { - message.push(`A complete log of this run can be found in: ${logFiles}`) - } else if (logsMax <= 0) { - // user specified no log file - message.push(`Log files were not written due to the config logs-max=${logsMax}`) - } else { - // could be an error writing to the directory - message.push( - `Log files were not written due to an error writing to the directory: ${logsDir}`, - 'You can rerun the command with `--loglevel=verbose` to see the logs in your terminal' - ) - } - - log[logMethod]('', message.join('\n')) - } - + npm.finish({ showLogFileError }) // This removes any listeners npm setup, mostly for tests to avoid max listener warnings npm.unload() } diff --git a/lib/npm.js b/lib/npm.js index 1deae661bc100..691d13ef1be99 100644 --- a/lib/npm.js +++ b/lib/npm.js @@ -117,13 +117,35 @@ class Npm { this.#logFile.off() } - finish () { + finish ({ showLogFileError } = {}) { this.#timers.finish({ id: this.#runId, command: this.#argvClean, logfiles: this.logFiles, version: this.version, }) + + if (showLogFileError) { + if (!this.silent) { + // just a line break if not in silent mode + output.error('') + } + + const logsMax = this.config.get('logs-max') + + if (this.logFiles.length) { + log.error('', `A complete log of this run can be found in: ${this.logFiles}`) + } else if (logsMax <= 0) { + // user specified no log file + log.error('', `Log files were not written due to the config logs-max=${logsMax}`) + } else { + // could be an error writing to the directory + log.error('', + `Log files were not written due to an error writing to the directory: ${this.#logsDir}` + + '\nYou can rerun the command with `--loglevel=verbose` to see the logs in your terminal' + ) + } + } } get title () { @@ -179,7 +201,7 @@ class Npm { // which we will tell them about at the end if (this.config.get('logs-max') > 0) { await time.start('npm:load:mkdirplogs', () => - fs.mkdir(this.logsDir, { recursive: true }) + fs.mkdir(this.#logsDir, { recursive: true }) .catch((e) => log.verbose('logfile', `could not create logs-dir: ${e}`))) } @@ -208,7 +230,7 @@ class Npm { }) this.#timers.load({ - path: this.config.get('timing') ? this.logPath : null, + path: this.logPath, timing: this.config.get('timing'), }) @@ -281,14 +303,6 @@ class Npm { return 2 } - get unfinishedTimers () { - return this.#timers.unfinished - } - - get finishedTimers () { - return this.#timers.finished - } - get started () { return this.#timers.started } @@ -297,16 +311,12 @@ class Npm { return this.#logFile.files } - get logsDir () { + get #logsDir () { return this.config.get('logs-dir') || join(this.cache, '_logs') } get logPath () { - return resolve(this.logsDir, `${this.#runId}-`) - } - - get timingFile () { - return this.#timers.file + return resolve(this.#logsDir, `${this.#runId}-`) } get npmRoot () { diff --git a/tap-snapshots/test/lib/cli/exit-handler.js.test.cjs b/tap-snapshots/test/lib/cli/exit-handler.js.test.cjs index 3a510647ece8e..cedb56642f26d 100644 --- a/tap-snapshots/test/lib/cli/exit-handler.js.test.cjs +++ b/tap-snapshots/test/lib/cli/exit-handler.js.test.cjs @@ -29,9 +29,9 @@ XX error code ECODE XX error ERR SUMMARY Unknown error XX error ERR DETAIL Unknown error XX verbose exit 1 -XX timing npm Completed in {TIME}ms XX verbose code 1 -XX error Timing info written to: {CWD}/cache/_logs/{DATE}-timing.json +XX timing npm Completed in {TIME}ms +XX info timing Timing info written to: {CWD}/cache/_logs/{DATE}-timing.json XX error A complete log of this run can be found in: {CWD}/cache/_logs/{DATE}-debug-0.log ` @@ -59,8 +59,8 @@ error code ECODE error ERR SUMMARY Unknown error error ERR DETAIL Unknown error verbose exit 1 -timing npm Completed in {TIME}ms verbose code 1 -error Timing info written to: {CWD}/cache/_logs/{DATE}-timing.json +timing npm Completed in {TIME}ms +info timing Timing info written to: {CWD}/cache/_logs/{DATE}-timing.json error A complete log of this run can be found in: {CWD}/cache/_logs/{DATE}-debug-0.log ` diff --git a/tap-snapshots/test/lib/utils/exit-handler.js.test.cjs b/tap-snapshots/test/lib/utils/exit-handler.js.test.cjs deleted file mode 100644 index 3fa13309d6249..0000000000000 --- a/tap-snapshots/test/lib/utils/exit-handler.js.test.cjs +++ /dev/null @@ -1,68 +0,0 @@ -/* IMPORTANT - * This snapshot file is auto-generated, but designed for humans. - * It should be checked into source control and tracked carefully. - * Re-generate by setting TAP_SNAPSHOT=1 and running tests. - * Make sure to inspect the output below. Do not ignore changes! - */ -'use strict' -exports[`test/lib/utils/exit-handler.js TAP handles unknown error with logs and debug file > debug file contents 1`] = ` -XX timing npm:load:whichnode Completed in {TIME}ms -XX timing config:load Completed in {TIME}ms -XX timing npm:load:configload Completed in {TIME}ms -XX timing npm:load:mkdirpcache Completed in {TIME}ms -XX timing npm:load:mkdirplogs Completed in {TIME}ms -XX verbose title npm -XX verbose argv "--fetch-retries" "0" "--cache" "{CWD}/cache" "--loglevel" "silly" "--color" "false" "--timing" "true" -XX timing npm:load:setTitle Completed in {TIME}ms -XX timing npm:load:display Completed in {TIME}ms -XX verbose logfile logs-max:10 dir:{CWD}/cache/_logs/{DATE}- -XX verbose logfile {CWD}/cache/_logs/{DATE}-debug-0.log -XX timing npm:load:logFile Completed in {TIME}ms -XX timing npm:load:timers Completed in {TIME}ms -XX timing npm:load:configScope Completed in {TIME}ms -XX timing npm:load Completed in {TIME}ms -XX verbose stack Error: Unknown error -XX verbose cwd {CWD}/prefix -XX verbose {OS} -XX verbose {NODE-VERSION} -XX verbose npm {NPM-VERSION} -XX error code ECODE -XX error ERR SUMMARY Unknown error -XX error ERR DETAIL Unknown error -XX verbose exit 1 -XX timing npm Completed in {TIME}ms -XX verbose code 1 -XX error Timing info written to: {CWD}/cache/_logs/{DATE}-timing.json -XX error A complete log of this run can be found in: {CWD}/cache/_logs/{DATE}-debug-0.log -` - -exports[`test/lib/utils/exit-handler.js TAP handles unknown error with logs and debug file > logs 1`] = ` -timing npm:load:whichnode Completed in {TIME}ms -timing config:load Completed in {TIME}ms -timing npm:load:configload Completed in {TIME}ms -timing npm:load:mkdirpcache Completed in {TIME}ms -timing npm:load:mkdirplogs Completed in {TIME}ms -verbose title npm -verbose argv "--fetch-retries" "0" "--cache" "{CWD}/cache" "--loglevel" "silly" "--color" "false" "--timing" "true" -timing npm:load:setTitle Completed in {TIME}ms -timing npm:load:display Completed in {TIME}ms -verbose logfile logs-max:10 dir:{CWD}/cache/_logs/{DATE}- -verbose logfile {CWD}/cache/_logs/{DATE}-debug-0.log -timing npm:load:logFile Completed in {TIME}ms -timing npm:load:timers Completed in {TIME}ms -timing npm:load:configScope Completed in {TIME}ms -timing npm:load Completed in {TIME}ms -verbose stack Error: Unknown error -verbose cwd {CWD}/prefix -verbose {OS} -verbose {NODE-VERSION} -verbose npm {NPM-VERSION} -error code ECODE -error ERR SUMMARY Unknown error -error ERR DETAIL Unknown error -verbose exit 1 -timing npm Completed in {TIME}ms -verbose code 1 -error Timing info written to: {CWD}/cache/_logs/{DATE}-timing.json -error A complete log of this run can be found in: {CWD}/cache/_logs/{DATE}-debug-0.log -` diff --git a/test/lib/cli/exit-handler.js b/test/lib/cli/exit-handler.js index d7bedd7341632..3cb4523b3ee51 100644 --- a/test/lib/cli/exit-handler.js +++ b/test/lib/cli/exit-handler.js @@ -382,7 +382,7 @@ t.test('timers fail to write', async (t) => { await exitHandler(new Error()) - t.match(logs.error[2], `error writing to the directory`) + t.match(logs.warn[0], `timing could not write timing file: Error: err`) }) t.test('log files fail to write', async (t) => { @@ -455,7 +455,7 @@ t.test('files from error message with error', async (t) => { t.test('timing with no error', async (t) => { const { exitHandler, timingFile, npm, logs } = await mockExitHandler(t, { - config: { timing: true, loglevel: 'info' }, + config: { timing: true, loglevel: 'silly' }, }) await exitHandler() @@ -463,18 +463,9 @@ t.test('timing with no error', async (t) => { t.equal(process.exitCode, 0) - const msg = logs.info[1] - t.match(msg, /A complete log of this run can be found in:/) + const msg = logs.info.byTitle('timing')[0] t.match(msg, /Timing info written to:/) - t.match( - timingFileData.timers, - Object.keys(npm.finishedTimers).reduce((acc, k) => { - acc[k] = Number - return acc - }, {}) - ) - t.strictSame(npm.unfinishedTimers, new Map()) t.match(timingFileData, { metadata: { command: [], @@ -482,6 +473,7 @@ t.test('timing with no error', async (t) => { logfiles: [String], }, timers: { + 'npm:load': Number, npm: Number, }, }) @@ -511,7 +503,6 @@ t.test('unfinished timers', async (t) => { const timingFileData = await timingFile() t.equal(process.exitCode, 0) - t.match(npm.unfinishedTimers, new Map([['foo', Number], ['bar', Number]])) t.match(timingFileData, { metadata: { command: [],