Trim CLAUDE.md: condense crontab bug section to essentials
Remove investigation history, experiment data, upstream fix proposals, and source code analysis. Keep only: what the bug is, our fix (omit force_reboot), detection/auto-heal, and TPM corruption warning. 959 → 792 lines (-17%). Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
This commit is contained in:
parent
4854f15a16
commit
2f04a4838c
259
CLAUDE.md
259
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
|
||||
|
||||
|
|
|
|||
Loading…
Reference in New Issue