Fix: two autolock paths that could leave a door unlocked indefinitely

[ygelfand]

Summary

Two doors sat unlocked overnight — one for 34 hours — with autolock enabled
the whole time. No notification, switches still reading on. On v0.5.3 the
log had a bunch of these:

File "custom_components/keymaster/autolock/timer.py", line 185, in fire
  assert self._entry is not None
AssertionError

I think 2 separate but related causes:

1. A lock already unlocked at startup never gets a timer
2. cancel() can orphan a fire that start() just armed
   Note that ISSUE: Autolock race between cancel() and dispatched fire callback (AssertionError at timer.py:185) #671 turned that assertion into a debug-level bail, which removed the traceback but not the cause

• Dependency upgrade

• Bugfix (non-breaking change which fixes an issue)

• New feature (which adds functionality)

• Breaking change (fix/feature causing existing functionality to break)

• Code quality improvements to existing code or addition of tests

  test_cancel_does_not_orphan_fire_armed_during_await gates the first
  cancel() inside its await, re-arms, then releases — fails on main with
  assert None is <ScheduledFire>. Four _setup_timer tests cover the startup
  arm plus guards (autolock off, already locked, recovered timer wins); only the
  arming one fails on main.

  1010 passed, 3 skipped. ruff clean.

[codecov-commenter]

⚠️ Please install the to ensure uploads and comments are reliably processed by Codecov.

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 93.29%. Comparing base (cdb4922) to head (f2410b7).
⚠️ Report is 206 commits behind head on main.
❗ Your organization needs to install the Codecov GitHub app to enable full functionality.

Additional details and impacted files

@@            Coverage Diff             @@
##             main     #703      +/-   ##
==========================================
+ Coverage   84.14%   93.29%   +9.14%     
==========================================
  Files          10       42      +32     
  Lines         801     5263    +4462     
  Branches        0       30      +30     
==========================================
+ Hits          674     4910    +4236     
- Misses        127      353     +226     

Flag	Coverage Δ
python	93.17% <100.00%> (?)

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.
• 📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

[secondof9]

Code Review — FutureTense/keymaster PR #703

Title: Fix: two autolock paths that could leave a door unlocked indefinitely
Reviewer: secondof9
Recommendation: ✅ APPROVE

---

File 1: custom_components/keymaster/autolock/timer.py (lines 132–140)

cancel() method — race condition fix

     async def cancel(self) -> None:
         """Cancel the timer. Idempotent. Awaits in-flight callback."""
         if self._scheduled is not None:
-            await self._scheduled.cancel()
+            scheduled = self._scheduled
+            await scheduled.cancel()
+            if self._scheduled is not scheduled:
+                # A start() interleaved with the await and owns the timer now.
+                return
         self._scheduled = None
         if self._state == TimerState.ACTIVE:
             self._entry = None

The original await self._scheduled.cancel() can yield between the await and self._scheduled = None. If start() runs in the meantime and installs a new _scheduled, the unconditional assignment drops the new fire. The gated-cancel test proves this.

The fix captures the reference before the await, and short-circuits if _scheduled changed. The trailing self._scheduled = None becomes dead code in the early-return case — harmless, cosmetic.

File 2: custom_components/keymaster/coordinator.py (lines 1567–1577)

Startup arm — missing transition

         await kmlock.autolock_timer.recover()
+        if (
+            kmlock.lock_state == LockState.UNLOCKED
+            and kmlock.autolock_enabled
+            and not kmlock.autolock_timer.is_running
+        ):
+            # Already unlocked at startup: no unlocked transition will arrive
+            # to arm the timer, so arm it from the state we adopted.
+            await kmlock.autolock_timer.start(duration=self.autolock_duration_seconds(kmlock))

A lock that was already unlocked before HA started never produces an unlocked transition. Without this guard, the timer stays silent indefinitely. The four new tests in test_coordinator_lifecycle.py cover: arm-when-unlocked, skip-when-disabled, skip-when-locked, recovered-timer-wins.

File 3: tests/autolock/test_timer.py

test_cancel_does_not_orphan_fire_armed_during_await

This is a masterclass async race-condition test. It patches first.cancel with a gated_cancel() that pauses on the first call, lets start() install a replacement, then releases the gate. The four assertions verify: (1) the second fire was kept, (2) state is ACTIVE, (3) the timer is running, (4) the entry was written and the action was never called.

File 4: tests/test_coordinator_lifecycle.py

Four new tests for _setup_timer. Clean, minimal, and cover the full conditional space.

---

Summary

