disks stage failure without visible error

[arnegroskurth]

Bug

We justed tried to update Fedora CoreOS from 37.20230218.3.0 to 38.20230709.3.0 but now the VM fails to boot when any additional virtual disk is to be mounted. What particular bad about this, is that no more concrete error appears to be printed in the output that would allow to further track this down:

...
[   17.484716] ignition[825]: Ignition 2.15.0
[   17.489936] ignition[825]: Stage: disks
[   17.492430] ignition[825]: reading system config file "/usr/lib/ignition/base.d/00-core.ign"
[   17.496313] ignition[825]: reading system config file "/usr/lib/ignition/base.d/30-afterburn-sshkeys-core.ign"
[   17.500710] ignition[825]: no config dir at "/usr/lib/ignition/base.platform.d/vmware"
[   17.505835] ignition[825]: disks: createPartitions: op(1): [started]  waiting for devices [/dev/disk/by-id/coreos-boot-disk /dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e]
[   17.513148] ignition[825]: disks: createPartitions: op(1): [finished] waiting for devices [/dev/disk/by-id/coreos-boot-disk /dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e]
[   17.521313] ignition[825]: disks: createPartitions: created device alias for "/dev/disk/by-id/coreos-boot-disk": "/run/ignition/dev_aliases/dev/disk/by-id/coreos-boot-disk" -> "/dev/sda"
[   17.528738] ignition[825]: disks: createPartitions: created device alias for "/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e": "/run/ignition/dev_aliases/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e" -> "/dev/sdb"
[   17.532395]  sda: sda1 sda2 sda3 sda4
[   17.538298] ignition[825]: disks: createPartitions: op(2): [started]  partitioning "/run/ignition/dev_aliases/dev/disk/by-id/coreos-boot-disk"
[   17.546772] ignition[825]: disks: createPartitions: op(2): op(3): [started]  reading partition table of "/run/ignition/dev_aliases/dev/disk/by-id/coreos-boot-disk"
[   17.559888] ignition[825]: disks: createPartitions: op(2): op(3): [finished] reading partition table of "/run/ignition/dev_aliases/dev/disk/by-id/coreos-boot-disk"
[   17.565551]  sda: sda1 sda2 sda3 sda4
[   17.572530] ignition[825]: disks: createPartitions: op(2): running sgdisk with options: [--pretend --delete=4 --new=4:1050624:+16777216 --new=0:0:+0 /run/ignition/dev_aliases/dev/disk/by-id/coreos-boot-disk]
[   17.587239] ignition[825]: disks: createPartitions: op(2): resizing partition 4
[   17.587999]  sda: sda1 sda2 sda3 sda4 sda5
[   17.591320] ignition[825]: disks: createPartitions: op(2): running sgdisk with options: [--delete=4 --new=4:1050624:+16777216 --change-name=4:root --typecode=4:0FC63DAF-8483-4772-8E79-3D69D8477DE4 --partition-guid=4:5D839AC8-A925-4DB0-8277-6E9A9E6C41F8 --new=0:0:+0 --change-name=0:var /run/ignition/dev_aliases/dev/disk/by-id/coreos-boot-disk]
[   17.608752] ignition[825]: disks: createPartitions: op(2): op(4): [started]  deleting 1 partitions and creating 2 partitions on "/run/ignition/dev_aliases/dev/disk/by-id/coreos-boot-disk"
[   18.578073]  sda: sda1 sda2 sda3 sda4 sda5
[   18.596588] ignition[825]: disks: createPartitions: op(2): op(4): [finished] deleting 1 partitions and creating 2 partitions on "/run/ignition/dev_aliases/dev/disk/by-id/coreos-boot-disk"
[   18.610307] ignition[825]: disks: createPartitions: op(2): [finished] partitioning "/run/ignition/dev_aliases/dev/disk/by-id/coreos-boot-disk"
[   18.620072] ignition[825]: disks: createPartitions: op(5): [started]  partitioning "/run/ignition/dev_aliases/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e"
[   18.631228] ignition[825]: disks: createPartitions: op(5): op(6): [started]  reading partition table of "/run/ignition/dev_aliases/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e"
[   18.671848] ignition[825]: disks: createPartitions: op(5): op(6): [finished] reading partition table of "/run/ignition/dev_aliases/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e"
[   18.683096] ignition[825]: disks: createPartitions: op(5): running sgdisk with options: [--pretend --new=1:0:+0 /run/ignition/dev_aliases/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e]
[   18.695222] ignition[825]: disks: createPartitions: op(5): running sgdisk with options: [--new=1:0:+0 /run/ignition/dev_aliases/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e]
[   18.707006] ignition[825]: disks: createPartitions: op(5): op(7): [started]  deleting 0 partitions and creating 1 partitions on "/run/ignition/dev_aliases/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e"
[   19.680003]  sdb: sdb1
[   19.684847] ignition[825]: disks: createPartitions: op(5): op(7): [finished] deleting 0 partitions and creating 1 partitions on "/run/ignition/dev_aliases/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e"
[   19.696354] ignition[825]: disks: createPartitions: op(5): [finished] partitioning "/run/ignition/dev_aliases/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e"
[   19.703975] ignition[825]: disks: createLuks: op(8): [started]  waiting for devices [/dev/disk/by-partlabel/var]
[   19.709367] ignition[825]: disks: createLuks: op(8): [finished] waiting for devices [/dev/disk/by-partlabel/var]
[   19.716261] ignition[825]: disks: createLuks: created device alias for "/dev/disk/by-partlabel/var": "/run/ignition/dev_aliases/dev/disk/by-partlabel/var" -> "/dev/sda5"
[   19.724612] ignition[825]: disks: createLuks: op(9): [started]  checking if /dev/disk/by-partlabel/var is a luks2 device
[   19.732737] ignition[825]: disks: createLuks: op(9): [finished] checking if /dev/disk/by-partlabel/var is a luks2 device
[   19.740363] ignition[825]: disks: createLuks: op(a): [started]  checking if /dev/disk/by-partlabel/var is a luks device
[   19.747771] ignition[825]: disks: createLuks: op(a): [finished] checking if /dev/disk/by-partlabel/var is a luks device
[   19.755218] ignition[825]: disks: createLuks: op(b): [started]  determining volume type of "/dev/disk/by-partlabel/var"
[   19.762611] ignition[825]: disks: createLuks: op(b): [finished] determining volume type of "/dev/disk/by-partlabel/var"
[   19.769896] ignition[825]: disks: createLuks: found  at "/dev/disk/by-partlabel/var" with uuid "" and label ""
[   19.777154] ignition[825]: disks: createLuks: op(c): [started]  creating "var"
[   33.185409] ignition[825]: disks: createLuks: op(c): [finished] creating "var"
[   33.189636] ignition[825]: disks: createLuks: op(d): [started]  opening luks device var
[   36.317354] ignition[825]: disks: createLuks: op(d): [finished] opening luks device var
[   36.321493] ignition[825]: disks: createFilesystems: op(e): [started]  waiting for devices [/dev/mapper/var /dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e-part1]
[   36.335758] ignition[825]: disks: createFilesystems: op(e): [finished] waiting for devices [/dev/mapper/var /dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e-part1]
[   36.344377] ignition[825]: disks: createFilesystems: created device alias for "/dev/mapper/var": "/run/ignition/dev_aliases/dev/mapper/var" -> "/dev/dm-0"
[   36.352001] ignition[825]: disks: createFilesystems: created device alias for "/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e-part1": "/run/ignition/dev_aliases/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e-part1" -> "/dev/sdb1"
[   36.362370] ignition[825]: disks: createFilesystems: op(f): [started]  determining filesystem type of "/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e-part1"
[   36.374640] ignition[825]: disks: createFilesystems: op(f): op(10): [started]  determining filesystem type of "/dev/mapper/var"
[   36.390585] ignition[825]: disks: createFilesystems: op(f): op(10): [finished] determining filesystem type of "/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e-part1"
[   36.398809] ignition[825]: disks: createFilesystems: op(f): found  filesystem at "/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e-part1" with uuid "" and label ""
[   36.406505] ignition[825]: disks: createFilesystems: op(f): op(11): [started]  wiping filesystem signatures from "/run/ignition/dev_aliases/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e-part1"
[   36.414895] ignition[825]: disks: createFilesystems: op(f): op(11): [finished] wiping filesystem signatures from "/run/ignition/dev_aliases/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e-part1"
[   36.425618] ignition[825]: disks: createFilesystems: op(f): op(12): [started]  creating "xfs" filesystem on "/run/ignition/dev_aliases/dev/disk/by-id/wwn-0x6000c2982d69878ee6eba31f9da6c37e-part1"
[   36.462606] ignition[825]: disks: createFilesystems: op(f): [finished] determining filesystem type of "/dev/mapper/var"
[   36.468131] ignition[825]: disks: createFilesystems: found  filesystem at "/dev/mapper/var" with uuid "" and label ""
[   36.472725] ignition[825]: disks: createFilesystems: op(13): [started]  wiping filesystem signatures from "/run/ignition/dev_aliases/dev/mapper/var"
[   36.489249] ignition[825]: disks: createFilesystems: op(13): [finished] wiping filesystem signatures from "/run/ignition/dev_aliases/dev/mapper/var"
[   36.498266] ignition[825]: disks: createFilesystems: op(14): [started]  creating "xfs" filesystem on "/run/ignition/dev_aliases/dev/mapper/var"
[   37.475445] ignition[825]: disks: createFilesystems: op(14): [finished] creating "xfs" filesystem on "/run/ignition/dev_aliases/dev/mapper/var"
[   37.484169] systemd[1]: ignition-disks.service: Main process exited, code=exited, status=1/FAILURE
[   37.489778] ignition[825]: disks failed
[   37.493230] ignition[825]: Full config:
...

