0s autopkgtest [20:34:27]: starting date and time: 2024-07-08 20:34:27+0000 0s autopkgtest [20:34:27]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [20:34:27]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work._ci48f72/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-3ubuntu4 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos02-ppc64el-14.secgroup --name adt-oracular-ppc64el-multipath-tools-20240708-203427-juju-7f2275-prod-proposed-migration-environment-2-9a82822f-03aa-4519-ad49-b0997074a47d --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://ftpmaster.internal/ubuntu/ 90s autopkgtest [20:35:57]: testbed dpkg architecture: ppc64el 90s autopkgtest [20:35:57]: testbed apt version: 2.9.6 90s autopkgtest [20:35:57]: @@@@@@@@@@@@@@@@@@@@ test bed setup 91s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 92s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [51.0 kB] 92s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [355 kB] 92s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 92s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3436 B] 92s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [84.0 kB] 92s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2596 B] 92s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 92s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 92s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [351 kB] 92s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [9296 B] 92s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1936 B] 92s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 93s Fetched 994 kB in 1s (1229 kB/s) 94s Reading package lists... 96s Reading package lists... 96s Building dependency tree... 96s Reading state information... 96s Calculating upgrade... 96s The following packages will be upgraded: 96s dracut-install libnetplan1 lto-disabled-list netplan-generator netplan.io 96s python3-netplan 96s 6 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 96s Need to get 339 kB of archives. 96s After this operation, 1024 B of additional disk space will be used. 96s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el netplan-generator ppc64el 1.0.1-1ubuntu2 [59.6 kB] 97s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-netplan ppc64el 1.0.1-1ubuntu2 [22.0 kB] 97s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el netplan.io ppc64el 1.0.1-1ubuntu2 [66.9 kB] 97s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnetplan1 ppc64el 1.0.1-1ubuntu2 [141 kB] 97s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dracut-install ppc64el 102-3ubuntu4 [36.7 kB] 97s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el lto-disabled-list all 52 [12.3 kB] 97s Fetched 339 kB in 0s (681 kB/s) 97s (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 ... 72736 files and directories currently installed.) 97s Preparing to unpack .../0-netplan-generator_1.0.1-1ubuntu2_ppc64el.deb ... 97s Adding 'diversion of /lib/systemd/system-generators/netplan to /lib/systemd/system-generators/netplan.usr-is-merged by netplan-generator' 97s Unpacking netplan-generator (1.0.1-1ubuntu2) over (1.0.1-1ubuntu1) ... 97s Preparing to unpack .../1-python3-netplan_1.0.1-1ubuntu2_ppc64el.deb ... 97s Unpacking python3-netplan (1.0.1-1ubuntu2) over (1.0.1-1ubuntu1) ... 97s Preparing to unpack .../2-netplan.io_1.0.1-1ubuntu2_ppc64el.deb ... 97s Unpacking netplan.io (1.0.1-1ubuntu2) over (1.0.1-1ubuntu1) ... 97s Preparing to unpack .../3-libnetplan1_1.0.1-1ubuntu2_ppc64el.deb ... 97s Unpacking libnetplan1:ppc64el (1.0.1-1ubuntu2) over (1.0.1-1ubuntu1) ... 97s Preparing to unpack .../4-dracut-install_102-3ubuntu4_ppc64el.deb ... 97s Unpacking dracut-install (102-3ubuntu4) over (102-3ubuntu3) ... 97s Preparing to unpack .../5-lto-disabled-list_52_all.deb ... 97s Unpacking lto-disabled-list (52) over (51) ... 97s Setting up lto-disabled-list (52) ... 97s Setting up libnetplan1:ppc64el (1.0.1-1ubuntu2) ... 97s Setting up dracut-install (102-3ubuntu4) ... 97s Setting up python3-netplan (1.0.1-1ubuntu2) ... 97s Setting up netplan-generator (1.0.1-1ubuntu2) ... 97s Removing 'diversion of /lib/systemd/system-generators/netplan to /lib/systemd/system-generators/netplan.usr-is-merged by netplan-generator' 97s Setting up netplan.io (1.0.1-1ubuntu2) ... 97s Processing triggers for libc-bin (2.39-0ubuntu9) ... 97s Processing triggers for man-db (2.12.1-2) ... 98s Processing triggers for dbus (1.14.10-4ubuntu4) ... 98s Reading package lists... 98s Building dependency tree... 98s Reading state information... 99s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 99s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 99s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 99s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 99s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 100s Reading package lists... 100s Reading package lists... 100s Building dependency tree... 100s Reading state information... 100s Calculating upgrade... 100s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 100s Reading package lists... 101s Building dependency tree... 101s Reading state information... 101s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 103s autopkgtest [20:36:10]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 104s autopkgtest [20:36:11]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 107s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 107s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 107s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 107s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 107s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 107s gpgv: issuer "steve.langasek@ubuntu.com" 107s gpgv: Can't check signature: No public key 107s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 107s autopkgtest [20:36:14]: testing package multipath-tools version 0.9.4-5ubuntu8 107s autopkgtest [20:36:14]: build not needed 108s autopkgtest [20:36:15]: test kpartx-file-loopback: preparing testbed 109s Reading package lists... 109s Building dependency tree... 109s Reading state information... 109s Starting pkgProblemResolver with broken count: 0 109s Starting 2 pkgProblemResolver with broken count: 0 109s Done 109s The following additional packages will be installed: 109s liburing2 qemu-utils 109s Recommended packages: 109s qemu-block-extra 109s The following NEW packages will be installed: 109s autopkgtest-satdep liburing2 qemu-utils 109s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 109s Need to get 2330 kB/2331 kB of archives. 109s After this operation, 15.4 MB of additional disk space will be used. 109s Get:1 /tmp/autopkgtest.9Vo1BJ/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 109s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 110s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 110s Fetched 2330 kB in 1s (3315 kB/s) 110s Selecting previously unselected package liburing2:ppc64el. 110s (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 ... 72736 files and directories currently installed.) 110s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 110s Unpacking liburing2:ppc64el (2.6-1) ... 110s Selecting previously unselected package qemu-utils. 110s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 110s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 110s Selecting previously unselected package autopkgtest-satdep. 110s Preparing to unpack .../1-autopkgtest-satdep.deb ... 110s Unpacking autopkgtest-satdep (0) ... 110s Setting up liburing2:ppc64el (2.6-1) ... 110s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 110s Setting up autopkgtest-satdep (0) ... 110s Processing triggers for man-db (2.12.1-2) ... 111s Processing triggers for libc-bin (2.39-0ubuntu9) ... 113s (Reading database ... 72756 files and directories currently installed.) 113s Removing autopkgtest-satdep (0) ... 114s autopkgtest [20:36:21]: test kpartx-file-loopback: [----------------------- 114s Formatting 'foo.img', fmt=raw size=20971520 115s Creating new GPT entries in memory. 115s Warning: The kernel is still using the old partition table. 115s The new table will be used at the next reboot or after you 115s run partprobe(8) or kpartx(8) 115s The operation has completed successfully. 115s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 115s standard_filename: OK 115s del devmap : loop0p1 115s No devices found 115s standard_filename_cleanup: OK 115s Formatting 'fou du FaFa.img', fmt=raw size=20971520 116s Creating new GPT entries in memory. 116s Warning: The kernel is still using the old partition table. 116s The new table will be used at the next reboot or after you 116s run partprobe(8) or kpartx(8) 116s The operation has completed successfully. 116s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 116s filename_with_spaces: OK 116s del devmap : loop0p1 116s No devices found 116s filename_with_spaces_cleanup: OK 117s autopkgtest [20:36:24]: test kpartx-file-loopback: -----------------------] 117s autopkgtest [20:36:24]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 117s kpartx-file-loopback PASS 117s autopkgtest [20:36:24]: test tgtbasedmpaths: preparing testbed 219s autopkgtest [20:38:06]: testbed dpkg architecture: ppc64el 220s autopkgtest [20:38:07]: testbed apt version: 2.9.6 220s autopkgtest [20:38:07]: @@@@@@@@@@@@@@@@@@@@ test bed setup 221s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 221s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [51.0 kB] 221s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3436 B] 221s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 221s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [355 kB] 221s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [84.0 kB] 221s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2596 B] 221s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 221s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 221s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [351 kB] 221s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [9296 B] 221s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1936 B] 221s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 223s Fetched 994 kB in 1s (922 kB/s) 223s Reading package lists... 225s Reading package lists... 225s Building dependency tree... 226s Reading state information... 226s Calculating upgrade... 226s The following packages will be upgraded: 226s dracut-install libnetplan1 lto-disabled-list netplan-generator netplan.io 226s python3-netplan 226s 6 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 226s Need to get 339 kB of archives. 226s After this operation, 1024 B of additional disk space will be used. 226s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el netplan-generator ppc64el 1.0.1-1ubuntu2 [59.6 kB] 226s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-netplan ppc64el 1.0.1-1ubuntu2 [22.0 kB] 226s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el netplan.io ppc64el 1.0.1-1ubuntu2 [66.9 kB] 226s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnetplan1 ppc64el 1.0.1-1ubuntu2 [141 kB] 226s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dracut-install ppc64el 102-3ubuntu4 [36.7 kB] 226s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el lto-disabled-list all 52 [12.3 kB] 227s Fetched 339 kB in 1s (578 kB/s) 227s (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 ... 72736 files and directories currently installed.) 227s Preparing to unpack .../0-netplan-generator_1.0.1-1ubuntu2_ppc64el.deb ... 227s Adding 'diversion of /lib/systemd/system-generators/netplan to /lib/systemd/system-generators/netplan.usr-is-merged by netplan-generator' 227s Unpacking netplan-generator (1.0.1-1ubuntu2) over (1.0.1-1ubuntu1) ... 227s Preparing to unpack .../1-python3-netplan_1.0.1-1ubuntu2_ppc64el.deb ... 227s Unpacking python3-netplan (1.0.1-1ubuntu2) over (1.0.1-1ubuntu1) ... 227s Preparing to unpack .../2-netplan.io_1.0.1-1ubuntu2_ppc64el.deb ... 227s Unpacking netplan.io (1.0.1-1ubuntu2) over (1.0.1-1ubuntu1) ... 227s Preparing to unpack .../3-libnetplan1_1.0.1-1ubuntu2_ppc64el.deb ... 227s Unpacking libnetplan1:ppc64el (1.0.1-1ubuntu2) over (1.0.1-1ubuntu1) ... 227s Preparing to unpack .../4-dracut-install_102-3ubuntu4_ppc64el.deb ... 227s Unpacking dracut-install (102-3ubuntu4) over (102-3ubuntu3) ... 227s Preparing to unpack .../5-lto-disabled-list_52_all.deb ... 227s Unpacking lto-disabled-list (52) over (51) ... 227s Setting up lto-disabled-list (52) ... 227s Setting up libnetplan1:ppc64el (1.0.1-1ubuntu2) ... 227s Setting up dracut-install (102-3ubuntu4) ... 227s Setting up python3-netplan (1.0.1-1ubuntu2) ... 227s Setting up netplan-generator (1.0.1-1ubuntu2) ... 227s Removing 'diversion of /lib/systemd/system-generators/netplan to /lib/systemd/system-generators/netplan.usr-is-merged by netplan-generator' 227s Setting up netplan.io (1.0.1-1ubuntu2) ... 227s Processing triggers for libc-bin (2.39-0ubuntu9) ... 227s Processing triggers for man-db (2.12.1-2) ... 229s Processing triggers for dbus (1.14.10-4ubuntu4) ... 229s Reading package lists... 229s Building dependency tree... 229s Reading state information... 229s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 230s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 230s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 230s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 230s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 231s Reading package lists... 231s Reading package lists... 231s Building dependency tree... 231s Reading state information... 231s Calculating upgrade... 231s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 231s Reading package lists... 231s Building dependency tree... 231s Reading state information... 231s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 235s Reading package lists... 235s Building dependency tree... 235s Reading state information... 235s Starting pkgProblemResolver with broken count: 0 235s Starting 2 pkgProblemResolver with broken count: 0 235s Done 236s The following additional packages will be installed: 236s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 236s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 236s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 236s librdmacm1t64 lsscsi open-iscsi tgt 236s Suggested packages: 236s fio-examples gnuplot tgt-glusterfs tgt-rbd 236s Recommended packages: 236s finalrd 236s The following NEW packages will be installed: 236s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 236s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 236s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 236s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 236s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 236s Need to get 10.7 MB/10.7 MB of archives. 236s After this operation, 49.0 MB of additional disk space will be used. 236s Get:1 /tmp/autopkgtest.9Vo1BJ/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [736 B] 236s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 236s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 236s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 236s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2 [80.5 kB] 236s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 236s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 237s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4ubuntu1 [21.5 kB] 237s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4ubuntu1 [311 kB] 237s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4ubuntu1 [46.5 kB] 237s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4ubuntu1 [99.2 kB] 237s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-1 [97.4 kB] 237s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 237s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 237s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 237s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 237s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 237s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 238s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 238s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 238s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 239s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 239s Preconfiguring packages ... 239s Fetched 10.7 MB in 3s (3764 kB/s) 239s Selecting previously unselected package libopeniscsiusr. 239s (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 ... 72736 files and directories currently installed.) 239s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 239s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 239s Selecting previously unselected package libisns0t64:ppc64el. 239s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 239s Unpacking libisns0t64:ppc64el (0.101-1) ... 239s Selecting previously unselected package open-iscsi. 239s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 239s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 239s Selecting previously unselected package librdmacm1t64:ppc64el. 239s Preparing to unpack .../03-librdmacm1t64_52.0-2_ppc64el.deb ... 239s Unpacking librdmacm1t64:ppc64el (52.0-2) ... 239s Selecting previously unselected package libconfig-general-perl. 239s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 239s Unpacking libconfig-general-perl (2.65-2) ... 239s Selecting previously unselected package tgt. 239s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 239s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 239s Selecting previously unselected package libgfxdr0:ppc64el. 239s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_ppc64el.deb ... 239s Unpacking libgfxdr0:ppc64el (11.1-4ubuntu1) ... 239s Selecting previously unselected package libglusterfs0:ppc64el. 239s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_ppc64el.deb ... 239s Unpacking libglusterfs0:ppc64el (11.1-4ubuntu1) ... 239s Selecting previously unselected package libgfrpc0:ppc64el. 239s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_ppc64el.deb ... 239s Unpacking libgfrpc0:ppc64el (11.1-4ubuntu1) ... 239s Selecting previously unselected package libgfapi0:ppc64el. 239s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_ppc64el.deb ... 239s Unpacking libgfapi0:ppc64el (11.1-4ubuntu1) ... 239s Selecting previously unselected package libnbd0. 239s Preparing to unpack .../10-libnbd0_1.20.2-1_ppc64el.deb ... 239s Unpacking libnbd0 (1.20.2-1) ... 239s Selecting previously unselected package libdaxctl1:ppc64el. 239s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 239s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 239s Selecting previously unselected package libndctl6:ppc64el. 239s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 239s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 239s Selecting previously unselected package libpmem1:ppc64el. 239s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 239s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 239s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 239s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 239s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 239s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 239s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 239s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 239s Selecting previously unselected package librados2. 239s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 239s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 239s Selecting previously unselected package libpmemobj1:ppc64el. 239s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 239s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 239s Selecting previously unselected package librbd1. 239s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 239s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 239s Selecting previously unselected package fio. 239s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 239s Unpacking fio (3.37-1) ... 240s Selecting previously unselected package lsscsi. 240s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 240s Unpacking lsscsi (0.32-1build1) ... 240s Selecting previously unselected package autopkgtest-satdep. 240s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 240s Unpacking autopkgtest-satdep (0) ... 240s Setting up libconfig-general-perl (2.65-2) ... 240s Setting up libisns0t64:ppc64el (0.101-1) ... 240s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 240s Setting up libnbd0 (1.20.2-1) ... 240s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 240s Setting up libglusterfs0:ppc64el (11.1-4ubuntu1) ... 240s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 240s Setting up lsscsi (0.32-1build1) ... 240s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 240s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 240s Setting up librdmacm1t64:ppc64el (52.0-2) ... 240s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 240s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 240s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 240s Setting up libgfxdr0:ppc64el (11.1-4ubuntu1) ... 241s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 241s Setting up open-iscsi (2.1.10-1ubuntu1) ... 241s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 242s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 242s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 242s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 242s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 242s Setting up libgfrpc0:ppc64el (11.1-4ubuntu1) ... 242s Setting up libgfapi0:ppc64el (11.1-4ubuntu1) ... 242s Setting up fio (3.37-1) ... 243s Setting up autopkgtest-satdep (0) ... 243s Processing triggers for man-db (2.12.1-2) ... 244s Processing triggers for initramfs-tools (0.142ubuntu29) ... 244s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 244s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 252s Processing triggers for libc-bin (2.39-0ubuntu9) ... 254s (Reading database ... 72977 files and directories currently installed.) 254s Removing autopkgtest-satdep (0) ... 256s autopkgtest [20:38:43]: test tgtbasedmpaths: [----------------------- 256s + targetname=iqn.2016-11.foo.com:target.iscsi 256s + pwd 256s + cwd=/tmp/autopkgtest.9Vo1BJ/build.wpu/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.9Vo1BJ/tgtbasedmpaths-artifacts/test-background.log 256s + fioprep=/tmp/autopkgtest.9Vo1BJ/tgtbasedmpaths-artifacts/path-change-prep.fio 256s + fiovrfy=/tmp/autopkgtest.9Vo1BJ/tgtbasedmpaths-artifacts/path-change-check.fio 256s + service tgt restart 257s + truncate --size 100M backingfile 257s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 257s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 257s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.9Vo1BJ/build.wpu/src/backingfile 257s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 257s + echo login #1 257s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 257s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 257s login #1 257s + seq 2 4 257s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 257s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 257s + echo extra login #2 257s + iscsiadm --mode session -r 1 --op new 257s extra login #2 257s + echo extra login #3 257s + iscsiadm --mode session -r 1 --op new 257s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 257s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 257s extra login #3 257s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 257s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 257s extra login #4 257s + echo extra login #4 257s + iscsiadm --mode session -r 1 --op new 257s + udevadm settle 257s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 257s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 257s + sleep 5 262s Status after initial setup 262s + echo Status after initial setup 262s + tgtadm --lld iscsi --mode target --op show 262s Target 1: iqn.2016-11.foo.com:target.iscsi 262s System information: 262s Driver: iscsi 262s State: ready 262s I_T nexus information: 262s I_T nexus: 1 262s Initiator: iqn.2004-10.com.ubuntu:01:ed8b6bbc97f alias: autopkgtest 262s Connection: 0 262s IP Address: 127.0.0.1 262s I_T nexus: 2 262s Initiator: iqn.2004-10.com.ubuntu:01:ed8b6bbc97f alias: autopkgtest 262s Connection: 0 262s IP Address: 127.0.0.1 262s I_T nexus: 3 262s Initiator: iqn.2004-10.com.ubuntu:01:ed8b6bbc97f alias: autopkgtest 262s Connection: 0 262s IP Address: 127.0.0.1 262s I_T nexus: 4 262s Initiator: iqn.2004-10.com.ubuntu:01:ed8b6bbc97f alias: autopkgtest 262s Connection: 0 262s IP Address: 127.0.0.1 262s LUN information: 262s LUN: 0 262s Type: controller 262s SCSI ID: IET 00010000 262s SCSI SN: beaf10 262s Size: 0 MB, Block size: 1 262s Online: Yes 262s Removable media: No 262s Prevent removal: No 262s Readonly: No 262s SWP: No 262s Thin-provisioning: No 262s Backing store type: null 262s Backing store path: None 262s Backing store flags: 262s LUN: 1 262s Type: disk 262s SCSI ID: IET 00010001 262s SCSI SN: beaf11 262s Size: 105 MB, Block size: 512 262s Online: Yes 262s Removable media: No 262s Prevent removal: No 262s Readonly: No 262s SWP: No 262s Thin-provisioning: No 262s Backing store type: rdwr 262s Backing store path: /tmp/autopkgtest.9Vo1BJ/build.wpu/src/backingfile 262s Backing store flags: 262s Account information: 262s ACL information: 262s ALL 262s + tgtadm --lld iscsi --op show --mode conn --tid 1 262s + iscsiadm --mode session -P 1 262s Session: 4 262s Connection: 0 262s Initiator: iqn.2004-10.com.ubuntu:01:ed8b6bbc97f 262s IP Address: 127.0.0.1 262s Session: 3 262s Connection: 0 262s Initiator: iqn.2004-10.com.ubuntu:01:ed8b6bbc97f 262s IP Address: 127.0.0.1 262s Session: 2 262s Connection: 0 262s Initiator: iqn.2004-10.com.ubuntu:01:ed8b6bbc97f 262s IP Address: 127.0.0.1 262s Session: 1 262s Connection: 0 262s Initiator: iqn.2004-10.com.ubuntu:01:ed8b6bbc97f 262s IP Address: 127.0.0.1 262s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 262s Current Portal: 127.0.0.1:3260,1 262s Persistent Portal: 127.0.0.1:3260,1 262s ********** 262s Interface: 262s ********** 262s Iface Name: default 262s Iface Transport: tcp 262s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ed8b6bbc97f 262s Iface IPaddress: 127.0.0.1 262s Iface HWaddress: default 262s Iface Netdev: default 262s SID: 1 262s iSCSI Connection State: LOGGED IN 262s iSCSI Session State: LOGGED_IN 262s Internal iscsid Session State: NO CHANGE 262s 262s ********** 262s Interface: 262s ********** 262s Iface Name: default 262s Iface Transport: tcp 262s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ed8b6bbc97f 262s Iface IPaddress: 127.0.0.1 262s Iface HWaddress: default 262s Iface Netdev: default 262s SID: 2 262s iSCSI Connection State: LOGGED IN 262s iSCSI Session State: LOGGED_IN 262s Internal iscsid Session State: NO CHANGE 262s 262s ********** 262s Interface: 262s ********** 262s Iface Name: default 262s Iface Transport: tcp 262s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ed8b6bbc97f 262s Iface IPaddress: 127.0.0.1 262s Iface HWaddress: default 262s Iface Netdev: default 262s SID: 3 262s iSCSI Connection State: LOGGED IN 262s iSCSI Session State: LOGGED_IN 262s Internal iscsid Session State: NO CHANGE 262s 262s ********** 262s Interface: 262s ********** 262s Iface Name: default 262s Iface Transport: tcp 262s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ed8b6bbc97f 262s Iface IPaddress: 127.0.0.1 262s Iface HWaddress: default 262s Iface Netdev: default 262s SID: 4 262s iSCSI Connection State: LOGGED IN 262s iSCSI Session State: LOGGED_IN 262s Internal iscsid Session State: NO CHANGE 262s + lsscsi -liv 262s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 262s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 262s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 262s 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] 262s [1:0:0:0] storage IET Controller 0001 - - 262s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 262s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 262s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 262s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 262s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 262s [2:0:0:0] storage IET Controller 0001 - - 262s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 262s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 262s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 262s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 262s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 262s [3:0:0:0] storage IET Controller 0001 - - 262s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 262s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 262s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 262s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 262s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 262s [4:0:0:0] storage IET Controller 0001 - - 262s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 262s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 262s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 33000000100000001 262s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 262s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 262s NVMe module may not be loaded 262s + multipath -v3 -ll 262s 71.105825 | set open fds limit to 1048576/1048576 262s 71.105909 | loading /lib/multipath/libchecktur.so checker 262s 71.106040 | checker tur: message table size = 3 262s 71.106066 | loading /lib/multipath/libprioconst.so prioritizer 262s 71.106199 | _init_foreign: foreign library "nvme" is not enabled 262s 71.111539 | sda: size = 167772160 262s 71.111697 | sda: vendor = QEMU 262s 71.111737 | sda: product = QEMU HARDDISK 262s 71.111759 | sda: rev = 2.5+ 262s 71.112369 | sda: h:b:t:l = 0:0:0:0 262s 71.112673 | sda: tgt_node_name = 262s 71.112693 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 262s 71.112696 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 262s 71.112845 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 262s 71.112865 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 262s 71.112877 | __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 262s 71.112882 | failed to read sysfs vpd pg80: No such file or directory 262s 71.113099 | sda: fail to get serial 262s 71.113119 | sda: detect_checker = yes (setting: multipath internal) 262s 71.113302 | sda: path_checker = tur (setting: multipath internal) 262s 71.113322 | sda: checker timeout = 30 s (setting: kernel sysfs) 262s 71.113456 | sda: tur state = up 262s 71.113758 | sdb: size = 204800 262s 71.113900 | sdb: vendor = IET 262s 71.113938 | sdb: product = VIRTUAL-DISK 262s 71.113958 | sdb: rev = 0001 262s 71.114562 | sdb: h:b:t:l = 1:0:0:1 262s 71.114909 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 262s 71.114929 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 262s 71.114931 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 262s 71.115089 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 262s 71.115108 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 262s 71.115124 | sdb: serial = beaf11 262s 71.115126 | sdb: detect_checker = yes (setting: multipath internal) 262s 71.115418 | sdb: path_checker = tur (setting: multipath internal) 262s 71.115438 | sdb: checker timeout = 30 s (setting: kernel sysfs) 262s 71.115595 | sdb: tur state = up 262s 71.115732 | sdc: size = 204800 262s 71.115872 | sdc: vendor = IET 262s 71.115910 | sdc: product = VIRTUAL-DISK 262s 71.115931 | sdc: rev = 0001 262s 71.116615 | sdc: h:b:t:l = 2:0:0:1 262s 71.116960 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 262s 71.116980 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 262s 71.116982 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 262s 71.117122 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 262s 71.117141 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 262s 71.117155 | sdc: serial = beaf11 262s 71.117158 | sdc: detect_checker = yes (setting: multipath internal) 262s 71.117362 | sdc: path_checker = tur (setting: multipath internal) 262s 71.117382 | sdc: checker timeout = 30 s (setting: kernel sysfs) 262s 71.117533 | sdc: tur state = up 262s 71.117673 | sdd: size = 204800 262s 71.117813 | sdd: vendor = IET 262s 71.117851 | sdd: product = VIRTUAL-DISK 262s 71.117871 | sdd: rev = 0001 262s 71.118527 | sdd: h:b:t:l = 3:0:0:1 262s 71.118869 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 262s 71.118888 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 262s 71.118890 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 262s 71.119049 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 262s 71.119069 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 262s 71.119083 | sdd: serial = beaf11 262s 71.119085 | sdd: detect_checker = yes (setting: multipath internal) 262s 71.119286 | sdd: path_checker = tur (setting: multipath internal) 262s 71.119306 | sdd: checker timeout = 30 s (setting: kernel sysfs) 262s 71.119453 | sdd: tur state = up 262s 71.119591 | sde: size = 204800 262s 71.119730 | sde: vendor = IET 262s 71.119768 | sde: product = VIRTUAL-DISK 262s 71.119788 | sde: rev = 0001 262s 71.120458 | sde: h:b:t:l = 4:0:0:1 262s 71.120805 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 262s 71.120824 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 262s 71.120826 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 262s 71.120967 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 262s 71.120987 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 262s 71.121000 | sde: serial = beaf11 262s 71.121003 | sde: detect_checker = yes (setting: multipath internal) 262s 71.121150 | sde: path_checker = tur (setting: multipath internal) 262s 71.121170 | sde: checker timeout = 30 s (setting: kernel sysfs) 262s 71.121271 | sde: tur state = up 262s 71.121375 | loop0: device node name blacklisted 262s 71.121473 | loop1: device node name blacklisted 262s 71.121570 | loop2: device node name blacklisted 262s 71.121666 | loop3: device node name blacklisted 262s 71.121762 | loop4: device node name blacklisted 262s 71.121857 | loop5: device node name blacklisted 262s 71.121952 | loop6: device node name blacklisted 262s 71.122046 | loop7: device node name blacklisted 262s 71.122147 | dm-0: device node name blacklisted 262s 71.123087 | multipath-tools v0.9.4 (12/19, 2022) 262s 71.123112 | libdevmapper version 1.02.185 262s 71.123256 | kernel device mapper v4.48.0 262s 71.123286 | DM multipath kernel driver v1.14.0 262s 71.123400 | sdb: size = 204800 262s 71.123421 | sdb: vendor = IET 262s 71.123424 | sdb: product = VIRTUAL-DISK 262s 71.123426 | sdb: rev = 0001 262s 71.124061 | sdb: h:b:t:l = 1:0:0:1 262s 71.124190 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 262s 71.124225 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 262s 71.124227 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 262s 71.124239 | sdb: serial = beaf11 262s 71.124345 | sdb: tur state = up 262s 71.124365 | sdb: uid = 360000000000000000e00000000010001 (udev) 262s 71.124368 | sdb: detect_prio = yes (setting: multipath internal) 262s 71.124372 | sdb: prio = const (setting: multipath internal) 262s 71.124374 | sdb: prio args = "" (setting: multipath internal) 262s 71.124376 | sdb: const prio = 1 262s 71.124397 | sdc: size = 204800 262s 71.124401 | sdc: vendor = IET 262s 71.124404 | sdc: product = VIRTUAL-DISK 262s 71.124407 | sdc: rev = 0001 262s 71.124992 | sdc: h:b:t:l = 2:0:0:1 262s 71.125114 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 262s 71.125149 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 262s 71.125152 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 262s 71.125163 | sdc: serial = beaf11 262s 71.125317 | sdc: tur state = up 262s 71.125337 | sdc: uid = 360000000000000000e00000000010001 (udev) 262s 71.125340 | sdc: detect_prio = yes (setting: multipath internal) 262s 71.125342 | sdc: prio = const (setting: multipath internal) 262s 71.125344 | sdc: prio args = "" (setting: multipath internal) 262s 71.125346 | sdc: const prio = 1 262s 71.125368 | sdd: size = 204800 262s 71.125372 | sdd: vendor = IET 262s 71.125375 | sdd: product = VIRTUAL-DISK 262s 71.125377 | sdd: rev = 0001 262s 71.125959 | sdd: h:b:t:l = 3:0:0:1 262s 71.126063 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 262s 71.126081 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 262s 71.126083 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 262s 71.126094 | sdd: serial = beaf11 262s 71.126248 | sdd: tur state = up 262s 71.126268 | sdd: uid = 360000000000000000e00000000010001 (udev) 262s 71.126270 | sdd: detect_prio = yes (setting: multipath internal) 262s 71.126273 | sdd: prio = const (setting: multipath internal) 262s 71.126275 | sdd: prio args = "" (setting: multipath internal) 262s 71.126277 | sdd: const prio = 1 262s 71.126299 | sde: size = 204800 262s 71.126303 | sde: vendor = IET 262s 71.126305 | sde: product = VIRTUAL-DISK 262s 71.126308 | sde: rev = 0001 262s 71.126891 | sde: h:b:t:l = 4:0:0:1 262s 71.127033 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 262s 71.127068 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 262s 71.127071 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 262s 71.127082 | sde: serial = beaf11 262s 71.127236 | sde: tur state = up 262s 71.127255 | sde: uid = 360000000000000000e00000000010001 (udev) 262s 71.127258 | sde: detect_prio = yes (setting: multipath internal) 262s 71.127260 | sde: prio = const (setting: multipath internal) 262s 71.127262 | sde: prio args = "" (setting: multipath internal) 262s 71.127264 | sde: const prio = 1 262s 71.128058 | unloading tur checker 262s 71.128103 | unloading const prioritizer 262s ===== paths list ===== 262s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 262s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 262s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 262s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 262s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 262s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 262s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 262s size=100M features='0' hwhandler='0' wp=rw 262s |-+- policy='service-time 0' prio=1 status=active 262s | `- 1:0:0:1 sdb 8:16 active ready running 262s |-+- policy='service-time 0' prio=1 status=enabled 262s | `- 2:0:0:1 sdc 8:32 active ready running 262s |-+- policy='service-time 0' prio=1 status=enabled 262s | `- 3:0:0:1 sdd 8:48 active ready running 262s `-+- policy='service-time 0' prio=1 status=enabled 262s `- 4:0:0:1 sde 8:64 active ready running 262s 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 262s Test WWN should now point to DM 262s ../../dm-0 262s Creating filesystem with 25600 4k blocks and 25600 inodes 262s 262s Allocating group tables: 0/1 done 262s Writing inode tables: 0/1 done 262s Creating journal (1024 blocks): done 262s Writing superblocks and filesystem accounting information: 0/1 + dmsetup table 262s + echo Test WWN should now point to DM 262s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 262s + grep dm 262s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 262s mke2fs 1.47.1 (20-May-2024) 262s done 262s 262s + udevadm settle 262s + sleep 3s 265s + mkdir -p /mnt/tgtmpathtest 265s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 265s + cat 265s + cat 265s + fio --max-jobs=4 /tmp/autopkgtest.9Vo1BJ/tgtbasedmpaths-artifacts/path-change-prep.fio 265s 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 265s fio-3.37 265s Starting 1 thread 265s write-phase: Laying out IO file (1 file / 17592186044415MiB) 266s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91750400, buflen=65536 266s 266s write-phase: (groupid=0, jobs=1): err= 0: pid=6422: Mon Jul 8 20:38:53 2024 266s write: IOPS=1760, BW=110MiB/s (115MB/s)(87.5MiB/796msec); 0 zone resets 266s clat (usec): min=316, max=2141, avg=547.92, stdev=166.03 266s lat (usec): min=331, max=2166, avg=566.46, stdev=167.30 266s clat percentiles (usec): 266s | 1.00th=[ 359], 5.00th=[ 367], 10.00th=[ 429], 20.00th=[ 461], 266s | 30.00th=[ 486], 40.00th=[ 502], 50.00th=[ 519], 60.00th=[ 553], 266s | 70.00th=[ 586], 80.00th=[ 611], 90.00th=[ 635], 95.00th=[ 652], 266s | 99.00th=[ 1401], 99.50th=[ 1598], 99.90th=[ 2057], 99.95th=[ 2147], 266s | 99.99th=[ 2147] 266s bw ( KiB/s): min=114816, max=114816, per=100.00%, avg=114816.00, stdev= 0.00, samples=1 266s iops : min= 1794, max= 1794, avg=1794.00, stdev= 0.00, samples=1 266s lat (usec) : 500=39.69%, 750=57.46%, 1000=0.21% 266s lat (msec) : 2=2.43%, 4=0.14% 266s cpu : usr=4.03%, sys=7.55%, ctx=1402, majf=0, minf=0 266s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 266s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 266s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 266s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 266s latency : target=0, window=0, percentile=100.00%, depth=1 266s 266s Run status group 0 (all jobs): 266s WRITE: bw=110MiB/s (115MB/s), 110MiB/s-110MiB/s (115MB/s-115MB/s), io=87.5MiB (91.8MB), run=796-796msec 266s 266s Disk stats (read/write): 266s dm-0: ios=1/1119, sectors=8/143232, merge=0/0, ticks=0/623, in_queue=623, util=86.49%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/182, aggrin_queue=182, aggrutil=85.87% 266s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 266s sdb: ios=1/1402, sectors=8/179280, merge=0/0, ticks=0/728, in_queue=728, util=85.87% 266s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 266s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 266s + echo Starting the path changes in background 266s Starting the path changes in background 266s + date +Pre FIO %H:%M:%S.%N 266s Pre FIO 20:38:53.552570027 266s + fio --max-jobs=4 /tmp/autopkgtest.9Vo1BJ/tgtbasedmpaths-artifacts/path-change-check.fio 266s 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 266s fio-3.37 266s Starting 1 thread 446s 446s verify-phase: (groupid=0, jobs=1): err= 0: pid=6429: Mon Jul 8 20:41:53 2024 446s read: IOPS=3101, BW=194MiB/s (203MB/s)(34.1GiB/180001msec) 446s clat (usec): min=80, max=115504, avg=299.08, stdev=495.71 446s lat (usec): min=80, max=115504, avg=299.18, stdev=495.71 446s clat percentiles (usec): 446s | 1.00th=[ 133], 5.00th=[ 153], 10.00th=[ 176], 20.00th=[ 194], 446s | 30.00th=[ 208], 40.00th=[ 235], 50.00th=[ 273], 60.00th=[ 310], 446s | 70.00th=[ 347], 80.00th=[ 379], 90.00th=[ 429], 95.00th=[ 465], 446s | 99.00th=[ 955], 99.50th=[ 1188], 99.90th=[ 1663], 99.95th=[ 2180], 446s | 99.99th=[ 5276] 446s bw ( KiB/s): min=114432, max=344832, per=100.00%, avg=198569.66, stdev=54858.12, samples=359 446s iops : min= 1788, max= 5388, avg=3102.63, stdev=857.15, samples=359 446s lat (usec) : 100=0.39%, 250=44.25%, 500=53.37%, 750=0.66%, 1000=0.43% 446s lat (msec) : 2=0.83%, 4=0.05%, 10=0.01%, 20=0.01%, 50=0.01% 446s lat (msec) : 100=0.01%, 250=0.01% 446s cpu : usr=8.81%, sys=6.97%, ctx=558395, 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=558301,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=194MiB/s (203MB/s), 194MiB/s-194MiB/s (203MB/s-203MB/s), io=34.1GiB (36.6GB), run=180001-180001msec 446s 446s Disk stats (read/write): 446s dm-0: ios=557677/10, sectors=71331512/12928, merge=33/9, ticks=172420/84, in_queue=172561, util=99.85%, aggrios=36686/2, aggsectors=4692430/3232, aggrmerge=0/0, aggrticks=10975/6, aggrin_queue=10981, aggrutil=99.15% 446s sdd: ios=28095/0, sectors=3593600/0, merge=0/0, ticks=8727/0, in_queue=8727, util=33.09% 446s sdb: ios=27818/9, sectors=3558016/12928, merge=0/0, ticks=8643/26, in_queue=8669, util=99.15% 446s sde: ios=59628/0, sectors=7627008/0, merge=0/0, ticks=17653/0, in_queue=17653, util=39.79% 446s sdc: ios=31204/0, sectors=3991096/0, merge=0/0, ticks=8877/0, in_queue=8878, util=50.18% 446s Post FIO 20:41:53.770084234 446s FIO verify test with changing paths - OK 446s Report log of background activity 446s + date +Post FIO %H:%M:%S.%N 446s + echo FIO verify test with changing paths - OK 446s + echo Report log of background activity 446s + cat /tmp/autopkgtest.9Vo1BJ/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) 20:39:03.561808526 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 20:39:03.587512223 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) 20:39:13.686286644 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 20:39:13.715272373 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) 20:39:23.812794119 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 20:39:23.834620750 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) 20:39:33.929024732 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 20:39:33.943285725 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) 20:39:44.055352173 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 20:39:44.088592450 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 20:39:54.366399539 446s + systemctl restart multipathd 446s + sleep 10s 446s + date +Final background report (expect 2) %H:%M:%S.%N 446s Final background report (expect 2) 20:40:04.443216706 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: 19710504 446s rxdata_octets: 26888279700 446s noptx_pdus: 0 446s scsicmd_pdus: 410368 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: 410368 446s tmfrsp_pdus: 0 446s textrsp_pdus: 0 446s datain_pdus: 410335 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 Jul 08 12:30:42 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 446s Jul 08 12:30:42 ubuntu multipathd[328]: multipathd v0.9.4: start up 446s Jul 08 12:30:42 ubuntu multipathd[328]: reconfigure: setting up paths and maps 446s Jul 08 12:30:42 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 446s Jul 08 12:34:37 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[328]: multipathd: shut down 446s Jul 08 12:34:37 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 446s Jul 08 12:34:37 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: multipathd.service: Deactivated successfully. 446s Jul 08 12:34:37 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 446s -- Boot 10706fb342864abc806160f8524dd11c -- 446s Jul 08 12:35:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[265]: multipathd v0.9.4: start up 446s Jul 08 12:35:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[265]: reconfigure: setting up paths and maps 446s Jul 08 12:35:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 446s Jul 08 12:35:24 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[265]: multipathd: shut down 446s Jul 08 12:35:24 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 446s Jul 08 12:35:24 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: multipathd.service: Deactivated successfully. 446s Jul 08 12:35:24 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 446s -- Boot 67783f4a65dc4484bc3c27d32d210d62 -- 446s Jul 08 20:37:41 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[325]: multipathd v0.9.4: start up 446s Jul 08 20:37:41 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[325]: reconfigure: setting up paths and maps 446s Jul 08 20:37:41 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 446s Jul 08 20:38:44 autopkgtest multipathd[325]: 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 Jul 08 20:38:44 autopkgtest multipathd[325]: sdc [8:32]: path added to devmap mpatha 446s Jul 08 20:38:44 autopkgtest multipathd[325]: mpatha: performing delayed actions 446s Jul 08 20:38:44 autopkgtest multipathd[325]: 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 Jul 08 20:39:03 autopkgtest multipathd[325]: 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 Jul 08 20:39:03 autopkgtest multipathd[325]: check_removed_paths: sdb: freeing path in removed state 446s Jul 08 20:39:03 autopkgtest multipathd[325]: 8:16: path removed from map mpatha 446s Jul 08 20:39:13 autopkgtest multipathd[325]: 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 Jul 08 20:39:13 autopkgtest multipathd[325]: check_removed_paths: sdc: freeing path in removed state 446s Jul 08 20:39:13 autopkgtest multipathd[325]: 8:32: path removed from map mpatha 446s Jul 08 20:39:23 autopkgtest multipathd[325]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 446s Jul 08 20:39:23 autopkgtest multipathd[325]: check_removed_paths: sdd: freeing path in removed state 446s Jul 08 20:39:23 autopkgtest multipathd[325]: 8:48: path removed from map mpatha 446s Jul 08 20:39:34 autopkgtest multipathd[325]: 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 Jul 08 20:39:34 autopkgtest multipathd[325]: sdb [8:16]: path added to devmap mpatha 446s Jul 08 20:39:34 autopkgtest multipathd[325]: 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 Jul 08 20:39:34 autopkgtest multipathd[325]: sdc [8:32]: path added to devmap mpatha 446s Jul 08 20:39:34 autopkgtest multipathd[325]: 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 Jul 08 20:39:34 autopkgtest multipathd[325]: sdd [8:48]: path added to devmap mpatha 446s Jul 08 20:39:34 autopkgtest multipathd[325]: 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 Jul 08 20:39:34 autopkgtest multipathd[325]: sdf [8:80]: path added to devmap mpatha 446s Jul 08 20:39:44 autopkgtest multipathd[325]: 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 Jul 08 20:39:44 autopkgtest multipathd[325]: check_removed_paths: sde: freeing path in removed state 446s Jul 08 20:39:44 autopkgtest multipathd[325]: 8:64: path removed from map mpatha 446s Jul 08 20:39:44 autopkgtest multipathd[325]: 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 Jul 08 20:39:44 autopkgtest multipathd[325]: check_removed_paths: sdd: freeing path in removed state 446s Jul 08 20:39:44 autopkgtest multipathd[325]: 8:48: path removed from map mpatha 446s Jul 08 20:39:44 autopkgtest multipathd[325]: 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 Jul 08 20:39:44 autopkgtest multipathd[325]: check_removed_paths: sdf: freeing path in removed state 446s Jul 08 20:39:44 autopkgtest multipathd[325]: 8:80: path removed from map mpatha 446s Jul 08 20:39:54 autopkgtest multipathd[325]: multipathd: shut down 446s Jul 08 20:39:54 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 446s Jul 08 20:39:54 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 446s Jul 08 20:39:54 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 446s Jul 08 20:39:54 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 446s Jul 08 20:39:54 autopkgtest multipathd[6782]: multipathd v0.9.4: start up 446s Jul 08 20:39:54 autopkgtest multipathd[6782]: reconfigure: setting up paths and maps 446s Jul 08 20:39:54 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 + 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 + echo Check final path status 446s + multipath -ll 446s + multipath -ll 446s + grep --count status= 446s + diskc=2 446s + multipath -ll 446s + grep --count status=active 446s + diska=1 446s + multipath -ll 446s + grep --count status=enabled 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 OK 447s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 447s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 447s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 447s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 447s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 447s autopkgtest [20:41:54]: test tgtbasedmpaths: -----------------------] 447s tgtbasedmpaths PASS 447s autopkgtest [20:41:54]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 448s autopkgtest [20:41:55]: @@@@@@@@@@@@@@@@@@@@ summary 448s kpartx-file-loopback PASS 448s tgtbasedmpaths PASS 458s nova [W] Using flock in scalingstack-bos02-ppc64el 458s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240708-203427-juju-7f2275-prod-proposed-migration-environment-2-9a82822f-03aa-4519-ad49-b0997074a47d from image adt/ubuntu-oracular-ppc64el-server-20240708.img (UUID 3cbc90a1-cf8b-4b9d-b59e-48e0e7e6e511)... 458s nova [W] Using flock in scalingstack-bos02-ppc64el 458s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240708-203427-juju-7f2275-prod-proposed-migration-environment-2-9a82822f-03aa-4519-ad49-b0997074a47d from image adt/ubuntu-oracular-ppc64el-server-20240708.img (UUID 3cbc90a1-cf8b-4b9d-b59e-48e0e7e6e511)...