Bug 1465039 - fluentd crashes when reading from journald after 3.4 to 3.5 upgrade
fluentd crashes when reading from journald after 3.4 to 3.5 upgrade
Status: ON_QA
Product: OpenShift Container Platform
Classification: Red Hat
Component: Logging (Show other bugs)
3.5.0
Unspecified Unspecified
unspecified Severity high
: ---
: 3.9.z
Assigned To: Noriko Hosoi
Anping Li
: Reopened, UpcomingRelease
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2017-06-26 09:11 EDT by Sergi Jimenez Romero
Modified: 2018-02-14 14:05 EST (History)
11 users (show)

See Also:
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-01-18 14:54:06 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Sergi Jimenez Romero 2017-06-26 09:11:13 EDT
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 12:51:05 EDT
If you rsh into the fluentd pod, can you use journalctl to view the journal logs?
Comment 19 Rich Megginson 2017-07-17 13:20:29 EDT
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 13:56:52 EDT
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 14:00:03 EDT
(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 15:37:28 EDT
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 03:29:26 EDT
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 18:31:19 EDT
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 11:38:05 EDT
Hi Noriko,
We've tried and it doesn't change anything apparently.

Note You need to log in before you can comment on or make changes to this bug.