0s autopkgtest [23:40:56]: starting date and time: 2024-03-25 23:40:56+0000 0s autopkgtest [23:40:56]: git checkout: 4a1cd702 l/adt_testbed: don't blame the testbed for unsolvable build deps 0s autopkgtest [23:40:56]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.jrxky2fl/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --setup-commands /home/ubuntu/autopkgtest/setup-commands/setup-testbed --apt-pocket=proposed --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=qemu/1:8.2.1+ds-1ubuntu8 alsa-lib/1.2.11-1build1 at-spi2-core/2.51.90-3 ceph/19.2.0~git20240301.4c76c50-0ubuntu3 cups/2.4.7-1.2ubuntu1 curl/8.5.0-2ubuntu8 glib2.0/2.79.3-3ubuntu5 gnutls28/3.8.3-1.1ubuntu2 gtk+3.0/3.24.41-1.1ubuntu3 libpng1.6/1.6.43-3 libpsl/0.21.2-1.1 nettle/3.9.1-2.2 openssl/3.0.13-0ubuntu2 pipewire/1.0.4-2ubuntu2 usbredir/0.13.0-2.1 wp2latex/4.4~ds-1build1' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos02-ppc64el-16.secgroup --name adt-noble-ppc64el-multipath-tools-20240325-234056-juju-7f2275-prod-proposed-migration-environment-2 --image adt/ubuntu-noble-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 91s autopkgtest [23:42:27]: testbed dpkg architecture: ppc64el 92s autopkgtest [23:42:28]: testbed apt version: 2.7.12 92s autopkgtest [23:42:28]: @@@@@@@@@@@@@@@@@@@@ test bed setup 93s Get:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease [117 kB] 93s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/multiverse Sources [56.0 kB] 93s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/universe Sources [3998 kB] 95s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/restricted Sources [7592 B] 95s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/main Sources [497 kB] 95s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el Packages [700 kB] 95s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el c-n-f Metadata [3116 B] 95s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/restricted ppc64el Packages [1372 B] 95s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/restricted ppc64el c-n-f Metadata [116 B] 95s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/universe ppc64el Packages [4231 kB] 96s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/universe ppc64el c-n-f Metadata [8652 B] 96s Get:12 http://ftpmaster.internal/ubuntu noble-proposed/multiverse ppc64el Packages [61.7 kB] 96s Get:13 http://ftpmaster.internal/ubuntu noble-proposed/multiverse ppc64el c-n-f Metadata [116 B] 99s Fetched 9681 kB in 4s (2272 kB/s) 99s Reading package lists... 101s Reading package lists... 101s Building dependency tree... 101s Reading state information... 101s Calculating upgrade... 102s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 102s Reading package lists... 102s Building dependency tree... 102s Reading state information... 102s 0 upgraded, 0 newly installed, 0 to remove and 246 not upgraded. 103s sh: Attempting to set up Debian/Ubuntu apt sources automatically 103s sh: Distribution appears to be Ubuntu 103s Reading package lists... 104s Building dependency tree... 104s Reading state information... 104s eatmydata is already the newest version (131-1). 104s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 104s Reading package lists... 104s Building dependency tree... 104s Reading state information... 104s dbus is already the newest version (1.14.10-4ubuntu1). 104s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 104s Reading package lists... 104s Building dependency tree... 104s Reading state information... 105s rng-tools-debian is already the newest version (2.4). 105s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 105s Reading package lists... 105s Building dependency tree... 105s Reading state information... 105s The following packages will be REMOVED: 105s cloud-init* python3-configobj* python3-debconf* 105s 0 upgraded, 0 newly installed, 3 to remove and 0 not upgraded. 105s After this operation, 3256 kB disk space will be freed. 105s (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 ... 70156 files and directories currently installed.) 105s Removing cloud-init (24.1.2-0ubuntu1) ... 106s Removing python3-configobj (5.0.8-3) ... 106s Removing python3-debconf (1.5.86) ... 106s Processing triggers for man-db (2.12.0-3) ... 106s (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 ... 69767 files and directories currently installed.) 106s Purging configuration files for cloud-init (24.1.2-0ubuntu1) ... 107s dpkg: warning: while removing cloud-init, directory '/etc/cloud/cloud.cfg.d' not empty so not removed 107s Processing triggers for rsyslog (8.2312.0-3ubuntu3) ... 107s invoke-rc.d: policy-rc.d denied execution of try-restart. 107s Reading package lists... 107s Building dependency tree... 107s Reading state information... 107s linux-generic is already the newest version (6.8.0-11.11+1). 107s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 108s Hit:1 http://ftpmaster.internal/ubuntu noble InRelease 108s Hit:2 http://ftpmaster.internal/ubuntu noble-updates InRelease 108s Hit:3 http://ftpmaster.internal/ubuntu noble-security InRelease 110s Reading package lists... 110s Reading package lists... 110s Building dependency tree... 110s Reading state information... 110s Calculating upgrade... 111s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 111s Reading package lists... 111s Building dependency tree... 111s Reading state information... 111s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 111s autopkgtest [23:42:47]: rebooting testbed after setup commands that affected boot 274s autopkgtest [23:45:30]: testbed running kernel: Linux 6.8.0-11-generic #11-Ubuntu SMP Wed Feb 14 00:33:03 UTC 2024 276s autopkgtest [23:45:32]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 281s Get:1 http://ftpmaster.internal/ubuntu noble/main multipath-tools 0.9.4-5ubuntu3 (dsc) [2733 B] 281s Get:2 http://ftpmaster.internal/ubuntu noble/main multipath-tools 0.9.4-5ubuntu3 (tar) [554 kB] 281s Get:3 http://ftpmaster.internal/ubuntu noble/main multipath-tools 0.9.4-5ubuntu3 (diff) [42.6 kB] 281s gpgv: Signature made Wed Sep 6 23:15:24 2023 UTC 281s gpgv: using RSA key 8A2044F84F716A85B77FF76311DF4294CCA39893 281s gpgv: Can't check signature: No public key 281s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu3.dsc: no acceptable signature found 281s autopkgtest [23:45:37]: testing package multipath-tools version 0.9.4-5ubuntu3 281s autopkgtest [23:45:37]: build not needed 282s autopkgtest [23:45:38]: test kpartx-file-loopback: preparing testbed 283s Reading package lists... 283s Building dependency tree... 283s Reading state information... 283s Starting pkgProblemResolver with broken count: 0 283s Starting 2 pkgProblemResolver with broken count: 0 283s Done 284s The following additional packages will be installed: 284s liburing2 qemu-utils 284s Recommended packages: 284s qemu-block-extra 284s The following NEW packages will be installed: 284s autopkgtest-satdep liburing2 qemu-utils 284s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 284s Need to get 2323 kB/2324 kB of archives. 284s After this operation, 15.4 MB of additional disk space will be used. 284s Get:1 /tmp/autopkgtest.CVimhz/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 284s Get:2 http://ftpmaster.internal/ubuntu noble/main ppc64el liburing2 ppc64el 2.5-1 [25.2 kB] 284s Get:3 http://ftpmaster.internal/ubuntu noble/main ppc64el qemu-utils ppc64el 1:8.2.1+ds-1ubuntu1 [2298 kB] 285s Fetched 2323 kB in 1s (2004 kB/s) 285s Selecting previously unselected package liburing2:ppc64el. 285s (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 ... 69712 files and directories currently installed.) 285s Preparing to unpack .../liburing2_2.5-1_ppc64el.deb ... 285s Unpacking liburing2:ppc64el (2.5-1) ... 285s Selecting previously unselected package qemu-utils. 285s Preparing to unpack .../qemu-utils_1%3a8.2.1+ds-1ubuntu1_ppc64el.deb ... 285s Unpacking qemu-utils (1:8.2.1+ds-1ubuntu1) ... 285s Selecting previously unselected package autopkgtest-satdep. 285s Preparing to unpack .../1-autopkgtest-satdep.deb ... 285s Unpacking autopkgtest-satdep (0) ... 285s Setting up liburing2:ppc64el (2.5-1) ... 285s Setting up qemu-utils (1:8.2.1+ds-1ubuntu1) ... 285s Setting up autopkgtest-satdep (0) ... 285s Processing triggers for man-db (2.12.0-3) ... 286s Processing triggers for libc-bin (2.39-0ubuntu6) ... 288s (Reading database ... 69732 files and directories currently installed.) 288s Removing autopkgtest-satdep (0) ... 289s autopkgtest [23:45:45]: test kpartx-file-loopback: [----------------------- 289s Formatting 'foo.img', fmt=raw size=20971520 292s Creating new GPT entries in memory. 292s Warning: The kernel is still using the old partition table. 292s The new table will be used at the next reboot or after you 292s run partprobe(8) or kpartx(8) 292s The operation has completed successfully. 292s autopkgtest [23:45:48]: test kpartx-file-loopback: -----------------------] 292s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 292s standard_filename: OK 292s del devmap : loop0p1 292s No devices found 292s standard_filename_cleanup: OK 292s Formatting 'fou du FaFa.img', fmt=raw size=20971520 292s Creating new GPT entries in memory. 292s Warning: The kernel is still using the old partition table. 292s The new table will be used at the next reboot or after you 292s run partprobe(8) or kpartx(8) 292s The operation has completed successfully. 292s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 292s filename_with_spaces: OK 292s del devmap : loop0p1 292s No devices found 292s filename_with_spaces_cleanup: OK 292s kpartx-file-loopback PASS 292s autopkgtest [23:45:48]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 293s autopkgtest [23:45:49]: test tgtbasedmpaths: preparing testbed 487s autopkgtest [23:49:03]: testbed dpkg architecture: ppc64el 487s autopkgtest [23:49:03]: testbed apt version: 2.7.12 487s autopkgtest [23:49:03]: @@@@@@@@@@@@@@@@@@@@ test bed setup 488s Get:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease [117 kB] 488s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/main Sources [497 kB] 489s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/restricted Sources [7592 B] 489s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/universe Sources [3998 kB] 489s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/multiverse Sources [56.0 kB] 489s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el Packages [700 kB] 489s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main ppc64el c-n-f Metadata [3116 B] 489s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/restricted ppc64el Packages [1372 B] 489s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/restricted ppc64el c-n-f Metadata [116 B] 489s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/universe ppc64el Packages [4231 kB] 489s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/universe ppc64el c-n-f Metadata [8652 B] 489s Get:12 http://ftpmaster.internal/ubuntu noble-proposed/multiverse ppc64el Packages [61.7 kB] 489s Get:13 http://ftpmaster.internal/ubuntu noble-proposed/multiverse ppc64el c-n-f Metadata [116 B] 493s Fetched 9681 kB in 2s (4091 kB/s) 493s Reading package lists... 495s Reading package lists... 495s Building dependency tree... 495s Reading state information... 495s Calculating upgrade... 495s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 496s Reading package lists... 496s Building dependency tree... 496s Reading state information... 496s 0 upgraded, 0 newly installed, 0 to remove and 246 not upgraded. 497s sh: Attempting to set up Debian/Ubuntu apt sources automatically 497s sh: Distribution appears to be Ubuntu 498s Reading package lists... 498s Building dependency tree... 498s Reading state information... 498s eatmydata is already the newest version (131-1). 498s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 498s Reading package lists... 498s Building dependency tree... 498s Reading state information... 498s dbus is already the newest version (1.14.10-4ubuntu1). 498s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 499s Reading package lists... 499s Building dependency tree... 499s Reading state information... 499s rng-tools-debian is already the newest version (2.4). 499s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 499s Reading package lists... 499s Building dependency tree... 499s Reading state information... 499s The following packages will be REMOVED: 499s cloud-init* python3-configobj* python3-debconf* 500s 0 upgraded, 0 newly installed, 3 to remove and 0 not upgraded. 500s After this operation, 3256 kB disk space will be freed. 500s (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 ... 70156 files and directories currently installed.) 500s Removing cloud-init (24.1.2-0ubuntu1) ... 500s Removing python3-configobj (5.0.8-3) ... 500s Removing python3-debconf (1.5.86) ... 500s Processing triggers for man-db (2.12.0-3) ... 501s (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 ... 69767 files and directories currently installed.) 501s Purging configuration files for cloud-init (24.1.2-0ubuntu1) ... 502s dpkg: warning: while removing cloud-init, directory '/etc/cloud/cloud.cfg.d' not empty so not removed 502s Processing triggers for rsyslog (8.2312.0-3ubuntu3) ... 502s invoke-rc.d: policy-rc.d denied execution of try-restart. 502s Reading package lists... 502s Building dependency tree... 502s Reading state information... 502s linux-generic is already the newest version (6.8.0-11.11+1). 502s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 503s Hit:1 http://ftpmaster.internal/ubuntu noble InRelease 503s Hit:2 http://ftpmaster.internal/ubuntu noble-updates InRelease 503s Hit:3 http://ftpmaster.internal/ubuntu noble-security InRelease 506s Reading package lists... 506s Reading package lists... 506s Building dependency tree... 506s Reading state information... 506s Calculating upgrade... 506s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 506s Reading package lists... 506s Building dependency tree... 506s Reading state information... 506s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 507s autopkgtest [23:49:23]: rebooting testbed after setup commands that affected boot 680s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 691s Reading package lists... 692s Building dependency tree... 692s Reading state information... 692s Starting pkgProblemResolver with broken count: 0 692s Starting 2 pkgProblemResolver with broken count: 0 692s Done 693s The following additional packages will be installed: 693s fio libaio1t64 libboost-iostreams1.83.0 libboost-thread1.83.0 693s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 693s libglusterfs0 libisns0 libnbd0 libndctl6 libopeniscsiusr libpmem1 693s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 693s Suggested packages: 693s fio-examples gnuplot tgt-glusterfs tgt-rbd 693s Recommended packages: 693s finalrd 693s The following NEW packages will be installed: 693s autopkgtest-satdep fio libaio1t64 libboost-iostreams1.83.0 693s libboost-thread1.83.0 libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 693s libgfxdr0 libglusterfs0 libisns0 libnbd0 libndctl6 libopeniscsiusr libpmem1 693s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 693s 0 upgraded, 23 newly installed, 0 to remove and 0 not upgraded. 693s Need to get 10.7 MB/10.7 MB of archives. 693s After this operation, 48.4 MB of additional disk space will be used. 693s Get:1 /tmp/autopkgtest.CVimhz/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 693s Get:2 http://ftpmaster.internal/ubuntu noble/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu1 [54.1 kB] 693s Get:3 http://ftpmaster.internal/ubuntu noble/main ppc64el libisns0 ppc64el 0.101-0.2 [117 kB] 693s Get:4 http://ftpmaster.internal/ubuntu noble/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu1 [387 kB] 694s Get:5 http://ftpmaster.internal/ubuntu noble/main ppc64el librdmacm1t64 ppc64el 50.0-2 [80.9 kB] 694s Get:6 http://ftpmaster.internal/ubuntu noble/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 694s Get:7 http://ftpmaster.internal/ubuntu noble/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu2 [256 kB] 694s Get:8 http://ftpmaster.internal/ubuntu noble/main ppc64el libaio1t64 ppc64el 0.3.113-6 [8188 B] 694s Get:9 http://ftpmaster.internal/ubuntu noble/universe ppc64el libgfxdr0 ppc64el 11.1-4 [21.3 kB] 694s Get:10 http://ftpmaster.internal/ubuntu noble/universe ppc64el libglusterfs0 ppc64el 11.1-4 [313 kB] 694s Get:11 http://ftpmaster.internal/ubuntu noble/universe ppc64el libgfrpc0 ppc64el 11.1-4 [46.8 kB] 694s Get:12 http://ftpmaster.internal/ubuntu noble/universe ppc64el libgfapi0 ppc64el 11.1-4 [99.6 kB] 694s Get:13 http://ftpmaster.internal/ubuntu noble/universe ppc64el libnbd0 ppc64el 1.18.2-1build1 [95.2 kB] 694s Get:14 http://ftpmaster.internal/ubuntu noble/main ppc64el libdaxctl1 ppc64el 77-2ubuntu1 [23.6 kB] 694s Get:15 http://ftpmaster.internal/ubuntu noble/main ppc64el libndctl6 ppc64el 77-2ubuntu1 [74.8 kB] 694s Get:16 http://ftpmaster.internal/ubuntu noble/main ppc64el libpmem1 ppc64el 1.13.1-1.1 [40.0 kB] 694s Get:17 http://ftpmaster.internal/ubuntu noble/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-2ubuntu1 [340 kB] 694s Get:18 http://ftpmaster.internal/ubuntu noble/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-2ubuntu1 [363 kB] 695s Get:19 http://ftpmaster.internal/ubuntu noble/main ppc64el librados2 ppc64el 18.2.0-0ubuntu7 [3911 kB] 695s Get:20 http://ftpmaster.internal/ubuntu noble/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1 [139 kB] 695s Get:21 http://ftpmaster.internal/ubuntu noble/main ppc64el librbd1 ppc64el 18.2.0-0ubuntu7 [3517 kB] 696s Get:22 http://ftpmaster.internal/ubuntu noble/universe ppc64el fio ppc64el 3.36-1build1 [716 kB] 696s Get:23 http://ftpmaster.internal/ubuntu noble/main ppc64el lsscsi ppc64el 0.32-1 [53.4 kB] 696s Preconfiguring packages ... 697s Fetched 10.7 MB in 3s (3154 kB/s) 697s Selecting previously unselected package libopeniscsiusr. 697s (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 ... 69712 files and directories currently installed.) 697s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu1_ppc64el.deb ... 697s Unpacking libopeniscsiusr (2.1.9-3ubuntu1) ... 697s Selecting previously unselected package libisns0:ppc64el. 697s Preparing to unpack .../01-libisns0_0.101-0.2_ppc64el.deb ... 697s Unpacking libisns0:ppc64el (0.101-0.2) ... 697s Selecting previously unselected package open-iscsi. 697s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu1_ppc64el.deb ... 697s Unpacking open-iscsi (2.1.9-3ubuntu1) ... 697s Selecting previously unselected package librdmacm1t64:ppc64el. 697s Preparing to unpack .../03-librdmacm1t64_50.0-2_ppc64el.deb ... 697s Unpacking librdmacm1t64:ppc64el (50.0-2) ... 697s Selecting previously unselected package libconfig-general-perl. 697s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 697s Unpacking libconfig-general-perl (2.65-2) ... 697s Selecting previously unselected package tgt. 697s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu2_ppc64el.deb ... 697s Unpacking tgt (1:1.0.85-1.1ubuntu2) ... 697s Selecting previously unselected package libaio1t64:ppc64el. 697s Preparing to unpack .../06-libaio1t64_0.3.113-6_ppc64el.deb ... 697s Unpacking libaio1t64:ppc64el (0.3.113-6) ... 697s Selecting previously unselected package libgfxdr0:ppc64el. 697s Preparing to unpack .../07-libgfxdr0_11.1-4_ppc64el.deb ... 697s Unpacking libgfxdr0:ppc64el (11.1-4) ... 697s Selecting previously unselected package libglusterfs0:ppc64el. 697s Preparing to unpack .../08-libglusterfs0_11.1-4_ppc64el.deb ... 697s Unpacking libglusterfs0:ppc64el (11.1-4) ... 697s Selecting previously unselected package libgfrpc0:ppc64el. 697s Preparing to unpack .../09-libgfrpc0_11.1-4_ppc64el.deb ... 697s Unpacking libgfrpc0:ppc64el (11.1-4) ... 697s Selecting previously unselected package libgfapi0:ppc64el. 697s Preparing to unpack .../10-libgfapi0_11.1-4_ppc64el.deb ... 697s Unpacking libgfapi0:ppc64el (11.1-4) ... 697s Selecting previously unselected package libnbd0. 697s Preparing to unpack .../11-libnbd0_1.18.2-1build1_ppc64el.deb ... 697s Unpacking libnbd0 (1.18.2-1build1) ... 697s Selecting previously unselected package libdaxctl1:ppc64el. 697s Preparing to unpack .../12-libdaxctl1_77-2ubuntu1_ppc64el.deb ... 697s Unpacking libdaxctl1:ppc64el (77-2ubuntu1) ... 697s Selecting previously unselected package libndctl6:ppc64el. 697s Preparing to unpack .../13-libndctl6_77-2ubuntu1_ppc64el.deb ... 697s Unpacking libndctl6:ppc64el (77-2ubuntu1) ... 697s Selecting previously unselected package libpmem1:ppc64el. 697s Preparing to unpack .../14-libpmem1_1.13.1-1.1_ppc64el.deb ... 697s Unpacking libpmem1:ppc64el (1.13.1-1.1) ... 697s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 697s Preparing to unpack .../15-libboost-iostreams1.83.0_1.83.0-2ubuntu1_ppc64el.deb ... 697s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-2ubuntu1) ... 697s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 697s Preparing to unpack .../16-libboost-thread1.83.0_1.83.0-2ubuntu1_ppc64el.deb ... 697s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-2ubuntu1) ... 697s Selecting previously unselected package librados2. 697s Preparing to unpack .../17-librados2_18.2.0-0ubuntu7_ppc64el.deb ... 697s Unpacking librados2 (18.2.0-0ubuntu7) ... 697s Selecting previously unselected package libpmemobj1:ppc64el. 697s Preparing to unpack .../18-libpmemobj1_1.13.1-1.1_ppc64el.deb ... 697s Unpacking libpmemobj1:ppc64el (1.13.1-1.1) ... 697s Selecting previously unselected package librbd1. 697s Preparing to unpack .../19-librbd1_18.2.0-0ubuntu7_ppc64el.deb ... 697s Unpacking librbd1 (18.2.0-0ubuntu7) ... 697s Selecting previously unselected package fio. 697s Preparing to unpack .../20-fio_3.36-1build1_ppc64el.deb ... 698s Unpacking fio (3.36-1build1) ... 698s Selecting previously unselected package lsscsi. 698s Preparing to unpack .../21-lsscsi_0.32-1_ppc64el.deb ... 698s Unpacking lsscsi (0.32-1) ... 698s Selecting previously unselected package autopkgtest-satdep. 698s Preparing to unpack .../22-2-autopkgtest-satdep.deb ... 698s Unpacking autopkgtest-satdep (0) ... 698s Setting up libconfig-general-perl (2.65-2) ... 698s Setting up libboost-thread1.83.0:ppc64el (1.83.0-2ubuntu1) ... 698s Setting up libnbd0 (1.18.2-1build1) ... 698s Setting up libopeniscsiusr (2.1.9-3ubuntu1) ... 698s Setting up libglusterfs0:ppc64el (11.1-4) ... 698s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-2ubuntu1) ... 698s Setting up lsscsi (0.32-1) ... 698s Setting up libdaxctl1:ppc64el (77-2ubuntu1) ... 698s Setting up libaio1t64:ppc64el (0.3.113-6) ... 698s Setting up libisns0:ppc64el (0.101-0.2) ... 698s Setting up libndctl6:ppc64el (77-2ubuntu1) ... 698s Setting up librdmacm1t64:ppc64el (50.0-2) ... 698s Setting up tgt (1:1.0.85-1.1ubuntu2) ... 698s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 699s Setting up libpmem1:ppc64el (1.13.1-1.1) ... 699s Setting up libgfxdr0:ppc64el (11.1-4) ... 699s Setting up librados2 (18.2.0-0ubuntu7) ... 699s Setting up open-iscsi (2.1.9-3ubuntu1) ... 699s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 700s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 700s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 700s Setting up libpmemobj1:ppc64el (1.13.1-1.1) ... 700s Setting up librbd1 (18.2.0-0ubuntu7) ... 700s Setting up libgfrpc0:ppc64el (11.1-4) ... 701s Setting up libgfapi0:ppc64el (11.1-4) ... 701s Setting up fio (3.36-1build1) ... 701s Setting up autopkgtest-satdep (0) ... 701s Processing triggers for man-db (2.12.0-3) ... 702s Processing triggers for initramfs-tools (0.142ubuntu20) ... 702s update-initramfs: Generating /boot/initrd.img-6.8.0-11-generic 702s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 710s Processing triggers for libc-bin (2.39-0ubuntu6) ... 712s (Reading database ... 69957 files and directories currently installed.) 712s Removing autopkgtest-satdep (0) ... 716s autopkgtest [23:52:52]: test tgtbasedmpaths: [----------------------- 716s + targetname=iqn.2016-11.foo.com:target.iscsi 716s + pwd 716s + cwd=/tmp/autopkgtest.CVimhz/build.G2r/src 716s + testdir=/mnt/tgtmpathtest 716s + localhost=127.0.0.1 716s + portal=127.0.0.1:3260 716s + maxpaths=4 716s + backfn=backingfile 716s + expectwwid=60000000000000000e00000000010001 716s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 716s + bglog=/tmp/autopkgtest.CVimhz/tgtbasedmpaths-artifacts/test-background.log 716s + fioprep=/tmp/autopkgtest.CVimhz/tgtbasedmpaths-artifacts/path-change-prep.fio 716s + fiovrfy=/tmp/autopkgtest.CVimhz/tgtbasedmpaths-artifacts/path-change-check.fio 716s + service tgt restart 717s + truncate --size 100M backingfile 717s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 717s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 717s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.CVimhz/build.G2r/src/backingfile 717s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 717s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 717s login #1 717s + echo login #1 717s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 717s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 717s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 717s + seq 2 4 717s extra login #2 717s + echo extra login #2 717s + iscsiadm --mode session -r 1 --op new 717s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 717s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 717s extra login #3 717s + echo extra login #3 717s + iscsiadm --mode session -r 1 --op new 717s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 717s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 717s + echo extra login #4 717s + iscsiadm --mode session -r 1 --op new 717s extra login #4 717s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 717s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 717s + udevadm settle 717s + sleep 5 722s Status after initial setup 722s + echo Status after initial setup 722s + tgtadm --lld iscsi --mode target --op show 722s + tgtadm --lld iscsi --op show --mode conn --tid 1 722s Target 1: iqn.2016-11.foo.com:target.iscsi 722s System information: 722s Driver: iscsi 722s State: ready 722s I_T nexus information: 722s I_T nexus: 1 722s Initiator: iqn.2004-10.com.ubuntu:01:cd8efeae04f alias: autopkgtest 722s Connection: 0 722s IP Address: 127.0.0.1 722s I_T nexus: 2 722s Initiator: iqn.2004-10.com.ubuntu:01:cd8efeae04f alias: autopkgtest 722s Connection: 0 722s IP Address: 127.0.0.1 722s I_T nexus: 3 722s Initiator: iqn.2004-10.com.ubuntu:01:cd8efeae04f alias: autopkgtest 722s Connection: 0 722s IP Address: 127.0.0.1 722s I_T nexus: 4 722s Initiator: iqn.2004-10.com.ubuntu:01:cd8efeae04f alias: autopkgtest 722s Connection: 0 722s IP Address: 127.0.0.1 722s LUN information: 722s LUN: 0 722s Type: controller 722s SCSI ID: IET 00010000 722s SCSI SN: beaf10 722s Size: 0 MB, Block size: 1 722s Online: Yes 722s Removable media: No 722s Prevent removal: No 722s Readonly: No 722s SWP: No 722s Thin-provisioning: No 722s Backing store type: null 722s Backing store path: None 722s Backing store flags: 722s LUN: 1 722s Type: disk 722s SCSI ID: IET 00010001 722s SCSI SN: beaf11 722s Size: 105 MB, Block size: 512 722s Online: Yes 722s Removable media: No 722s Prevent removal: No 722s Readonly: No 722s SWP: No 722s Thin-provisioning: No 722s Backing store type: rdwr 722s Backing store path: /tmp/autopkgtest.CVimhz/build.G2r/src/backingfile 722s Backing store flags: 722s Account information: 722s ACL information: 722s ALL 722s Session: 4 722s Connection: 0 722s Initiator: iqn.2004-10.com.ubuntu:01:cd8efeae04f 722s IP Address: 127.0.0.1 722s Session: 3 722s Connection: 0 722s Initiator: iqn.2004-10.com.ubuntu:01:cd8efeae04f 722s IP Address: 127.0.0.1 722s Session: 2 722s Connection: 0 722s Initiator: iqn.2004-10.com.ubuntu:01:cd8efeae04f 722s IP Address: 127.0.0.1 722s Session: 1 722s Connection: 0 722s Initiator: iqn.2004-10.com.ubuntu:01:cd8efeae04f 722s IP Address: 127.0.0.1 722s + iscsiadm --mode session -P 1 722s + lsscsi -liv 722s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 722s Current Portal: 127.0.0.1:3260,1 722s Persistent Portal: 127.0.0.1:3260,1 722s ********** 722s Interface: 722s ********** 722s Iface Name: default 722s Iface Transport: tcp 722s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:cd8efeae04f 722s Iface IPaddress: 127.0.0.1 722s Iface HWaddress: default 722s Iface Netdev: default 722s SID: 1 722s iSCSI Connection State: LOGGED IN 722s iSCSI Session State: LOGGED_IN 722s Internal iscsid Session State: NO CHANGE 722s 722s ********** 722s Interface: 722s ********** 722s Iface Name: default 722s Iface Transport: tcp 722s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:cd8efeae04f 722s Iface IPaddress: 127.0.0.1 722s Iface HWaddress: default 722s Iface Netdev: default 722s SID: 2 722s iSCSI Connection State: LOGGED IN 722s iSCSI Session State: LOGGED_IN 722s Internal iscsid Session State: NO CHANGE 722s 722s ********** 722s Interface: 722s ********** 722s Iface Name: default 722s Iface Transport: tcp 722s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:cd8efeae04f 722s Iface IPaddress: 127.0.0.1 722s Iface HWaddress: default 722s Iface Netdev: default 722s SID: 3 722s iSCSI Connection State: LOGGED IN 722s iSCSI Session State: LOGGED_IN 722s Internal iscsid Session State: NO CHANGE 722s 722s ********** 722s Interface: 722s ********** 722s Iface Name: default 722s Iface Transport: tcp 722s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:cd8efeae04f 722s Iface IPaddress: 127.0.0.1 722s Iface HWaddress: default 722s Iface Netdev: default 722s SID: 4 722s iSCSI Connection State: LOGGED IN 722s iSCSI Session State: LOGGED_IN 722s Internal iscsid Session State: NO CHANGE 722s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 722s + multipath -v3 -ll 722s 55.454417 | set open fds limit to 1048576/1048576 722s 55.454574 | loading /lib/multipath/libchecktur.so checker 722s 55.454681 | checker tur: message table size = 3 722s 55.454691 | loading /lib/multipath/libprioconst.so prioritizer 722s 55.454818 | _init_foreign: foreign library "nvme" is not enabled 722s 55.461452 | sda: size = 167772160 722s 55.461666 | sda: vendor = QEMU 722s 55.461726 | sda: product = QEMU HARDDISK 722s 55.461753 | sda: rev = 2.5+ 722s 55.462472 | sda: h:b:t:l = 0:0:0:0 722s 55.462959 | sda: tgt_node_name = 722s 55.462987 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 722s 55.462990 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 722s 55.463177 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 722s 55.463203 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 722s 55.463219 | __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 722s 55.463226 | failed to read sysfs vpd pg80: No such file or directory 722s 55.463463 | sda: fail to get serial 722s 55.463490 | sda: detect_checker = yes (setting: multipath internal) 722s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 722s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 722s 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] 722s [1:0:0:0] storage IET Controller 0001 - - 722s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 722s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 722s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 722s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 722s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 722s [2:0:0:0] storage IET Controller 0001 - - 722s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 722s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 722s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 722s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 722s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 722s [3:0:0:0] storage IET Controller 0001 - - 722s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 722s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 722s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 722s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 722s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 722s [4:0:0:0] storage IET Controller 0001 - - 722s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 722s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 722s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 722s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 722s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 722s NVMe module may not be loaded 722s 55.463725 | sda: path_checker = tur (setting: multipath internal) 722s 55.463753 | sda: checker timeout = 30 s (setting: kernel sysfs) 722s 55.463857 | sda: tur state = up 722s 55.464247 | sdb: size = 204800 722s 55.464432 | sdb: vendor = IET 722s 55.464483 | sdb: product = VIRTUAL-DISK 722s 55.464510 | sdb: rev = 0001 722s 55.465233 | sdb: h:b:t:l = 1:0:0:1 722s 55.465675 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 722s 55.465701 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 722s 55.465703 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 722s 55.465887 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 722s 55.465912 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 722s 55.465931 | sdb: serial = beaf11 722s 55.465934 | sdb: detect_checker = yes (setting: multipath internal) 722s 55.466300 | sdb: path_checker = tur (setting: multipath internal) 722s 55.466326 | sdb: checker timeout = 30 s (setting: kernel sysfs) 722s 55.466524 | sdb: tur state = up 722s 55.466694 | sdc: size = 204800 722s 55.466872 | sdc: vendor = IET 722s 55.466921 | sdc: product = VIRTUAL-DISK 722s 55.466948 | sdc: rev = 0001 722s 55.467854 | sdc: h:b:t:l = 2:0:0:1 722s 55.468300 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 722s 55.468333 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 722s 55.468336 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 722s 55.468509 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 722s 55.468535 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 722s 55.468554 | sdc: serial = beaf11 722s 55.468557 | sdc: detect_checker = yes (setting: multipath internal) 722s 55.468897 | sdc: path_checker = tur (setting: multipath internal) 722s 55.468938 | sdc: checker timeout = 30 s (setting: kernel sysfs) 722s 55.469139 | sdc: tur state = up 722s 55.469327 | sdd: size = 204800 722s 55.469506 | sdd: vendor = IET 722s 55.469557 | sdd: product = VIRTUAL-DISK 722s 55.469584 | sdd: rev = 0001 722s 55.470346 | sdd: h:b:t:l = 3:0:0:1 722s 55.470780 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 722s 55.470805 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 722s 55.470808 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 722s 55.470978 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 722s 55.471003 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 722s 55.471020 | sdd: serial = beaf11 722s 55.471023 | sdd: detect_checker = yes (setting: multipath internal) 722s 55.471297 | sdd: path_checker = tur (setting: multipath internal) 722s 55.471325 | sdd: checker timeout = 30 s (setting: kernel sysfs) 722s 55.471619 | sdd: tur state = up 722s 55.471802 | sde: size = 204800 722s 55.471983 | sde: vendor = IET 722s 55.472103 | sde: product = VIRTUAL-DISK 722s 55.472154 | sde: rev = 0001 722s 55.472913 | sde: h:b:t:l = 4:0:0:1 722s 55.473358 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 722s 55.473385 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 722s 55.473387 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 722s 55.473569 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 722s 55.473595 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 722s 55.473612 | sde: serial = beaf11 722s 55.473614 | sde: detect_checker = yes (setting: multipath internal) 722s 55.473871 | sde: path_checker = tur (setting: multipath internal) 722s 55.473897 | sde: checker timeout = 30 s (setting: kernel sysfs) 722s 55.474084 | sde: tur state = up 722s 55.474224 | loop0: device node name blacklisted 722s 55.474353 | loop1: device node name blacklisted 722s 55.474477 | loop2: device node name blacklisted 722s 55.474601 | loop3: device node name blacklisted 722s 55.474726 | loop4: device node name blacklisted 722s 55.474847 | loop5: device node name blacklisted 722s 55.474971 | loop6: device node name blacklisted 722s 55.475094 | loop7: device node name blacklisted 722s 55.475228 | dm-0: device node name blacklisted 722s 55.476431 | multipath-tools v0.9.4 (12/19, 2022) 722s 55.476476 | libdevmapper version 1.02.185 722s 55.476650 | kernel device mapper v4.48.0 722s 55.476689 | DM multipath kernel driver v1.14.0 722s 55.476829 | sdb: size = 204800 722s 55.476857 | sdb: vendor = IET 722s 55.476860 | sdb: product = VIRTUAL-DISK 722s 55.476863 | sdb: rev = 0001 722s 55.477588 | sdb: h:b:t:l = 1:0:0:1 722s 55.477749 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 722s 55.477795 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 722s 55.477799 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 722s 55.477815 | sdb: serial = beaf11 722s 55.478043 | sdb: tur state = up 722s 55.478071 | sdb: uid = 360000000000000000e00000000010001 (udev) 722s 55.478075 | sdb: detect_prio = yes (setting: multipath internal) 722s 55.478079 | sdb: prio = const (setting: multipath internal) 722s 55.478082 | sdb: prio args = "" (setting: multipath internal) 722s 55.478085 | sdb: const prio = 1 722s 55.478116 | sdc: size = 204800 722s 55.478122 | sdc: vendor = IET 722s 55.478125 | sdc: product = VIRTUAL-DISK 722s 55.478128 | sdc: rev = 0001 722s 55.478813 | sdc: h:b:t:l = 2:0:0:1 722s 55.478971 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 722s 55.479016 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 722s 55.479020 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 722s 55.479035 | sdc: serial = beaf11 722s 55.479254 | sdc: tur state = up 722s 55.479280 | sdc: uid = 360000000000000000e00000000010001 (udev) 722s 55.479283 | sdc: detect_prio = yes (setting: multipath internal) 722s 55.479286 | sdc: prio = const (setting: multipath internal) 722s 55.479288 | sdc: prio args = "" (setting: multipath internal) 722s 55.479291 | sdc: const prio = 1 722s 55.479322 | sdd: size = 204800 722s 55.479327 | sdd: vendor = IET 722s 55.479330 | sdd: product = VIRTUAL-DISK 722s 55.479332 | sdd: rev = 0001 722s 55.480029 | sdd: h:b:t:l = 3:0:0:1 722s 55.480174 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 722s 55.480221 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 722s 55.480224 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 722s 55.480239 | sdd: serial = beaf11 722s ===== paths list ===== 722s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 722s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 722s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 722s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 722s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 722s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 722s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 722s size=100M features='0' hwhandler='0' wp=rw 722s |-+- policy='service-time 0' prio=1 status=active 722s | `- 1:0:0:1 sdb 8:16 active ready running 722s |-+- policy='service-time 0' prio=1 status=enabled 722s | `- 2:0:0:1 sdc 8:32 active ready running 722s |-+- policy='service-time 0' prio=1 status=enabled 722s | `- 3:0:0:1 sdd 8:48 active ready running 722s `-+- policy='service-time 0' prio=1 status=enabled 722s `- 4:0:0:1 sde 8:64 active ready running 722s 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 722s Test WWN should now point to DM 722s ../../dm-0 722s 55.480465 | sdd: tur state = up 722s 55.480491 | sdd: uid = 360000000000000000e00000000010001 (udev) 722s 55.480494 | sdd: detect_prio = yes (setting: multipath internal) 722s 55.480497 | sdd: prio = const (setting: multipath internal) 722s 55.480499 | sdd: prio args = "" (setting: multipath internal) 722s 55.480502 | sdd: const prio = 1 722s 55.480532 | sde: size = 204800 722s 55.480537 | sde: vendor = IET 722s 55.480541 | sde: product = VIRTUAL-DISK 722s 55.480544 | sde: rev = 0001 722s 55.481241 | sde: h:b:t:l = 4:0:0:1 722s 55.481399 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 722s 55.481445 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 722s 55.481448 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 722s 55.481462 | sde: serial = beaf11 722s 55.481662 | sde: tur state = up 722s 55.481688 | sde: uid = 360000000000000000e00000000010001 (udev) 722s 55.481691 | sde: detect_prio = yes (setting: multipath internal) 722s 55.481694 | sde: prio = const (setting: multipath internal) 722s 55.481697 | sde: prio args = "" (setting: multipath internal) 722s 55.481699 | sde: const prio = 1 722s 55.482760 | unloading tur checker 722s 55.482851 | unloading const prioritizer 722s + dmsetup table 722s + echo Test WWN should now point to DM 722s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 722s + grep dm 722s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 722s mke2fs 1.47.0 (5-Feb-2023) 722s Creating filesystem with 25600 4k blocks and 25600 inodes 722s 722s Allocating group tables: 0/1 done 722s Writing inode tables: 0/1 done 722s Creating journal (1024 blocks): done 722s Writing superblocks and filesystem accounting information: 0/1 + udevadm settle 722s done 722s 722s + sleep 3s 725s + mkdir -p /mnt/tgtmpathtest 725s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 725s + cat 725s + cat 725s + fio --max-jobs=4 /tmp/autopkgtest.CVimhz/tgtbasedmpaths-artifacts/path-change-prep.fio 725s 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 725s fio-3.36 725s Starting 1 thread 725s write-phase: Laying out IO file (1 file / 17592186044415MiB) 727s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 727s 727s write-phase: (groupid=0, jobs=1): err= 0: pid=4846: Mon Mar 25 23:53:02 2024 727s write: IOPS=1352, BW=84.5MiB/s (88.6MB/s)(87.6MiB/1037msec); 0 zone resets 727s clat (usec): min=459, max=7543, avg=707.51, stdev=321.65 727s lat (usec): min=482, max=7577, avg=737.43, stdev=322.85 727s clat percentiles (usec): 727s | 1.00th=[ 486], 5.00th=[ 506], 10.00th=[ 529], 20.00th=[ 578], 727s | 30.00th=[ 611], 40.00th=[ 635], 50.00th=[ 660], 60.00th=[ 676], 727s | 70.00th=[ 717], 80.00th=[ 766], 90.00th=[ 865], 95.00th=[ 988], 727s | 99.00th=[ 1778], 99.50th=[ 2311], 99.90th=[ 4883], 99.95th=[ 7570], 727s | 99.99th=[ 7570] 727s bw ( KiB/s): min=85120, max=87168, per=99.56%, avg=86144.00, stdev=1448.15, samples=2 727s iops : min= 1330, max= 1362, avg=1346.00, stdev=22.63, samples=2 727s lat (usec) : 500=3.99%, 750=71.77%, 1000=19.24% 727s lat (msec) : 2=4.21%, 4=0.50%, 10=0.21% 727s cpu : usr=5.50%, sys=6.66%, ctx=1404, majf=0, minf=0 727s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 727s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 727s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 727s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 727s latency : target=0, window=0, percentile=100.00%, depth=1 727s 727s Run status group 0 (all jobs): 727s WRITE: bw=84.5MiB/s (88.6MB/s), 84.5MiB/s-84.5MiB/s (88.6MB/s-88.6MB/s), io=87.6MiB (91.9MB), run=1037-1037msec 727s 727s Disk stats (read/write): 727s dm-0: ios=1/1167, sectors=8/149376, merge=0/0, ticks=1/903, in_queue=905, util=89.47%, aggrios=0/351, aggsectors=2/44884, aggrmerge=0/0, aggrticks=0/235, aggrin_queue=236, aggrutil=90.20% 727s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 727s sdb: ios=1/1404, sectors=8/179536, merge=0/0, ticks=0/943, in_queue=944, util=90.20% 727s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 727s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 727s + echo Starting the path changes in background 727s Starting the path changes in background 727s + date +Pre FIO %H:%M:%S.%N 727s Pre FIO 23:53:02.996177902 727s + fio --max-jobs=4 /tmp/autopkgtest.CVimhz/tgtbasedmpaths-artifacts/path-change-check.fio 727s 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 727s fio-3.36 727s Starting 1 thread 907s 907s verify-phase: (groupid=0, jobs=1): err= 0: pid=4853: Mon Mar 25 23:56:03 2024 907s read: IOPS=2938, BW=184MiB/s (193MB/s)(32.3GiB/180001msec) 907s clat (usec): min=96, max=44379, avg=314.51, stdev=200.16 907s lat (usec): min=96, max=44379, avg=314.62, stdev=200.17 907s clat percentiles (usec): 907s | 1.00th=[ 118], 5.00th=[ 174], 10.00th=[ 194], 20.00th=[ 221], 907s | 30.00th=[ 239], 40.00th=[ 258], 50.00th=[ 302], 60.00th=[ 330], 907s | 70.00th=[ 359], 80.00th=[ 392], 90.00th=[ 445], 95.00th=[ 482], 907s | 99.00th=[ 676], 99.50th=[ 922], 99.90th=[ 1991], 99.95th=[ 2737], 907s | 99.99th=[ 4948] 907s bw ( KiB/s): min=85120, max=340096, per=100.00%, avg=188185.13, stdev=44317.40, samples=359 907s iops : min= 1330, max= 5314, avg=2940.33, stdev=692.44, samples=359 907s lat (usec) : 100=0.01%, 250=36.69%, 500=59.66%, 750=2.87%, 1000=0.35% 907s lat (msec) : 2=0.32%, 4=0.08%, 10=0.02%, 20=0.01%, 50=0.01% 907s cpu : usr=8.72%, sys=7.40%, ctx=529050, majf=0, minf=1 907s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 907s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 907s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 907s issued rwts: total=528973,0,0,0 short=0,0,0,0 dropped=0,0,0,0 907s latency : target=0, window=0, percentile=100.00%, depth=1 907s 907s Run status group 0 (all jobs): 907s READ: bw=184MiB/s (193MB/s), 184MiB/s-184MiB/s (193MB/s-193MB/s), io=32.3GiB (34.7GB), run=180001-180001msec 907s 907s Disk stats (read/write): 907s dm-0: ios=528913/9, sectors=67649720/12912, merge=11/8, ticks=168739/86, in_queue=168876, util=100.00%, aggrios=33673/2, aggsectors=4306318/3228, aggrmerge=0/0, aggrticks=10974/8, aggrin_queue=10983, aggrutil=99.14% 907s sdd: ios=26165/0, sectors=3346816/0, merge=0/0, ticks=8894/0, in_queue=8893, util=33.41% 907s sdb: ios=25579/8, sectors=3271552/12912, merge=0/0, ticks=8510/35, in_queue=8545, util=99.14% 907s sde: ios=52955/0, sectors=6773376/0, merge=0/0, ticks=17812/0, in_queue=17813, util=40.01% 907s sdc: ios=29994/0, sectors=3833528/0, merge=0/0, ticks=8683/0, in_queue=8684, util=50.08% 907s + date +Post FIO %H:%M:%S.%N 907s + echo FIO verify test with changing paths - OK 907s + echo Report log of background activity 907s + cat /tmp/autopkgtest.CVimhz/tgtbasedmpaths-artifacts/test-background.log 907s Post FIO 23:56:03.216862116 907s FIO verify test with changing paths - OK 907s Report log of background activity 907s + iscsiadm --mode session 907s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s + sleep 10s 907s + date +MP report (expect 4) %H:%M:%S.%N 907s MP report (expect 4) 23:53:13.004545598 907s + multipath -ll 907s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 907s size=100M features='0' hwhandler='0' wp=rw 907s |-+- policy='service-time 0' prio=1 status=active 907s | `- 1:0:0:1 sdb 8:16 active ready running 907s |-+- policy='service-time 0' prio=1 status=enabled 907s | `- 2:0:0:1 sdc 8:32 active ready running 907s |-+- policy='service-time 0' prio=1 status=enabled 907s | `- 3:0:0:1 sdd 8:48 active ready running 907s `-+- policy='service-time 0' prio=1 status=enabled 907s `- 4:0:0:1 sde 8:64 active ready running 907s + date +UN-plug path 1 %H:%M:%S.%N 907s UN-plug path 1 23:53:13.041340915 907s + iscsiadm --mode session -r 1 -u 907s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 907s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 907s + iscsiadm --mode session 907s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s + sleep 10s 907s + date +MP report (expect 3) %H:%M:%S.%N 907s MP report (expect 3) 23:53:23.153503880 907s + multipath -ll 907s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 907s size=100M features='0' hwhandler='0' wp=rw 907s |-+- policy='service-time 0' prio=1 status=active 907s | `- 2:0:0:1 sdc 8:32 active ready running 907s |-+- policy='service-time 0' prio=1 status=enabled 907s | `- 3:0:0:1 sdd 8:48 active ready running 907s `-+- policy='service-time 0' prio=1 status=enabled 907s `- 4:0:0:1 sde 8:64 active ready running 907s + date +UN-plug path 2 %H:%M:%S.%N 907s UN-plug path 2 23:53:23.194158500 907s + iscsiadm --mode session -r 2 -u 907s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 907s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 907s + iscsiadm --mode session 907s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s + sleep 10s 907s + date +MP report (expect 2) %H:%M:%S.%N 907s MP report (expect 2) 23:53:33.299400008 907s + multipath -ll 907s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 907s size=100M features='0' hwhandler='0' wp=rw 907s |-+- policy='service-time 0' prio=1 status=active 907s | `- 3:0:0:1 sdd 8:48 active ready running 907s `-+- policy='service-time 0' prio=1 status=enabled 907s `- 4:0:0:1 sde 8:64 active ready running 907s + date +UN-plug path 3 %H:%M:%S.%N 907s UN-plug path 3 23:53:33.324470221 907s + iscsiadm --mode session -r 3 -u 907s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 907s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 907s + iscsiadm --mode session 907s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s + sleep 10s 907s + date +MP report (expect 1) %H:%M:%S.%N 907s MP report (expect 1) 23:53:43.419299863 907s + multipath -ll 907s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 907s size=100M features='0' hwhandler='0' wp=rw 907s `-+- policy='service-time 0' prio=1 status=active 907s `- 4:0:0:1 sde 8:64 active ready running 907s + date +Add paths 5/6/7/8 %H:%M:%S.%N 907s Add paths 5/6/7/8 23:53:43.436656106 907s + iscsiadm --mode session -r 4 --op new 907s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 907s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 907s + iscsiadm --mode session -r 4 --op new 907s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 907s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 907s + iscsiadm --mode session -r 4 --op new 907s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 907s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 907s + iscsiadm --mode session -r 4 --op new 907s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 907s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 907s + iscsiadm --mode session 907s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s + sleep 10s 907s + date +MP report (expect 5) %H:%M:%S.%N 907s MP report (expect 5) 23:53:53.592308827 907s + multipath -ll 907s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 907s size=100M features='0' hwhandler='0' wp=rw 907s |-+- policy='service-time 0' prio=1 status=active 907s | `- 4:0:0:1 sde 8:64 active ready running 907s |-+- policy='service-time 0' prio=1 status=enabled 907s | `- 1:0:0:1 sdb 8:16 active ready running 907s |-+- policy='service-time 0' prio=1 status=enabled 907s | `- 2:0:0:1 sdc 8:32 active ready running 907s |-+- policy='service-time 0' prio=1 status=enabled 907s | `- 3:0:0:1 sdd 8:48 active ready running 907s `-+- policy='service-time 0' prio=1 status=enabled 907s `- 5:0:0:1 sdf 8:80 active ready running 907s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 907s UN-plug multiple paths 4/7/8 23:53:53.628530097 907s + iscsiadm --mode session -r 4 -u 907s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 907s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 907s + iscsiadm --mode session -r 7 -u 907s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 907s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 907s + iscsiadm --mode session -r 8 -u 907s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 907s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 907s + iscsiadm --mode session 907s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 907s + sleep 10s 907s + date +Restart multipath daemon %H:%M:%S.%N 907s Restart multipath daemon 23:54:03.936083264 907s + systemctl restart multipathd 907s + sleep 10s 907s + date +Final background report (expect 2) %H:%M:%S.%N 907s Final background report (expect 2) 23:54:14.060772146 907s + multipath -ll 907s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 907s size=100M features='0' hwhandler='0' wp=rw 907s |-+- policy='service-time 0' prio=1 status=active 907s | `- 1:0:0:1 sdb 8:16 active ready running 907s `-+- policy='service-time 0' prio=1 status=enabled 907s `- 2:0:0:1 sdc 8:32 active ready running 907s Final stats 907s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 907s iSCSI SNMP: 907s txdata_octets: 18920760 907s rxdata_octets: 25810733364 907s noptx_pdus: 0 907s scsicmd_pdus: 393915 907s tmfcmd_pdus: 0 907s login_pdus: 0 907s text_pdus: 0 907s dataout_pdus: 0 907s logout_pdus: 0 907s snack_pdus: 0 907s noprx_pdus: 0 907s scsirsp_pdus: 393915 907s tmfrsp_pdus: 0 907s textrsp_pdus: 0 907s datain_pdus: 393880 907s logoutrsp_pdus: 0 907s r2t_pdus: 0 907s async_pdus: 0 907s rjt_pdus: 0 907s digest_err: 0 907s timeout_err: 0 907s iSCSI Extended: 907s tx_sendpage_failures: 0 907s rx_discontiguous_hdr: 0 907s eh_abort_cnt: 0 907s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 907s iSCSI SNMP: 907s txdata_octets: 6840 907s rxdata_octets: 2825908 907s noptx_pdus: 0 907s scsicmd_pdus: 113 907s tmfcmd_pdus: 0 907s login_pdus: 0 907s text_pdus: 0 907s dataout_pdus: 0 907s logout_pdus: 0 907s snack_pdus: 0 907s noprx_pdus: 0 907s scsirsp_pdus: 113 907s tmfrsp_pdus: 0 907s textrsp_pdus: 0 907s datain_pdus: 90 907s logoutrsp_pdus: 0 907s r2t_pdus: 0 907s async_pdus: 0 907s rjt_pdus: 0 907s digest_err: 0 907s timeout_err: 0 907s iSCSI Extended: 907s tx_sendpage_failures: 0 907s rx_discontiguous_hdr: 0 907s eh_abort_cnt: 0 907s + sync 907s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 907s + echo Final stats 907s + iscsiadm --mode session --stats 907s + journalctl --no-pager -u multipathd 907s + echo Check final path status 907s + multipath -ll 907s + multipath -ll 907s + grep --count status= 907s Mar 25 16:19:30 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 907s Mar 25 16:19:30 ubuntu multipathd[327]: multipathd v0.9.4: start up 907s Mar 25 16:19:30 ubuntu multipathd[327]: reconfigure: setting up paths and maps 907s Mar 25 16:19:30 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 907s Mar 25 16:25:36 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 multipathd[327]: multipathd: shut down 907s Mar 25 16:25:36 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 907s Mar 25 16:25:36 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: multipathd.service: Deactivated successfully. 907s Mar 25 16:25:36 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 907s -- Boot d15ebf7b610e4785b9bcc85de59fc33a -- 907s Mar 25 16:26:01 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 907s Mar 25 16:26:01 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 multipathd[267]: multipathd v0.9.4: start up 907s Mar 25 16:26:01 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 multipathd[267]: reconfigure: setting up paths and maps 907s Mar 25 16:26:01 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 907s Mar 25 16:26:23 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 multipathd[267]: multipathd: shut down 907s Mar 25 16:26:23 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 907s Mar 25 16:26:23 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: multipathd.service: Deactivated successfully. 907s Mar 25 16:26:23 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 907s -- Boot 7ffd87e767f44e51b46c787028bed008 -- 907s Mar 25 23:48:34 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 907s Mar 25 23:48:34 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 multipathd[318]: multipathd v0.9.4: start up 907s Mar 25 23:48:34 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 multipathd[318]: reconfigure: setting up paths and maps 907s Mar 25 23:48:34 auto-syncubuntu-noble-daily-ppc64el-server-20240312-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 907s Mar 25 23:49:27 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 907s Mar 25 23:49:27 autopkgtest multipathd[318]: multipathd: shut down 907s Mar 25 23:49:27 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 907s Mar 25 23:49:27 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 907s -- Boot 615725527b69449b918883a3b5cd4034 -- 907s Mar 25 23:49:52 autopkgtest multipathd[285]: multipathd v0.9.4: start up 907s Mar 25 23:49:52 autopkgtest multipathd[285]: reconfigure: setting up paths and maps 907s Mar 25 23:49:52 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 907s -- Boot 987c6dca262f487d96d019848788b552 -- 907s Mar 25 23:52:06 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 907s Mar 25 23:52:06 autopkgtest multipathd[304]: multipathd v0.9.4: start up 907s Mar 25 23:52:06 autopkgtest multipathd[304]: reconfigure: setting up paths and maps 907s Mar 25 23:52:06 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 907s Mar 25 23:52:53 autopkgtest multipathd[304]: 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] 907s Mar 25 23:52:53 autopkgtest multipathd[304]: sdc [8:32]: path added to devmap mpatha 907s Mar 25 23:52:53 autopkgtest multipathd[304]: mpatha: performing delayed actions 907s Mar 25 23:52:53 autopkgtest multipathd[304]: 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] 907s Mar 25 23:53:13 autopkgtest multipathd[304]: 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] 907s Mar 25 23:53:13 autopkgtest multipathd[304]: check_removed_paths: sdb: freeing path in removed state 907s Mar 25 23:53:13 autopkgtest multipathd[304]: 8:16: path removed from map mpatha 907s Mar 25 23:53:23 autopkgtest multipathd[304]: 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] 907s Mar 25 23:53:23 autopkgtest multipathd[304]: check_removed_paths: sdc: freeing path in removed state 907s Mar 25 23:53:23 autopkgtest multipathd[304]: 8:32: path removed from map mpatha 907s Mar 25 23:53:33 autopkgtest multipathd[304]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 907s Mar 25 23:53:33 autopkgtest multipathd[304]: check_removed_paths: sdd: freeing path in removed state 907s Mar 25 23:53:33 autopkgtest multipathd[304]: 8:48: path removed from map mpatha 907s Mar 25 23:53:43 autopkgtest multipathd[304]: 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] 907s Mar 25 23:53:43 autopkgtest multipathd[304]: sdb [8:16]: path added to devmap mpatha 907s Mar 25 23:53:43 autopkgtest multipathd[304]: 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] 907s Mar 25 23:53:43 autopkgtest multipathd[304]: sdc [8:32]: path added to devmap mpatha 907s Mar 25 23:53:43 autopkgtest multipathd[304]: 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] 907s Mar 25 23:53:43 autopkgtest multipathd[304]: sdd [8:48]: path added to devmap mpatha 907s Mar 25 23:53:43 autopkgtest multipathd[304]: 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] 907s Mar 25 23:53:43 autopkgtest multipathd[304]: sdf [8:80]: path added to devmap mpatha 907s Mar 25 23:53:53 autopkgtest multipathd[304]: 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] 907s Mar 25 23:53:53 autopkgtest multipathd[304]: check_removed_paths: sde: freeing path in removed state 907s Mar 25 23:53:53 autopkgtest multipathd[304]: 8:64: path removed from map mpatha 907s Mar 25 23:53:53 autopkgtest multipathd[304]: 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] 907s Mar 25 23:53:53 autopkgtest multipathd[304]: check_removed_paths: sdd: freeing path in removed state 907s Mar 25 23:53:53 autopkgtest multipathd[304]: 8:48: path removed from map mpatha 907s Mar 25 23:53:53 autopkgtest multipathd[304]: 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] 907s Mar 25 23:53:53 autopkgtest multipathd[304]: check_removed_paths: sdf: freeing path in removed state 907s Mar 25 23:53:53 autopkgtest multipathd[304]: 8:80: path removed from map mpatha 907s Mar 25 23:54:03 autopkgtest multipathd[304]: multipathd: shut down 907s Mar 25 23:54:03 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 907s Mar 25 23:54:03 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 907s Mar 25 23:54:03 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 907s Mar 25 23:54:04 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 907s Mar 25 23:54:04 autopkgtest multipathd[5225]: multipathd v0.9.4: start up 907s Mar 25 23:54:04 autopkgtest multipathd[5225]: reconfigure: setting up paths and maps 907s Mar 25 23:54:04 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 907s Check final path status 907s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 907s size=100M features='0' hwhandler='0' wp=rw 907s |-+- policy='service-time 0' prio=1 status=active 907s | `- 1:0:0:1 sdb 8:16 active ready running 907s `-+- policy='service-time 0' prio=1 status=enabled 907s `- 2:0:0:1 sdc 8:32 active ready running 907s + diskc=2 907s + multipath -ll 907s + grep --count status=active 907s + diska=1 907s + multipath -ll 907s + grep --count status=enabled 907s + diske=1 907s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 907s + echo OK 907s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 907s OK 907s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 907s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 907s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 907s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 907s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 907s autopkgtest [23:56:03]: test tgtbasedmpaths: -----------------------] 908s autopkgtest [23:56:04]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 908s tgtbasedmpaths PASS 908s autopkgtest [23:56:04]: @@@@@@@@@@@@@@@@@@@@ summary 908s kpartx-file-loopback PASS 908s tgtbasedmpaths PASS 929s Creating nova instance adt-noble-ppc64el-multipath-tools-20240325-234056-juju-7f2275-prod-proposed-migration-environment-2 from image adt/ubuntu-noble-ppc64el-server-20240325.img (UUID ce50e202-ac12-4562-879d-419903f0141e)... 929s Creating nova instance adt-noble-ppc64el-multipath-tools-20240325-234056-juju-7f2275-prod-proposed-migration-environment-2 from image adt/ubuntu-noble-ppc64el-server-20240325.img (UUID ce50e202-ac12-4562-879d-419903f0141e)...