0s autopkgtest [17:09:55]: starting date and time: 2024-03-18 17:09:55+0000 0s autopkgtest [17:09:55]: git checkout: b506e79c ssh-setup/nova: fix ARCH having two lines of data 0s autopkgtest [17:09:55]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.qxa76r4d/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=migration-reference/0 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos02-ppc64el-16.secgroup --name adt-noble-ppc64el-multipath-tools-20240318-170955-juju-7f2275-prod-proposed-migration-environment-2 --image adt/ubuntu-noble-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,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 99s autopkgtest [17:11:34]: testbed dpkg architecture: ppc64el 99s autopkgtest [17:11:34]: testbed apt version: 2.7.12 99s autopkgtest [17:11:34]: @@@@@@@@@@@@@@@@@@@@ test bed setup 100s Reading package lists... 100s Building dependency tree... 100s Reading state information... 101s Calculating upgrade... 101s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 101s Reading package lists... 101s Building dependency tree... 101s Reading state information... 101s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 102s Hit:1 http://ftpmaster.internal/ubuntu noble InRelease 102s Hit:2 http://ftpmaster.internal/ubuntu noble-updates InRelease 102s Hit:3 http://ftpmaster.internal/ubuntu noble-security InRelease 103s Reading package lists... 103s Reading package lists... 103s Building dependency tree... 103s Reading state information... 103s Calculating upgrade... 103s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 103s Reading package lists... 104s Building dependency tree... 104s Reading state information... 104s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 107s autopkgtest [17:11:42]: testbed running kernel: Linux 6.8.0-11-generic #11-Ubuntu SMP Wed Feb 14 00:33:03 UTC 2024 107s autopkgtest [17:11:42]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 112s Get:1 http://ftpmaster.internal/ubuntu noble/main multipath-tools 0.9.4-5ubuntu3 (dsc) [2733 B] 112s Get:2 http://ftpmaster.internal/ubuntu noble/main multipath-tools 0.9.4-5ubuntu3 (tar) [554 kB] 112s Get:3 http://ftpmaster.internal/ubuntu noble/main multipath-tools 0.9.4-5ubuntu3 (diff) [42.6 kB] 112s gpgv: Signature made Wed Sep 6 23:15:24 2023 UTC 112s gpgv: using RSA key 8A2044F84F716A85B77FF76311DF4294CCA39893 112s gpgv: Can't check signature: No public key 112s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu3.dsc: no acceptable signature found 112s autopkgtest [17:11:47]: testing package multipath-tools version 0.9.4-5ubuntu3 113s autopkgtest [17:11:48]: build not needed 114s autopkgtest [17:11:49]: test kpartx-file-loopback: preparing testbed 116s Reading package lists... 116s Building dependency tree... 116s Reading state information... 116s Starting pkgProblemResolver with broken count: 0 116s Starting 2 pkgProblemResolver with broken count: 0 116s Done 116s The following additional packages will be installed: 116s liburing2 qemu-utils 116s Recommended packages: 116s qemu-block-extra 116s The following NEW packages will be installed: 116s autopkgtest-satdep liburing2 qemu-utils 116s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 116s Need to get 2323 kB/2324 kB of archives. 116s After this operation, 15.4 MB of additional disk space will be used. 116s Get:1 /tmp/autopkgtest.i2kswK/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 117s Get:2 http://ftpmaster.internal/ubuntu noble/main ppc64el liburing2 ppc64el 2.5-1 [25.2 kB] 117s Get:3 http://ftpmaster.internal/ubuntu noble/main ppc64el qemu-utils ppc64el 1:8.2.1+ds-1ubuntu1 [2298 kB] 118s Fetched 2323 kB in 1s (1907 kB/s) 118s Selecting previously unselected package liburing2:ppc64el. 118s (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 ... 70095 files and directories currently installed.) 118s Preparing to unpack .../liburing2_2.5-1_ppc64el.deb ... 118s Unpacking liburing2:ppc64el (2.5-1) ... 118s Selecting previously unselected package qemu-utils. 118s Preparing to unpack .../qemu-utils_1%3a8.2.1+ds-1ubuntu1_ppc64el.deb ... 118s Unpacking qemu-utils (1:8.2.1+ds-1ubuntu1) ... 118s Selecting previously unselected package autopkgtest-satdep. 118s Preparing to unpack .../1-autopkgtest-satdep.deb ... 118s Unpacking autopkgtest-satdep (0) ... 118s Setting up liburing2:ppc64el (2.5-1) ... 118s Setting up qemu-utils (1:8.2.1+ds-1ubuntu1) ... 118s Setting up autopkgtest-satdep (0) ... 118s Processing triggers for man-db (2.12.0-3) ... 119s Processing triggers for libc-bin (2.39-0ubuntu2) ... 121s (Reading database ... 70115 files and directories currently installed.) 121s Removing autopkgtest-satdep (0) ... 122s autopkgtest [17:11:57]: test kpartx-file-loopback: [----------------------- 122s Formatting 'foo.img', fmt=raw size=20971520 123s Creating new GPT entries in memory. 123s Warning: The kernel is still using the old partition table. 123s The new table will be used at the next reboot or after you 123s run partprobe(8) or kpartx(8) 123s The operation has completed successfully. 123s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 123s standard_filename: OK 124s del devmap : loop0p1 124s No devices found 124s standard_filename_cleanup: OK 124s Formatting 'fou du FaFa.img', fmt=raw size=20971520 125s Creating new GPT entries in memory. 125s Warning: The kernel is still using the old partition table. 125s The new table will be used at the next reboot or after you 125s run partprobe(8) or kpartx(8) 125s The operation has completed successfully. 125s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 125s filename_with_spaces: OK 125s del devmap : loop0p1 125s No devices found 125s filename_with_spaces_cleanup: OK 125s autopkgtest [17:12:00]: test kpartx-file-loopback: -----------------------] 126s autopkgtest [17:12:01]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 126s kpartx-file-loopback PASS 126s autopkgtest [17:12:01]: test tgtbasedmpaths: preparing testbed 238s autopkgtest [17:13:53]: testbed dpkg architecture: ppc64el 238s autopkgtest [17:13:53]: testbed apt version: 2.7.12 238s autopkgtest [17:13:53]: @@@@@@@@@@@@@@@@@@@@ test bed setup 239s Reading package lists... 239s Building dependency tree... 239s Reading state information... 239s Calculating upgrade... 239s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 239s Reading package lists... 240s Building dependency tree... 240s Reading state information... 240s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 240s Hit:1 http://ftpmaster.internal/ubuntu noble InRelease 240s Hit:2 http://ftpmaster.internal/ubuntu noble-updates InRelease 240s Hit:3 http://ftpmaster.internal/ubuntu noble-security InRelease 241s Reading package lists... 241s Reading package lists... 242s Building dependency tree... 242s Reading state information... 242s Calculating upgrade... 242s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 242s Reading package lists... 242s Building dependency tree... 242s Reading state information... 243s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 249s Reading package lists... 250s Building dependency tree... 250s Reading state information... 250s Starting pkgProblemResolver with broken count: 0 250s Starting 2 pkgProblemResolver with broken count: 0 250s Done 250s The following additional packages will be installed: 250s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 250s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0 libnbd0 250s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 librdmacm1 250s lsscsi open-iscsi tgt 250s Suggested packages: 250s fio-examples gnuplot tgt-glusterfs tgt-rbd 250s Recommended packages: 250s finalrd 250s The following NEW packages will be installed: 250s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 250s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 250s libglusterfs0 libisns0 libnbd0 libndctl6 libopeniscsiusr libpmem1 250s libpmemobj1 librados2 librbd1 librdmacm1 lsscsi open-iscsi tgt 250s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 250s Need to get 10.7 MB/10.7 MB of archives. 250s After this operation, 48.3 MB of additional disk space will be used. 250s Get:1 /tmp/autopkgtest.i2kswK/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [736 B] 250s Get:2 http://ftpmaster.internal/ubuntu noble/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu1 [54.1 kB] 251s Get:3 http://ftpmaster.internal/ubuntu noble/main ppc64el libisns0 ppc64el 0.101-0.2 [117 kB] 251s Get:4 http://ftpmaster.internal/ubuntu noble/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu1 [387 kB] 251s Get:5 http://ftpmaster.internal/ubuntu noble/main ppc64el librdmacm1 ppc64el 50.0-1 [80.7 kB] 251s Get:6 http://ftpmaster.internal/ubuntu noble/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 251s Get:7 http://ftpmaster.internal/ubuntu noble/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu2 [256 kB] 251s Get:8 http://ftpmaster.internal/ubuntu noble/universe ppc64el libgfxdr0 ppc64el 11.1-4 [21.3 kB] 251s Get:9 http://ftpmaster.internal/ubuntu noble/universe ppc64el libglusterfs0 ppc64el 11.1-4 [313 kB] 251s Get:10 http://ftpmaster.internal/ubuntu noble/universe ppc64el libgfrpc0 ppc64el 11.1-4 [46.8 kB] 251s Get:11 http://ftpmaster.internal/ubuntu noble/universe ppc64el libgfapi0 ppc64el 11.1-4 [99.6 kB] 251s Get:12 http://ftpmaster.internal/ubuntu noble/universe ppc64el libnbd0 ppc64el 1.18.2-1build1 [95.2 kB] 251s Get:13 http://ftpmaster.internal/ubuntu noble/main ppc64el libdaxctl1 ppc64el 77-2ubuntu1 [23.6 kB] 251s Get:14 http://ftpmaster.internal/ubuntu noble/main ppc64el libndctl6 ppc64el 77-2ubuntu1 [74.8 kB] 251s Get:15 http://ftpmaster.internal/ubuntu noble/main ppc64el libpmem1 ppc64el 1.13.1-1.1 [40.0 kB] 251s Get:16 http://ftpmaster.internal/ubuntu noble/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-2ubuntu1 [340 kB] 251s Get:17 http://ftpmaster.internal/ubuntu noble/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-2ubuntu1 [363 kB] 251s Get:18 http://ftpmaster.internal/ubuntu noble/main ppc64el librados2 ppc64el 18.2.0-0ubuntu7 [3911 kB] 252s Get:19 http://ftpmaster.internal/ubuntu noble/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1 [139 kB] 252s Get:20 http://ftpmaster.internal/ubuntu noble/main ppc64el librbd1 ppc64el 18.2.0-0ubuntu7 [3517 kB] 252s Get:21 http://ftpmaster.internal/ubuntu noble/universe ppc64el fio ppc64el 3.36-1 [710 kB] 252s Get:22 http://ftpmaster.internal/ubuntu noble/main ppc64el lsscsi ppc64el 0.32-1 [53.4 kB] 252s Preconfiguring packages ... 252s Fetched 10.7 MB in 2s (5638 kB/s) 252s Selecting previously unselected package libopeniscsiusr. 252s (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 ... 70095 files and directories currently installed.) 252s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu1_ppc64el.deb ... 252s Unpacking libopeniscsiusr (2.1.9-3ubuntu1) ... 253s Selecting previously unselected package libisns0:ppc64el. 253s Preparing to unpack .../01-libisns0_0.101-0.2_ppc64el.deb ... 253s Unpacking libisns0:ppc64el (0.101-0.2) ... 253s Selecting previously unselected package open-iscsi. 253s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu1_ppc64el.deb ... 253s Unpacking open-iscsi (2.1.9-3ubuntu1) ... 253s Selecting previously unselected package librdmacm1:ppc64el. 253s Preparing to unpack .../03-librdmacm1_50.0-1_ppc64el.deb ... 253s Unpacking librdmacm1:ppc64el (50.0-1) ... 253s Selecting previously unselected package libconfig-general-perl. 253s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 253s Unpacking libconfig-general-perl (2.65-2) ... 253s Selecting previously unselected package tgt. 253s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu2_ppc64el.deb ... 253s Unpacking tgt (1:1.0.85-1.1ubuntu2) ... 253s Selecting previously unselected package libgfxdr0:ppc64el. 253s Preparing to unpack .../06-libgfxdr0_11.1-4_ppc64el.deb ... 253s Unpacking libgfxdr0:ppc64el (11.1-4) ... 253s Selecting previously unselected package libglusterfs0:ppc64el. 253s Preparing to unpack .../07-libglusterfs0_11.1-4_ppc64el.deb ... 253s Unpacking libglusterfs0:ppc64el (11.1-4) ... 253s Selecting previously unselected package libgfrpc0:ppc64el. 253s Preparing to unpack .../08-libgfrpc0_11.1-4_ppc64el.deb ... 253s Unpacking libgfrpc0:ppc64el (11.1-4) ... 253s Selecting previously unselected package libgfapi0:ppc64el. 253s Preparing to unpack .../09-libgfapi0_11.1-4_ppc64el.deb ... 253s Unpacking libgfapi0:ppc64el (11.1-4) ... 253s Selecting previously unselected package libnbd0. 253s Preparing to unpack .../10-libnbd0_1.18.2-1build1_ppc64el.deb ... 253s Unpacking libnbd0 (1.18.2-1build1) ... 253s Selecting previously unselected package libdaxctl1:ppc64el. 253s Preparing to unpack .../11-libdaxctl1_77-2ubuntu1_ppc64el.deb ... 253s Unpacking libdaxctl1:ppc64el (77-2ubuntu1) ... 253s Selecting previously unselected package libndctl6:ppc64el. 253s Preparing to unpack .../12-libndctl6_77-2ubuntu1_ppc64el.deb ... 253s Unpacking libndctl6:ppc64el (77-2ubuntu1) ... 253s Selecting previously unselected package libpmem1:ppc64el. 253s Preparing to unpack .../13-libpmem1_1.13.1-1.1_ppc64el.deb ... 253s Unpacking libpmem1:ppc64el (1.13.1-1.1) ... 253s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 253s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-2ubuntu1_ppc64el.deb ... 253s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-2ubuntu1) ... 253s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 253s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-2ubuntu1_ppc64el.deb ... 253s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-2ubuntu1) ... 253s Selecting previously unselected package librados2. 253s Preparing to unpack .../16-librados2_18.2.0-0ubuntu7_ppc64el.deb ... 253s Unpacking librados2 (18.2.0-0ubuntu7) ... 253s Selecting previously unselected package libpmemobj1:ppc64el. 253s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1_ppc64el.deb ... 253s Unpacking libpmemobj1:ppc64el (1.13.1-1.1) ... 253s Selecting previously unselected package librbd1. 253s Preparing to unpack .../18-librbd1_18.2.0-0ubuntu7_ppc64el.deb ... 253s Unpacking librbd1 (18.2.0-0ubuntu7) ... 253s Selecting previously unselected package fio. 253s Preparing to unpack .../19-fio_3.36-1_ppc64el.deb ... 253s Unpacking fio (3.36-1) ... 253s Selecting previously unselected package lsscsi. 253s Preparing to unpack .../20-lsscsi_0.32-1_ppc64el.deb ... 253s Unpacking lsscsi (0.32-1) ... 253s Selecting previously unselected package autopkgtest-satdep. 253s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 253s Unpacking autopkgtest-satdep (0) ... 253s Setting up librdmacm1:ppc64el (50.0-1) ... 253s Setting up libconfig-general-perl (2.65-2) ... 253s Setting up libboost-thread1.83.0:ppc64el (1.83.0-2ubuntu1) ... 253s Setting up libnbd0 (1.18.2-1build1) ... 253s Setting up libopeniscsiusr (2.1.9-3ubuntu1) ... 253s Setting up libglusterfs0:ppc64el (11.1-4) ... 253s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-2ubuntu1) ... 253s Setting up lsscsi (0.32-1) ... 253s Setting up libdaxctl1:ppc64el (77-2ubuntu1) ... 253s Setting up libisns0:ppc64el (0.101-0.2) ... 253s Setting up libndctl6:ppc64el (77-2ubuntu1) ... 253s Setting up tgt (1:1.0.85-1.1ubuntu2) ... 254s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 254s Setting up libpmem1:ppc64el (1.13.1-1.1) ... 254s Setting up libgfxdr0:ppc64el (11.1-4) ... 254s Setting up librados2 (18.2.0-0ubuntu7) ... 254s Setting up open-iscsi (2.1.9-3ubuntu1) ... 255s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 256s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 256s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 256s Setting up libpmemobj1:ppc64el (1.13.1-1.1) ... 256s Setting up librbd1 (18.2.0-0ubuntu7) ... 256s Setting up libgfrpc0:ppc64el (11.1-4) ... 256s Setting up libgfapi0:ppc64el (11.1-4) ... 256s Setting up fio (3.36-1) ... 256s Setting up autopkgtest-satdep (0) ... 256s Processing triggers for man-db (2.12.0-3) ... 257s Processing triggers for initramfs-tools (0.142ubuntu20) ... 257s update-initramfs: Generating /boot/initrd.img-6.8.0-11-generic 257s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 264s Processing triggers for libc-bin (2.39-0ubuntu2) ... 267s (Reading database ... 70333 files and directories currently installed.) 267s Removing autopkgtest-satdep (0) ... 272s autopkgtest [17:14:27]: test tgtbasedmpaths: [----------------------- 272s + targetname=iqn.2016-11.foo.com:target.iscsi 272s + pwd 272s + cwd=/tmp/autopkgtest.i2kswK/build.cZL/src 272s + testdir=/mnt/tgtmpathtest 272s + localhost=127.0.0.1 272s + portal=127.0.0.1:3260 272s + maxpaths=4 272s + backfn=backingfile 272s + expectwwid=60000000000000000e00000000010001 272s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 272s + bglog=/tmp/autopkgtest.i2kswK/tgtbasedmpaths-artifacts/test-background.log 272s + fioprep=/tmp/autopkgtest.i2kswK/tgtbasedmpaths-artifacts/path-change-prep.fio 272s + fiovrfy=/tmp/autopkgtest.i2kswK/tgtbasedmpaths-artifacts/path-change-check.fio 272s + service tgt restart 273s + truncate --size 100M backingfile 273s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 273s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 273s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.i2kswK/build.cZL/src/backingfile 273s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 273s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 273s + echo login #1 273s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 273s login #1 273s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 273s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 273s + seq 2 4 273s extra login #2 273s + echo extra login #2 273s + iscsiadm --mode session -r 1 --op new 273s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 273s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 273s + echo extra login #3 273s + iscsiadm --mode session -r 1 --op new 273s extra login #3 273s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 273s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 273s extra login #4 273s + echo extra login #4 273s + iscsiadm --mode session -r 1 --op new 273s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 273s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 273s + udevadm settle 273s + sleep 5 278s Status after initial setup 278s + echo Status after initial setup 278s + tgtadm --lld iscsi --mode target --op show 278s Target 1: iqn.2016-11.foo.com:target.iscsi 278s System information: 278s Driver: iscsi 278s State: ready 278s I_T nexus information: 278s I_T nexus: 1 278s Initiator: iqn.2004-10.com.ubuntu:01:89e8e2717e99 alias: autopkgtest 278s Connection: 0 278s IP Address: 127.0.0.1 278s I_T nexus: 2 278s Initiator: iqn.2004-10.com.ubuntu:01:89e8e2717e99 alias: autopkgtest 278s Connection: 0 278s IP Address: 127.0.0.1 278s I_T nexus: 3 278s Initiator: iqn.2004-10.com.ubuntu:01:89e8e2717e99 alias: autopkgtest 278s Connection: 0 278s IP Address: 127.0.0.1 278s I_T nexus: 4 278s Initiator: iqn.2004-10.com.ubuntu:01:89e8e2717e99 alias: autopkgtest 278s Connection: 0 278s IP Address: 127.0.0.1 278s LUN information: 278s LUN: 0 278s Type: controller 278s SCSI ID: IET 00010000 278s SCSI SN: beaf10 278s Size: 0 MB, Block size: 1 278s Online: Yes 278s Removable media: No 278s Prevent removal: No 278s Readonly: No 278s SWP: No 278s Thin-provisioning: No 278s Backing store type: null 278s Backing store path: None 278s Backing store flags: 278s LUN: 1 278s Type: disk 278s SCSI ID: IET 00010001 278s SCSI SN: beaf11 278s Size: 105 MB, Block size: 512 278s Online: Yes 278s Removable media: No 278s Prevent removal: No 278s Readonly: No 278s SWP: No 278s Thin-provisioning: No 278s Backing store type: rdwr 278s Backing store path: /tmp/autopkgtest.i2kswK/build.cZL/src/backingfile 278s Backing store flags: 278s Account information: 278s ACL information: 278s ALL 278s + tgtadm --lld iscsi --op show --mode conn --tid 1 278s Session: 4 278s Connection: 0 278s Initiator: iqn.2004-10.com.ubuntu:01:89e8e2717e99 278s IP Address: 127.0.0.1 278s Session: 3 278s Connection: 0 278s Initiator: iqn.2004-10.com.ubuntu:01:89e8e2717e99 278s IP Address: 127.0.0.1 278s Session: 2 278s Connection: 0 278s Initiator: iqn.2004-10.com.ubuntu:01:89e8e2717e99 278s IP Address: 127.0.0.1 278s Session: 1 278s Connection: 0 278s Initiator: iqn.2004-10.com.ubuntu:01:89e8e2717e99 278s IP Address: 127.0.0.1 278s + iscsiadm --mode session -P 1 278s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 278s Current Portal: 127.0.0.1:3260,1 278s Persistent Portal: 127.0.0.1:3260,1 278s ********** 278s Interface: 278s ********** 278s Iface Name: default 278s Iface Transport: tcp 278s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:89e8e2717e99 278s Iface IPaddress: 127.0.0.1 278s Iface HWaddress: default 278s Iface Netdev: default 278s SID: 1 278s iSCSI Connection State: LOGGED IN 278s iSCSI Session State: LOGGED_IN 278s Internal iscsid Session State: NO CHANGE 278s 278s ********** 278s Interface: 278s ********** 278s Iface Name: default 278s Iface Transport: tcp 278s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:89e8e2717e99 278s Iface IPaddress: 127.0.0.1 278s Iface HWaddress: default 278s Iface Netdev: default 278s SID: 2 278s iSCSI Connection State: LOGGED IN 278s iSCSI Session State: LOGGED_IN 278s Internal iscsid Session State: NO CHANGE 278s 278s ********** 278s Interface: 278s ********** 278s Iface Name: default 278s Iface Transport: tcp 278s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:89e8e2717e99 278s Iface IPaddress: 127.0.0.1 278s Iface HWaddress: default 278s Iface Netdev: default 278s SID: 3 278s iSCSI Connection State: LOGGED IN 278s iSCSI Session State: LOGGED_IN 278s Internal iscsid Session State: NO CHANGE 278s 278s ********** 278s Interface: 278s ********** 278s Iface Name: default 278s Iface Transport: tcp 278s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:89e8e2717e99 278s Iface IPaddress: 127.0.0.1 278s Iface HWaddress: default 278s Iface Netdev: default 278s SID: 4 278s iSCSI Connection State: LOGGED IN 278s iSCSI Session State: LOGGED_IN 278s Internal iscsid Session State: NO CHANGE 278s + lsscsi -liv 278s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 278s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 278s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 278s 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] 278s [1:0:0:0] storage IET Controller 0001 - - 278s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 278s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 278s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 278s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 278s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 278s [2:0:0:0] storage IET Controller 0001 - - 278s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 278s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 278s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 278s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 278s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 278s [3:0:0:0] storage IET Controller 0001 - - 278s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 278s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 278s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 278s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 278s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 278s [4:0:0:0] storage IET Controller 0001 - - 278s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 278s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 278s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 278s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 278s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 278s NVMe module may not be loaded 278s + multipath -v3 -ll 278s 74.436450 | set open fds limit to 1048576/1048576 278s 74.436614 | loading /lib/multipath/libchecktur.so checker 278s 74.436703 | checker tur: message table size = 3 278s 74.436712 | loading /lib/multipath/libprioconst.so prioritizer 278s 74.436821 | _init_foreign: foreign library "nvme" is not enabled 278s 74.442554 | sda: size = 167772160 278s 74.442779 | sda: vendor = QEMU 278s 74.442827 | sda: product = QEMU HARDDISK 278s 74.442873 | sda: rev = 2.5+ 278s 74.443529 | sda: h:b:t:l = 0:0:0:0 278s 74.443880 | sda: tgt_node_name = 278s 74.443927 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 278s 74.443949 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 278s 74.444167 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 278s 74.444222 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 278s 74.444255 | __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 278s 74.444307 | failed to read sysfs vpd pg80: No such file or directory 278s 74.444523 | sda: fail to get serial 278s 74.444570 | sda: detect_checker = yes (setting: multipath internal) 278s 74.444749 | sda: path_checker = tur (setting: multipath internal) 278s 74.444796 | sda: checker timeout = 30 s (setting: kernel sysfs) 278s 74.444926 | sda: tur state = up 278s 74.445281 | sdb: size = 204800 278s 74.445459 | sdb: vendor = IET 278s 74.445525 | sdb: product = VIRTUAL-DISK 278s 74.445569 | sdb: rev = 0001 278s 74.446276 | sdb: h:b:t:l = 1:0:0:1 278s 74.446679 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 278s 74.446723 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 278s 74.446744 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 278s 74.446936 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 278s 74.446980 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 278s 74.447016 | sdb: serial = beaf11 278s 74.447057 | sdb: detect_checker = yes (setting: multipath internal) 278s 74.447452 | sdb: path_checker = tur (setting: multipath internal) 278s 74.447498 | sdb: checker timeout = 30 s (setting: kernel sysfs) 278s 74.447696 | sdb: tur state = up 278s 74.447871 | sdc: size = 204800 278s 74.448061 | sdc: vendor = IET 278s 74.448125 | sdc: product = VIRTUAL-DISK 278s 74.448170 | sdc: rev = 0001 278s 74.448887 | sdc: h:b:t:l = 2:0:0:1 278s 74.449285 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 278s 74.449330 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 278s 74.449351 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 278s 74.449534 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 278s 74.449578 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 278s 74.449617 | sdc: serial = beaf11 278s 74.449640 | sdc: detect_checker = yes (setting: multipath internal) 278s 74.449918 | sdc: path_checker = tur (setting: multipath internal) 278s 74.449964 | sdc: checker timeout = 30 s (setting: kernel sysfs) 278s 74.450153 | sdc: tur state = up 278s 74.450335 | sdd: size = 204800 278s 74.450512 | sdd: vendor = IET 278s 74.450577 | sdd: product = VIRTUAL-DISK 278s 74.450621 | sdd: rev = 0001 278s 74.451907 | sdd: h:b:t:l = 3:0:0:1 278s 74.452396 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 278s 74.452460 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 278s 74.452482 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 278s 74.452677 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 278s 74.452721 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 278s 74.452757 | sdd: serial = beaf11 278s 74.452797 | sdd: detect_checker = yes (setting: multipath internal) 278s 74.453140 | sdd: path_checker = tur (setting: multipath internal) 278s 74.453187 | sdd: checker timeout = 30 s (setting: kernel sysfs) 278s 74.453454 | sdd: tur state = up 278s 74.453814 | sde: size = 204800 278s 74.454018 | sde: vendor = IET 278s 74.454065 | sde: product = VIRTUAL-DISK 278s 74.454110 | sde: rev = 0001 278s 74.454877 | sde: h:b:t:l = 4:0:0:1 278s 74.455277 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 278s 74.455322 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 278s 74.455344 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 278s 74.455532 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 278s 74.455576 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 278s 74.455611 | sde: serial = beaf11 278s 74.455633 | sde: detect_checker = yes (setting: multipath internal) 278s 74.456108 | sde: path_checker = tur (setting: multipath internal) 278s 74.456170 | sde: checker timeout = 30 s (setting: kernel sysfs) 278s 74.456357 | sde: tur state = up 278s 74.456503 | loop0: device node name blacklisted 278s 74.456636 | loop1: device node name blacklisted 278s 74.456766 | loop2: device node name blacklisted 278s 74.456895 | loop3: device node name blacklisted 278s 74.457025 | loop4: device node name blacklisted 278s 74.457154 | loop5: device node name blacklisted 278s 74.457282 | loop6: device node name blacklisted 278s 74.457411 | loop7: device node name blacklisted 278s 74.457548 | dm-0: device node name blacklisted 278s 74.458617 | multipath-tools v0.9.4 (12/19, 2022) 278s 74.458675 | libdevmapper version 1.02.185 278s 74.458834 | kernel device mapper v4.48.0 278s 74.458886 | DM multipath kernel driver v1.14.0 278s 74.459024 | sdb: size = 204800 278s 74.459070 | sdb: vendor = IET 278s 74.459092 | sdb: product = VIRTUAL-DISK 278s 74.459114 | sdb: rev = 0001 278s 74.459806 | sdb: h:b:t:l = 1:0:0:1 278s 74.459968 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 278s 74.460065 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 278s 74.460132 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 278s 74.460168 | sdb: serial = beaf11 278s 74.460540 | sdb: tur state = up 278s 74.460586 | sdb: uid = 360000000000000000e00000000010001 (udev) 278s 74.460608 | sdb: detect_prio = yes (setting: multipath internal) 278s 74.460630 | sdb: prio = const (setting: multipath internal) 278s 74.460651 | sdb: prio args = "" (setting: multipath internal) 278s 74.460672 | sdb: const prio = 1 278s 74.460719 | sdc: size = 204800 278s 74.460762 | sdc: vendor = IET 278s 74.460785 | sdc: product = VIRTUAL-DISK 278s 74.460807 | sdc: rev = 0001 278s 74.461464 | sdc: h:b:t:l = 2:0:0:1 278s 74.461625 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 278s 74.461687 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 278s 74.461710 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 278s 74.461743 | sdc: serial = beaf11 278s 74.461972 | sdc: tur state = up 278s 74.462017 | sdc: uid = 360000000000000000e00000000010001 (udev) 278s 74.462038 | sdc: detect_prio = yes (setting: multipath internal) 278s 74.462060 | sdc: prio = const (setting: multipath internal) 278s 74.462080 | sdc: prio args = "" (setting: multipath internal) 278s 74.462101 | sdc: const prio = 1 278s 74.462149 | sdd: size = 204800 278s 74.462192 | sdd: vendor = IET 278s 74.462214 | sdd: product = VIRTUAL-DISK 278s 74.462235 | sdd: rev = 0001 278s 74.462895 | sdd: h:b:t:l = 3:0:0:1 278s 74.463059 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 278s 74.463121 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 278s 74.463144 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 278s 74.463177 | sdd: serial = beaf11 278s 74.463383 | sdd: tur state = up 278s 74.463428 | sdd: uid = 360000000000000000e00000000010001 (udev) 278s 74.463449 | sdd: detect_prio = yes (setting: multipath internal) 278s 74.463471 | sdd: prio = const (setting: multipath internal) 278s 74.463491 | sdd: prio args = "" (setting: multipath internal) 278s 74.463504 | sdd: const prio = 1 278s 74.463531 | sde: size = 204800 278s 74.463535 | sde: vendor = IET 278s 74.463538 | sde: product = VIRTUAL-DISK 278s 74.463540 | sde: rev = 0001 278s 74.464208 | sde: h:b:t:l = 4:0:0:1 278s 74.464351 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 278s 74.464391 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 278s 74.464394 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 278s 74.464407 | sde: serial = beaf11 278s 74.464598 | sde: tur state = up 278s 74.464619 | sde: uid = 360000000000000000e00000000010001 (udev) 278s 74.464622 | sde: detect_prio = yes (setting: multipath internal) 278s 74.464624 | sde: prio = const (setting: multipath internal) 278s 74.464626 | sde: prio args = "" (setting: multipath internal) 278s 74.464629 | sde: const prio = 1 278s 74.465518 | unloading tur checker 278s ===== paths list ===== 278s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 278s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 278s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 278s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 278s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 278s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 278s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 278s size=100M features='0' hwhandler='0' wp=rw 278s |-+- policy='service-time 0' prio=1 status=active 278s | `- 1:0:0:1 sdb 8:16 active ready running 278s |-+- policy='service-time 0' prio=1 status=enabled 278s | `- 2:0:0:1 sdc 8:32 active ready running 278s |-+- policy='service-time 0' prio=1 status=enabled 278s | `- 3:0:0:1 sdd 8:48 active ready running 278s `-+- policy='service-time 0' prio=1 status=enabled 278s `- 4:0:0:1 sde 8:64 active ready running 278s 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 278s Test WWN should now point to DM 278s ../../dm-0 278s Creating filesystem with 25600 4k blocks and 25600 inodes 278s 278s Allocating group tables: 0/1 done 278s Writing inode tables: 0/1 done 278s Creating journal (1024 blocks): done 278s Writing superblocks and filesystem accounting information: 0/1 done 278s 278s 74.465588 | unloading const prioritizer 278s + dmsetup table 278s + echo Test WWN should now point to DM 278s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 278s + grep dm 278s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 278s mke2fs 1.47.0 (5-Feb-2023) 278s + udevadm settle 278s + sleep 3s 281s + mkdir -p /mnt/tgtmpathtest 281s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 281s + cat 281s + cat 281s + fio --max-jobs=4 /tmp/autopkgtest.i2kswK/tgtbasedmpaths-artifacts/path-change-prep.fio 281s 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 281s fio-3.36 281s Starting 1 thread 281s write-phase: Laying out IO file (1 file / 17592186044415MiB) 282s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 282s 282s write-phase: (groupid=0, jobs=1): err= 0: pid=5544: Mon Mar 18 17:14:37 2024 282s write: IOPS=1911, BW=119MiB/s (125MB/s)(87.6MiB/734msec); 0 zone resets 282s clat (usec): min=295, max=3099, avg=499.01, stdev=190.88 282s lat (usec): min=309, max=3133, avg=521.53, stdev=193.61 282s clat percentiles (usec): 282s | 1.00th=[ 318], 5.00th=[ 347], 10.00th=[ 363], 20.00th=[ 379], 282s | 30.00th=[ 412], 40.00th=[ 457], 50.00th=[ 478], 60.00th=[ 515], 282s | 70.00th=[ 545], 80.00th=[ 562], 90.00th=[ 603], 95.00th=[ 652], 282s | 99.00th=[ 1319], 99.50th=[ 1844], 99.90th=[ 2769], 99.95th=[ 3097], 282s | 99.99th=[ 3097] 282s bw ( KiB/s): min=116352, max=116352, per=95.18%, avg=116352.00, stdev= 0.00, samples=1 282s iops : min= 1818, max= 1818, avg=1818.00, stdev= 0.00, samples=1 282s lat (usec) : 500=56.52%, 750=40.84%, 1000=0.93% 282s lat (msec) : 2=1.28%, 4=0.36% 282s cpu : usr=5.32%, sys=8.87%, ctx=1405, majf=0, minf=0 282s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 282s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 282s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 282s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 282s latency : target=0, window=0, percentile=100.00%, depth=1 282s 282s Run status group 0 (all jobs): 282s WRITE: bw=119MiB/s (125MB/s), 119MiB/s-119MiB/s (125MB/s-125MB/s), io=87.6MiB (91.9MB), run=734-734msec 282s 282s Disk stats (read/write): 282s dm-0: ios=1/1166, sectors=8/149248, merge=0/0, ticks=1/648, in_queue=648, util=86.60%, aggrios=0/351, aggsectors=2/44884, aggrmerge=0/0, aggrticks=0/164, aggrin_queue=164, aggrutil=87.00% 282s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 282s sdb: ios=1/1404, sectors=8/179536, merge=0/0, ticks=0/658, in_queue=659, util=87.00% 282s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 282s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 282s + echo Starting the path changes in background 282s Starting the path changes in background 282s + date +Pre FIO %H:%M:%S.%N 282s Pre FIO 17:14:37.705584726 282s + fio --max-jobs=4 /tmp/autopkgtest.i2kswK/tgtbasedmpaths-artifacts/path-change-check.fio 282s 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 282s fio-3.36 282s Starting 1 thread 462s 462s verify-phase: (groupid=0, jobs=1): err= 0: pid=5551: Mon Mar 18 17:17:37 2024 462s read: IOPS=2981, BW=186MiB/s (195MB/s)(32.8GiB/180001msec) 462s clat (usec): min=85, max=48771, avg=312.26, stdev=273.97 462s lat (usec): min=85, max=48771, avg=312.38, stdev=273.97 462s clat percentiles (usec): 462s | 1.00th=[ 139], 5.00th=[ 169], 10.00th=[ 188], 20.00th=[ 202], 462s | 30.00th=[ 219], 40.00th=[ 247], 50.00th=[ 285], 60.00th=[ 314], 462s | 70.00th=[ 343], 80.00th=[ 371], 90.00th=[ 420], 95.00th=[ 498], 462s | 99.00th=[ 1012], 99.50th=[ 1532], 99.90th=[ 3621], 99.95th=[ 4555], 462s | 99.99th=[ 7701] 462s bw ( KiB/s): min=106880, max=333440, per=100.00%, avg=191135.04, stdev=44481.58, samples=359 462s iops : min= 1670, max= 5210, avg=2986.41, stdev=695.02, samples=359 462s lat (usec) : 100=0.13%, 250=40.39%, 500=54.64%, 750=3.15%, 1000=0.67% 462s lat (msec) : 2=0.72%, 4=0.23%, 10=0.08%, 20=0.01%, 50=0.01% 462s cpu : usr=8.18%, sys=8.28%, ctx=536831, majf=0, minf=1 462s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 462s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 462s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 462s issued rwts: total=536754,0,0,0 short=0,0,0,0 dropped=0,0,0,0 462s latency : target=0, window=0, percentile=100.00%, depth=1 462s 462s Run status group 0 (all jobs): 462s READ: bw=186MiB/s (195MB/s), 186MiB/s-186MiB/s (195MB/s-195MB/s), io=32.8GiB (35.2GB), run=180001-180001msec 462s 462s Disk stats (read/write): 462s dm-0: ios=536939/9, sectors=68676664/12912, merge=14/8, ticks=171352/66, in_queue=171459, util=99.94%, aggrios=39754/2, aggsectors=5084238/3228, aggrmerge=0/0, aggrticks=10909/6, aggrin_queue=10915, aggrutil=99.09% 462s sdd: ios=28330/0, sectors=3623680/0, merge=0/0, ticks=8988/0, in_queue=8988, util=33.47% 462s sdb: ios=29054/8, sectors=3716096/12912, merge=0/0, ticks=8562/25, in_queue=8587, util=99.09% 462s sde: ios=65702/0, sectors=8403840/0, merge=0/0, ticks=17474/0, in_queue=17474, util=39.94% 462s sdc: ios=35931/0, sectors=4593336/0, merge=0/0, ticks=8614/0, in_queue=8613, util=50.04% 462s Post FIO 17:17:37.921048515 462s FIO verify test with changing paths - OK 462s Report log of background activity 462s + date +Post FIO %H:%M:%S.%N 462s + echo FIO verify test with changing paths - OK 462s + echo Report log of background activity 462s + cat /tmp/autopkgtest.i2kswK/tgtbasedmpaths-artifacts/test-background.log 463s + sync 463s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 463s + echo Final stats 463s + iscsiadm --mode session --stats 463s + journalctl --no-pager -u multipathd 463s + iscsiadm --mode session 463s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s + sleep 10s 463s + date +MP report (expect 4) %H:%M:%S.%N 463s MP report (expect 4) 17:14:47.712485959 463s + multipath -ll 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s |-+- policy='service-time 0' prio=1 status=active 463s | `- 1:0:0:1 sdb 8:16 active ready running 463s |-+- policy='service-time 0' prio=1 status=enabled 463s | `- 2:0:0:1 sdc 8:32 active ready running 463s |-+- policy='service-time 0' prio=1 status=enabled 463s | `- 3:0:0:1 sdd 8:48 active ready running 463s `-+- policy='service-time 0' prio=1 status=enabled 463s `- 4:0:0:1 sde 8:64 active ready running 463s + date +UN-plug path 1 %H:%M:%S.%N 463s UN-plug path 1 17:14:47.740507688 463s + iscsiadm --mode session -r 1 -u 463s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session 463s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s + sleep 10s 463s + date +MP report (expect 3) %H:%M:%S.%N 463s MP report (expect 3) 17:14:57.839330648 463s + multipath -ll 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s |-+- policy='service-time 0' prio=1 status=active 463s | `- 2:0:0:1 sdc 8:32 active ready running 463s |-+- policy='service-time 0' prio=1 status=enabled 463s | `- 3:0:0:1 sdd 8:48 active ready running 463s `-+- policy='service-time 0' prio=1 status=enabled 463s `- 4:0:0:1 sde 8:64 active ready running 463s + date +UN-plug path 2 %H:%M:%S.%N 463s UN-plug path 2 17:14:57.867358764 463s + iscsiadm --mode session -r 2 -u 463s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session 463s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s + sleep 10s 463s + date +MP report (expect 2) %H:%M:%S.%N 463s MP report (expect 2) 17:15:07.994617290 463s + multipath -ll 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s |-+- policy='service-time 0' prio=1 status=active 463s | `- 3:0:0:1 sdd 8:48 active ready running 463s `-+- policy='service-time 0' prio=1 status=enabled 463s `- 4:0:0:1 sde 8:64 active ready running 463s + date +UN-plug path 3 %H:%M:%S.%N 463s UN-plug path 3 17:15:08.017321533 463s + iscsiadm --mode session -r 3 -u 463s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session 463s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s + sleep 10s 463s + date +MP report (expect 1) %H:%M:%S.%N 463s MP report (expect 1) 17:15:18.114743601 463s + multipath -ll 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s `-+- policy='service-time 0' prio=1 status=active 463s `- 4:0:0:1 sde 8:64 active ready running 463s + date +Add paths 5/6/7/8 %H:%M:%S.%N 463s Add paths 5/6/7/8 17:15:18.129512889 463s + iscsiadm --mode session -r 4 --op new 463s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 463s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session -r 4 --op new 463s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 463s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session -r 4 --op new 463s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 463s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session -r 4 --op new 463s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 463s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session 463s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s + sleep 10s 463s + date +MP report (expect 5) %H:%M:%S.%N 463s MP report (expect 5) 17:15:28.298913391 463s + multipath -ll 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s |-+- policy='service-time 0' prio=1 status=active 463s | `- 4:0:0:1 sde 8:64 active ready running 463s |-+- policy='service-time 0' prio=1 status=enabled 463s | `- 1:0:0:1 sdb 8:16 active ready running 463s |-+- policy='service-time 0' prio=1 status=enabled 463s | `- 2:0:0:1 sdc 8:32 active ready running 463s |-+- policy='service-time 0' prio=1 status=enabled 463s | `- 3:0:0:1 sdd 8:48 active ready running 463s `-+- policy='service-time 0' prio=1 status=enabled 463s `- 5:0:0:1 sdf 8:80 active ready running 463s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 463s UN-plug multiple paths 4/7/8 17:15:28.345302409 463s + iscsiadm --mode session -r 4 -u 463s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session -r 7 -u 463s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session -r 8 -u 463s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session 463s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s + sleep 10s 463s + date +Restart multipath daemon %H:%M:%S.%N 463s Restart multipath daemon 17:15:38.670174020 463s + systemctl restart multipathd 463s + sleep 10s 463s + date +Final background report (expect 2) %H:%M:%S.%N 463s Final background report (expect 2) 17:15:48.761554717 463s + multipath -ll 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s |-+- policy='service-time 0' prio=1 status=active 463s | `- 1:0:0:1 sdb 8:16 active ready running 463s `-+- policy='service-time 0' prio=1 status=enabled 463s `- 2:0:0:1 sdc 8:32 active ready running 463s Final stats 463s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s iSCSI SNMP: 463s txdata_octets: 18112296 463s rxdata_octets: 24706954020 463s noptx_pdus: 0 463s scsicmd_pdus: 377072 463s tmfcmd_pdus: 0 463s login_pdus: 0 463s text_pdus: 0 463s dataout_pdus: 0 463s logout_pdus: 0 463s snack_pdus: 0 463s noprx_pdus: 0 463s scsirsp_pdus: 377072 463s tmfrsp_pdus: 0 463s textrsp_pdus: 0 463s datain_pdus: 377037 463s logoutrsp_pdus: 0 463s r2t_pdus: 0 463s async_pdus: 0 463s rjt_pdus: 0 463s digest_err: 0 463s timeout_err: 0 463s iSCSI Extended: 463s tx_sendpage_failures: 0 463s rx_discontiguous_hdr: 0 463s eh_abort_cnt: 0 463s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s iSCSI SNMP: 463s txdata_octets: 5976 463s rxdata_octets: 1514324 463s noptx_pdus: 0 463s scsicmd_pdus: 94 463s tmfcmd_pdus: 0 463s login_pdus: 0 463s text_pdus: 0 463s dataout_pdus: 0 463s logout_pdus: 0 463s snack_pdus: 0 463s noprx_pdus: 0 463s scsirsp_pdus: 94 463s tmfrsp_pdus: 0 463s textrsp_pdus: 0 463s datain_pdus: 72 463s logoutrsp_pdus: 0 463s r2t_pdus: 0 463s async_pdus: 0 463s rjt_pdus: 0 463s digest_err: 0 463s timeout_err: 0 463s iSCSI Extended: 463s tx_sendpage_failures: 0 463s rx_discontiguous_hdr: 0 463s eh_abort_cnt: 0 463s Mar 18 00:51:12 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 463s Mar 18 00:51:12 ubuntu multipathd[325]: multipathd v0.9.4: start up 463s Mar 18 00:51:12 ubuntu multipathd[325]: reconfigure: setting up paths and maps 463s Mar 18 00:51:12 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 463s Mar 18 00:53:56 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 multipathd[325]: multipathd: shut down 463s Mar 18 00:53:56 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 463s Mar 18 00:53:57 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: multipathd.service: Deactivated successfully. 463s Mar 18 00:53:57 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 463s -- Boot 6a3b000ef30f411788375f8bd1174ee8 -- 463s Mar 18 00:54:21 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 463s Mar 18 00:54:21 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 multipathd[262]: multipathd v0.9.4: start up 463s Mar 18 00:54:21 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 multipathd[262]: reconfigure: setting up paths and maps 463s Mar 18 00:54:21 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 463s Mar 18 00:54:35 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 multipathd[262]: multipathd: shut down 463s Mar 18 00:54:35 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 463s Mar 18 00:54:35 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: multipathd.service: Deactivated successfully. 463s Mar 18 00:54:35 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 463s -- Boot d95172ada3804248a73a4f63dde02d49 -- 463s Mar 18 17:13:21 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 463s Mar 18 17:13:21 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 multipathd[314]: multipathd v0.9.4: start up 463s Mar 18 17:13:21 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 multipathd[314]: reconfigure: setting up paths and maps 463s Mar 18 17:13:21 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 463s Mar 18 17:14:28 autopkgtest multipathd[314]: 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] 463s Mar 18 17:14:28 autopkgtest multipathd[314]: sdc [8:32]: path added to devmap mpatha 463s Mar 18 17:14:28 autopkgtest multipathd[314]: mpatha: performing delayed actions 463s Mar 18 17:14:28 autopkgtest multipathd[314]: 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] 463s Mar 18 17:14:47 autopkgtest multipathd[314]: 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] 463s Mar 18 17:14:47 autopkgtest multipathd[314]: check_removed_paths: sdb: freeing path in removed state 463s Mar 18 17:14:47 autopkgtest multipathd[314]: 8:16: path removed from map mpatha 463s Mar 18 17:14:57 autopkgtest multipathd[314]: sdc: mark as failed 463s Mar 18 17:14:57 autopkgtest multipathd[314]: mpatha: remaining active paths: 2 463s Mar 18 17:14:57 autopkgtest multipathd[314]: 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] 463s Mar 18 17:14:57 autopkgtest multipathd[314]: check_removed_paths: sdc: freeing path in removed state 463s Mar 18 17:14:57 autopkgtest multipathd[314]: 8:32: path removed from map mpatha 463s Mar 18 17:15:08 autopkgtest multipathd[314]: mpatha: reload [0 2048+ echo Check final path status 463s + multipath -ll 463s + multipath -ll 463s + grep --count status= 463s + diskc=2 463s + multipath -ll 463s + grep --count status=active 463s + diska=1 463s + multipath -ll 463s + grep --count status=enabled 463s + diske=1 463s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 463s + echo OK 463s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 463s 00 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 463s Mar 18 17:15:08 autopkgtest multipathd[314]: check_removed_paths: sdd: freeing path in removed state 463s Mar 18 17:15:08 autopkgtest multipathd[314]: 8:48: path removed from map mpatha 463s Mar 18 17:15:18 autopkgtest multipathd[314]: 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] 463s Mar 18 17:15:18 autopkgtest multipathd[314]: sdb [8:16]: path added to devmap mpatha 463s Mar 18 17:15:18 autopkgtest multipathd[314]: 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] 463s Mar 18 17:15:18 autopkgtest multipathd[314]: sdc [8:32]: path added to devmap mpatha 463s Mar 18 17:15:18 autopkgtest multipathd[314]: 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] 463s Mar 18 17:15:18 autopkgtest multipathd[314]: sdd [8:48]: path added to devmap mpatha 463s Mar 18 17:15:18 autopkgtest multipathd[314]: 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] 463s Mar 18 17:15:18 autopkgtest multipathd[314]: sdf [8:80]: path added to devmap mpatha 463s Mar 18 17:15:28 autopkgtest multipathd[314]: sde: mark as failed 463s Mar 18 17:15:28 autopkgtest multipathd[314]: mpatha: remaining active paths: 4 463s Mar 18 17:15:28 autopkgtest multipathd[314]: 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] 463s Mar 18 17:15:28 autopkgtest multipathd[314]: check_removed_paths: sde: freeing path in removed state 463s Mar 18 17:15:28 autopkgtest multipathd[314]: 8:64: path removed from map mpatha 463s Mar 18 17:15:28 autopkgtest multipathd[314]: 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] 463s Mar 18 17:15:28 autopkgtest multipathd[314]: check_removed_paths: sdd: freeing path in removed state 463s Mar 18 17:15:28 autopkgtest multipathd[314]: 8:48: path removed from map mpatha 463s Mar 18 17:15:28 autopkgtest multipathd[314]: 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] 463s Mar 18 17:15:28 autopkgtest multipathd[314]: check_removed_paths: sdf: freeing path in removed state 463s Mar 18 17:15:28 autopkgtest multipathd[314]: 8:80: path removed from map mpatha 463s Mar 18 17:15:38 autopkgtest multipathd[314]: multipathd: shut down 463s Mar 18 17:15:38 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 463s Mar 18 17:15:38 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 463s Mar 18 17:15:38 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 463s Mar 18 17:15:38 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 463s Mar 18 17:15:38 autopkgtest multipathd[5941]: multipathd v0.9.4: start up 463s Mar 18 17:15:38 autopkgtest multipathd[5941]: reconfigure: setting up paths and maps 463s Mar 18 17:15:38 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 463s Check final path status 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s |-+- policy='service-time 0' prio=1 status=active 463s | `- 1:0:0:1 sdb 8:16 active ready running 463s `-+- policy='service-time 0' prio=1 status=enabled 463s `- 2:0:0:1 sdc 8:32 active ready running 463s OK 463s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 463s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s autopkgtest [17:17:38]: test tgtbasedmpaths: -----------------------] 464s tgtbasedmpaths PASS 464s autopkgtest [17:17:39]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 464s autopkgtest [17:17:39]: @@@@@@@@@@@@@@@@@@@@ summary 464s kpartx-file-loopback PASS 464s tgtbasedmpaths PASS 496s Creating nova instance adt-noble-ppc64el-multipath-tools-20240318-170955-juju-7f2275-prod-proposed-migration-environment-2 from image adt/ubuntu-noble-ppc64el-server-20240318.img (UUID 290ce4c5-ca44-4691-9a55-79589f8700e4)... 496s Creating nova instance adt-noble-ppc64el-multipath-tools-20240318-170955-juju-7f2275-prod-proposed-migration-environment-2 from image adt/ubuntu-noble-ppc64el-server-20240318.img (UUID 290ce4c5-ca44-4691-9a55-79589f8700e4)...