Don't log reconnect errors while a device reboots after OTA (#183664)

homeassistant/components/shelly/const.py

@@ -278,6 +278,9 @@ OTA_ERROR = "ota_error"
 OTA_PROGRESS = "ota_progress"
 OTA_SUCCESS = "ota_success"
 
+# Time allowed for a device to come back online after a firmware update
+OTA_REBOOT_TIMEOUT: Final = 300
+
 GEN1_RELEASE_URL = "https://shelly-api-docs.shelly.cloud/gen1/#changelog"
 GEN2_RELEASE_URL = "https://shelly-api-docs.shelly.cloud/gen2/changelog/"
 GEN2_BETA_RELEASE_URL = f"{GEN2_RELEASE_URL}#unreleased"

homeassistant/components/shelly/coordinator.py

@@ -3,7 +3,7 @@
 import asyncio
 from collections.abc import Callable, Coroutine
 from dataclasses import dataclass
-from datetime import timedelta
+from datetime import datetime, timedelta
 from typing import Any, cast, override
 
 from aioshelly.ble import async_ensure_ble_enabled, async_stop_scanner
@@ -37,6 +37,7 @@ from homeassistant.helpers import (
 from homeassistant.helpers.debounce import Debouncer
 from homeassistant.helpers.device_registry import CONNECTION_NETWORK_MAC, format_mac
 from homeassistant.helpers.update_coordinator import DataUpdateCoordinator, UpdateFailed
+from homeassistant.util import dt as dt_util
 
 from .bluetooth import async_connect_scanner
 from .const import (
@@ -59,6 +60,7 @@ from .const import (
     OTA_BEGIN,
     OTA_ERROR,
     OTA_PROGRESS,
+    OTA_REBOOT_TIMEOUT,
     OTA_SUCCESS,
     PUSH_UPDATE_ISSUE_ID,
     REST_SENSORS_UPDATE_INTERVAL,
@@ -532,6 +534,7 @@ class ShellyRpcCoordinator(ShellyCoordinatorBase[RpcDevice]):
         self._connection_lock = asyncio.Lock()
         self._event_listeners: list[Callable[[dict[str, Any]], None]] = []
         self._ota_event_listeners: list[Callable[[dict[str, Any]], None]] = []
+        self._ota_reboot_deadline: datetime | None = None
         self._input_event_listeners: list[Callable[[dict[str, Any]], None]] = []
         self._connect_task: asyncio.Task | None = None
 
@@ -657,6 +660,12 @@ class ShellyRpcCoordinator(ShellyCoordinatorBase[RpcDevice]):
                     },
                 )
             elif event_type in (OTA_BEGIN, OTA_ERROR, OTA_PROGRESS, OTA_SUCCESS):
+                # The device reboots to apply the update, expect it to go offline
+                self._ota_reboot_deadline = (
+                    None
+                    if event_type == OTA_ERROR
+                    else dt_util.utcnow() + timedelta(seconds=OTA_REBOOT_TIMEOUT)
+                )
                 for event_callback in self._ota_event_listeners:
                     event_callback(event)
 
@@ -682,6 +691,15 @@ class ShellyRpcCoordinator(ShellyCoordinatorBase[RpcDevice]):
                 return
 
             if not await self._async_device_connect_task():
+                if (
+                    self._ota_reboot_deadline is not None
+                    and dt_util.utcnow() < self._ota_reboot_deadline
+                ):
+                    LOGGER.debug(
+                        "Device %s is rebooting after a firmware update, retrying later",
+                        self.name,
+                    )
+                    return
                 raise UpdateFailed(
                     translation_domain=DOMAIN,
                     translation_key="update_error_reconnect_error",
@@ -807,6 +825,7 @@ class ShellyRpcCoordinator(ShellyCoordinatorBase[RpcDevice]):
             self._came_online_once = True
             self._async_handle_rpc_device_online()
         elif update_type is RpcUpdateType.INITIALIZED:
+            self._ota_reboot_deadline = None
             self.config_entry.async_create_background_task(
                 self.hass, self._async_connected(), "rpc device init", eager_start=True
             )

tests/components/shelly/test_coordinator.py

@@ -20,6 +20,11 @@ from homeassistant.components.shelly.const import (
     CONF_SLEEP_PERIOD,
     DOMAIN,
     ENTRY_RELOAD_COOLDOWN,
+    OTA_BEGIN,
+    OTA_ERROR,
+    OTA_PROGRESS,
+    OTA_REBOOT_TIMEOUT,
+    OTA_SUCCESS,
     RPC_RECONNECT_INTERVAL,
     UPDATE_PERIOD_MULTIPLIER,
     BLEScannerMode,
@@ -53,6 +58,7 @@ from tests.common import (
     mock_restore_cache,
 )
 
+RECONNECT_ERROR = "An error occurred while reconnecting to Test name"
 RELAY_BLOCK_ID = 0
 LIGHT_BLOCK_ID = 2
 SENSOR_BLOCK_ID = 3
@@ -816,6 +822,98 @@ async def test_rpc_reconnect_error(
     assert state.state == STATE_UNAVAILABLE
 
 
+def _inject_ota_event(
+    monkeypatch: pytest.MonkeyPatch, mock_rpc_device: Mock, event_type: str
+) -> None:
+    """Inject an OTA event for rpc device."""
+    inject_rpc_device_event(
+        monkeypatch,
+        mock_rpc_device,
+        {
+            "events": [{"event": event_type, "id": 1, "ts": 1668522399.2}],
+            "ts": 1668522399.2,
+        },
+    )
+
+
+async def _mock_rpc_device_rebooting(
+    hass: HomeAssistant, mock_rpc_device: Mock, monkeypatch: pytest.MonkeyPatch
+) -> None:
+    """Disconnect the rpc device and fail to reconnect while it reboots."""
+    monkeypatch.setattr(mock_rpc_device, "connected", False)
+    monkeypatch.setattr(mock_rpc_device, "initialized", False)
+    monkeypatch.setattr(
+        mock_rpc_device, "initialize", AsyncMock(side_effect=DeviceConnectionError)
+    )
+    mock_rpc_device.mock_disconnected()
+    await hass.async_block_till_done()
+
+
+@pytest.mark.parametrize("event_type", [OTA_BEGIN, OTA_PROGRESS, OTA_SUCCESS])
+async def test_rpc_reconnect_error_during_ota_reboot(
+    hass: HomeAssistant,
+    freezer: FrozenDateTimeFactory,
+    mock_rpc_device: Mock,
+    monkeypatch: pytest.MonkeyPatch,
+    caplog: pytest.LogCaptureFixture,
+    event_type: str,
+) -> None:
+    """Test RPC reconnect error is not logged while the device reboots after OTA."""
+    entity_id = "switch.test_name_test_switch_0"
+    monkeypatch.delitem(mock_rpc_device.status, "cover:0")
+    monkeypatch.setitem(mock_rpc_device.status["sys"], "relay_in_thermostat", False)
+    await init_integration(hass, 2)
+
+    _inject_ota_event(monkeypatch, mock_rpc_device, event_type)
+    await _mock_rpc_device_rebooting(hass, mock_rpc_device, monkeypatch)
+
+    assert (state := hass.states.get(entity_id))
+    assert state.state == STATE_UNAVAILABLE
+    assert RECONNECT_ERROR not in caplog.text
+
+    # Device did not come back after the firmware update
+    freezer.tick(timedelta(seconds=OTA_REBOOT_TIMEOUT))
+    async_fire_time_changed(hass)
+    await hass.async_block_till_done()
+
+    assert (state := hass.states.get(entity_id))
+    assert state.state == STATE_UNAVAILABLE
+    assert RECONNECT_ERROR in caplog.text
+
+
+async def test_rpc_reconnect_error_after_ota_error(
+    hass: HomeAssistant,
+    mock_rpc_device: Mock,
+    monkeypatch: pytest.MonkeyPatch,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    """Test RPC reconnect error is logged when the OTA update failed."""
+    await init_integration(hass, 2)
+
+    _inject_ota_event(monkeypatch, mock_rpc_device, OTA_BEGIN)
+    _inject_ota_event(monkeypatch, mock_rpc_device, OTA_ERROR)
+    await _mock_rpc_device_rebooting(hass, mock_rpc_device, monkeypatch)
+
+    assert RECONNECT_ERROR in caplog.text
+
+
+async def test_rpc_reconnect_error_after_ota_reboot_completed(
+    hass: HomeAssistant,
+    mock_rpc_device: Mock,
+    monkeypatch: pytest.MonkeyPatch,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    """Test RPC reconnect error is logged once the device is back after OTA."""
+    await init_integration(hass, 2)
+
+    _inject_ota_event(monkeypatch, mock_rpc_device, OTA_SUCCESS)
+    mock_rpc_device.mock_initialized()
+    await hass.async_block_till_done()
+    await _mock_rpc_device_rebooting(hass, mock_rpc_device, monkeypatch)
+
+    assert RECONNECT_ERROR in caplog.text
+
+
 async def test_rpc_error_running_connected_events(
     hass: HomeAssistant,
     freezer: FrozenDateTimeFactory,