From 99e627e370dab2d06af9013f6a7c5d89715b2dba Mon Sep 17 00:00:00 2001 From: Stefan Agner Date: Wed, 5 Jun 2024 21:08:14 +0200 Subject: [PATCH] Improve logging and use Future to mark completion Instead of using an Event use a Future to mark completion of the update. This allows to set an Exception in case we see update state transitions which are unexpected (specifically kQuerying -> kIdle). --- matter_server/server/device_controller.py | 5 +++ matter_server/server/ota/provider.py | 39 +++++++++++------------ 2 files changed, 24 insertions(+), 20 deletions(-) diff --git a/matter_server/server/device_controller.py b/matter_server/server/device_controller.py index ba167bba..e1ec92bf 100644 --- a/matter_server/server/device_controller.py +++ b/matter_server/server/device_controller.py @@ -910,6 +910,9 @@ async def update_node( notify the node about the new update. """ + node_logger = LOGGER.getChild(f"node_{node_id}") + node_logger.info("Update to software version %r", software_version) + update = await self._check_node_update(node_id, software_version) if update is None: raise UpdateCheckError( @@ -923,6 +926,7 @@ async def update_node( await ota_provider.initialize() + node_logger.info("Downloading update from '%s'", update["otaUrl"]) await ota_provider.download_update(update) self._attribute_update_callbacks.setdefault(node_id, []).append( @@ -931,6 +935,7 @@ async def update_node( try: # Make sure any previous instances get stopped + node_logger.info("Starting update using OTA Provider.") await ota_provider.start_update( self._chip_device_controller, node_id, diff --git a/matter_server/server/ota/provider.py b/matter_server/server/ota/provider.py index a646d0d6..6dc5f755 100644 --- a/matter_server/server/ota/provider.py +++ b/matter_server/server/ota/provider.py @@ -75,7 +75,7 @@ def __init__(self, vendor_id: int, ota_provider_dir: Path) -> None: self._ota_file_path: Path | None = None self._ota_provider_proc: Process | None = None self._ota_provider_task: asyncio.Task | None = None - self._ota_done: asyncio.Event = asyncio.Event() + self._ota_done: asyncio.Future = asyncio.Future() self._ota_target_node_id: int | None = None async def initialize(self) -> None: @@ -161,11 +161,9 @@ async def _commission_ota_provider( "Failed writing adjusted OTA Provider App ACL: Status %s.", str(write_result[0].Status), ) - await self.stop() raise UpdateError("Error while setting up OTA Provider.") except ChipStackError as ex: logging.exception("Failed adjusting OTA Provider App ACL.", exc_info=ex) - await self.stop() raise UpdateError("Error while setting up OTA Provider.") from ex async def start_update( @@ -239,8 +237,11 @@ async def start_update( "Error while announcing OTA Provider to node." ) from ex - await self._ota_done.wait() + LOGGER.info("Waiting for target node update state change") + await self._ota_done + LOGGER.info("OTA update finished successfully") finally: + LOGGER.info("Cleaning up OTA provider") await self.stop() self._ota_target_node_id = None @@ -345,30 +346,28 @@ async def check_update_state( ) -> None: """Check the update state of a node and take appropriate action.""" - LOGGER.info("Update state changed: %s, %s %s", str(path), old_value, new_value) if str(path) != OTA_SOFTWARE_UPDATE_REQUESTOR_UPDATE_STATE_ATTRIBUTE_PATH: return - update_state = cast( - Clusters.OtaSoftwareUpdateRequestor.Enums.UpdateStateEnum, new_value - ) + UpdateState = Clusters.OtaSoftwareUpdateRequestor.Enums.UpdateStateEnum # noqa: N806 - old_update_state = cast( - Clusters.OtaSoftwareUpdateRequestor.Enums.UpdateStateEnum, old_value + new_update_state = UpdateState(new_value) + old_update_state = UpdateState(old_value) + + LOGGER.info( + "Update state changed from %r to %r", + old_update_state, + new_update_state, ) # Update state of target node changed, check if update is done. - if ( - update_state - == Clusters.OtaSoftwareUpdateRequestor.Enums.UpdateStateEnum.kIdle - ): - if ( - old_update_state - == Clusters.OtaSoftwareUpdateRequestor.Enums.UpdateStateEnum.kQuerying - ): - raise UpdateError("Target node did not process the update file") + if new_update_state == UpdateState.kIdle: + if old_update_state == UpdateState.kQuerying: + self._ota_done.set_exception( + UpdateError("Target node did not process the update file") + ) LOGGER.info( "Node %d update state idle, assuming done.", self._ota_target_node_id ) - self._ota_done.set() + self._ota_done.set_result(None)