Ankündigung

**jdc** · 25.08.2023, 16:15

So, mir reichts, heute nacht um genau 04:00h ist das Problem bei mir wieder aufgetaucht, diesmal auch mit hochzählen der "Verbindungen".
Beachtet, dass es sich hier natürlich nicht um mehrere parallele Tunnel-Verbindungen zu Gateway handelt, sondern EDOMI stellt fest dass eine Kommunikationsstörung vorliegt und versucht das Problem dadurch zu beseitigen den Tunnel neu aufzubauen. Es sind also eher "Verdbindungsversuche".
Ich habe mal am Switch einen Monitorport auf den Port zum KNX Gateway aufgeschaltet und das Problem stellt sich so dar, dass zwar GA-Writes VOM Gateway zu EDOMI ankommen (und auch von EDOMI wahrgenommen werden) aber umgekehrt, also EDOMI nach KNX-Bus (also ZUM Gateway von Ethernet) fehlschlägt. Dafür gibts dann kein Tunnel-ACK vom Gateway und EDOMI dreht durch. Im Monitor (Wireshark) sehe ich zwar das WRITE von EDOMI aber der ACK vom Gateway fehlt. Die Sachen die vom Bus kommen und an EDOMI gehen sehe ich, EDOMI nimmt die ja auch wahr.
Es gibt also zwei Möglichkeiten:

Möglichkeit 1) Am Monitor-Port des Switch zu tracen ist irreführend, die GA-Writes die von EDOMI kommen, kommen am KNX-Gateway nie an weil der Ethernet-link an dem das Gateway hängt PHY-mässig ein Problem hat
Möglichkeit 2) Das KNX-Gateway selbst hängt irgendwie, droppt die GA-Writes, macht nichts und sendet auch kein Tunnel-ACK obwohl die Requests doch ethernetmässig angekommen sind

Um rauszufinden was Sache ist hab ich den Ethernet-Stecker direkt am KNX-Gateway mal abgezogen und meinen Wireshark-Notebook direkt angeschlossen.
Siehe da, die GA-Writes kamen im Wireshark-Trace an, kamen also auch aus dem Switchport raus.
KNX-Gateway wieder angeschlossen und auf einmal lief auch da wieder alles, die Queue in EDOMI baute sich wieder ab und ausser den Log-Einträgen keine Spur mehr vor dem Problem.
Das Rausziehen/Wiedereinstecken des Ethernet-Kabels am Gateway beseitigt das Problem also auch, nicht mehr wie bisher nur das Resetten des Ethernet-Switches. Interessant, macht den Versuch aber leider inconclusive. Notiert sei hier noch, dass bisher wirklich immer der ganze Switch geresettet werden musste. Weder einzelner-Port-reset noch KNX-Bus-reset mittels Busnetzteil-AUS-wiederAN noch EDOMI Neustart hatten manchmal Besserung gebracht. Aber offenbar hilft auch Ethernet-Kabel raus-rein. Gut, neue Erkenntnis. Dummerweise war das Problem jetzt wieder weg, so dass ich hier nicht weiter forschen konnte.

Stattdessen hab ich mal das KNX-Gateway ausgebaut und zerlegt. STM32-Hardware, TI DP83848 PHY Twisted-Pair Transceiver, Elmos 89103A KNX-TP-UART (Notiz: Interessantes Teil! Interessant auch es sind 2 Stück davon verbaut! Aber hier nicht relevant.). Der Rest ist ziemlich Standard. Der Ethernet-MAC ist im STM32 drin. Der PHY ist komplexer als gedacht und der Übertrager fürs 10/100baseT ist in der RJ45-Buchse (Würth 74990100011A) drin. Interessant bei der Buchse ist die Abschirmung vom Kabel geht laut Datenblatt u.a. über den Metallrahmen der Buchse über einen 1000pF/2kV Kondensator an einen Pin, der dann auf dem KNX-Gateway PCB zu einem SMD-Lötpad führt, welches nicht bestückt ist. Ich nehme an, hier ist auch ein C vorgesehen, aber dann weggelassen worden.
Das kommt mir alles sehr seltsam vor. Wie gesagt ich nehme noch ein Erdungsproblem an, da die Probleme oft dann auftreten, wenn irgendwas am Solar-Welchselrichter umschaltet wird oder große Lasten im Haus umgeschaltet werden.

Das Kabel vom Switch ist ein STP-Kabel über STP Hausinstallation. Bis zum KNX-Gateway war bisher also Erde auf der RJ45-Abschirmung. Ich habe das Kabel mal durch ein UTP-Kabel aus der Grabbelbox ersetzt, mal sehen was passiert, bzw. ob die Probleme jetzt weg sind. Ich vermute irgendwie, dass Störungen auf der Erdleitung endweder den Ethernet-PHY TX im Switch oder den Ethernet-RX im KNX-Gateway (dem DP83848) derartig aus dem Tritt bringen (evtl. Erdschleife?) dass diese sich erst dann wieder erholen wenn man den Ethernet-Link komplett inaktiviert und wieder aktiviert.

Weiterhin habe ich mal das proc_knx.php angeschaut. Es gibt in der Tat Situationen, wo wenn Kommunikationsprobleme mit dem KNX-Gateway auftreten die Tunnel-Session mit diesem wieder neu aufgebaut wird, dann zählen die "Verbindungen" im EDOMI-Admin Interface hoch. Genauer hätte man also in der EDOMI-Visu schreiben müssen "Verbindungsversuche". Es gibt aber auch Situationen, wo der Tunnel-Request ad infinitum nur wiederholt wird und das geloggt wird. Dann steht im Log nur "Kein Tunnel ACK" und "Wiederholung". Wenn die Ethernet-Kommunikation gestört ist können natürlich somit beide Möglichkeiten auftreten.

WARUM das passiert krieg ich jetzt raus, ich mach weiter bis ich das komplett debuggt habe bei mir. Es nervt.

Soviel zum Zwischenbericht von mir.
--j

**jdc** · 28.08.2023, 10:17

So, noch ein Zwischenstand nach 1 Tag debugging, Beschäftigung mit dem KNX Tunneling Protokoll, PHP, Scheduling, Datenbanken und Abläufen.
So langsam wird das Bild klarer. Aber nicht einfacher.

