delayed_job runでジョブが実行されない?
delayed_job runでdelayed_jobを起動すると、いつまでたってもジョブが実行されない。delayed_job startならば問題ない。
Railsのバージョンは5.2.0、delayed_jobは4.1.5、delayed_job_active_recordは4.1.3、環境はmacOSだ。
$ DISABLE_SPRING=1 bundle exec bin/delayed_job run
^CTraceback (most recent call last):
30: from /Users/akira/.rbenv/versions/2.5.1/bin/bundle:23:in `<main>'
29: from /Users/akira/.rbenv/versions/2.5.1/bin/bundle:23:in `load'
28: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-1.16.4/exe/bundle:22:in `<top (required)>'
27: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-1.16.4/lib/bundler/friendly_errors.rb:124:in `with_friendly_errors'
26: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-1.16.4/exe/bundle:30:in `block in <top (required)>'
25: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-1.16.4/lib/bundler/cli.rb:18:in `start'
24: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-1.16.4/lib/bundler/vendor/thor/lib/thor/base.rb:466:in `start'
23: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-1.16.4/lib/bundler/cli.rb:27:in `dispatch'
22: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-1.16.4/lib/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'
21: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-1.16.4/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
20: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-1.16.4/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
19: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-1.16.4/lib/bundler/cli.rb:424:in `exec'
18: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-1.16.4/lib/bundler/cli/exec.rb:28:in `run'
17: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-1.16.4/lib/bundler/cli/exec.rb:74:in `kernel_load'
16: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/bundler-1.16.4/lib/bundler/cli/exec.rb:74:in `load'
15: from bin/delayed_job:7:in `<top (required)>'
14: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/delayed_job-4.1.5/lib/delayed/command.rb:102:in `daemonize'
13: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/delayed_job-4.1.5/lib/delayed/command.rb:102:in `times'
12: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/delayed_job-4.1.5/lib/delayed/command.rb:104:in `block in daemonize'
11: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/delayed_job-4.1.5/lib/delayed/command.rb:123:in `run_process'
10: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons.rb:192:in `run_proc'
9: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/cmdline.rb:88:in `catch_exceptions'
8: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons.rb:193:in `block in run_proc'
7: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/controller.rb:59:in `run'
6: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/application.rb:295:in `start'
5: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/application.rb:272:in `start_proc'
4: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:30:in `simulate'
3: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:124:in `close_io'
2: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:124:in `each_object'
1: from /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126:in `block in close_io'
/Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126:in `close': Interrupt
動いてないっぽいことを確認したところでCtrl-Cしたらこんな感じに。では、追いかけてみよう。
$ DISABLE_SPRING=1 bundle exec byebug bin/delayed_job run
[1, 7] in /Users/akira/src/app_foo/bin/delayed_job
1: #!/usr/bin/env ruby
2:
=> 3: require File.expand_path(File.join(File.dirname(__FILE__), '..', 'config', 'environment'))
4: require 'delayed/command'
5: Delayed::Command.new(ARGV).daemonize
(byebug) b /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126
Created breakpoint 1 at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126
(byebug) c
Stopped by breakpoint 1 at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126
[121, 130] in /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb
121: def close_io
122: # Make sure all input/output streams are closed
123: # Part I: close all IO objects (except for STDIN/STDOUT/STDERR)
124: ObjectSpace.each_object(IO) do |io|
125: unless [STDIN, STDOUT, STDERR].include?(io)
=> 126: io.close rescue nil
127: end
128: end
129:
130: # Make sure all input/output streams are closed
(byebug) display io
1: io = #<File:/Users/akira/src/app_foo/log/development.log>
(byebug) display io.object_id
2: io.object_id = 70280810523920
(byebug) c
Stopped by breakpoint 1 at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126
1: io = #<IO:fd 10>
2: io.object_id = 70280811905400
[121, 130] in /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb
121: def close_io
122: # Make sure all input/output streams are closed
123: # Part I: close all IO objects (except for STDIN/STDOUT/STDERR)
124: ObjectSpace.each_object(IO) do |io|
125: unless [STDIN, STDOUT, STDERR].include?(io)
=> 126: io.close rescue nil
127: end
128: end
129:
130: # Make sure all input/output streams are closed
(byebug) c
^CReturn value is: nil
1: io = #<IO:(closed)>
2: io.object_id = 70280811905400
ここでIO#closeしようとしてささるのを確認できる。さて、このIOはなんだ? というわけで追跡してみる。そのためにpidと、ささるfd番号が必要。
$ DISABLE_SPRING=1 bundle exec byebug bin/delayed_job run
[1, 7] in /Users/akira/src/app_foo/bin/delayed_job
1: #!/usr/bin/env ruby
2:
=> 3: require File.expand_path(File.join(File.dirname(__FILE__), '..', 'config', 'environment'))
4: require 'delayed/command'
5: Delayed::Command.new(ARGV).daemonize
(byebug) b /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126
Created breakpoint 1 at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126
(byebug) c
Stopped by breakpoint 1 at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126
[121, 130] in /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb
121: def close_io
122: # Make sure all input/output streams are closed
123: # Part I: close all IO objects (except for STDIN/STDOUT/STDERR)
124: ObjectSpace.each_object(IO) do |io|
125: unless [STDIN, STDOUT, STDERR].include?(io)
=> 126: io.close rescue nil
127: end
128: end
129:
130: # Make sure all input/output streams are closed
(byebug) $$
35334
(byebug) display io
1: io = #<File:/Users/akira/src/app_foo/log/delayed_job.log>
(byebug) c
Stopped by breakpoint 1 at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126
1: io = #<IO:fd 10>
[121, 130] in /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb
121: def close_io
122: # Make sure all input/output streams are closed
123: # Part I: close all IO objects (except for STDIN/STDOUT/STDERR)
124: ObjectSpace.each_object(IO) do |io|
125: unless [STDIN, STDOUT, STDERR].include?(io)
=> 126: io.close rescue nil
127: end
128: end
129:
130: # Make sure all input/output streams are closed
(byebug)
ここでささる。PIDは35334、FD番号がまた10。なので
$ lsof -p 35334 -d 10 -a
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
ruby 35334 akira 10 PIPE 0x657d46e117f601fd 16384 ->0x657d46e117f5e03d
PIPEでアドレスが0x657d46e117f5e03dらしいので、この辺をキーに探してみる。PIPEだからおそらく子プロセスだろうとまずは当たりを付けて。
$ lsof -p $(pgrep -P35334 | tr '\n' ,) | grep 0x657d46e117f5e03d
fsevent_w 35359 akira 1 PIPE 0x657d46e117f5e03d 16384 ->0x657d46e117f601fd
35359がにぎっているっぽい。
$ ps p 35359
PID TT STAT TIME COMMAND
35359 s008 S+ 0:00.09 /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/bin/fsevent_watch --format=otnetstring --latency 0.1 ...
いかにもそれらしい。というかまあ、最初からうたがってた。
さて、ではこれを誰が立ち上げているのか?
最初からDISABLE_SPRING=1としている通り、この状況では疑わしそうに思えなくもないspringを除いた上でのことなのでspringではないはず。となるとRails自体か?
ともあれfsevent_watchが起動される場所を探そう。
$ EDITOR='rg -w -g lib/** fsevent_watch' bundle exec gem open rb-fsevent
/Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb
14: "#{File.join(FSEvent.root_path, 'bin', 'fsevent_watch')}"
rgは高速grep実装の一つで、特に指定しなければ再帰的にファイルを探してきてマッチする行を出力する。-wはgrepと同じでワードマッチの指定、-gで探索対象をlib/以下に限定。
gem openはgemのソースディレクトリを渡して$EDITORを実行するので、これにrgを指定してやることでソースディレクトリからファイルを探索しようとしたもの。(gem openはsystem(*ENV['EDITOR'].split(/\s+/), ...)のようなことをしているのでメタ文字の使い方によってはうまく動かない。他によい手があるかもしれないけど知らないので。)
ともあれ場所がわかったので再びbyebugで、と思ったのだが……
$ DISABLE_SPRING=1 bundle exec byebug bin/delayed_job run
[1, 7] in /Users/akira/src/app_foo/bin/delayed_job
1: #!/usr/bin/env ruby
2:
=> 3: require File.expand_path(File.join(File.dirname(__FILE__), '..', 'config', 'environment'))
4: require 'delayed/command'
5: Delayed::Command.new(ARGV).daemonize
(byebug) b /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:14
*** Line 14 is not a valid breakpoint in file /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb.
Valid break points are:
9: "#{File.expand_path(File.join(File.dirname(__FILE__), '..', '..'))}"
10: end
11: END
[B] 12: class_eval <<-END
13: def watcher_path
14: "#{File.join(FSEvent.root_path, 'bin', 'fsevent_watch')}"
15: end
16: END
[B] 17: end
18:
(byebug) q
Really quit? (y/n) y
……なんとダメらしい。なるほど。では14行目を含むメソッドのほうで引っかけてみよう。
$ EDITOR='rg -w -g lib/** watcher_path' bundle exec gem open rb-fsevent
/Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb
13: def watcher_path
108: IO.popen("'#{self.class.watcher_path}' #{options_string} #{shellescaped_paths}")
140: IO.popen([self.class.watcher_path] + @options + @paths)
108行目、140行目。ではそこで。
$ DISABLE_SPRING=1 bundle exec byebug bin/delayed_job run
[1, 7] in /Users/akira/src/app_foo/bin/delayed_job
1: #!/usr/bin/env ruby
2:
=> 3: require File.expand_path(File.join(File.dirname(__FILE__), '..', 'config', 'environment'))
4: require 'delayed/command'
5: Delayed::Command.new(ARGV).daemonize
(byebug) b /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:108
Created breakpoint 1 at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:108
(byebug) b /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:140
Created breakpoint 2 at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:140
(byebug) c
Stopped by breakpoint 2 at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:140
[135, 144] in /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb
135:
136: return str
137: end
138: else
139: def open_pipe
=> 140: IO.popen([self.class.watcher_path] + @options + @paths)
141: end
142: end
143:
144: private
(byebug) bt
--> #0 FSEvent.open_pipe at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:140
#1 FSEvent.run at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:39
#2 Listen::Adapter::Darwin._run_worker(worker#FSEvent) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:68
#3 Listen::Adapter::Darwin._run at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/adapter/darwin.rb:52
#4 block in Listen::Adapter::Base.block in start at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/adapter/base.rb:78
#5 block in #<Class:Listen::Internals::ThreadPool>.block in add(&block#Proc) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6
起源を知りたいわけだけどものなぜかスタックがとれない。名前からしてThreadらしい?
(byebug) up 5
[1, 10] in /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb
1: module Listen
2: # @private api
3: module Internals
4: module ThreadPool
5: def self.add(&block)
=> 6: Thread.new { block.call }.tap do |th|
7: (@threads ||= Queue.new) << th
8: end
9: end
10:
ではここら辺にブレークポイントを置いてみる。ついでにIOの様子も見ておこう。
(byebug) delete 1 2
Deleted breakpoint 1
Deleted breakpoint 2
(byebug) b 8
Created breakpoint 3 at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:8
(byebug) display ObjectSpace.each_object(IO).reject(&:closed?)
1: ObjectSpace.each_object(IO).reject(&:closed?) = [#<IO:<STDERR>>, #<IO:<STDOUT>>, #<IO:<STDIN>>, #<File:/Users/akira/src/app_foo/log/development.log>, #<File:/Users/akira/src/app_foo/log/delayed_job.log>]
まだPIPEらしいのはない。
(byebug) c
Return value is: #<Thread::Queue:0x00007fae105d4da8>
1: ObjectSpace.each_object(IO).reject(&:closed?) = [#<IO:<STDERR>>, #<IO:<STDOUT>>, #<IO:<STDIN>>, #<IO:fd 10>, #<File:/Users/akira/src/app_foo/log/development.log>, #<File:/Users/akira/src/app_foo/log/delayed_job.log>, #<File:/Users/akira/src/app_foo/log/bullet.log>]
[3, 12] in /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb
3: module Internals
4: module ThreadPool
5: def self.add(&block)
6: Thread.new { block.call }.tap do |th|
7: (@threads ||= Queue.new) << th
=> 8: end
9: end
10:
11: def self.stop
12: return unless @threads ||= nil
あやしめのIOが増えたのでbt。
(byebug) bt
--> #0 block in #<Class:Listen::Internals::ThreadPool>.block in add(&block#Proc) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:8
ͱ-- #1 Kernel.tap at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6
#2 #<Class:Listen::Internals::ThreadPool>.add(&block#Proc) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6
#3 Listen::Adapter::Base.start at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/adapter/base.rb:73
#4 Listen::Backend.start at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/backend.rb:28
#5 block in block in <class:Listener> at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/listener.rb:67
ͱ-- #6 BasicObject.instance_eval(*args) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/fsm.rb:120
#7 Listen::FSM::State.call(obj#Listen::Listener) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/fsm.rb:120
#8 Listen::FSM.transition_with_callbacks!(state_name#Listen::FSM::State) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/fsm.rb:91
#9 Listen::FSM.transition(state_name#Symbol) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/fsm.rb:57
#10 Listen::Listener.start at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/listen-3.0.8/lib/listen/listener.rb:90
#11 ActiveSupport::EventedFileUpdateChecker.boot! at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/evented_file_update_checker.rb:96
#12 ActiveSupport::EventedFileUpdateChecker.initialize(files#Array, dirs#Hash, &block#Proc) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/evented_file_update_checker.rb:67
ͱ-- #13 Class.new(*args) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/railties-5.2.0/lib/rails/application/finisher.rb:166
#14 block in block in <module:Finisher> at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/railties-5.2.0/lib/rails/application/finisher.rb:166
ͱ-- #15 BasicObject.instance_exec(*args) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/railties-5.2.0/lib/rails/initializable.rb:32
#16 Rails::Initializable::Initializer.run(*args#Array) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/railties-5.2.0/lib/rails/initializable.rb:32
#17 block in Rails::Initializable.block in run_initializers(group#Symbol, *args#Array) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/railties-5.2.0/lib/rails/initializable.rb:61
#18 block in #<Class:TSort>.block in tsort_each(each_node#Method, each_child#Method) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/2.5.0/tsort.rb:228
#19 block (2 levels) in #<Class:TSort>.block (2 levels) in each_strongly_connected_component(each_node#Method, each_child#Method) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/2.5.0/tsort.rb:350
#20 #<Class:TSort>.each_strongly_connected_component_from(node#Rails::Initializable::Initializer, each_child#Method, id_map#Hash, stack#Array) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/2.5.0/tsort.rb:431
#21 block in #<Class:TSort>.block in each_strongly_connected_component(each_node#Method, each_child#Method) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/2.5.0/tsort.rb:349
ͱ-- #22 Rails::Initializable::Collection.each at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/2.5.0/tsort.rb:347
ͱ-- #23 Method.call(*args) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/2.5.0/tsort.rb:347
#24 #<Class:TSort>.each_strongly_connected_component(each_node#Method, each_child#Method) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/2.5.0/tsort.rb:347
#25 #<Class:TSort>.tsort_each(each_node#Method, each_child#Method) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/2.5.0/tsort.rb:226
#26 TSort.tsort_each(&block#Proc) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/2.5.0/tsort.rb:205
#27 Rails::Initializable.run_initializers(group#Symbol, *args#Array) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/railties-5.2.0/lib/rails/initializable.rb:60
#28 Rails::Application.initialize!(group#Symbol) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/railties-5.2.0/lib/rails/application.rb:361
#29 <top (required)> at /Users/akira/src/app_foo/config/environment.rb:5
ͱ-- #30 Kernel.require at /Users/akira/src/app_foo/bin/delayed_job:3
#31 <top (required)> at /Users/akira/src/app_foo/bin/delayed_job:3
Listenはfsevent_watchを直接的に起動しているクラスなのでそれを飛ばすと#11 ActiveSupport::EventedFileUpdateChecker.boot!が起源らしい。
...(略)...
(byebug) up
[91, 100] in /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.0/lib/active_support/evented_file_update_checker.rb
91: end
92: end
93:
94: private
95: def boot!
=> 96: Listen.to(*@dtw, &method(:changed)).start
97: end
98:
99: def changed(modified, added, removed)
100: unless updated?
...(略)...
(byebug)
[161, 170] in /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/railties-5.2.0/lib/rails/application/finisher.rb
161: else
162: app.reloader.check = lambda { true }
163: end
164:
165: if config.reload_classes_only_on_change
=> 166: reloader = config.file_watcher.new(*watchable_args, &callback)
167: reloaders << reloader
168:
169: # Prepend this callback to have autoloaded constants cleared before
170: # any other possible reloading, in case they need to autoload fresh
config.reload_classes_only_on_changeは、「Ruby on Rails ガイド」の「Railsアプリを設定する」より
- config.reload_classes_only_on_changeは、監視しているファイルが変更された場合にのみクラスを再読み込みするかどうかを指定します。デフォルトでは、autoload_pathで指定されたすべてのファイルが監視対象となり、デフォルトでtrueが設定されます。config.cache_classesがtrueの場合はこのオプションは無視されます。
ということなので、まあ、そういうこと。これはRailsの標準の挙動。
設定で回避できるのかもしれないが、delayed_jobのためにこのあたりの設定を変えるのはさすがにナンセンスな気がする。
じゃあもう一度最初に戻って、そもそもどこでIO#closeしようとしているのか確認してみる。つまり、delayed_jobがIO#closeするのが遅すぎるのではないか? ということ。
$ DISABLE_SPRING=1 bundle exec byebug bin/delayed_job run
[1, 7] in /Users/akira/src/app_foo/bin/delayed_job
1: #!/usr/bin/env ruby
2:
=> 3: require File.expand_path(File.join(File.dirname(__FILE__), '..', 'config', 'environment'))
4: require 'delayed/command'
5: Delayed::Command.new(ARGV).daemonize
(byebug) b /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126
Created breakpoint 1 at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126
(byebug) c
Stopped by breakpoint 1 at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126
[121, 130] in /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb
121: def close_io
122: # Make sure all input/output streams are closed
123: # Part I: close all IO objects (except for STDIN/STDOUT/STDERR)
124: ObjectSpace.each_object(IO) do |io|
125: unless [STDIN, STDOUT, STDERR].include?(io)
=> 126: io.close rescue nil
127: end
128: end
129:
130: # Make sure all input/output streams are closed
(byebug) bt
--> #0 block in #<Class:Daemonize>.block in close_io at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:126
ͱ-- #1 #<Class:ObjectSpace>.each_object(*args) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:124
#2 #<Class:Daemonize>.close_io at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:124
#3 #<Class:Daemonize>.simulate(logfile_name#NilClass, app_name#NilClass) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/daemonize.rb:30
#4 Daemons::Application.start_proc at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/application.rb:272
#5 Daemons::Application.start(restart#FalseClass) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/application.rb:295
#6 Daemons::Controller.run at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/controller.rb:59
#7 block in #<Class:Daemons>.block in run_proc(app_name#String, options#Hash, &block#Proc) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons.rb:193
#8 Daemons::Controller.catch_exceptions(&block#Proc) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons/cmdline.rb:88
#9 #<Class:Daemons>.run_proc(app_name#String, options#Hash, &block#Proc) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/daemons-1.2.2/lib/daemons.rb:192
#10 Delayed::Command.run_process(process_name#String, options#Hash) at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/delayed_job-4.1.5/lib/delayed/command.rb:123
#11 block in Delayed::Command.block in daemonize at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/delayed_job-4.1.5/lib/delayed/command.rb:104
ͱ-- #12 Integer.times at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/delayed_job-4.1.5/lib/delayed/command.rb:102
#13 Delayed::Command.daemonize at /Users/akira/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/delayed_job-4.1.5/lib/delayed/command.rb:102
#14 <top (required)> at /Users/akira/src/app_foo/bin/delayed_job:5
#9までは別のgemだから#10からたどってみるが、実際のdelayed_jobの処理をDaemons配下で実行しようという部分のようなので、結局は一番上までたどりついてしまう。
(byebug)
[1, 7] in /Users/akira/src/app_foo/bin/delayed_job
1: #!/usr/bin/env ruby
2:
3: require File.expand_path(File.join(File.dirname(__FILE__), '..', 'config', 'environment'))
4: require 'delayed/command'
=> 5: Delayed::Command.new(ARGV).daemonize
これまに見てきたように3行目でPIPEがオープンされている。最初の行だ。ということは、設定を変えるのは! なんて言ってみたが設定を変えるほかないかもしれない。
となると関連しそうなconfig.cache_classesか? と思うが、これはうまくいかない。Railsガイドにあるように「監視しているファイルが変更された場合にのみクラスを再読み込みするか」については影響するようだが、fsevent_watchが起動されることには変わりなかった。ではより直接的なconfig.reload_classes_only_on_changeをfalseにするのはどうか。これもうまくいかない。通常、fsevent_watchは複数個起動されるのだが、このオプションをfalseにすると起動されるのが一つだけになる。だが一つは起動されてしまうのである。
これはactivesupport-5.2.0のlib/active_support/i18n_railtie.rbの以下によるものであるらしい。
reloader = app.config.file_watcher.new(I18n.load_path.dup, directories) do
I18n.load_path.keep_if { |p| File.exist?(p) }
I18n.load_path |= reloadable_paths.flat_map(&:existent)
I18n.reload!
end
こうなってくるとやぶれかぶれ感も出てくるのだが、config/initializers/development.rbで以下のようにするのはうまくいった。この場合はfsevent_watchが起動されなくなる。もしかするとちょっとひどいかもしれない。
config.file_watcher = ActiveSupport::EventedFileUpdateChecker
if %r{/delayed_job\z}.match?($0)
config.file_watcher = Class.new do
def initialize(*); end
def updated?; end
def execute; end
def execute_if_updated; end
end
end
また、以下のようなinitializersファイルを用意するのもうまくいった。この場合は問題のIO#closeの前にPIPEの相手を終了させている。見分けが付かないから問答無用である。
if %r{/delayed_job\z}.match?($0)
Rails.application.config.after_initialize do
ObjectSpace.each_object(IO) do |io|
next if io.closed? || io.pid.nil?
Process.kill(:KILL, io.pid)
end
end
end
もっとも、このようにするならbin/delayed_jobに組み込んでしまったほうがよいだろう。
#!/usr/bin/env ruby
require File.expand_path(File.join(File.dirname(__FILE__), '..', 'config', 'environment'))
ObjectSpace.each_object(IO) do |io|
next if io.closed? || io.pid.nil?
Process.kill(:KILL, io.pid)
end
require 'delayed/command'
Delayed::Command.new(ARGV).daemonize
Rails.application.after_initializeで仕込む必要があるのかと思ったのだが、そうでもないらしい。(もしかしたら他の設定や状況によるかもしれないが。)
ところで、実はこの問題はすでに報告されている。そしてPRもある。
これどうして放置されているのだろう?