Event Console: KeyError 'YYYY-MM-DD' TIMESTAMP RFC5424 RFC3339

CMK version: 2.1.0p33.cre
OS version: Debian 12

Error message:

2023-09-29 16:41:55,171 [20] [cmk.mkeventd.EventServer] processing message from host x.x.x.x, port 36318: "<133>2023-09-29 18:41:55 host 51890 Lo
gin the web by user on web (x.x.x.x)."
2023-09-29 16:41:55,172 [40] [cmk.mkeventd.EventServer] could not parse message "<133>2023-09-29 18:41:55 host 51890 Login the web by user on web (
x.x.x.x)." ('2023-09-29')
Traceback (most recent call last):
  File "/omd/sites/$SITE/lib/python3/cmk/ec/event.py", line 79, in create_event_from_line
    event = parse_message(line, ipaddress)
  File "/omd/sites/$SITE/lib/python3/cmk/ec/event.py", line 227, in parse_message
    month = _MONTH_NAMES[month_name]
KeyError: '2023-09-29'
2023-09-29 16:41:55,172 [20] [cmk.mkeventd.EventServer] parsed message:
 application:
 core_host:        None
 facility:         1
 host:
 host_in_downtime: False
 ipaddress:        x.x.x.x
 pid:              0
 priority:         0
 text:             <133>2023-09-29 18:41:55 host 51890 Login the web by user on web (x.x.x.x).
 time:             1696001949.023361

Hallo zusammen,
bei mir kommen Syslog Events mit leerem Hostfeld an und die komplette Line taucht im Text auf. Hostname, etc. werden nicht interpretiert und das Event landet nicht da wo es landen soll.

Ich bin mir ziemlich sicher, dass das ein Bug oder eine Regression sein mĂĽsste, da der Timestamp korrekt nach RFC3339 im Format YYYY-MM-DD HH:mm:ss ist.

Es sind hier jede Menge Varianten wohl auch berĂĽcksichtigt worden, aber nicht der obige.

    # Variant 1: plain syslog message without priority/facility:
    # May 26 13:45:01 Klapprechner CRON[8046]:  message....

    # Variant 1a: plain syslog message without priority/facility/host:
    # May 26 13:45:01 Klapprechner CRON[8046]:  message....

    # Variant 2: syslog message including facility (RFC 3164)
    # <78>May 26 13:45:01 Klapprechner CRON[8046]:  message....

    # Variant 3: local Nagios alert posted by mkevent -n
    # <154>@1341847712;5;Contact Info; MyHost My Service: CRIT - This che

    # Variant 4: remote Nagios alert posted by mkevent -n -> syslog
    # <154>Jul  9 17:28:32 Klapprechner @1341847712;5;Contact Info;  MyHost My Service: CRIT - This che

    # Variant 5: syslog message
    #  Timestamp is RFC3339 with additional restrictions:
    #  - The "T" and "Z" characters in this syntax MUST be upper case.
    #  - Usage of the "T" character is REQUIRED.
    #  - Leap seconds MUST NOT be used.
    # <166>2013-04-05T13:49:31.685Z esx Vpxa: message....

    # Variant 6: syslog message without date / host:
    # <5>SYSTEM_INFO: [WLAN-1] Triggering Background Scan

    # Variant 7: logwatch.ec event forwarding
    # <78>@1341847712 Klapprechner /var/log/syslog: message....

    # Variant 7a: Event simulation
    # <%PRI%>@%TIMESTAMP%;%SL% %HOSTNAME% %syslogtag%: %msg%

    # Variant 8: syslog message from sophos firewall
    # <84>2015:03:25-12:02:06 gw pluto[7122]: listening for IKE messages

    # Variant 9: syslog message (RFC 5424)
    # <134>1 2016-06-02T12:49:05.181+02:00 chrissw7 ChrisApp - TestID - coming from  java code

    # Variant 10:
    # 2016 May 26 15:41:47 IST XYZ Ebra: %LINEPROTO-5-UPDOWN: Line protocol on Interface Ethernet45 (XXX.ASAD.Et45), changed state to up
    # year month day hh:mm:ss timezone HOSTNAME KeyAgent:

