Bug 1703904

Summary:	[release-3.11] Fix typo of random_string that prevents forwarding to SYSLOG via UDP to fail
Product:	OpenShift Container Platform	Reporter:	Jatan Malde <jmalde>
Component:	Logging	Assignee:	Noriko Hosoi <nhosoi>
Status:	CLOSED ERRATA	QA Contact:	Anping Li <anli>
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	3.11.0	CC:	anli, aos-bugs, jcantril, pweil, rmeggins, wsun
Target Milestone:	---
Target Release:	3.11.z
Hardware:	x86_64
OS:	All
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:	Cause: 1) There was a missing '@' for an instance variable in the fleuntd remote syslog plugin code. 2) There were some cases that systemd-journald logged non-decimal facility values. Consequence: 1) Forwarding logs to remote rsyslog via UDP failed. 2) Forwarding a log record including a non-digital facility value failed regardless of the network protocol. Fix: 1) The missing '@' was added. 2) The fluentd remote syslog plugin checks the facility value. If the value is not in the defined value set, it resets to the default value. Result: Forwarding logs remote rsyslog do not fail.	Story Points:	---
Clone Of:
Clones:	1707538 1707899 (view as bug list)		Environment:
Last Closed:	2019-06-26 09:08:09 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:
Bug Depends On:
Bug Blocks:	1707538, 1707899, 1707901

Description Jatan Malde 2019-04-29 04:19:11 UTC

Description of problem:

Please include the following PR to the downstream images.

   https://github.com/openshift/origin-aggregated-logging/pull/1584

To fix this error:

[warn]: emit transaction failed: error_class=NameError error="undefined local variable or method `random_string' for #<Fluent::SyslogOutput:0x007f553ed585c8>" location="/etc/fluent/plugin/out_syslog.rb:126:in `block in emit'"


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


How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Comment 1 Paul Weil 2019-04-29 11:45:20 UTC

PR is merged, moving to MODIFIED

Comment 3 Anping Li 2019-05-06 09:09:26 UTC

The out_rsyslog failed with the following error.

Steps:
1.  Create a rsyslog server in openshift-logging namespace as cluster admin
https://raw.githubusercontent.com/openshift-qe/v3-testfiles/master/logging/rsyslogserver/01_createsa.sh
oc create -f https://raw.githubusercontent.com/openshift-qe/v3-testfiles/master/logging/rsyslogserver/02_rsyslogserver.yaml
oc new-app rsyslogserver-template -p NAME=rsyslogserver
2. Patch the fluentd configmap to send log via out_rsyslog
https://github.com/openshift-qe/v3-testfiles/blob/master/logging/rsyslogserver/03_patchcm.sh

3. Check the fluentd logs
oc exec fluentd-4s9jr -- logs


