Ensure recorder shuts down cleanly on restart before startup is finished (#46604)

homeassistant/components/recorder/__init__.py

@@ -346,8 +346,15 @@ class Recorder(threading.Thread):
         self.hass.add_job(register)
         result = hass_started.result()
 
+        self.event_session = self.get_session()
+        self.event_session.expire_on_commit = False
+
         # If shutdown happened before Home Assistant finished starting
         if result is shutdown_task:
+            # Make sure we cleanly close the run if
+            # we restart before startup finishes
+            self._close_run()
+            self._close_connection()
             return
 
         # Start periodic purge
@@ -363,8 +370,6 @@ class Recorder(threading.Thread):
                 async_purge, hour=4, minute=12, second=0
             )
 
-        self.event_session = self.get_session()
-        self.event_session.expire_on_commit = False
         # Use a session for the event read loop
         # with a commit every time the event time
         # has changed. This reduces the disk io.

homeassistant/components/recorder/util.py

@@ -171,7 +171,10 @@ def validate_sqlite_database(dbpath: str, db_integrity_check: bool) -> bool:
 
 def run_checks_on_open_db(dbpath, cursor, db_integrity_check):
     """Run checks that will generate a sqlite3 exception if there is corruption."""
-    if basic_sanity_check(cursor) and last_run_was_recently_clean(cursor):
+    sanity_check_passed = basic_sanity_check(cursor)
+    last_run_was_clean = last_run_was_recently_clean(cursor)
+
+    if sanity_check_passed and last_run_was_clean:
         _LOGGER.debug(
             "The quick_check will be skipped as the system was restarted cleanly and passed the basic sanity check"
         )
@@ -187,7 +190,19 @@ def run_checks_on_open_db(dbpath, cursor, db_integrity_check):
         )
         return
 
-    _LOGGER.debug(
+    if not sanity_check_passed:
+        _LOGGER.warning(
+            "The database sanity check failed to validate the sqlite3 database at %s",
+            dbpath,
+        )
+
+    if not last_run_was_clean:
+        _LOGGER.warning(
+            "The system could not validate that the sqlite3 database at %s was shutdown cleanly.",
+            dbpath,
+        )
+
+    _LOGGER.info(
         "A quick_check is being performed on the sqlite3 database at %s", dbpath
     )
     cursor.execute("PRAGMA QUICK_CHECK")

tests/components/recorder/test_init.py

@@ -16,14 +16,45 @@ from homeassistant.components.recorder import (
 from homeassistant.components.recorder.const import DATA_INSTANCE
 from homeassistant.components.recorder.models import Events, RecorderRuns, States
 from homeassistant.components.recorder.util import session_scope
-from homeassistant.const import MATCH_ALL, STATE_LOCKED, STATE_UNLOCKED
-from homeassistant.core import Context, callback
+from homeassistant.const import (
+    EVENT_HOMEASSISTANT_STOP,
+    MATCH_ALL,
+    STATE_LOCKED,
+    STATE_UNLOCKED,
+)
+from homeassistant.core import Context, CoreState, callback
 from homeassistant.setup import async_setup_component
 from homeassistant.util import dt as dt_util
 
 from .common import wait_recording_done
 
-from tests.common import fire_time_changed, get_test_home_assistant
+from tests.common import (
+    async_init_recorder_component,
+    fire_time_changed,
+    get_test_home_assistant,
+)
+
+
+async def test_shutdown_before_startup_finishes(hass):
+    """Test shutdown before recorder starts is clean."""
+
+    hass.state = CoreState.not_running
+
+    await async_init_recorder_component(hass)
+    await hass.async_block_till_done()
+
+    session = await hass.async_add_executor_job(hass.data[DATA_INSTANCE].get_session)
+
+    with patch.object(hass.data[DATA_INSTANCE], "engine"):
+        hass.bus.async_fire(EVENT_HOMEASSISTANT_STOP)
+        await hass.async_block_till_done()
+        hass.stop()
+
+    run_info = await hass.async_add_executor_job(run_information_with_session, session)
+
+    assert run_info.run_id == 1
+    assert run_info.start is not None
+    assert run_info.end is not None
 
 
 def test_saving_state(hass, hass_recorder):

tests/components/recorder/test_util.py

@@ -178,36 +178,72 @@ def test_basic_sanity_check(hass_recorder):
         util.basic_sanity_check(cursor)
 
 
-def test_combined_checks(hass_recorder):
+def test_combined_checks(hass_recorder, caplog):
     """Run Checks on the open database."""
     hass = hass_recorder()
 
-    db_integrity_check = False
-
     cursor = hass.data[DATA_INSTANCE].engine.raw_connection().cursor()
 
-    assert (
-        util.run_checks_on_open_db("fake_db_path", cursor, db_integrity_check) is None
-    )
+    assert util.run_checks_on_open_db("fake_db_path", cursor, False) is None
+    assert "skipped because db_integrity_check was disabled" in caplog.text
+
+    caplog.clear()
+    assert util.run_checks_on_open_db("fake_db_path", cursor, True) is None
+    assert "could not validate that the sqlite3 database" in caplog.text
+
+    # We are patching recorder.util here in order
+    # to avoid creating the full database on disk
+    with patch(
+        "homeassistant.components.recorder.util.basic_sanity_check", return_value=False
+    ):
+        caplog.clear()
+        assert util.run_checks_on_open_db("fake_db_path", cursor, False) is None
+        assert "skipped because db_integrity_check was disabled" in caplog.text
+
+        caplog.clear()
+        assert util.run_checks_on_open_db("fake_db_path", cursor, True) is None
+        assert "could not validate that the sqlite3 database" in caplog.text
 
     # We are patching recorder.util here in order
     # to avoid creating the full database on disk
     with patch("homeassistant.components.recorder.util.last_run_was_recently_clean"):
+        caplog.clear()
+        assert util.run_checks_on_open_db("fake_db_path", cursor, False) is None
         assert (
-            util.run_checks_on_open_db("fake_db_path", cursor, db_integrity_check)
-            is None
+            "system was restarted cleanly and passed the basic sanity check"
+            in caplog.text
         )
 
+        caplog.clear()
+        assert util.run_checks_on_open_db("fake_db_path", cursor, True) is None
+        assert (
+            "system was restarted cleanly and passed the basic sanity check"
+            in caplog.text
+        )
+
+    caplog.clear()
     with patch(
         "homeassistant.components.recorder.util.last_run_was_recently_clean",
         side_effect=sqlite3.DatabaseError,
     ), pytest.raises(sqlite3.DatabaseError):
-        util.run_checks_on_open_db("fake_db_path", cursor, db_integrity_check)
+        util.run_checks_on_open_db("fake_db_path", cursor, False)
+
+    caplog.clear()
+    with patch(
+        "homeassistant.components.recorder.util.last_run_was_recently_clean",
+        side_effect=sqlite3.DatabaseError,
+    ), pytest.raises(sqlite3.DatabaseError):
+        util.run_checks_on_open_db("fake_db_path", cursor, True)
 
     cursor.execute("DROP TABLE events;")
 
+    caplog.clear()
     with pytest.raises(sqlite3.DatabaseError):
-        util.run_checks_on_open_db("fake_db_path", cursor, db_integrity_check)
+        util.run_checks_on_open_db("fake_db_path", cursor, False)
+
+    caplog.clear()
+    with pytest.raises(sqlite3.DatabaseError):
+        util.run_checks_on_open_db("fake_db_path", cursor, True)
 
 
 def _corrupt_db_file(test_db_file):