loki.source.syslog rfc3164 - timestamp not parsed

[Nachtfalkeaw]

What's wrong?

Hello,

this is my log entry on the local /var/log/messages of the device:

Sun Dec 15 23:15:06 2024 authpriv.info dropbear[13472]: Child connection from 192.168.178.10:62593

this is the tcpdump

23:15:06.030228 ens3  In  IP (tos 0x0, ttl 64, id 33847, offset 0, flags [DF], proto UDP (17), length 161)
    192.168.178.7.47913 > 192.168.178.51.5514: [udp sum ok] UDP, length 133
        0x0000:  4500 00a1 8437 4000 4011 d088 c0a8 b207  E....7@.@.......
        0x0010:  c0a8 b233 bb29 158a 008d 5081 3c38 363e  ...3.)....P.<86>
        0x0020:  4465 6320 3135 2032 333a 3135 3a30 3620  Dec.15.23:15:06.
        0x0030:  5541 502d 4143 2d4d 4761 7274 656e 2064  UAP-AC-MGarten.d
        0x0040:  3862 3337 3063 3039 3735 322c 5541 502d  8b370c09752,UAP-
        0x0050:  4143 2d4d 6573 682d 362e 362e 3737 2b31  AC-Mesh-6.6.77+1
        0x0060:  3534 3032 3a20 6472 6f70 6265 6172 5b31  5402:.dropbear[1
        0x0070:  3334 3732 5d3a 2043 6869 6c64 2063 6f6e  3472]:.Child.con
        0x0080:  6e65 6374 696f 6e20 6672 6f6d 2031 3932  nection.from.192
        0x0090:  2e31 3638 2e31 3738 2e31 303a 3632 3539  .168.178.10:6259
        0x00a0:  33                                       3

and this is the live_debugging of a loki.process. As you can see the incoming timestamp has 0000 as year:

[IN]: timestamp: 0000-12-15T23:15:06Z, entry: dropbear[13472]: Child connection from 192.168.178.10:62593, labels: {application="d8b370c09752,UAP-AC-Mesh-6.6.77+15402", connection_hostname="uap-ac-m-garten.fritz.box.,UAP-AC-M_Garten.fritz.box.,UAP-AC-MGarten.fritz.box.", connection_ip_address="192.168.178.7", facility="authpriv", format="rfc3164", instance="UAP-AC-MGarten", level="informational", message_app_name="d8b370c09752,UAP-AC-Mesh-6.6.77+15402", message_facility="authpriv", message_hostname="UAP-AC-MGarten", message_severity="informational", port="5514", protocol="udp", service_name="syslog_rfc3164_5514"}


[OUT]: timestamp: 0000-12-15T23:15:06Z, entry: dropbear[13472]: Child connection from 192.168.178.10:62593, labels: {application="d8b370c09752,UAP-AC-Mesh-6.6.77+15402", connection_hostname="uap-ac-m-garten.fritz.box.,UAP-AC-M_Garten.fritz.box.,UAP-AC-MGarten.fritz.box.", connection_ip_address="192.168.178.7", facility="authpriv", format="rfc3164", instance="UAP-AC-MGarten", level="informational", message_app_name="d8b370c09752,UAP-AC-Mesh-6.6.77+15402", message_facility="authpriv", message_hostname="UAP-AC-MGarten", message_severity="informational", port="5514", protocol="udp", service_name="syslog_rfc3164_5514"}

this is the loki.source.syslog which is in front of the loki.process. loki.process is for live_debugging purposes.

loki.source.syslog "syslog_receiver_udp_5514" {
  listener {
    address = "0.0.0.0:5514"
    protocol = "udp"
    use_incoming_timestamp = true
    max_message_length = 0                         // 0=unlimited ansonsten Angabe in Bytes
    syslog_format = "rfc3164"
    labels = {
      protocol = "udp",
      format = "rfc3164",
      port = "5514",
      service_name = "syslog_rfc3164_5514",
    }
  }
  relabel_rules = loki.relabel.syslog_01.rules
  forward_to = [loki.process.syslog_processor.receiver]
}

