search

open-telemetry / opentelemetry-collector-contrib

Contrib repository for the OpenTelemetry Collector
https://opentelemetry.io
Apache License 2.0
3.12k stars 2.39k forks source link

syslog receiver Error expecting a Stamp timestamp [col 5] #33344

Open massimilianocorsi opened 6 months ago

massimilianocorsi commented 6 months ago

Describe the bug When using the syslog receiver, an error occurs while processing log entries. The error message is "expecting a Stamp timestamp [col 5]".

Steps to reproduce Configure the syslog receiver in the configuration file. Send logs via syslog. Check the logs for the error.

What did you expect to see? I expected the logs to be processed without errors.

What did you see instead? I saw the following error:

{"level":"error","ts":1716980076.4129574,"caller":"helper/transformer.go:98","msg":"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","stacktrace":"github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*TransformerOperator).HandleEntryError\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/helper/transformer.go:98\ngithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*ParserOperator).ParseWith\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/helper/parser.go:140\ngithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*ParserOperator).ProcessWithCallback\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/helper/parser.go:112\ngithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/parser/syslog.(*Parser).Process\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/parser/syslog/syslog.go:184\ngithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*WriterOperator).Write\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/helper/writer.go:53\ngithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/tcp.(*Input).handleMessage\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/input/tcp/tcp.go:321\ngithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/tcp.(*Input).goHandleMessages.func1\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/input/tcp/tcp.go:282"}
{"level":"error","ts":1716980076.4130704,"caller":"helper/transformer.go:98","msg":"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","stacktrace":"github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*TransformerOperator).HandleEntryError\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/helper/transformer.go:98\ngithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*ParserOperator).ParseWith\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/helper/parser.go:140\ngithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*ParserOperator).ProcessWithCallback\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/helper/parser.go:112\ngithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/parser/syslog.(*Parser).Process\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/parser/syslog/syslog.go:184\ngithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*WriterOperator).Write\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/helper/writer.go:53\ngithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/tcp.(*Input).handleMessage\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/input/tcp/tcp.go:321\ngithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/tcp.(*Input).goHandleMessages.func1\n\tgithub.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.97.0/operator/input/tcp/tcp.go:282"}

What version did you use?

  version: 0.82.0

What config did you use?

receivers:
  syslog:
    tcp:
      listen_address: '0.0.0.0:54527'
    protocol: RFC5424
    location: UTC

Environment Openshift

(host)$ helm list
NAME                    NAMESPACE       REVISION        UPDATED                                 STATUS          CHART                   APP VERSION
otel-integration-ac95e  otel-monitoring 1               2024-05-29 09:33:10.348891722 +0000 UTC deployed        otel-integration-0.0.68
github-actions[bot] commented 5 months ago

Pinging code owners for receiver/syslog: @djaglowski @andrzej-stencel. See Adding Labels via Comments if you do not have permissions to add labels yourself.

djaglowski commented 5 months ago

Can you please share with us an example log which is failing to parse?

massimilianocorsi commented 5 months ago

Can you please share with us an example log which is failing to parse?

Hi, Unfortunately, I have not been able to identify which syslog is generating this error in the parser.

github-actions[bot] commented 3 months ago

This issue has been inactive for 60 days. It will be closed in 60 days if there is no activity. To ping code owners by adding a component label, see Adding Labels via Comments, or if you are unsure of which component this issue relates to, please ping @open-telemetry/collector-contrib-triagers. If this issue is still relevant, please ping the code owners or leave a comment explaining why it is still relevant. Otherwise, please close it.

Pinging code owners:

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

bowling233 commented 1 month ago

@djaglowski Hi, I'm facing the same issue when receiving syslog from network devices. Here is an example log which is failing to parse, Hex + ASCII dump:

0000   3c 31 38 38 3e 4f 63 74 20 20 33 20 32 30 32 34   <188>Oct  3 2024
0010   20 31 33 3a 31 39 3a 33 33 20 48 75 61 77 65 69    13:19:33 Huawei
0020   20 57 4c 41 4e 2f 34 2f 53 54 41 54 49 4f 4e 5f    WLAN/4/STATION_
0030   4f 4e 4c 49 4e 45 5f 4e 4f 54 49 46 59 3a 4f 49   ONLINE_NOTIFY:OI
0040   44 20 31 2e 33 2e 36 2e 31 2e 34 2e 31 2e 32 30   D 1.3.6.1.4.1.20
0050   31 31 2e 36 2e 31 33 39 2e 32 2e 31 2e 31 2e 34   11.6.139.2.1.1.4
0060   36 20 54 68 65 20 53 74 61 74 69 6f 6e 20 67 6f   6 The Station go
0070   20 6f 6e 6c 69 6e 65 2e 20 28 41 50 49 44 3d 30    online. (APID=0
0080   2c 53 74 61 74 69 6f 6e 20 20 4d 41 43 3d 5b 37   ,Station  MAC=[7
0090   61 2e 34 38 2e 30 64 2e 38 33 2e 32 66 2e 36 36   a.48.0d.83.2f.66
00a0   20 28 68 65 78 29 5d 2c 20 41 50 20 4d 61 63 3d    (hex)], AP Mac=
00b0   5b 37 63 2e 64 39 2e 61 30 2e 31 30 2e 65 39 2e   [7c.d9.a0.10.e9.
00c0   39 65 20 28 68 65 78 29 5d 2c 20 52 61 64 69 6f   9e (hex)], Radio
00d0   20 49 44 3d 31 2c 20 53 74 61 74 69 6f 6e 20 41    ID=1, Station A
00e0   63 63 65 73 73 20 43 68 61 6e 6e 65 6c 3d 31 34   ccess Channel=14
00f0   39 2c 20 53 74 61 74 69 6f 6e 20 52 53 53 49 3d   9, Station RSSI=
0100   31 39 32 31 2c 20 4f 63 63 75 72 20 54 69 6d 65   1921, Occur Time
0110   3d 32 30 32 34 2d 31 30 2d 30 33 20 31 33 3a 31   =2024-10-03 13:1
0120   39 3a 33 33 29                                    9:33)

