Node: os x: FSEventStreamFlushSync assertions logged to console

[robey]

after switching from node to io.js, periodically these alarming asserts get logged to the console:

(FSEvents.framework) FSEventStreamFlushSync(): failed assertion '(SInt64)last_id > 0LL'

they seem to be caused by the fs.watch code. i tried digging into libuv/iojs but didn't see anything obvious. OTOH, i don't really know how much pent-up code was unleashed in the migration to io.js, so this bug may have been added a year or two ago.

i can reproduce the assertion with a short script, which i'll attach. run the script 10-20 times, because it only happens about every 4th time. (i suspect a race.)

[robey]

#!/usr/bin/env iojs --harmony_arrow_functions
"use strict";

const fs = require("fs");
const Promise = require("bluebird");

const folders = [ "Library", "Music", "Documents", "Pictures", "Movies", "Downloads" ];

function addWatch(name) {
  return fs.watch("/Users/robey/" + name, { persistent: false, recursive: false }, (event) => {
    console.log("event.");
  });
}

function iterate(list) {
  if (list.length == 0) return Promise.resolve();
  addWatch(list[0]);
  return Promise.delay(100).then(() => iterate(list.slice(1)));
}

console.log("hello.");
iterate(folders).then(() => {
  console.log("goodbye.");
});

[Fishrock123]

cc @bnoordhuis?

[cjihrig]

@robey just out of curiosity, are you able to reproduce this with no external dependencies (bluebird), and without using any features behind flags (harmony_arrow_functions)?

[robey]

@cjihrig haha yes, it's not related to those, feel free to remove them from the test code if they bother you.

the test script is just to show that it can happen with very little setup. you may have to run it 20 or 30 times to see the assert, but i'm intentionally not looping in the code, to prove that it happens even if the only watches you add are for folders not previously watched.

i built io.js from source (v1.x branch) and added some debugging lines that proved to me that the assert always happens from this call:

https://github.com/iojs/io.js/blob/v1.x/deps/uv/src/unix/fsevents.c#L377

but that's as far as i got before realizing i'd have to have a pretty deep understanding of the event loop to get any further.

if you want a test case that is _not_ isolated, but is _very frequent_, run the unit tests of "globwatcher". the assert happens at almost every other test case, and once it actually caused io.js to coredump, so the assert may be trying to tell you something deeper is wrong.

because there's no reliable way to reproduce the failure, i suspect this is a race or uninitialized code.

i'm going back to node.js right now so i can keep making progress on my real task (converting all my coffee-script libraries to ES6), so good luck!

[robey]

oh, one interesting data point: i tried node.js 0.12 and it has the same assert bug, so this is something that crept into libuv between 0.10 and 0.12 (i guess that narrows it down to five years...)

[bnoordhuis]

Maybe /cc @indutny? He wrote most of the fsevents code.

[indutny]

@robey thanks for test case! May I ask you help me a bit and reduce it so that it'll run without deps and harmony stuff?

[indutny]

@robey does following test reproduce the problem for you?

const fs = require("fs");

const folders = [ "Library", "Music", "Documents", "Pictures", "Movies", "Downloads" ];

function addWatch(name) {
  return fs.watch("/Users/indutny/" + name, { persistent: false, recursive: false }, function (event) {
    console.log("event.");
  });
}

function iterate(list) {
  if (list.length === 0)
    return;

  console.log(' ~ ', list[0]);
  addWatch(list.shift());
  setTimeout(iterate.bind(null, list), 200);
}

console.log("hello.");
iterate(folders);

[indutny]

@robey which OS X version are you using, btw? I wasn't able to reproduce it on 10.10.2

[robey]

OS X 10.10.2, according to "About". "uname -a" gives:

Darwin davos.local 14.1.0 Darwin Kernel Version 14.1.0: Mon Dec 22 23:10:38 PST 2014; root:xnu-2782.10.72~2/RELEASE_X86_64 x86_64

Because it's non-deterministic, it's hard to nail down exactly what code causes it. The _best_ way I've found is to run "npm i; npm test" in globwatcher, where it will emit the assertion on about 2/3 of the tests that invoke fs.watch.

