The time format in the syslog-rfc5424 parser is incorrect (flb_strptime)

[matthewhembree]

Bug Report

Describe the bug
The rfc5424 timezone designator ±00:00 is not supported as claimed by flb_strptime

This is almost a duplicate of #2407, but references flb_strptime (fluentbit v1.5.3+) rather than the system strptime. The resolution provided in that issue does not work in v1.5.3+ (v1.5.4, v1.5.7-debug).

To Reproduce

• Example log message if applicable:

<14>1 2020-09-30T00:09:33+00:00 xxxx-xxxxxxx-vpn-non-prod - - - - 1,2020/09/30 00:09:33,4E4FC3A3E6AA87D,SYSTEM,general,0,2020/09/30 00:09:33,,general,,0,0,general,informational,"User xxxxx logged out via CLI from 1.1.1.1",7157,0x0,0,0,0,0,,xxxx-xxxxxxx-vpn-non-prod

• Steps to reproduce the problem:
  Try to parse logs with builtin parser syslog-rfc3164.

Config:

config:
  inputs: |
    [INPUT]
        Name syslog
        Parser syslog-rfc3164
        Mode tcp
        Listen 0.0.0.0
        Port 5140
        Buffer_Chunk_Size 32000
        Buffer_Max_Size 64000
  outputs: |
    [OUTPUT]
        Name datadog
        Match *
        Host http-intake.logs.datadoghq.com
        TLS on
        compress gzip
        apikey xxxxxxxxxx
        dd_service xxxxxxxxxx
        dd_source xxxxxxxxxx
        dd_tags xxxxxxxxxx
  customParsers: |
    [PARSER]
        Name        syslog-rfc5424-notfixed-either
        Format      regex
        Regex       ^\<(?<pri>[0-9]{1,5})\>1 (?<time>[^ ]+) (?<host>[^ ]+) (?<ident>[^ ]+) (?<pid>[-0-9]+) (?<msgid>[^ ]+) (?<extradata>(\[(.*?)\]|-)) (?<message>.+)$
        Time_Key    time
        Time_Format %Y-%m-%dT%H:%M:%S.%L%Z
        Time_Keep   On

Expected behavior

Logs are forwarded to the next stage in the pipeline.

Error message
Trace logs:

2020-09-30T00:09:51.936784187Z [2020/09/30 00:09:51] [debug] [input:syslog:syslog.0] new Unix connection arrived FD=31
2020-09-30T00:09:51.936808247Z [2020/09/30 00:09:51] [trace] [input:syslog:syslog.0 at plugins/in_syslog/syslog_conn.c:83] fd=31 closed connection
2020-09-30T00:09:54.012633818Z [2020/09/30 00:09:54] [trace] [input:syslog:syslog.0 at plugins/in_syslog/syslog_conn.c:73] read()=4 pre_len=0 now_len=4
2020-09-30T00:09:54.013295072Z [2020/09/30 00:09:54] [trace] [input:syslog:syslog.0 at plugins/in_syslog/syslog_conn.c:73] read()=274 pre_len=4 now_len=278
2020-09-30T00:09:54.013308276Z [2020/09/30 00:09:54] [ warn] [input:syslog:syslog.0] error parsing log message with parser 'syslog-rfc5424'
2020-09-30T00:09:54.013312249Z [2020/09/30 00:09:54] [debug] [input:syslog:syslog.0] unparsed log message: 274 <14>1 2020-09-30T00:09:33+00:00 xxxx-xxxxxxx-vpn-non-prod - - - - 1,2020/09/30 00:09:33,4E4FC3A3E6AA87D,SYSTEM,general,0,2020/09/30 00:09:33,,general,,0,0,general,informational,"User xxxxx logged out via CLI from 1.1.1.1",7157,0x0,0,0,0,0,,xxxx-xxxxxxx-vpn-non-prod

Your Environment

• Version used: 1.5.4, 1.5.7-debug
• Environment name and version (e.g. Kubernetes? What version?): Kubernetes 1.15.11
• Filters and plugins: syslog input
• Syslog source: PanOS 9.1.5 IETF syslog over TCP

Thanks!

[fujimotos]

I revisited this issue this morning, and found that flb_strptime()
actually can handle timezone specification like +00:00 .

https://github.com/fluent/fluent-bit/blob/master/src/flb_strptime.c#L513

On a closer look, the root problem here seems to be that the configuration
uses %Z instead of '%z'. According to the strptime(2):

   %z     An RFC-822/ISO 8601 standard timezone specification.

   %Z     The timezone name.

So %Z (upper case) is supposed to be timezone names like GMT.
This issue should be resolved just by switching %Z to %z.

[matthewhembree]

@fujimotos I may be responsible for some confusion here.

In my report above, I stated:

Steps to reproduce the problem:
Try to parse logs with builtin parser syslog-rfc3164.

But the actual errors from the tracelog above were with syslog-rfc5424 which uses this time format.

I also used the custom parser in my config above just to test flipping the case:

        Name        syslog-rfc5424-notfixed-either
        Format      regex
        Regex       ^\<(?<pri>[0-9]{1,5})\>1 (?<time>[^ ]+) (?<host>[^ ]+) (?<ident>[^ ]+) (?<pid>[-0-9]+) (?<msgid>[^ ]+) (?<extradata>(\[(.*?)\]|-)) (?<message>.+)$
        Time_Key    time
        Time_Format %Y-%m-%dT%H:%M:%S.%L%Z
        Time_Keep   On

What I ended up having to use was syslog-rfc3164 and make an adjustment in my logging flow due to the lack of TZ.

I'll test to see if this still matters with your related merge, but I wanted to clarify that initially I tested %Z (custom) and %z (built in).

[github-actions]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days.

[github-actions]

This issue was closed because it has been stalled for 5 days with no activity.