fix(clock): provision icons only once rediscover has judged the clock URL

[tarakanof]

Closes #382

Summary

• Root cause (live log, boot 13:15:20Z): the stale /ICONS list did not come from rediscover being slow. reapplySettings restores stored slices in registration order. Weather and Pomodoro come before clock (the URL override), and their after hooks call provisionIconsInBackground. That job dialled the file URL (192.168.0.14, now the knob) while the override (.16) was still being restored, before initDeviceDiscovery ran. The ESP32's slow RST explains the ~100 ms gap before the warning. There is no clock auto-discovered line, and caps were fetched fresh from the right URL right after.
• Second gap: a rediscover swap by the 30 s watch refreshed capabilities but never re-ran icon provisioning or the boot-ping install, so a clock found after boot lacked both until a config change or restart.

Design (updated after review, 51834b2)

• App.iconHold: reapplySettings holds icon provisioning while it restores slices, so their after hooks can't hit a URL that rediscover hasn't judged. The hold and the clock-sync pause are both released by defer. /admin/reload provisions explicitly after its reapply.
• provisionClockInBackground(ctx) starts icon provisioning and the boot-ping install on App.clockJobs, and shutdown waits for them. There are two callers:
  • initDeviceDiscovery, after the boot rediscover. This is the only boot run: the StartWeather icon call and main's boot-ping worker are removed.
  • StartDeviceWatch, on a swap, after rediscoverClock returns.
• rediscoverClock itself does no provisioning, so it never waits on a slow clock while holding deviceRediscoverMu.

Test plan

• New cmd/ember/icon_provision_clock_test.go uses real clockPublisher and two httptest clocks (stale = 404 everything, moved = awtrix-ng fingerprint):
  • TestRediscoverClock_ProvisionsIconsOnMovedClock: swap → moved clock gets the /ICONS list, 2 uploads and the boot-ping script GET; stale gets none.
  • TestBootSequence_ProvisionsIconsOnlyAfterRediscover: stored weather slice, stale file URL → reapplySettings → initDeviceDiscovery → no /ICONS request to stale, uploads land on the rediscovered clock.
• Fail-first, fix stashed:

  --- FAIL: TestRediscoverClock_ProvisionsIconsOnMovedClock
      moved clock got no icon list request; saw [GET /api/v1/device GET /api/v1/capabilities]
  --- FAIL: TestBootSequence_ProvisionsIconsOnlyAfterRediscover
      stale clock URL got icon requests before rediscover: [GET /api/v1/files?dir=%2FICONS]
  

  With the fix, both pass. The second test reproduces the live icon provision: device list failed warning against the stale URL.
• gofmt -l . clean, go vet ./... clean, go test -race ./... all ok.

Audit: boot-time clock I/O before rediscover

• Icon provisioning from reapply hooks: stale. Fixed (hold).
• Capabilities: refreshCapabilities runs inside initDeviceDiscovery after rediscoverClock. In the live log the 21.032 device capabilities cached was a fresh fetch from the judged URL. There is no persistent cache, and a.caps is in-memory only.
• initPomodoro, migrateClockConfig, other reapply after hooks (nudgePomo): no clock I/O. Coordinator sends are queued and published only after StartCoordinator.
• ClearIndicators, ensureBootPingScript, coordinator, brightness, weather workers: all start after initDeviceDiscovery.
• Residual, not changed: if the boot rediscover finds no device (mDNS empty in its 3 s browse), the boot one-shots still hit the unreachable URL once. They now re-run on the watch's swap, so this self-heals within ~30 s.

Docs: ARCHITECTURE (icon provisioning, discovery swap) and RUNBOOK (self-healing) updated.

[tarakanof]

Codex review (read-only, static)

No blockers.

Should-fix: cmd/ember/device.go:81
rediscoverClock runs boot-ping provisioning synchronously while it still holds deviceRediscoverMu. Suppose the clock it found answers device probes but stalls script requests. Each script request then waits up to 8s, plus any time spent waiting on bootPingMu. That stalls rediscovery and the StartDeviceWatch republish. Run the best-effort work asynchronously, after the lock is released.

Nit: cmd/ember/clock_device.go:264
The iconHold release isn't deferred. If a settings hook panics during /admin/reload, HTTP panic recovery keeps the server running, but iconHold stays above zero. From then on, background provisioning is skipped on every reload and every rediscovery. Release it with defer.

Nit: cmd/ember/icon_provision_clock_test.go:64
Both tests set BootPing=false, so they only cover the uninstall path. Add a case with boot ping enabled that checks the script is installed on the moved clock with the right callback URL.

