Closed cgruver closed 1 year ago
praveenkumar
commented
2 years ago @cgruver Do you have any workload deployed on that cluster when it start failing? We don't have M2 machine in the team but have M1 so we can try to reproduce it if you let us know the steps when it happen.
cgruver
commented
2 years ago No workloads are deployed. It generally happens pretty quickly. The first symptom seems to be that the node stops accepting SSH connections. The OpenShift instance will continue to run for a while, but then will eventually stop responding as well.
The crc machine has to be deleted after, and a new one created.
I'll try to catch it and upload all of the logs.
cfergeau
commented
2 years ago The crc machine has to be deleted after, and a new one created.
It's quite surprising that the VM can't be force restarted after this start happening :-/ .crc/machines/crc/vfkit.log has the kernel backtrace every time you restart the VM after this started happening?
cgruver
commented
2 years ago OK. Here's one way to reproduce it:
crc delete
crc startAfter it starts:
eval $(crc podman-env)
podman imagesResult:
Cannot connect to Podman. Please verify your connection to the Linux system using `podman system connection list`, or try `podman machine init` and `podman machine start` to manage a new Linux VM
Error: unable to connect to Podman. failed to create sshClient: Connection to bastion host (ssh://core@127.0.0.1:2222/run/user/1000/podman/podman.sock) failed.: ssh: handshake failed: EOFvfkit.log
[ 760.952531] hrtimer: interrupt took 117543762 ns
[ 784.851140] BUG: Bad rss-counter state mm:000000001dca0567 type:MM_FILEPAGES val:27
[ 784.864870] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart.
[ 784.865004] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 2.
[ 784.865166] systemd[1]: systemd-journal-flush.service: Succeeded.
[ 784.865743] systemd[1]: Stopped Flush Journal to Persistent Storage.
[ 784.865814] systemd[1]: systemd-journal-flush.service: Consumed 0 CPU time
[ 784.865856] systemd[1]: Stopping Flush Journal to Persistent Storage...
[ 784.865908] systemd[1]: Stopped Journal Service.
[ 784.865961] systemd[1]: systemd-journald.service: Consumed 871ms CPU time
[ 784.867556] systemd[1]: Starting Journal Service...
[ 784.917405] systemd[1]: sssd.service: Main process exited, code=killed, status=11/SEGV
[ 784.960932] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000008
[ 784.961032] Mem abort info:
[ 784.961080] ESR = 0x96000047
[ 784.961119] EC = 0x25: DABT (current EL), IL = 32 bits
[ 784.961169] SET = 0, FnV = 0
[ 784.961253] EA = 0, S1PTW = 0
[ 784.961277] FSC = 0x07: level 3 translation fault
[ 784.961322] Data abort info:
[ 784.961350] ISV = 0, ISS = 0x00000047
[ 784.961376] CM = 0, WnR = 1
[ 784.961408] user pgtable: 4k pages, 48-bit VAs, pgdp=000000037cc4b000
[ 784.961450] [0000000000000008] pgd=08000004370d3003, p4d=08000004370d3003, pud=080000034682d003, pmd=08000003463a9003, pte=0000000000000000
[ 784.961536] Internal error: Oops: 96000047 [#1] SMP
[ 784.961584] Modules linked in: xt_statistic nf_conntrack_netlink veth xt_nat xt_addrtype ipt_REJECT nf_reject_ipv4 xt_CT xt_MASQUERADE xt_conntrack xt_comment nft_counter xt_mark nft_compat nft_chain_nat nf_tables tun overlay dummy rfkill vxlan ip6_udp_tunnel udp_tunnel nfnetlink_cttimeout nfnetlink openvswitch nf_conncount nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ext4 mbcache jbd2 vmw_vsock_virtio_transport vmw_vsock_virtio_transport_common vsock ip_tables xfs libcrc32c crct10dif_ce ghash_ce sha2_ce virtio_console virtiofs sha256_arm64 virtio_blk sha1_ce dm_multipath dm_mirror dm_region_hash dm_log dm_mod be2iscsi cxgb4i cxgb4 tls libcxgbi libcxgb qla4xxx iscsi_boot_sysfs iscsi_tcp libiscsi_tcp libiscsi ipmi_devintf ipmi_msghandler scsi_transport_iscsi fuse
[ 784.962015] CPU: 0 PID: 39737 Comm: kworker/0:0 Not tainted 5.14.0-70.22.1.el9_0.aarch64 #1
[ 784.962070] Workqueue: cgroup_destroy css_killed_work_fn
[ 784.962141] pstate: a04000c5 (NzCv daIF +PAN -UAO -TCO BTYPE=--)
[ 784.962189] pc : memcg_drain_all_list_lrus+0x114/0x2f0
[ 784.962239] lr : memcg_drain_all_list_lrus+0x34/0x2f0
[ 784.962278] sp : ffff800013213c60
[ 784.962309] x29: ffff800013213c60 x28: 0000000000000001 x27: ffff0000ce8ff000
[ 784.962363] x26: ffff0000c8361480 x25: 0000000000000000 x24: ffff00022c104000
[ 784.962419] x23: ffff800011920b20 x22: ffff800011d36cb8 x21: 0000000000000000
[ 784.962474] x20: ffff0000d313e980 x19: ffff0000cf07ba00 x18: 0000000000000000
[ 784.962527] x17: 0000000000000000 x16: 0000000000000000 x15: 0000000000000000
[ 784.962581] x14: 0000000000000000 x13: 0000000000000030 x12: 0101010101010101
[ 784.962635] x11: 7f7f7f7f7f7f7f7f x10: feff786e71737264 x9 : ffff800010b8f1c4
[ 784.962689] x8 : fefefefefefefeff x7 : 000000000000000f x6 : ffff000380982474
[ 784.962746] x5 : 0000000000000000 x4 : 0000000000000000 x3 : 0000000000000000
[ 784.962801] x2 : ffff0000cf07b700 x1 : 0000000000000000 x0 : ffff0000cf07b700
[ 784.962855] Call trace:
[ 784.962871] memcg_drain_all_list_lrus+0x114/0x2f0
[ 784.962911] memcg_offline_kmem.part.0+0x150/0x180
[ 784.962958] mem_cgroup_css_offline+0xe0/0x130
[ 784.962998] css_killed_work_fn+0x5c/0x160
[ 784.963024] process_one_work+0x1ec/0x4b0
[ 784.963067] worker_thread+0x180/0x540
[ 784.963088] kthread+0x134/0x140
[ 784.963119] ret_from_fork+0x10/0x18
[ 784.963144] Code: eb00029f 54000120 a9400684 f9400040 (f9000482)
[ 784.963202] ---[ end trace 6007b8688c9089cf ]---
[ 784.963241] Kernel panic - not syncing: Oops: Fatal exception
[ 784.963285] SMP: stopping secondary CPUs
[ 784.963380] Kernel Offset: disabled
[ 784.963504] CPU features: 0x00000141,4b307ec0
[ 784.963558] Memory Limit: none
[ 784.963611] Rebooting in 10 seconds..
[ 1.592873] systemd-udevd[504]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.
[ 1.596194] vda: vda1 vda2 vda3 vda4
[ 1.619846] s[ OK ] Found device /dev/disk/by-uuid/38cffd8d-7f77-4d00-a96a-fd020e8d2af9.ystemd[1]: Found
device /dev/disk/by-uuid/38cffd8d-7f77-4d00-a96a-fd020e8d2af9.
[ OK ] Found device /dev/disk/by-label/root.[ 1.620044] s
ystemd[1]: Found device /dev/disk/by-label/root.
[ OK ] Reached target Initrd Root Device.[ 1.620162] s
ystemd[1]: Reached target Initrd Root Device.
[ OK ] Started udev Wait for Complete Device Initialization.[ 1.659792] s
ystemd[1]: Started udev Wait for Complete Device Initialization.
Starting Device-Mapper Multipath Device Controller...
[ 1.660250] systemd[1]: Starting Device-Mapper Multipath Device Controller...
[ OK ] Started Device-Mapper Multipath Device Controller.
[ 1.668707] systemd[1]: Started Device-Mapper Multipath Device Controller.
[ 1.669977] systemd[1]: Starting Open-iSCSI...
Starting Open-iSCSI...
[ 1.670128] systemd[1]: Reached target Local File Systems (Pre).
[ OK ] Reached target Local File Systems (Pre).
[ 1.670299] systemd[1]: Reached target Local File Systems.
[ OK ] Reached target Local File Systems.
[ 1.670615] systemd[1]: Starting Create Volatile Files and Directories...
Starting Create Volatile Files and Directories...
[ 1.691975] multipathd[525]: --------start up--------
[ 1.692532] multipathd[525]: read /etc/multipath.conf
[ 1.692647] multipathd[525]: /etc/multipath.conf does not exist, blacklisting all devices.
[ 1.695088] multipathd[525]: You can run "/sbin/mpathconf --enable" to create
[ 1.695196] multipathd[525]: /etc/multipath.conf. See man mpathconf(8) for more details
[ 1.695296] multipathd[525]: /etc/multipath.conf does not exist, blacklisting all devices.
[ 1.695392] multipathd[525]: You can run "/sbin/mpathconf --enable" to create
[ 1.695495] multipathd[525]: /etc/multipath.conf. See man mpathconf(8) for more details
[ 1.695588] multipathd[525]: path checkers start up
[ 1.710128] iscsid[526]: iscsid: can't open InitiatorName configuration file /etc/iscsi/initiatorname.iscsi
[ 1.710278] iscsid[526]: iscsid: Warning: InitiatorName file /etc/iscsi/initiatorname.iscsi does not exist or does not contain a properly formatted InitiatorName. If using software iscsi (iscsi_tcp or ib_iser) or partial offload (bnx2i or cxgbi iscsi), you may not be able to log into or discover targets. Please create a file /etc/iscsi/initiatorname.iscsi that contains a sting with the format: InitiatorName=iqn.yyyy-mm.<reversed domain name>[:identifier].
[ 1.710648] iscsid[526]: Example: InitiatorName=iqn.2001-04.com.redhat:fc6.
[ 1.710726] iscsid[526]: If using hardware iscsi like qla4xxx this message can be ignored.
[ 1.710798] iscsid[526]: iscsid: can't open InitiatorAlias configuration file /etc/iscsi/initiatorname.iscsi
[ OK ] Started Open-iSCSI.[ 1.711000] s
ystemd[1]: Started Open-iSCSI.
[ OK ] Started Create Volatile Files and Directories.[ 1.715659] s
ystemd[1]: Started Create Volatile Files and Directories.
[ 1.715790] systemd[1]: Reached target System Initialization.
[ OK ] Reached target System Initialization.
[ OK ] Reached target Basic System.[ 1.715926] s
ystemd[1]: Reached target Basic System.
Starting dracut initqueue hook...
[ 1.716276] systemd[1]: Starting dracut initqueue hook...
[ OK ] Started dracut initqueue hook.
[ 1.724320] systemd[1]: Started dracut initqueue hook.
[ 1.724587] systemd[1]: Starting dracut pre-mount hook...
Starting dracut pre-mount hook...
[ 1.725944] systemd[1]: Reached target Remote File Systems (Pre).
[ OK ] Reached target Remote File Systems (Pre).
[ 1.726082] systemd[1]: Reached target Remote File Systems.
[ OK ] Reached target Remote File Systems.
[ OK ] Started dracut pre-mount hook.
Starting File System Check on /dev/…d8d-7f77-4d00-a96a-fd020e8d2af9...
[ 1.744575] systemd[1]: Started dracut pre-mount hook.
[ 1.744713] systemd[1]: Starting File System Check on /dev/disk/by-uuid/38cffd8d-7f77-4d00-a96a-fd020e8d2af9...
[ 1.768296] systemd-fsck[552]: /usr/sbin/fsck.xfs: XFS file system.
[ 1.768857] s[ OK ] Started File System Check on /dev/d…ffd8d-7f77-4d00-a96a-fd020e8d2af9.ystemd[1]: Start
ed File System Check on /dev/disk/by-uuid/38cffd8d-7f77-4d00-a96a-fd020e8d2af9.
Mounting /sysroot...
[ 1.769245] systemd[1]: Mounting /sysroot...
[ 1.820665] SGI XFS with ACLs, security attributes, scrub, quota, no debug enabled
[ 1.822432] XFS (vda4): Mounting V5 Filesystem
[ 1.833234] XFS (vda4): Starting recovery (logdev: internal)
[ 1.872362] XFS (vda4): Ending recovery (logdev: internal)
[ 1.947840] xfs filesystem being mounted at /sysroot supports timestamps until 2038 (0x7fffffff)
[ 1.948224] s[ OK ] Mounted /sysroot.ystemd[1]: Mount
ed /sysroot.
Starting OSTree Prepare OS/...[ 1.948689] s
ystemd[1]: Starting OSTree Prepare OS/...
[ 1.969390] ostree-prepare-root[569]: preparing sysroot at /sysroot
[ 1.969842] ostree-prepare-root[569]: ostree-prepare-root: Couldn't find specified OSTree root '/sysroot//ostree/boot.0/rhcos/af091a0e76dc85593f8f5deeedce37851a992f53c8764aacac65b9e0f4dbffa9/0': No such file or directory
[ 1.962801] ostree-prepare-root[569]: ostree-prepare-root: Couldn't find specified OSTree root '/sysroot//ostree/boot.0/rhcos/af091a0e76dc85593f8f5deeedce37851a992f53c8764aacac65b9e0f4dbffa9/0': No such file or directory
[ 1.970091] systemd[1]: ostree-prepare-root.service: Main process exited, code=exited, status=1/FAILURE
[ 1.970201] systemd[1]: ostree-prepare-root.service: Failed with result 'exit-code'.
[FAILED] Failed to start OSTree Prepare OS/.
[ 1.970386] systemd[1]: Failed to start OSTree Prepare OS/.
See 'systemctl status ostree-prepare-root.service' for details.
[ 1.970609] systemd[1]: ostree-prepare-root.service: Triggering OnFailure= dependencies.
[ 1.970722] systemd[1]: Stopped target Subsequent (Not Ignition) boot complete.
[ OK ] Stopped target Subsequent (Not Ignition) boot complete.
[ OK ] Stopped target Ignition Subsequent Boot Disk Setup.[ 1.970895] s
ystemd[1]: Stopped target Ignition Subsequent Boot Disk Setup.
[ 1.971016] systemd[1]: Stopp[ OK ] Stopped target Basic System.ed target Basic
System.
[ OK ] Stopped target System Initialization.[ 1.971178] s
ystemd[1]: Stopped target System Initialization.
[ 1.971300] systemd[1]: dracut-pre-mount.service: Succeeded.
[ 1.971413] systemd[1]: Stopped dracut pre-mount hook.
[ OK ] Stopped dracut pre-mount hook.
[ 1.971617] systemd[1]: dracut-initqueue.service: Succeeded.
[ OK ] Stopped dracut initqueue hook.[ 1.971717] s
ystemd[1]: Stopped dracut initqueue hook.
[ 1.971818] systemd[1]: dracut-pre-trigger.service: Succeeded.
[ 1.973107] systemd[1]: Stopped dracut pre-trigger hook.
[ OK ] Stopped dracut pre-trigger hook.
[ 1.973300] systemd[1]: dracut-pre-udev.service: Succeeded.
[ OK ] Stopped dracut pre-udev hook.
[ 1.973435] systemd[1]: Stopped dracut pre-udev hook.
[ 1.973517] systemd[1]: dracut-cmdline.service: Succeeded.
[ 1.973606] s[ OK ] Stopped dracut cmdline hook.ystemd[1]: Stopp
ed dracut cmdline hook.
[ 1.973760] systemd[1]: dracut-cmdline-ask.service: Succeeded.
[ 1.973857] systemd[1]: Stopped dracut ask for additional cmdline parameters.
[ OK ] Stopped dracut ask for additional cmdline parameters.
[ 1.974237] systemd[1]: Starting Setup Virtual Console...
Starting Setup Virtual Console...
[ 1.974348] systemd[1]: Reached target Initrd Root File System.
[ OK ] Reached target Initrd Root File System.
[ 1.974633] systemd[1]: Starting Reload Configuration from the Real Root...
Starting Reload Configuration from the Real Root...
[ 2.003866] systemd[1]: Reloading.
[ 2.161371] systemd[1]: systemd-vconsole-setup.service: Succeeded.
[ 2.161492] s[ OK ] Started Setup Virtual Console.ystemd[1]: Start
ed Setup Virtual Console.
[ 2.162395] systemd[1]: Started Emergency Shell.
[ OK ] Started Emergency Shell.
[ 2.162554] systemd[1]: Reached target Emergency Mode.
[ OK ] Reached target Emergency Mode.
[ 2.220108] multipathd[525]: exit (signal)
Stopping Device-Mapper Multipath Device Controller...[ 2.220267] s
ystemd[1]: Stopping Device-Mapper Multipath Device Controller...
[ 2.220438] multipathd[525]: --------shut down-------
[ 2.221003] systemd[1]: initrd-parse-etc.service: Succeeded.
[ OK ] Started Reload Configuration from the Real Root.[ 2.221105] s
ystemd[1]: Started Reload Configuration from the Real Root.
[ OK ] Reached target Initrd File Systems.[ 2.221238] s
ystemd[1]: Reached target Initrd File Systems.
[ 2.221775] systemd[1]: multipathd.service: Succeeded.
[ 2.221911] systemd[1]: Stopped Device-Mapper Multipath Device Controller.
[ OK ] Stopped Device-Mapper Multipath Device Controller.
[ 2.222336] systemd[1]: Starting Cleaning Up and Shutting Down Daemons...
Starting Cleaning Up and Shutting Down Daemons...
Stopping udev Kernel Device Manager...[ 2.251422] s
ystemd[1]: Stopping udev Kernel Device Manager...
[ 2.251575] s[ OK ] Stopped target Initrd Root Device.ystemd[1]: Stopp
ed target Initrd Root Device.
[ 2.251732] systemd[1]: systemd-udev-settle.service: Succeeded.
[ OK ] Stopped udev Wait for Complete Device Initialization.[ 2.251823] s
ystemd[1]: Stopped udev Wait for Complete Device Initialization.
[ 2.251957] s[ OK ] Stopped target Paths.ystemd[1]: Stopp
ed target Paths.
[ 2.252083] s[ OK ] Stopped target Timers.ystemd[1]: Stopp
ed target Timers.
[ 2.252175] s[ OK ] Stopped target Local Encrypted Volumes.ystemd[1]: Stopp
ed target Local Encrypted Volumes.
[ OK ] Stopped Dispatch Password Requests to Console Directory Watch.[ 2.252309] s
ystemd[1]: systemd-ask-password-console.path: Succeeded.
[ 2.252424] s[ OK ] Stopped target Remote File Systems.ystemd[1]: Stopp
ed Dispatch Password Requests to Console Directory Watch.
[ 2.252505] systemd[1]: Stopped target Remote File Systems.
Starting OSTree Prepare OS/...[ 2.252729] s
ystemd[1]: Starting OSTree Prepare OS/...
[ 2.252847] systemd[1]: systemd-sysctl.service: Succeeded.
[ OK ] Stopped Apply Kernel Variables.[ 2.252959] s
ystemd[1]: Stopped Apply Kernel Variables.
[ 2.253949] systemd[1]: systemd-modules-load.service: Succeeded.
[ 2.254067] s[ OK ] Stopped Load Kernel Modules.ystemd[1]: Stopp
ed Load Kernel Modules.
[ 2.254187] systemd[1]: clevis-luks-askpass.path: Succeeded.
[ 2.254195] systemd[1]: Stopped Forward Password Requests to Clevis Directory Watch.
[ OK ] Stopped Forward Password Requests to Clevis Directory Watch.
[ 2.254436] systemd[1]: coreos-touch-run-agetty.service: Succeeded.
[ OK ] Stopped CoreOS: Touch /run/agetty.reload.[ 2.254520] s
ystemd[1]: Stopped CoreOS: Touch /run/agetty.reload.
[ 2.254632] s[ OK ] Stopped target Remote File Systems (Pre).ystemd[1]: Stopp
ed target Remote File Systems (Pre).
Stopping Open-iSCSI...[ 2.254738] s
ystemd[1]: Stopping Open-iSCSI...
[ 2.254840] s[ OK ] Stopped target Slices.ystemd[1]: Stopp
ed target Slices.
[ 2.254989] systemd[1]: systemd-udev-trigger.service: Succeeded.
[ 2.255124] systemd[1]: Stopped udev Coldplug all Devices.
[ 2.255182] iscsid[526]: iscs[ OK ] Stopped udev Coldplug all Devices.id shutting down
.
[ 2.255954] systemd[1]: Stopped target Emergency Mode.
[ OK ] Stopped target Emergency Mode.
Stopping Emergency Shell...
[ 2.256245] systemd[1]: Stopping Emergency Shell...
[ 2.256312] s[ OK ] Stopped target Swap.ystemd[1]: Stopp
ed target Swap.
[ 2.256430] systemd[1]: Stopped target Sockets.
[ OK ] Stopped target Sockets.
[ 2.256614] systemd[1]: systemd-tmpfiles-setup.service: Succeeded.
[ OK ] Stopped Create Volatile Files and Directories.
[ 2.256749] systemd[1]: Stopped Create Volatile Files and Directories.
[ 2.256843] s[ OK ] Stopped target Local File Systems.ystemd[1]: Stopp
ed target Local File Systems.
[ OK ] Stopped target Local File Systems (Pre).
[ 2.256998] systemd[1]: Stopped target Local File Systems (Pre).
[ OK ] Stopped Open-iSCSI.
[ 2.257626] systemd[1]: iscsid.service: Succeeded.
[ 2.258452] systemd[1]: Stopped Open-iSCSI.
[ 2.259264] systemd[1]: Stopping iSCSI UserSpace I/O driver...
Stopping iSCSI UserSpace I/O driver...
[ 2.259414] systemd[1]: iscsid.socket: Succeeded.
[ 2.259572] systemd[1]: Closed Open-iSCSI iscsid Socket.
[ OK ] Closed Open-iSCSI iscsid Socket.
[ 2.259727] systemd[1]: iscsiuio.service: Succeeded.
[ 2.259892] systemd[1]: Stopped iSCSI UserSpace I/O driver.
[ OK ] Stopped iSCSI UserSpace I/O driver.
[ 2.260082] systemd[1]: initrd-cleanup.service: Succeeded.
[ 2.260233] systemd[1]: Started Cleaning Up and Shutting Down Daemons.
[ OK ] Started Cleaning Up and Shutting Down Daemons.
[ 2.260624] systemd[1]: iscsiuio.socket: Succeeded.
[ 2.260779] systemd[1]: Closed Open-iSCSI iscsiuio Socket.
[ OK ] Closed Open-iSCSI iscsiuio Socket.
[ 2.268397] systemd[1]: systemd-udevd.service: Succeeded.
[ 2.268651] s[ OK ] Stopped udev Kernel Device Manager.ystemd[1]: Stopped udev Kernel D
evice Manager.
[ 2.268995] systemd[1]: systemd-tmpfiles-setup-dev.service: Succeeded.
[ 2.269257] s[ OK ] Stopped Create Static Device Nodes in /dev.ystemd[1]: Stopped Create Static
Device Nodes in /dev.
[ 2.269489] systemd[1]: kmod-static-nodes.service: Succeeded.
[ 2.269726] s[ OK ] Stopped Create list of required sta…vice nodes for the current kernel.ystemd[1]: Stopped Create list of required stati
c device nodes for the current kernel.
[ 2.269921] systemd[1]: systemd-udevd-control.socket: Succeeded.
[ OK ] Closed udev Control Socket.[ 2.270171] s
ystemd[1]: Closed udev Control Socket.
[ 2.270317] systemd[1]: systemd-udevd-kernel.socket: Succeeded.
[ 2.270542] s[ OK ] Closed udev Kernel Socket.ystemd[1]: Closed udev Kernel Socket.
[ 2.271104] s Starting Cleanup udevd DB...ystemd[1]: Starting Cleanup udevd DB...
[ 2.273094] ostree-prepare-root[654]: preparing sysroot at /sysroot
[ 2.273245] ostree-prepare-root[654]: ostree-prepare-root: Couldn't find specified OSTree root '/sysroot//ostree/boot.0/rhcos/af091a0e76dc85593f8f5deeedce37851a992f53c8764aacac65b9e0f4dbffa9/0': No such file or directory
[ 2.266264] ostree-prepare-root[654]: ostree-prepare-root: Couldn't find specified OSTree root '/sysroot//ostree/boot.0/rhcos/af091a0e76dc85593f8f5deeedce37851a992f53c8764aacac65b9e0f4dbffa9/0': No such file or directory
[ 2.273721] systemd[1]: ostree-prepare-root.service: Main process exited, code=exited, status=1/FAILURE
[ 2.273848] systemd[1]: ostree-prepare-root.service: Failed with result 'exit-code'.
[FAILED] Failed to start OSTree Prepare OS/.[ 2.273952] s
ystemd[1]: Failed to start OSTree Prepare OS/.
See 'systemctl status ostree-prepare-root.service' for details.
[ 2.274093] systemd[1]: ostree-prepare-root.service: Triggering OnFailure= dependencies.
Starting Setup Virtual Console...[ 2.274386] s
ystemd[1]: Starting Setup Virtual Console...
[ OK ] Started Cleanup udevd DB.Entry that starts repeating in vfkit.log:
[ 73.457981] s[FAILED] Failed to start OSTree Prepare OS/.ystemd[1]: ostre
e-prepare-root.service: Failed with result 'exit-code'.
See 'systemctl status ostree-prepare-root.service' for details.[ 73.458157] s
ystemd[1]: Failed to start OSTree Prepare OS/.
[ 73.458262] systemd[1]: ostree-prepare-root.service: Triggering OnFailure= dependencies.
[ 73.458375] s[ OK ] Stopped target Subsequent (Not Ignition) boot complete.ystemd[1]: Stopp
ed target Subsequent (Not Ignition) boot complete.
[ 73.458527] s[ OK ] Stopped target Ignition Subsequent Boot Disk Setup.ystemd[1]: Stopp
ed target Ignition Subsequent Boot Disk Setup.
[ 73.458859] s Starting udev Coldplug all Devices...ystemd[1]: Start
ing udev Coldplug all Devices...
[ 73.459128] s Starting Reload Configuration from the Real Root...ystemd[1]: Start
ing Reload Configuration from the Real Root...
[ OK ] Started iSCSI UserSpace I/O driver.[ 73.480924] s
ystemd[1]: Started iSCSI UserSpace I/O driver.
[ OK ] Started Create Static Device Nodes in /dev.[ 73.507398] s
ystemd[1]: Started Create Static Device Nodes in /dev.
[ 73.507846] s Starting udev Kernel Device Manager...ystemd[1]: Starting udev Kernel Device Manager...
[ 73.517406] s[ OK ] Started Load Kernel Modules.ystemd[1]: Started Load Kernel Modules.
[ 73.517669] systemd[1]: systemd-vconsole-setup.service: Succeeded.
[ 73.517814] s[ OK ] Started Setup Virtual Console.ystemd[1]: Started Setup Virtual Console.
[ OK ] Started Emergency Shell.
[ OK ] Reached target Emergency Mode.
[ 73.518395] systemd[1]: Started Emergency Shell.
[ 73.518463] systemd[1]: Reached target Emergency Mode.
[ 73.518647] s Starting Apply Kernel Variables...ystemd[1]: Starting Apply Kernel Variables...
[ 73.530146] systemd[1]: Reloading.
[ OK ] Started udev Kernel Device Manager.[ 73.676467] s
ystemd[1]: Started udev Kernel Device Manager.
[ OK ] Started Apply Kernel Variables.[ 73.677085] s
ystemd[1]: Started Apply Kernel Variables.
[ 73.721303] systemd[1]: Started udev Coldplug all Devices.
[ OK ] Started udev Coldplug all Devices.
[ 73.721755] systemd[1]: Starting udev Wait for Complete Device Initialization...
Starting udev Wait for Complete Device Initialization...
[ 73.737282] systemd[1]: initrd-parse-etc.service: Succeeded.
[ OK ] Started Reload Configuration from the Real Root.[ 73.737383] s
ystemd[1]: Started Reload Configuration from the Real Root.
Starting Cleaning Up and Shutting Down Daemons...[ 73.737778] s
ystemd[1]: Starting Cleaning Up and Shutting Down Daemons...
[ 73.741240] systemd-udevd[2657]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.
[ OK ] Stopped target Sockets.[ 73.769879] s
ystemd[1]: Stopped target Sockets.
[ 73.769990] systemd[1]: coreos-touch-run-agetty.service: Succeeded.
[ OK ] Stopped CoreOS: Touch /run/agetty.reload.[ 73.770109] s
ystemd[1]: Stopped CoreOS: Touch /run/agetty.reload.
[ 73.770246] systemd[1]: systemd-sysctl.service: Succeeded.
[ OK ] Stopped Apply Kernel Variables.[ 73.770341] s
ystemd[1]: Stopped Apply Kernel Variables.
[ 73.770404] s[ OK ] Stopped target Local Encrypted Volumes.ystemd[1]: Stopp
ed target Local Encrypted Volumes.
[ 73.770524] systemd[1]: clevis-luks-askpass.path: Succeeded.
[ OK ] Stopped Forward Password Requests to Clevis Directory Watch.[ 73.789435] s
ystemd[1]: Stopped Forward Password Requests to Clevis Directory Watch.
[ 73.789637] s[ OK ] Stopped target Swap.ystemd[1]: Stopp
ed target Swap.
Starting OSTree Prepare OS/...
[ OK ] Stopped target Timers.
[ OK ] Stopped Load Kernel Modules.
[ OK ] Stopped target Emergency Mode.[ 73.790355] s
ystemd[1]: Starting OSTree Prepare OS/...
[ 73.790457] systemd[1]: Stopped target Timers.
Stopping Emergency Shell...
[ OK ] Stopped target Initrd Root Device.[ 73.790658] s
ystemd[1]: systemd-modules-load.service: Succeeded.
[ OK ] Stopped target Slices.[ 73.790794] s
ystemd[1]: Stopped Load Kernel Modules.
[ 73.790892] s[ OK ] Stopped target Paths.ystemd[1]: Stopp
ed target Emergency Mode.
[ 73.791004] systemd[1]: Stopping Emergency Shell...
[ 73.791057] systemd[1]: Stopped target Initrd Root Device.
[ 73.791103] systemd[1]: Stopped target Slices.
[ 73.791151] systemd[1]: Stopped target Paths.
[ 73.791194] systemd[1]: systemd-ask-password-console.path: Succeeded.
[ 73.809961] ostree-prepare-root[2673]: preparing sysroot at /sysroot
[ 73.810021] ostree-prepare-root[2673]: ostree-prepare-root: Couldn't find specified OSTree root '/sysroot//ostree/boot.0/rhcos/af091a0e76dc85593f8f5deeedce37851a992f53c8764aacac65b9e0f4dbffa9/0': No such file or directory
[ 73.802906] ostree-prepare-root[2673]: ostree-prepare-root: Couldn't find specified OSTree root '/sysroot//ostree/boot.0/rhcos/af091a0e76dc85593f8f5deeedce37851a992f53c8764aacac65b9e0f4dbffa9/0': No such file or directory
[ OK ] Stopped Dispatch Password Requests to Console Directory Watch.[ 73.829330] s
ystemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.
[ 73.829519] systemd[1]: Stopping iSCSI UserSpace I/O driver...
Stopping iSCSI UserSpace I/O driver...
[ OK ] Closed Open-iSCSI iscsid Socket.
Stopping udev Kernel Device Manager...
[ OK ] Stopped iSCSI UserSpace I/O driver.
[ 73.830784] systemd[1]: iscsid.socket: Succeeded.
[ 73.830873] systemd[1]: Closed Open-iSCSI iscsid Socket.
[ 73.830944] systemd[1]: Stopping udev Kernel Device Manager...
[ 73.831021] systemd[1]: iscsiuio.service: Succeeded.
[ 73.831031] systemd[1]: Stopped iSCSI UserSpace I/O driver.
[ 73.831039] systemd[1]: systemd-udev-settle.service: Succeeded.
[ 73.831047] systemd[1]: Stopped udev Wait for Complete Device Initialization.
[ OK ] Stopped udev Wait for Complete Device Initialization.
[ 73.831415] systemd[1]: ostree-prepare-root.service: Main process exited, code=exited, status=1/FAILURE
[FAILED] Failed to start OSTree Prepare OS/.[ 73.831543] s
ystemd[1]: ostree-prepare-root.service: Failed with result 'exit-code'.If you attempt to restart crc after the above failure. The same ostree errors as above repeat in vfkit.log. The cluster cannot restart and must be deleted.
cfergeau
commented
2 years ago If you attempt to restart crc after the above failure. The same ostree errors as above repeat in vfkit.log. The cluster cannot restart and must be deleted.
Ah this one is a different issue, the first time the cluster stops/starts must be a clean shutdown or it won't be able to restart. If you manage to do crc start; crc stop; crc start before reproducing, the subsequent restarts should be fine.
cgruver
commented
2 years ago The above method for reproducing the issue does not always work. Sometimes the cluster will run for a while before it quits accepting SSH. After it quits accepting SSH, OpenShift will still run for a while too. Then suddenly stop.
I'll keep playing with it and upload any interesting logs.
cgruver
commented
2 years ago Here's a vfkit.log snippet that might have something useful.
I started crc and let it idle for a few minutes.
[ 630.615006] ------------[ cut here ]------------
[ 630.615078] kernel BUG at security/selinux/ss/services.c:436!
[ 630.615173] Internal error: Oops - BUG: 0 [#1] SMP
[ 630.615280] Modules linked in: xt_statistic veth nf_conntrack_netlink xt_nat xt_addrtype ipt_REJECT nf_reject_ipv4 xt_CT xt_MASQUERADE xt_conntrack xt_comment nft_counter xt_mark nft_compat tun nft_chain_nat nf_tables overlay dummy rfkill vxlan ip6_udp_tunnel udp_tunnel nfnetlink_cttimeout nfnetlink openvswitch nf_conncount nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ext4 mbcache jbd2 vmw_vsock_virtio_transport vmw_vsock_virtio_transport_common vsock ip_tables xfs libcrc32c crct10dif_ce ghash_ce sha2_ce sha256_arm64 sha1_ce virtio_console virtio_blk virtiofs dm_multipath dm_mirror dm_region_hash dm_log dm_mod be2iscsi cxgb4i cxgb4 tls libcxgbi libcxgb qla4xxx iscsi_boot_sysfs iscsi_tcp libiscsi_tcp libiscsi ipmi_devintf ipmi_msghandler fuse scsi_transport_iscsi
[ 630.615749] CPU: 1 PID: 30020 Comm: kworker/u8:3 Not tainted 5.14.0-70.22.1.el9_0.aarch64 #1
[ 630.615839] pstate: 80400005 (Nzcv daif +PAN -UAO -TCO BTYPE=--)
[ 630.615882] pc : constraint_expr_eval+0x524/0x544
[ 630.615951] lr : constraint_expr_eval+0x328/0x544
[ 630.615981] sp : ffff80001ec1b7d0
[ 630.616019] x29: ffff80001ec1b7d0 x28: ffff0000c7940b28 x27: ffff80001ec1b854
[ 630.616069] x26: ffff0000c0c68078 x25: ffff0000c7940b28 x24: ffff0000d36fc008
[ 630.616124] x23: 0000000000000000 x22: ffff0000c0c68068 x21: ffff0000c7940b00
[ 630.616166] x20: 0000000000000001 x19: ffff0000cef7f280 x18: 0000000000000000
[ 630.616231] x17: 0000000000000000 x16: 0000000000000000 x15: ffff0001c87e8400
[ 630.616288] x14: 0000000000000000 x13: 706d756465726f63 x12: ffff0000c9240000
[ 630.616342] x11: 00000000e6546b64 x10: 0000000085ebca6b x9 : ffff800010487888
[ 630.616383] x8 : 000000000000003f x7 : 0000000000000000 x6 : 0000000000000000
[ 630.616424] x5 : 0000000000000000 x4 : 0000000000000000 x3 : 0000000000000015
[ 630.616460] x2 : 0000000000000000 x1 : 0000000000000015 x0 : 0000000000000001
[ 630.616496] Call trace:
[ 630.616518] constraint_expr_eval+0x524/0x544
[ 630.616550] context_struct_compute_av+0x300/0x4b0
[ 630.616575] security_compute_av+0x120/0x2e0
[ 630.616614] avc_compute_av.isra.0+0x48/0x80
[ 630.616667] avc_has_perm_noaudit+0xdc/0x120
[ 630.616695] selinux_inode_permission+0x144/0x280
[ 630.616723] security_inode_permission+0x48/0x80
[ 630.616755] inode_permission+0x74/0x1d4
[ 630.616789] may_open+0x74/0x16c
[ 630.616816] do_open+0x98/0x3c0
[ 630.616837] path_openat+0x10c/0x280
[ 630.616855] do_filp_open+0x84/0x130
[ 630.616873] do_open_execat+0x6c/0x1c4
[ 630.616890] bprm_execve.part.0+0x108/0x254
[ 630.616925] bprm_execve+0x60/0x90
[ 630.616942] kernel_execve+0x128/0x1a0
[ 630.616961] call_usermodehelper_exec_async+0x134/0x1f4
[ 630.617019] ret_from_fork+0x10/0x18
[ 630.617048] Code: 17fffed9 52800000 17fffeef d4210000 (d4210000)
[ 630.617091] ---[ end trace 7ae02c2db764cae8 ]---
[ 630.617118] Kernel panic - not syncing: Oops - BUG: Fatal exception
[ 630.617143] SMP: stopping secondary CPUs
[ 630.617180] Kernel Offset: disabled
[ 630.617429] CPU features: 0x00000141,4b307ec0
[ 630.617466] Memory Limit: none
[ 630.617487] Rebooting in 10 seconds..
[ 1.482083] vda: vda1 vda2 vda3 vda4
[ 1.500886] s[ OK ] Found device /dev/disk/by-uuid/38cffd8d-7f77-4d00-a96a-fd020e8d2af9.ystemd[1]: Found
device /dev/disk/by-uuid/38cffd8d-7f77-4d00-a96a-fd020e8d2af9.
[ OK ] Found device /dev/disk/by-label/root.[ 1.501003] s
ystemd[1]: Found device /dev/disk/by-label/root.
[ 1.501088] s[ OK ] Reached target Initrd Root Device.ystemd[1]: Reach
ed target Initrd Root Device.
[ OK ] Started udev Wait for Complete Device Initialization.[ 1.528567] s
ystemd[1]: Started udev Wait for Complete Device Initialization.
Starting Device-Mapper Multipath Device Controller...[ 1.528968] s
ystemd[1]: Starting Device-Mapper Multipath Device Controller...
[ 1.537420] systemd[1]: Started Device-Mapper Multipath Device Controller.
[ OK ] Started Device-Mapper Multipath Device Controller.
[ 1.537714] systemd[1]: Reached target Local File Systems (Pre).
[ OK ] Reached target Local File Systems (Pre).
[ 1.537903] systemd[1]: Reached target Local File Systems.
[ OK ] Reached target Local File Systems.
[ 1.538270] systemd[1]: Starting Create Volatile Files and Directories...
Starting Create Volatile Files and Directories...
[ 1.538709] systemd[1]: Starting Open-iSCSI...
Starting Open-iSCSI...
[ 1.559508] multipathd[526]: --------start up--------
[ 1.559666] multipathd[526]: read /etc/multipath.conf
[ 1.559749] multipathd[526]: /etc/multipath.conf does not exist, blacklisting all devices.
[ 1.559837] multipathd[526]: You can run "/sbin/mpathconf --enable" to create
[ 1.559886] multipathd[526]: /etc/multipath.conf. See man mpathconf(8) for more details
[ 1.560400] multipathd[526]: path checkers start up
[ 1.562508] multipathd[526]: /etc/multipath.conf does not exist, blacklisting all devices.
[ 1.562656] multipathd[526]: You can run "/sbin/mpathconf --enable" to create
[ 1.562758] multipathd[526]: /etc/multipath.conf. See man mpathconf(8) for more details
[ 1.577219] iscsid[528]: iscsid: can't open InitiatorName configuration file /etc/iscsi/initiatorname.iscsi
[ 1.577296] iscsid[528]: iscsid: Warning: InitiatorName file /etc/iscsi/initiatorname.iscsi does not exist or does not contain a properly formatted InitiatorName. If using software iscsi (iscsi_tcp or ib_iser) or partial offload (bnx2i or cxgbi iscsi), you may not be able to log into or discover targets. Please create a file /etc/iscsi/initiatorname.iscsi that contains a sting with the format: InitiatorName=iqn.yyyy-mm.<reversed domain name>[:identifier].
[ 1.577502] iscsid[528]: Example: InitiatorName=iqn.2001-04.com.redhat:fc6.
[ 1.577538] iscsid[528]: If using hardware iscsi like qla4xxx this message can be ignored.
[ 1.577582] iscsid[528]: iscsid: can't open InitiatorAlias configuration file /etc/iscsi/initiatorname.iscsi
[ OK ] Started Create Volatile Files and Directories.[ 1.578326] s
ystemd[1]: Started Create Volatile Files and Directories.
[ OK ] Started Open-iSCSI.[ 1.578496] s
ystemd[1]: Started Open-iSCSI.
[ OK ] Reached target System Initialization.[ 1.578600] s
ystemd[1]: Reached target System Initialization.
[ 1.578724] s[ OK ] Reached target Basic System.ystemd[1]: Reach
ed target Basic System.
Starting dracut initqueue hook...[ 1.579059] s
ystemd[1]: Starting dracut initqueue hook...
[ OK ] Started dracut initqueue hook.[ 1.586942] s
ystemd[1]: Started dracut initqueue hook.
Starting dracut pre-mount hook...
[ OK ] Reached target Remote File Systems (Pre).
[ OK ] Reached target Remote File Systems.
[ 1.587588] systemd[1]: Starting dracut pre-mount hook...
[ 1.587685] systemd[1]: Reached target Remote File Systems (Pre).
[ 1.587787] systemd[1]: Reached target Remote File Systems.
[ OK ] Started dracut pre-mount hook.
Starting File System Check on /dev/…d8d-7f77-4d00-a96a-fd020e8d2af9...
[ 1.606093] systemd[1]: Started dracut pre-mount hook.
[ 1.606253] systemd[1]: Starting File System Check on /dev/disk/by-uuid/38cffd8d-7f77-4d00-a96a-fd020e8d2af9...
[ 1.630496] systemd-fsck[554]: /usr/sbin/fsck.xfs: XFS file system.
[ 1.631040] s[ OK ] Started File System Check on /dev/d…ffd8d-7f77-4d00-a96a-fd020e8d2af9.ystemd[1]: Started File System Check on /dev/dis
k/by-uuid/38cffd8d-7f77-4d00-a96a-fd020e8d2af9.
Mounting /sysroot...[ 1.631423] s
ystemd[1]: Mounting /sysroot...
[ 1.681867] SGI XFS with ACLs, security attributes, scrub, quota, no debug enabled
[ 1.683680] XFS (vda4): Mounting V5 Filesystem
[ 1.714357] XFS (vda4): Starting recovery (logdev: internal)
[ 1.779365] XFS (vda4): Ending recovery (logdev: internal)
[ 1.858527] xfs filesystem being mounted at /sysroot supports timestamps until 2038 (0x7fffffff)
[ 1.858936] s[ OK ] Mounted /sysroot.ystemd[1]: Mount
ed /sysroot.
Starting OSTree Prepare OS/...[ 1.860064] s
ystemd[1]: Starting OSTree Prepare OS/...
[ 1.879930] ostree-prepare-root[571]: preparing sysroot at /sysroot
[ 1.881947] ostree-prepare-root[571]: Resolved OSTree target to: /sysroot/ostree/deploy/rhcos/deploy/067aa92645240a53bbe96aa19953f8ba5f75f53f39f6f4afa418597de4d294fc.0
[ 1.882752] ostree-prepare-root[571]: filesystem at /sysroot currently writable: 1
[ 1.882818] ostree-prepare-root[571]: sysroot.readonly configuration value: 1
[ 1.883416] xfs filesystem being remounted at /sysroot/ostree/deploy/rhcos/deploy/067aa92645240a53bbe96aa19953f8ba5f75f53f39f6f4afa418597de4d294fc.0/etc supports timestamps until 2038 (0x7fffffff)
[ 1.883795] xfs filesystem being remounted at /sysroot/ostree/deploy/rhcos/var supports timestamps until 2038 (0x7fffffff)
[ OK ] Started OSTree Prepare OS/.[ 1.884518] s
ystemd[1]: Started OSTree Prepare OS/.
[ OK ] Reached target Initrd Root File System.[ 1.884652] s
ystemd[1]: Reached target Initrd Root File System.
Starting Reload Configuration from the Real Root...
[ 1.885066] systemd[1]: Starting Reload Configuration from the Real Root...
[ 1.912727] systemd[1]: Reloading.
Stopping Device-Mapper Multipath Device Controller...[ 2.118979] s
ystemd[1]: Stopping Device-Mapper Multipath Device Controller...
[ 2.119549] multipathd[526]: exit (signal)
[ 2.119593] multipathd[526]: --------shut down-------
[ 2.119702] systemd[1]: initrd-parse-etc.service: Succeeded.
[ 2.119789] s[ OK ] Started Reload Configuration from the Real Root.ystemd[1]: Start
ed Reload Configuration from the Real Root.
Starting dracut mount hook...[ 2.120159] s
ystemd[1]: Starting dracut mount hook...
[ 2.120253] s[ OK ] Reached target Initrd File Systems.ystemd[1]: Reach
ed target Initrd File Systems.
[ OK ] Reached target Initrd Default Target.[ 2.120351] s
ystemd[1]: Reached target Initrd Default Target.
[ 2.120447] systemd[1]: multipathd.service: Succeeded.
[ OK ] Stopped Device-Mapper Multipath Device Controller.
[ 2.120634] systemd[1]: Stopped Device-Mapper Multipath Device Controller.
[ OK ] Started dracut mount hook.
Starting dracut pre-pivot and cleanup hook...
[ 2.133950] systemd[1]: Started dracut mount hook.
[ 2.134070] systemd[1]: Starting dracut pre-pivot and cleanup hook...
[ 2.246181] dracut-pre-pivot[681]: Sep 19 12:50:49 | /etc/multipath.conf does not exist, blacklisting all devices.
[ 2.240251] dracut-pre-pivot[681]: Sep 19 12:50:49 | /etc/multipath.conf does not exist, blacklisting all devices.
[ 2.246363] dracut-pre-pivot[681]: Sep 19 12:50:49 | You can run "/sbin/mpathconf --enable" to create
[ 2.240399] dracut-pre-pivot[681]: Sep 19 12:50:49 | You can run "/sbin/mpathconf --enable" to create
[ 2.246502] dracut-pre-pivot[681]: Sep 19 12:50:49 | /etc/multipath.conf. See man mpathconf(8) for more details
[ 2.240521] dracut-pre-pivot[681]: Sep 19 12:50:49 | /etc/multipath.conf. See man mpathconf(8) for more details
[ OK ] Started dracut pre-pivot and cleanup hook.[ 2.251751] s
ystemd[1]: Started dracut pre-pivot and cleanup hook.
Starting Cleaning Up and Shutting Down Daemons...[ 2.252119] s
ystemd[1]: Starting Cleaning Up and Shutting Down Daemons...
[ 2.280171] systemd[1]: clevis-luks-askpass.path: Succeeded.
[ OK ] Stopped Forward Password Requests to Clevis Directory Watch.[ 2.280267] s
ystemd[1]: Stopped Forward Password Requests to Clevis Directory Watch.
[ 2.280381] systemd[1]: coreos-touch-run-agetty.service: Succeeded.
[ OK ] Stopped CoreOS: Touch /run/agetty.reload.[ 2.280482] s
ystemd[1]: Stopped CoreOS: Touch /run/agetty.reload.
[ 2.280562] systemd[1]: dracut-pre-pivot.service: Succeeded.
[ OK ] Stopped dracut pre-pivot and cleanup hook.[ 2.280653] s
ystemd[1]: Stopped dracut pre-pivot and cleanup hook.
[ 2.280739] s[ OK ] Stopped target Remote File Systems.ystemd[1]: Stopp
ed target Remote File Systems.
[ 2.280819] s[ OK ] Stopped target Remote File Systems (Pre).ystemd[1]: Stopp
ed target Remote File Systems (Pre).
[ 2.280913] systemd[1]: dracut-mount.service: Succeeded.
[ OK ] Stopped dracut mount hook.[ 2.281015] s
ystemd[1]: Stopped dracut mount hook.
[ 2.281095] systemd[1]: dracut-pre-mount.service: Succeeded.
[ OK ] Stopped dracut pre-mount hook.[ 2.281198] s
ystemd[1]: Stopped dracut pre-mount hook.
[ 2.283182] systemd[1]: dracut-initqueue.service: Succeeded.
[ OK ] Stopped dracut initqueue hook.[ 2.283319] s
ystemd[1]: Stopped dracut initqueue hook.
[ OK ] Stopped target Initrd Default Target.[ 2.283396] s
ystemd[1]: Stopped target Initrd Default Target.
[ 2.283485] s[ OK ] Stopped target Initrd Root Device.ystemd[1]: Stopp
ed target Initrd Root Device.
[ 2.283541] s[ OK ] Stopped target Timers.ystemd[1]: Stopp
ed target Timers.
[ 2.283643] s Stopping Open-iSCSI...ystemd[1]: Stopp
ing Open-iSCSI...
[ 2.283739] s[ OK ] Stopped target Basic System.ystemd[1]: Stopp
ed target Basic System.
[ 2.283831] s[ OK ] Stopped target System Initialization.ystemd[1]: Stopp
ed target System Initialization.
[ 2.283931] iscsid[528]: iscsid shutting down.
[ 2.283968] systemd[1]: systemd-tmpfiles-setup.service: Succeeded.
[ OK ] Stopped Create Volatile Files and Directories.[ 2.284037] s
ystemd[1]: Stopped Create Volatile Files and Directories.
[ 2.284188] systemd[1]: systemd-sysctl.service: Succeeded.
[ OK ] Stopped Apply Kernel Variables.[ 2.284255] s
ystemd[1]: Stopped Apply Kernel Variables.
[ 2.284356] s[ OK ] Stopped target Swap.ystemd[1]: Stopp
ed target Swap.
[ 2.284513] systemd[1]: systemd-udev-settle.service: Succeeded.
[ OK ] Stopped udev Wait for Complete Device Initialization.[ 2.284625] s
ystemd[1]: Stopped udev Wait for Complete Device Initialization.
[ 2.284766] systemd[1]: systemd-udev-trigger.service: Succeeded.
[ OK ] Stopped udev Coldplug all Devices.[ 2.284869] s
ystemd[1]: Stopped udev Coldplug all Devices.
[ 2.284970] systemd[1]: dracut-pre-trigger.service: Succeeded.
[ OK ] Stopped dracut pre-trigger hook.[ 2.285072] s
ystemd[1]: Stopped dracut pre-trigger hook.
[ 2.285212] s[ OK ] Stopped target Local File Systems.ystemd[1]: Stopp
ed target Local File Systems.
[ 2.285296] systemd[1]: Stopped target Local File Systems (Pre).
[ OK ] Stopped target Local File Systems (Pre).
[ 2.285464] systemd[1]: systemd-modules-load.service: Succeeded.
[ OK ] Stopped Load Kernel Modules.[ 2.285557] s
ystemd[1]: Stopped Load Kernel Modules.
[ 2.285683] s[ OK ] Stopped target Local Encrypted Volumes.ystemd[1]: Stopp
ed target Local Encrypted Volumes.
[ 2.285817] s Stopping udev Kernel Device Manager...ystemd[1]: Stopp
ing udev Kernel Device Manager...
[ 2.285881] systemd[1]: Stopped target Slices.
[ OK ] Stopped target Slices.
[ OK ] Stopped target Sockets.[ 2.286003] s
ystemd[1]: Stopped target Sockets.
[ OK ] Stopped target Paths.
[ 2.286133] systemd[1]: Stopped target Paths.
[ 2.286210] systemd[1]: systemd-ask-password-console.path: Succeeded.
[ OK ] Stopped Dispatch Password Requests to Console Directory Watch.[ 2.348214] s
ystemd[1]: Stopped Dispatch Password Requests to Console Directory Watch.
[ 2.348347] s[ OK ] Stopped target Subsequent (Not Ignition) boot complete.ystemd[1]: Stopp
ed target Subsequent (Not Ignition) boot complete.
[ 2.348432] s[ OK ] Stopped target Ignition Subsequent Boot Disk Setup.ystemd[1]: Stopp
ed target Ignition Subsequent Boot Disk Setup.
[ 2.349067] systemd[1]: systemd-udevd.service: Succeeded.
[ OK ] Stopped udev Kernel Device Manager.[ 2.349171] s
ystemd[1]: Stopped udev Kernel Device Manager.
[ 2.349369] systemd[1]: iscsid.service: Succeeded.
[ OK ] Stopped Open-iSCSI.[ 2.349465] s
ystemd[1]: Stopped Open-iSCSI.
Stopping iSCSI UserSpace I/O driver...[ 2.349815] s
ystemd[1]: Stopping iSCSI UserSpace I/O driver...
[ 2.349920] systemd[1]: iscsid.socket: Succeeded.
[ 2.349995] systemd[1]: Closed Open-iSCSI iscsid Socket.
[ OK ] Closed Open-iSCSI iscsid Socket.
[ OK ] Stopped dracut pre-udev hook.
[ OK ] Stopped dracut cmdline hook.
[ OK ] Stopped dracut ask for additional cmdline parameters.
[ 2.350649] systemd[1]: dracut-pre-udev.service: Succeeded.
[ 2.350712] systemd[1]: Stopped dracut pre-udev hook.
[ 2.350792] systemd[1]: dracut-cmdline.service: Succeeded.
[ 2.350868] systemd[1]: Stopped dracut cmdline hook.
[ 2.350949] s[ OK ] Stopped Create Static Device Nodes in /dev.ystemd[1]: dracut-cmdline-ask.service: Succeeded
.
[ 2.351062] systemd[1]: Stopped dracut ask for additional cmdline parameters.
[ 2.351162] systemd[1]: systemd-tmpfiles-setup-dev.service: Succeeded.
[ 2.351259] systemd[1]: Stopped Create Static Device Nodes in /dev.
[ 2.351356] systemd[1]: kmod-static-nodes.service: Succeeded.
[ OK ] Stopped Create list of required sta…vice nodes for the current kernel.[ 2.351472] s
ystemd[1]: Stopped Create list of required static device nodes for the current kernel.
[ 2.351627] systemd[1]: systemd-udevd-control.socket: Succeeded.
[ OK ] Closed udev Control Socket.
[ 2.351801] systemd[1]: Closed udev Control Socket.
[ 2.351897] systemd[1]: systemd-udevd-kernel.socket: Succeeded.
[ OK ] Closed udev Kernel Socket.
[ 2.352084] systemd[1]: Closed udev Kernel Socket.
Starting Cleanup udevd DB...
[ OK ] Stopped iSCSI UserSpace I/O driver.
[ OK ] Started Cleaning Up and Shutting Down Daemons.
[ OK ] Closed Open-iSCSI iscsiuio Socket.
[ 2.353341] systemd[1]: Starting Cleanup udevd DB...
[ 2.353415] systemd[1]: iscsiuio.service: Succeeded.
[ 2.353511] systemd[1]: Stopped iSCSI UserSpace I/O driver.
[ 2.353584] systemd[1]: initrd-cleanup.service: Succeeded.
[ 2.353650] systemd[1]: Started Cleaning Up and Shutting Down Daemons.
[ 2.353727] systemd[1]: iscsiuio.socket: Succeeded.
[ 2.353784] systemd[1]: Closed Open-iSCSI iscsiuio Socket.
[ 2.380877] systemd[1]: initrd-udevadm-cleanup-db.service: Succeeded.
[ OK ] Started Cleanup udevd DB.[ 2.381005] s
ystemd[1]: Started Cleanup udevd DB.
[ OK ] Reached target Switch Root.[ 2.381174] s
ystemd[1]: Reached target Switch Root.
Starting Switch Root...[ 2.381473] s
ystemd[1]: Starting Switch Root...
[ 2.411477] systemd[1]: Switching root.
[ 2.570222] printk: systemd: 24 output lines suppressed due to ratelimiting
[ 2.618232] audit: type=1404 audit(1663591849.910:2): enforcing=1 old_enforcing=0 auid=4294967295 ses=4294967295 enabled=1 old-enabled=1 lsm=selinux res=1
[ 2.764870] SELinux: Permission watch in class filesystem not defined in policy.
[ 2.764941] SELinux: Permission watch in class file not defined in policy.
[ 2.764989] SELinux: Permission watch_mount in class file not defined in policy.
[ 2.765040] SELinux: Permission watch_sb in class file not defined in policy.
[ 2.765094] SELinux: Permission watch_with_perm in class file not defined in policy.
[ 2.765146] SELinux: Permission watch_reads in class file not defined in policy.
[ 2.765200] SELinux: Permission watch in class dir not defined in policy.
[ 2.765245] SELinux: Permission watch_mount in class dir not defined in policy.
[ 2.765297] SELinux: Permission watch_sb in class dir not defined in policy.
[ 2.765348] SELinux: Permission watch_with_perm in class dir not defined in policy.
[ 2.765398] SELinux: Permission watch_reads in class dir not defined in policy.
[ 2.765450] SELinux: Permission watch in class lnk_file not defined in policy.
[ 2.765499] SELinux: Permission watch_mount in class lnk_file not defined in policy.
[ 2.765550] SELinux: Permission watch_sb in class lnk_file not defined in policy.
[ 2.765589] SELinux: Permission watch_with_perm in class lnk_file not defined in policy.
[ 2.765639] SELinux: Permission watch_reads in class lnk_file not defined in policy.
[ 2.765690] SELinux: Permission watch in class chr_file not defined in policy.
[ 2.765739] SELinux: Permission watch_mount in class chr_file not defined in policy.
[ 2.765790] SELinux: Permission watch_sb in class chr_file not defined in policy.
[ 2.765840] SELinux: Permission watch_with_perm in class chr_file not defined in policy.
[ 2.765894] SELinux: Permission watch_reads in class chr_file not defined in policy.
[ 2.765945] SELinux: Permission watch in class blk_file not defined in policy.
[ 2.765997] SELinux: Permission watch_mount in class blk_file not defined in policy.
[ 2.766060] SELinux: Permission watch_sb in class blk_file not defined in policy.
[ 2.766126] SELinux: Permission watch_with_perm in class blk_file not defined in policy.
[ 2.766177] SELinux: Permission watch_reads in class blk_file not defined in policy.
[ 2.766228] SELinux: Permission watch in class sock_file not defined in policy.
[ 2.766277] SELinux: Permission watch_mount in class sock_file not defined in policy.
[ 2.766336] SELinux: Permission watch_sb in class sock_file not defined in policy.
[ 2.766390] SELinux: Permission watch_with_perm in class sock_file not defined in policy.
[ 2.766439] SELinux: Permission watch_reads in class sock_file not defined in policy.
[ 2.766490] SELinux: Permission watch in class fifo_file not defined in policy.
[ 2.766534] SELinux: Permission watch_mount in class fifo_file not defined in policy.
[ 2.766585] SELinux: Permission watch_sb in class fifo_file not defined in policy.
[ 2.766636] SELinux: Permission watch_with_perm in class fifo_file not defined in policy.
[ 2.766687] SELinux: Permission watch_reads in class fifo_file not defined in policy.
[ 2.766759] SELinux: Permission perfmon in class capability2 not defined in policy.
[ 2.766806] SELinux: Permission bpf in class capability2 not defined in policy.
[ 2.766861] SELinux: Permission perfmon in class cap2_userns not defined in policy.
[ 2.766912] SELinux: Permission bpf in class cap2_userns not defined in policy.
[ 2.766974] SELinux: Class anon_inode not defined in policy.
[ 2.767016] SELinux: the above unknown classes and permissions will be allowed
[ 2.768183] SELinux: policy capability network_peer_controls=1
[ 2.768234] SELinux: policy capability open_perms=1
[ 2.768272] SELinux: policy capability extended_socket_class=1
[ 2.768309] SELinux: policy capability always_check_network=0
[ 2.768353] SELinux: policy capability cgroup_seclabel=1
[ 2.768392] SELinux: policy capability nnp_nosuid_transition=1
[ 2.768430] SELinux: policy capability genfs_seclabel_symlinks=0
[ 2.855421] audit: type=1403 audit(1663591850.140:3): auid=4294967295 ses=4294967295 lsm=selinux res=1
[ 2.856704] systemd[1]: Successfully loaded SELinux policy in 238.694ms.
[ 2.874604] systemd[1]: Relabelled /dev, /run and /sys/fs/cgroup in 10.331ms.
[ 2.877379] systemd[1]: systemd 239 (239-58.el8_6.3) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy)
[ 2.877535] systemd[1]: Detected architecture arm64.
Welcome to Red Hat Enterprise Linux CoreOS 411.86.202208111758-0 (Ootpa)!
[ 2.878238] systemd[1]: Set hostname to <crc-nz7ls-master-0>.
[ 2.986587] systemd[1]: /usr/lib/systemd/system/bootupd.service:22: Unknown lvalue 'ProtectHostname' in section 'Service'
[ 2.996995] systemd[1]: systemd-journald.service: Succeeded.
[ 2.997297] systemd[1]: systemd-journald.service: Consumed 0 CPU time
[ 2.997412] systemd[1]: initrd-switch-root.service: Succeeded.
[ 2.997609] systemd[1]: Stopped Switch Root.
[ OK ] Stopped Switch Root.
[ 2.997767] systemd[1]: initrd-switch-root.service: Consumed 0 CPU time
[ 2.997899] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart.
[ 2.997977] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1.
[ 2.998033] systemd[1]: Stopped Journal Service.
[ OK ] Stopped Journal Service.
[ 2.998097] systemd[1]: systemd-journald.service: Consumed 0 CPU time
[ 2.998394] systemd[1]: Starting Journal Service...
Starting Journal Service...
[ 2.998541] systemd[1]: Reached target Host and Network Name Lookups.
[ OK ] Reached target Host and Network Name Lookups.
[ 2.998660] systemd[1]: systemd-fsck-root.service: Succeeded.
[ 2.998883] systemd[1]: Stopped File System Check on Root Device.
[ OK ] Stopped File System Check on Root Device.
[ 2.998967] systemd[1]: systemd-fsck-root.service: Consumed 0 CPU time
[ 2.999017] systemd[1]: Reached target Remote File Systems.
[ OK ] Reached target Remote File Systems.
[ 2.999878] systemd[1]: Listening on RPCbind Server Activation Socket.
[ OK ] Listening on RPCbind Server Activation Socket.
[ 3.000788] systemd[1]: Starting Create list of required static device nodes for the current kernel...
Starting Create list of required st…ce nodes for the current kernel...
[ 3.001170] systemd[1]: Listening on Device-mapper event daemon FIFOs.
[ OK ] Listening on Device-mapper event daemon FIFOs.
[ 3.001465] systemd[1]: Created slice system-sshd\x2dkeygen.slice.
[ OK ] Created slice system-sshd\x2dkeygen.slice.
[ 3.001848] systemd[1]: Listening on LVM2 poll daemon socket.
[ OK ] Listening on LVM2 poll daemon socket.
[ 3.002188] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[ OK ] Set up automount Arbitrary Executab…rmats File System Automount Point.
[ 3.002333] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[ OK ] Started Dispatch Password Requests to Console Directory Watch.
[ 3.002688] systemd[1]: Starting Load Kernel Modules...
Starting Load Kernel Modules...
[ 3.002824] systemd[1]: Reached target Synchronize afterburn-sshkeys@.service template instances.
[ OK ] Reached target Synchronize afterbur…hkeys@.service template instances.
[ 3.003065] systemd[1]: Created slice system-getty.slice.
[ OK ] Created slice system-getty.slice.
[ 3.003960] systemd[1]: Created slice system-serial\x2dgetty.slice.
[ OK ] Created slice system-serial\x2dgetty.slice.
[ 3.004615] systemd[1]: Mounting POSIX Message Queue File System...
Mounting POSIX Message Queue File System...
[ 3.004770] systemd[1]: Stopped target Switch Root.
[ OK ] Stopped target Switch Root.
[ 3.004968] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[ OK ] Started Forward Password Requests to Wall Directory Watch.
[ 3.005402] systemd[1]: Mounting Kernel Debug File System...
Mounting Kernel Debug File System...
[ 3.007233] systemd[1]: Listening on udev Control Socket.
[ OK ] Listening on udev Control Socket.
[ 3.007721] systemd[1]: Started Forward Password Requests to Clevis Directory Watch.
[ OK ] Started Forward Password Requests to Clevis Directory Watch.
[ 3.007869] systemd[1]: Reached target Local Encrypted Volumes (Pre).
[ OK ] Reached target Local Encrypted Volumes (Pre).
[ 3.008044] systemd[1]: Stopped target Initrd Root File System.
[ OK ] Stopped target Initrd Root File System.
[ 3.008721] systemd[1]: Mounting Huge Pages File System...
Mounting Huge Pages File System...
[ 3.008895] systemd[1]: Listening on initctl Compatibility Named Pipe.
[ OK ] Listening on initctl Compatibility Named Pipe.
[ 3.009150] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[ OK ] Created slice system-systemd\x2dfsck.slice.
[ 3.009374] systemd[1]: Created slice User and Session Slice.
[ OK ] Created slice User and Session Slice.
[ 3.009513] systemd[1]: Reached target Slices.
[ OK ] Reached target Slices.
[ 3.009630] systemd[1]: ostree-prepare-root.service: Succeeded.
[ 3.009861] systemd[1]: Stopped OSTree Prepare OS/.
[ OK ] Stopped OSTree Prepare OS/.
[ 3.009961] systemd[1]: ostree-prepare-root.service: Consumed 0 CPU time
[ 3.010111] systemd[1]: Listening on udev Kernel Socket.
[ OK ] Listening on udev Kernel Socket.
[ 3.010397] systemd[1]: Starting Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling...
Starting Monitoring of LVM2 mirrors…ng dmeventd or progress polling...
[ 3.010842] systemd[1]: Starting udev Coldplug all Devices...
Starting udev Coldplug all Devices...
[ 3.010994] systemd[1]: Reached target Remote Encrypted Volumes.
[ OK ] Reached target Remote Encrypted Volumes.
[ 3.012570] systemd[1]: Listening on Process Core Dump Socket.
[ OK ] Listening on Process Core Dump Socket.
[ 3.013151] systemd[1]: Reached target RPC Port Mapper.
[ OK ] Reached target RPC Port Mapper.
[ 3.013229] systemd[1]: Reached target Swap.
[ OK ] Reached target Swap.
[ 3.013680] systemd[1]: Mounting Temporary Directory (/tmp)...
Mounting Temporary Directory (/tmp)...
[ 3.013822] systemd[1]: Reached target Local Encrypted Volumes.
[ OK ] Reached target Local Encrypted Volumes.
[ 3.014024] systemd[1]: Stopped target Initrd File Systems.
[ OK ] Stopped target Initrd File Systems.
[ 3.015755] systemd[1]: sysroot-sysroot-ostree-deploy-rhcos-var.mount: Succeeded.
[ 3.016002] systemd[1]: sysroot-sysroot-ostree-deploy-rhcos-var.mount: Consumed 0 CPU time
[ 3.016085] systemd[1]: sysroot-etc.mount: Succeeded.
[ 3.016368] systemd[1]: sysroot-etc.mount: Consumed 0 CPU time
[ 3.016443] systemd[1]: sysroot-sysroot.mount: Succeeded.
[ 3.016658] systemd[1]: sysroot-sysroot.mount: Consumed 0 CPU time
[ 3.016725] systemd[1]: sysroot-usr.mount: Succeeded.
[ 3.017089] systemd[1]: sysroot-usr.mount: Consumed 0 CPU time
[ 3.017270] systemd[1]: Started Journal Service.
[ OK ] Started Journal Service.
[ OK ] Started Create list of required sta…vice nodes for the current kernel.
[ OK ] Mounted POSIX Message Queue File System.
[ OK ] Mounted Kernel Debug File System.
[ OK ] Mounted Huge Pages File System.
[ OK ] Mounted Temporary Directory (/tmp).
Starting Create Static Device Nodes in /dev...
[ 3.024448] Warning: Deprecated Driver is detected: iptables will not be maintained in a future major release and may be disabled
[ OK ] Started Load Kernel Modules.
Mounting FUSE Control File System...
Starting Apply Kernel Variables...
[ OK ] Mounted FUSE Control File System.
[ OK ] Started Apply Kernel Variables.
[ OK ] Started udev Coldplug all Devices.
[ OK ] Started Create Static Device Nodes in /dev.
Starting udev Kernel Device Manager...
Starting udev Wait for Complete Device Initialization...
[ OK ] Started udev Kernel Device Manager.
[ 3.077009] NET: Registered PF_VSOCK protocol family
[ OK ] Started udev Wait for Complete Device Initialization.
[ OK ] Started Monitoring of LVM2 mirrors,…sing dmeventd or progress polling.
[ OK ] Reached target Local File Systems (Pre).
Starting File System Check on /dev/…366-de9e-461d-ae26-845f3de31cd8...
Mounting /var...
[ OK ] Mounted /var.
Starting OSTree Remount OS/ Bind Mounts...
[ OK ] Started OSTree Remount OS/ Bind Mounts.
Starting Load/Save Random Seed...
Starting Flush Journal to Persistent Storage...
[ OK ] Started Load/Save Random Seed.
[ OK ] Started File System Check on /dev/d…d3366-de9e-461d-ae26-845f3de31cd8.
Mounting CoreOS Dynamic Mount for /boot...
[ OK ] Started Flush Journal to Persistent Storage.
[ 3.283837] EXT4-fs (vda3): mounted filesystem with ordered data mode. Quota mode: none.
[ OK ] Mounted CoreOS Dynamic Mount for /boot.
[ OK ] Reached target Local File Systems.
Starting Restore /run/initramfs on shutdown...
Starting Run update-ca-trust...
Starting Create Volatile Files and Directories...
[ OK ] Started Restore /run/initramfs on shutdown.
[ OK ] Started Create Volatile Files and Directories.
Starting Security Auditing Service...
Starting RHCOS Fix SELinux Labeling For /usr/local/sbin...
[ OK ] Started RHCOS Fix SELinux Labeling For /usr/local/sbin.
[ 3.351127] audit: type=1400 audit(1663591850.640:4): avc: denied { fowner } for pid=845 comm="auditd" capability=3 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=capability permissive=0
[ 3.351285] audit: type=1400 audit(1663591850.640:5): avc: denied { fowner } for pid=845 comm="auditd" capability=3 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=capability permissive=0
[ 3.351358] audit: type=1400 audit(1663591850.640:6): avc: denied { fowner } for pid=845 comm="auditd" capability=3 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=capability permissive=0
[ 3.351447] audit: type=1400 audit(1663591850.640:7): avc: denied { fowner } for pid=845 comm="auditd" capability=3 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=capability permissive=0
[ 3.351525] audit: type=1400 audit(1663591850.640:8): avc: denied { fowner } for pid=845 comm="auditd" capability=3 scontext=system_u:system_r:auditd_t:s0 tcontext=system_u:system_r:auditd_t:s0 tclass=capability permissive=0
[ OK ] Started Security Auditing Service.
Starting Update UTMP about System Boot/Shutdown...
[ OK ] Started Update UTMP about System Boot/Shutdown.
[ OK ] Started Run update-ca-trust.
[ OK ] Reached target System Initialization.
[ OK ] Started Monitor console-login-helpe…ue snippets directory for changes.
[ OK ] Listening on D-Bus System Message Bus Socket.
[ OK ] Started Daily Cleanup of Temporary Directories.
[ OK ] Listening on Podman API Socket.
[ OK ] Started Daily rotation of log files.
[ OK ] Started daily update of the root trust anchor for DNSSEC.
[ OK ] Reached target Timers.
[ OK ] Listening on bootupd.socket.
[ OK ] Reached target Sockets.
[ OK ] Started OSTree Monitor Staged Deployment.
[ OK ] Reached target Paths.
[ OK ] Reached target Basic System.
[ OK ] Started D-Bus System Message Bus.
Starting Dummy crio-wipe service...
Starting Generate console-login-helper-messages issue snippet...
Starting Open vSwitch Database Unit...
Starting NTP client/server...
Starting Generation of shadow ID ranges for CRI-O...
Starting System Security Services Daemon...
[ OK ] Reached target sshd-keygen.target.
Starting Generate SSH keys snippet …a console-login-helper-messages...
Starting Create Ignition Status Issue Files...
[ OK ] Started Dummy crio-wipe service.
[ OK ] Started Generate SSH keys snippet f…via console-login-helper-messages.
[ OK ] Started NTP client/server.
[ OK ] Started Generation of shadow ID ranges for CRI-O.
[ OK ] Started Create Ignition Status Issue Files.
[ OK ] Started Open vSwitch Database Unit.
Starting Open vSwitch Delete Transient Ports...
[ OK ] Started Open vSwitch Delete Transient Ports.
Starting Open vSwitch Forwarding Unit...
[ OK ] Started System Security Services Daemon.
[ OK ] Reached target User and Group Name Lookups.
Starting Login Service...
[ OK ] Started Login Service.
[ 4.135205] openvswitch: Open vSwitch switching datapath
[ 4.156933] device ovs-system entered promiscuous mode
[ 4.157208] Timeout policy base is empty
[ 4.157240] Failed to associated timeout policy `ovs_test_tp'
[ 4.167539] device tun0 entered promiscuous mode
[ 4.173902] device vxlan_sys_4789 entered promiscuous mode
[ 4.206388] device br0 entered promiscuous mode
[ OK ] Started Open vSwitch Forwarding Unit.
Starting Open vSwitch...
[ OK ] Started Open vSwitch.
Starting Network Manager...
[ OK ] Started Network Manager.
Starting Network Manager Wait Online...
[ OK ] Reached target Network.
Starting OpenSSH server daemon...
Starting Create dummy network...
Starting Hostname Service...
[ OK ] Started OpenSSH server daemon.
[ OK ] Started Hostname Service.
[ OK ] Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
Starting Network Manager Script Dispatcher Service...
[ OK ] Started Network Manager Script Dispatcher Service.
[ OK ] Started Create dummy network.
[ OK ] Started Network Manager Wait Online.
Starting Configures OVS with proper host networking configuration...
[ 4.436970] configure-ovs.sh[1395]: + touch /var/run/ovs-config-executed
[ 4.451962] configure-ovs.sh[1395]: + NM_CONN_PATH=/etc/NetworkManager/system-connections
[ 4.452025] configure-ovs.sh[1395]: + nm_config_changed=0
[ 4.452067] configure-ovs.sh[1395]: + MANAGED_NM_CONN_SUFFIX=-slave-ovs-clone
[ 4.452107] configure-ovs.sh[1395]: + BRIDGE_METRIC=48
[ 4.452200] configure-ovs.sh[1395]: + BRIDGE1_METRIC=49
[ 4.452288] configure-ovs.sh[1395]: + trap handle_exit EXIT
[ 4.452340] configure-ovs.sh[1395]: + '[' '!' -f /etc/cno/mtu-migration/config ']'
[ 4.452596] configure-ovs.sh[1395]: + echo 'Cleaning up left over mtu migration configuration'
[ 4.452663] configure-ovs.sh[1395]: Cleaning up left over mtu migration configuration
[ 4.452700] configure-ovs.sh[1395]: + rm -rf /etc/cno/mtu-migration
[ 4.452890] configure-ovs.sh[1404]: + rpm -qa
[ 4.452971] configure-ovs.sh[1405]: + grep -q openvswitch
[ OK ] Started Generate console-login-helper-messages issue snippet.
Starting Permit User Sessions...
[ OK ] Started Permit User Sessions.
[ OK ] Started Getty on tty1.
[ OK ] Started Serial Getty on hvc0.
[ OK ] Reached target Login Prompts.
[ 4.550091] configure-ovs.sh[1395]: + print_state
[ 4.550268] configure-ovs.sh[1395]: + echo 'Current device, connection, interface and routing state:'
[ 4.550423] configure-ovs.sh[1395]: Current device, connection, interface and routing state:
[ 4.550611] configure-ovs.sh[1475]: + nmcli -g all device
[ 4.550752] configure-ovs.sh[1476]: + grep -v unmanaged
[ 4.560673] configure-ovs.sh[1476]: eth10:dummy:connected:limited:limited:/org/freedesktop/NetworkManager/Devices/5:internalEtcd:859c7fd9-c005-4c5d-9e0d-b48d615a8e93:/org/freedesktop/NetworkManager/ActiveConnection/1
[ 4.560749] configure-ovs.sh[1395]: + nmcli -g all connection
[ 4.570301] configure-ovs.sh[1480]: internalEtcd:859c7fd9-c005-4c5d-9e0d-b48d615a8e93:dummy:1663591851:Mon Sep 19 12\:50\:51 2022:yes:0:no:/org/freedesktop/NetworkManager/Settings/1:yes:eth10:activated:/org/freedesktop/NetworkManager/ActiveConnection/1::/etc/NetworkManager/system-connections/internalEtcd.nmconnection
[ 4.570419] configure-ovs.sh[1480]: internalEtcd:d205c672-ec52-4332-8c3f-fc18962811b6:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/2:no:::::/etc/NetworkManager/system-connections/internalEtcd-d205c672-ec52-4332-8c3f-fc18962811b6.nmconnection
[ 4.570474] configure-ovs.sh[1480]: internalEtcd:fa0e184f-bbc6-4c08-8635-69b53e0da9a9:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/3:no:::::/etc/NetworkManager/system-connections/internalEtcd-fa0e184f-bbc6-4c08-8635-69b53e0da9a9.nmconnection
[ 4.570518] configure-ovs.sh[1480]: internalEtcd:72dc93f3-bd57-4b8c-b66d-bd059c02894d:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/4:no:::::/etc/NetworkManager/system-connections/internalEtcd-72dc93f3-bd57-4b8c-b66d-bd059c02894d.nmconnection
[ 4.570561] configure-ovs.sh[1480]: internalEtcd:2eab7ce1-287b-4683-8843-a10bf3e99b21:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/5:no:::::/etc/NetworkManager/system-connections/internalEtcd-2eab7ce1-287b-4683-8843-a10bf3e99b21.nmconnection
[ 4.570605] configure-ovs.sh[1480]: internalEtcd:f0aa33fb-60ee-4a72-9870-877b5271560e:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/6:no:::::/etc/NetworkManager/system-connections/internalEtcd-f0aa33fb-60ee-4a72-9870-877b5271560e.nmconnection
[ 4.570645] configure-ovs.sh[1480]: internalEtcd:d3f49293-91cb-41bf-833e-f75f67468ed1:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/7:no:::::/etc/NetworkManager/system-connections/internalEtcd-d3f49293-91cb-41bf-833e-f75f67468ed1.nmconnection
[ 4.570695] configure-ovs.sh[1480]: internalEtcd:5c13b671-4a12-41d3-8baf-47cff7350421:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/8:no:::::/etc/NetworkManager/system-connections/internalEtcd-5c13b671-4a12-41d3-8baf-47cff7350421.nmconnection
[ 4.570880] configure-ovs.sh[1395]: + ip -d address show
[ 4.576106] configure-ovs.sh[1484]: 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
[ 4.576156] configure-ovs.sh[1484]: link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00 promiscuity 0 minmtu 0 maxmtu 0 numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535
[ 4.576187] configure-ovs.sh[1484]: inet 127.0.0.1/8 scope host lo
[ 4.576221] configure-ovs.sh[1484]: valid_lft forever preferred_lft forever
[ 4.576252] configure-ovs.sh[1484]: inet6 ::1/128 scope host
[ 4.576285] configure-ovs.sh[1484]: valid_lft forever preferred_lft forever
[ 4.576316] configure-ovs.sh[1484]: 2: ovs-system: <BROADCAST,MULTICAST> mtu 1500 qdisc noop state DOWN group default qlen 1000
[ 4.576347] configure-ovs.sh[1484]: link/ether a6:f1:9e:80:9f:a3 brd ff:ff:ff:ff:ff:ff promiscuity 1 minmtu 68 maxmtu 65535
[ 4.576383] configure-ovs.sh[1484]: openvswitch numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535
[ 4.576413] configure-ovs.sh[1484]: 3: tun0: <BROADCAST,MULTICAST> mtu 1400 qdisc noop state DOWN group default qlen 1000
[ 4.576442] configure-ovs.sh[1484]: link/ether 7e:e3:75:47:c5:74 brd ff:ff:ff:ff:ff:ff promiscuity 1 minmtu 68 maxmtu 65535
[ 4.576472] configure-ovs.sh[1484]: openvswitch numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535
[ 4.576506] configure-ovs.sh[1484]: 4: vxlan_sys_4789: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 65000 qdisc noqueue master ovs-system state UNKNOWN group default qlen 1000
[ 4.576537] configure-ovs.sh[1484]: link/ether 1e:a1:f0:ae:c4:8a brd ff:ff:ff:ff:ff:ff promiscuity 1 minmtu 68 maxmtu 65535
[ 4.576566] configure-ovs.sh[1484]: vxlan external id 0 srcport 0 0 dstport 4789 nolearning ttl auto ageing 300 udpcsum noudp6zerocsumtx udp6zerocsumrx
[ 4.576594] configure-ovs.sh[1484]: openvswitch_slave numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535
[ 4.576623] configure-ovs.sh[1484]: inet6 fe80::1ca1:f0ff:feae:c48a/64 scope link tentative
[ 4.576653] configure-ovs.sh[1484]: valid_lft forever preferred_lft forever
[ 4.576709] configure-ovs.sh[1484]: 5: br0: <BROADCAST,MULTICAST> mtu 1400 qdisc noop state DOWN group default qlen 1000
[ 4.576739] configure-ovs.sh[1484]: link/ether ba:5c:64:c8:f1:4d brd ff:ff:ff:ff:ff:ff promiscuity 1 minmtu 68 maxmtu 65535
[ 4.576767] configure-ovs.sh[1484]: openvswitch numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535
[ 4.576796] configure-ovs.sh[1484]: 6: eth10: <BROADCAST,NOARP,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default qlen 1000
[ 4.576824] configure-ovs.sh[1484]: link/ether 46:9a:8a:ea:ad:69 brd ff:ff:ff:ff:ff:ff promiscuity 0 minmtu 0 maxmtu 0
[ 4.576851] configure-ovs.sh[1484]: dummy numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535
[ 4.576878] configure-ovs.sh[1484]: inet 192.168.126.11/24 brd 192.168.126.255 scope global noprefixroute eth10
[ 4.576906] configure-ovs.sh[1484]: valid_lft forever preferred_lft forever
[ 4.576937] configure-ovs.sh[1395]: + ip route show
[ 4.577502] configure-ovs.sh[1485]: 192.168.126.0/24 dev eth10 proto kernel scope link src 192.168.126.11 metric 550
[ 4.577575] configure-ovs.sh[1395]: + ip -6 route show
[ 4.578370] configure-ovs.sh[1486]: ::1 dev lo proto kernel metric 256 pref medium
[ 4.578424] configure-ovs.sh[1486]: fe80::/64 dev vxlan_sys_4789 proto kernel metric 256 pref medium
[ 4.578715] configure-ovs.sh[1395]: + '[' OpenShiftSDN == OVNKubernetes ']'
[ 4.578746] configure-ovs.sh[1395]: + '[' OpenShiftSDN == OpenShiftSDN ']'
[ 4.578808] configure-ovs.sh[1395]: + rollback_nm
[ 4.579082] configure-ovs.sh[1487]: ++ get_bridge_physical_interface ovs-if-phys0
[ 4.579120] configure-ovs.sh[1487]: ++ local bridge_interface=ovs-if-phys0
[ 4.579150] configure-ovs.sh[1487]: ++ local physical_interface=
[ 4.579439] configure-ovs.sh[1488]: +++ nmcli -g connection.interface-name conn show ovs-if-phys0
[ 4.589322] configure-ovs.sh[1488]: +++ echo ''
[ 4.589456] configure-ovs.sh[1487]: ++ physical_interface=
[ 4.589500] configure-ovs.sh[1487]: ++ echo ''
[ 4.589597] configure-ovs.sh[1395]: + phys0=
[ 4.589958] configure-ovs.sh[1493]: ++ get_bridge_physical_interface ovs-if-phys1
[ 4.590023] configure-ovs.sh[1493]: ++ local bridge_interface=ovs-if-phys1
[ 4.590054] configure-ovs.sh[1493]: ++ local physical_interface=
[ 4.590313] configure-ovs.sh[1494]: +++ nmcli -g connection.interface-name conn show ovs-if-phys1
[ 4.599941] configure-ovs.sh[1494]: +++ echo ''
[ 4.600095] configure-ovs.sh[1493]: ++ physical_interface=
[ 4.600146] configure-ovs.sh[1493]: ++ echo ''
[ 4.600258] configure-ovs.sh[1395]: + phys1=
[ 4.600311] configure-ovs.sh[1395]: + remove_all_ovn_bridges
[ 4.600362] configure-ovs.sh[1395]: + echo 'Reverting any previous OVS configuration'
[ 4.600407] configure-ovs.sh[1395]: Reverting any previous OVS configuration
[ 4.600450] configure-ovs.sh[1395]: + remove_ovn_bridges br-ex phys0
[ 4.600504] configure-ovs.sh[1395]: + bridge_name=br-ex
[ 4.600546] configure-ovs.sh[1395]: + port_name=phys0
[ 4.600597] configure-ovs.sh[1395]: + update_nm_conn_files br-ex phys0
[ 4.600632] configure-ovs.sh[1395]: + bridge_name=br-ex
[ 4.600673] configure-ovs.sh[1395]: + port_name=phys0
[ 4.600716] configure-ovs.sh[1395]: + ovs_port=ovs-port-br-ex
[ 4.600761] configure-ovs.sh[1395]: + ovs_interface=ovs-if-br-ex
[ 4.600795] configure-ovs.sh[1395]: + default_port_name=ovs-port-phys0
[ 4.600841] configure-ovs.sh[1395]: + bridge_interface_name=ovs-if-phys0
[ 4.600884] configure-ovs.sh[1395]: + MANAGED_NM_CONN_FILES=($(echo "${NM_CONN_PATH}"/{"$bridge_name","$ovs_interface","$ovs_port","$bridge_interface_name","$default_port_name"}{,.nmconnection}))
[ 4.601073] configure-ovs.sh[1499]: ++ echo /etc/NetworkManager/system-connections/br-ex /etc/NetworkManager/system-connections/br-ex.nmconnection /etc/NetworkManager/system-connections/ovs-if-br-ex /etc/NetworkManager/system-connections/ovs-if-br-ex.nmconnection /etc/NetworkManager/system-connections/ovs-port-br-ex /etc/NetworkManager/system-connections/ovs-port-br-ex.nmconnection /etc/NetworkManager/system-connections/ovs-if-phys0 /etc/NetworkManager/system-connections/ovs-if-phys0.nmconnection /etc/NetworkManager/system-connections/ovs-port-phys0 /etc/NetworkManager/system-connections/ovs-port-phys0.nmconnection
[ 4.601198] configure-ovs.sh[1395]: + shopt -s nullglob
[ 4.601241] configure-ovs.sh[1395]: + MANAGED_NM_CONN_FILES+=(${NM_CONN_PATH}/*${MANAGED_NM_CONN_SUFFIX}.nmconnection ${NM_CONN_PATH}/*${MANAGED_NM_CONN_SUFFIX})
[ 4.601280] configure-ovs.sh[1395]: + shopt -u nullglob
[ 4.601317] configure-ovs.sh[1395]: + rm_nm_conn_files
[ 4.601359] configure-ovs.sh[1395]: + for file in "${MANAGED_NM_CONN_FILES[@]}"
[ 4.601399] configure-ovs.sh[1395]: + '[' -f /etc/NetworkManager/system-connections/br-ex ']'
[ 4.601430] configure-ovs.sh[1395]: + for file in "${MANAGED_NM_CONN_FILES[@]}"
[ 4.601482] configure-ovs.sh[1395]: + '[' -f /etc/NetworkManager/system-connections/br-ex.nmconnection ']'
[ 4.601524] configure-ovs.sh[1395]: + for file in "${MANAGED_NM_CONN_FILES[@]}"
[ 4.601561] configure-ovs.sh[1395]: + '[' -f /etc/NetworkManager/system-connections/ovs-if-br-ex ']'
[ 4.601605] configure-ovs.sh[1395]: + for file in "${MANAGED_NM_CONN_FILES[@]}"
[ 4.601646] configure-ovs.sh[1395]: + '[' -f /etc/NetworkManager/system-connections/ovs-if-br-ex.nmconnection ']'
[ 4.601684] configure-ovs.sh[1395]: + for file in "${MANAGED_NM_CONN_FILES[@]}"
[ 4.601727] configure-ovs.sh[1395]: + '[' -f /etc/NetworkManager/system-connections/ovs-port-br-ex ']'
[ 4.601769] configure-ovs.sh[1395]: + for file in "${MANAGED_NM_CONN_FILES[@]}"
[ 4.601807] configure-ovs.sh[1395]: + '[' -f /etc/NetworkManager/system-connections/ovs-port-br-ex.nmconnection ']'
[ 4.601853] configure-ovs.sh[1395]: + for file in "${MANAGED_NM_CONN_FILES[@]}"
[ 4.601896] configure-ovs.sh[1395]: + '[' -f /etc/NetworkManager/system-connections/ovs-if-phys0 ']'
[ 4.601940] configure-ovs.sh[1395]: + for file in "${MANAGED_NM_CONN_FILES[@]}"
[ 4.601993] configure-ovs.sh[1395]: + '[' -f /etc/NetworkManager/system-connections/ovs-if-phys0.nmconnection ']'
[ 4.602034] configure-ovs.sh[1395]: + for file in "${MANAGED_NM_CONN_FILES[@]}"
[ 4.602077] configure-ovs.sh[1395]: + '[' -f /etc/NetworkManager/system-connections/ovs-port-phys0 ']'
[ 4.602127] configure-ovs.sh[1395]: + for file in "${MANAGED_NM_CONN_FILES[@]}"
[ 4.602169] configure-ovs.sh[1395]: + '[' -f /etc/NetworkManager/system-connections/ovs-port-phys0.nmconnection ']'
[ 4.602215] configure-ovs.sh[1395]: + ovs-vsctl --timeout=30 --if-exists del-br br-ex
[ 4.605160] configure-ovs.sh[1395]: + '[' -d /sys/class/net/br-ex1 ']'
[ 4.605213] configure-ovs.sh[1395]: + echo 'OVS configuration successfully reverted'
[ 4.605276] configure-ovs.sh[1395]: OVS configuration successfully reverted
[ 4.605322] configure-ovs.sh[1395]: + reload_profiles_nm '' ''
[ 4.605363] configure-ovs.sh[1395]: + '[' 0 -eq 0 ']'
[ 4.605396] configure-ovs.sh[1395]: + return
[ 4.605442] configure-ovs.sh[1395]: + ovs-vsctl --timeout=30 --if-exists del-br br-int -- --if-exists del-br br-local
[ 4.607909] configure-ovs.sh[1395]: + handle_exit
[ 4.607965] configure-ovs.sh[1395]: + e=0
[ 4.608062] configure-ovs.sh[1395]: + '[' 0 -eq 0 ']'
[ 4.608107] configure-ovs.sh[1395]: + print_state
[ 4.608149] configure-ovs.sh[1395]: + echo 'Current device, connection, interface and routing state:'
[ 4.608191] configure-ovs.sh[1395]: Current device, connection, interface and routing state:
[ 4.608268] configure-ovs.sh[1502]: + nmcli -g all device
[ 4.608345] configure-ovs.sh[1503]: + grep -v unmanaged
[ 4.618107] configure-ovs.sh[1503]: eth10:dummy:connected:limited:limited:/org/freedesktop/NetworkManager/Devices/5:internalEtcd:859c7fd9-c005-4c5d-9e0d-b48d615a8e93:/org/freedesktop/NetworkManager/ActiveConnection/1
[ 4.618189] configure-ovs.sh[1395]: + nmcli -g all connection
[ 4.627518] configure-ovs.sh[1507]: internalEtcd:859c7fd9-c005-4c5d-9e0d-b48d615a8e93:dummy:1663591851:Mon Sep 19 12\:50\:51 2022:yes:0:no:/org/freedesktop/NetworkManager/Settings/1:yes:eth10:activated:/org/freedesktop/NetworkManager/ActiveConnection/1::/etc/NetworkManager/system-connections/internalEtcd.nmconnection
[ 4.627609] configure-ovs.sh[1507]: internalEtcd:d205c672-ec52-4332-8c3f-fc18962811b6:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/2:no:::::/etc/NetworkManager/system-connections/internalEtcd-d205c672-ec52-4332-8c3f-fc18962811b6.nmconnection
[ 4.627669] configure-ovs.sh[1507]: internalEtcd:fa0e184f-bbc6-4c08-8635-69b53e0da9a9:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/3:no:::::/etc/NetworkManager/system-connections/internalEtcd-fa0e184f-bbc6-4c08-8635-69b53e0da9a9.nmconnection
[ 4.627731] configure-ovs.sh[1507]: internalEtcd:72dc93f3-bd57-4b8c-b66d-bd059c02894d:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/4:no:::::/etc/NetworkManager/system-connections/internalEtcd-72dc93f3-bd57-4b8c-b66d-bd059c02894d.nmconnection
[ 4.627789] configure-ovs.sh[1507]: internalEtcd:2eab7ce1-287b-4683-8843-a10bf3e99b21:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/5:no:::::/etc/NetworkManager/system-connections/internalEtcd-2eab7ce1-287b-4683-8843-a10bf3e99b21.nmconnection
[ 4.627866] configure-ovs.sh[1507]: internalEtcd:f0aa33fb-60ee-4a72-9870-877b5271560e:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/6:no:::::/etc/NetworkManager/system-connections/internalEtcd-f0aa33fb-60ee-4a72-9870-877b5271560e.nmconnection
[ 4.627923] configure-ovs.sh[1507]: internalEtcd:d3f49293-91cb-41bf-833e-f75f67468ed1:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/7:no:::::/etc/NetworkManager/system-connections/internalEtcd-d3f49293-91cb-41bf-833e-f75f67468ed1.nmconnection
[ 4.627983] configure-ovs.sh[1507]: internalEtcd:5c13b671-4a12-41d3-8baf-47cff7350421:dummy:0:never:yes:0:no:/org/freedesktop/NetworkManager/Settings/8:no:::::/etc/NetworkManager/system-connections/internalEtcd-5c13b671-4a12-41d3-8baf-47cff7350421.nmconnection
[ 4.628102] configure-ovs.sh[1395]: + ip -d address show
[ 4.628948] configure-ovs.sh[1511]: 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
[ 4.629001] configure-ovs.sh[1511]: link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00 promiscuity 0 minmtu 0 maxmtu 0 numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535
[ 4.629048] configure-ovs.sh[1511]: inet 127.0.0.1/8 scope host lo
[ 4.629099] configure-ovs.sh[1511]: valid_lft forever preferred_lft forever
[ 4.629201] configure-ovs.sh[1511]: inet6 ::1/128 scope host
[ 4.629246] configure-ovs.sh[1511]: valid_lft forever preferred_lft forever
[ 4.629295] configure-ovs.sh[1511]: 2: ovs-system: <BROADCAST,MULTICAST> mtu 1500 qdisc noop state DOWN group default qlen 1000
[ 4.629344] configure-ovs.sh[1511]: link/ether a6:f1:9e:80:9f:a3 brd ff:ff:ff:ff:ff:ff promiscuity 1 minmtu 68 maxmtu 65535
[ 4.629389] configure-ovs.sh[1511]: openvswitch numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535
[ 4.629434] configure-ovs.sh[1511]: 3: tun0: <BROADCAST,MULTICAST> mtu 1400 qdisc noop state DOWN group default qlen 1000
[ 4.629479] configure-ovs.sh[1511]: link/ether 7e:e3:75:47:c5:74 brd ff:ff:ff:ff:ff:ff promiscuity 1 minmtu 68 maxmtu 65535
[ 4.629525] configure-ovs.sh[1511]: openvswitch numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535
[ 4.629570] configure-ovs.sh[1511]: 4: vxlan_sys_4789: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 65000 qdisc noqueue master ovs-system state UNKNOWN group default qlen 1000
[ 4.629615] configure-ovs.sh[1511]: link/ether 1e:a1:f0:ae:c4:8a brd ff:ff:ff:ff:ff:ff promiscuity 1 minmtu 68 maxmtu 65535
[ 4.629663] configure-ovs.sh[1511]: vxlan external id 0 srcport 0 0 dstport 4789 nolearning ttl auto ageing 300 udpcsum noudp6zerocsumtx udp6zerocsumrx
[ 4.629709] configure-ovs.sh[1511]: openvswitch_slave numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535
[ 4.629753] configure-ovs.sh[1511]: inet6 fe80::1ca1:f0ff:feae:c48a/64 scope link tentative
[ 4.629797] configure-ovs.sh[1511]: valid_lft forever preferred_lft forever
[ 4.629840] configure-ovs.sh[1511]: 5: br0: <BROADCAST,MULTICAST> mtu 1400 qdisc noop state DOWN group default qlen 1000
[ 4.629885] configure-ovs.sh[1511]: link/ether ba:5c:64:c8:f1:4d brd ff:ff:ff:ff:ff:ff promiscuity 1 minmtu 68 maxmtu 65535
[ 4.629929] configure-ovs.sh[1511]: openvswitch numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535
[ 4.629968] configure-ovs.sh[1511]: 6: eth10: <BROADCAST,NOARP,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default qlen 1000
[ 4.630020] configure-ovs.sh[1511]: link/ether 46:9a:8a:ea:ad:69 brd ff:ff:ff:ff:ff:ff promiscuity 0 minmtu 0 maxmtu 0
[ 4.630058] configure-ovs.sh[1511]: dummy numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535
[ 4.630102] configure-ovs.sh[1511]: inet 192.168.126.11/24 brd 192.168.126.255 scope global noprefixroute eth10
[ 4.630150] configure-ovs.sh[1511]: valid_lft forever preferred_lft forever
[ 4.630229] configure-ovs.sh[1395]: + ip route show
[ 4.630290] configure-ovs.sh[1512]: 192.168.126.0/24 dev eth10 proto kernel scope link src 192.168.126.11 metric 550
[ 4.630334] configure-ovs.sh[1395]: + ip -6 route show
[ 4.630956] configure-ovs.sh[1513]: ::1 dev lo proto kernel metric 256 pref medium
[ 4.631004] configure-ovs.sh[1513]: fe80::/64 dev vxlan_sys_4789 proto kernel metric 256 pref medium
[ 4.631046] configure-ovs.sh[1395]: + exit 0
[ OK ] Started Configures OVS with proper host networking configuration.
Starting Wait for a non-localhost hostname...
[ OK ] Started Wait for a non-localhost hostname.
[ OK ] Reached target Network is Online.
Starting Dynamically sets the system reserved for the kubelet...
Starting NFS status monitor for NFSv2/3 locking....
Starting Podman container-4a4530a0a…223b65e55f30cf0d4f8a08c.service...
[ OK ] Started Dynamically sets the system reserved for the kubelet.
Starting Container Runtime Interface for OCI (CRI-O)...
Starting RPC Bind...
[ OK ] Started RPC Bind.
[ OK ] Started NFS status monitor for NFSv2/3 locking..
[ OK ] Created slice machine.slice.
[ OK ] Started libcontainer container 4a45…742bd35c59223b65e55f30cf0d4f8a08c.
[ 5.258546] cgroup: cgroup: disabling cgroup2 socket matching due to net_prio or net_cls activation
[ OK ] Started Podman container-4a4530a0a8…59223b65e55f30cf0d4f8a08c.service.At this point the machine appears to be dead.
The vfkit.log has not progressed beyond the last entry above.
However, my machine is still listening on 6443 and 2222... Is that the crc daemon?
netstat -an
tcp4 0 0 127.0.0.1.6443 *.* LISTEN
tcp4 0 0 127.0.0.1.2222 *.* LISTEN ps -ef | grep -i crc
501 637 1 0 7:38AM ?? 0:59.86 ~/.crc/bin/crc daemon --log-level=debug
501 3742 792 0 9:06AM ttys000 0:00.00 grep -i crcssh core@127.0.0.1 -p 2222 -i ${SSH_KEY} "journalctl -f"
kex_exchange_identification: read: Connection reset by peer
Connection reset by 127.0.0.1 port 2222OK. Here's one way to reproduce it:
crc delete crc startAfter it starts:
eval $(crc podman-env) podman imagesResult:
Cannot connect to Podman. Please verify your connection to the Linux system using `podman system connection list`, or try `podman machine init` and `podman machine start` to manage a new Linux VM Error: unable to connect to Podman. failed to create sshClient: Connection to bastion host (ssh://core@127.0.0.1:2222/run/user/1000/podman/podman.sock) failed.: ssh: handshake failed: EOF
I've tried this on a macbook pro M1 Pro/Max, and I could run podman images a dozen times without any issues. I'll let the VM run for a bit and try again later.
cgruver
commented
2 years ago Yeah, it's not always immediate.
I was able to login to the local registry, and run several oc commands. Then, after sitting idle for just a couple of minutes, it died again.
I had done a clean restart before the test, so I was able to start it again.
cfergeau
commented
2 years ago To be sure, can you also double check that the cached disk image you use is not corrupted:
% shasum -a 256 ~/.crc/cache/crc_vfkit_4.11.1_arm64/crc.img
1d2ecc66a3d9a947cc49fae169060b36079f00c34233d4645011bff360fa4902 /Users/teuf/.crc/cache/crc_vfkit_4.11.1_arm64/crc.imgIt looks OK.
1d2ecc66a3d9a947cc49fae169060b36079f00c34233d4645011bff360fa4902
cfergeau
commented
2 years ago Still no luck reproducing after running for 30 minutes :( Same macOS version as yours
cgruver
commented
2 years ago Weird... It may be an M2 thing...
Or, maybe I have something installed that is causing issues...
I might try a full reset of the MacBook and just install crc before all the rest of my dev stack.
cfergeau
commented
2 years ago Yeah, worried it's something m2 specific :-/ A 4.11.3 bundle with a newer kernel is about to be released, would be worth trying it to see if it's better
cgruver
commented
2 years ago I built the crc executable from the v2.9.0 tag and am testing with the 4.11.3 bundle.
So far, so good...
If things continue to look good, I'll close this tomorrow as resolved in release v2.9.0.
cfergeau
commented
2 years ago I built the crc executable from the v2.9.0 tag and am testing with the 4.11.3 bundle.
For completeness, would be great if you can test this same v2.9.0 executable with the 4.11.1 bundle. ./out/macos-arm64/crc setup -b ~/.crc/cache/crc_vfkit_4.11.1_amd64 && ./out/macos-arm64/crc start -b ~/.crc/cache/crc_vfkit_4.11.1_amd64 should let you do that.
gbraad
commented
2 years ago I was afraid to see the following statement:
Weird... It may be an M2 thing...
as I was expecting something similar. At the moment no access to an M2 within our team AFAIK.
cgruver
commented
2 years ago The 4.11.3 bundle with v2.9.0 of crc seems to be stable. I was able to deploy workloads, manipulate images with Podman, and restart the OpenShift instance several times.
I'll try running the 4.11.1 bundle as well.
cgruver
commented
2 years ago I built the crc executable from the v2.9.0 tag and am testing with the 4.11.3 bundle.
For completeness, would be great if you can test this same v2.9.0 executable with the 4.11.1 bundle.
./out/macos-arm64/crc setup -b ~/.crc/cache/crc_vfkit_4.11.1_amd64 && ./out/macos-arm64/crc start -b ~/.crc/cache/crc_vfkit_4.11.1_amd64should let you do that.
@cfergeau I ran the test with v2.9.0 and bundle 4.11.1. It died during an app build:
[ 573.517636] XFS (vda4): Metadata corruption detected at xfs_inode_buf_verify+0x164/0x180 [xfs], xfs_inode block 0x313c3c0 xfs_inode_buf_verify
[ 573.532825] XFS (vda4): Unmount and run xfs_repair
[ 573.532897] XFS (vda4): First 128 bytes of corrupted metadata buffer:
[ 573.533001] 00000000: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
[ 573.533180] 00000010: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
[ 573.533389] 00000020: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
[ 573.533485] 00000030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
[ 573.533642] 00000040: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
[ 573.533884] 00000050: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
[ 573.534079] 00000060: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
[ 573.534159] 00000070: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
[ 573.576605] XFS (vda4): Corruption of in-memory data (0x8) detected at _xfs_buf_ioapply+0x16c/0x174 [xfs] (fs/xfs/xfs_buf.c:1513). Shutting down filesystem
[ 573.576869] XFS (vda4): Please unmount the filesystem and rectify the problem(s)
[ 573.600822] overlayfs: failed to get metacopy (-5)
[ 573.600963] overlayfs: failed to get metacopy (-5)
[ 609.524135] Core dump to |/usr/lib/systemd/systemd-coredump pipe failed
[ 914.947565] Core dump to |/usr/lib/systemd/systemd-coredump pipe failedThis is a disk corruption this time, this is different from the initial issue you were seeing.
cgruver
commented
2 years ago I saw disk corruption periodically with v2.8.0 as well.
When it happens, you have to delete the VM. Otherwise, when it boots, it drops straight into the emergency shell.
cgruver
commented
2 years ago I'm going to keep running tests on the v2.9.0 + 4.11.3 instance.
If it remains stable, I'll close this after v2.9.0 officially drops.
cgruver
commented
2 years ago One more run with v2.9.0 and the older 4.11.1 bundle. Same test as before, deploy Quarkus app, different failure that looks like what I posted above. Sometimes kernel panic, sometimes filesystem corruption.
[ 1243.732694] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000000
[ 1243.732901] Mem abort info:
[ 1243.732915] ESR = 0x86000004
[ 1243.732944] EC = 0x21: IABT (current EL), IL = 32 bits
[ 1243.732994] SET = 0, FnV = 0
[ 1243.733026] EA = 0, S1PTW = 0
[ 1243.733059] FSC = 0x04: level 0 translation fault
[ 1243.733098] user pgtable: 4k pages, 48-bit VAs, pgdp=000000011fe8a000
[ 1243.733139] [0000000000000000] pgd=0000000000000000, p4d=0000000000000000
[ 1243.733211] Internal error: Oops: 86000004 [#1] SMP
[ 1243.733249] Modules linked in: xt_statistic nf_conntrack_netlink veth xt_nat xt_addrtype ipt_REJECT nf_reject_ipv4 xt_CT xt_MASQUERADE xt_conntrack xt_comment nft_counter xt_mark nft_compat nft_chain_nat nf_tables tun overlay dummy rfkill vxlan ip6_udp_tunnel udp_tunnel nfnetlink_cttimeout nfnetlink openvswitch nf_conncount nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ext4 mbcache jbd2 vmw_vsock_virtio_transport vmw_vsock_virtio_transport_common vsock ip_tables xfs libcrc32c crct10dif_ce virtio_blk virtiofs virtio_console ghash_ce sha2_ce sha256_arm64 sha1_ce dm_multipath dm_mirror dm_region_hash dm_log dm_mod be2iscsi cxgb4i cxgb4 tls libcxgbi libcxgb qla4xxx iscsi_boot_sysfs iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi ipmi_devintf ipmi_msghandler fuse
[ 1243.733653] CPU: 3 PID: 1055 Comm: systemd-logind Not tainted 5.14.0-70.22.1.el9_0.aarch64 #1
[ 1243.733704] pstate: 60400805 (nZCv daif +PAN -UAO -TCO BTYPE=-c)
[ 1243.733737] pc : 0x0
[ 1243.733755] lr : seccomp_run_filters+0x94/0x160
[ 1243.733823] sp : ffff800013923cf0
[ 1243.733859] x29: ffff800013923cf0 x28: ffff0000c7b42880 x27: 0000000000000000
[ 1243.733905] x26: 0000000000000000 x25: 0000000000000000 x24: ffff800013923d80
[ 1243.733952] x23: 000000007fff0000 x22: ffff800013923db8 x21: ffff80001321d000
[ 1243.733998] x20: ffff0000c4e79c00 x19: 000000007fff0000 x18: 0000000000000000
[ 1243.734045] x17: 0000000000000000 x16: 0000000000000000 x15: 0000000000000000
[ 1243.734081] x14: 0000000000000000 x13: 0000000000000000 x12: 0000000000000000
[ 1243.734113] x11: 0000000000000000 x10: 0000000040000028 x9 : ffff8000101b1b10
[ 1243.734163] x8 : 0000000000000000 x7 : 000000007fff0000 x6 : 0000000000000000
[ 1243.734197] x5 : 0000000000000038 x4 : 474f444843544157 x3 : 0000000000000001
[ 1243.734232] x2 : 0000000000000000 x1 : ffff80001321d048 x0 : ffff800013923db8
[ 1243.734275] Call trace:
[ 1243.734291] 0x0
[ 1243.734306] __seccomp_filter+0x2a4/0x4d0
[ 1243.734332] __secure_computing+0x44/0xc0
[ 1243.734358] syscall_trace_enter+0x160/0x1b0
[ 1243.734398] el0_svc_common.constprop.0+0x134/0x15c
[ 1243.734437] do_el0_svc+0x2c/0xb0
[ 1243.734464] el0_svc+0x28/0x90
[ 1243.734502] el0t_64_sync_handler+0x9c/0x120
[ 1243.734540] el0t_64_sync+0x168/0x16c
[ 1243.734566] Code: bad PC value
[ 1243.734598] ---[ end trace 03ff7d93c9ec0232 ]---
[ 1243.734629] Kernel panic - not syncing: Oops: Fatal exception
[ 1243.734668] SMP: stopping secondary CPUs
[ 1243.734716] Kernel Offset: disabled
[ 1243.734807] CPU features: 0x00000141,4b307ec0
[ 1243.734840] Memory Limit: none
[ 1243.734878] Rebooting in 10 seconds..FWIW, v2.9.0 + 4.11.3 still looks good.
cfergeau
commented
2 years ago I'll take a look at the changes between the linux kernels in the 2 versions, maybe there will be something obvious in there.
cgruver
commented
2 years ago Appears to be resolved with release of version v2.9.0 and bundle 4.11.3.
I ran several tests, and restarted the cluster. It appears stable.
cgruver
commented
2 years ago Reopening this case.
It's definitely running longer than the previous version. But it's still hitting the filesystem corruption issue.
I don't know what activity was happening in the cluster, it had been idle for a while. I'll try to catch the activity when this happens.
[ 890.168507] Pid 49086(systemd-cgroups) over core_pipe_limit
[ 890.184094] Skipping core dump
[ 890.226495] Pid 49092(systemd-cgroups) over core_pipe_limit
[ 890.238972] Skipping core dump
[ 890.241946] Pid 49093(systemd-cgroups) over core_pipe_limit
[ 890.255879] Skipping core dump
[ 890.478206] device vethecb59c75 left promiscuous mode
[ 900.314991] Pid 49930(systemd-tmpfile) over core_pipe_limit
[ 900.315295] Skipping core dump
[ 900.322677] Pid 49933(systemd-cgroups) over core_pipe_limit
[ 900.322800] Skipping core dump
[ 922.332751] Pid 51735(systemd-cgroups) over core_pipe_limit
[ 922.336283] Skipping core dump
[ 1039.559021] Pid 60685(systemd-cgroups) over core_pipe_limit
[ 1039.560067] Skipping core dump
[ 1039.564570] Pid 60694(systemd-cgroups) over core_pipe_limit
[ 1039.564706] Skipping core dump
[ 1085.489138] XFS (vda4): xfs_iflush: Bad inode 62955559 magic number 0x0, ptr 00000000bd310a27
[ 1085.490072] XFS (vda4): metadata I/O error in "xfs_buf_ioend_handle_error+0x100/0x400 [xfs]" at daddr 0x3124020 len 32 error 5
[ 1085.507323] XFS (vda4): Corruption of in-memory data (0x8) detected at xfs_iflush_cluster+0x32c/0x3ac [xfs] (fs/xfs/xfs_inode.c:3634). Shutting down filesystem
[ 1085.507679] XFS (vda4): Please unmount the filesystem and rectify the problem(s)
[ 1085.509418] vda4: writeback error on inode 12751640, offset 23212032, sector 12070232
[ 1085.510756] vda4: writeback error on inode 12751640, offset 40599552, sector 12104192
[ 2240.837807] Core dump to |/usr/lib/systemd/systemd-coredump pipe failedthe filesystem corruption issue.
filesystem corruption happens due to an unexpected shutdown. this feels like a coredump/kernel panic happened...
cgruver
commented
2 years ago Yes it does.
I'm going to compare the crc that I built locally from https://github.com/code-ready/crc/tree/v2.9.0 to the release. When I built it from code, it seemed pretty stable.
I also have cleaned up my machine to make sure that there were no residual libraries or configurations from previous installations.
I'll let you know.
cgruver
commented
2 years ago There must be some race condition somewhere. Sometimes it will run for hours, and even shutdown and start back up successfully. Other times it fails during startup.
So, I was apparently led into a false sense of stability last week.
This failure occurred during startup of a previously shutdown cluster. This is using the crc that I built from source.
The cluster appeared to successfully restart. But, immediately panicked.
INFO 2 operators are not available: authentication, openshift-apiserver
INFO 2 operators are not available: authentication, openshift-apiserver
INFO 2 operators are not available: authentication, openshift-apiserver
INFO 2 operators are not available: authentication, openshift-apiserver
INFO Operator authentication is not yet available
INFO All operators are available. Ensuring stability...
INFO Operators are stable (2/3)...
INFO Operators are stable (3/3)...
INFO Adding crc-admin and crc-developer contexts to kubeconfig...
Started the OpenShift cluster.
...vfkit.log
[ 489.204426] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000008
[ 489.218768] Mem abort info:
[ 489.218796] ESR = 0x96000047
[ 489.218844] EC = 0x25: DABT (current EL), IL = 32 bits
[ 489.218910] SET = 0, FnV = 0
[ 489.218971] EA = 0, S1PTW = 0
[ 489.219023] FSC = 0x07: level 3 translation fault
[ 489.219051] Data abort info:
[ 489.219421] ISV = 0, ISS = 0x00000047
[ 489.219453] CM = 0, WnR = 1
[ 489.219481] user pgtable: 4k pages, 48-bit VAs, pgdp=000000024c1d3000
[ 489.219536] [0000000000000008] pgd=08000002f00f1003, p4d=08000002f00f1003, pud=08000001f7817003, pmd=080000025c1d0003, pte=0000000000000000
[ 489.219663] Internal error: Oops: 96000047 [#1] SMP
[ 489.219711] Modules linked in: veth nf_conntrack_netlink xt_nat xt_addrtype ipt_REJECT nf_reject_ipv4 xt_CT xt_MASQUERADE xt_conntrack xt_comment nft_counter xt_mark nft_compat tun nft_chain_nat nf_tables overlay dummy rfkill vxlan ip6_udp_tunnel udp_tunnel nfnetlink_cttimeout nfnetlink openvswitch nf_conncount nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ext4 mbcache jbd2 vmw_vsock_virtio_transport vmw_vsock_virtio_transport_common vsock ip_tables xfs libcrc32c crct10dif_ce ghash_ce sha2_ce sha256_arm64 virtio_console sha1_ce virtiofs virtio_blk dm_multipath dm_mirror dm_region_hash dm_log dm_mod be2iscsi cxgb4i cxgb4 tls libcxgbi libcxgb qla4xxx iscsi_boot_sysfs iscsi_tcp libiscsi_tcp libiscsi ipmi_devintf ipmi_msghandler fuse scsi_transport_iscsi
[ 489.220122] CPU: 0 PID: 6406 Comm: kworker/0:42 Not tainted 5.14.0-70.22.1.el9_0.aarch64 #1
[ 489.220176] Workqueue: cgroup_destroy css_killed_work_fn
[ 489.220254] pstate: a04000c5 (NzCv daIF +PAN -UAO -TCO BTYPE=--)
[ 489.220307] pc : memcg_drain_all_list_lrus+0x114/0x2f0
[ 489.220379] lr : memcg_drain_all_list_lrus+0x34/0x2f0
[ 489.220432] sp : ffff800015da3c60
[ 489.220465] x29: ffff800015da3c60 x28: 0000000000000001 x27: ffff0000d2363000
[ 489.220508] x26: ffff0000c795dca0 x25: 0000000000000000 x24: ffff000224c00248
[ 489.220569] x23: ffff800011920b20 x22: ffff800011d36cb8 x21: 0000000000000000
[ 489.220636] x20: ffff0000c9637180 x19: ffff0000c2559b00 x18: 0000000000000000
[ 489.220684] x17: 0000000000000000 x16: 0000000000000000 x15: 0000000000000000
[ 489.220735] x14: 0000000000000000 x13: 0000000000000030 x12: 0101010101010101
[ 489.220787] x11: 7f7f7f7f7f7f7f7f x10: feff786e71737264 x9 : ffff800010b8f1c4
[ 489.220839] x8 : fefefefefefefeff x7 : 000000000000000f x6 : ffff0001ea267e74
[ 489.220890] x5 : 0000000000000000 x4 : 0000000000000000 x3 : 0000000000000000
[ 489.220942] x2 : ffff0000c9637b80 x1 : 0000000000000000 x0 : 0000000000000000
[ 489.220996] Call trace:
[ 489.221018] memcg_drain_all_list_lrus+0x114/0x2f0
[ 489.221052] memcg_offline_kmem.part.0+0x150/0x180
[ 489.221100] mem_cgroup_css_offline+0xe0/0x130
[ 489.221138] css_killed_work_fn+0x5c/0x160
[ 489.221163] process_one_work+0x1ec/0x4b0
[ 489.221200] worker_thread+0x180/0x540
[ 489.221225] kthread+0x134/0x140
[ 489.221256] ret_from_fork+0x10/0x18
[ 489.221286] Code: eb00029f 54000120 a9400684 f9400040 (f9000482)
[ 489.221339] ---[ end trace 41a5fe29ee905cb9 ]---
[ 489.221379] Kernel panic - not syncing: Oops: Fatal exception
[ 489.221433] SMP: stopping secondary CPUs
[ 489.221498] Kernel Offset: disabled
[ 489.221672] CPU features: 0x00000141,4b307ec0
[ 489.221729] Memory Limit: none
[ 489.221790] Rebooting in 10 seconds..I'm attaching the full vfkit.log. The machine appears to reboot, but something kills it.
It's interesting to note that after this particular failure, the cluster did come up after crc start. So, in this case, the filesystem was not corrupted.
gbraad
commented
2 years ago When I built it from code, it seemed pretty stable.
That should not matter (for crc unless you do a full rebuild). The VM runs with a driver based on vfkit+vz. This is independent of the crc management tool. If a panic happens, this is in the Virtualization driver maintained by another codebase.
gbraad
commented
2 years ago Have asked @anjannath to also run extended tests, though he has an M1.
anjannath
commented
2 years ago I ran crc 2.9.0 for quite some time (6hrs+) on the M1, in this time, i did several start stop, and the cluster had a ruby sample application running, i did not experience any crash though the cluster woukd jump around from Running to Starting then Unreachable then running again, the console route would stop working and oc commands fail with error 500 or some TLS handshake error after some time
It'd become responsive and working again after multiple retries :/
gbraad
commented
2 years ago We need to find someone else with an M2.
cgruver
commented
2 years ago @anjannath Did you take a look at the vfkit.log to see if the VM had rebooted during the times that crc status showed the cluster as Starting or Unreachable?
@gbraad If there is any info I can capture for you guys, let me know.
gbraad
commented
2 years ago Perhaps set up a call. At the moment I can only suggest to monitor. Have to look for someone else to repro this on an M2 or otherwise obtain one.
cgruver
commented
2 years ago FWIW: Anecdotal Observations
It seems that once I get past the initial start, shutdown, start without filesystem corruption... Then the cluster is relatively stable.
It will periodically kernel panic, but will restart successfully. Something stops the VM after it reboots, so I have to restart it manually. But, it does restart and run for a while.
The kernel panic does not seem to be associated with any user load or activity. It seems to happen even when "idle".
I am able to run some pretty significant load, Cassandra Cluster, and Quarkus apps.
anjannath
commented
2 years ago @anjannath Did you take a look at the
vfkit.logto see if the VM had rebooted during the times thatcrc statusshowed the cluster as Starting or Unreachable?
yeah, there weren't any reboots.. vfkit.log
cgruver
commented
2 years ago New data point:
VM is stuck with the following repeating in vfkit.log
[ 1524.841747] audit: audit_backlog=8193 > audit_backlog_limit=8192
[ 1524.855777] audit: audit_lost=1 audit_rate_limit=0 audit_backlog_limit=8192
[ 1524.855925] audit: backlog limit exceeded
[ 1528.836278] audit: audit_backlog=8193 > audit_backlog_limit=8192
[ 1528.845855] audit: audit_lost=2 audit_rate_limit=0 audit_backlog_limit=8192
[ 1528.845913] audit: backlog limit exceededAdditional Data point:
I managed to gain some stability, i.e. haven't seen a kernel panic yet... by increasing the value of the audit buffers in /etc/audit/rules.d/audit.rules
## First rule - delete all
-D
## Increase the buffers to survive stress events.
## Make this bigger for busy systems
-b 16384
## This determine how long to wait in burst of events
--backlog_wait_time 60000
## Set failure mode to syslog
-f 1To implement this workaround, execute the following as soon as the crc VM boots for the first time. No need to repeat on crc stop, crc start. Only after a crc delete or the first boot of a new instance.
export SSH_KEY=${HOME}/.crc/machines/crc/id_ecdsa
ssh -i ${SSH_KEY} -p 2222 core@127.0.0.1 'sudo auditctl -b 16384'
ssh -i ${SSH_KEY} -p 2222 core@127.0.0.1 'sudo sed -i "s|-b 8192|-b 16384|g" /etc/audit/rules.d/audit.rules'So far, the above work-around has proven to be pretty stable. I have a cluster running the K8ssandra operator with a single node Cassandra cluster and Stargate. I've stopped are restarted the cluster a few times over that last couple of days. So far, so good.
I don't know that the work-around is a "fix" as much as it is masking the underlying issue, but we'll see.
Cheers
Update: Just had a kernel panic that resulted in a corrupted filesystem. This is definitely not a fix, but it does buy some stability.
cgruver
commented
2 years ago Update: @anjannath I may have found a hit.
I disabled selinux, and got a new failure that got a hit on google: (It's for a newer kernel version, but might be relevant)
https://lkml.org/lkml/2022/3/14/2
https://lists.nongnu.org/archive/html/qemu-devel/2022-02/msg01973.html
Note: There is also a weird correlation that the failures happen predictably if I have VS Code running. It is very stable without VS Code running. That's likely due to the additional load on the system and not specifically anything to do with VS Code.
[ 169.433916] kernel BUG at arch/arm64/kernel/traps.c:498!
[ 169.433970] Internal error: Oops - BUG: 0 [#1] SMP
[ 169.434025] Modules linked in: veth nf_conntrack_netlink xt_nat xt_addrtype ipt_REJECT nf_reject_ipv4 xt_CT xt_MASQUERADE xt_conntrack xt_comment nft_counter xt_mark nft_compat tun nft_chain_nat nf_tables overlay dummy rfkill vxlan ip6_udp_tunnel udp_tunnel nfnetlink_cttimeout nfnetlink openvswitch nf_conncount nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ext4 mbcache jbd2 vmw_vsock_virtio_transport vmw_vsock_virtio_transport_common vsock ip_tables xfs libcrc32c virtio_console virtiofs virtio_blk crct10dif_ce ghash_ce sha2_ce sha256_arm64 sha1_ce dm_multipath dm_mirror dm_region_hash dm_log dm_mod be2iscsi cxgb4i cxgb4 tls libcxgbi libcxgb qla4xxx iscsi_boot_sysfs iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi ipmi_devintf ipmi_msghandler fuse
[ 169.434795] CPU: 2 PID: 1580 Comm: vm Not tainted 5.14.0-70.22.1.el9_0.aarch64 #1
[ 169.434859] pstate: 00400005 (nzcv daif +PAN -UAO -TCO BTYPE=--)
[ 169.434895] pc : do_undefinstr+0x64/0x70
[ 169.434956] lr : do_undefinstr+0x34/0x70
[ 169.434980] sp : ffff800013283a00
[ 169.435000] x29: ffff800013283a00 x28: ffff0000c05f9440 x27: 0000000000000000
[ 169.435070] x26: 0000000000000000 x25: 0000000000000000 x24: 0000000000000000
[ 169.435118] x23: 0000000060400005 x22: ffff800008fc0950 x21: ffff800013283ba0
[ 169.435159] x20: ffff800013283c98 x19: ffff800013283a50 x18: 0000000000000000
[ 169.435205] x17: 0000000000000000 x16: 0000000000000000 x15: 0000000000000000
[ 169.435279] x14: 0000000000000000 x13: 0000000000000000 x12: 0000000000000000
[ 169.435332] x11: 0000000000000000 x10: 0000000000000000 x9 : ffff8000102947f8
[ 169.435379] x8 : ffff800013283bf8 x7 : 0000000000000001 x6 : 0000000000000000
[ 169.435431] x5 : ffff80001193c178 x4 : 00000000d503403f x3 : 0000000000000000
[ 169.435480] x2 : 0000000000000000 x1 : ffff0000c05f9440 x0 : 0000000060400005
[ 169.435544] Call trace:
[ 169.435569] do_undefinstr+0x64/0x70
[ 169.435592] el1_undef+0x5c/0xbc
[ 169.435637] el1h_64_sync_handler+0x80/0xc0
[ 169.435661] el1h_64_sync+0x78/0x7c
[ 169.435682] vsock_addr_bound+0x0/0x20 [vsock]
[ 169.435746] sock_sendmsg+0x54/0x60
[ 169.435790] sock_write_iter+0x9c/0x100
[ 169.435813] new_sync_write+0x174/0x184
[ 169.435841] vfs_write+0x214/0x2ac
[ 169.435862] ksys_write+0xdc/0xf4
[ 169.435884] __arm64_sys_write+0x20/0x2c
[ 169.435903] invoke_syscall.constprop.0+0x54/0xe4
[ 169.435946] el0_svc_common.constprop.0+0x154/0x15c
[ 169.435981] do_el0_svc+0x2c/0xb0
[ 169.436001] el0_svc+0x28/0x90
[ 169.436022] el0t_64_sync_handler+0x9c/0x120
[ 169.436105] el0t_64_sync+0x168/0x16c
[ 169.436130] Code: 97ffffb3 f9400bf3 a8c27bfd d65f03c0 (d4210000)
[ 169.436179] ---[ end trace 8e9ce2300f44e704 ]---
[ 169.436196] Kernel panic - not syncing: Oops - BUG: Fatal exception
[ 169.436256] SMP: stopping secondary CPUs
[ 169.436329] Kernel Offset: disabled
[ 169.436395] CPU features: 0x00000141,4b307ec0
[ 169.436417] Memory Limit: none
[ 169.436431] Rebooting in 10 seconds..@anjannath Here's a bit more info.
After some experimentation with load, I believe that the issue is triggered by moderate memory pressure on the host system.
If you have a chance on your M1 system, try boosting the memory for crc to something higher than the default, and run an app or two that will consume memory on the Mac, not in crc. Load a GO project in VSCode with the GO language extension installed and enabled... that will use a LOT of RAM. ;-)
I discovered that the correlation between VSCode and the crc crash is due to the memory consumption of gopls. After disabling the GO extension in VSCode it is using a lot less memory.
My MacBook has 24GB of RAM.
I configured crc to use 16GB of RAM.
With gopls consuming 3+ GB of RAM, plus the other load on my MacBook, the system was under moderate memory pressure.
As mentioned, I disabled the GO extension. I also reconfigured crc with 12GB of RAM.
It is much more stable now.
cfergeau
commented
2 years ago The thread starting at https://github.com/Code-Hex/vz/pull/63#issuecomment-1275811980 and issue https://github.com/Code-Hex/vz/issues/13 hints at some potential memory corruption coming from Code-Hex/vz, this may be related to what you are seeing.
gbraad
commented
2 years ago @cfergeau I might question the maturity; we need additional tests to run on this, one of the complaints I had an reason to allow different workloads/enablement, such as minikube, etc. like a machine-driver.
cgruver
commented
2 years ago Since I reduced the RAM for crc down to 12GB from 16, I have not seen a crash. It's likely that I'm just avoiding a SIGSEGV with lots of empty RAM... but, at least it works for now. :-)
Turning off gopls helped to avoid memory pressure as well.
jdloft
commented
2 years ago I can reliably reproduce this on M1 Pro hardware with the 4.11.7 bundle (sha256 4f8f088fcfd709417865e034c3c5d0854510d0737ce8be4117679e6f7b011f0a).
[ 94.149471] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000008
[ 94.149652] Mem abort info:
[ 94.149690] ESR = 0x96000044
[ 94.149742] EC = 0x25: DABT (current EL), IL = 32 bits
[ 94.149830] SET = 0, FnV = 0
[ 94.149884] EA = 0, S1PTW = 0
[ 94.149927] FSC = 0x04: level 0 translation fault
[ 94.149980] Data abort info:
[ 94.150025] ISV = 0, ISS = 0x00000044
[ 94.150075] CM = 0, WnR = 1
[ 94.150116] user pgtable: 4k pages, 48-bit VAs, pgdp=000000010b6d8000
[ 94.150184] [0000000000000008] pgd=0000000000000000, p4d=0000000000000000
[ 94.150277] Internal error: Oops: 96000044 [#1] SMP
[ 94.150371] Modules linked in: nf_conntrack_netlink veth xt_nat xt_addrtype ipt_REJECT nf_reject_ipv4 xt_CT xt_MASQUERADE xt_conntrack xt_comment nft_counter xt_mark nft_compat nft_chain_nat nf_tables tun overlay dummy rfkill vxlan ip6_udp_tunnel udp_tunnel nfnetlink_cttimeout nfnetlink openvswitch nf_conncount nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ext4 mbcache jbd2 vmw_vsock_virtio_transport vmw_vsock_virtio_transport_common vsock ip_tables xfs libcrc32c crct10dif_ce ghash_ce sha2_ce sha256_arm64 sha1_ce virtio_blk virtio_console dm_multipath dm_mirror dm_region_hash dm_log dm_mod be2iscsi cxgb4i cxgb4 tls libcxgbi libcxgb qla4xxx iscsi_boot_sysfs iscsi_tcp libiscsi_tcp libiscsi ipmi_devintf ipmi_msghandler fuse scsi_transport_iscsi
[ 94.151087] CPU: 2 PID: 3267 Comm: kworker/2:3 Not tainted 5.14.0-70.26.1.el9_0.aarch64 #1
[ 94.151149] Workqueue: cgroup_destroy css_killed_work_fn
[ 94.151279] pstate: a04000c5 (NzCv daIF +PAN -UAO -TCO BTYPE=--)
[ 94.151336] pc : memcg_drain_all_list_lrus+0x114/0x2f0
[ 94.151427] lr : memcg_drain_all_list_lrus+0x1d0/0x2f0
[ 94.151472] sp : ffff8000111e3c60
[ 94.151506] x29: ffff8000111e3c60 x28: 0000000000000001 x27: ffff3c5205b5b000
[ 94.151579] x26: ffff3c5200b93ca0 x25: 0000000000000000 x24: ffff3c537d604000
[ 94.151653] x23: ffffcb5d16120b20 x22: ffffcb5d16536cb8 x21: 0000000000000000
[ 94.151718] x20: ffff3c521028a400 x19: ffff3c52024a7700 x18: 0000000000000000
[ 94.151800] x17: 0000000000000000 x16: 0000000000000000 x15: 0000aaaaf13c7760
[ 94.151886] x14: 0000000000000000 x13: 0000000000000030 x12: 0101010101010101
[ 94.151957] x11: 7f7f7f7f7f7f7f7f x10: feff786e71737264 x9 : ffffcb5d14acd9d0
[ 94.152027] x8 : fefefefefefefeff x7 : 000000000000000f x6 : ffff3c5218a99574
[ 94.152085] x5 : 00000000000006ec x4 : 0000000000000000 x3 : 0000000000000000
[ 94.152144] x2 : ffff3c52077df280 x1 : 0000000000000000 x0 : ffff3c52077df280
[ 94.152219] Call trace:
[ 94.152237] memcg_drain_all_list_lrus+0x114/0x2f0
[ 94.152275] memcg_offline_kmem.part.0+0x150/0x180
[ 94.152329] mem_cgroup_css_offline+0xe0/0x130
[ 94.152371] css_killed_work_fn+0x5c/0x160
[ 94.152409] process_one_work+0x1ec/0x4b0
[ 94.152472] worker_thread+0x180/0x540
[ 94.152519] kthread+0x134/0x140
[ 94.152565] ret_from_fork+0x10/0x18
[ 94.152623] Code: eb00029f 54000120 a9400684 f9400040 (f9000482)Followed by
[ 1.940125] SGI XFS with ACLs, security attributes, scrub, quota, no debug enabled
[ 1.943840] XFS (vda4): Mounting V5 Filesystem
[ 1.990687] XFS (vda4): Starting recovery (logdev: internal)
[ 2.045640] XFS (vda4): Metadata corruption detected at xfs_dir3_leaf_check_int+0xdc/0x120 [xfs], xfs_dir3_leaf1 block 0x19e948
[ 2.045752] XFS (vda4): Unmount and run xfs_repair
[ 2.045781] XFS (vda4): First 128 bytes of corrupted metadata buffer:
[ 2.045816] 00000000: 00 00 00 00 00 00 00 00 3d f1 00 00 a3 60 bc a9 ........=....`..
[ 2.045851] 00000010: 00 00 00 00 00 19 e9 48 00 00 00 2a 00 00 1a bc .......H...*....
[ 2.045888] 00000020: 91 06 78 ff f7 7e 4a 7d 8d 53 86 f2 ac 47 a8 23 ..x..~J}.S...G.#
[ 2.045920] 00000030: 00 00 00 00 00 16 ff c9 01 4b 00 56 00 00 00 00 .........K.V....
[ 2.045964] 00000040: 00 00 00 2e 00 00 00 08 00 00 17 2e 00 00 00 0a ................
[ 2.045997] 00000050: 00 44 99 b8 00 00 04 9e 01 5e c2 2b 00 00 04 da .D.......^.+....
[ 2.046035] 00000060: 01 e2 f6 e0 00 00 01 92 02 0d 99 42 00 00 01 47 ...........B...G
[ 2.046077] 00000070: 02 98 c6 47 00 00 03 52 05 2d d9 6a 00 00 01 33 ...G...R.-.j...3
[ 2.046111] XFS (vda4): Corruption of in-memory data (0x8) detected at _xfs_buf_ioapply+0x16c/0x174 [xfs] (fs/xfs/xfs_buf.c:1513). Shutting down filesystem
[ 2.046203] XFS (vda4): Please unmount the filesystem and rectify the problem(s)
[ 2.046434] XFS (vda4): log mount/recovery failed: error -117
[ 2.046514] XFS (vda4): log mount failed
[ 2.055505] mount[556]: mount: /sysroot: mount(2) system call failed: Structure needs cleaning.
[ 2.055605] systemd[1]: sysroot.mount: Mount process exited, code=exited status=32
[ 2.055664] systemd[1]: sysroot.mount: Failed with result 'exit-code'.
[ 2.055719] s[FAILED] Failed to mount /sysroot.ystemd[1]: Faile
d to mount /sysroot.@cfergeau I might question the maturity; we need additional tests to run on this, one of the complaints I had an reason to allow different workloads/enablement, such as minikube, etc. like a machine-driver.
VMware Fusion just hit stable release for this hardware. Would be awesome if that was supported.
cfergeau
commented
2 years ago I can reliably reproduce this
Any specific steps you are taking? how long does it take before happening? What macOS version are you running?
CRC will run on my MacBook Air M2, but it is not stable.
It will often fail to start a fresh instance, and does not seem to be able to ever restart a stopped instance.
Upon investigation of logs, it looks like something causes a kernel panic that results in the VM rebooting.
Even when OpenShift is running, the VM will eventually stop accepting ssh connections, which results in Podman not working.
The output is:
Take a look at the log info below, and let me know what other info I can capture.
General information
CRC version
CRC config
Host Operating System
Logs Captured from .crc/machines/crc/vfkit.log
Logs Captured from
journalctl -fin SSH Session