Fakt #1:
Zunächst folgendes. PCs, die typischen Betriebssysteme für selbige und auch Ethernet sind eigentlich keine "Echtzeitsysteme". D.h. man kann keine MAXIMALE ZEIT angeben in der ein System bestehend aus KNX Router/GW, Ethernet, Switches, Ethernet-Karte, PC mit UNIX Betriebssystem und Software wie MySQL und EDOMI auf ein externes Ereignis (wie hier z.B. das Betätigen eines KNX Tasters in der Hausinstallation) reagiert. IN DER REGEL sind das nur Millisekunden. Aber was wenn:
- Auf einem Ethernet Strang gerade ein 60GB großer Film kopiert/downloaded abgespielt wird und die KNX UDP Pakete daher warten müssen?
- Ein Impuls auf dem PE durch Wechselrichter-Umschaltereien gerade den PHY im Ethernet-Switch aus dem Konzept gebracht hat und der mal 5 Sekunden braucht um sich zu reinitialisieren?
- Die MySQL Datenbank auf dem EDOMI PC gerade die Datenbankstruktur updated/pflegt/aufräumt?
- Um Mitternacht gerade das EDOMI Projekt die Logik-Engine für 30 Sekunden so richtig zum Schwitzen bringt weil gerade ein Wetterupdate gezogen wurde und nun die ganze Berechnung für Wetterprognose, Photovoltaiksystem-Ertragsberechnung etc. -zig Logikblöcke anwirft, die ordentlich Events queuen und Datenbankzugriffe in MySQL verursachen, möglicherweise auf Tabellen die gerade wg. RAM-mangels ausgelagert sind weil sie nur alle 24h benötigt werden und wieder eingeSWAPt werden müssen? Auf einmal blockiert das Betriebssystem (VFS, ZFS, swapper) sämtliche Userprozesse für 3 bis 10 Sekunden.
- Das auf dem PC laufende Unix System gerade den täglichen/wöchentlichen/monatlichen Filesystemcheck durchführt, was viel RAM kostet, selbiges aber nicht ausreicht und daher Speicher ausgelager (geswapt) wird und das System daher sekundenlang blockiert und die EDOMI Prozesse derweil nicht laufen? Wohlmöglich ist auch eine Festplatte in den Powersave-Modus gegangen und muss jetzt erstmal einen Spinup machen. Blockiert evtl. einen USB Bus wo sie dranhängt damit.
- Irgendwelche anderen Prozesse die noch auf dem PC laufen gerade viel RAM brauchen / swappen / den Prozessor in Beschlag nehmen?
- Prinzipiell kann sogar ein Zugriff über PCI den Rechner beliebig lang lahmlegen
- etc. etc.
Es gibt also realistisch gesehen unendlich viele Möglichkeiten wie die Verarbeitung der KNX UDP Pakete zwischen EDOMI und Gateway verzögert werden können. PC Hardware und Netzwerkequipment ist halt kein Luft-/Raumfahrtsystem oder medizinisches oder automotive Equipment wo auch schon mal richtige Echtzeitsysteme eingesetzt werden. Is halt so.
UDP Pakete können auch mal verloren gehen und werden anders als TCP Pakete dann nicht vom Protokollstack des Betriebssystems wiederholt. Is halt auch so. Evtl. hat der Switch ein Duplex-Mismatch-Problem oder die als Switch eingesetzte FritzBox versucht gerade ein Systemupdate und droppt Frames.
Die Möglichkeiten für sporadischen Paketverlust, Paketverzögerung und Ausführungsverzögerung der Prozesse von EDOMI (und natürlich betrifft das stellvertretend auch andere Heimautomatisierungssysteme auf PC Basis) sind endlos. Man kann vieles Minimieren (z.B. genau abgestimmtes, getestetes, optimiertes System als Docker-Container laufen lassen, eigenen i7-Rechner mit 128GB RAM nur für EDOMI designieren, SSD anstatt spinning-rust HDD verwenden, Prozessprioritäten anpassen mit renice, dabei Priority Inversion vermeiden, KNX UDP Pakete im Switch und OS auf realtime-Prio setzen etc.) aber ganz beseitigen kann man das Problem nicht. Soviel zu Fakt #1.

Fakt #2:
a.) Das KNX UDP Tunneling-Protokoll hat relativ strikte Requirements. In der Regel werden "Services" wie "Tunneling Requests" die z.B. einen Gruppenadressen-Schreibzugriff enthalten nur 1 mal wiederholt übers LAN falls beim ersten mal keine Bestätigung innerhalb von Sekunden (bei mir 2 Sekunden, jedenfalls recht wenig) erfolgt. Wenn dann immer noch keine Bestätigung kommt, disconnected schon das KNX Gateway. Meins jedenfalls. Und ich habe dann nur folgendes im Log:

2023-08-28 09:07:08	957263	KNX	95245	CE < \| DISCONNECT_REQUEST / Raw: 06100209001048000801c0a8db060e57	ERROR
2023-08-28 09:07:09	068253	KNX	95245	KNX-Verbindung verloren.	ERROR

Was jetzt passieren muss ist das EDOMI das mitbekommt und die Verbindung wieder neu aufbaut und weitermacht. Es ist aber zurecht ein "ERROR", weil der Gruppen-Write ja jetzt verloren gegangen ist und nicht nochmal kommt. Hoffentlich war's nur das Einschalten der Kaffeemaschine am Morgen was jetzt ausfällt und nicht das Abschalten des Herds weil alle das Haus verlassen haben und sich drauf verlassen, dass die Heimautomatisierung sie rettet. ;-)

Jedenfalls baut EDOMI die Verbindung recht zuverlässig neu auf. RECHT zuverlässig, weil manchmal offenbar die "Verbindungen" nur hochzählen und alles hängt. Bei mir auch manchmal. Eigentlich können wir nur versuchen das zu fixen, alles andere ist hoffnungslos, s.o..

b.) Pakete könne auch auf dem KNX Bus verloren gehen. Target busy, Bus busy, elektrische Probleme etc. Daraus ergibt sich die Frage wer wie wo wiederholt und wen informiert. Andersherum natürlich auch. Diskutiert hier:

https://knx-user-forum.de/forum/%C3%...on-beim-tunnel

auch:

https://github.com/ioBroker/ioBroker.knx/issues/184

Jetzt ergibt sich daraus eine sehr hohe Komplexität in der Verarbeitung weil all diese Dinge in beliebiger Reihenfolge mit beliebigem Timing vorkommen können und EDOMI damit klarkommen muss.
Das KNX Interface ist der Prozess proc_knx.php. Ich habe momentan noch keine Lösung. Verändern is auch nich. Soviel zum Zwischenstand der Analyse.
Aber hier ist mal ein kleines Skript welches zum Stresstest verwendet werden kann, also um die oben beschriebenen Timingprobleme zu provozieren, bzw. zu simulieren durch starten und stoppen des Prozesses für eine zufällige Anzahl Sekunden:

Code:

#!/bin/bash
# JD 2023-08-28
# Beliebigen UNIX Prozess zufaellige Sekunden anhalten und weiterlaufen lassen.
# Syntax: ./start_stop_stress.sh <pid> <stop_sekunden_max> <continue_sekunden_max>
# z.B. ./start_stop_stress.sh 19545 2 10
# Die PID findet man raus z.B. mit
# ps axlwww | fgrep proc_knx     <--- für freeBSD, für Linux evtl. "ps -aux" verwenden
#
# Abbrechen mit CTRL-C im CONTINUED Zustand sinnvollerweise

while true;
do
    kill -STOP $1;
    echo "STOPPED";
    rand=$(($RANDOM % $2));
    sleep $rand;
    kill -CONT $1;
    echo "CONTINUED";
    rand=$(($RANDOM % $3));
    sleep $rand;
done

Jetzt habe ich ein Tool zum reproduzieren und kann weiter forschen.
Würde mich mal interessieren, was bei Euren Konfigurationen so im Log landet wenn das läuft, am besten mit Angabe zumindest mit welchem KNX Router/GW.

Schöne Woche noch,

--j

**jdc** · 30.08.2023, 08:35

Um unter hoher Systemlast die relativ rigiden echtzeit-Anforderungen des KNX Tunnel Protokolls einzuhalten mag es hilfreich sein, die Prozesse, die für den KNX UDP Kommunikation erforderlich sind zu prioritisieren (s.o.).
Hier ist mal eine Anregung für ein Skript welches dieses tut unter Benutzung des Periodic-Frameworks (note FreeBSD, mag für Linux Abänderung bedürfen). Fummelig aber funktioniert. Die SQL-Datenbank muss mit reprioritisiert werden da EDOMI die als Dreh-und-Angelpunkt für die IPC nutzt und sonst der proc_knx.php darauf wartet was auch nix bringt:

Code:

#!/bin/sh

# If there is a global system configuration file, suck it in.
#
if [ -r /etc/defaults/periodic.conf ]
then
    . /etc/defaults/periodic.conf
    source_periodic_confs
fi

pid_edomi_knx_proc=`pgrep -f "proc_knx.php"`
pid_edomi_mysql_proc=`pgrep -f "libexec/mysqld"`
pids="${pid_edomi_knx_proc} ${pid_edomi_mysql_proc}"

target_prio="-5"

for pid in ${pids};
do
    renice ${target_prio} ${pid} >/dev/null 2>/dev/null;
done

Zusätzlich habe ich die anderen Nacht-Aktivitäten (Backup, ZFS-Snapshot, ZFS-Scrub) etwas entzerrt, d.h. nicht mehr gleichzeitig.
Seit dem Tausch des Ethernet-Kabels durch ein UTP-Kabel keine Hänger mehr, seit obiger Aktion auch keine Wiederholungen, also insgesamt keine Log-Einträge mehr.

--j

**jdc** · 30.08.2023, 14:49

Erwischt.
Heute ist das Problem wieder aufgetreten, ohne Last und im optimierten System, also keine Folge von erhöhter Prozessorlast.
Diesmal lief zufällig Wireshark noch am Monitorport mit und ich konnte die Stelle ausfindig machen.

Zunächst das EDOMI-Log:

2023-08-30 10:39:02	831937	KNX	95245	DE > \| TUNNELING_ACK / Timeout nach 1s / ErrMsg: Kein TUNNELING_ACK vom Router erhalten / Wiederholen	ERROR
2023-08-30 10:39:09	069938	KNX	95245	DE > \| TUNNELING_ACK / Timeout nach 1s / ErrMsg: Kein TUNNELING_ACK vom Router erhalten / Wiederholen	ERROR
2023-08-30 10:39:10	197304	KNX	95245	DE > \| TUNNELING_ACK / Timeout nach 1s / ErrMsg: Kein TUNNELING_ACK vom Router erhalten / Verwerfen	ERROR
2023-08-30 10:39:11	321422	KNX	95245	DE > \| TUNNELING_ACK / Timeout nach 1s / ErrMsg: Kein TUNNELING_ACK vom Router erhalten / Wiederholen	ERROR
2023-08-30 10:39:12	522293	KNX	95245	DE > \| TUNNELING_ACK / Timeout nach 1s / ErrMsg: Kein TUNNELING_ACK vom Router erhalten / Verwerfen	ERROR
2023-08-30 10:39:13	701946	KNX	95245	DE > \| TUNNELING_ACK / Timeout nach 1s / ErrMsg: Kein TUNNELING_ACK vom Router erhalten / Wiederholen	ERROR

Und endlos so weiter. Der EDOMI-TX hing dabei.

Wireshark hat am Monitor-Port folgendes mitgeschnitten (Info: 192.168.170.9 ist EDOMI, 192.168.119.6 das MDT KNX-Gateway):

