Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Events not firing #10

Closed
whatupdave opened this issue Mar 31, 2011 · 239 comments
Closed

Events not firing #10

whatupdave opened this issue Mar 31, 2011 · 239 comments
Assignees

Comments

@whatupdave
Copy link

I'm trying to pin down exactly what's happening here. The specs don't pass, I ran it in debug mode:

creating Makefile
CFLAGS='-isysroot /Developer/SDKs/MacOSX10.6.sdk -mmacosx-version-min=10.6 -mdynamic-no-pic -std=gnu99 -Os -pipe -Wmissing-prototypes -Wreturn-type -Wmissing-braces -Wparentheses -Wswitch -Wunused-function -Wunused-label -Wunused-parameter -Wunused-variable -Wunused-value -Wuninitialized -Wunknown-pragmas -Wshadow -Wfour-char-constants -Wsign-compare -Wnewline-eof -Wconversion -Wshorten-64-to-32 -Wglobal-constructors -pedantic' /usr/bin/gcc -isysroot /Developer/SDKs/MacOSX10.6.sdk -mmacosx-version-min=10.6 -mdynamic-no-pic -std=gnu99 -dead_strip -framework CoreServices -D DEBUG=true -o '/users/dave/code/temp/rb-fsevent/bin/fsevent_watch' fsevent/fsevent_watch.c
fsevent_watch compiled
.
append_path called for: /users/dave/code/temp/rb-fsevent/spec/fixtures/custom 'path
  resolved path to: /Users/dave/code/temp/rb-fsevent/spec/fixtures/custom 'path

config.sinceWhen    18446744073709551615
config.latency      0.300000
config.flags        00000000
config.paths
  /Users/dave/code/temp/rb-fsevent/spec/fixtures/custom 'path

FSEventStreamRef @ 0x1001085c0:
   allocator = 0x7fff709faee0
   callback = 0x100001522
   context = {0, 0x0, 0x0, 0x0, 0x0}
   numPathsToWatch = 1
   pathsToWatch = 0x7fff709faee0
        pathsToWatch[0] = '/Users/dave/code/temp/rb-fsevent/spec/fixtures/custom 'path'
   latestEventId = -1
   latency = 300000 (microseconds)
   flags = 0x00000000
   runLoop = 0x0
   runLoopMode = 0x0

F
append_path called for: /users/dave/code/temp/rb-fsevent/spec/fixtures/custom 'path
  resolved path to: /Users/dave/code/temp/rb-fsevent/spec/fixtures/custom 'path

config.sinceWhen    18446744073709551615
config.latency      0.300000
config.flags        00000000
config.paths
  /Users/dave/code/temp/rb-fsevent/spec/fixtures/custom 'path

FSEventStreamRef @ 0x1001085c0:
   allocator = 0x7fff709faee0
   callback = 0x100001522
   context = {0, 0x0, 0x0, 0x0, 0x0}
   numPathsToWatch = 1
   pathsToWatch = 0x7fff709faee0
        pathsToWatch[0] = '/Users/dave/code/temp/rb-fsevent/spec/fixtures/custom 'path'
   latestEventId = -1
   latency = 300000 (microseconds)
   flags = 0x00000000
   runLoop = 0x0
   runLoopMode = 0x0


append_path called for: /users/dave/code/temp/rb-fsevent/spec/fixtures
  resolved path to: /Users/dave/code/temp/rb-fsevent/spec/fixtures

config.sinceWhen    18446744073709551615
config.latency      0.500000
config.flags        00000000
config.paths
  /Users/dave/code/temp/rb-fsevent/spec/fixtures

FSEventStreamRef @ 0x1001085e0:
   allocator = 0x7fff709faee0
   callback = 0x100001522
   context = {0, 0x0, 0x0, 0x0, 0x0}
   numPathsToWatch = 1
   pathsToWatch = 0x7fff709faee0
        pathsToWatch[0] = '/Users/dave/code/temp/rb-fsevent/spec/fixtures'
   latestEventId = -1
   latency = 500000 (microseconds)
   flags = 0x00000000
   runLoop = 0x0
   runLoopMode = 0x0

F
append_path called for: /users/dave/code/temp/rb-fsevent/spec/fixtures
  resolved path to: /Users/dave/code/temp/rb-fsevent/spec/fixtures

config.sinceWhen    18446744073709551615
config.latency      0.500000
config.flags        00000000
config.paths
  /Users/dave/code/temp/rb-fsevent/spec/fixtures

FSEventStreamRef @ 0x1001085e0:
   allocator = 0x7fff709faee0
   callback = 0x100001522
   context = {0, 0x0, 0x0, 0x0, 0x0}
   numPathsToWatch = 1
   pathsToWatch = 0x7fff709faee0
        pathsToWatch[0] = '/Users/dave/code/temp/rb-fsevent/spec/fixtures'
   latestEventId = -1
   latency = 500000 (microseconds)
   flags = 0x00000000
   runLoop = 0x0
   runLoopMode = 0x0


