Hide Forgot
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:
PR is merged, moving to MODIFIED
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
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]'
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).)
(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
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
(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.
(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.
(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.
https://github.com/openshift/origin-aggregated-logging/pull/1629 (ocp4.1; will be backported to 3.11, as well)
(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
The log can be sent out via out_rsyslog using openshift3/ose-logging-fluentd:v3.11.117
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