search

iobroker-community-adapters / ioBroker.shelly

Integrate your Shelly devices into ioBroker via MQTT or CoIoT
Other
155 stars 62 forks source link

Bug reportDB closed w #573

Closed freaktech closed 2 years ago

freaktech commented 2 years ago

Shelly device

-

Protocol (CoAP / MQTT)

-

The problem

was bedeutet diese Fehler die aktuell bei mir immer im Protokoll stehen

Version of nodejs

NODE.JS: V12.22.11

Version of ioBroker js-controller

NPM: 6.14.16

Version of Adapter

5.3.2

Operating system running ioBroker

proxmox

Checklist of files to include below

Additional information & file uploads

1

klein0r commented 2 years ago

In welchen Fällen passiert das? Wenn die Instanz gestoppt wird? Siehe auch #549

freaktech commented 2 years ago

mir wär nicht bekannt das da was besonderes läuft oder so erst kam es wieder

2022-03-25 13_31_07-Window

Apollon77 commented 2 years ago

Dann bitte mehr log zeigen -auch andere loglevel ... zeitlich drumrum... DB Closed bedeutet das die DB Verbindung zu deinem js-controller abgebrochen ist ... das darf während dem normalen lauf nicht passieren

freaktech commented 2 years ago

hilft das weiter

mehr seh ich nicht

Bildschirmfoto 2022-03-25 um 22 28 21
Apollon77 commented 2 years ago

Naja da steht es ... es ist ein Restart - du hast einen restart Schedule definiert ... und damit wird sie in dem dort angegebenen Zeitinterval neu gestartet ... warum auch immer :-)

@klein0r Also ja ... da scheint wohl nach dem "unload" nich logik zu laufen

klein0r commented 2 years ago

@Apollon77 Has the adapter a function to check if the db connection is still alive? Otherwise I have to add an own flag which will be set in unload for example.

Apollon77 commented 2 years ago

The "best practice" is to make sure on unload all stuff is cleaned up ... in reality set a flag when unload was called and check on "long running" actions or before re-setting timeouts.

I was trying to fix the some times in the past but seems I did not catched all places :-)

JuniperChris929 commented 2 years ago

Hatte ich eben auch - ohne Änderungen am System... Bin die Logs der letzten 8 Tage durchgegangen - trat heute plötzlich gegen 22.13Uhr auf und wiederholte sich alle 20min bis ich jetzt gerade (00:15) den Adapter manuell neugestartet habe. Aufgefallen war mir das, weil mein script das Licht beim verlassen des Raumes nicht ausgeschaltet hatte...

Apollon77 commented 2 years ago

Then a full log including the minutes before the error would help a lot

