[gelöst] mqtt2client disconnected ständig

mthome · 05 Juli 2019, 09:56:56

Hallo zusammen,

hatte heute ein update von FHEM durchgeführt mit dem Ergebnis, dass sich der mqtt2client ständig disconnected.

Code Auswählen


2019.07.05 09:23:02 1: localhost:1883 reappeared (mqtt2client)
2019.07.05 09:23:02 1: localhost:1883 disconnected, waiting to reappear (mqtt2client)
2019.07.05 09:23:03 1: localhost:1883 reappeared (mqtt2client)
2019.07.05 09:23:03 1: localhost:1883 disconnected, waiting to reappear (mqtt2client)
2019.07.05 09:23:03 1: localhost:1883 reappeared (mqtt2client)
2019.07.05 09:23:03 1: localhost:1883 disconnected, waiting to reappear (mqtt2client)
2019.07.05 09:23:03 1: localhost:1883 reappeared (mqtt2client)
2019.07.05 09:23:03 1: localhost:1883 disconnected, waiting to reappear (mqtt2client)

Löschen und Neuanlegen hatte nichts gebracht. Ein "rollback" auf die vorherige Version hat das Problem wieder gelöst. Halte mich jetzt erst mal vom Update fern (Urlaub naht).
FYI, ich nutze mosquitto als broker.

Hat noch jemand das Problem?

EDIT: Im Log von mosquitto sehe ich folgende Einträge (mehrfach):

Code Auswählen


1562311391: New client connected from 127.0.0.1 as mqtt2client (c1, k30).
1562311391: Socket error on client mqtt2client, disconnecting.

pcjogi · 05 Juli 2019, 11:00:59

Ich habe ähnliche Probleme, habe schon etwas weiter analysiert. Leider habe ich noch keine abschließende Lösung, aber ein disable 1 und ein löschen des attr disable hilft. Ich habe leider zu wenig Ahnung von MQTT um zu verstehen was hier ggf. falsch läuft.

Ich bekomme nach einem Neustart von fhem folgende Logeinträge (Das Passwort ist natürlich geändert)

Code Auswählen

2019.07.05 10:41:20 1: Including fhem.cfg
2019.07.05 10:41:21 3: WEB: port 8083 opened
2019.07.05 10:41:21 2: eventTypes: loaded 1069 events from ./log/eventTypes.txt
2019.07.05 10:41:21 3: freezemon defined FREEZEMON freezemon
2019.07.05 10:41:21 3: WEBDEV: port 8089 opened
2019.07.05 10:41:22 1: HMCCU: [d_ccu] Initialized version 4.3.015
2019.07.05 10:41:22 1: HMCCU: [d_ccu] HMCCU: Initializing device
2019.07.05 10:41:22 1: HMCCU: [d_ccu] HMCCU: Read 30 devices with 194 channels from CCU 192.168.1.136
2019.07.05 10:41:22 1: HMCCU: [d_ccu] HMCCU: Read 3 interfaces from CCU 192.168.1.136
2019.07.05 10:41:22 1: HMCCU: [d_ccu] HMCCU: Read 4 programs from CCU 192.168.1.136
2019.07.05 10:41:22 1: HMCCU: [d_ccu] HMCCU: Read 0 virtual groups from CCU 192.168.1.136
2019.07.05 10:41:22 2: HMCCU: [d_ccu] Updating CCU system variables every 120 seconds
2019.07.05 10:41:22 1: HMCCURPCPROC: [d_rpc001136BidCos_RF] Initialized version 1.7.001 for interface BidCos-RF with I/O device d_ccu
2019.07.05 10:41:22 1: HMCCURPCPROC: [d_rpc001136HmIP_RF] Initialized version 1.7.001 for interface HmIP-RF with I/O device d_ccu
2019.07.05 10:41:22 3: HourCounter HourCounter Initialize.220 Init Done with Version 1.0.1.2 - 24.12.2014
2019.07.05 10:41:22 0: HourCounter HEIZUNG.Brenner.HourCounter Define.228 parameters: HEIZUNG.Brenner.HourCounter HourCounter HEIZUNG.Brenner.Status:on HEIZUNG.Brenner.Status:off
2019.07.05 10:41:22 3: TelegramBot_Define SYSTEM.Message.Telegram: called 
2019.07.05 10:41:23 3: AptToDate (fhemServerApt) - defined
2019.07.05 10:41:24 3: AutoShuttersControl (ASC) - defined
2019.07.05 10:41:24 1: FULLY: [fully_diele] Version 1.2 Opening device 192.168.1.116
2019.07.05 10:41:24 1: Including ./log/fhem.save
2019.07.05 10:41:24 0: HMCCU: Start of RPC server after FHEM initialization in 12 seconds
2019.07.05 10:41:25 2: [Freezemon] FREEZEMON: ready to watch out for delays greater than 1 second(s)
2019.07.05 10:41:25 0: Featurelevel: 5.9
2019.07.05 10:41:25 0: Server started with 86 defined entities (fhem.pl:19755/2019-07-01 perl:5.024001 os:linux user:fhem pid:27062)
2019.07.05 10:41:25 3: Opening MQTT device kale.local:1883
2019.07.05 10:41:25 5: HttpUtils url=http://kale.local:1883/
2019.07.05 10:41:25 4: IP: kale.local -> 192.168.1.32
2019.07.05 10:41:25 3: telnetForBlockingFn_1562316085: port 36521 opened
2019.07.05 10:41:25 5: MQTT: sending CONNECT (16)&(0)(6)MQIsdp(3)(194)(0)(30)(0)(4)MQTT(0)(7)CSSMQTT(0)(9)PWD
2019.07.05 10:41:25 5: SW: 102600064d514973647003c2001e00044d51545400074353534d51545400094d51545442696c6c65
2019.07.05 10:41:25 3: MQTT device opened
2019.07.05 10:41:25 5: MQTT: received CONNACK (0)(0)
2019.07.05 10:41:25 5: MQTT: sending SUBSCRIBE (128)(6)(0)(24)(0)(1)#(0)
2019.07.05 10:41:25 5: MQTT: received SUBACK (0)(24)(0)
2019.07.05 10:41:25 5: MQTT: sending PUBLISH 0(2)(0)(0)
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)!SmartHome/CSS/IoBrokerMQTT/status (217)K(1)((216)K(1)(0)(0)(0)(0)((4)(168)(0)(0)(0)(0)(0)(231)_L(1)(200)_L
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000SmartHome/CSS/IoBrokerMQTT/status\000 �K\001(�K\001\000\000\000\000(\004�\000\000\000\000\000�_L\001�_L
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)"SmartHome/CSS/CSS2TASMOTA/tele/LWT(176)(214)K(1)(152)(213)K
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000SmartHome/CSS/CSS2TASMOTA/tele/LWT\000��K\001��K
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(29)SmartHome/IoBrokerMQTT/status (217)K(1)((216)K(1)(0)(0)(0)(0)((4)(168)(0)(0)(0)(0)(0)(231)_L(1)(200)_L
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000SmartHome/IoBrokerMQTT/status\000 �K\001(�K\001\000\000\000\000(\004�\000\000\000\000\000�_L\001�_L
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(29)SmartHome/IoBrokerMQTT/Status((216)K(1)(152)(213)K(1)(0)(0)(0)(0)((4)(168)(0)(0)(0)(0)(0)(231)_L(1)(200)_L(1)(239)
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000SmartHome/IoBrokerMQTT/Status\000(�K\001��K\001\000\000\000\000(\004�\000\000\000\000\000�_L\001�_L\001�
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(31)SmartHome/IoBrokerMQTT.1/statusIoBroker MQTT Client.1 online
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000SmartHome/IoBrokerMQTT.1/status\000IoBroker MQTT Client.1 online
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)"System/Tasmota/GASCOUNTER/tele/LWT(176)(212)K(1)(152)(213)K
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000System/Tasmota/GASCOUNTER/tele/LWT\000��K\001��K
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(31)System/Tasmota/WEMOS02/tele/LWTOnline
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000System/Tasmota/WEMOS02/tele/LWT\000Online
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(31)System/Tasmota/WEMOS01/tele/LWTOnline
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000System/Tasmota/WEMOS01/tele/LWT\000Online
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(31)System/Tasmota/WEMOS03/tele/LWTOnline
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000System/Tasmota/WEMOS03/tele/LWT\000Online
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(30)System/Tasmota/Bridge/tele/LWTOnline
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000System/Tasmota/Bridge/tele/LWT\000Online
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(29)System/Tasmota/POW00/tele/LWTOnline
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000System/Tasmota/POW00/tele/LWT\000Online
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)!/System/Tasmota/Licht_01/tele/LWTOnline
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000/System/Tasmota/Licht_01/tele/LWT\000Online
2019.07.05 10:41:25 1: kale.local:1883 disconnected, waiting to reappear (MQTT)
2019.07.05 10:41:25 5: HttpUtils url=http://kale.local:1883/
2019.07.05 10:41:25 4: IP: kale.local -> 192.168.1.32
2019.07.05 10:41:25 5: MQTT: sending CONNECT (16)&(0)(6)MQIsdp(3)(194)(0)(30)(0)(4)MQTT(0)(7)CSSMQTT(0)(9)PWD
2019.07.05 10:41:25 5: SW: 102600064d514973647003c2001e00044d51545400074353534d51545400094d51545442696c6c65
2019.07.05 10:41:25 1: kale.local:1883 reappeared (MQTT)
2019.07.05 10:41:25 5: MQTT: received CONNACK (0)(0)
2019.07.05 10:41:25 5: MQTT: sending SUBSCRIBE (128)(6)(0)(4)(0)(1)#(0)
2019.07.05 10:41:25 5: MQTT: received SUBACK (0)(4)(0)
2019.07.05 10:41:25 5: MQTT: sending PUBLISH 0(2)(0)(0)
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)!SmartHome/CSS/IoBrokerMQTT/status (217)K(1)((216)K(1)(0)(0)(0)(0)((4)(168)(0)(0)(0)(0)(0)(231)_L(1)(200)_L
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000SmartHome/CSS/IoBrokerMQTT/status\000 �K\001(�K\001\000\000\000\000(\004�\000\000\000\000\000�_L\001�_L
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)"SmartHome/CSS/CSS2TASMOTA/tele/LWT(176)(214)K(1)(152)(213)K
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000SmartHome/CSS/CSS2TASMOTA/tele/LWT\000��K\001��K
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(29)SmartHome/IoBrokerMQTT/status (217)K(1)((216)K(1)(0)(0)(0)(0)((4)(168)(0)(0)(0)(0)(0)(231)_L(1)(200)_L
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000SmartHome/IoBrokerMQTT/status\000 �K\001(�K\001\000\000\000\000(\004�\000\000\000\000\000�_L\001�_L
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(29)SmartHome/IoBrokerMQTT/Status((216)K(1)(152)(213)K(1)(0)(0)(0)(0)((4)(168)(0)(0)(0)(0)(0)(231)_L(1)(200)_L(1)(239)
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000SmartHome/IoBrokerMQTT/Status\000(�K\001��K\001\000\000\000\000(\004�\000\000\000\000\000�_L\001�_L\001�
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(31)SmartHome/IoBrokerMQTT.1/statusIoBroker MQTT Client.1 online
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000SmartHome/IoBrokerMQTT.1/status\000IoBroker MQTT Client.1 online
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)"System/Tasmota/GASCOUNTER/tele/LWT(176)(212)K(1)(152)(213)K
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000System/Tasmota/GASCOUNTER/tele/LWT\000��K\001��K
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(31)System/Tasmota/WEMOS02/tele/LWTOnline
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000System/Tasmota/WEMOS02/tele/LWT\000Online
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(31)System/Tasmota/WEMOS01/tele/LWTOnline
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000System/Tasmota/WEMOS01/tele/LWT\000Online
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(31)System/Tasmota/WEMOS03/tele/LWTOnline
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000System/Tasmota/WEMOS03/tele/LWT\000Online
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(30)System/Tasmota/Bridge/tele/LWTOnline
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000System/Tasmota/Bridge/tele/LWT\000Online
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)(29)System/Tasmota/POW00/tele/LWTOnline
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000System/Tasmota/POW00/tele/LWT\000Online
2019.07.05 10:41:25 5: MQTT: received PUBLISH (0)!/System/Tasmota/Licht_01/tele/LWTOnline
2019.07.05 10:41:25 5: MQTT: dispatch autocreate=no\000MQTT\000/System/Tasmota/Licht_01/tele/LWT\000Online
2019.07.05 10:41:25 1: kale.local:1883 disconnected, waiting to reappear (MQTT)
2019.07.05 10:41:25 5: HttpUtils url=http://kale.local:1883/
2019.07.05 10:41:25 4: IP: kale.local -> 192.168.1.32
2019.07.05 10:41:25 5: MQTT: sending CONNECT (16)&(0)(6)MQIsdp(3)(194)(0)(30)(0)(4)MQTT(0)(7)CSSMQTT(0)(9)PWD
2019.07.05 10:41:25 5: SW: 102600064d514973647003c2001e00044d51545400074353534d51545400094d51545442696c6c65
2019.07.05 10:41:25 1: kale.local:1883 reappeared (MQTT)

Nach einem disable von MQTT und einem anschließendem Löschern des attr ist alles wieder ok. Die Logeinträge dazu:

Code Auswählen

2019.07.05 10:41:34 1: kale.local:1883 disconnected, waiting to reappear (MQTT)
2019.07.05 10:41:34 5: HttpUtils url=http://kale.local:1883/
2019.07.05 10:41:34 4: IP: kale.local -> 192.168.1.32
2019.07.05 10:41:34 5: MQTT: sending CONNECT (16)&(0)(6)MQIsdp(3)(194)(0)(30)(0)(4)MQTT(0)(7)CSSMQTT(0)(9)MQTTBille
2019.07.05 10:41:34 5: SW: 102600064d514973647003c2001e00044d51545400074353534d51545400094d51545442696c6c65
2019.07.05 10:41:34 1: kale.local:1883 reappeared (MQTT)
2019.07.05 10:41:34 5: MQTT: received CONNACK (0)(0)
2019.07.05 10:41:34 5: MQTT: sending SUBSCRIBE (128)(6)(0)(29)(0)(1)#(0)
2019.07.05 10:41:34 5: MQTT: received SUBACK (0)(29)(0)
2019.07.05 10:41:34 5: MQTT: received PUBLISH (0)!SmartHome/CSS/IoBrokerMQTT/status (217)K(1)((216)K(1)(0)(0)(0)(0)((4)(168)(0)(0)(0)(0)(0)(231)_L(1)(200)_L
2019.07.05 10:41:34 5: MQTT: received PUBLISH (0)"SmartHome/CSS/CSS2TASMOTA/tele/LWT(176)(214)K(1)(152)(213)K
2019.07.05 10:41:34 5: MQTT: received PUBLISH (0)(29)SmartHome/IoBrokerMQTT/status (217)K(1)((216)K(1)(0)(0)(0)(0)((4)(168)(0)(0)(0)(0)(0)(231)_L(1)(200)_L
2019.07.05 10:41:34 5: MQTT: received PUBLISH (0)(29)SmartHome/IoBrokerMQTT/Status((216)K(1)(152)(213)K(1)(0)(0)(0)(0)((4)(168)(0)(0)(0)(0)(0)(231)_L(1)(200)_L(1)(239)
2019.07.05 10:41:34 5: MQTT: received PUBLISH (0)(31)SmartHome/IoBrokerMQTT.1/statusIoBroker MQTT Client.1 online
2019.07.05 10:41:34 5: MQTT: received PUBLISH (0)"System/Tasmota/GASCOUNTER/tele/LWT(176)(212)K(1)(152)(213)K
2019.07.05 10:41:34 5: MQTT: received PUBLISH (0)(31)System/Tasmota/WEMOS02/tele/LWTOnline
2019.07.05 10:41:34 5: MQTT: received PUBLISH (0)(31)System/Tasmota/WEMOS01/tele/LWTOnline
2019.07.05 10:41:34 5: MQTT: received PUBLISH (0)(31)System/Tasmota/WEMOS03/tele/LWTOnline
2019.07.05 10:41:34 5: MQTT: received PUBLISH (0)(30)System/Tasmota/Bridge/tele/LWTOnline
2019.07.05 10:41:34 5: MQTT: received PUBLISH (0)(29)System/Tasmota/POW00/tele/LWTOnline
2019.07.05 10:41:34 5: MQTT: received PUBLISH (0)!/System/Tasmota/Licht_01/tele/LWTOnline
2019.07.05 10:41:36 5: MQTT: received PUBLISH (0)!System/Tasmota/WEMOS02/tele/STATE{"Time":"2019-07-05T09:41:37","Uptime":"48T04:45:16","Vcc":3.012,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"Wifi":{"AP":1,"SSId":"CSSIoT","BSSId":"B6:FB:E4:41:2E:B9","Channel":11,"RSSI":96}}
2019.07.05 10:41:36 5: MQTT: received PUBLISH (0)"System/Tasmota/WEMOS02/tele/SENSOR{"Time":"2019-07-05T09:41:37","DS18B20-1":{"Id":"000006964A5A","Temperature":25.7},"DS18B20-2":{"Id":"000006991D7A","Temperature":40.4},"DS18B20-3":{"Id":"000006BC0E17","Temperature":44.7},"DS18B20-4":{"Id":"000006BC2A9E","Temperature":48.6},"DS18B20-5":{"Id":"000006BC5036","Temperature":35.9},"DS18B20-6":{"Id":"000006C807FF","Temperature":43.5},"DS18B20-7":{"Id":"000006C8127B","Temperature":32.2},"TempUnit":"C"}
2019.07.05 10:41:36 5: MQTT: received PUBLISH (0)-javascript/0/OneWire/000006BC0E17/Temperature44.7
2019.07.05 10:41:36 5: MQTT: received PUBLISH (0)-javascript/0/OneWire/000006BC2A9E/Temperature48.6
2019.07.05 10:41:36 5: MQTT: received PUBLISH (0)-javascript/0/OneWire/000006C807FF/Temperature43.5

Code Auswählen


Internals:
   BUF        
   DEF        kale.local:1883
   DeviceName kale.local:1883
   FD         29
   FUUID      5d08682c-f33f-c8ac-d560-aa8f65a42a073568
   NAME       MQTT
   NR         42
   PARTIAL    
   STATE      opened
   TYPE       MQTT2_CLIENT
   WBCallback 
   clientId   MQTT
   lastMsgTime 1562317079.10456
   nextOpenDelay 5
   READINGS:
     2019-07-05 10:41:34   state           opened
Attributes:
   room       _MQTT
   username   CSSMQTT
   verbose    5

rudolfkoenig · 05 Juli 2019, 11:38:04

Danke fuer den Hinweis, da habe ich gestern wohl nicht ausreichend getestet.
Habs gefixt und eingecheckt.

mthome · 05 Juli 2019, 11:47:35

Danke für den schnellen Fix

.

D.h. wenn ich morgen ein update mache sollte alles gut sein?

pcjogi · 05 Juli 2019, 20:06:06

ich hab jetzt etwas verwunderliche Inhalte im internals BUF und leider immer noch die gleiche Fehlersituation nach einem Neustart

Code Auswählen

Internals:
   BUF        0�/info/0/sysinfo/cpu/currentLoad/currentload_hist100,99.54128440366972,99.35691318327974,100,100,100,99.62121212121212,100,100,100,100,100,100,100,99.375,1 
   DEF        kale.local:1883
   DeviceName kale.local:1883
   FD         21
   FUUID      5d08682c-f33f-c8ac-d560-aa8f65a42a073568
   NAME       MQTT
   NR         42
   PARTIAL    
   STATE      opened
   TYPE       MQTT2_CLIENT
   WBCallback 
   clientId   MQTT
   connecting 3
   lastMsgTime 1562349461.05439
   nextOpenDelay 5
   READINGS:
     2019-07-05 20:02:55   state           opened
Attributes:
   disable    1
   room       _MQTT
   username   CSSMQTT

rudolfkoenig · 05 Juli 2019, 20:20:40

Ein nicht leeres BUF bedeutet eine nicht vollstaendig empfangene Nachricht.
Ist die MQTT2_CLIENT Version 19784 (aus der SVN gezogen) ?

pcjogi · 05 Juli 2019, 21:34:18

Nein, ist die 00_MQTT2_CLIENT.pm 19775 2019-07-04 19:55:24Z rudolfkoenig

Ich muss nochmal nachlesen wie ich die aus dem SVN installiere

pcjogi · 05 Juli 2019, 22:05:28

mit der Version 19784 sieht es besser aus. Ich Teste noch ein bisschen
Danke

mthome · 06 Juli 2019, 20:44:49

Also bei mir ist mit dem Update von heute alles supi

Vielen Dank nochmals für den schnellen Fix.