Occasionally only 1 core recognized instead of 4 on Raspberry Pi 4

Timoses commented 2 years ago

Bug Report

Description

Running talosctl dashboard -n 192.168.2.36 sometimes displays 1 cores on the first line rather than 4 cores after a reboot.

This appears to also be reflected in pods not being able to schedule due to "Insufficient cpu".

I noticed this happening seemingly consistently after a talosctl -n 192.168.2.36 upgrade --image ghcr.io/siderolabs/installer:v1.0.4. Running talosctl -n 192.168.2.36 reboot afterwards seems to help.

I also noticed this happening on all nodes simultaneously after running talosctl -n 192.168.2.36,192.168.2.37,192.168.2.38 reboot.

Logs

Please point me to some log sources that would be helpful. I am quite new using Talos.

Environment

Talos version: [talosctl version --nodes <problematic nodes>]

19:44:32 0> talosctl version --nodes 192.168.2.36,192.168.2.37,192.168.2.38
Client:
    Tag:         v1.0.0
    SHA:         80167fd2
    Built:
    Go version:  go1.17.8
    OS/Arch:     darwin/amd64
Server:
    NODE:        192.168.2.37
    Tag:         v1.0.4
    SHA:         f6696063
    Built:
    Go version:  go1.17.7
    OS/Arch:     linux/arm64
    Enabled:     RBAC
    NODE:        192.168.2.36
    Tag:         v1.0.4
    SHA:         f6696063
    Built:
    Go version:  go1.17.7
    OS/Arch:     linux/arm64
    Enabled:     RBAC
    NODE:        192.168.2.38
    Tag:         v1.0.4
    SHA:         f6696063
    Built:
    Go version:  go1.17.7
    OS/Arch:     linux/arm64
    Enabled:     RBAC

Kubernetes version: [kubectl version --short]:

19:45:23 0> kubectl version --short
Client Version: v1.21.2
Server Version: v1.23.5

Platform: Raspberry Pi 4

Timoses commented 2 years ago

Results of talosctl dmesg when:

Only 1 core recognized (achieved by talosctl -n 192.168.2.37 upgrade --image ghcr.io/siderolabs/installer:v1.0.4 from v1.0.4):

