[gelöst] HMCCU blockiert beim Hochfahren (war: HMCCU und XML-API 1.22)

[kjmEjfu]

Ahoi,

für die XML-API gab es ein Update auf die 1.22
Seit ich die installiert habe, habe ich beim FHEM Restart einen sehr langen Hänger (22:49:57.942 für 12 Minuten):

Code Auswählen Erweitern

2022.06.22 22:49:38.854 1: HMCCU [d_ccu] Reading device config from CCU. This may take a couple of seconds ...
2022.06.22 22:49:40.160 2: HMCCU [d_ccu] Reading Device Descriptions for interface BidCos-RF
2022.06.22 22:49:41.550 2: HMCCU [d_ccu] Read 154 Device Descriptions for interface BidCos-RF
2022.06.22 22:49:41.550 2: HMCCU [d_ccu] Reading Paramset Descriptions for interface BidCos-RF
2022.06.22 22:49:53.694 2: HMCCU [d_ccu] Read 225 Paramset Descriptions for interface BidCos-RF
2022.06.22 22:49:53.694 2: HMCCU [d_ccu] Reading Peer Descriptions for interface BidCos-RF
2022.06.22 22:49:55.016 2: HMCCU [d_ccu] Read 62 Peer Descriptions for interface BidCos-RF
2022.06.22 22:49:56.328 2: HMCCU [d_ccu] Reading Device Descriptions for interface HmIP-RF
2022.06.22 22:49:57.942 2: HMCCU [d_ccu] Read 355 Device Descriptions for interface HmIP-RF
2022.06.22 22:49:57.942 2: HMCCU [d_ccu] Reading Paramset Descriptions for interface HmIP-RF
2022.06.22 23:02:06.801 2: HMCCU [d_ccu] Read 531 Paramset Descriptions for interface HmIP-RF
2022.06.22 23:02:06.801 2: HMCCU [d_ccu] Reading Peer Descriptions for interface HmIP-RF
2022.06.22 23:02:08.191 2: HMCCU [d_ccu] Read 30 Peer Descriptions for interface HmIP-RF
2022.06.22 23:02:08.251 2: HMCCU [d_ccu] Read device configuration in 749.397107124329 seconds: devices/channels=509 parametersets=756 links=92
2022.06.22 23:02:08.251 2: HMCCU [d_ccu] RPC device for interface HmIP-RF: d_rpcHmIP_RF
2022.06.22 23:02:08.251 2: HMCCU [d_ccu] RPC device for interface BidCos-RF: d_rpcBidCos_RF
2022.06.22 23:02:08.257 2: HMCCURPCPROC [d_rpcHmIP_RF] RPC server process started for interface HmIP-RF with PID=11540
2022.06.22 23:02:08.260 2: HMCCURPCPROC [d_rpcHmIP_RF] Initializing RPC server CB2010050051178059 for interface HmIP-RF
2022.06.22 23:02:08.261 1: HMCCURPCPROC [d_rpcHmIP_RF] RPC server starting
2022.06.22 23:02:08.269 2: HMCCURPCPROC [d_rpcBidCos_RF] RPC server process started for interface BidCos-RF with PID=11541
2022.06.22 23:02:08.272 2: HMCCURPCPROC [d_rpcBidCos_RF] Initializing RPC server CB2001050051178059 for interface BidCos-RF
2022.06.22 23:02:08.273 1: HMCCURPCPROC [d_rpcBidCos_RF] RPC server starting
2022.06.22 23:02:08.274 2: HMCCU [d_ccu] RPC server start: 2 started, 0 already running, 0 failed to start
2022.06.22 23:02:08.280 2: HMCCURPCPROC [d_rpcHmIP_RF] Callback server CB2010050051178059 created. Listening on port 7420
2022.06.22 23:02:08.281 2: HMCCURPCPROC [d_rpcHmIP_RF] CB2010050051178059 accepting connections. PID=11540
2022.06.22 23:02:08.291 2: HMCCURPCPROC [d_rpcBidCos_RF] Callback server CB2001050051178059 created. Listening on port 7411
2022.06.22 23:02:08.292 2: HMCCURPCPROC [d_rpcBidCos_RF] CB2001050051178059 accepting connections. PID=11541

