Skip to content

File system watcher returns zero events despite successful FSEvents API initialization #61551

@cbenhagen

Description

@cbenhagen

Summary

Dart's FSEvents implementation on macOS fails to deliver file system events on some machines. To investigate this issue, I added debug logging to runtime/bin/file_system_watcher_macos.cc. The debug output shows errno=32 (Broken pipe) errors when FSEvents callbacks attempt to write event data to the internal pipe. This results in zero events being delivered to applications despite FSEvents API functioning correctly.

Environment

  • Platform: macOS 15.7
  • Architecture: ARM64 (Apple Silicon)
  • Dart SDK versions: Several versions from 2.12 to 3.9. Still present in latest version built from source (latest main branch)
  • Affected Component: runtime/bin/file_system_watcher_macos.cc

Observed Behavior

Debug Output Analysis

On failing machines, the debug output shows:

  1. FSEvents API initializes successfully
  2. FSEvents callbacks are triggered
  3. Event processing completes normally
  4. Pipe write operation fails with errno=32 (Broken pipe)
  5. No events reach the Dart application (0 events received)

On working machines, all pipe write operations succeed and events are delivered normally.

Reproduction

Test Case

The test script performs normal file operations (create, modify, delete) and waits for events. On some machines, no events are received.

Reproduction Script

import 'dart:async';
import 'dart:io';

void main() async {
  print('=== FSEvents Debug Test ===');
  
  var tempDir = await Directory.systemTemp.createTemp('fsevents_test_');
  print('Created temp directory: ${tempDir.path}');
  
  print('Starting native directory watcher...');
  var watcher = tempDir.watch();
  var eventsReceived = 0;
  
  var subscription = watcher.listen((event) {
    eventsReceived++;
    print('DART EVENT #$eventsReceived: ${event.type.index} - ${event.path}');
  });
  
  print('Waiting for watcher to initialize...');
  await Future.delayed(Duration(milliseconds: 100));
  
  print('Creating test file...');
  var testFile = File('${tempDir.path}/test_file.txt');
  await testFile.writeAsString('test content');
  
  print('Modifying test file...');
  await testFile.writeAsString('modified content', mode: FileMode.append);
  
  print('Deleting test file...');
  await testFile.delete();
  
  print('Waiting for final events...');
  await Future.delayed(Duration(milliseconds: 100));
  
  print('Cancelling watcher...');
  await subscription.cancel();
  
  print('\n=== Test Results ===');
  print('Events received: $eventsReceived');
  
  if (eventsReceived > 0) {
    print('✅ SUCCESS: FSEvents are working - received $eventsReceived events');
  } else {
    print('❌ FAILURE: No FSEvents received - file watcher is not working');
  }
  
  print('\nCleaning up temp directory...');
  try {
    await tempDir.delete(recursive: true);
  } catch (e) {
    print('Cleanup error: $e');
  }
  
  print('\n=== Test Complete ===');
  print('Final result: ${eventsReceived > 0 ? "PASSED" : "FAILED"}');
}

Test Results

Working Machine

