"Gerätekommunikation war gestört" .. jeden Tag


#1

Moin,

jeden Morgen ist ein anderes Nachtlicht an, eine andere Jalousie unten oder ein Heizkörper kalt. Und das, obwohl mein überschaubares Haus mit 3 Homematic Access Points ausgerüstet ist. Wie kann ich der Ursache am ehesten auf die Schliche kommen und idealerweise beheben?

Situation:

  • freistehendes Einfamilienhaus mit nebenstehender Garage
  • 3 Etagen (Keller, EG, 1. OG) und Dachboden
  • 33 verbaute Homematic Geräte (Aktoren, Sensoren, Thermostate)
  • 3 HM Access Points, alle per LAN angebunden
    • 1 HM-CFG-LAN (Dachboden)
    • 1 Raspberry Pi 3B mit CC1101/8cm Modul von @pmayer und homegear-gateway (Keller)
    • 1 Raspberry Pi 3B+ mit CC1101/16cm Modul von @pmayer und homegear (Erdgeschoß)
  • Home Assistant auf dem RPi3B+ als Broker

#2

RSSI Werte sind durchaus im Rahmen, Roaming ist für alle Geräte aktiviert:

ID Type Interface Signal
1 HM-LC-Bl1PBU-FM hm-cfg-lan -57
2 HM-LC-Bl1PBU-FM cc1101-16 -60
3 HM-LC-Sw1-DR cc1101-16 -75
4 HM-CC-RT-DN cc1101-8 -36
5 HM-LC-Sw1-FM cc1101-16 -54
6 HM-LC-Sw1PBU-FM cc1101-16 -41
7 HM-LC-Sw1PBU-FM cc1101-16 -63
8 HM-LC-Sw4-DR cc1101-8 -74
9 HM-LC-Sw1-DR cc1101-16 -61
10 HM-Sen-MDIR-O-2 cc1101-16 -73
11 HM-Sen-MDIR-O-2 cc1101-8 -67
12 HM-CC-RT-DN cc1101-16 -23
13 HM-CC-RT-DN cc1101-16 -46
14 HM-CC-RT-DN cc1101-16 -52
15 HM-CC-RT-DN cc1101-16 -56
16 HM-CC-RT-DN hm-cfg-lan -45
17 HM-CC-RT-DN cc1101-16 -68
18 HM-CC-RT-DN cc1101-16 -50
19 HM-WDS10-TH-O cc1101-16 -46
20 HM-LC-Bl1PBU-FM cc1101-16 -60
21 HM-Sec-SCo cc1101-16 -66
22 HM-WDS40-TH-I-2 cc1101-16 -51
23 HM-Sec-SCo hm-cfg-lan -61
24 HM-LC-Bl1PBU-FM hm-cfg-lan -58
25 HM-LC-Bl1PBU-FM cc1101-16 -59
26 HM-LC-Bl1PBU-FM cc1101-16 -58
27 HM-LC-Bl1PBU-FM cc1101-16 -43
28 HM-LC-Bl1PBU-FM cc1101-16 -46
29 HM-LC-Bl1PBU-FM cc1101-16 -45
30 HM-LC-Bl1PBU-FM hm-cfg-lan -61
31 HM-Sec-SCo cc1101-16 -66
32 HM-Sec-SCo hm-cfg-lan -53
33 HM-Sec-SCo cc1101-16 -61

#3

Etwas obskur ist manchmal die Zuordnung eines Devices zu einem AP. So sind in einem Zimmer im Obergeschoss ein Heizkörperventil, ein Fensterkontakt (optisch) und ein Jalousien-Aktor verbaut. Fensterkontakt und Aktor sind am hm-cfg-lan im Dachboden, Thermostat ist am AP im Erdgeschoss.


#4

Hallo @m0wlheld,

versuch doch einmal zu ermitteln, in etwa wann das Gerät eingeschaltet wird und poste das Log von etwa diesem Zeitpunkt (bzw. gerne das ganze Log des Tages). Dann können wir mal sehen, woher der Befehl kommt. Wenn das Gerät nur einmal in der Nacht geschaltet wird, muss der Zeitpunkt nicht einmal bekannt sein, dann können wir das Log einfach nach einem Paket an dieses Gerät durchsuchen und schauen, was das Senden auslöst.

