Missing Start of Drives in Drive Data

[drewpost]

Describe the bug

I am having an issue where, a number of times, the starting time/location for a drive on the drives dashboard is shown as somewhere that was actually in the middle of the drive. I thought it may have been an API/data issue but on TeslaFi it shows complete data for the drive and, also, in my TeslaMate "States" dashboard, it correctly shows me as driving as well.

Expected behavior

The data would be consistent across dashboards. The drives should match the "driving" state and represent when I was actually driving the car.

How to reproduce it (as minimally and precisely as possible):

teslamate_1 | 2021-08-04 16:36:39.728 [warn] TeslaApi.Error / %{"error" => "https://mothership-api.vn.teslamotors.com:443/vehicles/173037340341 => operation_timedout with 10s timeout", "error_description" => "", "response" => nil} teslamate_1 | 2021-08-04 16:36:39.728 car_id=4 [error] Error / :unknown teslamate_1 | 2021-08-04 16:40:26.730 [warn] GET https://owner-api.teslamotors.com/api/1/vehicles/191678483224/vehicle_data -> 504 (10210.953 ms) teslamate_1 | 2021-08-04 16:40:26.730 car_id=4 [error] Error / :timeout teslamate_1 | 2021-08-04 16:49:22.084 [warn] GET https://owner-api.teslamotors.com/api/1/vehicles/191678483224/vehicle_data -> 504 (10844.227 ms) teslamate_1 | 2021-08-04 16:49:22.084 car_id=4 [error] Error / :timeout teslamate_1 | 2021-08-04 16:55:59.532 [error] ** (RuntimeError) Client Error: %{"error_type" => "client_error", "msg_type" => "data:error", "tag" => "173037340341", "value" => "owner_api error: Post \"https://ownerapi-internal.vn.teslamotors.com:443/authenticate/vehicles/173037340341?operation=streaming_authenticate\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)"} teslamate_1 | (teslamate 1.23.7) lib/tesla_api/stream.ex:150: TeslaApi.Stream.handle_frame/2 teslamate_1 | (websockex 0.4.3) lib/websockex.ex:1113: WebSockex.try_callback/3 teslamate_1 | (websockex 0.4.3) lib/websockex.ex:797: WebSockex.common_handle/4 teslamate_1 | (stdlib 3.15.1) proc_lib.erl:226: :proc_lib.init_p_do_apply/3 teslamate_1 | teslamate_1 | 2021-08-04 16:56:06.765 car_id=4 [info] Start / :online teslamate_1 | 2021-08-04 16:56:06.794 car_id=4 [info] Connecting ... teslamate_1 | 2021-08-04 16:56:06.798 car_id=4 [info] Driving / Start teslamate_1 | 2021-08-04 17:03:07.865 car_id=6 [info] Start / :online teslamate_1 | 2021-08-04 17:03:07.898 car_id=6 [info] Connecting ... teslamate_1 | 2021-08-04 17:06:26.459 car_id=6 [info] Suspending logging teslamate_1 | 2021-08-04 17:10:09.418 car_id=4 [info] Fetch already in progress ... teslamate_1 | 2021-08-04 17:10:10.415 car_id=4 [info] Fetch already in progress ... teslamate_1 | 2021-08-04 17:10:11.435 car_id=4 [info] Fetch already in progress ... teslamate_1 | 2021-08-04 17:10:11.615 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (127.277 ms) teslamate_1 | 2021-08-04 17:10:12.074 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (449.581 ms) teslamate_1 | 2021-08-04 17:10:12.107 car_id=4 [info] Driving / Ended / 12 km – 14 min teslamate_1 | 2021-08-04 17:10:12.108 car_id=4 [info] Start / :online teslamate_1 | 2021-08-04 17:16:31.467 car_id=6 [info] Fetching vehicle state ... teslamate_1 | 2021-08-04 17:16:32.462 car_id=6 [info] Start / :asleep teslamate_1 | 2021-08-04 17:16:32.470 car_id=6 [info] Disconnecting ... teslamate_1 | 2021-08-04 17:45:55.041 car_id=6 [info] Start / :online teslamate_1 | 2021-08-04 17:45:55.075 car_id=6 [info] Connecting ... teslamate_1 | 2021-08-04 17:47:12.420 car_id=4 [info] Driving / Start teslamate_1 | 2021-08-04 17:48:07.729 [warn] GET https://owner-api.teslamotors.com/api/1/vehicles/222576494051/vehicle_data -> 504 (10162.074 ms) teslamate_1 | 2021-08-04 17:48:07.729 car_id=6 [error] Error / :timeout teslamate_1 | 2021-08-04 17:48:59.749 car_id=6 [info] Suspending logging teslamate_1 | 2021-08-04 17:56:46.026 [warn] GET https://owner-api.teslamotors.com/api/1/vehicles/191678483224/vehicle_data -> 500 (1592.713 ms) teslamate_1 | 2021-08-04 17:56:46.027 [warn] TeslaApi.Error / upstream internal error teslamate_1 | 2021-08-04 17:56:46.027 car_id=4 [error] Error / :unknown teslamate_1 | 2021-08-04 17:59:41.128 car_id=6 [info] Fetching vehicle state ... teslamate_1 | 2021-08-04 17:59:41.363 car_id=6 [info] Start / :asleep teslamate_1 | 2021-08-04 17:59:41.379 car_id=6 [info] Disconnecting ... teslamate_1 | 2021-08-04 18:16:22.449 [warn] GET https://owner-api.teslamotors.com/api/1/vehicles/191678483224/vehicle_data -> 504 (10632.843 ms) teslamate_1 | 2021-08-04 18:16:22.449 car_id=4 [error] Error / :timeout teslamate_1 | 2021-08-04 18:17:40.194 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/191678483224/vehicle_data -> 408 (9250.499 ms) teslamate_1 | 2021-08-04 18:17:40.396 car_id=4 [warn] Discarded incomplete fetch result teslamate_1 | 2021-08-04 18:28:47.597 car_id=6 [info] Start / :online teslamate_1 | 2021-08-04 18:28:47.628 car_id=6 [info] Connecting ... teslamate_1 | 2021-08-04 18:31:06.363 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/222576494051/vehicle_data -> 408 (9215.719 ms)

