search

ioBroker / ioBroker.hm-rpc

Connects HomeMatic Interface-Processes to ioBroker
www.iobroker.org
MIT License
60 stars 25 forks source link

Reconnect problems after network issues #215

Closed twonky4 closed 4 years ago

twonky4 commented 4 years ago

Describe the bug I have 2 iobroker. One master and one slave system. On the slave system I have a hm-rpc adapter installed and it's working fine. But if I reboot the master system I cannot send any commands to my CCU any more. The states are stay with ack: false. If I change the STATE directly on the CCU then the iobroker state was refreshed and have ack: false, but a change again on the iobroker state will not transmitted to the CCU. If I stop and start the adapter it start working correctly.

To Reproduce Steps to reproduce the behavior:

  1. Reboot the iobroker of 2 connected iobroker systems which is the master system. A network reconnect (for example a reboot of a router) of the slave system will also trigger the same issue.
  2. Try to a changed object state of the hm-rpc which is running at the slave system after the reboot/reconnected is done.
  3. The changed state will not transmitted to the CCU.

Expected behavior The hm-rpc should transmit changed state values to the CCU after a reboot.

Screenshots & Logfiles iobroker.2019-12-12_master.log iobroker.2019-12-12_slave.log

Versions:

Additional context I noticed it after I refreshed the versions of the adapters, JS-Controller and CCU3. So I hope the issue is on the correct place. I don't have other adapter on the slave system to test with if it's depended on hm-rpc or JS-Controller. I test with a "Funk-Schaltaktor mit Leistungsmessung".

twonky4 commented 4 years ago

The issue still exists in hm-rpc 1.12.1.

foxriver76 commented 4 years ago

Hui @Apollon77 irgendeine Idee warum der Adapter der auf dem Slave läuft nach Master Neustart Probleme haben könnte? Evtl. Bekommt er die StateChange Events nicht mehr?

@twonky4 werden die stateChanges nach dem Neustart noch geloggt auf debug, sprich setValue ...?

Ich vermute ja ist ein Controller issue

twonky4 commented 4 years ago

Nein, das alla

2019-12-12 16:05:45.283 - debug: hm-rpc.0 (17771) xmlrpc -> setValue 1 STATE: false 2019-12-12 16:05:45.284 - debug: hm-rpc.0 (17771) setValue ["PEQ0412824:1","STATE",false] BOOL

wird nicht mehr geloggt nach dem Neustart.

Oder meinst du mit stateChanges noch was anders?

foxriver76 commented 4 years ago

19.44 Controller Neustart und danach sehe ich kein setValue mehr geloggt, bin allerdings gerade nur am Smartphone...

twonky4 commented 4 years ago

Genau das habe ich auch gesehen.

foxriver76 commented 4 years ago

Muss Ingo was zu sagen.

Apollon77 commented 4 years ago

Wann genau war denn der master weg?

die sets kommen im Log im Sekundentakt bis 16:05:45 ... dann stoppt es. Der Master Restart war doch erst 19:44 oder wann genau war das was wie?

Das Logging das die DB weg ist sieht man schön beim Slave 19:44:08.172 ... sowas war aber nicht früher

twonky4 commented 4 years ago

Der master restart war um 19:44:07.987. Zwischen 16:05:45 und dem restart war natürlich noch ganz viel, aber vor'm restart ging auch noch alles. Fehler sind soweit keine im restlichen log.

Apollon77 commented 4 years ago

Kannst Du mal das Log bitte bereitstellen von master und Slave 1 min vor und nach dem Update oder so?

Apollon77 commented 4 years ago

Ich hatte bei mir auch einmal den Fall das die redis lib die subscriptions nicht wiederhergestellt hat ... aber konnte es danach nie wieder nachvollziehen :-( und auch der COde in der Lib sieht vollkommen ok aus

twonky4 commented 4 years ago

Update? Du meinst restart?

Apollon77 commented 4 years ago

ja restart :-)

twonky4 commented 4 years ago

iobroker.2019-12-12-master.log iobroker.2019-12-12-slave.log

Hier sind 2 frische log-Dateien.

Der restart war um 2019-12-12 23:11:22

Apollon77 commented 4 years ago

Da sehe ich aber keine SET STATE?!

Also an sich ist dso alles korrekt. es kommt das connection refused als die DB we war und er versucht hat neu zu verbinden. Das versucht er alle 5s (23:11:22/27 ... und 32 wars wieder da). An sich sollte zu dem Zeitpunkt beim Reconnect auch automatisch alle subscribes die es vorher gab wieder hergestellt werden.

Wie oben geschrieben hatte ich auch schonmal den Fall das es nicht tat, konnte es aber danach nicht mehr nachvollziehen ... Meine Idee für die 2.2 (wo ich eh gerade was am umbauen bin daran) ist einfach alle subscribes noch bei bei uns zu merken und nach reconnect selbst alle nochmal zu senden ... (obwohl es eigentlich unnötig sein sollte)

twonky4 commented 4 years ago

Ich habe nun gerade gesehen welche Ausmaße das Problem eigentlich hat. Ich dachte das tritt nur auf, wenn ich den master neu starte. Aber das tritt auch auf, wenn mein Internet Provider die tägliche Zwangstrennung durchführt 😭 (da übers Internet verbunden)

foxriver76 commented 4 years ago

Sprich Master und Slave sind über Internet verbunden?

twonky4 commented 4 years ago

Genug, hat mit js-controller 1.5 auch noch super funktioniert.

Apollon77 commented 4 years ago

Hast du logs? Wie gesagt ich baue gerade in der 2.2.0 ein das wir uns alle subscribes merken und erneuern nachweinen Reconnect.

Um das Problem in der ioredis lib zu finden müsste Mannes nachvollziehen können und dort logging einbauen ... der Code an sich sieht korrekt aus.

Denke ich habe nach dem Wochenende eine 2.2.0 auf GitHub die du testen könntest ob es mit der besser tut (müsste am Ende auch nur auf dem Slave laufen)

twonky4 commented 4 years ago

Ja, liegt definitiv nicht am hm-rpc Adapter. Das Problem ist Adapter übergreifen. Ich kann es auch bei anderen Adaptern nachstellen. Die State Änderungen kommen bei stateChange nicht mehr an.

Apollon77 commented 4 years ago

Ich hab den Umbau fertig und ist gerade in Review. Dann sollten wir einen Controller 2.2.x auf GitHub haben der das Thema hoffentlich löst.

Wir merken und jetzt alle subscribes und spielen sie selbst nach einem reconnect nochmal nach und verlassen uns nicht auf die redis lib.

Wäre super wenn du dann testen könntest weil ich kann das Problem auf meinen dev Systemen nicht nachstellen - und in live hatte ich es nur auf einem meiner 2 slaves und nur bei Objekten :-(

foxriver76 commented 4 years ago

Fixed? Bzw kann hier zugemacht werden?

Apollon77 commented 4 years ago

@twonky4 if you like the js-Controller 2.2.x Beta GitHub test started. So please check if this solved the issue.

twonky4 commented 4 years ago

Problem solved with js-controller versin 2.2.4