0s autopkgtest [07:05:27]: starting date and time: 2024-05-01 07:05:27+0000 0s autopkgtest [07:05:27]: git checkout: 699e7f9f ssh-setup/nova: explicitely set 'fqdn' in cloud-init 0s autopkgtest [07:05:27]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.2ds5sfyp/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:glibc --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=glibc/2.39-0ubuntu8.1 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos02-ppc64el-24.secgroup --name adt-oracular-ppc64el-multipath-tools-20240501-070527-juju-7f2275-prod-proposed-migration-environment-3-7aef95ce-a0e9-48ab-b301-0750d182fbbb --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 109s autopkgtest [07:07:16]: testbed dpkg architecture: ppc64el 109s autopkgtest [07:07:16]: testbed apt version: 2.7.14build2 109s autopkgtest [07:07:16]: @@@@@@@@@@@@@@@@@@@@ test bed setup 110s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [64.7 kB] 110s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [1964 B] 110s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [197 kB] 110s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [1680 B] 110s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [21.5 kB] 110s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [33.7 kB] 110s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [123 kB] 110s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [756 B] 111s Fetched 444 kB in 1s (661 kB/s) 111s Reading package lists... 113s Reading package lists... 113s Building dependency tree... 113s Reading state information... 113s Calculating upgrade... 113s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 113s Reading package lists... 114s Building dependency tree... 114s Reading state information... 114s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 114s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 114s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 114s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 114s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 115s Reading package lists... 115s Reading package lists... 116s Building dependency tree... 116s Reading state information... 116s Calculating upgrade... 116s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 116s Reading package lists... 116s Building dependency tree... 116s Reading state information... 116s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 119s autopkgtest [07:07:26]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 120s autopkgtest [07:07:27]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 123s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 123s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 123s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 123s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 123s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 123s gpgv: issuer "steve.langasek@ubuntu.com" 123s gpgv: Can't check signature: No public key 123s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 123s autopkgtest [07:07:30]: testing package multipath-tools version 0.9.4-5ubuntu8 124s autopkgtest [07:07:31]: build not needed 131s autopkgtest [07:07:38]: test kpartx-file-loopback: preparing testbed 132s Reading package lists... 132s Building dependency tree... 132s Reading state information... 132s Starting pkgProblemResolver with broken count: 0 133s Starting 2 pkgProblemResolver with broken count: 0 133s Done 133s The following additional packages will be installed: 133s liburing2 qemu-utils 133s Recommended packages: 133s qemu-block-extra 133s The following NEW packages will be installed: 133s autopkgtest-satdep liburing2 qemu-utils 133s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 133s Need to get 2329 kB/2330 kB of archives. 133s After this operation, 15.4 MB of additional disk space will be used. 133s Get:1 /tmp/autopkgtest.HYxDxd/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 133s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.5-1build1 [26.0 kB] 133s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 134s Fetched 2329 kB in 1s (3394 kB/s) 134s Selecting previously unselected package liburing2:ppc64el. 134s (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 ... 72135 files and directories currently installed.) 134s Preparing to unpack .../liburing2_2.5-1build1_ppc64el.deb ... 134s Unpacking liburing2:ppc64el (2.5-1build1) ... 134s Selecting previously unselected package qemu-utils. 134s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 134s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 134s Selecting previously unselected package autopkgtest-satdep. 134s Preparing to unpack .../1-autopkgtest-satdep.deb ... 134s Unpacking autopkgtest-satdep (0) ... 134s Setting up liburing2:ppc64el (2.5-1build1) ... 134s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 134s Setting up autopkgtest-satdep (0) ... 134s Processing triggers for man-db (2.12.0-4build2) ... 135s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 137s (Reading database ... 72155 files and directories currently installed.) 137s Removing autopkgtest-satdep (0) ... 138s autopkgtest [07:07:45]: test kpartx-file-loopback: [----------------------- 138s Formatting 'foo.img', fmt=raw size=20971520 139s Creating new GPT entries in memory. 139s Warning: The kernel is still using the old partition table. 139s The new table will be used at the next reboot or after you 139s run partprobe(8) or kpartx(8) 139s The operation has completed successfully. 139s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 139s standard_filename: OK 139s del devmap : loop0p1 139s No devices found 139s standard_filename_cleanup: OK 139s Formatting 'fou du FaFa.img', fmt=raw size=20971520 140s Creating new GPT entries in memory. 140s Warning: The kernel is still using the old partition table. 140s The new table will be used at the next reboot or after you 140s run partprobe(8) or kpartx(8) 140s The operation has completed successfully. 140s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 140s filename_with_spaces: OK 140s del devmap : loop0p1 140s No devices found 140s filename_with_spaces_cleanup: OK 141s autopkgtest [07:07:48]: test kpartx-file-loopback: -----------------------] 141s kpartx-file-loopback PASS 141s autopkgtest [07:07:48]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 141s autopkgtest [07:07:48]: test tgtbasedmpaths: preparing testbed 240s autopkgtest [07:09:27]: testbed dpkg architecture: ppc64el 241s autopkgtest [07:09:28]: testbed apt version: 2.7.14build2 241s autopkgtest [07:09:28]: @@@@@@@@@@@@@@@@@@@@ test bed setup 241s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [64.7 kB] 242s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [1680 B] 242s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [1964 B] 242s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [21.5 kB] 242s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [197 kB] 242s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [33.7 kB] 242s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [123 kB] 242s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [756 B] 242s Fetched 444 kB in 1s (651 kB/s) 242s Reading package lists... 245s Reading package lists... 245s Building dependency tree... 245s Reading state information... 245s Calculating upgrade... 245s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 245s Reading package lists... 245s Building dependency tree... 245s Reading state information... 245s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 246s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 246s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 246s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 246s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 247s Reading package lists... 247s Reading package lists... 247s Building dependency tree... 247s Reading state information... 248s Calculating upgrade... 248s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 248s Reading package lists... 248s Building dependency tree... 248s Reading state information... 248s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 252s Reading package lists... 252s Building dependency tree... 252s Reading state information... 252s Starting pkgProblemResolver with broken count: 0 252s Starting 2 pkgProblemResolver with broken count: 0 252s Done 253s The following additional packages will be installed: 253s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 253s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 253s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 253s librdmacm1t64 lsscsi open-iscsi tgt 253s Suggested packages: 253s fio-examples gnuplot tgt-glusterfs tgt-rbd 253s Recommended packages: 253s finalrd 253s The following NEW packages will be installed: 253s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 253s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 253s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 253s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 253s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 253s Need to get 10.8 MB/10.8 MB of archives. 253s After this operation, 49.9 MB of additional disk space will be used. 253s Get:1 /tmp/autopkgtest.HYxDxd/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 253s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu4 [54.4 kB] 253s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-0.3build3 [119 kB] 253s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu4 [389 kB] 253s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 253s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 253s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu6 [256 kB] 253s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4build3 [21.5 kB] 253s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4build3 [311 kB] 253s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4build3 [47.0 kB] 253s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4build3 [100 kB] 253s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.0-1 [97.3 kB] 253s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 253s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 253s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 253s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-2.1ubuntu3 [260 kB] 253s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-2.1ubuntu3 [280 kB] 253s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu6 [4050 kB] 254s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 254s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu6 [3612 kB] 254s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.36-1build2 [716 kB] 254s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 254s Preconfiguring packages ... 254s Fetched 10.8 MB in 1s (9554 kB/s) 254s Selecting previously unselected package libopeniscsiusr. 254s (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 ... 72135 files and directories currently installed.) 254s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu4_ppc64el.deb ... 254s Unpacking libopeniscsiusr (2.1.9-3ubuntu4) ... 254s Selecting previously unselected package libisns0t64:ppc64el. 254s Preparing to unpack .../01-libisns0t64_0.101-0.3build3_ppc64el.deb ... 254s Unpacking libisns0t64:ppc64el (0.101-0.3build3) ... 254s Selecting previously unselected package open-iscsi. 254s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu4_ppc64el.deb ... 254s Unpacking open-iscsi (2.1.9-3ubuntu4) ... 254s Selecting previously unselected package librdmacm1t64:ppc64el. 254s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 254s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 254s Selecting previously unselected package libconfig-general-perl. 254s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 254s Unpacking libconfig-general-perl (2.65-2) ... 255s Selecting previously unselected package tgt. 255s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu6_ppc64el.deb ... 255s Unpacking tgt (1:1.0.85-1.1ubuntu6) ... 255s Selecting previously unselected package libgfxdr0:ppc64el. 255s Preparing to unpack .../06-libgfxdr0_11.1-4build3_ppc64el.deb ... 255s Unpacking libgfxdr0:ppc64el (11.1-4build3) ... 255s Selecting previously unselected package libglusterfs0:ppc64el. 255s Preparing to unpack .../07-libglusterfs0_11.1-4build3_ppc64el.deb ... 255s Unpacking libglusterfs0:ppc64el (11.1-4build3) ... 255s Selecting previously unselected package libgfrpc0:ppc64el. 255s Preparing to unpack .../08-libgfrpc0_11.1-4build3_ppc64el.deb ... 255s Unpacking libgfrpc0:ppc64el (11.1-4build3) ... 255s Selecting previously unselected package libgfapi0:ppc64el. 255s Preparing to unpack .../09-libgfapi0_11.1-4build3_ppc64el.deb ... 255s Unpacking libgfapi0:ppc64el (11.1-4build3) ... 255s Selecting previously unselected package libnbd0. 255s Preparing to unpack .../10-libnbd0_1.20.0-1_ppc64el.deb ... 255s Unpacking libnbd0 (1.20.0-1) ... 255s Selecting previously unselected package libdaxctl1:ppc64el. 255s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 255s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 255s Selecting previously unselected package libndctl6:ppc64el. 255s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 255s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 255s Selecting previously unselected package libpmem1:ppc64el. 255s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 255s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 255s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 255s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 255s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 255s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 255s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 255s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 255s Selecting previously unselected package librados2. 255s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu6_ppc64el.deb ... 255s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 255s Selecting previously unselected package libpmemobj1:ppc64el. 255s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 255s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 255s Selecting previously unselected package librbd1. 255s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu6_ppc64el.deb ... 255s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 255s Selecting previously unselected package fio. 255s Preparing to unpack .../19-fio_3.36-1build2_ppc64el.deb ... 255s Unpacking fio (3.36-1build2) ... 255s Selecting previously unselected package lsscsi. 255s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 255s Unpacking lsscsi (0.32-1build1) ... 255s Selecting previously unselected package autopkgtest-satdep. 255s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 255s Unpacking autopkgtest-satdep (0) ... 255s Setting up libconfig-general-perl (2.65-2) ... 255s Setting up libisns0t64:ppc64el (0.101-0.3build3) ... 255s Setting up libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 255s Setting up libnbd0 (1.20.0-1) ... 255s Setting up libopeniscsiusr (2.1.9-3ubuntu4) ... 255s Setting up libglusterfs0:ppc64el (11.1-4build3) ... 255s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 255s Setting up lsscsi (0.32-1build1) ... 255s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 255s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 255s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 255s Setting up tgt (1:1.0.85-1.1ubuntu6) ... 256s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 256s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 256s Setting up libgfxdr0:ppc64el (11.1-4build3) ... 256s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 256s Setting up open-iscsi (2.1.9-3ubuntu4) ... 257s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 257s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 257s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 258s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 258s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 258s Setting up libgfrpc0:ppc64el (11.1-4build3) ... 258s Setting up libgfapi0:ppc64el (11.1-4build3) ... 258s Setting up fio (3.36-1build2) ... 258s Setting up autopkgtest-satdep (0) ... 258s Processing triggers for man-db (2.12.0-4build2) ... 259s Processing triggers for initramfs-tools (0.142ubuntu25) ... 259s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 259s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 268s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 270s (Reading database ... 72376 files and directories currently installed.) 270s Removing autopkgtest-satdep (0) ... 273s autopkgtest [07:10:00]: test tgtbasedmpaths: [----------------------- 273s + targetname=iqn.2016-11.foo.com:target.iscsi 273s + pwd 273s + cwd=/tmp/autopkgtest.HYxDxd/build.ONY/src 273s + testdir=/mnt/tgtmpathtest 273s + localhost=127.0.0.1 273s + portal=127.0.0.1:3260 273s + maxpaths=4 273s + backfn=backingfile 273s + expectwwid=60000000000000000e00000000010001 273s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 273s + bglog=/tmp/autopkgtest.HYxDxd/tgtbasedmpaths-artifacts/test-background.log 273s + fioprep=/tmp/autopkgtest.HYxDxd/tgtbasedmpaths-artifacts/path-change-prep.fio 273s + fiovrfy=/tmp/autopkgtest.HYxDxd/tgtbasedmpaths-artifacts/path-change-check.fio 273s + service tgt restart 274s + truncate --size 100M backingfile 274s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 274s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 274s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.HYxDxd/build.ONY/src/backingfile 274s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 274s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 274s login #1 274s + echo login #1 274s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 274s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 274s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 274s + seq 2 4 274s extra login #2 274s + echo extra login #2 274s + iscsiadm --mode session -r 1 --op new 274s + echo extra login #3 274s + iscsiadm --mode session -r 1 --op new 274s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 274s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 274s extra login #3 274s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 274s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 274s extra login #4 274s + echo extra login #4 274s + iscsiadm --mode session -r 1 --op new 274s + udevadm settle 274s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 274s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 274s + sleep 5 279s Status after initial setup 279s + echo Status after initial setup 279s + tgtadm --lld iscsi --mode target --op show 279s + tgtadm --lld iscsi --op show --mode conn --tid 1 279s Target 1: iqn.2016-11.foo.com:target.iscsi 279s System information: 279s Driver: iscsi 279s State: ready 279s I_T nexus information: 279s I_T nexus: 1 279s Initiator: iqn.2004-10.com.ubuntu:01:5128426bca alias: autopkgtest 279s Connection: 0 279s IP Address: 127.0.0.1 279s I_T nexus: 2 279s Initiator: iqn.2004-10.com.ubuntu:01:5128426bca alias: autopkgtest 279s Connection: 0 279s IP Address: 127.0.0.1 279s I_T nexus: 3 279s Initiator: iqn.2004-10.com.ubuntu:01:5128426bca alias: autopkgtest 279s Connection: 0 279s IP Address: 127.0.0.1 279s I_T nexus: 4 279s Initiator: iqn.2004-10.com.ubuntu:01:5128426bca alias: autopkgtest 279s Connection: 0 279s IP Address: 127.0.0.1 279s LUN information: 279s LUN: 0 279s Type: controller 279s SCSI ID: IET 00010000 279s SCSI SN: beaf10 279s Size: 0 MB, Block size: 1 279s Online: Yes 279s Removable media: No 279s Prevent removal: No 279s Readonly: No 279s SWP: No 279s Thin-provisioning: No 279s Backing store type: null 279s Backing store path: None 279s Backing store flags: 279s LUN: 1 279s Type: disk 279s SCSI ID: IET 00010001 279s SCSI SN: beaf11 279s Size: 105 MB, Block size: 512 279s Online: Yes 279s Removable media: No 279s Prevent removal: No 279s Readonly: No 279s SWP: No 279s Thin-provisioning: No 279s Backing store type: rdwr 279s Backing store path: /tmp/autopkgtest.HYxDxd/build.ONY/src/backingfile 279s Backing store flags: 279s Account information: 279s ACL information: 279s ALL 279s + iscsiadm --mode session -P 1 279s Session: 4 279s Connection: 0 279s Initiator: iqn.2004-10.com.ubuntu:01:5128426bca 279s IP Address: 127.0.0.1 279s Session: 3 279s Connection: 0 279s Initiator: iqn.2004-10.com.ubuntu:01:5128426bca 279s IP Address: 127.0.0.1 279s Session: 2 279s Connection: 0 279s Initiator: iqn.2004-10.com.ubuntu:01:5128426bca 279s IP Address: 127.0.0.1 279s Session: 1 279s Connection: 0 279s Initiator: iqn.2004-10.com.ubuntu:01:5128426bca 279s IP Address: 127.0.0.1 279s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 279s Current Portal: 127.0.0.1:3260,1 279s Persistent Portal: 127.0.0.1:3260,1 279s ********** 279s Interface: 279s ********** 279s Iface Name: default 279s Iface Transport: tcp 279s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:5128426bca 279s Iface IPaddress: 127.0.0.1 279s Iface HWaddress: default 279s Iface Netdev: default 279s SID: 1 279s iSCSI Connection State: LOGGED IN 279s iSCSI Session State: LOGGED_IN 279s Internal iscsid Session State: NO CHANGE 279s 279s ********** 279s Interface: 279s ********** 279s Iface Name: default 279s Iface Transport: tcp 279s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:5128426bca 279s Iface IPaddress: 127.0.0.1 279s Iface HWaddress: default 279s Iface Netdev: default 279s SID: 2 279s iSCSI Connection State: LOGGED IN 279s iSCSI Session State: LOGGED_IN 279s Internal iscsid Session State: NO CHANGE 279s 279s ********** 279s Interface: 279s ********** 279s Iface Name: default 279s Iface Transport: tcp 279s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:5128426bca 279s Iface IPaddress: 127.0.0.1 279s Iface HWaddress: default 279s Iface Netdev: default 279s SID: 3 279s iSCSI Connection State: LOGGED IN 279s iSCSI Session State: LOGGED_IN 279s Internal iscsid Session State: NO CHANGE 279s 279s ********** 279s Interface: 279s ********** 279s Iface Name: default 279s Iface Transport: tcp 279s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:5128426bca 279s Iface IPaddress: 127.0.0.1 279s Iface HWaddress: default 279s Iface Netdev: default 279s SID: 4 279s iSCSI Connection State: LOGGED IN 279s iSCSI Session State: LOGGED_IN 279s Internal iscsid Session State: NO CHANGE 279s + lsscsi -liv 279s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 279s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 279s 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] 279s [1:0:0:0] storage IET Controller 0001 - - 279s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 279s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 279s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 279s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 279s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 279s [2:0:0:0] storage IET Controller 0001 - - 279s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 279s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 279s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 279s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 279s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 279s [3:0:0:0] storage IET Controller 0001 - - 279s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 279s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 279s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 279s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 279s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 279s [4:0:0:0] storage IET Controller 0001 - - 279s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 279s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 279s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 279s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 279s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 279s NVMe module may not be loaded 279s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 279s + multipath -v3 -ll 279s 65.154205 | set open fds limit to 1048576/1048576 279s 65.154321 | loading /lib/multipath/libchecktur.so checker 279s 65.154421 | checker tur: message table size = 3 279s 65.154450 | loading /lib/multipath/libprioconst.so prioritizer 279s 65.154571 | _init_foreign: foreign library "nvme" is not enabled 279s 65.160722 | sda: size = 167772160 279s 65.160934 | sda: vendor = QEMU 279s 65.160982 | sda: product = QEMU HARDDISK 279s 65.161007 | sda: rev = 2.5+ 279s 65.161699 | sda: h:b:t:l = 0:0:0:0 279s 65.162052 | sda: tgt_node_name = 279s 65.162075 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 279s 65.162078 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 279s 65.162245 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 279s 65.162269 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 279s 65.162284 | __sysfs_attr_get_value: attribute '/sys/devices/pci0000:00/0000:00:02.0/virtio1/host0/target0:0:0/0:0:0:0/vpd_pg80' can not be opened: No such file or directory 279s 65.162289 | failed to read sysfs vpd pg80: No such file or directory 279s 65.162551 | sda: fail to get serial 279s 65.162575 | sda: detect_checker = yes (setting: multipath internal) 279s 65.162799 | sda: path_checker = tur (setting: multipath internal) 279s 65.162823 | sda: checker timeout = 30 s (setting: kernel sysfs) 279s 65.163018 | sda: tur state = up 279s 65.163384 | sdb: size = 204800 279s 65.163550 | sdb: vendor = IET 279s 65.163594 | sdb: product = VIRTUAL-DISK 279s 65.163618 | sdb: rev = 0001 279s 65.164363 | sdb: h:b:t:l = 1:0:0:1 279s 65.164782 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 279s 65.164805 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 279s 65.164808 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 279s 65.164990 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 279s 65.165013 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 279s 65.165030 | sdb: serial = beaf11 279s 65.165033 | sdb: detect_checker = yes (setting: multipath internal) 279s 65.165468 | sdb: path_checker = tur (setting: multipath internal) 279s 65.165493 | sdb: checker timeout = 30 s (setting: kernel sysfs) 279s 65.165758 | sdb: tur state = up 279s 65.165923 | sdc: size = 204800 279s 65.166067 | sdc: vendor = IET 279s 65.166111 | sdc: product = VIRTUAL-DISK 279s 65.166135 | sdc: rev = 0001 279s 65.166931 | sdc: h:b:t:l = 2:0:0:1 279s 65.167336 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 279s 65.167359 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 279s 65.167362 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 279s 65.167532 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 279s 65.167554 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 279s 65.167570 | sdc: serial = beaf11 279s 65.167573 | sdc: detect_checker = yes (setting: multipath internal) 279s 65.168040 | sdc: path_checker = tur (setting: multipath internal) 279s 65.168074 | sdc: checker timeout = 30 s (setting: kernel sysfs) 279s 65.168342 | sdc: tur state = up 279s 65.168513 | sdd: size = 204800 279s 65.168681 | sdd: vendor = IET 279s 65.168726 | sdd: product = VIRTUAL-DISK 279s 65.168751 | sdd: rev = 0001 279s 65.169510 | sdd: h:b:t:l = 3:0:0:1 279s 65.169910 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 279s 65.169933 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 279s 65.169936 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 279s 65.170102 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 279s 65.170125 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 279s 65.170140 | sdd: serial = beaf11 279s 65.170143 | sdd: detect_checker = yes (setting: multipath internal) 279s 65.170533 | sdd: path_checker = tur (setting: multipath internal) 279s 65.170556 | sdd: checker timeout = 30 s (setting: kernel sysfs) 279s 65.170786 | sdd: tur state = up 279s 65.170975 | sde: size = 204800 279s 65.171143 | sde: vendor = IET 279s 65.171187 | sde: product = VIRTUAL-DISK 279s 65.171211 | sde: rev = 0001 279s 65.171973 | sde: h:b:t:l = 4:0:0:1 279s 65.172425 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 279s 65.172458 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 279s 65.172460 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 279s 65.172639 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 279s 65.172661 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 279s 65.172677 | sde: serial = beaf11 279s 65.172680 | sde: detect_checker = yes (setting: multipath internal) 279s 65.175405 | sde: path_checker = tur (setting: multipath internal) 279s 65.175445 | sde: checker timeout = 30 s (setting: kernel sysfs) 279s 65.175712 | sde: tur state = up 279s 65.175876 | loop0: device node name blacklisted 279s 65.176020 | loop1: device node name blacklisted 279s 65.176139 | loop2: device node name blacklisted 279s 65.176264 | loop3: device node name blacklisted 279s 65.176388 | loop4: device node name blacklisted 279s 65.176511 | loop5: device node name blacklisted 279s 65.176632 | loop6: device node name blacklisted 279s 65.176752 | loop7: device node name blacklisted 279s 65.176885 | dm-0: device node name blacklisted 279s 65.178078 | multipath-tools v0.9.4 (12/19, 2022) 279s 65.178118 | libdevmapper version 1.02.185 279s 65.178276 | kernel device mapper v4.48.0 279s 65.178309 | DM multipath kernel driver v1.14.0 279s 65.178441 | sdb: size = 204800 279s 65.178468 | sdb: vendor = IET 279s 65.178471 | sdb: product = VIRTUAL-DISK 279s 65.178474 | sdb: rev = 0001 279s 65.179267 | sdb: h:b:t:l = 1:0:0:1 279s 65.179430 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 279s 65.179478 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 279s 65.179482 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 279s 65.179499 | sdb: serial = beaf11 279s 65.179840 | sdb: tur state = up 279s 65.179866 | sdb: uid = 360000000000000000e00000000010001 (udev) 279s 65.179869 | sdb: detect_prio = yes (setting: multipath internal) 279s 65.179873 | sdb: prio = const (setting: multipath internal) 279s 65.179875 | sdb: prio args = "" (setting: multipath internal) 279s 65.179878 | sdb: const prio = 1 279s 65.179917 | sdc: size = 204800 279s 65.179942 | sdc: vendor = IET 279s 65.179945 | sdc: product = VIRTUAL-DISK 279s 65.179947 | sdc: rev = 0001 279s 65.180741 | sdc: h:b:t:l = 2:0:0:1 279s 65.180933 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 279s 65.180979 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 279s 65.180983 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 279s 65.180997 | sdc: serial = beaf11 279s 65.181270 | sdc: tur state = up 279s 65.181299 | sdc: uid = 360000000000000000e00000000010001 (udev) 279s 65.181306 | sdc: detect_prio = yes (setting: multipath internal) 279s 65.181312 | sdc: prio = const (setting: multipath internal) 279s 65.181318 | sdc: prio args = "" (setting: multipath internal) 279s 65.181324 | sdc: const prio = 1 279s 65.181389 | sdd: size = 204800 279s 65.181413 | sdd: vendor = IET 279s 65.181416 | sdd: product = VIRTUAL-DISK 279s 65.181419 | sdd: rev = 0001 279s 65.182126 | sdd: h:b:t:l = 3:0:0:1 279s 65.182284 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 279s 65.182330 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 279s 65.182333 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 279s 65.182348 | sdd: serial = beaf11 279s 65.182620 | sdd: tur state = up 279s 65.182646 | sdd: uid = 360000000000000000e00000000010001 (udev) 279s 65.182649 | sdd: detect_prio = yes (setting: multipath internal) 279s 65.182652 | sdd: prio = const (setting: multipath internal) 279s 65.182655 | sdd: prio args = "" (setting: multipath internal) 279s 65.182657 | sdd: const prio = 1 279s 65.182688 | sde: size = 204800 279s 65.182693 | sde: vendor = IET 279s 65.182696 | sde: product = VIRTUAL-DISK 279s 65.182699 | sde: rev = 0001 279s 65.183428 | sde: h:b:t:l = 4:0:0:1 279s 65.183595 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 279s 65.183643 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 279s 65.183646 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 279s 65.183660 | sde: serial = beaf11 279s 65.183931 | sde: tur state = up 279s 65.183959 | sde: uid = 360000000000000000e00000000010001 (udev) 279s 65.183966 | sde: detect_prio = yes (setting: multipath internal) 279s 65.183969 | sde: prio = const (setting: multipath internal) 279s 65.183971 | sde: prio args = "" (setting: multipath internal) 279s 65.183974 | sde: const prio = 1 279s 65.185065 | unloading tur checker 279s 65.185146 | unloading const prioritizer 279s ===== paths list ===== 279s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 279s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 279s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 279s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 279s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 279s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 279s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 279s size=100M features='0' hwhandler='0' wp=rw 279s |-+- policy='service-time 0' prio=1 status=active 279s | `- 1:0:0:1 sdb 8:16 active ready running 279s |-+- policy='service-time 0' prio=1 status=enabled 279s | `- 2:0:0:1 sdc 8:32 active ready running 279s |-+- policy='service-time 0' prio=1 status=enabled 279s | `- 3:0:0:1 sdd 8:48 active ready running 279s `-+- policy='service-time 0' prio=1 status=enabled 279s `- 4:0:0:1 sde 8:64 active ready running 279s 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 279s Test WWN should now point to DM 279s ../../dm-0 279s Creating filesystem with 25600 4k blocks and 25600 inodes 279s 279s Allocating group tables: 0/1 done 279s Writing inode tables: 0/1 done 279s Creating journal (1024 blocks): done 279s Writing superblocks and filesystem accounting information: 0/1 + dmsetup table 279s + echo Test WWN should now point to DM 279s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 279s + grep dm 279s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 279s mke2fs 1.47.0 (5-Feb-2023) 279s done 279s 279s + udevadm settle 279s + sleep 3s 282s + mkdir -p /mnt/tgtmpathtest 282s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 282s + cat 282s + cat 282s + fio --max-jobs=4 /tmp/autopkgtest.HYxDxd/tgtbasedmpaths-artifacts/path-change-prep.fio 282s 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 282s fio-3.36 282s Starting 1 thread 282s write-phase: Laying out IO file (1 file / 17592186044415MiB) 283s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 283s 283s write-phase: (groupid=0, jobs=1): err= 0: pid=6564: Wed May 1 07:10:10 2024 283s write: IOPS=1843, BW=115MiB/s (121MB/s)(87.6MiB/761msec); 0 zone resets 283s clat (usec): min=300, max=4034, avg=522.10, stdev=227.82 283s lat (usec): min=322, max=4049, avg=540.69, stdev=228.43 283s clat percentiles (usec): 283s | 1.00th=[ 334], 5.00th=[ 363], 10.00th=[ 383], 20.00th=[ 412], 283s | 30.00th=[ 433], 40.00th=[ 449], 50.00th=[ 474], 60.00th=[ 519], 283s | 70.00th=[ 545], 80.00th=[ 578], 90.00th=[ 660], 95.00th=[ 742], 283s | 99.00th=[ 1434], 99.50th=[ 1942], 99.90th=[ 3654], 99.95th=[ 4047], 283s | 99.99th=[ 4047] 283s bw ( KiB/s): min=110371, max=110371, per=93.61%, avg=110371.00, stdev= 0.00, samples=1 283s iops : min= 1724, max= 1724, avg=1724.00, stdev= 0.00, samples=1 283s lat (usec) : 500=56.09%, 750=39.27%, 1000=2.28% 283s lat (msec) : 2=1.85%, 4=0.36%, 10=0.07% 283s cpu : usr=6.32%, sys=5.13%, ctx=1404, majf=0, minf=0 283s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 283s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 283s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 283s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 283s latency : target=0, window=0, percentile=100.00%, depth=1 283s 283s Run status group 0 (all jobs): 283s WRITE: bw=115MiB/s (121MB/s), 115MiB/s-115MiB/s (121MB/s-121MB/s), io=87.6MiB (91.9MB), run=761-761msec 283s 283s Disk stats (read/write): 283s dm-0: ios=1/1147, sectors=8/159352, merge=0/0, ticks=0/640, in_queue=664, util=87.14%, aggrios=0/351, aggsectors=2/48082, aggrmerge=0/0, aggrticks=6/178, aggrin_queue=184, aggrutil=87.02% 283s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 283s sdb: ios=2/1405, sectors=8/192328, merge=0/0, ticks=25/712, in_queue=736, util=87.02% 283s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 283s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 283s + echo Starting the path changes in background 283s + date +Pre FIO %H:%M:%S.%N 283s Starting the path changes in background 283s Pre FIO 07:10:10.455450533 283s + fio --max-jobs=4 /tmp/autopkgtest.HYxDxd/tgtbasedmpaths-artifacts/path-change-check.fio 283s 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 283s fio-3.36 283s Starting 1 thread 463s 463s verify-phase: (groupid=0, jobs=1): err= 0: pid=6571: Wed May 1 07:13:10 2024 463s read: IOPS=2925, BW=183MiB/s (192MB/s)(32.1GiB/180001msec) 463s clat (usec): min=97, max=52040, avg=316.02, stdev=190.62 463s lat (usec): min=97, max=52040, avg=316.13, stdev=190.62 463s clat percentiles (usec): 463s | 1.00th=[ 151], 5.00th=[ 174], 10.00th=[ 204], 20.00th=[ 223], 463s | 30.00th=[ 243], 40.00th=[ 269], 50.00th=[ 310], 60.00th=[ 334], 463s | 70.00th=[ 363], 80.00th=[ 400], 90.00th=[ 445], 95.00th=[ 478], 463s | 99.00th=[ 586], 99.50th=[ 725], 99.90th=[ 1418], 99.95th=[ 1827], 463s | 99.99th=[ 3425] 463s bw ( KiB/s): min=120689, max=337792, per=100.00%, avg=187328.55, stdev=39734.19, samples=359 463s iops : min= 1885, max= 5278, avg=2926.97, stdev=620.86, samples=359 463s lat (usec) : 100=0.01%, 250=33.87%, 500=63.07%, 750=2.59%, 1000=0.20% 463s lat (msec) : 2=0.22%, 4=0.04%, 10=0.01%, 20=0.01%, 50=0.01% 463s lat (msec) : 100=0.01% 463s cpu : usr=8.86%, sys=7.17%, ctx=526721, majf=0, minf=1 463s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 463s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 463s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 463s issued rwts: total=526637,0,0,0 short=0,0,0,0 dropped=0,0,0,0 463s latency : target=0, window=0, percentile=100.00%, depth=1 463s 463s Run status group 0 (all jobs): 463s READ: bw=183MiB/s (192MB/s), 183MiB/s-183MiB/s (192MB/s-192MB/s), io=32.1GiB (34.5GB), run=180001-180001msec 463s 463s Disk stats (read/write): 463s dm-0: ios=526667/7, sectors=67360952/120, merge=0/8, ticks=170356/24, in_queue=170401, util=100.00%, aggrios=37809/1, aggsectors=4835054/30, aggrmerge=0/0, aggrticks=10833/1, aggrin_queue=10834, aggrutil=99.13% 463s sdd: ios=30007/0, sectors=3838208/0, merge=0/0, ticks=8780/0, in_queue=8780, util=33.40% 463s sdb: ios=27801/7, sectors=3555968/120, merge=0/0, ticks=8475/4, in_queue=8480, util=99.13% 463s sde: ios=67070/0, sectors=8578816/0, merge=0/0, ticks=17191/0, in_queue=17191, util=39.93% 463s sdc: ios=26360/0, sectors=3367224/0, merge=0/0, ticks=8888/0, in_queue=8888, util=50.07% 463s + date +Post FIO %H:%M:%S.%N 463s Post FIO 07:13:10.672329206 463s FIO verify test with changing paths - OK 463s Report log of background activity 463s + echo FIO verify test with changing paths - OK 463s + echo Report log of background activity 463s + cat /tmp/autopkgtest.HYxDxd/tgtbasedmpaths-artifacts/test-background.log 463s + iscsiadm --mode session 463s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s + sleep 10s 463s + date +MP report (expect 4) %H:%M:%S.%N 463s MP report (expect 4) 07:10:20.463089685 463s + multipath -ll 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s |-+- policy='service-time 0' prio=1 status=active 463s | `- 1:0:0:1 sdb 8:16 active ready running 463s |-+- policy='service-time 0' prio=1 status=enabled 463s | `- 2:0:0:1 sdc 8:32 active ready running 463s |-+- policy='service-time 0' prio=1 status=enabled 463s | `- 3:0:0:1 sdd 8:48 active ready running 463s `-+- policy='service-time 0' prio=1 status=enabled 463s `- 4:0:0:1 sde 8:64 active ready running 463s + date +UN-plug path 1 %H:%M:%S.%N 463s UN-plug path 1 07:10:20.494920284 463s + iscsiadm --mode session -r 1 -u 463s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session 463s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s + sleep 10s 463s + date +MP report (expect 3) %H:%M:%S.%N 463s MP report (expect 3) 07:10:30.619935582 463s + multipath -ll 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s |-+- policy='service-time 0' prio=1 status=active 463s | `- 2:0:0:1 sdc 8:32 active ready running 463s |-+- policy='service-time 0' prio=1 status=enabled 463s | `- 3:0:0:1 sdd 8:48 active ready running 463s `-+- policy='service-time 0' prio=1 status=enabled 463s `- 4:0:0:1 sde 8:64 active ready running 463s + date +UN-plug path 2 %H:%M:%S.%N 463s UN-plug path 2 07:10:30.644555765 463s + iscsiadm --mode session -r 2 -u 463s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session 463s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s + sleep 10s 463s + date +MP report (expect 2) %H:%M:%S.%N 463s MP report (expect 2) 07:10:40.750395923 463s + multipath -ll 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s |-+- policy='service-time 0' prio=1 status=active 463s | `- 3:0:0:1 sdd 8:48 active ready running 463s `-+- policy='service-time 0' prio=1 status=enabled 463s `- 4:0:0:1 sde 8:64 active ready running 463s + date +UN-plug path 3 %H:%M:%S.%N 463s UN-plug path 3 07:10:40.773693248 463s + iscsiadm --mode session -r 3 -u 463s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session 463s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s + sleep 10s 463s + date +MP report (expect 1) %H:%M:%S.%N 463s MP report (expect 1) 07:10:50.863056031 463s + multipath -ll 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s `-+- policy='service-time 0' prio=1 status=active 463s `- 4:0:0:1 sde 8:64 active ready running 463s + date +Add paths 5/6/7/8 %H:%M:%S.%N 463s Add paths 5/6/7/8 07:10:50.880257862 463s + iscsiadm --mode session -r 4 --op new 463s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 463s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session -r 4 --op new 463s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 463s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session -r 4 --op new 463s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 463s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session -r 4 --op new 463s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 463s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session 463s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s + sleep 10s 463s + date +MP report (expect 5) %H:%M:%S.%N 463s MP report (expect 5) 07:11:01.023745844 463s + multipath -ll 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s |-+- policy='service-time 0' prio=1 status=active 463s | `- 4:0:0:1 sde 8:64 active ready running 463s |-+- policy='service-time 0' prio=1 status=enabled 463s | `- 1:0:0:1 sdb 8:16 active ready running 463s |-+- policy='service-time 0' prio=1 status=enabled 463s | `- 2:0:0:1 sdc 8:32 active ready running 463s |-+- policy='service-time 0' prio=1 status=enabled 463s | `- 3:0:0:1 sdd 8:48 active ready running 463s `-+- policy='service-time 0' prio=1 status=enabled 463s `- 5:0:0:1 sdf 8:80 active ready running 463s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 463s UN-plug multiple paths 4/7/8 07:11:01.056682611 463s + iscsiadm --mode session -r 4 -u 463s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session -r 7 -u 463s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session -r 8 -u 463s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + iscsiadm --mode session 463s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 463s + sleep 10s 463s + date +Restart multipath daemon %H:%M:%S.%N 463s Restart multipath daemon 07:11:11.364728536 463s + systemctl restart multipathd 463s + sleep 10s 463s + date +Final background report (expect 2) %H:%M:%S.%N 463s Final background report (expect 2) 07:11:21.445218838 463s + multipath -ll 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s |-+- policy='service-time 0' prio=1 status=active 463s | `- 1:0:0:1 sdb 8:16 active ready running 463s `-+- policy='service-time 0' prio=1 status=enabled 463s `- 2:0:0:1 sdc 8:32 active ready running 463s Final stats 463s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s iSCSI SNMP: 463s txdata_octets: 18004052 463s rxdata_octets: 24558341316 463s noptx_pdus: 0 463s scsicmd_pdus: 374817 463s tmfcmd_pdus: 0 463s login_pdus: 0 463s text_pdus: 0 463s dataout_pdus: 0 463s logout_pdus: 0 463s snack_pdus: 0 463s noprx_pdus: 0 463s scsirsp_pdus: 374817 463s tmfrsp_pdus: 0 463s textrsp_pdus: 0 463s datain_pdus: 374783 463s logoutrsp_pdus: 0 463s r2t_pdus: 0 463s async_pdus: 0 463s rjt_pdus: 0 463s digest_err: 0 463s timeout_err: 0 463s iSCSI Extended: 463s tx_sendpage_failures: 0 463s rx_discontiguous_hdr: 0 463s eh_abort_cnt: 0 463s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s iSCSI SNMP: 463s txdata_octets: 6548 463s rxdata_octets: 1515012 463s noptx_pdus: 0 463s scsicmd_pdus: 106 463s tmfcmd_pdus: 0 463s login_pdus: 0 463s text_pdus: 0 463s dataout_pdus: 0 463s logout_pdus: 0 463s snack_pdus: 0 463s noprx_pdus: 0 463s scsirsp_pdus: 106 463s tmfrsp_pdus: 0 463s textrsp_pdus: 0 463s datain_pdus: 83 463s logoutrsp_pdus: 0 463s r2t_pdus: 0 463s async_pdus: 0 463s rjt_pdus: 0 463s digest_err: 0 463s timeout_err:+ sync 463s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 463s + echo Final stats 463s + iscsiadm --mode session --stats 463s + journalctl --no-pager -u multipathd 463s + echo Check final path status 463s + multipath -ll 463s + multipath -ll 463s + grep --count status= 463s 0 463s iSCSI Extended: 463s tx_sendpage_failures: 0 463s rx_discontiguous_hdr: 0 463s eh_abort_cnt: 0 463s Apr 30 08:14:24 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 463s Apr 30 08:14:24 ubuntu multipathd[323]: multipathd v0.9.4: start up 463s Apr 30 08:14:24 ubuntu multipathd[323]: reconfigure: setting up paths and maps 463s Apr 30 08:14:24 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 463s Apr 30 08:15:57 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 multipathd[323]: multipathd: shut down 463s Apr 30 08:15:57 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 463s Apr 30 08:15:57 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 systemd[1]: multipathd.service: Deactivated successfully. 463s Apr 30 08:15:57 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 463s Apr 30 08:15:57 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 463s Apr 30 08:15:57 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 multipathd[12459]: multipathd v0.9.4: start up 463s Apr 30 08:15:57 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 multipathd[12459]: reconfigure: setting up paths and maps 463s Apr 30 08:17:06 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 multipathd[12459]: multipathd: shut down 463s Apr 30 08:17:06 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 463s Apr 30 08:17:06 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 systemd[1]: multipathd.service: Deactivated successfully. 463s Apr 30 08:17:06 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 463s -- Boot 56ff1a7d620c43deb43ced78aaf3dde6 -- 463s Apr 30 08:17:35 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 multipathd[258]: multipathd v0.9.4: start up 463s Apr 30 08:17:35 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 multipathd[258]: reconfigure: setting up paths and maps 463s Apr 30 08:17:35 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 463s Apr 30 08:17:52 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 multipathd[258]: multipathd: shut down 463s Apr 30 08:17:52 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 463s Apr 30 08:17:52 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 systemd[1]: multipathd.service: Deactivated successfully. 463s Apr 30 08:17:52 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 463s -- Boot 3759d9e56803493d815e7d6da156f193 -- 463s May 01 07:09:04 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 463s May 01 07:09:04 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 multipathd[325]: multipathd v0.9.4: start up 463s May 01 07:09:04 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 multipathd[325]: reconfigure: setting up paths and maps 463s May 01 07:09:04 auto-syncubuntu-noble-daily-ppc64el-server-20240423-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 463s May 01 07:10:01 autopkgtest multipathd[325]: mpatha: addmap [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 463s May 01 07:10:01 autopkgtest multipathd[325]: sdc [8:32]: path added to devmap mpatha 463s May 01 07:10:01 autopkgtest multipathd[325]: mpatha: performing delayed actions 463s May 01 07:10:01 autopkgtest multipathd[325]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 463s May 01 07:10:20 autopkgtest multipathd[325]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 463s May 01 07:10:20 autopkgtest multipathd[325]: check_removed_paths: sdb: freeing path in removed state 463s May 01 07:10:20 autopkgtest multipathd[325]: 8:16: path removed from map mpatha 463s May 01 07:10:30 autopkgtest multipathd[325]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 463s May 01 07:10:30 autopkgtest multipathd[325]: check_removed_paths: sdc: freeing path in removed state 463s May 01 07:10:30 autopkgtest multipathd[325]: 8:32: path removed from map mpatha 463s May 01 07:10:40 autopkgtest multipathd[325]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 463s May 01 07:10:40 autopkgtest multipathd[325]: check_removed_paths: sdd: freeing path in removed state 463s May 01 07:10:40 autopkgtest multipathd[325]: 8:48: path removed from map mpatha 463s May 01 07:10:50 autopkgtest multipathd[325]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1] 463s May 01 07:10:51 autopkgtest multipathd[325]: sdb [8:16]: path added to devmap mpatha 463s May 01 07:10:51 autopkgtest multipathd[325]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 463s May 01 07:10:51 autopkgtest multipathd[325]: sdc [8:32]: path added to devmap mpatha 463s May 01 07:10:51 autopkgtest multipathd[325]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 463s May 01 07:10:51 autopkgtest multipathd[325]: sdd [8:48]: path added to devmap mpatha 463s May 01 07:10:51 autopkgtest multipathd[325]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:80 1] 463s May 01 07:10:51 autopkgtest multipathd[325]: sdf [8:80]: path added to devmap mpatha 463s May 01 07:11:01 autopkgtest multipathd[325]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:80 1] 463s May 01 07:11:01 autopkgtest multipathd[325]: check_removed_paths: sde: freeing path in removed state 463s May 01 07:11:01 autopkgtest multipathd[325]: 8:64: path removed from map mpatha 463s May 01 07:11:01 autopkgtest multipathd[325]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:80 1] 463s May 01 07:11:01 autopkgtest multipathd[325]: check_removed_paths: sdd: freeing path in removed state 463s May 01 07:11:01 autopkgtest multipathd[325]: 8:48: path removed from map mpatha 463s May 01 07:11:01 autopkgtest multipathd[325]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 463s May 01 07:11:01 autopkgtest multipathd[325]: check_removed_paths: sdf: freeing path in removed state 463s May 01 07:11:01 autopkgtest multipathd[325]: 8:80: path removed from map mpatha 463s May 01 07:11:11 autopkgtest multipathd[325]: multipathd: shut down 463s May 01 07:11:11 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 463s May 01 07:11:11 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 463s May 01 07:11:11 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 463s May 01 07:11:11 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 463s May 01 07:11:11 autopkgtest multipathd[6926]: multipathd v0.9.4: start up 463s May 01 07:11:11 autopkgtest multipathd[6926]: reconfigure: setting up paths and maps 463s May 01 07:11:11 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 463s Check final path status 463s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 463s size=100M features='0' hwhandler='0' wp=rw 463s |-+- policy='service-time 0' prio=1 status=active 463s | `- 1:0:0:1 sdb 8:16 active ready running 463s `-+- policy='service-time 0' prio=1 status=enabled 463s `- 2:0:0:1 sdc 8:32 active ready running 463s + diskc=2 463s + multipath -ll 463s + grep --count status=active 463s + diska=1 463s + multipath -ll 463s + grep --count status=enabled 463s + diske=1 463s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 463s + echo OK 463s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 463s OK 463s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 463s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 463s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 464s autopkgtest [07:13:11]: test tgtbasedmpaths: -----------------------] 464s autopkgtest [07:13:11]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 464s tgtbasedmpaths PASS 465s autopkgtest [07:13:12]: @@@@@@@@@@@@@@@@@@@@ summary 465s kpartx-file-loopback PASS 465s tgtbasedmpaths PASS 475s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240501-070527-juju-7f2275-prod-proposed-migration-environment-3-7aef95ce-a0e9-48ab-b301-0750d182fbbb from image adt/ubuntu-oracular-ppc64el-server-20240430.img (UUID f18b7fb3-2610-4941-b1f3-c4898d22f9cf)... 475s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240501-070527-juju-7f2275-prod-proposed-migration-environment-3-7aef95ce-a0e9-48ab-b301-0750d182fbbb from image adt/ubuntu-oracular-ppc64el-server-20240430.img (UUID f18b7fb3-2610-4941-b1f3-c4898d22f9cf)...