search

holomekc / ioBroker.bshb

This adapter allows communication to Bosch Smart Home Controller
MIT License
20 stars 7 forks source link

Restart loop detected #61

Closed Thomas-Doc closed 2 years ago

Thomas-Doc commented 2 years ago

Einige Adapter, so auch bshb (und telegram) starten nicht mehr, wenn das Internet für einige Zeit unterbrochen ist. Das ist bei uns häufiger der Fall (teilweise auch absichtlich in der Nacht, wegen der Kinder). Nach ein paar Versuchen erscheint dann im Log die Fehlermeldung: restart loop detected ...

Der Adapter bleibt dann wg. des Fehlers (wohl nach 3 Restart-Versuchen) inaktiv und muss per Hand neu gestartet werden.

Am liebsten wäre es mir natürlich, der Adapter würde wegen der fehlenden Internet-Konnektivität überhaupt nicht auf Fehler laufen und würde max. eine Meldung ins log ausgeben, aber nicht beendet werden. Denn die App funktioniert ja bei fehlender Internet-Verbindung auch weiterhin, wenn man sich im lokalen Netzwerk befindet. Allerdings gibt es in der App auch erst mal einen Fehler, weil offenbar zuerst versucht wird, von außen den Bosch-Controller zu erreichen. Dann kommt die Meldung: Der Controller ist nicht erreichbar. Erst, wenn man die mobilen Daten aussschaltet und den Controller nochmals über das Wlan sucht (bzw. die IP-Adresse manuell eingibt), dann funktioniert die Kommunikation mit dem Bosch-Controller wieder einwandrei, trotz fehlender Internet-Konnektivität. Vielleicht hilft das?

Siehe zum gleichen Problem auch hier: https://github.com/ioBroker/ioBroker.js-controller/issues/1217#issue-797358894

holomekc commented 2 years ago

Hi. Danke für die Info. Ich habe versucht das bei mir nachzustellen. Ich habe dazu bei der Fritzbox einfach mal das DSL Kabel gezogen. Ich konnte hier jedoch keinerlei Fehlermeldungen vom Adapter sehen. Er funktionierte auch weiterhin. Ich habe ca 10min gewartet bis ich das Kabel dann wieder angeschlossen habe. Der Adapter verwendet auch kein Internet, sondern verbindet sich direkt mit dem Controller.

Meinst du vielleicht WLAN Unterbrechungen? Ansonsten würde es mir helfen wenn du Fehlermeldungen schicken könntest, dann kann ich vielleicht mehr sehen. Vielleicht schickt der Controller andere Nachrichten oder Fehler zurück, mit denen der Adapter noch nicht umgehen kann.

Thomas-Doc commented 2 years ago

DSL-Kabel ziehen entspricht in etwa dem, was meine Frau in der Nacht macht :). Also eine gute Simulation. Gleiches passiert übrigens, wenn du die App nutzt. Auch wenn du im heimischen WLAN eingeloggt bist, so zeigt die App nach kurzer Zeit an: Smart home controller nicht gefunden. Man muss dann erst die mobilen Daten ausschalten, und am besten in der App "IP manuell eingeben" auswählen, dann findet die App den Controller wieder. Versuch mal, das DSL-Kabel zu ziehen, und danach den bshb-Adaper neuzustarten. Dann müsse eigentlich beim Neustart gleich dieser nachfolgende Fehler auftreten (sonst kommt er eben etwas später):

Betroffen sind die Adapter telegram und eben bshb. Sie versuchen, mehrfach neu zu starten, irgendwann gibt es dann den Eintrag mit "restart loop detected". Hier mal ein Log-Auszug, das DSL-Kabel wurde so etwa kurz vor 24h gezogen.

