Subscribing fails with "i/o timeout"

[TinHead]

Hello,

As per our discussion on Slack I updated natiu-mqtt to latest main:

github.com/soypat/natiu-mqtt v0.5.2-0.20241009154510-7c992f5072e3
Tinygo version:
tinygo version tinygo version 0.32.0 linux/amd64 (using go version go1.21.5 and LLVM version 18.1.2)

Code I'm using in the repo here: https://github.com/TinHead/tinygo-playground/tree/main/rfm-wifi-gw
Debug output:

Connected to /dev/ttyACM0. Press Ctrl-C to exit.
time=1970-01-01T00:00:05.972Z level=INFO msg="wifi join success!" mac=28:cd:c1:01:78:8a
Connecting to MQTT broker at 192.168.1.3:1883
time=1970-01-01T00:00:05.983Z level=INFO msg=socket:listen
time=1970-01-01T00:00:05.985Z level=DEBUG msg=ARP:send isReply=false
time=1970-01-01T00:00:06.036Z level=DEBUG msg=tcp:noSocket port=25429 avail=2
time=1970-01-01T00:00:06.087Z level=DEBUG msg=ARP:recv op=2
time=1970-01-01T00:00:06.138Z level=DEBUG msg=TCP:send plen=54
time=1970-01-01T00:00:06.189Z level=DEBUG msg=TCP:recv opt=4 ipopt=0 payload=0
time=1970-01-01T00:00:06.190Z level=INFO msg=TCP:rx-statechange port=20593 old=SynSent new=Established rxflags=[SYN,ACK]
time=1970-01-01T00:00:06.191Z level=DEBUG msg=TCP:send plen=54
time=1970-01-01T00:00:06.289Z level=INFO msg=mqtt:start-connecting
time=1970-01-01T00:00:06.291Z level=DEBUG msg=TCP:send plen=107
time=1970-01-01T00:00:06.342Z level=DEBUG msg=TCP:recv opt=0 ipopt=0 payload=0
time=1970-01-01T00:00:06.393Z level=DEBUG msg=tcp:noSocket port=25429 avail=2
time=1970-01-01T00:00:06.443Z level=DEBUG msg=TCP:recv opt=0 ipopt=0 payload=4
time=1970-01-01T00:00:06.445Z level=DEBUG msg=TCP:send plen=54
time=1970-01-01T00:00:06.455Z level=INFO msg="mqtt:isconn? %t" !BADKEY=true
time=1970-01-01T00:00:06.462Z level=INFO msg="{\"name\":\"rfm-gw\",\"device_class\":\"running\",\"state_topic\":\"homeassistant/binary_sensor/rfm-gw/state\",\"command_topic\":\"homeassistant/binary_sensor/rfm-gw/set\",\"unique_id\":\"gw01\",\"device\":{\"identifiers\":[\"gw01\"],\"name\":\"gw01\"},\"payload_on\":\"on\",\"payload_off\":\"off\",\"value_template\":\"{{ value_json.state }}\"}"
time=1970-01-01T00:00:06.465Z level=INFO msg="published message" packetID=43649
time=1970-01-01T00:00:06.495Z level=DEBUG msg=TCP:send plen=403
time=1970-01-01T00:00:06.546Z level=DEBUG msg=TCP:recv opt=0 ipopt=0 payload=0
time=1970-01-01T00:00:06.597Z level=DEBUG msg=tcp:noSocket port=25429 avail=2
time=1970-01-01T00:00:07.157Z level=DEBUG msg=tcp:noSocket port=25429 avail=2
time=1970-01-01T00:00:08.279Z level=DEBUG msg=tcp:noSocket port=25429 avail=2
time=1970-01-01T00:00:10.319Z level=DEBUG msg=tcp:noSocket port=25429 avail=2
ignoring error i/o timeout
time=1970-01-01T00:00:11.493Z level=ERROR msg="could not subscribe, " !BADKEY="i/o timeout"
ignoring error i/o timeout
LED ON
time=1970-01-01T00:00:11.505Z level=INFO msg="published message" packetID=63733
time=1970-01-01T00:00:11.506Z level=DEBUG msg=TCP:send plen=115
time=1970-01-01T00:00:11.559Z level=DEBUG msg=TCP:recv opt=0 ipopt=0 payload=0
time=1970-01-01T00:00:14.721Z level=DEBUG msg=tcp:noSocket port=25429 avail=2
ignoring error i/o timeout
LED OFF
time=1970-01-01T00:00:20.555Z level=INFO msg="published message" packetID=21182
time=1970-01-01T00:00:20.595Z level=DEBUG msg=TCP:send plen=116
time=1970-01-01T00:00:20.646Z level=DEBUG msg=TCP:recv opt=0 ipopt=0 payload=0
time=1970-01-01T00:00:23.145Z level=DEBUG msg=tcp:noSocket port=25429 avail=2
ignoring error i/o timeout
LED ON
time=1970-01-01T00:00:25.602Z level=INFO msg="published message" packetID=56954
time=1970-01-01T00:00:25.604Z level=DEBUG msg=TCP:send plen=115
time=1970-01-01T00:00:25.657Z level=DEBUG msg=TCP:recv opt=0 ipopt=0 payload=0
ignoring error i/o timeout
LED OFF
time=1970-01-01T00:00:34.653Z level=INFO msg="published message" packetID=47988
time=1970-01-01T00:00:34.693Z level=DEBUG msg=TCP:send plen=116
time=1970-01-01T00:00:34.744Z level=DEBUG msg=TCP:recv opt=0 ipopt=0 payload=0
ignoring error i/o timeout
LED ON
time=1970-01-01T00:00:39.700Z level=INFO msg="published message" packetID=48886
time=1970-01-01T00:00:39.702Z level=DEBUG msg=TCP:send plen=115
time=1970-01-01T00:00:39.754Z level=DEBUG msg=TCP:recv opt=0 ipopt=0 payload=0
time=1970-01-01T00:00:39.805Z level=DEBUG msg=ARP:recv op=2
time=1970-01-01T00:00:39.806Z level=DEBUG msg=ARP:send isReply=true
time=1970-01-01T00:00:41.896Z level=DEBUG msg=tcp:noSocket port=25429 avail=2```

Let me know if you need more info.
Cheers,
TH

[soypat]

OK, sorry for taking so long to get back to you. There seems to be a bug in your code for starters. Calling SetDeadline will eventuall cause the connection to fail. Here is where you call it: https://github.com/TinHead/tinygo-playground/blob/67527d1910c0c0796213bbd9b498c627b79a892f/rfm-wifi-gw/mqttops.go#L78

On success you should reset the deadline by setting a zero time time.Time{} with the same function.

I understand this might not solve your issue, but it will narrow down causes.

[TinHead]

Well ok it's all copy pasted from your stuff as much as I were able to understand it, unfortunately it's very confusing for me how seqs, net, and natiu-mqtt and the cyw43439 driver are supposed to interact. As much as I would like for this to work I'm not that well versed to help fix whatever is wrong :/

I guess your time is as limited as mine so I won't pursue this any further at this time it's easier to just move on to a Raspberry Pi Zero and use normal go instead, as I need to finish this before the cold starts (project is integrating heating with Homeassistant as you might have guessed).

Thanks for looking into it and all the hard work, I'll watch this space.

Cheers!
TH