MQTT timeout/retry?

[Zitt]

@tjko ... twice now I've noticed that picofan does not appear to be resilient w/ regards to MQTT communication.

I'm seeing a situation where picofan launches pretty fast as compared to my Proxmox server which then launches a container with runs the EMWX broker.

I'm thinking that picofan tries to subscribe / post to the MQTT broker and makes some unintentional decision because the IP address is not "up yet".

Then it refuses to send another packet to the broker until the picofan is power cycled or reset.
I can "fix" this by manually connecting the picofan serial port and typing *RST ... then the firmware sees the broker and will send data.

Is there a "timeout" which would allow picofan to retry the MQTT process?

[tjko]

@Zitt, nice integration with Promox!

Issue you describe, sure sounds like it could be a bug in the Fanpico firmware.
Would you be able to capture some logs from Fanpico console when this is happening?
If logging is set to "INFO" (SYS:LOG INFO), then it should log events about MQTT connections/activity to console...

Alternatively, if you have syslog server available, you could enable logging over network using SYS:SYSLOG INFO...

In the meanwhile, I'll check the source if I can find some obvious bug...

Btw, do you have MQTT server configured using IP or DNS name?

[Zitt]

yeah; let me see what I can do.
It's configured for MQTT broker via an IP address; IIRC correctly ,

[tjko]

LwIP sometimes works rather unexpected ways, probably just bug somewhere in my code...

It should be retrying if connection fails or if existing connection disconnects for some reason (unless broker reports authentication failure):

In mqtt_connection_cb() in mqtt.c:

...
	else if (status == MQTT_CONNECT_DISCONNECTED) {
		log_msg(LOG_WARNING, "MQTT disconnected from %s", ipaddr_ntoa(&mqtt_server_ip));
		mqtt_reconnect = 15;
	}
	else if (status == MQTT_CONNECT_TIMEOUT) {
		log_msg(LOG_WARNING, "MQTT connect: timeout (%s)", ipaddr_ntoa(&mqtt_server_ip));
		mqtt_reconnect = 30;
	}
	else if (status == MQTT_CONNECT_REFUSED_USERNAME_PASS) {
		log_msg(LOG_WARNING, "MQTT connect: login failure (%s)", ipaddr_ntoa(&mqtt_server_ip));
	}
	else if (status == MQTT_CONNECT_REFUSED_NOT_AUTHORIZED_) {
		log_msg(LOG_WARNING, "MQTT connect: not authorized (%s)", ipaddr_ntoa(&mqtt_server_ip));
		mqtt_reconnect = 180;
	}
	else {
		log_msg(LOG_WARNING, "MQTT connect: refused (status=%d) (%s)", status, ipaddr_ntoa(&mqtt_server_ip));
		mqtt_reconnect = 90;
	}
...

[Zitt]

@tjko - I'm getting ready to try and reproduce but have another data point.
The box has been off for a few days via physical switch. This means Fanpico and the motherboard were off.
The pico seemed to come up properly. IE it came up... then the virtual machine/broker came up... and I saw messages in the broker dashboard.
I'm starting to think this may be a case where the fanpico remains powered on thru a power cycle.
IE everything works/transmits ok...
then the VM goes down... stays down for hours... fan pico times out but remains powered via USB.
when the broker comes back up; the fan pico has long given up trying to send messages to the mqtt broker.

[tjko]

@Zitt , it should keep retrying connection to MQTT server "forever". Hopefully it will log on the console some meaningful errors, that would point to what the problem is...

I configured a Fanpico test unit to connect to a non-existent MQTT server, but so far its' been working ok (it keeps retrying after 15 second pause....), I'll leave it running and check if it stops connecting at somepoint like you've observed to happen...

[tjko]

I may have reproduced the issue, it seems that after about 170 connection attempts LwIP starts returning error when trying to open TCP connection...

[  5724.522549][0] MQTT attempt reconnecting to server
[  5724.525304][0] MQTT Connecting to 172.30.1.40:8883 (TLS)
[  5743.033188][0] MQTT disconnected from 172.30.1.40
[  5758.538887][0] MQTT attempt reconnecting to server
[  5758.541611][0] MQTT Connecting to 172.30.1.40:8883 (TLS)
[  5777.049497][0] MQTT disconnected from 172.30.1.40
[  5792.554111][0] MQTT attempt reconnecting to server
[  5792.556858][0] MQTT Connecting to 172.30.1.40:8883 (TLS)
[  5792.562852][0] mqtt_client_connect(): failed -1

Now need to try to figure out what is causing this, and is the problem in Fanpico or in LwIP library...