2021-09-18 00:10:27.475 - info: bshb.0 (301) starting. Version 0.1.14 in /opt/iobroker/node_modules/iobroker.bshb, node: v12.22.5, js-controller: 3.3.15 2021-09-18 00:10:27.632 - info: bshb.0 (301) Client certificate found in system.certificates 2021-09-18 00:10:27.633 - info: bshb.0 (301) Check if certificate is file reference or actual content 2021-09-18 00:10:27.638 - info: bshb.0 (301) certificate seems to be actual content. Use value from state. 2021-09-18 00:10:27.642 - info: bshb.0 (301) private key seems to be actual content. Use value from state. 2021-09-18 00:10:27.674 - info: bshb.0 (301) Check if client with identifier: ioBroker.bshb_xxxx is already paired. 2021-09-18 00:10:28.233 - info: bshb.0 (301) Client with identifier: ioBroker.bshb_xxxxx already paired. Using existing certificate 2021-09-18 00:10:28.235 - info: bshb.0 (301) Start detecting scenarios... 2021-09-18 00:10:28.239 - info: bshb.0 (301) Start detecting messages... 2021-09-18 00:10:28.240 - info: bshb.0 (301) Start detecting intrusion detection system... 2021-09-18 00:10:28.241 - info: bshb.0 (301) Start detecting devices... 2021-09-18 00:10:28.254 - info: bshb.0 (301) Start detecting open doors/windows... 2021-09-18 00:10:28.441 - info: host.iobroker instance system.adapter.history.0 started with pid 398 2021-09-18 00:10:28.548 - info: host.iobroker instance system.adapter.telegram.0 started with pid 405 2021-09-18 00:10:28.814 - info: bshb.0 (301) Detecting scenarios finished 2021-09-18 00:10:28.960 - info: bshb.0 (301) Detecting messages finished 2021-09-18 00:10:28.972 - info: bshb.0 (301) Detecting intrusion detection system finished 2021-09-18 00:10:34.610 - error: bshb.0 (301) uncaught exception: timeout during call to BSHC 2021-09-18 00:10:34.612 - error: bshb.0 (301) BshbError: timeout during call to BSHC at BshcClient.AbstractBshcClient.handleError (/opt/iobroker/node_modules/bosch-smart-home-bridge/dist/api/abstract-bshc-client.js:170:32) at ClientRequest. (/opt/iobroker/node_modules/bosch-smart-home-bridge/dist/api/abstract-bshc-client.js:155:23) at ClientRequest.emit (events.js:314:20) at TLSSocket.emitRequestTimeout (_http_client.js:715:9) at Object.onceWrapper (events.js:420:28) at TLSSocket.emit (events.js:326:22) at TLSSocket.Socket._onTimeout (net.js:483:8) at listOnTimeout (internal/timers.js:554:17) at processTimers (internal/timers.js:497:7) 2021-09-18 00:10:34.613 - error: bshb.0 (301) timeout during call to BSHC 2021-09-18 00:10:34.622 - info: bshb.0 (301) cleaned everything up... 2021-09-18 00:10:34.623 - info: bshb.0 (301) terminating 2021-09-18 00:10:34.624 - warn: bshb.0 (301) Terminated (UNCAUGHT_EXCEPTION): Without reason

Thomas-Doc commented 2 years ago

... und so endet es dann: 2021-09-18 00:12:01.763 - error: bshb.0 (1291) timeout during call to BSHC 2021-09-18 00:12:01.773 - info: bshb.0 (1291) cleaned everything up... 2021-09-18 00:12:01.776 - info: bshb.0 (1291) terminating 2021-09-18 00:12:01.781 - warn: bshb.0 (1291) Terminated (UNCAUGHT_EXCEPTION): Without reason 2021-09-18 00:12:02.422 - error: host.iobroker instance system.adapter.bshb.0 terminated with code 6 (UNCAUGHT_EXCEPTION) 2021-09-18 00:12:02.423 - info: host.iobroker Restart adapter system.adapter.bshb.0 because enabled 2021-09-18 00:12:02.423 - warn: host.iobroker Do not restart adapter system.adapter.bshb.0 because restart loop detected

Thomas-Doc commented 2 years ago

Hab den Fehler noch etwas eingrenzen können, ist eigentlich nicht schlimm.

Er tritt nur auf, wenn keine Internet-Verbindung besteht ("DSL-Kabel ist gezogen") und zufällig der Adapter aus anderen Gründen gestartet bzw. neugestartet wird. Bei mir tritt das manchmal auf, weil ich den Rechner 2 mal die Woche nachts neu starten lasse (damit er stabil läuft). Das ist dann eben ein blödes Zusammentreffen unglücklicher Umstände ...

Also zum Reproduzieren: DSL-Stecker ziehen und dann einen Neustart des bshb-Adapters versuchen. Der Fehler tritt zu 100 Prozent auf. Obwohl der bshc ja eigentlich im lokalen Netz weiterhin für den Adapter erreichbar sein sollte, auch beim Neustart ...

holomekc commented 2 years ago

Hi. Danke für die Infos. Reproduzieren kann ich es jetzt. Ich sehe auch was das Problem ist. Weiß jedoch noch nicht was ich dagegen tue :)

Aktuell ist es so, dass der Adapter 5 verschiedene Handler hat:

Der BshbDeviceHandler fliegt in dem von dir genannten Szenario auf die Nase. Folgendes tut dieser Handler:

Diese Infos werden verwendet, um die Objekte aufzubauen/aktualisieren und der Adapter cached einige Informationen, damit Updates/Nachrichten schneller gesendet werden können. Alle 3 sind ein extra Endpunkt an der Controller API.

Beim Aufruf von den Services kommt jedoch immer ein Timeout vom Controller. Mir ist hier nicht klar warum das passiert. Ich kann daran jedoch auch nicht wirklich was ändern. Ich vermute das deswegen die App auch erst einmal auf die Nase fällt. Warum diese dann bei IP manuell eingeben wieder funktioniert verstehe ich noch nicht ganz.

Was ich machen könnte ist, dass ich schaue, ob ich den BshbDeviceHandler so umbaue, dass er auch damit klar kommt, wenn er die genannten Informationen nicht auslesen kann. Dazu muss ich aber die Infos aus dem Cache anders wiederherstellen, damit es weiterhin funktioniert. Dabei kann ich Infos an die ioBroker Objekte schreiben (damit muss der Adapter zumindest einmal erfolgreich gestartet worden sein) und im Zweifel diese dann auslesen. Neue Geräte können dann aber auch nicht bei fehlender Internetverbindung im Adapter gefunden werden.

