Bug 1465039

Summary: fluentd crashes when reading from journald after 3.4 to 3.5 upgrade
Product: OpenShift Container Platform Reporter: Sergi Jimenez Romero <sjr>
Component: LoggingAssignee: Noriko Hosoi <nhosoi>
Status: CLOSED CURRENTRELEASE QA Contact: Anping Li <anli>
Severity: high Docs Contact:
Priority: unspecified    
Version: 3.5.0CC: aos-bugs, cheimes, fcami, jcantril, nhosoi, pportant, pweil, rmeggins, saime, sjr, smunilla, wsun
Target Milestone: ---Keywords: Reopened, UpcomingRelease
Target Release: 3.9.z   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: rubygem-ffi-1.9.21-2.el7 Doc Type: Bug Fix
Doc Text:
fluent-plugin-systemd calls the C systemd library via ffi. In rubygem-ffi, there was a code which was not compatible with the PaX effort. The problem was if selinux deny_execmem is enabled, fluentd configured with journald was not allowed to start. The PaX uncompliant code was fixed and the problem is solved.
 Story Points: ---
Clone Of: Environment:
Last Closed: 2018-06-18 18:03:54 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Sergi Jimenez Romero 2017-06-26 13:11:13 UTC 
Description of problem:
After upgrading the platform to 3.5 from 3.4, fluentd crashes when using journald, switching docker back to json-file works.

Version-Release number of selected component (if applicable):

3.5

How reproducible:
Always (at customer infra).

Steps to Reproduce:
1. Upgrade logging stack
2. Fluentd crashes is left to use journald.

Actual results:
Fluentd crashes with the following logs:

+ fluentdargs=-vv
+ '[' '' '!=' false ']'
+ '[' -z '' ']'
+ '[' -d /var/log/journal ']'
+ export JOURNAL_SOURCE=/run/log/journal
+ JOURNAL_SOURCE=/run/log/journal
+ '[' -z '' ']'
+ docker_uses_journal
+ grep -q '^OPTIONS='\''[^'\'']*--log-driver=journald' /etc/sysconfig/docker
+ export USE_JOURNAL=true
+ USE_JOURNAL=true
++ /usr/sbin/ip -4 addr show dev eth0
++ grep inet
++ sed -e 's/[ \t]*inet \([0-9.]*\).*/\1/'
+ IPADDR4=10.130.0.35
++ /usr/sbin/ip -6 addr show dev eth0
++ grep inet6
++ sed 's/[ \t]*inet6 \([a-f0-9:]*\).*/\1/'
+ IPADDR6=fe80::7c07:33ff:feb5:9659
+ export IPADDR4 IPADDR6
+ CFG_DIR=/etc/fluent/configs.d
+ ruby generate_throttle_configs.rb
+ OPS_COPY_HOST=
+ OPS_COPY_PORT=
+ OPS_COPY_SCHEME=https
+ OPS_COPY_CLIENT_CERT=
+ OPS_COPY_CLIENT_KEY=
+ OPS_COPY_CA=
+ OPS_COPY_USERNAME=
+ OPS_COPY_PASSWORD=
+ export OPS_COPY_HOST OPS_COPY_PORT OPS_COPY_SCHEME OPS_COPY_CLIENT_CERT OPS_COPY_CLIENT_KEY OPS_COPY_CA OPS_COPY_USERNAME OPS_COPY_PASSWORD
+ '[' false = true ']'
+ echo
+ echo
+ exec fluentd -vv
2017-06-23 08:57:44 +0200 [info]: fluent/supervisor.rb:471:read_config: reading config file path="/etc/fluent/fluent.conf"
2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:378:rescue in main_process: unexpected error error="x\xBC\xF2\xBA\xA6\x7F"
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/ffi-1.9.17/lib/ffi/library.rb:277:in `attach'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/ffi-1.9.17/lib/ffi/library.rb:277:in `attach_function'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/systemd-journal-1.2.3/lib/systemd/id128.rb:51:in `<module:Native>'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/systemd-journal-1.2.3/lib/systemd/id128.rb:45:in `<module:Id128>'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/systemd-journal-1.2.3/lib/systemd/id128.rb:6:in `<module:Systemd>'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/systemd-journal-1.2.3/lib/systemd/id128.rb:3:in `<top (required)>'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/systemd-journal-1.2.3/lib/systemd/journal/native.rb:1:in `<top (required)>'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/systemd-journal-1.2.3/lib/systemd/journal.rb:2:in `<top (required)>'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:135:in `require'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:135:in `rescue in require'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:144:in `require'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluent-plugin-systemd-0.0.6/lib/fluent/plugin/in_systemd.rb:1:in `<top (required)>'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/plugin.rb:172:in `block in try_load_plugin'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/plugin.rb:170:in `each'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/plugin.rb:170:in `try_load_plugin'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/plugin.rb:130:in `new_impl'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/plugin.rb:55:in `new_input'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/root_agent.rb:149:in `add_source'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/root_agent.rb:95:in `block in configure'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/root_agent.rb:92:in `each'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/root_agent.rb:92:in `configure'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/engine.rb:129:in `configure'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/engine.rb:103:in `run_configure'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:489:in `run_configure'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:160:in `block in start'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:366:in `call'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:366:in `main_process'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:339:in `block in supervise'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:338:in `fork'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:338:in `supervise'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:156:in `start'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/lib/fluent/command/fluentd.rb:173:in `<top (required)>'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/share/gems/gems/fluentd-0.12.31/bin/fluentd:5:in `<top (required)>'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/bin/fluentd:23:in `load'
  2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:338:fork: /usr/bin/fluentd:23:in `<main>'
