Fluent-bit: tail plugin with parser has incorrect timestamp

[scottbuettner]

When ingesting a standard CentOS 7 /var/log/messages file (sample below) with the following parser config:

[PARSER]
    Name var-log-messages_rhel7
    Format regex
    Regex ^(?<time>\S{3} \d{2} \d{2}:\d{2}:\d{2}) (?<host>\S+?) (?<ident>\S+?): (?<message>.+)$
    Time_Key time
    Time_Format %b %d %H:%M:%S

While the parsing of fields seems to be functioning, the timestamps are being emitted incorrectly, by an amount equal to the UTC offset configured on the host. The host is in MDT (UTC -0600 currently) and the events are being emitted (via forward protocol to a td-agent host) with epoch times that are 6 hours behind what they should be.

I suspect that if our logs contained a timezone offset and we were parsing it, that this would function correctly. However our logs do not contain a timezone offset in all cases.

Is there a config option (or can one be added) to set a default UTC offset, either for the entire daemon or per input?

Sample of log file being ingested:

Jul 12 13:33:01 fluentd01 td-agent_healthcheck: ::98d0:9f5a:3d7f:0%2 "GET / HTTP/1.1" 200
Jul 12 13:33:01 fluentd01 td-agent_healthcheck: ::98d0:9f5a:3d7f:0%2 "GET / HTTP/1.1" 200
Jul 12 13:33:01 fluentd01 td-agent_healthcheck: ::98d0:9f5a:3d7f:0%2 "GET / HTTP/1.1" 200
Jul 12 13:33:01 fluentd01 td-agent_healthcheck: ::98d0:9f5a:3d7f:0%2 "GET / HTTP/1.1" 200
Jul 12 13:33:01 fluentd01 td-agent_healthcheck: ::98d0:9f5a:3d7f:0%2 "GET / HTTP/1.1" 200
Jul 12 13:33:01 fluentd01 td-agent_healthcheck: ::98d0:9f5a:3d7f:0%2 "GET / HTTP/1.1" 200
Jul 12 13:33:01 fluentd01 td-agent_healthcheck: ::98d0:9f5a:3d7f:0%2 "GET / HTTP/1.1" 200
Jul 12 13:33:06 fluentd01 systemd: Started Session 3 of user root.
Jul 12 13:33:06 fluentd01 systemd-logind: New session 3 of user root.
Jul 12 13:33:06 fluentd01 systemd: Starting Session 3 of user root.

This is how td-agent (on the same host) emits those events using a JSON file output:

2017-07-12T07:33:01-06:00       logtail.host.linux.messages     {"file_path":"/var/log/messages","host":"fluentd01","ident":"td-agent_healthcheck","message":"::98d0:9f5a:3d7f:0%2 \"GET / HTTP/1.1\" 200"}
2017-07-12T07:33:01-06:00       logtail.host.linux.messages     {"file_path":"/var/log/messages","host":"fluentd01","ident":"td-agent_healthcheck","message":"::98d0:9f5a:3d7f:0%2 \"GET / HTTP/1.1\" 200"}
2017-07-12T07:33:01-06:00       logtail.host.linux.messages     {"file_path":"/var/log/messages","host":"fluentd01","ident":"td-agent_healthcheck","message":"::98d0:9f5a:3d7f:0%2 \"GET / HTTP/1.1\" 200"}
2017-07-12T07:33:01-06:00       logtail.host.linux.messages     {"file_path":"/var/log/messages","host":"fluentd01","ident":"td-agent_healthcheck","message":"::98d0:9f5a:3d7f:0%2 \"GET / HTTP/1.1\" 200"}
2017-07-12T07:33:01-06:00       logtail.host.linux.messages     {"file_path":"/var/log/messages","host":"fluentd01","ident":"td-agent_healthcheck","message":"::98d0:9f5a:3d7f:0%2 \"GET / HTTP/1.1\" 200"}
2017-07-12T07:33:01-06:00       logtail.host.linux.messages     {"file_path":"/var/log/messages","host":"fluentd01","ident":"td-agent_healthcheck","message":"::98d0:9f5a:3d7f:0%2 \"GET / HTTP/1.1\" 200"}
2017-07-12T07:33:01-06:00       logtail.host.linux.messages     {"file_path":"/var/log/messages","host":"fluentd01","ident":"td-agent_healthcheck","message":"::98d0:9f5a:3d7f:0%2 \"GET / HTTP/1.1\" 200"}
2017-07-12T07:33:06-06:00       logtail.host.linux.messages     {"file_path":"/var/log/messages","host":"fluentd01","ident":"systemd","message":"Started Session 3 of user root."}
2017-07-12T07:33:06-06:00       logtail.host.linux.messages     {"file_path":"/var/log/messages","host":"fluentd01","ident":"systemd-logind","message":"New session 3 of user root."}
2017-07-12T07:33:06-06:00       logtail.host.linux.messages     {"file_path":"/var/log/messages","host":"fluentd01","ident":"systemd","message":"Starting Session 3 of user root."}

[edsiper]

If I understand correctly (please confirm):

• Your host is not UTC
• Your source logs don't contain the timezone/offset
• Fluent Bit is assuming the records time is UTC

[scottbuettner]

Correct.

[edsiper]

Update:

latest commits in GIT master (Fluent Bit 0.12 dev) contain the following changes:

• Unified and clean mechanism for time lookup
• New configuration key "Time_Offset" to set a fixed UTC offset in the parser config section (e.g: Time_Offset -0600)
• Unit tests: new unit tests for parser engine and it backends (json/regex)

note: these changes will be backported to 0.11 series shortly.

[edsiper]

Changes have been backported to 0.11 series, unit tests passed:

https://travis-ci.org/fluent/fluent-bit/jobs/254970456#L1171

To be included in 0.11.14 release

[matrey]

I have a machine configured with UTC+8

# date
Thu Jan 24 15:16:58 CST 2019
# date -u
Thu Jan 24 07:17:00 UTC 2019

When parsing an epoch (which is supposed to be UTC no matter what is the local timezone), fluent bit wrongly offsets it by 8 hours. Weirdly it's actually putting it 8 hours in the future.

[PARSER]
    Name sysdig_tracer_json
    Format json
    Time_Key time
    Time_Format %s.%L

Source:
"time":"1548314221.5840979"
1548314221 = Thursday, January 24, 2019 7:17:01 AM UTC

Fluentbit result:
sysdig-tracers: [1548343021.584098,
1548343021 = Thursday, January 24, 2019 3:17:01 PM UTC --> 8 hours too much

So in the end I have to

1/ pre-process my nanosecond integer timestamp, to cast it into a string (as discovered on #662).

"time":"1548315001.7801085"

2/ Then hardcode the local machine timezone in the parser configuration.

    Time_Offset +0800

Which finally gives the expected result:
{"time":"1548315121.3414543",
ends up as
sysdig-tracers: [1548315121.341454,

It's quite some work to just get fluent bit to simply pass an epoch without mangling it along the way :unamused:

[apollo13]

@matrey I have fixed it locally by settings the TZ environment variable to UTC for the fluent-bit service in systemd. Now Epoch gets parsed properly without having to set an offset. You probably still want offsets if you parse "2019-08-12 12:12:12" from a logfile, but that is to be expected