Very low update rate on some drives

[Kevga]

Describe the bug
On some drives using the streaming API, the update rate of TeslaMate drops down to around one update every ~15 seconds. I only noticed this after I started using the data published via MQTT to automate garage door opening/closing, however the issue is also apparent in the Grafana dashboard for affected drives.

Expected behavior
I expect around 2 updates per second using the streaming API. Actual result is around 4 updates per minute on some drives.

How to reproduce it (as minimally and precisely as possible):
I have not had it happen often enough to figure out when or why exactly it happens, but I feel like it usually happens on the return trip after the car was parked for a while with sentry mode activated. Could be a coincidence though.

Relevant entries from the logs
Log entry of one affected trip. Included are the drive to a store, a period with sentry mode active, followed by the drive back home. The drive back home was affected by reduced update frequency.

teslamate_1  | 10:38:12.303 [info] PUT /api/car/1/logging/resume
teslamate_1  | 10:38:12.308 car_id=1 [info] Expecting imminent wakeup. Increasing polling frequency ...
teslamate_1  | 10:38:12.309 [info] Sent 204 in 4ms
teslamate_1  | 10:38:53.042 car_id=1 [info] Start / :online
teslamate_1  | 10:38:53.085 car_id=1 [info] Connecting ...
teslamate_1  | 10:39:04.110 car_id=1 [info] Driving / Start
teslamate_1  | 10:46:23.001 car_id=1 [info] Driving / Ended / 4 km – 7 min
teslamate_1  | 10:46:23.001 car_id=1 [info] Start / :online
teslamate_1  | 10:49:07.822 [info] GET /
teslamate_1  | 10:49:07.845 [info] Sent 200 in 22ms
teslamate_1  | 10:55:36.785 [error] TeslaApi.Error / 408 – %{
teslamate_1  |   "error" => "vehicle unavailable: {:error=>\"{\\\"error\\\": \\\"timeout\\\"}\"}",
teslamate_1  |   "error_description" => "",
teslamate_1  |   "response" => nil
teslamate_1  | }
teslamate_1  | 10:55:37.903 car_id=1 [warn] Discarded incomplete fetch result: %TeslaApi.Vehicle{api_version: 10, backseat_token: nil, backseat_token_updated_at: nil, calendar_enabled: true, charge_state: nil, climate_state: nil, color: nil, display_name: "<redacted>", drive_state: nil, gui_settings: nil, id: <redacted>, in_service: false, option_codes: ["<redacted>", ...], state: "online", tokens: ["<redacted>", "<redacted>"], vehicle_config: nil, vehicle_id: <redacted>, vehicle_state: nil, vin: "<redacted>"}
teslamate_1  | 10:55:58.297 [error] TeslaApi.Error / 408 – %{
teslamate_1  |   "error" => "vehicle unavailable: {:error=>\"{\\\"error\\\": \\\"timeout\\\"}\"}",
teslamate_1  |   "error_description" => "",
teslamate_1  |   "response" => nil
teslamate_1  | }
teslamate_1  | 10:55:59.448 car_id=1 [warn] Discarded incomplete fetch result: %TeslaApi.Vehicle{api_version: 10, backseat_token: nil, backseat_token_updated_at: nil, calendar_enabled: true, charge_state: nil, climate_state: nil, color: nil, display_name: "<redacted>", drive_state: nil, gui_settings: nil, id: <redacted>, in_service: false, option_codes: ["<redacted>", ...], state: "online", tokens: ["<redacted>", "<redacted>"], vehicle_config: nil, vehicle_id: <redacted>, vehicle_state: nil, vin: "<redacted>"}
teslamate_1  | 10:56:19.831 [error] TeslaApi.Error / 408 – %{
teslamate_1  |   "error" => "vehicle unavailable: {:error=>\"{\\\"error\\\": \\\"timeout\\\"}\"}",
teslamate_1  |   "error_description" => "",
teslamate_1  |   "response" => nil
teslamate_1  | }
teslamate_1  | 10:56:20.969 car_id=1 [warn] Discarded incomplete fetch result: %TeslaApi.Vehicle{api_version: 10, backseat_token: nil, backseat_token_updated_at: nil, calendar_enabled: true, charge_state: nil, climate_state: nil, color: nil, display_name: "<redacted>", drive_state: nil, gui_settings: nil, id: <redacted>, in_service: false, option_codes: ["<redacted>", ...], state: "online", tokens: ["<redacted>", "<redacted>"], vehicle_config: nil, vehicle_id: <redacted>, vehicle_state: nil, vin: "<redacted>"}
teslamate_1  | 10:56:41.376 [error] TeslaApi.Error / 408 – %{
teslamate_1  |   "error" => "vehicle unavailable: {:error=>\"{\\\"error\\\": \\\"timeout\\\"}\"}",
teslamate_1  |   "error_description" => "",
teslamate_1  |   "response" => nil
teslamate_1  | }
teslamate_1  | 10:56:42.517 car_id=1 [warn] Discarded incomplete fetch result: %TeslaApi.Vehicle{api_version: 10, backseat_token: nil, backseat_token_updated_at: nil, calendar_enabled: true, charge_state: nil, climate_state: nil, color: nil, display_name: "<redacted>", drive_state: nil, gui_settings: nil, id: <redacted>, in_service: false, option_codes: ["<redacted>", ...], state: "online", tokens: ["<redacted>", "<redacted>"], vehicle_config: nil, vehicle_id: <redacted>, vehicle_state: nil, vin: "<redacted>"}
teslamate_1  | 11:01:14.754 [error] TeslaApi.Error / 408 – %{
teslamate_1  |   "error" => "vehicle unavailable: {:error=>\"{\\\"error\\\": \\\"timeout\\\"}\"}",
teslamate_1  |   "error_description" => "",
teslamate_1  |   "response" => nil
teslamate_1  | }
teslamate_1  | 11:01:15.856 car_id=1 [warn] Discarded incomplete fetch result: %TeslaApi.Vehicle{api_version: 10, backseat_token: nil, backseat_token_updated_at: nil, calendar_enabled: true, charge_state: nil, climate_state: nil, color: nil, display_name: "<redacted>", drive_state: nil, gui_settings: nil, id: <redacted>, in_service: false, option_codes: ["<redacted>", ...], state: "online", tokens: ["<redacted>", "<redacted>"], vehicle_config: nil, vehicle_id: <redacted>, vehicle_state: nil, vin: "<redacted>"}
teslamate_1  | 11:01:36.348 [error] TeslaApi.Error / 408 – %{
teslamate_1  |   "error" => "vehicle unavailable: {:error=>\"{\\\"error\\\": \\\"timeout\\\"}\"}",
teslamate_1  |   "error_description" => "",
teslamate_1  |   "response" => nil
teslamate_1  | }
teslamate_1  | 11:02:06.349 car_id=1 [error] Error / :timeout
teslamate_1  | 11:05:51.685 [error] TeslaApi.Error / 408 – %{
teslamate_1  |   "error" => "vehicle unavailable: {:error=>\"{\\\"error\\\": \\\"timeout\\\"}\"}",
teslamate_1  |   "error_description" => "",
teslamate_1  |   "response" => nil
teslamate_1  | }
teslamate_1  | 11:05:52.812 car_id=1 [warn] Discarded incomplete fetch result: %TeslaApi.Vehicle{api_version: 10, backseat_token: nil, backseat_token_updated_at: nil, calendar_enabled: true, charge_state: nil, climate_state: nil, color: nil, display_name: "<redacted>", drive_state: nil, gui_settings: nil, id: <redacted>, in_service: false, option_codes: ["<redacted>", ...], state: "online", tokens: ["<redacted>", "<redacted>"], vehicle_config: nil, vehicle_id: <redacted>, vehicle_state: nil, vin: "<redacted>"}
teslamate_1  | 11:06:13.226 [error] TeslaApi.Error / 408 – %{
teslamate_1  |   "error" => "vehicle unavailable: {:error=>\"{\\\"error\\\": \\\"timeout\\\"}\"}",
teslamate_1  |   "error_description" => "",
teslamate_1  |   "response" => nil
teslamate_1  | }
teslamate_1  | 11:06:14.376 car_id=1 [warn] Discarded incomplete fetch result: %TeslaApi.Vehicle{api_version: 10, backseat_token: nil, backseat_token_updated_at: nil, calendar_enabled: true, charge_state: nil, climate_state: nil, color: nil, display_name: "<redacted>", drive_state: nil, gui_settings: nil, id: <redacted>, in_service: false, option_codes: ["<redacted>", ...], state: "online", tokens: ["<redacted>", "<redacted>"], vehicle_config: nil, vehicle_id: <redacted>, vehicle_state: nil, vin: "<redacted>"}
teslamate_1  | 11:06:34.747 [error] TeslaApi.Error / 408 – %{
teslamate_1  |   "error" => "vehicle unavailable: {:error=>\"{\\\"error\\\": \\\"timeout\\\"}\"}",
teslamate_1  |   "error_description" => "",
teslamate_1  |   "response" => nil
teslamate_1  | }
teslamate_1  | 11:06:35.911 car_id=1 [warn] Discarded incomplete fetch result: %TeslaApi.Vehicle{api_version: 10, backseat_token: nil, backseat_token_updated_at: nil, calendar_enabled: true, charge_state: nil, climate_state: nil, color: nil, display_name: "<redacted>", drive_state: nil, gui_settings: nil, id: <redacted>, in_service: false, option_codes: ["<redacted>", ...], state: "online", tokens: ["<redacted>", "<redacted>"], vehicle_config: nil, vehicle_id: <redacted>, vehicle_state: nil, vin: "<redacted>"}
teslamate_1  | 11:26:34.504 [info] GET /
teslamate_1  | 11:26:34.526 [info] Sent 200 in 22ms
teslamate_1  | 11:51:13.488 [info] GET /
teslamate_1  | 11:51:13.512 [info] Sent 200 in 23ms
teslamate_1  | 11:56:23.770 [info] GET /
teslamate_1  | 11:56:23.793 [info] Sent 200 in 22ms
teslamate_1  | 12:10:01.300 car_id=1 [info] Driving / Start
teslamate_1  | 12:17:10.717 [info] PUT /api/car/1/logging/resume
teslamate_1  | 12:17:10.723 [info] Sent 204 in 5ms
teslamate_1  | 12:17:43.178 car_id=1 [info] Driving / Ended / 5 km – 8 min
teslamate_1  | 12:17:43.178 car_id=1 [info] Start / :online
teslamate_1  | 12:18:35.435 [info] PUT /api/car/1/logging/suspend
teslamate_1  | 12:18:37.134 car_id=1 [info] Suspending logging [Triggered manually]
teslamate_1  | 12:18:37.153 [info] Sent 204 in 1717ms

Screenshots
Below are Grafana screenshots of the two drives covered by the log. Please note that the log seems to use UTC while Grafana shows times in UTC+2.

1.: Drive to the store. Normal update frequency.

2.: Drive back home. Similar distance and duration as drive in previous screenshot, but affected by the issue.

Environment

• TeslaMate version: 1.19.4
• Type of installation: Docker
• OS TeslaMate is installed on: Raspbian GNU/Linux 10 (buster)

[Kevga]

I read in a different issue that TeslaMate is polling the API every 15 seconds, even when using the streaming API. So that explains the interval. The question would be, why was the streaming API not used? I see timeout errors while the car was parked, that probably has something to do with it. However, the last error was over an hour before the start of the drive.

Maybe TeslaMate needs a better retry mechanism for connectivity issues with the streaming API? It might also be a good idea to increase the polling frequency in the case that no connection to the streaming API could be established.

[Dulanic]

So streaming api is actually not "polled" so that isn't why. Hence why it is a "streaming" api not a normal polling api. Tesla had some system problems recently that may be the cause? Typically /w streaming I see updates every .5 seconds.

Are you positive you were using steaming? And @adriankumpf maybe should edit out the log comment that it is polling?

[Kevga]

So streaming api is actually not "polled" so that isn't why. Hence why it is a "streaming" api not a normal polling api.

