Wrong RUBYLIB path for resolv gem

[ncsibra]

We hit the Fluentd burning CPU problem, because of a bug in the resolv lib, which is already described in multiple issues, e.g.: uken/fluent-plugin-elasticsearch#885, fluent/fluentd#3382.
Read through the issues and determine that we were already using the v1.13.0-1.0 docker image, which has the fixed resolv and excon lib and the RUBYLIB env update from here: #275.

Despite that, we still saw the 100% CPU issue and after some investigation, I think I found the problem.
The RUBLYLIB env set here is wrong because the official fluentd docker file using another path for installed gems.
I tested this out, based on the config file used in the PR above.
After fixing this in our environment, the issue is gone.

➜  cat fluent.conf
<source>
 @type sample
 tag sample
</source>

<filter>
  @type record_modifier
  remove_keys _dummy_
  <record>
    _dummy_ ${record['loaded'] = $LOADED_FEATURES.collect { |entry| entry if entry.include?('resolv.rb') }.compact }
  </record>
</filter>

<match sample>
  @type stdout
</match>

➜  docker run -v $PWD:/fluentd/etc --rm -it --entrypoint sh fluent/fluentd:v1.13.0-1.0
/ $ fluent-gem env
RubyGems Environment:
  - RUBYGEMS VERSION: 3.1.6
  - RUBY VERSION: 2.7.3 (2021-04-05 patchlevel 183) [x86_64-linux-musl]
  - INSTALLATION DIRECTORY: /usr/lib/ruby/gems/2.7.0
  - USER INSTALLATION DIRECTORY: /home/fluent/.gem/ruby/2.7.0
  - RUBY EXECUTABLE: /usr/bin/ruby
  - GIT EXECUTABLE:
  - EXECUTABLE DIRECTORY: /usr/bin
  - SPEC CACHE DIRECTORY: /home/fluent/.gem/specs
  - SYSTEM CONFIGURATION DIRECTORY: /etc
  - RUBYGEMS PLATFORMS:
    - ruby
  - GEM PATHS:
     - /usr/lib/ruby/gems/2.7.0
     - /home/fluent/.gem/ruby/2.7.0
  - GEM CONFIGURATION:
     - :update_sources => true
     - :verbose => true
     - :backtrace => false
     - :bulk_threshold => 1000
     - "gem" => "--no-document"
  - REMOTE SOURCES:
     - https://rubygems.org/
  - SHELL PATH:
     - /usr/local/sbin
     - /usr/local/bin
     - /usr/sbin
     - /usr/bin
     - /sbin
     - /bin

/ $ env
HOSTNAME=d9cabb00c72c
SHLVL=1
HOME=/home/fluent
FLUENTD_CONF=fluent.conf
RUBYLIB=/usr/local/bundle/gems/resolv-0.2.1/lib
TERM=xterm
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
LD_PRELOAD=
PWD=/

/ $ fluent-gem which resolv -a
/usr/lib/ruby/2.7.0/resolv.rb
/usr/lib/ruby/gems/2.7.0/gems/resolv-0.2.1/lib/resolv.rb

/ $ fluent-gem install fluent-plugin-record-modifier --no-document --user-install
Fetching fluent-plugin-record-modifier-2.1.0.gem
WARNING:  You don't have /home/fluent/.gem/ruby/2.7.0/bin in your PATH,
          gem executables will not run.
Successfully installed fluent-plugin-record-modifier-2.1.0
1 gem installed

