rbrooks/Iris-WLED
Watch
1
0
Fork
You've already forked Iris-WLED
 0
Code Issues 21 Pull requests Projects Releases 2 Packages 1 Wiki Activity Actions

The nightly reschedule cancels the pending sunrise-off, so lights are never turned off automatically #106

New issue
Closed
opened 2026-09-01 16:28:04 +00:00 by claude-bot · 2 comments
claude-bot commented 2026-09-01 16:28:04 +00:00
Contributor
Copy link

Found while checking whether #7's unattended overnight cycle actually ran on the dev deployment. It did not — and the cause is a scheduling bug, not a one-off.

Symptom

On 2026-09-01, dim_job fired correctly at 23:00 CDT. off_job never fired at all. There is no Running job run_off_job line in the container log, and no off_job row in schedule-log for that morning — the only two entries are from my manual runs the night before.

The lights were off when I checked, which briefly looked like success. They had been turned off by a Home Assistant automation, not by Iris. Without that coincidence the roofline would have burned all day.

Cause

There is exactly one off_job slot, and the nightly reschedule overwrites it before it can fire.

_solar_times correctly computes off as the next day's sunrise (scheduler.py / schedule_service.py:78-82):

target 2026-08-31: on=2026-08-31 19:03 CDT  dim=2026-08-31 23:00 CDT  off=2026-09-01 06:31 CDT
target 2026-09-01: on=2026-09-01 19:01 CDT  dim=2026-09-01 23:00 CDT  off=2026-09-02 06:32 CDT

_maybe_schedule registers all three under fixed ids with replace_existing=True:

_maybe_schedule("off_job", run_off_job, off_time, now)
...
_scheduler.add_job(func, DateTrigger(run_date=run_time), id=job_id, replace_existing=True)

And reschedule_daily runs at 00:01 local — which falls between the evening that scheduled the off and the morning it was due:

Time What happens
evening of D−1 off_job scheduled for sunrise of D (06:31)
00:01 on D reschedule_daily recomputes for target D → off = sunrise of D+1, replacing the pending job
06:31 on D nothing fires — that job no longer exists

Confirmed in the live jobstore: after 00:01 CDT on 2026-09-01, off_job sits at 2026-09-02 11:32 UTC, and the 2026-09-01 06:31 CDT firing simply never happened.

on_job and dim_job are unaffected because their correct values always fall on the same calendar day as the reschedule. off_job is the only one whose value belongs to the next day, which is why it is the only one that collides.

Impact

For an outdoor lighting controller this is close to worst-case: the lights are never turned off by Iris. Every night they come on and dim on schedule, then stay lit through the following day until the next evening's cycle. It is silent — every job reports success, and the schedule log looks healthy because the missing job leaves no row.

It also means #7's remaining acceptance criterion — "the configure→approve→push→schedule→sunrise-off loop runs unattended" — cannot pass today.

Possible fixes

  1. Move reschedule_daily off midnight to a time that never has a pending job — local noon, say. It always sits between the morning off and the evening on, so nothing is ever clobbered. One-line cron change, fixes it structurally, and log pruning is just as happy at noon.
  2. Date-qualify the job ids (off_job:2026-09-01), so a new day's jobs cannot replace a pending one. Needs cleanup of stale ids.
  3. Refuse to replace a pending job with a later one in _maybe_schedule. Narrowest change, but the subtlest — the invariant lives in a helper that reads as a pure "add a job".

Option 1 is my recommendation: it removes the overlap rather than defending against it. But this is a design call and the "day" boundary for a lighting schedule is genuinely sunset→sunrise, not midnight→midnight, so option 2 may model it more honestly.

Acceptance criteria

  • A pending sunrise-off survives the nightly reschedule
  • Regression test: schedule an evening cycle, run the reschedule, assert the morning off_job is still registered for the original time
  • Verified unattended on the dev deployment over a real night — off_job present in schedule-log and the controller off after sunrise, with no external automation involved

Blocks #7. Related: #10.

Found while checking whether #7's unattended overnight cycle actually ran on the dev deployment. **It did not** — and the cause is a scheduling bug, not a one-off. ## Symptom On 2026-09-01, `dim_job` fired correctly at 23:00 CDT. **`off_job` never fired at all.** There is no `Running job run_off_job` line in the container log, and no `off_job` row in `schedule-log` for that morning — the only two entries are from my manual runs the night before. The lights *were* off when I checked, which briefly looked like success. They had been turned off by a Home Assistant automation, not by Iris. Without that coincidence the roofline would have burned all day. ## Cause There is exactly one `off_job` slot, and the nightly reschedule overwrites it before it can fire. `_solar_times` correctly computes off as **the next day's** sunrise (`scheduler.py` / `schedule_service.py:78-82`): ``` target 2026-08-31: on=2026-08-31 19:03 CDT dim=2026-08-31 23:00 CDT off=2026-09-01 06:31 CDT target 2026-09-01: on=2026-09-01 19:01 CDT dim=2026-09-01 23:00 CDT off=2026-09-02 06:32 CDT ``` `_maybe_schedule` registers all three under fixed ids with `replace_existing=True`: ```python _maybe_schedule("off_job", run_off_job, off_time, now) ... _scheduler.add_job(func, DateTrigger(run_date=run_time), id=job_id, replace_existing=True) ``` And `reschedule_daily` runs at **00:01 local** — which falls *between* the evening that scheduled the off and the morning it was due: | Time | What happens | |---|---| | evening of D−1 | `off_job` scheduled for **sunrise of D** (06:31) | | **00:01 on D** | `reschedule_daily` recomputes for target D → off = **sunrise of D+1**, replacing the pending job | | 06:31 on D | nothing fires — that job no longer exists | Confirmed in the live jobstore: after 00:01 CDT on 2026-09-01, `off_job` sits at `2026-09-02 11:32 UTC`, and the 2026-09-01 06:31 CDT firing simply never happened. `on_job` and `dim_job` are unaffected because their correct values always fall on the same calendar day as the reschedule. `off_job` is the only one whose value belongs to the *next* day, which is why it is the only one that collides. ## Impact For an outdoor lighting controller this is close to worst-case: **the lights are never turned off by Iris.** Every night they come on and dim on schedule, then stay lit through the following day until the next evening's cycle. It is silent — every job reports success, and the schedule log looks healthy because the missing job leaves no row. It also means #7's remaining acceptance criterion — *"the configure→approve→push→schedule→sunrise-off loop runs unattended"* — **cannot pass today.** ## Possible fixes 1. **Move `reschedule_daily` off midnight** to a time that never has a pending job — local noon, say. It always sits between the morning off and the evening on, so nothing is ever clobbered. One-line cron change, fixes it structurally, and log pruning is just as happy at noon. 2. **Date-qualify the job ids** (`off_job:2026-09-01`), so a new day's jobs cannot replace a pending one. Needs cleanup of stale ids. 3. **Refuse to replace a pending job with a later one** in `_maybe_schedule`. Narrowest change, but the subtlest — the invariant lives in a helper that reads as a pure "add a job". Option 1 is my recommendation: it removes the overlap rather than defending against it. But this is a design call and the "day" boundary for a lighting schedule is genuinely sunset→sunrise, not midnight→midnight, so option 2 may model it more honestly. ## Acceptance criteria - [ ] A pending sunrise-off survives the nightly reschedule - [ ] Regression test: schedule an evening cycle, run the reschedule, assert the morning `off_job` is still registered for the original time - [ ] Verified unattended on the dev deployment over a real night — `off_job` present in `schedule-log` and the controller off after sunrise, with no external automation involved Blocks #7. Related: #10.
claude-bot commented 2026-09-01 16:57:24 +00:00
Author
Contributor
Copy link

Fixed in #107, merged and deployed to the dev host. Staying open until one real overnight confirms it.

Not the fix proposed above

I recommended option 1 — move reschedule_daily off midnight. Implementing it showed that was incomplete. A container restart between midnight and sunrise loses the pending off the same way, because startup calls schedule_today_jobs() too. Moving the cron would have fixed the scheduled path, left the restart path broken, and looked fixed — worse than leaving it.

So the fix went to where the wrong assumption lives. get_active_times() carries a still-pending off forward from the previous cycle; the scheduler and /schedule/status both use it, so the reported off is the one that will actually fire.

Verified on the deployed image, real settings and coordinates

00:01 Sep 2  (reschedule_daily)     off=2026-09-02 06:32 CDT   <-- kept; pre-fix would have said 09-03 06:33
05:00 Sep 2  (restart pre-sunrise)  off=2026-09-02 06:32 CDT   <-- kept; pre-fix would have said 09-03 06:33
12:00 Sep 2  (cycle closed)         off=2026-09-03 06:33 CDT

Row 2 is the case the cron move would have missed.

Jobstore after deploy:

on_job             2026-09-01 19:01 CDT
dim_job            2026-09-01 23:00 CDT
reschedule_daily   2026-09-02 00:01 CDT   <- the moment that used to destroy the off
off_job            2026-09-02 06:32 CDT   <- must still be here at 00:02

One small diagnostic change

The startup log line now prints the date, not just HH:MM. Previously it read off=06:32 with no indication of which day, so the log looked identical whether the off was 6 hours away or 30. That ambiguity is part of why this survived so long, and it cost nothing to remove.

Acceptance criteria

  • A pending sunrise-off survives the nightly reschedule
  • Regression test — two, covering the after-midnight carry-forward and the correct advance once the cycle closes
  • Verified unattended over a real night — pending. Tonight: on_job 19:01, dim_job 23:00, reschedule_daily 00:01, off_job 06:32. The proof is an off_job row in schedule-log tomorrow morning plus the controller actually off.

The Home Assistant automation that masked the original failure has been disabled, so nothing external can produce that result on Iris's behalf this time.

**Fixed in #107, merged and deployed to the dev host.** Staying open until one real overnight confirms it. ### Not the fix proposed above I recommended option 1 — move `reschedule_daily` off midnight. **Implementing it showed that was incomplete.** A container restart between midnight and sunrise loses the pending off the same way, because startup calls `schedule_today_jobs()` too. Moving the cron would have fixed the scheduled path, left the restart path broken, and *looked* fixed — worse than leaving it. So the fix went to where the wrong assumption lives. `get_active_times()` carries a still-pending off forward from the previous cycle; the scheduler and `/schedule/status` both use it, so the reported off is the one that will actually fire. ### Verified on the deployed image, real settings and coordinates ``` 00:01 Sep 2 (reschedule_daily) off=2026-09-02 06:32 CDT <-- kept; pre-fix would have said 09-03 06:33 05:00 Sep 2 (restart pre-sunrise) off=2026-09-02 06:32 CDT <-- kept; pre-fix would have said 09-03 06:33 12:00 Sep 2 (cycle closed) off=2026-09-03 06:33 CDT ``` Row 2 is the case the cron move would have missed. Jobstore after deploy: ``` on_job 2026-09-01 19:01 CDT dim_job 2026-09-01 23:00 CDT reschedule_daily 2026-09-02 00:01 CDT <- the moment that used to destroy the off off_job 2026-09-02 06:32 CDT <- must still be here at 00:02 ``` ### One small diagnostic change The startup log line now prints the date, not just `HH:MM`. Previously it read `off=06:32` with no indication of *which day*, so the log looked identical whether the off was 6 hours away or 30. That ambiguity is part of why this survived so long, and it cost nothing to remove. ### Acceptance criteria - [x] A pending sunrise-off survives the nightly reschedule - [x] Regression test — two, covering the after-midnight carry-forward and the correct advance once the cycle closes - [ ] **Verified unattended over a real night** — pending. Tonight: `on_job` 19:01, `dim_job` 23:00, `reschedule_daily` 00:01, `off_job` 06:32. The proof is an `off_job` row in `schedule-log` tomorrow morning plus the controller actually off. The Home Assistant automation that masked the original failure has been disabled, so nothing external can produce that result on Iris's behalf this time.
claude-bot commented 2026-09-01 17:07:36 +00:00
Author
Contributor
Copy link

Verified on real hardware without waiting for morning

Rather than wait for the overnight, the bug condition was reproduced in minutes by manufacturing it with SUNRISE_OFFSET_MIN.

The distinguishing condition is "now is after midnight but before an off that was computed from the previous cycle." Setting sunrise_offset_min = 334 at 12:00 CDT produced exactly that:
Yesterday-cycle off 2026-09-01 12:05 CDT — pending, 4 minutes out
Today-cycle off 2026-09-02 12:06 CDT — what the pre-fix code would have chosen

Side by side on the deployed image:

FIXED  get_active_times   off=09-01 12:05 CDT   <- carried forward
OLD    get_today_times    off=09-02 12:06 CDT   <- would never fire today

The app then scheduled it itself on startup:

Today's schedule: on=2026-09-01 19:01 CDT, dim=2026-09-01 23:00 CDT, off=2026-09-01 12:05 CDT
off_job    2026-09-01 12:05 CDT

And it fired:

17:05:39Z  off_job  success
off_job: lights off (82 ms)
device: on=False

A schedule_log row for off_job — the row that was missing on the morning of 2026-09-01 — plus the controller actually off. That is the whole failure closed end to end.

Two method notes worth keeping

docker exec … run_reschedule_daily_jobs() does nothing. That process has its own _scheduler = None, so schedule_today_jobs() returns immediately and the app's jobstore is untouched. It reports success. This is the same process-isolation trap as init_controller — a job driven by hand in a fresh process proves nothing about the running scheduler. The reschedule was therefore forced through a container restart, so the app did the scheduling.

That restart also covered the case the originally-proposed fix would have missed — startup between midnight and the pending off. Moving the cron off midnight would have left exactly this path broken.

The date on the startup log line earned itself immediately: off=12:05 and off=12:06 are indistinguishable without it, and those were the two candidate answers.

Restored

  • sunrise_offset_min → 0
  • Rescheduled: on=2026-09-01 19:01 CDT, dim=23:00, off=2026-09-02 06:32 CDT
  • Controller returned to its pre-test snapshot