Firewalleinstellungen auf der CCU3 sind weiterhin:
Firewall-Richtline: Ports offen
Homematic XML-RPC API: Eingeschränkt
Remote Homematic-Script-API: EIngeschränkt
Port-Freigabe: (nix)
IP-Adressen für den eingeschränkten Zugriff: 192.168.0.0/16

Damit hat es vorher auch gut funktioniert.
Irgendeine Idee, woran das jetzt liegen kann?

FHEM ist aktuell und läuft auf Basis des latest-Docker-Containers, librpc-xml-perl ist da schon installiert.

[frank]

am längsten dauert dieses einlesen:

Code Auswählen Erweitern

2022.06.22 22:49:57.942 2: HMCCU [d_ccu] Reading Paramset Descriptions for interface HmIP-RF
2022.06.22 23:02:06.801 2: HMCCU [d_ccu] Read 531 Paramset Descriptions for interface HmIP-RF

hat sich hier der datenumfang vielleicht deutlich erhöht?
oder dieses lesen hat ein problem.

[kjmEjfu]

Da hat sich nichts dran verändert.
Habe weder neue Geräte, noch irgendwas umgestellt.

Im Changelog der XML-API steht

Code Auswählen Erweitern

limit the update-check.cgi to parse for cmd=download and not parse arbitrary query string options.

k.A. ob HMCCU das nutzt und jetzt gebremst wird.

[zap]

HMCCU nutzt das XML-API Addon nicht.

[kjmEjfu]

Puh, ok.

Hast du dann eine Idee, woran das liegen könnte?
Am Netzwerk hat sich nichts geändert, auf der CCU3 nur das Addon, bei HMCCU gab es keine Änderungen in letzter Zeit ... dubios.
Habe ich eventuell einen Anhaltspunkt wenn ich Verbose hochdrehe?

[kjmEjfu]

Update auf die neue 3.63.9.20220625 von RaspberryMatic hat auch nichts verbessert.

[zap]

Ich bin etwas hintendran mit meinen CCU Updates. Versuche mal folgendes:

- RPC Server oder FHEM stoppen
- CCU neu starten und mal 5-10 Minuten warten (die CCU ist nach einem Neustart ziemlich beschäftigt)
- Dann RPC Server oder FHEM wieder starten

Falls das nicht hilft, mal im Log von der CCU schauen ob da Fehlermeldungen dring stehen.

[kjmEjfu]

"RPC Server stoppen, CCU neu starten, RPC neu starten" funktioniert ziemlich gut.
Liegt allerdings IMO daran, dass dieser Teil:

Code Auswählen Erweitern

2022.06.27 02:21:58.135 2: HMCCU [d_ccu] Reading Paramset Descriptions for interface HmIP-RF
2022.06.27 02:38:22.638 2: HMCCU [d_ccu] Read 531 Paramset Descriptions for interface HmIP-RF

bei dem es so ewig dauert, ja nur bei einem Neustart von FHEM passiert.

[kjmEjfu]

So, im Log der CCU ist nichts zu finden.
Sehr dubios, da ich HMCCU ja quasi nutze seit es das gibt.

Apptime zeigt mir noch sowas an:

Code Auswählen Erweitern

name                                     function                               max    count      total  average   maxDly   avgDly TS Max call     param Max call
tmr-HMCCURPCPROC_RPCPing                 HASH(0x55c9b3d7df68)                  4666        8   35091.13  4386.39   979.61   124.39 07.07. 11:20:53 HASH(d_rpcBidCos_RF)

Womit der RPCPing beim average auf Platz 1 ist.
Ist das normal?

[kjmEjfu]

Vielleicht ist aber auch irgendwas in meiner Config nicht in Ordnung, was bisher aus irgendwelchen Gründen kein Problem erzeugt hat?

HMCCU:

Code Auswählen Erweitern

