0s autopkgtest [05:35:57]: starting date and time: 2024-06-27 05:35:57+0000 0s autopkgtest [05:35:57]: git checkout: 85adf9a1 setup-testbed: prevent /tmp from getting a tmpfs mount 0s autopkgtest [05:35:57]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.athb92ur/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:open-iscsi --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=open-iscsi/2.1.10-1ubuntu1 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos02-ppc64el-4.secgroup --name adt-oracular-ppc64el-multipath-tools-20240627-053557-juju-7f2275-prod-proposed-migration-environment-2-1b1ce8e9-5375-4d32-92b1-a128a99031f5 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,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/ 117s autopkgtest [05:37:54]: testbed dpkg architecture: ppc64el 118s autopkgtest [05:37:55]: testbed apt version: 2.9.5 118s autopkgtest [05:37:55]: @@@@@@@@@@@@@@@@@@@@ test bed setup 119s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 119s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [47.6 kB] 119s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [383 kB] 119s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 119s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7052 B] 119s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [65.5 kB] 119s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1860 B] 119s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [350 kB] 119s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1768 B] 120s Fetched 970 kB in 1s (981 kB/s) 120s Reading package lists... 122s Reading package lists... 123s Building dependency tree... 123s Reading state information... 123s Calculating upgrade... 123s The following packages will be upgraded: 123s lsb-release tmux 123s 2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 123s Need to get 607 kB of archives. 123s After this operation, 0 B of additional disk space will be used. 123s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsb-release all 12.1-1 [5910 B] 123s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el tmux ppc64el 3.4-7 [601 kB] 124s Fetched 607 kB in 1s (1079 kB/s) 124s (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 ... 72687 files and directories currently installed.) 124s Preparing to unpack .../lsb-release_12.1-1_all.deb ... 124s Unpacking lsb-release (12.1-1) over (12.0-2) ... 124s Preparing to unpack .../tmux_3.4-7_ppc64el.deb ... 124s Unpacking tmux (3.4-7) over (3.4-6) ... 124s Setting up lsb-release (12.1-1) ... 124s Setting up tmux (3.4-7) ... 124s Processing triggers for debianutils (5.19) ... 125s Processing triggers for man-db (2.12.1-2) ... 125s Reading package lists... 126s Building dependency tree... 126s Reading state information... 126s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 127s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 127s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 127s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 127s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 128s Reading package lists... 128s Reading package lists... 129s Building dependency tree... 129s Reading state information... 129s Calculating upgrade... 129s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 130s Reading package lists... 130s Building dependency tree... 130s Reading state information... 130s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 133s autopkgtest [05:38:10]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 133s autopkgtest [05:38:10]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 137s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 137s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 137s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 137s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 137s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 137s gpgv: issuer "steve.langasek@ubuntu.com" 137s gpgv: Can't check signature: No public key 137s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 137s autopkgtest [05:38:14]: testing package multipath-tools version 0.9.4-5ubuntu8 138s autopkgtest [05:38:15]: build not needed 139s autopkgtest [05:38:16]: test kpartx-file-loopback: preparing testbed 140s Reading package lists... 140s Building dependency tree... 140s Reading state information... 140s Starting pkgProblemResolver with broken count: 0 140s Starting 2 pkgProblemResolver with broken count: 0 140s Done 141s The following additional packages will be installed: 141s liburing2 qemu-utils 141s Recommended packages: 141s qemu-block-extra 141s The following NEW packages will be installed: 141s autopkgtest-satdep liburing2 qemu-utils 141s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 141s Need to get 2330 kB/2331 kB of archives. 141s After this operation, 15.4 MB of additional disk space will be used. 141s Get:1 /tmp/autopkgtest.blvRQo/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 141s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 141s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 142s Fetched 2330 kB in 1s (3100 kB/s) 142s Selecting previously unselected package liburing2:ppc64el. 142s (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 ... 72687 files and directories currently installed.) 142s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 142s Unpacking liburing2:ppc64el (2.6-1) ... 142s Selecting previously unselected package qemu-utils. 142s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 142s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 142s Selecting previously unselected package autopkgtest-satdep. 142s Preparing to unpack .../1-autopkgtest-satdep.deb ... 142s Unpacking autopkgtest-satdep (0) ... 142s Setting up liburing2:ppc64el (2.6-1) ... 142s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 142s Setting up autopkgtest-satdep (0) ... 142s Processing triggers for man-db (2.12.1-2) ... 144s Processing triggers for libc-bin (2.39-0ubuntu9) ... 147s (Reading database ... 72707 files and directories currently installed.) 147s Removing autopkgtest-satdep (0) ... 147s autopkgtest [05:38:24]: test kpartx-file-loopback: [----------------------- 148s Formatting 'foo.img', fmt=raw size=20971520 149s Creating new GPT entries in memory. 149s Warning: The kernel is still using the old partition table. 149s The new table will be used at the next reboot or after you 149s run partprobe(8) or kpartx(8) 149s The operation has completed successfully. 149s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 149s standard_filename: OK 149s del devmap : loop0p1 149s No devices found 149s standard_filename_cleanup: OK 149s Formatting 'fou du FaFa.img', fmt=raw size=20971520 150s Creating new GPT entries in memory. 150s Warning: The kernel is still using the old partition table. 150s The new table will be used at the next reboot or after you 150s run partprobe(8) or kpartx(8) 150s The operation has completed successfully. 150s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 150s filename_with_spaces: OK 150s del devmap : loop0p1 150s No devices found 150s filename_with_spaces_cleanup: OK 150s autopkgtest [05:38:27]: test kpartx-file-loopback: -----------------------] 151s autopkgtest [05:38:28]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 151s kpartx-file-loopback PASS 151s autopkgtest [05:38:28]: test tgtbasedmpaths: preparing testbed 291s autopkgtest [05:40:48]: testbed dpkg architecture: ppc64el 291s autopkgtest [05:40:48]: testbed apt version: 2.9.5 291s autopkgtest [05:40:48]: @@@@@@@@@@@@@@@@@@@@ test bed setup 292s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 293s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 293s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [47.6 kB] 293s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7052 B] 293s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [383 kB] 293s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [65.5 kB] 293s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1860 B] 293s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [350 kB] 293s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1768 B] 293s Fetched 970 kB in 1s (961 kB/s) 293s Reading package lists... 296s Reading package lists... 296s Building dependency tree... 296s Reading state information... 297s Calculating upgrade... 297s The following packages will be upgraded: 297s lsb-release tmux 297s 2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 297s Need to get 607 kB of archives. 297s After this operation, 0 B of additional disk space will be used. 297s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsb-release all 12.1-1 [5910 B] 297s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el tmux ppc64el 3.4-7 [601 kB] 299s Fetched 607 kB in 1s (734 kB/s) 299s (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 ... 72687 files and directories currently installed.) 299s Preparing to unpack .../lsb-release_12.1-1_all.deb ... 299s Unpacking lsb-release (12.1-1) over (12.0-2) ... 299s Preparing to unpack .../tmux_3.4-7_ppc64el.deb ... 299s Unpacking tmux (3.4-7) over (3.4-6) ... 299s Setting up lsb-release (12.1-1) ... 299s Setting up tmux (3.4-7) ... 299s Processing triggers for debianutils (5.19) ... 299s Processing triggers for man-db (2.12.1-2) ... 300s Reading package lists... 300s Building dependency tree... 300s Reading state information... 301s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 302s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 302s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 302s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 302s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 303s Reading package lists... 303s Reading package lists... 304s Building dependency tree... 304s Reading state information... 304s Calculating upgrade... 305s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 305s Reading package lists... 305s Building dependency tree... 305s Reading state information... 305s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 310s Reading package lists... 310s Building dependency tree... 310s Reading state information... 311s Starting pkgProblemResolver with broken count: 0 311s Starting 2 pkgProblemResolver with broken count: 0 311s Done 311s The following additional packages will be installed: 311s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 311s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 311s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 311s librdmacm1t64 lsscsi open-iscsi tgt 311s Suggested packages: 311s fio-examples gnuplot tgt-glusterfs tgt-rbd 311s Recommended packages: 311s finalrd 311s The following NEW packages will be installed: 311s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 311s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 311s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 311s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 311s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 311s Need to get 10.7 MB/10.7 MB of archives. 311s After this operation, 49.0 MB of additional disk space will be used. 311s Get:1 /tmp/autopkgtest.blvRQo/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 311s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 311s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 312s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 312s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 312s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 312s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 312s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4ubuntu1 [21.5 kB] 312s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4ubuntu1 [311 kB] 312s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4ubuntu1 [46.5 kB] 312s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4ubuntu1 [99.2 kB] 312s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.1-1 [97.4 kB] 312s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 312s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 312s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 312s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 313s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 313s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 314s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 314s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 314s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 314s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 315s Preconfiguring packages ... 315s Fetched 10.7 MB in 3s (3172 kB/s) 315s Selecting previously unselected package libopeniscsiusr. 315s (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 ... 72687 files and directories currently installed.) 315s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 315s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 315s Selecting previously unselected package libisns0t64:ppc64el. 315s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 315s Unpacking libisns0t64:ppc64el (0.101-1) ... 315s Selecting previously unselected package open-iscsi. 315s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 315s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 315s Selecting previously unselected package librdmacm1t64:ppc64el. 315s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 315s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 315s Selecting previously unselected package libconfig-general-perl. 315s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 315s Unpacking libconfig-general-perl (2.65-2) ... 316s Selecting previously unselected package tgt. 316s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 316s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 316s Selecting previously unselected package libgfxdr0:ppc64el. 316s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_ppc64el.deb ... 316s Unpacking libgfxdr0:ppc64el (11.1-4ubuntu1) ... 316s Selecting previously unselected package libglusterfs0:ppc64el. 316s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_ppc64el.deb ... 316s Unpacking libglusterfs0:ppc64el (11.1-4ubuntu1) ... 316s Selecting previously unselected package libgfrpc0:ppc64el. 316s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_ppc64el.deb ... 316s Unpacking libgfrpc0:ppc64el (11.1-4ubuntu1) ... 316s Selecting previously unselected package libgfapi0:ppc64el. 316s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_ppc64el.deb ... 316s Unpacking libgfapi0:ppc64el (11.1-4ubuntu1) ... 316s Selecting previously unselected package libnbd0. 316s Preparing to unpack .../10-libnbd0_1.20.1-1_ppc64el.deb ... 316s Unpacking libnbd0 (1.20.1-1) ... 316s Selecting previously unselected package libdaxctl1:ppc64el. 316s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 316s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 316s Selecting previously unselected package libndctl6:ppc64el. 316s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 316s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 316s Selecting previously unselected package libpmem1:ppc64el. 316s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 316s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 316s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 316s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 316s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 316s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 316s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 316s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 316s Selecting previously unselected package librados2. 316s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 316s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 316s Selecting previously unselected package libpmemobj1:ppc64el. 316s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 316s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 316s Selecting previously unselected package librbd1. 316s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 316s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 316s Selecting previously unselected package fio. 316s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 316s Unpacking fio (3.37-1) ... 316s Selecting previously unselected package lsscsi. 316s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 316s Unpacking lsscsi (0.32-1build1) ... 317s Selecting previously unselected package autopkgtest-satdep. 317s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 317s Unpacking autopkgtest-satdep (0) ... 317s Setting up libconfig-general-perl (2.65-2) ... 317s Setting up libisns0t64:ppc64el (0.101-1) ... 317s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 317s Setting up libnbd0 (1.20.1-1) ... 317s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 317s Setting up libglusterfs0:ppc64el (11.1-4ubuntu1) ... 317s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 317s Setting up lsscsi (0.32-1build1) ... 317s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 317s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 317s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 317s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 317s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 318s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 318s Setting up libgfxdr0:ppc64el (11.1-4ubuntu1) ... 318s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 318s Setting up open-iscsi (2.1.10-1ubuntu1) ... 319s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 320s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 320s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 321s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 321s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 321s Setting up libgfrpc0:ppc64el (11.1-4ubuntu1) ... 321s Setting up libgfapi0:ppc64el (11.1-4ubuntu1) ... 321s Setting up fio (3.37-1) ... 321s Setting up autopkgtest-satdep (0) ... 321s Processing triggers for man-db (2.12.1-2) ... 323s Processing triggers for initramfs-tools (0.142ubuntu28) ... 323s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 323s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 336s Processing triggers for libc-bin (2.39-0ubuntu9) ... 339s (Reading database ... 72928 files and directories currently installed.) 339s Removing autopkgtest-satdep (0) ... 341s autopkgtest [05:41:38]: test tgtbasedmpaths: [----------------------- 341s + targetname=iqn.2016-11.foo.com:target.iscsi 341s + pwd 341s + cwd=/tmp/autopkgtest.blvRQo/build.cSP/src 341s + testdir=/mnt/tgtmpathtest 341s + localhost=127.0.0.1 341s + portal=127.0.0.1:3260 341s + maxpaths=4 341s + backfn=backingfile 341s + expectwwid=60000000000000000e00000000010001 341s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 341s + bglog=/tmp/autopkgtest.blvRQo/tgtbasedmpaths-artifacts/test-background.log 341s + fioprep=/tmp/autopkgtest.blvRQo/tgtbasedmpaths-artifacts/path-change-prep.fio 341s + fiovrfy=/tmp/autopkgtest.blvRQo/tgtbasedmpaths-artifacts/path-change-check.fio 341s + service tgt restart 342s + truncate --size 100M backingfile 342s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 342s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 342s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.blvRQo/build.cSP/src/backingfile 342s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 342s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 342s + echo login #1 342s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 342s login #1 342s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 342s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 342s + seq 2 4 342s extra login #2 342s + echo extra login #2 342s + iscsiadm --mode session -r 1 --op new 342s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 342s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 342s extra login #3 342s + echo extra login #3 342s + iscsiadm --mode session -r 1 --op new 342s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 342s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 342s extra login #4 342s + echo extra login #4 342s + iscsiadm --mode session -r 1 --op new 342s + udevadm settle 342s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 342s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 343s + sleep 5 348s Status after initial setup 348s + echo Status after initial setup 348s + tgtadm --lld iscsi --mode target --op show 348s + tgtadm --lld iscsi --op show --mode conn --tid 1 348s Target 1: iqn.2016-11.foo.com:target.iscsi 348s System information: 348s Driver: iscsi 348s State: ready 348s I_T nexus information: 348s I_T nexus: 1 348s Initiator: iqn.2004-10.com.ubuntu:01:c71683d93248 alias: autopkgtest 348s Connection: 0 348s IP Address: 127.0.0.1 348s I_T nexus: 2 348s Initiator: iqn.2004-10.com.ubuntu:01:c71683d93248 alias: autopkgtest 348s Connection: 0 348s IP Address: 127.0.0.1 348s I_T nexus: 3 348s Initiator: iqn.2004-10.com.ubuntu:01:c71683d93248 alias: autopkgtest 348s Connection: 0 348s IP Address: 127.0.0.1 348s I_T nexus: 4 348s Initiator: iqn.2004-10.com.ubuntu:01:c71683d93248 alias: autopkgtest 348s Connection: 0 348s IP Address: 127.0.0.1 348s LUN information: 348s LUN: 0 348s Type: controller 348s SCSI ID: IET 00010000 348s SCSI SN: beaf10 348s Size: 0 MB, Block size: 1 348s Online: Yes 348s Removable media: No 348s Prevent removal: No 348s Readonly: No 348s SWP: No 348s Thin-provisioning: No 348s Backing store type: null 348s Backing store path: None 348s Backing store flags: 348s LUN: 1 348s Type: disk 348s SCSI ID: IET 00010001 348s SCSI SN: beaf11 348s Size: 105 MB, Block size: 512 348s Online: Yes 348s Removable media: No 348s Prevent removal: No 348s Readonly: No 348s SWP: No 348s Thin-provisioning: No 348s Backing store type: rdwr 348s Backing store path: /tmp/autopkgtest.blvRQo/build.cSP/src/backingfile 348s Backing store flags: 348s Account information: 348s ACL information: 348s ALL 348s Session: 4 348s Connection: 0 348s Initiator: iqn.2004-10.com.ubuntu:01:c71683d93248 348s IP Address: 127.0.0.1 348s Session: 3 348s Connection: 0 348s Initiator: iqn.2004-10.com.ubuntu:01:c71683d93248 348s IP Address: 127.0.0.1 348s Session: 2 348s Connection: 0 348s Initiator: iqn.2004-10.com.ubuntu:01:c71683d93248 348s IP Address: 127.0.0.1 348s Session: 1 348s Connection: 0 348s Initiator: iqn.2004-10.com.ubuntu:01:c71683d93248 348s IP Address: 127.0.0.1 348s + iscsiadm --mode session -P 1 348s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 348s Current Portal: 127.0.0.1:3260,1 348s Persistent Portal: 127.0.0.1:3260,1 348s ********** 348s Interface: 348s ********** 348s Iface Name: default 348s Iface Transport: tcp 348s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:c71683d93248 348s Iface IPaddress: 127.0.0.1 348s Iface HWaddress: default 348s Iface Netdev: default 348s SID: 1 348s iSCSI Connection State: LOGGED IN 348s iSCSI Session State: LOGGED_IN 348s Internal iscsid Session State: NO CHANGE 348s 348s ********** 348s Interface: 348s ********** 348s Iface Name: default 348s Iface Transport: tcp 348s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:c71683d93248 348s Iface IPaddress: 127.0.0.1 348s Iface HWaddress: default 348s Iface Netdev: default 348s SID: 2 348s iSCSI Connection State: LOGGED IN 348s iSCSI Session State: LOGGED_IN 348s Internal iscsid Session State: NO CHANGE 348s 348s ********** 348s Interface: 348s ********** 348s Iface Name: default 348s Iface Transport: tcp 348s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:c71683d93248 348s Iface IPaddress: 127.0.0.1 348s Iface HWaddress: default 348s Iface Netdev: default 348s SID: 3 348s iSCSI Connection State: LOGGED IN 348s iSCSI Session State: LOGGED_IN 348s Internal iscsid Session State: NO CHANGE 348s 348s ********** 348s Interface: 348s ********** 348s Iface Name: default 348s Iface Transport: tcp 348s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:c71683d93248 348s Iface IPaddress: 127.0.0.1 348s Iface HWaddress: default 348s Iface Netdev: default 348s SID: 4 348s iSCSI Connection State: LOGGED IN 348s iSCSI Session State: LOGGED_IN 348s Internal iscsid Session State: NO CHANGE 348s + lsscsi -liv 348s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 348s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 348s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 348s 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] 348s [1:0:0:0] storage IET Controller 0001 - - 348s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 348s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 348s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 348s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 348s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 348s [2:0:0:0] storage IET Controller 0001 - - 348s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 348s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 348s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 348s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 348s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 348s [3:0:0:0] storage IET Controller 0001 - - 348s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 348s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 348s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 348s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 348s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 348s [4:0:0:0] storage IET Controller 0001 - - 348s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 348s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 348s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 348s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 348s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 348s NVMe module may not be loaded 348s + multipath -v3 -ll 348s 92.369594 | set open fds limit to 1048576/1048576 348s 92.372304 | loading /lib/multipath/libchecktur.so checker 348s 92.372448 | checker tur: message table size = 3 348s 92.372457 | loading /lib/multipath/libprioconst.so prioritizer 348s 92.372587 | _init_foreign: foreign library "nvme" is not enabled 348s 92.384917 | sda: size = 167772160 348s 92.392614 | sda: vendor = QEMU 348s 92.392643 | sda: product = QEMU HARDDISK 348s 92.392670 | sda: rev = 2.5+ 348s 92.393389 | sda: h:b:t:l = 0:0:0:0 348s 92.393765 | sda: tgt_node_name = 348s 92.393770 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 348s 92.393773 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 348s 92.393970 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 348s 92.393974 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 348s 92.393988 | __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 348s 92.393993 | failed to read sysfs vpd pg80: No such file or directory 348s 92.394509 | sda: fail to get serial 348s 92.396195 | sda: detect_checker = yes (setting: multipath internal) 348s 92.396629 | sda: path_checker = tur (setting: multipath internal) 348s 92.396794 | sda: checker timeout = 30 s (setting: kernel sysfs) 348s 92.397021 | sda: tur state = up 348s 92.397494 | sdb: size = 204800 348s 92.397682 | sdb: vendor = IET 348s 92.397708 | sdb: product = VIRTUAL-DISK 348s 92.397733 | sdb: rev = 0001 348s 92.398472 | sdb: h:b:t:l = 1:0:0:1 348s 92.398882 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 348s 92.398887 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 348s 92.398890 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 348s 92.399098 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 348s 92.399103 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 348s 92.399131 | sdb: serial = beaf11 348s 92.399134 | sdb: detect_checker = yes (setting: multipath internal) 348s 92.416993 | sdb: path_checker = tur (setting: multipath internal) 348s 92.417021 | sdb: checker timeout = 30 s (setting: kernel sysfs) 348s 92.417359 | sdb: tur state = up 348s 92.417572 | sdc: size = 204800 348s 92.417732 | sdc: vendor = IET 348s 92.417757 | sdc: product = VIRTUAL-DISK 348s 92.417781 | sdc: rev = 0001 348s 92.418577 | sdc: h:b:t:l = 2:0:0:1 348s 92.419018 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 348s 92.419022 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 348s 92.419025 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 348s 92.419222 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 348s 92.419226 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 348s 92.419244 | sdc: serial = beaf11 348s 92.419248 | sdc: detect_checker = yes (setting: multipath internal) 348s 92.420525 | sdc: path_checker = tur (setting: multipath internal) 348s 92.420552 | sdc: checker timeout = 30 s (setting: kernel sysfs) 348s 92.421128 | sdc: tur state = up 348s 92.421327 | sdd: size = 204800 348s 92.421486 | sdd: vendor = IET 348s 92.421512 | sdd: product = VIRTUAL-DISK 348s 92.421570 | sdd: rev = 0001 348s 92.422492 | sdd: h:b:t:l = 3:0:0:1 348s 92.422904 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 348s 92.422908 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 348s 92.422911 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 348s 92.423112 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 348s 92.423115 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 348s 92.423133 | sdd: serial = beaf11 348s 92.423136 | sdd: detect_checker = yes (setting: multipath internal) 348s 92.427917 | sdd: path_checker = tur (setting: multipath internal) 348s 92.431504 | sdd: checker timeout = 30 s (setting: kernel sysfs) 348s 92.432232 | sdd: tur state = up 348s 92.432535 | sde: size = 204800 348s 92.432694 | sde: vendor = IET 348s 92.432719 | sde: product = VIRTUAL-DISK 348s 92.432744 | sde: rev = 0001 348s 92.434015 | sde: h:b:t:l = 4:0:0:1 348s 92.434472 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 348s 92.434477 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 348s 92.434479 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 348s 92.434685 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 348s 92.434689 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 348s 92.434706 | sde: serial = beaf11 348s 92.434709 | sde: detect_checker = yes (setting: multipath internal) 348s 92.435314 | sde: path_checker = tur (setting: multipath internal) 348s 92.435353 | sde: checker timeout = 30 s (setting: kernel sysfs) 348s 92.436487 | sde: tur state = up 348s 92.436669 | loop0: device node name blacklisted 348s 92.436772 | loop1: device node name blacklisted 348s 92.436868 | loop2: device node name blacklisted 348s 92.436964 | loop3: device node name blacklisted 348s 92.437058 | loop4: device node name blacklisted 348s 92.437150 | loop5: device node name blacklisted 348s 92.437245 | loop6: device node name blacklisted 348s 92.437339 | loop7: device node name blacklisted 348s 92.437445 | dm-0: device node name blacklisted 348s 92.439009 | multipath-tools v0.9.4 (12/19, 2022) 348s 92.439768 | libdevmapper version 1.02.185 348s 92.439939 | kernel device mapper v4.48.0 348s 92.439955 | DM multipath kernel driver v1.14.0 348s 92.440455 | sdc: size = 204800 348s 92.440703 | sdc: vendor = IET 348s 92.440706 | sdc: product = VIRTUAL-DISK 348s 92.440709 | sdc: rev = 0001 348s 92.441453 | sdc: h:b:t:l = 2:0:0:1 348s 92.441622 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 348s 92.441651 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 348s 92.441655 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 348s 92.441672 | sdc: serial = beaf11 348s 92.445396 | sdc: tur state = up 348s 92.445466 | sdc: uid = 360000000000000000e00000000010001 (udev) 348s 92.445472 | sdc: detect_prio = yes (setting: multipath internal) 348s 92.445478 | sdc: prio = const (setting: multipath internal) 348s 92.445481 | sdc: prio args = "" (setting: multipath internal) 348s 92.445485 | sdc: const prio = 1 348s 92.445598 | sdb: size = 204800 348s 92.445607 | sdb: vendor = IET 348s 92.445611 | sdb: product = VIRTUAL-DISK 348s 92.445614 | sdb: rev = 0001 348s 92.446402 | sdb: h:b:t:l = 1:0:0:1 348s 92.446612 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 348s 92.446648 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 348s 92.446653 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 348s 92.446674 | sdb: serial = beaf11 348s 92.458526 | sdb: tur state = up 348s 92.458585 | sdb: uid = 360000000000000000e00000000010001 (udev) 348s 92.458591 | sdb: detect_prio = yes (setting: multipath internal) 348s 92.458596 | sdb: prio = const (setting: multipath internal) 348s 92.458599 | sdb: prio args = "" (setting: multipath internal) 348s 92.458602 | sdb: const prio = 1 348s 92.458682 | sdd: size = 204800 348s 92.458691 | sdd: vendor = IET 348s 92.458695 | sdd: product = VIRTUAL-DISK 348s 92.458698 | sdd: rev = 0001 348s 92.459491 | sdd: h:b:t:l = 3:0:0:1 348s 92.459696 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 348s 92.459731 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 348s 92.459735 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 348s 92.459755 | sdd: serial = beaf11 348s 92.462687 | sdd: tur state = up 348s 92.462804 | sdd: uid = 360000000000000000e00000000010001 (udev) 348s 92.462810 | sdd: detect_prio = yes (setting: multipath internal) 348s 92.462816 | sdd: prio = const (setting: multipath internal) 348s 92.462819 | sdd: prio args = "" (setting: multipath internal) 348s 92.462822 | sdd: const prio = 1 348s 92.462895 | sde: size = 204800 348s 92.462928 | sde: vendor = IET 348s 92.462932 | sde: product = VIRTUAL-DISK 348s 92.462935 | sde: rev = 0001 348s 92.464092 | sde: h:b:t:l = 4:0:0:1 348s 92.464513 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 348s 92.464575 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 348s 92.464580 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 348s 92.464601 | sde: serial = beaf11 348s 92.465120 | sde: tur state = up 348s 92.465152 | sde: uid = 360000000000000000e00000000010001 (udev) 348s 92.465157 | sde: detect_prio = yes (setting: multipath internal) 348s 92.465162 | sde: prio = const (setting: multipath internal) 348s 92.465165 | sde: prio args = "" (setting: multipath internal) 348s 92.465169 | sde: const prio = 1 348s 92.466375 | unloading tur checker 348s ===== paths list ===== 348s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 348s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 348s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 348s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 348s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 348s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 348s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 348s size=100M features='0' hwhandler='0' wp=rw 348s |-+- policy='service-time 0' prio=1 status=active 348s | `- 2:0:0:1 sdc 8:32 active ready running 348s |-+- policy='service-time 0' prio=1 status=enabled 348s | `- 1:0:0:1 sdb 8:16 active ready running 348s |-+- policy='service-time 0' prio=1 status=enabled 348s | `- 3:0:0:1 sdd 8:48 active ready running 348s `-+- policy='service-time 0' prio=1 status=enabled 348s `- 4:0:0:1 sde 8:64 active ready running 348s mpatha: 0 204800 multipath 0 0 4 1 service-time 0 1 2 8:32 1 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:64 1 1 348s Test WWN should now point to DM 348s ../../dm-0 348s 92.466690 | unloading const prioritizer 348s + dmsetup table 348s + echo Test WWN should now point to DM 348s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 348s + grep dm 348s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 348s mke2fs 1.47.1 (20-May-2024) 348s Creating filesystem with 25600 4k blocks and 25600 inodes 348s 348s Allocating group tables: 0/1 done 348s Writing inode tables: 0/1 done 348s Creating journal (1024 blocks): done 348s Writing superblocks and filesystem accounting information: 0/1 done 348s 348s + udevadm settle 348s + sleep 3s 351s + mkdir -p /mnt/tgtmpathtest 351s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 351s + cat 351s + cat 351s + fio --max-jobs=4 /tmp/autopkgtest.blvRQo/tgtbasedmpaths-artifacts/path-change-prep.fio 351s 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 351s fio-3.37 351s Starting 1 thread 351s write-phase: Laying out IO file (1 file / 17592186044415MiB) 352s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91750400, buflen=65536 353s 353s write-phase: (groupid=0, jobs=1): err= 0: pid=6473: Thu Jun 27 05:41:50 2024 353s write: IOPS=1131, BW=70.7MiB/s (74.1MB/s)(87.5MiB/1238msec); 0 zone resets 353s clat (usec): min=295, max=33092, avg=860.63, stdev=1389.61 353s lat (usec): min=309, max=33117, avg=881.26, stdev=1389.51 353s clat percentiles (usec): 353s | 1.00th=[ 367], 5.00th=[ 437], 10.00th=[ 529], 20.00th=[ 586], 353s | 30.00th=[ 627], 40.00th=[ 660], 50.00th=[ 676], 60.00th=[ 701], 353s | 70.00th=[ 725], 80.00th=[ 791], 90.00th=[ 906], 95.00th=[ 1237], 353s | 99.00th=[ 6783], 99.50th=[10814], 99.90th=[15533], 99.95th=[33162], 353s | 99.99th=[33162] 353s bw ( KiB/s): min=62464, max=75008, per=94.97%, avg=68736.00, stdev=8869.95, samples=2 353s iops : min= 976, max= 1172, avg=1074.00, stdev=138.59, samples=2 353s lat (usec) : 500=7.28%, 750=66.95%, 1000=18.06% 353s lat (msec) : 2=5.14%, 4=0.93%, 10=1.00%, 20=0.50%, 50=0.07% 353s cpu : usr=5.09%, sys=6.14%, ctx=1403, majf=0, minf=0 353s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 353s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 353s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 353s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 353s latency : target=0, window=0, percentile=100.00%, depth=1 353s 353s Run status group 0 (all jobs): 353s WRITE: bw=70.7MiB/s (74.1MB/s), 70.7MiB/s-70.7MiB/s (74.1MB/s-74.1MB/s), io=87.5MiB (91.8MB), run=1238-1238msec 353s 353s Disk stats (read/write): 353s dm-0: ios=1/1213, sectors=8/155392, merge=0/0, ticks=8/1039, in_queue=1048, util=91.24%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=2/283, aggrin_queue=285, aggrutil=90.95% 353s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 353s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 353s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 353s sdc: ios=1/1402, sectors=8/179280, merge=0/0, ticks=9/1134, in_queue=1143, util=90.95% 353s + echo Starting the path changes in background 353s + date +Pre FIO %H:%M:%S.%N 353s Starting the path changes in background 353s Pre FIO 05:41:50.068046741 353s + fio --max-jobs=4 /tmp/autopkgtest.blvRQo/tgtbasedmpaths-artifacts/path-change-check.fio 353s 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 353s fio-3.37 353s Starting 1 thread 533s 533s verify-phase: (groupid=0, jobs=1): err= 0: pid=6484: Thu Jun 27 05:44:50 2024 533s read: IOPS=1740, BW=109MiB/s (114MB/s)(19.1GiB/180001msec) 533s clat (usec): min=110, max=54927, avg=547.18, stdev=1014.06 533s lat (usec): min=110, max=54928, avg=547.36, stdev=1014.19 533s clat percentiles (usec): 533s | 1.00th=[ 204], 5.00th=[ 249], 10.00th=[ 281], 20.00th=[ 343], 533s | 30.00th=[ 379], 40.00th=[ 404], 50.00th=[ 433], 60.00th=[ 453], 533s | 70.00th=[ 478], 80.00th=[ 519], 90.00th=[ 611], 95.00th=[ 742], 533s | 99.00th=[ 4293], 99.50th=[ 7308], 99.90th=[14877], 99.95th=[18744], 533s | 99.99th=[28443] 533s bw ( KiB/s): min=28134, max=231680, per=100.00%, avg=111514.38, stdev=21805.33, samples=359 533s iops : min= 439, max= 3620, avg=1742.36, stdev=340.73, samples=359 533s lat (usec) : 250=5.33%, 500=71.35%, 750=18.42%, 1000=1.80% 533s lat (msec) : 2=1.27%, 4=0.76%, 10=0.82%, 20=0.21%, 50=0.04% 533s lat (msec) : 100=0.01% 533s cpu : usr=5.18%, sys=9.20%, ctx=313353, majf=0, minf=1 533s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 533s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 533s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 533s issued rwts: total=313302,0,0,0 short=0,0,0,0 dropped=0,0,0,0 533s latency : target=0, window=0, percentile=100.00%, depth=1 533s 533s Run status group 0 (all jobs): 533s READ: bw=109MiB/s (114MB/s), 109MiB/s-109MiB/s (114MB/s-114MB/s), io=19.1GiB (20.5GB), run=180001-180001msec 533s 533s Disk stats (read/write): 533s dm-0: ios=313327/11, sectors=40077112/12944, merge=33/10, ticks=177926/295, in_queue=178319, util=97.07%, aggrios=23248/2, aggsectors=2973550/3236, aggrmerge=0/0, aggrticks=11595/49, aggrin_queue=11644, aggrutil=99.38% 533s sdd: ios=18196/0, sectors=2327424/0, merge=0/0, ticks=9326/0, in_queue=9326, util=33.46% 533s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 533s sde: ios=36054/0, sectors=4611584/0, merge=0/0, ticks=18621/0, in_queue=18621, util=39.94% 533s sdc: ios=38743/10, sectors=4955192/12944, merge=0/0, ticks=18434/197, in_queue=18630, util=99.38% 533s + date +Post FIO %H:%M:%S.%N 533s + echo FIO verify test with changing paths - OK 533s + echo Report log of background activity 533s + cat /tmp/autopkgtest.blvRQo/tgtbasedmpaths-artifacts/test-background.log 533s Post FIO 05:44:50.436932231 533s FIO verify test with changing paths - OK 533s Report log of background activity 533s + iscsiadm --mode session 533s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s + sleep 10s 533s + date +MP report (expect 4) %H:%M:%S.%N 533s MP report (expect 4) 05:42:00.075891610 533s + multipath -ll 533s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 533s size=100M features='0' hwhandler='0' wp=rw 533s |-+- policy='service-time 0' prio=1 status=active 533s | `- 2:0:0:1 sdc 8:32 active ready running 533s |-+- policy='service-time 0' prio=1 status=enabled 533s | `- 1:0:0:1 sdb 8:16 active ready running 533s |-+- policy='service-time 0' prio=1 status=enabled 533s | `- 3:0:0:1 sdd 8:48 active ready running 533s `-+- policy='service-time 0' prio=1 status=enabled 533s `- 4:0:0:1 sde 8:64 active ready running 533s + date +UN-plug path 1 %H:%M:%S.%N 533s UN-plug path 1 05:42:00.156987305 533s + iscsiadm --mode session -r 1 -u 533s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 533s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 533s + iscsiadm --mode session 533s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s + sleep 10s 533s + date +MP report (expect 3) %H:%M:%S.%N 533s MP report (expect 3) 05:42:10.364877846 533s + multipath -ll 533s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 533s size=100M features='0' hwhandler='0' wp=rw 533s |-+- policy='service-time 0' prio=1 status=active 533s | `- 2:0:0:1 sdc 8:32 active ready running 533s |-+- policy='service-time 0' prio=1 status=enabled 533s | `- 3:0:0:1 sdd 8:48 active ready running 533s `-+- policy='service-time 0' prio=1 status=enabled 533s `- 4:0:0:1 sde 8:64 active ready running 533s + date +UN-plug path 2 %H:%M:%S.%N 533s UN-plug path 2 05:42:10.421449273 533s + iscsiadm --mode session -r 2 -u 533s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 533s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 533s + iscsiadm --mode session 533s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s + sleep 10s 533s + date +MP report (expect 2) %H:%M:%S.%N 533s MP report (expect 2) 05:42:20.653286763 533s + multipath -ll 533s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 533s size=100M features='0' hwhandler='0' wp=rw 533s |-+- policy='service-time 0' prio=1 status=active 533s | `- 3:0:0:1 sdd 8:48 active ready running 533s `-+- policy='service-time 0' prio=1 status=enabled 533s `- 4:0:0:1 sde 8:64 active ready running 533s + date +UN-plug path 3 %H:%M:%S.%N 533s UN-plug path 3 05:42:20.700469090 533s + iscsiadm --mode session -r 3 -u 533s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 533s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 533s + iscsiadm --mode session 533s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s + sleep 10s 533s + date +MP report (expect 1) %H:%M:%S.%N 533s MP report (expect 1) 05:42:30.851124270 533s + multipath -ll 533s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 533s size=100M features='0' hwhandler='0' wp=rw 533s `-+- policy='service-time 0' prio=1 status=active 533s `- 4:0:0:1 sde 8:64 active ready running 533s + date +Add paths 5/6/7/8 %H:%M:%S.%N 533s Add paths 5/6/7/8 05:42:30.884129722 533s + iscsiadm --mode session -r 4 --op new 533s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 533s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 533s + iscsiadm --mode session -r 4 --op new 533s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 533s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 533s + iscsiadm --mode session -r 4 --op new 533s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 533s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 533s + iscsiadm --mode session -r 4 --op new 533s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 533s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 533s + iscsiadm --mode session 533s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s + sleep 10s 533s + date +MP report (expect 5) %H:%M:%S.%N 533s MP report (expect 5) 05:42:41.300018456 533s + multipath -ll 533s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 533s size=100M features='0' hwhandler='0' wp=rw 533s |-+- policy='service-time 0' prio=1 status=active 533s | `- 4:0:0:1 sde 8:64 active ready running 533s |-+- policy='service-time 0' prio=1 status=enabled 533s | `- 1:0:0:1 sdb 8:16 active ready running 533s |-+- policy='service-time 0' prio=1 status=enabled 533s | `- 2:0:0:1 sdc 8:32 active ready running 533s |-+- policy='service-time 0' prio=1 status=enabled 533s | `- 3:0:0:1 sdd 8:48 active ready running 533s `-+- policy='service-time 0' prio=1 status=enabled 533s `- 5:0:0:1 sdf 8:80 active ready running 533s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 533s UN-plug multiple paths 4/7/8 05:42:41.387033073 533s + iscsiadm --mode session -r 4 -u 533s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 533s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 533s + iscsiadm --mode session -r 7 -u 533s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 533s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 533s + iscsiadm --mode session -r 8 -u 533s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 533s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 533s + iscsiadm --mode session 533s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 533s + sleep 10s 533s + date +Restart multipath daemon %H:%M:%S.%N 533s Restart multipath daemon 05:42:51.894095443 533s + systemctl restart multipathd 533s + sleep 10s 533s + date +Final background report (expect 2) %H:%M:%S.%N 533s Final background report (expect 2) 05:43:02.007190775 533s + multipath -ll 533s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 533s size=100M features='0' hwhandler='0' wp=rw 533s |-+- policy='service-time 0' prio=1 status=active 533s | `- 1:0:0:1 sdb 8:16 active ready running 533s `-+- policy='service-time 0' prio=1 status=enabled 533s `- 2:0:0:1 sdc 8:32 active ready running 533s Final stats 533s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 533s iSCSI SNMP: 533s txdata_octets: 10589064 533s rxdata_octets: 14434199540 533s noptx_pdus: 0 533s scsicmd_pdus: 220338 533s tmfcmd_pdus: 0 533s login_pdus: 0 533s text_pdus: 0 533s dataout_pdus: 0 533s logout_pdus: 0 533s snack_pdus: 0 533s noprx_pdus: 0 533s scsirsp_pdus: 220338 533s tmfrsp_pdus: 0 533s textrsp_pdus: 0 533s datain_pdus: 220304 533s logoutrsp_pdus: 0 533s r2t_pdus: 0 533s async_pdus: 0 533s rjt_pdus: 0 533s digest_err: 0 533s timeout_err: 0 533s iSCSI Extended: 533s tx_sendpage_failures: 0 533s rx_discontiguous_hdr: 0 533s eh_abort_cnt: 0 533s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 533s iSCSI SNMP: 533s txdata_octets: 6504 533s rxdata_octets: 1514964 533s noptx_pdus: 0 533s scsicmd_pdus: 104 533s tmfcmd_pdus: 0 533s login_pdus: 0 533s text_pdus: 0 533s dataout_pdus: 0 533s logout_pdus: 0 533s snack_pdus: 0 533s noprx_pdus: 0 533s scsirsp_pdus: 104 533s tmfrsp_pdus: 0 533s textrsp_pdus: 0 533s datain_pdus: 83 533s logoutrsp_pdus: 0 533s r2t_pdus: 0 533s async_pdus: 0 533s rjt_pdus: 0 533s digest_err: 0 533s timeout_err: 0 533s iSCSI Extended: 533s tx_sendpage_failures: 0 533s rx_discontiguous_hdr: 0 533s eh_abort_cnt: 0 533s + sync 533s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 533s + echo Final stats 533s + iscsiadm --mode session --stats 533s + journalctl --no-pager -u multipathd 533s Jun 26 17:02:06 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 533s Jun 26 17:02:07 ubuntu multipathd[328]: multipathd v0.9.4: start up 533s Jun 26 17:02:07 ubuntu multipathd[328]: reconfigure: setting up paths and maps 533s Jun 26 17:02:07 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 533s Jun 26 17:04:57 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 multipathd[328]: multipathd: shut down 533s Jun 26 17:04:57 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 533s Jun 26 17:04:57 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: multipathd.service: Deactivated successfully. 533s Jun 26 17:04:57 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 533s -- Boot e274a553cc3948e5989f5a91ccb15473 -- 533s Jun 26 17:05:26 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 multipathd[262]: multipathd v0.9.4: start up 533s Jun 26 17:05:26 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 multipathd[262]: reconfigure: setting up paths and maps 533s Jun 26 17:05:26 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 533s Jun 26 17:05:48 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 multipathd[262]: multipathd: shut down 533s Jun 26 17:05:48 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 533s Jun 26 17:05:48 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: multipathd.service: Deactivated successfully. 533s Jun 26 17:05:48 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 533s -- Boot 98b855b969804cd5bd4cb56cfd103b13 -- 533s Jun 27 05:40:16 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 533s Jun 27 05:40:16 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 multipathd[328]: multipathd v0.9.4: start up 533s Jun 27 05:40:16 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 multipathd[328]: reconfigure: setting up paths and maps 533s Jun 27 05:40:16 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 533s Jun 27 05:41:39 autopkgtest multipathd[328]: mpatha: addmap [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:16 1] 533s Jun 27 05:41:39 autopkgtest multipathd[328]: sdb [8:16]: path added to devmap mpatha 533s Jun 27 05:41:40 autopkgtest multipathd[328]: mpatha: performing delayed actions 533s Jun 27 05:41:40 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 533s Jun 27 05:42:00 autopkgtest multipathd[328]: 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] 533s Jun 27 05:42:00 autopkgtest multipathd[328]: check_removed_paths: sdb: freeing path in removed state 533s Jun 27 05:42:00 autopkgtest multipathd[328]: 8:16: path removed from map mpatha 533s Jun 27 05:42:10 autopkgtest multipathd[328]: sdc: mark as failed 533s Jun 27 05:42:10 autopkgtest multipathd[328]: mpatha: remaining active paths: 2 533s Jun 27 05:42:10 autopkgtest multipathd[328]: 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] 533s Jun 27 05:42:10 autopkgtest multipathd[328]: check_removed_paths: sdc: freeing path in removed state 533s Jun 27 05:42:10 autopkgtest multipathd[328]: 8:32: path removed from map mpatha 533s Jun 27 05:42:20 autopkgtest multipathd[328]: sdd: mark as failed 533s Jun 27 05:42:20 autopkgtest multipathd[328]: mpatha: remaining active paths: 1 533s Jun 27 05:42:20 autopkgtest multipathd[+ echo Check final path status 533s + multipath -ll 533s 328]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 533s Jun 27 05:42:20 autopkgtest multipathd[328]: check_removed_paths: sdd: freeing path in removed state 533s Jun 27 05:42:20 autopkgtest multipathd[328]: 8:48: path removed from map mpatha 533s Jun 27 05:42:31 autopkgtest multipathd[328]: 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] 533s Jun 27 05:42:31 autopkgtest multipathd[328]: sdb [8:16]: path added to devmap mpatha 533s Jun 27 05:42:31 autopkgtest multipathd[328]: 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] 533s Jun 27 05:42:31 autopkgtest multipathd[328]: sdc [8:32]: path added to devmap mpatha 533s Jun 27 05:42:31 autopkgtest multipathd[328]: 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] 533s Jun 27 05:42:31 autopkgtest multipathd[328]: sdd [8:48]: path added to devmap mpatha 533s Jun 27 05:42:31 autopkgtest multipathd[328]: 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] 533s Jun 27 05:42:31 autopkgtest multipathd[328]: sdf [8:80]: path added to devmap mpatha 533s Jun 27 05:42:41 autopkgtest multipathd[328]: sde: mark as failed 533s Jun 27 05:42:41 autopkgtest multipathd[328]: mpatha: remaining active paths: 4 533s Jun 27 05:42:41 autopkgtest multipathd[328]: 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] 533s Jun 27 05:42:41 autopkgtest multipathd[328]: check_removed_paths: sde: freeing path in removed state 533s Jun 27 05:42:41 autopkgtest multipathd[328]: 8:64: path removed from map mpatha 533s Jun 27 05:42:41 autopkgtest multipathd[328]: 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] 533s Jun 27 05:42:41 autopkgtest multipathd[328]: check_removed_paths: sdd: freeing path in removed state 533s Jun 27 05:42:41 autopkgtest multipathd[328]: 8:48: path removed from map mpatha 533s Jun 27 05:42:41 autopkgtest multipathd[328]: 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] 533s Jun 27 05:42:41 autopkgtest multipathd[328]: check_removed_paths: sdf: freeing path in removed state 533s Jun 27 05:42:41 autopkgtest multipathd[328]: 8:80: path removed from map mpatha 533s Jun 27 05:42:51 autopkgtest multipathd[328]: multipathd: shut down 533s Jun 27 05:42:51 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 533s Jun 27 05:42:51 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 533s Jun 27 05:42:51 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 533s Jun 27 05:42:51 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 533s Jun 27 05:42:51 autopkgtest multipathd[6872]: multipathd v0.9.4: start up 533s Jun 27 05:42:51 autopkgtest multipathd[6872]: reconfigure: setting up paths and maps 533s Jun 27 05:42:51 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 533s Check final path status 533s + multipath -ll 533s + grep --count status= 533s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 533s size=100M features='0' hwhandler='0' wp=rw 533s |-+- policy='service-time 0' prio=1 status=active 533s | `- 1:0:0:1 sdb 8:16 active ready running 533s `-+- policy='service-time 0' prio=1 status=enabled 533s `- 2:0:0:1 sdc 8:32 active ready running 533s + diskc=2 533s + multipath -ll 533s + grep --count status=active 533s + diska=1 533s + grep --count status=enabled 533s + multipath -ll 533s + diske=1 533s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 533s + echo OK 533s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 533s OK 533s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 533s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 533s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 533s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 533s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 534s autopkgtest [05:44:51]: test tgtbasedmpaths: -----------------------] 534s autopkgtest [05:44:51]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 534s tgtbasedmpaths PASS 535s autopkgtest [05:44:52]: @@@@@@@@@@@@@@@@@@@@ summary 535s kpartx-file-loopback PASS 535s tgtbasedmpaths PASS 547s nova [W] Using flock in scalingstack-bos02-ppc64el 547s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240627-053557-juju-7f2275-prod-proposed-migration-environment-2-1b1ce8e9-5375-4d32-92b1-a128a99031f5 from image adt/ubuntu-oracular-ppc64el-server-20240626.img (UUID fa594093-eedb-4d89-8a75-780351d83ba9)... 547s nova [W] Using flock in scalingstack-bos02-ppc64el 547s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240627-053557-juju-7f2275-prod-proposed-migration-environment-2-1b1ce8e9-5375-4d32-92b1-a128a99031f5 from image adt/ubuntu-oracular-ppc64el-server-20240626.img (UUID fa594093-eedb-4d89-8a75-780351d83ba9)...