diff --git a/README.md b/README.md index 772304b..7939e2a 100644 --- a/README.md +++ b/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 `._`: +Default entity IDs are `._`. Installs that +predate the serial-prefixed rename keep their original IDs, which carry the +device name as well (`sensor.home_alpha_ess_energy_statistics__...`) — +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. diff --git a/custom_components/alphaess/const.py b/custom_components/alphaess/const.py index 5e8ce92..b50c5e5 100644 --- a/custom_components/alphaess/const.py +++ b/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 diff --git a/custom_components/alphaess/coordinator.py b/custom_components/alphaess/coordinator.py index b19abc3..36edb50 100644 --- a/custom_components/alphaess/coordinator.py +++ b/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,8 +1839,6 @@ def _patch_periodic_schedule( "charge": { "changes": charge, "list": "chargeTimeList", - "cycle": "gridChargeCycle", - "cycle_field": "gridCharge", "limit": "batHighCap", "start": "timeChaf", "end": "timeChae", @@ -1743,8 +1846,6 @@ def _patch_periodic_schedule( "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. diff --git a/custom_components/alphaess/diagnostics.py b/custom_components/alphaess/diagnostics.py index f3f388e..387c201 100644 --- a/custom_components/alphaess/diagnostics.py +++ b/custom_components/alphaess/diagnostics.py @@ -45,6 +45,15 @@ async def async_get_config_entry_diagnostics( for idx, serial in enumerate(coordinator.data or {}) } + # The state behind the schedule surface: which store governs, why the + # controls are in the state they are, and what the stores actually hold. + # None of it identifies anyone, and it is what a report needs to be + # answerable without a round trip. + schedule = { + f"inverter_{idx + 1}": coordinator.schedule_diagnostics(serial) + for idx, serial in enumerate(coordinator.data or {}) + } + return { "entry": { "data": async_redact_data(dict(entry.data), TO_REDACT_CONFIG), @@ -62,6 +71,8 @@ async def async_get_config_entry_diagnostics( "model_list": coordinator.model_list, "has_throttle": coordinator.has_throttle, "periodic_schedule_read": periodic_schedule_read, + "api": coordinator.api_diagnostics(), }, + "schedule": schedule, "data": inverters, } diff --git a/tests/test_device_diagnostics.py b/tests/test_device_diagnostics.py index 23d2166..60f7c91 100644 --- a/tests/test_device_diagnostics.py +++ b/tests/test_device_diagnostics.py @@ -1,4 +1,6 @@ """Tests for device info builders and diagnostics.""" +import time as time_mod + from custom_components.alphaess.device import ( build_ev_charger_device_info, build_inverter_device_info, @@ -97,3 +99,112 @@ async def test_diagnostics_with_empty_data(self, mock_hass, make_coordinator): result = await async_get_config_entry_diagnostics(mock_hass, entry) assert result["data"] == {} + + +class TestScheduleDiagnostics: + """Every field here exists because answering a report needed it and the + download did not have it.""" + + def _periodic(self): + return { + "executeCycleType": 1, + "chargeTimeList": [ + { + "beginTime": "05:00", + "endTime": "06:00", + "weeks": [1, 2, 3, 4, 5, 6, 7], + "chargePower": 5000, + "chargeLimit": 55, + } + ], + "dischargeTimeList": [], + } + + async def test_a_periodic_system_reports_why_it_is_in_that_state( + self, mock_hass, make_coordinator + ): + coordinator = make_coordinator() + coordinator.data = {"AL_SERIAL": {"Model": "SMILE-G3-S5-INV"}} + coordinator._periodic_readable["AL_SERIAL"] = True + coordinator._periodic_schedules["AL_SERIAL"] = self._periodic() + coordinator.set_periodic_enable_intent( + "AL_SERIAL", grid_charge=1, ctr_dis=0, + ) + coordinator.last_charge_update["AL_SERIAL"] = time_mod.monotonic() + entry = FakeEntry() + entry.runtime_data = coordinator + + result = await async_get_config_entry_diagnostics(mock_hass, entry) + schedule = result["schedule"]["inverter_1"] + + assert schedule["governing_store"] == "periodic" + assert schedule["periodic_read"] == "readable" + assert schedule["periodic_write_denied"] is False + # The write-only pair: the only record there is. + assert schedule["enable_intent"] == { + "gridChargeCycle": 1, "ctrDisCycle": 0, + } + # The resource itself, so an empty list is visible without asking. + assert schedule["periodic_snapshot"]["dischargeTimeList"] == [] + assert schedule["capabilities"]["can_modify_time_controls"] is True + assert schedule["draft"] is None + assert schedule["seconds_since_last_charge_write"] is not None + assert schedule["seconds_since_last_discharge_write"] is None + assert result["coordinator"]["api"]["fast_api_lane"] is True + + async def test_a_backup_system_reports_the_legacy_snapshot( + self, mock_hass, make_coordinator + ): + """The store a migrated system no longer uses is exactly what needs to + be visible when it is the one being read.""" + coordinator = make_coordinator() + coordinator.data = {"AL_SERIAL": {"Model": "SMILE5-INV"}} + coordinator._periodic_readable["AL_SERIAL"] = False + coordinator._legacy_schedules["AL_SERIAL"] = { + "charge": {"gridCharge": 0, "timeChaf1": "17:00", "timeChae1": "17:15"}, + "discharge": {"ctrDis": 0, "timeDisf1": "00:00", "timeDise1": "00:00"}, + } + entry = FakeEntry() + entry.runtime_data = coordinator + + result = await async_get_config_entry_diagnostics(mock_hass, entry) + schedule = result["schedule"]["inverter_1"] + + assert schedule["governing_store"] == "legacy-backup" + assert schedule["legacy_snapshot"]["charge"]["timeChaf1"] == "17:00" + assert schedule["capabilities"]["can_reset_schedule"] is True + + async def test_an_open_draft_is_described(self, mock_hass, make_coordinator): + coordinator = make_coordinator() + coordinator.data = {"AL_SERIAL": {"Model": "SMILE-G3-S5-INV"}} + coordinator._periodic_readable["AL_SERIAL"] = True + coordinator._periodic_schedules["AL_SERIAL"] = self._periodic() + coordinator.set_periodic_enable_intent( + "AL_SERIAL", grid_charge=1, ctr_dis=1, + ) + coordinator.stage_schedule_change("AL_SERIAL", charge={"timeChaf1": "02:00"}) + entry = FakeEntry() + entry.runtime_data = coordinator + + result = await async_get_config_entry_diagnostics(mock_hass, entry) + draft = result["schedule"]["inverter_1"]["draft"] + + assert draft["dirty"]["charge"] == ["timeChaf1"] + assert draft["apply_in_progress"] is False + assert draft["staged"]["charge"]["timeChaf1"] == "02:00" + + async def test_a_system_with_no_usable_store_says_so( + self, mock_hass, make_coordinator + ): + coordinator = make_coordinator() + coordinator.data = {"AL_SERIAL": {"Model": "SMILE5-INV"}} + entry = FakeEntry() + entry.runtime_data = coordinator + + result = await async_get_config_entry_diagnostics(mock_hass, entry) + schedule = result["schedule"]["inverter_1"] + + assert schedule["governing_store"] == "none" + assert schedule["periodic_read"] == "unknown" + assert schedule["enable_intent"] is None + assert schedule["capabilities"]["can_stage_schedule"] is False diff --git a/tests/test_periodic_schedule.py b/tests/test_periodic_schedule.py index 8f83c52..959e0a5 100644 --- a/tests/test_periodic_schedule.py +++ b/tests/test_periodic_schedule.py @@ -885,6 +885,40 @@ async def test_one_sided_knowledge_is_still_not_an_answer( mock_api.setTimeChargeBySn.assert_not_awaited() + def test_half_a_restored_answer_does_not_break_the_switches( + self, make_coordinator + ): + """Reported on #267: one switch restores its state and the other has + none, so the entity view holds a None the last-timer guard tried to + cast. Nothing here is knowable enough to guard on, and guessing at the + missing side would invent the answer this store cannot give.""" + periodic = _daily_schedule() + coordinator = _seed(make_coordinator(), periodic=deepcopy(periodic), readable=True) + coordinator._periodic_enable_intent[SERIAL] = {"ctrDisCycle": 1} + coordinator._overlay_schedule_view(SERIAL, coordinator.data[SERIAL]) + + assert coordinator._committed_enable_flags(SERIAL) is None + + coordinator.stage_schedule_change(SERIAL, charge={"timeChaf1": "02:00"}) + coordinator.stage_schedule_change(SERIAL, charge={"gridCharge": 1}) + + assert coordinator._schedule_drafts[SERIAL]["charge"]["gridCharge"] == 1 + + async def test_an_incomplete_answer_still_refuses_the_write( + self, make_coordinator, mock_api + ): + """Skipping the guard does not let a half-known pair reach the API.""" + periodic = _daily_schedule() + coordinator = _seed(make_coordinator(), periodic=deepcopy(periodic), readable=True) + coordinator._periodic_enable_intent[SERIAL] = {"ctrDisCycle": 1} + mock_api.getTimeChargeBySn.return_value = deepcopy(periodic) + + coordinator.stage_schedule_change(SERIAL, charge={"timeChaf1": "02:00"}) + with pytest.raises(ScheduleWriteError, match="does not know whether"): + await coordinator.async_apply_schedule_draft(SERIAL) + + mock_api.setTimeChargeBySn.assert_not_awaited() + async def test_a_flag_only_change_still_reaches_the_api( self, make_coordinator, mock_api ): diff --git a/tests/test_schedule_edge_coverage.py b/tests/test_schedule_edge_coverage.py index 031a381..d221307 100644 --- a/tests/test_schedule_edge_coverage.py +++ b/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