See this comment by @adriankumpf that I referenced previously if you are confused about how the two APIs (streaming-based and polling-based) are used together. What you are seeing in the screenshots is the streaming working correctly in the first one and the streaming not working with very slow polling as a fallback in the second one.

Are you positive you were using steaming? And @adriankumpf maybe should edit out the log comment that it is polling?

The comments in the log about increased polling frequency are correct and should not be removed. I trigger that by calling the /resume endpoint of TeslaMate's API every time the garage is opened, which makes TeslaMate check more often if the car is awake so the logging (via the streaming API) starts immediately when the car is in use.

[MaxG88]

I've had this issue for a few months now.
I've documented one possible way of reproducing it in #838. Does your car perhaps have bad connectivity when this happens?

[Kevga]

I'm not sure but I don't think so. At least the location I mentioned in the issue description has good LTE coverage. It also happens sporadically at other locations, but I can never reliably reproduce the issue anywhere.

It sounds very much like your issue #838 describes the same problem though. I'm tempted to close this one.

[Wesleyl89]

I'm experiencing the same. Sometimes it uses the streaming API and other times an update every 15 secs and keeps doing that for the whole drive. Sometimes it starts the streaming in the middle of a drive as well so I can't really pinpoint the problem.

I only noticed once I was using the MQTT stuff in Home Assistant where I show the elevation. The streaming API updates elevation while the 15sec poll one doesn't update this attribute at all.

