Installationsprozess Integration: Custom Homematic

[Alexandra]

Servus,

ich hatte die vorherige Integration installiert und wollte auf die neue Version upgraden. Sicherheitshalber einen Snapshot vom aktuellen Serverstand gemacht. Gute Idee.

Step 1: Deinstallation der bestehenden Integrationen

installierte_integrationen.jpg (5 KiB) 2008 mal betrachtet

Step 2: Upgrade und Neustart
Upgrade der Integration im HACS
Sicherheitshalber Neustart von Home Assistant

Step 3: Erste Integration - bidcos
Welche unserer drei HomeMatics wurden automatisch entdeckt?
Spoiler Alert: Wir haben 2 x CCU und 1 x debmatic. Gefunden wurde 1 x CCU (ausgerechnet die bidcos, warum auch immer).

bidcos_gefunden.jpg (8.58 KiB) 2008 mal betrachtet

Integration installiert, konfiguriert - passt.

success_ccu3dev.jpg (18.93 KiB) 2008 mal betrachtet

Nach einem "Neuladen der Konfiguration" und einem Restart von Home Assistant wurden auch die Geräte/Entitäten angezeigt. Passt.

Step 4: Zweite Integration - ccu3dev
Eine weitere CCU3 in unserem System, die ccu3dev wurde nicht automatisch gefunden,
kein Problem, Hinzufügen der Integration, Parameter übergeben, Integration neu laden, Home Assistant Neustart - kennen wir ja schon alles.

Im Gegensatz zu den Geräten der ersten Installation wurden hier die Namen aus der Rega NICHT übernommen, die Entitäten tragen Namen wie "binary_sensor.hahm_000xxxxxxxx_0_low_bat".

Soll sein, ist ja nur die Dev.

Step 5: Dritte Integration - debmatic
Auch die debmatic wurde nicht automatisch erkannt,
also wieder hinzufügen, neu laden, neu starten ...

Keine Geräte, keine Entitäten.

debmatic.jpg (5.81 KiB) 2008 mal betrachtet

Auch nach mehrmaligem Neuladen / Durchstarten keine Änderung.

Was sagt das Logfile?

Code: Alles auswählen

2022-01-28 09:14:07 ERROR (MainThread) [hahomematic.central_unit] check_connection: No clients exist. Trying to create clients for server debmatic
2022-01-28 09:14:07 WARNING (MainThread) [hahomematic.central_unit] create_clients: Trying to create interfaces to central debmatic. Using saved client configs)
2022-01-28 09:14:07 WARNING (MainThread) [hahomematic.central_unit] create_clients: Failed to create interfaces for central {}. (('Failed to get backend version. Not creating client: http://user:passwd@debmatic.milnet.at:2000',))
2022-01-28 09:14:09 ERROR (SyncWorker_8) [homeassistant] Error doing job: Future exception was never retrieved

[140586428583168] Client exceeded max pending messages [2]: 2048
09:13:15 – (FEHLER) Home Assistant WebSocket API - Die Nachricht ist zum ersten Mal um 09:13:13 aufgetreten und erscheint 1430 mal

check_connection: No clients exist. Trying to create clients for server debmatic
09:29:13 – (FEHLER) /usr/local/lib/python3.9/site-packages/hahomematic/central_unit.py

Soweit, so gut ... zurück zum Start .. "revert to latest snapshot".

Liebe Grüße, Alexa

[danielperna84]

Step 3: Es ist nicht so, dass Home Assistant nach Geräten sucht (soweit ich weiß). Die Geräte schicken selbst per ssdp eine Nachricht ins Netzwerk dass es sie gibt. Da können auch schon mal mehrere Minuten vergehen bis ein Gerät sagt "Hallo, hier bin ich". Hier wäre also vielleicht noch mehr gekommen mit der Zeit.

