0s autopkgtest [09:36:35]: starting date and time: 2024-09-14 09:36:35+0000 0s autopkgtest [09:36:35]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [09:36:35]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.bwgs8iyh/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:linux-meta,src:linux --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=linux-meta/6.11.0-7.7+1 linux/6.11.0-7.7' --setup-commands 'apt-get install -y ^kernel-testing--linux--full--preferred$ || apt-get install -y ^linux-image$ ^linux-headers$ || apt-get install -y ^linux-image-generic$ ^linux-headers-generic$' --setup-commands 'apt-get install -y ^kernel-testing--linux--modules-extra--preferred$ || apt-get install -y ^linux-modules-extra$ || :' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big-ppc64el --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos03-ppc64el-26.secgroup --name adt-oracular-ppc64el-multipath-tools-20240914-093635-juju-7f2275-prod-proposed-migration-environment-2-9ea77da9-2779-4fb7-af92-509881c8be73 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --net-id=net_prod-proposed-migration-ppc64el -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 122s autopkgtest [09:38:37]: testbed dpkg architecture: ppc64el 122s autopkgtest [09:38:37]: testbed apt version: 2.9.8 122s autopkgtest [09:38:37]: @@@@@@@@@@@@@@@@@@@@ test bed setup 123s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 123s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [300 kB] 123s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.5 kB] 123s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [13.2 kB] 123s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4496 B] 123s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [106 kB] 123s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2204 B] 123s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1372 B] 123s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 123s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [257 kB] 123s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [5656 B] 123s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [764 B] 123s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 125s Fetched 856 kB in 1s (1211 kB/s) 125s Reading package lists... 127s Reading package lists... 128s Building dependency tree... 128s Reading state information... 128s Calculating upgrade... 128s The following NEW packages will be installed: 128s libpython3.12t64 linux-headers-6.11.0-7 linux-headers-6.11.0-7-generic 128s linux-image-6.11.0-7-generic linux-modules-6.11.0-7-generic 128s linux-modules-extra-6.11.0-7-generic linux-tools-6.11.0-7 128s linux-tools-6.11.0-7-generic 128s The following packages will be upgraded: 128s hwdata linux-firmware linux-generic linux-headers-generic 128s linux-headers-virtual linux-image-generic linux-image-virtual linux-libc-dev 128s linux-tools-common linux-virtual 128s 10 upgraded, 8 newly installed, 0 to remove and 0 not upgraded. 128s Need to get 730 MB of archives. 128s After this operation, 349 MB of additional disk space will be used. 128s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el hwdata all 0.387-1 [29.4 kB] 129s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpython3.12t64 ppc64el 3.12.6-1 [2561 kB] 129s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el linux-firmware ppc64el 20240913.gita34e7a5f-0ubuntu2 [500 MB] 141s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-6.11.0-7-generic ppc64el 6.11.0-7.7 [32.8 MB] 142s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-6.11.0-7-generic ppc64el 6.11.0-7.7 [63.9 MB] 143s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-extra-6.11.0-7-generic ppc64el 6.11.0-7.7 [105 MB] 146s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-generic ppc64el 6.11.0-7.7+2 [1734 B] 146s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-generic ppc64el 6.11.0-7.7+2 [10.7 kB] 146s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-virtual ppc64el 6.11.0-7.7+2 [1726 B] 146s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-virtual ppc64el 6.11.0-7.7+2 [10.7 kB] 146s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-virtual ppc64el 6.11.0-7.7+2 [1644 B] 146s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.11.0-7 all 6.11.0-7.7 [13.9 MB] 146s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.11.0-7-generic ppc64el 6.11.0-7.7 [3945 kB] 146s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-generic ppc64el 6.11.0-7.7+2 [10.6 kB] 146s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-libc-dev ppc64el 6.11.0-7.7 [1653 kB] 146s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-common all 6.11.0-7.7 [483 kB] 146s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-7 ppc64el 6.11.0-7.7 [5177 kB] 147s Get:18 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-7-generic ppc64el 6.11.0-7.7 [1742 B] 147s Fetched 730 MB in 18s (39.9 MB/s) 147s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72839 files and directories currently installed.) 147s Preparing to unpack .../00-hwdata_0.387-1_all.deb ... 147s Unpacking hwdata (0.387-1) over (0.385-1) ... 147s Selecting previously unselected package libpython3.12t64:ppc64el. 147s Preparing to unpack .../01-libpython3.12t64_3.12.6-1_ppc64el.deb ... 147s Unpacking libpython3.12t64:ppc64el (3.12.6-1) ... 147s Preparing to unpack .../02-linux-firmware_20240913.gita34e7a5f-0ubuntu2_ppc64el.deb ... 147s Unpacking linux-firmware (20240913.gita34e7a5f-0ubuntu2) over (20240911.gitce299c0f-0ubuntu1) ... 151s Selecting previously unselected package linux-modules-6.11.0-7-generic. 151s Preparing to unpack .../03-linux-modules-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 151s Unpacking linux-modules-6.11.0-7-generic (6.11.0-7.7) ... 151s Selecting previously unselected package linux-image-6.11.0-7-generic. 151s Preparing to unpack .../04-linux-image-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 151s Unpacking linux-image-6.11.0-7-generic (6.11.0-7.7) ... 151s Selecting previously unselected package linux-modules-extra-6.11.0-7-generic. 151s Preparing to unpack .../05-linux-modules-extra-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 151s Unpacking linux-modules-extra-6.11.0-7-generic (6.11.0-7.7) ... 152s Preparing to unpack .../06-linux-generic_6.11.0-7.7+2_ppc64el.deb ... 152s Unpacking linux-generic (6.11.0-7.7+2) over (6.8.0-31.31) ... 152s Preparing to unpack .../07-linux-image-generic_6.11.0-7.7+2_ppc64el.deb ... 152s Unpacking linux-image-generic (6.11.0-7.7+2) over (6.8.0-31.31) ... 152s Preparing to unpack .../08-linux-virtual_6.11.0-7.7+2_ppc64el.deb ... 152s Unpacking linux-virtual (6.11.0-7.7+2) over (6.8.0-31.31) ... 152s Preparing to unpack .../09-linux-image-virtual_6.11.0-7.7+2_ppc64el.deb ... 152s Unpacking linux-image-virtual (6.11.0-7.7+2) over (6.8.0-31.31) ... 152s Preparing to unpack .../10-linux-headers-virtual_6.11.0-7.7+2_ppc64el.deb ... 152s Unpacking linux-headers-virtual (6.11.0-7.7+2) over (6.8.0-31.31) ... 152s Selecting previously unselected package linux-headers-6.11.0-7. 152s Preparing to unpack .../11-linux-headers-6.11.0-7_6.11.0-7.7_all.deb ... 152s Unpacking linux-headers-6.11.0-7 (6.11.0-7.7) ... 155s Selecting previously unselected package linux-headers-6.11.0-7-generic. 155s Preparing to unpack .../12-linux-headers-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 155s Unpacking linux-headers-6.11.0-7-generic (6.11.0-7.7) ... 156s Preparing to unpack .../13-linux-headers-generic_6.11.0-7.7+2_ppc64el.deb ... 156s Unpacking linux-headers-generic (6.11.0-7.7+2) over (6.8.0-31.31) ... 156s Preparing to unpack .../14-linux-libc-dev_6.11.0-7.7_ppc64el.deb ... 156s Unpacking linux-libc-dev:ppc64el (6.11.0-7.7) over (6.8.0-31.31) ... 156s Preparing to unpack .../15-linux-tools-common_6.11.0-7.7_all.deb ... 156s Unpacking linux-tools-common (6.11.0-7.7) over (6.8.0-31.31) ... 156s Selecting previously unselected package linux-tools-6.11.0-7. 156s Preparing to unpack .../16-linux-tools-6.11.0-7_6.11.0-7.7_ppc64el.deb ... 156s Unpacking linux-tools-6.11.0-7 (6.11.0-7.7) ... 156s Selecting previously unselected package linux-tools-6.11.0-7-generic. 156s Preparing to unpack .../17-linux-tools-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 156s Unpacking linux-tools-6.11.0-7-generic (6.11.0-7.7) ... 156s Setting up linux-headers-6.11.0-7 (6.11.0-7.7) ... 156s Setting up linux-modules-6.11.0-7-generic (6.11.0-7.7) ... 158s Setting up linux-firmware (20240913.gita34e7a5f-0ubuntu2) ... 158s Setting up linux-libc-dev:ppc64el (6.11.0-7.7) ... 158s Setting up linux-modules-extra-6.11.0-7-generic (6.11.0-7.7) ... 161s Setting up hwdata (0.387-1) ... 161s Setting up libpython3.12t64:ppc64el (3.12.6-1) ... 161s Setting up linux-image-6.11.0-7-generic (6.11.0-7.7) ... 163s I: /boot/vmlinux is now a symlink to vmlinux-6.11.0-7-generic 163s I: /boot/initrd.img is now a symlink to initrd.img-6.11.0-7-generic 163s Setting up linux-headers-6.11.0-7-generic (6.11.0-7.7) ... 163s Setting up linux-image-virtual (6.11.0-7.7+2) ... 163s Setting up linux-tools-common (6.11.0-7.7) ... 163s Setting up linux-tools-6.11.0-7 (6.11.0-7.7) ... 163s Setting up linux-image-generic (6.11.0-7.7+2) ... 163s Setting up linux-headers-generic (6.11.0-7.7+2) ... 163s Setting up linux-tools-6.11.0-7-generic (6.11.0-7.7) ... 163s Setting up linux-headers-virtual (6.11.0-7.7+2) ... 163s Setting up linux-generic (6.11.0-7.7+2) ... 163s Setting up linux-virtual (6.11.0-7.7+2) ... 163s Processing triggers for man-db (2.12.1-3) ... 164s Processing triggers for libc-bin (2.40-1ubuntu1) ... 164s Processing triggers for initramfs-tools (0.142ubuntu33) ... 164s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 164s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 173s Processing triggers for linux-image-6.11.0-7-generic (6.11.0-7.7) ... 173s /etc/kernel/postinst.d/initramfs-tools: 173s update-initramfs: Generating /boot/initrd.img-6.11.0-7-generic 173s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 181s /etc/kernel/postinst.d/zz-update-grub: 181s Sourcing file `/etc/default/grub' 181s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 181s Generating grub configuration file ... 182s Found linux image: /boot/vmlinux-6.11.0-7-generic 182s Found initrd image: /boot/initrd.img-6.11.0-7-generic 182s Found linux image: /boot/vmlinux-6.8.0-31-generic 182s Found initrd image: /boot/initrd.img-6.8.0-31-generic 182s Warning: os-prober will not be executed to detect other bootable partitions. 182s Systems on them will not be added to the GRUB boot configuration. 182s Check GRUB_DISABLE_OS_PROBER documentation entry. 182s Adding boot menu entry for UEFI Firmware Settings ... 182s done 182s Reading package lists... 182s Building dependency tree... 182s Reading state information... 182s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 183s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 183s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 183s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 183s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 184s Reading package lists... 184s Reading package lists... 184s Building dependency tree... 184s Reading state information... 185s Calculating upgrade... 185s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 185s Reading package lists... 185s Building dependency tree... 185s Reading state information... 185s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 186s Reading package lists... 186s Building dependency tree... 186s Reading state information... 186s linux-generic is already the newest version (6.11.0-7.7+2). 186s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 186s Reading package lists... 187s Building dependency tree... 187s Reading state information... 187s E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 187s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 187s Reading package lists... 187s Building dependency tree... 187s Reading state information... 187s E: Unable to locate package ^linux-modules-extra$ 187s E: Couldn't find any package by regex '^linux-modules-extra$' 187s autopkgtest [09:39:42]: rebooting testbed after setup commands that affected boot 191s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 224s autopkgtest [09:40:19]: testbed running kernel: Linux 6.11.0-7-generic #7-Ubuntu SMP Mon Sep 9 13:10:01 UTC 2024 227s autopkgtest [09:40:22]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 230s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (dsc) [2772 B] 230s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (tar) [588 kB] 230s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (diff) [42.7 kB] 230s gpgv: Signature made Thu Sep 5 17:42:16 2024 UTC 230s gpgv: using RSA key 63EEFC3DE14D5146CE7F24BF34B8AD7D9529E793 230s gpgv: Can't check signature: No public key 230s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.9-1ubuntu3.dsc: no acceptable signature found 230s autopkgtest [09:40:25]: testing package multipath-tools version 0.9.9-1ubuntu3 230s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 230s autopkgtest [09:40:25]: build not needed 231s autopkgtest [09:40:26]: test kpartx-file-loopback: preparing testbed 231s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 232s Reading package lists... 232s Building dependency tree... 232s Reading state information... 232s Starting pkgProblemResolver with broken count: 0 232s Starting 2 pkgProblemResolver with broken count: 0 232s Done 233s The following additional packages will be installed: 233s liburing2 qemu-utils 233s Recommended packages: 233s qemu-block-extra 233s The following NEW packages will be installed: 233s autopkgtest-satdep liburing2 qemu-utils 233s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 233s Need to get 2431 kB/2432 kB of archives. 233s After this operation, 16.9 MB of additional disk space will be used. 233s Get:1 /tmp/autopkgtest.0w3jVJ/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 233s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 233s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:9.0.2+ds-4ubuntu5 [2404 kB] 234s Fetched 2431 kB in 1s (3810 kB/s) 234s Selecting previously unselected package liburing2:ppc64el. 234s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 110271 files and directories currently installed.) 234s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 234s Unpacking liburing2:ppc64el (2.6-1) ... 234s Selecting previously unselected package qemu-utils. 234s Preparing to unpack .../qemu-utils_1%3a9.0.2+ds-4ubuntu5_ppc64el.deb ... 234s Unpacking qemu-utils (1:9.0.2+ds-4ubuntu5) ... 234s Selecting previously unselected package autopkgtest-satdep. 234s Preparing to unpack .../1-autopkgtest-satdep.deb ... 234s Unpacking autopkgtest-satdep (0) ... 234s Setting up liburing2:ppc64el (2.6-1) ... 234s Setting up qemu-utils (1:9.0.2+ds-4ubuntu5) ... 234s Setting up autopkgtest-satdep (0) ... 234s Processing triggers for man-db (2.12.1-3) ... 235s Processing triggers for libc-bin (2.40-1ubuntu1) ... 238s (Reading database ... 110295 files and directories currently installed.) 238s Removing autopkgtest-satdep (0) ... 239s autopkgtest [09:40:34]: test kpartx-file-loopback: [----------------------- 239s Formatting 'foo.img', fmt=raw size=20971520 240s Creating new GPT entries in memory. 240s Warning: The kernel is still using the old partition table. 240s The new table will be used at the next reboot or after you 240s run partprobe(8) or kpartx(8) 240s The operation has completed successfully. 240s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 240s standard_filename: OK 240s del devmap : loop0p1 240s No devices found 240s standard_filename_cleanup: OK 240s Formatting 'fou du FaFa.img', fmt=raw size=20971520 241s Creating new GPT entries in memory. 241s Warning: The kernel is still using the old partition table. 241s The new table will be used at the next reboot or after you 241s run partprobe(8) or kpartx(8) 241s The operation has completed successfully. 241s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 241s filename_with_spaces: OK 241s del devmap : loop0p1 241s No devices found 241s filename_with_spaces_cleanup: OK 241s autopkgtest [09:40:36]: test kpartx-file-loopback: -----------------------] 242s kpartx-file-loopback PASS 242s autopkgtest [09:40:37]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 242s autopkgtest [09:40:37]: test tgtbasedmpaths: preparing testbed 364s autopkgtest [09:42:39]: testbed dpkg architecture: ppc64el 364s autopkgtest [09:42:39]: testbed apt version: 2.9.8 364s autopkgtest [09:42:39]: @@@@@@@@@@@@@@@@@@@@ test bed setup 365s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 365s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4496 B] 365s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.5 kB] 365s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [13.2 kB] 365s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [300 kB] 365s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [106 kB] 365s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2204 B] 365s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1372 B] 365s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 365s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [257 kB] 365s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [5656 B] 365s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [764 B] 365s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 367s Fetched 856 kB in 1s (1138 kB/s) 367s Reading package lists... 369s Reading package lists... 369s Building dependency tree... 369s Reading state information... 370s Calculating upgrade... 370s The following NEW packages will be installed: 370s libpython3.12t64 linux-headers-6.11.0-7 linux-headers-6.11.0-7-generic 370s linux-image-6.11.0-7-generic linux-modules-6.11.0-7-generic 370s linux-modules-extra-6.11.0-7-generic linux-tools-6.11.0-7 370s linux-tools-6.11.0-7-generic 370s The following packages will be upgraded: 370s hwdata linux-firmware linux-generic linux-headers-generic 370s linux-headers-virtual linux-image-generic linux-image-virtual linux-libc-dev 370s linux-tools-common linux-virtual 370s 10 upgraded, 8 newly installed, 0 to remove and 0 not upgraded. 370s Need to get 730 MB of archives. 370s After this operation, 349 MB of additional disk space will be used. 370s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el hwdata all 0.387-1 [29.4 kB] 370s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpython3.12t64 ppc64el 3.12.6-1 [2561 kB] 370s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el linux-firmware ppc64el 20240913.gita34e7a5f-0ubuntu2 [500 MB] 389s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-6.11.0-7-generic ppc64el 6.11.0-7.7 [32.8 MB] 390s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-6.11.0-7-generic ppc64el 6.11.0-7.7 [63.9 MB] 392s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-extra-6.11.0-7-generic ppc64el 6.11.0-7.7 [105 MB] 395s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-generic ppc64el 6.11.0-7.7+2 [1734 B] 395s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-generic ppc64el 6.11.0-7.7+2 [10.7 kB] 395s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-virtual ppc64el 6.11.0-7.7+2 [1726 B] 395s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-virtual ppc64el 6.11.0-7.7+2 [10.7 kB] 395s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-virtual ppc64el 6.11.0-7.7+2 [1644 B] 395s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.11.0-7 all 6.11.0-7.7 [13.9 MB] 395s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.11.0-7-generic ppc64el 6.11.0-7.7 [3945 kB] 396s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-generic ppc64el 6.11.0-7.7+2 [10.6 kB] 396s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-libc-dev ppc64el 6.11.0-7.7 [1653 kB] 396s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-common all 6.11.0-7.7 [483 kB] 396s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-7 ppc64el 6.11.0-7.7 [5177 kB] 396s Get:18 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-7-generic ppc64el 6.11.0-7.7 [1742 B] 396s Fetched 730 MB in 26s (28.0 MB/s) 396s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72839 files and directories currently installed.) 396s Preparing to unpack .../00-hwdata_0.387-1_all.deb ... 396s Unpacking hwdata (0.387-1) over (0.385-1) ... 396s Selecting previously unselected package libpython3.12t64:ppc64el. 396s Preparing to unpack .../01-libpython3.12t64_3.12.6-1_ppc64el.deb ... 396s Unpacking libpython3.12t64:ppc64el (3.12.6-1) ... 396s Preparing to unpack .../02-linux-firmware_20240913.gita34e7a5f-0ubuntu2_ppc64el.deb ... 396s Unpacking linux-firmware (20240913.gita34e7a5f-0ubuntu2) over (20240911.gitce299c0f-0ubuntu1) ... 400s Selecting previously unselected package linux-modules-6.11.0-7-generic. 400s Preparing to unpack .../03-linux-modules-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 400s Unpacking linux-modules-6.11.0-7-generic (6.11.0-7.7) ... 400s Selecting previously unselected package linux-image-6.11.0-7-generic. 400s Preparing to unpack .../04-linux-image-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 400s Unpacking linux-image-6.11.0-7-generic (6.11.0-7.7) ... 400s Selecting previously unselected package linux-modules-extra-6.11.0-7-generic. 400s Preparing to unpack .../05-linux-modules-extra-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 400s Unpacking linux-modules-extra-6.11.0-7-generic (6.11.0-7.7) ... 401s Preparing to unpack .../06-linux-generic_6.11.0-7.7+2_ppc64el.deb ... 401s Unpacking linux-generic (6.11.0-7.7+2) over (6.8.0-31.31) ... 401s Preparing to unpack .../07-linux-image-generic_6.11.0-7.7+2_ppc64el.deb ... 401s Unpacking linux-image-generic (6.11.0-7.7+2) over (6.8.0-31.31) ... 401s Preparing to unpack .../08-linux-virtual_6.11.0-7.7+2_ppc64el.deb ... 401s Unpacking linux-virtual (6.11.0-7.7+2) over (6.8.0-31.31) ... 401s Preparing to unpack .../09-linux-image-virtual_6.11.0-7.7+2_ppc64el.deb ... 401s Unpacking linux-image-virtual (6.11.0-7.7+2) over (6.8.0-31.31) ... 401s Preparing to unpack .../10-linux-headers-virtual_6.11.0-7.7+2_ppc64el.deb ... 401s Unpacking linux-headers-virtual (6.11.0-7.7+2) over (6.8.0-31.31) ... 401s Selecting previously unselected package linux-headers-6.11.0-7. 401s Preparing to unpack .../11-linux-headers-6.11.0-7_6.11.0-7.7_all.deb ... 401s Unpacking linux-headers-6.11.0-7 (6.11.0-7.7) ... 404s Selecting previously unselected package linux-headers-6.11.0-7-generic. 404s Preparing to unpack .../12-linux-headers-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 404s Unpacking linux-headers-6.11.0-7-generic (6.11.0-7.7) ... 405s Preparing to unpack .../13-linux-headers-generic_6.11.0-7.7+2_ppc64el.deb ... 405s Unpacking linux-headers-generic (6.11.0-7.7+2) over (6.8.0-31.31) ... 405s Preparing to unpack .../14-linux-libc-dev_6.11.0-7.7_ppc64el.deb ... 405s Unpacking linux-libc-dev:ppc64el (6.11.0-7.7) over (6.8.0-31.31) ... 405s Preparing to unpack .../15-linux-tools-common_6.11.0-7.7_all.deb ... 405s Unpacking linux-tools-common (6.11.0-7.7) over (6.8.0-31.31) ... 405s Selecting previously unselected package linux-tools-6.11.0-7. 405s Preparing to unpack .../16-linux-tools-6.11.0-7_6.11.0-7.7_ppc64el.deb ... 405s Unpacking linux-tools-6.11.0-7 (6.11.0-7.7) ... 405s Selecting previously unselected package linux-tools-6.11.0-7-generic. 405s Preparing to unpack .../17-linux-tools-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 405s Unpacking linux-tools-6.11.0-7-generic (6.11.0-7.7) ... 405s Setting up linux-headers-6.11.0-7 (6.11.0-7.7) ... 405s Setting up linux-modules-6.11.0-7-generic (6.11.0-7.7) ... 407s Setting up linux-firmware (20240913.gita34e7a5f-0ubuntu2) ... 407s Setting up linux-libc-dev:ppc64el (6.11.0-7.7) ... 407s Setting up linux-modules-extra-6.11.0-7-generic (6.11.0-7.7) ... 409s Setting up hwdata (0.387-1) ... 409s Setting up libpython3.12t64:ppc64el (3.12.6-1) ... 409s Setting up linux-image-6.11.0-7-generic (6.11.0-7.7) ... 411s I: /boot/vmlinux is now a symlink to vmlinux-6.11.0-7-generic 411s I: /boot/initrd.img is now a symlink to initrd.img-6.11.0-7-generic 411s Setting up linux-headers-6.11.0-7-generic (6.11.0-7.7) ... 411s Setting up linux-image-virtual (6.11.0-7.7+2) ... 411s Setting up linux-tools-common (6.11.0-7.7) ... 411s Setting up linux-tools-6.11.0-7 (6.11.0-7.7) ... 411s Setting up linux-image-generic (6.11.0-7.7+2) ... 411s Setting up linux-headers-generic (6.11.0-7.7+2) ... 411s Setting up linux-tools-6.11.0-7-generic (6.11.0-7.7) ... 411s Setting up linux-headers-virtual (6.11.0-7.7+2) ... 411s Setting up linux-generic (6.11.0-7.7+2) ... 411s Setting up linux-virtual (6.11.0-7.7+2) ... 411s Processing triggers for man-db (2.12.1-3) ... 413s Processing triggers for libc-bin (2.40-1ubuntu1) ... 413s Processing triggers for initramfs-tools (0.142ubuntu33) ... 413s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 413s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 421s Processing triggers for linux-image-6.11.0-7-generic (6.11.0-7.7) ... 421s /etc/kernel/postinst.d/initramfs-tools: 421s update-initramfs: Generating /boot/initrd.img-6.11.0-7-generic 421s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 428s /etc/kernel/postinst.d/zz-update-grub: 428s Sourcing file `/etc/default/grub' 428s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 428s Generating grub configuration file ... 428s Found linux image: /boot/vmlinux-6.11.0-7-generic 428s Found initrd image: /boot/initrd.img-6.11.0-7-generic 429s Found linux image: /boot/vmlinux-6.8.0-31-generic 429s Found initrd image: /boot/initrd.img-6.8.0-31-generic 429s Warning: os-prober will not be executed to detect other bootable partitions. 429s Systems on them will not be added to the GRUB boot configuration. 429s Check GRUB_DISABLE_OS_PROBER documentation entry. 429s Adding boot menu entry for UEFI Firmware Settings ... 429s done 429s Reading package lists... 429s Building dependency tree... 429s Reading state information... 429s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 430s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 430s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 430s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 430s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 431s Reading package lists... 431s Reading package lists... 431s Building dependency tree... 431s Reading state information... 431s Calculating upgrade... 431s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 431s Reading package lists... 431s Building dependency tree... 431s Reading state information... 432s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 432s Reading package lists... 432s Building dependency tree... 432s Reading state information... 432s linux-generic is already the newest version (6.11.0-7.7+2). 432s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 433s Reading package lists... 433s Building dependency tree... 433s Reading state information... 433s E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 433s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 433s Reading package lists... 433s Building dependency tree... 433s Reading state information... 433s E: Unable to locate package ^linux-modules-extra$ 433s E: Couldn't find any package by regex '^linux-modules-extra$' 433s autopkgtest [09:43:48]: rebooting testbed after setup commands that affected boot 437s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 468s Reading package lists... 469s Building dependency tree... 469s Reading state information... 469s Starting pkgProblemResolver with broken count: 0 469s Starting 2 pkgProblemResolver with broken count: 0 469s Done 469s The following additional packages will be installed: 469s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 469s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 469s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 469s librdmacm1t64 lsscsi open-iscsi tgt 469s Suggested packages: 469s fio-examples gnuplot tgt-glusterfs tgt-rbd 469s Recommended packages: 469s finalrd 469s The following NEW packages will be installed: 469s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 469s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 469s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 469s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 469s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 469s Need to get 11.0 MB/11.0 MB of archives. 469s After this operation, 50.0 MB of additional disk space will be used. 469s Get:1 /tmp/autopkgtest.0w3jVJ/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [736 B] 469s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 470s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 470s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 470s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2ubuntu1 [80.6 kB] 470s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 470s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 470s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-5ubuntu1 [21.7 kB] 470s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-5ubuntu1 [308 kB] 470s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-5ubuntu1 [46.3 kB] 470s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-5ubuntu1 [99.1 kB] 470s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-2build1 [98.5 kB] 470s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2.2ubuntu1 [23.7 kB] 470s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2.2ubuntu1 [73.4 kB] 470s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 470s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3.2ubuntu2 [260 kB] 470s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3.2ubuntu2 [281 kB] 470s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~rc2-0ubuntu1 [4194 kB] 470s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 470s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~rc2-0ubuntu1 [3714 kB] 470s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 470s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 471s Preconfiguring packages ... 471s Fetched 11.0 MB in 1s (10.4 MB/s) 471s Selecting previously unselected package libopeniscsiusr. 471s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 110271 files and directories currently installed.) 471s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 471s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 471s Selecting previously unselected package libisns0t64:ppc64el. 471s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 471s Unpacking libisns0t64:ppc64el (0.101-1) ... 471s Selecting previously unselected package open-iscsi. 471s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 471s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 471s Selecting previously unselected package librdmacm1t64:ppc64el. 471s Preparing to unpack .../03-librdmacm1t64_52.0-2ubuntu1_ppc64el.deb ... 471s Unpacking librdmacm1t64:ppc64el (52.0-2ubuntu1) ... 471s Selecting previously unselected package libconfig-general-perl. 471s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 471s Unpacking libconfig-general-perl (2.65-2) ... 471s Selecting previously unselected package tgt. 471s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 471s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 471s Selecting previously unselected package libgfxdr0:ppc64el. 471s Preparing to unpack .../06-libgfxdr0_11.1-5ubuntu1_ppc64el.deb ... 471s Unpacking libgfxdr0:ppc64el (11.1-5ubuntu1) ... 471s Selecting previously unselected package libglusterfs0:ppc64el. 471s Preparing to unpack .../07-libglusterfs0_11.1-5ubuntu1_ppc64el.deb ... 471s Unpacking libglusterfs0:ppc64el (11.1-5ubuntu1) ... 471s Selecting previously unselected package libgfrpc0:ppc64el. 471s Preparing to unpack .../08-libgfrpc0_11.1-5ubuntu1_ppc64el.deb ... 471s Unpacking libgfrpc0:ppc64el (11.1-5ubuntu1) ... 471s Selecting previously unselected package libgfapi0:ppc64el. 471s Preparing to unpack .../09-libgfapi0_11.1-5ubuntu1_ppc64el.deb ... 471s Unpacking libgfapi0:ppc64el (11.1-5ubuntu1) ... 471s Selecting previously unselected package libnbd0. 471s Preparing to unpack .../10-libnbd0_1.20.2-2build1_ppc64el.deb ... 471s Unpacking libnbd0 (1.20.2-2build1) ... 471s Selecting previously unselected package libdaxctl1:ppc64el. 471s Preparing to unpack .../11-libdaxctl1_77-2.2ubuntu1_ppc64el.deb ... 471s Unpacking libdaxctl1:ppc64el (77-2.2ubuntu1) ... 471s Selecting previously unselected package libndctl6:ppc64el. 471s Preparing to unpack .../12-libndctl6_77-2.2ubuntu1_ppc64el.deb ... 471s Unpacking libndctl6:ppc64el (77-2.2ubuntu1) ... 471s Selecting previously unselected package libpmem1:ppc64el. 471s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 471s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 471s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 471s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 471s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 471s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 471s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 471s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 471s Selecting previously unselected package librados2. 471s Preparing to unpack .../16-librados2_19.2.0~rc2-0ubuntu1_ppc64el.deb ... 471s Unpacking librados2 (19.2.0~rc2-0ubuntu1) ... 472s Selecting previously unselected package libpmemobj1:ppc64el. 472s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 472s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 472s Selecting previously unselected package librbd1. 472s Preparing to unpack .../18-librbd1_19.2.0~rc2-0ubuntu1_ppc64el.deb ... 472s Unpacking librbd1 (19.2.0~rc2-0ubuntu1) ... 472s Selecting previously unselected package fio. 472s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 472s Unpacking fio (3.37-1) ... 472s Selecting previously unselected package lsscsi. 472s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 472s Unpacking lsscsi (0.32-1build1) ... 472s Selecting previously unselected package autopkgtest-satdep. 472s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 472s Unpacking autopkgtest-satdep (0) ... 472s Setting up libconfig-general-perl (2.65-2) ... 472s Setting up libisns0t64:ppc64el (0.101-1) ... 472s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 472s Setting up libnbd0 (1.20.2-2build1) ... 472s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 472s Setting up libglusterfs0:ppc64el (11.1-5ubuntu1) ... 472s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 472s Setting up lsscsi (0.32-1build1) ... 472s Setting up libdaxctl1:ppc64el (77-2.2ubuntu1) ... 472s Setting up libndctl6:ppc64el (77-2.2ubuntu1) ... 472s Setting up librdmacm1t64:ppc64el (52.0-2ubuntu1) ... 472s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 472s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 473s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 473s Setting up libgfxdr0:ppc64el (11.1-5ubuntu1) ... 473s Setting up librados2 (19.2.0~rc2-0ubuntu1) ... 473s Setting up open-iscsi (2.1.10-1ubuntu1) ... 473s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 474s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 474s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 474s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 474s Setting up librbd1 (19.2.0~rc2-0ubuntu1) ... 474s Setting up libgfrpc0:ppc64el (11.1-5ubuntu1) ... 474s Setting up libgfapi0:ppc64el (11.1-5ubuntu1) ... 474s Setting up fio (3.37-1) ... 475s Setting up autopkgtest-satdep (0) ... 475s Processing triggers for man-db (2.12.1-3) ... 476s Processing triggers for initramfs-tools (0.142ubuntu33) ... 476s update-initramfs: Generating /boot/initrd.img-6.11.0-7-generic 476s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 484s Processing triggers for libc-bin (2.40-1ubuntu1) ... 487s (Reading database ... 110512 files and directories currently installed.) 487s Removing autopkgtest-satdep (0) ... 489s autopkgtest [09:44:44]: test tgtbasedmpaths: [----------------------- 489s + targetname=iqn.2016-11.foo.com:target.iscsi 489s + pwd 489s + cwd=/tmp/autopkgtest.0w3jVJ/build.1ns/src 489s + testdir=/mnt/tgtmpathtest 489s + localhost=127.0.0.1 489s + portal=127.0.0.1:3260 489s + maxpaths=4 489s + backfn=backingfile 489s + expectwwid=60000000000000000e00000000010001 489s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 489s + bglog=/tmp/autopkgtest.0w3jVJ/tgtbasedmpaths-artifacts/test-background.log 489s + fioprep=/tmp/autopkgtest.0w3jVJ/tgtbasedmpaths-artifacts/path-change-prep.fio 489s + fiovrfy=/tmp/autopkgtest.0w3jVJ/tgtbasedmpaths-artifacts/path-change-check.fio 489s + mkdir -p /etc/multipath 489s + echo /360000000000000000e00000000010001/ 489s + service tgt restart 490s + truncate --size 100M backingfile 490s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 490s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 490s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.0w3jVJ/build.1ns/src/backingfile 490s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 490s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 490s login #1 490s + echo login #1 490s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 490s + seq 2 4 490s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 490s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 490s extra login #2 490s + echo extra login #2 490s + iscsiadm --mode session -r 1 --op new 490s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 490s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 490s + echo extra login #3 490s + iscsiadm --mode session -r 1 --op new 490s extra login #3 490s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 490s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 490s + echo extra login #4 490s + iscsiadm --mode session -r 1 --op new 490s extra login #4 490s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 490s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 490s + udevadm settle 490s + sleep 5 495s Status after initial setup 495s + echo Status after initial setup 495s + tgtadm --lld iscsi --mode target --op show 495s Target 1: iqn.2016-11.foo.com:target.iscsi 495s System information: 495s Driver: iscsi 495s State: ready 495s I_T nexus information: 495s I_T nexus: 1 495s Initiator: iqn.2004-10.com.ubuntu:01:58d786576e2 alias: autopkgtest 495s Connection: 0 495s IP Address: 127.0.0.1 495s I_T nexus: 2 495s Initiator: iqn.2004-10.com.ubuntu:01:58d786576e2 alias: autopkgtest 495s Connection: 0 495s IP Address: 127.0.0.1 495s I_T nexus: 3 495s Initiator: iqn.2004-10.com.ubuntu:01:58d786576e2 alias: autopkgtest 495s Connection: 0 495s IP Address: 127.0.0.1 495s I_T nexus: 4 495s Initiator: iqn.2004-10.com.ubuntu:01:58d786576e2 alias: autopkgtest 495s Connection: 0 495s IP Address: 127.0.0.1 495s LUN information: 495s LUN: 0 495s Type: controller 495s SCSI ID: IET 00010000 495s SCSI SN: beaf10 495s Size: 0 MB, Block size: 1 495s Online: Yes 495s Removable media: No 495s Prevent removal: No 495s Readonly: No 495s SWP: No 495s Thin-provisioning: No 495s Backing store type: null 495s Backing store path: None 495s Backing store flags: 495s LUN: 1 495s Type: disk 495s SCSI ID: IET 00010001 495s SCSI SN: beaf11 495s Size: 105 MB, Block size: 512 495s Online: Yes 495s Removable media: No 495s Prevent removal: No 495s Readonly: No 495s SWP: No 495s Thin-provisioning: No 495s Backing store type: rdwr 495s Backing store path: /tmp/autopkgtest.0w3jVJ/build.1ns/src/backingfile 495s Backing store flags: 495s Account information: 495s ACL information: 495s ALL 495s + tgtadm --lld iscsi --op show --mode conn --tid 1 495s Session: 4 495s Connection: 0 495s Initiator: iqn.2004-10.com.ubuntu:01:58d786576e2 495s IP Address: 127.0.0.1 495s Session: 3 495s Connection: 0 495s Initiator: iqn.2004-10.com.ubuntu:01:58d786576e2 495s IP Address: 127.0.0.1 495s Session: 2 495s Connection: 0 495s Initiator: iqn.2004-10.com.ubuntu:01:58d786576e2 495s IP Address: 127.0.0.1 495s Session: 1 495s Connection: 0 495s Initiator: iqn.2004-10.com.ubuntu:01:58d786576e2 495s IP Address: 127.0.0.1 495s + iscsiadm --mode session -P 1 495s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 495s Current Portal: 127.0.0.1:3260,1 495s Persistent Portal: 127.0.0.1:3260,1 495s ********** 495s Interface: 495s ********** 495s Iface Name: default 495s Iface Transport: tcp 495s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:58d786576e2 495s Iface IPaddress: 127.0.0.1 495s Iface HWaddress: default 495s Iface Netdev: default 495s SID: 1 495s iSCSI Connection State: LOGGED IN 495s iSCSI Session State: LOGGED_IN 495s Internal iscsid Session State: NO CHANGE 495s 495s ********** 495s Interface: 495s ********** 495s Iface Name: default 495s Iface Transport: tcp 495s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:58d786576e2 495s Iface IPaddress: 127.0.0.1 495s Iface HWaddress: default 495s Iface Netdev: default 495s SID: 2 495s iSCSI Connection State: LOGGED IN 495s iSCSI Session State: LOGGED_IN 495s Internal iscsid Session State: NO CHANGE 495s 495s ********** 495s Interface: 495s ********** 495s Iface Name: default 495s Iface Transport: tcp 495s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:58d786576e2 495s Iface IPaddress: 127.0.0.1 495s Iface HWaddress: default 495s Iface Netdev: default 495s SID: 3 495s iSCSI Connection State: LOGGED IN 495s iSCSI Session State: LOGGED_IN 495s Internal iscsid Session State: NO CHANGE 495s 495s ********** 495s Interface: 495s ********** 495s Iface Name: default 495s Iface Transport: tcp 495s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:58d786576e2 495s Iface IPaddress: 127.0.0.1 495s Iface HWaddress: default 495s Iface Netdev: default 495s SID: 4 495s iSCSI Connection State: LOGGED IN 495s iSCSI Session State: LOGGED_IN 495s Internal iscsid Session State: NO CHANGE 495s + lsscsi -liv 495s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 495s + multipath -v3 -ll 495s 47.528305 | set open fds limit to 1073741816/1073741816 495s 47.528382 | _read_bindings_file: reading /etc/multipath/bindings 495s 47.528416 | loading /usr/lib/multipath/libchecktur.so checker 495s 47.528510 | checker tur: message table size = 4 495s 47.528519 | loading /usr/lib/multipath/libprioconst.so prioritizer 495s 47.528641 | _init_foreign: foreign library "nvme" is not enabled 495s 47.533425 | vda: device node name blacklisted 495s 47.533717 | sda: size = 204800 495s 47.533848 | sda: vendor = IET 495s 47.533871 | sda: product = VIRTUAL-DISK 495s 47.533895 | sda: rev = 0001 495s 47.534540 | sda: h:b:t:l = 0:0:0:1 495s 47.534880 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 495s 47.534884 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 495s 47.534887 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 495s 47.535054 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 495s 47.535059 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 495s 47.535075 | sda: serial = beaf11 495s 47.535077 | sda: detect_checker = yes (setting: multipath internal) 495s 47.535105 | sda checker timeout = 30 s (setting: kernel sysfs) 495s 47.535524 | sda: path_checker = tur (setting: multipath internal) 495s 47.535636 | sda: tur state = up 495s 47.535760 | sdb: size = 204800 495s 47.535887 | sdb: vendor = IET 495s 47.535909 | sdb: product = VIRTUAL-DISK 495s 47.535932 | sdb: rev = 0001 495s 47.536527 | sdb: h:b:t:l = 1:0:0:1 495s 47.536865 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 495s 47.536869 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 495s 47.536871 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 495s 47.537010 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 495s 47.537014 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 495s 47.537027 | sdb: serial = beaf11 495s 47.537029 | sdb: detect_checker = yes (setting: multipath internal) 495s 47.537055 | sdb checker timeout = 30 s (setting: kernel sysfs) 495s 47.537202 | sdb: path_checker = tur (setting: multipath internal) 495s 47.537307 | sdb: tur state = up 495s 47.537429 | sdc: size = 204800 495s 47.537555 | sdc: vendor = IET 495s 47.537577 | sdc: product = VIRTUAL-DISK 495s 47.537615 | sdc: rev = 0001 495s 47.538260 | sdc: h:b:t:l = 2:0:0:1 495s 47.538617 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 495s 47.538621 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 495s 47.538624 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 495s 47.538764 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 495s 47.538768 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 495s 47.538780 | sdc: serial = beaf11 495s 47.538783 | sdc: detect_checker = yes (setting: multipath internal) 495s 47.538808 | sdc checker timeout = 30 s (setting: kernel sysfs) 495s 47.538916 | sdc: path_checker = tur (setting: multipath internal) 495s 47.538992 | sdc: tur state = up 495s 47.539119 | sdd: size = 204800 495s 47.539251 | sdd: vendor = IET 495s 47.539274 | sdd: product = VIRTUAL-DISK 495s 47.539297 | sdd: rev = 0001 495s 47.539920 | sdd: h:b:t:l = 3:0:0:1 495s 47.540292 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 495s 47.540300 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 495s 47.540302 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 495s 47.540438 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 495s 47.540442 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 495s 47.540455 | sdd: serial = beaf11 495s 47.540457 | sdd: detect_checker = yes (setting: multipath internal) 495s 47.540483 | sdd checker timeout = 30 s (setting: kernel sysfs) 495s 47.540591 | sdd: path_checker = tur (setting: multipath internal) 495s 47.540666 | sdd: tur state = up 495s 47.540756 | loop0: device node name blacklisted 495s 47.540839 | loop1: device node name blacklisted 495s 47.540920 | loop2: device node name blacklisted 495s 47.540998 | loop3: device node name blacklisted 495s 47.541075 | loop4: device node name blacklisted 495s 47.541152 | loop5: device node name blacklisted 495s 47.541229 | loop6: device node name blacklisted 495s 47.541306 | loop7: device node name blacklisted 495s 47.541390 | dm-0: device node name blacklisted 495s 47.542509 | multipath-tools v0.9.9 (05/03, 2024) 495s 47.542521 | libdevmapper version 1.02.196 495s 47.542673 | kernel device mapper v4.48.0 495s 47.542688 | DM multipath kernel driver v1.14.0 495s 47.542804 | sda: size = 204800 495s 47.542810 | sda: vendor = IET 495s 47.542812 | sda: product = VIRTUAL-DISK 495s 47.542815 | sda: rev = 0001 495s 47.543382 | sda: h:b:t:l = 0:0:0:1 495s 47.543495 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 495s 47.543514 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 495s 47.543517 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 495s 47.543529 | sda: serial = beaf11 495s 47.543658 | sda: tur state = up 495s 47.543664 | sda: uid = 360000000000000000e00000000010001 (udev) 495s 47.543667 | sda: detect_prio = yes (setting: multipath internal) 495s 47.543670 | sda: prio = const (setting: multipath internal) 495s 47.543672 | sda: prio args = "" (setting: multipath internal) 495s 47.543674 | sda: const prio = 1 495s 47.543695 | sdb: size = 204800 495s 47.543700 | sdb: vendor = IET 495s 47.543702 | sdb: product = VIRTUAL-DISK 495s 47.543705 | sdb: rev = 0001 495s 47.544271 | sdb: h:b:t:l = 1:0:0:1 495s 47.544386 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 495s 47.544405 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 495s 47.544408 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 495s 47.544419 | sdb: serial = beaf11 495s 47.544500 | sdb: tur state = up 495s 47.544505 | sdb: uid = 360000000000000000e00000000010001 (udev) 495s 47.544507 | sdb: detect_prio = yes (setting: multipath internal) 495s 47.544509 | sdb: prio = const (setting: multipath internal) 495s 47.544511 | sdb: prio args = "" (setting: multipath internal) 495s 47.544513 | sdb: const prio = 1 495s 47.544534 | sdc: size = 204800 495s 47.544540 | sdc: vendor = IET 495s 47.544542 | sdc: product = VIRTUAL-DISK 495s 47.544545 | sdc: rev = 0001 495s 47.545096 | sdc: h:b:t:l = 2:0:0:1 495s 47.545202 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 495s 47.545220 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 495s 47.545224 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 495s 47.545235 | sdc: serial = beaf11 495s 47.545315 | sdc: tur state = up 495s 47.545320 | sdc: uid = 360000000000000000e00000000010001 (udev) 495s 47.545322 | sdc: detect_prio = yes (setting: multipath internal) 495s 47.545325 | sdc: prio = const (setting: multipath internal) 495s 47.545326 | sdc: prio args = "" (setting: multipath internal) 495s 47.545329 | sdc: const prio = 1 495s 47.545348 | sdd: size = 204800 495s 47.545365 | sdd: vendor = IET 495s 47.545368 | sdd: product = VIRTUAL-DISK 495s 47.545370 | sdd: rev = 0001 495s 47.545919 | sdd: h:b:t:l = 3:0:0:1 495s 47.546028 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 495s 47.546046 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 495s 47.546049 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 495s 47.546060 | sdd: serial = beaf11 495s 47.546138 | sdd: tur state = up 495s 47.546143 | sdd: uid = 360000000000000000e00000000010001 (udev) 495s 47.546145 | sdd: detect_prio = yes (setting: multipath internal) 495s 47.546147 | sdd: prio = const (setting: multipath internal) 495s 47.546149 | sdd: prio args = "" (setting: multipath internal) 495s 47.546151 | sdd: const prio = 1 495s 47.546952 | unloading tur checker 495s 47.547011 | unloading const prioritizer 495s + dmsetup table 495s + grep . /etc/multipath/bindings /etc/multipath/wwids 495s + systemctl status multipathd.service 495s + ret_code=0 495s + systemctl status multipathd.socket 495s + ret_code=3 495s + [ 3 -eq 0 ] 495s + [ 3 -eq 3 ] 495s + ls -la /dev/mapper/ 495s + echo journal 495s + journalctl -b 495s [0:0:0:0] storage IET Controller 0001 - - 495s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 495s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 495s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 495s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 495s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 495s [1:0:0:0] storage IET Controller 0001 - - 495s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 495s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 495s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 495s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 495s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 495s [2:0:0:0] storage IET Controller 0001 - - 495s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 495s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 495s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 495s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 495s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 495s [3:0:0:0] storage IET Controller 0001 - - 495s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 495s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 495s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 495s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 495s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 495s NVMe module may not be loaded 495s ===== paths list ===== 495s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 495s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 495s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 495s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 495s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 495s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 495s size=100M features='0' hwhandler='0' wp=rw 495s |-+- policy='service-time 0' prio=1 status=active 495s | `- 0:0:0:1 sda 8:0 active ready running 495s |-+- policy='service-time 0' prio=1 status=enabled 495s | `- 1:0:0:1 sdb 8:16 active ready running 495s |-+- policy='service-time 0' prio=1 status=enabled 495s | `- 2:0:0:1 sdc 8:32 active ready running 495s `-+- policy='service-time 0' prio=1 status=enabled 495s `- 3:0:0:1 sdd 8:48 active ready running 495s mpatha: 0 204800 multipath 0 0 4 1 service-time 0 1 2 8:0 1 1 service-time 0 1 2 8:16 1 1 service-time 0 1 2 8:32 1 1 service-time 0 1 2 8:48 1 1 495s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 495s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 495s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 495s /etc/multipath/bindings:# 495s /etc/multipath/bindings:# Format: 495s /etc/multipath/bindings:# alias wwid 495s /etc/multipath/bindings:# 495s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 495s /etc/multipath/wwids:/360000000000000000e00000000010001/ 495s ● multipathd.service - Device-Mapper Multipath Device Controller 495s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 495s Active: active (running) since Sat 2024-09-14 09:44:05 UTC; 45s ago 495s Invocation: 62d2336b2e1d4ae699b07af1b86413b2 495s TriggeredBy: ○ multipathd.socket 495s Main PID: 314 (multipathd) 495s Status: "up" 495s Tasks: 7 495s Memory: 27.8M (peak: 34.2M) 495s CPU: 43ms 495s CGroup: /system.slice/multipathd.service 495s └─314 /sbin/multipathd -d -s 495s 495s Sep 14 09:44:05 autopkgtest multipathd[314]: multipathd v0.9.9: start up 495s Sep 14 09:44:05 autopkgtest multipathd[314]: reconfigure: setting up paths and maps 495s Sep 14 09:44:05 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 495s Sep 14 09:44:45 autopkgtest multipathd[314]: updated bindings file /etc/multipath/bindings 495s Sep 14 09:44:45 autopkgtest multipathd[314]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 495s Sep 14 09:44:45 autopkgtest multipathd[314]: sda [8:0]: path added to devmap mpatha 495s Sep 14 09:44:45 autopkgtest multipathd[314]: mpatha: performing delayed actions 495s Sep 14 09:44:45 autopkgtest multipathd[314]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 495s ○ multipathd.socket - multipathd control socket 495s Loaded: loaded (/usr/lib/systemd/system/multipathd.socket; static) 495s Active: inactive (dead) 495s Triggers: ● multipathd.service 495s Listen: @/org/kernel/linux/storage/multipathd (Stream) 495s total 0 495s drwxr-xr-x 2 root root 80 Sep 14 09:44 . 495s drwxr-xr-x 20 root root 4360 Sep 14 09:44 .. 495s crw------- 1 root root 10, 236 Sep 14 09:44 control 495s lrwxrwxrwx 1 root root 7 Sep 14 09:44 mpatha -> ../dm-0 495s journal 495s Sep 14 09:44:05 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 495s Sep 14 09:44:05 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 495s Sep 14 09:44:05 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 495s Sep 14 09:44:05 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 495s Sep 14 09:44:05 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 495s Sep 14 09:44:05 autopkgtest kernel: Activating Kernel Userspace Access Prevention 495s Sep 14 09:44:05 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 495s Sep 14 09:44:05 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x0000000003a00000 with 2.00 MiB pages (exec) 495s Sep 14 09:44:05 autopkgtest kernel: radix-mmu: Mapped 0x0000000003a00000-0x0000000040000000 with 2.00 MiB pages 495s Sep 14 09:44:05 autopkgtest kernel: radix-mmu: Mapped 0x0000000040000000-0x0000000200000000 with 1.00 GiB pages 495s Sep 14 09:44:05 autopkgtest kernel: lpar: Using radix MMU under hypervisor 495s Sep 14 09:44:05 autopkgtest kernel: Linux version 6.11.0-7-generic (buildd@bos02-ppc64el-027) (powerpc64le-linux-gnu-gcc-14 (Ubuntu 14.2.0-4ubuntu2) 14.2.0, GNU ld (GNU Binutils for Ubuntu) 2.43.1) #7-Ubuntu SMP Mon Sep 9 13:10:01 UTC 2024 (Ubuntu 6.11.0-7.7-generic 6.11.0-rc7) 495s Sep 14 09:44:05 autopkgtest kernel: Secure boot mode disabled 495s Sep 14 09:44:05 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc000000009442b51 495s Sep 14 09:44:05 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (architected) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 495s Sep 14 09:44:05 autopkgtest kernel: Partition configured for 4 cpus. 495s Sep 14 09:44:05 autopkgtest kernel: CPU maps initialized for 1 thread per core 495s Sep 14 09:44:05 autopkgtest kernel: (thread shift is 0) 495s Sep 14 09:44:05 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 495s Sep 14 09:44:05 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 495s Sep 14 09:44:05 autopkgtest kernel: ----------------------------------------------------- 495s Sep 14 09:44:05 autopkgtest kernel: phys_mem_size = 0x200000000 495s Sep 14 09:44:05 autopkgtest kernel: dcache_bsize = 0x80 495s Sep 14 09:44:05 autopkgtest kernel: icache_bsize = 0x80 495s Sep 14 09:44:05 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 495s Sep 14 09:44:05 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 495s Sep 14 09:44:05 autopkgtest kernel: always = 0x0000000380008181 495s Sep 14 09:44:05 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 495s Sep 14 09:44:05 autopkgtest kernel: mmu_features = 0x3c007641 495s Sep 14 09:44:05 autopkgtest kernel: firmware_features = 0x00000285455a445f 495s Sep 14 09:44:05 autopkgtest kernel: vmalloc start = 0xc008000000000000 495s Sep 14 09:44:05 autopkgtest kernel: IO start = 0xc00a000000000000 495s Sep 14 09:44:05 autopkgtest kernel: vmemmap start = 0xc00c000000000000 495s Sep 14 09:44:05 autopkgtest kernel: ----------------------------------------------------- 495s Sep 14 09:44:05 autopkgtest kernel: numa: NODE_DATA [mem 0x1fff7c280-0x1fff83fff] 495s Sep 14 09:44:05 autopkgtest kernel: rfi-flush: fallback displacement flush available 495s Sep 14 09:44:05 autopkgtest kernel: rfi-flush: ori type flush available 495s Sep 14 09:44:05 autopkgtest kernel: rfi-flush: mttrig type flush available 495s Sep 14 09:44:05 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 495s Sep 14 09:44:05 autopkgtest kernel: count-cache-flush: hardware flush enabled. 495s Sep 14 09:44:05 autopkgtest kernel: link-stack-flush: software flush enabled. 495s Sep 14 09:44:05 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 495s Sep 14 09:44:05 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 495s Sep 14 09:44:05 autopkgtest kernel: stf-barrier: eieio barrier available 495s Sep 14 09:44:05 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 495s Sep 14 09:44:05 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 495s Sep 14 09:44:05 autopkgtest kernel: PPC64 nvram contains 65536 bytes 495s Sep 14 09:44:05 autopkgtest kernel: barrier-nospec: using ORI speculation barrier 495s Sep 14 09:44:05 autopkgtest kernel: barrier-nospec: patched 275 locations 495s Sep 14 09:44:05 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 495s Sep 14 09:44:05 autopkgtest kernel: Memory hole size: 0MB 495s Sep 14 09:44:05 autopkgtest kernel: Zone ranges: 495s Sep 14 09:44:05 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 495s Sep 14 09:44:05 autopkgtest kernel: Device empty 495s Sep 14 09:44:05 autopkgtest kernel: Movable zone start for each node 495s Sep 14 09:44:05 autopkgtest kernel: Early memory node ranges 495s Sep 14 09:44:05 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 495s Sep 14 09:44:05 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 495s Sep 14 09:44:05 autopkgtest kernel: percpu: Embedded 12 pages/cpu s619032 r0 d167400 u786432 495s Sep 14 09:44:05 autopkgtest kernel: pcpu-alloc: s619032 r0 d167400 u786432 alloc=12*65536 495s Sep 14 09:44:05 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 495s Sep 14 09:44:05 autopkgtest kernel: Kernel command line: BOOT_IMAGE=/boot/vmlinux-6.11.0-7-generic root=UUID=8acaf42a-699c-4aab-9932-0a38fe5bb8c4 ro console=hvc0 earlyprintk 495s Sep 14 09:44:05 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.11.0-7-generic", will be passed to user space. 495s Sep 14 09:44:05 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 495s Sep 14 09:44:05 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 495s Sep 14 09:44:05 autopkgtest kernel: Fallback order for Node 0: 0 495s Sep 14 09:44:05 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 131072 495s Sep 14 09:44:05 autopkgtest kernel: Policy zone: Normal 495s Sep 14 09:44:05 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 495s Sep 14 09:44:05 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 495s Sep 14 09:44:05 autopkgtest kernel: ftrace: allocating 52916 entries in 20 pages 495s Sep 14 09:44:05 autopkgtest kernel: ftrace: allocated 20 pages with 2 groups 495s Sep 14 09:44:05 autopkgtest kernel: trace event string verifier disabled 495s Sep 14 09:44:05 autopkgtest kernel: rcu: Hierarchical RCU implementation. 495s Sep 14 09:44:05 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 495s Sep 14 09:44:05 autopkgtest kernel: Rude variant of Tasks RCU enabled. 495s Sep 14 09:44:05 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 495s Sep 14 09:44:05 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 495s Sep 14 09:44:05 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 495s Sep 14 09:44:05 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 495s Sep 14 09:44:05 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 495s Sep 14 09:44:05 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 495s Sep 14 09:44:05 autopkgtest kernel: xive: Using IRQ range [0-3] 495s Sep 14 09:44:05 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 495s Sep 14 09:44:05 autopkgtest kernel: xive: Using priority 6 for all interrupts 495s Sep 14 09:44:05 autopkgtest kernel: xive: Using 64kB queues 495s Sep 14 09:44:05 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 495s Sep 14 09:44:05 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 495s Sep 14 09:44:05 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 495s Sep 14 09:44:05 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 495s Sep 14 09:44:05 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 495s Sep 14 09:44:05 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 495s Sep 14 09:44:05 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 495s Sep 14 09:44:05 autopkgtest kernel: Console: colour dummy device 80x25 495s Sep 14 09:44:05 autopkgtest kernel: pid_max: default: 32768 minimum: 301 495s Sep 14 09:44:05 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,ima,evm 495s Sep 14 09:44:05 autopkgtest kernel: landlock: Up and running. 495s Sep 14 09:44:05 autopkgtest kernel: Yama: becoming mindful. 495s Sep 14 09:44:05 autopkgtest kernel: AppArmor: AppArmor initialized 495s Sep 14 09:44:05 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 495s Sep 14 09:44:05 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 495s Sep 14 09:44:05 autopkgtest kernel: POWER9 performance monitor hardware support registered 495s Sep 14 09:44:05 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 495s Sep 14 09:44:05 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 495s Sep 14 09:44:05 autopkgtest kernel: Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level 495s Sep 14 09:44:05 autopkgtest kernel: smp: Bringing up secondary CPUs ... 495s Sep 14 09:44:05 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 495s Sep 14 09:44:05 autopkgtest kernel: numa: Node 0 CPUs: 0-3 495s Sep 14 09:44:05 autopkgtest kernel: Memory: 8202112K/8388608K available (24448K kernel code, 4160K rwdata, 24704K rodata, 8768K init, 1851K bss, 157184K reserved, 0K cma-reserved) 495s Sep 14 09:44:05 autopkgtest kernel: devtmpfs: initialized 495s Sep 14 09:44:05 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 495s Sep 14 09:44:05 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 495s Sep 14 09:44:05 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 495s Sep 14 09:44:05 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 495s Sep 14 09:44:05 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 495s Sep 14 09:44:05 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 495s Sep 14 09:44:05 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 495s Sep 14 09:44:05 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 495s Sep 14 09:44:05 autopkgtest kernel: audit: initializing netlink subsys (disabled) 495s Sep 14 09:44:05 autopkgtest kernel: audit: type=2000 audit(1726307043.040:1): state=initialized audit_enabled=0 res=1 495s Sep 14 09:44:05 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 495s Sep 14 09:44:05 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 495s Sep 14 09:44:05 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 495s Sep 14 09:44:05 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 495s Sep 14 09:44:05 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 495s Sep 14 09:44:05 autopkgtest kernel: cpuidle: using governor ladder 495s Sep 14 09:44:05 autopkgtest kernel: cpuidle: using governor menu 495s Sep 14 09:44:05 autopkgtest kernel: RTAS daemon started 495s Sep 14 09:44:05 autopkgtest kernel: pstore: Using crash dump compression: deflate 495s Sep 14 09:44:05 autopkgtest kernel: pstore: Registered nvram as persistent store backend 495s Sep 14 09:44:05 autopkgtest kernel: EEH: pSeries platform initialized 495s Sep 14 09:44:05 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 495s Sep 14 09:44:05 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 495s Sep 14 09:44:05 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 495s Sep 14 09:44:05 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 495s Sep 14 09:44:05 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 495s Sep 14 09:44:05 autopkgtest kernel: iommu: Default domain type: Translated 495s Sep 14 09:44:05 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 495s Sep 14 09:44:05 autopkgtest kernel: SCSI subsystem initialized 495s Sep 14 09:44:05 autopkgtest kernel: libata version 3.00 loaded. 495s Sep 14 09:44:05 autopkgtest kernel: usbcore: registered new interface driver usbfs 495s Sep 14 09:44:05 autopkgtest kernel: usbcore: registered new interface driver hub 495s Sep 14 09:44:05 autopkgtest kernel: usbcore: registered new device driver usb 495s Sep 14 09:44:05 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 495s Sep 14 09:44:05 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 495s Sep 14 09:44:05 autopkgtest kernel: PTP clock support registered 495s Sep 14 09:44:05 autopkgtest kernel: EDAC MC: Ver: 3.0.0 495s Sep 14 09:44:05 autopkgtest kernel: NetLabel: Initializing 495s Sep 14 09:44:05 autopkgtest kernel: NetLabel: domain hash size = 128 495s Sep 14 09:44:05 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 495s Sep 14 09:44:05 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 495s Sep 14 09:44:05 autopkgtest kernel: mctp: management component transport protocol core 495s Sep 14 09:44:05 autopkgtest kernel: NET: Registered PF_MCTP protocol family 495s Sep 14 09:44:05 autopkgtest kernel: PCI: Probing PCI hardware 495s Sep 14 09:44:05 autopkgtest kernel: PCI host bridge to bus 0000:00 495s Sep 14 09:44:05 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 495s Sep 14 09:44:05 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 495s Sep 14 09:44:05 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 495s Sep 14 09:44:05 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:05.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:06.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:07.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 495s Sep 14 09:44:05 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 495s Sep 14 09:44:05 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 495s Sep 14 09:44:05 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 495s Sep 14 09:44:05 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 495s Sep 14 09:44:05 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:01.0: ibm,query-pe-dma-windows(2026) 800 8000000 20000000 returned 0, lb=80000000 ps=7 wn=1 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:05.0: Adding to iommu group 0 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:06.0: Adding to iommu group 0 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:07.0: Adding to iommu group 0 495s Sep 14 09:44:05 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 495s Sep 14 09:44:05 autopkgtest kernel: PCI: Probing PCI hardware done 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:07.0: vgaarb: setting as boot VGA device 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:07.0: vgaarb: bridge control possible 495s Sep 14 09:44:05 autopkgtest kernel: pci 0000:00:07.0: vgaarb: VGA device added: decodes=io+mem,owns=mem,locks=none 495s Sep 14 09:44:05 autopkgtest kernel: vgaarb: loaded 495s Sep 14 09:44:05 autopkgtest kernel: clocksource: Switched to clocksource timebase 495s Sep 14 09:44:05 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 495s Sep 14 09:44:05 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 495s Sep 14 09:44:05 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 495s Sep 14 09:44:05 autopkgtest kernel: NET: Registered PF_INET protocol family 495s Sep 14 09:44:05 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 495s Sep 14 09:44:05 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 495s Sep 14 09:44:05 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 495s Sep 14 09:44:05 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 495s Sep 14 09:44:05 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 495s Sep 14 09:44:05 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 495s Sep 14 09:44:05 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 495s Sep 14 09:44:05 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 495s Sep 14 09:44:05 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 495s Sep 14 09:44:05 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 495s Sep 14 09:44:05 autopkgtest kernel: NET: Registered PF_XDP protocol family 495s Sep 14 09:44:05 autopkgtest kernel: PCI: CLS 0 bytes, default 128 495s Sep 14 09:44:05 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 495s Sep 14 09:44:05 autopkgtest kernel: Initialise system trusted keyrings 495s Sep 14 09:44:05 autopkgtest kernel: Key type blacklist registered 495s Sep 14 09:44:05 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 495s Sep 14 09:44:05 autopkgtest kernel: zbud: loaded 495s Sep 14 09:44:05 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 495s Sep 14 09:44:05 autopkgtest kernel: fuse: init (API version 7.40) 495s Sep 14 09:44:05 autopkgtest kernel: integrity: Platform Keyring initialized 495s Sep 14 09:44:05 autopkgtest kernel: integrity: Machine keyring initialized 495s Sep 14 09:44:05 autopkgtest kernel: Key type asymmetric registered 495s Sep 14 09:44:05 autopkgtest kernel: Asymmetric key parser 'x509' registered 495s Sep 14 09:44:05 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 495s Sep 14 09:44:05 autopkgtest kernel: io scheduler mq-deadline registered 495s Sep 14 09:44:05 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 495s Sep 14 09:44:05 autopkgtest kernel: virtio-pci 0000:00:01.0: ibm,query-pe-dma-windows(2026) 800 8000000 20000000 returned 0, lb=80000000 ps=7 wn=1 495s Sep 14 09:44:05 autopkgtest kernel: virtio-pci 0000:00:01.0: ibm,create-pe-dma-window(2027) 800 8000000 20000000 18 21 returned 0 (liobn = 0x80000001 starting addr = 8000000 0) 495s Sep 14 09:44:05 autopkgtest kernel: virtio-pci 0000:00:03.0: enabling device (0100 -> 0103) 495s Sep 14 09:44:05 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 495s Sep 14 09:44:05 autopkgtest kernel: virtio-pci 0000:00:05.0: enabling device (0100 -> 0103) 495s Sep 14 09:44:05 autopkgtest kernel: virtio-pci 0000:00:06.0: enabling device (0100 -> 0103) 495s Sep 14 09:44:05 autopkgtest kernel: printk: legacy console [hvc0] enabled 495s Sep 14 09:44:05 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 495s Sep 14 09:44:05 autopkgtest kernel: Non-volatile memory driver v1.3 495s Sep 14 09:44:05 autopkgtest kernel: Linux agpgart interface v0.103 495s Sep 14 09:44:05 autopkgtest kernel: loop: module loaded 495s Sep 14 09:44:05 autopkgtest kernel: virtio_blk virtio2: 4/0/0 default/read/poll queues 495s Sep 14 09:44:05 autopkgtest kernel: virtio_blk virtio2: [vda] 209715200 512-byte logical blocks (107 GB/100 GiB) 495s Sep 14 09:44:05 autopkgtest kernel: vda: vda1 vda2 495s Sep 14 09:44:05 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 495s Sep 14 09:44:05 autopkgtest kernel: PPP generic driver version 2.4.2 495s Sep 14 09:44:05 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 495s Sep 14 09:44:05 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 495s Sep 14 09:44:05 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-09-14T09:44:03 UTC (1726307043) 495s Sep 14 09:44:05 autopkgtest kernel: i2c_dev: i2c /dev entries driver 495s Sep 14 09:44:05 autopkgtest kernel: Freeing initrd memory: 51456K 495s Sep 14 09:44:05 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 495s Sep 14 09:44:05 autopkgtest kernel: device-mapper: uevent: version 1.0.3 495s Sep 14 09:44:05 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@lists.linux.dev 495s Sep 14 09:44:05 autopkgtest kernel: pseries_idle_driver registered 495s Sep 14 09:44:05 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 495s Sep 14 09:44:05 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 495s Sep 14 09:44:05 autopkgtest kernel: NET: Registered PF_INET6 protocol family 495s Sep 14 09:44:05 autopkgtest kernel: Segment Routing with IPv6 495s Sep 14 09:44:05 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 495s Sep 14 09:44:05 autopkgtest kernel: NET: Registered PF_PACKET protocol family 495s Sep 14 09:44:05 autopkgtest kernel: Key type dns_resolver registered 495s Sep 14 09:44:05 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 495s Sep 14 09:44:05 autopkgtest kernel: registered taskstats version 1 495s Sep 14 09:44:05 autopkgtest kernel: Loading compiled-in X.509 certificates 495s Sep 14 09:44:05 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: 12384d98c3ac13d6e28ded7f2584c514f41d658f' 495s Sep 14 09:44:05 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 495s Sep 14 09:44:05 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 495s Sep 14 09:44:05 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 495s Sep 14 09:44:05 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 495s Sep 14 09:44:05 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 495s Sep 14 09:44:05 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 495s Sep 14 09:44:05 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 495s Sep 14 09:44:05 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 495s Sep 14 09:44:05 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 495s Sep 14 09:44:05 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 495s Sep 14 09:44:05 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 495s Sep 14 09:44:05 autopkgtest kernel: Demotion targets for Node 0: null 495s Sep 14 09:44:05 autopkgtest kernel: Key type .fscrypt registered 495s Sep 14 09:44:05 autopkgtest kernel: Key type fscrypt-provisioning registered 495s Sep 14 09:44:05 autopkgtest kernel: Key type encrypted registered 495s Sep 14 09:44:05 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 495s Sep 14 09:44:05 autopkgtest kernel: Secure boot mode disabled 495s Sep 14 09:44:05 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 495s Sep 14 09:44:05 autopkgtest kernel: Loading compiled-in module X.509 certificates 495s Sep 14 09:44:05 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: 12384d98c3ac13d6e28ded7f2584c514f41d658f' 495s Sep 14 09:44:05 autopkgtest kernel: ima: Allocated hash algorithm: sha256 495s Sep 14 09:44:05 autopkgtest kernel: Secure boot mode disabled 495s Sep 14 09:44:05 autopkgtest kernel: Trusted boot mode disabled 495s Sep 14 09:44:05 autopkgtest kernel: ima: No architecture policies found 495s Sep 14 09:44:05 autopkgtest kernel: evm: Initialising EVM extended attributes: 495s Sep 14 09:44:05 autopkgtest kernel: evm: security.selinux 495s Sep 14 09:44:05 autopkgtest kernel: evm: security.SMACK64 495s Sep 14 09:44:05 autopkgtest kernel: evm: security.SMACK64EXEC 495s Sep 14 09:44:05 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 495s Sep 14 09:44:05 autopkgtest kernel: evm: security.SMACK64MMAP 495s Sep 14 09:44:05 autopkgtest kernel: evm: security.apparmor 495s Sep 14 09:44:05 autopkgtest kernel: evm: security.ima 495s Sep 14 09:44:05 autopkgtest kernel: evm: security.capability 495s Sep 14 09:44:05 autopkgtest kernel: evm: HMAC attrs: 0x1 495s Sep 14 09:44:05 autopkgtest kernel: SED: plpks not available 495s Sep 14 09:44:05 autopkgtest kernel: clk: Disabling unused clocks 495s Sep 14 09:44:05 autopkgtest kernel: PM: genpd: Disabling unused power domains 495s Sep 14 09:44:05 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 495s Sep 14 09:44:05 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8768K 495s Sep 14 09:44:05 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 495s Sep 14 09:44:05 autopkgtest kernel: Run /init as init process 495s Sep 14 09:44:05 autopkgtest kernel: with arguments: 495s Sep 14 09:44:05 autopkgtest kernel: /init 495s Sep 14 09:44:05 autopkgtest kernel: earlyprintk 495s Sep 14 09:44:05 autopkgtest kernel: with environment: 495s Sep 14 09:44:05 autopkgtest kernel: HOME=/ 495s Sep 14 09:44:05 autopkgtest kernel: TERM=linux 495s Sep 14 09:44:05 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.11.0-7-generic 495s Sep 14 09:44:05 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 495s Sep 14 09:44:05 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 495s Sep 14 09:44:05 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 1 495s Sep 14 09:44:05 autopkgtest kernel: xhci_hcd 0000:00:02.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010 495s Sep 14 09:44:05 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 495s Sep 14 09:44:05 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2 495s Sep 14 09:44:05 autopkgtest kernel: xhci_hcd 0000:00:02.0: Host supports USB 3.0 SuperSpeed 495s Sep 14 09:44:05 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.11 495s Sep 14 09:44:05 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 495s Sep 14 09:44:05 autopkgtest kernel: usb usb1: Product: xHCI Host Controller 495s Sep 14 09:44:05 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.11.0-7-generic xhci-hcd 495s Sep 14 09:44:05 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:02.0 495s Sep 14 09:44:05 autopkgtest kernel: hub 1-0:1.0: USB hub found 495s Sep 14 09:44:05 autopkgtest kernel: hub 1-0:1.0: 4 ports detected 495s Sep 14 09:44:05 autopkgtest kernel: usb usb2: We don't know the algorithms for LPM for this host, disabling LPM. 495s Sep 14 09:44:05 autopkgtest kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.11 495s Sep 14 09:44:05 autopkgtest kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 495s Sep 14 09:44:05 autopkgtest kernel: usb usb2: Product: xHCI Host Controller 495s Sep 14 09:44:05 autopkgtest kernel: usb usb2: Manufacturer: Linux 6.11.0-7-generic xhci-hcd 495s Sep 14 09:44:05 autopkgtest kernel: usb usb2: SerialNumber: 0000:00:02.0 495s Sep 14 09:44:05 autopkgtest kernel: hub 2-0:1.0: USB hub found 495s Sep 14 09:44:05 autopkgtest kernel: hub 2-0:1.0: 4 ports detected 495s Sep 14 09:44:05 autopkgtest kernel: random: crng init done 495s Sep 14 09:44:05 autopkgtest kernel: [drm] Found bochs VGA, ID 0xb0c5. 495s Sep 14 09:44:05 autopkgtest kernel: [drm] Framebuffer size 16384 kB @ 0x200081000000, mmio @ 0x200082000000. 495s Sep 14 09:44:05 autopkgtest kernel: [drm] Found EDID data blob. 495s Sep 14 09:44:05 autopkgtest kernel: [drm] Initialized bochs-drm 1.0.0 for 0000:00:07.0 on minor 0 495s Sep 14 09:44:05 autopkgtest kernel: fbcon: Deferring console take-over 495s Sep 14 09:44:05 autopkgtest kernel: bochs-drm 0000:00:07.0: [drm] fb0: bochs-drmdrmfb frame buffer device 495s Sep 14 09:44:05 autopkgtest kernel: raid6: vpermxor8 gen() 20027 MB/s 495s Sep 14 09:44:05 autopkgtest kernel: raid6: vpermxor4 gen() 19570 MB/s 495s Sep 14 09:44:05 autopkgtest kernel: usb 1-1: new high-speed USB device number 2 using xhci_hcd 495s Sep 14 09:44:05 autopkgtest kernel: raid6: vpermxor2 gen() 15451 MB/s 495s Sep 14 09:44:05 autopkgtest kernel: raid6: vpermxor1 gen() 13189 MB/s 495s Sep 14 09:44:05 autopkgtest kernel: usb 1-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 495s Sep 14 09:44:05 autopkgtest kernel: usb 1-1: New USB device strings: Mfr=1, Product=4, SerialNumber=11 495s Sep 14 09:44:05 autopkgtest kernel: usb 1-1: Product: QEMU USB Keyboard 495s Sep 14 09:44:05 autopkgtest kernel: usb 1-1: Manufacturer: QEMU 495s Sep 14 09:44:05 autopkgtest kernel: usb 1-1: SerialNumber: 68284-pci@800000020000000:02.0-1 495s Sep 14 09:44:05 autopkgtest kernel: hid: raw HID events driver (C) Jiri Kosina 495s Sep 14 09:44:05 autopkgtest kernel: usbcore: registered new interface driver usbhid 495s Sep 14 09:44:05 autopkgtest kernel: usbhid: USB HID core driver 495s Sep 14 09:44:05 autopkgtest kernel: input: QEMU QEMU USB Keyboard as /devices/pci0000:00/0000:00:02.0/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input0 495s Sep 14 09:44:05 autopkgtest kernel: raid6: altivecx8 gen() 13646 MB/s 495s Sep 14 09:44:05 autopkgtest kernel: hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v1.11 Keyboard [QEMU QEMU USB Keyboard] on usb-0000:00:02.0-1/input0 495s Sep 14 09:44:05 autopkgtest kernel: raid6: altivecx4 gen() 13681 MB/s 495s Sep 14 09:44:05 autopkgtest kernel: usb 1-2: new high-speed USB device number 3 using xhci_hcd 495s Sep 14 09:44:05 autopkgtest kernel: raid6: altivecx2 gen() 11109 MB/s 495s Sep 14 09:44:05 autopkgtest kernel: raid6: altivecx1 gen() 8326 MB/s 495s Sep 14 09:44:05 autopkgtest kernel: usb 1-2: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 495s Sep 14 09:44:05 autopkgtest kernel: usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=9 495s Sep 14 09:44:05 autopkgtest kernel: usb 1-2: Product: QEMU USB Mouse 495s Sep 14 09:44:05 autopkgtest kernel: usb 1-2: Manufacturer: QEMU 495s Sep 14 09:44:05 autopkgtest kernel: usb 1-2: SerialNumber: 89126-pci@800000020000000:02.0-2 495s Sep 14 09:44:05 autopkgtest kernel: input: QEMU QEMU USB Mouse as /devices/pci0000:00/0000:00:02.0/usb1/1-2/1-2:1.0/0003:0627:0001.0002/input/input1 495s Sep 14 09:44:05 autopkgtest kernel: hid-generic 0003:0627:0001.0002: input,hidraw1: USB HID v0.01 Mouse [QEMU QEMU USB Mouse] on usb-0000:00:02.0-2/input0 495s Sep 14 09:44:05 autopkgtest kernel: raid6: int64x8 gen() 6855 MB/s 495s Sep 14 09:44:05 autopkgtest kernel: raid6: int64x4 gen() 8103 MB/s 495s Sep 14 09:44:05 autopkgtest kernel: raid6: int64x2 gen() 6410 MB/s 495s Sep 14 09:44:05 autopkgtest kernel: raid6: int64x1 gen() 4998 MB/s 495s Sep 14 09:44:05 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 20027 MB/s 495s Sep 14 09:44:05 autopkgtest kernel: raid6: using intx1 recovery algorithm 495s Sep 14 09:44:05 autopkgtest kernel: xor: measuring software checksum speed 495s Sep 14 09:44:05 autopkgtest kernel: 8regs : 17330 MB/sec 495s Sep 14 09:44:05 autopkgtest kernel: 8regs_prefetch : 15601 MB/sec 495s Sep 14 09:44:05 autopkgtest kernel: 32regs : 17336 MB/sec 495s Sep 14 09:44:05 autopkgtest kernel: 32regs_prefetch : 15547 MB/sec 495s Sep 14 09:44:05 autopkgtest kernel: altivec : 19351 MB/sec 495s Sep 14 09:44:05 autopkgtest kernel: xor: using function: altivec (19351 MB/sec) 495s Sep 14 09:44:05 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 495s Sep 14 09:44:05 autopkgtest kernel: EXT4-fs (vda1): orphan cleanup on readonly fs 495s Sep 14 09:44:05 autopkgtest kernel: EXT4-fs (vda1): mounted filesystem 8acaf42a-699c-4aab-9932-0a38fe5bb8c4 ro with ordered data mode. Quota mode: none. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Inserted module 'autofs4' 495s Sep 14 09:44:05 autopkgtest systemd[1]: systemd 256.5-2ubuntu2 running in system mode (+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -XKBCOMMON +UTMP +SYSVINIT +LIBARCHIVE) 495s Sep 14 09:44:05 autopkgtest systemd[1]: Detected virtualization kvm. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Detected architecture ppc64-le. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Hostname set to . 495s Sep 14 09:44:05 autopkgtest systemd[1]: bpf-restrict-fs: BPF LSM hook not enabled in the kernel, BPF LSM not supported. 495s Sep 14 09:44:05 autopkgtest kernel: NET: Registered PF_VSOCK protocol family 495s Sep 14 09:44:05 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Queued start job for default target graphical.target. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Reached target swap.target - Swaps. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 495s Sep 14 09:44:05 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Sockets. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounting run-lock.mount - Legacy Locks Directory /run/lock... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting modprobe@dm_multipath.service - Load Kernel Module dm_multipath... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 495s Sep 14 09:44:05 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 495s Sep 14 09:44:05 autopkgtest systemd[1]: systemd-fsck-root.service - File System Check on Root Device was skipped because of an unmet condition check (ConditionPathExists=!/run/initramfs/fsck-root). 495s Sep 14 09:44:05 autopkgtest systemd[1]: systemd-hibernate-clear.service - Clear Stale Hibernate Storage Info was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67). 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounted run-lock.mount - Legacy Locks Directory /run/lock. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 495s Sep 14 09:44:05 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 495s Sep 14 09:44:05 autopkgtest systemd[1]: modprobe@dm_multipath.service: Deactivated successfully. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished modprobe@dm_multipath.service - Load Kernel Module dm_multipath. 495s Sep 14 09:44:05 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 495s Sep 14 09:44:05 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 495s Sep 14 09:44:05 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 495s Sep 14 09:44:05 autopkgtest kernel: EXT4-fs (vda1): re-mounted 8acaf42a-699c-4aab-9932-0a38fe5bb8c4 r/w. Quota mode: none. 495s Sep 14 09:44:05 autopkgtest systemd-journald[284]: Collecting audit messages is disabled. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting cloud-init-main.service - Cloud-init: Single Process... 495s Sep 14 09:44:05 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 495s Sep 14 09:44:05 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 495s Sep 14 09:44:05 autopkgtest systemd-journald[284]: Journal started 495s Sep 14 09:44:05 autopkgtest systemd-journald[284]: Runtime Journal (/run/log/journal/a2415cfb48a9486bb36babfbfaab0895) is 8M, max 81M, 73M free. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 495s Sep 14 09:44:05 autopkgtest multipathd[314]: multipathd v0.9.9: start up 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 495s Sep 14 09:44:05 autopkgtest multipathd[314]: reconfigure: setting up paths and maps 495s Sep 14 09:44:05 autopkgtest systemd-journald[284]: Time spent on flushing to /var/log/journal/a2415cfb48a9486bb36babfbfaab0895 is 39.190ms for 464 entries. 495s Sep 14 09:44:05 autopkgtest systemd-journald[284]: System Journal (/var/log/journal/a2415cfb48a9486bb36babfbfaab0895) is 18.9M, max 4G, 3.9G free. 495s Sep 14 09:44:05 autopkgtest systemd-journald[284]: Received client request to flush runtime journal. 495s Sep 14 09:44:05 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 495s Sep 14 09:44:05 autopkgtest apparmor.systemd[350]: Restarting AppArmor 495s Sep 14 09:44:05 autopkgtest apparmor.systemd[350]: Reloading AppArmor profiles 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 495s Sep 14 09:44:05 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 495s Sep 14 09:44:05 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 353 (systemd-binfmt) 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... 495s Sep 14 09:44:05 autopkgtest systemd-tmpfiles[369]: /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. 495s Sep 14 09:44:05 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 495s Sep 14 09:44:05 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 495s Sep 14 09:44:05 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 495s Sep 14 09:44:05 autopkgtest systemd[1]: systemd-machine-id-commit.service - Save Transient machine-id to Disk was skipped because of an unmet condition check (ConditionPathIsMountPoint=/etc/machine-id). 495s Sep 14 09:44:05 autopkgtest kernel: audit: type=1400 audit(1726307045.524:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=378 comm="apparmor_parser" 495s Sep 14 09:44:05 autopkgtest kernel: audit: type=1400 audit(1726307045.524:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=377 comm="apparmor_parser" 495s Sep 14 09:44:05 autopkgtest kernel: audit: type=1400 audit(1726307045.524:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=379 comm="apparmor_parser" 495s Sep 14 09:44:05 autopkgtest kernel: audit: type=1400 audit(1726307045.524:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=376 comm="apparmor_parser" 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 495s Sep 14 09:44:05 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 495s Sep 14 09:44:05 autopkgtest kernel: audit: type=1400 audit(1726307045.532:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=385 comm="apparmor_parser" 495s Sep 14 09:44:05 autopkgtest kernel: audit: type=1400 audit(1726307045.532:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=384 comm="apparmor_parser" 495s Sep 14 09:44:05 autopkgtest kernel: audit: type=1400 audit(1726307045.532:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=386 comm="apparmor_parser" 495s Sep 14 09:44:05 autopkgtest kernel: audit: type=1400 audit(1726307045.536:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="cam" pid=389 comm="apparmor_parser" 495s Sep 14 09:44:05 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 495s Sep 14 09:44:05 autopkgtest systemd-udevd[355]: Using default interface naming scheme 'v255'. 495s Sep 14 09:44:05 autopkgtest kernel: audit: type=1400 audit(1726307045.536:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="busybox" pid=388 comm="apparmor_parser" 495s Sep 14 09:44:05 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 495s Sep 14 09:44:05 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 495s Sep 14 09:44:05 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 495s Sep 14 09:44:05 autopkgtest systemd[1]: systemd-ask-password-plymouth.path - Forward Password Requests to Plymouth Directory Watch was skipped because of an unmet condition check (ConditionPathExists=/run/plymouth/pid). 495s Sep 14 09:44:05 autopkgtest systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. 495s Sep 14 09:44:05 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 495s Sep 14 09:44:05 autopkgtest (udev-worker)[446]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 495s Sep 14 09:44:05 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 495s Sep 14 09:44:06 autopkgtest systemd[1]: Started cloud-init-main.service - Cloud-init: Single Process. 495s Sep 14 09:44:06 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 495s Sep 14 09:44:06 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 495s Sep 14 09:44:06 autopkgtest cloud-init[682]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 running 'init-local' at Sat, 14 Sep 2024 09:44:06 +0000. Up 3.00 seconds. 495s Sep 14 09:44:06 autopkgtest dhcpcd[686]: dhcpcd-10.0.8 starting 495s Sep 14 09:44:06 autopkgtest dhcpcd[689]: DUID 00:01:00:01:2e:77:32:31:fa:16:3e:4b:a8:00 495s Sep 14 09:44:06 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 495s Sep 14 09:44:06 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 495s Sep 14 09:44:06 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 495s Sep 14 09:44:06 autopkgtest dhcpcd[689]: enp0s1: IAID 3e:f6:45:db 495s Sep 14 09:44:06 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 495s Sep 14 09:44:06 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 495s Sep 14 09:44:06 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 495s Sep 14 09:44:06 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 495s Sep 14 09:44:06 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 495s Sep 14 09:44:06 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 495s Sep 14 09:44:06 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 495s Sep 14 09:44:06 autopkgtest systemd-resolved[381]: Positive Trust Anchors: 495s Sep 14 09:44:06 autopkgtest systemd-resolved[381]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 495s Sep 14 09:44:06 autopkgtest systemd-resolved[381]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 170.0.0.192.in-addr.arpa 171.0.0.192.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa ipv4only.arpa resolver.arpa corp home internal intranet lan local private test 495s Sep 14 09:44:06 autopkgtest systemd-resolved[381]: Using system hostname 'autopkgtest'. 495s Sep 14 09:44:06 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 495s Sep 14 09:44:06 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 495s Sep 14 09:44:07 autopkgtest dhcpcd[689]: enp0s1: rebinding lease of 10.145.227.63 495s Sep 14 09:44:07 autopkgtest dhcpcd[689]: enp0s1: leased 10.145.227.63 for 43200 seconds 495s Sep 14 09:44:07 autopkgtest dhcpcd[689]: enp0s1: adding route to 10.145.227.0/24 495s Sep 14 09:44:07 autopkgtest dhcpcd[689]: enp0s1: adding host route to 169.254.169.254 via 10.145.227.2 495s Sep 14 09:44:07 autopkgtest dhcpcd[689]: enp0s1: adding default route via 10.145.227.1 495s Sep 14 09:44:07 autopkgtest dhcpcd[689]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 495s Sep 14 09:44:14 autopkgtest sh[678]: Completed socket interaction for boot stage local 495s Sep 14 09:44:14 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 495s Sep 14 09:44:14 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 495s Sep 14 09:44:14 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 495s Sep 14 09:44:14 autopkgtest systemd-networkd[723]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 495s Sep 14 09:44:14 autopkgtest systemd-networkd[723]: lo: Link UP 495s Sep 14 09:44:14 autopkgtest systemd-networkd[723]: lo: Gained carrier 495s Sep 14 09:44:14 autopkgtest systemd-networkd[723]: Enumeration completed 495s Sep 14 09:44:14 autopkgtest systemd-networkd[723]: enp0s1: Link UP 495s Sep 14 09:44:14 autopkgtest systemd-networkd[723]: enp0s1: Gained carrier 495s Sep 14 09:44:14 autopkgtest systemd-networkd[723]: enp0s1: Gained IPv6LL 495s Sep 14 09:44:14 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 495s Sep 14 09:44:14 autopkgtest systemd-networkd[723]: enp0s1: Link DOWN 495s Sep 14 09:44:14 autopkgtest systemd-networkd[723]: enp0s1: Lost carrier 495s Sep 14 09:44:14 autopkgtest systemd[1]: Reached target network.target - Network. 495s Sep 14 09:44:14 autopkgtest systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... 495s Sep 14 09:44:14 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 495s Sep 14 09:44:14 autopkgtest systemd-networkd[723]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 495s Sep 14 09:44:14 autopkgtest systemd-networkd[723]: enp0s1: Link UP 495s Sep 14 09:44:14 autopkgtest systemd-networkd[723]: enp0s1: Gained carrier 495s Sep 14 09:44:14 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 495s Sep 14 09:44:14 autopkgtest systemd-networkd[723]: enp0s1: DHCPv4 address 10.145.227.63/24, gateway 10.145.227.1 acquired from 10.145.227.1 495s Sep 14 09:44:14 autopkgtest systemd-timesyncd[382]: Network configuration changed, trying to establish connection. 495s Sep 14 09:44:14 autopkgtest systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. 495s Sep 14 09:44:15 autopkgtest systemd-networkd[723]: enp0s1: Gained IPv6LL 495s Sep 14 09:44:15 autopkgtest systemd-timesyncd[382]: Network configuration changed, trying to establish connection. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting cloud-init-network.service - Cloud-init: Network Stage... 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 running 'init' at Sat, 14 Sep 2024 09:44:16 +0000. Up 12.89 seconds. 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | enp0s1 | True | 10.145.227.63 | 255.255.255.0 | global | fa:16:3e:f6:45:db | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | enp0s1 | True | fe80::f816:3eff:fef6:45db/64 | . | link | fa:16:3e:f6:45:db | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | lo | True | ::1/128 | . | host | . | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++++ 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | 0 | 0.0.0.0 | 10.145.227.1 | 0.0.0.0 | enp0s1 | UG | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | 1 | 10.145.227.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | 2 | 10.145.227.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | 3 | 10.145.227.2 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | 4 | 91.189.91.131 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | 5 | 91.189.91.132 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | 6 | 169.254.169.254 | 10.145.227.2 | 255.255.255.255 | enp0s1 | UGH | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: +-------+-------------+---------+-----------+-------+ 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | Route | Destination | Gateway | Interface | Flags | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: +-------+-------------+---------+-----------+-------+ 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | 2 | local | :: | enp0s1 | U | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: | 3 | multicast | :: | enp0s1 | U | 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: ci-info: +-------+-------------+---------+-----------+-------+ 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: 2024-09-14 09:44:16,149 - log.py[DEPRECATED]: Deprecated cloud-config provided: apt_update: Deprecated in version 22.2. Use **package_update** instead., apt_upgrade: Deprecated in version 22.2. Use **package_upgrade** instead. 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: 2024-09-14 09:44:16,149 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 495s Sep 14 09:44:16 autopkgtest sh[735]: Completed socket interaction for boot stage network 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished cloud-init-network.service - Cloud-init: Network Stage. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 495s Sep 14 09:44:16 autopkgtest systemd[1]: apport-autoreport.path - Process error reports when automatic reporting is enabled (file watch) was skipped because of an unmet condition check (ConditionPathExists=/var/lib/apport/autoreport). 495s Sep 14 09:44:16 autopkgtest systemd[1]: apport-autoreport.timer - Process error reports when automatic reporting is enabled (timer based) was skipped because of an unmet condition check (ConditionPathExists=/var/lib/apport/autoreport). 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started sysstat-collect.timer - Run system activity accounting tool every 10 minutes. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started sysstat-rotate.timer - Rotate daily system activity data file at midnight. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started sysstat-summary.timer - Generate summary of yesterday's process accounting. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 495s Sep 14 09:44:16 autopkgtest systemd[1]: ua-timer.timer - Ubuntu Pro Timer for running repeated jobs was skipped because of an unmet condition check (ConditionPathExists=/var/lib/ubuntu-advantage/private/machine-token.json). 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target paths.target - Path Units. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 495s Sep 14 09:44:16 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 495s Sep 14 09:44:16 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). 495s Sep 14 09:44:16 autopkgtest systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target ssh-access.target - SSH Access Available. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target basic.target + echo Test WWN should now point to DM 495s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 495s + grep dm 495s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 495s mke2fs 1.47.1 (20-May-2024) 495s + udevadm settle 495s + sleep 3s 495s - Basic System. 495s Sep 14 09:44:16 autopkgtest systemd[1]: System is tainted: unmerged-bin 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 495s Sep 14 09:44:16 autopkgtest (sh)[770]: autopkgtest@hvc1.service: Failed to set up standard input: No such device 495s Sep 14 09:44:16 autopkgtest (sh)[770]: autopkgtest@hvc1.service: Failed at step STDIN spawning /bin/sh: No such device 495s Sep 14 09:44:16 autopkgtest (sh)[771]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 495s Sep 14 09:44:16 autopkgtest (sh)[771]: autopkgtest@ttyS1.service: Failed at step STDIN spawning /bin/sh: Input/output error 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 495s Sep 14 09:44:16 autopkgtest (cron)[773]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 495s Sep 14 09:44:16 autopkgtest systemd[1]: getty-static.service - getty on tty2-tty6 if dbus and logind are not available was skipped because of an unmet condition check (ConditionPathExists=!/usr/bin/dbus-daemon). 495s Sep 14 09:44:16 autopkgtest cron[773]: (CRON) INFO (pidfile fd = 3) 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 495s Sep 14 09:44:16 autopkgtest cron[773]: (CRON) INFO (Running @reboot jobs) 495s Sep 14 09:44:16 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 495s Sep 14 09:44:16 autopkgtest systemd[1]: opal_errd.service - opal_errd (PowerNV platform error handling) Service was skipped because of an unmet condition check (ConditionVirtualization=false). 495s Sep 14 09:44:16 autopkgtest systemd[1]: pollinate.service - Pollinate to seed the pseudo random number generator was skipped because of an unmet condition check (ConditionPathExists=!/var/cache/pollinate/seeded). 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting sysstat.service - Resets System Activity Logs... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 495s Sep 14 09:44:16 autopkgtest systemd[1]: ua-reboot-cmds.service - Ubuntu Pro reboot cmds was skipped because of an unmet condition check (ConditionPathExists=/var/lib/ubuntu-advantage/private/machine-token.json). 495s Sep 14 09:44:16 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 495s Sep 14 09:44:16 autopkgtest dbus-daemon[777]: [system] AppArmor D-Bus mediation is enabled 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 495s Sep 14 09:44:16 autopkgtest systemd[1]: autopkgtest@hvc1.service: Deactivated successfully. 495s Sep 14 09:44:16 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 495s Sep 14 09:44:16 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished sysstat.service - Resets System Activity Logs. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 495s Sep 14 09:44:16 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 495s Sep 14 09:44:16 autopkgtest udisksd[794]: udisks daemon version 2.10.1 starting 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 495s Sep 14 09:44:16 autopkgtest rngd[851]: rngd 2.4 starting up... 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 running 'modules:config' at Sat, 14 Sep 2024 09:44:16 +0000. Up 13.20 seconds. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 495s Sep 14 09:44:16 autopkgtest rngd[851]: entropy feed to the kernel ready 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 495s Sep 14 09:44:16 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 495s Sep 14 09:44:16 autopkgtest systemd-logind[790]: New seat seat0. 495s Sep 14 09:44:16 autopkgtest systemd-logind[790]: Watching system buttons on /dev/input/event0 (QEMU QEMU USB Keyboard) 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 495s Sep 14 09:44:16 autopkgtest kernel: kauditd_printk_skb: 110 callbacks suppressed 495s Sep 14 09:44:16 autopkgtest kernel: audit: type=1400 audit(1726307056.484:121): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=849 comm="apparmor_parser" 495s Sep 14 09:44:16 autopkgtest sh[776]: Completed socket interaction for boot stage config 495s Sep 14 09:44:16 autopkgtest udisksd[794]: Acquired the name org.freedesktop.UDisks2 on the system message bus 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 495s Sep 14 09:44:16 autopkgtest rsyslogd[879]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2406.0] 495s Sep 14 09:44:16 autopkgtest rsyslogd[879]: rsyslogd's groupid changed to 102 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 495s Sep 14 09:44:16 autopkgtest rsyslogd[879]: rsyslogd's userid changed to 102 495s Sep 14 09:44:16 autopkgtest rsyslogd[879]: [origin software="rsyslogd" swVersion="8.2406.0" x-pid="879" x-info="https://www.rsyslog.com"] start 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 495s Sep 14 09:44:16 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 running 'modules:final' at Sat, 14 Sep 2024 09:44:16 +0000. Up 13.47 seconds. 495s Sep 14 09:44:16 autopkgtest cloud-init[682]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 finished at Sat, 14 Sep 2024 09:44:16 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 13.54 seconds 495s Sep 14 09:44:16 autopkgtest sh[890]: Completed socket interaction for boot stage final 495s Sep 14 09:44:16 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Startup finished in 1.760s (kernel) + 11.803s (userspace) = 13.564s. 495s Sep 14 09:44:16 autopkgtest kernel: fbcon: Taking over console 495s Sep 14 09:44:16 autopkgtest kernel: Console: switching to colour frame buffer device 128x48 495s Sep 14 09:44:16 autopkgtest systemd[1]: cloud-init-main.service: Deactivated successfully. 495s Sep 14 09:44:16 autopkgtest systemd[1]: cloud-init-main.service: Consumed 996ms CPU time, 107.8M memory peak. 495s Sep 14 09:44:16 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 495s Sep 14 09:44:16 autopkgtest sshd[941]: Server listening on :: port 22. 495s Sep 14 09:44:16 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 495s Sep 14 09:44:17 autopkgtest sshd[942]: Accepted publickey for ubuntu from 10.136.6.184 port 46596 ssh2: RSA SHA256:h+sR5tlNZDfTFbz7cAH7wlRKfPAD8MpCdKJaoGeL2vg 495s Sep 14 09:44:17 autopkgtest sshd[942]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 495s Sep 14 09:44:17 autopkgtest sshd[942]: pam_systemd(sshd:session): New sd-bus connection (system-bus-pam-systemd-942) opened. 495s Sep 14 09:44:17 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 495s Sep 14 09:44:17 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 495s Sep 14 09:44:17 autopkgtest systemd-logind[790]: New session 1 of user ubuntu. 495s Sep 14 09:44:17 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 495s Sep 14 09:44:17 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 495s Sep 14 09:44:17 autopkgtest (systemd)[946]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 495s Sep 14 09:44:17 autopkgtest systemd-logind[790]: New session 2 of user ubuntu. 495s Sep 14 09:44:17 autopkgtest systemd[946]: Queued start job for default target default.target. 495s Sep 14 09:44:17 autopkgtest systemd[946]: Created slice app.slice - User Application Slice. 495s Sep 14 09:44:17 autopkgtest systemd[946]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 495s Sep 14 09:44:17 autopkgtest systemd[946]: Reached target paths.target - Paths. 495s Sep 14 09:44:17 autopkgtest systemd[946]: Reached target timers.target - Timers. 495s Sep 14 09:44:17 autopkgtest systemd[946]: Starting dbus.socket - D-Bus User Message Bus Socket... 495s Sep 14 09:44:17 autopkgtest systemd[946]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 495s Sep 14 09:44:17 autopkgtest systemd[946]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 495s Sep 14 09:44:17 autopkgtest systemd[946]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 495s Sep 14 09:44:17 autopkgtest systemd[946]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 495s Sep 14 09:44:17 autopkgtest systemd[946]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 495s Sep 14 09:44:17 autopkgtest systemd[946]: Listening on keyboxd.socket - GnuPG public key management service. 495s Sep 14 09:44:17 autopkgtest systemd[946]: Listening on dbus.socket - D-Bus User Message Bus Socket. 495s Sep 14 09:44:17 autopkgtest systemd[946]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 495s Sep 14 09:44:17 autopkgtest systemd[946]: Reached target sockets.target - Sockets. 495s Sep 14 09:44:17 autopkgtest systemd[946]: Reached target basic.target - Basic System. 495s Sep 14 09:44:17 autopkgtest systemd[946]: Reached target default.target - Main User Target. 495s Sep 14 09:44:17 autopkgtest systemd[946]: Startup finished in 129ms. 495s Sep 14 09:44:17 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 495s Sep 14 09:44:17 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 495s Sep 14 09:44:18 autopkgtest sudo[974]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 495s Sep 14 09:44:18 autopkgtest sudo[974]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:18 autopkgtest sudo[974]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:18 autopkgtest sudo[979]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper /bin/sh -ec 'for d in /var/cache /home; do if [ -e $d/autopkgtest-tmpdir.tar ]; then /bin/tar --warning=none --extract --absolute-names -f $d/autopkgtest-tmpdir.tar; /bin/rm $d/autopkgtest-tmpdir.tar; exit 0; fi; done; exit 1' 495s Sep 14 09:44:18 autopkgtest sudo[979]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:18 autopkgtest sudo[979]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:18 autopkgtest sudo[991]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.0w3jVJ 495s Sep 14 09:44:18 autopkgtest sudo[991]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:18 autopkgtest sudo[991]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:18 autopkgtest sudo[1001]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.0w3jVJ/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot' 495s Sep 14 09:44:18 autopkgtest sudo[1001]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:18 autopkgtest sudo[1001]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:19 autopkgtest sudo[1013]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot 495s Sep 14 09:44:19 autopkgtest sudo[1013]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:19 autopkgtest sudo[1013]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:19 autopkgtest sudo[1023]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot /tmp/autopkgtest-reboot 495s Sep 14 09:44:19 autopkgtest sudo[1023]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:19 autopkgtest sudo[1023]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:19 autopkgtest sudo[1033]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot /sbin/autopkgtest-reboot 495s Sep 14 09:44:19 autopkgtest sudo[1033]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:19 autopkgtest sudo[1033]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:19 autopkgtest sudo[1043]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.0w3jVJ 495s Sep 14 09:44:19 autopkgtest sudo[1043]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:19 autopkgtest sudo[1043]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:19 autopkgtest sudo[1053]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.0w3jVJ/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot-prepare' 495s Sep 14 09:44:19 autopkgtest sudo[1053]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:19 autopkgtest sudo[1053]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:19 autopkgtest sudo[1065]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot-prepare 495s Sep 14 09:44:19 autopkgtest sudo[1065]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:19 autopkgtest sudo[1065]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:20 autopkgtest sudo[1075]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 495s Sep 14 09:44:20 autopkgtest sudo[1075]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:20 autopkgtest sudo[1075]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:20 autopkgtest sudo[1085]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 495s Sep 14 09:44:20 autopkgtest sudo[1085]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:20 autopkgtest sudo[1085]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:20 autopkgtest sudo[1095]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 495s Sep 14 09:44:20 autopkgtest sudo[1095]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:20 autopkgtest sudo[1095]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:20 autopkgtest sudo[1105]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.0w3jVJ/testbed-packages' 495s Sep 14 09:44:20 autopkgtest sudo[1105]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:20 autopkgtest sudo[1105]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:20 autopkgtest sudo[1116]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot' 495s Sep 14 09:44:21 autopkgtest sudo[1137]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:21 autopkgtest sudo[1137]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:21 autopkgtest sudo[1149]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot 495s Sep 14 09:44:21 autopkgtest sudo[1149]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:21 autopkgtest sudo[1149]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:21 autopkgtest sudo[1160]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot /tmp/autopkgtest-reboot 495s Sep 14 09:44:21 autopkgtest sudo[1160]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:21 autopkgtest sudo[1160]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:21 autopkgtest sudo[1170]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot /sbin/autopkgtest-reboot 495s Sep 14 09:44:21 autopkgtest sudo[1170]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:21 autopkgtest sudo[1170]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:22 autopkgtest sudo[1180]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.0w3jVJ 495s Sep 14 09:44:22 autopkgtest sudo[1180]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:22 autopkgtest sudo[1180]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:22 autopkgtest sudo[1190]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.0w3jVJ/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot-prepare' 495s Sep 14 09:44:22 autopkgtest sudo[1190]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:22 autopkgtest sudo[1190]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:22 autopkgtest sudo[1202]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot-prepare 495s Sep 14 09:44:22 autopkgtest sudo[1202]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:22 autopkgtest sudo[1202]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:22 autopkgtest sudo[1212]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.0w3jVJ/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 495s Sep 14 09:44:22 autopkgtest sudo[1212]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:22 autopkgtest sudo[1212]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:22 autopkgtest sudo[1222]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 495s Sep 14 09:44:22 autopkgtest sudo[1222]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:22 autopkgtest sudo[1222]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:23 autopkgtest sudo[1232]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 495s Sep 14 09:44:23 autopkgtest sudo[1232]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:23 autopkgtest sudo[1232]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:23 autopkgtest sudo[1241]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.0w3jVJ 495s Sep 14 09:44:23 autopkgtest sudo[1241]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:23 autopkgtest sudo[1241]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:23 autopkgtest sudo[1251]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.0w3jVJ/2-autopkgtest-satdep.deb' 495s Sep 14 09:44:23 autopkgtest sudo[1251]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:23 autopkgtest sudo[1251]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:23 autopkgtest sudo[1262]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.0w3jVJ/2-autopkgtest-satdep.deb 495s Sep 14 09:44:23 autopkgtest sudo[1262]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:23 autopkgtest sudo[1262]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:23 autopkgtest sudo[1272]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper env DEBIAN_FRONTEND=noninteractive APT_LISTBUGS_FRONTEND=none APT_LISTCHANGES_FRONTEND=none /bin/sh -ec '/usr/bin/eatmydata apt-get install --assume-yes /tmp/autopkgtest.0w3jVJ/2-autopkgtest-satdep.deb -o APT::Status-Fd=3 -o APT::Install-Recommends=false -o Dpkg::Options::=--force-confnew -o Debug::pkgProblemResolver=true 3>&2 2>&1' 495s Sep 14 09:44:23 autopkgtest sudo[1272]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:27 autopkgtest systemd[1]: Reload requested from client PID 1512 ('systemctl') (unit session-1.scope)... 495s Sep 14 09:44:27 autopkgtest systemd[1]: Reloading... 495s Sep 14 09:44:27 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:27 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:27 autopkgtest systemd[1]: Reloading finished in 191 ms. 495s Sep 14 09:44:27 autopkgtest systemd[1]: Reload requested from client PID 1561 ('systemctl') (unit session-1.scope)... 495s Sep 14 09:44:27 autopkgtest systemd[1]: Reloading... 495s Sep 14 09:44:28 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:28 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:28 autopkgtest systemd[1]: Reloading finished in 201 ms. 495s Sep 14 09:44:28 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 495s Sep 14 09:44:28 autopkgtest tgtd[1606]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 495s Sep 14 09:44:28 autopkgtest tgtd[1606]: tgtd: work_timer_start(146) use timer_fd based scheduler 495s Sep 14 09:44:28 autopkgtest tgtd[1606]: tgtd: bs_init(387) use signalfd notification 495s Sep 14 09:44:28 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 495s Sep 14 09:44:28 autopkgtest systemd[1]: Reload requested from client PID 1634 ('systemctl') (unit session-1.scope)... 495s Sep 14 09:44:28 autopkgtest systemd[1]: Reloading... 495s Sep 14 09:44:28 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:28 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:28 autopkgtest systemd[1]: Reloading finished in 208 ms. 495s Sep 14 09:44:28 autopkgtest systemd[1]: Reload requested from client PID 1676 ('systemctl') (unit session-1.scope)... 495s Sep 14 09:44:28 autopkgtest systemd[1]: Reloading... 495s Sep 14 09:44:28 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:28 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:29 autopkgtest systemd[1]: Reloading finished in 229 ms. 495s Sep 14 09:44:29 autopkgtest systemd[1]: Reload requested from client PID 1721 ('systemctl') (unit session-1.scope)... 495s Sep 14 09:44:29 autopkgtest systemd[1]: Reloading... 495s Sep 14 09:44:29 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:29 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:29 autopkgtest systemd[1]: Reloading finished in 219 ms. 495s Sep 14 09:44:29 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 495s Sep 14 09:44:29 autopkgtest systemd[1]: Reload requested from client PID 1771 ('systemctl') (unit session-1.scope)... 495s Sep 14 09:44:29 autopkgtest systemd[1]: Reloading... 495s Sep 14 09:44:29 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:29 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:29 autopkgtest systemd[1]: Reloading finished in 195 ms. 495s Sep 14 09:44:29 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 495s Sep 14 09:44:29 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 495s Sep 14 09:44:30 autopkgtest systemd[1]: Reload requested from client PID 1825 ('systemctl') (unit session-1.scope)... 495s Sep 14 09:44:30 autopkgtest systemd[1]: Reloading... 495s Sep 14 09:44:30 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:30 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 495s Sep 14 09:44:30 autopkgtest systemd[1]: Reloading finished in 212 ms. 495s Sep 14 09:44:40 autopkgtest sudo[1272]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:40 autopkgtest sudo[5695]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 495s Sep 14 09:44:40 autopkgtest sudo[5695]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:40 autopkgtest sudo[5695]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:40 autopkgtest sudo[5705]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 495s Sep 14 09:44:40 autopkgtest sudo[5705]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:40 autopkgtest sudo[5705]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:40 autopkgtest sudo[5715]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-get --simulate --quiet -o APT::Get::Show-User-Simulation-Note=False --auto-remove purge autopkgtest-satdep 495s Sep 14 09:44:40 autopkgtest sudo[5715]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:41 autopkgtest sudo[5715]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:42 autopkgtest sudo[5728]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq fio librbd1 librados2 libboost-iostreams1.83.0 libboost-thread1.83.0 tgt libconfig-general-perl libpmemobj1 libpmem1 libndctl6 libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 open-iscsi libisns0t64 libnbd0 libopeniscsiusr librdmacm1t64 495s Sep 14 09:44:42 autopkgtest sudo[5728]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:42 autopkgtest sudo[5728]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:42 autopkgtest sudo[5740]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 495s Sep 14 09:44:42 autopkgtest sudo[5740]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:42 autopkgtest sudo[5740]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:42 autopkgtest sudo[5752]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 495s Sep 14 09:44:42 autopkgtest sudo[5752]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:43 autopkgtest sudo[5752]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:43 autopkgtest sudo[5762]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.0w3jVJ/tgtbasedmpaths-packages.all' 495s Sep 14 09:44:43 autopkgtest sudo[5762]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 495s Sep 14 09:44:43 autopkgtest sudo[5762]: pam_unix(sudo:session): session closed for user root 495s Sep 14 09:44:43 autopkgtest sudo[5773]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 499s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 499s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 499s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 499s latency : target=0, window=0, percentile=100.00%, depth=1 499s 499s Run status group 0 (all jobs): 499s WRITE: bw=183MiB/s (192MB/s), 183MiB/s-183MiB/s (192MB/s-192MB/s), io=87.5MiB (91.8MB), run=479-479msec 499s 499s Disk stats (read/write): 499s dm-0: ios=1/1189, sectors=8/152192, merge=0/0, ticks=0/346, in_queue=347, util=71.02%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/106, aggrin_queue=106, aggrutil=73.40% 499s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 499s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 499s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 499s sda: ios=1/1402, sectors=8/179280, merge=0/0, ticks=0/425, in_queue=425, util=73.40% 499s + echo Starting the path changes in background 499s + date +Pre FIO %H:%M:%S.%N 499s Starting the path changes in background 499s Pre FIO 09:44:54.542240948 499s + fio --max-jobs=4 /tmp/autopkgtest.0w3jVJ/tgtbasedmpaths-artifacts/path-change-check.fio 499s verify-phase: (g=0): rw=read, bs=(R) 64.0KiB-64.0KiB, (W) 64.0KiB-64.0KiB, (T) 64.0KiB-64.0KiB, ioengine=sync, iodepth=1 499s fio-3.37 499s Starting 1 thread 679s 679s verify-phase: (groupid=0, jobs=1): err= 0: pid=6114: Sat Sep 14 09:47:54 2024 679s read: IOPS=5416, BW=339MiB/s (355MB/s)(59.5GiB/180001msec) 679s clat (usec): min=72, max=67875, avg=161.53, stdev=199.92 679s lat (usec): min=72, max=67875, avg=161.64, stdev=199.92 679s clat percentiles (usec): 679s | 1.00th=[ 89], 5.00th=[ 97], 10.00th=[ 105], 20.00th=[ 116], 679s | 30.00th=[ 125], 40.00th=[ 135], 50.00th=[ 143], 60.00th=[ 153], 679s | 70.00th=[ 163], 80.00th=[ 176], 90.00th=[ 200], 95.00th=[ 253], 679s | 99.00th=[ 717], 99.50th=[ 840], 99.90th=[ 1401], 99.95th=[ 1729], 679s | 99.99th=[ 2900] 679s bw ( KiB/s): min=217984, max=484992, per=100.00%, avg=346957.04, stdev=41864.03, samples=359 679s iops : min= 3406, max= 7578, avg=5421.17, stdev=654.14, samples=359 679s lat (usec) : 100=7.17%, 250=87.65%, 500=3.53%, 750=0.76%, 1000=0.64% 679s lat (msec) : 2=0.21%, 4=0.02%, 10=0.01%, 20=0.01%, 50=0.01% 679s lat (msec) : 100=0.01% 679s cpu : usr=12.88%, sys=6.36%, ctx=975094, majf=0, minf=1 679s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 679s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 679s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 679s issued rwts: total=974942,0,0,0 short=0,0,0,0 dropped=0,0,0,0 679s latency : target=0, window=0, percentile=100.00%, depth=1 679s 679s Run status group 0 (all jobs): 679s READ: bw=339MiB/s (355MB/s), 339MiB/s-339MiB/s (355MB/s-355MB/s), io=59.5GiB (63.9GB), run=180001-180001msec 679s 679s Disk stats (read/write): 679s dm-0: ios=975096/10, sectors=124718904/12928, merge=0/9, ticks=156039/80, in_queue=156173, util=83.43%, aggrios=64659/2, aggsectors=8269358/3232, aggrmerge=0/0, aggrticks=10131/6, aggrin_queue=10138, aggrutil=78.14% 679s sdd: ios=103441/0, sectors=13230976/0, merge=0/0, ticks=16298/0, in_queue=16297, util=30.96% 679s sdb: ios=52920/0, sectors=6764472/0, merge=0/0, ticks=8152/0, in_queue=8151, util=40.12% 679s sdc: ios=51725/0, sectors=6616064/0, merge=0/0, ticks=8113/0, in_queue=8114, util=25.54% 679s sda: ios=50553/9, sectors=6465920/12928, merge=0/0, ticks=7964/27, in_queue=7991, util=78.14% 679s + date +Post FIO %H:%M:%S.%N 679s + echo FIO verify test with changing paths - OK 679s + echo Report log of background activity 679s + cat /tmp/autopkgtest.0w3jVJ/tgtbasedmpaths-artifacts/test-background.log 679s Post FIO 09:47:54.884474178 679s FIO verify test with changing paths - OK 679s Report log of background activity 679s + iscsiadm --mode session 679s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s + sleep 10s 679s + date +MP report (expect 4) %H:%M:%S.%N 679s MP report (expect 4) 09:45:04.549268078 679s + multipath -ll 679s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 679s size=100M features='0' hwhandler='0' wp=rw 679s |-+- policy='service-time 0' prio=1 status=active 679s | `- 0:0:0:1 sda 8:0 active ready running 679s |-+- policy='service-time 0' prio=1 status=enabled 679s | `- 1:0:0:1 sdb 8:16 active ready running 679s |-+- policy='service-time 0' prio=1 status=enabled 679s | `- 2:0:0:1 sdc 8:32 active ready running 679s `-+- policy='service-time 0' prio=1 status=enabled 679s `- 3:0:0:1 sdd 8:48 active ready running 679s + date +UN-plug path 1 %H:%M:%S.%N 679s UN-plug path 1 09:45:04.576935751 679s + iscsiadm --mode session -r 1 -u 679s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 679s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 679s + iscsiadm --mode session 679s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s + sleep 10s 679s + date +MP report (expect 3) %H:%M:%S.%N 679s MP report (expect 3) 09:45:14.655673507 679s + multipath -ll 679s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 679s size=100M features='0' hwhandler='0' wp=rw 679s |-+- policy='service-time 0' prio=1 status=active 679s | `- 1:0:0:1 sdb 8:16 active ready running 679s |-+- policy='service-time 0' prio=1 status=enabled 679s | `- 2:0:0:1 sdc 8:32 active ready running 679s `-+- policy='service-time 0' prio=1 status=enabled 679s `- 3:0:0:1 sdd 8:48 active ready running 679s + date +UN-plug path 2 %H:%M:%S.%N 679s UN-plug path 2 09:45:14.677065683 679s + iscsiadm --mode session -r 2 -u 679s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 679s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 679s + iscsiadm --mode session 679s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s + sleep 10s 679s + date +MP report (expect 2) %H:%M:%S.%N 679s MP report (expect 2) 09:45:24.775049288 679s + multipath -ll 679s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 679s size=100M features='0' hwhandler='0' wp=rw 679s |-+- policy='service-time 0' prio=1 status=active 679s | `- 2:0:0:1 sdc 8:32 active ready running 679s `-+- policy='service-time 0' prio=1 status=enabled 679s `- 3:0:0:1 sdd 8:48 active ready running 679s + date +UN-plug path 3 %H:%M:%S.%N 679s UN-plug path 3 09:45:24.790986867 679s + iscsiadm --mode session -r 3 -u 679s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 679s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 679s + iscsiadm --mode session 679s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s + sleep 10s 679s + date +MP report (expect 1) %H:%M:%S.%N 679s MP report (expect 1) 09:45:34.901960217 679s + multipath -ll 679s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 679s size=100M features='0' hwhandler='0' wp=rw 679s `-+- policy='service-time 0' prio=1 status=active 679s `- 3:0:0:1 sdd 8:48 active ready running 679s + date +Add paths 5/6/7/8 %H:%M:%S.%N 679s Add paths 5/6/7/8 09:45:34.915597577 679s + iscsiadm --mode session -r 4 --op new 679s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 679s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 679s + iscsiadm --mode session -r 4 --op new 679s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 679s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 679s + iscsiadm --mode session -r 4 --op new 679s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 679s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 679s + iscsiadm --mode session -r 4 --op new 679s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 679s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 679s + iscsiadm --mode session 679s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s + sleep 10s 679s + date +MP report (expect 5) %H:%M:%S.%N 679s MP report (expect 5) 09:45:44.983450580 679s + multipath -ll 679s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 679s size=100M features='0' hwhandler='0' wp=rw 679s |-+- policy='service-time 0' prio=1 status=active 679s | `- 3:0:0:1 sdd 8:48 active ready running 679s |-+- policy='service-time 0' prio=1 status=enabled 679s | `- 0:0:0:1 sda 8:0 active ready running 679s |-+- policy='service-time 0' prio=1 status=enabled 679s | `- 1:0:0:1 sdb 8:16 active ready running 679s |-+- policy='service-time 0' prio=1 status=enabled 679s | `- 2:0:0:1 sdc 8:32 active ready running 679s `-+- policy='service-time 0' prio=1 status=enabled 679s `- 4:0:0:1 sde 8:64 active ready running 679s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 679s UN-plug multiple paths 4/7/8 09:45:45.009675111 679s + iscsiadm --mode session -r 4 -u 679s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 679s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 679s + iscsiadm --mode session -r 7 -u 679s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 679s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 679s + iscsiadm --mode session -r 8 -u 679s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 679s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 679s + iscsiadm --mode session 679s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 679s + sleep 10s 679s + date +Restart multipath daemon %H:%M:%S.%N 679s Restart multipath daemon 09:45:55.275877018 679s + systemctl restart multipathd 679s + sleep 10s 679s + date +Final background report (expect 2) %H:%M:%S.%N 679s Final background report (expect 2) 09:46:05.339734694 679s + multipath -ll 679s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 679s size=100M features='0' hwhandler='0' wp=rw 679s |-+- policy='service-time 0' prio=1 status=active 679s | `- 0:0:0:1 sda 8:0 active ready running 679s `-+- policy='service-time 0' prio=1 status=enabled 679s `- 1:0:0:1 sdb 8:16 active ready running 679s Final stats 679s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 679s iSCSI SNMP: 679s txdata_octets: 34300536 679s rxdata_octets: 46808512352 679s noptx_pdus: 0 679s scsicmd_pdus: 714327 679s tmfcmd_pdus: 0 679s login_pdus: 0 679s text_pdus: 0 679s dataout_pdus: 0 679s logout_pdus: 0 679s snack_pdus: 0 679s noprx_pdus: 0 679s scsirsp_pdus: 714327 679s tmfrsp_pdus: 0 679s textrsp_pdus: 0 679s datain_pdus: 714292 679s logoutrsp_pdus: 0 679s r2t_pdus: 0 679s async_pdus: 0 679s rjt_pdus: 0 679s digest_err: 0 679s timeout_err: 0 679s iSCSI Extended: 679s tx_sendpage_failures: 0 679s rx_discontiguous_hdr: 0 679s eh_abort_cnt: 0 679s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 679s iSCSI SNMP: 679s txdata_octets: 6744 679s rxdata_octets: 1515328 679s noptx_pdus: 0 679s scsicmd_pdus: 111 679s tmfcmd_pdus: 0 679s login_pdus: 0 679s text_pdus: 0 679s dataout_pdus: 0 679s logout_pdus: 0 679s snack_pdus: 0 679s noprx_pdus: 0 679s scsirsp_pdus: 111 679s tmfrsp_pdus: 0 679s textrsp_pdus: 0 679s datain_pdus: 87 679s logoutrsp_pdus: 0 679s r2t_pdus: 0 679s async_pdus: 0 679s rjt_pdus: 0 679s digest_err: 0 679s timeout_err: 0 679s iSCSI Extended: 679s tx_sendpage_failures: 0 679s rx_discontiguous_hdr: 0 679s eh_abort_cnt: 0 679s + sync 679s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 679s + echo Final stats 679s + iscsiadm --mode session --stats 679s + journalctl --no-pager -u multipathd 679s + echo Check final path status 679s + multipath -ll 679s + multipath -ll 679s + grep --count status= 679s + diskc=2 679s + multipath -ll 679s + grep --count status=active 679s + diska=1 679s + multipath -ll 679s + grep --count status=enabled 679s Sep 13 17:26:08 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 679s Sep 13 17:26:08 ubuntu multipathd[356]: multipathd v0.9.9: start up 679s Sep 13 17:26:08 ubuntu multipathd[356]: reconfigure: setting up paths and maps 679s Sep 13 17:26:08 ubuntu multipathd[356]: _check_bindings_file: failed to read header from /etc/multipath/bindings 679s Sep 13 17:26:08 ubuntu multipathd[356]: updated bindings file /etc/multipath/bindings 679s Sep 13 17:26:08 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 679s Sep 13 17:28:50 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i multipathd[356]: multipathd: shut down 679s Sep 13 17:28:50 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 679s Sep 13 17:28:50 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 679s Sep 13 17:28:50 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 679s -- Boot 4a444738c451454fa296335a9e1de230 -- 679s Sep 13 17:29:02 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 679s Sep 13 17:29:02 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i multipathd[297]: multipathd v0.9.9: start up 679s Sep 13 17:29:02 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i multipathd[297]: reconfigure: setting up paths and maps 679s Sep 13 17:29:02 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 679s Sep 13 17:29:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 679s Sep 13 17:29:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i multipathd[297]: multipathd: shut down 679s Sep 13 17:29:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 679s Sep 13 17:29:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 679s -- Boot 20ccc5513a6d4c27a534ea9cc94d10d0 -- 679s Sep 14 09:42:15 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 679s Sep 14 09:42:15 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i multipathd[329]: multipathd v0.9.9: start up 679s Sep 14 09:42:15 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i multipathd[329]: reconfigure: setting up paths and maps 679s Sep 14 09:42:15 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 679s Sep 14 09:43:52 autopkgtest multipathd[329]: multipathd: shut down 679s Sep 14 09:43:52 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 679s Sep 14 09:43:53 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 679s Sep 14 09:43:53 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 679s -- Boot 2d369c138a0f4e15ac5654123a2697c2 -- 679s Sep 14 09:44:05 autopkgtest multipathd[314]: multipathd v0.9.9: start up 679s Sep 14 09:44:05 autopkgtest multipathd[314]: reconfigure: setting up paths and maps 679s Sep 14 09:44:05 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 679s Sep 14 09:44:45 autopkgtest multipathd[314]: updated bindings file /etc/multipath/bindings 679s Sep 14 09:44:45 autopkgtest multipathd[314]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 679s Sep 14 09:44:45 autopkgtest multipathd[314]: sda [8:0]: path added to devmap mpatha 679s Sep 14 09:44:45 autopkgtest multipathd[314]: mpatha: performing delayed actions 679s Sep 14 09:44:45 autopkgtest multipathd[314]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 679s Sep 14 09:45:04 autopkgtest multipathd[314]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 679s Sep 14 09:45:04 autopkgtest multipathd[314]: check_removed_paths: sda: freeing path in removed state 679s Sep 14 09:45:04 autopkgtest multipathd[314]: 8:0: path removed from map mpatha 679s Sep 14 09:45:14 autopkgtest multipathd[314]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 679s Sep 14 09:45:14 autopkgtest multipathd[314]: check_removed_paths: sdb: freeing path in removed state 679s Sep 14 09:45:14 autopkgtest multipathd[314]: 8:16: path removed from map mpatha 679s Sep 14 09:45:24 autopkgtest multipathd[314]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 679s Sep 14 09:45:24 autopkgtest multipathd[314]: check_removed_paths: sdc: freeing path in removed state 679s Sep 14 09:45:24 autopkgtest multipathd[314]: 8:32: path removed from map mpatha 679s Sep 14 09:45:35 autopkgtest multipathd[314]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1] 679s Sep 14 09:45:35 autopkgtest multipathd[314]: sda [8:0]: path added to devmap mpatha 679s Sep 14 09:45:35 autopkgtest multipathd[314]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 679s Sep 14 09:45:35 autopkgtest multipathd[314]: sdb [8:16]: path added to devmap mpatha 679s Sep 14 09:45:35 autopkgtest multipathd[314]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 679s Sep 14 09:45:35 autopkgtest multipathd[314]: sdc [8:32]: path added to devmap mpatha 679s Sep 14 09:45:35 autopkgtest multipathd[314]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 679s Sep 14 09:45:35 autopkgtest multipathd[314]: sde [8:64]: path added to devmap mpatha 679s Sep 14 09:45:45 autopkgtest multipathd[314]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 679s Sep 14 09:45:45 autopkgtest multipathd[314]: check_removed_paths: sdd: freeing path in removed state 679s Sep 14 09:45:45 autopkgtest multipathd[314]: 8:48: path removed from map mpatha 679s Sep 14 09:45:45 autopkgtest multipathd[314]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:64 1] 679s Sep 14 09:45:45 autopkgtest multipathd[314]: check_removed_paths: sdc: freeing path in removed state 679s Sep 14 09:45:45 autopkgtest multipathd[314]: 8:32: path removed from map mpatha 679s Sep 14 09:45:45 autopkgtest multipathd[314]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 679s Sep 14 09:45:45 autopkgtest multipathd[314]: check_removed_paths: sde: freeing path in removed state 679s Sep 14 09:45:45 autopkgtest multipathd[314]: 8:64: path removed from map mpatha 679s Sep 14 09:45:55 autopkgtest multipathd[314]: multipathd: shut down 679s Sep 14 09:45:55 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 679s Sep 14 09:45:55 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 679s Sep 14 09:45:55 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 679s Sep 14 09:45:55 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 679s Sep 14 09:45:55 autopkgtest multipathd[6471]: multipathd v0.9.9: start up 679s Sep 14 09:45:55 autopkgtest multipathd[6471]: reconfigure: setting up paths and maps 679s Sep 14 09:45:55 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 679s Check final path status 679s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 679s size=100M features='0' hwhandler='0' wp=rw 679s |-+- policy='service-time 0' prio=1 status=active 679s | `- 0:0:0:1 sda 8:0 active ready running 679s `-+- policy='service-time 0' prio=1 status=enabled 679s `- 1:0:0:1 sdb 8:16 active ready running 679s + diske=1 679s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 679s + echo OK 679s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 679s OK 680s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 680s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 680s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 680s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 680s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 680s autopkgtest [09:47:55]: test tgtbasedmpaths: -----------------------] 681s tgtbasedmpaths PASS 681s autopkgtest [09:47:56]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 681s autopkgtest [09:47:56]: @@@@@@@@@@@@@@@@@@@@ summary 681s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 681s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 681s kpartx-file-loopback PASS 681s tgtbasedmpaths PASS 685s nova [W] Using flock in prodstack6-ppc64el 685s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240914-093635-juju-7f2275-prod-proposed-migration-environment-2-9ea77da9-2779-4fb7-af92-509881c8be73 from image adt/ubuntu-oracular-ppc64el-server-20240913.img (UUID fe25b897-3dd6-415f-af83-adc681eec9df)... 685s nova [W] Using flock in prodstack6-ppc64el 685s flock: timeout while waiting to get lock 685s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240914-093635-juju-7f2275-prod-proposed-migration-environment-2-9ea77da9-2779-4fb7-af92-509881c8be73 from image adt/ubuntu-oracular-ppc64el-server-20240913.img (UUID fe25b897-3dd6-415f-af83-adc681eec9df)...