Losing connection to database

[BabyYeggie]

Is there an existing issue for this?

• I have searched the existing issues

What happened?

Teslamate seems to be losing connection to postgres 12. This is causing no data to be stored. Currently running on a GCP E2 instance running Debian 10 buster v20210122.

Expected Behavior

Data is stored as intended

Steps To Reproduce

Start Teslamate as normal using the "advanced" set up.

Relevant log output

Attaching to postgres
postgres     | 
postgres     | PostgreSQL Database directory appears to contain a database; Skipping initialization
postgres     | 
postgres     | 2021-10-11 06:58:16.717 UTC [1] LOG:  starting PostgreSQL 12.8 (Debian 12.8-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
postgres     | 2021-10-11 06:58:16.763 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
postgres     | 2021-10-11 06:58:16.763 UTC [1] LOG:  listening on IPv6 address "::", port 5432
postgres     | 2021-10-11 06:58:16.931 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
postgres     | 2021-10-11 06:58:17.589 UTC [25] LOG:  database system was shut down at 2021-10-11 06:54:16 UTC
postgres     | 2021-10-11 06:58:18.085 UTC [1] LOG:  database system is ready to accept connections
postgres     | 2021-10-12 01:17:51.153 UTC [39] LOG:  unexpected EOF on client connection with an open transaction
postgres     | 2021-10-12 01:17:52.771 UTC [2252] LOG:  PID 39 in cancel request did not match any process
postgres     | 2021-10-12 14:16:13.745 UTC [38] ERROR:  canceling statement due to user request
postgres     | 2021-10-12 14:16:13.745 UTC [38] 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
postgres     | 2021-10-12 14:16:14.098 UTC [38] LOG:  could not send data to client: Broken pipe
postgres     | 2021-10-12 14:16:14.098 UTC [38] FATAL:  connection to client lost
postgres     | 2021-10-12 14:39:25.287 UTC [2253] LOG:  unexpected EOF on client connection with an open transaction
postgres     | 2021-10-12 19:02:59.522 UTC [3860] ERROR:  canceling statement due to user request
postgres     | 2021-10-12 19:02:59.522 UTC [3860] 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)
postgres     | 2021-10-12 19:02:59.624 UTC [4434] FATAL:  terminating connection due to administrator command
postgres     | 2021-10-12 14:16:14.098 UTC [38] LOG:  could not send data to client: Broken pipe
postgres     | 2021-10-12 14:16:14.098 UTC [38] FATAL:  connection to client lost
postgres     | 2021-10-12 14:39:25.287 UTC [2253] LOG:  unexpected EOF on client connection with an open transaction
postgres     | 2021-10-12 19:02:59.522 UTC [3860] ERROR:  canceling statement due to user request
postgres     | 2021-10-12 19:02:59.522 UTC [3860] 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)
postgres     | 2021-10-12 19:02:59.624 UTC [4434] FATAL:  terminating connection due to administrator command
postgres     | 2021-10-12 19:02:59.624 UTC [4434] 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)
postgres     | 2021-10-12 19:02:59.624 UTC [4435] FATAL:  terminating connection due to administrator command
postgres     | 2021-10-12 19:02:59.624 UTC [4435] 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)
postgres     | 2021-10-12 19:02:59.716 UTC [1] LOG:  background worker "parallel worker" (PID 4435) exited with exit code 1
postgres     | 2021-10-12 19:02:59.716 UTC [1] LOG:  background worker "parallel worker" (PID 4434) exited with exit code 1
postgres     | 2021-10-12 19:03:00.152 UTC [3860] LOG:  could not send data to client: Broken pipe
postgres     | 2021-10-12 19:03:00.152 UTC [3860] FATAL:  connection to client lost
postgres     | 2021-10-13 14:18:26.297 UTC [36] ERROR:  canceling statement due to user request

Screenshots

No response

Additional data

While no drive data is stored, the "visited" and "trip" map is accurate and shows the proper trips.

Type of installation

Docker

Version

v1.24.2

[jopotti]

I have the same problem.
mosquitto is logging:

2021-12-23T15:59:05.035955796Z 0: New connection from 172.21.0.4 on port 1883.,
2021-12-23T15:59:05.040198171Z 0: Client has exceeded timeout, disconnecting.,
2021-12-23T15:59:05.258352566Z 0: New connection from 172.21.0.4 on port 1883.,
2021-12-23T15:59:05.260324008Z 0: Client has exceeded timeout, disconnecting.,
2021-12-23T15:59:05.673981217Z 0: New connection from 172.21.0.4 on port 1883.,
2021-12-23T15:59:05.676943796Z 0: Client has exceeded timeout, disconnecting.,
2021-12-23T15:59:06.499708720Z 0: New connection from 172.21.0.4 on port 1883.,
2021-12-23T15:59:06.501245217Z 0: Client has exceeded timeout, disconnecting.

database logging:

2021-12-23T16:02:32.923630782Z 1970-01-01 00:00:00.000 UTC [374] STATEMENT: SELECT p0."id", p0."date", p0."latitude", p0."longitude", p0."elevation", p0."speed", p0."power", p0."odometer", p0."ideal_battery_range_km", p0."est_battery_range_km", p0."rated_battery_range_km", p0."battery_level", p0."usable_battery_level", p0."battery_heater", p0."battery_heater_on", p0."battery_heater_no_power", p0."outside_temp", p0."inside_temp", p0."fan_status", p0."driver_temp_setting", p0."passenger_temp_setting", p0."is_climate_on", p0."is_rear_defroster_on", p0."is_front_defroster_on", p0."car_id", p0."drive_id" FROM "positions" AS p0 WHERE (((p0."id" > $1) AND (p0."elevation" IS NULL)) AND p0."drive_id" = ANY($2)) ORDER BY p0."id" LIMIT $3,
2021-12-23T16:02:32.929975671Z 1970-01-01 00:00:00.000 UTC [373] FATAL: terminating background worker "parallel worker" due to administrator command,
2021-12-23T16:02:32.930705857Z 1970-01-01 00:00:00.000 UTC [373] STATEMENT: SELECT p0."id", p0."date", p0."latitude", p0."longitude", p0."elevation", p0."speed", p0."power", p0."odometer", p0."ideal_battery_range_km", p0."est_battery_range_km", p0."rated_battery_range_km", p0."battery_level", p0."usable_battery_level", p0."battery_heater", p0."battery_heater_on", p0."battery_heater_no_power", p0."outside_temp", p0."inside_temp", p0."fan_status", p0."driver_temp_setting", p0."passenger_temp_setting", p0."is_climate_on", p0."is_rear_defroster_on", p0."is_front_defroster_on", p0."car_id", p0."drive_id" FROM "positions" AS p0 WHERE (((p0."id" > $1) AND (p0."elevation" IS NULL)) AND p0."drive_id" = ANY($2)) ORDER BY p0."id" LIMIT $3,
2021-12-23T16:02:34.290039196Z 1970-01-01 00:00:00.000 UTC [1] LOG: background worker "parallel worker" (PID 373) exited with exit code 1,
2021-12-23T16:02:34.302919927Z 1970-01-01 00:00:00.000 UTC [342] LOG: could not send data to client: Broken pipe,
2021-12-23T16:02:34.307741029Z 1970-01-01 00:00:00.000 UTC [1] LOG: background worker "parallel worker" (PID 374) exited with exit code 1,
2021-12-23T16:02:34.309022989Z 1970-01-01 00:00:00.000 UTC [342] FATAL: connection to client lost

teslamate logging:

2021-12-23T16:03:32.768791303Z (db_connection 2.4.1) lib/db_connection.ex:1333: DBConnection.run_execute/5,
2021-12-23T16:03:32.768853009Z (db_connection 2.4.1) lib/db_connection.ex:1428: DBConnection.run/6,
2021-12-23T16:03:32.768914174Z (db_connection 2.4.1) lib/db_connection.ex:650: DBConnection.execute/4,
2021-12-23T16:03:32.768974964Z ,
2021-12-23T16:03:32.777849856Z 2021-12-23 16:03:32.728 [error] GenStateMachine TeslaMate.Terrain terminating,
2021-12-23T16:03:32.778616333Z ** (DBConnection.ConnectionError) tcp recv: closed (the connection was closed by the pool, possibly due to a timeout or because the pool has been terminated),
2021-12-23T16:03:32.779076902Z (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:760: Ecto.Adapters.SQL.raise_sql_call_error/1,
2021-12-23T16:03:32.779229189Z (ecto_sql 3.7.1) lib/ecto/adapters/sql.ex:693: Ecto.Adapters.SQL.execute/5,
2021-12-23T16:03:32.779422141Z (ecto 3.7.1) lib/ecto/repo/queryable.ex:219: Ecto.Repo.Queryable.execute/4,
2021-12-23T16:03:32.779555804Z (ecto 3.7.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3,
2021-12-23T16:03:32.779735882Z (teslamate 1.25.0) lib/teslamate/log.ex:177: TeslaMate.Log.get_positions_without_elevation/2,
2021-12-23T16:03:32.779862253Z (teslamate 1.25.0) lib/teslamate/terrain.ex:84: TeslaMate.Terrain.handle_event/4,
2021-12-23T16:03:32.779986290Z (stdlib 3.16.1) gen_statem.erl:1196: :gen_statem.loop_state_callback/11,
2021-12-23T16:03:32.780169618Z (stdlib 3.16.1) proc_lib.erl:226: :proc_lib.init_p_do_apply/3,
2021-12-23T16:05:16.348354862Z 2021-12-23 16:05:16.233 [error] Postgrex.Protocol (#PID<0.2323.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.3448.0> timed out because it queued and checked out the connection for longer than 60000ms,
2021-12-23T16:05:16.394931072Z