Steps to reproduce

try to parse the log line / use the log line from tcpdump and parse timestamp

System information

Linux ubiquiti 5.10.0-33-amd64 #1 SMP Debian 5.10.226-1 (2024-10-03) x86_64 GNU/Linux

Software version

Grafana Alloy 1.5.1

Configuration

loki.source.syslog "syslog_receiver_udp_5514" {
  listener {
    address = "0.0.0.0:5514"
    protocol = "udp"
    use_incoming_timestamp = true
    max_message_length = 0                         // 0=unlimited ansonsten Angabe in Bytes
    syslog_format = "rfc3164"
    labels = {
      protocol = "udp",
      format = "rfc3164",
      port = "5514",
      service_name = "syslog_rfc3164_5514",
    }
  }
  relabel_rules = loki.relabel.syslog_01.rules
  forward_to = [loki.process.syslog_processor.receiver]
}

Logs

this is my log entry on the local /var/log/messages of the device:

`Sun Dec 15 23:15:06 2024 authpriv.info dropbear[13472]: Child connection from 192.168.178.10:62593`

this is the tcpdump


23:15:06.030228 ens3  In  IP (tos 0x0, ttl 64, id 33847, offset 0, flags [DF], proto UDP (17), length 161)
    192.168.178.7.47913 > 192.168.178.51.5514: [udp sum ok] UDP, length 133
        0x0000:  4500 00a1 8437 4000 4011 d088 c0a8 b207  E....7@.@.......
        0x0010:  c0a8 b233 bb29 158a 008d 5081 3c38 363e  ...3.)....P.<86>
        0x0020:  4465 6320 3135 2032 333a 3135 3a30 3620  Dec.15.23:15:06.
        0x0030:  5541 502d 4143 2d4d 4761 7274 656e 2064  UAP-AC-MGarten.d
        0x0040:  3862 3337 3063 3039 3735 322c 5541 502d  8b370c09752,UAP-
        0x0050:  4143 2d4d 6573 682d 362e 362e 3737 2b31  AC-Mesh-6.6.77+1
        0x0060:  3534 3032 3a20 6472 6f70 6265 6172 5b31  5402:.dropbear[1
        0x0070:  3334 3732 5d3a 2043 6869 6c64 2063 6f6e  3472]:.Child.con
        0x0080:  6e65 6374 696f 6e20 6672 6f6d 2031 3932  nection.from.192
        0x0090:  2e31 3638 2e31 3738 2e31 303a 3632 3539  .168.178.10:6259
        0x00a0:  33                                       3


and this is the live_debugging of a loki.process. As you can see the incoming timestamp has 0000 as year:

[IN]: timestamp: 0000-12-15T23:15:06Z, entry: dropbear[13472]: Child connection from 192.168.178.10:62593, labels: {application="d8b370c09752,UAP-AC-Mesh-6.6.77+15402", connection_hostname="uap-ac-m-garten.fritz.box.,UAP-AC-M_Garten.fritz.box.,UAP-AC-MGarten.fritz.box.", connection_ip_address="192.168.178.7", facility="authpriv", format="rfc3164", instance="UAP-AC-MGarten", level="informational", message_app_name="d8b370c09752,UAP-AC-Mesh-6.6.77+15402", message_facility="authpriv", message_hostname="UAP-AC-MGarten", message_severity="informational", port="5514", protocol="udp", service_name="syslog_rfc3164_5514"}


[OUT]: timestamp: 0000-12-15T23:15:06Z, entry: dropbear[13472]: Child connection from 192.168.178.10:62593, labels: {application="d8b370c09752,UAP-AC-Mesh-6.6.77+15402", connection_hostname="uap-ac-m-garten.fritz.box.,UAP-AC-M_Garten.fritz.box.,UAP-AC-MGarten.fritz.box.", connection_ip_address="192.168.178.7", facility="authpriv", format="rfc3164", instance="UAP-AC-MGarten", level="informational", message_app_name="d8b370c09752,UAP-AC-Mesh-6.6.77+15402", message_facility="authpriv", message_hostname="UAP-AC-MGarten", message_severity="informational", port="5514", protocol="udp", service_name="syslog_rfc3164_5514"}