2019-05-06 08:56:04 +0000 [warn]: [container-input] 'encoding' and 'from_encoding' are same encoding. No effect
2019-05-06 08:56:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="'DEVICE' is not a designated facility" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/syslog_protocol-0.9.2/lib/syslog_protocol/packet.rb:37:in `facility='" tag="output_tag"
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/syslog_protocol-0.9.2/lib/syslog_protocol/packet.rb:37:in `facility='
  2019-05-06 08:56:06 +0000 [warn]: /etc/fluent/plugin/out_syslog.rb:82:in `block in emit'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/event.rb:193:in `block in each'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/event.rb:192:in `each'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/event.rb:192:in `each'
  2019-05-06 08:56:06 +0000 [warn]: /etc/fluent/plugin/out_syslog.rb:70:in `emit'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/compat/output.rb:164:in `process'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/plugin/output.rb:782:in `emit_sync'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/plugin/out_copy.rb:58:in `block in process'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/plugin/out_copy.rb:56:in `each'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/plugin/out_copy.rb:56:in `each_with_index'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/plugin/out_copy.rb:56:in `process'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/plugin/multi_output.rb:148:in `emit_sync'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/event_router.rb:96:in `emit_stream'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluent-plugin-rewrite-tag-filter-2.2.0/lib/fluent/plugin/out_rewrite_tag_filter.rb:85:in `block in process'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluent-plugin-rewrite-tag-filter-2.2.0/lib/fluent/plugin/out_rewrite_tag_filter.rb:84:in `each'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluent-plugin-rewrite-tag-filter-2.2.0/lib/fluent/plugin/out_rewrite_tag_filter.rb:84:in `process'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/plugin/output.rb:782:in `emit_sync'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/event_router.rb:159:in `emit_events'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/event_router.rb:96:in `emit_stream'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluent-plugin-rewrite-tag-filter-2.2.0/lib/fluent/plugin/out_rewrite_tag_filter.rb:85:in `block in process'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluent-plugin-rewrite-tag-filter-2.2.0/lib/fluent/plugin/out_rewrite_tag_filter.rb:84:in `each'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluent-plugin-rewrite-tag-filter-2.2.0/lib/fluent/plugin/out_rewrite_tag_filter.rb:84:in `process'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/plugin/output.rb:782:in `emit_sync'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/event_router.rb:96:in `emit_stream'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/event_router.rb:87:in `emit'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluent-plugin-systemd-1.0.2/lib/fluent/plugin/in_systemd.rb:115:in `emit'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluent-plugin-systemd-1.0.2/lib/fluent/plugin/in_systemd.rb:110:in `block in run'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluent-plugin-systemd-1.0.2/lib/fluent/plugin/in_systemd.rb:135:in `yield_current_entry'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluent-plugin-systemd-1.0.2/lib/fluent/plugin/in_systemd.rb:131:in `watch'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluent-plugin-systemd-1.0.2/lib/fluent/plugin/in_systemd.rb:109:in `run'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/plugin_helper/timer.rb:80:in `on_timer'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/cool.io-1.5.3/lib/cool.io/loop.rb:88:in `run_once'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/cool.io-1.5.3/lib/cool.io/loop.rb:88:in `run'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
  2019-05-06 08:56:06 +0000 [warn]: /opt/rh/rh-ruby25/root/usr/local/share/gems/gems/fluentd-1.4.1/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2019-05-06 08:56:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="'DEVICE' is not a designated facility" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/syslog_protocol-0.9.2/lib/syslog_protocol/packet.rb:37:in `facility='" tag="journal.system"
  2019-05-06 08:56:06 +0000 [warn]: suppressed same stacktrace
2019-05-06 08:56:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="'DEVICE' is not a designated facility" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/syslog_protocol-0.9.2/lib/syslog_protocol/packet.rb:37:in `facility='" tag="journal"
  2019-05-06 08:56:06 +0000 [warn]: suppressed same stacktrace
2019-05-06 08:56:06 +0000 [error]: [systemd-input] Exception emitting record: 'DEVICE' is not a designated facility
2019-05-06 08:56:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="'DEVICE' is not a designated facility" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/syslog_protocol-0.9.2/lib/syslog_protocol/packet.rb:37:in `facility='" tag="output_tag"
  2019-05-06 08:56:06 +0000 [warn]: suppressed same stacktrace
2019-05-06 08:56:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="'DEVICE' is not a designated facility" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/syslog_protocol-0.9.2/lib/syslog_protocol/packet.rb:37:in `facility='" tag="journal.system"
  2019-05-06 08:56:06 +0000 [warn]: suppressed same stacktrace
2019-05-06 08:56:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="'DEVICE' is not a designated facility" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/syslog_protocol-0.9.2/lib/syslog_protocol/packet.rb:37:in `facility='" tag="journal"
  2019-05-06 08:56:06 +0000 [warn]: suppressed same stacktrace
2019-05-06 08:56:06 +0000 [error]: [systemd-input] Exception emitting record: 'DEVICE' is not a designated facility
2019-05-06 08:56:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="'DEVICE' is not a designated facility" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/syslog_protocol-0.9.2/lib/syslog_protocol/packet.rb:37:in `facility='" tag="output_tag"
  2019-05-06 08:56:06 +0000 [warn]: suppressed same stacktrace