Viele Grüße

Sathya


#5

Also,

es sind ja immer andere Geräte betroffen. Gewisse Aktoren aber häufiger als andere. Letzte Nacht sollte z.B. um 23:00 ein Aktor vom Typ HM-LC-Sw1-DR abschalten. Der Befehl dazu kommt zeitgesteuert von Home Assistant, welches auf dem gleichen Raspberry läuft wie Homegear.

Im Home Assistant error.log steht dann folgendes:

HMGeneric.setValue: STATE on OEQ1012434:1 Exception: <Fault -100: 'No answer from device.'>

Im homegear.err steht nix relevantes, im homegear.log lässt sich folgender Passus zuordnen (dabei ist cc1101-paula ein RPi3B+ mit Homegear via CC1101 Modul von @pmayer und Home Assistant, cc1101-denise ein RPi3 mit Homegear-Gateway via CC1101 Modul von @pmayer und hm-cfg-lan ein Homematic HM-CFG-LAN Adapter):

01/13/19 23:00:02.872 RPC Server (Port 2001): Info: Connection from ::ffff:127.0.0.1:56648 accepted.     Client number: 397111
01/13/19 23:00:02.873 RPC Server (Port 2001): Info: RPC server client id for client number 397111 is: 62029
01/13/19 23:00:02.878 RPC Server (Port 2001): Info: Client number 397111 is calling RPC method: setValue (1) Parameters:
(String) OEQ1012434:1
(String) STATE
(Boolean) 0
01/13/19 23:00:02.879 Module HomeMatic BidCoS: TI CC110X "cc1101-paula": Info: Sending (cc1101-paula): 0E34A011FDCD995D50470201000000
01/13/19 23:00:02.901 HomeMatic BidCoS packet received (cc1101-denise, RSSI: -52 dBm): 0E34A011FDCD995D50470201000000
01/13/19 23:00:02.938 HomeMatic BidCoS packet received (hm-cfg-lan-1, RSSI: -57 dBm): 0E34A011FDCD995D50470201000000
01/13/19 23:00:03.028 Info: c-Frame is: 1134A0025D5047FDCD9904E5EA2267265C02
01/13/19 23:00:03.029 HomeMatic BidCoS packet received (cc1101-denise, RSSI: -80 dBm): 1134A0025D5047FDCD9904E5EA2267265C02
01/13/19 23:00:03.066 HomeMatic BidCoS packet received (hm-cfg-lan-1, RSSI: -81 dBm): 1134A0025D5047FDCD9904E5EA2267265C02
01/13/19 23:00:03.128 Module HomeMatic BidCoS: TI CC110X "cc1101-paula": Info: Sending (cc1101-paula): 1934A003FDCD995D50473F761E1551C99E35A429B3E28501D8FC
01/13/19 23:00:03.158 HomeMatic BidCoS packet received (cc1101-denise, RSSI: -52 dBm): 1934A003FDCD995D50473F761E1551C99E35A429B3E28501D8FC
01/13/19 23:00:03.278 HomeMatic BidCoS packet received (cc1101-denise, RSSI: -79 dBm): 123480025D5047FDCD990101000045CDAAD886
01/13/19 23:00:03.321 HomeMatic BidCoS packet received (hm-cfg-lan-1, RSSI: -82 dBm): 123480025D5047FDCD990101000045CDAAD886
01/13/19 23:00:03.680 Module HomeMatic BidCoS: TI CC110X "cc1101-paula": Info: Sending (cc1101-paula): 0E34A011FDCD995D50470201000000 Planned sending time: 01/13/19 23:00:03.080
01/13/19 23:00:03.702 HomeMatic BidCoS packet received (cc1101-denise, RSSI: -52 dBm): 0E34A011FDCD995D50470201000000
01/13/19 23:00:03.733 HomeMatic BidCoS packet received (hm-cfg-lan-1, RSSI: -57 dBm): 0E34A011FDCD995D50470201000000
01/13/19 23:00:03.829 HomeMatic BidCoS packet received (cc1101-denise, RSSI: -80 dBm): 1134A0025D5047FDCD990444028B470F2C02
01/13/19 23:00:03.867 HomeMatic BidCoS packet received (hm-cfg-lan-1, RSSI: -82 dBm): 1134A0025D5047FDCD990444028B470F2C02
01/13/19 23:00:04.280 Module HomeMatic BidCoS: TI CC110X "cc1101-paula": Info: Sending (cc1101-paula): 0E34A011FDCD995D50470201000000 Planned sending time: 01/13/19 23:00:03.280
01/13/19 23:00:04.302 HomeMatic BidCoS packet received (cc1101-denise, RSSI: -52 dBm): 0E34A011FDCD995D50470201000000
01/13/19 23:00:04.339 HomeMatic BidCoS packet received (hm-cfg-lan-1, RSSI: -57 dBm): 0E34A011FDCD995D50470201000000
01/13/19 23:00:04.429 HomeMatic BidCoS packet received (cc1101-denise, RSSI: -79 dBm): 1134A0025D5047FDCD990480D9BD9D9EF902
01/13/19 23:00:04.467 HomeMatic BidCoS packet received (hm-cfg-lan-1, RSSI: -81 dBm): 1134A0025D5047FDCD990480D9BD9D9EF902

