in_syslog resulting in TimeParseError with OpenBSD syslogd(8)

[dspruell]

What is a problem?

I've been trying to diagnose high error rates with system log collection on my network.

I can't seem to identify a configuration that results in proper receipt of logs from the OpenBSD built-in syslogd without seeing TimeParseError from Fluentd. Looking at the error, I can't see why it occurs, as the timestamps appear to be correct.

Sample error and received log line detail:

2024-04-14 01:40:23 -0700 [error]: #0 invalid input data="<30>Apr 14 01:40:23 unbound: [91920:0] info: 10.0.x.xx xxxxxxxx.xxx.xxxxxx.net. A IN" error_class=Fluent::TimeParser::TimeParseError error="invalid time format: value = Apr 14 01:40:23, error_class = ArgumentError, error = string doesn't match"
  2024-04-14 01:40:23 -0700 [error]: #0 /usr/local/lib/ruby/gems/3.2/gems/fluentd-1.16.5/lib/fluent/time.rb:280:in `rescue in parse'
  2024-04-14 01:40:23 -0700 [error]: #0 /usr/local/lib/ruby/gems/3.2/gems/fluentd-1.16.5/lib/fluent/time.rb:277:in `parse'
  2024-04-14 01:40:23 -0700 [error]: #0 /usr/local/lib/ruby/gems/3.2/gems/fluentd-1.16.5/lib/fluent/plugin/parser_syslog.rb:193:in `block in parse_rfc3164_regex'
  2024-04-14 01:40:23 -0700 [error]: #0 /usr/local/lib/ruby/gems/3.2/gems/fluentd-1.16.5/lib/fluent/plugin/parser_syslog.rb:193:in `synchronize'
  2024-04-14 01:40:23 -0700 [error]: #0 /usr/local/lib/ruby/gems/3.2/gems/fluentd-1.16.5/lib/fluent/plugin/parser_syslog.rb:193:in `parse_rfc3164_regex'
  2024-04-14 01:40:23 -0700 [error]: #0 /usr/local/lib/ruby/gems/3.2/gems/fluentd-1.16.5/lib/fluent/plugin/in_syslog.rb:241:in `message_handler'
  2024-04-14 01:40:23 -0700 [error]: #0 /usr/local/lib/ruby/gems/3.2/gems/fluentd-1.16.5/lib/fluent/plugin/in_syslog.rb:174:in `block in start_udp_server'
  2024-04-14 01:40:23 -0700 [error]: #0 /usr/local/lib/ruby/gems/3.2/gems/fluentd-1.16.5/lib/fluent/plugin_helper/server.rb:570:in `on_readable_with_sock'
  2024-04-14 01:40:23 -0700 [error]: #0 /usr/local/lib/ruby/gems/3.2/gems/cool.io-1.7.1/lib/cool.io/io.rb:186:in `on_readable'
  2024-04-14 01:40:23 -0700 [error]: #0 /usr/local/lib/ruby/gems/3.2/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run_once'
  2024-04-14 01:40:23 -0700 [error]: #0 /usr/local/lib/ruby/gems/3.2/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run'
  2024-04-14 01:40:23 -0700 [error]: #0 /usr/local/lib/ruby/gems/3.2/gems/fluentd-1.16.5/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
  2024-04-14 01:40:23 -0700 [error]: #0 /usr/local/lib/ruby/gems/3.2/gems/fluentd-1.16.5/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'

Apr 14 01:40:23 appears to be the valid format for RFC 3164 format timestamps.

What else I've tried

• I've enabled RFC 5424 style ISO timestamp format in syslogd(8), and encountered the same issue in Fluentd:

2024-04-14 02:11:09 -0700 [error]: #0 invalid input data="<30>2024-04-14T09:11:09.769Z unbound: [91920:0] info: 10.0.x.xx xxxxxxxx.xxx.xxxxxxxx.xxx. A IN" error_class=Fluent::TimeParser::TimeParseError error=
"invalid time format: value = 2024-04-14T09:11:09.769Z unbound: [91920:0], error_class = ArgumentError, error = string doesn't match"

