search

xoseperez / espurna

Home automation firmware for ESP8266-based devices
http://tinkerman.cat
GNU General Public License v3.0
3k stars 638 forks source link

MQTT disconnects randomly #715

Closed richlock1 closed 6 years ago

richlock1 commented 6 years ago

First of all thanks for this very great project. The best framework for ESP8266. But I have an instability issue. The main problem that sometimes the MQTT conection is disconected and the reconnection takes 1 minutes to 15 minutes. The frequency is 20 times/day. During reconnect phase I miss data. The mosquitto broker is always available as from the logs other clients have sucessfull publishes. The problem comes on Wemos D1 mini board with DHT22 sensor and with DS18B20 temperature sensor and also on Electrodragon 2 ch relay board without any sensor. I saw the same behaviour with version 1.12.3 and now with 1.12.4. On both card telnet is enabled, on Wemos thingspeak feature is on and I saw missing data on their web interface. Earlier I used an free RTOS based fw on the wemos, and there was not missing thingspeak data, so I guess the hardwares are OK.

I logged the electrodragon board and here I show, that the MQTT disconnects random period. During the same time I also pingged that device, and that is always working. Sometimes the ping fails with 1 per minute frequency, but I think the issue is somewhere else as MQTT reconnect takes in bad case 15 minutes.

Here is an example when it takes 4 minutes to reconnect again.

[067340] [INIT] ESPURNA 1.12.4 [067340] [INIT] xose.perez@gmail.com [067340] [INIT] http://tinkerman.cat