Btw, do you have TLS enabled with MQTT?

[Zitt]

Ok. My quick check this afternoon spawned this "improvement":
#104

I tried a brief powerdown of the mqtt server and it indeed did recover; but, I only left the VM "off" for a few minutes.
I'll try an overnight run w/ syslog logging tonight.

[tjko]

Looks like there is memory leak. LwIP heap memory usage grows every time there is failed connection (eventually leading LwIP running out of memory and all connections starting to fail..)

Possible "fix" is here #105 and precompiled firmware images with the fix can be found here:
https://github.com/tjko/fanpico/actions/runs/10338104577

This seemed to fix the memory leak, but didn't have time to test if successful (TLS) connections still work ok...

[Zitt]

I was unable to reproduce last night. I left it running syslog but didn't see any MQTT errors being sent to the syslog.

when I booted up the machine/virual machines the MQTT messages didn't recover; but there was still no messages on either the usb nor on the syslog server.

Looks like there is memory leak. LwIP heap memory usage grows every time there is failed connection (eventually leading LwIP running out of memory and all connections starting to fail..)

I pulled #105 and merged it with my hysterisis changes and rebuilt. I'm going to run the experiment tonight to see if I can reproduce.

[Zitt]

@tjko Good news is that #105 seemed to fix the connection problem I was having (but unreported). I can log into the system with telnet after the main system was powered off for several hours to half a day.

I'm still not seeing MQTT recover tho. I turned off the system at about 11:30pm last night and left it off until about 6pm today. I don't remember if I set the logs to INFO or not last night.

That said at about 11:30pm; I saw a bunch of syslog messages saying Warning: MQTT disconnected from 192.168.1.135 which is my MQTT broker. It repeated irregularly; probably printing 1000 times until 13:11:50 where it just stopped reporting those messages.
It did not report the disconnected message even after the system came online at ~19:01:00. I haven't seen any new messages regarding MQTT at all no messages are flowing into the broker.

[tjko]

Are you able monitor unit via USB (or serial TTL) connection? Since if there is some LwIP related issue, then likely logging to syslog could be failing when the issue/bug is triggered...

[Zitt]

Was not able to replicate with latest firmware based upon our changes.
Night before last I shutdown the broker VM to "simulate" a lost connection but left the rest of the system "online" so I could capture the usb debug messages. It gave me hours of:

[ 77734.326103][0] MQTT attempt reconnecting to server
[ 77734.327837][0] MQTT Connecting to 192.168.1.135:8883 (TLS)
[ 77751.583482][0] MQTT disconnected from 192.168.1.135

but when I fired up the VM again; it auto recovered:

[ 77767.342539][0] MQTT attempt reconnecting to server
[ 77767.344332][0] MQTT Connecting to 192.168.1.135:8883 (TLS)
[ 77767.615042][0] core0: max_loop_time=245433
[ 77767.647236][0] MQTT connected to 192.168.1.135:8883
[ 77767.648672][0] MQTT subscribe to command topic: picofan/feeds/cmd
[ 77769.942578][0] MQTT publish to picofan/feeds/ProxFanPico: 908 bytes.

I'll see if I can make another attempt tonight.

[tjko]

Before patching that memory leak (on new TLS MQTT connections), it would have started failing making outbound connections after about 200 connection attempts.

[Zitt]

I was able to recreate a MQTT hang.

Log said:

[379459.227465][0] MQTT disconnected from 192.168.1.135
[379474.738966][0] MQTT attempt reconnecting to server
[379474.740702][0] MQTT Connecting to 192.168.1.135:8883 (TLS)
[379505.250937][0] MQTT disconnected from 192.168.1.135
[379520.764520][0] MQTT attempt reconnecting to server
[379520.766271][0] MQTT Connecting to 192.168.1.135:8883 (TLS)
[379533.703736][0] WiFi Link: DOWN
[379545.268648][0] MQTT disconnected from 192.168.1.135
[379560.781624][0] MQTT attempt reconnecting to server
[379560.782882][0] MQTT Connecting to 192.168.1.135:8883 (TLS)
[379560.784712][0] mqtt_client_connect(): failed -4
[379684.965305][0] WiFi Link: UP

I think the Wifi down/up message was because I happen to have my router set to reboot every Sunday morning.
I can't explain why the client failed with -4.
Do you think the two are related?

[tjko]

I made small fix, that should cause it to keep trying if there is issue with interface down, etc: 7f92142

Pre-built firmware images with this fix (and initial I2C temperature sensor support) can be found here:
https://github.com/tjko/fanpico/actions/runs/10449366326