• I've set syslogd(8) and Fluentd to send/receive using TCP:

*.*     @tcp4://127.0.0.1:5150

<source>
    @type syslog
    tag system
    port 5150
    <transport tcp>
    </transport>
</source>

<match system.**>
    @type stdout
</match>

Error; seems like framing changed with change to TCP:

2024-04-14 02:14:21 -0700 [warn]: #0 failed to parse message data="50 <46>2024-04-14T09:14:06.720Z syslogd[6365]: start"

From this I've then set frame_type octet_count in the source, and the timestamp again fails to parse:

2024-04-14 02:22:56 -0700 [error]: #0 invalid input data="<30>2024-04-14T09:22:56.957Z unbound: [91920:0] info: 10.0.x.x endpoint6.collection.us2.sumologic.com. AAAA IN\n" error_class=Fluent::TimeParser::TimeParseError error="invalid time format: value = 2024-04-14T09:22:56.957Z unbound: [91920:0], error_class = ArgumentError, error = string doesn't match"

Same when reverting to traditional timestamp format with TCP:

2024-04-14 02:25:29 -0700 [error]: #0 invalid input data="<30>Apr 14 02:25:29 unbound: [91920:0] info: 10.0.x.xx xxxxxxxx-xxx.xxx.xxxxxxxx.xxx. A IN\n" error_class=Fluent::TimeParser::TimeParseError error="invalid time format: value = Apr 14 02:25:29, error_class = ArgumentError, error = string doesn't match"

Describe the configuration of Fluentd

Fluentd test configuration:

<source>
    @type syslog
    tag system
    port 5150
</source>

<match system.**>
    @type stdout
</match>

OpenBSD syslogd(8) test configuration:

*.*     @127.0.0.1:5150

