Fluentd 終了時に起きる "[!] There was an error parsing `Gemfile`: SIGTERM. Bundler cannot continue." を握り潰す
Fluentd が終了する時に次のようなエラーに遭遇することがあります。
/private/tmp/fluentd/Gemfile:13:in `sleep': (Bundler::Dsl::DSLError)
[!] There was an error parsing `Gemfile`: SIGTERM. Bundler cannot continue.
# from /private/tmp/fluentd/Gemfile:13
# -------------------------------------------
# $stderr.puts "#{File.basename($PROGRAM_NAME)}: sleep 1"
> sleep 1
# -------------------------------------------
from /private/tmp/fluentd/Gemfile:13:in `eval_gemfile'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/dsl.rb:47:in `instance_eval'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/dsl.rb:47:in `eval_gemfile'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/dsl.rb:12:in `evaluate'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/definition.rb:33:in `build'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler.rb:195:in `definition'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler.rb:143:in `setup'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/setup.rb:20:in `block in <top (required)>'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/ui/shell.rb:136:in `with_level'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/ui/shell.rb:88:in `silence'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/setup.rb:20:in `<top (required)>'
from <internal:/Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
from <internal:/Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
/private/tmp/fluentd/Gemfile:13:in `sleep': SIGTERM (SignalException)
from /private/tmp/fluentd/Gemfile:13:in `eval_gemfile'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/dsl.rb:47:in `instance_eval'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/dsl.rb:47:in `eval_gemfile'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/dsl.rb:12:in `evaluate'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/definition.rb:33:in `build'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler.rb:195:in `definition'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler.rb:143:in `setup'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/setup.rb:20:in `block in <top (required)>'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/ui/shell.rb:136:in `with_level'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/ui/shell.rb:88:in `silence'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/setup.rb:20:in `<top (required)>'
from <internal:/Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
from <internal:/Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
stacktrace を見ると Fluentd が起動せずに Gemfile を処理するところで stuck してしまっているのではないかと不安になりますよね！このエラーがどういう時に起きるエラーで、どうすれば無視できるかについて解説します。
どういう時に起きるエラーなのか？
exec output plugin 等、外部プログラムを呼び出す plugin で、Ruby のスクリプトを処理している最中、中でも Gemfile を処理している最中に Fluentd が終了すると起きるエラーです。exec output plugin に関して言えば、プログラムがエラー終了した場合は rollback するようになっているので、file buffer で管理していれば Fluentd が再度起動した後に再処理されます。memory buffer を使っていたり、Fluentd が起動することがなかったりすれば、flush できなかったデータは消失することになります。
なので、問題があるかどうかはデータの性質や Fluentd の運用方法次第ですが、Fluentd 本体のエラーではありません。
再現手順
次の設定ファイルで再現できます。
fluent.conf
<source>
@type sample
tag test
</source>
<match>
@type exec
command "ruby main.rb" # main.rb の内容は何でも良い
<format>
@type json
</format>
<buffer>
flush_interval 2s
</buffer>
</match>
Gemfile
# frozen_string_literal: true
source "https://rubygems.org"
git_source(:github) { |repo_name| "https://github.com/#{repo_name}" }
gem "fluentd"
if File.basename($PROGRAM_NAME) == "main.rb"
Thread.start { Process.kill(:TERM, Process.ppid) }
end
$stderr.puts "#{File.basename($PROGRAM_NAME)}: sleep 1"
sleep 1
実行してみます。
% fluentd -c fluent.conf --gemfile Gemfile
bundle: sleep 1
bundle: sleep 1
Using bundler 2.2.22
Using concurrent-ruby 1.1.10
Using cool.io 1.7.1
Using http_parser.rb 0.8.0
Using msgpack 1.6.0
Using sigdump 0.2.4
Using serverengine 2.3.0
Using strptime 0.2.5
Using tzinfo 2.0.5
Using tzinfo-data 1.2022.6
Using webrick 1.7.0
Using yajl-ruby 1.4.3
Using fluentd 1.15.3
Bundle complete! 1 Gemfile dependency, 13 gems now installed.
Bundled gems are installed into `./vendor/bundle`
fluentd.rb: sleep 1
2022-11-04 02:30:54 +0900 [info]: init supervisor logger path=nil rotate_age=nil rotate_size=nil
2022-11-04 02:30:54 +0900 [info]: parsing config file is succeeded path="fluent.conf"
2022-11-04 02:30:54 +0900 [info]: gem 'fluentd' version '1.15.3'
2022-11-04 02:30:54 +0900 [info]: Oj isn't installed, fallback to Yajl as json parser
2022-11-04 02:30:54 +0900 [warn]: both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2022-11-04 02:30:54 +0900 [warn]: both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2022-11-04 02:30:54 +0900 [warn]: define <match fluent.**> to capture fluentd logs in top level is deprecated. Use <label @FLUENT_LOG> instead
2022-11-04 02:30:54 +0900 [info]: using configuration file: <ROOT>
<source>
@type sample
tag "test"
</source>
<match>
@type exec
command "ruby main.rb"
<format>
@type "json"
</format>
<buffer>
flush_interval 2s
</buffer>
</match>
</ROOT>
2022-11-04 02:30:54 +0900 [info]: starting fluentd-1.15.3 pid=79643 ruby="3.0.2"
2022-11-04 02:30:54 +0900 [info]: spawn command to main: cmdline=["/Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/bin/ruby", "-r/Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/setup", "-Eascii-8bit:ascii-8bit", "/Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/fluentd-1.15.3/lib/fluent/command/fluentd.rb", "-c", "fluent.conf", "--gemfile", "Gemfile", "--under-supervisor"]
2022-11-04 02:30:54 +0900 [info]: init supervisor logger path=nil rotate_age=nil rotate_size=nil
fluentd.rb: sleep 1
2022-11-04 02:30:56 +0900 [info]: #0 init worker0 logger path=nil rotate_age=nil rotate_size=nil
2022-11-04 02:30:56 +0900 [info]: adding match pattern="**" type="exec"
2022-11-04 02:30:56 +0900 [info]: #0 Oj isn't installed, fallback to Yajl as json parser
2022-11-04 02:30:56 +0900 [info]: adding source type="sample"
2022-11-04 02:30:56 +0900 [warn]: #0 both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2022-11-04 02:30:56 +0900 [warn]: #0 both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2022-11-04 02:30:56 +0900 [warn]: #0 define <match fluent.**> to capture fluentd logs in top level is deprecated. Use <label @FLUENT_LOG> instead
2022-11-04 02:30:56 +0900 [info]: #0 starting fluentd worker pid=79678 ppid=79643 worker=0
2022-11-04 02:30:56 +0900 [info]: #0 fluentd worker is now running worker=0
main.rb: sleep 1
2022-11-04 02:30:59 +0900 [info]: #0 fluentd worker is now stopping worker=0
2022-11-04 02:30:59 +0900 [info]: #0 shutting down fluentd worker worker=0
2022-11-04 02:30:59 +0900 [info]: #0 shutting down input plugin type=:sample plugin_id="object:960"
main.rb: sleep 1
2022-11-04 02:31:00 +0900 [info]: #0 shutting down output plugin type=:exec plugin_id="object:938"
/private/tmp/fluentd/Gemfile:13:in `sleep': (Bundler::Dsl::DSLError)
[!] There was an error parsing `Gemfile`: SIGTERM. Bundler cannot continue.
# from /private/tmp/fluentd/Gemfile:13
# -------------------------------------------
# $stderr.puts "#{File.basename($PROGRAM_NAME)}: sleep 1"
> sleep 1
# -------------------------------------------
from /private/tmp/fluentd/Gemfile:13:in `eval_gemfile'
from /Users/arabiki/.anyenv/envs/rbenv/versions/3.0.2/lib/ruby/3.0.0/bundler/dsl.rb:47:in `instance_eval'
-- snip --
ruby main.rb は bundle exec 経由で呼び出されていないから Gemfile が処理されているのはおかしいと思う方もいるかもしれませんが、fluentd は --gemfile が指定されていると、起動時に BUNDLE_GEMFILE をセットし、bundle exec 経由で再度プロセスを起動します。そうすると、起動したプロセスには依然として BUNDLE_GEMFILE がセットされた状態だし、RUBYOPT に -r/path/to/bundler/setup のような値がセットされるので、そのプロセスが起動した子プロセスや孫プロセスも bundle exec 経由で実行するのと同じ効果が得られます。
よって、もし bundler を経由したくなければ RUBYOPT='' ruby main.rb とすることで回避できます。
エラーメッセージを握り潰す
Gemfile を次のように begin で囲んで SignalException を rescue し、$stderr を $stdout に差し替えるのが一番無難なんじゃないかと思います。握り潰すというよりは、不安を煽る仰々しい stacktrace の代わりに 1 行シグナルを受け取った旨を出す感じですね。
# frozen_string_literal: true
begin
source "https://rubygems.org"
git_source(:github) { |repo_name| "https://github.com/#{repo_name}" }
...
rescue SignalException => e
$stderr.puts "#{File.basename($PROGRAM_NAME)}: Received SIG#{Signal.signame(e.signo)} while parsing Gemfile"
# Suppress the error "There was an error ..." from Bundler::Dsl
$stderr = $stdout
raise e
end
どうしてわざわざ $stderr を $stdout にしているかというと、exec output plugin に関して言えば、標準エラー出力をハンドリングしておらず、子プロセスが標準エラー出力に吐いた内容がそのまま表示されてしまうからです。内容を握り潰せれば良いので、File.open(File::NULL, 'w') や StringIO.new でも良いとは思います。
なお、exit も試してみたんですが、依然終了時にエラーメッセージが出てしまいました。bundler は一般的には rescue しない Exception を rescue しているからみたいですね。
cf. bundler/dsl.rb#L41-L56
以上、同じ不安を抱えている人の不安解消になれば幸いです。