1465039 – fluentd crashes when reading from journald after 3.4 to 3.5 upgrade

Bug 1465039 - fluentd crashes when reading from journald after 3.4 to 3.5 upgrade

Summary: fluentd crashes when reading from journald after 3.4 to 3.5 upgrade

Keywords:
Status:	CLOSED CURRENTRELEASE
Alias:	None
Product:	OpenShift Container Platform
Classification:	Red Hat
Component:	Logging
Sub Component:
Version:	3.5.0
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	high
Target Milestone:	---
Target Release:	3.9.z
Assignee:	Noriko Hosoi
QA Contact:	Anping Li
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2017-06-26 13:11 UTC by Sergi Jimenez Romero
Modified:	2021-09-09 12:23 UTC (History)
CC List:	12 users (show)
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.
Clone Of:
Environment:
Last Closed:	2018-06-18 18:03:54 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

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

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