Bug 1519213 - NoMethodError if remote_syslog enabled remote_syslog_tag_key
Summary: NoMethodError if remote_syslog enabled remote_syslog_tag_key
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Logging
Version: 3.7.0
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ---
: 3.7.z
Assignee: Noriko Hosoi
QA Contact: Anping Li
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-11-30 12:03 UTC by Anping Li
Modified: 2018-01-23 17:58 UTC (History)
5 users (show)

Fixed In Version: openshift3/logging-fluentd:v3.7.16-4
Doc Type: Bug Fix
Doc Text:
The remote-syslog plugin in fluentd takes a configuration parameter tag_key to use the field specified in tag_key from record to set the syslog key. When a field specified in tag_key does not exist, it caused ruby exception which was not caught. The bug was fixed so that if the field does not exist, tag_key is ignored and the default tag is used.
Clone Of:
Environment:
Last Closed: 2018-01-23 17:58:09 UTC
Target Upstream Version:


Attachments (Terms of Use)
A preliminary patch to handle tag_key. (3.92 KB, patch)
2017-11-30 23:02 UTC, Noriko Hosoi
no flags Details | Diff
tag_key -> @tag_key (1.97 KB, patch)
2017-12-06 02:00 UTC, Noriko Hosoi
no flags Details | Diff


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2018:0113 normal SHIPPED_LIVE OpenShift Container Platform 3.7 and 3.6 bug fix and enhancement update 2018-01-23 22:55:59 UTC

Description Anping Li 2017-11-30 12:03:02 UTC
Description of problem:
NoMethodError if we set openshift_logging_fluentd_remote_syslog_tag_key. It seems we should use tag_key rather than record[tag_key].


/etc/fluent/plugin/out_syslog.rb
81         @packet.tag      = if tag_key
82                               record[tag_key][0..31].gsub(/[\[\]]/,'') # tag is trimmed to 32 chars for syslog_protocol gem compatibility


Version-Release number of selected component (if applicable):
logging-fluentd/images/v3.7.9-21

How reproducible:
always

Steps to Reproduce:
1) deploy logging with rsyslog
openshift_logging_install_logging=true
openshift_logging_image_version=v3.7
openshift_logging_namespace=logging
openshift_logging_es_cluster_size=1
openshift_logging_es_memory_limit=2Gi

openshift_logging_fluentd_remote_syslog=true
openshift_logging_fluentd_remote_syslog_host=192.168.1.221
openshift_logging_fluentd_remote_syslog_tag_key=tagkey1
2) waiting for about 1 minute

3) oc logs logging-fluentd-zqcll


Actual results:
[root@host3-ha-master-1 ~]# oc logs logging-fluentd-zqcll
umounts of dead containers will fail. Ignoring...
umount: /var/lib/docker/containers/118847ce7a1e3c2c61ad360815648f147445defbd10e7105c81fb9090b687433/shm: not mounted
umount: /var/lib/docker/containers/2ab90b75849fea48904cb229c85ebc14700930c2ba012c58efbd128eece26222/shm: not mounted
umount: /var/lib/docker/containers/54ff785cd20b7107f69acae0e3fea4690aa15e8ac8577e484052a813e3951f7d/shm: not mounted
umount: /var/lib/docker/containers/9d266dead6e1e1607440268ef6231b283d357c6472169131b6a23bda55ceb574/shm: not mounted
2017-11-30 06:52:12 -0500 [info]: reading config file path="/etc/fluent/fluent.conf"
2017-11-30 06:52:13 -0500 [warn]: 'block' action stops input process until the buffer full is resolved. Check your pipeline this action is fit or not
2017-11-30 06:52:13 -0500 [warn]: /var/log/containers/logging-fluentd-zqcll_logging_fluentd-elasticsearch-82e2dfd9571da73eb884ab49cb36bd0a9f8697cfd561d53042ed163fee4cba33.log unreadable. It is excluded and would be examined next time.
2017-11-30 06:53:14 -0500 [warn]: temporarily failed to flush the buffer. next_retry=2017-11-30 06:53:15 -0500 error_class="NoMethodError" error="undefined method `[]' for nil:NilClass" plugin_id="object:1483ba8"
  2017-11-30 06:53:14 -0500 [warn]: /etc/fluent/plugin/out_syslog_buffered.rb:106:in `send_to_syslog'
  2017-11-30 06:53:14 -0500 [warn]: /etc/fluent/plugin/out_syslog_buffered.rb:85:in `block in write'
  2017-11-30 06:53:14 -0500 [warn]: /usr/share/gems/gems/fluentd-0.12.39/lib/fluent/plugin/buf_memory.rb:67:in `feed_each'
  2017-11-30 06:53:14 -0500 [warn]: /usr/share/gems/gems/fluentd-0.12.39/lib/fluent/plugin/buf_memory.rb:67:in `msgpack_each'
  2017-11-30 06:53:14 -0500 [warn]: /etc/fluent/plugin/out_syslog_buffered.rb:84:in `write'
  2017-11-30 06:53:14 -0500 [warn]: /usr/share/gems/gems/fluentd-0.12.39/lib/fluent/buffer.rb:354:in `write_chunk'
  2017-11-30 06:53:14 -0500 [warn]: /usr/share/gems/gems/fluentd-0.12.39/lib/fluent/buffer.rb:333:in `pop'
  2017-11-30 06:53:14 -0500 [warn]: /usr/share/gems/gems/fluentd-0.12.39/lib/fluent/output.rb:342:in `try_flush'
  2017-11-30 06:53:14 -0500 [warn]: /usr/share/gems/gems/fluentd-0.12.39/lib/fluent/output.rb:149:in `run'
2017-11-30 06:53:15 -0500 [warn]: temporarily failed to flush the buffer. next_retry=2017-11-30 06:53:16 -0500 error_class="NoMethodError" error="undefined method `[]' for nil:NilClass" plugin_id="object:1483ba8"
  2017-11-30 06:53:15 -0500 [warn]: suppressed same stacktrace