Screenshots

These drives should be the same duration/distance as they were from the same point and back.

This is the states dashboard correctly showing the state as driving:

and TeslaFi showing the whole drive

Data

Environment

• TeslaMate version: 1.23.7
• Type of installation: Docker
• OS TeslaMate is installed on: Raspbian GNU/Linux 10 (buster)
• User OS & Browser: macOS Safari and Chrome
• Others:

[dyxyl]

It looks like TeslaMate is getting errors when trying to connect to the Tesla servers. Do you have the logs going back to 2021-08-04 16:00? The time in the log is in UTC, so the 17:07 wall clock start time will be 16:07 in the log but your log starts at 16:36.

[brianmay]

Sometimes Tesla's can be slow to connect to the mobile network at the start of the drive. I have been told this is a known issue. If this is the problem here, nothing Teslamate can do to solve this issue unfortunately.

It could also be because Teslamate is slow to pick up on the state change of the car which is connected, which is a bit more complicated.

I have seen both cases.

[VenomrushCT]

I can confirm i have the same issue since upgrading to 2021.12.25.7 Did not have this ever since March this year, only notices it this week.

Today before leaving the house I quickly went to Teslamate on my phone just to check the status is current before driving off. It did log the start time (13:17) but somehow created another drive (13:29) in the middle of the trip.

[johnpane]

This past weekend, I drove from near Pittsburgh, PA to Erie, PA and back -- about 113 miles each way. The drive to Erie was captured perfectly. The drive back was not. The overview screen shows the full drive timespan, but only the last 11 minutes was captured in Drives. There is strong LTE coverage along the whole route.

[leewillis77]

I saw this on a trip this weekend just gone. In my case, I can rule out slowness of the car to wake up. Here's the rough events:

• 11:17am - start car charging, so car powered up with good data signal, and WiFi
• 4:13pm - 4:17pm - short journey from 'A' to 'B' - captured as a Drive, and in States report. I parked, but driver never left the car.
• 4:21pm - 6:17pm - main journey from 'B' to 'C'