I've played around with my smaller script, and I think I have a better case now, which I'll attach below. This one generates 1k folders, watches them, then deletes the folders and closes the watchers. It emits about a dozen of the assertions as it does the delete/close.

[robey]

#!/usr/bin/env iojs 
"use strict";

const fs = require("fs");

const folders = [];
for (let i = 0; i < 1000; i++) {
  folders.push("temp" + i);
}
folders.forEach(function (folder) {
  fs.mkdirSync(folder);
});

console.log("hello.");
var watchers = [];
for (var i = 0; i < folders.length; i++) {
  var watcher = fs.watch(folders[i], { persistent: false, recursive: false }, function (event) {
    // don't care.
  });
  watchers.push(watcher);
}

console.log("goodbye.");
for (var i = 0; i < folders.length; i++) {
  fs.rmdirSync(folders[i]);
  watchers[i].close();
}

[indutny]

Filed Apple bugreport: 19866413

[robey]

in case you're stuck, my current pet theory is that removing the folder is now causing the watch to get cleaned up in some other codepath, and if that happens before you close() the watch, you lose the race and close() tries to free resources that it doesn't have.

no data for this; just my spidey-sense for races.

[indutny]

@robey good idea, but I don't see how it could happen. Unfortunately I can't reproduce the problem on my machine, @saghul maybe you could give it a try?

[saghul]

Will do.
On Mar 3, 2015 7:52 PM, "Fedor Indutny" [email protected] wrote:

@robey https://github.com/robey good idea, but I don't see how it could
happen. Unfortunately I can't reproduce the problem on my machine, @saghul
https://github.com/saghul maybe you could give it a try?

—
Reply to this email directly or view it on GitHub
https://github.com/iojs/io.js/issues/854#issuecomment-77008887.

[saghul]

Tried on OSX 10.9.5, couldn't reproduce it with the code here: https://github.com/iojs/io.js/issues/854#issuecomment-74733455

[saghul]

Also tried it on 10.10.3, couldn't reproduce it either.

[robey]

I confirm this is fixed in io.js 1.5 -- thank you! :)

I don't want to close this in case you have a process, but I would consider it closed.

[Fishrock123]

Closing, doesn't seem like there is anything actionable here.

[mgol]

I'm now seeing these messages in io.js 1.7.1. Was it really fixed?

[Fishrock123]

@mzgol Do you have any more info that we can use to do something other than file an apple bug report? How is this reproducible?

[mgol]

@Fishrock123 I have a large project (~2000 files) with lots of Grunt tasks and I run a dev server via grunt-contrib-connect 0.9.0 with grunt-contrib-watch 0.6.1. I see this error message quite frequently on watch. I'm on OS X 10.10.3.

This project is not public but I can try with other, public ones and see if I can reproduce it there as well.

[Fishrock123]

@mzgol Ideally we'd want something testable without dependancies if possible, but I suppose any info might be be helpful.

[Fishrock123]

Also, does the test-case above reproduce it for you?

[mgol]

Also, does the test-case above reproduce it for you?

Yes, it does!

EDIT: It reproduces for me on io.js 1.7.1, 1.6.4 & 1.5.1. But it also reproduces on Node.js 0.12.2... On Node.js 0.10.38 it's way worse, on Node.js 0.12.2 & io.js it's comparable.

So maybe Apple broke sth in OS X 10.10.3?

[robey]

Ah, yep, it's back.

One very simple way to see the assertions is to grab the globwatcher repo, and:

$ nvm use iojs-v1.7.1
$ npm run distclean
$ npm i
$ npm test

[Fishrock123]

So maybe Apple broke sth in OS X 10.10.3?

