Ankündigung

**Sisamiwe** · 25.04.2022, 18:49

Zitat von blobo Beitrag anzeigen

kommt auch nicht in Mosquitto an. Zigbee2MQTT-Plugin disabled, alles geht wieder.

Hallo,
in meiner Umgebung läuft alles (shNG mit Pluign, Zigbee2MQTT etc) auf einem (dem selben) RPi. Daher kann es sein, dass andere Setups zu Fehlern führen. Aber die finden wir raus und beheben sie.

Auch ich hatte bei der Entwicklung Probleme mit dem Debugging, da (zumindest habe ich es nicht anders hinbekommen) sowohl das Tasmota Plugin als auch das Zigbee2Mqtt Plugin bei Fehlern keine LogMessages mehr ausgeben. Das tritt vermutlich ich immer dann auf, wenn das MQTT Modul "dazwischen" ist. Vielleicht kann Msinn dazu was sagen?
Das Plugin "stützt" ab und blockiert dann teilweise. Du könntest das prüfen, ob im WebIF des Plugins der Status noch auch "Aktive" steht.

Wie kommst Du dem Fehler näher:

Idealerweise hast Du eine Testumgebung (also nicht im produktiven Einsatz).
Du beendest in der Konsole shNG

sudo systemctl stop smarthome.service

und deaktiviert den Dienst

sudo systemctl disable smarthome.service

vorübergehend.
Du startest shNG "manuell" im Debug Modus mit

cd /usr/local/smarthome

python3 bin/smarthome.py -d

und bekommst die Fehlermeldung direkt auf dem Bildschirm. Dort sollte auch die Fehlermeldung sein, die das Problem verursacht. (zumindest war es bei mir so)
Für das manuelle Neustarten nutzt du

python3 bin/smarthome.py -r

und für das Beenden

python3 bin/smarthome.py -s

.
Wenn du mit der Session fertig bist, aktivierst Du den shNG Dienst wieder mit

sudo systemctl enable smarthome.service

und startest ihn mit

sudo systemctl start smarthome.service
Eine andere Möglichkeit ist, den Lauf des PluginCodes anhand der Log nachzuvollziehen. Der Fehler lag bei mir dann meinst in dem Stück Code der als nächstes nach dem letzten erfolgreichen Debug-Log einer eingegangenen MQTT Message abgearbeitet worden wäre.

Probier mal und melde dich wieder.
Wie gut kennst Du dich mit shNG, Python, etc aus?
Bist Du auch bei Gitter?

Beste Grüße

**blobo** · 25.04.2022, 19:19

Hi Sisamiwe,

darauf, dass Smarthome direkt auf der Konsole mehr ausgibt als im Log, bin ich nicht gleich gekommen :-(

Vielen Dank für deine äußerst ausführliche Anleitung.
Ich selber bin schon ein paar Jährchen in der SW-Entwicklung aktiv, aber eher in Richtung C/Assembler und Treiber/Firmware. Python habe ich bisher nie wirklich gelernt, aber mir genug abgeschaut, um z.B. selber ein Plugin zu schreiben.

Nun denn, auf der Konsole sieht man mehr:

File "/usr/local/smarthome/plugins/zigbee2mqtt/__init__.py", line 383, in on_mqtt_announce
self.zigbee2mqtt_plugin_devices[topic_level2]['online'] = bool(payload)
KeyError: 'bridge'

Im Übrigen zeigen sowohl das MQTT als auch zigbee2mqtt-Plugin im Fehlerfall einen aktiven Status in den Web-Interfaces - aber in der Broker-Information finden sich außer der Broker Version nichts mehr, d.h. Active Clients / Subscriptions etc. sind blank. Klingt logisch, wenn das Plugin hängt.

Ich schau mir mal den Code etwas näher an. Ich hatte nur den "brain fart", nicht auf der Konsole nachzusehen, sondern nur per Webfrontend in die Logs zu schauen.
Ich werde berichten ;-)

Gruß aus der benachbarten Oberpfalz,
Thomas

**Sisamiwe** · 25.04.2022, 19:29

Zitat von blobo Beitrag anzeigen