Das ist ein kleines bisschen aufwändiger. Ich schaue mal wann ich dazu komme.

holomekc commented 2 years ago

Hmm wenn ich keinen Denkfehler habe sollte es jetzt gehen. Zumindest sieht es bei mir sehr gut aus. Der Adapter probiert erst den Cache so wiederherzustellen ohne den Controller zu fragen. Er überschreibt dann den Cache mit den Werten vom Controller. Falls bei der Kommunikation mit dem Controller an der Stelle etwas schief geht, dann ignoriert er das und zeigt nur eine Warnung an.

Ich wäre dir dankbar, wenn du das Update testen könntest. Vielleicht übersehe ich ja was. Installation aktuell nur über GitHub.

Scotty-89 commented 2 years ago

ich hab es mal installiert mal schauen was passiert ;)

holomekc commented 2 years ago

Hi. Habe noch einen kleinen Fehler gefunden. Bitte updaten.

Thomas-Doc commented 2 years ago

Vielen Dank! Hab es gerade installiert und einen Neustart getestet. Allerdings noch mit intakter Internet-Verbindung. Da kommen dann erwartungsgemäß die Einträge mit dem Cache...

Da ich z.Zt. nicht vor Ort bin, muss ich die Simulation zeitgesteuert machen (d.h. DSL-Unterbrechung und dann ein paar Minuten später automatischer Neustart des Adapters). Werde dann morgen berichten, welche Meldungen es im Log gibt.

Thomas-Doc commented 2 years ago

Ich denke, es sieht alles gut aus.

2021-09-26 22:40:00.029 - info: bshb.0 (28297) Scheduled restart. 2021-09-26 22:40:00.034 - info: bshb.0 (28297) cleaned everything up... 2021-09-26 22:40:00.078 - info: bshb.0 (28297) terminating 2021-09-26 22:40:00.080 - info: bshb.0 (28297) Terminated (START_IMMEDIATELY_AFTER_STOP): Without reason 2021-09-26 22:40:00.672 - info: host.iobroker instance system.adapter.bshb.0 scheduled normal terminated and will be restarted on schedule. 2021-09-26 22:40:00.676 - info: host.iobroker Restart adapter system.adapter.bshb.0 because enabled 2021-09-26 22:40:01.710 - info: host.iobroker instance system.adapter.bshb.0 started with pid 31014 2021-09-26 22:40:03.787 - info: bshb.0 (31014) starting. Version 0.1.15 in /opt/iobroker/nodemodules/iobroker.bshb, node: v12.22.6, js-controller: 3.3.18 2021-09-26 22:40:03.930 - info: bshb.0 (31014) Client certificate found in system.certificates 2021-09-26 22:40:03.930 - info: bshb.0 (31014) Check if certificate is file reference or actual content 2021-09-26 22:40:03.931 - info: bshb.0 (31014) certificate seems to be actual content. Use value from state. 2021-09-26 22:40:03.932 - info: bshb.0 (31014) private key seems to be actual content. Use value from state. 2021-09-26 22:40:03.940 - info: bshb.0 (31014) Check if client with identifier: ioBroker.bshb is already paired. 2021-09-26 22:40:04.395 - info: bshb.0 (31014) Client with identifier: ioBroker.bshb_ already paired. Using existing certificate 2021-09-26 22:40:04.402 - info: bshb.0 (31014) Start detecting scenarios... 2021-09-26 22:40:04.404 - info: bshb.0 (31014) Start detecting messages... 2021-09-26 22:40:04.405 - info: bshb.0 (31014) Start detecting intrusion detection system... 2021-09-26 22:40:04.408 - info: bshb.0 (31014) Start detecting devices... 2021-09-26 22:40:04.414 - info: bshb.0 (31014) Start detecting open doors/windows... 2021-09-26 22:40:04.592 - info: bshb.0 (31014) Detecting scenarios finished 2021-09-26 22:40:04.674 - info: bshb.0 (31014) Detecting messages finished 2021-09-26 22:40:04.718 - info: bshb.0 (31014) Detecting intrusion detection system finished 2021-09-26 22:40:04.719 - info: bshb.0 (31014) Restoring cache started... 2021-09-26 22:40:04.728 - info: bshb.0 (31014) Restoring cache: rooms 2021-09-26 22:40:04.739 - info: bshb.0 (31014) Restoring cache: devices, device service and states 2021-09-26 22:40:06.700 - info: bshb.0 (31014) Restoring cache finished 2021-09-26 22:40:12.114 - warn: bshb.0 (31014) Failure during detection in BshbDeviceHandler. Continue with cached data. This only works if the adapter has been started successfully at least once. New devices may not be recognized. BshbError: timeout during call to BSHC 2021-09-26 22:40:12.234 - info: bshb.0 (31014) Detecting open doors/windows finished 2021-09-26 22:40:12.235 - info: bshb.0 (31014) Subscribe to ioBroker states 2021-09-26 22:40:12.237 - info: bshb.0 (31014) Listen to changes

holomekc commented 2 years ago

Klingt soweit gut. Genau so sollte es sich verhalten.