Neues MQTT Plugin

[gklein]

die Nachricht kommt von einer Gosund-Steckdose, geflasht mit Tasmota - Warum auch immer

Ich habe mal versucht den Code im Plugin zu verstehen und hätte sonst testweise mal ein zusätzliches "try / catch" drumrum gebaut, scheitere aber daran die richtige Stelle zu finden. Vermutung wäre in df_on_mqtt_messager ab Zeile 524 in _init_.py

def _on_mqtt_message(self, client, userdata, message):
        """
        Callback function to handle received messages for items and logics

Viele Grüße
Gunnar

[bmx]

Naja das hier

"Sleep":50\xfe\x01\x00\x13tele/gosund7/SENSOR{"Time":"2023-07-15T11:21:19","ENERGY":

sieht für mich nicht wirklich wohlgeformt aus. Die Frage wäre wo das herkommt. Im Client könnte man vermutlich an der Stelle einfach alles verwerfen was empfangen wurde und dann weitermachen...

[gklein]

Hallo zusammen,

mein Fehler ist wieder aufgetaucht. Hier mal das Log dazu:

23-07-15 12:21:20 CEST DEBUG    __init__          modules.mqtt.paho_client _get_caller_type: inspect.stack()[2][1] = '/usr/local/smarthome/lib/model/mqttplugin.py', split = ['', 'usr', 'local', 'smarthome', 'lib', 'model', 'mqttplugin.py']  --  (__init__.py:_get_caller_type:743)
2023-07-15 12:21:20 CEST INFO     __init__          modules.mqtt.paho_client 'publish_topic()' - called from Plugin by 'publish_topic()'  --  (__init__.py:publish_topic:773)
2023-07-15 12:21:20 CEST INFO     __init__          modules.mqtt.paho_client Plugin 'tasmota' is publishing topic 'cmnd/gosund7/teleperiod' with payload '15' (qos=1, retain=False)  --  (__init__.py:publish_topic:781)
2023-07-15 12:21:20 CEST DEBUG    __init__          modules.mqtt.paho_client cast_to_mqtt: data = '15', type(data) = '<class 'int'>', bool_values ='None'  --  (__init__.py:cast_to_mqtt:870)
2023-07-15 12:21:20 CEST DEBUG    __init__          modules.mqtt.paho_client _on_log: Sending PUBLISH (d0, q1, r0, m20032), 'b'cmnd/gosund7/teleperiod'', ... (2 bytes)  --  (__init__.py:_on_mqtt_log:597)
2023-07-15 12:21:20 CEST INFO     __init__          modules.mqtt.paho_client Plugin 'tasmota' has published topic 'cmnd/gosund7/teleperiod' with payload '15'  --  (__init__.py:publish_topic:785)
2023-07-15 12:21:20 CEST DEBUG    __init__          modules.mqtt.paho_client _on_log: Received PUBACK (Mid: 20032)  --  (__init__.py:_on_mqtt_log:597)
2023-07-15 12:21:20 CEST DEBUG    __init__          modules.mqtt.paho_client _on_log: Received PUBLISH (d0, q0, r0, m0), 'tele/gosund7/STATE', ...  (318 bytes)  --  (__init__.py:_on_mqtt_log:597)
2023-07-15 12:21:20 CEST DEBUG    __init__          modules.mqtt.paho_client _on_mqtt_message: RECEIVED topic 'tele/gosund7/STATE', payload 'b'{"Time":"2023-07-15T11:21:19","Uptime":"55T02:10:11","UptimeSec":4759811,"Vcc":3.405,"Heap":28,"SleepMode":"Dynamic","Sleep":50\xfe\x01\x00\x13tele/gosund7/SENSOR{"Time":"2023-07-15T11:21:19","ENERGY":{"TotalStartTime":"2022-02-25T21:34:59","Total":219.881,"Yesterday":0.581,"Today":0.038,"Period": 0,"Power":94,"ApparentPower":94', QoS '0', retain '0'  --  (__init__.py:_on_mqtt_message:533)
2023-07-15 12:21:20 CEST DEBUG    __init__          modules.mqtt.paho_client _on_mqtt_message: subscription 'tasmota-5': {'subscriber_type': 'plugin', 'callback': <bound method Tasmota.on_mqtt_message of <plugins.tasmota.Tasmota object at 0x7fa8f423d880>>, 'payload_type': 'dict', 'bool_values': None}  --  (__init__.py:_on_mqtt_message:560)
2023-07-15 12:21:20 CEST ERROR    __init__          modules.mqtt.paho_client _on_log: Caught exception in on_message: 'utf-8' codec can't decode byte 0xfe in position 127: invalid start byte  --  (__init__.py:_on_mqtt_log:595)
​

Danach kommt kein einziger Log-Eintrag vom paho_client mehr. Sieht für mich also mausetot aus.

Viele Grüße
Gunnar

[gklein]

Danke für die Erläuterung, ich stelle mal das Logging entsprechend ein und schaue was beim nächsten Disconnect so auftaucht

Schönen Abend
Gunnar

[Msinn]

Das paho-mqtt Package überwacht das bestehen der Verbindung.

Das mqtt Modul tut bei einem disconnect folgendes:

Wenn das paho-mqtt Package einen disconnect feststellt, ruft es ein Callback Routine im mqtt Modul auf.
Diese erzeugt einen Logeintrag, abhängig vom Resultcode (rc) den das paho-mqtt Package zurückmeldet.

Bei rc = 0 wird ein INFO Eintrag geloggt: Disconnection was successful (rc=0)'"
bei rc = 7 wird ein WARNING Eintrag geloggt: Disconnected from broker with returncode '7'
Bei einem anderen rc wird ein NOTICE Eintrag geloggt: Disconnection returned result '{rc}'

Wenn ein rc = 7 zurück gemeldet wird, wird anschließend ein Reconnect veranlasst.

[gklein]

Hi,

ich habe scheinbar ein Problem mit dem Push von Mqtt-Meldungen. Es sieht für mich aktuell so aus, als wenn SmarthomeNG als Cleint irgendwann die Verbindung zum Mosquitto verliert und dann nicht wieder herstellt.

mosquitto.log:1688925105: Client cubie2.MQTT-module has exceeded timeout, disconnecting.
mosquitto.log:1688984478: New client connected from 192.168.2.131:59533 as cubie2.MQTT-module (p2, c1, k60).

Die Plugins (bei mir smlx) scheinen das nicht mitzubekommen und schicken munter Daten, die aber im Mosquitto nicht mehr ankommen.

2023-07-10 12:04:36 CEST INFO     mqttplugin        plugins.smlx.Smlx publish_topic: Item 'Haus.Zentral.Strom_Haushalt.Bezug.Phasen.L1' -> topic 'sgm-c8/phases/L1', payload '1.7', QoS 'None', retain 'True'  --  (mqttplugin.py:publish_topic:164)
2023-07-10 12:04:36 CEST INFO     __init__          plugins.smlx.Smlx Update item: Haus.Zentral.Strom_Haushalt.Bezug.Phasen.L2, item has been changed outside this plugin  --  (__init__.py:update_item:206)
2023-07-10 12:04:36 CEST INFO     mqttplugin        plugins.smlx.Smlx publish_topic: Item 'Haus.Zentral.Strom_Haushalt.Bezug.Phasen.L2' -> topic 'sgm-c8/phases/L2', payload '3.2', QoS 'None', retain 'True'  --  (mqttplugin.py:publish_topic:164)
2023-07-10 12:04:36 CEST INFO     __init__          plugins.smlx.Smlx Update item: Haus.Zentral.Strom_Haushalt.Bezug.Phasen.L3, item has been changed outside this plugin  --  (__init__.py:update_item:206)
2023-07-10 12:04:36 CEST INFO     mqttplugin        plugins.smlx.Smlx publish_topic: Item 'Haus.Zentral.Strom_Haushalt.Bezug.Phasen.L3' -> topic 'sgm-c8/phases/L3', payload '3.1', QoS 'None', retain 'True'  --  (mqttplugin.py:publish_topic:164)

Der Reconnect ist erst nach dem Restart (10.7. 12:20 Uhr) von SmarthomeNG erfolgt. Ein Parameter dafür konnte ich jetzt nicht finden.
Ich habe das Debug-Log jetzt mal hochgedreht, vlt. gibt es da noch eine brauchbare Meldung.
Frage an die Experten - Gibt es da ein Polling oder ähnliches, um zu sehen ob der Connect zum Broker noch steht?

Danke
Gunnar

[ThommyKNX]

Ich konnte den Fehler finden. Ich benutze auch das shelly-plugin, welches shellles/# via mqtt abonniert. Jedoch habe ich unter anderem ein neues Shelly-Device bekommen, welches nicht mit dem plugin kompatibel ist, jedoch auch nicht konfiguriert ist. Es existiert nur zusätzlich im Netz, und published dort messages. Nachdem ich das neue shelly vom broker genommen habe, kam auch

2023-06-01 22:43:54 ERROR modules.mqtt _on_log: Caught exception in on_message: 'ip'

nicht mehr und es funktioniert alles wie gewohnt.
Offenbar pulished das Teil messages, welches vom shelly-plugin nicht interpretiert werden können.

[ThommyKNX]

Habe grade gefunden, dass das Problem hier https://knx-user-forum.de/forum/supp...39#post1763639 schon mal beschrieben wurde.

Den entsprechenden Fix habe ich durch shng version 1.9.5 ja bereits drinnen. paho-mqtt ist Version ist jedoch 1.6.1.

[ThommyKNX]

Hallo,

sorry, dass ich mich erst jetzt melde, aber ich hatte isher noch keine Zeit gehabt, dies näher zu Untersuchen.
Ich habe mosquitto 2.0.11 im Einsatz.

Das mosquitto log gibt leider nicht sehr viel Aufschluss.

Anfangs sieht es noch gut aus:

1686601396: New connection from 192.168.7.239:37635 on port 1883.
1686601396: New client connected from 192.168.7.239:37635 as smarthome.shng-mqtt (p2, c1, k60, u'smarthomeng').
1686601396: No will message specified.
1686601396: Sending CONNACK to smarthome.shng-mqtt (0, 0)
1686601396: Received SUBSCRIBE from smarthome.shng-mqtt
1686601396:     $SYS/broker/version (QoS 0)
1686601396: smarthome.shng-mqtt 0 $SYS/broker/version
1686601396: Sending SUBACK to smarthome.shng-mqtt
1686601396: Sending PUBLISH to smarthome.shng-mqtt (d0, q0, r1, m0, '$SYS/broker/version', ... (24 bytes))
1686601396: Received SUBSCRIBE from smarthome.shng-mqtt
1686601396:     $SYS/broker/clients/active (QoS 0)
1686601396: smarthome.shng-mqtt 0 $SYS/broker/clients/active
1686601396: Sending SUBACK to smarthome.shng-mqtt
1686601396: Received SUBSCRIBE from smarthome.shng-mqtt
1686601396:     $SYS/broker/subscriptions/count (QoS 0)
1686601396: smarthome.shng-mqtt 0 $SYS/broker/subscriptions/count
1686601396: Sending SUBACK to smarthome.shng-mqtt
1686601396: Received SUBSCRIBE from smarthome.shng-mqtt
1686601396:     $SYS/broker/messages/stored (QoS 0)
1686601396: smarthome.shng-mqtt 0 $SYS/broker/messages/stored
1686601396: Sending SUBACK to smarthome.shng-mqtt
1686601396: Received SUBSCRIBE from smarthome.shng-mqtt
1686601396:     $SYS/broker/uptime (QoS 0)
1686601396: smarthome.shng-mqtt 0 $SYS/broker/uptime
1686601396: Sending SUBACK to smarthome.shng-mqtt
1686601396: Sending PUBLISH to smarthome.shng-mqtt (d0, q0, r1, m0, '$SYS/broker/uptime', ... (11 bytes))
1686601396: Received SUBSCRIBE from smarthome.shng-mqtt
1686601396:     $SYS/broker/retained messages/count (QoS 0)
1686601396: smarthome.shng-mqtt 0 $SYS/broker/retained messages/count
.
.
.
1686601423: Received PUBLISH from evcc-1213392744 (d0, q1, r1, m44171, 'evcc/updated', ... (10 bytes))
1686601423: Sending PUBLISH to smarthome.shng-mqtt (d0, q1, r0, m29, 'evcc/updated', ... (10 bytes))
1686601423: Sending PUBACK to evcc-1213392744 (m44171, rc0)
1686601423: Received PUBLISH from evcc-1213392744 (d0, q1, r1, m44172, 'evcc/loadpoints/1/chargePower', ... (1 bytes))
1686601423: Sending PUBLISH to smarthome.shng-mqtt (d0, q1, r0, m30, 'evcc/loadpoints/1/chargePower', ... (1 bytes))
1686601423: Sending PUBACK to evcc-1213392744 (m44172, rc0)
1686601423: Received PUBLISH from evcc-1213392744 (d0, q1, r1, m44173, 'evcc/site/pvPower', ... (3 bytes))
1686601423: Sending PUBACK to evcc-1213392744 (m44173, rc0)
1686601423: Received PUBLISH from evcc-1213392744 (d0, q1, r1, m44174, 'evcc/site/pv/1/power', ... (3 bytes))
1686601423: Sending PUBACK to evcc-1213392744 (m44174, rc0)
1686601423: Received PUBLISH from evcc-1213392744 (d0, q1, r1, m44175, 'evcc/site/pv', ... (1 bytes))
1686601423: Sending PUBACK to evcc-1213392744 (m44175, rc0)
1686601423: Received PUBLISH from evcc-1213392744 (d0, q1, r1, m44176, 'evcc/site/batteryCapacity', ... (1 bytes))
1686601423: Sending PUBACK to evcc-1213392744 (m44176, rc0)

sieht ja ganz gut aus, da auch publishes an SHNG kommen, und die auch im mqtt plugin-webinterface angezeigt werden.

aber irgendwann dann uas heiterem Himmel:

1686601483: Sending PUBACK to evcc-1213392744 (m44436, rc0)
1686601486: Received PUBLISH from ESP-GEIGER-4F7392 (d0, q0, r1, m0, 'Tkacsik/Sensoren/MightyOhm/CPM', ... (2 bytes))
1686601486: Sending PUBLISH to smarthome.shng-mqtt (d0, q0, r0, m0, 'Tkacsik/Sensoren/MightyOhm/CPM', ... (2 bytes))
1686601486: Received PUBLISH from ESP-GEIGER-4F7392 (d0, q0, r1, m0, 'Tkacsik/Sensoren/MightyOhm/dose', ... (4 bytes))
1686601486: Sending PUBLISH to smarthome.shng-mqtt (d0, q0, r0, m0, 'Tkacsik/Sensoren/MightyOhm/dose', ... (4 bytes))
1686601491: Client smarthome.shng-mqtt has exceeded timeout, disconnecting.
1686601491: Received PINGREQ from ESP-GEIGER-4F7392
1686601491: Sending PINGRESP to ESP-GEIGER-4F7392

und ab dann ist es auch aus. Das passierte ca. 1 Min nachdem mosuitto und danach shng neu gestartet wurde.
Ich könnte mir vorstellen, dass es an irgendwelchen subscribes liegt. Ich denke ich kommentier mal alle aus den yaml-files aus, und schau, ob es dann immer noch ist.
Zuvor habe ich eigentlich nicht viel geändert, nur neue items angelegt mit neuen subscribes.

[Msinn]

Ok, die nutze ich auch. An der sollte es dann wohl nicht liegen.

Welche Version vom Mosquitto Broker setzt Du ein und was steht denn im Log vom Mosquitto Broker?

[ThommyKNX]

Welche Version des paho-mqtt Packages hast Du denn installiert?

die aktuellste, 1.6.1

[Sisamiwe]

Hi,
Auch beim Tasmota-Plugin ist mir diese Fehlermeldung mit 'ip' schon untergekommen.
Ich konnte den Fehler auch nicht finden.
Beste Grüße

[Msinn]

Wie ich bereits schrieb, gibt der paho-mqtt Client nicht mehr Informationen zum Loggen an die _on_log Funktion. Daher kann ich aus SmartHomeNG Sicht dazu nichts sagen.

Welche Version des paho-mqtt Packages hast Du denn installiert?

[ThommyKNX]

Für einen Broker Error 7 kann es diverse Möglichkeiten geben.

Der Error 7 kommt erst beim shutdown von SHNG, ich habe auch schon versucht, der default-instanz einen anderen Namen zu geben, jedoch ohne Erfolg

Hast Du evtl. mehrere SmartHomeNG Instanzen laufen? Schau mal in die Prozess Liste.

Nein, definitiv nicht, ich hab auch geguckt ob das plugin aus Versehen zwei mal geladen ist, dies ist aber nicht der Fall.

Was, denke ich, der Verursacher des Problems ist:

2023-06-01  22:43:54 ERROR    modules.mqtt      _on_log: Caught exception in on_message: 'ip'

Nach dem startup holt sich SHNG einmalig die Daten aus dem Broker, nur nach dieser Nachricht ist schluss.

[Msinn]

2023-06-01 17:14:22 WARNING modules.mqtt Disconnected from broker with returncode '7'

Für einen Broker Error 7 kann es diverse Möglichkeiten geben.

Google spuckt z.B. folgendes aus:

Some disconnection errors are due to reuse the same clientID.
If a client connects with the same clientID, the previous client is disconnected with error 7 or 8.
Try to use a unique clientID or randomize it.

Hast Du evtl. mehrere SmartHomeNG Instanzen laufen? Schau mal in die Prozess Liste.