=== FSEvents Debug Test ===
Created temp directory: /var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h
Starting native directory watcher...
[FSEVENTS DEBUG] AddPath called: path='/var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h', events=15, recursive=1
[FSEVENTS DEBUG] Resolved path: '/var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h' -> '/private/var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h'
[FSEVENTS DEBUG] Creating Node with read_fd=6, write_fd=7
[FSEVENTS DEBUG] Starting FSEvents for path: base_path_length=77, recursive=1
[FSEVENTS DEBUG] FSEventStreamCreate succeeded, stream=0x12c604150
[FSEVENTS DEBUG] FSEventStream scheduled with run loop
[FSEVENTS DEBUG] FSEventStreamStart result: SUCCESS
[FSEVENTS DEBUG] FSEventStream setup completed
Waiting for watcher to initialize...
[FSEVENTS DEBUG] Callback triggered with 1 events
[FSEVENTS DEBUG] Node info: base_path_length=77, recursive=1
[FSEVENTS DEBUG] Event 0: original_path='/private/var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h', flags=0x00028100
[FSEVENTS DEBUG] File exists check: /private/var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h -> true
[FSEVENTS DEBUG] Processed relative path: ''
[FSEVENTS DEBUG] Writing event to pipe: path='', flags=0x00028100, exists=1
[FSEVENTS DEBUG] Write result: 1032 bytes (expected 1032) - SUCCESS
DART EVENT #1: 1 - /var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h
DART EVENT #2: 2 - /var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h
Creating test file...
[FSEVENTS DEBUG] Callback triggered with 1 events
[FSEVENTS DEBUG] Node info: base_path_length=77, recursive=1
[FSEVENTS DEBUG] Event 0: original_path='/private/var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt', flags=0x00019100
[FSEVENTS DEBUG] File exists check: /private/var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt -> true
[FSEVENTS DEBUG] Processed relative path: 'test_file.txt'
[FSEVENTS DEBUG] Writing event to pipe: path='test_file.txt', flags=0x00019100, exists=1
[FSEVENTS DEBUG] Write result: 1032 bytes (expected 1032) - SUCCESS
DART EVENT #3: 1 - /var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt
DART EVENT #4: 2 - /var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt
DART EVENT #5: 2 - /var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt
Modifying test file...
[FSEVENTS DEBUG] Callback triggered with 1 events
[FSEVENTS DEBUG] Node info: base_path_length=77, recursive=1
[FSEVENTS DEBUG] Event 0: original_path='/private/var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt', flags=0x00019500
[FSEVENTS DEBUG] File exists check: /private/var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt -> true
[FSEVENTS DEBUG] Processed relative path: 'test_file.txt'
[FSEVENTS DEBUG] Writing event to pipe: path='test_file.txt', flags=0x00019500, exists=1
[FSEVENTS DEBUG] Write result: 1032 bytes (expected 1032) - SUCCESS
DART EVENT #6: 1 - /var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt
DART EVENT #7: 2 - /var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt
DART EVENT #8: 2 - /var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt
Deleting test file...
Waiting for final events...
[FSEVENTS DEBUG] Callback triggered with 1 events
[FSEVENTS DEBUG] Node info: base_path_length=77, recursive=1
[FSEVENTS DEBUG] Event 0: original_path='/private/var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt', flags=0x00019700
[FSEVENTS DEBUG] File exists check: /private/var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt -> false
[FSEVENTS DEBUG] Processed relative path: 'test_file.txt'
[FSEVENTS DEBUG] Writing event to pipe: path='test_file.txt', flags=0x00019700, exists=0
[FSEVENTS DEBUG] Write result: 1032 bytes (expected 1032) - SUCCESS
DART EVENT #9: 1 - /var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt
DART EVENT #10: 2 - /var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt
DART EVENT #11: 2 - /var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt
DART EVENT #12: 4 - /var/folders/k8/wkdccllx2718jbgb_5qm5dsh0000gn/T/fsevents_test_Ibwa5h/test_file.txt
Cancelling watcher...

=== Test Results ===
Events received: 12
✅ SUCCESS: FSEvents are working - received 12 events

Cleaning up temp directory...

=== Test Complete ===

Failing Machine

=== FSEvents Debug Test ===
Created temp directory: /var/folders/4l/qvvv84514t10q9br028s07xh0000gn/T/fsevents_test_8Rs9un
Starting native directory watcher...
[FSEVENTS DEBUG] AddPath called: path='/var/folders/4l/qvvv84514t10q9br028s07xh0000gn/T/fsevents_test_8Rs9un', events=15, recursive=1
[FSEVENTS DEBUG] Resolved path: '/var/folders/4l/qvvv84514t10q9br028s07xh0000gn/T/fsevents_test_8Rs9un' -> '/private/var/folders/4l/qvvv84514t10q9br028s07xh0000gn/T/fsevents_test_8Rs9un'
[FSEVENTS DEBUG] Creating Node with read_fd=6, write_fd=7
[FSEVENTS DEBUG] Starting FSEvents for path: base_path_length=77, recursive=1
[FSEVENTS DEBUG] FSEventStreamCreate succeeded, stream=0x152304280
[FSEVENTS DEBUG] FSEventStream scheduled with run loop
[FSEVENTS DEBUG] FSEventStreamStart result: SUCCESS
[FSEVENTS DEBUG] FSEventStream setup completed
Waiting for watcher to initialize...
[FSEVENTS DEBUG] Callback triggered with 1 events
[FSEVENTS DEBUG] Node info: base_path_length=77, recursive=1
[FSEVENTS DEBUG] Event 0: original_path='/private/var/folders/4l/qvvv84514t10q9br028s07xh0000gn/T/fsevents_test_8Rs9un', flags=0x00020100
[FSEVENTS DEBUG] File exists check: /private/var/folders/4l/qvvv84514t10q9br028s07xh0000gn/T/fsevents_test_8Rs9un -> true
[FSEVENTS DEBUG] Processed relative path: ''
[FSEVENTS DEBUG] Writing event to pipe: path='', flags=0x00020100, exists=1
Creating test file...
Modifying test file...
Deleting test file...
Waiting for final events...
Cancelling watcher...
[FSEVENTS DEBUG] Write result: -1 bytes (expected 1032) - ERROR: errno=32 (Broken pipe)

