0s autopkgtest [22:25:50]: starting date and time: 2024-07-12 22:25:50+0000 0s autopkgtest [22:25:50]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [22:25:50]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.tqt3fcut/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.1ubuntu3 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos02-ppc64el-19.secgroup --name adt-oracular-ppc64el-multipath-tools-20240712-222550-juju-7f2275-prod-proposed-migration-environment-3-ad789904-a72e-4042-b77e-762d628562bf --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 143s autopkgtest [22:28:13]: testbed dpkg architecture: ppc64el 143s autopkgtest [22:28:13]: testbed apt version: 2.9.6 143s autopkgtest [22:28:13]: @@@@@@@@@@@@@@@@@@@@ test bed setup 144s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 145s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 145s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3288 B] 145s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [360 kB] 145s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [46.5 kB] 145s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [74.0 kB] 145s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2132 B] 145s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 145s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 145s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [365 kB] 145s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [9000 B] 145s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1788 B] 145s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 147s Fetched 997 kB in 1s (1168 kB/s) 147s Reading package lists... 150s Reading package lists... 150s Building dependency tree... 150s Reading state information... 150s Calculating upgrade... 151s The following packages will be upgraded: 151s libc-bin libc-dev-bin libc-devtools libc6 libc6-dev locales 151s 6 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 151s Need to get 10.1 MB of archives. 151s After this operation, 1843 kB disk space will be freed. 151s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-devtools ppc64el 2.39-3.1ubuntu3 [29.5 kB] 151s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6-dev ppc64el 2.39-3.1ubuntu3 [1982 kB] 152s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-dev-bin ppc64el 2.39-3.1ubuntu3 [21.0 kB] 152s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6 ppc64el 2.39-3.1ubuntu3 [3174 kB] 152s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-bin ppc64el 2.39-3.1ubuntu3 [720 kB] 152s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el locales all 2.39-3.1ubuntu3 [4220 kB] 152s Preconfiguring packages ... 152s Fetched 10.1 MB in 1s (9742 kB/s) 153s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72754 files and directories currently installed.) 153s Preparing to unpack .../libc-devtools_2.39-3.1ubuntu3_ppc64el.deb ... 153s Unpacking libc-devtools (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 153s Preparing to unpack .../libc6-dev_2.39-3.1ubuntu3_ppc64el.deb ... 153s Unpacking libc6-dev:ppc64el (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 153s Preparing to unpack .../libc-dev-bin_2.39-3.1ubuntu3_ppc64el.deb ... 153s Unpacking libc-dev-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 153s Preparing to unpack .../libc6_2.39-3.1ubuntu3_ppc64el.deb ... 153s Unpacking libc6:ppc64el (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 154s Setting up libc6:ppc64el (2.39-3.1ubuntu3) ... 154s Error: Could not restart systemd, systemd binary not working 154s (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 ... 72754 files and directories currently installed.) 154s Preparing to unpack .../libc-bin_2.39-3.1ubuntu3_ppc64el.deb ... 154s Unpacking libc-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 154s Setting up libc-bin (2.39-3.1ubuntu3) ... 154s (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 ... 72754 files and directories currently installed.) 154s Preparing to unpack .../locales_2.39-3.1ubuntu3_all.deb ... 154s Unpacking locales (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 154s Setting up locales (2.39-3.1ubuntu3) ... 155s Generating locales (this might take a while)... 157s en_US.UTF-8... done 157s Generation complete. 157s Setting up libc-dev-bin (2.39-3.1ubuntu3) ... 157s Setting up libc-devtools (2.39-3.1ubuntu3) ... 157s Setting up libc6-dev:ppc64el (2.39-3.1ubuntu3) ... 157s Processing triggers for man-db (2.12.1-2) ... 158s Processing triggers for systemd (256-1ubuntu1) ... 159s Reading package lists... 160s Building dependency tree... 160s Reading state information... 160s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 160s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 160s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 160s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 160s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 162s Reading package lists... 162s Reading package lists... 162s Building dependency tree... 162s Reading state information... 162s Calculating upgrade... 162s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 162s Reading package lists... 162s Building dependency tree... 162s Reading state information... 163s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 166s autopkgtest [22:28:36]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 166s autopkgtest [22:28:36]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 169s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 169s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 169s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 169s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 169s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 169s gpgv: issuer "steve.langasek@ubuntu.com" 169s gpgv: Can't check signature: No public key 169s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 169s autopkgtest [22:28:39]: testing package multipath-tools version 0.9.4-5ubuntu8 170s autopkgtest [22:28:40]: build not needed 170s autopkgtest [22:28:40]: test kpartx-file-loopback: preparing testbed 171s Reading package lists... 172s Building dependency tree... 172s Reading state information... 172s Starting pkgProblemResolver with broken count: 0 172s Starting 2 pkgProblemResolver with broken count: 0 172s Done 172s The following additional packages will be installed: 172s liburing2 qemu-utils 172s Recommended packages: 172s qemu-block-extra 172s The following NEW packages will be installed: 172s autopkgtest-satdep liburing2 qemu-utils 172s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 172s Need to get 2330 kB/2331 kB of archives. 172s After this operation, 15.4 MB of additional disk space will be used. 172s Get:1 /tmp/autopkgtest.jCvjOV/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 172s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 173s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 173s Fetched 2330 kB in 1s (3326 kB/s) 173s Selecting previously unselected package liburing2:ppc64el. 173s (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 ... 72754 files and directories currently installed.) 173s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 173s Unpacking liburing2:ppc64el (2.6-1) ... 173s Selecting previously unselected package qemu-utils. 173s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 173s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 173s Selecting previously unselected package autopkgtest-satdep. 173s Preparing to unpack .../1-autopkgtest-satdep.deb ... 173s Unpacking autopkgtest-satdep (0) ... 173s Setting up liburing2:ppc64el (2.6-1) ... 173s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 173s Setting up autopkgtest-satdep (0) ... 173s Processing triggers for man-db (2.12.1-2) ... 174s Processing triggers for libc-bin (2.39-3.1ubuntu3) ... 176s (Reading database ... 72774 files and directories currently installed.) 176s Removing autopkgtest-satdep (0) ... 177s autopkgtest [22:28:47]: test kpartx-file-loopback: [----------------------- 177s Formatting 'foo.img', fmt=raw size=20971520 178s Creating new GPT entries in memory. 178s Warning: The kernel is still using the old partition table. 178s The new table will be used at the next reboot or after you 178s run partprobe(8) or kpartx(8) 178s The operation has completed successfully. 178s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 178s standard_filename: OK 179s del devmap : loop0p1 179s No devices found 179s standard_filename_cleanup: OK 179s Formatting 'fou du FaFa.img', fmt=raw size=20971520 180s Creating new GPT entries in memory. 180s Warning: The kernel is still using the old partition table. 180s The new table will be used at the next reboot or after you 180s run partprobe(8) or kpartx(8) 180s The operation has completed successfully. 180s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 180s filename_with_spaces: OK 180s del devmap : loop0p1 180s No devices found 180s filename_with_spaces_cleanup: OK 180s autopkgtest [22:28:50]: test kpartx-file-loopback: -----------------------] 181s kpartx-file-loopback PASS 181s autopkgtest [22:28:51]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 181s autopkgtest [22:28:51]: test tgtbasedmpaths: preparing testbed 325s autopkgtest [22:31:15]: testbed dpkg architecture: ppc64el 325s autopkgtest [22:31:15]: testbed apt version: 2.9.6 325s autopkgtest [22:31:15]: @@@@@@@@@@@@@@@@@@@@ test bed setup 326s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 326s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [360 kB] 326s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3288 B] 326s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 326s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [46.5 kB] 326s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [74.0 kB] 326s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2132 B] 326s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 326s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 326s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [365 kB] 326s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [9000 B] 326s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1788 B] 326s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 328s Fetched 997 kB in 1s (1230 kB/s) 328s Reading package lists... 330s Reading package lists... 330s Building dependency tree... 330s Reading state information... 330s Calculating upgrade... 331s The following packages will be upgraded: 331s libc-bin libc-dev-bin libc-devtools libc6 libc6-dev locales 331s 6 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 331s Need to get 10.1 MB of archives. 331s After this operation, 1843 kB disk space will be freed. 331s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-devtools ppc64el 2.39-3.1ubuntu3 [29.5 kB] 331s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6-dev ppc64el 2.39-3.1ubuntu3 [1982 kB] 331s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-dev-bin ppc64el 2.39-3.1ubuntu3 [21.0 kB] 331s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc6 ppc64el 2.39-3.1ubuntu3 [3174 kB] 331s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libc-bin ppc64el 2.39-3.1ubuntu3 [720 kB] 331s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el locales all 2.39-3.1ubuntu3 [4220 kB] 332s Preconfiguring packages ... 332s Fetched 10.1 MB in 1s (11.1 MB/s) 332s (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 ... 72754 files and directories currently installed.) 332s Preparing to unpack .../libc-devtools_2.39-3.1ubuntu3_ppc64el.deb ... 332s Unpacking libc-devtools (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 332s Preparing to unpack .../libc6-dev_2.39-3.1ubuntu3_ppc64el.deb ... 332s Unpacking libc6-dev:ppc64el (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 332s Preparing to unpack .../libc-dev-bin_2.39-3.1ubuntu3_ppc64el.deb ... 332s Unpacking libc-dev-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 332s Preparing to unpack .../libc6_2.39-3.1ubuntu3_ppc64el.deb ... 332s Unpacking libc6:ppc64el (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 333s Setting up libc6:ppc64el (2.39-3.1ubuntu3) ... 333s Error: Could not restart systemd, systemd binary not working 333s (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 ... 72754 files and directories currently installed.) 333s Preparing to unpack .../libc-bin_2.39-3.1ubuntu3_ppc64el.deb ... 333s Unpacking libc-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 333s Setting up libc-bin (2.39-3.1ubuntu3) ... 333s (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 ... 72754 files and directories currently installed.) 333s Preparing to unpack .../locales_2.39-3.1ubuntu3_all.deb ... 333s Unpacking locales (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 333s Setting up locales (2.39-3.1ubuntu3) ... 334s Generating locales (this might take a while)... 335s en_US.UTF-8... done 335s Generation complete. 335s Setting up libc-dev-bin (2.39-3.1ubuntu3) ... 335s Setting up libc-devtools (2.39-3.1ubuntu3) ... 335s Setting up libc6-dev:ppc64el (2.39-3.1ubuntu3) ... 335s Processing triggers for man-db (2.12.1-2) ... 336s Processing triggers for systemd (256-1ubuntu1) ... 337s Reading package lists... 337s Building dependency tree... 337s Reading state information... 337s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 337s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 337s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 338s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 338s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 338s Reading package lists... 339s Reading package lists... 339s Building dependency tree... 339s Reading state information... 339s Calculating upgrade... 339s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 339s Reading package lists... 339s Building dependency tree... 339s Reading state information... 339s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 343s Reading package lists... 343s Building dependency tree... 343s Reading state information... 343s Starting pkgProblemResolver with broken count: 0 343s Starting 2 pkgProblemResolver with broken count: 0 343s Done 343s The following additional packages will be installed: 343s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 343s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 343s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 343s librdmacm1t64 lsscsi open-iscsi tgt 344s Suggested packages: 344s fio-examples gnuplot tgt-glusterfs tgt-rbd 344s Recommended packages: 344s finalrd 344s The following NEW packages will be installed: 344s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 344s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 344s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 344s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 344s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 344s Need to get 10.7 MB/10.7 MB of archives. 344s After this operation, 49.0 MB of additional disk space will be used. 344s Get:1 /tmp/autopkgtest.jCvjOV/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 344s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 344s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 344s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 344s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2 [80.5 kB] 344s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 344s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 344s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4ubuntu1 [21.5 kB] 344s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4ubuntu1 [311 kB] 344s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4ubuntu1 [46.5 kB] 344s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4ubuntu1 [99.2 kB] 344s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-1 [97.4 kB] 344s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 344s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 344s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 344s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 344s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 344s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 345s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 345s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 345s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 345s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 345s Preconfiguring packages ... 345s Fetched 10.7 MB in 1s (9159 kB/s) 345s Selecting previously unselected package libopeniscsiusr. 345s (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 ... 72754 files and directories currently installed.) 345s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 345s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 345s Selecting previously unselected package libisns0t64:ppc64el. 345s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 345s Unpacking libisns0t64:ppc64el (0.101-1) ... 345s Selecting previously unselected package open-iscsi. 345s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 345s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 345s Selecting previously unselected package librdmacm1t64:ppc64el. 345s Preparing to unpack .../03-librdmacm1t64_52.0-2_ppc64el.deb ... 345s Unpacking librdmacm1t64:ppc64el (52.0-2) ... 345s Selecting previously unselected package libconfig-general-perl. 345s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 345s Unpacking libconfig-general-perl (2.65-2) ... 345s Selecting previously unselected package tgt. 345s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 345s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 345s Selecting previously unselected package libgfxdr0:ppc64el. 345s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_ppc64el.deb ... 345s Unpacking libgfxdr0:ppc64el (11.1-4ubuntu1) ... 345s Selecting previously unselected package libglusterfs0:ppc64el. 345s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_ppc64el.deb ... 345s Unpacking libglusterfs0:ppc64el (11.1-4ubuntu1) ... 345s Selecting previously unselected package libgfrpc0:ppc64el. 345s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_ppc64el.deb ... 345s Unpacking libgfrpc0:ppc64el (11.1-4ubuntu1) ... 345s Selecting previously unselected package libgfapi0:ppc64el. 345s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_ppc64el.deb ... 345s Unpacking libgfapi0:ppc64el (11.1-4ubuntu1) ... 345s Selecting previously unselected package libnbd0. 345s Preparing to unpack .../10-libnbd0_1.20.2-1_ppc64el.deb ... 345s Unpacking libnbd0 (1.20.2-1) ... 345s Selecting previously unselected package libdaxctl1:ppc64el. 345s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 345s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 345s Selecting previously unselected package libndctl6:ppc64el. 345s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 345s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 345s Selecting previously unselected package libpmem1:ppc64el. 345s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 345s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 345s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 345s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 345s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 345s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 345s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 345s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 345s Selecting previously unselected package librados2. 345s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 345s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 345s Selecting previously unselected package libpmemobj1:ppc64el. 345s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 345s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 345s Selecting previously unselected package librbd1. 345s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 345s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 346s Selecting previously unselected package fio. 346s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 346s Unpacking fio (3.37-1) ... 346s Selecting previously unselected package lsscsi. 346s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 346s Unpacking lsscsi (0.32-1build1) ... 346s Selecting previously unselected package autopkgtest-satdep. 346s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 346s Unpacking autopkgtest-satdep (0) ... 346s Setting up libconfig-general-perl (2.65-2) ... 346s Setting up libisns0t64:ppc64el (0.101-1) ... 346s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 346s Setting up libnbd0 (1.20.2-1) ... 346s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 346s Setting up libglusterfs0:ppc64el (11.1-4ubuntu1) ... 346s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 346s Setting up lsscsi (0.32-1build1) ... 346s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 346s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 346s Setting up librdmacm1t64:ppc64el (52.0-2) ... 346s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 346s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 347s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 347s Setting up libgfxdr0:ppc64el (11.1-4ubuntu1) ... 347s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 347s Setting up open-iscsi (2.1.10-1ubuntu1) ... 347s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 348s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 348s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 348s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 348s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 348s Setting up libgfrpc0:ppc64el (11.1-4ubuntu1) ... 348s Setting up libgfapi0:ppc64el (11.1-4ubuntu1) ... 348s Setting up fio (3.37-1) ... 348s Setting up autopkgtest-satdep (0) ... 348s Processing triggers for man-db (2.12.1-2) ... 349s Processing triggers for initramfs-tools (0.142ubuntu30) ... 349s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 349s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 356s Processing triggers for libc-bin (2.39-3.1ubuntu3) ... 358s (Reading database ... 72995 files and directories currently installed.) 358s Removing autopkgtest-satdep (0) ... 360s autopkgtest [22:31:50]: test tgtbasedmpaths: [----------------------- 360s + targetname=iqn.2016-11.foo.com:target.iscsi 360s + pwd 360s + cwd=/tmp/autopkgtest.jCvjOV/build.jG3/src 360s + testdir=/mnt/tgtmpathtest 360s + localhost=127.0.0.1 360s + portal=127.0.0.1:3260 360s + maxpaths=4 360s + backfn=backingfile 360s + expectwwid=60000000000000000e00000000010001 360s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 360s + bglog=/tmp/autopkgtest.jCvjOV/tgtbasedmpaths-artifacts/test-background.log 360s + fioprep=/tmp/autopkgtest.jCvjOV/tgtbasedmpaths-artifacts/path-change-prep.fio 360s + fiovrfy=/tmp/autopkgtest.jCvjOV/tgtbasedmpaths-artifacts/path-change-check.fio 360s + service tgt restart 361s + truncate --size 100M backingfile 361s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 361s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 361s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.jCvjOV/build.jG3/src/backingfile 361s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 361s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 361s login #1 361s + echo login #1 361s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 361s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 361s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 361s + seq 2 4 361s + echo extra login #2 361s + iscsiadm --mode session -r 1 --op new 361s extra login #2 361s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 361s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 361s + echo extra login #3 361s + iscsiadm --mode session -r 1 --op new 361s extra login #3 361s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 361s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 361s extra login #4 361s + echo extra login #4 361s + iscsiadm --mode session -r 1 --op new 361s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 361s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 361s + udevadm settle 361s + sleep 5 366s Status after initial setup 366s + echo Status after initial setup 366s + tgtadm --lld iscsi --mode target --op show 366s Target 1: iqn.2016-11.foo.com:target.iscsi 366s System information: 366s Driver: iscsi 366s State: ready 366s I_T nexus information: 366s I_T nexus: 1 366s Initiator: iqn.2004-10.com.ubuntu:01:31117d6b59ea alias: autopkgtest 366s Connection: 0 366s IP Address: 127.0.0.1 366s I_T nexus: 2 366s Initiator: iqn.2004-10.com.ubuntu:01:31117d6b59ea alias: autopkgtest 366s Connection: 0 366s IP Address: 127.0.0.1 366s I_T nexus: 3 366s Initiator: iqn.2004-10.com.ubuntu:01:31117d6b59ea alias: autopkgtest 366s Connection: 0 366s IP Address: 127.0.0.1 366s I_T nexus: 4 366s Initiator: iqn.2004-10.com.ubuntu:01:31117d6b59ea alias: autopkgtest 366s Connection: 0 366s IP Address: 127.0.0.1 366s LUN information: 366s LUN: 0 366s Type: controller 366s SCSI ID: IET 00010000 366s SCSI SN: beaf10 366s Size: 0 MB, Block size: 1 366s Online: Yes 366s Removable media: No 366s Prevent removal: No 366s Readonly: No 366s SWP: No 366s Thin-provisioning: No 366s Backing store type: null 366s Backing store path: None 366s Backing store flags: 366s LUN: 1 366s Type: disk 366s SCSI ID: IET 00010001 366s SCSI SN: beaf11 366s Size: 105 MB, Block size: 512 366s Online: Yes 366s Removable media: No 366s Prevent removal: No 366s Readonly: No 366s SWP: No 366s Thin-provisioning: No 366s Backing store type: rdwr 366s Backing store path: /tmp/autopkgtest.jCvjOV/build.jG3/src/backingfile 366s Backing store flags: 366s Account information: 366s ACL information: 366s ALL 366s Session: 4 366s Connection: 0 366s Initiator: iqn.2004-10.com.ubuntu:01:31117d6b59ea 366s IP Address: 127.0.0.1 366s Session: 3 366s Connection: 0 366s Initiator: iqn.2004-10.com.ubuntu:01:31117d6b59ea 366s IP Address: 127.0.0.1 366s Session: 2 366s Connection: 0 366s Initiator: iqn.2004-10.com.ubuntu:01:31117d6b59ea 366s IP Address: 127.0.0.1 366s Session: 1 366s Connection: 0 366s Initiator: iqn.2004-10.com.ubuntu:01:31117d6b59ea 366s IP Address: 127.0.0.1 366s + tgtadm --lld iscsi --op show --mode conn --tid 1 366s + iscsiadm --mode session -P 1 366s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 366s Current Portal: 127.0.0.1:3260,1 366s Persistent Portal: 127.0.0.1:3260,1 366s ********** 366s Interface: 366s ********** 366s Iface Name: default 366s Iface Transport: tcp 366s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:31117d6b59ea 366s Iface IPaddress: 127.0.0.1 366s Iface HWaddress: default 366s Iface Netdev: default 366s SID: 1 366s iSCSI Connection State: LOGGED IN 366s iSCSI Session State: LOGGED_IN 366s Internal iscsid Session State: NO CHANGE 366s 366s ********** 366s Interface: 366s ********** 366s Iface Name: default 366s Iface Transport: tcp 366s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:31117d6b59ea 366s Iface IPaddress: 127.0.0.1 366s Iface HWaddress: default 366s Iface Netdev: default 366s SID: 2 366s iSCSI Connection State: LOGGED IN 366s iSCSI Session State: LOGGED_IN 366s Internal iscsid Session State: NO CHANGE 366s 366s ********** 366s Interface: 366s ********** 366s Iface Name: default 366s Iface Transport: tcp 366s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:31117d6b59ea 366s Iface IPaddress: 127.0.0.1 366s Iface HWaddress: default 366s Iface Netdev: default 366s SID: 3 366s iSCSI Connection State: LOGGED IN 366s iSCSI Session State: LOGGED_IN 366s Internal iscsid Session State: NO CHANGE 366s 366s ********** 366s Interface: 366s ********** 366s Iface Name: default 366s Iface Transport: tcp 366s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:31117d6b59ea 366s Iface IPaddress: 127.0.0.1 366s Iface HWaddress: default 366s Iface Netdev: default 366s SID: 4 366s iSCSI Connection State: LOGGED IN 366s iSCSI Session State: LOGGED_IN 366s Internal iscsid Session State: NO CHANGE 366s + lsscsi -liv 366s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 366s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 366s 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] 366s [1:0:0:0] storage IET Controller 0001 - - 366s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 366s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 366s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 366s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 366s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 366s [2:0:0:0] storage IET Controller 0001 - - 366s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 366s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 366s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 366s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 366s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 366s [3:0:0:0] storage IET Controller 0001 - - 366s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 366s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 366s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 366s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 366s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 366s [4:0:0:0] storage IET Controller 0001 - - 366s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 366s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 366s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 366s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 366s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 366s NVMe module may not be loaded 366s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 366s + multipath -v3 -ll 366s 70.764170 | set open fds limit to 1073741816/1073741816 366s 70.764240 | loading /lib/multipath/libchecktur.so checker 366s 70.764318 | checker tur: message table size = 3 366s 70.764343 | loading /lib/multipath/libprioconst.so prioritizer 366s 70.764441 | _init_foreign: foreign library "nvme" is not enabled 366s 70.769971 | sda: size = 167772160 366s 70.770139 | sda: vendor = QEMU 366s 70.770180 | sda: product = QEMU HARDDISK 366s 70.770202 | sda: rev = 2.5+ 366s 70.770807 | sda: h:b:t:l = 0:0:0:0 366s 70.771146 | sda: tgt_node_name = 366s 70.771166 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 366s 70.771169 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 366s 70.771318 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 366s 70.771338 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 366s 70.771350 | __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 366s 70.771354 | failed to read sysfs vpd pg80: No such file or directory 366s 70.771552 | sda: fail to get serial 366s 70.771572 | sda: detect_checker = yes (setting: multipath internal) 366s 70.771756 | sda: path_checker = tur (setting: multipath internal) 366s 70.771777 | sda: checker timeout = 30 s (setting: kernel sysfs) 366s 70.771856 | sda: tur state = up 366s 70.772200 | sdb: size = 204800 366s 70.772362 | sdb: vendor = IET 366s 70.772402 | sdb: product = VIRTUAL-DISK 366s 70.772423 | sdb: rev = 0001 366s 70.773047 | sdb: h:b:t:l = 1:0:0:1 366s 70.773410 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 366s 70.773430 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 366s 70.773432 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 366s 70.773581 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 366s 70.773600 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 366s 70.773614 | sdb: serial = beaf11 366s 70.773616 | sdb: detect_checker = yes (setting: multipath internal) 366s ===== paths list ===== 366s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 366s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 366s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 366s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 366s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 366s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 366s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 366s size=100M features='0' hwhandler='0' wp=rw 366s |-+- policy='service-time 0' prio=1 status=active 366s | `- 1:0:0:1 sdb 8:16 active ready running 366s |-+- policy='service-time 0' prio=1 status=enabled 366s | `- 2:0:0:1 sdc 8:32 active ready running 366s |-+- policy='service-time 0' prio=1 status=enabled 366s | `- 3:0:0:1 sdd 8:48 active ready running 366s `-+- policy='service-time 0' prio=1 status=enabled 366s `- 4:0:0:1 sde 8:64 active ready running 366s 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 366s Test WWN should now point to DM 366s ../../dm-0 366s Creating filesystem with 25600 4k blocks and 25600 inodes 366s 366s Allocating group tables: 0/1 done 366s Writing inode tables: 0/1 done 366s Creating journal (1024 blocks): done 366s Writing superblocks and filesystem accounting information: 0/1 done 366s 366s 70.773935 | sdb: path_checker = tur (setting: multipath internal) 366s 70.773955 | sdb: checker timeout = 30 s (setting: kernel sysfs) 366s 70.774193 | sdb: tur state = up 366s 70.774331 | sdc: size = 204800 366s 70.774477 | sdc: vendor = IET 366s 70.774527 | sdc: product = VIRTUAL-DISK 366s 70.774550 | sdc: rev = 0001 366s 70.775233 | sdc: h:b:t:l = 2:0:0:1 366s 70.775590 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 366s 70.775609 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 366s 70.775612 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 366s 70.775753 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 366s 70.775772 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 366s 70.775785 | sdc: serial = beaf11 366s 70.775788 | sdc: detect_checker = yes (setting: multipath internal) 366s 70.775995 | sdc: path_checker = tur (setting: multipath internal) 366s 70.776006 | sdc: checker timeout = 30 s (setting: kernel sysfs) 366s 70.776223 | sdc: tur state = up 366s 70.776366 | sdd: size = 204800 366s 70.776514 | sdd: vendor = IET 366s 70.776552 | sdd: product = VIRTUAL-DISK 366s 70.776573 | sdd: rev = 0001 366s 70.777238 | sdd: h:b:t:l = 3:0:0:1 366s 70.777595 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 366s 70.777614 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 366s 70.777616 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 366s 70.777758 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 366s 70.777777 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 366s 70.777790 | sdd: serial = beaf11 366s 70.777792 | sdd: detect_checker = yes (setting: multipath internal) 366s 70.778056 | sdd: path_checker = tur (setting: multipath internal) 366s 70.778076 | sdd: checker timeout = 30 s (setting: kernel sysfs) 366s 70.778286 | sdd: tur state = up 366s 70.778427 | sde: size = 204800 366s 70.778587 | sde: vendor = IET 366s 70.778608 | sde: product = VIRTUAL-DISK 366s 70.778646 | sde: rev = 0001 366s 70.779311 | sde: h:b:t:l = 4:0:0:1 366s 70.779669 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 366s 70.779688 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 366s 70.779690 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 366s 70.779838 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 366s 70.779857 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 366s 70.779870 | sde: serial = beaf11 366s 70.779872 | sde: detect_checker = yes (setting: multipath internal) 366s 70.780143 | sde: path_checker = tur (setting: multipath internal) 366s 70.780167 | sde: checker timeout = 30 s (setting: kernel sysfs) 366s 70.780373 | sde: tur state = up 366s 70.780481 | loop0: device node name blacklisted 366s 70.780583 | loop1: device node name blacklisted 366s 70.780683 | loop2: device node name blacklisted 366s 70.780781 | loop3: device node name blacklisted 366s 70.780879 | loop4: device node name blacklisted 366s 70.780978 | loop5: device node name blacklisted 366s 70.781076 | loop6: device node name blacklisted 366s 70.781173 | loop7: device node name blacklisted 366s 70.781275 | dm-0: device node name blacklisted 366s 70.782222 | multipath-tools v0.9.4 (12/19, 2022) 366s 70.782249 | libdevmapper version 1.02.185 366s 70.782381 | kernel device mapper v4.48.0 366s 70.782406 | DM multipath kernel driver v1.14.0 366s 70.782507 | sdb: size = 204800 366s 70.782540 | sdb: vendor = IET 366s 70.782543 | sdb: product = VIRTUAL-DISK 366s 70.782545 | sdb: rev = 0001 366s 70.783155 | sdb: h:b:t:l = 1:0:0:1 366s 70.783283 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 366s 70.783319 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 366s 70.783322 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 366s 70.783333 | sdb: serial = beaf11 366s 70.783553 | sdb: tur state = up 366s 70.783572 | sdb: uid = 360000000000000000e00000000010001 (udev) 366s 70.783575 | sdb: detect_prio = yes (setting: multipath internal) 366s 70.783578 | sdb: prio = const (setting: multipath internal) 366s 70.783580 | sdb: prio args = "" (setting: multipath internal) 366s 70.783583 | sdb: const prio = 1 366s 70.783606 | sdc: size = 204800 366s 70.783610 | sdc: vendor = IET 366s 70.783612 | sdc: product = VIRTUAL-DISK 366s 70.783616 | sdc: rev = 0001 366s 70.784236 | sdc: h:b:t:l = 2:0:0:1 366s 70.784366 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 366s 70.784401 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 366s 70.784404 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 366s 70.784416 | sdc: serial = beaf11 366s 70.784630 | sdc: tur state = up 366s 70.784649 | sdc: uid = 360000000000000000e00000000010001 (udev) 366s 70.784652 | sdc: detect_prio = yes (setting: multipath internal) 366s 70.784654 | sdc: prio = const (setting: multipath internal) 366s 70.784656 | sdc: prio args = "" (setting: multipath internal) 366s 70.784659 | sdc: const prio = 1 366s 70.784682 | sdd: size = 204800 366s 70.784686 | sdd: vendor = IET 366s 70.784688 | sdd: product = VIRTUAL-DISK 366s 70.784690 | sdd: rev = 0001 366s 70.785287 | sdd: h:b:t:l = 3:0:0:1 366s 70.785412 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 366s 70.785447 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 366s 70.785449 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 366s 70.785461 | sdd: serial = beaf11 366s 70.785671 | sdd: tur state = up 366s 70.785690 | sdd: uid = 360000000000000000e00000000010001 (udev) 366s 70.785693 | sdd: detect_prio = yes (setting: multipath internal) 366s 70.785695 | sdd: prio = const (setting: multipath internal) 366s 70.785697 | sdd: prio args = "" (setting: multipath internal) 366s 70.785700 | sdd: const prio = 1 366s 70.785722 | sde: size = 204800 366s 70.785726 | sde: vendor = IET 366s 70.785728 | sde: product = VIRTUAL-DISK 366s 70.785731 | sde: rev = 0001 366s 70.786325 | sde: h:b:t:l = 4:0:0:1 366s 70.786450 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 366s 70.786484 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 366s 70.786487 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 366s 70.786498 | sde: serial = beaf11 366s 70.786742 | sde: tur state = up 366s 70.786761 | sde: uid = 360000000000000000e00000000010001 (udev) 366s 70.786764 | sde: detect_prio = yes (setting: multipath internal) 366s 70.786766 | sde: prio = const (setting: multipath internal) 366s 70.786769 | sde: prio args = "" (setting: multipath internal) 366s 70.786771 | sde: const prio = 1 366s 70.787558 | unloading tur checker 366s 70.787606 | unloading const prioritizer 366s + dmsetup table 366s + echo Test WWN should now point to DM 366s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 366s + grep dm 366s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 366s mke2fs 1.47.1 (20-May-2024) 366s + udevadm settle 366s + sleep 3s 369s + mkdir -p /mnt/tgtmpathtest 369s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 369s + cat 369s + cat 369s + fio --max-jobs=4 /tmp/autopkgtest.jCvjOV/tgtbasedmpaths-artifacts/path-change-prep.fio 369s 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 369s fio-3.37 369s Starting 1 thread 369s write-phase: Laying out IO file (1 file / 17592186044415MiB) 370s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91750400, buflen=65536 370s 370s write-phase: (groupid=0, jobs=1): err= 0: pid=7178: Fri Jul 12 22:32:00 2024 370s write: IOPS=2346, BW=147MiB/s (154MB/s)(87.5MiB/597msec); 0 zone resets 370s clat (usec): min=257, max=1841, avg=408.01, stdev=97.94 370s lat (usec): min=277, max=1854, avg=425.07, stdev=98.94 370s clat percentiles (usec): 370s | 1.00th=[ 265], 5.00th=[ 310], 10.00th=[ 322], 20.00th=[ 347], 370s | 30.00th=[ 367], 40.00th=[ 379], 50.00th=[ 392], 60.00th=[ 404], 370s | 70.00th=[ 441], 80.00th=[ 469], 90.00th=[ 502], 95.00th=[ 529], 370s | 99.00th=[ 635], 99.50th=[ 725], 99.90th=[ 1745], 99.95th=[ 1844], 370s | 99.99th=[ 1844] 370s bw ( KiB/s): min=147584, max=147584, per=98.33%, avg=147584.00, stdev= 0.00, samples=1 370s iops : min= 2306, max= 2306, avg=2306.00, stdev= 0.00, samples=1 370s lat (usec) : 500=89.08%, 750=10.35% 370s lat (msec) : 2=0.50% 370s cpu : usr=6.54%, sys=5.03%, ctx=1402, majf=0, minf=0 370s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 370s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 370s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 370s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 370s latency : target=0, window=0, percentile=100.00%, depth=1 370s 370s Run status group 0 (all jobs): 370s WRITE: bw=147MiB/s (154MB/s), 147MiB/s-147MiB/s (154MB/s-154MB/s), io=87.5MiB (91.8MB), run=597-597msec 370s 370s Disk stats (read/write): 370s dm-0: ios=1/866, sectors=8/110848, merge=0/0, ticks=0/359, in_queue=359, util=79.84%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/133, aggrin_queue=133, aggrutil=84.03% 370s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 370s sdb: ios=1/1402, sectors=8/179280, merge=0/0, ticks=1/534, in_queue=535, util=84.03% 370s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 370s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 370s + echo Starting the path changes in background 370s Starting the path changes in background 370s + date +Pre FIO %H:%M:%S.%N 370s Pre FIO 22:32:00.231758144 370s + fio --max-jobs=4 /tmp/autopkgtest.jCvjOV/tgtbasedmpaths-artifacts/path-change-check.fio 370s 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 370s fio-3.37 370s Starting 1 thread 550s 550s verify-phase: (groupid=0, jobs=1): err= 0: pid=7185: Fri Jul 12 22:35:00 2024 550s read: IOPS=3684, BW=230MiB/s (241MB/s)(40.5GiB/180001msec) 550s clat (usec): min=83, max=57682, avg=249.03, stdev=244.03 550s lat (usec): min=83, max=57682, avg=249.14, stdev=244.03 550s clat percentiles (usec): 550s | 1.00th=[ 99], 5.00th=[ 145], 10.00th=[ 153], 20.00th=[ 182], 550s | 30.00th=[ 194], 40.00th=[ 206], 50.00th=[ 221], 60.00th=[ 265], 550s | 70.00th=[ 285], 80.00th=[ 314], 90.00th=[ 351], 95.00th=[ 371], 550s | 99.00th=[ 453], 99.50th=[ 685], 99.90th=[ 1516], 99.95th=[ 2311], 550s | 99.99th=[ 5997] 550s bw ( KiB/s): min=133632, max=385152, per=100.00%, avg=235885.68, stdev=54591.27, samples=359 550s iops : min= 2088, max= 6018, avg=3685.71, stdev=852.98, samples=359 550s lat (usec) : 100=1.08%, 250=55.60%, 500=42.58%, 750=0.28%, 1000=0.18% 550s lat (msec) : 2=0.20%, 4=0.04%, 10=0.01%, 20=0.01%, 50=0.01% 550s lat (msec) : 100=0.01% 550s cpu : usr=9.92%, sys=7.05%, ctx=663264, majf=0, minf=1 550s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 550s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 550s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 550s issued rwts: total=663172,0,0,0 short=0,0,0,0 dropped=0,0,0,0 550s latency : target=0, window=0, percentile=100.00%, depth=1 550s 550s Run status group 0 (all jobs): 550s READ: bw=230MiB/s (241MB/s), 230MiB/s-230MiB/s (241MB/s-241MB/s), io=40.5GiB (43.5GB), run=180001-180001msec 550s 550s Disk stats (read/write): 550s dm-0: ios=663182/11, sectors=84826296/12944, merge=31/10, ticks=165882/60, in_queue=165973, util=99.96%, aggrios=41322/2, aggsectors=5285358/3236, aggrmerge=0/0, aggrticks=10780/6, aggrin_queue=10787, aggrutil=99.11% 550s sdd: ios=28838/0, sectors=3688704/0, merge=0/0, ticks=8780/0, in_queue=8780, util=32.90% 550s sdb: ios=32109/10, sectors=4106880/12944, merge=0/0, ticks=8446/26, in_queue=8472, util=99.11% 550s sde: ios=70032/0, sectors=8957696/0, merge=0/0, ticks=17215/0, in_queue=17215, util=39.56% 550s sdc: ios=34311/0, sectors=4388152/0, merge=0/0, ticks=8682/0, in_queue=8683, util=50.02% 550s Post FIO 22:35:00.570150407 550s FIO verify test with changing paths - OK 550s Report log of background activity 550s + date +Post FIO %H:%M:%S.%N 550s + echo FIO verify test with changing paths - OK 550s + echo Report log of background activity 550s + cat /tmp/autopkgtest.jCvjOV/tgtbasedmpaths-artifacts/test-background.log 550s + iscsiadm --mode session 550s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s + sleep 10s 550s + date +MP report (expect 4) %H:%M:%S.%N 550s MP report (expect 4) 22:32:10.240925443 550s + multipath -ll 550s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 550s size=100M features='0' hwhandler='0' wp=rw 550s |-+- policy='service-time 0' prio=1 status=active 550s | `- 1:0:0:1 sdb 8:16 active ready running 550s |-+- policy='service-time 0' prio=1 status=enabled 550s | `- 2:0:0:1 sdc 8:32 active ready running 550s |-+- policy='service-time 0' prio=1 status=enabled 550s | `- 3:0:0:1 sdd 8:48 active ready running 550s `-+- policy='service-time 0' prio=1 status=enabled 550s `- 4:0:0:1 sde 8:64 active ready running 550s + date +UN-plug path 1 %H:%M:%S.%N 550s UN-plug path 1 22:32:10.265898093 550s + iscsiadm --mode session -r 1 -u 550s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 550s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 550s + iscsiadm --mode session 550s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s + sleep 10s 550s + date +MP report (expect 3) %H:%M:%S.%N 550s MP report (expect 3) 22:32:20.377615504 550s + multipath -ll 550s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 550s size=100M features='0' hwhandler='0' wp=rw 550s |-+- policy='service-time 0' prio=1 status=active 550s | `- 2:0:0:1 sdc 8:32 active ready running 550s |-+- policy='service-time 0' prio=1 status=enabled 550s | `- 3:0:0:1 sdd 8:48 active ready running 550s `-+- policy='service-time 0' prio=1 status=enabled 550s `- 4:0:0:1 sde 8:64 active ready running 550s + date +UN-plug path 2 %H:%M:%S.%N 550s UN-plug path 2 22:32:20.401332998 550s + iscsiadm --mode session -r 2 -u 550s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 550s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 550s + iscsiadm --mode session 550s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s + sleep 10s 550s + date +MP report (expect 2) %H:%M:%S.%N 550s MP report (expect 2) 22:32:30.490107693 550s + multipath -ll 550s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 550s size=100M features='0' hwhandler='0' wp=rw 550s |-+- policy='service-time 0' prio=1 status=active 550s | `- 3:0:0:1 sdd 8:48 active ready running 550s `-+- policy='service-time 0' prio=1 status=enabled 550s `- 4:0:0:1 sde 8:64 active ready running 550s + date +UN-plug path 3 %H:%M:%S.%N 550s UN-plug path 3 22:32:30.507336428 550s + iscsiadm --mode session -r 3 -u 550s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 550s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 550s + iscsiadm --mode session 550s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s + sleep 10s 550s + date +MP report (expect 1) %H:%M:%S.%N 550s MP report (expect 1) 22:32:40.572903607 550s + multipath -ll 550s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 550s size=100M features='0' hwhandler='0' wp=rw 550s `-+- policy='service-time 0' prio=1 status=active 550s `- 4:0:0:1 sde 8:64 active ready running 550s + date +Add paths 5/6/7/8 %H:%M:%S.%N 550s Add paths 5/6/7/8 22:32:40.586923179 550s + iscsiadm --mode session -r 4 --op new 550s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 550s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 550s + iscsiadm --mode session -r 4 --op new 550s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 550s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 550s + iscsiadm --mode session -r 4 --op new 550s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 550s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 550s + iscsiadm --mode session -r 4 --op new 550s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 550s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 550s + iscsiadm --mode session 550s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s + sleep 10s 550s + date +MP report (expect 5) %H:%M:%S.%N 550s MP report (expect 5) 22:32:50.725752963 550s + multipath -ll 550s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 550s size=100M features='0' hwhandler='0' wp=rw 550s |-+- policy='service-time 0' prio=1 status=active 550s | `- 4:0:0:1 sde 8:64 active ready running 550s |-+- policy='service-time 0' prio=1 status=enabled 550s | `- 1:0:0:1 sdb 8:16 active ready running 550s |-+- policy='service-time 0' prio=1 status=enabled 550s | `- 2:0:0:1 sdc 8:32 active ready running 550s |-+- policy='service-time 0' prio=1 status=enabled 550s | `- 3:0:0:1 sdd 8:48 active ready running 550s `-+- policy='service-time 0' prio=1 status=enabled 550s `- 5:0:0:1 sdf 8:80 active ready running 550s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 550s UN-plug multiple paths 4/7/8 22:32:50.755337264 550s + iscsiadm --mode session -r 4 -u 550s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 550s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 550s + iscsiadm --mode session -r 7 -u 550s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 550s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 550s + iscsiadm --mode session -r 8 -u 550s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 550s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 550s + iscsiadm --mode session 550s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 550s + sleep 10s 550s + date +Restart multipath daemon %H:%M:%S.%N 550s Restart multipath daemon 22:33:01.021249813 550s + systemctl restart multipathd 550s + sleep 10s 550s + date +Final background report (expect 2) %H:%M:%S.%N 550s Final background report (expect 2) 22:33:11.094029479 550s + multipath -ll 550s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 550s size=100M features='0' hwhandler='0' wp=rw 550s |-+- policy='service-time 0' prio=1 status=active 550s | `- 1:0:0:1 sdb 8:16 active ready running 550s `-+- policy='service-time 0' prio=1 status=enabled 550s `- 2:0:0:1 sdc 8:32 active ready running 550s Final stats 550s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 550s iSCSI SNMP: 550s txdata_octets: 23827320 550s rxdata_octets: 32509224932 550s noptx_pdus: 0 550s scsicmd_pdus: 496135 550s tmfcmd_pdus: 0 550s login_pdus: 0 550s text_pdus: 0 550s dataout_pdus: 0 550s logout_pdus: 0 550s snack_pdus: 0 550s noprx_pdus: 0 550s scsirsp_pdus: 496135 550s tmfrsp_pdus: 0 550s textrsp_pdus: 0 550s datain_pdus: 496102 550s logoutrsp_pdus: 0 550s r2t_pdus: 0 550s async_pdus: 0 550s rjt_pdus: 0 550s digest_err: 0 550s timeout_err: 0 550s iSCSI Extended: 550s tx_sendpage_failures: 0 550s rx_discontiguous_hdr: 0 550s eh_abort_cnt: 0 550s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 550s iSCSI SNMP: 550s txdata_octets: 6456 550s rxdata_octets: 1514916 550s noptx_pdus: 0 550s scsicmd_pdus: 105 550s tmfcmd_pdus: 0 550s login_pdus: 0 550s text_pdus: 0 550s dataout_pdus: 0 550s logout_pdus: 0 550s snack_pdus: 0 550s noprx_pdus: 0 550s scsirsp_pdus: 105 550s tmfrsp_pdus: 0 550s textrsp_pdus: 0 550s datain_pdus: 83 550s logoutrsp_pdus: 0 550s r2t_pdus: 0 550s async_pdus: 0 550s rjt_pdus: 0 550s digest_err: 0 550s timeout_err: 0 550s iSCSI Extended: 550s tx_sendpage_failures: 0 550s rx_discontiguous_hdr: 0 550s eh_abort_cnt: 0 550s + sync 550s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 550s + echo Final stats 550s + iscsiadm --mode session --stats 550s + journalctl --no-pager -u multipathd 550s + echo Check final path status 550s + multipath -ll 550s + multipath -ll 550s + grep --count status= 550s + diskc=2 550s + multipath -ll 550s + grep --count status=active 550s Jul 12 21:05:47 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 550s Jul 12 21:05:47 ubuntu multipathd[330]: multipathd v0.9.4: start up 550s Jul 12 21:05:47 ubuntu multipathd[330]: reconfigure: setting up paths and maps 550s Jul 12 21:05:47 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 550s Jul 12 21:09:08 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[330]: multipathd: shut down 550s Jul 12 21:09:08 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 550s Jul 12 21:09:08 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: multipathd.service: Deactivated successfully. 550s Jul 12 21:09:08 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 550s -- Boot 42eb1aa402424898b15d1dc5c86ee4ab -- 550s Jul 12 21:09:34 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 550s Jul 12 21:09:34 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[290]: multipathd v0.9.4: start up 550s Jul 12 21:09:34 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[290]: reconfigure: setting up paths and maps 550s Jul 12 21:09:34 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 550s Jul 12 21:09:53 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[290]: multipathd: shut down 550s Jul 12 21:09:53 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 550s Jul 12 21:09:53 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: multipathd.service: Deactivated successfully. 550s Jul 12 21:09:53 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 550s -- Boot 45c316d851a1498f8124d2c176a046b8 -- 550s Jul 12 22:30:47 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 550s Jul 12 22:30:47 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[342]: multipathd v0.9.4: start up 550s Jul 12 22:30:47 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 multipathd[342]: reconfigure: setting up paths and maps 550s Jul 12 22:30:47 auto-syncubuntu-oracular-daily-ppc64el-server-20240626-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 550s Jul 12 22:31:51 autopkgtest multipathd[342]: 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] 550s Jul 12 22:31:51 autopkgtest multipathd[342]: sdc [8:32]: path added to devmap mpatha 550s Jul 12 22:31:51 autopkgtest multipathd[342]: mpatha: performing delayed actions 550s Jul 12 22:31:51 autopkgtest multipathd[342]: 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] 550s Jul 12 22:32:10 autopkgtest multipathd[342]: 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] 550s Jul 12 22:32:10 autopkgtest multipathd[342]: check_removed_paths: sdb: freeing path in removed state 550s Jul 12 22:32:10 autopkgtest multipathd[342]: 8:16: path removed from map mpatha 550s Jul 12 22:32:20 autopkgtest multipathd[342]: 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] 550s Jul 12 22:32:20 autopkgtest multipathd[342]: check_removed_paths: sdc: freeing path in removed state 550s Jul 12 22:32:20 autopkgtest multipathd[342]: 8:32: path removed from map mpatha 550s Jul 12 22:32:30 autopkgtest multipathd[342]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 550s Jul 12 22:32:30 autopkgtest multipathd[342]: check_removed_paths: sdd: freeing path in removed state 550s Jul 12 22:32:30 autopkgtest multipathd[342]: 8:48: path removed from map mpatha 550s Jul 12 22:32:40 autopkgtest multipathd[342]: 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] 550s Jul 12 22:32:40 autopkgtest multipathd[342]: sdb [8:16]: path added to devmap mpatha 550s Jul 12 22:32:40 autopkgtest multipathd[342]: 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] 550s Jul 12 22:32:40 autopkgtest multipathd[342]: sdc [8:32]: path added to devmap mpatha 550s Jul 12 22:32:40 autopkgtest multipathd[342]: 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] 550s Jul 12 22:32:40 autopkgtest multipathd[342]: sdd [8:48]: path added to devmap mpatha 550s Jul 12 22:32:40 autopkgtest multipathd[342]: 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] 550s Jul 12 22:32:40 autopkgtest multipathd[342]: sdf [8:80]: path added to devmap mpatha 550s Jul 12 22:32:50 autopkgtest multipathd[342]: 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] 550s Jul 12 22:32:50 autopkgtest multipathd[342]: check_removed_paths: sde: freeing path in removed state 550s Jul 12 22:32:50 autopkgtest multipathd[342]: 8:64: path removed from map mpatha 550s Jul 12 22:32:50 autopkgtest multipathd[342]: 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] 550s Jul 12 22:32:50 autopkgtest multipathd[342]: check_removed_paths: sdd: freeing path in removed state 550s Jul 12 22:32:50 autopkgtest multipathd[342]: 8:48: path removed from map mpatha 550s Jul 12 22:32:50 autopkgtest multipathd[342]: 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] 550s Jul 12 22:32:50 autopkgtest multipathd[342]: check_removed_paths: sdf: freeing path in removed state 550s Jul 12 22:32:50 autopkgtest multipathd[342]: 8:80: path removed from map mpatha 550s Jul 12 22:33:01 autopkgtest multipathd[342]: multipathd: shut down 550s Jul 12 22:33:01 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 550s Jul 12 22:33:01 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 550s Jul 12 22:33:01 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 550s Jul 12 22:33:01 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 550s Jul 12 22:33:01 autopkgtest multipathd[7551]: multipathd v0.9.4: start up 550s Jul 12 22:33:01 autopkgtest multipathd[7551]: reconfigure: setting up paths and maps 550s Jul 12 22:33:01 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 550s Check final path status 550s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 550s size=100M features='0' hwhandler='0' wp=rw 550s |-+- policy='service-time 0' prio=1 status=active 550s | `- 1:0:0:1 sdb 8:16 active ready running 550s `-+- policy='service-time 0' prio=1 status=enabled 550s `- 2:0:0:1 sdc 8:32 active ready running 550s + diska=1 550s + multipath -ll 550s + grep --count status=enabled 550s OK 550s + diske=1 550s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 550s + echo OK 550s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 550s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 550s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 550s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 550s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 550s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 551s autopkgtest [22:35:01]: test tgtbasedmpaths: -----------------------] 551s autopkgtest [22:35:01]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 551s tgtbasedmpaths PASS 552s autopkgtest [22:35:02]: @@@@@@@@@@@@@@@@@@@@ summary 552s kpartx-file-loopback PASS 552s tgtbasedmpaths PASS 562s nova [W] Using flock in scalingstack-bos02-ppc64el 562s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240712-222550-juju-7f2275-prod-proposed-migration-environment-3-ad789904-a72e-4042-b77e-762d628562bf from image adt/ubuntu-oracular-ppc64el-server-20240712.img (UUID 740e1066-971a-4f95-9033-0eb4cf07697e)... 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-20240712-222550-juju-7f2275-prod-proposed-migration-environment-3-ad789904-a72e-4042-b77e-762d628562bf from image adt/ubuntu-oracular-ppc64el-server-20240712.img (UUID 740e1066-971a-4f95-9033-0eb4cf07697e)...