0s autopkgtest [02:31:38]: starting date and time: 2024-05-24 02:31:38+0000 0s autopkgtest [02:31:38]: git checkout: 699e7f9f ssh-setup/nova: explicitely set 'fqdn' in cloud-init 0s autopkgtest [02:31:38]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.x6djsryy/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:libedit --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=libedit/3.1-20240517-1 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos01-ppc64el-15.secgroup --name adt-oracular-ppc64el-multipath-tools-20240524-023138-juju-7f2275-prod-proposed-migration-environment-3-a82b75fa-a9f3-4620-8fb4-7e8d4a5734d4 --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://us.ports.ubuntu.com/ubuntu-ports/ 190s autopkgtest [02:34:48]: testbed dpkg architecture: ppc64el 190s autopkgtest [02:34:48]: testbed apt version: 2.9.3 190s autopkgtest [02:34:48]: @@@@@@@@@@@@@@@@@@@@ test bed setup 191s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [73.9 kB] 191s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [54.1 kB] 191s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [1964 B] 191s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [493 kB] 192s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4716 B] 192s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [184 kB] 192s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [502 kB] 192s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [2640 B] 192s Fetched 1317 kB in 1s (940 kB/s) 192s Reading package lists... 195s Reading package lists... 195s Building dependency tree... 195s Reading state information... 195s Calculating upgrade... 195s The following packages will be upgraded: 195s dracut-install gir1.2-glib-2.0 klibc-utils libedit2 libglib2.0-0t64 195s libglib2.0-data libklibc libuv1t64 195s 8 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 195s Need to get 2444 kB of archives. 195s After this operation, 2048 B of additional disk space will be used. 195s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el gir1.2-glib-2.0 ppc64el 2.80.2-1ubuntu1 [182 kB] 196s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libglib2.0-0t64 ppc64el 2.80.2-1ubuntu1 [1765 kB] 196s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libglib2.0-data all 2.80.2-1ubuntu1 [49.3 kB] 196s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libedit2 ppc64el 3.1-20240517-1 [123 kB] 197s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el libuv1t64 ppc64el 1.48.0-4 [115 kB] 197s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el dracut-install ppc64el 060+5-8ubuntu1 [35.2 kB] 197s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el klibc-utils ppc64el 2.0.13-4ubuntu1 [120 kB] 197s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el libklibc ppc64el 2.0.13-4ubuntu1 [54.2 kB] 197s Fetched 2444 kB in 2s (1621 kB/s) 197s (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 ... 72605 files and directories currently installed.) 197s Preparing to unpack .../0-gir1.2-glib-2.0_2.80.2-1ubuntu1_ppc64el.deb ... 197s Unpacking gir1.2-glib-2.0:ppc64el (2.80.2-1ubuntu1) over (2.80.1-0ubuntu2) ... 197s Preparing to unpack .../1-libglib2.0-0t64_2.80.2-1ubuntu1_ppc64el.deb ... 197s Unpacking libglib2.0-0t64:ppc64el (2.80.2-1ubuntu1) over (2.80.1-0ubuntu2) ... 197s Preparing to unpack .../2-libglib2.0-data_2.80.2-1ubuntu1_all.deb ... 197s Unpacking libglib2.0-data (2.80.2-1ubuntu1) over (2.80.1-0ubuntu2) ... 197s Preparing to unpack .../3-libedit2_3.1-20240517-1_ppc64el.deb ... 197s Unpacking libedit2:ppc64el (3.1-20240517-1) over (3.1-20230828-1build1) ... 197s Preparing to unpack .../4-libuv1t64_1.48.0-4_ppc64el.deb ... 197s Unpacking libuv1t64:ppc64el (1.48.0-4) over (1.48.0-1.1build1) ... 197s Preparing to unpack .../5-dracut-install_060+5-8ubuntu1_ppc64el.deb ... 197s Unpacking dracut-install (060+5-8ubuntu1) over (060+5-1ubuntu3) ... 197s Preparing to unpack .../6-klibc-utils_2.0.13-4ubuntu1_ppc64el.deb ... 197s Unpacking klibc-utils (2.0.13-4ubuntu1) over (2.0.13-4) ... 197s Preparing to unpack .../7-libklibc_2.0.13-4ubuntu1_ppc64el.deb ... 197s Unpacking libklibc:ppc64el (2.0.13-4ubuntu1) over (2.0.13-4) ... 197s Setting up libedit2:ppc64el (3.1-20240517-1) ... 197s Setting up libuv1t64:ppc64el (1.48.0-4) ... 197s Setting up libklibc:ppc64el (2.0.13-4ubuntu1) ... 197s Setting up libglib2.0-0t64:ppc64el (2.80.2-1ubuntu1) ... 197s No schema files found: doing nothing. 197s Setting up libglib2.0-data (2.80.2-1ubuntu1) ... 197s Setting up gir1.2-glib-2.0:ppc64el (2.80.2-1ubuntu1) ... 197s Setting up dracut-install (060+5-8ubuntu1) ... 197s Setting up klibc-utils (2.0.13-4ubuntu1) ... 197s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 197s Processing triggers for man-db (2.12.1-1) ... 198s Processing triggers for initramfs-tools (0.142ubuntu27) ... 198s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 198s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 205s Reading package lists... 205s Building dependency tree... 205s Reading state information... 205s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 206s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 206s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 206s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 206s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 207s Reading package lists... 207s Reading package lists... 207s Building dependency tree... 207s Reading state information... 207s Calculating upgrade... 207s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 207s Reading package lists... 208s Building dependency tree... 208s Reading state information... 208s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 208s autopkgtest [02:35:06]: rebooting testbed after setup commands that affected boot 242s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 262s autopkgtest [02:36:00]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 266s autopkgtest [02:36:04]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 270s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 270s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 270s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 270s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 270s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 270s gpgv: issuer "steve.langasek@ubuntu.com" 270s gpgv: Can't check signature: No public key 270s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 270s autopkgtest [02:36:08]: testing package multipath-tools version 0.9.4-5ubuntu8 271s autopkgtest [02:36:09]: build not needed 271s autopkgtest [02:36:09]: test kpartx-file-loopback: preparing testbed 272s Reading package lists... 273s Building dependency tree... 273s Reading state information... 273s Starting pkgProblemResolver with broken count: 0 273s Starting 2 pkgProblemResolver with broken count: 0 273s Done 273s The following additional packages will be installed: 273s liburing2 qemu-utils 273s Recommended packages: 273s qemu-block-extra 273s The following NEW packages will be installed: 273s autopkgtest-satdep liburing2 qemu-utils 273s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 273s Need to get 2330 kB/2331 kB of archives. 273s After this operation, 15.4 MB of additional disk space will be used. 273s Get:1 /tmp/autopkgtest.bh32B8/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 273s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 273s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 275s Fetched 2330 kB in 2s (1551 kB/s) 275s Selecting previously unselected package liburing2:ppc64el. 275s (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 ... 72605 files and directories currently installed.) 275s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 275s Unpacking liburing2:ppc64el (2.6-1) ... 275s Selecting previously unselected package qemu-utils. 275s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 275s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 275s Selecting previously unselected package autopkgtest-satdep. 275s Preparing to unpack .../1-autopkgtest-satdep.deb ... 275s Unpacking autopkgtest-satdep (0) ... 275s Setting up liburing2:ppc64el (2.6-1) ... 275s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 275s Setting up autopkgtest-satdep (0) ... 275s Processing triggers for man-db (2.12.1-1) ... 276s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 278s (Reading database ... 72625 files and directories currently installed.) 278s Removing autopkgtest-satdep (0) ... 279s autopkgtest [02:36:17]: test kpartx-file-loopback: [----------------------- 279s Formatting 'foo.img', fmt=raw size=20971520 280s Creating new GPT entries in memory. 280s Warning: The kernel is still using the old partition table. 280s The new table will be used at the next reboot or after you 280s run partprobe(8) or kpartx(8) 280s The operation has completed successfully. 280s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 280s standard_filename: OK 280s del devmap : loop0p1 280s No devices found 280s standard_filename_cleanup: OK 280s Formatting 'fou du FaFa.img', fmt=raw size=20971520 281s Creating new GPT entries in memory. 281s Warning: The kernel is still using the old partition table. 281s The new table will be used at the next reboot or after you 281s run partprobe(8) or kpartx(8) 281s The operation has completed successfully. 281s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 281s filename_with_spaces: OK 281s del devmap : loop0p1 281s No devices found 281s filename_with_spaces_cleanup: OK 282s autopkgtest [02:36:20]: test kpartx-file-loopback: -----------------------] 282s kpartx-file-loopback PASS 282s autopkgtest [02:36:20]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 283s autopkgtest [02:36:21]: test tgtbasedmpaths: preparing testbed 442s autopkgtest [02:39:00]: testbed dpkg architecture: ppc64el 442s autopkgtest [02:39:00]: testbed apt version: 2.9.3 442s autopkgtest [02:39:00]: @@@@@@@@@@@@@@@@@@@@ test bed setup 443s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [73.9 kB] 443s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [54.1 kB] 443s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [1964 B] 443s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4060 B] 443s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [490 kB] 444s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [184 kB] 444s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [499 kB] 444s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [2324 B] 444s Fetched 1309 kB in 1s (1428 kB/s) 444s Reading package lists... 446s Reading package lists... 446s Building dependency tree... 446s Reading state information... 447s Calculating upgrade... 447s The following packages will be upgraded: 447s dracut-install gir1.2-glib-2.0 klibc-utils libedit2 libglib2.0-0t64 447s libglib2.0-data libklibc libuv1t64 447s 8 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 447s Need to get 2444 kB of archives. 447s After this operation, 2048 B of additional disk space will be used. 447s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el gir1.2-glib-2.0 ppc64el 2.80.2-1ubuntu1 [182 kB] 447s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libglib2.0-0t64 ppc64el 2.80.2-1ubuntu1 [1765 kB] 448s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libglib2.0-data all 2.80.2-1ubuntu1 [49.3 kB] 448s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libedit2 ppc64el 3.1-20240517-1 [123 kB] 448s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el libuv1t64 ppc64el 1.48.0-4 [115 kB] 448s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el dracut-install ppc64el 060+5-8ubuntu1 [35.2 kB] 448s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el klibc-utils ppc64el 2.0.13-4ubuntu1 [120 kB] 448s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el libklibc ppc64el 2.0.13-4ubuntu1 [54.2 kB] 448s Fetched 2444 kB in 1s (1980 kB/s) 448s (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 ... 72605 files and directories currently installed.) 448s Preparing to unpack .../0-gir1.2-glib-2.0_2.80.2-1ubuntu1_ppc64el.deb ... 448s Unpacking gir1.2-glib-2.0:ppc64el (2.80.2-1ubuntu1) over (2.80.1-0ubuntu2) ... 448s Preparing to unpack .../1-libglib2.0-0t64_2.80.2-1ubuntu1_ppc64el.deb ... 448s Unpacking libglib2.0-0t64:ppc64el (2.80.2-1ubuntu1) over (2.80.1-0ubuntu2) ... 448s Preparing to unpack .../2-libglib2.0-data_2.80.2-1ubuntu1_all.deb ... 448s Unpacking libglib2.0-data (2.80.2-1ubuntu1) over (2.80.1-0ubuntu2) ... 448s Preparing to unpack .../3-libedit2_3.1-20240517-1_ppc64el.deb ... 448s Unpacking libedit2:ppc64el (3.1-20240517-1) over (3.1-20230828-1build1) ... 448s Preparing to unpack .../4-libuv1t64_1.48.0-4_ppc64el.deb ... 448s Unpacking libuv1t64:ppc64el (1.48.0-4) over (1.48.0-1.1build1) ... 448s Preparing to unpack .../5-dracut-install_060+5-8ubuntu1_ppc64el.deb ... 448s Unpacking dracut-install (060+5-8ubuntu1) over (060+5-1ubuntu3) ... 448s Preparing to unpack .../6-klibc-utils_2.0.13-4ubuntu1_ppc64el.deb ... 449s Unpacking klibc-utils (2.0.13-4ubuntu1) over (2.0.13-4) ... 449s Preparing to unpack .../7-libklibc_2.0.13-4ubuntu1_ppc64el.deb ... 449s Unpacking libklibc:ppc64el (2.0.13-4ubuntu1) over (2.0.13-4) ... 449s Setting up libedit2:ppc64el (3.1-20240517-1) ... 449s Setting up libuv1t64:ppc64el (1.48.0-4) ... 449s Setting up libklibc:ppc64el (2.0.13-4ubuntu1) ... 449s Setting up libglib2.0-0t64:ppc64el (2.80.2-1ubuntu1) ... 449s No schema files found: doing nothing. 449s Setting up libglib2.0-data (2.80.2-1ubuntu1) ... 449s Setting up gir1.2-glib-2.0:ppc64el (2.80.2-1ubuntu1) ... 449s Setting up dracut-install (060+5-8ubuntu1) ... 449s Setting up klibc-utils (2.0.13-4ubuntu1) ... 449s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 449s Processing triggers for man-db (2.12.1-1) ... 449s Processing triggers for initramfs-tools (0.142ubuntu27) ... 449s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 449s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 456s Reading package lists... 456s Building dependency tree... 456s Reading state information... 457s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 457s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 457s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 457s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 457s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 458s Reading package lists... 458s Reading package lists... 458s Building dependency tree... 458s Reading state information... 458s Calculating upgrade... 459s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 459s Reading package lists... 459s Building dependency tree... 459s Reading state information... 459s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 459s autopkgtest [02:39:17]: rebooting testbed after setup commands that affected boot 463s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 496s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 528s Reading package lists... 528s Building dependency tree... 528s Reading state information... 528s Starting pkgProblemResolver with broken count: 0 528s Starting 2 pkgProblemResolver with broken count: 0 528s Done 528s The following additional packages will be installed: 528s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 528s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 528s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 528s librdmacm1t64 lsscsi open-iscsi tgt 528s Suggested packages: 528s fio-examples gnuplot tgt-glusterfs tgt-rbd 528s Recommended packages: 528s finalrd 528s The following NEW packages will be installed: 528s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 528s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 528s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 528s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 528s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 528s Need to get 10.8 MB/10.8 MB of archives. 528s After this operation, 49.9 MB of additional disk space will be used. 528s Get:1 /tmp/autopkgtest.bh32B8/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 529s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu4 [54.4 kB] 530s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-0.3build3 [119 kB] 530s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu4 [389 kB] 531s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 531s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 531s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu6 [256 kB] 531s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4build3 [21.5 kB] 531s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4build3 [311 kB] 531s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4build3 [47.0 kB] 531s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4build3 [100 kB] 531s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.1-1 [97.4 kB] 531s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 531s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 531s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 531s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-2.1ubuntu3 [260 kB] 531s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-2.1ubuntu3 [280 kB] 531s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu6 [4050 kB] 532s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 532s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu6 [3612 kB] 533s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 533s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 533s Preconfiguring packages ... 533s Fetched 10.8 MB in 4s (2409 kB/s) 533s Selecting previously unselected package libopeniscsiusr. 533s (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 ... 72605 files and directories currently installed.) 533s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu4_ppc64el.deb ... 533s Unpacking libopeniscsiusr (2.1.9-3ubuntu4) ... 533s Selecting previously unselected package libisns0t64:ppc64el. 533s Preparing to unpack .../01-libisns0t64_0.101-0.3build3_ppc64el.deb ... 533s Unpacking libisns0t64:ppc64el (0.101-0.3build3) ... 533s Selecting previously unselected package open-iscsi. 533s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu4_ppc64el.deb ... 534s Unpacking open-iscsi (2.1.9-3ubuntu4) ... 534s Selecting previously unselected package librdmacm1t64:ppc64el. 534s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 534s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 534s Selecting previously unselected package libconfig-general-perl. 534s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 534s Unpacking libconfig-general-perl (2.65-2) ... 534s Selecting previously unselected package tgt. 534s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu6_ppc64el.deb ... 534s Unpacking tgt (1:1.0.85-1.1ubuntu6) ... 534s Selecting previously unselected package libgfxdr0:ppc64el. 534s Preparing to unpack .../06-libgfxdr0_11.1-4build3_ppc64el.deb ... 534s Unpacking libgfxdr0:ppc64el (11.1-4build3) ... 534s Selecting previously unselected package libglusterfs0:ppc64el. 534s Preparing to unpack .../07-libglusterfs0_11.1-4build3_ppc64el.deb ... 534s Unpacking libglusterfs0:ppc64el (11.1-4build3) ... 534s Selecting previously unselected package libgfrpc0:ppc64el. 534s Preparing to unpack .../08-libgfrpc0_11.1-4build3_ppc64el.deb ... 534s Unpacking libgfrpc0:ppc64el (11.1-4build3) ... 534s Selecting previously unselected package libgfapi0:ppc64el. 534s Preparing to unpack .../09-libgfapi0_11.1-4build3_ppc64el.deb ... 534s Unpacking libgfapi0:ppc64el (11.1-4build3) ... 534s Selecting previously unselected package libnbd0. 534s Preparing to unpack .../10-libnbd0_1.20.1-1_ppc64el.deb ... 534s Unpacking libnbd0 (1.20.1-1) ... 534s Selecting previously unselected package libdaxctl1:ppc64el. 534s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 534s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 534s Selecting previously unselected package libndctl6:ppc64el. 534s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 534s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 534s Selecting previously unselected package libpmem1:ppc64el. 534s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 534s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 534s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 534s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 534s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 534s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 534s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 534s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 534s Selecting previously unselected package librados2. 534s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu6_ppc64el.deb ... 534s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 534s Selecting previously unselected package libpmemobj1:ppc64el. 534s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 534s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 534s Selecting previously unselected package librbd1. 534s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu6_ppc64el.deb ... 534s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 534s Selecting previously unselected package fio. 534s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 534s Unpacking fio (3.37-1) ... 534s Selecting previously unselected package lsscsi. 534s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 534s Unpacking lsscsi (0.32-1build1) ... 534s Selecting previously unselected package autopkgtest-satdep. 534s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 534s Unpacking autopkgtest-satdep (0) ... 534s Setting up libconfig-general-perl (2.65-2) ... 534s Setting up libisns0t64:ppc64el (0.101-0.3build3) ... 534s Setting up libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 534s Setting up libnbd0 (1.20.1-1) ... 534s Setting up libopeniscsiusr (2.1.9-3ubuntu4) ... 534s Setting up libglusterfs0:ppc64el (11.1-4build3) ... 534s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 534s Setting up lsscsi (0.32-1build1) ... 534s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 534s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 534s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 534s Setting up tgt (1:1.0.85-1.1ubuntu6) ... 534s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 535s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 535s Setting up libgfxdr0:ppc64el (11.1-4build3) ... 535s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 535s Setting up open-iscsi (2.1.9-3ubuntu4) ... 536s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 536s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 536s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 536s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 536s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 536s Setting up libgfrpc0:ppc64el (11.1-4build3) ... 536s Setting up libgfapi0:ppc64el (11.1-4build3) ... 536s Setting up fio (3.37-1) ... 537s Setting up autopkgtest-satdep (0) ... 537s Processing triggers for man-db (2.12.1-1) ... 538s Processing triggers for initramfs-tools (0.142ubuntu27) ... 538s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 538s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 545s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 547s (Reading database ... 72846 files and directories currently installed.) 547s Removing autopkgtest-satdep (0) ... 551s autopkgtest [02:40:49]: test tgtbasedmpaths: [----------------------- 551s + targetname=iqn.2016-11.foo.com:target.iscsi 551s + pwd 551s + cwd=/tmp/autopkgtest.bh32B8/build.d8n/src 551s + testdir=/mnt/tgtmpathtest 551s + localhost=127.0.0.1 551s + portal=127.0.0.1:3260 551s + maxpaths=4 551s + backfn=backingfile 551s + expectwwid=60000000000000000e00000000010001 551s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 551s + bglog=/tmp/autopkgtest.bh32B8/tgtbasedmpaths-artifacts/test-background.log 551s + fioprep=/tmp/autopkgtest.bh32B8/tgtbasedmpaths-artifacts/path-change-prep.fio 551s + fiovrfy=/tmp/autopkgtest.bh32B8/tgtbasedmpaths-artifacts/path-change-check.fio 551s + service tgt restart 552s + truncate --size 100M backingfile 552s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 552s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 552s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.bh32B8/build.d8n/src/backingfile 552s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 552s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 552s login #1 552s + echo login #1 552s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 552s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 552s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 552s + seq 2 4 552s extra login #2 552s + echo extra login #2 552s + iscsiadm --mode session -r 1 --op new 552s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 552s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 552s extra login #3 552s + echo extra login #3 552s + iscsiadm --mode session -r 1 --op new 552s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 552s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 552s extra login #4 552s + echo extra login #4 552s + iscsiadm --mode session -r 1 --op new 552s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 552s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 552s + udevadm settle 552s + sleep 5 557s Status after initial setup 557s + echo Status after initial setup 557s + tgtadm --lld iscsi --mode target --op show 557s + tgtadm --lld iscsi --op show --mode conn --tid 1 557s + iscsiadm --mode session -P 1 557s Target 1: iqn.2016-11.foo.com:target.iscsi 557s System information: 557s Driver: iscsi 557s State: ready 557s I_T nexus information: 557s I_T nexus: 1 557s Initiator: iqn.2004-10.com.ubuntu:01:24f97726adfc alias: autopkgtest 557s Connection: 0 557s IP Address: 127.0.0.1 557s I_T nexus: 2 557s Initiator: iqn.2004-10.com.ubuntu:01:24f97726adfc alias: autopkgtest 557s Connection: 0 557s IP Address: 127.0.0.1 557s I_T nexus: 3 557s Initiator: iqn.2004-10.com.ubuntu:01:24f97726adfc alias: autopkgtest 557s Connection: 0 557s IP Address: 127.0.0.1 557s I_T nexus: 4 557s Initiator: iqn.2004-10.com.ubuntu:01:24f97726adfc alias: autopkgtest 557s Connection: 0 557s IP Address: 127.0.0.1 557s LUN information: 557s LUN: 0 557s Type: controller 557s SCSI ID: IET 00010000 557s SCSI SN: beaf10 557s Size: 0 MB, Block size: 1 557s Online: Yes 557s Removable media: No 557s Prevent removal: No 557s Readonly: No 557s SWP: No 557s Thin-provisioning: No 557s Backing store type: null 557s Backing store path: None 557s Backing store flags: 557s LUN: 1 557s Type: disk 557s SCSI ID: IET 00010001 557s SCSI SN: beaf11 557s Size: 105 MB, Block size: 512 557s Online: Yes 557s Removable media: No 557s Prevent removal: No 557s Readonly: No 557s SWP: No 557s Thin-provisioning: No 557s Backing store type: rdwr 557s Backing store path: /tmp/autopkgtest.bh32B8/build.d8n/src/backingfile 557s Backing store flags: 557s Account information: 557s ACL information: 557s ALL 557s Session: 4 557s Connection: 0 557s Initiator: iqn.2004-10.com.ubuntu:01:24f97726adfc 557s IP Address: 127.0.0.1 557s Session: 3 557s Connection: 0 557s Initiator: iqn.2004-10.com.ubuntu:01:24f97726adfc 557s IP Address: 127.0.0.1 557s Session: 2 557s Connection: 0 557s Initiator: iqn.2004-10.com.ubuntu:01:24f97726adfc 557s IP Address: 127.0.0.1 557s Session: 1 557s Connection: 0 557s Initiator: iqn.2004-10.com.ubuntu:01:24f97726adfc 557s IP Address: 127.0.0.1 557s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 557s Current Portal: 127.0.0.1:3260,1 557s Persistent Portal: 127.0.0.1:3260,1 557s ********** 557s Interface: 557s ********** 557s Iface Name: default 557s Iface Transport: tcp 557s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:24f97726adfc 557s Iface IPaddress: 127.0.0.1 557s Iface HWaddress: default 557s Iface Netdev: default 557s SID: 1 557s iSCSI Connection State: LOGGED IN 557s iSCSI Session State: LOGGED_IN 557s Internal iscsid Session State: NO CHANGE 557s 557s ********** 557s Interface: 557s ********** 557s Iface Name: default 557s Iface Transport: tcp 557s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:24f97726adfc 557s Iface IPaddress: 127.0.0.1 557s Iface HWaddress: default 557s Iface Netdev: default 557s SID: 2 557s iSCSI Connection State: LOGGED IN 557s iSCSI Session State: LOGGED_IN 557s Internal iscsid Session State: NO CHANGE 557s 557s ********** 557s Interface: 557s ********** 557s Iface Name: default 557s Iface Transport: tcp 557s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:24f97726adfc 557s Iface IPaddress: 127.0.0.1 557s Iface HWaddress: default 557s Iface Netdev: default 557s SID: 3 557s iSCSI Connection State: LOGGED IN 557s iSCSI Session State: LOGGED_IN 557s Internal iscsid Session State: NO CHANGE 557s 557s ********** 557s Interface: 557s ********** 557s Iface Name: default 557s Iface Transport: tcp 557s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:24f97726adfc 557s Iface IPaddress: 127.0.0.1 557s Iface HWaddress: default 557s Iface Netdev: default 557s SID: 4 557s iSCSI Connection State: LOGGED IN 557s iSCSI Session State: LOGGED_IN 557s Internal iscsid Session State: NO CHANGE 557s + lsscsi -liv 557s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 557s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 557s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 557s 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] 557s [1:0:0:0] storage IET Controller 0001 - - 557s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 557s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 557s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 557s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 557s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 557s [2:0:0:0] storage IET Controller 0001 - - 557s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 557s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 557s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 557s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 557s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 557s [3:0:0:0] storage IET Controller 0001 - - 557s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 557s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 557s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 557s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 557s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 557s [4:0:0:0] storage IET Controller 0001 - - 557s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 557s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 557s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 33000000100000001 557s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 557s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 557s NVMe module may not be loaded 557s + multipath -v3 -ll 557s 74.528643 | set open fds limit to 1048576/1048576 557s 74.528742 | loading /lib/multipath/libchecktur.so checker 557s 74.528872 | checker tur: message table size = 3 557s 74.528902 | loading /lib/multipath/libprioconst.so prioritizer 557s 74.529035 | _init_foreign: foreign library "nvme" is not enabled 557s 74.534680 | sda: size = 167772160 557s 74.534864 | sda: vendor = QEMU 557s 74.534906 | sda: product = QEMU HARDDISK 557s 74.534928 | sda: rev = 2.5+ 557s 74.535557 | sda: h:b:t:l = 0:0:0:0 557s 74.535859 | sda: tgt_node_name = 557s 74.535880 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 557s 74.535883 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 557s 74.536055 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 557s 74.536080 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 557s 74.536092 | __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 557s 74.536097 | failed to read sysfs vpd pg80: No such file or directory 557s 74.536298 | sda: fail to get serial 557s 74.536319 | sda: detect_checker = yes (setting: multipath internal) 557s 74.536474 | sda: path_checker = tur (setting: multipath internal) 557s 74.536496 | sda: checker timeout = 30 s (setting: kernel sysfs) 557s 74.536608 | sda: tur state = up 557s 74.536910 | sdb: size = 204800 557s 74.537053 | sdb: vendor = IET 557s 74.537092 | sdb: product = VIRTUAL-DISK 557s 74.537113 | sdb: rev = 0001 557s 74.537736 | sdb: h:b:t:l = 1:0:0:1 557s 74.538092 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 557s 74.538112 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 557s 74.538114 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 557s 74.538266 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 557s 74.538285 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 557s 74.538300 | sdb: serial = beaf11 557s 74.538303 | sdb: detect_checker = yes (setting: multipath internal) 557s 74.538638 | sdb: path_checker = tur (setting: multipath internal) 557s 74.538660 | sdb: checker timeout = 30 s (setting: kernel sysfs) 557s 74.538838 | sdb: tur state = up 557s 74.538977 | sdc: size = 204800 557s 74.539119 | sdc: vendor = IET 557s 74.539157 | sdc: product = VIRTUAL-DISK 557s 74.539178 | sdc: rev = 0001 557s 74.539842 | sdc: h:b:t:l = 2:0:0:1 557s 74.540197 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 557s 74.540222 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 557s 74.540224 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 557s 74.540369 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 557s 74.540390 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 557s 74.540403 | sdc: serial = beaf11 557s 74.540405 | sdc: detect_checker = yes (setting: multipath internal) 557s 74.540548 | sdc: path_checker = tur (setting: multipath internal) 557s 74.540570 | sdc: checker timeout = 30 s (setting: kernel sysfs) 557s 74.540626 | sdc: tur state = up 557s 74.540767 | sdd: size = 204800 557s 74.540910 | sdd: vendor = IET 557s 74.540949 | sdd: product = VIRTUAL-DISK 557s 74.540970 | sdd: rev = 0001 557s 74.541645 | sdd: h:b:t:l = 3:0:0:1 557s 74.541988 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 557s 74.542008 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 557s 74.542010 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 557s 74.542155 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 557s 74.542174 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 557s 74.542188 | sdd: serial = beaf11 557s 74.542190 | sdd: detect_checker = yes (setting: multipath internal) 557s 74.542426 | sdd: path_checker = tur (setting: multipath internal) 557s 74.542447 | sdd: checker timeout = 30 s (setting: kernel sysfs) 557s 74.542603 | sdd: tur state = up 557s 74.542742 | sde: size = 204800 557s 74.542884 | sde: vendor = IET 557s 74.542922 | sde: product = VIRTUAL-DISK 557s 74.542943 | sde: rev = 0001 557s 74.543608 | sde: h:b:t:l = 4:0:0:1 557s 74.543953 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 557s 74.543973 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 557s 74.543976 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 557s 74.544170 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 557s 74.544193 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 557s 74.544207 | sde: serial = beaf11 557s 74.544210 | sde: detect_checker = yes (setting: multipath internal) 557s 74.544372 | sde: path_checker = tur (setting: multipath internal) 557s 74.544393 | sde: checker timeout = 30 s (setting: kernel sysfs) 557s 74.544494 | sde: tur state = up 557s 74.544584 | loop0: device node name blacklisted 557s 74.544687 | loop1: device node name blacklisted 557s 74.544784 | loop2: device node name blacklisted 557s 74.544882 | loop3: device node name blacklisted 557s 74.544978 | loop4: device node name blacklisted 557s 74.545074 | loop5: device node name blacklisted 557s 74.545152 | loop6: device node name blacklisted 557s 74.545248 | loop7: device node name blacklisted 557s 74.545364 | dm-0: device node name blacklisted 557s 74.546310 | multipath-tools v0.9.4 (12/19, 2022) 557s 74.546338 | libdevmapper version 1.02.185 557s 74.546492 | kernel device mapper v4.48.0 557s 74.546522 | DM multipath kernel driver v1.14.0 557s 74.546638 | sdb: size = 204800 557s 74.546659 | sdb: vendor = IET 557s 74.546662 | sdb: product = VIRTUAL-DISK 557s 74.546664 | sdb: rev = 0001 557s 74.547274 | sdb: h:b:t:l = 1:0:0:1 557s 74.547398 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 557s 74.547434 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 557s 74.547437 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 557s 74.547449 | sdb: serial = beaf11 557s 74.547553 | sdb: tur state = up 557s 74.547573 | sdb: uid = 360000000000000000e00000000010001 (udev) 557s 74.547576 | sdb: detect_prio = yes (setting: multipath internal) 557s 74.547580 | sdb: prio = const (setting: multipath internal) 557s 74.547582 | sdb: prio args = "" (setting: multipath internal) 557s 74.547584 | sdb: const prio = 1 557s 74.547606 | sdc: size = 204800 557s 74.547610 | sdc: vendor = IET 557s 74.547613 | sdc: product = VIRTUAL-DISK 557s 74.547615 | sdc: rev = 0001 557s 74.548218 | sdc: h:b:t:l = 2:0:0:1 557s 74.548346 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 557s 74.548382 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 557s 74.548384 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 557s 74.548396 | sdc: serial = beaf11 557s 74.548544 | sdc: tur state = up 557s 74.548563 | sdc: uid = 360000000000000000e00000000010001 (udev) 557s 74.548566 | sdc: detect_prio = yes (setting: multipath internal) 557s 74.548568 | sdc: prio = const (setting: multipath internal) 557s 74.548570 | sdc: prio args = "" (setting: multipath internal) 557s 74.548572 | sdc: const prio = 1 557s 74.548595 | sdd: size = 204800 557s 74.548599 | sdd: vendor = IET 557s 74.548601 | sdd: product = VIRTUAL-DISK 557s 74.548604 | sdd: rev = 0001 557s 74.549194 | sdd: h:b:t:l = 3:0:0:1 557s 74.549326 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 557s 74.549361 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 557s 74.549364 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 557s 74.549375 | sdd: serial = beaf11 557s 74.549527 | sdd: tur state = up 557s 74.549547 | sdd: uid = 360000000000000000e00000000010001 (udev) 557s 74.549550 | sdd: detect_prio = yes (setting: multipath internal) 557s 74.549553 | sdd: prio = const (setting: multipath internal) 557s 74.549555 | sdd: prio args = "" (setting: multipath internal) 557s 74.549557 | sdd: const prio = 1 557s 74.549580 | sde: size = 204800 557s 74.549584 | sde: vendor = IET 557s 74.549587 | sde: product = VIRTUAL-DISK 557s 74.549590 | sde: rev = 0001 557s 74.550191 | sde: h:b:t:l = 4:0:0:1 557s 74.550313 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 557s 74.550348 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 557s 74.550350 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 557s 74.550362 | sde: serial = beaf11 557s 74.550462 | sde: tur state = up 557s 74.550481 | sde: uid = 360000000000000000e00000000010001 (udev) 557s 74.550484 | sde: detect_prio = yes (setting: multipath internal) 557s 74.550486 | sde: prio = const (setting: multipath internal) 557s 74.550488 | sde: prio args = "" (setting: multipath internal) 557s 74.550490 | sde: const prio = 1 557s 74.551304 | unloading tur checker 557s 74.551363 | unloading const prioritizer 557s + dmsetup table 557s + echo Test WWN should now point to DM 557s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 557s + grep dm 557s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 557s mke2fs 1.47.0 (5-Feb-2023) 557s + udevadm settle 557s ===== paths list ===== 557s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 557s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 557s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 557s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 557s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 557s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 557s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 557s size=100M features='0' hwhandler='0' wp=rw 557s |-+- policy='service-time 0' prio=1 status=active 557s | `- 1:0:0:1 sdb 8:16 active ready running 557s |-+- policy='service-time 0' prio=1 status=enabled 557s | `- 2:0:0:1 sdc 8:32 active ready running 557s |-+- policy='service-time 0' prio=1 status=enabled 557s | `- 3:0:0:1 sdd 8:48 active ready running 557s `-+- policy='service-time 0' prio=1 status=enabled 557s `- 4:0:0:1 sde 8:64 active ready running 557s 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 557s Test WWN should now point to DM 557s ../../dm-0 557s Creating filesystem with 25600 4k blocks and 25600 inodes 557s 557s Allocating group tables: 0/1 done 557s Writing inode tables: 0/1 done 557s Creating journal (1024 blocks): done 557s Writing superblocks and filesystem accounting information: 0/1 done 557s 557s + sleep 3s 560s + mkdir -p /mnt/tgtmpathtest 560s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 560s + cat 560s + cat 560s + fio --max-jobs=4 /tmp/autopkgtest.bh32B8/tgtbasedmpaths-artifacts/path-change-prep.fio 560s 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 560s fio-3.37 560s Starting 1 thread 560s write-phase: Laying out IO file (1 file / 17592186044415MiB) 561s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 561s 561s write-phase: (groupid=0, jobs=1): err= 0: pid=5629: Fri May 24 02:40:59 2024 561s write: IOPS=2181, BW=136MiB/s (143MB/s)(87.6MiB/643msec); 0 zone resets 561s clat (usec): min=256, max=39530, avg=442.56, stdev=1048.54 561s lat (usec): min=269, max=39543, avg=456.69, stdev=1048.64 561s clat percentiles (usec): 561s | 1.00th=[ 310], 5.00th=[ 322], 10.00th=[ 334], 20.00th=[ 359], 561s | 30.00th=[ 367], 40.00th=[ 379], 50.00th=[ 383], 60.00th=[ 396], 561s | 70.00th=[ 416], 80.00th=[ 478], 90.00th=[ 562], 95.00th=[ 586], 561s | 99.00th=[ 660], 99.50th=[ 668], 99.90th=[ 1254], 99.95th=[39584], 561s | 99.99th=[39584] 561s bw ( KiB/s): min=132864, max=132864, per=95.21%, avg=132864.00, stdev= 0.00, samples=1 561s iops : min= 2076, max= 2076, avg=2076.00, stdev= 0.00, samples=1 561s lat (usec) : 500=82.39%, 750=17.18% 561s lat (msec) : 2=0.29%, 50=0.07% 561s cpu : usr=5.61%, sys=12.46%, ctx=1404, majf=0, minf=0 561s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 561s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 561s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 561s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 561s latency : target=0, window=0, percentile=100.00%, depth=1 561s 561s Run status group 0 (all jobs): 561s WRITE: bw=136MiB/s (143MB/s), 136MiB/s-136MiB/s (143MB/s-143MB/s), io=87.6MiB (91.9MB), run=643-643msec 561s 561s Disk stats (read/write): 561s dm-0: ios=1/1401, sectors=8/179200, merge=0/0, ticks=1/595, in_queue=596, util=86.91%, aggrios=0/351, aggsectors=2/44884, aggrmerge=0/0, aggrticks=0/144, aggrin_queue=145, aggrutil=84.85% 561s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 561s sdb: ios=1/1404, sectors=8/179536, merge=0/0, ticks=0/579, in_queue=580, util=84.85% 561s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 561s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 561s + echo Starting the path changes in background 561s + date +Pre FIO %H:%M:%S.%N 561s Starting the path changes in background 561s + fio --max-jobs=4 /tmp/autopkgtest.bh32B8/tgtbasedmpaths-artifacts/path-change-check.fio 561s Pre FIO 02:40:59.967552620 562s 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 562s fio-3.37 562s Starting 1 thread 742s 742s verify-phase: (groupid=0, jobs=1): err= 0: pid=5636: Fri May 24 02:44:00 2024 742s read: IOPS=3290, BW=206MiB/s (216MB/s)(36.1GiB/180001msec) 742s clat (usec): min=86, max=57238, avg=280.30, stdev=208.45 742s lat (usec): min=86, max=57238, avg=280.42, stdev=208.45 742s clat percentiles (usec): 742s | 1.00th=[ 101], 5.00th=[ 153], 10.00th=[ 174], 20.00th=[ 192], 742s | 30.00th=[ 212], 40.00th=[ 237], 50.00th=[ 273], 60.00th=[ 297], 742s | 70.00th=[ 322], 80.00th=[ 351], 90.00th=[ 404], 95.00th=[ 437], 742s | 99.00th=[ 490], 99.50th=[ 717], 99.90th=[ 1188], 99.95th=[ 1369], 742s | 99.99th=[ 3425] 742s bw ( KiB/s): min=121856, max=410624, per=100.00%, avg=210879.19, stdev=55221.83, samples=359 742s iops : min= 1904, max= 6416, avg=3294.97, stdev=862.86, samples=359 742s lat (usec) : 100=0.96%, 250=42.54%, 500=55.66%, 750=0.37%, 1000=0.24% 742s lat (msec) : 2=0.22%, 4=0.02%, 10=0.01%, 20=0.01%, 50=0.01% 742s lat (msec) : 100=0.01% 742s cpu : usr=9.27%, sys=6.61%, ctx=592377, majf=0, minf=1 742s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 742s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 742s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 742s issued rwts: total=592271,0,0,0 short=0,0,0,0 dropped=0,0,0,0 742s latency : target=0, window=0, percentile=100.00%, depth=1 742s 742s Run status group 0 (all jobs): 742s READ: bw=206MiB/s (216MB/s), 206MiB/s-206MiB/s (216MB/s-216MB/s), io=36.1GiB (38.8GB), run=180001-180001msec 742s 742s Disk stats (read/write): 742s dm-0: ios=592528/9, sectors=75789368/12912, merge=32/8, ticks=169608/70, in_queue=169724, util=100.00%, aggrios=39214/2, aggsectors=5015726/3228, aggrmerge=0/0, aggrticks=10788/6, aggrin_queue=10794, aggrutil=99.15% 742s sdd: ios=29476/0, sectors=3770240/0, merge=0/0, ticks=8680/0, in_queue=8680, util=32.92% 742s sdb: ios=29126/8, sectors=3725312/12912, merge=0/0, ticks=8480/25, in_queue=8503, util=99.15% 742s sde: ios=70113/0, sectors=8968064/0, merge=0/0, ticks=17125/0, in_queue=17125, util=39.76% 742s sdc: ios=28142/0, sectors=3599288/0, merge=0/0, ticks=8870/0, in_queue=8871, util=50.08% 742s + date +Post FIO %H:%M:%S.%N 742s + echo FIO verify test with changing paths - OK 742s + echo Report log of background activity 742s + cat /tmp/autopkgtest.bh32B8/tgtbasedmpaths-artifacts/test-background.log 742s Post FIO 02:44:00.324343788 742s FIO verify test with changing paths - OK 742s Report log of background activity 742s + iscsiadm --mode session 742s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s + sleep 10s 742s + date +MP report (expect 4) %H:%M:%S.%N 742s MP report (expect 4) 02:41:09.974665034 742s + multipath -ll 742s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 742s size=100M features='0' hwhandler='0' wp=rw 742s |-+- policy='service-time 0' prio=1 status=active 742s | `- 1:0:0:1 sdb 8:16 active ready running 742s |-+- policy='service-time 0' prio=1 status=enabled 742s | `- 2:0:0:1 sdc 8:32 active ready running 742s |-+- policy='service-time 0' prio=1 status=enabled 742s | `- 3:0:0:1 sdd 8:48 active ready running 742s `-+- policy='service-time 0' prio=1 status=enabled 742s `- 4:0:0:1 sde 8:64 active ready running 742s + date +UN-plug path 1 %H:%M:%S.%N 742s UN-plug path 1 02:41:10.001376544 742s + iscsiadm --mode session -r 1 -u 742s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 742s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 742s + iscsiadm --mode session 742s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s + sleep 10s 742s + date +MP report (expect 3) %H:%M:%S.%N 742s MP report (expect 3) 02:41:20.112093065 742s + multipath -ll 742s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 742s size=100M features='0' hwhandler='0' wp=rw 742s |-+- policy='service-time 0' prio=1 status=active 742s | `- 2:0:0:1 sdc 8:32 active ready running 742s |-+- policy='service-time 0' prio=1 status=enabled 742s | `- 3:0:0:1 sdd 8:48 active ready running 742s `-+- policy='service-time 0' prio=1 status=enabled 742s `- 4:0:0:1 sde 8:64 active ready running 742s + date +UN-plug path 2 %H:%M:%S.%N 742s UN-plug path 2 02:41:20.136106307 742s + iscsiadm --mode session -r 2 -u 742s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 742s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 742s + iscsiadm --mode session 742s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s + sleep 10s 742s + date +MP report (expect 2) %H:%M:%S.%N 742s MP report (expect 2) 02:41:30.243639440 742s + multipath -ll 742s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 742s size=100M features='0' hwhandler='0' wp=rw 742s |-+- policy='service-time 0' prio=1 status=active 742s | `- 3:0:0:1 sdd 8:48 active ready running 742s `-+- policy='service-time 0' prio=1 status=enabled 742s `- 4:0:0:1 sde 8:64 active ready running 742s + date +UN-plug path 3 %H:%M:%S.%N 742s UN-plug path 3 02:41:30.261790756 742s + iscsiadm --mode session -r 3 -u 742s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 742s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 742s + iscsiadm --mode session 742s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s + sleep 10s 742s + date +MP report (expect 1) %H:%M:%S.%N 742s MP report (expect 1) 02:41:40.346462803 742s + multipath -ll 742s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 742s size=100M features='0' hwhandler='0' wp=rw 742s `-+- policy='service-time 0' prio=1 status=active 742s `- 4:0:0:1 sde 8:64 active ready running 742s + date +Add paths 5/6/7/8 %H:%M:%S.%N 742s Add paths 5/6/7/8 02:41:40.360749660 742s + iscsiadm --mode session -r 4 --op new 742s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 742s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 742s + iscsiadm --mode session -r 4 --op new 742s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 742s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 742s + iscsiadm --mode session -r 4 --op new 742s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 742s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 742s + iscsiadm --mode session -r 4 --op new 742s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 742s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 742s + iscsiadm --mode session 742s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s + sleep 10s 742s + date +MP report (expect 5) %H:%M:%S.%N 742s MP report (expect 5) 02:41:50.495791891 742s + multipath -ll 742s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 742s size=100M features='0' hwhandler='0' wp=rw 742s |-+- policy='service-time 0' prio=1 status=active 742s | `- 4:0:0:1 sde 8:64 active ready running 742s |-+- policy='service-time 0' prio=1 status=enabled 742s | `- 1:0:0:1 sdb 8:16 active ready running 742s |-+- policy='service-time 0' prio=1 status=enabled 742s | `- 2:0:0:1 sdc 8:32 active ready running 742s |-+- policy='service-time 0' prio=1 status=enabled 742s | `- 3:0:0:1 sdd 8:48 active ready running 742s `-+- policy='service-time 0' prio=1 status=enabled 742s `- 5:0:0:1 sdf 8:80 active ready running 742s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 742s UN-plug multiple paths 4/7/8 02:41:50.528552925 742s + iscsiadm --mode session -r 4 -u 742s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 742s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 742s + iscsiadm --mode session -r 7 -u 742s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 742s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 742s + iscsiadm --mode session -r 8 -u 742s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 742s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 742s + iscsiadm --mode session 742s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 742s + sleep 10s 742s + date +Restart multipath daemon %H:%M:%S.%N 742s Restart multipath daemon 02:42:00.804337641 742s + systemctl restart multipathd 742s + sleep 10s 742s + date +Final background report (expect 2) %H:%M:%S.%N 742s Final background report (expect 2) 02:42:10.876635058 742s + multipath -ll 742s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 742s size=100M features='0' hwhandler='0' wp=rw 742s |-+- policy='service-time 0' prio=1 status=active 742s | `- 1:0:0:1 sdb 8:16 active ready running 742s `-+- policy='service-time 0' prio=1 status=enabled 742s `- 2:0:0:1 sdc 8:32 active ready running 742s Final stats 742s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 742s iSCSI SNMP: 742s txdata_octets: 20831256 742s rxdata_octets: 28418486404 742s noptx_pdus: 0 742s scsicmd_pdus: 433717 742s tmfcmd_pdus: 0 742s login_pdus: 0 742s text_pdus: 0 742s dataout_pdus: 0 742s logout_pdus: 0 742s snack_pdus: 0 742s noprx_pdus: 0 742s scsirsp_pdus: 433717 742s tmfrsp_pdus: 0 742s textrsp_pdus: 0 742s datain_pdus: 433683 742s logoutrsp_pdus: 0 742s r2t_pdus: 0 742s async_pdus: 0 742s rjt_pdus: 0 742s digest_err: 0 742s timeout_err: 0 742s iSCSI Extended: 742s tx_sendpage_failures: 0 742s rx_discontiguous_hdr: 0 742s eh_abort_cnt: 0 742s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 742s iSCSI SNMP: 742s txdata_octets: 7368 742s rxdata_octets: 2826548 742s noptx_pdus: 0 742s scsicmd_pdus: 124 742s tmfcmd_pdus: 0 742s login_pdus: 0 742s text_pdus: 0 742s dataout_pdus: 0 742s logout_pdus: 0 742s snack_pdus: 0 742s noprx_pdus: 0 742s scsirsp_pdus: 124 742s tmfrsp_pdus: 0 742s textrsp_pdus: 0 742s datain_pdus: 101 742s logoutrsp_pdus: 0 742s r2t_pdus: 0 742s async_pdus: 0 742s rjt_pdus: 0 742s digest_err: 0 742s timeout_err: 0 742s iSCSI Extended: 742s tx_sendpage_failures: 0 742s rx_discontiguous_hdr: 0 742s eh_abort_cnt: 0 742s May 23 08:01:02 adtubuntu-oracular-ppc64el-server-20240521 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 742s May 23 08:01:02 adtubuntu-oracular-ppc64el-server-20240521 multipathd[282]: multipathd v0.9.4: start up 742s May 23 08:01:02 adtubuntu-oracular-ppc64el-server-20240521 multipathd[282]: reconfigure: setting up paths and maps 742s May 23 08:01:02 adtubuntu-oracular-ppc64el-server-20240521 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 742s May 23 08:02:27 adtubuntu-oracular-ppc64el-server-20240522 multipathd[282]: multipathd: shut down 742s May 23 08:02:27 adtubuntu-oracular-ppc64el-server-20240522 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 742s May 23 08:02:27 adtubuntu-oracular-ppc64el-server-20240522 systemd[1]: multipathd.service: Deactivated successfully. 742s May 23 08:02:27 adtubuntu-oracular-ppc64el-server-20240522 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 742s -- Boot a37ad0b414654401806347a9fbd9b19d -- 742s May 23 08:02:50 adtubuntu-oracular-ppc64el-server-20240522 multipathd[263]: multipathd v0.9.4: start up 742s May 23 08:02:50 adtubuntu-oracular-ppc64el-server-20240522 multipathd[263]: reconfigure: setting up paths and maps 742s May 23 08:02:50 adtubuntu-oracular-ppc64el-server-20240522 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 742s May 23 08:03:17 adtubuntu-oracular-ppc64el-server-20240522 multipathd[263]: multipathd: shut down 742s May 23 08:03:17 adtubuntu-oracular-ppc64el-server-20240522 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 742s May 23 08:03:17 adtubuntu-oracular-ppc64el-server-20240522 systemd[1]: multipathd.service: Deactivated successfully. 742s May 23 08:03:17 adtubuntu-oracular-ppc64el-server-20240522 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 742s -- Boot 94717815395e47eab7b29a31fc011305 -- 742s May 24 02:38:21 adtubuntu-oracular-ppc64el-server-20240522 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 742s May 24 02:38:21 adtubuntu-oracular-ppc64el-server-20240522 multipathd[332]: multipathd v0.9.4: start up 742s May 24 02:38:21 adtubuntu-oracular-ppc64el-server-20240522 multipathd[332]: reconfigure: setting up paths and maps 742s May 24 02:38:21 adtubuntu-oracular-ppc64el-server-20240522 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 742s May 24 02:39:21 autopkgtest multipathd[332]: multipathd: shut down 742s May 24 02:39:21 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 742s May 24 02:39:21 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 742s May 24 02:39:21 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 742s -- Boot 3e54d6becfa6407482fd72fded4d1728 -- 742s May 24 02:39:44 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 742s May 24 02:39:44 autopkgtest multipathd[333]: multipathd v0.9.4: start up 742s May 24 02:39:44 autopkgtest multipathd[333]: reconfigure: setting up paths and maps 742s May 24 02:39:44 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 742s May 24 02:40:50 autopkgtest multipathd[333]: mpatha: addmap [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 742s May 24 02:40:50 autopkgtest multipathd[333]: sdc [8:32]: path added to devmap mpatha 742s May 24 02:40:50 autopkgtest multipathd[333]: mpatha: performing delayed actions 742s May 24 02:40:50 autopkgtest multipathd[333]: 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] 742s May 24 02:41:10 autopkgtest multipathd[333]: 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] 742s May 24 02:41:10 autopkgtest multipathd[333]: check_removed_paths: sdb: freeing path in removed state 742s May 24 02:41:10 autopkgtest multipathd[333]: 8:16: path removed from map mpatha 742s May 24 02:41:20 autopkgtest multipathd[333]: 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] 742s May 24 02:41:20 autopkgtest multipathd[333]: check_removed_paths: sdc: freeing path in removed state 742s May 24 02:41:20 autopkgtest multipathd[333]: 8:32: path removed from map mpatha 742s May 24 02:41:30 autopkgtest multipathd[333]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 742s May 24 02:41:30 autopkgtest multipathd[333]: check_removed_paths: sdd: freeing path in removed state 742s May 24 02:41:30 autopkgtest multipathd[333]: 8:48: path removed from map mpatha 742s May 24 02:41:40 autopkgtest multipathd[333]: 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] 742s May 24 02:41:40 autopkgtest multipathd[333]: sdb [8:16]: path added to devmap mpatha 742s May 24 02:41:40 autopkgtest multipathd[333]: 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] 742s May 24 02:41:40 autopkgtest multipathd[333]: sdc [8:32]: path added to devmap mpatha 742s May 24 02:41:40 autopkgtest multipathd[333]: 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] 742s May 24 02:41:40 autopkgtest multipathd[333]: sdd [8:48]: path added to devmap mpatha 742s May 24 02:41:40 autopkgtest multipathd[333]: 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] 742s May 24 02:41:40 autopkgtest multipathd[333]: sdf [8:80]: path added to devmap mpatha 742s May 24 02:41:50 autopkgtest multipathd[333]: 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] 742s May 24 02:41:50 autopkgtest multipathd[333]: check_removed_paths: sde: freeing path in removed state 742s May 24 02:41:50 autopkgtest multipathd[333]: 8:64: path removed from map mpatha 742s May 24 02:41:50 autopkgtest multipathd[333]: 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] 742s May 24 02:41:50 autopkgtest multipathd[333]: check_removed_paths: sdd: freeing path in removed state 742s May 24 02:41:50 autopkgtest multipathd[333]: 8:48: path removed from map mpatha 742s May 24 02:41:50 autopkgtest multipathd[333]: 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] 742s May 24 02:41:50 autopkgtest multipathd[333]: check_removed_paths: sdf: freeing path in removed state 742s May 24 02:41:50 autopkgtest multipathd[333]: 8:80: path removed from map mpatha 742s May 24 02:42:00 autopkgtest multipathd[333]: multipathd: shut down 742s May 24 02:42:00 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 742s May 24 02:42:00 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 742s May 24 02:42:00 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 742s May 24 02:42:00 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 742s May 24 02:42:00 autopkgtest multipathd[5992]: multipathd v0.9.4: start up 742s May 24 02:42:00 autopkgtest multipathd[5992]: reconfigure: setting up paths and maps 742s May 24 02:42:00 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 742s Check final path status 742s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 742s size=100M features='0' hwhandler='0' wp=rw 742s |-+- policy='service-time 0' prio=1 status=active 742s | `- 1:0:0:1 sdb 8:16 active ready running 742s `-+- policy='service-time 0' prio=1 status=enabled 742s `- 2:0:0:1 sdc 8:32 active ready running 742s + sync 742s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 742s + echo Final stats 742s + iscsiadm --mode session --stats 742s + journalctl --no-pager -u multipathd 742s + echo Check final path status 742s + multipath -ll 742s + multipath -ll 742s + grep --count status= 742s + diskc=2 742s + multipath -ll 742s + grep --count status=active 742s + diska=1 742s + multipath -ll 742s + grep --count status=enabled 742s + diske=1 742s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 742s + echo OK 742s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 742s OK 742s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 742s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 742s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 742s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 742s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 742s autopkgtest [02:44:00]: test tgtbasedmpaths: -----------------------] 743s autopkgtest [02:44:01]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 743s tgtbasedmpaths PASS 743s autopkgtest [02:44:01]: @@@@@@@@@@@@@@@@@@@@ summary 743s kpartx-file-loopback PASS 743s tgtbasedmpaths PASS 760s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240524-023138-juju-7f2275-prod-proposed-migration-environment-3-a82b75fa-a9f3-4620-8fb4-7e8d4a5734d4 from image adt/ubuntu-oracular-ppc64el-server-20240523.img (UUID cda94afc-8fb0-4522-9017-cb501faf689a)... 760s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240524-023138-juju-7f2275-prod-proposed-migration-environment-3-a82b75fa-a9f3-4620-8fb4-7e8d4a5734d4 from image adt/ubuntu-oracular-ppc64el-server-20240523.img (UUID cda94afc-8fb0-4522-9017-cb501faf689a)...