/ $ /bin/entrypoint.sh fluentd -c /fluentd/etc/fluent.conf
fluentd -c /fluentd/etc/fluent.conf
2021-06-21 06:49:19 +0000 [info]: parsing config file is succeeded path="/fluentd/etc/fluent.conf"
2021-06-21 06:49:19 +0000 [info]: gem 'fluent-plugin-record-modifier' version '2.1.0'
2021-06-21 06:49:19 +0000 [info]: gem 'fluentd' version '1.13.0'
2021-06-21 06:49:19 +0000 [warn]: both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2021-06-21 06:49:19 +0000 [warn]: both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2021-06-21 06:49:19 +0000 [warn]: define <match fluent.**> to capture fluentd logs in top level is deprecated. Use <label @FLUENT_LOG> instead
2021-06-21 06:49:19 +0000 [info]: using configuration file: <ROOT>
  <source>
    @type sample
    tag "sample"
  </source>
  <filter>
    @type record_modifier
    remove_keys "_dummy_"
    <record>
      _dummy_ ${record['loaded'] = $LOADED_FEATURES.collect { |entry| entry if entry.include?('resolv.rb') }.compact }
    </record>
  </filter>
  <match sample>
    @type stdout
  </match>
</ROOT>
2021-06-21 06:49:19 +0000 [info]: starting fluentd-1.13.0 pid=21 ruby="2.7.3"
2021-06-21 06:49:19 +0000 [info]: spawn command to main:  cmdline=["/usr/bin/ruby", "-Eascii-8bit:ascii-8bit", "/usr/bin/fluentd", "-c", "/fluentd/etc/fluent.conf", "-p", "/fluentd/plugins", "--under-supervisor"]
2021-06-21 06:49:19 +0000 [info]: adding filter pattern="**" type="record_modifier"
2021-06-21 06:49:19 +0000 [info]: adding match pattern="sample" type="stdout"
2021-06-21 06:49:19 +0000 [info]: adding source type="sample"
2021-06-21 06:49:19 +0000 [warn]: #0 both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2021-06-21 06:49:19 +0000 [warn]: #0 both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2021-06-21 06:49:19 +0000 [warn]: #0 define <match fluent.**> to capture fluentd logs in top level is deprecated. Use <label @FLUENT_LOG> instead
2021-06-21 06:49:19 +0000 [info]: #0 starting fluentd worker pid=30 ppid=21 worker=0
2021-06-21 06:49:19 +0000 [info]: #0 fluentd worker is now running worker=0
2021-06-21 06:49:19 +0000 [warn]: #0 no patterns matched tag="fluent.info"
2021-06-21 06:49:19 +0000 [warn]: #0 no patterns matched tag="fluent.info"
2021-06-21 06:49:20.038585800 +0000 sample: {"message":"sample","loaded":["/usr/lib/ruby/2.7.0/resolv.rb"]}
2021-06-21 06:49:21.042191300 +0000 sample: {"message":"sample","loaded":["/usr/lib/ruby/2.7.0/resolv.rb"]}
^C2021-06-21 06:49:21 +0000 [info]: Received graceful stop
2021-06-21 06:49:22.045774100 +0000 sample: {"message":"sample","loaded":["/usr/lib/ruby/2.7.0/resolv.rb"]}
2021-06-21 06:49:22 +0000 [info]: #0 fluentd worker is now stopping worker=0
2021-06-21 06:49:22 +0000 [info]: #0 shutting down fluentd worker worker=0
2021-06-21 06:49:22 +0000 [info]: #0 shutting down input plugin type=:sample plugin_id="object:71c"
2021-06-21 06:49:22 +0000 [info]: #0 shutting down filter plugin type=:record_modifier plugin_id="object:794"
2021-06-21 06:49:22 +0000 [info]: #0 shutting down output plugin type=:stdout plugin_id="object:708"
2021-06-21 06:49:22 +0000 [info]: Worker 0 finished with status 0

/ $ export RUBYLIB=/usr/lib/ruby/gems/2.7.0/gems/resolv-0.2.1/lib