=== Test Results ===
Events received: 0
❌ FAILURE: No FSEvents received - file watcher is not working

Cleaning up temp directory...

=== Test Complete ===
Final result: FAILED

Debug Infrastructure Added

To investigate this issue, comprehensive debug logging was added to runtime/bin/file_system_watcher_macos.cc. The modifications include:

Debug Output Added

  • FSEvents stream creation and initialization status
  • Callback invocation with event counts
  • Detailed event processing (paths, flags, existence checks)
  • Pipe write operations with success/failure status and errno details
  • Path resolution and processing steps

Key Debug Modifications

diff --git a/runtime/bin/file_system_watcher_macos.cc b/runtime/bin/file_system_watcher_macos.cc
index 4e4fb47ac15..d50605ba2d6 100644
--- a/runtime/bin/file_system_watcher_macos.cc
+++ b/runtime/bin/file_system_watcher_macos.cc
@@ -86,6 +86,11 @@ class FSEventsWatcher {
     void set_ref(FSEventStreamRef ref) { ref_ = ref; }
 
     void Start() {
+      // DEBUG: Log start of FSEvents setup
+      printf("[FSEVENTS DEBUG] Starting FSEvents for path: base_path_length=%ld, recursive=%d\n", 
+             base_path_length_, recursive_);
+      fflush(stdout);
+      
       FSEventStreamContext context;
       memset(&context, 0, sizeof(context));
       context.info = reinterpret_cast<void*>(this);
@@ -99,13 +104,37 @@ class FSEventsWatcher {
           0.10, kFSEventStreamCreateFlagFileEvents);
       CFRelease(array);
 
+      // DEBUG: Log FSEventStream creation result
+      if (ref == nullptr) {
+        printf("[FSEVENTS DEBUG] CRITICAL: FSEventStreamCreate returned NULL!\n");
+        fflush(stdout);
+        return;
+      } else {
+        printf("[FSEVENTS DEBUG] FSEventStreamCreate succeeded, stream=%p\n", ref);
+        fflush(stdout);
+      }
+
       set_ref(ref);
 
       FSEventStreamScheduleWithRunLoop(ref_, watcher_->run_loop_,
                                        kCFRunLoopDefaultMode);
-
-      FSEventStreamStart(ref_);
+      
+      // DEBUG: Log FSEventStream scheduling result
+      printf("[FSEVENTS DEBUG] FSEventStream scheduled with run loop\n");
+      fflush(stdout);
+
+      Boolean started = FSEventStreamStart(ref_);
+      
+      // DEBUG: Log FSEventStream start result
+      printf("[FSEVENTS DEBUG] FSEventStreamStart result: %s\n", 
+             started ? "SUCCESS" : "FAILED");
+      fflush(stdout);
+      
       FSEventStreamFlushSync(ref_);
+      
+      // DEBUG: Log completion
+      printf("[FSEVENTS DEBUG] FSEventStream setup completed\n");
+      fflush(stdout);
     }
 
     void Stop() {
@@ -205,6 +234,11 @@ class FSEventsWatcher {
   }
 
   Node* AddPath(const char* path, int events, bool recursive) {
+    // DEBUG: Log path addition
+    printf("[FSEVENTS DEBUG] AddPath called: path='%s', events=%d, recursive=%d\n", 
+           path, events, recursive);
+    fflush(stdout);
+    
     int fds[2];
     VOID_NO_RETRY_EXPECTED(pipe(fds));
     FDUtils::SetNonBlocking(fds[0]);
@@ -212,6 +246,11 @@ class FSEventsWatcher {
 
     char base_path[PATH_MAX];
     realpath(path, base_path);
+    
+    // DEBUG: Log resolved path
+    printf("[FSEVENTS DEBUG] Resolved path: '%s' -> '%s'\n", path, base_path);
+    printf("[FSEVENTS DEBUG] Creating Node with read_fd=%d, write_fd=%d\n", fds[0], fds[1]);
+    fflush(stdout);
 
     return new Node(this, base_path, fds[0], fds[1], recursive);
   }
@@ -223,6 +262,10 @@ class FSEventsWatcher {
                        void* event_paths,
                        const FSEventStreamEventFlags event_flags[],
                        const FSEventStreamEventId event_ids[]) {
+    // DEBUG: Log callback entry
+    printf("[FSEVENTS DEBUG] Callback triggered with %zu events\n", num_events);
+    fflush(stdout);
+    
     if (FileSystemWatcher::delayed_filewatch_callback()) {
       // Used in tests to highlight race between callback invocation
       // and unwatching the file path, Node destruction
@@ -231,22 +274,63 @@ class FSEventsWatcher {
     Node* node = static_cast<Node*>(client);
     RELEASE_ASSERT(node->watcher() != nullptr);
     DEBUG_ASSERT(node->watcher()->owner_.IsOwnedByCurrentThread());
+    
+    // DEBUG: Log node info
+    printf("[FSEVENTS DEBUG] Node info: base_path_length=%ld, recursive=%d\n", 
+           node->base_path_length(), node->recursive());
+    fflush(stdout);
+    
     for (size_t i = 0; i < num_events; i++) {
       char* path = reinterpret_cast<char**>(event_paths)[i];
       FSEvent event;
+      
+      // DEBUG: Log original path and flags
+      printf("[FSEVENTS DEBUG] Event %zu: original_path='%s', flags=0x%08x\n", 
+             i, path, event_flags[i]);
+      fflush(stdout);
+      
       event.data.exists =
           File::GetType(nullptr, path, false) != File::kDoesNotExist;
+      
+      // DEBUG: Log file existence check
+      printf("[FSEVENTS DEBUG] File exists check: %s -> %s\n", 
+             path, event.data.exists ? "true" : "false");
+      fflush(stdout);
+      
       path += node->base_path_length();
       // If path is longer the base, skip next character ('/').
       if (path[0] != '\0') {
         path += 1;
       }
+      
+      // DEBUG: Log processed path
+      printf("[FSEVENTS DEBUG] Processed relative path: '%s'\n", path);
+      fflush(stdout);
+      
       if (!node->recursive() && (strstr(path, "/") != nullptr)) {
+        printf("[FSEVENTS DEBUG] Skipping non-recursive path: '%s'\n", path);
+        fflush(stdout);
         continue;
       }
       event.data.flags = event_flags[i];
       memmove(event.data.path, path, strlen(path) + 1);
-      write(node->write_fd(), event.bytes, sizeof(event));
+      
+      // DEBUG: Log write attempt
+      printf("[FSEVENTS DEBUG] Writing event to pipe: path='%s', flags=0x%08x, exists=%d\n",
+             event.data.path, event.data.flags, event.data.exists);
+      fflush(stdout);
+      
+      ssize_t written = write(node->write_fd(), event.bytes, sizeof(event));
+      
+      // DEBUG: Log write result with errno
+      if (written == sizeof(event)) {
+        printf("[FSEVENTS DEBUG] Write result: %ld bytes (expected %zu) - SUCCESS\n", 
+               written, sizeof(event));
+      } else {
+        printf("[FSEVENTS DEBUG] Write result: %ld bytes (expected %zu) - ERROR: errno=%d (%s)\n", 
+               written, sizeof(event), errno, strerror(errno));
+      }
+      fflush(stdout);
     }
   }

Metadata

Metadata

Assignees

Labels

P2A bug or feature request we're likely to work onarea-vmUse area-vm for VM related issues, including code coverage, and the AOT and JIT backends.library-iotriagedIssue has been triaged by sub team

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions