search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
73.6k stars 30.76k forks source link

Postgres DB Migration stuck in 2022.4.3 #70106

Closed zacs closed 2 years ago

zacs commented 2 years ago

The problem

Upgraded to 2022.4.3 (from 2022.2.1) yesterday, and the migration is continuing. Machine is well-resourced (10th gen i5 and 32gb) so it seems as if the migration should be done.

Running using Docker, with separate container for Postgres, which is on version 12.8.

I'm unable to restart HA, so can't really change any logging settings. But have included logs from the Postgres container.

What version of Home Assistant Core has the issue?

core-2022.4.3

What was the last working version of Home Assistant Core?

core-2022.2.1

What type of installation are you running?

Home Assistant Container

Integration causing the issue

recorder

Link to integration documentation on our website

https://www.home-assistant.io/integrations/recorder/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2022-04-14 02:18:16.933 UTC [9660] LOG:  invalid length of startup packet
2022-04-14 02:18:17.117 UTC [9661] LOG:  invalid length of startup packet
2022-04-14 02:18:17.132 UTC [9662] FATAL:  unsupported frontend protocol 65363.19778: server supports 2.0 to 3.0
2022-04-14 07:12:10.816 UTC [10302] LOG:  invalid length of startup packet
2022-04-14 07:12:10.996 UTC [10303] LOG:  invalid length of startup packet
2022-04-14 07:12:11.013 UTC [10304] FATAL:  unsupported frontend protocol 65363.19778: server supports 2.0 to 3.0
2022-04-14 10:44:08.211 UTC [10729] LOG:  invalid length of startup packet
2022-04-14 10:44:08.391 UTC [10730] LOG:  invalid length of startup packet
2022-04-14 10:44:08.406 UTC [10731] FATAL:  unsupported frontend protocol 65363.19778: server supports 2.0 to 3.0
2022-04-14 15:10:00.147 UTC [11299] LOG:  invalid length of startup packet
2022-04-14 15:10:00.276 UTC [11300] LOG:  invalid length of startup packet
2022-04-14 15:10:00.292 UTC [11301] FATAL:  unsupported frontend protocol 65363.19778: server supports 2.0 to 3.0
2022-04-14 18:49:48.088 UTC [11790] LOG:  invalid length of startup packet
2022-04-14 18:49:48.266 UTC [11791] LOG:  invalid length of startup packet
2022-04-14 18:49:48.281 UTC [11792] FATAL:  unsupported frontend protocol 65363.19778: server supports 2.0 to 3.0
2022-04-14 19:13:01.103 UTC [11569] LOG:  unexpected EOF on client connection with an open transaction
2022-04-14 19:13:30.465 UTC [1] LOG:  received fast shutdown request
2022-04-14 19:13:30.473 UTC [1] LOG:  aborting any active transactions
2022-04-14 19:13:30.481 UTC [1] LOG:  background worker "logical replication launcher" (PID 31) exited with exit code 1
2022-04-14 19:13:30.483 UTC [26] LOG:  shutting down
2022-04-14 19:13:31.377 UTC [1] LOG:  database system is shut down

PostgreSQL Database directory appears to contain a database; Skipping initialization

2022-04-14 19:13:42.651 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
2022-04-14 19:13:42.652 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2022-04-14 19:13:42.652 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2022-04-14 19:13:42.666 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-04-14 19:13:42.703 UTC [24] LOG:  database system was shut down at 2022-04-14 19:13:31 UTC
2022-04-14 19:13:42.715 UTC [1] LOG:  database system is ready to accept connections
2022-04-14 19:15:11.081 UTC [1] LOG:  received fast shutdown request
2022-04-14 19:15:11.089 UTC [1] LOG:  aborting any active transactions
2022-04-14 19:15:11.089 UTC [31] FATAL:  terminating connection due to administrator command
2022-04-14 19:15:11.091 UTC [33] FATAL:  terminating connection due to administrator command
2022-04-14 19:15:11.092 UTC [1] LOG:  background worker "logical replication launcher" (PID 30) exited with exit code 1
2022-04-14 19:15:11.095 UTC [25] LOG:  shutting down
2022-04-14 19:15:11.228 UTC [1] LOG:  database system is shut down

PostgreSQL Database directory appears to contain a database; Skipping initialization