Ich lasse mich natĂĽrlich gerne eines Besseren belehren.

PS: Beim versendenden Gerät handelt es sich um einen TP-Link T1500G-8T 2.0, also nichts Exotisches.

Ich habe gesehen, dass es wohl mittlerweile eine 11te Variante gibt. Kann man (/ich, also ein Nicht-Mitarbeiter) sich da irgendwo das Diff zu ansehen?

Des Weiteren scheint es die p34 noch nicht als Docker Image zu geben, sonst würde ich meine Site einfach mal zwecks Testen aktualisieren…

1 Like

Hier ist der Commit zu Werk 16115:

Danke für den Commit. Allerdings löst das das Problem nicht.

Ich habe das gleiche Problem bei unserer Fortigate.

Update auf p33 hat keine Ă„nderung gebracht.

Danke für’s Melden. Je mehr Leute sich zum Problem äußern, desto eher wird (hoffentlich) an der Lösung gearbeitet.

Das Schlimmste ist, dass durch die Exception alle archivierten Events ständig wieder zurückkehren, egal wie oft man es wiederholt. Das ist echt nervig

Vielleicht kann @Sven_Panne etwas beitragen?

Wenn noch irgendwas gebraucht wird an Infos, einfach Bescheid sagen.

Und wieder ein Gerät, das sich nicht an einen simplen Standard halten kann… :roll_eyes: Wenn man sich die problematische Nachricht <133>2023-09-29 18:41:55 host 51890 Login the web by user on web (x.x.x.x). genau anschaut, dann sieht man, daß sie sich weder an die alte noch an die aktuelle syslog-Spezifikation hält. Für die alte Spezifikation müsste der Zeitstempel z.B. Sep 29 18:41:55 lauten, für die neue z.B. 2023-09-29T18:41:55 (da fehlt u.a. auch noch die Version des syslog-Protokolls, aber da wäre die Event-Konsole schon tolerant).

Kurzum: Das wäre neben den 2 offiziellen Formaten und den mittlerweile 11 zusätzlichen falschen Formaten, die die Event-Konsole akzeptiert, eine weitere Variante. Leider sehe ich ad hoc nicht, wie ich das auf die Schnelle fixen könnte ohne dabei eine der anderen 13 Varianten kaputt zu machen. Ich mache mal ein internes Ticket auf, allerdings kann ich nicht sagen, wann wir Zeit dafür haben werden. Falls jemand mit Support-Vertrag dies dringend benötigt, bitte ein entsprechendes Support-Ticket aufmachen, damit wir das entsprechend priorisieren können.

Ansonsten wäre es gut, wenn auch entsprechende Bug-Tickets bei den Geräteherstellern eröffnet würden: Das sind eindeutige Bugs in den Geräten, die 2 RFCs sind sehr einfach und ziemlich eindeutig diesbezüglich. Es wird halt zunehmend komplizierter, in der Event-Konsole um all die vielen verbuggten Geräten herumzuprogrammieren. Ich verstehe ehrlich gesagt nicht, warum die Gerätehersteller eine so simple Sache so oft vergeigen… :sob:

Ach ja: Der letzte Fix, der oben erwähnt wurde, ist in der 2.1.0p34, nicht p33.

1 Like

Könnt ihr es dann wenigstens so einrichten, dass es dann keine unhandled Exception mehr gibt? Das würde dann zumindest den Bug mit dem Archivieren nicht mehr auslösen und man kann sich ja dann mit einem Rulepack die entsprechenden Stellen mit Match Groups “zurechtrücken”.

Für die Geräte, die ich im Einsatz habe, gibt es einfach keine Updates mehr. Sowas ist natürlich das Erste wonach ich schaue. Möchte hier auch nochmal loswerden, dass ich das Produkt nur noch privat einsetze und mich hier zum Dank mit etwas Community Support revanchiere.

