0s autopkgtest [11:52:03]: starting date and time: 2024-05-24 11:52:03+0000 0s autopkgtest [11:52:03]: git checkout: 699e7f9f ssh-setup/nova: explicitely set 'fqdn' in cloud-init 0s autopkgtest [11:52:03]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.vd7u3g5p/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:lvm2 --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=lvm2/2.03.16-3ubuntu4 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos01-ppc64el-19.secgroup --name adt-oracular-ppc64el-multipath-tools-20240524-115203-juju-7f2275-prod-proposed-migration-environment-3-c187b20a-cbaa-40a2-a96b-fdce677718b4 --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/ 385s autopkgtest [11:58:28]: testbed dpkg architecture: ppc64el 385s autopkgtest [11:58:28]: testbed apt version: 2.9.3 385s autopkgtest [11:58:28]: @@@@@@@@@@@@@@@@@@@@ test bed setup 386s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [73.9 kB] 386s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [56.0 kB] 386s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3388 B] 386s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [1964 B] 386s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [524 kB] 386s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [167 kB] 386s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [539 kB] 386s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1968 B] 386s Fetched 1367 kB in 1s (1571 kB/s) 387s Reading package lists... 389s Reading package lists... 389s Building dependency tree... 389s Reading state information... 389s Calculating upgrade... 390s The following packages will be upgraded: 390s dmsetup libdevmapper1.02.1 390s 2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 390s Need to get 272 kB of archives. 390s After this operation, 0 B of additional disk space will be used. 390s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libdevmapper1.02.1 ppc64el 2:1.02.185-3ubuntu4 [181 kB] 390s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dmsetup ppc64el 2:1.02.185-3ubuntu4 [91.3 kB] 390s Fetched 272 kB in 0s (599 kB/s) 390s (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 ... 72606 files and directories currently installed.) 390s Preparing to unpack .../libdevmapper1.02.1_2%3a1.02.185-3ubuntu4_ppc64el.deb ... 391s Unpacking libdevmapper1.02.1:ppc64el (2:1.02.185-3ubuntu4) over (2:1.02.185-3ubuntu3) ... 391s Preparing to unpack .../dmsetup_2%3a1.02.185-3ubuntu4_ppc64el.deb ... 391s Unpacking dmsetup (2:1.02.185-3ubuntu4) over (2:1.02.185-3ubuntu3) ... 391s Setting up libdevmapper1.02.1:ppc64el (2:1.02.185-3ubuntu4) ... 391s Setting up dmsetup (2:1.02.185-3ubuntu4) ... 391s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 391s Processing triggers for man-db (2.12.1-1) ... 391s Processing triggers for initramfs-tools (0.142ubuntu27) ... 391s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 391s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 398s Reading package lists... 399s Building dependency tree... 399s Reading state information... 399s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 400s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 400s Get:2 http://ftpmaster.internal/ubuntu oracular InRelease [73.9 kB] 400s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 400s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 400s Get:5 http://ftpmaster.internal/ubuntu oracular/universe Sources [20.0 MB] 401s Get:6 http://ftpmaster.internal/ubuntu oracular/main Sources [1387 kB] 401s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el Packages [1339 kB] 401s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el Packages [15.5 MB] 407s Fetched 38.3 MB in 8s (5031 kB/s) 408s Reading package lists... 408s Reading package lists... 408s Building dependency tree... 408s Reading state information... 408s Calculating upgrade... 408s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 408s Reading package lists... 409s Building dependency tree... 409s Reading state information... 409s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 409s autopkgtest [11:58:52]: rebooting testbed after setup commands that affected boot 452s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 461s autopkgtest [11:59:44]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 473s autopkgtest [11:59:56]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 477s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 477s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 477s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 477s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 477s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 477s gpgv: issuer "steve.langasek@ubuntu.com" 477s gpgv: Can't check signature: No public key 477s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 478s autopkgtest [12:00:01]: testing package multipath-tools version 0.9.4-5ubuntu8 478s autopkgtest [12:00:01]: build not needed 478s autopkgtest [12:00:01]: test kpartx-file-loopback: preparing testbed 480s Reading package lists... 480s Building dependency tree... 480s Reading state information... 480s Starting pkgProblemResolver with broken count: 0 480s Starting 2 pkgProblemResolver with broken count: 0 480s Done 480s The following additional packages will be installed: 480s liburing2 qemu-utils 480s Recommended packages: 480s qemu-block-extra 480s The following NEW packages will be installed: 480s autopkgtest-satdep liburing2 qemu-utils 480s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 480s Need to get 2330 kB/2331 kB of archives. 480s After this operation, 15.4 MB of additional disk space will be used. 480s Get:1 /tmp/autopkgtest.MDKOup/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 481s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 481s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 482s Fetched 2330 kB in 1s (1566 kB/s) 482s Selecting previously unselected package liburing2:ppc64el. 482s (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 ... 72606 files and directories currently installed.) 482s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 482s Unpacking liburing2:ppc64el (2.6-1) ... 482s Selecting previously unselected package qemu-utils. 482s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 482s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 482s Selecting previously unselected package autopkgtest-satdep. 482s Preparing to unpack .../1-autopkgtest-satdep.deb ... 482s Unpacking autopkgtest-satdep (0) ... 482s Setting up liburing2:ppc64el (2.6-1) ... 482s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 482s Setting up autopkgtest-satdep (0) ... 482s Processing triggers for man-db (2.12.1-1) ... 483s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 486s (Reading database ... 72626 files and directories currently installed.) 486s Removing autopkgtest-satdep (0) ... 488s autopkgtest [12:00:11]: test kpartx-file-loopback: [----------------------- 488s Formatting 'foo.img', fmt=raw size=20971520 490s Creating new GPT entries in memory. 490s Warning: The kernel is still using the old partition table. 490s The new table will be used at the next reboot or after you 490s run partprobe(8) or kpartx(8) 490s The operation has completed successfully. 490s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 490s standard_filename: OK 490s del devmap : loop0p1 490s No devices found 490s standard_filename_cleanup: OK 490s Formatting 'fou du FaFa.img', fmt=raw size=20971520 491s Creating new GPT entries in memory. 491s Warning: The kernel is still using the old partition table. 491s The new table will be used at the next reboot or after you 491s run partprobe(8) or kpartx(8) 491s The operation has completed successfully. 491s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 491s filename_with_spaces: OK 491s del devmap : loop0p1 491s No devices found 491s filename_with_spaces_cleanup: OK 491s autopkgtest [12:00:14]: test kpartx-file-loopback: -----------------------] 492s autopkgtest [12:00:15]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 492s kpartx-file-loopback PASS 492s autopkgtest [12:00:15]: test tgtbasedmpaths: preparing testbed 783s autopkgtest [12:05:06]: testbed dpkg architecture: ppc64el 783s autopkgtest [12:05:06]: testbed apt version: 2.9.3 783s autopkgtest [12:05:06]: @@@@@@@@@@@@@@@@@@@@ test bed setup 784s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [73.9 kB] 784s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [1964 B] 784s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [524 kB] 784s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3388 B] 784s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [56.0 kB] 784s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [167 kB] 784s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [539 kB] 784s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1968 B] 785s Fetched 1367 kB in 1s (1610 kB/s) 785s Reading package lists... 787s Reading package lists... 787s Building dependency tree... 787s Reading state information... 787s Calculating upgrade... 787s The following packages will be upgraded: 787s dmsetup libdevmapper1.02.1 787s 2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 787s Need to get 272 kB of archives. 787s After this operation, 0 B of additional disk space will be used. 787s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libdevmapper1.02.1 ppc64el 2:1.02.185-3ubuntu4 [181 kB] 788s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dmsetup ppc64el 2:1.02.185-3ubuntu4 [91.3 kB] 788s Fetched 272 kB in 0s (644 kB/s) 788s (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 ... 72606 files and directories currently installed.) 788s Preparing to unpack .../libdevmapper1.02.1_2%3a1.02.185-3ubuntu4_ppc64el.deb ... 788s Unpacking libdevmapper1.02.1:ppc64el (2:1.02.185-3ubuntu4) over (2:1.02.185-3ubuntu3) ... 788s Preparing to unpack .../dmsetup_2%3a1.02.185-3ubuntu4_ppc64el.deb ... 788s Unpacking dmsetup (2:1.02.185-3ubuntu4) over (2:1.02.185-3ubuntu3) ... 788s Setting up libdevmapper1.02.1:ppc64el (2:1.02.185-3ubuntu4) ... 788s Setting up dmsetup (2:1.02.185-3ubuntu4) ... 788s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 788s Processing triggers for man-db (2.12.1-1) ... 789s Processing triggers for initramfs-tools (0.142ubuntu27) ... 789s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 789s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 796s Reading package lists... 796s Building dependency tree... 796s Reading state information... 796s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 796s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 796s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 796s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 797s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 797s Reading package lists... 798s Reading package lists... 798s Building dependency tree... 798s Reading state information... 798s Calculating upgrade... 798s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 798s Reading package lists... 798s Building dependency tree... 798s Reading state information... 799s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 799s autopkgtest [12:05:22]: rebooting testbed after setup commands that affected boot 833s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 854s Reading package lists... 854s Building dependency tree... 854s Reading state information... 854s Starting pkgProblemResolver with broken count: 0 854s Starting 2 pkgProblemResolver with broken count: 0 854s Done 854s The following additional packages will be installed: 854s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 854s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 854s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 854s librdmacm1t64 lsscsi open-iscsi tgt 854s Suggested packages: 854s fio-examples gnuplot tgt-glusterfs tgt-rbd 854s Recommended packages: 854s finalrd 855s The following NEW packages will be installed: 855s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 855s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 855s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 855s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 855s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 855s Need to get 10.8 MB/10.8 MB of archives. 855s After this operation, 49.9 MB of additional disk space will be used. 855s Get:1 /tmp/autopkgtest.MDKOup/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 855s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu4 [54.4 kB] 855s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-0.3build3 [119 kB] 855s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu4 [389 kB] 855s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 855s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 855s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu6 [256 kB] 855s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4build3 [21.5 kB] 855s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4build3 [311 kB] 855s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4build3 [47.0 kB] 855s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4build3 [100 kB] 855s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.1-1 [97.4 kB] 855s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 855s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 855s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 855s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-2.1ubuntu3 [260 kB] 855s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-2.1ubuntu3 [280 kB] 855s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu6 [4050 kB] 855s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 855s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu6 [3612 kB] 856s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 856s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 856s Preconfiguring packages ... 856s Fetched 10.8 MB in 1s (10.9 MB/s) 856s Selecting previously unselected package libopeniscsiusr. 856s (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 ... 72606 files and directories currently installed.) 856s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu4_ppc64el.deb ... 856s Unpacking libopeniscsiusr (2.1.9-3ubuntu4) ... 856s Selecting previously unselected package libisns0t64:ppc64el. 856s Preparing to unpack .../01-libisns0t64_0.101-0.3build3_ppc64el.deb ... 856s Unpacking libisns0t64:ppc64el (0.101-0.3build3) ... 856s Selecting previously unselected package open-iscsi. 856s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu4_ppc64el.deb ... 856s Unpacking open-iscsi (2.1.9-3ubuntu4) ... 856s Selecting previously unselected package librdmacm1t64:ppc64el. 856s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 856s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 856s Selecting previously unselected package libconfig-general-perl. 856s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 856s Unpacking libconfig-general-perl (2.65-2) ... 856s Selecting previously unselected package tgt. 856s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu6_ppc64el.deb ... 856s Unpacking tgt (1:1.0.85-1.1ubuntu6) ... 856s Selecting previously unselected package libgfxdr0:ppc64el. 856s Preparing to unpack .../06-libgfxdr0_11.1-4build3_ppc64el.deb ... 856s Unpacking libgfxdr0:ppc64el (11.1-4build3) ... 856s Selecting previously unselected package libglusterfs0:ppc64el. 856s Preparing to unpack .../07-libglusterfs0_11.1-4build3_ppc64el.deb ... 856s Unpacking libglusterfs0:ppc64el (11.1-4build3) ... 856s Selecting previously unselected package libgfrpc0:ppc64el. 856s Preparing to unpack .../08-libgfrpc0_11.1-4build3_ppc64el.deb ... 856s Unpacking libgfrpc0:ppc64el (11.1-4build3) ... 856s Selecting previously unselected package libgfapi0:ppc64el. 856s Preparing to unpack .../09-libgfapi0_11.1-4build3_ppc64el.deb ... 856s Unpacking libgfapi0:ppc64el (11.1-4build3) ... 856s Selecting previously unselected package libnbd0. 856s Preparing to unpack .../10-libnbd0_1.20.1-1_ppc64el.deb ... 856s Unpacking libnbd0 (1.20.1-1) ... 856s Selecting previously unselected package libdaxctl1:ppc64el. 856s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 856s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 856s Selecting previously unselected package libndctl6:ppc64el. 856s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 856s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 856s Selecting previously unselected package libpmem1:ppc64el. 856s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 856s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 856s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 856s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 856s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 856s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 856s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 856s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 856s Selecting previously unselected package librados2. 856s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu6_ppc64el.deb ... 856s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 856s Selecting previously unselected package libpmemobj1:ppc64el. 856s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 856s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 856s Selecting previously unselected package librbd1. 856s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu6_ppc64el.deb ... 856s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 857s Selecting previously unselected package fio. 857s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 857s Unpacking fio (3.37-1) ... 857s Selecting previously unselected package lsscsi. 857s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 857s Unpacking lsscsi (0.32-1build1) ... 857s Selecting previously unselected package autopkgtest-satdep. 857s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 857s Unpacking autopkgtest-satdep (0) ... 857s Setting up libconfig-general-perl (2.65-2) ... 857s Setting up libisns0t64:ppc64el (0.101-0.3build3) ... 857s Setting up libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 857s Setting up libnbd0 (1.20.1-1) ... 857s Setting up libopeniscsiusr (2.1.9-3ubuntu4) ... 857s Setting up libglusterfs0:ppc64el (11.1-4build3) ... 857s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 857s Setting up lsscsi (0.32-1build1) ... 857s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 857s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 857s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 857s Setting up tgt (1:1.0.85-1.1ubuntu6) ... 857s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 857s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 857s Setting up libgfxdr0:ppc64el (11.1-4build3) ... 857s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 857s Setting up open-iscsi (2.1.9-3ubuntu4) ... 858s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 859s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 859s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 859s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 859s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 859s Setting up libgfrpc0:ppc64el (11.1-4build3) ... 859s Setting up libgfapi0:ppc64el (11.1-4build3) ... 859s Setting up fio (3.37-1) ... 859s Setting up autopkgtest-satdep (0) ... 859s Processing triggers for man-db (2.12.1-1) ... 860s Processing triggers for initramfs-tools (0.142ubuntu27) ... 860s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 860s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 867s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 871s (Reading database ... 72847 files and directories currently installed.) 871s Removing autopkgtest-satdep (0) ... 873s autopkgtest [12:06:36]: test tgtbasedmpaths: [----------------------- 873s + targetname=iqn.2016-11.foo.com:target.iscsi 873s + pwd 873s + cwd=/tmp/autopkgtest.MDKOup/build.xe4/src 873s + testdir=/mnt/tgtmpathtest 873s + localhost=127.0.0.1 873s + portal=127.0.0.1:3260 873s + maxpaths=4 873s + backfn=backingfile 873s + expectwwid=60000000000000000e00000000010001 873s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 873s + bglog=/tmp/autopkgtest.MDKOup/tgtbasedmpaths-artifacts/test-background.log 873s + fioprep=/tmp/autopkgtest.MDKOup/tgtbasedmpaths-artifacts/path-change-prep.fio 873s + fiovrfy=/tmp/autopkgtest.MDKOup/tgtbasedmpaths-artifacts/path-change-check.fio 873s + service tgt restart 874s + truncate --size 100M backingfile 874s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 874s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 874s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.MDKOup/build.xe4/src/backingfile 874s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 874s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 874s login #1 874s + echo login #1 874s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 874s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 874s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 874s + seq 2 4 874s extra login #2 874s + echo extra login #2 874s + iscsiadm --mode session -r 1 --op new 874s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 874s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 874s + extra login #3 874s echo extra login #3 874s + iscsiadm --mode session -r 1 --op new 874s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 874s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 874s + echo extra login #4 874s + iscsiadm --mode session -r 1 --op new 874s extra login #4 874s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 874s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 874s + udevadm settle 874s + sleep 5 879s Status after initial setup 879s + echo Status after initial setup 879s + tgtadm --lld iscsi --mode target --op show 879s Target 1: iqn.2016-11.foo.com:target.iscsi 879s System information: 879s Driver: iscsi 879s State: ready 879s I_T nexus information: 879s I_T nexus: 1 879s Initiator: iqn.2004-10.com.ubuntu:01:166173d7d84c alias: autopkgtest 879s Connection: 0 879s IP Address: 127.0.0.1 879s I_T nexus: 2 879s Initiator: iqn.2004-10.com.ubuntu:01:166173d7d84c alias: autopkgtest 879s Connection: 0 879s IP Address: 127.0.0.1 879s I_T nexus: 3 879s Initiator: iqn.2004-10.com.ubuntu:01:166173d7d84c alias: autopkgtest 879s Connection: 0 879s IP Address: 127.0.0.1 879s I_T nexus: 4 879s Initiator: iqn.2004-10.com.ubuntu:01:166173d7d84c alias: autopkgtest 879s Connection: 0 879s IP Address: 127.0.0.1 879s LUN information: 879s LUN: 0 879s Type: controller 879s SCSI ID: IET 00010000 879s SCSI SN: beaf10 879s Size: 0 MB, Block size: 1 879s Online: Yes 879s Removable media: No 879s Prevent removal: No 879s Readonly: No 879s SWP: No 879s Thin-provisioning: No 879s Backing store type: null 879s Backing store path: None 879s Backing store flags: 879s LUN: 1 879s Type: disk 879s SCSI ID: IET 00010001 879s SCSI SN: beaf11 879s Size: 105 MB, Block size: 512 879s Online: Yes 879s Removable media: No 879s Prevent removal: No 879s Readonly: No 879s SWP: No 879s Thin-provisioning: No 879s Backing store type: rdwr 879s Backing store path: /tmp/autopkgtest.MDKOup/build.xe4/src/backingfile 879s Backing store flags: 879s Account information: 879s ACL information: 879s ALL 879s + tgtadm --lld iscsi --op show --mode conn --tid 1 879s + iscsiadm --mode session -P 1 879s Session: 4 879s Connection: 0 879s Initiator: iqn.2004-10.com.ubuntu:01:166173d7d84c 879s IP Address: 127.0.0.1 879s Session: 3 879s Connection: 0 879s Initiator: iqn.2004-10.com.ubuntu:01:166173d7d84c 879s IP Address: 127.0.0.1 879s Session: 2 879s Connection: 0 879s Initiator: iqn.2004-10.com.ubuntu:01:166173d7d84c 879s IP Address: 127.0.0.1 879s Session: 1 879s Connection: 0 879s Initiator: iqn.2004-10.com.ubuntu:01:166173d7d84c 879s IP Address: 127.0.0.1 879s + lsscsi -liv 879s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 879s Current Portal: 127.0.0.1:3260,1 879s Persistent Portal: 127.0.0.1:3260,1 879s ********** 879s Interface: 879s ********** 879s Iface Name: default 879s Iface Transport: tcp 879s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:166173d7d84c 879s Iface IPaddress: 127.0.0.1 879s Iface HWaddress: default 879s Iface Netdev: default 879s SID: 1 879s iSCSI Connection State: LOGGED IN 879s iSCSI Session State: LOGGED_IN 879s Internal iscsid Session State: NO CHANGE 879s 879s ********** 879s Interface: 879s ********** 879s Iface Name: default 879s Iface Transport: tcp 879s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:166173d7d84c 879s Iface IPaddress: 127.0.0.1 879s Iface HWaddress: default 879s Iface Netdev: default 879s SID: 2 879s iSCSI Connection State: LOGGED IN 879s iSCSI Session State: LOGGED_IN 879s Internal iscsid Session State: NO CHANGE 879s 879s ********** 879s Interface: 879s ********** 879s Iface Name: default 879s Iface Transport: tcp 879s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:166173d7d84c 879s Iface IPaddress: 127.0.0.1 879s Iface HWaddress: default 879s Iface Netdev: default 879s SID: 3 879s iSCSI Connection State: LOGGED IN 879s iSCSI Session State: LOGGED_IN 879s Internal iscsid Session State: NO CHANGE 879s 879s ********** 879s Interface: 879s ********** 879s Iface Name: default 879s Iface Transport: tcp 879s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:166173d7d84c 879s Iface IPaddress: 127.0.0.1 879s Iface HWaddress: default 879s Iface Netdev: default 879s SID: 4 879s iSCSI Connection State: LOGGED IN 879s iSCSI Session State: LOGGED_IN 879s Internal iscsid Session State: NO CHANGE 879s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 879s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 879s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 879s 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] 879s [1:0:0:0] storage IET Controller 0001 - - 879s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 879s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 879s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 879s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 879s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 879s [2:0:0:0] storage IET Controller 0001 - - 879s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 879s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 879s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 879s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 879s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 879s [3:0:0:0] storage IET Controller 0001 - - 879s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 879s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 879s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 879s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 879s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 879s [4:0:0:0] storage IET Controller 0001 - - 879s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 879s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 879s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 33000000100000001 879s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 879s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 879s NVMe module may not be loaded 879s + multipath -v3 -ll 879s 57.143940 | set open fds limit to 1048576/1048576 879s 57.144022 | loading /lib/multipath/libchecktur.so checker 879s 57.144123 | checker tur: message table size = 3 879s 57.144148 | loading /lib/multipath/libprioconst.so prioritizer 879s 57.144245 | _init_foreign: foreign library "nvme" is not enabled 879s 57.149542 | sda: size = 167772160 879s 57.149701 | sda: vendor = QEMU 879s 57.149741 | sda: product = QEMU HARDDISK 879s 57.149763 | sda: rev = 2.5+ 879s 57.150396 | sda: h:b:t:l = 0:0:0:0 879s 57.150699 | sda: tgt_node_name = 879s 57.150719 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 879s 57.150722 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 879s 57.150865 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 879s 57.150885 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 879s 57.150896 | __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 879s 57.150900 | failed to read sysfs vpd pg80: No such file or directory 879s 57.151022 | sda: fail to get serial 879s 57.151042 | sda: detect_checker = yes (setting: multipath internal) 879s 57.151186 | sda: path_checker = tur (setting: multipath internal) 879s 57.151208 | sda: checker timeout = 30 s (setting: kernel sysfs) 879s 57.151293 | sda: tur state = up 879s 57.151593 | sdb: size = 204800 879s 57.151736 | sdb: vendor = IET 879s 57.151774 | sdb: product = VIRTUAL-DISK 879s 57.151795 | sdb: rev = 0001 879s 57.152447 | sdb: h:b:t:l = 1:0:0:1 879s 57.152802 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 879s 57.152823 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 879s 57.152825 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 879s 57.152978 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 879s 57.152998 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 879s 57.153012 | sdb: serial = beaf11 879s 57.153015 | sdb: detect_checker = yes (setting: multipath internal) 879s 57.153351 | sdb: path_checker = tur (setting: multipath internal) 879s 57.153372 | sdb: checker timeout = 30 s (setting: kernel sysfs) 879s ===== paths list ===== 879s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 879s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 879s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 879s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 879s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 879s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 879s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 879s size=100M features='0' hwhandler='0' wp=rw 879s |-+- policy='service-time 0' prio=1 status=active 879s | `- 1:0:0:1 sdb 8:16 active ready running 879s |-+- policy='service-time 0' prio=1 status=enabled 879s | `- 2:0:0:1 sdc 8:32 active ready running 879s |-+- policy='service-time 0' prio=1 status=enabled 879s | `- 3:0:0:1 sdd 8:48 active ready running 879s `-+- policy='service-time 0' prio=1 status=enabled 879s `- 4:0:0:1 sde 8:64 active ready running 879s 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 879s Test WWN should now point to DM 879s ../../dm-0 879s Creating filesystem with 25600 4k blocks and 25600 inodes 879s 879s Allocating group tables: 0/1 done 879s Writing inode tables: 0/1 done 879s Creating journal (1024 blocks): done 879s Writing superblocks and filesystem accounting information: 0/1 done 879s 879s 57.153605 | sdb: tur state = up 879s 57.153742 | sdc: size = 204800 879s 57.153913 | sdc: vendor = IET 879s 57.153954 | sdc: product = VIRTUAL-DISK 879s 57.153977 | sdc: rev = 0001 879s 57.154654 | sdc: h:b:t:l = 2:0:0:1 879s 57.155006 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 879s 57.155027 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 879s 57.155029 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 879s 57.155177 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 879s 57.155197 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 879s 57.155212 | sdc: serial = beaf11 879s 57.155214 | sdc: detect_checker = yes (setting: multipath internal) 879s 57.155495 | sdc: path_checker = tur (setting: multipath internal) 879s 57.155516 | sdc: checker timeout = 30 s (setting: kernel sysfs) 879s 57.155745 | sdc: tur state = up 879s 57.155890 | sdd: size = 204800 879s 57.156045 | sdd: vendor = IET 879s 57.156073 | sdd: product = VIRTUAL-DISK 879s 57.156113 | sdd: rev = 0001 879s 57.156789 | sdd: h:b:t:l = 3:0:0:1 879s 57.157142 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 879s 57.157163 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 879s 57.157165 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 879s 57.157316 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 879s 57.157336 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 879s 57.157350 | sdd: serial = beaf11 879s 57.157353 | sdd: detect_checker = yes (setting: multipath internal) 879s 57.157635 | sdd: path_checker = tur (setting: multipath internal) 879s 57.157656 | sdd: checker timeout = 30 s (setting: kernel sysfs) 879s 57.157880 | sdd: tur state = up 879s 57.158025 | sde: size = 204800 879s 57.158176 | sde: vendor = IET 879s 57.158215 | sde: product = VIRTUAL-DISK 879s 57.158238 | sde: rev = 0001 879s 57.158931 | sde: h:b:t:l = 4:0:0:1 879s 57.159280 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 879s 57.159301 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 879s 57.159303 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 879s 57.159452 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 879s 57.159472 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 879s 57.159486 | sde: serial = beaf11 879s 57.159489 | sde: detect_checker = yes (setting: multipath internal) 879s 57.159762 | sde: path_checker = tur (setting: multipath internal) 879s 57.159782 | sde: checker timeout = 30 s (setting: kernel sysfs) 879s 57.159935 | sde: tur state = up 879s 57.160084 | loop0: device node name blacklisted 879s 57.160196 | loop1: device node name blacklisted 879s 57.160301 | loop2: device node name blacklisted 879s 57.160404 | loop3: device node name blacklisted 879s 57.160507 | loop4: device node name blacklisted 879s 57.160610 | loop5: device node name blacklisted 879s 57.160712 | loop6: device node name blacklisted 879s 57.160813 | loop7: device node name blacklisted 879s 57.160922 | dm-0: device node name blacklisted 879s 57.161871 | multipath-tools v0.9.4 (12/19, 2022) 879s 57.161899 | libdevmapper version 1.02.185 879s 57.162032 | kernel device mapper v4.48.0 879s 57.162060 | DM multipath kernel driver v1.14.0 879s 57.162166 | sdb: size = 204800 879s 57.162188 | sdb: vendor = IET 879s 57.162191 | sdb: product = VIRTUAL-DISK 879s 57.162193 | sdb: rev = 0001 879s 57.162812 | sdb: h:b:t:l = 1:0:0:1 879s 57.162945 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 879s 57.162982 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 879s 57.162985 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 879s 57.162998 | sdb: serial = beaf11 879s 57.163218 | sdb: tur state = up 879s 57.163239 | sdb: uid = 360000000000000000e00000000010001 (udev) 879s 57.163242 | sdb: detect_prio = yes (setting: multipath internal) 879s 57.163245 | sdb: prio = const (setting: multipath internal) 879s 57.163247 | sdb: prio args = "" (setting: multipath internal) 879s 57.163249 | sdb: const prio = 1 879s 57.163274 | sdc: size = 204800 879s 57.163293 | sdc: vendor = IET 879s 57.163295 | sdc: product = VIRTUAL-DISK 879s 57.163298 | sdc: rev = 0001 879s 57.163900 | sdc: h:b:t:l = 2:0:0:1 879s 57.164036 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 879s 57.164061 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 879s 57.164064 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 879s 57.164075 | sdc: serial = beaf11 879s 57.164365 | sdc: tur state = up 879s 57.164385 | sdc: uid = 360000000000000000e00000000010001 (udev) 879s 57.164387 | sdc: detect_prio = yes (setting: multipath internal) 879s 57.164390 | sdc: prio = const (setting: multipath internal) 879s 57.164392 | sdc: prio args = "" (setting: multipath internal) 879s 57.164394 | sdc: const prio = 1 879s 57.164418 | sdd: size = 204800 879s 57.164422 | sdd: vendor = IET 879s 57.164425 | sdd: product = VIRTUAL-DISK 879s 57.164428 | sdd: rev = 0001 879s 57.165027 | sdd: h:b:t:l = 3:0:0:1 879s 57.165159 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 879s 57.165196 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 879s 57.165199 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 879s 57.165211 | sdd: serial = beaf11 879s 57.165473 | sdd: tur state = up 879s 57.165494 | sdd: uid = 360000000000000000e00000000010001 (udev) 879s 57.165497 | sdd: detect_prio = yes (setting: multipath internal) 879s 57.165499 | sdd: prio = const (setting: multipath internal) 879s 57.165501 | sdd: prio args = "" (setting: multipath internal) 879s 57.165503 | sdd: const prio = 1 879s 57.165527 | sde: size = 204800 879s 57.165531 | sde: vendor = IET 879s 57.165534 | sde: product = VIRTUAL-DISK 879s 57.165537 | sde: rev = 0001 879s 57.166166 | sde: h:b:t:l = 4:0:0:1 879s 57.166297 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 879s 57.166334 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 879s 57.166337 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 879s 57.166349 | sde: serial = beaf11 879s 57.166576 | sde: tur state = up 879s 57.166597 | sde: uid = 360000000000000000e00000000010001 (udev) 879s 57.166599 | sde: detect_prio = yes (setting: multipath internal) 879s 57.166602 | sde: prio = const (setting: multipath internal) 879s 57.166604 | sde: prio args = "" (setting: multipath internal) 879s 57.166606 | sde: const prio = 1 879s 57.167426 | unloading tur checker 879s 57.167478 | unloading const prioritizer 879s + dmsetup table 879s + echo Test WWN should now point to DM 879s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 879s + grep dm 879s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 879s mke2fs 1.47.0 (5-Feb-2023) 879s + udevadm settle 879s + sleep 3s 882s + mkdir -p /mnt/tgtmpathtest 882s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 882s + cat 882s + cat 882s + fio --max-jobs=4 /tmp/autopkgtest.MDKOup/tgtbasedmpaths-artifacts/path-change-prep.fio 882s 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 882s fio-3.37 882s Starting 1 thread 882s write-phase: Laying out IO file (1 file / 17592186044415MiB) 883s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 883s 883s write-phase: (groupid=0, jobs=1): err= 0: pid=5662: Fri May 24 12:06:46 2024 883s write: IOPS=2532, BW=158MiB/s (166MB/s)(87.6MiB/554msec); 0 zone resets 883s clat (usec): min=243, max=2995, avg=379.85, stdev=88.40 883s lat (usec): min=257, max=3009, avg=393.21, stdev=88.45 883s clat percentiles (usec): 883s | 1.00th=[ 302], 5.00th=[ 318], 10.00th=[ 326], 20.00th=[ 343], 883s | 30.00th=[ 359], 40.00th=[ 371], 50.00th=[ 375], 60.00th=[ 383], 883s | 70.00th=[ 392], 80.00th=[ 400], 90.00th=[ 416], 95.00th=[ 441], 883s | 99.00th=[ 586], 99.50th=[ 750], 99.90th=[ 1057], 99.95th=[ 2999], 883s | 99.99th=[ 2999] 883s bw ( KiB/s): min=162432, max=162432, per=100.00%, avg=162432.00, stdev= 0.00, samples=1 883s iops : min= 2538, max= 2538, avg=2538.00, stdev= 0.00, samples=1 883s lat (usec) : 250=0.07%, 500=97.72%, 750=1.57%, 1000=0.43% 883s lat (msec) : 2=0.07%, 4=0.07% 883s cpu : usr=6.51%, sys=7.59%, ctx=1404, majf=0, minf=0 883s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 883s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 883s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 883s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 883s latency : target=0, window=0, percentile=100.00%, depth=1 883s 883s Run status group 0 (all jobs): 883s WRITE: bw=158MiB/s (166MB/s), 158MiB/s-158MiB/s (166MB/s-166MB/s), io=87.6MiB (91.9MB), run=554-554msec 883s 883s Disk stats (read/write): 883s dm-0: ios=1/983, sectors=8/125824, merge=0/0, ticks=2/349, in_queue=351, util=80.82%, aggrios=0/351, aggsectors=2/44884, aggrmerge=0/0, aggrticks=0/122, aggrin_queue=123, aggrutil=82.96% 883s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 883s sdb: ios=1/1404, sectors=8/179536, merge=0/0, ticks=2/490, in_queue=492, util=82.96% 883s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 883s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 883s + echo Starting the path changes in background 883s + date +Pre FIO %H:%M:%S.%N 883s Starting the path changes in background 883s Pre FIO 12:06:46.462570597 883s + fio --max-jobs=4 /tmp/autopkgtest.MDKOup/tgtbasedmpaths-artifacts/path-change-check.fio 883s 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 883s fio-3.37 883s Starting 1 thread 1063s 1063s verify-phase: (groupid=0, jobs=1): err= 0: pid=5669: Fri May 24 12:09:46 2024 1063s read: IOPS=3265, BW=204MiB/s (214MB/s)(35.9GiB/180001msec) 1063s clat (usec): min=86, max=52682, avg=282.50, stdev=171.82 1063s lat (usec): min=86, max=52682, avg=282.62, stdev=171.82 1063s clat percentiles (usec): 1063s | 1.00th=[ 98], 5.00th=[ 149], 10.00th=[ 155], 20.00th=[ 190], 1063s | 30.00th=[ 217], 40.00th=[ 255], 50.00th=[ 289], 60.00th=[ 310], 1063s | 70.00th=[ 330], 80.00th=[ 363], 90.00th=[ 404], 95.00th=[ 433], 1063s | 99.00th=[ 486], 99.50th=[ 545], 99.90th=[ 1139], 99.95th=[ 1467], 1063s | 99.99th=[ 3032] 1063s bw ( KiB/s): min=138752, max=388736, per=100.00%, avg=209293.09, stdev=57090.97, samples=359 1063s iops : min= 2168, max= 6074, avg=3270.18, stdev=892.04, samples=359 1063s lat (usec) : 100=1.37%, 250=37.61%, 500=60.25%, 750=0.51%, 1000=0.12% 1063s lat (msec) : 2=0.12%, 4=0.02%, 10=0.01%, 20=0.01%, 50=0.01% 1063s lat (msec) : 100=0.01% 1063s cpu : usr=8.83%, sys=6.74%, ctx=587864, majf=0, minf=1 1063s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 1063s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1063s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1063s issued rwts: total=587778,0,0,0 short=0,0,0,0 dropped=0,0,0,0 1063s latency : target=0, window=0, percentile=100.00%, depth=1 1063s 1063s Run status group 0 (all jobs): 1063s READ: bw=204MiB/s (214MB/s), 204MiB/s-204MiB/s (214MB/s-214MB/s), io=35.9GiB (38.5GB), run=180001-180001msec 1063s 1063s Disk stats (read/write): 1063s dm-0: ios=588024/9, sectors=75212856/12912, merge=30/8, ticks=172595/72, in_queue=172710, util=100.00%, aggrios=40582/2, aggsectors=5190702/3228, aggrmerge=0/0, aggrticks=10770/6, aggrin_queue=10777, aggrutil=99.16% 1063s sdd: ios=33743/0, sectors=4316032/0, merge=0/0, ticks=8547/0, in_queue=8547, util=32.98% 1063s sdb: ios=32537/8, sectors=4161536/12912, merge=0/0, ticks=8414/27, in_queue=8442, util=99.16% 1063s sde: ios=59021/0, sectors=7549312/0, merge=0/0, ticks=17583/0, in_queue=17583, util=39.75% 1063s sdc: ios=37030/0, sectors=4735928/0, merge=0/0, ticks=8538/0, in_queue=8538, util=50.04% 1063s + date +Post FIO %H:%M:%S.%N 1063s + echo FIO verify test with changing paths - OK 1063s + echo Report log of background activity 1063s + cat /tmp/autopkgtest.MDKOup/tgtbasedmpaths-artifacts/test-background.log 1063s Post FIO 12:09:46.804747218 1063s FIO verify test with changing paths - OK 1063s Report log of background activity 1063s + iscsiadm --mode session 1063s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s + sleep 10s 1063s + date +MP report (expect 4) %H:%M:%S.%N 1063s MP report (expect 4) 12:06:56.468965184 1063s + multipath -ll 1063s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1063s size=100M features='0' hwhandler='0' wp=rw 1063s |-+- policy='service-time 0' prio=1 status=active 1063s | `- 1:0:0:1 sdb 8:16 active ready running 1063s |-+- policy='service-time 0' prio=1 status=enabled 1063s | `- 2:0:0:1 sdc 8:32 active ready running 1063s |-+- policy='service-time 0' prio=1 status=enabled 1063s | `- 3:0:0:1 sdd 8:48 active ready running 1063s `-+- policy='service-time 0' prio=1 status=enabled 1063s `- 4:0:0:1 sde 8:64 active ready running 1063s + date +UN-plug path 1 %H:%M:%S.%N 1063s UN-plug path 1 12:06:56.495376261 1063s + iscsiadm --mode session -r 1 -u 1063s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1063s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1063s + iscsiadm --mode session 1063s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s + sleep 10s 1063s + date +MP report (expect 3) %H:%M:%S.%N 1063s MP report (expect 3) 12:07:06.599037672 1063s + multipath -ll 1063s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1063s size=100M features='0' hwhandler='0' wp=rw 1063s |-+- policy='service-time 0' prio=1 status=active 1063s | `- 2:0:0:1 sdc 8:32 active ready running 1063s |-+- policy='service-time 0' prio=1 status=enabled 1063s | `- 3:0:0:1 sdd 8:48 active ready running 1063s `-+- policy='service-time 0' prio=1 status=enabled 1063s `- 4:0:0:1 sde 8:64 active ready running 1063s + date +UN-plug path 2 %H:%M:%S.%N 1063s UN-plug path 2 12:07:06.623730820 1063s + iscsiadm --mode session -r 2 -u 1063s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1063s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1063s + iscsiadm --mode session 1063s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s + sleep 10s 1063s + date +MP report (expect 2) %H:%M:%S.%N 1063s MP report (expect 2) 12:07:16.714481605 1063s + multipath -ll 1063s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1063s size=100M features='0' hwhandler='0' wp=rw 1063s |-+- policy='service-time 0' prio=1 status=active 1063s | `- 3:0:0:1 sdd 8:48 active ready running 1063s `-+- policy='service-time 0' prio=1 status=enabled 1063s `- 4:0:0:1 sde 8:64 active ready running 1063s + date +UN-plug path 3 %H:%M:%S.%N 1063s UN-plug path 3 12:07:16.735126787 1063s + iscsiadm --mode session -r 3 -u 1063s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1063s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1063s + iscsiadm --mode session 1063s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s + sleep 10s 1063s + date +MP report (expect 1) %H:%M:%S.%N 1063s MP report (expect 1) 12:07:26.817491168 1063s + multipath -ll 1063s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1063s size=100M features='0' hwhandler='0' wp=rw 1063s `-+- policy='service-time 0' prio=1 status=active 1063s `- 4:0:0:1 sde 8:64 active ready running 1063s + date +Add paths 5/6/7/8 %H:%M:%S.%N 1063s Add paths 5/6/7/8 12:07:26.832555014 1063s + iscsiadm --mode session -r 4 --op new 1063s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1063s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1063s + iscsiadm --mode session -r 4 --op new 1063s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1063s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1063s + iscsiadm --mode session -r 4 --op new 1063s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1063s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1063s + iscsiadm --mode session -r 4 --op new 1063s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1063s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1063s + iscsiadm --mode session 1063s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s + sleep 10s 1063s + date +MP report (expect 5) %H:%M:%S.%N 1063s MP report (expect 5) 12:07:36.952467910 1063s + multipath -ll 1063s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1063s size=100M features='0' hwhandler='0' wp=rw 1063s |-+- policy='service-time 0' prio=1 status=active 1063s | `- 4:0:0:1 sde 8:64 active ready running 1063s |-+- policy='service-time 0' prio=1 status=enabled 1063s | `- 1:0:0:1 sdb 8:16 active ready running 1063s |-+- policy='service-time 0' prio=1 status=enabled 1063s | `- 2:0:0:1 sdc 8:32 active ready running 1063s |-+- policy='service-time 0' prio=1 status=enabled 1063s | `- 3:0:0:1 sdd 8:48 active ready running 1063s `-+- policy='service-time 0' prio=1 status=enabled 1063s `- 5:0:0:1 sdf 8:80 active ready running 1063s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 1063s UN-plug multiple paths 4/7/8 12:07:36.983736711 1063s + iscsiadm --mode session -r 4 -u 1063s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1063s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1063s + iscsiadm --mode session -r 7 -u 1063s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1063s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1063s + iscsiadm --mode session -r 8 -u 1063s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1063s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1063s + iscsiadm --mode session 1063s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1063s + sleep 10s 1063s + date +Restart multipath daemon %H:%M:%S.%N 1063s Restart multipath daemon 12:07:47.302607575 1063s + systemctl restart multipathd 1063s + sleep 10s 1063s + date +Final background report (expect 2) %H:%M:%S.%N 1063s Final background report (expect 2) 12:07:57.383875078 1063s + multipath -ll 1063s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1063s size=100M features='0' hwhandler='0' wp=rw 1063s |-+- policy='service-time 0' prio=1 status=active 1063s | `- 1:0:0:1 sdb 8:16 active ready running 1063s `-+- policy='service-time 0' prio=1 status=enabled 1063s `- 2:0:0:1 sdc 8:32 active ready running 1063s Final stats 1063s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1063s iSCSI SNMP: 1063s txdata_octets: 20379384 1063s rxdata_octets: 27801537380 1063s noptx_pdus: 0 1063s scsicmd_pdus: 424303 1063s tmfcmd_pdus: 0 1063s login_pdus: 0 1063s text_pdus: 0 1063s dataout_pdus: 0 1063s logout_pdus: 0 1063s snack_pdus: 0 1063s noprx_pdus: 0 1063s scsirsp_pdus: 424303 1063s tmfrsp_pdus: 0 1063s textrsp_pdus: 0 1063s datain_pdus: 424270 1063s logoutrsp_pdus: 0 1063s r2t_pdus: 0 1063s async_pdus: 0 1063s rjt_pdus: 0 1063s digest_err: 0 1063s timeout_err: 0 1063s iSCSI Extended: 1063s tx_sendpage_failures: 0 1063s rx_discontiguous_hdr: 0 1063s eh_abort_cnt: 0 1063s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1063s iSCSI SNMP: 1063s txdata_octets: 6504 1063s rxdata_octets: 1514964 1063s noptx_pdus: 0 1063s scsicmd_pdus: 106 1063s tmfcmd_pdus: 0 1063s login_pdus: 0 1063s text_pdus: 0 1063s dataout_pdus: 0 1063s logout_pdus: 0 1063s snack_pdus: 0 1063s noprx_pdus: 0 1063s scsirsp_pdus: 106 1063s tmfrsp_pdus: 0 1063s textrsp_pdus: 0 1063s datain_pdus: 83 1063s logoutrsp_pdus: 0 1063s r2t_pdus: 0 1063s async_pdus: 0 1063s rjt_pdus: 0 1063s digest_err: 0 1063s timeout_err: 0 1063s iSCSI Extended: 1063s tx_sendpage_failures: 0 1063s rx_discontiguous_hdr: 0 1063s eh_abort_cnt: 0 1063s + sync 1063s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1063s + echo Final stats 1063s + iscsiadm --mode session --stats 1063s + journalctl --no-pager -u multipathd 1063s + echo Check final path status 1063s + multipath -ll 1063s + multipath -ll 1063s + grep --count status= 1063s May 24 10:34:23 adtubuntu-oracular-ppc64el-server-20240522 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1063s May 24 10:34:23 adtubuntu-oracular-ppc64el-server-20240522 multipathd[284]: multipathd v0.9.4: start up 1063s May 24 10:34:23 adtubuntu-oracular-ppc64el-server-20240522 multipathd[284]: reconfigure: setting up paths and maps 1063s May 24 10:34:23 adtubuntu-oracular-ppc64el-server-20240522 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1063s May 24 10:35:38 adtubuntu-oracular-ppc64el-server-20240523 multipathd[284]: multipathd: shut down 1063s May 24 10:35:38 adtubuntu-oracular-ppc64el-server-20240523 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1063s May 24 10:35:38 adtubuntu-oracular-ppc64el-server-20240523 systemd[1]: multipathd.service: Deactivated successfully. 1063s May 24 10:35:38 adtubuntu-oracular-ppc64el-server-20240523 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1063s -- Boot 04ec69c8073f4da89852f887445c9d2a -- 1063s May 24 10:36:01 adtubuntu-oracular-ppc64el-server-20240523 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1063s May 24 10:36:01 adtubuntu-oracular-ppc64el-server-20240523 multipathd[277]: multipathd v0.9.4: start up 1063s May 24 10:36:01 adtubuntu-oracular-ppc64el-server-20240523 multipathd[277]: reconfigure: setting up paths and maps 1063s May 24 10:36:01 adtubuntu-oracular-ppc64el-server-20240523 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1063s May 24 10:36:30 adtubuntu-oracular-ppc64el-server-20240523 multipathd[277]: multipathd: shut down 1063s May 24 10:36:30 adtubuntu-oracular-ppc64el-server-20240523 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1063s May 24 10:36:30 adtubuntu-oracular-ppc64el-server-20240523 systemd[1]: multipathd.service: Deactivated successfully. 1063s May 24 10:36:30 adtubuntu-oracular-ppc64el-server-20240523 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1063s -- Boot c7eca4aca95c4ec4bb644f6515ba64af -- 1063s May 24 12:04:26 adtubuntu-oracular-ppc64el-server-20240523 multipathd[313]: multipathd v0.9.4: start up 1063s May 24 12:04:26 adtubuntu-oracular-ppc64el-server-20240523 multipathd[313]: reconfigure: setting up paths and maps 1063s May 24 12:04:26 adtubuntu-oracular-ppc64el-server-20240523 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1063s May 24 12:05:26 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1063s May 24 12:05:26 autopkgtest multipathd[313]: multipathd: shut down 1063s May 24 12:05:26 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 1063s May 24 12:05:26 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1063s -- Boot 1efcab871f434ac090030ea019aa62af -- 1063s May 24 12:05:49 autopkgtest multipathd[311]: multipathd v0.9.4: start up 1063s May 24 12:05:49 autopkgtest multipathd[311]: reconfigure: setting up paths and maps 1063s May 24 12:05:49 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1063s May 24 12:06:37 autopkgtest multipathd[311]: 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] 1063s May 24 12:06:37 autopkgtest multipathd[311]: sdc [8:32]: path added to devmap mpatha 1063s May 24 12:06:37 autopkgtest multipathd[311]: mpatha: performing delayed actions 1063s May 24 12:06:37 autopkgtest multipathd[311]: 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] 1063s May 24 12:06:56 autopkgtest multipathd[311]: 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] 1063s May 24 12:06:56 autopkgtest multipathd[311]: check_removed_paths: sdb: freeing path in removed state 1063s May 24 12:06:56 autopkgtest multipathd[311]: 8:16: path removed from map mpatha 1063s May 24 12:07:06 autopkgtest multipathd[311]: 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] 1063s May 24 12:07:06 autopkgtest multipathd[311]: check_removed_paths: sdc: freeing path in removed state 1063s May 24 12:07:06 autopkgtest multipathd[311]: 8:32: path removed from map mpatha 1063s May 24 12:07:16 autopkgtest multipathd[311]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 1063s May 24 12:07:16 autopkgtest multipathd[311]: check_removed_paths: sdd: freeing path in removed state 1063s May 24 12:07:16 autopkgtest multipathd[311]: 8:48: path removed from map mpatha 1063s May 24 12:07:26 autopkgtest multipathd[311]: 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] 1063s May 24 12:07:26 autopkgtest multipathd[311]: sdb [8:16]: path added to devmap mpatha 1063s May 24 12:07:26 autopkgtest multipathd[311]: 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] 1063s May 24 12:07:26 autopkgtest multipathd[311]: sdc [8:32]: path added to devmap mpatha 1063s May 24 12:07:26 autopkgtest multipathd[311]: 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] 1063s May 24 12:07:26 autopkgtest multipathd[311]: sdd [8:48]: path added to devmap mpatha 1063s May 24 12:07:27 autopkgtest multipathd[311]: 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] 1063s May 24 12:07:27 autopkgtest multipathd[311]: sdf [8:80]: path added to devmap mpatha 1063s May 24 12:07:37 autopkgtest multipathd[311]: sde: mark as failed 1063s May 24 12:07:37 autopkgtest multipathd[311]: mpatha: remaining active paths: 4 1063s May 24 12:07:37 autopkgtest multipathd[311]: 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] 1063s May 24 12:07:37 autopkgtest multipathd[311]: check_removed_paths: sde: freeing path in removed state 1063s May 24 12:07:37 autopkgtest multipathd[311]: 8:64: path removed from map mpatha 1063s May 24 12:07:37 autopkgtest multipathd[311]: 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] 1063s May 24 12:07:37 autopkgtest multipathd[311]: check_removed_paths: sdd: freeing path in removed state 1063s May 24 12:07:37 autopkgtest multipathd[311]: 8:48: path removed from map mpatha 1063s May 24 12:07:37 autopkgtest multipathd[311]: 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] 1063s May 24 12:07:37 autopkgtest multipathd[311]: check_removed_paths: sdf: freeing path in removed state 1063s May 24 12:07:37 autopkgtest multipathd[311]: 8:80: path removed from map mpatha 1063s May 24 12:07:47 autopkgtest multipathd[311]: multipathd: shut down 1063s May 24 12:07:47 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1063s May 24 12:07:47 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 1063s May 24 12:07:47 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1063s May 24 12:07:47 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1063s May 24 12:07:47 autopkgtest multipathd[6031]: multipathd v0.9.4: start up 1063s May 24 12:07:47 autopkgtest multipathd[6031]: reconfigure: setting up paths and maps 1063s May 24 12:07:47 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1063s Check final path status 1063s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1063s size=100M features='0' hwhandler='0' wp=rw 1063s |-+- policy='service-time 0' prio=1 status=active 1063s | `- 1:0:0:1 sdb 8:16 active ready running 1063s `-+- policy='service-time 0' prio=1 status=enabled 1063s `- 2:0:0:1 sdc 8:32 active ready running 1063s + diskc=2 1063s + multipath -ll 1063s + grep --count status=active 1063s + diska=1 1063s + multipath -ll 1063s + grep --count status=enabled 1063s OK 1063s + diske=1 1063s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 1063s + echo OK 1063s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 1064s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1064s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1064s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1064s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1064s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 1064s autopkgtest [12:09:47]: test tgtbasedmpaths: -----------------------] 1064s autopkgtest [12:09:47]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 1064s tgtbasedmpaths PASS 1065s autopkgtest [12:09:48]: @@@@@@@@@@@@@@@@@@@@ summary 1065s kpartx-file-loopback PASS 1065s tgtbasedmpaths PASS 1087s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240524-115203-juju-7f2275-prod-proposed-migration-environment-3-c187b20a-cbaa-40a2-a96b-fdce677718b4 from image adt/ubuntu-oracular-ppc64el-server-20240524.img (UUID 775cef78-42a8-4f2f-816d-9e23babb10a6)... 1087s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240524-115203-juju-7f2275-prod-proposed-migration-environment-3-c187b20a-cbaa-40a2-a96b-fdce677718b4 from image adt/ubuntu-oracular-ppc64el-server-20240524.img (UUID 775cef78-42a8-4f2f-816d-9e23babb10a6)...