Fix the half-known flag crash, and make diagnostics answer the question

README.md

@@ -159,7 +159,10 @@ them:
 Do not mix them on one inverter. A service write replaces the remote schedule,
 so a draft staged before it fails its next Apply as a conflict.
 
-Default entity IDs are `<domain>.<serial in lower case>_<name>`:
+Default entity IDs are `<domain>.<serial in lower case>_<name>`. Installs that
+predate the serial-prefixed rename keep their original IDs, which carry the
+device name as well (`sensor.home_alpha_ess_energy_statistics_<serial>_...`) —
+check the entity list rather than assuming the short form:
 
 | Purpose | Entity |
 | --- | --- |
@@ -337,12 +340,59 @@ until a full periodic read succeeds. The integration never builds a
 replacement schedule from anything but a fresh read, because doing so could
 erase weekly settings, extra periods, or power values that it cannot see.
 
+### Reporting a schedule problem
+
+**Settings → Devices & Services → AlphaESS → ⋮ → Download diagnostics** answers
+most of what a report needs, without anyone having to sign API requests by hand.
+Alongside the usual entry and entity data, the `schedule` section carries, per
+inverter:
+
+- `governing_store` and `periodic_read` — which surface the system is on;
+- `capabilities` — the exact flags behind every unavailable control, so a locked
+  UI explains itself;
+- `enable_intent` / `enable_last_sent` — the write-only pair, which nothing else
+  can report;
+- `periodic_snapshot` and `legacy_snapshot` — what each store actually held,
+  including an empty period list or a stale window the app no longer shows;
+- `draft` — what is staged, which fields are dirty, and whether an Apply is in
+  flight;
+- cooldowns and consecutive poll errors.
+
+The `coordinator.api` section reports the current call spacing and whether the
+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
-  complete discharge period. The integration never inserts a fake
-  `00:00-00:00` period. If either list would be empty, Apply fails rather than
-  replacing an app-managed schedule with incomplete data.
+  complete discharge period: an empty list answers `6001` and a missing one
+  `10001`. The integration never inserts a fake `00:00-00:00` period. If either
+  list would be empty, Apply fails rather than replacing an app-managed schedule
+  with incomplete data. AlphaESS itself will happily *store* an empty list, so a
+  system with no discharge periods cannot be written to from Home Assistant at
+  all until one exists — add a period to that side in the app, or give it one and
+  turn its switch off, which is how the API is told to run a single side.
 - Both a start and end time must be set before adding a new period. Existing
   weekly periods can be edited while retaining their weekdays, but the entity UI
   cannot add a new weekly period because it has no weekday selector.

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(
@@ -1286,16 +1378,25 @@ def stage_schedule_change(
                 "Scheduled Charging or Scheduled Discharging on to re-enable a "
                 "timer; a working mode can only be changed in the AlphaESS app"
             )
-        if active is True:
-            # Refuse to author the 0/0 flag state: it is indistinguishable
-            # from a self-consumption mode afterwards, and leaving it is
-            # app-only anyway. Disable the last timer from the app instead.
-            flags = self._committed_enable_flags(serial) or (1, 1)
+        flags = self._committed_enable_flags(serial)
+        if active is True and flags is not None:
+            # Refuse to author the 0/0 flag state: on the legacy store it is
+            # indistinguishable from a self-consumption mode afterwards, and
+            # on the periodic store it is the request that switches the
+            # inverter into one. Only guard when both committed flags are
+            # actually known - guessing at the other side would be inventing
+            # the very answer this store cannot supply.
             grid_flag, dis_flag = flags
             draft = self._schedule_drafts.get(serial)
             if draft is not None:
-                grid_flag = int(draft["charge"].get("gridCharge", grid_flag))
-                dis_flag = int(draft["discharge"].get("ctrDis", dis_flag))
+                # A staged half can be None (nothing recorded for that side
+                # yet), which is not a value to fall back from.
+                staged_grid = draft["charge"].get("gridCharge")
+                staged_dis = draft["discharge"].get("ctrDis")
+                if staged_grid is not None:
+                    grid_flag = int(staged_grid)
+                if staged_dis is not None:
+                    dis_flag = int(staged_dis)
             if charge and "gridCharge" in charge:
                 grid_flag = int(charge["gridCharge"])
             if discharge and "ctrDis" in discharge:
@@ -1320,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] = (
@@ -1734,17 +1839,13 @@ def _patch_periodic_schedule(
             "charge": {
                 "changes": charge,
                 "list": "chargeTimeList",
-                "cycle": "gridChargeCycle",
-                "cycle_field": "gridCharge",
                 "limit": "batHighCap",
                 "start": "timeChaf",
                 "end": "timeChae",
             },
             "discharge": {
                 "changes": discharge,
                 "list": "dischargeTimeList",
-                "cycle": "ctrDisCycle",
-                "cycle_field": "ctrDis",
                 "limit": "batUseCap",
                 "start": "timeDisf",
                 "end": "timeDise",
@@ -2136,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"],
         )
@@ -2588,6 +2690,71 @@ def _update_diagnostics(self) -> None:
                 self.get_periodic_read_state(serial)
             )
 
+    def schedule_diagnostics(self, serial: str) -> dict[str, Any]:
+        """Return everything needed to explain a schedule state from a report.
+
+        Every field here answers a question that has cost a round trip with a
+        tester: which store governs, why the controls are locked, what the two
+        write-only enable flags were last set to, and what the stores actually
+        held at the time. It must never raise - a diagnostics download is often
+        the only thing a user can still produce.
+        """
+        draft = self._schedule_drafts.get(serial)
+        dirty = self._schedule_draft_dirty.get(serial) or {}
+        now = time_mod.monotonic()
+
+        def _cooldown(store: dict[str, float]) -> float | None:
+            started = store.get(serial)
+            return None if started is None else round(now - started, 1)
+
+        if self.is_periodic_schedule_readable(serial):
+            governing_store = "periodic"
+        elif self.is_legacy_backup_active(serial):
+            governing_store = "legacy-backup"
+        else:
+            governing_store = "none"
+
+        return {
+            "governing_store": governing_store,
+            "periodic_read": self.get_periodic_read_state(serial),
+            "periodic_write_denied": serial in self._periodic_write_denied,
+            "capabilities": {
+                "time_based_control_active": self.is_time_based_control_active(serial),
+                "can_stage_schedule": self.can_stage_schedule(serial),
+                "can_modify_time_controls": self.can_modify_time_controls(serial),
+                "can_unlock_time_controls": self.can_unlock_time_controls(serial),
+                "can_reset_schedule": self.can_reset_schedule(serial),
+            },
+            # Write-only on the periodic API: the read reports 0 for both
+            # whatever the inverter is set to, so this record is the only
+            # answer there is, and an absent one blocks every write.
+            "enable_intent": self._periodic_enable_intent.get(serial),
+            "enable_last_sent": self._periodic_enable_sent.get(serial),
+            "periodic_snapshot": self._periodic_schedules.get(serial),
+            "legacy_snapshot": self._legacy_schedules.get(serial),
+            "draft": None if draft is None else {
+                "dirty": {side: sorted(fields) for side, fields in dirty.items()},
+                "revision": self._schedule_draft_revisions.get(serial, 0),
+                "apply_in_progress": serial in self._schedule_apply_in_progress,
+                "staged": draft,
+            },
+            "number_settings": self.number_settings.get(serial),
+            "seconds_since_last_charge_write": _cooldown(self.last_charge_update),
+            "seconds_since_last_discharge_write": _cooldown(self.last_discharge_update),
+            "consecutive_poll_errors": self._inverter_error_count.get(serial, 0),
+        }
+
+    def api_diagnostics(self) -> dict[str, Any]:
+        """Return how the client is currently pacing and answering."""
+        return {
+            "fast_api_lane": self._fast_api_lane,
+            "call_interval_seconds": self._call_interval(),
+            "throttle_multiplier": self.throttle_multiplier,
+            "last_poll_type": self._last_poll_type,
+            "last_full_poll": self._last_full_poll_utc or "never",
+            "poll_tick_count": self._poll_tick_count,
+        }
+
     def get_periodic_read_state(self, serial: str) -> str:
         """Return whether the periodic schedule can be read on this account.