2017-06-23 08:57:52 +0200 [error]: fluent/supervisor.rb:165:start: fluentd main process died unexpectedly. restarting.

Expected results:
Fluentd should work.

Additional info:
Comment 15 Rich Megginson 2017-07-12 16:51:05 UTC 
If you rsh into the fluentd pod, can you use journalctl to view the journal logs?
Comment 19 Rich Megginson 2017-07-17 17:20:29 UTC 
journalctl should be using the exact same libraries as fluentd to read from the journal.  I'm at a loss to explain this.  Perhaps it is some sort of LANG or LOCALE env. var. or other setting?
Comment 20 Noriko Hosoi 2017-07-17 17:56:52 UTC 
Could there be any way to check the library dependency on a ruby module?  Something equivalent to ldd?
Comment 21 Rich Megginson 2017-07-17 18:00:03 UTC 
(In reply to Noriko Hosoi from comment #20)
> Could there be any way to check the library dependency on a ruby module? 
> Something equivalent to ldd?

If a ruby module wraps a C shared library, those files will be listed e.g. rpm -ql rubygem-systemd-journal.  One or more of those files will be a .so.  Then you can use ldd on those .so files.
Comment 34 Noriko Hosoi 2017-08-16 19:37:28 UTC 
Hi François, 
Could you please find out the version of libffi on the fluentd pod?

# oc exec $FLUENTDPOD -- rpm -q libffi
libffi-3.0.13-18.el7.x86_64
# oc exec $FLUENTDPOD -- rpm -ql libffi
/usr/lib64/libffi.so.6
/usr/lib64/libffi.so.6.0.1
/usr/share/doc/libffi-3.0.13
/usr/share/doc/libffi-3.0.13/LICENSE
/usr/share/doc/libffi-3.0.13/README
Comment 35 François Cami 2017-08-21 07:29:26 UTC 
Hi Noriko,

Here is the data:

$ oc exec logging-fluentd-fhqpg -- rpm -q libffi
libffi-3.0.13-18.el7.x86_64

$ oc exec logging-fluentd-fhqpg -- rpm -ql libffi
/usr/lib64/libffi.so.6
/usr/lib64/libffi.so.6.0.1
/usr/share/doc/libffi-3.0.13
/usr/share/doc/libffi-3.0.13/LICENSE
/usr/share/doc/libffi-3.0.13/README

$ oc exec logging-fluentd-fhqpg -- rpm -V libffi
$
Comment 36 Noriko Hosoi 2017-08-30 22:31:19 UTC 
Thank you, François.  libffi looks flawless...

Could you please try one more thing?  When you switch the input to journald, could you set this environment variable DEFAULT_ENCODING to ASCII-8BIT?

oc set env daemonset logging-fluentd DEFAULT_ENCODING=ASCII-8BIT
Comment 38 François Cami 2017-09-08 15:38:05 UTC 
Hi Noriko,
We've tried and it doesn't change anything apparently.
Comment 73 Anping Li 2018-02-23 15:16:12 UTC 
Pass on logging-fluentd/images/v3.9.0-0.50.0.0
Comment 74 Jeff Cantrill 2018-03-22 02:05:52 UTC 
https://github.com/openshift/origin-aggregated-logging/pull/940