0s autopkgtest [00:56:15]: starting date and time: 2024-06-07 00:56:15+0000 0s autopkgtest [00:56:15]: git checkout: 433ed4cb Merge branch 'skia/nova_flock' into 'ubuntu/5.34+prod' 0s autopkgtest [00:56:15]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.25ft4epa/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:liburcu --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=liburcu/0.14.0-4 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos02-ppc64el-23.secgroup --name adt-oracular-ppc64el-multipath-tools-20240607-005614-juju-7f2275-prod-proposed-migration-environment-3-8c086abd-438e-47bc-be75-88e47f665525 --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/ 147s autopkgtest [00:58:42]: testbed dpkg architecture: ppc64el 147s autopkgtest [00:58:42]: testbed apt version: 2.9.3 147s autopkgtest [00:58:42]: @@@@@@@@@@@@@@@@@@@@ test bed setup 148s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 148s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [45.6 kB] 148s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [4792 B] 148s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [364 kB] 148s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2416 B] 148s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [98.1 kB] 148s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [360 kB] 148s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1388 B] 148s Fetched 987 kB in 1s (1153 kB/s) 149s Reading package lists... 151s Reading package lists... 151s Building dependency tree... 151s Reading state information... 151s Calculating upgrade... 151s The following packages will be upgraded: 151s cron cron-daemon-common libaom3 liburcu8t64 152s 4 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 152s Need to get 3189 kB of archives. 152s After this operation, 3072 B of additional disk space will be used. 152s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el cron ppc64el 3.0pl1-189ubuntu1 [94.0 kB] 152s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el cron-daemon-common all 3.0pl1-189ubuntu1 [14.2 kB] 152s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libaom3 ppc64el 3.8.2-3 [3008 kB] 152s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el liburcu8t64 ppc64el 0.14.0-4 [72.9 kB] 153s Fetched 3189 kB in 1s (3944 kB/s) 153s (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 ... 72602 files and directories currently installed.) 153s Preparing to unpack .../cron_3.0pl1-189ubuntu1_ppc64el.deb ... 153s Unpacking cron (3.0pl1-189ubuntu1) over (3.0pl1-184ubuntu2) ... 153s Preparing to unpack .../cron-daemon-common_3.0pl1-189ubuntu1_all.deb ... 153s Unpacking cron-daemon-common (3.0pl1-189ubuntu1) over (3.0pl1-184ubuntu2) ... 153s Preparing to unpack .../libaom3_3.8.2-3_ppc64el.deb ... 153s Unpacking libaom3:ppc64el (3.8.2-3) over (3.8.2-2ubuntu1) ... 153s Preparing to unpack .../liburcu8t64_0.14.0-4_ppc64el.deb ... 153s Unpacking liburcu8t64:ppc64el (0.14.0-4) over (0.14.0-3.1build1) ... 153s Setting up liburcu8t64:ppc64el (0.14.0-4) ... 153s Setting up libaom3:ppc64el (3.8.2-3) ... 153s Setting up cron-daemon-common (3.0pl1-189ubuntu1) ... 153s Setting up cron (3.0pl1-189ubuntu1) ... 154s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 154s Processing triggers for man-db (2.12.1-1) ... 155s Reading package lists... 155s Building dependency tree... 155s Reading state information... 156s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 156s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 156s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 156s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 156s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 157s Reading package lists... 157s Reading package lists... 158s Building dependency tree... 158s Reading state information... 158s Calculating upgrade... 158s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 158s Reading package lists... 158s Building dependency tree... 158s Reading state information... 158s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 158s autopkgtest [00:58:53]: rebooting testbed after setup commands that affected boot 192s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 204s autopkgtest [00:59:39]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 207s autopkgtest [00:59:42]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 211s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 211s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 211s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 211s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 211s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 211s gpgv: issuer "steve.langasek@ubuntu.com" 211s gpgv: Can't check signature: No public key 211s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 211s autopkgtest [00:59:46]: testing package multipath-tools version 0.9.4-5ubuntu8 211s autopkgtest [00:59:46]: build not needed 212s autopkgtest [00:59:47]: test kpartx-file-loopback: preparing testbed 213s Reading package lists... 213s Building dependency tree... 213s Reading state information... 213s Starting pkgProblemResolver with broken count: 0 213s Starting 2 pkgProblemResolver with broken count: 0 213s Done 214s The following additional packages will be installed: 214s liburing2 qemu-utils 214s Recommended packages: 214s qemu-block-extra 214s The following NEW packages will be installed: 214s autopkgtest-satdep liburing2 qemu-utils 214s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 214s Need to get 2330 kB/2331 kB of archives. 214s After this operation, 15.4 MB of additional disk space will be used. 214s Get:1 /tmp/autopkgtest.ZoqZV9/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 214s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 214s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 215s Fetched 2330 kB in 1s (3304 kB/s) 215s Selecting previously unselected package liburing2:ppc64el. 215s (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 ... 72602 files and directories currently installed.) 215s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 215s Unpacking liburing2:ppc64el (2.6-1) ... 215s Selecting previously unselected package qemu-utils. 215s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 215s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 215s Selecting previously unselected package autopkgtest-satdep. 215s Preparing to unpack .../1-autopkgtest-satdep.deb ... 215s Unpacking autopkgtest-satdep (0) ... 215s Setting up liburing2:ppc64el (2.6-1) ... 215s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 215s Setting up autopkgtest-satdep (0) ... 215s Processing triggers for man-db (2.12.1-1) ... 216s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 219s (Reading database ... 72622 files and directories currently installed.) 219s Removing autopkgtest-satdep (0) ... 219s autopkgtest [00:59:54]: test kpartx-file-loopback: [----------------------- 220s Formatting 'foo.img', fmt=raw size=20971520 221s Creating new GPT entries in memory. 221s Warning: The kernel is still using the old partition table. 221s The new table will be used at the next reboot or after you 221s run partprobe(8) or kpartx(8) 221s The operation has completed successfully. 221s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 221s standard_filename: OK 221s del devmap : loop0p1 221s No devices found 221s standard_filename_cleanup: OK 221s Formatting 'fou du FaFa.img', fmt=raw size=20971520 222s Creating new GPT entries in memory. 222s Warning: The kernel is still using the old partition table. 222s The new table will be used at the next reboot or after you 222s run partprobe(8) or kpartx(8) 222s The operation has completed successfully. 222s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 222s filename_with_spaces: OK 222s del devmap : loop0p1 222s No devices found 222s filename_with_spaces_cleanup: OK 222s autopkgtest [00:59:57]: test kpartx-file-loopback: -----------------------] 223s kpartx-file-loopback PASS 223s autopkgtest [00:59:58]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 223s autopkgtest [00:59:58]: test tgtbasedmpaths: preparing testbed 390s autopkgtest [01:02:45]: testbed dpkg architecture: ppc64el 390s autopkgtest [01:02:45]: testbed apt version: 2.9.3 390s autopkgtest [01:02:45]: @@@@@@@@@@@@@@@@@@@@ test bed setup 391s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 392s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2416 B] 392s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [4792 B] 392s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [45.6 kB] 392s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [364 kB] 392s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [98.1 kB] 392s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [360 kB] 392s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1388 B] 392s Fetched 987 kB in 1s (686 kB/s) 392s Reading package lists... 395s Reading package lists... 395s Building dependency tree... 395s Reading state information... 395s Calculating upgrade... 395s The following packages will be upgraded: 395s cron cron-daemon-common libaom3 liburcu8t64 395s 4 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 395s Need to get 3189 kB of archives. 395s After this operation, 3072 B of additional disk space will be used. 395s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el cron ppc64el 3.0pl1-189ubuntu1 [94.0 kB] 396s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el cron-daemon-common all 3.0pl1-189ubuntu1 [14.2 kB] 396s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libaom3 ppc64el 3.8.2-3 [3008 kB] 397s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el liburcu8t64 ppc64el 0.14.0-4 [72.9 kB] 397s Fetched 3189 kB in 2s (1806 kB/s) 397s (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 ... 72602 files and directories currently installed.) 397s Preparing to unpack .../cron_3.0pl1-189ubuntu1_ppc64el.deb ... 397s Unpacking cron (3.0pl1-189ubuntu1) over (3.0pl1-184ubuntu2) ... 397s Preparing to unpack .../cron-daemon-common_3.0pl1-189ubuntu1_all.deb ... 397s Unpacking cron-daemon-common (3.0pl1-189ubuntu1) over (3.0pl1-184ubuntu2) ... 397s Preparing to unpack .../libaom3_3.8.2-3_ppc64el.deb ... 397s Unpacking libaom3:ppc64el (3.8.2-3) over (3.8.2-2ubuntu1) ... 397s Preparing to unpack .../liburcu8t64_0.14.0-4_ppc64el.deb ... 397s Unpacking liburcu8t64:ppc64el (0.14.0-4) over (0.14.0-3.1build1) ... 397s Setting up liburcu8t64:ppc64el (0.14.0-4) ... 397s Setting up libaom3:ppc64el (3.8.2-3) ... 397s Setting up cron-daemon-common (3.0pl1-189ubuntu1) ... 397s Setting up cron (3.0pl1-189ubuntu1) ... 398s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 398s Processing triggers for man-db (2.12.1-1) ... 399s Reading package lists... 400s Building dependency tree... 400s Reading state information... 400s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 400s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 400s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 400s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 400s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 401s Reading package lists... 401s Reading package lists... 401s Building dependency tree... 401s Reading state information... 402s Calculating upgrade... 402s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 402s Reading package lists... 402s Building dependency tree... 402s Reading state information... 402s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 402s autopkgtest [01:02:57]: rebooting testbed after setup commands that affected boot 436s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 448s Reading package lists... 449s Building dependency tree... 449s Reading state information... 449s Starting pkgProblemResolver with broken count: 0 449s Starting 2 pkgProblemResolver with broken count: 0 449s Done 449s The following additional packages will be installed: 449s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 449s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 449s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 449s librdmacm1t64 lsscsi open-iscsi tgt 449s Suggested packages: 449s fio-examples gnuplot tgt-glusterfs tgt-rbd 449s Recommended packages: 449s finalrd 449s The following NEW packages will be installed: 449s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 449s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 449s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 449s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 449s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 449s Need to get 10.7 MB/10.7 MB of archives. 449s After this operation, 49.1 MB of additional disk space will be used. 449s Get:1 /tmp/autopkgtest.ZoqZV9/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [736 B] 449s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu4 [54.4 kB] 449s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 449s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu4 [389 kB] 450s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 450s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 450s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu6 [256 kB] 450s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4build3 [21.5 kB] 450s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4build3 [311 kB] 450s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4build3 [47.0 kB] 450s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4build3 [100 kB] 450s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.1-1 [97.4 kB] 450s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 450s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 450s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 450s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 450s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 450s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 451s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 451s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 452s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 452s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 452s Preconfiguring packages ... 452s Fetched 10.7 MB in 3s (3834 kB/s) 452s Selecting previously unselected package libopeniscsiusr. 452s (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 ... 72602 files and directories currently installed.) 452s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu4_ppc64el.deb ... 452s Unpacking libopeniscsiusr (2.1.9-3ubuntu4) ... 452s Selecting previously unselected package libisns0t64:ppc64el. 452s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 452s Unpacking libisns0t64:ppc64el (0.101-1) ... 452s Selecting previously unselected package open-iscsi. 452s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu4_ppc64el.deb ... 452s Unpacking open-iscsi (2.1.9-3ubuntu4) ... 452s Selecting previously unselected package librdmacm1t64:ppc64el. 452s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 452s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 452s Selecting previously unselected package libconfig-general-perl. 452s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 452s Unpacking libconfig-general-perl (2.65-2) ... 452s Selecting previously unselected package tgt. 452s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu6_ppc64el.deb ... 452s Unpacking tgt (1:1.0.85-1.1ubuntu6) ... 453s Selecting previously unselected package libgfxdr0:ppc64el. 453s Preparing to unpack .../06-libgfxdr0_11.1-4build3_ppc64el.deb ... 453s Unpacking libgfxdr0:ppc64el (11.1-4build3) ... 453s Selecting previously unselected package libglusterfs0:ppc64el. 453s Preparing to unpack .../07-libglusterfs0_11.1-4build3_ppc64el.deb ... 453s Unpacking libglusterfs0:ppc64el (11.1-4build3) ... 453s Selecting previously unselected package libgfrpc0:ppc64el. 453s Preparing to unpack .../08-libgfrpc0_11.1-4build3_ppc64el.deb ... 453s Unpacking libgfrpc0:ppc64el (11.1-4build3) ... 453s Selecting previously unselected package libgfapi0:ppc64el. 453s Preparing to unpack .../09-libgfapi0_11.1-4build3_ppc64el.deb ... 453s Unpacking libgfapi0:ppc64el (11.1-4build3) ... 453s Selecting previously unselected package libnbd0. 453s Preparing to unpack .../10-libnbd0_1.20.1-1_ppc64el.deb ... 453s Unpacking libnbd0 (1.20.1-1) ... 453s Selecting previously unselected package libdaxctl1:ppc64el. 453s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 453s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 453s Selecting previously unselected package libndctl6:ppc64el. 453s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 453s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 453s Selecting previously unselected package libpmem1:ppc64el. 453s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 453s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 453s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 453s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 453s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 453s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 453s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 453s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 453s Selecting previously unselected package librados2. 453s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 453s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 453s Selecting previously unselected package libpmemobj1:ppc64el. 453s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 453s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 453s Selecting previously unselected package librbd1. 453s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 453s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 453s Selecting previously unselected package fio. 453s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 453s Unpacking fio (3.37-1) ... 453s Selecting previously unselected package lsscsi. 453s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 453s Unpacking lsscsi (0.32-1build1) ... 453s Selecting previously unselected package autopkgtest-satdep. 453s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 453s Unpacking autopkgtest-satdep (0) ... 453s Setting up libconfig-general-perl (2.65-2) ... 453s Setting up libisns0t64:ppc64el (0.101-1) ... 453s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 453s Setting up libnbd0 (1.20.1-1) ... 453s Setting up libopeniscsiusr (2.1.9-3ubuntu4) ... 453s Setting up libglusterfs0:ppc64el (11.1-4build3) ... 453s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 453s Setting up lsscsi (0.32-1build1) ... 453s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 453s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 453s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 453s Setting up tgt (1:1.0.85-1.1ubuntu6) ... 453s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 454s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 454s Setting up libgfxdr0:ppc64el (11.1-4build3) ... 454s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 454s Setting up open-iscsi (2.1.9-3ubuntu4) ... 455s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 455s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 455s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 455s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 455s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 455s Setting up libgfrpc0:ppc64el (11.1-4build3) ... 455s Setting up libgfapi0:ppc64el (11.1-4build3) ... 455s Setting up fio (3.37-1) ... 456s Setting up autopkgtest-satdep (0) ... 456s Processing triggers for man-db (2.12.1-1) ... 457s Processing triggers for initramfs-tools (0.142ubuntu28) ... 457s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 457s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 464s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 467s (Reading database ... 72843 files and directories currently installed.) 467s Removing autopkgtest-satdep (0) ... 469s autopkgtest [01:04:04]: test tgtbasedmpaths: [----------------------- 469s + targetname=iqn.2016-11.foo.com:target.iscsi 469s + pwd 469s + cwd=/tmp/autopkgtest.ZoqZV9/build.ViE/src 469s + testdir=/mnt/tgtmpathtest 469s + localhost=127.0.0.1 469s + portal=127.0.0.1:3260 469s + maxpaths=4 469s + backfn=backingfile 469s + expectwwid=60000000000000000e00000000010001 469s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 469s + bglog=/tmp/autopkgtest.ZoqZV9/tgtbasedmpaths-artifacts/test-background.log 469s + fioprep=/tmp/autopkgtest.ZoqZV9/tgtbasedmpaths-artifacts/path-change-prep.fio 469s + fiovrfy=/tmp/autopkgtest.ZoqZV9/tgtbasedmpaths-artifacts/path-change-check.fio 469s + service tgt restart 470s + truncate --size 100M backingfile 470s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 470s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 470s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.ZoqZV9/build.ViE/src/backingfile 470s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 470s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 470s login #1 470s + echo login #1 470s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 470s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 470s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 470s + extra login #2 470s seq 2 4 470s + echo extra login #2 470s + iscsiadm --mode session -r 1 --op new 470s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 470s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 470s extra login #3 470s + echo extra login #3 470s + iscsiadm --mode session -r 1 --op new 470s + echo extra login #4 470s + iscsiadm --mode session -r 1 --op new 470s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 470s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 470s extra login #4 470s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 470s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 470s + udevadm settle 470s + sleep 5 475s Status after initial setup 475s + echo Status after initial setup 475s + tgtadm --lld iscsi --mode target --op show 475s Target 1: iqn.2016-11.foo.com:target.iscsi 475s System information: 475s Driver: iscsi 475s State: ready 475s I_T nexus information: 475s I_T nexus: 1 475s Initiator: iqn.2004-10.com.ubuntu:01:14c66c5c1ffd alias: autopkgtest 475s Connection: 0 475s IP Address: 127.0.0.1 475s I_T nexus: 2 475s Initiator: iqn.2004-10.com.ubuntu:01:14c66c5c1ffd alias: autopkgtest 475s Connection: 0 475s IP Address: 127.0.0.1 475s I_T nexus: 3 475s Initiator: iqn.2004-10.com.ubuntu:01:14c66c5c1ffd alias: autopkgtest 475s Connection: 0 475s IP Address: 127.0.0.1 475s I_T nexus: 4 475s Initiator: iqn.2004-10.com.ubuntu:01:14c66c5c1ffd alias: autopkgtest 475s Connection: 0 475s IP Address: 127.0.0.1 475s LUN information: 475s LUN: 0 475s Type: controller 475s SCSI ID: IET 00010000 475s SCSI SN: beaf10 475s Size: 0 MB, Block size: 1 475s Online: Yes 475s Removable media: No 475s Prevent removal: No 475s Readonly: No 475s SWP: No 475s Thin-provisioning: No 475s Backing store type: null 475s Backing store path: None 475s Backing store flags: 475s LUN: 1 475s Type: disk 475s SCSI ID: IET 00010001 475s SCSI SN: beaf11 475s Size: 105 MB, Block size: 512 475s Online: Yes 475s Removable media: No 475s Prevent removal: No 475s Readonly: No 475s SWP: No 475s Thin-provisioning: No 475s Backing store type: rdwr 475s Backing store path: /tmp/autopkgtest.ZoqZV9/build.ViE/src/backingfile 475s Backing store flags: 475s Account information: 475s ACL information: 475s ALL 475s Session: 4 475s Connection: 0 475s Initiator: iqn.2004-10.com.ubuntu:01:14c66c5c1ffd 475s IP Address: 127.0.0.1 475s Session: 3 475s Connection: 0 475s Initiator: iqn.2004-10.com.ubuntu:01:14c66c5c1ffd 475s IP Address: 127.0.0.1 475s Session: 2 475s Connection: 0 475s Initiator: iqn.2004-10.com.ubuntu:01:14c66c5c1ffd 475s IP Address: 127.0.0.1 475s Session: 1 475s Connection: 0 475s Initiator: iqn.2004-10.com.ubuntu:01:14c66c5c1ffd 475s IP Address: 127.0.0.1 475s + tgtadm --lld iscsi --op show --mode conn --tid 1 475s + iscsiadm --mode session -P 1 475s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 475s Current Portal: 127.0.0.1:3260,1 475s Persistent Portal: 127.0.0.1:3260,1 475s ********** 475s Interface: 475s ********** 475s Iface Name: default 475s Iface Transport: tcp 475s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:14c66c5c1ffd 475s Iface IPaddress: 127.0.0.1 475s Iface HWaddress: default 475s Iface Netdev: default 475s SID: 1 475s iSCSI Connection State: LOGGED IN 475s iSCSI Session State: LOGGED_IN 475s Internal iscsid Session State: NO CHANGE 475s 475s ********** 475s Interface: 475s ********** 475s Iface Name: default 475s Iface Transport: tcp 475s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:14c66c5c1ffd 475s Iface IPaddress: 127.0.0.1 475s Iface HWaddress: default 475s Iface Netdev: default 475s SID: 2 475s iSCSI Connection State: LOGGED IN 475s iSCSI Session State: LOGGED_IN 475s Internal iscsid Session State: NO CHANGE 475s 475s ********** 475s Interface: 475s ********** 475s Iface Name: default 475s Iface Transport: tcp 475s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:14c66c5c1ffd 475s Iface IPaddress: 127.0.0.1 475s Iface HWaddress: default 475s Iface Netdev: default 475s SID: 3 475s iSCSI Connection State: LOGGED IN 475s iSCSI Session State: LOGGED_IN 475s Internal iscsid Session State: NO CHANGE 475s 475s ********** 475s Interface: 475s ********** 475s Iface Name: default 475s Iface Transport: tcp 475s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:14c66c5c1ffd 475s Iface IPaddress: 127.0.0.1 475s Iface HWaddress: default 475s Iface Netdev: default 475s SID: 4 475s iSCSI Connection State: LOGGED IN 475s iSCSI Session State: LOGGED_IN 475s Internal iscsid Session State: NO CHANGE 475s + lsscsi -liv 475s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 475s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 475s 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] 475s [1:0:0:0] storage IET Controller 0001 - - 475s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 475s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 475s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 475s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 475s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 475s [2:0:0:0] storage IET Controller 0001 - - 475s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 475s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 475s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 475s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 475s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 475s [3:0:0:0] storage IET Controller 0001 - - 475s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 475s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 475s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 475s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 475s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 475s [4:0:0:0] storage IET Controller 0001 - - 475s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 475s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 475s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 475s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 475s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 475s NVMe module may not be loaded 475s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 475s + multipath -v3 -ll 475s 48.779168 | set open fds limit to 1048576/1048576 475s 48.779280 | loading /lib/multipath/libchecktur.so checker 475s 48.779410 | checker tur: message table size = 3 475s 48.779446 | loading /lib/multipath/libprioconst.so prioritizer 475s 48.779580 | _init_foreign: foreign library "nvme" is not enabled 475s 48.784980 | sda: size = 167772160 475s 48.785148 | sda: vendor = QEMU 475s 48.785170 | sda: product = QEMU HARDDISK 475s 48.785193 | sda: rev = 2.5+ 475s 48.785802 | sda: h:b:t:l = 0:0:0:0 475s 48.786124 | sda: tgt_node_name = 475s 48.786145 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 475s 48.786148 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 475s 48.786302 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 475s 48.786322 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 475s 48.786334 | __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 475s 48.786339 | failed to read sysfs vpd pg80: No such file or directory 475s 48.786578 | sda: fail to get serial 475s 48.786598 | sda: detect_checker = yes (setting: multipath internal) 475s 48.787512 | sda: path_checker = tur (setting: multipath internal) 475s 48.787534 | sda: checker timeout = 30 s (setting: kernel sysfs) 475s 48.787759 | sda: tur state = up 475s 48.788082 | sdb: size = 204800 475s 48.788251 | sdb: vendor = IET 475s 48.788330 | sdb: product = VIRTUAL-DISK 475s 48.788370 | sdb: rev = 0001 475s 48.789001 | sdb: h:b:t:l = 1:0:0:1 475s 48.789361 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 475s 48.789381 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 475s 48.789383 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 475s 48.789538 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 475s 48.789559 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 475s 48.789575 | sdb: serial = beaf11 475s 48.789577 | sdb: detect_checker = yes (setting: multipath internal) 475s 48.789877 | sdb: path_checker = tur (setting: multipath internal) 475s 48.789899 | sdb: checker timeout = 30 s (setting: kernel sysfs) 475s 48.790078 | sdb: tur state = up 475s 48.790219 | sdc: size = 204800 475s 48.790369 | sdc: vendor = IET 475s 48.790408 | sdc: product = VIRTUAL-DISK 475s 48.790431 | sdc: rev = 0001 475s 48.791117 | sdc: h:b:t:l = 2:0:0:1 475s 48.791468 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 475s 48.791488 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 475s 48.791490 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 475s 48.791638 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 475s 48.791658 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 475s 48.791673 | sdc: serial = beaf11 475s 48.791675 | sdc: detect_checker = yes (setting: multipath internal) 475s 48.791855 | sdc: path_checker = tur (setting: multipath internal) 475s 48.791878 | sdc: checker timeout = 30 s (setting: kernel sysfs) 475s 48.792063 | sdc: tur state = up 475s 48.792226 | sdd: size = 204800 475s 48.792376 | sdd: vendor = IET 475s 48.792416 | sdd: product = VIRTUAL-DISK 475s 48.792438 | sdd: rev = 0001 475s 48.793115 | sdd: h:b:t:l = 3:0:0:1 475s 48.793468 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 475s 48.793489 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 475s 48.793491 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 475s 48.793638 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 475s 48.793657 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 475s 48.793672 | sdd: serial = beaf11 475s 48.793674 | sdd: detect_checker = yes (setting: multipath internal) 475s 48.793902 | sdd: path_checker = tur (setting: multipath internal) 475s 48.793923 | sdd: checker timeout = 30 s (setting: kernel sysfs) 475s 48.794105 | sdd: tur state = up 475s 48.794249 | sde: size = 204800 475s 48.794398 | sde: vendor = IET 475s 48.794437 | sde: product = VIRTUAL-DISK 475s 48.794459 | sde: rev = 0001 475s 48.795132 | sde: h:b:t:l = 4:0:0:1 475s 48.795481 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 475s 48.795501 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 475s 48.795504 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 475s 48.795658 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 475s 48.795677 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 475s 48.795691 | sde: serial = beaf11 475s 48.795694 | sde: detect_checker = yes (setting: multipath internal) 475s 48.795863 | sde: path_checker = tur (setting: multipath internal) 475s 48.795885 | sde: checker timeout = 30 s (setting: kernel sysfs) 475s 48.796039 | sde: tur state = up 475s 48.796137 | loop0: device node name blacklisted 475s 48.796257 | loop1: device node name blacklisted 475s 48.796362 | loop2: device node name blacklisted 475s 48.796465 | loop3: device node name blacklisted 475s 48.796568 | loop4: device node name blacklisted 475s 48.796671 | loop5: device node name blacklisted 475s 48.796772 | loop6: device node name blacklisted 475s 48.796873 | loop7: device node name blacklisted 475s 48.796980 | dm-0: device node name blacklisted 475s 48.797922 | multipath-tools v0.9.4 (12/19, 2022) 475s 48.797949 | libdevmapper version 1.02.185 475s 48.798083 | kernel device mapper v4.48.0 475s 48.798110 | DM multipath kernel driver v1.14.0 475s 48.798219 | sdb: size = 204800 475s 48.798241 | sdb: vendor = IET 475s 48.798244 | sdb: product = VIRTUAL-DISK 475s 48.798246 | sdb: rev = 0001 475s 48.798868 | sdb: h:b:t:l = 1:0:0:1 475s 48.798999 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 475s 48.799036 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 475s 48.799039 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 475s 48.799051 | sdb: serial = beaf11 475s 48.799237 | sdb: tur state = up 475s 48.799258 | sdb: uid = 360000000000000000e00000000010001 (udev) 475s 48.799261 | sdb: detect_prio = yes (setting: multipath internal) 475s 48.799266 | sdb: prio = const (setting: multipath internal) 475s 48.799268 | sdb: prio args = "" (setting: multipath internal) 475s 48.799270 | sdb: const prio = 1 475s 48.799292 | sdc: size = 204800 475s 48.799297 | sdc: vendor = IET 475s 48.799300 | sdc: product = VIRTUAL-DISK 475s 48.799302 | sdc: rev = 0001 475s 48.799909 | sdc: h:b:t:l = 2:0:0:1 475s 48.800046 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 475s 48.800070 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 475s 48.800073 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 475s 48.800085 | sdc: serial = beaf11 475s 48.800293 | sdc: tur state = up 475s 48.800314 | sdc: uid = 360000000000000000e00000000010001 (udev) 475s 48.800317 | sdc: detect_prio = yes (setting: multipath internal) 475s 48.800319 | sdc: prio = const (setting: multipath internal) 475s 48.800321 | sdc: prio args = "" (setting: multipath internal) 475s 48.800323 | sdc: const prio = 1 475s 48.800348 | sdd: size = 204800 475s 48.800353 | sdd: vendor = IET 475s 48.800355 | sdd: product = VIRTUAL-DISK 475s 48.800358 | sdd: rev = 0001 475s 48.800961 | sdd: h:b:t:l = 3:0:0:1 475s 48.801091 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 475s 48.801128 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 475s 48.801131 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 475s 48.801143 | sdd: serial = beaf11 475s 48.802069 | sdd: tur state = up 475s 48.802092 | sdd: uid = 360000000000000000e00000000010001 (udev) 475s 48.802095 | sdd: detect_prio = yes (setting: multipath internal) 475s 48.802097 | sdd: prio = const (setting: multipath internal) 475s 48.802099 | sdd: prio args = "" (setting: multipath internal) 475s 48.802101 | sdd: const prio = 1 475s 48.802127 | sde: size = 204800 475s 48.802132 | sde: vendor = IET 475s 48.802135 | sde: product = VIRTUAL-DISK 475s 48.802138 | sde: rev = 0001 475s 48.802757 | sde: h:b:t:l = 4:0:0:1 475s 48.802893 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 475s 48.802931 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 475s 48.802934 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 475s 48.802946 | sde: serial = beaf11 475s 48.803888 | sde: tur state = up 475s 48.803911 | sde: uid = 360000000000000000e00000000010001 (udev) 475s 48.803913 | sde: detect_prio = yes (setting: multipath internal) 475s 48.803916 | sde: prio = const (setting: multipath internal) 475s 48.803918 | sde: prio args = "" (setting: multipath internal) 475s 48.803920 | sde: const prio = 1 475s 48.805538 | unloading tur checker 475s 48.805591 | unloading const prioritizer 475s + dmsetup table 475s + echo Test WWN should now point to DM 475s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 475s + grep dm 475s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 475s mke2fs 1.47.0 (5-Feb-2023) 475s ===== paths list ===== 475s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 475s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 475s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 475s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 475s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 475s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 475s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 475s size=100M features='0' hwhandler='0' wp=rw 475s |-+- policy='service-time 0' prio=1 status=active 475s | `- 1:0:0:1 sdb 8:16 active ready running 475s |-+- policy='service-time 0' prio=1 status=enabled 475s | `- 2:0:0:1 sdc 8:32 active ready running 475s |-+- policy='service-time 0' prio=1 status=enabled 475s | `- 3:0:0:1 sdd 8:48 active ready running 475s `-+- policy='service-time 0' prio=1 status=enabled 475s `- 4:0:0:1 sde 8:64 active ready running 475s 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 475s Test WWN should now point to DM 475s ../../dm-0 475s Creating filesystem with 25600 4k blocks and 25600 inodes 475s 475s Allocating group tables: 0/1 done 475s Writing inode tables: 0/1 done 475s Creating journal (1024 blocks): done 475s Writing superblocks and filesystem accounting information: 0/1 done 475s 475s + udevadm settle 475s + sleep 3s 478s + mkdir -p /mnt/tgtmpathtest 478s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 478s + cat 478s + cat 478s + fio --max-jobs=4 /tmp/autopkgtest.ZoqZV9/tgtbasedmpaths-artifacts/path-change-prep.fio 478s 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 478s fio-3.37 478s Starting 1 thread 478s write-phase: Laying out IO file (1 file / 17592186044415MiB) 479s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 479s 479s write-phase: (groupid=0, jobs=1): err= 0: pid=5613: Fri Jun 7 01:04:14 2024 479s write: IOPS=1721, BW=108MiB/s (113MB/s)(87.6MiB/815msec); 0 zone resets 479s clat (usec): min=271, max=2646, avg=557.78, stdev=203.78 479s lat (usec): min=284, max=2664, avg=579.46, stdev=206.75 479s clat percentiles (usec): 479s | 1.00th=[ 314], 5.00th=[ 334], 10.00th=[ 367], 20.00th=[ 416], 479s | 30.00th=[ 457], 40.00th=[ 498], 50.00th=[ 529], 60.00th=[ 578], 479s | 70.00th=[ 627], 80.00th=[ 660], 90.00th=[ 693], 95.00th=[ 750], 479s | 99.00th=[ 1565], 99.50th=[ 1680], 99.90th=[ 1876], 99.95th=[ 2638], 479s | 99.99th=[ 2638] 479s bw ( KiB/s): min=99072, max=99072, per=89.99%, avg=99072.00, stdev= 0.00, samples=1 479s iops : min= 1548, max= 1548, avg=1548.00, stdev= 0.00, samples=1 479s lat (usec) : 500=40.70%, 750=54.60%, 1000=1.85% 479s lat (msec) : 2=2.71%, 4=0.07% 479s cpu : usr=3.32%, sys=9.58%, ctx=1404, majf=0, minf=0 479s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 479s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 479s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 479s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 479s latency : target=0, window=0, percentile=100.00%, depth=1 479s 479s Run status group 0 (all jobs): 479s WRITE: bw=108MiB/s (113MB/s), 108MiB/s-108MiB/s (113MB/s-113MB/s), io=87.6MiB (91.9MB), run=815-815msec 479s 479s Disk stats (read/write): 479s dm-0: ios=1/988, sectors=8/126464, merge=0/0, ticks=1/648, in_queue=650, util=87.03%, aggrios=0/351, aggsectors=2/44884, aggrmerge=0/0, aggrticks=0/183, aggrin_queue=184, aggrutil=87.18% 479s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 479s sdb: ios=1/1404, sectors=8/179536, merge=0/0, ticks=1/735, in_queue=737, util=87.18% 479s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 479s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 479s Starting the path changes in background 479s Pre FIO 01:04:14.606406130 479s + echo Starting the path changes in background 479s + date +Pre FIO %H:%M:%S.%N 479s + fio --max-jobs=4 /tmp/autopkgtest.ZoqZV9/tgtbasedmpaths-artifacts/path-change-check.fio 479s 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 479s fio-3.37 479s Starting 1 thread 659s 659s verify-phase: (groupid=0, jobs=1): err= 0: pid=5620: Fri Jun 7 01:07:14 2024 659s read: IOPS=3445, BW=215MiB/s (226MB/s)(37.9GiB/180001msec) 659s clat (usec): min=83, max=58518, avg=267.42, stdev=216.14 659s lat (usec): min=83, max=58518, avg=267.52, stdev=216.14 659s clat percentiles (usec): 659s | 1.00th=[ 100], 5.00th=[ 151], 10.00th=[ 169], 20.00th=[ 192], 659s | 30.00th=[ 206], 40.00th=[ 219], 50.00th=[ 249], 60.00th=[ 285], 659s | 70.00th=[ 314], 80.00th=[ 343], 90.00th=[ 375], 95.00th=[ 404], 659s | 99.00th=[ 478], 99.50th=[ 635], 99.90th=[ 1237], 99.95th=[ 1680], 659s | 99.99th=[ 4113] 659s bw ( KiB/s): min=113536, max=387840, per=100.00%, avg=220747.66, stdev=52400.33, samples=359 659s iops : min= 1774, max= 6060, avg=3449.17, stdev=818.75, samples=359 659s lat (usec) : 100=1.05%, 250=49.17%, 500=48.98%, 750=0.41%, 1000=0.18% 659s lat (msec) : 2=0.18%, 4=0.02%, 10=0.01%, 20=0.01%, 50=0.01% 659s lat (msec) : 100=0.01% 659s cpu : usr=9.31%, sys=7.21%, ctx=620362, majf=0, minf=1 659s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 659s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 659s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 659s issued rwts: total=620275,0,0,0 short=0,0,0,0 dropped=0,0,0,0 659s latency : target=0, window=0, percentile=100.00%, depth=1 659s 659s Run status group 0 (all jobs): 659s READ: bw=215MiB/s (226MB/s), 215MiB/s-215MiB/s (226MB/s-226MB/s), io=37.9GiB (40.7GB), run=180001-180001msec 659s 659s Disk stats (read/write): 659s dm-0: ios=620403/9, sectors=79353016/12912, merge=19/8, ticks=169844/79, in_queue=169971, util=100.00%, aggrios=38505/2, aggsectors=4924622/3228, aggrmerge=0/0, aggrticks=10890/7, aggrin_queue=10898, aggrutil=99.18% 659s sdd: ios=32260/0, sectors=4126336/0, merge=0/0, ticks=8633/0, in_queue=8633, util=32.99% 659s sdb: ios=27583/8, sectors=3527936/12912, merge=0/0, ticks=8615/30, in_queue=8645, util=99.18% 659s sde: ios=63843/0, sectors=8166144/0, merge=0/0, ticks=17453/0, in_queue=17453, util=39.64% 659s sdc: ios=30334/0, sectors=3878072/0, merge=0/0, ticks=8861/0, in_queue=8861, util=50.03% 659s Post FIO 01:07:14.943619763 659s FIO verify test with changing paths - OK 659s Report log of background activity 659s + date +Post FIO %H:%M:%S.%N 659s + echo FIO verify test with changing paths - OK 659s + echo Report log of background activity 659s + cat /tmp/autopkgtest.ZoqZV9/tgtbasedmpaths-artifacts/test-background.log 660s + iscsiadm --mode session 660s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s + sleep 10s 660s + date +MP report (expect 4) %H:%M:%S.%N 660s MP report (expect 4) 01:04:24.613434935 660s + multipath -ll 660s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 660s size=100M features='0' hwhandler='0' wp=rw 660s |-+- policy='service-time 0' prio=1 status=active 660s | `- 1:0:0:1 sdb 8:16 active ready running 660s |-+- policy='service-time 0' prio=1 status=enabled 660s | `- 2:0:0:1 sdc 8:32 active ready running 660s |-+- policy='service-time 0' prio=1 status=enabled 660s | `- 3:0:0:1 sdd 8:48 active ready running 660s `-+- policy='service-time 0' prio=1 status=enabled 660s `- 4:0:0:1 sde 8:64 active ready running 660s + date +UN-plug path 1 %H:%M:%S.%N 660s UN-plug path 1 01:04:24.640139924 660s + iscsiadm --mode session -r 1 -u 660s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 660s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 660s + iscsiadm --mode session 660s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s + sleep 10s 660s + date +MP report (expect 3) %H:%M:%S.%N 660s MP report (expect 3) 01:04:34.738262133 660s + multipath -ll 660s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 660s size=100M features='0' hwhandler='0' wp=rw 660s |-+- policy='service-time 0' prio=1 status=active 660s | `- 2:0:0:1 sdc 8:32 active ready running 660s |-+- policy='service-time 0' prio=1 status=enabled 660s | `- 3:0:0:1 sdd 8:48 active ready running 660s `-+- policy='service-time 0' prio=1 status=enabled 660s `- 4:0:0:1 sde 8:64 active ready running 660s + date +UN-plug path 2 %H:%M:%S.%N 660s UN-plug path 2 01:04:34.762149548 660s + iscsiadm --mode session -r 2 -u 660s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 660s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 660s + iscsiadm --mode session 660s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s + sleep 10s 660s + date +MP report (expect 2) %H:%M:%S.%N 660s MP report (expect 2) 01:04:44.827736971 660s + multipath -ll 660s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 660s size=100M features='0' hwhandler='0' wp=rw 660s |-+- policy='service-time 0' prio=1 status=active 660s | `- 3:0:0:1 sdd 8:48 active ready running 660s `-+- policy='service-time 0' prio=1 status=enabled 660s `- 4:0:0:1 sde 8:64 active ready running 660s + date +UN-plug path 3 %H:%M:%S.%N 660s UN-plug path 3 01:04:44.846807253 660s + iscsiadm --mode session -r 3 -u 660s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 660s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 660s + iscsiadm --mode session 660s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s + sleep 10s 660s + date +MP report (expect 1) %H:%M:%S.%N 660s MP report (expect 1) 01:04:54.940476805 660s + multipath -ll 660s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 660s size=100M features='0' hwhandler='0' wp=rw 660s `-+- policy='service-time 0' prio=1 status=active 660s `- 4:0:0:1 sde 8:64 active ready running 660s + date +Add paths 5/6/7/8 %H:%M:%S.%N 660s Add paths 5/6/7/8 01:04:54.955879590 660s + iscsiadm --mode session -r 4 --op new 660s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 660s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 660s + iscsiadm --mode session -r 4 --op new 660s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 660s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 660s + iscsiadm --mode session -r 4 --op new 660s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 660s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 660s + iscsiadm --mode session -r 4 --op new 660s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 660s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 660s + iscsiadm --mode session 660s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s + sleep 10s 660s + date +MP report (expect 5) %H:%M:%S.%N 660s MP report (expect 5) 01:05:05.077366083 660s + multipath -ll 660s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 660s size=100M features='0' hwhandler='0' wp=rw 660s |-+- policy='service-time 0' prio=1 status=active 660s | `- 4:0:0:1 sde 8:64 active ready running 660s |-+- policy='service-time 0' prio=1 status=enabled 660s | `- 1:0:0:1 sdb 8:16 active ready running 660s |-+- policy='service-time 0' prio=1 status=enabled 660s | `- 2:0:0:1 sdc 8:32 active ready running 660s |-+- policy='service-time 0' prio=1 status=enabled 660s | `- 3:0:0:1 sdd 8:48 active ready running 660s `-+- policy='service-time 0' prio=1 status=enabled 660s `- 5:0:0:1 sdf 8:80 active ready running 660s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 660s UN-plug multiple paths 4/7/8 01:05:05.110258233 660s + iscsiadm --mode session -r 4 -u 660s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 660s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 660s + iscsiadm --mode session -r 7 -u 660s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 660s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 660s + iscsiadm --mode session -r 8 -u 660s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 660s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 660s + iscsiadm --mode session 660s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 660s + sleep 10s 660s + date +Restart multipath daemon %H:%M:%S.%N 660s Restart multipath daemon 01:05:15.420555617 660s + systemctl restart multipathd 660s + sleep 10s 660s + date +Final background report (expect 2) %H:%M:%S.%N 660s Final background report (expect 2) 01:05:25.495727854 660s + multipath -ll 660s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 660s size=100M features='0' hwhandler='0' wp=rw 660s |-+- policy='service-time 0' prio=1 status=active 660s | `- 1:0:0:1 sdb 8:16 active ready running 660s `-+- policy='service-time 0' prio=1 status=enabled 660s `- 2:0:0:1 sdc 8:32 active ready running 660s Final stats 660s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 660s iSCSI SNMP: 660s txdata_octets: 22332936 660s rxdata_octets: 30468905588 660s noptx_pdus: 0 660s scsicmd_pdus: 465002 660s tmfcmd_pdus: 0 660s login_pdus: 0 660s text_pdus: 0 660s dataout_pdus: 0 660s logout_pdus: 0 660s snack_pdus: 0 660s noprx_pdus: 0 660s scsirsp_pdus: 465002 660s tmfrsp_pdus: 0 660s textrsp_pdus: 0 660s datain_pdus: 464969 660s logoutrsp_pdus: 0 660s r2t_pdus: 0 660s async_pdus: 0 660s rjt_pdus: 0 660s digest_err: 0 660s timeout_err: 0 660s iSCSI Extended: 660s tx_sendpage_failures: 0 660s rx_discontiguous_hdr: 0 660s eh_abort_cnt: 0 660s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 660s iSCSI SNMP: 660s txdata_octets: 6552 660s rxdata_octets: 1515012 660s noptx_pdus: 0 660s scsicmd_pdus: 106 660s tmfcmd_pdus: 0 660s login_pdus: 0 660s text_pdus: 0 660s dataout_pdus: 0 660s logout_pdus: 0 660s snack_pdus: 0 660s noprx_pdus: 0 660s scsirsp_pdus: 106 660s tmfrsp_pdus: 0 660s textrsp_pdus: 0 660s datain_pdus: 83 660s logoutrsp_pdus: 0 660s r2t_pdus: 0 660s async_pdus: 0 660s rjt_pdus: 0 660s digest_err: 0 660s timeout_err: 0 660s iSCSI Extended: 660s tx_sendpage_failures: 0 660s rx_discontiguous_hdr: 0 660s eh_abort_cnt: 0 660s Jun 06 02:07:00 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 660s Jun 06 02:07:00 ubuntu multipathd[331]: multipathd v0.9.4: start up 660s Jun 06 02:07:00 ubuntu multipathd[331]: reconfigure: setting up paths and maps 660s Jun 06 02:07:00 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 660s Jun 06 02:09:34 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 multipathd[331]: multipathd: shut down 660s Jun 06 02:09:34 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 660s Jun 06 02:09:34 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 systemd[1]: multipathd.service: Deactivated successfully. 660s Jun 06 02:09:34 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 660s -- Boot 273fede14af247fbbc3bb252a71cc317 -- 660s Jun 06 02:09:59 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 multipathd[261]: multipathd v0.9.4: start up 660s Jun 06 02:09:59 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 multipathd[261]: reconfigure: setting up paths and maps 660s Jun 06 02:09:59 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 660s Jun 06 02:10:17 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 multipathd[261]: multipathd: shut down 660s Jun 06 02:10:17 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 660s Jun 06 02:10:17 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 systemd[1]: multipathd.service: Deactivated successfully. 660s Jun 06 02:10:17 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 660s -- Boot 147a9a4582e542c1855ae0589f22df35 -- 660s Jun 07 01:02:19 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 multipathd[313]: multipathd v0.9.4: start up 660s Jun 07 01:02:19 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 multipathd[313]: reconfigure: setting up paths and maps 660s Jun 07 01:02:19 auto-syncubuntu-oracular-daily-ppc64el-server-20240604-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 660s Jun 07 01:03:01 autopkgtest multipathd[313]: multipathd: shut down 660s Jun 07 01:03:01 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 660s Jun 07 01:03:01 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 660s Jun 07 01:03:01 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 660s -- Boot b08de76040c24d8db6b861c2f6e50e4a -- 660s Jun 07 01:03:25 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 660s Jun 07 01:03:25 autopkgtest multipathd[330]: multipathd v0.9.4: start up 660s Jun 07 01:03:25 autopkgtest multipathd[330]: reconfigure: setting up paths and maps 660s Jun 07 01:03:25 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 660s Jun 07 01:04:05 autopkgtest multipathd[330]: 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] 660s Jun 07 01:04:05 autopkgtest multipathd[330]: sdc [8:32]: path added to devmap mpatha 660s Jun 07 01:04:05 autopkgtest multipathd[330]: mpatha: performing delayed actions 660s Jun 07 01:04:05 autopkgtest multipathd[330]: 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] 660s Jun 07 01:04:24 autopkgtest multipathd[330]: 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] 660s Jun 07 01:04:24 autopkgtest multipathd[330]: check_removed_paths: sdb: freeing path in removed state 660s Jun 07 01:04:24 autopkgtest multipathd[330]: 8:16: path removed from map mpatha 660s Jun 07 01:04:34 autopkgtest multipathd[330]: sdc: mark as failed 660s Jun 07 01:04:34 autopkgtest multipathd[330]: mpatha: remaining active paths: 2 660s Jun 07 01:04:34 autopkgtest multipathd[330]: 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] 660s Jun 07 01:04:34 autopkgtest multipathd[330]: check_removed_paths: sdc: freeing path in removed state 660s Jun 07 01:04:34 autopkgtest multipathd[330]: 8:32: path removed from map mpatha 660s Jun 07 01:04:44 autopkgtest multipathd[330]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 660s Jun 07 01:04:44 autopkgtest multipathd[330]: check_removed_paths: sdd: freeing path in removed state 660s Jun 07 01:04:44 autopkgtest multipathd[330]: 8:48: path removed from map mpatha 660s Jun 07 01:04:55 autopkgtest multipathd[330]: 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] 660s Jun 07 01:04:55 autopkgtest multipathd[330]: sdb [8:16]: path added to devmap mpatha 660s Jun 07 01:04:55 autopkgtest multipathd[330]: 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] 660s Jun 07 01:04:55 autopkgtest multipathd[330]: sdc [8:32]: path added to devmap mpatha 660s Jun 07 01:04:55 autopkgtest multipathd[330]: 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] 660s Jun 07 01:04:55 autopkgtest multipathd[330]: sdd [8:48]: path added to devmap mpatha 660s Jun 07 01:04:55 autopkgtest multipathd[330]: 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] 660s Jun 07 01:04:55 autopkgtest multipathd[330]: sdf [8:80]: path added to devmap mpatha 660s Jun 07 01:05:05 autopkgtest multipathd[330]: 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] 660s Jun 07 01:05:05 autopkgtest multipathd[330]: check_removed_paths: sde: freeing path in removed state 660s Jun 07 01:05:05 autopkgtest multipathd[330]: 8:64: path removed from map mpatha 660s Jun 07 01:05:05 autopkgtest multipathd[330]: 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] 660s Jun 07 01:05:05 autopkgtest multipathd[330]: check_removed_paths: sdd: freeing path in removed state 660s Jun 07 01:05:05 autopkgtest multipathd[330]: 8:48: path removed from map mpatha 660s Jun 07 01:05:05 autopkgtest multipathd[330]: 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] 660s Jun 07 01:05:05 autopkgtest multipathd[330]: check_removed_paths: sdf: freeing path in removed state 660s Jun 07 01:05:05 autopkgtest multipathd[330]: 8:80: path removed from map mpatha 660s Jun 07 01:05:15 autopkgtest multipathd[330]: multipathd: shut down 660s Jun 07 01:05:15 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 660s Jun 07 01:05:15 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 660s Jun 07 01:05:15 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 660s Jun 07 01:05:15 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 660s Jun 07 01:05:15 autopkgtest multipathd[5992]: multipathd v0.9.4: start up 660s Jun 07 01:05:15 autopkgtest multipathd[5992]: reconfigure: setting up paths and maps 660s Jun 07 01:05:15 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 660s Check final path status 660s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 660s size=100M features='0' hwhandler='0' wp=rw 660s |-+- policy='service-time 0' prio=1 status=active 660s | `- 1:0:0:1 sdb 8:16 active ready running 660s `-+- policy='service-time 0' prio=1 status=enabled 660s `- 2:0:0:1 sdc 8:32 active ready running 660s + sync 660s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 660s + echo Final stats 660s + iscsiadm --mode session --stats 660s + journalctl --no-pager -u multipathd 660s + echo Check final path status 660s + multipath -ll 660s + multipath -ll 660s + grep --count status= 660s + diskc=2 660s + multipath -ll 660s + grep --count status=active 660s + diska=1 660s + multipath -ll 660s + grep --count status=enabled 660s OK 660s + diske=1 660s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 660s + echo OK 660s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 660s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 660s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 660s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 660s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 660s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 660s autopkgtest [01:07:15]: test tgtbasedmpaths: -----------------------] 661s tgtbasedmpaths PASS 661s autopkgtest [01:07:16]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 671s autopkgtest [01:07:26]: @@@@@@@@@@@@@@@@@@@@ summary 671s kpartx-file-loopback PASS 671s tgtbasedmpaths PASS 681s nova [W] Using flock in scalingstack-bos02-ppc64el 681s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240607-005614-juju-7f2275-prod-proposed-migration-environment-3-8c086abd-438e-47bc-be75-88e47f665525 from image adt/ubuntu-oracular-ppc64el-server-20240606.img (UUID 117a058b-23b7-4e29-8ba4-b05604e9e4e2)... 681s nova [W] Using flock in scalingstack-bos02-ppc64el 681s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240607-005614-juju-7f2275-prod-proposed-migration-environment-3-8c086abd-438e-47bc-be75-88e47f665525 from image adt/ubuntu-oracular-ppc64el-server-20240606.img (UUID 117a058b-23b7-4e29-8ba4-b05604e9e4e2)...