0s autopkgtest [10:52:47]: starting date and time: 2024-07-05 10:52:47+0000 0s autopkgtest [10:52:47]: git checkout: 85adf9a1 setup-testbed: prevent /tmp from getting a tmpfs mount 0s autopkgtest [10:52:47]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.dexkyw_4/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:initramfs-tools,src:multipath-tools --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=initramfs-tools/0.142ubuntu30 multipath-tools/0.9.7-7ubuntu1' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos02-ppc64el-18.secgroup --name adt-oracular-ppc64el-multipath-tools-20240705-105247-juju-7f2275-prod-proposed-migration-environment-3-3ef97c02-acf5-4bbe-9363-ba8efcfb60d7 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --net-id=net_prod-proposed-migration -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/ 135s autopkgtest [10:55:02]: testbed dpkg architecture: ppc64el 135s autopkgtest [10:55:02]: testbed apt version: 2.9.5 135s autopkgtest [10:55:02]: @@@@@@@@@@@@@@@@@@@@ test bed setup 136s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 136s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.4 kB] 136s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [348 kB] 137s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7052 B] 137s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 137s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [81.2 kB] 137s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 137s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [345 kB] 137s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1448 B] 137s Fetched 949 kB in 1s (914 kB/s) 137s Reading package lists... 139s Reading package lists... 140s Building dependency tree... 140s Reading state information... 140s Calculating upgrade... 140s The following packages have been kept back: 140s kpartx multipath-tools 140s The following packages will be upgraded: 140s debianutils groff-base hwdata initramfs-tools initramfs-tools-bin 140s initramfs-tools-core libudisks2-0 ubuntu-pro-client ubuntu-pro-client-l10n 140s udisks2 140s 10 upgraded, 0 newly installed, 0 to remove and 2 not upgraded. 140s Need to get 2078 kB of archives. 140s After this operation, 19.5 kB of additional disk space will be used. 140s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el debianutils ppc64el 5.20 [90.7 kB] 140s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el ubuntu-pro-client-l10n ppc64el 33 [19.2 kB] 140s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el ubuntu-pro-client ppc64el 33 [231 kB] 140s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el groff-base ppc64el 1.23.0-5 [1105 kB] 141s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el hwdata all 0.384-1 [29.3 kB] 141s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools all 0.142ubuntu30 [7908 B] 141s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools-core all 0.142ubuntu30 [49.9 kB] 141s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools-bin ppc64el 0.142ubuntu30 [21.9 kB] 141s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el udisks2 ppc64el 2.10.1-9 [342 kB] 141s Get:10 http://ftpmaster.internal/ubuntu oracular/main ppc64el libudisks2-0 ppc64el 2.10.1-9 [181 kB] 141s Fetched 2078 kB in 1s (1698 kB/s) 141s (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 ... 72733 files and directories currently installed.) 141s Preparing to unpack .../debianutils_5.20_ppc64el.deb ... 141s Unpacking debianutils (5.20) over (5.19) ... 141s Setting up debianutils (5.20) ... 142s (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 ... 72733 files and directories currently installed.) 142s Preparing to unpack .../0-ubuntu-pro-client-l10n_33_ppc64el.deb ... 142s Unpacking ubuntu-pro-client-l10n (33) over (32.3.1) ... 142s Preparing to unpack .../1-ubuntu-pro-client_33_ppc64el.deb ... 142s Unpacking ubuntu-pro-client (33) over (32.3.1) ... 142s Preparing to unpack .../2-groff-base_1.23.0-5_ppc64el.deb ... 142s Unpacking groff-base (1.23.0-5) over (1.23.0-4) ... 142s Preparing to unpack .../3-hwdata_0.384-1_all.deb ... 142s Unpacking hwdata (0.384-1) over (0.383-1) ... 142s Preparing to unpack .../4-initramfs-tools_0.142ubuntu30_all.deb ... 142s Unpacking initramfs-tools (0.142ubuntu30) over (0.142ubuntu29) ... 142s Preparing to unpack .../5-initramfs-tools-core_0.142ubuntu30_all.deb ... 142s Unpacking initramfs-tools-core (0.142ubuntu30) over (0.142ubuntu29) ... 142s Preparing to unpack .../6-initramfs-tools-bin_0.142ubuntu30_ppc64el.deb ... 142s Unpacking initramfs-tools-bin (0.142ubuntu30) over (0.142ubuntu29) ... 142s Preparing to unpack .../7-udisks2_2.10.1-9_ppc64el.deb ... 142s Unpacking udisks2 (2.10.1-9) over (2.10.1-8) ... 142s Preparing to unpack .../8-libudisks2-0_2.10.1-9_ppc64el.deb ... 142s Unpacking libudisks2-0:ppc64el (2.10.1-9) over (2.10.1-8) ... 142s Setting up hwdata (0.384-1) ... 142s Setting up groff-base (1.23.0-5) ... 142s Setting up ubuntu-pro-client (33) ... 144s Setting up libudisks2-0:ppc64el (2.10.1-9) ... 144s Setting up initramfs-tools-bin (0.142ubuntu30) ... 144s Setting up ubuntu-pro-client-l10n (33) ... 144s Setting up udisks2 (2.10.1-9) ... 145s Setting up initramfs-tools-core (0.142ubuntu30) ... 145s Setting up initramfs-tools (0.142ubuntu30) ... 145s update-initramfs: deferring update (trigger activated) 145s Processing triggers for man-db (2.12.1-2) ... 146s Processing triggers for dbus (1.14.10-4ubuntu4) ... 146s Processing triggers for libc-bin (2.39-0ubuntu9) ... 146s Processing triggers for initramfs-tools (0.142ubuntu30) ... 146s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 146s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 154s Reading package lists... 154s Building dependency tree... 154s Reading state information... 154s 0 upgraded, 0 newly installed, 0 to remove and 2 not upgraded. 155s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 155s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 155s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 155s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 156s Reading package lists... 156s Reading package lists... 156s Building dependency tree... 156s Reading state information... 156s Calculating upgrade... 156s The following packages have been kept back: 156s kpartx multipath-tools 156s 0 upgraded, 0 newly installed, 0 to remove and 2 not upgraded. 156s Reading package lists... 157s Building dependency tree... 157s Reading state information... 157s 0 upgraded, 0 newly installed, 0 to remove and 2 not upgraded. 157s autopkgtest [10:55:24]: rebooting testbed after setup commands that affected boot 191s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 202s autopkgtest [10:56:09]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 205s autopkgtest [10:56:12]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 208s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main multipath-tools 0.9.7-7ubuntu1 (dsc) [2842 B] 208s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main multipath-tools 0.9.7-7ubuntu1 (tar) [570 kB] 208s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main multipath-tools 0.9.7-7ubuntu1 (diff) [42.8 kB] 208s gpgv: Signature made Wed Jun 5 21:25:50 2024 UTC 208s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 208s gpgv: issuer "steve.langasek@ubuntu.com" 208s gpgv: Can't check signature: No public key 208s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.7-7ubuntu1.dsc: no acceptable signature found 209s autopkgtest [10:56:16]: testing package multipath-tools version 0.9.7-7ubuntu1 209s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 209s autopkgtest [10:56:16]: build not needed 210s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 210s autopkgtest [10:56:17]: test kpartx-file-loopback: preparing testbed 211s Reading package lists... 211s Building dependency tree... 211s Reading state information... 211s Starting pkgProblemResolver with broken count: 0 211s Starting 2 pkgProblemResolver with broken count: 0 211s Done 211s The following additional packages will be installed: 211s liburing2 qemu-utils 211s Recommended packages: 211s qemu-block-extra 211s The following NEW packages will be installed: 211s autopkgtest-satdep liburing2 qemu-utils 211s 0 upgraded, 3 newly installed, 0 to remove and 2 not upgraded. 211s Need to get 2330 kB/2331 kB of archives. 211s After this operation, 15.4 MB of additional disk space will be used. 211s Get:1 /tmp/autopkgtest.LIWM2n/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 211s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 212s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 213s Fetched 2330 kB in 1s (1805 kB/s) 213s Selecting previously unselected package liburing2:ppc64el. 213s (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 ... 72734 files and directories currently installed.) 213s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 213s Unpacking liburing2:ppc64el (2.6-1) ... 213s Selecting previously unselected package qemu-utils. 213s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 213s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 213s Selecting previously unselected package autopkgtest-satdep. 213s Preparing to unpack .../1-autopkgtest-satdep.deb ... 213s Unpacking autopkgtest-satdep (0) ... 213s Setting up liburing2:ppc64el (2.6-1) ... 213s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 213s Setting up autopkgtest-satdep (0) ... 213s Processing triggers for man-db (2.12.1-2) ... 214s Processing triggers for libc-bin (2.39-0ubuntu9) ... 216s (Reading database ... 72754 files and directories currently installed.) 216s Removing autopkgtest-satdep (0) ... 217s autopkgtest [10:56:24]: test kpartx-file-loopback: [----------------------- 217s Formatting 'foo.img', fmt=raw size=20971520 218s Creating new GPT entries in memory. 218s Warning: The kernel is still using the old partition table. 218s The new table will be used at the next reboot or after you 218s run partprobe(8) or kpartx(8) 218s The operation has completed successfully. 218s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 218s standard_filename: OK 218s del devmap : loop0p1 218s No devices found 218s standard_filename_cleanup: OK 218s Formatting 'fou du FaFa.img', fmt=raw size=20971520 219s Creating new GPT entries in memory. 219s Warning: The kernel is still using the old partition table. 219s The new table will be used at the next reboot or after you 219s run partprobe(8) or kpartx(8) 219s The operation has completed successfully. 219s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 219s filename_with_spaces: OK 219s del devmap : loop0p1 219s No devices found 219s filename_with_spaces_cleanup: OK 220s autopkgtest [10:56:27]: test kpartx-file-loopback: -----------------------] 220s kpartx-file-loopback PASS 220s autopkgtest [10:56:27]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 220s autopkgtest [10:56:27]: test tgtbasedmpaths: preparing testbed 309s autopkgtest [10:57:56]: testbed dpkg architecture: ppc64el 309s autopkgtest [10:57:56]: testbed apt version: 2.9.5 309s autopkgtest [10:57:56]: @@@@@@@@@@@@@@@@@@@@ test bed setup 310s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 311s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.4 kB] 311s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 311s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [348 kB] 311s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7052 B] 311s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [81.2 kB] 311s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 311s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [345 kB] 311s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1448 B] 311s Fetched 949 kB in 1s (1107 kB/s) 311s Reading package lists... 313s Reading package lists... 313s Building dependency tree... 313s Reading state information... 314s Calculating upgrade... 314s The following packages have been kept back: 314s kpartx multipath-tools 314s The following packages will be upgraded: 314s debianutils groff-base hwdata initramfs-tools initramfs-tools-bin 314s initramfs-tools-core libudisks2-0 ubuntu-pro-client ubuntu-pro-client-l10n 314s udisks2 314s 10 upgraded, 0 newly installed, 0 to remove and 2 not upgraded. 314s Need to get 2078 kB of archives. 314s After this operation, 19.5 kB of additional disk space will be used. 314s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el debianutils ppc64el 5.20 [90.7 kB] 314s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el ubuntu-pro-client-l10n ppc64el 33 [19.2 kB] 314s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el ubuntu-pro-client ppc64el 33 [231 kB] 314s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el groff-base ppc64el 1.23.0-5 [1105 kB] 315s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el hwdata all 0.384-1 [29.3 kB] 315s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools all 0.142ubuntu30 [7908 B] 315s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools-core all 0.142ubuntu30 [49.9 kB] 315s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools-bin ppc64el 0.142ubuntu30 [21.9 kB] 315s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el udisks2 ppc64el 2.10.1-9 [342 kB] 315s Get:10 http://ftpmaster.internal/ubuntu oracular/main ppc64el libudisks2-0 ppc64el 2.10.1-9 [181 kB] 315s Fetched 2078 kB in 1s (1606 kB/s) 315s (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 ... 72733 files and directories currently installed.) 315s Preparing to unpack .../debianutils_5.20_ppc64el.deb ... 315s Unpacking debianutils (5.20) over (5.19) ... 315s Setting up debianutils (5.20) ... 316s (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 ... 72733 files and directories currently installed.) 316s Preparing to unpack .../0-ubuntu-pro-client-l10n_33_ppc64el.deb ... 316s Unpacking ubuntu-pro-client-l10n (33) over (32.3.1) ... 316s Preparing to unpack .../1-ubuntu-pro-client_33_ppc64el.deb ... 316s Unpacking ubuntu-pro-client (33) over (32.3.1) ... 316s Preparing to unpack .../2-groff-base_1.23.0-5_ppc64el.deb ... 316s Unpacking groff-base (1.23.0-5) over (1.23.0-4) ... 316s Preparing to unpack .../3-hwdata_0.384-1_all.deb ... 316s Unpacking hwdata (0.384-1) over (0.383-1) ... 316s Preparing to unpack .../4-initramfs-tools_0.142ubuntu30_all.deb ... 316s Unpacking initramfs-tools (0.142ubuntu30) over (0.142ubuntu29) ... 316s Preparing to unpack .../5-initramfs-tools-core_0.142ubuntu30_all.deb ... 316s Unpacking initramfs-tools-core (0.142ubuntu30) over (0.142ubuntu29) ... 316s Preparing to unpack .../6-initramfs-tools-bin_0.142ubuntu30_ppc64el.deb ... 316s Unpacking initramfs-tools-bin (0.142ubuntu30) over (0.142ubuntu29) ... 316s Preparing to unpack .../7-udisks2_2.10.1-9_ppc64el.deb ... 316s Unpacking udisks2 (2.10.1-9) over (2.10.1-8) ... 316s Preparing to unpack .../8-libudisks2-0_2.10.1-9_ppc64el.deb ... 316s Unpacking libudisks2-0:ppc64el (2.10.1-9) over (2.10.1-8) ... 316s Setting up hwdata (0.384-1) ... 316s Setting up groff-base (1.23.0-5) ... 316s Setting up ubuntu-pro-client (33) ... 318s Setting up libudisks2-0:ppc64el (2.10.1-9) ... 318s Setting up initramfs-tools-bin (0.142ubuntu30) ... 318s Setting up ubuntu-pro-client-l10n (33) ... 318s Setting up udisks2 (2.10.1-9) ... 319s Setting up initramfs-tools-core (0.142ubuntu30) ... 319s Setting up initramfs-tools (0.142ubuntu30) ... 319s update-initramfs: deferring update (trigger activated) 319s Processing triggers for man-db (2.12.1-2) ... 320s Processing triggers for dbus (1.14.10-4ubuntu4) ... 320s Processing triggers for libc-bin (2.39-0ubuntu9) ... 320s Processing triggers for initramfs-tools (0.142ubuntu30) ... 320s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 320s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 328s Reading package lists... 328s Building dependency tree... 328s Reading state information... 328s 0 upgraded, 0 newly installed, 0 to remove and 2 not upgraded. 329s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 329s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 329s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 329s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 330s Reading package lists... 330s Reading package lists... 330s Building dependency tree... 330s Reading state information... 330s Calculating upgrade... 330s The following packages have been kept back: 330s kpartx multipath-tools 330s 0 upgraded, 0 newly installed, 0 to remove and 2 not upgraded. 330s Reading package lists... 331s Building dependency tree... 331s Reading state information... 331s 0 upgraded, 0 newly installed, 0 to remove and 2 not upgraded. 331s autopkgtest [10:58:18]: rebooting testbed after setup commands that affected boot 365s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 380s Reading package lists... 380s Building dependency tree... 380s Reading state information... 380s Starting pkgProblemResolver with broken count: 0 380s Starting 2 pkgProblemResolver with broken count: 0 380s Done 380s The following additional packages will be installed: 380s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 380s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 380s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 380s librdmacm1t64 lsscsi open-iscsi tgt 380s Suggested packages: 380s fio-examples gnuplot tgt-glusterfs tgt-rbd 380s Recommended packages: 380s finalrd 380s The following NEW packages will be installed: 380s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 380s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 380s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 380s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 380s 0 upgraded, 22 newly installed, 0 to remove and 2 not upgraded. 380s Need to get 10.7 MB/10.7 MB of archives. 380s After this operation, 49.0 MB of additional disk space will be used. 380s Get:1 /tmp/autopkgtest.LIWM2n/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 380s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 381s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 381s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 381s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2 [80.5 kB] 381s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 381s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 381s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4ubuntu1 [21.5 kB] 381s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4ubuntu1 [311 kB] 381s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4ubuntu1 [46.5 kB] 381s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4ubuntu1 [99.2 kB] 381s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-1 [97.4 kB] 381s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 381s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 381s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 381s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 381s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 381s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 382s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 382s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 383s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 383s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 383s Preconfiguring packages ... 383s Fetched 10.7 MB in 3s (4045 kB/s) 383s Selecting previously unselected package libopeniscsiusr. 383s (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 ... 72734 files and directories currently installed.) 383s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 383s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 383s Selecting previously unselected package libisns0t64:ppc64el. 383s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 383s Unpacking libisns0t64:ppc64el (0.101-1) ... 383s Selecting previously unselected package open-iscsi. 383s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 384s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 384s Selecting previously unselected package librdmacm1t64:ppc64el. 384s Preparing to unpack .../03-librdmacm1t64_52.0-2_ppc64el.deb ... 384s Unpacking librdmacm1t64:ppc64el (52.0-2) ... 384s Selecting previously unselected package libconfig-general-perl. 384s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 384s Unpacking libconfig-general-perl (2.65-2) ... 384s Selecting previously unselected package tgt. 384s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 384s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 384s Selecting previously unselected package libgfxdr0:ppc64el. 384s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_ppc64el.deb ... 384s Unpacking libgfxdr0:ppc64el (11.1-4ubuntu1) ... 384s Selecting previously unselected package libglusterfs0:ppc64el. 384s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_ppc64el.deb ... 384s Unpacking libglusterfs0:ppc64el (11.1-4ubuntu1) ... 384s Selecting previously unselected package libgfrpc0:ppc64el. 384s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_ppc64el.deb ... 384s Unpacking libgfrpc0:ppc64el (11.1-4ubuntu1) ... 384s Selecting previously unselected package libgfapi0:ppc64el. 384s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_ppc64el.deb ... 384s Unpacking libgfapi0:ppc64el (11.1-4ubuntu1) ... 384s Selecting previously unselected package libnbd0. 384s Preparing to unpack .../10-libnbd0_1.20.2-1_ppc64el.deb ... 384s Unpacking libnbd0 (1.20.2-1) ... 384s Selecting previously unselected package libdaxctl1:ppc64el. 384s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 384s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 384s Selecting previously unselected package libndctl6:ppc64el. 384s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 384s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 384s Selecting previously unselected package libpmem1:ppc64el. 384s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 384s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 384s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 384s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 384s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 384s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 384s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 384s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 384s Selecting previously unselected package librados2. 384s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 384s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 384s Selecting previously unselected package libpmemobj1:ppc64el. 384s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 384s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 384s Selecting previously unselected package librbd1. 384s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 384s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 384s Selecting previously unselected package fio. 384s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 384s Unpacking fio (3.37-1) ... 384s Selecting previously unselected package lsscsi. 384s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 384s Unpacking lsscsi (0.32-1build1) ... 384s Selecting previously unselected package autopkgtest-satdep. 384s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 384s Unpacking autopkgtest-satdep (0) ... 384s Setting up libconfig-general-perl (2.65-2) ... 384s Setting up libisns0t64:ppc64el (0.101-1) ... 384s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 384s Setting up libnbd0 (1.20.2-1) ... 384s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 384s Setting up libglusterfs0:ppc64el (11.1-4ubuntu1) ... 384s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 384s Setting up lsscsi (0.32-1build1) ... 384s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 384s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 384s Setting up librdmacm1t64:ppc64el (52.0-2) ... 384s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 385s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 385s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 385s Setting up libgfxdr0:ppc64el (11.1-4ubuntu1) ... 385s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 385s Setting up open-iscsi (2.1.10-1ubuntu1) ... 386s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 387s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 387s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 387s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 387s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 387s Setting up libgfrpc0:ppc64el (11.1-4ubuntu1) ... 387s Setting up libgfapi0:ppc64el (11.1-4ubuntu1) ... 387s Setting up fio (3.37-1) ... 387s Setting up autopkgtest-satdep (0) ... 387s Processing triggers for man-db (2.12.1-2) ... 389s Processing triggers for initramfs-tools (0.142ubuntu30) ... 389s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 389s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 397s Processing triggers for libc-bin (2.39-0ubuntu9) ... 399s (Reading database ... 72975 files and directories currently installed.) 399s Removing autopkgtest-satdep (0) ... 402s autopkgtest [10:59:29]: test tgtbasedmpaths: [----------------------- 402s + targetname=iqn.2016-11.foo.com:target.iscsi 402s + pwd 402s + cwd=/tmp/autopkgtest.LIWM2n/build.zDI/src 402s + testdir=/mnt/tgtmpathtest 402s + localhost=127.0.0.1 402s + portal=127.0.0.1:3260 402s + maxpaths=4 402s + backfn=backingfile 402s + expectwwid=60000000000000000e00000000010001 402s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 402s + bglog=/tmp/autopkgtest.LIWM2n/tgtbasedmpaths-artifacts/test-background.log 402s + fioprep=/tmp/autopkgtest.LIWM2n/tgtbasedmpaths-artifacts/path-change-prep.fio 402s + fiovrfy=/tmp/autopkgtest.LIWM2n/tgtbasedmpaths-artifacts/path-change-check.fio 402s + mkdir -p /etc/multipath 402s + echo /360000000000000000e00000000010001/ 402s + service tgt restart 402s + truncate --size 100M backingfile 402s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 402s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 402s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.LIWM2n/build.zDI/src/backingfile 402s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 402s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 402s login #1 402s + echo login #1 402s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 402s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 402s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 402s + seq 2 4 402s + echo extra login #2 402s + iscsiadm --mode session -r 1 --op new 402s extra login #2 402s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 402s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 402s extra login #3 402s + echo extra login #3 402s + iscsiadm --mode session -r 1 --op new 402s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 402s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 402s extra login #4 402s + echo extra login #4 402s + iscsiadm --mode session -r 1 --op new 402s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 402s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 402s + udevadm settle 403s + sleep 5 408s Status after initial setup 408s + echo Status after initial setup 408s + tgtadm --lld iscsi --mode target --op show 408s + tgtadm --lld iscsi --op show --mode conn --tid 1 408s Target 1: iqn.2016-11.foo.com:target.iscsi 408s System information: 408s Driver: iscsi 408s State: ready 408s I_T nexus information: 408s I_T nexus: 1 408s Initiator: iqn.2004-10.com.ubuntu:01:1fc0de8065e4 alias: autopkgtest 408s Connection: 0 408s IP Address: 127.0.0.1 408s I_T nexus: 2 408s Initiator: iqn.2004-10.com.ubuntu:01:1fc0de8065e4 alias: autopkgtest 408s Connection: 0 408s IP Address: 127.0.0.1 408s I_T nexus: 3 408s Initiator: iqn.2004-10.com.ubuntu:01:1fc0de8065e4 alias: autopkgtest 408s Connection: 0 408s IP Address: 127.0.0.1 408s I_T nexus: 4 408s Initiator: iqn.2004-10.com.ubuntu:01:1fc0de8065e4 alias: autopkgtest 408s Connection: 0 408s IP Address: 127.0.0.1 408s LUN information: 408s LUN: 0 408s Type: controller 408s SCSI ID: IET 00010000 408s SCSI SN: beaf10 408s Size: 0 MB, Block size: 1 408s Online: Yes 408s Removable media: No 408s Prevent removal: No 408s Readonly: No 408s SWP: No 408s Thin-provisioning: No 408s Backing store type: null 408s Backing store path: None 408s Backing store flags: 408s LUN: 1 408s Type: disk 408s SCSI ID: IET 00010001 408s SCSI SN: beaf11 408s Size: 105 MB, Block size: 512 408s Online: Yes 408s Removable media: No 408s Prevent removal: No 408s Readonly: No 408s SWP: No 408s Thin-provisioning: No 408s Backing store type: rdwr 408s Backing store path: /tmp/autopkgtest.LIWM2n/build.zDI/src/backingfile 408s Backing store flags: 408s Account information: 408s ACL information: 408s ALL 408s Session: 4 408s Connection: 0 408s Initiator: iqn.2004-10.com.ubuntu:01:1fc0de8065e4 408s IP Address: 127.0.0.1 408s Session: 3 408s Connection: 0 408s Initiator: iqn.2004-10.com.ubuntu:01:1fc0de8065e4 408s IP Address: 127.0.0.1 408s Session: 2 408s Connection: 0 408s Initiator: iqn.2004-10.com.ubuntu:01:1fc0de8065e4 408s IP Address: 127.0.0.1 408s Session: 1 408s Connection: 0 408s Initiator: iqn.2004-10.com.ubuntu:01:1fc0de8065e4 408s IP Address: 127.0.0.1 408s + iscsiadm --mode session -P 1 408s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 408s Current Portal: 127.0.0.1:3260,1 408s Persistent Portal: 127.0.0.1:3260,1 408s ********** 408s Interface: 408s ********** 408s Iface Name: default 408s Iface Transport: tcp 408s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:1fc0de8065e4 408s Iface IPaddress: 127.0.0.1 408s Iface HWaddress: default 408s Iface Netdev: default 408s SID: 1 408s iSCSI Connection State: LOGGED IN 408s iSCSI Session State: LOGGED_IN 408s Internal iscsid Session State: NO CHANGE 408s 408s ********** 408s Interface: 408s ********** 408s Iface Name: default 408s Iface Transport: tcp 408s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:1fc0de8065e4 408s Iface IPaddress: 127.0.0.1 408s Iface HWaddress: default 408s Iface Netdev: default 408s SID: 2 408s iSCSI Connection State: LOGGED IN 408s iSCSI Session State: LOGGED_IN 408s Internal iscsid Session State: NO CHANGE 408s 408s ********** 408s Interface: 408s ********** 408s Iface Name: default 408s Iface Transport: tcp 408s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:1fc0de8065e4 408s Iface IPaddress: 127.0.0.1 408s Iface HWaddress: default 408s Iface Netdev: default 408s SID: 3 408s iSCSI Connection State: LOGGED IN 408s iSCSI Session State: LOGGED_IN 408s Internal iscsid Session State: NO CHANGE 408s 408s ********** 408s Interface: 408s ********** 408s Iface Name: default 408s Iface Transport: tcp 408s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:1fc0de8065e4 408s Iface IPaddress: 127.0.0.1 408s Iface HWaddress: default 408s Iface Netdev: default 408s SID: 4 408s iSCSI Connection State: LOGGED IN 408s iSCSI Session State: LOGGED_IN 408s Internal iscsid Session State: NO CHANGE 408s + lsscsi -liv 408s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 408s + multipath -v3 -ll 408s 50.333666 | set open fds limit to 1048576/1048576 408s 50.333751 | loading /lib/multipath/libchecktur.so checker 408s 50.333844 | checker tur: message table size = 3 408s 50.333874 | loading /lib/multipath/libprioconst.so prioritizer 408s 50.333981 | _init_foreign: foreign library "nvme" is not enabled 408s 50.340105 | sda: size = 167772160 408s 50.340286 | sda: vendor = QEMU 408s 50.340332 | sda: product = QEMU HARDDISK 408s 50.340357 | sda: rev = 2.5+ 408s 50.341036 | sda: h:b:t:l = 0:0:0:0 408s 50.341384 | sda: tgt_node_name = 408s 50.341406 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 408s 50.341409 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 408s 50.341572 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 408s 50.341595 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 50.341607 | __sysfs_attr_get_value: attribute '/sys/devices/pci0000:00/0000:00:02.0/virtio1/host0/target0:0:0/0:0:0:0/vpd_pg80' can not be opened: No such file or directory 408s 50.341612 | failed to read sysfs vpd pg80: No such file or directory 408s 50.341844 | sda: fail to get serial 408s 50.341865 | sda: detect_checker = yes (setting: multipath internal) 408s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 408s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/pci0000:00/0000:00:02.0/virtio1/host0/target0:0:0/0:0:0:0] 408s [1:0:0:0] storage IET Controller 0001 - - 408s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 408s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 408s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 408s [2:0:0:0] storage IET Controller 0001 - - 408s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 408s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 408s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 408s [3:0:0:0] storage IET Controller 0001 - - 408s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 408s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 408s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 408s [4:0:0:0] storage IET Controller 0001 - - 408s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 408s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 33000000100000001 408s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 408s NVMe module may not be loaded 408s 50.342063 | sda: path_checker = tur (setting: multipath internal) 408s 50.342086 | sda: checker timeout = 30 s (setting: kernel sysfs) 408s 50.342232 | sda: tur state = up 408s 50.342576 | sdb: size = 204800 408s 50.342740 | sdb: vendor = IET 408s 50.342783 | sdb: product = VIRTUAL-DISK 408s 50.342807 | sdb: rev = 0001 408s 50.343504 | sdb: h:b:t:l = 1:0:0:1 408s 50.343927 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 50.343949 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 408s 50.343952 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 408s 50.344175 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 50.344203 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 50.344220 | sdb: serial = beaf11 408s 50.344223 | sdb: detect_checker = yes (setting: multipath internal) 408s 50.344585 | sdb: path_checker = tur (setting: multipath internal) 408s 50.344608 | sdb: checker timeout = 30 s (setting: kernel sysfs) 408s 50.344828 | sdb: tur state = up 408s 50.344982 | sdc: size = 204800 408s 50.345147 | sdc: vendor = IET 408s 50.345191 | sdc: product = VIRTUAL-DISK 408s 50.345216 | sdc: rev = 0001 408s 50.345971 | sdc: h:b:t:l = 2:0:0:1 408s 50.346365 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 50.346388 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 408s 50.346391 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 408s 50.346562 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 50.346584 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 50.346600 | sdc: serial = beaf11 408s 50.346602 | sdc: detect_checker = yes (setting: multipath internal) 408s 50.346922 | sdc: path_checker = tur (setting: multipath internal) 408s 50.346946 | sdc: checker timeout = 30 s (setting: kernel sysfs) 408s 50.347168 | sdc: tur state = up 408s 50.347329 | sdd: size = 204800 408s 50.347494 | sdd: vendor = IET 408s 50.347538 | sdd: product = VIRTUAL-DISK 408s 50.347563 | sdd: rev = 0001 408s 50.348344 | sdd: h:b:t:l = 3:0:0:1 408s 50.348762 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 50.348785 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 408s 50.348787 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 408s 50.348963 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 50.348985 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 50.349001 | sdd: serial = beaf11 408s 50.349004 | sdd: detect_checker = yes (setting: multipath internal) 408s 50.349338 | sdd: path_checker = tur (setting: multipath internal) 408s 50.349362 | sdd: checker timeout = 30 s (setting: kernel sysfs) 408s 50.349575 | sdd: tur state = up 408s 50.349737 | sde: size = 204800 408s 50.349902 | sde: vendor = IET 408s 50.349946 | sde: product = VIRTUAL-DISK 408s 50.349970 | sde: rev = 0001 408s 50.350721 | sde: h:b:t:l = 4:0:0:1 408s 50.351118 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 50.351141 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 408s 50.351143 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 408s 50.351318 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 50.351340 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 50.351356 | sde: serial = beaf11 408s 50.351359 | sde: detect_checker = yes (setting: multipath internal) 408s 50.351672 | sde: path_checker = tur (setting: multipath internal) 408s 50.351697 | sde: checker timeout = 30 s (setting: kernel sysfs) 408s 50.351931 | sde: tur state = up 408s 50.352089 | loop0: device node name blacklisted 408s 50.352211 | loop1: device node name blacklisted 408s 50.352302 | loop2: device node name blacklisted 408s 50.352415 | loop3: device node name blacklisted 408s 50.352530 | loop4: device node name blacklisted 408s 50.352621 | loop5: device node name blacklisted 408s 50.352710 | loop6: device node name blacklisted 408s 50.352819 | loop7: device node name blacklisted 408s 50.352916 | dm-0: device node name blacklisted 408s 50.353985 | multipath-tools v0.9.4 (12/19, 2022) 408s 50.354016 | libdevmapper version 1.02.185 408s 50.354158 | kernel device mapper v4.48.0 408s 50.354169 | DM multipath kernel driver v1.14.0 408s 50.354284 | sdb: size = 204800 408s 50.354289 | sdb: vendor = IET 408s 50.354292 | sdb: product = VIRTUAL-DISK 408s 50.354295 | sdb: rev = 0001 408s 50.354992 | sdb: h:b:t:l = 1:0:0:1 408s 50.355143 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 50.355185 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 50.355189 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 50.355202 | sdb: serial = beaf11 408s 50.355463 | sdb: tur state = up 408s 50.355486 | sdb: uid = 360000000000000000e00000000010001 (udev) 408s 50.355489 | sdb: detect_prio = yes (setting: multipath internal) 408s 50.355493 | sdb: prio = const (setting: multipath internal) 408s 50.355495 | sdb: prio args = "" (setting: multipath internal) 408s 50.355498 | sdb: const prio = 1 408s 50.355524 | sdc: size = 204800 408s 50.355529 | sdc: vendor = IET 408s 50.355532 | sdc: product = VIRTUAL-DISK 408s 50.355535 | sdc: rev = 0001 408s 50.356261 | sdc: h:b:t:l = 2:0:0:1 408s 50.356412 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 50.356454 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 50.356457 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 50.356471 | sdc: serial = beaf11 408s 50.356707 | sdc: tur state = up 408s 50.356730 | sdc: uid = 360000000000000000e00000000010001 (udev) 408s 50.356732 | sdc: detect_prio = yes (setting: multipath internal) 408s 50.356735 | sdc: prio = const (setting: multipath internal) 408s 50.356737 | sdc: prio args = "" (setting: multipath internal) 408s 50.356739 | sdc: const prio = 1 408s 50.356766 | sdd: size = 204800 408s 50.356771 | sdd: vendor = IET 408s 50.356775 | sdd: product = VIRTUAL-DISK 408s 50.356777 | sdd: rev = 0001 408s 50.357457 | sdd: h:b:t:l = 3:0:0:1 408s 50.357601 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 50.357643 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 50.357646 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 50.357659 | sdd: serial = beaf11 408s 50.357946 | sdd: tur state = up 408s 50.357969 | sdd: uid = 360000000000000000e00000000010001 (udev) 408s 50.357972 | sdd: detect_prio = yes (setting: multipath internal) 408s 50.357974 | sdd: prio = const (setting: multipath internal) 408s 50.357977 | sdd: prio args = "" (setting: multipath internal) 408s 50.357979 | sdd: const prio = 1 408s 50.358005 | sde: size = 204800 408s 50.358010 | sde: vendor = IET 408s 50.358013 | sde: product = VIRTUAL-DISK 408s 50.358016 | sde: rev = 0001 408s 50.358694 | sde: h:b:t:l = 4:0:0:1 408s 50.358838 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 50.358878 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 50.358882 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 50.358895 | sde: serial = beaf11 408s 50.359130 | sde: tur state = up 408s 50.359151 | sde: uid = 360000000000000000e00000000010001 (udev) 408s 50.359154 | sde: detect_prio = yes (setting: multipath internal) 408s 50.359157 | sde: prio = const (setting: multipath internal) 408s 50.359159 | sde: prio args = "" (setting: multipath internal) 408s 50.359161 | sde: const prio = 1 408s 50.359979 | unloading tur checker 408s 50.360051 | unloading const prioritizer 408s + dmsetup table 408s + grep . /etc/multipath/bindings /etc/multipath/wwids 408s + systemctl status multipathd.service 408s ===== paths list ===== 408s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 408s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 408s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 408s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 408s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 408s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 408s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 408s size=100M features='0' hwhandler='0' wp=rw 408s |-+- policy='service-time 0' prio=1 status=active 408s | `- 1:0:0:1 sdb 8:16 active ready running 408s |-+- policy='service-time 0' prio=1 status=enabled 408s | `- 2:0:0:1 sdc 8:32 active ready running 408s |-+- policy='service-time 0' prio=1 status=enabled 408s | `- 3:0:0:1 sdd 8:48 active ready running 408s `-+- policy='service-time 0' prio=1 status=enabled 408s `- 4:0:0:1 sde 8:64 active ready running 408s mpatha: 0 204800 multipath 0 0 4 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 service-time 0 1 2 8:64 1 1 408s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 408s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 408s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 408s /etc/multipath/bindings:# 408s /etc/multipath/bindings:# Format: 408s /etc/multipath/bindings:# alias wwid 408s /etc/multipath/bindings:# 408s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 408s /etc/multipath/wwids:/360000000000000000e00000000010001/ 408s ● multipathd.service - Device-Mapper Multipath Device Controller 408s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 408s Active: active (running) since Fri 2024-07-05 10:58:48 UTC; 46s ago 408s TriggeredBy: ● multipathd.socket 408s Main PID: 335 (multipathd) 408s Status: "up" 408s Tasks: 7 408s Memory: 30.5M (peak: 40.5M) 408s CPU: 57ms 408s CGroup: /system.slice/multipathd.service 408s └─335 /sbin/multipathd -d -s 408s 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 408s Jul 05 10:58:48 autopkgtest multipathd[335]: multipathd v0.9.4: start up 408s Jul 05 10:58:48 autopkgtest multipathd[335]: reconfigure: setting up paths and maps 408s Jul 05 10:58:48 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 408s Jul 05 10:59:29 autopkgtest multipathd[335]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:16 1] 408s Jul 05 10:59:29 autopkgtest multipathd[335]: sdb [8:16]: path added to devmap mpatha 408s Jul 05 10:59:29 autopkgtest multipathd[335]: mpatha: performing delayed actions 408s Jul 05 10:59:29 autopkgtest multipathd[335]: 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] 408s Jul 05 10:59:29 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 4 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 service-time 0 1 1 8:64 1] 408s Jul 05 10:59:29 autopkgtest multipathd[335]: sde [8:64]: path added to devmap mpatha 408s total 0 408s drwxr-xr-x 2 root root 80 Jul 5 10:59 . 408s drwxr-xr-x 18 root root 4240 Jul 5 10:59 .. 408s crw------- 1 root root 10, 236 Jul 5 10:58 control 408s lrwxrwxrwx 1 root root 7 Jul 5 10:59 mpatha -> ../dm-0 408s journal 408s + ls -la /dev/mapper/ 408s + echo journal 408s + journalctl -b 408s Jul 05 10:58:48 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 408s Jul 05 10:58:48 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 408s Jul 05 10:58:48 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 408s Jul 05 10:58:48 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 408s Jul 05 10:58:48 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 408s Jul 05 10:58:48 autopkgtest kernel: Activating Kernel Userspace Access Prevention 408s Jul 05 10:58:48 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 408s Jul 05 10:58:48 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x00000000038a0000 with 64.0 KiB pages (exec) 408s Jul 05 10:58:48 autopkgtest kernel: radix-mmu: Mapped 0x00000000038a0000-0x0000000200000000 with 64.0 KiB pages 408s Jul 05 10:58:48 autopkgtest kernel: lpar: Using radix MMU under hypervisor 408s Jul 05 10:58:48 autopkgtest kernel: Linux version 6.8.0-31-generic (buildd@bos02-ppc64el-018) (powerpc64le-linux-gnu-gcc-13 (Ubuntu 13.2.0-23ubuntu4) 13.2.0, GNU ld (GNU Binutils for Ubuntu) 2.42) #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 (Ubuntu 6.8.0-31.31-generic 6.8.1) 408s Jul 05 10:58:48 autopkgtest kernel: Secure boot mode disabled 408s Jul 05 10:58:48 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc0000000093cb80f 408s Jul 05 10:58:48 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (raw) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 408s Jul 05 10:58:48 autopkgtest kernel: printk: legacy bootconsole [udbg0] enabled 408s Jul 05 10:58:48 autopkgtest kernel: Partition configured for 4 cpus. 408s Jul 05 10:58:48 autopkgtest kernel: CPU maps initialized for 1 thread per core 408s Jul 05 10:58:48 autopkgtest kernel: (thread shift is 0) 408s Jul 05 10:58:48 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 408s Jul 05 10:58:48 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 408s Jul 05 10:58:48 autopkgtest kernel: ----------------------------------------------------- 408s Jul 05 10:58:48 autopkgtest kernel: phys_mem_size = 0x200000000 408s Jul 05 10:58:48 autopkgtest kernel: dcache_bsize = 0x80 408s Jul 05 10:58:48 autopkgtest kernel: icache_bsize = 0x80 408s Jul 05 10:58:48 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 408s Jul 05 10:58:48 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 408s Jul 05 10:58:48 autopkgtest kernel: always = 0x0000000380008181 408s Jul 05 10:58:48 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 408s Jul 05 10:58:48 autopkgtest kernel: mmu_features = 0x3c007641 408s Jul 05 10:58:48 autopkgtest kernel: firmware_features = 0x00000085455a445f 408s Jul 05 10:58:48 autopkgtest kernel: vmalloc start = 0xc008000000000000 408s Jul 05 10:58:48 autopkgtest kernel: IO start = 0xc00a000000000000 408s Jul 05 10:58:48 autopkgtest kernel: vmemmap start = 0xc00c000000000000 408s Jul 05 10:58:48 autopkgtest kernel: ----------------------------------------------------- 408s Jul 05 10:58:48 autopkgtest kernel: numa: NODE_DATA [mem 0x1eff10280-0x1eff17fff] 408s Jul 05 10:58:48 autopkgtest kernel: rfi-flush: fallback displacement flush available 408s Jul 05 10:58:48 autopkgtest kernel: rfi-flush: ori type flush available 408s Jul 05 10:58:48 autopkgtest kernel: rfi-flush: mttrig type flush available 408s Jul 05 10:58:48 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 408s Jul 05 10:58:48 autopkgtest kernel: count-cache-flush: software flush enabled. 408s Jul 05 10:58:48 autopkgtest kernel: link-stack-flush: software flush enabled. 408s Jul 05 10:58:48 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 408s Jul 05 10:58:48 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 408s Jul 05 10:58:48 autopkgtest kernel: stf-barrier: eieio barrier available 408s Jul 05 10:58:48 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 408s Jul 05 10:58:48 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 408s Jul 05 10:58:48 autopkgtest kernel: PPC64 nvram contains 65536 bytes 408s Jul 05 10:58:48 autopkgtest kernel: barrier-nospec: using ORI speculation barrier 408s Jul 05 10:58:48 autopkgtest kernel: barrier-nospec: patched 269 locations 408s Jul 05 10:58:48 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 408s Jul 05 10:58:48 autopkgtest kernel: Memory hole size: 0MB 408s Jul 05 10:58:48 autopkgtest kernel: Zone ranges: 408s Jul 05 10:58:48 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 408s Jul 05 10:58:48 autopkgtest kernel: Device empty 408s Jul 05 10:58:48 autopkgtest kernel: Movable zone start for each node 408s Jul 05 10:58:48 autopkgtest kernel: Early memory node ranges 408s Jul 05 10:58:48 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 408s Jul 05 10:58:48 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 408s Jul 05 10:58:48 autopkgtest kernel: percpu: Embedded 12 pages/cpu s609960 r0 d176472 u786432 408s Jul 05 10:58:48 autopkgtest kernel: pcpu-alloc: s609960 r0 d176472 u786432 alloc=12*65536 408s Jul 05 10:58:48 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 408s Jul 05 10:58:48 autopkgtest kernel: Kernel command line: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic root=UUID=d56a6f84-56d9-4867-a447-bcf23bdbf13a ro console=hvc0 earlyprintk 408s Jul 05 10:58:48 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic", will be passed to user space. 408s Jul 05 10:58:48 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 408s Jul 05 10:58:48 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 408s Jul 05 10:58:48 autopkgtest kernel: Fallback order for Node 0: 0 408s Jul 05 10:58:48 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 130944 408s Jul 05 10:58:48 autopkgtest kernel: Policy zone: Normal 408s Jul 05 10:58:48 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 408s Jul 05 10:58:48 autopkgtest kernel: Memory: 7969280K/8388608K available (23680K kernel code, 4096K rwdata, 25472K rodata, 8832K init, 1901K bss, 419328K reserved, 0K cma-reserved) 408s Jul 05 10:58:48 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 408s Jul 05 10:58:48 autopkgtest kernel: ftrace: allocating 51717 entries in 19 pages 408s Jul 05 10:58:48 autopkgtest kernel: ftrace: allocated 19 pages with 3 groups 408s Jul 05 10:58:48 autopkgtest kernel: trace event string verifier disabled 408s Jul 05 10:58:48 autopkgtest kernel: rcu: Hierarchical RCU implementation. 408s Jul 05 10:58:48 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 408s Jul 05 10:58:48 autopkgtest kernel: Rude variant of Tasks RCU enabled. 408s Jul 05 10:58:48 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 408s Jul 05 10:58:48 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 408s Jul 05 10:58:48 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 408s Jul 05 10:58:48 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 408s Jul 05 10:58:48 autopkgtest kernel: xive: Using IRQ range [0-3] 408s Jul 05 10:58:48 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 408s Jul 05 10:58:48 autopkgtest kernel: xive: Using priority 6 for all interrupts 408s Jul 05 10:58:48 autopkgtest kernel: xive: Using 64kB queues 408s Jul 05 10:58:48 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 408s Jul 05 10:58:48 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 408s Jul 05 10:58:48 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 408s Jul 05 10:58:48 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 408s Jul 05 10:58:48 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 408s Jul 05 10:58:48 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 408s Jul 05 10:58:48 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 408s Jul 05 10:58:48 autopkgtest kernel: Console: colour dummy device 80x25 408s Jul 05 10:58:48 autopkgtest kernel: printk: legacy console [hvc0] enabled 408s Jul 05 10:58:48 autopkgtest kernel: printk: legacy bootconsole [udbg0] disabled 408s Jul 05 10:58:48 autopkgtest kernel: pid_max: default: 32768 minimum: 301 408s Jul 05 10:58:48 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,integrity 408s Jul 05 10:58:48 autopkgtest kernel: landlock: Up and running. 408s Jul 05 10:58:48 autopkgtest kernel: Yama: becoming mindful. 408s Jul 05 10:58:48 autopkgtest kernel: AppArmor: AppArmor initialized 408s Jul 05 10:58:48 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 408s Jul 05 10:58:48 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 408s Jul 05 10:58:48 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 408s Jul 05 10:58:48 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 408s Jul 05 10:58:48 autopkgtest kernel: POWER9 performance monitor hardware support registered 408s Jul 05 10:58:48 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 408s Jul 05 10:58:48 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 408s Jul 05 10:58:48 autopkgtest kernel: smp: Bringing up secondary CPUs ... 408s Jul 05 10:58:48 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 408s Jul 05 10:58:48 autopkgtest kernel: numa: Node 0 CPUs: 0-3 408s Jul 05 10:58:48 autopkgtest kernel: devtmpfs: initialized 408s Jul 05 10:58:48 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 408s Jul 05 10:58:48 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 408s Jul 05 10:58:48 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 408s Jul 05 10:58:48 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 408s Jul 05 10:58:48 autopkgtest kernel: PCI: OF: PROBE_ONLY disabled 408s Jul 05 10:58:48 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 408s Jul 05 10:58:48 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 408s Jul 05 10:58:48 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 408s Jul 05 10:58:48 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 408s Jul 05 10:58:48 autopkgtest kernel: audit: initializing netlink subsys (disabled) 408s Jul 05 10:58:48 autopkgtest kernel: audit: type=2000 audit(1720177125.044:1): state=initialized audit_enabled=0 res=1 408s Jul 05 10:58:48 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 408s Jul 05 10:58:48 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 408s Jul 05 10:58:48 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 408s Jul 05 10:58:48 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 408s Jul 05 10:58:48 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 408s Jul 05 10:58:48 autopkgtest kernel: cpuidle: using governor ladder 408s Jul 05 10:58:48 autopkgtest kernel: cpuidle: using governor menu 408s Jul 05 10:58:48 autopkgtest kernel: RTAS daemon started 408s Jul 05 10:58:48 autopkgtest kernel: pstore: Using crash dump compression: deflate 408s Jul 05 10:58:48 autopkgtest kernel: pstore: Registered nvram as persistent store backend 408s Jul 05 10:58:48 autopkgtest kernel: EEH: pSeries platform initialized 408s Jul 05 10:58:48 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 408s Jul 05 10:58:48 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 408s Jul 05 10:58:48 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 408s Jul 05 10:58:48 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 408s Jul 05 10:58:48 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 408s Jul 05 10:58:48 autopkgtest kernel: iommu: Default domain type: Translated 408s Jul 05 10:58:48 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 408s Jul 05 10:58:48 autopkgtest kernel: SCSI subsystem initialized 408s Jul 05 10:58:48 autopkgtest kernel: libata version 3.00 loaded. 408s Jul 05 10:58:48 autopkgtest kernel: usbcore: registered new interface driver usbfs 408s Jul 05 10:58:48 autopkgtest kernel: usbcore: registered new interface driver hub 408s Jul 05 10:58:48 autopkgtest kernel: usbcore: registered new device driver usb 408s Jul 05 10:58:48 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 408s Jul 05 10:58:48 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 408s Jul 05 10:58:48 autopkgtest kernel: PTP clock support registered 408s Jul 05 10:58:48 autopkgtest kernel: EDAC MC: Ver: 3.0.0 408s Jul 05 10:58:48 autopkgtest kernel: NetLabel: Initializing 408s Jul 05 10:58:48 autopkgtest kernel: NetLabel: domain hash size = 128 408s Jul 05 10:58:48 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 408s Jul 05 10:58:48 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 408s Jul 05 10:58:48 autopkgtest kernel: mctp: management component transport protocol core 408s Jul 05 10:58:48 autopkgtest kernel: NET: Registered PF_MCTP protocol family 408s Jul 05 10:58:48 autopkgtest kernel: PCI: Probing PCI hardware 408s Jul 05 10:58:48 autopkgtest kernel: PCI host bridge to bus 0000:00 408s Jul 05 10:58:48 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 408s Jul 05 10:58:48 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 408s Jul 05 10:58:48 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 408s Jul 05 10:58:48 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 408s Jul 05 10:58:48 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 408s Jul 05 10:58:48 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 408s Jul 05 10:58:48 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 408s Jul 05 10:58:48 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 408s Jul 05 10:58:48 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 408s Jul 05 10:58:48 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 408s Jul 05 10:58:48 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 408s Jul 05 10:58:48 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 408s Jul 05 10:58:48 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 408s Jul 05 10:58:48 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 408s Jul 05 10:58:48 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 408s Jul 05 10:58:48 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 408s Jul 05 10:58:48 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 408s Jul 05 10:58:48 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 408s Jul 05 10:58:48 autopkgtest kernel: PCI: Probing PCI hardware done 408s Jul 05 10:58:48 autopkgtest kernel: vgaarb: loaded 408s Jul 05 10:58:48 autopkgtest kernel: clocksource: Switched to clocksource timebase 408s Jul 05 10:58:48 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 408s Jul 05 10:58:48 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 408s Jul 05 10:58:48 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 408s Jul 05 10:58:48 autopkgtest kernel: NET: Registered PF_INET protocol family 408s Jul 05 10:58:48 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 408s Jul 05 10:58:48 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 408s Jul 05 10:58:48 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 408s Jul 05 10:58:48 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 408s Jul 05 10:58:48 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 408s Jul 05 10:58:48 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 408s Jul 05 10:58:48 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 408s Jul 05 10:58:48 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 408s Jul 05 10:58:48 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 408s Jul 05 10:58:48 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 408s Jul 05 10:58:48 autopkgtest kernel: NET: Registered PF_XDP protocol family 408s Jul 05 10:58:48 autopkgtest kernel: PCI: CLS 0 bytes, default 128 408s Jul 05 10:58:48 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 408s Jul 05 10:58:48 autopkgtest kernel: Initialise system trusted keyrings 408s Jul 05 10:58:48 autopkgtest kernel: Key type blacklist registered 408s Jul 05 10:58:48 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 408s Jul 05 10:58:48 autopkgtest kernel: zbud: loaded 408s Jul 05 10:58:48 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 408s Jul 05 10:58:48 autopkgtest kernel: fuse: init (API version 7.39) 408s Jul 05 10:58:48 autopkgtest kernel: integrity: Platform Keyring initialized 408s Jul 05 10:58:48 autopkgtest kernel: integrity: Machine keyring initialized 408s Jul 05 10:58:48 autopkgtest kernel: Key type asymmetric registered 408s Jul 05 10:58:48 autopkgtest kernel: Asymmetric key parser 'x509' registered 408s Jul 05 10:58:48 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 408s Jul 05 10:58:48 autopkgtest kernel: io scheduler mq-deadline registered 408s Jul 05 10:58:48 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 408s Jul 05 10:58:48 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 408s Jul 05 10:58:48 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) 408s Jul 05 10:58:48 autopkgtest kernel: virtio-pci 0000:00:02.0: enabling device (0100 -> 0103) 408s Jul 05 10:58:48 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 408s Jul 05 10:58:48 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 408s Jul 05 10:58:48 autopkgtest kernel: Non-volatile memory driver v1.3 408s Jul 05 10:58:48 autopkgtest kernel: Linux agpgart interface v0.103 408s Jul 05 10:58:48 autopkgtest kernel: loop: module loaded 408s Jul 05 10:58:48 autopkgtest kernel: virtio_scsi virtio1: 1/0/0 default/read/poll queues 408s Jul 05 10:58:48 autopkgtest kernel: scsi host0: Virtio SCSI HBA 408s Jul 05 10:58:48 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 408s Jul 05 10:58:48 autopkgtest kernel: scsi 0:0:0:0: Direct-Access QEMU QEMU HARDDISK 2.5+ PQ: 0 ANSI: 5 408s Jul 05 10:58:48 autopkgtest kernel: PPP generic driver version 2.4.2 408s Jul 05 10:58:48 autopkgtest kernel: ohci-pci 0000:00:03.0: OHCI PCI host controller 408s Jul 05 10:58:48 autopkgtest kernel: ohci-pci 0000:00:03.0: new USB bus registered, assigned bus number 1 408s Jul 05 10:58:48 autopkgtest kernel: ohci-pci 0000:00:03.0: irq 20, io mem 0x200080090000 408s Jul 05 10:58:48 autopkgtest kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0 408s Jul 05 10:58:48 autopkgtest kernel: sd 0:0:0:0: Power-on or device reset occurred 408s Jul 05 10:58:48 autopkgtest kernel: sd 0:0:0:0: [sda] 167772160 512-byte logical blocks: (85.9 GB/80.0 GiB) 408s Jul 05 10:58:48 autopkgtest kernel: sd 0:0:0:0: [sda] Write Protect is off 408s Jul 05 10:58:48 autopkgtest kernel: sd 0:0:0:0: [sda] Mode Sense: 63 00 00 08 408s Jul 05 10:58:48 autopkgtest kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 408s Jul 05 10:58:48 autopkgtest kernel: sda: sda1 sda2 408s Jul 05 10:58:48 autopkgtest kernel: sd 0:0:0:0: [sda] Attached SCSI disk 408s Jul 05 10:58:48 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 6.08 408s Jul 05 10:58:48 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 408s Jul 05 10:58:48 autopkgtest kernel: usb usb1: Product: OHCI PCI host controller 408s Jul 05 10:58:48 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.8.0-31-generic ohci_hcd 408s Jul 05 10:58:48 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:03.0 408s Jul 05 10:58:48 autopkgtest kernel: hub 1-0:1.0: USB hub found 408s Jul 05 10:58:48 autopkgtest kernel: hub 1-0:1.0: 3 ports detected 408s Jul 05 10:58:48 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 408s Jul 05 10:58:48 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 408s Jul 05 10:58:48 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-07-05T10:58:45 UTC (1720177125) 408s Jul 05 10:58:48 autopkgtest kernel: i2c_dev: i2c /dev entries driver 408s Jul 05 10:58:48 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 408s Jul 05 10:58:48 autopkgtest kernel: device-mapper: uevent: version 1.0.3 408s Jul 05 10:58:48 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@redhat.com 408s Jul 05 10:58:48 autopkgtest kernel: pseries_idle_driver registered 408s Jul 05 10:58:48 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 408s Jul 05 10:58:48 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 408s Jul 05 10:58:48 autopkgtest kernel: NET: Registered PF_INET6 protocol family 408s Jul 05 10:58:48 autopkgtest kernel: Freeing initrd memory: 50944K 408s Jul 05 10:58:48 autopkgtest kernel: Segment Routing with IPv6 408s Jul 05 10:58:48 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 408s Jul 05 10:58:48 autopkgtest kernel: NET: Registered PF_PACKET protocol family 408s Jul 05 10:58:48 autopkgtest kernel: Key type dns_resolver registered 408s Jul 05 10:58:48 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 408s Jul 05 10:58:48 autopkgtest kernel: drmem: No dynamic reconfiguration memory found 408s Jul 05 10:58:48 autopkgtest kernel: registered taskstats version 1 408s Jul 05 10:58:48 autopkgtest kernel: Loading compiled-in X.509 certificates 408s Jul 05 10:58:48 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 408s Jul 05 10:58:48 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 408s Jul 05 10:58:48 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 408s Jul 05 10:58:48 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 408s Jul 05 10:58:48 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 408s Jul 05 10:58:48 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 408s Jul 05 10:58:48 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 408s Jul 05 10:58:48 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 408s Jul 05 10:58:48 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 408s Jul 05 10:58:48 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 408s Jul 05 10:58:48 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 408s Jul 05 10:58:48 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 408s Jul 05 10:58:48 autopkgtest kernel: Key type .fscrypt registered 408s Jul 05 10:58:48 autopkgtest kernel: Key type fscrypt-provisioning registered 408s Jul 05 10:58:48 autopkgtest kernel: Key type encrypted registered 408s Jul 05 10:58:48 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 408s Jul 05 10:58:48 autopkgtest kernel: Secure boot mode disabled 408s Jul 05 10:58:48 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 408s Jul 05 10:58:48 autopkgtest kernel: Loading compiled-in module X.509 certificates 408s Jul 05 10:58:48 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 408s Jul 05 10:58:48 autopkgtest kernel: ima: Allocated hash algorithm: sha256 408s Jul 05 10:58:48 autopkgtest kernel: Secure boot mode disabled 408s Jul 05 10:58:48 autopkgtest kernel: Trusted boot mode disabled 408s Jul 05 10:58:48 autopkgtest kernel: ima: No architecture policies found 408s Jul 05 10:58:48 autopkgtest kernel: evm: Initialising EVM extended attributes: 408s Jul 05 10:58:48 autopkgtest kernel: evm: security.selinux 408s Jul 05 10:58:48 autopkgtest kernel: evm: security.SMACK64 408s Jul 05 10:58:48 autopkgtest kernel: evm: security.SMACK64EXEC 408s Jul 05 10:58:48 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 408s Jul 05 10:58:48 autopkgtest kernel: evm: security.SMACK64MMAP 408s Jul 05 10:58:48 autopkgtest kernel: evm: security.apparmor 408s Jul 05 10:58:48 autopkgtest kernel: evm: security.ima 408s Jul 05 10:58:48 autopkgtest kernel: evm: security.capability 408s Jul 05 10:58:48 autopkgtest kernel: evm: HMAC attrs: 0x1 408s Jul 05 10:58:48 autopkgtest kernel: SED: plpks not available 408s Jul 05 10:58:48 autopkgtest kernel: clk: Disabling unused clocks 408s Jul 05 10:58:48 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 408s Jul 05 10:58:48 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8832K 408s Jul 05 10:58:48 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 408s Jul 05 10:58:48 autopkgtest kernel: Run /init as init process 408s Jul 05 10:58:48 autopkgtest kernel: with arguments: 408s Jul 05 10:58:48 autopkgtest kernel: /init 408s Jul 05 10:58:48 autopkgtest kernel: earlyprintk 408s Jul 05 10:58:48 autopkgtest kernel: with environment: 408s Jul 05 10:58:48 autopkgtest kernel: HOME=/ 408s Jul 05 10:58:48 autopkgtest kernel: TERM=linux 408s Jul 05 10:58:48 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic 408s Jul 05 10:58:48 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 408s Jul 05 10:58:48 autopkgtest kernel: raid6: vpermxor8 gen() 19505 MB/s 408s Jul 05 10:58:48 autopkgtest kernel: raid6: vpermxor4 gen() 16968 MB/s 408s Jul 05 10:58:48 autopkgtest kernel: raid6: vpermxor2 gen() 13195 MB/s 408s Jul 05 10:58:48 autopkgtest kernel: raid6: vpermxor1 gen() 11935 MB/s 408s Jul 05 10:58:48 autopkgtest kernel: raid6: altivecx8 gen() 12451 MB/s 408s Jul 05 10:58:48 autopkgtest kernel: raid6: altivecx4 gen() 12363 MB/s 408s Jul 05 10:58:48 autopkgtest kernel: raid6: altivecx2 gen() 10019 MB/s 408s Jul 05 10:58:48 autopkgtest kernel: raid6: altivecx1 gen() 7734 MB/s 408s Jul 05 10:58:48 autopkgtest kernel: raid6: int64x8 gen() 6527 MB/s 408s Jul 05 10:58:48 autopkgtest kernel: raid6: int64x4 gen() 7734 MB/s 408s Jul 05 10:58:48 autopkgtest kernel: raid6: int64x2 gen() 5941 MB/s 408s Jul 05 10:58:48 autopkgtest kernel: raid6: int64x1 gen() 4710 MB/s 408s Jul 05 10:58:48 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 19505 MB/s 408s Jul 05 10:58:48 autopkgtest kernel: raid6: using intx1 recovery algorithm 408s Jul 05 10:58:48 autopkgtest kernel: xor: measuring software checksum speed 408s Jul 05 10:58:48 autopkgtest kernel: 8regs : 15548 MB/sec 408s Jul 05 10:58:48 autopkgtest kernel: 8regs_prefetch : 13892 MB/sec 408s Jul 05 10:58:48 autopkgtest kernel: 32regs : 15566 MB/sec 408s Jul 05 10:58:48 autopkgtest kernel: 32regs_prefetch : 13934 MB/sec 408s Jul 05 10:58:48 autopkgtest kernel: altivec : 17373 MB/sec 408s Jul 05 10:58:48 autopkgtest kernel: xor: using function: altivec (17373 MB/sec) 408s Jul 05 10:58:48 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 408s Jul 05 10:58:48 autopkgtest kernel: EXT4-fs (sda1): orphan cleanup on readonly fs 408s Jul 05 10:58:48 autopkgtest kernel: EXT4-fs (sda1): mounted filesystem d56a6f84-56d9-4867-a447-bcf23bdbf13a ro with ordered data mode. Quota mode: none. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Inserted module 'autofs4' 408s Jul 05 10:58:48 autopkgtest systemd[1]: systemd 255.4-1ubuntu8 running in system mode (+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 -PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD -BPF_FRAMEWORK -XKBCOMMON +UTMP +SYSVINIT default-hierarchy=unified) 408s Jul 05 10:58:48 autopkgtest systemd[1]: Detected virtualization kvm. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Detected architecture ppc64-le. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Hostname set to . 408s Jul 05 10:58:48 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. 408s Jul 05 10:58:48 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. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Queued start job for default target graphical.target. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Reached target swap.target - Swaps. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Listening on multipathd.socket - multipathd control socket. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 408s Jul 05 10:58:48 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Socket. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting modprobe@dm_mod.service - Load Kernel Module dm_mod... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting modprobe@loop.service - Load Kernel Module loop... 408s Jul 05 10:58:48 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 408s Jul 05 10:58:48 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). 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 408s Jul 05 10:58:48 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 408s Jul 05 10:58:48 autopkgtest systemd[1]: modprobe@dm_mod.service: Deactivated successfully. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished modprobe@dm_mod.service - Load Kernel Module dm_mod. 408s Jul 05 10:58:48 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 408s Jul 05 10:58:48 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 408s Jul 05 10:58:48 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 408s Jul 05 10:58:48 autopkgtest systemd[1]: modprobe@loop.service: Deactivated successfully. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished modprobe@loop.service - Load Kernel Module loop. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 408s Jul 05 10:58:48 autopkgtest systemd-journald[299]: Collecting audit messages is disabled. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 408s Jul 05 10:58:48 autopkgtest systemd[1]: systemd-repart.service - Repartition Root Disk was skipped because no trigger condition checks were met. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 408s Jul 05 10:58:48 autopkgtest kernel: EXT4-fs (sda1): re-mounted d56a6f84-56d9-4867-a447-bcf23bdbf13a r/w. Quota mode: none. 408s Jul 05 10:58:48 autopkgtest systemd-journald[299]: Journal started 408s Jul 05 10:58:48 autopkgtest systemd-journald[299]: Runtime Journal (/run/log/journal/494b13dafb474840bd1ec45613dc7be2) is 8.0M, max 78.4M, 70.4M free. 408s Jul 05 10:58:48 autopkgtest systemd-modules-load[300]: Inserted module 'dm_multipath' 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 408s Jul 05 10:58:48 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 408s Jul 05 10:58:48 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 408s Jul 05 10:58:48 autopkgtest systemd-journald[299]: Time spent on flushing to /var/log/journal/494b13dafb474840bd1ec45613dc7be2 is 23.975ms for 417 entries. 408s Jul 05 10:58:48 autopkgtest systemd-journald[299]: System Journal (/var/log/journal/494b13dafb474840bd1ec45613dc7be2) is 44.9M, max 4.0G, 3.9G free. 408s Jul 05 10:58:48 autopkgtest systemd-journald[299]: Received client request to flush runtime journal. 408s Jul 05 10:58:48 autopkgtest systemd-journald[299]: /var/log/journal/494b13dafb474840bd1ec45613dc7be2/system.journal: Journal file uses a different sequence number ID, rotating. 408s Jul 05 10:58:48 autopkgtest systemd-journald[299]: Rotating system journal. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 408s Jul 05 10:58:48 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 408s Jul 05 10:58:48 autopkgtest multipathd[335]: multipathd v0.9.4: start up 408s Jul 05 10:58:48 autopkgtest multipathd[335]: reconfigure: setting up paths and maps 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 408s Jul 05 10:58:48 autopkgtest systemd-random-seed[334]: Kernel entropy pool is not initialized yet, waiting until it is. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management (Varlink). 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 408s Jul 05 10:58:48 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 408s Jul 05 10:58:48 autopkgtest apparmor.systemd[352]: Restarting AppArmor 408s Jul 05 10:58:48 autopkgtest apparmor.systemd[352]: Reloading AppArmor profiles 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 408s Jul 05 10:58:48 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 357 (systemd-binfmt) 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 408s Jul 05 10:58:48 autopkgtest kernel: audit: type=1400 audit(1720177128.428:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=372 comm="apparmor_parser" 408s Jul 05 10:58:48 autopkgtest kernel: audit: type=1400 audit(1720177128.428:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=370 comm="apparmor_parser" 408s Jul 05 10:58:48 autopkgtest kernel: audit: type=1400 audit(1720177128.428:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=369 comm="apparmor_parser" 408s Jul 05 10:58:48 autopkgtest kernel: audit: type=1400 audit(1720177128.428:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=371 comm="apparmor_parser" 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create Volatile Files and Directories... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 408s Jul 05 10:58:48 autopkgtest kernel: audit: type=1400 audit(1720177128.436:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=380 comm="apparmor_parser" 408s Jul 05 10:58:48 autopkgtest kernel: audit: type=1400 audit(1720177128.436:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=381 comm="apparmor_parser" 408s Jul 05 10:58:48 autopkgtest kernel: audit: type=1400 audit(1720177128.440:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=384 comm="apparmor_parser" 408s Jul 05 10:58:48 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 408s Jul 05 10:58:48 autopkgtest systemd-udevd[345]: Using default interface naming scheme 'v255'. 408s Jul 05 10:58:48 autopkgtest kernel: audit: type=1400 audit(1720177128.444:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="ch-checkns" pid=389 comm="apparmor_parser" 408s Jul 05 10:58:48 autopkgtest kernel: audit: type=1400 audit(1720177128.444:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="cam" pid=387 comm="apparmor_parser" 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 408s Jul 05 10:58:48 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 408s Jul 05 10:58:48 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 408s Jul 05 10:58:48 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). 408s Jul 05 10:58:48 autopkgtest systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create Volatile Files and Directories. 408s Jul 05 10:58:48 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 408s Jul 05 10:58:48 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 408s Jul 05 10:58:48 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 408s Jul 05 10:58:48 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 408s Jul 05 10:58:48 autopkgtest (udev-worker)[426]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 408s Jul 05 10:58:48 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 408s Jul 05 10:58:48 autopkgtest systemd-resolved[427]: Positive Trust Anchors: 408s Jul 05 10:58:48 autopkgtest systemd-resolved[427]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 408s Jul 05 10:58:48 autopkgtest systemd-resolved[427]: 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 corp home internal intranet lan local private test 408s Jul 05 10:58:48 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 408s Jul 05 10:58:48 autopkgtest kernel: random: crng init done 408s Jul 05 10:58:48 autopkgtest systemd-resolved[427]: Using system hostname 'autopkgtest'. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 408s Jul 05 10:58:48 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 408s Jul 05 10:58:48 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 408s Jul 05 10:58:48 autopkgtest systemd[1]: systemd-machine-id-commit.service - Commit a transient machine-id on disk was skipped because of an unmet condition check (ConditionPathIsMountPoint=/etc/machine-id). 408s Jul 05 10:58:48 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 408s Jul 05 10:58:49 autopkgtest cloud-init[663]: Cloud-init v. 24.2-0ubuntu1 running 'init-local' at Fri, 05 Jul 2024 10:58:49 +0000. Up 4.02 seconds. 408s Jul 05 10:58:49 autopkgtest dhcpcd[666]: dhcpcd-10.0.8 starting 408s Jul 05 10:58:49 autopkgtest dhcpcd[669]: DUID 00:01:00:01:2e:19:f7:b4:fa:16:3e:bf:df:61 408s Jul 05 10:58:49 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 408s Jul 05 10:58:49 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 408s Jul 05 10:58:49 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 408s Jul 05 10:58:49 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 408s Jul 05 10:58:49 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 408s Jul 05 10:58:49 autopkgtest dhcpcd[669]: enp0s1: IAID 3e:84:86:77 408s Jul 05 10:58:50 autopkgtest dhcpcd[669]: enp0s1: rebinding lease of 10.44.124.136 408s Jul 05 10:58:55 autopkgtest dhcpcd[669]: enp0s1: DHCP lease expired 408s Jul 05 10:58:55 autopkgtest dhcpcd[669]: enp0s1: soliciting a DHCP lease 408s Jul 05 10:58:55 autopkgtest dhcpcd[669]: enp0s1: offered 10.44.124.136 from 10.44.124.241 408s Jul 05 10:58:55 autopkgtest dhcpcd[669]: enp0s1: leased 10.44.124.136 for 86400 seconds 408s Jul 05 10:58:55 autopkgtest dhcpcd[669]: enp0s1: adding route to 10.44.124.0/24 408s Jul 05 10:58:55 autopkgtest dhcpcd[669]: enp0s1: adding host route to 169.254.169.254 via 10.44.124.1 408s Jul 05 10:58:55 autopkgtest dhcpcd[669]: enp0s1: adding default route via 10.44.124.1 408s Jul 05 10:58:55 autopkgtest dhcpcd[669]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 408s Jul 05 10:58:57 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 408s Jul 05 10:58:57 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 408s Jul 05 10:58:57 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 408s Jul 05 10:58:57 autopkgtest systemd-networkd[700]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 408s Jul 05 10:58:57 autopkgtest systemd-networkd[700]: lo: Link UP 408s Jul 05 10:58:57 autopkgtest systemd-networkd[700]: lo: Gained carrier 408s Jul 05 10:58:57 autopkgtest systemd-networkd[700]: Enumeration completed 408s Jul 05 10:58:57 autopkgtest systemd-networkd[700]: enp0s1: Link UP 408s Jul 05 10:58:57 autopkgtest systemd-networkd[700]: enp0s1: Gained carrier 408s Jul 05 10:58:57 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 408s Jul 05 10:58:57 autopkgtest systemd-networkd[700]: enp0s1: Gained IPv6LL 408s Jul 05 10:58:57 autopkgtest systemd[1]: Reached target network.target - Network. 408s Jul 05 10:58:57 autopkgtest systemd-networkd[700]: enp0s1: Link DOWN 408s Jul 05 10:58:57 autopkgtest systemd-networkd[700]: enp0s1: Lost carrier 408s Jul 05 10:58:57 autopkgtest systemd-networkd[700]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 408s Jul 05 10:58:57 autopkgtest systemd-networkd[700]: enp0s1: Link UP 408s Jul 05 10:58:57 autopkgtest systemd-networkd[700]: enp0s1: Gained carrier 408s Jul 05 10:58:57 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 408s Jul 05 10:58:57 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 408s Jul 05 10:58:57 autopkgtest systemd-networkd[700]: enp0s1: DHCPv4 address 10.44.124.136/24, gateway 10.44.124.1 acquired from 10.44.124.241 408s Jul 05 10:58:57 autopkgtest systemd-timesyncd[476]: Network configuration changed, trying to establish connection. 408s Jul 05 10:58:58 autopkgtest systemd-networkd[700]: enp0s1: Gained IPv6LL 408s Jul 05 10:58:58 autopkgtest systemd-timesyncd[476]: Network configuration changed, trying to establish connection. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Starting cloud-init.service - Cloud-init: Network Stage... 408s Jul 05 10:58:58 autopkgtest systemd-resolved[427]: Clock change detected. Flushing caches. 408s Jul 05 10:58:58 autopkgtest systemd-journald[299]: Time jumped backwards, rotating. 408s Jul 05 10:58:58 autopkgtest systemd-timesyncd[476]: Contacted time server 185.125.190.56:123 (ntp.ubuntu.com). 408s Jul 05 10:58:58 autopkgtest systemd-timesyncd[476]: Initial clock synchronization to Fri 2024-07-05 10:58:58.294949 UTC. 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: Cloud-init v. 24.2-0ubuntu1 running 'init' at Fri, 05 Jul 2024 10:58:58 +0000. Up 13.85 seconds. 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | enp0s1 | True | 10.44.124.136 | 255.255.255.0 | global | fa:16:3e:84:86:77 | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | enp0s1 | True | fe80::f816:3eff:fe84:8677/64 | . | link | fa:16:3e:84:86:77 | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | lo | True | ::1/128 | . | host | . | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info++++++++++++++++++++++++++++++++ 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | 0 | 0.0.0.0 | 10.44.124.1 | 0.0.0.0 | enp0s1 | UG | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | 1 | 10.44.124.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | 2 | 10.44.124.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | 3 | 91.189.91.130 | 10.44.124.1 | 255.255.255.255 | enp0s1 | UGH | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | 4 | 169.254.169.254 | 10.44.124.1 | 255.255.255.255 | enp0s1 | UGH | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: +-------+-------------+---------+-----------+-------+ 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | Route | Destination | Gateway | Interface | Flags | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: +-------+-------------+---------+-----------+-------+ 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | 2 | local | :: | enp0s1 | U | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: | 3 | multicast | :: | enp0s1 | U | 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: ci-info: +-------+-------------+---------+-----------+-------+ 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: 2024-07-05 10:58:58,750 - 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. 408s Jul 05 10:58:58 autopkgtest cloud-init[709]: 2024-07-05 10:58:58,752 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Finished cloud-init.service - Cloud-init: Network Stage. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 408s Jul 05 10:58:58 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). 408s Jul 05 10:58:58 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). 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started sysstat-collect.timer - Run system activity accounting tool every 10 minutes. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started sysstat-rotate.timer - Rotate daily system activity data file at midnight. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started sysstat-summary.timer - Generate summary of yesterday's process accounting. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 408s Jul 05 10:58:58 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). 408s Jul 05 10:58:58 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Reached target paths.target - Path Units. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 408s Jul 05 10:58:58 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 408s Jul 05 10:58:58 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 408s Jul 05 10:58:58 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Reached target basic.target - Basic System. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 408s Jul 05 10:58:58 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 408s Jul 05 10:58:58 autopkgtest (sh)[746]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 408s Jul 05 10:58:58 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 408s Jul 05 10:58:58 autopkgtest (cron)[748]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 408s Jul 05 10:58:58 autopkgtest cron[748]: (CRON) INFO (pidfile fd = 3) 408s Jul 05 10:58:58 autopkgtest cron[748]: (CRON) INFO (Running @reboot jobs) 408s Jul 05 10:58:58 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 408s Jul 05 10:58:58 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). 408s Jul 05 10:58:58 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 408s Jul 05 10:58:58 autopkgtest systemd-logind[743]: New seat seat0. 408s Jul 05 10:58:58 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 408s Jul 05 10:58:58 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 408s Jul 05 10:58:58 autopkgtest dbus-daemon[749]: [system] AppArmor D-Bus mediation is enabled 408s Jul 05 10:58:58 autopkgtest systemd[1]: opal_errd.service - opal_errd (PowerNV platform error handling) Service was skipped because of an unmet condition check (ConditionVirtualization=false). 408s Jul 05 10:58:58 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). 408s Jul 05 10:58:58 autopkgtest dbus-daemon[749]: [system] Activating systemd to hand-off: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.3' (uid=998 pid=700 comm="/usr/lib/systemd/systemd-networkd" label="unconfined") 408s Jul 05 10:58:58 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 408s Jul 05 10:58:58 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 408s Jul 05 10:58:58 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting sysstat.service - Resets System Activity Logs... 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 408s Jul 05 10:58:59 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). 408s Jul 05 10:58:59 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 408s Jul 05 10:58:59 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Finished sysstat.service - Resets System Activity Logs. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 408s Jul 05 10:58:59 autopkgtest dbus-daemon[749]: [system] Successfully activated service 'org.freedesktop.systemd1' 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 408s Jul 05 10:58:59 autopkgtest udisksd[766]: udisks daemon version 2.10.1 starting 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 408s Jul 05 10:58:59 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 408s Jul 05 10:58:59 autopkgtest rng-tools-debian[806]: found /dev/hwrng but could not use it 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 408s Jul 05 10:58:59 autopkgtest rng-tools-debian[808]: not starting: no hardware RNG device found 408s Jul 05 10:58:59 autopkgtest rng-tools-debian[757]: * Configuring Hardware RNG entropy gatherer daemon 408s Jul 05 10:58:59 autopkgtest rng-tools-debian[757]: ...fail! 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting systemd-hostnamed.service - Hostname Service... 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 408s Jul 05 10:58:59 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 408s Jul 05 10:58:59 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 408s Jul 05 10:58:59 autopkgtest kernel: kauditd_printk_skb: 110 callbacks suppressed 408s Jul 05 10:58:59 autopkgtest kernel: audit: type=1400 audit(1720177139.182:121): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=782 comm="apparmor_parser" 408s Jul 05 10:58:59 autopkgtest udisksd[766]: Acquired the name org.freedesktop.UDisks2 on the system message bus 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 408s Jul 05 10:58:59 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 408s Jul 05 10:58:59 autopkgtest dbus-daemon[749]: [system] Successfully activated service 'org.freedesktop.hostname1' 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started systemd-hostnamed.service - Hostname Service. 408s Jul 05 10:58:59 autopkgtest systemd-networkd[700]: Could not set hostname: Access denied 408s Jul 05 10:58:59 autopkgtest rsyslogd[828]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2312.0] 408s Jul 05 10:58:59 autopkgtest rsyslogd[828]: rsyslogd's groupid changed to 102 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 408s Jul 05 10:58:59 autopkgtest rsyslogd[828]: rsyslogd's userid changed to 102 408s Jul 05 10:58:59 autopkgtest rsyslogd[828]: [origin software="rsyslogd" swVersion="8.2312.0" x-pid="828" x-info="https://www.rsyslog.com"] start 408s Jul 05 10:58:59 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 408s Jul 05 10:58:59 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 408s Jul 05 10:58:59 autopkgtest cloud-init[839]: Cloud-init v. 24.2-0ubuntu1 running 'modules:config' at Fri, 05 Jul 2024 10:58:59 +0000. Up 14.62 seconds. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 408s Jul 05 10:58:59 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 408s Jul 05 10:58:59 autopkgtest sshd[844]: Server listening on :: port 22. 408s Jul 05 10:58:59 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 408s Jul 05 10:58:59 autopkgtest cloud-init[850]: Cloud-init v. 24.2-0ubuntu1 running 'modules:final' at Fri, 05 Jul 2024 10:58:59 +0000. Up 15.13 seconds. 408s Jul 05 10:58:59 autopkgtest cloud-init[850]: Cloud-init v. 24.2-0ubuntu1 finished at Fri, 05 Jul 2024 10:58:59 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 15.21 seconds 408s Jul 05 10:59:00 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 408s Jul 05 10:59:00 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 408s Jul 05 10:59:00 autopkgtest systemd[1]: Startup finished in 2.770s (kernel) + 12.492s (userspace) = 15.263s. 408s Jul 05 10:59:00 autopkgtest kernel: fbcon: Taking over console 408s Jul 05 10:59:00 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 408s Jul 05 10:59:00 autopkgtest sshd[845]: Accepted publickey for ubuntu from 10.136.6.201 port 36342 ssh2: RSA SHA256:YaYyKWTl9zFJEBK5G3u+MRj3WPJt+vEplFd0J96PUBw 408s Jul 05 10:59:00 autopkgtest sshd[845]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 408s Jul 05 10:59:00 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 408s Jul 05 10:59:00 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 408s Jul 05 10:59:00 autopkgtest systemd-logind[743]: New session 1 of user ubuntu. 408s Jul 05 10:59:00 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 408s Jul 05 10:59:00 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 408s Jul 05 10:59:00 autopkgtest (systemd)[876]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 408s Jul 05 10:59:00 autopkgtest systemd[876]: Queued start job for default target default.target. 408s Jul 05 10:59:00 autopkgtest systemd[876]: Created slice app.slice - User Application Slice. 408s Jul 05 10:59:00 autopkgtest systemd[876]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 408s Jul 05 10:59:00 autopkgtest systemd[876]: Reached target paths.target - Paths. 408s Jul 05 10:59:00 autopkgtest systemd[876]: Reached target timers.target - Timers. 408s Jul 05 10:59:00 autopkgtest systemd[876]: Starting dbus.socket - D-Bus User Message Bus Socket... 408s Jul 05 10:59:00 autopkgtest systemd[876]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 408s Jul 05 10:59:00 autopkgtest systemd[876]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 408s Jul 05 10:59:00 autopkgtest systemd[876]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 408s Jul 05 10:59:00 autopkgtest systemd[876]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 408s Jul 05 10:59:00 autopkgtest systemd[876]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 408s Jul 05 10:59:00 autopkgtest systemd[876]: Listening on keyboxd.socket - GnuPG public key management service. 408s Jul 05 10:59:00 autopkgtest systemd[876]: Listenin+ echo Test WWN should now point to DM 408s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 408s + grep dm 408s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 408s mke2fs 1.47.1 (20-May-2024) 408s + udevadm settle 408s + sleep 3s 408s g on dbus.socket - D-Bus User Message Bus Socket. 408s Jul 05 10:59:00 autopkgtest systemd[876]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 408s Jul 05 10:59:00 autopkgtest systemd[876]: Reached target sockets.target - Sockets. 408s Jul 05 10:59:00 autopkgtest systemd[876]: Reached target basic.target - Basic System. 408s Jul 05 10:59:00 autopkgtest systemd[876]: Reached target default.target - Main User Target. 408s Jul 05 10:59:00 autopkgtest systemd[876]: Startup finished in 188ms. 408s Jul 05 10:59:00 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 408s Jul 05 10:59:00 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 408s Jul 05 10:59:01 autopkgtest sudo[904]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 408s Jul 05 10:59:01 autopkgtest sudo[904]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:01 autopkgtest sudo[904]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:01 autopkgtest sudo[909]: 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' 408s Jul 05 10:59:01 autopkgtest sudo[909]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:01 autopkgtest sudo[909]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:01 autopkgtest sudo[921]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.LIWM2n 408s Jul 05 10:59:01 autopkgtest sudo[921]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:01 autopkgtest sudo[921]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:01 autopkgtest sudo[931]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.LIWM2n/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.LIWM2n/autopkgtest-reboot' 408s Jul 05 10:59:01 autopkgtest sudo[931]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:01 autopkgtest sudo[931]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:02 autopkgtest sudo[943]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.LIWM2n/autopkgtest-reboot 408s Jul 05 10:59:02 autopkgtest sudo[943]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:02 autopkgtest sudo[943]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:02 autopkgtest sudo[953]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.LIWM2n/autopkgtest-reboot /tmp/autopkgtest-reboot 408s Jul 05 10:59:02 autopkgtest sudo[953]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:02 autopkgtest sudo[953]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:02 autopkgtest sudo[963]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.LIWM2n/autopkgtest-reboot /sbin/autopkgtest-reboot 408s Jul 05 10:59:02 autopkgtest sudo[963]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:02 autopkgtest sudo[963]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:02 autopkgtest sudo[973]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.LIWM2n 408s Jul 05 10:59:02 autopkgtest sudo[973]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:02 autopkgtest sudo[973]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:02 autopkgtest sudo[983]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.LIWM2n/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.LIWM2n/autopkgtest-reboot-prepare' 408s Jul 05 10:59:02 autopkgtest sudo[983]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:02 autopkgtest sudo[983]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:02 autopkgtest sudo[995]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.LIWM2n/autopkgtest-reboot-prepare 408s Jul 05 10:59:02 autopkgtest sudo[995]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:02 autopkgtest sudo[995]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:03 autopkgtest sudo[1005]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.LIWM2n/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 408s Jul 05 10:59:03 autopkgtest sudo[1005]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:03 autopkgtest sudo[1005]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:03 autopkgtest sudo[1015]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 408s Jul 05 10:59:03 autopkgtest sudo[1015]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:03 autopkgtest sudo[1015]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:03 autopkgtest sudo[1025]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 408s Jul 05 10:59:03 autopkgtest sudo[1025]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:03 autopkgtest sudo[1025]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:03 autopkgtest sudo[1035]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.LIWM2n/testbed-packages' 408s Jul 05 10:59:03 autopkgtest sudo[1035]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:03 autopkgtest sudo[1035]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:03 autopkgtest sudo[1046]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.LIWM2n/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.LIWM2n/autopkgtest-reboot' 408s Jul 05 10:59:04 autopkgtest sudo[1067]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:04 autopkgtest sudo[1067]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:04 autopkgtest sudo[1079]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.LIWM2n/autopkgtest-reboot 408s Jul 05 10:59:04 autopkgtest sudo[1079]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:04 autopkgtest sudo[1079]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:04 autopkgtest sudo[1089]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.LIWM2n/autopkgtest-reboot /tmp/autopkgtest-reboot 408s Jul 05 10:59:04 autopkgtest sudo[1089]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:04 autopkgtest sudo[1089]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:04 autopkgtest sudo[1099]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.LIWM2n/autopkgtest-reboot /sbin/autopkgtest-reboot 408s Jul 05 10:59:04 autopkgtest sudo[1099]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:04 autopkgtest sudo[1099]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:05 autopkgtest sudo[1109]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.LIWM2n 408s Jul 05 10:59:05 autopkgtest sudo[1109]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:05 autopkgtest sudo[1109]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:05 autopkgtest sudo[1119]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.LIWM2n/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.LIWM2n/autopkgtest-reboot-prepare' 408s Jul 05 10:59:05 autopkgtest sudo[1119]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:05 autopkgtest sudo[1119]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:05 autopkgtest sudo[1131]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.LIWM2n/autopkgtest-reboot-prepare 408s Jul 05 10:59:05 autopkgtest sudo[1131]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:05 autopkgtest sudo[1131]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:05 autopkgtest sudo[1141]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.LIWM2n/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 408s Jul 05 10:59:05 autopkgtest sudo[1141]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:05 autopkgtest sudo[1141]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:05 autopkgtest sudo[1151]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 408s Jul 05 10:59:05 autopkgtest sudo[1151]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:05 autopkgtest sudo[1151]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:06 autopkgtest sudo[1161]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 408s Jul 05 10:59:06 autopkgtest sudo[1161]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:06 autopkgtest sudo[1161]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:06 autopkgtest sudo[1170]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.LIWM2n 408s Jul 05 10:59:06 autopkgtest sudo[1170]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:06 autopkgtest sudo[1170]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:06 autopkgtest sudo[1180]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.LIWM2n/2-autopkgtest-satdep.deb' 408s Jul 05 10:59:06 autopkgtest sudo[1180]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:06 autopkgtest sudo[1180]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:06 autopkgtest sudo[1191]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.LIWM2n/2-autopkgtest-satdep.deb 408s Jul 05 10:59:06 autopkgtest sudo[1191]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:06 autopkgtest sudo[1191]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:06 autopkgtest sudo[1201]: 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.LIWM2n/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' 408s Jul 05 10:59:06 autopkgtest sudo[1201]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:11 autopkgtest systemd[1]: Reloading requested from client PID 1441 ('systemctl') (unit session-1.scope)... 408s Jul 05 10:59:11 autopkgtest systemd[1]: Reloading... 408s Jul 05 10:59:11 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. 408s Jul 05 10:59:11 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. 408s Jul 05 10:59:11 autopkgtest systemd[1]: Reloading finished in 242 ms. 408s Jul 05 10:59:12 autopkgtest systemd[1]: Reloading requested from client PID 1489 ('systemctl') (unit session-1.scope)... 408s Jul 05 10:59:12 autopkgtest systemd[1]: Reloading... 408s Jul 05 10:59:12 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. 408s Jul 05 10:59:12 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. 408s Jul 05 10:59:12 autopkgtest systemd[1]: Reloading finished in 251 ms. 408s Jul 05 10:59:12 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 408s Jul 05 10:59:12 autopkgtest tgtd[1532]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 408s Jul 05 10:59:12 autopkgtest tgtd[1532]: tgtd: work_timer_start(146) use timer_fd based scheduler 408s Jul 05 10:59:12 autopkgtest tgtd[1532]: tgtd: bs_init(387) use signalfd notification 408s Jul 05 10:59:12 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 408s Jul 05 10:59:12 autopkgtest systemd[1]: Reloading requested from client PID 1559 ('systemctl') (unit session-1.scope)... 408s Jul 05 10:59:12 autopkgtest systemd[1]: Reloading... 408s Jul 05 10:59:12 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. 408s Jul 05 10:59:12 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. 408s Jul 05 10:59:13 autopkgtest systemd[1]: Reloading finished in 254 ms. 408s Jul 05 10:59:13 autopkgtest systemd[1]: Reloading requested from client PID 1600 ('systemctl') (unit session-1.scope)... 408s Jul 05 10:59:13 autopkgtest systemd[1]: Reloading... 408s Jul 05 10:59:13 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. 408s Jul 05 10:59:13 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. 408s Jul 05 10:59:13 autopkgtest systemd[1]: Reloading finished in 264 ms. 408s Jul 05 10:59:13 autopkgtest systemd[1]: Reloading requested from client PID 1643 ('systemctl') (unit session-1.scope)... 408s Jul 05 10:59:13 autopkgtest systemd[1]: Reloading... 408s Jul 05 10:59:13 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. 408s Jul 05 10:59:13 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. 408s Jul 05 10:59:13 autopkgtest systemd[1]: Reloading finished in 258 ms. 408s Jul 05 10:59:13 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 408s Jul 05 10:59:14 autopkgtest systemd[1]: Reloading requested from client PID 1691 ('systemctl') (unit session-1.scope)... 408s Jul 05 10:59:14 autopkgtest systemd[1]: Reloading... 408s Jul 05 10:59:14 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. 408s Jul 05 10:59:14 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. 408s Jul 05 10:59:14 autopkgtest systemd[1]: Reloading finished in 263 ms. 408s Jul 05 10:59:14 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 408s Jul 05 10:59:14 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 408s Jul 05 10:59:14 autopkgtest systemd[1]: Reloading requested from client PID 1743 ('systemctl') (unit session-1.scope)... 408s Jul 05 10:59:14 autopkgtest systemd[1]: Reloading... 408s Jul 05 10:59:14 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. 408s Jul 05 10:59:14 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. 408s Jul 05 10:59:14 autopkgtest systemd[1]: Reloading finished in 265 ms. 408s Jul 05 10:59:24 autopkgtest sudo[1201]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:24 autopkgtest sudo[5205]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 408s Jul 05 10:59:24 autopkgtest sudo[5205]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:24 autopkgtest sudo[5205]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:24 autopkgtest sudo[5215]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 408s Jul 05 10:59:24 autopkgtest sudo[5215]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:24 autopkgtest sudo[5215]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:24 autopkgtest sudo[5225]: 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 408s Jul 05 10:59:24 autopkgtest sudo[5225]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:25 autopkgtest sudo[5225]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:25 autopkgtest sudo[5238]: 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 408s Jul 05 10:59:25 autopkgtest sudo[5238]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:26 autopkgtest sudo[5238]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:26 autopkgtest sudo[5250]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 408s Jul 05 10:59:26 autopkgtest sudo[5250]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:26 autopkgtest sudo[5250]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:26 autopkgtest sudo[5262]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 408s Jul 05 10:59:26 autopkgtest sudo[5262]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:26 autopkgtest sudo[5262]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:26 autopkgtest sudo[5272]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.LIWM2n/tgtbasedmpaths-packages.all' 408s Jul 05 10:59:26 autopkgtest sudo[5272]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 408s Jul 05 10:59:26 autopkgtest sudo[5272]: pam_unix(sudo:session): session closed for user root 408s Jul 05 10:59:27 autopkgtest sudo[5283]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 412s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 412s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 412s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 412s latency : target=0, window=0, percentile=100.00%, depth=1 412s 412s Run status group 0 (all jobs): 412s WRITE: bw=80.2MiB/s (84.1MB/s), 80.2MiB/s-80.2MiB/s (84.1MB/s-84.1MB/s), io=87.5MiB (91.8MB), run=1091-1091msec 412s 412s Disk stats (read/write): 412s dm-0: ios=1/1118, sectors=8/143104, merge=0/0, ticks=0/845, in_queue=844, util=90.19%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/251, aggrin_queue=251, aggrutil=90.70% 412s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 412s sdb: ios=1/1402, sectors=8/179280, merge=0/0, ticks=0/1004, in_queue=1004, util=90.70% 412s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 412s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 412s Starting the path changes in background 412s + echo Starting the path changes in background 412s + date +Pre FIO %H:%M:%S.%N 412s Pre FIO 10:59:39.653316786 412s + fio --max-jobs=4 /tmp/autopkgtest.LIWM2n/tgtbasedmpaths-artifacts/path-change-check.fio 412s 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 412s fio-3.37 412s Starting 1 thread 593s 593s verify-phase: (groupid=0, jobs=1): err= 0: pid=5646: Fri Jul 5 11:02:40 2024 593s read: IOPS=2670, BW=167MiB/s (175MB/s)(29.3GiB/180001msec) 593s clat (usec): min=96, max=67206, avg=348.70, stdev=344.72 593s lat (usec): min=97, max=67206, avg=348.82, stdev=344.73 593s clat percentiles (usec): 593s | 1.00th=[ 151], 5.00th=[ 172], 10.00th=[ 200], 20.00th=[ 225], 593s | 30.00th=[ 253], 40.00th=[ 293], 50.00th=[ 322], 60.00th=[ 347], 593s | 70.00th=[ 375], 80.00th=[ 404], 90.00th=[ 449], 95.00th=[ 529], 593s | 99.00th=[ 1254], 99.50th=[ 2008], 99.90th=[ 4555], 99.95th=[ 5669], 593s | 99.99th=[10028] 593s bw ( KiB/s): min=101632, max=342400, per=100.00%, avg=171035.95, stdev=38327.26, samples=359 593s iops : min= 1588, max= 5350, avg=2672.42, stdev=598.85, samples=359 593s lat (usec) : 100=0.01%, 250=29.35%, 500=64.62%, 750=4.01%, 1000=0.66% 593s lat (msec) : 2=0.85%, 4=0.35%, 10=0.14%, 20=0.01%, 50=0.01% 593s lat (msec) : 100=0.01% 593s cpu : usr=7.84%, sys=8.62%, ctx=480730, majf=0, minf=1 593s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 593s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 593s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 593s issued rwts: total=480642,0,0,0 short=0,0,0,0 dropped=0,0,0,0 593s latency : target=0, window=0, percentile=100.00%, depth=1 593s 593s Run status group 0 (all jobs): 593s READ: bw=167MiB/s (175MB/s), 167MiB/s-167MiB/s (175MB/s-175MB/s), io=29.3GiB (31.5GB), run=180001-180001msec 593s 593s Disk stats (read/write): 593s dm-0: ios=480800/13, sectors=61498296/12960, merge=33/10, ticks=173405/76, in_queue=173526, util=99.74%, aggrios=34317/3, aggsectors=4389326/3240, aggrmerge=0/0, aggrticks=10947/7, aggrin_queue=10955, aggrutil=99.10% 593s sdd: ios=27387/0, sectors=3502976/0, merge=0/0, ticks=8869/0, in_queue=8868, util=33.42% 593s sdb: ios=29539/12, sectors=3778048/12960, merge=0/0, ticks=8380/30, in_queue=8411, util=99.10% 593s sde: ios=53364/0, sectors=6825728/0, merge=0/0, ticks=17690/0, in_queue=17690, util=39.90% 593s sdc: ios=26978/0, sectors=3450552/0, merge=0/0, ticks=8852/0, in_queue=8852, util=50.08% 593s Post FIO 11:02:40.052820548 593s + date +Post FIO %H:%M:%S.%N 593s + echo FIO verify test with changing paths - OK 593s + echo Report log of background activity 593s + cat /tmp/autopkgtest.LIWM2n/tgtbasedmpaths-artifacts/test-background.log 593s + sync 593s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 593s + echo Final stats 593s + iscsiadm --mode session --stats 593s + journalctl --no-pager -u multipathd 593s + echo Check final path status 593s + multipath -ll 593s + multipath+ -ll 593s grep --count status= 593s FIO verify test with changing paths - OK 593s Report log of background activity 593s + iscsiadm --mode session 593s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s + sleep 10s 593s + date +MP report (expect 4) %H:%M:%S.%N 593s MP report (expect 4) 10:59:49.661368964 593s + multipath -ll 593s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 593s size=100M features='0' hwhandler='0' wp=rw 593s |-+- policy='service-time 0' prio=1 status=active 593s | `- 1:0:0:1 sdb 8:16 active ready running 593s |-+- policy='service-time 0' prio=1 status=enabled 593s | `- 2:0:0:1 sdc 8:32 active ready running 593s |-+- policy='service-time 0' prio=1 status=enabled 593s | `- 3:0:0:1 sdd 8:48 active ready running 593s `-+- policy='service-time 0' prio=1 status=enabled 593s `- 4:0:0:1 sde 8:64 active ready running 593s + date +UN-plug path 1 %H:%M:%S.%N 593s UN-plug path 1 10:59:49.693913704 593s + iscsiadm --mode session -r 1 -u 593s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 593s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 593s + iscsiadm --mode session 593s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s + sleep 10s 593s + date +MP report (expect 3) %H:%M:%S.%N 593s MP report (expect 3) 10:59:59.802998097 593s + multipath -ll 593s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 593s size=100M features='0' hwhandler='0' wp=rw 593s |-+- policy='service-time 0' prio=1 status=active 593s | `- 2:0:0:1 sdc 8:32 active ready running 593s |-+- policy='service-time 0' prio=1 status=enabled 593s | `- 3:0:0:1 sdd 8:48 active ready running 593s `-+- policy='service-time 0' prio=1 status=enabled 593s `- 4:0:0:1 sde 8:64 active ready running 593s + date +UN-plug path 2 %H:%M:%S.%N 593s UN-plug path 2 10:59:59.831704085 593s + iscsiadm --mode session -r 2 -u 593s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 593s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 593s + iscsiadm --mode session 593s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s + sleep 10s 593s + date +MP report (expect 2) %H:%M:%S.%N 593s MP report (expect 2) 11:00:09.963529755 593s + multipath -ll 593s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 593s size=100M features='0' hwhandler='0' wp=rw 593s |-+- policy='service-time 0' prio=1 status=active 593s | `- 3:0:0:1 sdd 8:48 active ready running 593s `-+- policy='service-time 0' prio=1 status=enabled 593s `- 4:0:0:1 sde 8:64 active ready running 593s + date +UN-plug path 3 %H:%M:%S.%N 593s UN-plug path 3 11:00:09.989828081 593s + iscsiadm --mode session -r 3 -u 593s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 593s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 593s + iscsiadm --mode session 593s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s + sleep 10s 593s + date +MP report (expect 1) %H:%M:%S.%N 593s MP report (expect 1) 11:00:20.114273640 593s + multipath -ll 593s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 593s size=100M features='0' hwhandler='0' wp=rw 593s `-+- policy='service-time 0' prio=1 status=active 593s `- 4:0:0:1 sde 8:64 active ready running 593s + date +Add paths 5/6/7/8 %H:%M:%S.%N 593s Add paths 5/6/7/8 11:00:20.147472981 593s + iscsiadm --mode session -r 4 --op new 593s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 593s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 593s + iscsiadm --mode session -r 4 --op new 593s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 593s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 593s + iscsiadm --mode session -r 4 --op new 593s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 593s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 593s + iscsiadm --mode session -r 4 --op new 593s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 593s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 593s + iscsiadm --mode session 593s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s + sleep 10s 593s + date +MP report (expect 5) %H:%M:%S.%N 593s MP report (expect 5) 11:00:30.342205619 593s + multipath -ll 593s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 593s size=100M features='0' hwhandler='0' wp=rw 593s |-+- policy='service-time 0' prio=1 status=active 593s | `- 4:0:0:1 sde 8:64 active ready running 593s |-+- policy='service-time 0' prio=1 status=enabled 593s | `- 1:0:0:1 sdb 8:16 active ready running 593s |-+- policy='service-time 0' prio=1 status=enabled 593s | `- 2:0:0:1 sdc 8:32 active ready running 593s |-+- policy='service-time 0' prio=1 status=enabled 593s | `- 3:0:0:1 sdd 8:48 active ready running 593s `-+- policy='service-time 0' prio=1 status=enabled 593s `- 5:0:0:1 sdf 8:80 active ready running 593s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 593s UN-plug multiple paths 4/7/8 11:00:30.385281993 593s + iscsiadm --mode session -r 4 -u 593s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 593s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 593s + iscsiadm --mode session -r 7 -u 593s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 593s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 593s + iscsiadm --mode session -r 8 -u 593s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 593s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 593s + iscsiadm --mode session 593s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 593s + sleep 10s 593s + date +Restart multipath daemon %H:%M:%S.%N 593s Restart multipath daemon 11:00:40.763159030 593s + systemctl restart multipathd 593s + sleep 10s 593s + date +Final background report (expect 2) %H:%M:%S.%N 593s Final background report (expect 2) 11:00:50.858166251 593s + multipath -ll 593s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 593s size=100M features='0' hwhandler='0' wp=rw 593s |-+- policy='service-time 0' prio=1 status=active 593s | `- 1:0:0:1 sdb 8:16 active ready running 593s `-+- policy='service-time 0' prio=1 status=enabled 593s `- 2:0:0:1 sdc 8:32 active ready running 593s Final stats 593s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 593s iSCSI SNMP: 593s txdata_octets: 16465176 593s rxdata_octets: 22457160068 593s noptx_pdus: 0 593s scsicmd_pdus: 342757 593s tmfcmd_pdus: 0 593s login_pdus: 0 593s text_pdus: 0 593s dataout_pdus: 0 593s logout_pdus: 0 593s snack_pdus: 0 593s noprx_pdus: 0 593s scsirsp_pdus: 342757 593s tmfrsp_pdus: 0 593s textrsp_pdus: 0 593s datain_pdus: 342723 593s logoutrsp_pdus: 0 593s r2t_pdus: 0 593s async_pdus: 0 593s rjt_pdus: 0 593s digest_err: 0 593s timeout_err: 0 593s iSCSI Extended: 593s tx_sendpage_failures: 0 593s rx_discontiguous_hdr: 0 593s eh_abort_cnt: 0 593s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 593s iSCSI SNMP: 593s txdata_octets: 6456 593s rxdata_octets: 1514916 593s noptx_pdus: 0 593s scsicmd_pdus: 104 593s tmfcmd_pdus: 0 593s login_pdus: 0 593s text_pdus: 0 593s dataout_pdus: 0 593s logout_pdus: 0 593s snack_pdus: 0 593s noprx_pdus: 0 593s scsirsp_pdus: 104 593s tmfrsp_pdus: 0 593s textrsp_pdus: 0 593s datain_pdus: 83 593s logoutrsp_pdus: 0 593s r2t_pdus: 0 593s async_pdus: 0 593s rjt_pdus: 0 593s digest_err: 0 593s timeout_err: 0 593s iSCSI Extended: 593s tx_sendpage_failures: 0 593s rx_discontiguous_hdr: 0 593s eh_abort_cnt: 0 593s Jul 05 00:15:46 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 593s Jul 05 00:15:46 ubuntu multipathd[328]: multipathd v0.9.4: start up 593s Jul 05 00:15:46 ubuntu multipathd[328]: reconfigure: setting up paths and maps 593s Jul 05 00:15:46 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 593s Jul 05 00:19:45 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[328]: multipathd: shut down 593s Jul 05 00:19:45 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 593s Jul 05 00:19:45 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: multipathd.service: Deactivated successfully. 593s Jul 05 00:19:45 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 593s -- Boot 86ef57e6108f4f4da0558586cf4adee5 -- 593s Jul 05 00:20:10 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 593s Jul 05 00:20:10 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[282]: multipathd v0.9.4: start up 593s Jul 05 00:20:10 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[282]: reconfigure: setting up paths and maps 593s Jul 05 00:20:10 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 593s Jul 05 00:20:30 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[282]: multipathd: shut down 593s Jul 05 00:20:30 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 593s Jul 05 00:20:30 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: multipathd.service: Deactivated successfully. 593s Jul 05 00:20:30 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 593s -- Boot e6af738a418648b4a6f8416d66c0924f -- 593s Jul 05 10:57:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 593s Jul 05 10:57:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[334]: multipathd v0.9.4: start up 593s Jul 05 10:57:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[334]: reconfigure: setting up paths and maps 593s Jul 05 10:57:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 593s Jul 05 10:58:22 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 593s Jul 05 10:58:22 autopkgtest multipathd[334]: multipathd: shut down 593s Jul 05 10:58:22 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 593s Jul 05 10:58:22 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 593s -- Boot 7306289c81d04cbfa2bd7b6d3f4e3409 -- 593s Jul 05 10:58:48 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 593s Jul 05 10:58:48 autopkgtest multipathd[335]: multipathd v0.9.4: start up 593s Jul 05 10:58:48 autopkgtest multipathd[335]: reconfigure: setting up paths and maps 593s Jul 05 10:58:48 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 593s Jul 05 10:59:29 autopkgtest multipathd[335]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:16 1] 593s Jul 05 10:59:29 autopkgtest multipathd[335]: sdb [8:16]: path added to devmap mpatha 593s Jul 05 10:59:29 autopkgtest multipathd[335]: mpatha: performing delayed actions 593s Jul 05 10:59:29 autopkgtest multipathd[335]: 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] 593s Jul 05 10:59:29 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 4 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 service-time 0 1 1 8:64 1] 593s Jul 05 10:59:29 autopkgtest multipathd[335]: sde [8:64]: path added to devmap mpatha 593s Jul 05 10:59:49 autopkgtest multipathd[335]: sdb: mark as failed 593s Jul 05 10:59:49 autopkgtest multipathd[335]: mpatha: remaining active paths: 3 593s Jul 05 10:59:49 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 593s Jul 05 10:59:49 autopkgtest multipathd[335]: check_removed_paths: sdb: freeing path in removed state 593s Jul 05 10:59:49 autopkgtest multipathd[335]: 8:16: path removed from map mpatha 593s Jul 05 10:59:59 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 593s Jul 05 10:59:59 autopkgtest multipathd[335]: check_removed_paths: sdc: freeing path in removed state 593s Jul 05 10:59:59 autopkgtest multipathd[335]: 8:32: path removed from map mpatha 593s Jul 05 11:00:10 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 593s Jul 05 11:00:10 autopkgtest multipathd[335]: check_removed_paths: sdd: freeing path in removed state 593s Jul 05 11:00:10 autopkgtest multipathd[335]: 8:48: path removed from map mpatha 593s Jul 05 11:00:20 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1] 593s Jul 05 11:00:20 autopkgtest multipathd[335]: sdb [8:16]: path added to devmap mpatha 593s Jul 05 11:00:20 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 593s Jul 05 11:00:20 autopkgtest multipathd[335]: sdc [8:32]: path added to devmap mpatha 593s Jul 05 11:00:20 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:64 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] 593s Jul 05 11:00:20 autopkgtest multipathd[335]: sdd [8:48]: path added to devmap mpatha 593s Jul 05 11:00:20 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:64 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 service-time 0 1 1 8:80 1] 593s Jul 05 11:00:20 autopkgtest multipathd[335]: sdf [8:80]: path added to devmap mpatha 593s Jul 05 11:00:30 autopkgtest multipathd[335]: sde: mark as failed 593s Jul 05 11:00:30 autopkgtest multipathd[335]: mpatha: remaining active paths: 4 593s Jul 05 11:00:30 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 4 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 service-time 0 1 1 8:80 1] 593s Jul 05 11:00:30 autopkgtest multipathd[335]: check_removed_paths: sde: freeing path in removed state 593s Jul 05 11:00:30 autopkgtest multipathd[335]: 8:64: path removed from map mpatha 593s Jul 05 11:00:30 autopkgtest multipathd[335]: 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:80 1] 593s Jul 05 11:00:30 autopkgtest multipathd[335]: check_removed_paths: sdd: freeing path in removed state 593s Jul 05 11:00:30 autopkgtest multipathd[335]: 8:48: path removed from map mpatha 593s Jul 05 11:00:30 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 593s Jul 05 11:00:30 autopkgtest multipathd[335]: check_removed_paths: sdf: freeing path in removed state 593s Jul 05 11:00:30 autopkgtest multipathd[335]: 8:80: path removed from map mpatha 593s Jul 05 11:00:40 autopkgtest multipathd[335]: multipathd: shut down 593s Jul 05 11:00:40 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 593s Jul 05 11:00:40 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 593s Jul 05 11:00:40 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 593s Jul 05 11:00:40 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 593s Jul 05 11:00:40 autopkgtest multipathd[6019]: multipathd v0.9.4: start up 593s Jul 05 11:00:40 autopkgtest multipathd[6019]: reconfigure: setting up paths and maps 593s Jul 05 11:00:40 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 593s Check final path status 593s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 593s size=100M features='0' hwhandler='0' wp=rw 593s |-+- policy='service-time 0' prio=1 status=active 593s | `- 1:0:0:1 sdb 8:16 active ready running 593s `-+- policy='service-time 0' prio=1 status=enabled 593s `- 2:0:0:1 sdc 8:32 active ready running 593s + diskc=2 593s + multipath -ll 593s + grep --count status=active 593s + diska=1 593s + multipath -ll 593s + grep --count status=enabled 593s + diske=1 593s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 593s + echo OK 593s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 593s OK 593s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 593s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 593s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 593s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 593s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 593s autopkgtest [11:02:40]: test tgtbasedmpaths: -----------------------] 594s tgtbasedmpaths PASS 594s autopkgtest [11:02:41]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 594s autopkgtest [11:02:41]: @@@@@@@@@@@@@@@@@@@@ summary 594s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 594s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 594s kpartx-file-loopback PASS 594s tgtbasedmpaths PASS 605s nova [W] Using flock in scalingstack-bos02-ppc64el 605s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240705-105247-juju-7f2275-prod-proposed-migration-environment-3-3ef97c02-acf5-4bbe-9363-ba8efcfb60d7 from image adt/ubuntu-oracular-ppc64el-server-20240705.img (UUID f2e64649-4587-477c-bc52-1e333d3c5b07)... 605s nova [W] Using flock in scalingstack-bos02-ppc64el 605s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240705-105247-juju-7f2275-prod-proposed-migration-environment-3-3ef97c02-acf5-4bbe-9363-ba8efcfb60d7 from image adt/ubuntu-oracular-ppc64el-server-20240705.img (UUID f2e64649-4587-477c-bc52-1e333d3c5b07)...