TMP: Add logging for debugging test

Author: llucax

src/frequenz/sdk/microgrid/_power_managing/_matryoshka.py

@@ -200,7 +200,14 @@ def calculate_target_power(
 
         target_power = None
         if proposals is not None:
+            _logger.warning(
+                "[MATRYOSHKA] Calculating target power for %s: proposals=%s, system_bounds=%s",
+                component_ids,
+                proposals,
+                system_bounds,
+            )
             target_power = self._calc_target_power(proposals, system_bounds)
+            _logger.warning("[MATRYOSHKA] Calculated target power: %s", target_power)
 
         if target_power is not None:
             self._target_power[component_ids] = target_power

src/frequenz/sdk/microgrid/_power_managing/_power_managing_actor.py

@@ -215,7 +215,7 @@ async def _bounds_tracker(
         component_ids: frozenset[ComponentId],
         bounds_receiver: Receiver[SystemBounds],
     ) -> None:
-        """Track the power bounds of a set of components and update the cache.
+        """Track system bounds for the given components and send updated reports.
 
         Args:
             component_ids: The component IDs for which this task should track the
@@ -230,6 +230,11 @@ async def _bounds_tracker(
             ):
                 continue
             last_bounds = bounds
+            _logger.warning(
+                "[BOUNDS_TRACKER] New bounds received for %s: %s -> calling _send_updated_target_power(None)",
+                component_ids,
+                bounds.inclusion_bounds,
+            )
             self._system_bounds[component_ids] = bounds
             await self._send_updated_target_power(component_ids, None)
             await self._send_reports(component_ids)
@@ -282,19 +287,45 @@ async def _send_updated_target_power(
         component_ids: frozenset[ComponentId],
         proposal: Proposal | None,
     ) -> None:
+        """Send updated target power to power distributing actor.
+
+        Args:
+            component_ids: The component IDs to send the power request for.
+            proposal: The proposal to be sent.  If `None`, this method acts as an
+                announcement that the bounds have been updated, and the target power
+                should be recalculated.
+        """
+        _logger.warning(
+            "[SEND_TARGET_POWER] Called with component_ids=%s, proposal=%s",
+            component_ids,
+            proposal,
+        )
         target_power = self._algorithm.calculate_target_power(
             component_ids,
             proposal,
             self._system_bounds[component_ids],
         )
+        _logger.warning("[SEND_TARGET_POWER] Calculated target_power=%s", target_power)
         if target_power is not None:
+            _logger.warning(
+                "[SEND_TARGET_POWER] Sending power distributing request power=%s, "
+                "component_ids=%s, adjust_power=True",
+                target_power,
+                component_ids,
+            )
             await self._power_distributing_requests_sender.send(
                 _power_distributing.Request(
                     power=target_power,
                     component_ids=component_ids,
                     adjust_power=True,
                 )
             )
+            _logger.warning(
+                "[SEND_TARGET_POWER] Power distributing request SENT: power=%s, "
+                "component_ids=%s, adjust_power=True",
+                target_power,
+                component_ids,
+            )
 
     @override
     async def _run(self) -> None:

tests/timeseries/_pv_pool/test_pv_pool_control_methods.py

@@ -197,27 +197,38 @@ async def test_setting_power(  # pylint: disable=too-many-statements
 
         # After failing 1 inverter, bounds should go down and power shouldn't be
         # distributed to that inverter.
+        print(f"\n[TEST] ========== FAILING INVERTER {inv_ids[1]} ==========")
         await self._fail_pv_inverters([inv_ids[1]], mocks)
+        print("[TEST] Waiting for bounds to update to -80_000.0...")
         report = await self._recv_reports_until(
             bounds_rx,
             lambda x: x.bounds is not None and x.bounds.lower.as_watts() == -80_000.0,
         )
         assert report is not None, "No report meeting the condition was received"
+        print(f"[TEST] Got bounds report: {report}")
         self._assert_report(report, power=-4_000.0, lower=-80_000.0, upper=0.0)
 
         set_power.reset_mock()
+        print(f"\n[TEST] ========== PROPOSING NEW POWER -70_000.0 ==========")
+        print(f"[TEST] set_power call count before proposal: {set_power.call_count}")
         await pv_pool.propose_power(Power.from_watts(-70_000.0))
+        print("[TEST] Waiting for target power to be -70_000.0...")
         report = await self._recv_reports_until(
             bounds_rx,
             lambda x: x.target_power is not None
             and x.target_power.as_watts() == -70_000.0,
         )
 
         assert report is not None, "No report meeting the condition was received"
+        print(f"[TEST] Got target power report: {report}")
         self._assert_report(report, power=-70_000.0, lower=-80_000.0, upper=0.0)
+        print(repr(report))
         await asyncio.sleep(0.0)
 
         # Components are set initial power
+        print(f"\n[TEST] ========== CHECKING SET_POWER CALLS ==========")
+        print(f"[TEST] set_power.call_count = {set_power.call_count}")
+        print(f"[TEST] set_power.call_args_list = {set_power.call_args_list}")
         assert set_power.call_count == 3
         inv_ids = mocks.microgrid.pv_inverter_ids
         assert sorted(set_power.call_args_list, key=lambda x: x.args[0]) == [