[Request] Improve logging and handling of MQTT disconnect

[jeremysherriff]

Describe the solution you'd like

I have had 3 situations when the remote MQTT broker has been offline for a period and unfortunately I have not realised that the LnxLink instances have not reconnected when the broker is back up. To recover from this I have to log into each LnxLink endpoint and restart the service, because I have lost remote control and can't use LnxLink to fix things for me :)

I assume that the MQTT broker connection is reattempted, and that eventually LnxLink gives up. But I see no log entries to help understand what is happening.

I turned on debug logging and shut down my MQTT broker, here's the log output:

Nov 16 19:39:55 stuff systemd[1]: Started LNXlink.
Nov 16 19:39:56 stuff lnxlink[717354]: INFO:lnxlink:LNXlink 2024.11.0, Python 3.10.12
Nov 16 19:39:56 stuff lnxlink[717354]: DEBUG:lnxlink:Path=/usr/local/lib/python3.10/dist-packages
Nov 16 19:39:56 stuff lnxlink[717354]: DEBUG:lnxlink:Found addons: bash, cpu, memory, mounts, restart, required_restart, statistics, sys_updates, update
Nov 16 19:39:56 stuff lnxlink[717354]: INFO:lnxlink:Loaded addons: bash, cpu, memory, mounts, required_restart, restart, statistics, sys_updates, update
Nov 16 19:39:56 stuff lnxlink[717354]: INFO:lnxlink:MQTT connection: Connection Accepted.
Nov 16 19:39:56 stuff lnxlink[717354]: DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): api.github.com:443
Nov 16 19:39:57 stuff lnxlink[717354]: DEBUG:urllib3.connectionpool:https://api.github.com:443 "GET /repos/bkbilly/lnxlink/releases/latest HTTP/1.1" 200 822
Nov 16 19:54:58 stuff lnxlink[717354]: INFO:lnxlink:Sending statistics data: {"uuid": "c55c416261984ee982cd6a6ac871b920", "version": "2024.11.0"}
Nov 16 19:54:58 stuff lnxlink[717354]: DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): analyzer.bkbilly.workers.dev:443
Nov 16 19:55:00 stuff lnxlink[717354]: DEBUG:urllib3.connectionpool:https://analyzer.bkbilly.workers.dev:443 "POST /api/lnxlink HTTP/1.1" 200 0
Nov 16 20:12:06 stuff lnxlink[717354]: INFO:lnxlink:MQTT connection: Connection Accepted.

I shut down the MQTT broker at 19:52 and started it back up again at 20:10 (just over 17 minutes with no MQTT broker available). A few things of note:

• no log entry to indicate MQTT broker connection has been lost
• no log entry to indicate reconnection attempts
• when the MQTT broker was started back up, LnxLink reconnected automatically as expected (after around 2 minutes)

How long/how many times is the MQTT connection attempted before giving up?
Can we get some log entries to indicate broker connection attempts, and broker connection loss?

Additional context

As a side note, I would like the log level setting to be in the config file rather than having to edit the service definition.

[bkbilly]

Thank you for taking the time to investigate the issue!

I've also made some tests, but I couldn't get the MQTT to timeout.
I disabled the MQTT Broker for about 2 hours, but my LNXlink devices connected without any issue.

The 2 minutes connection time is the default after some time, so it is normal to connect with a bit of a delay.
The MQTT client used by LNXlink should never give up connecting after a connection drop.

I could add a log message when it loses connection which will make it more clear when this happens, but I don't know what else I could check for the issue you are having.

[jeremysherriff]

Adding a log entry when connection is lost would be helpful as there is already a "Connection Accepted" log message, so a disconnect message would be appropriate.

The MQTT client used by LNXlink should never give up connecting after a connection drop.

Interesting.. that means the behaviour I have experienced is probably related to my environment.
If you are able to add a DEBUG log entry for MQTT connection attempts then I can attempt to diagnose my issue further, and confirm whether the MQTT client is indeed giving up or if something else is happening.