Skip to content

Commit

Permalink
chore: fix flaky log file tests
Browse files Browse the repository at this point in the history
  • Loading branch information
lukekarrys committed Aug 31, 2023
1 parent 7f81e96 commit b8a5764
Show file tree
Hide file tree
Showing 2 changed files with 11 additions and 3 deletions.
1 change: 1 addition & 0 deletions tap-snapshots/test/lib/utils/exit-handler.js.test.cjs
Expand Up @@ -63,4 +63,5 @@ verbose exit 1
timing npm Completed in {TIME}ms
verbose code 1
error A complete log of this run can be found in: {CWD}/cache/_logs/{DATE}-debug-0.log
silly logfile done cleaning log files
`
13 changes: 10 additions & 3 deletions test/lib/utils/exit-handler.js
Expand Up @@ -132,6 +132,8 @@ t.test('handles unknown error with logs and debug file', async (t) => {
const { exitHandler, debugFile, logs } = await mockExitHandler(t)

await exitHandler(err('Unknown error', 'ECODE'))
// force logfile cleaning logs to happen since those are purposefully not awaited
await require('timers/promises').setTimeout(200)

This comment has been minimized.

Copy link
@rotu

rotu Sep 6, 2023

Contributor

This change looks strange to me. Why was it necessary?

This comment has been minimized.

Copy link
@lukekarrys

lukekarrys Sep 7, 2023

Author Member

We have a purposeful race condition where npm attempts to clean up old log files inside a Promise without await-ing the result. We do this so that for short lived processes, the process will still exit even if log cleaning has not finished.

This has caused us to have flaky tests because CI machines are often slower than others which causes that promise to usually have finished. This change is strange, since it only waits an arbitrary amount of time, but that amount of time should be enough for any machine to finish removing a few files.

This comment has been minimized.

Copy link
@rotu

rotu Sep 8, 2023

Contributor

Doesn't Node wait for the event queue to be empty before exiting? How would the process exit if those log cleaning promises are still pending?

This comment has been minimized.

Copy link
@lukekarrys

lukekarrys Sep 11, 2023

Author Member

We only wait for stderr and stdout to be flushed and then we call process.exit from inside the exit handler. This forces things like the log file cleaning and update notifier to end no matter their state.

https://github.com/npm/cli/blob/latest/lib/utils/exit-handler.js#L217-L223


const fileLogs = await debugFile()
const fileLines = fileLogs.split('\n')
Expand All @@ -141,14 +143,19 @@ t.test('handles unknown error with logs and debug file', async (t) => {

t.equal(process.exitCode, 1)

let skippedLogs = 0
logs.forEach((logItem, i) => {
const logLines = format(i, ...logItem).trim().split(os.EOL)
logLines.forEach((line) => {
for (const line of logLines) {
if (line.includes('logfile') && line.includes('cleaning')) {
skippedLogs++
continue
}
t.match(fileLogs.trim(), line, 'log appears in debug file')
})
}
})

t.equal(logs.length, parseInt(lastLog) + 1)
t.equal(logs.length - skippedLogs, parseInt(lastLog) + 1)
t.match(logs.error, [
['code', 'ECODE'],
['ERR SUMMARY', 'Unknown error'],
Expand Down

0 comments on commit b8a5764

Please sign in to comment.