[067340] [INIT] CPU chip ID: 0x21C176 [067342] [INIT] CPU frequency: 80 MHz [067345] [INIT] SDK version: 1.5.3(aec24ac9) [067349] [INIT] Core version: 2_3_0 [067352] [INIT] Core revision: [067355] [067 [067360] [INIT] Flash speed: 40000000 Hz [067363] [INIT] Flash mode: DIO [067366] [067367] [INIT] Flash sector size: 4096 bytes [067371] [INIT] Flash size (CHIP): 4194304 bytes [067375] [INIT] Flash size (SDK): 4194304 bytes / 1024 sectors [067381] [INIT] Firmware size: 465120 bytes / 114 sectors [067387] [INIT] OTA size: 26 654 sectors [067392] [INIT] SPIFFS size: 0 bytes / 0 sectors [067398] [INIT] EEPROM size: 4096 bytes / 1 sectors [067404] [INIT] Empty space: 16384 bytes / 4 sectors [067409] [067410] [INIT] BUILD_FLAGS: [067413] [INIT] BOARD: ELECTRODRAGON_WIFI_IOT [067417] [INIT] SUPPORT: ALEXA BROKER DEBUG_SERIAL DEBUG_TELNET DOMOTICZ HOMEASSISTANT MDNS_SERVER NTP SCHEDULER TELNET TERMINAL THINGSPEAK WEB

[067429] External System [067434] [INIT] Settings size: 1268 bytes [067438] [INIT] Free heap: 25064 bytes [067441] [INIT] Power: 3156 mV [067443] [INIT] Power saving delay value: 10 ms [067448] [067448] [WIFI] MODE STA ------------------------------------- [067454] [WIFI] SSID DIGI-UW83 [067457] [WIFI] IP 192.168.0.31 [067460] [WIFI] MAC DC:4F:22:21:C1:76 [067463] [WIFI] GW 192.18.0.1 [067466] [WIFI] DNS 192.168.0.1 [067469] [WIFI] MASK 255.255.255.0 [067472] [WIFI] HOST ESPURNA_21C176 [067475] [WIFI] BSSID 34:B3:54:BB:45:28 [067479] [WIFI] CH 2 [067481] [WIFI] RSSI -64 [067483] [WIFI] ---------------------------------------------- [067489] +OK [307855] [MQTT] Sending ESPURNA_21C176/app => ESPURNA (PID 1) [307856] [MQTT] Sending ESPURNA_21C176/version => 1.12.4 (PID 1) [307856] [MQTT] Sending ESPURNA_21C176/host => ESPURNA_21C176 (PID 1) [307862] [MQTT] Sending ESPURNA_21C176/ip => 192.168.0.31 (PID 1) [307867] [MQTT] Sending ESPURNA_21C176/mac => DC:4F:22:21:C1:76 (PID 1) [307874] [MQTT] Sending ESPURNA_21C176/rssi => -65 (PID 1) [307879] [MQTT] Sending ESPURNA_21C176/uptime => 307 (PID 1) [307884] [MQTT] Sending ESPURNA_21C176/datetime => 2018-03-19 21:02:03 (PID 1) [307891] [MQTT] Sending ESPURNA_21C176/freeheap => 25040 (PID 1) [307897] [MQTT] Sending ESPURNA_21C176/relay/0 => 0 (PID 1) [307902] [MQTT] Sending ESPURNA_21C176/relay/NA_21C176/vcc => 3148 (PID 1) [307912] [MQTT] Sending ESPURNA_21C176/status => 1 (PID 1) [607864] [MQTT] Sending ESPURNA_21C176/app => ESPURNA (PID 1) [607864] [MQTT] Sending ESPURNA_21C176/version => 1.12.4 (PID 1) [607865] [MQTT] Sending ESPURNA_21C176/host => ESPURNA_21C176 (PID 1) [607870] [MQTT] Sending ESPURNA_21C176/ip => 192.168.0.31 (PID 1) [607876] [MQTT] Sending ESPURNA_21C176/mac => DC:4F:22:21:C1:76 (PID 1) [607882] [MQTT] Sending ESPURNA_21C176/rssi => -64 (PID 1) [607887] [MQTT] Sending ESPURNA_21C176/uptime => 607 (PID 1) [607893] [MQTT] Sending ESPURNA_21C176/datetime => 2018-03-19 21:07:03 (PID 1) [607899] [T] Sending ESPURNA_21C176/freeheap => 25040 (PID 1) [607905] [MQTT] Sending ESPURNA_21C176/relay/0 => 0 (PID 1) [607910] [MQTT] Sending ESPURNA_21C176/relay/1 => 0 (PID 1) [607916] [MQTT] Sending ESPURNA_21C176/vcc => 3148 (PID 1) [607920] [MQTT] Sending ESPURNA_21C176/status => 1 (PID 1) [907868] [MQTT] Sending ESPURNA_21C176/app => ESPURNA (PID 1) [907869] [MQTT] Sending ESPURNA_21C176/version => 1.12.4 (PID 1) [907869] [MQTT] Sending ESPURNA_21C176/host => ESPURNA_21C176 (PID 1) [907875] [MQTT] Sending ESPURNA_21C176/ip => 192.168.0.31 (PID 1) [907880] [MQTT] Sending ESPURNA_21C176/mac => DC:4F:22:21:C1:76 (PID 1) [907887] [MQTT] Sending ESPURNA_21C176/rssi => -65 (PID 1) [907892] [MQTT] Sending ESPURNA_21C176/uptime => 907 (PID 1) [907897] [MQTT] Sending ESPURNA_21C176/datetime => 2018-03-19 21:12:03 (PID 1) [907904] [MQTT] Sending ESPURNA_21C176/freeheap => 24872 (PID 1) [907909] [MQTT] Sending ESPURNA_21C176/relay/0 => 0 (PID 1) [907915] [MQTT] Sending ESPURNA_21C176/relay/1 => 0 (PID 1) [907920] [MQTT] Sending ESPURNA_21C176/vcc => 3157 (PID 1) [907925] [MQTT] SendinNA_21C176/status => 1 (PID 1) ............. [2018-03-20 02:27:03] [807074] [MQTT] Sendin[930031] [NTP] Time: 2018-03-20 02:29:05 [2018-03-20 02:32:03] [107022] [MQTT] Sending ESPURNA_21C176/app => ESPURNA (PID 1) [2018-03-20 02:32:03] [107023] [MQTT] Sending ESPURNA_21C176/version => 1.12.4 (PID 1) [2018-03-20 02:32:03] [107023] [MQTT] Sending ESPURNA_21C176/host => ESPURNA_21C176 (PID 1) [2018-03-20 02:32:03] [107029] [MQTT] Sending ESPURNA_21C176/ip => 192.168.0.31 (PID 1) [2018-03-20 02:32:03] [107034] [MQTT] Sending ESPURNA_21C176/mac => DC:4F:22:21:C1:76 (PID 1) [2018-03-20 02:32:03] [107041] [MQTT] Sending ESPURNA_21C176/rssi => -70 (PID 1) [2018-03-20 02:32:03] [107046] [MQTT] Sendin> 20107 (PID 1) [2018-03-20 02:32:03] [107051] [MQTT] 107058] [MQTT] Sending ESPURNA_21C176/freeheap => 24760 (PID 1) [2018-03-20 02:32:03] 0 (PID 1) [2018-03-20 02:32:03] [107069] [MQTT] Sending ESPURNA_21C176/relay/1 => 0 (PID 1) [2018-03-20 02:32:03] [107075] [MQTT] Sending ESPURNA_21C176/vcc => 3149 (PID 1) [2018-03-20 02:32:03] [107079] [MQTT] Sending ESPURNA[407032] [MQTT] Sending ESPURNA_21C176/app => ESPURNA (PID 1) [2018-03-20 02:37:03] [407032] [MQTT] Sending ESPURNA_21C176/version => 1.12.4 (PID 1) [2018-03-20 02:37:03] [407033] [MQTT] Sending ESPURNA_21C176/host => ESPURNA_21C176 (PID 1) [2018-03-20 02:37:03] [407038] [MQTT] Sending ESPURNA_21C176/ip => 192.168.0.31 (PID 1) [2018-03-20 02:37:03] [407044] [MQTT] Sending ESPURNA_21C176/mac => DC:4F:22:21:C1:76 (PID 1) [2018-03-20 02:37:03] [407050] [MQTT] Sending ESPURNA_21C176/rssi => -68 (PID 1) [2018-03-20 02:37:03] [407055] [MQTT] SendinURNA_21C176/uptime => 20407 (PID 1) [2018-03-20 02:37:03] [407061] [MQTT] Sending ESPURNA_21C176/datetime => 2018-03-20 02:37:02 (PID 1) [2018-03-20 02:37:03] [407068] [MQTT] Sending ESPURNA_21C176/freeheap => 24760 (PID 1) [2018-03-20 02:37:03] [407073] [MQrelay/0 => 0 (PID 1) [2018-03-20 02:37:03] [407078] [MQTT] Sending ESPURNA_21C176/relay/1 => 0 (PID 1) [2018-03-20 02:37:03] [407084] [MQTT] Sending ESPURNA_21C176/vcc => 3148 (PID 1) [2018-03-20 02:37:03] [407089] [MQTT] Sending ESPURNA_21C176/status => 1 (PID 1) [2018-03-20 02:38:26] [490749] [MQTT] TCP Disconnected [2018-03-20 02:38:26] [490749] [MQTT] Disconnected! [2018-03-20 02:38:26] [490756] [MQTT] Connecting to broker at 192.168.0.2:1883 [2018-03-20 02:38:26] [490756] [MQTT] Client ID: GarzsKapu [2018-03-20 02:38:26] [490757] [MQTT] QoS: 0 [2018-03-20 02:38:26] [490757] [MQTT] Retain flag: 1 [2018-03-20 02:38:26] [490758] [MQTT] Keepalive time: 30s [2018-03-20 02:38:26] [490761] [MQTT] Will topic: ESPURNA_21C176/status [2018-03-20 02:38:35] [499748] [MQTT] TCP Disconnected [2018-03-20 02:38:35] [499748] [MQTT] Disconnected! [2018-03-20 02:38:36] [500759] [MQTT] Connecting to broker at 192.168.0.2:1883 [2018-03-20 02:38:36] [500759] [MQTT] Client ID: GarzsKapu [2018-03-20 02:38:36] [500759] [MQTT] QoS: 0 [2018-03-20 02:38:36] [500760] [MQTT] Retain flag: 1 [2018-03-20 02:38:36] [500761] [MQTT] Keepalive time: 30s [2018-03-20 02:38:36] [500764] [MQTT] Will topic: ESPURNA_21C176/status [2018-03-20 02:38:44] [508748] [MQTT] TCP Disconnected [2018-03-20 02:38:44] [508748] [MQTT] Disconnected! [2018-03-20 02:38:51] [515763] [MQTT] Connecting to broker at 192.168.0.2:1883 [2018-03-20 02:38:51] [515763] [MQTT] Client ID: GarzsKapu [2018-03-20 02:38:51] [515763] [MQTT] QoS: 0 [2018-03-20 02:38:51] [515763] [MQTT] Retain flag: 1 [2018-03-20 02:38:51] [515764] [MQTT] Keepalive time: 30s [2018-03-20 02:38:51] [515768] [MQTT] Will topic: ESPURNA_21C176/status [2018-03-20 02:38:59] [523749] [MQTT] TCP Disconnected [2018-03-20 02:38:59] [523749] [MQTT] Disconnected! [2018-03-20 02:39:11] [535763] [MQTT] Connecting to broker at 192.168.0.2:1883 [2018-03-20 02:39:11] [535763] [MQTT] Client ID: GarzsKapu [2018-03-20 02:39:11] [535764] [MQTT] QoS: 0 [2018-03-20 02:39:11] [535764] [MQTT] Retain flag: 1 [2018-03-20 02:39:11] [535765] [MQTT] Keepalive time: 30s [2018-03-20 02:39:11] [535768] [MQTT] Will topic: ESPURNA_21C176/status [2018-03-20 02:39:20] [544748] [MQTT] TCP Disconnected [2018-03-20 02:39:20] [544748] [MQTT] Disconnected! [2018-03-20 02:39:36] [560766] [MQTT] Connecting to broker at 192.168.0.2:1883 [2018-03-20 02:39:36] [560766] [MQTT] Client ID: GarzsKapu [2018-03-20 02:39:36] [560766] [MQTT] QoS: 0 [2018-03-20 02:39:36] [560766] [MQTT] Retain flag: 1 [2018-03-20 02:39:36] [560767] [MQTT] Keepalive time: 30s [2018-03-20 02:39:36] [560771] [MQTT] Will topic: ESPURNA_21C176/status [2018-03-20 02:39:44] [568748] [MQTT] TCP Disconnected [2018-03-20 02:39:44] [568748] [MQTT] Disconnected! [2018-03-20 02:40:06] [590767] [MQTT] Connecting to broker at 192.168.0.2:1883 [2018-03-20 02:40:06] [590767] [MQTT] Client ID: GarzsKapu [2018-03-20 02:40:06] [590767] [MQTT] QoS: 0 [2018-03-20 02:40:06] [590767] [MQTT] Retain flag: 1 [2018-03-20 02:40:06] [590769] [MQTT] Keepalive time: 30s [2018-03-20 02:40:06] [590772] [MQTT] Will topic: ESPURNA_21C176/status [2018-03-20 02:40:14] [598749] [MQTT] TCP Disconnected [2018-03-20 02:40:14] [598749] [MQTT] Disconnected! [2018-03-20 02:40:41] [625774] [MQTT] Connecting to broker at 192.168.0.2:1883 [2018-03-20 02:40:41] [625775] [MQTT] Client ID: GarzsKapu [2018-03-20 02:40:41] [625775] [MQTT] QoS: 0 [2018-03-20 02:40:41] [625775] [MQTT] Retain flag: 1 [2018-03-20 02:40:41] [625776] [MQTT] Keepalive time: 30s [2018-03-20 02:40:41] [625779] [MQTT] Will topic: ESPURNA_21C176/status [2018-03-20 02:40:50] [634748] [MQTT] TCP Disconnected [2018-03-20 02:40:50] [634748] [MQTT] Disconnected! [2018-03-20 02:41:21] [665784] [MQTT] Connecting to broker at 192.168.0.2:1883 [2018-03-20 02:41:21] [665784] [MQTT] Client ID: GarzsKapu [2018-03-20 02:41:21] [665784] [MQTT] QoS: 0 [2018-03-20 02:41:21] [665784] [MQTT] Retain flag: 1 [2018-03-20 02:41:21] [665786] [MQTT] Keepalive time: 30s [2018-03-20 02:41:21] [665789] [MQTT] Will topic: ESPURNA_21C176/status [2018-03-20 02:41:29] [673748] [MQTT] TCP Disconnected [2018-03-20 02:41:29] [673749] [MQTT] Disconnected! [2018-03-20 02:42:03] [707038] [MAIN] Uptime: 20707 seconds [2018-03-20 02:42:03] [707038] [MAIN] Free heap: 21560 bytes [2018-03-20 02:42:03] [707038] [MAIN] Power: 3148 mV [2018-03-20 02:42:03] [707039] [MAIN] Time: 2018-03-20 02:42:02 [2018-03-20 02:42:06] [710791] [MQTT] Connecting to broker at 192.168.0.2:1883 [2018-03-20 02:42:06] [710792] [MQTT] Client ID: GarzsKapu [2018-03-20 02:42:06] [710792] [MQTT] QoS: 0 [2018-03-20 02:42:06] [710792] [MQTT] Retain flag: 1 [2018-03-20 02:42:06] [710793] [MQTT] Keepalive time: 30s [2018-03-20 02:42:06] [710796] [MQTT] Will topic: ESPURNA_21C176/status [2018-03-20 02:42:06] [710808] [MQTT] Connected! [2018-03-20 02:42:06] [710808] [MQTT] Unsubscribing to # (PID 1) [2018-03-20 02:42:06] [710809] [MQTT] Subscribing to ESPURNA_21C176/relay/+/set (PID 2) [2018-03-20 02:42:06] [710813] [MQTT] Subscribing to ESPURNA_21C176/led/+/set (PID 3) [2018-03-20 02:42:06] [710818] [MQTT] Subscribing to ESPURNA_21C176/action/set (PID 4) [2018-03-20 02:42:06] [710826] [MQTT] Sending ESPURNA_21C176/app => ESPURNA (PID 1) [2018-03-20 02:42:06] [710829] [MQTT] Sending ESPURNA_21C176/version => 1.12.4 (PID 1) [2018-03-20 02:42:06] [710835] [MQTT] Sending ESPURNA_21C176/host => ESPURNA_21C176 (PID 1) [2018-03-20 02:42:06] [710841] [MQTT] Sending ESPURNA_21C176/ip => 192.168.0.31 (PID 1) [2018-03-20 02:42:06] [710847] [MQTT] Sending ESPURNA_21C176/mac => DC:4F:22:21:C1:76 (PID 1) [2018-03-20 02:42:06] [710853] [MQTT] Sending ESPURNA_21C176/rssi => -67 (PID 1) [2018-03-20 02:42:06] [710858] [MQTT] Sending ESPURNA_21C176/uptime => 20710 (PID 1) [2018-03-20 02:42:06] [710863] [MQTT] Sending ESPURNA_21C176/datetime => 2018-03-20 02:42:05 (PID 1) [2018-03-20 02:42:06] [710870] [MQTT] Sending ESPURNA_21C176/freeheap => 19776 (PID 1) [2018-03-20 02:42:06] [710876] [MQTT] Sending ESPURNA_21C176/relay/0 => 0 (PID 1) [2018-03-20 02:42:06] [710881] [MQTT] Sending ESPURNA_21C176/relay/1 => 0 (PID 1) [2018-03-20 02:42:06] [710887] [MQTT] Sending ESPURNA_21C176/vcc => 3147 (PID 1) [2018-03-20 02:42:06] [710891] [MQTT] Sending ESPURNA_21C176/status => 1 (PID 1) [2018-03-20 02:42:06] [710902] [MQTT] Subscribe ACK for PID 2 [2018-03-20 02:42:07] [710902] [MQTT] Subscribe ACK for PID 3 [2018-03-20 02:42:07] [710903] [MQTT] Subscribe ACK for PID 4 [2018-03-20 02:47:06] [010832] [MQTT] Sending ESPURNA_21C176/app => ESPURNA (PID 1) [2018-03-20 02:47:06] [010833] [MQTT] Sending ESPURNA_21C176/version => 1.12.4 (PID 1) [2018-03-20 02:47:06] [010833] [MQTT] Sending ESPURNA_21C176/host => ESPURNA_21C176 (PID 1) [2018-03-20 02:47:06] [010839] [MQTT] Sending ESPURNA_21C176/ip => 192.168.0.31 (PID 1) [2018-03-20 02:47:06] [010844] [MQTT] Sending ESPURNA_21C176/mac => DC:4F:22:21:C1:76 (PID 1) [2018-03-20 02:47:06] [010851] [MQTT] Sing ESPURNA_21C176/rssi => -68 (PID 1) [2018-03-20 02:47:06] [010856] [MQTT] Sending ESPURNA_21C176/uptime => 21010 (PID 1) [2018-03-20 02:47:06] [010861] [MQTT] Sending ESPURNA_21C176/datetime => 2018-03-20 02:47:05 (PID 1) [2018-03-20 02:47:06] [010868] [MQTT] Sending ESPURNA_21C176/freeheap => 24760 (PID 1) [2018-03-20 02:47:06] [010874] [MQTT] Sending ESPURNA_21C176/relay/0 => 0 (PID 1) [2018-03-20 02:47:06] [010879] [MQTT] Sending ESPURNA_21C176/relay/1 => 0 (PID 1) [2018-03-20 02:47:06] [010885] [MQTT] Sending ESPURNA_21C176/vcc => 3149 (PID 1) [2018-03-20 02:47:06] [010889] [MQTT] Sending ESPURNA_21C176/status => 1 (PID 1)

Ping info during disconnect phase:

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 3.120/3.120/3.120/0.000 ms

  1. márc. 20., kedd, 02:38:24 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=2.18 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 2.181/2.181/2.181/0.000 ms

  1. márc. 20., kedd, 02:38:25 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=2.02 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 2.026/2.026/2.026/0.000 ms

  1. márc. 20., kedd, 02:38:26 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=3.54 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 3.547/3.547/3.547/0.000 ms

  1. márc. 20., kedd, 02:38:27 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=8.78 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 8.787/8.787/8.787/0.000 ms

  1. márc. 20., kedd, 02:38:28 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=4.55 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 4.551/4.551/4.551/0.000 ms

  1. márc. 20., kedd, 02:38:29 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=3.24 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 3.241/3.241/3.241/0.000 ms

  1. márc. 20., kedd, 02:38:30 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=3.08 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 3.084/3.084/3.084/0.000 ms

  1. márc. 20., kedd, 02:38:32 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=3.76 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 3.765/3.765/3.765/0.000 ms

  1. márc. 20., kedd, 02:38:33 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=2.45 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 2.451/2.451/2.451/0.000 ms

  1. márc. 20., kedd, 02:38:34 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=2.17 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 2.179/2.179/2.179/0.000 ms

  1. márc. 20., kedd, 02:38:35 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=2.37 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 2.372/2.372/2.372/0.000 ms

  1. márc. 20., kedd, 02:38:36 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=3.15 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 3.154/3.154/3.154/0.000 ms

  1. márc. 20., kedd, 02:38:37 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=1.96 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 1.968/1.968/1.968/0.000 ms

  1. márc. 20., kedd, 02:38:38 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=2.16 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 2.167/2.167/2.167/0.000 ms

  1. márc. 20., kedd, 02:38:39 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=1.86 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 1.861/1.861/1.861/0.000 ms

  1. márc. 20., kedd, 02:38:40 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data.

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 0 received, 100% packet loss, time 0ms

  1. márc. 20., kedd, 02:38:51 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data.

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 0 received, 100% packet loss, time 0ms

  1. márc. 20., kedd, 02:39:02 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=810 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 810.910/810.910/810.910/0.000 ms

  1. márc. 20., kedd, 02:39:03 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=4.09 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 4.093/4.093/4.093/0.000 ms

  1. márc. 20., kedd, 02:39:04 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=1.83 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 1.832/1.832/1.832/0.000 ms

  1. márc. 20., kedd, 02:39:05 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=106 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 106.702/106.702/106.702/0.000 ms

  1. márc. 20., kedd, 02:39:07 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=1.80 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 1.806/1.806/1.806/0.000 ms

  1. márc. 20., kedd, 02:39:08 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=1.75 ms

--- 192.168.0.31 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 1.757/1.757/1.757/0.000 ms

  1. márc. 20., kedd, 02:39:09 CET PING 192.168.0.31 (192.168.0.31) 56(84) bytes of data. 64 bytes from 192.168.0.31: icmp_seq=1 ttl=127 time=849 ms

..............

Coud you give me some hints what to set, what to debug more? Thanks.

xoseperez commented 6 years ago

What do the logs say on the mosquitto side?

richlock1 commented 6 years ago

It says:

Mar 20 02:36:41 raspberrypi mosquitto[531]: Received PINGREQ from GarzsKapu Mar 20 02:36:41 raspberrypi mosquitto[531]: Sending PINGRESP to GarzsKapu ... Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PINGREQ from GarzsKapu Mar 20 02:37:02 raspberrypi mosquitto[531]: Sending PINGRESP to GarzsKapu Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/app', ... (7 bytes)) Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/version', ... (6 bytes)) Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/host', ... (14 bytes)) Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/ip', ... (12 bytes)) Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/mac', ... (17 bytes)) Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/rssi', ... (3 bytes)) Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/uptime', ... (5 bytes)) Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/datetime', ... (19 bytes)) Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/freeheap', ... (5 bytes)) Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/relay/0', ... (1 bytes)) Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/relay/1', ... (1 bytes)) Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/vcc', ... (4 bytes)) Mar 20 02:37:02 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/status', ... (1 bytes)) ... Mar 20 02:37:26 raspberrypi mosquitto[531]: Received PINGREQ from GarzsKapu Mar 20 02:37:26 raspberrypi mosquitto[531]: Sending PINGRESP to GarzsKapu ...

Mar 20 02:38:11 raspberrypi mosquitto[531]: Client GarzsKapu has exceeded timeout, disconnecting. ..... Mar 20 02:42:06 raspberrypi mosquitto[531]: New client connected from 192.168.0.31 as GarzsKapu (c0, k30). Mar 20 02:42:06 raspberrypi mosquitto[531]: Sending CONNACK to GarzsKapu (0) Mar 20 02:42:06 raspberrypi mosquitto[531]: Received UNSUBSCRIBE from GarzsKapu Mar 20 02:42:06 raspberrypi mosquitto[531]: #011# Mar 20 02:42:06 raspberrypi mosquitto[531]: GarzsKapu # Mar 20 02:42:06 raspberrypi mosquitto[531]: Received SUBSCRIBE from GarzsKapu Mar 20 02:42:06 raspberrypi mosquitto[531]: #011ESPURNA_21C176/relay/+/set (QoS 0) Mar 20 02:42:06 raspberrypi mosquitto[531]: GarzsKapu 0 ESPURNA_21C176/relay/+/set Mar 20 02:42:06 raspberrypi mosquitto[531]: Sending SUBACK to GarzsKapu Mar 20 02:42:06 raspberrypi mosquitto[531]: Received SUBSCRIBE from GarzsKapu Mar 20 02:42:06 raspberrypi mosquitto[531]: #011ESPURNA_21C176/led/+/set (QoS 0) Mar 20 02:42:06 raspberrypi mosquitto[531]: GarzsKapu 0 ESPURNA_21C176/led/+/set Mar 20 02:42:06 raspberrypi mosquitto[531]: Sending SUBACK to GarzsKapu Mar 20 02:42:06 raspberrypi mosquitto[531]: Received SUBSCRIBE from GarzsKapu Mar 20 02:42:06 raspberrypi mosquitto[531]: #011ESPURNA_21C176/action/set (QoS 0) Mar 20 02:42:06 raspberrypi mosquitto[531]: GarzsKapu 0 ESPURNA_21C176/action/set Mar 20 02:42:06 raspberrypi mosquitto[531]: Sending SUBACK to GarzsKapu Mar 20 02:42:06 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/app', ... (7 bytes)) Mar 20 02:42:06 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/version', ... (6 bytes)) Mar 20 02:42:06 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/host', ... (14 bytes)) Mar 20 02:42:06 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/ip', ... (12 bytes)) Mar 20 02:42:06 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/mac', ... (17 bytes)) Mar 20 02:42:06 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/rssi', ... (3 bytes)) Mar 20 02:42:06 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/uptime', ... (5 bytes)) Mar 20 02:42:06 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/datetime', ... (19 bytes)) Mar 20 02:42:06 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/freeheap', ... (5 bytes)) Mar 20 02:42:06 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/relay/0', ... (1 bytes)) Mar 20 02:42:06 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/relay/1', ... (1 bytes)) Mar 20 02:42:06 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/vcc', ... (4 bytes)) Mar 20 02:42:06 raspberrypi mosquitto[531]: Received PUBLISH from GarzsKapu (d0, q0, r1, m0, 'ESPURNA_21C176/status', ... (1 bytes)) .... Mar 20 02:42:29 raspberrypi mosquitto[531]: Received PINGREQ from GarzsKapu Mar 20 02:42:29 raspberrypi mosquitto[531]: Sending PINGRESP to GarzsKapu .... Mar 20 02:42:50 raspberrypi mosquitto[531]: Received PINGREQ from GarzsKapu Mar 20 02:42:50 raspberrypi mosquitto[531]: Sending PINGRESP to GarzsKapu .... Mar 20 02:43:11 raspberrypi mosquitto[531]: Received PINGREQ from GarzsKapu Mar 20 02:43:11 raspberrypi mosquitto[531]: Sending PINGRESP to GarzsKapu

xoseperez commented 6 years ago

Looks like the client is not pinging the broker inside the keepalive time... or the ping gets lost (network issue?). Try increasing the value. Actually. something over 300s (5 minutes) will probably do the trick since that's the heartbeat interval.

richlock1 commented 6 years ago

I made wireshark capture. electroDragonMqttDisconnet.zip

It seems there is a lot of re-transmission when the problem happens and both client and server takes much time inside this cycle.

Good idea to increase ping timeout, less chance to get into this re-transmission situation, but I think the problem still be there. I will try.

xoseperez commented 6 years ago

Any update on this?

richlock1 commented 6 years ago

Made the suggested timeout increment to 300. No problem at all on several devices since several days. So it solved the problem. One note: setting the MQTT keepalive to 255 actually makes ping interval 180 secs according to mosquitto logs. Making 300 actually results 213 secs in reality.

mcspr commented 6 years ago

@richlock1 that's going to be fixed in 1.12.5 - https://github.com/xoseperez/espurna/commit/6ef4d130c789a1f8e649e66f0118e35f44fd568f

xoseperez commented 6 years ago

@richlock1 Can you try with latest 1.12.5? If the connection is stable and the keepalive interval is right I think we might close this issue.

richlock1 commented 6 years ago

I will try in the next couple of weeks, but I think it will be stable if you set big enough keepalive interval.

richlock1 commented 6 years ago

I have tried with 1.12.6 on electrodragon relay board. No problem at all. I used 300 secs keepalive interval. Thanks.

xoseperez commented 6 years ago

Good. I'm increasing the MQTT keepalive interval to 300 by default. Staged for release.

arihantdaga commented 6 years ago

@xoseperez But setting keepAlive to 300 is also quiet unsafe, because the broker will not know if the device goes offline for atleast 150Secods i think.. right ? And it will show the device reachable even if it is actually not....

richlock1 commented 6 years ago

As I saw in the logs this setting affects publish timeout, which is 300 secs in our example, where Espurna reports its sensor values. The pingreq MQTT messages times are around 3.5 mins. It may be calculated some other way.