0s autopkgtest [09:41:26]: starting date and time: 2024-09-14 09:41:26+0000 0s autopkgtest [09:41:26]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [09:41:26]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.ti5zp5rh/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+2 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-3@bos03-ppc64el-12.secgroup --name adt-oracular-ppc64el-multipath-tools-20240914-094126-juju-7f2275-prod-proposed-migration-environment-3-ea2162c1-cd07-4da3-92ab-8845a3077359 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --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/ 131s autopkgtest [09:43:37]: testbed dpkg architecture: ppc64el 131s autopkgtest [09:43:37]: testbed apt version: 2.9.8 131s autopkgtest [09:43:37]: @@@@@@@@@@@@@@@@@@@@ test bed setup 132s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 132s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4496 B] 132s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [13.2 kB] 132s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.5 kB] 132s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [300 kB] 132s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [106 kB] 132s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2204 B] 132s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1372 B] 132s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 132s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [257 kB] 132s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [5656 B] 132s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [764 B] 132s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 134s Fetched 856 kB in 1s (1079 kB/s) 134s Reading package lists... 136s Reading package lists... 136s Building dependency tree... 136s Reading state information... 137s Calculating upgrade... 137s The following NEW packages will be installed: 137s libpython3.12t64 linux-headers-6.11.0-7 linux-headers-6.11.0-7-generic 137s linux-image-6.11.0-7-generic linux-modules-6.11.0-7-generic 137s linux-modules-extra-6.11.0-7-generic linux-tools-6.11.0-7 137s linux-tools-6.11.0-7-generic 137s The following packages will be upgraded: 137s hwdata linux-firmware linux-generic linux-headers-generic 137s linux-headers-virtual linux-image-generic linux-image-virtual linux-libc-dev 137s linux-tools-common linux-virtual 137s 10 upgraded, 8 newly installed, 0 to remove and 0 not upgraded. 137s Need to get 730 MB of archives. 137s After this operation, 349 MB of additional disk space will be used. 137s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el hwdata all 0.387-1 [29.4 kB] 137s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpython3.12t64 ppc64el 3.12.6-1 [2561 kB] 137s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el linux-firmware ppc64el 20240913.gita34e7a5f-0ubuntu2 [500 MB] 155s 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] 156s 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] 157s 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] 160s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-generic ppc64el 6.11.0-7.7+2 [1734 B] 160s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-generic ppc64el 6.11.0-7.7+2 [10.7 kB] 160s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-virtual ppc64el 6.11.0-7.7+2 [1726 B] 160s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-virtual ppc64el 6.11.0-7.7+2 [10.7 kB] 160s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-virtual ppc64el 6.11.0-7.7+2 [1644 B] 160s 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] 160s 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] 161s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-generic ppc64el 6.11.0-7.7+2 [10.6 kB] 161s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-libc-dev ppc64el 6.11.0-7.7 [1653 kB] 161s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-common all 6.11.0-7.7 [483 kB] 161s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-7 ppc64el 6.11.0-7.7 [5177 kB] 161s 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] 161s Fetched 730 MB in 24s (30.4 MB/s) 161s (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.) 161s Preparing to unpack .../00-hwdata_0.387-1_all.deb ... 161s Unpacking hwdata (0.387-1) over (0.385-1) ... 161s Selecting previously unselected package libpython3.12t64:ppc64el. 161s Preparing to unpack .../01-libpython3.12t64_3.12.6-1_ppc64el.deb ... 161s Unpacking libpython3.12t64:ppc64el (3.12.6-1) ... 161s Preparing to unpack .../02-linux-firmware_20240913.gita34e7a5f-0ubuntu2_ppc64el.deb ... 161s Unpacking linux-firmware (20240913.gita34e7a5f-0ubuntu2) over (20240911.gitce299c0f-0ubuntu1) ... 164s Selecting previously unselected package linux-modules-6.11.0-7-generic. 165s Preparing to unpack .../03-linux-modules-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 165s Unpacking linux-modules-6.11.0-7-generic (6.11.0-7.7) ... 165s Selecting previously unselected package linux-image-6.11.0-7-generic. 165s Preparing to unpack .../04-linux-image-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 165s Unpacking linux-image-6.11.0-7-generic (6.11.0-7.7) ... 165s Selecting previously unselected package linux-modules-extra-6.11.0-7-generic. 165s Preparing to unpack .../05-linux-modules-extra-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 165s Unpacking linux-modules-extra-6.11.0-7-generic (6.11.0-7.7) ... 166s Preparing to unpack .../06-linux-generic_6.11.0-7.7+2_ppc64el.deb ... 166s Unpacking linux-generic (6.11.0-7.7+2) over (6.8.0-31.31) ... 166s Preparing to unpack .../07-linux-image-generic_6.11.0-7.7+2_ppc64el.deb ... 166s Unpacking linux-image-generic (6.11.0-7.7+2) over (6.8.0-31.31) ... 166s Preparing to unpack .../08-linux-virtual_6.11.0-7.7+2_ppc64el.deb ... 166s Unpacking linux-virtual (6.11.0-7.7+2) over (6.8.0-31.31) ... 166s Preparing to unpack .../09-linux-image-virtual_6.11.0-7.7+2_ppc64el.deb ... 166s Unpacking linux-image-virtual (6.11.0-7.7+2) over (6.8.0-31.31) ... 166s Preparing to unpack .../10-linux-headers-virtual_6.11.0-7.7+2_ppc64el.deb ... 166s Unpacking linux-headers-virtual (6.11.0-7.7+2) over (6.8.0-31.31) ... 166s Selecting previously unselected package linux-headers-6.11.0-7. 166s Preparing to unpack .../11-linux-headers-6.11.0-7_6.11.0-7.7_all.deb ... 166s Unpacking linux-headers-6.11.0-7 (6.11.0-7.7) ... 169s Selecting previously unselected package linux-headers-6.11.0-7-generic. 169s Preparing to unpack .../12-linux-headers-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 169s Unpacking linux-headers-6.11.0-7-generic (6.11.0-7.7) ... 169s Preparing to unpack .../13-linux-headers-generic_6.11.0-7.7+2_ppc64el.deb ... 169s Unpacking linux-headers-generic (6.11.0-7.7+2) over (6.8.0-31.31) ... 170s Preparing to unpack .../14-linux-libc-dev_6.11.0-7.7_ppc64el.deb ... 170s Unpacking linux-libc-dev:ppc64el (6.11.0-7.7) over (6.8.0-31.31) ... 170s Preparing to unpack .../15-linux-tools-common_6.11.0-7.7_all.deb ... 170s Unpacking linux-tools-common (6.11.0-7.7) over (6.8.0-31.31) ... 170s Selecting previously unselected package linux-tools-6.11.0-7. 170s Preparing to unpack .../16-linux-tools-6.11.0-7_6.11.0-7.7_ppc64el.deb ... 170s Unpacking linux-tools-6.11.0-7 (6.11.0-7.7) ... 170s Selecting previously unselected package linux-tools-6.11.0-7-generic. 170s Preparing to unpack .../17-linux-tools-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 170s Unpacking linux-tools-6.11.0-7-generic (6.11.0-7.7) ... 170s Setting up linux-headers-6.11.0-7 (6.11.0-7.7) ... 170s Setting up linux-modules-6.11.0-7-generic (6.11.0-7.7) ... 172s Setting up linux-firmware (20240913.gita34e7a5f-0ubuntu2) ... 172s Setting up linux-libc-dev:ppc64el (6.11.0-7.7) ... 172s Setting up linux-modules-extra-6.11.0-7-generic (6.11.0-7.7) ... 174s Setting up hwdata (0.387-1) ... 174s Setting up libpython3.12t64:ppc64el (3.12.6-1) ... 174s Setting up linux-image-6.11.0-7-generic (6.11.0-7.7) ... 176s I: /boot/vmlinux is now a symlink to vmlinux-6.11.0-7-generic 176s I: /boot/initrd.img is now a symlink to initrd.img-6.11.0-7-generic 176s Setting up linux-headers-6.11.0-7-generic (6.11.0-7.7) ... 176s Setting up linux-image-virtual (6.11.0-7.7+2) ... 176s Setting up linux-tools-common (6.11.0-7.7) ... 176s Setting up linux-tools-6.11.0-7 (6.11.0-7.7) ... 176s Setting up linux-image-generic (6.11.0-7.7+2) ... 176s Setting up linux-headers-generic (6.11.0-7.7+2) ... 176s Setting up linux-tools-6.11.0-7-generic (6.11.0-7.7) ... 176s Setting up linux-headers-virtual (6.11.0-7.7+2) ... 176s Setting up linux-generic (6.11.0-7.7+2) ... 176s Setting up linux-virtual (6.11.0-7.7+2) ... 176s Processing triggers for man-db (2.12.1-3) ... 177s Processing triggers for libc-bin (2.40-1ubuntu1) ... 177s Processing triggers for initramfs-tools (0.142ubuntu33) ... 178s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 178s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 186s Processing triggers for linux-image-6.11.0-7-generic (6.11.0-7.7) ... 186s /etc/kernel/postinst.d/initramfs-tools: 186s update-initramfs: Generating /boot/initrd.img-6.11.0-7-generic 186s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 194s /etc/kernel/postinst.d/zz-update-grub: 194s Sourcing file `/etc/default/grub' 194s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 194s Generating grub configuration file ... 195s Found linux image: /boot/vmlinux-6.11.0-7-generic 195s Found initrd image: /boot/initrd.img-6.11.0-7-generic 195s Found linux image: /boot/vmlinux-6.8.0-31-generic 195s Found initrd image: /boot/initrd.img-6.8.0-31-generic 195s Warning: os-prober will not be executed to detect other bootable partitions. 195s Systems on them will not be added to the GRUB boot configuration. 195s Check GRUB_DISABLE_OS_PROBER documentation entry. 195s Adding boot menu entry for UEFI Firmware Settings ... 195s done 195s Reading package lists... 195s Building dependency tree... 195s Reading state information... 196s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 196s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 196s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 196s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 196s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 197s Reading package lists... 197s Reading package lists... 197s Building dependency tree... 197s Reading state information... 197s Calculating upgrade... 198s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 198s Reading package lists... 198s Building dependency tree... 198s Reading state information... 198s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 198s Reading package lists... 198s Building dependency tree... 198s Reading state information... 199s linux-generic is already the newest version (6.11.0-7.7+2). 199s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 199s Reading package lists... 199s Building dependency tree... 199s Reading state information... 199s E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 199s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 199s Reading package lists... 200s Building dependency tree... 200s Reading state information... 200s E: Unable to locate package ^linux-modules-extra$ 200s E: Couldn't find any package by regex '^linux-modules-extra$' 200s autopkgtest [09:44:46]: rebooting testbed after setup commands that affected boot 204s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 230s autopkgtest [09:45:16]: testbed running kernel: Linux 6.11.0-7-generic #7-Ubuntu SMP Mon Sep 9 13:10:01 UTC 2024 233s autopkgtest [09:45:19]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 235s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (dsc) [2772 B] 235s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (tar) [588 kB] 235s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (diff) [42.7 kB] 236s gpgv: Signature made Thu Sep 5 17:42:16 2024 UTC 236s gpgv: using RSA key 63EEFC3DE14D5146CE7F24BF34B8AD7D9529E793 236s gpgv: Can't check signature: No public key 236s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.9-1ubuntu3.dsc: no acceptable signature found 236s autopkgtest [09:45:22]: testing package multipath-tools version 0.9.9-1ubuntu3 236s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 236s autopkgtest [09:45:22]: build not needed 237s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 237s autopkgtest [09:45:23]: test kpartx-file-loopback: preparing testbed 238s Reading package lists... 238s Building dependency tree... 238s Reading state information... 238s Starting pkgProblemResolver with broken count: 0 238s Starting 2 pkgProblemResolver with broken count: 0 238s Done 238s The following additional packages will be installed: 238s liburing2 qemu-utils 238s Recommended packages: 238s qemu-block-extra 238s The following NEW packages will be installed: 238s autopkgtest-satdep liburing2 qemu-utils 238s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 238s Need to get 2431 kB/2432 kB of archives. 238s After this operation, 16.9 MB of additional disk space will be used. 238s Get:1 /tmp/autopkgtest.HKOtCD/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 239s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 239s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:9.0.2+ds-4ubuntu5 [2404 kB] 239s Fetched 2431 kB in 1s (3903 kB/s) 239s Selecting previously unselected package liburing2:ppc64el. 240s (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.) 240s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 240s Unpacking liburing2:ppc64el (2.6-1) ... 240s Selecting previously unselected package qemu-utils. 240s Preparing to unpack .../qemu-utils_1%3a9.0.2+ds-4ubuntu5_ppc64el.deb ... 240s Unpacking qemu-utils (1:9.0.2+ds-4ubuntu5) ... 240s Selecting previously unselected package autopkgtest-satdep. 240s Preparing to unpack .../1-autopkgtest-satdep.deb ... 240s Unpacking autopkgtest-satdep (0) ... 240s Setting up liburing2:ppc64el (2.6-1) ... 240s Setting up qemu-utils (1:9.0.2+ds-4ubuntu5) ... 240s Setting up autopkgtest-satdep (0) ... 240s Processing triggers for man-db (2.12.1-3) ... 241s Processing triggers for libc-bin (2.40-1ubuntu1) ... 243s (Reading database ... 110295 files and directories currently installed.) 243s Removing autopkgtest-satdep (0) ... 244s autopkgtest [09:45:30]: test kpartx-file-loopback: [----------------------- 244s Formatting 'foo.img', fmt=raw size=20971520 245s Creating new GPT entries in memory. 245s Warning: The kernel is still using the old partition table. 245s The new table will be used at the next reboot or after you 245s run partprobe(8) or kpartx(8) 245s The operation has completed successfully. 245s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 245s standard_filename: OK 245s del devmap : loop0p1 245s No devices found 245s standard_filename_cleanup: OK 245s Formatting 'fou du FaFa.img', fmt=raw size=20971520 246s Creating new GPT entries in memory. 246s Warning: The kernel is still using the old partition table. 246s The new table will be used at the next reboot or after you 246s run partprobe(8) or kpartx(8) 246s The operation has completed successfully. 246s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 246s filename_with_spaces: OK 246s del devmap : loop0p1 246s No devices found 246s filename_with_spaces_cleanup: OK 247s autopkgtest [09:45:33]: test kpartx-file-loopback: -----------------------] 247s autopkgtest [09:45:33]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 247s kpartx-file-loopback PASS 247s autopkgtest [09:45:33]: test tgtbasedmpaths: preparing testbed 355s autopkgtest [09:47:21]: testbed dpkg architecture: ppc64el 355s autopkgtest [09:47:21]: testbed apt version: 2.9.8 355s autopkgtest [09:47:21]: @@@@@@@@@@@@@@@@@@@@ test bed setup 356s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 356s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [300 kB] 357s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [13.2 kB] 357s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.5 kB] 357s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4496 B] 357s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [106 kB] 357s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2204 B] 357s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1372 B] 357s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 357s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [257 kB] 357s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [5656 B] 357s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [764 B] 357s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 360s Fetched 856 kB in 1s (1155 kB/s) 360s Reading package lists... 363s Reading package lists... 363s Building dependency tree... 363s Reading state information... 363s Calculating upgrade... 364s The following NEW packages will be installed: 364s libpython3.12t64 linux-headers-6.11.0-7 linux-headers-6.11.0-7-generic 364s linux-image-6.11.0-7-generic linux-modules-6.11.0-7-generic 364s linux-modules-extra-6.11.0-7-generic linux-tools-6.11.0-7 364s linux-tools-6.11.0-7-generic 364s The following packages will be upgraded: 364s hwdata linux-firmware linux-generic linux-headers-generic 364s linux-headers-virtual linux-image-generic linux-image-virtual linux-libc-dev 364s linux-tools-common linux-virtual 364s 10 upgraded, 8 newly installed, 0 to remove and 0 not upgraded. 364s Need to get 730 MB of archives. 364s After this operation, 349 MB of additional disk space will be used. 364s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el hwdata all 0.387-1 [29.4 kB] 364s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpython3.12t64 ppc64el 3.12.6-1 [2561 kB] 364s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el linux-firmware ppc64el 20240913.gita34e7a5f-0ubuntu2 [500 MB] 378s 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] 379s 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] 381s 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] 385s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-generic ppc64el 6.11.0-7.7+2 [1734 B] 385s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-generic ppc64el 6.11.0-7.7+2 [10.7 kB] 385s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-virtual ppc64el 6.11.0-7.7+2 [1726 B] 385s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-virtual ppc64el 6.11.0-7.7+2 [10.7 kB] 385s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-virtual ppc64el 6.11.0-7.7+2 [1644 B] 385s 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] 386s 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] 386s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-generic ppc64el 6.11.0-7.7+2 [10.6 kB] 386s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-libc-dev ppc64el 6.11.0-7.7 [1653 kB] 386s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-common all 6.11.0-7.7 [483 kB] 386s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-7 ppc64el 6.11.0-7.7 [5177 kB] 386s 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] 386s Fetched 730 MB in 22s (32.8 MB/s) 387s (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.) 387s Preparing to unpack .../00-hwdata_0.387-1_all.deb ... 387s Unpacking hwdata (0.387-1) over (0.385-1) ... 387s Selecting previously unselected package libpython3.12t64:ppc64el. 387s Preparing to unpack .../01-libpython3.12t64_3.12.6-1_ppc64el.deb ... 387s Unpacking libpython3.12t64:ppc64el (3.12.6-1) ... 387s Preparing to unpack .../02-linux-firmware_20240913.gita34e7a5f-0ubuntu2_ppc64el.deb ... 387s Unpacking linux-firmware (20240913.gita34e7a5f-0ubuntu2) over (20240911.gitce299c0f-0ubuntu1) ... 391s Selecting previously unselected package linux-modules-6.11.0-7-generic. 391s Preparing to unpack .../03-linux-modules-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 391s Unpacking linux-modules-6.11.0-7-generic (6.11.0-7.7) ... 391s Selecting previously unselected package linux-image-6.11.0-7-generic. 391s Preparing to unpack .../04-linux-image-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 391s Unpacking linux-image-6.11.0-7-generic (6.11.0-7.7) ... 392s Selecting previously unselected package linux-modules-extra-6.11.0-7-generic. 392s Preparing to unpack .../05-linux-modules-extra-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 392s Unpacking linux-modules-extra-6.11.0-7-generic (6.11.0-7.7) ... 393s Preparing to unpack .../06-linux-generic_6.11.0-7.7+2_ppc64el.deb ... 393s Unpacking linux-generic (6.11.0-7.7+2) over (6.8.0-31.31) ... 393s Preparing to unpack .../07-linux-image-generic_6.11.0-7.7+2_ppc64el.deb ... 393s Unpacking linux-image-generic (6.11.0-7.7+2) over (6.8.0-31.31) ... 393s Preparing to unpack .../08-linux-virtual_6.11.0-7.7+2_ppc64el.deb ... 393s Unpacking linux-virtual (6.11.0-7.7+2) over (6.8.0-31.31) ... 393s Preparing to unpack .../09-linux-image-virtual_6.11.0-7.7+2_ppc64el.deb ... 393s Unpacking linux-image-virtual (6.11.0-7.7+2) over (6.8.0-31.31) ... 393s Preparing to unpack .../10-linux-headers-virtual_6.11.0-7.7+2_ppc64el.deb ... 393s Unpacking linux-headers-virtual (6.11.0-7.7+2) over (6.8.0-31.31) ... 393s Selecting previously unselected package linux-headers-6.11.0-7. 393s Preparing to unpack .../11-linux-headers-6.11.0-7_6.11.0-7.7_all.deb ... 393s Unpacking linux-headers-6.11.0-7 (6.11.0-7.7) ... 396s Selecting previously unselected package linux-headers-6.11.0-7-generic. 397s Preparing to unpack .../12-linux-headers-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 397s Unpacking linux-headers-6.11.0-7-generic (6.11.0-7.7) ... 398s Preparing to unpack .../13-linux-headers-generic_6.11.0-7.7+2_ppc64el.deb ... 398s Unpacking linux-headers-generic (6.11.0-7.7+2) over (6.8.0-31.31) ... 398s Preparing to unpack .../14-linux-libc-dev_6.11.0-7.7_ppc64el.deb ... 398s Unpacking linux-libc-dev:ppc64el (6.11.0-7.7) over (6.8.0-31.31) ... 398s Preparing to unpack .../15-linux-tools-common_6.11.0-7.7_all.deb ... 398s Unpacking linux-tools-common (6.11.0-7.7) over (6.8.0-31.31) ... 398s Selecting previously unselected package linux-tools-6.11.0-7. 398s Preparing to unpack .../16-linux-tools-6.11.0-7_6.11.0-7.7_ppc64el.deb ... 398s Unpacking linux-tools-6.11.0-7 (6.11.0-7.7) ... 398s Selecting previously unselected package linux-tools-6.11.0-7-generic. 398s Preparing to unpack .../17-linux-tools-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 398s Unpacking linux-tools-6.11.0-7-generic (6.11.0-7.7) ... 398s Setting up linux-headers-6.11.0-7 (6.11.0-7.7) ... 398s Setting up linux-modules-6.11.0-7-generic (6.11.0-7.7) ... 401s Setting up linux-firmware (20240913.gita34e7a5f-0ubuntu2) ... 401s Setting up linux-libc-dev:ppc64el (6.11.0-7.7) ... 401s Setting up linux-modules-extra-6.11.0-7-generic (6.11.0-7.7) ... 403s Setting up hwdata (0.387-1) ... 403s Setting up libpython3.12t64:ppc64el (3.12.6-1) ... 403s Setting up linux-image-6.11.0-7-generic (6.11.0-7.7) ... 405s I: /boot/vmlinux is now a symlink to vmlinux-6.11.0-7-generic 405s I: /boot/initrd.img is now a symlink to initrd.img-6.11.0-7-generic 405s Setting up linux-headers-6.11.0-7-generic (6.11.0-7.7) ... 405s Setting up linux-image-virtual (6.11.0-7.7+2) ... 405s Setting up linux-tools-common (6.11.0-7.7) ... 405s Setting up linux-tools-6.11.0-7 (6.11.0-7.7) ... 405s Setting up linux-image-generic (6.11.0-7.7+2) ... 405s Setting up linux-headers-generic (6.11.0-7.7+2) ... 405s Setting up linux-tools-6.11.0-7-generic (6.11.0-7.7) ... 405s Setting up linux-headers-virtual (6.11.0-7.7+2) ... 405s Setting up linux-generic (6.11.0-7.7+2) ... 405s Setting up linux-virtual (6.11.0-7.7+2) ... 405s Processing triggers for man-db (2.12.1-3) ... 407s Processing triggers for libc-bin (2.40-1ubuntu1) ... 407s Processing triggers for initramfs-tools (0.142ubuntu33) ... 407s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 407s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 417s Processing triggers for linux-image-6.11.0-7-generic (6.11.0-7.7) ... 417s /etc/kernel/postinst.d/initramfs-tools: 417s update-initramfs: Generating /boot/initrd.img-6.11.0-7-generic 417s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 426s /etc/kernel/postinst.d/zz-update-grub: 426s Sourcing file `/etc/default/grub' 426s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 426s Generating grub configuration file ... 426s Found linux image: /boot/vmlinux-6.11.0-7-generic 426s Found initrd image: /boot/initrd.img-6.11.0-7-generic 426s Found linux image: /boot/vmlinux-6.8.0-31-generic 426s Found initrd image: /boot/initrd.img-6.8.0-31-generic 426s Warning: os-prober will not be executed to detect other bootable partitions. 426s Systems on them will not be added to the GRUB boot configuration. 426s Check GRUB_DISABLE_OS_PROBER documentation entry. 426s Adding boot menu entry for UEFI Firmware Settings ... 426s done 426s Reading package lists... 427s Building dependency tree... 427s Reading state information... 427s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 427s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 427s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 427s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 428s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 429s Reading package lists... 429s Reading package lists... 429s Building dependency tree... 429s Reading state information... 429s Calculating upgrade... 430s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 430s Reading package lists... 430s Building dependency tree... 430s Reading state information... 430s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 430s Reading package lists... 431s Building dependency tree... 431s Reading state information... 431s linux-generic is already the newest version (6.11.0-7.7+2). 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 E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 432s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 432s Reading package lists... 432s Building dependency tree... 432s Reading state information... 432s E: Unable to locate package ^linux-modules-extra$ 432s E: Couldn't find any package by regex '^linux-modules-extra$' 432s autopkgtest [09:48:38]: rebooting testbed after setup commands that affected boot 436s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 468s Reading package lists... 468s Building dependency tree... 468s Reading state information... 468s Starting pkgProblemResolver with broken count: 0 468s Starting 2 pkgProblemResolver with broken count: 0 468s 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.HKOtCD/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 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.5 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. 472s Preparing to unpack .../12-libndctl6_77-2.2ubuntu1_ppc64el.deb ... 472s Unpacking libndctl6:ppc64el (77-2.2ubuntu1) ... 472s Selecting previously unselected package libpmem1:ppc64el. 472s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 472s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 472s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 472s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 472s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 472s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 472s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 472s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 472s Selecting previously unselected package librados2. 472s Preparing to unpack .../16-librados2_19.2.0~rc2-0ubuntu1_ppc64el.deb ... 472s 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) ... 474s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 475s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 475s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 475s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 475s Setting up librbd1 (19.2.0~rc2-0ubuntu1) ... 475s Setting up libgfrpc0:ppc64el (11.1-5ubuntu1) ... 475s Setting up libgfapi0:ppc64el (11.1-5ubuntu1) ... 475s Setting up fio (3.37-1) ... 476s Setting up autopkgtest-satdep (0) ... 476s Processing triggers for man-db (2.12.1-3) ... 477s Processing triggers for initramfs-tools (0.142ubuntu33) ... 477s update-initramfs: Generating /boot/initrd.img-6.11.0-7-generic 477s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 486s Processing triggers for libc-bin (2.40-1ubuntu1) ... 490s (Reading database ... 110512 files and directories currently installed.) 490s Removing autopkgtest-satdep (0) ... 491s autopkgtest [09:49:37]: test tgtbasedmpaths: [----------------------- 492s + targetname=iqn.2016-11.foo.com:target.iscsi 492s + pwd 492s + cwd=/tmp/autopkgtest.HKOtCD/build.aEd/src 492s + testdir=/mnt/tgtmpathtest 492s + localhost=127.0.0.1 492s + portal=127.0.0.1:3260 492s + maxpaths=4 492s + backfn=backingfile 492s + expectwwid=60000000000000000e00000000010001 492s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 492s + bglog=/tmp/autopkgtest.HKOtCD/tgtbasedmpaths-artifacts/test-background.log 492s + fioprep=/tmp/autopkgtest.HKOtCD/tgtbasedmpaths-artifacts/path-change-prep.fio 492s + fiovrfy=/tmp/autopkgtest.HKOtCD/tgtbasedmpaths-artifacts/path-change-check.fio 492s + mkdir -p /etc/multipath 492s + echo /360000000000000000e00000000010001/ 492s + service tgt restart 492s + truncate --size 100M backingfile 492s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 492s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 492s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.HKOtCD/build.aEd/src/backingfile 492s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 492s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 492s login #1 492s + echo login #1 492s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 492s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 492s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 492s + seq 2 4 492s extra login #2 492s + echo extra login #2 492s + iscsiadm --mode session -r 1 --op new 492s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 492s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 492s extra login #3 492s + echo extra login #3 492s + iscsiadm --mode session -r 1 --op new 492s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 492s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 492s extra login #4 492s + echo extra login #4 492s + iscsiadm --mode session -r 1 --op new 492s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 492s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 492s + udevadm settle 492s + sleep 5 497s Status after initial setup 497s + echo Status after initial setup 497s + tgtadm --lld iscsi --mode target --op show 497s + tgtadm --lld iscsi --op show --mode conn --tid 1 497s Target 1: iqn.2016-11.foo.com:target.iscsi 497s System information: 497s Driver: iscsi 497s State: ready 497s I_T nexus information: 497s I_T nexus: 1 497s Initiator: iqn.2004-10.com.ubuntu:01:7da6cd33b2f alias: autopkgtest 497s Connection: 0 497s IP Address: 127.0.0.1 497s I_T nexus: 2 497s Initiator: iqn.2004-10.com.ubuntu:01:7da6cd33b2f alias: autopkgtest 497s Connection: 0 497s IP Address: 127.0.0.1 497s I_T nexus: 3 497s Initiator: iqn.2004-10.com.ubuntu:01:7da6cd33b2f alias: autopkgtest 497s Connection: 0 497s IP Address: 127.0.0.1 497s I_T nexus: 4 497s Initiator: iqn.2004-10.com.ubuntu:01:7da6cd33b2f alias: autopkgtest 497s Connection: 0 497s IP Address: 127.0.0.1 497s LUN information: 497s LUN: 0 497s Type: controller 497s SCSI ID: IET 00010000 497s SCSI SN: beaf10 497s Size: 0 MB, Block size: 1 497s Online: Yes 497s Removable media: No 497s Prevent removal: No 497s Readonly: No 497s SWP: No 497s Thin-provisioning: No 497s Backing store type: null 497s Backing store path: None 497s Backing store flags: 497s LUN: 1 497s Type: disk 497s SCSI ID: IET 00010001 497s SCSI SN: beaf11 497s Size: 105 MB, Block size: 512 497s Online: Yes 497s Removable media: No 497s Prevent removal: No 497s Readonly: No 497s SWP: No 497s Thin-provisioning: No 497s Backing store type: rdwr 497s Backing store path: /tmp/autopkgtest.HKOtCD/build.aEd/src/backingfile 497s Backing store flags: 497s Account information: 497s ACL information: 497s ALL 497s + iscsiadm --mode session -P 1 497s Session: 4 497s Connection: 0 497s Initiator: iqn.2004-10.com.ubuntu:01:7da6cd33b2f 497s IP Address: 127.0.0.1 497s Session: 3 497s Connection: 0 497s Initiator: iqn.2004-10.com.ubuntu:01:7da6cd33b2f 497s IP Address: 127.0.0.1 497s Session: 2 497s Connection: 0 497s Initiator: iqn.2004-10.com.ubuntu:01:7da6cd33b2f 497s IP Address: 127.0.0.1 497s Session: 1 497s Connection: 0 497s Initiator: iqn.2004-10.com.ubuntu:01:7da6cd33b2f 497s IP Address: 127.0.0.1 497s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 497s Current Portal: 127.0.0.1:3260,1 497s Persistent Portal: 127.0.0.1:3260,1 497s ********** 497s Interface: 497s ********** 497s Iface Name: default 497s Iface Transport: tcp 497s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:7da6cd33b2f 497s Iface IPaddress: 127.0.0.1 497s Iface HWaddress: default 497s Iface Netdev: default 497s SID: 1 497s iSCSI Connection State: LOGGED IN 497s iSCSI Session State: LOGGED_IN 497s Internal iscsid Session State: NO CHANGE 497s 497s ********** 497s Interface: 497s ********** 497s Iface Name: default 497s Iface Transport: tcp 497s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:7da6cd33b2f 497s Iface IPaddress: 127.0.0.1 497s Iface HWaddress: default 497s Iface Netdev: default 497s SID: 2 497s iSCSI Connection State: LOGGED IN 497s iSCSI Session State: LOGGED_IN 497s Internal iscsid Session State: NO CHANGE 497s 497s ********** 497s Interface: 497s ********** 497s Iface Name: default 497s Iface Transport: tcp 497s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:7da6cd33b2f 497s Iface IPaddress: 127.0.0.1 497s Iface HWaddress: default 497s Iface Netdev: default 497s SID: 3 497s iSCSI Connection State: LOGGED IN 497s iSCSI Session State: LOGGED_IN 497s Internal iscsid Session State: NO CHANGE 497s 497s ********** 497s Interface: 497s ********** 497s Iface Name: default 497s Iface Transport: tcp 497s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:7da6cd33b2f 497s Iface IPaddress: 127.0.0.1 497s Iface HWaddress: default 497s Iface Netdev: default 497s SID: 4 497s iSCSI Connection State: LOGGED IN 497s iSCSI Session State: LOGGED_IN 497s Internal iscsid Session State: NO CHANGE 497s + lsscsi -liv 497s [0:0:0:0] storage IET Controller 0001 - - 497s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 497s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 497s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 497s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 497s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 497s [1:0:0:0] storage IET Controller 0001 - - 497s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 497s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 497s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 497s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 497s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 497s [2:0:0:0] storage IET Controller 0001 - - 497s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 497s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 497s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 497s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 497s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 497s [3:0:0:0] storage IET Controller 0001 - - 497s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 497s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 497s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 497s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 497s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 497s NVMe module may not be loaded 497s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 497s + multipath -v3 -ll 497s 51.323126 | set open fds limit to 1073741816/1073741816 497s 51.323189 | _read_bindings_file: reading /etc/multipath/bindings 497s 51.323224 | loading /usr/lib/multipath/libchecktur.so checker 497s 51.323341 | checker tur: message table size = 4 497s 51.323352 | loading /usr/lib/multipath/libprioconst.so prioritizer 497s 51.323490 | _init_foreign: foreign library "nvme" is not enabled 497s 51.330638 | vda: device node name blacklisted 497s 51.331068 | sda: size = 204800 497s 51.331268 | sda: vendor = IET 497s 51.331306 | sda: product = VIRTUAL-DISK 497s 51.331339 | sda: rev = 0001 497s 51.332429 | sda: h:b:t:l = 0:0:0:1 497s 51.332931 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 497s 51.332938 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 497s 51.332942 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 497s 51.333186 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 497s 51.333191 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 497s 51.333212 | sda: serial = beaf11 497s 51.333216 | sda: detect_checker = yes (setting: multipath internal) 497s 51.333252 | sda checker timeout = 30 s (setting: kernel sysfs) 497s 51.333538 | sda: path_checker = tur (setting: multipath internal) 497s 51.333697 | sda: tur state = up 497s 51.333872 | sdb: size = 204800 497s 51.334055 | sdb: vendor = IET 497s 51.334085 | sdb: product = VIRTUAL-DISK 497s 51.334140 | sdb: rev = 0001 497s 51.335138 | sdb: h:b:t:l = 1:0:0:1 497s 51.335739 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 497s 51.335746 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 497s 51.335749 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 497s 51.336014 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 497s 51.336033 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 497s 51.336060 | sdb: serial = beaf11 497s 51.336065 | sdb: detect_checker = yes (setting: multipath internal) 497s 51.336108 | sdb checker timeout = 30 s (setting: kernel sysfs) 497s 51.336341 | sdb: path_checker = tur (setting: multipath internal) 497s 51.336492 | sdb: tur state = up 497s 51.336711 | sdc: size = 204800 497s 51.336871 | sdc: vendor = IET 497s 51.336895 | sdc: product = VIRTUAL-DISK 497s 51.336918 | sdc: rev = 0001 497s 51.338146 | sdc: h:b:t:l = 2:0:0:1 497s 51.338858 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 497s 51.338866 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 497s 51.338874 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 497s 51.339160 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 497s 51.339167 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 497s 51.339192 | sdc: serial = beaf11 497s 51.339196 | sdc: detect_checker = yes (setting: multipath internal) 497s 51.339237 | sdc checker timeout = 30 s (setting: kernel sysfs) 497s 51.339453 | sdc: path_checker = tur (setting: multipath internal) 497s 51.339618 | sdc: tur state = up 497s 51.339851 | sdd: size = 204800 497s 51.340195 | sdd: vendor = IET 497s 51.340250 | sdd: product = VIRTUAL-DISK 497s 51.340288 | sdd: rev = 0001 497s 51.341530 | sdd: h:b:t:l = 3:0:0:1 497s 51.342153 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 497s 51.342161 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 497s 51.342165 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 497s 51.342423 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 497s 51.342432 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 497s 51.342458 | sdd: serial = beaf11 497s 51.342465 | sdd: detect_checker = yes (setting: multipath internal) 497s 51.342512 | sdd checker timeout = 30 s (setting: kernel sysfs) 497s 51.342701 | sdd: path_checker = tur (setting: multipath internal) 497s 51.342822 | sdd: tur state = up 497s 51.342984 | loop0: device node name blacklisted 497s 51.343123 | loop1: device node name blacklisted 497s 51.343278 | loop2: device node name blacklisted 497s 51.343442 | loop3: device node name blacklisted 497s 51.343594 | loop4: device node name blacklisted 497s 51.343758 | loop5: device node name blacklisted 497s 51.343886 | loop6: device node name blacklisted 497s 51.344029 | loop7: device node name blacklisted 497s 51.344241 | dm-0: device node name blacklisted 497s 51.346230 | multipath-tools v0.9.9 (05/03, 2024) 497s 51.346263 | libdevmapper version 1.02.196 497s 51.346513 | kernel device mapper v4.48.0 497s 51.346535 | DM multipath kernel driver v1.14.0 497s 51.346733 | sda: size = 204800 497s 51.346744 | sda: vendor = IET 497s 51.346749 | sda: product = VIRTUAL-DISK 497s 51.346753 | sda: rev = 0001 497s 51.347981 | sda: h:b:t:l = 0:0:0:1 497s 51.348293 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 497s 51.348345 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 497s 51.348353 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 497s 51.348379 | sda: serial = beaf11 497s 51.348625 | sda: tur state = up 497s 51.348635 | sda: uid = 360000000000000000e00000000010001 (udev) 497s 51.348640 | sda: detect_prio = yes (setting: multipath internal) 497s 51.348646 | sda: prio = const (setting: multipath internal) 497s 51.348650 | sda: prio args = "" (setting: multipath internal) 497s 51.348655 | sda: const prio = 1 497s 51.348699 | sdb: size = 204800 497s 51.348709 | sdb: vendor = IET 497s 51.348713 | sdb: product = VIRTUAL-DISK 497s 51.348717 | sdb: rev = 0001 497s 51.349835 | sdb: h:b:t:l = 1:0:0:1 497s 51.350030 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 497s 51.350065 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 497s 51.350071 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 497s 51.350119 | sdb: serial = beaf11 497s 51.350319 | sdb: tur state = up 497s 51.350340 | sdb: uid = 360000000000000000e00000000010001 (udev) 497s 51.350345 | sdb: detect_prio = yes (setting: multipath internal) 497s 51.350350 | sdb: prio = const (setting: multipath internal) 497s 51.350353 | sdb: prio args = "" (setting: multipath internal) 497s 51.350357 | sdb: const prio = 1 497s 51.350396 | sdc: size = 204800 497s 51.350406 | sdc: vendor = IET 497s 51.350410 | sdc: product = VIRTUAL-DISK 497s 51.350414 | sdc: rev = 0001 497s 51.351519 | sdc: h:b:t:l = 2:0:0:1 497s 51.351744 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 497s 51.351783 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 497s 51.351790 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 497s 51.351815 | sdc: serial = beaf11 497s 51.351993 | sdc: tur state = up 497s 51.352023 | sdc: uid = 360000000000000000e00000000010001 (udev) 497s 51.352040 | sdc: detect_prio = yes (setting: multipath internal) 497s 51.352045 | sdc: prio = const (setting: multipath internal) 497s 51.352049 | sdc: prio args = "" (setting: multipath internal) 497s 51.352053 | sdc: const prio = 1 497s 51.352099 | sdd: size = 204800 497s 51.352110 | sdd: vendor = IET 497s 51.352114 | sdd: product = VIRTUAL-DISK 497s 51.352119 | sdd: rev = 0001 497s 51.353369 | sdd: h:b:t:l = 3:0:0:1 497s 51.353526 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 497s 51.353562 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 497s 51.353569 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 497s 51.353591 | sdd: serial = beaf11 497s 51.353723 | sdd: tur state = up 497s 51.353729 | sdd: uid = 360000000000000000e00000000010001 (udev) 497s 51.353732 | sdd: detect_prio = yes (setting: multipath internal) 497s 51.353735 | sdd: prio = const (setting: multipath internal) 497s 51.353738 | sdd: prio args = "" (setting: multipath internal) 497s 51.353740 | sdd: const prio = 1 497s 51.354930 | unloading tur checker 497s 51.354974 | unloading const prioritizer 497s ===== paths list ===== 497s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 497s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 497s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 497s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 497s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 497s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 497s size=100M features='0' hwhandler='0' wp=rw 497s |-+- policy='service-time 0' prio=1 status=active 497s | `- 0:0:0:1 sda 8:0 active ready running 497s |-+- policy='service-time 0' prio=1 status=enabled 497s | `- 1:0:0:1 sdb 8:16 active ready running 497s |-+- policy='service-time 0' prio=1 status=enabled 497s | `- 2:0:0:1 sdc 8:32 active ready running 497s `-+- policy='service-time 0' prio=1 status=enabled 497s `- 3:0:0:1 sdd 8:48 active ready running 497s 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 497s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 497s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 497s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 497s /etc/multipath/bindings:# 497s /etc/multipath/bindings:# Format: 497s /etc/multipath/bindings:# alias wwid 497s /etc/multipath/bindings:# 497s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 497s /etc/multipath/wwids:/360000000000000000e00000000010001/ 497s + dmsetup table 497s + grep . /etc/multipath/bindings /etc/multipath/wwids 497s + systemctl status multipathd.service 497s + ret_code=0 497s + systemctl status multipathd.socket 497s ● multipathd.service - Device-Mapper Multipath Device Controller 497s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 497s Active: active (running) since Sat 2024-09-14 09:48:55 UTC; 48s ago 497s Invocation: bb2872ac8c02402e813332447fade813 497s TriggeredBy: ○ multipathd.socket 497s Main PID: 334 (multipathd) 497s Status: "up" 497s Tasks: 7 497s Memory: 27.8M (peak: 35.6M) 497s CPU: 40ms 497s CGroup: /system.slice/multipathd.service 497s └─334 /sbin/multipathd -d -s 497s 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 497s Sep 14 09:48:55 autopkgtest multipathd[334]: multipathd v0.9.9: start up 497s Sep 14 09:48:55 autopkgtest multipathd[334]: reconfigure: setting up paths and maps 497s Sep 14 09:48:55 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 497s Sep 14 09:49:38 autopkgtest multipathd[334]: updated bindings file /etc/multipath/bindings 497s Sep 14 09:49:38 autopkgtest multipathd[334]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 497s Sep 14 09:49:38 autopkgtest multipathd[334]: sda [8:0]: path added to devmap mpatha 497s Sep 14 09:49:38 autopkgtest multipathd[334]: mpatha: performing delayed actions 497s Sep 14 09:49:38 autopkgtest multipathd[334]: 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] 497s ○ multipathd.socket - multipathd control socket 497s Loaded: loaded (/usr/lib/systemd/system/multipathd.socket; static) 497s Active: inactive (dead) 497s Triggers: ● multipathd.service 497s Listen: @/org/kernel/linux/storage/multipathd (Stream) 497s + ret_code=3 497s + [ 3 -eq 0 ] 497s + [ 3 -eq 3 ] 497s + ls -la /dev/mapper/ 497s total 0 497s drwxr-xr-x 2 root root 80 Sep 14 09:49 . 497s drwxr-xr-x 20 root root 4360 Sep 14 09:49 .. 497s crw------- 1 root root 10, 236 Sep 14 09:48 control 497s lrwxrwxrwx 1 root root 7 Sep 14 09:49 mpatha -> ../dm-0 497s journal 497s + echo journal 497s + journalctl -b 497s Sep 14 09:48:55 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 497s Sep 14 09:48:55 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 497s Sep 14 09:48:55 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 497s Sep 14 09:48:55 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 497s Sep 14 09:48:55 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 497s Sep 14 09:48:55 autopkgtest kernel: Activating Kernel Userspace Access Prevention 497s Sep 14 09:48:55 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 497s Sep 14 09:48:55 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x0000000003a00000 with 2.00 MiB pages (exec) 497s Sep 14 09:48:55 autopkgtest kernel: radix-mmu: Mapped 0x0000000003a00000-0x0000000040000000 with 2.00 MiB pages 497s Sep 14 09:48:55 autopkgtest kernel: radix-mmu: Mapped 0x0000000040000000-0x0000000200000000 with 1.00 GiB pages 497s Sep 14 09:48:55 autopkgtest kernel: lpar: Using radix MMU under hypervisor 497s Sep 14 09:48:55 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) 497s Sep 14 09:48:55 autopkgtest kernel: Secure boot mode disabled 497s Sep 14 09:48:55 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc000000009442eed 497s Sep 14 09:48:55 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (architected) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 497s Sep 14 09:48:55 autopkgtest kernel: Partition configured for 4 cpus. 497s Sep 14 09:48:55 autopkgtest kernel: CPU maps initialized for 1 thread per core 497s Sep 14 09:48:55 autopkgtest kernel: (thread shift is 0) 497s Sep 14 09:48:55 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 497s Sep 14 09:48:55 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 497s Sep 14 09:48:55 autopkgtest kernel: ----------------------------------------------------- 497s Sep 14 09:48:55 autopkgtest kernel: phys_mem_size = 0x200000000 497s Sep 14 09:48:55 autopkgtest kernel: dcache_bsize = 0x80 497s Sep 14 09:48:55 autopkgtest kernel: icache_bsize = 0x80 497s Sep 14 09:48:55 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 497s Sep 14 09:48:55 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 497s Sep 14 09:48:55 autopkgtest kernel: always = 0x0000000380008181 497s Sep 14 09:48:55 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 497s Sep 14 09:48:55 autopkgtest kernel: mmu_features = 0x3c007641 497s Sep 14 09:48:55 autopkgtest kernel: firmware_features = 0x00000285455a445f 497s Sep 14 09:48:55 autopkgtest kernel: vmalloc start = 0xc008000000000000 497s Sep 14 09:48:55 autopkgtest kernel: IO start = 0xc00a000000000000 497s Sep 14 09:48:55 autopkgtest kernel: vmemmap start = 0xc00c000000000000 497s Sep 14 09:48:55 autopkgtest kernel: ----------------------------------------------------- 497s Sep 14 09:48:55 autopkgtest kernel: numa: NODE_DATA [mem 0x1fff7c280-0x1fff83fff] 497s Sep 14 09:48:55 autopkgtest kernel: rfi-flush: fallback displacement flush available 497s Sep 14 09:48:55 autopkgtest kernel: rfi-flush: ori type flush available 497s Sep 14 09:48:55 autopkgtest kernel: rfi-flush: mttrig type flush available 497s Sep 14 09:48:55 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 497s Sep 14 09:48:55 autopkgtest kernel: count-cache-flush: hardware flush enabled. 497s Sep 14 09:48:55 autopkgtest kernel: link-stack-flush: software flush enabled. 497s Sep 14 09:48:55 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 497s Sep 14 09:48:55 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 497s Sep 14 09:48:55 autopkgtest kernel: stf-barrier: eieio barrier available 497s Sep 14 09:48:55 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 497s Sep 14 09:48:55 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 497s Sep 14 09:48:55 autopkgtest kernel: PPC64 nvram contains 65536 bytes 497s Sep 14 09:48:55 autopkgtest kernel: barrier-nospec: using ORI speculation barrier 497s Sep 14 09:48:55 autopkgtest kernel: barrier-nospec: patched 275 locations 497s Sep 14 09:48:55 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 497s Sep 14 09:48:55 autopkgtest kernel: Memory hole size: 0MB 497s Sep 14 09:48:55 autopkgtest kernel: Zone ranges: 497s Sep 14 09:48:55 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 497s Sep 14 09:48:55 autopkgtest kernel: Device empty 497s Sep 14 09:48:55 autopkgtest kernel: Movable zone start for each node 497s Sep 14 09:48:55 autopkgtest kernel: Early memory node ranges 497s Sep 14 09:48:55 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 497s Sep 14 09:48:55 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 497s Sep 14 09:48:55 autopkgtest kernel: percpu: Embedded 12 pages/cpu s619032 r0 d167400 u786432 497s Sep 14 09:48:55 autopkgtest kernel: pcpu-alloc: s619032 r0 d167400 u786432 alloc=12*65536 497s Sep 14 09:48:55 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 497s Sep 14 09:48:55 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 497s Sep 14 09:48:55 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.11.0-7-generic", will be passed to user space. 497s Sep 14 09:48:55 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 497s Sep 14 09:48:55 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 497s Sep 14 09:48:55 autopkgtest kernel: Fallback order for Node 0: 0 497s Sep 14 09:48:55 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 131072 497s Sep 14 09:48:55 autopkgtest kernel: Policy zone: Normal 497s Sep 14 09:48:55 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 497s Sep 14 09:48:55 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 497s Sep 14 09:48:55 autopkgtest kernel: ftrace: allocating 52916 entries in 20 pages 497s Sep 14 09:48:55 autopkgtest kernel: ftrace: allocated 20 pages with 2 groups 497s Sep 14 09:48:55 autopkgtest kernel: trace event string verifier disabled 497s Sep 14 09:48:55 autopkgtest kernel: rcu: Hierarchical RCU implementation. 497s Sep 14 09:48:55 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 497s Sep 14 09:48:55 autopkgtest kernel: Rude variant of Tasks RCU enabled. 497s Sep 14 09:48:55 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 497s Sep 14 09:48:55 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 497s Sep 14 09:48:55 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 497s Sep 14 09:48:55 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 497s Sep 14 09:48:55 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 497s Sep 14 09:48:55 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 497s Sep 14 09:48:55 autopkgtest kernel: xive: Using IRQ range [0-3] 497s Sep 14 09:48:55 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 497s Sep 14 09:48:55 autopkgtest kernel: xive: Using priority 6 for all interrupts 497s Sep 14 09:48:55 autopkgtest kernel: xive: Using 64kB queues 497s Sep 14 09:48:55 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 497s Sep 14 09:48:55 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 497s Sep 14 09:48:55 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 497s Sep 14 09:48:55 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 497s Sep 14 09:48:55 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 497s Sep 14 09:48:55 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 497s Sep 14 09:48:55 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 497s Sep 14 09:48:55 autopkgtest kernel: Console: colour dummy device 80x25 497s Sep 14 09:48:55 autopkgtest kernel: pid_max: default: 32768 minimum: 301 497s Sep 14 09:48:55 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,ima,evm 497s Sep 14 09:48:55 autopkgtest kernel: landlock: Up and running. 497s Sep 14 09:48:55 autopkgtest kernel: Yama: becoming mindful. 497s Sep 14 09:48:55 autopkgtest kernel: AppArmor: AppArmor initialized 497s Sep 14 09:48:55 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 497s Sep 14 09:48:55 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 497s Sep 14 09:48:55 autopkgtest kernel: POWER9 performance monitor hardware support registered 497s Sep 14 09:48:55 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 497s Sep 14 09:48:55 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 497s Sep 14 09:48:55 autopkgtest kernel: Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level 497s Sep 14 09:48:55 autopkgtest kernel: smp: Bringing up secondary CPUs ... 497s Sep 14 09:48:55 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 497s Sep 14 09:48:55 autopkgtest kernel: numa: Node 0 CPUs: 0-3 497s Sep 14 09:48:55 autopkgtest kernel: Memory: 8202112K/8388608K available (24448K kernel code, 4160K rwdata, 24704K rodata, 8768K init, 1851K bss, 157184K reserved, 0K cma-reserved) 497s Sep 14 09:48:55 autopkgtest kernel: devtmpfs: initialized 497s Sep 14 09:48:55 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 497s Sep 14 09:48:55 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 497s Sep 14 09:48:55 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 497s Sep 14 09:48:55 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 497s Sep 14 09:48:55 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 497s Sep 14 09:48:55 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 497s Sep 14 09:48:55 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 497s Sep 14 09:48:55 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 497s Sep 14 09:48:55 autopkgtest kernel: audit: initializing netlink subsys (disabled) 497s Sep 14 09:48:55 autopkgtest kernel: audit: type=2000 audit(1726307332.044:1): state=initialized audit_enabled=0 res=1 497s Sep 14 09:48:55 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 497s Sep 14 09:48:55 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 497s Sep 14 09:48:55 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 497s Sep 14 09:48:55 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 497s Sep 14 09:48:55 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 497s Sep 14 09:48:55 autopkgtest kernel: cpuidle: using governor ladder 497s Sep 14 09:48:55 autopkgtest kernel: cpuidle: using governor menu 497s Sep 14 09:48:55 autopkgtest kernel: RTAS daemon started 497s Sep 14 09:48:55 autopkgtest kernel: pstore: Using crash dump compression: deflate 497s Sep 14 09:48:55 autopkgtest kernel: pstore: Registered nvram as persistent store backend 497s Sep 14 09:48:55 autopkgtest kernel: EEH: pSeries platform initialized 497s Sep 14 09:48:55 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 497s Sep 14 09:48:55 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 497s Sep 14 09:48:55 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 497s Sep 14 09:48:55 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 497s Sep 14 09:48:55 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 497s Sep 14 09:48:55 autopkgtest kernel: iommu: Default domain type: Translated 497s Sep 14 09:48:55 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 497s Sep 14 09:48:55 autopkgtest kernel: SCSI subsystem initialized 497s Sep 14 09:48:55 autopkgtest kernel: libata version 3.00 loaded. 497s Sep 14 09:48:55 autopkgtest kernel: usbcore: registered new interface driver usbfs 497s Sep 14 09:48:55 autopkgtest kernel: usbcore: registered new interface driver hub 497s Sep 14 09:48:55 autopkgtest kernel: usbcore: registered new device driver usb 497s Sep 14 09:48:55 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 497s Sep 14 09:48:55 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 497s Sep 14 09:48:55 autopkgtest kernel: PTP clock support registered 497s Sep 14 09:48:55 autopkgtest kernel: EDAC MC: Ver: 3.0.0 497s Sep 14 09:48:55 autopkgtest kernel: NetLabel: Initializing 497s Sep 14 09:48:55 autopkgtest kernel: NetLabel: domain hash size = 128 497s Sep 14 09:48:55 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 497s Sep 14 09:48:55 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 497s Sep 14 09:48:55 autopkgtest kernel: mctp: management component transport protocol core 497s Sep 14 09:48:55 autopkgtest kernel: NET: Registered PF_MCTP protocol family 497s Sep 14 09:48:55 autopkgtest kernel: PCI: Probing PCI hardware 497s Sep 14 09:48:55 autopkgtest kernel: PCI host bridge to bus 0000:00 497s Sep 14 09:48:55 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 497s Sep 14 09:48:55 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 497s Sep 14 09:48:55 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 497s Sep 14 09:48:55 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:05.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:06.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:07.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 497s Sep 14 09:48:55 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 497s Sep 14 09:48:55 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 497s Sep 14 09:48:55 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 497s Sep 14 09:48:55 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 497s Sep 14 09:48:55 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:01.0: ibm,query-pe-dma-windows(2026) 800 8000000 20000000 returned 0, lb=80000000 ps=7 wn=1 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:05.0: Adding to iommu group 0 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:06.0: Adding to iommu group 0 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:07.0: Adding to iommu group 0 497s Sep 14 09:48:55 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 497s Sep 14 09:48:55 autopkgtest kernel: PCI: Probing PCI hardware done 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:07.0: vgaarb: setting as boot VGA device 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:07.0: vgaarb: bridge control possible 497s Sep 14 09:48:55 autopkgtest kernel: pci 0000:00:07.0: vgaarb: VGA device added: decodes=io+mem,owns=mem,locks=none 497s Sep 14 09:48:55 autopkgtest kernel: vgaarb: loaded 497s Sep 14 09:48:55 autopkgtest kernel: clocksource: Switched to clocksource timebase 497s Sep 14 09:48:55 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 497s Sep 14 09:48:55 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 497s Sep 14 09:48:55 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 497s Sep 14 09:48:55 autopkgtest kernel: NET: Registered PF_INET protocol family 497s Sep 14 09:48:55 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 497s Sep 14 09:48:55 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 497s Sep 14 09:48:55 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 497s Sep 14 09:48:55 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 497s Sep 14 09:48:55 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 497s Sep 14 09:48:55 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 497s Sep 14 09:48:55 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 497s Sep 14 09:48:55 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 497s Sep 14 09:48:55 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 497s Sep 14 09:48:55 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 497s Sep 14 09:48:55 autopkgtest kernel: NET: Registered PF_XDP protocol family 497s Sep 14 09:48:55 autopkgtest kernel: PCI: CLS 0 bytes, default 128 497s Sep 14 09:48:55 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 497s Sep 14 09:48:55 autopkgtest kernel: Initialise system trusted keyrings 497s Sep 14 09:48:55 autopkgtest kernel: Key type blacklist registered 497s Sep 14 09:48:55 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 497s Sep 14 09:48:55 autopkgtest kernel: zbud: loaded 497s Sep 14 09:48:55 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 497s Sep 14 09:48:55 autopkgtest kernel: fuse: init (API version 7.40) 497s Sep 14 09:48:55 autopkgtest kernel: integrity: Platform Keyring initialized 497s Sep 14 09:48:55 autopkgtest kernel: integrity: Machine keyring initialized 497s Sep 14 09:48:55 autopkgtest kernel: Key type asymmetric registered 497s Sep 14 09:48:55 autopkgtest kernel: Asymmetric key parser 'x509' registered 497s Sep 14 09:48:55 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 497s Sep 14 09:48:55 autopkgtest kernel: io scheduler mq-deadline registered 497s Sep 14 09:48:55 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 497s Sep 14 09:48:55 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 497s Sep 14 09:48:55 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) 497s Sep 14 09:48:55 autopkgtest kernel: virtio-pci 0000:00:03.0: enabling device (0100 -> 0103) 497s Sep 14 09:48:55 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 497s Sep 14 09:48:55 autopkgtest kernel: virtio-pci 0000:00:05.0: enabling device (0100 -> 0103) 497s Sep 14 09:48:55 autopkgtest kernel: virtio-pci 0000:00:06.0: enabling device (0100 -> 0103) 497s Sep 14 09:48:55 autopkgtest kernel: printk: legacy console [hvc0] enabled 497s Sep 14 09:48:55 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 497s Sep 14 09:48:55 autopkgtest kernel: Freeing initrd memory: 51456K 497s Sep 14 09:48:55 autopkgtest kernel: Non-volatile memory driver v1.3 497s Sep 14 09:48:55 autopkgtest kernel: Linux agpgart interface v0.103 497s Sep 14 09:48:55 autopkgtest kernel: loop: module loaded 497s Sep 14 09:48:55 autopkgtest kernel: virtio_blk virtio2: 4/0/0 default/read/poll queues 497s Sep 14 09:48:55 autopkgtest kernel: virtio_blk virtio2: [vda] 209715200 512-byte logical blocks (107 GB/100 GiB) 497s Sep 14 09:48:55 autopkgtest kernel: vda: vda1 vda2 497s Sep 14 09:48:55 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 497s Sep 14 09:48:55 autopkgtest kernel: PPP generic driver version 2.4.2 497s Sep 14 09:48:55 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 497s Sep 14 09:48:55 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 497s Sep 14 09:48:55 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-09-14T09:48:53 UTC (1726307333) 497s Sep 14 09:48:55 autopkgtest kernel: i2c_dev: i2c /dev entries driver 497s Sep 14 09:48:55 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 497s Sep 14 09:48:55 autopkgtest kernel: device-mapper: uevent: version 1.0.3 497s Sep 14 09:48:55 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@lists.linux.dev 497s Sep 14 09:48:55 autopkgtest kernel: pseries_idle_driver registered 497s Sep 14 09:48:55 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 497s Sep 14 09:48:55 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 497s Sep 14 09:48:55 autopkgtest kernel: NET: Registered PF_INET6 protocol family 497s Sep 14 09:48:55 autopkgtest kernel: Segment Routing with IPv6 497s Sep 14 09:48:55 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 497s Sep 14 09:48:55 autopkgtest kernel: NET: Registered PF_PACKET protocol family 497s Sep 14 09:48:55 autopkgtest kernel: Key type dns_resolver registered 497s Sep 14 09:48:55 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 497s Sep 14 09:48:55 autopkgtest kernel: registered taskstats version 1 497s Sep 14 09:48:55 autopkgtest kernel: Loading compiled-in X.509 certificates 497s Sep 14 09:48:55 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: 12384d98c3ac13d6e28ded7f2584c514f41d658f' 497s Sep 14 09:48:55 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 497s Sep 14 09:48:55 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 497s Sep 14 09:48:55 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 497s Sep 14 09:48:55 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 497s Sep 14 09:48:55 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 497s Sep 14 09:48:55 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 497s Sep 14 09:48:55 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 497s Sep 14 09:48:55 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 497s Sep 14 09:48:55 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 497s Sep 14 09:48:55 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 497s Sep 14 09:48:55 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 497s Sep 14 09:48:55 autopkgtest kernel: Demotion targets for Node 0: null 497s Sep 14 09:48:55 autopkgtest kernel: Key type .fscrypt registered 497s Sep 14 09:48:55 autopkgtest kernel: Key type fscrypt-provisioning registered 497s Sep 14 09:48:55 autopkgtest kernel: Key type encrypted registered 497s Sep 14 09:48:55 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 497s Sep 14 09:48:55 autopkgtest kernel: Secure boot mode disabled 497s Sep 14 09:48:55 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 497s Sep 14 09:48:55 autopkgtest kernel: Loading compiled-in module X.509 certificates 497s Sep 14 09:48:55 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: 12384d98c3ac13d6e28ded7f2584c514f41d658f' 497s Sep 14 09:48:55 autopkgtest kernel: ima: Allocated hash algorithm: sha256 497s Sep 14 09:48:55 autopkgtest kernel: Secure boot mode disabled 497s Sep 14 09:48:55 autopkgtest kernel: Trusted boot mode disabled 497s Sep 14 09:48:55 autopkgtest kernel: ima: No architecture policies found 497s Sep 14 09:48:55 autopkgtest kernel: evm: Initialising EVM extended attributes: 497s Sep 14 09:48:55 autopkgtest kernel: evm: security.selinux 497s Sep 14 09:48:55 autopkgtest kernel: evm: security.SMACK64 497s Sep 14 09:48:55 autopkgtest kernel: evm: security.SMACK64EXEC 497s Sep 14 09:48:55 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 497s Sep 14 09:48:55 autopkgtest kernel: evm: security.SMACK64MMAP 497s Sep 14 09:48:55 autopkgtest kernel: evm: security.apparmor 497s Sep 14 09:48:55 autopkgtest kernel: evm: security.ima 497s Sep 14 09:48:55 autopkgtest kernel: evm: security.capability 497s Sep 14 09:48:55 autopkgtest kernel: evm: HMAC attrs: 0x1 497s Sep 14 09:48:55 autopkgtest kernel: SED: plpks not available 497s Sep 14 09:48:55 autopkgtest kernel: clk: Disabling unused clocks 497s Sep 14 09:48:55 autopkgtest kernel: PM: genpd: Disabling unused power domains 497s Sep 14 09:48:55 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 497s Sep 14 09:48:55 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8768K 497s Sep 14 09:48:55 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 497s Sep 14 09:48:55 autopkgtest kernel: Run /init as init process 497s Sep 14 09:48:55 autopkgtest kernel: with arguments: 497s Sep 14 09:48:55 autopkgtest kernel: /init 497s Sep 14 09:48:55 autopkgtest kernel: earlyprintk 497s Sep 14 09:48:55 autopkgtest kernel: with environment: 497s Sep 14 09:48:55 autopkgtest kernel: HOME=/ 497s Sep 14 09:48:55 autopkgtest kernel: TERM=linux 497s Sep 14 09:48:55 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.11.0-7-generic 497s Sep 14 09:48:55 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 497s Sep 14 09:48:55 autopkgtest kernel: random: crng init done 497s Sep 14 09:48:55 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 497s Sep 14 09:48:55 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 1 497s Sep 14 09:48:55 autopkgtest kernel: xhci_hcd 0000:00:02.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010 497s Sep 14 09:48:55 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 497s Sep 14 09:48:55 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2 497s Sep 14 09:48:55 autopkgtest kernel: xhci_hcd 0000:00:02.0: Host supports USB 3.0 SuperSpeed 497s Sep 14 09:48:55 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.11 497s Sep 14 09:48:55 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 497s Sep 14 09:48:55 autopkgtest kernel: usb usb1: Product: xHCI Host Controller 497s Sep 14 09:48:55 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.11.0-7-generic xhci-hcd 497s Sep 14 09:48:55 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:02.0 497s Sep 14 09:48:55 autopkgtest kernel: hub 1-0:1.0: USB hub found 497s Sep 14 09:48:55 autopkgtest kernel: hub 1-0:1.0: 4 ports detected 497s Sep 14 09:48:55 autopkgtest kernel: usb usb2: We don't know the algorithms for LPM for this host, disabling LPM. 497s Sep 14 09:48:55 autopkgtest kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.11 497s Sep 14 09:48:55 autopkgtest kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 497s Sep 14 09:48:55 autopkgtest kernel: usb usb2: Product: xHCI Host Controller 497s Sep 14 09:48:55 autopkgtest kernel: usb usb2: Manufacturer: Linux 6.11.0-7-generic xhci-hcd 497s Sep 14 09:48:55 autopkgtest kernel: usb usb2: SerialNumber: 0000:00:02.0 497s Sep 14 09:48:55 autopkgtest kernel: hub 2-0:1.0: USB hub found 497s Sep 14 09:48:55 autopkgtest kernel: hub 2-0:1.0: 4 ports detected 497s Sep 14 09:48:55 autopkgtest kernel: [drm] Found bochs VGA, ID 0xb0c5. 497s Sep 14 09:48:55 autopkgtest kernel: [drm] Framebuffer size 16384 kB @ 0x200081000000, mmio @ 0x200082000000. 497s Sep 14 09:48:55 autopkgtest kernel: [drm] Found EDID data blob. 497s Sep 14 09:48:55 autopkgtest kernel: [drm] Initialized bochs-drm 1.0.0 for 0000:00:07.0 on minor 0 497s Sep 14 09:48:55 autopkgtest kernel: fbcon: Deferring console take-over 497s Sep 14 09:48:55 autopkgtest kernel: bochs-drm 0000:00:07.0: [drm] fb0: bochs-drmdrmfb frame buffer device 497s Sep 14 09:48:55 autopkgtest kernel: raid6: vpermxor8 gen() 20871 MB/s 497s Sep 14 09:48:55 autopkgtest kernel: raid6: vpermxor4 gen() 17648 MB/s 497s Sep 14 09:48:55 autopkgtest kernel: usb 1-1: new high-speed USB device number 2 using xhci_hcd 497s Sep 14 09:48:55 autopkgtest kernel: raid6: vpermxor2 gen() 15117 MB/s 497s Sep 14 09:48:55 autopkgtest kernel: raid6: vpermxor1 gen() 12703 MB/s 497s Sep 14 09:48:55 autopkgtest kernel: usb 1-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 497s Sep 14 09:48:55 autopkgtest kernel: usb 1-1: New USB device strings: Mfr=1, Product=4, SerialNumber=11 497s Sep 14 09:48:55 autopkgtest kernel: usb 1-1: Product: QEMU USB Keyboard 497s Sep 14 09:48:55 autopkgtest kernel: usb 1-1: Manufacturer: QEMU 497s Sep 14 09:48:55 autopkgtest kernel: usb 1-1: SerialNumber: 68284-pci@800000020000000:02.0-1 497s Sep 14 09:48:55 autopkgtest kernel: hid: raw HID events driver (C) Jiri Kosina 497s Sep 14 09:48:55 autopkgtest kernel: usbcore: registered new interface driver usbhid 497s Sep 14 09:48:55 autopkgtest kernel: usbhid: USB HID core driver 497s Sep 14 09:48:55 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 497s Sep 14 09:48:55 autopkgtest kernel: raid6: altivecx8 gen() 12914 MB/s 497s Sep 14 09:48:55 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 497s Sep 14 09:48:55 autopkgtest kernel: raid6: altivecx4 gen() 11355 MB/s 497s Sep 14 09:48:55 autopkgtest kernel: usb 1-2: new high-speed USB device number 3 using xhci_hcd 497s Sep 14 09:48:55 autopkgtest kernel: raid6: altivecx2 gen() 8917 MB/s 497s Sep 14 09:48:55 autopkgtest kernel: raid6: altivecx1 gen() 6585 MB/s 497s Sep 14 09:48:55 autopkgtest kernel: usb 1-2: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 497s Sep 14 09:48:55 autopkgtest kernel: usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=9 497s Sep 14 09:48:55 autopkgtest kernel: usb 1-2: Product: QEMU USB Mouse 497s Sep 14 09:48:55 autopkgtest kernel: usb 1-2: Manufacturer: QEMU 497s Sep 14 09:48:55 autopkgtest kernel: usb 1-2: SerialNumber: 89126-pci@800000020000000:02.0-2 497s Sep 14 09:48:55 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 497s Sep 14 09:48:55 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 497s Sep 14 09:48:55 autopkgtest kernel: raid6: int64x8 gen() 5396 MB/s 497s Sep 14 09:48:55 autopkgtest kernel: raid6: int64x4 gen() 6187 MB/s 497s Sep 14 09:48:55 autopkgtest kernel: raid6: int64x2 gen() 5033 MB/s 497s Sep 14 09:48:55 autopkgtest kernel: raid6: int64x1 gen() 3890 MB/s 497s Sep 14 09:48:55 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 20871 MB/s 497s Sep 14 09:48:55 autopkgtest kernel: raid6: using intx1 recovery algorithm 497s Sep 14 09:48:55 autopkgtest kernel: xor: measuring software checksum speed 497s Sep 14 09:48:55 autopkgtest kernel: 8regs : 17325 MB/sec 497s Sep 14 09:48:55 autopkgtest kernel: 8regs_prefetch : 13346 MB/sec 497s Sep 14 09:48:55 autopkgtest kernel: 32regs : 12190 MB/sec 497s Sep 14 09:48:55 autopkgtest kernel: 32regs_prefetch : 10510 MB/sec 497s Sep 14 09:48:55 autopkgtest kernel: altivec : 15839 MB/sec 497s Sep 14 09:48:55 autopkgtest kernel: xor: using function: 8regs (17325 MB/sec) 497s Sep 14 09:48:55 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 497s Sep 14 09:48:55 autopkgtest kernel: EXT4-fs (vda1): orphan cleanup on readonly fs 497s Sep 14 09:48:55 autopkgtest kernel: EXT4-fs (vda1): mounted filesystem 8acaf42a-699c-4aab-9932-0a38fe5bb8c4 ro with ordered data mode. Quota mode: none. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Inserted module 'autofs4' 497s Sep 14 09:48:55 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) 497s Sep 14 09:48:55 autopkgtest systemd[1]: Detected virtualization kvm. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Detected architecture ppc64-le. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Hostname set to . 497s Sep 14 09:48:55 autopkgtest systemd[1]: bpf-restrict-fs: BPF LSM hook not enabled in the kernel, BPF LSM not supported. 497s Sep 14 09:48:55 autopkgtest kernel: NET: Registered PF_VSOCK protocol family 497s Sep 14 09:48:55 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. 497s Sep 14 09:48:55 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. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Queued start job for default target graphical.target. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Reached target swap.target - Swaps. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 497s Sep 14 09:48:55 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Sockets. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounting run-lock.mount - Legacy Locks Directory /run/lock... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting modprobe@dm_multipath.service - Load Kernel Module dm_multipath... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 497s Sep 14 09:48:55 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 497s Sep 14 09:48:55 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). 497s Sep 14 09:48:55 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). 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 497s Sep 14 09:48:55 autopkgtest systemd-journald[284]: Collecting audit messages is disabled. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounted run-lock.mount - Legacy Locks Directory /run/lock. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 497s Sep 14 09:48:55 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 497s Sep 14 09:48:55 autopkgtest systemd[1]: modprobe@dm_multipath.service: Deactivated successfully. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished modprobe@dm_multipath.service - Load Kernel Module dm_multipath. 497s Sep 14 09:48:55 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 497s Sep 14 09:48:55 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 497s Sep 14 09:48:55 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 497s Sep 14 09:48:55 autopkgtest systemd-journald[284]: Journal started 497s Sep 14 09:48:55 autopkgtest systemd-journald[284]: Runtime Journal (/run/log/journal/a2415cfb48a9486bb36babfbfaab0895) is 8M, max 81M, 73M free. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 497s Sep 14 09:48:55 autopkgtest kernel: EXT4-fs (vda1): re-mounted 8acaf42a-699c-4aab-9932-0a38fe5bb8c4 r/w. Quota mode: none. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting cloud-init-main.service - Cloud-init: Single Process... 497s Sep 14 09:48:55 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 497s Sep 14 09:48:55 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 497s Sep 14 09:48:55 autopkgtest systemd-journald[284]: Time spent on flushing to /var/log/journal/a2415cfb48a9486bb36babfbfaab0895 is 39.027ms for 461 entries. 497s Sep 14 09:48:55 autopkgtest systemd-journald[284]: System Journal (/var/log/journal/a2415cfb48a9486bb36babfbfaab0895) is 18.9M, max 4G, 3.9G free. 497s Sep 14 09:48:55 autopkgtest systemd-journald[284]: Received client request to flush runtime journal. 497s Sep 14 09:48:55 autopkgtest multipathd[334]: multipathd v0.9.9: start up 497s Sep 14 09:48:55 autopkgtest multipathd[334]: reconfigure: setting up paths and maps 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 497s Sep 14 09:48:55 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 497s Sep 14 09:48:55 autopkgtest apparmor.systemd[353]: Restarting AppArmor 497s Sep 14 09:48:55 autopkgtest apparmor.systemd[353]: Reloading AppArmor profiles 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 497s Sep 14 09:48:55 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 497s Sep 14 09:48:55 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 357 (systemd-binfmt) 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... 497s Sep 14 09:48:55 autopkgtest systemd-tmpfiles[375]: /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 497s Sep 14 09:48:55 autopkgtest systemd-udevd[352]: Using default interface naming scheme 'v255'. 497s Sep 14 09:48:55 autopkgtest kernel: audit: type=1400 audit(1726307335.680:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=380 comm="apparmor_parser" 497s Sep 14 09:48:55 autopkgtest kernel: audit: type=1400 audit(1726307335.680:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=378 comm="apparmor_parser" 497s Sep 14 09:48:55 autopkgtest kernel: audit: type=1400 audit(1726307335.680:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=377 comm="apparmor_parser" 497s Sep 14 09:48:55 autopkgtest kernel: audit: type=1400 audit(1726307335.680:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=379 comm="apparmor_parser" 497s Sep 14 09:48:55 autopkgtest kernel: audit: type=1400 audit(1726307335.684:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=383 comm="apparmor_parser" 497s Sep 14 09:48:55 autopkgtest kernel: audit: type=1400 audit(1726307335.684:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=382 comm="apparmor_parser" 497s Sep 14 09:48:55 autopkgtest kernel: audit: type=1400 audit(1726307335.684:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=384 comm="apparmor_parser" 497s Sep 14 09:48:55 autopkgtest kernel: audit: type=1400 audit(1726307335.684:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="cam" pid=386 comm="apparmor_parser" 497s Sep 14 09:48:55 autopkgtest kernel: audit: type=1400 audit(1726307335.684:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="busybox" pid=385 comm="apparmor_parser" 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. 497s Sep 14 09:48:55 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 497s Sep 14 09:48:55 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 497s Sep 14 09:48:55 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 497s Sep 14 09:48:55 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). 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 497s Sep 14 09:48:55 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 497s Sep 14 09:48:55 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 497s Sep 14 09:48:55 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 497s Sep 14 09:48:55 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 497s Sep 14 09:48:55 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). 497s Sep 14 09:48:55 autopkgtest systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 497s Sep 14 09:48:55 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 497s Sep 14 09:48:55 autopkgtest (udev-worker)[429]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 497s Sep 14 09:48:56 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 497s Sep 14 09:48:56 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 497s Sep 14 09:48:56 autopkgtest systemd[1]: Started cloud-init-main.service - Cloud-init: Single Process. 497s Sep 14 09:48:56 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 497s Sep 14 09:48:56 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 497s Sep 14 09:48:56 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 497s Sep 14 09:48:56 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 497s Sep 14 09:48:56 autopkgtest cloud-init[687]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 running 'init-local' at Sat, 14 Sep 2024 09:48:56 +0000. Up 3.40 seconds. 497s Sep 14 09:48:56 autopkgtest systemd-resolved[398]: Positive Trust Anchors: 497s Sep 14 09:48:56 autopkgtest systemd-resolved[398]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 497s Sep 14 09:48:56 autopkgtest systemd-resolved[398]: 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 497s Sep 14 09:48:56 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 497s Sep 14 09:48:56 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 497s Sep 14 09:48:56 autopkgtest systemd-resolved[398]: Using system hostname 'autopkgtest'. 497s Sep 14 09:48:56 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 497s Sep 14 09:48:56 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 497s Sep 14 09:48:56 autopkgtest dhcpcd[691]: dhcpcd-10.0.8 starting 497s Sep 14 09:48:56 autopkgtest dhcpcd[694]: DUID 00:01:00:01:2e:77:32:31:fa:16:3e:4b:a8:00 497s Sep 14 09:48:56 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 497s Sep 14 09:48:56 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 497s Sep 14 09:48:56 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 497s Sep 14 09:48:56 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 497s Sep 14 09:48:56 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 497s Sep 14 09:48:56 autopkgtest dhcpcd[694]: enp0s1: IAID 3e:5e:d6:b0 497s Sep 14 09:48:56 autopkgtest dhcpcd[694]: enp0s1: rebinding lease of 10.145.227.70 497s Sep 14 09:48:56 autopkgtest dhcpcd[694]: enp0s1: leased 10.145.227.70 for 43200 seconds 497s Sep 14 09:48:56 autopkgtest dhcpcd[694]: enp0s1: adding route to 10.145.227.0/24 497s Sep 14 09:48:56 autopkgtest dhcpcd[694]: enp0s1: adding host route to 169.254.169.254 via 10.145.227.2 497s Sep 14 09:48:56 autopkgtest dhcpcd[694]: enp0s1: adding default route via 10.145.227.1 497s Sep 14 09:48:56 autopkgtest dhcpcd[694]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 497s Sep 14 09:49:04 autopkgtest sh[679]: Completed socket interaction for boot stage local 497s Sep 14 09:49:04 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 497s Sep 14 09:49:04 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 497s Sep 14 09:49:04 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 497s Sep 14 09:49:04 autopkgtest systemd-networkd[724]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 497s Sep 14 09:49:04 autopkgtest systemd-networkd[724]: lo: Link UP 497s Sep 14 09:49:04 autopkgtest systemd-networkd[724]: lo: Gained carrier 497s Sep 14 09:49:04 autopkgtest systemd-networkd[724]: Enumeration completed 497s Sep 14 09:49:04 autopkgtest systemd-networkd[724]: enp0s1: Link UP 497s Sep 14 09:49:04 autopkgtest systemd-networkd[724]: enp0s1: Gained carrier 497s Sep 14 09:49:04 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 497s Sep 14 09:49:04 autopkgtest systemd-timesyncd[401]: Network configuration changed, trying to establish connection. 497s Sep 14 09:49:04 autopkgtest systemd-networkd[724]: enp0s1: Gained IPv6LL 497s Sep 14 09:49:04 autopkgtest systemd[1]: Reached target network.target - Network. 497s Sep 14 09:49:04 autopkgtest systemd-networkd[724]: enp0s1: Link DOWN 497s Sep 14 09:49:04 autopkgtest systemd-networkd[724]: enp0s1: Lost carrier 497s Sep 14 09:49:04 autopkgtest systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... 497s Sep 14 09:49:04 autopkgtest systemd-networkd[724]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 497s Sep 14 09:49:04 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 497s Sep 14 09:49:04 autopkgtest systemd-networkd[724]: enp0s1: Link UP 497s Sep 14 09:49:04 autopkgtest systemd-networkd[724]: enp0s1: Gained carrier 497s Sep 14 09:49:04 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 497s Sep 14 09:49:04 autopkgtest systemd-networkd[724]: enp0s1: DHCPv4 address 10.145.227.70/24, gateway 10.145.227.1 acquired from 10.145.227.1 497s Sep 14 09:49:04 autopkgtest systemd-timesyncd[401]: Network configuration changed, trying to establish connection. 497s Sep 14 09:49:04 autopkgtest systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. 497s Sep 14 09:49:06 autopkgtest systemd-networkd[724]: enp0s1: Gained IPv6LL 497s Sep 14 09:49:06 autopkgtest systemd-timesyncd[401]: Network configuration changed, trying to establish connection. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting cloud-init-network.service - Cloud-init: Network Stage... 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 running 'init' at Sat, 14 Sep 2024 09:49:06 +0000. Up 13.09 seconds. 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 497s Sep 14 09:49+ echo Test WWN should now point to DM 497s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 497s + grep dm 497s :06 autopkgtest cloud-init[687]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | enp0s1 | True | 10.145.227.70 | 255.255.255.0 | global | fa:16:3e:5e:d6:b0 | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | enp0s1 | True | fe80::f816:3eff:fe5e:d6b0/64 | . | link | fa:16:3e:5e:d6:b0 | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | lo | True | ::1/128 | . | host | . | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++++ 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | 0 | 0.0.0.0 | 10.145.227.1 | 0.0.0.0 | enp0s1 | UG | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | 1 | 10.145.227.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | 2 | 10.145.227.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | 3 | 10.145.227.2 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | 4 | 91.189.91.131 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | 5 | 91.189.91.132 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | 6 | 169.254.169.254 | 10.145.227.2 | 255.255.255.255 | enp0s1 | UGH | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: +-------+-------------+---------+-----------+-------+ 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | Route | Destination | Gateway | Interface | Flags | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: +-------+-------------+---------+-----------+-------+ 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | 2 | local | :: | enp0s1 | U | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: | 3 | multicast | :: | enp0s1 | U | 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: ci-info: +-------+-------------+---------+-----------+-------+ 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: 2024-09-14 09:49:06,395 - 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. 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: 2024-09-14 09:49:06,395 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 497s Sep 14 09:49:06 autopkgtest sh[736]: Completed socket interaction for boot stage network 497s Sep 14 09:49:06 autopkgtest systemd[1]: Finished cloud-init-network.service - Cloud-init: Network Stage. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 497s Sep 14 09:49:06 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). 497s Sep 14 09:49:06 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). 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started sysstat-collect.timer - Run system activity accounting tool every 10 minutes. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started sysstat-rotate.timer - Rotate daily system activity data file at midnight. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started sysstat-summary.timer - Generate summary of yesterday's process accounting. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 497s Sep 14 09:49:06 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). 497s Sep 14 09:49:06 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Reached target paths.target - Path Units. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 497s Sep 14 09:49:06 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 497s Sep 14 09:49:06 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). 497s Sep 14 09:49:06 autopkgtest systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). 497s Sep 14 09:49:06 autopkgtest systemd[1]: Reached target ssh-access.target - SSH Access Available. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Reached target basic.target - Basic System. 497s Sep 14 09:49:06 autopkgtest systemd[1]: System is tainted: unmerged-bin 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 497s Sep 14 09:49:06 autopkgtest (sh)[771]: autopkgtest@hvc1.service: Failed to set up standard input: No such device 497s Sep 14 09:49:06 autopkgtest (sh)[771]: autopkgtest@hvc1.service: Failed at step STDIN spawning /bin/sh: No such device 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 497s Sep 14 09:49:06 autopkgtest (sh)[772]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 497s Sep 14 09:49:06 autopkgtest (sh)[772]: autopkgtest@ttyS1.service: Failed at step STDIN spawning /bin/sh: Input/output error 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 497s Sep 14 09:49:06 autopkgtest (cron)[774]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 497s Sep 14 09:49:06 autopkgtest cron[774]: (CRON) INFO (pidfile fd = 3) 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 497s Sep 14 09:49:06 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). 497s Sep 14 09:49:06 autopkgtest cron[774]: (CRON) INFO (Running @reboot jobs) 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 497s Sep 14 09:49:06 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 497s Sep 14 09:49:06 autopkgtest systemd[1]: opal_errd.service - opal_errd (PowerNV platform error handling) Service was skipped because of an unmet condition check (ConditionVirtualization=false). 497s Sep 14 09:49:06 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). 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting sysstat.service - Resets System Activity Logs... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 497s Sep 14 09:49:06 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). 497s Sep 14 09:49:06 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 497s Sep 14 09:49:06 autopkgtest dbus-daemon[778]: [system] AppArmor D-Bus mediation is enabled 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 497s Sep 14 09:49:06 autopkgtest systemd[1]: autopkgtest@hvc1.service: Deactivated successfully. 497s Sep 14 09:49:06 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 497s Sep 14 09:49:06 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 497s Sep 14 09:49:06 autopkgtest udisksd[794]: udisks daemon version 2.10.1 starting 497s Sep 14 09:49:06 autopkgtest systemd[1]: Finished sysstat.service - Resets System Activity Logs. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 497s Sep 14 09:49:06 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 497s Sep 14 09:49:06 autopkgtest rngd[845]: rngd 2.4 starting up... 497s Sep 14 09:49:06 autopkgtest rngd[845]: entropy feed to the kernel ready 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 497s Sep 14 09:49:06 autopkgtest systemd-logind[792]: New seat seat0. 497s Sep 14 09:49:06 autopkgtest systemd-logind[792]: Watching system buttons on /dev/input/event0 (QEMU QEMU USB Keyboard) 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 497s Sep 14 09:49:06 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 running 'modules:config' at Sat, 14 Sep 2024 09:49:06 +0000. Up 13.53 seconds. 497s Sep 14 09:49:06 autopkgtest udisksd[794]: Acquired the name org.freedesktop.UDisks2 on the system message bus 497s Sep 14 09:49:06 autopkgtest kernel: kauditd_printk_skb: 110 callbacks suppressed 497s Sep 14 09:49:06 autopkgtest kernel: audit: type=1400 audit(1726307346.812:121): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=862 comm="apparmor_parser" 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 497s Sep 14 09:49:06 autopkgtest sh[777]: Completed socket interaction for boot stage config 497s Sep 14 09:49:06 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 497s Sep 14 09:49:06 autopkgtest rsyslogd[876]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2406.0] 497s Sep 14 09:49:06 autopkgtest rsyslogd[876]: rsyslogd's groupid changed to 102 497s Sep 14 09:49:06 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 497s Sep 14 09:49:06 autopkgtest rsyslogd[876]: rsyslogd's userid changed to 102 497s Sep 14 09:49:06 autopkgtest rsyslogd[876]: [origin software="rsyslogd" swVersion="8.2406.0" x-pid="876" x-info="https://www.rsyslog.com"] start 497s Sep 14 09:49:06 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 497s Sep 14 09:49:06 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 497s Sep 14 09:49:06 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 497s Sep 14 09:49:06 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 497s Sep 14 09:49:06 autopkgtest cloud-init[687]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 running 'modules:final' at Sat, 14 Sep 2024 09:49:06 +0000. Up 13.81 seconds. 497s Sep 14 09:49:07 autopkgtest cloud-init[687]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 finished at Sat, 14 Sep 2024 09:49:07 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 13.89 seconds 497s Sep 14 09:49:07 autopkgtest sh[887]: Completed socket interaction for boot stage final 497s Sep 14 09:49:07 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 497s Sep 14 09:49:07 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 497s Sep 14 09:49:07 autopkgtest systemd[1]: Startup finished in 1.834s (kernel) + 12.064s (userspace) = 13.899s. 497s Sep 14 09:49:07 autopkgtest kernel: fbcon: Taking over console 497s Sep 14 09:49:07 autopkgtest kernel: Console: switching to colour frame buffer device 128x48 497s Sep 14 09:49:07 autopkgtest systemd[1]: cloud-init-main.service: Deactivated successfully. 497s Sep 14 09:49:07 autopkgtest systemd[1]: cloud-init-main.service: Unit process 686 (sh) remains running after unit stopped. 497s Sep 14 09:49:07 autopkgtest systemd[1]: cloud-init-main.service: Consumed 1.481s CPU time, 108.2M memory peak. 497s Sep 14 09:49:07 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 497s Sep 14 09:49:07 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 497s Sep 14 09:49:07 autopkgtest sshd[938]: Server listening on :: port 22. 497s Sep 14 09:49:07 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 497s Sep 14 09:49:07 autopkgtest sshd[940]: Accepted publickey for ubuntu from 10.136.6.201 port 55634 ssh2: RSA SHA256:YaYyKWTl9zFJEBK5G3u+MRj3WPJt+vEplFd0J96PUBw 497s Sep 14 09:49:07 autopkgtest sshd[940]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 497s Sep 14 09:49:07 autopkgtest sshd[940]: pam_systemd(sshd:session): New sd-bus connection (system-bus-pam-systemd-940) opened. 497s Sep 14 09:49:07 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 497s Sep 14 09:49:07 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 497s Sep 14 09:49:07 autopkgtest systemd-logind[792]: New session 1 of user ubuntu. 497s Sep 14 09:49:07 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 497s Sep 14 09:49:07 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 497s Sep 14 09:49:08 autopkgtest (systemd)[944]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 497s Sep 14 09:49:08 autopkgtest systemd-logind[792]: New session 2 of user ubuntu. 497s Sep 14 09:49:08 autopkgtest systemd[944]: Queued start job for default target default.target. 497s Sep 14 09:49:08 autopkgtest systemd[944]: Created slice app.slice - User Application Slice. 497s Sep 14 09:49:08 autopkgtest systemd[944]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 497s Sep 14 09:49:08 autopkgtest systemd[944]: Reached target paths.target - Paths. 497s Sep 14 09:49:08 autopkgtest systemd[944]: Reached target timers.target - Timers. 497s Sep 14 09:49:08 autopkgtest systemd[944]: Starting dbus.socket - D-Bus User Message Bus Socket... 497s Sep 14 09:49:08 autopkgtest systemd[944]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 497s Sep 14 09:49:08 autopkgtest systemd[944]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 497s Sep 14 09:49:08 autopkgtest systemd[944]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 497s Sep 14 09:49:08 autopkgtest systemd[944]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 497s Sep 14 09:49:08 autopkgtest systemd[944]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 497s Sep 14 09:49:08 autopkgtest systemd[944]: Listening on keyboxd.socket - GnuPG public key management service. 497s Sep 14 09:49:08 autopkgtest systemd[944]: Listening on dbus.socket - D-Bus User Message Bus Socket. 497s Sep 14 09:49:08 autopkgtest systemd[944]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 497s Sep 14 09:49:08 autopkgtest systemd[944]: Reached target sockets.target - Sockets. 497s Sep 14 09:49:08 autopkgtest systemd[944]: Reached target basic.target - Basic System. 497s Sep 14 09:49:08 autopkgtest systemd[944]: Reached target default.target - Main User Target. 497s Sep 14 09:49:08 autopkgtest systemd[944]: Startup finished in 184ms. 497s Sep 14 09:49:08 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 497s Sep 14 09:49:08 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 497s Sep 14 09:49:08 autopkgtest sudo[972]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 497s Sep 14 09:49:08 autopkgtest sudo[972]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:08 autopkgtest sudo[972]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:08 autopkgtest sudo[977]: 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' 497s Sep 14 09:49:08 autopkgtest sudo[977]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:08 autopkgtest sudo[977]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:09 autopkgtest sudo[989]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.HKOtCD 497s Sep 14 09:49:09 autopkgtest sudo[989]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:09 autopkgtest sudo[989]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:09 autopkgtest sudo[999]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.HKOtCD/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.HKOtCD/autopkgtest-reboot' 497s Sep 14 09:49:09 autopkgtest sudo[999]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:09 autopkgtest sudo[999]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:09 autopkgtest sudo[1011]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.HKOtCD/autopkgtest-reboot 497s Sep 14 09:49:09 autopkgtest sudo[1011]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:09 autopkgtest sudo[1011]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:09 autopkgtest sudo[1021]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.HKOtCD/autopkgtest-reboot /tmp/autopkgtest-reboot 497s Sep 14 09:49:09 autopkgtest sudo[1021]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:09 autopkgtest sudo[1021]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:09 autopkgtest sudo[1031]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.HKOtCD/autopkgtest-reboot /sbin/autopkgtest-reboot 497s Sep 14 09:49:09 autopkgtest sudo[1031]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:09 autopkgtest sudo[1031]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:10 autopkgtest sudo[1041]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.HKOtCD 497s Sep 14 09:49:10 autopkgtest sudo[1041]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:10 autopkgtest sudo[1041]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:10 autopkgtest sudo[1051]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.HKOtCD/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.HKOtCD/autopkgtest-reboot-prepare' 497s Sep 14 09:49:10 autopkgtest sudo[1051]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:10 autopkgtest sudo[1051]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:10 autopkgtest sudo[1063]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.HKOtCD/autopkgtest-reboot-prepare 497s Sep 14 09:49:10 autopkgtest sudo[1063]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:10 autopkgtest sudo[1063]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:10 autopkgtest sudo[1073]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.HKOtCD/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 497s Sep 14 09:49:10 autopkgtest sudo[1073]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:10 autopkgtest sudo[1073]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:10 autopkgtest sudo[1083]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 497s Sep 14 09:49:10 autopkgtest sudo[1083]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:10 autopkgtest sudo[1083]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:11 autopkgtest sudo[1093]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 497s Sep 14 09:49:11 autopkgtest sudo[1093]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:11 autopkgtest sudo[1093]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:11 autopkgtest sudo[1103]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.HKOtCD/testbed-packages' 497s Sep 14 09:49:11 autopkgtest sudo[1103]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:11 autopkgtest sudo[1103]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:11 autopkgtest sudo[1114]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.HKOtCD/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.HKOtCD/autopkgtest-reboot' 497s Sep 14 09:49:11 autopkgtest sudo[1135]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:11 autopkgtest sudo[1135]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:12 autopkgtest sudo[1149]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.HKOtCD/autopkgtest-reboot 497s Sep 14 09:49:12 autopkgtest sudo[1149]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:12 autopkgtest sudo[1149]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:12 autopkgtest sudo[1159]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.HKOtCD/autopkgtest-reboot /tmp/autopkgtest-reboot 497s Sep 14 09:49:12 autopkgtest sudo[1159]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:12 autopkgtest sudo[1159]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:12 autopkgtest sudo[1169]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.HKOtCD/autopkgtest-reboot /sbin/autopkgtest-reboot 497s Sep 14 09:49:12 autopkgtest sudo[1169]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:12 autopkgtest sudo[1169]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:12 autopkgtest sudo[1179]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.HKOtCD 497s Sep 14 09:49:12 autopkgtest sudo[1179]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:12 autopkgtest sudo[1179]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:12 autopkgtest sudo[1189]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.HKOtCD/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.HKOtCD/autopkgtest-reboot-prepare' 497s Sep 14 09:49:12 autopkgtest sudo[1189]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:12 autopkgtest sudo[1189]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:12 autopkgtest sudo[1201]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.HKOtCD/autopkgtest-reboot-prepare 497s Sep 14 09:49:12 autopkgtest sudo[1201]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:12 autopkgtest sudo[1201]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:13 autopkgtest sudo[1211]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.HKOtCD/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 497s Sep 14 09:49:13 autopkgtest sudo[1211]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:13 autopkgtest sudo[1211]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:13 autopkgtest sudo[1221]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 497s Sep 14 09:49:13 autopkgtest sudo[1221]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:13 autopkgtest sudo[1221]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:13 autopkgtest sudo[1231]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 497s Sep 14 09:49:13 autopkgtest sudo[1231]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:13 autopkgtest sudo[1231]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:13 autopkgtest sudo[1240]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.HKOtCD 497s Sep 14 09:49:13 autopkgtest sudo[1240]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:13 autopkgtest sudo[1240]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:13 autopkgtest sudo[1250]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.HKOtCD/2-autopkgtest-satdep.deb' 497s Sep 14 09:49:13 autopkgtest sudo[1250]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:14 autopkgtest sudo[1250]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:14 autopkgtest sudo[1261]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.HKOtCD/2-autopkgtest-satdep.deb 497s Sep 14 09:49:14 autopkgtest sudo[1261]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:14 autopkgtest sudo[1261]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:14 autopkgtest sudo[1271]: 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.HKOtCD/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' 497s Sep 14 09:49:14 autopkgtest sudo[1271]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:19 autopkgtest systemd[1]: Reload requested from client PID 1511 ('systemctl') (unit session-1.scope)... 497s Sep 14 09:49:19 autopkgtest systemd[1]: Reloading... 497s Sep 14 09:49:19 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. 497s Sep 14 09:49:19 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. 497s Sep 14 09:49:19 autopkgtest systemd[1]: Reloading finished in 239 ms. 497s Sep 14 09:49:19 autopkgtest systemd[1]: Reload requested from client PID 1560 ('systemctl') (unit session-1.scope)... 497s Sep 14 09:49:19 autopkgtest systemd[1]: Reloading... 497s Sep 14 09:49:19 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. 497s Sep 14 09:49:19 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. 497s Sep 14 09:49:19 autopkgtest systemd[1]: Reloading finished in 287 ms. 497s Sep 14 09:49:20 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 497s Sep 14 09:49:20 autopkgtest tgtd[1605]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 497s Sep 14 09:49:20 autopkgtest tgtd[1605]: tgtd: work_timer_start(146) use timer_fd based scheduler 497s Sep 14 09:49:20 autopkgtest tgtd[1605]: tgtd: bs_init(387) use signalfd notification 497s Sep 14 09:49:20 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 497s Sep 14 09:49:20 autopkgtest systemd[1]: Reload requested from client PID 1633 ('systemctl') (unit session-1.scope)... 497s Sep 14 09:49:20 autopkgtest systemd[1]: Reloading... 497s Sep 14 09:49:20 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. 497s Sep 14 09:49:20 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. 497s Sep 14 09:49:20 autopkgtest systemd[1]: Reloading finished in 276 ms. 497s Sep 14 09:49:20 autopkgtest systemd[1]: Reload requested from client PID 1675 ('systemctl') (unit session-1.scope)... 497s Sep 14 09:49:20 autopkgtest systemd[1]: Reloading... 497s Sep 14 09:49:20 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. 497s Sep 14 09:49:20 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. 497s Sep 14 09:49:20 autopkgtest systemd[1]: Reloading finished in 199 ms. 497s Sep 14 09:49:21 autopkgtest systemd[1]: Reload requested from client PID 1720 ('systemctl') (unit session-1.scope)... 497s Sep 14 09:49:21 autopkgtest systemd[1]: Reloading... 497s Sep 14 09:49:21 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. 497s Sep 14 09:49:21 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. 497s Sep 14 09:49:21 autopkgtest systemd[1]: Reloading finished in 247 ms. 497s Sep 14 09:49:21 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 497s Sep 14 09:49:21 autopkgtest systemd[1]: Reload requested from client PID 1770 ('systemctl') (unit session-1.scope)... 497s Sep 14 09:49:21 autopkgtest systemd[1]: Reloading... 497s Sep 14 09:49:21 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. 497s Sep 14 09:49:21 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. 497s Sep 14 09:49:22 autopkgtest systemd[1]: Reloading finished in 293 ms. 497s Sep 14 09:49:22 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 497s Sep 14 09:49:22 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 497s Sep 14 09:49:22 autopkgtest systemd[1]: Reload requested from client PID 1824 ('systemctl') (unit session-1.scope)... 497s Sep 14 09:49:22 autopkgtest systemd[1]: Reloading... 497s Sep 14 09:49:22 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. 497s Sep 14 09:49:22 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. 497s Sep 14 09:49:22 autopkgtest systemd[1]: Reloading finished in 278 ms. 497s Sep 14 09:49:33 autopkgtest sudo[1271]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:33 autopkgtest sudo[5694]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 497s Sep 14 09:49:33 autopkgtest sudo[5694]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:33 autopkgtest sudo[5694]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:34 autopkgtest sudo[5704]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 497s Sep 14 09:49:34 autopkgtest sudo[5704]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:34 autopkgtest sudo[5704]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:34 autopkgtest sudo[5714]: 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 497s Sep 14 09:49:34 autopkgtest sudo[5714]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:35 autopkgtest sudo[5714]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:35 autopkgtest sudo[5727]: 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 497s Sep 14 09:49:35 autopkgtest sudo[5727]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:35 autopkgtest sudo[5727]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:36 autopkgtest sudo[5739]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 497s Sep 14 09:49:36 autopkgtest sudo[5739]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:35 autopkgtest systemd-timesyncd[401]: Contacted time server 185.125.190.56:123 (ntp.ubuntu.com). 497s Sep 14 09:49:35 autopkgtest systemd-journald[284]: Time jumped backwards, rotating. 497s Sep 14 09:49:35 autopkgtest systemd-timesyncd[401]: Initial clock synchronization to Sat 2024-09-14 09:49:35.551515 UTC. 497s Sep 14 09:49:35 autopkgtest systemd-resolved[398]: Clock change detected. Flushing caches. 497s Sep 14 09:49:35 autopkgtest sudo[5739]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:36 autopkgtest sudo[5753]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 497s Sep 14 09:49:36 autopkgtest sudo[5753]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:36 autopkgtest sudo[5753]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:36 autopkgtest sudo[5763]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.HKOtCD/tgtbasedmpaths-packages.all' 497s Sep 14 09:49:36 autopkgtest sudo[5763]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 497s Sep 14 09:49:36 autopkgtest sudo[5763]: pam_unix(sudo:session): session closed for user root 497s Sep 14 09:49:36 autopkgtest sudo[5774]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 501s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 501s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 501s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 501s latency : target=0, window=0, percentile=100.00%, depth=1 501s 501s Run status group 0 (all jobs): 501s WRITE: bw=149MiB/s (156MB/s), 149MiB/s-149MiB/s (156MB/s-156MB/s), io=87.5MiB (91.8MB), run=588-588msec 501s 501s Disk stats (read/write): 501s dm-0: ios=1/865, sectors=8/123256, merge=0/0, ticks=0/422, in_queue=472, util=73.10%, aggrios=0/350, aggsectors=2/48018, aggrmerge=0/0, aggrticks=12/135, aggrin_queue=147, aggrutil=71.49% 501s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 501s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 501s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 501s sda: ios=2/1403, sectors=8/192072, merge=0/0, ticks=51/540, in_queue=590, util=71.49% 501s + echo Starting the path changes in background 501s + date +Pre FIO %H:%M:%S.%N 501s Starting the path changes in background 501s + fio --max-jobs=4 /tmp/autopkgtest.HKOtCD/tgtbasedmpaths-artifacts/path-change-check.fio 501s Pre FIO 09:49:47.801599217 501s 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 501s fio-3.37 501s Starting 1 thread 682s 682s verify-phase: (groupid=0, jobs=1): err= 0: pid=6114: Sat Sep 14 09:52:48 2024 682s read: IOPS=5282, BW=330MiB/s (346MB/s)(58.0GiB/180001msec) 682s clat (usec): min=72, max=64293, avg=162.61, stdev=165.97 682s lat (usec): min=72, max=64293, avg=162.74, stdev=165.97 682s clat percentiles (usec): 682s | 1.00th=[ 93], 5.00th=[ 105], 10.00th=[ 114], 20.00th=[ 126], 682s | 30.00th=[ 137], 40.00th=[ 147], 50.00th=[ 157], 60.00th=[ 165], 682s | 70.00th=[ 178], 80.00th=[ 192], 90.00th=[ 212], 95.00th=[ 233], 682s | 99.00th=[ 289], 99.50th=[ 338], 99.90th=[ 898], 99.95th=[ 1045], 682s | 99.99th=[ 1565] 682s bw ( KiB/s): min=172288, max=477312, per=100.00%, avg=338457.18, stdev=44744.11, samples=359 682s iops : min= 2692, max= 7458, avg=5288.34, stdev=699.14, samples=359 682s lat (usec) : 100=2.88%, 250=94.26%, 500=2.59%, 750=0.09%, 1000=0.11% 682s lat (msec) : 2=0.06%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01% 682s lat (msec) : 100=0.01% 682s cpu : usr=15.06%, sys=7.77%, ctx=950983, majf=0, minf=1 682s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 682s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 682s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 682s issued rwts: total=950864,0,0,0 short=0,0,0,0 dropped=0,0,0,0 682s latency : target=0, window=0, percentile=100.00%, depth=1 682s 682s Run status group 0 (all jobs): 682s READ: bw=330MiB/s (346MB/s), 330MiB/s-330MiB/s (346MB/s-346MB/s), io=58.0GiB (62.3GB), run=180001-180001msec 682s 682s Disk stats (read/write): 682s dm-0: ios=951114/11, sectors=121651384/168, merge=0/10, ticks=152317/79, in_queue=152468, util=79.14%, aggrios=66805/2, aggsectors=8543950/42, aggrmerge=0/0, aggrticks=9779/1, aggrin_queue=9780, aggrutil=70.86% 682s sdd: ios=109177/0, sectors=13964672/0, merge=0/0, ticks=15594/0, in_queue=15594, util=27.85% 682s sdb: ios=53703/0, sectors=6864696/0, merge=0/0, ticks=7911/0, in_queue=7911, util=35.91% 682s sdc: ios=51757/0, sectors=6620288/0, merge=0/0, ticks=7901/0, in_queue=7901, util=23.80% 682s sda: ios=52586/11, sectors=6726144/168, merge=0/0, ticks=7711/4, in_queue=7715, util=70.86% 682s + date +Post FIO %H:%M:%S.%N 682s + echo FIO verify test with changing paths - OK 682s + echo Report log of background activity 682s + cat /tmp/autopkgtest.HKOtCD/tgtbasedmpaths-artifacts/test-background.log 682s Post FIO 09:52:48.140139198 682s FIO verify test with changing paths - OK 682s Report log of background activity 682s + iscsiadm --mode session 682s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s + sleep 10s 682s + date +MP report (expect 4) %H:%M:%S.%N 682s MP report (expect 4) 09:49:57.808795239 682s + multipath -ll 682s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 682s size=100M features='0' hwhandler='0' wp=rw 682s |-+- policy='service-time 0' prio=1 status=active 682s | `- 0:0:0:1 sda 8:0 active ready running 682s |-+- policy='service-time 0' prio=1 status=enabled 682s | `- 1:0:0:1 sdb 8:16 active ready running 682s |-+- policy='service-time 0' prio=1 status=enabled 682s | `- 2:0:0:1 sdc 8:32 active ready running 682s `-+- policy='service-time 0' prio=1 status=enabled 682s `- 3:0:0:1 sdd 8:48 active ready running 682s + date +UN-plug path 1 %H:%M:%S.%N 682s UN-plug path 1 09:49:57.841971708 682s + iscsiadm --mode session -r 1 -u 682s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 682s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 682s + iscsiadm --mode session 682s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s + sleep 10s 682s + date +MP report (expect 3) %H:%M:%S.%N 682s MP report (expect 3) 09:50:07.911279741 682s + multipath -ll 682s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 682s size=100M features='0' hwhandler='0' wp=rw 682s |-+- policy='service-time 0' prio=1 status=active 682s | `- 1:0:0:1 sdb 8:16 active ready running 682s |-+- policy='service-time 0' prio=1 status=enabled 682s | `- 2:0:0:1 sdc 8:32 active ready running 682s `-+- policy='service-time 0' prio=1 status=enabled 682s `- 3:0:0:1 sdd 8:48 active ready running 682s + date +UN-plug path 2 %H:%M:%S.%N 682s UN-plug path 2 09:50:07.934057674 682s + iscsiadm --mode session -r 2 -u 682s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 682s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 682s + iscsiadm --mode session 682s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s + sleep 10s 682s + date +MP report (expect 2) %H:%M:%S.%N 682s MP report (expect 2) 09:50:18.004581959 682s + multipath -ll 682s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 682s size=100M features='0' hwhandler='0' wp=rw 682s |-+- policy='service-time 0' prio=1 status=active 682s | `- 2:0:0:1 sdc 8:32 active ready running 682s `-+- policy='service-time 0' prio=1 status=enabled 682s `- 3:0:0:1 sdd 8:48 active ready running 682s + date +UN-plug path 3 %H:%M:%S.%N 682s UN-plug path 3 09:50:18.022681970 682s + iscsiadm --mode session -r 3 -u 682s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 682s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 682s + iscsiadm --mode session 682s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s + sleep 10s 682s + date +MP report (expect 1) %H:%M:%S.%N 682s MP report (expect 1) 09:50:28.135512087 682s + multipath -ll 682s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 682s size=100M features='0' hwhandler='0' wp=rw 682s `-+- policy='service-time 0' prio=1 status=active 682s `- 3:0:0:1 sdd 8:48 active ready running 682s + date +Add paths 5/6/7/8 %H:%M:%S.%N 682s Add paths 5/6/7/8 09:50:28.152605061 682s + iscsiadm --mode session -r 4 --op new 682s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 682s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 682s + iscsiadm --mode session -r 4 --op new 682s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 682s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 682s + iscsiadm --mode session -r 4 --op new 682s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 682s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 682s + iscsiadm --mode session -r 4 --op new 682s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 682s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 682s + iscsiadm --mode session 682s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s + sleep 10s 682s + date +MP report (expect 5) %H:%M:%S.%N 682s MP report (expect 5) 09:50:38.247281778 682s + multipath -ll 682s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 682s size=100M features='0' hwhandler='0' wp=rw 682s |-+- policy='service-time 0' prio=1 status=active 682s | `- 3:0:0:1 sdd 8:48 active ready running 682s |-+- policy='service-time 0' prio=1 status=enabled 682s | `- 0:0:0:1 sda 8:0 active ready running 682s |-+- policy='service-time 0' prio=1 status=enabled 682s | `- 1:0:0:1 sdb 8:16 active ready running 682s |-+- policy='service-time 0' prio=1 status=enabled 682s | `- 2:0:0:1 sdc 8:32 active ready running 682s `-+- policy='service-time 0' prio=1 status=enabled 682s `- 4:0:0:1 sde 8:64 active ready running 682s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 682s UN-plug multiple paths 4/7/8 09:50:38.276255907 682s + iscsiadm --mode session -r 4 -u 682s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 682s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 682s + iscsiadm --mode session -r 7 -u 682s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 682s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 682s + iscsiadm --mode session -r 8 -u 682s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 682s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 682s + iscsiadm --mode session 682s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 682s + sleep 10s 682s + date +Restart multipath daemon %H:%M:%S.%N 682s Restart multipath daemon 09:50:48.594549008 682s + systemctl restart multipathd 682s + sleep 10s 682s + date +Final background report (expect 2) %H:%M:%S.%N 682s Final background report (expect 2) 09:50:58.697736798 682s + multipath -ll 682s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 682s size=100M features='0' hwhandler='0' wp=rw 682s |-+- policy='service-time 0' prio=1 status=active 682s | `- 0:0:0:1 sda 8:0 active ready running 682s `-+- policy='service-time 0' prio=1 status=enabled 682s `- 1:0:0:1 sdb 8:16 active ready running 682s Final stats 682s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 682s iSCSI SNMP: 682s txdata_octets: 32721192 682s rxdata_octets: 44652109328 682s noptx_pdus: 0 682s scsicmd_pdus: 681424 682s tmfcmd_pdus: 0 682s login_pdus: 0 682s text_pdus: 0 682s dataout_pdus: 0 682s logout_pdus: 0 682s snack_pdus: 0 682s noprx_pdus: 0 682s scsirsp_pdus: 681424 682s tmfrsp_pdus: 0 682s textrsp_pdus: 0 682s datain_pdus: 681389 682s logoutrsp_pdus: 0 682s r2t_pdus: 0 682s async_pdus: 0 682s rjt_pdus: 0 682s digest_err: 0 682s timeout_err: 0 682s iSCSI Extended: 682s tx_sendpage_failures: 0 682s rx_discontiguous_hdr: 0 682s eh_abort_cnt: 0 682s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 682s iSCSI SNMP: 682s txdata_octets: 6744 682s rxdata_octets: 1515328 682s noptx_pdus: 0 682s scsicmd_pdus: 111 682s tmfcmd_pdus: 0 682s login_pdus: 0 682s text_pdus: 0 682s dataout_pdus: 0 682s logout_pdus: 0 682s snack_pdus: 0 682s noprx_pdus: 0 682s scsirsp_pdus: 111 682s tmfrsp_pdus: 0 682s textrsp_pdus: 0 682s datain_pdus: 87 682s logoutrsp_pdus: 0 682s r2t_pdus: 0 682s async_pdus: 0 682s rjt_pdus: 0 682s digest_err: 0 682s timeout_err: 0 682s iSCSI Extended: 682s tx_sendpage_failures: 0 682s rx_discontiguous_hdr: 0 682s eh_abort_cnt: 0 682s Sep 13 17:26:08 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 682s Sep 13 17:26:08 ubuntu multipathd[356]: multipathd v0.9.9: start up 682s Sep 13 17:26:08 ubuntu multipathd[356]: reconfigure: setting up paths and maps 682s Sep 13 17:26:08 ubuntu multipathd[356]: _check_bindings_file: failed to read header from /etc/multipath/bindings 682s Sep 13 17:26:08 ubuntu multipathd[356]: updated bindings file /etc/multipath/bindings 682s Sep 13 17:26:08 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 682s Sep 13 17:28:50 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i multipathd[356]: multipathd: shut down 682s Sep 13 17:28:50 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 682s Sep 13 17:28:50 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 682s Sep 13 17:28:50 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 682s -- Boot 4a444738c451454fa296335a9e1de230 -- 682s Sep 13 17:29:02 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 682s Sep 13 17:29:02 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i multipathd[297]: multipathd v0.9.9: start up 682s Sep 13 17:29:02 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i multipathd[297]: reconfigure: setting up paths and maps 682s Sep 13 17:29:02 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 682s Sep 13 17:29:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 682s Sep 13 17:29:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i multipathd[297]: multipathd: shut down 682s Sep 13 17:29:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 682s Sep 13 17:29:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 682s -- Boot 65986270febb48039521b0cb6ebd3676 -- 682s Sep 14 09:46:49 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 682s Sep 14 09:46:49 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i multipathd[329]: multipathd v0.9.9: start up 682s Sep 14 09:46:49 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i multipathd[329]: reconfigure: setting up paths and maps 682s Sep 14 09:46:49 auto-syncubuntu-oracular-daily-ppc64el-server-20240912-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 682s Sep 14 09:48:42 autopkgtest multipathd[329]: multipathd: shut down 682s Sep 14 09:48:42 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 682s Sep 14 09:48:42 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 682s Sep 14 09:48:42 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 682s -- Boot 622ccb59554f4d7db73bc0e35fb0dd0a -- 682s Sep 14 09:48:55 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 682s Sep 14 09:48:55 autopkgtest multipathd[334]: multipathd v0.9.9: start up 682s Sep 14 09:48:55 autopkgtest multipathd[334]: reconfigure: setting up paths and maps 682s Sep 14 09:48:55 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 682s Sep 14 09:49:38 autopkgtest multipathd[334]: updated bindings file /etc/multipath/bindings 682s Sep 14 09:49:38 autopkgtest multipathd[334]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 682s Sep 14 09:49:38 autopkgtest multipathd[334]: sda [8:0]: path added to devmap mpatha 682s Sep 14 09:49:38 autopkgtest multipathd[334]: mpatha: performing delayed actions 682s Sep 14 09:49:38 autopkgtest multipathd[334]: 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] 682s Sep 14 09:49:57 autopkgtest multipathd[334]: 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] 682s Sep 14 09:49:57 autopkgtest multipathd[334]: check_removed_paths: sda: freeing path in removed state 682s Sep 14 09:49:57 autopkgtest multipathd[334]: 8:0: path removed from map mpatha 682s Sep 14 09:50:07 autopkgtest multipathd[334]: 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] 682s Sep 14 09:50:08 autopkgtest multipathd[334]: check_removed_paths: sdb: freeing path in removed state 682s Sep 14 09:50:08 autopkgtest multipathd[334]: 8:16: path removed from map mpatha 682s Sep 14 09:50:18 autopkgtest multipathd[334]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 682s Sep 14 09:50:18 autopkgtest multipathd[334]: check_removed_paths: sdc: freeing path in removed state 682s Sep 14 09:50:18 autopkgtest multipathd[334]: 8:32: path removed from map mpatha 682s Sep 14 09:50:28 autopkgtest multipathd[334]: 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] 682s Sep 14 09:50:28 autopkgtest multipathd[334]: sda [8:0]: path added to devmap mpatha 682s Sep 14 09:50:28 autopkgtest multipathd[334]: 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] 682s Sep 14 09:50:28 autopkgtest multipathd[334]: sdb [8:16]: path added to devmap mpatha 682s Sep 14 09:50:28 autopkgtest multipathd[334]: 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] 682s Sep 14 09:50:28 autopkgtest multipathd[334]: sdc [8:32]: path added to devmap mpatha 682s Sep 14 09:50:28 autopkgtest multipathd[334]: 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] 682s Sep 14 09:50:28 autopkgtest multipathd[334]: sde [8:64]: path added to devmap mpatha 682s Sep 14 09:50:38 autopkgtest multipathd[334]: 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] 682s Sep 14 09:50:38 autopkgtest multipathd[334]: check_removed_paths: sdd: freeing path in removed state 682s Sep 14 09:50:38 autopkgtest multipathd[334]: 8:48: path removed from map mpatha 682s Sep 14 09:50:38 autopkgtest multipathd[334]: 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] 682s Sep 14 09:50:38 autopkgtest multipathd[334]: check_removed_paths: sdc: freeing path in removed state 682s Sep 14 09:50:38 autopkgtest multipathd[334]: 8:32: path removed from map mpatha 682s Sep 14 09:50:38 autopkgtest multipathd[334]: 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] 682s Sep 14 09:50:38 autopkgtest multipathd[334]: check_removed_paths: sde: freeing path in removed state 682s Sep 14 09:50:38 autopkgtest multipathd[334]: 8:64: path removed from map mpatha 682s Sep 14 09:50:48 autopkgtest multipathd[334]: multipathd: shut down 682s Sep 14 09:50:48 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 682s Sep 14 09:50:48 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 682s Sep 14 09:50:48 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 682s Sep 14 09:50:48 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 682s Sep 14 09:50:48 autopkgtest multipathd[6475]: multipathd v0.9.9: start up 682s Sep 14 09:50:48 autopkgtest multipathd[6475]: reconfigure: setting up paths and maps 682s Sep 14 09:50:48 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 682s Check final path status 682s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 682s size=100M features='0' hwhandler='0' wp=rw 682s |-+- policy='service-time 0' prio=1 status=active 682s | `- 0:0:0:1 sda 8:0 active ready running 682s `-+- policy='service-time 0' prio=1 status=enabled 682s `- 1:0:0:1 sdb 8:16 active ready running 682s + sync 682s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 682s + echo Final stats 682s + iscsiadm --mode session --stats 682s + journalctl --no-pager -u multipathd 682s + echo Check final path status 682s + multipath -ll 682s + multipath -ll 682s + grep --count status= 682s + diskc=2 682s + multipath -ll 682s + grep --count status=active 682s + diska=1 682s + multipath -ll 682s + grep --count status=enabled 682s OK 682s + diske=1 682s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 682s + echo OK 682s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 682s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 682s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 682s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 682s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 682s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 682s autopkgtest [09:52:48]: test tgtbasedmpaths: -----------------------] 683s tgtbasedmpaths PASS 683s autopkgtest [09:52:49]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 683s autopkgtest [09:52:49]: @@@@@@@@@@@@@@@@@@@@ summary 683s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 683s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 683s kpartx-file-loopback PASS 683s tgtbasedmpaths PASS 687s nova [W] Using flock in prodstack6-ppc64el 687s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240914-094126-juju-7f2275-prod-proposed-migration-environment-3-ea2162c1-cd07-4da3-92ab-8845a3077359 from image adt/ubuntu-oracular-ppc64el-server-20240913.img (UUID fe25b897-3dd6-415f-af83-adc681eec9df)... 687s nova [W] Using flock in prodstack6-ppc64el 687s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240914-094126-juju-7f2275-prod-proposed-migration-environment-3-ea2162c1-cd07-4da3-92ab-8845a3077359 from image adt/ubuntu-oracular-ppc64el-server-20240913.img (UUID fe25b897-3dd6-415f-af83-adc681eec9df)...