more debugging

Author: jenseng

workspaces/libnpmexec/lib/with-lock.js

@@ -1,3 +1,4 @@
+/* eslint-disable no-console */
 const fs = require('node:fs/promises')
 const { rmdirSync } = require('node:fs')
 const promiseRetry = require('promise-retry')
@@ -143,18 +144,28 @@ async function maintainLock (lockPath) {
   // fs.utimes operates on floating points seconds (directly, or via strings/Date objects), which may not match the underlying filesystem's mtime precision, meaning that we might read a slightly different mtime than we write. always round to the nearest second, since all filesystems support at least second precision
   let mtime = Math.round(stats.mtimeMs / 1000)
   const signal = controller.signal
+  let touchCount = 0
 
   async function touchLock () {
+    touchCount++
     try {
+      const currentTouchCount = touchCount
+      const start = Date.now()
+      console.log(`${currentTouchCount} fs.stat start`)
       const currentStats = (await fs.stat(lockPath))
+      console.log(`${currentTouchCount} fs.stat done in ${Date.now() - start}ms`)
       const currentMtime = Math.round(currentStats.mtimeMs / 1000)
       if (currentStats.ino !== stats.ino || currentMtime !== mtime) {
+        console.log(`${currentTouchCount} expected ${currentStats.ino} === ${stats.ino} and ${currentMtime} === ${mtime}`)
         throw new Error('Lock compromised')
       }
       mtime = Math.round(Date.now() / 1000)
       // touch the lock, unless we just released it during this iteration
       if (currentLocks.has(lockPath)) {
+        const start2 = Date.now()
+        console.log(`${currentTouchCount} fs.utimes start`)
         await fs.utimes(lockPath, mtime, mtime)
+        console.log(`${currentTouchCount} fs.utimes done in ${Date.now() - start2}ms`)
       }
     } catch (err) {
       // stats mismatch or other fs error means the lock was compromised