Connection fails after a timeout

[ddp526]

Hi,

Sorry to raise another issue, because the code is much more stable, but I have seen this issue twice now (first time I was too optimistic and removed debugs). With debugs on, it seems that for some reason the connection to the device times out and then never recovers.

I don't know whether the time out is due to a transient event or is the cause, because using nmap now, the port is closed on the rinnai device to my hass container. I am suspicious that if the timeout is transient, the repeated and fast re-connect attempts could trigger the device to block or even just confuse their code :)

Also noting the 'Bad file descriptor' error in the first part of the reconnect makes me wonder if the way in which the timeout is processed might need a tweak? (as always happy even to dig into the code a little if you want or add some debugs/wait for it to occur again)

2023-03-29 03:36:31.019 DEBUG (Thread-2 (poll_loop)) [pyrinnaitouch.unit_status] Unit set temp is: 18
2023-03-29 03:37:30.146 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.receiver] Sequence: 0 Json: [{"SYST": {"CFG": {"MTSP": "N", "NC": "00", "DF": "N", "TU": "C", "CF": "1", "VR": "0183",
 "CV": "0010", "CC": "043", "ZA": "                ", "ZB": "                ", "ZC": "                ", "ZD": "                " }, "AVM": {"HG": "Y", "EC": "N", "CG": "N", "RA": "N",
 "RH": "N", "RC": "N" }, "OSS": {"DY": "TUE", "TM": "03:12", "BP": "Y", "RG": "Y", "ST": "N", "MD": "H", "DE": "N", "DU": "N", "AT": "999", "LO": "N" }, "FLT": {"AV": "N", "C3": "000" }
 } },{"HGOM": {"CFG": {"ZUIS": "Y", "ZAIS": "N", "ZBIS": "N", "ZCIS": "N", "ZDIS": "N", "CF": "N", "PS": "Y", "DG": "W" }, "OOP": {"ST": "N", "CF": "N", "FL": "08", "SN": "N" }, "GSO": 
{"OP": "M", "SP": "18", "AO": "N" }, "GSS": {"HC": "N", "FS": "N", "GV": "N", "PH": "N", "AT": "W", "AZ": "W" }, "APS": {"AV": "N" }, "ZUO": {"UE": "Y" }, "ZAO": {"UE": "N" }, "ZBO": {"
UE": "N" }, "ZCO": {"UE": "N" }, "ZDO": {"UE": "N" }, "ZUS": {"AE": "N", "MT": "999" }, "ZAS": {"AE": "N", "MT": "999" }, "ZBS": {"AE": "N", "MT": "999" }, "ZCS": {"AE": "N", "MT": "999
" }, "ZDS": {"AE": "N", "MT": "999" } } }]
2023-03-29 03:37:30.146 DEBUG (Thread-2 (poll_loop)) [pyrinnaitouch.system_status] We are in HEAT mode
2023-03-29 03:37:30.146 DEBUG (Thread-2 (poll_loop)) [pyrinnaitouch.unit_status] Unit is ON
2023-03-29 03:37:30.146 DEBUG (Thread-2 (poll_loop)) [pyrinnaitouch.unit_status] Fan Speed is: 08
2023-03-29 03:37:30.146 DEBUG (Thread-2 (poll_loop)) [pyrinnaitouch.unit_status] Unit OpMode is: M
2023-03-29 03:37:30.146 DEBUG (Thread-2 (poll_loop)) [pyrinnaitouch.unit_status] Unit set temp is: 18
2023-03-29 03:38:07.221 ERROR (Thread-3 (receiver)) [pyrinnaitouch.receiver] Socket timed out, renewing connection (TimeoutError('timed out'))
2023-03-29 03:38:07.221 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Connection successfully closed
2023-03-29 03:38:07.221 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Error 1st phase during renewConnection [Errno 9] Bad file descriptor
2023-03-29 03:38:07.222 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Creating new client...
2023-03-29 03:38:07.276 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Client connection created: ('192.168.0.237', 27847)
2023-03-29 03:38:07.277 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Connected to ('192.168.0.237', 27847)
2023-03-29 03:38:07.531 ERROR (Thread-3 (receiver)) [pyrinnaitouch.receiver] Couldn't decode JSON (connection), skipping (ConnectionResetError(104, 'Connection reset by peer'))
2023-03-29 03:38:07.531 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Exception during client shutdown [Errno 107] Socket not connected
2023-03-29 03:38:07.531 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Error 1st phase during renewConnection [Errno 107] Socket not connected
2023-03-29 03:38:07.531 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Creating new client...
2023-03-29 03:38:07.712 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Client refused connection: [Errno 111] Connection refused
2023-03-29 03:38:07.713 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Error during renewConnection [Errno 111] Connection refused
2023-03-29 03:38:07.713 ERROR (Thread-3 (receiver)) [pyrinnaitouch.receiver] Socket timed out, renewing connection (OSError(9, 'Bad file descriptor'))
2023-03-29 03:38:07.713 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Exception during client shutdown [Errno 9] Bad file descriptor
2023-03-29 03:38:07.713 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Error 1st phase during renewConnection [Errno 9] Bad file descriptor
2023-03-29 03:38:07.713 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Creating new client...
2023-03-29 03:38:07.715 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Client refused connection: [Errno 111] Connection refused
2023-03-29 03:38:07.716 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Error during renewConnection [Errno 111] Connection refused
2023-03-29 03:38:07.716 ERROR (Thread-3 (receiver)) [pyrinnaitouch.receiver] Socket timed out, renewing connection (OSError(9, 'Bad file descriptor'))
2023-03-29 03:38:07.716 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Exception during client shutdown [Errno 9] Bad file descriptor
2023-03-29 03:38:07.716 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Error 1st phase during renewConnection [Errno 9] Bad file descriptor
2023-03-29 03:38:07.716 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Creating new client...
2023-03-29 03:38:07.720 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Client refused connection: [Errno 111] Connection refused
2023-03-29 03:38:07.720 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Error during renewConnection [Errno 111] Connection refused
2023-03-29 03:38:07.721 ERROR (Thread-3 (receiver)) [pyrinnaitouch.receiver] Socket timed out, renewing connection (OSError(9, 'Bad file descriptor'))
2023-03-29 03:38:07.721 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Exception during client shutdown [Errno 9] Bad file descriptor
2023-03-29 03:38:07.721 DEBUG (Thread-3 (receiver)) [pyrinnaitouch.connection] Error 1st phase during renewConnection [Errno 9] Bad file descriptor
<this repeats in the logs still>

[zagnuts]

for some reason the connection to the device times out and then never recovers.

Could be a coincidence, but I recently moved to running HA in a container. At first I found that there was no connection. I tried reinstalling/installing rebooting etc but no joy. For a while I thought that maybe there was an issue with it running in a container as my old HA on a 'pi connected without an issue.

I then cast my mind way back when we were all trying to work out how to access the mysimplelink device and remembered it had issues with multiple devices connecting locally. I wondered if somehow the mysimplelink gateway was keeping the connection open for the old pi, even though it was powered off. Another more likely story is, as I do sometimes use the app on my 'phone, that was locking the gateway and for whatever reason when running HA in a container the script struggles to reconnect. Perhaps it's simply too fast now - compiling an Esphome device now takes 30 seconds rather than the ten minutes it was taking on the 'pi 3B+. Anyhow I power cycled the gateway to ensure nothing was using it, and restarted the container, and (sound of magic tinkling) the thermostat started working.

I'll keep an eye on it for now, and at least I now how to get things working again.

My suggestion would be to keep in mind, if you are using the native Rinnai Touch app as well, that it blocks this script unless you are connecting via the cloud.

[funtastix]

The gateway/device can only keep a single local connection. Therefore, it's best to connect the home assistant integration first and "hog" that connection. The app will then just use the cloud connection automatically.