teslamate-org / teslamate

A self-hosted data logger for your Tesla 🚘
https://docs.teslamate.org
MIT License
5.76k stars 720 forks source link

Drives (trips) altogether missing #2502

Closed rmyadsk closed 2 years ago

rmyadsk commented 2 years ago

Is there an existing issue for this?

What happened?

I have not logged into the Grafana interface in some time, but doing so just now, I have noticed that the vast majority of drives my vehicles have taken have not been logged. The behavior seems to have begun around the beginning of February 2022.

All of my charge sessions appear to be logged normally.

Expected Behavior

All drives are visible under Dashboards -> Drives.

Steps To Reproduce

  1. Drive a Teslamate-monitored vehicle.
  2. Some time later, go to Dashboards -> Drives in Grafana.
  3. Note the absence of the drive in Grafana.

Relevant log output

docker-compose logs teslamate: 

pi@piaware:~ $ docker-compose logs teslamate
Attaching to pi_teslamate_1
teslamate_1  | 2022-02-26 10:04:35.985 [info] Migrations already up
teslamate_1  | 2022-02-26 10:04:46.056 [info] System Info: Erlang/OTP 24 (emu)
teslamate_1  | 2022-02-26 10:04:46.056 [info] Version: 1.27.0-dev
teslamate_1  | 2022-02-26 10:04:46.210 [warning] Could not decrypt API tokens!
teslamate_1  | 2022-02-26 10:04:46.254 [info] Running TeslaMateWeb.Endpoint with cowboy 2.9.0 at :::4000 (http)
teslamate_1  | 2022-02-26 10:04:46.262 [info] Access TeslaMateWeb.Endpoint at http://teslamate.oscarfish.com
teslamate_1  | 2022-02-26 10:04:46.298 [warning] Using fallback vehicles:
teslamate_1  | 
teslamate_1  | [
teslamate_1  |   %TeslaApi.Vehicle{
teslamate_1  |     api_version: nil,
teslamate_1  |     backseat_token: nil,
teslamate_1  |     backseat_token_updated_at: nil,
teslamate_1  |     calendar_enabled: nil,
teslamate_1  |     charge_state: nil,
teslamate_1  |     climate_state: nil,
teslamate_1  |     color: nil,
teslamate_1  |     display_name: "Baby Blue",
teslamate_1  |     drive_state: nil,
teslamate_1  |     gui_settings: nil,
teslamate_1  |     id: 1492932132939306,
teslamate_1  |     in_service: false,
teslamate_1  |     option_codes: [],
teslamate_1  |     state: "unknown",
teslamate_1  |     tokens: [],
teslamate_1  |     vehicle_config: nil,
teslamate_1  |     vehicle_id: 1038433579,
teslamate_1  |     vehicle_state: nil,
teslamate_1  |     vin: "5YJ3E1EA7KF299285"
teslamate_1  |   },
teslamate_1  |   %TeslaApi.Vehicle{
teslamate_1  |     api_version: nil,
teslamate_1  |     backseat_token: nil,
teslamate_1  |     backseat_token_updated_at: nil,
teslamate_1  |     calendar_enabled: nil,
teslamate_1  |     charge_state: nil,
teslamate_1  |     climate_state: nil,
teslamate_1  |     color: nil,
teslamate_1  |     display_name: "Don't Panic",
teslamate_1  |     drive_state: nil,
teslamate_1  |     gui_settings: nil,
teslamate_1  |     id: 1492932493538049,
teslamate_1  |     in_service: false,
teslamate_1  |     option_codes: [],
teslamate_1  |     state: "unknown",
teslamate_1  |     tokens: [],
teslamate_1  |     vehicle_config: nil,
teslamate_1  |     vehicle_id: 174286848,
teslamate_1  |     vehicle_state: nil,
teslamate_1  |     vin: "5YJ3E1EA2JF046440"
teslamate_1  |   }
teslamate_1  | ]
teslamate_1  | 2022-02-26 10:04:46.298 [info] Starting logger for 'Baby Blue'
teslamate_1  | 2022-02-26 10:04:46.323 [info] Starting logger for 'Don't Panic'
teslamate_1  | 2022-02-26 10:04:46.382 car_id=1 [error] Error / not_signed_in
teslamate_1  | 2022-02-26 10:04:46.396 car_id=2 [error] Error / not_signed_in
teslamate_1  | 2022-02-26 10:05:12.213 [info] GET /settings
teslamate_1  | 2022-02-26 10:05:12.390 [info] Sent 200 in 176ms
teslamate_1  | 2022-02-26 10:05:43.226 [notice]     :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_1_api_error, :fuse_blown}}
teslamate_1  | 2022-02-26 10:05:43.228 [notice]     :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_2_api_error, :fuse_blown}}
teslamate_1  | 2022-02-26 10:09:42.033 [info] GET /settings
teslamate_1  | 2022-02-26 10:09:42.072 [info] Sent 200 in 38ms
teslamate_1  | 2022-02-26 10:09:50.281 [info] GET /
teslamate_1  | 2022-02-26 10:09:50.290 [info] Sent 302 in 9ms
teslamate_1  | 2022-02-26 10:09:50.711 [info] GET /sign_in
teslamate_1  | 2022-02-26 10:09:50.726 [info] Sent 200 in 14ms
teslamate_1  | 2022-02-26 10:12:18.384 [info] POST https://auth.tesla.com/oauth2/v3/token -> 200 (388.574 ms)
teslamate_1  | 2022-02-26 10:12:18.431 [info] Scheduling token refresh in 6 h
teslamate_1  | 2022-02-26 10:12:19.255 [info] GET /
teslamate_1  | 2022-02-26 10:12:19.311 [info] Starting logger for 'Baby Blue'
teslamate_1  | 2022-02-26 10:12:19.316 [info] Starting logger for 'Don't Panic'
teslamate_1  | 2022-02-26 10:12:19.346 [info] Sent 200 in 90ms
teslamate_1  | 2022-02-26 10:12:19.833 car_id=2 [info] Start / :asleep
teslamate_1  | 2022-02-26 10:12:19.993 car_id=1 [info] Start / :online
teslamate_1  | 2022-02-26 10:12:20.072 car_id=1 [info] Connecting ...
teslamate_1  | 2022-02-26 10:14:16.745 [info] GET /settings
teslamate_1  | 2022-02-26 10:14:16.783 [info] Sent 200 in 37ms
teslamate_1  | 2022-02-26 10:14:43.235 [notice]     :alarm_handler: {:clear, TeslaMate.Vehicles.Vehicle_1_api_error}
teslamate_1  | 2022-02-26 10:14:43.235 [notice]     :alarm_handler: {:clear, TeslaMate.Vehicles.Vehicle_2_api_error}
teslamate_1  | 2022-02-26 10:15:23.927 car_id=1 [info] Suspending logging
teslamate_1  | 2022-02-26 10:16:01.490 car_id=2 [info] Start / :online
teslamate_1  | 2022-02-26 10:16:01.592 car_id=2 [info] Connecting ...
teslamate_1  | 2022-02-26 10:19:06.930 car_id=2 [info] Suspending logging
teslamate_1  | 2022-02-26 10:20:15.563 car_id=1 [info] Fetching vehicle state ...
teslamate_1  | 2022-02-26 10:20:15.742 car_id=1 [info] Start / :asleep
teslamate_1  | 2022-02-26 10:20:15.765 car_id=1 [info] Disconnecting ...
teslamate_1  | 2022-02-26 10:29:21.566 car_id=2 [info] Fetching vehicle state ...
teslamate_1  | 2022-02-26 10:29:21.718 car_id=2 [info] Start / :asleep
teslamate_1  | 2022-02-26 10:29:21.750 car_id=2 [info] Disconnecting ...
teslamate_1  | 2022-02-26 10:46:08.225 car_id=2 [info] Start / :online
teslamate_1  | 2022-02-26 10:46:08.288 car_id=2 [info] Connecting ...
teslamate_1  | 2022-02-26 10:48:58.096 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9144.229 ms)
teslamate_1  | 2022-02-26 10:48:58.096 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 10:48:58.097 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 10:49:27.260 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9161.475 ms)
teslamate_1  | 2022-02-26 10:49:27.261 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 10:49:27.261 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 10:49:56.462 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9197.730 ms)
teslamate_1  | 2022-02-26 10:49:56.462 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 10:49:56.463 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 10:50:25.646 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9179.689 ms)
teslamate_1  | 2022-02-26 10:50:25.646 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 10:50:25.647 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 10:50:43.271 [notice]     :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_2_api_error, :fuse_blown}}
teslamate_1  | 2022-02-26 10:50:54.838 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9188.755 ms)
teslamate_1  | 2022-02-26 10:50:54.838 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 10:50:54.839 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 10:51:24.187 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9345.826 ms)
teslamate_1  | 2022-02-26 10:51:24.187 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 10:51:24.188 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 10:51:53.335 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9145.336 ms)
teslamate_1  | 2022-02-26 10:51:53.336 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 10:51:53.337 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 10:52:22.495 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9155.392 ms)
teslamate_1  | 2022-02-26 10:52:22.495 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 10:52:22.496 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 10:52:51.644 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9146.262 ms)
teslamate_1  | 2022-02-26 10:52:51.645 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 10:52:51.645 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 10:53:20.809 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9161.172 ms)
teslamate_1  | 2022-02-26 10:53:20.810 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 10:53:20.810 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 10:53:33.732 car_id=2 [info] Received stream data: :inactive
teslamate_1  | 2022-02-26 10:53:49.980 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9168.084 ms)
teslamate_1  | 2022-02-26 10:53:49.981 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 10:53:49.981 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 10:54:19.152 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9167.816 ms)
teslamate_1  | 2022-02-26 10:54:19.152 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 10:54:19.153 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 10:54:39.687 car_id=2 [info] Suspending logging
teslamate_1  | 2022-02-26 10:57:43.278 [notice]     :alarm_handler: {:clear, TeslaMate.Vehicles.Vehicle_2_api_error}
teslamate_1  | 2022-02-26 10:58:19.740 [error] Vehicle Error: Vehicle is offline
teslamate_1  | 2022-02-26 10:59:37.982 car_id=2 [info] Fetching vehicle state ...
teslamate_1  | 2022-02-26 10:59:38.137 car_id=2 [info] Start / :asleep
teslamate_1  | 2022-02-26 10:59:38.158 car_id=2 [info] Disconnecting ...
teslamate_1  | 2022-02-26 11:16:26.011 car_id=2 [info] Start / :online
teslamate_1  | 2022-02-26 11:16:26.135 car_id=2 [info] Connecting ...
teslamate_1  | 2022-02-26 11:17:05.310 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9166.646 ms)
teslamate_1  | 2022-02-26 11:17:05.310 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 11:17:05.311 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 11:19:37.365 car_id=2 [info] Suspending logging
teslamate_1  | 2022-02-26 11:28:30.277 [info] GET /
teslamate_1  | 2022-02-26 11:28:30.294 [info] Sent 200 in 16ms
teslamate_1  | 2022-02-26 11:30:13.611 car_id=2 [info] Fetching vehicle state ...
teslamate_1  | 2022-02-26 11:30:13.804 car_id=2 [info] Start / :asleep
teslamate_1  | 2022-02-26 11:30:13.821 car_id=2 [info] Disconnecting ...
teslamate_1  | 2022-02-26 11:47:02.559 car_id=2 [info] Start / :online
teslamate_1  | 2022-02-26 11:47:02.600 car_id=2 [info] Connecting ...
teslamate_1  | 2022-02-26 11:50:07.300 car_id=2 [info] Suspending logging
teslamate_1  | 2022-02-26 12:00:16.163 car_id=2 [info] Fetching vehicle state ...
teslamate_1  | 2022-02-26 12:00:16.358 car_id=2 [info] Start / :asleep
teslamate_1  | 2022-02-26 12:00:16.379 car_id=2 [info] Disconnecting ...
teslamate_1  | 2022-02-26 12:02:42.391 [info] GET /
teslamate_1  | 2022-02-26 12:02:42.408 [info] Sent 200 in 16ms
teslamate_1  | 2022-02-26 12:17:05.672 car_id=2 [info] Start / :online
teslamate_1  | 2022-02-26 12:17:05.735 car_id=2 [info] Connecting ...
teslamate_1  | 2022-02-26 12:17:39.402 car_id=2 [warning] Received stale stream data: %TeslaApi.Stream.Data{elevation: 16, est_heading: 339, est_lat: 39.141492, est_lng: -76.561755, est_range: 50, heading: 340, odometer: 54968.2, power: 0, range: 64, shift_state: nil, soc: 26, speed: nil, time: ~U[2022-02-26 17:17:34.784Z]}
teslamate_1  | 2022-02-26 12:18:10.135 car_id=2 [warning] Received stale stream data: %TeslaApi.Stream.Data{elevation: 16, est_heading: 339, est_lat: 39.141492, est_lng: -76.561755, est_range: 50, heading: 340, odometer: 54968.2, power: 0, range: 64, shift_state: nil, soc: 26, speed: nil, time: ~U[2022-02-26 17:18:05.491Z]}
teslamate_1  | 2022-02-26 12:20:09.299 car_id=2 [info] Suspending logging
teslamate_1  | 2022-02-26 12:30:35.870 car_id=2 [info] Fetching vehicle state ...
teslamate_1  | 2022-02-26 12:30:36.019 car_id=2 [info] Start / :asleep
teslamate_1  | 2022-02-26 12:30:36.041 car_id=2 [info] Disconnecting ...
teslamate_1  | 2022-02-26 12:42:27.282 car_id=1 [info] Start / :online
teslamate_1  | 2022-02-26 12:42:27.325 car_id=1 [info] Connecting ...
teslamate_1  | 2022-02-26 12:43:29.958 car_id=1 [warning] Received stale stream data: %TeslaApi.Stream.Data{elevation: 18, est_heading: 157, est_lat: 39.141555, est_lng: -76.561702, est_range: 169, heading: 337, odometer: 25652.6, power: 0, range: 198, shift_state: nil, soc: 88, speed: nil, time: ~U[2022-02-26 17:43:29.963Z]}
teslamate_1  | 2022-02-26 12:45:31.785 car_id=1 [info] Suspending logging
teslamate_1  | 2022-02-26 12:47:54.954 car_id=2 [info] Start / :online
teslamate_1  | 2022-02-26 12:47:55.026 car_id=2 [info] Connecting ...
teslamate_1  | 2022-02-26 12:50:58.015 car_id=2 [info] Suspending logging
teslamate_1  | 2022-02-26 12:51:34.701 [info] GET /
teslamate_1  | 2022-02-26 12:51:34.731 [info] Sent 200 in 29ms
teslamate_1  | 2022-02-26 12:55:44.973 car_id=1 [info] Fetching vehicle state ...
teslamate_1  | 2022-02-26 12:55:45.066 [error] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306 -> error: "socket closed" (90.623 ms)
teslamate_1  | 2022-02-26 12:55:45.066 [warning] TeslaApi.Error / socket closed
teslamate_1  | 2022-02-26 12:55:45.067 car_id=1 [info] Unhandled fetch result: {:error, :unknown}
teslamate_1  | 2022-02-26 13:00:50.625 car_id=1 [info] Fetching vehicle state ...
teslamate_1  | 2022-02-26 13:01:25.629 [error] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306 -> error: "timeout" (35002.201 ms)
teslamate_1  | 2022-02-26 13:01:25.629 [warning] TeslaApi.Error / timeout
teslamate_1  | 2022-02-26 13:01:25.631 car_id=1 [info] Unhandled fetch result: {:error, :unknown}
teslamate_1  | 2022-02-26 13:01:28.929 car_id=2 [info] Fetching vehicle state ...
teslamate_1  | 2022-02-26 13:01:29.457 car_id=2 [info] Start / :asleep
teslamate_1  | 2022-02-26 13:01:29.477 car_id=2 [info] Disconnecting ...
teslamate_1  | 2022-02-26 13:05:56.269 car_id=1 [info] Fetching vehicle state ...
teslamate_1  | 2022-02-26 13:05:56.493 car_id=1 [info] Start / :asleep
teslamate_1  | 2022-02-26 13:05:56.508 car_id=1 [info] Disconnecting ...
teslamate_1  | 2022-02-26 13:18:16.645 car_id=2 [info] Start / :online
teslamate_1  | 2022-02-26 13:18:16.688 car_id=2 [info] Connecting ...
teslamate_1  | 2022-02-26 13:21:20.362 car_id=2 [info] Suspending logging
teslamate_1  | 2022-02-26 13:30:28.555 [error] Vehicle Error: Vehicle is offline
teslamate_1  | 2022-02-26 13:32:06.793 car_id=2 [info] Fetching vehicle state ...
teslamate_1  | 2022-02-26 13:32:07.343 car_id=2 [info] Start / :asleep
teslamate_1  | 2022-02-26 13:32:07.357 car_id=2 [info] Disconnecting ...
teslamate_1  | 2022-02-26 16:00:58.261 car_id=2 [info] Start / :online
teslamate_1  | 2022-02-26 16:00:58.310 car_id=2 [info] Connecting ...
teslamate_1  | 2022-02-26 16:04:01.374 car_id=2 [info] Suspending logging
teslamate_1  | 2022-02-26 16:12:18.432 [info] Refreshing access token ...
teslamate_1  | 2022-02-26 16:12:18.852 [info] POST https://auth.tesla.com/oauth2/v3/token -> 200 (407.377 ms)
teslamate_1  | 2022-02-26 16:12:18.891 [info] Scheduling token refresh in 6 h
teslamate_1  | 2022-02-26 16:14:36.877 car_id=1 [info] Start / :online
teslamate_1  | 2022-02-26 16:14:36.987 car_id=1 [info] Connecting ...
teslamate_1  | 2022-02-26 16:17:22.920 [info] Start of drive initiated by: %TeslaApi.Stream.Data{elevation: 18, est_heading: 157, est_lat: 39.141535, est_lng: -76.56169, est_range: 168, heading: 157, odometer: 25652.6, power: 4, range: 198, shift_state: "N", soc: 88, speed: 0, time: ~U[2022-02-26 21:17:22.837Z]}
teslamate_1  | 2022-02-26 16:17:22.920 car_id=1 [info] Driving / Start
teslamate_1  | 2022-02-26 16:17:32.151 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9165.319 ms)
teslamate_1  | 2022-02-26 16:17:32.152 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 16:17:32.152 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 16:18:32.179 car_id=1 [info] Received stream data: :inactive
teslamate_1  | 2022-02-26 16:20:26.586 [error] Postgrex.Protocol (#PID<0.2365.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2557.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.2557.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:3090: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2120: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2012: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:585: DBConnection.prepare_execute/4
teslamate_1  | 
teslamate_1  | 2022-02-26 16:20:27.405 [error] GenStateMachine :"1" terminating
teslamate_1  | ** (Postgrex.Error) ERROR 57014 (query_canceled) canceling statement due to user request
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:146: Ecto.Repo.Queryable.one/3
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/log.ex:292: TeslaMate.Log.close_drive/2
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/vehicles/vehicle.ex:1007: anonymous fn/3 in TeslaMate.Vehicles.Vehicle.handle_event/4
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:1021: anonymous fn/3 in Ecto.Adapters.SQL.checkout_or_transaction/4
teslamate_1  | 2022-02-26 16:20:28.635 car_id=1 [info] Start / :online
teslamate_1  | 2022-02-26 16:20:29.248 car_id=1 [info] Connecting ...
teslamate_1  | 2022-02-26 16:21:25.964 [error] Vehicle Error: Vehicle is offline
teslamate_1  | 2022-02-26 16:22:33.599 car_id=2 [info] Fetching vehicle state ...
teslamate_1  | 2022-02-26 16:22:33.759 car_id=2 [info] Start / :asleep
teslamate_1  | 2022-02-26 16:22:33.859 car_id=2 [info] Disconnecting ...
teslamate_1  | 2022-02-26 16:24:30.182 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9233.000 ms)
teslamate_1  | 2022-02-26 16:24:30.183 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 16:24:30.183 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 16:24:42.041 [info] Start of drive initiated by: %TeslaApi.Stream.Data{elevation: 19, est_heading: 269, est_lat: 39.141407, est_lng: -76.561604, est_range: 164, heading: 90, odometer: 25653.0, power: 3, range: 196, shift_state: "R", soc: 87, speed: 1, time: ~U[2022-02-26 21:24:41.860Z]}
teslamate_1  | 2022-02-26 16:24:42.041 car_id=1 [info] Driving / Start
teslamate_1  | 2022-02-26 16:34:59.447 car_id=1 [info] Received stream data: :inactive
teslamate_1  | 2022-02-26 16:42:52.166 car_id=2 [info] Start / :online
teslamate_1  | 2022-02-26 16:42:52.209 car_id=2 [info] Connecting ...
teslamate_1  | 2022-02-26 16:43:07.920 [info] Start of drive initiated by: %TeslaApi.Vehicle.State.Drive{gps_as_of: 1645911786, heading: 337, latitude: 39.141484, longitude: -76.561753, native_latitude: 39.141484, native_location_supported: 1, native_longitude: -76.561753, native_type: "wgs", power: 8, shift_state: "R", speed: 3, timestamp: 1645911787443}
teslamate_1  | 2022-02-26 16:43:07.920 car_id=2 [info] Driving / Start
teslamate_1  | 2022-02-26 16:44:10.016 [error] Vehicle Error: Vehicle is offline
teslamate_1  | 2022-02-26 16:44:37.998 [error] Postgrex.Protocol (#PID<0.2362.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2559.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.2559.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:3090: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2120: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2012: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:585: DBConnection.prepare_execute/4
teslamate_1  | 
teslamate_1  | 2022-02-26 16:44:38.271 [error] GenStateMachine :"2" terminating
teslamate_1  | ** (Postgrex.Error) ERROR 57014 (query_canceled) canceling statement due to user request
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:146: Ecto.Repo.Queryable.one/3
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/log.ex:292: TeslaMate.Log.close_drive/2
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/vehicles/vehicle.ex:1007: anonymous fn/3 in TeslaMate.Vehicles.Vehicle.handle_event/4
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:1021: anonymous fn/3 in Ecto.Adapters.SQL.checkout_or_transaction/4
teslamate_1  | 2022-02-26 16:44:39.084 car_id=2 [info] Start / :online
teslamate_1  | 2022-02-26 16:44:39.211 car_id=2 [info] Connecting ...
teslamate_1  | 2022-02-26 16:47:42.684 car_id=2 [info] Suspending logging
teslamate_1  | 2022-02-26 16:58:02.533 car_id=1 [info] Fetch already in progress ...
teslamate_1  | 2022-02-26 16:59:02.748 [error] Postgrex.Protocol (#PID<0.2364.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.4738.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.4738.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:3090: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2120: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2012: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:585: DBConnection.prepare_execute/4
teslamate_1  | 
teslamate_1  | 2022-02-26 16:59:02.773 [error] GenStateMachine :"1" terminating
teslamate_1  | ** (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_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:146: Ecto.Repo.Queryable.one/3
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/log.ex:292: TeslaMate.Log.close_drive/2
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/vehicles/vehicle.ex:1007: anonymous fn/3 in TeslaMate.Vehicles.Vehicle.handle_event/4
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:1021: anonymous fn/3 in Ecto.Adapters.SQL.checkout_or_transaction/4
teslamate_1  | 2022-02-26 16:59:04.068 car_id=1 [info] Start / :online
teslamate_1  | 2022-02-26 16:59:04.131 car_id=1 [info] Connecting ...
teslamate_1  | 2022-02-26 17:08:31.027 [info] GET /
teslamate_1  | 2022-02-26 17:08:31.053 [info] Sent 200 in 25ms
teslamate_1  | 2022-02-26 17:14:24.790 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9248.802 ms)
teslamate_1  | 2022-02-26 17:14:24.791 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 17:14:24.791 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 17:16:01.095 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9273.838 ms)
teslamate_1  | 2022-02-26 17:16:01.095 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 17:16:01.096 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 17:16:30.253 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9153.800 ms)
teslamate_1  | 2022-02-26 17:16:30.253 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 17:16:30.254 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 17:16:59.424 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9166.932 ms)
teslamate_1  | 2022-02-26 17:16:59.425 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 17:16:59.425 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 17:17:43.670 [notice]     :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_1_api_error, :fuse_blown}}
teslamate_1  | 2022-02-26 17:17:52.016 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9168.965 ms)
teslamate_1  | 2022-02-26 17:17:52.017 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 17:17:52.017 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 17:18:31.308 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9140.290 ms)
teslamate_1  | 2022-02-26 17:18:31.309 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 17:18:31.309 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-02-26 17:18:36.824 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9167.732 ms)
teslamate_1  | 2022-02-26 17:18:36.824 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 17:18:36.825 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 17:19:06.118 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9290.305 ms)
teslamate_1  | 2022-02-26 17:19:06.119 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}

[408 error repeats several hundred times]

teslamate_1  | 2022-02-26 19:52:56.488 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9137.788 ms)
teslamate_1  | 2022-02-26 19:52:56.489 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 19:52:56.489 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 19:53:25.632 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9139.963 ms)
teslamate_1  | 2022-02-26 19:53:25.632 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 19:53:25.633 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 19:53:54.789 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9154.541 ms)
teslamate_1  | 2022-02-26 19:53:54.790 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 19:53:54.791 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 19:54:15.304 car_id=1 [warning] User present ...
teslamate_1  | 2022-02-26 19:58:03.051 [info] Start of drive initiated by: %TeslaApi.Stream.Data{elevation: 5, est_heading: 214, est_lat: 38.963238, est_lng: -76.48787, est_range: 164, heading: 206, odometer: 25672.6, power: 3, range: 170, shift_state: "D", soc: 75, speed: 0, time: ~U[2022-02-27 00:58:02.932Z]}
teslamate_1  | 2022-02-26 19:58:03.051 car_id=1 [info] Driving / Start
teslamate_1  | 2022-02-26 19:59:43.832 [notice]     :alarm_handler: {:clear, TeslaMate.Vehicles.Vehicle_1_api_error}
teslamate_1  | 2022-02-26 20:11:42.561 [error] Postgrex.Protocol (#PID<0.2365.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.5040.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.5040.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:3090: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2120: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2012: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:585: DBConnection.prepare_execute/4
teslamate_1  | 
teslamate_1  | 2022-02-26 20:11:43.392 [error] GenStateMachine :"1" terminating
teslamate_1  | ** (Postgrex.Error) ERROR 57014 (query_canceled) canceling statement due to user request
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:146: Ecto.Repo.Queryable.one/3
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/log.ex:292: TeslaMate.Log.close_drive/2
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/vehicles/vehicle.ex:1007: anonymous fn/3 in TeslaMate.Vehicles.Vehicle.handle_event/4
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:1021: anonymous fn/3 in Ecto.Adapters.SQL.checkout_or_transaction/4
teslamate_1  | 2022-02-26 20:11:44.208 car_id=1 [info] Start / :online
teslamate_1  | 2022-02-26 20:11:44.337 car_id=1 [info] Connecting ...
teslamate_1  | 2022-02-26 20:16:03.898 car_id=1 [warning] Received stale stream data: %TeslaApi.Stream.Data{elevation: 18, est_heading: 35, est_lat: 38.979954, est_lng: -76.537209, est_range: 138, heading: 35, odometer: 25677.8, power: 0, range: 159, shift_state: nil, soc: 70, speed: nil, time: ~U[2022-02-27 01:16:03.310Z]}
teslamate_1  | 2022-02-26 20:19:17.140 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9160.135 ms)
teslamate_1  | 2022-02-26 20:19:17.141 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 20:19:17.141 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 20:20:55.015 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9156.647 ms)
teslamate_1  | 2022-02-26 20:20:55.015 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 20:20:55.016 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 20:21:24.191 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9173.066 ms)
teslamate_1  | 2022-02-26 20:21:24.192 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 20:21:24.192 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 20:21:53.356 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9162.019 ms)
teslamate_1  | 2022-02-26 20:21:53.357 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 20:21:53.357 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 20:22:22.524 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9164.003 ms)
teslamate_1  | 2022-02-26 20:22:22.525 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 20:22:22.525 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 20:22:43.855 [notice]     :alarm_handler: {:set, {TeslaMate.Vehicles.Vehicle_1_api_error, :fuse_blown}}
teslamate_1  | 2022-02-26 20:27:59.838 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9195.895 ms)
teslamate_1  | 2022-02-26 20:27:59.839 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 20:27:59.839 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 20:28:29.025 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9182.649 ms)
teslamate_1  | 2022-02-26 20:28:29.026 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 20:28:29.026 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 20:28:58.257 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9228.884 ms)
teslamate_1  | 2022-02-26 20:28:58.257 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 20:28:58.258 car_id=1 [error] Error / :unknown

[408 error repeats several dozen times]

