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:
$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:
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:
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:
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