Difference between lock.mtime and stat.mtime precision

[pimlie]

Possibly related to #79

We are still getting a lot of reports about stale locks, often on CI platforms (and docker). One possible cause might be users who are using Node <v9. It appears that in Node v9 there can be a difference in precision about the lock.mtime which is set with what stat.mtime reports back:

updateLock 2019-03-23T09:30:18.519Z 2019-03-23T09:30:18.519Z                                                             10:30:33
precision ms                                                                                                             10:30:33
createdMtimeChecked 1553333418519 1553333418519                                                                          10:30:33
mtime set to 2019-03-23T09:30:33.523Z                                                                                    10:30:33
updateLock 2019-03-23T09:30:33.523Z 2019-03-23T09:30:33.000Z                                                             10:30:48
precision ms                                                                                                             10:30:48
createdMtimeChecked 1553333433523 1553333433000           

(lines above are: <function.name> <lock.mtime> <stat.mtime>)

After the last line the lock gets compromised due to the 523ms difference

-- edit --
I removed Node v9 from the title because actually I am not sure if this is really a Node v9 issue only. It might very well be a Node v10+ issue as well which just doesnt show as often / repeatedly due to the general (performance) improvements made in v10+

[alanshaw]

Can you check you're using the latest version? This issue should have been resolved already.

[pimlie]

@alanshaw See screenshot from vim node_modules/proper-lockfile/package.json, just tried again and the lock gets compromised again

createdMtimeChecked 1553860346774 1553860346774                                                                          12:52:41
createdMtimeChecked 1553860361781 1553860361000                                                                          12:52:56

[alanshaw]

Where are you logging createdMtimeChecked?

[pimlie]

node_modules/proper-lockfile/lib/lockfile.js line 330

[alanshaw]

Oh interesting, maybe on your system utimes is second precision but mkdir is ms precision.

[alanshaw]

@satazor a simple fix to this would be to do an initial utimes after the lock directory is created here

node-proper-lockfile/lib/lockfile.js

Line 26 in 1a478a4

options.fs.mkdir(getLockFile(file, options), (err) => {

- adds another FS call...any better ideas?

[pimlie]

I dont think its my fs, its just Linux with ext4. The problem occurs always with Node v9, but in my case never with v10+

[satazor]

@alanshaw perhaps it would be better to implement the strategy in #79 without calling detect after the mkdir call?

[pimlie]

Another option would be to just call fs.stat immediately after fs.utimes so we know for sure the next stale check compares the correct mtime.

[satazor]

@pimlie right, but then there’s one unecessary io syscall

[pimlie]

@satazor Its not really unnecessary when it squashes buggy behaviour I guess (and there is no other workaround)

I spent a fair amount of time trying to debug this but am afraid although I can reproduce it consistently in one of my Nuxt projects I still dont understand what causes it. Could be linux/fs behaviour, could be node. Could be related to high cpu usage or high io usage. Sorry to say I havent been able to put my finger on it yet. Any suggestions what I could do to get to the bottom of this would really be appreciated though :)

[satazor]

@pimlie what I’m saying is that there’s an alternative solution that we discussed in another PR that would solve this issue while not doing any additional io syscall.

You may read the suggestion in the link I gave above but @alanshaw has more context.

Anyway, I will also accept a PR that does the extra syscall to resolve the bug.

[satazor]

@pimlie I have a fix in #88. Could you test it out and report back?

It would make things easier for me, otherwise I will have to spawn a VM with ext4 and test it out.

[pimlie]

Thanks for the quick work. Can confirm the fix seems to work:

precision s 1554276465737 1554276465000                                                                                  09:28:00
precision s 1554276480000 1554276480000                                                                                  09:28:15

I also checked whether I still get a warning when I manually change the mtime once the lock has been created and that works too:

precision s 1554276687945 978282000000                                                                                   09:31:42

 WARN  Unable to update lock within the stale threshold                                                                  09:31:42