Write the API traffic out when debug logging is on

Working out what this API does has twice meant asking a user to write and sign
their own requests, because nothing in the integration reported what it sent or
what came back. Every call already goes through one gate, so that is where the
trace belongs.

With debug on, each request is written out as it would be typed, with its full
response, how long it took and how long it waited for the call spacing.
Rejections carry the return code, transport failures the exception, and a retry
after a 6053 says so. Nothing is rendered when debug is off, and the clock is not
even read then, so the cost is a level check per call. Long responses are capped
rather than dropped - one day of power data is thousands of samples.

Three additions around it: the write log now carries the enable pair it sent,
which is the field that decides the inverter's working mode and the one that was
missing when it mattered; staging logs each field and the resulting draft; and a
lock or unlock of the schedule surface is announced once, with the read state,
the timed-control answer and the recorded flags that decided it. A user reporting
that the controls vanished should be answerable from the log alone.

README says how to turn it on, and warns that the log carries the serial.

Author: Poshy163

README.md

@@ -363,6 +363,26 @@ fast lane is still active, which is what to check when something else is sharing
 the same API account. Serials are replaced with `inverter_1`, `inverter_2` and so
 on, and credentials, keys and addresses are redacted.
 
+For anything the download cannot show — what happened, in what order — turn on
+debug logging:
+
+```yaml
+logger:
+  default: warning
+  logs:
+    custom_components.alphaess: debug
+    alphaess: debug
+```
+
+Every OpenAPI request and **its full response** is then written out, along with
+each staged field, each write and the enable pair sent with it, and a line
+whenever the schedule surface locks or unlocks and what decided it. That is the
+same information a hand-signed API request would give you, without signing one.
+Very large responses are capped rather than dropped. Requests carry no
+credentials — those live in the headers, which are not logged — but the log does
+contain your serial number, so trim it before posting if you would rather not
+share it.
+
 ### AlphaESS API limitations
 
 - The periodic API requires at least one complete charge period **and** one

custom_components/alphaess/const.py

@@ -44,6 +44,10 @@
 # up to five. Any 6053 drops the session back to the documented
 # MIN_API_CALL_INTERVAL_SECONDS and retries that one call once.
 FAST_API_CALL_INTERVAL_SECONDS = 1
+
+# Debug logging writes every API response out in full. getOneDayPowerBySn can
+# run to thousands of samples, so long ones are capped rather than dropped.
+MAX_LOGGED_RESPONSE_CHARS = 4000
 RATE_LIMIT_CODE = 6053
 MIN_FAST_SCAN_INTERVAL_SECONDS = MIN_API_CALL_INTERVAL_SECONDS
 MAX_FAST_SCAN_INTERVAL_SECONDS = 300

custom_components/alphaess/coordinator.py

@@ -24,6 +24,7 @@
     DOMAIN,
     FAST_API_CALL_INTERVAL_SECONDS,
     LOWER_INVERTER_API_CALL_LIST,
+    MAX_LOGGED_RESPONSE_CHARS,
     MIN_API_CALL_INTERVAL_SECONDS,
     RATE_LIMIT_CODE,
     SCAN_INTERVAL,
@@ -519,6 +520,10 @@ def __init__(
         self._periodic_enable_intent: dict[str, dict[str, int]] = {}
         self._periodic_enable_sent: dict[str, dict[str, int]] = {}
 
+        # Last logged schedule surface state per serial, so a lock or unlock is
+        # reported once with its reason rather than on every poll.
+        self._schedule_state_logged: dict[str, tuple] = {}
+
         # Entity changes are drafts. A user can edit start/end/limits/switches
         # without emitting a series of unsafe intermediate full replacements,
         # then commit once with the Apply Schedule button.
@@ -574,17 +579,51 @@ def _call_interval(self) -> float:
             )
         return self.throttle_multiplier
 
