0s autopkgtest [19:27:22]: starting date and time: 2024-06-10 19:27:22+0000 0s autopkgtest [19:27:22]: git checkout: 433ed4cb Merge branch 'skia/nova_flock' into 'ubuntu/5.34+prod' 0s autopkgtest [19:27:22]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.xlk6yz65/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-0ubuntu9 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos01-ppc64el-8.secgroup --name adt-oracular-ppc64el-multipath-tools-20240610-192722-juju-7f2275-prod-proposed-migration-environment-3-56b3f044-8cee-484a-b768-a18326eba5ec --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://us.ports.ubuntu.com/ubuntu-ports/ 104s autopkgtest [19:29:06]: testbed dpkg architecture: ppc64el 104s autopkgtest [19:29:06]: testbed apt version: 2.9.3 104s autopkgtest [19:29:06]: @@@@@@@@@@@@@@@@@@@@ test bed setup 106s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 106s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [46.4 kB] 106s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [1680 B] 106s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7972 B] 106s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [355 kB] 106s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [68.0 kB] 106s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1860 B] 106s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [319 kB] 107s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1768 B] 107s Fetched 911 kB in 1s (719 kB/s) 107s Reading package lists... 109s Reading package lists... 109s Building dependency tree... 109s Reading state information... 110s Calculating upgrade... 110s The following packages will be upgraded: 110s debianutils libc-bin libc-dev-bin libc-devtools libc6 libc6-dev 110s libgdbm-compat4t64 libgdbm6t64 libunwind8 locales python3-typing-extensions 110s tmux 110s 12 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 110s Need to get 11.3 MB of archives. 110s After this operation, 0 B of additional disk space will be used. 110s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el debianutils ppc64el 5.19 [90.5 kB] 110s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-devtools ppc64el 2.39-0ubuntu9 [29.6 kB] 110s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6-dev ppc64el 2.39-0ubuntu9 [2102 kB] 111s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-dev-bin ppc64el 2.39-0ubuntu9 [21.3 kB] 111s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6 ppc64el 2.39-0ubuntu9 [3275 kB] 112s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-bin ppc64el 2.39-0ubuntu9 [751 kB] 112s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el locales all 2.39-0ubuntu9 [4235 kB] 113s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgdbm6t64 ppc64el 1.23-6 [41.4 kB] 113s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgdbm-compat4t64 ppc64el 1.23-6 [6876 B] 113s Get:10 http://ftpmaster.internal/ubuntu oracular/main ppc64el libunwind8 ppc64el 1.6.2-3.1 [58.9 kB] 113s Get:11 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-typing-extensions all 4.12.2-1 [65.9 kB] 113s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el tmux ppc64el 3.4-6 [602 kB] 113s Preconfiguring packages ... 113s Fetched 11.3 MB in 3s (3859 kB/s) 113s (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 ... 72675 files and directories currently installed.) 113s Preparing to unpack .../debianutils_5.19_ppc64el.deb ... 113s Unpacking debianutils (5.19) over (5.18) ... 113s Setting up debianutils (5.19) ... 114s (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 ... 72675 files and directories currently installed.) 114s Preparing to unpack .../libc-devtools_2.39-0ubuntu9_ppc64el.deb ... 114s Unpacking libc-devtools (2.39-0ubuntu9) over (2.39-0ubuntu8.1) ... 114s Preparing to unpack .../libc6-dev_2.39-0ubuntu9_ppc64el.deb ... 114s Unpacking libc6-dev:ppc64el (2.39-0ubuntu9) over (2.39-0ubuntu8.1) ... 114s Preparing to unpack .../libc-dev-bin_2.39-0ubuntu9_ppc64el.deb ... 114s Unpacking libc-dev-bin (2.39-0ubuntu9) over (2.39-0ubuntu8.1) ... 114s Preparing to unpack .../libc6_2.39-0ubuntu9_ppc64el.deb ... 114s Unpacking libc6:ppc64el (2.39-0ubuntu9) over (2.39-0ubuntu8.1) ... 114s Setting up libc6:ppc64el (2.39-0ubuntu9) ... 115s (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 ... 72675 files and directories currently installed.) 115s Preparing to unpack .../libc-bin_2.39-0ubuntu9_ppc64el.deb ... 115s Unpacking libc-bin (2.39-0ubuntu9) over (2.39-0ubuntu8.1) ... 115s Setting up libc-bin (2.39-0ubuntu9) ... 115s (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 ... 72675 files and directories currently installed.) 115s Preparing to unpack .../0-locales_2.39-0ubuntu9_all.deb ... 115s Unpacking locales (2.39-0ubuntu9) over (2.39-0ubuntu8.1) ... 115s Preparing to unpack .../1-libgdbm6t64_1.23-6_ppc64el.deb ... 115s Unpacking libgdbm6t64:ppc64el (1.23-6) over (1.23-5.1build1) ... 115s Preparing to unpack .../2-libgdbm-compat4t64_1.23-6_ppc64el.deb ... 115s Unpacking libgdbm-compat4t64:ppc64el (1.23-6) over (1.23-5.1build1) ... 115s Preparing to unpack .../3-libunwind8_1.6.2-3.1_ppc64el.deb ... 115s Unpacking libunwind8:ppc64el (1.6.2-3.1) over (1.6.2-3build1) ... 115s Preparing to unpack .../4-python3-typing-extensions_4.12.2-1_all.deb ... 115s Unpacking python3-typing-extensions (4.12.2-1) over (4.12.1-1) ... 115s Preparing to unpack .../5-tmux_3.4-6_ppc64el.deb ... 115s Unpacking tmux (3.4-6) over (3.4-5) ... 115s Setting up libgdbm6t64:ppc64el (1.23-6) ... 115s Setting up libgdbm-compat4t64:ppc64el (1.23-6) ... 115s Setting up locales (2.39-0ubuntu9) ... 116s Generating locales (this might take a while)... 118s en_US.UTF-8... done 118s Generation complete. 118s Setting up libunwind8:ppc64el (1.6.2-3.1) ... 118s Setting up python3-typing-extensions (4.12.2-1) ... 118s Setting up libc-dev-bin (2.39-0ubuntu9) ... 118s Setting up tmux (3.4-6) ... 118s Setting up libc-devtools (2.39-0ubuntu9) ... 118s Setting up libc6-dev:ppc64el (2.39-0ubuntu9) ... 118s Processing triggers for libc-bin (2.39-0ubuntu9) ... 118s Processing triggers for man-db (2.12.1-2) ... 119s Processing triggers for debianutils (5.19) ... 120s Reading package lists... 120s Building dependency tree... 120s Reading state information... 120s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 120s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 121s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 121s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 121s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 122s Reading package lists... 122s Reading package lists... 122s Building dependency tree... 122s Reading state information... 122s Calculating upgrade... 122s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 122s Reading package lists... 123s Building dependency tree... 123s Reading state information... 123s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 126s autopkgtest [19:29:28]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 126s autopkgtest [19:29:28]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 130s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 130s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 130s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 130s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 130s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 130s gpgv: issuer "steve.langasek@ubuntu.com" 130s gpgv: Can't check signature: No public key 130s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 130s autopkgtest [19:29:32]: testing package multipath-tools version 0.9.4-5ubuntu8 131s autopkgtest [19:29:33]: build not needed 131s autopkgtest [19:29:33]: test kpartx-file-loopback: preparing testbed 133s Reading package lists... 133s Building dependency tree... 133s Reading state information... 133s Starting pkgProblemResolver with broken count: 0 133s Starting 2 pkgProblemResolver with broken count: 0 133s Done 133s The following additional packages will be installed: 133s liburing2 qemu-utils 133s Recommended packages: 133s qemu-block-extra 133s The following NEW packages will be installed: 133s autopkgtest-satdep liburing2 qemu-utils 133s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 133s Need to get 2330 kB/2331 kB of archives. 133s After this operation, 15.4 MB of additional disk space will be used. 133s Get:1 /tmp/autopkgtest.nkwejd/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 133s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 134s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 134s Fetched 2330 kB in 1s (2763 kB/s) 134s Selecting previously unselected package liburing2:ppc64el. 134s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72675 files and directories currently installed.) 134s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 134s Unpacking liburing2:ppc64el (2.6-1) ... 134s Selecting previously unselected package qemu-utils. 134s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 134s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 135s Selecting previously unselected package autopkgtest-satdep. 135s Preparing to unpack .../1-autopkgtest-satdep.deb ... 135s Unpacking autopkgtest-satdep (0) ... 135s Setting up liburing2:ppc64el (2.6-1) ... 135s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 135s Setting up autopkgtest-satdep (0) ... 135s Processing triggers for man-db (2.12.1-2) ... 135s Processing triggers for libc-bin (2.39-0ubuntu9) ... 138s (Reading database ... 72695 files and directories currently installed.) 138s Removing autopkgtest-satdep (0) ... 139s autopkgtest [19:29:41]: test kpartx-file-loopback: [----------------------- 139s Formatting 'foo.img', fmt=raw size=20971520 140s Creating new GPT entries in memory. 140s Warning: The kernel is still using the old partition table. 140s The new table will be used at the next reboot or after you 140s run partprobe(8) or kpartx(8) 140s The operation has completed successfully. 140s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 140s standard_filename: OK 140s del devmap : loop0p1 140s No devices found 140s standard_filename_cleanup: OK 140s Formatting 'fou du FaFa.img', fmt=raw size=20971520 141s Creating new GPT entries in memory. 141s Warning: The kernel is still using the old partition table. 141s The new table will be used at the next reboot or after you 141s run partprobe(8) or kpartx(8) 141s The operation has completed successfully. 141s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 141s filename_with_spaces: OK 141s del devmap : loop0p1 141s No devices found 141s filename_with_spaces_cleanup: OK 142s autopkgtest [19:29:44]: test kpartx-file-loopback: -----------------------] 142s autopkgtest [19:29:44]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 142s kpartx-file-loopback PASS 143s autopkgtest [19:29:45]: test tgtbasedmpaths: preparing testbed 256s autopkgtest [19:31:38]: testbed dpkg architecture: ppc64el 257s autopkgtest [19:31:39]: testbed apt version: 2.9.3 257s autopkgtest [19:31:39]: @@@@@@@@@@@@@@@@@@@@ test bed setup 258s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 258s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [46.4 kB] 258s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7972 B] 258s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [355 kB] 258s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [1680 B] 258s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [68.0 kB] 258s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1860 B] 258s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [319 kB] 258s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1768 B] 258s Fetched 911 kB in 1s (1044 kB/s) 258s Reading package lists... 261s Reading package lists... 261s Building dependency tree... 261s Reading state information... 262s Calculating upgrade... 262s The following packages will be upgraded: 262s debianutils libc-bin libc-dev-bin libc-devtools libc6 libc6-dev 262s libgdbm-compat4t64 libgdbm6t64 libunwind8 locales python3-typing-extensions 262s tmux 262s 12 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 262s Need to get 11.3 MB of archives. 262s After this operation, 0 B of additional disk space will be used. 262s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el debianutils ppc64el 5.19 [90.5 kB] 262s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-devtools ppc64el 2.39-0ubuntu9 [29.6 kB] 262s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6-dev ppc64el 2.39-0ubuntu9 [2102 kB] 263s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-dev-bin ppc64el 2.39-0ubuntu9 [21.3 kB] 263s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6 ppc64el 2.39-0ubuntu9 [3275 kB] 263s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-bin ppc64el 2.39-0ubuntu9 [751 kB] 263s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el locales all 2.39-0ubuntu9 [4235 kB] 263s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgdbm6t64 ppc64el 1.23-6 [41.4 kB] 263s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgdbm-compat4t64 ppc64el 1.23-6 [6876 B] 263s Get:10 http://ftpmaster.internal/ubuntu oracular/main ppc64el libunwind8 ppc64el 1.6.2-3.1 [58.9 kB] 263s Get:11 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-typing-extensions all 4.12.2-1 [65.9 kB] 263s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el tmux ppc64el 3.4-6 [602 kB] 263s Preconfiguring packages ... 264s Fetched 11.3 MB in 1s (8633 kB/s) 264s (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 ... 72675 files and directories currently installed.) 264s Preparing to unpack .../debianutils_5.19_ppc64el.deb ... 264s Unpacking debianutils (5.19) over (5.18) ... 264s Setting up debianutils (5.19) ... 264s (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 ... 72675 files and directories currently installed.) 264s Preparing to unpack .../libc-devtools_2.39-0ubuntu9_ppc64el.deb ... 264s Unpacking libc-devtools (2.39-0ubuntu9) over (2.39-0ubuntu8.1) ... 264s Preparing to unpack .../libc6-dev_2.39-0ubuntu9_ppc64el.deb ... 264s Unpacking libc6-dev:ppc64el (2.39-0ubuntu9) over (2.39-0ubuntu8.1) ... 265s Preparing to unpack .../libc-dev-bin_2.39-0ubuntu9_ppc64el.deb ... 265s Unpacking libc-dev-bin (2.39-0ubuntu9) over (2.39-0ubuntu8.1) ... 265s Preparing to unpack .../libc6_2.39-0ubuntu9_ppc64el.deb ... 265s Unpacking libc6:ppc64el (2.39-0ubuntu9) over (2.39-0ubuntu8.1) ... 265s Setting up libc6:ppc64el (2.39-0ubuntu9) ... 266s (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 ... 72675 files and directories currently installed.) 266s Preparing to unpack .../libc-bin_2.39-0ubuntu9_ppc64el.deb ... 266s Unpacking libc-bin (2.39-0ubuntu9) over (2.39-0ubuntu8.1) ... 266s Setting up libc-bin (2.39-0ubuntu9) ... 266s (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 ... 72675 files and directories currently installed.) 266s Preparing to unpack .../0-locales_2.39-0ubuntu9_all.deb ... 266s Unpacking locales (2.39-0ubuntu9) over (2.39-0ubuntu8.1) ... 266s Preparing to unpack .../1-libgdbm6t64_1.23-6_ppc64el.deb ... 266s Unpacking libgdbm6t64:ppc64el (1.23-6) over (1.23-5.1build1) ... 266s Preparing to unpack .../2-libgdbm-compat4t64_1.23-6_ppc64el.deb ... 266s Unpacking libgdbm-compat4t64:ppc64el (1.23-6) over (1.23-5.1build1) ... 266s Preparing to unpack .../3-libunwind8_1.6.2-3.1_ppc64el.deb ... 266s Unpacking libunwind8:ppc64el (1.6.2-3.1) over (1.6.2-3build1) ... 266s Preparing to unpack .../4-python3-typing-extensions_4.12.2-1_all.deb ... 267s Unpacking python3-typing-extensions (4.12.2-1) over (4.12.1-1) ... 267s Preparing to unpack .../5-tmux_3.4-6_ppc64el.deb ... 267s Unpacking tmux (3.4-6) over (3.4-5) ... 267s Setting up libgdbm6t64:ppc64el (1.23-6) ... 267s Setting up libgdbm-compat4t64:ppc64el (1.23-6) ... 267s Setting up locales (2.39-0ubuntu9) ... 268s Generating locales (this might take a while)... 269s en_US.UTF-8... done 269s Generation complete. 269s Setting up libunwind8:ppc64el (1.6.2-3.1) ... 269s Setting up python3-typing-extensions (4.12.2-1) ... 269s Setting up libc-dev-bin (2.39-0ubuntu9) ... 269s Setting up tmux (3.4-6) ... 269s Setting up libc-devtools (2.39-0ubuntu9) ... 269s Setting up libc6-dev:ppc64el (2.39-0ubuntu9) ... 269s Processing triggers for libc-bin (2.39-0ubuntu9) ... 269s Processing triggers for man-db (2.12.1-2) ... 271s Processing triggers for debianutils (5.19) ... 272s Reading package lists... 272s Building dependency tree... 272s Reading state information... 272s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 274s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 274s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 274s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 274s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 275s Reading package lists... 275s Reading package lists... 275s Building dependency tree... 275s Reading state information... 275s Calculating upgrade... 276s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 276s Reading package lists... 276s Building dependency tree... 276s Reading state information... 276s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 281s Reading package lists... 281s Building dependency tree... 281s Reading state information... 281s Starting pkgProblemResolver with broken count: 0 281s Starting 2 pkgProblemResolver with broken count: 0 281s Done 281s The following additional packages will be installed: 281s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 281s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 281s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 281s librdmacm1t64 lsscsi open-iscsi tgt 281s Suggested packages: 281s fio-examples gnuplot tgt-glusterfs tgt-rbd 281s Recommended packages: 281s finalrd 281s The following NEW packages will be installed: 281s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 281s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 281s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 281s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 281s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 281s Need to get 10.7 MB/10.7 MB of archives. 281s After this operation, 49.1 MB of additional disk space will be used. 281s Get:1 /tmp/autopkgtest.nkwejd/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 281s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu4 [54.4 kB] 282s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 282s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu4 [389 kB] 282s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 282s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 282s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu6 [256 kB] 282s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4build3 [21.5 kB] 282s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4build3 [311 kB] 282s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4build3 [47.0 kB] 282s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4build3 [100 kB] 282s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.1-1 [97.4 kB] 282s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 282s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 282s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 282s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 282s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 282s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 282s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 282s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 283s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 283s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 283s Preconfiguring packages ... 283s Fetched 10.7 MB in 1s (7772 kB/s) 283s Selecting previously unselected package libopeniscsiusr. 283s (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 ... 72675 files and directories currently installed.) 283s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu4_ppc64el.deb ... 283s Unpacking libopeniscsiusr (2.1.9-3ubuntu4) ... 283s Selecting previously unselected package libisns0t64:ppc64el. 283s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 283s Unpacking libisns0t64:ppc64el (0.101-1) ... 283s Selecting previously unselected package open-iscsi. 283s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu4_ppc64el.deb ... 283s Unpacking open-iscsi (2.1.9-3ubuntu4) ... 283s Selecting previously unselected package librdmacm1t64:ppc64el. 283s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 283s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 283s Selecting previously unselected package libconfig-general-perl. 283s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 283s Unpacking libconfig-general-perl (2.65-2) ... 283s Selecting previously unselected package tgt. 283s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu6_ppc64el.deb ... 283s Unpacking tgt (1:1.0.85-1.1ubuntu6) ... 284s Selecting previously unselected package libgfxdr0:ppc64el. 284s Preparing to unpack .../06-libgfxdr0_11.1-4build3_ppc64el.deb ... 284s Unpacking libgfxdr0:ppc64el (11.1-4build3) ... 284s Selecting previously unselected package libglusterfs0:ppc64el. 284s Preparing to unpack .../07-libglusterfs0_11.1-4build3_ppc64el.deb ... 284s Unpacking libglusterfs0:ppc64el (11.1-4build3) ... 284s Selecting previously unselected package libgfrpc0:ppc64el. 284s Preparing to unpack .../08-libgfrpc0_11.1-4build3_ppc64el.deb ... 284s Unpacking libgfrpc0:ppc64el (11.1-4build3) ... 284s Selecting previously unselected package libgfapi0:ppc64el. 284s Preparing to unpack .../09-libgfapi0_11.1-4build3_ppc64el.deb ... 284s Unpacking libgfapi0:ppc64el (11.1-4build3) ... 284s Selecting previously unselected package libnbd0. 284s Preparing to unpack .../10-libnbd0_1.20.1-1_ppc64el.deb ... 284s Unpacking libnbd0 (1.20.1-1) ... 284s Selecting previously unselected package libdaxctl1:ppc64el. 284s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 284s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 284s Selecting previously unselected package libndctl6:ppc64el. 284s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 284s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 284s Selecting previously unselected package libpmem1:ppc64el. 284s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 284s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 284s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 284s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 284s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 284s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 284s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 284s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 284s Selecting previously unselected package librados2. 284s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 284s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 284s Selecting previously unselected package libpmemobj1:ppc64el. 284s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 284s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 284s Selecting previously unselected package librbd1. 284s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 284s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 284s Selecting previously unselected package fio. 284s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 284s Unpacking fio (3.37-1) ... 284s Selecting previously unselected package lsscsi. 284s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 284s Unpacking lsscsi (0.32-1build1) ... 284s Selecting previously unselected package autopkgtest-satdep. 284s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 284s Unpacking autopkgtest-satdep (0) ... 284s Setting up libconfig-general-perl (2.65-2) ... 284s Setting up libisns0t64:ppc64el (0.101-1) ... 284s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 284s Setting up libnbd0 (1.20.1-1) ... 284s Setting up libopeniscsiusr (2.1.9-3ubuntu4) ... 284s Setting up libglusterfs0:ppc64el (11.1-4build3) ... 284s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 284s Setting up lsscsi (0.32-1build1) ... 284s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 284s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 284s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 284s Setting up tgt (1:1.0.85-1.1ubuntu6) ... 285s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 286s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 286s Setting up libgfxdr0:ppc64el (11.1-4build3) ... 286s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 286s Setting up open-iscsi (2.1.9-3ubuntu4) ... 287s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 287s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 287s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 288s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 288s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 288s Setting up libgfrpc0:ppc64el (11.1-4build3) ... 288s Setting up libgfapi0:ppc64el (11.1-4build3) ... 288s Setting up fio (3.37-1) ... 288s Setting up autopkgtest-satdep (0) ... 288s Processing triggers for man-db (2.12.1-2) ... 289s Processing triggers for initramfs-tools (0.142ubuntu28) ... 289s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 289s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 300s Processing triggers for libc-bin (2.39-0ubuntu9) ... 304s (Reading database ... 72916 files and directories currently installed.) 304s Removing autopkgtest-satdep (0) ... 306s autopkgtest [19:32:28]: test tgtbasedmpaths: [----------------------- 306s + targetname=iqn.2016-11.foo.com:target.iscsi 306s + pwd 306s + cwd=/tmp/autopkgtest.nkwejd/build.CEi/src 306s + testdir=/mnt/tgtmpathtest 306s + localhost=127.0.0.1 306s + portal=127.0.0.1:3260 306s + maxpaths=4 306s + backfn=backingfile 306s + expectwwid=60000000000000000e00000000010001 306s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 306s + bglog=/tmp/autopkgtest.nkwejd/tgtbasedmpaths-artifacts/test-background.log 306s + fioprep=/tmp/autopkgtest.nkwejd/tgtbasedmpaths-artifacts/path-change-prep.fio 306s + fiovrfy=/tmp/autopkgtest.nkwejd/tgtbasedmpaths-artifacts/path-change-check.fio 306s + service tgt restart 307s + truncate --size 100M backingfile 307s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 307s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 307s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.nkwejd/build.CEi/src/backingfile 307s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 307s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 307s + echo login #1 307s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 307s login #1 307s + seq 2 4 307s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 307s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 307s extra login #2 307s + echo extra login #2 307s + iscsiadm --mode session -r 1 --op new 307s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 307s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 307s + echo extra login #3 307s + iscsiadm --mode session -r 1 --op new 307s extra login #3 307s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 307s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 307s extra login #4 307s + echo extra login #4 307s + iscsiadm --mode session -r 1 --op new 307s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 307s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 307s + udevadm settle 307s + sleep 5 312s Status after initial setup 312s + echo Status after initial setup 312s + tgtadm --lld iscsi --mode target --op show 312s Target 1: iqn.2016-11.foo.com:target.iscsi 312s System information: 312s Driver: iscsi 312s State: ready 312s I_T nexus information: 312s I_T nexus: 1 312s Initiator: iqn.2004-10.com.ubuntu:01:1e59d707bcc alias: autopkgtest 312s Connection: 0 312s IP Address: 127.0.0.1 312s I_T nexus: 2 312s Initiator: iqn.2004-10.com.ubuntu:01:1e59d707bcc alias: autopkgtest 312s Connection: 0 312s IP Address: 127.0.0.1 312s I_T nexus: 3 312s Initiator: iqn.2004-10.com.ubuntu:01:1e59d707bcc alias: autopkgtest 312s Connection: 0 312s IP Address: 127.0.0.1 312s I_T nexus: 4 312s Initiator: iqn.2004-10.com.ubuntu:01:1e59d707bcc alias: autopkgtest 312s Connection: 0 312s IP Address: 127.0.0.1 312s LUN information: 312s LUN: 0 312s Type: controller 312s SCSI ID: IET 00010000 312s SCSI SN: beaf10 312s Size: 0 MB, Block size: 1 312s Online: Yes 312s Removable media: No 312s Prevent removal: No 312s Readonly: No 312s SWP: No 312s Thin-provisioning: No 312s Backing store type: null 312s Backing store path: None 312s Backing store flags: 312s LUN: 1 312s Type: disk 312s SCSI ID: IET 00010001 312s SCSI SN: beaf11 312s Size: 105 MB, Block size: 512 312s Online: Yes 312s Removable media: No 312s Prevent removal: No 312s Readonly: No 312s SWP: No 312s Thin-provisioning: No 312s Backing store type: rdwr 312s Backing store path: /tmp/autopkgtest.nkwejd/build.CEi/src/backingfile 312s Backing store flags: 312s Account information: 312s ACL information: 312s ALL 312s + tgtadm --lld iscsi --op show --mode conn --tid 1 312s Session: 4 312s Connection: 0 312s Initiator: iqn.2004-10.com.ubuntu:01:1e59d707bcc 312s IP Address: 127.0.0.1 312s Session: 3 312s Connection: 0 312s Initiator: iqn.2004-10.com.ubuntu:01:1e59d707bcc 312s IP Address: 127.0.0.1 312s Session: 2 312s Connection: 0 312s Initiator: iqn.2004-10.com.ubuntu:01:1e59d707bcc 312s IP Address: 127.0.0.1 312s Session: 1 312s Connection: 0 312s Initiator: iqn.2004-10.com.ubuntu:01:1e59d707bcc 312s IP Address: 127.0.0.1 312s + iscsiadm --mode session -P 1 312s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 312s Current Portal: 127.0.0.1:3260,1 312s Persistent Portal: 127.0.0.1:3260,1 312s ********** 312s Interface: 312s ********** 312s Iface Name: default 312s Iface Transport: tcp 312s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:1e59d707bcc 312s Iface IPaddress: 127.0.0.1 312s Iface HWaddress: default 312s Iface Netdev: default 312s SID: 1 312s iSCSI Connection State: LOGGED IN 312s iSCSI Session State: LOGGED_IN 312s Internal iscsid Session State: NO CHANGE 312s 312s ********** 312s Interface: 312s ********** 312s Iface Name: default 312s Iface Transport: tcp 312s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:1e59d707bcc 312s Iface IPaddress: 127.0.0.1 312s Iface HWaddress: default 312s Iface Netdev: default 312s SID: 2 312s iSCSI Connection State: LOGGED IN 312s iSCSI Session State: LOGGED_IN 312s Internal iscsid Session State: NO CHANGE 312s 312s ********** 312s Interface: 312s ********** 312s Iface Name: default 312s Iface Transport: tcp 312s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:1e59d707bcc 312s Iface IPaddress: 127.0.0.1 312s Iface HWaddress: default 312s Iface Netdev: default 312s SID: 3 312s iSCSI Connection State: LOGGED IN 312s iSCSI Session State: LOGGED_IN 312s Internal iscsid Session State: NO CHANGE 312s 312s ********** 312s Interface: 312s ********** 312s Iface Name: default 312s Iface Transport: tcp 312s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:1e59d707bcc 312s Iface IPaddress: 127.0.0.1 312s Iface HWaddress: default 312s Iface Netdev: default 312s SID: 4 312s iSCSI Connection State: LOGGED IN 312s iSCSI Session State: LOGGED_IN 312s Internal iscsid Session State: NO CHANGE 312s + lsscsi -liv 312s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 312s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 312s 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] 312s [1:0:0:0] storage IET Controller 0001 - - 312s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 312s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 312s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 312s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 312s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 312s [2:0:0:0] storage IET Controller 0001 - - 312s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 312s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 312s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 312s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 312s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 312s [3:0:0:0] storage IET Controller 0001 - - 312s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 312s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 312s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 312s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 312s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 312s [4:0:0:0] storage IET Controller 0001 - - 312s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 312s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 312s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 312s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 312s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 312s NVMe module may not be loaded 312s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 312s + multipath -v3 -ll 312s 92.516321 | set open fds limit to 1048576/1048576 312s 92.516414 | loading /lib/multipath/libchecktur.so checker 312s 92.516627 | checker tur: message table size = 3 312s 92.516656 | loading /lib/multipath/libprioconst.so prioritizer 312s 92.516847 | _init_foreign: foreign library "nvme" is not enabled 312s 92.523148 | sda: size = 167772160 312s 92.523426 | sda: vendor = QEMU 312s 92.523472 | sda: product = QEMU HARDDISK 312s 92.523495 | sda: rev = 2.5+ 312s 92.524289 | sda: h:b:t:l = 0:0:0:0 312s 92.524722 | sda: tgt_node_name = 312s 92.524745 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 312s 92.524749 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 312s 92.525002 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 312s 92.525025 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 312s 92.525041 | __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 312s 92.525046 | failed to read sysfs vpd pg80: No such file or directory 312s 92.525341 | sda: fail to get serial 312s 92.525363 | sda: detect_checker = yes (setting: multipath internal) 312s 92.525634 | sda: path_checker = tur (setting: multipath internal) 312s 92.525656 | sda: checker timeout = 30 s (setting: kernel sysfs) 312s 92.525858 | sda: tur state = up 312s 92.526320 | sdb: size = 204800 312s 92.526557 | sdb: vendor = IET 312s 92.526601 | sdb: product = VIRTUAL-DISK 312s 92.526624 | sdb: rev = 0001 312s 92.527345 | sdb: h:b:t:l = 1:0:0:1 312s 92.527823 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 312s 92.527849 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 312s 92.527851 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 312s 92.528227 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 312s 92.528254 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 312s 92.528271 | sdb: serial = beaf11 312s 92.528274 | sdb: detect_checker = yes (setting: multipath internal) 312s 92.530555 | sdb: path_checker = tur (setting: multipath internal) 312s 92.530585 | sdb: checker timeout = 30 s (setting: kernel sysfs) 312s 92.530889 | sdb: tur state = up 312s 92.531089 | sdc: size = 204800 312s 92.531247 | sdc: vendor = IET 312s 92.531271 | sdc: product = VIRTUAL-DISK 312s 92.531297 | sdc: rev = 0001 312s 92.532142 | sdc: h:b:t:l = 2:0:0:1 312s 92.532560 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 312s 92.532564 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 312s 92.532567 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 312s 92.532741 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 312s 92.532745 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 312s 92.532760 | sdc: serial = beaf11 312s 92.532762 | sdc: detect_checker = yes (setting: multipath internal) 312s 92.533154 | sdc: path_checker = tur (setting: multipath internal) 312s 92.533187 | sdc: checker timeout = 30 s (setting: kernel sysfs) 312s 92.533460 | sdc: tur state = up 312s 92.533646 | sdd: size = 204800 312s 92.533789 | sdd: vendor = IET 312s 92.533812 | sdd: product = VIRTUAL-DISK 312s 92.533839 | sdd: rev = 0001 312s 92.534674 | sdd: h:b:t:l = 3:0:0:1 312s 92.535096 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 312s 92.535121 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 312s 92.535124 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 312s 92.535296 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 312s 92.535318 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 312s 92.535334 | sdd: serial = beaf11 312s 92.535337 | sdd: detect_checker = yes (setting: multipath internal) 312s 92.535781 | sdd: path_checker = tur (setting: multipath internal) 312s 92.536077 | sdd: checker timeout = 30 s (setting: kernel sysfs) 312s 92.536393 | sdd: tur state = up 312s 92.536561 | sde: size = 204800 312s 92.536713 | sde: vendor = IET 312s 92.536736 | sde: product = VIRTUAL-DISK 312s 92.536761 | sde: rev = 0001 312s 92.537794 | sde: h:b:t:l = 4:0:0:1 312s 92.538315 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 312s 92.538338 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 312s 92.538340 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 312s 92.538519 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 312s 92.538542 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 312s 92.538560 | sde: serial = beaf11 312s 92.538563 | sde: detect_checker = yes (setting: multipath internal) 312s 92.538885 | sde: path_checker = tur (setting: multipath internal) 312s 92.538909 | sde: checker timeout = 30 s (setting: kernel sysfs) 312s 92.539144 | sde: tur state = up 312s 92.539268 | loop0: device node name blacklisted 312s 92.539383 | loop1: device node name blacklisted 312s 92.539493 | loop2: device node name blacklisted 312s 92.539603 | loop3: device node name blacklisted 312s 92.539716 | loop4: device node name blacklisted 312s 92.539820 | loop5: device node name blacklisted 312s 92.539929 | loop6: device node name blacklisted 312s 92.540089 | loop7: device node name blacklisted 312s 92.540233 | dm-0: device node name blacklisted 312s 92.541365 | multipath-tools v0.9.4 (12/19, 2022) 312s 92.541402 | libdevmapper version 1.02.185 312s 92.541550 | kernel device mapper v4.48.0 312s 92.541582 | DM multipath kernel driver v1.14.0 312s 92.541708 | sdb: size = 204800 312s 92.541733 | sdb: vendor = IET 312s 92.541736 | sdb: product = VIRTUAL-DISK 312s 92.541739 | sdb: rev = 0001 312s 92.542483 | sdb: h:b:t:l = 1:0:0:1 312s 92.542642 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 312s 92.542687 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 312s 92.542690 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 312s 92.542707 | sdb: serial = beaf11 312s 92.543077 | sdb: tur state = up 312s 92.543142 | sdb: uid = 360000000000000000e00000000010001 (udev) 312s 92.543146 | sdb: detect_prio = yes (setting: multipath internal) 312s 92.543150 | sdb: prio = const (setting: multipath internal) 312s 92.543152 | sdb: prio args = "" (setting: multipath internal) 312s 92.543154 | sdb: const prio = 1 312s 92.544502 | sdc: size = 204800 312s 92.544509 | sdc: vendor = IET 312s 92.544512 | sdc: product = VIRTUAL-DISK 312s 92.544515 | sdc: rev = 0001 312s 92.545209 | sdc: h:b:t:l = 2:0:0:1 312s ===== paths list ===== 312s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 312s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 312s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 312s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 312s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 312s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 312s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 312s size=100M features='0' hwhandler='0' wp=rw 312s |-+- policy='service-time 0' prio=1 status=active 312s | `- 1:0:0:1 sdb 8:16 active ready running 312s |-+- policy='service-time 0' prio=1 status=enabled 312s | `- 2:0:0:1 sdc 8:32 active ready running 312s |-+- policy='service-time 0' prio=1 status=enabled 312s | `- 3:0:0:1 sdd 8:48 active ready running 312s `-+- policy='service-time 0' prio=1 status=enabled 312s `- 4:0:0:1 sde 8:64 active ready running 312s 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 312s Test WWN should now point to DM 312s ../../dm-0 312s 92.545382 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 312s 92.545425 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 312s 92.545428 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 312s 92.545451 | sdc: serial = beaf11 312s 92.545715 | sdc: tur state = up 312s 92.545743 | sdc: uid = 360000000000000000e00000000010001 (udev) 312s 92.545746 | sdc: detect_prio = yes (setting: multipath internal) 312s 92.545752 | sdc: prio = const (setting: multipath internal) 312s 92.545754 | sdc: prio args = "" (setting: multipath internal) 312s 92.545757 | sdc: const prio = 1 312s 92.545789 | sdd: size = 204800 312s 92.545795 | sdd: vendor = IET 312s 92.545829 | sdd: product = VIRTUAL-DISK 312s 92.545832 | sdd: rev = 0001 312s 92.546510 | sdd: h:b:t:l = 3:0:0:1 312s 92.546901 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 312s 92.546945 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 312s 92.546948 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 312s 92.547361 | sdd: serial = beaf11 312s 92.547618 | sdd: tur state = up 312s 92.547644 | sdd: uid = 360000000000000000e00000000010001 (udev) 312s 92.547648 | sdd: detect_prio = yes (setting: multipath internal) 312s 92.547653 | sdd: prio = const (setting: multipath internal) 312s 92.547655 | sdd: prio args = "" (setting: multipath internal) 312s 92.547657 | sdd: const prio = 1 312s 92.547688 | sde: size = 204800 312s 92.547694 | sde: vendor = IET 312s 92.547697 | sde: product = VIRTUAL-DISK 312s 92.547700 | sde: rev = 0001 312s 92.548432 | sde: h:b:t:l = 4:0:0:1 312s 92.548603 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 312s 92.548647 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 312s 92.548650 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 312s 92.548665 | sde: serial = beaf11 312s 92.548916 | sde: tur state = up 312s 92.548938 | sde: uid = 360000000000000000e00000000010001 (udev) 312s 92.548940 | sde: detect_prio = yes (setting: multipath internal) 312s 92.548944 | sde: prio = const (setting: multipath internal) 312s 92.548946 | sde: prio args = "" (setting: multipath internal) 312s 92.548949 | sde: const prio = 1 312s 92.549996 | unloading tur checker 312s 92.550065 | unloading const prioritizer 312s + dmsetup table 312s + echo Test WWN should now point to DM 312s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 312s + grep dm 312s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 312s mke2fs 1.47.0 (5-Feb-2023) 312s Creating filesystem with 25600 4k blocks and 25600 inodes 312s 312s Allocating group tables: 0/1 done 312s Writing inode tables: 0/1 done 312s Creating journal (1024 blocks): done 312s Writing superblocks and filesystem accounting information: 0/1 done 312s 312s + udevadm settle 312s + sleep 3s 315s + mkdir -p /mnt/tgtmpathtest 315s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 315s + cat 315s + cat 315s + fio --max-jobs=4 /tmp/autopkgtest.nkwejd/tgtbasedmpaths-artifacts/path-change-prep.fio 316s 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 316s fio-3.37 316s Starting 1 thread 316s write-phase: Laying out IO file (1 file / 17592186044415MiB) 316s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 317s 317s write-phase: (groupid=0, jobs=1): err= 0: pid=7219: Mon Jun 10 19:32:38 2024 317s write: IOPS=1745, BW=109MiB/s (114MB/s)(87.6MiB/804msec); 0 zone resets 317s clat (usec): min=309, max=12316, avg=556.97, stdev=581.61 317s lat (usec): min=323, max=12334, avg=571.36, stdev=582.19 317s clat percentiles (usec): 317s | 1.00th=[ 330], 5.00th=[ 347], 10.00th=[ 359], 20.00th=[ 383], 317s | 30.00th=[ 400], 40.00th=[ 416], 50.00th=[ 441], 60.00th=[ 478], 317s | 70.00th=[ 519], 80.00th=[ 594], 90.00th=[ 717], 95.00th=[ 938], 317s | 99.00th=[ 2868], 99.50th=[ 4621], 99.90th=[ 7439], 99.95th=[12256], 317s | 99.99th=[12256] 317s bw ( KiB/s): min=102656, max=102656, per=91.98%, avg=102656.00, stdev= 0.00, samples=1 317s iops : min= 1604, max= 1604, avg=1604.00, stdev= 0.00, samples=1 317s lat (usec) : 500=66.43%, 750=24.59%, 1000=4.42% 317s lat (msec) : 2=2.92%, 4=0.93%, 10=0.57%, 20=0.07% 317s cpu : usr=4.11%, sys=9.22%, ctx=1404, majf=0, minf=0 317s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 317s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 317s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 317s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 317s latency : target=0, window=0, percentile=100.00%, depth=1 317s 317s Run status group 0 (all jobs): 317s WRITE: bw=109MiB/s (114MB/s), 109MiB/s-109MiB/s (114MB/s-114MB/s), io=87.6MiB (91.9MB), run=804-804msec 317s 317s Disk stats (read/write): 317s dm-0: ios=1/1099, sectors=8/140672, merge=0/0, ticks=11/574, in_queue=586, util=87.26%, aggrios=0/351, aggsectors=2/44884, aggrmerge=0/0, aggrticks=2/180, aggrin_queue=183, aggrutil=88.98% 317s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 317s sdb: ios=1/1404, sectors=8/179536, merge=0/0, ticks=11/720, in_queue=732, util=88.98% 317s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 317s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 317s + echo Starting the path changes in background 317s Starting the path changes in background 317s + date +Pre FIO %H:%M:%S.%N 317s Pre FIO 19:32:39.000028420 317s + fio --max-jobs=4 /tmp/autopkgtest.nkwejd/tgtbasedmpaths-artifacts/path-change-check.fio 317s 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 317s fio-3.37 317s Starting 1 thread 497s 497s verify-phase: (groupid=0, jobs=1): err= 0: pid=7226: Mon Jun 10 19:35:39 2024 497s read: IOPS=2774, BW=173MiB/s (182MB/s)(30.5GiB/180001msec) 497s clat (usec): min=86, max=44602, avg=336.97, stdev=325.26 497s lat (usec): min=86, max=44602, avg=337.08, stdev=325.26 497s clat percentiles (usec): 497s | 1.00th=[ 147], 5.00th=[ 182], 10.00th=[ 202], 20.00th=[ 223], 497s | 30.00th=[ 247], 40.00th=[ 277], 50.00th=[ 310], 60.00th=[ 330], 497s | 70.00th=[ 355], 80.00th=[ 379], 90.00th=[ 441], 95.00th=[ 529], 497s | 99.00th=[ 1172], 99.50th=[ 1844], 99.90th=[ 4424], 99.95th=[ 5604], 497s | 99.99th=[ 9896] 497s bw ( KiB/s): min=107520, max=297472, per=100.00%, avg=177608.38, stdev=32140.97, samples=359 497s iops : min= 1680, max= 4648, avg=2775.12, stdev=502.21, samples=359 497s lat (usec) : 100=0.03%, 250=30.63%, 500=63.35%, 750=3.87%, 1000=0.81% 497s lat (msec) : 2=0.86%, 4=0.31%, 10=0.13%, 20=0.01%, 50=0.01% 497s cpu : usr=7.24%, sys=9.24%, ctx=499407, majf=0, minf=1 497s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 497s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 497s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 497s issued rwts: total=499333,0,0,0 short=0,0,0,0 dropped=0,0,0,0 497s latency : target=0, window=0, percentile=100.00%, depth=1 497s 497s Run status group 0 (all jobs): 497s READ: bw=173MiB/s (182MB/s), 173MiB/s-173MiB/s (182MB/s-182MB/s), io=30.5GiB (32.7GB), run=180001-180001msec 497s 497s Disk stats (read/write): 497s dm-0: ios=499398/7, sectors=63877176/120, merge=32/8, ticks=175868/6, in_queue=175874, util=99.74%, aggrios=33205/1, aggsectors=4247214/30, aggrmerge=0/0, aggrticks=11142/1, aggrin_queue=11143, aggrutil=99.05% 497s sdd: ios=24136/0, sectors=3087232/0, merge=0/0, ticks=9130/0, in_queue=9130, util=33.41% 497s sdb: ios=24920/7, sectors=3187456/120, merge=0/0, ticks=8635/5, in_queue=8639, util=99.05% 497s sde: ios=55610/0, sectors=7112960/0, merge=0/0, ticks=17932/0, in_queue=17932, util=39.93% 497s sdc: ios=28157/0, sectors=3601208/0, merge=0/0, ticks=8873/0, in_queue=8873, util=50.06% 497s + date +Post FIO %H:%M:%S.%N 497s Post FIO 19:35:39.373211563 497s FIO verify test with changing paths - OK 497s Report log of background activity 497s + echo FIO verify test with changing paths - OK 497s + echo Report log of background activity 497s + cat /tmp/autopkgtest.nkwejd/tgtbasedmpaths-artifacts/test-background.log 497s + iscsiadm --mode session 497s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s + sleep 10s 497s + date +MP report (expect 4) %H:%M:%S.%N 497s MP report (expect 4) 19:32:49.012027491 497s + multipath -ll 497s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 497s size=100M features='0' hwhandler='0' wp=rw 497s |-+- policy='service-time 0' prio=1 status=active 497s | `- 1:0:0:1 sdb 8:16 active ready running 497s |-+- policy='service-time 0' prio=1 status=enabled 497s | `- 2:0:0:1 sdc 8:32 active ready running 497s |-+- policy='service-time 0' prio=1 status=enabled 497s | `- 3:0:0:1 sdd 8:48 active ready running 497s `-+- policy='service-time 0' prio=1 status=enabled 497s `- 4:0:0:1 sde 8:64 active ready running 497s + date +UN-plug path 1 %H:%M:%S.%N 497s UN-plug path 1 19:32:49.048930630 497s + iscsiadm --mode session -r 1 -u 497s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 497s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 497s + iscsiadm --mode session 497s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s + sleep 10s 497s + date +MP report (expect 3) %H:%M:%S.%N 497s MP report (expect 3) 19:32:59.173860875 497s + multipath -ll 497s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 497s size=100M features='0' hwhandler='0' wp=rw 497s |-+- policy='service-time 0' prio=1 status=active 497s | `- 2:0:0:1 sdc 8:32 active ready running 497s |-+- policy='service-time 0' prio=1 status=enabled 497s | `- 3:0:0:1 sdd 8:48 active ready running 497s `-+- policy='service-time 0' prio=1 status=enabled 497s `- 4:0:0:1 sde 8:64 active ready running 497s + date +UN-plug path 2 %H:%M:%S.%N 497s UN-plug path 2 19:32:59.208281487 497s + iscsiadm --mode session -r 2 -u 497s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 497s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 497s + iscsiadm --mode session 497s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s + sleep 10s 497s + date +MP report (expect 2) %H:%M:%S.%N 497s MP report (expect 2) 19:33:09.306197817 497s + multipath -ll 497s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 497s size=100M features='0' hwhandler='0' wp=rw 497s |-+- policy='service-time 0' prio=1 status=active 497s | `- 3:0:0:1 sdd 8:48 active ready running 497s `-+- policy='service-time 0' prio=1 status=enabled 497s `- 4:0:0:1 sde 8:64 active ready running 497s + date +UN-plug path 3 %H:%M:%S.%N 497s UN-plug path 3 19:33:09.341631509 497s + iscsiadm --mode session -r 3 -u 497s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 497s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 497s + iscsiadm --mode session 497s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s + sleep 10s 497s + date +MP report (expect 1) %H:%M:%S.%N 497s MP report (expect 1) 19:33:19.447353302 497s + multipath -ll 497s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 497s size=100M features='0' hwhandler='0' wp=rw 497s `-+- policy='service-time 0' prio=1 status=active 497s `- 4:0:0:1 sde 8:64 active ready running 497s + date +Add paths 5/6/7/8 %H:%M:%S.%N 497s Add paths 5/6/7/8 19:33:19.463938549 497s + iscsiadm --mode session -r 4 --op new 497s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 497s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 497s + iscsiadm --mode session -r 4 --op new 497s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 497s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 497s + iscsiadm --mode session -r 4 --op new 497s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 497s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 497s + iscsiadm --mode session -r 4 --op new 497s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 497s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 497s + iscsiadm --mode session 497s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s + sleep 10s 497s + date +MP report (expect 5) %H:%M:%S.%N 497s MP report (expect 5) 19:33:29.643953226 497s + multipath -ll 497s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 497s size=100M features='0' hwhandler='0' wp=rw 497s |-+- policy='service-time 0' prio=1 status=active 497s | `- 4:0:0:1 sde 8:64 active ready running 497s |-+- policy='service-time 0' prio=1 status=enabled 497s | `- 1:0:0:1 sdb 8:16 active ready running 497s |-+- policy='service-time 0' prio=1 status=enabled 497s | `- 2:0:0:1 sdc 8:32 active ready running 497s |-+- policy='service-time 0' prio=1 status=enabled 497s | `- 3:0:0:1 sdd 8:48 active ready running 497s `-+- policy='service-time 0' prio=1 status=enabled 497s `- 5:0:0:1 sdf 8:80 active ready running 497s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 497s UN-plug multiple paths 4/7/8 19:33:29.680010892 497s + iscsiadm --mode session -r 4 -u 497s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 497s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 497s + iscsiadm --mode session -r 7 -u 497s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 497s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 497s + iscsiadm --mode session -r 8 -u 497s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 497s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 497s + iscsiadm --mode session 497s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 497s + sleep 10s 497s + date +Restart multipath daemon %H:%M:%S.%N 497s Restart multipath daemon 19:33:39.984129562 497s + systemctl restart multipathd 497s + sleep 10s 497s + date +Final background report (expect 2) %H:%M:%S.%N 497s Final background report (expect 2) 19:33:50.096886966 497s + multipath -ll 497s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 497s size=100M features='0' hwhandler='0' wp=rw 497s |-+- policy='service-time 0' prio=1 status=active 497s | `- 1:0:0:1 sdb 8:16 active ready running 497s `-+- policy='service-time 0' prio=1 status=enabled 497s `- 2:0:0:1 sdc 8:32 active ready running 497s Final stats 497s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 497s iSCSI SNMP: 497s txdata_octets: 17584680 497s rxdata_octets: 23985858196 497s noptx_pdus: 0 497s scsicmd_pdus: 366080 497s tmfcmd_pdus: 0 497s login_pdus: 0 497s text_pdus: 0 497s dataout_pdus: 0 497s logout_pdus: 0 497s snack_pdus: 0 497s noprx_pdus: 0 497s scsirsp_pdus: 366080 497s tmfrsp_pdus: 0 497s textrsp_pdus: 0 497s datain_pdus: 366048 497s logoutrsp_pdus: 0 497s r2t_pdus: 0 497s async_pdus: 0 497s rjt_pdus: 0 497s digest_err: 0 497s timeout_err: 0 497s iSCSI Extended: 497s tx_sendpage_failures: 0 497s rx_discontiguous_hdr: 0 497s eh_abort_cnt: 0 497s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 497s iSCSI SNMP: 497s txdata_octets: 6504 497s rxdata_octets: 1514964 497s noptx_pdus: 0 497s scsicmd_pdus: 105 497s tmfcmd_pdus: 0 497s login_pdus: 0 497s text_pdus: 0 497s dataout_pdus: 0 497s logout_pdus: 0 497s snack_pdus: 0 497s noprx_pdus: 0 497s scsirsp_pdus: 105 497s tmfrsp_pdus: 0 497s textrsp_pdus: 0 497s datain_pdus: 83 497s logoutrsp_pdus: 0 497s r2t_pdus: 0 497s async_pdus: 0 497s rjt_pdus: 0 497s digest_err: 0 497s timeout_err:+ sync 497s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 497s + echo Final stats 497s + iscsiadm --mode session --stats 497s + journalctl --no-pager -u multipathd 497s + echo Check final path status 497s + multipath -ll 497s + multipath -ll 497s + grep --count status= 497s + diskc=2 497s + multipath -ll 497s + grep --count status=active 497s 0 497s iSCSI Extended: 497s tx_sendpage_failures: 0 497s rx_discontiguous_hdr: 0 497s eh_abort_cnt: 0 497s Jun 10 09:25:49 adtubuntu-oracular-ppc64el-server-20240608 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 497s Jun 10 09:25:49 adtubuntu-oracular-ppc64el-server-20240608 multipathd[279]: multipathd v0.9.4: start up 497s Jun 10 09:25:49 adtubuntu-oracular-ppc64el-server-20240608 multipathd[279]: reconfigure: setting up paths and maps 497s Jun 10 09:25:49 adtubuntu-oracular-ppc64el-server-20240608 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 497s Jun 10 09:26:25 adtubuntu-oracular-ppc64el-server-20240609 multipathd[279]: multipathd: shut down 497s Jun 10 09:26:25 adtubuntu-oracular-ppc64el-server-20240609 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 497s Jun 10 09:26:25 adtubuntu-oracular-ppc64el-server-20240609 systemd[1]: multipathd.service: Deactivated successfully. 497s Jun 10 09:26:25 adtubuntu-oracular-ppc64el-server-20240609 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 497s -- Boot 0786cfafe2184df6a68c789633d42b9c -- 497s Jun 10 09:26:48 adtubuntu-oracular-ppc64el-server-20240609 multipathd[261]: multipathd v0.9.4: start up 497s Jun 10 09:26:48 adtubuntu-oracular-ppc64el-server-20240609 multipathd[261]: reconfigure: setting up paths and maps 497s Jun 10 09:26:48 adtubuntu-oracular-ppc64el-server-20240609 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 497s Jun 10 09:27:10 adtubuntu-oracular-ppc64el-server-20240609 multipathd[261]: multipathd: shut down 497s Jun 10 09:27:10 adtubuntu-oracular-ppc64el-server-20240609 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 497s Jun 10 09:27:10 adtubuntu-oracular-ppc64el-server-20240609 systemd[1]: multipathd.service: Deactivated successfully. 497s Jun 10 09:27:10 adtubuntu-oracular-ppc64el-server-20240609 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 497s -- Boot 590e64874a7a41c48410ede9bfb995b4 -- 497s Jun 10 19:31:05 adtubuntu-oracular-ppc64el-server-20240609 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 497s Jun 10 19:31:05 adtubuntu-oracular-ppc64el-server-20240609 multipathd[337]: multipathd v0.9.4: start up 497s Jun 10 19:31:05 adtubuntu-oracular-ppc64el-server-20240609 multipathd[337]: reconfigure: setting up paths and maps 497s Jun 10 19:31:05 adtubuntu-oracular-ppc64el-server-20240609 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 497s Jun 10 19:32:29 autopkgtest multipathd[337]: 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] 497s Jun 10 19:32:29 autopkgtest multipathd[337]: sdc [8:32]: path added to devmap mpatha 497s Jun 10 19:32:29 autopkgtest multipathd[337]: mpatha: sdc - tur checker reports path is up 497s Jun 10 19:32:29 autopkgtest multipathd[337]: 8:32: reinstated 497s Jun 10 19:32:29 autopkgtest multipathd[337]: mpatha: remaining active paths: 2 497s Jun 10 19:32:29 autopkgtest multipathd[337]: mpatha: performing delayed actions 497s Jun 10 19:32:29 autopkgtest multipathd[337]: 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] 497s Jun 10 19:32:49 autopkgtest multipathd[337]: 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] 497s Jun 10 19:32:49 autopkgtest multipathd[337]: check_removed_paths: sdb: freeing path in removed state 497s Jun 10 19:32:49 autopkgtest multipathd[337]: 8:16: path removed from map mpatha 497s Jun 10 19:32:59 autopkgtest multipathd[337]: 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] 497s Jun 10 19:32:59 autopkgtest multipathd[337]: check_removed_paths: sdc: freeing path in removed state 497s Jun 10 19:32:59 autopkgtest multipathd[337]: 8:32: path removed from map mpatha 497s Jun 10 19:33:09 autopkgtest multipathd[337]: sdd: mark as failed 497s Jun 10 19:33:09 autopkgtest multipathd[337]: mpatha: remaining active paths: 1 497s Jun 10 19:33:09 autopkgtest multipathd[337]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 497s Jun 10 19:33:09 autopkgtest multipathd[337]: check_removed_paths: sdd: freeing path in removed state 497s Jun 10 19:33:09 autopkgtest multipathd[337]: 8:48: path removed from map mpatha 497s Jun 10 19:33:19 autopkgtest multipathd[337]: 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] 497s Jun 10 19:33:19 autopkgtest multipathd[337]: sdb [8:16]: path added to devmap mpatha 497s Jun 10 19:33:19 autopkgtest multipathd[337]: 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] 497s Jun 10 19:33:19 autopkgtest multipathd[337]: sdc [8:32]: path added to devmap mpatha 497s Jun 10 19:33:19 autopkgtest multipathd[337]: 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] 497s Jun 10 19:33:19 autopkgtest multipathd[337]: sdd [8:48]: path added to devmap mpatha 497s Jun 10 19:33:19 autopkgtest multipathd[337]: 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] 497s Jun 10 19:33:19 autopkgtest multipathd[337]: sdf [8:80]: path added to devmap mpatha 497s Jun 10 19:33:29 autopkgtest multipathd[337]: 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] 497s Jun 10 19:33:29 autopkgtest multipathd[337]: check_removed_paths: sde: freeing path in removed state 497s Jun 10 19:33:29 autopkgtest multipathd[337]: 8:64: path removed from map mpatha 497s Jun 10 19:33:29 autopkgtest multipathd[337]: 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] 497s Jun 10 19:33:29 autopkgtest multipathd[337]: check_removed_paths: sdd: freeing path in removed state 497s Jun 10 19:33:29 autopkgtest multipathd[337]: 8:48: path removed from map mpatha 497s Jun 10 19:33:29 autopkgtest multipathd[337]: 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] 497s Jun 10 19:33:29 autopkgtest multipathd[337]: check_removed_paths: sdf: freeing path in removed state 497s Jun 10 19:33:29 autopkgtest multipathd[337]: 8:80: path removed from map mpatha 497s Jun 10 19:33:39 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 497s Jun 10 19:33:39 autopkgtest multipathd[337]: multipathd: shut down 497s Jun 10 19:33:40 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 497s Jun 10 19:33:40 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 497s Jun 10 19:33:40 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 497s Jun 10 19:33:40 autopkgtest multipathd[7603]: multipathd v0.9.4: start up 497s Jun 10 19:33:40 autopkgtest multipathd[7603]: reconfigure: setting up paths and maps 497s Jun 10 19:33:40 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 497s Check final path status 497s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 497s size=100M features='0' hwhandler='0' wp=rw 497s |-+- policy='service-time 0' prio=1 status=active 497s | `- 1:0:0:1 sdb 8:16 active ready running 497s `-+- policy='service-time 0' prio=1 status=enabled 497s `- 2:0:0:1 sdc 8:32 active ready running 497s + diska=1 497s + grep --count status=enabled+ 497s multipath -ll 497s + diske=1 497s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 497s + echo OK 497s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 497s OK 497s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 497s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 497s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 497s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 497s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 497s autopkgtest [19:35:39]: test tgtbasedmpaths: -----------------------] 498s tgtbasedmpaths PASS 498s autopkgtest [19:35:40]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 498s autopkgtest [19:35:40]: @@@@@@@@@@@@@@@@@@@@ summary 498s kpartx-file-loopback PASS 498s tgtbasedmpaths PASS 513s nova [W] Using flock in scalingstack-bos01-ppc64el 513s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240610-192722-juju-7f2275-prod-proposed-migration-environment-3-56b3f044-8cee-484a-b768-a18326eba5ec from image adt/ubuntu-oracular-ppc64el-server-20240610.img (UUID 7b59f80e-4e6b-462d-bae7-0b4a0ed6ba38)... 513s nova [W] Using flock in scalingstack-bos01-ppc64el 513s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240610-192722-juju-7f2275-prod-proposed-migration-environment-3-56b3f044-8cee-484a-b768-a18326eba5ec from image adt/ubuntu-oracular-ppc64el-server-20240610.img (UUID 7b59f80e-4e6b-462d-bae7-0b4a0ed6ba38)...