The main journey is correctly reported in the "States" report and Timeline as "Driving". However, while the 4.13pm drive is captured, the 4:21pm journey is only captured as a "Drive" from 5:19pm, with a start location of "Z" [where the car was at 5.19], instead of "B"

"States"

"Drives"

"Timeline"

[leewillis77]

Here's the logs. The time period in the logs includes 2 vehicles (IDs 2 and 3). We're interested in car_id 3 (EID-3 / VID-3), but I've left the entries relating to car id 2 on the off-chance they're related.

teslamate_1  | 2021-08-14 15:21:01.988 car_id=3 [info] Driving / Start
teslamate_1  | 2021-08-14 15:21:08.454 car_id=3 [info] Fetch already in progress ...
teslamate_1  | 2021-08-14 15:21:17.264 car_id=3 [info] Driving / Ended / 0 km – 0 min
teslamate_1  | 2021-08-14 15:21:17.264 car_id=3 [info] Start / :online
teslamate_1  | 2021-08-14 15:21:17.279 car_id=3 [info] Driving / Start
teslamate_1  | 2021-08-14 15:23:29.966 [warn] GET https://owner-api.teslamotors.com/api/1/vehicles/EID-2/vehicle_data -> 504 (10218.596 ms)
teslamate_1  | 2021-08-14 15:23:29.967 car_id=2 [error] Error / :timeout
teslamate_1  | 2021-08-14 15:23:54.218 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/EID-2/vehicle_data -> 408 (9250.228 ms)
teslamate_1  | 2021-08-14 15:23:54.474 car_id=2 [warn] Discarded incomplete fetch result
teslamate_1  | 2021-08-14 15:47:11.885 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/EID-2/vehicle_data -> 408 (15046.686 ms)
teslamate_1  | 2021-08-14 15:47:11.885 [warn] TeslaApi.Error / %{"error" => "https://mothership-api.vn.teslamotors.com:443/vehicles/VID-2 => operation_timedout with 10s timeout", "error_description" => "", "response" => nil}
teslamate_1  | 2021-08-14 15:47:11.886 car_id=2 [error] Error / :unknown
teslamate_1  | 2021-08-14 15:47:32.829 [warn] GET https://owner-api.teslamotors.com/api/1/vehicles/EID-3/vehicle_data -> 503 (416.813 ms)
teslamate_1  | 2021-08-14 15:47:32.829 [warn] TeslaApi.Error / "upstream connect error or disconnect/reset before headers. reset reason: connection failure"
teslamate_1  | 2021-08-14 15:47:32.829 car_id=3 [error] Error / :unknown
teslamate_1  | 2021-08-14 16:04:15.189 [warn] GET https://owner-api.teslamotors.com/api/1/vehicles/EID-3/vehicle_data -> 503 (412.127 ms)
teslamate_1  | 2021-08-14 16:04:15.190 [warn] TeslaApi.Error / "upstream connect error or disconnect/reset before headers. reset reason: connection failure"
teslamate_1  | 2021-08-14 16:04:15.190 car_id=3 [error] Error / :unknown
teslamate_1  | 2021-08-14 16:05:38.622 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/EID-2/vehicle_data -> 408 (12609.687 ms)
teslamate_1  | 2021-08-14 16:05:38.622 [warn] TeslaApi.Error / %{"error" => "https://mothership-api.vn.teslamotors.com:443/vehicles/VID-2 => operation_timedout with 10s timeout", "error_description" => "", "response" => nil}
teslamate_1  | 2021-08-14 16:05:38.623 car_id=2 [error] Error / :unknown
teslamate_1  | 2021-08-14 16:19:45.249 [error] ** (RuntimeError) Client Error: %{"error_type" => "client_error", "msg_type" => "data:error", "tag" => "VID-3", "value" => "owner_api error: `Post \"https://ownerapi-internal.vn.teslamotors.com:443/authenticate/vehicles/VID-3?operation=streaming_authenticate\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)`"}
teslamate_1  |     (teslamate 1.23.7) lib/tesla_api/stream.ex:150: TeslaApi.Stream.handle_frame/2
teslamate_1  |     (websockex 0.4.3) lib/websockex.ex:1113: WebSockex.try_callback/3
teslamate_1  |     (websockex 0.4.3) lib/websockex.ex:797: WebSockex.common_handle/4
teslamate_1  |     (stdlib 3.15.1) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
teslamate_1  |
teslamate_1  | 2021-08-14 16:19:55.775 car_id=3 [info] Start / :online
teslamate_1  | 2021-08-14 16:19:55.803 car_id=3 [info] Connecting ...
teslamate_1  | 2021-08-14 16:19:55.806 car_id=3 [info] Driving / Start