No. Time Source Destination Protocol Length Info
1344991 168955.712584 192.168.170.9 192.168.119.6 KNXnet/IP 65 TunnelReq #23:50 L_Data.req 15.15.241->1/6/1 GroupValueWrite $168B
1344992 168955.712940 192.168.119.6 192.168.170.9 KNXnet/IP 60 TunnelAck #23:50 OK
1344993 168955.713560 192.168.119.6 224.0.23.12 KNXnet/IP 61 RoutingInd L_Data.ind 15.15.241->1/6/1 GroupValueWrite $168B
1344994 168955.724156 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:30 OK
1344995 168955.724625 192.168.119.6 192.168.170.9 KNXnet/IP 65 TunnelReq #23:31 L_Data.ind 1.2.57->2/7/6 GroupValueWrite $0C1A
1344996 168955.751145 192.168.119.6 224.0.23.12 KNXnet/IP 60 RoutingInd L_Data.ind 1.2.54->7/4/7 GroupValueWrite $00
1344997 168955.847512 192.168.119.6 224.0.23.12 KNXnet/IP 60 RoutingInd L_Data.ind 1.2.54->9/2/10 GroupValueWrite $01
1344998 168955.928237 192.168.170.9 192.168.119.6 KNXnet/IP 64 TunnelReq #23:51 L_Data.req 15.15.241->7/1/16 GroupValueWrite $FF
1344999 168955.928576 192.168.119.6 192.168.170.9 KNXnet/IP 60 TunnelAck #23:51 OK
1345000 168955.929132 192.168.119.6 224.0.23.12 KNXnet/IP 60 RoutingInd L_Data.ind 15.15.241->7/1/16 GroupValueWrite $FF
1345001 168956.678321 192.168.119.6 192.168.170.9 KNXnet/IP 65 TunnelReq #23:31 L_Data.ind 1.2.57->2/7/6 GroupValueWrite $0C1A
1345002 168956.841318 192.168.119.6 224.0.23.12 KNXnet/IP 60 RoutingInd L_Data.ind 1.2.28->3/3/7 GroupValueWrite $01
1345003 168957.065452 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:31 OK
1345004 168957.065963 192.168.119.6 192.168.170.9 KNXnet/IP 65 TunnelReq #23:32 L_Data.con 15.15.241->1/6/0 GroupValueWrite $06C2
1345005 168957.157925 192.168.119.6 224.0.23.12 KNXnet/IP 60 RoutingInd L_Data.ind 1.2.29->3/2/7 GroupValueWrite $01
1345006 168957.234377 192.168.170.9 192.168.119.6 KNXnet/IP 64 TunnelReq #23:51 L_Data.req 15.15.241->7/1/16 GroupValueWrite $FF
1345007 168957.234504 192.168.119.6 192.168.170.9 KNXnet/IP 60 TunnelAck #23:51 OK
1345008 168957.291207 192.168.119.6 224.0.23.12 KNXnet/IP 60 RoutingInd L_Data.ind 1.2.22->3/2/8 GroupValueWrite $00
1345009 168957.336759 192.168.170.9 192.168.119.6 KNXnet/IP 64 TunnelReq #23:52 L_Data.req 15.15.241->2/7/13 GroupValueWrite $FF
1345010 168957.337160 192.168.119.6 192.168.170.9 KNXnet/IP 60 TunnelAck #23:52 OK
1345011 168957.337703 192.168.119.6 224.0.23.12 KNXnet/IP 60 RoutingInd L_Data.ind 15.15.241->2/7/13 GroupValueWrite $FF
1345012 168957.340575 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:31 OK
1345013 168957.341033 192.168.119.6 192.168.170.9 KNXnet/IP 63 TunnelReq #23:33 L_Data.ind 1.2.37->7/4/5 GroupValueWrite $01
1345014 168957.446232 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:32 OK
1345015 168957.446643 192.168.119.6 192.168.170.9 KNXnet/IP 65 TunnelReq #23:34 L_Data.con 15.15.241->1/6/1 GroupValueWrite $168B
1345016 168957.651037 192.168.170.9 192.168.119.6 KNXnet/IP 65 TunnelReq #23:53 L_Data.req 15.15.241->1/6/5 GroupValueWrite $0DAF
1345017 168957.651520 192.168.119.6 192.168.170.9 KNXnet/IP 60 TunnelAck #23:53 OK
1345018 168957.652101 192.168.119.6 224.0.23.12 KNXnet/IP 61 RoutingInd L_Data.ind 15.15.241->1/6/5 GroupValueWrite $0DAF
1345019 168957.759678 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:33 OK
1345020 168957.759960 192.168.119.6 192.168.170.9 KNXnet/IP 63 TunnelReq #23:35 L_Data.ind 1.2.54->7/4/7 GroupValueWrite $00
1345021 168957.866132 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:34 OK
1345022 168957.866404 192.168.119.6 192.168.170.9 KNXnet/IP 63 TunnelReq #23:36 L_Data.ind 1.2.54->9/2/10 GroupValueWrite $01
1345023 168957.971206 192.168.170.9 192.168.119.6 KNXnet/IP 63 TunnelReq #23:54 L_Data.req 15.15.241->1/6/4 GroupValueWrite $01
1345024 168957.971619 192.168.119.6 192.168.170.9 KNXnet/IP 60 TunnelAck #23:54 OK
1345025 168957.972241 192.168.119.6 224.0.23.12 KNXnet/IP 60 RoutingInd L_Data.ind 15.15.241->1/6/4 GroupValueWrite $01
1345026 168958.079322 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:35 OK
1345027 168958.079816 192.168.119.6 192.168.170.9 KNXnet/IP 64 TunnelReq #23:37 L_Data.con 15.15.241->7/1/16 GroupValueWrite $FF
1345028 168958.187558 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:36 OK
1345029 168958.187915 192.168.119.6 192.168.170.9 KNXnet/IP 63 TunnelReq #23:38 L_Data.ind 1.2.28->3/3/7 GroupValueWrite $01
1345030 168958.404944 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:37 OK
1345031 168958.405240 192.168.119.6 192.168.170.9 KNXnet/IP 63 TunnelReq #23:39 L_Data.ind 1.2.29->3/2/7 GroupValueWrite $01
1345032 168958.502084 192.168.119.6 224.0.23.12 KNXnet/IP 61 RoutingInd L_Data.ind 1.2.54->2/5/3 GroupValueWrite $0C4C
1345033 168958.515213 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:38 OK
1345034 168958.515569 192.168.119.6 192.168.170.9 KNXnet/IP 63 TunnelReq #23:40 L_Data.ind 1.2.22->3/2/8 GroupValueWrite $00
1345035 168958.625377 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:39 OK
1345036 168958.625509 192.168.119.6 192.168.170.9 KNXnet/IP 64 TunnelReq #23:41 L_Data.con 15.15.241->2/7/13 GroupValueWrite $FF
1345037 168958.734363 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:40 OK
1345038 168958.734486 192.168.119.6 192.168.170.9 KNXnet/IP 65 TunnelReq #23:42 L_Data.con 15.15.241->1/6/5 GroupValueWrite $0DAF
1345039 168958.844496 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:41 OK
1345040 168958.844625 192.168.119.6 192.168.170.9 KNXnet/IP 63 TunnelReq #23:43 L_Data.con 15.15.241->1/6/4 GroupValueWrite $01
1345041 168958.956990 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:42 OK
1345042 168958.957273 192.168.119.6 192.168.170.9 KNXnet/IP 65 TunnelReq #23:44 L_Data.ind 1.2.54->2/5/3 GroupValueWrite $0C4C
1345043 168959.065440 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:43 OK
1345044 168959.174255 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:44 OK
1345045 168961.841124 192.168.119.6 224.0.23.12 KNXnet/IP 60 RoutingInd L_Data.ind 1.2.28->3/3/5 GroupValueWrite $01
1345046 168961.841646 192.168.119.6 192.168.170.9 KNXnet/IP 63 TunnelReq #23:45 L_Data.ind 1.2.28->3/3/5 GroupValueWrite $01
1345047 168961.862264 192.168.119.6 224.0.23.12 KNXnet/IP 60 RoutingInd L_Data.ind 1.2.28->3/3/6 GroupValueWrite $01
1345048 168961.865098 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:45 OK
1345049 168961.865455 192.168.119.6 192.168.170.9 KNXnet/IP 63 TunnelReq #23:46 L_Data.ind 1.2.28->3/3/6 GroupValueWrite $01
1345050 168961.975579 192.168.170.9 192.168.119.6 KNXnet/IP 56 TunnelAck #23:46 OK
1345051 168962.282633 192.168.170.9 192.168.119.6 KNXnet/IP 63 TunnelReq #23:56 L_Data.req 15.15.241->0/3/11 GroupValueWrite $00
1345052 168963.410181 192.168.170.9 192.168.119.6 KNXnet/IP 63 TunnelReq #23:56 L_Data.req 15.15.241->0/3/11 GroupValueWrite $00
1345053 168964.457095 192.168.119.6 224.0.23.12 KNXnet/IP 60 RoutingInd L_Data.ind 1.2.32->3/5/5 GroupValueWrite $01
1345054 168964.457420 192.168.119.6 192.168.170.9 KNXnet/IP 63 TunnelReq #23:47 L_Data.ind 1.2.32->3/5/5 GroupValueWrite $01
1345055 168964.541078 192.168.170.9 192.168.119.6 KNXnet/IP 65 TunnelReq #23:56 L_Data.req 15.15.241->0/3/0 GroupValueWrite $44AA