• 7/7 CI checks passed (coverage, pytest 3.14, hassfest, hacs, prek)
• 4 files changed (2 production, 2 test)
• The bug is real — PR author ran into doors sitting unlocked for 34 hours on v0.5.3
• The fix is minimal, targeted, and well-tested
• No architectural concerns, no async hazards beyond the one being fixed, no missing defensive defaults

Verdict: Approved for merge. The _scheduled = None trailing assignment in cancel() is cosmetic dead code in the early-return path and does not affect behavior.

[firstof9]

The fixes look good to me, but a 3rd set of eyes would be good.

[tykeal]

Walkthrough

Two independent autolock fixes. AutolockTimer.cancel() now captures the ScheduledFire it is cancelling and bails out if a concurrent start() installed a replacement during the await, instead of unconditionally clearing _scheduled and orphaning the new fire. KeymasterCoordinator._setup_timer() now arms the autolock timer for a lock that is already unlocked when the integration starts, since no unlocked state transition will ever arrive to arm it.

Changes

• custom_components/keymaster/autolock/timer.py — cancel() (L131-144) captures _scheduled into a local, and returns early after await scheduled.cancel() if self._scheduled is no longer that object.
• custom_components/keymaster/coordinator.py — _setup_timer() (L1570-1577) arms the timer after recover() when lock_state == UNLOCKED, autolock is enabled, and the timer is not already running.
• tests/autolock/test_timer.py — test_cancel_does_not_orphan_fire_armed_during_await, gating the first ScheduledFire.cancel() inside its await via an asyncio.Event.
• tests/test_coordinator_lifecycle.py — four _setup_timer tests (startup arm, autolock disabled, already locked, recovered timer wins).

Verification performed

Both claims check out.

Race on main: cancel() awaited self._scheduled.cancel() and then executed self._scheduled = None unconditionally. A start() interleaving with that await installs a fresh ScheduledFire at _schedule_remaining(); cancel() then dropped that object without cancelling it and fell through to self._entry = None / store.remove() / _state = DONE. The dropped fire still runs, reads self._entry is None, and takes the debug bail — lock never engages. test_cancel_does_not_orphan_fire_armed_during_await fails on 1cc73a9 with exactly assert None is <ScheduledFire object>, and also produces a verify_cleanup teardown error there (the orphaned async_call_later handle). On the head commit it passes with no teardown error.

test_setup_timer_arms_lock_already_unlocked_at_startup fails on 1cc73a9 with assert False on is_running; the other three pass on both. Ordering in _async_setup (coordinator.py:496-497) is correct — _update_door_and_lock_state() populates kmlock.lock_state from hass.states before _setup_timers() runs. Reload does not double-arm: _update_lock transfers the timer (coordinator.py:1752-1753) and _setup_timer returns at the if kmlock.autolock_timer is not None guard before reaching the new block.

The PR #671 claim is accurate. 010520e replaced assert self._entry is not None inside the fire closure — which was line 185 in v0.5.3, matching the reported traceback — with the debug-logged bail. Recommend retaining that bail as defence-in-depth rather than reverting it to an assert; see the start() note below.

Full suite on head: 1010 passed, 3 skipped. ruff==0.16.0 check . and ruff format --check . clean. mypy . reports 28 errors, all pre-existing and identical on the merge base.

Review comments

custom_components/keymaster/coordinator.py

[SUGGESTION] L1569-1577 — the startup arm also fires after recover() consumed an entry, which is wrong in both of recover()'s entry-consuming outcomes.

is_running is False after recover() handles an expired entry, in both the success and the failure branch, so the new block arms in both cases. Verified against the head commit with a probe (kmlock registered in coordinator.kmlocks, store pre-seeded with an entry whose end_time is in the past):

• Action succeeds: _timer_triggered await count is 1 (the door was just locked), then the block arms a fresh 300s timer, because kmlock.lock_state is still the stale UNLOCKED adopted before recovery. This self-corrects only when the lock entity's LOCKED state change arrives and _lock_locked reaches await kmlock.autolock_timer.cancel() (coordinator.py:1427), and it emits a spurious async_schedule_global_notification() in the meantime.
• Action raises: _fire re-persists the entry (timer.py:243) specifically so recover() retries it on the next restart — documented at timer.py:24 ("cancel() and successful fire remove it") and timer.py:92-93 ("On failure → re-persist for retry on next restart"). The startup arm then calls start(), which overwrites that entry. Probe output: original end_time 13:56:41Z became 14:01:51Z in the store. A restart inside the new window now re-schedules instead of retrying.