[Nachtfalkeaw]

The behaviour is the same for tcp and same rfc3154 from a different device.

Live Debugging Alloy loki.process after loki.source.syslog:

[IN]: timestamp: 0000-12-16T00:29:29Z, entry: conn log: Users: addim, Source IP: 192.168.178.10, Computer name: ---, Connection type: HTTP, Accessed resources: Administration, Action: Login Fail, labels: {application="qulogd", connection_hostname="HASE-NAS.fritz.box.", connection_ip_address="192.168.178.50", facility="daemon", format="rfc3164", instance="HASE-NAS", level="warning", message_app_name="qulogd", message_facility="daemon", message_hostname="HASE-NAS", message_proc_id="12945", message_severity="warning", port="5514", proc_id="12945", protocol="tcp", service_name="syslog_rfc3164_5514"}


[OUT]: timestamp: 0000-12-16T00:29:29Z, entry: conn log: Users: addim, Source IP: 192.168.178.10, Computer name: ---, Connection type: HTTP, Accessed resources: Administration, Action: Login Fail, labels: {application="qulogd", connection_hostname="HASE-NAS.fritz.box.", connection_ip_address="192.168.178.50", facility="daemon", format="rfc3164", instance="HASE-NAS", level="warning", message_app_name="qulogd", message_facility="daemon", message_hostname="HASE-NAS", message_proc_id="12945", message_severity="warning", port="5514", proc_id="12945", protocol="tcp", service_name="syslog_rfc3164_5514"}

tcpdump:

00:29:26.971832 ens3  In  IP (tos 0x0, ttl 64, id 23267, offset 0, flags [DF], proto TCP (6), length 245)
    192.168.178.50.41276 > 192.168.178.51.5514: Flags [P.], cksum 0xe69e (incorrect -> 0x0cd5), seq 1:194, ack 1, win 128, options [nop,nop,TS val 2590902613 ecr 3131239026], length 193
        0x0000:  4500 00f5 5ae3 4000 4006 f968 c0a8 b232  E...Z.@[email protected]
        0x0010:  c0a8 b233 a13c 158a 3fca 2669 4d86 f137  ...3.<..?.&iM..7
        0x0020:  8018 0080 e69e 0000 0101 080a 9a6e 0955  .............n.U
        0x0030:  baa2 ea72 3c32 383e 4465 6320 3136 2030  ...r<28>Dec.16.0
        0x0040:  303a 3239 3a32 3920 4841 5345 2d4e 4153  0:29:29.HASE-NAS
        0x0050:  2071 756c 6f67 645b 3132 3934 355d 3a20  .qulogd[12945]:.
        0x0060:  636f 6e6e 206c 6f67 3a20 5573 6572 733a  conn.log:.Users:
        0x0070:  2061 6464 696d 2c20 536f 7572 6365 2049  .addim,.Source.I
        0x0080:  503a 2031 3932 2e31 3638 2e31 3738 2e31  P:.192.168.178.1
        0x0090:  302c 2043 6f6d 7075 7465 7220 6e61 6d65  0,.Computer.name
        0x00a0:  3a20 2d2d 2d2c 2043 6f6e 6e65 6374 696f  :.---,.Connectio
        0x00b0:  6e20 7479 7065 3a20 4854 5450 2c20 4163  n.type:.HTTP,.Ac
        0x00c0:  6365 7373 6564 2072 6573 6f75 7263 6573  cessed.resources
        0x00d0:  3a20 4164 6d69 6e69 7374 7261 7469 6f6e  :.Administration
        0x00e0:  2c20 4163 7469 6f6e 3a20 4c6f 6769 6e20  ,.Action:.Login.
        0x00f0:  4661 696c 0a                             Fail.

