Skip to content

Commit 9985d8f

Browse files
fix(enphase): retry POST-create on conflict, disambiguate HTTP logs, surface write failures
Addresses the three follow-ups from #4461, filed after #4428/#4429 shipped: - The retry-once-and-prune conflict handling from #4428 only covered the PUT (update) path. The POST (create) path - taken whenever no schedule id is cached yet, e.g. right after a disable/re-enable during the plan's Charging<->Exporting oscillation - had no retry at all, so a stray untracked schedule there could 409 nightly forever. Added _create_schedule_with_conflict_retry, mirroring the PUT path: re-read and retry once on conflict, via PUT if the re-read finds an adoptable id or POST again if not. - The generic "HTTP {status} on {path}" failure log couldn't tell a GET, a POST create and a PUT update apart when they shared the same bare /schedules path shape. request_json now logs the method and an optional caller-supplied context (schedule family/action). - Enphase writes go through an HA switch/select bridge that always looks like it "succeeded" regardless of the cloud's response, so predbat.status/binary_sensor.predbat_exporting kept reporting the intended plan with no sign a write never landed. Failed writes now bump the component's error count (visible on components_healthy) and flag a new binary_sensor.predbat_enphase_<site>_schedule_write_ok sensor naming the failing family. The debounce/settle-interval idea floated in the issue is deliberately not implemented here - it's speculative and needs real-account behaviour to design safely. Bumped v8.47.6 -> v8.47.7. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
1 parent df96f89 commit 9985d8f

3 files changed

Lines changed: 254 additions & 20 deletions

File tree

apps/predbat/enphase.py

