GoogleCloudPlatform/fluent-plugin-detect-exceptions

emit transaction failed: error_class=ThreadError error="deadlock; recursive locking"

jushiyuan opened this issue · 2 comments

Hi,when I start fluentd,it give the "deadlock; recursive locking" error.
the error log:

2018-02-10 02:09:06 +0000 [info]: #0 starting fluentd worker pid=68 ppid=64 worker=0
2018-02-10 02:09:06 +0000 [info]: #0 following tail of /host/var/lib/docker/containers/d88c17659be484591802745716d9644f81f5dea83fa1d0033684706d14bfe555/d88c17659be484591802745716d9644f81f5dea83fa1d0033684706d14bfe555-json.log
2018-02-10 02:09:06 +0000 [info]: #0 disable filter chain optimization because [Fluent::Plugin::RecordTransformerFilter] uses `#filter_stream` method.
2018-02-10 02:09:06 +0000 [warn]: #0 emit transaction failed: error_class=ThreadError error="deadlock; recursive locking" location="/usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:131:in `synchronize'" tag="docker.d88c17659be484591802745716d9644f81f5dea83fa1d0033684706d14bfe555.wsicomp-beta-stdout"
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:131:in `synchronize'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:131:in `synchronize'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:88:in `process_record'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:80:in `block in emit'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/event.rb:193:in `block in each'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/event.rb:192:in `each'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/event.rb:192:in `each'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:79:in `emit'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/compat/output.rb:164:in `process'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/output.rb:760:in `emit_sync'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/event_router.rb:159:in `emit_events'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/event_router.rb:96:in `emit_stream'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/event_router.rb:87:in `emit'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:97:in `block (2 levels) in process_record'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/exception_detector.rb:276:in `update_buffer'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/exception_detector.rb:226:in `push'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:101:in `block in process_record'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:131:in `synchronize'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:131:in `synchronize'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:88:in `process_record'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:80:in `block in emit'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/event.rb:193:in `block in each'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/event.rb:192:in `each'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/event.rb:192:in `each'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:79:in `emit'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/compat/output.rb:164:in `process'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/output.rb:760:in `emit_sync'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/event_router.rb:159:in `emit_events'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/event_router.rb:96:in `emit_stream'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/in_tail.rb:385:in `receive_lines'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/in_tail.rb:503:in `wrap_receive_lines'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/in_tail.rb:707:in `block in on_notify'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/in_tail.rb:751:in `with_io'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/in_tail.rb:685:in `on_notify'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/in_tail.rb:534:in `on_notify'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/in_tail.rb:507:in `attach'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/in_tail.rb:264:in `setup_watcher'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/in_tail.rb:292:in `block in start_watchers'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/in_tail.rb:278:in `each'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/in_tail.rb:278:in `start_watchers'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/in_tail.rb:258:in `refresh_watchers'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/plugin/in_tail.rb:193:in `start'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/root_agent.rb:165:in `block in start'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/root_agent.rb:154:in `block (2 levels) in lifecycle'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/root_agent.rb:153:in `each'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/root_agent.rb:153:in `block in lifecycle'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/root_agent.rb:140:in `each'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/root_agent.rb:140:in `lifecycle'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/root_agent.rb:164:in `start'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/engine.rb:274:in `start'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/engine.rb:219:in `run'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/supervisor.rb:774:in `run_engine'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/supervisor.rb:523:in `block in run_worker'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/supervisor.rb:699:in `main_process'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/supervisor.rb:518:in `run_worker'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/lib/fluent/command/fluentd.rb:316:in `<top (required)>'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/lib/ruby/gems/2.4.0/gems/fluentd-1.1.0/bin/fluentd:8:in `<top (required)>'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/bin/fluentd:23:in `load'
  2018-02-10 02:09:06 +0000 [warn]: #0 /usr/bin/fluentd:23:in `<main>'
2018-02-10 02:09:06 +0000 [warn]: #0 emit transaction failed: error_class=ThreadError error="deadlock; recursive locking" location="/usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:131:in `synchronize'" tag="docker.d88c17659be484591802745716d9644f81f5dea83fa1d0033684706d14bfe555.wsicomp-beta-stdout"
  2018-02-10 02:09:06 +0000 [warn]: #0 suppressed same stacktrace
2018-02-10 02:09:06 +0000 [warn]: #0 emit transaction failed: error_class=ThreadError error="deadlock; recursive locking" location="/usr/lib/ruby/gems/2.4.0/gems/fluent-plugin-detect-exceptions-0.0.9/lib/fluent/plugin/out_detect_exceptions.rb:131:in `synchronize'" tag="docker.d88c17659be484591802745716d9644f81f5dea83fa1d0033684706d14bfe555.wsicomp-beta-stdout"
  2018-02-10 02:09:06 +0000 [warn]: #0 suppressed same stacktrace

Thanks.

The detect-exceptions plugin is an output plugin that re-posts messages into the buffer. Thus, if you do not rewrite the tags before re-posting, the message will be routed to the same plugin again, and this causes recursion and deadlock.

To avoid this, please set up your config to rewrite the tag (by stripping off a prefix), so tags that already went through exception detection aren't matched again.

Thanks very much.