2019-05-06 08:56:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="'DEVICE' is not a designated facility" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/syslog_protocol-0.9.2/lib/syslog_protocol/packet.rb:37:in `facility='" tag="journal.system"
  2019-05-06 08:56:06 +0000 [warn]: suppressed same stacktrace
2019-05-06 08:56:06 +0000 [warn]: emit transaction failed: error_class=ArgumentError error="'DEVICE' is not a designated facility" location="/opt/rh/rh-ruby25/root/usr/local/share/gems/gems/syslog_protocol-0.9.2/lib/syslog_protocol/packet.rb:37:in `facility='" tag="journal"
  2019-05-06 08:56:06 +0000 [warn]: suppressed same stacktrace
2019-05-06 08:56:06 +0000 [error]: [systemd-input] Exception emitting record: 'DEVICE' is not a designated facility

Comment 4 Rich Megginson 2019-05-06 13:42:52 UTC

I notice on my fedora system that the SYSLOG_FACILITY field from the journal can have non-numeric values - I see one that has SYSLOG_FACILITY=DHCP4 - I haven't seen one that has SYSLOG_FACILITY=DEVICE but it would appear that this is what is happening.

@anping - try this on the fluentd node:

journalctl -m -o export | grep SYSLOG_FACILITY= | grep -v 'SYSLOG_FACILITY=[0-9]'

Comment 5 Noriko Hosoi 2019-05-06 20:02:09 UTC

