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

Suspend logging is not needed anymore as car falls asleep even while polling #3639

Open
1 task done
pkuehnel opened this issue Jan 30, 2024 · 47 comments
Open
1 task done
Labels
area:tesla api Related to the Tesla API area:teslamate Related to TeslaMate core note:discussion Details or approval are up for discussion note:more information needed The reporter has to provide more information

Comments

@pkuehnel
Copy link

pkuehnel commented Jan 30, 2024

Is there an existing issue for this?

  • I have searched the existing issues

What happened?

If the car does not have good connectivity or on Tesla's side breaks something regarding the streaming API, data is not recorded due to Logging being suspended. This was needed as cars stayed online when constantly being polled. But this is not the case anymore. Even if continually polling, the vehicle falls asleep without issues. I own a Model 3 from 2019, currently on 2023.44.30.9, but I tried this almost a year ago, and there, the car fell asleep while constantly being polled, as well.

Expected Behavior

"Falling asleep" should not occur anymore, or at least there should be an option to disable the "falling asleep" feature.

Steps To Reproduce

  1. Drive the car to a place with no internet connectivity.
  2. Wait until TeslaMate displays trying to sleep.
  3. Start a drive
  4. The drive won't be recorded due to the missing connection in drive start and TeslaMate not polling the Onwers API

Relevant log output

2024-01-27 15:21:34.045 car_id=1 [info] Suspending logging
2024-01-27 15:29:23.091 [warning] Too many disconnects from streaming API
2024-01-27 15:29:23.094 car_id=1 [info] Creating new connection … 
2024-01-27 15:29:23.094 car_id=1 [info] Disconnecting ...
2024-01-27 15:29:23.110 car_id=1 [info] Connecting ...
2024-01-27 15:51:34.401 car_id=1 [info] Vehicle is still online. Falling asleep for: 33 min
2024-01-27 15:51:34.409 [info] Start of drive initiated by: %TeslaApi.Vehicle.State.Drive{gps_as_of: 1706370691, heading: 354, latitude: 48.984552, longitude: 12.980987, native_latitude: 48.984552, native_location_supported: 1, native_longitude: 12.980987, native_type: "wgs", power: 11, shift_state: "D", speed: 5, timestamp: 1706370694311}
2024-01-27 15:51:34.409 car_id=1 [info] Driving / Start

Screenshots

No response

Additional data

No response

Type of installation

Docker

Version

1.28.2

@cwanja
Copy link
Collaborator

cwanja commented Jan 30, 2024

What do you mean by "the car fell asleep while constantly being polled"?

The car will not sleep if an application (Tesla app, TeslaMate, other third-party Tesla loggers) are polling the car. Thus the "falling asleep" feature was introduced to allow the car to enter a sleep pattern. And yes, if you start a drive or a charge during the "falling asleep" window, it will miss some (or all depending on the duration) of that event. This is intended behavior.

@cwanja cwanja added note:more information needed The reporter has to provide more information area:tesla api Related to the Tesla API area:teslamate Related to TeslaMate core labels Jan 30, 2024
@pkuehnel
Copy link
Author

The car will not sleep if an application (Tesla app, TeslaMate, other third-party Tesla loggers) are polling the car.

This has been the case for years, but not anymore. I created the following Powershell Script:

while ($true) {
    try {
        Invoke-WebRequest -Uri "http://192.168.1.50:4000/api/car/1/logging/resume" -Method Put
    } catch {
        Write-Output "An error occurred with car 1: $_"
    }

    try {
        Invoke-WebRequest -Uri "http://192.168.1.50:4000/api/car/4/logging/resume" -Method Put
    } catch {
        Write-Output "An error occurred with car 4: $_"
    }

    Start-Sleep -Seconds 10
}

This results in the following TeslaMateLog:

2024-01-30 15:39:42.525 [info] PUT /api/car/1/logging/resume
2024-01-30 15:39:42.526 [info] Sent 204 in 692µs
2024-01-30 15:39:42.559 [info] PUT /api/car/4/logging/resume
2024-01-30 15:39:42.560 [info] Sent 204 in 580µs
2024-01-30 15:39:52.602 [info] PUT /api/car/1/logging/resume
2024-01-30 15:39:52.603 [info] Sent 204 in 505µs
2024-01-30 15:39:52.638 [info] PUT /api/car/4/logging/resume
2024-01-30 15:39:52.639 [info] Sent 204 in 638µs

This results in TeslaMate never letting the cars go to sleep, but they still do. I know the issue regarding Teslas not sleeping due to constant polling of the car, but this is not the case anymore. At least not with a 2019 Model 3 and a 2023 Model Y. What I do not know is, how Model S/X (especially Legacy Model S/X) handle that. Still, Model 3 with Intel atom and Model Y with Ryzen MCU sleep without any issue, although TeslaMate does not pause polling.

@pkuehnel
Copy link
Author

pkuehnel commented Jan 30, 2024

What I noticed is that TeslaMate is a bit freaking out, probably because it does not expect the car to go to sleep:

2024-01-30 15:46:26.019 [info] Sent 200 in 4ms
2024-01-30 15:46:26.045 [info] PUT /api/car/1/logging/resume
2024-01-30 15:46:26.045 [info] Sent 204 in 612µs
2024-01-30 15:46:26.081 [info] PUT /api/car/4/logging/resume
2024-01-30 15:46:26.081 [info] Sent 204 in 483µs
2024-01-30 15:46:33.264 car_id=1 [info] Start / :asleep
2024-01-30 15:46:33.275 car_id=1 [info] Disconnecting ...
2024-01-30 15:46:36.115 [info] PUT /api/car/1/logging/resume
2024-01-30 15:46:36.116 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 15:46:36.116 [info] Sent 204 in 678µs
2024-01-30 15:46:36.148 [info] PUT /api/car/4/logging/resume
2024-01-30 15:46:36.151 [info] Sent 204 in 2ms
2024-01-30 15:46:46.216 [info] PUT /api/car/1/logging/resume
2024-01-30 15:46:46.218 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 15:46:46.218 [info] Sent 204 in 1ms
2024-01-30 15:46:46.258 [info] PUT /api/car/4/logging/resume
2024-01-30 15:46:46.259 [info] Sent 204 in 561µs
2024-01-30 15:46:49.647 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXX -> 429 (51.729 ms)
2024-01-30 15:46:49.647 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 15:46:56.303 [info] PUT /api/car/1/logging/resume
2024-01-30 15:46:49.648 car_id=1 [error] Error / :unknown
2024-01-30 15:46:56.304 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 15:46:56.304 [info] Sent 204 in 620µs
2024-01-30 15:46:56.338 [info] PUT /api/car/4/logging/resume
2024-01-30 15:46:56.339 [info] Sent 204 in 646µs
2024-01-30 15:46:56.361 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXX -> 429 (57.012 ms)
2024-01-30 15:46:56.361 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 15:46:56.361 car_id=1 [error] Error / :unknown

@dyxyl
Copy link
Contributor

dyxyl commented Jan 30, 2024

Do you have the Streaming API enabled in the Settings page?

@pkuehnel
Copy link
Author

pkuehnel commented Jan 30, 2024

Yes. As I said, this only occurs when there is something wrong with the streaming API on drive/charge start. But your question has nothing to do with my issue. The issue is, that suspend logging is not needed anymore.

@pkuehnel pkuehnel changed the title Missing data due to suspend logging which is not needed anymore Suspend logging is not needed anymore as car falls asleep even while polling Jan 30, 2024
@micves
Copy link
Contributor

micves commented Jan 30, 2024

For me it seems more that there might be an issue with /api/car//logging/resume

This:

2024-01-30 15:46:56.361 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXX -> 429 (57.012 ms)

Indicates that teslamate is polling on the non-keeping-car-awake-state, which is happening when teslamate suspends the polling from https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXX/vehicle_data which is the polling that can keep the car awake (and should also be able to wake it up)

Can you extend the log you have to also contain some earlier [info] Start / :xxxx like this one:

2024-01-30 15:46:33.264 car_id=1 [info] Start / :asleep

The must be some Start / :online somewhere. At that point vehicle_data is being polled.
At some point something like "Suspending logging" should appear which switched the polling to non-vehicle_data polling.

Since you are telling teslamate to resume every 10 seconds it might mess something up in the switch between what is polled.

@pkuehnel
Copy link
Author

I updated my script to only call /api/car//logging/resume every 90 seconds now and will post a log tomorrow.

But I am pretty sure that pausing the log is not needed anymore. I am using the new Fleet API in parallel, and there I also call vehicle_data as long as the car is online and still falls asleep.

Is there a way to change the polling breaks? Sadly, the options to change the intervals disappear when enabling the streaming API.

@pkuehnel
Copy link
Author

Both cars still falling asleep while polling.

Logs
2024-01-30 22:40:17.627 car_id=4 [info] Start / :online
2024-01-30 22:39:17.537 car_id=1 [info] Start / :online
2024-01-30 22:39:17.627 car_id=1 [info] Connecting ...
2024-01-30 22:39:26.019 [info] Sent 200 in 1ms
2024-01-30 22:39:26.017 [info] GET /
2024-01-30 22:39:45.883 [info] PUT /api/car/1/logging/resume
2024-01-30 22:39:45.883 [info] Sent 204 in 626µs
2024-01-30 22:39:45.934 [info] PUT /api/car/4/logging/resume
2024-01-30 22:39:45.935 car_id=4 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 22:39:45.935 [info] Sent 204 in 1ms
2024-01-30 22:40:17.636 car_id=4 [info] Connecting ...
2024-01-30 22:40:26.021 [info] Sent 200 in 2ms
2024-01-30 22:41:16.002 [info] PUT /api/car/1/logging/resume
2024-01-30 22:40:26.019 [info] GET /
2024-01-30 22:41:16.003 [info] Sent 204 in 1ms
2024-01-30 22:41:16.046 [info] PUT /api/car/4/logging/resume
2024-01-30 22:41:16.047 [info] Sent 204 in 614µs
2024-01-30 22:41:26.007 [info] GET /
2024-01-30 22:41:26.009 [info] Sent 200 in 1ms
2024-01-30 22:42:12.656 [info] Start of drive initiated by: %TeslaApi.Stream.Data{time: ~U[2024-01-30 22:42:11.057Z], speed: 0, odometer: 71432.2, soc: 44, elevation: 532, est_heading: 294, est_lat: XX.988284, est_lng: XX.970618, power: 1, shift_state: "D", range: 117, est_range: 99, heading: 293}
2024-01-30 22:42:12.657 car_id=1 [info] Driving / Start
2024-01-30 22:42:12.723 car_id=1 [info] Fetch already in progress ...
2024-01-30 22:42:26.016 [info] GET /
2024-01-30 22:42:26.021 [info] Sent 200 in 4ms
2024-01-30 22:42:46.090 [info] PUT /api/car/1/logging/resume
2024-01-30 22:42:46.090 [info] Sent 204 in 448µs
2024-01-30 22:42:46.140 [info] PUT /api/car/4/logging/resume
2024-01-30 22:42:46.141 [info] Sent 204 in 551µs
2024-01-30 22:42:47.893 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (216.763 ms)
2024-01-30 22:42:48.429 [info] End of drive initiated by: %TeslaApi.Vehicle.State.Drive{gps_as_of: 1706654566, heading: 109, latitude: XX.988232, longitude: XX.97057, native_latitude: XX.988232, native_location_supported: 1, native_longitude: XX.97057, native_type: "wgs", power: 1, shift_state: "P", speed: 0, timestamp: 1706654566034}
2024-01-30 22:42:48.398 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (487.029 ms)
2024-01-30 22:42:48.430 car_id=1 [info] Driving / Ended / 0 km – 1 min
2024-01-30 22:42:48.430 car_id=1 [info] Start / :online
2024-01-30 22:43:03.499 [notice]     :alarm_handler: {:clear, TeslaMate.Vehicles.Vehicle_4_api_error}
2024-01-30 22:43:19.293 car_id=4 [warning] Received stale stream data: %TeslaApi.Stream.Data{time: ~U[2024-01-30 22:43:47.927Z], speed: nil, odometer: 7044.8, soc: 64, elevation: 425, est_heading: 249, est_lat: XX.887404, est_lng: XX.975627, power: 0, shift_state: nil, range: 202, est_range: 184, heading: 249}
2024-01-30 22:43:26.010 [info] GET /
2024-01-30 22:43:26.012 [info] Sent 200 in 1ms
2024-01-30 22:44:16.186 [info] PUT /api/car/1/logging/resume
2024-01-30 22:44:16.187 [info] Sent 204 in 676µs
2024-01-30 22:44:16.239 [info] PUT /api/car/4/logging/resume
2024-01-30 22:44:16.240 [info] Sent 204 in 668µs
2024-01-30 22:44:26.012 [info] Sent 200 in 2ms
2024-01-30 22:44:28.157 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX/vehicle_data -> 408 (9085.830 ms)
2024-01-30 22:44:26.010 [info] GET /
2024-01-30 22:44:28.157 car_id=4 [error] Error / :unknown
2024-01-30 22:44:28.157 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
2024-01-30 22:44:57.251 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX/vehicle_data -> 408 (9093.577 ms)
2024-01-30 22:44:57.251 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
2024-01-30 22:44:57.253 car_id=4 [error] Error / :unknown
2024-01-30 22:45:26.008 [info] GET /
2024-01-30 22:45:26.010 [info] Sent 200 in 1ms
2024-01-30 22:45:46.354 [info] PUT /api/car/1/logging/resume
2024-01-30 22:45:46.354 [info] Sent 204 in 548µs
2024-01-30 22:45:46.390 [info] PUT /api/car/4/logging/resume
2024-01-30 22:45:46.390 [info] Sent 204 in 560µs
2024-01-30 22:46:03.502 [notice]     :alarm_handler: {:clear, TeslaMate.Vehicles.Vehicle_1_api_error}
2024-01-30 22:46:26.009 [info] GET /
2024-01-30 22:46:26.011 [info] Sent 200 in 2ms
2024-01-30 22:47:16.424 [info] PUT /api/car/1/logging/resume
2024-01-30 22:47:16.425 [info] Sent 204 in 822µs
2024-01-30 22:47:16.459 [info] PUT /api/car/4/logging/resume
2024-01-30 22:47:16.460 [info] Sent 204 in 682µs
2024-01-30 22:47:26.015 [info] GET /
2024-01-30 22:47:26.017 [info] Sent 200 in 2ms
2024-01-30 22:48:26.011 [info] GET /
2024-01-30 22:48:26.014 [info] Sent 200 in 2ms
2024-01-30 22:48:46.497 [info] PUT /api/car/1/logging/resume
2024-01-30 22:48:46.498 [info] Sent 204 in 590µs
2024-01-30 22:48:46.556 [info] PUT /api/car/4/logging/resume
2024-01-30 22:48:46.556 [info] Sent 204 in 556µs
2024-01-30 22:49:26.018 [info] GET /
2024-01-30 22:49:26.020 [info] Sent 200 in 2ms
2024-01-30 22:50:16.609 [info] PUT /api/car/1/logging/resume
2024-01-30 22:50:16.609 [info] Sent 204 in 671µs
2024-01-30 22:50:16.642 [info] PUT /api/car/4/logging/resume
2024-01-30 22:50:16.643 [info] Sent 204 in 632µs
2024-01-30 22:50:26.006 [info] GET /
2024-01-30 22:50:26.008 [info] Sent 200 in 1ms
2024-01-30 22:50:36.983 [warning] Too many disconnects from streaming API
2024-01-30 22:50:36.983 car_id=4 [info] Creating new connection … 
2024-01-30 22:50:36.985 car_id=4 [info] Disconnecting ...
2024-01-30 22:50:36.991 car_id=4 [info] Connecting ...
2024-01-30 22:51:01.565 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX/vehicle_data -> 408 (9086.480 ms)
2024-01-30 22:51:01.565 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
2024-01-30 22:51:01.565 car_id=1 [error] Error / :unknown
2024-01-30 22:51:26.020 [info] GET /
2024-01-30 22:51:30.657 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX/vehicle_data -> 408 (9090.484 ms)
2024-01-30 22:51:26.022 [info] Sent 200 in 2ms
2024-01-30 22:51:30.657 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
2024-01-30 22:51:30.657 car_id=1 [error] Error / :unknown
2024-01-30 22:51:46.686 [info] PUT /api/car/1/logging/resume
2024-01-30 22:51:46.687 [info] Sent 204 in 584µs
2024-01-30 22:51:46.720 [info] PUT /api/car/4/logging/resume
2024-01-30 22:51:46.720 [info] Sent 204 in 570µs
2024-01-30 22:52:26.020 [info] GET /
2024-01-30 22:53:16.758 [info] PUT /api/car/1/logging/resume
2024-01-30 22:52:26.022 [info] Sent 200 in 1ms
2024-01-30 22:53:16.758 [info] Sent 204 in 654µs
2024-01-30 22:53:16.801 [info] PUT /api/car/4/logging/resume
2024-01-30 22:53:16.802 [info] Sent 204 in 531µs
2024-01-30 22:53:26.024 [info] Sent 200 in 2ms
2024-01-30 22:53:26.022 [info] GET /
2024-01-30 22:53:51.850 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX/vehicle_data -> 408 (94.011 ms)
2024-01-30 22:54:02.019 car_id=1 [info] Start / :asleep
2024-01-30 22:54:02.046 car_id=1 [info] Disconnecting ...
2024-01-30 22:54:22.415 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX/vehicle_data -> 408 (80.042 ms)
2024-01-30 22:54:26.022 [info] Sent 200 in 1ms
2024-01-30 22:54:26.020 [info] GET /
2024-01-30 22:54:32.585 car_id=4 [info] Start / :asleep
2024-01-30 22:54:32.590 car_id=4 [info] Disconnecting ...
2024-01-30 22:54:46.842 [info] PUT /api/car/1/logging/resume
2024-01-30 22:54:46.842 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 22:54:46.843 [info] Sent 204 in 824µs
2024-01-30 22:54:46.891 [info] PUT /api/car/4/logging/resume
2024-01-30 22:54:46.892 car_id=4 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 22:54:46.892 [info] Sent 204 in 650µs
2024-01-30 22:54:47.972 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (53.504 ms)
2024-01-30 22:54:47.972 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 22:54:48.019 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (52.586 ms)
2024-01-30 22:54:47.972 car_id=1 [error] Error / :unknown
2024-01-30 22:54:48.019 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 22:54:48.019 car_id=4 [error] Error / :unknown
2024-01-30 22:55:26.012 [info] GET /
2024-01-30 22:55:48.365 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (65.659 ms)
2024-01-30 22:55:26.014 [info] Sent 200 in 2ms

@cwanja
Copy link
Collaborator

cwanja commented Jan 30, 2024

What I never see is:

  1. state asleep
  2. You try to poll
  3. Vehicle returns a state of asleep still

Unless I am missing that in the logs. But I fail to see it.

@pkuehnel
Copy link
Author

@cwanja I'm not sure what you want me to do 🤔

@cwanja
Copy link
Collaborator

cwanja commented Jan 30, 2024

@cwanja I'm not sure what you want me to do 🤔

Where in those logs does it show that the car is asleep? And still asleep after you resume polling.

That's what I am missing. To answer you specifically, I am looking for evidence that:

  1. The car went into a sleep state (via the Tesla API) or TeslaMate reporting it as asleep.
  2. Resume your polling however you want and show that you are actively polling the car.
  3. Reflect that your Tesla is still asleep after you resume polling.

@pkuehnel
Copy link
Author

pkuehnel commented Jan 30, 2024

  1. I thought
2024-01-30 22:54:02.019 car_id=1 [info] Start / :asleep 

Means the car is asleep, that's why I pasted the log until that point.

  1. How can I show that I am actively polling the car? The only thing I do for now is resume logging, this cancels the trying to sleep.
  2. Also not sure how I can show that.

What I am trying to tell you is, that the car falls asleep even though polling /vehicle_data. While the car is asleep calling /vehicle is enough, as the state is displayed as online there when the car wakes up. The only issue is that /vehicle_data is not polled when the car is parked and these breaks are not needed anymore.

@cwanja
Copy link
Collaborator

cwanja commented Jan 31, 2024

  1. No, that is just TeslaMate suspending polling to let the car go to sleep.

@pkuehnel
Copy link
Author

It looks like there is a bug in TeslaMate that if the car falls asleep while being polled, the message is not logged. As you can see here, in the dashboard, the car is displayed as asleep from that point (I am UTC +1; Screenshot is from carID 1):

image

What I also notice is that the car is alternating between healthy and not healthy all the time while being asleep:
image

Here are a few more logs, but as you can see, nothing is logged, indicating that the car is asleep. But it is, the States Dashboard is correct.

Logs
2024-01-30 22:55:48.365 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (65.659 ms)
2024-01-30 22:55:48.365 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 22:55:48.367 car_id=1 [error] Error / :unknown
2024-01-30 22:55:48.407 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (67.651 ms)
2024-01-30 22:55:48.407 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 22:55:48.407 car_id=4 [error] Error / :unknown
2024-01-30 22:56:03.512 [notice]     :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_1_api_error, :fuse_blown}}
2024-01-30 22:56:16.922 [info] PUT /api/car/1/logging/resume
2024-01-30 22:56:16.923 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 22:56:16.923 [info] Sent 204 in 669µs
2024-01-30 22:56:16.997 [info] PUT /api/car/4/logging/resume
2024-01-30 22:56:16.998 car_id=4 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 22:56:16.998 [info] Sent 204 in 838µs
2024-01-30 22:56:26.008 [info] GET /
2024-01-30 22:56:26.010 [info] Sent 200 in 1ms
2024-01-30 22:56:32.317 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (52.421 ms)
2024-01-30 22:56:32.317 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 22:56:32.317 car_id=1 [error] Error / :unknown
2024-01-30 22:56:32.373 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (52.599 ms)
2024-01-30 22:56:32.373 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 22:56:32.373 car_id=4 [error] Error / :unknown
2024-01-30 22:57:26.009 [info] GET /
2024-01-30 22:57:26.011 [info] Sent 200 in 2ms
2024-01-30 22:57:47.091 [info] PUT /api/car/1/logging/resume
2024-01-30 22:57:47.092 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 22:57:47.092 [info] Sent 204 in 719µs
2024-01-30 22:57:47.133 [info] PUT /api/car/4/logging/resume
2024-01-30 22:57:47.134 car_id=4 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 22:57:47.134 [info] Sent 204 in 826µs
2024-01-30 22:57:50.304 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (52.904 ms)
2024-01-30 22:57:50.304 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 22:57:50.304 car_id=1 [error] Error / :unknown
2024-01-30 22:57:50.346 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (53.095 ms)
2024-01-30 22:57:50.346 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 22:57:50.346 car_id=4 [error] Error / :unknown
2024-01-30 22:58:03.514 [notice]     :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_4_api_error, :fuse_blown}}
2024-01-30 22:58:26.013 [info] GET /
2024-01-30 22:58:26.017 [info] Sent 200 in 4ms
2024-01-30 22:59:17.204 [info] PUT /api/car/1/logging/resume
2024-01-30 22:59:17.204 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 22:59:17.204 [info] Sent 204 in 707µs
2024-01-30 22:59:17.234 [info] PUT /api/car/4/logging/resume
2024-01-30 22:59:17.235 car_id=4 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 22:59:17.235 [info] Sent 204 in 656µs
2024-01-30 22:59:26.007 [info] GET /
2024-01-30 22:59:26.009 [info] Sent 200 in 1ms
2024-01-30 22:59:32.595 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (53.564 ms)
2024-01-30 22:59:32.595 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 22:59:32.595 car_id=1 [error] Error / :unknown
2024-01-30 22:59:32.613 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (60.847 ms)
2024-01-30 22:59:32.614 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 22:59:32.614 car_id=4 [error] Error / :unknown
2024-01-30 23:00:26.017 [info] GET /
2024-01-30 23:00:26.020 [info] Sent 200 in 3ms
2024-01-30 23:00:47.279 [info] PUT /api/car/1/logging/resume
2024-01-30 23:00:47.279 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 23:00:47.280 [info] Sent 204 in 690µs
2024-01-30 23:00:47.317 [info] PUT /api/car/4/logging/resume
2024-01-30 23:00:47.317 car_id=4 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 23:00:47.317 [info] Sent 204 in 637µs
2024-01-30 23:00:50.489 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (53.305 ms)
2024-01-30 23:00:50.489 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 23:00:50.489 car_id=1 [error] Error / :unknown
2024-01-30 23:00:50.552 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (57.738 ms)
2024-01-30 23:00:50.552 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 23:00:50.553 car_id=4 [error] Error / :unknown
2024-01-30 23:01:26.007 [info] GET /
2024-01-30 23:01:26.009 [info] Sent 200 in 1ms
2024-01-30 23:02:17.366 [info] PUT /api/car/1/logging/resume
2024-01-30 23:02:17.367 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 23:02:17.367 [info] Sent 204 in 729µs
2024-01-30 23:02:17.406 [info] PUT /api/car/4/logging/resume
2024-01-30 23:02:17.408 car_id=4 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 23:02:17.408 [info] Sent 204 in 2ms
2024-01-30 23:02:26.016 [info] GET /
2024-01-30 23:02:26.019 [info] Sent 200 in 2ms
2024-01-30 23:02:32.794 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (52.524 ms)
2024-01-30 23:02:32.794 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 23:02:32.794 car_id=1 [error] Error / :unknown
2024-01-30 23:02:32.987 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (107.717 ms)
2024-01-30 23:02:32.987 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 23:02:32.988 car_id=4 [error] Error / :unknown
2024-01-30 23:03:03.519 [notice]     :alarm_handler: {:clear, TeslaMate.Vehicles.Vehicle_1_api_error}
2024-01-30 23:03:26.020 [info] GET /
2024-01-30 23:03:26.022 [info] Sent 200 in 1ms
2024-01-30 23:03:47.450 [info] PUT /api/car/1/logging/resume
2024-01-30 23:03:47.451 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 23:03:47.451 [info] Sent 204 in 768µs
2024-01-30 23:03:47.490 [info] PUT /api/car/4/logging/resume
2024-01-30 23:03:47.490 car_id=4 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 23:03:47.491 [info] Sent 204 in 743µs
2024-01-30 23:03:50.664 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (53.943 ms)
2024-01-30 23:03:50.664 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 23:03:50.664 car_id=1 [error] Error / :unknown
2024-01-30 23:03:50.718 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (60.166 ms)
2024-01-30 23:03:50.718 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 23:03:50.718 car_id=4 [error] Error / :unknown
2024-01-30 23:04:26.013 [info] GET /
2024-01-30 23:04:26.015 [info] Sent 200 in 2ms
2024-01-30 23:05:03.521 [notice]     :alarm_handler: {:clear, TeslaMate.Vehicles.Vehicle_4_api_error}
2024-01-30 23:05:17.532 [info] PUT /api/car/1/logging/resume
2024-01-30 23:05:17.533 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 23:05:17.533 [info] Sent 204 in 828µs
2024-01-30 23:05:17.579 [info] PUT /api/car/4/logging/resume
2024-01-30 23:05:17.580 car_id=4 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 23:05:17.580 [info] Sent 204 in 720µs
2024-01-30 23:05:26.012 [info] GET /
2024-01-30 23:05:26.014 [info] Sent 200 in 1ms
2024-01-30 23:05:32.952 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (54.449 ms)
2024-01-30 23:05:32.952 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 23:05:32.952 car_id=4 [error] Error / :unknown
2024-01-30 23:05:32.958 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (53.710 ms)
2024-01-30 23:05:32.958 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 23:05:32.959 car_id=1 [error] Error / :unknown
2024-01-30 23:06:03.522 [notice]     :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_1_api_error, :fuse_blown}}
2024-01-30 23:06:26.019 [info] GET /
2024-01-30 23:06:26.021 [info] Sent 200 in 1ms
2024-01-30 23:06:47.626 [info] PUT /api/car/1/logging/resume
2024-01-30 23:06:47.635 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 23:06:47.635 [info] Sent 204 in 9ms
2024-01-30 23:06:47.679 [info] PUT /api/car/4/logging/resume
2024-01-30 23:06:47.679 car_id=4 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 23:06:47.680 [info] Sent 204 in 946µs
2024-01-30 23:06:50.854 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (58.919 ms)
2024-01-30 23:06:50.855 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 23:06:50.855 car_id=1 [error] Error / :unknown
2024-01-30 23:06:50.894 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (55.082 ms)
2024-01-30 23:06:50.894 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 23:06:50.894 car_id=4 [error] Error / :unknown
2024-01-30 23:07:26.022 [info] GET /
2024-01-30 23:07:26.027 [info] Sent 200 in 4ms
2024-01-30 23:08:17.731 [info] PUT /api/car/1/logging/resume
2024-01-30 23:08:17.732 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 23:08:17.732 [info] Sent 204 in 738µs
2024-01-30 23:08:17.764 [info] PUT /api/car/4/logging/resume
2024-01-30 23:08:17.764 car_id=4 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 23:08:17.764 [info] Sent 204 in 611µs
2024-01-30 23:08:26.016 [info] GET /
2024-01-30 23:08:26.018 [info] Sent 200 in 1ms
2024-01-30 23:08:33.113 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (52.669 ms)
2024-01-30 23:08:33.113 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 23:08:33.113 car_id=1 [error] Error / :unknown
2024-01-30 23:08:33.147 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/XXXXXXXXXXXXXX -> 429 (53.239 ms)
2024-01-30 23:08:33.147 [warning] TeslaApi.Error / "Retry later\n"
2024-01-30 23:08:33.147 car_id=4 [error] Error / :unknown
2024-01-30 23:09:03.525 [notice]     :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_4_api_error, :fuse_blown}}
2024-01-30 23:09:19.518 car_id=4 [info] Start / :online
2024-01-30 23:09:19.600 car_id=4 [info] Connecting ...
2024-01-30 23:09:26.007 [info] GET /
2024-01-30 23:09:26.009 [info] Sent 200 in 2ms
2024-01-30 23:09:36.879 [info] GET /
2024-01-30 23:09:36.882 [info] Sent 200 in 2ms
2024-01-30 23:09:47.796 [info] PUT /api/car/1/logging/resume
2024-01-30 23:09:47.796 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
2024-01-30 23:09:47.796 [info] Sent 204 in 636µs
2024-01-30 23:09:47.854 [info] PUT /api/car/4/logging/resume
2024-01-30 23:09:47.855 [info] Sent 204 in 662µs

@brianmay
Copy link
Collaborator

Some random points.

asleep state

I do believe that:

2024-01-30 22:54:02.019 car_id=1 [info] Start / :asleep 

Means TeslaMate is entering the :asleep state. Which means it thinks for some reason the car is asleep. But we can only guess if the car is asleep or not, it is possible that we got it wrong.

Having said that, my understanding of how we transition to the :asleep state is somewhat foggy. I imagine it is based on the get and/or get_with_state Tesla calls. But I can't find that logic right now.

The :suspended state is for when we are trying to get the car to go to sleep.

429 errors

The expected error when the car is asleep is 408. But in the above we are seeing 429. This is the rate limit error, it means that the Tesla API is refusing to process the request because it has deemed that we have exceeded predetermined limits. It does not mean that the car is asleep.

We do not currently process 429 errors correctly.

@pkuehnel
Copy link
Author

The car is definitely asleep at this point as the high voltage switches click at this point. Try it yourself, the car goes to sleep while polling /vehicle_data. The polling breaks are not needed anymore.

@pkuehnel
Copy link
Author

pkuehnel commented Jan 31, 2024

The car is also displayed for multiple hours as asleep, when I enter the car the high voltage switches click again and there is no vampire drain even not after 30 hours.

The new Fleet API /vehicle Endpoint also prints asleep as state, the /vehicle_data Endpoint returns an error that the car can't be polled as it is offline or asleep. And this happens seconds after the last poll succeeded with returning location, climate state, driving state, charging state,... Don't know why no one trusts me here 😂

@micves
Copy link
Contributor

micves commented Jan 31, 2024

My findings are that whenever Teslamate writes Start / :[something] it is because that is the state coming directly from the api using either /vehicle or /vehicle_data. They both contain a state that can be online, asleep or offline. So that should be the true state of the car.

Suspended is an internal state in Teslamate where the actual state is online, but /vehicle_data is not polled. Only /vehicle.
When streaming api is turned on, the timer before going to suspended is lower (3min I think) because the streaming api will try to stay connected and detect driving or charging based on the shift_state = D/R/N or power < 0

I agree in /vehicle_data not doing anything if the car is already asleep or offline, I can't wake my car (2017 model s with MCU2 retrofit) with Invoke-WebRequest -Uri "http://192.168.1.5:4000/api/car/1/logging/resume" -Method Put

I would however say that going to suspended is still useful, see my PR #3262
My findings are that polling vehicle_data extends the wake time. Not saying that it will never sleep, never really tried it...

Is this something you can test. E.g. after a drive or after you leave it and lock it: How long does it take your car to go to asleep when you trigger resume vs. when you don't

@pkuehnel
Copy link
Author

pkuehnel commented Jan 31, 2024

How long does it take your car to go to asleep

I tested that already but it is not really possible to determine the time it takes as (at least my 2019 Model 3) dries the air conditioning after each drive. So after a drive in very cold conditions (below ~-5°C) the car goes to sleep pretty much immediately after leaving it, sometimes after less than one minutes. But there are times the car is still awake after the first trying to sleep period which are 30 minutes I think. Sometimes it takes more than 30 minutes even if I only opened the trunk and do not drive (so AC did not start). So absolutely not sure if it makes a difference. But as it often goes to sleep immediately even if polling, I think it makes no difference.

@brianmay
Copy link
Collaborator

I think we need to make the appropriate change, test it on as many different cars and MCU versions as possible, and see what happens.

I think the relevant code is:

https://github.com/teslamate-org/teslamate/blob/master/lib/teslamate/vehicles/vehicle.ex#L1345-L1352

    {suspend_after_idle_min, suspend_min, i} =
      case {car.settings, streaming?(data)} do
        {%CarSettings{use_streaming_api: true}, true} -> {3, 30, 2}
        {%CarSettings{suspend_after_idle_min: i, suspend_min: s}, _} -> {i, s, 1}
      end

    suspend? = diff_seconds(DateTime.utc_now(), data.last_used) / 60 >= suspend_after_idle_min

So if streaming is enabled in web interface, then we use hard coded values, otherwise we get values from the database (which come from the web interface but only shown if streaming is disabled).

My theory is if we can set a long time for suspend_after_idle_min then we give let the car go to sleep while still polling for longer. And only if that fails, do we try to enter the :suspend mode.

I think the other two values control how long we wait before trying to fetch the data.

@brianmay
Copy link
Collaborator

Also note that stuff here might change, e.g. if Tesla introduces the strict rate limits as documented here, then increasing the polling may be a bad idea.

@pkuehnel
Copy link
Author

As a first step a good solution would be to use the database values on streaming API as well and allow editing the values when streaming API is enabled. Maybe auto set the currently hard coded values when switching to streaming API.

@JakobLichterfeld
Copy link
Collaborator

JakobLichterfeld commented Feb 3, 2024

The vehicle takes much longer to fall asleep during active polling. It does fall asleep, but it takes longer. If we prolong the polling, we increase the vampire drain.

Personally, I hit "try to sleep" manually when I leave the car. This causes the least amount of irritation and the smoothest fall asleep observed.

@JakobLichterfeld JakobLichterfeld added the closed:invalid This doesn't seem right label Feb 3, 2024
@pkuehnel
Copy link
Author

pkuehnel commented Feb 3, 2024

@JakobLichterfeld Not sure where your data is from, but my car sleeps sometimes after 3 minutes even though polling every 10 seconds, so your comment seems to be invalid:
image

@pkuehnel
Copy link
Author

pkuehnel commented Feb 3, 2024

Most of the time it is about 10 minutes but not sure how 10 minutes can be "way" longer:

image

@JakobLichterfeld
Copy link
Collaborator

JakobLichterfeld commented Feb 3, 2024

Obviously our MCUs are different. And you only consider wake time after charge or drive.

@pkuehnel
Copy link
Author

pkuehnel commented Feb 3, 2024

As my 2019 Model 3 and my 2023 Model Y behave the same, it seems like all cars except Legacy S/X fall asleep despite being polled. So there won't be a solution on that front, and very likely,> 90% of the users have to deal with missing drives/charges? I really would appreciate it if at least the three and 30 minutes weren't hard-coded (and the invalid label would be removed on that issue).

@JakobLichterfeld
Copy link
Collaborator

JakobLichterfeld commented Feb 3, 2024

I don't own any legacy S or X. Model 3 has at least 3 different MCU versions.
I would really love to get rid of these suspend logging, just need a working solution. Setting sleep values feels really like ancient times and do not go in the right direction.

@micves
Copy link
Contributor

micves commented Feb 3, 2024

I have a 2017 Model S with MCU2 retrofit
I got some data just after a drive

When doing nothing:

2024-01-29 09:02:54.967 car_id=1 [info] Driving / Ended / 30 km – 22 min
2024-01-29 09:02:54.967 car_id=1 [info] Start / :online
2024-01-29 09:06:29.366 car_id=1 [info] Suspending logging
2024-01-29 09:10:16.558 car_id=1 [info] Fetching vehicle state ...
2024-01-29 09:11:00.092 car_id=1 [info] Start / :offline

2024-01-30 08:59:15.805 car_id=1 [info] Driving / Ended / 22 km – 27 min
2024-01-30 08:59:15.805 car_id=1 [info] Start / :online
2024-01-30 09:02:33.846 car_id=1 [info] Suspending logging
2024-01-30 09:06:26.516 car_id=1 [info] Fetching vehicle state ...
2024-01-30 09:07:27.309 [info] Streaming API: Vehicle offline
2024-01-30 09:07:27.310 car_id=1 [info] Stream reports vehicle as offline …
2024-01-30 09:07:27.310 car_id=1 [info] Start / :offline

2024-01-30 17:45:24.203 car_id=1 [info] Driving / Ended / 152 km – 94 min
2024-01-30 17:45:24.203 car_id=1 [info] Start / :online
2024-01-30 17:50:57.803 car_id=1 [info] Suspending logging
2024-01-30 17:58:21.808 car_id=1 [info] Fetching vehicle state ...
2024-01-30 17:58:59.214 car_id=1 [info] Start / :offline

2024-01-31 08:03:13.398 car_id=1 [info] Driving / Ended / 16 km – 16 min
2024-01-31 08:03:13.398 car_id=1 [info] Start / :online
2024-01-31 08:06:34.049 car_id=1 [info] Suspending logging
2024-01-31 08:15:51.415 car_id=1 [info] Fetching vehicle state ...
2024-01-31 08:16:52.143 [info] Streaming API: Vehicle offline
2024-01-31 08:16:52.143 car_id=1 [info] Stream reports vehicle as offline …
2024-01-31 08:16:52.143 car_id=1 [info] Start / :offline

2024-01-31 18:07:43.765 car_id=1 [info] Driving / Ended / 22 km – 31 min
2024-01-31 18:07:43.765 car_id=1 [info] Start / :online
2024-01-31 18:11:18.194 car_id=1 [info] Suspending logging
2024-01-31 18:15:06.643 car_id=1 [info] Fetching vehicle state ...
2024-01-31 18:15:06.927 [info] Streaming API: Vehicle offline
2024-01-31 18:15:06.927 car_id=1 [info] Stream reports vehicle as offline …
2024-01-31 18:15:06.927 car_id=1 [info] Start / :offline

2024-01-31 19:44:31.734 car_id=1 [info] Driving / Ended / 22 km – 21 min
2024-01-31 19:44:31.735 car_id=1 [info] Start / :online
2024-01-31 19:48:26.835 car_id=1 [info] Suspending logging
2024-01-31 19:52:16.519 car_id=1 [info] Fetching vehicle state ...
2024-01-31 19:52:57.778 car_id=1 [info] Start / :offline

2024-02-01 17:19:23.482 car_id=1 [info] Driving / Ended / 17 km – 18 min
2024-02-01 17:19:23.482 car_id=1 [info] Start / :online
2024-02-01 17:21:08.218 [info] GET /
2024-02-01 17:21:08.226 [info] Sent 200 in 7ms
2024-02-01 17:22:59.357 car_id=1 [info] Suspending logging [Triggered manually]
2024-02-01 17:32:21.510 car_id=1 [info] Fetching vehicle state ...
2024-02-01 17:32:52.119 [info] Streaming API: Vehicle offline
2024-02-01 17:32:52.119 car_id=1 [info] Stream reports vehicle as offline …
2024-02-01 17:32:52.119 car_id=1 [info] Start / :offline

Suspending logging happens after around 3 minuttes (like intended based on the code)
offline comes 4-10 minuttes after suspending logging

I have tried after a drive to keep it logging by clicking resume logging on the webpage

2024-02-02 12:34:29.752 car_id=1 [info] Driving / Ended / 16 km – 27 min
2024-02-02 12:34:29.752 car_id=1 [info] Start / :online
2024-02-02 12:35:24.360 [warning] Too many disconnects from streaming API
2024-02-02 12:35:24.361 car_id=1 [info] Creating new connection …
2024-02-02 12:35:24.361 car_id=1 [info] Disconnecting ...
2024-02-02 12:35:24.369 car_id=1 [info] Connecting ...
2024-02-02 12:37:28.686 [info] GET /
2024-02-02 12:37:28.699 [info] Sent 200 in 13ms
2024-02-02 12:37:34.009 [info] GET /
2024-02-02 12:37:34.021 [info] Sent 200 in 11ms
2024-02-02 12:37:47.258 car_id=1 [info] Suspending logging
2024-02-02 12:37:53.562 car_id=1 [info] Resuming logging
2024-02-02 12:38:31.963 [info] GET /
2024-02-02 12:38:31.975 [info] Sent 200 in 11ms
2024-02-02 12:40:58.183 car_id=1 [info] Suspending logging
2024-02-02 12:41:53.315 [warning] Too many disconnects from streaming API
2024-02-02 12:41:53.315 car_id=1 [info] Creating new connection …
2024-02-02 12:41:53.315 car_id=1 [info] Disconnecting ...
2024-02-02 12:41:53.327 car_id=1 [info] Connecting ...
2024-02-02 12:46:21.601 car_id=1 [info] Resuming logging
2024-02-02 12:48:22.995 [warning] Too many disconnects from streaming API
2024-02-02 12:48:22.996 car_id=1 [info] Creating new connection …
2024-02-02 12:48:22.997 car_id=1 [info] Disconnecting ...
2024-02-02 12:48:23.006 car_id=1 [info] Connecting ...
2024-02-02 12:49:26.996 car_id=1 [info] Suspending logging
2024-02-02 12:51:09.068 car_id=1 [info] Fetching vehicle state ...
2024-02-02 12:53:10.414 [info] Streaming API: Vehicle offline
2024-02-02 12:53:10.414 car_id=1 [info] Stream reports vehicle as offline …
2024-02-02 12:53:10.414 car_id=1 [info] Start / :offline

For now I only have this one test where I did it.
After the last [info] Suspending logging it goes offline after 4 minutes.
It does seem to keep it awake.. on MCU2 retrofit Model S 2017 anyways :)

I actually don't think I ever missed a drive due to the stream API being down.
It will keep reconnecting and eventually trigger the drive, right?

And with bad internet. Wont both polling and streaming be down anyways?

So I would actually rather have it suspend faster :)
I know this would go against the original issue, but it would make sense to actually suspend logging as soon as the car is ready for it. All the conditions are listed in the function @brianmay got the code from further up.
try_to_suspend:
https://github.com/teslamate-org/teslamate/blob/master/lib/teslamate/vehicles/vehicle.ex#L1345

I actually already have an experiment in PR #3262 where I suspend when getting fetch errors in online.
It seems to work quite well, but again it is to avoid polling vehicle_data that keeps (some) cars awake

@pkuehnel
Copy link
Author

pkuehnel commented Feb 3, 2024

And with bad internet. Wont both polling and streaming be down anyways?

@micves No: The streaming API only detects drive and charge starts. If you begin your drive in a garage with no internet and polling has just stopped, the next 30 minutes won't be logged. Calling vehicle_data does not only detect the starts of charges/drives but also if the car is charging/driving. So, as soon as you drive out of your garage and the car has an internet connection, logging is started as TeslaMate detects the car is driving.

But I see there are many different requirements. Best would probably be if the timers wouldn't be hard coded, so I could enter 999999 minutes until polling is stopped and @micves or @JakobLichterfeld could enter 0 resulting in polling is immediately stopped.

@brianmay
Copy link
Collaborator

brianmay commented Feb 4, 2024

As much as this suspend state is a huge hack; it means we can take a while to notice events that happen while the car is in the suspend state (other then what we pick up from streaming - e.g. event when car is plugged in) - I am not convinced we can remove it.

Maybe if we can fill in a table like the following? Hopefully I got this correct, please check ;-)

A wiki page might be better, anyone can edit; although I don't think we have that enabled at present.

Model MCU Requires Suspend
2017 Model S MCU2 yes
2019 Model 3 ? yes
2023 Model Y ? yes

@pkuehnel
Copy link
Author

pkuehnel commented Feb 4, 2024

2019 Model 3 and 2023 Model Y do not require suspend.

@JakobLichterfeld
Copy link
Collaborator

If the car has been woken up by Tesla to let you know that a new update is available, the car won't go to sleep immediately if polling is active. Instead, it will charge the 12V battery and be awake for about 1 hour. I use TeslaMateTelegramBot, and as soon as I get the message that the update is available, I open TeslaMate, hit try to sleep, and if I'm fast enough, the car will fall asleep in the next few minutes. That being said, there are cases where polling prevents the car from going to sleep and causes vampire drain as mentioned before.

@pkuehnel
Copy link
Author

pkuehnel commented Feb 4, 2024

Why is just letting the user decide with not using the hardcoded values not an option? Everyone who is not interested can let the defaults, everyone who prefers less vampire drain can use zero minutes instead of the hard coded values, everyone who is interested in safely not loosing any data can insert a high value and in rare occasions there is somewhat more vampire drain.

When switching off the streaming API there is also no hard coded value and the user can decide. Why removing that option when using the Streaming API?

@micves
Copy link
Contributor

micves commented Feb 4, 2024

No: The streaming API only detects drive and charge starts. If you begin your drive in a garage with no internet and polling has just stopped, the next 30 minutes won't be logged. Calling vehicle_data does not only detect the starts of charges/drives but also if the car is charging/driving. So, as soon as you drive out of your garage and the car has an internet connection, logging is started as TeslaMate detects the car is driving.

If I read the code correct, it disagrees with this. Streaming should just as well trigger a drive when suspended as it does online. I also read it as it should also start the drive if the car is already driving:

#### Online
def handle_event(:info, {:stream, %Stream.Data{} = stream_data}, :online, data) do
stale_stream_data? = stale?(stream_data, data.last_response)
case stream_data do
%Stream.Data{} when stale_stream_data? ->
Logger.warning("Received stale stream data: #{inspect(stream_data)}", car_id: data.car.id)
:keep_state_and_data
%Stream.Data{shift_state: shift_state} when shift_state in ~w(D N R) ->
Logger.info("Start of drive initiated by: #{inspect(stream_data)}")
%{elevation: elevation} = position = create_position(stream_data, data)
{drive, data} = start_drive(position, data)
vehicle = merge(data.last_response, stream_data, time: true)
{:next_state, {:driving, :available, drive},
%Data{data | last_response: vehicle, elevation: elevation},
[broadcast_summary(), schedule_fetch(0, data)]}

#### Suspended
def handle_event(:info, {:stream, %Stream.Data{} = stream_data}, {:suspended, prev_state}, data) do
stale_stream_data? = stale?(stream_data, data.last_response)
case stream_data do
%Stream.Data{} when stale_stream_data? ->
Logger.warning("Received stale stream data: #{inspect(stream_data)}", car_id: data.car.id)
:keep_state_and_data
%Stream.Data{shift_state: shift_state} when shift_state in ~w(D N R) ->
Logger.info("Start of drive initiated by: #{inspect(stream_data)}")
%{elevation: elevation} = position = create_position(stream_data, data)
{drive, data} = start_drive(position, data)
vehicle = merge(data.last_response, stream_data, time: true)
{:next_state, {:driving, :available, drive},
%Data{data | last_response: vehicle, elevation: elevation},
[broadcast_summary(), schedule_fetch(0, data)]}

I don't know if something is buggy in this or behave weird with bad internet.
Again, I would think polling would have failed just as well as streaming.

Do you have the log from such an incident?

I'm actually not against having the options when streaming is selected.
I just think that new fields should be added with own defaults:

field :suspend_min, :integer, default: 21
field :suspend_after_idle_min, :integer, default: 15

That way you can switch streaming on and off without messing with the stored values.

@pkuehnel
Copy link
Author

pkuehnel commented Feb 4, 2024

A log is on my initial comment but here another log starting a little earlier:

024-01-27 15:34:52.009 [info] GET /
2024-01-27 15:34:52.028 [info] Sent 200 in 15ms
2024-01-27 15:35:47.181 [warning] Too many disconnects from streaming API
2024-01-27 15:35:47.189 car_id=1 [info] Creating new connection … 
2024-01-27 15:35:47.191 car_id=1 [info] Disconnecting ...
2024-01-27 15:35:47.206 car_id=1 [info] Connecting ...
2024-01-27 15:35:52.017 [info] GET /
2024-01-27 15:35:52.021 [info] Sent 200 in 4ms
2024-01-27 15:36:52.005 [info] GET /
2024-01-27 15:36:52.021 [info] Sent 200 in 13ms
2024-01-27 15:37:52.007 [info] GET /
2024-01-27 15:37:52.025 [info] Sent 200 in 12ms
2024-01-27 15:38:52.016 [info] GET /
2024-01-27 15:38:52.034 [info] Sent 200 in 13ms
2024-01-27 15:39:52.012 [info] GET /
2024-01-27 15:39:52.043 [info] Sent 200 in 24ms
2024-01-27 15:40:52.010 [info] GET /
2024-01-27 15:40:52.028 [info] Sent 200 in 13ms
2024-01-27 15:41:52.020 [info] GET /
2024-01-27 15:41:52.058 [info] Sent 200 in 26ms
2024-01-27 15:42:10.359 [warning] Too many disconnects from streaming API
2024-01-27 15:42:10.360 car_id=1 [info] Creating new connection … 
2024-01-27 15:42:10.360 car_id=1 [info] Disconnecting ...
2024-01-27 15:42:10.365 car_id=1 [info] Connecting ...
2024-01-27 15:42:52.015 [info] GET /
2024-01-27 15:42:52.024 [info] Sent 200 in 8ms
2024-01-27 15:43:52.022 [info] GET /
2024-01-27 15:43:52.060 [info] Sent 200 in 28ms
2024-01-27 15:44:52.017 [info] GET /
2024-01-27 15:44:52.044 [info] Sent 200 in 20ms
2024-01-27 15:45:52.017 [info] GET /
2024-01-27 15:45:52.046 [info] Sent 200 in 18ms
2024-01-27 15:46:52.018 [info] GET /
2024-01-27 15:46:52.039 [info] Sent 200 in 14ms
2024-01-27 15:47:52.015 [info] GET /
2024-01-27 15:47:52.030 [info] Sent 200 in 12ms
2024-01-27 15:48:34.604 [warning] Too many disconnects from streaming API
2024-01-27 15:48:34.610 car_id=1 [info] Creating new connection … 
2024-01-27 15:48:34.611 car_id=1 [info] Disconnecting ...
2024-01-27 15:48:34.620 car_id=1 [info] Connecting ...
2024-01-27 15:48:52.013 [info] GET /
2024-01-27 15:48:52.017 [info] Sent 200 in 4ms
2024-01-27 15:49:45.239 [info] Refreshing access token ...
2024-01-27 15:49:45.903 [info] POST https://auth.tesla.com/oauth2/v3/token -> 200 (651.153 ms)
2024-01-27 15:49:45.931 [info] Scheduling token refresh in 6 h
2024-01-27 15:49:52.014 [info] GET /
2024-01-27 15:49:52.017 [info] Sent 200 in 3ms
2024-01-27 15:50:52.016 [info] GET /
2024-01-27 15:50:52.041 [info] Sent 200 in 20ms
2024-01-27 15:51:34.401 car_id=1 [info] Vehicle is still online. Falling asleep for: 33 min
2024-01-27 15:51:34.409 [info] Start of drive initiated by: %TeslaApi.Vehicle.State.Drive{gps_as_of: 1706370691, heading: 354, latitude: XX.984552, longitude: XX.980987, native_latitude: XX.984552, native_location_supported: 1, native_longitude: XX.980987, native_type: "wgs", power: 11, shift_state: "D", speed: 5, timestamp: 1706370694311}
2024-01-27 15:51:34.409 car_id=1 [info] Driving / Start
2024-01-27 15:51:52.005 [info] GET /
2024-01-27 15:51:52.017 [info] Sent 200 in 12ms
2024-01-27 15:52:39.231 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (240.337 ms)
2024-01-27 15:52:39.706 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (454.999 ms)
2024-01-27 15:52:39.723 [info] End of drive initiated by: %TeslaApi.Vehicle.State.Drive{gps_as_of: 1706370757, heading: 348, latitude: XX.985008, longitude: XX.979491, native_latitude: XX.985008, native_location_supported: 1, native_longitude: XX.979491, native_type: "wgs", power: 4, shift_state: "P", speed: 0, timestamp: 1706370758886}
2024-01-27 15:52:39.723 car_id=1 [info] Driving / Ended / 0 km – 1 min
2024-01-27 15:52:39.723 car_id=1 [info] Start / :online

Note: The actual drive started at 15:37 and was 16km long.

@micves
Copy link
Contributor

micves commented Feb 4, 2024

Yeah, I can see that is a problem.

Is all the 'GET /' because you watch your teslamate webpage to monitor what is going on?

Do you have a test where you on teslamate webpage click resume? Does it catch the drive right away after resume?

Streaming and polling are on different sites, so one could fail while the other doesn't

streaming:

_global -> "wss://streaming.vn.teslamotors.com/streaming/"

normal:

_global -> "https://owner-api.teslamotors.com"

Available timings when streaming api is on could help some.
But on top of that maybe a more general fix could be to cancel suspended logging whenever stream has too many disconnects?
My guess it would be very rare that could cause vampire drain.

@pkuehnel
Copy link
Author

pkuehnel commented Feb 4, 2024

Is all the 'GET /' because you watch your teslamate webpage to monitor what is going on?

No idea why these are there but very likely something from my side.

Do you have a test where you on teslamate webpage click resume? Does it catch the drive right away after resume?

Yes it starts immediately when clicking on resume. Here is a log:

2024-01-30 15:31:28.080 car_id=4 [info] Resuming logging
2024-01-30 15:31:29.358 [info] Start of drive initiated by: %TeslaApi.Vehicle.State.Drive{gps_as_of: 1706628687, heading: 275, latitude: XX.853606, longitude: XX.962288, native_latitude: XX.853606, native_location_supported: 1, native_longitude: XX.962288, native_type: "wgs", power: 1, shift_state: "D", speed: 0, timestamp: 1706628688692}
2024-01-30 15:31:29.358 car_id=4 [info] Driving / Start

@Mystere98
Copy link

Hi, just adding my 2 cents,

I own a Tesla model 3 2024 with SW : 2023.44.30.9

The car is plugged on the wall but the Wallbox is offline. ( So not charging)
I did wake up the car using the Official app and then run the following script.

while true; do curl --header 'Content-Type: application/json' --header "Authorization: Bearer xxx" 'https://owner-api.teslamotors.com/api/1/vehicles/xxx/vehicle_data' -s | jq '.response.state + " : " + (.response.vehicle_state.timestamp|tostring)'; sleep 30; done

I did this multiple time, and every time, after 12 min my car go in the arms of Morpheus. And then i get those error from the API : {"response":null,"error":"vehicle unavailable: vehicle is offline or asleep","error_description":""}

So indeed /vehicle_data don't keep the car awake.

@brianmay
Copy link
Collaborator

brianmay commented Feb 5, 2024

I believe these lines:

2024-01-27 15:51:52.005 [info] GET /
2024-01-27 15:51:52.017 [info] Sent 200 in 12ms

Involve the internal web server inside TeslaMate, we don't need to worry about them here.

@brianmay
Copy link
Collaborator

brianmay commented Feb 5, 2024

Why is just letting the user decide with not using the hardcoded values not an option? Everyone who is not interested can let the defaults, everyone who prefers less vampire drain can use zero minutes instead of the hard coded values, everyone who is interested in safely not loosing any data can insert a high value and in rare occasions there is somewhat more vampire drain.

Somebody needs to come up with a pull request, and then we need to test it to ensure it really does what it is suppose to on different cars.

And there has been a suggestion how to do this already, #3639 (comment).

I note this was given a thumbs down, but unfortunately I am not sure why this was given a thumbs down.

In short though, we would need:

  • Update the UI so that it always shows those two time fields (suspend_after_idle_min, suspend_min) - even if streaming is enabled. Maybe even update the help information so it is more clear what they do (I personally found these fields to be confusing until I looked at the source code).

  • Maybe reset these fields (suspend_after_idle_min, suspend_min) to some default if the streamable value is changed.

  • Update the logic to always use values from the database, even if streamable is enabled. Note: Might make sense to continue hard coding value of i, not sure here.

This would mean we have less hard coded values in the code, which is probably a good thing. Even if we find out we do need the suspended logging.

On the other hand, it means there are more variables to consider if somebody were to complain "it is not working for me" without giving any details.

@JakobLichterfeld
Copy link
Collaborator

JakobLichterfeld commented Feb 6, 2024

I wrote about my concerns above.
If we can avoid additional settings, this would be the preferred solution. Why? In the beginning(edit: old API and custom user settings), the majority of bugs/user errors were due to sleep behavior, now (edit: with streaming API and current solution) it is only a problem in very rare cases. Adding settings without understanding the implications will always get a thumbs down from me ;-)
In addition, I have already outlined several situations where the proposed continuous polling results in unwanted behavior.

To sum up, I would highly appreciate @adriankumpf background view on streaming API polling sleep things, before moving on.

@pkuehnel
Copy link
Author

pkuehnel commented Feb 6, 2024

now it is only a problem in very rare cases

Because of Tesla's update in the cars resulting in no matter what TeslaMate does, the car falls asleep anyway (in most cases).

@pkuehnel
Copy link
Author

pkuehnel commented Feb 6, 2024

Well as @JakobLichterfeld shows his love to hard coded values by voting down every single comment against hard coded values, I just stick to my powershell script. Looks like there won't be a solution in the official release.

@pkuehnel pkuehnel closed this as not planned Won't fix, can't repro, duplicate, stale Feb 6, 2024
@JakobLichterfeld
Copy link
Collaborator

JakobLichterfeld commented Feb 6, 2024

Well as @JakobLichterfeld shows his love to hard coded values by voting down every single comment against hard coded values, I just stick to my powershell script. Looks like there won't be a solution in the official release.

Thanks for your misinterpretation. I already explained it above:

Adding settings without understanding the implications will always get a thumbs down from me ;-)

We do need a solution for all the users, who pulled the docker image nearly 22 Million times.

From your single point of measurement, we can expect to drop the hard coded values for streaming. Reality has shown that we need to look much further, which is explained above in several ways.

Would like to keep this open for further exchange and perspective from Adrian and others.

@JakobLichterfeld JakobLichterfeld added note:discussion Details or approval are up for discussion and removed closed:invalid This doesn't seem right labels Feb 6, 2024
@brianmay
Copy link
Collaborator

brianmay commented Feb 7, 2024

I have mixed feeling here. Yes, support is an issue. And yes, people will want to try this out in weird and wonderful ways that we never even considered.

If somebody sets the value to 99999 and finds it isn't working for them, they are going to ask for support. And they probably have won't mention that they did set the value to 99999. We will have remember to ask.

What happens if you set the value to 0? What happens if you set the value to -1? Maybe it is OK, but have we really considered such cases?

Will this will increase polling of the Tesla APIs? Or allow reduction of the polling time? As mentioned above this makes me nervous. We don't want to give Tesla any additional reason to block us.

But it is kind of hard to argue the merits of a particular approach when we don't have a pull request to evaluate...

I think we could use the existing values already in the database. We don't need to add more settings that don't already exist.

Also maybe we could clarify the labels "Idle Time Before Trying to Sleep" and "Time to Try Sleeping". They look the same. I think I know what they mean, and I find these labels confusing. Maybe the second one should be "Maximum time to try sleeping", because if I am reading this correctly we poll the car after this time even in suspend mode.

@LelandSindt
Copy link
Contributor

For context here is a thread with (I think) good information about how teslamate polls/streams and when. #1288

Opinion: Whenever possible I think that reasonable defaults should be set but overrides be available. In this case make it clear that these are experimental and/or un-supported.

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 note:discussion Details or approval are up for discussion note:more information needed The reporter has to provide more information
Projects
None yet
Development

No branches or pull requests

8 participants