Step 4: Mit der aktuellen Version musst du die Integration nicht mehr neu laden nach dem Setup. Auch Home Assistant muss nicht mehr neu gestartet werden. Das sollte alles ganz straight-forward gehen.
Warum die Namen nicht aufgelöst wurden kann ich natürlich nicht sagen. Hier wäre es interessant zu sehen was in den Logs steht / stand.

Step 5: Meine Debmatic wird erkannt. Ist also definitiv kein kompatibilitätsproblem. Je nach Firewall auf dem OS kann es aber natürlich sein, dass die Pakete für die Erkennung blockiert werden.
Woher die Meldung mit der Backend Version kommt weiß ich nicht. Aber ohne zu wissen welches Backend vorhanden ist, ist es der Integration auch nicht möglich die entsprechenden Methoden zu nutzen um an die Daten zu kommen. Hier wären ggf. Logs vom Debmatic Host interessant. Vielleicht gibt's auf dem ja Probleme. Das war bei mir gestern Abend tatsächlich auch der Fall. Ich konnte die Integration eine Zeit lang gar nicht fertig konfigurieren. Auf dem Host habe ich dann gesehen, dass ein java-Prozess permanent 100% CPU Last erzeugt hat. Der debmatic Service ließ sich auch nicht stoppen. Musste dann ein kill -9 auf die PID machen. Nach einer Weile ging's dann wieder.

[Alexandra]

Servus,

ad Step 3:
ich denke nicht dass hier noch etwas gekommen wäre, das Setup war für etwa 2h im Netz. Ist aber für mich nicht entscheidend, (noch) weiss ich welche Server ich am Start habe und habe auch kein Problem damit die händisch einzubinden

ad Step 4:
ok, gut zu wissen dass hier kein Reload mehr nötig ist - kommen die Geräte dann mit der Zeit von selbst? Instant waren sie jedenfalls nicht hier.

ad Step 5:
Die Integration der debmatic funktioniert wenn ich sie im laufenden Betrieb von der Version 0.27.1 auf 0.28.0 upgrade.
Wenn ich die debmatic VOR dem Update rauswerfe und dann versuche sie neu anzulegen funktioniert dieser Vorgang reproduzierbar nicht.

Logfiles vom Host kann ich gerne zur Verfügung stellen.

Detail am Rande: Bei einem der Durchgänge (ja, ich hab das ganze mehrfach durchgespielt) kam es zu einem interessanten Fall:
Alle Integrationen gelöscht - (durchgestartet) - UPDATE der Integration - (durchgestartet) - Installation der (automatisch erkannten) bidcos -> Home Assistant startet OHNE mein Zutun durch .. nope, kein Durchstart, kommt nicht mehr in die Höhe.
War nicht mehr zu erwecken - ohne Snapshot wär's trist gewesen.

Im Moment ist das ganze jedenfalls noch etwas wackelig - aber ist ja auch ok so, ist ja noch in Development.

Liebe Grüße, Alexa

[danielperna84]

Step 3: Hm, komisch. Vielleicht ist es tatsächlich so, dass das discovery abbricht sobald es ein Ergebnis gab.

Step 4: Es sollte alles komplett da sein. Also so wie als würde die Integration sich automatisch neu laden und alles ist perfekt. Wenn das nicht funktioniert wären auch hier Logs hilfreich.

Step 5: Ok, das klingt nach einem echten Problem.

Grundsätzlich würde ich sagen, dass für diese Probleme Issues im Repo angelegt werden sollten.

[Baxxy]

zu 3 kann ich sagen das bei mir das "Auto-Discovery" problemlos funktioniert.

Die .26 und .27 sind die beiden Dauerläufer die aber schon (über eine ältere Version) als RM-26 und RM-27 integriert sind.
Die .18 ist eine VM die ich heute morgen für ein paar Tests gebootet hatte.

Jetzt schmeiße ich mal die .27 raus und binde sie dann neu ein, mal schauen.

[Alexandra]

Servus,

neuer Tag, neues Glück.
Snapshot - Update der Integration auf 0.28.3