append_path called for: /users/dave/code/temp/rb-fsevent/spec/fixtures
  resolved path to: /Users/dave/code/temp/rb-fsevent/spec/fixtures

config.sinceWhen    18446744073709551615
config.latency      0.500000
config.flags        00000000
config.paths
  /Users/dave/code/temp/rb-fsevent/spec/fixtures

FSEventStreamRef @ 0x1001085e0:
   allocator = 0x7fff709faee0
   callback = 0x100001522
   context = {0, 0x0, 0x0, 0x0, 0x0}
   numPathsToWatch = 1
   pathsToWatch = 0x7fff709faee0
        pathsToWatch[0] = '/Users/dave/code/temp/rb-fsevent/spec/fixtures'
   latestEventId = -1
   latency = 500000 (microseconds)
   flags = 0x00000000
   runLoop = 0x0
   runLoopMode = 0x0

F
append_path called for: /users/dave/code/temp/rb-fsevent/spec/fixtures
  resolved path to: /Users/dave/code/temp/rb-fsevent/spec/fixtures

config.sinceWhen    18446744073709551615
config.latency      0.500000
config.flags        00000000
config.paths
  /Users/dave/code/temp/rb-fsevent/spec/fixtures

FSEventStreamRef @ 0x1001085e0:
   allocator = 0x7fff709faee0
   callback = 0x100001522
   context = {0, 0x0, 0x0, 0x0, 0x0}
   numPathsToWatch = 1
   pathsToWatch = 0x7fff709faee0
        pathsToWatch[0] = '/Users/dave/code/temp/rb-fsevent/spec/fixtures'
   latestEventId = -1
   latency = 500000 (microseconds)
   flags = 0x00000000
   runLoop = 0x0
   runLoopMode = 0x0


append_path called for: /users/dave/code/temp/rb-fsevent/spec/fixtures
  resolved path to: /Users/dave/code/temp/rb-fsevent/spec/fixtures

config.sinceWhen    18446744073709551615
config.latency      0.500000
config.flags        00000000
config.paths
  /Users/dave/code/temp/rb-fsevent/spec/fixtures

FSEventStreamRef @ 0x1001085e0:
   allocator = 0x7fff709faee0
   callback = 0x100001522
   context = {0, 0x0, 0x0, 0x0, 0x0}
   numPathsToWatch = 1
   pathsToWatch = 0x7fff709faee0
        pathsToWatch[0] = '/Users/dave/code/temp/rb-fsevent/spec/fixtures'
   latestEventId = -1
   latency = 500000 (microseconds)
   flags = 0x00000000
   runLoop = 0x0
   runLoopMode = 0x0

F
append_path called for: /users/dave/code/temp/rb-fsevent/spec/fixtures
  resolved path to: /Users/dave/code/temp/rb-fsevent/spec/fixtures

config.sinceWhen    18446744073709551615
config.latency      0.500000
config.flags        00000000
config.paths
  /Users/dave/code/temp/rb-fsevent/spec/fixtures

FSEventStreamRef @ 0x1001085e0:
   allocator = 0x7fff709faee0
   callback = 0x100001522
   context = {0, 0x0, 0x0, 0x0, 0x0}
   numPathsToWatch = 1
   pathsToWatch = 0x7fff709faee0
        pathsToWatch[0] = '/Users/dave/code/temp/rb-fsevent/spec/fixtures'
   latestEventId = -1
   latency = 500000 (microseconds)
   flags = 0x00000000
   runLoop = 0x0
   runLoopMode = 0x0



Failures:

  1) FSEvent should work with path with an apostrophe
     Failure/Error: @results.should == [custom_path.to_s + '/']
       expected: ["/users/dave/code/temp/rb-fsevent/spec/fixtures/custom 'path/"]
            got: [] (using ==)
       Diff:
       @@ -1,2 +1,2 @@
       -["/users/dave/code/temp/rb-fsevent/spec/fixtures/custom 'path/"]
       +[]
     # ./spec/rb-fsevent/fsevent_spec.rb:30:in `block (2 levels) in <top (required)>'

  2) FSEvent should catch new file
     Failure/Error: @results.should == [@fixture_path.to_s + '/']
       expected: ["/users/dave/code/temp/rb-fsevent/spec/fixtures/"]
            got: [] (using ==)
       Diff:
       @@ -1,2 +1,2 @@
       -["/users/dave/code/temp/rb-fsevent/spec/fixtures/"]
       +[]
     # ./spec/rb-fsevent/fsevent_spec.rb:40:in `block (2 levels) in <top (required)>'

  3) FSEvent should catch file update
     Failure/Error: @results.should == [@fixture_path.join("folder1/").to_s]
       expected: ["/users/dave/code/temp/rb-fsevent/spec/fixtures/folder1/"]
            got: [] (using ==)
       Diff:
       @@ -1,2 +1,2 @@
       -["/users/dave/code/temp/rb-fsevent/spec/fixtures/folder1/"]
       +[]
     # ./spec/rb-fsevent/fsevent_spec.rb:49:in `block (2 levels) in <top (required)>'

  4) FSEvent should catch files update
     Failure/Error: @results.should == [@fixture_path.join("folder1/").to_s, @fixture_path.join("folder1/folder2/").to_s]
       expected: ["/users/dave/code/temp/rb-fsevent/spec/fixtures/folder1/", "/users/dave/code/temp/rb-fsevent/spec/fixtures/folder1/folder2/"]
            got: [] (using ==)
       Diff:
       @@ -1,3 +1,2 @@
       -["/users/dave/code/temp/rb-fsevent/spec/fixtures/folder1/",
       - "/users/dave/code/temp/rb-fsevent/spec/fixtures/folder1/folder2/"]
       +[]
     # ./spec/rb-fsevent/fsevent_spec.rb:61:in `block (2 levels) in <top (required)>'

