Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"emit_unmatched_lines" option for in_syslog / in_udp #2497

Closed
candlerb opened this issue Jul 14, 2019 · 1 comment · Fixed by #2499
Closed

"emit_unmatched_lines" option for in_syslog / in_udp #2497

candlerb opened this issue Jul 14, 2019 · 1 comment · Fixed by #2499

Comments

@candlerb
Copy link
Contributor

candlerb commented Jul 14, 2019

Is your feature request related to a problem? Please describe.

When in_syslog (with default syslog parser) is unable to parse a line, effectively it gets thrown away. (Example at end of ticket).

It does generate an internal warning, of the form:

[warn]: #0 failed to parse message data="...."

but that does not go through the same processing path as the syslog messages themselves, and is not itself in a form which could be easily (re-)parsed.

I would like to be confident that all syslog messages are retained, even ones which are of an unexpected format.

Describe the solution you'd like

in_tail has the ability to emit_unmatched_lines, and it would be consistent to add something like this for in_syslog / in_udp (and possibly all other input modules?)

It might be nice to be able to set the key they are emitted under: e.g.

emit_unmatched_lines  bad_message

And/or add an extra key such as "unparsed": true.

Describe alternatives you've considered

As a workaround, I can use in_udp with <parser>@type none</parser>. That gives me the raw syslog reliably, but of course completely unparsed (e.g. it includes the <pri> header)

In theory I could combine this with a parser filter and emit_invalid_record_to_error. However that's very difficult to set up (*), and in any case <label @ERROR> catches other errors (e.g. buffer full) that I don't want to catch.

If I could change the label used when parsing fails, e.g. <label @UNPARSED>, that could be a workable solution.

Another solution might be to allow a chain of parsers, with parsing stopping on the first match. You could end with parser none, or with parser regexp and expression (.*), as a catch-all. This is not currently supported - you get error "duplicated parsers configured" if you put more than one <parse> section in an input module.

(*) It's not obvious how to strip/relabel without getting into infinite loops. For example, the following gives an infinite loop:

<source>
  @type udp
  tag syslog
  port 5140
  bind 0.0.0.0
  source_address_key source_address
  <parse>
    @type none
  </parse>
</source>

<filter syslog.**>
  @type parser
  key_name message
  emit_invalid_record_to_error
  <parse>
    @type syslog
  </parse>
</filter>

<label @ERROR>
  <match syslog.**>
    @type file
    path /var/log/fluent/syslog_error
    compress gzip
    <buffer>
      timekey_use_utc
    </buffer>
  </match>
</label>

<match syslog.**>
  @type file
  path /var/log/fluent/syslog
  compress gzip
  <buffer>
    timekey_use_utc
  </buffer>
</match>

This gives the following infinite loop of errors, which I can't see how to avoid:

...
Jul 14 16:41:28 fluentd fluentd[14652]: 2019-07-14 16:41:28 +0000 [warn]: #0 send an error event to @ERROR: error_class=Fluent::Plugin::Parser::ParserError error="parse failed invalid time format: value = <30>Jul 14 16:41:28, error_class = ArgumentError, error = string doesn't match" location="/var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin/filter_parser.rb:110:in `rescue in filter_with_time'" tag="syslog" time=2019-07-14 16:41:28.366510476 +0000
Jul 14 16:41:28 fluentd fluentd[14652]: 2019-07-14 16:41:28 +0000 [warn]: #0 send an error event to @ERROR: error_class=Fluent::Plugin::Parser::ParserError error="parse failed invalid time format: value = <30>Jul 14 16:41:28, error_class = ArgumentError, error = string doesn't match" location="/var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin/filter_parser.rb:110:in `rescue in filter_with_time'" tag="syslog" time=2019-07-14 16:41:28.368301612 +0000
Jul 14 16:41:28 fluentd fluentd[14652]: 2019-07-14 16:41:28 +0000 [warn]: #0 send an error event to @ERROR: error_class=Fluent::Plugin::Parser::ParserError error="parse failed invalid time format: value = <30>Jul 14 16:41:28, error_class = ArgumentError, error = string doesn't match" location="/var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin/filter_parser.rb:110:in `rescue in filter_with_time'" tag="syslog" time=2019-07-14 16:41:28.370026582 +0000
...

Additional context

Here is a real raw syslog generated by a Netgear GS724Tv4 switch, captured by in_udp with parser none:

2019-07-14T16:01:51+00:00	syslog	{"message":"<14> Jul 14 16:01:51 10.12.255.2-1 CLI_WEB[53145316]: login_sessions.c(172) 117489 %% Telnet Session 0 ended for user admin connected from 10.12.255.248\n\u0000","source_address":"10.12.255.2"}

Notice how there is a spurious space after the <pri> prefix, and a spurious \u0000 at the end. I'll agree that this device is broken, but broken things exist in the real world.

If I try to receive this using in_syslog with the default syslog parser, I get the following backtrace barf in local syslog (for every message!)

Jul 14 16:07:34 fluentd fluentd[14232]: 2019-07-14 16:07:34 +0000 [error]: #0 invalid input data="<14> Jul 14 16:07:34 10.12.255.2-1 CLI_WEB[53145316]: login_sessions.c(172) 117496 %% Telnet Session 0 ended for user admin connected from 10.12.255.248\n\x00" error_class=Fluent::TimeParser::TimeParseError error="invalid time format: value =  Jul 14, error_class = ArgumentError, error = string doesn't match"
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/time.rb:266:in `rescue in parse'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/time.rb:263:in `parse'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin/parser_syslog.rb:117:in `block (2 levels) in parse_plain'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin/parser_syslog.rb:114:in `synchronize'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin/parser_syslog.rb:114:in `block in parse_plain'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin/parser_syslog.rb:108:in `each'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin/parser_syslog.rb:108:in `parse_plain'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin/parser_syslog.rb:95:in `parse_auto'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin/in_syslog.rb:213:in `message_handler'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin/in_syslog.rb:161:in `block in start_udp_server'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin_helper/server.rb:542:in `on_readable_with_sock'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/cool.io-1.5.4/lib/cool.io/io.rb:186:in `on_readable'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/cool.io-1.5.4/lib/cool.io/loop.rb:88:in `run_once'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/cool.io-1.5.4/lib/cool.io/loop.rb:88:in `run'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
Jul 14 16:07:34 fluentd fluentd[14232]:   2019-07-14 16:07:34 +0000 [error]: #0 /var/lib/gems/2.3.0/gems/fluentd-1.6.2/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'

If I send something which is more obviously not in standard syslog format, e.g.

echo "hello" | nc -u -w0 localhost 5140

then I just get a single warning line logged:

Jul 14 16:22:13 fluentd fluentd[14232]: 2019-07-14 16:22:13 +0000 [warn]: #0 failed to parse message data="hello"

In both cases, I would like the broken syslog message to propagate through the stack, albeit with some way to identify it as non-parsed.

Another example is Cisco's weird syslog format

@candlerb
Copy link
Contributor Author

Another example of a server sending broken syslog is FreeBSD, and hence derivatives like pfSense.

candlerb added a commit to candlerb/fluentd that referenced this issue Jul 15, 2019
candlerb added a commit to candlerb/fluentd that referenced this issue Jul 16, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant