From f266158909b8cc23e3c3ca2fca7214df2f416589 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Andr=C3=A9=20Cruz?= Date: Wed, 3 Apr 2019 13:11:27 +0100 Subject: [PATCH] fix: fix mtime precision on some filesystems (#88) Closes #82, #87 --- lib/lockfile.js | 63 +++++++--------- lib/mtime-precision.js | 55 ++++++++++++++ test/check.test.js | 2 +- test/lock.test.js | 167 ++++++++++++++++++++++++++--------------- test/unlock.test.js | 21 +++--- 5 files changed, 198 insertions(+), 110 deletions(-) create mode 100644 lib/mtime-precision.js diff --git a/lib/lockfile.js b/lib/lockfile.js index 3cd769b..97b6637 100644 --- a/lib/lockfile.js +++ b/lib/lockfile.js @@ -4,6 +4,7 @@ const path = require('path'); const fs = require('graceful-fs'); const retry = require('retry'); const onExit = require('signal-exit'); +const mtimePrecision = require('./mtime-precision'); const locks = {}; @@ -22,11 +23,24 @@ function resolveCanonicalPath(file, options, callback) { } function acquireLock(file, options, callback) { + const lockfilePath = getLockFile(file, options); + // Use mkdir to create the lockfile (atomic operation) - options.fs.mkdir(getLockFile(file, options), (err) => { - // If successful, we are done + options.fs.mkdir(lockfilePath, (err) => { if (!err) { - return options.fs.stat(getLockFile(file, options), callback); + // At this point, we acquired the lock! + // Probe the mtime precision + return mtimePrecision.probe(lockfilePath, options.fs, (err, mtime, mtimePrecision) => { + // If it failed, try to remove the lock.. + /* istanbul ignore if */ + if (err) { + options.fs.rmdir(lockfilePath, () => {}); + + return callback(err); + } + + callback(null, mtime, mtimePrecision); + }); } // If error is not EEXIST then some other error occurred while locking @@ -39,7 +53,7 @@ function acquireLock(file, options, callback) { return callback(Object.assign(new Error('Lock file is already being held'), { code: 'ELOCKED', file })); } - options.fs.stat(getLockFile(file, options), (err, stat) => { + options.fs.stat(lockfilePath, (err, stat) => { if (err) { // Retry if the lockfile has been removed (meanwhile) // Skip stale check to avoid recursiveness @@ -95,8 +109,9 @@ function updateLock(file, options) { lock.updateTimeout = setTimeout(() => { lock.updateTimeout = null; - // 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) => { + // Stat the file to 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(lock.lockfilePath, (err, stat) => { const isOverThreshold = lock.lastUpdate + options.stale < Date.now(); // If it failed to update the lockfile, keep trying unless @@ -111,7 +126,7 @@ function updateLock(file, options) { return updateLock(file, options); } - const isMtimeOurs = lock.mtimeChecker(lock.mtime, stat.mtime); + const isMtimeOurs = lock.mtime.getTime() === stat.mtime.getTime(); if (!isMtimeOurs) { return setLockAsCompromised( @@ -123,9 +138,9 @@ function updateLock(file, options) { )); } - const mtime = new Date(); + const mtime = mtimePrecision.getMtime(lock.mtimePrecision); - options.fs.utimes(getLockFile(file, options), mtime, mtime, (err) => { + options.fs.utimes(lock.lockfilePath, mtime, mtime, (err) => { const isOverThreshold = lock.lastUpdate + options.stale < Date.now(); // Ignore if the lock was released @@ -215,7 +230,7 @@ function lock(file, options, callback) { const operation = retry.operation(options.retries); operation.attempt(() => { - acquireLock(file, options, (err, stat) => { + acquireLock(file, options, (err, mtime, mtimePrecision) => { if (operation.retry(err)) { return; } @@ -226,10 +241,11 @@ function lock(file, options, callback) { // We now own the lock const lock = locks[file] = { - mtime: stat.mtime, + lockfilePath: getLockFile(file, options), + mtime, + mtimePrecision, options, lastUpdate: Date.now(), - mtimeChecker: createMtimeChecker(), }; // We must keep the lock fresh to avoid staleness @@ -310,29 +326,6 @@ function getLocks() { return locks; } -function createMtimeChecker() { - let precision; - - return (lockMtime, statMtime) => { - // If lock time was not on the second we can determine precision - if (!precision && lockMtime % 1000 !== 0) { - precision = statMtime % 1000 === 0 ? 's' : 'ms'; - } - - if (precision === 's') { - const lockTs = lockMtime.getTime(); - const statTs = statMtime.getTime(); - - // Maybe the file system truncates or rounds... - return Math.trunc(lockTs / 1000) === Math.trunc(statTs / 1000) || - Math.round(lockTs / 1000) === Math.round(statTs / 1000); - } - - // Must be ms or lockMtime was on the second - return lockMtime.getTime() === statMtime.getTime(); - }; -} - // Remove acquired locks on exit /* istanbul ignore next */ onExit(() => { diff --git a/lib/mtime-precision.js b/lib/mtime-precision.js new file mode 100644 index 0000000..b82a3ce --- /dev/null +++ b/lib/mtime-precision.js @@ -0,0 +1,55 @@ +'use strict'; + +const cacheSymbol = Symbol(); + +function probe(file, fs, callback) { + const cachedPrecision = fs[cacheSymbol]; + + if (cachedPrecision) { + return fs.stat(file, (err, stat) => { + /* istanbul ignore if */ + if (err) { + return callback(err); + } + + callback(null, stat.mtime, cachedPrecision); + }); + } + + // Set mtime by ceiling Date.now() to seconds + 5ms so that it's "not on the second" + const mtime = new Date((Math.ceil(Date.now() / 1000) * 1000) + 5); + + fs.utimes(file, mtime, mtime, (err) => { + /* istanbul ignore if */ + if (err) { + return callback(err); + } + + fs.stat(file, (err, stat) => { + /* istanbul ignore if */ + if (err) { + return callback(err); + } + + const precision = stat.mtime.getTime() % 1000 === 0 ? 's' : 'ms'; + + // Cache the precision in a non-enumerable way + Object.defineProperty(fs, cacheSymbol, { value: precision }); + + callback(null, stat.mtime, precision); + }); + }); +} + +function getMtime(precision) { + let now = Date.now(); + + if (precision === 's') { + now = Math.ceil(now / 1000) * 1000; + } + + return new Date(now); +} + +module.exports.probe = probe; +module.exports.getMtime = getMtime; diff --git a/test/check.test.js b/test/check.test.js index e51bf38..c02bbba 100644 --- a/test/check.test.js +++ b/test/check.test.js @@ -108,7 +108,7 @@ it('should not resolve symlinks if realpath is false', async () => { it('should fail if stating the lockfile errors out when verifying staleness', async () => { fs.writeFileSync(`${tmpDir}/foo`, ''); - const mtime = (Date.now() - 60000) / 1000; + const mtime = new Date(Date.now() - 60000); const customFs = { ...fs, stat: (path, callback) => callback(new Error('foo')), diff --git a/test/lock.test.js b/test/lock.test.js index 4846874..ec4accb 100644 --- a/test/lock.test.js +++ b/test/lock.test.js @@ -20,6 +20,7 @@ beforeAll(() => mkdirp.sync(tmpDir)); afterAll(() => rimraf.sync(tmpDir)); afterEach(async () => { + jest.restoreAllMocks(); clearTimeouts(); await unlockAll(); @@ -171,7 +172,7 @@ it('should not resolve symlinks if realpath is false', async () => { }); it('should remove and acquire over stale locks', async () => { - const mtime = (Date.now() - 60000) / 1000; + const mtime = new Date(Date.now() - 60000); fs.writeFileSync(`${tmpDir}/foo`, ''); fs.mkdirSync(`${tmpDir}/foo.lock`); @@ -183,7 +184,7 @@ 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; + const mtime = new Date(Date.now() - 60000); let count = 0; const customFs = { ...fs, @@ -209,7 +210,7 @@ it('should retry if the lockfile was removed when verifying staleness', async () }); it('should retry if the lockfile was removed when verifying staleness (not recursively)', async () => { - const mtime = (Date.now() - 60000) / 1000; + const mtime = new Date(Date.now() - 60000); const customFs = { ...fs, mkdir: jest.fn((...args) => fs.mkdir(...args)), @@ -232,7 +233,7 @@ it('should retry if the lockfile was removed when verifying staleness (not recur }); it('should fail if stating the lockfile errors out when verifying staleness', async () => { - const mtime = (Date.now() - 60000) / 1000; + const mtime = new Date(Date.now() - 60000); const customFs = { ...fs, stat: (path, callback) => callback(new Error('foo')), @@ -252,7 +253,7 @@ it('should fail if stating the lockfile errors out when verifying staleness', as }); it('should fail if removing a stale lockfile errors out', async () => { - const mtime = (Date.now() - 60000) / 1000; + const mtime = new Date(Date.now() - 60000); const customFs = { ...fs, rmdir: (path, callback) => callback(new Error('foo')), @@ -278,22 +279,22 @@ it('should fail if removing a stale lockfile errors out', async () => { it('should update the lockfile mtime automatically', async () => { fs.writeFileSync(`${tmpDir}/foo`, ''); - await lockfile.lock(`${tmpDir}/foo`, { update: 1000 }); + await lockfile.lock(`${tmpDir}/foo`, { update: 1500 }); expect.assertions(2); let mtime = fs.statSync(`${tmpDir}/foo.lock`).mtime; - // First update occurs at 1000ms - await pDelay(1500); + // First update occurs at 1500ms + await pDelay(2000); let stat = fs.statSync(`${tmpDir}/foo.lock`); expect(stat.mtime.getTime()).toBeGreaterThan(mtime.getTime()); mtime = stat.mtime; - // Second update occurs at 2000ms - await pDelay(1000); + // Second update occurs at 3000ms + await pDelay(2000); stat = fs.statSync(`${tmpDir}/foo.lock`); @@ -360,14 +361,37 @@ it('should call the compromised function if ENOENT was detected when updating th await deferred.promise; }); -it('should call the compromised function if failed to update the lockfile mtime too many times', async () => { +it('should call the compromised function if failed to update the lockfile mtime too many times (stat)', async () => { fs.writeFileSync(`${tmpDir}/foo`, ''); - const customFs = { - ...fs, - utimes: (path, atime, mtime, callback) => callback(new Error('foo')), + const customFs = { ...fs }; + + const deferred = pDefer(); + + const handleCompromised = (err) => { + expect(err.code).toBe('ECOMPROMISED'); + expect(err.message).toMatch('foo'); + + deferred.resolve(); }; + await lockfile.lock(`${tmpDir}/foo`, { + fs: customFs, + update: 1000, + stale: 5000, + onCompromised: handleCompromised, + }); + + customFs.stat = (path, callback) => callback(new Error('foo')); + + await deferred.promise; +}, 10000); + +it('should call the compromised function if failed to update the lockfile mtime too many times (utimes)', async () => { + fs.writeFileSync(`${tmpDir}/foo`, ''); + + const customFs = { ...fs }; + const deferred = pDefer(); const handleCompromised = (err) => { @@ -384,16 +408,15 @@ it('should call the compromised function if failed to update the lockfile mtime onCompromised: handleCompromised, }); + customFs.utimes = (path, atime, mtime, callback) => callback(new Error('foo')); + await deferred.promise; }, 10000); it('should call the compromised function if updating the lockfile took too much time', async () => { fs.writeFileSync(`${tmpDir}/foo`, ''); - const customFs = { - ...fs, - utimes: (path, atime, mtime, callback) => setTimeout(() => callback(new Error('foo')), 6000), - }; + const customFs = { ...fs }; const deferred = pDefer(); @@ -411,16 +434,15 @@ it('should call the compromised function if updating the lockfile took too much onCompromised: handleCompromised, }); + customFs.utimes = (path, atime, mtime, callback) => setTimeout(() => callback(new Error('foo')), 6000); + await deferred.promise; }, 10000); it('should call the compromised function if lock was acquired by someone else due to staleness', async () => { fs.writeFileSync(`${tmpDir}/foo`, ''); - const customFs = { - ...fs, - utimes: (path, atime, mtime, callback) => setTimeout(() => callback(new Error('foo')), 6000), - }; + const customFs = { ...fs }; const deferred = pDefer(); @@ -434,13 +456,15 @@ it('should call the compromised function if lock was acquired by someone else du await lockfile.lock(`${tmpDir}/foo`, { fs: customFs, update: 1000, - stale: 5000, + stale: 3000, onCompromised: handleCompromised, }); - await pDelay(5500); + customFs.utimes = (path, atime, mtime, callback) => setTimeout(() => callback(new Error('foo')), 6000); + + await pDelay(4500); - await lockfile.lock(`${tmpDir}/foo`, { stale: 5000 }); + await lockfile.lock(`${tmpDir}/foo`, { stale: 3000 }); await deferred.promise; }, 10000); @@ -505,23 +529,41 @@ 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 () => { +it('should not fail to update mtime when we are over the threshold but mtime is ours', 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 () => { +it('should call the compromised function when we are over the threshold and mtime is not ours', async () => { fs.writeFileSync(`${tmpDir}/foo`, ''); - await lockfile.lock(`${tmpDir}/foo`, { update: 1000, stale: 2000 }); - setTimeout(() => { - sleep(3000); - }, 1000); - await pDelay(5000); + + const deferred = pDefer(); + + const handleCompromised = (err) => { + expect(err.code).toBe('ECOMPROMISED'); + expect(err.message).toMatch('Unable to update lock within the stale threshold'); + + deferred.resolve(); + }; + + await lockfile.lock(`${tmpDir}/foo`, { + update: 1000, + stale: 2000, + onCompromised: handleCompromised, + }); + + const mtime = new Date(Date.now() - 60000); + + fs.utimesSync(`${tmpDir}/foo.lock`, mtime, mtime); + + sleep(3000); + + await deferred.promise; }, 16000); -it('should allow truncated second precision mtime', async () => { +it('should allow millisecond precision mtime', async () => { fs.writeFileSync(`${tmpDir}/foo`, ''); const customFs = { @@ -532,36 +574,25 @@ it('should allow truncated second precision mtime', async () => { return cb(err); } - // Make second precision if not already - stat.mtime = new Date(Math.trunc(stat.mtime.getTime() / 1000) * 1000); + stat.mtime = new Date((Math.floor(stat.mtime.getTime() / 1000) * 1000) + 123); cb(null, stat); }); }, }; - const deferred = pDefer(); + const dateNow = Date.now; - // If the module does not detect second precision for mtime, the mtime - // comparison will cause the lock to appear compromised. - const handleCompromised = (err) => { - clearTimeout(successTimeoutId); - deferred.reject(err); - }; + jest.spyOn(Date, 'now').mockImplementation(() => (Math.floor(dateNow() / 1000) * 1000) + 123); await lockfile.lock(`${tmpDir}/foo`, { fs: customFs, update: 1000, - onCompromised: handleCompromised, }); - // First update is fine because we `stat` after we `mkdir`, it'll fail on - // the second update when we use `utimes` and do not `stat` for the `mtime` - const successTimeoutId = setTimeout(deferred.resolve, 3000); - - await deferred.promise; + await pDelay(3000); }); -it('should allow rounded second precision mtime', async () => { +it('should allow floor\'ed second precision mtime', async () => { fs.writeFileSync(`${tmpDir}/foo`, ''); const customFs = { @@ -573,30 +604,42 @@ it('should allow rounded second precision mtime', async () => { } // Make second precision if not already - stat.mtime = new Date(Math.round(stat.mtime.getTime() / 1000) * 1000); + stat.mtime = new Date(Math.floor(stat.mtime.getTime() / 1000) * 1000); cb(null, stat); }); }, }; - const deferred = pDefer(); + await lockfile.lock(`${tmpDir}/foo`, { + fs: customFs, + update: 1000, + }); - // If the module does not detect second precision for mtime, the mtime - // comparison will cause the lock to appear compromised. - const handleCompromised = (err) => { - clearTimeout(successTimeoutId); - deferred.reject(err); + await pDelay(3000); +}); + +it('should allow ceil\'ed second precision mtime', async () => { + fs.writeFileSync(`${tmpDir}/foo`, ''); + + const customFs = { + ...fs, + stat(path, cb) { + fs.stat(path, (err, stat) => { + if (err) { + return cb(err); + } + + // Make second precision if not already + stat.mtime = new Date(Math.ceil(stat.mtime.getTime() / 1000) * 1000); + cb(null, stat); + }); + }, }; await lockfile.lock(`${tmpDir}/foo`, { fs: customFs, update: 1000, - onCompromised: handleCompromised, }); - // First update is fine because we `stat` after we `mkdir`, it'll fail on - // the second update when we use `utimes` and do not `stat` for the `mtime` - const successTimeoutId = setTimeout(deferred.resolve, 3000); - - await deferred.promise; + await pDelay(3000); }); diff --git a/test/unlock.test.js b/test/unlock.test.js index 7a6995b..e5ca5dd 100644 --- a/test/unlock.test.js +++ b/test/unlock.test.js @@ -102,13 +102,12 @@ it('should ignore ENOENT errors when removing the lockfile', async () => { it('should stop updating the lockfile mtime', async () => { fs.writeFileSync(`${tmpDir}/foo`, ''); - const customFs = { - ...fs, - utimes: jest.fn((path, atime, mtime, callback) => callback()), - }; + const customFs = { ...fs }; await lockfile.lock(`${tmpDir}/foo`, { update: 2000, fs: customFs }); + customFs.utimes = jest.fn((path, atime, mtime, callback) => callback()); + await lockfile.unlock(`${tmpDir}/foo`); // First update occurs at 2000ms @@ -120,13 +119,12 @@ it('should stop updating the lockfile mtime', async () => { it('should stop updating the lockfile mtime (slow fs)', async () => { fs.writeFileSync(`${tmpDir}/foo`, ''); - const customFs = { - ...fs, - utimes: jest.fn((...args) => setTimeout(() => fs.utimes(...args), 2000)), - }; + const customFs = { ...fs }; await lockfile.lock(`${tmpDir}/foo`, { fs: customFs, update: 2000 }); + customFs.utimes = jest.fn((...args) => setTimeout(() => fs.utimes(...args), 2000)); + await pDelay(3000); await lockfile.unlock(`${tmpDir}/foo`); @@ -139,13 +137,12 @@ it('should stop updating the lockfile mtime (slow fs)', async () => { it('should stop updating the lockfile mtime (slow fs + new lock)', async () => { fs.writeFileSync(`${tmpDir}/foo`, ''); - const customFs = { - ...fs, - utimes: jest.fn((...args) => setTimeout(() => fs.utimes(...args), 2000)), - }; + const customFs = { ...fs }; await lockfile.lock(`${tmpDir}/foo`, { fs: customFs, update: 2000 }); + customFs.utimes = jest.fn((...args) => setTimeout(() => fs.utimes(...args), 2000)); + await pDelay(3000); await lockfile.unlock(`${tmpDir}/foo`);