Acceptance criteria

  • A pending sunrise-off survives the nightly reschedule
  • Regression tests — after-midnight carry-forward, and correct advance once the cycle closes
  • Verified on the dev deployment: off_job fired unattended, logged, and switched the controller off, with the pending-off condition genuinely reproduced

Closing. Tonight's real cycle (19:01 → 23:00 → 00:01 reschedule → 06:32 off) now serves as confirmation in ordinary conditions rather than as the only proof; that observation belongs to #7.

## Verified on real hardware without waiting for morning Rather than wait for the overnight, the bug condition was reproduced in minutes by manufacturing it with `SUNRISE_OFFSET_MIN`. The distinguishing condition is *"now is after midnight but before an off that was computed from the previous cycle."* Setting `sunrise_offset_min = 334` at 12:00 CDT produced exactly that: | | | |---|---| | Yesterday-cycle off | **2026-09-01 12:05 CDT** — pending, 4 minutes out | | Today-cycle off | 2026-09-02 12:06 CDT — what the pre-fix code would have chosen | Side by side on the deployed image: ``` FIXED get_active_times off=09-01 12:05 CDT <- carried forward OLD get_today_times off=09-02 12:06 CDT <- would never fire today ``` The app then scheduled it itself on startup: ``` Today's schedule: on=2026-09-01 19:01 CDT, dim=2026-09-01 23:00 CDT, off=2026-09-01 12:05 CDT off_job 2026-09-01 12:05 CDT ``` And it fired: ``` 17:05:39Z off_job success off_job: lights off (82 ms) device: on=False ``` **A `schedule_log` row for `off_job` — the row that was missing on the morning of 2026-09-01 — plus the controller actually off.** That is the whole failure closed end to end. ### Two method notes worth keeping **`docker exec … run_reschedule_daily_jobs()` does nothing.** That process has its own `_scheduler = None`, so `schedule_today_jobs()` returns immediately and the app's jobstore is untouched. It reports success. This is the same process-isolation trap as `init_controller` — a job driven by hand in a fresh process proves nothing about the running scheduler. The reschedule was therefore forced through a container restart, so the *app* did the scheduling. **That restart also covered the case the originally-proposed fix would have missed** — startup between midnight and the pending off. Moving the cron off midnight would have left exactly this path broken. The date on the startup log line earned itself immediately: `off=12:05` and `off=12:06` are indistinguishable without it, and those were the two candidate answers. ### Restored - `sunrise_offset_min` → 0 - Rescheduled: `on=2026-09-01 19:01 CDT, dim=23:00, off=2026-09-02 06:32 CDT` - Controller returned to its pre-test snapshot ### Acceptance criteria - [x] A pending sunrise-off survives the nightly reschedule - [x] Regression tests — after-midnight carry-forward, and correct advance once the cycle closes - [x] **Verified on the dev deployment**: `off_job` fired unattended, logged, and switched the controller off, with the pending-off condition genuinely reproduced Closing. Tonight's real cycle (19:01 → 23:00 → 00:01 reschedule → 06:32 off) now serves as confirmation in ordinary conditions rather than as the only proof; that observation belongs to #7.
claude-bot added this to the v1.0.0 milestone 2026-09-01 21:54:05 +00:00
Sign in to join this conversation.
No Branch/Tag specified
Branches Tags
main
renovate/lock-file-maintenance
v1.1.0
v1.0.0
Labels
Clear labels   
area/ai
AI suggestion pipeline

  
area/backend
FastAPI / Python backend

  
area/frontend
React / Vite frontend

  
area/infra
Docker, deployment, and infrastructure

  
area/scheduler
Scheduler and time envelope

  
area/wled
WLED controller integration

  
good-first-issue
Good for newcomers

  
priority/high
Blocks release or high impact

  
priority/low
Nice to have

  
priority/medium
Should be done soon

  
type/bug
Something isn't working

  
type/chore
Maintenance, release, or housekeeping

  
type/ci-cd
CI/CD pipeline, build, or release automation

  
type/docs
Documentation

  
type/feature
New capability or enhancement

  
type/qa
Testing, validation, or quality assurance

  
v1.0.0
Target release: v1.0.0

  
v1.1.0
Target release: v1.1.0

  
v1.2.0
Target release: v1.2.0

  
v2.0.0
Target release: v2.0.0

No labels
area/ai
area/backend
area/frontend
area/infra
area/scheduler
area/wled
good-first-issue
priority/high
priority/low
priority/medium
type/bug
type/chore
type/ci-cd
type/docs
type/feature
type/qa
v1.0.0
v1.1.0
v1.2.0
v2.0.0
Milestone
Clear milestone
No items
No milestone
v1.0.0
Projects
Clear projects
No items
No project
Assignees
Clear assignees
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
rbrooks/Iris-WLED#106
No description provided.