(gelöst)Mqtt2_client merkt nicht , wenn Mqtt2_Server tot, nicht erreichbar ist

LuckyDay · 28 August 2019, 18:09:59

Ich habe das Problem, dass der MQTT2_CLIENT nicht merkt, also immer opened ist und bleibt obwohl der Server nicht mehr erreichbar ist.
bin noch neu bei Mqtt, vielleicht auch etwas übersehen.

logs und defs anbei

server

Code Auswählen

defmod mqtt_fhem MQTT2_SERVER 1883 global
attr mqtt_fhem autocreate no
attr mqtt_fhem room MQTT2_DEVICE

setstate mqtt_fhem 2019-08-28 17:52:18 RETAIN {"tele/WZ_C_T_P/LWT":"Online"}
setstate mqtt_fhem 2019-08-28 17:52:18 nrclients 1
setstate mqtt_fhem 2019-08-28 16:41:20 state Initialized

client

Code Auswählen

defmod mqttclient1 MQTT2_CLIENT 192.168.2.114:1883
attr mqttclient1 clientId mqttclient1
attr mqttclient1 keepaliveTimeout 10
attr mqttclient1 room test
attr mqttclient1 verbose 5

setstate mqttclient1 opened
setstate mqttclient1 2019-08-28 17:35:27 state opened

Verbose 5 am client

Code Auswählen

2019.08.28 17:39:38.074 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:39:38.074 5: mqttclient1: keepalive 10
2019.08.28 17:39:28.074 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:39:28.074 5: mqttclient1: keepalive 10
2019.08.28 17:39:18.072 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:39:18.072 5: mqttclient1: keepalive 10
2019.08.28 17:39:08.071 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:39:08.071 5: mqttclient1: keepalive 10
2019.08.28 17:38:58.061 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:38:58.060 5: mqttclient1: keepalive 10
2019.08.28 17:38:51.351 5: mqttclient1: dispatch autocreate=no\000mqttclient1\000tele/WZ_C_T_P/SENSOR\000{"Time":"2019-08-28T16:38:50","BMP180":{"Temperature":39.3,"Pressure":995.5},"CCS811":{"eCO2":403,"TVOC":0},"PressureUnit":"hPa","TempUnit":"C"}
2019.08.28 17:38:51.351 5: mqttclient1: received PUBLISH (0)(20)tele/WZ_C_T_P/SENSOR{"Time":"2019-08-28T16:38:50","BMP180":{"Temperature":39.3,"Pressure":995.5},"CCS811":{"eCO2":403,"TVOC":0},"PressureUnit":"hPa","TempUnit":"C"}
2019.08.28 17:38:51.345 5: mqttclient1: dispatch autocreate=no\000mqttclient1\000tele/WZ_C_T_P/STATE\000{"Time":"2019-08-28T16:38:50","Uptime":"0T01:10:24","Vcc":3.466,"SleepMode":"Dynamic","Sleep":0,"LoadAvg":764,"POWER1":"on","Dimmer":4,"Color":"0A0000","HSBColor":"0,100,4","Channel":[3,0,0],"Scheme":0,"Width":1,"Fade":"off","Speed":1,"LedTable":"off","Wifi":{"AP":1,"SSId":"FRITZBox2","BSSId":"24:65:11:87:35:32","Channel":11,"RSSI":100,"LinkCount":1,"Downtime":"0T00:00:04"}}
2019.08.28 17:38:51.344 5: mqttclient1: received PUBLISH (0)(19)tele/WZ_C_T_P/STATE{"Time":"2019-08-28T16:38:50","Uptime":"0T01:10:24","Vcc":3.466,"SleepMode":"Dynamic","Sleep":0,"LoadAvg":764,"POWER1":"on","Dimmer":4,"Color":"0A0000","HSBColor":"0,100,4","Channel":[3,0,0],"Scheme":0,"Width":1,"Fade":"off","Speed":1,"LedTable":"off","Wifi":{"AP":1,"SSId":"FRITZBox2","BSSId":"24:65:11:87:35:32","Channel":11,"RSSI":100,"LinkCount":1,"Downtime":"0T00:00:04"}}
2019.08.28 17:38:48.059 5: mqttclient1: received PINGRESP 
2019.08.28 17:38:48.053 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:38:48.053 5: mqttclient1: keepalive 10
2019.08.28 17:38:38.052 5: mqttclient1: received PINGRESP 
2019.08.28 17:38:38.046 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:38:38.046 5: mqttclient1: keepalive 10
2019.08.28 17:38:28.041 5: mqttclient1: received PINGRESP 
2019.08.28 17:38:28.036 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:38:28.036 5: mqttclient1: keepalive 10

Server wieder online ca.17.51

Code Auswählen