Checked, nothing found:

• Boot without weather: startup still provisions icons, because main always starts the weather path.
• Duplicate concurrent provisioning: the icon mutex serializes runs.
• Flaky tests.

[tarakanof]

Independent review: #383

Verdict: no blockers. The fix is correct for #382. I'd fix the four should-fix items before merging.

What I checked: go test -race ./cmd/ember/... passes. The two new tests ran 30x with -race and all passed. Fail-first is confirmed. On base 29947c5, both tests fail with the messages quoted in the PR body. Reverting only the iconHold lines makes TestBootSequence_… fail. Removing the admin.go:227 call leaves the whole suite green (see #3).

should-fix

1. cmd/ember/clock_device.go:264-266: the hold is not released on panic. iconHold.Add(-1) is not deferred. /admin/reload calls reapplySettings inside an HTTP handler, and net/http recovers handler panics. So a panic in any apply/after hook leaves iconHold at 1 for the rest of the process. After that, every provisionIconsInBackground returns silently: weather and Pomodoro PUTs, rediscover swaps, later reloads. No log line says why. pauseClockSync has the same pre-existing problem. Fix: defer a.iconHold.Add(-1) and defer a.resumeClockSync().

2. cmd/ember/device.go:81: ensureBootPingScript runs synchronously while deviceRediscoverMu is held. There is no deadlock risk, because nothing takes bootPingMu and then deviceRediscoverMu. Latency is the problem:

   • Boot: initDeviceDiscovery runs before net.Listen (main.go:111). On a swap, boot now waits for a script GET and maybe a PUT, at up to menuCallTimeout = 8 s each. That is up to ~16 s before the HTTP server listens, and the server→clock link is known to be lossy.
   • Watch: RepublishAll("clock_rediscovered") (device.go:144-146) runs only after rediscoverClock returns. So the RAM-only apps on a moved clock are republished up to ~16 s later.

   Fix: go a.ensureBootPingScript(ctx). bootPingMu already serializes it with the main.go:149 worker.

3. cmd/ember/admin.go:227: reload provisioning has no test. Before this PR, a reload provisioned icons through the weather and Pomodoro after hooks. Now the hold suppresses those, and this one line is the only path left. Deleting it keeps go test ./cmd/ember/ green (I checked). If it is lost in a refactor, a reload that turns on native weather icons provisions nothing until restart. Add a reload test that asserts a GET /api/v1/files?dir=/ICONS reaches the stub.

4. cmd/ember/weather.go:511: the common boot case relies on a side effect. When the clock is reachable at its URL and no swap happens, the only boot provisioning is StartWeather's ensureNativeIcons. It works today because a.weather is always non-nil (app.go:135), so weather-disabled and Pomodoro-only configs still get icons, and EMBER_CLOCK=off returns early inside ensureNativeIcons. But Pomodoro icons now depend on the weather worker's first line. If someone adds an early if !cfg.Weather.Enabled { return }, Pomodoro icons stop provisioning at boot and no test fails. TestBootSequence_… only covers the swap path. Fix: provision explicitly in main after initDeviceDiscovery (and drop the StartWeather call), or add a test for "reachable at boot, no swap → icons provisioned".

nit

5. Duplicate boot runs on a swap. Boot provisioning runs twice: once from the swap's provisionIconsInBackground and once from StartWeather's ensureNativeIcons. The boot-ping install also runs twice: once from the swap and once from the main.go:149 worker. iconMu and bootPingMu serialize these, so it's harmless, but it adds an extra /ICONS list and an extra script GET on a lossy link. If ci: add Go fmt/vet/test workflow #4 moves provisioning into main, consider skipping it when the boot rediscover already swapped.

6. cmd/ember/icon_provision.go:18: the hold drops calls instead of deferring them. Correctness depends on every caller of reapplySettings re-running provisioning itself (main through StartWeather, reload through admin.go:227). A "dropped while held" flag that reapplySettings checks and runs on release would keep this inside one function and make deploy: Unraid host networking + writable store volume for discovery; release-driven redeploy docs #3 and ci: add Go fmt/vet/test workflow #4 structural. A PUT that lands during a reload's reapply is fine today only because reload re-provisions after it, and it reads the config fresh.

7. Adjacent and pre-existing, not for this PR. A user PUT of the clock base_url (clockSettingSpec, clock_url.go:66) has no after hook. So a clock the user moves by hand gets no icons or boot-ping until a reload or restart. This is the same gap the swap half of this PR closes for mDNS moves. Worth a follow-up issue.

8. docs/ARCHITECTURE.md (edited paragraph): stale endpoint names, pre-existing. It still says GET /list?dir=/ICONS and multipart POST /edit. The code and the new test stubs use GET/POST /api/v1/files?dir=/ICONS. You're editing this paragraph anyway.

STYLE / docs

• No code comments were added, and iconHold fits the existing hold naming (holdClockRotation).
• The ARCHITECTURE and RUNBOOK changes match the code. "clock is registered last" is true (settings_overlay.go:74).
• In the new paragraph, "the startup run is StartWeather's" is accurate, but it documents the implicit dependency from ci: add Go fmt/vet/test workflow #4.

[tarakanof]

Review replies: fixed in 51834b2

Fail-first means the test was run against a178815, the commit before the fix.

Opus #1 / Codex nit (iconHold not released on panic): fixed. reapplySettings now defers both resumeClockSync and iconHold.Add(-1).

• Test: TestReapplySettings_PanickingHookReleasesHolds.
• Fail-first: iconHold=1 after a panicking reapply, want 0.

Opus #2 / Codex should-fix (boot ping sync under deviceRediscoverMu): fixed. rediscoverClock no longer provisions anything.

• initDeviceDiscovery and the watch's swap branch call provisionClockInBackground(ctx) after rediscoverClock returns. It starts icons and boot ping on App.clockJobs (renamed from iconJobs, and shutdown now waits on it).
• Neither the lock, the boot listener nor the clock_rediscovered republish waits on them.
• Test: TestRediscoverClock_DoesNotWaitOnStalledBootPing.
• Fail-first: rediscoverClock took 8.001699625s behind a stalled boot ping script request.

Opus #3 (reload call untested): fixed.

• Test: TestAdminReload_ProvisionsIcons.
• With the admin.go call deleted it fails: timed out waiting for icon list request after reload.

Opus #4 + #5 (boot provisioning relied on StartWeather; duplicate boot runs): fixed.

• Boot provisioning is now explicit in initDeviceDiscovery.
• The StartWeather icon run and main's boot-ping worker are removed, so boot runs each one-shot exactly once, swap or not.
• Test: TestInitDeviceDiscovery_ProvisionsReachableClockOnce (reachable clock, no swap → exactly one /ICONS list, 2 uploads, 1 boot-ping install).
• Fail-first: icon list requests [], want exactly one boot run.
• TestBootSequence_… now also asserts exactly one list on the swap path.

Opus #6 (dropped-while-held flag): not done. Running the dropped job on release would fire at boot as soon as reapplySettings returns. That is still before initDeviceDiscovery has judged the URL, which is the #382 bug. Each caller re-provisions at the point where the URL is known to be right, and #3 and #4 are now pinned by tests.

Opus #7 (PUT base_url doesn't re-provision): out of scope. The coordinator is filing it as a separate issue.

Opus #8 (ARCHITECTURE endpoints): fixed. The paragraph now says GET/POST /api/v1/files?dir=/ICONS, and it describes the new boot path and the off-lock swap path.

Codex nit (only the uninstall path covered): fixed. TestDeviceWatch_ProvisionsMovedClock drives StartDeviceWatch with boot_ping on and asserts exactly one install on the moved clock equal to berry.BootPingSource(expectedBootCallback()). It also checks the stale URL got no /ICONS or script requests.

Checks: gofmt clean, go vet ./... clean, go test -race ./... all ok. The new tests passed 15 times in a row with -race.

[tarakanof]

Re-review of 51834b2 (on top of a178815)

Verdict: clean. No blockers and no should-fix items. Two nits, neither needs to block the merge.

Prior should-fixes: all fixed

I copied the new tests onto a178815's code, with clockJobs renamed back to iconJobs so they compile:

• TestReapplySettings_PanickingHookReleasesHolds fails with iconHold=1 after a panicking reapply. Fixed by the two defers.

• TestRediscoverClock_DoesNotWaitOnStalledBootPing fails after 8.002s. Fixed: rediscoverClock no longer provisions anything.

• TestInitDeviceDiscovery_ProvisionsReachableClockOnce fails with icon list requests []. Fixed.

• TestAdminReload_ProvisionsIcons, TestDeviceWatch_ProvisionsMovedClock and TestBootSequence_… pass on a178815. That is expected: a178815 already had the admin.go call and provisioned inside rediscoverClock. So I mutation-tested them on 51834b2 instead:

  • Deleting admin.go:227 fails TestAdminReload_ProvisionsIcons.
  • Deleting the watch's provisionClockInBackground (device.go:146) fails TestDeviceWatch_ProvisionsMovedClock.
  • Deleting the one in initDeviceDiscovery (device.go:36) fails TestInitDeviceDiscovery_… and TestBootSequence_….

  Each call site is now pinned by a test.

Boot coverage after moving provisioning into initDeviceDiscovery

• auto_rediscover: false: initDeviceDiscovery is not gated by it, so icons and boot ping still run once at boot. Only the watch is skipped, same as before.
• EMBER_CLOCK=off: initDeviceDiscovery is skipped. Before this PR, ensureNativeIcons returned on clockDisabled() and the boot-ping worker was gated on it too, so nothing changes. On reload, ensureNativeIcons still returns early and the boot ping is still gated.
• No mDNS, or any early return in rediscoverClock (reachable / no-device / same URL / swap lost): initDeviceDiscovery ignores the result and always calls provisionClockInBackground, so these runs target the current URL. An unreachable clock at boot that later comes back at the same URL gets nothing until a reload. That gap predates this PR: the StartWeather call had it too.
• Weather start / weather config change: the weather and Pomodoro after hooks still call provisionIconsInBackground, so a PUT that changes weather icons still provisions. The removed StartWeather call only ever ran once at worker start, and initDeviceDiscovery now covers that run. It reads cfg after reapplySettings and migrateClockConfig, so it sees stored weather and Pomodoro settings.
• Boot ping before net.Listen: same as before. The old worker was also started before Listen, and expectedBootCallback derives the callback from the config, not the listener.

clockJobs, shutdown, Add/Wait

• initDeviceDiscovery runs before the workers start. The watch's provisionClockInBackground runs inside a workers goroutine, so its Add happens-before workers.Wait() returns, and so before clockJobs.Wait(). Both jobs use the signal ctx, so they abort once shutdown starts.
• The handler-side Gos (settings PUT, reload) come before server.Shutdown returns in the normal case. They could race clockJobs.Wait only if Shutdown hits its deadline with a handler still running. That needs the 8 s deadline to expire, and by then done is already abandoned. Negligible.
• iconMu and bootPingMu serialize the overlap between the ctx-bound boot jobs and handler jobs.

#6 argument (don't provision on hold release): sound

main calls reapplySettings before initDeviceDiscovery. A run fired on release would list /ICONS before the URL has been judged, which is #382 again. Each caller now provisions at a point where the URL is known to be good, and tests pin those points.

Real network egress in tests: none added by this PR

I ran go test ./cmd/ember/ with HTTP_PROXY pointed at a local logging stub, on both the PR head and base 29947c5. The outbound requests were identical:

• 19 GET …/api/v1/apps/script/ember-boot-ping in total, to 1.2.3.4, 5.6.7.8, 9.9.9.9, 10.0.0.1 and x.
• No icon requests. The reload tests don't need any icons: Pomodoro and weather are off in their config, so ensureNativeIcons returns before the list.

The boot-ping requests come from the existing go app.ensureBootPingScript(...) in reload. Nothing waits on that goroutine, so it doesn't hang or slow CI. It is still real egress, though, so it's worth a follow-up: give newAppForReload a stub publisher and clock, or turn boot_ping off there. Not caused by this PR.

Nits

1. main.go:211-213: shutdown ordering. clockJobs.Wait() now sits between workers.Wait() and clockMigrate.stopAndWait(). provisionIconsInBackground jobs use context.Background(), so they ignore shutdown, and up to 8 icons × a 10 s gallery fetch on the lossy link can outlast the 8 s deadline. If that happens, stopAndWait is never reached, and a migration job already running can overlap store.Close(). Before this PR, the icon jobs weren't waited on at all. Cheap fix: call clockMigrate.stopAndWait() before clockJobs.Wait(), or have provisionIconsInBackground use an app-lifetime ctx that shutdown cancels.
2. admin.go:229: the reload boot-ping goroutine is the one clock one-shot not on clockJobs. It escapes the shutdown wait, and it is also the source of the test egress above. Moving it onto clockJobs would make the docs claim ("both run on App.clockJobs") true for reload too. Pre-existing.

Runs

• go test -race ./cmd/ember/... -count=3 -run '<the 6 new/changed tests>': ok.
• go test -race ./cmd/ember/... -count=1: ok (83.7 s).
• go vet and gofmt -l: clean.