Bei 2023-09-29T18:41:55 müsste ja einfach nur das “T” optional gemacht werden und schon hätten wir eine Lösung.

PS: Das mit der p34 ist klar.

Bei 2023-09-29T18:41:55 müsste ja einfach nur das “T” optional gemacht werden und schon hätten wir eine Lösung.

Sooo einfach ist das leider nicht, sonst hätte ich das längst gemacht, das wäre wesentlich einfacher als ein Ticket zu öffnen. :wink: Das Problem ist, daß das Parsen der 2 + 11 chaotischen Varianten recht trickreich ist, alleine das Finden eines potentiellen Zeitstempels innerhalb des Message-Durcheinanders ist alles andere als einfach: Wann genau man wo bei all der Raterei versuchsweise ein “T” einfügen sollte, ist nicht trivial, Details des ganzen Dramas sind hier.

Die Exception ist nicht “unhandled”, sie wird nur geloggt, wenn “Debug rule execution” aktiviert ist. Was genau klappt mit dem Archivieren nicht? Lokal habe ich es getestet, und es scheint alles zu funktionieren, aber evtl. verstehe ich hier etwas nicht.

Hallo, muss mich hier nochmal einklinken.

Wenn ich das richtig verstehe werden hier die 2 + 11 Varianten geprĂĽft.
Unsere Varianten sind darin nicht enthalten, ich nehme an auch bei der 1.6 war mein syslog

<185>date=2023-08-22 time=15:57:42 devname="FGT" devid="FGT...

nie extra enthalten, allerdings wurde dann dort wohl einfach die aktuelle Zeit eingesetzt?

Für mich würde das im Prinzip auch schon reichen, nach dem Motto, “wenn es keine der 2+11 Varianten ist dann verwende als Zeit einfach die aktuelle Systemzeit.”

Im Moment erhalte ich leider ein komplett falsches Datum und Uhrzeit bei “time of last occurrance” :frowning:

Wenn eine Message von der Event-Konsole nicht geparsed werden kann, dann wird die gesamte Message als Text übernommen, Facility ist 1, Priority ist 0, etc. etc. und als Zeit wird die aktuelle Systemzeit genommen, s. hier. Viel mehr lässt sich da nicht machen, immerhin wird die Message nicht komplett verworfen, was wahrscheinlich die schlechtere Alternative wäre.

Und das obige Format ist natürlich auch weit davon entfernt, Spec-konform zu sein. Das schaut für mich nach einem verunglückten Versuch aus, STRUCTURED-DATA zu benutzen. Auch da wäre ein Bug-Ticket beim Hersteller sicherlich angebracht. :wink:

Dann haben wir ja die selbe Vorstellung davon was passieren soll :slight_smile:
Damit wär für mich auch alles in Ordnung und so war es wohl auch bisher.
Ich versteh auch das es nicht der Norm entspricht ein Bug-Ticket beim Hersteller wird hier leider nicht viel ändern :frowning:

Allerdings wird mir in der EC bei “Time of last occurrance” und “Time of first occurrance” ein völlig anderes Datum angezeigt, obwohl “Time of entry in logfile” correct ist.
https://forum.checkmk.com/uploads/default/original/3X/d/7/d741e4268ef3ca478a95b3ba5622eeb0f7d563b0.png

So war es wohl auch bei den nicht konformen Meldungen der Sophos Firewall, bis dort eine extra Variante gebaut wurde?
Mir ist klar das nicht für alle falschen Meldungen extra Varianten gebaut werden können, aber wenn keine Zeit erkannt wird sollte imho auch keine verkehrte letzte Zeit aufscheinen…

1 Like

Das wird vermutlich dann auch der Grund sein, warum bei mir das Archivieren nicht mehr klappt.

