0s autopkgtest [18:10:09]: starting date and time: 2024-07-19 18:10:09+0000 0s autopkgtest [18:10:09]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [18:10:09]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.7gdyyxx9/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:linux-meta,src:linux-signed,src:linux --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=linux-meta/6.10.0-15.15 linux-signed/6.10.0-15.15 linux/6.10.0-15.15' --setup-commands 'apt-get install -y ^kernel-testing--linux--full--preferred$ || apt-get install -y ^linux-image$ ^linux-headers$ || apt-get install -y ^linux-image-generic$ ^linux-headers-generic$' --setup-commands 'apt-get install -y ^kernel-testing--linux--modules-extra--preferred$ || apt-get install -y ^linux-modules-extra$ || :' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos01-s390x-4.secgroup --name adt-oracular-s390x-multipath-tools-20240719-181009-juju-7f2275-prod-proposed-migration-environment-3-8ca7fa2e-22f6-462b-b30f-851da6640b32 --image adt/ubuntu-oracular-s390x-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://us.ports.ubuntu.com/ubuntu-ports/ 67s autopkgtest [18:11:16]: testbed dpkg architecture: s390x 67s autopkgtest [18:11:16]: testbed apt version: 2.9.6 67s autopkgtest [18:11:16]: @@@@@@@@@@@@@@@@@@@@ test bed setup 68s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 69s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [372 kB] 69s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.7 kB] 69s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3232 B] 69s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 69s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x Packages [73.4 kB] 69s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x c-n-f Metadata [2112 B] 69s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted s390x Packages [1368 B] 69s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted s390x c-n-f Metadata [120 B] 69s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe s390x Packages [364 kB] 69s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe s390x c-n-f Metadata [8372 B] 69s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse s390x Packages [1844 B] 69s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse s390x c-n-f Metadata [120 B] 69s Fetched 1014 kB in 1s (1319 kB/s) 69s Reading package lists... 71s Reading package lists... 71s Building dependency tree... 71s Reading state information... 71s Calculating upgrade... 72s The following NEW packages will be installed: 72s libpython3.12t64 linux-headers-6.10.0-15 linux-headers-6.10.0-15-generic 72s linux-image-6.10.0-15-generic linux-modules-6.10.0-15-generic 72s linux-modules-extra-6.10.0-15-generic linux-tools-6.10.0-15 72s linux-tools-6.10.0-15-generic 72s The following packages will be upgraded: 72s libxml2 linux-generic linux-headers-generic linux-headers-virtual 72s linux-image-generic linux-image-virtual linux-libc-dev linux-tools-common 72s linux-virtual 72s 9 upgraded, 8 newly installed, 0 to remove and 0 not upgraded. 72s Need to get 65.7 MB of archives. 72s After this operation, 168 MB of additional disk space will be used. 72s Get:1 http://ftpmaster.internal/ubuntu oracular/main s390x libxml2 s390x 2.12.7+dfsg-3 [663 kB] 72s Get:2 http://ftpmaster.internal/ubuntu oracular/main s390x libpython3.12t64 s390x 3.12.4-1ubuntu1 [2476 kB] 72s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-modules-6.10.0-15-generic s390x 6.10.0-15.15 [20.4 MB] 74s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-image-6.10.0-15-generic s390x 6.10.0-15.15 [9453 kB] 74s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-modules-extra-6.10.0-15-generic s390x 6.10.0-15.15 [11.0 MB] 75s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-generic s390x 6.10.0-15.15 [1728 B] 75s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-image-generic s390x 6.10.0-15.15 [10.4 kB] 75s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-virtual s390x 6.10.0-15.15 [1722 B] 75s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-image-virtual s390x 6.10.0-15.15 [10.4 kB] 75s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-headers-virtual s390x 6.10.0-15.15 [1646 B] 75s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-headers-6.10.0-15 all 6.10.0-15.15 [13.8 MB] 77s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-headers-6.10.0-15-generic s390x 6.10.0-15.15 [2705 kB] 78s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-headers-generic s390x 6.10.0-15.15 [10.3 kB] 78s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-libc-dev s390x 6.10.0-15.15 [1638 kB] 78s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-tools-common all 6.10.0-15.15 [474 kB] 78s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-tools-6.10.0-15 s390x 6.10.0-15.15 [3109 kB] 78s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-tools-6.10.0-15-generic s390x 6.10.0-15.15 [1724 B] 79s Fetched 65.7 MB in 7s (9847 kB/s) 79s (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 ... 54705 files and directories currently installed.) 79s Preparing to unpack .../00-libxml2_2.12.7+dfsg-3_s390x.deb ... 79s Unpacking libxml2:s390x (2.12.7+dfsg-3) over (2.9.14+dfsg-1.3ubuntu3) ... 79s Selecting previously unselected package libpython3.12t64:s390x. 79s Preparing to unpack .../01-libpython3.12t64_3.12.4-1ubuntu1_s390x.deb ... 79s Unpacking libpython3.12t64:s390x (3.12.4-1ubuntu1) ... 79s Selecting previously unselected package linux-modules-6.10.0-15-generic. 79s Preparing to unpack .../02-linux-modules-6.10.0-15-generic_6.10.0-15.15_s390x.deb ... 79s Unpacking linux-modules-6.10.0-15-generic (6.10.0-15.15) ... 79s Selecting previously unselected package linux-image-6.10.0-15-generic. 79s Preparing to unpack .../03-linux-image-6.10.0-15-generic_6.10.0-15.15_s390x.deb ... 79s Unpacking linux-image-6.10.0-15-generic (6.10.0-15.15) ... 79s Selecting previously unselected package linux-modules-extra-6.10.0-15-generic. 79s Preparing to unpack .../04-linux-modules-extra-6.10.0-15-generic_6.10.0-15.15_s390x.deb ... 79s Unpacking linux-modules-extra-6.10.0-15-generic (6.10.0-15.15) ... 79s Preparing to unpack .../05-linux-generic_6.10.0-15.15_s390x.deb ... 79s Unpacking linux-generic (6.10.0-15.15) over (6.8.0-31.31) ... 79s Preparing to unpack .../06-linux-image-generic_6.10.0-15.15_s390x.deb ... 79s Unpacking linux-image-generic (6.10.0-15.15) over (6.8.0-31.31) ... 79s Preparing to unpack .../07-linux-virtual_6.10.0-15.15_s390x.deb ... 79s Unpacking linux-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 79s Preparing to unpack .../08-linux-image-virtual_6.10.0-15.15_s390x.deb ... 79s Unpacking linux-image-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 79s Preparing to unpack .../09-linux-headers-virtual_6.10.0-15.15_s390x.deb ... 79s Unpacking linux-headers-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 79s Selecting previously unselected package linux-headers-6.10.0-15. 79s Preparing to unpack .../10-linux-headers-6.10.0-15_6.10.0-15.15_all.deb ... 79s Unpacking linux-headers-6.10.0-15 (6.10.0-15.15) ... 81s Selecting previously unselected package linux-headers-6.10.0-15-generic. 81s Preparing to unpack .../11-linux-headers-6.10.0-15-generic_6.10.0-15.15_s390x.deb ... 81s Unpacking linux-headers-6.10.0-15-generic (6.10.0-15.15) ... 82s Preparing to unpack .../12-linux-headers-generic_6.10.0-15.15_s390x.deb ... 82s Unpacking linux-headers-generic (6.10.0-15.15) over (6.8.0-31.31) ... 82s Preparing to unpack .../13-linux-libc-dev_6.10.0-15.15_s390x.deb ... 82s Unpacking linux-libc-dev:s390x (6.10.0-15.15) over (6.8.0-31.31) ... 82s Preparing to unpack .../14-linux-tools-common_6.10.0-15.15_all.deb ... 82s Unpacking linux-tools-common (6.10.0-15.15) over (6.8.0-31.31) ... 82s Selecting previously unselected package linux-tools-6.10.0-15. 82s Preparing to unpack .../15-linux-tools-6.10.0-15_6.10.0-15.15_s390x.deb ... 82s Unpacking linux-tools-6.10.0-15 (6.10.0-15.15) ... 82s Selecting previously unselected package linux-tools-6.10.0-15-generic. 82s Preparing to unpack .../16-linux-tools-6.10.0-15-generic_6.10.0-15.15_s390x.deb ... 82s Unpacking linux-tools-6.10.0-15-generic (6.10.0-15.15) ... 82s Setting up linux-headers-6.10.0-15 (6.10.0-15.15) ... 82s Setting up linux-headers-6.10.0-15-generic (6.10.0-15.15) ... 82s Setting up linux-libc-dev:s390x (6.10.0-15.15) ... 82s Setting up linux-headers-generic (6.10.0-15.15) ... 82s Setting up libpython3.12t64:s390x (3.12.4-1ubuntu1) ... 82s Setting up linux-modules-6.10.0-15-generic (6.10.0-15.15) ... 82s Setting up linux-tools-common (6.10.0-15.15) ... 82s Setting up libxml2:s390x (2.12.7+dfsg-3) ... 82s Setting up linux-modules-extra-6.10.0-15-generic (6.10.0-15.15) ... 83s Setting up linux-image-6.10.0-15-generic (6.10.0-15.15) ... 83s I: /boot/vmlinuz is now a symlink to vmlinuz-6.10.0-15-generic 83s I: /boot/initrd.img is now a symlink to initrd.img-6.10.0-15-generic 83s Setting up linux-headers-virtual (6.10.0-15.15) ... 83s Setting up linux-tools-6.10.0-15 (6.10.0-15.15) ... 83s Setting up linux-image-virtual (6.10.0-15.15) ... 83s Setting up linux-image-generic (6.10.0-15.15) ... 83s Setting up linux-generic (6.10.0-15.15) ... 83s Setting up linux-virtual (6.10.0-15.15) ... 83s Setting up linux-tools-6.10.0-15-generic (6.10.0-15.15) ... 83s Processing triggers for man-db (2.12.1-2) ... 84s Processing triggers for libc-bin (2.39-0ubuntu9) ... 84s Processing triggers for linux-image-6.10.0-15-generic (6.10.0-15.15) ... 84s /etc/kernel/postinst.d/initramfs-tools: 84s update-initramfs: Generating /boot/initrd.img-6.10.0-15-generic 84s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 88s Using config file '/etc/zipl.conf' 88s Building bootmap in '/boot' 88s Adding IPL section 'ubuntu' (default) 88s Preparing boot device for LD-IPL: vda (0000). 88s Done. 88s /etc/kernel/postinst.d/zz-zipl: 88s Using config file '/etc/zipl.conf' 88s Building bootmap in '/boot' 88s Adding IPL section 'ubuntu' (default) 88s Preparing boot device for LD-IPL: vda (0000). 88s Done. 89s Reading package lists... 89s Building dependency tree... 89s Reading state information... 89s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 89s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 89s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 90s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 90s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 91s Reading package lists... 91s Reading package lists... 91s Building dependency tree... 91s Reading state information... 91s Calculating upgrade... 91s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 91s Reading package lists... 91s Building dependency tree... 91s Reading state information... 91s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 92s Reading package lists... 92s Building dependency tree... 92s Reading state information... 92s linux-generic is already the newest version (6.10.0-15.15). 92s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 92s Reading package lists... 92s Building dependency tree... 92s Reading state information... 92s E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 92s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 92s Reading package lists... 93s Building dependency tree... 93s Reading state information... 93s E: Unable to locate package ^linux-modules-extra$ 93s E: Couldn't find any package by regex '^linux-modules-extra$' 93s autopkgtest [18:11:42]: rebooting testbed after setup commands that affected boot 97s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 124s autopkgtest [18:12:13]: testbed running kernel: Linux 6.10.0-15-generic #15-Ubuntu SMP Thu Jul 4 11:09:43 UTC 2024 127s autopkgtest [18:12:16]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 129s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 129s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 129s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 130s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 130s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 130s gpgv: issuer "steve.langasek@ubuntu.com" 130s gpgv: Can't check signature: No public key 130s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 130s autopkgtest [18:12:19]: testing package multipath-tools version 0.9.4-5ubuntu8 130s autopkgtest [18:12:19]: build not needed 131s autopkgtest [18:12:20]: test kpartx-file-loopback: preparing testbed 132s Reading package lists... 133s Building dependency tree... 133s Reading state information... 133s Starting pkgProblemResolver with broken count: 0 133s Starting 2 pkgProblemResolver with broken count: 0 133s Done 133s The following additional packages will be installed: 133s liburing2 qemu-utils 133s Recommended packages: 133s qemu-block-extra 133s The following NEW packages will be installed: 133s autopkgtest-satdep liburing2 qemu-utils 133s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 133s Need to get 2043 kB/2044 kB of archives. 133s After this operation, 11.9 MB of additional disk space will be used. 133s Get:1 /tmp/autopkgtest.Ui3yZk/1-autopkgtest-satdep.deb autopkgtest-satdep s390x 0 [720 B] 133s Get:2 http://ftpmaster.internal/ubuntu oracular/main s390x liburing2 s390x 2.6-1 [24.4 kB] 133s Get:3 http://ftpmaster.internal/ubuntu oracular/main s390x qemu-utils s390x 1:8.2.2+ds-0ubuntu1 [2019 kB] 134s Fetched 2043 kB in 1s (2442 kB/s) 134s Selecting previously unselected package liburing2:s390x. 134s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 79307 files and directories currently installed.) 134s Preparing to unpack .../liburing2_2.6-1_s390x.deb ... 134s Unpacking liburing2:s390x (2.6-1) ... 134s Selecting previously unselected package qemu-utils. 134s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_s390x.deb ... 134s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 134s Selecting previously unselected package autopkgtest-satdep. 134s Preparing to unpack .../1-autopkgtest-satdep.deb ... 134s Unpacking autopkgtest-satdep (0) ... 134s Setting up liburing2:s390x (2.6-1) ... 134s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 134s Setting up autopkgtest-satdep (0) ... 134s Processing triggers for man-db (2.12.1-2) ... 135s Processing triggers for libc-bin (2.39-0ubuntu9) ... 137s (Reading database ... 79327 files and directories currently installed.) 137s Removing autopkgtest-satdep (0) ... 138s autopkgtest [18:12:27]: test kpartx-file-loopback: [----------------------- 138s Formatting 'foo.img', fmt=raw size=20971520 139s Creating new GPT entries in memory. 139s Warning: The kernel is still using the old partition table. 139s The new table will be used at the next reboot or after you 139s run partprobe(8) or kpartx(8) 139s The operation has completed successfully. 139s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 139s standard_filename: OK 139s del devmap : loop0p1 139s No devices found 139s standard_filename_cleanup: OK 139s Formatting 'fou du FaFa.img', fmt=raw size=20971520 140s Creating new GPT entries in memory. 140s Warning: The kernel is still using the old partition table. 140s The new table will be used at the next reboot or after you 140s run partprobe(8) or kpartx(8) 140s The operation has completed successfully. 140s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 140s filename_with_spaces: OK 140s del devmap : loop0p1 140s No devices found 140s filename_with_spaces_cleanup: OK 141s autopkgtest [18:12:30]: test kpartx-file-loopback: -----------------------] 141s autopkgtest [18:12:30]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 141s kpartx-file-loopback PASS 142s autopkgtest [18:12:31]: test tgtbasedmpaths: preparing testbed 244s autopkgtest [18:14:13]: testbed dpkg architecture: s390x 245s autopkgtest [18:14:14]: testbed apt version: 2.9.6 245s autopkgtest [18:14:14]: @@@@@@@@@@@@@@@@@@@@ test bed setup 245s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 246s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.7 kB] 246s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [372 kB] 246s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3232 B] 246s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 246s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x Packages [73.4 kB] 246s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x c-n-f Metadata [2112 B] 246s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted s390x Packages [1368 B] 246s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted s390x c-n-f Metadata [120 B] 246s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe s390x Packages [364 kB] 246s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe s390x c-n-f Metadata [8372 B] 246s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse s390x Packages [1844 B] 246s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse s390x c-n-f Metadata [120 B] 246s Fetched 1014 kB in 1s (1310 kB/s) 246s Reading package lists... 248s Reading package lists... 248s Building dependency tree... 248s Reading state information... 249s Calculating upgrade... 249s The following NEW packages will be installed: 249s libpython3.12t64 linux-headers-6.10.0-15 linux-headers-6.10.0-15-generic 249s linux-image-6.10.0-15-generic linux-modules-6.10.0-15-generic 249s linux-modules-extra-6.10.0-15-generic linux-tools-6.10.0-15 249s linux-tools-6.10.0-15-generic 249s The following packages will be upgraded: 249s libxml2 linux-generic linux-headers-generic linux-headers-virtual 249s linux-image-generic linux-image-virtual linux-libc-dev linux-tools-common 249s linux-virtual 249s 9 upgraded, 8 newly installed, 0 to remove and 0 not upgraded. 249s Need to get 65.7 MB of archives. 249s After this operation, 168 MB of additional disk space will be used. 249s Get:1 http://ftpmaster.internal/ubuntu oracular/main s390x libxml2 s390x 2.12.7+dfsg-3 [663 kB] 249s Get:2 http://ftpmaster.internal/ubuntu oracular/main s390x libpython3.12t64 s390x 3.12.4-1ubuntu1 [2476 kB] 250s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-modules-6.10.0-15-generic s390x 6.10.0-15.15 [20.4 MB] 251s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-image-6.10.0-15-generic s390x 6.10.0-15.15 [9453 kB] 252s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-modules-extra-6.10.0-15-generic s390x 6.10.0-15.15 [11.0 MB] 253s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-generic s390x 6.10.0-15.15 [1728 B] 253s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-image-generic s390x 6.10.0-15.15 [10.4 kB] 253s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-virtual s390x 6.10.0-15.15 [1722 B] 253s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-image-virtual s390x 6.10.0-15.15 [10.4 kB] 253s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-headers-virtual s390x 6.10.0-15.15 [1646 B] 253s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-headers-6.10.0-15 all 6.10.0-15.15 [13.8 MB] 254s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-headers-6.10.0-15-generic s390x 6.10.0-15.15 [2705 kB] 254s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-headers-generic s390x 6.10.0-15.15 [10.3 kB] 254s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-libc-dev s390x 6.10.0-15.15 [1638 kB] 255s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-tools-common all 6.10.0-15.15 [474 kB] 255s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-tools-6.10.0-15 s390x 6.10.0-15.15 [3109 kB] 255s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x linux-tools-6.10.0-15-generic s390x 6.10.0-15.15 [1724 B] 255s Fetched 65.7 MB in 6s (10.7 MB/s) 255s (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 ... 54705 files and directories currently installed.) 255s Preparing to unpack .../00-libxml2_2.12.7+dfsg-3_s390x.deb ... 255s Unpacking libxml2:s390x (2.12.7+dfsg-3) over (2.9.14+dfsg-1.3ubuntu3) ... 255s Selecting previously unselected package libpython3.12t64:s390x. 255s Preparing to unpack .../01-libpython3.12t64_3.12.4-1ubuntu1_s390x.deb ... 255s Unpacking libpython3.12t64:s390x (3.12.4-1ubuntu1) ... 255s Selecting previously unselected package linux-modules-6.10.0-15-generic. 255s Preparing to unpack .../02-linux-modules-6.10.0-15-generic_6.10.0-15.15_s390x.deb ... 255s Unpacking linux-modules-6.10.0-15-generic (6.10.0-15.15) ... 255s Selecting previously unselected package linux-image-6.10.0-15-generic. 255s Preparing to unpack .../03-linux-image-6.10.0-15-generic_6.10.0-15.15_s390x.deb ... 255s Unpacking linux-image-6.10.0-15-generic (6.10.0-15.15) ... 256s Selecting previously unselected package linux-modules-extra-6.10.0-15-generic. 256s Preparing to unpack .../04-linux-modules-extra-6.10.0-15-generic_6.10.0-15.15_s390x.deb ... 256s Unpacking linux-modules-extra-6.10.0-15-generic (6.10.0-15.15) ... 256s Preparing to unpack .../05-linux-generic_6.10.0-15.15_s390x.deb ... 256s Unpacking linux-generic (6.10.0-15.15) over (6.8.0-31.31) ... 256s Preparing to unpack .../06-linux-image-generic_6.10.0-15.15_s390x.deb ... 256s Unpacking linux-image-generic (6.10.0-15.15) over (6.8.0-31.31) ... 256s Preparing to unpack .../07-linux-virtual_6.10.0-15.15_s390x.deb ... 256s Unpacking linux-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 256s Preparing to unpack .../08-linux-image-virtual_6.10.0-15.15_s390x.deb ... 256s Unpacking linux-image-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 256s Preparing to unpack .../09-linux-headers-virtual_6.10.0-15.15_s390x.deb ... 256s Unpacking linux-headers-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 256s Selecting previously unselected package linux-headers-6.10.0-15. 256s Preparing to unpack .../10-linux-headers-6.10.0-15_6.10.0-15.15_all.deb ... 256s Unpacking linux-headers-6.10.0-15 (6.10.0-15.15) ... 265s Selecting previously unselected package linux-headers-6.10.0-15-generic. 265s Preparing to unpack .../11-linux-headers-6.10.0-15-generic_6.10.0-15.15_s390x.deb ... 265s Unpacking linux-headers-6.10.0-15-generic (6.10.0-15.15) ... 266s Preparing to unpack .../12-linux-headers-generic_6.10.0-15.15_s390x.deb ... 266s Unpacking linux-headers-generic (6.10.0-15.15) over (6.8.0-31.31) ... 266s Preparing to unpack .../13-linux-libc-dev_6.10.0-15.15_s390x.deb ... 266s Unpacking linux-libc-dev:s390x (6.10.0-15.15) over (6.8.0-31.31) ... 266s Preparing to unpack .../14-linux-tools-common_6.10.0-15.15_all.deb ... 266s Unpacking linux-tools-common (6.10.0-15.15) over (6.8.0-31.31) ... 266s Selecting previously unselected package linux-tools-6.10.0-15. 266s Preparing to unpack .../15-linux-tools-6.10.0-15_6.10.0-15.15_s390x.deb ... 266s Unpacking linux-tools-6.10.0-15 (6.10.0-15.15) ... 266s Selecting previously unselected package linux-tools-6.10.0-15-generic. 266s Preparing to unpack .../16-linux-tools-6.10.0-15-generic_6.10.0-15.15_s390x.deb ... 266s Unpacking linux-tools-6.10.0-15-generic (6.10.0-15.15) ... 266s Setting up linux-headers-6.10.0-15 (6.10.0-15.15) ... 266s Setting up linux-headers-6.10.0-15-generic (6.10.0-15.15) ... 266s Setting up linux-libc-dev:s390x (6.10.0-15.15) ... 266s Setting up linux-headers-generic (6.10.0-15.15) ... 266s Setting up libpython3.12t64:s390x (3.12.4-1ubuntu1) ... 266s Setting up linux-modules-6.10.0-15-generic (6.10.0-15.15) ... 267s Setting up linux-tools-common (6.10.0-15.15) ... 267s Setting up libxml2:s390x (2.12.7+dfsg-3) ... 267s Setting up linux-modules-extra-6.10.0-15-generic (6.10.0-15.15) ... 267s Setting up linux-image-6.10.0-15-generic (6.10.0-15.15) ... 267s I: /boot/vmlinuz is now a symlink to vmlinuz-6.10.0-15-generic 267s I: /boot/initrd.img is now a symlink to initrd.img-6.10.0-15-generic 267s Setting up linux-headers-virtual (6.10.0-15.15) ... 267s Setting up linux-tools-6.10.0-15 (6.10.0-15.15) ... 267s Setting up linux-image-virtual (6.10.0-15.15) ... 267s Setting up linux-image-generic (6.10.0-15.15) ... 267s Setting up linux-generic (6.10.0-15.15) ... 267s Setting up linux-virtual (6.10.0-15.15) ... 267s Setting up linux-tools-6.10.0-15-generic (6.10.0-15.15) ... 267s Processing triggers for man-db (2.12.1-2) ... 268s Processing triggers for libc-bin (2.39-0ubuntu9) ... 277s Processing triggers for linux-image-6.10.0-15-generic (6.10.0-15.15) ... 277s /etc/kernel/postinst.d/initramfs-tools: 277s update-initramfs: Generating /boot/initrd.img-6.10.0-15-generic 277s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 295s Using config file '/etc/zipl.conf' 295s Building bootmap in '/boot' 295s Adding IPL section 'ubuntu' (default) 295s Preparing boot device for LD-IPL: vda (0000). 295s Done. 296s /etc/kernel/postinst.d/zz-zipl: 296s Using config file '/etc/zipl.conf' 296s Building bootmap in '/boot' 296s Adding IPL section 'ubuntu' (default) 296s Preparing boot device for LD-IPL: vda (0000). 296s Done. 297s Reading package lists... 297s Building dependency tree... 297s Reading state information... 297s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 299s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 299s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 299s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 299s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 300s Reading package lists... 300s Reading package lists... 300s Building dependency tree... 300s Reading state information... 300s Calculating upgrade... 300s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 300s Reading package lists... 300s Building dependency tree... 300s Reading state information... 301s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 301s Reading package lists... 301s Building dependency tree... 301s Reading state information... 301s linux-generic is already the newest version (6.10.0-15.15). 301s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 302s Reading package lists... 302s Building dependency tree... 302s Reading state information... 302s E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 302s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 302s Reading package lists... 302s Building dependency tree... 302s Reading state information... 302s E: Unable to locate package ^linux-modules-extra$ 302s E: Couldn't find any package by regex '^linux-modules-extra$' 302s autopkgtest [18:15:11]: rebooting testbed after setup commands that affected boot 306s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 339s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 349s Reading package lists... 349s Building dependency tree... 349s Reading state information... 350s Starting pkgProblemResolver with broken count: 0 350s Starting 2 pkgProblemResolver with broken count: 0 350s Done 350s The following additional packages will be installed: 350s fio libatomic1 libboost-iostreams1.83.0 libboost-thread1.83.0 350s libconfig-general-perl libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 350s libisns0t64 libnbd0 libopeniscsiusr librados2 librbd1 librdmacm1t64 lsscsi 350s open-iscsi tgt 350s Suggested packages: 350s fio-examples gnuplot tgt-glusterfs tgt-rbd 350s Recommended packages: 350s finalrd 350s The following NEW packages will be installed: 350s autopkgtest-satdep fio libatomic1 libboost-iostreams1.83.0 350s libboost-thread1.83.0 libconfig-general-perl libgfapi0 libgfrpc0 libgfxdr0 350s libglusterfs0 libisns0t64 libnbd0 libopeniscsiusr librados2 librbd1 350s librdmacm1t64 lsscsi open-iscsi tgt 350s 0 upgraded, 19 newly installed, 0 to remove and 0 not upgraded. 350s Need to get 9646 kB/9647 kB of archives. 350s After this operation, 39.0 MB of additional disk space will be used. 350s Get:1 /tmp/autopkgtest.Ui3yZk/2-autopkgtest-satdep.deb autopkgtest-satdep s390x 0 [728 B] 350s Get:2 http://ftpmaster.internal/ubuntu oracular/main s390x libopeniscsiusr s390x 2.1.10-1ubuntu1 [51.3 kB] 350s Get:3 http://ftpmaster.internal/ubuntu oracular/main s390x libisns0t64 s390x 0.101-1 [95.0 kB] 350s Get:4 http://ftpmaster.internal/ubuntu oracular/main s390x open-iscsi s390x 2.1.10-1ubuntu1 [330 kB] 350s Get:5 http://ftpmaster.internal/ubuntu oracular/main s390x librdmacm1t64 s390x 52.0-2 [73.1 kB] 351s Get:6 http://ftpmaster.internal/ubuntu oracular/universe s390x libconfig-general-perl all 2.65-2 [57.1 kB] 351s Get:7 http://ftpmaster.internal/ubuntu oracular/universe s390x tgt s390x 1:1.0.85-1.2ubuntu1 [235 kB] 351s Get:8 http://ftpmaster.internal/ubuntu oracular/universe s390x libgfxdr0 s390x 11.1-4ubuntu1 [20.1 kB] 351s Get:9 http://ftpmaster.internal/ubuntu oracular/universe s390x libglusterfs0 s390x 11.1-4ubuntu1 [280 kB] 351s Get:10 http://ftpmaster.internal/ubuntu oracular/universe s390x libgfrpc0 s390x 11.1-4ubuntu1 [41.1 kB] 351s Get:11 http://ftpmaster.internal/ubuntu oracular/universe s390x libgfapi0 s390x 11.1-4ubuntu1 [81.2 kB] 351s Get:12 http://ftpmaster.internal/ubuntu oracular/universe s390x libnbd0 s390x 1.20.2-1 [91.8 kB] 351s Get:13 http://ftpmaster.internal/ubuntu oracular/main s390x libboost-iostreams1.83.0 s390x 1.83.0-3ubuntu1 [258 kB] 351s Get:14 http://ftpmaster.internal/ubuntu oracular/main s390x libboost-thread1.83.0 s390x 1.83.0-3ubuntu1 [278 kB] 351s Get:15 http://ftpmaster.internal/ubuntu oracular/main s390x librados2 s390x 19.2.0~git20240301.4c76c50-0ubuntu7 [4106 kB] 351s Get:16 http://ftpmaster.internal/ubuntu oracular/main s390x libatomic1 s390x 14.1.0-4ubuntu2 [9428 B] 351s Get:17 http://ftpmaster.internal/ubuntu oracular/main s390x librbd1 s390x 19.2.0~git20240301.4c76c50-0ubuntu7 [2936 kB] 351s Get:18 http://ftpmaster.internal/ubuntu oracular/universe s390x fio s390x 3.37-1 [652 kB] 351s Get:19 http://ftpmaster.internal/ubuntu oracular/main s390x lsscsi s390x 0.32-1build1 [50.4 kB] 352s Preconfiguring packages ... 352s Fetched 9646 kB in 2s (6371 kB/s) 352s Selecting previously unselected package libopeniscsiusr. 352s (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 ... 79307 files and directories currently installed.) 352s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_s390x.deb ... 352s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 352s Selecting previously unselected package libisns0t64:s390x. 352s Preparing to unpack .../01-libisns0t64_0.101-1_s390x.deb ... 352s Unpacking libisns0t64:s390x (0.101-1) ... 352s Selecting previously unselected package open-iscsi. 352s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_s390x.deb ... 352s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 352s Selecting previously unselected package librdmacm1t64:s390x. 352s Preparing to unpack .../03-librdmacm1t64_52.0-2_s390x.deb ... 352s Unpacking librdmacm1t64:s390x (52.0-2) ... 352s Selecting previously unselected package libconfig-general-perl. 352s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 352s Unpacking libconfig-general-perl (2.65-2) ... 352s Selecting previously unselected package tgt. 352s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_s390x.deb ... 352s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 352s Selecting previously unselected package libgfxdr0:s390x. 352s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_s390x.deb ... 352s Unpacking libgfxdr0:s390x (11.1-4ubuntu1) ... 352s Selecting previously unselected package libglusterfs0:s390x. 352s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_s390x.deb ... 352s Unpacking libglusterfs0:s390x (11.1-4ubuntu1) ... 352s Selecting previously unselected package libgfrpc0:s390x. 352s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_s390x.deb ... 352s Unpacking libgfrpc0:s390x (11.1-4ubuntu1) ... 352s Selecting previously unselected package libgfapi0:s390x. 352s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_s390x.deb ... 352s Unpacking libgfapi0:s390x (11.1-4ubuntu1) ... 352s Selecting previously unselected package libnbd0. 352s Preparing to unpack .../10-libnbd0_1.20.2-1_s390x.deb ... 352s Unpacking libnbd0 (1.20.2-1) ... 352s Selecting previously unselected package libboost-iostreams1.83.0:s390x. 352s Preparing to unpack .../11-libboost-iostreams1.83.0_1.83.0-3ubuntu1_s390x.deb ... 352s Unpacking libboost-iostreams1.83.0:s390x (1.83.0-3ubuntu1) ... 352s Selecting previously unselected package libboost-thread1.83.0:s390x. 352s Preparing to unpack .../12-libboost-thread1.83.0_1.83.0-3ubuntu1_s390x.deb ... 352s Unpacking libboost-thread1.83.0:s390x (1.83.0-3ubuntu1) ... 352s Selecting previously unselected package librados2. 352s Preparing to unpack .../13-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_s390x.deb ... 352s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 352s Selecting previously unselected package libatomic1:s390x. 352s Preparing to unpack .../14-libatomic1_14.1.0-4ubuntu2_s390x.deb ... 352s Unpacking libatomic1:s390x (14.1.0-4ubuntu2) ... 353s Selecting previously unselected package librbd1. 353s Preparing to unpack .../15-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_s390x.deb ... 353s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 353s Selecting previously unselected package fio. 353s Preparing to unpack .../16-fio_3.37-1_s390x.deb ... 353s Unpacking fio (3.37-1) ... 353s Selecting previously unselected package lsscsi. 353s Preparing to unpack .../17-lsscsi_0.32-1build1_s390x.deb ... 353s Unpacking lsscsi (0.32-1build1) ... 353s Selecting previously unselected package autopkgtest-satdep. 353s Preparing to unpack .../18-2-autopkgtest-satdep.deb ... 353s Unpacking autopkgtest-satdep (0) ... 353s Setting up libconfig-general-perl (2.65-2) ... 353s Setting up libisns0t64:s390x (0.101-1) ... 353s Setting up libboost-thread1.83.0:s390x (1.83.0-3ubuntu1) ... 353s Setting up libnbd0 (1.20.2-1) ... 353s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 353s Setting up libglusterfs0:s390x (11.1-4ubuntu1) ... 353s Setting up libboost-iostreams1.83.0:s390x (1.83.0-3ubuntu1) ... 353s Setting up libatomic1:s390x (14.1.0-4ubuntu2) ... 353s Setting up lsscsi (0.32-1build1) ... 353s Setting up librdmacm1t64:s390x (52.0-2) ... 353s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 353s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 353s Setting up libgfxdr0:s390x (11.1-4ubuntu1) ... 353s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 353s Setting up open-iscsi (2.1.10-1ubuntu1) ... 354s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 354s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 354s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 355s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 355s Setting up libgfrpc0:s390x (11.1-4ubuntu1) ... 355s Setting up libgfapi0:s390x (11.1-4ubuntu1) ... 355s Setting up fio (3.37-1) ... 355s Setting up autopkgtest-satdep (0) ... 355s Processing triggers for man-db (2.12.1-2) ... 356s Processing triggers for initramfs-tools (0.142ubuntu30) ... 356s update-initramfs: Generating /boot/initrd.img-6.10.0-15-generic 356s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 360s Using config file '/etc/zipl.conf' 360s Building bootmap in '/boot' 360s Adding IPL section 'ubuntu' (default) 360s Preparing boot device for LD-IPL: vda (0000). 360s Done. 360s Processing triggers for libc-bin (2.39-0ubuntu9) ... 363s (Reading database ... 79525 files and directories currently installed.) 363s Removing autopkgtest-satdep (0) ... 364s autopkgtest [18:16:13]: test tgtbasedmpaths: [----------------------- 365s + targetname=iqn.2016-11.foo.com:target.iscsi 365s + pwd 365s + cwd=/tmp/autopkgtest.Ui3yZk/build.fz8/src 365s + testdir=/mnt/tgtmpathtest 365s + localhost=127.0.0.1 365s + portal=127.0.0.1:3260 365s + maxpaths=4 365s + backfn=backingfile 365s + expectwwid=60000000000000000e00000000010001 365s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 365s + bglog=/tmp/autopkgtest.Ui3yZk/tgtbasedmpaths-artifacts/test-background.log 365s + fioprep=/tmp/autopkgtest.Ui3yZk/tgtbasedmpaths-artifacts/path-change-prep.fio 365s + fiovrfy=/tmp/autopkgtest.Ui3yZk/tgtbasedmpaths-artifacts/path-change-check.fio 365s + service tgt restart 365s + truncate --size 100M backingfile 365s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 365s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 365s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.Ui3yZk/build.fz8/src/backingfile 365s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 365s + echo login #1 365s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 365s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 365s login #1 365s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 365s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 365s + extra login #2 365s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 365s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 365s extra login #3 365s seq 2 4 365s + echo extra login #2 365s + iscsiadm --mode session -r 1 --op new 365s + echo extra login #3 365s + iscsiadm --mode session -r 1 --op new 365s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 365s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 365s extra login #4 365s + echo extra login #4 365s + iscsiadm --mode session -r 1 --op new 365s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 365s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 365s + udevadm settle 365s + sleep 5 370s Status after initial setup 370s Target 1: iqn.2016-11.foo.com:target.iscsi 370s System information: 370s Driver: iscsi 370s State: ready 370s I_T nexus information: 370s I_T nexus: 1 370s Initiator: iqn.2004-10.com.ubuntu:01:4b64427c9e98 alias: autopkgtest 370s Connection: 0 370s IP Address: 127.0.0.1 370s I_T nexus: 2 370s Initiator: iqn.2004-10.com.ubuntu:01:4b64427c9e98 alias: autopkgtest 370s Connection: 0 370s IP Address: 127.0.0.1 370s I_T nexus: 3 370s Initiator: iqn.2004-10.com.ubuntu:01:4b64427c9e98 alias: autopkgtest 370s Connection: 0 370s IP Address: 127.0.0.1 370s I_T nexus: 4 370s Initiator: iqn.2004-10.com.ubuntu:01:4b64427c9e98 alias: autopkgtest 370s Connection: 0 370s IP Address: 127.0.0.1 370s LUN information: 370s LUN: 0 370s Type: controller 370s SCSI ID: IET 00010000 370s SCSI SN: beaf10 370s Size: 0 MB, Block size: 1 370s Online: Yes 370s Removable media: No 370s Prevent removal: No 370s Readonly: No 370s SWP: No 370s Thin-provisioning: No 370s Backing store type: null 370s Backing store path: None 370s Backing store flags: 370s LUN: 1 370s Type: disk 370s SCSI ID: IET 00010001 370s SCSI SN: beaf11 370s Size: 105 MB, Block size: 512 370s Online: Yes 370s Removable media: No 370s Prevent removal: No 370s Readonly: No 370s SWP: No 370s Thin-provisioning: No 370s Backing store type: rdwr 370s Backing store path: /tmp/autopkgtest.Ui3yZk/build.fz8/src/backingfile 370s Backing store flags: 370s Account information: 370s ACL information: 370s ALL 370s Session: 4 370s Connection: 0 370s Initiator: iqn.2004-10.com.ubuntu:01:4b64427c9e98 370s IP Address: 127.0.0.1 370s Session: 3 370s Connection: 0 370s Initiator: iqn.2004-10.com.ubuntu:01:4b64427c9e98 370s IP Address: 127.0.0.1 370s Session: 2 370s Connection: 0 370s Initiator: iqn.2004-10.com.ubuntu:01:4b64427c9e98 370s IP Address: 127.0.0.1 370s Session: 1 370s Connection: 0 370s Initiator: iqn.2004-10.com.ubuntu:01:4b64427c9e98 370s IP Address: 127.0.0.1 370s + echo Status after initial setup 370s + tgtadm --lld iscsi --mode target --op show 370s + tgtadm --lld iscsi --op show --mode conn --tid 1 370s + iscsiadm --mode session -P 1 370s + lsscsi -liv 370s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 370s Current Portal: 127.0.0.1:3260,1 370s Persistent Portal: 127.0.0.1:3260,1 370s ********** 370s Interface: 370s ********** 370s Iface Name: default 370s Iface Transport: tcp 370s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:4b64427c9e98 370s Iface IPaddress: 127.0.0.1 370s Iface HWaddress: default 370s Iface Netdev: default 370s SID: 1 370s iSCSI Connection State: LOGGED IN 370s iSCSI Session State: LOGGED_IN 370s Internal iscsid Session State: NO CHANGE 370s 370s ********** 370s Interface: 370s ********** 370s Iface Name: default 370s Iface Transport: tcp 370s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:4b64427c9e98 370s Iface IPaddress: 127.0.0.1 370s Iface HWaddress: default 370s Iface Netdev: default 370s SID: 2 370s iSCSI Connection State: LOGGED IN 370s iSCSI Session State: LOGGED_IN 370s Internal iscsid Session State: NO CHANGE 370s 370s ********** 370s Interface: 370s ********** 370s Iface Name: default 370s Iface Transport: tcp 370s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:4b64427c9e98 370s Iface IPaddress: 127.0.0.1 370s Iface HWaddress: default 370s Iface Netdev: default 370s SID: 3 370s iSCSI Connection State: LOGGED IN 370s iSCSI Session State: LOGGED_IN 370s Internal iscsid Session State: NO CHANGE 370s 370s ********** 370s Interface: 370s ********** 370s Iface Name: default 370s Iface Transport: tcp 370s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:4b64427c9e98 370s Iface IPaddress: 127.0.0.1 370s Iface HWaddress: default 370s Iface Netdev: default 370s SID: 4 370s iSCSI Connection State: LOGGED IN 370s iSCSI Session State: LOGGED_IN 370s Internal iscsid Session State: NO CHANGE 370s [0:0:0:0] storage IET Controller 0001 - - 370s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 370s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 370s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 370s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 370s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 370s [1:0:0:0] storage IET Controller 0001 - - 370s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 370s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 370s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 370s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 370s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 370s [2:0:0:0] storage IET Controller 0001 - - 370s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 370s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 370s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 33000000100000001 370s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 370s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 370s [3:0:0:0] storage IET Controller 0001 - - 370s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 370s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 370s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 370s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 370s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 370s NVMe module may not be loaded 370s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 370s + multipath -v3 -ll 370s 63.242824 | set open fds limit to 1073741816/1073741816 370s 63.242899 | loading /lib/multipath/libchecktur.so checker 370s 63.242999 | checker tur: message table size = 3 370s 63.243010 | loading /lib/multipath/libprioconst.so prioritizer 370s 63.243109 | _init_foreign: foreign library "nvme" is not enabled 370s 63.248970 | vda: device node name blacklisted 370s 63.249174 | sda: size = 204800 370s 63.249292 | sda: vendor = IET 370s 63.249305 | sda: product = VIRTUAL-DISK 370s 63.249318 | sda: rev = 0001 370s 63.249987 | sda: h:b:t:l = 0:0:0:1 370s 63.250354 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 370s 63.250417 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 370s 63.250470 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 370s 63.250701 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 370s 63.250748 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 370s 63.250826 | sda: serial = beaf11 370s 63.250882 | sda: detect_checker = yes (setting: multipath internal) 370s 63.251113 | sda: path_checker = tur (setting: multipath internal) 370s 63.251160 | sda: checker timeout = 30 s (setting: kernel sysfs) 370s 63.251265 | sda: tur state = up 370s 63.251489 | sdb: size = 204800 370s 63.251744 | sdb: vendor = IET 370s 63.251856 | sdb: product = VIRTUAL-DISK 370s 63.251964 | sdb: rev = 0001 370s 63.252761 | sdb: h:b:t:l = 1:0:0:1 370s 63.253052 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 370s 63.253093 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 370s 63.253132 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 370s 63.253303 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 370s 63.253344 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 370s 63.253390 | sdb: serial = beaf11 370s 63.253428 | sdb: detect_checker = yes (setting: multipath internal) 370s 63.253550 | sdb: path_checker = tur (setting: multipath internal) 370s 63.253606 | sdb: checker timeout = 30 s (setting: kernel sysfs) 370s 63.253742 | sdb: tur state = up 370s 63.253949 | sdc: size = 204800 370s 63.254152 | sdc: vendor = IET 370s 63.254224 | sdc: product = VIRTUAL-DISK 370s 63.254274 | sdc: rev = 0001 370s 63.255310 | sdc: h:b:t:l = 2:0:0:1 370s 63.255599 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 370s 63.255642 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 370s 63.255680 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 370s 63.255967 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 370s 63.256008 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 370s 63.256057 | sdc: serial = beaf11 370s 63.256096 | sdc: detect_checker = yes (setting: multipath internal) 370s 63.256200 | sdc: path_checker = tur (setting: multipath internal) 370s 63.256252 | sdc: checker timeout = 30 s (setting: kernel sysfs) 370s 63.256317 | sdc: tur state = up 370s 63.256443 | sdd: size = 204800 370s 63.256573 | sdd: vendor = IET 370s 63.256624 | sdd: product = VIRTUAL-DISK 370s 63.256675 | sdd: rev = 0001 370s 63.257371 | sdd: h:b:t:l = 3:0:0:1 370s 63.257643 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 370s 63.257683 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 370s 63.257721 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 370s 63.258101 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 370s 63.258181 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 370s 63.258257 | sdd: serial = beaf11 370s 63.258296 | sdd: detect_checker = yes (setting: multipath internal) 370s 63.258448 | sdd: path_checker = tur (setting: multipath internal) 370s 63.258507 | sdd: checker timeout = 30 s (setting: kernel sysfs) 370s 63.258588 | sdd: tur state = up 370s 63.258696 | loop0: device node name blacklisted 370s 63.258796 | loop1: device node name blacklisted 370s 63.258889 | loop2: device node name blacklisted 370s 63.258982 | loop3: device node name blacklisted 370s 63.259142 | loop4: device node name blacklisted 370s 63.259351 | loop5: device node name blacklisted 370s 63.259449 | loop6: device node name blacklisted 370s 63.259547 | loop7: device node name blacklisted 370s 63.259655 | dm-0: device node name blacklisted 370s 63.260415 | multipath-tools v0.9.4 (12/19, 2022) 370s 63.260485 | libdevmapper version 1.02.185 370s 63.260688 | kernel device mapper v4.48.0 370s 63.260740 | DM multipath kernel driver v1.14.0 370s 63.260898 | sda: size = 204800 370s 63.260940 | sda: vendor = IET 370s 63.260979 | sda: product = VIRTUAL-DISK 370s 63.261017 | sda: rev = 0001 370s 63.261724 | sda: h:b:t:l = 0:0:0:1 370s 63.261850 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 370s 63.261905 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 370s 63.261945 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 370s 63.261994 | sda: serial = beaf11 370s 63.262134 | sda: tur state = up 370s 63.262175 | sda: uid = 360000000000000000e00000000010001 (udev) 370s 63.262213 | sda: detect_prio = yes (setting: multipath internal) 370s 63.262252 | sda: prio = const (setting: multipath internal) 370s 63.262290 | sda: prio args = "" (setting: multipath internal) 370s 63.262328 | sda: const prio = 1 370s 63.262379 | sdb: size = 204800 370s 63.262419 | sdb: vendor = IET 370s 63.262457 | sdb: product = VIRTUAL-DISK 370s 63.262494 | sdb: rev = 0001 370s 63.263129 | sdb: h:b:t:l = 1:0:0:1 370s 63.263249 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 370s 63.263300 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 370s 63.263339 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 370s 63.263386 | sdb: serial = beaf11 370s 63.263464 | sdb: tur state = up 370s 63.263509 | sdb: uid = 360000000000000000e00000000010001 (udev) 370s 63.263548 | sdb: detect_prio = yes (setting: multipath internal) 370s 63.263586 | sdb: prio = const (setting: multipath internal) 370s 63.263624 | sdb: prio args = "" (setting: multipath internal) 370s 63.263661 | sdb: const prio = 1 370s 63.263714 | sdc: size = 204800 370s 63.263754 | sdc: vendor = IET 370s 63.263792 | sdc: product = VIRTUAL-DISK 370s 63.263829 | sdc: rev = 0001 370s 63.264462 | sdc: h:b:t:l = 2:0:0:1 370s 63.264576 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 370s 63.264625 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 370s 63.264664 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 370s 63.264709 | sdc: serial = beaf11 370s 63.264802 | sdc: tur state = up 370s 63.264843 | sdc: uid = 360000000000000000e00000000010001 (udev) 370s 63.264881 | sdc: detect_prio = yes (setting: multipath internal) 370s 63.264919 | sdc: prio = const (setting: multipath internal) 370s 63.264957 | sdc: prio args = "" (setting: multipath internal) 370s 63.264994 | sdc: const prio = 1 370s 63.265047 | sdd: size = 204800 370s 63.265087 | sdd: vendor = IET 370s 63.265125 | sdd: product = VIRTUAL-DISK 370s 63.265162 | sdd: rev = 0001 370s 63.265797 | sdd: h:b:t:l = 3:0:0:1 370s 63.265913 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 370s 63.265965 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 370s 63.266005 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 370s 63.266051 | sdd: serial = beaf11 370s 63.266138 | sdd: tur state = up 370s 63.266182 | sdd: uid = 360000000000000000e00000000010001 (udev) 370s 63.266220 | sdd: detect_prio = yes (setting: multipath internal) 370s 63.266257 | sdd: prio = const (setting: multipath internal) 370s 63.266295 | sdd: prio args = "" (setting: multipath internal) 370s 63.266332 | sdd: const prio = 1 370s 63.267083 | unloading tur checker 370s 63.267192 | unloading const prioritizer 370s + dmsetup table 370s + echo Test WWN should now point to DM 370s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 370s + grep dm 370s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 370s mke2fs 1.47.1 (20-May-2024) 370s ===== paths list ===== 370s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 370s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK unknown 370s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 370s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 370s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 370s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 370s size=100M features='0' hwhandler='0' wp=rw 370s |-+- policy='service-time 0' prio=1 status=active 370s | `- 0:0:0:1 sda 8:0 active ready running 370s |-+- policy='service-time 0' prio=1 status=enabled 370s | `- 1:0:0:1 sdb 8:16 active ready running 370s |-+- policy='service-time 0' prio=1 status=enabled 370s | `- 2:0:0:1 sdc 8:32 active ready running 370s `-+- policy='service-time 0' prio=1 status=enabled 370s `- 3:0:0:1 sdd 8:48 active ready running 370s 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 370s Test WWN should now point to DM 370s ../../dm-0 370s Creating filesystem with 25600 4k blocks and 25600 inodes 370s 370s Allocating group tables: 0/1 done 370s Writing inode tables: 0/1 done 370s Creating journal (1024 blocks): done 370s Writing superblocks and filesystem accounting information: 0/1 done 370s 370s + udevadm settle 370s + sleep 3s 373s + mkdir -p /mnt/tgtmpathtest 373s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 373s + cat 373s + cat 373s + fio --max-jobs=4 /tmp/autopkgtest.Ui3yZk/tgtbasedmpaths-artifacts/path-change-prep.fio 373s 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 373s fio-3.37 373s Starting 1 thread 373s write-phase: Laying out IO file (1 file / 17592186044415MiB) 374s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91750400, buflen=65536 374s 374s write-phase: (groupid=0, jobs=1): err= 0: pid=4951: Fri Jul 19 18:16:23 2024 374s write: IOPS=2859, BW=179MiB/s (187MB/s)(87.5MiB/490msec); 0 zone resets 374s clat (usec): min=221, max=5276, avg=335.13, stdev=147.87 374s lat (usec): min=232, max=5289, avg=348.19, stdev=148.52 374s clat percentiles (usec): 374s | 1.00th=[ 231], 5.00th=[ 245], 10.00th=[ 255], 20.00th=[ 273], 374s | 30.00th=[ 289], 40.00th=[ 306], 50.00th=[ 326], 60.00th=[ 343], 374s | 70.00th=[ 363], 80.00th=[ 383], 90.00th=[ 420], 95.00th=[ 453], 374s | 99.00th=[ 506], 99.50th=[ 529], 99.90th=[ 979], 99.95th=[ 5276], 374s | 99.99th=[ 5276] 374s lat (usec) : 250=7.49%, 500=91.29%, 750=1.00%, 1000=0.07% 374s lat (msec) : 10=0.07% 374s cpu : usr=4.29%, sys=7.57%, ctx=1402, majf=0, minf=0 374s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 374s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 374s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 374s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 374s latency : target=0, window=0, percentile=100.00%, depth=1 374s 374s Run status group 0 (all jobs): 374s WRITE: bw=179MiB/s (187MB/s), 179MiB/s-179MiB/s (187MB/s-187MB/s), io=87.5MiB (91.8MB), run=490-490msec 374s 374s Disk stats (read/write): 374s dm-0: ios=1/1121, sectors=8/143488, merge=0/0, ticks=1/364, in_queue=364, util=73.02%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/109, aggrin_queue=109, aggrutil=72.85% 374s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 374s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 374s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 374s sda: ios=1/1402, sectors=8/179280, merge=0/0, ticks=0/436, in_queue=436, util=72.85% 374s Starting the path changes in background 374s + echo Starting the path changes in background 374s + date +Pre FIO %H:%M:%S.%N 374s Pre FIO 18:16:23.517692134 374s + fio --max-jobs=4 /tmp/autopkgtest.Ui3yZk/tgtbasedmpaths-artifacts/path-change-check.fio 374s 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 374s fio-3.37 374s Starting 1 thread 554s 554s verify-phase: (groupid=0, jobs=1): err= 0: pid=4962: Fri Jul 19 18:19:23 2024 554s read: IOPS=5733, BW=358MiB/s (376MB/s)(63.0GiB/180001msec) 554s clat (usec): min=68, max=146318, avg=154.34, stdev=348.69 554s lat (usec): min=68, max=146318, avg=154.41, stdev=348.69 554s clat percentiles (usec): 554s | 1.00th=[ 82], 5.00th=[ 92], 10.00th=[ 100], 20.00th=[ 114], 554s | 30.00th=[ 125], 40.00th=[ 135], 50.00th=[ 147], 60.00th=[ 159], 554s | 70.00th=[ 174], 80.00th=[ 190], 90.00th=[ 215], 95.00th=[ 237], 554s | 99.00th=[ 281], 99.50th=[ 302], 99.90th=[ 371], 99.95th=[ 424], 554s | 99.99th=[ 1221] 554s bw ( KiB/s): min=165632, max=579072, per=100.00%, avg=367398.54, stdev=55219.23, samples=359 554s iops : min= 2588, max= 9048, avg=5740.58, stdev=862.81, samples=359 554s lat (usec) : 100=9.45%, 250=87.38%, 500=3.14%, 750=0.01%, 1000=0.01% 554s lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 100=0.01% 554s lat (msec) : 250=0.01% 554s cpu : usr=11.87%, sys=8.46%, ctx=1032118, majf=0, minf=16 554s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 554s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 554s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 554s issued rwts: total=1032070,0,0,0 short=0,0,0,0 dropped=0,0,0,0 554s latency : target=0, window=0, percentile=100.00%, depth=1 554s 554s Run status group 0 (all jobs): 554s READ: bw=358MiB/s (376MB/s), 358MiB/s-358MiB/s (376MB/s-376MB/s), io=63.0GiB (67.6GB), run=180001-180001msec 554s 554s Disk stats (read/write): 554s dm-0: ios=1032397/10, sectors=132048480/12928, merge=0/9, ticks=155739/85, in_queue=155892, util=92.50%, aggrios=75614/2, aggsectors=9670584/3232, aggrmerge=0/0, aggrticks=10039/4, aggrin_queue=10043, aggrutil=86.95% 554s sdd: ios=129466/0, sectors=16559744/0, merge=0/0, ticks=15775/0, in_queue=15776, util=33.50% 554s sdb: ios=57014/5, sectors=7288544/56, merge=0/0, ticks=8235/1, in_queue=8236, util=44.16% 554s sdc: ios=60942/0, sectors=7794944/0, merge=0/0, ticks=8018/0, in_queue=8017, util=29.61% 554s sda: ios=55034/4, sectors=7039104/12872, merge=0/0, ticks=8130/16, in_queue=8146, util=86.95% 554s + date +Post FIO %H:%M:%S.%N 554s + echo FIO verify test with changing paths - OK 554s + echo Report log of background activity 554s + cat /tmp/autopkgtest.Ui3yZk/tgtbasedmpaths-artifacts/test-background.log 554s Post FIO 18:19:23.796909817 554s FIO verify test with changing paths - OK 554s Report log of background activity 554s + iscsiadm --mode session 554s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s + sleep 10s 554s + date +MP report (expect 4) %H:%M:%S.%N 554s MP report (expect 4) 18:16:33.524332221 554s + multipath -ll 554s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 554s size=100M features='0' hwhandler='0' wp=rw 554s |-+- policy='service-time 0' prio=1 status=active 554s | `- 0:0:0:1 sda 8:0 active ready running 554s |-+- policy='service-time 0' prio=1 status=enabled 554s | `- 1:0:0:1 sdb 8:16 active ready running 554s |-+- policy='service-time 0' prio=1 status=enabled 554s | `- 2:0:0:1 sdc 8:32 active ready running 554s `-+- policy='service-time 0' prio=1 status=enabled 554s `- 3:0:0:1 sdd 8:48 active ready running 554s + date +UN-plug path 1 %H:%M:%S.%N 554s UN-plug path 1 18:16:33.545581860 554s + iscsiadm --mode session -r 1 -u 554s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 554s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 554s + iscsiadm --mode session 554s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s + sleep 10s 554s + date +MP report (expect 3) %H:%M:%S.%N 554s MP report (expect 3) 18:16:43.928860912 554s + multipath -ll 554s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 554s size=100M features='0' hwhandler='0' wp=rw 554s |-+- policy='service-time 0' prio=1 status=active 554s | `- 1:0:0:1 sdb 8:16 active ready running 554s |-+- policy='service-time 0' prio=1 status=enabled 554s | `- 2:0:0:1 sdc 8:32 active ready running 554s `-+- policy='service-time 0' prio=1 status=enabled 554s `- 3:0:0:1 sdd 8:48 active ready running 554s + date +UN-plug path 2 %H:%M:%S.%N 554s UN-plug path 2 18:16:43.951339294 554s + iscsiadm --mode session -r 2 -u 554s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 554s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 554s + iscsiadm --mode session 554s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s + sleep 10s 554s + date +MP report (expect 2) %H:%M:%S.%N 554s MP report (expect 2) 18:16:54.147057084 554s + multipath -ll 554s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 554s size=100M features='0' hwhandler='0' wp=rw 554s |-+- policy='service-time 0' prio=1 status=active 554s | `- 2:0:0:1 sdc 8:32 active ready running 554s `-+- policy='service-time 0' prio=1 status=enabled 554s `- 3:0:0:1 sdd 8:48 active ready running 554s + date +UN-plug path 3 %H:%M:%S.%N 554s UN-plug path 3 18:16:54.159980776 554s + iscsiadm --mode session -r 3 -u 554s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 554s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 554s + iscsiadm --mode session 554s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s + sleep 10s 554s + date +MP report (expect 1) %H:%M:%S.%N 554s MP report (expect 1) 18:17:04.346006778 554s + multipath -ll 554s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 554s size=100M features='0' hwhandler='0' wp=rw 554s `-+- policy='service-time 0' prio=1 status=active 554s `- 3:0:0:1 sdd 8:48 active ready running 554s + date +Add paths 5/6/7/8 %H:%M:%S.%N 554s Add paths 5/6/7/8 18:17:04.355772393 554s + iscsiadm --mode session -r 4 --op new 554s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 554s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 554s + iscsiadm --mode session -r 4 --op new 554s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 554s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 554s + iscsiadm --mode session -r 4 --op new 554s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 554s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 554s + iscsiadm --mode session -r 4 --op new 554s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 554s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 554s + iscsiadm --mode session 554s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s + sleep 10s 554s + date +MP report (expect 5) %H:%M:%S.%N 554s MP report (expect 5) 18:17:14.413886440 554s + multipath -ll 554s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 554s size=100M features='0' hwhandler='0' wp=rw 554s |-+- policy='service-time 0' prio=1 status=active 554s | `- 3:0:0:1 sdd 8:48 active ready running 554s |-+- policy='service-time 0' prio=1 status=enabled 554s | `- 0:0:0:1 sda 8:0 active ready running 554s |-+- policy='service-time 0' prio=1 status=enabled 554s | `- 1:0:0:1 sdb 8:16 active ready running 554s |-+- policy='service-time 0' prio=1 status=enabled 554s | `- 2:0:0:1 sdc 8:32 active ready running 554s `-+- policy='service-time 0' prio=1 status=enabled 554s `- 4:0:0:1 sde 8:64 active ready running 554s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 554s UN-plug multiple paths 4/7/8 18:17:14.450046011 554s + iscsiadm --mode session -r 4 -u 554s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 554s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 554s + iscsiadm --mode session -r 7 -u 554s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 554s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 554s + iscsiadm --mode session -r 8 -u 554s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 554s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 554s + iscsiadm --mode session 554s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 554s + sleep 10s 554s + date +Restart multipath daemon %H:%M:%S.%N 554s Restart multipath daemon 18:17:24.868155826 554s + systemctl restart multipathd 554s + sleep 10s 554s + date +Final background report (expect 2) %H:%M:%S.%N 554s Final background report (expect 2) 18:17:34.972187815 554s + multipath -ll 554s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 554s size=100M features='0' hwhandler='0' wp=rw 554s |-+- policy='service-time 0' prio=1 status=active 554s | `- 0:0:0:1 sda 8:0 active ready running 554s `-+- policy='service-time 0' prio=1 status=enabled 554s `- 1:0:0:1 sdb 8:16 active ready running 554s Final stats 554s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 554s iSCSI SNMP: 554s txdata_octets: 34953576 554s rxdata_octets: 47695908420 554s noptx_pdus: 0 554s scsicmd_pdus: 727932 554s tmfcmd_pdus: 0 554s login_pdus: 0 554s text_pdus: 0 554s dataout_pdus: 0 554s logout_pdus: 0 554s snack_pdus: 0 554s noprx_pdus: 0 554s scsirsp_pdus: 727932 554s tmfrsp_pdus: 0 554s textrsp_pdus: 0 554s datain_pdus: 727897 554s logoutrsp_pdus: 0 554s r2t_pdus: 0 554s async_pdus: 0 554s rjt_pdus: 0 554s digest_err: 0 554s timeout_err: 0 554s iSCSI Extended: 554s tx_sendpage_failures: 0 554s rx_discontiguous_hdr: 0 554s eh_abort_cnt: 0 554s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 554s iSCSI SNMP: 554s txdata_octets: 10440 554s rxdata_octets: 2157988 554s noptx_pdus: 0 554s scsicmd_pdus: 187 554s tmfcmd_pdus: 0 554s login_pdus: 0 554s text_pdus: 0 554s dataout_pdus: 0 554s logout_pdus: 0 554s snack_pdus: 0 554s noprx_pdus: 0 554s scsirsp_pdus: 187 554s tmfrsp_pdus: 0 554s textrsp_pdus: 0 554s datain_pdus: 163 554s logoutrsp_pdus: 0 554s r2t_pdus: 0 554s async_pdus: 0 554s rjt_pdus: 0 554s digest_err: 0 554s timeout_err: 0 554s iSCSI Extended: 554s tx_sendpage_failures: 0 554s rx_discontiguous_hdr: 0 554s eh_abort_cnt: 0 554s Jul 19 11:31:51 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 554s Jul 19 11:31:52 ubuntu multipathd[357]: multipathd v0.9.4: start up 554s Jul 19 11:31:52 ubuntu multipathd[357]: reconfigure: setting up paths and maps 554s Jul 19 11:31:52 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 554s Jul 19 11:34:55 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 multipathd[357]: multipathd: shut down 554s Jul 19 11:34:55 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 554s Jul 19 11:34:55 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 systemd[1]: multipathd.service: Deactivated successfully. 554s Jul 19 11:34:55 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 554s -- Boot 14acebd2e0d94420911840c48453bbd8 -- 554s Jul 19 11:34:59 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 554s Jul 19 11:34:59 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 multipathd[312]: multipathd v0.9.4: start up 554s Jul 19 11:34:59 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 multipathd[312]: reconfigure: setting up paths and maps 554s Jul 19 11:34:59 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 554s Jul 19 11:35:24 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 multipathd[312]: multipathd: shut down 554s Jul 19 11:35:24 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 554s Jul 19 11:35:24 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 systemd[1]: multipathd.service: Deactivated successfully. 554s Jul 19 11:35:24 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 554s -- Boot 8ab2a8783bae426197ad292a01fa24b1 -- 554s Jul 19 18:13:32 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 554s Jul 19 18:13:32 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 multipathd[368]: multipathd v0.9.4: start up 554s Jul 19 18:13:32 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 multipathd[368]: reconfigure: setting up paths and maps 554s Jul 19 18:13:32 ubuntuubuntu-oracular-daily-s390x-server-20240627-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 554s Jul 19 18:15:15 autopkgtest multipathd[368]: multipathd: shut down 554s Jul 19 18:15:15 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 554s Jul 19 18:15:15 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 554s Jul 19 18:15:15 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 554s -- Boot 21865b1256e347f3bd4cd6371482aafb -- 554s Jul 19 18:15:17 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 554s Jul 19 18:15:18 autopkgtest multipathd[370]: multipathd v0.9.4: start up 554s Jul 19 18:15:18 autopkgtest multipathd[370]: reconfigure: setting up paths and maps 554s Jul 19 18:15:18 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 554s Jul 19 18:16:14 autopkgtest multipathd[370]: 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] 554s Jul 19 18:16:14 autopkgtest multipathd[370]: sdb [8:16]: path added to devmap mpatha 554s Jul 19 18:16:14 autopkgtest multipathd[370]: mpatha: performing delayed actions 554s Jul 19 18:16:14 autopkgtest multipathd[370]: 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] 554s Jul 19 18:16:33 autopkgtest multipathd[370]: 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] 554s Jul 19 18:16:33 autopkgtest multipathd[370]: check_removed_paths: sda: freeing path in removed state 554s Jul 19 18:16:33 autopkgtest multipathd[370]: 8:0: path removed from map mpatha 554s Jul 19 18:16:44 autopkgtest multipathd[370]: 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] 554s Jul 19 18:16:44 autopkgtest multipathd[370]: check_removed_paths: sdb: freeing path in removed state 554s Jul 19 18:16:44 autopkgtest multipathd[370]: 8:16: path removed from map mpatha 554s Jul 19 18:16:54 autopkgtest multipathd[370]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 554s Jul 19 18:16:54 autopkgtest multipathd[370]: check_removed_paths: sdc: freeing path in removed state 554s Jul 19 18:16:54 autopkgtest multipathd[370]: 8:32: path removed from map mpatha 554s Jul 19 18:17:04 autopkgtest multipathd[370]: 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] 554s Jul 19 18:17:04 autopkgtest multipathd[370]: sda [8:0]: path added to devmap mpatha 554s Jul 19 18:17:04 autopkgtest multipathd[370]: 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] 554s Jul 19 18:17:04 autopkgtest multipathd[370]: sdb [8:16]: path added to devmap mpatha 554s Jul 19 18:17:04 autopkgtest multipathd[370]: 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] 554s Jul 19 18:17:04 autopkgtest multipathd[370]: sdc [8:32]: path added to devmap mpatha 554s Jul 19 18:17:04 autopkgtest multipathd[370]: 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] 554s Jul 19 18:17:04 autopkgtest multipathd[370]: sde [8:64]: path added to devmap mpatha 554s Jul 19 18:17:14 autopkgtest multipathd[370]: 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] 554s Jul 19 18:17:14 autopkgtest multipathd[370]: check_removed_paths: sdd: freeing path in removed state 554s Jul 19 18:17:14 autopkgtest multipathd[370]: 8:48: path removed from map mpatha 554s Jul 19 18:17:14 autopkgtest multipathd[370]: 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] 554s Jul 19 18:17:14 autopkgtest multipathd[370]: check_removed_paths: sdc: freeing path in removed state 554s Jul 19 18:17:14 autopkgtest multipathd[370]: 8:32: path removed from map mpatha 554s Jul 19 18:17:14 autopkgtest multipathd[370]: checker failed path 8:64 in map mpatha 554s Jul 19 18:17:14 autopkgtest multipathd[370]: mpatha: remaining active paths: 2 554s Jul 19 18:17:14 autopkgtest multipathd[370]: 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] 554s Jul 19 18:17:14 autopkgtest multipathd[370]: check_removed_paths: sde: freeing path in removed state 554s Jul 19 18:17:14 autopkgtest multipathd[370]: 8:64: path removed from map mpatha 554s Jul 19 18:17:24 autopkgtest multipathd[370]: multipathd: shut down 554s Jul 19 18:17:24 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 554s Jul 19 18:17:24 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 554s Jul 19 18:17:24 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 554s Jul 19 18:17:24 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 554s Jul 19 18:17:24 autopkgtest multipathd[5319]: multipathd v0.9.4: start up 554s Jul 19 18:17:24 autopkgtest multipathd[5319]: reconfigure: setting up paths and maps 554s Jul 19 18:17:24 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 554s Check final path status 554s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 554s size=100M features='0' hwhandler='0' wp=rw 554s |-+- policy='service-time 0' prio=1 status=active 554s | `- 0:0:0:1 sda 8:0 active ready running 554s `-+- policy='service-time 0' prio=1 status=enabled 554s `- 1:0:0:1 sdb 8:16 active ready running 554s + sync 554s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 554s + echo Final stats 554s + iscsiadm --mode session --stats 554s + journalctl --no-pager -u multipathd 554s + echo Check final path status 554s + multipath -ll 554s + multipath -ll 554s + grep --count status= 554s + diskc=2 554s + multipath -ll 554s + grep --count status=active 554s + diska=1 554s + multipath -ll 554s + grep --count status=enabled 554s + diske=1 554s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 554s + echo OK 554s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 554s OK 555s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 555s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 555s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 555s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 555s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 555s autopkgtest [18:19:24]: test tgtbasedmpaths: -----------------------] 556s autopkgtest [18:19:25]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 556s tgtbasedmpaths PASS 556s autopkgtest [18:19:25]: @@@@@@@@@@@@@@@@@@@@ summary 556s kpartx-file-loopback PASS 556s tgtbasedmpaths PASS 569s nova [W] Using flock in scalingstack-bos01-s390x 569s Creating nova instance adt-oracular-s390x-multipath-tools-20240719-181009-juju-7f2275-prod-proposed-migration-environment-3-8ca7fa2e-22f6-462b-b30f-851da6640b32 from image adt/ubuntu-oracular-s390x-server-20240719.img (UUID e5837032-c27f-4e89-b235-02d789b999a3)... 569s nova [W] Using flock in scalingstack-bos01-s390x 569s Creating nova instance adt-oracular-s390x-multipath-tools-20240719-181009-juju-7f2275-prod-proposed-migration-environment-3-8ca7fa2e-22f6-462b-b30f-851da6640b32 from image adt/ubuntu-oracular-s390x-server-20240719.img (UUID e5837032-c27f-4e89-b235-02d789b999a3)...