teslamate_1  | 2022-02-26 20:50:07.058 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 20:50:36.270 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9209.891 ms)
teslamate_1  | 2022-02-26 20:50:36.270 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 20:50:36.271 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 20:51:43.884 [notice]     :alarm_handler: {:clear, TeslaMate.Vehicles.Vehicle_1_api_error}
teslamate_1  | 2022-02-26 20:52:34.594 car_id=1 [warning] Received stale stream data: %TeslaApi.Stream.Data{elevation: 18, est_heading: 35, est_lat: 38.979954, est_lng: -76.537209, est_range: 137, heading: 35, odometer: 25677.8, power: 6, range: 158, shift_state: nil, soc: 70, speed: nil, time: ~U[2022-02-27 01:52:33.964Z]}
teslamate_1  | 2022-02-26 20:55:42.984 [info] Start of drive initiated by: %TeslaApi.Stream.Data{elevation: 18, est_heading: 35, est_lat: 38.979954, est_lng: -76.537209, est_range: 136, heading: 35, odometer: 25677.8, power: 4, range: 157, shift_state: "D", soc: 70, speed: 0, time: ~U[2022-02-27 01:55:42.856Z]}
teslamate_1  | 2022-02-26 20:55:42.984 car_id=1 [info] Driving / Start
teslamate_1  | 2022-02-26 20:59:22.446 car_id=2 [info] Start / :online
teslamate_1  | 2022-02-26 20:59:22.552 car_id=2 [info] Connecting ...
teslamate_1  | 2022-02-26 20:59:58.343 car_id=1 [info] Fetch already in progress ...
teslamate_1  | 2022-02-26 21:00:15.210 car_id=2 [info] Charging detected: -3 kW
teslamate_1  | 2022-02-26 21:00:16.647 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (835.868 ms)
teslamate_1  | 2022-02-26 21:00:18.250 car_id=2 [info] Charging / SOC: 25% / Home
teslamate_1  | 2022-02-26 21:00:18.250 car_id=2 [info] Disconnecting ...
teslamate_1  | 2022-02-26 21:00:58.531 [error] Postgrex.Protocol (#PID<0.2362.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.6244.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.6244.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:3090: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2120: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2012: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:585: DBConnection.prepare_execute/4
teslamate_1  | 
teslamate_1  | 2022-02-26 21:00:58.679 [error] GenStateMachine :"1" terminating
teslamate_1  | ** (Postgrex.Error) ERROR 57014 (query_canceled) canceling statement due to user request
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:146: Ecto.Repo.Queryable.one/3
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/log.ex:292: TeslaMate.Log.close_drive/2
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/vehicles/vehicle.ex:1007: anonymous fn/3 in TeslaMate.Vehicles.Vehicle.handle_event/4
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:1021: anonymous fn/3 in Ecto.Adapters.SQL.checkout_or_transaction/4
teslamate_1  | 2022-02-26 21:00:59.681 car_id=1 [info] Start / :online
teslamate_1  | 2022-02-26 21:00:59.733 car_id=1 [info] Connecting ...
teslamate_1  | 2022-02-26 21:02:20.384 car_id=1 [warning] Received stale stream data: %TeslaApi.Stream.Data{elevation: 22, est_heading: 203, est_lat: 38.97897, est_lng: -76.541152, est_range: 132, heading: 206, odometer: 25678.4, power: 0, range: 155, shift_state: nil, soc: 69, speed: nil, time: ~U[2022-02-27 02:02:18.596Z]}
teslamate_1  | 2022-02-26 21:05:44.690 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9226.173 ms)
teslamate_1  | 2022-02-26 21:05:44.691 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 21:05:44.691 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 21:06:13.838 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9144.624 ms)
teslamate_1  | 2022-02-26 21:06:13.839 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 21:06:13.840 car_id=1 [error] Error / :unknown

[408 error repeats ~100 times]

teslamate_1  | 2022-02-26 22:38:34.455 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9146.656 ms)
teslamate_1  | 2022-02-26 22:38:34.455 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 22:38:34.456 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 22:39:04.110 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9652.140 ms)
teslamate_1  | 2022-02-26 22:39:04.111 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 22:39:04.112 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-26 22:41:02.430 [info] Start of drive initiated by: %TeslaApi.Stream.Data{elevation: 22, est_heading: 215, est_lat: 38.978928, est_lng: -76.54118, est_range: 130, heading: 206, odometer: 25678.4, power: -3, range: 153, shift_state: "D", soc: 68, speed: 9, time: ~U[2022-02-27 03:41:01.949Z]}
teslamate_1  | 2022-02-26 22:41:02.430 car_id=1 [info] Driving / Start
teslamate_1  | 2022-02-26 22:41:43.996 [notice]     :alarm_handler: {:clear, TeslaMate.Vehicles.Vehicle_1_api_error}
teslamate_1  | 2022-02-26 22:51:02.524 [error] Postgrex.Protocol (#PID<0.2366.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.6527.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.6527.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:3090: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2120: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2012: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:585: DBConnection.prepare_execute/4
teslamate_1  | 
teslamate_1  | 2022-02-26 22:51:03.119 [error] GenStateMachine :"1" terminating
teslamate_1  | ** (Postgrex.Error) ERROR 57014 (query_canceled) canceling statement due to user request
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:146: Ecto.Repo.Queryable.one/3
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/log.ex:292: TeslaMate.Log.close_drive/2
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/vehicles/vehicle.ex:1007: anonymous fn/3 in TeslaMate.Vehicles.Vehicle.handle_event/4
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:1021: anonymous fn/3 in Ecto.Adapters.SQL.checkout_or_transaction/4
teslamate_1  | 2022-02-26 22:51:03.975 car_id=1 [info] Start / :online
teslamate_1  | 2022-02-26 22:51:05.489 car_id=1 [info] Connecting ...
teslamate_1  | 2022-02-26 22:58:37.421 [info] Start of drive initiated by: %TeslaApi.Stream.Data{elevation: 10, est_heading: 101, est_lat: 38.965209, est_lng: -76.488641, est_range: 114, heading: 283, odometer: 25682.9, power: 3, range: 145, shift_state: "R", soc: 64, speed: 1, time: ~U[2022-02-27 03:58:36.739Z]}
teslamate_1  | 2022-02-26 22:58:37.421 car_id=1 [info] Driving / Start
teslamate_1  | 2022-02-26 23:01:32.644 [error] Postgrex.Protocol (#PID<0.2364.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.7323.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.7323.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:3090: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2120: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2012: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:585: DBConnection.prepare_execute/4
teslamate_1  | 
teslamate_1  | 2022-02-26 23:01:32.881 [error] GenStateMachine :"1" terminating
teslamate_1  | ** (Postgrex.Error) ERROR 57014 (query_canceled) canceling statement due to user request
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:146: Ecto.Repo.Queryable.one/3
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/log.ex:292: TeslaMate.Log.close_drive/2
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/vehicles/vehicle.ex:1007: anonymous fn/3 in TeslaMate.Vehicles.Vehicle.handle_event/4
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:1021: anonymous fn/3 in Ecto.Adapters.SQL.checkout_or_transaction/4
teslamate_1  | 2022-02-26 23:01:33.604 car_id=1 [info] Start / :online
teslamate_1  | 2022-02-26 23:01:33.686 car_id=1 [info] Connecting ...
teslamate_1  | 2022-02-26 23:07:52.124 car_id=1 [warning] Received stale stream data: %TeslaApi.Stream.Data{elevation: 10, est_heading: 206, est_lat: 38.963385, est_lng: -76.487818, est_range: 114, heading: 26, odometer: 25683.1, power: 0, range: 144, shift_state: nil, soc: 63, speed: nil, time: ~U[2022-02-27 04:07:51.592Z]}
teslamate_1  | 2022-02-26 23:14:15.669 [info] GET /
teslamate_1  | 2022-02-26 23:14:15.703 [info] Sent 200 in 34ms
teslamate_1  | 2022-02-26 23:17:35.658 [info] GET /donate
teslamate_1  | 2022-02-26 23:17:35.664 [info] Sent 302 in 5ms
teslamate_1  | 2022-02-26 23:31:14.699 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9158.562 ms)
teslamate_1  | 2022-02-26 23:31:14.699 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-26 23:31:14.700 car_id=1 [error] Error / :unknown

[408 error repeats ~200 times]

teslamate_1  | 2022-02-27 02:29:21.569 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-27 02:29:50.700 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9129.035 ms)
teslamate_1  | 2022-02-27 02:29:50.701 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-02-27 02:29:50.701 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-02-27 02:35:21.701 [warning] Too many disconnects from streaming API

[Too many disconnects error repeats ~50 times]