Nur die markierten Frames sind relevant. Der Rest ist KNX Telegramme von KNX->EDOMI, hier mal nicht relevant, deren ACKs und Multicast-Traffic (Zieladresse 224.0.23.12).
Diskussion. Bei #23:50 gehts los (1344991). 50 ist die Sendesequenznummer (EDOMI->KNX), ein Groupwrite auf 1/6/1. Ist OK.
1344991 das ACK vom KNX Gateway dazu. Prima.
1344998 #23:51 15.15.241->7/1/16 GroupValueWrite $FF ein anderer Gruppenschreibvorgang. Prima.
1344999 TunnelAck #23:51 OK das ACK dazu. Auch prima.
Jetzt achtet auf die Sequenznummern. Wir sind bei 51.
[EDIT] Nr. 51 wird nochmal wiederholt (oder im Switch geDUPed, kann ja auch sein!).
Als nächstes kommt 52:
1345009 TunnelReq #23:52 L_Data.req 15.15.241->2/7/13 GroupValueWrite $FF
1345010 TunnelAck #23:52 OK
52 auch OK.
53:
1345016 L_Data.req 15.15.241->1/6/5 GroupValueWrite $0DAF
1345017 TunnelAck #23:53 OK
Ist OK.
54:
1345023 TunnelReq #23:54 L_Data.req 15.15.241->1/6/4 GroupValueWrite $01
1345024 TunnelAck #23:54 OK
Gut.
Jetzt gehts los mit den Problemen. 55 FEHLT!. ERSTE PROTOKOLLVERLETZUNG DURCH EDOMI, oder verloren gegangenes UDP Paket. Kein ACK vom KNX Gateway. Jetzt müsste EDOMI #55 wiederholen. Tut es aber nicht. Stattdessen:
Als nächstes kommt 56:
1345051 TunnelReq #23:56 L_Data.req 15.15.241->0/3/11 GroupValueWrite $00
1345052 TunnelReq #23:56 L_Data.req 15.15.241->0/3/11 GroupValueWrite $00
... und zwar gleich doppelt, mit selbem Inhalt ca. 1.200ms später. Also wiederholt EDOMI nicht 54, für das es kein ACK bekommen hat, sondern dafür das nächste Paket. Gut, ist ja auch kein ACK für gekommen.
Aber das KNX Gateway wartet jetzt immer noch auf die verlorene #55 und ACKt die #56 nicht. Hat recht damit, wartet noch auf die #55.
...und was macht EDOMI jetzt?
1345055 TunnelReq #23:56 L_Data.req 15.15.241->0/3/0 GroupValueWrite $44AA
Schiebt NOCH EINEN Gruppenschreibzugriff hinterher. Und zwar UNTER WIEDERVERWENDUNG der Sequenznummer #56. Denn Nr. 56 war ja schon der Schreibzugriff auf 0/3/11 in Frame 1345051 und 1345052.

Conclusion:
Das sind gleich zwei richtig fette Protokollverletzungen seitens EDOMI. An der Stelle hängt die Verbindung in Senderichtung (EDOMI -> Bus), die andere Richtung geht noch. Später kommt noch ein Disconnect aber die Verbindung zum Bus recovered nicht.