Operating System Version

Fedora CoreOS 38.20230709.3.0

Ignition Version

2.15.0

But also tested with Fedora Core OS 38.20230722.2.1 including ignition 2.16.2 with the same result.

Environment

Running CoreOS as .ova VM template on ESXi / vSphere

Expected Behavior

The VM successfully boots.

Actual Behavior

Ignition fails during boot causting the VM to enter the emergency mode.

Other Information

Full VM log: container-host-test-64ccbc62c62d7.milchundzucker.de.log

Full ignition:

{
    "ignition": {
        "version": "3.3.0"
    },
    "storage": {
        "disks": [
            {
                "device": "\/dev\/disk\/by-id\/coreos-boot-disk",
                "partitions": [
                    {
                        "number": 4,
                        "label": "root",
                        "sizeMiB": 8192,
                        "resize": true
                    },
                    {
                        "label": "var",
                        "sizeMiB": 0
                    }
                ]
            },
            {
                "device": "\/dev\/disk\/by-id\/wwn-0x6000c2982d69878ee6eba31f9da6c37e",
                "wipeTable": false,
                "partitions": [
                    {
                        "number": 1
                    }
                ]
            }
        ],
        "luks": [
            {
                "name": "var",
                "device": "\/dev\/disk\/by-partlabel\/var"
            }
        ],
        "filesystems": [
            {
                "device": "\/dev\/mapper\/var",
                "path": "\/var",
                "label": "var",
                "format": "xfs"
            },
            {
                "device": "\/dev\/disk\/by-id\/wwn-0x6000c2982d69878ee6eba31f9da6c37e-part1",
                "format": "xfs",
                "path": "\/var\/mnt\/test"
            }
        ],
        "files": [
            {
                "path": "\/etc\/systemd\/network\/10-net0.link",
                "contents": {
                    "source": "data:text\/plain;base64,W01hdGNoXQpNQUNBZGRyZXNzPTAyOmFhOjIwOmZiOjc1OjMwCltMaW5rXQpOYW1lPW5ldDAK"
                }
            },
            {
                "path": "\/etc\/NetworkManager\/system-connections\/net0.nmconnection",
                "mode": 384,
                "contents": {
                    "source": "data:text\/plain;base64,W2Nvbm5lY3Rpb25dCmlkPW5ldDAKdHlwZT1ldGhlcm5ldAppbnRlcmZhY2UtbmFtZT1uZXQwCgpbaXB2NF0KYWRkcmVzczE9CmRucz0KbWF5LWZhaWw9ZmFsc2UKbWV0aG9kPWF1dG8K"
                }
            }
        ]
    },
    "systemd": {
        "units": [
            {
                "name": "var.mount",
                "enabled": true,
                "contents": "[Mount]\nWhat=\/dev\/disk\/by-id\/dm-name-var\nWhere=\/var\n\n[Install]\nWantedBy=local-fs.target\n"
            },
            {
                "name": "var-mnt-test.mount",
                "enabled": true,
                "contents": "[Mount]\nWhat=\/dev\/disk\/by-id\/wwn-0x6000c2982d69878ee6eba31f9da6c37e-part1\nWhere=\/var\/mnt\/test\n\n[Install]\nWantedBy=local-fs.target\n"
            }
        ]
    }
}

[arnegroskurth]

Running journalctl -u ignition-disks.service on the emergency shell showed the actual error - mkfs.xfs failed because the disk to be formatted was less than 300MB in size. Seems like a lower limit has been introduced for xfs in one of the last releases.

I'm not sure if this is a problem with ignition but any hint about why that message did not occur within VM logs?

[cgwalters]

A few links on this from #1583

[arnegroskurth]

I'm closing this as the actual error could be explained with limitations of an external component.

However, there might still room for improvement here to make such errors more visible.