Lines changed: 98 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -351,6 +351,11 @@ def initialize(self, username, password, site_id=None, automatic=False, automati
351351
self.last_midnight_utc = None
352352
self.last_error_status = None # HTTP status (or None) of the most recent request_json() failure
353353

354+
# site_id -> {family_key: True} for schedule/reserve writes that failed outright (all
355+
# retries exhausted), so the failure is visible on the dashboard instead of only in the
356+
# log - see _note_schedule_write_result / _publish_schedule_write_health.
357+
self.schedule_write_failed = {}
358+
354359
def is_alive(self):
355360
"""Return True when the component has started and discovered a site."""
356361
return self.api_started and bool(self.sites)
@@ -678,14 +683,38 @@ def sync_local_schedule_from_cloud(self, site_id):
678683
local[direction]["enable"] = bool(entry.get("enabled"))
679684
self._schedule_seeded.add(site_id)
680685

686+
async def _publish_schedule_write_health(self, site_id):
687+
"""Publish a dedicated sensor reporting whether recent schedule/reserve writes landed.
688+
689+
A write that fails outright (a conflict surviving every retry, a failed delete or
690+
activation) previously only ever appeared as a log warning - `predbat.status` kept
691+
reporting the *intended* plan with no visible sign the cloud never actually accepted it
692+
(#4461). This sensor stays "on" (ok) until a write fails, and reports exactly which
693+
families/writes are currently failing so the mismatch is visible on the dashboard.
694+
"""
695+
failures = self.schedule_write_failed.get(site_id, {})
696+
self.dashboard_item(
697+
f"binary_sensor.{self.prefix}_enphase_{site_id}_schedule_write_ok",
698+
state="off" if failures else "on",
699+
attributes={
700+
"friendly_name": f"Enphase {site_id} Schedule Write Ok",
701+
"icon": "mdi:cloud-check-outline" if not failures else "mdi:cloud-alert-outline",
702+
"failed": sorted(failures.keys()),
703+
},
704+
app="enphase",
705+
)
706+
681707
async def publish_schedule_settings_ha(self, site_id):
682708
"""Publish the schedule control entities for a site.
683709
684710
Publishes the reserve control plus both the charge-from-grid and export (discharge-to-grid)
685711
window controls (a configured inverter always supports both - automatic_config requires
686712
DTG). There is no separate freeze control: Predbat freezes charge via the reserve, and
687-
freeze-export is derived automatically from an export target SOC of 99%.
713+
freeze-export is derived automatically from an export target SOC of 99%. Also (re)publishes
714+
the schedule-write-health sensor, so a write failure is reflected immediately after the
715+
attempt (switch_event) and kept current on every subsequent poll (run()).
688716
"""
717+
await self._publish_schedule_write_health(site_id)
689718
local = self.local_schedule.setdefault(site_id, self._default_local_schedule())
690719
reserve_min = int(self.battery_settings.get(site_id, {}).get("veryLowSocMin", 5) or 5)
691720
base_name = f"{self.prefix}_enphase_{site_id}_battery_schedule"
@@ -835,11 +864,15 @@ async def _write_schedule(self, site_id, family, start_time_ha, end_time_ha, lim
835864
836865
Converts the HA "HH:MM:SS" option times to Enphase "HH:MM" format, then compares against
837866
the cached cloud schedule via `schedules_equal()`. A matching schedule is a no-op. Otherwise
838-
it updates the existing schedule by id (`PUT`) or creates a new one (`POST`). On success it
839-
optimistically updates our cached copy to the written state and returns - the periodic
840-
settings re-read will correct it if the write did not actually land. A create additionally
841-
re-reads the schedules once, to capture the cloud-assigned scheduleId (so later edits update
842-
in place rather than creating duplicates - the write responses do not return the id).
867+
it updates the existing schedule by id (`PUT`) or creates a new one (`POST`), each retrying
868+
once on a conflict via `_put_schedule_with_conflict_retry` / `_create_schedule_with_conflict_retry`.
869+
On success it optimistically updates our cached copy to the written state and returns - the
870+
periodic settings re-read will correct it if the write did not actually land. A create
871+
additionally re-reads the schedules once, to capture the cloud-assigned scheduleId (so later
872+
edits update in place rather than creating duplicates - the write responses do not return the
873+
id). Every attempted write records its outcome via `_note_schedule_write_result`, so a write
874+
that is attempted but never lands is visible instead of silently leaving the device on its
875+
previous schedule.
843876
Returns True if a write was issued.
844877
"""
845878
start_hm = ha_time_to_enphase(start_time_ha)
@@ -858,7 +891,8 @@ async def _write_schedule(self, site_id, family, start_time_ha, end_time_ha, lim
858891
# and keeps enforcing the window), so the only way to retire a window is to delete it.
859892
# A lingering window would also conflict with the other family's next write.
860893
self.log(f"Enphase: Deleting {family} schedule {schedule_id} on site {site_id} (window no longer required)")
861-
if not await self._delete_schedule(site_id, schedule_id):
894+
if not await self._delete_schedule(site_id, schedule_id, context=f"{family} disable"):
895+
self._note_schedule_write_result(site_id, family_key, False)
862896
return False
863897
# Drop the id/window so the next apply is a no-op while disabled, and a re-enable creates
864898
# a fresh schedule rather than PUTting an id the cloud no longer knows.
@@ -867,6 +901,7 @@ async def _write_schedule(self, site_id, family, start_time_ha, end_time_ha, lim
867901
cleared.pop(field, None)
868902
cleared["enabled"] = False
869903
self.schedules.setdefault(site_id, {})[family_key] = cleared
904+
self._note_schedule_write_result(site_id, family_key, True)
870905
return True
871906
if schedule_id:
872907
self.log(f"Enphase: Updating {family} schedule {schedule_id} on site {site_id}: {start_hm}-{end_hm} limit={limit} enabled={enabled}")
@@ -878,10 +913,11 @@ async def _write_schedule(self, site_id, family, start_time_ha, end_time_ha, lim
878913
self.schedules.setdefault(site_id, {})[family_key] = updated
879914
else:
880915
self.log(f"Enphase: Creating {family} schedule on site {site_id}: {start_hm}-{end_hm} limit={limit} enabled={enabled}")
881-
result = await self.request_json("POST", f"{BATTERY_CONFIG_BASE}/battery/sites/{site_id}/schedules", family="battery_config", json_body=payload)
916+
result = await self._create_schedule_with_conflict_retry(site_id, family_key, payload)
882917
if result is not None:
883918
# Re-read once so we learn the new schedule's cloud-assigned id for future edits.
884919
await self.get_schedules(site_id)
920+
self._note_schedule_write_result(site_id, family_key, result is not None)
885921
return result is not None
886922

887923
async def _put_schedule_with_conflict_retry(self, site_id, family_key, schedule_id, payload):
@@ -894,26 +930,47 @@ async def _put_schedule_with_conflict_retry(self, site_id, family_key, schedule_
894930
and retrying it again would just burn API calls every cycle.
895931
"""
896932
for attempt in range(2):
897-
result = await self.request_json("PUT", f"{BATTERY_CONFIG_BASE}/battery/sites/{site_id}/schedules/{schedule_id}", family="battery_config", json_body=payload)
933+
result = await self.request_json("PUT", f"{BATTERY_CONFIG_BASE}/battery/sites/{site_id}/schedules/{schedule_id}", family="battery_config", json_body=payload, context=f"{family_key.upper()} schedule update")
898934
if result is not None or self.last_error_status != 409 or attempt:
899935
return result
900936
self.log(f"Enphase: Schedule {schedule_id} on site {site_id} conflicts with another schedule; re-reading schedules and retrying once")
901937
await self.get_schedules(site_id)
902938
schedule_id = (self.schedules.get(site_id, {}).get(family_key) or {}).get("id") or schedule_id
903939
return None
904940

941+
async def _create_schedule_with_conflict_retry(self, site_id, family_key, payload):
942+
"""POST a new schedule, re-reading and retrying once if the cloud reports a conflict.
943+
944+
Mirrors `_put_schedule_with_conflict_retry` for the create path, which #4428 left without a
945+
retry: an HTTP 409 here means an untracked schedule already occupies the family - a sibling
946+
`_prune_sibling_schedules` had not yet reached, or one left over from an earlier create whose
947+
response Predbat never saw. Re-reading picks it up: `get_schedules` prunes any sibling (so
948+
the retried POST no longer collides with it) and, if a schedule remains in the family, adopts
949+
its id (so the retry goes out as a PUT instead of a second POST). Retried once only, matching
950+
the PUT path.
951+
"""
952+
result = await self.request_json("POST", f"{BATTERY_CONFIG_BASE}/battery/sites/{site_id}/schedules", family="battery_config", json_body=payload, context=f"{family_key.upper()} schedule create")
953+
if result is not None or self.last_error_status != 409:
954+
return result
955+
self.log(f"Enphase: Create of a new {family_key.upper()} schedule on site {site_id} conflicts with another schedule; re-reading schedules and retrying once")
956+
await self.get_schedules(site_id)
957+
schedule_id = (self.schedules.get(site_id, {}).get(family_key) or {}).get("id")
958+
if schedule_id:
959+
return await self.request_json("PUT", f"{BATTERY_CONFIG_BASE}/battery/sites/{site_id}/schedules/{schedule_id}", family="battery_config", json_body=payload, context=f"{family_key.upper()} schedule update after create conflict")
960+
return await self.request_json("POST", f"{BATTERY_CONFIG_BASE}/battery/sites/{site_id}/schedules", family="battery_config", json_body=payload, context=f"{family_key.upper()} schedule create retry")
961+
905962
def _is_read_only(self):
906963
"""Return True when Predbat is in read-only mode and must not write to the account."""
907964
return self.get_state_wrapper(f"switch.{self.prefix}_set_read_only", default="off") == "on"
908965

909-
async def _delete_schedule(self, site_id, schedule_id):
966+
async def _delete_schedule(self, site_id, schedule_id, context=None):
910967
"""Delete one schedule by id. Returns True on success.
911968
912969
Deletion is a POST to the schedule's /delete sub-resource. The gateway does not allow the
913970
DELETE verb here - it rejects it with "403 Invalid CORS request" - and because a 403 counts
914971
as an auth failure, using it also burned a re-login on every attempt.
915972
"""
916-
result = await self.request_json("POST", f"{BATTERY_CONFIG_BASE}/battery/sites/{site_id}/schedules/{schedule_id}/delete", family="battery_config", allow_empty=True)
973+
result = await self.request_json("POST", f"{BATTERY_CONFIG_BASE}/battery/sites/{site_id}/schedules/{schedule_id}/delete", family="battery_config", allow_empty=True, context=context)
917974
return result is not None
918975

919976
async def _prune_sibling_schedules(self, site_id, family_key, details, keep):
@@ -959,6 +1016,23 @@ def _invalidate_cached_schedule(self, site_id, family):
9591016
if isinstance(entry, dict):
9601017
entry["startTime"] = ""
9611018

1019+
def _note_schedule_write_result(self, site_id, family_key, ok):
1020+
"""Track whether the most recent write/activation for a schedule family landed on the cloud.
1021+
1022+
A write that fails outright (a conflict surviving every retry, a failed delete, a failed
1023+
activation PUT) otherwise only ever shows up as a generic HTTP warning in the log -
1024+
`predbat.status` keeps reporting the *intended* plan with no visible sign the device never
1025+
actually changed (#4461). ``count_errors`` feeds the existing per-component error count on
1026+
the `components_healthy` sensor; ``schedule_write_failed`` backs the dedicated per-family
1027+
warning published by `_publish_schedule_write_health`. Cleared on the next successful write.
1028+
"""
1029+
failures = self.schedule_write_failed.setdefault(site_id, {})
1030+
if ok:
1031+
failures.pop(family_key, None)
1032+
else:
1033+
failures[family_key] = True
1034+
self.count_errors += 1
1035+
9621036
async def _activate_control_mode(self, site_id, family, body, apply_cache, label):
9631037
"""Commit a freshly written schedule to the gateway via a batterySettings PUT.
9641038
@@ -972,15 +1046,17 @@ async def _activate_control_mode(self, site_id, family, body, apply_cache, label
9721046
params = {"source": "enho"}
9731047
if self.user_id:
9741048
params["userId"] = self.user_id
975-
result = await self.request_json("PUT", f"{BATTERY_CONFIG_BASE}/batterySettings/{site_id}", family="battery_config", params=params, json_body=body)
1049+
result = await self.request_json("PUT", f"{BATTERY_CONFIG_BASE}/batterySettings/{site_id}", family="battery_config", params=params, json_body=body, context=f"{label} activation")
1050+
family_key = family.lower()
9761051
if result is not None:
9771052
apply_cache(self.battery_settings.setdefault(site_id, {}))
978-
entry = self.schedules.get(site_id, {}).get(family.lower())
1053+
entry = self.schedules.get(site_id, {}).get(family_key)
9791054
if isinstance(entry, dict):
9801055
entry.pop("status", None)
9811056
else:
9821057
self.log(f"Warn: Enphase: {label} activation failed for site {site_id}")
9831058
self._invalidate_cached_schedule(site_id, family)
1059+
self._note_schedule_write_result(site_id, family_key, result is not None)
9841060
return result is not None
9851061

9861062
async def _activate_cfg_mode(self, site_id, family=SCHEDULE_CHARGE):
@@ -1058,11 +1134,12 @@ async def set_reserve(self, site_id, reserve):
10581134
params = {"source": "enho"}
10591135
if self.user_id:
10601136
params["userId"] = self.user_id
1061-
result = await self.request_json("PUT", f"{BATTERY_CONFIG_BASE}/profile/{site_id}", family="battery_config", params=params, json_body={"profile": profile_name, "batteryBackupPercentage": int(reserve)})
1137+
result = await self.request_json("PUT", f"{BATTERY_CONFIG_BASE}/profile/{site_id}", family="battery_config", params=params, json_body={"profile": profile_name, "batteryBackupPercentage": int(reserve)}, context="reserve update")
10621138
if result is not None:
10631139
# Optimistically cache the written reserve; the periodic profile re-read will correct
10641140
# it if the write did not actually land (e.g. the gateway never activated it).
10651141
self.profile.setdefault(site_id, {})["reserve"] = int(reserve)
1142+
self._note_schedule_write_result(site_id, "reserve", result is not None)
10661143
return result
10671144

10681145
async def apply_battery_schedule(self, site_id):
@@ -1677,7 +1754,7 @@ def _is_login_wall(self, json_data, text):
16771754
stripped = (text or "").lstrip().lower()
16781755
return stripped.startswith("<!doctype") or stripped.startswith("<html")
16791756

1680-
async def request_json(self, method, path, family="site", json_body=None, data=None, params=None, allow_empty=False):
1757+
async def request_json(self, method, path, family="site", json_body=None, data=None, params=None, allow_empty=False, context=None):
16811758
"""Perform an authenticated JSON request with retries and a single 401 re-login.
16821759
16831760
Builds the request URL from BASE_URL + path and attaches family-appropriate headers
@@ -1688,7 +1765,10 @@ async def request_json(self, method, path, family="site", json_body=None, data=N
16881765
attempt); otherwise it performs one login() and retries once.
16891766
- HTTP 429 and 5xx responses, plus timeouts/connection errors, are retried with
16901767
jittered backoff up to ENPHASE_RETRIES times.
1691-
- Any other non-200 status is treated as a terminal failure.
1768+
- Any other non-200 status is treated as a terminal failure, logged as
1769+
"HTTP {method} {path} -> {status}" (plus ``context`` when the caller gave one, e.g. the
1770+
schedule family/window being written) so a bare-path 409 is never ambiguous between the
1771+
GET, the POST create and the PUT update that all share that path shape.
16921772
``allow_empty`` additionally accepts a 204/empty body as success (returning {} rather than
16931773
None), as a DELETE returns no content.
16941774
Every outcome is recorded via record_api_call("enphase", ...) for metrics/health.
@@ -1732,7 +1812,8 @@ async def request_json(self, method, path, family="site", json_body=None, data=N
17321812
continue
17331813

17341814
if status != 200 and not (allow_empty and status == 204):
1735-
self.log(f"Warn: Enphase: HTTP {status} on {path}")
1815+
context_suffix = f" ({context})" if context else ""
1816+
self.log(f"Warn: Enphase: HTTP {method} {path} -> {status}{context_suffix}")
17361817
record_api_call("enphase", False, "client_error")
17371818
self.last_error_status = status
17381819
self.failures_total += 1

apps/predbat/predbat.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,7 @@
3535
import pytz
3636
import asyncio
3737

38-
THIS_VERSION = "v8.47.6"
38+
THIS_VERSION = "v8.47.7"
3939

4040
from download import predbat_update_move, predbat_update_download, check_install, DEFAULT_PREDBAT_REPOSITORY
4141
from const import MINUTE_WATT

0 commit comments

Comments
 (0)