173 lines
7.2 KiB
Markdown
173 lines
7.2 KiB
Markdown
# IncusOS Boot Failure Investigation Report
|
|
|
|
Date: 2026-02-21
|
|
ISO tested: IncusOS_202602210344.iso (latest CDN)
|
|
Filed as: IncusOS issue #843
|
|
|
|
## Executive Summary
|
|
|
|
The "ERROR invalid crontab expression" boot failure occurs on **67% of first
|
|
boots** (8/12 API-verified deploys). The bug is a race condition in the
|
|
IncusOS daemon startup sequence — NOT related to version mismatch, update
|
|
downloads, or seed configuration. The `fix_scrub_schedule()` workaround in
|
|
`incusos-proxmox` combined with Proxmox stop+start retry is effective.
|
|
|
|
## Test Methodology
|
|
|
|
- **Tool**: `investigate-parallel` — deploys N VMs simultaneously on Proxmox,
|
|
monitors install via blockstat, transitions to disk boot, detects IP via
|
|
ARP sweep, probes IncusOS REST API, captures console screenshots.
|
|
- **Environment**: Proxmox VE 9.1, Intel i9-13900HK, 4 VMs in parallel
|
|
(VMIDs 850-853), 4096 MiB RAM / 4 cores each, ZFS storage.
|
|
- **ISO**: IncusOS_202602210344.iso (matching CDN latest, no version mismatch)
|
|
- **Seed**: standalone mode (`apply_defaults: true`), `force_reboot: true`,
|
|
app=incus, no update.yaml.
|
|
|
|
## Results
|
|
|
|
### Batches with reliable IP detection (API-verified)
|
|
|
|
| Batch | PASS | CRONTAB_BUG | Bug Rate | Notes |
|
|
|-------|------|-------------|----------|-------|
|
|
| v3 | 1 | 3 | 75% | First batch with working IP detection |
|
|
| v4 | 1 | 3 | 75% | Consistent with v3 |
|
|
| v5 | 2 | 2 | 50% | Slightly better |
|
|
| **Total** | **4** | **8** | **67%** | **12 VMs total** |
|
|
|
|
### Earlier batches (screenshot-verified, IP detection unreliable)
|
|
|
|
| Batch | PASS | CRONTAB_BUG | Notes |
|
|
|-------|------|-------------|-------|
|
|
| v1 | 1* | 3 | *VM 850 showed "System is ready" on console |
|
|
| v2 | 4* | 0 | *All showed "System is ready" on console |
|
|
|
|
*Batch v1-v2 had broken ARP-based IP detection (broadcast ping disabled).
|
|
Console screenshots confirm actual state.
|
|
|
|
### Combined (20 VMs)
|
|
|
|
- **Genuine PASS**: 9 (45%)
|
|
- **CRONTAB_BUG**: 11 (55%)
|
|
- **Overall bug rate: 55-67%** depending on which batches are included
|
|
|
|
## Key Findings
|
|
|
|
### 1. Version mismatch is 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%. The earlier 6 successful observe-deploy
|
|
runs were done when 202602200553 was the latest — those would now also show
|
|
the bug since CDN has been updated to 202602210344.
|
|
|
|
### 2. Sysext downloads happen on EVERY first boot
|
|
|
|
Even with matching ISO version, the first boot downloads:
|
|
1. SecureBoot update (~1 second)
|
|
2. Application sysext (Incus, ~2 minutes from CDN)
|
|
|
|
These are NOT in the ISO. The sysext is always fetched from the update
|
|
provider. An OS update (which triggers a reboot) only occurs when the CDN
|
|
has a newer OS version than the installed ISO.
|
|
|
|
### 3. The error window allows false-positive detection
|
|
|
|
When the bug hits:
|
|
1. `initialize()` creates state.txt with correct ScrubSchedule
|
|
2. REST API starts (port 8443 opens on the IncusOS daemon)
|
|
3. Incus application starts (port 8443 now proxies to Incus)
|
|
4. `registerJobs()` finds empty ScrubSchedule → ERROR
|
|
5. 15-second sleep before `os.Exit(1)`
|
|
6. During this 15-second window, port 8443 is reachable and API works
|
|
7. After exit, daemon restarts → corrupt state.txt → crash loop
|
|
|
|
**Detection**: `scrub_schedule` empty in API response = bug hit.
|
|
`scrub_schedule` = `"0 4 * * 0"` = genuine success.
|
|
|
|
### 4. Console messages are definitive
|
|
|
|
| Last console line | Status |
|
|
|-------------------|--------|
|
|
| `INFO System is ready` | Genuine success |
|
|
| `ERROR invalid crontab expression` | Crontab bug |
|
|
|
|
### 5. The bug is genuinely random
|
|
|
|
Same ISO, same VM specs, same network, same Proxmox host — some VMs
|
|
succeed and some fail within the same batch. No positional pattern
|
|
(VMID, creation order). The timing of concurrent goroutines determines
|
|
whether the race condition triggers.
|
|
|
|
### 6. Version mismatch path adds significant time
|
|
|
|
When ISO version != CDN latest (tested with old ISO 202602200553 against
|
|
CDN 202602210344), the first boot downloads a ~3 GB OS update and reboots.
|
|
With 4 VMs downloading simultaneously, this takes >5 minutes (4 VMs
|
|
sharing bandwidth). The second boot then goes through the normal startup.
|
|
This path was not fully tested for bug rate due to timeout constraints.
|
|
|
|
## Timeline (typical first boot from disk)
|
|
|
|
```
|
|
T+0s UEFI firmware
|
|
T+5s "IncusOS is starting..."
|
|
T+10s state.LoadOrCreate() → initialize() → ScrubSchedule="0 4 * * 0"
|
|
T+10s "Auto-generating encryption recovery key"
|
|
T+15s "System is starting up" (REST API starts)
|
|
T+20s "Bringing up the network"
|
|
T+25s "Downloading SecureBoot update" → "Applying Secure Boot certificate"
|
|
T+25s "Downloading application update" (Incus sysext, ~2 min)
|
|
T+140s "Bringing up the local storage"
|
|
T+142s "Starting application" → "Initializing application"
|
|
T+145s "Application TLS certificate fingerprint" (port 8443 now open)
|
|
T+147s registerJobs() — SUCCESS: "System is ready"
|
|
— or FAILURE: "ERROR invalid crontab expression"
|
|
```
|
|
|
|
## Root Cause Analysis
|
|
|
|
The race condition occurs between `initialize()` setting ScrubSchedule and
|
|
`registerJobs()` reading it. Something between these two steps clears or
|
|
overwrites the ScrubSchedule field. The most likely candidates:
|
|
|
|
1. **Concurrent Save() from sysext application**: when applying the sysext
|
|
update, the daemon may call `Save()` which uses `encodeHelper()`. If the
|
|
ScrubSchedule field has been zeroed in the struct (not the file), the
|
|
encoder skips it, and the next `Load()` reads an empty value.
|
|
|
|
2. **API handler race**: the REST API is active during startup. If any
|
|
handler reads+modifies+saves state concurrently with `startup()`, the
|
|
ScrubSchedule could be lost.
|
|
|
|
3. **Non-atomic writes**: `Save()` uses `os.WriteFile()` (truncate+write).
|
|
A concurrent `Load()` during write could read a partial file.
|
|
|
|
The `defer s.Save()` in `startup()` runs even on error, persisting the
|
|
corrupt state (version 7, ScrubSchedule missing). This makes the error
|
|
permanent within a VM session — only a hard power-off + restart gives a
|
|
chance of recovery (by losing uncommitted journal writes).
|
|
|
|
## Recommendations
|
|
|
|
### For upstream (IncusOS issue #843):
|
|
1. **Defensive default in registerJobs()**: fall back to `"0 4 * * 0"` if
|
|
ScrubSchedule is empty
|
|
2. **Atomic state writes**: use write-to-temp + rename pattern in Save()
|
|
3. **Mutex on State struct**: protect shared fields between API handlers and
|
|
startup goroutines
|
|
4. **Always encode ScrubSchedule**: don't skip zero values for critical fields
|
|
5. **Don't defer Save() unconditionally**: only save on success path
|
|
|
|
### For deployment (incusos-proxmox):
|
|
1. **3 retries** gives 96.3% success rate (1 - 0.67^3) — current default
|
|
2. **fix_scrub_schedule()** heals the root cause via API — already implemented
|
|
3. **Monitor scrub_schedule** on every deployed node — already implemented
|
|
4. **Use latest ISO** to avoid the long OS update + reboot path (saves ~5 min)
|
|
|
|
## Files
|
|
|
|
- Investigation tool: `incusos/investigate-parallel`
|
|
- API helper: `incusos/pve-api`
|
|
- Results: `incusos/observe-runs/parallel_2026-02-21_*`
|
|
- Screenshots: `incusos/observe-runs/parallel_2026-02-21_*/vm-*/frame-*.png`
|