Home Assistant Status Unavailable due to MQTT Topic Connection: Lost

[fraknu]

The Problem

Since 16.0 RC1 the MQTT Topic Connection is "Connection lost" ~1-10 sec after transmitting the values.
Because of that HA says Status is unavailable.

Version

Release: 16.0.0-RC2 (Commit: 3708698+)

Logfile

[1d08h38m22s] 2024-10-06T08:57:58 <ERR> [MQTT IF] Other event id:
[1d08h38m47s] 2024-10-06T08:58:23 <ERR> [MQTT IF] Other event id:
[1d08h39m07s] 2024-10-06T08:58:44 <ERR> [MQTT IF] Other event id:
[1d08h39m40s] 2024-10-06T08:59:16 <ERR> [MQTT IF] Other event id:
[1d08h40m15s] 2024-10-06T08:59:51 <ERR> [MQTT IF] Other event id:
[1d08h40m40s] 2024-10-06T09:00:17 <ERR> [MQTT IF] Other event id:
[1d08h40m55s] 2024-10-06T09:00:32 <ERR> [POSTPROC] main: Raw: 044.8476, Value: , Status: Rate too high - Read: 44.8476 - Pre: 43.8302 - Rate: 1.0174
[1d08h41m23s] 2024-10-06T09:00:59 <ERR> [MQTT IF] Other event id:
[1d08h41m40s] 2024-10-06T09:01:17 <ERR> [MQTT IF] Other event id:
[1d08h42m01s] 2024-10-06T09:01:37 <ERR> [MQTT IF] Other event id:
[1d08h42m41s] 2024-10-06T09:02:17 <ERR> [MQTT IF] Other event id:
[1d08h43m24s] 2024-10-06T09:03:00 <ERR> [MQTT IF] Other event id:
[1d08h44m01s] 2024-10-06T09:03:38 <ERR> [MQTT IF] Other event id:
[1d08h44m26s] 2024-10-06T09:04:03 <ERR> [MQTT IF] Other event id:
[1d08h45m02s] 2024-10-06T09:04:38 <ERR> [MQTT IF] Other event id:
[1d08h45m27s] 2024-10-06T09:05:03 <ERR> [MQTT IF] Other event id:
[1d08h45m55s] 2024-10-06T09:05:32 <ERR> [POSTPROC] main: Raw: 044.8498, Value: , Status: Rate too high - Read: 44.8498 - Pre: 43.8302 - Rate: 1.0196
[1d08h46m02s] 2024-10-06T09:05:39 <ERR> [MQTT IF] Other event id:
[1d08h46m35s] 2024-10-06T09:06:11 <ERR> [MQTT IF] Other event id:
[1d08h47m10s] 2024-10-06T09:06:47 <ERR> [MQTT IF] Other event id:
[1d08h47m48s] 2024-10-06T09:07:24 <ERR> [MQTT IF] Other event id:
[1d08h48m28s] 2024-10-06T09:08:05 <ERR> [MQTT IF] Other event id:
[1d08h48m56s] 2024-10-06T09:08:32 <ERR> [MQTT IF] Other event id:
[1d08h49m36s] 2024-10-06T09:09:12 <ERR> [MQTT IF] Other event id:
[1d08h50m03s] 2024-10-06T09:09:40 <ERR> [MQTT IF] Other event id:
[1d08h50m44s] 2024-10-06T09:10:20 <ERR> [MQTT IF] Other event id:
[1d08h51m11s] 2024-10-06T09:10:48 <ERR> [MQTT IF] Other event id:
[1d08h51m44s] 2024-10-06T09:11:20 <ERR> [MQTT IF] Other event id:
[1d08h52m19s] 2024-10-06T09:11:56 <ERR> [MQTT IF] Other event id:
[1d08h52m52s] 2024-10-06T09:12:28 <ERR> [MQTT IF] Other event id:
[1d08h53m27s] 2024-10-06T09:13:04 <ERR> [MQTT IF] Other event id:
[1d08h53m52s] 2024-10-06T09:13:29 <ERR> [MQTT IF] Other event id:
[1d08h54m35s] 2024-10-06T09:14:12 <ERR> [MQTT IF] Other event id:
[1d08h54m53s] 2024-10-06T09:14:29 <ERR> [OTA FILE] File sending failed!
[1d08h55m00s] 2024-10-06T09:14:37 <ERR> [MQTT IF] Other event id:
[1d08h55m38s] 2024-10-06T09:15:14 <ERR> [MQTT IF] Other event id:
[1d08h56m13s] 2024-10-06T09:15:50 <ERR> [MQTT IF] Other event id:
[1d08h56m46s] 2024-10-06T09:16:22 <ERR> [MQTT IF] Other event id:
[1d08h57m21s] 2024-10-06T09:16:58 <ERR> [MQTT IF] Other event id:
[1d08h57m46s] 2024-10-06T09:17:23 <ERR> [MQTT IF] Other event id:
[1d08h58m22s] 2024-10-06T09:17:58 <ERR> [MQTT IF] Other event id:
[1d08h58m54s] 2024-10-06T09:18:30 <ERR> [MQTT IF] Other event id:
[1d08h59m29s] 2024-10-06T09:19:06 <ERR> [MQTT IF] Other event id:
[1d08h59m47s] 2024-10-06T09:19:23 <ERR> [MQTT IF] Other event id:
[1d09h00m07s] 2024-10-06T09:19:44 <ERR> [MQTT IF] Other event id:
[1d09h00m25s] 2024-10-06T09:20:01 <ERR> [MQTT IF] Other event id:
[1d09h00m55s] 2024-10-06T09:20:32 <ERR> [POSTPROC] main: Raw: 044.8516, Value: , Status: Rate too high - Read: 44.8516 - Pre: 43.8515 - Rate: 1.0001
[1d09h01m08s] 2024-10-06T09:20:44 <ERR> [MQTT IF] Other event id:

Expected Behavior

Connection-Topic not being lost

Screenshots

Screenshots are in the Description of the problem, see above.

Additional Context

First occured in 16.0 RC1

[caco3]

Are you using TLS for MQTT?

There seem to be a communication error with the MQTT broker.
Can you find more information in the log of the MQTT broker?

I improved the error logging, please give it a try:

1. select the most top build in https://github.com/jomjol/AI-on-the-edge-device/actions?query=branch%3Alog-mqtt-connection.error-id
2. scroll down and use the AI-on-the-edge-device__update__* for an OTA-Update.

[caco3]

Maybe related: #3289

[fraknu]

Yes, #3289 may be related.

Regarding 1: no TLS is in use

Regarding 2: I will give it a try when I am at home in 1 h.

Thanks!

BR Frank

[fraknu]

Hello again,

MQTT Log is empty. I am using eclipse-mosquitto:latest in docker on SynologyNAS DS1520+ DSM 7.2.1-69057 Update 5:

Here is the Log from Build Build and Pack #3116: Commit [4e1df4a]

[0d00h00m00s] 2024-10-06T18:44:02 <INF> [MAIN] =================================================
[0d00h00m00s] 2024-10-06T18:44:02 <INF> [MAIN] ==================== Start ======================
[0d00h00m00s] 2024-10-06T18:44:02 <INF> [MAIN] =================================================
[0d00h00m00s] 2024-10-06T18:44:02 <INF> [MAIN] PSRAM size: 8388608 byte (8MB / 64MBit)
[0d00h00m00s] 2024-10-06T18:44:02 <INF> [MAIN] Total heap: 4382911 byte
[0d00h00m02s] 2024-10-06T18:44:04 <INF> [MAIN] Camera info: PID: 0x26, VER: 0x42, MIDL: 0x7f, MIDH: 0xa2
[0d00h00m02s] 2024-10-06T18:44:04 <INF> [SDCARD] Basic R/W check started...
[0d00h00m02s] 2024-10-06T18:44:04 <INF> [SDCARD] Basic R/W check successful
[0d00h00m02s] 2024-10-06T18:44:04 <INF> [SNTP] TimeServer not defined, using default: pool.ntp.org
[0d00h00m02s] 2024-10-06T18:44:04 <INF> [SNTP] Configuring NTP Client...
[0d00h00m02s] 2024-10-06T20:44:04 <INF> [SNTP] Time zone set to CET-1CEST,M3.5.0,M10.5.0/3
[0d00h00m02s] 2024-10-06T20:44:04 <INF> [SNTP] time zone: +0200 Delta to UTC: 7200 seconds
[0d00h00m02s] 2024-10-06T20:44:05 <INF> [SNTP] Time is already set: 2024-10-06 20:44:05
[0d00h00m02s] 2024-10-06T20:44:05 <INF> [MAIN] CPU frequency: 160 MHz
[0d00h00m03s] 2024-10-06T20:44:05 <INF> [OTA] Start update process (/sdcard/firmware/AI-on-the-edge-device__update__log-mqtt-connection.error-id_(4e1df4a).zip)
[0d00h00m03s] 2024-10-06T20:44:05 <INF> [OTA] File: /sdcard/firmware/AI-on-the-edge-device__update__log-mqtt-connection.error-id_(4e1df4a).zip Filetype: ZIP
[0d00h00m03s] 2024-10-06T20:44:05 <INF> [OTA FILE] Files to be extracted: 73
[0d00h00m44s] 2024-10-06T20:44:47 <INF> [OTA] Files unzipped.
[0d00h00m44s] 2024-10-06T20:44:47 <INF> [OTA] Found firmware.bin
[0d00h01m01s] 2024-10-06T20:45:04 <INF> [OTA] Trigger reboot due to firmware update
[0d00h01m01s] 2024-10-06T20:45:04 <WRN> [OTA] Reboot in 5sec
[0d00h00m00s] 2024-10-06T18:45:11 <INF> [MAIN] =================================================
[0d00h00m00s] 2024-10-06T18:45:11 <INF> [MAIN] ==================== Start ======================
[0d00h00m00s] 2024-10-06T18:45:11 <INF> [MAIN] =================================================
[0d00h00m00s] 2024-10-06T18:45:11 <INF> [MAIN] PSRAM size: 8388608 byte (8MB / 64MBit)
[0d00h00m00s] 2024-10-06T18:45:11 <INF> [MAIN] Total heap: 4382911 byte
[0d00h00m02s] 2024-10-06T18:45:13 <INF> [MAIN] Camera info: PID: 0x26, VER: 0x42, MIDL: 0x7f, MIDH: 0xa2
[0d00h00m02s] 2024-10-06T18:45:13 <INF> [SDCARD] Basic R/W check started...
[0d00h00m02s] 2024-10-06T18:45:13 <INF> [SDCARD] Basic R/W check successful
[0d00h00m02s] 2024-10-06T18:45:13 <INF> [SNTP] TimeServer not defined, using default: pool.ntp.org
[0d00h00m02s] 2024-10-06T18:45:13 <INF> [SNTP] Configuring NTP Client...
[0d00h00m02s] 2024-10-06T20:45:13 <INF> [SNTP] Time zone set to CET-1CEST,M3.5.0,M10.5.0/3
[0d00h00m02s] 2024-10-06T20:45:13 <INF> [SNTP] time zone: +0200 Delta to UTC: 7200 seconds
[0d00h00m02s] 2024-10-06T20:45:13 <INF> [SNTP] Time is already set: 2024-10-06 20:45:13
[0d00h00m02s] 2024-10-06T20:45:13 <INF> [MAIN] CPU frequency: 160 MHz
[0d00h00m03s] 2024-10-06T20:45:14 <INF> [SDCARD] Folder/file presence check started...
[0d00h00m03s] 2024-10-06T20:45:14 <INF> [SDCARD] Folder/file presence check successful
[0d00h00m03s] 2024-10-06T20:45:14 <INF> [MAIN] Development-Branch: log-mqtt-connection.error-id (Commit: 4e1df4a+), Date/Time: 2024-10-06 14:50, Web UI: Development-Branch: log-mqtt-connection.error-id (Commit: 4e1df4a+)
[0d00h00m03s] 2024-10-06T20:45:14 <INF> [MAIN] Reset reason: Via esp_restart
[0d00h00m03s] 2024-10-06T20:45:14 <INF> [WLANINI] SSID: Franks FRITZ!Box
[0d00h00m03s] 2024-10-06T20:45:14 <INF> [WLANINI] Password: XXXXXXXX
[0d00h00m03s] 2024-10-06T20:45:14 <INF> [WLANINI] RSSIThreshold: -75
[0d00h00m03s] 2024-10-06T20:45:14 <INF> [MAIN] WLAN config loaded, init WIFI...
[0d00h00m03s] 2024-10-06T20:45:14 <INF> [WIFI] Automatic interface config --> Use DHCP service
[0d00h00m03s] 2024-10-06T20:45:14 <INF> [WIFI] Set hostname to: watermeter
[0d00h00m03s] 2024-10-06T20:45:14 <INF> [WIFI] Init successful
[0d00h00m05s] 2024-10-06T20:45:17 <INF> [WIFI] Connected to: Franks FRITZ!Box, RSSI: -72
[0d00h00m06s] 2024-10-06T20:45:18 <INF> [WIFI] Assigned IP: 192.168.178.16
[0d00h00m07s] 2024-10-06T20:45:18 <INF> [SNTP] Time is synced with NTP Server pool.ntp.org: 2024-10-06 20:45:18
[0d00h00m09s] 2024-10-06T20:45:20 <INF> [MAIN] Device info: CPU cores: 2, Chip revision: 301
[0d00h00m09s] 2024-10-06T20:45:20 <INF> [MAIN] SD card info: Name: SH32G, Capacity: 30436MB, Free: 30391MB
[0d00h00m11s] 2024-10-06T20:45:22 <INF> [MAIN] Initialization completed successfully
[0d00h00m13s] 2024-10-06T20:45:24 <INF> [TFLITE] Trying to load the model. If it crashes here, it ist most likely due to a corrupted model!
[0d00h00m14s] 2024-10-06T20:45:25 <INF> [TFLITE] Trying to load the model. If it crashes here, it ist most likely due to a corrupted model!
[0d00h00m14s] 2024-10-06T20:45:25 <INF> [LOGFILE] Set log level to ERROR
[0d00h00m27s] 2024-10-06T20:45:38 <ERR> [MQTT IF] Connection Refused with unknown event id:0
[0d00h00m59s] 2024-10-06T20:46:10 <ERR> [MQTT IF] Connection Refused with unknown event id:0
[0d00h01m34s] 2024-10-06T20:46:45 <ERR> [MQTT IF] Connection Refused with unknown event id:0
[0d00h02m00s] 2024-10-06T20:47:11 <ERR> [MQTT IF] Connection Refused with unknown event id:0
[0d00h02m35s] 2024-10-06T20:47:46 <ERR> [MQTT IF] Connection Refused with unknown event id:0
…and so on