The error report from otel-collector are as follows:

2024-10-03T05:19:40.645Z    error   helper/transformer.go:100       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 14]", "action": "send"}
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*TransformerOperator).HandleEntryError
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/helper/transformer.go:100
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*ParserOperator).ParseWith
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/helper/parser.go:138
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*ParserOperator).ProcessWithCallback
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/helper/parser.go:111
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/parser/syslog.(*Parser).Process
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/parser/syslog/parser.go:55
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*WriterOperator).Write
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/helper/writer.go:54
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/udp.(*Input).handleMessage
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/input/udp/input.go:223
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/udp.(*Input).processMessage
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/input/udp/input.go:113
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/udp.(*Input).readAndProcessMessages
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/input/udp/input.go:106
2024-10-03T05:19:40.646Z    error   udp/input.go:225        Failed to write entry   {"kind": "receiver", "name": "syslog", "data_type": "logs", "operator_id": "syslog_input_internal_udp", "operator_type": "udp_input", "error": "expecting a Stamp timestamp [col 14]"}
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/udp.(*Input).handleMessage
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/input/udp/input.go:225
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/udp.(*Input).processMessage
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/input/udp/input.go:113
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/udp.(*Input).readAndProcessMessages
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/input/udp/input.go:106
2024-10-03T05:19:40.691Z    error   helper/transformer.go:100       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"}
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*TransformerOperator).HandleEntryError
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/helper/transformer.go:100
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*ParserOperator).ParseWith
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/helper/parser.go:138
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*ParserOperator).ProcessWithCallback
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/helper/parser.go:111
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/parser/syslog.(*Parser).Process
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/parser/syslog/parser.go:55
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/helper.(*WriterOperator).Write
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/helper/writer.go:54
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/udp.(*Input).handleMessage
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/input/udp/input.go:223
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/udp.(*Input).processMessage
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/input/udp/input.go:113
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/udp.(*Input).readAndProcessMessages
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/input/udp/input.go:106
2024-10-03T05:19:40.691Z    error   udp/input.go:225        Failed to write entry   {"kind": "receiver", "name": "syslog", "data_type": "logs", "operator_id": "syslog_input_internal_udp", "operator_type": "udp_input", "error": "expecting a Stamp timestamp [col 5]"}
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/udp.(*Input).handleMessage
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/input/udp/input.go:225
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/udp.(*Input).processMessage
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/input/udp/input.go:113
github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/udp.(*Input).readAndProcessMessages
    github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza@v0.110.0/operator/input/udp/input.go:106
2024-10-03T05:19:40.814Z    info    LogsExporter    {"kind": "exporter", "data_type": "logs", "name": "debug", "resource logs": 1, "log records": 2}
2024-10-03T05:19:40.815Z    info    ResourceLog #0
Resource SchemaURL: 
ScopeLogs #0
ScopeLogs SchemaURL: 
InstrumentationScope  
LogRecord #0
ObservedTimestamp: 2024-10-03 05:19:40.637529562 +0000 UTC
Timestamp: 1970-01-01 00:00:00 +0000 UTC
SeverityText: 
SeverityNumber: Unspecified(0)
Body: Str(<188>Oct  3 2024 13:19:33 Huawei WLAN/4/STATION_ONLINE_NOTIFY:OID 1.3.6.1.4.1.2011.6.139.2.1.1.46 The Station go online. (APID=0,Station  MAC=[7a.48.0d.83.2f.66 (hex)], AP Mac=[7c.d9.a0.10.e9.9e (hex)], Radio ID=1, Station Access Channel=149, Station RSSI=1921, Occur Time=2024-10-03 13:19:33))
Attributes:
     -> net.host.ip: Str(::)
     -> net.host.port: Str(514)
     -> net.host.name: Str(::)
     -> net.peer.ip: Str(192.168.1.1)
     -> net.peer.port: Str(49155)
     -> net.peer.name: Str(192.168.1.1)
     -> net.transport: Str(IP.UDP)
Trace ID: 
Span ID: 
Flags: 0

And here is my configuration:

receivers:
  syslog:
    udp:
      listen_address: "0.0.0.0:514"
      add_attributes: true
      one_log_per_packet: true
    protocol: rfc3164
    location: Asia/Shanghai
bowling233 commented 1 month ago

After reading RFC 3164, I found that the issue occurs because HUAWEI does not follow the TIMESTAMP field format as defined in the RFC. According to RFC 3164, the TIMESTAMP field should be in the format Mmm dd hh:mm:ss, but HUAWEI adds the year (YYYY) between Mmm and dd, which causes the FSM (Finite State Machine) in go-syslog to fail.

HUAWEI defines multiple timestamp formats: mm dd yyyy hh:mm:ss is referred to as the "date" type and is set as the default. However, they also provide a "short-date" type that adheres to RFC 3164. After configuring it to use the "short-date" format, the error was resolved.

Given that many software and hardware manufacturers do not strictly adhere to specifications, this type of error is quite common. It may be helpful to mention in the documentation that users should verify whether the original format strictly complies with the RFC before opening an issue.

djaglowski commented 1 month ago

Thanks for reporting the example and figuring out the cause @bowling233.

I agree there are many instances where slight variations of the syslog protocol cause problems. In principle I am supportive of being more flexible but it is easier said than done. I think the documentation is clear about which protocols it supports but perhaps adding an additional note as you suggested would be helpful.