192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Booting Linux on physical CPU 0x0000000000 [0x410fd083]
192.168.2.37: kern:  notice: [2022-05-29T09:23:44.850949629Z]: Linux version 5.15.36-talos (@buildkitsandbox) (gcc (GCC) 11.2.0, GNU ld (GNU Binutils) 2.37) #1 SMP Wed Apr 27 18:33:07 UTC 2022
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Machine model: Raspberry Pi 4 Model B Rev 1.4
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: efi: EFI v2.90 by Das U-Boot
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: efi: RTPROP=0x3cb2c040 SMBIOS=0x3cb28000 RNG=0x27cc0040 MEMRESERVE=0x243ef040
192.168.2.37: kern:  notice: [2022-05-29T09:23:44.850949629Z]: efi: seeding entropy pool
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Reserved memory: created CMA memory pool at 0x000000002c000000, size 64 MiB
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: NUMA: No NUMA configuration found
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: NUMA: Faking a node at [mem 0x0000000000000000-0x00000000fbffffff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: NUMA: NODE_DATA [mem 0xfb7ef400-0xfb7f2fff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Zone ranges:
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   DMA      [mem 0x0000000000000000-0x000000003fffffff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   DMA32    [mem 0x0000000040000000-0x00000000fbffffff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   Normal   empty
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Movable zone start for each node
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Early memory node ranges
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x0000000000000000-0x000000000007ffff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x0000000000080000-0x0000000027cbffff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x0000000027cc0000-0x0000000027cc0fff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x0000000027cc1000-0x000000003cb27fff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x000000003cb28000-0x000000003cb28fff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x000000003cb29000-0x000000003cb2bfff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x000000003cb2c000-0x000000003cb2efff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x000000003cb2f000-0x000000003cb2ffff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x000000003cb30000-0x000000003cb33fff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x000000003cb34000-0x000000003df4ffff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x000000003df50000-0x000000003df5ffff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x000000003df60000-0x000000003dffffff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x000000003ef60000-0x000000003ef60fff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]:   node   0: [mem 0x0000000040000000-0x00000000fbffffff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Initmem setup node 0 [mem 0x0000000000000000-0x00000000fbffffff]
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: On node 0, zone DMA: 3936 pages in unavailable ranges
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: On node 0, zone DMA32: 4255 pages in unavailable ranges
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: On node 0, zone DMA32: 16384 pages in unavailable ranges
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: psci: probing for conduit method from DT.
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: psci: PSCIv1.1 detected in firmware.
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: psci: Using standard PSCI v0.2 function IDs
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: psci: MIGRATE_INFO_TYPE not supported.
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: psci: SMC Calling Convention v1.2
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: percpu: Embedded 29 pages/cpu s81296 r8192 d29296 u118784
192.168.2.37: kern:   debug: [2022-05-29T09:23:44.850949629Z]: pcpu-alloc: s81296 r8192 d29296 u118784 alloc=29*4096
192.168.2.37: kern:   debug: [2022-05-29T09:23:44.850949629Z]: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Detected PIPT I-cache on CPU0
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: CPU features: detected: Spectre-v2
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: CPU features: detected: Spectre-v3a
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: CPU features: detected: Spectre-BHB
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: CPU features: kernel page table isolation forced ON by KASLR
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: CPU features: detected: Kernel page table isolation (KPTI)
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: CPU features: detected: ARM errata 1165522, 1319367, or 1530923
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Built 1 zonelists, mobility grouping on.  Total pages: 1007873
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Policy zone: DMA32
192.168.2.37: kern:  notice: [2022-05-29T09:23:44.850949629Z]: Kernel command line: talos.platform=metal talos.config=none console=tty0 console=ttyAMA0,115200 init_on_alloc=1 slab_nomerge pti=on consoleblank=0 nvme_core.io_timeout=4294967295 random.trust_cpu=on printk.devkmsg=on ima_template=ima-ng ima_appraise=fix ima_hash=sha512 talos.board=rpi_4
192.168.2.37: kern:  notice: [2022-05-29T09:23:44.850949629Z]: Unknown kernel command line parameters "pti=on", will be passed to user space.
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: mem auto-init: stack:byref_all(zero), heap alloc:on, heap free:off
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: software IO TLB: mapped [mem 0x0000000038b28000-0x000000003cb28000] (64MB)
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Memory: 3788168K/4096004K available (32128K kernel code, 5094K rwdata, 11068K rodata, 8768K init, 936K bss, 242300K reserved, 65536K cma-reserved)
192.168.2.37: kern:  notice: [2022-05-29T09:23:44.850949629Z]: random: get_random_u64 called from __kmem_cache_create+0x30/0x57c with crng_init=0
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: trace event string verifier disabled
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: rcu: Hierarchical RCU implementation.
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: rcu: \x09RCU restricting CPUs from NR_CPUS=512 to nr_cpu_ids=4.
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: \x09Tracing variant of Tasks RCU enabled.
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: Root IRQ handler: gic_handle_irq
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: GIC: Using split EOI/Deactivate mode
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: arch_timer: cp15 timer(s) running at 54.00MHz (phys).
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
192.168.2.37: kern:    info: [2022-05-29T09:23:44.850949629Z]: sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
192.168.2.37: kern:    info: [2022-05-29T09:23:44.851209629Z]: Console: colour dummy device 80x25
192.168.2.37: kern:    info: [2022-05-29T09:23:44.851563629Z]: printk: console [tty0] enabled
192.168.2.37: kern:    info: [2022-05-29T09:23:44.851648629Z]: Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=216000)
192.168.2.37: kern:    info: [2022-05-29T09:23:44.851667629Z]: pid_max: default: 32768 minimum: 301
192.168.2.37: kern:    info: [2022-05-29T09:23:44.851759629Z]: LSM: Security Framework initializing
192.168.2.37: kern:    info: [2022-05-29T09:23:44.851786629Z]: Yama: becoming mindful.
192.168.2.37: kern:    info: [2022-05-29T09:23:44.851957629Z]: Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
192.168.2.37: kern:    info: [2022-05-29T09:23:44.852025629Z]: Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
192.168.2.37: kern:    info: [2022-05-29T09:23:44.853666629Z]: rcu: Hierarchical SRCU implementation.
192.168.2.37: kern:    info: [2022-05-29T09:23:44.855182629Z]: Remapping and enabling EFI services.
192.168.2.37: kern:    info: [2022-05-29T09:23:44.855534629Z]: smp: Bringing up secondary CPUs ...
192.168.2.37: kern:    crit: [2022-05-29T09:23:49.941509629Z]: CPU1: failed to come online
192.168.2.37: kern:     err: [2022-05-29T09:23:49.941523629Z]: CPU1: failed in unknown state : 0x0
192.168.2.37: kern:    crit: [2022-05-29T09:23:55.063882629Z]: CPU2: failed to come online
192.168.2.37: kern:     err: [2022-05-29T09:23:55.063895629Z]: CPU2: failed in unknown state : 0x0
192.168.2.37: kern:    crit: [2022-05-29T09:24:00.186239629Z]: CPU3: failed to come online
192.168.2.37: kern:     err: [2022-05-29T09:24:00.186252629Z]: CPU3: failed in unknown state : 0x0
192.168.2.37: kern:    info: [2022-05-29T09:24:00.186293629Z]: smp: Brought up 1 node, 1 CPU
192.168.2.37: kern:    info: [2022-05-29T09:24:00.186303629Z]: SMP: Total of 1 processors activated.
192.168.2.37: kern:    info: [2022-05-29T09:24:00.186313629Z]: CPU features: detected: 32-bit EL0 Support
192.168.2.37: kern:    info: [2022-05-29T09:24:00.186320629Z]: CPU features: detected: 32-bit EL1 Support
192.168.2.37: kern:    info: [2022-05-29T09:24:00.186331629Z]: CPU features: detected: CRC32 instructions
192.168.2.37: kern:    info: [2022-05-29T09:24:00.186472629Z]: CPU features: emulated: Privileged Access Never (PAN) using TTBR0_EL1 switching
192.168.2.37: kern:    info: [2022-05-29T09:24:00.211099629Z]: CPU: All CPU(s) started at EL2
...

4 cores correctly recognized (after talosctl reboot):

192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Booting Linux on physical CPU 0x0000000000 [0x410fd083]
192.168.2.37: kern:  notice: [2022-05-29T09:38:58.047699019Z]: Linux version 5.15.36-talos (@buildkitsandbox) (gcc (GCC) 11.2.0, GNU ld (GNU Binutils) 2.37) #1 SMP Wed Apr 27 18:33:07 UTC 2022
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Machine model: Raspberry Pi 4 Model B Rev 1.4
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: efi: EFI v2.90 by Das U-Boot
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: efi: RTPROP=0x3cb2a040 SMBIOS=0x3cb26000 RNG=0x243ef040 MEMRESERVE=0x243ee040
192.168.2.37: kern:  notice: [2022-05-29T09:38:58.047699019Z]: efi: seeding entropy pool
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Reserved memory: created CMA memory pool at 0x000000002c000000, size 64 MiB
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: NUMA: No NUMA configuration found
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: NUMA: Faking a node at [mem 0x0000000000000000-0x00000000fbffffff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: NUMA: NODE_DATA [mem 0xfb7f1400-0xfb7f4fff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Zone ranges:
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   DMA      [mem 0x0000000000000000-0x000000003fffffff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   DMA32    [mem 0x0000000040000000-0x00000000fbffffff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   Normal   empty
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Movable zone start for each node
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Early memory node ranges
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x0000000000000000-0x000000000007ffff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x0000000000080000-0x00000000243eefff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x00000000243ef000-0x00000000243effff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x00000000243f0000-0x000000003cb25fff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x000000003cb26000-0x000000003cb26fff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x000000003cb27000-0x000000003cb29fff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x000000003cb2a000-0x000000003cb2cfff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x000000003cb2d000-0x000000003cb2dfff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x000000003cb2e000-0x000000003cb31fff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x000000003cb32000-0x000000003df4ffff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x000000003df50000-0x000000003df5ffff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x000000003df60000-0x000000003dffffff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x000000003ef60000-0x000000003ef60fff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]:   node   0: [mem 0x0000000040000000-0x00000000fbffffff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Initmem setup node 0 [mem 0x0000000000000000-0x00000000fbffffff]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: On node 0, zone DMA: 3936 pages in unavailable ranges
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: On node 0, zone DMA32: 4255 pages in unavailable ranges
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: On node 0, zone DMA32: 16384 pages in unavailable ranges
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: psci: probing for conduit method from DT.
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: psci: PSCIv1.1 detected in firmware.
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: psci: Using standard PSCI v0.2 function IDs
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: psci: MIGRATE_INFO_TYPE not supported.
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: psci: SMC Calling Convention v1.2
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: percpu: Embedded 29 pages/cpu s81296 r8192 d29296 u118784
192.168.2.37: kern:   debug: [2022-05-29T09:38:58.047699019Z]: pcpu-alloc: s81296 r8192 d29296 u118784 alloc=29*4096
192.168.2.37: kern:   debug: [2022-05-29T09:38:58.047699019Z]: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Detected PIPT I-cache on CPU0
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: CPU features: detected: Spectre-v2
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: CPU features: detected: Spectre-v3a
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: CPU features: detected: Spectre-BHB
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: CPU features: kernel page table isolation forced ON by KASLR
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: CPU features: detected: Kernel page table isolation (KPTI)
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: CPU features: detected: ARM errata 1165522, 1319367, or 1530923
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Built 1 zonelists, mobility grouping on.  Total pages: 1007873
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Policy zone: DMA32
192.168.2.37: kern:  notice: [2022-05-29T09:38:58.047699019Z]: Kernel command line: BOOT_IMAGE=/B/vmlinuz talos.platform=metal talos.config=none console=tty0 console=ttyAMA0,115200 init_on_alloc=1 slab_nomerge pti=on consoleblank=0 nvme_core.io_timeout=4294967295 random.trust_cpu=on printk.devkmsg=on ima_template=ima-ng ima_appraise=fix ima_hash=sha512 talos.board=rpi_4
192.168.2.37: kern:  notice: [2022-05-29T09:38:58.047699019Z]: Unknown kernel command line parameters "BOOT_IMAGE=/B/vmlinuz pti=on", will be passed to user space.
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: mem auto-init: stack:byref_all(zero), heap alloc:on, heap free:off
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: software IO TLB: mapped [mem 0x0000000038b26000-0x000000003cb26000] (64MB)
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Memory: 3788176K/4096004K available (32128K kernel code, 5094K rwdata, 11068K rodata, 8768K init, 936K bss, 242292K reserved, 65536K cma-reserved)
192.168.2.37: kern:  notice: [2022-05-29T09:38:58.047699019Z]: random: get_random_u64 called from __kmem_cache_create+0x30/0x57c with crng_init=0
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: trace event string verifier disabled
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: rcu: Hierarchical RCU implementation.
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: rcu: \x09RCU restricting CPUs from NR_CPUS=512 to nr_cpu_ids=4.
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: \x09Tracing variant of Tasks RCU enabled.
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: Root IRQ handler: gic_handle_irq
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: GIC: Using split EOI/Deactivate mode
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: arch_timer: cp15 timer(s) running at 54.00MHz (phys).
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
192.168.2.37: kern:    info: [2022-05-29T09:38:58.047699019Z]: sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
192.168.2.37: kern:    info: [2022-05-29T09:38:58.048190019Z]: Console: colour dummy device 80x25
192.168.2.37: kern:    info: [2022-05-29T09:38:58.048893019Z]: printk: console [tty0] enabled
192.168.2.37: kern:    info: [2022-05-29T09:38:58.049040019Z]: Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=216000)
192.168.2.37: kern:    info: [2022-05-29T09:38:58.049075019Z]: pid_max: default: 32768 minimum: 301
192.168.2.37: kern:    info: [2022-05-29T09:38:58.049244019Z]: LSM: Security Framework initializing
192.168.2.37: kern:    info: [2022-05-29T09:38:58.049287019Z]: Yama: becoming mindful.
192.168.2.37: kern:    info: [2022-05-29T09:38:58.049525019Z]: Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
192.168.2.37: kern:    info: [2022-05-29T09:38:58.049610019Z]: Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
192.168.2.37: kern:    info: [2022-05-29T09:38:58.052281019Z]: rcu: Hierarchical SRCU implementation.
192.168.2.37: kern:    info: [2022-05-29T09:38:58.054992019Z]: Remapping and enabling EFI services.
192.168.2.37: kern:    info: [2022-05-29T09:38:58.055492019Z]: smp: Bringing up secondary CPUs ...
192.168.2.37: kern:    info: [2022-05-29T09:38:58.056330019Z]: Detected PIPT I-cache on CPU1
192.168.2.37: kern:    info: [2022-05-29T09:38:58.056406019Z]: CPU1: Booted secondary processor 0x0000000001 [0x410fd083]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.057253019Z]: Detected PIPT I-cache on CPU2
192.168.2.37: kern:    info: [2022-05-29T09:38:58.057305019Z]: CPU2: Booted secondary processor 0x0000000002 [0x410fd083]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.058174019Z]: Detected PIPT I-cache on CPU3
192.168.2.37: kern:    info: [2022-05-29T09:38:58.058226019Z]: CPU3: Booted secondary processor 0x0000000003 [0x410fd083]
192.168.2.37: kern:    info: [2022-05-29T09:38:58.058335019Z]: smp: Brought up 1 node, 4 CPUs
192.168.2.37: kern:    info: [2022-05-29T09:38:58.058419019Z]: SMP: Total of 4 processors activated.
192.168.2.37: kern:    info: [2022-05-29T09:38:58.058435019Z]: CPU features: detected: 32-bit EL0 Support
192.168.2.37: kern:    info: [2022-05-29T09:38:58.058448019Z]: CPU features: detected: 32-bit EL1 Support
192.168.2.37: kern:    info: [2022-05-29T09:38:58.058465019Z]: CPU features: detected: CRC32 instructions
192.168.2.37: kern:    info: [2022-05-29T09:38:58.058683019Z]: CPU features: emulated: Privileged Access Never (PAN) using TTBR0_EL1 switching
192.168.2.37: kern:    info: [2022-05-29T09:38:58.104465019Z]: CPU: All CPU(s) started at EL2
...

Timoses commented 2 years ago

Reproduced with Talos v1.0.0:

Spun up new v1.0.0 node by copying metal-rpi_4-arm64.img.xz onto SD card and doing a talosctl apply-config --insecure.
Initially recognized 4 cores correctly
After talosctl reboot -> Only 1 core found

Timoses commented 2 years ago

I believe I found the pattern:

talosctl reboot -> 4 cores
talosctl reboot -> 1 core
talosctl reboot -> 4 cores
talosctl reboot -> 1 core
talosctl reboot -> 4 cores
talosctl reboot -> 1 core

Difference in dmesg:

> diff -u <(cat 1core_100_reboot  | cut -d: -f7-) <(cat 4core_100_reboot  | cut -d: -f7-)  | head -50
--- /dev/fd/11  2022-05-29 12:16:49.000000000 +0200
+++ /dev/fd/13  2022-05-29 12:16:49.000000000 +0200
@@ -8,7 +8,7 @@
  OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
  NUMA: No NUMA configuration found
  NUMA: Faking a node at [mem 0x0000000000000000-0x00000000fbffffff]
- NUMA: NODE_DATA [mem 0xfb7ef400-0xfb7f2fff]
+ NUMA: NODE_DATA [mem 0xfb7ee400-0xfb7f1fff]
  Zone ranges:
    DMA      [mem 0x0000000000000000-0x000000003fffffff]
    DMA32    [mem 0x0000000040000000-0x00000000fbffffff]
@@ -47,13 +47,13 @@
  CPU features: detected: ARM errata 1165522, 1319367, or 1530923
  Built 1 zonelists, mobility grouping on.  Total pages: 1007873
  Policy zone: DMA32
- Kernel command line: talos.platform=metal console=tty0 console=ttyAMA0,115200 init_on_alloc=1 slab_nomerge pti=on consoleblank=0 nvme_core.io_timeout=4294967295 random.trust_cpu=on printk.devkmsg=on ima_template=ima-ng ima_appraise=fix ima_hash=sha512 talos.board=rpi_4
- Unknown kernel command line parameters "pti=on", will be passed to user space.
+ Kernel command line: BOOT_IMAGE=/A/vmlinuz talos.platform=metal console=tty0 console=ttyAMA0,115200 init_on_alloc=1 slab_nomerge pti=on consoleblank=0 nvme_core.io_timeout=4294967295 random.trust_cpu=on printk.devkmsg=on ima_template=ima-ng ima_appraise=fix ima_hash=sha512 talos.board=rpi_4
+ Unknown kernel command line parameters "BOOT_IMAGE=/A/vmlinuz pti=on", will be passed to user space.
  Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)
  Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
  mem auto-init: stack:byref_all(zero), heap alloc:on, heap free:off
  software IO TLB: mapped [mem 0x0000000038b26000-0x000000003cb26000] (64MB)
- Memory: 3788428K/4096004K available (32064K kernel code, 5098K rwdata, 11064K rodata, 8768K init, 932K bss, 242040K reserved, 65536K cma-reserved)
+ Memory: 3788424K/4096004K available (32064K kernel code, 5098K rwdata, 11064K rodata, 8768K init, 932K bss, 242044K reserved, 65536K cma-reserved)
  random: get_random_u64 called from __kmem_cache_create+0x30/0x57c with crng_init=0
  SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
  trace event string verifier disabled
@@ -79,14 +79,14 @@
  rcu: Hierarchical SRCU implementation.
  Remapping and enabling EFI services.
  smp: Bringing up secondary CPUs ...
- CPU1: failed to come online
- CPU1: failed in unknown state : 0x0
- CPU2: failed to come online
- CPU2: failed in unknown state : 0x0
- CPU3: failed to come online
- CPU3: failed in unknown state : 0x0
- smp: Brought up 1 node, 1 CPU
- SMP: Total of 1 processors activated.
+ Detected PIPT I-cache on CPU1
+ CPU1: Booted secondary processor 0x0000000001 [0x410fd083]
+ Detected PIPT I-cache on CPU2
+ CPU2: Booted secondary processor 0x0000000002 [0x410fd083]
+ Detected PIPT I-cache on CPU3
+ CPU3: Booted secondary processor 0x0000000003 [0x410fd083]
+ smp: Brought up 1 node, 4 CPUs
+ SMP: Total of 4 processors activated.
  CPU features: detected: 32-bit EL0 Support
  CPU features: detected: 32-bit EL1 Support

Important one I think is:

- Kernel command line: talos.platform=metal console=tty0 console=ttyAMA0,115200 init_on_alloc=1 slab_nomerge pti=on consoleblank=0 nvme_core.io_timeout=4294967295 random.trust_cpu=on printk.devkmsg=on ima_template=ima-ng ima_appraise=fix ima_hash=sha512 talos.board=rpi_4
+ Kernel command line: BOOT_IMAGE=/A/vmlinuz talos.platform=metal console=tty0 console=ttyAMA0,115200 init_on_alloc=1 slab_nomerge pti=on consoleblank=0 nvme_core.io_timeout=4294967295 random.trust_cpu=on printk.devkmsg=on ima_template=ima-ng ima_appraise=fix ima_hash=sha512 talos.board=rpi_4

=> It works when BOOT_IMAGE is specified => It fails when it is not

Question is: Why does Talos switch between specifying it and leaving it out between reboots? Should it always be specified on boot?

Timoses commented 2 years ago

Workaround: Set kernel.kexec_load_disabled: 1 to /machine/sysctls configuration.

frezbo commented 2 years ago

Awesome, thanks for finding a way for reproducing the issue. Will get it fixed in the code soon

siderolabs / talos