Change in node v14.17.0 broke the mtimeMs comparison for source/target files in gulp-changed

[gavinaiken]

• Version: v14.17.0
• Platform: Darwin gav-mbp 19.6.0 Darwin Kernel Version 19.6.0: Tue Nov 10 00:10:30 PST 2020; root:xnu-6153.141.10~1/RELEASE_X86_64 x86_64
• Subsystem: not known

What steps will reproduce the bug?

Please see issue sindresorhus/gulp-changed#83

How often does it reproduce? Is there a required condition?

It reproduces 100% of the time

What is the expected behavior?

What do you see instead?

Additional information

[bl-ue]

@gavinaiken are you able to provide steps to reproduce? I'm not that familiar with gulp.

[Trott]

@gavinaiken are you able to provide steps to reproduce? I'm not that familiar with gulp.

I tried some simple things on Big Sur and couldn't replicate this issue, but it's possible I'm Doing It Wrong or that the issue is specific to Catalina. A Gulpfile.js that shows the problem when npx gulp is run under 14.17.0 but not when run under 14.16.1 would be a big help.

[gavinaiken]

No problem, I will put together a simple example

[gavinaiken]

Hmm, I tried a very simple example and I cannot reproduce the issue. Looks like it may require more moving parts, probably babel which is being used in my real world gulpfile. Working on getting a repro together with all necessary pieces included. How shall I share it once I have got an example? Maybe make a repo on github?

[targos]

If mtime is compared, I guess it means that something changes the mtime of the output file to match that of the input. Do you know which part of gulp does that?

[bl-ue]

How shall I share it once I have got an example? Maybe make a repo on github?

Yeah @gavinaiken that'll be great!

[gavinaiken]

https://github.com/gavinaiken/node-mtime-issue

To test the problem, clone the repo, then do the following:

npm i
gulp build
gulp build

You should see that on the first run of gulp build it copies all 3 test*.js files from src to dist.

On the second and subsequent runs of gulp build it is expected that no files will be copied over unless you touch the src file. However due to the bug, one or more files should be copied over every time.

I think I can see what is going on now. If the source file mtime ends with an ms fractional part greater than .500, the dist file is created with the same time but .999 on the end, or sometimes with the rounded-up integer. Whereas if the src file mtime ends with a part lower than .500 the dist file is created with the integer part minus 1 ms, with .999 on the end. Files which fall into the first camp are therefore not seen as c hanged by gulp-changed because the dist has a later mtime than the src. Files which fall into the second camp are always seen as changed because the dist mtime is always behind the src.

The mtime given to the dist seems to be deterministic - if you blow it away, it gets the same mtime again when gulp build is run. You can use gulp clean to remove the files in dist.

Examples:

src: 1623252746145.8945 dist: 1623252746145.999
// ok since dist is newer than src

src: 1623253024100.679 dist: 1623253024101
// ok since dist is newer than src

src: 1623253070597.3147 dist: 1623253070596.999
// not ok since dist is older than src

The only issue at the moment with recreating this from the repo is that when you clone it, you will get new mtimes on the src files so you may or may not see the issue. I will try to add a script in a minute to set the mtimes to something that will definitely show the issue.

[bl-ue]

What gulp version are you using? I'm not able to reproduce on macOS Big Sur 11.4. I ran gulp build several times and the mtimes on all three files were the same (12:10) as they were when the files were initially copied.

[gavinaiken]

I am using 4.0.2. You may have got (un)lucky with the mtimes on your files when you cloned the repo. If I can get this script working to override the mtime I should be able to force the issue to appear.

[gavinaiken]

I've pushed a script called mtimes.js to the repo. I haven't got the set part of it working properly yet, it sets the mtimes to a very high number for some reason which I haven't figured out yet. However the list function works to show you the mtimes on the files. You should get output something like this if you run it:

$ ./mtimes.js list
file: test1.js src mtimeMs: 1623259049896.848 dist mtimeMs: 1623259049897 dist newer than src?: true
file: test2.js src mtimeMs: 1623259053978.404 dist mtimeMs: 1623259053977.999 dist newer than src?: false
file: test3.js src mtimeMs: 1623259056650.612 dist mtimeMs: 1623259056651 dist newer than src?: true

If you see a false as the list output on the line for a particular file, that should indicate that if you run gulp build again, that file will be copied over to dist again (and again, and again, each time you run it), but a true indicates that the mtime on the dist is newer than the src so it will not be copied again (the expected behaviour).

Will continue working on the set fn to ensure you can repro the issue. In the meantime, if you have 3 true, you can try touching a file and running gulp build again.

touch src/test1.js
gulp build
gulp build

[gavinaiken]