Soweit zum Stand der Dinge. Ich weiss noch nicht wie weiter vorzugehen ist, die proc_knx.php zu reparieren müsste Christian machen.
Evtl. könnte man einen Proxy zwischen EDOMI und KNX-Gateway schalten, sowas wie den knxd und den auf localhost laufen lassen, so dass keine UDP Pakete verloren gehen können. Kenn ich mich aber nicht mit aus. Ideen/Kommentare? Christian? Update?

lg aus Thüringen,
--Jens

**jdc** · 31.08.2023, 10:00

Notiz: Hier noch ein weiterer aufschlussreicher Stresstest.
Ethernet/switch/IP-router mit UDP mittels iperf nahezu sättigen bringt auch jede menge Fehler, Verbindungsabbrüche, insbesondere Sequenz-Errors.
In meinem Fall iperf Service auf meinem IP-router aktiviert, dann auf dem EDOMI-Rechner Client dazu gestartet:

Code:

# 900Mbit/s Traffic zwischen EDOMI-Rechner und IP Router generieren für 1 Stunde
iperf -z -t 3600 -i 10 -b900m -u -p 5001 -e -c 192.168.119.1

Bleiben immernoch 100Mbit/s für die Kommunikation mit dem KNX Gateway.
Trotzdem kommt:

2023-08-31 09:53:29	775183	KNX	88288	DE < \| TUNNELING_REQUEST / Hinweis: SequenceCounter abweichend (ACK): Ist-Wert=67, Soll-Wert=68 / Raw: 061004200015042b43002e00bce0fff10307010081	ERROR
2023-08-31 09:53:31	732418	KNX	88288	DE < \| TUNNELING_REQUEST / Hinweis: SequenceCounter abweichend (ACK): Ist-Wert=70, Soll-Wert=71 / Raw: 061004200015042b46002900bce0111c1b06010081	ERROR
2023-08-31 09:53:33	788271	KNX	88288	DE > \| TUNNELING_ACK / Timeout nach 5s / ErrMsg: Kein TUNNELING_ACK vom Router erhalten / Wiederholen	ERROR
2023-08-31 09:53:42	310749	KNX	88288	DE < \| TUNNELING_REQUEST / Hinweis: SequenceCounter abweichend (ACK): Ist-Wert=94, Soll-Wert=95 / Raw: 061004200016042b5e002900bce0113915020200801a	ERROR
2023-08-31 09:53:46	407135	KNX	88288	DE > \| TUNNELING_ACK / Timeout nach 5s / ErrMsg: Kein TUNNELING_ACK vom Router erhalten / Wiederholen	ERROR
2023-08-31 09:54:00	789477	KNX	88288	DE < \| TUNNELING_REQUEST / Hinweis: SequenceCounter abweichend (ACK): Ist-Wert=133, Soll-Wert=134 / Raw: 061004200015042b85002900bce0111f2a02010080	ERROR
2023-08-31 09:55:18	086777	KNX	88288	DE < \| TUNNELING_REQUEST / Hinweis: SequenceCounter abweichend (ACK): Ist-Wert=61, Soll-Wert=62 / Raw: 061004200015042b3d002900bce0110c0c02010081	ERROR
2023-08-31 09:56:35	195823	KNX	88288	DE < \| TUNNELING_REQUEST / Hinweis: SequenceCounter abweichend (ACK): Ist-Wert=217, Soll-Wert=218 / Raw: 061004200015042bd9002e00bce0fff1030c010080	ERROR
2023-08-31 09:57:53	028409	KNX	88288	DE > \| TUNNELING_ACK / Timeout nach 5s / ErrMsg: Kein TUNNELING_ACK vom Router erhalten / Wiederholen	ERROR
2023-08-31 09:58:15	262573	KNX	88288	DE < \| TUNNELING_REQUEST / Hinweis: SequenceCounter abweichend (ACK): Ist-Wert=185, Soll-Wert=186 / Raw: 061004200015042bb9002e00bce0fff1030b010080	ERROR
2023-08-31 09:59:06	579164	KNX	88288	DE < \| TUNNELING_REQUEST / Hinweis: SequenceCounter abweichend (ACK): Ist-Wert=34, Soll-Wert=35 / Raw: 061004200017042b22002900bce011333803030080144c	ERROR
2023-08-31 09:59:10	967387	KNX	88288	DE > \| TUNNELING_ACK / Timeout nach 5s / ErrMsg: Kein TUNNELING_ACK vom Router erhalten / Wiederholen	ERROR
2023-08-31 09:59:41	161616	KNX	88288	DE < \| TUNNELING_REQUEST / Hinweis: SequenceCounter abweichend (ACK): Ist-Wert=106, Soll-Wert=107 / Raw: 061004200023042b6a002e00bce0fff103040f00804261743a 35372520343956200000	ERROR
2023-08-31 09:59:42	153188	KNX	88288	CE < \| DISCONNECT_REQUEST / Raw: 0610020900102b000801c0a8db060e57	ERROR
2023-08-31 09:59:42	255192	KNX	88288	KNX-Verbindung verloren.	ERROR

Dürfte nicht sein.

Vermutung: Die UDP Pakete zum KNX Gateway werden auf dem Weg gereordered, daher Sequenz-Errors. Evtl. schon auf dem EDOMI-Host, kann aber auch erst im Switch oder IP Router passieren. Darf so sein, ist ja UDP. Muss EDOMI mit klarkommen, tut es aber nicht so richtig.
Mag dadurch gekommen sein, dass alle modernen TCP/IP Stacks mittlerweile multi-threaded sind und selbst der älteste Celeron-Rechner schon mindestens 2 CPUs hat. Da werden die UDP Pakete dann umsortiert wie die Autos an einer Mautstelle auf der Autobahn. Das könnte erklären, warum Last auf dem Rechner, auf dem Netzwerk und Netzwerkeinstellungen wie Halb/Vollduplex Einfluss haben. Vielleicht läuft EDOMI in einem Docker-Container auch besser deswegen.