Integration der debmatic:
ein Großteil der bestehenden Entities sind in der Übersicht mit rotem Rufzeichen versehen, nicht mehr adressiert.

debmatic-Konfiguration rauslöschen - neu anlegen - erkannt wird 1 Dienst und 136 Entitäten (die Systemvariablen).
Keine Geräte, keine Datenpunkte.
Logfile:

Code: Alles auswählen

create_clients: Failed to create clients for central {'debmatic-HmIP-RF': <hahomematic.client.ClientCCU object at 0x7f9dd65098e0>, 'debmatic-BidCos-RF': <hahomematic.client.ClientCCU object at 0x7f9dd61d1250>}. (('Failed to get backend version. Not creating client: http://user:password@10.20.30.10:2000',))

Welche Logs soll ich euch zur Verfügung stellen um das Problem zu debuggen?
Die debmatic läuft unverändert stabil und ist in anderen Systemen weiterhin problemlos ansprechbar.

Liebe Grüße,
Alexa

[danielperna84]

@Alexandra

Könntest du mal folgendes in einem Python 3 Interpreter machen und sagen was du bekommst?

Code: Alles auswählen

from xmlrpc.client import ServerProxy
p = ServerProxy("http://user:password@10.20.30.10:2000")
p.getVersion()

Das macht der Code um zu schauen mit was für einem Backend die Integration spricht. Wenn du hierbei eine Exception bekommst wäre es interessant zu sehen was die Logs auf Debmatic dazu sagen. Hier könnte ggf. ein Reboot von Debmatic helfen falls da ein Dienst gerade instabil läuft. Andere Tools fragen Debmatic vermutlich nicht auf diesem Weg ab, weshalb da das Problem nicht erscheint.

[Alexandra]

Servus,

auf einem Rechner im selben Netz kommt als Antwort

