00_TCM.pm: ESP3-Parser verliert Synchronisation durch TCP-Heartbeat

[Flachzange]

Hallo Klaus,

ich habe hier etwas Spannendes

Ich verwende vier BSC Tiny EG32SC PoE-Gateways mit TCM515, die über TCP an FHEM angebunden sind. Durch signOfLife und sonstige Watchdogs versuche ich schon immer, systematische Probleme in der Kommunikation zu erkennen, vor allem Reichweitenprobleme, Störungen etc.

Seit Monaten/Jahren beobachte ich, dass sporadisch im Umfeld eines der Gateways mehrere Sensoren mehr oder weniger gleichzeitig in einen signOfLife-Alarm laufen. Nachdem diverse Hypothesen nicht zutrafen, habe ich einfach mal TCP-Mitschnitte laufen lassen.

Das Ergebnis war überraschend:

1. Die vermeintlich ausgefallenen Telegramme sind alle über TCP beim FHEM-Host angekommen.
2. Das Gateway sendet bei inaktiver Kommunikation offenbar Heartbeat-Pakete (kein ESP3). Konkret sind das die vier ASCII-Bytes IM2M (49 4D 32 4D).

Das wäre zunächst unproblematisch, allerdings enthält TCM_Read() in 00_TCM.pm zwei problematische Stellen:

1. Bei der Frame-Synchronisation wird mit s/.*55/55/ auf das letzte 0x55 synchronisiert. Dadurch kann ein Byte am Ende eines gültigen ESP3-Frames fälschlicherweise als neuer Frame-Anfang interpretiert werden.
2. Die Datenlänge des ESP3-Headers wird übernommen, bevor dessen CRC geprüft wurde.

Warum führt gerade der Heartbeat zu diesem Problem?

Die Regex zur Resynchronisation wird nur ausgeführt, wenn der verbleibende Datenpuffer mindestens zwei Bytes enthält und nicht mit 55 beginnt:

Code Auswählen Erweitern

$data =~ s/.*55/55/ if($data !~ m/^55/);

Bei einem normalen ESP3-Datenstrom beginnt der Puffer mit 55. Der Parser verarbeitet die vollständigen Frames anhand ihrer Längenangaben und bleibt synchronisiert. Die problematische Regex kommt dabei normalerweise gar nicht zum Einsatz.

Durch den Heartbeat ändert sich das. Im TCP-Mitschnitt gab es beispielsweise folgende Konstellation:

Code Auswählen Erweitern

49 4D 32 4D       Heartbeat "IM2M"
55 00 07 ... 55   Vollständiger, gültiger ESP3-Frame

Das letzte Byte des ESP3-Frames ist hier zufällig ebenfalls 0x55.

Werden beide Teile gemeinsam von TCM_Read() verarbeitet, beginnt der Puffer mit 49 statt 55. Damit greift die Resynchronisation.

Da .* in der Regex gierig ist, wird allerdings nicht auf das erste 55 (den tatsächlichen ESP3-Frame-Anfang), sondern auf das letzte 55 synchronisiert. In diesem Fall bleibt nur das letzte Byte des vollständigen Frames im Puffer stehen.

Kommt anschließend der nächste reguläre ESP3-Frame, entsteht:

Code Auswählen Erweitern

55 | 55 00 07 07 01 ...
^    ^
|    Tatsächlicher Beginn des nächsten Frames
|
Fälschlicherweise stehen gebliebenes Byte

Der Parser interpretiert jetzt:

- 55 = ESP3-Sync-Byte
- 55 00 = Datenlänge 0x5500 = 21.760 Bytes
- 07 = optionale Datenlänge
- 07 = Pakettyp
- 01 = vermeintliche Header-CRC

Da die Header-CRC erst nach dem vollständigen Einlesen der vermeintlichen Nutzdaten geprüft wird, sammelt der Parser zunächst weitere Daten, statt den ungültigen Header sofort zu verwerfen.

In meinem Fall dauerte es rund 26 Minuten, bis genügend Daten zusammengekommen waren. Währenddessen wurden gültige Sensortelegramme nicht verarbeitet, obwohl sie im TCP-Mitschnitt vollständig vorhanden waren.

Im Log erschien schließlich:

Code Auswählen Erweitern

TCM TCM_Remote_Garage wrong header checksum: got 01, computed CC

Ich habe den Fehler mit der unveränderten TCM_Read()-Funktion und den aufgezeichneten TCP-Daten reproduziert. Entscheidend ist dabei auch, wie die TCP-Daten auf einzelne Lesevorgänge verteilt werden. Werden die Heartbeat-Bytes beispielsweise separat eingelesen und verworfen, tritt dieser konkrete Fehler nicht auf.

Der Heartbeat ist damit nicht die eigentliche Ursache, sondern lediglich der Auslöser für eine bereits vorhandene Schwachstelle. Grundsätzlich könnte der Fehler auch durch andere Fremddaten oder eine gestörte Übertragung entstehen, sobald die Resynchronisation benötigt wird.

Anbei ein Patch, der die Header-CRC vor der Längenauswertung prüft und die Frame-Synchronisation korrigiert. Die vergleichbare Problematik in TCM_ReadAnswer() habe ich ebenfalls berücksichtigt.

Die bisherigen Tests sind erfolgreich. Beim Replay von 33.543 Funk-Frames mit der problematischen Datenbündelung gingen im Original 907 Frames verloren, mit dem Patch keiner.

Der Patch läuft inzwischen bei mir im Produktivtest. Eine abschließende Langzeitbewertung steht noch aus.

