Database Timeout - drives not terminating

[w0rd3r]

Is there an existing issue for this?

• I have searched the existing issues

What happened?

With default DATABASE_TIMEOUT (https://docs.teslamate.org/docs/configuration/environment_variables/), drives are not terminating.
Increasing the DATABASE_TIMEOUT to 60000ms solved the issue for about 6 months.
Today, I doubled DATABASE_TIMEOUT again to be able to terminate drives.

The main issue with this is that I lose the first few minutes of every charge (before it terminates the drive)

Expected Behavior

After a drive, Teslamate terminates the drive immediately.

Steps To Reproduce

• drive the car
• put it in park
• It takes multiple minutes to register the end of the drive.

Relevant log output

2022-01-05 10:21:55.542 car_id=1 [info] Start / :online
2022-01-05 10:21:56.642 car_id=1 [info] Connecting ...
2022-01-05 10:22:08.549 [info] Start of drive initiated by: %TeslaApi.Stream.Data{elevation: ****}
2022-01-05 10:22:08.550 car_id=1 [info] Driving / Start
2022-01-05 10:25:13.577 [info] GET https://owner-api.teslamotors.com/api/1/vehicles//vehicle_data -> 408 (9091.201 ms)
2022-01-05 10:25:13.577 [warn] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
2022-01-05 10:25:13.578 car_id=1 [error] Error / :unknown
2022-01-05 10:26:04.745 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/***/vehicle_data -> 408 (9074.469 ms)
2022-01-05 10:26:04.746 [warn] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
2022-01-05 10:26:04.746 car_id=1 [error] Error / :unknown
2022-01-05 10:26:09.322 car_id=1 [info] Received stream data: :inactive
2022-01-05 10:26:55.205 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/***/vehicle_data -> 408 (9095.879 ms)
2022-01-05 10:26:55.205 [warn] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
2022-01-05 10:26:55.265 car_id=1 [error] Error / :unknown
2022-01-05 10:30:59.974 [info] GET /
2022-01-05 10:31:15.728 [info] GET /
2022-01-05 10:31:20.742 [error] #PID<0.9633.0> running TeslaMateWeb.Endpoint (connection #PID<0.9632.0>, stream id 1) terminated
Server: teslamate.***:80 (http)
Request: GET /
** (exit) exited in: Task.Supervised.stream(5000)
    ** (EXIT) time out
2022-01-05 10:31:26.094 [info] GET /
2022-01-05 10:31:33.551 [info] GET /
2022-01-05 10:31:40.137 [error] #PID<0.9647.0> running TeslaMateWeb.Endpoint (connection #PID<0.9646.0>, stream id 1) terminated
Server: teslamate.***:80 (http)
Request: GET /
** (exit) exited in: Task.Supervised.stream(5000)
    ** (EXIT) time out
2022-01-05 10:31:51.539 [info] GET /
2022-01-05 10:31:56.903 [error] #PID<0.9660.0> running TeslaMateWeb.Endpoint (connection #PID<0.9659.0>, stream id 1) terminated
Server: teslamate.***:80 (http)
Request: GET /
** (exit) exited in: Task.Supervised.stream(5000)
    ** (EXIT) time out
2022-01-05 10:32:09.099 [info] GET /
2022-01-05 10:32:14.123 [error] #PID<0.9674.0> running TeslaMateWeb.Endpoint (connection #PID<0.9673.0>, stream id 1) terminated
Server: teslamate.***:80 (http)
Request: GET /
** (exit) exited in: Task.Supervised.stream(5000)
    ** (EXIT) time out
2022-01-05 10:32:17.005 [info] GET /
2022-01-05 10:32:22.033 [error] #PID<0.9681.0> running TeslaMateWeb.Endpoint (connection #PID<0.9680.0>, stream id 1) terminated
Server: teslamate.***:80 (http)
Request: GET /
** (exit) exited in: Task.Supervised.stream(5000)
    ** (EXIT) time out
2022-01-05 10:32:24.220 [info] GET /
2022-01-05 10:32:39.357 [info] GET /
2022-01-05 10:32:44.436 [error] #PID<0.9698.0> running TeslaMateWeb.Endpoint (connection #PID<0.9697.0>, stream id 1) terminated
Server: teslamate.***:80 (http)
Request: GET /
** (exit) exited in: Task.Supervised.stream(5000)
    ** (EXIT) time out
2022-01-05 10:32:44.961 [error] Postgrex.Protocol (#PID<0.2323.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2465.0> timed out because it queued and checked out the connection for longer than 120000ms
#PID<0.2465.0> was at location:
    :prim_inet.recv0/3
    (postgrex 0.15.13) lib/postgrex/protocol.ex:2996: Postgrex.Protocol.msg_recv/4
    (postgrex 0.15.13) lib/postgrex/protocol.ex:2042: Postgrex.Protocol.recv_bind/3
    (postgrex 0.15.13) lib/postgrex/protocol.ex:1934: Postgrex.Protocol.bind_execute/4
    (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
    (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
    (db_connection 2.4.1) lib/db_connection.ex:650: DBConnection.execute/4
    (ecto_sql 3.7.1) lib/ecto/adapters/postgres/connection.ex:80: Ecto.Adapters.Postgres.Connection.execute/4
    2022-01-05 10:32:44.971 [error] GenStateMachine :"1" terminating
** (DBConnection.ConnectionError) tcp recv: closed (the connection was closed by the pool, possibly due to a timeout or because the pool has been terminated)
    (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
    (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
    (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
    (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
    (ecto 3.7.1) lib/ecto/repo/queryable.ex:146: Ecto.Repo.Queryable.one/3
    (teslamate 1.25.0) lib/teslamate/log.ex:292: TeslaMate.Log.close_drive/2
    (teslamate 1.25.0) lib/teslamate/vehicles/vehicle.ex:1004: anonymous fn/3 in TeslaMate.Vehicles.Vehicle.handle_event/4
    (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:1021: anonymous fn/3 in Ecto.Adapters.SQL.checkout_or_transaction/4
2022-01-05 10:32:46.983 car_id=1 [info] Start / :online
2022-01-05 10:32:49.417 car_id=1 [info] Connecting ...
2022-01-05 10:33:04.895 [info] GET /
2022-01-05 10:33:05.040 [info] Sent 200 in 145ms
2022-01-05 10:39:07.289 car_id=1 [info] Received stream data: :inactive
2022-01-05 10:39:38.889 [info] Start of drive initiated by: %TeslaApi.Stream.Data{elevation: *****}
2022-01-05 10:39:38.889 car_id=1 [info] Driving / Start
2022-01-05 10:41:55.903 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (440.214 ms)
2022-01-05 10:41:57.338 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (115.800 ms)
2022-01-05 10:41:57.872 [info] End of drive initiated by: %TeslaApi.Vehicle.State.Drive{****}
2022-01-05 10:41:57.872 car_id=1 [info] Driving / Ended / 0 km – 1 min
2022-01-05 10:41:57.872 car_id=1 [info] Start / :online
2022-01-05 10:46:16.463 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (232.863 ms)
2022-01-05 10:46:16.898 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (41.378 ms)
2022-01-05 10:46:24.384 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/***/vehicle_data -> 408 (9233.912 ms)
2022-01-05 10:46:24.385 [warn] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
2022-01-05 10:46:24.386 car_id=1 [error] Error / :unknown
2022-01-05 10:47:20.690 [info] Start of drive initiated by: %TeslaApi.Stream.Data{****}
2022-01-05 10:47:20.690 car_id=1 [info] Driving / Start
2022-01-05 10:54:11.246 [info] GET /
2022-01-05 10:54:16.405 [error] #PID<0.14212.0> running TeslaMateWeb.Endpoint (connection #PID<0.14211.0>, stream id 1) terminated
Server: teslamate.***:80 (http)
Request: GET /
** (exit) exited in: Task.Supervised.stream(5000)
    ** (EXIT) time out
2022-01-05 10:55:17.212 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (484.663 ms)
2022-01-05 10:55:17.735 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (488.592 ms)
2022-01-05 10:55:18.062 [info] End of drive initiated by: %TeslaApi.Vehicle.State.Drive{****}
2022-01-05 10:55:18.062 car_id=1 [info] Driving / Ended / 3 km – 7 min
2022-01-05 10:55:18.062 car_id=1 [info] Start / :online
2022-01-05 10:58:36.206 car_id=1 [info] Suspending logging
2022-01-05 11:01:11.143 [info] GET /
2022-01-05 11:01:11.343 [info] Sent 200 in 200ms

Screenshots

No response

Additional data

No response

Type of installation

Docker

Version

v1.25.0

[adriankumpf]

What kind of hardware are you running?

[w0rd3r]

NAS Synology DS2415+
INTEL Atom C2538
2.4 GHz
4 cores
2 GB RAM

[adriankumpf]

Most problems of this kind have been reported by users of Synology or Raspberry Pis so far. The database seems to be temporarily overloaded or not responsive.

[adriankumpf]

I'll move this to a discussion for now as this looks like a hardware related issue.