chore: fix flaky exit handler test (#6286)

tap-snapshots/test/lib/utils/exit-handler.js.test.cjs

@@ -6,35 +6,34 @@
  */
 'use strict'
 exports[`test/lib/utils/exit-handler.js TAP handles unknown error with logs and debug file > debug file contents 1`] = `
-0 timing npm:load:whichnode Completed in {TIME}ms
-13 timing config:load Completed in {TIME}ms
-14 timing npm:load:configload Completed in {TIME}ms
-15 timing npm:load:mkdirpcache Completed in {TIME}ms
-16 timing npm:load:mkdirplogs Completed in {TIME}ms
-17 verbose title npm
-18 verbose argv "--fetch-retries" "0" "--cache" "{CWD}/cache" "--loglevel" "notice"
-19 timing npm:load:setTitle Completed in {TIME}ms
-21 timing npm:load:display Completed in {TIME}ms
-22 verbose logfile logs-max:10 dir:{CWD}/cache/_logs/{DATE}-
-23 verbose logfile {CWD}/cache/_logs/{DATE}-debug-0.log
-24 timing npm:load:logFile Completed in {TIME}ms
-25 timing npm:load:timers Completed in {TIME}ms
-26 timing npm:load:configScope Completed in {TIME}ms
-27 timing npm:load Completed in {TIME}ms
-28 silly logfile done cleaning log files
-29 verbose stack Error: Unknown error
-30 verbose cwd {CWD}/prefix
-31 verbose Foo 1.0.0
-32 verbose node v1.0.0
-33 verbose npm  v1.0.0
-34 error code ECODE
-35 error ERR SUMMARY Unknown error
-36 error ERR DETAIL Unknown error
-37 verbose exit 1
-38 timing npm Completed in {TIME}ms
-39 verbose code 1
-40 error A complete log of this run can be found in:
-40 error     {CWD}/cache/_logs/{DATE}-debug-0.log
+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" "notice"
+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 Foo 1.0.0
+XX verbose node v1.0.0
+XX verbose npm  v1.0.0
+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 A complete log of this run can be found in:
+XX error     {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`] = `
@@ -53,7 +52,6 @@ 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
-silly logfile done cleaning log files
 verbose stack Error: Unknown error
 verbose cwd {CWD}/prefix
 verbose  Foo 1.0.0

test/lib/utils/exit-handler.js

@@ -27,6 +27,9 @@ t.formatSnapshot = (obj) => {
 t.cleanSnapshot = (path) => cleanDate(cleanCwd(path))
   // Config loading is dependent on env so strip those from snapshots
   .replace(/.*timing config:load:.*\n/gm, '')
+  // logfile cleaning is not awaited so it races with the process.exit
+  // in this test and can cause snapshot failures so we always remove them
+  .replace(/.*silly logfile.*cleaning.*\n/gm, '')
   .replace(/(Completed in )\d+(ms)/g, '$1{TIME}$2')
   .replace(/(removing )\d+( files)/g, '$1${NUM}2')
 
@@ -106,13 +109,11 @@ const mockExitHandler = async (t, { init, load, testdir, config, mocks, files }
     errors,
     npm,
     // Make it async to make testing ergonomics a little easier so we dont need
-    // to t.plan() every test to make sure we get process.exit called. Also
-    // introduce a small artificial delay so the logs are consistently finished
-    // by the time the exit handler forces process.exit
-    exitHandler: (...args) => new Promise(res => setTimeout(() => {
+    // to t.plan() every test to make sure we get process.exit called.
+    exitHandler: (...args) => new Promise(res => {
       process.once('exit', res)
       exitHandler(...args)
-    }, 50)),
+    }),
   }
 }
 
@@ -134,30 +135,32 @@ t.test('handles unknown error with logs and debug file', async (t) => {
 
   await exitHandler(err('Unknown error', 'ECODE'))
 
-  const debugContent = await debugFile()
+  const fileLogs = await debugFile()
+  const fileLines = fileLogs.split('\n')
+
+  const lineNumber = /^(\d+)\s/
+  const lastLog = fileLines[fileLines.length - 1].match(lineNumber)[1]
 
   t.equal(process.exitCode, 1)
+
   logs.forEach((logItem, i) => {
     const logLines = format(i, ...logItem).trim().split(os.EOL)
     logLines.forEach((line) => {
-      t.match(debugContent.trim(), line, 'log appears in debug file')
+      t.match(fileLogs.trim(), line, 'log appears in debug file')
     })
   })
 
-  const lastLog = debugContent
-    .split('\n')
-    .reduce((__, l) => parseInt(l.match(/^(\d+)\s/)[1]))
-  t.equal(logs.length, lastLog + 1)
+  t.equal(logs.length, parseInt(lastLog) + 1)
   t.match(logs.error, [
     ['code', 'ECODE'],
     ['ERR SUMMARY', 'Unknown error'],
     ['ERR DETAIL', 'Unknown error'],
   ])
-  t.match(debugContent, /\d+ error code ECODE/)
-  t.match(debugContent, /\d+ error ERR SUMMARY Unknown error/)
-  t.match(debugContent, /\d+ error ERR DETAIL Unknown error/)
+  t.match(fileLogs, /\d+ error code ECODE/)
+  t.match(fileLogs, /\d+ error ERR SUMMARY Unknown error/)
+  t.match(fileLogs, /\d+ error ERR DETAIL Unknown error/)
   t.matchSnapshot(logs, 'logs')
-  t.matchSnapshot(debugContent, 'debug file contents')
+  t.matchSnapshot(fileLines.map(l => l.replace(lineNumber, 'XX ')), 'debug file contents')
 })
 
 t.test('exit handler never called - loglevel silent', async (t) => {