Missing sleep state, long wake times and errors in log with MCU2 updated cars

[markusdd]

Is there an existing issue for this?

• [X] I have searched the existing issues

What happened?

The car only switches between online and offline state, sleep does never occur. Also, the log is littered with weird API errors and the wakeup times of the car are far too frequent and long, leading to bad phantom drain. Also raised this in the discussion area: https://github.com/adriankumpf/teslamate/discussions/3083

Expected Behavior

the car goes to sleep (not offline), there are no API query errors in the log and the car actually sleeps when it is not being used or charged

Steps To Reproduce

if only I knew, but I can give my config:

• Streaming API is enabled
• apart fromt his weird behavior everything else works, drives etc are all recorded fine
• car works
• this is an 85D Model S with MCU2 upgrade, so no MCU1 energy save settings required/possible
• no other services are registered with my account except Teslamate

In the current example the below log output belongs to the last offline/online phase, error prints start happeneing at around the red arrow marker:

Relevant log output

see screen below

Screenshots

ok....and now after a long wake period we are suddenly offline....that is weird.

Additional data

No response

Type of installation

Manual

Version

v1.27.2

[woutersmit]

fyi HTTP 408's are just a way for the api to communicate the verhicle IS in standby. After which you'd send a 'wake_up' api-call.

But, I'm also seeing increased drain caused by verhicle standby. Will try to rollback a version and see if that solves it.

[micves]

I'm seeing the same pattern with my Model S 2017 upgraded to MCU2 (version 2023.2.12) I only just started using teslamate, so I don't know how it looked before MCU2. Streaming API is enabled.

When teslamate is running I'm getting 54 minutes of offline and 19 minutes of online according to grafana.

If I turn off teslamate and poll the API (using the command from this comment: https://github.com/adriankumpf/teslamate/discussions/1288#discussioncomment-495420 ) it only wakes up for about 3-4 minutes.

It seems that teslamate is keeping it awake for longer than necessary.

teslamate_1 | 2023-03-17 14:01:38.024 car_id=1 [info] Start / :online teslamate_1 | 2023-03-17 14:01:38.075 car_id=1 [info] Connecting ... teslamate_1 | 2023-03-17 14:04:42.039 car_id=1 [info] Suspending logging

So the question might be: What is happening behind [info] Start / :online and [info] Connecting ... that is extending the wake time?

@adriankumpf do you remember off the top of your head? :) Is it getting vehicle_data or starting the streaming API ?

[markusdd]

I confirm. I have run similar experiments and is definetly teslamate keeping the car awake and creating this pattern. The phantom drain (and hence cost) of this is pretty substantial. But I would hate having to turn of teslamte. It would be good to get some support on debugging this.

[micves]

