0s autopkgtest [20:25:26]: starting date and time: 2024-06-14 20:25:26+0000 0s autopkgtest [20:25:26]: git checkout: 433ed4cb Merge branch 'skia/nova_flock' into 'ubuntu/5.34+prod' 0s autopkgtest [20:25:26]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.673oym0d/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:tgt --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=tgt/1:1.0.85-1.2ubuntu1 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos02-ppc64el-10.secgroup --name adt-oracular-ppc64el-multipath-tools-20240614-202526-juju-7f2275-prod-proposed-migration-environment-3-94c0cf50-4bc7-4ac2-8505-ec464deefa3e --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 158s autopkgtest [20:28:04]: testbed dpkg architecture: ppc64el 158s autopkgtest [20:28:04]: testbed apt version: 2.9.3 158s autopkgtest [20:28:04]: @@@@@@@@@@@@@@@@@@@@ test bed setup 159s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 159s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [355 kB] 160s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7052 B] 160s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.9 kB] 160s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 160s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [50.3 kB] 160s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1860 B] 160s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [316 kB] 160s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [2532 B] 160s Fetched 885 kB in 1s (1239 kB/s) 160s Reading package lists... 162s Reading package lists... 162s Building dependency tree... 162s Reading state information... 162s Calculating upgrade... 162s The following packages will be upgraded: 162s fwupd libdrm-common libdrm2 libfwupd2 162s 4 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 162s Need to get 4844 kB of archives. 162s After this operation, 2048 B of additional disk space will be used. 162s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdrm-common all 2.4.121-2 [8330 B] 163s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdrm2 ppc64el 2.4.121-2 [49.3 kB] 163s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libfwupd2 ppc64el 1.9.21-1 [137 kB] 163s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el fwupd ppc64el 1.9.21-1 [4650 kB] 164s Fetched 4844 kB in 1s (4621 kB/s) 164s (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 ... 72665 files and directories currently installed.) 164s Preparing to unpack .../libdrm-common_2.4.121-2_all.deb ... 164s Unpacking libdrm-common (2.4.121-2) over (2.4.120-2build1) ... 164s Preparing to unpack .../libdrm2_2.4.121-2_ppc64el.deb ... 164s Unpacking libdrm2:ppc64el (2.4.121-2) over (2.4.120-2build1) ... 164s Preparing to unpack .../libfwupd2_1.9.21-1_ppc64el.deb ... 164s Unpacking libfwupd2:ppc64el (1.9.21-1) over (1.9.20-1) ... 164s Preparing to unpack .../fwupd_1.9.21-1_ppc64el.deb ... 164s Unpacking fwupd (1.9.21-1) over (1.9.20-1) ... 164s Setting up libfwupd2:ppc64el (1.9.21-1) ... 164s Setting up libdrm-common (2.4.121-2) ... 164s Setting up fwupd (1.9.21-1) ... 165s fwupd-offline-update.service is a disabled or a static unit not running, not starting it. 165s fwupd-refresh.service is a disabled or a static unit not running, not starting it. 165s fwupd.service is a disabled or a static unit not running, not starting it. 165s Setting up libdrm2:ppc64el (2.4.121-2) ... 165s Processing triggers for man-db (2.12.1-2) ... 166s Processing triggers for dbus (1.14.10-4ubuntu4) ... 166s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 166s Reading package lists... 166s Building dependency tree... 166s Reading state information... 166s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 166s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 166s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 167s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 167s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 167s Reading package lists... 167s Reading package lists... 168s Building dependency tree... 168s Reading state information... 168s Calculating upgrade... 168s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 168s Reading package lists... 168s Building dependency tree... 168s Reading state information... 168s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 168s autopkgtest [20:28:14]: rebooting testbed after setup commands that affected boot 202s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 213s autopkgtest [20:28:59]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 216s autopkgtest [20:29:02]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 219s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 219s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 219s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 220s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 220s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 220s gpgv: issuer "steve.langasek@ubuntu.com" 220s gpgv: Can't check signature: No public key 220s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 220s autopkgtest [20:29:06]: testing package multipath-tools version 0.9.4-5ubuntu8 220s autopkgtest [20:29:06]: build not needed 221s autopkgtest [20:29:07]: test kpartx-file-loopback: preparing testbed 222s Reading package lists... 222s Building dependency tree... 222s Reading state information... 222s Starting pkgProblemResolver with broken count: 0 222s Starting 2 pkgProblemResolver with broken count: 0 222s Done 223s The following additional packages will be installed: 223s liburing2 qemu-utils 223s Recommended packages: 223s qemu-block-extra 223s The following NEW packages will be installed: 223s autopkgtest-satdep liburing2 qemu-utils 223s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 223s Need to get 2330 kB/2331 kB of archives. 223s After this operation, 15.4 MB of additional disk space will be used. 223s Get:1 /tmp/autopkgtest.eLbDPj/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 223s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 223s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 224s Fetched 2330 kB in 1s (1758 kB/s) 224s Selecting previously unselected package liburing2:ppc64el. 224s (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 ... 72665 files and directories currently installed.) 224s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 224s Unpacking liburing2:ppc64el (2.6-1) ... 224s Selecting previously unselected package qemu-utils. 224s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 224s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 224s Selecting previously unselected package autopkgtest-satdep. 224s Preparing to unpack .../1-autopkgtest-satdep.deb ... 224s Unpacking autopkgtest-satdep (0) ... 225s Setting up liburing2:ppc64el (2.6-1) ... 225s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 225s Setting up autopkgtest-satdep (0) ... 225s Processing triggers for man-db (2.12.1-2) ... 225s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 227s (Reading database ... 72685 files and directories currently installed.) 227s Removing autopkgtest-satdep (0) ... 228s autopkgtest [20:29:14]: test kpartx-file-loopback: [----------------------- 228s Formatting 'foo.img', fmt=raw size=20971520 229s Creating new GPT entries in memory. 229s Warning: The kernel is still using the old partition table. 229s The new table will be used at the next reboot or after you 229s run partprobe(8) or kpartx(8) 229s The operation has completed successfully. 229s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 229s standard_filename: OK 229s del devmap : loop0p1 229s No devices found 229s standard_filename_cleanup: OK 229s Formatting 'fou du FaFa.img', fmt=raw size=20971520 230s Creating new GPT entries in memory. 230s Warning: The kernel is still using the old partition table. 230s The new table will be used at the next reboot or after you 230s run partprobe(8) or kpartx(8) 230s The operation has completed successfully. 230s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 230s filename_with_spaces: OK 230s del devmap : loop0p1 230s No devices found 230s filename_with_spaces_cleanup: OK 231s autopkgtest [20:29:17]: test kpartx-file-loopback: -----------------------] 231s kpartx-file-loopback PASS 231s autopkgtest [20:29:17]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 232s autopkgtest [20:29:18]: test tgtbasedmpaths: preparing testbed 360s autopkgtest [20:31:26]: testbed dpkg architecture: ppc64el 360s autopkgtest [20:31:26]: testbed apt version: 2.9.3 360s autopkgtest [20:31:26]: @@@@@@@@@@@@@@@@@@@@ test bed setup 361s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 361s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7052 B] 361s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [355 kB] 362s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 362s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.9 kB] 362s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [50.3 kB] 362s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1860 B] 362s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [316 kB] 362s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [2532 B] 362s Fetched 885 kB in 1s (998 kB/s) 362s Reading package lists... 364s Reading package lists... 364s Building dependency tree... 364s Reading state information... 364s Calculating upgrade... 365s The following packages will be upgraded: 365s fwupd libdrm-common libdrm2 libfwupd2 365s 4 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 365s Need to get 4844 kB of archives. 365s After this operation, 2048 B of additional disk space will be used. 365s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdrm-common all 2.4.121-2 [8330 B] 365s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdrm2 ppc64el 2.4.121-2 [49.3 kB] 365s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libfwupd2 ppc64el 1.9.21-1 [137 kB] 365s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el fwupd ppc64el 1.9.21-1 [4650 kB] 367s Fetched 4844 kB in 2s (2270 kB/s) 367s (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 ... 72665 files and directories currently installed.) 367s Preparing to unpack .../libdrm-common_2.4.121-2_all.deb ... 367s Unpacking libdrm-common (2.4.121-2) over (2.4.120-2build1) ... 367s Preparing to unpack .../libdrm2_2.4.121-2_ppc64el.deb ... 367s Unpacking libdrm2:ppc64el (2.4.121-2) over (2.4.120-2build1) ... 367s Preparing to unpack .../libfwupd2_1.9.21-1_ppc64el.deb ... 367s Unpacking libfwupd2:ppc64el (1.9.21-1) over (1.9.20-1) ... 367s Preparing to unpack .../fwupd_1.9.21-1_ppc64el.deb ... 367s Unpacking fwupd (1.9.21-1) over (1.9.20-1) ... 368s Setting up libfwupd2:ppc64el (1.9.21-1) ... 368s Setting up libdrm-common (2.4.121-2) ... 368s Setting up fwupd (1.9.21-1) ... 368s fwupd-offline-update.service is a disabled or a static unit not running, not starting it. 368s fwupd-refresh.service is a disabled or a static unit not running, not starting it. 368s fwupd.service is a disabled or a static unit not running, not starting it. 368s Setting up libdrm2:ppc64el (2.4.121-2) ... 368s Processing triggers for man-db (2.12.1-2) ... 369s Processing triggers for dbus (1.14.10-4ubuntu4) ... 369s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 369s Reading package lists... 369s Building dependency tree... 369s Reading state information... 370s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 370s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 370s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 370s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 370s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 371s Reading package lists... 371s Reading package lists... 371s Building dependency tree... 371s Reading state information... 372s Calculating upgrade... 372s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 372s Reading package lists... 372s Building dependency tree... 372s Reading state information... 372s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 372s autopkgtest [20:31:38]: rebooting testbed after setup commands that affected boot 376s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 409s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 422s Reading package lists... 423s Building dependency tree... 423s Reading state information... 423s Starting pkgProblemResolver with broken count: 0 423s Starting 2 pkgProblemResolver with broken count: 0 423s Done 423s The following additional packages will be installed: 423s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 423s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 423s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 423s librdmacm1t64 lsscsi open-iscsi tgt 423s Suggested packages: 423s fio-examples gnuplot tgt-glusterfs tgt-rbd 423s Recommended packages: 423s finalrd 423s The following NEW packages will be installed: 423s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 423s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 423s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 423s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 423s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 423s Need to get 10.7 MB/10.7 MB of archives. 423s After this operation, 49.0 MB of additional disk space will be used. 423s Get:1 /tmp/autopkgtest.eLbDPj/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 423s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu4 [54.4 kB] 424s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 424s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu4 [389 kB] 424s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 424s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 424s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 424s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4ubuntu1 [21.5 kB] 424s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4ubuntu1 [311 kB] 424s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4ubuntu1 [46.5 kB] 424s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4ubuntu1 [99.2 kB] 424s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.1-1 [97.4 kB] 424s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 424s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 424s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 424s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 424s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 424s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 425s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 425s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 426s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 426s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 426s Preconfiguring packages ... 426s Fetched 10.7 MB in 2s (4452 kB/s) 426s Selecting previously unselected package libopeniscsiusr. 426s (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 ... 72665 files and directories currently installed.) 426s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu4_ppc64el.deb ... 426s Unpacking libopeniscsiusr (2.1.9-3ubuntu4) ... 426s Selecting previously unselected package libisns0t64:ppc64el. 426s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 426s Unpacking libisns0t64:ppc64el (0.101-1) ... 426s Selecting previously unselected package open-iscsi. 426s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu4_ppc64el.deb ... 426s Unpacking open-iscsi (2.1.9-3ubuntu4) ... 426s Selecting previously unselected package librdmacm1t64:ppc64el. 426s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 426s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 426s Selecting previously unselected package libconfig-general-perl. 426s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 426s Unpacking libconfig-general-perl (2.65-2) ... 426s Selecting previously unselected package tgt. 426s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 426s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 426s Selecting previously unselected package libgfxdr0:ppc64el. 426s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_ppc64el.deb ... 426s Unpacking libgfxdr0:ppc64el (11.1-4ubuntu1) ... 426s Selecting previously unselected package libglusterfs0:ppc64el. 426s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_ppc64el.deb ... 426s Unpacking libglusterfs0:ppc64el (11.1-4ubuntu1) ... 426s Selecting previously unselected package libgfrpc0:ppc64el. 426s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_ppc64el.deb ... 426s Unpacking libgfrpc0:ppc64el (11.1-4ubuntu1) ... 426s Selecting previously unselected package libgfapi0:ppc64el. 426s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_ppc64el.deb ... 426s Unpacking libgfapi0:ppc64el (11.1-4ubuntu1) ... 426s Selecting previously unselected package libnbd0. 426s Preparing to unpack .../10-libnbd0_1.20.1-1_ppc64el.deb ... 426s Unpacking libnbd0 (1.20.1-1) ... 426s Selecting previously unselected package libdaxctl1:ppc64el. 426s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 426s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 427s Selecting previously unselected package libndctl6:ppc64el. 427s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 427s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 427s Selecting previously unselected package libpmem1:ppc64el. 427s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 427s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 427s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 427s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 427s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 427s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 427s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 427s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 427s Selecting previously unselected package librados2. 427s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 427s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 427s Selecting previously unselected package libpmemobj1:ppc64el. 427s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 427s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 427s Selecting previously unselected package librbd1. 427s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 427s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 427s Selecting previously unselected package fio. 427s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 427s Unpacking fio (3.37-1) ... 427s Selecting previously unselected package lsscsi. 427s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 427s Unpacking lsscsi (0.32-1build1) ... 427s Selecting previously unselected package autopkgtest-satdep. 427s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 427s Unpacking autopkgtest-satdep (0) ... 427s Setting up libconfig-general-perl (2.65-2) ... 427s Setting up libisns0t64:ppc64el (0.101-1) ... 427s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 427s Setting up libnbd0 (1.20.1-1) ... 427s Setting up libopeniscsiusr (2.1.9-3ubuntu4) ... 427s Setting up libglusterfs0:ppc64el (11.1-4ubuntu1) ... 427s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 427s Setting up lsscsi (0.32-1build1) ... 427s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 427s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 427s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 427s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 427s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 428s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 428s Setting up libgfxdr0:ppc64el (11.1-4ubuntu1) ... 428s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 428s Setting up open-iscsi (2.1.9-3ubuntu4) ... 429s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 429s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 429s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 429s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 429s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 429s Setting up libgfrpc0:ppc64el (11.1-4ubuntu1) ... 429s Setting up libgfapi0:ppc64el (11.1-4ubuntu1) ... 429s Setting up fio (3.37-1) ... 430s Setting up autopkgtest-satdep (0) ... 430s Processing triggers for man-db (2.12.1-2) ... 431s Processing triggers for initramfs-tools (0.142ubuntu28) ... 431s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 431s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 438s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 441s (Reading database ... 72906 files and directories currently installed.) 441s Removing autopkgtest-satdep (0) ... 445s autopkgtest [20:32:51]: test tgtbasedmpaths: [----------------------- 445s + targetname=iqn.2016-11.foo.com:target.iscsi 445s + pwd 445s + cwd=/tmp/autopkgtest.eLbDPj/build.KpB/src 445s + testdir=/mnt/tgtmpathtest 445s + localhost=127.0.0.1 445s + portal=127.0.0.1:3260 445s + maxpaths=4 445s + backfn=backingfile 445s + expectwwid=60000000000000000e00000000010001 445s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 445s + bglog=/tmp/autopkgtest.eLbDPj/tgtbasedmpaths-artifacts/test-background.log 445s + fioprep=/tmp/autopkgtest.eLbDPj/tgtbasedmpaths-artifacts/path-change-prep.fio 445s + fiovrfy=/tmp/autopkgtest.eLbDPj/tgtbasedmpaths-artifacts/path-change-check.fio 445s + service tgt restart 445s + truncate --size 100M backingfile 445s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 445s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 445s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.eLbDPj/build.KpB/src/backingfile 445s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 445s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 445s login #1 445s + echo login #1 445s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 445s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 445s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 445s + seq 2 4 445s + echo extra login #2 445s + iscsiadm --mode session -r 1 --op new 445s extra login #2 445s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 445s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 445s extra login #3 445s + echo extra login #3 445s + iscsiadm --mode session -r 1 --op new 445s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 445s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 445s + echo extra login #4 445s + iscsiadm --mode session -r 1 --op new 445s extra login #4 445s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 445s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 445s + udevadm settle 446s + sleep 5 450s Status after initial setup 450s + echo Status after initial setup 450s + tgtadm --lld iscsi --mode target --op show 450s Target 1: iqn.2016-11.foo.com:target.iscsi 450s System information: 450s Driver: iscsi 450s State: ready 450s I_T nexus information: 450s I_T nexus: 1 450s Initiator: iqn.2004-10.com.ubuntu:01:2aa07f284eca alias: autopkgtest 450s Connection: 0 450s IP Address: 127.0.0.1 450s I_T nexus: 2 450s Initiator: iqn.2004-10.com.ubuntu:01:2aa07f284eca alias: autopkgtest 450s Connection: 0 450s IP Address: 127.0.0.1 450s I_T nexus: 3 450s Initiator: iqn.2004-10.com.ubuntu:01:2aa07f284eca alias: autopkgtest 450s Connection: 0 450s IP Address: 127.0.0.1 450s I_T nexus: 4 450s Initiator: iqn.2004-10.com.ubuntu:01:2aa07f284eca alias: autopkgtest 450s Connection: 0 450s IP Address: 127.0.0.1 450s LUN information: 450s LUN: 0 450s Type: controller 450s SCSI ID: IET 00010000 450s SCSI SN: beaf10 450s Size: 0 MB, Block size: 1 450s Online: Yes 450s Removable media: No 450s Prevent removal: No 450s Readonly: No 450s SWP: No 450s Thin-provisioning: No 450s Backing store type: null 450s Backing store path: None 450s Backing store flags: 450s LUN: 1 450s Type: disk 450s SCSI ID: IET 00010001 450s SCSI SN: beaf11 450s Size: 105 MB, Block size: 512 450s Online: Yes 450s Removable media: No 450s Prevent removal: No 450s Readonly: No 450s SWP: No 450s Thin-provisioning: No 450s Backing store type: rdwr 450s Backing store path: /tmp/autopkgtest.eLbDPj/build.KpB/src/backingfile 450s Backing store flags: 450s Account information: 450s ACL information: 450s ALL 450s + tgtadm --lld iscsi --op show --mode conn --tid 1 450s Session: 4 450s Connection: 0 450s Initiator: iqn.2004-10.com.ubuntu:01:2aa07f284eca 450s IP Address: 127.0.0.1 450s Session: 3 450s Connection: 0 450s Initiator: iqn.2004-10.com.ubuntu:01:2aa07f284eca 450s IP Address: 127.0.0.1 450s Session: 2 450s Connection: 0 450s Initiator: iqn.2004-10.com.ubuntu:01:2aa07f284eca 450s IP Address: 127.0.0.1 450s Session: 1 450s Connection: 0 450s Initiator: iqn.2004-10.com.ubuntu:01:2aa07f284eca 450s IP Address: 127.0.0.1 450s + iscsiadm --mode session -P 1 451s + lsscsi -liv 451s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 451s Current Portal: 127.0.0.1:3260,1 451s Persistent Portal: 127.0.0.1:3260,1 451s ********** 451s Interface: 451s ********** 451s Iface Name: default 451s Iface Transport: tcp 451s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:2aa07f284eca 451s Iface IPaddress: 127.0.0.1 451s Iface HWaddress: default 451s Iface Netdev: default 451s SID: 1 451s iSCSI Connection State: LOGGED IN 451s iSCSI Session State: LOGGED_IN 451s Internal iscsid Session State: NO CHANGE 451s 451s ********** 451s Interface: 451s ********** 451s Iface Name: default 451s Iface Transport: tcp 451s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:2aa07f284eca 451s Iface IPaddress: 127.0.0.1 451s Iface HWaddress: default 451s Iface Netdev: default 451s SID: 2 451s iSCSI Connection State: LOGGED IN 451s iSCSI Session State: LOGGED_IN 451s Internal iscsid Session State: NO CHANGE 451s 451s ********** 451s Interface: 451s ********** 451s Iface Name: default 451s Iface Transport: tcp 451s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:2aa07f284eca 451s Iface IPaddress: 127.0.0.1 451s Iface HWaddress: default 451s Iface Netdev: default 451s SID: 3 451s iSCSI Connection State: LOGGED IN 451s iSCSI Session State: LOGGED_IN 451s Internal iscsid Session State: NO CHANGE 451s 451s ********** 451s Interface: 451s ********** 451s Iface Name: default 451s Iface Transport: tcp 451s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:2aa07f284eca 451s Iface IPaddress: 127.0.0.1 451s Iface HWaddress: default 451s Iface Netdev: default 451s SID: 4 451s iSCSI Connection State: LOGGED IN 451s iSCSI Session State: LOGGED_IN 451s Internal iscsid Session State: NO CHANGE 451s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 451s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 451s 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] 451s [1:0:0:0] storage IET Controller 0001 - - 451s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 451s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 451s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 451s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 451s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 451s [2:0:0:0] storage IET Controller 0001 - - 451s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 451s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 451s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 451s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 451s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 451s [3:0:0:0] storage IET Controller 0001 - - 451s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 451s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 451s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 451s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 451s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 451s [4:0:0:0] storage IET Controller 0001 - - 451s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 451s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 451s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 451s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 451s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 451s NVMe module may not be loaded 451s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 451s + multipath -v3 -ll 451s 53.799880 | set open fds limit to 1048576/1048576 451s 53.800073 | loading /lib/multipath/libchecktur.so checker 451s 53.800238 | checker tur: message table size = 3 451s 53.800276 | loading /lib/multipath/libprioconst.so prioritizer 451s 53.800436 | _init_foreign: foreign library "nvme" is not enabled 451s 53.807541 | sda: size = 167772160 451s 53.807708 | sda: vendor = QEMU 451s 53.807752 | sda: product = QEMU HARDDISK 451s 53.807775 | sda: rev = 2.5+ 451s 53.808415 | sda: h:b:t:l = 0:0:0:0 451s 53.808728 | sda: tgt_node_name = 451s 53.808751 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 451s 53.808754 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 451s 53.808909 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 451s 53.808932 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 451s 53.808945 | __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 451s 53.808950 | failed to read sysfs vpd pg80: No such file or directory 451s 53.809233 | sda: fail to get serial 451s 53.809256 | sda: detect_checker = yes (setting: multipath internal) 451s 53.810156 | sda: path_checker = tur (setting: multipath internal) 451s 53.810180 | sda: checker timeout = 30 s (setting: kernel sysfs) 451s 53.811039 | sda: tur state = up 451s 53.811328 | sdb: size = 204800 451s 53.811475 | sdb: vendor = IET 451s 53.811516 | sdb: product = VIRTUAL-DISK 451s 53.811537 | sdb: rev = 0001 451s 53.812199 | sdb: h:b:t:l = 1:0:0:1 451s 53.812571 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 451s 53.812594 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 451s 53.812596 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 451s 53.812750 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 451s 53.812774 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 451s 53.812789 | sdb: serial = beaf11 451s 53.812792 | sdb: detect_checker = yes (setting: multipath internal) 451s 53.813231 | sdb: path_checker = tur (setting: multipath internal) 451s 53.813236 | sdb: checker timeout = 30 s (setting: kernel sysfs) 451s 53.813441 | sdb: tur state = up 451s 53.813565 | sdc: size = 204800 451s 53.813694 | sdc: vendor = IET 451s 53.813738 | sdc: product = VIRTUAL-DISK 451s 53.813760 | sdc: rev = 0001 451s 53.814446 | sdc: h:b:t:l = 2:0:0:1 451s 53.814799 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 451s 53.814822 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 451s 53.814824 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 451s 53.814976 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 451s 53.814999 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 451s 53.815013 | sdc: serial = beaf11 451s 53.815016 | sdc: detect_checker = yes (setting: multipath internal) 451s 53.815276 | sdc: path_checker = tur (setting: multipath internal) 451s 53.815280 | sdc: checker timeout = 30 s (setting: kernel sysfs) 451s 53.815472 | sdc: tur state = up 451s 53.815601 | sdd: size = 204800 451s 53.815726 | sdd: vendor = IET 451s 53.815747 | sdd: product = VIRTUAL-DISK 451s 53.815768 | sdd: rev = 0001 451s 53.816452 | sdd: h:b:t:l = 3:0:0:1 451s 53.816814 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 451s 53.816836 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 451s 53.816839 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 451s 53.816986 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 451s 53.817009 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 451s 53.817023 | sdd: serial = beaf11 451s 53.817025 | sdd: detect_checker = yes (setting: multipath internal) 451s 53.817290 | sdd: path_checker = tur (setting: multipath internal) 451s 53.817294 | sdd: checker timeout = 30 s (setting: kernel sysfs) 451s 53.817486 | sdd: tur state = up 451s 53.817613 | sde: size = 204800 451s 53.817738 | sde: vendor = IET 451s 53.817759 | sde: product = VIRTUAL-DISK 451s 53.817781 | sde: rev = 0001 451s 53.818464 | sde: h:b:t:l = 4:0:0:1 451s 53.818820 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 451s 53.818843 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 451s 53.818845 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 451s 53.818999 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 451s 53.819022 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 451s 53.819035 | sde: serial = beaf11 451s 53.819038 | sde: detect_checker = yes (setting: multipath internal) 451s 53.819240 | sde: path_checker = tur (setting: multipath internal) 451s 53.819244 | sde: checker timeout = 30 s (setting: kernel sysfs) 451s 53.819370 | sde: tur state = up 451s 53.819463 | loop0: device node name blacklisted 451s 53.819547 | loop1: device node name blacklisted 451s 53.819628 | loop2: device node name blacklisted 451s 53.819707 | loop3: device node name blacklisted 451s 53.819788 | loop4: device node name blacklisted 451s 53.819867 | loop5: device node name blacklisted 451s 53.819969 | loop6: device node name blacklisted 451s 53.820115 | loop7: device node name blacklisted 451s 53.820232 | dm-0: device node name blacklisted 451s 53.821200 | multipath-tools v0.9.4 (12/19, 2022) 451s 53.821230 | libdevmapper version 1.02.185 451s 53.821384 | kernel device mapper v4.48.0 451s 53.821416 | DM multipath kernel driver v1.14.0 451s 53.821537 | sdb: size = 204800 451s 53.821560 | sdb: vendor = IET 451s 53.821563 | sdb: product = VIRTUAL-DISK 451s 53.821565 | sdb: rev = 0001 451s 53.822224 | sdb: h:b:t:l = 1:0:0:1 451s 53.822357 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 451s 53.822398 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 451s 53.822401 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 451s 53.822413 | sdb: serial = beaf11 451s 53.822641 | sdb: tur state = up 451s 53.822665 | sdb: uid = 360000000000000000e00000000010001 (udev) 451s 53.822668 | sdb: detect_prio = yes (setting: multipath internal) 451s 53.822671 | sdb: prio = const (setting: multipath internal) 451s 53.822673 | sdb: prio args = "" (setting: multipath internal) 451s 53.822676 | sdb: const prio = 1 451s 53.822701 | sdc: size = 204800 451s 53.822705 | sdc: vendor = IET 451s 53.822710 | sdc: product = VIRTUAL-DISK 451s 53.822712 | sdc: rev = 0001 451s 53.823348 | sdc: h:b:t:l = 2:0:0:1 451s 53.823477 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 451s 53.823517 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 451s 53.823520 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 451s 53.823531 | sdc: serial = beaf11 451s 53.823727 | sdc: tur state = up 451s 53.823750 | sdc: uid = 360000000000000000e00000000010001 (udev) 451s 53.823752 | sdc: detect_prio = yes (setting: multipath internal) 451s 53.823755 | sdc: prio = const (setting: multipath internal) 451s 53.823757 | sdc: prio args = "" (setting: multipath internal) 451s 53.823759 | sdc: const prio = 1 451s 53.823782 | sdd: size = 204800 451s 53.823786 | sdd: vendor = IET 451s 53.823788 | sdd: product = VIRTUAL-DISK 451s 53.823791 | sdd: rev = 0001 451s 53.824439 | sdd: h:b:t:l = 3:0:0:1 451s 53.824570 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 451s 53.824609 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 451s 53.824611 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 451s 53.824623 | sdd: serial = beaf11 451s 53.824826 | sdd: tur state = up 451s 53.824848 | sdd: uid = 360000000000000000e00000000010001 (udev) 451s 53.824851 | sdd: detect_prio = yes (setting: multipath internal) 451s 53.824853 | sdd: prio = const (setting: multipath internal) 451s 53.824855 | sdd: prio args = "" (setting: multipath internal) 451s 53.824857 | sdd: const prio = 1 451s 53.824880 | sde: size = 204800 451s 53.824884 | sde: vendor = IET 451s 53.824886 | sde: product = VIRTUAL-DISK 451s 53.824889 | sde: rev = 0001 451s 53.825497 | sde: h:b:t:l = 4:0:0:1 451s 53.825624 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 451s 53.825662 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 451s 53.825665 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 451s 53.825677 | sde: serial = beaf11 451s 53.825874 | sde: tur state = up 451s 53.825896 | sde: uid = 360000000000000000e00000000010001 (udev) 451s 53.825899 | sde: detect_prio = yes (setting: multipath internal) 451s 53.825901 | sde: prio = const (setting: multipath internal) 451s 53.825903 | sde: prio args = "" (setting: multipath internal) 451s 53.825905 | sde: const prio = 1 451s ===== paths list ===== 451s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 451s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 451s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 451s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 451s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 451s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 451s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 451s size=100M features='0' hwhandler='0' wp=rw 451s |-+- policy='service-time 0' prio=1 status=active 451s | `- 1:0:0:1 sdb 8:16 active ready running 451s |-+- policy='service-time 0' prio=1 status=enabled 451s | `- 2:0:0:1 sdc 8:32 active ready running 451s |-+- policy='service-time 0' prio=1 status=enabled 451s | `- 3:0:0:1 sdd 8:48 active ready running 451s `-+- policy='service-time 0' prio=1 status=enabled 451s `- 4:0:0:1 sde 8:64 active ready running 451s 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 451s Test WWN should now point to DM 451s ../../dm-0 451s Creating filesystem with 25600 4k blocks and 25600 inodes 451s 451s Allocating group tables: 0/1 done 451s Writing inode tables: 0/1 done 451s Creating journal (1024 blocks): 53.826827 | unloading tur checker 451s 53.826897 | unloading const prioritizer 451s + dmsetup table 451s + echo Test WWN should now point to DM 451s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 451s + grep dm 451s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 451s mke2fs 1.47.0 (5-Feb-2023) 451s done 451s Writing superblocks and filesystem accounting information: 0/1 done 451s 451s + udevadm settle 451s + sleep 3s 454s + mkdir -p /mnt/tgtmpathtest 454s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 454s + cat 454s + cat 454s + fio --max-jobs=4 /tmp/autopkgtest.eLbDPj/tgtbasedmpaths-artifacts/path-change-prep.fio 454s 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 454s fio-3.37 454s Starting 1 thread 454s write-phase: Laying out IO file (1 file / 17592186044415MiB) 455s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 455s 455s write-phase: (groupid=0, jobs=1): err= 0: pid=5611: Fri Jun 14 20:33:01 2024 455s write: IOPS=1633, BW=102MiB/s (107MB/s)(87.6MiB/859msec); 0 zone resets 455s clat (usec): min=376, max=8340, avg=586.19, stdev=256.83 455s lat (usec): min=389, max=8374, avg=611.31, stdev=260.96 455s clat percentiles (usec): 455s | 1.00th=[ 392], 5.00th=[ 412], 10.00th=[ 429], 20.00th=[ 449], 455s | 30.00th=[ 494], 40.00th=[ 545], 50.00th=[ 611], 60.00th=[ 627], 455s | 70.00th=[ 644], 80.00th=[ 652], 90.00th=[ 676], 95.00th=[ 701], 455s | 99.00th=[ 1287], 99.50th=[ 1418], 99.90th=[ 2540], 99.95th=[ 8356], 455s | 99.99th=[ 8356] 455s bw ( KiB/s): min=91337, max=91337, per=87.44%, avg=91337.00, stdev= 0.00, samples=1 455s iops : min= 1427, max= 1427, avg=1427.00, stdev= 0.00, samples=1 455s lat (usec) : 500=30.65%, 750=66.50%, 1000=1.43% 455s lat (msec) : 2=1.07%, 4=0.21%, 10=0.07% 455s cpu : usr=3.96%, sys=8.51%, ctx=1404, majf=0, minf=0 455s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 455s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 455s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 455s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 455s latency : target=0, window=0, percentile=100.00%, depth=1 455s 455s Run status group 0 (all jobs): 455s WRITE: bw=102MiB/s (107MB/s), 102MiB/s-102MiB/s (107MB/s-107MB/s), io=87.6MiB (91.9MB), run=859-859msec 455s 455s Disk stats (read/write): 455s dm-0: ios=1/949, sectors=8/121472, merge=0/0, ticks=1/631, in_queue=632, util=87.03%, aggrios=0/351, aggsectors=2/44884, aggrmerge=0/0, aggrticks=0/195, aggrin_queue=195, aggrutil=88.34% 455s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 455s sdb: ios=1/1404, sectors=8/179536, merge=0/0, ticks=1/781, in_queue=783, util=88.34% 455s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 455s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 455s + echo Starting the path changes in background 455s Starting the path changes in background 455s + date +Pre FIO %H:%M:%S.%N 455s Pre FIO 20:33:01.212505438 455s + fio --max-jobs=4 /tmp/autopkgtest.eLbDPj/tgtbasedmpaths-artifacts/path-change-check.fio 455s 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 455s fio-3.37 455s Starting 1 thread 635s 635s verify-phase: (groupid=0, jobs=1): err= 0: pid=5618: Fri Jun 14 20:36:01 2024 635s read: IOPS=2992, BW=187MiB/s (196MB/s)(32.9GiB/180001msec) 635s clat (usec): min=87, max=41069, avg=311.07, stdev=189.69 635s lat (usec): min=87, max=41069, avg=311.16, stdev=189.69 635s clat percentiles (usec): 635s | 1.00th=[ 145], 5.00th=[ 169], 10.00th=[ 200], 20.00th=[ 221], 635s | 30.00th=[ 243], 40.00th=[ 281], 50.00th=[ 306], 60.00th=[ 326], 635s | 70.00th=[ 355], 80.00th=[ 388], 90.00th=[ 416], 95.00th=[ 449], 635s | 99.00th=[ 570], 99.50th=[ 938], 99.90th=[ 1467], 99.95th=[ 1827], 635s | 99.99th=[ 4359] 635s bw ( KiB/s): min=122112, max=331776, per=100.00%, avg=191736.53, stdev=41619.08, samples=359 635s iops : min= 1908, max= 5184, avg=2995.81, stdev=650.29, samples=359 635s lat (usec) : 100=0.15%, 250=31.95%, 500=66.33%, 750=0.85%, 1000=0.30% 635s lat (msec) : 2=0.38%, 4=0.03%, 10=0.01%, 20=0.01%, 50=0.01% 635s cpu : usr=8.16%, sys=6.68%, ctx=538667, majf=0, minf=1 635s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 635s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 635s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 635s issued rwts: total=538578,0,0,0 short=0,0,0,0 dropped=0,0,0,0 635s latency : target=0, window=0, percentile=100.00%, depth=1 635s 635s Run status group 0 (all jobs): 635s READ: bw=187MiB/s (196MB/s), 187MiB/s-187MiB/s (196MB/s-196MB/s), io=32.9GiB (35.3GB), run=180001-180001msec 635s 635s Disk stats (read/write): 635s dm-0: ios=538704/9, sectors=68902072/12912, merge=11/8, ticks=174538/69, in_queue=174652, util=100.00%, aggrios=37403/2, aggsectors=4783438/3228, aggrmerge=0/0, aggrticks=10987/6, aggrin_queue=10993, aggrutil=99.15% 635s sdd: ios=29184/0, sectors=3732864/0, merge=0/0, ticks=8708/0, in_queue=8708, util=32.96% 635s sdb: ios=28209/8, sectors=3607936/12912, merge=0/0, ticks=8573/24, in_queue=8597, util=99.15% 635s sde: ios=60143/0, sectors=7692800/0, merge=0/0, ticks=17893/0, in_queue=17893, util=40.04% 635s sdc: ios=32079/0, sectors=4100152/0, merge=0/0, ticks=8777/0, in_queue=8776, util=50.18% 635s + date +Post FIO %H:%M:%S.%N 635s Post FIO 20:36:01.557276561 635s + echo FIO verify test with changing paths - OK 635s + echo Report log of background activity 635s + cat /tmp/autopkgtest.eLbDPj/tgtbasedmpaths-artifacts/test-background.log 635s FIO verify test with changing paths - OK 635s Report log of background activity 635s + sync 635s + iscsiadm --mode session 635s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s + sleep 10s 635s + date +MP report (expect 4) %H:%M:%S.%N 635s MP report (expect 4) 20:33:11.219645793 635s + multipath -ll 635s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 635s size=100M features='0' hwhandler='0' wp=rw 635s |-+- policy='service-time 0' prio=1 status=active 635s | `- 1:0:0:1 sdb 8:16 active ready running 635s |-+- policy='service-time 0' prio=1 status=enabled 635s | `- 2:0:0:1 sdc 8:32 active ready running 635s |-+- policy='service-time 0' prio=1 status=enabled 635s | `- 3:0:0:1 sdd 8:48 active ready running 635s `-+- policy='service-time 0' prio=1 status=enabled 635s `- 4:0:0:1 sde 8:64 active ready running 635s + date +UN-plug path 1 %H:%M:%S.%N 635s UN-plug path 1 20:33:11.249005958 635s + iscsiadm --mode session -r 1 -u 635s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 635s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 635s + iscsiadm --mode session 635s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s + sleep 10s 635s + date +MP report (expect 3) %H:%M:%S.%N 635s MP report (expect 3) 20:33:21.364066786 635s + multipath -ll 635s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 635s size=100M features='0' hwhandler='0' wp=rw 635s |-+- policy='service-time 0' prio=1 status=active 635s | `- 2:0:0:1 sdc 8:32 active ready running 635s |-+- policy='service-time 0' prio=1 status=enabled 635s | `- 3:0:0:1 sdd 8:48 active ready running 635s `-+- policy='service-time 0' prio=1 status=enabled 635s `- 4:0:0:1 sde 8:64 active ready running 635s + date +UN-plug path 2 %H:%M:%S.%N 635s UN-plug path 2 20:33:21.387047167 635s + iscsiadm --mode session -r 2 -u 635s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 635s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 635s + iscsiadm --mode session 635s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s + sleep 10s 635s + date +MP report (expect 2) %H:%M:%S.%N 635s MP report (expect 2) 20:33:31.484766005 635s + multipath -ll 635s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 635s size=100M features='0' hwhandler='0' wp=rw 635s |-+- policy='service-time 0' prio=1 status=active 635s | `- 3:0:0:1 sdd 8:48 active ready running 635s `-+- policy='service-time 0' prio=1 status=enabled 635s `- 4:0:0:1 sde 8:64 active ready running 635s + date +UN-plug path 3 %H:%M:%S.%N 635s UN-plug path 3 20:33:31.507676795 635s + iscsiadm --mode session -r 3 -u 635s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 635s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 635s + iscsiadm --mode session 635s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s + sleep 10s 635s + date +MP report (expect 1) %H:%M:%S.%N 635s MP report (expect 1) 20:33:41.615479783 635s + multipath -ll 635s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 635s size=100M features='0' hwhandler='0' wp=rw 635s `-+- policy='service-time 0' prio=1 status=active 635s `- 4:0:0:1 sde 8:64 active ready running 635s + date +Add paths 5/6/7/8 %H:%M:%S.%N 635s Add paths 5/6/7/8 20:33:41.632675436 635s + iscsiadm --mode session -r 4 --op new 635s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 635s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 635s + iscsiadm --mode session -r 4 --op new 635s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 635s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 635s + iscsiadm --mode session -r 4 --op new 635s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 635s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 635s + iscsiadm --mode session -r 4 --op new 635s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 635s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 635s + iscsiadm --mode session 635s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s + sleep 10s 635s + date +MP report (expect 5) %H:%M:%S.%N 635s MP report (expect 5) 20:33:51.763156649 635s + multipath -ll 635s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 635s size=100M features='0' hwhandler='0' wp=rw 635s |-+- policy='service-time 0' prio=1 status=active 635s | `- 4:0:0:1 sde 8:64 active ready running 635s |-+- policy='service-time 0' prio=1 status=enabled 635s | `- 1:0:0:1 sdb 8:16 active ready running 635s |-+- policy='service-time 0' prio=1 status=enabled 635s | `- 2:0:0:1 sdc 8:32 active ready running 635s |-+- policy='service-time 0' prio=1 status=enabled 635s | `- 3:0:0:1 sdd 8:48 active ready running 635s `-+- policy='service-time 0' prio=1 status=enabled 635s `- 5:0:0:1 sdf 8:80 active ready running 635s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 635s UN-plug multiple paths 4/7/8 20:33:51.792579248 635s + iscsiadm --mode session -r 4 -u 635s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 635s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 635s + iscsiadm --mode session -r 7 -u 635s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 635s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 635s + iscsiadm --mode session -r 8 -u 635s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 635s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 635s + iscsiadm --mode session 635s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 635s + sleep 10s 635s + date +Restart multipath daemon %H:%M:%S.%N 635s Restart multipath daemon 20:34:02.056039406 635s + systemctl restart multipathd 635s + sleep 10s 635s + date +Final background report (expect 2) %H:%M:%S.%N 635s Final background report (expect 2) 20:34:12.144719832 635s + multipath -ll 635s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 635s size=100M features='0' hwhandler='0' wp=rw 635s |-+- policy='service-time 0' prio=1 status=active 635s | `- 1:0:0:1 sdb 8:16 active ready running 635s `-+- policy='service-time 0' prio=1 status=enabled 635s `- 2:0:0:1 sdc 8:32 active ready running 635s Final stats 635s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 635s iSCSI SNMP: 635s txdata_octets: 18632472 635s rxdata_octets: 25416377220 635s noptx_pdus: 0 635s scsicmd_pdus: 387909 635s tmfcmd_pdus: 0 635s login_pdus: 0 635s text_pdus: 0 635s dataout_pdus: 0 635s logout_pdus: 0 635s snack_pdus: 0 635s noprx_pdus: 0 635s scsirsp_pdus: 387909 635s tmfrsp_pdus: 0 635s textrsp_pdus: 0 635s datain_pdus: 387876 635s logoutrsp_pdus: 0 635s r2t_pdus: 0 635s async_pdus: 0 635s rjt_pdus: 0 635s digest_err: 0 635s timeout_err: 0 635s iSCSI Extended: 635s tx_sendpage_failures: 0 635s rx_discontiguous_hdr: 0 635s eh_abort_cnt: 0 635s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 635s iSCSI SNMP: 635s txdata_octets: 6504 635s rxdata_octets: 1514964 635s noptx_pdus: 0 635s scsicmd_pdus: 106 635s tmfcmd_pdus: 0 635s login_pdus: 0 635s text_pdus: 0 635s dataout_pdus: 0 635s logout_pdus: 0 635s snack_pdus: 0 635s noprx_pdus: 0 635s scsirsp_pdus: 106 635s tmfrsp_pdus: 0 635s textrsp_pdus: 0 635s datain_pdus: 83 635s logoutrsp_pdus: 0 635s r2t_pdus: 0 635s async_pdus: 0 635s rjt_pdus: 0 635s digest_err: 0 635s timeout_err: 0 635s iSCSI Extended: 635s tx_sendpage_failures: 0 635s rx_discontiguous_hdr: 0 635s eh_abort_cnt: 0 635s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 635s + echo Final stats 635s + iscsiadm --mode session --stats 635s + journalctl --no-pager -u multipathd 635s Jun 14 03:43:05 adtubuntu-oracular-ppc64el-server-20240612 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 635s Jun 14 03:43:05 adtubuntu-oracular-ppc64el-server-20240612 multipathd[280]: multipathd v0.9.4: start up 635s Jun 14 03:43:05 adtubuntu-oracular-ppc64el-server-20240612 multipathd[280]: reconfigure: setting up paths and maps 635s Jun 14 03:43:05 adtubuntu-oracular-ppc64el-server-20240612 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 635s Jun 14 03:43:45 adtubuntu-oracular-ppc64el-server-20240613 multipathd[280]: multipathd: shut down 635s Jun 14 03:43:45 adtubuntu-oracular-ppc64el-server-20240613 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 635s Jun 14 03:43:45 adtubuntu-oracular-ppc64el-server-20240613 systemd[1]: multipathd.service: Deactivated successfully. 635s Jun 14 03:43:45 adtubuntu-oracular-ppc64el-server-20240613 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 635s -- Boot b600269139634cf4b8702c9d45f8ceb8 -- 635s Jun 14 03:44:11 adtubuntu-oracular-ppc64el-server-20240613 multipathd[261]: multipathd v0.9.4: start up 635s Jun 14 03:44:11 adtubuntu-oracular-ppc64el-server-20240613 multipathd[261]: reconfigure: setting up paths and maps 635s Jun 14 03:44:11 adtubuntu-oracular-ppc64el-server-20240613 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 635s Jun 14 03:44:30 adtubuntu-oracular-ppc64el-server-20240613 multipathd[261]: multipathd: shut down 635s Jun 14 03:44:30 adtubuntu-oracular-ppc64el-server-20240613 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 635s Jun 14 03:44:30 adtubuntu-oracular-ppc64el-server-20240613 systemd[1]: multipathd.service: Deactivated successfully. 635s Jun 14 03:44:30 adtubuntu-oracular-ppc64el-server-20240613 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 635s -- Boot 8d624bf89ecd4c90850fd0c6c313c217 -- 635s Jun 14 20:30:58 adtubuntu-oracular-ppc64el-server-20240613 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 635s Jun 14 20:30:58 adtubuntu-oracular-ppc64el-server-20240613 multipathd[331]: multipathd v0.9.4: start up 635s Jun 14 20:30:58 adtubuntu-oracular-ppc64el-server-20240613 multipathd[331]: reconfigure: setting up paths and maps 635s Jun 14 20:30:58 adtubuntu-oracular-ppc64el-server-20240613 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 635s Jun 14 20:31:42 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 635s Jun 14 20:31:42 autopkgtest multipathd[331]: multipathd: shut down 635s Jun 14 20:31:42 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 635s Jun 14 20:31:42 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 635s -- Boot fe287c97545540cea969e1ddd58d19ab -- 635s Jun 14 20:32:06 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 635s Jun 14 20:32:06 autopkgtest multipathd[329]: multipathd v0.9.4: start up 635s Jun 14 20:32:06 autopkgtest multipathd[329]: reconfigure: setting up paths and maps 635s Jun 14 20:32:06 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 635s Jun 14 20:32:51 autopkgtest multipathd[329]: 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] 635s Jun 14 20:32:51 autopkgtest multipathd[329]: sdc [8:32]: path added to devmap mpatha 635s Jun 14 20:32:51 autopkgtest multipathd[329]: mpatha: performing delayed actions 635s Jun 14 20:32:51 autopkgtest multipathd[329]: 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] 635s Jun 14 20:33:11 autopkgtest multipathd[329]: sdb: mark as failed 635s Jun 14 20:33:11 autopkgtest multipathd[329]: mpatha: remaining active paths: 3 635s Jun 14 20:33:11 autopkgtest multipathd[329]: 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] 635s Jun 14 20:33:11 autopkgtest multipathd[329]: check_removed_paths: sdb: freeing path in removed state 635s Jun 14 20:33:11 autopkgtest multipathd[329]: 8:16: path removed from map mpatha 635s Jun 14 20:33:21 autopkgtest multipathd[329]: sdc: mark as failed 635s Jun 14 20:33:21 autopkgtest multipathd[329]: mpatha: remaining active paths: 2 635s Jun 14 20:33:21 autopkgtest multipathd[329]: 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] 635s Jun 14 20:33:21 autopkgtest multipathd[329]: check_removed_paths: sdc: freeing path in removed state 635s Jun 14 20:33:21 autopkgtest multipathd[329]: 8:32: path removed from map mpatha 635s Jun 14 20:33:31 autopkgtest multipathd[329]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 635s Jun 14 20:33:31 autopkgtest multipathd[329]: check_removed_paths: sdd: freeing path in removed state 635s Jun 14 20:33:31 autopkgtest multipathd[329]: 8:48: path removed from map mpatha 635s Jun 14 20:33:41 autopkgtest multipathd[329]: 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] 635s Jun 14 20:33:41 autopkgtest multipathd[329]: sdb [8:16]: path added to devmap mpatha 635s Jun 14 20:33:41 autopkgtest multipathd[329]: 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] 635s Jun 14 20:33:41 autopkgtest multipathd[329]: sdc [8:32]: path added to devmap mpatha 635s Jun 14 20:33:41 autopkgtest multipathd[329]: 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] 635s Jun 14 20:33:41 autopkgtest multipathd[329]: sdd [8:48]: path added to devmap mpatha 635s Jun 14 20:33:41 autopkgtest multipathd[329]: 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] 635s Jun 14 20:33:41 autopkgtest multipathd[329]: sdf [8:80]: path added to devmap mpatha 635s Jun 14 20:33:51 autopkgtest multipathd[329]: 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] 635s Jun 14 20:33:51 autopkgtest multipathd[329]: check_removed_paths: sde: freeing path in removed state 635s Jun 14 20:33:51 autopkgtest multipathd[329]: 8:64: path removed from map mpatha 635s Jun 14 20:33:51 autopkgtest multipathd[329]: 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] 635s Jun 14 20:33:51 autopkgtest multipathd[329]: check_removed_paths: sdd: freeing path in removed state 635s Jun 14 20:33:51 autopkgtest multipathd[329]: 8:48: path removed from map mpatha 635s Jun 14 20:33:51 autopkgtest multipathd[329]: 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] 635s Jun 14 20:33:52 autopkgtest multipathd[329]: check_removed_paths: sdf: freeing path in removed state 635s Jun 14 20:33:52 autopkgtest multipathd[329]: 8:80: path removed from map mpatha 635s Jun 14 20:34:02 autopkgtest multipathd[329]: multipathd: shut down 635s Jun 14 20:34:02 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 635s Jun 14 20:34:02 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 635s Jun 14 20:34:02 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 635s Jun 14 20:34:02 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 635s Jun 14 20:34:02 autopkgtest multipathd[5987]: multipathd v0.9.4: start up 635s Jun 14 20:34:02 autopkgtest multipathd[5987]: reconfigure: setting up paths and maps 635s Jun 14 20:34:02 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 635s Check final path status 635s + echo Check final path status 635s + multipath -ll 635s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 635s size=100M features='0' hwhandler='0' wp=rw 635s |-+- policy='service-time 0' prio=1 status=active 635s | `- 1:0:0:1 sdb 8:16 active ready running 635s `-+- policy='service-time 0' prio=1 status=enabled 635s `- 2:0:0:1 sdc 8:32 active ready running 635s + multipath -ll 635s + grep --count status= 635s + diskc=2 635s + multipath -ll 635s + grep --count status=active 635s + diska=1 635s + multipath -ll 635s + grep --count status=enabled 635s OK 635s + diske=1 635s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 635s + echo OK 635s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 635s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 635s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 635s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 635s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 635s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 636s autopkgtest [20:36:02]: test tgtbasedmpaths: -----------------------] 636s autopkgtest [20:36:02]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 636s tgtbasedmpaths PASS 637s autopkgtest [20:36:03]: @@@@@@@@@@@@@@@@@@@@ summary 637s kpartx-file-loopback PASS 637s tgtbasedmpaths PASS 648s nova [W] Using flock in scalingstack-bos02-ppc64el 648s flock: timeout while waiting to get lock 648s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240614-202526-juju-7f2275-prod-proposed-migration-environment-3-94c0cf50-4bc7-4ac2-8505-ec464deefa3e from image adt/ubuntu-oracular-ppc64el-server-20240614.img (UUID bff4f888-5232-4e18-a9ca-120fb2686f5e)... 648s nova [W] Using flock in scalingstack-bos02-ppc64el 648s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240614-202526-juju-7f2275-prod-proposed-migration-environment-3-94c0cf50-4bc7-4ac2-8505-ec464deefa3e from image adt/ubuntu-oracular-ppc64el-server-20240614.img (UUID bff4f888-5232-4e18-a9ca-120fb2686f5e)...