S2: record an actuator status that arrived before any system description

CHANGELOG-S2.rst

@@ -123,7 +123,7 @@ Fixed
 
 * A full message history now keeps the newest messages. It used to make room by evicting the newest entry, so it kept a session's first messages and lost all later ones except the last. A message stored again under the same id now counts as the latest [`#274 <https://github.com/FlexMeasures/flexmeasures-client/pull/274>`__]
 * ``Handler.is_revoked()`` now finds objects the resource manager revoked. The CEM and its handlers stored a revoked object's id as a ``UUID``, so a lookup by its string id always missed [`#257 <https://github.com/FlexMeasures/flexmeasures-client/pull/257>`__]
-* An FRBC actuator status that arrives before any system description is logged and skipped, instead of raising an error in a background task. This can happen after a reconnection [`#274 <https://github.com/FlexMeasures/flexmeasures-client/pull/274>`__]
+* An FRBC actuator status that arrives before any system description, which can happen after a reconnection, is kept, and recorded once a system description arrives. Only the latest per actuator is kept, since a status describes the actuator's present state. It used to raise an error in a background task [`#274 <https://github.com/FlexMeasures/flexmeasures-client/pull/274>`__, `#287 <https://github.com/FlexMeasures/flexmeasures-client/pull/287>`__]
 * A CEM records measured power by the time it was measured. It records one average per step of the sensor's resolution (15 minutes on the example's sites, previously five), in watts, as S2 states it. A step is recorded with the first measurement that arrives after the step has ended by the CEM's clock. Before, measurements were grouped by the CEM's current time, which dropped every measurement sent after the fact, as co-simulations do. They were also labelled as kilowatts instead of watts, and kept in a buffer shared by every CEM in the process. Recording happens in the background, with a few retries if it fails [`#266 <https://github.com/FlexMeasures/flexmeasures-client/pull/266>`__]
 * A CEM without a sensor for a resource manager's measured power no longer records L1 measurements on sensor 357. That was whatever sensor had that id on the server, on any site, and the CEM reported the measurement as recorded [`#265 <https://github.com/FlexMeasures/flexmeasures-client/pull/265>`__]
 * A CEM that is selecting a control type now takes a message of that control type as confirmation of the selection, because a resource manager only sends such messages once it uses that control type. Before, the CEM stayed without a control type, and answered each such message with a temporary error, which the resource manager retried; co-simulations whose resource managers reconnect showed this. A message of any other control type activates nothing [`#263 <https://github.com/FlexMeasures/flexmeasures-client/pull/263>`__]

src/flexmeasures_client/s2/control_types/FRBC/__init__.py

@@ -55,6 +55,8 @@ class FRBC(ControlTypeHandler):
 
     _timer_status_history: SizeLimitOrderedDict[str, FRBCTimerStatus]
     _actuator_status_history: SizeLimitOrderedDict[str, FRBCActuatorStatus]
+    #: Per actuator, the latest status that arrived before any system description, to be handled once one arrives.
+    _statuses_awaiting_a_description: dict[str, FRBCActuatorStatus]
     _storage_status_history: SizeLimitOrderedDict[str, FRBCStorageStatus]
     background_tasks: set
     _sent_instructions: dict[str, FRBCInstruction]
@@ -75,6 +77,7 @@ def __init__(self, max_size: int = 100) -> None:
 
         self._timer_status_history = SizeLimitOrderedDict(max_size=max_size)
         self._actuator_status_history = SizeLimitOrderedDict(max_size=max_size)
+        self._statuses_awaiting_a_description = {}
         self._storage_status_history = SizeLimitOrderedDict(max_size=max_size)
 
         self._system_description_history = SizeLimitOrderedDict(max_size=max_size)
@@ -243,6 +246,15 @@ def handle_system_description(
         # store system_description message for later
         self._system_description_history[system_description_id] = message
 
+        # A status that arrived before any description could not be handled then, since only a description says what its operation mode stands for.
+        # A status describes the actuator's present state, so the latest per actuator is handled now.
+        awaiting = list(self._statuses_awaiting_a_description.values())
+        self._statuses_awaiting_a_description.clear()
+        for status in awaiting:
+            task = asyncio.create_task(self.send_actuator_status(status))
+            self.background_tasks.add(task)
+            task.add_done_callback(self.background_tasks.discard)
+
         # Warn once per description, because nothing else here would mention it.
         # An instruction can ask for a switch that a running timer or a missing transition forbids, and then the device refuses it.
         actuator = message.actuators[0]

src/flexmeasures_client/s2/control_types/FRBC/frbc_simple.py

@@ -679,8 +679,10 @@ async def send_actuator_status(self, status: FRBCActuatorStatus):
         # After a reconnection, an actuator status can arrive before any description.
         # This method needs a description to tell what power the status stands for.
         if not self._system_description_history:
-            self._logger.warning(
-                "Not recording the power of an FRBC.ActuatorStatus: no FRBC.SystemDescription has arrived yet to tell what its operation mode draws."
+            # Kept instead, and recorded once a description arrives (see handle_system_description).
+            self._statuses_awaiting_a_description[str(status.actuator_id)] = status
+            self._logger.info(
+                "Not recording the power of an FRBC.ActuatorStatus yet: no FRBC.SystemDescription has arrived to tell what its operation mode draws, so it is recorded once one does."
             )
             return
         sd: FRBCSystemDescription = list(self._system_description_history.values())[-1]

tests/s2/test_frbc_actuator_measurement.py

@@ -11,6 +11,7 @@
 
 from __future__ import annotations
 
+import asyncio
 import logging
 from datetime import datetime, timedelta, timezone
 from unittest.mock import AsyncMock
@@ -351,15 +352,23 @@ async def test_a_unit_nothing_converts_between_is_reported(system_description, c
 
 
 @pytest.mark.asyncio
-async def test_an_actuator_status_before_any_description_is_said_and_skipped(
+async def test_an_actuator_status_before_any_description_waits_for_one(
     system_description, caplog
 ):
     """After a reconnection one can arrive first; indexing the empty history raised an IndexError in a task nobody awaited."""
+    caplog.set_level(logging.INFO)
     frbc = _frbc(system_description, consumption_as_positive=True)
-    status = _status(system_description, 0)
     frbc._system_description_history.clear()
 
-    await frbc.send_actuator_status(status)
+    await frbc.send_actuator_status(_status(system_description, 0))
+    await frbc.send_actuator_status(_status(system_description, 1))
 
     assert _posts_to_the_power_sensor(frbc) == []
-    assert "no FRBC.SystemDescription has arrived yet" in caplog.text
+    assert "no FRBC.SystemDescription has arrived" in caplog.text
+
+    await frbc.handle_system_description(system_description.to_dict())
+    await asyncio.gather(*frbc.background_tasks)
+
+    # Only the latest status describes the actuator's present state, so only that one is recorded.
+    assert [post["values"] for post in _posts_to_the_power_sensor(frbc)] == [[ON_W]]
+    assert frbc._statuses_awaiting_a_description == {}