[ngardiner]

I recall (but can't find a reference for) a limitation around only one stream being possible at a time, ie if the Tesla app is streaming, it would result in Teslamate not being able to use the Streaming API - anyone else recall this being mentioned? Perhaps try killing the Tesla app on your phone before your drives to see if that could be a reason for this?

[Kevga]

@ngardiner I don't know if this is the right way to test this, but I had my passenger open the Tesla app for me while I was driving. The data in the app seemed to update as usual and looking at Grafana it seems the logging by TeslaMate was not affected by this. Though I don't know if maybe the app was polling instead because TeslaMate had an active streaming connection. I may try waking the car with the app to make sure the app gets the streaming connection before TeslaMate, to see if that changes anything.

In any case, it seems increasing the polling frequency if connecting to the streaming API fails is the way to go.

[tonypilborg]

hmmm - funny. These past few days, the polling frequency has been around 1 sec., not the usual 1/4 second on the streaming api.... Anybody else seeing this change?

[ratza]

I've also seen this happen regularly, including in v1.20.1 and car on v2020.40.9. I'll leave here my observations, maybe it gives ideas.

Two things I noticed:

1. After a normal charging session, all the drives (20+) I checked, start using the Streaming API, either immediately or after a few seconds. (I charge at a public post, so my car is not usually plugged in at home)
2. Any subsequent drives are also reliably recorded using the Streaming API, until the car disconnects from the internet while parked. After that it used to never record through the Streaming API, until I would put the car to charge. Since v2020.40.4, it recovers randomly in a subsequent drive (sometimes several drives, anywhere from 1 hour to several days later). If the 4G connection is restored during the same drive, Streaming API picks it up after a few seconds again.

Interestingly, the car switching between 4G and (really bad) WiFi doesn't influence the subsequent drives rate.

So for me this bug seems to reproduce when:

• I drive into a underground garage with no 4G coverage and park there.
• Reboot the car (after, updates as well)
• I used to have these weird parking spots, where I would leave the car, 200 meters away from where I usually park now, in an open area, it would show full 4G bars, but after the car would go to sleep, it would lose connection for good (only a restart helped, has been fixed since 2020.28 or so).
• Unrelated to the car: when the TeslaMate app gets restarted (because of server updates, etc).

Sentry Mode, simultaneous Tesla app usage or car going to Sleep doesn't seem to influence it in my case.

I live in a metropolitan area, so I assume/experience 4G coverage is very good, however we have a few fairly long tunnels, in which the car reverts to polling for the tunnel portion and after I get out, it goes back to Streaming API. Note that the car doesn't really show any issues while driving in the tunnel - Maps, Spotify work flawlessly.

For some reason, this makes me think the problem is in the way the car communicates to the "mothership" and not related to TeslaMate. The only thing that doesn't check out is why restarting TeslaMate causes it to fail using the Streaming API for a long time.