@robey had this on OS X 10.10.2, it's definitely an apple bug, but it doesn't happen everywhere, it seems. (It doesn't happen to me running OS X 10.10.3 on a 2012 Retina Macbook Pro.)

@mzgol, @robey what hardware are you running?

[mgol]

@mzgol, @robey what hardware are you running?

A mid-2012 non-retina 15" MacBook Pro.
CPU: 2,3 GHz Intel Core i7
RAM: 16 GB 1600 MHz DDR3
Graphics: NVIDIA GeForce GT 650M 512 MB / Intel HD Graphics 4000 1024 MB

[robey]

10.10.3, "MacBook Pro (Retina, 15-inch, Mid 2014)"

it also happens on my home laptop, which is about 2.5 years old.

i suspect this is a case where sometimes libuv is releasing a resource twice, and sometimes osx notices and complains. i dug into it briefly when this first showed up (details are probably above) but i'm not familiar enough with libuv to make progress in a reasonable time. :)

[mgol]

So I guess this issue should be reopened?

[robey]

sorry! i can't figure out how.

i think this is a known bug in github.

[mgol]

@robey You didn't close the bug so you cannot reopen it, I guess. One of maintainers has to, e.g. @Fishrock123

[brendanashworth]

I'm going to mark this as a confirmed-bug because it's been confirmed by two people, even though no collaborators have been able to repeat this as of yet (neither can I).

[brendanashworth]

Seems like this is/has been an issue for grunt users: https://github.com/gruntjs/grunt-contrib-watch/issues/415

[Fishrock123]

Some people in the above thread seemed to have said that when they didn't spawn child processes on watch it seemed to be OK.

[Fishrock123]

Also maybe https://github.com/bdkjones/fseventsbug/wiki/realpath()-And-FSEvents

[joshrickert]

I'm getting this on a gulp watch as well. Also on OS X. I have my project in a Dropbox folder; maybe that helps? I know Dropbox is known to cause oddness with file system events.

[robey]

I don't use dropbox, so it wasn't that.... but this bug has been open for so long, I think you're better off just avoiding the fs.watch interface. Use one of the native modules like everyone else does.

[brettdorrans]

+1 experiencing this issue on OSX.

The folder is also monitored by Bittorrent Sync, so it does seem to be related to both processes accessing the filesystem on OSX.

[smlombardi]

This happens to me as well, sporadically but often:

2016-07-26 15:34 gulp[43763] (FSEvents.framework) FSEventStreamFlushSync(): failed assertion '(SInt64)last_id > 0LL'

Everything keeps working, but that's logged to console. I am running a gulp watch task, with node-sass, autoprefixer, gulp-sourcemaps, and browsersync.

Mac OS 10.11.6

[EugeneDae]

On macOS El Capitan 10.11.5 I'm getting this warning:

2016-07-30 18:15 gulp[20177] (FSEvents.framework) FSEventStreamFlushSync(): failed assertion '(SInt64)last_id > 0LL'

each time I add a new .less file to the directory watched by Gulp that is configured like so:

var gulp        = require('gulp');

gulp.task('css', function () {
    // Empty function still throws an error
});

gulp.task('default', function() {
    gulp.watch('static/less/**/*.less', ['css']);
});

[cb1kenobi]

This is still an issue with Node.js 4.4.7 and 6.3.1. I'm on OS X 10.11.6. I'm NOT using chokidar, fsevents, gaze, or any other filesystem watching library. I'm only using the built-in fs.watch().

[jasnell]

Ok. I'll queue up some time to dig into this again. Very unfortunate that this is still happening.

[saghul]

@cb1kenobi Do you have a reproducible test case only using fs.watch(). We have struggled to reproduce this in the past.

[cb1kenobi]

@saghul I don't have a isolated test case, but I do have a library that easily reproduces the problem.

I'm working on a library called node-appc that has some common utils we use in our products. In it there is a fs module that has a filesystem watcher. (yeah, yeah, I know... reinventing the wheel)

To reproduce:

git clone -b v2 https://[email protected]/appcelerator/node-appc.git
cd node-appc
npm install
gulp test --suite fs

You can run DEBUG=node-appc:* gulp test --suite fs to display debug logging.

Edit test/test-fs.js and under the watcher test group, you can run a specific test by changing the test case from it(... to it.only(....

Hope that helps.

[bnoordhuis]

My working hypothesis is that fsevents doesn't like it when we call FSEventStreamFlushSync() when there is nothing to flush. Can someone try this patch and report back?

diff --git a/deps/uv/src/unix/fsevents.c b/deps/uv/src/unix/fsevents.c
index d331a13..81448f3 100644
--- a/deps/uv/src/unix/fsevents.c
+++ b/deps/uv/src/unix/fsevents.c
@@ -141,6 +141,8 @@ static FSEventStreamRef (*pFSEventStreamCreate)(CFAllocatorRef,
                                                 FSEventStreamEventId,
                                                 CFTimeInterval,
                                                 FSEventStreamCreateFlags);
+static FSEventStreamEventId
+    (*pFSEventStreamGetLatestEventId)(ConstFSEventStreamRef);
 static void (*pFSEventStreamFlushSync)(FSEventStreamRef);
 static void (*pFSEventStreamInvalidate)(FSEventStreamRef);
 static void (*pFSEventStreamRelease)(FSEventStreamRef);
@@ -372,6 +374,7 @@ static int uv__fsevents_create_stream(uv_loop_t* loop, CFArrayRef paths) {
 /* Runs in CF thread */
 static void uv__fsevents_destroy_stream(uv_loop_t* loop) {
   uv__cf_loop_state_t* state;
+  FSEventStreamEventId evid;

   state = loop->cf_state;

@@ -379,7 +382,9 @@ static void uv__fsevents_destroy_stream(uv_loop_t* loop) {
     return;

   /* Flush all accumulated events */
-  pFSEventStreamFlushSync(state->fsevent_stream);
+  evid = pFSEventStreamGetLatestEventId(state->fsevent_stream);
+  if (evid != 0 && evid != kFSEventStreamEventIdSinceNow)
+    pFSEventStreamFlushSync(state->fsevent_stream);

   /* Stop emitting events */
   pFSEventStreamStop(state->fsevent_stream);
@@ -551,6 +556,7 @@ static int uv__fsevents_global_init(void) {
   V(core_foundation_handle, kCFRunLoopDefaultMode);
   V(core_services_handle, FSEventStreamCreate);
   V(core_services_handle, FSEventStreamFlushSync);
+  V(core_services_handle, FSEventStreamGetLatestEventId);
   V(core_services_handle, FSEventStreamInvalidate);
   V(core_services_handle, FSEventStreamRelease);
   V(core_services_handle, FSEventStreamScheduleWithRunLoop);

[cb1kenobi]

@bnoordhuis I tried your patch with both the v4.x and master branch and it didn't fix the problem.

I've created an isolated test case:

const fs = require('fs');
const dir = '/Users/chris/Desktop';

if (fs.existsSync(`${dir}/foo.txt`)) {
    fs.unlinkSync(`${dir}/foo.txt`);
}

console.log(`Watching ${dir}`);
const watcher = fs.watch(dir);

setTimeout(() => {
    console.log(`Writing ${dir}/foo.txt`);
    fs.writeFileSync(`${dir}/foo.txt`, 'foo!');
}, 100);

setTimeout(() => {
    console.log(`Closing watcher`);
    watcher.close();
}, 1000);

I littered fsevents.c with a bunch of printf() calls and noticed that the error occurs after I close the watcher. If I have multiple watchers, it displays the error after the first close() call.

$ node test.js 
Watching /Users/chris/Desktop
uv__fsevents_reschedule()
Writing /Users/chris/Desktop/foo.txt
Closing watcher
uv__fsevents_close()
uv__fsevents_reschedule()
uv__fsevents_destroy_stream()
evid = 18158642515182076391 (unknown)
Calling pFSEventStreamFlushSync()
2016-08-10 11:22 node[10248] (FSEvents.framework) FSEventStreamFlushSync(): failed assertion '(SInt64)last_id > 0LL'

Done calling pFSEventStreamFlushSync()

[saghul]

@cb1kenobi I tried your test case, but I still can't reproduce it :-S macOS 10.11.6, Node 4.2.2. FWIW, I don't think the Node version is very relevant here, since the fsevents code hasn't seen changes in months.

[cb1kenobi]

Hmm, I can reproduce it consistently. I just tried again with 4.4.7:

$ node -v
v4.4.7
$ node test.js 
Watching /Users/chris/Desktop
Writing /Users/chris/Desktop/foo.txt
Closing watcher
2016-08-10 11:39 node[10511] (FSEvents.framework) FSEventStreamFlushSync(): failed assertion '(SInt64)last_id > 0LL'
$

[saghul]

 $  node t.js
Watching /Users/saghul/work/ag-projects/blink-ios
Writing /Users/saghul/work/ag-projects/blink-ios/foo.txt
Closing watcher

All I changed was to point the directory to process.cwd().

[EugeneDae]

I can consistently reproduce the problem with @cb1kenobi's test on v6.3.1:

Dae-MBP:Desktop Dae$ node test.js 
Watching /Users/Dae/Desktop
Writing /Users/Dae/Desktop/foo.txt
Closing watcher
2016-08-10 20:01 node[16079] (FSEvents.framework) FSEventStreamFlushSync(): failed assertion '(SInt64)last_id > 0LL'

Dae-MBP:Desktop Dae$ node -v
v6.3.1

[indutny]

Can't reproduce it too. @EugeneDae @cb1kenobi does any of you have a dropbox, or any other syncing program active?

[jasnell]

I've been unable to reproduce here either :-/ ... frustrating.

[EugeneDae]

@indutny Yes, Dropbox and Google Drive, but I can still reproduce the problem with the test if I quit them. (I've verified they're off via Activity Monitor).

[indutny]

@EugeneDae interesting... do you just run script in a loop?

[EugeneDae]

@indutny Mmm not sure if I understand correctly -- I just run the script from the Terminal (node test.js). The warning (failed assertion) comes up every single time, always. Also I can now confirm that it can be reproduced from a newly created user account.

I've a second MacBook; I can give a Node.js Foundation member Teamviewer access if that would help you guys tackle the problem.

[indutny]

@EugeneDae gotcha! Thanks!

It is unlikely that I'll be able to investigate the cause of it this way, but thanks for proposing this! Maybe @bnoordhuis would want to take a look?

Meanwhile, I'll file a bug report at Apple's bug tracker (radar) and try to get any tips from them!

[cb1kenobi]

I do not have Dropbox or Google Drive.

Thanks for looking into this guys. Let me know if I can help test another patch.

[renesansz]

I got also this error everytime I tried to create a new file

2016-08-31 10:38 gulp[4480] (FSEvents.framework) FSEventStreamFlushSync(): failed assertion '(SInt64)last_id > 0LL

OSX Yosemite (10.11.6)
Node v4.4.7
NPM v2.15.8

[Fishrock123]

@renesansz Really? Could you post some code that consistently reproduces the issue for you?

If you are able to get it to happen consistently... that could be a breakthrough.

[bdavidxyz]

I have the bug all the time with Impatient-Jekyll

$ git clone https://github.com/bdavidxyz/impatient-jekyll
$ cd impatient-jekyll
$ npm install
$ $(npm bin)/gulp

Then the bug occurs on my mac 10.11.6

To solve that bug I stop/restart the server many times and... it will work after a few attempts. Ouch !

[saghul]

@bdavidxyz I'm afraid we need a far more reduced test case. Ideally only with core modules. Thanks for the efforts though!

[bdavidxyz]

Ok I'll work on isolation

[cb1kenobi]

@bdavidxyz Can you reproduce it using my test case? https://github.com/nodejs/node/issues/854#issuecomment-238922150

[renesansz]

@Fishrock123 , I was only able to experience the issue on my Gulp script upon watching changes for the files.

Everytime I create new file it gives an error: 2016-08-31 10:38 gulp[4480] (FSEvents.framework) FSEventStreamFlushSync(): failed assertion '(SInt64)last_id > 0LL

Here's my gist.

That's only what I did

[bdavidxyz]

@cb1kenobi Yes !! I am able to reproduce the bug on my machine.

mac os x 10.11.6
node v5.12.0
npm 3.8.6

~/workspace/david/bug$ node index.js 
Watching /Users/david/workspace/david/foo
Writing /Users/david/workspace/david/foo/foo.txt
Closing watcher
2016-09-02 06:56 node[50499] (FSEvents.framework) FSEventStreamFlushSync(): failed assertion '(SInt64)last_id > 0LL'

[indutny]

I have a good confidence that this is a bug in OS X's FSEvents and not in the node.js core itself. Can't comment much on it yet, though.

[sedubois]

I also have this issue, as described here https://github.com/jimkyndemeyer/js-graphql-intellij-plugin/issues/34#issuecomment-254268161.

[sedubois]

Any news on this? It makes usage of https://github.com/jimkyndemeyer/js-graphql-intellij-plugin very difficult (errors popping up all the time). Thanks 👍

[piotrd]

I second @sedubois. Any plans on taking care of this one?

[cb1kenobi]

tl;dr I spent several hours investigating this and I've come to the conclusion that the call to FSEventStreamFlushSync() has no effect or is broken and it should be removed from libuv.

The concept behind FSEventStreamFlushSync() sounds great. Flush all buffered FS events that the app has yet to receive. The problem is I can't seem to prove that it actually does anything. If I change the FSEventStream latency to 5 seconds, write 1000 files, and then close the watcher, there should be some events that the FSEvents daemon caught and that libuv has yet to receive, but there aren't any.

No matter the latency or number of files I write, I keep getting (FSEvents.framework) FSEventStreamFlushSync(): failed assertion '(SInt64)last_id > 0LL' error.

To make things more interesting, FSEventStreamEventId is actually a UInt64. Obviously it will always be a positive number. If you cast it as a SInt64, then it can be negative and on my machine it is. The reason I say "my machine" is because according to the docs in the FSEvents.h file:

"They are monotonically increasing per system, even across reboots and drives coming and going. They bear no relation to any particular clock or timebase."

I have no idea where this value is persisted or what happens when it overflows.

I tried to figure out if there's a way to detect if there are any more events, but I don't think there is. FSEventStreamGetLatestEventId() just returns the latest event id of events that have already been received by the app, not the buffered events. When the uv__fsevents_event_cb() event callback is fired, one of the arguments is an array of FSEventStreamEventIds, but the latest event id is already set to the latest and greatest event id in that array of event ids. In other words, when uv__fsevents_event_cb() is called, you will have received all buffered events from the FSEvents daemon.

If there have never been any events, then FSEventStreamGetLatestEventId() returns -1 and no error is displayed. In all of my testing, when libuv calls FSEventStreamFlushSync() and there are buffered events, then I always get the assertion failure.

I tried compiling libuv using gnu99 instead of gnu89 just in case, but it had no effect.

I tried looking at other projects to see how they use FSEvents, but I didn't find anybody that used FSEventStreamFlushSync() or FSEventStreamFlushAsync(). For example, Watchman simply stops the stream, invalidates, and releases it: https://github.com/facebook/watchman/blob/master/watcher/fsevents.cpp#L263-L272.

So my vote is to just remove the call to FSEventStreamFlushSync() from libuv. What do you think?

[bnoordhuis]

cc @indutny - as its primary author you probably (hopefully!) have the most informed opinion.

[indutny]

I agree, let's remove it.

[cb1kenobi]

Confirmed the assertion message no longer occurs in Node.js v8.1.0! Thank you!

[vtjnash]

For example, Watchman simply stops the stream, invalidates, and releases it

I'm not sure that's a good example, since if I'm understanding the code correctly, it doesn't appear to be at all "simple" how they were making this strategy valid (e.g. optimizations added to it in https://github.com/facebook/watchman/pull/287, Apache License v2, so unfortunately can't be copied directly into libuv). I'm thinking of opening a bug over at libuv noting that, from reading the source code, it appears that libuv may forget to report events sometimes (according to one code comment added in https://github.com/libuv/libuv/commit/cd2794c01fc84a4118f79e31071cb1bca78918f5, this is done to ensure that libuv doesn't accidentally report an event twice sometimes). Any thoughts? I can't promise to have any time to actually look into or work on this.