refactor: implement wait_and_log helper method to log periodically du…

…ring waiting for all sub ECUs before reboot (#410)

This PR introduces `wait_and_log` helper method, which issues logs during waiting for flag set. otaclient now uses this method when waiting for all sub ECUs before reboot. 

Other changes:
1. otaclient will issue a warning log before actually calling reboot command.
2. otaclient will sleep 6 seconds before actually reboot the system.

src/otaclient/app/ota_client.py

@@ -48,6 +48,7 @@
     get_standby_slot_creator,
 )
 from otaclient.create_standby.common import DeltaBundle
+from otaclient.utils import wait_and_log
 from otaclient_api.v2 import types as api_types
 from otaclient_common.common import ensure_otaproxy_start
 from otaclient_common.downloader import (
@@ -68,6 +69,7 @@
 logger = logging.getLogger(__name__)
 
 DEFAULT_STATUS_QUERY_INTERVAL = 1
+WAIT_BEFORE_REBOOT = 6
 
 
 class LiveOTAStatus:
@@ -485,7 +487,14 @@ def _execute_update(self):
         next(_postupdate_gen := self._boot_controller.post_update())
 
         logger.info("local update finished, wait on all subecs...")
-        self._control_flags.wait_can_reboot_flag()
+        wait_and_log(
+            flag=self._control_flags._can_reboot,
+            message="permit reboot flag",
+            log_func=logger.info,
+        )
+
+        logger.info(f"device will reboot in {WAIT_BEFORE_REBOOT} seconds!")
+        time.sleep(WAIT_BEFORE_REBOOT)
         next(_postupdate_gen, None)  # reboot
 
     # API

src/otaclient/boot_control/_common.py

@@ -446,6 +446,7 @@ def reboot(cls, args: Optional[list[str]] = None) -> NoReturn:
             cmd.extend(args)
 
         try:
+            logger.warning("system will reboot now!")
             subprocess_call(cmd, raise_exception=True)
             sys.exit(0)
         except CalledProcessError:

src/otaclient/utils.py

@@ -0,0 +1,52 @@
+# Copyright 2022 TIER IV, INC. All rights reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+"""Common shared utils, only used by otaclient package."""
+
+
+from __future__ import annotations
+
+import itertools
+import logging
+import time
+from abc import abstractmethod
+from typing import Callable, Protocol
+
+logger = logging.getLogger(__name__)
+
+
+class CheckableFlag(Protocol):
+
+    @abstractmethod
+    def is_set(self) -> bool: ...
+
+
+def wait_and_log(
+    flag: CheckableFlag,
+    message: str = "",
+    *,
+    check_interval: int = 2,
+    log_interval: int = 30,
+    log_func: Callable[[str], None] = logger.info,
+) -> None:
+    """Wait for <flag> until it is set while print a log every <log_interval>."""
+    log_round = 0
+    for seconds in itertools.count(step=check_interval):
+        if flag.is_set():
+            return
+
+        _new_log_round = seconds // log_interval
+        if _new_log_round > log_round:
+            log_func(f"wait for {message}: {seconds}s passed ...")
+            log_round = _new_log_round
+        time.sleep(check_interval)

tests/test_otaclient/test_create_standby.py

@@ -90,6 +90,8 @@ def test_update_with_rebuild_mode(self, mocker: MockerFixture):
         otaclient_control_flags = typing.cast(
             OTAClientControlFlags, mocker.MagicMock(spec=OTAClientControlFlags)
         )
+        otaclient_control_flags._can_reboot = _can_reboot = mocker.MagicMock()
+        _can_reboot.is_set = mocker.MagicMock(return_value=True)
 
         ca_store = load_ca_cert_chains(cfg.CERTS_DIR)
 
@@ -116,7 +118,7 @@ def test_update_with_rebuild_mode(self, mocker: MockerFixture):
         persist_handler.assert_called_once()
         # --- assert update finished
         _updater.shutdown.assert_called_once()
-        otaclient_control_flags.wait_can_reboot_flag.assert_called_once()  # type: ignore
+        otaclient_control_flags._can_reboot.is_set.assert_called_once()  # type: ignore
         # --- ensure the update stats are collected
         collector = _updater._update_stats_collector
         assert collector.processed_files_num

tests/test_otaclient/test_ota_client.py

@@ -176,6 +176,9 @@ def test_otaupdater(self, mocker: pytest_mock.MockerFixture):
         otaclient_control_flags = typing.cast(
             OTAClientControlFlags, mocker.MagicMock(spec=OTAClientControlFlags)
         )
+        otaclient_control_flags._can_reboot = _can_reboot = mocker.MagicMock()
+        _can_reboot.is_set = mocker.MagicMock(return_value=True)
+
         ca_store = load_ca_cert_chains(cfg.CERTS_DIR)
 
         _updater = _OTAUpdater(
@@ -199,7 +202,7 @@ def test_otaupdater(self, mocker: pytest_mock.MockerFixture):
             _downloaded_files_size += _f.stat().st_size
         assert _downloaded_files_size == self._delta_bundle.total_download_files_size
         # assert the control_flags has been waited
-        otaclient_control_flags.wait_can_reboot_flag.assert_called_once()
+        otaclient_control_flags._can_reboot.is_set.assert_called_once()
         assert _updater.updating_version == str(cfg.UPDATE_VERSION)
         # assert boot controller is used
         self._boot_control.pre_update.assert_called_once()

tests/test_otaclient/test_utils.py

@@ -0,0 +1,55 @@
+# Copyright 2022 TIER IV, INC. All rights reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+
+from __future__ import annotations
+
+import logging
+import time
+
+import pytest
+
+from otaclient.utils import wait_and_log
+
+logger = logging.getLogger(__name__)
+
+
+class _TickingFlag:
+
+    def __init__(self, trigger_in: int) -> None:
+        self._trigger_time = time.time() + trigger_in
+
+    def is_set(self) -> bool:
+        _now = time.time()
+        return _now > self._trigger_time
+
+
+def test_wait_and_log(caplog: pytest.LogCaptureFixture):
+    # NOTE: allow 2 more seconds for expected_trigger_time
+    trigger_in, expected_trigger_time = 11, time.time() + 11 + 2
+    _flag = _TickingFlag(trigger_in=trigger_in)
+    _msg = "ticking flag"
+
+    wait_and_log(
+        _flag,
+        _msg,
+        check_interval=1,
+        log_interval=2,
+        log_func=logger.warning,
+    )
+
+    assert len(caplog.records) == 5
+    assert caplog.records[0].levelno == logging.WARNING
+    assert caplog.records[0].msg == f"wait for {_msg}: 2s passed ..."
+    assert time.time() < expected_trigger_time