0s autopkgtest [10:34:12]: starting date and time: 2024-04-03 10:34:12+0000 0s autopkgtest [10:34:12]: git checkout: 31124158 autopkgtest: take Paride's WIP change regarding wrong src pkg selection 0s autopkgtest [10:34:12]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.fq6td6w2/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@bos03-arm64-15.secgroup --name adt-focal-arm64-multipath-tools-20240403-103412-juju-7f2275-prod-proposed-migration-environment-2-049acc4a-dc1a-432c-824e-6608d1d8b64f --image adt/ubuntu-focal-arm64-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/ 108s autopkgtest [10:36:00]: testbed dpkg architecture: arm64 108s autopkgtest [10:36:00]: testbed apt version: 2.0.10 108s autopkgtest [10:36:00]: @@@@@@@@@@@@@@@@@@@@ test bed setup 109s Get:1 http://ftpmaster.internal/ubuntu focal-proposed InRelease [267 kB] 109s Get:2 http://ftpmaster.internal/ubuntu focal-proposed/restricted Sources [19.7 kB] 109s Get:3 http://ftpmaster.internal/ubuntu focal-proposed/main Sources [72.0 kB] 109s Get:4 http://ftpmaster.internal/ubuntu focal-proposed/universe Sources [14.2 kB] 109s Get:5 http://ftpmaster.internal/ubuntu focal-proposed/main arm64 Packages [242 kB] 109s Get:6 http://ftpmaster.internal/ubuntu focal-proposed/main arm64 c-n-f Metadata [1580 B] 109s Get:7 http://ftpmaster.internal/ubuntu focal-proposed/restricted arm64 Packages [2416 B] 109s Get:8 http://ftpmaster.internal/ubuntu focal-proposed/restricted arm64 c-n-f Metadata [380 B] 109s Get:9 http://ftpmaster.internal/ubuntu focal-proposed/universe arm64 Packages [51.6 kB] 109s Get:10 http://ftpmaster.internal/ubuntu focal-proposed/universe arm64 c-n-f Metadata [2448 B] 109s Get:11 http://ftpmaster.internal/ubuntu focal-proposed/multiverse arm64 c-n-f Metadata [116 B] 111s Fetched 674 kB in 1s (841 kB/s) 111s Reading package lists... 114s Reading package lists... 115s Building dependency tree... 115s Reading state information... 115s Calculating upgrade... 116s The following packages will be upgraded: 116s initramfs-tools initramfs-tools-bin initramfs-tools-core 116s 3 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 116s Need to get 67.9 kB of archives. 116s After this operation, 0 B of additional disk space will be used. 116s Get:1 http://ftpmaster.internal/ubuntu focal-proposed/main arm64 initramfs-tools all 0.136ubuntu6.8 [9212 B] 116s Get:2 http://ftpmaster.internal/ubuntu focal-proposed/main arm64 initramfs-tools-core all 0.136ubuntu6.8 [47.8 kB] 116s Get:3 http://ftpmaster.internal/ubuntu focal-proposed/main arm64 initramfs-tools-bin arm64 0.136ubuntu6.8 [10.9 kB] 117s Fetched 67.9 kB in 0s (190 kB/s) 117s (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 ... 100084 files and directories currently installed.) 117s Preparing to unpack .../initramfs-tools_0.136ubuntu6.8_all.deb ... 117s Unpacking initramfs-tools (0.136ubuntu6.8) over (0.136ubuntu6.7) ... 118s Preparing to unpack .../initramfs-tools-core_0.136ubuntu6.8_all.deb ... 118s Unpacking initramfs-tools-core (0.136ubuntu6.8) over (0.136ubuntu6.7) ... 118s Preparing to unpack .../initramfs-tools-bin_0.136ubuntu6.8_arm64.deb ... 118s Unpacking initramfs-tools-bin (0.136ubuntu6.8) over (0.136ubuntu6.7) ... 118s Setting up initramfs-tools-bin (0.136ubuntu6.8) ... 118s Setting up initramfs-tools-core (0.136ubuntu6.8) ... 118s Setting up initramfs-tools (0.136ubuntu6.8) ... 118s update-initramfs: deferring update (trigger activated) 118s Processing triggers for man-db (2.9.1-1) ... 118s Processing triggers for initramfs-tools (0.136ubuntu6.8) ... 118s update-initramfs: Generating /boot/initrd.img-5.4.0-174-generic 145s Unsupported platform on EFI system, doing nothing. 145s Reading package lists... 146s Building dependency tree... 146s Reading state information... 146s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 147s Hit:1 http://ftpmaster.internal/ubuntu focal InRelease 147s Hit:2 http://ftpmaster.internal/ubuntu focal-updates InRelease 147s Hit:3 http://ftpmaster.internal/ubuntu focal-security InRelease 147s Hit:4 http://ftpmaster.internal/ubuntu focal-proposed InRelease 148s Reading package lists... 149s Reading package lists... 149s Building dependency tree... 149s Reading state information... 149s Calculating upgrade... 149s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 149s Reading package lists... 150s Building dependency tree... 150s Reading state information... 150s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 150s autopkgtest [10:36:42]: rebooting testbed after setup commands that affected boot 360s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 367s autopkgtest [10:40:19]: testbed running kernel: Linux 5.4.0-174-generic #193-Ubuntu SMP Thu Mar 7 15:13:37 UTC 2024 371s autopkgtest [10:40:23]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 377s Get:1 http://ftpmaster.internal/ubuntu focal-updates/main multipath-tools 0.8.3-1ubuntu2.3 (dsc) [2882 B] 377s Get:2 http://ftpmaster.internal/ubuntu focal-updates/main multipath-tools 0.8.3-1ubuntu2.3 (tar) [465 kB] 377s Get:3 http://ftpmaster.internal/ubuntu focal-updates/main multipath-tools 0.8.3-1ubuntu2.3 (diff) [53.9 kB] 378s gpgv: Signature made Tue Nov 7 21:58:20 2023 UTC 378s gpgv: using RSA key 8F8D83B5270649A080648255EAF23F4A0BD34BF0 378s gpgv: issuer "mfo@canonical.com" 378s gpgv: Can't check signature: No public key 378s dpkg-source: warning: failed to verify signature on ./multipath-tools_0.8.3-1ubuntu2.3.dsc 380s autopkgtest [10:40:32]: testing package multipath-tools version 0.8.3-1ubuntu2.3 380s autopkgtest [10:40:32]: build not needed 381s autopkgtest [10:40:33]: test kpartx-file-loopback: preparing testbed 383s Reading package lists... 383s Building dependency tree... 383s Reading state information... 383s Starting pkgProblemResolver with broken count: 0 384s Starting 2 pkgProblemResolver with broken count: 0 384s Done 384s The following additional packages will be installed: 384s libboost-iostreams1.71.0 libboost-thread1.71.0 libibverbs1 libiscsi7 384s libnl-route-3-200 librados2 librbd1 librdmacm1 qemu-block-extra qemu-utils 384s Suggested packages: 384s debootstrap 384s Recommended packages: 384s ibverbs-providers sharutils 384s The following NEW packages will be installed: 384s autopkgtest-satdep libboost-iostreams1.71.0 libboost-thread1.71.0 384s libibverbs1 libiscsi7 libnl-route-3-200 librados2 librbd1 librdmacm1 384s qemu-block-extra qemu-utils 384s 0 upgraded, 11 newly installed, 0 to remove and 0 not upgraded. 384s Need to get 6024 kB/6025 kB of archives. 384s After this operation, 30.5 MB of additional disk space will be used. 384s Get:1 /tmp/autopkgtest.ZM03dJ/1-autopkgtest-satdep.deb autopkgtest-satdep arm64 0 [724 B] 384s Get:2 http://ftpmaster.internal/ubuntu focal/main arm64 libboost-iostreams1.71.0 arm64 1.71.0-6ubuntu6 [234 kB] 385s Get:3 http://ftpmaster.internal/ubuntu focal/main arm64 libboost-thread1.71.0 arm64 1.71.0-6ubuntu6 [245 kB] 385s Get:4 http://ftpmaster.internal/ubuntu focal-updates/main arm64 libnl-route-3-200 arm64 3.4.0-1ubuntu0.1 [137 kB] 385s Get:5 http://ftpmaster.internal/ubuntu focal/main arm64 libibverbs1 arm64 28.0-1ubuntu1 [50.7 kB] 385s Get:6 http://ftpmaster.internal/ubuntu focal/main arm64 librdmacm1 arm64 28.0-1ubuntu1 [61.2 kB] 385s Get:7 http://ftpmaster.internal/ubuntu focal/main arm64 libiscsi7 arm64 1.18.0-2 [59.6 kB] 385s Get:8 http://ftpmaster.internal/ubuntu focal-updates/main arm64 librados2 arm64 15.2.17-0ubuntu0.20.04.6 [2877 kB] 385s Get:9 http://ftpmaster.internal/ubuntu focal-updates/main arm64 librbd1 arm64 15.2.17-0ubuntu0.20.04.6 [1387 kB] 385s Get:10 http://ftpmaster.internal/ubuntu focal-updates/main arm64 qemu-block-extra arm64 1:4.2-3ubuntu6.28 [50.5 kB] 385s Get:11 http://ftpmaster.internal/ubuntu focal-updates/main arm64 qemu-utils arm64 1:4.2-3ubuntu6.28 [922 kB] 387s Fetched 6024 kB in 1s (7546 kB/s) 389s Selecting previously unselected package libboost-iostreams1.71.0:arm64. 389s (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 ... 100084 files and directories currently installed.) 389s Preparing to unpack .../00-libboost-iostreams1.71.0_1.71.0-6ubuntu6_arm64.deb ... 389s Unpacking libboost-iostreams1.71.0:arm64 (1.71.0-6ubuntu6) ... 389s Selecting previously unselected package libboost-thread1.71.0:arm64. 391s Preparing to unpack .../01-libboost-thread1.71.0_1.71.0-6ubuntu6_arm64.deb ... 391s Unpacking libboost-thread1.71.0:arm64 (1.71.0-6ubuntu6) ... 391s Selecting previously unselected package libnl-route-3-200:arm64. 391s Preparing to unpack .../02-libnl-route-3-200_3.4.0-1ubuntu0.1_arm64.deb ... 391s Unpacking libnl-route-3-200:arm64 (3.4.0-1ubuntu0.1) ... 391s Selecting previously unselected package libibverbs1:arm64. 391s Preparing to unpack .../03-libibverbs1_28.0-1ubuntu1_arm64.deb ... 391s Unpacking libibverbs1:arm64 (28.0-1ubuntu1) ... 391s Selecting previously unselected package librdmacm1:arm64. 391s Preparing to unpack .../04-librdmacm1_28.0-1ubuntu1_arm64.deb ... 391s Unpacking librdmacm1:arm64 (28.0-1ubuntu1) ... 391s Selecting previously unselected package libiscsi7:arm64. 391s Preparing to unpack .../05-libiscsi7_1.18.0-2_arm64.deb ... 391s Unpacking libiscsi7:arm64 (1.18.0-2) ... 392s Selecting previously unselected package librados2. 392s Preparing to unpack .../06-librados2_15.2.17-0ubuntu0.20.04.6_arm64.deb ... 392s Unpacking librados2 (15.2.17-0ubuntu0.20.04.6) ... 392s Selecting previously unselected package librbd1. 392s Preparing to unpack .../07-librbd1_15.2.17-0ubuntu0.20.04.6_arm64.deb ... 392s Unpacking librbd1 (15.2.17-0ubuntu0.20.04.6) ... 392s Selecting previously unselected package qemu-block-extra:arm64. 392s Preparing to unpack .../08-qemu-block-extra_1%3a4.2-3ubuntu6.28_arm64.deb ... 392s Unpacking qemu-block-extra:arm64 (1:4.2-3ubuntu6.28) ... 392s Selecting previously unselected package qemu-utils. 392s Preparing to unpack .../09-qemu-utils_1%3a4.2-3ubuntu6.28_arm64.deb ... 392s Unpacking qemu-utils (1:4.2-3ubuntu6.28) ... 392s Selecting previously unselected package autopkgtest-satdep. 392s Preparing to unpack .../10-1-autopkgtest-satdep.deb ... 392s Unpacking autopkgtest-satdep (0) ... 392s Setting up libboost-iostreams1.71.0:arm64 (1.71.0-6ubuntu6) ... 392s Setting up libnl-route-3-200:arm64 (3.4.0-1ubuntu0.1) ... 392s Setting up libboost-thread1.71.0:arm64 (1.71.0-6ubuntu6) ... 392s Setting up libibverbs1:arm64 (28.0-1ubuntu1) ... 393s Setting up librdmacm1:arm64 (28.0-1ubuntu1) ... 393s Setting up librados2 (15.2.17-0ubuntu0.20.04.6) ... 393s Setting up librbd1 (15.2.17-0ubuntu0.20.04.6) ... 393s Setting up libiscsi7:arm64 (1.18.0-2) ... 393s Setting up qemu-block-extra:arm64 (1:4.2-3ubuntu6.28) ... 393s Setting up qemu-utils (1:4.2-3ubuntu6.28) ... 393s Setting up autopkgtest-satdep (0) ... 393s Processing triggers for man-db (2.9.1-1) ... 393s Processing triggers for libc-bin (2.31-0ubuntu9.14) ... 397s (Reading database ... 100154 files and directories currently installed.) 397s Removing autopkgtest-satdep (0) ... 398s autopkgtest [10:40:50]: test kpartx-file-loopback: [----------------------- 398s Formatting 'foo.img', fmt=raw size=20971520 400s Creating new GPT entries in memory. 400s Warning: The kernel is still using the old partition table. 400s The new table will be used at the next reboot or after you 400s run partprobe(8) or kpartx(8) 400s The operation has completed successfully. 400s add map loop0p1 (253:0): 0 38879 linear 7:0 2048 400s standard_filename: OK 400s del devmap : loop0p1 400s loop deleted : /dev/loop0 400s No devices found 400s standard_filename_cleanup: OK 400s Formatting 'fou du FaFa.img', fmt=raw size=20971520 401s Creating new GPT entries in memory. 401s Warning: The kernel is still using the old partition table. 401s The new table will be used at the next reboot or after you 401s run partprobe(8) or kpartx(8) 401s The operation has completed successfully. 401s add map loop0p1 (253:0): 0 38879 linear 7:0 2048 401s filename_with_spaces: OK 401s del devmap : loop0p1 401s loop deleted : /dev/loop0 401s No devices found 401s filename_with_spaces_cleanup: OK 401s autopkgtest [10:40:53]: test kpartx-file-loopback: -----------------------] 402s autopkgtest [10:40:54]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 402s kpartx-file-loopback PASS 402s autopkgtest [10:40:54]: test tgtbasedmpaths: preparing testbed 486s autopkgtest [10:42:18]: testbed dpkg architecture: arm64 486s autopkgtest [10:42:18]: testbed apt version: 2.0.10 486s autopkgtest [10:42:18]: @@@@@@@@@@@@@@@@@@@@ test bed setup 487s Get:1 http://ftpmaster.internal/ubuntu focal-proposed InRelease [267 kB] 488s Get:2 http://ftpmaster.internal/ubuntu focal-proposed/universe Sources [14.2 kB] 489s Get:3 http://ftpmaster.internal/ubuntu focal-proposed/main Sources [72.0 kB] 489s Get:4 http://ftpmaster.internal/ubuntu focal-proposed/restricted Sources [19.7 kB] 489s Get:5 http://ftpmaster.internal/ubuntu focal-proposed/main arm64 Packages [242 kB] 489s Get:6 http://ftpmaster.internal/ubuntu focal-proposed/main arm64 c-n-f Metadata [1580 B] 489s Get:7 http://ftpmaster.internal/ubuntu focal-proposed/restricted arm64 Packages [2416 B] 489s Get:8 http://ftpmaster.internal/ubuntu focal-proposed/restricted arm64 c-n-f Metadata [380 B] 489s Get:9 http://ftpmaster.internal/ubuntu focal-proposed/universe arm64 Packages [51.6 kB] 489s Get:10 http://ftpmaster.internal/ubuntu focal-proposed/universe arm64 c-n-f Metadata [2448 B] 489s Get:11 http://ftpmaster.internal/ubuntu focal-proposed/multiverse arm64 c-n-f Metadata [116 B] 491s Fetched 674 kB in 2s (270 kB/s) 491s Reading package lists... 494s Reading package lists... 495s Building dependency tree... 495s Reading state information... 495s Calculating upgrade... 495s The following packages will be upgraded: 495s initramfs-tools initramfs-tools-bin initramfs-tools-core 495s 3 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 495s Need to get 67.9 kB of archives. 495s After this operation, 0 B of additional disk space will be used. 495s Get:1 http://ftpmaster.internal/ubuntu focal-proposed/main arm64 initramfs-tools all 0.136ubuntu6.8 [9212 B] 495s Get:2 http://ftpmaster.internal/ubuntu focal-proposed/main arm64 initramfs-tools-core all 0.136ubuntu6.8 [47.8 kB] 495s Get:3 http://ftpmaster.internal/ubuntu focal-proposed/main arm64 initramfs-tools-bin arm64 0.136ubuntu6.8 [10.9 kB] 496s Fetched 67.9 kB in 0s (147 kB/s) 496s (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 ... 100084 files and directories currently installed.) 496s Preparing to unpack .../initramfs-tools_0.136ubuntu6.8_all.deb ... 497s Unpacking initramfs-tools (0.136ubuntu6.8) over (0.136ubuntu6.7) ... 497s Preparing to unpack .../initramfs-tools-core_0.136ubuntu6.8_all.deb ... 497s Unpacking initramfs-tools-core (0.136ubuntu6.8) over (0.136ubuntu6.7) ... 497s Preparing to unpack .../initramfs-tools-bin_0.136ubuntu6.8_arm64.deb ... 497s Unpacking initramfs-tools-bin (0.136ubuntu6.8) over (0.136ubuntu6.7) ... 497s Setting up initramfs-tools-bin (0.136ubuntu6.8) ... 497s Setting up initramfs-tools-core (0.136ubuntu6.8) ... 497s Setting up initramfs-tools (0.136ubuntu6.8) ... 497s update-initramfs: deferring update (trigger activated) 497s Processing triggers for man-db (2.9.1-1) ... 498s Processing triggers for initramfs-tools (0.136ubuntu6.8) ... 498s update-initramfs: Generating /boot/initrd.img-5.4.0-174-generic 519s Unsupported platform on EFI system, doing nothing. 520s Reading package lists... 520s Building dependency tree... 520s Reading state information... 520s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 521s Hit:1 http://ftpmaster.internal/ubuntu focal InRelease 521s Hit:2 http://ftpmaster.internal/ubuntu focal-updates InRelease 521s Hit:3 http://ftpmaster.internal/ubuntu focal-security InRelease 521s Hit:4 http://ftpmaster.internal/ubuntu focal-proposed InRelease 522s Reading package lists... 522s Reading package lists... 522s Building dependency tree... 522s Reading state information... 523s Calculating upgrade... 523s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 523s Reading package lists... 523s Building dependency tree... 523s Reading state information... 524s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 524s autopkgtest [10:42:56]: rebooting testbed after setup commands that affected boot 562s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 591s Reading package lists... 591s Building dependency tree... 591s Reading state information... 592s Starting pkgProblemResolver with broken count: 0 592s Starting 2 pkgProblemResolver with broken count: 0 592s Done 592s The following additional packages will be installed: 592s fio libboost-iostreams1.71.0 libboost-thread1.71.0 libconfig-general-perl 592s libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libibverbs1 libisns0 592s libnl-route-3-200 libpython2.7-minimal libpython2.7-stdlib librados2 librbd1 592s librdmacm1 libtirpc-common libtirpc3 lsscsi open-iscsi python2.7 592s python2.7-minimal tgt 592s Suggested packages: 592s gnuplot gfio python-scipy python2.7-doc binfmt-support tgt-rbd 592s Recommended packages: 592s ibverbs-providers finalrd 593s The following NEW packages will be installed: 593s autopkgtest-satdep fio libboost-iostreams1.71.0 libboost-thread1.71.0 593s libconfig-general-perl libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 593s libibverbs1 libisns0 libnl-route-3-200 libpython2.7-minimal 593s libpython2.7-stdlib librados2 librbd1 librdmacm1 libtirpc-common libtirpc3 593s lsscsi open-iscsi python2.7 python2.7-minimal tgt 593s 0 upgraded, 24 newly installed, 0 to remove and 0 not upgraded. 593s Need to get 10.3 MB/10.3 MB of archives. 593s After this operation, 47.4 MB of additional disk space will be used. 593s Get:1 /tmp/autopkgtest.ZM03dJ/2-autopkgtest-satdep.deb autopkgtest-satdep arm64 0 [732 B] 593s Get:2 http://ftpmaster.internal/ubuntu focal/main arm64 libisns0 arm64 0.97-3 [105 kB] 593s Get:3 http://ftpmaster.internal/ubuntu focal-updates/main arm64 open-iscsi arm64 2.0.874-7.1ubuntu6.4 [277 kB] 594s Get:4 http://ftpmaster.internal/ubuntu focal-updates/universe arm64 libpython2.7-minimal arm64 2.7.18-1~20.04.4 [335 kB] 594s Get:5 http://ftpmaster.internal/ubuntu focal-updates/universe arm64 python2.7-minimal arm64 2.7.18-1~20.04.4 [1261 kB] 594s Get:6 http://ftpmaster.internal/ubuntu focal-updates/main arm64 libnl-route-3-200 arm64 3.4.0-1ubuntu0.1 [137 kB] 594s Get:7 http://ftpmaster.internal/ubuntu focal/main arm64 libibverbs1 arm64 28.0-1ubuntu1 [50.7 kB] 594s Get:8 http://ftpmaster.internal/ubuntu focal/main arm64 librdmacm1 arm64 28.0-1ubuntu1 [61.2 kB] 594s Get:9 http://ftpmaster.internal/ubuntu focal/main arm64 libconfig-general-perl all 2.63-1 [53.9 kB] 594s Get:10 http://ftpmaster.internal/ubuntu focal/main arm64 tgt arm64 1:1.0.79-2ubuntu1 [204 kB] 594s Get:11 http://ftpmaster.internal/ubuntu focal/universe arm64 libglusterfs0 arm64 7.2-2build1 [257 kB] 595s Get:12 http://ftpmaster.internal/ubuntu focal-updates/main arm64 libtirpc-common all 1.2.5-1ubuntu0.1 [7712 B] 595s Get:13 http://ftpmaster.internal/ubuntu focal-updates/main arm64 libtirpc3 arm64 1.2.5-1ubuntu0.1 [74.4 kB] 595s Get:14 http://ftpmaster.internal/ubuntu focal/universe arm64 libgfxdr0 arm64 7.2-2build1 [23.5 kB] 595s Get:15 http://ftpmaster.internal/ubuntu focal/universe arm64 libgfrpc0 arm64 7.2-2build1 [43.2 kB] 595s Get:16 http://ftpmaster.internal/ubuntu focal/universe arm64 libgfapi0 arm64 7.2-2build1 [64.9 kB] 595s Get:17 http://ftpmaster.internal/ubuntu focal/main arm64 libboost-iostreams1.71.0 arm64 1.71.0-6ubuntu6 [234 kB] 595s Get:18 http://ftpmaster.internal/ubuntu focal/main arm64 libboost-thread1.71.0 arm64 1.71.0-6ubuntu6 [245 kB] 595s Get:19 http://ftpmaster.internal/ubuntu focal-updates/main arm64 librados2 arm64 15.2.17-0ubuntu0.20.04.6 [2877 kB] 596s Get:20 http://ftpmaster.internal/ubuntu focal-updates/main arm64 librbd1 arm64 15.2.17-0ubuntu0.20.04.6 [1387 kB] 596s Get:21 http://ftpmaster.internal/ubuntu focal-updates/universe arm64 libpython2.7-stdlib arm64 2.7.18-1~20.04.4 [1868 kB] 596s Get:22 http://ftpmaster.internal/ubuntu focal-updates/universe arm64 python2.7 arm64 2.7.18-1~20.04.4 [248 kB] 596s Get:23 http://ftpmaster.internal/ubuntu focal/universe arm64 fio arm64 3.16-1 [472 kB] 596s Get:24 http://ftpmaster.internal/ubuntu focal/main arm64 lsscsi arm64 0.30-0.1 [43.6 kB] 605s Preconfiguring packages ... 607s Fetched 10.3 MB in 3s (2991 kB/s) 608s Selecting previously unselected package libisns0:arm64. 609s (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 ... 100084 files and directories currently installed.) 609s Preparing to unpack .../00-libisns0_0.97-3_arm64.deb ... 609s Unpacking libisns0:arm64 (0.97-3) ... 610s Selecting previously unselected package open-iscsi. 614s Preparing to unpack .../01-open-iscsi_2.0.874-7.1ubuntu6.4_arm64.deb ... 615s Unpacking open-iscsi (2.0.874-7.1ubuntu6.4) ... 615s Selecting previously unselected package libpython2.7-minimal:arm64. 619s Preparing to unpack .../02-libpython2.7-minimal_2.7.18-1~20.04.4_arm64.deb ... 619s Unpacking libpython2.7-minimal:arm64 (2.7.18-1~20.04.4) ... 620s Selecting previously unselected package python2.7-minimal. 621s Preparing to unpack .../03-python2.7-minimal_2.7.18-1~20.04.4_arm64.deb ... 621s Unpacking python2.7-minimal (2.7.18-1~20.04.4) ... 621s Selecting previously unselected package libnl-route-3-200:arm64. 621s Preparing to unpack .../04-libnl-route-3-200_3.4.0-1ubuntu0.1_arm64.deb ... 621s Unpacking libnl-route-3-200:arm64 (3.4.0-1ubuntu0.1) ... 621s Selecting previously unselected package libibverbs1:arm64. 621s Preparing to unpack .../05-libibverbs1_28.0-1ubuntu1_arm64.deb ... 621s Unpacking libibverbs1:arm64 (28.0-1ubuntu1) ... 621s Selecting previously unselected package librdmacm1:arm64. 621s Preparing to unpack .../06-librdmacm1_28.0-1ubuntu1_arm64.deb ... 621s Unpacking librdmacm1:arm64 (28.0-1ubuntu1) ... 621s Selecting previously unselected package libconfig-general-perl. 622s Preparing to unpack .../07-libconfig-general-perl_2.63-1_all.deb ... 622s Unpacking libconfig-general-perl (2.63-1) ... 622s Selecting previously unselected package tgt. 623s Preparing to unpack .../08-tgt_1%3a1.0.79-2ubuntu1_arm64.deb ... 623s Unpacking tgt (1:1.0.79-2ubuntu1) ... 623s Selecting previously unselected package libglusterfs0:arm64. 626s Preparing to unpack .../09-libglusterfs0_7.2-2build1_arm64.deb ... 626s Unpacking libglusterfs0:arm64 (7.2-2build1) ... 626s Selecting previously unselected package libtirpc-common. 626s Preparing to unpack .../10-libtirpc-common_1.2.5-1ubuntu0.1_all.deb ... 626s Unpacking libtirpc-common (1.2.5-1ubuntu0.1) ... 626s Selecting previously unselected package libtirpc3:arm64. 626s Preparing to unpack .../11-libtirpc3_1.2.5-1ubuntu0.1_arm64.deb ... 626s Unpacking libtirpc3:arm64 (1.2.5-1ubuntu0.1) ... 626s Selecting previously unselected package libgfxdr0:arm64. 626s Preparing to unpack .../12-libgfxdr0_7.2-2build1_arm64.deb ... 626s Unpacking libgfxdr0:arm64 (7.2-2build1) ... 626s Selecting previously unselected package libgfrpc0:arm64. 626s Preparing to unpack .../13-libgfrpc0_7.2-2build1_arm64.deb ... 626s Unpacking libgfrpc0:arm64 (7.2-2build1) ... 626s Selecting previously unselected package libgfapi0:arm64. 627s Preparing to unpack .../14-libgfapi0_7.2-2build1_arm64.deb ... 627s Unpacking libgfapi0:arm64 (7.2-2build1) ... 627s Selecting previously unselected package libboost-iostreams1.71.0:arm64. 627s Preparing to unpack .../15-libboost-iostreams1.71.0_1.71.0-6ubuntu6_arm64.deb ... 627s Unpacking libboost-iostreams1.71.0:arm64 (1.71.0-6ubuntu6) ... 627s Selecting previously unselected package libboost-thread1.71.0:arm64. 627s Preparing to unpack .../16-libboost-thread1.71.0_1.71.0-6ubuntu6_arm64.deb ... 627s Unpacking libboost-thread1.71.0:arm64 (1.71.0-6ubuntu6) ... 627s Selecting previously unselected package librados2. 627s Preparing to unpack .../17-librados2_15.2.17-0ubuntu0.20.04.6_arm64.deb ... 627s Unpacking librados2 (15.2.17-0ubuntu0.20.04.6) ... 627s Selecting previously unselected package librbd1. 627s Preparing to unpack .../18-librbd1_15.2.17-0ubuntu0.20.04.6_arm64.deb ... 627s Unpacking librbd1 (15.2.17-0ubuntu0.20.04.6) ... 627s Selecting previously unselected package libpython2.7-stdlib:arm64. 628s Preparing to unpack .../19-libpython2.7-stdlib_2.7.18-1~20.04.4_arm64.deb ... 628s Unpacking libpython2.7-stdlib:arm64 (2.7.18-1~20.04.4) ... 628s Selecting previously unselected package python2.7. 628s Preparing to unpack .../20-python2.7_2.7.18-1~20.04.4_arm64.deb ... 628s Unpacking python2.7 (2.7.18-1~20.04.4) ... 628s Selecting previously unselected package fio. 628s Preparing to unpack .../21-fio_3.16-1_arm64.deb ... 628s Unpacking fio (3.16-1) ... 628s Selecting previously unselected package lsscsi. 628s Preparing to unpack .../22-lsscsi_0.30-0.1_arm64.deb ... 628s Unpacking lsscsi (0.30-0.1) ... 628s Selecting previously unselected package autopkgtest-satdep. 628s Preparing to unpack .../23-2-autopkgtest-satdep.deb ... 628s Unpacking autopkgtest-satdep (0) ... 628s Setting up libconfig-general-perl (2.63-1) ... 628s Setting up libtirpc-common (1.2.5-1ubuntu0.1) ... 628s Setting up libboost-iostreams1.71.0:arm64 (1.71.0-6ubuntu6) ... 628s Setting up libnl-route-3-200:arm64 (3.4.0-1ubuntu0.1) ... 628s Setting up libglusterfs0:arm64 (7.2-2build1) ... 628s Setting up libpython2.7-minimal:arm64 (2.7.18-1~20.04.4) ... 628s Setting up python2.7-minimal (2.7.18-1~20.04.4) ... 629s Setting up lsscsi (0.30-0.1) ... 629s Setting up libisns0:arm64 (0.97-3) ... 629s Setting up libboost-thread1.71.0:arm64 (1.71.0-6ubuntu6) ... 629s Setting up libtirpc3:arm64 (1.2.5-1ubuntu0.1) ... 629s Setting up libibverbs1:arm64 (28.0-1ubuntu1) ... 629s Setting up open-iscsi (2.0.874-7.1ubuntu6.4) ... 629s grep: /lib/modules-load.d/open-iscsi.conf: No such file or directory 629s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /lib/systemd/system/iscsid.socket. 630s Created symlink /etc/systemd/system/iscsi.service → /lib/systemd/system/open-iscsi.service. 630s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /lib/systemd/system/open-iscsi.service. 631s Setting up libpython2.7-stdlib:arm64 (2.7.18-1~20.04.4) ... 631s Setting up libgfxdr0:arm64 (7.2-2build1) ... 631s Setting up librdmacm1:arm64 (28.0-1ubuntu1) ... 631s Setting up librados2 (15.2.17-0ubuntu0.20.04.6) ... 631s Setting up python2.7 (2.7.18-1~20.04.4) ... 631s Setting up librbd1 (15.2.17-0ubuntu0.20.04.6) ... 631s Setting up tgt (1:1.0.79-2ubuntu1) ... 633s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /lib/systemd/system/tgt.service. 634s Setting up libgfrpc0:arm64 (7.2-2build1) ... 634s Setting up libgfapi0:arm64 (7.2-2build1) ... 634s Setting up fio (3.16-1) ... 634s Processing triggers for libc-bin (2.31-0ubuntu9.14) ... 635s Processing triggers for systemd (245.4-4ubuntu3.23) ... 635s Processing triggers for man-db (2.9.1-1) ... 636s Processing triggers for mime-support (3.64ubuntu1) ... 636s Processing triggers for initramfs-tools (0.136ubuntu6.8) ... 636s update-initramfs: Generating /boot/initrd.img-5.4.0-174-generic 682s Unsupported platform on EFI system, doing nothing. 682s Setting up autopkgtest-satdep (0) ... 687s (Reading database ... 101076 files and directories currently installed.) 687s Removing autopkgtest-satdep (0) ... 690s autopkgtest [10:45:42]: test tgtbasedmpaths: [----------------------- 690s + targetname=iqn.2016-11.foo.com:target.iscsi 690s + pwd 690s + cwd=/tmp/autopkgtest.ZM03dJ/build.87u/src 690s + testdir=/mnt/tgtmpathtest 690s + localhost=127.0.0.1 690s + portal=127.0.0.1:3260 690s + maxpaths=4 690s + backfn=backingfile 690s + expectwwid=60000000000000000e00000000010001 690s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 690s + bglog=/tmp/autopkgtest.ZM03dJ/tgtbasedmpaths-artifacts/test-background.log 690s + fioprep=/tmp/autopkgtest.ZM03dJ/tgtbasedmpaths-artifacts/path-change-prep.fio 690s + fiovrfy=/tmp/autopkgtest.ZM03dJ/tgtbasedmpaths-artifacts/path-change-check.fio 690s + service tgt restart 691s + truncate --size 100M backingfile 691s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 691s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 691s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.ZM03dJ/build.87u/src/backingfile 691s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 691s + echo login #1 691s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 691s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 691s login #1 691s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 691s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 691s + seq 2 4 691s + echo extra login #2 691s + iscsiadm --mode session -r 1 --op new 691s extra login #2 691s + echo extra login #3 691s + iscsiadm --mode session -r 1 --op new 691s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 691s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 691s extra login #3 691s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 691s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 691s extra login #4 691s + echo extra login #4 691s + iscsiadm --mode session -r 1 --op new 691s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 691s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 691s + udevadm settle 691s + sleep 5 696s Status after initial setup 696s + echo Status after initial setup 696s + tgtadm --lld iscsi --mode target --op show 696s Target 1: iqn.2016-11.foo.com:target.iscsi 696s System information: 696s Driver: iscsi 696s State: ready 696s I_T nexus information: 696s I_T nexus: 1 696s Initiator: iqn.1993-08.org.debian:01:ae647af5f8c7 alias: autopkgtest 696s Connection: 0 696s IP Address: 127.0.0.1 696s I_T nexus: 2 696s Initiator: iqn.1993-08.org.debian:01:ae647af5f8c7 alias: autopkgtest 696s Connection: 0 696s IP Address: 127.0.0.1 696s I_T nexus: 3 696s Initiator: iqn.1993-08.org.debian:01:ae647af5f8c7 alias: autopkgtest 696s Connection: 0 696s IP Address: 127.0.0.1 696s I_T nexus: 4 696s Initiator: iqn.1993-08.org.debian:01:ae647af5f8c7 alias: autopkgtest 696s Connection: 0 696s IP Address: 127.0.0.1 696s LUN information: 696s LUN: 0 696s Type: controller 696s SCSI ID: IET 00010000 696s SCSI SN: beaf10 696s Size: 0 MB, Block size: 1 696s Online: Yes 696s Removable media: No 696s Prevent removal: No 696s Readonly: No 696s SWP: No 696s Thin-provisioning: No 696s Backing store type: null 696s Backing store path: None 696s Backing store flags: 696s LUN: 1 696s Type: disk 696s SCSI ID: IET 00010001 696s SCSI SN: beaf11 696s Size: 105 MB, Block size: 512 696s Online: Yes 696s Removable media: No 696s Prevent removal: No 696s Readonly: No 696s SWP: No 696s Thin-provisioning: No 696s Backing store type: rdwr 696s Backing store path: /tmp/autopkgtest.ZM03dJ/build.87u/src/backingfile 696s Backing store flags: 696s Account information: 696s ACL information: 696s ALL 696s + tgtadm --lld iscsi --op show --mode conn --tid 1 696s Session: 4 696s Connection: 0 696s Initiator: iqn.1993-08.org.debian:01:ae647af5f8c7 696s IP Address: 127.0.0.1 696s Session: 3 696s Connection: 0 696s Initiator: iqn.1993-08.org.debian:01:ae647af5f8c7 696s IP Address: 127.0.0.1 696s Session: 2 696s Connection: 0 696s Initiator: iqn.1993-08.org.debian:01:ae647af5f8c7 696s IP Address: 127.0.0.1 696s Session: 1 696s Connection: 0 696s Initiator: iqn.1993-08.org.debian:01:ae647af5f8c7 696s IP Address: 127.0.0.1 696s + iscsiadm --mode session -P 1 696s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 696s Current Portal: 127.0.0.1:3260,1 696s Persistent Portal: 127.0.0.1:3260,1 696s ********** 696s Interface: 696s ********** 696s Iface Name: default 696s Iface Transport: tcp 696s Iface Initiatorname: iqn.1993-08.org.debian:01:ae647af5f8c7 696s Iface IPaddress: 127.0.0.1 696s Iface HWaddress: 696s Iface Netdev: 696s SID: 1 696s iSCSI Connection State: LOGGED IN 696s iSCSI Session State: LOGGED_IN 696s Internal iscsid Session State: NO CHANGE 696s 696s ********** 696s Interface: 696s ********** 696s Iface Name: default 696s Iface Transport: tcp 696s Iface Initiatorname: iqn.1993-08.org.debian:01:ae647af5f8c7 696s Iface IPaddress: 127.0.0.1 696s Iface HWaddress: 696s Iface Netdev: 696s SID: 4 696s iSCSI Connection State: LOGGED IN 696s iSCSI Session State: LOGGED_IN 696s Internal iscsid Session State: NO CHANGE 696s 696s ********** 696s Interface: 696s ********** 696s Iface Name: default 696s Iface Transport: tcp 696s Iface Initiatorname: iqn.1993-08.org.debian:01:ae647af5f8c7 696s Iface IPaddress: 127.0.0.1 696s Iface HWaddress: 696s Iface Netdev: 696s SID: 3 696s iSCSI Connection State: LOGGED IN 696s iSCSI Session State: LOGGED_IN 696s Internal iscsid Session State: NO CHANGE 696s 696s ********** 696s Interface: 696s ********** 696s Iface Name: default 696s Iface Transport: tcp 696s Iface Initiatorname: iqn.1993-08.org.debian:01:ae647af5f8c7 696s Iface IPaddress: 127.0.0.1 696s Iface HWaddress: 696s Iface Netdev: 696s SID: 2 696s iSCSI Connection State: LOGGED IN 696s iSCSI Session State: LOGGED_IN 696s Internal iscsid Session State: NO CHANGE 696s + lsscsi -liv 696s [0:0:0:0] storage IET Controller 0001 - - 696s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 696s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 696s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 696s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 696s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 696s [1:0:0:0] storage IET Controller 0001 - - 696s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 696s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 696s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 696s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 696s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 696s [2:0:0:0] storage IET Controller 0001 - - 696s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 696s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 696s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 696s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 696s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 696s [3:0:0:0] storage IET Controller 0001 - - 696s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 696s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 696s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd SIET_VIRTUAL-DISK_beaf11 696s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 696s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 696s NVMe module may not be loaded 696s ===== paths list ===== 696s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 696s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK unknown 696s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 696s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 696s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 696s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 696s size=100M features='0' hwhandler='0' wp=rw 696s |-+- policy='service-time 0' prio=1 status=active 696s | `- 1:0:0:1 sdb 8:16 active ready running 696s |-+- policy='service-time 0' prio=1 status=enabled 696s | `- 3:0:0:1 sdd 8:48 active ready running 696s |-+- policy='service-time 0' prio=1 status=enabled 696s | `- 0:0:0:1 sda 8:0 active ready running 696s `-+- policy='service-time 0' prio=1 status=enabled 696s `- 2:0:0:1 sdc 8:32 active ready running 696s mpatha: 0 204800 multipath 0 0 4 1 service-time 0 1 2 8:16 1 1 service-time 0 1 2 8:48 1 1 service-time 0 1 2 8:0 1 1 service-time 0 1 2 8:32 1 1 696s Test WWN should now point to DM 696s ../../dm-0 696s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 696s + multipath -v3 -ll 696s Apr 03 10:45:48 | set open fds limit to 1048576/1048576 696s Apr 03 10:45:48 | loading //lib/multipath/libchecktur.so checker 696s Apr 03 10:45:48 | checker tur: message table size = 3 696s Apr 03 10:45:48 | loading //lib/multipath/libprioconst.so prioritizer 696s Apr 03 10:45:48 | foreign library "nvme" loaded successfully 696s Apr 03 10:45:48 | vda: device node name blacklisted 696s Apr 03 10:45:48 | sda: size = 204800 696s Apr 03 10:45:48 | sda: vendor = IET 696s Apr 03 10:45:48 | sda: product = VIRTUAL-DISK 696s Apr 03 10:45:48 | sda: rev = 0001 696s Apr 03 10:45:48 | sda: h:b:t:l = 0:0:0:1 696s Apr 03 10:45:48 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 696s Apr 03 10:45:48 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 696s Apr 03 10:45:48 | sda: serial = beaf11 696s Apr 03 10:45:48 | sda: detect_checker = yes (setting: multipath internal) 696s Apr 03 10:45:48 | sda: path_checker = tur (setting: multipath internal) 696s Apr 03 10:45:48 | sda: checker timeout = 30 s (setting: kernel sysfs) 696s Apr 03 10:45:48 | sda: tur state = up 696s Apr 03 10:45:48 | sdb: size = 204800 696s Apr 03 10:45:48 | sdb: vendor = IET 696s Apr 03 10:45:48 | sdb: product = VIRTUAL-DISK 696s Apr 03 10:45:48 | sdb: rev = 0001 696s Apr 03 10:45:48 | sdb: h:b:t:l = 1:0:0:1 696s Apr 03 10:45:48 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 696s Apr 03 10:45:48 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 696s Apr 03 10:45:48 | sdb: serial = beaf11 696s Apr 03 10:45:48 | sdb: detect_checker = yes (setting: multipath internal) 696s Apr 03 10:45:48 | sdb: path_checker = tur (setting: multipath internal) 696s Apr 03 10:45:48 | sdb: checker timeout = 30 s (setting: kernel sysfs) 696s Apr 03 10:45:48 | sdb: tur state = up 696s Apr 03 10:45:48 | sdc: size = 204800 696s Apr 03 10:45:48 | sdc: vendor = IET 696s Apr 03 10:45:48 | sdc: product = VIRTUAL-DISK 696s Apr 03 10:45:48 | sdc: rev = 0001 696s Apr 03 10:45:48 | sdc: h:b:t:l = 2:0:0:1 696s Apr 03 10:45:48 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 696s Apr 03 10:45:48 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 696s Apr 03 10:45:48 | sdc: serial = beaf11 696s Apr 03 10:45:48 | sdc: detect_checker = yes (setting: multipath internal) 696s Apr 03 10:45:48 | sdc: path_checker = tur (setting: multipath internal) 696s Apr 03 10:45:48 | sdc: checker timeout = 30 s (setting: kernel sysfs) 696s Apr 03 10:45:48 | sdc: tur state = up 696s Apr 03 10:45:48 | sdd: size = 204800 696s Apr 03 10:45:48 | sdd: vendor = IET 696s Apr 03 10:45:48 | sdd: product = VIRTUAL-DISK 696s Apr 03 10:45:48 | sdd: rev = 0001 696s Apr 03 10:45:48 | sdd: h:b:t:l = 3:0:0:1 696s Apr 03 10:45:48 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 696s Apr 03 10:45:48 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 696s Apr 03 10:45:48 | sdd: serial = beaf11 696s Apr 03 10:45:48 | sdd: detect_checker = yes (setting: multipath internal) 696s Apr 03 10:45:48 | sdd: path_checker = tur (setting: multipath internal) 696s Apr 03 10:45:48 | sdd: checker timeout = 30 s (setting: kernel sysfs) 696s Apr 03 10:45:48 | sdd: tur state = up 696s Apr 03 10:45:48 | loop0: device node name blacklisted 696s Apr 03 10:45:48 | loop1: device node name blacklisted 696s Apr 03 10:45:48 | loop2: device node name blacklisted 696s Apr 03 10:45:48 | loop3: device node name blacklisted 696s Apr 03 10:45:48 | loop4: device node name blacklisted 696s Apr 03 10:45:48 | loop5: device node name blacklisted 696s Apr 03 10:45:48 | loop6: device node name blacklisted 696s Apr 03 10:45:48 | loop7: device node name blacklisted 696s Apr 03 10:45:48 | dm-0: device node name blacklisted 696s Apr 03 10:45:48 | libdevmapper version 1.02.167 (2019-11-30) 696s Apr 03 10:45:48 | DM multipath kernel driver v1.13.0 696s Apr 03 10:45:48 | params = 0 0 4 1 service-time 0 1 2 8:16 1 1 service-time 0 1 2 8:48 1 1 service-time 0 1 2 8:0 1 1 service-time 0 1 2 8:32 1 1 696s Apr 03 10:45:48 | status = 2 0 0 0 4 1 A 0 1 2 8:16 A 0 0 1 E 0 1 2 8:48 A 0 0 1 E 0 1 2 8:0 A 0 0 1 E 0 1 2 8:32 A 0 0 1 696s Apr 03 10:45:48 | sdb: detect_prio = yes (setting: multipath internal) 696s Apr 03 10:45:48 | sdb: prio = const (setting: multipath internal) 696s Apr 03 10:45:48 | sdb: prio args = "" (setting: multipath internal) 696s Apr 03 10:45:48 | sdb: const prio = 1 696s Apr 03 10:45:48 | sdd: detect_prio = yes (setting: multipath internal) 696s Apr 03 10:45:48 | sdd: prio = const (setting: multipath internal) 696s Apr 03 10:45:48 | sdd: prio args = "" (setting: multipath internal) 696s Apr 03 10:45:48 | sdd: const prio = 1 696s Apr 03 10:45:48 | sda: detect_prio = yes (setting: multipath internal) 696s Apr 03 10:45:48 | sda: prio = const (setting: multipath internal) 696s Apr 03 10:45:48 | sda: prio args = "" (setting: multipath internal) 696s Apr 03 10:45:48 | sda: const prio = 1 696s Apr 03 10:45:48 | sdc: detect_prio = yes (setting: multipath internal) 696s Apr 03 10:45:48 | sdc: prio = const (setting: multipath internal) 696s Apr 03 10:45:48 | sdc: prio args = "" (setting: multipath internal) 696s Apr 03 10:45:48 | sdc: const prio = 1 696s Apr 03 10:45:48 | unloading const prioritizer 696s Apr 03 10:45:48 | unloading tur checker 696s + dmsetup table 696s + echo Test WWN should now point to DM 696s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 696s + grep dm 696s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 696s mke2fs 1.45.5 (07-Jan-2020) 696s Creating filesystem with 25600 4k blocks and 25600 inodes 696s 696s Allocating group tables: 0/1 done 696s Writing inode tables: 0/1 done 696s Creating journal (1024 blocks): done 696s Writing superblocks and filesystem accounting information: 0/1 done 696s 696s + udevadm settle 696s + sleep 3s 699s + mkdir -p /mnt/tgtmpathtest 699s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 700s + cat 700s + cat 700s + fio /tmp/autopkgtest.ZM03dJ/tgtbasedmpaths-artifacts/path-change-prep.fio 701s 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 701s fio-3.16 701s Starting 1 thread 701s write-phase: Laying out IO file (1 file / 17592186044415MiB) 701s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=95158272, buflen=65536 701s 701s write-phase: (groupid=0, jobs=1): err= 0: pid=9126: Wed Apr 3 10:45:53 2024 701s write: IOPS=4657, BW=291MiB/s (305MB/s)(90.8MiB/312msec); 0 zone resets 701s clat (usec): min=167, max=797, avg=207.31, stdev=41.10 701s lat (usec): min=173, max=801, avg=212.93, stdev=41.11 701s clat percentiles (usec): 701s | 1.00th=[ 172], 5.00th=[ 178], 10.00th=[ 182], 20.00th=[ 188], 701s | 30.00th=[ 192], 40.00th=[ 198], 50.00th=[ 202], 60.00th=[ 204], 701s | 70.00th=[ 208], 80.00th=[ 212], 90.00th=[ 223], 95.00th=[ 241], 701s | 99.00th=[ 404], 99.50th=[ 416], 99.90th=[ 441], 99.95th=[ 799], 701s | 99.99th=[ 799] 701s lat (usec) : 250=95.60%, 500=4.27%, 1000=0.07% 701s cpu : usr=1.29%, sys=11.25%, ctx=1456, majf=0, minf=1 701s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 701s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 701s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 701s issued rwts: total=0,1453,0,0 short=0,0,0,0 dropped=0,0,0,0 701s latency : target=0, window=0, percentile=100.00%, depth=1 701s 701s Run status group 0 (all jobs): 701s WRITE: bw=291MiB/s (305MB/s), 291MiB/s-291MiB/s (305MB/s-305MB/s), io=90.8MiB (95.2MB), run=312-312msec 701s 701s Disk stats (read/write): 701s dm-0: ios=1/692, merge=0/0, ticks=0/132, in_queue=0, util=61.54%, aggrios=0/363, aggrmerge=0/0, aggrticks=0/69, aggrin_queue=0, aggrutil=73.15% 701s sdd: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 701s sdb: ios=1/1453, merge=0/0, ticks=1/278, in_queue=0, util=73.15% 701s sdc: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 701s sda: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 702s Starting the path changes in background 702s + echo Starting the path changes in background 702s Pre FIO 10:45:54.029000301 702s + date +Pre FIO %H:%M:%S.%N 702s + fio /tmp/autopkgtest.ZM03dJ/tgtbasedmpaths-artifacts/path-change-check.fio 704s 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 704s fio-3.16 704s Starting 1 thread 884s 884s verify-phase: (groupid=0, jobs=1): err= 0: pid=9137: Wed Apr 3 10:48:56 2024 884s read: IOPS=8202, BW=513MiB/s (538MB/s)(90.1GiB/180001msec) 884s clat (usec): min=66, max=356269, avg=113.65, stdev=541.68 884s lat (usec): min=66, max=356269, avg=113.82, stdev=541.68 884s clat percentiles (usec): 884s | 1.00th=[ 75], 5.00th=[ 79], 10.00th=[ 81], 20.00th=[ 88], 884s | 30.00th=[ 97], 40.00th=[ 103], 50.00th=[ 109], 60.00th=[ 114], 884s | 70.00th=[ 119], 80.00th=[ 124], 90.00th=[ 133], 95.00th=[ 143], 884s | 99.00th=[ 180], 99.50th=[ 217], 99.90th=[ 334], 99.95th=[ 611], 884s | 99.99th=[13042] 884s bw ( KiB/s): min=98422, max=761088, per=99.80%, avg=523907.73, stdev=90945.92, samples=359 884s iops : min= 1537, max=11892, avg=8186.04, stdev=1421.04, samples=359 884s lat (usec) : 100=35.87%, 250=63.86%, 500=0.21%, 750=0.02%, 1000=0.01% 884s lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01% 884s lat (msec) : 100=0.01%, 250=0.01%, 500=0.01% 884s cpu : usr=7.46%, sys=10.46%, ctx=1477488, majf=0, minf=16 884s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 884s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 884s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 884s issued rwts: total=1476436,0,0,0 short=0,0,0,0 dropped=0,0,0,0 884s latency : target=0, window=0, percentile=100.00%, depth=1 884s 884s Run status group 0 (all jobs): 884s READ: bw=513MiB/s (538MB/s), 513MiB/s-513MiB/s (538MB/s-538MB/s), io=90.1GiB (96.8GB), run=180001-180001msec 884s 884s Disk stats (read/write): 884s dm-0: ios=1475542/21, merge=0/7, ticks=168565/157, in_queue=6124, util=99.03%, aggrios=100470/2, aggrmerge=0/0, aggrticks=10227/0, aggrin_queue=451, aggrutil=97.94% 884s sdd: ios=262099/0, merge=0/0, ticks=25540/0, in_queue=932, util=61.83% 884s sdb: ios=139781/8, merge=0/0, ticks=15369/2, in_queue=872, util=97.94% 884s sdc: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 884s sda: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 885s + date +Post FIO %H:%M:%S.%N 885s Post FIO 10:48:57.076494532 885s FIO verify test with changing paths - OK 885s + echo FIO verify test with changing paths - OK 885s + echo Report log of background activity 885s + cat /tmp/autopkgtest.ZM03dJ/tgtbasedmpaths-artifacts/test-background.log 885s Report log of background activity 885s + iscsiadm --mode session 885s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s + sleep 10s 885s + date +MP report (expect 4) %H:%M:%S.%N 885s MP report (expect 4) 10:46:04.108945873 885s + multipath -ll 885s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 885s size=100M features='0' hwhandler='0' wp=rw 885s |-+- policy='service-time 0' prio=1 status=active 885s | `- 1:0:0:1 sdb 8:16 active ready running 885s |-+- policy='service-time 0' prio=1 status=enabled 885s | `- 3:0:0:1 sdd 8:48 active ready running 885s |-+- policy='service-time 0' prio=1 status=enabled 885s | `- 0:0:0:1 sda 8:0 active ready running 885s `-+- policy='service-time 0' prio=1 status=enabled 885s `- 2:0:0:1 sdc 8:32 active ready running 885s + date +UN-plug path 1 %H:%M:%S.%N 885s UN-plug path 1 10:46:04.185721980 885s + iscsiadm --mode session -r 1 -u 885s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 885s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 885s + iscsiadm --mode session 885s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s + sleep 10s 885s + date +MP report (expect 3) %H:%M:%S.%N 885s MP report (expect 3) 10:46:14.638425769 885s + multipath -ll 885s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 885s size=100M features='0' hwhandler='0' wp=rw 885s |-+- policy='service-time 0' prio=1 status=active 885s | `- 1:0:0:1 sdb 8:16 active ready running 885s |-+- policy='service-time 0' prio=1 status=enabled 885s | `- 3:0:0:1 sdd 8:48 active ready running 885s `-+- policy='service-time 0' prio=1 status=enabled 885s `- 2:0:0:1 sdc 8:32 active ready running 885s + date +UN-plug path 2 %H:%M:%S.%N 885s UN-plug path 2 10:46:14.652748928 885s + iscsiadm --mode session -r 2 -u 885s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 885s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 885s + iscsiadm --mode session 885s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s + sleep 10s 885s + date +MP report (expect 2) %H:%M:%S.%N 885s MP report (expect 2) 10:46:24.749201292 885s + multipath -ll 885s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 885s size=100M features='0' hwhandler='0' wp=rw 885s |-+- policy='service-time 0' prio=1 status=active 885s | `- 3:0:0:1 sdd 8:48 active ready running 885s `-+- policy='service-time 0' prio=1 status=enabled 885s `- 2:0:0:1 sdc 8:32 active ready running 885s + date +UN-plug path 3 %H:%M:%S.%N 885s UN-plug path 3 10:46:24.770297644 885s + iscsiadm --mode session -r 3 -u 885s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 885s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 885s + iscsiadm --mode session 885s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s + sleep 10s 885s + date +MP report (expect 1) %H:%M:%S.%N 885s MP report (expect 1) 10:46:35.051641773 885s + multipath -ll 885s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 885s size=100M features='0' hwhandler='0' wp=rw 885s `-+- policy='service-time 0' prio=1 status=active 885s `- 3:0:0:1 sdd 8:48 active ready running 885s + date +Add paths 5/6/7/8 %H:%M:%S.%N 885s Add paths 5/6/7/8 10:46:35.092001662 885s + iscsiadm --mode session -r 4 --op new 885s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 885s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 885s + iscsiadm --mode session -r 4 --op new 885s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 885s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 885s + iscsiadm --mode session -r 4 --op new 885s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 885s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 885s + iscsiadm --mode session -r 4 --op new 885s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 885s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 885s + iscsiadm --mode session 885s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s + sleep 10s 885s + date +MP report (expect 5) %H:%M:%S.%N 885s MP report (expect 5) 10:46:45.439553933 885s + multipath -ll 885s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 885s size=100M features='0' hwhandler='0' wp=rw 885s |-+- policy='service-time 0' prio=1 status=active 885s | `- 3:0:0:1 sdd 8:48 active ready running 885s |-+- policy='service-time 0' prio=1 status=enabled 885s | `- 1:0:0:1 sdb 8:16 active ready running 885s |-+- policy='service-time 0' prio=1 status=enabled 885s | `- 2:0:0:1 sdc 8:32 active ready running 885s |-+- policy='service-time 0' prio=1 status=enabled 885s | `- 0:0:0:1 sda 8:0 active ready running 885s `-+- policy='service-time 0' prio=1 status=enabled 885s `- 4:0:0:1 sde 8:64 active ready running 885s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 885s UN-plug multiple paths 4/7/8 10:46:45.452062277 885s + iscsiadm --mode session -r 4 -u 885s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 885s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 885s + iscsiadm --mode session -r 7 -u 885s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 885s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 885s + iscsiadm --mode session -r 8 -u 885s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 885s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 885s + iscsiadm --mode session 885s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 885s + sleep 10s 885s + date +Restart multipath daemon %H:%M:%S.%N 885s Restart multipath daemon 10:46:55.678016127 885s + systemctl restart multipathd 885s + sleep 10s 885s + date +Final background report (expect 2) %H:%M:%S.%N 885s Final background report (expect 2) 10:47:06.029655330 885s + multipath -ll 885s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 885s size=100M features='0' hwhandler='0' wp=rw 885s |-+- policy='service-time 0' prio=1 status=active 885s | `- 1:0:0:1 sdb 8:16 active ready running 885s `-+- policy='service-time 0' prio=1 status=enabled 885s `- 0:0:0:1 sda 8:0 active ready running 885s + sync 885s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 885s Final stats 885s + echo Final stats 885s + iscsiadm --mode session --stats 885s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 885s iSCSI SNMP: 885s txdata_octets: 7464 885s rxdata_octets: 1155592 885s noptx_pdus: 0 885s scsicmd_pdus: 126 885s tmfcmd_pdus: 0 885s login_pdus: 0 885s text_pdus: 0 885s dataout_pdus: 0 885s logout_pdus: 0 885s snack_pdus: 0 885s noprx_pdus: 0 885s scsirsp_pdus: 126 885s tmfrsp_pdus: 0 885s textrsp_pdus: 0 885s datain_pdus: 101 885s logoutrsp_pdus: 0 885s r2t_pdus: 0 885s async_pdus: 0 885s rjt_pdus: 0 885s digest_err: 0 885s timeout_err: 0 885s iSCSI Extended: 885s tx_sendpage_failures: 0 885s rx_discontiguous_hdr: 0 885s eh_abort_cnt: 0 885s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 885s iSCSI SNMP: 885s txdata_octets: 51487944 885s rxdata_octets: 70324021672 885s noptx_pdus: 0 885s scsicmd_pdus: 1072398 885s tmfcmd_pdus: 0 885s login_pdus: 0 885s text_pdus: 0 885s dataout_pdus: 0 885s logout_pdus: 0 885s snack_pdus: 0 885s noprx_pdus: 0 885s scsirsp_pdus: 1072398 885s tmfrsp_pdus: 0 885s textrsp_pdus: 0 885s datain_pdus: 1072356 885s logoutrsp_pdus: 0 885s r2t_pdus: 0 885s async_pdus: 0 885s rjt_pdus: 0 885s digest_err: 0 885s timeout_err: 0 885s iSCSI Extended: 885s tx_sendpage_failures: 0 885s rx_discontiguous_hdr: 0 885s eh_abort_cnt: 0 885s + journalctl --no-pager -u multipathd 885s -- Logs begin at Tue 2024-04-02 06:25:09 UTC, end at Wed 2024-04-03 10:48:57 UTC. -- 885s Apr 02 06:25:10 ubuntu systemd[1]: Starting Device-Mapper Multipath Device Controller... 885s Apr 02 06:25:11 ubuntu multipathd[505]: --------start up-------- 885s Apr 02 06:25:11 ubuntu multipathd[505]: read /etc/multipath.conf 885s Apr 02 06:25:11 ubuntu multipathd[505]: path checkers start up 885s Apr 02 06:25:11 ubuntu systemd[1]: Started Device-Mapper Multipath Device Controller. 885s Apr 02 06:30:19 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad systemd[1]: Stopping Device-Mapper Multipath Device Controller... 885s Apr 02 06:30:19 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad multipathd[505]: exit (signal) 885s Apr 02 06:30:19 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad multipathd[505]: --------shut down------- 885s Apr 02 06:30:19 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad systemd[1]: multipathd.service: Succeeded. 885s Apr 02 06:30:19 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad systemd[1]: Stopped Device-Mapper Multipath Device Controller. 885s -- Reboot -- 885s Apr 02 06:30:38 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad systemd[1]: Starting Device-Mapper Multipath Device Controller... 885s Apr 02 06:30:38 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad multipathd[400]: --------start up-------- 885s Apr 02 06:30:38 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad multipathd[400]: read /etc/multipath.conf 885s Apr 02 06:30:38 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad multipathd[400]: path checkers start up 885s Apr 02 06:30:38 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad systemd[1]: Started Device-Mapper Multipath Device Controller. 885s Apr 02 06:31:01 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad multipathd[400]: exit (signal) 885s Apr 02 06:31:01 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad multipathd[400]: --------shut down------- 885s Apr 02 06:31:01 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad systemd[1]: Stopping Device-Mapper Multipath Device Controller... 885s -- Reboot -- 885s Apr 03 10:42:00 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad systemd[1]: Starting Device-Mapper Multipath Device Controller... 885s Apr 03 10:42:00 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad multipathd[427]: --------start up-------- 885s Apr 03 10:42:00 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad multipathd[427]: read /etc/multipath.conf 885s Apr 03 10:42:00 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad multipathd[427]: path checkers start up 885s Apr 03 10:42:00 auto-syncubuntu-focal-20-04-arm64-server-20240220-disk1-img-ad systemd[1]: Started Device-Mapper Multipath Device Controller. 885s Apr 03 10:42:59 autopkgtest multipathd[427]: exit (signal) 885s Apr 03 10:42:59 autopkgtest multipathd[427]: --------shut down------- 885s Apr 03 10:42:59 autopkgtest systemd[1]: Stopping Device-Mapper Multipath Device Controller... 885s -- Reboot -- 885s Apr 03 10:43:32 autopkgtest systemd[1]: Starting Device-Mapper Multipath Device Controller... 885s Apr 03 10:43:34 autopkgtest multipathd[426]: --------start up-------- 885s Apr 03 10:43:34 autopkgtest multipathd[426]: read /etc/multipath.conf 885s Apr 03 10:43:34 autopkgtest multipathd[426]: path checkers start up 885s Apr 03 10:43:34 autopkgtest systemd[1]: Started Device-Mapper Multipath Device Controller. 885s Apr 03 10:45:44 autopkgtest multipathd[426]: mpatha: load table [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:48 1] 885s Apr 03 10:45:44 autopkgtest multipathd[426]: sdd [8:48]: path added to devmap mpatha 885s Apr 03 10:45:45 autopkgtest multipathd[426]: mpatha: performing delayed actions 885s Apr 03 10:45:45 autopkgtest multipathd[426]: mpatha: load table [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:32 1] 885s Apr 03 10:46:04 autopkgtest multipathd[426]: mpatha: load table [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:32 1] 885s Apr 03 10:46:04 autopkgtest multipathd[426]: sda [8:0]: path removed from map mpatha 885s Apr 03 10:46:14 autopkgtest multipathd[426]: sdb: mark as failed 885s Apr 03 10:46:14 autopkgtest multipathd[426]: mpatha: remaining active paths: 2 885s Apr 03 10:46:14 autopkgtest multipathd[426]: mpatha: load table [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:32 1] 885s Apr 03 10:46:14 autopkgtest multipathd[426]: sdb [8:16]: path removed from map mpatha 885s Apr 03 10:46:25 autopkgtest multipathd[426]: mpatha: load table [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 885s Apr 03 10:46:25 autopkgtest multipathd[426]: sdc [8:32]: path removed from map mpatha 885s Apr 03 10:46:35 autopkgtest multipathd[426]: mpatha: load table [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:16 1] 885s Apr 03 10:46:35 autopkgtest multipathd[426]: sdb [8:16]: path added to devmap mpatha 885s Apr 03 10:46:36 autopkgtest multipathd[426]: mpatha: load table [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 885s Apr 03 10:46:36 autopkgtest multipathd[426]: sdc [8:32]: path added to devmap mpatha 885s Apr 03 10:46:36 autopkgtest multipathd[426]: mpatha: load table [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:0 1] 885s Apr 03 10:46:36 autopkgtest multipathd[426]: sda [8:0]: path added to devmap mpatha 885s Apr 03 10:46:36 autopkgtest multipathd[426]: mpatha: load table [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:64 1] 885s Apr 03 10:46:36 autopkgtest multipathd[426]: sde [8:64]: path added to devmap mpatha 885s Apr 03 10:46:45 autopkgtest multipathd[426]: 8:48: cannot find block device 885s Apr 03 10:46:45 autopkgtest multipathd[426]: sdd: mark as failed 885s Apr 03 10:46:45 autopkgtest multipathd[426]: mpatha: remaining active paths: 4 885s Apr 03 10:46:45 autopkgtest multipathd[426]: 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:0 1 service-time 0 1 1 8:64 1] 885s Apr 03 10:46:45 autopkgtest multipathd[426]: sdd [8:48]: path removed from map mpatha 885s Apr 03 10:46:46 autopkgtest multipathd[426]: 8:32: cannot find block device 885s Apr 03 10:46:46 autopkgtest multipathd[426]: 8:64: cannot find block device 885s Apr 03 10:46:46 autopkgtest multipathd[426]: sde: No iscsi session for 'session8' 885s Apr 03 10:46:46 autopkgtest multipathd[426]: mpatha: load table [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:64 1] 885s Apr 03 10:46:46 autopkgtest multipathd[426]: 8:64: cannot find block device 885s Apr 03 10:46:46 autopkgtest multipathd[426]: sdc [8:32]: path removed from map mpatha 885s Apr 03 10:46:46 autopkgtest multipathd[426]: mpatha: load table [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:0 1] 885s Apr 03 10:46:46 autopkgtest multipathd[426]: sde [8:64]: path removed from map mpatha 885s Apr 03 10:46:55 autopkgtest multipathd[426]: exit (signal) 885s Apr 03 10:46:55 autopkgtest systemd[1]: Stopping Device-Mapper Multipath Device Controller... 885s Apr 03 10:46:55 autopkgtest multipathd[426]: --------shut down------- 885s Apr 03 10:46:55 autopkgtest systemd[1]: multipathd.service: Succeeded. 885s Apr 03 10:46:55 autopkgtest systemd[1]: Stopped Device-Mapper Multipath Device Controller. 885s Apr 03 10:46:55 autopkgtest systemd[1]: Starting Device-Mapper Multipath Device Controller... 885s Apr 03 10:46:55 autopkgtest multipathd[9515]: --------start up-------- 885s Apr 03 10:46:55 autopkgtest multipathd[9515]: read /etc/multipath.conf 885s Apr 03 10:46:55 autopkgtest multipathd[9515]: path checkers start up 885s Apr 03 10:46:56 autopkgtest systemd[1]: Started Device-Mapper Multipath Device Controller. 885s + echo Check final path status 885s Check final path status 885s + multipath -ll 885s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 885s size=100M features='0' hwhandler='0' wp=rw 885s |-+- policy='service-time 0' prio=1 status=active 885s | `- 1:0:0:1 sdb 8:16 active ready running 885s `-+- policy='service-time 0' prio=1 status=enabled 885s `- 0:0:0:1 sda 8:0 active ready running 885s + multipath -ll 885s + grep --count status= 885s + diskc=2 885s + multipath -ll 885s + grep --count status=active 885s + diska=1 885s + multipath -ll 885s + grep --count status=enabled 885s + OK 885s diske=1 885s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 885s + echo OK 885s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 885s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 885s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 885s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 885s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 885s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 886s autopkgtest [10:48:58]: test tgtbasedmpaths: -----------------------] 886s autopkgtest [10:48:58]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 886s tgtbasedmpaths PASS 886s autopkgtest [10:48:58]: @@@@@@@@@@@@@@@@@@@@ summary 886s kpartx-file-loopback PASS 886s tgtbasedmpaths PASS 898s Creating nova instance adt-focal-arm64-multipath-tools-20240403-103412-juju-7f2275-prod-proposed-migration-environment-2-049acc4a-dc1a-432c-824e-6608d1d8b64f from image adt/ubuntu-focal-arm64-server-20240402.img (UUID fea2be9d-9d8e-477e-86cb-6bc08147c3ab)... 898s Creating nova instance adt-focal-arm64-multipath-tools-20240403-103412-juju-7f2275-prod-proposed-migration-environment-2-049acc4a-dc1a-432c-824e-6608d1d8b64f from image adt/ubuntu-focal-arm64-server-20240402.img (UUID fea2be9d-9d8e-477e-86cb-6bc08147c3ab)...