0s autopkgtest [23:56:08]: starting date and time: 2024-03-25 23:56:08+0000 0s autopkgtest [23:56:08]: git checkout: 4a1cd702 l/adt_testbed: don't blame the testbed for unsolvable build deps 0s autopkgtest [23:56:08]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.zv6s71df/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-s390x-16.secgroup --name adt-noble-s390x-multipath-tools-20240325-235608-juju-7f2275-prod-proposed-migration-environment-2 --image adt/ubuntu-noble-s390x-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/ 110s autopkgtest [23:57:58]: testbed dpkg architecture: s390x 110s autopkgtest [23:57:58]: testbed apt version: 2.7.12 110s autopkgtest [23:57:58]: @@@@@@@@@@@@@@@@@@@@ test bed setup 111s Get:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease [117 kB] 112s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/universe Sources [3998 kB] 114s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/multiverse Sources [56.0 kB] 114s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/restricted Sources [7592 B] 114s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/main Sources [497 kB] 114s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main s390x Packages [692 kB] 114s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main s390x c-n-f Metadata [3032 B] 114s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/restricted s390x Packages [1372 B] 114s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/restricted s390x c-n-f Metadata [116 B] 114s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/universe s390x Packages [4135 kB] 115s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/universe s390x c-n-f Metadata [7292 B] 115s Get:12 http://ftpmaster.internal/ubuntu noble-proposed/multiverse s390x Packages [47.8 kB] 115s Get:13 http://ftpmaster.internal/ubuntu noble-proposed/multiverse s390x c-n-f Metadata [116 B] 116s Fetched 9562 kB in 4s (2214 kB/s) 117s Reading package lists... 118s Reading package lists... 119s Building dependency tree... 119s Reading state information... 119s Calculating upgrade... 119s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 119s Reading package lists... 119s Building dependency tree... 119s Reading state information... 119s 0 upgraded, 0 newly installed, 0 to remove and 242 not upgraded. 120s Unknown architecture, assuming PC-style ttyS0 120s sh: Attempting to set up Debian/Ubuntu apt sources automatically 120s sh: Distribution appears to be Ubuntu 120s Reading package lists... 121s Building dependency tree... 121s Reading state information... 121s eatmydata is already the newest version (131-1). 121s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 121s Reading package lists... 121s Building dependency tree... 121s Reading state information... 121s dbus is already the newest version (1.14.10-4ubuntu1). 121s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 121s Reading package lists... 121s Building dependency tree... 121s Reading state information... 121s rng-tools-debian is already the newest version (2.4). 121s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 121s Reading package lists... 122s Building dependency tree... 122s Reading state information... 122s The following packages will be REMOVED: 122s cloud-init* python3-configobj* python3-debconf* 122s 0 upgraded, 0 newly installed, 3 to remove and 0 not upgraded. 122s After this operation, 3256 kB disk space will be freed. 122s (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 ... 52170 files and directories currently installed.) 122s Removing cloud-init (24.1.2-0ubuntu1) ... 122s Removing python3-configobj (5.0.8-3) ... 123s Removing python3-debconf (1.5.86) ... 123s Processing triggers for man-db (2.12.0-3) ... 123s (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 ... 51781 files and directories currently installed.) 123s Purging configuration files for cloud-init (24.1.2-0ubuntu1) ... 123s dpkg: warning: while removing cloud-init, directory '/etc/cloud/cloud.cfg.d' not empty so not removed 123s Processing triggers for rsyslog (8.2312.0-3ubuntu3) ... 123s invoke-rc.d: policy-rc.d denied execution of try-restart. 124s Reading package lists... 124s Building dependency tree... 124s Reading state information... 124s linux-generic is already the newest version (6.8.0-11.11+1). 124s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 124s Hit:1 http://ftpmaster.internal/ubuntu noble InRelease 124s Hit:2 http://ftpmaster.internal/ubuntu noble-updates InRelease 125s Hit:3 http://ftpmaster.internal/ubuntu noble-security InRelease 126s Reading package lists... 126s Reading package lists... 126s Building dependency tree... 126s Reading state information... 126s Calculating upgrade... 127s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 127s Reading package lists... 127s Building dependency tree... 127s Reading state information... 127s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 127s autopkgtest [23:58:15]: rebooting testbed after setup commands that affected boot 143s autopkgtest [23:58:31]: testbed running kernel: Linux 6.8.0-11-generic #11-Ubuntu SMP Tue Feb 13 23:45:46 UTC 2024 146s autopkgtest [23:58:34]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 150s Get:1 http://ftpmaster.internal/ubuntu noble/main multipath-tools 0.9.4-5ubuntu3 (dsc) [2733 B] 150s Get:2 http://ftpmaster.internal/ubuntu noble/main multipath-tools 0.9.4-5ubuntu3 (tar) [554 kB] 150s Get:3 http://ftpmaster.internal/ubuntu noble/main multipath-tools 0.9.4-5ubuntu3 (diff) [42.6 kB] 150s gpgv: Signature made Wed Sep 6 23:15:24 2023 UTC 150s gpgv: using RSA key 8A2044F84F716A85B77FF76311DF4294CCA39893 150s gpgv: Can't check signature: No public key 150s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu3.dsc: no acceptable signature found 150s autopkgtest [23:58:38]: testing package multipath-tools version 0.9.4-5ubuntu3 150s autopkgtest [23:58:38]: build not needed 152s autopkgtest [23:58:40]: test kpartx-file-loopback: preparing testbed 158s Reading package lists... 159s Building dependency tree... 159s Reading state information... 159s Starting pkgProblemResolver with broken count: 0 159s Starting 2 pkgProblemResolver with broken count: 0 159s Done 159s The following additional packages will be installed: 159s liburing2 qemu-utils 159s Recommended packages: 159s qemu-block-extra 159s The following NEW packages will be installed: 159s autopkgtest-satdep liburing2 qemu-utils 159s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 159s Need to get 2045 kB/2046 kB of archives. 159s After this operation, 11.8 MB of additional disk space will be used. 159s Get:1 /tmp/autopkgtest.tvgjcT/1-autopkgtest-satdep.deb autopkgtest-satdep s390x 0 [720 B] 159s Get:2 http://ftpmaster.internal/ubuntu noble/main s390x liburing2 s390x 2.5-1 [22.9 kB] 159s Get:3 http://ftpmaster.internal/ubuntu noble/main s390x qemu-utils s390x 1:8.2.1+ds-1ubuntu1 [2022 kB] 161s Fetched 2045 kB in 2s (1328 kB/s) 161s Selecting previously unselected package liburing2:s390x. 161s (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 ... 51726 files and directories currently installed.) 161s Preparing to unpack .../liburing2_2.5-1_s390x.deb ... 161s Unpacking liburing2:s390x (2.5-1) ... 161s Selecting previously unselected package qemu-utils. 161s Preparing to unpack .../qemu-utils_1%3a8.2.1+ds-1ubuntu1_s390x.deb ... 161s Unpacking qemu-utils (1:8.2.1+ds-1ubuntu1) ... 161s Selecting previously unselected package autopkgtest-satdep. 161s Preparing to unpack .../1-autopkgtest-satdep.deb ... 161s Unpacking autopkgtest-satdep (0) ... 161s Setting up liburing2:s390x (2.5-1) ... 161s Setting up qemu-utils (1:8.2.1+ds-1ubuntu1) ... 161s Setting up autopkgtest-satdep (0) ... 161s Processing triggers for man-db (2.12.0-3) ... 162s Processing triggers for libc-bin (2.39-0ubuntu6) ... 164s (Reading database ... 51746 files and directories currently installed.) 164s Removing autopkgtest-satdep (0) ... 164s autopkgtest [23:58:52]: test kpartx-file-loopback: [----------------------- 164s Formatting 'foo.img', fmt=raw size=20971520 166s Creating new GPT entries in memory. 166s Warning: The kernel is still using the old partition table. 166s The new table will be used at the next reboot or after you 166s run partprobe(8) or kpartx(8) 166s The operation has completed successfully. 166s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 166s standard_filename: OK 166s del devmap : loop0p1 166s No devices found 166s standard_filename_cleanup: OK 166s Formatting 'fou du FaFa.img', fmt=raw size=20971520 167s Creating new GPT entries in memory. 167s Warning: The kernel is still using the old partition table. 167s The new table will be used at the next reboot or after you 167s run partprobe(8) or kpartx(8) 167s The operation has completed successfully. 167s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 167s filename_with_spaces: OK 167s del devmap : loop0p1 167s No devices found 167s filename_with_spaces_cleanup: OK 167s autopkgtest [23:58:55]: test kpartx-file-loopback: -----------------------] 168s kpartx-file-loopback PASS 168s autopkgtest [23:58:56]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 168s autopkgtest [23:58:56]: test tgtbasedmpaths: preparing testbed 278s autopkgtest [00:00:46]: testbed dpkg architecture: s390x 279s autopkgtest [00:00:47]: testbed apt version: 2.7.12 279s autopkgtest [00:00:47]: @@@@@@@@@@@@@@@@@@@@ test bed setup 280s Get:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease [117 kB] 280s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/restricted Sources [7592 B] 280s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/universe Sources [3998 kB] 280s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/main Sources [497 kB] 280s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/multiverse Sources [56.0 kB] 280s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main s390x Packages [692 kB] 280s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main s390x c-n-f Metadata [3032 B] 280s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/restricted s390x Packages [1372 B] 280s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/restricted s390x c-n-f Metadata [116 B] 280s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/universe s390x Packages [4135 kB] 280s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/universe s390x c-n-f Metadata [7292 B] 280s Get:12 http://ftpmaster.internal/ubuntu noble-proposed/multiverse s390x Packages [47.8 kB] 280s Get:13 http://ftpmaster.internal/ubuntu noble-proposed/multiverse s390x c-n-f Metadata [116 B] 283s Fetched 9562 kB in 2s (3949 kB/s) 283s Reading package lists... 284s Reading package lists... 285s Building dependency tree... 285s Reading state information... 285s Calculating upgrade... 285s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 285s Reading package lists... 285s Building dependency tree... 285s Reading state information... 285s 0 upgraded, 0 newly installed, 0 to remove and 242 not upgraded. 286s Unknown architecture, assuming PC-style ttyS0 286s sh: Attempting to set up Debian/Ubuntu apt sources automatically 286s sh: Distribution appears to be Ubuntu 286s Reading package lists... 287s Building dependency tree... 287s Reading state information... 287s eatmydata is already the newest version (131-1). 287s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 287s Reading package lists... 287s Building dependency tree... 287s Reading state information... 287s dbus is already the newest version (1.14.10-4ubuntu1). 287s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 287s Reading package lists... 287s Building dependency tree... 287s Reading state information... 288s rng-tools-debian is already the newest version (2.4). 288s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 288s Reading package lists... 288s Building dependency tree... 288s Reading state information... 288s The following packages will be REMOVED: 288s cloud-init* python3-configobj* python3-debconf* 288s 0 upgraded, 0 newly installed, 3 to remove and 0 not upgraded. 288s After this operation, 3256 kB disk space will be freed. 288s (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 ... 52170 files and directories currently installed.) 288s Removing cloud-init (24.1.2-0ubuntu1) ... 289s Removing python3-configobj (5.0.8-3) ... 289s Removing python3-debconf (1.5.86) ... 289s Processing triggers for man-db (2.12.0-3) ... 289s (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 ... 51781 files and directories currently installed.) 289s Purging configuration files for cloud-init (24.1.2-0ubuntu1) ... 290s dpkg: warning: while removing cloud-init, directory '/etc/cloud/cloud.cfg.d' not empty so not removed 290s Processing triggers for rsyslog (8.2312.0-3ubuntu3) ... 290s invoke-rc.d: policy-rc.d denied execution of try-restart. 290s Reading package lists... 290s Building dependency tree... 290s Reading state information... 290s linux-generic is already the newest version (6.8.0-11.11+1). 290s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 291s Hit:1 http://ftpmaster.internal/ubuntu noble InRelease 291s Hit:2 http://ftpmaster.internal/ubuntu noble-updates InRelease 291s Hit:3 http://ftpmaster.internal/ubuntu noble-security InRelease 292s Reading package lists... 292s Reading package lists... 293s Building dependency tree... 293s Reading state information... 293s Calculating upgrade... 293s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 293s Reading package lists... 293s Building dependency tree... 293s Reading state information... 293s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 293s autopkgtest [00:01:01]: rebooting testbed after setup commands that affected boot 319s Reading package lists... 320s Building dependency tree... 320s Reading state information... 320s Starting pkgProblemResolver with broken count: 0 320s Starting 2 pkgProblemResolver with broken count: 0 320s Done 320s The following additional packages will be installed: 320s fio libaio1t64 libatomic1 libboost-iostreams1.83.0 libboost-thread1.83.0 320s libconfig-general-perl libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0 320s libnbd0 libopeniscsiusr librados2 librbd1 librdmacm1t64 lsscsi open-iscsi 320s tgt 320s Suggested packages: 320s fio-examples gnuplot tgt-glusterfs tgt-rbd 320s Recommended packages: 320s finalrd 320s The following NEW packages will be installed: 320s autopkgtest-satdep fio libaio1t64 libatomic1 libboost-iostreams1.83.0 320s libboost-thread1.83.0 libconfig-general-perl libgfapi0 libgfrpc0 libgfxdr0 320s libglusterfs0 libisns0 libnbd0 libopeniscsiusr librados2 librbd1 320s librdmacm1t64 lsscsi open-iscsi tgt 320s 0 upgraded, 20 newly installed, 0 to remove and 0 not upgraded. 320s Need to get 9722 kB/9723 kB of archives. 320s After this operation, 38.5 MB of additional disk space will be used. 320s Get:1 /tmp/autopkgtest.tvgjcT/2-autopkgtest-satdep.deb autopkgtest-satdep s390x 0 [728 B] 320s Get:2 http://ftpmaster.internal/ubuntu noble/main s390x libopeniscsiusr s390x 2.1.9-3ubuntu1 [50.7 kB] 320s Get:3 http://ftpmaster.internal/ubuntu noble/main s390x libisns0 s390x 0.101-0.2 [90.6 kB] 320s Get:4 http://ftpmaster.internal/ubuntu noble/main s390x open-iscsi s390x 2.1.9-3ubuntu1 [333 kB] 321s Get:5 http://ftpmaster.internal/ubuntu noble/main s390x librdmacm1t64 s390x 50.0-2 [74.1 kB] 321s Get:6 http://ftpmaster.internal/ubuntu noble/universe s390x libconfig-general-perl all 2.65-2 [57.1 kB] 321s Get:7 http://ftpmaster.internal/ubuntu noble/universe s390x tgt s390x 1:1.0.85-1.1ubuntu2 [238 kB] 321s Get:8 http://ftpmaster.internal/ubuntu noble/main s390x libaio1t64 s390x 0.3.113-6 [7290 B] 321s Get:9 http://ftpmaster.internal/ubuntu noble/universe s390x libgfxdr0 s390x 11.1-4 [20.0 kB] 321s Get:10 http://ftpmaster.internal/ubuntu noble/universe s390x libglusterfs0 s390x 11.1-4 [283 kB] 321s Get:11 http://ftpmaster.internal/ubuntu noble/universe s390x libgfrpc0 s390x 11.1-4 [41.8 kB] 321s Get:12 http://ftpmaster.internal/ubuntu noble/universe s390x libgfapi0 s390x 11.1-4 [82.1 kB] 321s Get:13 http://ftpmaster.internal/ubuntu noble/universe s390x libnbd0 s390x 1.18.2-1build1 [91.3 kB] 321s Get:14 http://ftpmaster.internal/ubuntu noble/main s390x libboost-iostreams1.83.0 s390x 1.83.0-2ubuntu1 [340 kB] 321s Get:15 http://ftpmaster.internal/ubuntu noble/main s390x libboost-thread1.83.0 s390x 1.83.0-2ubuntu1 [362 kB] 321s Get:16 http://ftpmaster.internal/ubuntu noble/main s390x librados2 s390x 18.2.0-0ubuntu7 [4026 kB] 321s Get:17 http://ftpmaster.internal/ubuntu noble/main s390x libatomic1 s390x 14-20240303-1ubuntu1 [9392 B] 321s Get:18 http://ftpmaster.internal/ubuntu noble/main s390x librbd1 s390x 18.2.0-0ubuntu7 [2912 kB] 321s Get:19 http://ftpmaster.internal/ubuntu noble/universe s390x fio s390x 3.36-1build1 [654 kB] 321s Get:20 http://ftpmaster.internal/ubuntu noble/main s390x lsscsi s390x 0.32-1 [50.2 kB] 321s Preconfiguring packages ... 321s Fetched 9722 kB in 1s (10.7 MB/s) 321s Selecting previously unselected package libopeniscsiusr. 321s (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 ... 51726 files and directories currently installed.) 321s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu1_s390x.deb ... 321s Unpacking libopeniscsiusr (2.1.9-3ubuntu1) ... 321s Selecting previously unselected package libisns0:s390x. 321s Preparing to unpack .../01-libisns0_0.101-0.2_s390x.deb ... 321s Unpacking libisns0:s390x (0.101-0.2) ... 321s Selecting previously unselected package open-iscsi. 321s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu1_s390x.deb ... 322s Unpacking open-iscsi (2.1.9-3ubuntu1) ... 322s Selecting previously unselected package librdmacm1t64:s390x. 322s Preparing to unpack .../03-librdmacm1t64_50.0-2_s390x.deb ... 322s Unpacking librdmacm1t64:s390x (50.0-2) ... 322s Selecting previously unselected package libconfig-general-perl. 322s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 322s Unpacking libconfig-general-perl (2.65-2) ... 322s Selecting previously unselected package tgt. 322s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu2_s390x.deb ... 322s Unpacking tgt (1:1.0.85-1.1ubuntu2) ... 322s Selecting previously unselected package libaio1t64:s390x. 322s Preparing to unpack .../06-libaio1t64_0.3.113-6_s390x.deb ... 322s Unpacking libaio1t64:s390x (0.3.113-6) ... 322s Selecting previously unselected package libgfxdr0:s390x. 322s Preparing to unpack .../07-libgfxdr0_11.1-4_s390x.deb ... 322s Unpacking libgfxdr0:s390x (11.1-4) ... 322s Selecting previously unselected package libglusterfs0:s390x. 322s Preparing to unpack .../08-libglusterfs0_11.1-4_s390x.deb ... 322s Unpacking libglusterfs0:s390x (11.1-4) ... 322s Selecting previously unselected package libgfrpc0:s390x. 322s Preparing to unpack .../09-libgfrpc0_11.1-4_s390x.deb ... 322s Unpacking libgfrpc0:s390x (11.1-4) ... 322s Selecting previously unselected package libgfapi0:s390x. 322s Preparing to unpack .../10-libgfapi0_11.1-4_s390x.deb ... 322s Unpacking libgfapi0:s390x (11.1-4) ... 322s Selecting previously unselected package libnbd0. 322s Preparing to unpack .../11-libnbd0_1.18.2-1build1_s390x.deb ... 322s Unpacking libnbd0 (1.18.2-1build1) ... 322s Selecting previously unselected package libboost-iostreams1.83.0:s390x. 322s Preparing to unpack .../12-libboost-iostreams1.83.0_1.83.0-2ubuntu1_s390x.deb ... 322s Unpacking libboost-iostreams1.83.0:s390x (1.83.0-2ubuntu1) ... 322s Selecting previously unselected package libboost-thread1.83.0:s390x. 322s Preparing to unpack .../13-libboost-thread1.83.0_1.83.0-2ubuntu1_s390x.deb ... 322s Unpacking libboost-thread1.83.0:s390x (1.83.0-2ubuntu1) ... 322s Selecting previously unselected package librados2. 322s Preparing to unpack .../14-librados2_18.2.0-0ubuntu7_s390x.deb ... 322s Unpacking librados2 (18.2.0-0ubuntu7) ... 322s Selecting previously unselected package libatomic1:s390x. 322s Preparing to unpack .../15-libatomic1_14-20240303-1ubuntu1_s390x.deb ... 322s Unpacking libatomic1:s390x (14-20240303-1ubuntu1) ... 322s Selecting previously unselected package librbd1. 322s Preparing to unpack .../16-librbd1_18.2.0-0ubuntu7_s390x.deb ... 322s Unpacking librbd1 (18.2.0-0ubuntu7) ... 322s Selecting previously unselected package fio. 322s Preparing to unpack .../17-fio_3.36-1build1_s390x.deb ... 322s Unpacking fio (3.36-1build1) ... 322s Selecting previously unselected package lsscsi. 322s Preparing to unpack .../18-lsscsi_0.32-1_s390x.deb ... 322s Unpacking lsscsi (0.32-1) ... 322s Selecting previously unselected package autopkgtest-satdep. 322s Preparing to unpack .../19-2-autopkgtest-satdep.deb ... 322s Unpacking autopkgtest-satdep (0) ... 322s Setting up libconfig-general-perl (2.65-2) ... 322s Setting up libboost-thread1.83.0:s390x (1.83.0-2ubuntu1) ... 322s Setting up libnbd0 (1.18.2-1build1) ... 322s Setting up libopeniscsiusr (2.1.9-3ubuntu1) ... 322s Setting up libglusterfs0:s390x (11.1-4) ... 322s Setting up libboost-iostreams1.83.0:s390x (1.83.0-2ubuntu1) ... 322s Setting up libatomic1:s390x (14-20240303-1ubuntu1) ... 322s Setting up lsscsi (0.32-1) ... 322s Setting up libaio1t64:s390x (0.3.113-6) ... 322s Setting up libisns0:s390x (0.101-0.2) ... 322s Setting up librdmacm1t64:s390x (50.0-2) ... 322s Setting up tgt (1:1.0.85-1.1ubuntu2) ... 322s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 323s Setting up libgfxdr0:s390x (11.1-4) ... 323s Setting up librados2 (18.2.0-0ubuntu7) ... 323s Setting up open-iscsi (2.1.9-3ubuntu1) ... 323s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 324s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 324s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 324s Setting up librbd1 (18.2.0-0ubuntu7) ... 324s Setting up libgfrpc0:s390x (11.1-4) ... 324s Setting up libgfapi0:s390x (11.1-4) ... 324s Setting up fio (3.36-1build1) ... 325s Setting up autopkgtest-satdep (0) ... 325s Processing triggers for man-db (2.12.0-3) ... 325s Processing triggers for initramfs-tools (0.142ubuntu20) ... 325s update-initramfs: Generating /boot/initrd.img-6.8.0-11-generic 325s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 329s Using config file '/etc/zipl.conf' 329s Building bootmap in '/boot' 329s Adding IPL section 'ubuntu' (default) 329s Preparing boot device for LD-IPL: vda (0000). 329s Done. 329s Processing triggers for libc-bin (2.39-0ubuntu6) ... 331s (Reading database ... 51948 files and directories currently installed.) 331s Removing autopkgtest-satdep (0) ... 334s autopkgtest [00:01:42]: test tgtbasedmpaths: [----------------------- 334s + targetname=iqn.2016-11.foo.com:target.iscsi 334s + pwd 334s + cwd=/tmp/autopkgtest.tvgjcT/build.wVi/src 334s + testdir=/mnt/tgtmpathtest 334s + localhost=127.0.0.1 334s + portal=127.0.0.1:3260 334s + maxpaths=4 334s + backfn=backingfile 334s + expectwwid=60000000000000000e00000000010001 334s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 334s + bglog=/tmp/autopkgtest.tvgjcT/tgtbasedmpaths-artifacts/test-background.log 334s + fioprep=/tmp/autopkgtest.tvgjcT/tgtbasedmpaths-artifacts/path-change-prep.fio 334s + fiovrfy=/tmp/autopkgtest.tvgjcT/tgtbasedmpaths-artifacts/path-change-check.fio 334s + service tgt restart 334s + truncate --size 100M backingfile 334s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 334s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 334s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.tvgjcT/build.wVi/src/backingfile 334s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 334s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 334s + echo login #1 334s login #1 334s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 334s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 334s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 334s + seq 2 4 334s extra login #2 334s + echo extra login #2 334s + iscsiadm --mode session -r 1 --op new 334s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 334s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 334s extra login #3 334s + echo extra login #3 334s + iscsiadm --mode session -r 1 --op new 334s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 334s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 334s extra login #4 334s + echo extra login #4 334s + iscsiadm --mode session -r 1 --op new 334s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 334s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 334s + udevadm settle 334s + sleep 5 339s Status after initial setup 339s + echo Status after initial setup 339s + tgtadm --lld iscsi --mode target --op show 339s Target 1: iqn.2016-11.foo.com:target.iscsi 339s System information: 339s Driver: iscsi 339s State: ready 339s I_T nexus information: 339s I_T nexus: 1 339s Initiator: iqn.2004-10.com.ubuntu:01:4d79d2cdc1f1 alias: autopkgtest 339s Connection: 0 339s IP Address: 127.0.0.1 339s I_T nexus: 2 339s Initiator: iqn.2004-10.com.ubuntu:01:4d79d2cdc1f1 alias: autopkgtest 339s Connection: 0 339s IP Address: 127.0.0.1 339s I_T nexus: 3 339s Initiator: iqn.2004-10.com.ubuntu:01:4d79d2cdc1f1 alias: autopkgtest 339s Connection: 0 339s IP Address: 127.0.0.1 339s I_T nexus: 4 339s Initiator: iqn.2004-10.com.ubuntu:01:4d79d2cdc1f1 alias: autopkgtest 339s Connection: 0 339s IP Address: 127.0.0.1 339s LUN information: 339s LUN: 0 339s Type: controller 339s SCSI ID: IET 00010000 339s SCSI SN: beaf10 339s Size: 0 MB, Block size: 1 339s Online: Yes 339s Removable media: No 339s Prevent removal: No 339s Readonly: No 339s SWP: No 339s Thin-provisioning: No 339s Backing store type: null 339s Backing store path: None 339s Backing store flags: 339s LUN: 1 339s Type: disk 339s SCSI ID: IET 00010001 339s SCSI SN: beaf11 339s Size: 105 MB, Block size: 512 339s Online: Yes 339s Removable media: No 339s Prevent removal: No 339s Readonly: No 339s SWP: No 339s Thin-provisioning: No 339s Backing store type: rdwr 339s Backing store path: /tmp/autopkgtest.tvgjcT/build.wVi/src/backingfile 339s Backing store flags: 339s Account information: 339s ACL information: 339s ALL 339s + tgtadm --lld iscsi --op show --mode conn --tid 1 339s Session: 4 339s Connection: 0 339s Initiator: iqn.2004-10.com.ubuntu:01:4d79d2cdc1f1 339s IP Address: 127.0.0.1 339s Session: 3 339s Connection: 0 339s Initiator: iqn.2004-10.com.ubuntu:01:4d79d2cdc1f1 339s IP Address: 127.0.0.1 339s Session: 2 339s Connection: 0 339s Initiator: iqn.2004-10.com.ubuntu:01:4d79d2cdc1f1 339s IP Address: 127.0.0.1 339s Session: 1 339s Connection: 0 339s Initiator: iqn.2004-10.com.ubuntu:01:4d79d2cdc1f1 339s IP Address: 127.0.0.1 339s + iscsiadm --mode session -P 1 339s + lsscsi -liv 339s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 339s Current Portal: 127.0.0.1:3260,1 339s Persistent Portal: 127.0.0.1:3260,1 339s ********** 339s Interface: 339s ********** 339s Iface Name: default 339s Iface Transport: tcp 339s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:4d79d2cdc1f1 339s Iface IPaddress: 127.0.0.1 339s Iface HWaddress: default 339s Iface Netdev: default 339s SID: 1 339s iSCSI Connection State: LOGGED IN 339s iSCSI Session State: LOGGED_IN 339s Internal iscsid Session State: NO CHANGE 339s 339s ********** 339s Interface: 339s ********** 339s Iface Name: default 339s Iface Transport: tcp 339s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:4d79d2cdc1f1 339s Iface IPaddress: 127.0.0.1 339s Iface HWaddress: default 339s Iface Netdev: default 339s SID: 2 339s iSCSI Connection State: LOGGED IN 339s iSCSI Session State: LOGGED_IN 339s Internal iscsid Session State: NO CHANGE 339s 339s ********** 339s Interface: 339s ********** 339s Iface Name: default 339s Iface Transport: tcp 339s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:4d79d2cdc1f1 339s Iface IPaddress: 127.0.0.1 339s Iface HWaddress: default 339s Iface Netdev: default 339s SID: 3 339s iSCSI Connection State: LOGGED IN 339s iSCSI Session State: LOGGED_IN 339s Internal iscsid Session State: NO CHANGE 339s 339s ********** 339s Interface: 339s ********** 339s Iface Name: default 339s Iface Transport: tcp 339s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:4d79d2cdc1f1 339s Iface IPaddress: 127.0.0.1 339s Iface HWaddress: default 339s Iface Netdev: default 339s SID: 4 339s iSCSI Connection State: LOGGED IN 339s iSCSI Session State: LOGGED_IN 339s Internal iscsid Session State: NO CHANGE 339s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 340s [0:0:0:0] storage IET Controller 0001 - - 340s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 340s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 340s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 340s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 340s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 340s [1:0:0:0] storage IET Controller 0001 - - 340s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 340s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 340s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 340s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 340s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 340s [2:0:0:0] storage IET Controller 0001 - - 340s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 340s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 340s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 340s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 340s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 340s [3:0:0:0] storage IET Controller 0001 - - 340s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 340s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 340s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 340s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 340s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 340s NVMe module may not be loaded 340s ===== paths list ===== 340s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 340s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK unknown 340s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 340s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 340s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 340s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 340s size=100M features='0' hwhandler='0' wp=rw 340s |-+- policy='service-time 0' prio=1 status=active 340s | `- 0:0:0:1 sda 8:0 active ready running 340s |-+- policy='service-time 0' prio=1 status=enabled 340s | `- 1:0:0:1 sdb 8:16 active ready running 340s |-+- policy='service-time 0' prio=1 status=enabled 340s | `- 2:0:0:1 sdc 8:32 active ready running 340s `-+- policy='service-time 0' prio=1 status=enabled 340s `- 3:0:0:1 sdd 8:48 active ready running 340s mpatha: 0 204800 multipath 0 0 4 1 service-time 0 1 2 8:0 1 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 340s Test WWN should now point to DM 340s ../../dm-0 340s + multipath -v3 -ll 340s 36.782846 | set open fds limit to 1048576/1048576 340s 36.782903 | loading /lib/multipath/libchecktur.so checker 340s 36.782981 | checker tur: message table size = 3 340s 36.782993 | loading /lib/multipath/libprioconst.so prioritizer 340s 36.783069 | _init_foreign: foreign library "nvme" is not enabled 340s 36.786307 | vda: device node name blacklisted 340s 36.786447 | sda: size = 204800 340s 36.786537 | sda: vendor = IET 340s 36.786554 | sda: product = VIRTUAL-DISK 340s 36.786567 | sda: rev = 0001 340s 36.787188 | sda: h:b:t:l = 0:0:0:1 340s 36.787409 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 340s 36.787417 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 340s 36.787419 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 340s 36.787596 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 340s 36.787606 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 340s 36.787618 | sda: serial = beaf11 340s 36.787620 | sda: detect_checker = yes (setting: multipath internal) 340s 36.787847 | sda: path_checker = tur (setting: multipath internal) 340s 36.787857 | sda: checker timeout = 30 s (setting: kernel sysfs) 340s 36.787939 | sda: tur state = up 340s 36.788017 | sdb: size = 204800 340s 36.788111 | sdb: vendor = IET 340s 36.788129 | sdb: product = VIRTUAL-DISK 340s 36.788140 | sdb: rev = 0001 340s 36.788810 | sdb: h:b:t:l = 1:0:0:1 340s 36.789038 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 340s 36.789045 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 340s 36.789047 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 340s 36.789176 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 340s 36.789184 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 340s 36.789193 | sdb: serial = beaf11 340s 36.789195 | sdb: detect_checker = yes (setting: multipath internal) 340s 36.789318 | sdb: path_checker = tur (setting: multipath internal) 340s 36.789326 | sdb: checker timeout = 30 s (setting: kernel sysfs) 340s 36.789376 | sdb: tur state = up 340s 36.789453 | sdc: size = 204800 340s 36.789539 | sdc: vendor = IET 340s 36.789556 | sdc: product = VIRTUAL-DISK 340s 36.789569 | sdc: rev = 0001 340s 36.790247 | sdc: h:b:t:l = 2:0:0:1 340s 36.790464 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 340s 36.790471 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 340s 36.790473 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 340s 36.790747 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 340s 36.790755 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 340s 36.790766 | sdc: serial = beaf11 340s 36.790768 | sdc: detect_checker = yes (setting: multipath internal) 340s 36.790836 | sdc: path_checker = tur (setting: multipath internal) 340s 36.790845 | sdc: checker timeout = 30 s (setting: kernel sysfs) 340s 36.790903 | sdc: tur state = up 340s 36.790985 | sdd: size = 204800 340s 36.791069 | sdd: vendor = IET 340s 36.791086 | sdd: product = VIRTUAL-DISK 340s 36.791098 | sdd: rev = 0001 340s 36.791703 | sdd: h:b:t:l = 3:0:0:1 340s 36.791918 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 340s 36.791926 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 340s 36.791928 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 340s 36.792203 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 340s 36.792214 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 340s 36.792232 | sdd: serial = beaf11 340s 36.792234 | sdd: detect_checker = yes (setting: multipath internal) 340s 36.792328 | sdd: path_checker = tur (setting: multipath internal) 340s 36.792336 | sdd: checker timeout = 30 s (setting: kernel sysfs) 340s 36.792405 | sdd: tur state = up 340s 36.792520 | loop0: device node name blacklisted 340s 36.792583 | loop1: device node name blacklisted 340s 36.792641 | loop2: device node name blacklisted 340s 36.792697 | loop3: device node name blacklisted 340s 36.792753 | loop4: device node name blacklisted 340s 36.792807 | loop5: device node name blacklisted 340s 36.792862 | loop6: device node name blacklisted 340s 36.792916 | loop7: device node name blacklisted 340s 36.792977 | dm-0: device node name blacklisted 340s 36.793584 | multipath-tools v0.9.4 (12/19, 2022) 340s 36.793603 | libdevmapper version 1.02.185 340s 36.793748 | kernel device mapper v4.48.0 340s 36.793766 | DM multipath kernel driver v1.14.0 340s 36.793874 | sda: size = 204800 340s 36.793885 | sda: vendor = IET 340s 36.793887 | sda: product = VIRTUAL-DISK 340s 36.793888 | sda: rev = 0001 340s 36.794509 | sda: h:b:t:l = 0:0:0:1 340s 36.794586 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 340s 36.794603 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 340s 36.794605 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 340s 36.794614 | sda: serial = beaf11 340s 36.794722 | sda: tur state = up 340s 36.794732 | sda: uid = 360000000000000000e00000000010001 (udev) 340s 36.794735 | sda: detect_prio = yes (setting: multipath internal) 340s 36.794737 | sda: prio = const (setting: multipath internal) 340s 36.794738 | sda: prio args = "" (setting: multipath internal) 340s 36.794740 | sda: const prio = 1 340s 36.794764 | sdb: size = 204800 340s 36.794771 | sdb: vendor = IET 340s 36.794773 | sdb: product = VIRTUAL-DISK 340s 36.794774 | sdb: rev = 0001 340s 36.795405 | sdb: h:b:t:l = 1:0:0:1 340s 36.795485 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 340s 36.795499 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 340s 36.795501 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 340s 36.795510 | sdb: serial = beaf11 340s 36.795560 | sdb: tur state = up 340s 36.795566 | sdb: uid = 360000000000000000e00000000010001 (udev) 340s 36.795567 | sdb: detect_prio = yes (setting: multipath internal) 340s 36.795569 | sdb: prio = const (setting: multipath internal) 340s 36.795570 | sdb: prio args = "" (setting: multipath internal) 340s 36.795571 | sdb: const prio = 1 340s 36.795583 | sdc: size = 204800 340s 36.795586 | sdc: vendor = IET 340s 36.795587 | sdc: product = VIRTUAL-DISK 340s 36.795589 | sdc: rev = 0001 340s 36.796188 | sdc: h:b:t:l = 2:0:0:1 340s 36.796258 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 340s 36.796271 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 340s 36.796273 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 340s 36.796280 | sdc: serial = beaf11 340s 36.796322 | sdc: tur state = up 340s 36.796325 | sdc: uid = 360000000000000000e00000000010001 (udev) 340s 36.796326 | sdc: detect_prio = yes (setting: multipath internal) 340s 36.796327 | sdc: prio = const (setting: multipath internal) 340s 36.796328 | sdc: prio args = "" (setting: multipath internal) 340s 36.796330 | sdc: const prio = 1 340s 36.796341 | sdd: size = 204800 340s 36.796343 | sdd: vendor = IET 340s 36.796345 | sdd: product = VIRTUAL-DISK 340s 36.796347 | sdd: rev = 0001 340s 36.796946 | sdd: h:b:t:l = 3:0:0:1 340s 36.797015 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 340s 36.797029 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 340s 36.797030 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 340s 36.797038 | sdd: serial = beaf11 340s 36.797088 | sdd: tur state = up 340s 36.797096 | sdd: uid = 360000000000000000e00000000010001 (udev) 340s 36.797097 | sdd: detect_prio = yes (setting: multipath internal) 340s 36.797098 | sdd: prio = const (setting: multipath internal) 340s 36.797100 | sdd: prio args = "" (setting: multipath internal) 340s 36.797101 | sdd: const prio = 1 340s 36.797630 | unloading tur checker 340s 36.797656 | unloading const prioritizer 340s + dmsetup table 340s + echo Test WWN should now point to DM 340s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 340s + grep dm 340s Creating filesystem with 25600 4k blocks and 25600 inodes 340s 340s Allocating group tables: 0/1 done 340s Writing inode tables: 0/1 done 340s Creating journal (1024 blocks): done 340s Writing superblocks and filesystem accounting information: 0/1 done 340s 340s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 340s mke2fs 1.47.0 (5-Feb-2023) 340s + udevadm settle 340s + sleep 3s 343s + mkdir -p /mnt/tgtmpathtest 343s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 343s + cat 343s + cat 343s + fio --max-jobs=4 /tmp/autopkgtest.tvgjcT/tgtbasedmpaths-artifacts/path-change-prep.fio 343s 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 343s fio-3.36 343s Starting 1 thread 343s write-phase: Laying out IO file (1 file / 17592186044415MiB) 343s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 343s 343s write-phase: (groupid=0, jobs=1): err= 0: pid=4135: Tue Mar 26 00:01:51 2024 343s write: IOPS=3167, BW=198MiB/s (207MB/s)(87.6MiB/443msec); 0 zone resets 343s clat (usec): min=209, max=10210, avg=303.49, stdev=495.96 343s lat (usec): min=220, max=10223, avg=315.03, stdev=496.09 343s clat percentiles (usec): 343s | 1.00th=[ 217], 5.00th=[ 227], 10.00th=[ 231], 20.00th=[ 241], 343s | 30.00th=[ 251], 40.00th=[ 258], 50.00th=[ 265], 60.00th=[ 269], 343s | 70.00th=[ 281], 80.00th=[ 297], 90.00th=[ 326], 95.00th=[ 363], 343s | 99.00th=[ 586], 99.50th=[ 963], 99.90th=[ 9896], 99.95th=[10159], 343s | 99.99th=[10159] 343s lat (usec) : 250=28.65%, 500=69.71%, 750=0.86%, 1000=0.29% 343s lat (msec) : 2=0.07%, 4=0.07%, 10=0.21%, 20=0.07% 343s cpu : usr=3.85%, sys=6.56%, ctx=1404, majf=0, minf=1 343s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 343s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 343s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 343s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 343s latency : target=0, window=0, percentile=100.00%, depth=1 343s 343s Run status group 0 (all jobs): 343s WRITE: bw=198MiB/s (207MB/s), 198MiB/s-198MiB/s (207MB/s-207MB/s), io=87.6MiB (91.9MB), run=443-443msec 343s 343s Disk stats (read/write): 343s dm-0: ios=1/1218, sectors=8/155904, merge=0/0, ticks=0/364, in_queue=363, util=81.14%, aggrios=0/351, aggsectors=2/44884, aggrmerge=0/0, aggrticks=0/99, aggrin_queue=99, aggrutil=80.94% 343s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 343s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 343s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 343s sda: ios=1/1404, sectors=8/179536, merge=0/0, ticks=0/396, in_queue=397, util=80.94% 343s Starting the path changes in background 343s + echo Starting the path changes in background 343s + date +Pre FIO %H:%M:%S.%N 343s Pre FIO 00:01:51.648172332 343s + fio --max-jobs=4 /tmp/autopkgtest.tvgjcT/tgtbasedmpaths-artifacts/path-change-check.fio 343s 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 343s fio-3.36 343s Starting 1 thread 523s 523s verify-phase: (groupid=0, jobs=1): err= 0: pid=4146: Tue Mar 26 00:04:51 2024 523s read: IOPS=5948, BW=372MiB/s (390MB/s)(65.3GiB/180001msec) 523s clat (usec): min=66, max=137579, avg=148.00, stdev=327.51 523s lat (usec): min=66, max=137579, avg=148.06, stdev=327.51 523s clat percentiles (usec): 523s | 1.00th=[ 80], 5.00th=[ 89], 10.00th=[ 96], 20.00th=[ 108], 523s | 30.00th=[ 118], 40.00th=[ 127], 50.00th=[ 137], 60.00th=[ 151], 523s | 70.00th=[ 165], 80.00th=[ 178], 90.00th=[ 196], 95.00th=[ 217], 523s | 99.00th=[ 297], 99.50th=[ 355], 99.90th=[ 783], 99.95th=[ 1942], 523s | 99.99th=[ 7177] 523s bw ( KiB/s): min=118400, max=608128, per=100.00%, avg=381022.41, stdev=62166.76, samples=359 523s iops : min= 1850, max= 9502, avg=5953.47, stdev=971.35, samples=359 523s lat (usec) : 100=13.27%, 250=84.62%, 500=1.94%, 750=0.07%, 1000=0.02% 523s lat (msec) : 2=0.03%, 4=0.02%, 10=0.02%, 20=0.01%, 50=0.01% 523s lat (msec) : 100=0.01%, 250=0.01% 523s cpu : usr=12.11%, sys=7.93%, ctx=1070826, majf=0, minf=16 523s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 523s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 523s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 523s issued rwts: total=1070701,0,0,0 short=0,0,0,0 dropped=0,0,0,0 523s latency : target=0, window=0, percentile=100.00%, depth=1 523s 523s Run status group 0 (all jobs): 523s READ: bw=372MiB/s (390MB/s), 372MiB/s-372MiB/s (390MB/s-390MB/s), io=65.3GiB (70.2GB), run=180001-180001msec 523s 523s Disk stats (read/write): 523s dm-0: ios=1071006/9, sectors=136986848/12912, merge=0/8, ticks=160478/93, in_queue=160645, util=100.00%, aggrios=81249/2, aggsectors=10391384/3228, aggrmerge=0/0, aggrticks=9932/4, aggrin_queue=9936, aggrutil=99.15% 523s sdd: ios=130570/4, sectors=16701056/48, merge=0/0, ticks=15798/1, in_queue=15799, util=39.39% 523s sdb: ios=62584/0, sectors=8000736/0, merge=0/0, ticks=8119/0, in_queue=8119, util=50.13% 523s sdc: ios=66467/0, sectors=8501760/0, merge=0/0, ticks=7822/0, in_queue=7821, util=32.69% 523s sda: ios=65376/4, sectors=8361984/12864, merge=0/0, ticks=7991/18, in_queue=8008, util=99.15% 523s + date +Post FIO %H:%M:%S.%N 523s + echo FIO verify test with changing paths - OK 523s + echo Report log of background activity 523s + cat /tmp/autopkgtest.tvgjcT/tgtbasedmpaths-artifacts/test-background.log 523s Post FIO 00:04:51.795076035 523s FIO verify test with changing paths - OK 523s Report log of background activity 523s + iscsiadm --mode session 523s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s + sleep 10s 523s + date +MP report (expect 4) %H:%M:%S.%N 523s MP report (expect 4) 00:02:01.653497020 523s + multipath -ll 523s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 523s size=100M features='0' hwhandler='0' wp=rw 523s |-+- policy='service-time 0' prio=1 status=active 523s | `- 0:0:0:1 sda 8:0 active ready running 523s |-+- policy='service-time 0' prio=1 status=enabled 523s | `- 1:0:0:1 sdb 8:16 active ready running 523s |-+- policy='service-time 0' prio=1 status=enabled 523s | `- 2:0:0:1 sdc 8:32 active ready running 523s `-+- policy='service-time 0' prio=1 status=enabled 523s `- 3:0:0:1 sdd 8:48 active ready running 523s + date +UN-plug path 1 %H:%M:%S.%N 523s UN-plug path 1 00:02:01.672675148 523s + iscsiadm --mode session -r 1 -u 523s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 523s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 523s + iscsiadm --mode session 523s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s + sleep 10s 523s + date +MP report (expect 3) %H:%M:%S.%N 523s MP report (expect 3) 00:02:11.902831583 523s + multipath -ll 523s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 523s size=100M features='0' hwhandler='0' wp=rw 523s |-+- policy='service-time 0' prio=1 status=active 523s | `- 1:0:0:1 sdb 8:16 active ready running 523s |-+- policy='service-time 0' prio=1 status=enabled 523s | `- 2:0:0:1 sdc 8:32 active ready running 523s `-+- policy='service-time 0' prio=1 status=enabled 523s `- 3:0:0:1 sdd 8:48 active ready running 523s + date +UN-plug path 2 %H:%M:%S.%N 523s UN-plug path 2 00:02:11.917962396 523s + iscsiadm --mode session -r 2 -u 523s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 523s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 523s + iscsiadm --mode session 523s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s + sleep 10s 523s + date +MP report (expect 2) %H:%M:%S.%N 523s MP report (expect 2) 00:02:22.043681607 523s + multipath -ll 523s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 523s size=100M features='0' hwhandler='0' wp=rw 523s |-+- policy='service-time 0' prio=1 status=active 523s | `- 2:0:0:1 sdc 8:32 active ready running 523s `-+- policy='service-time 0' prio=1 status=enabled 523s `- 3:0:0:1 sdd 8:48 active ready running 523s + date +UN-plug path 3 %H:%M:%S.%N 523s UN-plug path 3 00:02:22.056064488 523s + iscsiadm --mode session -r 3 -u 523s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 523s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 523s + iscsiadm --mode session 523s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s + sleep 10s 523s + date +MP report (expect 1) %H:%M:%S.%N 523s MP report (expect 1) 00:02:32.252490832 523s + multipath -ll 523s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 523s size=100M features='0' hwhandler='0' wp=rw 523s `-+- policy='service-time 0' prio=1 status=active 523s `- 3:0:0:1 sdd 8:48 active ready running 523s + date +Add paths 5/6/7/8 %H:%M:%S.%N 523s Add paths 5/6/7/8 00:02:32.262101196 523s + iscsiadm --mode session -r 4 --op new 523s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 523s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 523s + iscsiadm --mode session -r 4 --op new 523s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 523s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 523s + iscsiadm --mode session -r 4 --op new 523s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 523s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 523s + iscsiadm --mode session -r 4 --op new 523s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 523s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 523s + iscsiadm --mode session 523s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s + sleep 10s 523s + date +MP report (expect 5) %H:%M:%S.%N 523s MP report (expect 5) 00:02:42.349395147 523s + multipath -ll 523s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 523s size=100M features='0' hwhandler='0' wp=rw 523s |-+- policy='service-time 0' prio=1 status=active 523s | `- 3:0:0:1 sdd 8:48 active ready running 523s |-+- policy='service-time 0' prio=1 status=enabled 523s | `- 0:0:0:1 sda 8:0 active ready running 523s |-+- policy='service-time 0' prio=1 status=enabled 523s | `- 1:0:0:1 sdb 8:16 active ready running 523s |-+- policy='service-time 0' prio=1 status=enabled 523s | `- 2:0:0:1 sdc 8:32 active ready running 523s `-+- policy='service-time 0' prio=1 status=enabled 523s `- 4:0:0:1 sde 8:64 active ready running 523s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 523s UN-plug multiple paths 4/7/8 00:02:42.371993397 523s + iscsiadm --mode session -r 4 -u 523s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 523s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 523s + iscsiadm --mode session -r 7 -u 523s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 523s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 523s + iscsiadm --mode session -r 8 -u 523s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 523s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 523s + iscsiadm --mode session 523s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 523s + sleep 10s 523s + date +Restart multipath daemon %H:%M:%S.%N 523s Restart multipath daemon 00:02:52.842437221 523s + systemctl restart multipathd 523s + sleep 10s 523s + date +Final background report (expect 2) %H:%M:%S.%N 523s Final background report (expect 2) 00:03:02.947278159 523s + multipath -ll 523s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 523s size=100M features='0' hwhandler='0' wp=rw 523s |-+- policy='service-time 0' prio=1 status=active 523s | `- 0:0:0:1 sda 8:0 active ready running 523s `-+- policy='service-time 0' prio=1 status=enabled 523s `- 1:0:0:1 sdb 8:16 active ready running 523s Final stats 523s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 523s iSCSI SNMP: 523s txdata_octets: 35809032 523s rxdata_octets: 48864881412 523s noptx_pdus: 0 523s scsicmd_pdus: 745754 523s tmfcmd_pdus: 0 523s login_pdus: 0 523s text_pdus: 0 523s dataout_pdus: 0 523s logout_pdus: 0 523s snack_pdus: 0 523s noprx_pdus: 0 523s scsirsp_pdus: 745754 523s tmfrsp_pdus: 0 523s textrsp_pdus: 0 523s datain_pdus: 745719 523s logoutrsp_pdus: 0 523s r2t_pdus: 0 523s async_pdus: 0 523s rjt_pdus: 0 523s digest_err: 0 523s timeout_err: 0 523s iSCSI Extended: 523s tx_sendpage_failures: 0 523s rx_discontiguous_hdr: 0 523s eh_abort_cnt: 0 523s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 523s iSCSI SNMP: 523s txdata_octets: 7512 523s rxdata_octets: 1089876 523s noptx_pdus: 0 523s scsicmd_pdus: 126 523s tmfcmd_pdus: 0 523s login_pdus: 0 523s text_pdus: 0 523s dataout_pdus: 0 523s logout_pdus: 0 523s snack_pdus: 0 523s noprx_pdus: 0 523s scsirsp_pdus: 126 523s tmfrsp_pdus: 0 523s textrsp_pdus: 0 523s datain_pdus: 102 523s logoutrsp_pdus: 0 523s r2t_pdus: 0 523s async_pdus: 0 523s rjt_pdus: 0 523s digest_err: 0 523s timeout_err: 0 523s iSCSI Extended: 523s tx_sendpage_failures: 0 523s rx_discontiguous_hdr: 0 523s eh_abort_cnt: 0 523s Mar 25 03:56:28 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 523s Mar 25 03:56:29 ubuntu multipathd[352]: multipathd v0.9.4: start up 523s Mar 25 03:56:29 ubuntu multipathd[352]: reconfigure: setting up paths and maps 523s Mar 25 03:56:29 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 523s Mar 25 03:57:55 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 multipathd[352]: multipathd: shut down 523s Mar 25 03:57:55 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 523s Mar 25 03:57:55 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 systemd[1]: multipathd.service: Deactivated successfully. 523s Mar 25 03:57:55 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 523s -- Boot d18595e9b7474f0a8ab08da8d97a35e2 -- 523s Mar 25 03:57:59 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 523s Mar 25 03:57:59 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 multipathd[272]: multipathd v0.9.4: start up 523s Mar 25 03:57:59 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 multipathd[272]: reconfigure: setting up paths and maps 523s Mar 25 03:57:59 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 523s Mar 25 03:58:17 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 multipathd[272]: multipathd: shut down 523s Mar 25 03:58:17 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 523s Mar 25 03:58:17 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 systemd[1]: multipathd.service: Deactivated successfully. 523s Mar 25 03:58:17 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 523s -- Boot 8dc4012e007e4c46a2689bf17b3ee80e -- 523s Mar 26 00:00:19 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 multipathd[322]: multipathd v0.9.4: start up 523s Mar 26 00:00:19 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 multipathd[322]: reconfigure: setting up paths and maps 523s Mar 26 00:00:19 auto-syncubuntu-noble-daily-s390x-server-20240312-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 523s Mar 26 00:01:06 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 523s Mar 26 00:01:06 autopkgtest multipathd[322]: multipathd: shut down 523s Mar 26 00:01:06 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 523s Mar 26 00:01:06 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 523s -- Boot f89f165e994c4307ac9bd970fc3e2e9e -- 523s Mar 26 00:01:11 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 523s Mar 26 00:01:11 autopkgtest multipathd[335]: multipathd v0.9.4: start up 523s Mar 26 00:01:11 autopkgtest multipathd[335]: reconfigure: setting up paths and maps 523s Mar 26 00:01:11 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 523s Mar 26 00:01:41 autopkgtest multipathd[335]: mpatha: addmap [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 523s Mar 26 00:01:41 autopkgtest multipathd[335]: sdb [8:16]: path added to devmap mpatha 523s Mar 26 00:01:41 autopkgtest multipathd[335]: mpatha: performing delayed actions 523s Mar 26 00:01:41 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 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] 523s Mar 26 00:02:01 autopkgtest multipathd[335]: 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:48 1] 523s Mar 26 00:02:01 autopkgtest multipathd[335]: check_removed_paths: sda: freeing path in removed state 523s Mar 26 00:02:01 autopkgtest multipathd[335]: 8:0: path removed from map mpatha 523s Mar 26 00:02:11 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 523s Mar 26 00:02:12 autopkgtest multipathd[335]: check_removed_paths: sdb: freeing path in removed state 523s Mar 26 00:02:12 autopkgtest multipathd[335]: 8:16: path removed from map mpatha 523s Mar 26 00:02:22 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 523s Mar 26 00:02:22 autopkgtest multipathd[335]: check_removed_paths: sdc: freeing path in removed state 523s Mar 26 00:02:22 autopkgtest multipathd[335]: 8:32: path removed from map mpatha 523s Mar 26 00:02:32 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1] 523s Mar 26 00:02:32 autopkgtest multipathd[335]: sda [8:0]: path added to devmap mpatha 523s Mar 26 00:02:32 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 523s Mar 26 00:02:32 autopkgtest multipathd[335]: sdb [8:16]: path added to devmap mpatha 523s Mar 26 00:02:32 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 523s Mar 26 00:02:32 autopkgtest multipathd[335]: sdc [8:32]: path added to devmap mpatha 523s Mar 26 00:02:32 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 523s Mar 26 00:02:32 autopkgtest multipathd[335]: sde [8:64]: path added to devmap mpatha 523s Mar 26 00:02:42 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 523s Mar 26 00:02:42 autopkgtest multipathd[335]: check_removed_paths: sdd: freeing path in removed state 523s Mar 26 00:02:42 autopkgtest multipathd[335]: 8:48: path removed from map mpatha 523s Mar 26 00:02:42 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:64 1] 523s Mar 26 00:02:42 autopkgtest multipathd[335]: check_removed_paths: sdc: freeing path in removed state 523s Mar 26 00:02:42 autopkgtest multipathd[335]: 8:32: path removed from map mpatha 523s Mar 26 00:02:42 autopkgtest multipathd[335]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 523s Mar 26 00:02:42 autopkgtest multipathd[335]: check_removed_paths: sde: freeing path in removed state 523s Mar 26 00:02:42 autopkgtest multipathd[335]: 8:64: path removed from map mpatha 523s Mar 26 00:02:52 autopkgtest multipathd[335]: multipathd: shut down 523s Mar 26 00:02:52 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 523s Mar 26 00:02:52 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 523s Mar 26 00:02:52 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 523s Mar 26 00:02:52 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 523s Mar 26 00:02:52 autopkgtest multipathd[4472]: multipathd v0.9.4: start up 523s Mar 26 00:02:52 autopkgtest multipathd[4472]: reconfigure: setting up paths and maps 523s Mar 26 00:02:52 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 523s + sync 523s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 523s + echo Final stats 523s + iscsiadm --mode session --stats 523s + journalctl --no-pager -u multipathd 523s + echo Check final path status 523s + multipath -ll 523s + multipath -ll 523s + grep --count status= 523s + diskc=2 523s + multipath -ll 523s + grep --count status=active 523s + diska=1 523s + multipath -ll 523s + grep --count status=enabled 523s + diske=1 523s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 523s + echo OK 523s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 523s Check final path status 523s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 523s size=100M features='0' hwhandler='0' wp=rw 523s |-+- policy='service-time 0' prio=1 status=active 523s | `- 0:0:0:1 sda 8:0 active ready running 523s `-+- policy='service-time 0' prio=1 status=enabled 523s `- 1:0:0:1 sdb 8:16 active ready running 523s OK 524s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 524s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 524s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 524s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 524s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 524s autopkgtest [00:04:52]: test tgtbasedmpaths: -----------------------] 525s autopkgtest [00:04:53]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 525s tgtbasedmpaths PASS 525s autopkgtest [00:04:53]: @@@@@@@@@@@@@@@@@@@@ summary 525s kpartx-file-loopback PASS 525s tgtbasedmpaths PASS 538s Creating nova instance adt-noble-s390x-multipath-tools-20240325-235608-juju-7f2275-prod-proposed-migration-environment-2 from image adt/ubuntu-noble-s390x-server-20240325.img (UUID 9f25d9bc-613c-4979-9452-2ea8e4d84cd0)... 538s Creating nova instance adt-noble-s390x-multipath-tools-20240325-235608-juju-7f2275-prod-proposed-migration-environment-2 from image adt/ubuntu-noble-s390x-server-20240325.img (UUID 9f25d9bc-613c-4979-9452-2ea8e4d84cd0)...