Railsから複数行のLinuxコマンドを非同期（バックグラウンド）で実行させる
時間のかかる処理を非同期で実行させる場合に、いろいろはまったのでまとめておきます。
最終ゴール：
複数行のLinuxコマンド（ShellScript）を非同期で実行させ、
途中でキャンセルもできるようにする
非同期で実行する仕組みはresqueとかsidekiqとかいくつもありますが、
- 非同期で実行させたいのはRubyのコードではなくLinuxのコマンドだけ
- 定期ジョブで実行させたい（コマンド処理が終わればRubyは終了させたい）
ということもあり、Ruby標準の仕組みで簡単に済まそうと考えました。
ポイントは次の6つです。
- 複数のLinuxコマンドは実行可能ファイルにまとめる
- その実行可能ファイルを非同期（バックグラウンド）で実行させる
- バックグラウンド実行のために標準出力と標準エラーをファイルに落としておく（もしくは/dev/nullにリダイレクト）
- forkしてrailsとは別プロセスで実行させる
- キャンセル用（kill用）にpidを取得しておく
- pidからpgidを取得し、紐づいている子プロセス含めて全てキャンセルする
Linuxコマンド実行は次のページを参考にしました。
結論を早く見たい人は、 試行3 あたりから見てもらえると良いと思います。
非同期処理させたいLinuxコマンドを準備
まず時間のかかる処理をtest_commandとして作っておきます。
$ echo "sleep 100000" > ~/bin/test_command
$ chmod +x ~/bin/test_command
sleep 100000
次にRailsにtest_commandを呼び出す部分とキャンセルする部分を作ります。
（本当はpidをmodelやファイルに保存するなどの処理が必要ですが、この記事用にはpidを標準出力に表示させる形にしています）
試行1（IO.popenを使う）
最初に試したのはIO.popenです。
pidが簡単に取れそうだったからです。
class JobTask
class << self
def execute
execute_job "test_command > test.log >2&1 &"
end
def cancel(pid)
IO.popen("kill -TERM #{pid}")
p "canceled!"
end
private
def execute_job(command)
begin
IO.popen("#{command}"){|pipe| p pipe.pid}
rescue => e
Rails.logger.error e.message
end
end
end
end
実行させるとpidが表示されます。
$ rails runner JobTask.execute
3377
ここで、pidを確認してみると
$ ps aux | grep test_command
ogi 3388 0.0 0.0 2432784 580 s001 R+ 3:37PM 0:00.00 grep test_command
ogi 3378 0.0 0.0 2442580 580 ?? S 3:35PM 0:00.00 sh -c test_command > test.log 2>&1 &
となり、取得した3377とは異なるpid（+1された値）となっていました。
これではpidでキャンセルできません。う〜ん困りました。
試行2（実行後にpsでpidを取得する）
欲しいpidはtest_commandのものなので、実行直後にpsでpidを取得しようと考えました。
grepするとgrepのプロセスまで取得してしまうため、それは対象としないようにしました。
class JobTask
class << self
def execute
execute_job "test_command > test.log >2&1 &"
end
def cancel(pid)
IO.popen("kill -TERM #{pid}")
p "canceled!"
end
private
def execute_job(command)
IO.popen("#{command}"){}
IO.popen("ps aux | grep -E \"test_command \> test.log\"") do |pipe|
pipe.readlines.each do |line|
p line.split[1] if line =~ /^(?!.*grep -E).*$/
end
end
end
end
end
実行します。
$ rails runner JobTask.execute
"3836"
取得したpidが正しいか確認します。
$ ps aux | grep test_command
ogi 3847 0.0 0.0 2432784 524 s001 R+ 4:08PM 0:00.00 grep test_command
ogi 3836 0.0 0.0 2442580 580 ?? S 4:08PM 0:00.00 sh -c test_command > test.log 2>&1 &
今度は欲しいpidが取得できていました。
ではそのpidを使ってキャンセルしてみます。
$ rails runner "JobTask.cancel(3836)"
キャンセルされたか確認します。
$ ps aux | grep test_command
ogi 3944 0.0 0.0 2423368 184 s001 R+ 4:14PM 0:00.00 grep test_command
プロセスはkillされていました。
と思っていましたが、落とし穴がありました。
test_command内で呼び出しているコマンド（sleep）は残っていました。
$ ps aux | grep sleep
ogi 3954 0.0 0.0 2432784 504 s001 R+ 4:17PM 0:00.00 grep sleep
ogi 3838 0.0 0.0 2432764 468 ?? S 4:08PM 0:00.00 sleep 100000
つまり、対象のプロセスはkillできましたが、そこから呼び出している子プロセスまではkillできていないということです。
試行3（echo $!でpid取得と、pgidで関連プロセス全てキャンセル）
まずpid取得ですが、grepとか使わずとも簡単に取得できることがわかりました。
test_command > test.log 2>&1 & echo $!
のように、バックグラウンド実行直後にecho $!をつなげるだけで、最後に実行したpidが取得できるというのです！
（西脇.rb & 神戸.rbのメンバーに感謝！）
pidが一行で取得できるのでIO.popenではなく`test_command`の形に変更できそうです。
さらに、子プロセスまでまとめてkillする方法も教えてもらいました。
gpidを利用する方法です。
（こちらも西脇.rb & 神戸.rbのメンバーが教えてくれました）
プロセスグループIDの調べ方
$ ps -p 4043 -o "pgid"
PGID
2947
プロセスグループをkillする方法
$ kill -- -2947
rubyから実行する場合は、--がうまく解釈されないようなので次のようにします。
`kill -TERM -2947`
これらを反映したコードは次の通りです。
class JobTask
class << self
def execute
execute_job "test_command > test.log 2>&1 & echo $!"
end
def cancel(pid)
command = "ps -p #{pid} -o \"pgid\""
pgid = system_command(command).lines.to_a.last.lstrip.chomp
if pgid =~ /[0-9]/
system_command "kill -TERM -#{pgid}"
p "canceled!"
else
Rails.logger.error 'Process was not found'
end
end
private
def execute_job(command)
begin
pid = system_command(command).lstrip.chomp
if pid =~ /[0-9]/
p pid
else
Rails.logger.error 'command has not pid'
end
rescue => e
Rails.logger.error e.message
end
end
def system_command(command)
`#{command}`
end
end
end
再度試します。
$ rails runner JobTask.execute
"4308"
欲しいpidが返ってきました。
$ ps aux | grep test_command
ogi 4317 0.0 0.0 2423368 216 s001 R+ 4:45PM 0:00.00 grep test_command
ogi 4308 0.0 0.0 2442580 568 ?? S 4:44PM 0:00.00 sh -c test_command > test.log 2>&1 & echo $!
$ ps aux | grep sleep
ogi 4324 0.0 0.0 2432784 472 s001 R+ 4:45PM 0:00.00 grep sleep
ogi 4309 0.0 0.0 2432764 468 ?? S 4:44PM 0:00.00 sleep 100000
キャンセルしてみます。
$ rails runner "JobTask.cancel(4308)"
$
プロセスを確認しています。
$ ps aux | grep test_command
ogi 4456 0.0 0.0 2424588 388 s001 R+ 4:48PM 0:00.00 grep test_command
$ ps aux | grep sleep
ogi 4467 0.0 0.0 2432784 508 s001 R+ 4:50PM 0:00.00 grep sleep
子プロセスまでちゃんとkillされています。
うまくいった！と思いきや、ここにも落とし穴がありました。
コードでは、
system_command "kill -TERM -#{pgid}"
p "canceled!"
とkillの後にログを表示させているのですが、コマンド実行しても何も表示されていませんでした。
デバッガで追いかけても続きを実行できません。
まるで途中で強制終了されたような動きです。
JobTask.execute後のプロセスグループをもう一度確認してみます。
$ rails runner JobTask.execute
"4520"
$ ps -p 4520 -o "pgid"
PGID
4449
$ ps 4449
PID TT STAT TIME COMMAND
4449 ?? Ss 0:05.35 spring app | background_linux_command | started 8 mins ago | development mode
グループのルートプロセスがspring（railsを動かしているそのもの）だとわかりました。
なるほど、test_commandとその子プロセスをkillしたつもりが、親のrailsまでkillしていたため続きが実行されていなかったということですね。納得です。
ということで別グループで動かす必要があることがわかりました。
試行4（forkして別プロセスで実行する）
railsとは別グループで動かすにはどうすればいいのでしょう？
そういえばデーモンっぽく動かしているdaemon-spawnはどうしてるんだろう？
と思ってソースを見てみました。
daemon_spawn.rb
:
def self.start(daemon, args) #:nodoc:
:
fork do
Process.setsid
exit if fork
open(daemon.pid_file, 'w') { |f| f << Process.pid }
:
end
:
end
:
なるほど、forkして別プロセスにするわけですね！
これを参考にしてみました。
```rb:lib/job_task.rb
class JobTask
class << self
def execute
execute_job "test_command > test.log 2>&1 & echo $!"
end
def cancel(pid)
command = "ps -p #{pid} -o \"pgid\""
pgid = system_command(command).lines.to_a.last.lstrip.chomp
if pgid =~ /[0-9]/
system_command "kill -TERM -#{pgid}"
p "canceled!"
else
Rails.logger.error 'Process was not found'
end
end
private
def execute_job(command)
begin
fork do
Process.setsid
pid = system_command(command).lstrip.chomp
if pid =~ /[0-9]/
p pid
else
Rails.logger.error 'command has not pid'
end
end
rescue => e
Rails.logger.error e.message
end
end
def system_command(command)
`#{command}`
end
end
end
では実行してみます。
$ rails runner JobTask.execute
"4877"
$ ps -p 4877 -o "pgid"
PGID
4875
$ ps 4875
PID TT STAT TIME COMMAND
ルートプロセスはspringではなくなりました。というより今度はルートプロセスがすでにいなくなっています。
Rails consoleで確認するとわかるのですが、forkさせるとルートプロセスはrubyになっていました。
$ rails c
Loading development environment (Rails 4.1.8)
irb(main):001:0> JobTask.execute
=> 5003
irb(main):002:0> "5005"
irb(main):003:0* exit
$ ps -p 5005 -o "pgid"
PGID
5003
$ ps 5003
PID TT STAT TIME COMMAND
5003 ?? Z 0:00.00 (ruby)
Rails runnerの処理が終わってrubyプロセスが終了したという認識です。
では、今度はキャンセルしてみます。
$ rails runner "JobTask.cancel(4877)"
"canceled!"
$ ps aux | grep test_command
ogi 4951 0.0 0.0 2432784 488 s001 R+ 5:18PM 0:00.00 grep test_command
$ ps aux | grep sleep
ogi 4958 0.0 0.0 2432784 500 s001 R+ 5:18PM 0:00.00 grep sleep
今度は意図した動きになりました。
試行5（実行させるコマンドをRailsから生成させる）
これまでは実行させるコマンドを~/bin/test_command固定にしていましたが、
実行時に生成したい場合を考えます。
chefのbashブロックがやってるように一時ファイルにコマンドを出力し、
それを実行させるようにします。
class JobTask
class << self
def execute
execute_job
end
def cancel(pid)
command = "ps -p #{pid} -o \"pgid\""
pgid = system_command(command).lines.to_a.last.lstrip.chomp
if pgid =~ /[0-9]/
system_command "kill -TERM -#{pgid}"
p "canceled!"
else
Rails.logger.error 'Process was not found'
end
end
private
def create_command
command = <<-"EOS"
echo "start sleep"
sleep 100000
echo "end sleep"
EOS
script_path = "tmp/test_command"
File.open(script_path, "w", 0755) do |f|
f.write command
end
# execute background and return pid
"#{script_path} > tmp/test.log 2>&1 & echo $!"
end
def execute_job
begin
fork do
Process.setsid
pid = system_command(create_command).lstrip.chomp
if pid =~ /[0-9]/
p pid
else
Rails.logger.error 'command has not pid'
end
end
rescue => e
Rails.logger.error e.message
end
end
def system_command(command)
`#{command}`
end
end
end
実行してみます。
$ rails runner JobTask.execute
"5507"
$ ps aux | grep test_command
ogi 5522 0.0 0.0 2432784 496 s001 R+ 5:49PM 0:00.00 grep test_command
ogi 5507 0.0 0.0 2442580 568 ?? S 5:49PM 0:00.00 sh -c tmp/test_command > tmp/test.log 2>&1 & echo $!
$ ps aux | grep sleep
ogi 5529 0.0 0.0 2424588 404 s001 R+ 5:49PM 0:00.00 grep sleep
ogi 5508 0.0 0.0 2432764 468 ?? S 5:49PM 0:00.00 sleep 100000
キャンセルしてみます。
$ rails runner "JobTask.cancel(5507)"
"canceled!"
$ ps aux | grep test_command
ogi 5572 0.0 0.0 2442000 616 s001 S+ 5:50PM 0:00.00 grep test_command
$ ps aux | grep sleep
ogi 5579 0.0 0.0 2432784 512 s001 R+ 5:50PM 0:00.00 grep sleep
実行用のファイルとログも確認します。
$ ls tmp/
cache test.log test_command
$ cat tmp/test_command
echo "start sleep"
sleep 100000
echo "end sleep"
$ cat tmp/test.log
start sleep
意図した動きになりました。
最後に
試行錯誤でやりたいことを実現している状態なので、
もっと良い方法を知っている方がいましたら教えてもらえるとうれしいです。