From those, it appears that Teslamate knows the car started driving at 2021-08-14 15:21:17.279. The point at which the drive starts being logged coincides with the error thrown at 2021-08-14 16:19:45.249.

[dyxyl]

@leewillis77 The errors were all timeouts when TeslaMate tried to connect to the Tesla servers, so they were probably overloaded.

[VenomrushCT]

@leewillis77 The errors were all timeouts when TeslaMate tried to connect to the Tesla servers, so they were probably overloaded.

Can we handle this timeout exception better? What challenges/restrictions are we facing?

As more vehicles going online with TeslaMate, Tesla servers will become overloaded more often with more frequent requests

[leewillis77]

@dyxyl Hmm. There are no timeout errors logged for the relevant car (id 3) at the time the drive started (15:21 in the logs). The errors at 15:23 relate to a different vehicle. The first error logged for car ID 3 is 15:47 by which time I was already over 20 minutes into the drive.

[dyxyl]

Hopefully the fix for "owner_api error" in #1848 (6c19a7b8a712a2b6bc091c7db51ad763b5bd337f) in v1.24.0 will also fix many of these reports.

[BabyYeggie]

It looks like I'm getting DB timeouts. While the drives have no data, charges have detailed data, so the data stream is quite odd...

teslamate | 2021-09-01 08:48:54.311 car_id=1 [warn] Discarded incomplete fetch result teslamate | 2021-09-01 08:49:13.372 car_id=1 [info] Suspending logging teslamate | 2021-09-01 08:54:39.454 car_id=1 [info] Fetching vehicle state ... teslamate | 2021-09-01 08:54:40.997 car_id=1 [info] Start / :asleep teslamate | 2021-09-01 08:54:43.769 car_id=1 [info] Disconnecting ... teslamate | 2021-09-01 12:24:38.595 car_id=1 [info] Start / :online teslamate | 2021-09-01 12:24:43.034 car_id=1 [info] Connecting ... teslamate | 2021-09-01 12:24:51.210 car_id=1 [info] Driving / Start teslamate | 2021-09-01 12:27:54.335 [error] Postgrex.Protocol (#PID<0.2287.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.11294.1> timed out because it queued and checked out the connection for longer than 60000ms teslamate | teslamate | #PID<0.11294.1> was at location: teslamate | teslamate | :prim_inet.recv0/3 teslamate | (postgrex 0.15.10) lib/postgrex/protocol.ex:2976: Postgrex.Protocol.msg_recv/4 teslamate | (postgrex 0.15.10) lib/postgrex/protocol.ex:2022: Postgrex.Protocol.recv_bind/3 teslamate | (postgrex 0.15.10) lib/postgrex/protocol.ex:1914: Postgrex.Protocol.bind_execute/4 teslamate | (db_connection 2.4.0) lib/db_connection/holder.ex:325: DBConnection.Holder.holder_apply/4 teslamate | (db_connection 2.4.0) lib/db_connection.ex:1314: DBConnection.run_execute/5 teslamate | (db_connection 2.4.0) lib/db_connection.ex:631: DBConnection.execute/4 teslamate | (ecto_sql 3.7.0) lib/ecto/adapters/postgres/connection.ex:80: Ecto.Adapters.Postgres.Connection.execute/4 teslamate | teslamate | 2021-09-01 12:27:54.904 [error] GenStateMachine :"1" terminating teslamate | ** (DBConnection.ConnectionError) tcp recv: closed (the connection was closed by the pool, possibly due to a timeout or because the pool has been terminated) teslamate | (ecto_sql 3.7.0) lib/ecto/adapters/sql.ex:756: Ecto.Adapters.SQL.raise_sql_call_error/1 teslamate | (ecto_sql 3.7.0) lib/ecto/adapters/sql.ex:689: Ecto.Adapters.SQL.execute/5 teslamate | (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4 teslamate | (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3 teslamate | (ecto 3.7.1) lib/ecto/repo/queryable.ex:146: Ecto.Repo.Queryable.one/3 teslamate | (teslamate 1.24.0) lib/teslamate/log.ex:292: TeslaMate.Log.close_drive/2 teslamate | (teslamate 1.24.0) lib/teslamate/vehicles/vehicle.ex:985: anonymous fn/3 in TeslaMate.Vehicles.Vehicle.handle_event/4 teslamate | (ecto_sql 3.7.0) lib/ecto/adapters/sql.ex:1013: anonymous fn/3 in Ecto.Adapters.SQL.checkout_or_transaction/4 teslamate | 2021-09-01 12:27:58.837 car_id=1 [info] Start / :online

[brianmay]

@BabyYeggie I believe that error typically means that we held a database transaction open for too long. At least that was the code when I had this happen in my (unrelated) project. No idea why that might be happening here. Might be best to open up a new bug report, I suspect it isn't related to this one.

[aradoorolesen]

Two days ago I installed Teslamate for the first time to evaluate it for replacing Teslafi. After importing a years worth of data from Teslafi, I noticed the about half of my drives from home was missing the start. The source data from Teslafi is missing the start of the drives - probably because of the switch from Wifi to LFE, but I assume Teslafi assume start position to be the last end position. Most of the drives I did yesterday, were missing the start of the beginning, and that is a deal breaker for me, because the home geo fence wont work.

After googling I found similar problems reported more than a year ago, but after reading this report, I get the impression that the this problem (or at least the symptoms) may have been fixed and has recently reappeared. If that is the case, then I will indeed continue my evaluation - assuming it will be fixed.

[brianmay]

@aradoorolesen Will be interested to know what you find.

I suspect though that in at least some cases the problems cannot be fixed in teslamate and are because the Tesla is not providing the required information. For example, it is often reported that MCU2 cars disconnect from the mobile network when the car is parked and will take several minutes to reconnect. Which might be the same switch from Wifi to LFE problem you mention, but I have seen it happen without any wifi.

[aradoorolesen]

@brianmay I have a Model 3 with MCU 3. I have a years worth of data in Teslafi, and it looks like in many situations, when I start a drive, the "P" state at my home location is recorded, but the first couple of "D" states are missed and after about 30-60 seconds, I get the first "D" now being up to 1km away from home. Teslafi has no problem with this, so I assume it starts the drive at the last known position either the "P" state or the end position of the last drive. Never had any problems with that. Teslamate starts the drive 1km away from my home, and that is a problem. What logic is used to determine the start of a drive? Is it only the first "D" state? Just to make it clear, this problem is not with the Teslafi import, as I see the same problem with data recorded by Teslamate itself.

[johnpane]

Aha! I had been viewing my TeslaFi data on TeslaFi and my TeslaMate data on TeslaMate. By outward appearance, TeslaFi had the beginnings of drives and TeslaMate did not. I thought it was a data collection issue isolated to TeslaMate. But now, looking at historical TeslaFi data on TeslaMate I see that TeslaFi also suffered from the problem of missing data at the beginning of drives. It basically patched the data for display purposes. (I had always wondered why TeslaFi also slightly underestimated the drive duration).

I hypothesize that TeslaFi not only imputed the start point from the last location of the car, but also used a routing/road-following algorithm to impute the path from the start point to the start of actual data so that it wasn't just a straight line across terrain.

It would be super-cool if TeslaMate could implement something like this.

[brianmay]

@johnpane Agreed, it would be super cool.

I look forward to reviewing your Pull Request :grinning:

I suspect part of the problem people might be having is that TeslaMate is more aggressive at trying to get the car to sleep then other solutions, and this can cause more complications as a result especially when TeslaMate is trying to get the car to sleep. Complications that may not be easy to resolve without changes to the Tesla API, which is unlikely to happen.

[JakobLichterfeld]

Follow: https://docs.teslamate.org/docs/maintenance/manually_fixing_data