0s autopkgtest [18:10:10]: starting date and time: 2024-07-19 18:10:10+0000 0s autopkgtest [18:10:10]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [18:10:10]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.mhksghmx/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:linux-meta,src:linux --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=linux-meta/6.10.0-15.15 linux/6.10.0-15.15' --setup-commands 'apt-get install -y ^kernel-testing--linux--full--preferred$ || apt-get install -y ^linux-image$ ^linux-headers$ || apt-get install -y ^linux-image-generic$ ^linux-headers-generic$' --setup-commands 'apt-get install -y ^kernel-testing--linux--modules-extra--preferred$ || apt-get install -y ^linux-modules-extra$ || :' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big-ppc64el --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos03-ppc64el-4.secgroup --name adt-oracular-ppc64el-multipath-tools-20240719-181009-juju-7f2275-prod-proposed-migration-environment-2-cef53be3-7742-4c8b-82fd-7465b6e82a17 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --net-id=net_prod-proposed-migration-ppc64el -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 82s autopkgtest [18:11:32]: testbed dpkg architecture: ppc64el 82s autopkgtest [18:11:32]: testbed apt version: 2.9.6 82s autopkgtest [18:11:32]: @@@@@@@@@@@@@@@@@@@@ test bed setup 83s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 83s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.7 kB] 83s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [372 kB] 83s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3232 B] 83s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 83s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [73.6 kB] 83s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2116 B] 83s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 83s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 83s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [376 kB] 83s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [8952 B] 83s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1840 B] 83s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 85s Fetched 1027 kB in 1s (1211 kB/s) 85s Reading package lists... 88s Reading package lists... 88s Building dependency tree... 88s Reading state information... 88s Calculating upgrade... 88s The following NEW packages will be installed: 88s libpython3.12t64 linux-headers-6.10.0-15 linux-headers-6.10.0-15-generic 88s linux-image-6.10.0-15-generic linux-modules-6.10.0-15-generic 88s linux-modules-extra-6.10.0-15-generic linux-tools-6.10.0-15 88s linux-tools-6.10.0-15-generic 88s The following packages will be upgraded: 88s libxml2 linux-generic linux-headers-generic linux-headers-virtual 88s linux-image-generic linux-image-virtual linux-libc-dev linux-tools-common 88s linux-virtual 88s 9 upgraded, 8 newly installed, 0 to remove and 0 not upgraded. 88s Need to get 227 MB of archives. 88s After this operation, 336 MB of additional disk space will be used. 88s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el libxml2 ppc64el 2.12.7+dfsg-3 [728 kB] 89s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpython3.12t64 ppc64el 3.12.4-1ubuntu1 [2540 kB] 89s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-6.10.0-15-generic ppc64el 6.10.0-15.15 [32.7 MB] 90s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-6.10.0-15-generic ppc64el 6.10.0-15.15 [64.1 MB] 91s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-extra-6.10.0-15-generic ppc64el 6.10.0-15.15 [103 MB] 93s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-generic ppc64el 6.10.0-15.15 [1730 B] 93s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-generic ppc64el 6.10.0-15.15 [10.5 kB] 93s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-virtual ppc64el 6.10.0-15.15 [1724 B] 93s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-virtual ppc64el 6.10.0-15.15 [10.4 kB] 93s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-virtual ppc64el 6.10.0-15.15 [1646 B] 93s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.10.0-15 all 6.10.0-15.15 [13.8 MB] 94s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.10.0-15-generic ppc64el 6.10.0-15.15 [3844 kB] 94s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-generic ppc64el 6.10.0-15.15 [10.3 kB] 94s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-libc-dev ppc64el 6.10.0-15.15 [1629 kB] 94s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-common all 6.10.0-15.15 [474 kB] 94s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.10.0-15 ppc64el 6.10.0-15.15 [4110 kB] 94s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.10.0-15-generic ppc64el 6.10.0-15.15 [1740 B] 94s Fetched 227 MB in 6s (39.7 MB/s) 95s (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 ... 72764 files and directories currently installed.) 95s Preparing to unpack .../00-libxml2_2.12.7+dfsg-3_ppc64el.deb ... 95s Unpacking libxml2:ppc64el (2.12.7+dfsg-3) over (2.9.14+dfsg-1.3ubuntu3) ... 95s Selecting previously unselected package libpython3.12t64:ppc64el. 95s Preparing to unpack .../01-libpython3.12t64_3.12.4-1ubuntu1_ppc64el.deb ... 95s Unpacking libpython3.12t64:ppc64el (3.12.4-1ubuntu1) ... 95s Selecting previously unselected package linux-modules-6.10.0-15-generic. 95s Preparing to unpack .../02-linux-modules-6.10.0-15-generic_6.10.0-15.15_ppc64el.deb ... 95s Unpacking linux-modules-6.10.0-15-generic (6.10.0-15.15) ... 95s Selecting previously unselected package linux-image-6.10.0-15-generic. 95s Preparing to unpack .../03-linux-image-6.10.0-15-generic_6.10.0-15.15_ppc64el.deb ... 95s Unpacking linux-image-6.10.0-15-generic (6.10.0-15.15) ... 95s Selecting previously unselected package linux-modules-extra-6.10.0-15-generic. 95s Preparing to unpack .../04-linux-modules-extra-6.10.0-15-generic_6.10.0-15.15_ppc64el.deb ... 95s Unpacking linux-modules-extra-6.10.0-15-generic (6.10.0-15.15) ... 96s Preparing to unpack .../05-linux-generic_6.10.0-15.15_ppc64el.deb ... 96s Unpacking linux-generic (6.10.0-15.15) over (6.8.0-31.31) ... 96s Preparing to unpack .../06-linux-image-generic_6.10.0-15.15_ppc64el.deb ... 96s Unpacking linux-image-generic (6.10.0-15.15) over (6.8.0-31.31) ... 96s Preparing to unpack .../07-linux-virtual_6.10.0-15.15_ppc64el.deb ... 96s Unpacking linux-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 96s Preparing to unpack .../08-linux-image-virtual_6.10.0-15.15_ppc64el.deb ... 96s Unpacking linux-image-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 96s Preparing to unpack .../09-linux-headers-virtual_6.10.0-15.15_ppc64el.deb ... 96s Unpacking linux-headers-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 96s Selecting previously unselected package linux-headers-6.10.0-15. 96s Preparing to unpack .../10-linux-headers-6.10.0-15_6.10.0-15.15_all.deb ... 96s Unpacking linux-headers-6.10.0-15 (6.10.0-15.15) ... 98s Selecting previously unselected package linux-headers-6.10.0-15-generic. 98s Preparing to unpack .../11-linux-headers-6.10.0-15-generic_6.10.0-15.15_ppc64el.deb ... 98s Unpacking linux-headers-6.10.0-15-generic (6.10.0-15.15) ... 99s Preparing to unpack .../12-linux-headers-generic_6.10.0-15.15_ppc64el.deb ... 99s Unpacking linux-headers-generic (6.10.0-15.15) over (6.8.0-31.31) ... 99s Preparing to unpack .../13-linux-libc-dev_6.10.0-15.15_ppc64el.deb ... 99s Unpacking linux-libc-dev:ppc64el (6.10.0-15.15) over (6.8.0-31.31) ... 100s Preparing to unpack .../14-linux-tools-common_6.10.0-15.15_all.deb ... 100s Unpacking linux-tools-common (6.10.0-15.15) over (6.8.0-31.31) ... 100s Selecting previously unselected package linux-tools-6.10.0-15. 100s Preparing to unpack .../15-linux-tools-6.10.0-15_6.10.0-15.15_ppc64el.deb ... 100s Unpacking linux-tools-6.10.0-15 (6.10.0-15.15) ... 100s Selecting previously unselected package linux-tools-6.10.0-15-generic. 100s Preparing to unpack .../16-linux-tools-6.10.0-15-generic_6.10.0-15.15_ppc64el.deb ... 100s Unpacking linux-tools-6.10.0-15-generic (6.10.0-15.15) ... 100s Setting up linux-headers-6.10.0-15 (6.10.0-15.15) ... 100s Setting up linux-headers-6.10.0-15-generic (6.10.0-15.15) ... 100s Setting up linux-libc-dev:ppc64el (6.10.0-15.15) ... 100s Setting up linux-headers-generic (6.10.0-15.15) ... 100s Setting up libpython3.12t64:ppc64el (3.12.4-1ubuntu1) ... 100s Setting up linux-modules-6.10.0-15-generic (6.10.0-15.15) ... 102s Setting up linux-tools-common (6.10.0-15.15) ... 102s Setting up libxml2:ppc64el (2.12.7+dfsg-3) ... 102s Setting up linux-modules-extra-6.10.0-15-generic (6.10.0-15.15) ... 104s Setting up linux-image-6.10.0-15-generic (6.10.0-15.15) ... 106s I: /boot/vmlinux is now a symlink to vmlinux-6.10.0-15-generic 106s I: /boot/initrd.img is now a symlink to initrd.img-6.10.0-15-generic 106s Setting up linux-headers-virtual (6.10.0-15.15) ... 106s Setting up linux-tools-6.10.0-15 (6.10.0-15.15) ... 106s Setting up linux-image-virtual (6.10.0-15.15) ... 106s Setting up linux-image-generic (6.10.0-15.15) ... 106s Setting up linux-generic (6.10.0-15.15) ... 106s Setting up linux-virtual (6.10.0-15.15) ... 106s Setting up linux-tools-6.10.0-15-generic (6.10.0-15.15) ... 106s Processing triggers for man-db (2.12.1-2) ... 108s Processing triggers for libc-bin (2.39-0ubuntu9) ... 108s Processing triggers for linux-image-6.10.0-15-generic (6.10.0-15.15) ... 108s /etc/kernel/postinst.d/initramfs-tools: 108s update-initramfs: Generating /boot/initrd.img-6.10.0-15-generic 108s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 115s /etc/kernel/postinst.d/zz-update-grub: 115s Sourcing file `/etc/default/grub' 115s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 115s Generating grub configuration file ... 116s Found linux image: /boot/vmlinux-6.10.0-15-generic 116s Found initrd image: /boot/initrd.img-6.10.0-15-generic 116s Found linux image: /boot/vmlinux-6.8.0-31-generic 116s Found initrd image: /boot/initrd.img-6.8.0-31-generic 116s Warning: os-prober will not be executed to detect other bootable partitions. 116s Systems on them will not be added to the GRUB boot configuration. 116s Check GRUB_DISABLE_OS_PROBER documentation entry. 116s Adding boot menu entry for UEFI Firmware Settings ... 116s done 116s Reading package lists... 116s Building dependency tree... 116s Reading state information... 117s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 117s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 117s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 117s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 117s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 118s Reading package lists... 118s Reading package lists... 118s Building dependency tree... 118s Reading state information... 119s Calculating upgrade... 119s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 119s Reading package lists... 119s Building dependency tree... 119s Reading state information... 119s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 119s Reading package lists... 120s Building dependency tree... 120s Reading state information... 120s linux-generic is already the newest version (6.10.0-15.15). 120s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 120s Reading package lists... 120s Building dependency tree... 120s Reading state information... 120s E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 120s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 120s Reading package lists... 121s Building dependency tree... 121s Reading state information... 121s E: Unable to locate package ^linux-modules-extra$ 121s E: Couldn't find any package by regex '^linux-modules-extra$' 121s autopkgtest [18:12:11]: rebooting testbed after setup commands that affected boot 125s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 150s autopkgtest [18:12:40]: testbed running kernel: Linux 6.10.0-15-generic #15-Ubuntu SMP Thu Jul 4 12:09:15 UTC 2024 153s autopkgtest [18:12:43]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 157s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 157s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 157s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 157s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 157s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 157s gpgv: issuer "steve.langasek@ubuntu.com" 157s gpgv: Can't check signature: No public key 157s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 157s autopkgtest [18:12:47]: testing package multipath-tools version 0.9.4-5ubuntu8 158s autopkgtest [18:12:48]: build not needed 158s autopkgtest [18:12:48]: test kpartx-file-loopback: preparing testbed 159s Reading package lists... 159s Building dependency tree... 159s Reading state information... 159s Starting pkgProblemResolver with broken count: 0 159s Starting 2 pkgProblemResolver with broken count: 0 159s Done 160s The following additional packages will be installed: 160s liburing2 qemu-utils 160s Recommended packages: 160s qemu-block-extra 160s The following NEW packages will be installed: 160s autopkgtest-satdep liburing2 qemu-utils 160s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 160s Need to get 2330 kB/2331 kB of archives. 160s After this operation, 15.4 MB of additional disk space will be used. 160s Get:1 /tmp/autopkgtest.aI6Xax/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 160s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 160s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 161s Fetched 2330 kB in 1s (3724 kB/s) 161s Selecting previously unselected package liburing2:ppc64el. 161s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 109888 files and directories currently installed.) 161s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 161s Unpacking liburing2:ppc64el (2.6-1) ... 161s Selecting previously unselected package qemu-utils. 161s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 161s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 161s Selecting previously unselected package autopkgtest-satdep. 161s Preparing to unpack .../1-autopkgtest-satdep.deb ... 161s Unpacking autopkgtest-satdep (0) ... 161s Setting up liburing2:ppc64el (2.6-1) ... 161s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 161s Setting up autopkgtest-satdep (0) ... 161s Processing triggers for man-db (2.12.1-2) ... 163s Processing triggers for libc-bin (2.39-0ubuntu9) ... 165s (Reading database ... 109908 files and directories currently installed.) 165s Removing autopkgtest-satdep (0) ... 166s autopkgtest [18:12:56]: test kpartx-file-loopback: [----------------------- 166s Formatting 'foo.img', fmt=raw size=20971520 167s Creating new GPT entries in memory. 167s Warning: The kernel is still using the old partition table. 167s The new table will be used at the next reboot or after you 167s run partprobe(8) or kpartx(8) 167s The operation has completed successfully. 167s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 167s standard_filename: OK 167s del devmap : loop0p1 167s No devices found 167s standard_filename_cleanup: OK 167s Formatting 'fou du FaFa.img', fmt=raw size=20971520 168s Creating new GPT entries in memory. 168s Warning: The kernel is still using the old partition table. 168s The new table will be used at the next reboot or after you 168s run partprobe(8) or kpartx(8) 168s The operation has completed successfully. 168s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 168s filename_with_spaces: OK 168s del devmap : loop0p1 168s No devices found 168s filename_with_spaces_cleanup: OK 169s autopkgtest [18:12:59]: test kpartx-file-loopback: -----------------------] 169s kpartx-file-loopback PASS 169s autopkgtest [18:12:59]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 170s autopkgtest [18:13:00]: test tgtbasedmpaths: preparing testbed 246s autopkgtest [18:14:16]: testbed dpkg architecture: ppc64el 246s autopkgtest [18:14:16]: testbed apt version: 2.9.6 246s autopkgtest [18:14:16]: @@@@@@@@@@@@@@@@@@@@ test bed setup 247s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 247s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3232 B] 247s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [372 kB] 247s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 247s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.7 kB] 247s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [73.6 kB] 247s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2116 B] 247s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 247s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 247s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [376 kB] 247s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [8952 B] 247s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1840 B] 247s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 249s Fetched 1027 kB in 1s (1363 kB/s) 249s Reading package lists... 251s Reading package lists... 251s Building dependency tree... 251s Reading state information... 251s Calculating upgrade... 252s The following NEW packages will be installed: 252s libpython3.12t64 linux-headers-6.10.0-15 linux-headers-6.10.0-15-generic 252s linux-image-6.10.0-15-generic linux-modules-6.10.0-15-generic 252s linux-modules-extra-6.10.0-15-generic linux-tools-6.10.0-15 252s linux-tools-6.10.0-15-generic 252s The following packages will be upgraded: 252s libxml2 linux-generic linux-headers-generic linux-headers-virtual 252s linux-image-generic linux-image-virtual linux-libc-dev linux-tools-common 252s linux-virtual 252s 9 upgraded, 8 newly installed, 0 to remove and 0 not upgraded. 252s Need to get 227 MB of archives. 252s After this operation, 336 MB of additional disk space will be used. 252s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el libxml2 ppc64el 2.12.7+dfsg-3 [728 kB] 252s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpython3.12t64 ppc64el 3.12.4-1ubuntu1 [2540 kB] 252s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-6.10.0-15-generic ppc64el 6.10.0-15.15 [32.7 MB] 253s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-6.10.0-15-generic ppc64el 6.10.0-15.15 [64.1 MB] 255s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-extra-6.10.0-15-generic ppc64el 6.10.0-15.15 [103 MB] 258s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-generic ppc64el 6.10.0-15.15 [1730 B] 258s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-generic ppc64el 6.10.0-15.15 [10.5 kB] 258s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-virtual ppc64el 6.10.0-15.15 [1724 B] 258s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-virtual ppc64el 6.10.0-15.15 [10.4 kB] 258s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-virtual ppc64el 6.10.0-15.15 [1646 B] 258s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.10.0-15 all 6.10.0-15.15 [13.8 MB] 258s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.10.0-15-generic ppc64el 6.10.0-15.15 [3844 kB] 258s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-generic ppc64el 6.10.0-15.15 [10.3 kB] 258s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-libc-dev ppc64el 6.10.0-15.15 [1629 kB] 258s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-common all 6.10.0-15.15 [474 kB] 258s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.10.0-15 ppc64el 6.10.0-15.15 [4110 kB] 258s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.10.0-15-generic ppc64el 6.10.0-15.15 [1740 B] 259s Fetched 227 MB in 7s (33.6 MB/s) 259s (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 ... 72764 files and directories currently installed.) 259s Preparing to unpack .../00-libxml2_2.12.7+dfsg-3_ppc64el.deb ... 259s Unpacking libxml2:ppc64el (2.12.7+dfsg-3) over (2.9.14+dfsg-1.3ubuntu3) ... 259s Selecting previously unselected package libpython3.12t64:ppc64el. 259s Preparing to unpack .../01-libpython3.12t64_3.12.4-1ubuntu1_ppc64el.deb ... 259s Unpacking libpython3.12t64:ppc64el (3.12.4-1ubuntu1) ... 259s Selecting previously unselected package linux-modules-6.10.0-15-generic. 259s Preparing to unpack .../02-linux-modules-6.10.0-15-generic_6.10.0-15.15_ppc64el.deb ... 259s Unpacking linux-modules-6.10.0-15-generic (6.10.0-15.15) ... 259s Selecting previously unselected package linux-image-6.10.0-15-generic. 259s Preparing to unpack .../03-linux-image-6.10.0-15-generic_6.10.0-15.15_ppc64el.deb ... 259s Unpacking linux-image-6.10.0-15-generic (6.10.0-15.15) ... 260s Selecting previously unselected package linux-modules-extra-6.10.0-15-generic. 260s Preparing to unpack .../04-linux-modules-extra-6.10.0-15-generic_6.10.0-15.15_ppc64el.deb ... 260s Unpacking linux-modules-extra-6.10.0-15-generic (6.10.0-15.15) ... 260s Preparing to unpack .../05-linux-generic_6.10.0-15.15_ppc64el.deb ... 260s Unpacking linux-generic (6.10.0-15.15) over (6.8.0-31.31) ... 260s Preparing to unpack .../06-linux-image-generic_6.10.0-15.15_ppc64el.deb ... 260s Unpacking linux-image-generic (6.10.0-15.15) over (6.8.0-31.31) ... 261s Preparing to unpack .../07-linux-virtual_6.10.0-15.15_ppc64el.deb ... 261s Unpacking linux-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 261s Preparing to unpack .../08-linux-image-virtual_6.10.0-15.15_ppc64el.deb ... 261s Unpacking linux-image-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 261s Preparing to unpack .../09-linux-headers-virtual_6.10.0-15.15_ppc64el.deb ... 261s Unpacking linux-headers-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 261s Selecting previously unselected package linux-headers-6.10.0-15. 261s Preparing to unpack .../10-linux-headers-6.10.0-15_6.10.0-15.15_all.deb ... 261s Unpacking linux-headers-6.10.0-15 (6.10.0-15.15) ... 263s Selecting previously unselected package linux-headers-6.10.0-15-generic. 263s Preparing to unpack .../11-linux-headers-6.10.0-15-generic_6.10.0-15.15_ppc64el.deb ... 263s Unpacking linux-headers-6.10.0-15-generic (6.10.0-15.15) ... 264s Preparing to unpack .../12-linux-headers-generic_6.10.0-15.15_ppc64el.deb ... 264s Unpacking linux-headers-generic (6.10.0-15.15) over (6.8.0-31.31) ... 264s Preparing to unpack .../13-linux-libc-dev_6.10.0-15.15_ppc64el.deb ... 264s Unpacking linux-libc-dev:ppc64el (6.10.0-15.15) over (6.8.0-31.31) ... 264s Preparing to unpack .../14-linux-tools-common_6.10.0-15.15_all.deb ... 264s Unpacking linux-tools-common (6.10.0-15.15) over (6.8.0-31.31) ... 264s Selecting previously unselected package linux-tools-6.10.0-15. 264s Preparing to unpack .../15-linux-tools-6.10.0-15_6.10.0-15.15_ppc64el.deb ... 264s Unpacking linux-tools-6.10.0-15 (6.10.0-15.15) ... 264s Selecting previously unselected package linux-tools-6.10.0-15-generic. 264s Preparing to unpack .../16-linux-tools-6.10.0-15-generic_6.10.0-15.15_ppc64el.deb ... 264s Unpacking linux-tools-6.10.0-15-generic (6.10.0-15.15) ... 264s Setting up linux-headers-6.10.0-15 (6.10.0-15.15) ... 264s Setting up linux-headers-6.10.0-15-generic (6.10.0-15.15) ... 264s Setting up linux-libc-dev:ppc64el (6.10.0-15.15) ... 264s Setting up linux-headers-generic (6.10.0-15.15) ... 264s Setting up libpython3.12t64:ppc64el (3.12.4-1ubuntu1) ... 264s Setting up linux-modules-6.10.0-15-generic (6.10.0-15.15) ... 266s Setting up linux-tools-common (6.10.0-15.15) ... 266s Setting up libxml2:ppc64el (2.12.7+dfsg-3) ... 266s Setting up linux-modules-extra-6.10.0-15-generic (6.10.0-15.15) ... 268s Setting up linux-image-6.10.0-15-generic (6.10.0-15.15) ... 270s I: /boot/vmlinux is now a symlink to vmlinux-6.10.0-15-generic 270s I: /boot/initrd.img is now a symlink to initrd.img-6.10.0-15-generic 270s Setting up linux-headers-virtual (6.10.0-15.15) ... 270s Setting up linux-tools-6.10.0-15 (6.10.0-15.15) ... 270s Setting up linux-image-virtual (6.10.0-15.15) ... 270s Setting up linux-image-generic (6.10.0-15.15) ... 270s Setting up linux-generic (6.10.0-15.15) ... 270s Setting up linux-virtual (6.10.0-15.15) ... 270s Setting up linux-tools-6.10.0-15-generic (6.10.0-15.15) ... 270s Processing triggers for man-db (2.12.1-2) ... 272s Processing triggers for libc-bin (2.39-0ubuntu9) ... 272s Processing triggers for linux-image-6.10.0-15-generic (6.10.0-15.15) ... 272s /etc/kernel/postinst.d/initramfs-tools: 272s update-initramfs: Generating /boot/initrd.img-6.10.0-15-generic 272s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 279s /etc/kernel/postinst.d/zz-update-grub: 279s Sourcing file `/etc/default/grub' 279s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 279s Generating grub configuration file ... 279s Found linux image: /boot/vmlinux-6.10.0-15-generic 279s Found initrd image: /boot/initrd.img-6.10.0-15-generic 279s Found linux image: /boot/vmlinux-6.8.0-31-generic 279s Found initrd image: /boot/initrd.img-6.8.0-31-generic 279s Warning: os-prober will not be executed to detect other bootable partitions. 279s Systems on them will not be added to the GRUB boot configuration. 279s Check GRUB_DISABLE_OS_PROBER documentation entry. 279s Adding boot menu entry for UEFI Firmware Settings ... 279s done 280s Reading package lists... 280s Building dependency tree... 280s Reading state information... 280s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 280s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 280s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 280s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 280s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 281s Reading package lists... 281s Reading package lists... 281s Building dependency tree... 281s Reading state information... 282s Calculating upgrade... 282s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 282s Reading package lists... 282s Building dependency tree... 282s Reading state information... 282s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 282s Reading package lists... 282s Building dependency tree... 282s Reading state information... 283s linux-generic is already the newest version (6.10.0-15.15). 283s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 283s Reading package lists... 283s Building dependency tree... 283s Reading state information... 283s E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 283s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 283s Reading package lists... 283s Building dependency tree... 283s Reading state information... 283s E: Unable to locate package ^linux-modules-extra$ 283s E: Couldn't find any package by regex '^linux-modules-extra$' 284s autopkgtest [18:14:54]: rebooting testbed after setup commands that affected boot 288s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 318s Reading package lists... 318s Building dependency tree... 318s Reading state information... 318s Starting pkgProblemResolver with broken count: 0 318s Starting 2 pkgProblemResolver with broken count: 0 318s Done 318s The following additional packages will be installed: 318s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 318s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 318s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 318s librdmacm1t64 lsscsi open-iscsi tgt 318s Suggested packages: 318s fio-examples gnuplot tgt-glusterfs tgt-rbd 318s Recommended packages: 318s finalrd 319s The following NEW packages will be installed: 319s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 319s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 319s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 319s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 319s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 319s Need to get 10.7 MB/10.7 MB of archives. 319s After this operation, 49.0 MB of additional disk space will be used. 319s Get:1 /tmp/autopkgtest.aI6Xax/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 319s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 319s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 319s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 319s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2 [80.5 kB] 319s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 319s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 319s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4ubuntu1 [21.5 kB] 319s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4ubuntu1 [311 kB] 319s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4ubuntu1 [46.5 kB] 319s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4ubuntu1 [99.2 kB] 319s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-1 [97.4 kB] 319s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 319s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 319s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 319s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 319s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 319s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 319s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 319s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 319s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 320s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 320s Preconfiguring packages ... 320s Fetched 10.7 MB in 1s (11.1 MB/s) 320s Selecting previously unselected package libopeniscsiusr. 320s (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 ... 109888 files and directories currently installed.) 320s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 320s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 320s Selecting previously unselected package libisns0t64:ppc64el. 320s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 320s Unpacking libisns0t64:ppc64el (0.101-1) ... 320s Selecting previously unselected package open-iscsi. 320s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 320s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 320s Selecting previously unselected package librdmacm1t64:ppc64el. 320s Preparing to unpack .../03-librdmacm1t64_52.0-2_ppc64el.deb ... 320s Unpacking librdmacm1t64:ppc64el (52.0-2) ... 320s Selecting previously unselected package libconfig-general-perl. 320s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 320s Unpacking libconfig-general-perl (2.65-2) ... 320s Selecting previously unselected package tgt. 320s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 320s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 320s Selecting previously unselected package libgfxdr0:ppc64el. 320s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_ppc64el.deb ... 320s Unpacking libgfxdr0:ppc64el (11.1-4ubuntu1) ... 320s Selecting previously unselected package libglusterfs0:ppc64el. 320s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_ppc64el.deb ... 320s Unpacking libglusterfs0:ppc64el (11.1-4ubuntu1) ... 320s Selecting previously unselected package libgfrpc0:ppc64el. 320s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_ppc64el.deb ... 320s Unpacking libgfrpc0:ppc64el (11.1-4ubuntu1) ... 320s Selecting previously unselected package libgfapi0:ppc64el. 320s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_ppc64el.deb ... 320s Unpacking libgfapi0:ppc64el (11.1-4ubuntu1) ... 320s Selecting previously unselected package libnbd0. 320s Preparing to unpack .../10-libnbd0_1.20.2-1_ppc64el.deb ... 320s Unpacking libnbd0 (1.20.2-1) ... 320s Selecting previously unselected package libdaxctl1:ppc64el. 320s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 320s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 320s Selecting previously unselected package libndctl6:ppc64el. 320s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 320s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 320s Selecting previously unselected package libpmem1:ppc64el. 320s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 320s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 320s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 320s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 320s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 321s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 321s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 321s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 321s Selecting previously unselected package librados2. 321s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 321s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 321s Selecting previously unselected package libpmemobj1:ppc64el. 321s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 321s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 321s Selecting previously unselected package librbd1. 321s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 321s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 321s Selecting previously unselected package fio. 321s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 321s Unpacking fio (3.37-1) ... 321s Selecting previously unselected package lsscsi. 321s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 321s Unpacking lsscsi (0.32-1build1) ... 321s Selecting previously unselected package autopkgtest-satdep. 321s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 321s Unpacking autopkgtest-satdep (0) ... 321s Setting up libconfig-general-perl (2.65-2) ... 321s Setting up libisns0t64:ppc64el (0.101-1) ... 321s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 321s Setting up libnbd0 (1.20.2-1) ... 321s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 321s Setting up libglusterfs0:ppc64el (11.1-4ubuntu1) ... 321s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 321s Setting up lsscsi (0.32-1build1) ... 321s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 321s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 321s Setting up librdmacm1t64:ppc64el (52.0-2) ... 321s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 321s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 322s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 322s Setting up libgfxdr0:ppc64el (11.1-4ubuntu1) ... 322s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 322s Setting up open-iscsi (2.1.10-1ubuntu1) ... 323s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 323s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 323s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 323s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 323s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 323s Setting up libgfrpc0:ppc64el (11.1-4ubuntu1) ... 323s Setting up libgfapi0:ppc64el (11.1-4ubuntu1) ... 323s Setting up fio (3.37-1) ... 324s Setting up autopkgtest-satdep (0) ... 324s Processing triggers for man-db (2.12.1-2) ... 326s Processing triggers for initramfs-tools (0.142ubuntu30) ... 326s update-initramfs: Generating /boot/initrd.img-6.10.0-15-generic 326s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 333s Processing triggers for libc-bin (2.39-0ubuntu9) ... 336s (Reading database ... 110129 files and directories currently installed.) 336s Removing autopkgtest-satdep (0) ... 338s autopkgtest [18:15:48]: test tgtbasedmpaths: [----------------------- 338s + targetname=iqn.2016-11.foo.com:target.iscsi 338s + pwd 338s + cwd=/tmp/autopkgtest.aI6Xax/build.GO8/src 338s + testdir=/mnt/tgtmpathtest 338s + localhost=127.0.0.1 338s + portal=127.0.0.1:3260 338s + maxpaths=4 338s + backfn=backingfile 338s + expectwwid=60000000000000000e00000000010001 338s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 338s + bglog=/tmp/autopkgtest.aI6Xax/tgtbasedmpaths-artifacts/test-background.log 338s + fioprep=/tmp/autopkgtest.aI6Xax/tgtbasedmpaths-artifacts/path-change-prep.fio 338s + fiovrfy=/tmp/autopkgtest.aI6Xax/tgtbasedmpaths-artifacts/path-change-check.fio 338s + service tgt restart 338s + truncate --size 100M backingfile 338s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 338s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 338s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.aI6Xax/build.GO8/src/backingfile 338s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 338s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 338s login #1 338s + echo login #1 338s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 338s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 338s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 338s + seq 2 4 338s extra login #2 338s + echo extra login #2 338s + iscsiadm --mode session -r 1 --op new 338s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 338s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 338s + echo extra login #3 338s + iscsiadm --mode session -r 1 --op new 338s extra login #3 338s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 338s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 338s + echo extra login #4 338s + iscsiadm --mode session -rextra login #4 338s 1 --op new 338s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 338s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 338s + udevadm settle 338s + sleep 5 344s Status after initial setup 344s Target 1: iqn.2016-11.foo.com:target.iscsi 344s System information: 344s Driver: iscsi 344s State: ready 344s I_T nexus information: 344s I_T nexus: 1 344s Initiator: iqn.2004-10.com.ubuntu:01:793538d61916 alias: autopkgtest 344s Connection: 0 344s IP Address: 127.0.0.1 344s I_T nexus: 2 344s Initiator: iqn.2004-10.com.ubuntu:01:793538d61916 alias: autopkgtest 344s Connection: 0 344s IP Address: 127.0.0.1 344s I_T nexus: 3 344s Initiator: iqn.2004-10.com.ubuntu:01:793538d61916 alias: autopkgtest 344s Connection: 0 344s IP Address: 127.0.0.1 344s I_T nexus: 4 344s Initiator: iqn.2004-10.com.ubuntu:01:793538d61916 alias: autopkgtest 344s Connection: 0 344s IP Address: 127.0.0.1 344s LUN information: 344s LUN: 0 344s Type: controller 344s SCSI ID: IET 00010000 344s SCSI SN: beaf10 344s Size: 0 MB, Block size: 1 344s Online: Yes 344s Removable media: No 344s Prevent removal: No 344s Readonly: No 344s SWP: No 344s Thin-provisioning: No 344s Backing store type: null 344s Backing store path: None 344s Backing store flags: 344s LUN: 1 344s Type: disk 344s SCSI ID: IET 00010001 344s SCSI SN: beaf11 344s Size: 105 MB, Block size: 512 344s Online: Yes 344s Removable media: No 344s Prevent removal: No 344s Readonly: No 344s SWP: No 344s Thin-provisioning: No 344s Backing store type: rdwr 344s Backing store path: /tmp/autopkgtest.aI6Xax/build.GO8/src/backingfile 344s Backing store flags: 344s Account information: 344s ACL information: 344s ALL 344s + echo Status after initial setup 344s + tgtadm --lld iscsi --mode target --op show 344s + tgtadm --lld iscsi --op show --mode conn --tid 1 344s + iscsiadm --mode session -P 1 344s Session: 4 344s Connection: 0 344s Initiator: iqn.2004-10.com.ubuntu:01:793538d61916 344s IP Address: 127.0.0.1 344s Session: 3 344s Connection: 0 344s Initiator: iqn.2004-10.com.ubuntu:01:793538d61916 344s IP Address: 127.0.0.1 344s Session: 2 344s Connection: 0 344s Initiator: iqn.2004-10.com.ubuntu:01:793538d61916 344s IP Address: 127.0.0.1 344s Session: 1 344s Connection: 0 344s Initiator: iqn.2004-10.com.ubuntu:01:793538d61916 344s IP Address: 127.0.0.1 344s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 344s Current Portal: 127.0.0.1:3260,1 344s Persistent Portal: 127.0.0.1:3260,1 344s ********** 344s Interface: 344s ********** 344s Iface Name: default 344s Iface Transport: tcp 344s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:793538d61916 344s Iface IPaddress: 127.0.0.1 344s Iface HWaddress: default 344s Iface Netdev: default 344s SID: 1 344s iSCSI Connection State: LOGGED IN 344s iSCSI Session State: LOGGED_IN 344s Internal iscsid Session State: NO CHANGE 344s 344s ********** 344s Interface: 344s ********** 344s Iface Name: default 344s Iface Transport: tcp 344s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:793538d61916 344s Iface IPaddress: 127.0.0.1 344s Iface HWaddress: default 344s Iface Netdev: default 344s SID: 2 344s iSCSI Connection State: LOGGED IN 344s iSCSI Session State: LOGGED_IN 344s Internal iscsid Session State: NO CHANGE 344s 344s ********** 344s Interface: 344s ********** 344s Iface Name: default 344s Iface Transport: tcp 344s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:793538d61916 344s Iface IPaddress: 127.0.0.1 344s Iface HWaddress: default 344s Iface Netdev: default 344s SID: 3 344s iSCSI Connection State: LOGGED IN 344s iSCSI Session State: LOGGED_IN 344s Internal iscsid Session State: NO CHANGE 344s 344s ********** 344s Interface: 344s ********** 344s Iface Name: default 344s Iface Transport: tcp 344s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:793538d61916 344s Iface IPaddress: 127.0.0.1 344s Iface HWaddress: default 344s Iface Netdev: default 344s SID: 4 344s iSCSI Connection State: LOGGED IN 344s iSCSI Session State: LOGGED_IN 344s Internal iscsid Session State: NO CHANGE 344s + lsscsi -liv 344s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 344s [0:0:0:0] storage IET Controller 0001 - - 344s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 344s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 344s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 344s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 344s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 344s [1:0:0:0] storage IET Controller 0001 - - 344s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 344s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 344s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 344s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 344s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 344s [2:0:0:0] storage IET Controller 0001 - - 344s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 344s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 344s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 344s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 344s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 344s [3:0:0:0] storage IET Controller 0001 - - 344s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 344s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 344s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 344s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 344s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 344s NVMe module may not be loaded 344s + multipath -v3 -ll 344s 46.183347 | set open fds limit to 1073741816/1073741816 344s 46.183393 | loading /lib/multipath/libchecktur.so checker 344s 46.183462 | checker tur: message table size = 3 344s 46.183469 | loading /lib/multipath/libprioconst.so prioritizer 344s 46.183560 | _init_foreign: foreign library "nvme" is not enabled 344s 46.188096 | vda: device node name blacklisted 344s 46.188367 | sda: size = 204800 344s 46.188491 | sda: vendor = IET 344s 46.188513 | sda: product = VIRTUAL-DISK 344s 46.188534 | sda: rev = 0001 344s 46.189188 | sda: h:b:t:l = 0:0:0:1 344s 46.189511 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 344s 46.189515 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 344s 46.189518 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 344s 46.189670 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 344s 46.189674 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 344s 46.189687 | sda: serial = beaf11 344s 46.189690 | sda: detect_checker = yes (setting: multipath internal) 344s 46.189918 | sda: path_checker = tur (setting: multipath internal) 344s 46.189923 | sda: checker timeout = 30 s (setting: kernel sysfs) 344s 46.190034 | sda: tur state = up 344s 46.190155 | sdb: size = 204800 344s 46.190278 | sdb: vendor = IET 344s 46.190298 | sdb: product = VIRTUAL-DISK 344s 46.190318 | sdb: rev = 0001 344s 46.190945 | sdb: h:b:t:l = 1:0:0:1 344s 46.191266 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 344s 46.191270 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 344s 46.191272 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 344s 46.191407 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 344s 46.191411 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 344s 46.191423 | sdb: serial = beaf11 344s 46.191425 | sdb: detect_checker = yes (setting: multipath internal) 344s 46.191579 | sdb: path_checker = tur (setting: multipath internal) 344s 46.191584 | sdb: checker timeout = 30 s (setting: kernel sysfs) 344s 46.191689 | sdb: tur state = up 344s 46.191808 | sdc: size = 204800 344s 46.191933 | sdc: vendor = IET 344s 46.191953 | sdc: product = VIRTUAL-DISK 344s 46.191973 | sdc: rev = 0001 344s 46.192638 | sdc: h:b:t:l = 2:0:0:1 344s 46.192985 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 344s 46.192989 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 344s 46.192991 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 344s 46.193123 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 344s 46.193127 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 344s 46.193139 | sdc: serial = beaf11 344s 46.193141 | sdc: detect_checker = yes (setting: multipath internal) 344s 46.193895 | sdc: path_checker = tur (setting: multipath internal) 344s 46.193899 | sdc: checker timeout = 30 s (setting: kernel sysfs) 344s 46.194599 | sdc: tur state = up 344s 46.194718 | sdd: size = 204800 344s 46.194839 | sdd: vendor = IET 344s 46.194858 | sdd: product = VIRTUAL-DISK 344s 46.194878 | sdd: rev = 0001 344s 46.195509 | sdd: h:b:t:l = 3:0:0:1 344s 46.195828 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 344s 46.195831 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 344s 46.195833 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 344s 46.195967 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 344s 46.195970 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 344s 46.195981 | sdd: serial = beaf11 344s 46.195983 | sdd: detect_checker = yes (setting: multipath internal) 344s 46.196726 | sdd: path_checker = tur (setting: multipath internal) 344s 46.196735 | sdd: checker timeout = 30 s (setting: kernel sysfs) 344s 46.197449 | sdd: tur state = up 344s 46.197540 | loop0: device node name blacklisted 344s 46.197620 | loop1: device node name blacklisted 344s 46.197698 | loop2: device node name blacklisted 344s 46.197776 | loop3: device node name blacklisted 344s 46.197852 | loop4: device node name blacklisted 344s 46.197929 | loop5: device node name blacklisted 344s 46.198005 | loop6: device node name blacklisted 344s 46.198081 | loop7: device node name blacklisted 344s 46.198161 | dm-0: device node name blacklisted 344s 46.199014 | multipath-tools v0.9.4 (12/19, 2022) 344s 46.199024 | libdevmapper version 1.02.185 344s 46.199147 | kernel device mapper v4.48.0 344s 46.199157 | DM multipath kernel driver v1.14.0 344s 46.199251 | sda: size = 204800 344s 46.199256 | sda: vendor = IET 344s 46.199259 | sda: product = VIRTUAL-DISK 344s 46.199261 | sda: rev = 0001 344s 46.199847 | sda: h:b:t:l = 0:0:0:1 344s 46.199992 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 344s 46.200039 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 344s 46.200047 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 344s 46.200059 | sda: serial = beaf11 344s 46.200694 | sda: tur state = up 344s 46.200700 | sda: uid = 360000000000000000e00000000010001 (udev) 344s 46.200702 | sda: detect_prio = yes (setting: multipath internal) 344s 46.200705 | sda: prio = const (setting: multipath internal) 344s 46.200707 | sda: prio args = "" (setting: multipath internal) 344s 46.200709 | sda: const prio = 1 344s 46.200732 | sdb: size = 204800 344s 46.200736 | sdb: vendor = IET 344s 46.200739 | sdb: product = VIRTUAL-DISK 344s 46.200741 | sdb: rev = 0001 344s 46.201313 | sdb: h:b:t:l = 1:0:0:1 344s 46.201416 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 344s 46.201434 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 344s 46.201437 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 344s 46.201448 | sdb: serial = beaf11 344s 46.201555 | sdb: tur state = up 344s 46.201560 | sdb: uid = 360000000000000000e00000000010001 (udev) 344s 46.201563 | sdb: detect_prio = yes (setting: multipath internal) 344s 46.201565 | sdb: prio = const (setting: multipath internal) 344s 46.201567 | sdb: prio args = "" (setting: multipath internal) 344s 46.201569 | sdb: const prio = 1 344s 46.201591 | sdc: size = 204800 344s 46.201595 | sdc: vendor = IET 344s 46.201598 | sdc: product = VIRTUAL-DISK 344s 46.201600 | sdc: rev = 0001 344s 46.202168 | sdc: h:b:t:l = 2:0:0:1 344s 46.202272 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 344s 46.202290 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 344s 46.202292 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 344s 46.202303 | sdc: serial = beaf11 344s 46.202410 | sdc: tur state = up 344s 46.202415 | sdc: uid = 360000000000000000e00000000010001 (udev) 344s 46.202418 | sdc: detect_prio = yes (setting: multipath internal) 344s 46.202420 | sdc: prio = const (setting: multipath internal) 344s 46.202422 | sdc: prio args = "" (setting: multipath internal) 344s 46.202424 | sdc: const prio = 1 344s 46.202446 | sdd: size = 204800 344s 46.202450 | sdd: vendor = IET 344s 46.202452 | sdd: product = VIRTUAL-DISK 344s 46.202455 | sdd: rev = 0001 344s 46.203023 | sdd: h:b:t:l = 3:0:0:1 344s ===== paths list ===== 344s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 344s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK unknown 344s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 344s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 344s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 344s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 344s size=100M features='0' hwhandler='0' wp=rw 344s |-+- policy='service-time 0' prio=1 status=active 344s | `- 0:0:0:1 sda 8:0 active ready running 344s |-+- policy='service-time 0' prio=1 status=enabled 344s | `- 1:0:0:1 sdb 8:16 active ready running 344s |-+- policy='service-time 0' prio=1 status=enabled 344s | `- 2:0:0:1 sdc 8:32 active ready running 344s `-+- policy='service-time 0' prio=1 status=enabled 344s `- 3:0:0:1 sdd 8:48 active ready running 344s mpatha: 0 204800 multipath 0 0 4 1 service-time 0 1 2 8:0 1 1 service-time 0 1 2 8:16 1 1 service-time 0 1 2 8:32 1 1 service-time 0 1 2 8:48 1 1 344s Test WWN should now point to DM 344s ../../dm-0 344s Creating filesystem with 25600 4k blocks and 25600 inodes 344s 344s Allocating group tables: 0/1 done 344s Writing inode tables: 0/1 done 344s Creating journal (1024 blocks): done 344s Writing superblocks and filesystem accounting information: 0/1 done 344s 344s 46.203126 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 344s 46.203144 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 344s 46.203146 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 344s 46.203157 | sdd: serial = beaf11 344s 46.203260 | sdd: tur state = up 344s 46.203265 | sdd: uid = 360000000000000000e00000000010001 (udev) 344s 46.203268 | sdd: detect_prio = yes (setting: multipath internal) 344s 46.203270 | sdd: prio = const (setting: multipath internal) 344s 46.203271 | sdd: prio args = "" (setting: multipath internal) 344s 46.203273 | sdd: const prio = 1 344s 46.203919 | unloading tur checker 344s 46.203945 | unloading const prioritizer 344s + dmsetup table 344s + echo Test WWN should now point to DM 344s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 344s + grep dm 344s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 344s mke2fs 1.47.1 (20-May-2024) 344s + udevadm settle 344s + sleep 3s 347s + mkdir -p /mnt/tgtmpathtest 347s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 347s + cat 347s + cat 347s + fio --max-jobs=4 /tmp/autopkgtest.aI6Xax/tgtbasedmpaths-artifacts/path-change-prep.fio 347s write-phase: (g=0): rw=write, bs=(R) 64.0KiB-64.0KiB, (W) 64.0KiB-64.0KiB, (T) 64.0KiB-64.0KiB, ioengine=sync, iodepth=1 347s fio-3.37 347s Starting 1 thread 347s write-phase: Laying out IO file (1 file / 17592186044415MiB) 348s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91750400, buflen=65536 348s 348s write-phase: (groupid=0, jobs=1): err= 0: pid=5824: Fri Jul 19 18:15:58 2024 348s write: IOPS=1911, BW=119MiB/s (125MB/s)(87.5MiB/733msec); 0 zone resets 348s clat (usec): min=266, max=2067, avg=499.80, stdev=273.60 348s lat (usec): min=286, max=2081, avg=521.80, stdev=273.98 348s clat percentiles (usec): 348s | 1.00th=[ 285], 5.00th=[ 314], 10.00th=[ 326], 20.00th=[ 338], 348s | 30.00th=[ 351], 40.00th=[ 363], 50.00th=[ 383], 60.00th=[ 433], 348s | 70.00th=[ 490], 80.00th=[ 578], 90.00th=[ 947], 95.00th=[ 1090], 348s | 99.00th=[ 1680], 99.50th=[ 1811], 99.90th=[ 1975], 99.95th=[ 2073], 348s | 99.99th=[ 2073] 348s bw ( KiB/s): min=113024, max=113024, per=92.46%, avg=113024.00, stdev= 0.00, samples=1 348s iops : min= 1766, max= 1766, avg=1766.00, stdev= 0.00, samples=1 348s lat (usec) : 500=71.38%, 750=15.77%, 1000=6.07% 348s lat (msec) : 2=6.64%, 4=0.07% 348s cpu : usr=6.01%, sys=3.83%, ctx=1402, majf=0, minf=0 348s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 348s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 348s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 348s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 348s latency : target=0, window=0, percentile=100.00%, depth=1 348s 348s Run status group 0 (all jobs): 348s WRITE: bw=119MiB/s (125MB/s), 119MiB/s-119MiB/s (125MB/s-125MB/s), io=87.5MiB (91.8MB), run=733-733msec 348s 348s Disk stats (read/write): 348s dm-0: ios=1/1228, sectors=8/157184, merge=0/0, ticks=1/586, in_queue=587, util=76.76%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/166, aggrin_queue=166, aggrutil=72.13% 348s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 348s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 348s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 348s sda: ios=1/1402, sectors=8/179280, merge=0/0, ticks=1/664, in_queue=665, util=72.13% 348s + echo Starting the path changes in background 348s Starting the path changes in background 348s + date +Pre FIO %H:%M:%S.%N 348s Pre FIO 18:15:58.532294963 348s + fio --max-jobs=4 /tmp/autopkgtest.aI6Xax/tgtbasedmpaths-artifacts/path-change-check.fio 348s 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 348s fio-3.37 348s Starting 1 thread 528s 528s verify-phase: (groupid=0, jobs=1): err= 0: pid=5831: Fri Jul 19 18:18:58 2024 528s read: IOPS=5280, BW=330MiB/s (346MB/s)(58.0GiB/180001msec) 528s clat (usec): min=75, max=67506, avg=167.38, stdev=229.38 528s lat (usec): min=75, max=67506, avg=167.48, stdev=229.38 528s clat percentiles (usec): 528s | 1.00th=[ 92], 5.00th=[ 98], 10.00th=[ 104], 20.00th=[ 115], 528s | 30.00th=[ 122], 40.00th=[ 129], 50.00th=[ 137], 60.00th=[ 147], 528s | 70.00th=[ 155], 80.00th=[ 165], 90.00th=[ 182], 95.00th=[ 212], 528s | 99.00th=[ 889], 99.50th=[ 1401], 99.90th=[ 1713], 99.95th=[ 2114], 528s | 99.99th=[ 2802] 528s bw ( KiB/s): min=93312, max=496000, per=100.00%, avg=338567.95, stdev=84698.26, samples=359 528s iops : min= 1458, max= 7750, avg=5290.12, stdev=1323.41, samples=359 528s lat (usec) : 100=7.37%, 250=88.62%, 500=0.59%, 750=0.59%, 1000=2.16% 528s lat (msec) : 2=0.61%, 4=0.06%, 10=0.01%, 20=0.01%, 50=0.01% 528s lat (msec) : 100=0.01% 528s cpu : usr=12.45%, sys=6.64%, ctx=950524, majf=0, minf=1 528s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 528s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 528s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 528s issued rwts: total=950426,0,0,0 short=0,0,0,0 dropped=0,0,0,0 528s latency : target=0, window=0, percentile=100.00%, depth=1 528s 528s Run status group 0 (all jobs): 528s READ: bw=330MiB/s (346MB/s), 330MiB/s-330MiB/s (346MB/s-346MB/s), io=58.0GiB (62.3GB), run=180001-180001msec 528s 528s Disk stats (read/write): 528s dm-0: ios=950941/11, sectors=121629240/12944, merge=0/10, ticks=156671/109, in_queue=156866, util=81.42%, aggrios=62710/2, aggsectors=8019982/3236, aggrmerge=0/0, aggrticks=10312/6, aggrin_queue=10318, aggrutil=81.24% 528s sdd: ios=105448/0, sectors=13487616/0, merge=0/0, ticks=16296/0, in_queue=16296, util=29.49% 528s sdb: ios=51512/0, sectors=6584376/0, merge=0/0, ticks=8309/0, in_queue=8309, util=37.97% 528s sdc: ios=56106/0, sectors=7176448/0, merge=0/0, ticks=8187/0, in_queue=8188, util=24.89% 528s sda: ios=37774/10, sectors=4831488/12944, merge=0/0, ticks=8457/25, in_queue=8482, util=81.24% 528s Post FIO 18:18:58.868399367 528s FIO verify test with changing paths - OK 528s Report log of background activity 528s + date +Post FIO %H:%M:%S.%N 528s + echo FIO verify test with changing paths - OK 528s + echo Report log of background activity 528s + cat /tmp/autopkgtest.aI6Xax/tgtbasedmpaths-artifacts/test-background.log 528s + sync 528s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 528s + echo Final stats 528s + iscsiadm --mode session --stats 528s + journalctl --no-pager -u multipathd 528s + iscsiadm --mode session 528s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s + sleep 10s 528s + date +MP report (expect 4) %H:%M:%S.%N 528s MP report (expect 4) 18:16:08.538553699 528s + multipath -ll 528s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 528s size=100M features='0' hwhandler='0' wp=rw 528s |-+- policy='service-time 0' prio=1 status=active 528s | `- 0:0:0:1 sda 8:0 active ready running 528s |-+- policy='service-time 0' prio=1 status=enabled 528s | `- 1:0:0:1 sdb 8:16 active ready running 528s |-+- policy='service-time 0' prio=1 status=enabled 528s | `- 2:0:0:1 sdc 8:32 active ready running 528s `-+- policy='service-time 0' prio=1 status=enabled 528s `- 3:0:0:1 sdd 8:48 active ready running 528s + date +UN-plug path 1 %H:%M:%S.%N 528s UN-plug path 1 18:16:08.558725657 528s + iscsiadm --mode session -r 1 -u 528s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 528s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 528s + iscsiadm --mode session 528s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s + sleep 10s 528s + date +MP report (expect 3) %H:%M:%S.%N 528s MP report (expect 3) 18:16:18.671207435 528s + multipath -ll 528s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 528s size=100M features='0' hwhandler='0' wp=rw 528s |-+- policy='service-time 0' prio=1 status=active 528s | `- 1:0:0:1 sdb 8:16 active ready running 528s |-+- policy='service-time 0' prio=1 status=enabled 528s | `- 2:0:0:1 sdc 8:32 active ready running 528s `-+- policy='service-time 0' prio=1 status=enabled 528s `- 3:0:0:1 sdd 8:48 active ready running 528s + date +UN-plug path 2 %H:%M:%S.%N 528s UN-plug path 2 18:16:18.701199654 528s + iscsiadm --mode session -r 2 -u 528s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 528s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 528s + iscsiadm --mode session 528s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s + sleep 10s 528s + date +MP report (expect 2) %H:%M:%S.%N 528s MP report (expect 2) 18:16:28.832324099 528s + multipath -ll 528s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 528s size=100M features='0' hwhandler='0' wp=rw 528s |-+- policy='service-time 0' prio=1 status=active 528s | `- 2:0:0:1 sdc 8:32 active ready running 528s `-+- policy='service-time 0' prio=1 status=enabled 528s `- 3:0:0:1 sdd 8:48 active ready running 528s + date +UN-plug path 3 %H:%M:%S.%N 528s UN-plug path 3 18:16:28.845779553 528s + iscsiadm --mode session -r 3 -u 528s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 528s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 528s + iscsiadm --mode session 528s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s + sleep 10s 528s + date +MP report (expect 1) %H:%M:%S.%N 528s MP report (expect 1) 18:16:38.945824584 528s + multipath -ll 528s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 528s size=100M features='0' hwhandler='0' wp=rw 528s `-+- policy='service-time 0' prio=1 status=active 528s `- 3:0:0:1 sdd 8:48 active ready running 528s + date +Add paths 5/6/7/8 %H:%M:%S.%N 528s Add paths 5/6/7/8 18:16:38.961324898 528s + iscsiadm --mode session -r 4 --op new 528s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 528s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 528s + iscsiadm --mode session -r 4 --op new 528s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 528s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 528s + iscsiadm --mode session -r 4 --op new 528s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 528s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 528s + iscsiadm --mode session -r 4 --op new 528s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 528s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 528s + iscsiadm --mode session 528s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s + sleep 10s 528s + date +MP report (expect 5) %H:%M:%S.%N 528s MP report (expect 5) 18:16:49.050594433 528s + multipath -ll 528s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 528s size=100M features='0' hwhandler='0' wp=rw 528s |-+- policy='service-time 0' prio=1 status=active 528s | `- 3:0:0:1 sdd 8:48 active ready running 528s |-+- policy='service-time 0' prio=1 status=enabled 528s | `- 0:0:0:1 sda 8:0 active ready running 528s |-+- policy='service-time 0' prio=1 status=enabled 528s | `- 1:0:0:1 sdb 8:16 active ready running 528s |-+- policy='service-time 0' prio=1 status=enabled 528s | `- 2:0:0:1 sdc 8:32 active ready running 528s `-+- policy='service-time 0' prio=1 status=enabled 528s `- 4:0:0:1 sde 8:64 active ready running 528s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 528s UN-plug multiple paths 4/7/8 18:16:49.084117709 528s + iscsiadm --mode session -r 4 -u 528s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 528s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 528s + iscsiadm --mode session -r 7 -u 528s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 528s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 528s + iscsiadm --mode session -r 8 -u 528s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 528s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 528s + iscsiadm --mode session 528s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 528s + sleep 10s 528s + date +Restart multipath daemon %H:%M:%S.%N 528s Restart multipath daemon 18:16:59.295411734 528s + systemctl restart multipathd 528s + sleep 10s 528s + date +Final background report (expect 2) %H:%M:%S.%N 528s Final background report (expect 2) 18:17:09.388813419 528s + multipath -ll 528s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 528s size=100M features='0' hwhandler='0' wp=rw 528s |-+- policy='service-time 0' prio=1 status=active 528s | `- 0:0:0:1 sda 8:0 active ready running 528s `-+- policy='service-time 0' prio=1 status=enabled 528s `- 1:0:0:1 sdb 8:16 active ready running 528s Final stats 528s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 528s iSCSI SNMP: 528s txdata_octets: 33516264 528s rxdata_octets: 45737983940 528s noptx_pdus: 0 528s scsicmd_pdus: 697988 528s tmfcmd_pdus: 0 528s login_pdus: 0 528s text_pdus: 0 528s dataout_pdus: 0 528s logout_pdus: 0 528s snack_pdus: 0 528s noprx_pdus: 0 528s scsirsp_pdus: 697988 528s tmfrsp_pdus: 0 528s textrsp_pdus: 0 528s datain_pdus: 697954 528s logoutrsp_pdus: 0 528s r2t_pdus: 0 528s async_pdus: 0 528s rjt_pdus: 0 528s digest_err: 0 528s timeout_err: 0 528s iSCSI Extended: 528s tx_sendpage_failures: 0 528s rx_discontiguous_hdr: 0 528s eh_abort_cnt: 0 528s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 528s iSCSI SNMP: 528s txdata_octets: 7512 528s rxdata_octets: 2826804 528s noptx_pdus: 0 528s scsicmd_pdus: 127 528s tmfcmd_pdus: 0 528s login_pdus: 0 528s text_pdus: 0 528s dataout_pdus: 0 528s logout_pdus: 0 528s snack_pdus: 0 528s noprx_pdus: 0 528s scsirsp_pdus: 127 528s tmfrsp_pdus: 0 528s textrsp_pdus: 0 528s datain_pdus: 104 528s logoutrsp_pdus: 0 528s r2t_pdus: 0 528s async_pdus: 0 528s rjt_pdus: 0 528s digest_err: 0 528s timeout_err: 0 528s iSCSI Extended: 528s tx_sendpage_failures: 0 528s rx_discontiguous_hdr: 0 528s eh_abort_cnt: 0 528s + echo Check final path status 528s + multipath -ll 528s + multipath -ll 528s + grep --count status= 528s + diskc=2 528s + multipath -ll 528s + grep --count status=active 528s Jul 19 06:29:25 adtubuntu-oracular-ppc64el-server-20240718-img-adt-prepare multipathd[311]: multipathd: shut down 528s Jul 19 06:29:25 adtubuntu-oracular-ppc64el-server-20240718-img-adt-prepare systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 528s Jul 19 06:29:25 adtubuntu-oracular-ppc64el-server-20240718-img-adt-prepare systemd[1]: multipathd.service: Deactivated successfully. 528s Jul 19 06:29:25 adtubuntu-oracular-ppc64el-server-20240718-img-adt-prepare systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 528s -- Boot 32b02fd9a798477385d93cc9d7f4247d -- 528s Jul 19 18:13:46 adtubuntu-oracular-ppc64el-server-20240718-img-adt-prepare systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 528s Jul 19 18:13:46 adtubuntu-oracular-ppc64el-server-20240718-img-adt-prepare multipathd[335]: multipathd v0.9.4: start up 528s Jul 19 18:13:46 adtubuntu-oracular-ppc64el-server-20240718-img-adt-prepare multipathd[335]: reconfigure: setting up paths and maps 528s Jul 19 18:13:46 adtubuntu-oracular-ppc64el-server-20240718-img-adt-prepare systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 528s Jul 19 18:14:58 autopkgtest multipathd[335]: multipathd: shut down 528s Jul 19 18:14:58 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 528s Jul 19 18:14:58 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 528s Jul 19 18:14:58 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 528s -- Boot 3e063c3119584c7989a90cebe3bd713b -- 528s Jul 19 18:15:10 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 528s Jul 19 18:15:10 autopkgtest multipathd[345]: multipathd v0.9.4: start up 528s Jul 19 18:15:10 autopkgtest multipathd[345]: reconfigure: setting up paths and maps 528s Jul 19 18:15:10 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 528s Jul 19 18:15:49 autopkgtest multipathd[345]: mpatha: addmap [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 528s Jul 19 18:15:49 autopkgtest multipathd[345]: sdb [8:16]: path added to devmap mpatha 528s Jul 19 18:15:49 autopkgtest multipathd[345]: mpatha: performing delayed actions 528s Jul 19 18:15:49 autopkgtest multipathd[345]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 528s Jul 19 18:16:08 autopkgtest multipathd[345]: 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] 528s Jul 19 18:16:08 autopkgtest multipathd[345]: check_removed_paths: sda: freeing path in removed state 528s Jul 19 18:16:08 autopkgtest multipathd[345]: 8:0: path removed from map mpatha 528s Jul 19 18:16:18 autopkgtest multipathd[345]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 528s Jul 19 18:16:18 autopkgtest multipathd[345]: check_removed_paths: sdb: freeing path in removed state 528s Jul 19 18:16:18 autopkgtest multipathd[345]: 8:16: path removed from map mpatha 528s Jul 19 18:16:28 autopkgtest multipathd[345]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 528s Jul 19 18:16:28 autopkgtest multipathd[345]: check_removed_paths: sdc: freeing path in removed state 528s Jul 19 18:16:28 autopkgtest multipathd[345]: 8:32: path removed from map mpatha 528s Jul 19 18:16:39 autopkgtest multipathd[345]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1] 528s Jul 19 18:16:39 autopkgtest multipathd[345]: sda [8:0]: path added to devmap mpatha 528s Jul 19 18:16:39 autopkgtest multipathd[345]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 528s Jul 19 18:16:39 autopkgtest multipathd[345]: sdb [8:16]: path added to devmap mpatha 528s Jul 19 18:16:39 autopkgtest multipathd[345]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 528s Jul 19 18:16:39 autopkgtest multipathd[345]: sdc [8:32]: path added to devmap mpatha 528s Jul 19 18:16:39 autopkgtest multipathd[345]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 528s Jul 19 18:16:39 autopkgtest multipathd[345]: sde [8:64]: path added to devmap mpatha 528s Jul 19 18:16:49 autopkgtest multipathd[345]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 528s Jul 19 18:16:49 autopkgtest multipathd[345]: check_removed_paths: sdd: freeing path in removed state 528s Jul 19 18:16:49 autopkgtest multipathd[345]: 8:48: path removed from map mpatha 528s Jul 19 18:16:49 autopkgtest multipathd[345]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:64 1] 528s Jul 19 18:16:49 autopkgtest multipathd[345]: check_removed_paths: sdc: freeing path in removed state 528s Jul 19 18:16:49 autopkgtest multipathd[345]: 8:32: path removed from map mpatha 528s Jul 19 18:16:49 autopkgtest multipathd[345]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 528s Jul 19 18:16:49 autopkgtest multipathd[345]: check_removed_paths: sde: freeing path in removed state 528s Jul 19 18:16:49 autopkgtest multipathd[345]: 8:64: path removed from map mpatha 528s Jul 19 18:16:59 autopkgtest multipathd[345]: multipathd: shut down 528s Jul 19 18:16:59 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 528s Jul 19 18:16:59 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 528s Jul 19 18:16:59 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 528s Jul 19 18:16:59 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 528s Jul 19 18:16:59 autopkgtest multipathd[6221]: multipathd v0.9.4: start up 528s Jul 19 18:16:59 autopkgtest multipathd[6221]: reconfigure: setting up paths and maps 528s Jul 19 18:16:59 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 528s Check final path status 528s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 528s size=100M features='0' hwhandler='0' wp=rw 528s |-+- policy='service-time 0' prio=1 status=active 528s | `- 0:0:0:1 sda 8:0 active ready running 528s `-+- policy='service-time 0' prio=1 status=enabled 528s `- 1:0:0:1 sdb 8:16 active ready running 528s + diska=1 528s + multipath -ll 528s + grep --count status=enabled 528s + diske=1 528s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 528s + echo OK 528s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 528s OK 529s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 529s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 529s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 529s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 529s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 529s autopkgtest [18:18:59]: test tgtbasedmpaths: -----------------------] 529s tgtbasedmpaths PASS 529s autopkgtest [18:18:59]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 530s autopkgtest [18:19:00]: @@@@@@@@@@@@@@@@@@@@ summary 530s kpartx-file-loopback PASS 530s tgtbasedmpaths PASS 535s nova [W] Using flock in prodstack6-ppc64el 535s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240719-181009-juju-7f2275-prod-proposed-migration-environment-2-cef53be3-7742-4c8b-82fd-7465b6e82a17 from image adt/ubuntu-oracular-ppc64el-server-20240719.img (UUID c7e7903a-4946-42f9-bdb2-2e8c523426c0)... 535s nova [W] Using flock in prodstack6-ppc64el 535s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240719-181009-juju-7f2275-prod-proposed-migration-environment-2-cef53be3-7742-4c8b-82fd-7465b6e82a17 from image adt/ubuntu-oracular-ppc64el-server-20240719.img (UUID c7e7903a-4946-42f9-bdb2-2e8c523426c0)...