2019.08.28 17:53:06.874 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:53:06.873 5: mqttclient1: keepalive 10
2019.08.28 17:52:56.874 5: mqttclient1: received PINGRESP 
2019.08.28 17:52:56.867 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:52:56.867 5: mqttclient1: keepalive 10
2019.08.28 17:52:53.074 5: mqttclient1: dispatch autocreate=no\000mqttclient1\000tele/WZ_C_T_P/SENSOR\000{"Time":"2019-08-28T16:52:51","BMP180":{"Temperature":38.5,"Pressure":995.5},"CCS811":{"eCO2":425,"TVOC":3},"PressureUnit":"hPa","TempUnit":"C"}
2019.08.28 17:52:53.074 5: mqttclient1: received PUBLISH (0)(20)tele/WZ_C_T_P/SENSOR{"Time":"2019-08-28T16:52:51","BMP180":{"Temperature":38.5,"Pressure":995.5},"CCS811":{"eCO2":425,"TVOC":3},"PressureUnit":"hPa","TempUnit":"C"}
2019.08.28 17:52:53.068 5: mqttclient1: dispatch autocreate=no\000mqttclient1\000tele/WZ_C_T_P/STATE\000{"Time":"2019-08-28T16:52:51","Uptime":"0T01:24:25","Vcc":3.466,"SleepMode":"Dynamic","Sleep":0,"LoadAvg":999,"POWER1":"on","Dimmer":4,"Color":"0A0000","HSBColor":"0,100,4","Channel":[3,0,0],"Scheme":0,"Width":1,"Fade":"off","Speed":1,"LedTable":"off","Wifi":{"AP":1,"SSId":"FRITZBox2","BSSId":"24:65:11:87:35:32","Channel":11,"RSSI":100,"LinkCount":1,"Downtime":"0T00:00:04"}}
2019.08.28 17:52:53.068 5: mqttclient1: received PUBLISH (0)(19)tele/WZ_C_T_P/STATE{"Time":"2019-08-28T16:52:51","Uptime":"0T01:24:25","Vcc":3.466,"SleepMode":"Dynamic","Sleep":0,"LoadAvg":999,"POWER1":"on","Dimmer":4,"Color":"0A0000","HSBColor":"0,100,4","Channel":[3,0,0],"Scheme":0,"Width":1,"Fade":"off","Speed":1,"LedTable":"off","Wifi":{"AP":1,"SSId":"FRITZBox2","BSSId":"24:65:11:87:35:32","Channel":11,"RSSI":100,"LinkCount":1,"Downtime":"0T00:00:04"}}
2019.08.28 17:52:47.901 5: mqttclient1: dispatch autocreate=no\000mqttclient1\000tele/WZ_C_T_P/LWT\000Online
2019.08.28 17:52:47.901 5: mqttclient1: received PUBLISH (0)(17)tele/WZ_C_T_P/LWTOnline
2019.08.28 17:52:46.897 5: mqttclient1: received SUBACK (0)(4)(0)
2019.08.28 17:52:46.889 5: mqttclient1: sending SUBSCRIBE (130)(6)(0)(4)(0)(1)#(0)
2019.08.28 17:52:46.888 5: mqttclient1: received CONNACK (0)(0)
2019.08.28 17:52:46.863 1: 192.168.2.114:1883 reappeared (mqttclient1)
2019.08.28 17:52:46.862 5: SW: 101900064d51497364700302000a000b6d717474636c69656e7431
2019.08.28 17:52:46.862 5: mqttclient1: sending CONNECT (16)(25)(0)(6)MQIsdp(3)(2)(0)(10)(0)(11)mqttclient1
2019.08.28 17:52:46.860 4: IP: 192.168.2.114 -> 192.168.2.114
2019.08.28 17:52:46.860 5: HttpUtils url=http://192.168.2.114:1883/
2019.08.28 17:52:46.858 1: 192.168.2.114:1883 disconnected, waiting to reappear (mqttclient1)
2019.08.28 17:52:38.453 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:52:38.452 5: mqttclient1: keepalive 10
2019.08.28 17:52:28.443 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:52:28.443 5: mqttclient1: keepalive 10
2019.08.28 17:52:18.442 5: mqttclient1: sending PINGREQ (192)(0)

rudolfkoenig · 28 August 2019, 19:35:25

Kann nicht nachvollziehen, gerade getestet.
Im beigefuegten Log sieht man die disconnected...reappeared Meldungen, und dabei wird bei mir state auf disconnected/opened gesetzt.

Heisst nicht, dass das Problem nicht besteht, nur dass ich zum Reproduzieren eine deutlich detailliertere Beschreibung brauche.
Z.Bsp. weiss ich nicht wann der Server offline gegangen ist, und gerade fuer den fraglichen Zeitraum (17:51) gibt es keine Logs.

