Skip to content

Commit

Permalink
feat: write eresolve error files to the logs directory
Browse files Browse the repository at this point in the history
Also refactor all files written to the logs directory to use the same
code path for file name creation.
  • Loading branch information
lukekarrys committed Sep 27, 2022
1 parent 3445da0 commit e64d69a
Show file tree
Hide file tree
Showing 16 changed files with 192 additions and 234 deletions.
15 changes: 9 additions & 6 deletions lib/npm.js
Original file line number Diff line number Diff line change
Expand Up @@ -18,11 +18,9 @@ const replaceInfo = require('./utils/replace-info.js')
const updateNotifier = require('./utils/update-notifier.js')
const pkg = require('../package.json')
const cmdList = require('./utils/cmd-list.js')
const runId = require('./utils/run-id.js')

let warnedNonDashArg = false
const _load = Symbol('_load')
const RUN_ID = runId()

class Npm extends EventEmitter {
static get version () {
Expand All @@ -34,16 +32,16 @@ class Npm extends EventEmitter {
loadErr = null
argv = []

#runId = new Date().toISOString().replace(/[.:]/g, '_')
#loadPromise = null
#tmpFolder = null
#title = 'npm'
#argvClean = []
#chalk = null

#logFile = new LogFile({ id: RUN_ID })
#logFile = new LogFile()
#display = new Display()
#timers = new Timers({
id: RUN_ID,
start: 'npm',
listener: (name, ms) => {
const args = ['timing', name, `Completed in ${ms}ms`]
Expand Down Expand Up @@ -209,6 +207,7 @@ class Npm extends EventEmitter {

writeTimingFile () {
this.#timers.writeFile({
id: this.#runId,
command: this.#argvClean,
logfiles: this.logFiles,
version: this.version,
Expand Down Expand Up @@ -289,15 +288,15 @@ class Npm extends EventEmitter {

this.time('npm:load:logFile', () => {
this.#logFile.load({
dir: this.logsDir,
path: this.logPath,
logsMax: this.config.get('logs-max'),
})
log.verbose('logfile', this.#logFile.files[0] || 'no logfile created')
})

this.time('npm:load:timers', () =>
this.#timers.load({
dir: this.config.get('timing') ? this.logsDir : null,
path: this.config.get('timing') ? this.logPath : null,
})
)

Expand Down Expand Up @@ -371,6 +370,10 @@ class Npm extends EventEmitter {
return this.config.get('logs-dir') || join(this.cache, '_logs')
}

get logPath () {
return resolve(this.logsDir, `${this.#runId}-`)
}

get timingFile () {
return this.#timers.file
}
Expand Down
10 changes: 7 additions & 3 deletions lib/utils/error-message.js
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@ const log = require('./log-shim')
module.exports = (er, npm) => {
const short = []
const detail = []
const files = []

if (er.message) {
er.message = replaceInfo(er.message)
Expand All @@ -17,14 +18,17 @@ module.exports = (er, npm) => {
}

switch (er.code) {
case 'ERESOLVE':
case 'ERESOLVE': {
short.push(['ERESOLVE', er.message])
detail.push(['', ''])
// XXX(display): error messages are logged so we use the logColor since that is based
// on stderr. This should be handled solely by the display layer so it could also be
// printed to stdout if necessary.
detail.push(['', report(er, !!npm.logColor, resolve(npm.cache, 'eresolve-report.txt'))])
const { explanation, file } = report(er, !!npm.logColor)
detail.push(['', explanation])
files.push(['eresolve-report.txt', file])
break
}

case 'ENOLOCK': {
const cmd = npm.command || ''
Expand Down Expand Up @@ -398,5 +402,5 @@ module.exports = (er, npm) => {

break
}
return { summary: short, detail: detail }
return { summary: short, detail, files }
}
35 changes: 25 additions & 10 deletions lib/utils/exit-handler.js
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
const os = require('os')
const fs = require('@npmcli/fs')

const log = require('./log-shim.js')
const errorMessage = require('./error-message.js')
Expand All @@ -18,11 +19,10 @@ process.on('exit', code => {
// unfinished timer check below
process.emit('timeEnd', 'npm')

const hasNpm = !!npm
const hasLoadedNpm = hasNpm && npm.config.loaded
const hasLoadedNpm = npm?.config.loaded

// Unfinished timers can be read before config load
if (hasNpm) {
if (npm) {
for (const [name, timer] of npm.unfinishedTimers) {
log.verbose('unfinished npm timer', name, timer)
}
Expand Down Expand Up @@ -111,10 +111,9 @@ const exitHandler = err => {

log.disableProgress()

const hasNpm = !!npm
const hasLoadedNpm = hasNpm && npm.config.loaded
const hasLoadedNpm = npm?.config.loaded

if (!hasNpm) {
if (!npm) {
err = err || new Error('Exit prior to setting npm in exit handler')
// eslint-disable-next-line no-console
console.error(err.stack || err.message)
Expand Down Expand Up @@ -181,17 +180,33 @@ const exitHandler = err => {
}
}

const msg = errorMessage(err, npm)
for (const errline of [...msg.summary, ...msg.detail]) {
const { summary, detail, files = [] } = errorMessage(err, npm)

for (let [file, content] of files) {
file = `${npm.logPath}${file}`
content = `'Log files:\n${npm.logFiles.join('\n')}\n\n${content.trim()}\n`
try {
fs.withOwnerSync(
file,
() => fs.writeFileSync(file, content),
{ owner: 'inherit' }
)
detail.push(['', `\n\nFor a full report see:\n${file}`])
} catch (err) {
log.warn('', `Could not write error message to ${file} due to ${err}`)
}
}

for (const errline of [...summary, ...detail]) {
log.error(...errline)
}

if (hasLoadedNpm && npm.config.get('json')) {
const error = {
error: {
code: err.code,
summary: messageText(msg.summary),
detail: messageText(msg.detail),
summary: messageText(summary),
detail: messageText(detail),
},
}
npm.outputError(JSON.stringify(error, null, 2))
Expand Down
35 changes: 16 additions & 19 deletions lib/utils/explain-eresolve.js
Original file line number Diff line number Diff line change
@@ -1,7 +1,6 @@
// this is called when an ERESOLVE error is caught in the exit-handler,
// or when there's a log.warn('eresolve', msg, explanation), to turn it
// into a human-intelligible explanation of what's wrong and how to fix.
const { writeFileSync } = require('fs')
const { explainEdge, explainNode, printNode } = require('./explain-dep.js')

// expl is an explanation object that comes from Arborist. It looks like:
Expand Down Expand Up @@ -45,27 +44,25 @@ const explain = (expl, color, depth) => {
}

// generate a full verbose report and tell the user how to fix it
const report = (expl, color, fullReport) => {
const orNoStrict = expl.strictPeerDeps ? '--no-strict-peer-deps, ' : ''
const fix = `Fix the upstream dependency conflict, or retry
this command with ${orNoStrict}--force, or --legacy-peer-deps
to accept an incorrect (and potentially broken) dependency resolution.`

writeFileSync(fullReport, `# npm resolution error report
${new Date().toISOString()}
${explain(expl, false, Infinity)}
const report = (expl, color) => {
const flags = [
expl.strictPeerDeps ? '--no-strict-peer-deps' : '',
'--force',
'--legacy-peer-deps',
].filter(Boolean)

${fix}
const or = (arr) => arr.length <= 2
? arr.join(' or ') :
arr.map((v, i, l) => i + 1 === l.length ? `or ${v}` : v).join(', ')

Raw JSON explanation object:
${JSON.stringify(expl, null, 2)}
`, 'utf8')
const fix = `Fix the upstream dependency conflict, or retry
this command with ${or(flags)}
to accept an incorrect (and potentially broken) dependency resolution.`

return explain(expl, color, 4) +
`\n\n${fix}\n\nSee ${fullReport} for a full report.`
return {
explanation: `${explain(expl, color, 4)}\n\n${fix}`,
file: `# npm resolution error report\n\n${explain(expl, false, Infinity)}\n\n${fix}`,
}
}

module.exports = {
Expand Down
17 changes: 5 additions & 12 deletions lib/utils/log-file.js
Original file line number Diff line number Diff line change
Expand Up @@ -7,16 +7,11 @@ const MiniPass = require('minipass')
const fsMiniPass = require('fs-minipass')
const fs = require('@npmcli/fs')
const log = require('./log-shim')
const runId = require('./run-id')

const padZero = (n, length) => n.toString().padStart(length.toString().length, '0')
const globify = pattern => pattern.split('\\').join('/')

class LogFiles {
// If we write multiple log files we want them all to have the same
// identifier for sorting and matching purposes
#logId = null

// Default to a plain minipass stream so we can buffer
// initial writes before we know the cache location
#logStream = null
Expand All @@ -34,16 +29,14 @@ class LogFiles {

#fileLogCount = 0
#totalLogCount = 0
#dir = null
#path = null
#logsMax = null
#files = []

constructor ({
id = runId(),
maxLogsPerFile = 50_000,
maxFilesPerProcess = 5,
} = {}) {
this.#logId = id
this.#MAX_LOGS_PER_FILE = maxLogsPerFile
this.#MAX_FILES_PER_PROCESS = maxFilesPerProcess
this.on()
Expand Down Expand Up @@ -73,18 +66,18 @@ class LogFiles {
this.#endStream()
}

load ({ dir, logsMax = Infinity } = {}) {
load ({ path, logsMax = Infinity } = {}) {
// dir is user configurable and is required to exist so
// this can error if the dir is missing or not configured correctly
this.#dir = dir
this.#path = path
this.#logsMax = logsMax

// Log stream has already ended
if (!this.#logStream) {
return
}

log.verbose('logfile', `logs-max:${logsMax} dir:${dir}`)
log.verbose('logfile', `logs-max:${logsMax} dir:${this.#path}`)

// Pipe our initial stream to our new file stream and
// set that as the new log logstream for future writes
Expand Down Expand Up @@ -164,7 +157,7 @@ class LogFiles {
}

#getLogFilePath (count = '') {
return path.resolve(this.#dir, `${this.#logId}-debug-${count}.log`)
return `${this.#path}debug-${count}.log`
}

#openLogFile () {
Expand Down
3 changes: 0 additions & 3 deletions lib/utils/run-id.js

This file was deleted.

17 changes: 5 additions & 12 deletions lib/utils/timers.js
Original file line number Diff line number Diff line change
@@ -1,25 +1,21 @@
const EE = require('events')
const { resolve } = require('path')
const fs = require('@npmcli/fs')
const log = require('./log-shim')
const runId = require('./run-id')

// This is an event emiiter but on/off
// only listen on a single internal event that gets
// emitted whenever a timer ends
class Timers extends EE {
file = null

#id = null
#unfinished = new Map()
#finished = {}
#onTimeEnd = Symbol('onTimeEnd')
#initialListener = null
#initialTimer = null

constructor ({ id = runId(), listener = null, start = 'npm' } = {}) {
constructor ({ listener = null, start = 'npm' } = {}) {
super()
this.#id = id
this.#initialListener = listener
this.#initialTimer = start
this.#init()
Expand Down Expand Up @@ -71,9 +67,9 @@ class Timers extends EE {
return end
}

load ({ dir } = {}) {
if (dir) {
this.file = resolve(dir, `${this.#id}-timing.json`)
load ({ path } = {}) {
if (path) {
this.file = `${path}timing.json`
}
}

Expand All @@ -86,10 +82,7 @@ class Timers extends EE {
const globalStart = this.started
const globalEnd = this.#finished.npm || Date.now()
const content = {
metadata: {
id: this.#id,
...metadata,
},
metadata,
timers: this.#finished,
// add any unfinished timers with their relative start/end
unfinishedTimers: [...this.#unfinished.entries()].reduce((acc, [name, start]) => {
Expand Down
Loading

0 comments on commit e64d69a

Please sign in to comment.