During the time the same behaviour:

Hope it helps.

Thanks,

Frank

[fraknu]

I turned on DEBUG LOG Level, please see the attached log:

[0d00h03m23s] 2024-10-06T21:16:05 <WRN> [OTA] Reboot in 5sec
[0d00h00m00s] 2024-10-06T19:16:16 <INF> [MAIN] =================================================
[0d00h00m00s] 2024-10-06T19:16:16 <INF> [MAIN] ==================== Start ======================
[0d00h00m00s] 2024-10-06T19:16:16 <INF> [MAIN] =================================================
[0d00h00m00s] 2024-10-06T19:16:16 <INF> [MAIN] PSRAM size: 8388608 byte (8MB / 64MBit)
[0d00h00m00s] 2024-10-06T19:16:16 <INF> [MAIN] Total heap: 4382911 byte
[0d00h00m02s] 2024-10-06T19:16:18 <INF> [MAIN] Camera info: PID: 0x26, VER: 0x42, MIDL: 0x7f, MIDH: 0xa2
[0d00h00m02s] 2024-10-06T19:16:18 <INF> [SDCARD] Basic R/W check started...
[0d00h00m02s] 2024-10-06T19:16:18 <INF> [SDCARD] Basic R/W check successful
[0d00h00m02s] 2024-10-06T19:16:18 <INF> [SNTP] TimeServer not defined, using default: pool.ntp.org
[0d00h00m02s] 2024-10-06T19:16:18 <INF> [SNTP] Configuring NTP Client...
[0d00h00m02s] 2024-10-06T21:16:18 <INF> [SNTP] Time zone set to CET-1CEST,M3.5.0,M10.5.0/3
[0d00h00m02s] 2024-10-06T21:16:18 <INF> [SNTP] time zone: +0200 Delta to UTC: 7200 seconds
[0d00h00m02s] 2024-10-06T21:16:18 <INF> [SNTP] Time is already set: 2024-10-06 21:16:18
[0d00h00m02s] 2024-10-06T21:16:18 <INF> [MAIN] CPU frequency: 160 MHz
[0d00h00m03s] 2024-10-06T21:16:19 <INF> [SDCARD] Folder/file presence check started...
[0d00h00m03s] 2024-10-06T21:16:19 <INF> [SDCARD] Folder/file presence check successful
[0d00h00m03s] 2024-10-06T21:16:19 <INF> [MAIN] Development-Branch: log-mqtt-connection.error-id (Commit: 4e1df4a+), Date/Time: 2024-10-06 14:50, Web UI: Development-Branch: log-mqtt-connection.error-id (Commit: 4e1df4a+)
[0d00h00m03s] 2024-10-06T21:16:19 <INF> [MAIN] Reset reason: Via esp_restart
[0d00h00m03s] 2024-10-06T21:16:19 <INF> [WLANINI] SSID: Franks FRITZ!Box
[0d00h00m03s] 2024-10-06T21:16:19 <INF> [WLANINI] Password: XXXXXXXX
[0d00h00m03s] 2024-10-06T21:16:19 <INF> [WLANINI] RSSIThreshold: -75
[0d00h00m03s] 2024-10-06T21:16:19 <INF> [MAIN] WLAN config loaded, init WIFI...
[0d00h00m03s] 2024-10-06T21:16:19 <INF> [WIFI] Automatic interface config --> Use DHCP service
[0d00h00m03s] 2024-10-06T21:16:19 <INF> [WIFI] Set hostname to: watermeter
[0d00h00m03s] 2024-10-06T21:16:19 <INF> [WIFI] Init successful
[0d00h00m06s] 2024-10-06T21:16:22 <INF> [WIFI] Connected to: Franks FRITZ!Box, RSSI: -71
[0d00h00m07s] 2024-10-06T21:16:23 <INF> [WIFI] Assigned IP: 192.168.178.16
[0d00h00m23s] 2024-10-06T21:16:39 <INF> [MAIN] Device info: CPU cores: 2, Chip revision: 301
[0d00h00m23s] 2024-10-06T21:16:39 <INF> [MAIN] SD card info: Name: SH32G, Capacity: 30436MB, Free: 30391MB
[0d00h00m25s] 2024-10-06T21:16:41 <INF> [MAIN] Initialization completed successfully
[0d00h00m28s] 2024-10-06T21:16:44 <INF> [TFLITE] Trying to load the model. If it crashes here, it ist most likely due to a corrupted model!
[0d00h00m28s] 2024-10-06T21:16:44 <INF> [TFLITE] Trying to load the model. If it crashes here, it ist most likely due to a corrupted model!
[0d00h00m28s] 2024-10-06T21:16:44 <INF> [LOGFILE] Set log level to DEBUG
[0d00h00m28s] 2024-10-06T21:16:44 <DBG> [MQTT] Digitizer interval is 5.0 minutes => setting MQTT LWT timeout to 12.5 minutes.
[0d00h00m28s] 2024-10-06T21:16:44 <DBG> [MQTT IF] URI: mqtt://192.168.178.2:1883, clientname: watermeter, user: , password: XXXXXXXX, maintopic: watermeterhaus, last-will-topic: watermeterhaus/connection, keepAlive: 750, RetainFlag: 0
[0d00h00m28s] 2024-10-06T21:16:44 <INF> [MQTT IF] Init
[0d00h00m28s] 2024-10-06T21:16:44 <INF> [MQTT IF] Client started, waiting for established connection...
[0d00h00m28s] 2024-10-06T21:16:44 <INF> [MAINCTRL] Starting Flow...
[0d00h00m28s] 2024-10-06T21:16:44 <DBG> [MAINCTRL] ----------------------------------------------------------------
[0d00h00m28s] 2024-10-06T21:16:44 <INF> [MAINCTRL] Round #1 started
[0d00h00m28s] 2024-10-06T21:16:44 <DBG> [FLOWCTRL] Status: Take Image (21:16:44)
[0d00h00m28s] 2024-10-06T21:16:44 <DBG> [MQTT IF] Publish skipped. Client not initalized or not connected. (topic: watermeterhaus/status)
[0d00h00m28s] 2024-10-06T21:16:44 <DBG> [PSRAM] Init shared memory for step 'Take Image' (STBI buffers)
[0d00h00m28s] 2024-10-06T21:16:44 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h00m28s] 2024-10-06T21:16:44 <DBG> [MQTT IF] topic watermeterhaus/ctrl/flow_start subscribe successful, msg_id=1
[0d00h00m28s] 2024-10-06T21:16:44 <DBG> [MQTT IF] topic watermeterhaus/ctrl/set_prevalue subscribe successful, msg_id=2
[0d00h00m31s] 2024-10-06T21:16:47 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h00m35s] 2024-10-06T21:16:51 <DBG> [PSRAM] Allocated 18456 bytes in PSRAM for 'STBI'
[0d00h00m35s] 2024-10-06T21:16:51 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m35s] 2024-10-06T21:16:51 <DBG> [PSRAM] Allocated 18456 bytes in PSRAM for 'STBI'
[0d00h00m35s] 2024-10-06T21:16:51 <DBG> [PSRAM] Allocating memory (307215 bytes) for STBI (use shared memory in PSRAM)...
[0d00h00m35s] 2024-10-06T21:16:51 <DBG> [PSRAM] Allocating memory (153615 bytes) for STBI (use shared memory in PSRAM)...
[0d00h00m35s] 2024-10-06T21:16:51 <DBG> [PSRAM] Allocating memory (153615 bytes) for STBI (use shared memory in PSRAM)...
[0d00h00m35s] 2024-10-06T21:16:51 <DBG> [PSRAM] Allocated 643 bytes in PSRAM for 'STBI'
[0d00h00m35s] 2024-10-06T21:16:51 <DBG> [PSRAM] Allocated 643 bytes in PSRAM for 'STBI'
[0d00h00m35s] 2024-10-06T21:16:51 <DBG> [PSRAM] Allocated 643 bytes in PSRAM for 'STBI'
[0d00h00m35s] 2024-10-06T21:16:51 <DBG> [PSRAM] Allocating memory (921601 bytes) for STBI (use shared memory in PSRAM)...
[0d00h00m36s] 2024-10-06T21:16:52 <INF> [SNTP] Time is synced with NTP Server pool.ntp.org: 2024-10-06 21:16:52
[0d00h00m36s] 2024-10-06T21:16:52 <DBG> [PSRAM] Part of shared memory used for STBI (PSRAM, part of shared memory) is free again
[0d00h00m36s] 2024-10-06T21:16:52 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m36s] 2024-10-06T21:16:52 <DBG> [PSRAM] Part of shared memory used for STBI (PSRAM, part of shared memory) is free again
[0d00h00m36s] 2024-10-06T21:16:52 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m36s] 2024-10-06T21:16:52 <DBG> [PSRAM] Part of shared memory used for STBI (PSRAM, part of shared memory) is free again
[0d00h00m36s] 2024-10-06T21:16:52 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m36s] 2024-10-06T21:16:52 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m38s] 2024-10-06T21:16:54 <DBG> [C IMG BASIS] Not freeing (zwImage as there was never PSRAM allocated for it)
[0d00h00m38s] 2024-10-06T21:16:54 <DBG> [PSRAM] Deinit shared memory for step 'Take Image' (STBI buffers)
[0d00h00m38s] 2024-10-06T21:16:54 <DBG> [FLOWCTRL] Status: Aligning (21:16:54)
[0d00h00m38s] 2024-10-06T21:16:54 <DBG> [MQTT IF] Published topic: watermeterhaus/status, content: Aligning (msg_id=3)
[0d00h00m38s] 2024-10-06T21:16:54 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h00m39s] 2024-10-06T21:16:55 <DBG> [PSRAM] Allocating tmpImage (921600 bytes, use shared memory in PSRAM)...
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Allocated 18456 bytes in PSRAM for 'STBI'
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Allocated 18456 bytes in PSRAM for 'STBI'
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Allocated 3855 bytes in PSRAM for 'STBI'
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Allocated 975 bytes in PSRAM for 'STBI'
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Allocated 975 bytes in PSRAM for 'STBI'
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Allocated 46 bytes in PSRAM for 'STBI'
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Allocated 46 bytes in PSRAM for 'STBI'
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Allocated 46 bytes in PSRAM for 'STBI'
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Allocated 8515 bytes in PSRAM for 'STBI'
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m42s] 2024-10-06T21:16:58 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m43s] 2024-10-06T21:16:59 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h00m44s] 2024-10-06T21:17:00 <ERR> [MQTT IF] Connection Refused with unknown event id:0
[0d00h00m44s] 2024-10-06T21:17:00 <WRN> [MQTT IF] Disconnected, trying to reconnect
[0d00h00m47s] 2024-10-06T21:17:03 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h00m50s] 2024-10-06T21:17:06 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h00m51s] 2024-10-06T21:17:06 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Allocated 18456 bytes in PSRAM for 'STBI'
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Allocated 18456 bytes in PSRAM for 'STBI'
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Allocated 4111 bytes in PSRAM for 'STBI'
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Allocated 1039 bytes in PSRAM for 'STBI'
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Allocated 1039 bytes in PSRAM for 'STBI'
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Allocated 67 bytes in PSRAM for 'STBI'
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Allocated 67 bytes in PSRAM for 'STBI'
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Allocated 67 bytes in PSRAM for 'STBI'
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Allocated 11329 bytes in PSRAM for 'STBI'
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m51s] 2024-10-06T21:17:07 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m53s] 2024-10-06T21:17:09 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h00m56s] 2024-10-06T21:17:12 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h00m58s] 2024-10-06T21:17:14 <DBG> [PSRAM] Freeing memory in PSRAM used for 'STBI'...
[0d00h00m58s] 2024-10-06T21:17:14 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h00m59s] 2024-10-06T21:17:15 <INF> [MQTT IF] Connected to broker
[0d00h00m59s] 2024-10-06T21:17:15 <DBG> [MQTT IF] topic watermeterhaus/ctrl/flow_start subscribe successful, msg_id=4
[0d00h00m59s] 2024-10-06T21:17:15 <DBG> [MQTT IF] topic watermeterhaus/ctrl/set_prevalue subscribe successful, msg_id=5
[0d00h01m01s] 2024-10-06T21:17:17 <ERR> [MQTT IF] Connection Refused with unknown event id:0
[0d00h01m01s] 2024-10-06T21:17:17 <WRN> [MQTT IF] Disconnected, trying to reconnect
[0d00h01m01s] 2024-10-06T21:17:17 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [PSRAM] Shared memory used for tmpImage (PSRAM, part of shared memory) is free again
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [FLOWCTRL] Status: Digitization of ROIs (21:17:21)
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [MQTT IF] Publish skipped. Client not initalized or not connected. (topic: watermeterhaus/status)
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [CNN] doFlow after alignment
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [PSRAM] Allocating Tensor Arena (819200 bytes, use shared memory in PSRAM)...
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [TFLITE] CTfLiteClass::LoadModel
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [TFLITE] CTfLiteClass::ReadFileToModel: /sdcard/config/dig-cont_0700_s3_q.tflite
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [TFLITE] Loading Model /sdcard/config/dig-cont_0700_s3_q.tflite /size: 315504 bytes...
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [PSRAM] Allocating Model memory (1363148 bytes, use shared memory in PSRAM)...
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [TFLITE] CTfLiteClass::MakeAllocate
[0d00h01m05s] 2024-10-06T21:17:21 <INF> [TFLITE] Trying to load the model. If it crashes here, it ist most likely due to a corrupted model!
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [CNN] Processing Number 'main'
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [CNN] ROI #0 - TfLite
[0d00h01m05s] 2024-10-06T21:17:21 <DBG> [CNN] CNN Type: DoubleHyprid10
[0d00h01m08s] 2024-10-06T21:17:24 <DBG> [CNN] After Invoke
[0d00h01m08s] 2024-10-06T21:17:24 <DBG> [CNN] _num (p, m): 0 1 9 _val (p, m): 0.996094 0.003906 0.000000 result: 0.003906 _fit: 1.000000
[0d00h01m08s] 2024-10-06T21:17:24 <DBG> [CNN] ROI #1 - TfLite
[0d00h01m08s] 2024-10-06T21:17:24 <DBG> [CNN] CNN Type: DoubleHyprid10
[0d00h01m08s] 2024-10-06T21:17:24 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h01m11s] 2024-10-06T21:17:27 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h01m11s] 2024-10-06T21:17:27 <DBG> [CNN] After Invoke
[0d00h01m11s] 2024-10-06T21:17:27 <DBG> [CNN] _num (p, m): 4 5 3 _val (p, m): 0.992188 0.000000 0.007812 result: 3.992188 _fit: 1.000000
[0d00h01m11s] 2024-10-06T21:17:27 <DBG> [CNN] ROI #2 - TfLite
[0d00h01m11s] 2024-10-06T21:17:27 <DBG> [CNN] CNN Type: DoubleHyprid10
[0d00h01m13s] 2024-10-06T21:17:29 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h01m14s] 2024-10-06T21:17:30 <DBG> [CNN] After Invoke
[0d00h01m14s] 2024-10-06T21:17:30 <DBG> [CNN] _num (p, m): 4 5 3 _val (p, m): 0.976562 0.023438 0.000000 result: 4.023438 _fit: 1.000000
[0d00h01m14s] 2024-10-06T21:17:30 <DBG> [PSRAM] Shared memory used for Tensor Arena and model (PSRAM, part of shared memory) is free again
[0d00h01m14s] 2024-10-06T21:17:30 <DBG> [FLOWCTRL] Status: Digitization of ROIs (21:17:30)
[0d00h01m14s] 2024-10-06T21:17:30 <DBG> [MQTT IF] Publish skipped. Client not initalized or not connected. (topic: watermeterhaus/status)
[0d00h01m14s] 2024-10-06T21:17:30 <DBG> [CNN] doFlow after alignment
[0d00h01m14s] 2024-10-06T21:17:30 <DBG> [PSRAM] Allocating Tensor Arena (819200 bytes, use shared memory in PSRAM)...
[0d00h01m14s] 2024-10-06T21:17:30 <DBG> [TFLITE] CTfLiteClass::LoadModel
[0d00h01m14s] 2024-10-06T21:17:30 <DBG> [TFLITE] CTfLiteClass::ReadFileToModel: /sdcard/config/ana-cont_1300_s2.tflite
[0d00h01m14s] 2024-10-06T21:17:30 <DBG> [TFLITE] Loading Model /sdcard/config/ana-cont_1300_s2.tflite /size: 183756 bytes...
[0d00h01m14s] 2024-10-06T21:17:30 <DBG> [PSRAM] Allocating Model memory (1363148 bytes, use shared memory in PSRAM)...
[0d00h01m14s] 2024-10-06T21:17:30 <DBG> [TFLITE] CTfLiteClass::MakeAllocate
[0d00h01m15s] 2024-10-06T21:17:30 <INF> [TFLITE] Trying to load the model. If it crashes here, it ist most likely due to a corrupted model!
[0d00h01m15s] 2024-10-06T21:17:30 <DBG> [CNN] Processing Number 'main'
[0d00h01m15s] 2024-10-06T21:17:31 <DBG> [CNN] ROI #0 - TfLite
[0d00h01m15s] 2024-10-06T21:17:31 <DBG> [CNN] CNN Type: Analogue
[0d00h01m15s] 2024-10-06T21:17:31 <DBG> [CNN] After Invoke
[0d00h01m15s] 2024-10-06T21:17:31 <DBG> [CNN] ROI #1 - TfLite
[0d00h01m15s] 2024-10-06T21:17:31 <DBG> [CNN] CNN Type: Analogue
[0d00h01m16s] 2024-10-06T21:17:32 <INF> [MQTT IF] Connected to broker
[0d00h01m16s] 2024-10-06T21:17:32 <DBG> [MQTT IF] topic watermeterhaus/ctrl/flow_start subscribe successful, msg_id=6
[0d00h01m16s] 2024-10-06T21:17:32 <DBG> [MQTT IF] topic watermeterhaus/ctrl/set_prevalue subscribe successful, msg_id=7
[0d00h01m16s] 2024-10-06T21:17:32 <DBG> [CNN] After Invoke
[0d00h01m16s] 2024-10-06T21:17:32 <DBG> [CNN] ROI #2 - TfLite
[0d00h01m16s] 2024-10-06T21:17:32 <DBG> [CNN] CNN Type: Analogue
[0d00h01m17s] 2024-10-06T21:17:33 <DBG> [CNN] After Invoke
[0d00h01m17s] 2024-10-06T21:17:33 <DBG> [CNN] ROI #3 - TfLite
[0d00h01m17s] 2024-10-06T21:17:33 <DBG> [CNN] CNN Type: Analogue
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] After Invoke
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [PSRAM] Shared memory used for Tensor Arena and model (PSRAM, part of shared memory) is free again
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [FLOWCTRL] Status: Post-Processing (21:17:34)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: watermeterhaus/status, content: Post-Processing (msg_id=8)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] getReadout _analog=0, _extendedResolution=0, prev=-1
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] PointerEvalAnalogNew - No predecessor - Result = 2 number: 2.278733 numeral_preceder = -1 Analog_error = 3
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] PointerEvalAnalogNew - number ambiguous, correction upwards - result = 2 number: 2.150443 numeral_preceder = 2 Analog_error = 3
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] PointerEvalAnalogNew - number ambiguous, correction upwards - result = 2 number: 2.101405 numeral_preceder = 2 Analog_error = 3
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] PointerEvalAnalogNew - number ambiguous, correction upwards - result = 1 number: 1.080284 numeral_preceder = 2 Analog_error = 3
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] getReadout _analog=0, _extendedResolution=0, prev=1
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] PointerEvalAnalogToDigitNew - NO digit Uncertainty - Result = 4 number: 4.023438 numeral_preceder = 1.080284
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] PointerEvalHybridNew - Analog predecessor, evaluation over PointerEvalAnalogNew = 4 number: 4.023438 number_of_predecessors = 1.080284 eval_predecessors = 1 Digit_Uncertainty = 0.200000
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] getReadout(dig100) prev=4
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] PointerEvalHybridNew - NO analogue predecessor, no change of digits, as pre-decimal point far enough away = 4 number: 3.992188 number_of_predecessors = 4.023438 eval_predecessors = 4 Digit_Uncertainty = 0.200000
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] getReadout#PointerEvalHybridNew()= 4
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] getReadout#result= 44
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] PointerEvalHybridNew - NO analogue predecessor, no change of digits, as pre-decimal point far enough away = 0 number: 0.003906 number_of_predecessors = 3.992188 eval_predecessors = 4 Digit_Uncertainty = 0.200000
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] getReadout#PointerEvalHybridNew()= 0
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [CNN] getReadout#result= 044
[0d00h01m18s] 2024-10-06T21:17:34 <INF> [POSTPROC] main: Raw: 044.1222, Value: 44.1222, Status: no error
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [FLOWCTRL] Status: Sending MQTT (21:17:34)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: watermeterhaus/status, content: Sending MQTT (msg_id=9)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT SERVER] Publishing Homeassistant Discovery topics (Meter Type: 'water', Value Unit: 'm³' , Rate Unit: 'm³/h') ...
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/uptime/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-uptime","object_id": "waterm.. (msg_id=10)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/MAC/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-MAC","object_id": "watermete.. (msg_id=11)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/fwVersion/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-fwVersion","object_id": "wat.. (msg_id=12)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/hostname/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-hostname","object_id": "wate.. (msg_id=13)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/freeMem/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-freeMem","object_id": "water.. (msg_id=14)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/wifiRSSI/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-wifiRSSI","object_id": "wate.. (msg_id=15)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/CPUtemp/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-CPUtemp","object_id": "water.. (msg_id=16)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/interval/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-interval","object_id": "wate.. (msg_id=17)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/IP/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-IP","object_id": "watermeter.. (msg_id=18)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/status/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-status","object_id": "waterm.. (msg_id=19)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/value/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-value","object_id": "waterme.. (msg_id=20)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/raw/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-raw","object_id": "watermete.. (msg_id=21)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/error/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-error","object_id": "waterme.. (msg_id=22)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/rate_per_time_unit/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-rate_per_time_unit","object_.. (msg_id=23)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/rate_per_digitization_round/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-rate_per_digitization_round".. (msg_id=24)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/timestamp/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-timestamp","object_id": "wat.. (msg_id=25)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/sensor/watermeterhaus/json/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-json","object_id": "watermet.. (msg_id=26)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: homeassistant/binary_sensor/watermeterhaus/problem/config, content: {"~": "watermeterhaus","unique_id": "watermeterhaus-problem","object_id": "water.. (msg_id=27)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT SERVER] Successfully published all Homeassistant Discovery MQTT topics
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT SERVER] Int. Heap Usage before Publishing Homeassistand Discovery Topics: 100171, after: 100031, delta: 140, lowest free: 85703
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT SERVER] Publishing static MQTT topics...
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: watermeterhaus/fwVersion, content: Development-Branch: log-mqtt-connection.error-id (Commit: 4e1df4a+) (msg_id=28)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: watermeterhaus/MAC, content: A0:B7:65:50:65:28 (msg_id=29)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: watermeterhaus/IP, content: 192.168.178.16 (msg_id=30)
[0d00h01m18s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: watermeterhaus/hostname, content: watermeter (msg_id=31)
[0d00h01m19s] 2024-10-06T21:17:34 <DBG> [MQTT IF] Published topic: watermeterhaus/interval, content: 5.0 (msg_id=32)
[0d00h01m19s] 2024-10-06T21:17:34 <DBG> [MQTT SERVER] Successfully published all Static MQTT topics
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT SERVER] Int. Heap Usage before Publishing Static Topics: 100031, after: 99807, delta: 224, lowest free: 85703
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT SERVER] Publishing System MQTT topics...
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/connection, content: connected (msg_id=33)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/uptime, content: 79 (msg_id=34)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/freeMem, content: 755107 (msg_id=35)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/wifiRSSI, content: -77 (msg_id=36)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/CPUtemp, content: 94 (msg_id=37)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT SERVER] Successfully published all System MQTT topics
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT SERVER] Int. Heap Usage before publishing System Topics: 99807, after: 99879, delta: -72, lowest free: 85703
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT] Publishing MQTT topics...
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/main/value, content: 44.1222 (msg_id=38)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/main/error, content: no error (msg_id=39)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/main/rate, content: 0.001711 (msg_id=40)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/main/rate_per_time_unit, content: 0.102632 (msg_id=41)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/main/changeabsolut, content: 0.0065 (msg_id=42)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/main/rate_per_digitization_round, content: 0.0065 (msg_id=43)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/main/raw, content: 044.1222 (msg_id=44)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/main/timestamp, content: 2024-10-06T21:16:54+0200 (msg_id=45)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/main/json, content: { "value": "44.1222", "raw": "044.1222", "pre": "44.1222", "er.. (msg_id=46)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MQTT IF] Published topic: watermeterhaus/status, content: Flow finished (msg_id=47)
[0d00h01m19s] 2024-10-06T21:17:35 <INF> [MAINCTRL] Round #1 completed (51 seconds)
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MAINCTRL] CPU Temperature: 94°C
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [MAINCTRL] WIFI Signal (RSSI): -77dBm
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [WIFI] Roaming: Start scan of all channels for SSID Franks FRITZ!Box
[0d00h01m19s] 2024-10-06T21:17:35 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h01m22s] 2024-10-06T21:17:38 <DBG> [WIFI] Roaming: Current AP BSSID=3c:37:12:fa:95:d2
[0d00h01m22s] 2024-10-06T21:17:38 <DBG> [WIFI] Roaming: Scan completed, APs found with configured SSID: 2
[0d00h01m22s] 2024-10-06T21:17:38 <ERR> [MQTT IF] Connection Refused with unknown event id:0
[0d00h01m22s] 2024-10-06T21:17:38 <WRN> [MQTT IF] Disconnected, trying to reconnect
[0d00h01m22s] 2024-10-06T21:17:38 <DBG> [WIFI] Roaming: 2: SSID=Franks FRITZ!Box, BSSID=44:4e:6d:db:88:98, RSSI=-85, CH=6, AUTH=WPA2 PSK
[0d00h01m22s] 2024-10-06T21:17:38 <DBG> [WIFI] Roaming: Scan completed, stay on current AP
[0d00h01m36s] 2024-10-06T21:17:52 <DBG> [MAIN SERVER] info_get_handler
[0d00h01m36s] 2024-10-06T21:17:52 <DBG> [MAIN SERVER] info_get_handler
[0d00h01m36s] 2024-10-06T21:17:52 <DBG> [MAIN SERVER] info_get_handler
[0d00h01m36s] 2024-10-06T21:17:52 <DBG> [OTA FILE] download_get_handler
[0d00h01m37s] 2024-10-06T21:17:53 <INF> [MQTT IF] Connected to broker
[0d00h01m37s] 2024-10-06T21:17:53 <DBG> [MQTT IF] topic watermeterhaus/ctrl/flow_start subscribe successful, msg_id=48
[0d00h01m37s] 2024-10-06T21:17:53 <DBG> [MQTT IF] topic watermeterhaus/ctrl/set_prevalue subscribe successful, msg_id=49
[0d00h01m43s] 2024-10-06T21:17:59 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h01m54s] 2024-10-06T21:18:10 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h02m00s] 2024-10-06T21:18:16 <ERR> [MQTT IF] Connection Refused with unknown event id:0
[0d00h02m00s] 2024-10-06T21:18:16 <DBG> [MAIN SERVER] info_get_handler
[0d00h02m00s] 2024-10-06T21:18:16 <DBG> [MAIN SERVER] info_get_handler
[0d00h02m00s] 2024-10-06T21:18:16 <DBG> [MAIN SERVER] info_get_handler
[0d00h02m00s] 2024-10-06T21:18:16 <DBG> [OTA FILE] download_get_handler
[0d00h02m15s] 2024-10-06T21:18:31 <INF> [MQTT IF] Connected to broker
[0d00h02m15s] 2024-10-06T21:18:31 <DBG> [MQTT IF] topic watermeterhaus/ctrl/flow_start subscribe successful, msg_id=50
[0d00h02m15s] 2024-10-06T21:18:31 <DBG> [MQTT IF] topic watermeterhaus/ctrl/set_prevalue subscribe successful, msg_id=51
[0d00h02m24s] 2024-10-06T21:18:40 <DBG> [OTA FILE] log_get_last_part_handler

[caco3]

Connection Refused with unknown event id:0

The problem is that this ID actually sais that there is no error, so I have no clue what it means :(
See https://docs.espressif.com/projects/esp-idf/en/v5.3.1/esp32/api-reference/protocols/mqtt.html#_CPPv4N30esp_mqtt_connect_return_code_t24MQTT_CONNECTION_ACCEPTEDE resp. https://github.com/espressif/esp-mqtt/blob/master/include/mqtt_client.h#L100

[fraknu]

I think I found the problem. FYI: I have 3 water meter units.

I was able to activate the logging in MQTT and it says that it is closing the connection when another watermeter connects, because it thinks that they are all one client.

I have then put in a different client ID for every watermeter and now it is stable. I think I had this configured in the previous stable release, but since OTA-Update of all 3 units to 16.0 RC1 forced me to create a new config file I must have missed that.

So I think there is nothing more to do and we can close this issue.

Thanks for the support!

BR Frank

[caco3]

yes, the MQTT client IDs must be unique. And there is no way the devices cold check/handle this.