MQTT gets disconnected after short time and don't reconnect #673
Comments
|
I found a solution, I'm not sure this have any implications that I don't realise but now Mqtt re-connects. The solution I found was to modify AsyncMqttClient and add a AsyncMqttClient::resetLockMutiConnections() that sets _lockMutiConnections to false. I hope this helps somehow to find the real problem which seems to be that AsyncMqttClient::_onDisconnect is not called, as there is the place where _lockMutiConnections is set to false. Thank you, |
|
Glad you've found a workaround. It looks like it may be the WiFi cutting out if you're seeing messages like In any case, I should be able to reproduce this too if I disable one of my access points and see if MQTT is able to reconnect to the broker. |
The wifi_quality() function reports 100 and I think it's correct. The router and the EMS are on the same room, let's say 3-4m distance and the only thing getting in the way are the furniture dors which are not very tick. I noticed letting it run (and having some more info added to the log) that when the connectcount_ is increasing over 50 the web interface became unresponsive (while mqtt and remote logging still worked) and at some point in my insistences of loading the web ui the ESP restarted. There is one thing that intrigues me: the disconects happend very rhythmical, like programmed :), one per minute, see beelow the log filtered: I'm think I will play with the SYSTEM_HEARTBEAT_INTERVAL and EMS_FETCH_FREQUENCY which are both one minute maybe I can find something. |
|
/are you getting the "Wifi Connected" messages too every 1-2 minutes? |
Yes, it seems the two coincide: Dec 28 21:58:00 ems-esp - 000+00:11:00.104 I 1008: [emsesp] WiFi Connected with IP=192.168.100.130, hostname=ems-esp |
|
Right. To rule out any 3rd party library issues, do you get the same behaviour when using the prebuilt binaries? |
|
I just downloaded the prebuilt 2.2 image and I can confirm it's the same behavior, it disconects. |
|
Changing SYSTEM_HEARTBEAT_INTERVAL to 70000 and SYSTEM_HEARTBEAT_INTERVAL to 50000 (at the same time) doesn't change the situation too much even though it seems to add a little more variation to the timing of the disconects: Dec 28 22:42:12 ems-esp - 000+00:01:00.053 I 236: [mqtt] MQTT disconnected: TCP |
|
I found the cause of the rithmical disconects (every minute): the DHCP server in my router have the lease time set to 1 minute (I needed it at some point and forgot it that way). I set it to 2 minutes for the sake of testing and the problem disapeared. I watched the "remaining lease time" reported by the router for the ESP and it seems that ESP is renewing the WiFi connection as the lease time never got to zero so I don't get the WiFi disconect and subsequently the Mqtt disconect. I will wach it for few days and see if the problem occur anymore and I will get back. |
|
I haven't been able to test yet so just shouting out ideas for now so we can home in on the root cause.
|
|
Thank you for help!
Yes, the telnet connection dropped also very quick and now it stays connected. |
|
I think we can close this. |
Bug description
I have a Gateway Premium II connected to a Buderus Logamax Plus GB172i-30 K. I use a Raspbery Pi 4 with Mosquito to receive the information on MQTT and also logs in syslog and the problem is that the ESP gets disconnected from MQTT after about a minute and isn't connecting back.
The behavior was present on version 2.1 and is also present in 2.2.
I need a little help to try solve this, thank you in advance.
All the best,
Virgil
Steps to reproduce
In my setup it's very easy to reproduce, I just restart the ESP, it connects to Mqtt works well for about one minute and then it gets disconnected and (almost) never succed to reconnect back.
In just few ocasions, after restarting the ESP, the mqtt re-connection worked for a number of times, maybe a few minutes but finally it hanged.
I downloaded the code and tried to find the where/how the re-connection should occur and why its not working.
The only place where I can find a call to mqtt connect() is in MqttSettingsService::configureMqtt() which is called in
MqttSettingsService::loop().
In my case it seem that both _mqttClient.disconnect() and _mqttClient.connect() calls are reurning immediately (maybe because bcause of _lockMutiConnections ).
I tried a few things but nothing worked so far.
I keep seeing the following line in the logs, I don't know if it's related:
[emsesp] WiFi Connected with IP=192.168.100.130, hostname=emsesp
The log line is written in WebStatusService::onStationModeGotIP() but I don't understand who is calling this handler because I don't see any Wifi Disconect ...
Also, the ESP continue to send logs to rsyslog on my RaspberyPi, so the Wifi connection even if id drops it gets back.
Expected behavior
The expected behavior is that MQTT connection is re-established.
Device information
{
"System": {
"version": "2.2.0",
"uptime": "000+00:07:50.553",
"freemem": 44,
"fragmem": 40
},
"Settings": {
"enabled": "on",
"publish_time_boiler": 10,
"publish_time_thermostat": 0,
"publish_time_solar": 0,
"publish_time_mixer": 0,
"publish_time_other": 0,
"publish_time_sensor": 0,
"mqtt_format": 1,
"mqtt_qos": 0,
"mqtt_retain": "off",
"tx_mode": 1,
"ems_bus_id": 11,
"master_thermostat": 0,
"rx_gpio": 13,
"tx_gpio": 15,
"dallas_gpio": 0,
"dallas_parasite": "off",
"led_gpio": 2,
"hide_led": "off",
"api_enabled": "off",
"bool_format": 1,
"analog_enabled": "off"
},
"Status": {
"bus": "connected",
"bus protocol": "Buderus",
"#telegrams received": 265,
"#read requests sent": 58,
"#write requests sent": 0,
"#incomplete telegrams": 0,
"#tx fails": 3,
"rx line quality": 100,
"tx line quality": 100,
"#MQTT publish fails": 0,
"#dallas sensors": 0
},
"Devices": [
{
"type": "Boiler",
"name": "Buderus GBx72/Trendline/Cerapur/Greenstar Si/27i (DeviceID:0x08 ProductID:123, Version:06.08)",
"handlers": "0x10 0x11 0x14 0x15 0x16 0x18 0x19 0x1A 0x1C 0x2A 0x33 0x34 0x35 0xD1 0xE3 0xE4 0xE5 0xE6 0xE9 0xEA 0x494 0x495"
},
{
"type": "Controller",
"name": "BC25 (DeviceID:0x09, ProductID:125, Version:03.03)",
"handlers": ""
}
]
}
Additional context
Bellow I paste the logs from the start to the disconect moment:
Dec 28 17:46:40 emsesp - 000+00:00:07.967 I 99: [mqtt] MQTT connected
Dec 28 17:46:40 emsesp - 000+00:00:07.967 D 100: [mqtt] Subscribing to topic: emsesp/system
Dec 28 17:46:40 emsesp - 000+00:00:08.160 D 101: [telegram] Sending read Tx [#12], telegram: 0B 88 E6 00 20 07
Dec 28 17:46:40 emsesp - 000+00:00:08.183 D 102: [mqtt] Subscribing to topic: emsesp/boiler
Dec 28 17:46:40 emsesp - 000+00:00:08.212 D 103: [emsesp] Last Tx read successful
Dec 28 17:46:40 emsesp - 000+00:00:08.212 T 104: [emsesp] Boiler(0x08) -> Me(0x0B), UBAParametersPlus(0xE6), data:
Dec 28 17:46:40 emsesp - 000+00:00:08.212 D 105: [emsesp] This telegram (UBAParametersPlus) is not recognized by the EMS bus
Dec 28 17:46:40 emsesp - 000+00:00:08.212 D 106: [emsesp] Toggling fetch for device ID 0x08, telegram ID 0xE6 to 0
Dec 28 17:46:40 emsesp - 000+00:00:08.212 D 107: [emsesp] No telegram type handler found for ID 0xE6 (src 0x08)
Dec 28 17:46:40 emsesp - 000+00:00:08.384 D 108: [mqtt] Publishing topic emsesp/info (#2, retain=0, try#1, size 58, pid 1)
Dec 28 17:46:40 emsesp - 000+00:00:08.482 D 109: [telegram] Sending read Tx [#13], telegram: 0B 88 EA 00 20 37
Dec 28 17:46:40 emsesp - 000+00:00:08.512 D 110: [emsesp] Last Tx read successful
Dec 28 17:46:40 emsesp - 000+00:00:08.512 T 111: [emsesp] Boiler(0x08) -> Me(0x0B), UBAParameterWWPlus(0xEA), data:
Dec 28 17:46:40 emsesp - 000+00:00:08.512 D 112: [emsesp] This telegram (UBAParameterWWPlus) is not recognized by the EMS bus
Dec 28 17:46:40 emsesp - 000+00:00:08.512 D 113: [emsesp] Toggling fetch for device ID 0x08, telegram ID 0xEA to 0
Dec 28 17:46:40 emsesp - 000+00:00:08.512 D 114: [emsesp] No telegram type handler found for ID 0xEA (src 0x08)
Dec 28 17:46:40 emsesp - 000+00:00:08.586 D 115: [mqtt] Publishing topic emsesp/status (#3, retain=1, try#1, size 6, pid 1)
Dec 28 17:46:41 emsesp - 000+00:00:10.198 D 116: [mqtt] Publishing topic emsesp/boiler_data (#4, retain=0, try#1, size 290, pid 1)
Dec 28 17:46:41 emsesp - 000+00:00:10.399 D 117: [mqtt] Publishing topic emsesp/boiler_data_ww (#5, retain=0, try#1, size 151, pid 1)
Dec 28 17:46:41 emsesp - 000+00:00:10.738 T 118: [emsesp] Boiler(0x08) -> All(0x00), UBADevices(0x07), data: 0B 00 00 00 00 00 00 00 00 00 00 00 00
Dec 28 17:46:42 emsesp - 000+00:00:10.973 T 119: [emsesp] Boiler(0x08) -> All(0x00), UBAMonitorFast(0x18), data: 28 01 8A 64 0F 09 02 25 C0 01 38 80 00 80 00 00 71 FF 2D 48 00 C8 00 02 00
Dec 28 17:46:42 emsesp - 000+00:00:11.002 D 120: [mqtt] Publishing topic emsesp/heating_active (#6, retain=0, try#1, size 2, pid 1)
Dec 28 17:46:42 emsesp - 000+00:00:11.203 D 121: [mqtt] Publishing topic emsesp/tapwater_active (#7, retain=0, try#1, size 3, pid 1)
Dec 28 17:46:42 emsesp - 000+00:00:11.265 T 122: [emsesp] Boiler(0x08) -> All(0x00), UBAMonitorSlow(0x19), data: 80 00 80 00 80 00 00 00 00 40 00 E1 FF 04 C6 ED 00 00 00 04 48 45 00 2C 8C 80 00
Dec 28 17:46:42 emsesp - 000+00:00:11.546 T 123: [emsesp] Boiler(0x08) -> All(0x00), UBAMaintenanceStatus(0x1C), data: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Dec 28 17:46:42 emsesp - 000+00:00:11.749 T 124: [emsesp] Boiler(0x08) -> All(0x00), MC10Status(0x2A), data: 00 00 00 00 00 00 00 00 A7 00 A8 80 00 00 80 00 80 00 80 00 00
Dec 28 17:46:43 emsesp - 000+00:00:12.040 T 125: [emsesp] Boiler(0x08) -> All(0x00), UBAMonitorWW(0x34), data: 3C 01 38 80 00 21 00 00 01 00 00 7E A8 00 B5 73 00 80 00
Dec 28 17:46:51 emsesp - 000+00:00:20.051 D 126: [mqtt] Publishing topic emsesp/boiler_data (#8, retain=0, try#1, size 550, pid 1)
Dec 28 17:46:51 emsesp - 000+00:00:20.252 D 127: [mqtt] Publishing topic emsesp/boiler_data_ww (#9, retain=0, try#1, size 412, pid 1)
Dec 28 17:46:51 emsesp - 000+00:00:20.857 T 128: [emsesp] Boiler(0x08) -> All(0x00), UBAMonitorWW(0x34), data: 3C 01 37 80 00 21 00 00 01 00 00 7E A8 00 B5 73 00 80 00
Dec 28 17:46:52 emsesp - 000+00:00:21.081 T 129: [emsesp] Boiler(0x08) -> All(0x00), UBAMonitorFast(0x18), data: 28 01 8E 64 0F 09 02 25 C0 01 37 80 00 80 00 00 71 FF 2D 48 00 C8 00 02 00
Dec 28 17:46:52 emsesp - 000+00:00:21.355 T 130: [emsesp] Boiler(0x08) -> All(0x00), MC10Status(0x2A), data: 00 00 00 00 00 00 00 00 A8 00 A8 80 00 00 80 00 80 00 80 00 00
Dec 28 17:47:01 emsesp - 000+00:00:30.107 D 131: [mqtt] Publishing topic emsesp/boiler_data (#10, retain=0, try#1, size 550, pid 1)
Dec 28 17:47:01 emsesp - 000+00:00:30.308 D 132: [mqtt] Publishing topic emsesp/boiler_data_ww (#11, retain=0, try#1, size 412, pid 1)
Dec 28 17:47:01 emsesp - 000+00:00:30.748 T 133: [emsesp] Boiler(0x08) -> All(0x00), MC10Status(0x2A), data: 00 00 00 00 00 00 00 00 A8 00 A8 80 00 00 80 00 80 00 80 00 00
Dec 28 17:47:02 emsesp - 000+00:00:30.995 T 134: [emsesp] Boiler(0x08) -> All(0x00), UBAMonitorWW(0x34), data: 3C 01 37 80 00 21 00 00 01 00 00 7E A8 00 B5 73 00 80 00
Dec 28 17:47:02 emsesp - 000+00:00:31.213 T 135: [emsesp] Boiler(0x08) -> All(0x00), UBAMonitorFast(0x18), data: 28 01 8E 64 0F 09 02 25 C0 01 36 80 00 80 00 00 72 FF 2D 48 00 C8 00 02 00
Dec 28 17:47:11 emsesp - 000+00:00:40.163 D 136: [mqtt] Publishing topic emsesp/boiler_data (#12, retain=0, try#1, size 550, pid 1)
Dec 28 17:47:11 emsesp - 000+00:00:40.364 D 137: [mqtt] Publishing topic emsesp/boiler_data_ww (#13, retain=0, try#1, size 410, pid 1)
Dec 28 17:47:11 emsesp - 000+00:00:40.672 T 138: [emsesp] Boiler(0x08) -> All(0x00), UBAMonitorFast(0x18), data: 28 01 8C 64 0F 09 02 25 C0 01 36 80 00 80 00 00 73 FF 2D 48 00 C8 00 02 00
Dec 28 17:47:12 emsesp - 000+00:00:40.942 T 139: [emsesp] Boiler(0x08) -> All(0x00), MC10Status(0x2A), data: 00 00 00 00 00 00 00 00 A8 00 A8 80 00 00 80 00 80 00 80 00 00
Dec 28 17:47:12 emsesp - 000+00:00:41.160 T 140: [emsesp] Boiler(0x08) -> All(0x00), UBAMonitorWW(0x34), data: 3C 01 36 80 00 21 00 00 01 00 00 7E A8 00 B5 73 00 80 00
Dec 28 17:47:21 emsesp - 000+00:00:50.016 D 141: [mqtt] Publishing topic emsesp/boiler_data (#14, retain=0, try#1, size 550, pid 1)
Dec 28 17:47:21 emsesp - 000+00:00:50.217 D 142: [mqtt] Publishing topic emsesp/boiler_data_ww (#15, retain=0, try#1, size 408, pid 1)
Dec 28 17:47:21 emsesp - 000+00:00:50.677 T 143: [emsesp] Boiler(0x08) -> All(0x00), UBAMonitorWW(0x34), data: 3C 01 36 80 00 21 00 00 01 00 00 7E A8 00 B5 73 00 80 00
Dec 28 17:47:22 emsesp - 000+00:00:50.937 T 144: [emsesp] Boiler(0x08) -> All(0x00), UBAMonitorFast(0x18), data: 28 01 8F 64 0F 09 02 25 C0 01 35 80 00 80 00 00 71 FF 2D 48 00 C8 00 02 00
Dec 28 17:47:22 emsesp - 000+00:00:51.139 T 145: [emsesp] Boiler(0x08) -> All(0x00), MC10Status(0x2A), data: 00 00 00 00 00 00 00 00 A8 00 A8 80 00 00 80 00 80 00 80 00 00
Dec 28 17:47:29 emsesp - 000+00:00:58.661 T 146: [emsesp] Boiler(0x08) -> All(0x00), UBAMonitorFast(0x18), data: 28 01 90 64 0F 09 02 25 C0 01 35 80 00 80 00 00 73 FF 2D 48 00 C8 00 02 00
Dec 28 17:47:31 emsesp - 000+00:01:00.001 D 147: [emsesp] Fetching values for device ID 0x08
Dec 28 17:47:31 emsesp - 000+00:01:00.001 D 148: [telegram] Tx read request to device 0x08 for type ID 0x14
Dec 28 17:47:31 emsesp - 000+00:01:00.001 D 149: [telegram] Tx read request to device 0x08 for type ID 0x16
Dec 28 17:47:31 emsesp - 000+00:01:00.001 D 150: [telegram] Tx read request to device 0x08 for type ID 0x19
Dec 28 17:47:31 emsesp - 000+00:01:00.001 D 151: [telegram] Tx read request to device 0x08 for type ID 0x33
Dec 28 17:47:31 emsesp - 000+00:01:00.001 D 152: [emsesp] Fetching values for device ID 0x09
Dec 28 17:47:33 emsesp - 000+00:01:00.058 I 153: [mqtt] MQTT disconnected: TCP
Dec 28 17:47:33 emsesp - 000+00:01:00.131 D 154: [telegram] Sending read Tx [#16], telegram: 0B 88 14 00 20 E4
Dec 28 17:47:33 emsesp - 000+00:01:00.165 D 155: [emsesp] Last Tx read successful
Dec 28 17:47:33 emsesp - 000+00:01:00.165 T 156: [emsesp] Boiler(0x08) -> Me(0x0B), UBATotalUptime(0x14), data: 17 69 90
Dec 28 17:47:33 emsesp - 000+00:01:00.429 D 157: [telegram] Sending read Tx [#17], telegram: 0B 88 16 00 20 EC
The text was updated successfully, but these errors were encountered: