MQTT disconnects after ~3hrs on ESP32 about ems-esp32

[proddy]

@MichaelDvP I'll run some tests too.

One thing worth trying is whether it still crashes when the ESP32 is standalone and USB powered (only the heartbeat is sent)

[MichaelDvP]

Tried the usb-powered standalone in parallel, connected to a different mqtt broker, only heartbeat and syslog. But same disconnects (half a minute delayed to the other, but i think thats due to AP-settings. Standalone: AP until connect, other AP off.)

Standalone:

Aug 30 16:20:25 ems-esp2 - 000+00:00:00.000 I 0: [syslog] Log level set to INFO
Aug 30 16:20:25 ems-esp2 - 000+00:00:00.000 I 1: [emsesp] EMS Device library loaded with 70 records
Aug 30 16:20:25 ems-esp2 - 000+00:00:30.521 I 2: [mqtt] MQTT connected
Aug 30 19:40:56 ems-esp2 - 000+03:21:01.910 I 3: [mqtt] MQTT disconnected: TCP
Aug 30 19:40:57 ems-esp2 - 000+03:21:02.930 I 4: [mqtt] MQTT connected
Aug 30 23:01:28 ems-esp2 - 000+06:41:34.243 I 5: [mqtt] MQTT disconnected: TCP
Aug 30 23:01:29 ems-esp2 - 000+06:41:35.262 I 6: [mqtt] MQTT connected
Aug 31 02:22:00 ems-esp2 - 000+10:02:06.794 I 7: [mqtt] MQTT disconnected: TCP
Aug 31 02:22:01 ems-esp2 - 000+10:02:07.812 I 8: [mqtt] MQTT connected
Aug 31 05:42:33 ems-esp2 - 000+13:22:39.386 I 9: [mqtt] MQTT disconnected: TCP
Aug 31 05:42:34 ems-esp2 - 000+13:22:40.408 I 10: [mqtt] MQTT connected

Working

Aug 30 19:13:10 ems - 000+00:00:00.000 I 0: [syslog] Log level set to INFO
Aug 30 19:13:10 ems - 000+00:00:00.000 I 1: [emsesp] EMS Device library loaded with 70 records
Aug 30 19:13:10 ems - 000+00:00:00.000 E 2: [telegram] Rx: F5 B5 7D 55 FD FD 15 (CRC 15 != 94)
Aug 30 19:13:10 ems - 000+00:00:00.566 I 3: [mqtt] MQTT connected
Aug 30 19:13:14 ems - 000+00:00:04.513 E 4: [telegram] Last Tx Read operation failed after 3 retries. Ignoring request.
Aug 30 21:41:51 ems - 000+02:28:41.989 E 5: [telegram] Rx: 19 00 AF 00 00 DC 00 B5 (CRC B5 != BD)
Aug 30 22:33:42 ems - 000+03:20:32.630 I 6: [mqtt] MQTT disconnected: TCP
Aug 30 22:33:43 ems - 000+03:20:33.648 I 7: [mqtt] MQTT connected
Aug 30 22:41:11 ems - 000+03:28:01.251 E 8: [telegram] Rx: 19 00 AB 00 00 DD 00 BF (CRC BF != FF)
Aug 31 01:54:14 ems - 000+06:41:05.085 I 9: [mqtt] MQTT disconnected: TCP
Aug 31 01:54:15 ems - 000+06:41:06.103 I 10: [mqtt] MQTT connected
Aug 31 03:45:58 ems - 000+08:32:49.164 E 11: [telegram] Rx: BF 0C 08 00 34 00 0A 01 F9 7D 00 20 00 00 03 00 01 19 45 00 18 B8 1F (CRC 1F != 4D)
Aug 31 05:14:47 ems - 000+10:01:37.572 I 12: [mqtt] MQTT disconnected: TCP
Aug 31 05:14:48 ems - 000+10:01:38.591 I 13: [mqtt] MQTT connected

[proddy]

I'm running some tests too on an ESP32, USB powered and no EMS bus attached. I'll see if it croaks after 3hrs.
BTW MQTT is now part of the Espressif ESP32 core (https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/protocols/mqtt.html). Not that we should re-write everything, but nice to know.

[proddy]

Been running for 5hrs, no MQTT disconnects. ESP32 (https://docs.wemos.cc/en/latest/d32/d32.html) with firmware 2.0.1b1, USB power, no gateway/ems attached. Using mosquitto on Ubuntu.

[MichaelDvP]

Was syslog activated?
I tried also usb powered, no connection to EMS, with syslog debug. After your post i setup a mosquitto on a rapberry and connect mqtt to this. My Hardware is a MH-ET D1 Mini 32
Edit: and this test was with version v2b11 (before the cmd-build).

Starting on my default mqtt broker:

Aug 31 13:08:39 ems-esp2 - 000+00:00:00.000 I 0: [syslog] Log level set to DEBUG
Aug 31 13:08:39 ems-esp2 - 000+00:00:00.000 D 1: [telegram] Tx read request to device 0x08 for type ID 0x07
Aug 31 13:08:39 ems-esp2 - 000+00:00:04.221 D 2: [emsesp] WiFi Connected with IP=192.168.0.23, hostname=ems-esp2
Aug 31 13:08:39 ems-esp2 - 000+00:00:04.242 I 3: [mqtt] MQTT connected
Aug 31 13:08:39 ems-esp2 - 000+00:00:04.242 D 4: [mqtt] Publishing topic ems-esp2/heartbeat (#00, attempt emsesp/EMS-ESP#1, pid 1)
Aug 31 13:08:39 ems-esp2 - 000+00:00:04.443 D 5: [mqtt] Publishing topic ems-esp2/info (#01, attempt emsesp/EMS-ESP#1, pid 1)
Aug 31 13:08:40 ems-esp2 - 000+00:00:04.644 D 6: [mqtt] Publishing topic ems-esp2/status (#02, attempt emsesp/EMS-ESP#1, pid 1)
Aug 31 13:08:40 ems-esp2 - 000+00:00:04.845 D 7: [mqtt] Subscribing to topic: ems-esp2/cmd
Aug 31 13:09:36 ems-esp2 - 000+00:01:01.529 D 8: [mqtt] Publishing topic ems-esp2/heartbeat (#04, attempt emsesp/EMS-ESP#1, pid 1)
Aug 31 13:10:36 ems-esp2 - 000+00:02:01.628 D 9: [mqtt] Publishing topic ems-esp2/heartbeat (#05, attempt emsesp/EMS-ESP#1, pid 1)
...
Aug 31 14:27:36 ems-esp2 - 000+01:19:01.716 D 99: [mqtt] Publishing topic ems-esp2/heartbeat (#85, attempt emsesp/EMS-ESP#1, pid 1)

after 1h20 i change the mqtt setting to the mosquitto

Aug 31 14:28:16 ems-esp2 - 000+01:19:41.125 I 100: [mqtt] MQTT disconnected: TCP
Aug 31 14:28:16 ems-esp2 - 000+01:19:41.172 I 101: [mqtt] MQTT connected
Aug 31 14:28:16 ems-esp2 - 000+01:19:41.314 D 102: [mqtt] Publishing topic ems-esp2/info (#86, attempt emsesp/EMS-ESP#1, pid 1)
Aug 31 14:28:16 ems-esp2 - 000+01:19:41.515 D 103: [mqtt] Publishing topic ems-esp2/status (#87, attempt emsesp/EMS-ESP#1, pid 1)
Aug 31 14:28:16 ems-esp2 - 000+01:19:41.716 D 104: [mqtt] Subscribing to topic: ems-esp2/cmd
Aug 31 14:28:36 ems-esp2 - 000+01:20:01.616 D 105: [mqtt] Publishing topic ems-esp2/heartbeat (#89, attempt emsesp/EMS-ESP#1, pid 1)
...
Aug 31 16:27:36 ems-esp2 - 000+03:19:01.758 D 224: [mqtt] Publishing topic ems-esp2/heartbeat (#208, attempt emsesp/EMS-ESP#1, pid 1)
Aug 31 16:28:36 ems-esp2 - 000+03:20:01.857 D 225: [mqtt] Publishing topic ems-esp2/heartbeat (#209, attempt emsesp/EMS-ESP#1, pid 1)

and after 3h20 from start without doing something:

Aug 31 16:29:12 ems-esp2 - 000+03:20:37.028 I 226: [mqtt] MQTT disconnected: TCP
Aug 31 16:29:17 ems-esp2 - 000+03:20:42.086 I 227: [mqtt] MQTT connected
Aug 31 16:29:17 ems-esp2 - 000+03:20:42.086 D 228: [mqtt] Publishing topic ems-esp2/info (#210, attempt emsesp/EMS-ESP#1, pid 1)
Aug 31 16:29:17 ems-esp2 - 000+03:20:42.287 D 229: [mqtt] Publishing topic ems-esp2/status (#211, attempt emsesp/EMS-ESP#1, pid 1)
Aug 31 16:29:17 ems-esp2 - 000+03:20:42.488 D 230: [mqtt] Subscribing to topic: ems-esp2/cmd
Aug 31 16:29:36 ems-esp2 - 000+03:21:01.784 D 231: [mqtt] Publishing topic ems-esp2/heartbeat (#213, attempt emsesp/EMS-ESP#1, pid 1)
Aug 31 16:30:36 ems-esp2 - 000+03:22:01.883 D 232: [mqtt] Publishing topic ems-esp2/heartbeat (#214, attempt emsesp/EMS-ESP#1, pid 1)
Aug 31 16:31:36 ems-esp2 - 000+03:23:01.781 D 233: [mqtt] Publishing topic ems-esp2/heartbeat (#215, attempt emsesp/EMS-ESP#1, pid 1)
Aug 31 16:32:36 ems-esp2 - 000+03:24:01.880 D 234: [mqtt] Publishing topic ems-esp2/heartbeat (#216, attempt emsesp/EMS-ESP#1, pid 1)

The log from mosquitto:

1594380036: mosquitto version 1.5.7 starting
1594380036: Config loaded from /etc/mosquitto/mosquitto.conf.
1594380036: Opening ipv4 listen socket on port 1883.
1594380036: Opening ipv6 listen socket on port 1883.
1598876896: New connection from 192.168.0.23 on port 1883.
1598876896: New client connected from 192.168.0.23 as ems-esp2 (c1, k120).
1598878410: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1598880212: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1598882013: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1598883813: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1598884152: Socket error on client ems-esp2, disconnecting.
1598884157: New connection from 192.168.0.23 on port 1883.

I'll flash the precompiled travis-bin, set syslog off and test again.

[proddy]

I had syslog on. I'll run some more tests.

[MichaelDvP]

No luck with the travis bin. No EMS, no syslog, no NTP, QoS 0, no username/password, only mqtt-heartbeat to mosquitto on rasperry 3b (rasbian buster) and this raspberry runs nothing but mosquitto.
mosquitto.log:

1598886218: New client connected from 192.168.0.23 as ems-esp2 (c1, k120).
1598887416: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1598889216: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1598891017: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1598892818: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1598894620: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1598896420: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1598898221: Saving in-memory database to /var/lib/mosquitto/mosquitto.db.
1598898251: Socket error on client ems-esp2, disconnecting.
1598898252: New connection from 192.168.0.23 on port 1883.
1598898252: New client connected from 192.168.0.23 as ems-esp2 (c1, k120).

[proddy]

If the heartbeat is disabled (i.e. no Publishing) does the same thing happen?

I think we need to create a new branch with a stripped-down version of EMS-ESP with nothing except the Mqtt library and the heartbeat. No web, console etc.

[proddy]

Also Pablo2048 has an updated version of the AsyncMQTT Library with the PRs 156, 157, 159 and 180 applied. Also he modified it to use the TCP_FLAG_WRITE_COPY and says it solves a lot of the problems he was seeing. Worth a try?

async-mqtt-client (1).zip

He also suggests to modify the ESPAsyncTCP library with correct 'cansend' version from here: https://github.com/glmnet/ESPAsyncTCP/tree/patch-cansend

[MichaelDvP]

Worth a try?
async-mqtt-client (1).zip

Tried, get some warnings and errors when compiling, but can fix it. Now 3h20 later i got the same reconnect-error as before. I go back to standard lib.

He also suggests to modify the ESPAsyncTCP library

This is esp8266 only, but 8266 is working for me without any error.

I give up searching for the cause, the reconnects do not really bother. Maybe with the next core update they disappear.

[proddy]

Then lets close this and re-open if others have similar issues. In my testing I wasn't able to reproduce the MQTT disconnects