Doppelte KNX-Telegramme seit IPS 6.2

Hardware KNX/EIB, LCN
1

Hallo,

seit dieser Woche habe ich das Problem, dass bestimmte Ereignisse in IPS zweimal direkt hintereinander ausgeführt werden.
Ich habe mich dann mal auf Spurensuche begeben und herausgefunden, dass neuerdings wohl KNX-Telegramme in IPS doppelt ankommen bzw. verarbeitet werden. Das wiederum führt dazu, dass Ereignisse, die bei gleichem Wert mehrfach auslösen sollen, nun zweimal hintereinander ausgeführt werden.

Da ich an den betroffenen Instanzen, Ereignissen etc. nichts geändert habe und es erst seit dieser Woche passiert, gehe ich stark davon aus, dass es einen Zusammenhang mit dem Update auf 6.2 gibt.

Ich habe bisher nur einzelne EIS1-Instanzen betrachtet, weil es mir hier durch Zufall aufgefallen ist, und habe noch nicht auf Gateway-Ebene geschaut.
Jedenfalls ist es so, dass wenn ich auf dem Bus etwas schalte, die betroffenen Instanzen zweimal den Wert im Debug der Instanz anzeigen, während im Gruppenmonitor der ETS der Wert korrekterweise nur einmal empfangen wird.

Hier mal ein Beispiel für eine EIS1-Instanz, die den Wert „Ein“ empfängt.

IPS_EIS1_doppelt
IPS_EIS1_doppelt1857×133 12.6 KB

Die Instanzen, die ich bisher analysiert habe, haben nur die Hauptadresse (keine weiteren, auf die gehört wird).
Die Flags in der Instanz sind „Empfangen“ und „Status emulieren“.

Bevor ich jetzt weiter bei anderen Instanzen (auch DPT etc.) analysiere, kurz die Frage an @paresy: Habt ihr da zur 6.2 irgendwas angefasst, was das Verhalten erklären könnte?

Wie gesagt, ich habe an den Instanzen, Ereignissen, an KNX selbst etc. seit Ewigkeiten nichts geändert und das Problem tritt erst seit dieser Woche auf.

Gruß
Slummi

EDIT:
Habe gerade noch mal schnell ins Debug des Gateways (Splitter) geschaut.
Dort kommen die Telegramme ebenfalls doppelt an.

IPS_EIS1_doppelt_Splitter
IPS_EIS1_doppelt_Splitter1797×70 4.23 KB

EDIT 2:
Im Splitter kommt scheinbar jedes Telegramm doppelt an, also unabhängig von der Instanz.

2

Ich bin jetzt gerade noch mal die ganzen Logs durchgegangen.
Bis zum Herunterfahren der 6.1 gibt es für jede KNX-Variable immer genau einen Wert im Log.

Seit dem Hochfahren der 6.2 kommt jede KX-Variable immer doppelt im Log vor (zur gleichen Zeit).

Also irgendwas hat sich da mit der 6.2 definitiv geändert.

3

Hallo Slummi,

bist du sicher, dass es in IPS verdoppelt wird und nicht doch auf dem Bus doppelt vorkommt? Würde der ETS Gruppenmonitor wiederholte Telegramme anzeigen oder sieht man die nur im Busmonitor?

Bei mir kann ich solche doppelten Telegramme mit EIS1 oder anderen Datentypen nicht feststellen.
IP-Symcon 6.2, Windows (amd64), 25.03.2022, f6cba45813ec
Busanbindung über MDT IP-Schnittstelle

edit: Unsere Beiträge haben sich überschnitten. Das klingt bei dir wirklich nach einen IPS-Effekt, den ich hier mit meinem IPS 6.2 aber nicht beobachten kann.

Viele Grüße
Volker

4

Ja, da bin ich mir sicher. Habe es jetzt mehrfach geprüft. Jedes Telegramm wird in der ETS genau einmal angezeigt und in IPS durch die gesamte Kette (I/O - Splitter - Instanz) doppelt.

Das kann ja auch eigentlich kein Zufall sein, dass die Werte exakt seit dem Update auf 6.2 in den Logs alle doppelt vorkommen und in den Logs der 6.1 nicht.