Still having teslamate off I did a poll on vehicle_data when the car came online. This extended the time :(

And the normal state response (https://owner-api.teslamotors.com/api/1/vehicles/:id) doesn't contain any info if its a real online or just a i'm-just-checking-in online

Hopefully the streaming API can connect for more info and not extend the wake time... I'm not really into that yet, so hopefully someone else can enlighten us :)

[micves]

I have done some tests using https://github.com/tdorssers/TeslaPy

My code is here if somebody would like to try it out:

#!/usr/bin/env python
import teslapy
from datetime import datetime
import time
import logging

state=None
code_verifier=None
#logging.basicConfig(level=logging.DEBUG)

# First stage
tesla = teslapy.Tesla('mymail@mail.com, retry=2, timeout=15)
if not tesla.authorized:
    state = tesla.new_state()
    code_verifier = tesla.new_code_verifier()
    print('Use browser to login. Page Not Found will be shown at success.')
    print('Open: ' + tesla.authorization_url(state=state, code_verifier=code_verifier))
    tesla.close()
    # Second stage
    tesla = teslapy.Tesla('mymail@mail.com', state=state, code_verifier=code_verifier)
    if not tesla.authorized:
        tesla.fetch_token(authorization_response=input('Enter URL after authentication: '))

vehicles = tesla.vehicle_list()
vehicle = vehicles[0]
current_state = vehicle.get_vehicle_summary()['state']
t_start = datetime.now()
print(str(datetime.now()) + ': ' + current_state)
last_state = current_state

#stream callback
def stream_cb(mydict):
    print(mydict)

time.sleep(10)
exCount = 0
try:
    while True:
        try:
            current_state = vehicle.get_vehicle_summary()['state']
            exCount = 0
        except Exception:
            exCount = exCount + 1 
            print(str(datetime.now()) + ": Exception "+ str(exCount) +", sleep 90")
            time.sleep(90)
        if last_state != current_state:
            t_end = datetime.now()
            print(str(datetime.now()) + ': ' + '{:>7}'.format(last_state) + ' for {:6.2f}'.format((t_end - t_start).total_seconds() / 60) + ' min, new state: ' + current_state)
            t_start = datetime.now()

            # start the stream
            vehicle.stream(stream_cb) # retry=12 seems to get more samples, but also locks up and no new states are detected

            # print(vehicle.get_latest_vehicle_data())
            # requests.exceptions.HTTPError: 404 Client Error: Not Found for url:
            # #https://owner-api.teslamotors.com/api/1/vehicles/{id}/latest_vehicle_data 
            # even in online state

        last_state = current_state
        time.sleep(10)
except KeyboardInterrupt:
    print('closing')
    tesla.close()

First test is with Teslamate off:

I start a stream every time there is a change in state:

2023-03-26 13:19:52.462120: offline
2023-03-26 14:07:37.737771: offline for  47.75 min, new state: online
{'soc': 64, 'elevation': 31, 'est_lat': xx.358406, 'power': None, 'est_range': 147, 'timestamp': 1679832428944, 'heading': 22, 'odometer': 86385.3, 'range': 171, 'est_lng': yy.571832, 'est_heading': 22, 'speed': None, 'shift_state': None}
2023-03-26 14:10:20.099877:  online for   2.71 min, new state: offline
2023-03-26 15:08:37.788812: offline for  58.29 min, new state: online
{'soc': 64, 'elevation': 31, 'est_lat': xx.358406, 'power': None, 'est_range': 147, 'timestamp': 1679836088398, 'heading': 22, 'odometer': 86385.3, 'range': 171, 'est_lng': yy.571832, 'est_heading': 22, 'speed': None, 'shift_state': None}
2023-03-26 15:11:20.035421:  online for   2.70 min, new state: offline

At this point, when the car is in offline, I open the Tesla app and thereby wake the car for real:

2023-03-26 15:47:01.532903: offline for  35.69 min, new state: online
{'soc': 64, 'elevation': 31, 'est_lat': xx.358406, 'power': 0, 'est_range': 146, 'timestamp': 1679838391939, 'heading': 22, 'odometer': 86385.3, 'range': 170, 'est_lng': yy.571832, 'est_heading': 22, 'speed': None, 'shift_state': None}

Notice the power says 0 instead of None.

I then tried with teslamate on, teslapy poll 10 sec and stream retry of 12 (hope to catch a None before teslamate poll vehicle_data)

2023-03-27 20:19:03.458722: offline
2023-03-27 20:35:03.836941: offline for  16.01 min, new state: online
{'soc': 68, 'elevation': 15, 'est_lat': xx.358393, 'power': None, 'est_range': 146, 'timestamp': 1679942102760, 'heading': 23, 'odometer': 86444.4, 'range': 179, 'est_lng': yy.571729, 'est_heading': 22, 'speed': None, 'shift_state': None}
{'soc': 68, 'elevation': 15, 'est_lat': xx.358393, 'power': None, 'est_range': 146, 'timestamp': 1679942113982, 'heading': 23, 'odometer': 86444.4, 'range': 179, 'est_lng': yy.571729, 'est_heading': 22, 'speed': None, 'shift_state': None}
{'soc': 68, 'elevation': 15, 'est_lat': xx.358393, 'power': 0, 'est_range': 146, 'timestamp': 1679942115733, 'heading': 23, 'odometer': 86444.4, 'range': 179, 'est_lng': yy.571729, 'est_heading': 22, 'speed': None, 'shift_state': None}
{'soc': 68, 'elevation': 15, 'est_lat': xx.358393, 'power': 0, 'est_range': 145, 'timestamp': 1679942116232, 'heading': 23, 'odometer': 86444.4, 'range': 179, 'est_lng': yy.571729, 'est_heading': 22, 'speed': None, 'shift_state': None}
{'soc': 68, 'elevation': 15, 'est_lat': xx.358393, 'power': 0, 'est_range': 145, 'timestamp': 1679942138041, 'heading': 23, 'odometer': 86444.4, 'range': 179, 'est_lng': yy.571729, 'est_heading': 22, 'speed': None, 'shift_state': None}
{'soc': 68, 'elevation': 15, 'est_lat': xx.358393, 'power': 0, 'est_range': 145, 'timestamp': 1679942149163, 'heading': 23, 'odometer': 86444.4, 'range': 179, 'est_lng': yy.571729, 'est_heading': 22, 'speed': None, 'shift_state': None}
{'soc': 68, 'elevation': 15, 'est_lat': xx.358393, 'power': 0, 'est_range': 145, 'timestamp': 1679942160357, 'heading': 23, 'odometer': 86444.4, 'range': 179, 'est_lng': yy.571729, 'est_heading': 22, 'speed': None, 'shift_state': None}
{'soc': 68, 'elevation': 15, 'est_lat': xx.358393, 'power': 0, 'est_range': 145, 'timestamp': 1679942206898, 'heading': 23, 'odometer': 86444.4, 'range': 179, 'est_lng': yy.571729, 'est_heading': 22, 'speed': None, 'shift_state': None}
{'soc': 68, 'elevation': 15, 'est_lat': xx.358393, 'power': 0, 'est_range': 145, 'timestamp': 1679942218158, 'heading': 23, 'odometer': 86444.4, 'range': 179, 'est_lng': yy.571729, 'est_heading': 22, 'speed': None, 'shift_state': None}
2023-03-27 20:50:20.295447:  online for  15.27 min, new state: offline

It seems that power is None when the online is the 'fake' online. power is 0 after teslamate requests a vehicle_data and wakes the car for real. (None is a python-thing, but I would guess Elixir gets nil, null or something similar)

Maybe this could be used in Teslamate for handling this issue?

[markusdd]

That is a VERY interesting observvation and maybe the key to finally get rid of this phantom drain.

@adriankumpf what do you say? I know very little about Elixir, might this be useful?

[sb1089]

I have the same issues awake/sleep issues with my Model S with upgraded MCU and I think it applies to more people indeed (https://github.com/adriankumpf/teslamate/issues/2556). I like your finding. Hopefully someone can implement this check into Teslamate. Currently I turn off Teslamate every night to preserve the battery drain.

[markusdd]

As a call to action here: I would be willing to look into this but my experience with Elixir is absolutely zero, as well as with this code base.

@adriankumpf do you have any time to address this based on what has been posted above or can you give at least a hint to the part of the code base where changes would likely need to be made?

I do run a manual install so doing local changes and recompile would be quite easy to do for me.

[markusdd]

@micves and @sb1089 as Adrian is unfortunately not responding at all for weeks now I tried to have a look myself and here seems to be the region where basically Teslamate falls for the 'fake' online state https://github.com/adriankumpf/teslamate/blob/00cb6efd4257021d4dad64f7d8719b6677d535f5/lib/teslamate/vehicles/vehicle.ex#L700

It then proceeds to poll the vehicle_data API und this directly correlates with this loooong online state that furthers battery drain.

So at this point we need to somehow recognize it is a fake online state and let the vehicle sleep.

[micves]

I also started looking into it myself last week. Never got around to write about it, but I'll try to describe my findings so far.

I also started with the log 'Start / :online' but couldn't really figure out how everything was working. Elixir is quite different to my other known languages :)

I got a development environment set up and added some more Log.info around the code. Old school debug, but it works. At some point I'll write my steps for that here: https://github.com/adriankumpf/teslamate/issues/1903

At 'Start / :online' it is too late to check if it is a fake online. The api call to vehicle_data has already been executed and woken the car up.

When the car is offline this regularly gets the state: https://github.com/adriankumpf/teslamate/blob/00cb6efd4257021d4dad64f7d8719b6677d535f5/lib/teslamate/vehicles/vehicle.ex#L1103

schedule_fetch ends up calling: https://github.com/adriankumpf/teslamate/blob/00cb6efd4257021d4dad64f7d8719b6677d535f5/lib/teslamate/vehicles/vehicle.ex#L1189

which in case of online (also fake online) calls: https://github.com/adriankumpf/teslamate/blob/00cb6efd4257021d4dad64f7d8719b6677d535f5/lib/teslamate/vehicles/vehicle.ex#L1217

that end up in here: https://github.com/adriankumpf/teslamate/blob/00cb6efd4257021d4dad64f7d8719b6677d535f5/lib/tesla_api/vehicle.ex#L54 (vehicle_data is the one waking the car completely)

I'm guessing 'Start / :online' is an event based on the fact that the state is online. I think this is the one setting it to online in the result_handler of the fetch: https://github.com/adriankumpf/teslamate/blob/00cb6efd4257021d4dad64f7d8719b6677d535f5/lib/teslamate/vehicles/vehicle.ex#L312

The stream is started in the same place as 'Start / :online'. This is a issue, that it is started so late, if we want to see if the power is nil or 0 to determine if its a fake or a real online. And we need that already in the fetch function.

This is kind of where I got stuck for now. And I'm a little scared of Elixir :D

[markusdd]

I can relate. I would not even say that I am completely devoid of understanding how functional programming works but Elixir is just somethign else. The syntax is...special. To be kind.

I can follow what you are saying and agree with it. we probably somehow need to pick apart that last statement and make sure whenever power shows something similar to a NULL value we just act as if the car is asleep.

[markusdd]

and I just try it again: @adriankumpf if you don't have the time that is ok, but can you at least give us SOME hint where we need to look to apply a fix for this? I think we are pretty close here but Elixir makes it really hard. I have real issues understanding the control flow of this code :(

[markusdd]

Ok I now also put in some logging in my installation and it is a hard one to catch:

Teslamate correctly suspends logging after some time after a drive and goes into stream only mode. Then at some point weird error messages come as the car transistions into offline, which seems to not be gracefully handled. (but at least it goes offline) But about an hour later an unsolited API call happens, waking up the car.

As you can see there are no detailed logs, so I still have not found the location in the code where this call happens and first and foremost: WHY.

This is frustrating...

[micves]

I think the errors are not handled gracefully because its a rare behavior that only MCU2 upgraded cars do. All other cars are in either asleep or online.

I have talked to a Tesla service center that says it normal behavior for a MCU2 upgraded car to be offline ~1hour and online for 2-3 minutes. Also with no 3rd party access. It is the car waking it self up to check sub-systems. When it does this it apparently shows itself as online in the API.

So that is something we cannot control. But we can fix the extension of online and going from subsystem online to real online.

I think your API call starts at the line i also wrote in my last post. If you put in a log here after the 'do' you will get the initiator: https://github.com/adriankumpf/teslamate/blob/00cb6efd4257021d4dad64f7d8719b6677d535f5/lib/teslamate/vehicles/vehicle.ex#L1101-L1104

This however happens every 30 seconds so it will flood the log.

So every 30 seconds you get into the fetch_with_unreachable_assumption: https://github.com/adriankumpf/teslamate/blob/00cb6efd4257021d4dad64f7d8719b6677d535f5/lib/teslamate/vehicles/vehicle.ex#L1215-L1219

I'm guessing your log is just before the 'call(deps.api, :get_vehicle_with_state, [id])'

But look at the line above: 'with {:ok, %Vehicle{state: "online"}} <- call(deps.api, :get_vehicle, [id]) do'

As I see that line it calls the get_vehicle function that gets the state of the car without waking the car. If the car is online (in our case to check sub-systems) it will call the get_vehicle_with_state

[markusdd]

Good point.

Still, I am unsure how to distinguish between 'real online' and 'fake online'. Below you see a logging which I put in all 5 'offline/asleep' handle_event functions. When the car is offline, it constantly uses the first function and the saved data is power: nil, shift_state unknown. It then suddenly uses the 5th function, where power becomes 0 and shift_state nil, afterwards the wakeup happens. But this is also the case in regular online state...

Apr 28 15:20:40 tesla teslamate[171598]: 2023-04-28 15:20:40.552 [info] In 1. asleep/offline handle_event function in state: offline and power: %TeslaMate.Vehicles.Vehicle.Data{
Apr 28 15:20:40 tesla teslamate[171598]:   car: %TeslaMate.Log.Car{
Apr 28 15:20:40 tesla teslamate[171598]:     __meta__: #Ecto.Schema.Metadata<:loaded, "cars">,
Apr 28 15:20:40 tesla teslamate[171598]:     charging_processes: #Ecto.Association.NotLoaded<association :charging_processes is not loaded>,
Apr 28 15:20:40 tesla teslamate[171598]:     drives: #Ecto.Association.NotLoaded<association :drives is not loaded>,
Apr 28 15:20:40 tesla teslamate[171598]:     efficiency: 0.185,
Apr 28 15:20:40 tesla teslamate[171598]:     eid: 1492932437245351,
Apr 28 15:20:40 tesla teslamate[171598]:     exterior_color: "SteelGrey",
Apr 28 15:20:40 tesla teslamate[171598]:     id: 1,
Apr 28 15:20:40 tesla teslamate[171598]:     inserted_at: ~N[2020-01-12 11:48:53],
Apr 28 15:20:40 tesla teslamate[171598]:     marketing_name: nil,
Apr 28 15:20:40 tesla teslamate[171598]:     model: "S",
Apr 28 15:20:40 tesla teslamate[171598]:     name: "Hyperion",
Apr 28 15:20:40 tesla teslamate[171598]:     positions: #Ecto.Association.NotLoaded<association :positions is not loaded>,
Apr 28 15:20:40 tesla teslamate[171598]:     settings: %TeslaMate.Settings.CarSettings{
Apr 28 15:20:40 tesla teslamate[171598]:       __meta__: #Ecto.Schema.Metadata<:loaded, "car_settings">,
Apr 28 15:20:40 tesla teslamate[171598]:       car: #Ecto.Association.NotLoaded<association :car is not loaded>,
Apr 28 15:20:40 tesla teslamate[171598]:       free_supercharging: true,
Apr 28 15:20:40 tesla teslamate[171598]:       id: 1,
Apr 28 15:20:40 tesla teslamate[171598]:       req_not_unlocked: true,
Apr 28 15:20:40 tesla teslamate[171598]:       suspend_after_idle_min: 15,
Apr 28 15:20:40 tesla teslamate[171598]:       suspend_min: 21,
Apr 28 15:20:40 tesla teslamate[171598]:       use_streaming_api: true
Apr 28 15:20:40 tesla teslamate[171598]:     },
Apr 28 15:20:40 tesla teslamate[171598]:     settings_id: 1,
Apr 28 15:20:40 tesla teslamate[171598]:     spoiler_type: "None",
Apr 28 15:20:40 tesla teslamate[171598]:     trim_badging: "85D",
Apr 28 15:20:40 tesla teslamate[171598]:     updated_at: ~N[2023-02-16 18:49:49],
Apr 28 15:20:40 tesla teslamate[171598]:     vid: 252208806,
Apr 28 15:20:40 tesla teslamate[171598]:     vin: "xxx",
Apr 28 15:20:40 tesla teslamate[171598]:     wheel_type: "Turbine19"
Apr 28 15:20:40 tesla teslamate[171598]:   },
Apr 28 15:20:40 tesla teslamate[171598]:   deps: %{
Apr 28 15:20:40 tesla teslamate[171598]:     api: TeslaMate.Api,
Apr 28 15:20:40 tesla teslamate[171598]:     locations: TeslaMate.Locations,
Apr 28 15:20:40 tesla teslamate[171598]:     log: TeslaMate.Log,
Apr 28 15:20:40 tesla teslamate[171598]:     pubsub: Phoenix.PubSub,
Apr 28 15:20:40 tesla teslamate[171598]:     settings: TeslaMate.Settings,
Apr 28 15:20:40 tesla teslamate[171598]:     vehicles: TeslaMate.Vehicles
Apr 28 15:20:40 tesla teslamate[171598]:   },
Apr 28 15:20:40 tesla teslamate[171598]:   elevation: nil,
Apr 28 15:20:40 tesla teslamate[171598]:   geofence: nil,
Apr 28 15:20:40 tesla teslamate[171598]:   import?: false,
Apr 28 15:20:40 tesla teslamate[171598]:   last_response: %TeslaApi.Vehicle{
Apr 28 15:20:40 tesla teslamate[171598]:     api_version: 54,
Apr 28 15:20:40 tesla teslamate[171598]:     backseat_token: nil,
Apr 28 15:20:40 tesla teslamate[171598]:     backseat_token_updated_at: nil,
Apr 28 15:20:40 tesla teslamate[171598]:     calendar_enabled: true,
Apr 28 15:20:40 tesla teslamate[171598]:     charge_state: %TeslaApi.Vehicle.State.Charge{
Apr 28 15:20:40 tesla teslamate[171598]:       charge_port_latch: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       scheduled_charging_pending: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charge_current_request_max: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       fast_charger_type: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charge_limit_soc_min: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charge_to_max_range: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       time_to_full_charge: :unknown,
Apr 28 15:20:40 tesla teslamate[171598]:       charge_miles_added_rated: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charge_miles_added_ideal: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       fast_charger_present: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charger_phases: :unknown,
Apr 28 15:20:40 tesla teslamate[171598]:       scheduled_charging_start_time: :unknown,
Apr 28 15:20:40 tesla teslamate[171598]:       not_enough_power_to_heat: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charge_limit_soc_std: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charge_port_cold_weather_mode: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       managed_charging_start_time: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charger_actual_current: :unknown,
Apr 28 15:20:40 tesla teslamate[171598]:       timestamp: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       ideal_battery_range: 159.53,
Apr 28 15:20:40 tesla teslamate[171598]:       charger_power: :unknown,
Apr 28 15:20:40 tesla teslamate[171598]:       battery_level: 65,
Apr 28 15:20:40 tesla teslamate[171598]:       max_range_charge_counter: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charge_current_request: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       trip_charging: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charge_port_door_open: :unknown,
Apr 28 15:20:40 tesla teslamate[171598]:       conn_charge_cable: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       fast_charger_brand: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charge_energy_added: :unknown,
Apr 28 15:20:40 tesla teslamate[171598]:       charging_state: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       battery_heater_on: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charger_pilot_current: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charge_rate: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       battery_range: 199.41,
Apr 28 15:20:40 tesla teslamate[171598]:       est_battery_range: 136.61,
Apr 28 15:20:40 tesla teslamate[171598]:       managed_charging_active: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       charge_limit_soc: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       usable_battery_level: 65,
Apr 28 15:20:40 tesla teslamate[171598]:       charger_voltage: :unknown,
Apr 28 15:20:40 tesla teslamate[171598]:       charge_limit_soc_max: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       ...
Apr 28 15:20:40 tesla teslamate[171598]:     },
Apr 28 15:20:40 tesla teslamate[171598]:     climate_state: %TeslaApi.Vehicle.State.Climate{
Apr 28 15:20:40 tesla teslamate[171598]:       battery_heater: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       battery_heater_no_power: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       climate_keeper_mode: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       defrost_mode: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       driver_temp_setting: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       fan_status: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       inside_temp: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       is_auto_conditioning_on: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       is_climate_on: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       is_front_defroster_on: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       is_preconditioning: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       is_rear_defroster_on: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       left_temp_direction: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       max_avail_temp: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       min_avail_temp: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       outside_temp: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       passenger_temp_setting: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       remote_heater_control_enabled: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       right_temp_direction: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       seat_heater_left: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       seat_heater_rear_center: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       seat_heater_rear_left: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       seat_heater_rear_left_back: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       seat_heater_rear_right: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       seat_heater_rear_right_back: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       seat_heater_right: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       side_mirror_heaters: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       smart_preconditioning: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       steering_wheel_heater: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       timestamp: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       wiper_blade_heater: nil
Apr 28 15:20:40 tesla teslamate[171598]:     },
Apr 28 15:20:40 tesla teslamate[171598]:     color: nil,
Apr 28 15:20:40 tesla teslamate[171598]:     display_name: "Hyperion",
Apr 28 15:20:40 tesla teslamate[171598]:     drive_state: %TeslaApi.Vehicle.State.Drive{
Apr 28 15:20:40 tesla teslamate[171598]:       gps_as_of: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       heading: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       latitude: #Decimal<51.057609>,
Apr 28 15:20:40 tesla teslamate[171598]:       longitude: #Decimal<13.772231>,
Apr 28 15:20:40 tesla teslamate[171598]:       native_latitude: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       native_location_supported: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       native_longitude: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       native_type: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       power: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       shift_state: :unknown,
Apr 28 15:20:40 tesla teslamate[171598]:       speed: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       timestamp: nil
Apr 28 15:20:40 tesla teslamate[171598]:     },
Apr 28 15:20:40 tesla teslamate[171598]:     gui_settings: nil,
Apr 28 15:20:40 tesla teslamate[171598]:     id: 1492932437245351,
Apr 28 15:20:40 tesla teslamate[171598]:     in_service: false,
Apr 28 15:20:40 tesla teslamate[171598]:     option_codes: [""],
Apr 28 15:20:40 tesla teslamate[171598]:     state: "offline",
Apr 28 15:20:40 tesla teslamate[171598]:     tokens: ["xxx", "xxx"],
Apr 28 15:20:40 tesla teslamate[171598]:     vehicle_config: nil,
Apr 28 15:20:40 tesla teslamate[171598]:     vehicle_id: 252208806,
Apr 28 15:20:40 tesla teslamate[171598]:     vehicle_state: %TeslaApi.Vehicle.State.VehicleState{
Apr 28 15:20:40 tesla teslamate[171598]:       is_user_present: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       valet_mode: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       tpms_pressure_fl: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       api_version: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       valet_pin_needed: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       fd_window: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       last_autopark_error: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       rp_window: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       sentry_mode: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       car_version: "2023.6.8 ca519fc096f3",
Apr 28 15:20:40 tesla teslamate[171598]:       pf: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       summon_standby_mode_enabled: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       remote_start_enabled: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       remote_start: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       autopark_state_v3: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       dr: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       homelink_nearby: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       calendar_supported: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       timestamp: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       parsed_calendar_supported: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       notifications_supported: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       software_update: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       ft: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       odometer: 79548.755613,
Apr 28 15:20:40 tesla teslamate[171598]:       autopark_style: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       fp_window: nil,
Apr 28 15:20:40 tesla teslamate[171598]:       ...
Apr 28 15:20:40 tesla teslamate[171598]:     },
Apr 28 15:20:40 tesla teslamate[171598]:     vin: "xxx"
Apr 28 15:20:40 tesla teslamate[171598]:   },
Apr 28 15:20:40 tesla teslamate[171598]:   last_state_change: ~U[2023-04-28 12:23:08.129649Z],
Apr 28 15:20:40 tesla teslamate[171598]:   last_used: ~U[2023-04-28 12:42:21.858508Z],
Apr 28 15:20:40 tesla teslamate[171598]:   stream_pid: nil,
Apr 28 15:20:40 tesla teslamate[171598]:   task: nil
Apr 28 15:20:40 tesla teslamate[171598]: }
Apr 28 15:21:10 tesla teslamate[171598]: 2023-04-28 15:21:10.653 [info] In fetch_with_unreachable_assumption
Apr 28 15:21:12 tesla teslamate[171598]: 2023-04-28 15:21:12.250 [info] In 5. asleep/offline handle_event function in state: offline and power: %TeslaMate.Vehicles.Vehicle.Data{
Apr 28 15:21:12 tesla teslamate[171598]:   car: %TeslaMate.Log.Car{
Apr 28 15:21:12 tesla teslamate[171598]:     __meta__: #Ecto.Schema.Metadata<:loaded, "cars">,
Apr 28 15:21:12 tesla teslamate[171598]:     charging_processes: #Ecto.Association.NotLoaded<association :charging_processes is not loaded>,
Apr 28 15:21:12 tesla teslamate[171598]:     drives: #Ecto.Association.NotLoaded<association :drives is not loaded>,
Apr 28 15:21:12 tesla teslamate[171598]:     efficiency: 0.185,
Apr 28 15:21:12 tesla teslamate[171598]:     eid: 1492932437245351,
Apr 28 15:21:12 tesla teslamate[171598]:     exterior_color: "SteelGrey",
Apr 28 15:21:12 tesla teslamate[171598]:     id: 1,
Apr 28 15:21:12 tesla teslamate[171598]:     inserted_at: ~N[2020-01-12 11:48:53],
Apr 28 15:21:12 tesla teslamate[171598]:     marketing_name: nil,
Apr 28 15:21:12 tesla teslamate[171598]:     model: "S",
Apr 28 15:21:12 tesla teslamate[171598]:     name: "Hyperion",
Apr 28 15:21:12 tesla teslamate[171598]:     positions: #Ecto.Association.NotLoaded<association :positions is not loaded>,
Apr 28 15:21:12 tesla teslamate[171598]:     settings: %TeslaMate.Settings.CarSettings{
Apr 28 15:21:12 tesla teslamate[171598]:       __meta__: #Ecto.Schema.Metadata<:loaded, "car_settings">,
Apr 28 15:21:12 tesla teslamate[171598]:       car: #Ecto.Association.NotLoaded<association :car is not loaded>,
Apr 28 15:21:12 tesla teslamate[171598]:       free_supercharging: true,
Apr 28 15:21:12 tesla teslamate[171598]:       id: 1,
Apr 28 15:21:12 tesla teslamate[171598]:       req_not_unlocked: true,
Apr 28 15:21:12 tesla teslamate[171598]:       suspend_after_idle_min: 15,
Apr 28 15:21:12 tesla teslamate[171598]:       suspend_min: 21,
Apr 28 15:21:12 tesla teslamate[171598]:       use_streaming_api: true
Apr 28 15:21:12 tesla teslamate[171598]:     },
Apr 28 15:21:12 tesla teslamate[171598]:     settings_id: 1,
Apr 28 15:21:12 tesla teslamate[171598]:     spoiler_type: "None",
Apr 28 15:21:12 tesla teslamate[171598]:     trim_badging: "85D",
Apr 28 15:21:12 tesla teslamate[171598]:     updated_at: ~N[2023-02-16 18:49:49],
Apr 28 15:21:12 tesla teslamate[171598]:     vid: 252208806,
Apr 28 15:21:12 tesla teslamate[171598]:     vin: "xxx",
Apr 28 15:21:12 tesla teslamate[171598]:     wheel_type: "Turbine19"
Apr 28 15:21:12 tesla teslamate[171598]:   },
Apr 28 15:21:12 tesla teslamate[171598]:   deps: %{
Apr 28 15:21:12 tesla teslamate[171598]:     api: TeslaMate.Api,
Apr 28 15:21:12 tesla teslamate[171598]:     locations: TeslaMate.Locations,
Apr 28 15:21:12 tesla teslamate[171598]:     log: TeslaMate.Log,
Apr 28 15:21:12 tesla teslamate[171598]:     pubsub: Phoenix.PubSub,
Apr 28 15:21:12 tesla teslamate[171598]:     settings: TeslaMate.Settings,
Apr 28 15:21:12 tesla teslamate[171598]:     vehicles: TeslaMate.Vehicles
Apr 28 15:21:12 tesla teslamate[171598]:   },
Apr 28 15:21:12 tesla teslamate[171598]:   elevation: nil,
Apr 28 15:21:12 tesla teslamate[171598]:   geofence: nil,
Apr 28 15:21:12 tesla teslamate[171598]:   import?: false,
Apr 28 15:21:12 tesla teslamate[171598]:   last_response: %TeslaApi.Vehicle{
Apr 28 15:21:12 tesla teslamate[171598]:     api_version: 54,
Apr 28 15:21:12 tesla teslamate[171598]:     backseat_token: nil,
Apr 28 15:21:12 tesla teslamate[171598]:     backseat_token_updated_at: nil,
Apr 28 15:21:12 tesla teslamate[171598]:     calendar_enabled: true,
Apr 28 15:21:12 tesla teslamate[171598]:     charge_state: %TeslaApi.Vehicle.State.Charge{
Apr 28 15:21:12 tesla teslamate[171598]:       charge_port_latch: "<invalid>",
Apr 28 15:21:12 tesla teslamate[171598]:       scheduled_charging_pending: false,
Apr 28 15:21:12 tesla teslamate[171598]:       charge_current_request_max: 16,
Apr 28 15:21:12 tesla teslamate[171598]:       fast_charger_type: "<invalid>",
Apr 28 15:21:12 tesla teslamate[171598]:       charge_limit_soc_min: 50,
Apr 28 15:21:12 tesla teslamate[171598]:       charge_to_max_range: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       time_to_full_charge: 0.0,
Apr 28 15:21:12 tesla teslamate[171598]:       charge_miles_added_rated: 213.5,
Apr 28 15:21:12 tesla teslamate[171598]:       charge_miles_added_ideal: 171.0,
Apr 28 15:21:12 tesla teslamate[171598]:       fast_charger_present: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       charger_phases: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       scheduled_charging_start_time: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       not_enough_power_to_heat: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       charge_limit_soc_std: 90,
Apr 28 15:21:12 tesla teslamate[171598]:       charge_port_cold_weather_mode: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       managed_charging_start_time: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       charger_actual_current: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       timestamp: 1682688072094,
Apr 28 15:21:12 tesla teslamate[171598]:       ideal_battery_range: 159.53,
Apr 28 15:21:12 tesla teslamate[171598]:       charger_power: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       battery_level: 65,
Apr 28 15:21:12 tesla teslamate[171598]:       max_range_charge_counter: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       charge_current_request: 16,
Apr 28 15:21:12 tesla teslamate[171598]:       trip_charging: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       charge_port_door_open: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       conn_charge_cable: "<invalid>",
Apr 28 15:21:12 tesla teslamate[171598]:       fast_charger_brand: "<invalid>",
Apr 28 15:21:12 tesla teslamate[171598]:       charge_energy_added: 50.91,
Apr 28 15:21:12 tesla teslamate[171598]:       charging_state: "Disconnected",
Apr 28 15:21:12 tesla teslamate[171598]:       battery_heater_on: false,
Apr 28 15:21:12 tesla teslamate[171598]:       charger_pilot_current: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       charge_rate: 0.0,
Apr 28 15:21:12 tesla teslamate[171598]:       battery_range: 199.41,
Apr 28 15:21:12 tesla teslamate[171598]:       est_battery_range: 136.61,
Apr 28 15:21:12 tesla teslamate[171598]:       managed_charging_active: false,
Apr 28 15:21:12 tesla teslamate[171598]:       charge_limit_soc: 87,
Apr 28 15:21:12 tesla teslamate[171598]:       usable_battery_level: 65,
Apr 28 15:21:12 tesla teslamate[171598]:       charger_voltage: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       charge_limit_soc_max: 100,
Apr 28 15:21:12 tesla teslamate[171598]:       ...
Apr 28 15:21:12 tesla teslamate[171598]:     },
Apr 28 15:21:12 tesla teslamate[171598]:     climate_state: %TeslaApi.Vehicle.State.Climate{
Apr 28 15:21:12 tesla teslamate[171598]:       battery_heater: false,
Apr 28 15:21:12 tesla teslamate[171598]:       battery_heater_no_power: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       climate_keeper_mode: "off",
Apr 28 15:21:12 tesla teslamate[171598]:       defrost_mode: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       driver_temp_setting: 23.0,
Apr 28 15:21:12 tesla teslamate[171598]:       fan_status: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       inside_temp: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       is_auto_conditioning_on: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       is_climate_on: false,
Apr 28 15:21:12 tesla teslamate[171598]:       is_front_defroster_on: false,
Apr 28 15:21:12 tesla teslamate[171598]:       is_preconditioning: false,
Apr 28 15:21:12 tesla teslamate[171598]:       is_rear_defroster_on: false,
Apr 28 15:21:12 tesla teslamate[171598]:       left_temp_direction: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       max_avail_temp: 28.0,
Apr 28 15:21:12 tesla teslamate[171598]:       min_avail_temp: 15.0,
Apr 28 15:21:12 tesla teslamate[171598]:       outside_temp: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       passenger_temp_setting: 23.0,
Apr 28 15:21:12 tesla teslamate[171598]:       remote_heater_control_enabled: false,
Apr 28 15:21:12 tesla teslamate[171598]:       right_temp_direction: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       seat_heater_left: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       seat_heater_rear_center: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       seat_heater_rear_left: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       seat_heater_rear_left_back: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       seat_heater_rear_right: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       seat_heater_rear_right_back: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       seat_heater_right: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       side_mirror_heaters: false,
Apr 28 15:21:12 tesla teslamate[171598]:       smart_preconditioning: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       steering_wheel_heater: false,
Apr 28 15:21:12 tesla teslamate[171598]:       timestamp: 1682688072094,
Apr 28 15:21:12 tesla teslamate[171598]:       wiper_blade_heater: false
Apr 28 15:21:12 tesla teslamate[171598]:     },
Apr 28 15:21:12 tesla teslamate[171598]:     color: nil,
Apr 28 15:21:12 tesla teslamate[171598]:     display_name: "Hyperion",
Apr 28 15:21:12 tesla teslamate[171598]:     drive_state: %TeslaApi.Vehicle.State.Drive{
Apr 28 15:21:12 tesla teslamate[171598]:       gps_as_of: 1682688070,
Apr 28 15:21:12 tesla teslamate[171598]:       heading: 71,
Apr 28 15:21:12 tesla teslamate[171598]:       latitude: 51.057609,
Apr 28 15:21:12 tesla teslamate[171598]:       longitude: 13.772231,
Apr 28 15:21:12 tesla teslamate[171598]:       native_latitude: 51.057609,
Apr 28 15:21:12 tesla teslamate[171598]:       native_location_supported: 1,
Apr 28 15:21:12 tesla teslamate[171598]:       native_longitude: 13.772231,
Apr 28 15:21:12 tesla teslamate[171598]:       native_type: "wgs",
Apr 28 15:21:12 tesla teslamate[171598]:       power: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       shift_state: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       speed: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       timestamp: 1682688072094
Apr 28 15:21:12 tesla teslamate[171598]:     },
Apr 28 15:21:12 tesla teslamate[171598]:     gui_settings: nil,
Apr 28 15:21:12 tesla teslamate[171598]:     id: 1492932437245351,
Apr 28 15:21:12 tesla teslamate[171598]:     in_service: false,
Apr 28 15:21:12 tesla teslamate[171598]:     option_codes: [""],
Apr 28 15:21:12 tesla teslamate[171598]:     state: "online",
Apr 28 15:21:12 tesla teslamate[171598]:     tokens: ["xxx", "xxx"],
Apr 28 15:21:12 tesla teslamate[171598]:     vehicle_config: %TeslaApi.Vehicle.State.VehicleConfig{
Apr 28 15:21:12 tesla teslamate[171598]:       can_accept_navigation_requests: true,
Apr 28 15:21:12 tesla teslamate[171598]:       can_actuate_trunks: true,
Apr 28 15:21:12 tesla teslamate[171598]:       car_special_type: "base",
Apr 28 15:21:12 tesla teslamate[171598]:       car_type: "models",
Apr 28 15:21:12 tesla teslamate[171598]:       charge_port_type: "EU",
Apr 28 15:21:12 tesla teslamate[171598]:       eu_vehicle: true,
Apr 28 15:21:12 tesla teslamate[171598]:       exterior_color: "SteelGrey",
Apr 28 15:21:12 tesla teslamate[171598]:       has_air_suspension: true,
Apr 28 15:21:12 tesla teslamate[171598]:       has_ludicrous_mode: false,
Apr 28 15:21:12 tesla teslamate[171598]:       key_version: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       motorized_charge_port: false,
Apr 28 15:21:12 tesla teslamate[171598]:       perf_config: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       plg: true,
Apr 28 15:21:12 tesla teslamate[171598]:       rear_seat_heaters: 1,
Apr 28 15:21:12 tesla teslamate[171598]:       rear_seat_type: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       rhd: false,
Apr 28 15:21:12 tesla teslamate[171598]:       roof_color: "None",
Apr 28 15:21:12 tesla teslamate[171598]:       seat_type: 1,
Apr 28 15:21:12 tesla teslamate[171598]:       spoiler_type: "None",
Apr 28 15:21:12 tesla teslamate[171598]:       sun_roof_installed: 1,
Apr 28 15:21:12 tesla teslamate[171598]:       third_row_seats: "None",
Apr 28 15:21:12 tesla teslamate[171598]:       timestamp: 1682688072094,
Apr 28 15:21:12 tesla teslamate[171598]:       trim_badging: "85d",
Apr 28 15:21:12 tesla teslamate[171598]:       use_range_badging: false,
Apr 28 15:21:12 tesla teslamate[171598]:       wheel_type: "Turbine19"
Apr 28 15:21:12 tesla teslamate[171598]:     },
Apr 28 15:21:12 tesla teslamate[171598]:     vehicle_id: 252208806,
Apr 28 15:21:12 tesla teslamate[171598]:     vehicle_state: %TeslaApi.Vehicle.State.VehicleState{
Apr 28 15:21:12 tesla teslamate[171598]:       is_user_present: false,
Apr 28 15:21:12 tesla teslamate[171598]:       valet_mode: false,
Apr 28 15:21:12 tesla teslamate[171598]:       tpms_pressure_fl: 2.975,
Apr 28 15:21:12 tesla teslamate[171598]:       api_version: 54,
Apr 28 15:21:12 tesla teslamate[171598]:       valet_pin_needed: true,
Apr 28 15:21:12 tesla teslamate[171598]:       fd_window: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       last_autopark_error: "no_error",
Apr 28 15:21:12 tesla teslamate[171598]:       rp_window: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       sentry_mode: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       car_version: "2023.6.8 ca519fc096f3",
Apr 28 15:21:12 tesla teslamate[171598]:       pf: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       summon_standby_mode_enabled: false,
Apr 28 15:21:12 tesla teslamate[171598]:       remote_start_enabled: true,
Apr 28 15:21:12 tesla teslamate[171598]:       remote_start: false,
Apr 28 15:21:12 tesla teslamate[171598]:       autopark_state_v3: nil,
Apr 28 15:21:12 tesla teslamate[171598]:       dr: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       homelink_nearby: false,
Apr 28 15:21:12 tesla teslamate[171598]:       calendar_supported: true,
Apr 28 15:21:12 tesla teslamate[171598]:       timestamp: 1682688072094,
Apr 28 15:21:12 tesla teslamate[171598]:       parsed_calendar_supported: true,
Apr 28 15:21:12 tesla teslamate[171598]:       notifications_supported: true,
Apr 28 15:21:12 tesla teslamate[171598]:       software_update: %TeslaApi.Vehicle.State.VehicleState.SoftwareUpdate{
Apr 28 15:21:12 tesla teslamate[171598]:         download_perc: 0,
Apr 28 15:21:12 tesla teslamate[171598]:         expected_duration_sec: 2700,
Apr 28 15:21:12 tesla teslamate[171598]:         install_perc: 1,
Apr 28 15:21:12 tesla teslamate[171598]:         scheduled_time_ms: nil,
Apr 28 15:21:12 tesla teslamate[171598]:         ...
Apr 28 15:21:12 tesla teslamate[171598]:       },
Apr 28 15:21:12 tesla teslamate[171598]:       ft: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       odometer: 79548.755613,
Apr 28 15:21:12 tesla teslamate[171598]:       autopark_style: "dead_man",
Apr 28 15:21:12 tesla teslamate[171598]:       fp_window: 0,
Apr 28 15:21:12 tesla teslamate[171598]:       ...
Apr 28 15:21:12 tesla teslamate[171598]:     },
Apr 28 15:21:12 tesla teslamate[171598]:     vin: "xxx"
Apr 28 15:21:12 tesla teslamate[171598]:   },
Apr 28 15:21:12 tesla teslamate[171598]:   last_state_change: ~U[2023-04-28 12:23:08.129649Z],
Apr 28 15:21:12 tesla teslamate[171598]:   last_used: ~U[2023-04-28 12:42:21.858508Z],
Apr 28 15:21:12 tesla teslamate[171598]:   stream_pid: nil,
Apr 28 15:21:12 tesla teslamate[171598]:   task: nil
Apr 28 15:21:12 tesla teslamate[171598]: }
Apr 28 15:21:12 tesla teslamate[171598]: 2023-04-28 15:21:12.250 car_id=1 [info] Start / :online
Apr 28 15:21:12 tesla teslamate[171598]: 2023-04-28 15:21:12.259 car_id=1 [info] Connecting ...
Apr 28 15:21:12 tesla teslamate[171598]: 2023-04-28 15:21:12.260 [info] Car can sleep (in function can_fall_asleep). power: 0 shift_state:
Apr 28 15:21:13 tesla teslamate[171598]: 2023-04-28 15:21:13.675 [info] In Streaming API (Online): %TeslaApi.Stream.Data{elevation: 114, est_heading: 71, est_lat: 51.057609, est_lng: 13.772231, est_range: 137, heading: 71, odometer: 79548.8, power: 0, range: 199, shift_state: nil, soc: 65, speed: nil, time: ~U[2023-04-28 13:21:12.638Z]}
Apr 28 15:21:13 tesla teslamate[171598]: 2023-04-28 15:21:13.677 [info] In Streaming API (Online): %TeslaApi.Stream.Data{elevation: 114, est_heading: 71, est_lat: 51.057609, est_lng: 13.772231, est_range: 135, heading: 71, odometer: 79548.8, power: 0, range: 199, shift_state: nil, soc: 65, speed: nil, time: ~U[2023-04-28 13:21:13.139Z]}
Apr 28 15:21:23 tesla teslamate[171598]: 2023-04-28 15:21:23.225 [info] In Streaming API (Online): %TeslaApi.Stream.Data{elevation: 114, est_heading: 71, est_lat: 51.057609, est_lng: 13.772231, est_range: 136, heading: 71, odometer: 79548.8, power: 0, range: 199, shift_state: nil, soc: 65, speed: nil, time: ~U[2023-04-28 13:21:23.139Z]}
Apr 28 15:21:42 tesla teslamate[171598]: 2023-04-28 15:21:42.558 [info] Car can sleep (in function can_fall_asleep). power: 0 shift_state:
Apr 28 15:21:49 tesla teslamate[171598]: 2023-04-28 15:21:49.351 [info] In Streaming API (Online): %TeslaApi.Stream.Data{elevation: 114, est_heading: 71, est_lat: 51.057609, est_lng: 13.772231, est_range: 136, heading: 71, odometer: 79548.8, power: 0, range: 199, shift_state: nil, soc: 65, speed: nil, time: ~U[2023-04-28 13:21:48.409Z]}
Apr 28 15:22:12 tesla teslamate[171598]: 2023-04-28 15:22:12.841 [info] Car can sleep (in function can_fall_asleep). power: 0 shift_state:
Apr 28 15:22:15 tesla teslamate[171598]: 2023-04-28 15:22:15.616 [info] In Streaming API (Online): %TeslaApi.Stream.Data{elevation: 114, est_heading: 71, est_lat: 51.057609, est_lng: 13.772231, est_range: 136, heading: 71, odometer: 79548.8, power: 0, range: 199, shift_state: nil, soc: 65, speed: nil, time: ~U[2023-04-28 13:22:14.568Z]}
Apr 28 15:22:41 tesla teslamate[171598]: 2023-04-28 15:22:41.674 [info] In Streaming API (Online): %TeslaApi.Stream.Data{elevation: 114, est_heading: 71, est_lat: 51.057609, est_lng: 13.772231, est_range: 136, heading: 71, odometer: 79548.8, power: 0, range: 199, shift_state: nil, soc: 65, speed: nil, time: ~U[2023-04-28 13:22:40.762Z]}
Apr 28 15:22:44 tesla teslamate[171598]: 2023-04-28 15:22:44.297 [info] Car can sleep (in function can_fall_asleep). power: 0 shift_state:

[markusdd]

Ok, so I modified the function a little and this is interesting:

I basically pulled out the call and dumped the data we get

State says online, but everything else is nil, nevertheless Teslamate tries to pull the full state.

So...would the proper fix be to check if any of the other state are not nil and just plain ignore the state?

[micves]

What does it print when its a real online (open the app)?

My experiments with TeslaPy did not show any difference in the equivalent to get_vehicle when it was a fake online compared to real online.

The only thing I found different was the power in the message from streaming. I had to start the stream to get those. The power in vehicle_data might not be the same. And the power in Teslamates object VehicleApi.Vehicle might be both in the sense that both messages updates the object.

[markusdd]

I tried with the app and it is no different.

The car just went offline now, and I do not understand why and how this sequence happens. At some point the API URL fails, still streaming continues, then URL fails again then this stack of vehicle is offline happens and then Teslamate decides the car is offline. This does not make any sense to me. Why is the car suddenly sleeping anyway?

[markusdd]

I am still at a loss to understand how Teslamate even decides a car is now offline. That is all so confusing.

I have now 'mined' the fetch functions with logging and I cannot understand it. Like it literally prints 'vehicle is offline', it shows offline in grafana, but the last fetch above says state is online...this is robbing my sleep.

Is it taking the 408 HTML response as a sleep indicator? What is triggering this 'fetching vehicle state...'? And what makes it decide finally the car is online again?

[markusdd]

I think I slowly understand what is going on.

I think when the car wakes up it is absolutely no problem to consider it online, even if it is the 'fake' online, as teslamate relatively quickly goes into suspended mode where it only polls the streaming API but not the state API.

I think the issue is this:

there are regulary polls to the non streaming API (not the waking one though) but when these fail (for whatever reason this happens regulary on MCU2 cars, probably when the car just wanted to go to sleep) then it triggers an uncoditional fetch_with_unreachable_assumption, the streaming API still says online, but it interrupts the 'suspended mode', hence hindering the car from truly sleeping:

I think when we are in suspended mode, and there is no reason to leave that mode (and an API call fail isn't one of them, especially if the stream is still running), there must not be a fetch of vehicle_data. That is the whole point of suspend mode.

So essentially my theory would be: if car in suspend mode, disallow those fetches.

What do you say?

[micves]

I agree that it is no problem to be in online state as long as the get_vehicle_with_state is not called.

Havent looked into suspended. The what, when and how. It does make sense not to call get_vehicle_with_state in suspended.

But there are still cases that are not covered. I'm guessing suspended is different from offline. When we come from offline to fake online, we also do not want to call get_vehicle_with_state, as it extends the online time (or actually makes the car go from fake to real for no reason)

I have testet a little with replaced the get_vehicle_with_state with the non-waking get_vehicle. Cant really share the log at the moment as it is in dev mode and prints millions of lines :)

Doing this replace of course makes everything weird, but I found a place to start the stream. And when data comes in check on power: The fake online is a power=nil The real online (open app) is a power=0

At the moment it never goes to real online in teslamate, as this is apperantly based on get_vehicle_with_state. I need to find a way to switch to online when stream data comes in with a 0.

Something else to think about (robbing the sleep... :D ) is what about cars that originally have the MCU2. They might act differently :|

[markusdd]

suspended is not a state of the car. It is a strategy by Teslamate if nothing is going on (no_charge, no sentry, no service, no drive, no climate etc.) to not poll the API and hence let the car go to sleep. What happens in suspended though is that apparently every 30 minutes the car is anyway being polled. For our 'special MCU2 cars this fails with a socket closed message on the non-vehicle_data API. It is then brute-force retried on the vehicle_data API, which again leads to a wake-lock of the vehicle. This must not happen, because exactly this sequence is what causes the majority of the phantom drain as it keeps the car awake for hours on end.

I have not yet understood though why this wakelock breaks. At some point the car just seems to 'force-sleep' and then we enter this mysterious sequence here:

I have no idea why that happens, because my surrounding print outs all still say state' online'. But after that, teslmate decides the car is sleeping and goes to offline mode:

The next wakeup then occurs presumably when we once again have the 'fake-online' going on which teslamate picks up on and then teh wakelock start anew...

[markusdd]

Here is another picture perfect example just now:

Teslamate is in suspend mode. Just Streaming API running. Then it suddenly tries to fetch, it fails with a socket closed error, then it retries, and then we have the wakelock.

[markusdd]

what is surprising is the case where it actually goes into offline. It uses a sifferent one of the fetch functions and the api response is not socket closed but nil. It then fetches again against non-vehicle_data URL and detmines the car is offline.

What does the streaming API say in those circumstances?

[markusdd]

Another interesting observation:

I changed the fetch schedule in suspend mode from 30 to 60 minutes. The data from the Streaming API does not budge. Is that by design?

This way you will never see it go offline. Do you actually have to poll the non vehicle_data URL to find out?

[micves]

As I understand it Teslamate state is based on what comes in as response from the non-vehicle_data URL. If you print the state that the Teslamate object holds, it might not have been updated yet. I'm guessing you are on a prod build. You can change this to :debug instead of :info https://github.com/adriankumpf/teslamate/blob/00cb6efd4257021d4dad64f7d8719b6677d535f5/config/prod.exs#L9-L10 which will write alot more messages. Including the actual GET requests and responses.

And I dont think the streaming API can keep the car awake, and also not wake it up. You have to poll either the vehicle_data or the other one to get the state.

In the code I have running now, I try to start the stream whenever there is a result in from the fetch with non-vehicle_data The stream response is sometimes just :inactive and shortly after the car goes offline.

And I think you have some double trouble going on. I don't have the socket close errors or timeouts (at the moment anyways) I guess Teslamate really want some data when error occurs. And thats just to aggressive and keeps the car awake :(

Is your car on stable internet?

[markusdd]

The car is on normal LTE mobile.

Normal street parker...so no permanent Wifi for me. Shouldn't matter, this has to work.

I might still be misunderstanding you: If the streaming API does not tell us anything about the state, why is it even being polled in suspend mode? This would seem non-sensical to me then. What does it provide at all then compared to the normal GET requests on the non-vehicle_data URL?

The more I dig into this the less sense it makes.

[micves]

Mine is also on LTE. And I agree, it has to work.

Stream tells us indirectly if its a real or a fake online based on whether power is 0 or nil. The original idea for teslamate to keep it open must be this part: https://github.com/adriankumpf/teslamate/blob/00cb6efd4257021d4dad64f7d8719b6677d535f5/lib/teslamate/vehicles/vehicle.ex#L407-L439

It will detect if you start charging or driving (and I guess faster than if you have to wait 30 second for it to poll vehicle_data)

[markusdd]

ok that's a fair point.

But still, based on my log above: Teslmate is not polling vehicle data, yet streaming API never puts power to nil. The car is not going to sleep as per this api. But as soon as teslmate, as per schedule, tries to pull the non vehicle_data URL, it gets those weird errors like socket closed.

[markusdd]

I now turned on debug and this si all quite interesting, but:

If it goes into suspend mode it will not query any URL for 30min. Am I correct in assuming this means it will take at least 30min to realize that the car is sleeping?

[markusdd]

Can you see this behavior on your end?

The car can sleep, and eventually Teslamate suspends logging, as it should. The streaming API continues, but it has to issue re-subscriptions fairly regulary and I have several of these blocks in between every few minutes.

[micves]

The reason you never see power at nil is because it only happens if you start the stream during fake online before calling vehicle_data. And this will never happen the way teslamate is implemented at the moment.

If it does fetch anything in 30min you would also guess it will pretend to be in online until it does the next fetch

I don't really have data for suspend, but i'll keep an eye out.

My thoughts at the moment is that online state should only be based on non-vehicle_data fetches and stream data. vehicle_data could be limited to when you for sure is online (like driving, charging, etc.)

Also error and disconnects should stay away from vehicle_data. It just messes up the sleep/offline.

I'll keep on looking into it, but my time is limited for the next week or so. And again. What about other cars? Will they support such a thing? :|

[markusdd]

ok that makes sense. But as during suspend the stream keeps running, and no poll to vehicle_data happens (hence no wakeup from fake to real online): Why does the Streaming API never switch to power: nil?

I would expect if there is no poll for 60min the vehicle will eventually go to sleep. Or do you have to restart a stream each and every time state changes? My naive strategy would have been to just let the stream run always. But that does not seem to work (as it essentially is what happens in suspend).

I am wondering why you don't have suspend data as well: This happens per default 3min after the car is online (or cosnidered so) and does nothing. It will then print 'Suspending logging' and then it's there.

There is also another flaw in the logic I think: as it does not poll for 30min after suspending (to facilitate sleep) it will never catch of the vehicle sleeps earlier, hence the status display might be off quite a bit. Actually besides Streaming ist shoudl keep polling the non-vehicle data URL, because online there it can see the state change according to what you found out.

As for other vehicles I expect little issues as no one seems to have this problem.

[markusdd]

Interesting observation:

It seems that at times the stream API is actually not responding although teslamate thinks the car is still online. These MCU2 upgraded vehicles are really acting strange.

@micves are you still looking at this? I also want to pcik up again because this urgently needs fixing. Teslamate is super helpful but this phantom drain is not acceptable.

Also, still, I would appreciate a hint/comment from @adriankumpf on this. I am happy to help on driving a fix but I am still struggling with the code. Elixir is extremely far out of my comfort zone... To Adrian, once the root cause is known this is probably an easy fix.

[micves]

Havent had any time since my last post. This week is also limited in time for me.

But I definitively also want to get on with it somehow. I think I'm in the same place as you regarding Elixir 😕

It might not be an easy fix. As you say: MCU2 upgraded vehicles act strange. It might not even be a problem on vehicle born with MCU2, 3 and 4. On those it might be okay to call vehicle_data without effecting the online/sleep timer. Could be nice with some testers on newer vehicles.

[sb1089]

My situation: Upgraded MCU2 Tesla Model S 2017. I've setup a Postman environment to see what the API does. When I do a GET on vehicles ({{endPoint}}api/1/vehicles), my response is like below: { "response": [ { "id": XXX, "vehicle_id": XXX, "vin": "XXX", "display_name": "Charles", "option_codes": null, "color": null, "access_type": "OWNER", "tokens": [ "XXX", "XXX" ], "state": "offline", "in_service": false, "id_s": "XXX", "calendar_enabled": true, "api_version": 57, "backseat_token": null, "backseat_token_updated_at": null, "ble_autopair_enrolled": false } ], "count": 1 }

You see that my car currently is offline. When I do a GET on vehicle_data ({{endPoint}}/api/1/vehicles/{{teslaVehicleIdS}}/vehicle_data) I am not able to retrieve information: { "response": null, "error": "vehicle unavailable: {:error=>\"vehicle unavailable:\"}", "error_description": "" }

As soon as my car is in state 'online', the vehicle_data call is possible and will retrieve my vehicle information and also stays online for a minimum of 10 minutes (true wake state). If I don't call the above command in state 'online', my car gets offline within 1-3 minutes (no true wake state).

What I think happens is that Teslamate sees the state 'online' and immediately starts the streaming api to access all data.

[markusdd]

Your assesment is entirely correct and if you read through all of this issue you will discover that this is exactly the place we have arrived at as well.

Essentially, for retrofitted MCU2 cars (although it should not hurt for the other cars), we need an extra safeguard to detect offline and online status. For our cars, in the transition phase, the normal as well as the streaming API behave somewhat erratically. This causes teslamate to call vehicle_data endpoint to early, causing a wakelock.

The only thing I did not understand yet is why at somepoint the car basically 'forces' itself to sleep and why this weird pattern emerges:

The car has been completely untouched today. It has not been opened, the App has not been used. Just teslamate.

[markusdd]

@micves I actually have an idea for a "simple" fix, or at least a step for improvement.

To resolve the wakelock, would it help to cancel the vehicle_data poll timer when the car reports the 'can_sleep' condition? Because can_sleep essentially means 'nothing going on', so polling vehicle_data in that condition is senseless.

[micves]

@markusdd Sorry for the long wait, but have been busy with other things. Have had a little on and off time on the issue again now.

I think I have made a solution for handling the fake online thing, which also handles the wakelock. The poll timer in suspended ('can_sleep' condition) is actually already 30 minutes, so there is enough time for the car to go to sleep. I think the issue here is that the errors (socket closed, timeout and so on) triggers a poll. And if the car is already online it will trigger the vehicle_data poll and thereby extending the waketime. This should be fixed as well.

So now my next steps are:

1. At the moment I have a test setup running on my laptop. Normally not running all the time. My normal teslamate is running in docker on a NAS. It would be nice to build a docker image and install that on the NAS to get some real life testing.
2. commit my code somewhere for others to test (guess the way is a fork and pull request at some point)

Any steps to do the above would be appreciated :)

Or maybe you also did some fixes in my absence? :)

[markusdd]

hi! no I also did not make progress, I tried to setup a dev env for Elixir but I just can't get a grip of how that code actually works to make these changes. It is kind of dark magic as there are no normal function calls but some events are being passed that magically lead to the execution of certain functions xD

But as I have a manual install running, if you put your stuff in a PR, I can take the diff, simply run compile and then I can run it on my production system, as I do not use Docker.

[micves]

Yeah, the flow of thing are pretty hard to figure out. Pure voodoo :)

It uses https://hexdocs.pm/gen_state_machine/GenStateMachine.html but it still causes a lot of headache trying to figure out of how things are working - and there are not many comment in the code to help :|

Essential things are :next_state and :next_event which decides which handle_event() is triggered. The syntax is also quite funky. And the VS Code extension doesn't seem to help with completing.

Well, I'll try to make a PR later today after work. Or during the weekend.

[micves]

I have created a fork: https://github.com/micves/teslamate

I havent made it a PR yet as there are still some TODO's in the code, and some more testing to be done

I guess if you just change your origin you can pull it?

[markusdd]

Wow, thanks so much! I think you figured this out better than I did, but I read through the diff and it makes a lot of sense to me. I have imported the 2 changed files and compiled it in my LXC container, my instance is now ruinning on it, let's see how this goes!

[Dhtjf]

I've been watching, having the same issue, and am happy to help test with my 17 S with MCU2. My coding experience is pretty minimal so I'm also happy to wait on the sidelines to avoid being more trouble than it's worth.

[markusdd]

So initially this looks super promising!

The small blue stripe is a manually triggered wakeup through the app, which is directly followed by sleeping again.

Normally sleep periods never lasted longer than an hour, so let's see how this goes over night, but I think you might have finally fixed this after literally years of wasting power.

I hope @adriankumpf will review this and bring it on mainline once we have a PR.

[markusdd]

Ok, some more insight @micves :

The short erratic wakeups are gone, what persists are the long ones. This seems to be caused by the fact that we keep, every 30min, polling the car through vehicle_data although we are actually in suspend logging mode. Should anything happen that requires actual vehicle_data logging, this would be visible through either stream data or the non-vehcile_data URL endpoint.

I think to get rid of these, we need to make sure to never poll vehicle_data when in suspend mode unless there is an event that pulls us out of suspend shift state, service, charging, remote climate activation etc.).