Ich versuche das ganze hier mal in Form von Screenshots irgendwie nachvollziehbar zu machen:

  1. Filtern der Events mit leerem Host und mit meiner “catchall syslog” regel, die greift wenn vorher nichts anderes erkannt wurde:
    image

  2. Aus irgendeinem Grund sind es 3 Commands (möglicherweise wegen mehrerer Slaves vom Distributed Monitoring):
    image

  3. Die Anzahl der Gesamt-Events geht von 1xxx auf 44 runter:
    image

  4. Die Events tauchen wieder sukzessive aus dem nichts auf:


    Der hätte ja definitiv von dem Filter oben mitarchiviert werden müssen!

  5. Der nächste erscheint:

  6. Einer geht noch…

In ~/var/log/mkeventd.log:

2023-10-12 19:13:33,042 [20] [cmk.mkeventd.StatusServer] Executing command: DELETE;181036,181034,181035,54520;simonmueller
2023-10-12 19:19:37,892 [20] [cmk.mkeventd.StatusServer] Executing command: DELETE;55297,55296,55268,55267,182855,182856,182857,182858;simonmueller
2023-10-12 19:20:08,376 [20] [cmk.mkeventd.StatusServer] Executing command: DELETE;55273,55274,55391,55388;simonmueller
2023-10-12 19:20:24,794 [20] [cmk.mkeventd.StatusServer] Executing command: DELETE;55903;simonmueller
2023-10-12 19:20:40,674 [20] [cmk.mkeventd.EventServer] Successfully forwarded notification for event 55925 to Check_MK
2023-10-12 19:23:41,044 [20] [cmk.mkeventd.EventServer] Successfully forwarded notification for event 55926 to Check_MK
2023-10-12 19:26:41,410 [20] [cmk.mkeventd.EventServer] Successfully forwarded notification for event 55927 to Check_MK

Die Events sind ja alle (Schnee) von gestern und sollten sowieso nicht mehr eintreffen. Möglicherweise weiß die Event Console durch diese unhandled exception bestimmte Dinge nicht, weil sie eben schon vor dem Moment aussteigt, bevor weitere Dinge passieren.

Sorry fĂĽr die laxe Beschreibung, aber es ist natĂĽrlich viel einfacher nachzuvollziehen wenn man direkt an der Site administriert.

Jedenfalls wenn ich morgen Abend wieder reinschauen würde, dann wären vermutlich wieder alle anderen 1000 Events von diesem (nicht-existenten) Host (^$) da und die EC geht in ihre 1000er Schranke.

Das von dir beschriebene Verhalten tritt so bei mir nicht auf.
Bei mir sind die Events problemlos archivierbar, nur die Zeit ist bei allen die selbe falsche (wie bei dir 2023-10-11 21:01:48).
Das macht ein sortieren nach Zeit unmöglich.

Wenn ich das richtig versteht bekommst du die Meldungen von einem System das nicht im Monitoring ist?
Meine Firewall ist im Monitoring und das Regelwerk greift über die IP, die Regeln setzen dann mit “rewrite hostname” den korrekten Hostnamen.

Eventuell hilft es das Gerät im Monitoring anzulegen und mit Regeln für die Meldungen ebenfalls einen Hostnamen festzulegen um das Verhalten zu beeinflussen?

Der Host existiert, hat den Alias sg2216-dachboden und die ipv4 172.17.255.253 und ich habe folgende Regel:

image

dh. selbst wenn der Hostname nicht matcht, weil dieser nur der shortname ist, sollte er den Host ja eigentlich via IP Adresse oder Alias zuordnen können, was er aber dann nicht mehr tut.

Ich kann deinen Screenshot jetzt leider nicht zuordnen, woher genau der ist?
Ich meinte direkt in der EC Rule ein Rewrite Hostname
2023-10-17 08_00_54-Checkmk Local site ardex - Edit rule FW-UTM-Important-1 – Mozilla Firefox

Unabhängig davon hat sich mein “Zeitproblem” erst erledigt als ich mir selbst eine Variante “92a” gebastelt habe.
Ich denke in deinem Fall müsstest du das dann wohl auch machen…

Hallo! Dieses Problem wird im Werk 16532 für Checkmk 2.4 behoben. Es wird leider kein Backport zu älteren Versionen geben.