Meine Version ist IP-Symcon 6.2, Windows (amd64), 22.04.2022, b29910a8a667.

Vielleicht sollte ich den Dienst noch mal neu starten…

5

Ich habe mal schnell ein Update gemacht, das Problem tritt hier weiterhin nicht auf.

6

Ich habe gerade mal den Dienst neu gestartet. Weiterhin alles doppelt. Das gibt’s doch nicht. :confused:

Dann muss ich wohl noch ein Trace des LAN-Traffics machen, um zu sehen, was dort konkret ankommt.

7

Wirklich sehr eigenartig. Ich habe jetzt einfach mal den ganzen Server neu gestartet und siehe da, alle Telegramme kommen wieder genau einmal in IPS an, so wie es sich gehört.
Das sieht ja fast so aus als hätte sich das ganze OS irgendwie verhaspelt, wenn der Neustart des Dienstes alleine nicht gereicht hat. Aber warum der Fehler exakt seit Installation der 6.2 aufgetreten ist, ist mir dennoch ein Rätsel.

Auch sehr eigenartig: Nach dem Neustart begrüßte mich die Konsole erst mal hiermit:
IPS_Lizenz

Ich habe dann einfach auf „Prüfe auf aktualisierte Subskription“ geklickt und gut war. Alles sehr mysteriös… :man_shrugging:t3:

8

Das klingt sehr spannend. Ich nutze zu Hause auch KNX und hatte auch extra geschaut, ob das bei mir passiert. Bisher alles ruhig.

Kannst du die Fehlermeldung noch einmal provozieren, wenn du neu startest? Ich vermute du hast das ganze System neu gestartet? Initial nach dem 6.2er Update laden wir einmalig die aktuell assoziierte Subskription von unserem Server. Dies hätte aber bereits bei einem der vorherigen Starts passieren sollen.

paresy

9

Seit dem letzten Neustart des gesamten Servers ist es bei mir auch wieder normal. Alle Telegramme kommen genau einmal an, somit werden die Variablen auch nur einmal aktualsiert und die Ereignisse nicht mehrfach ausgeführt.
Auch die Meldungen haben sich entsprechend reduziert (sowohl im Meldungs-Widget als auch in Prometheus/Grafana).
Der verfügbare RAM hat ebenfalls um ca. 1,4 GB zugenommen. Wobei ich dem jetzt erst mal keine Bedeutung beimessen würde, da es ja durchaus sein kann, dass der RAM bei einem lange laufenden System nach und nach abnimmt.

Ja, die Meldung kann ich reproduzieren. Habe gerade testweise noch mal den ganzen Server neu gestartet (nicht nur den IPS-Dienst). Nach dem ersten Login in der Konsole kommt wieder die Subskriptions-Meldung.

Nach dem Klicken auf erneut prüfen kommt diese Meldung und alles läuft normal:
IPS_Lizenz_OK

Gruß
Slummi

10

Ich habe das soeben versucht nachzustellen, aber bei mir geht es wie erwartet. Ich schreibe dir mal eine PM, ob wir uns das ggf. kurz per TeamViewer zusammen ansehen können.

paresy

11

Ich bin heute bald verrückt geworden… :crazy_face:

Seit ich den Server das letzte Mal neu gestaret habe, war alles in Ordnung mit meinen Telegrammen.
Heute habe ich dann auf die neue Beta der 6.2 aktualisiert. Nach dem Neustart des Dienstes kamen wieder alle KNX-Telegramme doppelt an.
Ich habe den Dienst dann noch mal beendet und neu gestaret, danach kamen alle Telegramme dreifach an. :astonished: Weitere Neustarts des Dienstes haben daran nichts mehr geändert. Es blieb bei einer Verdreifachung der Telegramme.

Also habe ich den gesamten Server neu gestartet (hat ja beim letzten Mal auch geholfen). Dieses Mal aber nicht. Nachdem IPS wieder gestartet war, kamen die Telegramme erneut doppelt (wenigstens nicht mehr dreifach). Weitere Neustarts des Dienstes haben nichts daran geändert, ebenso wenig wie das Öffnen und Schließen des I/Os.
Ich habe mir dann mal auf einem Testsystem ebenfalls ein KNX Gateway (UDP) eingerichtet. Dort kamen alle Telegramme einmal an, genau wie im Gruppenmonitor der ETS.