Finished in 13.4 seconds
5 examples, 4 failures

I'm running ruby-1.9.2-p180
Mac OSX 10.6.6

I'm not sure what other information would be helpful. If i build the debug binary and run it on a directory i'm not seeing any events firing.

Any ideas?

@whatupdave
Copy link
Author

Ok after filing this I checked apple update and updated to Mac 10.6.7 which has fixed the problem of file system events not firing.

@ttilley
Copy link
Member

ttilley commented Mar 31, 2011

CRAZY! I just read the email github sent about the bug and was worried I forgot to double-check everything in xcode3.latest or something silly. ;)

I'm glad that fixed things for you, but it's worrisome that there might be a configuration out there that just flat out doesn't work. shrug

@ttilley ttilley closed this as completed Mar 31, 2011
@whatupdave
Copy link
Author

I'm not 100% if it was the mac version or something else going on in the system. I rebooted a few times to see if it made a difference. I did install windows boot camp the other day so I guess my beautiful mac will never be the same....

@rmoriz
Copy link

rmoriz commented May 3, 2011

having exactly the same issues. running 10.6.7 with all patches + Xcode 4.0.2

events get fired by OSX as http://www.fernlightning.com/doku.php?id=software:fseventer:start shows them

could not find a way to fix this. tried several different rubies (1.8.7, 1.9.2, 1.8.7EE) without success.

@rmoriz
Copy link

rmoriz commented May 3, 2011

However v0.3.10 works (at least specs):

(in /private/tmp/rb-fsevent)
/Users/rmoriz/.rvm/rubies/ree-1.8.7-2011.03/bin/ruby -S bundle exec rspec ./spec/rb-fsevent/fsevent_spec.rb
No examples were matched by {:focus=>true}, running all
creating Makefile
fsevent_watch compiled
....

Finished in 13.27 seconds
4 examples, 0 failures

@ttilley ttilley reopened this May 6, 2011
@ttilley
Copy link
Member

ttilley commented May 6, 2011

rmoriz: there are two fsevent APIs. one is private, fairly low level, and essentially allows for a userspace application to insert itself in the middle of I/O events in the kernel... which allows not-well-behaved code to cause serious problems. This is the API used by spotlight, and apparently also fseventer.

The public API for FSEvents is based on a daemon that makes use of this much lower level API to log a much less detailed version of events, trimmed down to the directory level, under the /root_of_that_volume/.fseventsd/ directory.

Now... the most confusing detail of what you're seeing is that 0.3.10 works and 0.4 does not. This is different from anyone else I've heard from so far has been seeing: you either have issues that break use of FSEvents by any and all applications (minus spotlight, and cheaters that use undocumented APIs), or issues that break FSEvents when working within a specific volume.

I recently heard from a user who disabled spotlight, re-enabled it, rebooted twice, and POOF... magic. Things worked again. I'm still a bit frustrated I wasn't able to figure out what was going on before his machine just started working again out of nowhere, and thus don't understand the solution to what he was seeing. However, more out of superstition than logic (as spotlight uses /dev/fsevents, not fseventsd), you might want to go to preferences -> spotlight -> privacy, add your root filesystem, reboot, remove it, reboot. You have no idea how painful it is for me to even suggest such a thing.

Before hopping down that rabbit hole, however, it's worth re-trying 0.4 if you're seeing 0.3.10 work. With the changes involved it makes very little sense for you to not be seeing events. I can see there being compounding issues of all kinds that might stop them from reaching you, but not that fsevent_watch itself isn't seeing them. Please re-compile with debugging as well.

export FWDEBUG="true"
gem install rb-fsevent

...Note to self: make that a commandline option.

@rmoriz
Copy link