Im Ergebnis bleibt der Aktor geschaltet und das damit verbundene Licht an.

Und während ich diesen Bericht schreibe, verweigern gerade zwei andere Aktoren die Kooperation. Ein weiterer HM-LC-Sw1-DR und ein HM-LC-Sw4-DR. Ich kann aber nicht behaupten, dass gerade diese Hutschienen-Aktoren besonders auffällig wären. Eine gewisse Relation zur RSSI scheint gegeben, Geräte mit schlechterem Wert (Minimum aktuell -76) fallen häufiger auf, Geräte mit besseren Werten seltener. Bei -60 scheint eine kritische Grenze zu sein.


#6

Hallo @m0wlheld,

erst einmal eine Analyse des Logs:

  1. 0E34A011FDCD995D50470201000000 => Aus wird gesendet`
  2. c-Frame is: 1134A0025D5047FDCD9904E5EA2267265C02 => Erstes AES-Handshake-Paket wurde vom Aktor empfangen.
  3. 1934A003FDCD995D50473F761E1551C99E35A429B3E28501D8FC => Zweites AES-Handshake-Paket wird an Aktor gesendet.
  4. 123480025D5047FDCD990101000045CDAAD886 => Drittes Handshake-Paket, welches keine Antwort mehr erwartet, wird vom Aktor an die Zentrale gesendet. Dieses Paket wird nicht von cc1101-paula empfangen, daher wird die ursprüngliche Anfrage wiederholt. Der Aktor hat das Aus aber akzeptiert und bestätigt, müsste also geschaltet haben - außer das Relais klebt oder es gibt einen Firmwarefehler.
  5. 0E34A011FDCD995D50470201000000 erneutes Senden des Aus.
  6. 1134A0025D5047FDCD990444028B470F2C02. Dieses Mal kein c-Frame is, d. h. cc1101-paula hat dieses Paket nicht empfangen.
  7. 0E34A011FDCD995D50470201000000 erneutes Senden des Aus.
  8. 1134A0025D5047FDCD990444028B470F2C02. Erneut kein c-Frame is, d. h. cc1101-paula hat dieses Paket wieder nicht empfangen.
  9. Generierung des -100-Fehlers.

Wir haben also zwei Probleme. Zum einen hätte in diesem Fall der Aktor tatsächlich geschaltet haben müssen. Dieses wurde vom Aktor mit dem 8002-Paket bestätigt. Zum anderen wurde das Paket vom CC1101 nicht empfangen. Bei diesem Aktor könntest du mal den Wechsel auf cc1101-denise probieren. Der CC1101 hat das Paket ja zumindest in diesem Fall zuverlässig empfangen.

Generall ist der Empfang der UP-Aktoren nicht der beste. -80 dBm ist ja der RSSI auf Homegearseite und da sind die Bedingungen gut. Auf Aktorseite kann der RSSI - gerade bei den UP-Aktoren - deutlich schlechter sein, so dass es trotz der vielen Gateways immer noch ein Empfangsproblem sein kann. Ich hatte mit UP-Aktoren ähnliche Probleme (einer war nur etwa 5 bis 6 Meter vom Gateway und nur eine Wand weiter) und es half letztlich nur, AES wieder zu deaktivieren.

Viele Grüße

Sathya


#7

Hey,

ich danke Dir erstmal für die Analyse. Tatsächlich ist “paula” der Raspberry, auf dem neben Homegear noch Home Assistant (in Docker), MySQL und nginx liefen. Das Teil hatte eine Dauer-Load > 5, sicher nicht optimal. Auf “denise” läuft hingegen nur der homegear-gateway, die Load ist keiner Rede wert.

Ich habe heute Homegear, MySQL und Home Assistant auf einen HP N54L Server umgezogen, das Teil ruht dennoch in sich selbst (load < 0.2). “paula” wurde wie “denise” zum Homegear Gateway degradiert. Ich hoffe, dass dies einen positiven Einfluß auf die Stabilität hat.

Bei Bedarf melde ich mich wieder.


#8

ok, das kann nicht funktionieren. Homegear priorisiert zwar Threads, Möglicherweise funktioniert das aber nur mit Echtzeit-Kernel. Zudem ist mein letzter Stand, dass der SPI-Treiber keine Höherpriorisierung unterstützt, sodass bei hoher Load Pakete zu spät verarbeitet werden. Ich bin mir auch nicht sicher, ob die Netzwerktreiber Höherpriorisierung unterstützen. Bei timingsensitiven Kommunikationen (wie mit den HomeMatic-Geräten) funktioniert also irgendwann gar nichts mehr.

Viele Grüße

Sathya


#9

Es ist zum Kotzen, nachdem mein Setup einige wenige Tage störungsfrei lief gestern wieder totals Chaos. Gerätekommunikation war gestört bei 3-5 Geräten (zu verschiedenen Zeitpunkten). Ich habe langsam die Vermutung, dass der HM-CFG-LAN verreckt. Zumindest wird homegear.err im betroffenen Zeitpunkt mit Fehlermeldungen aus der Richtung geflutet.

02/03/19 09:30:01.672 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hm-cfg-lan-1": Warning: Too short packet received: F2
02/03/19 09:30:03.662 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hm-cfg-lan-1": Warning: Too short packet received: 94
02/03/19 09:30:04.187 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hm-cfg-lan-1": Warning: Too short packet received: B5
02/03/19 09:30:07.245 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hm-cfg-lan-1": Warning: Too short packet received: 74
02/03/19 09:30:07.510 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hm-cfg-lan-1": Warning: Too short packet received: 60
02/03/19 09:30:08.176 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hm-cfg-lan-1": Warning: Too short packet received: 8A
02/03/19 09:30:10.297 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hm-cfg-lan-1": Warning: Too short packet received: 33
02/03/19 09:30:11.219 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hm-cfg-lan-1": Warning: Too short packet received: 46
02/03/19 09:30:12.052 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hm-cfg-lan-1": Warning: Too short packet received: 6C
02/03/19 09:30:13.511 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hm-cfg-lan-1": Warning: Too short packet received: FC
02/03/19 09:30:14.205 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hm-cfg-lan-1": Warning: Too short packet received: 27
02/03/19 09:30:17.319 Module HomeMatic BidCoS: LAN-Konfigurationsadapter "hm-cfg-lan-1": Warning: Too short packet received: EA

Ich klemm’ das Ding jetzt erstmal ab, dadurch verliere ich zwar wieder Reichweite, aber vielleicht werden die Fehler ja weniger.


#10

Hallo @m0wlheld,

entweder mag der HM-CFG-LAN tatsächlich nicht oder der Pi war zu dem Zeitpunkt extrem ausgelastet. Bis zu 2 Sekunden Abstand zwischen zwei Bytes ist schon ziemlich viel…

Viele Grüße

Sathya


#11

Das wird das HM-CFG-LAN gewesen sein, die beiden Pi’s (“denise” und “paula”) sind ja nur noch homegear-gateways, der Rest (homegear und Home Assistant) “langweilen” seit einer Woche einen N54L Server.