2017-11-30 06:53:16 -0500 [warn]: temporarily failed to flush the buffer. next_retry=2017-11-30 06:53:21 -0500 error_class="NoMethodError" error="undefined method `[]' for nil:NilClass" plugin_id="object:1483ba8"
  2017-11-30 06:53:16 -0500 [warn]: suppressed same stacktrace
2017-11-30 06:53:21 -0500 [warn]: temporarily failed to flush the buffer. next_retry=2017-11-30 06:53:28 -0500 error_class="NoMethodError" error="undefined method `[]' for nil:NilClass" plugin_id="object:1483ba8"
  2017-11-30 06:53:21 -0500 [warn]: suppressed same stacktrace
2017-11-30 06:53:28 -0500 [warn]: temporarily failed to flush the buffer. next_retry=2017-11-30 06:53:45 -0500 error_class="NoMethodError" error="undefined method `[]' for nil:NilClass" plugin_id="object:1483ba8"
  2017-11-30 06:53:28 -0500 [warn]: suppressed same stacktrace
2017-11-30 06:53:45 -0500 [warn]: temporarily failed to flush the buffer. next_retry=2017-11-30 06:54:16 -0500 error_class="NoMethodError" error="undefined method `[]' for nil:NilClass" plugin_id="object:1483ba8"
  2017-11-30 06:53:45 -0500 [warn]: suppressed same stacktrace
2017-11-30 06:54:16 -0500 [warn]: temporarily failed to flush the buffer. next_retry=2017-11-30 06:55:26 -0500 error_class="NoMethodError" error="undefined method `[]' for nil:NilClass" plugin_id="object:1483ba8"
  2017-11-30 06:54:16 -0500 [warn]: suppressed same stacktrace


Expected results:

No error, the log can be sent to rsyslog, the tag is set to tagkey1

Additional info:

Comment 1 Noriko Hosoi 2017-11-30 23:00:18 UTC
Reading 
fluent-plugin-remote-syslog/lib/fluentd/plugin/{out_syslog,out_syslog_buffered}.rb, the code around tag_key looks indeed odd.

In our generate_syslog_config.rb, we do not use record.
 23       ['USE_RECORD', 'use_record', nil],

Thus, we should not refer record for tag_key.  But as Anping pointed out, it's done in {out_syslog,out_syslog_buffered}.rb.

The suggestion by Anping might be sufficient, but it looks to me treating tag_key in the plugin is half-baked.  Appending a preliminary patch to this bug next.  (Since I'm not good at Ruby, I'd like to have someone to take a look and fix it...)

Then, I'd think we should submit a pr or an issue to:
https://github.com/docebo/fluent-plugin-remote-syslog/

Comment 2 Noriko Hosoi 2017-11-30 23:02:04 UTC
Created attachment 1361347 [details]
A preliminary patch to handle tag_key.

Comment 3 Rich Megginson 2017-11-30 23:12:46 UTC
I don't understand.
https://github.com/docebo/fluent-plugin-remote-syslog#fluent-plugin-remote-syslog

    use_record: Use severity and facility from record if available

use_record doesn't have anything to do with the tag or tag_key.  I think the problem is that the code is using `tag_key` instead of `@tag_key`.  I think the solution is to use `@tag_key` instead of `tag_key` in the code.

And yes, this looks like an issue with the fluent plugin.

