diff --git a/CLAUDE.md b/CLAUDE.md index 41dde8d..837a875 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -148,16 +148,12 @@ incu-contrib/ (2) **ARP-based lookup** (fallback for DHCP): get MAC from Proxmox VM config → flush stale ARP → ping broadcast → look up MAC in ARP table. Only works on the same L2 domain (native LAN, not across VLANs). -- **force_reboot is NOT used on Proxmox** (changed 2026-02-22): the seed - omits `force_reboot`. Without it, IncusOS sits at "please remove - installation media" after install — which is exactly what we want. We +- **force_reboot is NOT used on Proxmox**: the seed omits `force_reboot`. + IncusOS sits at "please remove installation media" after install. We detect completion via blockstat (876 MiB written, then idle), stop the - VM externally, remove media, and start from disk. This eliminates the - SysRq-B intermediate boot that triggers the crontab race condition - (issue #843). On physical hardware or unmanaged VMs, `force_reboot: true` - is still needed — this optimization is specific to Proxmox automated deploys. - `force_reboot` triggers SysRq-B (raw kernel reboot via `/proc/sysrq-trigger`). - This does NOT reset QEMU VM uptime — only a Proxmox stop/start does. + VM externally, remove media, and start from disk. This avoids the + crontab race condition (issue #843). On physical hardware, + `force_reboot: true` is still needed (no external orchestrator). - **Resource pool isolation**: the optional `proxmox.pool` config field scopes all VM operations to a Proxmox resource pool. When set, the script only "sees" VMs in that pool (for collision detection and cleanup), and the API @@ -531,8 +527,7 @@ incu-contrib/ - **Stale entries** from out-of-band cluster changes persist after resync - **Server removal blocked** if server is part of an OC cluster - **Node failure recovery**: Proxmox hard-stop simulates crash. After restart, - node auto-rejoins cluster in ~60s. Containers auto-start. Works cleanly - if crontab bug doesn't hit (auto-healed by `fix_scrub_schedule()`). + node auto-rejoins cluster in ~60s. Containers auto-start. - **`needs_update` tracking is pipeline-based**: OC tracks whether an update was delivered through its pipeline, not just whether versions match. Nodes deployed from the latest ISO are tracked as needing updates even when @@ -560,223 +555,61 @@ incu-contrib/ except warnings and errors. - **`--retries N`**: number of stop+start retries for VMs that fail to boot (port 8443 not reachable). Default: 3. `--retries 0` disables retries. - Each retry: Proxmox stop → wait → start → 60s wait → poll port 8443 for - up to 120s. With the `force_reboot` fix (2026-02-22), the crontab bug is - eliminated and retries are rarely needed. They remain as a safety net for - other transient boot failures. After retries, `fix_scrub_schedule()` - proactively heals any remaining scrub_schedule issues via the IncusOS - REST API. + Retries are rarely needed since omitting `force_reboot`. After boot, + `fix_scrub_schedule()` proactively heals any scrub_schedule issues. - **Boot timeout is 180s** (60s initial sleep + 120s polling): first boot - downloads SecureBoot update + application sysext (Incus: ~30-120s depending - on CDN speed and concurrent VMs). The previous 90s timeout was too short - under load — premature retries (hard VM stop during first boot) can corrupt - the TPM encryption key, causing permanent "zfs load-key: Raw key too short - (expected 32)" errors that no amount of retries can fix. + downloads application sysext (~30-120s depending on CDN speed). Do not + reduce — premature retries can corrupt the TPM encryption key permanently. -### IncusOS first-boot sequence (observed via console screenshots) +### IncusOS first-boot sequence -Observed using `observe-deploy` with 2-second screenshot intervals. The -complete lifecycle from Proxmox VM start to port 8443 ready: +Complete lifecycle from Proxmox VM start to port 8443 ready: **Phase 1: ISO boot and installation (~60-85s)** -1. UEFI firmware → "Guest has not initialized the display (yet)" (~2s) -2. IncusOS boot menu: "IncusOS 202602200553" selected, "Boot in 1 s." (~10s) -3. IncusOS Install TUI: "Starting install of IncusOS to local disk" (~24s) - - "Installing IncusOS source=/dev/mapper/sr0 target=/dev/sda" - - "Cloning GPT partitions" → progress bar → complete -4. `force_reboot: true` triggers **SysRq-B** (raw kernel reboot via - `/proc/sysrq-trigger`, preceded by `unix.Sync()` + 5s sleep). Not - a graceful systemd reboot. This is intentional — the install - environment is minimal and may not have systemd running. -5. VM reboots but ISO still attached → boots from ISO again -6. "System check error: install media detected, but the system is already - installed; please remove USB/CDROM and reboot the system" (~40s). - IncusOS daemon sleeps **1 hour** at this error, then exits. The - `state.txt` on the installed disk (scsi0 data partition) is **NOT - touched** — this boot runs from the ISO rootfs (tmpfs). -7. Stays at this error until blockstat detects stable writes (3×5s = 15s idle) +1. UEFI firmware → IncusOS boot menu → "Starting install of IncusOS to local disk" +2. "Cloning GPT partitions" → progress bar → complete (~876 MiB written) +3. Without `force_reboot`, installer sits at "please remove installation media" **Phase 2: Transition (~15s)** -1. Proxmox stops VM -2. Remove ide2 (ISO) and ide3 (seed), set `boot: order=scsi0` +1. `incusos-proxmox` detects install complete via blockstat (876 MiB written, then idle) +2. Proxmox stops VM, removes ide2 (ISO) and ide3 (seed), sets `boot: order=scsi0` 3. Start VM from disk **Phase 3: First boot from disk (~50s to port 8443)** -1. UEFI → "IncusOS is starting..." (~8s) -2. `state.LoadOrCreate()` → state.txt doesn't exist → `initialize()` sets - defaults: `ScrubSchedule="0 4 * * 0"`, `CheckFrequency="6h"`, - `Channel="stable"` → `Save()` writes state.txt to data partition -3. "Auto-generating encryption recovery key, this may take a few seconds" (~10s) -4. "System is starting up machine-id=... mode=production" (~10s after key) -5. "Bringing up the network" (immediate) -6. "Downloading SecureBoot update" → "Applying Secure Boot certificate" (~12s) -7. "Downloading application update application=incus" + progress bar (~33-38s) -8. "Bringing up the local storage" (after download) -9. "Starting application" → "Initializing application" → TLS cert fingerprint -10. `registerJobs()` validates ScrubSchedule with gocron -11. "System is ready" — port 8443 now reachable +1. UEFI → "IncusOS is starting..." +2. `state.LoadOrCreate()` creates `state.txt` with defaults +3. "Auto-generating encryption recovery key" (~10s) +4. "Downloading SecureBoot update" + "Downloading application update" (~33-38s) +5. "Starting application" → "System is ready" — port 8443 now reachable **Total: ~130-215s from VM create to port 8443 ready.** The biggest variable -is the application download (33-38s on first boot; skipped if already cached). +is the application sysext download (~33-38s on first boot; skipped if cached). -**Important**: `DoInstall()` does NOT create `state.txt`. It writes the -IncusOS image to disk, processes seed files (including deleting `install.yaml` -from the target's seed partition via `CleanupPostInstall()`), and triggers -the SysRq-B reboot. The `state.txt` is created exclusively on first boot -from the installed disk by `state.LoadOrCreate()` → `initialize()`. +### IncusOS crontab bug (upstream issue #843) -### IncusOS boot failure (crontab / update frequency error) +**Status:** Eliminated in our pipeline by omitting `force_reboot` from seeds. +The upstream bug still exists but only triggers with `force_reboot: true`. -- **RESOLVED** (2026-02-22): root cause identified and fixed in our pipeline. - The `force_reboot` seed option triggers SysRq-B after install, causing an - "install media detected" intermediate boot. This intermediate boot generates - ~26 GB of additional disk writes (the IncusOS daemon starts from ISO tmpfs). - Our blockstat detection catches these late writes, but by then the - intermediate boot has run and somehow corrupted the state for the subsequent - first-from-disk boot. **Fix: omit `force_reboot` from the seed.** Without - it, the installer sits at "please remove media" after the 876 MiB image - clone, blockstat detects idle cleanly, and the first disk boot is pristine. - Results: **15/15 PASS (100%)** without force_reboot on 4 cores vs 50% with it. -- **Symptom**: "ERROR invalid crontab expression" appears on the console - during first boot. Intermittent — confirmed **~50% failure rate** with - `force_reboot: true` on 4-core VMs. Error does NOT correlate with - `update.yaml` presence/absence, ISO version, or version mismatch. -- **Two distinct error paths in IncusOS**: - - `registerJobs()` validates `ScrubSchedule` (5-field crontab expression - like `"0 4 * * 0"`) using `gocron.IsValid()`. If invalid, the entire - daemon exits — **this is the fatal one**. Port 8443 never opens - (or opens briefly during the 15-second error sleep). - - `updateChecker()` validates `CheckFrequency` (Go `time.ParseDuration()` - format like `"6h"`). If invalid, it logs an error but does **not** crash. -- **Not always fatal** (confirmed by parallel investigation): - - The REST API starts BEFORE `startup()` completes. Applications (Incus) - start at step ~16 of `startup()`, while `registerJobs()` is at step ~19. - When Incus starts before the scheduler crashes, port 8443 is available - during the 15-second error sleep (before `os.Exit(1)`). - - Port 8443 is reachable during the error window, and API calls work - (including `/os/1.0/system/storage`). The `scrub_schedule` field is - empty in the API response — this is the definitive indicator. - - "System is ready" is NOT shown on console (only appears after - `registerJobs()` succeeds). Console shows "ERROR invalid crontab - expression" as the last line when the bug hits. - - **Detection heuristic**: port 8443 reachable BUT `scrub_schedule` is - empty → crontab bug hit. Port 8443 reachable AND `scrub_schedule` is - `"0 4 * * 0"` → genuine success. -- **Source code analysis** (root cause investigation): - - `state.txt` is created FRESH on first boot from disk by - `LoadOrCreate()` → `initialize()`. The `initialize()` function - correctly sets `ScrubSchedule = "0 4 * * 0"`. - - The "install media detected" boot (#2, ISO still attached) runs from - the ISO rootfs. It creates state.txt in tmpfs, NOT on the installed - disk. The installed disk's state.txt is untouched. - - `DoInstall()` does not create state.txt. It only writes the OS image - and processes seed files. - - **The encoder skips zero values**: `encodeHelper()` returns early on - `v.IsZero()`. An empty ScrubSchedule string is NOT written to file. - If state.txt is read with a missing ScrubSchedule, the field stays - at Go's zero value (empty string) → `gocron.IsValid("")` fails. - - **Non-atomic state writes**: `Save()` uses `os.WriteFile()` which - truncates then writes. Crash during write → partial file. - - **Race window**: The REST API server starts BEFORE `startup()` - completes. Applications start before `registerJobs()`. A concurrent - API request modifying storage config could clear ScrubSchedule. - - **Root cause confirmed**: the bug is triggered by the SysRq-B - intermediate boot (from `force_reboot: true`). Controlled experiments - on VLAN 69 with static IP (2026-02-22, ISO 202602210344): - - Baseline (4 cores, force_reboot): 5/10 PASS (50%) - - cache=writethrough: 3/5 PASS (60%) — falsified - - agent=0: 3/5 PASS (60%) — falsified - - cores=1 (force_reboot): 14/15 PASS (93%) — GOMAXPROCS=1 reduces race - - **No force_reboot (4 cores): 15/15 PASS (100%)** — confirmed fix - Correlation: runs with 876 MiB blockstat detection (before SysRq-B) - had 100% success; runs with 27 GB detection (after SysRq-B) had ~55%. - - **The try-it service is NOT IncusOS**: stgraber's comparison ("thousands - of times a day") is invalid. The try-it service runs Ubuntu VMs with - Incus installed from the Zabbly daily repo — a completely different - product. Issue #843 was independently filed by another Proxmox user - (fperreau on Proxmox 9.1.4), confirming it's not unique to our setup. - - The underlying IncusOS bug is still a race condition between the REST - API/application startup and `registerJobs()` that clears `ScrubSchedule`. - Investigation ruled out version mismatch, update downloads, and gocron - library issues. The field is genuinely empty in the state struct. - - **Investigation data** (2026-02-21, ISO 202602210344, 4 VMs parallel): - Batch 3: 1 PASS, 3 BUG (75%); Batch 4: 1 PASS, 3 BUG (75%); - Batch 5: 2 PASS, 2 BUG (50%). Total API-verified: 4 PASS, 8 BUG - (67% failure rate). Console screenshots confirm "ERROR invalid crontab - expression" on failed VMs and "System is ready" on successful VMs. - - **Version mismatch NOT the cause**: stgraber's hypothesis that the bug - relates to ISO version != CDN latest was tested and ruled out. With - matching versions (ISO 202602210344 = CDN 202602210344), the bug rate - is 67%. Sysext downloads still occur with matching versions (SecureBoot - + application updates) but no OS update download. The bug occurs - regardless of whether sysext downloads happen. - - **Sysext download on matching versions**: even when ISO version matches - CDN latest, the first boot downloads SecureBoot update (~1s) and - application sysext (~2 min for Incus). The sysext is NOT in the ISO — - it's always downloaded from the update provider. An OS update download - (and reboot) only occurs when versions differ. -- **Proposed upstream fix** (for `incus-os` project): - ```go - // In registerJobs(): validate and fall back to default - func registerJobs(s *state.State) error { - schedule := s.System.Storage.Config.ScrubSchedule - if schedule == "" { - schedule = "0 4 * * 0" - s.System.Storage.Config.ScrubSchedule = schedule - } - err := s.JobScheduler.RegisterJob(zfs.PoolScrubJob, schedule, zfs.ScrubAllPools) - if err != nil { - // Fall back to default instead of crashing the daemon - slog.Warn("Invalid scrub schedule, using default", "schedule", schedule) - s.System.Storage.Config.ScrubSchedule = "0 4 * * 0" - return s.JobScheduler.RegisterJob(zfs.PoolScrubJob, "0 4 * * 0", zfs.ScrubAllPools) - } - return nil - } - ``` - Additional recommendations: (1) use atomic writes in `Save()` (write - to temp file + `os.Rename()`), (2) always encode `ScrubSchedule` even - when empty (to preserve the default through encode/decode cycles), - (3) add mutex protection on State fields shared between API handlers - and startup(). -- **Error is persistent within a VM session**: verified by screenshots — - when the crontab error hits, the deferred `s.Save()` writes corrupt - state (version 7, ScrubSchedule missing because encoder skips zero - values). Subsequent systemd daemon restarts read the corrupt state - and crash again. The error does NOT self-heal via daemon restart alone. -- **Recovery via Proxmox stop+start**: `phase_install` in `incusos-proxmox` - retries once with a full Proxmox stop (hard VM power-off) → 10s wait → - start. The hard power-off may cause uncommitted filesystem writes - (including the corrupt state.txt) to be lost, restoring the correct - state from `initialize()`. This works because IncusOS's data partition - has a journal commit interval (~5s) and the corrupt Save() may not have - been committed before the VM was killed. -- **Detection**: `phase_install` checks port 8443 after starting from disk - (60s wait + up to 120s polling = 180s total). If first check fails, - automatic retry adds ~180s. Failed VMs after retry are reported with - remediation. -- **TPM corruption from premature retry**: hard-stopping a VM during first - boot (while the encryption key is being written to the TPM zvol) can - leave the TPM with truncated key data. All subsequent boots fail with - "zfs load-key: Raw key too short (expected 32)" — a permanent error - that requires VM destruction and redeployment to fix. The 180s boot - timeout prevents this by allowing the full first-boot sequence (including - sysext download) to complete before any retry. -- **Auto-heal via IncusOS REST API**: `incusos-proxmox` includes - `fix_scrub_schedule()` which proactively fixes empty `scrub_schedule` on - every deployed node via `PUT /os/1.0/system/storage`. The `/os/` prefix - proxies to the IncusOS daemon API through Incus. Safe to call on every - node — returns early if schedule is already set. Called on both initial - success and retry success paths. -- **Filed upstream**: IncusOS issue #843. -- **Source files**: `incus-osd/cmd/incus-osd/main.go` (`registerJobs()`, - `updateChecker()`, `startup()`, `firstBootActions()`), - `incus-osd/internal/scheduling/scheduling.go` (`RegisterJob()`, - `ErrInvalidCronTab`), `incus-osd/internal/state/file.go` - (`LoadOrCreate()`, `Save()`, `initialize()`), - `incus-osd/internal/state/encode.go` (`encodeHelper()` zero-value skip), - `incus-osd/internal/install/install.go` (`DoInstall()`, - `rebootUponDeviceRemoval()` SysRq-B). +- **What it is**: a race condition in IncusOS where `ScrubSchedule` ends up + empty in `state.txt`, causing `registerJobs()` → `gocron.IsValid("")` to + fail and the daemon to exit. Port 8443 never opens (or opens briefly + before the daemon crashes). +- **Our fix**: omit `force_reboot` from the seed. Without it, there is no + SysRq-B intermediate boot, and the race condition does not trigger. + Result: **100% success rate** (vs ~50% with `force_reboot` on 4-core VMs). +- **Detection**: port 8443 reachable but `scrub_schedule` is empty in + `GET /os/1.0/system/storage` → bug hit. `incusos-proxmox` checks this + automatically. +- **Auto-heal**: `incusos-proxmox` includes `fix_scrub_schedule()` which + sets `scrub_schedule` to `"0 4 * * 0"` via `PUT /os/1.0/system/storage` + on every deployed node as a safety net. +- **TPM corruption risk**: hard-stopping a VM during first boot (while the + encryption key is being written) can permanently corrupt the TPM. Error: + "zfs load-key: Raw key too short (expected 32)". Only fix is VM destruction + and redeployment. The 180s boot timeout in `incusos-proxmox` prevents this. +- **On physical hardware**: `force_reboot: true` is still needed (no external + orchestrator to remove install media). The bug may occur; recovery is a + manual power cycle. ### Proxmox SSH root access — strict rules