dass Smarthome direkt auf der Konsole mehr ausgibt als im Log, bin ich nicht gleich gekommen :-(

Das kann shNG schon immer, ist aber deprecated und soll/ist im logging implementiert. Mir ist erging es bei der Entwicklung ebenso, so dass ich das mit der Konsole mal probiert habe. Zufallstreffer. Wo am Ende die Log "versacken", konnte ich bislang nicht rausfinden.

Zitat von blobo Beitrag anzeigen

Nun denn, auf der Konsole sieht man mehr:

Scheinbar findet er "bridge" im dict nicht. Setz das doch mal in try/except.

Zitat von blobo Beitrag anzeigen

sondern nur per Webfrontend in die Logs zu schauen.

Ich habe die log Dateien bei Entwicklung oder Debugging immer im Notepad++ offen. Die werden dort aktualisiert. Geht besser, finde ich.

Dann viel Erfolg bei der Suche. Wir können das dann gemeinsam testen und ich stelle einen PR, damit das dann auch Einzug hält.

**Sisamiwe** · 25.04.2022, 19:32

blobo

Zitat von Sisamiwe Beitrag anzeigen

Eine andere Möglichkeit ist, den Lauf des PluginCodes anhand der Log nachzuvollziehen. Der Fehler lag bei mir dann meinst in dem Stück Code der als nächstes nach dem letzten erfolgreichen Debug-Log einer eingegangenen MQTT Message abgearbeitet worden wäre.

Das siehst Du in deinem Log vom ersten Post.

Zitat von blobo Beitrag anzeigen

2022-04-25 10:52:21 DEBUG plugins.zigbee2mqtt on_mqtt_announce: topic_level1=zigbee2mqtt, topic_level2=bridge, topic_level3=state, topic_level4=, topic_level5=, payload=False

Die MQTT Message kommt noch an und dann ist "Feierabend". Also muss der Fehler in der Verarbeitung der Message liegen. (Tut er ja auch, hat ja die Konsolenausgabe gezeigt). So kann man den Fehler auch ohne Konsolenausgabe eingrenzen.

**blobo** · 25.04.2022, 19:36

Zitat von Sisamiwe Beitrag anzeigen

blobo
Die MQTT Message kommt noch an und dann ist "Feierabend". Also muss der Fehler in der Verarbeitung der Message liegen. (Tut er ja auch, hat ja die Konsolenausgabe gezeigt). So kann man den Fehler auch ohne Konsolenausgabe eingrenzen.

Der KeyError denke ich hilft weiter.
In der zugehörigen MQTT-Message findet sich auch kein bridge im dict:

zigbee2mqtt/bridge/state {"state":"online"}

Ich packe das mal in try/except wie vorgeschlagen.

Gruß,
Thomas

**Sisamiwe** · 25.04.2022, 19:45

Zitat von blobo Beitrag anzeigen

Ich packe das mal in try/except wie vorgeschlagen.

Das ist was anderes faul.

Das ist der OriginalCode:

Code:

        # handle different received mqtt messages
        if topic_level2 == 'bridge':
            if topic_level3 == 'state':
                # Payloads are 'online' and 'offline'; equal to LWT
                self.logger.debug(f"LWT: detail: {topic_level3} datetime: {datetime.now()} payload: {payload}")
                self.zigbee2mqtt_plugin_devices[topic_level2]['online'] = bool(payload)

wenn der topic_level2 = 'bridge' ist -> das ist er
wenn der topic_level3 = 'state' ist -> das ist er
wird im Plugin-internen dict der Onlinestatus gesetzt. Scheinbar ist bei Dir aber das dict nicht entsprechend vorbereitet.

Setze mal:

Code:

if not topic_level2 in self.zigbee2mqtt_plugin_devices:
    self.zigbee2mqtt_plugin_devices[topic_level2] = {}

vor die Zeile

Code:

self.zigbee2mqtt_plugin_devices[topic_level2]['online'] = bool(payload)

**Sisamiwe** · 25.04.2022, 19:47

Zitat von blobo Beitrag anzeigen

In der zugehörigen MQTT-Message findet sich auch kein bridge im dict:

Das muss auch nicht im dict sein. Es gibt ein Plugin-internes Dict (also Datenspeicher). Hier werden die Inhalte der Messages abgelegt. Die Keys setzten sich aus der MQTT Topic zusammen. Das ist auch die 'bridge' als Level2.

**blobo** · 25.04.2022, 20:07

OK, root cause gefunden.

Die Einträge für zigbee2mqtt_plugin_devices werden in parse_item() anhand der Items mit zigbee2mqtt_topic angelegt.
Da gab es bei mir keinen, da mich die Bridge bisher nicht interessiert hatte.

Der Code in on_mqtt_announce(), Zeile 385, geht aber davon aus, dass es diesen Index gibt. Dein Workaround, das an der Stelle zu initialisieren funktioniert genauso als ein entsprechendes Item anzulegen.

In der Folge stürzt das Plugin jetzt noch mit einem TypeError ab, sobald ein Payload-Update mit "last_seen" hereinkommt - das habe ich in zigbee2mqtt aktiviert.

File "/usr/local/smarthome/plugins/zigbee2mqtt/__init__.py", line 490, in on_mqtt_announce
payload.update({'last_seen': datetime.fromtimestamp(payload['last_seen'] / 1000)})
TypeError: unsupported operand type(s) for /: 'str' and 'int'

Das ist aber eine andere Baustelle, das ursprüngliche Problem ist identifiziert. Danke!

Gruß,
Thomas

**Msinn** · 25.04.2022, 23:37

Zitat von blobo Beitrag anzeigen

darauf, dass Smarthome direkt auf der Konsole mehr ausgibt als im Log, bin ich nicht gleich gekommen :-(

Das gilt eigentlich nur für die Initialisierung. Fehler die auftreten bevor das logging initialisiert ist, können halt nur auf der Console ausgegeben werden.

**blobo** · 26.04.2022, 07:54

Zitat von blobo Beitrag anzeigen

In der Folge stürzt das Plugin jetzt noch mit einem TypeError ab, sobald ein Payload-Update mit "last_seen" hereinkommt - das habe ich in zigbee2mqtt aktiviert.

Das Problem hier liegt daran, dass in Zigbee2MQTT verschiedene Zeitformate einstellbar sind, ISO 8601 als auch Epoch. Das Plugin geht aber fix von Epoch aus und versucht zu konvertieren.
Auf Epoch umgestellt ist auch dieses Problem weg.

Dafür stürzt jetzt irgendwann später das Frontend des Plugins ab, so sieht es zumindest vom Log her aus. Ich hatte gestern keine Zeit mehr, mir das näher anzusehen.

Gruß,
Thomas

**blobo** · 26.04.2022, 11:40

Hallo nochmal Sisamiwe ,

zwei Probleme habe ich dann noch gefunden, bevor das Plugin jetzt soweit läuft.

1) Standardmäßig ist in Zigbee2Mqtt das Feld "Include device information" in der MQTT-Konfiguration disabled.
Das Plugin legt nur bei Erhalt des Device-Datensatzes "device" in der Payload 'meta' an (ab Zeile 473):

Code:

## Korrekturen in der Payload

# Umbenennen des Key 'friendlyName' in 'friendly_name', damit er identisch zu denen aus den Log und Config Topics ist
if 'device' in payload:
    meta = payload['device']
    if 'friendlyName' in meta:
        meta['friendly_name'] = meta.pop('friendlyName')
    del payload['device']

    if not self.zigbee2mqtt_devices[topic_level2].get('meta'):
        self.zigbee2mqtt_devices[topic_level2]['meta'] = {}
    self.zigbee2mqtt_devices[topic_level2]['meta'].update(meta)

Wenn diese Option also nicht explizit in Zigbee2MQTT aktiviert wird, stürzt das Web-Interface beim Erhalt der Payload ab, da 'meta' nicht im dict gefunden wird.

2) Dasselbe gilt mehr oder weniger für "lastSeen", das vom Web-Interface als Bestandteil von 'meta' erwartet wird - aber optional ist.
Bei meinen Devices zum Beispiel erhält der 'device'-Teil in der Payload kein "lastSeen", sondern "last_seen" gibt es je nach Einstellung in der regulären Payload, also eine Ebene höher.
D.h. auch hier stürzt das Web-Interface ab, weil 'lastSeen' nicht vorhanden ist.