What do you think? Half-way there I think, this is already a huge success.

[micves]

I have only seen the problem with the long wake times in suspend when there are errors (socket closed and timeouts). One of the TODO's in the code :) With errors it seem to not respect the 30 minutes, but do the vehicle_data right away. And whenever one of the retries go through it can be too early and reset the wake timer somehow in the car.

I havent seen it like your screenshot. And it is actually a little weird. After 'Suspending logging' it should be in suspended state. And the 'Real online detected...' should only come when in state start and stream data comes in. It actually looks like it somehow in between those two logs switches state. I'll try to see if I can find an explanation for that. Maybe the car is actually offline and vehicle_data triggers internal state switch but also brings the car to online without teslamate ever registering the offline. A quickfix could be to do a non-vehicle_data fetch first whenever in suspended.

But you might be right that we should not use vehicle_data in suspended at all. I think however that we could miss something like remote climate activation. Not sure that is in stream data or in non-vehicle_data. But that would always be a issue when the car is in online and suspended. It would take up to 30 min for teslamate to register something like that. I guess its a rare case anyways. Normally the car would be offline/asleep and you would wake it with the app to start the climate.

@Dhtjf what kind of setup are you running? My main system is docker, and I havent figured out how to make a test image yet. I'm considering moving to something with a manual setup as it seems easier to change on the fly. You are very welcome to test. Trouble is not a problem, it will hopefully just give more insight :)

