0s autopkgtest [00:10:55]: starting date and time: 2024-06-29 00:10:55+0000 0s autopkgtest [00:10:55]: git checkout: 85adf9a1 setup-testbed: prevent /tmp from getting a tmpfs mount 0s autopkgtest [00:10:55]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.twkj6cr2/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:glibc --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=glibc/2.39-3.1ubuntu2 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos02-ppc64el-9.secgroup --name adt-oracular-ppc64el-multipath-tools-20240629-001055-juju-7f2275-prod-proposed-migration-environment-2-eb5b5eb1-c2c1-4b90-9517-a89c4f56c9c9 --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/ 120s autopkgtest [00:12:55]: testbed dpkg architecture: ppc64el 121s autopkgtest [00:12:56]: testbed apt version: 2.9.5 121s autopkgtest [00:12:56]: @@@@@@@@@@@@@@@@@@@@ test bed setup 122s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 122s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [368 kB] 122s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7052 B] 122s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.0 kB] 122s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 122s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [86.1 kB] 122s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 122s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [393 kB] 122s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1768 B] 122s Fetched 1022 kB in 1s (1241 kB/s) 122s Reading package lists... 125s Reading package lists... 125s Building dependency tree... 125s Reading state information... 126s Calculating upgrade... 126s The following packages will be upgraded: 126s libc-bin libc-dev-bin libc-devtools libc6 libc6-dev locales 126s 6 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 126s Need to get 10.1 MB of archives. 126s After this operation, 1844 kB disk space will be freed. 126s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-devtools ppc64el 2.39-3.1ubuntu2 [29.5 kB] 126s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6-dev ppc64el 2.39-3.1ubuntu2 [1982 kB] 126s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-dev-bin ppc64el 2.39-3.1ubuntu2 [21.0 kB] 126s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6 ppc64el 2.39-3.1ubuntu2 [3173 kB] 126s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-bin ppc64el 2.39-3.1ubuntu2 [720 kB] 126s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el locales all 2.39-3.1ubuntu2 [4220 kB] 127s Preconfiguring packages ... 127s Fetched 10.1 MB in 1s (11.3 MB/s) 127s (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 ... 72690 files and directories currently installed.) 127s Preparing to unpack .../libc-devtools_2.39-3.1ubuntu2_ppc64el.deb ... 127s Unpacking libc-devtools (2.39-3.1ubuntu2) over (2.39-0ubuntu9) ... 127s Preparing to unpack .../libc6-dev_2.39-3.1ubuntu2_ppc64el.deb ... 127s Unpacking libc6-dev:ppc64el (2.39-3.1ubuntu2) over (2.39-0ubuntu9) ... 127s Preparing to unpack .../libc-dev-bin_2.39-3.1ubuntu2_ppc64el.deb ... 127s Unpacking libc-dev-bin (2.39-3.1ubuntu2) over (2.39-0ubuntu9) ... 127s Preparing to unpack .../libc6_2.39-3.1ubuntu2_ppc64el.deb ... 127s Unpacking libc6:ppc64el (2.39-3.1ubuntu2) over (2.39-0ubuntu9) ... 128s Setting up libc6:ppc64el (2.39-3.1ubuntu2) ... 128s (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 ... 72690 files and directories currently installed.) 128s Preparing to unpack .../libc-bin_2.39-3.1ubuntu2_ppc64el.deb ... 128s Unpacking libc-bin (2.39-3.1ubuntu2) over (2.39-0ubuntu9) ... 128s Setting up libc-bin (2.39-3.1ubuntu2) ... 128s (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 ... 72690 files and directories currently installed.) 128s Preparing to unpack .../locales_2.39-3.1ubuntu2_all.deb ... 128s Unpacking locales (2.39-3.1ubuntu2) over (2.39-0ubuntu9) ... 129s Setting up locales (2.39-3.1ubuntu2) ... 129s Generating locales (this might take a while)... 131s en_US.UTF-8... done 131s Generation complete. 131s Setting up libc-dev-bin (2.39-3.1ubuntu2) ... 131s Setting up libc-devtools (2.39-3.1ubuntu2) ... 131s Setting up libc6-dev:ppc64el (2.39-3.1ubuntu2) ... 131s Processing triggers for man-db (2.12.1-2) ... 132s Reading package lists... 132s Building dependency tree... 132s Reading state information... 132s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 133s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 133s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 133s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 133s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 134s Reading package lists... 134s Reading package lists... 134s Building dependency tree... 134s Reading state information... 134s Calculating upgrade... 135s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 135s Reading package lists... 135s Building dependency tree... 135s Reading state information... 135s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 140s autopkgtest [00:13:15]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 140s autopkgtest [00:13:15]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 144s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 144s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 144s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 144s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 144s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 144s gpgv: issuer "steve.langasek@ubuntu.com" 144s gpgv: Can't check signature: No public key 144s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 144s autopkgtest [00:13:19]: testing package multipath-tools version 0.9.4-5ubuntu8 145s autopkgtest [00:13:20]: build not needed 145s autopkgtest [00:13:20]: test kpartx-file-loopback: preparing testbed 147s Reading package lists... 147s Building dependency tree... 147s Reading state information... 147s Starting pkgProblemResolver with broken count: 0 148s Starting 2 pkgProblemResolver with broken count: 0 148s Done 148s The following additional packages will be installed: 148s liburing2 qemu-utils 148s Recommended packages: 148s qemu-block-extra 148s The following NEW packages will be installed: 148s autopkgtest-satdep liburing2 qemu-utils 148s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 148s Need to get 2330 kB/2331 kB of archives. 148s After this operation, 15.4 MB of additional disk space will be used. 148s Get:1 /tmp/autopkgtest.JmD6uY/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 148s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 148s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 149s Fetched 2330 kB in 1s (3236 kB/s) 149s Selecting previously unselected package liburing2:ppc64el. 149s (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 ... 72690 files and directories currently installed.) 149s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 149s Unpacking liburing2:ppc64el (2.6-1) ... 149s Selecting previously unselected package qemu-utils. 149s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 149s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 149s Selecting previously unselected package autopkgtest-satdep. 149s Preparing to unpack .../1-autopkgtest-satdep.deb ... 149s Unpacking autopkgtest-satdep (0) ... 149s Setting up liburing2:ppc64el (2.6-1) ... 149s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 149s Setting up autopkgtest-satdep (0) ... 149s Processing triggers for man-db (2.12.1-2) ... 150s Processing triggers for libc-bin (2.39-3.1ubuntu2) ... 152s (Reading database ... 72710 files and directories currently installed.) 152s Removing autopkgtest-satdep (0) ... 153s autopkgtest [00:13:28]: test kpartx-file-loopback: [----------------------- 153s Formatting 'foo.img', fmt=raw size=20971520 154s Creating new GPT entries in memory. 154s Warning: The kernel is still using the old partition table. 154s The new table will be used at the next reboot or after you 154s run partprobe(8) or kpartx(8) 154s The operation has completed successfully. 154s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 154s standard_filename: OK 154s del devmap : loop0p1 154s No devices found 154s standard_filename_cleanup: OK 154s Formatting 'fou du FaFa.img', fmt=raw size=20971520 155s Creating new GPT entries in memory. 155s Warning: The kernel is still using the old partition table. 155s The new table will be used at the next reboot or after you 155s run partprobe(8) or kpartx(8) 155s The operation has completed successfully. 155s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 155s filename_with_spaces: OK 155s del devmap : loop0p1 155s No devices found 155s filename_with_spaces_cleanup: OK 156s autopkgtest [00:13:31]: test kpartx-file-loopback: -----------------------] 156s kpartx-file-loopback PASS 156s autopkgtest [00:13:31]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 157s autopkgtest [00:13:32]: test tgtbasedmpaths: preparing testbed 322s autopkgtest [00:16:17]: testbed dpkg architecture: ppc64el 322s autopkgtest [00:16:17]: testbed apt version: 2.9.5 322s autopkgtest [00:16:17]: @@@@@@@@@@@@@@@@@@@@ test bed setup 323s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 323s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 323s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.0 kB] 323s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [368 kB] 324s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7052 B] 324s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [86.1 kB] 324s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 324s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [393 kB] 324s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1768 B] 324s Fetched 1022 kB in 1s (1214 kB/s) 324s Reading package lists... 326s Reading package lists... 326s Building dependency tree... 326s Reading state information... 326s Calculating upgrade... 326s The following packages will be upgraded: 326s libc-bin libc-dev-bin libc-devtools libc6 libc6-dev locales 327s 6 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 327s Need to get 10.1 MB of archives. 327s After this operation, 1844 kB disk space will be freed. 327s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-devtools ppc64el 2.39-3.1ubuntu2 [29.5 kB] 327s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6-dev ppc64el 2.39-3.1ubuntu2 [1982 kB] 327s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-dev-bin ppc64el 2.39-3.1ubuntu2 [21.0 kB] 327s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6 ppc64el 2.39-3.1ubuntu2 [3173 kB] 327s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-bin ppc64el 2.39-3.1ubuntu2 [720 kB] 327s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el locales all 2.39-3.1ubuntu2 [4220 kB] 328s Preconfiguring packages ... 328s Fetched 10.1 MB in 1s (10.2 MB/s) 328s (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 ... 72690 files and directories currently installed.) 328s Preparing to unpack .../libc-devtools_2.39-3.1ubuntu2_ppc64el.deb ... 328s Unpacking libc-devtools (2.39-3.1ubuntu2) over (2.39-0ubuntu9) ... 328s Preparing to unpack .../libc6-dev_2.39-3.1ubuntu2_ppc64el.deb ... 328s Unpacking libc6-dev:ppc64el (2.39-3.1ubuntu2) over (2.39-0ubuntu9) ... 328s Preparing to unpack .../libc-dev-bin_2.39-3.1ubuntu2_ppc64el.deb ... 328s Unpacking libc-dev-bin (2.39-3.1ubuntu2) over (2.39-0ubuntu9) ... 328s Preparing to unpack .../libc6_2.39-3.1ubuntu2_ppc64el.deb ... 328s Unpacking libc6:ppc64el (2.39-3.1ubuntu2) over (2.39-0ubuntu9) ... 329s Setting up libc6:ppc64el (2.39-3.1ubuntu2) ... 329s (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 ... 72690 files and directories currently installed.) 329s Preparing to unpack .../libc-bin_2.39-3.1ubuntu2_ppc64el.deb ... 329s Unpacking libc-bin (2.39-3.1ubuntu2) over (2.39-0ubuntu9) ... 329s Setting up libc-bin (2.39-3.1ubuntu2) ... 329s (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 ... 72690 files and directories currently installed.) 329s Preparing to unpack .../locales_2.39-3.1ubuntu2_all.deb ... 329s Unpacking locales (2.39-3.1ubuntu2) over (2.39-0ubuntu9) ... 329s Setting up locales (2.39-3.1ubuntu2) ... 330s Generating locales (this might take a while)... 331s en_US.UTF-8... done 331s Generation complete. 331s Setting up libc-dev-bin (2.39-3.1ubuntu2) ... 331s Setting up libc-devtools (2.39-3.1ubuntu2) ... 331s Setting up libc6-dev:ppc64el (2.39-3.1ubuntu2) ... 331s Processing triggers for man-db (2.12.1-2) ... 333s Reading package lists... 333s Building dependency tree... 333s Reading state information... 333s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 334s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 334s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 334s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 334s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 335s Reading package lists... 335s Reading package lists... 335s Building dependency tree... 335s Reading state information... 335s Calculating upgrade... 335s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 335s Reading package lists... 335s Building dependency tree... 335s Reading state information... 336s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 340s Reading package lists... 340s Building dependency tree... 340s Reading state information... 340s Starting pkgProblemResolver with broken count: 0 340s Starting 2 pkgProblemResolver with broken count: 0 340s Done 340s The following additional packages will be installed: 340s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 340s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 340s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 340s librdmacm1t64 lsscsi open-iscsi tgt 340s Suggested packages: 340s fio-examples gnuplot tgt-glusterfs tgt-rbd 340s Recommended packages: 340s finalrd 340s The following NEW packages will be installed: 340s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 340s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 340s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 340s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 340s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 340s Need to get 10.7 MB/10.7 MB of archives. 340s After this operation, 49.0 MB of additional disk space will be used. 340s Get:1 /tmp/autopkgtest.JmD6uY/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [736 B] 341s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 341s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 341s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 341s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 341s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 341s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 341s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4ubuntu1 [21.5 kB] 341s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4ubuntu1 [311 kB] 341s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4ubuntu1 [46.5 kB] 341s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4ubuntu1 [99.2 kB] 341s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.1-1 [97.4 kB] 341s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 341s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 341s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 341s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 341s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 341s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 341s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 341s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 341s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 341s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 342s Preconfiguring packages ... 342s Fetched 10.7 MB in 1s (10.1 MB/s) 342s Selecting previously unselected package libopeniscsiusr. 342s (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 ... 72690 files and directories currently installed.) 342s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 342s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 342s Selecting previously unselected package libisns0t64:ppc64el. 342s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 342s Unpacking libisns0t64:ppc64el (0.101-1) ... 342s Selecting previously unselected package open-iscsi. 342s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 342s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 342s Selecting previously unselected package librdmacm1t64:ppc64el. 342s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 342s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 342s Selecting previously unselected package libconfig-general-perl. 342s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 342s Unpacking libconfig-general-perl (2.65-2) ... 342s Selecting previously unselected package tgt. 342s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 342s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 342s Selecting previously unselected package libgfxdr0:ppc64el. 342s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_ppc64el.deb ... 342s Unpacking libgfxdr0:ppc64el (11.1-4ubuntu1) ... 342s Selecting previously unselected package libglusterfs0:ppc64el. 342s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_ppc64el.deb ... 342s Unpacking libglusterfs0:ppc64el (11.1-4ubuntu1) ... 342s Selecting previously unselected package libgfrpc0:ppc64el. 342s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_ppc64el.deb ... 342s Unpacking libgfrpc0:ppc64el (11.1-4ubuntu1) ... 342s Selecting previously unselected package libgfapi0:ppc64el. 342s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_ppc64el.deb ... 342s Unpacking libgfapi0:ppc64el (11.1-4ubuntu1) ... 342s Selecting previously unselected package libnbd0. 342s Preparing to unpack .../10-libnbd0_1.20.1-1_ppc64el.deb ... 342s Unpacking libnbd0 (1.20.1-1) ... 342s Selecting previously unselected package libdaxctl1:ppc64el. 342s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 342s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 342s Selecting previously unselected package libndctl6:ppc64el. 342s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 342s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 342s Selecting previously unselected package libpmem1:ppc64el. 342s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 342s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 342s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 342s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 342s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 342s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 342s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 342s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 342s Selecting previously unselected package librados2. 342s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 342s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 342s Selecting previously unselected package libpmemobj1:ppc64el. 342s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 342s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 342s Selecting previously unselected package librbd1. 342s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 342s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 342s Selecting previously unselected package fio. 342s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 342s Unpacking fio (3.37-1) ... 342s Selecting previously unselected package lsscsi. 342s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 342s Unpacking lsscsi (0.32-1build1) ... 342s Selecting previously unselected package autopkgtest-satdep. 342s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 342s Unpacking autopkgtest-satdep (0) ... 343s Setting up libconfig-general-perl (2.65-2) ... 343s Setting up libisns0t64:ppc64el (0.101-1) ... 343s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 343s Setting up libnbd0 (1.20.1-1) ... 343s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 343s Setting up libglusterfs0:ppc64el (11.1-4ubuntu1) ... 343s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 343s Setting up lsscsi (0.32-1build1) ... 343s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 343s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 343s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 343s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 343s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 343s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 343s Setting up libgfxdr0:ppc64el (11.1-4ubuntu1) ... 343s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 343s Setting up open-iscsi (2.1.10-1ubuntu1) ... 344s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 345s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 345s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 345s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 345s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 345s Setting up libgfrpc0:ppc64el (11.1-4ubuntu1) ... 345s Setting up libgfapi0:ppc64el (11.1-4ubuntu1) ... 345s Setting up fio (3.37-1) ... 345s Setting up autopkgtest-satdep (0) ... 345s Processing triggers for man-db (2.12.1-2) ... 346s Processing triggers for initramfs-tools (0.142ubuntu28) ... 346s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 346s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 353s Processing triggers for libc-bin (2.39-3.1ubuntu2) ... 356s (Reading database ... 72931 files and directories currently installed.) 356s Removing autopkgtest-satdep (0) ... 358s autopkgtest [00:16:53]: test tgtbasedmpaths: [----------------------- 358s + targetname=iqn.2016-11.foo.com:target.iscsi 358s + pwd 358s + cwd=/tmp/autopkgtest.JmD6uY/build.uPi/src 358s + testdir=/mnt/tgtmpathtest 358s + localhost=127.0.0.1 358s + portal=127.0.0.1:3260 358s + maxpaths=4 358s + backfn=backingfile 358s + expectwwid=60000000000000000e00000000010001 358s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 358s + bglog=/tmp/autopkgtest.JmD6uY/tgtbasedmpaths-artifacts/test-background.log 358s + fioprep=/tmp/autopkgtest.JmD6uY/tgtbasedmpaths-artifacts/path-change-prep.fio 358s + fiovrfy=/tmp/autopkgtest.JmD6uY/tgtbasedmpaths-artifacts/path-change-check.fio 358s + service tgt restart 359s + truncate --size 100M backingfile 359s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 359s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 359s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.JmD6uY/build.uPi/src/backingfile 359s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 359s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 359s login #1 359s + echo login #1 359s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 359s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 359s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 359s + seq 2 4 359s extra login #2 359s + echo extra login #2 359s + iscsiadm --mode session -r 1 --op new 359s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 359s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 359s extra login #3 359s + echo extra login #3 359s + iscsiadm --mode session -r 1 --op new 359s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 359s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 359s extra login #4 359s + echo extra login #4 359s + iscsiadm --mode session -r 1 --op new 359s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 359s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 359s + udevadm settle 359s + sleep 5 364s Status after initial setup 364s + echo Status after initial setup 364s + tgtadm --lld iscsi --mode target --op show 364s Target 1: iqn.2016-11.foo.com:target.iscsi 364s System information: 364s Driver: iscsi 364s State: ready 364s I_T nexus information: 364s I_T nexus: 1 364s Initiator: iqn.2004-10.com.ubuntu:01:5312d5c7f8a6 alias: autopkgtest 364s Connection: 0 364s IP Address: 127.0.0.1 364s I_T nexus: 2 364s Initiator: iqn.2004-10.com.ubuntu:01:5312d5c7f8a6 alias: autopkgtest 364s Connection: 0 364s IP Address: 127.0.0.1 364s I_T nexus: 3 364s Initiator: iqn.2004-10.com.ubuntu:01:5312d5c7f8a6 alias: autopkgtest 364s Connection: 0 364s IP Address: 127.0.0.1 364s I_T nexus: 4 364s Initiator: iqn.2004-10.com.ubuntu:01:5312d5c7f8a6 alias: autopkgtest 364s Connection: 0 364s IP Address: 127.0.0.1 364s LUN information: 364s LUN: 0 364s Type: controller 364s SCSI ID: IET 00010000 364s SCSI SN: beaf10 364s Size: 0 MB, Block size: 1 364s Online: Yes 364s Removable media: No 364s Prevent removal: No 364s Readonly: No 364s SWP: No 364s Thin-provisioning: No 364s Backing store type: null 364s Backing store path: None 364s Backing store flags: 364s LUN: 1 364s Type: disk 364s SCSI ID: IET 00010001 364s SCSI SN: beaf11 364s Size: 105 MB, Block size: 512 364s Online: Yes 364s Removable media: No 364s Prevent removal: No 364s Readonly: No 364s SWP: No 364s Thin-provisioning: No 364s Backing store type: rdwr 364s Backing store path: /tmp/autopkgtest.JmD6uY/build.uPi/src/backingfile 364s Backing store flags: 364s Account information: 364s ACL information: 364s ALL 364s + tgtadm --lld iscsi --op show --mode conn --tid 1 364s Session: 4 364s Connection: 0 364s Initiator: iqn.2004-10.com.ubuntu:01:5312d5c7f8a6 364s IP Address: 127.0.0.1 364s Session: 3 364s Connection: 0 364s Initiator: iqn.2004-10.com.ubuntu:01:5312d5c7f8a6 364s IP Address: 127.0.0.1 364s Session: 2 364s Connection: 0 364s Initiator: iqn.2004-10.com.ubuntu:01:5312d5c7f8a6 364s IP Address: 127.0.0.1 364s Session: 1 364s Connection: 0 364s Initiator: iqn.2004-10.com.ubuntu:01:5312d5c7f8a6 364s IP Address: 127.0.0.1 364s + iscsiadm --mode session -P 1 364s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 364s Current Portal: 127.0.0.1:3260,1 364s Persistent Portal: 127.0.0.1:3260,1 364s ********** 364s Interface: 364s ********** 364s Iface Name: default 364s Iface Transport: tcp 364s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:5312d5c7f8a6 364s Iface IPaddress: 127.0.0.1 364s Iface HWaddress: default 364s Iface Netdev: default 364s SID: 1 364s iSCSI Connection State: LOGGED IN 364s iSCSI Session State: LOGGED_IN 364s Internal iscsid Session State: NO CHANGE 364s 364s ********** 364s Interface: 364s ********** 364s Iface Name: default 364s Iface Transport: tcp 364s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:5312d5c7f8a6 364s Iface IPaddress: 127.0.0.1 364s Iface HWaddress: default 364s Iface Netdev: default 364s SID: 2 364s iSCSI Connection State: LOGGED IN 364s iSCSI Session State: LOGGED_IN 364s Internal iscsid Session State: NO CHANGE 364s 364s ********** 364s Interface: 364s ********** 364s Iface Name: default 364s Iface Transport: tcp 364s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:5312d5c7f8a6 364s Iface IPaddress: 127.0.0.1 364s Iface HWaddress: default 364s Iface Netdev: default 364s SID: 3 364s iSCSI Connection State: LOGGED IN 364s iSCSI Session State: LOGGED_IN 364s Internal iscsid Session State: NO CHANGE 364s 364s ********** 364s Interface: 364s ********** 364s Iface Name: default 364s Iface Transport: tcp 364s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:5312d5c7f8a6 364s Iface IPaddress: 127.0.0.1 364s Iface HWaddress: default 364s Iface Netdev: default 364s SID: 4 364s iSCSI Connection State: LOGGED IN 364s iSCSI Session State: LOGGED_IN 364s Internal iscsid Session State: NO CHANGE 364s + lsscsi -liv 364s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 364s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 364s 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] 364s [1:0:0:0] storage IET Controller 0001 - - 364s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 364s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 364s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 364s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 364s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 364s [2:0:0:0] storage IET Controller 0001 - - 364s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 364s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 364s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 364s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 364s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 364s [3:0:0:0] storage IET Controller 0001 - - 364s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 364s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 364s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 364s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 364s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 364s [4:0:0:0] storage IET Controller 0001 - - 364s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 364s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 364s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 364s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 364s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 364s NVMe module may not be loaded 364s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 364s + multipath -v3 -ll 364s 78.728972 | set open fds limit to 1048576/1048576 364s 78.729097 | loading /lib/multipath/libchecktur.so checker 364s 78.729196 | checker tur: message table size = 3 364s 78.729204 | loading /lib/multipath/libprioconst.so prioritizer 364s 78.729318 | _init_foreign: foreign library "nvme" is not enabled 364s 78.734720 | sda: size = 167772160 364s 78.734933 | sda: vendor = QEMU 364s 78.735003 | sda: product = QEMU HARDDISK 364s 78.735053 | sda: rev = 2.5+ 364s 78.735687 | sda: h:b:t:l = 0:0:0:0 364s 78.736051 | sda: tgt_node_name = 364s 78.736104 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 364s 78.736128 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 364s 78.736306 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 364s 78.736351 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 364s 78.736385 | __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 364s 78.736441 | failed to read sysfs vpd pg80: No such file or directory 364s 78.736631 | sda: fail to get serial 364s 78.736674 | sda: detect_checker = yes (setting: multipath internal) 364s 78.736839 | sda: path_checker = tur (setting: multipath internal) 364s 78.736883 | sda: checker timeout = 30 s (setting: kernel sysfs) 364s 78.737001 | sda: tur state = up 364s 78.737334 | sdb: size = 204800 364s 78.737509 | sdb: vendor = IET 364s 78.737576 | sdb: product = VIRTUAL-DISK 364s 78.737622 | sdb: rev = 0001 364s 78.738272 | sdb: h:b:t:l = 1:0:0:1 364s 78.738656 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 364s 78.738702 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 364s 78.738724 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 364s 78.738913 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 364s 78.738957 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 364s 78.738995 | sdb: serial = beaf11 364s 78.739036 | sdb: detect_checker = yes (setting: multipath internal) 364s 78.739330 | sdb: path_checker = tur (setting: multipath internal) 364s 78.739376 | sdb: checker timeout = 30 s (setting: kernel sysfs) 364s 78.739552 | sdb: tur state = up 364s 78.739717 | sdc: size = 204800 364s 78.739892 | sdc: vendor = IET 364s 78.739957 | sdc: product = VIRTUAL-DISK 364s 78.740025 | sdc: rev = 0001 364s 78.740723 | sdc: h:b:t:l = 2:0:0:1 364s 78.741101 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 364s 78.741145 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 364s 78.741168 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 364s 78.741340 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 364s 78.741384 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 364s 78.741424 | sdc: serial = beaf11 364s 78.741465 | sdc: detect_checker = yes (setting: multipath internal) 364s 78.741679 | sdc: path_checker = tur (setting: multipath internal) 364s 78.741723 | sdc: checker timeout = 30 s (setting: kernel sysfs) 364s 78.741887 | sdc: tur state = up 364s 78.742054 | sdd: size = 204800 364s 78.742230 | sdd: vendor = IET 364s 78.742296 | sdd: product = VIRTUAL-DISK 364s 78.742344 | sdd: rev = 0001 364s 78.743059 | sdd: h:b:t:l = 3:0:0:1 364s 78.743441 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 364s 78.743486 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 364s 78.743508 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 364s 78.743680 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 364s 78.743725 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 364s 78.743761 | sdd: serial = beaf11 364s 78.743785 | sdd: detect_checker = yes (setting: multipath internal) 364s 78.743960 | sdd: path_checker = tur (setting: multipath internal) 364s 78.743987 | sdd: checker timeout = 30 s (setting: kernel sysfs) 364s 78.744189 | sdd: tur state = up 364s 78.744358 | sde: size = 204800 364s 78.744532 | sde: vendor = IET 364s 78.744597 | sde: product = VIRTUAL-DISK 364s 78.744643 | sde: rev = 0001 364s 78.745343 | sde: h:b:t:l = 4:0:0:1 364s 78.745720 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 364s 78.745764 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 364s 78.745787 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 364s 78.745967 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 364s 78.746012 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 364s 78.746049 | sde: serial = beaf11 364s 78.746072 | sde: detect_checker = yes (setting: multipath internal) 364s 78.746295 | sde: path_checker = tur (setting: multipath internal) 364s 78.746340 | sde: checker timeout = 30 s (setting: kernel sysfs) 364s 78.746458 | sde: tur state = up 364s 78.746588 | loop0: device node name blacklisted 364s 78.746717 | loop1: device node name blacklisted 364s 78.746843 | loop2: device node name blacklisted 364s 78.746983 | loop3: device node name blacklisted 364s 78.747110 | loop4: device node name blacklisted 364s 78.747235 | loop5: device node name blacklisted 364s 78.747361 | loop6: device node name blacklisted 364s 78.747485 | loop7: device node name blacklisted 364s 78.747618 | dm-0: device node name blacklisted 364s 78.748600 | multipath-tools v0.9.4 (12/19, 2022) 364s 78.748660 | libdevmapper version 1.02.185 364s 78.748808 | kernel device mapper v4.48.0 364s 78.748860 | DM multipath kernel driver v1.14.0 364s 78.748984 | sdb: size = 204800 364s 78.749029 | sdb: vendor = IET 364s 78.749052 | sdb: product = VIRTUAL-DISK 364s 78.749075 | sdb: rev = 0001 364s 78.749706 | sdb: h:b:t:l = 1:0:0:1 364s 78.749863 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 364s 78.749924 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 364s 78.749948 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 364s 78.749982 | sdb: serial = beaf11 364s 78.750212 | sdb: tur state = up 364s 78.750256 | sdb: uid = 360000000000000000e00000000010001 (udev) 364s 78.750279 | sdb: detect_prio = yes (setting: multipath internal) 364s 78.750303 | sdb: prio = const (setting: multipath internal) 364s 78.750324 | sdb: prio args = "" (setting: multipath internal) 364s 78.750346 | sdb: const prio = 1 364s 78.750391 | sdc: size = 204800 364s 78.750434 | sdc: vendor = IET 364s 78.750456 | sdc: product = VIRTUAL-DISK 364s 78.750480 | sdc: rev = 0001 364s 78.751110 | sdc: h:b:t:l = 2:0:0:1 364s 78.751268 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 364s 78.751329 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 364s 78.751353 | ===== paths list ===== 364s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 364s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 364s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 364s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 364s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 364s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 364s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 364s size=100M features='0' hwhandler='0' wp=rw 364s |-+- policy='service-time 0' prio=1 status=active 364s | `- 1:0:0:1 sdb 8:16 active ready running 364s |-+- policy='service-time 0' prio=1 status=enabled 364s | `- 2:0:0:1 sdc 8:32 active ready running 364s |-+- policy='service-time 0' prio=1 status=enabled 364s | `- 3:0:0:1 sdd 8:48 active ready running 364s `-+- policy='service-time 0' prio=1 status=enabled 364s `- 4:0:0:1 sde 8:64 active ready running 364s 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 364s Test WWN should now point to DM 364s ../../dm-0 364s Creating filesystem with 25600 4k blocks and 25600 inodes 364s 364s Allocating group tables: 0/1 done 364s Writing inode tables: 0/1 done 364s Creating journal (1024 blocks): sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 364s 78.751386 | sdc: serial = beaf11 364s 78.751585 | sdc: tur state = up 364s 78.751627 | sdc: uid = 360000000000000000e00000000010001 (udev) 364s 78.751650 | sdc: detect_prio = yes (setting: multipath internal) 364s 78.751673 | sdc: prio = const (setting: multipath internal) 364s 78.751694 | sdc: prio args = "" (setting: multipath internal) 364s 78.751716 | sdc: const prio = 1 364s 78.751742 | sdd: size = 204800 364s 78.751746 | sdd: vendor = IET 364s 78.751749 | sdd: product = VIRTUAL-DISK 364s 78.751751 | sdd: rev = 0001 364s 78.752380 | sdd: h:b:t:l = 3:0:0:1 364s 78.752492 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 364s 78.752510 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 364s 78.752512 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 364s 78.752524 | sdd: serial = beaf11 364s 78.752686 | sdd: tur state = up 364s 78.752692 | sdd: uid = 360000000000000000e00000000010001 (udev) 364s 78.752695 | sdd: detect_prio = yes (setting: multipath internal) 364s 78.752697 | sdd: prio = const (setting: multipath internal) 364s 78.752699 | sdd: prio args = "" (setting: multipath internal) 364s 78.752701 | sdd: const prio = 1 364s 78.752724 | sde: size = 204800 364s 78.752728 | sde: vendor = IET 364s 78.752730 | sde: product = VIRTUAL-DISK 364s 78.752732 | sde: rev = 0001 364s 78.753323 | sde: h:b:t:l = 4:0:0:1 364s 78.753428 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 364s 78.753446 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 364s 78.753448 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 364s 78.753460 | sde: serial = beaf11 364s 78.753588 | sde: tur state = up 364s 78.753595 | sde: uid = 360000000000000000e00000000010001 (udev) 364s 78.753597 | sde: detect_prio = yes (setting: multipath internal) 364s 78.753600 | sde: prio = const (setting: multipath internal) 364s 78.753602 | sde: prio args = "" (setting: multipath internal) 364s 78.753604 | sde: const prio = 1 364s 78.754540 | unloading tur checker 364s 78.754588 | unloading const prioritizer 364s + dmsetup table 364s + echo Test WWN should now point to DM 364s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 364s + grep dm 364s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 364s mke2fs 1.47.1 (20-May-2024) 364s done 364s Writing superblocks and filesystem accounting information: 0/1 done 364s 364s + udevadm settle 364s + sleep 3s 367s + mkdir -p /mnt/tgtmpathtest 367s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 367s + cat 367s + cat 367s + fio --max-jobs=4 /tmp/autopkgtest.JmD6uY/tgtbasedmpaths-artifacts/path-change-prep.fio 367s 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 367s fio-3.37 367s Starting 1 thread 367s write-phase: Laying out IO file (1 file / 17592186044415MiB) 368s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91750400, buflen=65536 368s 368s write-phase: (groupid=0, jobs=1): err= 0: pid=7110: Sat Jun 29 00:17:03 2024 368s write: IOPS=1584, BW=99.0MiB/s (104MB/s)(87.5MiB/884msec); 0 zone resets 368s clat (usec): min=411, max=5147, avg=609.31, stdev=186.19 368s lat (usec): min=431, max=5162, avg=629.63, stdev=186.21 368s clat percentiles (usec): 368s | 1.00th=[ 437], 5.00th=[ 465], 10.00th=[ 486], 20.00th=[ 510], 368s | 30.00th=[ 553], 40.00th=[ 578], 50.00th=[ 594], 60.00th=[ 611], 368s | 70.00th=[ 627], 80.00th=[ 644], 90.00th=[ 685], 95.00th=[ 766], 368s | 99.00th=[ 1303], 99.50th=[ 1434], 99.90th=[ 1811], 99.95th=[ 5145], 368s | 99.99th=[ 5145] 368s bw ( KiB/s): min=96574, max=96574, per=95.28%, avg=96574.00, stdev= 0.00, samples=1 368s iops : min= 1508, max= 1508, avg=1508.00, stdev= 0.00, samples=1 368s lat (usec) : 500=15.99%, 750=78.59%, 1000=2.50% 368s lat (msec) : 2=2.78%, 10=0.07% 368s cpu : usr=3.51%, sys=7.02%, ctx=1402, majf=0, minf=0 368s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 368s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 368s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 368s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 368s latency : target=0, window=0, percentile=100.00%, depth=1 368s 368s Run status group 0 (all jobs): 368s WRITE: bw=99.0MiB/s (104MB/s), 99.0MiB/s-99.0MiB/s (104MB/s-104MB/s), io=87.5MiB (91.8MB), run=884-884msec 368s 368s Disk stats (read/write): 368s dm-0: ios=1/989, sectors=8/126592, merge=0/0, ticks=1/651, in_queue=652, util=87.03%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/204, aggrin_queue=204, aggrutil=88.80% 368s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 368s sdb: ios=1/1402, sectors=8/179280, merge=0/0, ticks=1/818, in_queue=819, util=88.80% 368s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 368s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 368s + echo Starting the path changes in background 368s Starting the path changes in background 368s + date +Pre FIO %H:%M:%S.%N 368s + fio --max-jobs=4 /tmp/autopkgtest.JmD6uY/tgtbasedmpaths-artifacts/path-change-check.fio 368s Pre FIO 00:17:03.770342163 368s 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 368s fio-3.37 368s Starting 1 thread 549s 549s verify-phase: (groupid=0, jobs=1): err= 0: pid=7117: Sat Jun 29 00:20:04 2024 549s read: IOPS=3368, BW=211MiB/s (221MB/s)(37.0GiB/180001msec) 549s clat (usec): min=84, max=64094, avg=273.51, stdev=238.20 549s lat (usec): min=84, max=64094, avg=273.62, stdev=238.20 549s clat percentiles (usec): 549s | 1.00th=[ 100], 5.00th=[ 151], 10.00th=[ 174], 20.00th=[ 194], 549s | 30.00th=[ 210], 40.00th=[ 225], 50.00th=[ 251], 60.00th=[ 285], 549s | 70.00th=[ 314], 80.00th=[ 343], 90.00th=[ 388], 95.00th=[ 429], 549s | 99.00th=[ 523], 99.50th=[ 881], 99.90th=[ 1434], 99.95th=[ 1893], 549s | 99.99th=[ 3720] 549s bw ( KiB/s): min=111744, max=400640, per=99.97%, avg=215534.23, stdev=51013.59, samples=359 549s iops : min= 1746, max= 6260, avg=3367.69, stdev=797.08, samples=359 549s lat (usec) : 100=1.01%, 250=48.97%, 500=48.83%, 750=0.58%, 1000=0.24% 549s lat (msec) : 2=0.33%, 4=0.04%, 10=0.01%, 20=0.01%, 50=0.01% 549s lat (msec) : 100=0.01% 549s cpu : usr=9.55%, sys=6.56%, ctx=606492, majf=0, minf=1 549s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 549s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 549s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 549s issued rwts: total=606393,0,0,0 short=0,0,0,0 dropped=0,0,0,0 549s latency : target=0, window=0, percentile=100.00%, depth=1 549s 549s Run status group 0 (all jobs): 549s READ: bw=211MiB/s (221MB/s), 211MiB/s-211MiB/s (221MB/s-221MB/s), io=37.0GiB (39.7GB), run=180001-180001msec 549s 549s Disk stats (read/write): 549s dm-0: ios=606307/10, sectors=77548856/12928, merge=10/9, ticks=168343/76, in_queue=168469, util=100.00%, aggrios=38526/2, aggsectors=4926990/3232, aggrmerge=0/0, aggrticks=10802/6, aggrin_queue=10808, aggrutil=99.13% 549s sdd: ios=28152/0, sectors=3600896/0, merge=0/0, ticks=8688/0, in_queue=8688, util=32.84% 549s sdb: ios=32244/9, sectors=4124032/12928, merge=0/0, ticks=8475/26, in_queue=8501, util=99.13% 549s sde: ios=66005/0, sectors=8442624/0, merge=0/0, ticks=17209/0, in_queue=17209, util=39.54% 549s sdc: ios=27704/0, sectors=3540408/0, merge=0/0, ticks=8837/0, in_queue=8837, util=49.98% 549s + date +Post FIO %H:%M:%S.%N 549s Post FIO 00:20:04.120288274 549s FIO verify test with changing paths - OK 549s Report log of background activity 549s + echo FIO verify test with changing paths - OK 549s + echo Report log of background activity 549s + cat /tmp/autopkgtest.JmD6uY/tgtbasedmpaths-artifacts/test-background.log 549s + iscsiadm --mode session 549s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s + sleep 10s 549s + date +MP report (expect 4) %H:%M:%S.%N 549s MP report (expect 4) 00:17:13.777128372 549s + multipath -ll 549s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 549s size=100M features='0' hwhandler='0' wp=rw 549s |-+- policy='service-time 0' prio=1 status=active 549s | `- 1:0:0:1 sdb 8:16 active ready running 549s |-+- policy='service-time 0' prio=1 status=enabled 549s | `- 2:0:0:1 sdc 8:32 active ready running 549s |-+- policy='service-time 0' prio=1 status=enabled 549s | `- 3:0:0:1 sdd 8:48 active ready running 549s `-+- policy='service-time 0' prio=1 status=enabled 549s `- 4:0:0:1 sde 8:64 active ready running 549s + date +UN-plug path 1 %H:%M:%S.%N 549s UN-plug path 1 00:17:13.805091279 549s + iscsiadm --mode session -r 1 -u 549s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 549s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 549s + iscsiadm --mode session 549s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s + sleep 10s 549s + date +MP report (expect 3) %H:%M:%S.%N 549s MP report (expect 3) 00:17:23.930672331 549s + multipath -ll 549s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 549s size=100M features='0' hwhandler='0' wp=rw 549s |-+- policy='service-time 0' prio=1 status=active 549s | `- 2:0:0:1 sdc 8:32 active ready running 549s |-+- policy='service-time 0' prio=1 status=enabled 549s | `- 3:0:0:1 sdd 8:48 active ready running 549s `-+- policy='service-time 0' prio=1 status=enabled 549s `- 4:0:0:1 sde 8:64 active ready running 549s + date +UN-plug path 2 %H:%M:%S.%N 549s UN-plug path 2 00:17:23.952644169 549s + iscsiadm --mode session -r 2 -u 549s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 549s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 549s + iscsiadm --mode session 549s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s + sleep 10s 549s + date +MP report (expect 2) %H:%M:%S.%N 549s MP report (expect 2) 00:17:34.028861718 549s + multipath -ll 549s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 549s size=100M features='0' hwhandler='0' wp=rw 549s |-+- policy='service-time 0' prio=1 status=active 549s | `- 3:0:0:1 sdd 8:48 active ready running 549s `-+- policy='service-time 0' prio=1 status=enabled 549s `- 4:0:0:1 sde 8:64 active ready running 549s + date +UN-plug path 3 %H:%M:%S.%N 549s UN-plug path 3 00:17:34.046802982 549s + iscsiadm --mode session -r 3 -u 549s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 549s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 549s + iscsiadm --mode session 549s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s + sleep 10s 549s + date +MP report (expect 1) %H:%M:%S.%N 549s MP report (expect 1) 00:17:44.112743076 549s + multipath -ll 549s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 549s size=100M features='0' hwhandler='0' wp=rw 549s `-+- policy='service-time 0' prio=1 status=active 549s `- 4:0:0:1 sde 8:64 active ready running 549s + date +Add paths 5/6/7/8 %H:%M:%S.%N 549s Add paths 5/6/7/8 00:17:44.127907596 549s + iscsiadm --mode session -r 4 --op new 549s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 549s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 549s + iscsiadm --mode session -r 4 --op new 549s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 549s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 549s + iscsiadm --mode session -r 4 --op new 549s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 549s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 549s + iscsiadm --mode session -r 4 --op new 549s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 549s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 549s + iscsiadm --mode session 549s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s + sleep 10s 549s + date +MP report (expect 5) %H:%M:%S.%N 549s MP report (expect 5) 00:17:54.241167833 549s + multipath -ll 549s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 549s size=100M features='0' hwhandler='0' wp=rw 549s |-+- policy='service-time 0' prio=1 status=active 549s | `- 4:0:0:1 sde 8:64 active ready running 549s |-+- policy='service-time 0' prio=1 status=enabled 549s | `- 1:0:0:1 sdb 8:16 active ready running 549s |-+- policy='service-time 0' prio=1 status=enabled 549s | `- 2:0:0:1 sdc 8:32 active ready running 549s |-+- policy='service-time 0' prio=1 status=enabled 549s | `- 3:0:0:1 sdd 8:48 active ready running 549s `-+- policy='service-time 0' prio=1 status=enabled 549s `- 5:0:0:1 sdf 8:80 active ready running 549s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 549s UN-plug multiple paths 4/7/8 00:17:54.272268318 549s + iscsiadm --mode session -r 4 -u 549s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 549s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 549s + iscsiadm --mode session -r 7 -u 549s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 549s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 549s + iscsiadm --mode session -r 8 -u 549s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 549s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 549s + iscsiadm --mode session 549s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 549s + sleep 10s 549s + date +Restart multipath daemon %H:%M:%S.%N 549s Restart multipath daemon 00:18:04.538274969 549s + systemctl restart multipathd 549s + sleep 10s 549s + date +Final background report (expect 2) %H:%M:%S.%N 549s Final background report (expect 2) 00:18:14.631028223 549s + multipath -ll 549s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 549s size=100M features='0' hwhandler='0' wp=rw 549s |-+- policy='service-time 0' prio=1 status=active 549s | `- 1:0:0:1 sdb 8:16 active ready running 549s `-+- policy='service-time 0' prio=1 status=enabled 549s `- 2:0:0:1 sdc 8:32 active ready running 549s Final stats 549s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 549s iSCSI SNMP: 549s txdata_octets: 21672024 549s rxdata_octets: 29566403780 549s noptx_pdus: 0 549s scsicmd_pdus: 451233 549s tmfcmd_pdus: 0 549s login_pdus: 0 549s text_pdus: 0 549s dataout_pdus: 0 549s logout_pdus: 0 549s snack_pdus: 0 549s noprx_pdus: 0 549s scsirsp_pdus: 451233 549s tmfrsp_pdus: 0 549s textrsp_pdus: 0 549s datain_pdus: 451199 549s logoutrsp_pdus: 0 549s r2t_pdus: 0 549s async_pdus: 0 549s rjt_pdus: 0 549s digest_err: 0 549s timeout_err: 0 549s iSCSI Extended: 549s tx_sendpage_failures: 0 549s rx_discontiguous_hdr: 0 549s eh_abort_cnt: 0 549s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 549s iSCSI SNMP: 549s txdata_octets: 6552 549s rxdata_octets: 1515012 549s noptx_pdus: 0 549s scsicmd_pdus: 106 549s tmfcmd_pdus: 0 549s login_pdus: 0 549s text_pdus: 0 549s dataout_pdus: 0 549s logout_pdus: 0 549s snack_pdus: 0 549s noprx_pdus: 0 549s scsirsp_pdus: 106 549s tmfrsp_pdus: 0 549s textrsp_pdus: 0 549s datain_pdus: 83 549s logoutrsp_pdus: 0 549s r2t_pdus: 0 549s async_pdus: 0 549s rjt_pdus: 0 549s digest_err: 0 549s timeout_err: 0 549s iSCSI Extended: 549s tx_sendpage_failures: 0 549s rx_discontiguous_hdr: 0 549s eh_abort_cnt: 0 549s Jun 28 19:54:38 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 549s Jun 28 19:54:38 ubuntu multipathd[327]: multipathd v0.9.4: start up 549s Jun 28 19:54:38 ubuntu multipathd[327]: reconfigure: setting up paths and maps 549s Jun 28 19:54:38 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 549s Jun 28 19:57:17 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 multipathd[327]: multipathd: shut down 549s Jun 28 19:57:17 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 549s Jun 28 19:57:17 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: multipathd.service: Deactivated successfully. 549s Jun 28 19:57:17 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 549s -- Boot 90b6ecf47e98464cae7c791120c2bc97 -- 549s Jun 28 19:57:45 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 549s Jun 28 19:57:45 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 multipathd[277]: multipathd v0.9.4: start up 549s Jun 28 19:57:45 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 multipathd[277]: reconfigure: setting up paths and maps 549s Jun 28 19:57:45 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 549s Jun 28 19:58:10 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 multipathd[277]: multipathd: shut down 549s Jun 28 19:58:10 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 549s Jun 28 19:58:10 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: multipathd.service: Deactivated successfully. 549s Jun 28 19:58:10 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 549s -- Boot 82b801d4c8724f29beafaa9453bb222a -- 549s Jun 29 00:15:43 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 549s Jun 29 00:15:43 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 multipathd[331]: multipathd v0.9.4: start up 549s Jun 29 00:15:43 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 multipathd[331]: reconfigure: setting up paths and maps 549s Jun 29 00:15:43 auto-syncubuntu-oracular-daily-ppc64el-server-20240622-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 549s Jun 29 00:16:54 autopkgtest multipathd[331]: 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] 549s Jun 29 00:16:54 autopkgtest multipathd[331]: sdc [8:32]: path added to devmap mpatha 549s Jun 29 00:16:54 autopkgtest multipathd[331]: mpatha: performing delayed actions 549s Jun 29 00:16:54 autopkgtest multipathd[331]: 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] 549s Jun 29 00:17:13 autopkgtest multipathd[331]: 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] 549s Jun 29 00:17:13 autopkgtest multipathd[331]: check_removed_paths: sdb: freeing path in removed state 549s Jun 29 00:17:13 autopkgtest multipathd[331]: 8:16: path removed from map mpatha 549s Jun 29 00:17:23 autopkgtest multipathd[331]: 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] 549s Jun 29 00:17:24 autopkgtest multipathd[331]: check_removed_paths: sdc: freeing path in removed state 549s Jun 29 00:17:24 autopkgtest multipathd[331]: 8:32: path removed from map mpatha 549s Jun 29 00:17:34 autopkgtest multipathd[331]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 549s Jun 29 00:17:34 autopkgtest multipathd[331]: check_removed_paths: sdd: freeing path in removed state 549s Jun 29 00:17:34 autopkgtest multipathd[331]: 8:48: path removed from map mpatha 549s Jun 29 00:17:44 autopkgtest multipathd[331]: 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] 549s Jun 29 00:17:44 autopkgtest multipathd[331]: sdb [8:16]: path added to devmap mpatha 549s Jun 29 00:17:44 autopkgtest multipathd[331]: 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] 549s Jun 29 00:17:44 autopkgtest multipathd[331]: sdc [8:32]: path added to devmap mpatha 549s Jun 29 00:17:44 autopkgtest multipathd[331]: 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] 549s Jun 29 00:17:44 autopkgtest multipathd[331]: sdd [8:48]: path added to devmap mpatha 549s Jun 29 00:17:44 autopkgtest multipathd[331]: 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] 549s Jun 29 00:17:44 autopkgtest multipathd[331]: sdf [8:80]: path added to devmap mpatha 549s Jun 29 00:17:54 autopkgtest multipathd[331]: 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] 549s Jun 29 00:17:54 autopkgtest multipathd[331]: check_removed_paths: sde: freeing path in removed state 549s Jun 29 00:17:54 autopkgtest multipathd[331]: 8:64: path removed from map mpatha 549s Jun 29 00:17:54 autopkgtest multipathd[331]: 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] 549s Jun 29 00:17:54 autopkgtest multipathd[331]: check_removed_paths: sdd: freeing path in removed state 549s Jun 29 00:17:54 autopkgtest multipathd[331]: 8:48: path removed from map mpatha 549s Jun 29 00:17:54 autopkgtest multipathd[331]: 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] 549s Jun 29 00:17:54 autopkgtest multipathd[331]: check_removed_paths: sdf: freeing path in removed state 549s Jun 29 00:17:54 autopkgtest multipathd[331]: 8:80: path removed from map mpatha 549s Jun 29 00:18:04 autopkgtest multipathd[331]: multipathd: shut down 549s Jun 29 00:18:04 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 549s Jun 29 00:18:04 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 549s Jun 29 00:18:04 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 549s Jun 29 00:18:04 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 549s Jun 29 00:18:04 autopkgtest multipathd[7472]: multipathd v0.9.4: start up 549s Jun 29 00:18:04 autopkgtest multipathd[7472]: reconfigure: setting up paths and maps 549s Jun 29 00:18:04 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 549s Check final path status 549s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 549s size=100M features='0' hwhandler='0' wp=rw 549s |-+- policy='service-time 0' prio=1 status=active 549s | `- 1:0:0:1 sdb 8:16 active ready running 549s `-+- policy='service-time 0' prio=1 status=enabled 549s `- 2:0:0:1 sdc 8:32 active ready running 549s + sync 549s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 549s + echo Final stats 549s + iscsiadm --mode session --stats 549s + journalctl --no-pager -u multipathd 549s + echo Check final path status 549s + multipath -ll 549s + multipath -ll 549s + grep --count status= 549s + diskc=2 549s + multipath -ll 549s + grep --count status=active 549s + diska=1 549s + multipath -ll 549s + grep --count status=enabled 549s OK 549s + diske=1 549s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 549s + echo OK 549s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 549s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 549s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 549s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 549s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 549s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 549s autopkgtest [00:20:04]: test tgtbasedmpaths: -----------------------] 550s autopkgtest [00:20:05]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 550s tgtbasedmpaths PASS 550s autopkgtest [00:20:05]: @@@@@@@@@@@@@@@@@@@@ summary 550s kpartx-file-loopback PASS 550s tgtbasedmpaths PASS 562s nova [W] Using flock in scalingstack-bos02-ppc64el 562s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240629-001055-juju-7f2275-prod-proposed-migration-environment-2-eb5b5eb1-c2c1-4b90-9517-a89c4f56c9c9 from image adt/ubuntu-oracular-ppc64el-server-20240628.img (UUID 80a6f9a9-e36d-49d4-a48c-ef254216269f)... 562s nova [W] Using flock in scalingstack-bos02-ppc64el 562s flock: timeout while waiting to get lock 562s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240629-001055-juju-7f2275-prod-proposed-migration-environment-2-eb5b5eb1-c2c1-4b90-9517-a89c4f56c9c9 from image adt/ubuntu-oracular-ppc64el-server-20240628.img (UUID 80a6f9a9-e36d-49d4-a48c-ef254216269f)...