syslog receiver timestamp block not valid

[matthewmodestino]

Component(s)

receiver/syslog

Describe the issue you're reporting

The syslogreceiver docs say you can set a timestamp block in the root of the receiver config.

https://github.com/open-telemetry/opentelemetry-collector-contrib/tree/main/receiver/syslogreceiver#configuration

timestamp	nil	An optional timestamp block which will parse a timestamp field before passing the entry to the output operator

However, while trying to help a user debug an error with their incoming syslog:

2023-10-11T15:44:15.055-0400 error helper/transformer.go:98 Failed to process entry {"kind": "receiver", "name": "syslog", "data_type": "logs", "operator_id": "syslog_input_internal_parser", "operator_type": "syslog_parser", "error": "expecting a Stamp timestamp [col 5]", "action": "send", "entry": {"observed_timestamp":"2023-10-11T15:44:15.055183735-04:00","timestamp":"0001-01-01T00:00:00Z","body":"<189>date=2023-10-11 time=15:44:14 devname=\"FG81EPTKxxxxxxxxx\" devid=\"FG81EPTKxxxxxxxxx\" logid=\"0000000013\" type=\"traffic\" subtype=\"forward\" level=\"notice\" vd=\"root\" eventtime=1697053455006125684 tz=\"-0400\" srcip=192.168.13.16 srcname=\"500-64dba0f5d22a\" srcport=123 srcintf=\"Kape\" srcintfrole=\"lan\" dstip=xxx.xxx.16.12 dstport=123 dstintf=\"wan1\" dstintfrole=\"wan\" sessionid=28068198 proto=17 action=\"accept\" policyid=1 policytype=\"policy\" poluuid=\"17db15fc-2883-51e9-5365-52f4a7edf752\" service=\"NTP\" dstcountry=\"United States\" srccountry=\"Reserved\" trandisp=\"snat\" transip=xx.xx.xx.37 transport=634 appid=16270 app=\"NTP\" appcat=\"Network.Service\" apprisk=\"elevated\" applist=\"default\" duration=180 sentbyte=76 rcvdbyte=76 sentpkt=1 rcvdpkt=1 vwlid=0 utmaction=\"allow\" countapp=1 mastersrcmac=\"xx:xx:a0:f5:d2:2a\" srcmac=\"xx:xx:a0:f5:d2:2a\" srcserver=0","severity":0,"scope_name":""}}

we tried to use the timestamp block to properly parse the message and it says the key is invalid.

Are we configuring it wrong, or misinterpreting this setting? or is it just incorrect?

Fully understand this may have to do with sender not sending rfc compliant message, but docs read like we may be able to override the syslog_input_internal_parser

would appreciate a sanity check! /

Thanks team!

[github-actions]

Pinging code owners:

• receiver/syslog: @djaglowski

See Adding Labels via Comments if you do not have permissions to add labels yourself.

[crobert-1]

I think the error is '' invalid keys: timestamp

Here's a good reference for how to set it up. This functionality is provided by the stanza package, as referenced in the configuration section.

This is essentially what you need instead:

receivers:
  syslog:
    ...
    operators:
    - type: regex_parser
      regex: ...
      timestamp:
        layout: ...

[matthewmodestino]

Right, however that sets the timestamp parsing in an operator block...not in a timestamp block at the root.

Furthermore, the events will error out due to timestamp if we try it in operator block...so was hoping this fields was real...assuming the docs are wrong...and could use a bit more advanced example on what happens when the internal parser borks...does that just mean the rfc is not being followed?

..."operator_id": "syslog_input_internal_parser", "operator_type": "syslog_parser", "error": "expecting a Stamp timestamp [col 5]", , "action": "send",..

Or I guess it says despite the parse error still sends along to the operators...so still may be able to use operator, but would have a ton of parsing errors from the internal parser in this setup.

Looks like user will just ditch syslog receiver for tcplog where we can just use the operators to parse.

[djaglowski]

Thanks for pointing this out @matthewmodestino. I've confirmed that timestamp, as well as other standard "sub-parsers" (e.g. severity, trace), are not available on this receiver because we are embedding only a subset of the syslog parser's capabilities. I've opened #27871 to clarify this in the docs.

From a design perspective, I think this is probably for the better, since really the protocol should contain the timestamp, severity, etc.

events will error out due to timestamp if we try it in operator block

Can you elaborate on this? I was about to suggest using the standalone time_parser:

receivers:
  syslog:
    protocol: ...
    operators:
      - type: time_parser
        layout: ...

[matthewmodestino]

Yeah, I think i see whats happening...the internal syslog parser fails, but still sets the action to send...so basically if the rfc is not followed, or doesn't match what is set in protocol this error would be expected, but then technically an operator block could clean up the mess....

2023-10-11T15:44:15.055-0400 error helper/transformer.go:98 Failed to process entry {"kind": "receiver", "name": "syslog", "data_type": "logs", "operator_id": "syslog_input_internal_parser", "operator_type": "syslog_parser", "error": "expecting a Stamp timestamp [col 5]", "action": "send", "entry": {"observed_timestamp":"2023-10-11T15:44:15.055183735-04:00","timestamp":"0001-01-01T00:00:00Z","body":"<189>date=2023-10-11 time=15:44:14 devname=\"FG81EPTKxxxxxxxxx\" devid=\"FG81EPTKxxxxxxxxx\" logid=\"0000000013\" type=\"traffic\" subtype=\"forward\" level=\"notice\" vd=\"root\" eventtime=1697053455006125684 tz=\"-0400\" srcip=192.168.13.16 srcname=\"500-64dba0f5d22a\" srcport=123 srcintf=\"Kape\" srcintfrole=\"lan\" dstip=xxx.xxx.16.12 dstport=123 dstintf=\"wan1\" dstintfrole=\"wan\" sessionid=28068198 proto=17 action=\"accept\" policyid=1 policytype=\"policy\" poluuid=\"17db15fc-2883-51e9-5365-52f4a7edf752\" service=\"NTP\" dstcountry=\"United States\" srccountry=\"Reserved\" trandisp=\"snat\" transip=xx.xx.xx.37 transport=634 appid=16270 app=\"NTP\" appcat=\"Network.Service\" apprisk=\"elevated\" applist=\"default\" duration=180 sentbyte=76 rcvdbyte=76 sentpkt=1 rcvdpkt=1 vwlid=0 utmaction=\"allow\" countapp=1 mastersrcmac=\"xx:xx:a0:f5:d2:2a\" srcmac=\"xx:xx:a0:f5:d2:2a\" srcserver=0","severity":0,"scope_name":""}}

Source is an old Fortinet FortiGate fwiw...

I guess it will be key to determine when syslog is being "abused" (as it often is) and not following RFC chosen in protocol and recommend user sends to tcplog instead...does that sound accurate?

[djaglowski]

I guess it will be key to determine when syslog is being "abused" (as it often is) and not following RFC chosen in protocol and recommend user sends to tcplog instead...does that sound accurate?

That makes sense to me. Hopefully some pre-processing before running it through the syslog_parser can resolve it.

Maybe the receiver needs to allow special handling for malformed logs.

receiver:
  syslog:
    protocol: ...
    err_operators:
      - type: router
         default: annotate_as_unknown_problem
         routes:
           - expr: ... # matches some known problem
              output: fix_known_problem
      - id: annotate_as_unknown_problem
        type: add
        field: attributes.syslog_error
        value: Invalid syslog format
        output: noop
      - id: fix_known_problem
        type: add
        field: body
        value: ... # fancy expr to correct body
      - type: noop # exit point from operators