2022-04-14 19:16:29.625 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
2022-04-14 19:16:29.625 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2022-04-14 19:16:29.625 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2022-04-14 19:16:29.634 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-04-14 19:16:29.692 UTC [28] LOG:  database system was shut down at 2022-04-14 19:15:11 UTC
2022-04-14 19:16:29.709 UTC [1] LOG:  database system is ready to accept connections
2022-04-14 19:21:28.939 UTC [35] LOG:  unexpected EOF on client connection with an open transaction
2022-04-14 21:36:07.745 UTC [319] LOG:  invalid length of startup packet
2022-04-14 21:36:07.930 UTC [321] LOG:  invalid length of startup packet
2022-04-14 21:36:07.942 UTC [322] FATAL:  unsupported frontend protocol 65363.19778: server supports 2.0 to 3.0
2022-04-14 23:02:23.048 UTC [47] LOG:  unexpected EOF on client connection with an open transaction
2022-04-14 23:02:23.049 UTC [49] LOG:  unexpected EOF on client connection with an open transaction
2022-04-14 23:02:23.051 UTC [485] ERROR:  column states.attributes_id does not exist at character 1995
2022-04-14 23:02:23.051 UTC [485] HINT:  Perhaps you meant to reference the column "states.attributes".
2022-04-14 23:02:23.051 UTC [485] STATEMENT:  DECLARE "c_7fd8f3363520_1" CURSOR WITHOUT HOLD FOR SELECT anon_1.events_event_type AS anon_1_events_event_type, anon_1.events_event_data AS anon_1_events_event_data, anon_1.events_time_fired AS anon_1_events_time_fired, anon_1.events_context_id AS anon_1_events_context_id, anon_1.events_context_user_id AS anon_1_events_context_user_id, anon_1.events_context_parent_id AS anon_1_events_context_parent_id, anon_1.state AS anon_1_state, anon_1.entity_id AS anon_1_entity_id, anon_1.attributes AS anon_1_attributes, anon_1.shared_attrs AS anon_1_shared_attrs 
    FROM (SELECT events.event_type AS events_event_type, events.event_data AS events_event_data, events.time_fired AS events_time_fired, events.context_id AS events_context_id, events.context_user_id AS events_context_user_id, events.context_parent_id AS events_context_parent_id, NULL AS state, NULL AS entity_id, NULL AS attributes, NULL AS shared_attrs 
    FROM events 
    WHERE events.time_fired > '2022-04-13T22:56:37.547000+00:00'::timestamptz AND events.time_fired < '2022-04-14T22:56:37.547000+00:00'::timestamptz AND events.event_type IN ('logbook_entry', 'call_service', 'homeassistant_start', 'homeassistant_stop', 'google_assistant_command', 'script_started', 'homekit_state_change', 'automation_triggered') AND events.event_data LIKE '%"entity_id":"binary_sensor.office_desk_sensor_motion"%' UNION ALL SELECT events.event_type AS events_event_type, events.event_data AS events_event_data, events.time_fired AS events_time_fired, events.context_id AS events_context_id, events.context_user_id AS events_context_user_id, events.context_parent_id AS events_context_parent_id, states.state AS states_state, states.entity_id AS states_entity_id, states.attributes AS states_attributes, state_attributes.shared_attrs AS state_attributes_shared_attrs 
    FROM states LEFT OUTER JOIN events ON states.event_id = events.event_id LEFT OUTER JOIN states AS old_state ON states.old_state_id = old_state.state_id LEFT OUTER JOIN state_attributes ON states.attributes_id = state_attributes.attributes_id 
    WHERE old_state.state_id IS NOT NULL AND states.state != old_state.state AND states.state IS NOT NULL AND ((states.entity_id NOT LIKE 'proximity.%' AND states.entity_id NOT LIKE 'sensor.%') OR ((states.entity_id LIKE 'proximity.%' OR states.entity_id LIKE 'sensor.%') AND (state_attributes.shared_attrs NOT LIKE '%"unit_of_measurement":%' OR states.attributes NOT LIKE '%"unit_of_measurement":%'))) AND states.last_updated > '2022-04-13T22:56:37.547000+00:00'::timestamptz AND states.last_updated < '2022-04-14T22:56:37.547000+00:00'::timestamptz AND states.last_updated = states.last_changed AND states.entity_id IN ('binary_sensor.office_desk_sensor_motion')) AS anon_1 ORDER BY anon_1.events_time_fired