+    @staticmethod
+    def _describe_call(method, args, kwargs) -> str:
+        """Render one call the way it would be written by hand."""
+        shown = [repr(arg) for arg in args]
+        shown += [f"{key}={value!r}" for key, value in kwargs.items()]
+        return f"{getattr(method, '__name__', method)}({', '.join(shown)})"
+
+    @staticmethod
+    def _describe_response(value: Any) -> str:
+        """Render a response, capping the ones that run to thousands of lines."""
+        text = repr(value)
+        if len(text) <= MAX_LOGGED_RESPONSE_CHARS:
+            return text
+        return f"{text[:MAX_LOGGED_RESPONSE_CHARS]}... [{len(text)} chars]"
+
     async def _call_cloud_api(self, method, *args, **kwargs) -> Any:
-        """Call one OpenAPI endpoint after the currently required interval."""
+        """Call one OpenAPI endpoint after the currently required interval.
+
+        With debug logging on, every request and every response is written out.
+        Establishing what this API actually returns has needed hand-signed
+        requests more than once (#267); it should come out of a log instead.
+        """
+        tracing = _LOGGER.isEnabledFor(logging.DEBUG)
+        call = self._describe_call(method, args, kwargs) if tracing else ""
+        waited = 0.0
         async with self._api_request_lock:
             if self._last_api_request_completed is not None:
                 remaining = self._call_interval() - (
                     time_mod.monotonic() - self._last_api_request_completed
                 )
                 if remaining > 0:
+                    waited = remaining
                     await asyncio.sleep(remaining)
+            # Only read the clock when the answer will be used: tests and
+            # production alike should not pay for tracing that is switched off.
+            started = time_mod.monotonic() if tracing else 0.0
             try:
-                return await method(*args, **kwargs)
+                result = await method(*args, **kwargs)
+                if tracing:
+                    _LOGGER.debug(
+                        "API %s -> %s (%.2fs, waited %.2fs)",
+                        call, self._describe_response(result),
+                        time_mod.monotonic() - started, waited,
+                    )
+                return result
             except AlphaESSApiError as err:
                 if err.code == RATE_LIMIT_CODE and self._fast_api_lane:
                     # The fast lane overshot this server's limits. Fall back
@@ -596,7 +635,27 @@ async def _call_cloud_api(self, method, *args, **kwargs) -> Any:
                         "dropping to %ss spacing", self.throttle_multiplier,
                     )
                     await asyncio.sleep(self.throttle_multiplier)
-                    return await method(*args, **kwargs)
+                    retried = await method(*args, **kwargs)
+                    if tracing:
+                        _LOGGER.debug(
+                            "API %s retried after 6053 -> %s",
+                            call, self._describe_response(retried),
+                        )
+                    return retried
+                if tracing:
+                    _LOGGER.debug(
+                        "API %s -> %s (%.2fs, waited %.2fs)",
+                        call, describe_api_error(err),
+                        time_mod.monotonic() - started, waited,
+                    )
+                raise
+            except Exception as err:
+                if tracing:
+                    _LOGGER.debug(
+                        "API %s raised %s: %s (%.2fs, waited %.2fs)",
+                        call, type(err).__name__, err,
+                        time_mod.monotonic() - started, waited,
+                    )
                 raise
             finally:
                 # A rejected or indeterminate request still consumed an API
@@ -1227,11 +1286,44 @@ def _overlay_schedule_view(self, serial: str, data: dict[str, Any]) -> None:
                 committed[0] == 1 or committed[1] == 1
             )
 
+    def _note_schedule_surface(self, serial: str) -> None:
+        """Log a lock or unlock once, with what decided it.
+
+        A user reports "the controls went away"; this is the line that says
+        when, and on the strength of what.
+        """
+        state = (
+            self.get_periodic_read_state(serial),
+            self.is_time_based_control_active(serial),
+            self.can_modify_time_controls(serial),
+        )
+        if self._schedule_state_logged.get(serial) == state:
+            return
+        first_time = serial not in self._schedule_state_logged
+        self._schedule_state_logged[serial] = state
+        read_state, active, modifiable = state
+        message = (
+            "Schedule surface for %s is %s: periodic read %s, timed control %s, "
+            "recorded enable flags %s"
+        )
+        args = (
+            serial,
+            "editable" if modifiable else "locked",
+            read_state,
+            {True: "active", False: "inactive", None: "unknown"}[active],
+            self._periodic_enable_intent.get(serial) or "none recorded",
+        )
+        if first_time:
+            _LOGGER.debug(message, *args)
+        else:
+            _LOGGER.info(message, *args)
+
     def _publish_schedule_view(self, serial: str) -> None:
         """Publish a schedule view change to all coordinator entities."""
         if serial not in self.data:
             return
         self._overlay_schedule_view(serial, self.data[serial])
