auto-login-action: Wait for prompt ['Starting systemd-udevd version \\d+(\\.\\d+)*(-\\S+)*'] (timeout 00:15:00) [2J[01;01H[=3h[2J[01;01H[2J[01;01H[=3h[2J[01;01H[2J[01;01H[=3h[2J[01;01HBdsDxe: failed to load Boot0001 "UEFI QEMU HARDDISK QM00001 " from PciRoot(0x0)/Pci(0x1F,0x2)/Sata(0x0,0xFFFF,0x0): Not Found BdsDxe: loading Boot0002 "UEFI QEMU HARDDISK QM00011 " from PciRoot(0x0)/Pci(0x1F,0x2)/Sata(0x5,0xFFFF,0x0) BdsDxe: starting Boot0002 "UEFI QEMU HARDDISK QM00011 " from PciRoot(0x0)/Pci(0x1F,0x2)/Sata(0x5,0xFFFF,0x0) [2J[01;01H[0m[36m[40mEFI Boot Guard v0.16 [0m[37m[40mBoot medium: PciRoot(0)/Pci(0x1F,0x2)/Sata(0x5,0xFFFF,0x0) Found 3 handles for file IO Volume 0: (On boot medium) PciRoot(0)/Pci(0x1F,0x2)/Sata(0x5,0xFFFF,0x0)/HD(1,GPT,D1360F76-B09A-4BCC-B923-8195088CBE02), LABEL=efi, CLABEL=(null) Volume 1: (On boot medium) PciRoot(0)/Pci(0x1F,0x2)/Sata(0x5,0xFFFF,0x0)/HD(2,GPT,F870258B-706F-4A66-8D58-B5A75CE61B8B), LABEL=BOOT0, CLABEL=BOOT0 Volume 2: (On boot medium) PciRoot(0)/Pci(0x1F,0x2)/Sata(0x5,0xFFFF,0x0)/HD(3,GPT,6E41F2A7-E3EB-403F-8637-B111E4482EE9), LABEL=BOOT1, CLABEL=BOOT1 Loading configuration... Config file found on volume 1. Config file found on volume 2. 2 config partitions detected. Config filter: Booting with environments from boot medium only. Config Revision: 2: ustate: 0 kernel: C:BOOT0:linux.efi args: timeout: 0 seconds Full path for kernel is: PciRoot(0)/Pci(0x1F,0x2)/Sata(0x5,0xFFFF,0x0)/HD(2,GPT,F870258B-706F-4A66-8D58-B5A75CE61B8B)/linux.efi [1m[33m[40mWARNING: [0m[37m[40mWatchdog is disabled. LoaderDevicePartUUID=D1360F76-B09A-4BCC-B923-8195088CBE02 Starting C:BOOT0:linux.efi with watchdog set to 0 seconds ... Unified kernel stub (EFI Boot Guard v0.16) EFI stub: Loaded initrd from LINUX_EFI_INITRD_MEDIA_GUID device path EFI stub: Measured initrd data into PCR 9 [ 2.827525] ima: Can not allocate sha384 (reason: -2) [ 2.839054] ima: Can not allocate sha512 (reason: -2) Loading, please wait... start: 2.2.1 login-action (timeout 00:14:45) [common] The string 'root@device-mgmt' does not look like a typical prompt and could match status messages instead. Please check the job log files and use a prompt string which matches the actual prompt string more closely. Setting prompt string to [] Using line separator: #'\n'# Waiting for the login prompt Parsing kernel messages root@device-mgmt,device-mgmt login:,Login incorrect [login-action] Waiting for messages, (timeout 00:14:45) Waiting using forced prompt support (timeout 00:07:22) Starting systemd-udevd version 252.30-1~deb12u2 Begin: Loading essential drivers ... done. Begin: Running /scripts/init-premount ... done. Begin: Mounting root file system ... Begin: Running /scripts/local-top ... Device /dev/sdb4 is not a valid LUKS device. Begin: Encryption of /dev/sdb4 ... [2K Progress: 3.2%, ETA 00m53s, 32 MiB written, speed 18.6 MiB/s[2K Progress: 6.3%, ETA 00m35s, 64 MiB written, speed 26.9 MiB/s[2K Progress: 9.5%, ETA 00m29s, 96 MiB written, speed 31.7 MiB/s[2K Progress: 12.7%, ETA 00m26s, 128 MiB written, speed 33.8 MiB/s[2K Progress: 15.9%, ETA 00m24s, 160 MiB written, speed 35.9 MiB/s[2K Progress: 19.0%, ETA 00m22s, 192 MiB written, speed 36.9 MiB/s[2K Progress: 22.2%, ETA 00m20s, 224 MiB written, speed 38.2 MiB/s[2K Progress: 25.4%, ETA 00m20s, 256 MiB written, speed 38.4 MiB/s[2K Progress: 28.6%, ETA 00m18s, 288 MiB written, speed 39.0 MiB/s[2K Progress: 31.7%, ETA 00m17s, 320 MiB written, speed 39.4 MiB/s[2K Progress: 34.9%, ETA 00m17s, 352 MiB written, speed 39.1 MiB/s[2K Progress: 38.1%, ETA 00m16s, 384 MiB written, speed 39.4 MiB/s[2K Progress: 41.3%, ETA 00m15s, 416 MiB written, speed 39.5 MiB/s[2K Progress: 44.4%, ETA 00m14s, 448 MiB written, speed 39.6 MiB/s[2K Progress: 47.6%, ETA 00m13s, 480 MiB written, speed 39.9 MiB/s[2K Progress: 50.8%, ETA 00m12s, 512 MiB written, speed 39.7 MiB/s[2K Progress: 54.0%, ETA 00m12s, 544 MiB written, speed 39.8 MiB/s[2K Progress: 57.1%, ETA 00m11s, 576 MiB written, speed 40.0 MiB/s[2K Progress: 60.3%, ETA 00m10s, 608 MiB written, speed 40.0 MiB/s[2K Progress: 63.5%, ETA 00m09s, 640 MiB written, speed 40.1 MiB/s[2K Progress: 66.7%, ETA 00m08s, 672 MiB written, speed 40.2 MiB/s[2K Progress: 69.8%, ETA 00m07s, 704 MiB written, speed 40.2 MiB/s[2K Progress: 71.4%, ETA 00m07s, 720 MiB written, speed 39.9 MiB/s[2K Progress: 74.6%, ETA 00m06s, 752 MiB written, speed 40.2 MiB/s[2K Progress: 77.8%, ETA 00m05s, 784 MiB written, speed 40.2 MiB/s[2K Progress: 81.0%, ETA 00m05s, 816 MiB written, speed 40.2 MiB/s[2K Progress: 84.1%, ETA 00m04s, 848 MiB written, speed 40.0 MiB/s[2K Progress: 87.3%, ETA 00m03s, 880 MiB written, speed 40.0 MiB/s[2K Progress: 90.5%, ETA 00m02s, 912 MiB written, speed 40.0 MiB/s[2K Progress: 93.7%, ETA 00m02s, 944 MiB written, speed 39.9 MiB/s[2K Progress: 96.8%, ETA 00m01s, 976 MiB written, speed 39.8 MiB/s[2K Finished, time 00m24s, 1008 MiB written, speed 40.4 MiB/s New TPM2 token enrolled as key slot 1. done. Wiped slot 0. Device /dev/sdb5 is not a valid LUKS device. Begin: Encryption of /dev/sdb5 ... [2K Progress: 3.2%, ETA 00m50s, 32 MiB written, speed 19.8 MiB/s[2K Progress: 6.3%, ETA 00m33s, 64 MiB written, speed 28.4 MiB/s[2K Progress: 9.5%, ETA 00m28s, 96 MiB written, speed 32.5 MiB/s[2K Progress: 12.7%, ETA 00m26s, 128 MiB written, speed 34.2 MiB/s[2K Progress: 15.9%, ETA 00m24s, 160 MiB written, speed 34.7 MiB/s[2K Progress: 19.0%, ETA 00m23s, 192 MiB written, speed 35.3 MiB/s[2K Progress: 22.2%, ETA 00m22s, 224 MiB written, speed 36.0 MiB/s[2K Progress: 25.4%, ETA 00m20s, 256 MiB written, speed 36.9 MiB/s[2K Progress: 28.6%, ETA 00m19s, 288 MiB written, speed 37.6 MiB/s[2K Progress: 31.7%, ETA 00m18s, 320 MiB written, speed 38.2 MiB/s[2K Progress: 34.9%, ETA 00m17s, 352 MiB written, speed 38.2 MiB/s[2K Progress: 38.1%, ETA 00m16s, 384 MiB written, speed 38.5 MiB/s[2K Progress: 41.3%, ETA 00m15s, 416 MiB written, speed 38.4 MiB/s[2K Progress: 44.4%, ETA 00m14s, 448 MiB written, speed 38.9 MiB/s[2K Progress: 47.6%, ETA 00m13s, 480 MiB written, speed 39.0 MiB/s[2K Progress: 50.8%, ETA 00m13s, 512 MiB written, speed 39.0 MiB/s[2K Progress: 54.0%, ETA 00m12s, 544 MiB written, speed 39.4 MiB/s[2K Progress: 57.1%, ETA 00m11s, 576 MiB written, speed 39.7 MiB/s[2K Progress: 60.3%, ETA 00m10s, 608 MiB written, speed 39.6 MiB/s[2K Progress: 63.5%, ETA 00m09s, 640 MiB written, speed 39.7 MiB/s[2K Progress: 66.7%, ETA 00m08s, 672 MiB written, speed 39.7 MiB/s[2K Progress: 69.8%, ETA 00m07s, 704 MiB written, speed 40.1 MiB/s[2K Progress: 73.0%, ETA 00m07s, 736 MiB written, speed 40.2 MiB/s[2K Progress: 76.2%, ETA 00m06s, 768 MiB written, speed 40.3 MiB/s[2K Progress: 79.4%, ETA 00m05s, 800 MiB written, speed 40.3 MiB/s[2K Progress: 82.5%, ETA 00m04s, 832 MiB written, speed 40.4 MiB/s[2K Progress: 85.7%, ETA 00m03s, 864 MiB written, speed 40.4 MiB/s[2K Progress: 88.9%, ETA 00m03s, 896 MiB written, speed 40.4 MiB/s[2K Progress: 92.1%, ETA 00m02s, 928 MiB written, speed 40.5 MiB/s[2K Progress: 95.2%, ETA 00m01s, 960 MiB written, speed 40.5 MiB/s[2K Progress: 98.4%, ETA 00m00s, 992 MiB written, speed 40.5 MiB/s[2K Finished, time 00m24s, 1008 MiB written, speed 41.1 MiB/s New TPM2 token enrolled as key slot 1. done. Wiped slot 0. Device /dev/sdb6 is not a valid LUKS device. Begin: Encryption of /dev/sdb6 ... home: 19/170544 files (0.0% non-contiguous), 19895/340787 blocks resize2fs 1.47.0 (5-Feb-2023) Resizing the filesystem on /dev/sdb6 to 332595 (4k) blocks. The filesystem on /dev/sdb6 is now 332595 (4k) blocks long. [2K Progress: 2.4%, ETA 01m05s, 32 MiB written, speed 19.9 MiB/s[2K Progress: 4.9%, ETA 00m41s, 64 MiB written, speed 30.2 MiB/s[2K Progress: 7.3%, ETA 00m34s, 96 MiB written, speed 35.4 MiB/s[2K Progress: 9.7%, ETA 00m33s, 128 MiB written, speed 35.7 MiB/s[2K Progress: 12.2%, ETA 00m31s, 160 MiB written, speed 36.8 MiB/s[2K Progress: 14.6%, ETA 00m30s, 192 MiB written, speed 37.3 MiB/s[2K Progress: 17.0%, ETA 00m29s, 224 MiB written, speed 37.8 MiB/s[2K Progress: 19.5%, ETA 00m28s, 256 MiB written, speed 38.3 MiB/s[2K Progress: 21.9%, ETA 00m27s, 288 MiB written, speed 37.8 MiB/s[2K Progress: 24.3%, ETA 00m26s, 320 MiB written, speed 37.9 MiB/s[2K Progress: 26.8%, ETA 00m25s, 352 MiB written, speed 38.0 MiB/s[2K Progress: 29.2%, ETA 00m24s, 384 MiB written, speed 38.3 MiB/s[2K Progress: 31.6%, ETA 00m23s, 416 MiB written, speed 38.4 MiB/s[2K Progress: 34.1%, ETA 00m22s, 448 MiB written, speed 39.1 MiB/s[2K Progress: 36.5%, ETA 00m21s, 480 MiB written, speed 39.4 MiB/s[2K Progress: 38.9%, ETA 00m20s, 512 MiB written, speed 39.5 MiB/s[2K Progress: 41.4%, ETA 00m19s, 544 MiB written, speed 39.7 MiB/s[2K Progress: 43.8%, ETA 00m19s, 576 MiB written, speed 39.7 MiB/s[2K Progress: 46.2%, ETA 00m18s, 608 MiB written, speed 39.8 MiB/s[2K Progress: 48.7%, ETA 00m17s, 640 MiB written, speed 40.1 MiB/s[2K Progress: 51.1%, ETA 00m16s, 672 MiB written, speed 40.2 MiB/s[2K Progress: 53.5%, ETA 00m15s, 704 MiB written, speed 40.2 MiB/s[2K Progress: 56.0%, ETA 00m14s, 736 MiB written, speed 40.1 MiB/s[2K Progress: 58.4%, ETA 00m14s, 768 MiB written, speed 39.8 MiB/s[2K Progress: 59.6%, ETA 00m13s, 784 MiB written, speed 39.6 MiB/s[2K Progress: 62.0%, ETA 00m13s, 816 MiB written, speed 39.1 MiB/s[2K Progress: 63.3%, ETA 00m12s, 832 MiB written, speed 38.9 MiB/s[2K Progress: 65.7%, ETA 00m12s, 864 MiB written, speed 38.8 MiB/s[2K Progress: 68.1%, ETA 00m11s, 896 MiB written, speed 38.8 MiB/s[2K Progress: 70.6%, ETA 00m10s, 928 MiB written, speed 39.0 MiB/s[2K Progress: 73.0%, ETA 00m09s, 960 MiB written, speed 39.1 MiB/s[2K Progress: 75.4%, ETA 00m08s, 992 MiB written, speed 39.2 MiB/s[2K Progress: 77.9%, ETA 00m07s, 1024 MiB written, speed 39.2 MiB/s[2K Progress: 80.3%, ETA 00m07s, 1056 MiB written, speed 39.3 MiB/s[2K Progress: 82.7%, ETA 00m06s, 1088 MiB written, speed 39.4 MiB/s[2K Progress: 85.2%, ETA 00m05s, 1120 MiB written, speed 39.5 MiB/s[2K Progress: 87.6%, ETA 00m04s, 1152 MiB written, speed 39.6 MiB/s[2K Progress: 90.0%, ETA 00m03s, 1184 MiB written, speed 39.8 MiB/s[2K Progress: 92.5%, ETA 00m02s, 1216 MiB written, speed 39.8 MiB/s[2K Progress: 94.9%, ETA 00m02s, 1248 MiB written, speed 39.8 MiB/s[2K Progress: 97.3%, ETA 00m01s, 1280 MiB written, speed 39.9 MiB/s[2K Finished, time 00m32s, 1315 MiB written, speed 40.5 MiB/s New TPM2 token enrolled as key slot 1. done. Wiped slot 0. Device /dev/sdb7 is not a valid LUKS device. Begin: Encryption of /dev/sdb7 ... var: 1433/341040 files (0.1% non-contiguous), 90171/681574 blocks resize2fs 1.47.0 (5-Feb-2023) Resizing the filesystem on /dev/sdb7 to 673382 (4k) blocks. The filesystem on /dev/sdb7 is now 673382 (4k) blocks long. [2K Progress: 1.2%, ETA 02m15s, 32 MiB written, speed 19.4 MiB/s[2K Progress: 2.4%, ETA 01m27s, 64 MiB written, speed 29.6 MiB/s[2K Progress: 3.6%, ETA 01m17s, 96 MiB written, speed 33.1 MiB/s[2K Progress: 4.8%, ETA 01m12s, 128 MiB written, speed 34.7 MiB/s[2K Progress: 6.0%, ETA 01m09s, 160 MiB written, speed 35.8 MiB/s[2K Progress: 7.3%, ETA 01m06s, 192 MiB written, speed 37.1 MiB/s[2K Progress: 8.5%, ETA 01m04s, 224 MiB written, speed 37.5 MiB/s[2K Progress: 9.7%, ETA 01m02s, 256 MiB written, speed 38.3 MiB/s[2K Progress: 10.9%, ETA 01m01s, 288 MiB written, speed 38.8 MiB/s[2K Progress: 12.1%, ETA 01m00s, 320 MiB written, speed 39.0 MiB/s[2K Progress: 13.3%, ETA 00m58s, 352 MiB written, speed 39.5 MiB/s[2K Progress: 14.5%, ETA 00m56s, 384 MiB written, speed 40.0 MiB/s[2K Progress: 15.7%, ETA 00m56s, 416 MiB written, speed 39.9 MiB/s[2K Progress: 16.9%, ETA 00m55s, 448 MiB written, speed 39.7 MiB/s[2K Progress: 18.1%, ETA 00m54s, 480 MiB written, speed 40.1 MiB/s[2K Progress: 19.3%, ETA 00m53s, 512 MiB written, speed 40.3 MiB/s[2K Progress: 20.6%, ETA 00m52s, 544 MiB written, speed 40.6 MiB/s[2K Progress: 21.8%, ETA 00m51s, 576 MiB written, speed 40.6 MiB/s[2K Progress: 23.0%, ETA 00m50s, 608 MiB written, speed 40.9 MiB/s[2K Progress: 24.2%, ETA 00m49s, 640 MiB written, speed 40.7 MiB/s[2K Progress: 25.4%, ETA 00m48s, 672 MiB written, speed 40.8 MiB/s[2K Progress: 26.6%, ETA 00m47s, 704 MiB written, speed 41.0 MiB/s[2K Progress: 27.8%, ETA 00m46s, 736 MiB written, speed 41.2 MiB/s[2K Progress: 29.0%, ETA 00m45s, 768 MiB written, speed 41.4 MiB/s[2K Progress: 30.2%, ETA 00m45s, 800 MiB written, speed 41.2 MiB/s[2K Progress: 31.4%, ETA 00m44s, 832 MiB written, speed 41.3 MiB/s[2K Progress: 32.6%, ETA 00m43s, 864 MiB written, speed 41.3 MiB/s[2K Progress: 33.9%, ETA 00m42s, 896 MiB written, speed 41.1 MiB/s[2K Progress: 35.1%, ETA 00m42s, 928 MiB written, speed 41.1 MiB/s[2K Progress: 36.3%, ETA 00m41s, 960 MiB written, speed 41.1 MiB/s[2K Progress: 37.5%, ETA 00m40s, 992 MiB written, speed 41.1 MiB/s[2K Progress: 38.7%, ETA 00m39s, 1024 MiB written, speed 41.2 MiB/s[2K Progress: 39.9%, ETA 00m38s, 1056 MiB written, speed 41.3 MiB/s[2K Progress: 41.1%, ETA 00m38s, 1088 MiB written, speed 41.4 MiB/s[2K Progress: 42.3%, ETA 00m37s, 1120 MiB written, speed 41.4 MiB/s[2K Progress: 43.5%, ETA 00m36s, 1152 MiB written, speed 41.4 MiB/s[2K Progress: 44.7%, ETA 00m35s, 1184 MiB written, speed 41.3 MiB/s[2K Progress: 45.9%, ETA 00m35s, 1216 MiB written, speed 41.3 MiB/s[2K Progress: 47.2%, ETA 00m34s, 1248 MiB written, speed 41.3 MiB/s[2K Progress: 48.4%, ETA 00m33s, 1280 MiB written, speed 41.3 MiB/s[2K Progress: 49.6%, ETA 00m32s, 1312 MiB written, speed 41.5 MiB/s[2K Progress: 50.8%, ETA 00m31s, 1344 MiB written, speed 41.4 MiB/s[2K Progress: 52.0%, ETA 00m31s, 1376 MiB written, speed 41.4 MiB/s[2K Progress: 53.2%, ETA 00m30s, 1408 MiB written, speed 41.4 MiB/s[2K Progress: 54.4%, ETA 00m29s, 1440 MiB written, speed 41.5 MiB/s[2K Progress: 55.0%, ETA 00m29s, 1456 MiB written, speed 41.2 MiB/s[2K Progress: 56.2%, ETA 00m28s, 1488 MiB written, speed 41.1 MiB/s[2K Progress: 57.4%, ETA 00m27s, 1520 MiB written, speed 41.2 MiB/s[2K Progress: 58.6%, ETA 00m26s, 1552 MiB written, speed 41.2 MiB/s[2K Progress: 59.9%, ETA 00m26s, 1584 MiB written, speed 41.2 MiB/s[2K Progress: 61.1%, ETA 00m25s, 1616 MiB written, speed 41.3 MiB/s[2K Progress: 62.3%, ETA 00m24s, 1648 MiB written, speed 41.4 MiB/s[2K Progress: 63.5%, ETA 00m23s, 1680 MiB written, speed 41.4 MiB/s[2K Progress: 64.7%, ETA 00m22s, 1712 MiB written, speed 41.4 MiB/s[2K Progress: 65.9%, ETA 00m22s, 1744 MiB written, speed 41.4 MiB/s[2K Progress: 67.1%, ETA 00m21s, 1776 MiB written, speed 41.5 MiB/s[2K Progress: 68.3%, ETA 00m20s, 1808 MiB written, speed 41.5 MiB/s[2K Progress: 69.5%, ETA 00m19s, 1840 MiB written, speed 41.6 MiB/s[2K Progress: 70.7%, ETA 00m18s, 1872 MiB written, speed 41.6 MiB/s[2K Progress: 71.9%, ETA 00m18s, 1904 MiB written, speed 41.6 MiB/s[2K Progress: 73.2%, ETA 00m17s, 1936 MiB written, speed 41.4 MiB/s[2K Progress: 74.4%, ETA 00m16s, 1968 MiB written, speed 41.3 MiB/s[2K Progress: 75.6%, ETA 00m16s, 2000 MiB written, speed 41.2 MiB/s[2K Progress: 76.8%, ETA 00m15s, 2032 MiB written, speed 41.2 MiB/s[2K Progress: 78.0%, ETA 00m14s, 2064 MiB written, speed 41.1 MiB/s[2K Progress: 79.2%, ETA 00m13s, 2096 MiB written, speed 41.1 MiB/s[2K Progress: 80.4%, ETA 00m12s, 2128 MiB written, speed 41.2 MiB/s[2K Progress: 81.6%, ETA 00m12s, 2160 MiB written, speed 41.2 MiB/s[2K Progress: 82.8%, ETA 00m11s, 2192 MiB written, speed 41.2 MiB/s[2K Progress: 84.0%, ETA 00m10s, 2224 MiB written, speed 41.3 MiB/s[2K Progress: 85.2%, ETA 00m09s, 2256 MiB written, speed 41.2 MiB/s[2K Progress: 86.5%, ETA 00m09s, 2288 MiB written, speed 41.2 MiB/s[2K Progress: 87.7%, ETA 00m08s, 2320 MiB written, speed 41.2 MiB/s[2K Progress: 88.9%, ETA 00m07s, 2352 MiB written, speed 41.2 MiB/s[2K Progress: 90.1%, ETA 00m06s, 2384 MiB written, speed 41.2 MiB/s[2K Progress: 91.3%, ETA 00m05s, 2416 MiB written, speed 41.2 MiB/s[2K Progress: 92.5%, ETA 00m05s, 2448 MiB written, speed 41.2 MiB/s[2K Progress: 93.7%, ETA 00m04s, 2480 MiB written, speed 41.2 MiB/s[2K Progress: 94.9%, ETA 00m03s, 2512 MiB written, speed 41.3 MiB/s[2K Progress: 96.1%, ETA 00m02s, 2544 MiB written, speed 41.3 MiB/s[2K Progress: 97.3%, ETA 00m02s, 2576 MiB written, speed 41.3 MiB/s[2K Progress: 98.5%, ETA 00m01s, 2608 MiB written, speed 41.3 MiB/s[2K Progress: 99.4%, ETA 00m00s, 2630 MiB written, speed 41.3 MiB/s[2K Finished, time 01m03s, 2646 MiB written, speed 41.6 MiB/s New TPM2 token enrolled as key slot 1. done. Wiped slot 0. Device /dev/mapper/encrypted_home is not a valid VERITY device. done. Begin: Running /scripts/local-premount ... done. Warning: fsck not present, so skipping root file system done. Begin: Running /scripts/local-bottom ... var: 1433/341040 files (0.1% non-contiguous), 90171/673382 blocks done. Begin: Running /scripts/init-bottom ... done. Welcome to [1mDebian GNU/Linux 12 (bookworm)[0m! [[0;32m OK [0m] Created slice [0;1;39msystem-getty.slice[0m - Slice /system/getty. [[0;32m OK [0m] Created slice [0;1;39msystem-modpr���lice[0m - Slice /system/modprobe. [[0;32m OK [0m] Created slice [0;1;39msystem-seria���[0m - Slice /system/serial-getty. [[0;32m OK [0m] Started [0;1;39mntpsec-systemd-netif.path[0m. [[0;32m OK [0m] Started [0;1;39msystemd-ask-passwo���quests to Console Directory Watch. [[0;32m OK [0m] Started [0;1;39msystemd-ask-passwo��� Requests to Wall Directory Watch. [[0;32m OK [0m] Set up automount [0;1;39mproc-sys-���rmats File System Automount Point. Expecting device [0;1;39mdev-ttyS0.device[0m - /dev/ttyS0... Expecting device [0;1;39msys-subsy���sys/subsystem/net/devices/mgmt0... [[0;32m OK [0m] Reached target [0;1;39mcryptsetup.���get[0m - Local Encrypted Volumes. [[0;32m OK [0m] Reached target [0;1;39mintegrityse���Local Integrity Protected Volumes. [[0;32m OK [0m] Reached target [0;1;39mpaths.target[0m - Path Units. [[0;32m OK [0m] Reached target [0;1;39mremote-cryp���et[0m - Remote Encrypted Volumes. [[0;32m OK [0m] Reached target [0;1;39mremote-fs.target[0m - Remote File Systems. [[0;32m OK [0m] Reached target [0;1;39mremote-veri���- Remote Verity Protected Volumes. [[0;32m OK [0m] Reached target [0;1;39mslices.target[0m - Slice Units. [[0;32m OK [0m] Reached target [0;1;39mswap.target[0m - Swaps. [[0;32m OK [0m] Reached target [0;1;39mveritysetup��� - Local Verity Protected Volumes. [[0;32m OK [0m] Listening on [0;1;39msystemd-fsckd���sck to fsckd communication Socket. [[0;32m OK [0m] Listening on [0;1;39msystemd-initc��� initctl Compatibility Named Pipe. [[0;32m OK [0m] Listening on [0;1;39msystemd-journ���socket[0m - Journal Audit Socket. [[0;32m OK [0m] Listening on [0;1;39msystemd-journ���t[0m - Journal Socket (/dev/log). [[0;32m OK [0m] Listening on [0;1;39msystemd-journald.socket[0m - Journal Socket. [[0;32m OK [0m] Listening on [0;1;39msystemd-netwo��� - Network Service Netlink Socket. [[0;32m OK [0m] Listening on [0;1;39msystemd-udevd���.socket[0m - udev Control Socket. [[0;32m OK [0m] Listening on [0;1;39msystemd-udevd���l.socket[0m - udev Kernel Socket. Mounting [0;1;39mdev-hugepages.mount[0m - Huge Pages File System... Mounting [0;1;39mdev-mqueue.mount���POSIX Message Queue File System... Mounting [0;1;39msys-kernel-debug.���[0m - Kernel Debug File System... Mounting [0;1;39msys-kernel-tracin���[0m - Kernel Trace File System... Mounting [0;1;39mtmp.mount[0m - Temporary Directory /tmp... Starting [0;1;39mkmod-static-nodes���ate List of Static Device Nodes... Starting [0;1;39mmodprobe@configfs���m - Load Kernel Module configfs... Starting [0;1;39mmodprobe@dm_mod.s���[0m - Load Kernel Module dm_mod... Starting [0;1;39mmodprobe@efi_psto���- Load Kernel Module efi_pstore... Starting [0;1;39mmodprobe@fuse.ser���e[0m - Load Kernel Module fuse... Starting [0;1;39mmodprobe@loop.ser���e[0m - Load Kernel Module loop... Starting [0;1;39msystemd-fsck-root���ile System Check on Root Device... Starting [0;1;39msystemd-journald.service[0m - Journal Service... Starting [0;1;39msystemd-modules-l���rvice[0m - Load Kernel Modules... Starting [0;1;39msystemd-network-g��� units from Kernel command line... Starting [0;1;39msystemd-udev-trig���[0m - Coldplug All udev Devices... [[0;32m OK [0m] Mounted [0;1;39mdev-hugepages.mount[0m - Huge Pages File System. [[0;32m OK [0m] Mounted [0;1;39mdev-mqueue.mount[���- POSIX Message Queue File System. [[0;32m OK [0m] Mounted [0;1;39msys-kernel-debug.m���nt[0m - Kernel Debug File System. [[0;32m OK [0m] Mounted [0;1;39msys-kernel-tracing���nt[0m - Kernel Trace File System. [[0;32m OK [0m] Mounted [0;1;39mtmp.mount[0m - Temporary Directory /tmp. [[0;32m OK [0m] Finished [0;1;39mkmod-static-nodes���reate List of Static Device Nodes. [[0;32m OK [0m] Finished [0;1;39mmodprobe@configfs���[0m - Load Kernel Module configfs. [[0;32m OK [0m] Finished [0;1;39mmodprobe@dm_mod.s���e[0m - Load Kernel Module dm_mod. [[0;32m OK [0m] Finished [0;1;39mmodprobe@efi_psto���m - Load Kernel Module efi_pstore. [[0;32m OK [0m] Finished [0;1;39mmodprobe@fuse.service[0m - Load Kernel Module fuse. [[0;32m OK [0m] Finished [0;1;39mmodprobe@loop.service[0m - Load Kernel Module loop. [[0;32m OK [0m] Finished [0;1;39msystemd-fsck-root��� File System Check on Root Device. [[0;32m OK [0m] Finished [0;1;39msystemd-network-g���rk units from Kernel command line. [[0;32m OK [0m] Started [0;1;39msystemd-journald.service[0m - Journal Service. [[0;32m OK [0m] Reached target [0;1;39mnetwork-pre���get[0m - Preparation for Network. Mounting [0;1;39msys-fs-fuse-conne���[0m - FUSE Control File System... Mounting [0;1;39msys-kernel-config���ernel Configuration File System... Starting [0;1;39msystemd-remount-f���nt Root and Kernel File Systems... [[0;32m OK [0m] Mounted [0;1;39msys-fs-fuse-connec���nt[0m - FUSE Control File System. [[0;32m OK [0m] Mounted [0;1;39msys-kernel-config.��� Kernel Configuration File System. [[0;32m OK [0m] Finished [0;1;39msystemd-remount-f���ount Root and Kernel File Systems. Starting [0;1;39mexpand-on-first-b���ice[0m - Expand last partition... Starting [0;1;39msystemd-journal-f���h Journal to Persistent Storage... Starting [0;1;39msystemd-random-se���ice[0m - Load/Save Random Seed... Starting [0;1;39msystemd-sysusers.���rvice[0m - Create System Users... [[0;32m OK [0m] Finished [0;1;39msystemd-udev-trig���e[0m - Coldplug All udev Devices. [[0;32m OK [0m] Finished [0;1;39msystemd-random-se���rvice[0m - Load/Save Random Seed. [[0;32m OK [0m] Reached target [0;1;39mfirst-boot-���.target[0m - First Boot Complete. Starting [0;1;39msshd-regen-keys.s���[0m - Regenerate sshd host keys... [[0;32m OK [0m] Finished [0;1;39msystemd-journal-f���ush Journal to Persistent Storage. [[0;32m OK [0m] Finished [0;1;39msystemd-sysusers.service[0m - Create System Users. Starting [0;1;39msystemd-tmpfiles-���ate Static Device Nodes in /dev... [[0;32m OK [0m] Finished [0;1;39msystemd-tmpfiles-���reate Static Device Nodes in /dev. [ 244.988945] platform regulatory.0: firmware: failed to load regulatory.db (-2) [ 244.992365] firmware_class: See https://wiki.debian.org/Firmware for information about missing firmware [ 244.999990] platform regulatory.0: firmware: failed to load regulatory.db (-2) Starting [0;1;39msystemd-udevd.ser���ger for Device Events and Files... [[0;32m OK [0m] Found device [0;1;39mdev-ttyS0.device[0m - /dev/ttyS0. [[0;32m OK [0m] Started [0;1;39msystemd-udevd.serv���nager for Device Events and Files. [[0;32m OK [0m] Finished [0;1;39msystemd-modules-l���service[0m - Load Kernel Modules. [[0;32m OK [0m] Finished [0;1;39mexpand-on-first-b���rvice[0m - Expand last partition. [[0;32m OK [0m] Reached target [0;1;39mlocal-fs-pr���reparation for Local File Systems. [[0;32m OK [0m] Reached target [0;1;39mlocal-fs.target[0m - Local File Systems. [[0;32m OK [0m] Listening on [0;1;39msystemd-rfkil���l Switch Status /dev/rfkill Watch. Starting [0;1;39msystemd-binfmt.se���et Up Additional Binary Formats... Starting [0;1;39msystemd-machine-i��� a transient machine-id on disk... Starting [0;1;39msystemd-sysctl.se���ce[0m - Apply Kernel Variables... Starting [0;1;39msystemd-tmpfiles-���te System Files and Directories... [[0;32m OK [0m] Finished [0;1;39msshd-regen-keys.s���e[0m - Regenerate sshd host keys. [[0;32m OK [0m] Finished [0;1;39msystemd-sysctl.service[0m - Apply Kernel Variables. Mounting [0;1;39mproc-sys-fs-binfm���utable File Formats File System... Starting [0;1;39msystemd-networkd.���ice[0m - Network Configuration... [[0;32m OK [0m] Finished [0;1;39msystemd-machine-i���it a transient machine-id on disk. [[0;32m OK [0m] Finished [0;1;39msystemd-tmpfiles-���eate System Files and Directories. [[0;32m OK [0m] Mounted [0;1;39mproc-sys-fs-binfmt���ecutable File Formats File System. Starting [0;1;39mauditd.service[0m - Security Auditing Service... Starting [0;1;39mmodprobe@dm_mod.s���[0m - Load Kernel Module dm_mod... Starting [0;1;39mmodprobe@efi_psto���- Load Kernel Module efi_pstore... Starting [0;1;39mmodprobe@loop.ser���e[0m - Load Kernel Module loop... [[0;32m OK [0m] Finished [0;1;39msystemd-binfmt.se��� Set Up Additional Binary Formats. [[0;32m OK [0m] Finished [0;1;39mmodprobe@dm_mod.s���e[0m - Load Kernel Module dm_mod. [[0;32m OK [0m] Finished [0;1;39mmodprobe@efi_psto���m - Load Kernel Module efi_pstore. [[0;32m OK [0m] Finished [0;1;39mmodprobe@loop.service[0m - Load Kernel Module loop. [[0;32m OK [0m] Started [0;1;39msystemd-networkd.service[0m - Network Configuration. [[0;32m OK [0m] Reached target [0;1;39mnetwork.target[0m - Network. Starting [0;1;39msystemd-networkd-���it for Network to be Configured... [[0;32m OK [0m] Started [0;1;39mauditd.service[0m - Security Auditing Service. Starting [0;1;39msystemd-update-ut���rd System Boot/Shutdown in UTMP... [[0;32m OK [0m] Finished [0;1;39msystemd-update-ut���cord System Boot/Shutdown in UTMP. [[0;32m OK [0m] Reached target [0;1;39msysinit.target[0m - System Initialization. [[0;32m OK [0m] Started [0;1;39mapt-daily.timer[0m - Daily apt download activities. [[0;32m OK [0m] Started [0;1;39mapt-daily-upgrade.��� apt upgrade and clean activities. [[0;32m OK [0m] Started [0;1;39mdpkg-db-backup.tim��� Daily dpkg database backup timer. [[0;32m OK [0m] Started [0;1;39me2scrub_all.timer���etadata Check for All Filesystems. [[0;32m OK [0m] Started [0;1;39mfstrim.timer[0m - Discard unused blocks once a week. [[0;32m OK [0m] Started [0;1;39mntpsec-rotate-stat���mer[0m - Rotate ntpd stats daily. [[0;32m OK [0m] Started [0;1;39msystemd-tmpfiles-c��� Cleanup of Temporary Directories. [[0;32m OK [0m] Reached target [0;1;39mtimers.target[0m - Timer Units. [[0;32m OK [0m] Listening on [0;1;39mssh.socket[0���penBSD Secure Shell server socket. Starting [0;1;39mswupdate.socket[0m - SWUpdate socket listener... [[0;32m OK [0m] Listening on [0;1;39mswupdate.socket[0m - SWUpdate socket listener. [[0;32m OK [0m] Reached target [0;1;39msockets.target[0m - Socket Units. [[0;32m OK [0m] Reached target [0;1;39mbasic.target[0m - Basic System. [[0;32m OK [0m] Started [0;1;39mdevice-manager.service[0m - device manager service. Starting [0;1;39mdnsmasq.service[���ght DHCP and caching DNS server... Starting [0;1;39me2scrub_reap.serv���e ext4 Metadata Check Snapshots... Starting [0;1;39mgetty-static.serv���us and logind are not available... [[0;32m OK [0m] Started [0;1;39mntpsec-systemd-netif.service[0m. Starting [0;1;39mssh.service[0m - OpenBSD Secure Shell server... [[0;32m OK [0m] Started [0;1;39mswupdate.service[0m - SWUpdate daemon. [[0;32m OK [0m] Started [0;1;39mswupdate-progress.���e[0m - swupdate progress service. Starting [0;1;39msystemd-user-sess���vice[0m - Permit User Sessions... [[0;32m OK [0m] Finished [0;1;39msystemd-user-sess���ervice[0m - Permit User Sessions. [[0;32m OK [0m] Started [0;1;39mgetty@tty1.service[0m - Getty on tty1. [[0;32m OK [0m] Started [0;1;39mgetty@tty2.service[0m - Getty on tty2. [[0;32m OK [0m] Started [0;1;39mserial-getty@ttyS0���rvice[0m - Serial Getty on ttyS0. [[0;32m OK [0m] Started [0;1;39mgetty@tty3.service[0m - Getty on tty3. [[0;32m OK [0m] Started [0;1;39mgetty@tty4.service[0m - Getty on tty4. [[0;32m OK [0m] Started [0;1;39mgetty@tty5.service[0m - Getty on tty5. [[0;32m OK [0m] Started [0;1;39mgetty@tty6.service[0m - Getty on tty6. [[0;32m OK [0m] Finished [0;1;39mgetty-static.serv���dbus and logind are not available. [[0;32m OK [0m] Reached target [0;1;39mgetty.target[0m - Login Prompts. [[0;32m OK [0m] Started [0;1;39mssh.service[0m - OpenBSD Secure Shell server. [[0;32m OK [0m] Started [0;1;39mdnsmasq.service[0���eight DHCP and caching DNS server. [[0;32m OK [0m] Reached target [0;1;39mnss-lookup.���m - Host and Network Name Lookups. Starting [0;1;39mntpsec.service[0m - Network Time Service... [[0;32m OK [0m] Started [0;1;39mntpsec.service[0m - Network Time Service. [[0;32m OK [0m] Finished [0;1;39me2scrub_reap.serv���ine ext4 Metadata Check Snapshots. System Info: Matched prompt #1: device-mgmt login: Setting prompt string to ['\\r'] wait for prompt timed out end: 2.2.1 login-action (duration 00:14:45) [common] definition: lava namespace: common case: login-action level: 2.2.1 duration: 884.77 result: fail extra: ... auto-login-action failed: 1 of 1 attempts. 'wait for prompt timed out' wait for prompt timed out end: 2.2 auto-login-action (duration 00:15:00) [common] definition: lava namespace: common case: auto-login-action level: 2.2 duration: 900.10 result: fail extra: ... boot-image-retry failed: 1 of 1 attempts. 'wait for prompt timed out' wait for prompt timed out end: 2 boot-image-retry (duration 00:15:00) [common] definition: lava namespace: common case: boot-image-retry level: 2 duration: 900.11 result: fail extra: ... Cleaning after the job Cleaning up download directory: /var/lib/lava/dispatcher/tmp/266/deployimages-dcqtlv9_/rootfs start: 4.1 power-off (timeout 00:00:10) [common] end: 4.1 power-off (duration 00:00:00) [common] start: 4.2 read-feedback (timeout 00:05:00) [common] Finalising connection for namespace 'common' Sending line: 'poweroff' poweroff Already disconnected device-mgmt login: poweroff Traceback (most recent call last): File "/usr/lib/python3/dist-packages/lava_dispatcher/shell.py", line 173, in expect proc = super().expect(*args, **kw) ^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/pexpect/spawnbase.py", line 343, in expect return self.expect_list(compiled_pattern_list, ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/pexpect/spawnbase.py", line 372, in expect_list return exp.expect_loop(timeout) ^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/pexpect/expect.py", line 181, in expect_loop return self.timeout(e) ^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/pexpect/expect.py", line 144, in timeout raise exc pexpect.exceptions.TIMEOUT: Timeout exceeded. command: /usr/bin/qemu-system-x86_64 args: [b'/usr/bin/qemu-system-x86_64', b'-cpu', b'host', b'-enable-kvm', b'-nographic', b'-net', b'nic,model=virtio,macaddr=52:54:00:12:34:58', b'-net', b'user', b'-m', b'1024', b'-monitor', b'none', b'-global', b'ICH9-LPC.disable_s3=1', b'-global', b'isa-fdc.driveA=', b'-drive', b'if=pflash,format=raw,unit=0,readonly=on,file=/usr/share/OVMF/OVMF_CODE_4M.fd', b'-drive', b'file=/var/lib/lava/dispatcher/tmp/266/deployimages-dcqtlv9_/rootfs/iq-edge-os-cip-core-bookworm-qemu-amd64.wic,discard=unmap,if=none,id=disk,format=raw', b'-m', b'8G', b'-monitor', b'none', b'-serial', b'mon:stdio', b'-display', b'none', b'-cpu', b'qemu64', b'-smp', b'4', b'-machine', b'q35,accel=kvm:tcg', b'-global', b'ICH9-LPC.noreboot=off', b'-device', b'ide-hd,drive=disk', b'-nographic', b'-chardev', b'socket,id=chrtpm,path=/tmp/swtpm.sock/qemu-swtpm.sock', b'-tpmdev', b'emulator,id=tpm0,chardev=chrtpm', b'-device', b'tpm-tis,tpmdev=tpm0', b'-drive', b'format=qcow2,file=/var/lib/lava/dispatcher/tmp/266/apply-overlay-guest-8po4d1k7/lava-guest.qcow2,media=disk,if=ide,id=lavatest'] buffer (last 100 chars): ' ' before (last 100 chars): ' ' after: match: None match_index: None exitstatus: None flag_eof: False pid: 856563 child_fd: 10 closed: False timeout: 900 delimiter: logfile: None logfile_read: logfile_send: maxread: 2000 ignorecase: False searchwindowsize: 4000 delaybeforesend: 0.05 delayafterclose: 0.1 delayafterterminate: 1.0 searcher: searcher_re: 0: re.compile('\\r') During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib/python3/dist-packages/lava_dispatcher/shell.py", line 297, in wait return self.raw_connection.expect( ^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/shell.py", line 178, in expect raise TestError("ShellCommand command timed out.") lava_common.exceptions.TestError: ShellCommand command timed out. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib/python3/dist-packages/lava_dispatcher/job.py", line 239, in run self._run() File "/usr/lib/python3/dist-packages/lava_dispatcher/job.py", line 229, in _run self.pipeline.run_actions(self.connection, max_end_time) File "/usr/lib/python3/dist-packages/lava_dispatcher/action.py", line 249, in run_actions new_connection = action.run(connection, action_max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/logical.py", line 62, in run connection = self.pipeline.run_actions(connection, max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/action.py", line 249, in run_actions new_connection = action.run(connection, action_max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/actions/boot/__init__.py", line 336, in run connection = super().run(connection, max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/logical.py", line 62, in run connection = self.pipeline.run_actions(connection, max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/action.py", line 249, in run_actions new_connection = action.run(connection, action_max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/actions/boot/__init__.py", line 170, in run self.check_kernel_messages( File "/usr/lib/python3/dist-packages/lava_dispatcher/actions/boot/__init__.py", line 90, in check_kernel_messages parsed = LinuxKernelMessages.parse_failures( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/utils/messages.py", line 159, in parse_failures sub_index = connection.wait(max_end_time, max_searchwindowsize=True) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/shell.py", line 303, in wait raise JobError("wait for prompt timed out") lava_common.exceptions.JobError: wait for prompt timed out During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib/python3/dist-packages/pexpect/pty_spawn.py", line 23, in _wrap_ptyprocess_err yield File "/usr/lib/python3/dist-packages/pexpect/pty_spawn.py", line 328, in close self.ptyproc.close(force=force) File "/usr/lib/python3/dist-packages/ptyprocess/ptyprocess.py", line 406, in close raise PtyProcessError('Could not terminate the child.') ptyprocess.util.PtyProcessError: Could not terminate the child. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib/python3/dist-packages/lava_dispatcher/action.py", line 249, in run_actions new_connection = action.run(connection, action_max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/power.py", line 308, in run feedback[1].finalise() File "/usr/lib/python3/dist-packages/lava_dispatcher/connections/serial.py", line 246, in finalise self.disconnect("closing") File "/usr/lib/python3/dist-packages/lava_dispatcher/connections/serial.py", line 253, in disconnect super().disconnect(reason) File "/usr/lib/python3/dist-packages/lava_dispatcher/connection.py", line 153, in disconnect self.raw_connection.close(force=True) File "/usr/lib/python3/dist-packages/pexpect/pty_spawn.py", line 325, in close with _wrap_ptyprocess_err(): File "/usr/lib/python3.11/contextlib.py", line 155, in __exit__ self.gen.throw(typ, value, traceback) File "/usr/lib/python3/dist-packages/pexpect/pty_spawn.py", line 25, in _wrap_ptyprocess_err raise ExceptionPexpect(*e.args) pexpect.exceptions.ExceptionPexpect: Could not terminate the child. end: 4.2 read-feedback (duration 00:00:02) [common] definition: lava namespace: common case: read-feedback level: 4.2 duration: 1.69 result: fail extra: ... Failed to run 'finalize': Could not terminate the child. Traceback (most recent call last): File "/usr/lib/python3/dist-packages/lava_dispatcher/shell.py", line 173, in expect proc = super().expect(*args, **kw) ^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/pexpect/spawnbase.py", line 343, in expect return self.expect_list(compiled_pattern_list, ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/pexpect/spawnbase.py", line 372, in expect_list return exp.expect_loop(timeout) ^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/pexpect/expect.py", line 181, in expect_loop return self.timeout(e) ^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/pexpect/expect.py", line 144, in timeout raise exc pexpect.exceptions.TIMEOUT: Timeout exceeded. command: /usr/bin/qemu-system-x86_64 args: [b'/usr/bin/qemu-system-x86_64', b'-cpu', b'host', b'-enable-kvm', b'-nographic', b'-net', b'nic,model=virtio,macaddr=52:54:00:12:34:58', b'-net', b'user', b'-m', b'1024', b'-monitor', b'none', b'-global', b'ICH9-LPC.disable_s3=1', b'-global', b'isa-fdc.driveA=', b'-drive', b'if=pflash,format=raw,unit=0,readonly=on,file=/usr/share/OVMF/OVMF_CODE_4M.fd', b'-drive', b'file=/var/lib/lava/dispatcher/tmp/266/deployimages-dcqtlv9_/rootfs/iq-edge-os-cip-core-bookworm-qemu-amd64.wic,discard=unmap,if=none,id=disk,format=raw', b'-m', b'8G', b'-monitor', b'none', b'-serial', b'mon:stdio', b'-display', b'none', b'-cpu', b'qemu64', b'-smp', b'4', b'-machine', b'q35,accel=kvm:tcg', b'-global', b'ICH9-LPC.noreboot=off', b'-device', b'ide-hd,drive=disk', b'-nographic', b'-chardev', b'socket,id=chrtpm,path=/tmp/swtpm.sock/qemu-swtpm.sock', b'-tpmdev', b'emulator,id=tpm0,chardev=chrtpm', b'-device', b'tpm-tis,tpmdev=tpm0', b'-drive', b'format=qcow2,file=/var/lib/lava/dispatcher/tmp/266/apply-overlay-guest-8po4d1k7/lava-guest.qcow2,media=disk,if=ide,id=lavatest'] buffer (last 100 chars): ' ' before (last 100 chars): ' ' after: match: None match_index: None exitstatus: None flag_eof: False pid: 856563 child_fd: 10 closed: False timeout: 900 delimiter: logfile: None logfile_read: logfile_send: maxread: 2000 ignorecase: False searchwindowsize: 4000 delaybeforesend: 0.05 delayafterclose: 0.1 delayafterterminate: 1.0 searcher: searcher_re: 0: re.compile('\\r') During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib/python3/dist-packages/lava_dispatcher/shell.py", line 297, in wait return self.raw_connection.expect( ^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/shell.py", line 178, in expect raise TestError("ShellCommand command timed out.") lava_common.exceptions.TestError: ShellCommand command timed out. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib/python3/dist-packages/lava_dispatcher/job.py", line 239, in run self._run() File "/usr/lib/python3/dist-packages/lava_dispatcher/job.py", line 229, in _run self.pipeline.run_actions(self.connection, max_end_time) File "/usr/lib/python3/dist-packages/lava_dispatcher/action.py", line 249, in run_actions new_connection = action.run(connection, action_max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/logical.py", line 62, in run connection = self.pipeline.run_actions(connection, max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/action.py", line 249, in run_actions new_connection = action.run(connection, action_max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/actions/boot/__init__.py", line 336, in run connection = super().run(connection, max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/logical.py", line 62, in run connection = self.pipeline.run_actions(connection, max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/action.py", line 249, in run_actions new_connection = action.run(connection, action_max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/actions/boot/__init__.py", line 170, in run self.check_kernel_messages( File "/usr/lib/python3/dist-packages/lava_dispatcher/actions/boot/__init__.py", line 90, in check_kernel_messages parsed = LinuxKernelMessages.parse_failures( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/utils/messages.py", line 159, in parse_failures sub_index = connection.wait(max_end_time, max_searchwindowsize=True) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/shell.py", line 303, in wait raise JobError("wait for prompt timed out") lava_common.exceptions.JobError: wait for prompt timed out During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib/python3/dist-packages/pexpect/pty_spawn.py", line 23, in _wrap_ptyprocess_err yield File "/usr/lib/python3/dist-packages/pexpect/pty_spawn.py", line 328, in close self.ptyproc.close(force=force) File "/usr/lib/python3/dist-packages/ptyprocess/ptyprocess.py", line 406, in close raise PtyProcessError('Could not terminate the child.') ptyprocess.util.PtyProcessError: Could not terminate the child. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib/python3/dist-packages/lava_dispatcher/action.py", line 249, in run_actions new_connection = action.run(connection, action_max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/power.py", line 308, in run feedback[1].finalise() File "/usr/lib/python3/dist-packages/lava_dispatcher/connections/serial.py", line 246, in finalise self.disconnect("closing") File "/usr/lib/python3/dist-packages/lava_dispatcher/connections/serial.py", line 253, in disconnect super().disconnect(reason) File "/usr/lib/python3/dist-packages/lava_dispatcher/connection.py", line 153, in disconnect self.raw_connection.close(force=True) File "/usr/lib/python3/dist-packages/pexpect/pty_spawn.py", line 325, in close with _wrap_ptyprocess_err(): File "/usr/lib/python3.11/contextlib.py", line 155, in __exit__ self.gen.throw(typ, value, traceback) File "/usr/lib/python3/dist-packages/pexpect/pty_spawn.py", line 25, in _wrap_ptyprocess_err raise ExceptionPexpect(*e.args) pexpect.exceptions.ExceptionPexpect: Could not terminate the child. During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/lib/python3/dist-packages/lava_dispatcher/power.py", line 341, in run connection = super().run(connection, max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/action.py", line 848, in run return self.pipeline.run_actions(connection, max_end_time) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/lib/python3/dist-packages/lava_dispatcher/action.py", line 278, in run_actions raise LAVABug(str(exc)) lava_common.exceptions.LAVABug: Could not terminate the child. Removing root tmp directory at /var/lib/lava/dispatcher/tmp/266 JobError: Your job cannot terminate cleanly. definition: lava case: job result: fail