Teslemetry / hass-teslemetry

Teslemetry integration from Home Assistant through HACS
https://teslemetry.com
MIT License
13 stars 6 forks source link

Charge Limit temporarily snaps back to previous value after user input #76

Open fhteagle opened 2 months ago

fhteagle commented 2 months ago

Checklist

Describe the issue

After manually inputting a value for the number.mycar_charge_limit, the command does get set (verified in the Tesla mobile app), but for up to 60 seconds, the old value for this entity is displayed in home assistant. Looking at the debug log, this appears to be old data being echoed back with latency via teslemetry_stream event(s). After about a minute (next teslemetry_stream update?) the new updated value does get displayed. This is a little confusing as is, but gets way worse if making multiple changes to the value within that 60 second window. I believe a race condition ends up happening between the original value, first changed value, subsequent changed value, and "updated from car" values coming back via API.

I would assume this issue may affect other entities as well, but I have not tested other ones.

Found this bug using software / firmware versions:

HA Core (docker container) 2024.5.2 HA UI 20240501.1 Hass-teslemetry custom integration 1.9.3 Connecting to 2023 MYLR (HW3), 2024.2.2

Reproduction steps

  1. Note current charge_limit value
  2. Change charge limit value (note that value is displayed with an additional decimal point)
  3. Wait a few seconds
  4. Note that the previous value is now displayed in the Charge Limit entity input box (with integer precision)
  5. Wait up to 60 seconds
  6. Note new value is finally displayed in the Charge Limit entity input box ...

Debug logs

Sanitized (items with *** redacted for privacy/security ***) debug log available at https://pastebin.com/LS9Pm7Jp
Bre77 commented 2 months ago

So in your logs I see 21:29:06 ... {"percent": 54} 21:29:07 ... Command result: {'response': {'result': True, 'reason': ''}} 21:29:10 ... Response JSON ...charge_limit_soc': 54

Which means you made the change at second 6, it took effect and wrote a state change at second 7, and then a refresh ran with the new value returned at second 10. I am unsure how this would do a snap back.

However, the change from int to float is interesting and something I can address, so I have put in a fix for that and well see if it helps with the snapbackk.

fhteagle commented 2 months ago

Key line is at second 20 in that log, where "ChargeLimitSOC" comes back as "50", even after the car received the commands (and Tesla app updated to show) the Charge Limit being set to 54:

2024-05-10 21:29:20.628 DEBUG (MainThread) [teslemetry_stream] event {"data": {"ACChargingPower": "0.000", "ChargeAmps": "16", "ChargeLimitSoc": "50", "Odometer": "12602.168"}, "createdAt": "2024-05-11T03:29:20.174216209Z", "vin": "myvin", "timestamp": 1715398160174}

I've disabled automations, node red flows, everything that might be writing a different value for Charge Limit without my knowledge. But I can absolutely reproduce this 100% of the time. Just noticed that the length of time the old value is snapped back is sometimes up to 3 minutes, not just the one minute in my original bug report. Makes me wonder if there is some kind of lag / delay on your (US-West?) server side that is slowing down or caching old teslemetry_stream data?

I pulled a fresher log again this morning (UTC -0600 here), but its the same lines and behavior as the log I already posted. I also took screenshots to document as well. Let me know what of that you want.

fhteagle commented 2 months ago

Another clue:

I watched the web GUI "Telemetry Configuration for..." and the SSE events shown on there also affected/delayed. I did a Call:service number:set on number.mycar_charge_limit to 51 within 5 seconds after 9:41:31AM update tick, but the results don't make it to SSE until the 9:43:31 tick. The 9:42:31 tick had the old value:

9:41:31 AM  data    { "ChargeAmps": "16", "ChargeLimitSoc": "53", "Odometer": "12602.168", "ACChargingPower": "0.000" }
9:42:31 AM  data    { "ChargeAmps": "16", "ChargeLimitSoc": "53", "Odometer": "12602.168", "ACChargingPower": "0.000" }
9:43:31 AM  data    { "ChargeAmps": "16", "ChargeLimitSoc": "51", "Odometer": "12602.168", "ACChargingPower": "0.000" }
Bre77 commented 2 months ago

If streaming is also involved... it gets even more messier. I would have to rework the timestamp system to ignore streaming updates that occur within ~5 seconds of a command, or just accept snap backs can happen due to unlucky timing.

fhteagle commented 2 months ago

I just thought to check what happens if I adjust the charge limit via the Tesla app instead. Sure enough, SSE ticks held old data for that case as well.

fhteagle commented 2 months ago

The plot sickens ...

I am now seeing stale data in the teslemetry fleet api JSON response elsewhere. Tesla app is reporting battery SOC of 94% as I get ready to leave on a drive, but the api JSON has 'battery_level': 95 instead. Ugh.

Looks like the app goes by the "SOC" field value, not the "battery_level" field value, and the rounding method is different to boot. Will keep watching this during the drive to see if I can tease out any other pattern...