LuckyDay · 28 August 2019, 20:15:14

Ich habe den verboselog gedreht(lesen von oben nach unten) und die Server online/offline eingetragen
man sieht das kein received PINGRESP vom Server mehr kommt
und MQTT2_CLIENT immer opened im state bleibt.
erst als der Server wieder vorhanden ist merkt es der Client siehe disconnect und reappeared,
weiß gerade nicht wie ich es anders beschreiben soll

Code Auswählen

Server online-->

2019.08.28 17:38:28.036 5: mqttclient1: keepalive 10
2019.08.28 17:38:28.036 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:38:28.041 5: mqttclient1: received PINGRESP 
2019.08.28 17:38:38.046 5: mqttclient1: keepalive 10
2019.08.28 17:38:38.046 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:38:38.052 5: mqttclient1: received PINGRESP 
2019.08.28 17:38:48.053 5: mqttclient1: keepalive 10
2019.08.28 17:38:48.053 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:38:48.059 5: mqttclient1: received PINGRESP 
2019.08.28 17:38:51.344 5: mqttclient1: received PUBLISH (0)(19)tele/WZ_C_T_P/STATE{"Time":"2019-08-28T16:38:50","Uptime":"0T01:10:24","Vcc":3.466,"SleepMode":"Dynamic","Sleep":0,"LoadAvg":764,"POWER1":"on","Dimmer":4,"Color":"0A0000","HSBColor":"0,100,4","Channel":[3,0,0],"Scheme":0,"Width":1,"Fade":"off","Speed":1,"LedTable":"off","Wifi":{"AP":1,"SSId":"FRITZBox2","BSSId":"24:65:11:87:35:32","Channel":11,"RSSI":100,"LinkCount":1,"Downtime":"0T00:00:04"}}
2019.08.28 17:38:51.345 5: mqttclient1: dispatch autocreate=no\000mqttclient1\000tele/WZ_C_T_P/STATE\000{"Time":"2019-08-28T16:38:50","Uptime":"0T01:10:24","Vcc":3.466,"SleepMode":"Dynamic","Sleep":0,"LoadAvg":764,"POWER1":"on","Dimmer":4,"Color":"0A0000","HSBColor":"0,100,4","Channel":[3,0,0],"Scheme":0,"Width":1,"Fade":"off","Speed":1,"LedTable":"off","Wifi":{"AP":1,"SSId":"FRITZBox2","BSSId":"24:65:11:87:35:32","Channel":11,"RSSI":100,"LinkCount":1,"Downtime":"0T00:00:04"}}
2019.08.28 17:38:51.351 5: mqttclient1: received PUBLISH (0)(20)tele/WZ_C_T_P/SENSOR{"Time":"2019-08-28T16:38:50","BMP180":{"Temperature":39.3,"Pressure":995.5},"CCS811":{"eCO2":403,"TVOC":0},"PressureUnit":"hPa","TempUnit":"C"}
2019.08.28 17:38:51.351 5: mqttclient1: dispatch autocreate=no\000mqttclient1\000tele/WZ_C_T_P/SENSOR\000{"Time":"2019-08-28T16:38:50","BMP180":{"Temperature":39.3,"Pressure":995.5},"CCS811":{"eCO2":403,"TVOC":0},"PressureUnit":"hPa","TempUnit":"C"}

Server offline-->

2019.08.28 17:38:58.060 5: mqttclient1: keepalive 10
2019.08.28 17:38:58.061 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:39:08.071 5: mqttclient1: keepalive 10
2019.08.28 17:39:08.071 5: mqttclient1: sending PINGREQ (192)(0)
.
.
.
2019.08.28 17:52:28.443 5: mqttclient1: keepalive 10
2019.08.28 17:52:28.443 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:52:38.452 5: mqttclient1: keepalive 10
2019.08.28 17:52:38.453 5: mqttclient1: sending PINGREQ (192)(0)

Server online--->

