diff --git a/CHANGELOG.md b/CHANGELOG.md index e7273f586..2dd6d43b6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,9 @@ # Changelog +## v0.47.0 - 2025-09-26 + +- PR [345](https://github.com/plugwise/python-plugwise-usb/pull/345): New Feature: schedule clock synchronization every 3600 seconds + ## v0.46.1 - 2025-09-25 - PR [337](https://github.com/plugwise/python-plugwise-usb/pull/337): Improve node removal, remove and reset the node as executed by Source, and remove the cache-file. diff --git a/plugwise_usb/nodes/circle.py b/plugwise_usb/nodes/circle.py index b06f6c8e9..1ff06fb92 100644 --- a/plugwise_usb/nodes/circle.py +++ b/plugwise_usb/nodes/circle.py @@ -2,13 +2,14 @@ from __future__ import annotations -from asyncio import Task, create_task, gather +from asyncio import CancelledError, Task, create_task, gather, sleep from collections.abc import Awaitable, Callable from dataclasses import replace from datetime import UTC, datetime, timedelta from functools import wraps import logging from math import ceil +import random from typing import Any, Final, TypeVar, cast from ..api import ( @@ -74,7 +75,9 @@ # Default firmware if not known DEFAULT_FIRMWARE: Final = datetime(2008, 8, 26, 15, 46, tzinfo=UTC) -MAX_LOG_HOURS = DAY_IN_HOURS +MAX_LOG_HOURS: Final = DAY_IN_HOURS + +CLOCK_SYNC_PERIOD: Final = 3600 FuncT = TypeVar("FuncT", bound=Callable[..., Any]) _LOGGER = logging.getLogger(__name__) @@ -141,6 +144,8 @@ def __init__( """Initialize base class for Sleeping End Device.""" super().__init__(mac, node_type, controller, loaded_callback) + # Clock + self._clock_synchronize_task: Task[None] | None = None # Relay self._relay_lock: RelayLock = RelayLock() self._relay_state: RelayState = RelayState() @@ -852,47 +857,61 @@ async def _relay_update_lock( ) await self.save_cache() + async def _clock_synchronize_scheduler(self) -> None: + """Background task: periodically synchronize the clock until cancelled.""" + try: + while True: + await sleep(CLOCK_SYNC_PERIOD + (random.uniform(-5, 5))) + try: + await self.clock_synchronize() + except Exception: + _LOGGER.exception( + "Clock synchronization failed for %s", self._mac_in_str + ) + except CancelledError: + _LOGGER.debug("Clock sync scheduler cancelled for %s", self._mac_in_str) + raise + async def clock_synchronize(self) -> bool: """Synchronize clock. Returns true if successful.""" - get_clock_request = CircleClockGetRequest(self._send, self._mac_in_bytes) - clock_response = await get_clock_request.send() - if clock_response is None or clock_response.timestamp is None: + request = CircleClockGetRequest(self._send, self._mac_in_bytes) + response = await request.send() + if response is None or response.timestamp is None: return False - _dt_of_circle = datetime.now(tz=UTC).replace( - hour=clock_response.time.hour.value, - minute=clock_response.time.minute.value, - second=clock_response.time.second.value, + + dt_now = datetime.now(tz=UTC) + days_diff = (response.day_of_week.value - dt_now.weekday()) % 7 + circle_timestamp: datetime = dt_now.replace( + day=dt_now.day + days_diff, + hour=response.time.value.hour, + minute=response.time.value.minute, + second=response.time.value.second, microsecond=0, tzinfo=UTC, ) - clock_offset = clock_response.timestamp.replace(microsecond=0) - _dt_of_circle - if (clock_offset.seconds < MAX_TIME_DRIFT) or ( - clock_offset.seconds > -(MAX_TIME_DRIFT) - ): + clock_offset = response.timestamp.replace(microsecond=0) - circle_timestamp + if abs(clock_offset.total_seconds()) < MAX_TIME_DRIFT: return True + _LOGGER.info( - "Reset clock of node %s because time has drifted %s sec", + "Sync clock of node %s because time drifted %s seconds", self._mac_in_str, - str(clock_offset.seconds), + int(abs(clock_offset.total_seconds())), ) if self._node_protocols is None: raise NodeError( - "Unable to synchronize clock en when protocol version is unknown" + "Unable to synchronize clock when protocol version is unknown" ) - set_clock_request = CircleClockSetRequest( + + set_request = CircleClockSetRequest( self._send, self._mac_in_bytes, datetime.now(tz=UTC), self._node_protocols.max, ) - if (node_response := await set_clock_request.send()) is None: - _LOGGER.warning( - "Failed to (re)set the internal clock of %s", - self.name, - ) - return False - if node_response.ack_id == NodeResponseType.CLOCK_ACCEPTED: - return True + if (node_response := await set_request.send()) is not None: + return node_response.ack_id == NodeResponseType.CLOCK_ACCEPTED + _LOGGER.warning("Failed to sync the clock of %s", self.name) return False async def load(self) -> None: @@ -1016,6 +1035,10 @@ async def initialize(self) -> bool: return False await super().initialize() + if self._clock_synchronize_task is None or self._clock_synchronize_task.done(): + self._clock_synchronize_task = create_task( + self._clock_synchronize_scheduler() + ) return True async def node_info_update( @@ -1082,6 +1105,11 @@ async def unload(self) -> None: if self._cache_enabled: await self._energy_log_records_save_to_cache() + if self._clock_synchronize_task: + self._clock_synchronize_task.cancel() + await gather(self._clock_synchronize_task, return_exceptions=True) + self._clock_synchronize_task = None + await super().unload() @raise_not_loaded @@ -1318,7 +1346,7 @@ async def energy_reset_request(self) -> None: f"Unexpected NodeResponseType {response.ack_id!r} received as response to CircleClockSetRequest" ) - _LOGGER.warning("Energy reset for Node %s successful", self._mac_in_str) + _LOGGER.info("Energy reset for Node %s successful", self._mac_in_str) # Follow up by an energy-intervals (re)set interval_request = CircleMeasureIntervalRequest( @@ -1337,12 +1365,12 @@ async def energy_reset_request(self) -> None: raise MessageError( f"Unknown NodeResponseType '{interval_response.response_type.name}' received" ) - _LOGGER.warning("Resetting energy intervals to default (= consumption only)") + _LOGGER.info("Resetting energy intervals to default (= consumption only)") # Clear the cached energy_collection if self._cache_enabled: self._set_cache(CACHE_ENERGY_COLLECTION, "") - _LOGGER.warning( + _LOGGER.info( "Energy-collection cache cleared successfully, updating cache for %s", self._mac_in_str, ) @@ -1350,7 +1378,7 @@ async def energy_reset_request(self) -> None: # Clear PulseCollection._logs self._energy_counters.reset_pulse_collection() - _LOGGER.warning("Resetting pulse-collection") + _LOGGER.info("Resetting pulse-collection") # Request a NodeInfo update if await self.node_info_update() is None: @@ -1359,7 +1387,7 @@ async def energy_reset_request(self) -> None: self._mac_in_str, ) else: - _LOGGER.warning( + _LOGGER.info( "Node info update after energy-reset successful for %s", self._mac_in_str, ) diff --git a/plugwise_usb/nodes/circle_plus.py b/plugwise_usb/nodes/circle_plus.py index 66a52fcdb..5760bea92 100644 --- a/plugwise_usb/nodes/circle_plus.py +++ b/plugwise_usb/nodes/circle_plus.py @@ -67,44 +67,61 @@ async def load(self) -> bool: async def clock_synchronize(self) -> bool: """Synchronize realtime clock. Returns true if successful.""" - clock_request = CirclePlusRealTimeClockGetRequest( - self._send, self._mac_in_bytes - ) - if (clock_response := await clock_request.send()) is None: - _LOGGER.debug( - "No response for async_realtime_clock_synchronize() for %s", self.mac + request = CirclePlusRealTimeClockGetRequest(self._send, self._mac_in_bytes) + if (response := await request.send()) is None: + _LOGGER.warning( + "No response for clock_synchronize() for %s", self._mac_in_str ) await self._available_update_state(False) return False - await self._available_update_state(True, clock_response.timestamp) + await self._available_update_state(True, response.timestamp) + + dt_now = datetime.now(tz=UTC) + dt_now_date = dt_now.replace(hour=0, minute=0, second=0, microsecond=0) + response_date = datetime( + response.date.value.year, + response.date.value.month, + response.date.value.day, + hour=0, + minute=0, + second=0, + microsecond=0, + tzinfo=UTC, + ) + if dt_now_date != response_date: + _LOGGER.info( + "Sync clock of node %s because time has drifted %s days", + self._mac_in_str, + int(abs((dt_now_date - response_date).days)), + ) + return await self._send_clock_set_req() - _dt_of_circle: datetime = datetime.now(tz=UTC).replace( - hour=clock_response.time.value.hour, - minute=clock_response.time.value.minute, - second=clock_response.time.value.second, + circle_plus_timestamp: datetime = dt_now.replace( + hour=response.time.value.hour, + minute=response.time.value.minute, + second=response.time.value.second, microsecond=0, tzinfo=UTC, ) - clock_offset = clock_response.timestamp.replace(microsecond=0) - _dt_of_circle - if (clock_offset.seconds < MAX_TIME_DRIFT) or ( - clock_offset.seconds > -(MAX_TIME_DRIFT) - ): + clock_offset = response.timestamp.replace(microsecond=0) - circle_plus_timestamp + if abs(clock_offset.total_seconds()) < MAX_TIME_DRIFT: return True + _LOGGER.info( - "Reset realtime clock of node %s because time has drifted %s seconds while max drift is set to %s seconds)", - self._node_info.mac, - str(clock_offset.seconds), - str(MAX_TIME_DRIFT), + "Sync clock of node %s because time drifted %s seconds", + self._mac_in_str, + int(abs(clock_offset.total_seconds())), ) - clock_set_request = CirclePlusRealTimeClockSetRequest( + return await self._send_clock_set_req() + + async def _send_clock_set_req(self) -> bool: + """Send CirclePlusRealTimeClockSetRequest.""" + set_request = CirclePlusRealTimeClockSetRequest( self._send, self._mac_in_bytes, datetime.now(tz=UTC) ) - if (node_response := await clock_set_request.send()) is not None: + if (node_response := await set_request.send()) is not None: return node_response.ack_id == NodeResponseType.CLOCK_ACCEPTED - _LOGGER.warning( - "Failed to (re)set the internal realtime clock of %s", - self.name, - ) + _LOGGER.warning("Failed to sync the clock of %s", self.name) return False @raise_not_loaded diff --git a/pyproject.toml b/pyproject.toml index a46a3a4ae..df84cf0fc 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta" [project] name = "plugwise_usb" -version = "0.46.1" +version = "0.47.0" license = "MIT" keywords = ["home", "automation", "plugwise", "module", "usb"] classifiers = [ @@ -540,3 +540,7 @@ testpaths = [ ] asyncio_default_fixture_loop_scope = "session" asyncio_mode = "strict" +# log_cli = true +# log_cli_level = "DEBUG" +# log_format = "%(asctime)s %(levelname)s %(message)s" +# log_date_format = "%Y-%m-%d %H:%M:%S" diff --git a/tests/stick_test_data.py b/tests/stick_test_data.py index 4d22e5c64..b70ca5239 100644 --- a/tests/stick_test_data.py +++ b/tests/stick_test_data.py @@ -1,27 +1,27 @@ """Stick Test Program.""" -from datetime import UTC, datetime, timedelta +from datetime import datetime, timedelta import importlib pw_constants = importlib.import_module("plugwise_usb.constants") -# test using utc timezone -utc_now = datetime.now(tz=UTC).replace(tzinfo=UTC) - +# test using utc timezone - 2025-04-03 22:00:00 +fixed_time = datetime( + 2025, 4, 3, 22, 0, 0 +) # changed from datetime.now(tz=UTC).replace(tzinfo=UTC) # generate energy log timestamps with fixed hour timestamp used in tests -hour_timestamp = utc_now.replace(minute=0, second=0, microsecond=0) +hour_timestamp = fixed_time.replace(minute=0, second=0, microsecond=0) LOG_TIMESTAMPS = {} _one_hour = timedelta(hours=1) for x in range(168): delta_month = hour_timestamp - hour_timestamp.replace(day=1, hour=0) LOG_TIMESTAMPS[x] = ( - bytes(("%%0%dX" % 2) % (hour_timestamp.year - 2000), pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dX" % 2) % hour_timestamp.month, pw_constants.UTF8) # noqa: UP031 + bytes(f"{(hour_timestamp.year - 2000):02x}", pw_constants.UTF8) + + bytes(f"{hour_timestamp.month:02x}", pw_constants.UTF8) + bytes( - ("%%0%dX" % 4) # noqa: UP031 - % int((delta_month.days * 1440) + (delta_month.seconds / 60)), + f"{int((delta_month.days * 1440) + (delta_month.seconds / 60)):04x}", pw_constants.UTF8, ) ) @@ -596,23 +596,28 @@ b"000000C1", # Success ack b"003A" # msg_id + b"0098765432101234" # mac - + bytes(("%%0%dd" % 2) % utc_now.second, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dd" % 2) % utc_now.minute, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dd" % 2) % utc_now.hour, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dd" % 2) % utc_now.weekday(), pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dd" % 2) % utc_now.day, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dd" % 2) % utc_now.month, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dd" % 2) % (utc_now.year - 2000), pw_constants.UTF8), # noqa: UP031 + + bytes(f"{(fixed_time + timedelta(seconds=10)).second:02d}", pw_constants.UTF8) + + bytes(f"{fixed_time.minute:02d}", pw_constants.UTF8) + + bytes(f"{fixed_time.hour:02d}", pw_constants.UTF8) + + bytes(f"{fixed_time.weekday():02d}", pw_constants.UTF8) + + bytes(f"{fixed_time.day:02d}", pw_constants.UTF8) + + bytes(f"{fixed_time.month:02d}", pw_constants.UTF8) + + bytes(f"{(fixed_time.year - 2000):02d}", pw_constants.UTF8), + ), + b"\x05\x05\x03\x0300280098765432101234000022030304259DDF\r\n": ( + "Circle+ Realtime set clock for 0098765432101234", + b"000000C1", # Success ack + b"0000" + b"00D7" + b"0098765432101234", # msg_id, clock_ack, mac ), b"\x05\x05\x03\x03003E11111111111111111B8A\r\n": ( "clock for 0011111111111111", b"000000C1", # Success ack b"003F" # msg_id + b"1111111111111111" # mac - + bytes(("%%0%dX" % 2) % utc_now.hour, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dX" % 2) % utc_now.minute, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dX" % 2) % utc_now.second, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dX" % 2) % utc_now.weekday(), pw_constants.UTF8) # noqa: UP031 + + bytes(f"{fixed_time.hour:02x}", pw_constants.UTF8) + + bytes(f"{fixed_time.minute:02x}", pw_constants.UTF8) + + bytes(f"{(fixed_time + timedelta(seconds=10)).second:02x}", pw_constants.UTF8) + + bytes(f"{fixed_time.weekday():02x}", pw_constants.UTF8) + b"00" # unknown + b"0000", # unknown2 ), @@ -621,10 +626,10 @@ b"000000C1", # Success ack b"003F" # msg_id + b"2222222222222222" # mac - + bytes(("%%0%dX" % 2) % utc_now.hour, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dX" % 2) % utc_now.minute, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dX" % 2) % utc_now.second, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dX" % 2) % utc_now.weekday(), pw_constants.UTF8) # noqa: UP031 + + bytes(f"{fixed_time.hour:02x}", pw_constants.UTF8) + + bytes(f"{fixed_time.minute:02x}", pw_constants.UTF8) + + bytes(f"{fixed_time.second:02x}", pw_constants.UTF8) + + bytes(f"{fixed_time.weekday():02x}", pw_constants.UTF8) + b"00" # unknown + b"0000", # unknown2 ), @@ -633,10 +638,10 @@ b"000000C1", # Success ack b"003F" # msg_id + b"3333333333333333" # mac - + bytes(("%%0%dX" % 2) % utc_now.hour, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dX" % 2) % utc_now.minute, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dX" % 2) % utc_now.second, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dX" % 2) % utc_now.weekday(), pw_constants.UTF8) # noqa: UP031 + + bytes(f"{fixed_time.hour:02x}", pw_constants.UTF8) + + bytes(f"{fixed_time.minute:02x}", pw_constants.UTF8) + + bytes(f"{fixed_time.second:02x}", pw_constants.UTF8) + + bytes(f"{fixed_time.weekday():02x}", pw_constants.UTF8) + b"00" # unknown + b"0000", # unknown2 ), @@ -645,10 +650,10 @@ b"000000C1", # Success ack b"003F" # msg_id + b"4444444444444444" # mac - + bytes(("%%0%dX" % 2) % utc_now.hour, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dX" % 2) % utc_now.minute, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dX" % 2) % utc_now.second, pw_constants.UTF8) # noqa: UP031 - + bytes(("%%0%dX" % 2) % utc_now.weekday(), pw_constants.UTF8) # noqa: UP031 + + bytes(f"{fixed_time.hour:02x}", pw_constants.UTF8) + + bytes(f"{fixed_time.minute:02x}", pw_constants.UTF8) + + bytes(f"{fixed_time.second:02x}", pw_constants.UTF8) + + bytes(f"{fixed_time.weekday():02x}", pw_constants.UTF8) + b"00" # unknown + b"0000", # unknown2 ), diff --git a/tests/test_usb.py b/tests/test_usb.py index 59ce895f3..ad4979fb0 100644 --- a/tests/test_usb.py +++ b/tests/test_usb.py @@ -780,6 +780,7 @@ async def node_init_relay_state( ) ) + @freeze_time("2025-04-03 22:00:00", real_asyncio=True) @pytest.mark.asyncio async def test_node_relay_and_power(self, monkeypatch: pytest.MonkeyPatch) -> None: # noqa: PLR0915 """Testing discovery of nodes.""" @@ -908,6 +909,7 @@ async def test_node_relay_and_power(self, monkeypatch: pytest.MonkeyPatch) -> No await stick.disconnect() + @freeze_time("2025-04-03 22:00:00", real_asyncio=True) @pytest.mark.asyncio async def test_energy_circle(self, monkeypatch: pytest.MonkeyPatch) -> None: """Testing energy retrieval.""" @@ -2722,6 +2724,7 @@ async def load_callback(event: pw_api.NodeEvent, mac: str) -> None: # type: ign ) assert not state[pw_api.NodeFeature.AVAILABLE].state + @freeze_time("2025-04-03 22:00:00", real_asyncio=True) @pytest.mark.asyncio async def test_node_discovery_and_load( # noqa: PLR0915 self, monkeypatch: pytest.MonkeyPatch