Reading the store entry before recover() gates both cases with one condition and needs no change to AutolockTimer:

        recovered_entry = await self._timer_store.read(f"{entry_id}_autolock")
        await kmlock.autolock_timer.recover()
        if (
            recovered_entry is None
            and kmlock.lock_state == LockState.UNLOCKED
            and kmlock.autolock_enabled
            and not kmlock.autolock_timer.is_running
        ):
            # Already unlocked at startup with no persisted timer: no
            # unlocked transition will arrive to arm the timer, so arm it
            # from the state we adopted.
            await kmlock.autolock_timer.start(duration=self.autolock_duration_seconds(kmlock))

test_setup_timer_keeps_recovered_timer_over_startup_arm still passes under this form, and it makes that test assert the intended reason rather than passing incidentally via is_running.

custom_components/keymaster/autolock/timer.py

[SUGGESTION] L119-122 — the mirrored interleaving is still open, and it now raises from start() rather than bailing in fire().

The fix orders correctly for cancel-then-start. The reverse ordering — start() suspended in await self._store.write(...) (L121) while a cancel() runs to completion and executes self._entry = None (L141) — leaves start() resuming into _schedule_remaining(), whose assert self._entry is not None (L185) then raises. Confirmed on the head commit with a probe that gates TimerStore.write on an asyncio.Event, starts timer.start(duration=600) as a task, runs await timer.cancel() to completion, then releases the gate: start() raises AssertionError. This is pre-existing on main, not introduced here, but it is the same failure mode in the same function and is what keeps the L188-196 debug bail load-bearing.

Assigning self._entry after the write closes the in-memory half of that window — the resuming start() re-establishes _entry and _scheduled and leaves the timer ACTIVE and armed instead of raising:

        end_time = dt_util.utcnow() + timedelta(seconds=duration)
        entry = TimerEntry(end_time=end_time, duration=duration)
        await self._store.write(self._timer_id, entry)
        self._entry = entry
        self._schedule_remaining()
        self._state = TimerState.ACTIVE

Note this does not fully close it: a cancel() whose store.remove() lands after this store.write() still leaves the persisted entry absent while the in-memory timer is ACTIVE, so the timer would be lost across a restart. Fine to defer, but worth a follow-up.

[NITPICK] L131-139 — cancel()'s early return now silently makes the call a no-op, which contradicts the invariant stated at L34-35 ("cancel() awaits any in-flight callback before returning. After cancel() returns, no further action firing can happen"). The behaviour is right — the later start() should win — but the docstring invariant no longer holds unconditionally and the early return is not logged, unlike every other exit in this class.

    async def cancel(self) -> None:
        """Cancel the timer. Idempotent. Awaits in-flight callback.

        If a `start()` interleaves with that await and installs a
        replacement fire, that later start wins and this cancel becomes a
        no-op — see invariant 2 in the module docstring.
        """
        if self._scheduled is not None:
            scheduled = self._scheduled
            await scheduled.cancel()
            if self._scheduled is not scheduled:
                # A start() interleaved with the await and owns the timer now.
                _LOGGER.debug(
                    "[AutolockTimer] %s: cancel superseded by a concurrent start()",
                    self._timer_id,
                )
                return
            self._scheduled = None

tests

[NITPICK] tests/autolock/test_timer.py:330-338 — the gating is deterministic (asyncio.Event, single asyncio.sleep(0) to reach the suspension point, no wall-clock sleeps) and not tautological: it fails on the merge base for the stated reason and leaves no pending timer on head. tests/test_coordinator_lifecycle.py:838-846 correctly pins autolock_min_day == autolock_min_night == 5 so the duration == 300 assertions do not depend on sun position. No changes requested.

One gap: tests/test_coordinator_lifecycle.py:893-908 never inserts the kmlock into coordinator.kmlocks, so get_kmlock() would resolve to None if that timer ever fired. It does not fire there (the entry is 900s out), but the two recover()-fires-an-expired-entry cases described above cannot be tested without registering it — worth adding coordinator.kmlocks["entry_1"] = kmlock and a case for the expired-entry path.

[tykeal]

Re-reviewed against current main (42e22ea), which now includes #695 and #700.

Note on line numbers: every file:line reference below is against the merged result — upstream/pr/703 merged into main @ 42e22ea — not against the current PR head. They will not match your checkout until you rebase.

Rebase required

The branch is CONFLICTING. I produced the merged tree locally: only tests/test_coordinator_lifecycle.py conflicts — coordinator.py and autolock/timer.py auto-merge cleanly. Three regions, all union resolutions, but fold the duplicated imports rather than keeping both sides verbatim:

1. Stdlib import line — keep main's import copy / from datetime import datetime as dt, timedelta; drop the branch's from datetime import timedelta (already covered). dt and dt_util do not collide.

2. custom_components / homeassistant import block — keep main's block and add only the three new imports, in isort position:

   • from custom_components.keymaster.autolock.store import TimerEntry — before the const block
   • from homeassistant.components.lock.const import LockState — before homeassistant.config_entries
   • from homeassistant.util import dt as dt_util — after homeassistant.helpers

   The branch's re-imports of DOMAIN, KeymasterCoordinator, KeymasterLockCoordinator, KeymasterCodeSlot, KeymasterLock are redundant; main's block already supplies all of them.

3. End of file — straight union; keep main's two test_update_lock_* tests, then append _autolock_kmlock and the four test_setup_timer_* tests.

No test-name collisions after the union, so no renames are needed. I checked all top-level defs in both tests/test_coordinator_lifecycle.py and tests/autolock/test_timer.py on the merged tree — zero duplicates, and each of the five new names appears exactly once across tests/.

Nothing in the source needs adjusting for #695. _setup_timer still exists and the added block lands correctly between recover() and the notification hook; lock_state, autolock_enabled, autolock_timer, and autolock_duration_seconds are semantically unchanged. #695 replaced async_schedule_global_notification() with async_schedule_keymaster_notifications(entry_ids), but the merge resolves that line to main's version automatically — the merged tree has no reference to the removed symbol.

Verification on the merged tree

• pytest tests/: 1069 passed, 1 deselected, zero failures
• ruff check custom_components/ tests/: clean
• ruff format --check custom_components/ tests/: clean (80 files already formatted)
• mypy custom_components/keymaster/: clean (35 source files)
• codespell custom_components/keymaster tests: clean
• Coverage of the changed lines: 100%

I mutation-tested both regression tests; each fails when its production change is reverted:

• Reverting cancel() to await self._scheduled.cancel() → FAILED tests/autolock/test_timer.py::test_cancel_does_not_orphan_fire_armed_during_await — assert timer._scheduled is second / assert None is <ScheduledFire object at 0x…>
• Deleting the _setup_timer startup-arm block → FAILED tests/test_coordinator_lifecycle.py::test_setup_timer_arms_lock_already_unlocked_at_startup — assert kmlock.autolock_timer.is_running / AssertionError: assert False

Both fixes are sound. The rebase is the only mandatory action.

Outstanding items

[SUGGESTION] coordinator.py:1638-1645 — the startup arm also fires after recover() has consumed an expired entry, because is_running is False in both of recover()'s entry-consuming outcomes. I reproduced both on the merged tree:

• Action succeeds: the block arms a fresh 300s timer, since lock_state is still the UNLOCKED value adopted before recovery. Self-corrects when the LOCKED transition reaches _lock_locked, but a full extra window elapses first.
• Action raises: _fire deliberately re-persists the entry (autolock/timer.py:236, contract documented at timer.py:19-20 and timer.py:212-215) so recover() retries next restart. The startup arm's start() overwrites that entry with a fresh 300s one, so a restart inside the new window re-schedules instead of retrying, losing the retry.

Reading the store entry before recover() and gating the arm on recovered_entry is None addresses both.

[NIT] tests — the four new tests never do coordinator.kmlocks["entry_1"] = kmlock, so get_kmlock() would resolve to None if the timer fired. It does not fire in these cases, so they are correct as written, but registering the kmlock is a prerequisite for covering the two expired-entry cases above.

[NIT] autolock/timer.py:136-138 — the new early return makes cancel() a silent no-op and contradicts invariant 2 in the module docstring (timer.py:28-29, "After cancel() returns, no further action firing can happen"). Unlike every other exit in the class it is not logged. Suggest amending the invariant to note the interleaved-start() handoff and adding a _LOGGER.debug on that branch.

[NIT] coordinator.py:1644 — the comment says "Already unlocked at startup", but _setup_timer is also reached from _add_lock, so a lock added while unlocked now arms immediately. That looks correct (the state is fresh there, not adopted), but the comment is narrower than the behaviour.

Out of scope — not asked of this PR

start() suspended in await self._store.write(...) while a cancel() runs to completion leaves start() resuming into _schedule_remaining(), whose assert self._entry is not None (timer.py:185) raises. I confirmed this reproduces identically on unmodified main, so it is pre-existing and belongs in a follow-up issue. No change is requested here for it.