Ich habe also als zwei schnelle Workarounds zum einen die Device-Details in Zigbee2MQTT aktiviert, als auch die Zeile mit "lastSeen" im Webinterface entfernt.
Damit scheint das Plugin jetzt grundlegend erst einmal zu laufen.

Für einen richtigen Fix müssen die dicts wohl vom Plugin entsprechend vorinitialisiert werden.

Gruß,
Thomas

**Sisamiwe** · 26.04.2022, 19:29

Zitat von Msinn Beitrag anzeigen

Das gilt eigentlich nur für die Initialisierung. Fehler die auftreten bevor das logging initialisiert ist, können halt nur auf der Console ausgegeben werden.

Für das Tasmota Plugin und das Zigbee2Mqtt Plugin kann ich das nicht bestätigen. Hier kommt bei bestimmten Fehlern keine Meldung im Log, auch nicht nach abgeschlossener Initialisierung. Das Plugin scheint "abgestützt" und verarbeitet eingehende Daten nicht mehr. Da das immer Plugins sind, die auf das MQTT Modul aufsetzen/verwenden, könnte es auch damit irgendwie zusammenhängen.
Deinem Statement entnehme ich aber, dass das so nicht sein soll. Ich hatte auch schon mal den LogLevel des MQTT Modules auf Debug gesetzt, aber da kam auch nicht mehr im Log an.

Zitat von blobo Beitrag anzeigen

Für einen richtigen Fix müssen die dicts wohl vom Plugin entsprechend vorinitialisiert werden.

Das schaue ich mir an. Bzgl. der notwendigen Einstellungen den Zigbee2Mqtt. Kann man die Config von Z2M per mqtt message ändern? Beim Tasmota Plugin konfiguriere ich per mqtt message das Tasmota-Gerät bzw. den Aufbau der mqtt messages.
Ich mache die Tage mal ein Update und gebe Bescheid.

**Msinn** · 27.04.2022, 08:58

Zitat von Sisamiwe Beitrag anzeigen

Für das Tasmota Plugin und das Zigbee2Mqtt Plugin kann ich das nicht bestätigen

Benutzt Du vielleicht ein Python package, welches dann evtl. solche Ausgaben direkt per print() macht? Oder machst Du evtl. selber print() Ausgaben?

**Sisamiwe** · 30.04.2022, 19:50

blobo

Hallo,

ich habe die Fehler korrigiert und einen PR gestellt.

Beste Grüße

Ankündigung

Zigbee2MQTT Plugin legt MQTT lahm

Zigbee2MQTT Plugin legt MQTT lahm

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar

Kommentar