Control: retitle -1 autopkgtest-virt-qemu gives a mysterious error with arm64
testbed
Control: unblock -1 by 973484
> Both of them involves major design decision by the upstreams.
> So I stop my investigation here unless a good idea occurs.
> There seems no easy fix.
There DOES EXIST an easy fix as below.
By giving "-device pci-serial-2x,chardev1=ttyS0,chardev2=ttyS1"
to qemu-system-aarch64,
two serial ports can be attached to QEMU arm "virt" machine.
Bug #973484 no longer blocks this!
Combined with the patch to vmdb2 at
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=973467#12
the attached minimal changes allow one to do
debci setup -b qemu -a arm64 -s sid
autopkgtest -u debci -B bash -- qemu --debug --efi --show-boot \
-q qemu-system-aarch64 --timeout-reboot 300 \
/var/lib/debci/qemu/sid-arm64.img
on BOTH amd64 and arm64 hosts.
But for both cases (amd64 and arm64 hosts), I get the following identical error:
autopkgtest-virt-qemu: DBG: can connect to autopkgtest sh in VM
autopkgtest-virt-qemu: DBG: determine_normal_user: got user "user"
autopkgtest-virt-qemu: DBG: auxverb =
['/tmp/autopkgtest-qemu.iwcjv619/runcmd'], downtmp = None
autopkgtest-virt-qemu: DBG: execute-timeout:
/tmp/autopkgtest-qemu.iwcjv619/runcmd mktemp --directory --tmpdir
autopkgtest.XXXXXX
autopkgtest-virt-qemu: DBG: execute-timeout:
/tmp/autopkgtest-qemu.iwcjv619/runcmd chmod 1777 /tmp/autopkgtest.4DTPHS
autopkgtest-virt-qemu: DBG: cleanup...
qemu-system-aarch64: terminating on signal 15 from pid 24486 (/usr/bin/python3)
autopkgtest [19:17:50]: ERROR: testbed failure: cannot send to testbed: I/O
operation on closed file.
I tried to figure out how the above happens, but could not identify the cause.
The diff to autopkgtest and the execution log are attached below.
Ryutaroh
--- usr/bin/autopkgtest-virt-qemu-orig 2020-11-01 20:25:24.039639429 +0900
+++ usr/bin/autopkgtest-virt-qemu 2020-11-01 20:27:33.370088332 +0900
@@ -577,12 +577,27 @@
'-net', 'user' + nic_opt,
'-object', 'rng-random,filename=/dev/urandom,id=rng0', '-device',
'virtio-rng-pci,rng=rng0,id=rng-device0',
'-monitor', 'unix:%s/monitor,server,nowait' % workdir,
- '-serial', 'unix:%s/ttyS0,server,nowait' % workdir,
- '-serial', 'unix:%s/ttyS1,server,nowait' % workdir,
'-virtfs',
'local,id=autopkgtest,path=%s,security_model=none,mount_tag=autopkgtest' %
shareddir,
'-drive', 'file=%s,cache=unsafe,if=virtio,index=0,format=qcow2' %
overlay]
+ if 'qemu-system-aarch64' in args.qemu_command or 'qemu-system-arm' in
args.qemu_command or "arm" in os.uname()[4] or "aarch64" == os.uname()[4]:
+ argv.append('-machine')
+ argv.append('virt')
+ argv.append('-cpu')
+ argv.append('max')
+ argv.append('-chardev')
+ argv.append('socket,id=ttyS0,path=%s/ttyS0,server,nowait' % workdir)
+ argv.append('-chardev')
+ argv.append('socket,id=ttyS1,path=%s/ttyS1,server,nowait' % workdir)
+ argv.append('-device')
+ argv.append('pci-serial-2x,chardev1=ttyS0,chardev2=ttyS1')
+ else:
+ argv.append('-serial')
+ argv.append('unix:%s/ttyS0,server,nowait' % workdir)
+ argv.append('-serial')
+ argv.append('unix:%s/ttyS1,server,nowait' % workdir)
+
if args.efi:
code = None
data = None
--- usr/bin/autopkgtest-build-qemu-orig 2020-10-31 10:05:36.350588392 +0900
+++ usr/bin/autopkgtest-build-qemu 2020-11-01 18:45:29.534135709 +0900
@@ -252,12 +252,20 @@
- mkimg: "{{ image }}"
size: $size
- - mklabel: msdos
+ - mklabel: gpt
device: "{{ image }}"
- mkpart: primary
+ fs-type: fat32
device: "{{ image }}"
start: 0%
+ end: 200MiB
+ tag: efipart
+
+ - mkpart: primary
+ fs-type: ext4
+ device: "{{ image }}"
+ start: 200MiB
end: 100%
tag: root
@@ -266,6 +274,9 @@
- mkfs: ext4
partition: root
+ - mkfs: vfat
+ partition: efipart
+
- mount: root
- $debootstrap_cmd: $release
@@ -279,8 +290,9 @@
- ifupdown
tag: root
- - grub: bios
+ - grub: uefi
tag: root
+ efi: efipart
console: serial
- chroot: root
@@ -295,6 +307,9 @@
rootdev=\$(ls -1 /dev/mapper/loop* | sort | tail -1)
uuid=\$(blkid -c /dev/null -o value -s UUID \$rootdev)
echo "UUID=\$uuid / ext4 errors=remount-ro 0 1" > \$ROOT/etc/fstab
+ efidev=\$(ls -1 /dev/mapper/loop* | sort | head -1)
+ uuid=\$(blkid -c /dev/null -o value -s UUID \$efidev)
+ echo "UUID=\$uuid /boot/efi vfat rw 0 2" >> \$ROOT/etc/fstab
root-fs: root
- shell: '$script \$ROOT'
--- usr/share/autopkgtest/setup-commands/setup-testbed-orig 2020-10-31
15:24:46.526303266 +0900
+++ usr/share/autopkgtest/setup-commands/setup-testbed 2020-11-01
18:46:18.224112354 +0900
@@ -98,7 +98,7 @@
echo 'GRUB_CMDLINE_LINUX_DEFAULT="console=ttyS0 vmalloc=512M"' > \
"$root/etc/default/grub.d/90-autopkgtest.cfg"
changed=1
- elif [ "$ARCH" = "amd64" ]; then
+ else
echo 'GRUB_CMDLINE_LINUX_DEFAULT="console=ttyS0"' > \
"$root/etc/default/grub.d/90-autopkgtest.cfg"
changed=1
@@ -108,7 +108,7 @@
if [ "$ARCH" = "i386" ]; then
sed -i '/CMDLINE_LINUX_DEFAULT/ s/"$/ console=ttyS0
vmalloc=512M"/' "$root/etc/default/grub"
changed=1
- elif [ "$ARCH" = "amd64" ]; then
+ else
sed -i '/CMDLINE_LINUX_DEFAULT/ s/"$/ console=ttyS0"/'
"$root/etc/default/grub"
changed=1
fi
# autopkgtest -u debci -B bash -- qemu --debug --efi --show-boot -q
qemu-system-aarch64 --timeout-reboot 300 /var/lib/debci/qemu/sid-arm64.img
autopkgtest [19:17:19]: starting date: 2020-11-01
autopkgtest [19:17:19]: version 5.15
autopkgtest [19:17:19]: host raspi4-bullseye; command line:
/usr/bin/autopkgtest -u debci -B bash -- qemu --debug --efi --show-boot
/var/lib/debci/qemu/sid-arm64.img
autopkgtest-virt-qemu: DBG: executing open
autopkgtest-virt-qemu: DBG: execute-timeout: qemu-img info --output=json
/var/lib/debci/qemu/sid-arm64.img
autopkgtest-virt-qemu: DBG: Creating temporary overlay image in
/tmp/autopkgtest-qemu.iwcjv619/overlay.img
autopkgtest-virt-qemu: DBG: execute-timeout: qemu-img create -f qcow2 -F qcow2
-b /var/lib/debci/qemu/sid-arm64.img /tmp/autopkgtest-qemu.iwcjv619/overlay.img
autopkgtest-virt-qemu: DBG: find_free_port: trying 10022
autopkgtest-virt-qemu: DBG: find_free_port: 10022 is free
autopkgtest-virt-qemu: DBG: Forwarding local port 10022 to VM ssh port 22
autopkgtest-virt-qemu: DBG: expect: " login: "
[ 0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd083]
[ 0.000000] Linux version 5.9.0-1-arm64 (debian-ker...@lists.debian.org)
(gcc-10 (Debian 10.2.0-15) 10.2.0, GNU ld (GNU Binutils for Debian) 2.35.1) #1
SMP Debian 5.9.1-1 (2020-10-17)
[ 0.000000] efi: EFI v2.70 by EDK II
[ 0.000000] efi: SMBIOS 3.0=0x7bef0000 MEMATTR=0x79207018 ACPI
2.0=0x78450000 RNG=0x7bffca98 MEMRESERVE=0x7843fe18
[ 0.000000] efi: seeding entropy pool
[ 0.000000] secureboot: Secure boot disabled
[ 0.000000] cma: Reserved 64 MiB at 0x000000007c000000
[ 0.000000] ACPI: Early table checksum verification disabled
[ 0.000000] ACPI: RSDP 0x0000000078450000 000024 (v02 BOCHS )
[ 0.000000] ACPI: XSDT 0x0000000078440000 000054 (v01 BOCHS BXPCFACP
00000001 01000013)
[ 0.000000] ACPI: FACP 0x0000000078400000 00010C (v05 BOCHS BXPCFACP
00000001 BXPC 00000001)
[ 0.000000] ACPI: DSDT 0x0000000078410000 001455 (v02 BOCHS BXPCDSDT
00000001 BXPC 00000001)
[ 0.000000] ACPI: APIC 0x00000000783F0000 0000A8 (v03 BOCHS BXPCAPIC
00000001 BXPC 00000001)
[ 0.000000] ACPI: GTDT 0x00000000783E0000 000060 (v02 BOCHS BXPCGTDT
00000001 BXPC 00000001)
[ 0.000000] ACPI: MCFG 0x00000000783D0000 00003C (v01 BOCHS BXPCMCFG
00000001 BXPC 00000001)
[ 0.000000] ACPI: SPCR 0x00000000783C0000 000050 (v02 BOCHS BXPCSPCR
00000001 BXPC 00000001)
[ 0.000000] ACPI: IORT 0x00000000783B0000 00007C (v00 BOCHS BXPCIORT
00000001 BXPC 00000001)
[ 0.000000] ACPI: SPCR: console: pl011,mmio,0x9000000,9600
[ 0.000000] ACPI: NUMA: Failed to initialise from firmware
[ 0.000000] NUMA: Faking a node at [mem
0x0000000040000000-0x000000007fffffff]
[ 0.000000] NUMA: NODE_DATA [mem 0x7ba1a100-0x7ba1bfff]
[ 0.000000] Zone ranges:
[ 0.000000] DMA [mem 0x0000000040000000-0x000000007fffffff]
[ 0.000000] DMA32 empty
[ 0.000000] Normal empty
[ 0.000000] Movable zone start for each node
[ 0.000000] Early memory node ranges
[ 0.000000] node 0: [mem 0x0000000040000000-0x000000007845ffff]
[ 0.000000] node 0: [mem 0x0000000078460000-0x000000007874ffff]
[ 0.000000] node 0: [mem 0x0000000078750000-0x000000007bc1ffff]
[ 0.000000] node 0: [mem 0x000000007bc20000-0x000000007bffffff]
[ 0.000000] node 0: [mem 0x000000007c000000-0x000000007fffffff]
[ 0.000000] Zeroed struct page in unavailable ranges: 896 pages
[ 0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x000000007fffffff]
[ 0.000000] psci: probing for conduit method from ACPI.
[ 0.000000] psci: PSCIv1.0 detected in firmware.
[ 0.000000] psci: Using standard PSCI v0.2 function IDs
[ 0.000000] psci: Trusted OS migration not required
[ 0.000000] psci: SMC Calling Convention v1.1
[ 0.000000] ACPI: SRAT not present
[ 0.000000] percpu: Embedded 33 pages/cpu s94808 r8192 d32168 u135168
[ 0.000000] Detected PIPT I-cache on CPU0
[ 0.000000] CPU features: detected: EL2 vector hardening
[ 0.000000] CPU features: kernel page table isolation forced ON by KASLR
[ 0.000000] CPU features: detected: Kernel page table isolation (KPTI)
[ 0.000000] ARM_SMCCC_ARCH_WORKAROUND_1 missing from firmware
[ 0.000000] CPU features: detected: ARM errata 1165522, 1319367, or 1530923
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 258048
[ 0.000000] Policy zone: DMA
[ 0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-5.9.0-1-arm64
root=UUID=d01048ea-5014-446e-968e-e1f4168fe47a ro console=ttyS0
[ 0.000000] Dentry cache hash table entries: 131072 (order: 8, 1048576
bytes, linear)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes,
linear)
[ 0.000000] mem auto-init: stack:off, heap alloc:on, heap free:off
[ 0.000000] Memory: 904980K/1048576K available (11132K kernel code, 1890K
rwdata, 3792K rodata, 5184K init, 561K bss, 78060K reserved, 65536K
cma-reserved)
[ 0.000000] random: get_random_u64 called from
__kmem_cache_create+0x38/0x5d0 with crng_init=0
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[ 0.000000] ftrace: allocating 36677 entries in 144 pages
[ 0.000000] ftrace: allocated 144 pages with 2 groups
[ 0.000000] rcu: Hierarchical RCU implementation.
[ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=1.
[ 0.000000] Rude variant of Tasks RCU enabled.
[ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25
jiffies.
[ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
[ 0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[ 0.000000] GICv2m: ACPI overriding V2M MSI_TYPER (base:80, num:64)
[ 0.000000] GICv2m: range[mem 0x08020000-0x08020fff], SPI[80:143]
[ 0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (virt).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff
max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[ 0.000002] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every
4398046511102ns
[ 0.000082] Console: colour dummy device 80x25
[ 0.000141] ACPI: Core revision 20200717
[ 0.000245] Calibrating delay loop (skipped), value calculated using timer
frequency.. 108.00 BogoMIPS (lpj=216000)
[ 0.000251] pid_max: default: 32768 minimum: 301
[ 0.000303] LSM: Security Framework initializing
[ 0.000321] Yama: disabled by default; enable with sysctl kernel.yama.*
[ 0.000431] AppArmor: AppArmor initialized
[ 0.000437] TOMOYO Linux initialized
[ 0.000487] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes,
linear)
[ 0.000501] Mountpoint-cache hash table entries: 2048 (order: 2, 16384
bytes, linear)
[ 0.001330] ACPI PPTT: No PPTT table found, CPU and cache topology may be
inaccurate
[ 0.001768] rcu: Hierarchical SRCU implementation.
[ 0.002170] Remapping and enabling EFI services.
[ 0.002674] smp: Bringing up secondary CPUs ...
[ 0.002678] smp: Brought up 1 node, 1 CPU
[ 0.002681] SMP: Total of 1 processors activated.
[ 0.002689] CPU features: detected: 32-bit EL0 Support
[ 0.002694] CPU features: detected: CRC32 instructions
[ 0.002698] CPU features: detected: 32-bit EL1 Support
[ 0.015066] CPU: All CPU(s) started at EL1
[ 0.015127] alternatives: patching kernel code
[ 0.016212] devtmpfs: initialized
[ 0.016666] Registered cp15_barrier emulation handler
[ 0.016683] Registered setend emulation handler
[ 0.016689] KASLR enabled
[ 0.016966] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff,
max_idle_ns: 7645041785100000 ns
[ 0.016987] futex hash table entries: 256 (order: 2, 16384 bytes, linear)
[ 0.018112] pinctrl core: initialized pinctrl subsystem
[ 0.018671] SMBIOS 3.0.0 present.
[ 0.018681] DMI: QEMU KVM Virtual Machine, BIOS 0.0.0 02/06/2015
[ 0.019563] NET: Registered protocol family 16
[ 0.020426] DMA: preallocated 128 KiB GFP_KERNEL pool for atomic allocations
[ 0.020577] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA pool for atomic
allocations
[ 0.020635] DMA: preallocated 128 KiB GFP_KERNEL|GFP_DMA32 pool for atomic
allocations
[ 0.020662] audit: initializing netlink subsys (disabled)
[ 0.021183] thermal_sys: Registered thermal governor 'fair_share'
[ 0.021185] thermal_sys: Registered thermal governor 'step_wise'
[ 0.021198] cpuidle: using governor ladder
[ 0.021202] cpuidle: using governor menu
[ 0.021260] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[ 0.021294] ASID allocator initialised with 32768 entries
[ 0.021346] ACPI: bus type PCI registered
[ 0.021351] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[ 0.021487] Serial: AMBA PL011 UART driver
[ 0.023982] audit: type=2000 audit(0.020:1): state=initialized
audit_enabled=0 res=1
[ 0.024389] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
[ 0.024394] HugeTLB registered 32.0 MiB page size, pre-allocated 0 pages
[ 0.024398] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[ 0.024401] HugeTLB registered 64.0 KiB page size, pre-allocated 0 pages
[ 0.288680] ACPI: Added _OSI(Module Device)
[ 0.288688] ACPI: Added _OSI(Processor Device)
[ 0.288747] ACPI: Added _OSI(3.0 _SCP Extensions)
[ 0.288751] ACPI: Added _OSI(Processor Aggregator Device)
[ 0.288756] ACPI: Added _OSI(Linux-Dell-Video)
[ 0.288759] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[ 0.288763] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[ 0.290617] ACPI: 1 ACPI AML tables successfully acquired and loaded
[ 0.291404] ACPI: Interpreter enabled
[ 0.291408] ACPI: Using GIC for interrupt routing
[ 0.291434] ACPI: MCFG table detected, 1 entries
[ 0.296656] ARMH0011:00: ttyAMA0 at MMIO 0x9000000 (irq = 4, base_baud = 0)
is a SBSA
[ 0.463253] printk: console [ttyAMA0] enabled
[ 0.467459] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[ 0.468885] acpi PNP0A08:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM
Segments MSI HPX-Type3]
[ 0.471066] acpi PNP0A08:00: _OSC: platform does not support [LTR]
[ 0.472577] acpi PNP0A08:00: _OSC: OS now controls [PCIeHotplug SHPCHotplug
PME AER PCIeCapability]
[ 0.475134] acpi PNP0A08:00: ECAM area [mem 0x4010000000-0x401fffffff]
reserved by PNP0C02:00
[ 0.476964] acpi PNP0A08:00: ECAM at [mem 0x4010000000-0x401fffffff] for
[bus 00-ff]
[ 0.478652] Remapped I/O 0x000000003eff0000 to [io 0x0000-0xffff window]
[ 0.480389] PCI host bridge to bus 0000:00
[ 0.481267] pci_bus 0000:00: root bus resource [mem 0x10000000-0x3efeffff
window]
[ 0.482859] pci_bus 0000:00: root bus resource [io 0x0000-0xffff window]
[ 0.484307] pci_bus 0000:00: root bus resource [mem
0x8000000000-0xffffffffff window]
[ 0.485961] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 0.487239] pci 0000:00:00.0: [1b36:0008] type 00 class 0x060000
[ 0.489110] pci 0000:00:01.0: [1af4:1000] type 00 class 0x020000
[ 0.491308] pci 0000:00:01.0: reg 0x10: [io 0x00e0-0x00ff]
[ 0.493230] pci 0000:00:01.0: reg 0x14: [mem 0x10042000-0x10042fff]
[ 0.496781] pci 0000:00:01.0: reg 0x20: [mem 0x8000000000-0x8000003fff 64bit
pref]
[ 0.499406] pci 0000:00:01.0: reg 0x30: [mem 0xfffc0000-0xffffffff pref]
[ 0.501609] pci 0000:00:02.0: [1af4:1005] type 00 class 0x00ff00
[ 0.503816] pci 0000:00:02.0: reg 0x10: [io 0x00c0-0x00df]
[ 0.507966] pci 0000:00:02.0: reg 0x20: [mem 0x8000004000-0x8000007fff 64bit
pref]
[ 0.511105] pci 0000:00:03.0: [1af4:1009] type 00 class 0x000200
[ 0.514429] pci 0000:00:03.0: reg 0x10: [io 0x0080-0x00bf]
[ 0.516157] pci 0000:00:03.0: reg 0x14: [mem 0x10041000-0x10041fff]
[ 0.519078] pci 0000:00:03.0: reg 0x20: [mem 0x8000008000-0x800000bfff 64bit
pref]
[ 0.521923] pci 0000:00:04.0: [1b36:0003] type 00 class 0x070002
[ 0.523484] pci 0000:00:04.0: reg 0x10: [io 0x0100-0x010f]
[ 0.525161] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000
[ 0.527011] pci 0000:00:05.0: reg 0x10: [io 0x0000-0x007f]
[ 0.528780] pci 0000:00:05.0: reg 0x14: [mem 0x10040000-0x10040fff]
[ 0.531600] pci 0000:00:05.0: reg 0x20: [mem 0x800000c000-0x800000ffff 64bit
pref]
[ 0.535929] pci 0000:00:01.0: BAR 6: assigned [mem 0x10000000-0x1003ffff
pref]
[ 0.537471] pci 0000:00:01.0: BAR 4: assigned [mem 0x8000000000-0x8000003fff
64bit pref]
[ 0.539357] pci 0000:00:02.0: BAR 4: assigned [mem 0x8000004000-0x8000007fff
64bit pref]
[ 0.541113] pci 0000:00:03.0: BAR 4: assigned [mem 0x8000008000-0x800000bfff
64bit pref]
[ 0.542881] pci 0000:00:05.0: BAR 4: assigned [mem 0x800000c000-0x800000ffff
64bit pref]
[ 0.544773] pci 0000:00:01.0: BAR 1: assigned [mem 0x10040000-0x10040fff]
[ 0.546217] pci 0000:00:03.0: BAR 1: assigned [mem 0x10041000-0x10041fff]
[ 0.547671] pci 0000:00:05.0: BAR 1: assigned [mem 0x10042000-0x10042fff]
[ 0.549166] pci 0000:00:05.0: BAR 0: assigned [io 0x1000-0x107f]
[ 0.550948] pci 0000:00:03.0: BAR 0: assigned [io 0x1080-0x10bf]
[ 0.552694] pci 0000:00:01.0: BAR 0: assigned [io 0x10c0-0x10df]
[ 0.554615] pci 0000:00:02.0: BAR 0: assigned [io 0x10e0-0x10ff]
[ 0.556340] pci 0000:00:04.0: BAR 0: assigned [io 0x1100-0x110f]
[ 0.557656] pci_bus 0000:00: resource 4 [mem 0x10000000-0x3efeffff window]
[ 0.559240] pci_bus 0000:00: resource 5 [io 0x0000-0xffff window]
[ 0.560542] pci_bus 0000:00: resource 6 [mem 0x8000000000-0xffffffffff
window]
[ 0.562246] ACPI: PCI Interrupt Link [GSI0] (IRQs *35)
[ 0.563401] ACPI: PCI Interrupt Link [GSI1] (IRQs *36)
[ 0.564511] ACPI: PCI Interrupt Link [GSI2] (IRQs *37)
[ 0.565617] ACPI: PCI Interrupt Link [GSI3] (IRQs *38)
[ 0.567309] iommu: Default domain type: Translated
[ 0.568600] vgaarb: loaded
[ 0.569389] EDAC MC: Ver: 3.0.0
[ 0.570559] Registered efivars operations
[ 0.572043] NetLabel: Initializing
[ 0.572845] NetLabel: domain hash size = 128
[ 0.573765] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO
[ 0.575015] NetLabel: unlabeled traffic allowed by default
[ 0.576363] clocksource: Switched to clocksource arch_sys_counter
[ 0.613667] VFS: Disk quotas dquot_6.6.0
[ 0.614666] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[ 0.616590] AppArmor: AppArmor Filesystem Enabled
[ 0.617718] pnp: PnP ACPI init
[ 0.618734] system 00:00: [mem 0x4010000000-0x401fffffff window] could not
be reserved
[ 0.620474] pnp: PnP ACPI: found 1 devices
[ 0.625131] NET: Registered protocol family 2
[ 0.626447] tcp_listen_portaddr_hash hash table entries: 512 (order: 1, 8192
bytes, linear)
[ 0.628301] TCP established hash table entries: 8192 (order: 4, 65536 bytes,
linear)
[ 0.630227] TCP bind hash table entries: 8192 (order: 5, 131072 bytes,
linear)
[ 0.631814] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.633435] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[ 0.634877] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[ 0.636499] NET: Registered protocol family 1
[ 0.637439] NET: Registered protocol family 44
[ 0.638470] PCI: CLS 0 bytes, default 64
[ 0.639470] Trying to unpack rootfs image as initramfs...
[ 1.621131] Freeing initrd memory: 27696K
[ 1.634778] hw perfevents: enabled with armv8_pmuv3_0 PMU driver, 7 counters
available
[ 1.636503] kvm [1]: HYP mode not available
[ 1.638124] Initialise system trusted keyrings
[ 1.639145] Key type blacklist registered
[ 1.640173] workingset: timestamp_bits=44 max_order=18 bucket_order=0
[ 1.644529] zbud: loaded
[ 1.645533] integrity: Platform Keyring initialized
[ 1.646617] Key type asymmetric registered
[ 1.647487] Asymmetric key parser 'x509' registered
[ 1.648604] Block layer SCSI generic (bsg) driver version 0.4 loaded (major
249)
[ 1.650357] io scheduler mq-deadline registered
[ 1.652824] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[ 1.655159] input: Power Button as
/devices/LNXSYSTM:00/LNXSYBUS:00/PNP0C0C:00/input/input0
[ 1.657098] ACPI: Power Button [PWRB]
[ 1.659490] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[ 1.662244] PCI Interrupt Link [GSI0] enabled at IRQ 35
[ 1.663475] serial 0000:00:04.0: enabling device (0000 -> 0001)
[ 1.665810] printk: console [ttyS0] disabled
[ 1.696532] 0000:00:04.0: ttyS0 at I/O 0x1100 (irq = 37, base_baud = 115200)
is a 16550A
[ 2.044530] printk: console [ttyS0] enabled
[ 2.076493] 0000:00:04.0: ttyS1 at I/O 0x1108 (irq = 37, base_baud = 115200)
is a 16550A
[ 2.080754] Serial: AMBA driver
[ 2.082429] msm_serial: driver initialized
[ 2.084652] cacheinfo: Unable to detect cache hierarchy for CPU 0
[ 2.087848] mousedev: PS/2 mouse device common for all mice
[ 2.091003] rtc-efi rtc-efi.0: registered as rtc0
[ 2.093304] rtc-efi rtc-efi.0: setting system clock to 2020-11-01T10:17:30
UTC (1604225850)
[ 2.097725] ledtrig-cpu: registered to indicate activity on CPUs
[ 2.101566] NET: Registered protocol family 10
[ 2.127698] Segment Routing with IPv6
[ 2.129860] mip6: Mobile IPv6
[ 2.131254] NET: Registered protocol family 17
[ 2.133582] mpls_gso: MPLS GSO support
[ 2.135583] registered taskstats version 1
[ 2.137613] Loading compiled-in X.509 certificates
[ 2.200452] Loaded X.509 cert 'Debian Secure Boot CA:
6ccece7e4c6c0d1f6149f3dd27dfcc5cbb419ea1'
[ 2.204579] Loaded X.509 cert 'Debian Secure Boot Signer 2020: 00b55eb3b9'
[ 2.207767] zswap: loaded using pool lzo/zbud
[ 2.210238] Key type ._fscrypt registered
[ 2.212094] Key type .fscrypt registered
[ 2.214060] Key type fscrypt-provisioning registered
[ 2.216466] AppArmor: AppArmor sha1 policy hashing enabled
[ 2.227295] Freeing unused kernel memory: 5184K
[ 2.239010] Checked W+X mappings: passed, no W+X pages found
[ 2.241852] Run /init as init process
Loading, please wait...
Starting version 246.6-2
[ 2.602237] PCI Interrupt Link [GSI1] enabled at IRQ 36
[ 2.621235] virtio-pci 0000:00:01.0: enabling device (0005 -> 0007)
[ 2.649084] PCI Interrupt Link [GSI2] enabled at IRQ 37
[ 2.651636] virtio-pci 0000:00:02.0: enabling device (0005 -> 0007)
[ 2.690977] PCI Interrupt Link [GSI3] enabled at IRQ 38
[ 2.701934] virtio-pci 0000:00:03.0: enabling device (0005 -> 0007)
[ 2.710976] virtio-pci 0000:00:05.0: enabling device (0005 -> 0007)
[ 2.734187] virtio_blk virtio3: [vda] 52428800 512-byte logical blocks (26.8
GB/25.0 GiB)
[ 2.744603] vda: detected capacity change from 0 to 26843545600
[ 2.757848] vda: vda1 vda2
Begin: Loading essential drivers ... done.
Begin: Running /scripts/init-premount ... done.
Begin: Mounting root file system ... Begin: Running /scripts/local-top ... done.
Begin: Running /scripts/local-premount ... done.
Begin: Will now check root file system ... fsck from util-linux 2.36
[/sbin/fsck.ext4 (1) -- /dev/vda2] fsck.ext4 -a -C0 /dev/vda2
/dev/vda2: clean, 21257/1627024 files, 411160/6502144 blocks
done.
[ 2.970464] EXT4-fs (vda2): mounted filesystem with ordered data mode. Opts:
(null)
done.
Begin: Running /scripts/local-bottom ... done.
Begin: Running /scripts/init-bottom ... done.
[ 3.006924] random: fast init done
[ 3.081759] Not activating Mandatory Access Control as /sbin/tomoyo-init
does not exist.
[ 3.171115] systemd[1]: Inserted module 'autofs4'
[ 3.196891] random: crng init done
[ 3.214921] systemd[1]: systemd 246.6-2 running in system mode. (+PAM +AUDIT
+SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS
+ACL +XZ +LZ4 +ZSTD +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2
default-hierarchy=hybrid)
[ 3.225913] systemd[1]: Detected virtualization kvm.
[ 3.228229] systemd[1]: Detected architecture arm64.
Welcome to Debian GNU/Linux bullseye/sid!
[ 3.236454] systemd[1]: Set hostname to <host>.
[ 3.618819] systemd[1]: Queued start job for default target Graphical
Interface.
[ 3.625582] systemd[1]: Created slice system-getty.slice.
[ OK ] Created slice system-getty.slice.
[ 3.631577] systemd[1]: Created slice system-modprobe.slice.
[ OK ] Created slice system-modprobe.slice.
[ 3.638141] systemd[1]: Created slice system-serial\x2dgetty.slice.
[ OK ] Created slice system-serial\x2dgetty.slice.
[ 3.645156] systemd[1]: Created slice User and Session Slice.
[ OK ] Created slice User and Session Slice.
[ 3.650819] systemd[1]: Started Dispatch Password Requests to Console
Directory Watch.
[ OK ] Started Dispatch Password …ts to Console Directory Watch.
[ 3.658118] systemd[1]: Started Forward Password Requests to Wall Directory
Watch.
[ OK ] Started Forward Password R…uests to Wall Directory Watch.
[ 3.665556] systemd[1]: Set up automount Arbitrary Executable File Formats
File System Automount Point.
[ OK ] Set up automount Arbitrary…s File System Automount Point.
[ 3.673225] systemd[1]: Reached target Local Encrypted Volumes.
[ OK ] Reached target Local Encrypted Volumes.
[ 3.678380] systemd[1]: Reached target Paths.
[ OK ] Reached target Paths.
[ 3.682428] systemd[1]: Reached target Remote File Systems.
[ OK ] Reached target Remote File Systems.
[ 3.687253] systemd[1]: Reached target Slices.
[ OK ] Reached target Slices.
[ 3.691373] systemd[1]: Reached target Swap.
[ OK ] Reached target Swap.
[ 3.695848] systemd[1]: Listening on Syslog Socket.
[ OK ] Listening on Syslog Socket.
[ 3.700839] systemd[1]: Listening on fsck to fsckd communication Socket.
[ OK ] Listening on fsck to fsckd communication Socket.
[ 3.706716] systemd[1]: Listening on initctl Compatibility Named Pipe.
[ OK ] Listening on initctl Compatibility Named Pipe.
[ 3.712955] systemd[1]: Listening on Journal Audit Socket.
[ OK ] Listening on Journal Audit Socket.
[ 3.718335] systemd[1]: Listening on Journal Socket (/dev/log).
[ OK ] Listening on Journal Socket (/dev/log).
[ 3.724504] systemd[1]: Listening on Journal Socket.
[ OK ] Listening on Journal Socket.
[ 3.729813] systemd[1]: Listening on udev Control Socket.
[ OK ] Listening on udev Control Socket.
[ 3.735299] systemd[1]: Listening on udev Kernel Socket.
[ OK ] Listening on udev Kernel Socket.
[ 3.743688] systemd[1]: Mounting Huge Pages File System...
Mounting Huge Pages File System...
[ 3.758664] systemd[1]: Mounting POSIX Message Queue File System...
Mounting POSIX Message Queue File System...
[ 3.779607] systemd[1]: Mounting Kernel Debug File System...
Mounting Kernel Debug File System...
[ 3.792876] systemd[1]: Mounting Kernel Trace File System...
Mounting Kernel Trace File System...
[ 3.810009] systemd[1]: Starting Create list of static device nodes for the
current kernel...
Starting Create list of st…odes for the current kernel...
[ 3.828903] systemd[1]: Starting Load Kernel Module drm...
Starting Load Kernel Module drm...
[ 3.842303] systemd[1]: Condition check resulted in Set Up Additional Binary
Formats being skipped.
[ 3.850840] systemd[1]: Condition check resulted in File System Check on
Root Device being skipped.
[ 3.872388] systemd[1]: Starting Journal Service...
Starting Journal Service...
[ 3.901106] systemd[1]: Starting Load Kernel Modules...
Starting Load Kernel Modules...
[ 3.925781] systemd[1]: Starting Remount Root and Kernel File Systems...
Starting Remount Root and Kernel File Systems...
[ 3.972959] systemd[1]: Starting Coldplug All udev Devices...
Starting Coldplug All udev Devices...
[ 4.015005] systemd[1]: Mounted Huge Pages File System.
[ OK ] Mounted Huge Pages File System.
[ 4.043035] systemd[1]: Mounted POSIX Message Queue File System.
[ 4.046093] EXT4-fs (vda2): re-mounted. Opts: errors=remount-ro
[ OK ] Mounted POSIX Message Queue File System.
[ 4.066853] systemd[1]: Mounted Kernel Debug File System.
[ OK ] Mounted Kernel Debug File System.
[ 4.085282] systemd[1]: Mounted Kernel Trace File System.
[ OK ] Mounted Kernel Trace File System.
[ 4.108649] systemd[1]: Finished Create list of static device nodes for the
current kernel.
[ OK ] Finished Create list of st… nodes for the current kernel.
[ 4.129848] systemd[1]: modprobe@drm.service: Succeeded.
[ 4.148525] systemd[1]: Finished Load Kernel Module drm.
[ OK ] Finished Load Kernel Module drm.
[ 4.166257] systemd[1]: Finished Load Kernel Modules.
[ OK ] Finished Load Kernel Modules.
[ 4.188932] systemd[1]: Finished Remount Root and Kernel File Systems.
[ OK ] Finished Remount Root and Kernel File Systems.
[ 4.203486] systemd[1]: Condition check resulted in FUSE Control File System
being skipped.
[ 4.220943] systemd[1]: Condition check resulted in Kernel Configuration
File System being skipped.
[ 4.241116] systemd[1]: Condition check resulted in Rebuild Hardware
Database being skipped.
[ 4.252609] systemd[1]: Condition check resulted in Platform Persistent
Storage Archival being skipped.
[ 4.277179] systemd[1]: Starting Load/Save Random Seed...
Starting Load/Save Random Seed...
[ 4.309641] systemd[1]: Starting Apply Kernel Variables...
Starting Apply Kernel Variables...
[ 4.349707] systemd[1]: Starting Create System Users...
Starting Create System Users...
[ 4.391638] systemd[1]: Finished Load/Save Random Seed.
[ OK ] Finished Load/Save Random Seed.
[ 4.428303] systemd[1]: Finished Apply Kernel Variables.
[ OK ] Finished Apply Kernel Variables.
[ 4.491553] systemd[1]: Finished Create System Users.
[ OK ] Finished Create System Users.
[ 4.509834] systemd[1]: Finished Coldplug All udev Devices.
[ OK ] Finished Coldplug All udev Devices.
[ 4.529819] systemd[1]: Starting Helper to synchronize boot up for
ifupdown...
Starting Helper to synchronize boot up for ifupdown...
[ 4.555115] systemd[1]: Starting Create Static Device Nodes in /dev...
Starting Create Static Device Nodes in /dev...
[ 4.624309] systemd[1]: Finished Create Static Device Nodes in /dev.
[ OK ] Finished Create Static Device Nodes in /dev.
[ 4.636983] systemd[1]: Reached target Local File Systems (Pre).
[ OK ] Reached target Local File Systems (Pre).
[ 4.657866] systemd[1]: Starting Rule-based Manager for Device Events and
Files...
Starting Rule-based Manage…for Device Events and Files...
[ 4.757331] systemd[1]: Started Rule-based Manager for Device Events and
Files.
[ OK ] Started Rule-based Manager for Device Events and Files.
[ 5.167317] systemd[1]: Found device /dev/ttyAMA0.
[ OK ] Found device /dev/ttyAMA0.
[ 5.226984] systemd[1]: Found device QEMU PCI Dual-port 16550A Adapter (QEMU
Virtual Machine).
[ 5.266196] EFI Variables Facility v0.08 2004-May-17
[ 5.300804] 9pnet: Installing 9P2000 support
[ OK ] Found device QEMU PCI Dual…dapter (QEMU Virtual Machine).[
5.329622] pstore: Using crash dump compression: deflate
[ 5.332252] pstore: Registered efi as persistent store backend
[ 5.519197] systemd[1]: Found device /dev/disk/by-uuid/4425-3B5F.
[ OK ] Found device /dev/disk/by-uuid/4425-3B5F.
[ 5.536591] systemd[1]: Finished Helper to synchronize boot up for ifupdown.
[ OK ] Finished Helper to synchronize boot up for ifupdown.
[ 5.564859] systemd[1]: Mounting /boot/efi...
Mounting /boot/efi...
[ 5.577306] systemd[1]: Started Journal Service.
[ OK ] Started Journal Service.
Starting Flush Journal to Persistent Storage...
[ OK ] Mounted /boot/efi.
[ OK ] Reached target Local File Systems.
Starting Load AppArmor profiles...
[ OK ] Finished Flush Journal to Persistent Storage.
Starting Create Volatile Files and Directories...
[ OK ] Finished Create Volatile Files and Directories.
Starting Network Time Synchronization...
Starting Update UTMP about System Boot/Shutdown...
[ OK ] Finished Update UTMP about System Boot/Shutdown.
[ 6.067413] audit: type=1400 audit(1604225854.467:2): apparmor="STATUS"
operation="profile_load" profile="unconfined" name="lsb_release" pid=194
comm="apparmor_parser"
[ 6.316589] audit: type=1400 audit(1604225854.719:3): apparmor="STATUS"
operation="profile_load" profile="unconfined" name="nvidia_modprobe" pid=197
comm="apparmor_parser"
[ OK ] Finished Load AppArmor profiles.
[ 6.344464] audit: type=1400 audit(1604225854.727:4): apparmor="STATUS"
operation="profile_load" profile="unconfined" name="nvidia_modprobe//kmod"
pid=197 comm="apparmor_parser"
Starting Raise network interfaces...
[ OK ] Started Network Time Synchronization.
[ OK ] Reached target System Initialization.
[ OK ] Started Daily Cleanup of Temporary Directories.
[ OK ] Reached target System Time Set.
[ OK ] Reached target System Time Synchronized.
[ OK ] Started Daily apt download activities.
[ OK ] Started Daily apt upgrade and clean activities.
[ OK ] Started Periodic ext4 Onli…ata Check for All Filesystems.
[ OK ] Started Discard unused blocks once a week.
[ OK ] Started Daily rotation of log files.
[ OK ] Reached target Timers.
[ OK ] Listening on D-Bus System Message Bus Socket.
[ OK ] Reached target Sockets.
[ OK ] Reached target Basic System.
[ OK ] Started autopkgtest root shell on ttyS1.
[ OK ] Started Regular background program processing daemon.
[ OK ] Started D-Bus System Message Bus.
Starting Remove Stale Onli…t4 Metadata Check Snapshots...
Starting LSB: Hardware ran…tor entropy gatherer daemon...
Starting System Logging Service...
Starting User Login Management...
[ OK ] Started System Logging Service.
[ OK ] Started LSB: Hardware rand…rator entropy gatherer daemon.
[ OK ] Started User Login Management.
[ OK ] Finished Remove Stale Onli…ext4 Metadata Check Snapshots.
[* ] A start job is running for Raise network interfaces (5s / 5min 2s)
[** ] A start job is running for Raise network interfaces (6s / 5min 2s)
[*** ] A start job is running for Raise network interfaces (7s / 5min 2s)
[ *** ] A start job is running for Raise network interfaces (7s / 5min 2s)
[ *** ] A start job is running for Raise network interfaces (8s / 5min 2s)
[ ***] A start job is running for Raise network interfaces (8s / 5min 2s)
[ **] A start job is running for Raise network interfaces (9s / 5min 2s)
[ *] A start job is running for Raise network interfaces (10s / 5min 2s)
[ **] A start job is running for Raise network interfaces (10s / 5min 2s)
[ OK ] Finished Raise network interfaces.
[ OK ] Reached target Network.
Starting Permit User Sessions...
[ OK ] Finished Permit User Sessions.
[ OK ] Started Getty on tty1.
[ OK ] Started Serial Getty on ttyAMA0.
[ OK ] Started Serial Getty on ttyS0.
[ OK ] Reached target Login Prompts.
[ OK ] Reached target Multi-User System.
[ OK ] Reached target Graphical Interface.
Starting Update UTMP about System Runlevel Changes...
[ OK ] Finished Update UTMP about System Runlevel Changes.
Debian GNU/Linux bullseye/sid host ttyS0
host login: autopkgtest-virt-qemu: DBG: expect: found ""login prompt on ttyS0""
autopkgtest-virt-qemu: DBG: expect: "ok"
autopkgtest-virt-qemu: DBG: expect: found ""b'ok'""
autopkgtest-virt-qemu: DBG: setup_shell(): there already is a shell on ttyS1
autopkgtest-virt-qemu: DBG: expect: "#"
autopkgtest-virt-qemu: DBG: expect: found ""b'#'""
autopkgtest-virt-qemu: DBG: expect: "#"
autopkgtest-virt-qemu: DBG: expect: found ""b'#'""
autopkgtest-virt-qemu: DBG: expect: "# "
autopkgtest-virt-qemu: DBG: expect: found ""b'# '""
autopkgtest-virt-qemu: DBG: Copying host timezone Asia/Tokyo to VM
autopkgtest-virt-qemu: DBG: expect: "#"
autopkgtest-virt-qemu: DBG: expect: found ""b'#'""
autopkgtest-virt-qemu: DBG: expect: "/python"
autopkgtest-virt-qemu: DBG: expect: found ""b'/python'""
autopkgtest-virt-qemu: DBG: expect: "# "
autopkgtest-virt-qemu: DBG: expect: found ""b'# '""
autopkgtest-virt-qemu: DBG: execute-timeout:
/tmp/autopkgtest-qemu.iwcjv619/runcmd true
autopkgtest-virt-qemu: DBG: can connect to autopkgtest sh in VM
autopkgtest-virt-qemu: DBG: determine_normal_user: got user "user"
autopkgtest-virt-qemu: DBG: auxverb =
['/tmp/autopkgtest-qemu.iwcjv619/runcmd'], downtmp = None
autopkgtest-virt-qemu: DBG: execute-timeout:
/tmp/autopkgtest-qemu.iwcjv619/runcmd mktemp --directory --tmpdir
autopkgtest.XXXXXX
autopkgtest-virt-qemu: DBG: execute-timeout:
/tmp/autopkgtest-qemu.iwcjv619/runcmd chmod 1777 /tmp/autopkgtest.4DTPHS
autopkgtest-virt-qemu: DBG: cleanup...
qemu-system-aarch64: terminating on signal 15 from pid 24486 (/usr/bin/python3)
autopkgtest [19:17:50]: ERROR: testbed failure: cannot send to testbed: I/O
operation on closed file.