rmoriz commented May 6, 2011

@ttilley that was me on twitter ;)

btw. 0.3.10 didn't work, only the tests were all green, sorry for the confusion. As far as I saw the 0.4 released added more tests.

The strange thing was, that other fsevent based apps worked but rb-fsevent did not. First I thought maybe the noatime mount option (b/c of my SSD) could be a problem. I remembered that I've disabled spotlight indexing on the main partition. After removing the partition form the ignore list the indexer started. I rebooted 2 times because of other things…

Then rb-fsevent (used in guard) started working perfectly out of the blue. The rb-fsevent tests got green!
I've now disabled spotlight indexing again, rb-fsevent still works.

tl;dr

  • re-active spotlight indexing so mds starts
  • reboot
    => rb-fsevent may work now.
  • disabled the spotlight indexing again

BTW: I've updated my Xcode to the 4.0.x release. That alone did not help but maybe it's part of the solution? (System was already 10.6.7 when I started)

@ttilley
Copy link
Member

ttilley commented May 7, 2011

oh. well. alrighty then!

Definitely good to know that we have since improved the quality of the test suite so that it doesn't give false passes... Especially since I wasn't aware of them. A few of the modifications between 0.3.10 and 0.4 were actually done to prevent false failures. Both may have had the same cause.

@ttilley ttilley closed this as completed May 7, 2011
@lox
Copy link

lox commented Jun 1, 2011

I just had exactly the same issue. Very strange, nothing had changed in terms of ruby, rb-fsevent or any other software on my system, my sync script just stopped getting events. I could see events with fseventer, but nothing was coming through to my script. OSX is 10.6.7.

I tried rebooting twice, no result. I excluded the root partition from indexing, rebooted and everything is working again.

@lox
Copy link

lox commented Jun 1, 2011

Unfortunately the problem re-surfaces once I remove my root partition from the Spotlight exclusion list. Frustrating.

@quackingduck
Copy link

Same issue here. Adding the root partition to the spotlight exclusion list and rebooting fixed the problem

@lox
Copy link

lox commented Jun 6, 2011

Actually, I was able to add just the directories in question to the exclusion list and it works fine.

@bquorning
Copy link

On OSX 10.6.7, I have absolutely no luck making rb-fsevent work. Tried adding my "code" folder to Spotlight’s exclusion list and rebooted the machine. Still doesn’t work.

@ttilley ttilley reopened this Jun 17, 2011
@ttilley
Copy link
Member

ttilley commented Jun 17, 2011

can you all check each volume for /.fseventsd/no_log ? Also, make sure each volume has a /.fseventsd/fseventsd-uuid file containing a UUID of the format:

ABC01D2E-F345-6ABC-D7E8-F9AB01C234D5

Since I'm not using the volume specific API, it might also just blindly be using the root filesystem settings... That's certainly possible.

Also check to make sure there's an as-root process running called fseventsd (or, more specifically, /System/Library/Frameworks/CoreServices.framework/Versions/A/Frameworks/CarbonCore.framework/Versions/A/Support/fseventsd).

I guess also make sure there's a /dev/fsevents ? Looks like it should be mode 0644 with major,minor of 12,6393236.

