diff --git a/.cspell/custom-dictionary-workspace.txt b/.cspell/custom-dictionary-workspace.txt index fa533982d..c21a27f55 100644 --- a/.cspell/custom-dictionary-workspace.txt +++ b/.cspell/custom-dictionary-workspace.txt @@ -393,6 +393,8 @@ pytz randn rarr reactivepower +readback +readbacks recp redownload Referer diff --git a/apps/predbat/inverter.py b/apps/predbat/inverter.py index 9806a0be2..f6b8b109f 100644 --- a/apps/predbat/inverter.py +++ b/apps/predbat/inverter.py @@ -3391,6 +3391,15 @@ def rest_setDischargeTarget(self, target): """ Configure discharge to percent via REST """ + + def to_int(value): + """GivTCP reports these as strings, so coerce before comparing or a successful write + reads back as '4' and never matches the int target.""" + try: + return int(float(value)) + except (ValueError, TypeError): + return None + target = int(target) url = self.rest_api + "/setDischargeTarget" data = {"dischargeToPercent": target, "slot": 1} @@ -3398,14 +3407,21 @@ def rest_setDischargeTarget(self, target): for retry in range(INVERTER_MAX_RETRY_REST): r = self.rest_postCommand(url, json=data) + # GivTCP's write handler updates Control.Discharge_Target_SOC_1 synchronously the + # moment it accepts the command (confirmed against GivTCP's own source - write.py's + # setDischargeTarget() calls updateControlCache() straight after the Modbus write), so + # it's checked first. raw.invertor.discharge_target_soc_1 is kept as a fallback, but on + # its own it's an unreliable signal: it only refreshes on GivTCP's separate background + # self_run poll cycle, which can be tens of seconds away, not synchronous with this + # POST at all (#4421). A short settle delay still helps for the much smaller residual + # gap - the physical inverter itself taking a moment to apply the write, which a + # same-moment self_run poll could otherwise briefly overwrite Control with a stale read + # of. + self.sleep(1) self.rest_data = self.rest_runAll(self.rest_data) - # GivTCP reports the raw registers as strings, so coerce before comparing or a - # successful write reads back as '4' and never matches the int target - result = self.rest_data.get("raw", {}).get("invertor", {}).get("discharge_target_soc_1", None) - try: - result = int(float(result)) - except (ValueError, TypeError): - result = None + result = to_int(self.rest_data.get("Control", {}).get("Discharge_Target_SOC_1", None)) + if result != target: + result = to_int(self.rest_data.get("raw", {}).get("invertor", {}).get("discharge_target_soc_1", None)) if result == target: self.count_register_writes += 1 self.base.log("Inverter {} Set export target slot 1 {} via REST successful after retry {}".format(self.id, data, retry)) diff --git a/apps/predbat/tests/test_inverter.py b/apps/predbat/tests/test_inverter.py index 6fda29333..49d8a1ad4 100644 --- a/apps/predbat/tests/test_inverter.py +++ b/apps/predbat/tests/test_inverter.py @@ -1759,6 +1759,129 @@ def target_errors(): return failed +def test_discharge_target_settle_delay(test_name, ha, inv, dummy_rest): + """ + Regression test for issue #4421: spurious "REST failed to setExportTarget got 0" warnings + even though GivTCP's own log confirms the write succeeded. + + Exercises the raw.invertor.discharge_target_soc_1 fallback path specifically (Control has no + Discharge_Target_SOC_1 key in this fixture, so the primary signal can't match). That field is + only refreshed by GivTCP's own background self_run poll cycle, not synchronously with the + setDischargeTarget POST - reading it back immediately can therefore catch data from before + GivTCP has next polled and exposed the write. rest_setDischargeTarget must settle briefly + (self.sleep) between the POST and each readback, on every attempt - not just between retries - + giving that poll cycle a chance to catch up before it's checked. + + Simulates exactly that race: the first queued runAll response is still the stale pre-write value + (as if GivTCP's self_run hadn't polled since the write), the second is the real post-write value. + The write must still be recognised as a success once the fallback catches up, and a sleep must + have happened before each of the two readbacks, not only between them. + """ + failed = False + print("Test: {}".format(test_name)) + + saved_rest_data = inv.rest_data + saved_rest_api = inv.rest_api + saved_rest_v3 = inv.rest_v3 + saved_sleep = inv.sleep + + sleep_calls = [] + + def counting_sleep(seconds): + sleep_calls.append(seconds) + + inv.sleep = counting_sleep + + try: + inv.rest_api = "dummy" + inv.rest_v3 = True + inv.rest_data = {"Control": {"Mode": "Timed Export"}, "raw": {"invertor": {"discharge_target_soc_1": "0"}}} + dummy_rest.clear_queue() + dummy_rest.rest_data = copy.deepcopy(inv.rest_data) + # First readback: still the stale pre-write value (GivTCP's cache hasn't caught up yet). + stale = copy.deepcopy(inv.rest_data) + dummy_rest.queue_rest_data(stale) + # Second readback: the real post-write value. + settled = copy.deepcopy(inv.rest_data) + settled["raw"]["invertor"]["discharge_target_soc_1"] = "20" + dummy_rest.queue_rest_data(settled) + dummy_rest.get_commands() + + if not inv.rest_setDischargeTarget(20): + print("ERROR: {}: write should be recognised as successful once the stale cache catches up".format(test_name)) + failed = True + + commands = dummy_rest.get_commands() + if len(commands) != 2: + print("ERROR: {}: export target should be POSTed once per attempt (2 attempts needed here), got {} writes".format(test_name, len(commands))) + failed = True + + if len(sleep_calls) < 2: + print("ERROR: {}: expected a settle sleep before each of the 2 readbacks, got {} sleep call(s)".format(test_name, len(sleep_calls))) + failed = True + finally: + inv.sleep = saved_sleep + inv.rest_data = saved_rest_data + inv.rest_api = saved_rest_api + inv.rest_v3 = saved_rest_v3 + + return failed + + +def test_discharge_target_control_signal(test_name, ha, inv, dummy_rest): + """ + Regression test for issue #4421 (follow-up): rest_setDischargeTarget must trust + Control.Discharge_Target_SOC_1 as the primary success signal, not just the raw register. + + Traced against GivTCP's own source: write.py's setDischargeTarget() calls + updateControlCache() synchronously the moment it accepts the write, setting + Control.Discharge_Target_SOC_1 immediately - well before raw.invertor.discharge_target_soc_1 + is next refreshed by the separate, much slower self_run background poll (tens of seconds on + some installs, not a fixed short delay). Checking Control first means a write that GivTCP has + genuinely accepted is recognised straight away, on the very first readback, rather than only + once the (unrelated, much later) background poll happens to catch up. + + Simulates the synchronous case: the very first queued runAll response already has + Control.Discharge_Target_SOC_1 set to the target (raw.invertor still stale, as GivTCP's own + background poll wouldn't have run yet) - the write must be recognised as successful on attempt + 0, without needing any of the later retries the raw-only fallback would require. + """ + failed = False + print("Test: {}".format(test_name)) + + saved_rest_data = inv.rest_data + saved_rest_api = inv.rest_api + saved_rest_v3 = inv.rest_v3 + + try: + inv.rest_api = "dummy" + inv.rest_v3 = True + inv.rest_data = {"Control": {"Mode": "Timed Export"}, "raw": {"invertor": {"discharge_target_soc_1": "0"}}} + dummy_rest.clear_queue() + dummy_rest.rest_data = copy.deepcopy(inv.rest_data) + # Control is updated synchronously by GivTCP's write handler - raw.invertor is still stale, + # as if the background self_run poll hasn't run since the write. + settled_control = copy.deepcopy(inv.rest_data) + settled_control["Control"]["Discharge_Target_SOC_1"] = "20" + dummy_rest.queue_rest_data(settled_control) + dummy_rest.get_commands() + + if not inv.rest_setDischargeTarget(20): + print("ERROR: {}: write should be recognised as successful from Control.Discharge_Target_SOC_1 alone".format(test_name)) + failed = True + + commands = dummy_rest.get_commands() + if len(commands) != 1: + print("ERROR: {}: Control signalling success on the first readback should need only 1 POST, got {}".format(test_name, len(commands))) + failed = True + finally: + inv.rest_data = saved_rest_data + inv.rest_api = saved_rest_api + inv.rest_v3 = saved_rest_v3 + + return failed + + def test_force_export_unchanged_times_HM_format(test_name, ha, inv): """ Regression test for GS_fb00 (Solis) 'count register writes 0' bug. @@ -2889,5 +3012,17 @@ def run_inverter_tests(my_predbat_dummy): if failed: return failed + # Regression test for issue #4421: settle before each readback so a slow-to-update GivTCP cache + # isn't misread as a failed write + failed |= test_discharge_target_settle_delay("discharge_target_settle_delay", ha, inv, dummy_rest) + if failed: + return failed + + # Regression test for issue #4421 (follow-up): trust Control.Discharge_Target_SOC_1, GivTCP's + # synchronous write-time signal, ahead of the much slower raw.invertor background-poll fallback + failed |= test_discharge_target_control_signal("discharge_target_control_signal", ha, inv, dummy_rest) + if failed: + return failed + failed |= test_inverter_self_test("self_test1", my_predbat) return failed