[markusdd]

ever registering the offline. A quickfix could be to do a non-vehicle_data fetch first whenever in suspended.

But you might be right that we should not use vehicle_data in suspended at all. I think however that we could miss something like remote climate activation. Not sure that is in stream data or in non-vehicle_data. But that would always be a issue when the car is in online and suspended. It would take up to 30 min for teslamate to register something like that. I guess its a rare case anyways.

Yes, and no.

Yes, we should definitely never use vehicle_data in suspend. A good way to detect if e.g. climate comes on should be power. In that case it should rise above 0. (so one of the conditions to exit suspend should be power !=0 )

And no, I think that condition is missing in general, because I also had one instance a short while ago where it took Teslamate a lot of time to recognize I am actually charging. So it isn't that rare.

So maybe Power not equal to 0 is a good way to exit suspend, and in suspend we should not poll vehicle data no matter what.

[Dhtjf]

@Dhtjf what kind of setup are you running? My main system is docker, and I havent figured out how to make a test image yet. I'm considering moving to something with a manual setup as it seems easier to change on the fly. You are very welcome to test. Trouble is not a problem, it will hopefully just give more insight :)

I'm also running in docker but am certainly not opposed to running manual if needed for testing. I'd just need help with compiling and whatever else (or if there's a guide). Thanks again fellas.

[micves]

@Dhtjf There is a guide here: https://docs.teslamate.org/docs/installation/debian I haven't tried it but since docker install guide has postgres:14 the manual guide might not be up to date since it is using 12

@markusdd Good idea with the power. There is already a power < 0 to detect charging. I have locally (not commited) added a power > 0 to see if something will be detected (i'll pre-cool it tomorrow morning before going to work :)

And there is definitely something going on with suspended state. I got some timeout errors today where it switched to state start (where it detects real/fake online) Will dig some more into that.