Wahrscheinlich wird es darauf hinauslaufen, irgendwie dafür zu sorgen, dass immer nur 1 KNX Write auf den Weg geschickt wird und dann gewartet wird bis ein ACK dafür vom Gateway kommt (Window-Size auf 1 beschränken). Das scheint momentan nicht der Fall zu sein. Vielleicht kann der knxd das.

**marhal** · 01.09.2023, 05:00

Hallo alle zusammen,

ich weiß nicht ob ich hier mit den Fehler richtig bin. Aber ich habe auch jetzt etwas länger folgende Fehler in EDOMI. Ich konnte auch noch nicht herausbekommen, woher sie rühren. Ich hoffe es das es die gleiche Problematik ist wie bei euch. EDOMI läuft ja soweit, doch sind die Fehlermeldungen doch etwas störend

{EDOMI,ERRLOG_2023-08.htm,27.08.2023,08:30:40,845303,1760699}Zeitstem pelmsProzessPIDMeldungStatus2023-08-27 08:30:40845221KNX1760699CE > | CONNECTIONSTATE_REQUEST / Timeout nach 5s / ErrMsg: Kein CONNECTIONSTATE_RESPONSE vom Router erhaltenERROR2023-08-27 08:30:40855506KNX1760699KNX-Verbindung verloren.ERROR2023-08-27 08:30:53862879KNX1760699CE > | DESCRIPTION_REQUEST / Timeout nach 10s / ErrMsg: Kein DESCRIPTION_RESPONSE vom Router erhaltenERROR2023-08-27 08:30:53873101KNX1760699KNX-Verbindung verloren.ERROR2023-08-27 09:50:02716711KNX1760699CE > | CONNECTIONSTATE_REQUEST / Timeout nach 5s / ErrMsg: Kein CONNECTIONSTATE_RESPONSE vom Router erhaltenERROR2023-08-27 09:50:02727066KNX1760699KNX-Verbindung verloren.ERROR2023-08-27 19:09:16983275KNX1760699CE < | DISCONNECT_REQUEST / Raw: 06100209001010000801ac1301050e57ERROR2023-08-27 19:09:16993604KNX1760699KNX-Verbindung verloren.ERROR2023-08-28 05:59:01698952KNX1760699CE > | CONNECTIONSTATE_REQUEST / Timeout nach 5s / ErrMsg: Kein CONNECTIONSTATE_RESPONSE vom Router erhaltenERROR2023-08-28 05:59:01709193KNX1760699KNX-Verbindung verloren.ERROR2023-08-29 07:13:25379739KNX1760699CE > | CONNECTIONSTATE_REQUEST / Timeout nach 5s / ErrMsg: Kein CONNECTIONSTATE_RESPONSE vom Router erhaltenERROR2023-08-29 07:13:25390045KNX1760699KNX-Verbindung verloren.ERROR2023-08-29 07:13:38397490KNX1760699CE > | DESCRIPTION_REQUEST / Timeout nach 10s / ErrMsg: Kein DESCRIPTION_RESPONSE vom Router erhaltenERROR2023-08-29 07:13:38407742KNX1760699KNX-Verbindung verloren.ERROR2023-08-29 13:10:20041708KNX1760699CE > | CONNECTIONSTATE_REQUEST / Timeout nach 5s / ErrMsg: Kein CONNECTIONSTATE_RESPONSE vom Router erhaltenERROR2023-08-29 13:10:20052038KNX1760699KNX-Verbindung verloren.ERROR2023-08-30 16:04:40495903KNX1760699CE < | DISCONNECT_REQUEST / Raw: 06100209001010000801ac1301050e57ERROR2023-08-30 16:04:40506161KNX1760699KNX-Verbindung verloren.ERROR2023-08-31 18:31:34487763KNX1760699CE > | CONNECTIONSTATE_REQUEST / Timeout nach 5s / ErrMsg: Kein CONNECTIONSTATE_RESPONSE vom Router erhaltenERROR2023-08-31 18:31:34498023KNX1760699KNX-Verbindung verloren.ERROR

Gruß
Marhal

**jdc** · 01.09.2023, 07:39

Hallo Marhal,

interessant.

Bei Dir scheint die Control-Endpoint ("CE") Kommunikation gestört zu sein: EDOMI Prüft in regelmäßigen Abständen mittels CONNECTIONSTATE_REQUEST ob das KNX Gateway noch da ist und wenn keine Antwort innerhalb des Limits kommt dann ist Timeout, es werden beide UDP Sockets (CE und DE) geschlossen, neu aufgebaut und somit die Verbindung zum Gateway neu initialisiert. Die Limits sind in der edomi.ini eingestellt, Einstellungen global_knxHeartbeat und global_knxHeartbeatTimeout .

Was ist so alles zwischen EDOMI und KNX Gateway? Direkte Verbindung via Kabel? Oder Switch/Router/Firewall/NAT? Ich könnte mir z.B. vorstellen, dass falls das global_knxHeartbeat Intervall bei Dir sehr lang eingestellt ist irgendwo in einer Firewall oder NAT Tabelle auf dem Router der UDP State Eintrag expired. Evtl. auch auf dem EDOMI Hostrechner selber je nach Konfiguration. Entweder das, oder das KNX Gateway resettet von sich aus irgendwie, EDOMI merkt das und baut die Kommunikation wieder auf, was ja korrekt wäre. Also ein grundlegenderes Problem, nicht so subtil wie Ausfälle unter Last oder bei duplizierten oder gereorderten UDP Paketen die einmal am Tag mal vorkommen können.

Die bei EDOMI einlaufenden DISCONNECT_REQUESTS scheinen von den CONNECTIONSTATE_REQUEST Timeout-Events unabhängig zu sein, da zu unterschiedlichen Zeiten aufgetreten laut Log. Das Gateway trennt die Verbindung z.B. wenn keine Antwort auf CONNECTIONSTATE_REQUESTS seinerseits erfolgt (also möglicherweise selbe Ursache, nur von der anderen Seite des Links gesehen!) oder wenn Tunnel-Requests auf dem Data-Endpoint nicht rechtzeitig und nach Wiederholung derselben bestätigt werden.

Also möglicherweise selbe Ursache, zeitweise ist fällt die Kommunikation zwischen Gateway und EDOMI komplett aus, und anscheinend in beide Richtungen.

