Debounced events seem to be getting lost

[skorokithakis]

I'm new to rust, so this may be my fault, but I can't see why.

I create two debounced watchers here:

https://gitlab.com/stavros/hearth/blob/master/src/main.rs#L149

I do this so I can be notified immediately so I can emit a "change detected" event and then, after changes have stopped and 5 seconds have passed from debouncing, I process the files and emit a "done" event.

However, sometimes this "done" event seems to get lost. The code is identical, it's two debounced watchers, one with 0 seconds and one with 5 seconds delay, running in different threads. However, the 5 second watcher doesn't seem to fire, sometimes.

Here's a log of the printed events:

NoticeRemove("/Users/user/Hearth/file.svg")
NoticeRemove("/Users/user/Hearth/file.svg")
Remove("/Users/user/Hearth/file.svg")
Change detected in filesystem.
Remove("/Users/user/Hearth/file.svg")
Adding files to IPFS...
Finished adding files to IPFS.

NoticeWrite("/Users/user/Hearth/.DS_Store")
NoticeWrite("/Users/user/Hearth/.DS_Store")
NoticeRemove("/Users/user/Hearth/file.svg")
NoticeRemove("/Users/user/Hearth/file.svg")
Write("/Users/user/Hearth/.DS_Store")
Change detected in filesystem.
Create("/Users/user/Hearth/file.svg")
Write("/Users/user/Hearth/.DS_Store")
Adding files to IPFS...
Finished adding files to IPFS.

Create("/Users/user/Hearth/file.svg")
NoticeRemove("/Users/user/Hearth/file.svg")
NoticeRemove("/Users/user/Hearth/file.svg")
Remove("/Users/user/Hearth/file.svg")
Change detected in filesystem.
NoticeWrite("/Users/user/Hearth/.DS_Store")
NoticeWrite("/Users/user/Hearth/.DS_Store")
Write("/Users/user/Hearth/.DS_Store")
Write("/Users/user/Hearth/.DS_Store")
Adding files to IPFS...
Finished adding files to IPFS.

NoticeRemove("/Users/user/Hearth/file.svg")
Create("/Users/user/Hearth/file.svg")
Change detected in filesystem.

Log lines before "Change detected in filesystem" are events coming in to the 0-second debouncer, and log lines before "Adding files to IPFS" are events coming in to the 5-second debouncer.

As you can see in the last line, an event came in that never got to the 5-second debouncer. The log line is right after the event is received, so I have no code between the reception of the event and the processing of it.

[dfaust]