2022-04-14 23:02:23.051 UTC [485] LOG:  could not send data to client: Broken pipe
2022-04-14 23:02:23.051 UTC [485] FATAL:  connection to client lost
2022-04-14 23:02:23.057 UTC [102] LOG:  unexpected EOF on client connection with an open transaction
2022-04-14 23:02:23.057 UTC [105] LOG:  unexpected EOF on client connection with an open transaction
2022-04-14 23:02:23.078 UTC [484] LOG:  could not send data to client: Broken pipe
2022-04-14 23:02:23.078 UTC [484] STATEMENT:  SELECT states.entity_id AS states_entity_id, states.state AS states_state, states.last_changed AS states_last_changed, states.last_updated AS states_last_updated, NULL AS attributes, NULL AS shared_attrs 
    FROM states 
    WHERE states.last_changed = states.last_updated AND states.entity_id IN ('binary_sensor.office_desk_sensor_motion') AND states.last_updated > '2022-04-13T22:56:37.545000+00:00'::timestamptz AND states.last_updated < '2022-04-14T22:56:37.545000+00:00'::timestamptz ORDER BY states.entity_id, states.last_updated
2022-04-14 23:02:23.078 UTC [484] FATAL:  connection to client lost
2022-04-14 23:02:23.078 UTC [484] STATEMENT:  SELECT states.entity_id AS states_entity_id, states.state AS states_state, states.last_changed AS states_last_changed, states.last_updated AS states_last_updated, NULL AS attributes, NULL AS shared_attrs 
    FROM states 
    WHERE states.last_changed = states.last_updated AND states.entity_id IN ('binary_sensor.office_desk_sensor_motion') AND states.last_updated > '2022-04-13T22:56:37.545000+00:00'::timestamptz AND states.last_updated < '2022-04-14T22:56:37.545000+00:00'::timestamptz ORDER BY states.entity_id, states.last_updated
2022-04-15 00:56:11.691 UTC [727] LOG:  invalid length of startup packet
2022-04-15 00:56:11.873 UTC [729] LOG:  invalid length of startup packet
2022-04-15 00:56:11.888 UTC [730] FATAL:  unsupported frontend protocol 65363.19778: server supports 2.0 to 3.0
2022-04-15 04:39:11.572 UTC [1176] LOG:  invalid length of startup packet
2022-04-15 04:39:11.714 UTC [1178] LOG:  invalid length of startup packet
2022-04-15 04:39:11.730 UTC [1179] FATAL:  unsupported frontend protocol 65363.19778: server supports 2.0 to 3.0
2022-04-15 09:11:43.562 UTC [1724] LOG:  invalid length of startup packet
2022-04-15 09:11:43.736 UTC [1725] LOG:  invalid length of startup packet
2022-04-15 09:11:43.753 UTC [1726] FATAL:  unsupported frontend protocol 65363.19778: server supports 2.0 to 3.0
2022-04-15 11:51:34.423 UTC [2047] LOG:  invalid length of startup packet
2022-04-15 11:51:34.599 UTC [2048] LOG:  invalid length of startup packet
2022-04-15 11:51:34.614 UTC [2049] FATAL:  unsupported frontend protocol 65363.19778: server supports 2.0 to 3.0
2022-04-15 14:50:57.219 UTC [2408] LOG:  invalid length of startup packet
2022-04-15 14:50:57.394 UTC [2410] LOG:  invalid length of startup packet
2022-04-15 14:50:57.409 UTC [2411] FATAL:  unsupported frontend protocol 65363.19778: server supports 2.0 to 3.0

Additional information

No response

probot-home-assistant[bot] commented 2 years ago

recorder documentation recorder source (message by IssueLinks)

probot-home-assistant[bot] commented 2 years ago

Hey there @home-assistant/core, mind taking a look at this issue as it has been labeled with an integration (recorder) you are listed as a code owner for? Thanks! (message by CodeOwnersMention)

zacs commented 2 years ago

Closing since I am not sure I'll be able to provide any meaningful debug info, and because I ultimately just blew away the old DB and started over to achieve spousal approval factor :)