defmod d_ccu HMCCU 192.168.178.59 waitforccu=180
attr d_ccu userattr rpcinterfaces:multiple-strict,HmIP-RF,BidCos-RF,VirtualDevices
attr d_ccu ccuReqTimeout 10
attr d_ccu ccuaggregate name:battery,filter:type=HMCCUDEV|HMCCUCHN,read:(LOWBAT|LOW_BAT),if:any=yes,else:no,prefix:battery_,coll:comment!Batterien OK;;\
name:unreachable,filter:type=HMCCUDEV|HMCCUCHN,read:Activity,if:any=dead,else:alive,prefix:unreach_,coll:comment!Alle Devices erreichbar;;
attr d_ccu ccudef-hmstatevals UNREACH!(1|true):unreachable;;FAULT_REPORTING!#1-3:err_f_${value},#5:err_f_${value},#7-9:err_f_${value};;ERROR_OVERHEAT!(1|true):err_overheated;;ERROR_OVERLOAD!(1|true):err_overloaded;;ERROR_REDUCED!(1|true):err_reduced;;ERROR!#1-3:err_${value},#5-9:err_${value};;INHIBIT!(1|true):locked;;DIRECTION!1:up,2:down,3:undefined;;WORKING!(1|true):working;;MOTION!.*:${MOTION};;LEVEL!#0-0:off,#1-99:${LEVEL},#100-100:on;;STATE!.*:${STATE};;VALVE_STATE!.*:${VALVE_STATE}%;;CONTROL_MODE!.*:${CONTROL_MODE};;FAULT_REPORTING!6:warn_battery;;LOW_?BAT!(1|true):warn_battery;;ERROR!4:warn_battery;;UNREACH!0:ok;;
attr d_ccu ccudef-readingformat datapoint
attr d_ccu ccudef-substitute AES_KEY!(0|false):off,(1|true):on;;LOWBAT,LOW_BAT!(0|false):ok,(1|true):low;;UNREACH!(0|false):alive,(1|true):dead;;MOTION!(0|false):noMotion,(1|true):motion;;DIRECTION!0:stop,1:up,2:down,3:undefined;;SABOTAGE!0:false,1:true;;WORKING!0:false,1:true;;INHIBIT!(0|false):unlocked,(1|true):locked
attr d_ccu ccuflags procrpc,nonBlocking,reconnect
attr d_ccu cmdIcon on:general_an off:general_aus
attr d_ccu event-on-change-reading .*
attr d_ccu room Homematic
attr d_ccu rpcinterfaces BidCos-RF,HmIP-RF
attr d_ccu rpcserver on
attr d_ccu rpcserveraddr 192.168.50.51
attr d_ccu rpctimeout 5
attr d_ccu stateFormat rpcstate/state
attr d_ccu stripnumber 1


BidCos-RPC:

Code Auswählen Erweitern

defmod d_rpcBidCos_RF HMCCURPCPROC 192.168.178.59 BidCos-RF
attr d_rpcBidCos_RF alias CCU RPC BidCos-RF
attr d_rpcBidCos_RF ccuflags expert
attr d_rpcBidCos_RF eventMap /rpcserver on:on/rpcserver off:off/
attr d_rpcBidCos_RF room Homematic
attr d_rpcBidCos_RF rpcServerAddr 192.168.50.51
attr d_rpcBidCos_RF stateFormat rpcstate/state
attr d_rpcBidCos_RF verbose 2

HM-IP RPC:

Code Auswählen Erweitern

defmod d_rpcHmIP_RF HMCCURPCPROC 192.168.178.59 HmIP-RF
attr d_rpcHmIP_RF alias CCU RPC HmIP-RF
attr d_rpcHmIP_RF ccuflags expert
attr d_rpcHmIP_RF eventMap /rpcserver on:on/rpcserver off:off/
attr d_rpcHmIP_RF room Homematic
attr d_rpcHmIP_RF rpcServerAddr 192.168.50.51
attr d_rpcHmIP_RF stateFormat rpcstate/state
attr d_rpcHmIP_RF verbose 2

[kjmEjfu]

So, hab den Fehler beseitigt. Auch wenn ich bei der Ursache nicht ganz sicher bin.

Folgendes habe ich getan:
1. die beiden RPC Devices gelöscht und neu anlegen lassen
2. ein "configdb reorg" durchführen lassen

jetzt läuft ein Neustart (mehrfach getestet) ohne Pause/Blockieren innerhalb von Sekunden durch.