tests/acceptance/boot_linux_console.py:BootLinuxConsole.test_arm_raspi2_initrd can not perform graceful shutdown
Host environment
- Operating system: Fedora 34
- OS/kernel version: Linux hostname 5.13.14-200.fc34.x86_64 #1 SMP Fri Sep 3 15:33:01 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
- Architecture: x86
- QEMU flavor: qemu-system-arm
- QEMU version: QEMU emulator version 6.1.50 (v6.1.0-808-g73257aa0)
- QEMU command line:
./qemu-system-arm -display none -vga none -chardev socket,id=mon,path=/var/tmp/avo_qemu_sock_hd3upfg6/qemu-2435532-monitor.sock -mon chardev=mon,mode=control -machine raspi2b -chardev socket,id=console,path=/var/tmp/avo_qemu_sock_hd3upfg6/qemu-2435532-console.sock,server=on,wait=off -serial chardev:console -kernel /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/boot/kernel7.img -dtb /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/boot/bcm2709-rpi-2-b.dtb -initrd /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/rootfs.cpio -append printk.time=0 earlycon=pl011,0x3f201000 console=ttyAMA0 panic=-1 noreboot dwc_otg.fiq_fsm_enable=0 -no-reboot
Emulated/Virtualized environment
- Operating system: Debian
- OS/kernel version: Linux version 4.14.98-v7+ (dom@dom-XPS-13-9370) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1200 SMP Tue Feb 12 20:27:48 GMT 2019
- Architecture: ARM
Description of problem
Roughly once every 20 times, the halt
command will not produce the desired effect, and wait()ing on the QEMU process to gracefully shutdown will fail.
I was not able to see any other failure in what the test covers, except the halt
command and the wait()
ing. That is, the booting of the kernel and initrd, and the execution of commands to inspect the system all run without problems.
Steps to reproduce
- make check-venv
- ./tests/venv/bin/avocado run tests/acceptance/boot_linux_console.py:BootLinuxConsole.test_arm_raspi2_initrd
Additional information
13:48:01 DEBUG| PARAMS (key=arch, path=*, default=arm) => 'arm'
13:48:01 DEBUG| PARAMS (key=cpu, path=*, default=None) => None
13:48:01 DEBUG| PARAMS (key=machine, path=*, default=raspi2b) => 'raspi2b'
13:48:01 DEBUG| PARAMS (key=qemu_bin, path=*, default=./qemu-system-arm) => './qemu-system-arm'
13:48:01 DEBUG| Test workdir initialized at: /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd
13:48:08 DEBUG| QEMUMachine "default" created
13:48:08 DEBUG| QEMUMachine "default" temp_dir: /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/qemu-machine-5pavn9gy
13:48:08 DEBUG| QEMUMachine "default" log_dir: /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd
13:48:08 DEBUG| VM launch command: './qemu-system-arm -display none -vga none -chardev socket,id=mon,path=/var/tmp/avo_qemu_sock_hd3upfg6/qemu-2435532-monitor.sock -mon chardev=mon,mode=control -machine raspi2b -chardev socket,id=console,path=/var/tmp/avo_qemu_sock_hd3upfg6/qemu-2435532-console.sock,server=on,wait=off -serial chardev:console -kernel /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/boot/kernel7.img -dtb /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/boot/bcm2709-rpi-2-b.dtb -initrd /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/rootfs.cpio -append printk.time=0 earlycon=pl011,0x3f201000 console=ttyAMA0 panic=-1 noreboot dwc_otg.fiq_fsm_enable=0 -no-reboot'
13:48:08 DEBUG| >>> {'execute': 'qmp_capabilities'}
13:48:08 DEBUG| <<< {'return': {}}
13:48:08 DEBUG| [ 0.000000] Booting Linux on physical CPU 0xf00
13:48:08 DEBUG| [ 0.000000] Linux version 4.14.98-v7+ (dom@dom-XPS-13-9370) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1200 SMP Tue Feb 12 20:27:48 GMT 2019
13:48:08 DEBUG| [ 0.000000] CPU: ARMv7 Processor [410fc075] revision 5 (ARMv7), cr=10c5387d
13:48:08 DEBUG| [ 0.000000] CPU: div instructions available: patching division code
13:48:08 DEBUG| [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
13:48:08 DEBUG| [ 0.000000] OF: fdt: Machine model: Raspberry Pi 2 Model B
13:48:08 DEBUG| [ 0.000000] earlycon: pl11 at MMIO 0x3f201000 (options '')
13:48:08 DEBUG| [ 0.000000] bootconsole [pl11] enabled
13:48:08 DEBUG| [ 0.000000] Memory policy: Data cache writealloc
13:48:08 DEBUG| [ 0.000000] cma: Reserved 8 MiB at 0x3b800000
13:48:08 DEBUG| [ 0.000000] percpu: Embedded 17 pages/cpu @baf2e000 s38720 r8192 d22720 u69632
13:48:08 DEBUG| [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 243600
13:48:08 DEBUG| [ 0.000000] Kernel command line: printk.time=0 earlycon=pl011,0x3f201000 console=ttyAMA0 panic=-1 noreboot dwc_otg.fiq_fsm_enable=0
13:48:08 DEBUG| PID hash table entries: 4096 (order: 2, 16384 bytes)
13:48:08 DEBUG| Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
13:48:08 DEBUG| Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
13:48:08 DEBUG| Memory: 949120K/983040K available (7168K kernel code, 577K rwdata, 2080K rodata, 1024K init, 698K bss, 25728K reserved, 8192K cma-reserved)
13:48:08 DEBUG| Virtual kernel memory layout:
13:48:08 DEBUG| vector : 0xffff0000 - 0xffff1000 ( 4 kB)
13:48:08 DEBUG| fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
13:48:08 DEBUG| vmalloc : 0xbc800000 - 0xff800000 (1072 MB)
13:48:08 DEBUG| lowmem : 0x80000000 - 0xbc000000 ( 960 MB)
13:48:08 DEBUG| modules : 0x7f000000 - 0x80000000 ( 16 MB)
13:48:08 DEBUG| .text : 0x80008000 - 0x80800000 (8160 kB)
13:48:08 DEBUG| .init : 0x80b00000 - 0x80c00000 (1024 kB)
13:48:08 DEBUG| .data : 0x80c00000 - 0x80c906d4 ( 578 kB)
13:48:08 DEBUG| .bss : 0x80c97ef8 - 0x80d468f0 ( 699 kB)
13:48:08 DEBUG| SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
13:48:08 DEBUG| ftrace: allocating 25298 entries in 75 pages
13:48:09 DEBUG| Hierarchical RCU implementation.
13:48:09 DEBUG| NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
13:48:09 DEBUG| arch_timer: cp15 timer(s) running at 62.50MHz (virt).
13:48:09 DEBUG| clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x1cd42e208c, max_idle_ns: 881590405314 ns
13:48:09 DEBUG| sched_clock: 56 bits at 62MHz, resolution 16ns, wraps every 4398046511096ns
13:48:09 DEBUG| Switching to timer-based delay loop, resolution 16ns
13:48:09 DEBUG| Console: colour dummy device 80x30
13:48:09 DEBUG| Calibrating delay loop (skipped), value calculated using timer frequency.. 125.00 BogoMIPS (lpj=625000)
13:48:09 DEBUG| pid_max: default: 32768 minimum: 301
13:48:09 DEBUG| Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
13:48:09 DEBUG| Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
13:48:09 DEBUG| Disabling memory control group subsystem
13:48:09 DEBUG| CPU: Testing write buffer coherency: ok
13:48:09 DEBUG| CPU0: update cpu_capacity 1024
13:48:09 DEBUG| CPU0: thread -1, cpu 0, socket 15, mpidr 80000f00
13:48:09 DEBUG| Setting up static identity map for 0x100000 - 0x10003c
13:48:09 DEBUG| Hierarchical SRCU implementation.
13:48:09 DEBUG| smp: Bringing up secondary CPUs ...
13:48:09 DEBUG| CPU1: update cpu_capacity 1024
13:48:09 DEBUG| CPU1: thread -1, cpu 1, socket 15, mpidr 80000f01
13:48:09 DEBUG| CPU2: update cpu_capacity 1024
13:48:09 DEBUG| CPU2: thread -1, cpu 2, socket 15, mpidr 80000f02
13:48:09 DEBUG| CPU3: update cpu_capacity 1024
13:48:09 DEBUG| CPU3: thread -1, cpu 3, socket 15, mpidr 80000f03
13:48:09 DEBUG| smp: Brought up 1 node, 4 CPUs
13:48:09 DEBUG| SMP: Total of 4 processors activated (500.00 BogoMIPS).
13:48:09 DEBUG| CPU: All CPU(s) started in SVC mode.
13:48:09 DEBUG| devtmpfs: initialized
13:48:09 DEBUG| random: get_random_u32 called from bucket_table_alloc+0xfc/0x24c with crng_init=0
13:48:09 DEBUG| VFP support v0.3: implementor 41 architecture 2 part 30 variant 7 rev 5
13:48:09 DEBUG| clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
13:48:09 DEBUG| futex hash table entries: 1024 (order: 4, 65536 bytes)
13:48:09 DEBUG| pinctrl core: initialized pinctrl subsystem
13:48:09 DEBUG| NET: Registered protocol family 16
13:48:09 DEBUG| DMA: preallocated 1024 KiB pool for atomic coherent allocations
13:48:09 DEBUG| hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
13:48:09 DEBUG| hw-breakpoint: maximum watchpoint size is 8 bytes.
13:48:09 DEBUG| Serial: AMBA PL011 UART driver
13:48:09 DEBUG| bcm2835-mbox 3f00b880.mailbox: mailbox enabled
13:48:09 DEBUG| bcm2835-dma 3f007000.dma: DMA legacy API manager at bc813000, dmachans=0x1
13:48:09 DEBUG| SCSI subsystem initialized
13:48:09 DEBUG| usbcore: registered new interface driver usbfs
13:48:09 DEBUG| usbcore: registered new interface driver hub
13:48:09 DEBUG| usbcore: registered new device driver usb
13:48:09 DEBUG| raspberrypi-firmware soc:firmware: Attached to firmware from 1970-01-05 00:12
13:48:09 DEBUG| clocksource: Switched to clocksource arch_sys_counter
13:48:09 DEBUG| VFS: Disk quotas dquot_6.6.0
13:48:09 DEBUG| VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
13:48:09 DEBUG| FS-Cache: Loaded
13:48:09 DEBUG| CacheFiles: Loaded
13:48:09 DEBUG| NET: Registered protocol family 2
13:48:09 DEBUG| TCP established hash table entries: 8192 (order: 3, 32768 bytes)
13:48:09 DEBUG| TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
13:48:09 DEBUG| TCP: Hash tables configured (established 8192 bind 8192)
13:48:09 DEBUG| UDP hash table entries: 512 (order: 2, 16384 bytes)
13:48:09 DEBUG| UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
13:48:09 DEBUG| NET: Registered protocol family 1
13:48:09 DEBUG| RPC: Registered named UNIX socket transport module.
13:48:09 DEBUG| RPC: Registered udp transport module.
13:48:09 DEBUG| RPC: Registered tcp transport module.
13:48:09 DEBUG| RPC: Registered tcp NFSv4.1 backchannel transport module.
13:48:09 DEBUG| Trying to unpack rootfs image as initramfs...
13:48:09 DEBUG| Freeing initrd memory: 3256K
13:48:09 DEBUG| hw perfevents: enabled with armv7_cortex_a7 PMU driver, 5 counters available
13:48:09 DEBUG| workingset: timestamp_bits=14 max_order=18 bucket_order=4
13:48:09 DEBUG| FS-Cache: Netfs 'nfs' registered for caching
13:48:09 DEBUG| NFS: Registering the id_resolver key type
13:48:09 DEBUG| Key type id_resolver registered
13:48:09 DEBUG| Key type id_legacy registered
13:48:09 DEBUG| nfs4filelayout_init: NFSv4 File Layout Driver Registering...
13:48:09 DEBUG| Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
13:48:09 DEBUG| io scheduler noop registered
13:48:09 DEBUG| io scheduler deadline registered
13:48:09 DEBUG| io scheduler cfq registered (default)
13:48:09 DEBUG| io scheduler mq-deadline registered
13:48:09 DEBUG| io scheduler kyber registered
13:48:09 DEBUG| BCM2708FB: allocated DMA memory fb900000
13:48:09 DEBUG| BCM2708FB: allocated DMA channel 0 @ bc813000
13:48:09 DEBUG| Console: switching to colour frame buffer device 100x30
13:48:09 DEBUG| bcm2835-rng 3f104000.rng: hwrng registered
13:48:09 DEBUG| vc-mem: phys_addr:0x00000000 mem_base=0x00000000 mem_size:0x00000000(0 MiB)
13:48:09 DEBUG| vc-sm: Videocore shared memory driver
13:48:09 DEBUG| gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
13:48:09 DEBUG| brd: module loaded
13:48:09 DEBUG| loop: module loaded
13:48:09 DEBUG| Loading iSCSI transport class v2.0-870.
13:48:09 DEBUG| libphy: Fixed MDIO Bus: probed
13:48:09 DEBUG| usbcore: registered new interface driver lan78xx
13:48:09 DEBUG| usbcore: registered new interface driver smsc95xx
13:48:09 DEBUG| dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
13:48:09 DEBUG| dwc_otg 3f980000.usb: base=0xf0980000
13:48:10 DEBUG| Core Release: 2.94a
13:48:10 DEBUG| Setting default values for core params
13:48:10 DEBUG| Finished setting default values for core params
13:48:10 DEBUG| Using Buffer DMA mode
13:48:10 DEBUG| Periodic Transfer Interrupt Enhancement - disabled
13:48:10 DEBUG| Multiprocessor Interrupt Enhancement - disabled
13:48:10 DEBUG| OTG VER PARAM: 0, OTG VER FLAG: 0
13:48:10 DEBUG| Shared Tx FIFO mode
13:48:10 DEBUG| WARN::dwc_otg_hcd_init:1046: FIQ DMA bounce buffers: virt = 0xbb914000 dma = 0xfb914000 len=9024
13:48:10 DEBUG| WARN::hcd_init_fiq:459: FIQ on core 1 at 0x805edb88
13:48:10 DEBUG| WARN::hcd_init_fiq:460: FIQ ASM at 0x805edcb4 length 36
13:48:10 DEBUG| WARN::hcd_init_fiq:486: MPHI regs_base at 0xf0006000
13:48:10 DEBUG| dwc_otg 3f980000.usb: DWC OTG Controller
13:48:10 DEBUG| dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
13:48:10 DEBUG| dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
13:48:10 DEBUG| Init: Port Power? op_state=1
13:48:10 DEBUG| Init: Power Port (1)
13:48:10 DEBUG| usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
13:48:10 DEBUG| usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
13:48:10 DEBUG| usb usb1: Product: DWC OTG Controller
13:48:10 DEBUG| usb usb1: Manufacturer: Linux 4.14.98-v7+ dwc_otg_hcd
13:48:10 DEBUG| usb usb1: SerialNumber: 3f980000.usb
13:48:10 DEBUG| hub 1-0:1.0: USB hub found
13:48:10 DEBUG| hub 1-0:1.0: 1 port detected
13:48:10 DEBUG| usbcore: registered new interface driver usb-storage
13:48:10 DEBUG| mousedev: PS/2 mouse device common for all mice
13:48:10 DEBUG| IR NEC protocol handler initialized
13:48:10 DEBUG| IR RC5(x/sz) protocol handler initialized
13:48:10 DEBUG| IR RC6 protocol handler initialized
13:48:10 DEBUG| IR JVC protocol handler initialized
13:48:10 DEBUG| IR Sony protocol handler initialized
13:48:10 DEBUG| IR SANYO protocol handler initialized
13:48:10 DEBUG| IR Sharp protocol handler initialized
13:48:10 DEBUG| IR MCE Keyboard/mouse protocol handler initialized
13:48:10 DEBUG| IR XMP protocol handler initialized
13:48:10 DEBUG| bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer
13:48:10 DEBUG| bcm2835-cpufreq: min=700000 max=700000
13:48:10 DEBUG| sdhci: Secure Digital Host Controller Interface driver
13:48:10 DEBUG| sdhci: Copyright(c) Pierre Ossman
13:48:10 DEBUG| sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
13:48:10 DEBUG| sdhci-pltfm: SDHCI platform and OF driver helper
13:48:10 DEBUG| ledtrig-cpu: registered to indicate activity on CPUs
13:48:10 DEBUG| hidraw: raw HID events driver (C) Jiri Kosina
13:48:10 DEBUG| usbcore: registered new interface driver usbhid
13:48:10 DEBUG| usbhid: USB HID core driver
13:48:10 DEBUG| vchiq: vchiq_init_state: slot_zero = bb980000, is_master = 0
13:48:10 DEBUG| bcm2835_vchiq 3f00b840.vchiq: failed to set channelbase
13:48:10 DEBUG| vchiq: could not load vchiq
13:48:10 DEBUG| Initializing XFRM netlink socket
13:48:10 DEBUG| NET: Registered protocol family 17
13:48:10 DEBUG| Key type dns_resolver registered
13:48:10 DEBUG| Registering SWP/SWPB emulation handler
13:48:10 DEBUG| registered taskstats version 1
13:48:10 DEBUG| uart-pl011 3f201000.serial: cts_event_workaround enabled
13:48:10 DEBUG| 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2
13:48:10 DEBUG| console [ttyAMA0] enabled
13:48:10 DEBUG| console [ttyAMA0] enabled
13:48:10 DEBUG| bootconsole [pl11] disabled
13:48:10 DEBUG| bootconsole [pl11] disabled
13:48:10 DEBUG| bcm2835_thermal 3f212000.thermal: Not able to read trip_temp: -33
13:48:10 DEBUG| bcm2835-clk 3f101000.cprman: tsens: couldn't lock PLL
13:48:10 DEBUG| bcm2835_thermal: probe of 3f212000.thermal failed with error -33
13:48:10 DEBUG| sdhost: log_buf @ bb913000 (fb913000)
13:48:10 DEBUG| mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
13:48:10 DEBUG| of_cfs_init
13:48:10 DEBUG| of_cfs_init: OK
13:48:10 DEBUG| uart-pl011 3f201000.serial: no DMA platform data
13:48:10 DEBUG| Freeing unused kernel memory: 1024K
13:48:11 DEBUG| mount: mounting devtmpfs on /dev failed: Device or resource busy
13:48:11 DEBUG| Starting logging: OK
13:48:11 DEBUG| Initializing random number generator... random: dd: uninitialized urandom read (512 bytes read)
13:48:11 DEBUG| done.
13:48:12 DEBUG| Starting network: OK
13:48:12 DEBUG| Found console ttyAMA0
13:48:12 DEBUG| Linux version 4.14.98-v7+ (dom@dom-XPS-13-9370) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1200 SMP Tue Feb 12 20:27:48 GMT 2019
13:48:12 DEBUG| Boot successful.
13:48:12 DEBUG| cat /proc/cpuinfo
13:48:12 DEBUG| / # cat /proc/cpuinfo
13:48:12 DEBUG| processor : 0
13:48:12 DEBUG| model name : ARMv7 Processor rev 5 (v7l)
13:48:12 DEBUG| BogoMIPS : 125.00
13:48:12 DEBUG| Features : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm
13:48:12 DEBUG| CPU implementer : 0x41
13:48:12 DEBUG| CPU architecture: 7
13:48:12 DEBUG| CPU variant : 0x0
13:48:12 DEBUG| CPU part : 0xc07
13:48:12 DEBUG| CPU revision : 5
13:48:12 DEBUG| processor : 1
13:48:12 DEBUG| model name : ARMv7 Processor rev 5 (v7l)
13:48:12 DEBUG| BogoMIPS : 125.00
13:48:12 DEBUG| Features : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm
13:48:12 DEBUG| CPU implementer : 0x41
13:48:12 DEBUG| CPU architecture: 7
13:48:12 DEBUG| CPU variant : 0x0
13:48:12 DEBUG| CPU part : 0xc07
13:48:12 DEBUG| CPU revision : 5
13:48:12 DEBUG| processor : 2
13:48:12 DEBUG| model name : ARMv7 Processor rev 5 (v7l)
13:48:12 DEBUG| BogoMIPS : 125.00
13:48:12 DEBUG| Features : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm
13:48:12 DEBUG| CPU implementer : 0x41
13:48:12 DEBUG| CPU architecture: 7
13:48:12 DEBUG| CPU variant : 0x0
13:48:12 DEBUG| CPU part : 0xc07
13:48:12 DEBUG| CPU revision : 5
13:48:12 DEBUG| processor : 3
13:48:12 DEBUG| model name : ARMv7 Processor rev 5 (v7l)
13:48:12 DEBUG| BogoMIPS : 125.00
13:48:12 DEBUG| Features : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm
13:48:12 DEBUG| CPU implementer : 0x41
13:48:12 DEBUG| CPU architecture: 7
13:48:12 DEBUG| CPU variant : 0x0
13:48:12 DEBUG| CPU part : 0xc07
13:48:12 DEBUG| CPU revision : 5
13:48:12 DEBUG| Hardware : BCM2835
13:48:12 DEBUG| Revision : 0000
13:48:12 DEBUG| Serial : 0000000000000000
13:48:12 DEBUG| cat /proc/iomem
13:48:12 DEBUG| / # cat /proc/iomem
13:48:12 DEBUG| 00000000-3bffffff : System RAM
13:48:12 DEBUG| 00008000-00afffff : Kernel code
13:48:12 DEBUG| 00c00000-00d468ef : Kernel data
13:48:12 DEBUG| 3f006000-3f006fff : dwc_otg
13:48:12 DEBUG| 3f007000-3f007eff : /soc/dma@7e007000
13:48:12 DEBUG| 3f00b880-3f00b8bf : /soc/mailbox@7e00b880
13:48:12 DEBUG| 3f100000-3f100027 : /soc/watchdog@7e100000
13:48:12 DEBUG| 3f101000-3f102fff : /soc/cprman@7e101000
13:48:12 DEBUG| 3f200000-3f2000b3 : /soc/gpio@7e200000
13:53:12 WARNI| qemu received signal 9; command: "./qemu-system-arm -display none -vga none -chardev socket,id=mon,path=/var/tmp/avo_qemu_sock_hd3upfg6/qemu-2435532-monitor.sock -mon chardev=mon,mode=control -machine raspi2b -chardev socket,id=console,path=/var/tmp/avo_qemu_sock_hd3upfg6/qemu-2435532-console.sock,server=on,wait=off -serial chardev:console -kernel /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/boot/kernel7.img -dtb /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/boot/bcm2709-rpi-2-b.dtb -initrd /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/rootfs.cpio -append printk.time=0 earlycon=pl011,0x3f201000 console=ttyAMA0 panic=-1 noreboot dwc_otg.fiq_fsm_enable=0 -no-reboot"
13:53:12 ERROR|
13:53:12 ERROR| Reproduced traceback from: /var/lib/users/cleber/build/qemu/tests/venv/lib64/python3.9/site-packages/avocado/core/test.py:794
13:53:12 ERROR| Traceback (most recent call last):
13:53:12 ERROR| File "/home/cleber/src/qemu/python/qemu/machine/machine.py", line 514, in _do_shutdown
13:53:12 ERROR| self._soft_shutdown(timeout, has_quit)
13:53:12 ERROR| File "/home/cleber/src/qemu/python/qemu/machine/machine.py", line 497, in _soft_shutdown
13:53:12 ERROR| self._subp.wait(timeout=timeout)
13:53:12 ERROR| File "/usr/lib64/python3.9/subprocess.py", line 1189, in wait
13:53:12 ERROR| return self._wait(timeout=timeout)
13:53:12 ERROR| File "/usr/lib64/python3.9/subprocess.py", line 1909, in _wait
13:53:12 ERROR| raise TimeoutExpired(self.args, timeout)
13:53:12 ERROR| subprocess.TimeoutExpired: Command '('./qemu-system-arm', '-display', 'none', '-vga', 'none', '-chardev', 'socket,id=mon,path=/var/tmp/avo_qemu_sock_hd3upfg6/qemu-2435532-monitor.sock', '-mon', 'chardev=mon,mode=control', '-machine', 'raspi2b', '-chardev', 'socket,id=console,path=/var/tmp/avo_qemu_sock_hd3upfg6/qemu-2435532-console.sock,server=on,wait=off', '-serial', 'chardev:console', '-kernel', '/home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/boot/kernel7.img', '-dtb', '/home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/boot/bcm2709-rpi-2-b.dtb', '-initrd', '/home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/rootfs.cpio', '-append', 'printk.time=0 earlycon=pl011,0x3f201000 console=ttyAMA0 panic=-1 noreboot dwc_otg.fiq_fsm_enable=0', '-no-reboot')' timed out after 300 seconds
13:53:12 ERROR|
13:53:12 ERROR| The above exception was the direct cause of the following exception:
13:53:12 ERROR|
13:53:12 ERROR| Traceback (most recent call last):
13:53:12 ERROR| File "/var/lib/users/cleber/build/qemu/tests/acceptance/boot_linux_console.py", line 502, in test_arm_raspi2_initrd
13:53:12 ERROR| self.vm.wait(300)
13:53:12 ERROR| File "/home/cleber/src/qemu/python/qemu/machine/machine.py", line 561, in wait
13:53:12 ERROR| self.shutdown(has_quit=True, timeout=timeout)
13:53:12 ERROR| File "/home/cleber/src/qemu/python/qemu/machine/machine.py", line 544, in shutdown
13:53:12 ERROR| self._do_shutdown(timeout, has_quit)
13:53:12 ERROR| File "/home/cleber/src/qemu/python/qemu/machine/machine.py", line 517, in _do_shutdown
13:53:12 ERROR| raise AbnormalShutdown("Could not perform graceful shutdown") \
13:53:12 ERROR| qemu.machine.machine.AbnormalShutdown: Could not perform graceful shutdown
13:53:12 ERROR|
13:53:12 DEBUG| Local variables:
13:53:12 DEBUG| -> self <class 'boot_linux_console.BootLinuxConsole'>: 01-tests/acceptance/boot_linux_console.py:BootLinuxConsole.test_arm_raspi2_initrd
13:53:12 DEBUG| -> deb_url <class 'str'>: http://archive.raspberrypi.org/debian/pool/main/r/raspberrypi-firmware/raspberrypi-kernel_1.20190215-1_armhf.deb
13:53:12 DEBUG| -> deb_hash <class 'str'>: cd284220b32128c5084037553db3c482426f3972
13:53:12 DEBUG| -> deb_path <class 'str'>: /home/cleber/avocado/data/cache/by_location/c813ab2b9e4f63b2aa876075ad70d638a31a25b7/raspberrypi-kernel_1.20190215-1_armhf.deb
13:53:12 DEBUG| -> kernel_path <class 'str'>: /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/boot/kernel7.img
13:53:12 DEBUG| -> dtb_path <class 'str'>: /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/boot/bcm2709-rpi-2-b.dtb
13:53:12 DEBUG| -> initrd_url <class 'str'>: https://github.com/groeck/linux-build-test/raw/2eb0a73b5d5a28df3170c546ddaaa9757e1e0848/rootfs/arm/rootfs-armv7a.cpio.gz
13:53:12 DEBUG| -> initrd_hash <class 'str'>: 604b2e45cdf35045846b8bbfbf2129b1891bdc9c
13:53:12 DEBUG| -> initrd_path_gz <class 'str'>: /home/cleber/avocado/data/cache/by_location/d100d022b257e2c8f0c0c97434576ed642f9afe5/rootfs-armv7a.cpio.gz
13:53:12 DEBUG| -> initrd_path <class 'str'>: /home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/rootfs.cpio
13:53:12 DEBUG| -> kernel_command_line <class 'str'>: printk.time=0 earlycon=pl011,0x3f201000 console=ttyAMA0 panic=-1 noreboot dwc_otg.fiq_fsm_enable=0
13:53:12 DEBUG| DATA (filename=output.expected) => NOT FOUND (data sources: variant, test, file)
13:53:12 DEBUG| DATA (filename=stdout.expected) => NOT FOUND (data sources: variant, test, file)
13:53:12 DEBUG| DATA (filename=stderr.expected) => NOT FOUND (data sources: variant, test, file)
13:53:12 ERROR| Traceback (most recent call last):
13:53:12 ERROR| File "/home/cleber/src/qemu/python/qemu/machine/machine.py", line 514, in _do_shutdown
self._soft_shutdown(timeout, has_quit)
13:53:12 ERROR| File "/home/cleber/src/qemu/python/qemu/machine/machine.py", line 497, in _soft_shutdown
self._subp.wait(timeout=timeout)
13:53:12 ERROR| File "/usr/lib64/python3.9/subprocess.py", line 1189, in wait
return self._wait(timeout=timeout)
13:53:12 ERROR| File "/usr/lib64/python3.9/subprocess.py", line 1909, in _wait
raise TimeoutExpired(self.args, timeout)
13:53:12 ERROR| subprocess.TimeoutExpired: Command '('./qemu-system-arm', '-display', 'none', '-vga', 'none', '-chardev', 'socket,id=mon,path=/var/tmp/avo_qemu_sock_hd3upfg6/qemu-2435532-monitor.sock', '-mon', 'chardev=mon,mode=control', '-machine', 'raspi2b', '-chardev', 'socket,id=console,path=/var/tmp/avo_qemu_sock_hd3upfg6/qemu-2435532-console.sock,server=on,wait=off', '-serial', 'chardev:console', '-kernel', '/home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/boot/kernel7.img', '-dtb', '/home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/boot/bcm2709-rpi-2-b.dtb', '-initrd', '/home/cleber/avocado/job-results/job-2021-09-24T13.48-0890f76/test-results/tmp_dirdikw83mj/01-tests_acceptance_boot_linux_console.py_BootLinuxConsole.test_arm_raspi2_initrd/rootfs.cpio', '-append', 'printk.time=0 earlycon=pl011,0x3f201000 console=ttyAMA0 panic=-1 noreboot dwc_otg.fiq_fsm_enable=0', '-no-reboot')' timed out after 300 seconds
13:53:12 ERROR|
The above exception was the direct cause of the following exception:
13:53:12 ERROR| Traceback (most recent call last):
13:53:12 ERROR| File "/var/lib/users/cleber/build/qemu/tests/venv/lib64/python3.9/site-packages/avocado/core/test.py", line 882, in _run_avocado
raise test_exception
13:53:12 ERROR| File "/var/lib/users/cleber/build/qemu/tests/venv/lib64/python3.9/site-packages/avocado/core/test.py", line 789, in _run_avocado
testMethod()
13:53:12 ERROR| File "/var/lib/users/cleber/build/qemu/tests/acceptance/boot_linux_console.py", line 502, in test_arm_raspi2_initrd
self.vm.wait(300)
13:53:12 ERROR| File "/home/cleber/src/qemu/python/qemu/machine/machine.py", line 561, in wait
self.shutdown(has_quit=True, timeout=timeout)
13:53:12 ERROR| File "/home/cleber/src/qemu/python/qemu/machine/machine.py", line 544, in shutdown
self._do_shutdown(timeout, has_quit)
13:53:12 ERROR| File "/home/cleber/src/qemu/python/qemu/machine/machine.py", line 517, in _do_shutdown
raise AbnormalShutdown("Could not perform graceful shutdown") \
13:53:12 ERROR| qemu.machine.machine.AbnormalShutdown: Could not perform graceful shutdown
13:53:12 ERROR| ERROR 01-tests/acceptance/boot_linux_console.py:BootLinuxConsole.test_arm_raspi2_initrd -> AbnormalShutdown: Could not perform graceful shutdown
13:53:12 INFO |