Comment 4 Noriko Hosoi 2017-11-30 23:17:23 UTC
(In reply to Rich Megginson from comment #3)
> I don't understand.
> https://github.com/docebo/fluent-plugin-remote-syslog#fluent-plugin-remote-
> syslog
> 
>     use_record: Use severity and facility from record if available
Ahhh, ok.  Thanks, Rich.

> 
> use_record doesn't have anything to do with the tag or tag_key.  I think the
> problem is that the code is using `tag_key` instead of `@tag_key`.  I think
> the solution is to use `@tag_key` instead of `tag_key` in the code.

You mean this change would fix the problem?

@@ -102,8 +102,8 @@ module Fluent
         time = Time.now
       end
       @packet.time = time
-      @packet.tag      = if tag_key
-                           record[tag_key][0..31].gsub(/[\[\]]/,'') # tag is trimmed to 32 chars for syslog_protocol gem compatibility
+      @packet.tag      = if @tag_key
+                           record[@tag_key][0..31].gsub(/[\[\]]/,'') # tag is trimmed to 32 chars for syslog_protocol gem compatibility
                          else
                            tag[0..31] # tag is trimmed to 32 chars for syslog_protocol gem compatibility
                          end

> 
> And yes, this looks like an issue with the fluent plugin.

Comment 5 Noriko Hosoi 2017-11-30 23:18:45 UTC
Oops, is this needed, as well?

@@ -35,6 +35,7 @@ module Fluent
       if remove_tag_prefix = conf['remove_tag_prefix']
         @remove_tag_prefix = Regexp.new('^' + Regexp.escape(remove_tag_prefix))
       end
+      @tag_key = conf['tag_key']

Comment 6 Rich Megginson 2017-11-30 23:41:13 UTC
(In reply to Noriko Hosoi from comment #4)
> (In reply to Rich Megginson from comment #3)
> > I don't understand.
> > https://github.com/docebo/fluent-plugin-remote-syslog#fluent-plugin-remote-
> > syslog
> > 
> >     use_record: Use severity and facility from record if available
> Ahhh, ok.  Thanks, Rich.
> 
> > 
> > use_record doesn't have anything to do with the tag or tag_key.  I think the
> > problem is that the code is using `tag_key` instead of `@tag_key`.  I think
> > the solution is to use `@tag_key` instead of `tag_key` in the code.
> 
> You mean this change would fix the problem?

Yes.  The error is this:

error_class="NoMethodError" error="undefined method `[]' for nil:NilClass"

This is coming from here: record[tag_key][0..31].gsub....

This means `record[tag_key]` evaluates to `nil`, and the error is that you cannot access `nil[something]` because `nil` is not an `Array`.

The thing that puzzles me is - what does `tag_key` evaluate to?  It must evaluate to something in order to hit the error.

Maybe there is some legacy code in the fluentd plugin that allows you to use `tag_key` instead of `@tag_key`?  You could put some debugging prints in there to find out.

If `tag_key` evaluates to `@tag_key`, then the problem is that there is no field  with the value of `tag_key`.  I guess the code assumes that if you specify `tag_key something` in the config, then the field `something` will _always_ be present in _every_ record.  If `tag_key` evaluates to some random value, then the problem is the same `record[tag_key]` is `nil`.


> 
> @@ -102,8 +102,8 @@ module Fluent
>          time = Time.now
>        end
>        @packet.time = time
> -      @packet.tag      = if tag_key
> -                           record[tag_key][0..31].gsub(/[\[\]]/,'') # tag
> is trimmed to 32 chars for syslog_protocol gem compatibility
> +      @packet.tag      = if @tag_key
> +                           record[@tag_key][0..31].gsub(/[\[\]]/,'') # tag
> is trimmed to 32 chars for syslog_protocol gem compatibility
>                           else
>                             tag[0..31] # tag is trimmed to 32 chars for
> syslog_protocol gem compatibility
>                           end
> 
> > 
> > And yes, this looks like an issue with the fluent plugin.

Comment 7 Rich Megginson 2017-11-30 23:41:48 UTC
(In reply to Noriko Hosoi from comment #5)
> Oops, is this needed, as well?
> 
> @@ -35,6 +35,7 @@ module Fluent
>        if remove_tag_prefix = conf['remove_tag_prefix']
>          @remove_tag_prefix = Regexp.new('^' +
> Regexp.escape(remove_tag_prefix))
>        end
> +      @tag_key = conf['tag_key']

No, that is supposed to be automatically done by the fluentd plugin base code.

Comment 8 Noriko Hosoi 2017-12-01 00:03:32 UTC
> The thing that puzzles me is - what does `tag_key` evaluate to?  It must evaluate to something in order to hit the error.
>
> Maybe there is some legacy code in the fluentd plugin that allows you to use `tag_key` instead of `@tag_key`?  You could put some debugging prints in there to find out.

It's done via ansible which Anping is trying to test:

openshift_logging_fluentd/templates/fluentd.j2
{% if openshift_logging_fluentd_remote_syslog_tag_key is defined %}
        - name: REMOTE_SYSLOG_TAG_KEY
          value: "{{ openshift_logging_fluentd_remote_syslog_tag_key }}"
{% endif %}

openshift_logging_mux/templates/mux.j2
{% if openshift_logging_mux_remote_syslog_tag_key is defined %}
        - name: REMOTE_SYSLOG_TAG_KEY
          value: "{{ openshift_logging_mux_remote_syslog_tag_key }}"
{% endif %}

And this is the doc:
docs/remote-syslog.md:* `REMOTE_SYSLOG_TAG_KEY` : if specified, uses this field as the key to look on the record, to set the tag on the syslog message

Comment 9 Anping Li 2017-12-01 01:13:41 UTC
Noriko, you are right. We have Environment variable REMOTE_SYSLOG_TAG_KEY. it is design to replace tag for all records.  By the way, the default tag are output_tag.

Comment 10 Noriko Hosoi 2017-12-01 06:21:33 UTC
I could reproduce the problem by adding "-e openshift_logging_fluentd_remote_syslog_tag_key=syslog_tag" to the ansible-playbook command line.

2017-12-01 02:52:56 +0000 [warn]: temporarily failed to flush the buffer. next_retry=2017-12-01 02:52:57 +0000 error_class="NoMethodError" error="undefined method `[]' for nil:NilClass" plugin_id="object:12449dc"
  2017-12-01 02:52:56 +0000 [warn]: /etc/fluent/plugin/out_syslog_buffered.rb:106:in `send_to_syslog'
  2017-12-01 02:52:56 +0000 [warn]: /etc/fluent/plugin/out_syslog_buffered.rb:85:in `block in write'
  2017-12-01 02:52:56 +0000 [warn]: /opt/app-root/src/gems/fluentd-0.12.39/lib/fluent/plugin/buf_memory.rb:67:in `feed_each'
  2017-12-01 02:52:56 +0000 [warn]: /opt/app-root/src/gems/fluentd-0.12.39/lib/fluent/plugin/buf_memory.rb:67:in `msgpack_each'
  2017-12-01 02:52:56 +0000 [warn]: /etc/fluent/plugin/out_syslog_buffered.rb:84:in `write'
  2017-12-01 02:52:56 +0000 [warn]: /opt/app-root/src/gems/fluentd-0.12.39/lib/fluent/buffer.rb:354:in `write_chunk'
  2017-12-01 02:52:56 +0000 [warn]: /opt/app-root/src/gems/fluentd-0.12.39/lib/fluent/buffer.rb:333:in `pop'
  2017-12-01 02:52:56 +0000 [warn]: /opt/app-root/src/gems/fluentd-0.12.39/lib/fluent/output.rb:342:in `try_flush'
  2017-12-01 02:52:56 +0000 [warn]: /opt/app-root/src/gems/fluentd-0.12.39/lib/fluent/output.rb:149:in `run'

Comment 11 Noriko Hosoi 2017-12-05 23:25:36 UTC
(In reply to Rich Megginson from comment #3)
> I don't understand.
> https://github.com/docebo/fluent-plugin-remote-syslog#fluent-plugin-remote-
> syslog
>
>     use_record: Use severity and facility from record if available
>
> use_record doesn't have anything to do with the tag or tag_key.  I think the
> problem is that the code is using `tag_key` instead of `@tag_key`.  I think
> the solution is to use `@tag_key` instead of `tag_key` in the code.
>
> And yes, this looks like an issue with the fluent plugin.

Running the remote-syslog.sh test with various patched fluent-plugin-remote-syslog, only a patch which solved the error="undefined method `[]' for nil:NilClass" was the one I attached to this bug [1]. 

Reading the source code out_syslog.rb and out_syslog_buffered.rb again, I could not find the difference between 'tag_key' and the other config parameters such as 'severity' and 'facility'.  That is, the way how tag_key is set and retrieved from record looks the same to me as for 'severity' and 'facility' although the doc claims "use_record: Use severity and facility from record if available".  Do we want to submit the pr to https://github.com/docebo/fluent-plugin-remote-syslog and start a discussion there?  

But before going there, I have another question, which is how important to change the value of tag for remote-syslog?

If it is not important, can we just drop the tag_key feature from remote-syslog?

If it is important, should it be done with the config file generated by generate_syslog_config.rb?

The default value is output_tag (output_ops_tag is for OPS).  If you want to just replace it with the REMOTE_SYSLOG_TAG_KEY value, we could set it in this retag config [2] (and removing TAG_KEY setting from generate_syslog_config.rb)?  That way, we do not have to deal with the remote-syslog plugin?

[1] https://bugzilla.redhat.com/attachment.cgi?id=1361347

[2] diff --git a/fluentd/configs.d/filter-post-z-retag-one.conf b/fluentd/configs.d/filter-post-z-retag-one.conf
index c76180d..ef6fc26 100644
--- a/fluentd/configs.d/filter-post-z-retag-one.conf
+++ b/fluentd/configs.d/filter-post-z-retag-one.conf
@@ -7,6 +7,6 @@
 <match **>
   @type rewrite_tag_filter
   @label @OUTPUT
-  rewriterule1 message .+ output_tag
-  rewriterule2 message !.+ output_tag
+  rewriterule1 message .+ "#{ENV['REMOTE_SYSLOG_TAG_KEY'] || 'output_tag'}"
+  rewriterule2 message !.+ "#{ENV['REMOTE_SYSLOG_TAG_KEY'] || 'output_tag'}"
 </match>

Comment 12 Peter Portante 2017-12-06 01:43:51 UTC
Noriko, the documentation for "tag_key" and "use_record" at [1] says:

  tag_key: use the field specified in tag_key from record to set the syslog key
  use_record: Use severity and facility from record if available

So if "tag_key" is present, then it is defined to take the value from the record, and "use_record" is explicitly defined to only apply to where "severity" and "facility" are pulled from.

It seems that this is a bug as noted by Rich, that the code at lines 81 and 82 of out_syslog [2] should use "@tag_key", similarly for lines 105 and 106 of out_syslog_buffered [3].

If you tried the proper patch for the two files below, how does it fail?

[1] https://github.com/docebo/fluent-plugin-remote-syslog/blob/master/README.md
[2] https://github.com/docebo/fluent-plugin-remote-syslog/blob/master/lib/fluentd/plugin/out_syslog.rb#L81
[3] https://github.com/docebo/fluent-plugin-remote-syslog/blob/master/lib/fluentd/plugin/out_syslog_buffered.rb#L105

Comment 13 Noriko Hosoi 2017-12-06 02:00:51 UTC
Created attachment 1363484 [details]
tag_key -> @tag_key

Thanks for your comments, Peter.

I tried the attached patch, but it did not help.  (It still crashes as originally reported by @Anping.)  Do you have a suggestion how the patch should be modified?

Comment 14 Peter Portante 2017-12-06 02:20:44 UTC
Can you consider something like:

@packet.tag = if @tag_key
  # tag is trimmed to 32 chars for syslog_protocol gem compatibility
  begin
    record[@tag_key][0..31].gsub(/[\[\]]/,'')
  rescue
    # tag is trimmed to 32 chars for syslog_protocol gem compatibility
    tag[0..31] 
  end
else
  # tag is trimmed to 32 chars for syslog_protocol gem compatibility
  tag[0..31] 
end

This will handle the case where records don't have a tag key, so we fall back to the "tag" constructed by fluentd.

Comment 15 Noriko Hosoi 2017-12-06 05:37:10 UTC
(In reply to Peter Portante from comment #14)
> Can you consider something like:
> 
> @packet.tag = if @tag_key
>   # tag is trimmed to 32 chars for syslog_protocol gem compatibility
>   begin
>     record[@tag_key][0..31].gsub(/[\[\]]/,'')
>   rescue
>     # tag is trimmed to 32 chars for syslog_protocol gem compatibility
>     tag[0..31] 
>   end
> else
>   # tag is trimmed to 32 chars for syslog_protocol gem compatibility
>   tag[0..31] 
> end
> 
> This will handle the case where records don't have a tag key, so we fall
> back to the "tag" constructed by fluentd.

Sure.  But considering the current tests, it'd be the same as
   @packet.tag = tag[0..31]
since record[@tag_key][0..31] is always nil.

I don't know how to utilize tag_key...

Comment 16 Anping Li 2017-12-06 06:10:11 UTC
@Noriko, I think if we set REMOTE_SYSLOG_TAG_KEY="message",  it use  record[message][0..31] as the rsyslog tag.

Comment 17 Noriko Hosoi 2017-12-06 06:40:59 UTC
(In reply to Anping Li from comment #16)
> @Noriko, I think if we set REMOTE_SYSLOG_TAG_KEY="message",  it use 
> record[message][0..31] as the rsyslog tag.

Ah, I see... Sorry for my slow understanding...  We had to set one of the existing fields... :p  Then, Peter's suggestion #c14 totally makes sense.

I'm going to submit a pr to the remote syslog plugin tomorrow.

Thanks!

Comment 19 openshift-github-bot 2017-12-08 05:52:51 UTC
Commits pushed to master at https://github.com/openshift/origin-aggregated-logging

https://github.com/openshift/origin-aggregated-logging/commit/1cea2e10e1471c551cfda0322c20be1d549ea9e6
Bug 1519213 - NoMethodError if remote_syslog enabled remote_syslog_tag_key

fluent-plugin-remote-syslog: replacing tag_key with @tag_key
                             adding rescue around record[@tag_key]
Note: out_syslog.rb and out_syslog_buffered.rb are copied from
      https://github.com/docebo/fluent-plugin-remote-syslog and
      locally modified.  Once the changes made on the files are
      accepted by the plugin, out_syslog.rb and out_syslog_buffered.rb
      are to be removed and the changes on Dockerfile* are to be undone.

Adding test cases for tag_key to remote_syslog.sh

https://github.com/openshift/origin-aggregated-logging/commit/b223dc289fcc7b328e3847edea3a1b6533a9b33d
Merge pull request #820 from nhosoi/bz1519213-0

Automatic merge from submit-queue.

Bug 1519213 - NoMethodError if remote_syslog enabled remote_syslog_ta…

…g_key

fluent-plugin-remote-syslog: replacing tag_key with @tag_key
                             adding rescue around record[@tag_key]
Note: out_syslog.rb and out_syslog_buffered.rb are copied from
      https://github.com/docebo/fluent-plugin-remote-syslog and
      locally modified.  Once the changes made on the files are
      accepted by the plugin, out_syslog.rb and out_syslog_buffered.rb
      are to be removed and the changes on Dockerfile* are to be undone.

Adding test cases for tag_key to remote_syslog.sh

Comment 20 Noriko Hosoi 2017-12-11 19:16:09 UTC
Additional pr for license:
https://github.com/openshift/origin-aggregated-logging/pull/836

Comment 22 Anping Li 2017-12-19 08:09:30 UTC
@Noriko

I written some logs with logger and watch the rsyslog when enabled REMOTE_SYSLOG_TAG_KEY. I found the rsyslog records are still tagged with output_tag. It seems REMOTE_SYSLOG_TAG_KEY won't work. 

1)
#logger msg_with_tag_severity1

 - name: REMOTE_SYSLOG_TAG_KEY
    value: severity

#rsyslog records
Dec 19 02:20:46 logging-fluentd-tp4dj output_tag: msg_with_tag_severity1

2)
#logger msg_with_tag_time1

 - name: REMOTE_SYSLOG_TAG_KEY
    value: time

#rsyslog records
Dec 19 02:25:36 logging-fluentd-rsw6h output_tag: msg_with_tag_time1


3)
#logger msg_with_tag_abc1

 - name: REMOTE_SYSLOG_TAG_KEY
    value: abc

#rsyslog records
Dec 19 02:35:46 logging-fluentd-2tc9w output_tag: msg_with_tag_abc1

Comment 23 Noriko Hosoi 2017-12-19 18:43:19 UTC
Hi @Anping,

Could you please attach the generated output-remote-syslog.conf file to this bug?
/etc/fluent/configs.d/dynamic/output-remote-syslog.conf

And could you get the value of the environment variable REMOTE_SYSLOG_TAG_KEY in the fluentd pod?

Also, if you try running the test with these values, what happens?  The same?
 - name: REMOTE_SYSLOG_TAG_KEY
    value: log

 - name: REMOTE_SYSLOG_TAG_KEY
    value: message

 - name: REMOTE_SYSLOG_TAG_KEY
    value: MESSAGE

Thanks!

Comment 24 Anping Li 2017-12-20 01:54:00 UTC
1.1) configure  file
oc exec logging-fluentd-982dr -- cat /etc/fluent/configs.d/dynamic/output-remote-syslog.conf
## This file was generated by generate-syslog-config.rb
<store>
@type syslog_buffered
remote_syslog 192.168.1.221
port 514
hostname logging-fluentd-982dr
tag_key log
facility local0
severity debug
</store>

1.2) rsyslog records
Dec 19 20:48:12 logging-fluentd-982dr output_tag: msg_with_tag_log1
Dec 19 20:48:12 logging-fluentd-982dr output_tag: msg_with_tag_log2
Dec 19 20:48:12 logging-fluentd-982dr output_tag: msg_with_tag_log3
Dec 19 20:48:12 logging-fluentd-982dr output_tag: msg_with_tag_log4


2.1) configure file
oc exec logging-fluentd-6xfm5 -- cat /etc/fluent/configs.d/dynamic/output-remote-syslog.conf
## This file was generated by generate-syslog-config.rb
<store>
@type syslog_buffered
remote_syslog 192.168.1.221
port 514
hostname logging-fluentd-6xfm5
tag_key message
facility local0
severity debug
</store>