Also, grep /private/var/log/system.log for 'fseventsd'. Note that "destroying old logs" messages are harmless, and simply mean that the filesystem was modified without that specific fseventsd knowing about it (like... booting into your lion partition on the same drive and having its' spotlight index your snow leopard partition... or what have you). Example:

./system.log:Jun 17 15:09:38 Travis-Tilleys-MacBook-Pro fseventsd[20767]: event logs in /.fseventsd out of sync with volume.  destroying old logs. (1 170038 170050)

I really really wish I knew what the problem was, specifically, for you guys so that I could write in a check for it and display a helpful warning. Any information is invaluable.

@bquorning
Copy link

Just tried it on my home computer: it works fine. Running the “Singular path” example code from the README, I now see fsevent.run happily printing a line when a Dir is changed.

My work computer (which I reported rb-fsevent not working on yesterday) just returned when calling fsevent.run. Maybe pipe.eof? returns true right away? Anyhow, I’ll try debugging per your instructions above when I get back to my work machine on monday.

@robwilliams
Copy link

I came across this issue the other day and noticed it may be due to case sensitivity of directory names in the home folder.

All my projects were stored in:

/Users/Rob/Projects

I wanted to tab complete without typing the uppercase 'P' so I renamed projects to:

/Users/Rob/projects

Great so now I can tab complete.. Hold on a minute Guard has stopped working.

Renaming it back to Projects fixed it.

I tried creating a spec to catch this error but it passes without issues. :/

  # This only happens in the users home directory from what i can tell
  # so to prove it we test both
  {
    :in_home_directory     => Pathname.new(File.expand_path('~')),
    :in_fixtures_directory => Pathname.new(File.expand_path('../../fixtures/', __FILE__))
  }.each { |directory_description, path|

    it "should work with folder that has been renamed from Uppercase to lowercase #{directory_description}" do

      uppercase_path = path.join("FseventCasetest")
      lowercase_path = path.join("fseventcasetest")
      uppercase_file_path = uppercase_path.join("watch.txt")
      lowercase_file_path = lowercase_path.join("watch.txt")

      # Make sure fixtures are clean
      FileUtils.rm_rf(uppercase_path)
      FileUtils.rm_rf(lowercase_path)

      FileUtils.mkdir(uppercase_path)

      FileUtils.touch(uppercase_file_path)

      # Use OS X mv that is case sensitive and allows renaming of a directory
      # to its uppercase equivalent in the same parent directory
      `mv -v #{uppercase_path} #{lowercase_path}`


      @fsevent.watch lowercase_path.to_s do |paths|
        @results += paths
      end

      run
      FileUtils.touch lowercase_file_path
      stop

      File.delete lowercase_file_path
      # Make sure fixtures are clean
      FileUtils.rm_rf(uppercase_path)
      FileUtils.rm_rf(lowercase_path)

      @results.should == [lowercase_path.to_s + '/']

    end
  }

@ttilley
Copy link
Member

ttilley commented Jun 19, 2011

The subset of events involving directory renames (while running) aren't -actually- handled properly, since the communication format between the C subprocess and ruby library doesn't allow for it. This is only an issue when renaming a directory that's explicitly watched (not a subdirectory). I was determined to fix that and a number of other things (see the "coming soon" comments in the readme), but, erm... I got distracted. ^^;

You know, I actually have a fair chunk of time today and throughout this week to devote to the work necessary to check off those TODO items. I guess it's time to get motivated and bang that out...

An aside for @thibaudgg - I intend to use tagged netstrings (probably) as a serialization format. It honestly took an attempt at serializing to JSON in C to make me realize I was being silly creating so much extra work for myself.

@bquorning
Copy link

Before I got around to debugging per @ttilley’s request above, I found the following: Using the irbtools gem (version 1.0.4 here, haven’t tested with others) on ruby-1.8.7-p174 (ruby 1.8.7 (2009-06-12 patchlevel 174) [universal-darwin10.0]) causes rb-fsevent (calling fsevent.run per the README) to return instantly. Using ruby-1.8.7-p334 [ x86_64 ] or ruby-1.9.2-p180 [ x86_64 ] works just fine with irbtools.

Not requiring irbtools makes rb-fsevent work just fine on ruby-1.8.7-p174 here.

So, that looks like a bug right there. (Though maybe not on this gem…)

@ttilley
Copy link
Member

ttilley commented Jun 20, 2011

twitch

@bquorning
Copy link

My problems aren’t over yet: Now rb-fsevent does not work on my work computer anymore. Not in 1.8.7 (any patchlevel) or 1.9.2. With or without irbtools, no difference.

  • I have a /.fseventsd folder. (root:admin mode 700)
  • I have no /.fseventsd/no_log file.
  • I do have the /.fseventsd/fseventsd-uuid file with a proper-looking UUID. (root:admin mode 600)
  • The process /System/Library/Frameworks/CoreServices.framework/Versions/A/Frameworks/CarbonCore.framework/Versions/A/Support/fseventsd is running
  • There is a device /dev/fsevents (root:wheel mode 644)
  • grep fseventsd /private/var/log/system.log reveals nothing.

This is on OSX 10.6.8, 2.4GHz Intel Core 2 Duo. Let me know if you need more information.

@bquorning
Copy link

I just tried running the README sample code from an unsaved TextMate file. Here, Dir.pwd is "/private/var/folders/ds/[something very long]/-Tmp-/" – and rb-fsevent works!

Now, why doesn’t it work when watching my home dir? And how can I help you debug this issue?

@ttilley
Copy link
Member

ttilley commented Jul 14, 2011

...wtf? so it works under /private but not outside of /private? can you try other folders that are under /private/?

@bquorning
Copy link

Today’s round of debugging leaves me equally baffled…

  1. Tried watching /private (works), /Users/benjamin (works!) and /Users/benjamin/code (doesn’t work).
  2. I tried making a new subfolder /Users/benjamin/kode and watching it as first “kode”, then “Kode.” Both work.
  3. Suspecting that my code folder’s name (“code”) was the problem, I renamed the folder and watched it. Yay, now it works.
  4. Renamed back to “code” to confirm that the problem were indeed the folder’s name. Argh (but yay, I guess), it still works.

Concluding: I don’t know what the problem was, but changing the folder’s name to something else, and back, seems to have solved the problem.

@ttilley
Copy link
Member

ttilley commented Jul 15, 2011

That actually says quite a bit. When you rename a folder, that doesn't change the inode that data is kept in... just metadata. So, technically, there wasn't a new 'thing' to watch. It's not the folder itself that's a problem, OR that it's under the specially-handled OSX 'private' folder where exceptions are made in the realpath logic.

[09:13:08][~]$ stat -x code
  File: "code"
  Size: 68           FileType: Directory
  Mode: (0751/drwxr-x--x)         Uid: (  501/ ttilley)  Gid: (   20/   staff)
Device: 14,2   Inode: 5577795    Links: 2
Access: Fri Jul 15 09:12:43 2011
Modify: Fri Jul 15 09:12:43 2011
Change: Fri Jul 15 09:12:43 2011
[09:13:17][~]$ mv code kode
[09:13:24][~]$ stat -x kode
  File: "kode"
  Size: 68           FileType: Directory
  Mode: (0751/drwxr-x--x)         Uid: (  501/ ttilley)  Gid: (   20/   staff)
Device: 14,2   Inode: 5577795    Links: 2
Access: Fri Jul 15 09:12:43 2011
Modify: Fri Jul 15 09:12:43 2011
Change: Fri Jul 15 09:12:43 2011
[09:13:29][~]$ mv kode code
[09:13:40][~]$ stat -x code
  File: "code"
  Size: 68           FileType: Directory
  Mode: (0751/drwxr-x--x)         Uid: (  501/ ttilley)  Gid: (   20/   staff)
Device: 14,2   Inode: 5577795    Links: 2
Access: Fri Jul 15 09:12:43 2011
Modify: Fri Jul 15 09:12:43 2011
Change: Fri Jul 15 09:12:43 2011

Note that the inode (where it's kept on disk, the thing being watched) hasn't changed. It remains 5577795. Also, the access/modify/change times have stayed the same throughout. ALL that has changed is a small chunk of metadata in the inode referring to the directory.

I mean, it's not a solution, but it IS a significant amount of information.

@ttilley
Copy link
Member

ttilley commented Jul 15, 2011

It's good to know we're not the only ones seeing fsevents do crazy things of a similar nature -> http://lists.apple.com/archives/filesystem-dev/2011/Jan/msg00000.html

Note that his testing scenario resulted in the file creation event in one scenario, but not another (where the file was deeper in the tree before the multiple-level-ancestor directory was renamed)... and at least for time machine, both cases resulted in an inaccurate backup.

Fun times.

@volkanunsal
Copy link

I'm having this exact same problem. The event are not firing and as a result Guard, which depends on rb-fsevent, does not work on my system. Hopefully a solution can be found for it.

@bdkjones
Copy link

@andreyvit did most of the work; I just emailed Apple a lot. You guys were 80% of the way there years ago. It just took a little more info to get a workaround in place.

Sent from my iPhone

On May 21, 2015, at 00:17, Thibaud Guillaume-Gentil notifications@github.com wrote:

@andreyvit @bdkjones @ttilley thanks for having resolved that one!


Reply to this email directly or view it on GitHub.

@andreyvit
Copy link
Member

I'm putting the last touches on FSEventsFix. Meanwhile, we've sat down with @tvasenin and found HFS+ driver source code (which is open-source, after all — the fact that was helpfully discovered by first finding some source code references inside a disassembled Mach kernel, lol). We've spent a fair amount of time digging inside, but didn't come across anything that can possibly convert names into lower case. :-( :-)

@andreyvit
Copy link
Member

FSEventsFix 1.0.0 has just been released using unmodified @ttilley's CFURL_realpath (who's been added to copyrights). I've deleted the repair functions and verified that the fix works on actual broken folders. I've also tried to explain the bug and the workaround in more detail in README.

Thanks to everyone involved; a collaboration like this is a highlight of everything that's good about open-source Cocoa community. It's a lot of pleasure to work with you guys.

@thibaudgg
Copy link
Member

👌

@andreyvit
Copy link
Member

...and of course that was not the end of the story. I've decided that a radical simplification of the API and internals is in order, so let me present FSEventsFix 2.0. :-)

Important changes:

  1. It's 10x safer ©: realpath is now only replaced for the FSEvents binary, not for every image in the process, and we're no longer using a dyld hook.
  2. Added FSEventsFixIsCorrectPathToWatch function to check the result of FSEventStreamCopyPathsBeingWatched for the ultimate test of whether the fix has worked.
  3. No more logging and debug options; FSEventsFixEnable returns bool and takes an optional char ** argument for an error message if any.
  4. For the orig_realpath called from our CFURL-based reimplementation, we're now using the proper _realpath$DARWIN_EXTSN instead of the strictly-POSIX _realpath.
  5. The functions no longer try to be thread-safe by executing everything on an internal queue (which has been removed), and in fact there's no mutable global state except for the import table of FSEvents. If the caller wants thread safety, they can bring their own dispatch queue or whatever.

@bdkjones
Copy link

We've got a new twist to handle.

The FSEventsFix library works great. However, the one thing it does NOT handle is the case where a path is being watched and events are being reported perfectly normally... and then the "singularity" occurs that breaks the folder. Boom: no more events reported.

In my app, the user can fix this by clicking a "refresh" button in my UI, which scans the project folder and recreates the FSEvents stream. But that's manual work, annoying AND the end result is still the same as before the fix: our apps stop responding to changes in certain folders.

Thus far, the only way I can think to combat this is polling. Every 30 seconds, ask the FSEventsStream what paths it thinks it's watching, then test each one with FSEventsFix and, if any of them are broken, recreate the stream.

Anyone have a better approach?

@thibaudgg
Copy link
Member

Using polling to make system events work is kind of a joke, but sadly I can't think of better approach.
Is refreshing fast enough?

@andreyvit
Copy link
Member

@bdkjones While this case is certainly possible, I'd say that when the app stops working, the user will notice and will try restarting it (or clicking a refresh button, if one is available) as the first troubleshooting step. I'm not sure we actually need to do anything.

@andreyvit
Copy link
Member

@bdkjones On the other hand, the set of broken folders under my Dropbox seems to change at least weekly, so I can imagine an unfortunate case where the user has to do manual actions every few days. But I think I'm temporarily out of energy for this bug and would rather not deal with optional complications. :-)

@ttilley
Copy link
Member

ttilley commented May 26, 2015

Implementing polling as a solution kinda defeats the purpose a bit. Not
entirely, of course, but if you're on battery power I'd imagine polling of
any kind might make one grumpy. (It'd certainly make me grumpy)

A less invasive measure might be to double check monitored paths after an
event of some kind has already fired. It wouldn't always be effective, but
it's as much as I'd be willing to do since it wouldn't involve additional
wake ups from sleep.

Either way, it'd be somewhat complicated. Save the last event id, stop
monitoring, re-monitor but with a "include since event id " provision...

I'm not putting that much effort in without completely rewriting rb-fsevent
as an actual ruby c extension (to take advantage of the "ignore events
caused by this process" flag).

On Tuesday, May 26, 2015, Andrey Tarantsov notifications@github.com wrote:

@bdkjones https://github.com/bdkjones On the other hand, the set of
broken folders under my Dropbox seems to change at least weekly, so I can
imagine an unfortunate case where the user has to do manual actions every
few days. But I think I'm temporarily out of energy for this bug and would
rather not deal with optional complications. :-)


Reply to this email directly or view it on GitHub
#10 (comment)
.

Sent from Gmail Mobile

@andreyvit
Copy link
Member

I agree with @ttilley; if I were interested in solving the problem, I wouldn't do polling. One option would be to create FSEvents watchers for other potential names (for a normal folder, you can preregister a lowercase name, and for a broken folder, you can register its realpath name). So if the path has N components, you would create 2N watchers instead of one (or you can watch 2N paths with a single watcher, add a trick to FSEventsFix to return different values from each intercepted realpath call).

@ttilley
Copy link
Member

ttilley commented Jun 9, 2015

Sigh. OSX 10.11 might break our workaround without fixing fsevents either. Fuck all to NDAs, from the pre-release documentation:

System Integrity Protection

A new security policy that applies to every running process, including privileged code and code that runs out of the sandbox. The policy extends additional protections to components on disk and at run-time, only allowing system binaries to be modified by the system installer and software updates. Code injection and runtime attachments are no longer permitted.

I haven't tested it yet. I'm not even sure I'll still have broken folders after updating to test with (or if i'll regret updating for numerous other reasons).

@andreyvit
Copy link
Member

@ttilley We'll see what it actually means in practice. And maybe Apple will fix the bug in 10.11, who knows. I don't think we should worry about this until after the public beta.

@ttilley
Copy link
Member

ttilley commented Jun 9, 2015

@andreyvit well i took the plunge and previously broken folders have fixed themselves, though probably only temporarily... i noticed installd doing an intensive audit for a good 20 minutes. also, google chrome is now the only google app i have installed that will still run. even the google updater service spews error messages. google drive is a complete no go. instant regret.

@bdkjones
Copy link

bdkjones commented Jun 9, 2015

You didn't upgrade your main partition, did you? Ouch. OS X previews before DP4 are almost always a disaster. Hope you used a separate partition!

@bdkjones
Copy link

bdkjones commented Jun 9, 2015

Also: the Apple DTS Engineer got back to me with more information. His speculation was not correct, or at least it was not the whole story.

Apple has known about the issue that causes our problem with FSEvents for years, although this is the first time anyone has shown them that the issue breaks FSEvents. The underlying problem is way down in VFS and, apparently, fixing it involves a monumental effort and there are other side effects.

My interpretation of that is that we aren't likely to see this problem go away until Apple abandons HFS+ as their disk format. So my money is on 10.11 still having the same issue as 10.10 and previous.

@andreyvit
Copy link
Member

@bdkjones Any chance you can share the actual DTS exchange with me privately? (I assume @ttilley would love to read it as well.)

@ttilley
Copy link
Member

ttilley commented Jun 9, 2015

indeed i would.

@andreyvit
Copy link
Member

Holy fucking crap. I've just reproduced the issue on demand.

Before:

% ~/dev/mini/find-fsevents-bugs/find-fsevents-bugs ~/Dropbox  
Result 1:                                                                      
  readdir:         /Users/andreyvit/Dropbox/Budget
  realpath:        /Users/andreyvit/Dropbox/Budget
 !FSCopyAliasInfo: /Users/andreyvit/Dropbox/budget
Result 2:                                          
  readdir:         /Users/andreyvit/Dropbox/Clients/Ascendo
  realpath:        /Users/andreyvit/Dropbox/Clients/Ascendo
 !FSCopyAliasInfo: /Users/andreyvit/Dropbox/Clients/ascendo
Result 3:                                                                      
  readdir:         /Users/andreyvit/Dropbox/Clients/KEY-TEC
  realpath:        /Users/andreyvit/Dropbox/Clients/KEY-TEC
 !FSCopyAliasInfo: /Users/andreyvit/Dropbox/Clients/key-tec
Done, 3 result(s).                                                             

then (naturally, the folder is actually called Writing):

% ls /Users/andreyvit/Dropbox/writing

After:

% ~/dev/mini/find-fsevents-bugs/find-fsevents-bugs ~/Dropbox 
Result 1:                                                                      
  readdir:         /Users/andreyvit/Dropbox/Budget
  realpath:        /Users/andreyvit/Dropbox/Budget
 !FSCopyAliasInfo: /Users/andreyvit/Dropbox/budget
Result 2:                                          
  readdir:         /Users/andreyvit/Dropbox/Clients/Ascendo
  realpath:        /Users/andreyvit/Dropbox/Clients/Ascendo
 !FSCopyAliasInfo: /Users/andreyvit/Dropbox/Clients/ascendo
Result 3:                                                                      
  readdir:         /Users/andreyvit/Dropbox/Clients/KEY-TEC
  realpath:        /Users/andreyvit/Dropbox/Clients/KEY-TEC
 !FSCopyAliasInfo: /Users/andreyvit/Dropbox/Clients/key-tec
Result 4:                                                                      
  readdir:         /Users/andreyvit/Dropbox/Writing
  realpath:        /Users/andreyvit/Dropbox/Writing
 !FSCopyAliasInfo: /Users/andreyvit/Dropbox/writing
Done, 4 result(s).                                                             

@andreyvit
Copy link
Member

So for those who's not Bryan or Travis, the bug, as explained by the new favorite pet theory of Apple, is that VFS layer sometimes caches a name provided by a userspace process instead of the correct name, and then uses the cached name to answer some API calls.

Based on the above, ‘sometimes’ is actually ‘pretty much all the time’.

Caching is definitely a trivially reproducible part of the problem, but there's also an unknown ingredient that sometimes causes the wrong name to persist across reboots, presumably by getting written to disk (but maybe it just gets broken on every boot).

@bdkjones
Copy link

@andreyvit Huh? You reproduced it just by calling ls? I was doing that for weeks and did not get that on my end. Can you confirm that this breaks any folder on demand?

@andreyvit
Copy link
Member

@bdkjones I did! But maybe I just lucked out. I cannot do it again myself. :-( There's some other precondition required.

@ttilley
Copy link
Member

ttilley commented Jun 10, 2015

poked a kernel dev staffing a lab at WWDC. lol. https://twitter.com/jauricchio/status/608663324004188160

@andreyvit
Copy link
Member

@ttilley They actually had a dedicated file systems lab there (Tue 9:00). Not sure how to find someone from it, though.

@ttilley
Copy link
Member

ttilley commented Jun 10, 2015

may be fixed in 10.11. maybe. https://twitter.com/jauricchio/status/608713202935844864

@ttilley
Copy link
Member

ttilley commented Sep 29, 2015

I can confirm from personal experience (so far) that this is no longer an issue in El Capitan 10.11. For previous installations the workaround has proven to be effective, even if it's a hell of a workaround...

If this ever proves not to be the case, please reopen this issue. ❤️

@ttilley ttilley closed this as completed Sep 29, 2015
@ttilley
Copy link
Member

ttilley commented Sep 29, 2015

additional note: rb-fsevent is likely not breaking the additional security constraints on 10.11 only because we check for the issue before hotpatching realpath, and the check has yet to show a broken path.
¯_(ツ)_/¯

@thibaudgg
Copy link
Member

Awesome thanks for the news!
@ttilley in case you were not aware of that Rails PR (listen => rb-fsevent) 😍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests