guard / listen

The Listen gem listens to file modifications and notifies you about the changes.
https://rubygems.org/gems/listen
MIT License
1.92k stars 246 forks source link

Listen produces loads of "undefined method `change' for class `Celluloid::PoolManager" #268

Closed stephan-nordnes-eriksen closed 9 years ago

stephan-nordnes-eriksen commented 9 years ago

I am using listen for some monitoring. However I am also using an automated error-logging system, and it appears that the listen gem spews out "undefined method change' for classCelluloid::PoolManager" errors.

Example to reproduce problem (in IRB or something):

require "listen"
class Exception
    def initialize(*args)
        puts "ERROR ARGS: #{args}"
    end
end

listener = Listen.to("/some/folder") do |modified, added, removed|
    puts "Event: mod: #{modified}. add: #{added}. rev: #{removed}"
end
listener.start
# Change a file in /some/folder
#Will print:
ERROR ARGS: ["undefined method `change' for class `Celluloid::PoolManager'"]
ERROR ARGS: ["undefined method `change' for class `Celluloid::PoolManager'"]
ERROR ARGS: ["undefined method `change' for class `Celluloid::PoolManager'"]
....

I have not been able to completely trace down where this is coming from, as the stack trace in my systems only shows this:

\/Users/me/project_location/ext/ruby_ship/bin/shipyard/darwin_ruby/lib/ruby/gems/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 

`initialize'", "/Users/me/project_location/ext/ruby_ship/bin/shipyard/darwin_ruby/lib/ruby/gems/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 

`method'", "/Users/me/project_location/ext/ruby_ship/bin/shipyard/darwin_ruby/lib/ruby/gems/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 

`check'", "/Users/me/project_location/ext/ruby_ship/bin/shipyard/darwin_ruby/lib/ruby/gems/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:24:in 

`dispatch'", "/Users/me/project_location/ext/ruby_ship/bin/shipyard/darwin_ruby/lib/ruby/gems/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in 

`dispatch'", "/Users/me/project_location/ext/ruby_ship/bin/shipyard/darwin_ruby/lib/ruby/gems/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in 

`block in invoke'", "/Users/me/project_location/ext/ruby_ship/bin/shipyard/darwin_ruby/lib/ruby/gems/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in 

`block in task'", "/Users/me/project_location/ext/ruby_ship/bin/shipyard/darwin_ruby/lib/ruby/gems/2.1.0/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in 

`block in task'", "/Users/me/project_location/ext/ruby_ship/bin/shipyard/darwin_ruby/lib/ruby/gems/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in 

`block in initialize'", "/Users/me/project_location/ext/ruby_ship/bin/shipyard/darwin_ruby/lib/ruby/gems/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb:15:in 

`block in create'

This is arguably not a bug, since listener still works, but it is an annoyance since my logging-system goes bananas, and it does appear that something is rescuing an error which it shouldn't. I would love to look into it, but I am not sure where to start.

I am running OSx 10.10, ruby 2.1.2p95, and listen 2.7.11.

e2 commented 9 years ago

Could be a bug in listen.

Here's what I'd try:

  1. Make sure you're running your app with bundle exec (I often forget myself)
  2. run with the environment variable: LISTEN_GEM_DEBUGGING=2 (because this may show something crashing in celluloid or listen before the problem you're getting)
  3. At the beginning of your app, put: Celluloid.task_class = Celluloid::TaskThread (which could maybe give a better backtrace)
  4. You could try Celluloid logger = nil to see if that helps (listen may have bugs here)
  5. Try Celluloid master branch in your Gemfile:
gem 'celluloid', github: 'celluloid/celluloid'

If all that fails, I'd put STDERR.puts statements throughout listen (mostly file.rb, change.rb, directory.rb and adapter/base.rb) to see the last thing that happens before the error

Hope that helps!

stephan-nordnes-eriksen commented 9 years ago
  1. bundle exec did not appear to change anything (using bundle exec irb and then running the code above is still causing the same behaviour).
  2. When using LISTEN_GEM_DEBUGGING=2 I see can't see any errors. The error logger finds an exception telling me: No such file or directory @ rb_file_s_lstat - /some/folder/the_file_i_just_changed.file". Nothing else shows up (maybe I did it wrong? LISTEN_GEM_DEBUGGING=2; bundle exec irb; (enter all code when started)
  3. I get a slightly different backtrace. It now gives me:

    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'initialize'",
    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'method'",
    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'check'",
    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:24:in 'dispatch'",
    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in 'dispatch'",
    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in 'block in invoke'",
    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in 'block in task'",
    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in 'block in task'",
    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in 'block in initialize'",
    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_thread.rb:21:in 'block in create'",
    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in 'block in initialize'",
    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in 'block in get_thread'",
    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'call'",
    "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'block in create'"
  4. Same thing. No difference
  5. TBA

1.( nr. 2): I will try some stuff out and see if I can track down and destroy this arachnid.

e2 commented 9 years ago

It's either:

# run with given variable
LISTEN_GEM_DEBUGGING=2 bundle exec irb

(no semicolon)

or:

# set variable until you close your terminal
export LISTEN_GEM_DEBUGGING=2

bundle exec irb
stephan-nordnes-eriksen commented 9 years ago

Now I am getting this output.

    ARGS: ["caused by #<Celluloid::Task::TerminatedError: Celluloid::Task::TerminatedError>: Celluloid::Task::TerminatedError"]
    Message: Celluloid::AbortError
    backtrace: nil
    caller: ["/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/exceptions.rb:20:in 'initialize'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid.rb:316:in 'new'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid.rb:316:in 'abort'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/pool_manager.rb:47:in 'rescue in _send_'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/pool_manager.rb:53:in '_send_'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/pool_manager.rb:140:in 'method_missing'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in 'public_send'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in 'dispatch'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in 'dispatch'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in 'block in invoke'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in 'block in task'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in 'block in task'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in 'block in initialize'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb:15:in 'block in create'"]
    D, [2014-11-11T16:11:05.567599 #71721] DEBUG -- : Celluloid::PoolManager: async call 'change' aborted!
    Celluloid::Task::TerminatedError: Celluloid::Task::TerminatedError
        /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb:34:in 'terminate'
        /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:345:in 'each'
        /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:345:in 'cleanup'
        /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:329:in 'shutdown'
        /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:164:in 'run'
        /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:130:in 'block in start'
        /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in 'block in initialize'
        /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in 'block in get_thread'
        /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'call'
        /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'block in create'
    W, [2014-11-11T16:11:05.568142 #71721]  WARN -- : Terminating task: type=:call, meta={:method_name=>:change}, status=:callwait
        Celluloid::TaskFiber backtrace unavailable. Please try 'Celluloid.task_class = Celluloid::TaskThread' if you need backtraces here.
    ARGS: ["task was terminated"]
    Message: Celluloid::Task::TerminatedError
    backtrace: nil
    caller: ["/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:122:in 'new'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:122:in 'terminate'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb:34:in 'terminate'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:345:in 'each'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:345:in 'cleanup'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:329:in 'shutdown'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:164:in 'run'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:130:in 'block in start'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in 'block in initialize'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in 'block in get_thread'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'call'", "/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'block in create'"]

Not sure if this is the aureka moment required, but maybe it can lead to something. Note the Celluloid::Task::TerminatedError: Celluloid::Task::TerminatedError, which I don't believe showed up before.

stephan-nordnes-eriksen commented 9 years ago

When adding "Celluloid.task_class = Celluloid::TaskThread" i now see some more problems.

I get a bunch of output of this kind:

    D, [2014-11-11T16:24:52.213986 #72739] DEBUG -- : unknown: file:/Users/me/folder/listend/to/subfolder/0_0_1/some_quite_long_folder_with_a.in_the_name/some_error_log_with_this_format_2014_06_02_1729_03_+0200.log ({})

I just tested on a smaller folder and it looks like I get one of these, and a NameError, per event as well as one per file in the folder per file change. It is as tough something is itterating over every file in the folder every time a file is deleted/changed/modified, and whatever it is doing, an error is thrown and caught. The problem does not appear to change with file/folder name.

To me this smells of performance hit as well.

e2 commented 9 years ago

You should get a better backtrace with:

class Exception
    def initialize(*args)
      STDERR.puts "ERROR ARGS: #{args}"
      STDERR.puts "Backtrace: \n #{Thread.current.backtrace * "\n >> \t"}"
    end
end

I must admit that's an interesting technique of monkey-patching Exception.

TerminatedError means something might have called exit or abort or the process was killed by the "KILL" signal using Process.signal.

stephan-nordnes-eriksen commented 9 years ago

Yeah, I often find monkey-patching exception itself to be a nice way to find silly errors which are being handled incorrectly and so forth, and it is really handy for logging exceptions in production, just push stuff to a file, or get fancy. But you should be very carefull as you will get stack-overflows if you make a single mistake in there.

Anyways, I am looking through the code now and i have found the sinner. It looks like somewhere "invoke" is being called on a Celluloid::Cell where the argument is "change", but the Cell's subject does not have the "change" method.

The actual problem is in line 33 of cells.rb. For some reason the subject returns "true" on obj.respond_to?(@method), but when obj.method(@method).arity is called, a NameError is thrown. Very strange. Maybe change isn't a method? Maybe it is an alias?

stephan-nordnes-eriksen commented 9 years ago

And: the object in question is of class: Listen::Change.

e2 commented 9 years ago

To ignore changes in the log file, use an ignore rule with listen, see:https://github.com/guard/listen#options

Or, you may want to put the log files in a directory that listen ignores by default, see: https://github.com/guard/listen/blob/master/lib/listen/silencer.rb#L12-L13

Otherwise, everything something is logged, it will trigger an even in Listen.

stephan-nordnes-eriksen commented 9 years ago

This is actually an artifact of Celluloid. They are overriding some basic methods which is causing things to go wrong. They are overriding the #respond_to? in their pool_manager.rb, but not their #method, which is giving false positives/incorrect results. Working on a patch now.

e2 commented 9 years ago

Try on Celluloid master first (just to make sure).

stephan-nordnes-eriksen commented 9 years ago

Good point. Got a fix ready, but they might have fixed it already.

stephan-nordnes-eriksen commented 9 years ago

Made a pull-request now. The problem appeared to not be fixed in current master. https://github.com/celluloid/celluloid/pull/472

e2 commented 9 years ago

I'm honestly confused about this - I just can't seem to understand what's the exact invocation from Listen that doesn't work (and which invocation it is).

Calling :change on a Change actor from the pool (:change_pool in registry)

If there's a problem with arity, there's this line: https://github.com/guard/listen/blob/master/lib/listen/directory.rb#L69 which calls the Change actor (returned by pool using the :change_pool from registry) ...

... and it calls it with 3 parameters instead of 4 (4th one being optional).

Calling sync/async to get a Change actor

Here's how listen gets the async Change actor (async, which is why you won't get a backtrace):

https://github.com/guard/listen/blob/master/lib/listen/listener.rb#L149

Basically it does this:

# registry is Celluloid::Registry
obj = registry[:change_pool].async

# parameters are an example
obj.change(:file, '/home/me', 'project/foo.rb', {})

so it's strange to have :change be called on the pool manager - but I think it makes sense, since it's async.

Overall, it's strange you're getting this because your fix seems generic, while the paths in Listen are also generic, so if your fix works, I don't understand why Listen works as it is (or vice versa).

e2 commented 9 years ago

I'm asking because ideally there should be a spec reproducing the problem in Cellluloid - if you have it worked out (my brain hurts trying to think of how to reproduce this).

stephan-nordnes-eriksen commented 9 years ago

The script I used to debug was this:

    # usage: ruby path_to_this_file.rb
    # Be sure to install pry and listen first. "gem install pry", "gem install listen"
    require "listen"
    require "pry"
    class Exception
        def initialize(*args)
            puts "ARGS: #{args}"
            puts "Message: #{self.message}"
            puts "backtrace: #{self.backtrace.inspect}"
            puts "caller: #{caller.inspect}"
        end
    end
    listener = Listen.to('/Users/me/Desktop/test_folder') do |modified, added, removed| 
        puts "Event: mod: #{modified}. add: #{added}. rev: #{removed}"
    end
    listener.start

    while true
        sleep 1
    end

Then I simply added binding.pry inside the rescue block inside calls.rb, and browsed my way from there. NOTE: You might want to remove the Exception monkey-patch when using pry as it sometimes messes with pry.

I agree that there should be a spec for this, but I am not familiar enough with the whole system to figure out how to implement that. I essentially worked backwards. I don't know how to produce the exception the other way.

e2 commented 9 years ago

Ok, first of all, always use the backtrace * "\n\t " code instead (backtrace/caller).inspect, or it makes the backtrace completely unreadable (you'd have to scroll sideways for ages to see anything).

I can't reproduce this (I'm using Linux), and the error is hidden by Celluloid, because when Celluloid calls abort, it catches the error, but doesn't print the cause (you just get "Celluloid::AbortError" which is useless).

This is a big error in Celluloid in that it doesn't preserve the actual exception message (and this is needs a separate pull request).

[I've been bitten by this issue in Celluloid before, but from a different place, so I want to fix this too]

Since I can't reproduce this, please do the following so we can fix this properly:

  1. in pool_manager.rb, in line 47 (after the rescue and before the abort - https://github.com/celluloid/celluloid/blob/v0.16.0/lib/celluloid/pool_manager.rb#L47), put:
STDERR.puts "Exception: #{$!.inspect}: \nBacktrace:#{ex.backtrace * "\n\r (bt) "}"

so the code looks like this:

def _send_(method, *args, &block)
  worker = __provision_worker__

  begin
    worker._send_ method, *args, &block
  rescue DeadActorError # if we get a dead actor out of the pool
    wait :respawn_complete
    worker = __provision_worker__
    retry
  rescue Exception => ex
    STDERR.puts "Exception: #{$!.inspect}: \nBacktrace:#{ex.backtrace * "\n\r (bt) "}"
    abort ex
  ensure
    if worker.alive?
      @idle << worker
      @busy.delete worker
    end
  end
end

(This will show what caused the exception - I'm guessing Listen is failing somewhere)

  1. Use this slightly modified script to reproduce your error (if possible):
require "listen"
require "pry"
Celluloid.task_class = Celluloid::TaskThread

class Exception
  def initialize(*args)
    STDERR.puts "----------------------------"
    STDERR.puts "ARGS: #{args.inspect}"
    STDERR.puts "Message: #{self.message}"
    STDERR.puts "caller: #{caller * "\n\t >"}"
  end
end

listener = Listen.to('/Users/me/Desktop/test_folder') do |modified, added, removed|
  puts "Event: mod: #{modified}. add: #{added}. rev: #{removed}"
end
listener.start

while true
  sleep 1
end

And I hope we can nail not only this issue, but help with any other issues people may experience.

e2 commented 9 years ago

I'm guessing that since you're on Mac, Listen is going through a code path I haven't tested properly.

And so, listen is failing, celluloid is aborting silently, then catching the error, and showing a confusing exception and irrelevant call stack - and your Exception patching is just capturing the useless AbortError exception.

This means 3 things: 1) I have an error in Listen that occurs on MacOS that needs to be fixed 2) That error triggers a possible bug in Celluloid's pool manager (and by knowing how it's triggered, I can help reproduce this with a Celluloid spec, so the patch can be backported to multiple Celluloid versions and never produced again) 3) The fact that you get a cryptic error means there's a useful and needed change in Celluloid to actually print the error that happened, instead of silencing it.

stephan-nordnes-eriksen commented 9 years ago

Some backtracke:


ARGS: ["undefined method `change' for class `Celluloid::PoolManager'"]
Message: NameError
caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in `initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in `method'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in `check'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:24:in `dispatch'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in `dispatch'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in `block in invoke'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in `block in task'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in `block in task'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in `block in initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_thread.rb:21:in `block in create'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in `block in initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in `block in get_thread'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in `call'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in `block in create'
----------------------------
ARGS: ["undefined method `change' for class `Celluloid::PoolManager'"]
Message: NameError
caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in `initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in `method'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in `check'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:24:in `dispatch'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in `dispatch'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in `block in invoke'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in `block in task'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in `block in task'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in `block in initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_thread.rb:21:in `block in create'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in `block in initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in `block in get_thread'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in `call'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in `block in create'
----------------------------
ARGS: ["undefined method `change' for class `Celluloid::PoolManager'"]
Message: NameError
caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in `initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in `method'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in `check'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:24:in `dispatch'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in `dispatch'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in `block in invoke'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in `block in task'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in `block in task'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in `block in initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_thread.rb:21:in `block in create'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in `block in initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in `block in get_thread'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in `call'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in `block in create'
----------------------------
ARGS: ["undefined method `change' for class `Celluloid::PoolManager'"]
Message: NameError
caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in `initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in `method'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in `check'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:24:in `dispatch'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in `dispatch'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in `block in invoke'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in `block in task'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in `block in task'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in `block in initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_thread.rb:21:in `block in create'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in `block in initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in `block in get_thread'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in `call'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in `block in create'
----------------------------
ARGS: ["No such file or directory @ rb_file_s_lstat - /Users/me/Desktop/test_folder/file_I_changed.type"]
Message: Errno::ENOENT
caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/listen-2.7.11/lib/listen/file.rb:5:in `initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/listen-2.7.11/lib/listen/file.rb:5:in `lstat'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/listen-2.7.11/lib/listen/file.rb:5:in `lstat'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/listen-2.7.11/lib/listen/file.rb:5:in `change'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/listen-2.7.11/lib/listen/change.rb:40:in `change'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in `public_send'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in `dispatch'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:63:in `dispatch'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in `block in invoke'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in `block in task'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in `block in task'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in `block in initialize'
     >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb:15:in `block in create'
Event: mod: []. add: ["/Users/me/Desktop/test_folder/cssparalax.html"]. rev: ["/Users/me/Desktop/test_folder/file_I_changed.type"]

Not sure if it is any more usefull. I will see if I can squeeze out some more juice.

stephan-nordnes-eriksen commented 9 years ago

This is all the output generated when I do the following:

  1. run LISTEN_GEM_DEBUGGING=2 ruby ~/Desktop/listentester.rb.
  2. wait for it to settle.
  3. Rename file file_renamed_FROM_this.file to file_renamed_to_this.file.
  4. Using ctrl+c to stop the program.

    SomeLocation me$ LISTEN_GEM_DEBUGGING=2 ruby ~/Desktop/listentester.rb
    WARN: Unresolved specs during Gem::Specification.reset:
         ffi (>= 0.5.0)
    WARN: Clearing out unresolved specs.
    Please report a bug if this causes problems.
    I, [2014-11-11T21:45:36.966173 #50914]  INFO -- : Celluloid loglevel set to: 0
    ----------------------------
    ARGS: ["No such file or directory @ rb_sysopen - /sys/devices/system/cpu/present"]
    Message: Errno::ENOENT
    caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cpu_counter.rb:21:in 'initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cpu_counter.rb:21:in 'read'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cpu_counter.rb:21:in 'from_sysdev'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cpu_counter.rb:11:in 'count_cores'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cpu_counter.rb:5:in 'cores'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid.rb:82:in 'cores'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/pool_manager.rb:13:in 'initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in 'public_send'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in 'dispatch'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:63:in 'dispatch'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in 'block in invoke'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_thread.rb:21:in 'block in create'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in 'block in get_thread'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'call'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'block in create'
    D, [2014-11-11T21:45:36.982302 #50914] DEBUG -- : Adapter: considering TCP ...
    D, [2014-11-11T21:45:36.982464 #50914] DEBUG -- : Adapter: considering polling ...
    D, [2014-11-11T21:45:36.982507 #50914] DEBUG -- : Adapter: considering optimized backend...
    I, [2014-11-11T21:45:36.986582 #50914]  INFO -- : Record.build(): 0.0011990070343017578 seconds
    D, [2014-11-11T21:45:45.650063 #50914] DEBUG -- : fsevent: /Users/me/Desktop/test_folder
    D, [2014-11-11T21:45:45.652256 #50914] DEBUG -- : raw queue: [:dir, #<Pathname:/Users/me/Desktop/test_folder>, ".", {:recursive=>true}]
    ----------------------------
    ARGS: ["undefined method 'change' for class 'Celluloid::PoolManager'"]
    Message: NameError
    caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'method'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'check'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:24:in 'dispatch'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in 'dispatch'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in 'block in invoke'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_thread.rb:21:in 'block in create'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in 'block in get_thread'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'call'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'block in create'
    D, [2014-11-11T21:45:45.657641 #50914] DEBUG -- : unknown: dir:/Users/me/Desktop/test_folder ({:recursive=>true})
    D, [2014-11-11T21:45:45.658718 #50914] DEBUG -- : Scanning: .: {:recursive=>true} [{"file_renamed_FROM_this.file"=>{:mtime=>1414665060.0, :mode=>33184}, "file_not_touched.file"=>{:mtime=>1414665060.0, :mode=>33184}}] -> (#<Set: {#<Pathname:/Users/me/Desktop/test_folder/file_not_touched.file>, #<Pathname:/Users/me/Desktop/test_folder/file_renamed_to_this.file>}>)
    ----------------------------
    ARGS: ["undefined method 'change' for class 'Celluloid::PoolManager'"]
    Message: NameError
    caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'method'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'check'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:24:in 'dispatch'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in 'dispatch'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in 'block in invoke'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_thread.rb:21:in 'block in create'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in 'block in get_thread'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'call'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'block in create'
    D, [2014-11-11T21:45:45.678813 #50914] DEBUG -- : unknown: file:/Users/me/Desktop/test_folder/file_not_touched.file ({})
    ----------------------------
    ARGS: ["undefined method 'change' for class 'Celluloid::PoolManager'"]
    Message: NameError
    caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'method'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'check'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:24:in 'dispatch'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in 'dispatch'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in 'block in invoke'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_thread.rb:21:in 'block in create'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in 'block in get_thread'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'call'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'block in create'
    D, [2014-11-11T21:45:45.690063 #50914] DEBUG -- : unknown: file:/Users/me/Desktop/test_folder/file_renamed_to_this.file ({})
    ----------------------------
    ARGS: ["undefined method 'change' for class 'Celluloid::PoolManager'"]
    Message: NameError
    caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'method'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'check'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:24:in 'dispatch'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in 'dispatch'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in 'block in invoke'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_thread.rb:21:in 'block in create'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in 'block in get_thread'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'call'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'block in create'
    D, [2014-11-11T21:45:45.729776 #50914] DEBUG -- : unknown: file:/Users/me/Desktop/test_folder/file_renamed_FROM_this.file ({})
    ----------------------------
    ARGS: ["No such file or directory @ rb_file_s_lstat - /Users/me/Desktop/test_folder/file_renamed_FROM_this.file"]
    Message: Errno::ENOENT
    caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/listen-2.7.11/lib/listen/file.rb:5:in 'initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/listen-2.7.11/lib/listen/file.rb:5:in 'lstat'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/listen-2.7.11/lib/listen/file.rb:5:in 'lstat'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/listen-2.7.11/lib/listen/file.rb:5:in 'change'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/listen-2.7.11/lib/listen/change.rb:40:in 'change'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in 'public_send'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in 'dispatch'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/calls.rb:63:in 'dispatch'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in 'block in invoke'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb:15:in 'block in create'
    I, [2014-11-11T21:45:45.852610 #50914]  INFO -- : listen: raw changes: [[:added, "/Users/me/Desktop/test_folder/file_renamed_to_this.file"], [:removed, "/Users/me/Desktop/test_folder/file_renamed_FROM_this.file"]]
    I, [2014-11-11T21:45:45.852752 #50914]  INFO -- : listen: final changes: {:modified=>[], :added=>["/Users/me/Desktop/test_folder/file_renamed_to_this.file"], :removed=>["/Users/me/Desktop/test_folder/file_renamed_FROM_this.file"]}
    Event: mod: []. add: ["/Users/me/Desktop/test_folder/file_renamed_to_this.file"]. rev: ["/Users/me/Desktop/test_folder/file_renamed_FROM_this.file"]
    D, [2014-11-11T21:45:45.852969 #50914] DEBUG -- : Callback took 9.703636169433594e-05 seconds
    ^C----------------------------
    ARGS: [""]
    Message: Interrupt
    caller: /Users/me/Desktop/listentester.rb:39:in 'initialize'
        >/Users/me/Desktop/listentester.rb:39:in 'initialize'
        >/Users/me/Desktop/listentester.rb:39:in 'new'
        >/Users/me/Desktop/listentester.rb:39:in 'sleep'
        >/Users/me/Desktop/listentester.rb:39:in '<main>'
    ----------------------------
    ARGS: ["execution expired"]
    Message: Timeout::ExitException
    caller: /Users/me/.rvm/rubies/ruby-2.1.2/lib/ruby/2.1.0/timeout.rb:32:in 'new'
        >/Users/me/.rvm/rubies/ruby-2.1.2/lib/ruby/2.1.0/timeout.rb:32:in 'catch'
        >/Users/me/.rvm/rubies/ruby-2.1.2/lib/ruby/2.1.0/timeout.rb:106:in 'timeout'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:66:in 'shutdown'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid.rb:156:in 'shutdown'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid.rb:145:in 'block in register_shutdown'
    D, [2014-11-11T21:45:56.339017 #50914] DEBUG -- : Terminating 8 actors...
    ----------------------------
    ARGS: ["actor already terminated"]
    Message: Celluloid::DeadActorError
    caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/actor_proxy.rb:34:in 'exception'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/actor_proxy.rb:34:in 'raise'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/actor_proxy.rb:34:in 'terminate!'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/actor_proxy.rb:27:in 'terminate'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/cell_proxy.rb:60:in 'terminate'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/supervision_group.rb:154:in 'terminate'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/supervision_group.rb:166:in 'reverse_each'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/supervision_group.rb:166:in 'finalize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:82:in 'block in shutdown'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_thread.rb:21:in 'block in create'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in 'block in get_thread'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'call'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'block in create'
    ----------------------------
    ARGS: ["actor already terminated"]
    Message: Celluloid::DeadActorError
    caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/actor_proxy.rb:34:in 'exception'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/actor_proxy.rb:34:in 'raise'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/actor_proxy.rb:34:in 'terminate!'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/actor_proxy.rb:27:in 'terminate'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/cell_proxy.rb:60:in 'terminate'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/supervision_group.rb:154:in 'terminate'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/supervision_group.rb:166:in 'reverse_each'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/supervision_group.rb:166:in 'finalize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:82:in 'block in shutdown'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_thread.rb:21:in 'block in create'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in 'block in get_thread'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'call'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'block in create'
    ----------------------------
    ARGS: ["actor already terminated"]
    Message: Celluloid::DeadActorError
    caller: /Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/actor_proxy.rb:34:in 'exception'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/actor_proxy.rb:34:in 'raise'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/actor_proxy.rb:34:in 'terminate!'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/actor_proxy.rb:27:in 'terminate'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/proxies/cell_proxy.rb:60:in 'terminate'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/supervision_group.rb:154:in 'terminate'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/supervision_group.rb:166:in 'reverse_each'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/supervision_group.rb:166:in 'finalize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:82:in 'block in shutdown'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in 'block in task'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/tasks/task_thread.rb:21:in 'block in create'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/thread_handle.rb:13:in 'block in initialize'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/actor_system.rb:32:in 'block in get_thread'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'call'
        >/Users/me/.rvm/gems/ruby-2.1.2/gems/celluloid-0.16.0/lib/celluloid/internal_pool.rb:130:in 'block in create'
    /Users/me/Desktop/listentester.rb:39:in 'sleep': Interrupt (Interrupt)
       from /Users/me/Desktop/listentester.rb:39:in '<main>'
e2 commented 9 years ago

This is the only thing we need to focus on:

ARGS: ["undefined method 'change' for class 'Celluloid::PoolManager'"]
Message: NameError
caller: celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'initialize'
  celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'method'
  celluloid-0.16.0/lib/celluloid/calls.rb:33:in 'check'
  celluloid-0.16.0/lib/celluloid/calls.rb:24:in 'dispatch'
  celluloid-0.16.0/lib/celluloid/calls.rb:122:in 'dispatch'
  celluloid-0.16.0/lib/celluloid/cell.rb:60:in 'block in invoke'
  celluloid-0.16.0/lib/celluloid/cell.rb:71:in 'block in task'
  celluloid-0.16.0/lib/celluloid/actor.rb:357:in 'block in task'

(the rest are just exceptions occuring normally)

Could you run it with bundler and using celluloid from master? (just so we can debug this on master):

   gem 'celluloid', github: 'celluloid/celluloid'

If you can, put the output in a gist - they're usually much easier on the eyes.

stephan-nordnes-eriksen commented 9 years ago

Well, my hotfix is already in celluloid master now, so I am not sure if it will help currently.

Edit: Also, not entierly sure how I should use the gem 'celluloid', github: 'celluloid/celluloid' syntax. Just put it in a Gemfile next to the script?

e2 commented 9 years ago

Ok, I just tracked this on 0.16.0 source and ...

... this exception is normal, because async methods aren't called - and the exception you're getting is just a result of Celluloid pre-checking if you're passing the right amount of parameters to a method.

So, your hotfix basically "improves" Celulloid's validation of async method calls - and so, this is not a bug in Listen (as I thought).

e2 commented 9 years ago

As for the "No such file or directory @ rb_file_s_lstat" exception - you're also getting a handled exception. I could change the code to call File.exist? or Dir.exist? before stat(), but this unnecessarily uses 2 system calls to check a file's permissions (and the second call could fail anyway).

e2 commented 9 years ago

Anyway, I think we both learned a lot, so I'm closing this.

stephan-nordnes-eriksen commented 9 years ago

Yeah, as I figured, but this stuff is a bit complex so I am not 100% sure what to blame to be honest. What I can say for sure is that there was a part in celulloid which needed improvement, but if that is singelhandedly all that was wrong, I do not know.

Anywho, the fix reduces the try-catching by a boatload, and my error-system is happy again. I was getting one of these errors per file in almost my entire system every single time a single file changed. I do believe that this will increase performance by a bit actually. I do not know the exact overhead of a try-catch in Ruby, but I am sure it is more expensive than not getting them. Who knows what consequences this error also had further down the line?

One thing that does concern me though is that every single file on my system needed to be check when a single file changed. Might there be some "foreach file we are watching do some work" going on somewhere?

e2 commented 9 years ago

I am not 100% sure what to blame

Exceptions are actually a cool way to program - so monkey patching Exception is kind of like expecting every method in a class to return something other than false. But all because some method returns false, it doesn't mean there is an error. So if you want to have no exceptions, it's like expecting programmers to never return nil/false in the methods they write - unless there's an unexpected failure.

there was a part in celulloid which needed improvement

Yeah, there are many parts like that. I think your patch is cool for what it does, because it (as I understand it) async on a pool manager returns the pool manager - and it's nice that now pool manager can "know" if a method is available - because it means you can check if the method has the right number of parameters on a pool object (which doesn't exist yet).

So I'm impressed ;)

I was getting one of these errors per file in almost my entire system every single time a single file changed.

Ignoring files is the solution. Currently, watching multiple directories in Mac OS is broken (discovered today, fixed on master, but I got sidetracked by this to release it) - but otherwise, you should ONLY watch the directories you ABSOLUTELY need, even if you need to pass 20 dirs to listen(). Also, ignoring directories should reduce the calls to Celluloid.

As for performance, Celluloid is a MUCH bigger overhead than exceptions (which are much, much faster than are worth thinking about). Another big overhead in listen is pathnames (because of encoding), thread locking (mostly for Celluloid), thread switching, directory listing, etc. - All no where NEAR the cost of throwing and catching exceptions.

As for consequences for the error - there are none, because it was in a "check" method, which had the purpose of possibly checking if the number of arguments to the async method would match.

One thing that does concern me though is that every single file on my system needed to be check.

That's because you're on MacOS and not Linux, and watching files on MacOS is very limited. Only directories are watched in rb-fsevent, so when files change, listen has to check directory contents manually to see which files actually changed. Besides, on a Mac your filesystem has 1-second timestamp precision, so Listen has to do a lot of work and magic to find out if files REALLY changed (if a file changes more often than a second, Listen has to do a very expensive MD5 sum to know if a file really changed.

Overall, watching files on Mac is a bit slow currently and not optimal, but I work on Linux only, so I can't fix this no matter how much I'd want to.

For more info about performance: https://github.com/guard/listen#performance

Summary: for ultimate performance, use Linux. Otherwise, select directories conservatively and set ignore rules as aggressively as possible.

stephan-nordnes-eriksen commented 9 years ago

Many good points. Glad that you found out about the multi-directory bug :)

Also, ignoring directories should reduce the calls to Celluloid.

I feel the documentation on doing this is a bit bad. I have tried to do this, but it appears that folders are relative, and there is no way, that I can find, to explicitly ignore a folder if you have the absolute path. I tried a regex which should trigger on full path, but it does not work.

Overall, watching files on Mac is a bit slow currently and not optimal, but I work on Linux only, so I can't fix this no matter how much I'd want to.

I might have a look at this later as I am developing a cross platform app, so I need listen for both Linux, Mac, and Windows. I would love to have max performance on all platforms, but I bet a lot of work must be done to get that on all these platforms.

Mac your filesystem has 1-second timestamp precision, so Listen has to do a lot of work and magic to find out if files REALLY changed

I wonder: If a file changes that often, is it really necessary to fire off an event each time? Isn't it enough to get one a second? Essentially truncating the events to the last one after 1 second. I understand that if you are making a "Count the number of times a file changes"-application this approach would be too inaccurate, but often you want to recompile or something, and if the file changes two times in a row, it is really only necessary to compile the file the last time (since the in-between is outdated). Also, by the time the in-between event is fired, the file will have changed, and there is nothing you can do to get the file at the state indicated by the event.

I don't know if that makes sense, but to me it sounds like it could be a setting where you can say :precision or :performance, and have :precision be the default value, aka. leave things like it is right now.


Sidenote:

..., but I work on Linux only, so I can't fix this no matter how much I'd want to.

You should try out a mac. It is better than what you would expect. At least it was for me.

e2 commented 9 years ago

it appears that folders are relative

It could be a bug - give a specific example. Paths are matched relative to the watched directory - and this is actually a great feature, because you almost never want to work with full paths. E.g. you don't want to ignore /home/me/my/projects/log/foo.log, you want to ignore ./log/foo.log, so other users can still have the same config. Always think in terms of "relative to current working directory" or "relative to watched directory". I won't even mention symlinks, which as supposed to hide full paths ...

I would love to have max performance on all platforms

It's just rb-fsevent: https://github.com/thibaudgg/rb-fsevent that could use improving - it's a great gem, it just relies on a very old file monitoring implementation from earlier MacOSs. I'm sure Apple offers a newer, better approach. Otherwise, Linux has rb-inotify, and Windows has WDM - so there's nothing really work improving there. Or, you could just maybe help with this: https://github.com/guard/listen/issues/159

is it really necessary to fire off an event each time

https://github.com/guard/listen/blob/master/lib/listen/file.rb#L28-L53

Basically, all listen knows (based on what rb-fsevent reports), is that "something" changed inside a given directory (that's how file monitoring was implemented on MacOS - just telling what directories contained changes). So, if something changed in a directory, listen has to compare with the previous snapshot. And you don't know what exact time the change happened, either (there's potentially a few second delay). This means listen can't get an accurate snapshot - meaning listen only know that "potentially" something changed between when the last snapshot was taken and now. It's not that changes aren't detected - it's that too many things have "potentially" changed, and we need to find out what didn't change (thus, the md5 checking sometimes).

I don't know if that makes sense, but to me it sounds like it could be a setting

Nope, it's just that FSEvent on Mac doesn't say what changed, when and how (attributes or content) and the HFS filesystem on Mac doesn't help reduce suspects down effectively - so basically Listen implements something Apple doesn't (didn't). It's like "half-polling", because like polling we don't know what changed, except FSEvent at least gives us "clues" (directories changed).

You should try out a mac. It is better than what you would expect.

I did and I couldn't stand it, because Linux is a better implementation of UNIX and there's a lot less fooling around with dev tools and setup (I don't need stuff like brew, boxen, I have the terminal and apps I like, command-line tools are more "complete", etc.). Also, I just can't seem to let go of Fluxbox and I couldn't justify the time to find out how to do things I've already figured out. I'm just the wrong guy for a Mac.

stephan-nordnes-eriksen commented 9 years ago

About "what actually changed" and the MD5 stuff. Is it not enough to check the mtime of the file, and keep a list of those? This is what I do for a project which needs to know if a file changed since the last time the program ran. Mtime is super-fast to check and as I understand, will give correct answer to the question "did this change since last time".

By the way, FSEvent allow you to get the file which changed. It is a setting you must set to get the name of the files which changed. Don't remember right now, but it is something like :file_events or something, but it won't give you what changed, eg. Deleted, moved, or create, only "something happened to this path".

I'm just the wrong guy for a Mac.

Hehe, yeah. Maybe. I really like the hardware though. Solid stuff, good keyboard. But, enough about macs.

I will let you know if I can get FSEvents to actually give me events. I don't know when I will get the time to try though.

e2 commented 9 years ago

Is it not enough to check the mtime of the file, and keep a list of those?

This is exactly what Listen's Record class is for. This feature is extensively covered by tests - so you can see all the edge cases there.

Record building is fast - but that's slightly because filename encoding isn't checked (which causes crashes - see open issues).

Mtime is super-fast to check and as I understand

Yes, from what I believe, it's so fast, that it's faster to use it for detecting changes than processing the FSEvent file events (which is why Listen continues to use the "directories-only" feature of rb-fsevent, even though files have been supported on MaxOS for a long time now).

By the way, FSEvent allow you to get the file which changed.

See, see the previous paragraph. It just isn't practical on larger projects. vagrant-gatling-rsync - you can ask them why.

I don't know when I will get the time to try though.

I definately won't have time to work on Listen at all - except for bugfixing or work of that nature.