HeatPump
HeatPump copied to clipboard
SwiCago
HeatPump::update() treats update ack as synchronous
I saw behavior where every time I called update from the MQTT example, I always got "heatpump: update() failed".
Looking at the code for update:
createPacket(packet, wantedSettings);
writePacket(packet, PACKET_LEN);
while (!canRead()) {
delay(10);
}
int packetType = readPacket();
if (packetType == RCVD_PKT_UPDATE_SUCCESS) {
We write the settings, then read the next packet to see if the update was a success.
But the heatpump doesn't respond to updates synchronously. It takes a bit of time before the update is acknowledged (seems like 5-10 seconds usually).
Swicago mentioned this here: https://github.com/SwiCago/HeatPump/issues/123#issuecomment-482897333
So this code seems to be incorrect, though I can't think of a great way to fix it. It also seems that this means that autoUpdate is essentially dead code right now that never gets called.
An example update for me:
{"packetSent":"fc 41 01 30 10 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7c "} <-- settings updated
{"packetRecv":"fc 62 01 30 10 04 00 00 00 80 00 00 00 00 00 00 00 00 00 00 00 d9 "}
{"packetSent":"fc 42 01 30 10 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7b "}
{"packetRecv":"fc 62 01 30 10 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 58 "}
{"packetSent":"fc 42 01 30 10 03 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7a "}
{"packetRecv":"fc 62 01 30 10 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 57 "}
{"packetSent":"fc 42 01 30 10 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 79 "}
{"packetRecv":"fc 62 01 30 10 09 00 00 00 02 00 00 00 00 00 00 00 00 00 00 00 52 "}
{"packetSent":"fc 42 01 30 10 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 78 "}
{"packetRecv":"fc 62 01 30 10 02 00 00 01 0b 08 00 07 00 00 0c ae 00 00 00 00 86 "}
{"packetSent":"fc 42 01 30 10 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 77 "} ]
{"packetRecv":"fc 62 01 30 10 03 00 00 0c 00 a6 ac aa fe 00 00 00 00 00 00 00 54 "} |
{"packetSent":"fc 42 01 30 10 09 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 74 "} |-- 10s gap or so
{"packetRecv":"fc 62 01 30 10 04 00 00 00 80 00 00 00 00 00 00 00 00 00 00 00 d9 "} |
{"packetSent":"fc 42 01 30 10 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7b "} ]
{"packetRecv":"fc 62 01 30 10 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 58 "}
{"packetSent":"fc 42 01 30 10 03 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7a "}
{"packetRecv":"fc 62 01 30 10 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 57 "}
{"packetSent":"fc 42 01 30 10 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 79 "}
{"packetRecv":"fc 62 01 30 10 09 00 00 00 02 00 00 00 00 00 00 00 00 00 00 00 52 "}
{"packetSent":"fc 42 01 30 10 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 78 "}
{"packetRecv":"fc 61 01 30 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5e "} <-- update success
I think I have a better idea of what's going on, and that updates may be more synchronous than they appear (at least for my unit)
I noticed that the sample packets above are jumbled-- request 0x09, get back 0x04 as the response, etc. I assumed this was because everything was async.
I think instead what's happening is that we strictly read one packet on a turn of the event loop, even if other packets are queued up. This is enforced by the waitForRead semaphore, which flips to false on every read, meaning that if we send two packets, we'll only receive one and the buffer will increase by PACKET_SIZE.
Currently we write a packet, then wait for a second, read a packet, wait for a second, write a packet, etc. This means that 50% of the time, sending an update to the heat pump will send a packet while we're waiting to read a packet-- creating the above scenario where we are forever buffering packets.
One option would be to have a queue, but that's fragile if we drop a packet somewhere (which isn't that unlikely). I think a better option is just to flush the buffer on reads when we don't care about the returned packet specifically, only about its update.
With these changes, my packet stream looks way more robust!
{"packetSent":"fc 42 01 30 10 09 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 74 "} ]
{"packetRecv":"fc 62 01 30 10 09 00 00 00 02 00 00 00 00 00 00 00 00 00 00 00 52 "} ] -- request/response are paired now
{"packetSent":"fc 42 01 30 10 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7b "}
{"packetRecv":"fc 62 01 30 10 02 00 00 01 0b 08 00 07 00 00 0c ae 00 00 00 00 86 "}
{"packetSent":"fc 42 01 30 10 03 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7a "}
{"packetRecv":"fc 62 01 30 10 03 00 00 0b 00 a0 aa a9 fe 00 00 00 00 00 00 00 5e "}
{"packetSent":"fc 42 01 30 10 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 79 "}
{"packetRecv":"fc 62 01 30 10 04 00 00 00 80 00 00 00 00 00 00 00 00 00 00 00 d9 "}
{"packetSent":"fc 42 01 30 10 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 78 "}
{"power":"OFF"} <-- notice here I sent the command while we were waiting for the response for 0x05
{"packetRecv":"fc 62 01 30 10 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 58 "}
{"packetSent":"fc 41 01 30 10 01 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7c "} <-- but we waited to send the command until the buffer was flushed!
{"packetRecv":"fc 61 01 30 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5e "}
{"packetSent":"fc 42 01 30 10 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 77 "}
{"packetRecv":"fc 62 01 30 10 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 57 "}
{"roomTemperature":21,"operating":false}
{"mode":"NONE","onMins":0,"onRemainMins":0,"offMins":0,"offRemainMins":0}
{"packetSent":"fc 42 01 30 10 09 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 74 "}
{"packetRecv":"fc 62 01 30 10 09 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 54 "}
{"packetSent":"fc 42 01 30 10 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7b "}
{"packetRecv":"fc 62 01 30 10 02 00 00 00 0b 08 00 07 00 00 0c ae 00 00 00 00 87 "}
{"power":"OFF","mode":"COOL","temperature":23,"fan":"AUTO","vane":"SWING","wideVane":"SWING"}
{"packetSent":"fc 42 01 30 10 03 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7a "}
{"packetRecv":"fc 62 01 30 10 03 00 00 0b 00 a0 aa a9 fe 00 00 00 00 00 00 00 5e "}
{"power":"ON","mode":"COOL"}
{"packetSent":"fc 41 01 30 10 01 01 00 01 00 00 00 00 00 00 00 00 00 00 00 00 7b "} <-- sent the command when buffer was empty
{"packetRecv":"fc 61 01 30 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5e "} <-- get response back immediately
{"packetSent":"fc 42 01 30 10 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 79 "}
{"packetRecv":"fc 62 01 30 10 04 00 00 00 80 00 00 00 00 00 00 00 00 00 00 00 d9 "}
{"packetSent":"fc 42 01 30 10 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 78 "}
This also seems to dramatically improve the perceived responsiveness of my units. Check out this sample from an unpatched unit (running current master):
{"packetRecv":"fc 62 01 30 10 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 58 "}
{"temperature":20} <-- set temp
{"packetSent":"fc 41 01 30 10 01 04 00 00 00 00 00 00 00 00 00 00 00 00 a8 00 d1 "} <-- send packet setting temp to a8
{"packetRecv":"fc 62 01 30 10 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 57 "}
heatpump: update() failed <-- update returns false because the next packet was a buffered packet
{"packetSent":"fc 42 01 30 10 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 77 "}
{"packetRecv":"fc 62 01 30 10 09 00 00 00 02 00 00 00 00 00 00 00 00 00 00 00 52 "}
{"packetSent":"fc 42 01 30 10 09 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 74 "}
{"packetRecv":"fc 62 01 30 10 02 00 00 01 0b 0c 00 00 00 00 0c a6 00 00 00 00 91 "} <-- temp is still a6, not a8! This is a stale buffered packet
{"roomTemperature":19.5,"operating":false}
{"mode":"NONE","onMins":0,"onRemainMins":0,"offMins":0,"offRemainMins":0}
{"packetSent":"fc 42 01 30 10 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7b "}
{"packetRecv":"fc 62 01 30 10 03 00 00 09 00 a0 a7 a5 fe 00 00 00 00 00 00 00 67 "}
{"packetSent":"fc 42 01 30 10 03 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7a "}
{"packetRecv":"fc 62 01 30 10 04 00 00 00 80 00 00 00 00 00 00 00 00 00 00 00 d9 "}
{"packetSent":"fc 42 01 30 10 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 79 "}
{"packetRecv":"fc 62 01 30 10 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 58 "}
{"packetSent":"fc 42 01 30 10 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 78 "}
{"packetRecv":"fc 62 01 30 10 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 57 "}
{"packetSent":"fc 42 01 30 10 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 77 "}
{"packetRecv":"fc 62 01 30 10 09 00 00 00 02 00 00 00 00 00 00 00 00 00 00 00 52 "}
{"packetSent":"fc 42 01 30 10 09 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 74 "}
{"packetRecv":"fc 62 01 30 10 02 00 00 01 0b 0c 00 00 00 00 0c a6 00 00 00 00 91 "} <-- also stale
{"packetSent":"fc 42 01 30 10 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7b "}
{"packetRecv":"fc 62 01 30 10 03 00 00 09 00 a0 a7 a5 fe 00 00 00 00 00 00 00 67 "}
{"packetSent":"fc 42 01 30 10 03 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7a "}
{"packetRecv":"fc 62 01 30 10 04 00 00 00 80 00 00 00 00 00 00 00 00 00 00 00 d9 "}
{"packetSent":"fc 42 01 30 10 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 79 "}
{"packetRecv":"fc 62 01 30 10 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 58 "}
{"packetSent":"fc 42 01 30 10 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 78 "}
{"packetRecv":"fc 61 01 30 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5e "} <-- there's the confirmation packet finally
{"packetSent":"fc 42 01 30 10 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 77 "}
{"packetRecv":"fc 62 01 30 10 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 57 "}
{"packetSent":"fc 42 01 30 10 09 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 74 "}
{"packetRecv":"fc 62 01 30 10 09 00 00 00 02 00 00 00 00 00 00 00 00 00 00 00 52 "}
{"packetSent":"fc 42 01 30 10 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7b "}
{"packetRecv":"fc 62 01 30 10 02 00 00 01 0b 0b 00 00 00 00 0c a8 00 00 00 00 90 "} <-- finally updated!
{"power":"ON","mode":"COOL","temperature":20,"fan":"AUTO","vane":"AUTO","wideVane":"SWING"}