Falls ein Router/managed Switch dazwischen ist würde ich das Syslog/Port Statistiken checken. Stromausfall im ms-Bereich in Betracht ziehen. Wackelkontakt im Ethernet-Kabel. Sowas. Mein Gefühl sagt Dein Problem liegt bei Dir eher nicht an EDOMIs Protokollimplementation sondern ist grundlegender. Danach kommen erst die Probleme, die wir sehen. ;-)

--j

**marhal** · 02.09.2023, 06:48

Hallo idc,

vielen Dank für deine schnelle Antwort und Einschätzung. Das ist schon mal ein guter Anhaltspunkt wo nach schauen kann. Ich habe EDOMI halt auf ein Proxmox laufen mit VLAN. Ich versuche mal in die Richtung zu schauen und zu denken.
Aber vielen Dank für die Erklärung !

Gruß
Marhal

**jdc** · 02.09.2023, 07:42

Potentieller BUG Feststellung/Finding (!), wahrscheinlich Teilursache der Probleme:

!!! EDOMI zählt die TX Sequenznummer (also von EDOMI Richtung KNX Gateway) mit jedem eintreffenden ACK hoch (+1). !!!

Wenn jetzt ein ACK doppelt eintrifft, z.B. weil es auf UDP/IP/Ethernet-Ebene im Switch/Router aufgedoppelt wird, dann ist die Sende-Sequenznummer wie z.B. in meinem Trace oben um 1 zu hoch (Nr. 56 statt 55). Das dürfte die Ursache für das Hängen der Verbindung sein, weil das Gateway wartet jetzt auf die Nummer 55, die fehlt und auch nicht mehr kommt. Könnte mir Vorstellen, dass das Verhalten Herstellerspezifisch ist, dass also die anderen Hersteller (Weinzierl?) gelernt haben damit umzugehen und selber die Firmware in ihren Gateways angepasst haben (oder einfach sagen ACK ist ACK, unabhängig von der Sequenznummer, wie EDOMI halt auch), was erklärte warum nur bestimmte KNX-Gateways betroffen sind.
M.e. nach müsste der TX-Sequenznummer-Zähler auf den Wert im eintreffenden ACK-Frame gesetzt werden anstatt hochzuzählen. Die Häufigkeit der Aufdopplung dürfte Stressinduziert sein (Prozessorlast, Netzwerklast, Transmissionprobleme auf dem PHY wie Impulse durch Wechselrichter-Umschaltung/Brummschleifen etc.), dadurch statistisch zu solchen Zeiten häufiger auftreten.

Erklärt auch warum die Verbindung jetzt nicht einfach resettet und neu initialisiert wird, der Hänger also dauerhaft ist, bis man schliesslich manuell eingreift. Der Mechanismus wie bei marthal oben greift nicht, weil der KNX-Heartbeat-Timeout Mechnismus wie bei marthal oben beschrieben den anderen Endpoint (CE) mit getrenntem UDP Socket verwendet, der ja mit den Sequenznummern nichts am Hut hat, komplett unabhängig weiterläuft, und dadurch weiter normal funktioniert, also daher kein Heartbeat-Timeout auftritt. Wenn doch einer auftreten würde dann wäre das Problem nicht so schlimm, würde wenigstens die Session resetten und nervige Log-Einträge machen, aber man müsste wenigstens nicht mehr manuell eingreifen.

Erklärt auch warum bei direkter Verbindung vom EDOMI Hostrechner zum KNX Gateway, z.B. mit zweiter Netzwerk-Karte und direktem Kabel anstatt Switch/Router/VLAN etc. das ganze stabiler läuft, da weniger Potential für Aufdopplung/IP Paket reordering.

Christian? Ganz lieb bitte bitte bitte?
Ich bin fast sicher dass es einen Grund für das +1 anstatt setzen auf empfangenen Wert gibt, könntest Du das nicht doch bitte mal kommentieren, würde sicher vielen Leuten extrem helfen.

Schönes Wochenende noch,
-j

EDIT T+45min:
Ich bin offenbar auch blind, genau sowas ist im Trace oben auch aufgetreten, Nr. 51 wurde wiederholt und beide Male durchs Gateway geACKt. Hab ich übersehen. Das dürfte der Ursprung des im Trace erfassten Hängers sein. Ich verstehe nur nicht warum es noch einiger weiterer Tunnel-Requests (Nr. 52 und 53) bedarft hat bevor es dann final geknallt hat.

**sipiyou** · 02.09.2023, 10:32

@jdc: Mega Arbeit!

**jdc** · 01.12.2023, 18:28

Weiterer Zwischenstand:
Nach einigen Monaten habe ich zumindest das Problem des dauerhaft "hängens" ("hochzählen der Verbindungen") durch Änderungen auf EDOMI-Seite in den Griff bekommen. Die Verbindungen werden jetzt also verlässlich neu aufgebaut im Fehlerfall.

Der Verdacht, dass wohl durch den Switch/Router die Aufdopplung/Paketverlust der KNX UDP Pakete verursacht wird, hat sich bestätigt. Ein Switchtausch und Routertausch (Neugeräte) haben das Problem nicht beseitigt, eher etwas verschlimmert (Häufigkeit), offenbar handelt es sich also nicht um einen Hardware-Defekt sondern ein systematisches Problem. Wird das von modernen Switches/Routern heutzutage so erwartet/erduldet dass IP Pakete resequenziert werden und/oder gedroppt werden? Multithreading durch parallele Bearbeitung auf mehreren CPUs oder so etwas?

Mein Zwischenfazit für alle KNX-Gatewaybenutzer wäre bisweilen eine zweite Schnittstelle im PC vorsehen und das KNX-Gateway direkt nur über ein Kabel zu verbinden.

Ich weiss nicht ob/wann ich dazu komme das weiter zu debuggen, momentan sind andere Dinge wichtiger da ich jetzt so mehr oder weniger zufrieden sein kann mit der Stabilität meines Setups.

Vorweihnachtliche Grüße,
--j

Ankündigung

GELÖST: EDOMI KNX-Ethernet-Interface/Gateway Probleme

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar