0s autopkgtest [10:34:02]: starting date and time: 2024-04-03 10:34:02+0000 0s autopkgtest [10:34:02]: git checkout: 31124158 autopkgtest: take Paride's WIP change regarding wrong src pkg selection 0s autopkgtest [10:34:02]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.peenovj_/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:initramfs-tools --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=initramfs-tools/0.136ubuntu6.8 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos01-ppc64el-14.secgroup --name adt-focal-ppc64el-multipath-tools-20240403-103401-juju-7f2275-prod-proposed-migration-environment-2-3f5b4789-a7a4-4e72-a53b-f44ddce99aa3 --image adt/ubuntu-focal-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://us.ports.ubuntu.com/ubuntu-ports/ 233s autopkgtest [10:37:55]: testbed dpkg architecture: ppc64el 233s autopkgtest [10:37:55]: testbed apt version: 2.0.10 233s autopkgtest [10:37:55]: @@@@@@@@@@@@@@@@@@@@ test bed setup 234s Get:1 http://ftpmaster.internal/ubuntu focal-proposed InRelease [267 kB] 235s Get:2 http://ftpmaster.internal/ubuntu focal-proposed/restricted Sources [19.7 kB] 235s Get:3 http://ftpmaster.internal/ubuntu focal-proposed/main Sources [72.0 kB] 235s Get:4 http://ftpmaster.internal/ubuntu focal-proposed/universe Sources [14.2 kB] 235s Get:5 http://ftpmaster.internal/ubuntu focal-proposed/main ppc64el Packages [123 kB] 235s Get:6 http://ftpmaster.internal/ubuntu focal-proposed/main ppc64el c-n-f Metadata [1580 B] 235s Get:7 http://ftpmaster.internal/ubuntu focal-proposed/restricted ppc64el Packages [1188 B] 235s Get:8 http://ftpmaster.internal/ubuntu focal-proposed/restricted ppc64el c-n-f Metadata [116 B] 235s Get:9 http://ftpmaster.internal/ubuntu focal-proposed/universe ppc64el Packages [40.8 kB] 235s Get:10 http://ftpmaster.internal/ubuntu focal-proposed/universe ppc64el c-n-f Metadata [2420 B] 235s Get:11 http://ftpmaster.internal/ubuntu focal-proposed/multiverse ppc64el c-n-f Metadata [116 B] 240s Fetched 542 kB in 1s (505 kB/s) 240s Reading package lists... 243s Reading package lists... 243s Building dependency tree... 243s Reading state information... 243s Calculating upgrade... 243s The following packages will be upgraded: 243s initramfs-tools initramfs-tools-bin initramfs-tools-core 244s 3 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 244s Need to get 69.2 kB of archives. 244s After this operation, 0 B of additional disk space will be used. 244s Get:1 http://ftpmaster.internal/ubuntu focal-proposed/main ppc64el initramfs-tools all 0.136ubuntu6.8 [9212 B] 244s Get:2 http://ftpmaster.internal/ubuntu focal-proposed/main ppc64el initramfs-tools-core all 0.136ubuntu6.8 [47.8 kB] 244s Get:3 http://ftpmaster.internal/ubuntu focal-proposed/main ppc64el initramfs-tools-bin ppc64el 0.136ubuntu6.8 [12.2 kB] 244s Fetched 69.2 kB in 0s (166 kB/s) 244s (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 ... 94039 files and directories currently installed.) 244s Preparing to unpack .../initramfs-tools_0.136ubuntu6.8_all.deb ... 244s Unpacking initramfs-tools (0.136ubuntu6.8) over (0.136ubuntu6.7) ... 244s Preparing to unpack .../initramfs-tools-core_0.136ubuntu6.8_all.deb ... 244s Unpacking initramfs-tools-core (0.136ubuntu6.8) over (0.136ubuntu6.7) ... 244s Preparing to unpack .../initramfs-tools-bin_0.136ubuntu6.8_ppc64el.deb ... 244s Unpacking initramfs-tools-bin (0.136ubuntu6.8) over (0.136ubuntu6.7) ... 244s Setting up initramfs-tools-bin (0.136ubuntu6.8) ... 244s Setting up initramfs-tools-core (0.136ubuntu6.8) ... 244s Setting up initramfs-tools (0.136ubuntu6.8) ... 244s update-initramfs: deferring update (trigger activated) 244s Processing triggers for man-db (2.9.1-1) ... 245s Processing triggers for initramfs-tools (0.136ubuntu6.8) ... 245s update-initramfs: Generating /boot/initrd.img-5.4.0-174-generic 263s Reading package lists... 263s Building dependency tree... 263s Reading state information... 263s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 264s Hit:1 http://ftpmaster.internal/ubuntu focal InRelease 264s Hit:2 http://ftpmaster.internal/ubuntu focal-updates InRelease 264s Hit:3 http://ftpmaster.internal/ubuntu focal-security InRelease 264s Hit:4 http://ftpmaster.internal/ubuntu focal-proposed InRelease 265s Reading package lists... 265s Reading package lists... 265s Building dependency tree... 265s Reading state information... 265s Calculating upgrade... 265s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 266s Reading package lists... 266s Building dependency tree... 266s Reading state information... 266s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 266s autopkgtest [10:38:28]: rebooting testbed after setup commands that affected boot 434s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 451s autopkgtest [10:41:33]: testbed running kernel: Linux 5.4.0-174-generic #193-Ubuntu SMP Thu Mar 7 14:29:28 UTC 2024 454s autopkgtest [10:41:36]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 460s Get:1 http://ftpmaster.internal/ubuntu focal-updates/main multipath-tools 0.8.3-1ubuntu2.3 (dsc) [2882 B] 460s Get:2 http://ftpmaster.internal/ubuntu focal-updates/main multipath-tools 0.8.3-1ubuntu2.3 (tar) [465 kB] 460s Get:3 http://ftpmaster.internal/ubuntu focal-updates/main multipath-tools 0.8.3-1ubuntu2.3 (diff) [53.9 kB] 460s gpgv: Signature made Tue Nov 7 21:58:20 2023 UTC 460s gpgv: using RSA key 8F8D83B5270649A080648255EAF23F4A0BD34BF0 460s gpgv: issuer "mfo@canonical.com" 460s gpgv: Can't check signature: No public key 460s dpkg-source: warning: failed to verify signature on ./multipath-tools_0.8.3-1ubuntu2.3.dsc 460s autopkgtest [10:41:42]: testing package multipath-tools version 0.8.3-1ubuntu2.3 461s autopkgtest [10:41:43]: build not needed 464s autopkgtest [10:41:46]: test kpartx-file-loopback: preparing testbed 466s Reading package lists... 466s Building dependency tree... 466s Reading state information... 466s Starting pkgProblemResolver with broken count: 0 466s Starting 2 pkgProblemResolver with broken count: 0 466s Done 466s The following additional packages will be installed: 466s libboost-iostreams1.71.0 libboost-thread1.71.0 libibverbs1 libiscsi7 466s libnl-route-3-200 librados2 librbd1 librdmacm1 qemu-block-extra qemu-utils 466s Suggested packages: 466s debootstrap 466s Recommended packages: 466s ibverbs-providers sharutils 466s The following NEW packages will be installed: 466s autopkgtest-satdep libboost-iostreams1.71.0 libboost-thread1.71.0 466s libibverbs1 libiscsi7 libnl-route-3-200 librados2 librbd1 librdmacm1 466s qemu-block-extra qemu-utils 466s 0 upgraded, 11 newly installed, 0 to remove and 0 not upgraded. 466s Need to get 6461 kB/6462 kB of archives. 466s After this operation, 36.4 MB of additional disk space will be used. 466s Get:1 /tmp/autopkgtest.kDDgu3/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 466s Get:2 http://ftpmaster.internal/ubuntu focal/main ppc64el libboost-iostreams1.71.0 ppc64el 1.71.0-6ubuntu6 [235 kB] 467s Get:3 http://ftpmaster.internal/ubuntu focal/main ppc64el libboost-thread1.71.0 ppc64el 1.71.0-6ubuntu6 [249 kB] 467s Get:4 http://ftpmaster.internal/ubuntu focal-updates/main ppc64el libnl-route-3-200 ppc64el 3.4.0-1ubuntu0.1 [156 kB] 467s Get:5 http://ftpmaster.internal/ubuntu focal/main ppc64el libibverbs1 ppc64el 28.0-1ubuntu1 [56.8 kB] 467s Get:6 http://ftpmaster.internal/ubuntu focal/main ppc64el librdmacm1 ppc64el 28.0-1ubuntu1 [70.1 kB] 467s Get:7 http://ftpmaster.internal/ubuntu focal/main ppc64el libiscsi7 ppc64el 1.18.0-2 [69.4 kB] 467s Get:8 http://ftpmaster.internal/ubuntu focal-updates/main ppc64el librados2 ppc64el 15.2.17-0ubuntu0.20.04.6 [3111 kB] 468s Get:9 http://ftpmaster.internal/ubuntu focal-updates/main ppc64el librbd1 ppc64el 15.2.17-0ubuntu0.20.04.6 [1462 kB] 468s Get:10 http://ftpmaster.internal/ubuntu focal-updates/main ppc64el qemu-block-extra ppc64el 1:4.2-3ubuntu6.28 [56.0 kB] 468s Get:11 http://ftpmaster.internal/ubuntu focal-updates/main ppc64el qemu-utils ppc64el 1:4.2-3ubuntu6.28 [996 kB] 469s Fetched 6461 kB in 2s (3079 kB/s) 469s Selecting previously unselected package libboost-iostreams1.71.0:ppc64el. 469s (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 ... 94039 files and directories currently installed.) 469s Preparing to unpack .../00-libboost-iostreams1.71.0_1.71.0-6ubuntu6_ppc64el.deb ... 469s Unpacking libboost-iostreams1.71.0:ppc64el (1.71.0-6ubuntu6) ... 469s Selecting previously unselected package libboost-thread1.71.0:ppc64el. 469s Preparing to unpack .../01-libboost-thread1.71.0_1.71.0-6ubuntu6_ppc64el.deb ... 469s Unpacking libboost-thread1.71.0:ppc64el (1.71.0-6ubuntu6) ... 469s Selecting previously unselected package libnl-route-3-200:ppc64el. 469s Preparing to unpack .../02-libnl-route-3-200_3.4.0-1ubuntu0.1_ppc64el.deb ... 469s Unpacking libnl-route-3-200:ppc64el (3.4.0-1ubuntu0.1) ... 469s Selecting previously unselected package libibverbs1:ppc64el. 469s Preparing to unpack .../03-libibverbs1_28.0-1ubuntu1_ppc64el.deb ... 469s Unpacking libibverbs1:ppc64el (28.0-1ubuntu1) ... 469s Selecting previously unselected package librdmacm1:ppc64el. 469s Preparing to unpack .../04-librdmacm1_28.0-1ubuntu1_ppc64el.deb ... 469s Unpacking librdmacm1:ppc64el (28.0-1ubuntu1) ... 469s Selecting previously unselected package libiscsi7:ppc64el. 469s Preparing to unpack .../05-libiscsi7_1.18.0-2_ppc64el.deb ... 469s Unpacking libiscsi7:ppc64el (1.18.0-2) ... 469s Selecting previously unselected package librados2. 469s Preparing to unpack .../06-librados2_15.2.17-0ubuntu0.20.04.6_ppc64el.deb ... 469s Unpacking librados2 (15.2.17-0ubuntu0.20.04.6) ... 469s Selecting previously unselected package librbd1. 469s Preparing to unpack .../07-librbd1_15.2.17-0ubuntu0.20.04.6_ppc64el.deb ... 469s Unpacking librbd1 (15.2.17-0ubuntu0.20.04.6) ... 469s Selecting previously unselected package qemu-block-extra:ppc64el. 469s Preparing to unpack .../08-qemu-block-extra_1%3a4.2-3ubuntu6.28_ppc64el.deb ... 469s Unpacking qemu-block-extra:ppc64el (1:4.2-3ubuntu6.28) ... 469s Selecting previously unselected package qemu-utils. 469s Preparing to unpack .../09-qemu-utils_1%3a4.2-3ubuntu6.28_ppc64el.deb ... 469s Unpacking qemu-utils (1:4.2-3ubuntu6.28) ... 470s Selecting previously unselected package autopkgtest-satdep. 470s Preparing to unpack .../10-1-autopkgtest-satdep.deb ... 470s Unpacking autopkgtest-satdep (0) ... 470s Setting up libboost-iostreams1.71.0:ppc64el (1.71.0-6ubuntu6) ... 470s Setting up libnl-route-3-200:ppc64el (3.4.0-1ubuntu0.1) ... 470s Setting up libboost-thread1.71.0:ppc64el (1.71.0-6ubuntu6) ... 470s Setting up libibverbs1:ppc64el (28.0-1ubuntu1) ... 470s Setting up librdmacm1:ppc64el (28.0-1ubuntu1) ... 470s Setting up librados2 (15.2.17-0ubuntu0.20.04.6) ... 470s Setting up librbd1 (15.2.17-0ubuntu0.20.04.6) ... 470s Setting up libiscsi7:ppc64el (1.18.0-2) ... 470s Setting up qemu-block-extra:ppc64el (1:4.2-3ubuntu6.28) ... 470s Setting up qemu-utils (1:4.2-3ubuntu6.28) ... 470s Setting up autopkgtest-satdep (0) ... 470s Processing triggers for man-db (2.9.1-1) ... 470s Processing triggers for libc-bin (2.31-0ubuntu9.14) ... 472s (Reading database ... 94109 files and directories currently installed.) 472s Removing autopkgtest-satdep (0) ... 473s autopkgtest [10:41:55]: test kpartx-file-loopback: [----------------------- 473s Formatting 'foo.img', fmt=raw size=20971520 474s Creating new GPT entries in memory. 474s Warning: The kernel is still using the old partition table. 474s The new table will be used at the next reboot or after you 474s run partprobe(8) or kpartx(8) 474s The operation has completed successfully. 474s add map loop0p1 (253:0): 0 38879 linear 7:0 2048 474s standard_filename: OK 474s del devmap : loop0p1 474s loop deleted : /dev/loop0 474s No devices found 474s standard_filename_cleanup: OK 474s Formatting 'fou du FaFa.img', fmt=raw size=20971520 475s Creating new GPT entries in memory. 475s Warning: The kernel is still using the old partition table. 475s The new table will be used at the next reboot or after you 475s run partprobe(8) or kpartx(8) 475s The operation has completed successfully. 475s add map loop0p1 (253:0): 0 38879 linear 7:0 2048 475s filename_with_spaces: OK 475s del devmap : loop0p1 475s loop deleted : /dev/loop0 475s No devices found 475s filename_with_spaces_cleanup: OK 476s autopkgtest [10:41:58]: test kpartx-file-loopback: -----------------------] 476s autopkgtest [10:41:58]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 476s kpartx-file-loopback PASS 477s autopkgtest [10:41:59]: test tgtbasedmpaths: preparing testbed 741s autopkgtest [10:46:23]: testbed dpkg architecture: ppc64el 741s autopkgtest [10:46:23]: testbed apt version: 2.0.10 741s autopkgtest [10:46:23]: @@@@@@@@@@@@@@@@@@@@ test bed setup 741s Get:1 http://ftpmaster.internal/ubuntu focal-proposed InRelease [267 kB] 742s Get:2 http://ftpmaster.internal/ubuntu focal-proposed/main Sources [72.0 kB] 742s Get:3 http://ftpmaster.internal/ubuntu focal-proposed/restricted Sources [19.7 kB] 742s Get:4 http://ftpmaster.internal/ubuntu focal-proposed/universe Sources [14.2 kB] 742s Get:5 http://ftpmaster.internal/ubuntu focal-proposed/main ppc64el Packages [123 kB] 742s Get:6 http://ftpmaster.internal/ubuntu focal-proposed/main ppc64el c-n-f Metadata [1580 B] 742s Get:7 http://ftpmaster.internal/ubuntu focal-proposed/restricted ppc64el Packages [1188 B] 742s Get:8 http://ftpmaster.internal/ubuntu focal-proposed/restricted ppc64el c-n-f Metadata [116 B] 742s Get:9 http://ftpmaster.internal/ubuntu focal-proposed/universe ppc64el Packages [40.8 kB] 742s Get:10 http://ftpmaster.internal/ubuntu focal-proposed/universe ppc64el c-n-f Metadata [2420 B] 742s Get:11 http://ftpmaster.internal/ubuntu focal-proposed/multiverse ppc64el c-n-f Metadata [116 B] 747s Fetched 542 kB in 1s (718 kB/s) 747s Reading package lists... 750s Reading package lists... 750s Building dependency tree... 750s Reading state information... 750s Calculating upgrade... 750s The following packages will be upgraded: 750s initramfs-tools initramfs-tools-bin initramfs-tools-core 750s 3 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 750s Need to get 69.2 kB of archives. 750s After this operation, 0 B of additional disk space will be used. 750s Get:1 http://ftpmaster.internal/ubuntu focal-proposed/main ppc64el initramfs-tools all 0.136ubuntu6.8 [9212 B] 750s Get:2 http://ftpmaster.internal/ubuntu focal-proposed/main ppc64el initramfs-tools-core all 0.136ubuntu6.8 [47.8 kB] 750s Get:3 http://ftpmaster.internal/ubuntu focal-proposed/main ppc64el initramfs-tools-bin ppc64el 0.136ubuntu6.8 [12.2 kB] 751s Fetched 69.2 kB in 0s (191 kB/s) 751s (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 ... 94039 files and directories currently installed.) 751s Preparing to unpack .../initramfs-tools_0.136ubuntu6.8_all.deb ... 751s Unpacking initramfs-tools (0.136ubuntu6.8) over (0.136ubuntu6.7) ... 751s Preparing to unpack .../initramfs-tools-core_0.136ubuntu6.8_all.deb ... 751s Unpacking initramfs-tools-core (0.136ubuntu6.8) over (0.136ubuntu6.7) ... 751s Preparing to unpack .../initramfs-tools-bin_0.136ubuntu6.8_ppc64el.deb ... 751s Unpacking initramfs-tools-bin (0.136ubuntu6.8) over (0.136ubuntu6.7) ... 751s Setting up initramfs-tools-bin (0.136ubuntu6.8) ... 751s Setting up initramfs-tools-core (0.136ubuntu6.8) ... 751s Setting up initramfs-tools (0.136ubuntu6.8) ... 751s update-initramfs: deferring update (trigger activated) 751s Processing triggers for man-db (2.9.1-1) ... 751s Processing triggers for initramfs-tools (0.136ubuntu6.8) ... 751s update-initramfs: Generating /boot/initrd.img-5.4.0-174-generic 770s Reading package lists... 770s Building dependency tree... 770s Reading state information... 770s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 770s Hit:1 http://ftpmaster.internal/ubuntu focal InRelease 770s Hit:2 http://ftpmaster.internal/ubuntu focal-updates InRelease 771s Hit:3 http://ftpmaster.internal/ubuntu focal-security InRelease 771s Hit:4 http://ftpmaster.internal/ubuntu focal-proposed InRelease 772s Reading package lists... 772s Reading package lists... 772s Building dependency tree... 772s Reading state information... 772s Calculating upgrade... 772s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 772s Reading package lists... 772s Building dependency tree... 772s Reading state information... 772s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 773s autopkgtest [10:46:55]: rebooting testbed after setup commands that affected boot 882s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 905s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 929s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 954s Reading package lists... 954s Building dependency tree... 954s Reading state information... 954s Starting pkgProblemResolver with broken count: 0 954s Starting 2 pkgProblemResolver with broken count: 0 954s Done 954s The following additional packages will be installed: 954s fio libboost-iostreams1.71.0 libboost-thread1.71.0 libconfig-general-perl 954s libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libibverbs1 libisns0 954s libnl-route-3-200 libpython2.7-minimal libpython2.7-stdlib librados2 librbd1 954s librdmacm1 libtirpc-common libtirpc3 lsscsi open-iscsi python2.7 954s python2.7-minimal tgt 954s Suggested packages: 954s gnuplot gfio python-scipy python2.7-doc binfmt-support tgt-rbd 954s Recommended packages: 954s ibverbs-providers finalrd 954s The following NEW packages will be installed: 954s autopkgtest-satdep fio libboost-iostreams1.71.0 libboost-thread1.71.0 954s libconfig-general-perl libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 954s libibverbs1 libisns0 libnl-route-3-200 libpython2.7-minimal 954s libpython2.7-stdlib librados2 librbd1 librdmacm1 libtirpc-common libtirpc3 954s lsscsi open-iscsi python2.7 python2.7-minimal tgt 954s 0 upgraded, 24 newly installed, 0 to remove and 0 not upgraded. 954s Need to get 11.2 MB/11.2 MB of archives. 954s After this operation, 56.5 MB of additional disk space will be used. 954s Get:1 /tmp/autopkgtest.kDDgu3/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [736 B] 955s Get:2 http://ftpmaster.internal/ubuntu focal/main ppc64el libisns0 ppc64el 0.97-3 [129 kB] 955s Get:3 http://ftpmaster.internal/ubuntu focal-updates/main ppc64el open-iscsi ppc64el 2.0.874-7.1ubuntu6.4 [308 kB] 955s Get:4 http://ftpmaster.internal/ubuntu focal-updates/universe ppc64el libpython2.7-minimal ppc64el 2.7.18-1~20.04.4 [336 kB] 955s Get:5 http://ftpmaster.internal/ubuntu focal-updates/universe ppc64el python2.7-minimal ppc64el 2.7.18-1~20.04.4 [1466 kB] 955s Get:6 http://ftpmaster.internal/ubuntu focal-updates/main ppc64el libnl-route-3-200 ppc64el 3.4.0-1ubuntu0.1 [156 kB] 955s Get:7 http://ftpmaster.internal/ubuntu focal/main ppc64el libibverbs1 ppc64el 28.0-1ubuntu1 [56.8 kB] 955s Get:8 http://ftpmaster.internal/ubuntu focal/main ppc64el librdmacm1 ppc64el 28.0-1ubuntu1 [70.1 kB] 955s Get:9 http://ftpmaster.internal/ubuntu focal/main ppc64el libconfig-general-perl all 2.63-1 [53.9 kB] 955s Get:10 http://ftpmaster.internal/ubuntu focal/main ppc64el tgt ppc64el 1:1.0.79-2ubuntu1 [224 kB] 955s Get:11 http://ftpmaster.internal/ubuntu focal/universe ppc64el libglusterfs0 ppc64el 7.2-2build1 [297 kB] 955s Get:12 http://ftpmaster.internal/ubuntu focal-updates/main ppc64el libtirpc-common all 1.2.5-1ubuntu0.1 [7712 B] 955s Get:13 http://ftpmaster.internal/ubuntu focal-updates/main ppc64el libtirpc3 ppc64el 1.2.5-1ubuntu0.1 [90.2 kB] 955s Get:14 http://ftpmaster.internal/ubuntu focal/universe ppc64el libgfxdr0 ppc64el 7.2-2build1 [27.3 kB] 955s Get:15 http://ftpmaster.internal/ubuntu focal/universe ppc64el libgfrpc0 ppc64el 7.2-2build1 [49.4 kB] 955s Get:16 http://ftpmaster.internal/ubuntu focal/universe ppc64el libgfapi0 ppc64el 7.2-2build1 [77.1 kB] 955s Get:17 http://ftpmaster.internal/ubuntu focal/main ppc64el libboost-iostreams1.71.0 ppc64el 1.71.0-6ubuntu6 [235 kB] 955s Get:18 http://ftpmaster.internal/ubuntu focal/main ppc64el libboost-thread1.71.0 ppc64el 1.71.0-6ubuntu6 [249 kB] 955s Get:19 http://ftpmaster.internal/ubuntu focal-updates/main ppc64el librados2 ppc64el 15.2.17-0ubuntu0.20.04.6 [3111 kB] 955s Get:20 http://ftpmaster.internal/ubuntu focal-updates/main ppc64el librbd1 ppc64el 15.2.17-0ubuntu0.20.04.6 [1462 kB] 955s Get:21 http://ftpmaster.internal/ubuntu focal-updates/universe ppc64el libpython2.7-stdlib ppc64el 2.7.18-1~20.04.4 [1950 kB] 955s Get:22 http://ftpmaster.internal/ubuntu focal-updates/universe ppc64el python2.7 ppc64el 2.7.18-1~20.04.4 [248 kB] 955s Get:23 http://ftpmaster.internal/ubuntu focal/universe ppc64el fio ppc64el 3.16-1 [512 kB] 955s Get:24 http://ftpmaster.internal/ubuntu focal/main ppc64el lsscsi ppc64el 0.30-0.1 [48.3 kB] 956s Preconfiguring packages ... 956s Fetched 11.2 MB in 1s (10.9 MB/s) 956s Selecting previously unselected package libisns0:ppc64el. 956s (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 ... 94039 files and directories currently installed.) 956s Preparing to unpack .../00-libisns0_0.97-3_ppc64el.deb ... 956s Unpacking libisns0:ppc64el (0.97-3) ... 956s Selecting previously unselected package open-iscsi. 956s Preparing to unpack .../01-open-iscsi_2.0.874-7.1ubuntu6.4_ppc64el.deb ... 956s Unpacking open-iscsi (2.0.874-7.1ubuntu6.4) ... 956s Selecting previously unselected package libpython2.7-minimal:ppc64el. 956s Preparing to unpack .../02-libpython2.7-minimal_2.7.18-1~20.04.4_ppc64el.deb ... 956s Unpacking libpython2.7-minimal:ppc64el (2.7.18-1~20.04.4) ... 956s Selecting previously unselected package python2.7-minimal. 956s Preparing to unpack .../03-python2.7-minimal_2.7.18-1~20.04.4_ppc64el.deb ... 956s Unpacking python2.7-minimal (2.7.18-1~20.04.4) ... 956s Selecting previously unselected package libnl-route-3-200:ppc64el. 956s Preparing to unpack .../04-libnl-route-3-200_3.4.0-1ubuntu0.1_ppc64el.deb ... 956s Unpacking libnl-route-3-200:ppc64el (3.4.0-1ubuntu0.1) ... 957s Selecting previously unselected package libibverbs1:ppc64el. 957s Preparing to unpack .../05-libibverbs1_28.0-1ubuntu1_ppc64el.deb ... 957s Unpacking libibverbs1:ppc64el (28.0-1ubuntu1) ... 957s Selecting previously unselected package librdmacm1:ppc64el. 957s Preparing to unpack .../06-librdmacm1_28.0-1ubuntu1_ppc64el.deb ... 957s Unpacking librdmacm1:ppc64el (28.0-1ubuntu1) ... 957s Selecting previously unselected package libconfig-general-perl. 957s Preparing to unpack .../07-libconfig-general-perl_2.63-1_all.deb ... 957s Unpacking libconfig-general-perl (2.63-1) ... 957s Selecting previously unselected package tgt. 957s Preparing to unpack .../08-tgt_1%3a1.0.79-2ubuntu1_ppc64el.deb ... 957s Unpacking tgt (1:1.0.79-2ubuntu1) ... 957s Selecting previously unselected package libglusterfs0:ppc64el. 957s Preparing to unpack .../09-libglusterfs0_7.2-2build1_ppc64el.deb ... 957s Unpacking libglusterfs0:ppc64el (7.2-2build1) ... 957s Selecting previously unselected package libtirpc-common. 957s Preparing to unpack .../10-libtirpc-common_1.2.5-1ubuntu0.1_all.deb ... 957s Unpacking libtirpc-common (1.2.5-1ubuntu0.1) ... 957s Selecting previously unselected package libtirpc3:ppc64el. 957s Preparing to unpack .../11-libtirpc3_1.2.5-1ubuntu0.1_ppc64el.deb ... 957s Unpacking libtirpc3:ppc64el (1.2.5-1ubuntu0.1) ... 957s Selecting previously unselected package libgfxdr0:ppc64el. 957s Preparing to unpack .../12-libgfxdr0_7.2-2build1_ppc64el.deb ... 957s Unpacking libgfxdr0:ppc64el (7.2-2build1) ... 957s Selecting previously unselected package libgfrpc0:ppc64el. 957s Preparing to unpack .../13-libgfrpc0_7.2-2build1_ppc64el.deb ... 957s Unpacking libgfrpc0:ppc64el (7.2-2build1) ... 957s Selecting previously unselected package libgfapi0:ppc64el. 957s Preparing to unpack .../14-libgfapi0_7.2-2build1_ppc64el.deb ... 957s Unpacking libgfapi0:ppc64el (7.2-2build1) ... 957s Selecting previously unselected package libboost-iostreams1.71.0:ppc64el. 957s Preparing to unpack .../15-libboost-iostreams1.71.0_1.71.0-6ubuntu6_ppc64el.deb ... 957s Unpacking libboost-iostreams1.71.0:ppc64el (1.71.0-6ubuntu6) ... 957s Selecting previously unselected package libboost-thread1.71.0:ppc64el. 957s Preparing to unpack .../16-libboost-thread1.71.0_1.71.0-6ubuntu6_ppc64el.deb ... 957s Unpacking libboost-thread1.71.0:ppc64el (1.71.0-6ubuntu6) ... 957s Selecting previously unselected package librados2. 957s Preparing to unpack .../17-librados2_15.2.17-0ubuntu0.20.04.6_ppc64el.deb ... 957s Unpacking librados2 (15.2.17-0ubuntu0.20.04.6) ... 957s Selecting previously unselected package librbd1. 957s Preparing to unpack .../18-librbd1_15.2.17-0ubuntu0.20.04.6_ppc64el.deb ... 957s Unpacking librbd1 (15.2.17-0ubuntu0.20.04.6) ... 957s Selecting previously unselected package libpython2.7-stdlib:ppc64el. 957s Preparing to unpack .../19-libpython2.7-stdlib_2.7.18-1~20.04.4_ppc64el.deb ... 957s Unpacking libpython2.7-stdlib:ppc64el (2.7.18-1~20.04.4) ... 958s Selecting previously unselected package python2.7. 958s Preparing to unpack .../20-python2.7_2.7.18-1~20.04.4_ppc64el.deb ... 958s Unpacking python2.7 (2.7.18-1~20.04.4) ... 958s Selecting previously unselected package fio. 958s Preparing to unpack .../21-fio_3.16-1_ppc64el.deb ... 958s Unpacking fio (3.16-1) ... 958s Selecting previously unselected package lsscsi. 958s Preparing to unpack .../22-lsscsi_0.30-0.1_ppc64el.deb ... 958s Unpacking lsscsi (0.30-0.1) ... 958s Selecting previously unselected package autopkgtest-satdep. 958s Preparing to unpack .../23-2-autopkgtest-satdep.deb ... 958s Unpacking autopkgtest-satdep (0) ... 958s Setting up libconfig-general-perl (2.63-1) ... 958s Setting up libtirpc-common (1.2.5-1ubuntu0.1) ... 958s Setting up libboost-iostreams1.71.0:ppc64el (1.71.0-6ubuntu6) ... 958s Setting up libnl-route-3-200:ppc64el (3.4.0-1ubuntu0.1) ... 958s Setting up libglusterfs0:ppc64el (7.2-2build1) ... 958s Setting up libpython2.7-minimal:ppc64el (2.7.18-1~20.04.4) ... 958s Setting up python2.7-minimal (2.7.18-1~20.04.4) ... 958s Setting up lsscsi (0.30-0.1) ... 958s Setting up libisns0:ppc64el (0.97-3) ... 958s Setting up libboost-thread1.71.0:ppc64el (1.71.0-6ubuntu6) ... 958s Setting up libtirpc3:ppc64el (1.2.5-1ubuntu0.1) ... 958s Setting up libibverbs1:ppc64el (28.0-1ubuntu1) ... 958s Setting up open-iscsi (2.0.874-7.1ubuntu6.4) ... 958s grep: /lib/modules-load.d/open-iscsi.conf: No such file or directory 958s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /lib/systemd/system/iscsid.socket. 959s Created symlink /etc/systemd/system/iscsi.service → /lib/systemd/system/open-iscsi.service. 959s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /lib/systemd/system/open-iscsi.service. 960s Setting up libpython2.7-stdlib:ppc64el (2.7.18-1~20.04.4) ... 960s Setting up libgfxdr0:ppc64el (7.2-2build1) ... 960s Setting up librdmacm1:ppc64el (28.0-1ubuntu1) ... 960s Setting up librados2 (15.2.17-0ubuntu0.20.04.6) ... 960s Setting up python2.7 (2.7.18-1~20.04.4) ... 961s Setting up librbd1 (15.2.17-0ubuntu0.20.04.6) ... 961s Setting up tgt (1:1.0.79-2ubuntu1) ... 961s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /lib/systemd/system/tgt.service. 962s Setting up libgfrpc0:ppc64el (7.2-2build1) ... 962s Setting up libgfapi0:ppc64el (7.2-2build1) ... 962s Setting up fio (3.16-1) ... 962s Processing triggers for libc-bin (2.31-0ubuntu9.14) ... 962s Processing triggers for systemd (245.4-4ubuntu3.23) ... 962s Processing triggers for man-db (2.9.1-1) ... 962s Processing triggers for mime-support (3.64ubuntu1) ... 962s Processing triggers for initramfs-tools (0.136ubuntu6.8) ... 962s update-initramfs: Generating /boot/initrd.img-5.4.0-174-generic 980s Setting up autopkgtest-satdep (0) ... 983s (Reading database ... 95031 files and directories currently installed.) 983s Removing autopkgtest-satdep (0) ... 987s autopkgtest [10:50:29]: test tgtbasedmpaths: [----------------------- 987s + targetname=iqn.2016-11.foo.com:target.iscsi 987s + pwd 987s + cwd=/tmp/autopkgtest.kDDgu3/build.7Wj/src 987s + testdir=/mnt/tgtmpathtest 987s + localhost=127.0.0.1 987s + portal=127.0.0.1:3260 987s + maxpaths=4 987s + backfn=backingfile 987s + expectwwid=60000000000000000e00000000010001 987s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 987s + bglog=/tmp/autopkgtest.kDDgu3/tgtbasedmpaths-artifacts/test-background.log 987s + fioprep=/tmp/autopkgtest.kDDgu3/tgtbasedmpaths-artifacts/path-change-prep.fio 987s + fiovrfy=/tmp/autopkgtest.kDDgu3/tgtbasedmpaths-artifacts/path-change-check.fio 987s + service tgt restart 987s + truncate --size 100M backingfile 987s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 987s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 987s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.kDDgu3/build.7Wj/src/backingfile 987s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 987s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 987s + echo login #1 987s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260login #1 987s --login 987s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 987s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 987s + seq 2 4 987s extra login #2 987s + echo extra login #2 987s + iscsiadm --mode session -r 1 --op new 987s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 987s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 987s extra login #3 987s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 987s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 987s extra login #4 987s + echo extra login #3 987s + iscsiadm --mode session -r 1 --op new 987s + echo extra login #4 987s + iscsiadm --mode session -r 1 --op new 987s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 987s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 987s + udevadm settle 987s + sleep 5 992s + echo Status after initial setup 992s + tgtadm --lld iscsi --mode target --op show 992s + tgtadm --lld iscsi --op show --mode conn --tid 1 992s + iscsiadm --mode session -P 1 992s Status after initial setup 992s Target 1: iqn.2016-11.foo.com:target.iscsi 992s System information: 992s Driver: iscsi 992s State: ready 992s I_T nexus information: 992s I_T nexus: 1 992s Initiator: iqn.1993-08.org.debian:01:766e2a6f6874 alias: autopkgtest 992s Connection: 0 992s IP Address: 127.0.0.1 992s I_T nexus: 2 992s Initiator: iqn.1993-08.org.debian:01:766e2a6f6874 alias: autopkgtest 992s Connection: 0 992s IP Address: 127.0.0.1 992s I_T nexus: 3 992s Initiator: iqn.1993-08.org.debian:01:766e2a6f6874 alias: autopkgtest 992s Connection: 0 992s IP Address: 127.0.0.1 992s I_T nexus: 4 992s Initiator: iqn.1993-08.org.debian:01:766e2a6f6874 alias: autopkgtest 992s Connection: 0 992s IP Address: 127.0.0.1 992s LUN information: 992s LUN: 0 992s Type: controller 992s SCSI ID: IET 00010000 992s SCSI SN: beaf10 992s Size: 0 MB, Block size: 1 992s Online: Yes 992s Removable media: No 992s Prevent removal: No 992s Readonly: No 992s SWP: No 992s Thin-provisioning: No 992s Backing store type: null 992s Backing store path: None 992s Backing store flags: 992s LUN: 1 992s Type: disk 992s SCSI ID: IET 00010001 992s SCSI SN: beaf11 992s Size: 105 MB, Block size: 512 992s Online: Yes 992s Removable media: No 992s Prevent removal: No 992s Readonly: No 992s SWP: No 992s Thin-provisioning: No 992s Backing store type: rdwr 992s Backing store path: /tmp/autopkgtest.kDDgu3/build.7Wj/src/backingfile 992s Backing store flags: 992s Account information: 992s ACL information: 992s ALL 992s Session: 4 992s Connection: 0 992s Initiator: iqn.1993-08.org.debian:01:766e2a6f6874 992s IP Address: 127.0.0.1 992s Session: 3 992s Connection: 0 992s Initiator: iqn.1993-08.org.debian:01:766e2a6f6874 992s IP Address: 127.0.0.1 992s Session: 2 992s Connection: 0 992s Initiator: iqn.1993-08.org.debian:01:766e2a6f6874 992s IP Address: 127.0.0.1 992s Session: 1 992s Connection: 0 992s Initiator: iqn.1993-08.org.debian:01:766e2a6f6874 992s IP Address: 127.0.0.1 992s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 992s Current Portal: 127.0.0.1:3260,1 992s Persistent Portal: 127.0.0.1:3260,1 992s ********** 992s Interface: 992s ********** 992s Iface Name: default 992s Iface Transport: tcp 992s Iface Initiatorname: iqn.1993-08.org.debian:01:766e2a6f6874 992s Iface IPaddress: 127.0.0.1 992s Iface HWaddress: 992s Iface Netdev: 992s SID: 1 992s iSCSI Connection State: LOGGED IN 992s iSCSI Session State: LOGGED_IN 992s Internal iscsid Session State: NO CHANGE 992s 992s ********** 992s Interface: 992s ********** 992s Iface Name: default 992s Iface Transport: tcp 992s Iface Initiatorname: iqn.1993-08.org.debian:01:766e2a6f6874 992s Iface IPaddress: 127.0.0.1 992s Iface HWaddress: 992s Iface Netdev: 992s SID: 4 992s iSCSI Connection State: LOGGED IN 992s iSCSI Session State: LOGGED_IN 992s Internal iscsid Session State: NO CHANGE 992s 992s ********** 992s Interface: 992s ********** 992s Iface Name: default 992s Iface Transport: tcp 992s Iface Initiatorname: iqn.1993-08.org.debian:01:766e2a6f6874 992s Iface IPaddress: 127.0.0.1 992s Iface HWaddress: 992s Iface Netdev: 992s SID: 3 992s iSCSI Connection State: LOGGED IN 992s iSCSI Session State: LOGGED_IN 992s Internal iscsid Session State: NO CHANGE 992s 992s ********** 992s Interface: 992s ********** 992s Iface Name: default 992s Iface Transport: tcp 992s Iface Initiatorname: iqn.1993-08.org.debian:01:766e2a6f6874 992s Iface IPaddress: 127.0.0.1 992s Iface HWaddress: 992s Iface Netdev: 992s SID: 2 992s iSCSI Connection State: LOGGED IN 992s iSCSI Session State: LOGGED_IN 992s Internal iscsid Session State: NO CHANGE 992s + lsscsi -liv 992s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 993s + multipath -v3 -ll 993s Apr 03 10:50:34 | set open fds limit to 1048576/1048576 993s Apr 03 10:50:34 | loading //lib/multipath/libchecktur.so checker 993s Apr 03 10:50:34 | checker tur: message table size = 3 993s Apr 03 10:50:34 | loading //lib/multipath/libprioconst.so prioritizer 993s Apr 03 10:50:34 | foreign library "nvme" loaded successfully 993s Apr 03 10:50:34 | sda: size = 167772160 993s Apr 03 10:50:34 | sda: vendor = QEMU 993s Apr 03 10:50:34 | sda: product = QEMU HARDDISK 993s Apr 03 10:50:34 | sda: rev = 2.5+ 993s Apr 03 10:50:34 | sda: h:b:t:l = 0:0:0:0 993s Apr 03 10:50:34 | sda: tgt_node_name = 993s Apr 03 10:50:34 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 993s Apr 03 10:50:34 | 0:0:0:0: attribute vpd_pg80 not found in sysfs 993s Apr 03 10:50:34 | failed to read sysfs vpd pg80 993s Apr 03 10:50:34 | sda: fail to get serial 993s Apr 03 10:50:34 | sda: detect_checker = yes (setting: multipath internal) 993s Apr 03 10:50:34 | sda: path_checker = tur (setting: multipath internal) 993s Apr 03 10:50:34 | sda: checker timeout = 30 s (setting: kernel sysfs) 993s Apr 03 10:50:34 | sda: tur state = up 993s Apr 03 10:50:34 | sdb: size = 204800 993s Apr 03 10:50:34 | sdb: vendor = IET 993s Apr 03 10:50:34 | sdb: product = VIRTUAL-DISK 993s Apr 03 10:50:34 | sdb: rev = 0001 993s Apr 03 10:50:34 | sdb: h:b:t:l = 1:0:0:1 993s Apr 03 10:50:34 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 993s Apr 03 10:50:34 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 993s Apr 03 10:50:34 | sdb: serial = beaf11 993s Apr 03 10:50:34 | sdb: detect_checker = yes (setting: multipath internal) 993s Apr 03 10:50:34 | sdb: path_checker = tur (setting: multipath internal) 993s Apr 03 10:50:34 | sdb: checker timeout = 30 s (setting: kernel sysfs) 993s Apr 03 10:50:34 | sdb: tur state = up 993s Apr 03 10:50:34 | sdc: size = 204800 993s Apr 03 10:50:34 | sdc: vendor = IET 993s Apr 03 10:50:34 | sdc: product = VIRTUAL-DISK 993s Apr 03 10:50:34 | sdc: rev = 0001 993s Apr 03 10:50:34 | sdc: h:b:t:l = 2:0:0:1 993s Apr 03 10:50:34 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 993s Apr 03 10:50:34 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 993s Apr 03 10:50:34 | sdc: serial = beaf11 993s Apr 03 10:50:34 | sdc: detect_checker = yes (setting: multipath internal) 993s Apr 03 10:50:34 | sdc: path_checker = tur (setting: multipath internal) 993s Apr 03 10:50:34 | sdc: checker timeout = 30 s (setting: kernel sysfs) 993s Apr 03 10:50:34 | sdc: tur state = up 993s Apr 03 10:50:34 | sdd: size = 204800 993s Apr 03 10:50:34 | sdd: vendor = IET 993s Apr 03 10:50:34 | sdd: product = VIRTUAL-DISK 993s Apr 03 10:50:34 | sdd: rev = 0001 993s Apr 03 10:50:34 | sdd: h:b:t:l = 3:0:0:1 993s Apr 03 10:50:34 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 993s Apr 03 10:50:34 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 993s Apr 03 10:50:34 | sdd: serial = beaf11 993s Apr 03 10:50:34 | sdd: detect_checker = yes (setting: multipath internal) 993s Apr 03 10:50:34 | sdd: path_checker = tur (setting: multipath internal) 993s Apr 03 10:50:34 | sdd: checker timeout = 30 s (setting: kernel sysfs) 993s Apr 03 10:50:34 | sdd: tur state = up 993s Apr 03 10:50:34 | sde: size = 204800 993s Apr 03 10:50:34 | sde: vendor = IET 993s Apr 03 10:50:34 | sde: product = VIRTUAL-DISK 993s Apr 03 10:50:34 | sde: rev = 0001 993s Apr 03 10:50:34 | sde: h:b:t:l = 4:0:0:1 993s Apr 03 10:50:34 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 993s Apr 03 10:50:34 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 993s Apr 03 10:50:34 | sde: serial = beaf11 993s Apr 03 10:50:34 | sde: detect_checker = yes (setting: multipath internal) 993s Apr 03 10:50:34 | sde: path_checker = tur (setting: multipath internal) 993s Apr 03 10:50:34 | sde: checker timeout = 30 s (setting: kernel sysfs) 993s Apr 03 10:50:34 | sde: tur state = up 993s Apr 03 10:50:34 | loop0: device node name blacklisted 993s Apr 03 10:50:34 | loop1: device node name blacklisted 993s Apr 03 10:50:34 | loop2: device node name blacklisted 993s Apr 03 10:50:34 | loop3: device node name blacklisted 993s Apr 03 10:50:34 | loop4: device node name blacklisted 993s Apr 03 10:50:34 | loop5: device node name blacklisted 993s Apr 03 10:50:34 | loop6: device node name blacklisted 993s Apr 03 10:50:34 | loop7: device node name blacklisted 993s Apr 03 10:50:34 | dm-0: device node name blacklisted 993s Apr 03 10:50:34 | libdevmapper version 1.02.167 (2019-11-30) 993s Apr 03 10:50:34 | DM multipath kernel driver v1.13.0 993s Apr 03 10:50:34 | params = 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 993s Apr 03 10:50:34 | status = 2 0 0 0 4 1 A 0 1 2 8:16 A 0 0 1 E 0 1 2 8:32 A 0 0 1 E 0 1 2 8:48 A 0 0 1 E 0 1 2 8:64 A 0 0 1 993s Apr 03 10:50:34 | sdb: detect_prio = yes (setting: multipath internal) 993s Apr 03 10:50:34 | sdb: prio = const (setting: multipath internal) 993s Apr 03 10:50:34 | sdb: prio args = "" (setting: multipath internal) 993s Apr 03 10:50:34 | sdb: const prio = 1 993s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 993s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 993s 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] 993s [1:0:0:0] storage IET Controller 0001 - - 993s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 993s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 993s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 1IET_00010001 993s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 993s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 993s [2:0:0:0] storage IET Controller 0001 - - 993s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 993s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 993s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 993s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 993s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 993s [3:0:0:0] storage IET Controller 0001 - - 993s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 993s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 993s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 993s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 993s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 993s [4:0:0:0] storage IET Controller 0001 - - 993s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 993s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 993s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 993s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 993s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 993s NVMe module may not be loaded 993s ===== paths list ===== 993s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 993s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 993s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 993s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 993s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 993s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 993s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 993s size=100M features='0' hwhandler='0' wp=rw 993s |-+- policy='service-time 0' prio=1 status=active 993s | `- 1:0:0:1 sdb 8:16 active ready running 993s |-+- policy='service-time 0' prio=1 status=enabled 993s | `- 2:0:0:1 sdc 8:32 active ready running 993s |-+- policy='service-time 0' prio=1 status=enabled 993s | `- 3:0:0:1 sdd 8:48 active ready running 993s `-+- policy='service-time 0' prio=1 status=enabled 993s `- 4:0:0:1 sde 8:64 active ready running 993s 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 993s Test WWN should now point to DM 993s ../../dm-0 993s Creating filesystem with 25600 4k blocks and 25600 inodes 993s 993s Allocating group tables: 0/1 done 993s Writing inode tables: 0/1 done 993s Creating journal (1024 blocks): Apr 03 10:50:34 | sdc: detect_prio = yes (setting: multipath internal) 993s Apr 03 10:50:34 | sdc: prio = const (setting: multipath internal) 993s Apr 03 10:50:34 | sdc: prio args = "" (setting: multipath internal) 993s Apr 03 10:50:34 | sdc: const prio = 1 993s Apr 03 10:50:34 | sdd: detect_prio = yes (setting: multipath internal) 993s Apr 03 10:50:34 | sdd: prio = const (setting: multipath internal) 993s Apr 03 10:50:34 | sdd: prio args = "" (setting: multipath internal) 993s Apr 03 10:50:34 | sdd: const prio = 1 993s Apr 03 10:50:34 | sde: detect_prio = yes (setting: multipath internal) 993s Apr 03 10:50:34 | sde: prio = const (setting: multipath internal) 993s Apr 03 10:50:34 | sde: prio args = "" (setting: multipath internal) 993s Apr 03 10:50:34 | sde: const prio = 1 993s Apr 03 10:50:34 | unloading const prioritizer 993s Apr 03 10:50:34 | unloading tur checker 993s + dmsetup table 993s + echo Test WWN should now point to DM 993s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 993s + grep dm 993s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 993s mke2fs 1.45.5 (07-Jan-2020) 993s done 993s Writing superblocks and filesystem accounting information: 0/1 done 993s 993s + udevadm settle 993s + sleep 3s 996s + mkdir -p /mnt/tgtmpathtest 996s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 996s + cat 996s + cat 996s + fio /tmp/autopkgtest.kDDgu3/tgtbasedmpaths-artifacts/path-change-prep.fio 996s 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 996s fio-3.16 996s Starting 1 thread 996s write-phase: Laying out IO file (1 file / 17592186044415MiB) 996s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=95158272, buflen=65536 996s 996s write-phase: (groupid=0, jobs=1): err= 0: pid=8173: Wed Apr 3 10:50:38 2024 996s write: IOPS=2929, BW=183MiB/s (192MB/s)(90.8MiB/496msec); 0 zone resets 996s clat (usec): min=203, max=2679, avg=316.23, stdev=115.61 996s lat (usec): min=225, max=2701, avg=338.84, stdev=115.68 996s clat percentiles (usec): 996s | 1.00th=[ 206], 5.00th=[ 208], 10.00th=[ 212], 20.00th=[ 221], 996s | 30.00th=[ 251], 40.00th=[ 277], 50.00th=[ 297], 60.00th=[ 330], 996s | 70.00th=[ 355], 80.00th=[ 388], 90.00th=[ 449], 95.00th=[ 478], 996s | 99.00th=[ 578], 99.50th=[ 603], 99.90th=[ 1827], 99.95th=[ 2671], 996s | 99.99th=[ 2671] 996s lat (usec) : 250=29.53%, 500=67.72%, 750=2.48%, 1000=0.07% 996s lat (msec) : 2=0.07%, 4=0.07% 996s cpu : usr=6.67%, sys=7.27%, ctx=1454, majf=0, minf=0 996s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 996s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 996s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 996s issued rwts: total=0,1453,0,0 short=0,0,0,0 dropped=0,0,0,0 996s latency : target=0, window=0, percentile=100.00%, depth=1 996s 996s Run status group 0 (all jobs): 996s WRITE: bw=183MiB/s (192MB/s), 183MiB/s-183MiB/s (192MB/s-192MB/s), io=90.8MiB (95.2MB), run=496-496msec 996s 996s Disk stats (read/write): 996s dm-0: ios=0/1131, merge=0/0, ticks=0/346, in_queue=0, util=80.49%, aggrios=0/363, aggrmerge=0/0, aggrticks=0/107, aggrin_queue=0, aggrutil=81.57% 996s sdd: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 996s sdb: ios=0/1453, merge=0/0, ticks=0/431, in_queue=0, util=81.57% 996s sde: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 996s sdc: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 996s Starting the path changes in background 996s + echo Starting the path changes in background 996s + date +Pre FIO %H:%M:%S.%N 996s + fio /tmp/autopkgtest.kDDgu3/tgtbasedmpaths-artifacts/path-change-check.fio 996s Pre FIO 10:50:38.843911993 997s 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 997s fio-3.16 997s Starting 1 thread 1177s 1177s verify-phase: (groupid=0, jobs=1): err= 0: pid=8180: Wed Apr 3 10:53:39 2024 1177s read: IOPS=5203, BW=325MiB/s (341MB/s)(57.2GiB/180001msec) 1177s clat (usec): min=65, max=62144, avg=165.23, stdev=162.87 1177s lat (usec): min=65, max=62145, avg=165.78, stdev=162.87 1177s clat percentiles (usec): 1177s | 1.00th=[ 108], 5.00th=[ 110], 10.00th=[ 111], 20.00th=[ 112], 1177s | 30.00th=[ 115], 40.00th=[ 125], 50.00th=[ 155], 60.00th=[ 163], 1177s | 70.00th=[ 176], 80.00th=[ 204], 90.00th=[ 243], 95.00th=[ 306], 1177s | 99.00th=[ 375], 99.50th=[ 416], 99.90th=[ 889], 99.95th=[ 1090], 1177s | 99.99th=[ 2769] 1177s bw ( KiB/s): min=172032, max=440064, per=100.00%, avg=333041.71, stdev=74379.38, samples=359 1177s iops : min= 2688, max= 6876, avg=5203.75, stdev=1162.18, samples=359 1177s lat (usec) : 100=0.33%, 250=90.61%, 500=8.78%, 750=0.12%, 1000=0.10% 1177s lat (msec) : 2=0.05%, 4=0.01%, 10=0.01%, 50=0.01%, 100=0.01% 1177s cpu : usr=13.59%, sys=7.36%, ctx=938391, majf=0, minf=1 1177s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 1177s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1177s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1177s issued rwts: total=936548,0,0,0 short=0,0,0,0 dropped=0,0,0,0 1177s latency : target=0, window=0, percentile=100.00%, depth=1 1177s 1177s Run status group 0 (all jobs): 1177s READ: bw=325MiB/s (341MB/s), 325MiB/s-325MiB/s (341MB/s-341MB/s), io=57.2GiB (61.4GB), run=180001-180001msec 1177s 1177s Disk stats (read/write): 1177s dm-0: ios=936129/25, merge=0/7, ticks=149670/175, in_queue=756, util=99.91%, aggrios=59339/2, aggrmerge=0/0, aggrticks=10119/5, aggrin_queue=20, aggrutil=99.02% 1177s sdd: ios=40140/0, merge=0/0, ticks=8370/0, in_queue=8, util=33.21% 1177s sdb: ios=40900/4, merge=0/0, ticks=8100/19, in_queue=56, util=99.02% 1177s sde: ios=112716/0, merge=0/0, ticks=15713/0, in_queue=8, util=39.80% 1177s sdc: ios=43602/5, merge=0/0, ticks=8294/1, in_queue=8, util=50.10% 1177s + date +Post FIO %H:%M:%S.%N 1177s Post FIO 10:53:39.089800600 1177s + echo FIO verify test with changing paths - OK 1177s + echo Report log of background activity 1177s + cat /tmp/autopkgtest.kDDgu3/tgtbasedmpaths-artifacts/test-background.log 1177s FIO verify test with changing paths - OK 1177s Report log of background activity 1177s + iscsiadm --mode session 1177s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s + sleep 10s 1177s + date +MP report (expect 4) %H:%M:%S.%N 1177s MP report (expect 4) 10:50:48.851631722 1177s + multipath -ll 1177s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1177s size=100M features='0' hwhandler='0' wp=rw 1177s |-+- policy='service-time 0' prio=1 status=active 1177s | `- 1:0:0:1 sdb 8:16 active ready running 1177s |-+- policy='service-time 0' prio=1 status=enabled 1177s | `- 2:0:0:1 sdc 8:32 active ready running 1177s |-+- policy='service-time 0' prio=1 status=enabled 1177s | `- 3:0:0:1 sdd 8:48 active ready running 1177s `-+- policy='service-time 0' prio=1 status=enabled 1177s `- 4:0:0:1 sde 8:64 active ready running 1177s + date +UN-plug path 1 %H:%M:%S.%N 1177s UN-plug path 1 10:50:48.873065907 1177s + iscsiadm --mode session -r 1 -u 1177s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1177s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1177s + iscsiadm --mode session 1177s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s + sleep 10s 1177s + date +MP report (expect 3) %H:%M:%S.%N 1177s MP report (expect 3) 10:50:58.925365751 1177s + multipath -ll 1177s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1177s size=100M features='0' hwhandler='0' wp=rw 1177s |-+- policy='service-time 0' prio=1 status=active 1177s | `- 2:0:0:1 sdc 8:32 active ready running 1177s |-+- policy='service-time 0' prio=1 status=enabled 1177s | `- 3:0:0:1 sdd 8:48 active ready running 1177s `-+- policy='service-time 0' prio=1 status=enabled 1177s `- 4:0:0:1 sde 8:64 active ready running 1177s + date +UN-plug path 2 %H:%M:%S.%N 1177s UN-plug path 2 10:50:58.941286085 1177s + iscsiadm --mode session -r 2 -u 1177s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1177s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1177s + iscsiadm --mode session 1177s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s + sleep 10s 1177s + date +MP report (expect 2) %H:%M:%S.%N 1177s MP report (expect 2) 10:51:08.997361229 1177s + multipath -ll 1177s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1177s size=100M features='0' hwhandler='0' wp=rw 1177s |-+- policy='service-time 0' prio=1 status=active 1177s | `- 3:0:0:1 sdd 8:48 active ready running 1177s `-+- policy='service-time 0' prio=1 status=enabled 1177s `- 4:0:0:1 sde 8:64 active ready running 1177s + date +UN-plug path 3 %H:%M:%S.%N 1177s UN-plug path 3 10:51:09.010115090 1177s + iscsiadm --mode session -r 3 -u 1177s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1177s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1177s + iscsiadm --mode session 1177s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s + sleep 10s 1177s + date +MP report (expect 1) %H:%M:%S.%N 1177s MP report (expect 1) 10:51:19.068175027 1177s + multipath -ll 1177s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1177s size=100M features='0' hwhandler='0' wp=rw 1177s `-+- policy='service-time 0' prio=1 status=active 1177s `- 4:0:0:1 sde 8:64 active ready running 1177s + date +Add paths 5/6/7/8 %H:%M:%S.%N 1177s Add paths 5/6/7/8 10:51:19.080378940 1177s + iscsiadm --mode session -r 4 --op new 1177s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1177s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1177s + iscsiadm --mode session -r 4 --op new 1177s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1177s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1177s + iscsiadm --mode session -r 4 --op new 1177s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1177s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1177s + iscsiadm --mode session -r 4 --op new 1177s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1177s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1177s + iscsiadm --mode session 1177s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s + sleep 10s 1177s + date +MP report (expect 5) %H:%M:%S.%N 1177s MP report (expect 5) 10:51:29.159891405 1177s + multipath -ll 1177s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1177s size=100M features='0' hwhandler='0' wp=rw 1177s |-+- policy='service-time 0' prio=1 status=active 1177s | `- 4:0:0:1 sde 8:64 active ready running 1177s |-+- policy='service-time 0' prio=1 status=enabled 1177s | `- 1:0:0:1 sdb 8:16 active ready running 1177s |-+- policy='service-time 0' prio=1 status=enabled 1177s | `- 2:0:0:1 sdc 8:32 active ready running 1177s |-+- policy='service-time 0' prio=1 status=enabled 1177s | `- 3:0:0:1 sdd 8:48 active ready running 1177s `-+- policy='service-time 0' prio=1 status=enabled 1177s `- 5:0:0:1 sdf 8:80 active ready running 1177s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 1177s UN-plug multiple paths 4/7/8 10:51:29.181718142 1177s + iscsiadm --mode session -r 4 -u 1177s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1177s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1177s + iscsiadm --mode session -r 7 -u 1177s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1177s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1177s + iscsiadm --mode session -r 8 -u 1177s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1177s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1177s + iscsiadm --mode session 1177s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1177s + sleep 10s 1177s + date +Restart multipath daemon %H:%M:%S.%N 1177s Restart multipath daemon 10:51:39.352564744 1177s + systemctl restart multipathd 1177s + sleep 10s 1177s + date +Final background report (expect 2) %H:%M:%S.%N 1177s Final background report (expect 2) 10:51:49.388244612 1177s + multipath -ll 1177s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1177s size=100M features='0' hwhandler='0' wp=rw 1177s |-+- policy='service-time 0' prio=1 status=active 1177s | `- 1:0:0:1 sdb 8:16 active ready running 1177s `-+- policy='service-time 0' prio=1 status=enabled 1177s `- 2:0:0:1 sdc 8:32 active ready running 1177s Final stats 1177s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1177s iSCSI SNMP: 1177s txdata_octets: 33546600 1177s rxdata_octets: 45812725320 1177s noptx_pdus: 0 1177s scsicmd_pdus: 698620 1177s tmfcmd_pdus: 0 1177s login_pdus: 0 1177s text_pdus: 0 1177s dataout_pdus: 0 1177s logout_pdus: 0 1177s snack_pdus: 0 1177s noprx_pdus: 0 1177s scsirsp_pdus: 698620 1177s tmfrsp_pdus: 0 1177s textrsp_pdus: 0 1177s datain_pdus: 698577 1177s logoutrsp_pdus: 0 1177s r2t_pdus: 0 1177s async_pdus: 0 1177s rjt_pdus: 0 1177s digest_err: 0 1177s timeout_err: 0 1177s iSCSI Extended: 1177s tx_sendpage_failures: 0 1177s rx_discontiguous_hdr: 0 1177s eh_abort_cnt: 0 1177s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1177s iSCSI SNMP: 1177s txdata_octets: 5928 1177s rxdata_octets: 1842184 1177s noptx_pdus: 0 1177s scsicmd_pdus: 94 1177s tmfcmd_pdus: 0 1177s login_pdus: 0 1177s text_pdus: 0 1177s dataout_pdus: 0 1177s logout_pdus: 0 1177s snack_pdus: 0 1177s noprx_pdus: 0 1177s scsirsp_pdus: 94 1177s tmfrsp_pdus: 0 1177s textrsp_pdus: 0 1177s datain_pdus: 68 1177s logoutrsp_pdus: 0 1177s r2t_pdus: 0 1177s async_pdus: 0 1177s rjt_pdus: 0 1177s digest_err: 0 1177s timeout_err: 0+ sync 1177s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1177s + echo Final stats 1177s + iscsiadm --mode session --stats 1177s + journalctl --no-pager -u multipathd 1177s 1177s iSCSI Extended: 1177s tx_sendpage_failures: 0 1177s rx_discontiguous_hdr: 0 1177s eh_abort_cnt: 0 1177s -- Logs begin at Sun 2024-03-31 14:40:43 UTC, end at Wed 2024-04-03 10:53:39 UTC. -- 1177s Mar 31 14:40:45 ubuntu systemd[1]: Starting Device-Mapper Multipath Device Controller... 1177s Mar 31 14:40:45 ubuntu multipathd[492]: --------start up-------- 1177s Mar 31 14:40:45 ubuntu multipathd[492]: read /etc/multipath.conf 1177s Mar 31 14:40:45 ubuntu multipathd[492]: path checkers start up 1177s Mar 31 14:40:45 ubuntu systemd[1]: Started Device-Mapper Multipath Device Controller. 1177s Mar 31 14:40:58 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[492]: sda: failed to get udev uid: Invalid argument 1177s Mar 31 14:40:58 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[492]: sda: failed to get unknown uid: Invalid argument 1177s Mar 31 14:40:59 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[492]: sda: failed to get udev uid: Invalid argument 1177s Mar 31 14:40:59 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[492]: sda: failed to get unknown uid: Invalid argument 1177s Mar 31 14:45:29 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[492]: exit (signal) 1177s Mar 31 14:45:29 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[492]: --------shut down------- 1177s Mar 31 14:45:29 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: Stopping Device-Mapper Multipath Device Controller... 1177s Mar 31 14:45:29 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: multipathd.service: Succeeded. 1177s Mar 31 14:45:29 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: Stopped Device-Mapper Multipath Device Controller. 1177s -- Reboot -- 1177s Mar 31 14:45:50 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: Starting Device-Mapper Multipath Device Controller... 1177s Mar 31 14:45:50 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[412]: --------start up-------- 1177s Mar 31 14:45:50 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[412]: read /etc/multipath.conf 1177s Mar 31 14:45:50 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[412]: path checkers start up 1177s Mar 31 14:45:50 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: Started Device-Mapper Multipath Device Controller. 1177s Mar 31 14:47:22 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[412]: exit (signal) 1177s Mar 31 14:47:22 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[412]: --------shut down------- 1177s Mar 31 14:47:22 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: Stopping Device-Mapper Multipath Device Controller... 1177s Mar 31 14:47:22 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: multipathd.service: Succeeded. 1177s Mar 31 14:47:22 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: Stopped Device-Mapper Multipath Device Controller. 1177s -- Reboot -- 1177s Mar 31 14:47:45 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: Starting Device-Mapper Multipath Device Controller... 1177s Mar 31 14:47:45 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[410]: --------start up-------- 1177s Mar 31 14:47:45 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[410]: read /etc/multipath.conf 1177s Mar 31 14:47:45 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[410]: path checkers start up 1177s Mar 31 14:47:45 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: Started Device-Mapper Multipath Device Controller. 1177s Mar 31 14:48:01 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[410]: exit (signal) 1177s Mar 31 14:48:01 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[410]: --------shut down------- 1177s Mar 31 14:48:01 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: Stopping Device-Mapper Multipath Device Controller... 1177s Mar 31 14:48:01 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: multipathd.service: Succeeded. 1177s Mar 31 14:48:01 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: Stopped Device-Mapper Multipath Device Controller. 1177s -- Reboot -- 1177s Apr 03 10:45:16 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: Starting Device-Mapper Multipath Device Controller... 1177s Apr 03 10:45:16 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[456]: --------start up-------- 1177s Apr 03 10:45:16 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[456]: read /etc/multipath.conf 1177s Apr 03 10:45:16 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 multipathd[456]: path checkers start up 1177s Apr 03 10:45:16 ubuntuubuntu-focal-daily-ppc64el-server-20240306-disk1 systemd[1]: Started Device-Mapper Multipath Device Controller. 1177s Apr 03 10:46:14 adt-focal-ppc64el-multipath-tools-20240403-103401-juju-7f2275-p multipathd[456]: sda: failed to get udev uid: Invalid argument 1177s Apr 03 10:46:14 adt-focal-ppc64el-multipath-tools-20240403-103401-juju-7f2275-p multipathd[456]: sda: failed to get unknown uid: Invalid argument 1177s Apr 03 10:46:58 autopkgtest multipathd[456]: exit (signal) 1177s Apr 03 10:46:58 autopkgtest systemd[1]: Stopping Device-Mapper Multipath Device Controller... 1177s Apr 03 10:46:58 autopkgtest multipathd[456]: --------shut down------- 1177s Apr 03 10:46:58 autopkgtest systemd[1]: multipathd.service: Succeeded. 1177s Apr 03 10:46:58 autopkgtest systemd[1]: Stopped Device-Mapper Multipath Device Controller. 1177s -- Reboot -- 1177s Apr 03 10:47:18 autopkgtest systemd[1]: Starting Device-Mapper Multipath Device Controller... 1177s Apr 03 10:47:18 autopkgtest multipathd[464]: --------start up-------- 1177s Apr 03 10:47:18 autopkgtest multipathd[464]: read /etc/multipath.conf 1177s Apr 03 10:47:18 autopkgtest multipathd[464]: path checkers start up 1177s Apr 03 10:47:18 autopkgtest systemd[1]: Started Device-Mapper Multipath Device Controller. 1177s Apr 03 10:48:01 autopkgtest systemd[1]: Stopping Device-Mapper Multipath Device Controller... 1177s Apr 03 10:48:01 autopkgtest multipathd[464]: exit (signal) 1177s Apr 03 10:48:01 autopkgtest multipathd[464]: --------shut down------- 1177s Apr 03 10:48:01 autopkgtest systemd[1]: multipathd.service: Succeeded. 1177s Apr 03 10:48:01 autopkgtest systemd[1]: Stopped Device-Mapper Multipath Device Controller. 1177s -- Reboot -- 1177s Apr 03 10:48:21 autopkgtest systemd[1]: Starting Device-Mapper Multipath Device Controller... 1177s Apr 03 10:48:21 autopkgtest multipathd[462]: --------start up-------- 1177s Apr 03 10:48:21 autopkgtest multipathd[462]: read /etc/multipath.conf 1177s Apr 03 10:48:21 autopkgtest multipathd[462]: path checkers start up 1177s Apr 03 10:48:21 autopkgtest systemd[1]: Started Device-Mapper Multipath Device Controller. 1177s Apr 03 10:50:31 autopkgtest multipathd[462]: mpatha: load table [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 1177s Apr 03 10:50:31 autopkgtest multipathd[462]: sdc [8:32]: path added to devmap mpatha 1177s Apr 03 10:50:32 autopkgtest multipathd[462]: mpatha: performing delayed actions 1177s Apr 03 10:50:32 autopkgtest multipathd[462]: mpatha: load table [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] 1177s Apr 03 10:50:48 autopkgtest multipathd[462]: 8:16: cannot find block device 1177s Apr 03 10:50:48 autopkgtest multipathd[462]: sdb: mark as failed 1177s Apr 03 10:50:48 autopkgtest multipathd[462]: mpatha: remaining active paths: 3 1177s Apr 03 10:50:48 autopkgtest multipathd[462]: mpatha: load table [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] 1177s Apr 03 10:50:48 autopkgtest multipathd[462]: sdb [8:16]: path removed from map mpatha 1177s Apr 03 10:50:58 autopkgtest multipathd[462]: 8:32: cannot find block device 1177s Apr 03 10:50:58 autopkgtest multipathd[462]: sdc: mark as failed 1177s Apr 03 10:50:58 autopkgtest multipathd[462]: mpatha: remaining active paths: 2 1177s Apr 03 10:50:59 autopkgtest multipathd[462]: mpatha: load table [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 1177s Apr 03 10:50:59 autopkgtest multipathd[462]: sdc [8:32]: path removed from map mpatha 1177s Apr 03 10:51:09 autopkgtest multipathd[462]: mpatha: load table [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 1177s Apr 03 10:51:09 autopkgtest multipathd[462]: sdd [8:48]: path removed from map mpatha 1177s Apr 03 10:51:19 autopkg+ echo Check final path status 1177s + multipath -ll 1177s + multipath -ll 1177s + grep --count status= 1177s + diskc=2 1177s + multipath -ll 1177s + grep --count status=active 1177s test multipathd[462]: mpatha: load table [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1] 1177s Apr 03 10:51:19 autopkgtest multipathd[462]: sdb [8:16]: path added to devmap mpatha 1177s Apr 03 10:51:20 autopkgtest multipathd[462]: mpatha: load table [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] 1177s Apr 03 10:51:20 autopkgtest multipathd[462]: sdc [8:32]: path added to devmap mpatha 1177s Apr 03 10:51:20 autopkgtest multipathd[462]: mpatha: load table [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] 1177s Apr 03 10:51:20 autopkgtest multipathd[462]: sdd [8:48]: path added to devmap mpatha 1177s Apr 03 10:51:20 autopkgtest multipathd[462]: mpatha: load table [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] 1177s Apr 03 10:51:20 autopkgtest multipathd[462]: sdf [8:80]: path added to devmap mpatha 1177s Apr 03 10:51:29 autopkgtest multipathd[462]: mpatha: load table [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] 1177s Apr 03 10:51:29 autopkgtest multipathd[462]: sde [8:64]: path removed from map mpatha 1177s Apr 03 10:51:29 autopkgtest multipathd[462]: 8:48: cannot find block device 1177s Apr 03 10:51:30 autopkgtest multipathd[462]: sdf: No iscsi session for 'session8' 1177s Apr 03 10:51:30 autopkgtest multipathd[462]: mpatha: load table [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] 1177s Apr 03 10:51:30 autopkgtest multipathd[462]: 8:80: cannot find block device 1177s Apr 03 10:51:30 autopkgtest multipathd[462]: sdd [8:48]: path removed from map mpatha 1177s Apr 03 10:51:30 autopkgtest multipathd[462]: mpatha: load table [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 1177s Apr 03 10:51:30 autopkgtest multipathd[462]: sdf [8:80]: path removed from map mpatha 1177s Apr 03 10:51:39 autopkgtest multipathd[462]: exit (signal) 1177s Apr 03 10:51:39 autopkgtest systemd[1]: Stopping Device-Mapper Multipath Device Controller... 1177s Apr 03 10:51:39 autopkgtest multipathd[462]: --------shut down------- 1177s Apr 03 10:51:39 autopkgtest systemd[1]: multipathd.service: Succeeded. 1177s Apr 03 10:51:39 autopkgtest systemd[1]: Stopped Device-Mapper Multipath Device Controller. 1177s Apr 03 10:51:39 autopkgtest systemd[1]: Starting Device-Mapper Multipath Device Controller... 1177s Apr 03 10:51:39 autopkgtest multipathd[8637]: --------start up-------- 1177s Apr 03 10:51:39 autopkgtest multipathd[8637]: read /etc/multipath.conf 1177s Apr 03 10:51:39 autopkgtest multipathd[8637]: path checkers start up 1177s Apr 03 10:51:39 autopkgtest systemd[1]: Started Device-Mapper Multipath Device Controller. 1177s Check final path status 1177s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1177s size=100M features='0' hwhandler='0' wp=rw 1177s |-+- policy='service-time 0' prio=1 status=active 1177s | `- 1:0:0:1 sdb 8:16 active ready running 1177s `-+- policy='service-time 0' prio=1 status=enabled 1177s `- 2:0:0:1 sdc 8:32 active ready running 1177s + diska=1 1177s + multipath+ grep --count status=enabled 1177s -ll 1177s + diske=1 1177s + [ 2 -ne 2 -o 1OK 1177s -ne 1 -o 1 -ne 1 ] 1177s + echo OK 1177s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 1177s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1177s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1177s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1177s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1177s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 1177s autopkgtest [10:53:39]: test tgtbasedmpaths: -----------------------] 1178s autopkgtest [10:53:40]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 1178s tgtbasedmpaths PASS 1178s autopkgtest [10:53:40]: @@@@@@@@@@@@@@@@@@@@ summary 1178s kpartx-file-loopback PASS 1178s tgtbasedmpaths PASS 1217s Creating nova instance adt-focal-ppc64el-multipath-tools-20240403-103401-juju-7f2275-prod-proposed-migration-environment-2-3f5b4789-a7a4-4e72-a53b-f44ddce99aa3 from image adt/ubuntu-focal-ppc64el-server-20240331.img (UUID 6c081017-4f3f-4c7f-ac5c-901e7ea6bea9)... 1217s Creating nova instance adt-focal-ppc64el-multipath-tools-20240403-103401-juju-7f2275-prod-proposed-migration-environment-2-3f5b4789-a7a4-4e72-a53b-f44ddce99aa3 from image adt/ubuntu-focal-ppc64el-server-20240331.img (UUID 6c081017-4f3f-4c7f-ac5c-901e7ea6bea9)...