This device offers the possibility to send some logs in parallel to another syslog receiver using the rfc5424.
In this case the loki.source.syslog works.

[IN]: timestamp: 2024-12-16T00:29:29.127+01:00, entry: <28>1 2024-12-16T00:29:29.127+01:00 HASE-NAS qulogd: 12945 - [QuLog@Access action="256" action_result="0" application="---" client_agent="Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36" client_app="Web Desktop" client_id="db61e77a-c3fd-48d1-a83c-2e0589d619fb" computer="---" extra_data="" ip="192.168.178.10" mac="00:08:9b:e2:28:6c" service="4" source="HASE-NAS" user="addim"] Administration, labels: {application="qulogd:", connection_hostname="HASE-NAS.fritz.box.", connection_ip_address="192.168.178.50", facility="daemon", format="rfc5424", instance="HASE-NAS", level="warning", message_app_name="qulogd:", message_facility="daemon", message_hostname="HASE-NAS", message_proc_id="12945", message_severity="warning", port="514", proc_id="12945", protocol="tcp", service_name="syslog_rfc5424_514"}

[OUT]: timestamp: 2024-12-16T00:29:29.127+01:00, entry: <28>1 2024-12-16T00:29:29.127+01:00 HASE-NAS qulogd: 12945 - [QuLog@Access action="256" action_result="0" application="---" client_agent="Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36" client_app="Web Desktop" client_id="db61e77a-c3fd-48d1-a83c-2e0589d619fb" computer="---" extra_data="" ip="192.168.178.10" mac="00:08:9b:e2:28:6c" service="4" source="HASE-NAS" user="addim"] Administration, labels: {application="qulogd:", connection_hostname="HASE-NAS.fritz.box.", connection_ip_address="192.168.178.50", facility="daemon", format="rfc5424", instance="HASE-NAS", level="warning", message_app_name="qulogd:", message_facility="daemon", message_hostname="HASE-NAS", message_proc_id="12945", message_severity="warning", port="514", proc_id="12945", protocol="tcp", service_name="syslog_rfc5424_514"}

For me it seems to be a parsing issue of the timestamp in rfc3164.

I had a look at the rfc3164 and for me the timestamp of my applicating should be in the list of valid timestamps.
From the tcpdumps the first and second line of the rfc examples should match.

 <34>Oct 11 22:14:15 mymachine su: 'su root' failed for lonvickon /dev/pts/8
 <13>Feb  5 17:32:18 10.0.0.99 Use the BFG!
<165>Aug 24 05:34:00 CST 1987 mymachine myproc[10]: %% It'stime to make the do-nuts.  %%  Ingredients: Mix=OK, Jelly=OK #Devices: Mixer=OK, Jelly_Injector=OK, Frier=OK # Transport:Conveyer1=OK, Conveyer2=OK # %%
  <0>1990 Oct 22 10:52:01 TZ-6 scapegoat.dmz.example.org 10.1.2.3 sched[0]: That's All Folks!
  <0>Oct 22 10:52:12 scapegoat 1990 Oct 22 10:52:01 TZ-6 scapegoat.dmz.example.org 10.1.2.3 sched[0]: That's All Folks!

https://datatracker.ietf.org/doc/html/rfc3164#section-5.4

[Nachtfalkeaw]

Hello,

i tried to replicate the issue and it looks like it is parsing the timestamp for whatever reason as 1754.
Alloys loki.write error message indicates that timestamp is too old.

You should be able to replicate it ussing "logger"

logger --server 192.168.178.51 --port 5514 --tcp --rfc3164 "TEST_SYSLOG_TEST tcp rfc3164"

logger --server 192.168.178.51 --port 5514 --udp --rfc3164 "TEST_SYSLOG_TEST udp rfc3164"

[dehaansa]

It looks like the fact that loki handles syslog in this way was known and handled in loki by supporting 0-year timestamps in parsing.

However, there is also an option in the go-syslog library's parser used by loki (alloy embeds this implementation) to use the current year in the state machine options. I'm not certain why that wasn't implemented in loki, but I can take a look.