2019.08.28 17:52:46.858 1: 192.168.2.114:1883 disconnected, waiting to reappear (mqttclient1)
2019.08.28 17:52:46.860 5: HttpUtils url=http://192.168.2.114:1883/
2019.08.28 17:52:46.860 4: IP: 192.168.2.114 -> 192.168.2.114
2019.08.28 17:52:46.862 5: mqttclient1: sending CONNECT (16)(25)(0)(6)MQIsdp(3)(2)(0)(10)(0)(11)mqttclient1
2019.08.28 17:52:46.862 5: SW: 101900064d51497364700302000a000b6d717474636c69656e7431
2019.08.28 17:52:46.863 1: 192.168.2.114:1883 reappeared (mqttclient1)
2019.08.28 17:52:46.888 5: mqttclient1: received CONNACK (0)(0)
2019.08.28 17:52:46.889 5: mqttclient1: sending SUBSCRIBE (130)(6)(0)(4)(0)(1)#(0)
2019.08.28 17:52:46.897 5: mqttclient1: received SUBACK (0)(4)(0)
2019.08.28 17:52:47.901 5: mqttclient1: received PUBLISH (0)(17)tele/WZ_C_T_P/LWTOnline
2019.08.28 17:52:47.901 5: mqttclient1: dispatch autocreate=no\000mqttclient1\000tele/WZ_C_T_P/LWT\000Online
2019.08.28 17:52:53.068 5: mqttclient1: received PUBLISH (0)(19)tele/WZ_C_T_P/STATE{"Time":"2019-08-28T16:52:51","Uptime":"0T01:24:25","Vcc":3.466,"SleepMode":"Dynamic","Sleep":0,"LoadAvg":999,"POWER1":"on","Dimmer":4,"Color":"0A0000","HSBColor":"0,100,4","Channel":[3,0,0],"Scheme":0,"Width":1,"Fade":"off","Speed":1,"LedTable":"off","Wifi":{"AP":1,"SSId":"FRITZBox2","BSSId":"24:65:11:87:35:32","Channel":11,"RSSI":100,"LinkCount":1,"Downtime":"0T00:00:04"}}
2019.08.28 17:52:53.068 5: mqttclient1: dispatch autocreate=no\000mqttclient1\000tele/WZ_C_T_P/STATE\000{"Time":"2019-08-28T16:52:51","Uptime":"0T01:24:25","Vcc":3.466,"SleepMode":"Dynamic","Sleep":0,"LoadAvg":999,"POWER1":"on","Dimmer":4,"Color":"0A0000","HSBColor":"0,100,4","Channel":[3,0,0],"Scheme":0,"Width":1,"Fade":"off","Speed":1,"LedTable":"off","Wifi":{"AP":1,"SSId":"FRITZBox2","BSSId":"24:65:11:87:35:32","Channel":11,"RSSI":100,"LinkCount":1,"Downtime":"0T00:00:04"}}
2019.08.28 17:52:53.074 5: mqttclient1: received PUBLISH (0)(20)tele/WZ_C_T_P/SENSOR{"Time":"2019-08-28T16:52:51","BMP180":{"Temperature":38.5,"Pressure":995.5},"CCS811":{"eCO2":425,"TVOC":3},"PressureUnit":"hPa","TempUnit":"C"}
2019.08.28 17:52:53.074 5: mqttclient1: dispatch autocreate=no\000mqttclient1\000tele/WZ_C_T_P/SENSOR\000{"Time":"2019-08-28T16:52:51","BMP180":{"Temperature":38.5,"Pressure":995.5},"CCS811":{"eCO2":425,"TVOC":3},"PressureUnit":"hPa","TempUnit":"C"}
2019.08.28 17:52:56.867 5: mqttclient1: keepalive 10
2019.08.28 17:52:56.867 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:52:56.874 5: mqttclient1: received PINGRESP 
2019.08.28 17:53:06.873 5: mqttclient1: keepalive 10
2019.08.28 17:53:06.874 5: mqttclient1: sending PINGREQ (192)(0)
2019.08.28 17:53:06.880 5: mqttclient1: received PINGRESP

rudolfkoenig · 28 August 2019, 21:18:02

Was genau verstehst du unter "Server nicht erreichbar"?
Sowas wie Server-Absturz, Kabel abziehen oder Server ausschalten kriegt FHEM normalerweise mit.

LuckyDay · 28 August 2019, 21:43:24

ZitatWas genau verstehst du unter "Server nicht erreichbar"?

So wie im richtigen Leben,
in dem simulierten Fall oben habe ich das Netzwerkkabel vom Mqtt2server abgezogen, könnte natürlich auch Stromausfall, Netzgerät ,oder Switch sein.

Ich hatte eigentlich vermutet, dass der Client , da ich

Code Auswählen

attr mqttclient1 keepaliveTimeout 10
gesetzt hatte, bei ausbleibenden Antworten vom Server irgendwie versucht einen reconnect zu machen,
macht er aber nicht. auch gibt es kein reading von der letzten Antwort.

vermissenen tu ich auch ein manuelles reopen am client.

rudolfkoenig · 30 August 2019, 13:15:36

Ich konnte das bei mir auch nachstellen, was mein Verstaendnis von TCP/IP erschuettert.

Ab sofort prueft das Modul, ob beim Senden einer PINGREQ Nachricht die Letzte bestaetigt wurde, und falls nicht, wird die Verbindung neu aufgebaut.

LuckyDay · 30 August 2019, 14:18:42

Vielen Dank Rudi,

funktioniert sehr gut!