/ $ /bin/entrypoint.sh fluentd -c /fluentd/etc/fluent.conf
fluentd -c /fluentd/etc/fluent.conf
2021-06-21 06:49:57 +0000 [info]: parsing config file is succeeded path="/fluentd/etc/fluent.conf"
2021-06-21 06:49:57 +0000 [info]: gem 'fluent-plugin-record-modifier' version '2.1.0'
2021-06-21 06:49:57 +0000 [info]: gem 'fluentd' version '1.13.0'
2021-06-21 06:49:57 +0000 [warn]: both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2021-06-21 06:49:57 +0000 [warn]: both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2021-06-21 06:49:57 +0000 [warn]: define <match fluent.**> to capture fluentd logs in top level is deprecated. Use <label @FLUENT_LOG> instead
2021-06-21 06:49:57 +0000 [info]: using configuration file: <ROOT>
  <source>
    @type sample
    tag "sample"
  </source>
  <filter>
    @type record_modifier
    remove_keys "_dummy_"
    <record>
      _dummy_ ${record['loaded'] = $LOADED_FEATURES.collect { |entry| entry if entry.include?('resolv.rb') }.compact }
    </record>
  </filter>
  <match sample>
    @type stdout
  </match>
</ROOT>
2021-06-21 06:49:57 +0000 [info]: starting fluentd-1.13.0 pid=34 ruby="2.7.3"
2021-06-21 06:49:57 +0000 [info]: spawn command to main:  cmdline=["/usr/bin/ruby", "-Eascii-8bit:ascii-8bit", "/usr/bin/fluentd", "-c", "/fluentd/etc/fluent.conf", "-p", "/fluentd/plugins", "--under-supervisor"]
2021-06-21 06:49:57 +0000 [info]: adding filter pattern="**" type="record_modifier"
2021-06-21 06:49:57 +0000 [info]: adding match pattern="sample" type="stdout"
2021-06-21 06:49:57 +0000 [info]: adding source type="sample"
2021-06-21 06:49:57 +0000 [warn]: #0 both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2021-06-21 06:49:57 +0000 [warn]: #0 both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2021-06-21 06:49:57 +0000 [warn]: #0 define <match fluent.**> to capture fluentd logs in top level is deprecated. Use <label @FLUENT_LOG> instead
2021-06-21 06:49:57 +0000 [info]: #0 starting fluentd worker pid=43 ppid=34 worker=0
2021-06-21 06:49:57 +0000 [info]: #0 fluentd worker is now running worker=0
2021-06-21 06:49:57 +0000 [warn]: #0 no patterns matched tag="fluent.info"
2021-06-21 06:49:57 +0000 [warn]: #0 no patterns matched tag="fluent.info"
2021-06-21 06:49:58.051154200 +0000 sample: {"message":"sample","loaded":["/usr/lib/ruby/gems/2.7.0/gems/resolv-0.2.1/lib/resolv.rb"]}
2021-06-21 06:49:59.053895900 +0000 sample: {"message":"sample","loaded":["/usr/lib/ruby/gems/2.7.0/gems/resolv-0.2.1/lib/resolv.rb"]}
^C2021-06-21 06:49:59 +0000 [info]: Received graceful stop
2021-06-21 06:50:00.057317400 +0000 sample: {"message":"sample","loaded":["/usr/lib/ruby/gems/2.7.0/gems/resolv-0.2.1/lib/resolv.rb"]}
2021-06-21 06:50:00 +0000 [info]: #0 fluentd worker is now stopping worker=0
2021-06-21 06:50:00 +0000 [info]: #0 shutting down fluentd worker worker=0
2021-06-21 06:50:00 +0000 [info]: #0 shutting down input plugin type=:sample plugin_id="object:71c"
2021-06-21 06:50:00 +0000 [info]: #0 shutting down filter plugin type=:record_modifier plugin_id="object:794"
2021-06-21 06:50:00 +0000 [info]: #0 shutting down output plugin type=:stdout plugin_id="object:708"
2021-06-21 06:50:01 +0000 [info]: Worker 0 finished with status 0

[kenhys]

Hmm, this glitches come from different kind of base image, so I've missed it.

A) base image: alpine

• GEM PATHS:
  • /usr/lib/ruby/gems/2.7.0
  • /home/fluent/.gem/ruby/2.7.0

B) base image: debian fluent/fluentd:v1.13.0-debian-1.0

• GEM PATHS:
  • /usr/local/bundle
  • /usr/local/lib/ruby/gems/2.6.0

[kenhys]

#278 will fix this issue.

