diff --git a/hueman/circadian_daemon.py b/hueman/circadian_daemon.py index 52cd81a..0cea291 100644 --- a/hueman/circadian_daemon.py +++ b/hueman/circadian_daemon.py @@ -703,6 +703,36 @@ def _write(self, target: TargetState, transition_ms: int) -> bool: _LOG.warning("write to %s failed (%s); skipping", self._rid, e) return False + def _resume_locked(self, now: float) -> None: + """Resume driving and grant a settle-classification grace window. + + Every resume trigger (power-cycle, control-file, resume-trigger scene) + just flipped the controller out of SUSPENDED, but the settle-and-compare + classifier's ``_cmd_brightness``/``_cmd_on`` reference is stale — it was + last set before the suspension began and nothing refreshes it until the + daemon lands a real drive. Without this reset, the very next settle + judgment (which always runs before that drive gets a chance to happen — + see ``_tick_once``) compares the freshly-resumed live brightness against + that stale target and re-suspends within one tick, defeating the resume + outright. This mirrors the reset already proven in + ``_restore_after_security`` (born from the same failure mode observed + live 2026-07-03: "settled at 45.6% vs target 99.8%"), which was never + ported to the ordinary manual-override resume paths — confirmed live + 2026-08-08: motion-triggered brightness churn repeatedly power-cycled + the zone, and every single resume was undone by the next tick's stale + comparison, all night, without ever actually redriving. + + Discarding the unjudged sample and holding classification for one fade + + settle window gives the daemon time to land a fresh drive (or settle + into ``NIGHT_IDLE`` outside the window) before judging anything again. + Caller holds the lock. + """ + self._controller.on_resume(now) + self._obs_brightness = None + self._obs_classified = False + self._classify_grace_until = now + ( + self._spec.transition_ms + self._spec.settle_window_ms) / 1000.0 + def _poll_control_file(self, now: float) -> None: """Resume the daemon if the external control file is present, then remove it. @@ -713,7 +743,7 @@ def _poll_control_file(self, now: float) -> None: try: if os.path.exists(path): _LOG.info("resume via control-file -> driving") - self._controller.on_resume(now) + self._resume_locked(now) try: os.unlink(path) except FileNotFoundError: @@ -1203,7 +1233,7 @@ def _handle_event(self, event: BridgeEvent, now: float) -> None: self._security_aggregator.off(now, "sse") if self._resume_trigger_rid is not None and event.rid == self._resume_trigger_rid: _LOG.info("resume trigger %s -> resumed", event.rid) - self._controller.on_resume(now) + self._resume_locked(now) return if (self._presence is not None and event.rtype in ("convenience_area_motion", "security_area_motion")): @@ -1236,7 +1266,7 @@ def _handle_event(self, event: BridgeEvent, now: float) -> None: and self._spec.resume_on_power_cycle ): _LOG.info("power-cycle (off->on) -> resumed") - self._controller.on_resume(now) + self._resume_locked(now) self._last_on = True # -- brightness settle-and-compare ----------------------------- # diff --git a/tests/test_circadian_daemon.py b/tests/test_circadian_daemon.py index 3341bcf..a585c91 100644 --- a/tests/test_circadian_daemon.py +++ b/tests/test_circadian_daemon.py @@ -217,6 +217,112 @@ def test_power_cycle_off_then_on_resumes(): assert daemon._controller.mode == "driving" # off->on power cycle re-engages +# -- resume race: stale cmd reference (live 2026-08-08) --------------------- # +# THE LIVE 2026-08-08 BUG: overnight motion-triggered brightness churn +# repeatedly power-cycled the zone. Every "power-cycle -> resumed" was undone +# by the very next settle judgment, because _cmd_brightness/_cmd_on are never +# refreshed while SUSPENDED — they're still whatever the daemon last commanded +# BEFORE the override began — and classify-before-drive (_tick_once) always +# runs that judgment before the controller gets a chance to redrive and +# refresh the reference. Resume "worked" only by luck (when nothing moved +# after the original override), and flapped every time something did. All +# three resume paths (power-cycle, control-file, resume-trigger scene) shared +# the bug; `_resume_locked` closes it the same way `_restore_after_security` +# already closed the identical race for the security-exit path. +def test_power_cycle_resume_does_not_immediately_resuspend_on_stale_target(): + daemon = CircadianDaemon.for_test(_FakeClient(), _cfg(), grouped_light_rid="GL") + t0 = _epoch(12, 0) + daemon._tick_once(t0) # driving; records the target + stale_target = daemon._cmd_brightness + daemon._handle_event(_dim(stale_target - 30.0), t0 + 30) + daemon._handle_event(_dim(stale_target - 30.0), t0 + 33) # settles -> suspended + assert daemon._controller.mode == "suspended" + t1 = t0 + 1000 # no further drive since suspension + daemon._handle_event(BridgeEvent("grouped_light", "GL", {"on": {"on": False}}), t1) + daemon._handle_event(BridgeEvent("grouped_light", "GL", {"on": {"on": True}}), t1 + 1) + assert daemon._controller.mode == "driving" # power-cycle resumed + # the just-resumed brightness settles far from the STALE target -- without + # the grace reset this re-suspends within one settle window, every time. + fresh = stale_target + 40.0 + daemon._handle_event(_dim(fresh), t1 + 2) + daemon._handle_event(_dim(fresh), t1 + 5) # holds >= settle_window + assert daemon._controller.mode == "driving" + + +def test_power_cycle_resume_still_detects_a_genuine_override_after_grace(): + # The grace is not a permanent hall pass: once the daemon has had a real + # tick to redrive (refreshing _cmd_brightness) and the grace window has + # elapsed, a genuinely new manual change must still suspend normally. + daemon = CircadianDaemon.for_test(_FakeClient(), _cfg(), grouped_light_rid="GL") + t0 = _epoch(12, 0) + daemon._tick_once(t0) + stale_target = daemon._cmd_brightness + daemon._handle_event(_dim(stale_target - 30.0), t0 + 30) + daemon._handle_event(_dim(stale_target - 30.0), t0 + 33) + assert daemon._controller.mode == "suspended" + t1 = t0 + 1000 + daemon._handle_event(BridgeEvent("grouped_light", "GL", {"on": {"on": False}}), t1) + daemon._handle_event(BridgeEvent("grouped_light", "GL", {"on": {"on": True}}), t1 + 1) + assert daemon._controller.mode == "driving" + daemon._tick_once(t1 + 60) # a real tick redrives -> fresh target + fresh_target = daemon._cmd_brightness + assert daemon._controller.mode == "driving" + after_grace = t1 + 60 + 75 + 2.5 + 5 # past transition + settle_window + daemon._handle_event(_dim(fresh_target - 25.0), after_grace) + daemon._handle_event(_dim(fresh_target - 25.0), after_grace + 3) + assert daemon._controller.mode == "suspended" # a real override still lands + + +def _cfg_manual_override(control_file): + return Config.parse({ + "bridge": {"host": "x", "application_key": "k"}, + "location": {"lat": 45.5152, "lon": -122.6784, "tz_offset_hours": -7}, + "motion_policies": [], + "circadian_daemon": { + "zone": "Night Guide", "interval": "60s", "transition": "75s", + "manual_override": {"control_file": control_file}, + }, + }) + + +def test_control_file_resume_does_not_immediately_resuspend_on_stale_target(tmp_path): + resume_file = tmp_path / ".hue-circadian-resume" + daemon = CircadianDaemon.for_test( + _FakeClient(), _cfg_manual_override(str(resume_file)), grouped_light_rid="GL") + t0 = _epoch(12, 0) + daemon._tick_once(t0) + stale_target = daemon._cmd_brightness + daemon._handle_event(_dim(stale_target - 30.0), t0 + 30) + daemon._handle_event(_dim(stale_target - 30.0), t0 + 33) + assert daemon._controller.mode == "suspended" + resume_file.write_text("resume\n") + daemon._tick_once(t0 + 1000) # poll_control_file -> resumed + assert daemon._controller.mode == "driving" + assert not resume_file.exists() # consumed + fresh = stale_target + 40.0 + daemon._handle_event(_dim(fresh), t0 + 1002) + daemon._handle_event(_dim(fresh), t0 + 1005) + assert daemon._controller.mode == "driving" # not immediately re-suspended + + +def test_resume_trigger_does_not_immediately_resuspend_on_stale_target(): + daemon = CircadianDaemon.for_test(_FakeClient(), _cfg(), grouped_light_rid="GL") + daemon._resume_trigger_rid = "SCENE1" + t0 = _epoch(12, 0) + daemon._tick_once(t0) + stale_target = daemon._cmd_brightness + daemon._handle_event(_dim(stale_target - 30.0), t0 + 30) + daemon._handle_event(_dim(stale_target - 30.0), t0 + 33) + assert daemon._controller.mode == "suspended" + t1 = t0 + 1000 + daemon._handle_event(BridgeEvent("scene", "SCENE1", {"recall": {}}), t1) + assert daemon._controller.mode == "driving" + fresh = stale_target + 40.0 + daemon._handle_event(_dim(fresh), t1 + 2) + daemon._handle_event(_dim(fresh), t1 + 5) + assert daemon._controller.mode == "driving" + + def test_own_fade_off_does_not_suspend(): # After the daemon's own hand-off fade-off, cmd_on is False; the ensuing # on:false from the bridge is ours and must NOT be read as a human override.