syslogd is executed with a default configuration (no modified flags, so it emits standard RFC 3164 events and traditional timestamps.

Describe the logs of Fluentd

Fluentd startup:

# fluentd32 -c test.conf
2024-04-14 01:40:16 -0700 [info]: init supervisor logger path=nil rotate_age=nil rotate_size=nil
2024-04-14 01:40:16 -0700 [info]: parsing config file is succeeded path="test.conf"
2024-04-14 01:40:16 -0700 [info]: gem 'fluentd' version '1.16.5'
2024-04-14 01:40:16 -0700 [info]: gem 'fluent-plugin-mqtt-io' version '0.5.0'
2024-04-14 01:40:16 -0700 [info]: gem 'fluent-plugin-rewrite-tag-filter' version '2.4.0'
2024-04-14 01:40:16 -0700 [info]: gem 'fluent-plugin-sumologic_output' version '1.8.0'
2024-04-14 01:40:16 -0700 [info]: gem 'fluentd' version '1.16.1'
2024-04-14 01:40:16 -0700 [info]: Oj isn't installed, fallback to Yajl as json parser
2024-04-14 01:40:17 -0700 [info]: using configuration file: <ROOT>
  <source>
    @type syslog
    tag "system"
    port 5150
  </source>
  <match system.**>
    @type stdout
  </match>
</ROOT>
2024-04-14 01:40:17 -0700 [info]: starting fluentd-1.16.5 pid=69143 ruby="3.2.3"
2024-04-14 01:40:17 -0700 [info]: spawn command to main:  cmdline=["/usr/local/bin/ruby32", "-Eascii-8bit:ascii-8bit", "/usr/local/bin/fluentd32", "-c", "test.conf", "--under-supervisor"]
2024-04-14 01:40:18 -0700 [info]: #0 init worker0 logger path=nil rotate_age=nil rotate_size=nil
2024-04-14 01:40:18 -0700 [info]: adding match pattern="system.**" type="stdout"
2024-04-14 01:40:18 -0700 [info]: #0 Oj isn't installed, fallback to Yajl as json parser
2024-04-14 01:40:18 -0700 [info]: adding source type="syslog"
2024-04-14 01:40:18 -0700 [info]: #0 starting fluentd worker pid=97892 ppid=69143 worker=0
2024-04-14 01:40:18 -0700 [info]: #0 listening syslog socket on 0.0.0.0:5150 with udp
2024-04-14 01:40:18 -0700 [info]: #0 fluentd worker is now running worker=0

Environment

- Fluentd version: fluentd32 1.16.5
- Ruby version: ruby 3.2.3 (2024-01-18 revision 52bb2ac0a6) [x86_64-openbsd]
- Operating system: OpenBSD 7.4 amd64

[daipom]

Thanks for the detailed report.

I can't reproduce it.
In my environment, I can parse the message: <30>Apr 14 01:40:23 unbound: [91920:0] info: 10.0.x.xx xxxxxxxx.xxx.xxxxxx.net. A IN correctly with the default in_syslog setting.
I wonder what is affecting...

Config:

<source>
  @type syslog
  tag test
</source>

<match test.**>
  @type stdout
</match>

Command to send syslog:

echo "<30>Apr 14 01:40:23 unbound: [91920:0] info: 10.0.x.xx xxxxxxxx.xxx.xxxxxx.net. A IN" | nc -u 0.0.0.0 5140

Standard output of Fluentd:

2024-04-15 16:07:32 +0900 [info]: init supervisor logger path=nil rotate_age=nil rotate_size=nil
2024-04-15 16:07:32 +0900 [info]: parsing config file is succeeded path="/test/fluentd/config/in_syslog/1.conf"
2024-04-15 16:07:32 +0900 [info]: gem 'fluentd' version '1.16.5'
2024-04-15 16:07:32 +0900 [info]: using configuration file: <ROOT>
  <source>
    @type syslog
    tag "test"
  </source>
  <match test.**>
    @type stdout
  </match>
</ROOT>
2024-04-15 16:07:32 +0900 [info]: starting fluentd-1.16.5 pid=1029569 ruby="3.2.2"
2024-04-15 16:07:32 +0900 [info]: spawn command to main:  cmdline=["/home/daipom/.rbenv/versions/3.2.2/bin/ruby", "-r/home/daipom/.rbenv/versions/3.2.2/lib/ruby/site_ruby/3.2.0/bundler/setup", "-Eascii-8bit:ascii-8bit", "/home/daipom/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/bin/fluentd", "-c", "/test/fluentd/config/in_syslog/1.conf", "--under-supervisor"]
2024-04-15 16:07:33 +0900 [info]: #0 init worker0 logger path=nil rotate_age=nil rotate_size=nil
2024-04-15 16:07:33 +0900 [info]: adding match pattern="test.**" type="stdout"
2024-04-15 16:07:33 +0900 [info]: adding source type="syslog"
2024-04-15 16:07:33 +0900 [info]: #0 starting fluentd worker pid=1029589 ppid=1029569 worker=0
2024-04-15 16:07:33 +0900 [info]: #0 listening syslog socket on 0.0.0.0:5140 with udp
2024-04-15 16:07:33 +0900 [info]: #0 fluentd worker is now running worker=0
2024-04-14 01:40:23.000000000 +0900 test.daemon.info: {"host":"unbound:","ident":"","message":"0] info: 10.0.x.xx xxxxxxxx.xxx.xxxxxx.net. A IN"}

[dspruell]

I found at least one configuration that works without resulting in an error:

syslogd(8) flags:

syslogd_flags=-h -Z -u

syslogd.conf(5) forwarding entry:

*.*;mail.info @127.0.0.1:5140

fluentd in_udp source:

<source>
    @type udp
    @label @SYSLOG
    tag syslog
    port 5140
    bind 127.0.0.1
    <parse>
        @type syslog
        with_priority true
        time_format "%Y-%m-%dT%H:%M:%S.%L%z"
    </parse>
</source>