0s autopkgtest [19:43:51]: starting date and time: 2024-06-12 19:43:51+0000 0s autopkgtest [19:43:51]: git checkout: 433ed4cb Merge branch 'skia/nova_flock' into 'ubuntu/5.34+prod' 0s autopkgtest [19:43:51]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.n2v2o_bh/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:dracut --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=dracut/102-3ubuntu1 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos01-ppc64el-5.secgroup --name adt-oracular-ppc64el-multipath-tools-20240612-194349-juju-7f2275-prod-proposed-migration-environment-2-88802bd5-fb20-4feb-955b-fc1fa0ecd287 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --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/ 94s autopkgtest [19:45:25]: testbed dpkg architecture: ppc64el 94s autopkgtest [19:45:25]: testbed apt version: 2.9.3 94s autopkgtest [19:45:25]: @@@@@@@@@@@@@@@@@@@@ test bed setup 95s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 95s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7052 B] 95s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [356 kB] 95s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3780 B] 95s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [39.7 kB] 95s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [56.8 kB] 95s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1860 B] 95s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [307 kB] 95s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [2104 B] 96s Fetched 884 kB in 1s (1166 kB/s) 96s Reading package lists... 98s Reading package lists... 98s Building dependency tree... 98s Reading state information... 98s Calculating upgrade... 98s The following packages will be upgraded: 98s cryptsetup-bin dracut-install libaudit-common libaudit1 libcryptsetup12 98s 5 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 98s Need to get 696 kB of archives. 98s After this operation, 0 B of additional disk space will be used. 98s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el libaudit-common all 1:3.1.2-4 [5780 B] 98s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libaudit1 ppc64el 1:3.1.2-4 [52.3 kB] 99s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libcryptsetup12 ppc64el 2:2.7.0-1ubuntu6 [375 kB] 99s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el cryptsetup-bin ppc64el 2:2.7.0-1ubuntu6 [227 kB] 99s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dracut-install ppc64el 102-3ubuntu1 [35.7 kB] 99s Fetched 696 kB in 1s (1255 kB/s) 99s (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 ... 72675 files and directories currently installed.) 99s Preparing to unpack .../libaudit-common_1%3a3.1.2-4_all.deb ... 99s Unpacking libaudit-common (1:3.1.2-4) over (1:3.1.2-2.1build1) ... 99s Setting up libaudit-common (1:3.1.2-4) ... 99s (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 ... 72675 files and directories currently installed.) 99s Preparing to unpack .../libaudit1_1%3a3.1.2-4_ppc64el.deb ... 99s Unpacking libaudit1:ppc64el (1:3.1.2-4) over (1:3.1.2-2.1build1) ... 99s Setting up libaudit1:ppc64el (1:3.1.2-4) ... 99s (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 ... 72675 files and directories currently installed.) 99s Preparing to unpack .../libcryptsetup12_2%3a2.7.0-1ubuntu6_ppc64el.deb ... 99s Unpacking libcryptsetup12:ppc64el (2:2.7.0-1ubuntu6) over (2:2.7.0-1ubuntu5) ... 99s Preparing to unpack .../cryptsetup-bin_2%3a2.7.0-1ubuntu6_ppc64el.deb ... 99s Unpacking cryptsetup-bin (2:2.7.0-1ubuntu6) over (2:2.7.0-1ubuntu5) ... 99s Preparing to unpack .../dracut-install_102-3ubuntu1_ppc64el.deb ... 99s Unpacking dracut-install (102-3ubuntu1) over (060+5-8ubuntu2) ... 99s Setting up dracut-install (102-3ubuntu1) ... 99s Setting up libcryptsetup12:ppc64el (2:2.7.0-1ubuntu6) ... 99s Setting up cryptsetup-bin (2:2.7.0-1ubuntu6) ... 99s Processing triggers for man-db (2.12.1-2) ... 100s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 100s Reading package lists... 100s Building dependency tree... 100s Reading state information... 100s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 101s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 101s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 101s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 101s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 102s Reading package lists... 102s Reading package lists... 102s Building dependency tree... 102s Reading state information... 102s Calculating upgrade... 102s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 102s Reading package lists... 102s Building dependency tree... 102s Reading state information... 103s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 105s autopkgtest [19:45:36]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 105s autopkgtest [19:45:36]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 108s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 108s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 108s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 109s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 109s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 109s gpgv: issuer "steve.langasek@ubuntu.com" 109s gpgv: Can't check signature: No public key 109s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 109s autopkgtest [19:45:40]: testing package multipath-tools version 0.9.4-5ubuntu8 109s autopkgtest [19:45:40]: build not needed 110s autopkgtest [19:45:41]: test kpartx-file-loopback: preparing testbed 111s Reading package lists... 111s Building dependency tree... 111s Reading state information... 111s Starting pkgProblemResolver with broken count: 0 111s Starting 2 pkgProblemResolver with broken count: 0 111s Done 111s The following additional packages will be installed: 111s liburing2 qemu-utils 111s Recommended packages: 111s qemu-block-extra 111s The following NEW packages will be installed: 111s autopkgtest-satdep liburing2 qemu-utils 111s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 111s Need to get 2330 kB/2331 kB of archives. 111s After this operation, 15.4 MB of additional disk space will be used. 111s Get:1 /tmp/autopkgtest.WBeCvG/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 112s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 112s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 112s Fetched 2330 kB in 1s (3261 kB/s) 112s Selecting previously unselected package liburing2:ppc64el. 112s (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 ... 72675 files and directories currently installed.) 112s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 112s Unpacking liburing2:ppc64el (2.6-1) ... 112s Selecting previously unselected package qemu-utils. 112s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 112s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 113s Selecting previously unselected package autopkgtest-satdep. 113s Preparing to unpack .../1-autopkgtest-satdep.deb ... 113s Unpacking autopkgtest-satdep (0) ... 113s Setting up liburing2:ppc64el (2.6-1) ... 113s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 113s Setting up autopkgtest-satdep (0) ... 113s Processing triggers for man-db (2.12.1-2) ... 114s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 115s (Reading database ... 72695 files and directories currently installed.) 115s Removing autopkgtest-satdep (0) ... 117s autopkgtest [19:45:48]: test kpartx-file-loopback: [----------------------- 117s Formatting 'foo.img', fmt=raw size=20971520 118s Creating new GPT entries in memory. 118s Warning: The kernel is still using the old partition table. 118s The new table will be used at the next reboot or after you 118s run partprobe(8) or kpartx(8) 118s The operation has completed successfully. 118s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 118s standard_filename: OK 118s del devmap : loop0p1 118s No devices found 118s standard_filename_cleanup: OK 118s Formatting 'fou du FaFa.img', fmt=raw size=20971520 119s Creating new GPT entries in memory. 119s Warning: The kernel is still using the old partition table. 119s The new table will be used at the next reboot or after you 119s run partprobe(8) or kpartx(8) 119s The operation has completed successfully. 119s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 119s filename_with_spaces: OK 119s del devmap : loop0p1 119s No devices found 119s filename_with_spaces_cleanup: OK 120s autopkgtest [19:45:51]: test kpartx-file-loopback: -----------------------] 120s autopkgtest [19:45:51]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 120s kpartx-file-loopback PASS 121s autopkgtest [19:45:52]: test tgtbasedmpaths: preparing testbed 225s autopkgtest [19:47:36]: testbed dpkg architecture: ppc64el 225s autopkgtest [19:47:36]: testbed apt version: 2.9.3 225s autopkgtest [19:47:36]: @@@@@@@@@@@@@@@@@@@@ test bed setup 226s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 227s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3780 B] 227s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [39.7 kB] 227s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7052 B] 227s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [356 kB] 227s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [56.8 kB] 227s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1860 B] 227s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [307 kB] 227s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [2104 B] 227s Fetched 884 kB in 1s (1056 kB/s) 227s Reading package lists... 229s Reading package lists... 229s Building dependency tree... 229s Reading state information... 229s Calculating upgrade... 229s The following packages will be upgraded: 229s cryptsetup-bin dracut-install libaudit-common libaudit1 libcryptsetup12 230s 5 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 230s Need to get 696 kB of archives. 230s After this operation, 0 B of additional disk space will be used. 230s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el libaudit-common all 1:3.1.2-4 [5780 B] 230s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libaudit1 ppc64el 1:3.1.2-4 [52.3 kB] 230s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libcryptsetup12 ppc64el 2:2.7.0-1ubuntu6 [375 kB] 230s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el cryptsetup-bin ppc64el 2:2.7.0-1ubuntu6 [227 kB] 230s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dracut-install ppc64el 102-3ubuntu1 [35.7 kB] 230s Fetched 696 kB in 1s (1113 kB/s) 231s (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 ... 72675 files and directories currently installed.) 231s Preparing to unpack .../libaudit-common_1%3a3.1.2-4_all.deb ... 231s Unpacking libaudit-common (1:3.1.2-4) over (1:3.1.2-2.1build1) ... 231s Setting up libaudit-common (1:3.1.2-4) ... 231s (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 ... 72675 files and directories currently installed.) 231s Preparing to unpack .../libaudit1_1%3a3.1.2-4_ppc64el.deb ... 231s Unpacking libaudit1:ppc64el (1:3.1.2-4) over (1:3.1.2-2.1build1) ... 231s Setting up libaudit1:ppc64el (1:3.1.2-4) ... 231s (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 ... 72675 files and directories currently installed.) 231s Preparing to unpack .../libcryptsetup12_2%3a2.7.0-1ubuntu6_ppc64el.deb ... 231s Unpacking libcryptsetup12:ppc64el (2:2.7.0-1ubuntu6) over (2:2.7.0-1ubuntu5) ... 231s Preparing to unpack .../cryptsetup-bin_2%3a2.7.0-1ubuntu6_ppc64el.deb ... 231s Unpacking cryptsetup-bin (2:2.7.0-1ubuntu6) over (2:2.7.0-1ubuntu5) ... 231s Preparing to unpack .../dracut-install_102-3ubuntu1_ppc64el.deb ... 231s Unpacking dracut-install (102-3ubuntu1) over (060+5-8ubuntu2) ... 231s Setting up dracut-install (102-3ubuntu1) ... 231s Setting up libcryptsetup12:ppc64el (2:2.7.0-1ubuntu6) ... 231s Setting up cryptsetup-bin (2:2.7.0-1ubuntu6) ... 231s Processing triggers for man-db (2.12.1-2) ... 232s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 232s Reading package lists... 232s Building dependency tree... 232s Reading state information... 232s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 232s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 233s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 233s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 233s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 234s Reading package lists... 234s Reading package lists... 234s Building dependency tree... 234s Reading state information... 234s Calculating upgrade... 234s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 234s Reading package lists... 234s Building dependency tree... 234s Reading state information... 234s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 238s Reading package lists... 238s Building dependency tree... 238s Reading state information... 238s Starting pkgProblemResolver with broken count: 0 238s Starting 2 pkgProblemResolver with broken count: 0 238s Done 239s The following additional packages will be installed: 239s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 239s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 239s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 239s librdmacm1t64 lsscsi open-iscsi tgt 239s Suggested packages: 239s fio-examples gnuplot tgt-glusterfs tgt-rbd 239s Recommended packages: 239s finalrd 239s The following NEW packages will be installed: 239s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 239s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 239s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 239s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 239s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 239s Need to get 10.7 MB/10.7 MB of archives. 239s After this operation, 49.1 MB of additional disk space will be used. 239s Get:1 /tmp/autopkgtest.WBeCvG/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 239s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu4 [54.4 kB] 239s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 239s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu4 [389 kB] 239s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 239s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 239s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu6 [256 kB] 239s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4build3 [21.5 kB] 239s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4build3 [311 kB] 239s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4build3 [47.0 kB] 239s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4build3 [100 kB] 239s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.1-1 [97.4 kB] 239s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 239s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 239s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 239s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 239s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 239s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 240s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 240s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 240s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 240s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 240s Preconfiguring packages ... 240s Fetched 10.7 MB in 1s (10.9 MB/s) 240s Selecting previously unselected package libopeniscsiusr. 240s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72675 files and directories currently installed.) 240s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu4_ppc64el.deb ... 240s Unpacking libopeniscsiusr (2.1.9-3ubuntu4) ... 240s Selecting previously unselected package libisns0t64:ppc64el. 240s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 240s Unpacking libisns0t64:ppc64el (0.101-1) ... 240s Selecting previously unselected package open-iscsi. 240s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu4_ppc64el.deb ... 240s Unpacking open-iscsi (2.1.9-3ubuntu4) ... 240s Selecting previously unselected package librdmacm1t64:ppc64el. 240s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 240s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 240s Selecting previously unselected package libconfig-general-perl. 240s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 240s Unpacking libconfig-general-perl (2.65-2) ... 240s Selecting previously unselected package tgt. 240s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu6_ppc64el.deb ... 240s Unpacking tgt (1:1.0.85-1.1ubuntu6) ... 240s Selecting previously unselected package libgfxdr0:ppc64el. 240s Preparing to unpack .../06-libgfxdr0_11.1-4build3_ppc64el.deb ... 240s Unpacking libgfxdr0:ppc64el (11.1-4build3) ... 240s Selecting previously unselected package libglusterfs0:ppc64el. 240s Preparing to unpack .../07-libglusterfs0_11.1-4build3_ppc64el.deb ... 240s Unpacking libglusterfs0:ppc64el (11.1-4build3) ... 240s Selecting previously unselected package libgfrpc0:ppc64el. 240s Preparing to unpack .../08-libgfrpc0_11.1-4build3_ppc64el.deb ... 240s Unpacking libgfrpc0:ppc64el (11.1-4build3) ... 240s Selecting previously unselected package libgfapi0:ppc64el. 240s Preparing to unpack .../09-libgfapi0_11.1-4build3_ppc64el.deb ... 240s Unpacking libgfapi0:ppc64el (11.1-4build3) ... 240s Selecting previously unselected package libnbd0. 240s Preparing to unpack .../10-libnbd0_1.20.1-1_ppc64el.deb ... 240s Unpacking libnbd0 (1.20.1-1) ... 240s Selecting previously unselected package libdaxctl1:ppc64el. 240s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 240s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 240s Selecting previously unselected package libndctl6:ppc64el. 240s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 240s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 240s Selecting previously unselected package libpmem1:ppc64el. 240s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 240s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 240s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 240s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 240s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 240s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 240s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 240s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 240s Selecting previously unselected package librados2. 240s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 240s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 241s Selecting previously unselected package libpmemobj1:ppc64el. 241s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 241s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 241s Selecting previously unselected package librbd1. 241s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 241s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 241s Selecting previously unselected package fio. 241s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 241s Unpacking fio (3.37-1) ... 241s Selecting previously unselected package lsscsi. 241s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 241s Unpacking lsscsi (0.32-1build1) ... 241s Selecting previously unselected package autopkgtest-satdep. 241s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 241s Unpacking autopkgtest-satdep (0) ... 241s Setting up libconfig-general-perl (2.65-2) ... 241s Setting up libisns0t64:ppc64el (0.101-1) ... 241s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 241s Setting up libnbd0 (1.20.1-1) ... 241s Setting up libopeniscsiusr (2.1.9-3ubuntu4) ... 241s Setting up libglusterfs0:ppc64el (11.1-4build3) ... 241s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 241s Setting up lsscsi (0.32-1build1) ... 241s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 241s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 241s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 241s Setting up tgt (1:1.0.85-1.1ubuntu6) ... 241s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 242s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 242s Setting up libgfxdr0:ppc64el (11.1-4build3) ... 242s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 242s Setting up open-iscsi (2.1.9-3ubuntu4) ... 242s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 243s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 243s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 243s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 243s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 243s Setting up libgfrpc0:ppc64el (11.1-4build3) ... 243s Setting up libgfapi0:ppc64el (11.1-4build3) ... 243s Setting up fio (3.37-1) ... 244s Setting up autopkgtest-satdep (0) ... 244s Processing triggers for man-db (2.12.1-2) ... 244s Processing triggers for initramfs-tools (0.142ubuntu28) ... 244s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 244s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 251s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 254s (Reading database ... 72916 files and directories currently installed.) 254s Removing autopkgtest-satdep (0) ... 255s autopkgtest [19:48:06]: test tgtbasedmpaths: [----------------------- 256s + targetname=iqn.2016-11.foo.com:target.iscsi 256s + pwd 256s + cwd=/tmp/autopkgtest.WBeCvG/build.5Ls/src 256s + testdir=/mnt/tgtmpathtest 256s + localhost=127.0.0.1 256s + portal=127.0.0.1:3260 256s + maxpaths=4 256s + backfn=backingfile 256s + expectwwid=60000000000000000e00000000010001 256s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 256s + bglog=/tmp/autopkgtest.WBeCvG/tgtbasedmpaths-artifacts/test-background.log 256s + fioprep=/tmp/autopkgtest.WBeCvG/tgtbasedmpaths-artifacts/path-change-prep.fio 256s + fiovrfy=/tmp/autopkgtest.WBeCvG/tgtbasedmpaths-artifacts/path-change-check.fio 256s + service tgt restart 256s + truncate --size 100M backingfile 256s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 256s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 256s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.WBeCvG/build.5Ls/src/backingfile 256s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 256s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 256s login #1 256s + echo login #1 256s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 256s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 256s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 256s + seq 2 4 256s extra login #2 256s + echo extra login #2 256s + iscsiadm --mode session -r 1 --op new 256s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 256s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 256s extra login #3 256s + echo extra login #3 256s + iscsiadm --mode session -r 1 --op new 256s + echo extra login #4 256s + iscsiadm --mode session -r 1 --op new 256s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 256s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 256s extra login #4 256s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 256s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 256s + udevadm settle 256s + sleep 5 261s + echo Status after initial setup 261s + tgtadm --lld iscsi --mode target --op show 261s Status after initial setup 261s + tgtadm --lld iscsi --op show --mode conn --tid 1 261s Target 1: iqn.2016-11.foo.com:target.iscsi 261s System information: 261s Driver: iscsi 261s State: ready 261s I_T nexus information: 261s I_T nexus: 1 261s Initiator: iqn.2004-10.com.ubuntu:01:34fe715cbbef alias: autopkgtest 261s Connection: 0 261s IP Address: 127.0.0.1 261s I_T nexus: 2 261s Initiator: iqn.2004-10.com.ubuntu:01:34fe715cbbef alias: autopkgtest 261s Connection: 0 261s IP Address: 127.0.0.1 261s I_T nexus: 3 261s Initiator: iqn.2004-10.com.ubuntu:01:34fe715cbbef alias: autopkgtest 261s Connection: 0 261s IP Address: 127.0.0.1 261s I_T nexus: 4 261s Initiator: iqn.2004-10.com.ubuntu:01:34fe715cbbef alias: autopkgtest 261s Connection: 0 261s IP Address: 127.0.0.1 261s LUN information: 261s LUN: 0 261s Type: controller 261s SCSI ID: IET 00010000 261s SCSI SN: beaf10 261s Size: 0 MB, Block size: 1 261s Online: Yes 261s Removable media: No 261s Prevent removal: No 261s Readonly: No 261s SWP: No 261s Thin-provisioning: No 261s Backing store type: null 261s Backing store path: None 261s Backing store flags: 261s LUN: 1 261s Type: disk 261s SCSI ID: IET 00010001 261s SCSI SN: beaf11 261s Size: 105 MB, Block size: 512 261s Online: Yes 261s Removable media: No 261s Prevent removal: No 261s Readonly: No 261s SWP: No 261s Thin-provisioning: No 261s Backing store type: rdwr 261s Backing store path: /tmp/autopkgtest.WBeCvG/build.5Ls/src/backingfile 261s Backing store flags: 261s Account information: 261s ACL information: 261s ALL 261s Session: 4 261s Connection: 0 261s Initiator: iqn.2004-10.com.ubuntu:01:34fe715cbbef 261s IP Address: 127.0.0.1 261s Session: 3 261s Connection: 0 261s Initiator: iqn.2004-10.com.ubuntu:01:34fe715cbbef 261s IP Address: 127.0.0.1 261s Session: 2 261s Connection: 0 261s Initiator: iqn.2004-10.com.ubuntu:01:34fe715cbbef 261s IP Address: 127.0.0.1 261s Session: 1 261s Connection: 0 261s Initiator: iqn.2004-10.com.ubuntu:01:34fe715cbbef 261s IP Address: 127.0.0.1 261s + iscsiadm --mode session -P 1 261s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 261s Current Portal: 127.0.0.1:3260,1 261s Persistent Portal: 127.0.0.1:3260,1 261s ********** 261s Interface: 261s ********** 261s Iface Name: default 261s Iface Transport: tcp 261s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:34fe715cbbef 261s Iface IPaddress: 127.0.0.1 261s Iface HWaddress: default 261s Iface Netdev: default 261s SID: 1 261s iSCSI Connection State: LOGGED IN 261s iSCSI Session State: LOGGED_IN 261s Internal iscsid Session State: NO CHANGE 261s 261s ********** 261s Interface: 261s ********** 261s Iface Name: default 261s Iface Transport: tcp 261s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:34fe715cbbef 261s Iface IPaddress: 127.0.0.1 261s Iface HWaddress: default 261s Iface Netdev: default 261s SID: 2 261s iSCSI Connection State: LOGGED IN 261s iSCSI Session State: LOGGED_IN 261s Internal iscsid Session State: NO CHANGE 261s 261s ********** 261s Interface: 261s ********** 261s Iface Name: default 261s Iface Transport: tcp 261s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:34fe715cbbef 261s Iface IPaddress: 127.0.0.1 261s Iface HWaddress: default 261s Iface Netdev: default 261s SID: 3 261s iSCSI Connection State: LOGGED IN 261s iSCSI Session State: LOGGED_IN 261s Internal iscsid Session State: NO CHANGE 261s 261s ********** 261s Interface: 261s ********** 261s Iface Name: default 261s Iface Transport: tcp 261s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:34fe715cbbef 261s Iface IPaddress: 127.0.0.1 261s Iface HWaddress: default 261s Iface Netdev: default 261s SID: 4 261s iSCSI Connection State: LOGGED IN 261s iSCSI Session State: LOGGED_IN 261s Internal iscsid Session State: NO CHANGE 261s + lsscsi -liv 261s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 261s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 261s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 261s 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] 261s [1:0:0:0] storage IET Controller 0001 - - 261s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 261s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 261s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 261s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 261s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 261s [2:0:0:0] storage IET Controller 0001 - - 261s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 261s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 261s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 261s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 261s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 261s [3:0:0:0] storage IET Controller 0001 - - 261s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 261s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 261s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 261s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 261s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 261s [4:0:0:0] storage IET Controller 0001 - - 261s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 261s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 261s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 261s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 261s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 261s NVMe module may not be loaded 261s + multipath -v3 -ll 261s 69.438757 | set open fds limit to 1048576/1048576 261s 69.438871 | loading /lib/multipath/libchecktur.so checker 261s 69.438974 | checker tur: message table size = 3 261s 69.439009 | loading /lib/multipath/libprioconst.so prioritizer 261s 69.439134 | _init_foreign: foreign library "nvme" is not enabled 261s 69.445624 | sda: size = 167772160 261s 69.445813 | sda: vendor = QEMU 261s 69.445860 | sda: product = QEMU HARDDISK 261s 69.445884 | sda: rev = 2.5+ 261s 69.446524 | sda: h:b:t:l = 0:0:0:0 261s 69.446885 | sda: tgt_node_name = 261s 69.446910 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 261s 69.446912 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 261s 69.447084 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 261s 69.447108 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 261s 69.447123 | __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 261s 69.447128 | failed to read sysfs vpd pg80: No such file or directory 261s 69.447434 | sda: fail to get serial 261s 69.447459 | sda: detect_checker = yes (setting: multipath internal) 261s 69.447730 | sda: path_checker = tur (setting: multipath internal) 261s 69.447755 | sda: checker timeout = 30 s (setting: kernel sysfs) 261s 69.447875 | sda: tur state = up 261s 69.448215 | sdb: size = 204800 261s 69.448373 | sdb: vendor = IET 261s 69.448419 | sdb: product = VIRTUAL-DISK 261s 69.448441 | sdb: rev = 0001 261s 69.449065 | sdb: h:b:t:l = 1:0:0:1 261s 69.449434 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 261s 69.449457 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 261s 69.449459 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 261s 69.449619 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 261s 69.449641 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 261s 69.449659 | sdb: serial = beaf11 261s 69.449661 | sdb: detect_checker = yes (setting: multipath internal) 261s 69.450981 | sdb: path_checker = tur (setting: multipath internal) 261s 69.451004 | sdb: checker timeout = 30 s (setting: kernel sysfs) 261s 69.451311 | sdb: tur state = up 261s 69.451466 | sdc: size = 204800 261s 69.451655 | sdc: vendor = IET 261s 69.451699 | sdc: product = VIRTUAL-DISK 261s 69.451720 | sdc: rev = 0001 261s 69.452477 | sdc: h:b:t:l = 2:0:0:1 261s 69.452934 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 261s 69.452961 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 261s 69.452963 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 261s 69.453149 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 261s 69.453175 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 261s 69.453199 | sdc: serial = beaf11 261s 69.453202 | sdc: detect_checker = yes (setting: multipath internal) 261s 69.453564 | sdc: path_checker = tur (setting: multipath internal) 261s 69.453588 | sdc: checker timeout = 30 s (setting: kernel sysfs) 261s 69.453859 | sdc: tur state = up 261s 69.454029 | sdd: size = 204800 261s 69.454191 | sdd: vendor = IET 261s 69.454237 | sdd: product = VIRTUAL-DISK 261s 69.454264 | sdd: rev = 0001 261s 69.455000 | sdd: h:b:t:l = 3:0:0:1 261s 69.455367 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 261s 69.455370 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 261s 69.455373 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 261s 69.455519 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 261s 69.455522 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 261s 69.455536 | sdd: serial = beaf11 261s 69.455538 | sdd: detect_checker = yes (setting: multipath internal) 261s 69.456316 | sdd: path_checker = tur (setting: multipath internal) 261s 69.456332 | sdd: checker timeout = 30 s (setting: kernel sysfs) 261s 69.457565 | sdd: tur state = up 261s 69.457792 | sde: size = 204800 261s 69.457965 | sde: vendor = IET 261s 69.457994 | sde: product = VIRTUAL-DISK 261s 69.458021 | sde: rev = 0001 261s 69.458982 | sde: h:b:t:l = 4:0:0:1 261s 69.459427 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 261s 69.459431 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 261s 69.459434 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 261s 69.459666 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 261s 69.459671 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 261s 69.459688 | sde: serial = beaf11 261s 69.459692 | sde: detect_checker = yes (setting: multipath internal) 261s 69.460075 | sde: path_checker = tur (setting: multipath internal) 261s 69.460089 | sde: checker timeout = 30 s (setting: kernel sysfs) 261s 69.460349 | sde: tur state = up 261s 69.460477 | loop0: device node name blacklisted 261s 69.460585 | loop1: device node name blacklisted 261s 69.460690 | loop2: device node name blacklisted 261s 69.460793 | loop3: device node name blacklisted 261s 69.460897 | loop4: device node name blacklisted 261s 69.460998 | loop5: device node name blacklisted 261s 69.461101 | loop6: device node name blacklisted 261s 69.461205 | loop7: device node name blacklisted 261s 69.461317 | dm-0: device node name blacklisted 261s 69.462601 | multipath-tools v0.9.4 (12/19, 2022) 261s 69.462618 | libdevmapper version 1.02.185 261s 69.462827 | kernel device mapper v4.48.0 261s 69.462842 | DM multipath kernel driver v1.14.0 261s 69.462975 | sdb: size = 204800 261s 69.462981 | sdb: vendor = IET 261s 69.462984 | sdb: product = VIRTUAL-DISK 261s 69.462987 | sdb: rev = 0001 261s 69.463712 | sdb: h:b:t:l = 1:0:0:1 261s 69.463844 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 261s 69.463867 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 261s 69.463870 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 261s 69.463885 | sdb: serial = beaf11 261s 69.464148 | sdb: tur state = up 261s 69.464161 | sdb: uid = 360000000000000000e00000000010001 (udev) 261s 69.464165 | sdb: detect_prio = yes (setting: multipath internal) 261s 69.464168 | sdb: prio = const (setting: multipath internal) 261s 69.464171 | sdb: prio args = "" (setting: multipath internal) 261s 69.464174 | sdb: const prio = 1 261s 69.464205 | sdc: size = 204800 261s 69.464211 | sdc: vendor = IET 261s 69.464214 | sdc: product = VIRTUAL-DISK 261s 69.464217 | sdc: rev = 0001 261s 69.464936 | sdc: h:b:t:l = 2:0:0:1 261s 69.465070 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 261s 69.465093 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 261s 69.465097 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 261s 69.465111 | sdc: serial = beaf11 261s ===== paths list ===== 261s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 261s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 261s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 261s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 261s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 261s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 261s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 261s size=100M features='0' hwhandler='0' wp=rw 261s |-+- policy='service-time 0' prio=1 status=active 261s | `- 1:0:0:1 sdb 8:16 active ready running 261s |-+- policy='service-time 0' prio=1 status=enabled 261s | `- 2:0:0:1 sdc 8:32 active ready running 261s |-+- policy='service-time 0' prio=1 status=enabled 261s | `- 3:0:0:1 sdd 8:48 active ready running 261s `-+- policy='service-time 0' prio=1 status=enabled 261s `- 4:0:0:1 sde 8:64 active ready running 261s 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 261s Test WWN should now point to DM 261s ../../dm-0 261s Creating filesystem with 25600 4k blocks and 25600 inodes 261s 261s Allocating group tables: 0/1 done 261s Writing inode tables: 0/1 done 261s Creating journal (1024 blocks): 69.465358 | sdc: tur state = up 261s 69.465367 | sdc: uid = 360000000000000000e00000000010001 (udev) 261s 69.465370 | sdc: detect_prio = yes (setting: multipath internal) 261s 69.465373 | sdc: prio = const (setting: multipath internal) 261s 69.465375 | sdc: prio args = "" (setting: multipath internal) 261s 69.465378 | sdc: const prio = 1 261s 69.465406 | sdd: size = 204800 261s 69.465411 | sdd: vendor = IET 261s 69.465414 | sdd: product = VIRTUAL-DISK 261s 69.465417 | sdd: rev = 0001 261s 69.466124 | sdd: h:b:t:l = 3:0:0:1 261s 69.466254 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 261s 69.466276 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 261s 69.466279 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 261s 69.466293 | sdd: serial = beaf11 261s 69.466531 | sdd: tur state = up 261s 69.466540 | sdd: uid = 360000000000000000e00000000010001 (udev) 261s 69.466543 | sdd: detect_prio = yes (setting: multipath internal) 261s 69.466546 | sdd: prio = const (setting: multipath internal) 261s 69.466548 | sdd: prio args = "" (setting: multipath internal) 261s 69.466551 | sdd: const prio = 1 261s 69.466577 | sde: size = 204800 261s 69.466582 | sde: vendor = IET 261s 69.466585 | sde: product = VIRTUAL-DISK 261s 69.466588 | sde: rev = 0001 261s 69.467305 | sde: h:b:t:l = 4:0:0:1 261s 69.467432 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 261s 69.467453 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 261s 69.467456 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 261s 69.467469 | sde: serial = beaf11 261s 69.467743 | sde: tur state = up 261s 69.467751 | sde: uid = 360000000000000000e00000000010001 (udev) 261s 69.467754 | sde: detect_prio = yes (setting: multipath internal) 261s 69.467757 | sde: prio = const (setting: multipath internal) 261s 69.467759 | sde: prio args = "" (setting: multipath internal) 261s 69.467761 | sde: const prio = 1 261s 69.468889 | unloading tur checker 261s 69.469029 | unloading const prioritizer 261s + dmsetup table 261s + echo Test WWN should now point to DM 261s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 261s + grep dm 261s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 261s mke2fs 1.47.0 (5-Feb-2023) 261s done 261s Writing superblocks and filesystem accounting information: 0/1 done 261s 261s + udevadm settle 261s + sleep 3s 264s + mkdir -p /mnt/tgtmpathtest 264s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 264s + cat 264s + cat 264s + fio --max-jobs=4 /tmp/autopkgtest.WBeCvG/tgtbasedmpaths-artifacts/path-change-prep.fio 264s 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 264s fio-3.37 264s Starting 1 thread 264s write-phase: Laying out IO file (1 file / 17592186044415MiB) 265s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 265s 265s write-phase: (groupid=0, jobs=1): err= 0: pid=6390: Wed Jun 12 19:48:16 2024 265s write: IOPS=2354, BW=147MiB/s (154MB/s)(87.6MiB/596msec); 0 zone resets 265s clat (usec): min=263, max=4870, avg=410.14, stdev=253.05 265s lat (usec): min=276, max=4883, avg=423.29, stdev=253.15 265s clat percentiles (usec): 265s | 1.00th=[ 285], 5.00th=[ 310], 10.00th=[ 318], 20.00th=[ 334], 265s | 30.00th=[ 355], 40.00th=[ 375], 50.00th=[ 392], 60.00th=[ 400], 265s | 70.00th=[ 408], 80.00th=[ 416], 90.00th=[ 437], 95.00th=[ 515], 265s | 99.00th=[ 1139], 99.50th=[ 2180], 99.90th=[ 4080], 99.95th=[ 4883], 265s | 99.99th=[ 4883] 265s bw ( KiB/s): min=146048, max=146048, per=97.01%, avg=146048.00, stdev= 0.00, samples=1 265s iops : min= 2282, max= 2282, avg=2282.00, stdev= 0.00, samples=1 265s lat (usec) : 500=94.37%, 750=3.92%, 1000=0.57% 265s lat (msec) : 2=0.50%, 4=0.43%, 10=0.14% 265s cpu : usr=1.85%, sys=11.09%, ctx=1404, majf=0, minf=0 265s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 265s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 265s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 265s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 265s latency : target=0, window=0, percentile=100.00%, depth=1 265s 265s Run status group 0 (all jobs): 265s WRITE: bw=147MiB/s (154MB/s), 147MiB/s-147MiB/s (154MB/s-154MB/s), io=87.6MiB (91.9MB), run=596-596msec 265s 265s Disk stats (read/write): 265s dm-0: ios=1/896, sectors=8/114688, merge=0/0, ticks=1/349, in_queue=350, util=80.00%, aggrios=0/351, aggsectors=2/48082, aggrmerge=0/0, aggrticks=8/138, aggrin_queue=147, aggrutil=83.68% 265s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 265s sdb: ios=2/1405, sectors=8/192328, merge=0/0, ticks=34/555, in_queue=588, util=83.68% 265s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 265s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 265s + echo Starting the path changes in background 265s Starting the path changes in background 265s + date +Pre FIO %H:%M:%S.%N 265s Pre FIO 19:48:16.653341062 265s + fio --max-jobs=4 /tmp/autopkgtest.WBeCvG/tgtbasedmpaths-artifacts/path-change-check.fio 265s 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 265s fio-3.37 265s Starting 1 thread 446s 446s verify-phase: (groupid=0, jobs=1): err= 0: pid=6397: Wed Jun 12 19:51:17 2024 446s read: IOPS=2916, BW=182MiB/s (191MB/s)(32.0GiB/180001msec) 446s clat (usec): min=86, max=48671, avg=318.96, stdev=213.02 446s lat (usec): min=86, max=48672, avg=319.07, stdev=213.02 446s clat percentiles (usec): 446s | 1.00th=[ 135], 5.00th=[ 169], 10.00th=[ 188], 20.00th=[ 221], 446s | 30.00th=[ 265], 40.00th=[ 293], 50.00th=[ 314], 60.00th=[ 334], 446s | 70.00th=[ 359], 80.00th=[ 392], 90.00th=[ 429], 95.00th=[ 453], 446s | 99.00th=[ 865], 99.50th=[ 1057], 99.90th=[ 1418], 99.95th=[ 1729], 446s | 99.99th=[ 3818] 446s bw ( KiB/s): min=127744, max=339712, per=100.00%, avg=186949.53, stdev=43805.00, samples=359 446s iops : min= 1996, max= 5308, avg=2921.09, stdev=684.44, samples=359 446s lat (usec) : 100=0.36%, 250=26.23%, 500=71.60%, 750=0.58%, 1000=0.58% 446s lat (msec) : 2=0.61%, 4=0.03%, 10=0.01%, 20=0.01%, 50=0.01% 446s cpu : usr=8.37%, sys=6.38%, ctx=525081, majf=0, minf=1 446s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 446s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 446s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 446s issued rwts: total=524992,0,0,0 short=0,0,0,0 dropped=0,0,0,0 446s latency : target=0, window=0, percentile=100.00%, depth=1 446s 446s Run status group 0 (all jobs): 446s READ: bw=182MiB/s (191MB/s), 182MiB/s-182MiB/s (191MB/s-191MB/s), io=32.0GiB (34.4GB), run=180001-180001msec 446s 446s Disk stats (read/write): 446s dm-0: ios=525249/7, sectors=67182520/120, merge=23/8, ticks=176751/27, in_queue=176804, util=99.97%, aggrios=36503/1, aggsectors=4668654/30, aggrmerge=0/0, aggrticks=11060/0, aggrin_queue=11061, aggrutil=99.12% 446s sdd: ios=29681/0, sectors=3796480/0, merge=0/0, ticks=8802/0, in_queue=8802, util=32.94% 446s sdb: ios=30071/7, sectors=3846272/120, merge=0/0, ticks=8593/3, in_queue=8595, util=99.12% 446s sde: ios=53659/0, sectors=6863488/0, merge=0/0, ticks=18054/0, in_queue=18054, util=40.02% 446s sdc: ios=32601/0, sectors=4168376/0, merge=0/0, ticks=8794/0, in_queue=8795, util=50.06% 446s + date +Post FIO %H:%M:%S.%N 446s Post FIO 19:51:17.036930279 446s FIO verify test with changing paths - OK 446s Report log of background activity 446s + echo FIO verify test with changing paths - OK 446s + echo Report log of background activity 446s + cat /tmp/autopkgtest.WBeCvG/tgtbasedmpaths-artifacts/test-background.log 446s + iscsiadm --mode session 446s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s + sleep 10s 446s + date +MP report (expect 4) %H:%M:%S.%N 446s MP report (expect 4) 19:48:26.663739660 446s + multipath -ll 446s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 446s size=100M features='0' hwhandler='0' wp=rw 446s |-+- policy='service-time 0' prio=1 status=active 446s | `- 1:0:0:1 sdb 8:16 active ready running 446s |-+- policy='service-time 0' prio=1 status=enabled 446s | `- 2:0:0:1 sdc 8:32 active ready running 446s |-+- policy='service-time 0' prio=1 status=enabled 446s | `- 3:0:0:1 sdd 8:48 active ready running 446s `-+- policy='service-time 0' prio=1 status=enabled 446s `- 4:0:0:1 sde 8:64 active ready running 446s + date +UN-plug path 1 %H:%M:%S.%N 446s UN-plug path 1 19:48:26.689598629 446s + iscsiadm --mode session -r 1 -u 446s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 446s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 446s + iscsiadm --mode session 446s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s + sleep 10s 446s + date +MP report (expect 3) %H:%M:%S.%N 446s MP report (expect 3) 19:48:36.800895137 446s + multipath -ll 446s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 446s size=100M features='0' hwhandler='0' wp=rw 446s |-+- policy='service-time 0' prio=1 status=active 446s | `- 2:0:0:1 sdc 8:32 active ready running 446s |-+- policy='service-time 0' prio=1 status=enabled 446s | `- 3:0:0:1 sdd 8:48 active ready running 446s `-+- policy='service-time 0' prio=1 status=enabled 446s `- 4:0:0:1 sde 8:64 active ready running 446s + date +UN-plug path 2 %H:%M:%S.%N 446s UN-plug path 2 19:48:36.824873637 446s + iscsiadm --mode session -r 2 -u 446s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 446s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 446s + iscsiadm --mode session 446s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s + sleep 10s 446s + date +MP report (expect 2) %H:%M:%S.%N 446s MP report (expect 2) 19:48:46.931225050 446s + multipath -ll 446s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 446s size=100M features='0' hwhandler='0' wp=rw 446s |-+- policy='service-time 0' prio=1 status=active 446s | `- 3:0:0:1 sdd 8:48 active ready running 446s `-+- policy='service-time 0' prio=1 status=enabled 446s `- 4:0:0:1 sde 8:64 active ready running 446s + date +UN-plug path 3 %H:%M:%S.%N 446s UN-plug path 3 19:48:46.950046760 446s + iscsiadm --mode session -r 3 -u 446s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 446s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 446s + iscsiadm --mode session 446s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s + sleep 10s 446s + date +MP report (expect 1) %H:%M:%S.%N 446s MP report (expect 1) 19:48:57.049404958 446s + multipath -ll 446s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 446s size=100M features='0' hwhandler='0' wp=rw 446s `-+- policy='service-time 0' prio=1 status=active 446s `- 4:0:0:1 sde 8:64 active ready running 446s + date +Add paths 5/6/7/8 %H:%M:%S.%N 446s Add paths 5/6/7/8 19:48:57.066982779 446s + iscsiadm --mode session -r 4 --op new 446s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 446s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 446s + iscsiadm --mode session -r 4 --op new 446s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 446s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 446s + iscsiadm --mode session -r 4 --op new 446s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 446s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 446s + iscsiadm --mode session -r 4 --op new 446s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 446s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 446s + iscsiadm --mode session 446s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s + sleep 10s 446s + date +MP report (expect 5) %H:%M:%S.%N 446s MP report (expect 5) 19:49:07.207833285 446s + multipath -ll 446s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 446s size=100M features='0' hwhandler='0' wp=rw 446s |-+- policy='service-time 0' prio=1 status=active 446s | `- 4:0:0:1 sde 8:64 active ready running 446s |-+- policy='service-time 0' prio=1 status=enabled 446s | `- 1:0:0:1 sdb 8:16 active ready running 446s |-+- policy='service-time 0' prio=1 status=enabled 446s | `- 2:0:0:1 sdc 8:32 active ready running 446s |-+- policy='service-time 0' prio=1 status=enabled 446s | `- 3:0:0:1 sdd 8:48 active ready running 446s `-+- policy='service-time 0' prio=1 status=enabled 446s `- 5:0:0:1 sdf 8:80 active ready running 446s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 446s UN-plug multiple paths 4/7/8 19:49:07.240716296 446s + iscsiadm --mode session -r 4 -u 446s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 446s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 446s + iscsiadm --mode session -r 7 -u 446s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 446s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 446s + iscsiadm --mode session -r 8 -u 446s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 446s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 446s + iscsiadm --mode session 446s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 446s + sleep 10s 446s + date +Restart multipath daemon %H:%M:%S.%N 446s Restart multipath daemon 19:49:17.561634277 446s + systemctl restart multipathd 446s + sleep 10s 446s + date +Final background report (expect 2) %H:%M:%S.%N 446s Final background report (expect 2) 19:49:27.654706555 446s + multipath -ll 446s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 446s size=100M features='0' hwhandler='0' wp=rw 446s |-+- policy='service-time 0' prio=1 status=active 446s | `- 1:0:0:1 sdb 8:16 active ready running 446s `-+- policy='service-time 0' prio=1 status=enabled 446s `- 2:0:0:1 sdc 8:32 active ready running 446s Final stats 446s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 446s iSCSI SNMP: 446s txdata_octets: 18148440 446s rxdata_octets: 24755486916 446s noptx_pdus: 0 446s scsicmd_pdus: 377825 446s tmfcmd_pdus: 0 446s login_pdus: 0 446s text_pdus: 0 446s dataout_pdus: 0 446s logout_pdus: 0 446s snack_pdus: 0 446s noprx_pdus: 0 446s scsirsp_pdus: 377825 446s tmfrsp_pdus: 0 446s textrsp_pdus: 0 446s datain_pdus: 377791 446s logoutrsp_pdus: 0 446s r2t_pdus: 0 446s async_pdus: 0 446s rjt_pdus: 0 446s digest_err: 0 446s timeout_err: 0 446s iSCSI Extended: 446s tx_sendpage_failures: 0 446s rx_discontiguous_hdr: 0 446s eh_abort_cnt: 0 446s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 446s iSCSI SNMP: 446s txdata_octets: 6552 446s rxdata_octets: 1515012 446s noptx_pdus: 0 446s scsicmd_pdus: 106 446s tmfcmd_pdus: 0 446s login_pdus: 0 446s text_pdus: 0 446s dataout_pdus: 0 446s logout_pdus: 0 446s snack_pdus: 0 446s noprx_pdus: 0 446s scsirsp_pdus: 106 446s tmfrsp_pdus: 0 446s textrsp_pdus: 0 446s datain_pdus: 83 446s logoutrsp_pdus: 0 446s r2t_pdus: 0 446s async_pdus: 0 446s rjt_pdus: 0 446s digest_err: 0 446s timeout_err: 0 446s iSCSI Extended: 446s tx_sendpage_failures: 0 446s rx_discontiguous_hdr: 0 446s eh_abort_cnt: 0 446s + sync 446s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 446s + echo Final stats 446s + iscsiadm --mode session --stats 446s + journalctl --no-pager -u multipathd 446s Jun 12 17:58:33 adtubuntu-oracular-ppc64el-server-20240610 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 446s Jun 12 17:58:33 adtubuntu-oracular-ppc64el-server-20240610 multipathd[281]: multipathd v0.9.4: start up 446s Jun 12 17:58:33 adtubuntu-oracular-ppc64el-server-20240610 multipathd[281]: reconfigure: setting up paths and maps 446s Jun 12 17:58:33 adtubuntu-oracular-ppc64el-server-20240610 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 446s Jun 12 17:59:13 adtubuntu-oracular-ppc64el-server-20240611 multipathd[281]: multipathd: shut down 446s Jun 12 17:59:13 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 446s Jun 12 17:59:13 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: multipathd.service: Deactivated successfully. 446s Jun 12 17:59:13 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 446s -- Boot eb3890a22d3e44c38e4a72e6421d5c6b -- 446s Jun 12 17:59:38 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 446s Jun 12 17:59:38 adtubuntu-oracular-ppc64el-server-20240611 multipathd[285]: multipathd v0.9.4: start up 446s Jun 12 17:59:38 adtubuntu-oracular-ppc64el-server-20240611 multipathd[285]: reconfigure: setting up paths and maps 446s Jun 12 17:59:38 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 446s Jun 12 18:00:04 adtubuntu-oracular-ppc64el-server-20240611 multipathd[285]: multipathd: shut down 446s Jun 12 18:00:04 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 446s Jun 12 18:00:04 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: multipathd.service: Deactivated successfully. 446s Jun 12 18:00:04 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 446s -- Boot 054e80658c65473a8d52b66e146ea709 -- 446s Jun 12 19:47:06 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 446s Jun 12 19:47:06 adtubuntu-oracular-ppc64el-server-20240611 multipathd[333]: multipathd v0.9.4: start up 446s Jun 12 19:47:06 adtubuntu-oracular-ppc64el-server-20240611 multipathd[333]: reconfigure: setting up paths and maps 446s Jun 12 19:47:06 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 446s Jun 12 19:48:07 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] 446s Jun 12 19:48:07 autopkgtest multipathd[333]: sdc [8:32]: path added to devmap mpatha 446s Jun 12 19:48:07 autopkgtest multipathd[333]: mpatha: performing delayed actions 446s Jun 12 19:48:07 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] 446s Jun 12 19:48:26 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] 446s Jun 12 19:48:26 autopkgtest multipathd[333]: check_removed_paths: sdb: freeing path in removed state 446s Jun 12 19:48:26 autopkgtest multipathd[333]: 8:16: path removed from map mpatha 446s Jun 12 19:48:36 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] 446s Jun 12 19:48:36 autopkgtest multipathd[333]: check_removed_paths: sdc: freeing path in removed state 446s Jun 12 19:48:36 autopkgtest multipathd[333]: 8:32: path removed from map mpatha 446s Jun 12 19:48:46 autopkgtest multipathd[333]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 446s Jun 12 19:48:47 autopkgtest multipathd[333]: check_removed_paths: sdd: freeing path in removed state 446s Jun 12 19:48:47 autopkgtest multipathd[333]: 8:48: path removed from map mpatha 446s Jun 12 19:4+ echo Check final path status 446s + multipath -ll 446s 8:57 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] 446s Jun 12 19:48:57 autopkgtest multipathd[333]: sdb [8:16]: path added to devmap mpatha 446s Jun 12 19:48:57 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] 446s Jun 12 19:48:57 autopkgtest multipathd[333]: sdc [8:32]: path added to devmap mpatha 446s Jun 12 19:48:57 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] 446s Jun 12 19:48:57 autopkgtest multipathd[333]: sdd [8:48]: path added to devmap mpatha 446s Jun 12 19:48:57 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] 446s Jun 12 19:48:57 autopkgtest multipathd[333]: sdf [8:80]: path added to devmap mpatha 446s Jun 12 19:49:07 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] 446s Jun 12 19:49:07 autopkgtest multipathd[333]: check_removed_paths: sde: freeing path in removed state 446s Jun 12 19:49:07 autopkgtest multipathd[333]: 8:64: path removed from map mpatha 446s Jun 12 19:49:07 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] 446s Jun 12 19:49:07 autopkgtest multipathd[333]: check_removed_paths: sdd: freeing path in removed state 446s Jun 12 19:49:07 autopkgtest multipathd[333]: 8:48: path removed from map mpatha 446s Jun 12 19:49:07 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] 446s Jun 12 19:49:07 autopkgtest multipathd[333]: check_removed_paths: sdf: freeing path in removed state 446s Jun 12 19:49:07 autopkgtest multipathd[333]: 8:80: path removed from map mpatha 446s Jun 12 19:49:17 autopkgtest multipathd[333]: multipathd: shut down 446s Jun 12 19:49:17 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 446s Jun 12 19:49:17 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 446s Jun 12 19:49:17 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 446s Jun 12 19:49:17 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 446s Jun 12 19:49:17 autopkgtest multipathd[6764]: multipathd v0.9.4: start up 446s Jun 12 19:49:17 autopkgtest multipathd[6764]: reconfigure: setting up paths and maps 446s Jun 12 19:49:17 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 446s Check final path status 446s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 446s size=100M features='0' hwhandler='0' wp=rw 446s |-+- policy='service-time 0' prio=1 status=active 446s | `- 1:0:0:1 sdb 8:16 active ready running 446s `-+- policy='service-time 0' prio=1 status=enabled 446s `- 2:0:0:1 sdc 8:32 active ready running 446s + multipath+ -ll 446s grep --count status= 446s + diskc=2 446s + grep --count status=active 446s + multipath -ll 446s + diska=1 446s + multipath -ll 446s + grep --count status=enabled 446s OK 446s + diske=1 446s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 446s + echo OK 446s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 446s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 446s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 446s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 446s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 446s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 446s autopkgtest [19:51:17]: test tgtbasedmpaths: -----------------------] 447s autopkgtest [19:51:18]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 447s tgtbasedmpaths PASS 447s autopkgtest [19:51:18]: @@@@@@@@@@@@@@@@@@@@ summary 447s kpartx-file-loopback PASS 447s tgtbasedmpaths PASS 460s nova [W] Using flock in scalingstack-bos01-ppc64el 460s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240612-194349-juju-7f2275-prod-proposed-migration-environment-2-88802bd5-fb20-4feb-955b-fc1fa0ecd287 from image adt/ubuntu-oracular-ppc64el-server-20240612.img (UUID 7abe9be2-6b8b-44d9-8daf-bd7bebbc8526)... 460s nova [W] Using flock in scalingstack-bos01-ppc64el 460s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240612-194349-juju-7f2275-prod-proposed-migration-environment-2-88802bd5-fb20-4feb-955b-fc1fa0ecd287 from image adt/ubuntu-oracular-ppc64el-server-20240612.img (UUID 7abe9be2-6b8b-44d9-8daf-bd7bebbc8526)...