+        self._note_schedule_surface(serial)
         self.async_set_updated_data({key: dict(value) for key, value in self.data.items()})
 
     def stage_schedule_change(
@@ -1329,6 +1421,10 @@ def stage_schedule_change(
 
         for side, changes in (("charge", charge), ("discharge", discharge)):
             if changes:
+                _LOGGER.debug(
+                    "Staged %s for %s: %s (draft now %s)",
+                    side, serial, changes, self._schedule_drafts[serial][side],
+                )
                 self._schedule_drafts[serial][side].update(changes)
                 self._schedule_draft_dirty[serial][side].update(changes)
         self._schedule_draft_revisions[serial] = (
@@ -2141,8 +2237,9 @@ async def _safe_async_apply_schedule_locked(
         self._periodic_enable_intent[serial] = dict(enable)
         self._periodic_enable_sent[serial] = dict(enable)
         _LOGGER.info(
-            "Wrote periodic schedule for %s - charge: %s, discharge: %s",
+            "Wrote periodic schedule for %s - enable %s, charge: %s, discharge: %s",
             serial,
+            enable,
             periodic_proposed["chargeTimeList"],
             periodic_proposed["dischargeTimeList"],
         )

tests/test_schedule_edge_coverage.py

@@ -6,6 +6,7 @@
 from unittest.mock import AsyncMock
 
 import pytest
+from alphaess.alphaess import AlphaESSApiError
 from homeassistant.exceptions import ConfigEntryAuthFailed, HomeAssistantError
 
 from custom_components.alphaess.button import AlphaESSBatteryButton
@@ -1509,3 +1510,138 @@ def test_a_quick_button_will_not_create_a_period_without_a_cutoff(
                 discharge=None,
                 now_window=True,
             )
+
+
+class TestApiTracing:
+    """With debug logging on, the log should contain what a hand-signed request
+    would have told you - that is what it took to work out #267."""
+
+    async def test_a_call_and_its_answer_are_both_written_out(
+        self, make_coordinator, mock_api, caplog
+    ):
+        coordinator = make_coordinator()
+        schedule = _daily_schedule()
+        mock_api.getTimeChargeBySn.return_value = schedule
+
+        with caplog.at_level(logging.DEBUG, logger="custom_components.alphaess.coordinator"):
+            await coordinator._call_cloud_api(mock_api.getTimeChargeBySn, SERIAL)
+
+        trace = [r.getMessage() for r in caplog.records if "API " in r.getMessage()]
+        assert trace, caplog.text
+        assert SERIAL in trace[0]
+        assert "chargeTimeList" in trace[0]
+
+    async def test_keyword_arguments_are_shown_as_written(
+        self, make_coordinator, mock_api, caplog
+    ):
+        coordinator = make_coordinator()
+
+        with caplog.at_level(logging.DEBUG, logger="custom_components.alphaess.coordinator"):
+            await coordinator._call_cloud_api(
+                mock_api.setTimeChargeBySn,
+                sysSn=SERIAL,
+                executeCycleType=0,
+                chargeTimeList=[],
+                dischargeTimeList=[],
+                gridChargeCycle=1,
+                ctrDisCycle=0,
+            )
+
+        # The pair that decides the working mode has to be in the log.
+        assert "gridChargeCycle=1" in caplog.text
+        assert "ctrDisCycle=0" in caplog.text
+
+    async def test_a_rejection_is_traced_with_its_return_code(
+        self, make_coordinator, mock_api, caplog
+    ):
+        coordinator = make_coordinator()
+        mock_api.getTimeChargeBySn.side_effect = _api_error(6017)
+
+        with caplog.at_level(logging.DEBUG, logger="custom_components.alphaess.coordinator"):
+            with pytest.raises(AlphaESSApiError):
+                await coordinator._call_cloud_api(mock_api.getTimeChargeBySn, SERIAL)
+
+        assert "6017" in caplog.text
+
+    async def test_a_transport_failure_is_traced_too(
+        self, make_coordinator, mock_api, caplog
+    ):
+        coordinator = make_coordinator()
+        mock_api.getTimeChargeBySn.side_effect = TimeoutError("no response")
+
+        with caplog.at_level(logging.DEBUG, logger="custom_components.alphaess.coordinator"):
+            with pytest.raises(TimeoutError):
+                await coordinator._call_cloud_api(mock_api.getTimeChargeBySn, SERIAL)
+
+        assert "TimeoutError" in caplog.text
+
+    async def test_a_retry_after_a_rate_limit_is_traced(
+        self, make_coordinator, mock_api, caplog
+    ):
+        coordinator = make_coordinator()
+        mock_api.getTimeChargeBySn.side_effect = [_api_error(6053), {"ok": True}]
+
+        with caplog.at_level(logging.DEBUG, logger="custom_components.alphaess.coordinator"):
+            result = await coordinator._call_cloud_api(
+                mock_api.getTimeChargeBySn, SERIAL,
+            )
+
+        assert result == {"ok": True}
+        assert "retried after 6053" in caplog.text
+
+    def test_a_huge_response_is_capped_rather_than_dropped(self, make_coordinator):
+        """getOneDayPowerBySn runs to thousands of samples; the log stays
+        usable without losing the fact that an answer arrived."""
+        coordinator = make_coordinator()
+        rendered = coordinator._describe_response([{"cbat": 55}] * 5000)
+
+        assert rendered.endswith("chars]")
+        assert len(rendered) < 4200
+
+    async def test_nothing_is_rendered_when_tracing_is_off(
+        self, make_coordinator, mock_api, caplog
+    ):
+        coordinator = make_coordinator()
+        mock_api.getTimeChargeBySn.return_value = _daily_schedule()
+
+        with caplog.at_level(logging.INFO, logger="custom_components.alphaess.coordinator"):
+            await coordinator._call_cloud_api(mock_api.getTimeChargeBySn, SERIAL)
+
+        assert "API " not in caplog.text
+
+
+class TestScheduleSurfaceLogging:
+    """A user reports that the controls went away; the log should say when and
+    on the strength of what."""
+
+    async def test_a_lock_is_announced_with_its_reason(
+        self, make_coordinator, mock_api, caplog
+    ):
+        coordinator = _seed(
+            make_coordinator(), periodic=_daily_schedule(), readable=True,
+        )
+        coordinator._publish_schedule_view(SERIAL)  # first pass: debug only
+
+        with caplog.at_level(logging.INFO, logger="custom_components.alphaess.coordinator"):
+            coordinator.set_periodic_enable_intent(
+                SERIAL, grid_charge=0, ctr_dis=0,
+            )
+            coordinator._publish_schedule_view(SERIAL)
+
+        assert "is locked" in caplog.text
+        assert "periodic read readable" in caplog.text
+        assert "timed control inactive" in caplog.text
+
+    async def test_the_same_state_is_not_repeated_every_poll(
+        self, make_coordinator, mock_api, caplog
+    ):
+        coordinator = _seed(
+            make_coordinator(), periodic=_daily_schedule(), readable=True,
+        )
+        coordinator._publish_schedule_view(SERIAL)
+
+        with caplog.at_level(logging.INFO, logger="custom_components.alphaess.coordinator"):
+            for _ in range(5):
+                coordinator._publish_schedule_view(SERIAL)
+
+        assert "Schedule surface" not in caplog.text