As far as I can tell, this looks pretty normal. But it would be better, I you could include the events you created. This way I have to guess what really happened. Keep in mind that FSEvents is very unreliable, you should probably use notify only to detect changes and then re-scan the directory where the change occurred. The re-design (#147) should make that clearer. Also you shouldn't have to use two watchers. The debouncer emits Notice* events immediately when a change is detected. Or is there something missing?

[skorokithakis]

Ah, sorry, I don't have any events other than the ones in the log. What I did was create a file, move it out of the directory and move it back in. Upon moving it back in, it sometimes won't emit the debounced event.

I don't really need the exact file, I just need to be notified every time something in the directory changes. You make a good point about the Notice events, I forgot about them, I will refactor my code to use that. Basically, I'm using the debouncer just for that, to avoid implementing my own (although I guess it's not that hard).

Do you see any better way of implementing this so I am reliably notified? I plan to use the Notice events, like you said, but I worry that the method will still be unreliable sometimes.

[passcod]

While there is no Notify API for it (yet, and for some time to come), on macOS if you want more immediate events you can try to use the kqueue kernel feature instead. It's a lot less easy to use, as you have to start watches on every file and directory you want events on, but as far as I know it's closer spiritually to Linux's inotify: hooked directly into the kernel calls, it theoretically emits right as things happen.

[skorokithakis]

Ah, thank you for the information. I don't need immediacy, I just need reliability. Hopefully notify will be reliable enough.

[skorokithakis]

Hmm, unfortunately this method doesn't work, as there is no NoticeCreate event. In light of that, would the best course of action be to just debounce myself, given that events are not reliable? I'm not sure what that means for this ticket...

[dfaust]

Why do you need a NoticeCreate event? If you can make a good case for it, we might include it in notify. Otherwise, you'll have to implement event debouncing yourself. Have you looked at notify's raw interface? You can use it to get all events directly from FSEvents. If you find any issues with the debounced interface, please open an issue. But as I said, all I can see in your event log is the messiness that is FSEvents and using the raw events won't change that. If you want reliability, you must scan the directory where the event originated.

[skorokithakis]

The NoticeCreate event is because, on Linux, if I move a file to a directory I only get the Create debounced event, and no NoticeCreate or other event (so I don't know when the move actually took place, before the debounce).

I am implementing the raw interface right now, but I'm having some problems figuring out what the events in op should be.

This is the issue for the debounced interface. The 0-second watcher is seeing a Create event but the 5-second watcher is not:

NoticeRemove("/Users/user/Hearth/file.svg")
Create("/Users/user/Hearth/file.svg")
Change detected in filesystem.

Since the two watchers are the same, I would expect this to happen instead:

Remove("/Users/user/Hearth/file.svg")
Change detected in filesystem.
Remove("/Users/user/Hearth/file.svg")
Adding files to IPFS...
Finished adding files to IPFS.

How can the Create event only be seen by one of the two watchers and not the other?

I don't know if I'm explaining this clearly, does the above help?

[dfaust]

How can the Create event only be seen by one of the two watchers and not the other?

The debouncer tries to remove duplicate events reported by FSEvents.

But since your event log doesn't clearly show which watcher reports which event at what time, it's impossible to say whether there is an error in the debouncer or not.

[skorokithakis]

Here's the time stamped log:

Starting hearth...

Initializing IPFS...

Starting API server on 127.0.0.1:26484...

Starting IPFS daemon...

Change detected in filesystem.

Adding files to IPFS...

Finished adding files to IPFS.

Immediate watcher (1518167239): NoticeRemove("/folder/filename.txt")

5-sec watcher (1518167239): NoticeRemove("/folder/filename.txt")

Immediate watcher (1518167239): Remove("/folder/filename.txt")

Change detected in filesystem.

5-sec watcher (1518167244): Remove("/folder/filename.txt")

Adding files to IPFS...

Immediate watcher (1518167244): NoticeWrite("/folder/.DS_Store")

Immediate watcher (1518167244): Write("/folder/.DS_Store")

Change detected in filesystem.

Finished adding files to IPFS.

5-sec watcher (1518167245): NoticeWrite("/folder/.DS_Store")

5-sec watcher (1518167249): Write("/folder/.DS_Store")

Adding files to IPFS...

Finished adding files to IPFS.

5-sec watcher (1518167252): NoticeRemove("/folder/filename.txt")

Immediate watcher (1518167252): NoticeRemove("/folder/filename.txt")

Immediate watcher (1518167252): Create("/folder/filename.txt")

Change detected in filesystem.

5-sec watcher (1518167257): Create("/folder/filename.txt")

Adding files to IPFS...

Finished adding files to IPFS.

5-sec watcher (1518167260): NoticeRemove("/folder/filename.txt")

Immediate watcher (1518167260): NoticeRemove("/folder/filename.txt")

Immediate watcher (1518167260): Remove("/folder/filename.txt")

Change detected in filesystem.

5-sec watcher (1518167265): Remove("/folder/filename.txt")

Adding files to IPFS...

Immediate watcher (1518167265): NoticeWrite("/folder/.DS_Store")

Immediate watcher (1518167265): Write("/folder/.DS_Store")

Change detected in filesystem.

Finished adding files to IPFS.

5-sec watcher (1518167266): NoticeWrite("/folder/.DS_Store")

5-sec watcher (1518167268): NoticeRemove("/folder/filename.txt")

Immediate watcher (1518167268): NoticeRemove("/folder/filename.txt")

Immediate watcher (1518167268): Create("/folder/filename.txt")

5-sec watcher (1518167270): Write("/folder/.DS_Store")

Adding files to IPFS...

Finished adding files to IPFS.

5-sec watcher (1518167273): Create("/folder/filename.txt")

5-sec watcher (1518167279): NoticeRemove("/folder/filename.txt")

Immediate watcher (1518167279): NoticeRemove("/folder/filename.txt")

Immediate watcher (1518167279): Remove("/folder/filename.txt")

Change detected in filesystem.

5-sec watcher (1518167284): NoticeWrite("/folder/.DS_Store")

Immediate watcher (1518167284): NoticeWrite("/folder/.DS_Store")

Immediate watcher (1518167284): Write("/folder/.DS_Store")

5-sec watcher (1518167289): Write("/folder/.DS_Store")

Adding files to IPFS...

Finished adding files to IPFS.

Immediate watcher (1518167294): NoticeRemove("/folder/filename.txt")

Immediate watcher (1518167294): Create("/folder/filename.txt")

Change detected in filesystem.

As you can see, usually the immediate watcher gets events and five seconds later the delayed watcher gets them, except in the last one, where it never fires in the delayed watcher.

[skorokithakis]

Basically, I see two issues here:

• Figure out why the delayed watcher is missing events.
• Add Notice events for every type, which would have obviated my need for the two watchers (currently at least the NoticeCreate event is missing, maybe others too?).

[skorokithakis]

Yep, the NoticeCreate event is definitely needed. Running:

echo "foo" > bar.txt

results in a written file, but no Notice event is emitted (as there's only a Create emitted), which results in a new file with contents but no advance notice.

[skorokithakis]

I moved to a single, delayed watcher, and the Create event is getting lost (not seen at all) one in four to five times. Does this seem odd, or is this expected behaviour on OS X?

[skorokithakis]

Running an FSEvents sample, it catches the ItemRenamed events properly. notify running at the same time and on the same directory does not, so this seems like a notify problem rather than a general FSEvents problem?

[passcod]

Ahhhh, this was dropped, I'm sorry to say.

@dfaust What do you think about adding Notice* events for the other non-immediate ones at least?

[dfaust]

Yeah, totally forgot about this one, sorry.

I added the NoticeWrite and NoticeRemove events because an application may have references to files that need to be invalidated immediately when the files change. This does not apply to newly created files. So I still don't know why NoticeCreate would be useful.

[passcod]

Right. Let's close this cause it's been a year, and we can re-open if it's raised again.

[matklad]

Note we might be hitting something similar in rust-analyzer in https://github.com/rust-analyzer/rust-analyzer/issues/734.

That is, on Mac(linux and windows work ok) the write events seems to be dropped here:

https://github.com/rust-analyzer/rust-analyzer/blob/19718ea109eae2f933ce3464c73879c09f9bdbe2/crates/ra_vfs/tests/vfs.rs#L70-L71

I don't have a mac so I can't debug this myself, and it very well could be a bug in our code though!

[passcod]

Hmmm. I'll have my mac back next month, so I might be able to debug. I'll re-open out of caution anyway, given it seems there is something at least. Thanks for the second (tentative) repro!

[matklad]

@passcod it was a false alarm after all, see https://github.com/rust-analyzer/rust-analyzer/issues/734#issuecomment-462822770

The issue was that notify returned canonicalized paths, while the directory where the test was running was symlinked. We haven't canonicalized the dir name, and that made us to discard the canonicalized path as irrelevant,

[matklad]

or maybe not... After we've fixed that issue, we hit another one in the same test, when, for fs::rename call, we get Create event for one path, but we don't get Remove event for the other path: https://github.com/rust-analyzer/rust-analyzer/issues/734#issuecomment-463265566

[Keats]

I think I'm running into a similar thing on OSX with zola and with Pycharm only somehow. I don't know if Pycharm/Intellij is doing something weird but when I edit a file I get:

Event NoticeRemove("/Users/vincentprouillet/Code/zola/docs/sass/site.scss___jb_old___")
Event Chmod("/Users/vincentprouillet/Code/zola/docs/sass/site.scss")
Event Remove("/Users/vincentprouillet/Code/zola/docs/sass/site.scss___jb_old___")

when I edit a file. No Write whatsoever, just a weird chmod

Editing the file in another editor (VSCode/Sublime/etc) works fine so that might be just Intellij doing weird/crazy things?

[passcod]

Will look further but kneejerk is:

• intellij is known to do weird saves. This can be disabled iirc, or it might be that this is another mode.
• chmod is actually "metadata", so that's probably the mtime change or similar.

Any chance you can try with a raw mode notify to see the actual source events?

On Thu, 23 May 2019, 06:24 Vincent Prouillet, notifications@github.com wrote:

I think I'm running into a similar thing on OSX with zola https://github.com/getzola/zola/blob/master/src/cmd/serve.rs#L181-L204 and with Pycharm only somehow. I don't know if Pycharm/Intellij is doing something weird but when I edit a file I get:

Event NoticeRemove("/Users/vincentprouillet/Code/zola/docs/sass/site.scss_jb_old__") Event Chmod("/Users/vincentprouillet/Code/zola/docs/sass/site.scss") Event Remove("/Users/vincentprouillet/Code/zola/docs/sass/site.scssjb_old___")

when I edit a file. No Write whatsoever, just a weird chmod

Editing the file in another editor (VSCode/Sublime/etc) works fine so that might be just Intellij doing weird/crazy things?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/passcod/notify/issues/150?email_source=notifications&email_token=AABGBC54ISSXBPQWJAEYR5TPWWFWVA5CNFSM4EPZLH6KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODV74EUA#issuecomment-494912080, or mute the thread https://github.com/notifications/unsubscribe-auth/AABGBC5XLFSR54K4VF45NHLPWWFWVANCNFSM4EPZLH6A .

[matklad]

intellij is known to do weird saves

For the reference, here's the code that is reponsible for "create temp file & do rename" dance:

https://github.com/JetBrains/intellij-community/blob/6534a1430752e0720b048accade2c4c441433703/platform/util/src/com/intellij/util/io/SafeFileOutputStream.java#L90-L148

The config option for this is called "use "safe write""

[passcod]

Thanks, that's very helpful!

So, @Keats, what you're seeing is either FSEvent only reporting, or the debouncing eating all but, the metadata event as triggered by this:

if (myPreserveAttributes) {
  FileSystemUtil.clonePermissions(oldFile.getPath(), myTargetFile.getPath());
}

Now, in this particular case, you're getting an event. You may want to just add Chmod to your list of change events. In context, and outside of this issue, that could be someone writing a file with the wrong permissions ("only root can read", for example) and then fixing it, and then zola not triggering a rebuild on the fix.

[Keats]

Thanks for the info! I'll try the raw watcher this weekend and report back the results

[Keats]

The raw events for writing in a markdown file:

RawEvent { path: Some("/Users/vincentprouillet/Code/zola/docs/content/themes/_index.md___jb_tmp___"), op: Ok(CREATE | RENAME | WRITE), cookie: None }
RawEvent { path: Some("/Users/vincentprouillet/Code/zola/docs/content/themes/_index.md"), op: Ok(CHMOD | RENAME), cookie: None }
RawEvent { path: Some("/Users/vincentprouillet/Code/zola/docs/content/themes/_index.md___jb_old___"), op: Ok(REMOVE | RENAME), cookie: None }

[passcod]

Yeah, I think I'm starting to see how that happens, although I've just written out and trashed three different theories and am still not happy about it, so I clearly don't understand it enough yet (and I can't check right now because my rust computer is on the fritz).

Nevertheless, that's super helpful, thanks. For now, adding chmod is your best bet, and I'll work to find a fix for this (and other issues above) right after the current release is done.

On Sun, 26 May 2019, 03:30 Vincent Prouillet, notifications@github.com wrote:

The raw events for writing in a markdown file:

RawEvent { path: Some("/Users/vincentprouillet/Code/zola/docs/content/themes/_index.md_jb_tmp___"), op: Ok(CREATE | RENAME | WRITE), cookie: None } RawEvent { path: Some("/Users/vincentprouillet/Code/zola/docs/content/themes/_index.md"), op: Ok(CHMOD | RENAME), cookie: None } RawEvent { path: Some("/Users/vincentprouillet/Code/zola/docs/content/themes/index.mdjb_old___"), op: Ok(REMOVE | RENAME), cookie: None }

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/passcod/notify/issues/150?email_source=notifications&email_token=AABGBC4XSHK5UFY3EYSCNQDPXFLRHA5CNFSM4EPZLH6KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODWHT4QI#issuecomment-495926849, or mute the thread https://github.com/notifications/unsubscribe-auth/AABGBC657VFSB3KX4WBC3H3PXFLRHANCNFSM4EPZLH6A .