Aus meiner Sicht handelt es sich um eine grundsätzliche Schwachstelle in der ESP3-Verarbeitung, die nicht auf die BSC-Gateways beschränkt ist. Solche Heartbeat-Pakete werden auch von anderen Serial-to-TCP-Konvertern unterstützt.

Das erklärt vermutlich auch, warum ich die Probleme insbesondere bei einem der Gateways beobachtet habe. Die anderen Gateways haben deutlich mehr laufenden Datenverkehr, sodass entsprechende Leerlaufphasen seltener auftreten. Hinzu kommt, dass die betroffenen Sensoren in diesen Situationen von keinem weiteren Gateway empfangen werden, das die verlorenen Telegramme kompensieren könnte.

Gruß
Chris

[IPWF]

Interessante Beobachtung, vielen Dank für Deine Mühe.
Der Fehler könnte ja evtl. Ursache für manche seltsame ausgebliebene Nachrichten sein, die immer mal wieder auftreten.

[Flachzange]

Um fair zu sein: Es gibt drölfmillionen mögliche Ursachen, warum Nachrichten ausbleiben können, teilweise werden schon durch Fehlern in den Sensor-Firmwares in manchen Konstellationen keine Telegramme verschickt. Trifft beir mir z.B. auf Eltako-Bewegungsmelder und Türkontakte zu. Auch hat es ja nicht immer auch direkt praktische Auswirkungen. Nur weil ich einen signOfLife-Alarm erhalte, gibt es ja nicht auch gleich einen Funktionsausfall.

Aber ja, interesant fand ich das auch.

[klaus.schauer]

Die Dekodierung der Telegramme etwas robuster zu machen, ist durchaus sinnvoll. Ich sehe mir das sobald als möglich an.

Der Patch funktioniert auf dem aktuellen TCM-Modul V29702 bei mir nicht. Bitte den Patch auf dessen Basis erstellen. Bitte zusätzlich die gepatchte Moduldatei V29702 ins Forum einstellen. Dann können auch andere Anwender damit unmittelbar Erfahrungen sammeln. 

[Flachzange]

Der Patch funktioniert auf dem aktuellen TCM-Modul V29702 bei mir nicht. Bitte den Patch auf dessen Basis erstellen. Bitte zusätzlich die gepatchte Moduldatei V29702 ins Forum einstellen. Dann können auch andere Anwender damit unmittelbar Erfahrungen sammeln. 

Hallo Klaus,

woher nimmst du V29702? Ich sehe nur V29782. Dagegen sollte der Patch funktionieren. Anbei die komplette Datei.

[klaus.schauer]

Der Patch funktioniert auf dem aktuellen TCM-Modul V29702 bei mir nicht. Bitte den Patch auf dessen Basis erstellen. Bitte zusätzlich die gepatchte Moduldatei V29702 ins Forum einstellen. Dann können auch andere Anwender damit unmittelbar Erfahrungen sammeln. 

woher nimmst du V29702? Ich sehe nur V29782. Dagegen sollte der Patch funktionieren. Anbei die komplette Datei.

V29702 war ein Schreibfehler, sollte V29782 sein. Ich nehme jetzt einfach die gepatchte Datei.

[klaus.schauer]

Anbei ein Patch, der die Header-CRC vor der Längenauswertung prüft und die Frame-Synchronisation korrigiert. Die vergleichbare Problematik in TCM_ReadAnswer() habe ich ebenfalls berücksichtigt.

Die bisherigen Tests sind erfolgreich. Beim Replay von 33.543 Funk-Frames mit der problematischen Datenbündelung gingen im Original 907 Frames verloren, mit dem Patch keiner.

Aus meiner Sicht handelt es sich um eine grundsätzliche Schwachstelle in der ESP3-Verarbeitung, die nicht auf die BSC-Gateways beschränkt ist. Solche Heartbeat-Pakete werden auch von anderen Serial-to-TCP-Konvertern unterstützt.

Mir fehlt seit Monaten die Zeit, mich intensiver mit den Fhem-Modulen zu beschäftigen. Nach einer kurzen Durchsicht habe ich deshalb das geänderte Modul bei mir ebenfalls in Betrieb.

CRC-Fehlermeldungen sehe ich - bis vereinzelt beim Systemstart - bisher nicht. Auch gibt es weiterhin signOfLife-Meldungen.

Dennoch scheint es mir die Änderungen sinnvoll. Sie lösen wahrscheinlich ein anderes Problem. Es kommt vereinzelt insbesondere bei einem Systemstart oder Fhem-Restart vor, dass die Quittungstelegramme der Init-Befehle wie reset nicht sauber verarbeitet werden. Das führte zu mehr oder weniger langen Blockaden der Fhem-Startroutine.

Ich habe in den vergangenen Jahren schon mehrere Anläufe genommen, um das Problem zu lösen. Ich hatte vermutet, dass dies auf Pufferüberläufe oder die asynchrone Verarbeitung der Quittungstelegramme zurückzuführen ist. Die Ansätze über recht komplexe Warteschlangenkonstrukte konnten das Problem aber nicht beseitigen. Die logisch korrekte CRC-Prüfung des Headers und das Verwerfen des folgenden Datenblocks scheint die Lösung zu sein.

Ich werde das weiter beobachten und hoffentlich in ein paar Wochen mehr freie Zeit für's Analysieren und Programmieren haben. Vielleicht findet sich zwischenzeitlich der eine oder andere Anwender, der sich dem Test anschließt.