Windows FileWatcher misses modifications made after watcher.ready fires

[DanTup]

On Windows I see missed events if we wait for watcher.ready and then modify a file that was very recently created. This code watches for ready then modifies the file, but the watch event is never printed. Adding a fake delay before modifying the file "fixes" the issue.

import 'dart:io';

import 'package:watcher/watcher.dart';

Future<void> main(List<String> arguments) async {
  Directory('tmp').createSync(recursive: true);
  final file = File('tmp/file1')
    ..createSync()
    ..writeAsString('one');
  final watcher = FileWatcher(file.path);
  final sub = watcher.events.listen((event) {
    print(event.type);
  });

  // Wait for watcher to be ready so we do not miss events.
  await watcher.ready;

  // Uncommenting this fixes the issue.
  // await Future.delayed(const Duration(seconds: 5));

  // Write to the file - this should be detected.
  file.writeAsString('two');

  await Future.delayed(const Duration(seconds: 5));

  await sub.cancel();
}

[gspencergoog]

Could this just be due to using the PollingFileWatcher on Windows? I created a PR that duplicates the code of the polling watcher (https://dart-review.googlesource.com/c/sdk/+/382243), but applies it to a file package File instead of a path string, and even for a MemoryFileSystem, it has the same issue.

So, I'm just mentioning that maybe it's just something in the design of the PollingFileWatcher and not something specific to Windows. I haven't been able to find the issue, though. I'm starting to wonder if the polling version should just err on the side of notifying more often than necessary (e.g. notify of a "modification" when the file is first watched).

[DanTup]

Seems possible. I didn't dig too deep, but I assumed the polling watcher would take a snapshot and then fire ready, such that no events could be lost (but events that occur during the snapshot build could end up as "additional" events). I also agree that too many events is better than not enough - an app can probably handle additional events that were unnecessary, but you can't handle events you never get.

[jakemac53]

Note that you should be awaiting at least the first call to writeAsString('one') here to get any sort of reliable behavior - I would actually expect to get either 1 or 2 events as written depending on race conditions.

That being said, I could not reproduce this behavior using the polling watcher on Linux. And I didn't see any obvious errors in the polling logic.

I did notice that the watcher will shut down if modificationTime(..) throws, but that isn't supposed to throw according to the API. In general my hunch is it has something to do with windows claiming a file does not exist, even though createSync returned completed already. And then some weirdness around the behavior in that case.

@DanTup I am curious if you modify this line https://github.com/dart-lang/watcher/blob/master/lib/src/file_watcher/polling.dart#L67, to add a print(modified) after that call, if it is null.

[DanTup]

@jakemac53

@DanTup I am curious if you modify this line https://github.com/dart-lang/watcher/blob/master/lib/src/file_watcher/polling.dart#L67, to add a print(modified) after that call, if it is null.

It appears not - there is a timestamp every time (it seems to hit this code 5 times):

[DanTup]

This comment seems related though?

// If this is the first poll, don't emit an event, just set the last mtime
// and complete the completer.

It seems the first time we find a file, we record the lastModified but we do not emit an event. However subsequent polls still get the same modified time, so it's then treated as not modified, and therefore still no event. Here's some additional logging:

So, I guess my question is why we don't emit an event on the first detection of a file? If we specifically want to delay the event to the next poll, then surely we need to record an older timestamp than the actual modified timestamp, otherwise we will miss files that are created and only ever have a single timestamp?

(Edit: Looks like this code is 9yrs old, but I can't find any more clues about this in the original change - https://github.com/dart-lang/watcher/commit/57c5f5d794d318f2f6cd301cea93eda9b2cd77e0..)

[jakemac53]

So, I guess my question is why we don't emit an event on the first detection of a file?

It wasn't actually modified in that case (or, we don't have any reason to believe it was). File watchers are only supposed to be used on files that do exist (otherwise, it is supposed to immediately shut itself down and close its stream). Always emitting an event immediately wouldn't be useful afaik.

[DanTup]

Oh sorry, I forgot that this was on the file and that it had just been created.. So I wonder if it's down to the accuracy of the timestamps :/ Let me do some more digging..

[jakemac53]

Based on the logs you showed, the watcher code itself seems fine here.... it is simply not seeing the time stamp get updated so it is not emitting an event.

Could you add in more prints possibly? Maybe after the await watcher.ready; and inside a then callback for the writeAsString calls. I am definitely suspicious that it has to do with the unawaited writeAsString calls though. And, possibly try passing flush: true?

[DanTup]

I am definitely suspicious that it has to do with the unawaited writeAsString calls though

Whoops! 😅

However, with those fixed - I see this... So I do think the issue here is the modified time granularity?

[DanTup]

I can't find a good source, but according to https://stackoverflow.com/questions/31519880/windows-compatible-filesystems-file-time-resolutions, the granularity for NTFS is 100ns? It seems quite odd that my printed timestamps are all round seconds every time I run this 🤔

[jakemac53]

Try passing flush: true?

[DanTup]

No difference. Seems like https://github.com/dart-lang/sdk/issues/51937 is the issue?

Workaround: A hard-coded 1s delay in watcher.ready? 😅

[jakemac53]

Workaround: A hard-coded 1s delay in watcher.ready? 😅

Heh... I don't think we should do that (it could end up creating some pathological slowness that is hard to diagnose).

This seems like a general problem beyond just the first event also... if a user saves a file twice in a second (probably not that uncommon....), we will only ever see the first change?

[jakemac53]

I am going to close this issue given there isn't anything that can be done with this package short of providing its own modified time implementation via FFI which is probably not worth doing.

[DanTup]

Heh... I don't think we should do that (it could end up creating some pathological slowness that is hard to diagnose).

Indeed 😅

This seems like a general problem beyond just the first event also... if a user saves a file twice in a second (probably not that uncommon....), we will only ever see the first change?

Yeah, I'm wondering how many weird analysis server inconsistencies we've seen when external processes modify files (codegen, changing git branches etc.) could be caused by this..

I am going to close this issue given there isn't anything that can be done with this package short of providing its own modified time implementation via FFI which is probably not worth doing.

Yeah, agreed. I wonder how complicated fixing in dart:io would be. I'm guessing it's not just some nice Dart code 🙃

[jakemac53]

Yeah I looked a bit, it is a lot of platform specific c++ code. And it isn't clear the c++ APIs being used actually support more granular times (I saw that they are at least mostly in terms of time_t types which are usually only second granularity...). Somebody with more domain specific knowledge will have to chime in on that issue.

[DanTup]

Yeah, I just added a note at https://github.com/dart-lang/sdk/issues/51937#issuecomment-2326971351 along those lines.

[DanTup]

@jakemac53 just a thought... since stat is being used to get the modified time:

https://github.com/dart-lang/watcher/blob/0484625589d8512b36a7ad898a6cc6351d24c556/lib/src/stat.dart#L31-L33

We also have access to size. If we kept a pair of modifiedTime + size, I think we could detect many of these changes (any that change the size), so the number of lost events would be much smaller?

(ofc, getting the SDK issue fixed would be better, but I suspect that's less easy)

[jakemac53]

I am not sure how I feel about that, while it would catch many changes it adds a possibly even weirder and harder to discover edge case?

[DanTup]

It could be documented in the watcher dartdocs (and it would be quite visible in the code here). The existing issue was rather difficult to track down anyway (as it's not really in watcher, but the SDK).

Missing X events seems better than missing X + Y events in every way.. The ones that are missed are already pretty random (because it depends on the system clock at the time of the writes and how the times get truncated).

I don't feel strongly though, it just popped into my head and I thought I'd note it. Fixing the SDK would certainly be better... I just don't know how likely that is to happen and over what timeframe.. I wish I could contribute the fix there, but I've written so little C++ in my life (and it was >20 years ago) that I'm not sure it's within my capabilities 😄