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" notifications@github.com 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
#854 (comment).

[saghul]

Tried on OSX 10.9.5, couldn't reproduce it with the code here: #854 (comment)

[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

[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 facebook/watchman#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 libuv/libuv@cd2794c, 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.