Added paths prefixed with /private when listening on a tmpdir (OS X)

[olivernn]

Whilst testing some code that uses Listen I've noticed that the paths yielded from the Listen.to block have their paths prefixed with /private when listening on a tmpdir.

I've put together a small test case that reproduces the bug on my machine (late 2011 MacBook Pro; OS X 10.9), I've not had a chance to test this on any other platform.

$ ruby listen_tmp_dir_bug.rb
Ruby version: 2.1.1
Listen version: 2.7.9
tempdir path: /var/folders/q8/r8v1qxb54l3_mtnj6kd4g0kw0000gn/T/listen-test20140701-92313-zg1ixu
file_path: /var/folders/q8/r8v1qxb54l3_mtnj6kd4g0kw0000gn/T/listen-test20140701-92313-zg1ixu/foo
added: /private/var/folders/q8/r8v1qxb54l3_mtnj6kd4g0kw0000gn/T/listen-test20140701-92313-zg1ixu/foo

My test case is below:

require 'rubygems'
require 'listen'
require 'listen/version'
require 'tmpdir'

puts "Ruby version: #{RUBY_VERSION}"
puts "Listen version: #{Listen::VERSION}"

Dir.mktmpdir('listen-test') do |dir|
  tmpdir_path = Pathname(dir)
  file_path = tmpdir_path + 'foo'

  puts "tempdir path: #{tmpdir_path}"
  puts "file_path: #{file_path}"

  begin
    listener = Listen.to(tmpdir_path) do |_, added, _|
      Array(added).each { |path| puts "added: #{path}"}
    end

    listener.start

    FileUtils.touch(file_path)

    sleep 1 # sleep a bit so the event happens
  ensure
    listener && listener.stop
  end
end

[e2]

Thanks - looks like a bad bug.

I couldn't reproduce it yet, so could you run it with the environment variable set: LISTEN_GEM_DEBUGGING=2 and paste the output?

[olivernn]

Here is the output with the debugging:

$ LISTEN_GEM_DEBUGGING=2 ruby listen_gem_bug.rb
I, [2014-07-02T18:29:50.038465 #92702]  INFO -- : Celluloid loglevel set to: 0
D, [2014-07-02T18:29:50.053587 #92702] DEBUG -- : Adapter: considering TCP ...
D, [2014-07-02T18:29:50.053689 #92702] DEBUG -- : Adapter: considering polling ...
D, [2014-07-02T18:29:50.053734 #92702] DEBUG -- : Adapter: considering optimized backend...
I, [2014-07-02T18:29:50.055486 #92702]  INFO -- : Record.build took 0.00014495849609375 seconds
Ruby version: 2.1.1
Listen version: 2.7.9
tempdir path: /var/folders/q8/r8v1qxb54l3_mtnj6kd4g0kw0000gn/T/listen-test20140702-92702-1x6o3df
file_path: /var/folders/q8/r8v1qxb54l3_mtnj6kd4g0kw0000gn/T/listen-test20140702-92702-1x6o3df/foo
D, [2014-07-02T18:29:50.245157 #92702] DEBUG -- : fsevent: /private/var/folders/q8/r8v1qxb54l3_mtnj6kd4g0kw0000gn/T/listen-test20140702-92702-1x6o3df
D, [2014-07-02T18:29:50.245994 #92702] DEBUG -- : raw queue: [:dir, #<Pathname:/private/var/folders/q8/r8v1qxb54l3_mtnj6kd4g0kw0000gn/T/listen-test20140702-92702-1x6o3df>, ".", {:recursive=>true}]
D, [2014-07-02T18:29:50.247063 #92702] DEBUG -- : unknown: dir:/private/var/folders/q8/r8v1qxb54l3_mtnj6kd4g0kw0000gn/T/listen-test20140702-92702-1x6o3df ({:recursive=>true})
D, [2014-07-02T18:29:50.247798 #92702] DEBUG -- : Scanning: .: {:recursive=>true} [{}] -> (#<Set: {#<Pathname:/private/var/folders/q8/r8v1qxb54l3_mtnj6kd4g0kw0000gn/T/listen-test20140702-92702-1x6o3df/foo>}>)
D, [2014-07-02T18:29:50.249015 #92702] DEBUG -- : unknown: file:/private/var/folders/q8/r8v1qxb54l3_mtnj6kd4g0kw0000gn/T/listen-test20140702-92702-1x6o3df/foo ({})
I, [2014-07-02T18:29:50.350521 #92702]  INFO -- : listen: raw changes: [[:added, "/private/var/folders/q8/r8v1qxb54l3_mtnj6kd4g0kw0000gn/T/listen-test20140702-92702-1x6o3df/foo"]]
I, [2014-07-02T18:29:50.350640 #92702]  INFO -- : listen: final changes: {:modified=>[], :added=>["/private/var/folders/q8/r8v1qxb54l3_mtnj6kd4g0kw0000gn/T/listen-test20140702-92702-1x6o3df/foo"], :removed=>[]}
D, [2014-07-02T18:29:50.350791 #92702] DEBUG -- : Callback took 2.8133392333984375e-05 seconds
W, [2014-07-02T18:29:51.063050 #92702]  WARN -- : Terminating task: type=:finalizer, meta={:method_name=>:__shutdown__}, status=:callwait
added: /private/var/folders/q8/r8v1qxb54l3_mtnj6kd4g0kw0000gn/T/listen-test20140702-92702-1x6o3df/foo

So a quick check shows that, on my machine at least, /var is symlinked to /private/var

$ readlink /var
private/var

I don't know the internals of the gem but it looks like fsevent is yielding the actual path to added file, which I guess make sense. I can modify my test code to resolve symbolic links, I don't think this is then an issue with Listen, just a combination of odd behaviour from ruby's tmpdir handling and OS X's tmpdir fs, what do you think?

[e2]

If you check out: https://github.com/guard/listen/blob/master/lib/listen/adapter/darwin.rb#L29 the rel_path is supposed to be calculated as relative to the watched dir.

Listen wasn't designed to "unresolve" symlinks, but the above line could be "fixed" to behave as expected:

rel_path = new_path.relative_path_from(dir.realpath).to_s

Let me know if that works (I don't use OSX at all).

[e2]

The best "approach" is to never resolve symlinks within Listen (if possible) - anything Listen returns that is symlinked should always seem "unresolved" (so the user or plugin can decide whether to resolve or not).

[olivernn]

Yep, I worked around it by resolving the symlink myself in my test, no big deal, was just weird, almost definitely not a problem with the gem.

Does this issue/question/investigation allow you to resolve this todo?

I'm happy to do a bit of testing for you if you don't have easy access to a mac.

[e2]

Does changing the line above help without the need for you to resolve the symlink yourself? (using dir.realpath instead of dir).

TL; DR; I think it's not just weird, it's unexpected, so I'd like to fix this - we can keep this open until I release a fixed version (other platforms are also likely affected).

Expected behavior: if you are testing for /tmp/something in your tests, and you're providing /tmp/something as the watched dir, you should get files relative to /tmp/something, no matter what /tmp is linked to.

But if you're watching /tmp/something and you have symlinks within /tmp/something (e.g. /tmp/something/link_to_somewhere), there's no way to know whether you changed /tmp/something/link_to_somewhere or /tmp/something/link_target.

So from a user's perspective symlinking ideally shouldn't affect the actual paths used or returned. But all backends in Listen return event paths as resolved symlink (AFAIK), so the watched dir is the ONLY symlink which can be preserved.

If it does, I'll probably just need to add a test, fix this for other platforms and release a new version.

As for testing, there are probably edge cases worth testing such as:

1. adding/removing another file in the temp directory
2. adding/removing another file in a new subdirectory of the temp dir
3. handling symlinks within the watched subdir (the watched dir should be unresolved, but there's no reasonable way to preserve symlinks within the watched dir)
4. handling symlinks within the watched subdir, which point to a dir outside the directory

That's because of this line: https://github.com/guard/listen/blob/master/lib/listen/directory.rb#L26

Either way, symlink handling in Listen is a tough subject, so this issue really helps make a step forward - thanks for reporting and testing this!

[e2]

I'm closing this, because it should already be fixed (meaning, even if /tmp is just a symlink, you should get the /tmp path, and not the real directory).

It it doesn't work on OSX, it's probably because this needs implementing: #274 (and when it is implemented, this will be automatically resolved).