feat: make staleness check more robust (#74)

BREAKING CHANGE: We were marking the lock as compromised when system went into sleep or if the event loop was busy taking too long to run the internals timers, Now we keep track of the mtime updated by the current process, and if we lose some cycles in the update process but recover and the mtime is still ours we do not mark the lock as compromised.

closes #71 

ref:
ipfs/js-ipfs-repo#188 (comment)

Author: hugomrdias

.travis.yml

@@ -1,6 +1,7 @@
 language: node_js
 node_js:
-  - "node"
+# nodejs 11.11.X was failing with this https://travis-ci.org/moxystudio/node-proper-lockfile/jobs/503161746#L469
+#   - "node"
   - "lts/*"
 # Report coverage
 after_success:

lib/lockfile.js

@@ -26,7 +26,7 @@ function acquireLock(file, options, callback) {
     options.fs.mkdir(getLockFile(file, options), (err) => {
         // If successful, we are done
         if (!err) {
-            return callback();
+            return options.fs.stat(getLockFile(file, options), callback);
         }
 
         // If error is not EEXIST then some other error occurred while locking
@@ -93,47 +93,64 @@ function updateLock(file, options) {
 
     lock.updateDelay = lock.updateDelay || options.update;
     lock.updateTimeout = setTimeout(() => {
-        const mtime = Date.now() / 1000;
-
         lock.updateTimeout = null;
 
-        options.fs.utimes(getLockFile(file, options), mtime, mtime, (err) => {
-            // Ignore if the lock was released
-            if (lock.released) {
-                return;
-            }
-
-            // Verify if we are within the stale threshold
-            if (lock.lastUpdate <= Date.now() - options.stale && lock.lastUpdate > Date.now() - (options.stale * 2)) {
-                const err = Object.assign(
-                    new Error(lock.updateError || 'Unable to update lock within the stale threshold'),
-                    { code: 'ECOMPROMISED' }
-                );
-
-                return setLockAsCompromised(file, lock, err);
-            }
-
-            // If the file is older than (stale * 2), we assume the clock is moved manually,
-            // which we consider a valid case
+        // Check if mtime is still ours if it is we can still recover from a system sleep or a busy event loop
+        options.fs.stat(getLockFile(file, options), (err, stat) => {
+            const isOverThreshold = lock.lastUpdate + options.stale < Date.now();
 
             // If it failed to update the lockfile, keep trying unless
-            // the lockfile was deleted!
+            // the lockfile was deleted or we are over the threshold
             if (err) {
-                if (err.code === 'ENOENT') {
+                if (err.code === 'ENOENT' || isOverThreshold) {
                     return setLockAsCompromised(file, lock, Object.assign(err, { code: 'ECOMPROMISED' }));
                 }
 
-                lock.updateError = err;
                 lock.updateDelay = 1000;
 
                 return updateLock(file, options);
             }
 
-            // All ok, keep updating..
-            lock.lastUpdate = Date.now();
-            lock.updateError = null;
-            lock.updateDelay = null;
-            updateLock(file, options);
+            const isMtimeOurs = lock.mtime.getTime() === stat.mtime.getTime();
+
+            if (!isMtimeOurs) {
+                return setLockAsCompromised(
+                    file,
+                    lock,
+                    Object.assign(
+                        new Error('Unable to update lock within the stale threshold'),
+                        { code: 'ECOMPROMISED' }
+                    ));
+            }
+
+            const mtime = new Date();
+
+            options.fs.utimes(getLockFile(file, options), mtime, mtime, (err) => {
+                const isOverThreshold = lock.lastUpdate + options.stale < Date.now();
+
+                // Ignore if the lock was released
+                if (lock.released) {
+                    return;
+                }
+
+                // If it failed to update the lockfile, keep trying unless
+                // the lockfile was deleted or we are over the threshold
+                if (err) {
+                    if (err.code === 'ENOENT' || isOverThreshold) {
+                        return setLockAsCompromised(file, lock, Object.assign(err, { code: 'ECOMPROMISED' }));
+                    }
+
+                    lock.updateDelay = 1000;
+
+                    return updateLock(file, options);
+                }
+
+                // All ok, keep updating..
+                lock.mtime = mtime;
+                lock.lastUpdate = Date.now();
+                lock.updateDelay = null;
+                updateLock(file, options);
+            });
         });
     }, lock.updateDelay);
 
@@ -198,7 +215,7 @@ function lock(file, options, callback) {
         const operation = retry.operation(options.retries);
 
         operation.attempt(() => {
-            acquireLock(file, options, (err) => {
+            acquireLock(file, options, (err, stat) => {
                 if (operation.retry(err)) {
                     return;
                 }
@@ -209,6 +226,7 @@ function lock(file, options, callback) {
 
                 // We now own the lock
                 const lock = locks[file] = {
+                    mtime: stat.mtime,
                     options,
                     lastUpdate: Date.now(),
                 };

package-lock.json

@@ -69,6 +69,7 @@
     "p-defer": "^1.0.0",
     "rimraf": "^2.6.2",
     "stable": "^0.1.8",
-    "standard-version": "^5.0.0"
+    "standard-version": "^5.0.0",
+    "thread-sleep": "^2.1.0"
   }
 }

package.json

@@ -2,6 +2,7 @@
 
 const fs = require('graceful-fs');
 const mkdirp = require('mkdirp');
+const sleep = require('thread-sleep');
 const rimraf = require('rimraf');
 const execa = require('execa');
 const pDefer = require('p-defer');
@@ -183,12 +184,16 @@ it('should remove and acquire over stale locks', async () => {
 
 it('should retry if the lockfile was removed when verifying staleness', async () => {
     const mtime = (Date.now() - 60000) / 1000;
+    let count = 0;
     const customFs = {
         ...fs,
         mkdir: jest.fn((...args) => fs.mkdir(...args)),
         stat: jest.fn((...args) => {
-            rimraf.sync(`${tmpDir}/foo.lock`);
+            if (count % 2 === 0) {
+                rimraf.sync(`${tmpDir}/foo.lock`);
+            }
             fs.stat(...args);
+            count += 1;
         }),
     };
 
@@ -199,7 +204,7 @@ it('should retry if the lockfile was removed when verifying staleness', async ()
     await lockfile.lock(`${tmpDir}/foo`, { fs: customFs });
 
     expect(customFs.mkdir).toHaveBeenCalledTimes(2);
-    expect(customFs.stat).toHaveBeenCalledTimes(1);
+    expect(customFs.stat).toHaveBeenCalledTimes(2);
     expect(fs.statSync(`${tmpDir}/foo.lock`).mtime.getTime()).toBeGreaterThan(Date.now() - 3000);
 });
 
@@ -394,7 +399,7 @@ it('should call the compromised function if updating the lockfile took too much
 
     const handleCompromised = (err) => {
         expect(err.code).toBe('ECOMPROMISED');
-        expect(err.message).toMatch('threshold');
+        expect(err.message).toMatch('foo');
 
         deferred.resolve();
     };
@@ -499,3 +504,19 @@ it('should set update to a maximum of stale / 2', async () => {
 
     expect(fs.statSync(`${tmpDir}/foo.lock`).mtime.getTime()).toBeGreaterThan(mtime);
 }, 10000);
+
+it('should not fail to update mtime when we are over the threshold but mtime is ours, first', async () => {
+    fs.writeFileSync(`${tmpDir}/foo`, '');
+    await lockfile.lock(`${tmpDir}/foo`, { update: 1000, stale: 2000 });
+    sleep(3000);
+    await pDelay(5000);
+}, 16000);
+
+it('should not fail to update mtime when we are over the threshold but mtime is ours, not first', async () => {
+    fs.writeFileSync(`${tmpDir}/foo`, '');
+    await lockfile.lock(`${tmpDir}/foo`, { update: 1000, stale: 2000 });
+    setTimeout(() => {
+        sleep(3000);
+    }, 1000);
+    await pDelay(5000);
+}, 16000);