Code: Alles auswählen

    raise ProtocolError(
xmlrpc.client.ProtocolError: <ProtocolError for user:password@10.20.30.10:2000/RPC2: 503 Service Not Available>

Nachdem auf der debmatic im Moment Geräteupdates laufen (und wer unser System kennt weiss dass das 2-3 Monate dauern kann) möchte ich sie ungern nur auf Vermutung hin rebooten. Einzelne Prozesse monitoren ist natürlich kein Problem.

Bezüglich Logs auf der debmatic - auf den ersten Blick nichts ungewöhnliches zu erkennen, wonach soll ich greppen?

[Baxxy]

Mir ist da gestern was fieses im Zusammenhang mit einem Bug im Virtual-Devices-Teil des HmIP-Server und dem (gerade bei Testen häufig nötigen) HA-Neustart's aufgefallen. (wenn man auch die Gruppen in der Integration aktiviert hat)

Jeder HA-Neustart lässt einen "Zombie-Init" am Virtual-Devices-Teil zurück. (Der Bug des HmIP-Server ist, das diese Inits nicht nach einem unreach-Timeout rausgekickt werden).
Da versucht die Zentrale dann weiterhin die Events auszuliefern, das geht aber nicht und es kommt zum Stau. Zuerst werden dann die Gruppengeräte "zäh", d.h. die Stati der Gruppengeräte hinken den echten Sensorstati hinterher. Z.B. Fenster wird geöffnet, Sensor zeigt sofort an, Gruppe erst Minuten bis Stunden später. Irgendwann kommt es wohl auch zum Speicherüberlauf und die Zentrale kommt quasi zum erliegen.
Ich vermute das geht umso schneller, je mehr Gruppengeräte vorhanden sind.

Ich kenne leider nur die Möglichkeit solche "Zombie-Inits" mittels SDV von @Black zu erkennen. (Über CCU-Services --> Allgemein --> Systemübersicht, dann im rechten Fenster ganz nach unten Scrollen.
Das sieht dann z.B. so aus: (.211 ist der HA-Host)

Korrekt wäre ein Init für die Gruppen-Integration, so wie hier zu sehen.

HA_RM_Integration_Virt_Dev_OK.JPG (24.39 KiB) 1837 mal betrachtet

Ach ja, los wird man die Zombie-Inits nur durch einen Restart des HmIP-Server oder eben der ganzen Zentrale.

Vielleicht klemmt es deswegen bei Euch.
(Meine Re-Integration der per Discovery gefundenen Instanzen verlief auch äußerst holprig)

[danielperna84]

@Alexandra

Also ich kann die Meldung "simulieren", da ich keine Wired-Geräte habe und es bei mir deshalb richtigerweise nichts gibt was für Port 2000 zuständig ist. Ich sehe in /var/log/lighttpd/error.log sowas:

Code: Alles auswählen

2022-01-30 12:01:01: (gw_backend.c.240) establishing connection failed: Connection refused socket: tcp:127.0.0.1:32000
2022-01-30 12:01:01: (gw_backend.c.956) all handlers for /RPC2? on  are down.
2022-01-30 12:01:03: (gw_backend.c.319) gw-server re-enabled: tcp:127.0.0.1:32000 127.0.0.1 32000

Unabhängig davon bekomme ich aber tatsächlich auch gerade für die Gruppen keinen korrekten Wert zurück.

Code: Alles auswählen

>>> p = ServerProxy("http://192.168.1.20:9292/groups")
>>> p.getVersion()
'UNDEFINED'

Wenn ich dann folgendes mache:

Code: Alles auswählen

root@hassbian:/var/log# netstat -tlnp | grep 9292
tcp        0      0 0.0.0.0:9292            0.0.0.0:*               LISTEN      606/lighttpd
tcp6       0      0 :::9292                 :::*                    LISTEN      606/lighttpd
tcp6       0      0 :::39292                :::*                    LISTEN      27126/java
root@hassbian:/var/log# strace -f -p 27126 -s 256

...bekomme ich sehr viel Output, der inhaltlich vermuten lässt, dass da irgendein Serverprozess hängt.

In /var/log/daemon.log steht dann ganz viel hiervon:

Code: Alles auswählen

Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: Jan 30, 2022 12:23:45 PM io.vertx.core.impl.BlockedThreadChecker
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: WARNUNG: Thread Thread[hasstest-HmIP-RF_WorkerPool-1,5,main] has been blocked for 101067 ms, time limit is 60000
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: io.vertx.core.VertxException: Thread blocked
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at java.net.PlainSocketImpl.socketConnect(Native Method)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at java.net.Socket.connect(Socket.java:607)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:120)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:179)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:144)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:134)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:612)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:447)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at org.apache.http.impl.client.AbstractHttpClient.doExecute(AbstractHttpClient.java:884)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:107)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at de.eq3.cbcs.legacy.communication.rpc.internal.transport.http.HttpTransport.sendRequest(HttpTransport.java:106)
Jan 30 12:23:45 hassbian start_hmserver.sh[27106]: #011at de.eq3.cbcs.legacy.communication.rpc.internal.rpc.RpcClient.sendRequest(RpcClient.java:94)

Ein Reboot hat diesen blockierten Thread wohl abgeschossen und weitere Meldungen bleiben aus. Ich bekomme aber auch weiterhin UNDEFINED als Server-Version für die Gruppen. Da ich das vorher nie explizit gecheckt habe weiß ich nicht, ob das nicht vielleicht sogar normal für Port 9292. Hier müsste mal jemand mit einer echten CCU oder RaspiMatic mal sagen was dort als Antwort kommt.

Das hier ist jetzt nicht wirklich hilfreich, aber es zeigt zumindest auf wo ich hinschaue um den Problemen auf den Grund zu gehen. Interessant sind auch noch /var/log/syslog und /var/log/debug.

@Baxxy

Eigentlich sollte die Integration ein De-Init machen wenn sie beendet wird. Geht der von dir genannte Bug so weit, dass die Zombie-Inits behalten werden OBWOHL man das De-Init macht?