JuniperChris929 commented 2 years ago 
2022-04-19 15:18:00.393 - warn: shelly.0 (87643) State "shelly.0.SHSW-PM#xxx#1.online" has no existing object, this might lead to an error in future versions
2022-04-19 15:18:59.308 - warn: shelly.0 (87643) State "shelly.0.SHSW-PM#xxx#1.online" has no existing object, this might lead to an error in future versions
2022-04-19 15:19:33.062 - info: shelly.0 (87643) [MQTT] Device 192.168.11.84 (shellyht / shellyht-xxx / SHHT-1#xxx#1) connected! Polltime set to 300 sec.
2022-04-19 15:19:46.212 - info: shelly.0 (87643) [MQTT] Device 192.168.11.20 (shelly1pm / shelly1pm-xxx / SHSW-PM#xxx#1) connected! Polltime set to 300 sec.
2022-04-19 15:28:14.495 - info: shelly.0 (87643) [MQTT] Close Client: 192.168.11.20 (shelly1pm / shelly1pm-xxx / SHSW-PM#xxx#1) (false)
2022-04-19 15:28:14.550 - error: shelly.0 (87643) uncaught exception: This socket has been ended by the other party
2022-04-19 15:28:14.551 - error: shelly.0 (87643) Error: This socket has been ended by the other party
at Socket.writeAfterFIN [as write] (net.js:468:14)
at connack (/opt/iobroker/node_modules/mqtt-packet/writeToStream.js:291:10)
at generate (/opt/iobroker/node_modules/mqtt-packet/writeToStream.js:32:14)
at Writable.write [as _write] (/opt/iobroker/node_modules/mqtt-connection/lib/writeToStream.js:13:9)
at writeOrBuffer (internal/streams/writable.js:358:12)
at Writable.write (internal/streams/writable.js:303:10)
at Connection.Duplexify._write (/opt/iobroker/node_modules/duplexify/index.js:208:22)
at doWrite (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:428:64)
at writeOrBuffer (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:417:5)
at Connection.Writable.write (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:334:11)
2022-04-19 15:28:14.551 - error: shelly.0 (87643) Exception-Code: EPIPE: This socket has been ended by the other party
2022-04-19 15:28:14.553 - error: shelly.0 (87643) uncaught exception: This socket has been ended by the other party
2022-04-19 15:28:14.553 - error: shelly.0 (87643) Error: This socket has been ended by the other party
at Socket.writeAfterFIN [as write] (net.js:468:14)
at writeVarByteInt (/opt/iobroker/node_modules/mqtt-packet/writeToStream.js:795:17)
at connack (/opt/iobroker/node_modules/mqtt-packet/writeToStream.js:293:3)
at generate (/opt/iobroker/node_modules/mqtt-packet/writeToStream.js:32:14)
at Writable.write [as _write] (/opt/iobroker/node_modules/mqtt-connection/lib/writeToStream.js:13:9)
at writeOrBuffer (internal/streams/writable.js:358:12)
at Writable.write (internal/streams/writable.js:303:10)
at Connection.Duplexify._write (/opt/iobroker/node_modules/duplexify/index.js:208:22)
at doWrite (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:428:64)
at writeOrBuffer (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:417:5)
2022-04-19 15:28:14.554 - error: shelly.0 (87643) Exception-Code: EPIPE: This socket has been ended by the other party
2022-04-19 15:28:14.554 - error: shelly.0 (87643) uncaught exception: This socket has been ended by the other party
2022-04-19 15:28:14.555 - error: shelly.0 (87643) Error: This socket has been ended by the other party
at Socket.writeAfterFIN [as write] (net.js:468:14)
at connack (/opt/iobroker/node_modules/mqtt-packet/writeToStream.js:294:10)
at generate (/opt/iobroker/node_modules/mqtt-packet/writeToStream.js:32:14)
at Writable.write [as _write] (/opt/iobroker/node_modules/mqtt-connection/lib/writeToStream.js:13:9)
at writeOrBuffer (internal/streams/writable.js:358:12)
at Writable.write (internal/streams/writable.js:303:10)
at Connection.Duplexify._write (/opt/iobroker/node_modules/duplexify/index.js:208:22)
at doWrite (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:428:64)
at writeOrBuffer (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:417:5)
at Connection.Writable.write (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:334:11)
2022-04-19 15:28:14.555 - error: shelly.0 (87643) Exception-Code: EPIPE: This socket has been ended by the other party
2022-04-19 15:28:14.555 - error: shelly.0 (87643) uncaught exception: This socket has been ended by the other party
2022-04-19 15:28:14.556 - error: shelly.0 (87643) Error: This socket has been ended by the other party
at Socket.writeAfterFIN [as write] (net.js:468:14)
at connack (/opt/iobroker/node_modules/mqtt-packet/writeToStream.js:296:10)
at generate (/opt/iobroker/node_modules/mqtt-packet/writeToStream.js:32:14)
at Writable.write [as _write] (/opt/iobroker/node_modules/mqtt-connection/lib/writeToStream.js:13:9)
at writeOrBuffer (internal/streams/writable.js:358:12)
at Writable.write (internal/streams/writable.js:303:10)
at Connection.Duplexify._write (/opt/iobroker/node_modules/duplexify/index.js:208:22)
at doWrite (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:428:64)
at writeOrBuffer (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:417:5)
at Connection.Writable.write (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:334:11)
2022-04-19 15:28:14.556 - error: shelly.0 (87643) Exception-Code: EPIPE: This socket has been ended by the other party
2022-04-19 15:28:14.558 - info: shelly.0 (87643) Closing Adapter
2022-04-19 15:28:14.559 - info: shelly.0 (87643) terminating
2022-04-19 15:28:14.559 - warn: shelly.0 (87643) Terminated (UNCAUGHT_EXCEPTION): Without reason
2022-04-19 15:28:14.623 - warn: shelly.0 (87643) State "shelly.0.SHPLG-S#xxx#1.online" has no existing object, this might lead to an error in future versions
2022-04-19 15:28:14.718 - warn: shelly.0 (87643) State "shelly.0.SHSW-PM#xxx#1.online" has no existing object, this might lead to an error in future versions
2022-04-19 15:28:14.807 - warn: shelly.0 (87643) State "shelly.0.SHSW-PM#xxx#1.online" has no existing object, this might lead to an error in future versions
2022-04-19 15:28:14.903 - warn: shelly.0 (87643) State "shelly.0.SHSW-PM#xxx#1.online" has no existing object, this might lead to an error in future versions
2022-04-19 15:28:14.967 - warn: shelly.0 (87643) State "shelly.0.SHSW-PM#xxx#1.online" has no existing object, this might lead to an error in future versions
2022-04-19 15:28:14.999 - warn: shelly.0 (87643) State "shelly.0.SHSW-PM#xxx#1.online" has no existing object, this might lead to an error in future versions
2022-04-19 15:28:15.067 - error: shelly.0 (87643) Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch().
2022-04-19 15:28:15.068 - error: shelly.0 (87643) unhandled promise rejection: DB closed
2022-04-19 15:28:15.068 - error: shelly.0 (87643) Error: DB closed
at close (/opt/iobroker/node_modules/ioredis/built/redis/event_handler.js:184:25)
at Socket. (/opt/iobroker/node_modules/ioredis/built/redis/event_handler.js:151:20)
at Object.onceWrapper (events.js:520:26)
at Socket.emit (events.js:400:28)
at TCP. (net.js:686:12)
2022-04-19 15:28:15.068 - error: shelly.0 (87643) DB closed
2022-04-19 15:28:15.072 - warn: shelly.0 (87643) get state error: Connection is closed.
2022-04-19 15:28:15.128 - error: host.iobroker.hidden.name instance system.adapter.shelly.0 terminated with code 6 (UNCAUGHT_EXCEPTION)
2022-04-19 15:28:15.130 - info: host.iobroker.hidden.name Restart adapter system.adapter.shelly.0 because enabled
2022-04-19 15:28:45.224 - info: host.iobroker.hidden.name instance system.adapter.shelly.0 started with pid 107208
JuniperChris929 commented 2 years ago

Heute wieder insgesamt 4x abgestürzt :( Der recovered zwar eigentlich schnell aber wenn man in dem Moment ein Script laufen hat (Rollos etc.) dann ist das kacke... Scheint auch nur den Shelly-Part zu betreffen, nicht den Broker selbst - alle anderen Adapter (Zigbee, Viessmann etc.) zeigen keine Ausfälle

JuniperChris929 commented 2 years ago

Eben ein erneuter Absturz - diesmal hat's aber intern ebenfalls was "zerfetzt". Meine Scripte für Zigbee waren ebenfalls betroffen oO Erst nachdem der Shelly Adapter neugestartet wurde (manuell) liefen die Scripts auch wieder - "blockiert" der Shelly-Adapter da was? Ist das überhaupt möglich? Braucht Ihr noch weitere Infos von mir?

Apollon77 commented 2 years ago

Ich enke der relevante Part is:

2022-04-19 15:28:14.495 - info: shelly.0 (87643) [MQTT] Close Client: 192.168.11.20 (shelly1pm / shelly1pm-xxx / SHSW-PM#xxx#1) (false) 2022-04-19 15:28:14.550 - error: shelly.0 (87643) uncaught exception: This socket has been ended by the other party

Das sind zwei Themen

1.) Warum beendet der in der Meldung genannte Shelly die Verbindung? 2.) Der Shelly Adapter scheint auf dieses unerwartete mqtt close dann nicht so gut zu reagieren...

@klein0r If I digged correctly you need to add try/catches around all connack or other mqtt commands that do not have a callback, because in fact without callback they return a Promise and then this happens ... a try.catch areound or a ".catch" or a errorr callback should fix this issue

klein0r commented 2 years ago

Das läuft alles in einem separaten Prozess. Außer Du betreibst ioBroker im compact mode? Klingt erstmal so, als wären keine Ressourcen mehr frei. RAM voll oder Festplatte.

JuniperChris929 commented 2 years ago

Ist ne "Standardinstallation" - wie sehe ich denn ob ich den compact mode habe? Vermutlich nicht wenn ich das frage :D Bzgl. RAM, CPU und HDD ist noch "etwas" Luft nach oben ;)

perf01 perf02

klein0r commented 2 years ago

Ist ne "Standardinstallation" - wie sehe ich denn ob ich den compact mode habe?

Wenn Du das fragst, wahrscheinlich nicht. Normalerweise wird jede Instanz in einem eigenen Prozess gestartet. Die Frage ist also, warum deine Instanz 4x hinterander "abstürzt".

Hast Du einen Zeitplan für den Instanz-Neustart konfiguriert? Wenn ja, warum? Anders kann ich mir das Verhalten nicht erklären. Ressourcen gibt es ja wirklich genug.

Apollon77 commented 2 years ago

@klein0r Schau bitte mal was ich oben geschrieben habe ... ich glaube die richtung der Diskussion ist falsch.

Ja sein Shelly beendet die Mqtt verbindung, aber das kann passieren. Was aber im Adapter code passiert ist, dass dadurch ein mqtt befehl der gesendet wird crasht weil wenn ohne callback aufgerufen wie zb https://github.com/iobroker-community-adapters/ioBroker.shelly/blob/master/lib/protocol/mqtt.js#L428 dann gibt das ne unhandled promise weil die antwort rejected wird.

In meinen Augen müssten alle mqtt calls entweder nen callback oder ein await und try/catch oder ein ".catch()" bekommen das hier sichergestellt ist das fehler gefangen werden

klein0r commented 2 years ago

@Apollon77 Ja, habe ich gesehen und steht auf ToDo 👍

JuniperChris929 commented 2 years ago

Hab jetzt mal den "problematischen" Shelly ausgebaut - seit dem (gestern) hatte ich keinen Absturz mehr. Aber super, dass das auf der ToDo steht - sowas kann ja mit jedem Shelly passieren - bei über 100 1PM die ich im Haus verbaut habe wird mich das also noch öfter treffen können :P

SirFlour commented 2 years ago

Hallo zusammen, hab es bei mir auch. Ist auch 1pm shelly, der im Gartenhaus ist. Und somit auch je nach Wetter die Verbindung verliert. Dann kommt eigentlich immer nur die Meldung: [MQTT] Device 192.168.180.62 (shelly1pm / shelly1pm-E8DB84D7E602 / SHSW-PM#E8DB84D7E602#1) connected! Polltime set to 5 sec. und gut ist.

Jetzt ich glaube zum zweiten Mal, kommt dann der Absturtz und Neustart. Hoffe das hilft und gerne teste ich auch :)

shelly.0 | 2022-04-29 14:53:30.592 | error | uncaught exception: This socket has been ended by the other party -- | -- | -- | -- shelly.0 | 2022-04-29 14:53:30.562 | error | Exception-Code: EPIPE: This socket has been ended by the other party shelly.0 | 2022-04-29 14:53:30.561 | error | Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:468:14) at connack (/opt/iobroker/node_modules/mqtt-packet/writeToStream.js:300:10) at generate (/opt/iobroker/node_modules/mqtt-packet/writeToStream.js:32:14) at Writable.write [as _write] (/opt/iobroker/node_modules/mqtt-connection/lib/writeToStream.js:13:9) at writeOrBuffer (internal/streams/writable.js:358:12) at Writable.write (internal/streams/writable.js:303:10) at Connection.Duplexify._write (/opt/iobroker/node_modules/mqtt-connection/node_modules/duplexify/index.js:208:22) at doWrite (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:428:64) at writeOrBuffer (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:417:5) at Connection.Writable.write (/opt/iobroker/node_modules/readable-stream/lib/_stream_writable.js:334:11) shelly.0 | 2022-04-29 14:53:30.560 | error | uncaught exception: This socket has been ended by the other party shelly.0 | 2022-04-29 14:53:30.339 | info | [MQTT] Close Client: 192.168.180.62 (shelly1pm / shelly1pm-E8DB84D7E602 / SHSW-PM#E8DB84D7E602#1) (false) shelly.0 | 2022-04-29 14:53:30.316 | info | [MQTT] Device 192.168.180.62 (shelly1pm / shelly1pm-E8DB84D7E602 / SHSW-PM#E8DB84D7E602#1) connected! Polltime set to 5 sec.
JuniperChris929 commented 2 years ago

Bei mir gab es seit dem keinen Absturz mehr - scheint also tatsächlich daran zu liegen.