fhem Absturz nach Stopp der RCP Server einer HMCCU device

[clang]

fhem Absturz nach Stopp der RCP Server einer HMCCU device


Hallo zap, hallo *,

ich habe ein reproduzierbares Problem mit einem Programmabsturz von fhem: ich teste gerade HMCCU(CHN|DEV|RPC), um den Status eines Homematic IP-Geräts in fhem abzubbilden, welches an einer piVCCU angelernt wurde.

Es funktioniert alles super, sowohl mit der Instanziierung der notwendigen Prozesse, also auch mit der Übertragung der Attribute, und das ist schon ziemlich beeindruckend, was da alles im Log angezeigt wird und wie gut die Kommunikation funktioniert! Es geht aber nur gut, solange ich nach dem Befehl set HW_PI_HMCCU2 rpcserver on nicht die Prozesse mit dem Gegenbefehl wieder stoppe oder die Konfiguration sichere - in beiden Fällen stürzt fhem ab.

Hier die Fehlermeldung nach Ausführen von set HW_PI_HMCCU2 rpcserver off

Code Auswählen Erweitern

*** Error in `perl': double free or corruption (!prev): 0x02b41f40 ***

Hier die Fehlermeldung nach Ausführen der Konfigurationssicherung in der WebUI:

Code Auswählen Erweitern

hash- or arrayref expected (not a simple scalar, use allow_nonref to allow this) at ./FHEM/31_LightScene.pm line 364.

Ich setze Raspbian GNU/Linux 9 (stretch) mit Kernel 4.9.59+ und Perl v5.24.1 ein. Sowohl das System als auch fhem sind frisch aktualisiert.

Jetzt habe ich tagelang gebraucht, um auf einem Raspi mit Funkmodul eine CCU ans Laufen und daran eine HmIP-Device angelernt zu bekommen, und jetzt tut es am Ende das gute alte fhem nicht...  Gibt es etwas, was ich zur Behebung des Poblems oder auch nur zur Fehleranalyse tun kann ?

TIA, chris

[zap]

Das Verhalten ist (leider) bekannt. Liegt an einer Inkompatibilität zwischen den Perl Modulen JSON::XS und threads. Zur Abhilfe gibt es 2 Möglichkeiten:

1. In HMCCU den internen RPC Server verwenden (Attribut ccuflags) und das HMCCURPC Device löschen. Nachteil: Die Reaktion von FHEM auf Zustandsänderungen von Homematic Komponenten wird verlangsamt (von <1 auf >3-4 Sekunden).

2. Perl Modul JSON::XS deinstallieren. Wie ist hier beschrieben: https://wiki.fhem.de/wiki/HMCCU#RPC_Server_konfigurieren . Nachteil: Wenn sehr (sehr) viele JSON Daten verarbeitet werden, kann es hierbei zu Performance Einbußen kommen. Zumindest ich habe davon nichts bemerkt.

[clang]

Hallo nochmal,

vielen Dank für die prompte Hilfe! Den genannten Wiki-Eintrag habe ich auch schon gesehen, und den für das Problem relevanten Teil leider nicht richtig eingeordnet.

Zu meiner Ehrenrettung muß ich sagen, daß ich in dem Verhalten kein JSON-Fehler gesehen habe. Im Eintrag steht zu lesen: Falls im Log von FHEM JSON Fehlermeldungen auftauchen ..., ich habe aufgrund der Formulierung wohl erwartet, daß da nach der Definition der HMCCU-device Fehlermeldungen stehen, die das Wort JSON enthalten.

Allerdings ist mit der Deinstallation von JSON::XS lediglich der Fehler beim Speichern der Konfiguriation weg - womit ich das System aber immerhin betreiben kann. Der Absturz beim Stoppen des RCP-Servers nach set HW_PI_HMCCU2 rpcserver off mit der bereits genannten Fehlermeldung passiert weiterhin, da scheint es also nocn ein weiteres Problem zu geben.

Zu der Wiki-Seite bezgl. HMCCU: Ich würde den Text so erweitern, daß es z.B. zu Abstürzen beim Speichern der Konfiguration oder Stoppen der RPC-Server kommen kann - das sind ja beides Schritte, die man problemlos testen kann, um einen Fehler auszuschliessen. Ich mache das durchaus auch selbst, muß mir dafür noch Wiki-Credentials besorgen

Wenn HMCCU das problematische Modul detektieren könnte, wäre vielleicht auch eine Warnung im Logfile möglich, wennn zusätzlich auch das Attribut ccuflags auf extrpc gesetzt wird !?

Ich habe da auch noch ein Problem mmit den HMCCU-Attributwerten webCmd control und widgetOverride control:uzsuToggle,off,on,
die habe ich erst einmal gelöscht, weil das Control einfach nicht funktioniert hat. Ich nehme an, hierzu sollte ich besser ein eigenes Thema öffnen !?

TIA, chris

[zap]

Ich nehme an, du meinst das Attribut controldatapoint? Die Attribute webCmd und widgetOverride sind Standard FHEM Attribute, die einen Set Befehl als Steuerelement oder Link in die FHEM Oberfläche einbauen. Hast du dieses Problem im HMCCU oder in einem HMCCUDEV/HMCCUCHN Device? Poste doch mal alle Attribute, die gesetzt sind.

Zu dem Stop Problem: Hängt in dem Fall wohl nicht mit JSON::XS zusammen. Sonst gibt es keine Fehlermeldungen im Log? Anscheinend hat das Problem außer dir niemand. Bitte poste mal alle HMCCU Meldungen während Start und Stop des RPC Servers. Dazu am besten wie folgt vorgehen:

- Attribut rpcserver löschen oder auf off setzen
- FHEM stoppen
- in das Log Verzeichnis von FHEM wechseln und Logfile löschen
- FHEM starten
- RPC Server starten mit set rpcserver on
- warten bis alles läuft, dann wieder stoppen mit set rpcserver off
- Befehl ,,grep -i ccu Logfile" ausführen und Ausgabe posten

[clang]

Stimmt, da war ich etwas ungenau. Ich meinte tatäschlich, daß die Steuerung über das Widget nicht funktioniert, also das physische Gerät nicht umkonfiguriert wurde (hier: Aus/Einschalten der Präsenzerkennung), woran nicht die genannten Attribute schuld sein sollten. Ich persönlich brauche das nicht, da die Funktion hier immer an sein soll, helfe aber gerne bei der Fehlersuche.

Hier die momentane raw definition der Client-Device, also ohne die genannten Attribute:

Code Auswählen Erweitern

defmod HW_WZ_Presence HMCCUDEV 000C17099A00AF
attr HW_WZ_Presence IODev HW_HMCCU2
attr HW_WZ_Presence ccureadingfilter (ILLUMINATION|PRESENCE|LOW_BAT)
attr HW_WZ_Presence ccureadingname 0.LOW_BAT:battery;;1.ILLUMINATION:illumination;;1.PRESENCE_DETECTION_STATE:presence
attr HW_WZ_Presence controldatapoint 1.PRESENCE_DETECTION_ACTIVE
attr HW_WZ_Presence event-on-change-reading presence,battery,illumination
attr HW_WZ_Presence eventMap /datapoint 1.RESET_PRESENCE 1:reset/datapoint 1.PRESENCE_DETECTION_ACTIVE 1:detection-on/datapoint 1.PRESENCE_DETECTION_ACTIVE 0:detection-off/
attr HW_WZ_Presence hmstatevals SABOTAGE!(1|true):sabotage
attr HW_WZ_Presence statedatapoint 1.PRESENCE_DETECTION_STATE
attr HW_WZ_Presence stripnumber 1
attr HW_WZ_Presence substitute LOW_BAT!(0|false):ok,(1|true):low;;PRESENCE_DETECTION_STATE!(0|false):absent,(1|true):present;;PRESENCE_DETECTION_ACTIVE!(0|false):off,(1|true):on

Ich habe nur wenige Dinge hinzugefügt oder angepasst, nämlich die Umsetzung in die Attribute presence, battery und illumination mit passenden Werten, damit die mit meinen readingGroups zusammenpassen.

Nun zum Nachstellen des Absturzes:

• fhem: deleteattr ... rpcserver
• fhem: shutdown
• shell: reset log
• shell: fhem start
• fhem: set ... rpcserver on
• fhem: set ... rpcserver off
• shell: cat logfile

Hier das gesamte Log, die paar Zeilen vom Start habe ich jetzt nicht herausgenommen:

Code Auswählen Erweitern

2018.01.10 21:51:43.121 1: Including fhem.cfg
2018.01.10 21:52:05.435 1: HMCCU: Device HW_HMCCU2. Initialized version 4.1.004
2018.01.10 21:52:05.972 1: HMCCU: Read 2 devices with 53 channels from CCU 172.16.32.12
2018.01.10 21:52:06.426 1: HMCCURPC: Device HW_HMCCU2_rpc. Initialized version 0.98 beta
2018.01.10 21:52:06.646 1: Including ./log/fhem.save
2018.01.10 21:52:12.630 1: usb create starting
2018.01.10 21:52:20.670 1: usb create end
2018.01.10 21:52:20.676 0: Featurelevel: 5.8
2018.01.10 21:52:20.678 0: Server started with 202 defined entities (fhem.pl:15804/2018-01-06 perl:5.024001 os:linux user:fhem pid:9691)
2018.01.10 21:53:44.038 2: HMCCURPC: Starting thread for data processing
2018.01.10 21:53:45.444 2: HMCCURPC: Started thread for data processing. TID=1
2018.01.10 21:53:45.455 2: CCURPC: Thread DATA processing RPC events. TID=1
2018.01.10 21:53:46.815 2: HMCCURPC: RPC server thread started for interface BidCos-RF with TID=2
2018.01.10 21:53:46.824 2: CCURPC: Initializing RPC server CB2001 for interface BidCos-RF
2018.01.10 21:53:47.812 2: HMCCURPC: Callback server CB2001 created. Listening on port 7411
2018.01.10 21:53:47.831 2: CCURPC: CB2001 accepting connections. TID=2
2018.01.10 21:53:48.670 2: HMCCURPC: RPC server thread started for interface HmIP-RF with TID=3
2018.01.10 21:53:48.674 2: CCURPC: Initializing RPC server CB2010 for interface HmIP-RF
2018.01.10 21:53:49.153 2: HMCCURPC: Callback server CB2010 created. Listening on port 7420
2018.01.10 21:53:49.167 2: CCURPC: CB2010 accepting connections. TID=3
2018.01.10 21:53:49.728 1: HMCCURPC: RPC server(s) starting
2018.01.10 21:53:49.822 1: HMUARTLGW HW_HMLGW:keepAlive KeepAlive sent 5.118s too late, this might cause a disconnect!
2018.01.10 21:53:49.830 1: hmlgw:2000 disconnected, waiting to reappear (HW_HMLGW)
2018.01.10 21:53:49.866 1: hmlgw:2001 disconnected, waiting to reappear (HW_HMLGW:keepAlive)
2018.01.10 21:53:49.898 1: HMCCURPC: Received SL event. RPC server DATA enters server loop
2018.01.10 21:53:49.903 1: HMCCURPC: Received SL event. RPC server CB2001 enters server loop
2018.01.10 21:53:49.906 1: HMCCURPC: Received SL event. RPC server CB2010 enters server loop
2018.01.10 21:53:49.909 1: HMCCURPC: All threads working
2018.01.10 21:53:49.913 2: HMCCURPC: Registering callback http://172.16.32.8:7411/fh2001 with ID CB2001 at http://172.16.32.12:2001/
2018.01.10 21:53:50.082 1: CCURPC: CB2001 ListDevices. Sending init to HMCCU
2018.01.10 21:53:50.140 1: HMCCURPC: RPC callback with URL http://172.16.32.8:7411/fh2001 registered
2018.01.10 21:53:50.154 2: HMCCURPC: Registering callback http://172.16.32.8:7420/fh2010 with ID CB2010 at http://172.16.32.12:2010/
2018.01.10 21:53:50.239 1: HMCCURPC: RPC callback with URL http://172.16.32.8:7420/fh2010 registered
2018.01.10 21:53:50.255 1: HMCCURPC: Received IN event. RPC server CB2001 running.
2018.01.10 21:53:50.320 1: CCURPC: CB2010 ListDevices. Sending init to HMCCU
2018.01.10 21:53:50.655 2: CCURPC: CB2010 NewDevice received 3 device and channel specifications
2018.01.10 21:53:50.890 1: HMCCURPC: Received IN event. RPC server CB2010 running.
2018.01.10 21:53:50.939 1: HMCCURPC: All RPC servers running
2018.01.10 21:53:51.310 2: HMCCURPC: Updated devices. Success=1 Failed=0
2018.01.10 21:53:51.418 1: hmlgw:2000 reappeared (HW_HMLGW)
2018.01.10 21:53:51.864 2: CCURPC: CB2001 NewDevice received 52 device and channel specifications
2018.01.10 21:55:38.871 1: HMCCURPC: Found 3 threads. Stopping ...
2018.01.10 21:55:38.904 1: HMCCURPC: Deregistering RPC server http://172.16.32.8:7411/fh2001 with ID CB2001 at http://172.16.32.12:2001/
2018.01.10 21:55:38.954 1: HMCCURPC: RPC callback for server CB2001 deregistered
2018.01.10 21:55:38.956 1: HMCCURPC: Deregistering RPC server http://172.16.32.8:7420/fh2010 with ID CB2010 at http://172.16.32.12:2010/
2018.01.10 21:55:39.009 1: HMCCURPC: RPC callback for server CB2010 deregistered
2018.01.10 21:55:39.012 2: HMCCURPC: Sending signal INT to thread CB2001 TID=2
2018.01.10 21:55:39.015 2: HMCCURPC: Sending signal INT to thread CB2010 TID=3
2018.01.10 21:55:39.230 2: CCURPC: RPC server CB2001 stopped handling connections. TID=2
2018.01.10 21:55:39.952 2: CCURPC: RPC server CB2010 stopped handling connections. TID=3
2018.01.10 21:55:40.054 1: HMCCURPC: Received EX event. Thread CB2001 terminated.
2018.01.10 21:55:40.057 2: HMCCURPC: Thread CB2001 with TID=2 has been stopped. Deleting it
2018.01.10 21:55:40.060 1: HMCCURPC: Thread CB2010 with TID=3 still running. Can't delete it
2018.01.10 21:55:40.066 1: HMCCURPC: Received EX event. Thread CB2010 terminated.
2018.01.10 21:55:40.069 2: HMCCURPC: Thread CB2010 with TID=3 has been stopped. Deleting it
*** Error in `perl': double free or corruption (!prev): 0x04c4c8b8 ***