2.2) No rsyslog records

2.3) Fluned error
2017-12-19 20:50:00 -0500 [info]: reading config file path="/etc/fluent/fluent.conf"
2017-12-19 20:50:01 -0500 [warn]: 'block' action stops input process until the buffer full is resolved. Check your pipeline this action is fit or not
2017-12-19 20:51:02 -0500 [warn]: temporarily failed to flush the buffer. next_retry=2017-12-19 20:51:03 -0500 error_class="ArgumentError" error="Tag may not contain spaces" plugin_id="object:d92efc"
  2017-12-19 20:51:02 -0500 [warn]: /usr/share/gems/gems/syslog_protocol-0.9.2/lib/syslog_protocol/packet.rb:52:in `tag='
  2017-12-19 20:51:02 -0500 [warn]: /etc/fluent/plugin/out_syslog_buffered.rb:105:in `send_to_syslog'
  2017-12-19 20:51:02 -0500 [warn]: /etc/fluent/plugin/out_syslog_buffered.rb:85:in `block in write'
  2017-12-19 20:51:02 -0500 [warn]: /usr/share/gems/gems/fluentd-0.12.39/lib/fluent/plugin/buf_memory.rb:67:in `feed_each'
  2017-12-19 20:51:02 -0500 [warn]: /usr/share/gems/gems/fluentd-0.12.39/lib/fluent/plugin/buf_memory.rb:67:in `msgpack_each'
  2017-12-19 20:51:02 -0500 [warn]: /etc/fluent/plugin/out_syslog_buffered.rb:84:in `write'
  2017-12-19 20:51:02 -0500 [warn]: /usr/share/gems/gems/fluentd-0.12.39/lib/fluent/buffer.rb:354:in `write_chunk'
  2017-12-19 20:51:02 -0500 [warn]: /usr/share/gems/gems/fluentd-0.12.39/lib/fluent/buffer.rb:333:in `pop'
  2017-12-19 20:51:02 -0500 [warn]: /usr/share/gems/gems/fluentd-0.12.39/lib/fluent/output.rb:342:in `try_flush'
  2017-12-19 20:51:02 -0500 [warn]: /usr/share/gems/gems/fluentd-0.12.39/lib/fluent/output.rb:149:in `run'