Hmmm, then this man page is not valid... :(

   man systemd.journal-fields

       SYSLOG_FACILITY=, SYSLOG_IDENTIFIER=, SYSLOG_PID=
           Syslog compatibility fields containing the facility (formatted as decimal string), the identifier string
           (i.e. "tag"), and the client PID. (Note that the tag is usually derived from glibc's
           program_invocation_short_name variable, see program_invocation_short_name(3).)

Comment 6 Rich Megginson 2019-05-06 20:13:11 UTC

(In reply to Noriko Hosoi from comment #5)
> Hmmm, then this man page is not valid... :(
> 
>    man systemd.journal-fields
> 
>        SYSLOG_FACILITY=, SYSLOG_IDENTIFIER=, SYSLOG_PID=
>            Syslog compatibility fields containing the facility (formatted as
> decimal string), the identifier string
>            (i.e. "tag"), and the client PID. (Note that the tag is usually
> derived from glibc's
>            program_invocation_short_name variable, see
> program_invocation_short_name(3).)

Then it may be a bug in journald, that it does not sanitize input, and there are some misbehaving apps writing invalid data in the SYSLOG_FACILITY field.  But at any rate, we have to handle it in the remote syslog fluentd code, or at least not crash.  Not sure what value to use when SYSLOG_FACILITY is invalid - let's use 23 'local7' as the value.

For example, on a Fedora 29 system, I see the following:

sudo journalctl -m -o export | grep SYSLOG_FACILITY= | grep -v 'SYSLOG_FACILITY=[0-9]' | sort -u
SYSLOG_FACILITY=CORE
SYSLOG_FACILITY=DEVICE
SYSLOG_FACILITY=DHCP4
SYSLOG_FACILITY=DHCP6
SYSLOG_FACILITY=DNS
SYSLOG_FACILITY=RFKILL
SYSLOG_FACILITY=SETTINGS

Comment 7 Noriko Hosoi 2019-05-06 20:57:58 UTC

It seems syslog_protocol we depend on is not up-to-date...  It only supports this limited keys...

https://github.com/eric/syslog_protocol/blob/master/lib/syslog_protocol/common.rb

Comment 8 Rich Megginson 2019-05-06 21:16:06 UTC

(In reply to Noriko Hosoi from comment #7)
> It seems syslog_protocol we depend on is not up-to-date...  It only supports
> this limited keys...
> 
> https://github.com/eric/syslog_protocol/blob/master/lib/syslog_protocol/
> common.rb

I think that is up-to-date.  I think facility is supposed to be a numeric value.  I think the problem is not in the syslog_protocol code, I think the problem is that systemd journald is not sanitizing the inputs, that there is a bug in the systemd journald code.

We can fix it in https://github.com/eric/syslog_protocol/blob/master/lib/syslog_protocol/ by making it default to one of the numeric values if it gets an invalid value.  But I think they would say "please sanitize your data _before_ passing it to this code".  So I think we should fix our fluentd/out_syslog.rb and fluentd/out_syslog_buffered.rb.

You could either check the value before calling `facility=`, or wrap the call to `facility=` in a begin/except block, and call `facility=` again with a valid numeric value if the first call to `facility=` throws ArgumentError.

Comment 9 Noriko Hosoi 2019-05-06 21:25:05 UTC

(In reply to Rich Megginson from comment #8)
> (In reply to Noriko Hosoi from comment #7)
> > It seems syslog_protocol we depend on is not up-to-date...  It only supports
> > this limited keys...
> > 
> > https://github.com/eric/syslog_protocol/blob/master/lib/syslog_protocol/
> > common.rb
> 
> I think that is up-to-date.  I think facility is supposed to be a numeric
> value.  I think the problem is not in the syslog_protocol code, I think the
> problem is that systemd journald is not sanitizing the inputs, that there is
> a bug in the systemd journald code.

Do you think we should file a bug?

> We can fix it in
> https://github.com/eric/syslog_protocol/blob/master/lib/syslog_protocol/ by
> making it default to one of the numeric values if it gets an invalid value. 
> But I think they would say "please sanitize your data _before_ passing it to
> this code".  So I think we should fix our fluentd/out_syslog.rb and
> fluentd/out_syslog_buffered.rb.

Yes.  That's much easier for now.  Let me work on it.

> You could either check the value before calling `facility=`, or wrap the
> call to `facility=` in a begin/except block, and call `facility=` again with
> a valid numeric value if the first call to `facility=` throws ArgumentError.

Comment 10 Rich Megginson 2019-05-07 00:43:17 UTC

(In reply to Noriko Hosoi from comment #9)
> (In reply to Rich Megginson from comment #8)
> > (In reply to Noriko Hosoi from comment #7)
> > > It seems syslog_protocol we depend on is not up-to-date...  It only supports
> > > this limited keys...
> > > 
> > > https://github.com/eric/syslog_protocol/blob/master/lib/syslog_protocol/
> > > common.rb
> > 
> > I think that is up-to-date.  I think facility is supposed to be a numeric
> > value.  I think the problem is not in the syslog_protocol code, I think the
> > problem is that systemd journald is not sanitizing the inputs, that there is
> > a bug in the systemd journald code.
> 
> Do you think we should file a bug?

https://bugzilla.redhat.com/show_bug.cgi?id=1707175

> 
> > We can fix it in
> > https://github.com/eric/syslog_protocol/blob/master/lib/syslog_protocol/ by
> > making it default to one of the numeric values if it gets an invalid value. 
> > But I think they would say "please sanitize your data _before_ passing it to
> > this code".  So I think we should fix our fluentd/out_syslog.rb and
> > fluentd/out_syslog_buffered.rb.
> 
> Yes.  That's much easier for now.  Let me work on it.
> 
> > You could either check the value before calling `facility=`, or wrap the
> > call to `facility=` in a begin/except block, and call `facility=` again with
> > a valid numeric value if the first call to `facility=` throws ArgumentError.

Comment 11 Noriko Hosoi 2019-05-07 17:30:58 UTC

https://github.com/openshift/origin-aggregated-logging/pull/1629 (ocp4.1; will be backported to 3.11, as well)

Comment 12 Noriko Hosoi 2019-05-08 16:09:42 UTC

(In reply to Noriko Hosoi from comment #11)
> https://github.com/openshift/origin-aggregated-logging/pull/1629 (ocp4.1;
> will be backported to 3.11, as well)

3.11 - https://github.com/openshift/origin-aggregated-logging/pull/1636

Comment 15 Anping Li 2019-06-13 05:21:48 UTC

The log can be sent out via out_rsyslog using openshift3/ose-logging-fluentd:v3.11.117

Comment 17 errata-xmlrpc 2019-06-26 09:08:09 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2019:1605