Danach habe ich direkt das LAN-Interface des Servers getraced und siehe da, auch dort kamen alle Telegramme doppelt an. Ich habe dann den I/O zu gemacht und der dumme Router hat einfach weiter wie doof Telegramme an den Server geschickt. Zwischendurch kamen dann noch ein paar Disconnect Request, die IPS nicht beantwortet hat und dann hat der Router richtig aufgedreht und jedes Telegramm gleich 5-6 Mal raus gehauen. :astonished: Dann wurde es langsam etwas ruhiger. Ich habe daraufhin mal den Router über die ETS zur Sicherheit neu gestartet.

Als ich den I/O wieder aufgemacht habe, wurde zwar sofort ein Tunnel aufgebaut, darüber kamen aber erst mal keine Telegramme rein. Stattdessen wurde der Tunnel nach kurzer Zeit wieder abgebaut und sofort wieder ein neuer aufgebaut. Über den kamen dann auch wieder Telegramme rein. Ganz normal und auch nur einmal, wie es sich gehört.

Ich kann mir zwar immer noch nicht so recht erklären, was das war und warum das ausgerechnet immer nach dem Update und/oder Neustart von IPS passiert ist, aber irgendwie scheint der Router wohl durchgedreht zu sein, weil er nicht wusste, dass der/die Tunnel nicht mehr stehen. Ob der Router den Abbau einfach nicht mitbekommt oder ob IPS den Tunnel beim Herunterfahren nicht korrekt schließt, habe ich noch nicht weiter analysiert.

Ich warte jetzt erst mal ab, beobachte was passiert und frue mich, dass das System jetzt wieder vernünftig läuft und ich endlich ins Bett kann. Wahnsinn, was alles so an verrücktem Zeug passiert. :roll_eyes:

12

Hm. Ich könnte mir folgendes vorstellen: Da UDP ja stateless ist, könnte der Router weiter Daten senden auf der neuen und der alten Verbindung und wir nehmen wahrscheinlich alle Telegramme mit. Ich müsste mal schauen, ob wir Telegramme sauber verwerfen, wenn die nicht für die aktuell aktive Verbindung empfangen werden.

paresy

13

Die Frage hatte ich mir im Nachhinein auch gestellt, warum scheinbar sämtliche Telegramme, die auf dem Interface ankommen, von IPS ausgewertet werden. Jede Tunnel-Verbindung hat ja eine eindeutige ID, auf die man filtern könnte.

Ich muss mir mal die Spec von dem Protokoll raussuchen, wie sich die Geräte bei ausbleibenden Telegrammen verhalten sollen und wie eine Verbindung korrekt beendet wird. Das scheint ja beim Herunterfahren des Dienstes aus irgendeinem Grund nicht geklappt zu haben. Ist die Frage, ob IPS die Verbindung nicht sauber trennt oder mein Router ne Macke hat.

Ich gehe mal davon aus, dass da irgendwann auch ein Timeout greifen muss, wenn Telegramme ausbleiben.

14

Eigentlich ja. Und beim Herunterfahren machen wir eigentlich auch ein Disconnect.

Habe aber tatsächlich zwei Fehler gefunden. Der Disconnect hat nicht korrekt auf ein ACK gewartet und wir haben beim Empfangen der Telegramme vom Gateway nicht sauber auf die ConnectionID geprüft. Beides fixe ich zum nächsten Update der 6.3er und hole es ggf. noch in die 6.2er nach. Es ist immer wieder Spannend, dass man nach so vielen Jahren noch Fehler in der Implementation findet :slight_smile:

paresy

15

Cool, dann hatten die Probleme ja doch etwas gutes. :slight_smile:

Ja, finde ich auch. Wobei maches auch einfach nur durch Zufall auffällt.
Du sagtest ja, dass ihr mit der 6.2 nichts an KNX geändert habt. Vielleicht hat genau zum Zeitpunkt des Updates der Router bei mir angefangen, die Telegramme von abgebrochenen Verbindungen länger als sonst zu senden, sodass es dadurch erst aufgefallen ist. Und wenn ich nicht ein paar Ereignisse hätte, die auch bei Variablen-Aktualisierungen mehrfach auslösen, wäre es mir so schnell vermutlich gar nicht aufgefallen.

16

Weil ich gerade den Server wegen eines anderen Problems (Connect-Dienst Traffic Limit erreicht) neu starten musste, habe ich die Gelegenheit genutzt, um die Kommunikation zwischen IPS und dem KNX-Router nach dem Herunterfahren und Neustarten noch mal zu tracen. Anhand der Ergebnisse würde ich ein Fehlverhalten des Routers ausschließen und sehe hier ein (weiteres) Problem seitens IPS.

Nach dem Herunterfahren des Dienstes gab es keinerlei Kommunikation mehr zwischen dem Server und dem KNX-Router. Es wurden also auch keine Telegramme einer alten Verbindung mehr weitergeleitet.

Nach dem Hochfahren des Servers, baut dieser einen Tunnel zum KNX-Router auf (Tunnel Connection Request). Dieser wird mit einem Tunnel Connection Response unter Angabe der Tunnel-ID bestätigt und der Server beginnt mit der Kommunikation.
Direkt danach schickt der Server erneut ein Tunnel Connection Request raus, welches wiederum vom Router mit einer weiteren Tunnel-ID bestätigt wird. Ab diesem Zeitpunkt läuft die Kommunikation dann über beide Tunnel und ich bekomme natürlich wieder alle Telegramme doppelt. Also der Server baut definitiv mehrere Tunnel beim Start auf. Die Frage ist, warum?

@paresy Erklären deine bisher gefundenen Bugs dieses Verhalten ebenfalls?

17

Ich vermute, dass dies mit den Fixes sauber gelöst sein sollte.

paresy

18

OK, dann warten wir das erst mal ab. Anhand des Traces hätte ich sonst auf folgendes geschlossen:

Ich habe ein Skript, welches periodisch Daten auf den Bus sendet. Dies tut es auch direkt nach dem Server-Start. Ich hätte jetzt vermutet, dass das Skript bereits anfängt Daten auf den Bus zu senden, obwohl die Verbindung noch gar nicht steht. Dies triggert dann den Verbindungsaufbau des Gateways und parallel dazu fängt das Gateway von sich aus an ebenfalls eine weitere Verbindung aufzubauen. Zumindest gehen die Telegramme des Skripts über den ersten Tunnel raus und es handelt sich auch nach dem Neustart des Dienstes um die erste Kommunikation, die überhaupt mit dem Bus erfolgt.

Ich kann das Skript ja mal testweise deaktivieren und dann noch mal neu starten.

19

@paresy

Meine Vermutung hat sich bestätigt. Ich habe jetzt den Skript-Timer deaktiviert und den Dienst beendet. Dann sieht man sehr schön, dass die Zombie-Verbindung, die ganz am Anfang aufgebaut wurde, noch eine ganze Weile nach dem Beenden des Dienstes bestehen bleibt und der Router fleißig weiter Telegramme sendet. Irgendwann schickt der Router dann ein Disconnect Request, weil der Server nicht mehr mit ihm redet.

Danach habe ich den Dienst wieder gestartet und es wird nur ein Tunnel zum KNX-Router aufgebaut.
Aktiviere ich das Skript anschließend wieder, nutzt es den bereits bestehenden Tunnel zum Bus.

Also scheinbar verursacht das Senden von Werten auf den Bus direkt nach dem Start des Dienstes den Aufbau weiterer Verbindungen.

20

@paresy Würde es große Umstände machen, den Fix noch mit in die 6.2 zu ziehen? Irgendwie nervt das ständige Abwarten nach dem Herunterfahren des Dienstes, bis das Interface keine Telegramme mehr sendet.

Die 6.3 wird ja vermutlich noch etwas dauern und mein Produktivsystem möchte ich aktuell noch nicht auf die 6.3 bringen.

Gruß
Slummi