teslamate_1  | 2022-02-27 11:54:16.115 [warning] Too many disconnects from streaming API
teslamate_1  | 2022-02-27 11:54:16.115 car_id=1 [info] Creating new connection … 
teslamate_1  | 2022-02-27 11:54:16.115 car_id=1 [info] Disconnecting ...
teslamate_1  | 2022-02-27 11:54:16.135 car_id=1 [info] Connecting ...
teslamate_1  | 2022-02-27 12:00:44.538 [warning] Too many disconnects from streaming API
teslamate_1  | 2022-02-27 12:00:44.538 car_id=1 [info] Creating new connection … 
teslamate_1  | 2022-02-27 12:00:44.538 car_id=1 [info] Disconnecting ...
teslamate_1  | 2022-02-27 12:00:44.556 car_id=1 [info] Connecting ...
teslamate_1  | 2022-02-27 12:09:34.681 car_id=1 [info] Received stream data: :inactive
teslamate_1  | 2022-02-27 12:15:35.683 [info] Start of drive initiated by: %TeslaApi.Stream.Data{elevation: 10, est_heading: 206, est_lat: 38.963385, est_lng: -76.487818, est_range: 98, heading: 26, odometer: 25683.1, power: 3, range: 124, shift_state: "D", soc: 56, speed: 0, time: ~U[2022-02-27 17:15:35.454Z]}
teslamate_1  | 2022-02-27 12:15:35.683 car_id=1 [info] Driving / Start
teslamate_1  | 2022-02-27 12:37:46.663 [info] GET /
teslamate_1  | 2022-02-27 12:37:46.685 [info] Sent 200 in 21ms
teslamate_1  | 2022-02-27 12:40:51.473 [error] Postgrex.Protocol (#PID<0.2358.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.7403.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.7403.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:3090: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2120: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.16.1) lib/postgrex/protocol.ex:2012: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:585: DBConnection.prepare_execute/4
teslamate_1  | 
teslamate_1  | 2022-02-27 12:40:51.484 [error] GenStateMachine :"1" terminating
teslamate_1  | ** (Postgrex.Error) ERROR 57014 (query_canceled) canceling statement due to user request
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:146: Ecto.Repo.Queryable.one/3
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/log.ex:292: TeslaMate.Log.close_drive/2
teslamate_1  |     (teslamate 1.27.0-dev) lib/teslamate/vehicles/vehicle.ex:1007: anonymous fn/3 in TeslaMate.Vehicles.Vehicle.handle_event/4
teslamate_1  |     (ecto_sql 3.7.2) lib/ecto/adapters/sql.ex:1021: anonymous fn/3 in Ecto.Adapters.SQL.checkout_or_transaction/4
teslamate_1  | 2022-02-27 12:40:52.460 car_id=1 [info] Start / :online
teslamate_1  | 2022-02-27 12:40:52.506 car_id=1 [info] Connecting ...
teslamate_1  | 2022-02-27 12:43:43.064 car_id=1 [info] Received stream data: :inactive
teslamate_1  | 2022-02-27 12:51:15.300 car_id=1 [info] Received stream data: :inactive
teslamate_1  | 2022-02-27 12:58:15.285 [warning] Too many disconnects from streaming API
teslamate_1  | 2022-02-27 12:58:15.285 car_id=1 [info] Creating new connection … 
teslamate_1  | 2022-02-27 12:58:15.286 car_id=1 [info] Disconnecting ...
teslamate_1  | 2022-02-27 12:58:15.305 car_id=1 [info] Connecting ...
teslamate_1  | 2022-02-27 13:03:16.983 [info] Start of drive initiated by: %TeslaApi.Stream.Data{elevation: 19, est_heading: 289, est_lat: 39.075279, est_lng: -76.584035, est_range: 78, heading: 286, odometer: 25701.2, power: 0, range: 103, shift_state: "D", soc: 46, speed: 0, time: ~U[2022-02-27 18:03:16.773Z]}
teslamate_1  | 2022-02-27 13:03:16.983 car_id=1 [info] Driving / Start
teslamate_1  | 2022-02-27 13:04:21.672 [info] GET /settings
teslamate_1  | 2022-02-27 13:04:21.722 [info] Sent 200 in 49ms
pi@piaware:~ $

Screenshots

This is my daily driver, ~30 miles a day minimum. Almost all logging seems to have dropped off save for a single trip on Feb. 15:

Screen Shot 2022-02-27 at 1 08 38 PM

Additional data

No response

Type of installation

Docker

Version

v.1.27.0-dev

rmyadsk commented 2 years ago

There may be something odd happening at the database. Here's docker-compose logs database:

pi@piaware:~ $ docker-compose logs database Attaching to pi_database_1 database_1 | database_1 | PostgreSQL Database directory appears to contain a database; Skipping initialization database_1 | database_1 | 2022-02-26 15:04:26.206 UTC [1] LOG: starting PostgreSQL 12.10 (Debian 12.10-1.pgdg110+1) on arm-unknown-linux-gnueabihf, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 32-bit database_1 | 2022-02-26 15:04:26.218 UTC [1] LOG: listening on IPv4 address "0.0.0.0", port 5432 database_1 | 2022-02-26 15:04:26.218 UTC [1] LOG: listening on IPv6 address "::", port 5432 database_1 | 2022-02-26 15:04:26.710 UTC [1] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432" database_1 | 2022-02-26 15:04:27.941 UTC [26] LOG: database system was shut down at 2022-02-26 15:04:07 UTC database_1 | 2022-02-26 15:04:28.405 UTC [1] LOG: database system is ready to accept connections database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | 2022-02-26 21:20:27.115 UTC [39] ERROR: canceling statement due to user request database_1 | 2022-02-26 21:20:27.115 UTC [39] STATEMENT: SELECT s0."count", s0."start_position_id", s0."end_position_id", s0."outside_temp_avg", s0."inside_temp_avg", s0."speed_max", s0."power_max", s0."power_min", s0."start_date", s0."end_date", s0."start_km", s0."end_km", s0."distance", s0."duration_min", s0."start_ideal_range_km", s0."end_ideal_range_km", s0."start_rated_range_km", s0."end_rated_range_km", s1."start_ideal_range_km", s1."end_ideal_range_km", s1."start_rated_range_km", s1."end_rated_range_km" FROM (SELECT count() OVER "w" AS "count", first_value(sp0."id") OVER "w" AS "start_position_id", last_value(sp0."id") OVER "w" AS "end_position_id", avg(sp0."outside_temp") OVER "w" AS "outside_temp_avg", avg(sp0."inside_temp") OVER "w" AS "inside_temp_avg", max(sp0."speed") OVER "w" AS "speed_max", max(sp0."power") OVER "w" AS "power_max", min(sp0."power") OVER "w" AS "power_min", first_value(sp0."date") OVER "w" AS "start_date", last_value(sp0."date") OVER "w" AS "end_date", first_value(sp0."odometer") OVER "w" AS "start_km", last_value(sp0."odometer") OVER "w" AS "end_km", last_value(sp0."odometer") OVER "w" - first_value(sp0."odometer") OVER "w" AS "distance", round(extract(epoch from (last_value(sp0."date") OVER "w" - first_value(sp0."date") OVER "w")) / 60)::integer AS "duration_min", -1 AS "start_ideal_range_km", -1 AS "end_ideal_range_km", -1 AS "start_rated_range_km", -1 AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (sp0."drive_id" = $1) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s0 INNER JOIN (SELECT first_value(sp0."ideal_battery_range_km") OVER "w" AS "start_ideal_range_km", last_value(sp0."ideal_battery_range_km") OVER "w" AS "end_ideal_range_km", first_value(sp0."rated_battery_range_km") OVER "w" AS "start_rated_range_km", last_value(sp0."rated_battery_range_km") OVER "w" AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (((sp0."drive_id" = $2) AND NOT (sp0."ideal_battery_range_km" IS NULL)) AND NOT (sp0."odometer" IS NULL)) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s1 ON TRUE database_1 | 2022-02-26 21:44:38.249 UTC [45] ERROR: canceling statement due to user request database_1 | 2022-02-26 21:44:38.249 UTC [45] STATEMENT: SELECT s0."count", s0."start_position_id", s0."end_position_id", s0."outside_temp_avg", s0."inside_temp_avg", s0."speed_max", s0."power_max", s0."power_min", s0."start_date", s0."end_date", s0."start_km", s0."end_km", s0."distance", s0."duration_min", s0."start_ideal_range_km", s0."end_ideal_range_km", s0."start_rated_range_km", s0."end_rated_range_km", s1."start_ideal_range_km", s1."end_ideal_range_km", s1."start_rated_range_km", s1."end_rated_range_km" FROM (SELECT count() OVER "w" AS "count", first_value(sp0."id") OVER "w" AS "start_position_id", last_value(sp0."id") OVER "w" AS "end_position_id", avg(sp0."outside_temp") OVER "w" AS "outside_temp_avg", avg(sp0."inside_temp") OVER "w" AS "inside_temp_avg", max(sp0."speed") OVER "w" AS "speed_max", max(sp0."power") OVER "w" AS "power_max", min(sp0."power") OVER "w" AS "power_min", first_value(sp0."date") OVER "w" AS "start_date", last_value(sp0."date") OVER "w" AS "end_date", first_value(sp0."odometer") OVER "w" AS "start_km", last_value(sp0."odometer") OVER "w" AS "end_km", last_value(sp0."odometer") OVER "w" - first_value(sp0."odometer") OVER "w" AS "distance", round(extract(epoch from (last_value(sp0."date") OVER "w" - first_value(sp0."date") OVER "w")) / 60)::integer AS "duration_min", -1 AS "start_ideal_range_km", -1 AS "end_ideal_range_km", -1 AS "start_rated_range_km", -1 AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (sp0."drive_id" = $1) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s0 INNER JOIN (SELECT first_value(sp0."ideal_battery_range_km") OVER "w" AS "start_ideal_range_km", last_value(sp0."ideal_battery_range_km") OVER "w" AS "end_ideal_range_km", first_value(sp0."rated_battery_range_km") OVER "w" AS "start_rated_range_km", last_value(sp0."rated_battery_range_km") OVER "w" AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (((sp0."drive_id" = $2) AND NOT (sp0."ideal_battery_range_km" IS NULL)) AND NOT (sp0."odometer" IS NULL)) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s1 ON TRUE database_1 | 2022-02-26 21:59:02.796 UTC [41] ERROR: canceling statement due to user request database_1 | 2022-02-26 21:59:02.796 UTC [41] STATEMENT: SELECT s0."count", s0."start_position_id", s0."end_position_id", s0."outside_temp_avg", s0."inside_temp_avg", s0."speed_max", s0."power_max", s0."power_min", s0."start_date", s0."end_date", s0."start_km", s0."end_km", s0."distance", s0."duration_min", s0."start_ideal_range_km", s0."end_ideal_range_km", s0."start_rated_range_km", s0."end_rated_range_km", s1."start_ideal_range_km", s1."end_ideal_range_km", s1."start_rated_range_km", s1."end_rated_range_km" FROM (SELECT count() OVER "w" AS "count", first_value(sp0."id") OVER "w" AS "start_position_id", last_value(sp0."id") OVER "w" AS "end_position_id", avg(sp0."outside_temp") OVER "w" AS "outside_temp_avg", avg(sp0."inside_temp") OVER "w" AS "inside_temp_avg", max(sp0."speed") OVER "w" AS "speed_max", max(sp0."power") OVER "w" AS "power_max", min(sp0."power") OVER "w" AS "power_min", first_value(sp0."date") OVER "w" AS "start_date", last_value(sp0."date") OVER "w" AS "end_date", first_value(sp0."odometer") OVER "w" AS "start_km", last_value(sp0."odometer") OVER "w" AS "end_km", last_value(sp0."odometer") OVER "w" - first_value(sp0."odometer") OVER "w" AS "distance", round(extract(epoch from (last_value(sp0."date") OVER "w" - first_value(sp0."date") OVER "w")) / 60)::integer AS "duration_min", -1 AS "start_ideal_range_km", -1 AS "end_ideal_range_km", -1 AS "start_rated_range_km", -1 AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (sp0."drive_id" = $1) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s0 INNER JOIN (SELECT first_value(sp0."ideal_battery_range_km") OVER "w" AS "start_ideal_range_km", last_value(sp0."ideal_battery_range_km") OVER "w" AS "end_ideal_range_km", first_value(sp0."rated_battery_range_km") OVER "w" AS "start_rated_range_km", last_value(sp0."rated_battery_range_km") OVER "w" AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (((sp0."drive_id" = $2) AND NOT (sp0."ideal_battery_range_km" IS NULL)) AND NOT (sp0."odometer" IS NULL)) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s1 ON TRUE database_1 | 2022-02-26 21:59:03.037 UTC [41] LOG: could not send data to client: Broken pipe database_1 | 2022-02-26 21:59:03.037 UTC [41] FATAL: connection to client lost database_1 | 2022-02-27 01:11:43.186 UTC [426] ERROR: canceling statement due to user request database_1 | 2022-02-27 01:11:43.186 UTC [426] STATEMENT: SELECT s0."count", s0."start_position_id", s0."end_position_id", s0."outside_temp_avg", s0."inside_temp_avg", s0."speed_max", s0."power_max", s0."power_min", s0."start_date", s0."end_date", s0."start_km", s0."end_km", s0."distance", s0."duration_min", s0."start_ideal_range_km", s0."end_ideal_range_km", s0."start_rated_range_km", s0."end_rated_range_km", s1."start_ideal_range_km", s1."end_ideal_range_km", s1."start_rated_range_km", s1."end_rated_range_km" FROM (SELECT count() OVER "w" AS "count", first_value(sp0."id") OVER "w" AS "start_position_id", last_value(sp0."id") OVER "w" AS "end_position_id", avg(sp0."outside_temp") OVER "w" AS "outside_temp_avg", avg(sp0."inside_temp") OVER "w" AS "inside_temp_avg", max(sp0."speed") OVER "w" AS "speed_max", max(sp0."power") OVER "w" AS "power_max", min(sp0."power") OVER "w" AS "power_min", first_value(sp0."date") OVER "w" AS "start_date", last_value(sp0."date") OVER "w" AS "end_date", first_value(sp0."odometer") OVER "w" AS "start_km", last_value(sp0."odometer") OVER "w" AS "end_km", last_value(sp0."odometer") OVER "w" - first_value(sp0."odometer") OVER "w" AS "distance", round(extract(epoch from (last_value(sp0."date") OVER "w" - first_value(sp0."date") OVER "w")) / 60)::integer AS "duration_min", -1 AS "start_ideal_range_km", -1 AS "end_ideal_range_km", -1 AS "start_rated_range_km", -1 AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (sp0."drive_id" = $1) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s0 INNER JOIN (SELECT first_value(sp0."ideal_battery_range_km") OVER "w" AS "start_ideal_range_km", last_value(sp0."ideal_battery_range_km") OVER "w" AS "end_ideal_range_km", first_value(sp0."rated_battery_range_km") OVER "w" AS "start_rated_range_km", last_value(sp0."rated_battery_range_km") OVER "w" AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (((sp0."drive_id" = $2) AND NOT (sp0."ideal_battery_range_km" IS NULL)) AND NOT (sp0."odometer" IS NULL)) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s1 ON TRUE database_1 | 2022-02-27 02:00:58.651 UTC [452] ERROR: canceling statement due to user request database_1 | 2022-02-27 02:00:58.651 UTC [452] STATEMENT: SELECT s0."count", s0."start_position_id", s0."end_position_id", s0."outside_temp_avg", s0."inside_temp_avg", s0."speed_max", s0."power_max", s0."power_min", s0."start_date", s0."end_date", s0."start_km", s0."end_km", s0."distance", s0."duration_min", s0."start_ideal_range_km", s0."end_ideal_range_km", s0."start_rated_range_km", s0."end_rated_range_km", s1."start_ideal_range_km", s1."end_ideal_range_km", s1."start_rated_range_km", s1."end_rated_range_km" FROM (SELECT count() OVER "w" AS "count", first_value(sp0."id") OVER "w" AS "start_position_id", last_value(sp0."id") OVER "w" AS "end_position_id", avg(sp0."outside_temp") OVER "w" AS "outside_temp_avg", avg(sp0."inside_temp") OVER "w" AS "inside_temp_avg", max(sp0."speed") OVER "w" AS "speed_max", max(sp0."power") OVER "w" AS "power_max", min(sp0."power") OVER "w" AS "power_min", first_value(sp0."date") OVER "w" AS "start_date", last_value(sp0."date") OVER "w" AS "end_date", first_value(sp0."odometer") OVER "w" AS "start_km", last_value(sp0."odometer") OVER "w" AS "end_km", last_value(sp0."odometer") OVER "w" - first_value(sp0."odometer") OVER "w" AS "distance", round(extract(epoch from (last_value(sp0."date") OVER "w" - first_value(sp0."date") OVER "w")) / 60)::integer AS "duration_min", -1 AS "start_ideal_range_km", -1 AS "end_ideal_range_km", -1 AS "start_rated_range_km", -1 AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (sp0."drive_id" = $1) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s0 INNER JOIN (SELECT first_value(sp0."ideal_battery_range_km") OVER "w" AS "start_ideal_range_km", last_value(sp0."ideal_battery_range_km") OVER "w" AS "end_ideal_range_km", first_value(sp0."rated_battery_range_km") OVER "w" AS "start_rated_range_km", last_value(sp0."rated_battery_range_km") OVER "w" AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (((sp0."drive_id" = $2) AND NOT (sp0."ideal_battery_range_km" IS NULL)) AND NOT (sp0."odometer" IS NULL)) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s1 ON TRUE database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | 2022-02-27 03:51:02.992 UTC [40] ERROR: canceling statement due to user request database_1 | 2022-02-27 03:51:02.992 UTC [40] STATEMENT: SELECT s0."count", s0."start_position_id", s0."end_position_id", s0."outside_temp_avg", s0."inside_temp_avg", s0."speed_max", s0."power_max", s0."power_min", s0."start_date", s0."end_date", s0."start_km", s0."end_km", s0."distance", s0."duration_min", s0."start_ideal_range_km", s0."end_ideal_range_km", s0."start_rated_range_km", s0."end_rated_range_km", s1."start_ideal_range_km", s1."end_ideal_range_km", s1."start_rated_range_km", s1."end_rated_range_km" FROM (SELECT count() OVER "w" AS "count", first_value(sp0."id") OVER "w" AS "start_position_id", last_value(sp0."id") OVER "w" AS "end_position_id", avg(sp0."outside_temp") OVER "w" AS "outside_temp_avg", avg(sp0."inside_temp") OVER "w" AS "inside_temp_avg", max(sp0."speed") OVER "w" AS "speed_max", max(sp0."power") OVER "w" AS "power_max", min(sp0."power") OVER "w" AS "power_min", first_value(sp0."date") OVER "w" AS "start_date", last_value(sp0."date") OVER "w" AS "end_date", first_value(sp0."odometer") OVER "w" AS "start_km", last_value(sp0."odometer") OVER "w" AS "end_km", last_value(sp0."odometer") OVER "w" - first_value(sp0."odometer") OVER "w" AS "distance", round(extract(epoch from (last_value(sp0."date") OVER "w" - first_value(sp0."date") OVER "w")) / 60)::integer AS "duration_min", -1 AS "start_ideal_range_km", -1 AS "end_ideal_range_km", -1 AS "start_rated_range_km", -1 AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (sp0."drive_id" = $1) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s0 INNER JOIN (SELECT first_value(sp0."ideal_battery_range_km") OVER "w" AS "start_ideal_range_km", last_value(sp0."ideal_battery_range_km") OVER "w" AS "end_ideal_range_km", first_value(sp0."rated_battery_range_km") OVER "w" AS "start_rated_range_km", last_value(sp0."rated_battery_range_km") OVER "w" AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (((sp0."drive_id" = $2) AND NOT (sp0."ideal_battery_range_km" IS NULL)) AND NOT (sp0."odometer" IS NULL)) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s1 ON TRUE database_1 | 2022-02-27 04:01:32.858 UTC [469] ERROR: canceling statement due to user request database_1 | 2022-02-27 04:01:32.858 UTC [469] STATEMENT: SELECT s0."count", s0."start_position_id", s0."end_position_id", s0."outside_temp_avg", s0."inside_temp_avg", s0."speed_max", s0."power_max", s0."power_min", s0."start_date", s0."end_date", s0."start_km", s0."end_km", s0."distance", s0."duration_min", s0."start_ideal_range_km", s0."end_ideal_range_km", s0."start_rated_range_km", s0."end_rated_range_km", s1."start_ideal_range_km", s1."end_ideal_range_km", s1."start_rated_range_km", s1."end_rated_range_km" FROM (SELECT count() OVER "w" AS "count", first_value(sp0."id") OVER "w" AS "start_position_id", last_value(sp0."id") OVER "w" AS "end_position_id", avg(sp0."outside_temp") OVER "w" AS "outside_temp_avg", avg(sp0."inside_temp") OVER "w" AS "inside_temp_avg", max(sp0."speed") OVER "w" AS "speed_max", max(sp0."power") OVER "w" AS "power_max", min(sp0."power") OVER "w" AS "power_min", first_value(sp0."date") OVER "w" AS "start_date", last_value(sp0."date") OVER "w" AS "end_date", first_value(sp0."odometer") OVER "w" AS "start_km", last_value(sp0."odometer") OVER "w" AS "end_km", last_value(sp0."odometer") OVER "w" - first_value(sp0."odometer") OVER "w" AS "distance", round(extract(epoch from (last_value(sp0."date") OVER "w" - first_value(sp0."date") OVER "w")) / 60)::integer AS "duration_min", -1 AS "start_ideal_range_km", -1 AS "end_ideal_range_km", -1 AS "start_rated_range_km", -1 AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (sp0."drive_id" = $1) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s0 INNER JOIN (SELECT first_value(sp0."ideal_battery_range_km") OVER "w" AS "start_ideal_range_km", last_value(sp0."ideal_battery_range_km") OVER "w" AS "end_ideal_range_km", first_value(sp0."rated_battery_range_km") OVER "w" AS "start_rated_range_km", last_value(sp0."rated_battery_range_km") OVER "w" AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (((sp0."drive_id" = $2) AND NOT (sp0."ideal_battery_range_km" IS NULL)) AND NOT (sp0."odometer" IS NULL)) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s1 ON TRUE database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihfORC error: database_1 | No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | 2022-02-27 17:40:51.481 UTC [43] ERROR: canceling statement due to user request database_1 | 2022-02-27 17:40:51.481 UTC [43] STATEMENT: SELECT s0."count", s0."start_position_id", s0."end_position_id", s0."outside_temp_avg", s0."inside_temp_avg", s0."speed_max", s0."power_max", s0."power_min", s0."start_date", s0."end_date", s0."start_km", s0."end_km", s0."distance", s0."duration_min", s0."start_ideal_range_km", s0."end_ideal_range_km", s0."start_rated_range_km", s0."end_rated_range_km", s1."start_ideal_range_km", s1."end_ideal_range_km", s1."start_rated_range_km", s1."end_rated_range_km" FROM (SELECT count() OVER "w" AS "count", first_value(sp0."id") OVER "w" AS "start_position_id", last_value(sp0."id") OVER "w" AS "end_position_id", avg(sp0."outside_temp") OVER "w" AS "outside_temp_avg", avg(sp0."inside_temp") OVER "w" AS "inside_temp_avg", max(sp0."speed") OVER "w" AS "speed_max", max(sp0."power") OVER "w" AS "power_max", min(sp0."power") OVER "w" AS "power_min", first_value(sp0."date") OVER "w" AS "start_date", last_value(sp0."date") OVER "w" AS "end_date", first_value(sp0."odometer") OVER "w" AS "start_km", last_value(sp0."odometer") OVER "w" AS "end_km", last_value(sp0."odometer") OVER "w" - first_value(sp0."odometer") OVER "w" AS "distance", round(extract(epoch from (last_value(sp0."date") OVER "w" - first_value(sp0."date") OVER "w")) / 60)::integer AS "duration_min", -1 AS "start_ideal_range_km", -1 AS "end_ideal_range_km", -1 AS "start_rated_range_km", -1 AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (sp0."drive_id" = $1) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s0 INNER JOIN (SELECT first_value(sp0."ideal_battery_range_km") OVER "w" AS "start_ideal_range_km", last_value(sp0."ideal_battery_range_km") OVER "w" AS "end_ideal_range_km", first_value(sp0."rated_battery_range_km") OVER "w" AS "start_rated_range_km", last_value(sp0."rated_battery_range_km") OVER "w" AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (((sp0."drive_id" = $2) AND NOT (sp0."ideal_battery_range_km" IS NULL)) AND NOT (sp0."odometer" IS NULL)) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s1 ON TRUE pi@piaware:~ $

cwanja commented 2 years ago

It seems to match this issue #2450 and has a commit https://github.com/adriankumpf/teslamate/commit/b209d348f8cebca9dea480537bbd45f97af1d1ae that should resolve the issue whenever it is released to production.

cwanja commented 2 years ago

Does this happen on 1.26.X? Looks like you are running 1.27-dev and the first warning says teslamate_1 | 2022-02-26 10:04:46.210 [warning] Could not decrypt API tokens!

rmyadsk commented 2 years ago

Does this happen on 1.26.X? Looks like you are running 1.27-dev and the first warning says teslamate_1 | 2022-02-26 10:04:46.210 [warning] Could not decrypt API tokens!

I moved from teslamate/teslamate:latest to teslamate/teslamate:edge hoping for a fix for this issue. Upon entering edge I configured an ENCRYPTION_KEY and then entered my tokens; no errors were apparent. Might going back to 1.26 help, and how might I do this?

rmyadsk commented 2 years ago

Well, this sure isn't good. Declaring teslamate/telsmate:1.26.0 results in the following:

pi@piaware:~ $ docker-compose logs teslamate Attaching to pi_teslamate_1 teslamate_1 | 2022-02-27 19:53:58.139 [info] Migrations already up teslamate_1 | 2022-02-27 19:54:05.108 [info] System Info: Erlang/OTP 24 (emu) teslamate_1 | 2022-02-27 19:54:05.108 [info] Version: 1.26.0 teslamate_1 | 2022-02-27 19:54:05.275 [warning] Token refresh failed: %TeslaApi.Error{ teslamate_1 | env: nil, teslamate_1 | message: {Tesla.Middleware.JSON, :encode, teslamate_1 | %Jason.EncodeError{ teslamate_1 | message: "invalid byte 0xA9 in <<1, 10, 65, 69, 83, 46, 71, 67, 77, 46, 86, 49, 169, 112, 70, 230, 184, 67, 233, 56, 170, 4, 218, 71, 159, 153, 149, 166, 65, 229, 72, 61, 23, 71, 128, 193, 157, 209, 113, 206, 255, 126, 89, 84, 234, 34, 132, 242, 35, 201, ...>>" teslamate_1 | }}, teslamate_1 | reason: :token_refresh teslamate_1 | } teslamate_1 | 2022-02-27 19:54:05.275 [info] Scheduling token refresh in 7 min teslamate_1 | 2022-02-27 19:54:05.341 [info] Running TeslaMateWeb.Endpoint with cowboy 2.9.0 at :::4000 (http) teslamate_1 | 2022-02-27 19:54:05.359 [info] Access TeslaMateWeb.Endpoint at http://teslamate.oscarfish.com teslamate_1 | 2022-02-27 19:54:05.848 [error] GET https://owner-api.teslamotors.com/api/1/vehicles -> error: "invalid value for header (only printable ASCII characters are allowed) \"authorization\": <<66, 101, 97, 114, 101, 114, 32, 1, 10, 65, 69, 83, 46, 71, 67, 77, 46, 86, 49, 107, 222, 216, 56, 195, 198, 103, 52, 132, 22, 71, 233, 248, 36, 44, 85, 248, 160, 195, 244, 33, 106, 135, 186, 123, 164, 221, 232, 160, 128, 169, ...>>" (480.351 ms) teslamate_1 | 2022-02-27 19:54:05.848 [warning] TeslaApi.Error / invalid value for header (only printable ASCII characters are allowed) "authorization": <<66, 101, 97, 114, 101, 114, 32, 1, 10, 65, 69, 83, 46, 71, 67, 77, 46, 86, 49, 107, 222, 216, 56, 195, 198, 103, 52, 132, 22, 71, 233, 248, 36, 44, 85, 248, 160, 195, 244, 33, 106, 135, 186, 123, 164, 221, 232, 160, 128, 169, ...>> teslamate_1 | 2022-02-27 19:54:05.849 [warning] Could not get vehicles: :unknown teslamate_1 | 2022-02-27 19:54:05.900 [warning] Using fallback vehicles: teslamate_1 | teslamate_1 | [ teslamate_1 | %TeslaApi.Vehicle{ teslamate_1 | api_version: nil, teslamate_1 | backseat_token: nil, teslamate_1 | backseat_token_updated_at: nil, teslamate_1 | calendar_enabled: nil, teslamate_1 | charge_state: nil, teslamate_1 | climate_state: nil, teslamate_1 | color: nil, teslamate_1 | display_name: "Baby Blue", teslamate_1 | drive_state: nil, teslamate_1 | gui_settings: nil, teslamate_1 | id: 1492932132939306, teslamate_1 | in_service: false, teslamate_1 | option_codes: [], teslamate_1 | state: "unknown", teslamate_1 | tokens: [], teslamate_1 | vehicle_config: nil, teslamate_1 | vehicle_id: 1038433579, teslamate_1 | vehicle_state: nil, teslamate_1 | vin: "5YJ3E1EA7KF299285" teslamate_1 | }, teslamate_1 | %TeslaApi.Vehicle{ teslamate_1 | api_version: nil, teslamate_1 | backseat_token: nil, teslamate_1 | backseat_token_updated_at: nil, teslamate_1 | calendar_enabled: nil, teslamate_1 | charge_state: nil, teslamate_1 | climate_state: nil, teslamate_1 | color: nil, teslamate_1 | display_name: "Don't Panic", teslamate_1 | drive_state: nil, teslamate_1 | gui_settings: nil, teslamate_1 | id: 1492932493538049, teslamate_1 | in_service: false, teslamate_1 | option_codes: [], teslamate_1 | state: "unknown", teslamate_1 | tokens: [], teslamate_1 | vehicle_config: nil, teslamate_1 | vehicle_id: 174286848, teslamate_1 | vehicle_state: nil, teslamate_1 | vin: "5YJ3E1EA2JF046440" teslamate_1 | } teslamate_1 | ] teslamate_1 | 2022-02-27 19:54:05.900 [info] Starting logger for 'Baby Blue' teslamate_1 | 2022-02-27 19:54:05.922 [info] Starting logger for 'Don't Panic' teslamate_1 | 2022-02-27 19:54:05.968 [error] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306 -> error: "invalid value for header (only printable ASCII characters are allowed) \"authorization\": <<66, 101, 97, 114, 101, 114, 32, 1, 10, 65, 69, 83, 46, 71, 67, 77, 46, 86, 49, 107, 222, 216, 56, 195, 198, 103, 52, 132, 22, 71, 233, 248, 36, 44, 85, 248, 160, 195, 244, 33, 106, 135, 186, 123, 164, 221, 232, 160, 128, 169, ...>>" (1.661 ms) teslamate_1 | 2022-02-27 19:54:05.968 [warning] TeslaApi.Error / invalid value for header (only printable ASCII characters are allowed) "authorization": <<66, 101, 97, 114, 101, 114, 32, 1, 10, 65, 69, 83, 46, 71, 67, 77, 46, 86, 49, 107, 222, 216, 56, 195, 198, 103, 52, 132, 22, 71, 233, 248, 36, 44, 85, 248, 160, 195, 244, 33, 106, 135, 186, 123, 164, 221, 232, 160, 128, 169, ...>> teslamate_1 | 2022-02-27 19:54:05.969 car_id=1 [error] Error / :unknown teslamate_1 | 2022-02-27 19:54:05.988 [error] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049 -> error: "invalid value for header (only printable ASCII characters are allowed) \"authorization\": <<66, 101, 97, 114, 101, 114, 32, 1, 10, 65, 69, 83, 46, 71, 67, 77, 46, 86, 49, 107, 222, 216, 56, 195, 198, 103, 52, 132, 22, 71, 233, 248, 36, 44, 85, 248, 160, 195, 244, 33, 106, 135, 186, 123, 164, 221, 232, 160, 128, 169, ...>>" (2.833 ms) teslamate_1 | 2022-02-27 19:54:05.988 [warning] TeslaApi.Error / invalid value for header (only printable ASCII characters are allowed) "authorization": <<66, 101, 97, 114, 101, 114, 32, 1, 10, 65, 69, 83, 46, 71, 67, 77, 46, 86, 49, 107, 222, 216, 56, 195, 198, 103, 52, 132, 22, 71, 233, 248, 36, 44, 85, 248, 160, 195, 244, 33, 106, 135, 186, 123, 164, 221, 232, 160, 128, 169, ...>> teslamate_1 | 2022-02-27 19:54:05.989 car_id=2 [error] Error / :unknown teslamate_1 | 2022-02-27 19:54:18.823 [info] GET / teslamate_1 | 2022-02-27 19:54:18.934 [info] Sent 200 in 110ms teslamate_1 | 2022-02-27 19:54:29.835 [info] GET / teslamate_1 | 2022-02-27 19:54:29.848 [info] Sent 200 in 12ms teslamate_1 | 2022-02-27 19:54:36.067 [error] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306 -> error: "invalid value for header (only printable ASCII characters are allowed) \"authorization\": <<66, 101, 97, 114, 101, 114, 32, 1, 10, 65, 69, 83, 46, 71, 67, 77, 46, 86, 49, 107, 222, 216, 56, 195, 198, 103, 52, 132, 22, 71, 233, 248, 36, 44, 85, 248, 160, 195, 244, 33, 106, 135, 186, 123, 164, 221, 232, 160, 128, 169, ...>>" (1.034 ms) teslamate_1 | 2022-02-27 19:54:36.067 [warning] TeslaApi.Error / invalid value for header (only printable ASCII characters are allowed) "authorization": <<66, 101, 97, 114, 101, 114, 32, 1, 10, 65, 69, 83, 46, 71, 67, 77, 46, 86, 49, 107, 222, 216, 56, 195, 198, 103, 52, 132, 22, 71, 233, 248, 36, 44, 85, 248, 160, 195, 244, 33, 106, 135, 186, 123, 164, 221, 232, 160, 128, 169, ...>> teslamate_1 | 2022-02-27 19:54:36.067 car_id=1 [error] Error / :unknown teslamate_1 | 2022-02-27 19:54:36.073 [error] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049 -> error: "invalid value for header (only printable ASCII characters are allowed) \"authorization\": <<66, 101, 97, 114, 101, 114, 32, 1, 10, 65, 69, 83, 46, 71, 67, 77, 46, 86, 49, 107, 222, 216, 56, 195, 198, 103, 52, 132, 22, 71, 233, 248, 36, 44, 85, 248, 160, 195, 244, 33, 106, 135, 186, 123, 164, 221, 232, 160, 128, 169, ...>>" (1.692 ms) teslamate_1 | 2022-02-27 19:54:36.073 [warning] TeslaApi.Error / invalid value for header (only printable ASCII characters are allowed) "authorization": <<66, 101, 97, 114, 101, 114, 32, 1, 10, 65, 69, 83, 46, 71, 67, 77, 46, 86, 49, 107, 222, 216, 56, 195, 198, 103, 52, 132, 22, 71, 233, 248, 36, 44, 85, 248, 160, 195, 244, 33, 106, 135, 186, 123, 164, 221, 232, 160, 128, 169, ...>> teslamate_1 | 2022-02-27 19:54:36.073 car_id=2 [error] Error / :unknown pi@piaware:~ $

cwanja commented 2 years ago

Because you ran the dev / edge branch, it seems your encrypted API tokens are not able to unencrypted backwards. Drop the API tokens from the database and you will have to re-login.

Checking the other issue I linked to, they were running 1.26 and 1.26.1. So it is still in lower versions. Assuming they are the same (or similar issues).

rmyadsk commented 2 years ago

Drop the API tokens from the database and you will have to re-login.

Copy; this worked. Now on 1.26.0 and "Signed in successfully".

Checking the other issue I linked to, they were running 1.26 and 1.26.1. So it is still in lower versions. Assuming they are the same (or similar issues).

I'll do some driving tomorrow and see if the drives show up.

rmyadsk commented 2 years ago

Unfortunately the behavior is the same in 1.26.0; no new drives are present. Just moved to 1.26.1 but suspect I'll have the same result.

rmyadsk commented 2 years ago

Same behavior in 1.26.1. I'm back to teslamate/teslamate:latest for the time being. All but two drives (one each between two vehicles) since the beginning of February are missing.

cwanja commented 2 years ago

Same behavior in 1.26.1. I'm back to teslamate/teslamate:latest for the time being. All but two drives (one each between two vehicles) since the beginning of February are missing.

My assumption is the commit to fix the refresh token issues should resolve this. Though it does not get your data back. Hopefully we see a push to release this weekend.

rmyadsk commented 2 years ago

My assumption is the commit to fix the refresh token issues should resolve this. Though it does not get your data back. Hopefully we see a push to release this weekend.

Thanks, I'll look for new pulls periodically and report back with changes.

rmyadsk commented 2 years ago

Well, I pulled via teslamate/teslamate:latest this evening, and I'd venture that things may have gotten worse?

Not sure about the "No callback manager available" errors, but:

uname -a: Linux piaware 5.10.63-v7+ #1496 SMP Wed Dec 1 15:58:11 GMT 2021 armv7l GNU/Linux /etc/os-release: PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

Logs from database:

pi@piaware:~ $ docker-compose logs database
Attaching to pi_database_1
database_1   | 
database_1   | PostgreSQL Database directory appears to contain a database; Skipping initialization
database_1   | 
database_1   | 2022-03-18 21:49:33.573 UTC [1] LOG:  starting PostgreSQL 12.10 (Debian 12.10-1.pgdg110+1) on arm-unknown-linux-gnueabihf, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 32-bit
database_1   | 2022-03-18 21:49:33.600 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
database_1   | 2022-03-18 21:49:33.600 UTC [1] LOG:  listening on IPv6 address "::", port 5432
database_1   | 2022-03-18 21:49:33.682 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
database_1   | 2022-03-18 21:49:33.868 UTC [27] LOG:  database system was shut down at 2022-03-18 21:49:06 UTC
database_1   | 2022-03-18 21:49:34.129 UTC [1] LOG:  database system is ready to accept connections
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | 2022-03-18 21:50:56.375 UTC [39] ERROR:  canceling statement due to user request
database_1   | 2022-03-18 21:50:56.375 UTC [39] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:50:56.422 UTC [47] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:50:56.422 UTC [47] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:50:56.422 UTC [48] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:50:56.422 UTC [48] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:50:58.120 UTC [1] LOG:  background worker "parallel worker" (PID 48) exited with exit code 1
database_1   | 2022-03-18 21:50:58.127 UTC [1] LOG:  background worker "parallel worker" (PID 47) exited with exit code 1
database_1   | 2022-03-18 21:50:58.138 UTC [39] LOG:  could not send data to client: Broken pipe
database_1   | 2022-03-18 21:50:58.138 UTC [39] FATAL:  connection to client lost
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: ORC error: No callback manager available for armv7-unknown-linux-gnueabihfNo callback manager available for armv7-unknown-linux-gnueabihf
database_1   | 
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | 2022-03-18 21:51:56.401 UTC [42] ERROR:  canceling statement due to user request
database_1   | 2022-03-18 21:51:56.401 UTC [42] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:51:56.403 UTC [53] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:51:56.403 UTC [53] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:51:56.403 UTC [52] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:51:56.403 UTC [52] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:51:57.486 UTC [1] LOG:  background worker "parallel worker" (PID 52) exited with exit code 1
database_1   | 2022-03-18 21:51:57.486 UTC [1] LOG:  background worker "parallel worker" (PID 53) exited with exit code 1
database_1   | 2022-03-18 21:51:57.488 UTC [42] LOG:  could not send data to client: Broken pipe
database_1   | 2022-03-18 21:51:57.488 UTC [42] FATAL:  connection to client lost
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | 2022-03-18 21:52:56.446 UTC [40] ERROR:  canceling statement due to user request
database_1   | 2022-03-18 21:52:56.446 UTC [40] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:52:56.465 UTC [58] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:52:56.465 UTC [58] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:52:56.465 UTC [57] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:52:56.465 UTC [57] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:52:57.650 UTC [1] LOG:  background worker "parallel worker" (PID 57) exited with exit code 1
database_1   | 2022-03-18 21:52:57.653 UTC [1] LOG:  background worker "parallel worker" (PID 58) exited with exit code 1
database_1   | 2022-03-18 21:52:57.656 UTC [40] LOG:  could not send data to client: Broken pipe
database_1   | 2022-03-18 21:52:57.656 UTC [40] FATAL:  connection to client lost
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | 2022-03-18 21:53:56.537 UTC [43] ERROR:  canceling statement due to user request
database_1   | 2022-03-18 21:53:56.537 UTC [43] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:53:56.542 UTC [63] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:53:56.542 UTC [63] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:53:56.546 UTC [62] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:53:56.546 UTC [62] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:53:58.079 UTC [1] LOG:  background worker "parallel worker" (PID 62) exited with exit code 1
database_1   | 2022-03-18 21:53:58.088 UTC [1] LOG:  background worker "parallel worker" (PID 63) exited with exit code 1
database_1   | 2022-03-18 21:53:58.091 UTC [43] LOG:  could not send data to client: Broken pipe
database_1   | 2022-03-18 21:53:58.091 UTC [43] FATAL:  connection to client lost
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | 2022-03-18 21:54:56.779 UTC [37] ERROR:  canceling statement due to user request
database_1   | 2022-03-18 21:54:56.779 UTC [37] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:54:56.815 UTC [72] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:54:56.815 UTC [72] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:54:56.816 UTC [73] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:54:56.816 UTC [73] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:54:58.738 UTC [1] LOG:  background worker "parallel worker" (PID 72) exited with exit code 1
database_1   | 2022-03-18 21:54:58.740 UTC [1] LOG:  background worker "parallel worker" (PID 73) exited with exit code 1
database_1   | 2022-03-18 21:54:58.754 UTC [37] LOG:  could not send data to client: Broken pipe
database_1   | 2022-03-18 21:54:58.755 UTC [37] FATAL:  connection to client lost
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | 2022-03-18 21:55:56.818 UTC [41] ERROR:  canceling statement due to user request
database_1   | 2022-03-18 21:55:56.818 UTC [41] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:55:56.820 UTC [78] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:55:56.820 UTC [78] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:55:56.820 UTC [77] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:55:56.820 UTC [77] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:55:58.724 UTC [1] LOG:  background worker "parallel worker" (PID 77) exited with exit code 1
database_1   | 2022-03-18 21:55:58.726 UTC [1] LOG:  background worker "parallel worker" (PID 78) exited with exit code 1
database_1   | 2022-03-18 21:55:58.728 UTC [41] LOG:  could not send data to client: Broken pipe
database_1   | 2022-03-18 21:55:58.728 UTC [41] FATAL:  connection to client lost
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: ORC error: No callback manager available for armv7-unknown-linux-gnueabihfNo callback manager available for armv7-unknown-linux-gnueabihf
database_1   | 
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | 2022-03-18 21:56:56.747 UTC [45] ERROR:  canceling statement due to user request
database_1   | 2022-03-18 21:56:56.747 UTC [45] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:56:56.767 UTC [82] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:56:56.767 UTC [82] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:56:56.767 UTC [83] FATAL:  terminating connection due to administrator command
database_1   | 2022-03-18 21:56:56.767 UTC [83] STATEMENT:  SELECT s0."drive_id" FROM (SELECT sp0."drive_id" AS "drive_id", count(*) FILTER (WHERE NOT (sp0."odometer" IS NULL) AND (sp0."ideal_battery_range_km" IS NULL)) AS "streamed_count" FROM "positions" AS sp0 WHERE (NOT (sp0."drive_id" IS NULL)) GROUP BY sp0."drive_id") AS s0 WHERE (s0."streamed_count" = 0)
database_1   | 2022-03-18 21:56:57.968 UTC [1] LOG:  background worker "parallel worker" (PID 82) exited with exit code 1
database_1   | 2022-03-18 21:56:57.968 UTC [1] LOG:  background worker "parallel worker" (PID 83) exited with exit code 1
database_1   | 2022-03-18 21:56:57.970 UTC [45] LOG:  could not send data to client: Broken pipe
database_1   | 2022-03-18 21:56:57.970 UTC [45] FATAL:  connection to client lost
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: ORC error: No callback manager available for armv7-unknown-linux-gnueabihfNo callback manager available for armv7-unknown-linux-gnueabihf
database_1   | 
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf
database_1   | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf

Logs from Teslamate:


pi@piaware:~ $ docker-compose logs teslamate
Attaching to pi_teslamate_1
teslamate_1  | 2022-03-18 17:49:44.954 [info] Migrations already up
teslamate_1  | 2022-03-18 17:49:55.272 [info] System Info: Erlang/OTP 24 (emu)
teslamate_1  | 2022-03-18 17:49:55.272 [info] Version: 1.26.1
teslamate_1  | 2022-03-18 17:49:56.176 [info] POST https://auth.tesla.com/oauth2/v3/token -> 200 (753.278 ms)
teslamate_1  | 2022-03-18 17:49:56.177 [info] Refreshed api tokens
teslamate_1  | 2022-03-18 17:49:56.193 [info] Scheduling token refresh in 6 h
teslamate_1  | 2022-03-18 17:49:56.204 [info] Running TeslaMateWeb.Endpoint with cowboy 2.9.0 at :::4000 (http)
teslamate_1  | 2022-03-18 17:49:56.212 [info] Access TeslaMateWeb.Endpoint at http://teslamate.oscarfish.com
teslamate_1  | 2022-03-18 17:49:57.300 [warning] GET https://owner-api.teslamotors.com/api/1/vehicles -> 503 (1084.035 ms)
teslamate_1  | 2022-03-18 17:49:57.301 [warning] TeslaApi.Error / "upstream connect error or disconnect/reset before headers. reset reason: connection failure"
teslamate_1  | 2022-03-18 17:49:57.301 [warning] Could not get vehicles: :unknown
teslamate_1  | 2022-03-18 17:49:57.366 [warning] Using fallback vehicles:
teslamate_1  | 
teslamate_1  | [
teslamate_1  |   %TeslaApi.Vehicle{
teslamate_1  |     api_version: nil,
teslamate_1  |     backseat_token: nil,
teslamate_1  |     backseat_token_updated_at: nil,
teslamate_1  |     calendar_enabled: nil,
teslamate_1  |     charge_state: nil,
teslamate_1  |     climate_state: nil,
teslamate_1  |     color: nil,
teslamate_1  |     display_name: "Baby Blue",
teslamate_1  |     drive_state: nil,
teslamate_1  |     gui_settings: nil,
teslamate_1  |     id: 1492932132939306,
teslamate_1  |     in_service: false,
teslamate_1  |     option_codes: [],
teslamate_1  |     state: "unknown",
teslamate_1  |     tokens: [],
teslamate_1  |     vehicle_config: nil,
teslamate_1  |     vehicle_id: 1038433579,
teslamate_1  |     vehicle_state: nil,
teslamate_1  |     vin: "5YJ3E1EA7KFxxxxxx"
teslamate_1  |   },
teslamate_1  |   %TeslaApi.Vehicle{
teslamate_1  |     api_version: nil,
teslamate_1  |     backseat_token: nil,
teslamate_1  |     backseat_token_updated_at: nil,
teslamate_1  |     calendar_enabled: nil,
teslamate_1  |     charge_state: nil,
teslamate_1  |     climate_state: nil,
teslamate_1  |     color: nil,
teslamate_1  |     display_name: "Don't Panic",
teslamate_1  |     drive_state: nil,
teslamate_1  |     gui_settings: nil,
teslamate_1  |     id: 1492932493538049,
teslamate_1  |     in_service: false,
teslamate_1  |     option_codes: [],
teslamate_1  |     state: "unknown",
teslamate_1  |     tokens: [],
teslamate_1  |     vehicle_config: nil,
teslamate_1  |     vehicle_id: 174286848,
teslamate_1  |     vehicle_state: nil,
teslamate_1  |     vin: "5YJ3E1EA2JFxxxxxx"
teslamate_1  |   }
teslamate_1  | ]
teslamate_1  | 2022-03-18 17:49:57.366 [info] Starting logger for 'Baby Blue'
teslamate_1  | 2022-03-18 17:49:57.399 [info] Starting logger for 'Don't Panic'
teslamate_1  | 2022-03-18 17:49:57.948 car_id=1 [info] Start / :asleep
teslamate_1  | 2022-03-18 17:49:59.505 car_id=2 [info] Start / :asleep
teslamate_1  | 2022-03-18 17:49:59.538 [info] tzdata release in place is from a file last modified Fri, 22 Oct 2021 02:20:47 GMT. Release file on server was last modified Wed, 16 Mar 2022 13:36:02 GMT.
teslamate_1  | 2022-03-18 17:50:15.648 [info] GET /
teslamate_1  | 2022-03-18 17:50:15.713 [info] Sent 200 in 65ms
teslamate_1  | 2022-03-18 17:50:20.070 [info] Tzdata has updated the release from 2021e to 2022a
teslamate_1  | 2022-03-18 17:50:37.032 [info] GET /
teslamate_1  | 2022-03-18 17:50:37.091 [info] Sent 200 in 58ms
teslamate_1  | 2022-03-18 17:50:56.334 [error] Postgrex.Protocol (#PID<0.2323.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2455.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.2455.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2996: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2042: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:1934: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1428: DBConnection.run/6
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  | 
teslamate_1  | 2022-03-18 17:50:56.340 [error] GenStateMachine TeslaMate.Terrain terminating
teslamate_1  | ** (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_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/log.ex:177: TeslaMate.Log.get_positions_without_elevation/2
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/terrain.ex:84: TeslaMate.Terrain.handle_event/4
teslamate_1  |     (stdlib 3.17) gen_statem.erl:1205: :gen_statem.loop_state_callback/11
teslamate_1  |     (stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
teslamate_1  | 2022-03-18 17:51:09.358 car_id=1 [info] Start / :online
teslamate_1  | 2022-03-18 17:51:09.782 car_id=1 [info] Connecting ...
teslamate_1  | 2022-03-18 17:51:36.846 [error] Vehicle Error: Vehicle is offline
teslamate_1  | 2022-03-18 17:51:40.147 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (298.098 ms)
teslamate_1  | 2022-03-18 17:51:40.890 car_id=2 [info] Start / :online
teslamate_1  | 2022-03-18 17:51:41.432 car_id=2 [info] Connecting ...
teslamate_1  | 2022-03-18 17:51:50.532 car_id=1 [info] Start / :offline
teslamate_1  | 2022-03-18 17:51:50.588 car_id=1 [info] Disconnecting ...
teslamate_1  | 2022-03-18 17:51:56.361 [error] Postgrex.Protocol (#PID<0.2320.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2519.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.2519.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2996: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2042: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:1934: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1428: DBConnection.run/6
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  | 
teslamate_1  | 2022-03-18 17:51:56.363 [error] GenStateMachine TeslaMate.Terrain terminating
teslamate_1  | ** (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_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/log.ex:177: TeslaMate.Log.get_positions_without_elevation/2
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/terrain.ex:84: TeslaMate.Terrain.handle_event/4
teslamate_1  |     (stdlib 3.17) gen_statem.erl:1205: :gen_statem.loop_state_callback/11
teslamate_1  |     (stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
teslamate_1  | 2022-03-18 17:52:31.457 car_id=1 [info] Start / :online
teslamate_1  | 2022-03-18 17:52:33.198 car_id=1 [info] Connecting ...
teslamate_1  | 2022-03-18 17:52:56.394 [error] Postgrex.Protocol (#PID<0.2322.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2536.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.2536.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2996: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2042: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:1934: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1428: DBConnection.run/6
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  | 
teslamate_1  | 2022-03-18 17:52:56.394 [error] GenStateMachine TeslaMate.Terrain terminating
teslamate_1  | ** (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_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/log.ex:177: TeslaMate.Log.get_positions_without_elevation/2
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/terrain.ex:84: TeslaMate.Terrain.handle_event/4
teslamate_1  |     (stdlib 3.17) gen_statem.erl:1205: :gen_statem.loop_state_callback/11
teslamate_1  |     (stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
teslamate_1  | 2022-03-18 17:53:56.478 [error] Postgrex.Protocol (#PID<0.2318.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2546.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.2546.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2996: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2042: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:1934: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1428: DBConnection.run/6
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  | 
teslamate_1  | 2022-03-18 17:53:56.505 [error] GenStateMachine TeslaMate.Terrain terminating
teslamate_1  | ** (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_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/log.ex:177: TeslaMate.Log.get_positions_without_elevation/2
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/terrain.ex:84: TeslaMate.Terrain.handle_event/4
teslamate_1  |     (stdlib 3.17) gen_statem.erl:1205: :gen_statem.loop_state_callback/11
teslamate_1  |     (stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
teslamate_1  | 2022-03-18 17:54:44.904 car_id=2 [info] Suspending logging
teslamate_1  | 2022-03-18 17:54:56.607 [error] Postgrex.Protocol (#PID<0.2313.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2552.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.2552.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2996: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2042: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:1934: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1428: DBConnection.run/6
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  | 
teslamate_1  | 2022-03-18 17:54:56.629 [error] GenStateMachine TeslaMate.Terrain terminating
teslamate_1  | ** (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_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/log.ex:177: TeslaMate.Log.get_positions_without_elevation/2
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/terrain.ex:84: TeslaMate.Terrain.handle_event/4
teslamate_1  |     (stdlib 3.17) gen_statem.erl:1205: :gen_statem.loop_state_callback/11
teslamate_1  |     (stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
teslamate_1  | 2022-03-18 17:55:36.328 car_id=1 [info] Suspending logging
teslamate_1  | 2022-03-18 17:55:36.922 car_id=1 [warning] Received stale stream data: %TeslaApi.Stream.Data{elevation: 15, est_heading: 338, est_lat: 39.141558, est_lng: -76.561703, est_range: 95, heading: 340, odometer: 25915.1, power: 0, range: 133, shift_state: nil, soc: 59, speed: nil, time: ~U[2022-03-18 21:55:35.478Z]}
teslamate_1  | 2022-03-18 17:55:56.661 [error] Postgrex.Protocol (#PID<0.2321.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2557.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.2557.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2996: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2042: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:1934: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1428: DBConnection.run/6
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  | 
teslamate_1  | 2022-03-18 17:55:56.663 [error] GenStateMachine TeslaMate.Terrain terminating
teslamate_1  | ** (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_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/log.ex:177: TeslaMate.Log.get_positions_without_elevation/2
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/terrain.ex:84: TeslaMate.Terrain.handle_event/4
teslamate_1  |     (stdlib 3.17) gen_statem.erl:1205: :gen_statem.loop_state_callback/11
teslamate_1  |     (stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
teslamate_1  | 2022-03-18 17:56:56.699 [error] Postgrex.Protocol (#PID<0.2317.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2564.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.2564.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2996: Postgrex.Protocol.msg_recv/4
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2042: Postgrex.Protocol.recv_bind/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:1934: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1428: DBConnection.run/6
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  | 
teslamate_1  | 2022-03-18 17:56:56.701 [error] GenStateMachine TeslaMate.Terrain terminating
teslamate_1  | ** (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_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/log.ex:177: TeslaMate.Log.get_positions_without_elevation/2
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/terrain.ex:84: TeslaMate.Terrain.handle_event/4
teslamate_1  |     (stdlib 3.17) gen_statem.erl:1205: :gen_statem.loop_state_callback/11
teslamate_1  |     (stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
teslamate_1  | 2022-03-18 17:57:26.258 car_id=1 [info] Fetching vehicle state ...
teslamate_1  | 2022-03-18 17:57:56.790 [error] Postgrex.Protocol (#PID<0.2321.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2585.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate_1  | 
teslamate_1  | #PID<0.2585.0> was at location:
teslamate_1  | 
teslamate_1  |     :prim_inet.recv0/3
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:3038: Postgrex.Protocol.rows_recv/5
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:2061: Postgrex.Protocol.recv_execute/5
teslamate_1  |     (postgrex 0.15.13) lib/postgrex/protocol.ex:1935: Postgrex.Protocol.bind_execute/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:1428: DBConnection.run/6
teslamate_1  |     (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5
teslamate_1  | 
teslamate_1  | 2022-03-18 17:57:56.834 [error] GenStateMachine TeslaMate.Terrain terminating
teslamate_1  | ** (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_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate_1  |     (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4
teslamate_1  |     (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/log.ex:177: TeslaMate.Log.get_positions_without_elevation/2
teslamate_1  |     (teslamate 1.26.1) lib/teslamate/terrain.ex:84: TeslaMate.Terrain.handle_event/4
teslamate_1  |     (stdlib 3.17) gen_statem.erl:1205: :gen_statem.loop_state_callback/11
teslamate_1  |     (stdlib 3.17) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
teslamate_1  | 2022-03-18 17:59:07.933 car_id=2 [info] Fetching vehicle state ...
teslamate_1  | 2022-03-18 17:59:08.688 [error] Vehicle Error: Vehicle is offline
teslamate_1  | 2022-03-18 17:59:18.495 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049 -> 408 (10498.229 ms)
teslamate_1  | 2022-03-18 17:59:18.496 [warning] TeslaApi.Error / %{"error" => "https://mothership-api-america.vn.teslamotors.com:443/vehicles/174286848 => operation_timedout with 10s timeout", "error_description" => "", "response" => nil}
teslamate_1  | 2022-03-18 17:59:18.497 car_id=2 [info] Unhandled fetch result: {:error, :unknown}
teslamate_1  | 2022-03-18 17:59:39.463 [error] Vehicle Error: Vehicle is offline
teslamate_1  | 2022-03-18 18:00:29.861 [error] Vehicle Error: Vehicle is offline
teslamate_1  | 2022-03-18 18:01:00.686 [error] Vehicle Error: Vehicle is offline
teslamate_1  | 2022-03-18 18:01:39.234 [error] Vehicle Error: Vehicle is offline
teslamate_1  | 2022-03-18 18:02:10.000 [error] Vehicle Error: Vehicle is offline
teslamate_1  | 2022-03-18 18:02:40.750 [error] Vehicle Error: Vehicle is offline
teslamate_1  | 2022-03-18 18:03:11.491 [error] Vehicle Error: Vehicle is offline
teslamate_1  | 2022-03-18 18:04:42.645 car_id=2 [info] Fetching vehicle state ...
teslamate_1  | 2022-03-18 18:04:43.086 car_id=2 [info] Start / :asleep
teslamate_1  | 2022-03-18 18:04:43.125 car_id=2 [info] Disconnecting ...
teslamate_1  | 2022-03-18 18:06:00.646 car_id=1 [info] Fetching vehicle state ...
teslamate_1  | 2022-03-18 18:06:00.831 car_id=1 [info] Start / :asleep
teslamate_1  | 2022-03-18 18:06:00.872 car_id=1 [info] Disconnecting ...
teslamate_1  | 2022-03-18 18:21:10.024 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049 -> 408 (10430.280 ms)
teslamate_1  | 2022-03-18 18:21:10.025 [warning] TeslaApi.Error / %{"error" => "https://mothership-api-america.vn.teslamotors.com:443/vehicles/174286848 => operation_timedout with 10s timeout", "error_description" => "", "response" => nil}
teslamate_1  | 2022-03-18 18:21:10.025 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-03-18 18:31:44.818 car_id=2 [info] Start / :online
teslamate_1  | 2022-03-18 18:31:44.982 car_id=2 [info] Connecting ...
teslamate_1  | 2022-03-18 18:34:48.118 car_id=2 [info] Suspending logging
teslamate_1  | 2022-03-18 18:44:27.598 car_id=2 [info] Fetching vehicle state ...
teslamate_1  | 2022-03-18 18:44:27.775 car_id=2 [info] Start / :asleep
teslamate_1  | 2022-03-18 18:44:27.796 car_id=2 [info] Disconnecting ...
teslamate_1  | 2022-03-18 19:33:45.820 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049 -> 408 (18266.912 ms)
teslamate_1  | 2022-03-18 19:33:45.820 [warning] TeslaApi.Error / %{"error" => "https://mothership-api-america.vn.teslamotors.com:443/vehicles/174286848 => operation_timedout with 10s timeout", "error_description" => "", "response" => nil}
teslamate_1  | 2022-03-18 19:33:45.821 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-03-18 19:37:46.681 car_id=1 [info] Start / :online
teslamate_1  | 2022-03-18 19:37:46.769 car_id=1 [info] Connecting ...
teslamate_1  | 2022-03-18 19:38:26.087 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306/vehicle_data -> 408 (9310.174 ms)
teslamate_1  | 2022-03-18 19:38:26.087 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-03-18 19:38:26.088 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-03-18 19:40:49.207 car_id=1 [info] Suspending logging
teslamate_1  | 2022-03-18 19:51:00.519 car_id=1 [info] Fetching vehicle state ...
teslamate_1  | 2022-03-18 19:51:00.778 car_id=1 [info] Start / :asleep
teslamate_1  | 2022-03-18 19:51:00.830 car_id=1 [info] Disconnecting ...
teslamate_1  | 2022-03-18 20:01:08.638 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306 -> 408 (24055.104 ms)
teslamate_1  | 2022-03-18 20:01:08.639 [warning] TeslaApi.Error / %{"error" => "https://mothership-api-america.vn.teslamotors.com:443/vehicles/1038433579 => operation_timedout with 10s timeout", "error_description" => "", "response" => nil}
teslamate_1  | 2022-03-18 20:01:08.641 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-03-18 20:51:10.979 [error] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306 -> error: "timeout" (35002.018 ms)
teslamate_1  | 2022-03-18 20:51:10.979 [warning] TeslaApi.Error / timeout
teslamate_1  | 2022-03-18 20:51:10.979 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-03-18 20:59:35.278 car_id=2 [info] Start / :online
teslamate_1  | 2022-03-18 20:59:35.363 car_id=2 [info] Connecting ...
teslamate_1  | 2022-03-18 21:00:06.430 [info] GET https://nominatim.openstreetmap.org/reverse -> 200 (476.316 ms)
teslamate_1  | 2022-03-18 21:00:06.532 car_id=2 [info] Charging / SOC: 33% / Home
teslamate_1  | 2022-03-18 21:00:06.532 car_id=2 [info] Disconnecting ...
teslamate_1  | 2022-03-18 21:03:25.137 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (9463.501 ms)
teslamate_1  | 2022-03-18 21:03:25.137 [warning] TeslaApi.Error / %{"error" => "{\"error\": \"timeout\"}", "error_description" => "", "response" => nil}
teslamate_1  | 2022-03-18 21:03:25.138 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-03-18 21:13:24.382 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 408 (10405.085 ms)
teslamate_1  | 2022-03-18 21:13:24.383 [warning] TeslaApi.Error / %{"error" => "https://mothership-api-america.vn.teslamotors.com:443/vehicles/174286848 => operation_timedout with 10s timeout", "error_description" => "", "response" => nil}
teslamate_1  | 2022-03-18 21:13:24.383 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-03-18 21:13:33.451 [info] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306 -> 408 (14030.736 ms)
teslamate_1  | 2022-03-18 21:13:33.452 [warning] TeslaApi.Error / %{"error" => "https://mothership-api-america.vn.teslamotors.com:443/vehicles/1038433579 => operation_timedout with 10s timeout", "error_description" => "", "response" => nil}
teslamate_1  | 2022-03-18 21:13:33.453 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-03-18 21:13:56.391 [warning] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 504 (17005.661 ms)
teslamate_1  | 2022-03-18 21:13:56.392 car_id=2 [error] Error / :timeout
teslamate_1  | 2022-03-18 21:14:21.577 [warning] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 504 (10181.971 ms)
teslamate_1  | 2022-03-18 21:14:21.578 car_id=2 [error] Error / :timeout
teslamate_1  | 2022-03-18 21:15:55.147 [error] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> error: "timeout" (35002.698 ms)
teslamate_1  | 2022-03-18 21:15:55.147 [warning] TeslaApi.Error / timeout
teslamate_1  | 2022-03-18 21:15:55.148 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-03-18 21:25:33.272 [warning] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 504 (10179.592 ms)
teslamate_1  | 2022-03-18 21:25:33.273 car_id=2 [error] Error / :timeout
teslamate_1  | 2022-03-18 21:56:32.680 [error] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> error: "timeout" (35002.691 ms)
teslamate_1  | 2022-03-18 21:56:32.681 [warning] TeslaApi.Error / timeout
teslamate_1  | 2022-03-18 21:56:32.681 car_id=2 [error] Error / :unknown
teslamate_1  | 2022-03-18 21:56:41.751 [error] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932132939306 -> error: "timeout" (35002.837 ms)
teslamate_1  | 2022-03-18 21:56:41.752 [warning] TeslaApi.Error / timeout
teslamate_1  | 2022-03-18 21:56:41.752 car_id=1 [error] Error / :unknown
teslamate_1  | 2022-03-18 23:04:08.803 [warning] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 504 (25182.072 ms)
teslamate_1  | 2022-03-18 23:04:08.803 car_id=2 [error] Error / :timeout
teslamate_1  | 2022-03-18 23:05:02.198 [warning] GET https://owner-api.teslamotors.com/api/1/vehicles/1492932493538049/vehicle_data -> 504 (17940.462 ms)
teslamate_1  | 2022-03-18 23:05:02.199 car_id=2 [error] Error / :timeout
teslamate_1  | 2022-03-18 23:49:56.194 [info] Refreshing access token ...
teslamate_1  | 2022-03-18 23:49:56.472 [info] POST https://auth.tesla.com/oauth2/v3/token -> 200 (276.060 ms)
teslamate_1  | 2022-03-18 23:49:56.491 [info] Scheduling token refresh in 6 h
teslamate_1  | 2022-03-19 00:02:05.258 [info] GET /
teslamate_1  | 2022-03-19 00:02:05.348 [info] Sent 200 in 83ms
rmyadsk commented 2 years ago

Though strangely, tonight's charging session showed up in Grafana, as attached: Screen Shot 2022-03-19 at 2 47 50 AM

There seems to be an issue specific to drives.

JFLachance01 commented 2 years ago

Reporting the same problem here. My distinct drives are no longer visible in the "Drives" section. However I could see that car movements were logged in the database because when I look at the "Drive Details" section and set the time range to when I had my drives, I will see that those trips were recorded.

rmyadsk commented 2 years ago

So we have a reproducible issue here - is there any plan to address it? I am ready and willing to troubleshoot.

rmyadsk commented 2 years ago

The lack of response has been noted. To what degree is this project still supported? What say you @adriankumpf ?

rmyadsk commented 2 years ago

I mean, it's like we're speaking to a brick wall here.

DrMichael commented 2 years ago

The lack of response has been noted. To what degree is this project still supported?

The project is supported by users like you. After a quick look at your too long postings, I'd say, your installation is erroneous.

And, are you really still running buster, not bullseye??!?! But then you surely installed the fix for the library.

rmyadsk commented 2 years ago

I had implemented the buster fix, though following an in-place upgrade to bullseye, the behavior appears the same.

Upon attempting to "close" a drive:

teslamate:

teslamate_1 | 2022-03-27 14:19:41.267 car_id=1 [info] Fetch already in progress ... teslamate_1 | 2022-03-27 14:20:41.625 [error] Postgrex.Protocol (#PID<0.2318.0>) disconnected: (DBConnection.ConnectionError) client #PID<0.2463.0> timed out because it queued and checked out the connection for longer than 60000ms teslamate_1 | teslamate_1 | #PID<0.2463.0> was at location: teslamate_1 | teslamate_1 | :prim_inet.recv0/3 teslamate_1 | (postgrex 0.15.13) lib/postgrex/protocol.ex:2996: Postgrex.Protocol.msg_recv/4 teslamate_1 | (postgrex 0.15.13) lib/postgrex/protocol.ex:2042: Postgrex.Protocol.recv_bind/3 teslamate_1 | (postgrex 0.15.13) lib/postgrex/protocol.ex:1934: Postgrex.Protocol.bind_execute/4 teslamate_1 | (db_connection 2.4.1) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4 teslamate_1 | (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5 teslamate_1 | (db_connection 2.4.1) lib/db_connection.ex:593: DBConnection.parsed_prepare_execute/5 teslamate_1 | (db_connection 2.4.1) lib/db_connection.ex:585: DBConnection.prepare_execute/4 teslamate_1 | teslamate_1 | 2022-03-27 14:20:41.667 [error] GenStateMachine :"1" terminating teslamate_1 | (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_1 | (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1 teslamate_1 | (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5 teslamate_1 | (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4 teslamate_1 | (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3 teslamate_1 | (ecto 3.7.1) lib/ecto/repo/queryable.ex:146: Ecto.Repo.Queryable.one/3 teslamate_1 | (teslamate 1.26.1) lib/teslamate/log.ex:292: TeslaMate.Log.close_drive/2 teslamate_1 | (teslamate 1.26.1) lib/teslamate/vehicles/vehicle.ex:1005: anonymous fn/3 in TeslaMate.Vehicles.Vehicle.handle_event/4 teslamate_1 | (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:1021: anonymous fn/3 in Ecto.Adapters.SQL.checkout_or_transaction/4 teslamate_1 | 2022-03-27 14:20:43.246 car_id=1 [info] Start / :online teslamate_1 | 2022-03-27 14:20:43.348 car_id=1 [info] Connecting ... teslamate_1 | 2022-03-27 14:21:14.358 car_id=1 [warning] Received stale stream data: %TeslaApi.Stream.Data{elevation: 8, est_heading: 165, est_lat: 39.265936, est_lng: -76.526695, est_range: 83, heading: 10, odometer: 26483.1, power: 0, range: 78, shift_state: nil, soc: 34, speed: nil, time: ~U[2022-03-27 18:21:13.630Z]}

database:

database_1 | 2022-03-27 18:20:42.111 UTC [46] ERROR: canceling statement due to user request database_1 | 2022-03-27 18:20:42.111 UTC [46] STATEMENT: SELECT s0."count", s0."start_position_id", s0."end_position_id", s0."outside_temp_avg", s0."inside_temp_avg", s0."speed_max", s0."power_max", s0."power_min", s0."start_date", s0."end_date", s0."start_km", s0."end_km", s0."distance", s0."duration_min", s0."start_ideal_range_km", s0."end_ideal_range_km", s0."start_rated_range_km", s0."end_rated_range_km", s1."start_ideal_range_km", s1."end_ideal_range_km", s1."start_rated_range_km", s1."end_rated_range_km" FROM (SELECT count(*) OVER "w" AS "count", first_value(sp0."id") OVER "w" AS "start_position_id", last_value(sp0."id") OVER "w" AS "end_position_id", avg(sp0."outside_temp") OVER "w" AS "outside_temp_avg", avg(sp0."inside_temp") OVER "w" AS "inside_temp_avg", max(sp0."speed") OVER "w" AS "speed_max", max(sp0."power") OVER "w" AS "power_max", min(sp0."power") OVER "w" AS "power_min", first_value(sp0."date") OVER "w" AS "start_date", last_value(sp0."date") OVER "w" AS "end_date", first_value(sp0."odometer") OVER "w" AS "start_km", last_value(sp0."odometer") OVER "w" AS "end_km", last_value(sp0."odometer") OVER "w" - first_value(sp0."odometer") OVER "w" AS "distance", round(extract(epoch from (last_value(sp0."date") OVER "w" - first_value(sp0."date") OVER "w")) / 60)::integer AS "duration_min", -1 AS "start_ideal_range_km", -1 AS "end_ideal_range_km", -1 AS "start_rated_range_km", -1 AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (sp0."drive_id" = $1) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s0 INNER JOIN (SELECT first_value(sp0."ideal_battery_range_km") OVER "w" AS "start_ideal_range_km", last_value(sp0."ideal_battery_range_km") OVER "w" AS "end_ideal_range_km", first_value(sp0."rated_battery_range_km") OVER "w" AS "start_rated_range_km", last_value(sp0."rated_battery_range_km") OVER "w" AS "end_rated_range_km" FROM "positions" AS sp0 WHERE (((sp0."drive_id" = $2) AND NOT (sp0."ideal_battery_range_km" IS NULL)) AND NOT (sp0."odometer" IS NULL)) WINDOW "w" AS (ORDER BY sp0."date" RANGE BETWEEN UNBOUNDED PRECEDING AND UNBOUNDED FOLLOWING) LIMIT 1) AS s1 ON TRUE database_1 | 2022-03-27 18:20:42.360 UTC [46] LOG: could not send data to client: Broken pipe database_1 | 2022-03-27 18:20:42.360 UTC [46] FATAL: connection to client lost

rmyadsk commented 2 years ago

Notably, at database startup there are these messages which suggest a possible cross-compilation error:

Attaching to pi_database_1 database_1 | database_1 | PostgreSQL Database directory appears to contain a database; Skipping initialization database_1 | database_1 | 2022-03-27 19:00:08.760 UTC [1] LOG: starting PostgreSQL 12.10 (Debian 12.10-1.pgdg110+1) on arm-unknown-linux-gnueabihf, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 32-bit database_1 | 2022-03-27 19:00:08.772 UTC [1] LOG: listening on IPv4 address "0.0.0.0", port 5432 database_1 | 2022-03-27 19:00:08.772 UTC [1] LOG: listening on IPv6 address "::", port 5432 database_1 | 2022-03-27 19:00:08.814 UTC [1] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432" database_1 | 2022-03-27 19:00:08.968 UTC [29] LOG: database system was shut down at 2022-03-27 18:41:28 UTC database_1 | 2022-03-27 19:00:09.180 UTC [1] LOG: database system is ready to accept connections database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf database_1 | ORC error: No callback manager available for armv7-unknown-linux-gnueabihf

Krookd commented 2 years ago

I wrote a guide to fix various database problems and missing drives / unclosed drives. This will also fix future drives from staying open, after finishing the drive. Unfortunately I wrote it in german for the german community „TFF-Forum“. Feel free to translate it to english:

Hier wie versprochen die Anleitung zum fixen der Datenbankprobleme und nicht beendeter Fahrten:

Der Fix wurde mit Rasbian Bullseye (bzw. Debian Bullseye) getestet. Unter Buster exisitert offenbar noch ein anderes ungelöstes Datenbankproblem.

  1. Backup der Datenbank anlegen. Stellt auch sicher, dass sich das Backup wiederherstellen lässt:

docker-compose exec -T database pg_dump -U teslamate teslamate > /backuplocation/teslamate.bck

  1. Alle Container entfernen und die Datenbank löschen:
docker-compose down
docker volume rm "$(basename "$PWD")_teslamate-db"
  1. docker-compose.yml editieren, ich mache das mit nano. Der Texteditor bleibt aber euch überlassen. Wir wollen die Container eclipse-mosquitto und postgres auf den aktuellen Stand bringen. Beide waren zumindest bei mir veraltet (in meinem Fall Mosquitto 1.6 und postgres 13):

nano docker-compose.yml

Folgende Zeilen ändern:

....
database:
    image: postgres:14
....
mosquitto:
    image: eclipse-mosquitto:2
....
  1. Docker Container Images neu herunterladen:

docker-compose pull

  1. Datenbank Container starten (nur den Datenbankcontainer, um Schreibkonflikte zu vermeiden!!):

docker-compose up -d database

  1. Datenbank aus dem Backup wiederherstellen. Ihr könnt den gesamten Block in eure SSH Session kopieren oder als ausführbares Script speichern:
docker-compose exec -T database psql -U teslamate << .
drop schema public cascade;
create schema public;
create extension cube;
create extension earthdistance;
CREATE OR REPLACE FUNCTION public.ll_to_earth(float8, float8)
    RETURNS public.earth
    LANGUAGE SQL
    IMMUTABLE STRICT
    PARALLEL SAFE
    AS 'SELECT public.cube(public.cube(public.cube(public.earth()*cos(radians(\$1))*cos(radians(\$2))),public.earth()*cos(radians(\$1))*sin(radians(\$2))),public.earth()*sin(radians(\$1)))::public.earth';
.

docker-compose exec -T database psql -U teslamate -d teslamate < teslamate.bck
  1. Jetzt könnt ihr die restlichen Container wieder starten:

docker-compose up -d

  1. Der aufwändigste Teil kommt zum Schluss. Es werden jetzt zwar bereits alle neuen Fahrten korrekt aufgezeichnet und beendet, aber die fehlerhaften Fahrten sind noch in der Datenbank und müssen manuell korrigiert werden. Dazu sucht ihr euch unter "Drives" die letzte korrekt aufgezeichnete drive-id heraus (findet ihr oben in der URL, wenn die Fahrtdetails geöffnet sind) und ebenfalls die letzte Fahrt in der Datenbank (findet ihr ebenfalls oben in der URL. Die Fahrt ist unter eurem letzten Trip zu finden, achtet auf den Zeitstempel):

Alle Fahrten mit IDs zwischen letzter korrekt aufgezeichneter Fahrt und der letzten Fehlerhaften Fahrt müssen jetzt mit diesem Befehl korrigiert werden. Der Befehl ist pro Fahrt einmal auszuführen (XXX durch die ID ersetzen. Achtung, das Teslamatewiki hat hier einen Typo eingebaut, daher funktioniert der Befehl aus dem Wiki nicht!):

docker-compose exec teslamate bin/teslamate rpc "TeslaMate.Repo.get(TeslaMate.Log.Drive, XXX) |> TeslaMate.Log.close_drive()"

Damit ist dann alles gefixt :)