2017-12-19 20:51:03 -0500 [warn]: temporarily failed to flush the buffer. next_retry=2017-12-19 20:51:05 -0500 error_class="ArgumentError" error="Tag may not contain spaces" plugin_id="object:d92efc"
  2017-12-19 20:51:03 -0500 [warn]: suppressed same stacktrace
2017-12-19 20:51:05 -0500 [warn]: temporarily failed to flush the buffer. next_retry=2017-12-19 20:51:09 -0500 error_class="ArgumentError" error="Tag may not contain spaces" plugin_id="object:d92efc"
  2017-12-19 20:51:05 -0500 [warn]: suppressed same stacktrace
2017-12-19 20:51:09 -0500 [warn]: temporarily failed to flush the buffer. next_retry=2017-12-19 20:51:17 -0500 error_class="ArgumentError" error="Tag may not contain spaces" plugin_id="object:d92efc"
  2017-12-19 20:51:09 -0500 [warn]: suppressed same stacktrace
2017-12-19 20:51:17 -0500 [warn]: temporarily failed to flush the buffer. next_retry=2017-12-19 20:51:35 -0500 error_class="ArgumentError" error="Tag may not contain spaces" plugin_id="object:d92efc"
  2017-12-19 20:51:17 -0500 [warn]: suppressed same stacktrace