I believe the set fn is working now. So you should be able to reproduce the issue as follows:

$ ./mtimes.js set
$ gulp clean
[18:43:59] Using gulpfile ~/Desktop/gulp-changed-problem/gulpfile.js
[18:43:59] Starting 'clean'...
[18:43:59] deleting: dist/test1.js
[18:43:59] deleting: dist/test2.js
[18:43:59] deleting: dist/test3.js
[18:43:59] Finished 'clean' after 47 ms
$ gulp build
[18:44:03] Using gulpfile ~/Desktop/gulp-changed-problem/gulpfile.js
[18:44:03] Starting 'build'...
[18:44:03] babel built: src/test1.js
[18:44:03] babel built: src/test2.js
[18:44:03] babel built: src/test3.js
[18:44:03] Finished 'build' after 42 ms
$ gulp build
[18:44:05] Using gulpfile ~/Desktop/gulp-changed-problem/gulpfile.js
[18:44:05] Starting 'build'...
[18:44:05] babel built: src/test1.js
[18:44:05] babel built: src/test2.js
[18:44:05] Finished 'build' after 41 ms
$ gulp build
[18:44:07] Using gulpfile ~/Desktop/gulp-changed-problem/gulpfile.js
[18:44:07] Starting 'build'...
[18:44:07] babel built: src/test1.js
[18:44:07] babel built: src/test2.js
[18:44:07] Finished 'build' after 41 ms
$ ./mtimes.js list
file: test1.js src mtimeMs: 1623259049896.314 dist mtimeMs: 1623259049895.999 dist newer than src?: false
file: test2.js src mtimeMs: 1623259053978.499 dist mtimeMs: 1623259053977.999 dist newer than src?: false
file: test3.js src mtimeMs: 1623259056650.71 dist mtimeMs: 1623259056651 dist newer than src?: true

Notice that the files test1.js and test2.js are always copied over by gulp build every time it is run. Expected behaviour is that they should only be copied over the first time, like test3.js

[gavinaiken]

If mtime is compared, I guess it means that something changes the mtime of the output file to match that of the input. Do you know which part of gulp does that?

Sorry, I don't know. I could maybe dig through their source code and take a look if it would help?

[gavinaiken]

I don't have node 14.16.1 to hand any more but I do have node 12, and I believe the results would be the same, so here's the output when testing with node 12. (I believe the results would be the same because multiple developers in our company experienced this issue with gulp when they moved from node 14.16.1 to 14.17.0).

$ gulp clean
[20:23:42] Using gulpfile ~/Desktop/gulp-changed-problem/gulpfile.js
[20:23:42] Starting 'clean'...
[20:23:42] deleting: dist/test1.js
[20:23:42] deleting: dist/test2.js
[20:23:42] deleting: dist/test3.js
[20:23:43] Finished 'clean' after 46 ms
$ gulp build
[20:23:50] Using gulpfile ~/Desktop/gulp-changed-problem/gulpfile.js
[20:23:50] Starting 'build'...
[20:23:50] babel built: src/test1.js
[20:23:50] babel built: src/test2.js
[20:23:50] babel built: src/test3.js
[20:23:50] Finished 'build' after 41 ms
$ gulp build
[20:23:53] Using gulpfile ~/Desktop/gulp-changed-problem/gulpfile.js
[20:23:53] Starting 'build'...
[20:23:53] Finished 'build' after 36 ms
$ gulp build
[20:23:56] Using gulpfile ~/Desktop/gulp-changed-problem/gulpfile.js
[20:23:56] Starting 'build'...
[20:23:56] Finished 'build' after 43 ms
$ ./mtimes.js list
file: test1.js src mtimeMs: 1623259049896.314 dist mtimeMs: 1623259049896 dist newer than src?: false
file: test2.js src mtimeMs: 1623259053978.499 dist mtimeMs: 1623259053978 dist newer than src?: false
file: test3.js src mtimeMs: 1623259056650.71 dist mtimeMs: 1623259056651 dist newer than src?: true

Note that no files are copied in the 2nd and 3rd runs of gulp build with this version of node. Also note the difference in the dist mtimeMs for test1.js and test2.js - with node 12 the dist mtime was the floor of the src mtime, whereas on node 14.17.0 the dist mtime is the floor of the src minus 0.001 eg 1623259049896 vs 1623259049895.999

[richardlau]

14.17.0 included an update to libuv 1.41.0 (bfba66d) which includes a change to how timestamps are rounded: libuv/libuv#2747

Does the issue occur with Node.js 16?

[gavinaiken]

Tested this morning with 16.3.0 and it behaves the same as 14.17.0, so it is definitely looking like that libuv change is what has caused the problem.