[ncsibra]

Thanks for the quick fix!

[singhankush01]

Hi, I am getting similar issue. I don't know for sure if this is due to RUBYLIB is set wrong or what. I have been fluentd alpine current(edge) image.

2022-06-29 20:10:38 +0000 [info]: parsing config file is succeeded path="/fluentd/etc/fluent.conf"
2022-06-29 20:10:38 +0000 [info]: gem 'fluentd' version '1.14.6'
2022-06-29 20:10:38 +0000 [info]: using configuration file:
<source>
@type tail
tag "dmf"
read_from_head true
path "/logstore/log/example/stack/logBackupLink/dmf/log/pal.debug"
pos_file "/tmp/dmf.log.pos"
<parse>
@type "json"
unmatched_lines
</parse>
</source>
<match dmf>
@type stdout
</match>

2022-06-29 20:10:38 +0000 [info]: starting fluentd-1.14.6 pid=7 ruby="2.7.5"
2022-06-29 20:10:38 +0000 [info]: spawn command to main: cmdline=["/usr/bin/ruby", "-Eascii-8bit:ascii-8bit", "/usr/bin/fluentd", "--config", "/fluentd/etc/fluent.conf", "--plugin", "/fluentd/plugins", "--under-supervisor"]
2022-06-29 20:10:38 +0000 [info]: adding match pattern="dmf" type="stdout"
2022-06-29 20:10:38 +0000 [info]: adding source type="tail"
2022-06-29 20:10:38 +0000 [info]: #0 starting fluentd worker pid=16 ppid=7 worker=0
2022-06-29 20:10:38 +0000 [info]: #0 fluentd worker is now running worker=0

/ $ env
KUBERNETES_SERVICE_PORT=443
KUBERNETES_PORT=tcp://10.200.0.1:443
HOSTNAME=example
SHLVL=1
HOME=/home/fluent
FLUENTD_CONF=fluent.conf
TERM=xterm
KUBERNETES_PORT_443_TCP_ADDR=10.200.0.1
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
KUBERNETES_PORT_443_TCP_PORT=443
KUBERNETES_PORT_443_TCP_PROTO=tcp
fluent.conf=<source>
@type tail
tag dmf
read_from_head true
path /logstore/log/example/stack/logBackupLink/dmf/log/pal.debug
pos_file /tmp/dmf.log.pos
<parse>
@type json
</parse>
</source>
<match dmf>
@type stdout
</match>

LD_PRELOAD=
KUBERNETES_PORT_443_TCP=tcp://10.200.0.1:443
KUBERNETES_SERVICE_PORT_HTTPS=443
KUBERNETES_SERVICE_HOST=10.200.0.1
PWD=/

/ $ fluent-gem env
RubyGems Environment:

• RUBYGEMS VERSION: 3.1.6
• RUBY VERSION: 2.7.5 (2021-11-24 patchlevel 203) [x86_64-linux-musl]
• INSTALLATION DIRECTORY: /usr/lib/ruby/gems/2.7.0
• USER INSTALLATION DIRECTORY: /home/fluent/.gem/ruby/2.7.0
• RUBY EXECUTABLE: /usr/bin/ruby
• GIT EXECUTABLE:
• EXECUTABLE DIRECTORY: /usr/bin
• SPEC CACHE DIRECTORY: /home/fluent/.gem/specs
• SYSTEM CONFIGURATION DIRECTORY: /etc
• RUBYGEMS PLATFORMS:
  • ruby
• GEM PATHS:
  • /usr/lib/ruby/gems/2.7.0
  • /home/fluent/.gem/ruby/2.7.0
• GEM CONFIGURATION:
  • :update_sources => true
  • :verbose => true
  • :backtrace => false
  • :bulk_threshold => 1000
  • "gem" => "--no-document"
• REMOTE SOURCES:
  • https://rubygems.org/
• SHELL PATH:
  • /usr/local/sbin
  • /usr/local/bin
  • /usr/sbin
  • /usr/bin
  • /sbin
  • /bin