3.1) configure file
# oc exec logging-fluentd-7gb4g -- cat /etc/fluent/configs.d/dynamic/output-remote-syslog.conf
## This file was generated by generate-syslog-config.rb
<store>
@type syslog_buffered
remote_syslog 192.168.1.221
port 514
hostname logging-fluentd-7gb4g
tag_key severity
facility local0
severity debug
</store>

3.2) rsyslog records
Dec 19 20:53:43 logging-fluentd-7gb4g output_tag: msg_with_tag_severity1
Dec 19 20:53:43 logging-fluentd-7gb4g output_tag: msg_with_tag_severity2
Dec 19 20:53:43 logging-fluentd-7gb4g output_tag: msg_with_tag_severity3
Dec 19 20:53:43 logging-fluentd-7gb4g output_tag: msg_with_tag_severity4

Comment 25 Noriko Hosoi 2017-12-20 06:38:46 UTC
Thank you, @Anping!!!

Based upon your test results, only record[message] exists.  There is no "log", no "MESSAGE", no "time" in the test data?  (Not so sure about "severity", though.  I'd think there is no field in the test data?)

But the point is if record[tag_key] exists, it's picked up as logged in 2.3.  And reading rfc3164, tag is not supposed to contain non-alphanumeric characters including space characters?  
=======================================================================
   The TAG is a string of
   ABNF alphanumeric characters that MUST NOT exceed 32 characters.  Any
   non-alphanumeric character will terminate the TAG field and will be
   assumed to be the starting character of the CONTENT field.  Most
   commonly, the first character of the CONTENT field that signifies the
   conclusion of the TAG field has been seen to be the left square
   bracket character ("["), a colon character (":"), or a space
   character.
=======================================================================
That's being said, we may need to add space (as well as colon) to gsub?
record[tag_key][0..31].gsub(/[\[\]]/,'')

Comment 26 Noriko Hosoi 2017-12-20 19:10:31 UTC
https://github.com/openshift/origin-aggregated-logging/pull/868

Note: reading syslog_protocol, a space is not allowed but symbols are.
https://github.com/eric/syslog_protocol/blob/master/lib/syslog_protocol/packet.rb#L44-#L56

Comment 27 Noriko Hosoi 2017-12-20 20:33:48 UTC
Another note...

rfc3164 has been replaced with rfc5424.

   The MSG part of the message is described as TAG and CONTENT in RFC
   3164.  In this document, MSG is what was called CONTENT in RFC 3164.
   The TAG is now part of the header, but not as a single field.  The
   TAG has been split into APP-NAME, PROCID, and MSGID.  This does not
   totally resemble the usage of TAG, but provides the same
   functionality for most of the cases.

But it seems we don't have to worry about the new protocol for now...

Comment 28 Rich Megginson 2018-01-04 02:05:57 UTC
koji_builds:
  https://brewweb.engineering.redhat.com/brew/buildinfo?buildID=636331
repositories:
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:rhaos-3.9-rhel-7-docker-candidate-89109-20180103231254
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:latest
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.9.0
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.9.0-0.16.0.1
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.9.0
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.9.0.20180103.170133
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.9

koji_builds:
  https://brewweb.engineering.redhat.com/brew/buildinfo?buildID=636358
repositories:
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:rhaos-3.8-rhel-7-docker-candidate-92791-20180103235159
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:latest
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.8.25
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.8.25-3
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.8.25.20180102.220346
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.8
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.8.25

koji_builds:
  https://brewweb.engineering.redhat.com/brew/buildinfo?buildID=636394
repositories:
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:rhaos-3.7-rhel-7-docker-candidate-18263-20180104013419
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:latest
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.7.16
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.7.16-3
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.7.16
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.7
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.7.16.20171221.103556

Comment 29 Anping Li 2018-01-04 03:12:04 UTC
umounts of dead containers will fail. Ignoring...
umount: /var/lib/docker/containers/5201e782a0bb3e270e38c61a7e6dac341919d6e78969cc244f01f5e9fd33f641/shm: not mounted
umount: /var/lib/docker/containers/7969c5e63242a7462d5c47976465eb3b871b6b535543986cf77accd30aa03e78/shm: not mounted
umount: /var/lib/docker/containers/d4055f1a1b3ef65a8cb37438f394a30e78300a5d06cc7f79846f0ddab3c7c55c/shm: not mounted
umount: /var/lib/docker/containers/ea03fbe0990f03588cc9ac0d6d6b0d08b335a7933870e87bd53ae4e7726f2a25/shm: not mounted
2018-01-03 22:07:18 -0500 [info]: reading config file path="/etc/fluent/fluent.conf"
/usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require': cannot load such file -- fluent/mixin/config_placeholders (LoadError)
	from /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require'
	from /etc/fluent/plugin/out_syslog.rb:4:in `<top (required)>'
	from /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require'
	from /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require'
	from /usr/share/gems/gems/fluentd-0.12.42/lib/fluent/plugin.rb:89:in `block in load_plugin_dir'
	from /usr/share/gems/gems/fluentd-0.12.42/lib/fluent/plugin.rb:87:in `each'
	from /usr/share/gems/gems/fluentd-0.12.42/lib/fluent/plugin.rb:87:in `load_plugin_dir'
	from /usr/share/gems/gems/fluentd-0.12.42/lib/fluent/engine.rb:138:in `load_plugin_dir'
	from /usr/share/gems/gems/fluentd-0.12.42/lib/fluent/supervisor.rb:519:in `block in init_engine'
	from /usr/share/gems/gems/fluentd-0.12.42/lib/fluent/supervisor.rb:516:in `each'
	from /usr/share/gems/gems/fluentd-0.12.42/lib/fluent/supervisor.rb:516:in `init_engine'
	from /usr/share/gems/gems/fluentd-0.12.42/lib/fluent/supervisor.rb:172:in `block in start'
	from /usr/share/gems/gems/fluentd-0.12.42/lib/fluent/supervisor.rb:366:in `call'
	from /usr/share/gems/gems/fluentd-0.12.42/lib/fluent/supervisor.rb:366:in `main_process'
	from /usr/share/gems/gems/fluentd-0.12.42/lib/fluent/supervisor.rb:170:in `start'
	from /usr/share/gems/gems/fluentd-0.12.42/lib/fluent/command/fluentd.rb:173:in `<top (required)>'
	from /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require'
	from /usr/share/rubygems/rubygems/core_ext/kernel_require.rb:55:in `require'
	from /usr/share/gems/gems/fluentd-0.12.42/bin/fluentd:8:in `<top (required)>'
	from /usr/bin/fluentd:23:in `load'
	from /usr/bin/fluentd:23:in `<main>'

Comment 30 Rich Megginson 2018-01-04 04:28:56 UTC
koji_builds:
  https://brewweb.engineering.redhat.com/brew/buildinfo?buildID=636441
repositories:
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:rhaos-3.9-rhel-7-docker-candidate-62824-20180104032826
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:latest
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.9.0
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.9.0-0.16.0.2
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.9.0
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.9.0.20180103.170133
  brew-pulp-docker01.web.prod.ext.phx2.redhat.com:8888/openshift3/logging-fluentd:v3.9

and 

v3.7.16-4

Comment 31 Anping Li 2018-01-05 03:27:57 UTC
The fix works well on openshift3/logging-fluentd/images/v3.7.19-1

Once set REMOTE_SYSLOG_TAG_KEY=level, The rsyslog records are use level as tag.

For example: the level 'info' is the tag the following line.

Jan  4 22:24:32 logging-fluentd-gsq6m info: time="2018-01-04T22:24:30.916770180-05:00" level=info msg="{Action=start, LoginUID=4294967295, PID=77476}"

Comment 34 errata-xmlrpc 2018-01-23 17:58: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-2018:0113


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