Hi,
Per tests/avocado/replay_kernel.py:
def test_aarch64_virt(self):
...
console_pattern = 'VFS: Cannot open root device'
the test is succeeding, but Avocado reports an error.
I could get a verbose debug.log, so sharing it here, enjoy!
Regards,
Phil.[stdlog] 2023-07-10 19:04:08,084 avocado.test INFO | INIT
1-tests/avocado/replay_kernel.py:ReplayKernelNormal.test_aarch64_virt
[stdlog] 2023-07-10 19:04:08,089 avocado.test DEBUG| PARAMS (key=timeout,
path=*, default=120) => 120
[stdlog] 2023-07-10 19:04:08,090 avocado.test DEBUG| Test metadata:
[stdlog] 2023-07-10 19:04:08,091 avocado.test DEBUG| filename:
/Users/philmd/build/tests/avocado/replay_kernel.py
[stdlog] 2023-07-10 19:04:08,092 avocado.test DEBUG| teststmpdir:
/var/folders/yj/r7khncsj4d77k04ybz9lw4tm0000gn/T/avocado_0mpq0qad
[stdlog] 2023-07-10 19:04:08,095 avocado.test INFO | START
1-tests/avocado/replay_kernel.py:ReplayKernelNormal.test_aarch64_virt
[stdlog] 2023-07-10 19:04:08,095 avocado.test DEBUG| PARAMS (key=arch, path=*,
default=aarch64) => 'aarch64'
[stdlog] 2023-07-10 19:04:08,096 avocado.test DEBUG| PARAMS (key=cpu, path=*,
default=cortex-a53) => 'cortex-a53'
[stdlog] 2023-07-10 19:04:08,096 avocado.test DEBUG| PARAMS (key=qemu_bin,
path=*, default=./qemu-system-aarch64) => './qemu-system-aarch64'
[stdlog] 2023-07-10 19:04:08,097 avocado.test DEBUG| PARAMS (key=machine,
path=*, default=virt) => 'virt'
[stdlog] 2023-07-10 19:04:08,098 avocado.utils.asset INFO | Fetching asset
https://archives.fedoraproject.org/pub/archive/fedora/linux/releases/29/Everything/aarch64/os/images/pxeboot/vmlinuz
[stdlog] 2023-07-10 19:04:08,115 avocado.utils.asset INFO | Asset already
exists in cache.
[stdlog] 2023-07-10 19:04:08,117 avocado.test DEBUG| Test workdir initialized
at:
/Users/philmd/build/tests/results/job-2023-07-10T19.03-fe8fa79/test-results/170-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt/tmp_dirucu13g97/1-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt
[stdlog] 2023-07-10 19:04:08,162 avocado.test DEBUG| QEMUMachine
"6b877b41-8a16-4f91-acd6-f561ea0a3bcd" created
[stdlog] 2023-07-10 19:04:08,165 avocado.test DEBUG| QEMUMachine
"6b877b41-8a16-4f91-acd6-f561ea0a3bcd" temp_dir:
/Users/philmd/build/tests/results/job-2023-07-10T19.03-fe8fa79/test-results/170-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt/tmp_dirucu13g97/1-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt/qemu-machine-f4z4lx6_
[stdlog] 2023-07-10 19:04:08,167 avocado.test DEBUG| QEMUMachine
"6b877b41-8a16-4f91-acd6-f561ea0a3bcd" log_dir:
/Users/philmd/build/tests/results/job-2023-07-10T19.03-fe8fa79/test-results/170-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt
[stdlog] 2023-07-10 19:04:08,167 replay INFO | recording the execution...
[stdlog] 2023-07-10 19:04:08,169 qemu.qmp.qmp_client.101e41690 DEBUG|
Registering <qemu.qmp.events.EventListener object at 0x1029e8dd0>.
[stdlog] 2023-07-10 19:04:08,170 asyncio DEBUG| Using selector: KqueueSelector
[stdlog] 2023-07-10 19:04:08,170 qemu.machine.machine DEBUG| VM launch command:
'./qemu-system-aarch64 -display none -vga none -chardev socket,id=mon,fd=11
-mon chardev=mon,mode=control -machine virt -chardev
socket,id=console,path=/var/folders/yj/r7khncsj4d77k04ybz9lw4tm0000gn/T/qemu_iu7icxth/101e41690.con,server=on,wait=off
-serial chardev:console -cpu cortex-a53 -icount
shift=7,rr=record,rrfile=/Users/philmd/build/tests/results/job-2023-07-10T19.03-fe8fa79/test-results/170-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt/tmp_dirucu13g97/1-tests_avocado_replay_kernel.py_ReplayKernelNormal.test_aarch64_virt/replay.bin
-kernel
/Users/philmd/avocado/data/cache/by_location/a00ac4ae676ef0322126abd2f7d38f50cc9cbc95/vmlinuz
-append printk.time=1 panic=-1 console=ttyAMA0 -net none -no-reboot'
[stdlog] 2023-07-10 19:04:08,183 qemu.qmp.qmp_client.101e41690 DEBUG|
Transitioning from 'Runstate.IDLE' to 'Runstate.CONNECTING'.
[stdlog] 2023-07-10 19:04:08,187 qemu.qmp.qmp_client.101e41690 DEBUG|
Connecting with existing socket: fd=12, family=<AddressFamily.AF_UNIX: 1>,
type=<SocketKind.SOCK_STREAM: 1>
[stdlog] 2023-07-10 19:04:08,191 qemu.qmp.qmp_client.101e41690 DEBUG| Connected.
[stdlog] 2023-07-10 19:04:08,191 qemu.qmp.qmp_client.101e41690 DEBUG| Awaiting
greeting ...
[stdlog] 2023-07-10 19:04:08,208 qemu.qmp.qmp_client.101e41690 DEBUG| <-- {
[stdlog] "QMP": {
[stdlog] "version": {
[stdlog] "qemu": {
[stdlog] "micro": 50,
[stdlog] "minor": 0,
[stdlog] "major": 8
[stdlog] },
[stdlog] "package": "v8.0.0-2542-g2268e7980c"
[stdlog] },
[stdlog] "capabilities": [
[stdlog] "oob"
[stdlog] ]
[stdlog] }
[stdlog] }
[stdlog] 2023-07-10 19:04:08,209 qemu.qmp.qmp_client.101e41690 DEBUG|
Negotiating capabilities ...
[stdlog] 2023-07-10 19:04:08,209 qemu.qmp.qmp_client.101e41690 DEBUG| --> {
[stdlog] "execute": "qmp_capabilities",
[stdlog] "arguments": {
[stdlog] "enable": [
[stdlog] "oob"
[stdlog] ]
[stdlog] }
[stdlog] }
[stdlog] 2023-07-10 19:04:08,312 qemu.qmp.qmp_client.101e41690 DEBUG| <-- {
[stdlog] "return": {}
[stdlog] }
[stdlog] 2023-07-10 19:04:08,317 qemu.qmp.qmp_client.101e41690 DEBUG|
Transitioning from 'Runstate.CONNECTING' to 'Runstate.RUNNING'.
[stdlog] 2023-07-10 19:04:08,924 console DEBUG| [ 0.000000] Booting Linux on
physical CPU 0x0000000000 [0x410fd034]
[stdlog] 2023-07-10 19:04:08,925 console DEBUG| [ 0.000000] Linux version
4.18.16-300.fc29.aarch64 (mockbu...@buildvm-aarch64-02.arm.fedoraproject.org)
(gcc version 8.2.1 20180801 (Red Hat 8.2.1-2) (GCC)) #1 SMP Sat Oct 20 23:12:22
UTC 2018
[stdlog] 2023-07-10 19:04:08,925 console DEBUG| [ 0.000000] Machine model:
linux,dummy-virt
[stdlog] 2023-07-10 19:04:08,926 console DEBUG| [ 0.000000] efi: Getting EFI
parameters from FDT:
[stdlog] 2023-07-10 19:04:08,926 console DEBUG| [ 0.000000] efi: UEFI not
found.
[stdlog] 2023-07-10 19:04:08,926 console DEBUG| [ 0.000000] cma: Failed to
reserve 64 MiB
[stdlog] 2023-07-10 19:04:08,927 console DEBUG| [ 0.000000] NUMA: No NUMA
configuration found
[stdlog] 2023-07-10 19:04:08,927 console DEBUG| [ 0.000000] NUMA: Faking a
node at [mem 0x0000000000000000-0x0000000047ffffff]
[stdlog] 2023-07-10 19:04:08,927 console DEBUG| [ 0.000000] NUMA: NODE_DATA
[mem 0x47f9c780-0x47fa9fff]
[stdlog] 2023-07-10 19:04:08,927 console DEBUG| [ 0.000000] Zone ranges:
[stdlog] 2023-07-10 19:04:08,928 console DEBUG| [ 0.000000] DMA32 [mem
0x0000000040000000-0x0000000047ffffff]
[stdlog] 2023-07-10 19:04:08,928 console DEBUG| [ 0.000000] Normal empty
[stdlog] 2023-07-10 19:04:08,928 console DEBUG| [ 0.000000] Movable zone
start for each node
[stdlog] 2023-07-10 19:04:08,928 console DEBUG| [ 0.000000] Early memory
node ranges
[stdlog] 2023-07-10 19:04:08,928 console DEBUG| [ 0.000000] node 0: [mem
0x0000000040000000-0x0000000047ffffff]
[stdlog] 2023-07-10 19:04:08,929 console DEBUG| [ 0.000000] Initmem setup
node 0 [mem 0x0000000040000000-0x0000000047ffffff]
[stdlog] 2023-07-10 19:04:08,929 console DEBUG| [ 0.000000] psci: probing
for conduit method from DT.
[stdlog] 2023-07-10 19:04:08,929 console DEBUG| [ 0.000000] psci: PSCIv1.1
detected in firmware.
[stdlog] 2023-07-10 19:04:08,929 console DEBUG| [ 0.000000] psci: Using
standard PSCI v0.2 function IDs
[stdlog] 2023-07-10 19:04:08,930 console DEBUG| [ 0.000000] psci: Trusted OS
migration not required
[stdlog] 2023-07-10 19:04:08,930 console DEBUG| [ 0.000000] psci: SMC
Calling Convention v1.0
[stdlog] 2023-07-10 19:04:08,930 console DEBUG| [ 0.000000] percpu: Embedded
23 pages/cpu @(____ptrval____) s53528 r8192 d32488 u94208
[stdlog] 2023-07-10 19:04:08,930 console DEBUG| [ 0.000000] Detected VIPT
I-cache on CPU0
[stdlog] 2023-07-10 19:04:08,930 console DEBUG| [ 0.000000] CPU features:
enabling workaround for ARM erratum 843419
[stdlog] 2023-07-10 19:04:08,931 console DEBUG| [ 0.000000] CPU features:
detected: Kernel page table isolation (KPTI)
[stdlog] 2023-07-10 19:04:08,931 console DEBUG| [ 0.000000] Built 1
zonelists, mobility grouping on. Total pages: 32256
[stdlog] 2023-07-10 19:04:08,931 console DEBUG| [ 0.000000] Policy zone:
DMA32
[stdlog] 2023-07-10 19:04:08,931 console DEBUG| [ 0.000000] Kernel command
line: printk.time=1 panic=-1 console=ttyAMA0
[stdlog] 2023-07-10 19:04:08,931 console DEBUG| [ 0.000000] Memory:
87820K/131072K available (9980K kernel code, 1926K rwdata, 6664K rodata, 5760K
init, 913K bss, 43252K reserved, 0K cma-reserved)
[stdlog] 2023-07-10 19:04:08,932 console DEBUG| [ 0.000000] random:
get_random_u64 called from kmem_cache_open+0x40/0x4d0 with crng_init=0
[stdlog] 2023-07-10 19:04:08,932 console DEBUG| [ 0.000000] SLUB:
HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[stdlog] 2023-07-10 19:04:08,932 console DEBUG| [ 0.000000] ftrace:
allocating 37453 entries in 147 pages
[stdlog] 2023-07-10 19:04:08,932 console DEBUG| [ 0.000000] Hierarchical RCU
implementation.
[stdlog] 2023-07-10 19:04:08,933 console DEBUG| [ 0.000000] RCU restricting
CPUs from NR_CPUS=256 to nr_cpu_ids=1.
[stdlog] 2023-07-10 19:04:08,933 console DEBUG| [ 0.000000] Tasks RCU
enabled.
[stdlog] 2023-07-10 19:04:08,933 console DEBUG| [ 0.000000] RCU: Adjusting
geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
[stdlog] 2023-07-10 19:04:08,933 console DEBUG| [ 0.000000] NR_IRQS: 64,
nr_irqs: 64, preallocated irqs: 0
[stdlog] 2023-07-10 19:04:08,933 console DEBUG| [ 0.000000] GICv2m:
range[mem 0x08020000-0x08020fff], SPI[80:143]
[stdlog] 2023-07-10 19:04:08,934 console DEBUG| [ 0.000000] arch_timer: cp15
timer(s) running at 62.50MHz (virt).
[stdlog] 2023-07-10 19:04:08,934 console DEBUG| [ 0.000000] clocksource:
arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x1cd42e208c, max_idle_ns:
881590405314 ns
[stdlog] 2023-07-10 19:04:08,934 console DEBUG| [ 0.000330] sched_clock: 56
bits at 62MHz, resolution 16ns, wraps every 4398046511096ns
[stdlog] 2023-07-10 19:04:08,934 console DEBUG| [ 0.011417] Console: colour
dummy device 80x25
[stdlog] 2023-07-10 19:04:08,935 console DEBUG| [ 0.014079] Calibrating
delay loop (skipped), value calculated using timer frequency.. 125.00 BogoMIPS
(lpj=625000)
[stdlog] 2023-07-10 19:04:08,935 console DEBUG| [ 0.014912] pid_max:
default: 32768 minimum: 301
[stdlog] 2023-07-10 19:04:08,935 console DEBUG| [ 0.025265] Security
Framework initialized
[stdlog] 2023-07-10 19:04:08,935 console DEBUG| [ 0.025714] Yama: becoming
mindful.
[stdlog] 2023-07-10 19:04:08,935 console DEBUG| [ 0.026968] SELinux:
Initializing.
[stdlog] 2023-07-10 19:04:08,936 console DEBUG| [ 0.046515] Dentry cache
hash table entries: 16384 (order: 5, 131072 bytes)
[stdlog] 2023-07-10 19:04:08,936 console DEBUG| [ 0.050820] Inode-cache hash
table entries: 8192 (order: 4, 65536 bytes)
[stdlog] 2023-07-10 19:04:08,936 console DEBUG| [ 0.053372] Mount-cache hash
table entries: 512 (order: 0, 4096 bytes)
[stdlog] 2023-07-10 19:04:08,936 console DEBUG| [ 0.054236] Mountpoint-cache
hash table entries: 512 (order: 0, 4096 bytes)
[stdlog] 2023-07-10 19:04:08,937 console DEBUG| [ 0.115989] /cpus/cpu-map:
empty cluster
[stdlog] 2023-07-10 19:04:08,937 console DEBUG| [ 0.143134] ASID allocator
initialised with 32768 entries
[stdlog] 2023-07-10 19:04:08,937 console DEBUG| [ 0.149498] Hierarchical
SRCU implementation.
[stdlog] 2023-07-10 19:04:08,937 console DEBUG| [ 0.308603] EFI services
will not be available.
[stdlog] 2023-07-10 19:04:08,938 console DEBUG| [ 0.319371] smp: Bringing up
secondary CPUs ...
[stdlog] 2023-07-10 19:04:08,938 console DEBUG| [ 0.319926] smp: Brought up
1 node, 1 CPU
[stdlog] 2023-07-10 19:04:08,938 console DEBUG| [ 0.320365] SMP: Total of 1
processors activated.
[stdlog] 2023-07-10 19:04:08,938 console DEBUG| [ 0.320971] CPU features:
detected: 32-bit EL0 Support
[stdlog] 2023-07-10 19:04:08,938 console DEBUG| [ 0.523137] CPU features:
emulated: Privileged Access Never (PAN) using TTBR0_EL1 switching
[stdlog] 2023-07-10 19:04:08,939 console DEBUG| [ 0.523580] CPU: All CPU(s)
started at EL1
[stdlog] 2023-07-10 19:04:08,939 console DEBUG| [ 0.524339] alternatives:
patching kernel code
[stdlog] 2023-07-10 19:04:08,939 console DEBUG| [ 0.585197] devtmpfs:
initialized
[stdlog] 2023-07-10 19:04:08,939 console DEBUG| [ 0.750372] clocksource:
jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns:
19112604462750000 ns
[stdlog] 2023-07-10 19:04:08,939 console DEBUG| [ 0.752097] futex hash table
entries: 256 (order: 2, 16384 bytes)
[stdlog] 2023-07-10 19:04:08,940 console DEBUG| [ 0.762590] pinctrl core:
initialized pinctrl subsystem
[stdlog] 2023-07-10 19:04:08,940 console DEBUG| [ 0.808908] DMI not present
or invalid.
[stdlog] 2023-07-10 19:04:08,940 console DEBUG| [ 0.864635] NET: Registered
protocol family 16
[stdlog] 2023-07-10 19:04:08,940 console DEBUG| [ 0.877903] audit:
initializing netlink subsys (disabled)
[stdlog] 2023-07-10 19:04:08,940 console DEBUG| [ 0.889177] audit: type=2000
audit(0.800:1): state=initialized audit_enabled=0 res=1
[stdlog] 2023-07-10 19:04:08,941 console DEBUG| [ 0.942636] cpuidle: using
governor menu
[stdlog] 2023-07-10 19:04:08,941 console DEBUG| [ 0.946382] vdso: 2 pages (1
code @ (____ptrval____), 1 data @ (____ptrval____))
[stdlog] 2023-07-10 19:04:08,941 console DEBUG| [ 0.947486] hw-breakpoint:
found 6 breakpoint and 4 watchpoint registers.
[stdlog] 2023-07-10 19:04:08,941 console DEBUG| [ 0.954302] DMA:
preallocated 256 KiB pool for atomic allocations
[stdlog] 2023-07-10 19:04:08,942 console DEBUG| [ 0.969762] Serial: AMBA
PL011 UART driver
[stdlog] 2023-07-10 19:04:08,942 console DEBUG| [ 1.561587] 9000000.pl011:
ttyAMA0 at MMIO 0x9000000 (irq = 39, base_baud = 0) is a PL011 rev1
[stdlog] 2023-07-10 19:04:08,942 console DEBUG| [ 1.620438] console
[ttyAMA0] enabled
[stdlog] 2023-07-10 19:04:08,965 console DEBUG| [ 2.322499] HugeTLB
registered 2.00 MiB page size, pre-allocated 0 pages
[stdlog] 2023-07-10 19:04:08,967 console DEBUG| [ 2.341987] cryptd:
max_cpu_qlen set to 1000
[stdlog] 2023-07-10 19:04:08,970 console DEBUG| [ 2.386031] ACPI:
Interpreter disabled.
[stdlog] 2023-07-10 19:04:08,972 console DEBUG| [ 2.418443] vgaarb: loaded
[stdlog] 2023-07-10 19:04:08,973 console DEBUG| [ 2.442537] SCSI subsystem
initialized
[stdlog] 2023-07-10 19:04:08,975 console DEBUG| [ 2.463100] usbcore:
registered new interface driver usbfs
[stdlog] 2023-07-10 19:04:08,975 console DEBUG| [ 2.467717] usbcore:
registered new interface driver hub
[stdlog] 2023-07-10 19:04:08,976 console DEBUG| [ 2.471683] usbcore:
registered new device driver usb
[stdlog] 2023-07-10 19:04:08,976 console DEBUG| [ 2.482795] pps_core:
LinuxPPS API ver. 1 registered
[stdlog] 2023-07-10 19:04:08,977 console DEBUG| [ 2.483701] pps_core:
Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giome...@linux.it>
[stdlog] 2023-07-10 19:04:08,977 console DEBUG| [ 2.485604] PTP clock
support registered
[stdlog] 2023-07-10 19:04:08,977 console DEBUG| [ 2.494486] EDAC MC: Ver:
3.0.0
[stdlog] 2023-07-10 19:04:08,986 console DEBUG| [ 2.568880] NetLabel:
Initializing
[stdlog] 2023-07-10 19:04:08,986 console DEBUG| [ 2.569617] NetLabel:
domain hash size = 128
[stdlog] 2023-07-10 19:04:08,986 console DEBUG| [ 2.570912] NetLabel:
protocols = UNLABELED CIPSOv4 CALIPSO
[stdlog] 2023-07-10 19:04:08,987 console DEBUG| [ 2.575677] NetLabel:
unlabeled traffic allowed by default
[stdlog] 2023-07-10 19:04:08,989 console DEBUG| [ 2.586820] clocksource:
Switched to clocksource arch_sys_counter
[stdlog] 2023-07-10 19:04:09,166 console DEBUG| [ 8.650915] VFS: Disk quotas
dquot_6.6.0
[stdlog] 2023-07-10 19:04:09,167 console DEBUG| [ 8.654958] VFS: Dquot-cache
hash table entries: 512 (order 0, 4096 bytes)
[stdlog] 2023-07-10 19:04:09,169 console DEBUG| [ 8.672370] pnp: PnP ACPI:
disabled
[stdlog] 2023-07-10 19:04:09,189 console DEBUG| [ 9.119077] NET: Registered
protocol family 2
[stdlog] 2023-07-10 19:04:09,199 console DEBUG| [ 9.159414]
tcp_listen_portaddr_hash hash table entries: 256 (order: 0, 4096 bytes)
[stdlog] 2023-07-10 19:04:09,200 console DEBUG| [ 9.161712] TCP established
hash table entries: 1024 (order: 1, 8192 bytes)
[stdlog] 2023-07-10 19:04:09,209 console DEBUG| [ 9.164783] TCP bind hash
table entries: 1024 (order: 2, 16384 bytes)
[stdlog] 2023-07-10 19:04:09,209 console DEBUG| [ 9.168086] TCP: Hash tables
configured (established 1024 bind 1024)
[stdlog] 2023-07-10 19:04:09,211 console DEBUG| [ 9.172537] UDP hash table
entries: 256 (order: 1, 8192 bytes)
[stdlog] 2023-07-10 19:04:09,212 console DEBUG| [ 9.175319] UDP-Lite hash
table entries: 256 (order: 1, 8192 bytes)
[stdlog] 2023-07-10 19:04:09,212 console DEBUG| [ 9.185085] NET: Registered
protocol family 1
[stdlog] 2023-07-10 19:04:09,212 console DEBUG| [ 9.226294] hw perfevents:
enabled with armv8_pmuv3 PMU driver, 7 counters available
[stdlog] 2023-07-10 19:04:09,213 console DEBUG| [ 9.232265] kvm [1]: HYP
mode not available
[stdlog] 2023-07-10 19:04:09,310 console DEBUG| [ 10.497283] Initialise
system trusted keyrings
[stdlog] 2023-07-10 19:04:09,312 console DEBUG| [ 10.499065] Key type
blacklist registered
[stdlog] 2023-07-10 19:04:09,315 console DEBUG| [ 10.504496] workingset:
timestamp_bits=37 max_order=15 bucket_order=0
[stdlog] 2023-07-10 19:04:09,330 console DEBUG| [ 11.059756] zbud: loaded
[stdlog] 2023-07-10 19:04:09,337 console DEBUG| [ 11.169380] pstore: using
deflate compression
[stdlog] 2023-07-10 19:04:10,313 console DEBUG| [ 103.491326] alg: No test for
842 (842-generic)
[stdlog] 2023-07-10 19:04:10,315 console DEBUG| [ 103.499256] alg: No test for
842 (842-scomp)
[stdlog] 2023-07-10 19:04:10,344 console DEBUG| [ 104.039245] NET: Registered
protocol family 38
[stdlog] 2023-07-10 19:04:10,345 console DEBUG| [ 104.040306] Key type
asymmetric registered
[stdlog] 2023-07-10 19:04:10,345 console DEBUG| [ 104.041131] Asymmetric key
parser 'x509' registered
[stdlog] 2023-07-10 19:04:10,345 console DEBUG| [ 104.053427] Block layer SCSI
generic (bsg) driver version 0.4 loaded (major 245)
[stdlog] 2023-07-10 19:04:10,346 console DEBUG| [ 104.059820] io scheduler
noop registered
[stdlog] 2023-07-10 19:04:10,347 console DEBUG| [ 104.060661] io scheduler
deadline registered
[stdlog] 2023-07-10 19:04:10,347 console DEBUG| [ 104.072059] io scheduler cfq
registered (default)
[stdlog] 2023-07-10 19:04:10,348 console DEBUG| [ 104.072990] io scheduler
mq-deadline registered
[stdlog] 2023-07-10 19:04:10,352 console DEBUG| [ 104.089802] atomic64_test:
passed
[stdlog] 2023-07-10 19:04:10,363 console DEBUG| [ 104.317820] pl061_gpio
9030000.pl061: PL061 GPIO chip @0x0000000009030000 registered
[stdlog] 2023-07-10 19:04:10,365 console DEBUG| [ 104.379342] pci-host-generic
4010000000.pcie: host bridge /pcie@10000000 ranges:
[stdlog] 2023-07-10 19:04:10,366 console DEBUG| [ 104.381394] pci-host-generic
4010000000.pcie: IO 0x3eff0000..0x3effffff -> 0x00000000
[stdlog] 2023-07-10 19:04:10,368 console DEBUG| [ 104.383465] pci-host-generic
4010000000.pcie: MEM 0x10000000..0x3efeffff -> 0x10000000
[stdlog] 2023-07-10 19:04:10,369 console DEBUG| [ 104.385314] pci-host-generic
4010000000.pcie: MEM 0x8000000000..0xffffffffff -> 0x8000000000
[stdlog] 2023-07-10 19:04:10,369 console DEBUG| [ 104.390742] pci-host-generic
4010000000.pcie: ECAM at [mem 0x4010000000-0x401fffffff] for [bus 00-ff]
[stdlog] 2023-07-10 19:04:10,369 console DEBUG| [ 104.399367] pci-host-generic
4010000000.pcie: PCI host bridge to bus 0000:00
[stdlog] 2023-07-10 19:04:10,370 console DEBUG| [ 104.400749] pci_bus 0000:00:
root bus resource [bus 00-ff]
[stdlog] 2023-07-10 19:04:10,371 console DEBUG| [ 104.402010] pci_bus 0000:00:
root bus resource [io 0x0000-0xffff]
[stdlog] 2023-07-10 19:04:10,372 console DEBUG| [ 104.403360] pci_bus 0000:00:
root bus resource [mem 0x10000000-0x3efeffff]
[stdlog] 2023-07-10 19:04:10,372 console DEBUG| [ 104.404781] pci_bus 0000:00:
root bus resource [mem 0x8000000000-0xffffffffff]
[stdlog] 2023-07-10 19:04:10,393 console DEBUG| [ 104.962070] Serial:
8250/16550 driver, 32 ports, IRQ sharing enabled
[stdlog] 2023-07-10 19:04:10,423 console DEBUG| [ 105.602232] msm_serial:
driver initialized
[stdlog] 2023-07-10 19:04:10,430 console DEBUG| [ 105.682254] cacheinfo:
Unable to detect cache hierarchy for CPU 0
[stdlog] 2023-07-10 19:04:10,435 console DEBUG| [ 105.746043] libphy: Fixed
MDIO Bus: probed
[stdlog] 2023-07-10 19:04:10,437 console DEBUG| [ 105.757452] ehci_hcd: USB
2.0 'Enhanced' Host Controller (EHCI) Driver
[stdlog] 2023-07-10 19:04:10,438 console DEBUG| [ 105.758816] ehci-pci: EHCI
PCI platform driver
[stdlog] 2023-07-10 19:04:10,439 console DEBUG| [ 105.761675] ohci_hcd: USB
1.1 'Open' Host Controller (OHCI) Driver
[stdlog] 2023-07-10 19:04:10,440 console DEBUG| [ 105.763015] ohci-pci: OHCI
PCI platform driver
[stdlog] 2023-07-10 19:04:10,441 console DEBUG| [ 105.765893] uhci_hcd: USB
Universal Host Controller Interface driver
[stdlog] 2023-07-10 19:04:10,442 console DEBUG| [ 105.778801] usbcore:
registered new interface driver usbserial_generic
[stdlog] 2023-07-10 19:04:10,442 console DEBUG| [ 105.781237] usbserial: USB
Serial support registered for generic
[stdlog] 2023-07-10 19:04:10,443 console DEBUG| [ 105.790126] mousedev: PS/2
mouse device common for all mice
[stdlog] 2023-07-10 19:04:10,445 console DEBUG| [ 105.818561] rtc-pl031
9010000.pl031: rtc core: registered pl031 as rtc0
[stdlog] 2023-07-10 19:04:10,448 console DEBUG| [ 105.913014] device-mapper:
uevent: version 1.0.3
[stdlog] 2023-07-10 19:04:10,449 console DEBUG| [ 105.930526] device-mapper:
ioctl: 4.39.0-ioctl (2018-04-03) initialised: dm-de...@redhat.com
[stdlog] 2023-07-10 19:04:10,452 console DEBUG| [ 105.965130] ledtrig-cpu:
registered to indicate activity on CPUs
[stdlog] 2023-07-10 19:04:10,453 console DEBUG| [ 105.994600] hidraw: raw HID
events driver (C) Jiri Kosina
[stdlog] 2023-07-10 19:04:10,454 console DEBUG| [ 106.007912] usbcore:
registered new interface driver usbhid
[stdlog] 2023-07-10 19:04:10,455 console DEBUG| [ 106.008795] usbhid: USB HID
core driver
[stdlog] 2023-07-10 19:04:10,457 console DEBUG| [ 106.078877] drop_monitor:
Initializing network drop monitor service
[stdlog] 2023-07-10 19:04:10,461 console DEBUG| [ 106.094963] Initializing
XFRM netlink socket
[stdlog] 2023-07-10 19:04:10,463 console DEBUG| [ 106.145133] NET: Registered
protocol family 10
[stdlog] 2023-07-10 19:04:10,474 console DEBUG| [ 106.251367] Segment Routing
with IPv6
[stdlog] 2023-07-10 19:04:10,476 console DEBUG| [ 106.256292] mip6: Mobile IPv6
[stdlog] 2023-07-10 19:04:10,477 console DEBUG| [ 106.260743] NET: Registered
protocol family 17
[stdlog] 2023-07-10 19:04:10,479 console DEBUG| [ 106.302378] registered
taskstats version 1
[stdlog] 2023-07-10 19:04:10,479 console DEBUG| [ 106.304382] Loading
compiled-in X.509 certificates
[stdlog] 2023-07-10 19:04:10,694 console DEBUG| [ 127.745022] Loaded X.509
cert 'Fedora kernel signing key: 7f602be4cb818df6a720b272cd54e21962384370'
[stdlog] 2023-07-10 19:04:10,696 console DEBUG| [ 127.749381] zswap: loaded
using pool lzo/zbud
[stdlog] 2023-07-10 19:04:10,704 console DEBUG| [ 127.886379] Key type big_key
registered
[stdlog] 2023-07-10 19:04:10,708 console DEBUG| [ 127.956493] Key type
encrypted registered
[stdlog] 2023-07-10 19:04:10,709 console DEBUG| [ 127.959112] ima: No TPM chip
found, activating TPM-bypass! (rc=-19)
[stdlog] 2023-07-10 19:04:10,710 console DEBUG| [ 127.961057] ima: Allocated
hash algorithm: sha1
[stdlog] 2023-07-10 19:04:10,712 console DEBUG| [ 127.979427] rtc-pl031
9010000.pl031: setting system clock to 2023-07-10 17:04:10 UTC (1689008650)
[stdlog] 2023-07-10 19:04:10,723 console DEBUG| [ 128.575661] uart-pl011
9000000.pl011: no DMA platform data
[stdlog] 2023-07-10 19:04:10,724 console DEBUG| [ 128.580392] md: Waiting for
all devices to be available before autodetect
[stdlog] 2023-07-10 19:04:10,726 console DEBUG| [ 128.581395] md: If you don't
use raid, use raid=noautodetect
[stdlog] 2023-07-10 19:04:10,731 console DEBUG| [ 128.618348] md:
Autodetecting RAID arrays.
[stdlog] 2023-07-10 19:04:10,732 console DEBUG| [ 128.619108] md: autorun ...
[stdlog] 2023-07-10 19:04:10,732 console DEBUG| [ 128.619755] md: ... autorun
DONE.
[stdlog] 2023-07-10 19:04:10,733 console DEBUG| [ 128.628620] VFS: Cannot open
root device "(null)" or unknown-block(0,0): error -6
[stdlog] 2023-07-10 19:04:10,735 qemu.machine.machine DEBUG| Shutting down VM
appliance; timeout=30
[stdlog] 2023-07-10 19:04:10,736 qemu.machine.machine DEBUG| Attempting
graceful termination
[stdlog] 2023-07-10 19:04:10,737 qemu.machine.machine DEBUG| Closing console
socket
[stdlog] 2023-07-10 19:04:10,738 qemu.machine.machine DEBUG| Politely asking
QEMU to terminate
[stdlog] 2023-07-10 19:04:10,740 qemu.qmp.qmp_client.101e41690 DEBUG| --> {
[stdlog] "execute": "quit"
[stdlog] }
[stdlog] 2023-07-10 19:04:10,741 qemu.qmp.qmp_client.101e41690 DEBUG| <-- {
[stdlog] "timestamp": {
[stdlog] "seconds": 1689008650,
[stdlog] "microseconds": 736526
[stdlog] },
[stdlog] "event": "SHUTDOWN",
[stdlog] "data": {
[stdlog] "guest": true,
[stdlog] "reason": "guest-reset"
[stdlog] }
[stdlog] }
[stdlog] 2023-07-10 19:04:10,742 qemu.qmp.qmp_client.101e41690 ERROR|
Task.Reader: BrokenPipeError: [Errno 32] Broken pipe
[stdlog] 2023-07-10 19:04:10,747 qemu.qmp.qmp_client.101e41690 DEBUG|
Task.Reader: failure:
[stdlog] | Traceback (most recent call last):
[stdlog] | File "/Users/philmd/source/qemu/python/qemu/qmp/protocol.py",
line 871, in _bh_loop_forever
[stdlog] | await async_fn()
[stdlog] | File "/Users/philmd/source/qemu/python/qemu/qmp/protocol.py",
line 909, in _bh_recv_message
[stdlog] | msg = await self._recv()
[stdlog] | ^^^^^^^^^^^^^^^^^^
[stdlog] | File "/Users/philmd/source/qemu/python/qemu/qmp/protocol.py",
line 1010, in _recv
[stdlog] | message = await self._do_recv()
[stdlog] | ^^^^^^^^^^^^^^^^^^^^^
[stdlog] | File "/Users/philmd/source/qemu/python/qemu/qmp/qmp_client.py",
line 402, in _do_recv
[stdlog] | msg_bytes = await self._readline()
[stdlog] | ^^^^^^^^^^^^^^^^^^^^^^
[stdlog] | File "/Users/philmd/source/qemu/python/qemu/qmp/protocol.py",
line 974, in _readline
[stdlog] | msg_bytes = await self._reader.readline()
[stdlog] | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] | File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/streams.py",
line 545, in readline
[stdlog] | line = await self.readuntil(sep)
[stdlog] | ^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] | File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/streams.py",
line 637, in readuntil
[stdlog] | await self._wait_for_data('readuntil')
[stdlog] | File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/streams.py",
line 522, in _wait_for_data
[stdlog] | await self._waiter
[stdlog] | File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/selector_events.py",
line 1057, in write
[stdlog] | n = self._sock.send(data)
[stdlog] | ^^^^^^^^^^^^^^^^^^^^^
[stdlog] | BrokenPipeError: [Errno 32] Broken pipe
[stdlog] 2023-07-10 19:04:10,748 qemu.qmp.qmp_client.101e41690 DEBUG|
Transitioning from 'Runstate.RUNNING' to 'Runstate.DISCONNECTING'.
[stdlog] 2023-07-10 19:04:10,748 qemu.qmp.qmp_client.101e41690 DEBUG|
Scheduling disconnect.
[stdlog] 2023-07-10 19:04:10,749 qemu.qmp.qmp_client.101e41690 DEBUG|
Task.Reader: exiting.
[stdlog] 2023-07-10 19:04:10,750 qemu.qmp.qmp_client.101e41690 DEBUG|
Cancelling writer task.
[stdlog] 2023-07-10 19:04:10,751 qemu.qmp.qmp_client.101e41690 DEBUG| Waiting
for tasks to complete ...
[stdlog] 2023-07-10 19:04:10,751 qemu.qmp.qmp_client.101e41690 DEBUG|
Task.Writer: cancelled.
[stdlog] 2023-07-10 19:04:10,752 qemu.qmp.qmp_client.101e41690 DEBUG|
Task.Writer: exiting.
[stdlog] 2023-07-10 19:04:10,752 qemu.qmp.qmp_client.101e41690 DEBUG| Waiting
for StreamWriter to close ...
[stdlog] 2023-07-10 19:04:10,754 qemu.qmp.qmp_client.101e41690 DEBUG|
Discarding Exception from wait_closed:
[stdlog] | Traceback (most recent call last):
[stdlog] | File "/Users/philmd/source/qemu/python/qemu/qmp/protocol.py",
line 835, in _bh_close_stream
[stdlog] | await wait_closed(self._writer)
[stdlog] | File "/Users/philmd/source/qemu/python/qemu/qmp/util.py", line
130, in wait_closed
[stdlog] | await writer.wait_closed()
[stdlog] | File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/streams.py",
line 350, in wait_closed
[stdlog] | await self._protocol._get_close_waiter(self)
[stdlog] | File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/selector_events.py",
line 1057, in write
[stdlog] | n = self._sock.send(data)
[stdlog] | ^^^^^^^^^^^^^^^^^^^^^
[stdlog] | BrokenPipeError: [Errno 32] Broken pipe
[stdlog] 2023-07-10 19:04:10,755 qemu.qmp.qmp_client.101e41690 DEBUG|
StreamWriter closed.
[stdlog] 2023-07-10 19:04:10,755 qemu.qmp.qmp_client.101e41690 DEBUG|
Disconnected.
[stdlog] 2023-07-10 19:04:10,756 qemu.qmp.qmp_client.101e41690 DEBUG|
Cancelling pending executions
[stdlog] 2023-07-10 19:04:10,756 qemu.qmp.qmp_client.101e41690 DEBUG|
Cancelling execution 'None'
[stdlog] 2023-07-10 19:04:10,757 qemu.qmp.qmp_client.101e41690 DEBUG| QMP
Disconnected.
[stdlog] 2023-07-10 19:04:10,758 qemu.qmp.qmp_client.101e41690 DEBUG|
disconnect() called.
[stdlog] 2023-07-10 19:04:10,759 qemu.qmp.qmp_client.101e41690 DEBUG|
Transitioning from 'Runstate.DISCONNECTING' to 'Runstate.IDLE'.
[stdlog] 2023-07-10 19:04:10,760 qemu.machine.machine DEBUG| Graceful shutdown
failed
[stdlog] Traceback (most recent call last):
[stdlog] File "/Users/philmd/source/qemu/python/qemu/machine/machine.py",
line 558, in _soft_shutdown
[stdlog] self.qmp('quit')
[stdlog] File "/Users/philmd/source/qemu/python/qemu/machine/machine.py",
line 689, in qmp
[stdlog] ret = self._qmp.cmd(cmd, args=qmp_args)
[stdlog] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] File "/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line
212, in cmd
[stdlog] return self.cmd_obj(qmp_cmd)
[stdlog] ^^^^^^^^^^^^^^^^^^^^^
[stdlog] File "/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line
186, in cmd_obj
[stdlog] self._sync(
[stdlog] File "/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line
102, in _sync
[stdlog] return self._aloop.run_until_complete(
[stdlog] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/base_events.py",
line 653, in run_until_complete
[stdlog] return future.result()
[stdlog] ^^^^^^^^^^^^^^^
[stdlog] File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/tasks.py",
line 442, in wait_for
[stdlog] return await fut
[stdlog] ^^^^^^^^^
[stdlog] File "/Users/philmd/source/qemu/python/qemu/qmp/qmp_client.py", line
547, in _raw
[stdlog] return await self._execute(msg, assign_id=assign_id)
[stdlog] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] File "/Users/philmd/source/qemu/python/qemu/qmp/qmp_client.py", line
496, in _execute
[stdlog] return await self._reply(exec_id)
[stdlog] ^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] File "/Users/philmd/source/qemu/python/qemu/qmp/qmp_client.py", line
463, in _reply
[stdlog] raise result
[stdlog] qemu.qmp.qmp_client.ExecInterruptedError: Disconnected
[stdlog]
[stdlog] During handling of the above exception, another exception occurred:
[stdlog]
[stdlog] Traceback (most recent call last):
[stdlog] File "/Users/philmd/source/qemu/python/qemu/machine/machine.py",
line 589, in _do_shutdown
[stdlog] self._soft_shutdown(timeout)
[stdlog] File "/Users/philmd/source/qemu/python/qemu/machine/machine.py",
line 561, in _soft_shutdown
[stdlog] self._close_qmp_connection()
[stdlog] File "/Users/philmd/source/qemu/python/qemu/machine/machine.py",
line 489, in _close_qmp_connection
[stdlog] self._qmp.close()
[stdlog] File "/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line
285, in close
[stdlog] self._sync(
[stdlog] File "/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line
102, in _sync
[stdlog] return self._aloop.run_until_complete(
[stdlog] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/base_events.py",
line 653, in run_until_complete
[stdlog] return future.result()
[stdlog] ^^^^^^^^^^^^^^^
[stdlog] File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/tasks.py",
line 442, in wait_for
[stdlog] return await fut
[stdlog] ^^^^^^^^^
[stdlog] File "/Users/philmd/source/qemu/python/qemu/qmp/protocol.py", line
399, in disconnect
[stdlog] await self._wait_disconnect()
[stdlog] File "/Users/philmd/source/qemu/python/qemu/qmp/protocol.py", line
720, in _wait_disconnect
[stdlog] await all_defined_tasks # Raise Exceptions from the bottom half.
[stdlog] ^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] File "/Users/philmd/source/qemu/python/qemu/qmp/protocol.py", line
835, in _bh_close_stream
[stdlog] await wait_closed(self._writer)
[stdlog] File "/Users/philmd/source/qemu/python/qemu/qmp/util.py", line 130,
in wait_closed
[stdlog] await writer.wait_closed()
[stdlog] File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/streams.py",
line 350, in wait_closed
[stdlog] await self._protocol._get_close_waiter(self)
[stdlog] File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/selector_events.py",
line 1057, in write
[stdlog] n = self._sock.send(data)
[stdlog] ^^^^^^^^^^^^^^^^^^^^^
[stdlog] BrokenPipeError: [Errno 32] Broken pipe
[stdlog] 2023-07-10 19:04:10,765 qemu.machine.machine DEBUG| Falling back to
hard shutdown
[stdlog] 2023-07-10 19:04:10,765 qemu.machine.machine DEBUG| Performing hard
shutdown
[stdlog] 2023-07-10 19:04:10,766 qemu.machine.machine DEBUG| Cleaning up after
VM process
[stdlog] 2023-07-10 19:04:10,767 avocado.test ERROR|
[stdlog] 2023-07-10 19:04:10,768 avocado.test ERROR| Reproduced traceback from:
/Users/philmd/build/tests/venv/lib/python3.11/site-packages/avocado/core/test.py:631
[stdlog] 2023-07-10 19:04:10,771 avocado.test ERROR| Traceback (most recent
call last):
[stdlog] 2023-07-10 19:04:10,772 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 558, in
_soft_shutdown
[stdlog] 2023-07-10 19:04:10,772 avocado.test ERROR| self.qmp('quit')
[stdlog] 2023-07-10 19:04:10,773 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 689, in qmp
[stdlog] 2023-07-10 19:04:10,773 avocado.test ERROR| ret =
self._qmp.cmd(cmd, args=qmp_args)
[stdlog] 2023-07-10 19:04:10,774 avocado.test ERROR|
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,775 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line 212, in cmd
[stdlog] 2023-07-10 19:04:10,775 avocado.test ERROR| return
self.cmd_obj(qmp_cmd)
[stdlog] 2023-07-10 19:04:10,776 avocado.test ERROR|
^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,777 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line 186, in cmd_obj
[stdlog] 2023-07-10 19:04:10,778 avocado.test ERROR| self._sync(
[stdlog] 2023-07-10 19:04:10,778 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line 102, in _sync
[stdlog] 2023-07-10 19:04:10,780 avocado.test ERROR| return
self._aloop.run_until_complete(
[stdlog] 2023-07-10 19:04:10,781 avocado.test ERROR|
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,782 avocado.test ERROR| File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/base_events.py",
line 653, in run_until_complete
[stdlog] 2023-07-10 19:04:10,783 avocado.test ERROR| return future.result()
[stdlog] 2023-07-10 19:04:10,784 avocado.test ERROR| ^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,785 avocado.test ERROR| File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/tasks.py",
line 442, in wait_for
[stdlog] 2023-07-10 19:04:10,786 avocado.test ERROR| return await fut
[stdlog] 2023-07-10 19:04:10,787 avocado.test ERROR| ^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,787 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/qmp_client.py", line 547, in _raw
[stdlog] 2023-07-10 19:04:10,789 avocado.test ERROR| return await
self._execute(msg, assign_id=assign_id)
[stdlog] 2023-07-10 19:04:10,790 avocado.test ERROR|
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,791 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/qmp_client.py", line 496, in _execute
[stdlog] 2023-07-10 19:04:10,792 avocado.test ERROR| return await
self._reply(exec_id)
[stdlog] 2023-07-10 19:04:10,793 avocado.test ERROR|
^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,794 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/qmp_client.py", line 463, in _reply
[stdlog] 2023-07-10 19:04:10,795 avocado.test ERROR| raise result
[stdlog] 2023-07-10 19:04:10,796 avocado.test ERROR|
qemu.qmp.qmp_client.ExecInterruptedError: Disconnected
[stdlog] 2023-07-10 19:04:10,797 avocado.test ERROR|
[stdlog] 2023-07-10 19:04:10,799 avocado.test ERROR| During handling of the
above exception, another exception occurred:
[stdlog] 2023-07-10 19:04:10,800 avocado.test ERROR|
[stdlog] 2023-07-10 19:04:10,801 avocado.test ERROR| Traceback (most recent
call last):
[stdlog] 2023-07-10 19:04:10,801 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 589, in
_do_shutdown
[stdlog] 2023-07-10 19:04:10,802 avocado.test ERROR|
self._soft_shutdown(timeout)
[stdlog] 2023-07-10 19:04:10,803 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 561, in
_soft_shutdown
[stdlog] 2023-07-10 19:04:10,804 avocado.test ERROR|
self._close_qmp_connection()
[stdlog] 2023-07-10 19:04:10,805 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 489, in
_close_qmp_connection
[stdlog] 2023-07-10 19:04:10,805 avocado.test ERROR| self._qmp.close()
[stdlog] 2023-07-10 19:04:10,806 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line 285, in close
[stdlog] 2023-07-10 19:04:10,807 avocado.test ERROR| self._sync(
[stdlog] 2023-07-10 19:04:10,808 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line 102, in _sync
[stdlog] 2023-07-10 19:04:10,808 avocado.test ERROR| return
self._aloop.run_until_complete(
[stdlog] 2023-07-10 19:04:10,809 avocado.test ERROR|
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,810 avocado.test ERROR| File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/base_events.py",
line 653, in run_until_complete
[stdlog] 2023-07-10 19:04:10,811 avocado.test ERROR| return future.result()
[stdlog] 2023-07-10 19:04:10,811 avocado.test ERROR| ^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,812 avocado.test ERROR| File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/tasks.py",
line 442, in wait_for
[stdlog] 2023-07-10 19:04:10,813 avocado.test ERROR| return await fut
[stdlog] 2023-07-10 19:04:10,814 avocado.test ERROR| ^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,814 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/protocol.py", line 399, in disconnect
[stdlog] 2023-07-10 19:04:10,815 avocado.test ERROR| await
self._wait_disconnect()
[stdlog] 2023-07-10 19:04:10,816 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/protocol.py", line 720, in
_wait_disconnect
[stdlog] 2023-07-10 19:04:10,817 avocado.test ERROR| await
all_defined_tasks # Raise Exceptions from the bottom half.
[stdlog] 2023-07-10 19:04:10,818 avocado.test ERROR| ^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,819 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/protocol.py", line 835, in
_bh_close_stream
[stdlog] 2023-07-10 19:04:10,820 avocado.test ERROR| await
wait_closed(self._writer)
[stdlog] 2023-07-10 19:04:10,820 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/util.py", line 130, in wait_closed
[stdlog] 2023-07-10 19:04:10,821 avocado.test ERROR| await
writer.wait_closed()
[stdlog] 2023-07-10 19:04:10,822 avocado.test ERROR| File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/streams.py",
line 350, in wait_closed
[stdlog] 2023-07-10 19:04:10,823 avocado.test ERROR| await
self._protocol._get_close_waiter(self)
[stdlog] 2023-07-10 19:04:10,824 avocado.test ERROR| File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/selector_events.py",
line 1057, in write
[stdlog] 2023-07-10 19:04:10,825 avocado.test ERROR| n =
self._sock.send(data)
[stdlog] 2023-07-10 19:04:10,826 avocado.test ERROR|
^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,827 avocado.test ERROR| BrokenPipeError: [Errno
32] Broken pipe
[stdlog] 2023-07-10 19:04:10,828 avocado.test ERROR|
[stdlog] 2023-07-10 19:04:10,828 avocado.test ERROR| The above exception was
the direct cause of the following exception:
[stdlog] 2023-07-10 19:04:10,830 avocado.test ERROR|
[stdlog] 2023-07-10 19:04:10,831 avocado.test ERROR| Traceback (most recent
call last):
[stdlog] 2023-07-10 19:04:10,831 avocado.test ERROR| File
"/Users/philmd/build/tests/avocado/replay_kernel.py", line 162, in
test_aarch64_virt
[stdlog] 2023-07-10 19:04:10,833 avocado.test ERROR|
self.run_rr(kernel_path, kernel_command_line, console_pattern)
[stdlog] 2023-07-10 19:04:10,833 avocado.test ERROR| File
"/Users/philmd/build/tests/avocado/replay_kernel.py", line 76, in run_rr
[stdlog] 2023-07-10 19:04:10,834 avocado.test ERROR| t1 =
self.run_vm(kernel_path, kernel_command_line, console_pattern,
[stdlog] 2023-07-10 19:04:10,835 avocado.test ERROR|
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,836 avocado.test ERROR| File
"/Users/philmd/build/tests/avocado/replay_kernel.py", line 63, in run_vm
[stdlog] 2023-07-10 19:04:10,837 avocado.test ERROR| vm.shutdown()
[stdlog] 2023-07-10 19:04:10,837 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 626, in
shutdown
[stdlog] 2023-07-10 19:04:10,838 avocado.test ERROR|
self._do_shutdown(timeout)
[stdlog] 2023-07-10 19:04:10,839 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 596, in
_do_shutdown
[stdlog] 2023-07-10 19:04:10,841 avocado.test ERROR| raise
AbnormalShutdown("Could not perform graceful shutdown") \
[stdlog] 2023-07-10 19:04:10,841 avocado.test ERROR|
qemu.machine.machine.AbnormalShutdown: Could not perform graceful shutdown
[stdlog] 2023-07-10 19:04:10,842 avocado.test ERROR|
[stdlog] 2023-07-10 19:04:10,843 avocado.test DEBUG| Local variables:
[stdlog] 2023-07-10 19:04:10,927 avocado.test DEBUG| -> self <class
'replay_kernel.ReplayKernelNormal'>:
1-tests/avocado/replay_kernel.py:ReplayKernelNormal.test_aarch64_virt
[stdlog] 2023-07-10 19:04:10,930 avocado.test DEBUG| -> kernel_url <class
'str'>:
https://archives.fedoraproject.org/pub/archive/fedora/linux/releases/29/Everything/aarch64/os/images/pxeboot/vmlinuz
[stdlog] 2023-07-10 19:04:10,930 avocado.test DEBUG| -> kernel_hash <class
'str'>: 8c73e469fc6ea06a58dc83a628fc695b693b8493
[stdlog] 2023-07-10 19:04:10,931 avocado.test DEBUG| -> kernel_path <class
'str'>:
/Users/philmd/avocado/data/cache/by_location/a00ac4ae676ef0322126abd2f7d38f50cc9cbc95/vmlinuz
[stdlog] 2023-07-10 19:04:10,931 avocado.test DEBUG| -> kernel_command_line
<class 'str'>: printk.time=1 panic=-1 console=ttyAMA0
[stdlog] 2023-07-10 19:04:10,931 avocado.test DEBUG| -> console_pattern <class
'str'>: VFS: Cannot open root device
[stdlog] 2023-07-10 19:04:10,937 avocado.test ERROR| Traceback (most recent
call last):
[stdlog] 2023-07-10 19:04:10,937 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 558, in
_soft_shutdown
[stdlog] self.qmp('quit')
[stdlog] 2023-07-10 19:04:10,937 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 689, in qmp
[stdlog] ret = self._qmp.cmd(cmd, args=qmp_args)
[stdlog] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,937 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line 212, in cmd
[stdlog] return self.cmd_obj(qmp_cmd)
[stdlog] ^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,938 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line 186, in cmd_obj
[stdlog] self._sync(
[stdlog] 2023-07-10 19:04:10,938 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line 102, in _sync
[stdlog] return self._aloop.run_until_complete(
[stdlog] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,939 avocado.test ERROR| File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/base_events.py",
line 653, in run_until_complete
[stdlog] return future.result()
[stdlog] ^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,940 avocado.test ERROR| File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/tasks.py",
line 442, in wait_for
[stdlog] return await fut
[stdlog] ^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,941 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/qmp_client.py", line 547, in _raw
[stdlog] return await self._execute(msg, assign_id=assign_id)
[stdlog] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,941 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/qmp_client.py", line 496, in _execute
[stdlog] return await self._reply(exec_id)
[stdlog] ^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,942 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/qmp_client.py", line 463, in _reply
[stdlog] raise result
[stdlog] 2023-07-10 19:04:10,942 avocado.test ERROR|
qemu.qmp.qmp_client.ExecInterruptedError: Disconnected
[stdlog] 2023-07-10 19:04:10,943 avocado.test ERROR|
[stdlog] During handling of the above exception, another exception occurred:
[stdlog]
[stdlog] 2023-07-10 19:04:10,944 avocado.test ERROR| Traceback (most recent
call last):
[stdlog] 2023-07-10 19:04:10,945 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 589, in
_do_shutdown
[stdlog] self._soft_shutdown(timeout)
[stdlog] 2023-07-10 19:04:10,945 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 561, in
_soft_shutdown
[stdlog] self._close_qmp_connection()
[stdlog] 2023-07-10 19:04:10,947 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 489, in
_close_qmp_connection
[stdlog] self._qmp.close()
[stdlog] 2023-07-10 19:04:10,947 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line 285, in close
[stdlog] self._sync(
[stdlog] 2023-07-10 19:04:10,948 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/legacy.py", line 102, in _sync
[stdlog] return self._aloop.run_until_complete(
[stdlog] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,950 avocado.test ERROR| File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/base_events.py",
line 653, in run_until_complete
[stdlog] return future.result()
[stdlog] ^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,951 avocado.test ERROR| File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/tasks.py",
line 442, in wait_for
[stdlog] return await fut
[stdlog] ^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,951 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/protocol.py", line 399, in disconnect
[stdlog] await self._wait_disconnect()
[stdlog] 2023-07-10 19:04:10,952 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/protocol.py", line 720, in
_wait_disconnect
[stdlog] await all_defined_tasks # Raise Exceptions from the bottom half.
[stdlog] ^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:10,953 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/protocol.py", line 835, in
_bh_close_stream
[stdlog] await wait_closed(self._writer)
[stdlog] 2023-07-10 19:04:10,954 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/qmp/util.py", line 130, in wait_closed
[stdlog] await writer.wait_closed()
[stdlog] 2023-07-10 19:04:10,964 avocado.test ERROR| File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/streams.py",
line 350, in wait_closed
[stdlog] await self._protocol._get_close_waiter(self)
[stdlog] 2023-07-10 19:04:10,988 avocado.test ERROR| File
"/opt/homebrew/Cellar/python@3.11/3.11.4/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/selector_events.py",
line 1057, in write
[stdlog] n = self._sock.send(data)
[stdlog] ^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:11,012 avocado.test ERROR| BrokenPipeError: [Errno
32] Broken pipe
[stdlog] 2023-07-10 19:04:11,013 avocado.test ERROR|
[stdlog] The above exception was the direct cause of the following exception:
[stdlog]
[stdlog] 2023-07-10 19:04:11,025 avocado.test ERROR| Traceback (most recent
call last):
[stdlog] 2023-07-10 19:04:11,037 avocado.test ERROR| File
"/Users/philmd/build/tests/venv/lib/python3.11/site-packages/avocado/core/test.py",
line 639, in _run_test
[stdlog] raise details
[stdlog] 2023-07-10 19:04:11,061 avocado.test ERROR| File
"/Users/philmd/build/tests/venv/lib/python3.11/site-packages/avocado/core/test.py",
line 626, in _run_test
[stdlog] testMethod()
[stdlog] 2023-07-10 19:04:11,083 avocado.test ERROR| File
"/Users/philmd/build/tests/avocado/replay_kernel.py", line 162, in
test_aarch64_virt
[stdlog] self.run_rr(kernel_path, kernel_command_line, console_pattern)
[stdlog] 2023-07-10 19:04:11,108 avocado.test ERROR| File
"/Users/philmd/build/tests/avocado/replay_kernel.py", line 76, in run_rr
[stdlog] t1 = self.run_vm(kernel_path, kernel_command_line, console_pattern,
[stdlog] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[stdlog] 2023-07-10 19:04:11,143 avocado.test ERROR| File
"/Users/philmd/build/tests/avocado/replay_kernel.py", line 63, in run_vm
[stdlog] vm.shutdown()
[stdlog] 2023-07-10 19:04:11,144 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 626, in
shutdown
[stdlog] self._do_shutdown(timeout)
[stdlog] 2023-07-10 19:04:11,156 avocado.test ERROR| File
"/Users/philmd/source/qemu/python/qemu/machine/machine.py", line 596, in
_do_shutdown
[stdlog] raise AbnormalShutdown("Could not perform graceful shutdown") \
[stdlog] 2023-07-10 19:04:11,168 avocado.test ERROR|
qemu.machine.machine.AbnormalShutdown: Could not perform graceful shutdown
[stdlog] 2023-07-10 19:04:11,171 avocado.test ERROR| ERROR
1-tests/avocado/replay_kernel.py:ReplayKernelNormal.test_aarch64_virt ->
AbnormalShutdown: Could not perform graceful shutdown
[stdlog] 2023-07-10 19:04:11,172 avocado.test INFO |
