Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: handle sleep behavior of MCU2 upgraded cars #4453

Draft
wants to merge 1 commit into
base: master
Choose a base branch
from

Conversation

JakobLichterfeld
Copy link
Collaborator

changes from @micves from #3262, fixes #3084

@JakobLichterfeld JakobLichterfeld added enhancement New feature or request area:tesla api Related to the Tesla API area:teslamate Related to TeslaMate core labels Dec 23, 2024
Copy link

netlify bot commented Dec 23, 2024

Deploy Preview for teslamate ready!

Name Link
🔨 Latest commit cd6be38
🔍 Latest deploy log https://app.netlify.com/sites/teslamate/deploys/677c48370dd83d00081d7b48
😎 Deploy Preview https://deploy-preview-4453--teslamate.netlify.app
📱 Preview on mobile
Toggle QR Code...

QR Code

Use your smartphone camera to open QR code link.

To edit notification comments on pull requests, go to your Netlify site configuration.

@JakobLichterfeld JakobLichterfeld marked this pull request as draft December 23, 2024 12:25
@JakobLichterfeld JakobLichterfeld added note:help wanted Extra attention is needed note:needs investigation The issue must be investigated first labels Dec 23, 2024
@brianmay
Copy link
Collaborator

brianmay commented Jan 2, 2025

I am having trouble making sense of this PR.

It started off simple (with the original first two commits from the first PR) and has become rather complicated, and IMHO hard to understand. And I am wondering if this complexity is really required.

Then there are some changes when in this PR that don't belong here; for example the changes to delete the "models2" entries. I think this might have been included in error.

There are some changes though that would be easy to apply separately, for example improvements to the log messages.

@JakobLichterfeld
Copy link
Collaborator Author

Agree, I do have trouble reviewing. The comments helped a bit.
As so much test cases fail I would love to see a split up by @micves on this branch.

@brianmay brianmay force-pushed the mcu2-upgraded-cars branch from 850eb3f to dee7726 Compare January 2, 2025 20:41
@brianmay brianmay force-pushed the mcu2-upgraded-cars branch 2 times, most recently from d2999d2 to f951d44 Compare January 3, 2025 09:20
@micves
Copy link
Contributor

micves commented Jan 3, 2025

Not sure where the model2 changes are coming from. They are not in the original https://github.com/teslamate-org/teslamate/pull/3262/files Maybe it wasn't synced when this PR was made?

The commit history of the old #3262 is long and a bit messed up. Might be easier to only look at the end result. Which again as you mention is a bit complex :(
The issue is also complex as the length of #3084 also indicates.

The shortest way to sum it up, might actually just be the description I made on fake_online_state variable:

fake_online_state is introduced because older cars upgraded to MCU2 have a little wakeup every hour to check subsystems.
They report online but if vehicle_data is requested they wake up completely (cars clicks) and is awake for
15 minutes instead of a 2-3 minutes. The only difference (known at this moment) is that stream reports power=nil
in subsystem online and reports power as a number when it is a real online.

The complexity comes in because online all of a sudden might not be online.
It's Schrödinger's online until data from Stream is received :)

This means that the entire online state handling and stream is re-done, and the tests (or as I see it, the API mock used for tests) does not support the fact that a Stream is required.

The ultimate solution would be that the car or Tesla servers would hide the fake online.
I haven't checked in a while, but my guess is that nothing has changed there.

@brianmay
Copy link
Collaborator

brianmay commented Jan 3, 2025

I guess next step is to double check this is still required. Which might be the case, but I think we do need to check to be sure.

@micves
Copy link
Contributor

micves commented Jan 3, 2025

I just checked my logs and it seems to still be an issue:

2025-01-02 17:31:57.037 car_id=1 [info] Vehicle online, connect stream to check for real online
2025-01-02 17:31:57.037 car_id=1 [info] Stream connecting ...
2025-01-02 17:31:58.356 car_id=1 [info] Fake online: power is nil
2025-01-02 17:34:30.612 car_id=1 [info] Stream :inactive in state :offline, seems to have been a fake online
2025-01-02 17:34:30.907 [info] Streaming API: Vehicle offline
2025-01-02 17:34:30.907 car_id=1 [warning] Stream reports vehicle as offline, fetching vehicle state ...
2025-01-02 17:34:30.977 car_id=1 [info] Stream disconnecting ...
2025-01-02 18:33:31.219 car_id=1 [info] Vehicle online, connect stream to check for real online
2025-01-02 18:33:31.219 car_id=1 [info] Stream connecting ...
2025-01-02 18:33:32.431 car_id=1 [info] Fake online: power is nil
2025-01-02 18:35:35.748 car_id=1 [info] Stream :inactive in state :offline, seems to have been a fake online
2025-01-02 18:36:01.681 car_id=1 [info] Stream disconnecting ...
2025-01-02 19:24:10.953 [info] Refreshing access token ...
2025-01-02 19:24:11.301 [info] POST https://auth.tesla.com/oauth2/v3/token -> 200 (347.532 ms)
2025-01-02 19:24:11.343 [info] Scheduling token refresh in 6h
2025-01-02 19:34:43.498 car_id=1 [info] Vehicle online, connect stream to check for real online
2025-01-02 19:34:43.498 car_id=1 [info] Stream connecting ...
2025-01-02 19:34:44.882 car_id=1 [info] Fake online: power is nil
2025-01-02 19:37:00.137 car_id=1 [info] Stream :inactive in state :offline, seems to have been a fake online
2025-01-02 19:37:30.696 [info] Streaming API: Vehicle offline
2025-01-02 19:37:30.696 car_id=1 [warning] Stream reports vehicle as offline, fetching vehicle state ...
2025-01-02 19:37:30.760 car_id=1 [info] Stream disconnecting ...
2025-01-02 20:35:58.701 car_id=1 [info] Vehicle online, connect stream to check for real online
2025-01-02 20:35:58.701 car_id=1 [info] Stream connecting ...
2025-01-02 20:35:59.867 car_id=1 [info] Fake online: power is nil
2025-01-02 20:38:27.131 car_id=1 [info] Stream :inactive in state :offline, seems to have been a fake online
2025-01-02 20:38:57.674 [info] Streaming API: Vehicle offline
2025-01-02 20:38:57.674 car_id=1 [warning] Stream reports vehicle as offline, fetching vehicle state ...
2025-01-02 20:38:57.737 car_id=1 [info] Stream disconnecting ...
2025-01-02 21:37:43.140 car_id=1 [info] Vehicle online, connect stream to check for real online
2025-01-02 21:37:43.140 car_id=1 [info] Stream connecting ...
2025-01-02 21:37:44.633 car_id=1 [info] Fake online: power is nil
2025-01-02 21:39:53.967 car_id=1 [info] Stream :inactive in state :offline, seems to have been a fake online
2025-01-02 21:40:13.489 car_id=1 [info] Stream disconnecting ...

It has the hourly sequence with 'Fake online: power is nil' lasting 2-3 minutes
The car is on 2024.45.32

@brianmay, I think I read somewhere that you also have an MCU2 upgraded car?
If you are on a difference PR or release, my guess is that you also have these hourly wakeups, but yours will last longer because it wakes up for real because vehicle_data is polled. If you are near the car it will also click on the high voltage relay.

@Dhtjf
Copy link

Dhtjf commented Jan 3, 2025

Sample of my logs of 2017 MCU2 upgraded Model S. On 2024.26.7 and TeslaMate on 1.31.2-dev from pr-3262. 200s are from uptime Kuma, so unrelated.

2025-01-03` 22:49:19.230 [info] GET /
2025-01-03 22:49:19.231 [info] Sent 200 in 1ms
2025-01-03 22:50:46.620 car_id=1 [info] Vehicle online, connect stream to check for real online
2025-01-03 22:50:46.620 car_id=1 [info] Stream connecting ...
2025-01-03 22:50:48.561 car_id=1 [info] Fake online: power is nil
2025-01-03 22:51:19.235 [info] GET /
2025-01-03 22:51:19.237 [info] Sent 200 in 1ms
2025-01-03 22:51:46.950 car_id=1 [info] Stream disconnecting ...
2025-01-03 22:53:19.241 [info] GET /
2025-01-03 22:53:19.243 [info] Sent 200 in 1ms

@brianmay
Copy link
Collaborator

brianmay commented Jan 4, 2025

I can confirm that I have MCU2 upgraded car, am using this branch, and am seeing similar log messages. So yes, does seem like this PR is still required.

@brianmay brianmay force-pushed the mcu2-upgraded-cars branch from f951d44 to b15924e Compare January 4, 2025 02:56
@brianmay
Copy link
Collaborator

brianmay commented Jan 4, 2025

Looking at the simplest piece of the PR here:

diff --git a/lib/teslamate/vehicles/vehicle.ex b/lib/teslamate/vehicles/vehicle.ex
index d32098b9a8..e30020392b 100644
--- a/lib/teslamate/vehicles/vehicle.ex
+++ b/lib/teslamate/vehicles/vehicle.ex
@@ -1433,6 +1645,12 @@
         {:keep_state, %Data{data | last_used: DateTime.utc_now()},
          [broadcast_summary(), schedule_fetch(default_interval() * i, data)]}

+      {:error, :power_usage} ->
+        if suspend?, do: Logger.warning("Power usage ...", car_id: car.id)
+
+        {:keep_state, %Data{data | last_used: DateTime.utc_now()},
+         [broadcast_summary(), schedule_fetch(default_interval() * i, data)]}
+
       {:error, :unlocked} ->
         if suspend?, do: Logger.warning("Unlocked ...", car_id: car.id)

@@ -1501,6 +1719,10 @@
        %CarSettings{req_not_unlocked: true}} ->
         {:error, :unlocked}

+      {%Vehicle{drive_state: %Drive{power: power}}, _}
+      when is_number(power) and power > 0 ->
+        {:error, :power_usage}
+
       {%Vehicle{}, %CarSettings{}} ->
         :ok
     end

I believe this means Teslamate will never enter "trying to sleep" if power > 0. What is the rationale here?

Does power > 0 suggest that the tesla itself is not trying to sleep, and as a result there is no point entering "trying to sleep" ourselves?

Would it make sense to split this patch out and apply it first?

@brianmay
Copy link
Collaborator

brianmay commented Jan 4, 2025

There appear to be 4 different values for fake_online_state: 0, 1, 2, and 3. What do these different values mean?

@brianmay
Copy link
Collaborator

brianmay commented Jan 4, 2025

The model2 changes don't appear in the original PR:

@brianmay
Copy link
Collaborator

brianmay commented Jan 4, 2025

The model2 changes are not in the original PR; am going to delete them.

diff --git a/lib/teslamate/vehicles/vehicle.ex b/lib/teslamate/vehicles/vehicle.ex
index d32098b9a8..e30020392b 100644
--- a/lib/teslamate/vehicles/vehicle.ex
+++ b/lib/teslamate/vehicles/vehicle.ex
@@ -65,7 +70,6 @@
           with str when is_binary(str) <- type do
             case String.downcase(str) do
               "models" <> _ -> "S"
-              "models2" <> _ -> "S"
               "model3" <> _ -> "3"
               "modelx" <> _ -> "X"
               "modely" <> _ -> "Y"
@@ -79,7 +83,6 @@
           case {model, trim_badging, type} do
             {"S", "100D", "lychee"} -> "LR"
             {"S", "P100D", "lychee"} -> "Plaid"
-            {"S", "100D", "models2"} -> "LR+"
             {"3", "P74D", _} -> "LR AWD Performance"
             {"3", "74D", _} -> "LR AWD"
             {"3", "74", _} -> "LR"

@brianmay brianmay force-pushed the mcu2-upgraded-cars branch 2 times, most recently from f910970 to 6c7f0d8 Compare January 4, 2025 03:21
@brianmay
Copy link
Collaborator

brianmay commented Jan 4, 2025

Testing my understanding of the code here. Please correct any errors!

:get_vehicle -> TeslaApi.Vehicle.get: will return information Tesla has on the car but will not try to talk to the car, as such it will not keep the car awake and will succeed even if car is asleep. As such this will be limited in scope.

:get_vehicle_with_state -> TeslaApi.Vehicle.get_with_state will try to talk to the car and get all available information, but this will mean keeping the car awake if it is awake or out right failing if the car is asleep.

@brianmay
Copy link
Collaborator

brianmay commented Jan 4, 2025

Am wondering about the changes to the fetch function. What we have is:

  defp fetch(%Data{car: car, deps: deps}, expected_state: expected_state) do
    reachable? =
      case expected_state do
        :online -> true
        {:driving, _, _} -> true
        {:updating, _} -> true
        {:charging, _} -> true
        :start -> false
        {:offline, _} -> false
        {:asleep, _} -> false
        {:suspended, _} -> false
      end

    if reachable? do
      fetch_with_reachable_assumption(car.eid, deps)
    else
      fetch_with_unreachable_assumption(car.eid, deps)
    end
  end

  defp fetch_with_reachable_assumption(id, deps) do
    with {:error, :vehicle_unavailable} <- call(deps.api, :get_vehicle_with_state, [id]) do
      call(deps.api, :get_vehicle, [id])
    end
  end

  defp fetch_with_unreachable_assumption(id, deps) do
    with {:ok, %Vehicle{state: "online"}} <- call(deps.api, :get_vehicle, [id]) do
      call(deps.api, :get_vehicle_with_state, [id])
    end
  end

i.e. we try to guess if car is reachable or not, then we check if this assumption is correct or not, and then we try to get the data.

But after this PR we do things differently but only if the streaming api is enabled in the config.

        allow_vehicle_data? =
          case expected_state do
            # will not go to real state :online unless a stream is received
            # with power not nil in state :offline/:asleep or if use_streaming api is turned off
            :online ->
              true

            {:driving, _, _} ->
              true

            {:updating, _} ->
              true

            {:charging, _} ->
              true

            :start ->
              false

            {state, _} when state in [:asleep, :offline] ->
              case data do
                %Data{fake_online_state: 3} -> true
                %Data{} -> false
              end

            {:suspended, _} ->
              false
          end

        if allow_vehicle_data? do
          call(deps.api, :get_vehicle_with_state, [car.eid])
        else
          call(deps.api, :get_vehicle, [car.eid])
        end

So now if fake_online_state is 3 we consider the car to be awake, where as before we considered it to be asleep. That probably makes sense.

But now instead of carefully making calls to fetch_with_unreachable_assumption and fetch_with_reachable_assumption to check our assumptions are correct, we make the calls directly. What is the rationale here?

@brianmay
Copy link
Collaborator

brianmay commented Jan 4, 2025

To half answer my own question, we can't trust this logic anymore:

defp fetch_with_unreachable_assumption(id, deps) do
    with {:ok, %Vehicle{state: "online"}} <- call(deps.api, :get_vehicle, [id]) do
      call(deps.api, :get_vehicle_with_state, [id])
    end
  end

This would result in calling get_vehicle_with_state when the car is "fake awake", which will result in the car being woken up properly.

And the logic to upgrade a car that is asleep to awake does seem to be dependent on creating streaming. Hence we have to fall back to fetch_with_unreachable_assumption if streaming is disabled.

But I still do wonder why we can't use fetch_with_unreachable_assumption?

And contrary to the comment at the top, the logic seems to be more along the lines of "Is car awake? Can we receive streaming data?" as opposed to looking a the power level (except for the logic that inhibits sleeping when the power level is non-zero).

@brianmay
Copy link
Collaborator

brianmay commented Jan 4, 2025

Taking a different approach.

Take a random failing test, for example:

mix test test/teslamate/vehicles/vehicle/suspend_logging_test.exs:238

It looks like there is confusion in the date/time happening. As in the test wants to use 1970-01-01 but we are getting present day date and times.

This in turn means any incoming data is discarded because it is 2025-1970 = 55 years too late:

16:09:40.759 car_id=15611 [warning] Discarded stale fetch result: [
  now: %TeslaApi.Vehicle.State.Drive{
    active_route_destination: nil,
    active_route_energy_at_arrival: nil,
    active_route_latitude: nil,
    active_route_longitude: nil,
    active_route_miles_to_arrival: nil,
    active_route_minutes_to_arrival: nil,
    active_route_traffic_minutes_delay: nil,
    gps_as_of: nil,
    heading: nil,
    latitude: 0.0,
    longitude: 0.0,
    native_latitude: nil,
    native_location_supported: nil,
    native_longitude: nil,
    native_type: nil,
    power: nil,
    shift_state: "N",
    speed: nil,
    timestamp: 0
  },
  last: %TeslaApi.Vehicle.State.Drive{
    active_route_destination: nil,
    active_route_energy_at_arrival: nil,
    active_route_latitude: nil,
    active_route_longitude: nil,
    active_route_miles_to_arrival: nil,
    active_route_minutes_to_arrival: nil,
    active_route_traffic_minutes_delay: nil,
    gps_as_of: nil,
    heading: nil,
    latitude: 0.0,
    longitude: 0.0,
    native_latitude: nil,
    native_location_supported: nil,
    native_longitude: nil,
    native_type: nil,
    power: nil,
    shift_state: nil,
    speed: nil,
    timestamp: 1735967380670
  }
]

Note the timestamp of the incoming data is 0, the other timestamp is 1735967380670 which I assume was the current date time when I ran the test.

Similarly the test is expecting 1970-01-01 to be in the data, but it gets 2025-01-04 instead:

  1) test cannot be suspended if shift_state is N (TeslaMate.Vehicles.Vehicle.SuspendLoggingTest)
     test/teslamate/vehicles/vehicle/suspend_logging_test.exs:227
     Assertion failed, no matching message after 300ms
     The following variables were pinned:
       date = ~U[1970-01-01 00:00:00.000Z]
     Showing 4 of 4 messages in the mailbox
     code: assert_receive {:start_state, _, :online, date: ^date}
     mailbox:
       pattern: {:start_state, _, :online, [date: ^date]}
       value:   {
                  :start_state,
                  %TeslaMate.Log.Car{__meta__: #Ecto.Schema.Metadata<:built, "cars">, id: 15611, name: nil, efficiency: nil, model: "3", trim_badging: nil, marketing_name: nil, exterior_color: nil, wheel_type: nil, spoiler_type: nil, eid: 0, vid: 1000, vin: "1000", settings_id: nil, settings: %TeslaMate.Settings.CarSettings{__meta__: #Ecto.Schema.Metadata<:built, "car_settings">, id: nil, suspend_min: 21, suspend_after_idle_min: 15, req_not_unlocked: true, free_supercharging: false, use_streaming_api: true, enabled: true, lfp_battery: false, car: #Ecto.Association.NotLoaded<association :car is not loaded>}, charging_processes: #Ecto.Association.NotLoaded<association :charging_processes is not loaded>, positions: #Ecto.Association.NotLoaded<association :positions is not loaded>, drives: #Ecto.Association.NotLoaded<association :drives is not loaded>, inserted_at: nil, updated_at: nil},
                  :online,
                  [date: ~U[2025-01-04 05:09:40.670Z]]
                }

       pattern: {:start_state, _, :online, [date: ^date]}
       value:   {
                  :insert_position,
                  %TeslaMate.Log.Car{__meta__: #Ecto.Schema.Metadata<:built, "cars">, id: 15611, name: nil, efficiency: nil, model: "3", trim_badging: nil, marketing_name: nil, exterior_color: nil, wheel_type: nil, spoiler_type: nil, eid: 0, vid: 1000, vin: "1000", settings_id: nil, settings: %TeslaMate.Settings.CarSettings{__meta__: #Ecto.Schema.Metadata<:built, "car_settings">, id: nil, suspend_min: 21, suspend_after_idle_min: 15, req_not_unlocked: true, free_supercharging: false, use_streaming_api: true, enabled: true, lfp_battery: false, car: #Ecto.Association.NotLoaded<association :car is not loaded>}, charging_processes: #Ecto.Association.NotLoaded<association :charging_processes is not loaded>, positions: #Ecto.Association.NotLoaded<association :positions is not loaded>, drives: #Ecto.Association.NotLoaded<association :drives is not loaded>, inserted_at: nil, updated_at: nil},
                  %{date: ~U[2025-01-04 05:09:40.670Z], speed: nil, latitude: 0.0, longitude: 0.0, elevation: nil, power: nil, battery_level: nil, ideal_battery_range_km: nil, est_battery_range_km: nil, rated_battery_range_km: nil, usable_battery_level: nil, outside_temp: nil, inside_temp: nil, odometer: nil, fan_status: nil, is_climate_on: nil, driver_temp_setting: nil, passenger_temp_setting: nil, is_rear_defroster_on: nil, is_front_defroster_on: nil, battery_heater_on: nil, battery_heater: nil, battery_heater_no_power: nil, tpms_pressure_fl: nil, tpms_pressure_fr: nil, tpms_pressure_rl: nil, tpms_pressure_rr: nil}
                }

       pattern: {:start_state, _, :online, [date: ^date]}
       value:   {ApiMock, {:stream, 1000, #Function<0.51361193/1 in TeslaMate.Vehicles.Vehicle.connect_stream/1>}}

       pattern: {:start_state, _, :online, [date: ^date]}
       value:   {
                  :pubsub,
                  {:broadcast, TeslaMate.PubSub, "Elixir.TeslaMate.Vehicles.Vehicle/summary/15611", %TeslaMate.Vehicles.Vehicle.Summary{car: %TeslaMate.Log.Car{__meta__: #Ecto.Schema.Metadata<:built, "cars">, id: 15611, name: nil, efficiency: nil, model: "3", trim_badging: nil, marketing_name: nil, exterior_color: nil, wheel_type: nil, spoiler_type: nil, eid: 0, vid: 1000, vin: "1000", settings_id: nil, settings: %TeslaMate.Settings.CarSettings{__meta__: #Ecto.Schema.Metadata<:built, "car_settings">, id: nil, suspend_min: 21, suspend_after_idle_min: 15, req_not_unlocked: true, free_supercharging: false, use_streaming_api: true, enabled: true, lfp_battery: false, car: #Ecto.Association.NotLoaded<association :car is not loaded>}, charging_processes: #Ecto.Association.NotLoaded<association :charging_processes is not loaded>, positions: #Ecto.Association.NotLoaded<association :positions is not loaded>, drives: #Ecto.Association.NotLoaded<association :drives is not loaded>, inserted_at: nil, updated_at: nil}, display_name: nil, state: :online, since: ~U[2025-01-04 05:09:40.682977Z], healthy: true, latitude: 0.0, longitude: 0.0, heading: nil, battery_level: nil, charging_state: nil, usable_battery_level: nil, ideal_battery_range_km: nil, est_battery_range_km: nil, rated_battery_range_km: nil, charge_energy_added: nil, speed: nil, outside_temp: nil, inside_temp: nil, is_climate_on: nil, is_preconditioning: nil, locked: nil, sentry_mode: nil, plugged_in: true, scheduled_charging_start_time: nil, charge_limit_soc: nil, charger_power: nil, windows_open: nil, doors_open: nil, driver_front_door_open: nil, driver_rear_door_open: nil, passenger_front_door_open: nil, passenger_rear_door_open: nil, odometer: nil, shift_state: nil, charge_port_door_open: nil, time_to_full_charge: nil, charger_phases: nil, charger_actual_current: nil, charger_voltage: nil, version: "", update_available: nil, update_version: nil, is_user_present: nil, geofence: nil, model: "3", trim_badging: nil, ...}}
                }
     stacktrace:
       test/teslamate/vehicles/vehicle/suspend_logging_test.exs:238: (test)

But oddly enough I don't think anything in this PR deals with date/time?

@brianmay
Copy link
Collaborator

brianmay commented Jan 4, 2025

There are a lot of references to DateTime.utc_now() in lib/teslamate/vehicles/vehicle.ex...

Wonder if with these changes we have triggered a new code path that invokes one of these that wasn't previously used.

@brianmay
Copy link
Collaborator

brianmay commented Jan 4, 2025

I think bottom line is our tests are far too brittle.

I had hoped we already did something sensible with date times, but apparently not.

I created a hacked commit that will isolate calls to DateTime.utc_now() to my own function that is hard-coded to return a value for tests.

https://github.com/teslamate-org/teslamate/commits/push-ktmmkymmrnny/

But somehow parse_timestamp was being called with a datetime not a timestamp. So I hacked that too. (I really like compile time type checking...)

Now the test fails with a different error:

mix test test/teslamate/vehicles/vehicle/suspend_logging_test.exs:238
Running ExUnit with seed: 658308, max_cases: 64
Excluding tags: [:test]
Including tags: [location: {"test/teslamate/vehicles/vehicle/suspend_logging_test.exs", 238}]



  1) test cannot be suspended if shift_state is N (TeslaMate.Vehicles.Vehicle.SuspendLoggingTest)
     test/teslamate/vehicles/vehicle/suspend_logging_test.exs:227
     match (=) failed
     code:  assert {:error, :vehicle_not_parked} = Vehicle.suspend_logging(name)
     left:  {:error, :vehicle_not_parked}
     right: :ok
     stacktrace:
       test/teslamate/vehicles/vehicle/suspend_logging_test.exs:240: (test)


Finished in 0.2 seconds (0.00s async, 0.2s sync)
20 tests, 1 failure, 19 excluded

Which is kind of odd, somehow the vehicle got a state of driving.

@JakobLichterfeld
Copy link
Collaborator Author

Thank you for digging into this!

I think bottom line is our tests are far too brittle.

Unfortunately, I have to agree. At least in the past, they gave us enough confidence to release new versions.

As in the test wants to use 1970-01-01

I have stumbled over this in the past and wondered why more realistic dates are not used to cover the case where a date is not correctly initialized.

@brianmay brianmay force-pushed the mcu2-upgraded-cars branch from 6c7f0d8 to 8d4da30 Compare January 4, 2025 20:48
@micves
Copy link
Contributor

micves commented Jan 5, 2025

I believe this means Teslamate will never enter "trying to sleep" if power > 0. What is the rationale here?

Does power > 0 suggest that the tesla itself is not trying to sleep, and as a result there is no point entering "trying to sleep" ourselves?

Would it make sense to split this patch out and apply it first?

power > 0 is when e.g. the climate is on which could be scheduled preconditioning or starting preheat from the app.

The code parts you showed will make sure it doesn't enter 'trying to sleep' (the internal state suspended)
But there is more in this category on line 685-697 (Suspended / Usage detected) which will cancel an ongoing suspended state/trying to sleep and go back to online. For faster polling and more information since we are online anyways.

It would make sense to split it out, since its not really related to MCU2 upgraded cars. Might also need some added tests (like as far as I remember is for 'Charging detected')

And on that note I also added some optimizations for that in line 616-630 where it only goes to Charging when the car is plugged in (power < 0) and its not preconditioning or in dog mode.

There appear to be 4 different values for fake_online_state: 0, 1, 2, and 3. What do these different values mean?

There should have been an enumeration, but my noob-ness in elixir told me to do it later :)
0 = offline or asleep
1 = received online with non-vehicle_data (:get_vehicle), connect to stream to check for power nil or a number
2 = stream data received, power is nil, fake online, do not use vehicle_data (only allow :get_vehicle)
3 = stream data received, power is a number and we have a real online, allow vehicle_data (:get_vehicle_with_state)

I hope it kind of covers your other comments, which in general seems to make sense :)

Regarding the test fails and time. I actually don't think they fail because of the time. If the test succeeds I still think it makes those stale fetch logs, but you just don't see them.
Agreed that fixing them will be the correct thing to do and make test debugging easier.

Which is kind of odd, somehow the vehicle got a state of driving.

I think it makes sense, the test you tried is this one:

  test "cannot be suspended if shift_state is N", %{test: name} do
    not_suspendable =
      online_event(drive_state: %{timestamp: 0, shift_state: "N", latitude: 0.0, longitude: 0.0})

    events = [
      {:ok, online_event()},
      {:ok, not_suspendable}
    ]

    :ok = start_vehicle(name, events)
    date = DateTime.from_unix!(0, :millisecond)
    assert_receive {:start_state, _, :online, date: ^date}

    assert {:error, :vehicle_not_parked} = Vehicle.suspend_logging(name)
  end

The online_event is settting shift_state to N and this is feed into start_vehicle.

start_vehicle is creating a Vehicle and executing the array of events.
Everything after is a setup of what is expected. I don't quite understand how really.

But e.g. will assert_receive {:start_state, _, :online, date: ^date} expect the vehicle to be in online.
And my guess is that this will fail big time since my changes really wants some stream data with power not nil.
Pretty sure start_vehicle and events doesn't do this at the moment.

Sorry for the huge comment :D

@brianmay
Copy link
Collaborator

brianmay commented Jan 5, 2025

Thanks for your comprehensive response. Will be considering what you said in detail.

One thing I was missing is that you need to connect to the stream to get the power level. I guess that is the only way to do so without risking waking up the car.

@brianmay brianmay force-pushed the mcu2-upgraded-cars branch from 33a76ed to cd6be38 Compare January 6, 2025 21:16
@brianmay
Copy link
Collaborator

brianmay commented Jan 6, 2025

This PR is gradually becoming simpler now. I need to re-examine it when I have time I think.

The additional code at 341-417 is still a bit of a pain.

Possibly this is most this PR can be broken up.

Refactoring still possible, but not sure it will make the PR any easier to understand.

@micves
Copy link
Contributor

micves commented Jan 7, 2025

One thing I was missing is that you need to connect to the stream to get the power level. I guess that is the only way to do so without risking waking up the car.

Exactly. To be honest, its a nasty workaround but it was the only difference I found between fake and real online (back in the investigation days of #3084)

This PR is gradually becoming simpler now. I need to re-examine it when I have time I think.

The additional code at 341-417 is still a bit of a pain.

Possibly this is most this PR can be broken up.

Refactoring still possible, but not sure it will make the PR any easier to understand.

Thanks for helping splitting it up. I also think its sized down to the bare minimum now.

Still complex and I would hope there was another simpler way to detect it.
Maybe something new has happened but it would require some re-investigation.

Now the app for iphone and android can be opened without waking up the car.
It also writes for how long the car has been sleeping.... wonder how that works :|

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area:tesla api Related to the Tesla API area:teslamate Related to TeslaMate core enhancement New feature or request note:help wanted Extra attention is needed note:needs investigation The issue must be investigated first
Projects
None yet
Development

Successfully merging this pull request may close these issues.

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