Sieht alles super aus - bis na klar auf die letzte Zeile

Sollte ich vielleicht den verbosity-Level noch hochdrehen?

TIA chris

[zap]

Bitte gedulde dich noch ein paar Tage. Es gibt bald ein Update. Möglicherweise behebt das dein Problem. Bis dahin bitte den internen RPC Server nutzen.

Alternativ kannst Du mal folgendes versuchen: Für das Device HW_HMCCU2_rpc im Attribut ccuflags das Flag keepThreads aktivieren.

Würde mich interessieren, ob das das Problem löst.

[clang]

Hallo mal wieder und eine guten Start in die Woche!

Das Thema hat definitiv keine Eile, denn wie schon gesagt, ich kann fhem so definitiv betreiben. Ein rpcserver stop macht man ja nichtmal eben so, und sonst stürzte fhem hier nur bei einem shutdown aus der WebUI ab. Schon ein /etc/init.d/fhem stop, also ein pkill des Prozesses, umgeht das Problem auch beim Beenden von fhem, obwohl der Hauptthread den shutdown  nach wie vor vermeldet.

In dieselbe Richtung geht wohl ccuflags keepThreads, damit geht sowohl ein rpcserver stop als auch der shutdown aus der WebUI - das ist also ein absolut brauchbarer Workaround!

TIA chris

[clang]

Hallo zap, hallo *,

habe bislang nichts mehr gehört und das Thema glatt vergessen, nun aber mal wieder ein fhem Update gemacht.

Und dann das Attribut ccuflags  aus dem device HW_HMCCU2_rpc entfernt - und es läuft prima.

Vielen Dank an alle Beteiligten!

bye Chris