概要
ruby の puts でデバッグしているとコンテナが停止しないとログが表示されない現象が発生することがあります
今回はその対処方法を紹介します
環境
- macOS 10.14.4
- Ruby 2.6.2p47
- docker 18.09.2
サンプルコード
Ruby は以下のような感じとします
puts "start"
sleep 10
puts "hoge"
sleep 10
puts "fuga"
sleep 10
puts "end"本来なら 10 秒おきにそれぞれの puts 情報が表示されてほしいのですが docker logs -f などで見るとそうなりません
ちなみに Dockerfile は以下の通りです
FROM ruby:latest
ADD . /home
WORKDIR /home
CMD ["ruby", "app.rb"]対処方法
docker では有名ですが /proc/1/fd/1 を使います
docker では CMD で指定したコマンドは基本的には 1 番になります (意図的に変更しない限り)
/proc/1/fd/1 はプロセス 1 番のファイルディスクリプタで標準出力へのリダイレクトになっています
このファイルに直接書き込むことで標準出力を強制してさせます
$stdout = IO.new(IO.sysopen("/proc/1/fd/1", "w"), "w")
$stdout.sync = true
STDOUT = $stdout
puts "start"
sleep 10
puts "hoge"
sleep 10
puts "fuga"
sleep 10
puts "end"これでイメージを作成し直し run してみるとちゃんとリアルタイムに logs で確認できると思います
app.rb:3: warning: already initialized constant STDOUT が表示されてしまいますが不要な場合は -W0 を ruby 実行時に指定すれば OK です
CMD ["ruby", "-W0", "app.rb"]logger でも同じように対処できる
logger を使ってロギングしている場合も同様の現象になると思います
その場合は以下のようにしましょう
require 'logger'
logger = Logger.new(STDOUT)
logger.info "start"
sleep 10
logger.info "hoge"
sleep 10
logger.info "fuga"
sleep 10
logger.info "end"これだと表示されないので以下のようにします
require 'logger'
$stdout = IO.new(IO.sysopen("/proc/1/fd/1", "w"),"w")
$stdout.sync = true
STDOUT = $stdout
logger = Logger.new(STDOUT)
logger.info "start"
sleep 10
logger.info "hoge"
sleep 10
logger.info "fuga"
sleep 10
logger.info "end"これで表示されるようになると思います
Exception も考慮しなくていいのか
例えば以下のような感じだとエラーメッセージの部分は表示されます
$stdout = IO.new(IO.sysopen("/proc/1/fd/1", "w"),"w")
$stdout.sync = true
STDOUT = $stdout
$stderr = IO.new(IO.sysopen("/proc/1/fd/1", "w"),"w")
$stderr.sync = true
STDERR = $stderr
puts "start"
sleep 1
puts "hoge"
sleep 1
puts "fuga"
begin
5/0
rescue => e
puts e.full_message
end
sleep 1
puts "end"puts e.full_message の部分だけですが以下のようにちゃんと logs でもリアルタイムに確認できます
app.rb:14:in `/': divided by 0 (ZeroDivisionError)
from app.rb:14:in `<main>'普通に ruby を実行したときと違うのは「Traceback (most recent call last):」が表示されない部分だけかなと思います
標準エラーも操作してみましたが結果は変わらなかったので STDOUT だけで十分なのかなと思います
$stderr = IO.new(IO.sysopen("/proc/1/fd/2", "w"),"w")
$stderr.sync = true
STDERR = $stderr最後に
なぜか ruby の puts が docker logs -f でリアルタイムに表示されなかったのでその対処をしてみました
ファイルディスクリプタを直接操作することで解決しましたがちょっと気持ち悪い感じはします
docker のロギングドライバを変えるという方法はありかもしれませんがそもそも docker がログを拾えていないとドライバを変えても意味がないので結局ファイルディスクリプタを操作しなければいけないかもしれません
他の言語だとこういう現象はあまり遭遇しないので Ruby のイメージが原因なのかもしれません
ちなみに ruby の docker イメージバージョンは 2.6.3p62 なのでだいぶ最新を使いました
$ docker run -it --rm ruby ruby -v
ruby 2.6.3p62 (2019-04-16 revision 67580) [x86_64-linux]
0 件のコメント:
コメントを投稿