0s autopkgtest [00:51:05]: starting date and time: 2024-07-13 00:51:05+0000 0s autopkgtest [00:51:05]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [00:51:05]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.6q9ejrox/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:glibc --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=glibc/2.39-3.1ubuntu3 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos01-s390x-10.secgroup --name adt-oracular-s390x-multipath-tools-20240713-005105-juju-7f2275-prod-proposed-migration-environment-3-67e9df6d-4f8b-4c90-b56a-e56e14e8d9e3 --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/ 96s autopkgtest [00:52:41]: testbed dpkg architecture: s390x 96s autopkgtest [00:52:41]: testbed apt version: 2.9.6 96s autopkgtest [00:52:41]: @@@@@@@@@@@@@@@@@@@@ test bed setup 97s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 98s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [343 kB] 98s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 98s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [47.1 kB] 98s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 98s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x Packages [88.2 kB] 98s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x c-n-f Metadata [2112 B] 98s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted s390x Packages [1368 B] 98s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted s390x c-n-f Metadata [120 B] 98s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe s390x Packages [397 kB] 99s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe s390x c-n-f Metadata [8372 B] 99s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse s390x Packages [1448 B] 99s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse s390x c-n-f Metadata [120 B] 99s Fetched 1026 kB in 1s (689 kB/s) 99s Reading package lists... 101s Reading package lists... 102s Building dependency tree... 102s Reading state information... 102s Calculating upgrade... 102s The following packages will be upgraded: 102s binutils binutils-common binutils-s390x-linux-gnu gir1.2-glib-2.0 102s inetutils-telnet libbinutils libc-bin libc-dev-bin libc-devtools libc6 102s libc6-dev libctf-nobfd0 libctf0 libglib2.0-0t64 libglib2.0-data 102s libnghttp2-14 libnss3 libsframe1 libssl3t64 locales openssh-client 102s openssh-server openssh-sftp-server openssl telnet 102s 25 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 102s Need to get 20.4 MB of archives. 102s After this operation, 383 kB of additional disk space will be used. 102s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x libc-devtools s390x 2.39-3.1ubuntu3 [30.7 kB] 102s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x libc6-dev s390x 2.39-3.1ubuntu3 [1626 kB] 103s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x libc-dev-bin s390x 2.39-3.1ubuntu3 [20.2 kB] 103s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x libc6 s390x 2.39-3.1ubuntu3 [2841 kB] 104s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x libc-bin s390x 2.39-3.1ubuntu3 [654 kB] 105s Get:6 http://ftpmaster.internal/ubuntu oracular/main s390x libssl3t64 s390x 3.2.2-1ubuntu1 [1837 kB] 105s Get:7 http://ftpmaster.internal/ubuntu oracular/main s390x openssh-sftp-server s390x 1:9.6p1-3ubuntu17 [38.2 kB] 105s Get:8 http://ftpmaster.internal/ubuntu oracular/main s390x openssh-server s390x 1:9.6p1-3ubuntu17 [525 kB] 106s Get:9 http://ftpmaster.internal/ubuntu oracular/main s390x openssh-client s390x 1:9.6p1-3ubuntu17 [928 kB] 106s Get:10 http://ftpmaster.internal/ubuntu oracular/main s390x gir1.2-glib-2.0 s390x 2.80.4-1ubuntu1 [180 kB] 106s Get:11 http://ftpmaster.internal/ubuntu oracular/main s390x libglib2.0-0t64 s390x 2.80.4-1ubuntu1 [1551 kB] 106s Get:12 http://ftpmaster.internal/ubuntu oracular/main s390x libglib2.0-data all 2.80.4-1ubuntu1 [49.3 kB] 106s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x locales all 2.39-3.1ubuntu3 [4220 kB] 108s Get:14 http://ftpmaster.internal/ubuntu oracular/main s390x openssl s390x 3.2.2-1ubuntu1 [1125 kB] 109s Get:15 http://ftpmaster.internal/ubuntu oracular/main s390x inetutils-telnet s390x 2:2.5-5ubuntu1 [110 kB] 109s Get:16 http://ftpmaster.internal/ubuntu oracular/main s390x libnghttp2-14 s390x 1.62.1-2 [76.9 kB] 109s Get:17 http://ftpmaster.internal/ubuntu oracular/main s390x telnet all 0.17+2.5-5ubuntu1 [3688 B] 109s Get:18 http://ftpmaster.internal/ubuntu oracular/main s390x libctf0 s390x 2.42.50.20240710-1ubuntu1 [100 kB] 109s Get:19 http://ftpmaster.internal/ubuntu oracular/main s390x libctf-nobfd0 s390x 2.42.50.20240710-1ubuntu1 [101 kB] 109s Get:20 http://ftpmaster.internal/ubuntu oracular/main s390x binutils-s390x-linux-gnu s390x 2.42.50.20240710-1ubuntu1 [2289 kB] 110s Get:21 http://ftpmaster.internal/ubuntu oracular/main s390x libbinutils s390x 2.42.50.20240710-1ubuntu1 [471 kB] 110s Get:22 http://ftpmaster.internal/ubuntu oracular/main s390x binutils s390x 2.42.50.20240710-1ubuntu1 [3062 B] 110s Get:23 http://ftpmaster.internal/ubuntu oracular/main s390x binutils-common s390x 2.42.50.20240710-1ubuntu1 [220 kB] 110s Get:24 http://ftpmaster.internal/ubuntu oracular/main s390x libsframe1 s390x 2.42.50.20240710-1ubuntu1 [13.8 kB] 110s Get:25 http://ftpmaster.internal/ubuntu oracular/main s390x libnss3 s390x 2:3.102-1 [1408 kB] 111s Preconfiguring packages ... 111s Fetched 20.4 MB in 9s (2260 kB/s) 111s (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 ... 54721 files and directories currently installed.) 111s Preparing to unpack .../libc-devtools_2.39-3.1ubuntu3_s390x.deb ... 111s Unpacking libc-devtools (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 112s Preparing to unpack .../libc6-dev_2.39-3.1ubuntu3_s390x.deb ... 112s Unpacking libc6-dev:s390x (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 112s Preparing to unpack .../libc-dev-bin_2.39-3.1ubuntu3_s390x.deb ... 112s Unpacking libc-dev-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 112s Preparing to unpack .../libc6_2.39-3.1ubuntu3_s390x.deb ... 112s Unpacking libc6:s390x (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 112s Setting up libc6:s390x (2.39-3.1ubuntu3) ... 112s Error: Could not restart systemd, systemd binary not working 112s (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 ... 54721 files and directories currently installed.) 112s Preparing to unpack .../libc-bin_2.39-3.1ubuntu3_s390x.deb ... 112s Unpacking libc-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 112s Setting up libc-bin (2.39-3.1ubuntu3) ... 112s (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 ... 54721 files and directories currently installed.) 112s Preparing to unpack .../libssl3t64_3.2.2-1ubuntu1_s390x.deb ... 112s Unpacking libssl3t64:s390x (3.2.2-1ubuntu1) over (3.2.1-3ubuntu1) ... 112s Setting up libssl3t64:s390x (3.2.2-1ubuntu1) ... 112s (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 ... 54721 files and directories currently installed.) 112s Preparing to unpack .../00-openssh-sftp-server_1%3a9.6p1-3ubuntu17_s390x.deb ... 112s Unpacking openssh-sftp-server (1:9.6p1-3ubuntu17) over (1:9.6p1-3ubuntu15) ... 112s Preparing to unpack .../01-openssh-server_1%3a9.6p1-3ubuntu17_s390x.deb ... 112s Unpacking openssh-server (1:9.6p1-3ubuntu17) over (1:9.6p1-3ubuntu15) ... 112s Preparing to unpack .../02-openssh-client_1%3a9.6p1-3ubuntu17_s390x.deb ... 112s Unpacking openssh-client (1:9.6p1-3ubuntu17) over (1:9.6p1-3ubuntu15) ... 112s Preparing to unpack .../03-gir1.2-glib-2.0_2.80.4-1ubuntu1_s390x.deb ... 112s Unpacking gir1.2-glib-2.0:s390x (2.80.4-1ubuntu1) over (2.80.3-1ubuntu1) ... 112s Preparing to unpack .../04-libglib2.0-0t64_2.80.4-1ubuntu1_s390x.deb ... 112s Unpacking libglib2.0-0t64:s390x (2.80.4-1ubuntu1) over (2.80.3-1ubuntu1) ... 113s Preparing to unpack .../05-libglib2.0-data_2.80.4-1ubuntu1_all.deb ... 113s Unpacking libglib2.0-data (2.80.4-1ubuntu1) over (2.80.3-1ubuntu1) ... 113s Preparing to unpack .../06-locales_2.39-3.1ubuntu3_all.deb ... 113s Unpacking locales (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 113s Preparing to unpack .../07-openssl_3.2.2-1ubuntu1_s390x.deb ... 113s Unpacking openssl (3.2.2-1ubuntu1) over (3.2.1-3ubuntu1) ... 113s Preparing to unpack .../08-inetutils-telnet_2%3a2.5-5ubuntu1_s390x.deb ... 113s Unpacking inetutils-telnet (2:2.5-5ubuntu1) over (2:2.5-3ubuntu4) ... 113s Preparing to unpack .../09-libnghttp2-14_1.62.1-2_s390x.deb ... 113s Unpacking libnghttp2-14:s390x (1.62.1-2) over (1.62.1-1) ... 113s Preparing to unpack .../10-telnet_0.17+2.5-5ubuntu1_all.deb ... 113s Unpacking telnet (0.17+2.5-5ubuntu1) over (0.17+2.5-3ubuntu4) ... 113s Preparing to unpack .../11-libctf0_2.42.50.20240710-1ubuntu1_s390x.deb ... 113s Unpacking libctf0:s390x (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 113s Preparing to unpack .../12-libctf-nobfd0_2.42.50.20240710-1ubuntu1_s390x.deb ... 113s Unpacking libctf-nobfd0:s390x (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 113s Preparing to unpack .../13-binutils-s390x-linux-gnu_2.42.50.20240710-1ubuntu1_s390x.deb ... 113s Unpacking binutils-s390x-linux-gnu (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 113s Preparing to unpack .../14-libbinutils_2.42.50.20240710-1ubuntu1_s390x.deb ... 113s Unpacking libbinutils:s390x (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 113s Preparing to unpack .../15-binutils_2.42.50.20240710-1ubuntu1_s390x.deb ... 113s Unpacking binutils (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 113s Preparing to unpack .../16-binutils-common_2.42.50.20240710-1ubuntu1_s390x.deb ... 113s Unpacking binutils-common:s390x (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 113s Preparing to unpack .../17-libsframe1_2.42.50.20240710-1ubuntu1_s390x.deb ... 113s Unpacking libsframe1:s390x (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 113s Preparing to unpack .../18-libnss3_2%3a3.102-1_s390x.deb ... 113s Unpacking libnss3:s390x (2:3.102-1) over (2:3.101-1) ... 113s Setting up openssh-client (1:9.6p1-3ubuntu17) ... 113s Setting up binutils-common:s390x (2.42.50.20240710-1ubuntu1) ... 113s Setting up libnghttp2-14:s390x (1.62.1-2) ... 113s Setting up inetutils-telnet (2:2.5-5ubuntu1) ... 113s Setting up libctf-nobfd0:s390x (2.42.50.20240710-1ubuntu1) ... 113s Setting up libnss3:s390x (2:3.102-1) ... 113s Setting up locales (2.39-3.1ubuntu3) ... 114s Generating locales (this might take a while)... 115s en_US.UTF-8... done 115s Generation complete. 115s Setting up libsframe1:s390x (2.42.50.20240710-1ubuntu1) ... 115s Setting up libglib2.0-0t64:s390x (2.80.4-1ubuntu1) ... 115s No schema files found: doing nothing. 115s Setting up libglib2.0-data (2.80.4-1ubuntu1) ... 115s Setting up gir1.2-glib-2.0:s390x (2.80.4-1ubuntu1) ... 115s Setting up libbinutils:s390x (2.42.50.20240710-1ubuntu1) ... 115s Setting up libc-dev-bin (2.39-3.1ubuntu3) ... 115s Setting up openssl (3.2.2-1ubuntu1) ... 115s Installing new version of config file /etc/ssl/openssl.cnf ... 115s Setting up libc-devtools (2.39-3.1ubuntu3) ... 115s Setting up libctf0:s390x (2.42.50.20240710-1ubuntu1) ... 115s Setting up openssh-sftp-server (1:9.6p1-3ubuntu17) ... 115s Setting up binutils-s390x-linux-gnu (2.42.50.20240710-1ubuntu1) ... 115s Setting up telnet (0.17+2.5-5ubuntu1) ... 115s Setting up openssh-server (1:9.6p1-3ubuntu17) ... 115s Installing new version of config file /etc/pam.d/sshd ... 117s Setting up binutils (2.42.50.20240710-1ubuntu1) ... 117s Setting up libc6-dev:s390x (2.39-3.1ubuntu3) ... 117s Processing triggers for ufw (0.36.2-6) ... 117s Processing triggers for systemd (256-1ubuntu1) ... 117s Processing triggers for man-db (2.12.1-2) ... 118s Processing triggers for libc-bin (2.39-3.1ubuntu3) ... 118s Reading package lists... 119s Building dependency tree... 119s Reading state information... 119s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 119s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 119s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 119s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 119s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 120s Reading package lists... 120s Reading package lists... 120s Building dependency tree... 120s Reading state information... 121s Calculating upgrade... 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 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 121s autopkgtest [00:53:06]: rebooting testbed after setup commands that affected boot 125s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 151s autopkgtest [00:53:36]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:14:26 UTC 2024 154s autopkgtest [00:53:39]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 157s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 157s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 157s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 157s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 157s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 157s gpgv: issuer "steve.langasek@ubuntu.com" 157s gpgv: Can't check signature: No public key 157s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 157s autopkgtest [00:53:42]: testing package multipath-tools version 0.9.4-5ubuntu8 158s autopkgtest [00:53:43]: build not needed 158s autopkgtest [00:53:43]: test kpartx-file-loopback: preparing testbed 159s Reading package lists... 159s Building dependency tree... 159s Reading state information... 160s Starting pkgProblemResolver with broken count: 0 160s Starting 2 pkgProblemResolver with broken count: 0 160s Done 160s The following additional packages will be installed: 160s liburing2 qemu-utils 160s Recommended packages: 160s qemu-block-extra 160s The following NEW packages will be installed: 160s autopkgtest-satdep liburing2 qemu-utils 160s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 160s Need to get 2043 kB/2044 kB of archives. 160s After this operation, 11.9 MB of additional disk space will be used. 160s Get:1 /tmp/autopkgtest.rQ8TQq/1-autopkgtest-satdep.deb autopkgtest-satdep s390x 0 [724 B] 160s Get:2 http://ftpmaster.internal/ubuntu oracular/main s390x liburing2 s390x 2.6-1 [24.4 kB] 160s Get:3 http://ftpmaster.internal/ubuntu oracular/main s390x qemu-utils s390x 1:8.2.2+ds-0ubuntu1 [2019 kB] 162s Fetched 2043 kB in 1s (1491 kB/s) 162s Selecting previously unselected package liburing2:s390x. 162s (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 ... 54720 files and directories currently installed.) 162s Preparing to unpack .../liburing2_2.6-1_s390x.deb ... 162s Unpacking liburing2:s390x (2.6-1) ... 162s Selecting previously unselected package qemu-utils. 162s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_s390x.deb ... 162s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 162s Selecting previously unselected package autopkgtest-satdep. 162s Preparing to unpack .../1-autopkgtest-satdep.deb ... 162s Unpacking autopkgtest-satdep (0) ... 162s Setting up liburing2:s390x (2.6-1) ... 162s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 162s Setting up autopkgtest-satdep (0) ... 162s Processing triggers for man-db (2.12.1-2) ... 163s Processing triggers for libc-bin (2.39-3.1ubuntu3) ... 165s (Reading database ... 54740 files and directories currently installed.) 165s Removing autopkgtest-satdep (0) ... 165s autopkgtest [00:53:50]: test kpartx-file-loopback: [----------------------- 165s 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. 167s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 167s standard_filename: OK 167s del devmap : loop0p1 167s No devices found 167s standard_filename_cleanup: OK 167s Formatting 'fou du FaFa.img', fmt=raw size=20971520 168s Creating new GPT entries in memory. 168s Warning: The kernel is still using the old partition table. 168s The new table will be used at the next reboot or after you 168s run partprobe(8) or kpartx(8) 168s The operation has completed successfully. 168s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 168s filename_with_spaces: OK 168s del devmap : loop0p1 168s No devices found 168s filename_with_spaces_cleanup: OK 168s autopkgtest [00:53:53]: test kpartx-file-loopback: -----------------------] 169s autopkgtest [00:53:54]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 169s kpartx-file-loopback PASS 169s autopkgtest [00:53:54]: test tgtbasedmpaths: preparing testbed 328s autopkgtest [00:56:33]: testbed dpkg architecture: s390x 329s autopkgtest [00:56:34]: testbed apt version: 2.9.6 329s autopkgtest [00:56:34]: @@@@@@@@@@@@@@@@@@@@ test bed setup 330s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 330s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [343 kB] 330s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [47.1 kB] 330s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 330s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 330s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x Packages [88.2 kB] 330s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x c-n-f Metadata [2112 B] 330s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted s390x Packages [1368 B] 330s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted s390x c-n-f Metadata [120 B] 330s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe s390x Packages [397 kB] 330s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe s390x c-n-f Metadata [8372 B] 330s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse s390x Packages [1448 B] 330s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse s390x c-n-f Metadata [120 B] 331s Fetched 1026 kB in 1s (933 kB/s) 331s Reading package lists... 333s Reading package lists... 333s Building dependency tree... 333s Reading state information... 333s Calculating upgrade... 334s The following packages will be upgraded: 334s binutils binutils-common binutils-s390x-linux-gnu gir1.2-glib-2.0 334s inetutils-telnet libbinutils libc-bin libc-dev-bin libc-devtools libc6 334s libc6-dev libctf-nobfd0 libctf0 libglib2.0-0t64 libglib2.0-data 334s libnghttp2-14 libnss3 libsframe1 libssl3t64 locales openssh-client 334s openssh-server openssh-sftp-server openssl telnet 334s 25 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 334s Need to get 20.4 MB of archives. 334s After this operation, 383 kB of additional disk space will be used. 334s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x libc-devtools s390x 2.39-3.1ubuntu3 [30.7 kB] 334s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x libc6-dev s390x 2.39-3.1ubuntu3 [1626 kB] 335s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x libc-dev-bin s390x 2.39-3.1ubuntu3 [20.2 kB] 335s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x libc6 s390x 2.39-3.1ubuntu3 [2841 kB] 336s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x libc-bin s390x 2.39-3.1ubuntu3 [654 kB] 336s Get:6 http://ftpmaster.internal/ubuntu oracular/main s390x libssl3t64 s390x 3.2.2-1ubuntu1 [1837 kB] 336s Get:7 http://ftpmaster.internal/ubuntu oracular/main s390x openssh-sftp-server s390x 1:9.6p1-3ubuntu17 [38.2 kB] 336s Get:8 http://ftpmaster.internal/ubuntu oracular/main s390x openssh-server s390x 1:9.6p1-3ubuntu17 [525 kB] 336s Get:9 http://ftpmaster.internal/ubuntu oracular/main s390x openssh-client s390x 1:9.6p1-3ubuntu17 [928 kB] 337s Get:10 http://ftpmaster.internal/ubuntu oracular/main s390x gir1.2-glib-2.0 s390x 2.80.4-1ubuntu1 [180 kB] 337s Get:11 http://ftpmaster.internal/ubuntu oracular/main s390x libglib2.0-0t64 s390x 2.80.4-1ubuntu1 [1551 kB] 337s Get:12 http://ftpmaster.internal/ubuntu oracular/main s390x libglib2.0-data all 2.80.4-1ubuntu1 [49.3 kB] 337s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main s390x locales all 2.39-3.1ubuntu3 [4220 kB] 337s Get:14 http://ftpmaster.internal/ubuntu oracular/main s390x openssl s390x 3.2.2-1ubuntu1 [1125 kB] 338s Get:15 http://ftpmaster.internal/ubuntu oracular/main s390x inetutils-telnet s390x 2:2.5-5ubuntu1 [110 kB] 338s Get:16 http://ftpmaster.internal/ubuntu oracular/main s390x libnghttp2-14 s390x 1.62.1-2 [76.9 kB] 338s Get:17 http://ftpmaster.internal/ubuntu oracular/main s390x telnet all 0.17+2.5-5ubuntu1 [3688 B] 338s Get:18 http://ftpmaster.internal/ubuntu oracular/main s390x libctf0 s390x 2.42.50.20240710-1ubuntu1 [100 kB] 338s Get:19 http://ftpmaster.internal/ubuntu oracular/main s390x libctf-nobfd0 s390x 2.42.50.20240710-1ubuntu1 [101 kB] 338s Get:20 http://ftpmaster.internal/ubuntu oracular/main s390x binutils-s390x-linux-gnu s390x 2.42.50.20240710-1ubuntu1 [2289 kB] 338s Get:21 http://ftpmaster.internal/ubuntu oracular/main s390x libbinutils s390x 2.42.50.20240710-1ubuntu1 [471 kB] 338s Get:22 http://ftpmaster.internal/ubuntu oracular/main s390x binutils s390x 2.42.50.20240710-1ubuntu1 [3062 B] 338s Get:23 http://ftpmaster.internal/ubuntu oracular/main s390x binutils-common s390x 2.42.50.20240710-1ubuntu1 [220 kB] 338s Get:24 http://ftpmaster.internal/ubuntu oracular/main s390x libsframe1 s390x 2.42.50.20240710-1ubuntu1 [13.8 kB] 338s Get:25 http://ftpmaster.internal/ubuntu oracular/main s390x libnss3 s390x 2:3.102-1 [1408 kB] 339s Preconfiguring packages ... 339s Fetched 20.4 MB in 5s (4486 kB/s) 339s (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 ... 54721 files and directories currently installed.) 339s Preparing to unpack .../libc-devtools_2.39-3.1ubuntu3_s390x.deb ... 339s Unpacking libc-devtools (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 339s Preparing to unpack .../libc6-dev_2.39-3.1ubuntu3_s390x.deb ... 339s Unpacking libc6-dev:s390x (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 339s Preparing to unpack .../libc-dev-bin_2.39-3.1ubuntu3_s390x.deb ... 339s Unpacking libc-dev-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 339s Preparing to unpack .../libc6_2.39-3.1ubuntu3_s390x.deb ... 339s Unpacking libc6:s390x (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 339s Setting up libc6:s390x (2.39-3.1ubuntu3) ... 340s Error: Could not restart systemd, systemd binary not working 340s (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 ... 54721 files and directories currently installed.) 340s Preparing to unpack .../libc-bin_2.39-3.1ubuntu3_s390x.deb ... 340s Unpacking libc-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 340s Setting up libc-bin (2.39-3.1ubuntu3) ... 340s (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 ... 54721 files and directories currently installed.) 340s Preparing to unpack .../libssl3t64_3.2.2-1ubuntu1_s390x.deb ... 340s Unpacking libssl3t64:s390x (3.2.2-1ubuntu1) over (3.2.1-3ubuntu1) ... 340s Setting up libssl3t64:s390x (3.2.2-1ubuntu1) ... 340s (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 ... 54721 files and directories currently installed.) 340s Preparing to unpack .../00-openssh-sftp-server_1%3a9.6p1-3ubuntu17_s390x.deb ... 340s Unpacking openssh-sftp-server (1:9.6p1-3ubuntu17) over (1:9.6p1-3ubuntu15) ... 340s Preparing to unpack .../01-openssh-server_1%3a9.6p1-3ubuntu17_s390x.deb ... 340s Unpacking openssh-server (1:9.6p1-3ubuntu17) over (1:9.6p1-3ubuntu15) ... 340s Preparing to unpack .../02-openssh-client_1%3a9.6p1-3ubuntu17_s390x.deb ... 340s Unpacking openssh-client (1:9.6p1-3ubuntu17) over (1:9.6p1-3ubuntu15) ... 340s Preparing to unpack .../03-gir1.2-glib-2.0_2.80.4-1ubuntu1_s390x.deb ... 340s Unpacking gir1.2-glib-2.0:s390x (2.80.4-1ubuntu1) over (2.80.3-1ubuntu1) ... 340s Preparing to unpack .../04-libglib2.0-0t64_2.80.4-1ubuntu1_s390x.deb ... 340s Unpacking libglib2.0-0t64:s390x (2.80.4-1ubuntu1) over (2.80.3-1ubuntu1) ... 340s Preparing to unpack .../05-libglib2.0-data_2.80.4-1ubuntu1_all.deb ... 340s Unpacking libglib2.0-data (2.80.4-1ubuntu1) over (2.80.3-1ubuntu1) ... 340s Preparing to unpack .../06-locales_2.39-3.1ubuntu3_all.deb ... 340s Unpacking locales (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 340s Preparing to unpack .../07-openssl_3.2.2-1ubuntu1_s390x.deb ... 340s Unpacking openssl (3.2.2-1ubuntu1) over (3.2.1-3ubuntu1) ... 341s Preparing to unpack .../08-inetutils-telnet_2%3a2.5-5ubuntu1_s390x.deb ... 341s Unpacking inetutils-telnet (2:2.5-5ubuntu1) over (2:2.5-3ubuntu4) ... 341s Preparing to unpack .../09-libnghttp2-14_1.62.1-2_s390x.deb ... 341s Unpacking libnghttp2-14:s390x (1.62.1-2) over (1.62.1-1) ... 341s Preparing to unpack .../10-telnet_0.17+2.5-5ubuntu1_all.deb ... 341s Unpacking telnet (0.17+2.5-5ubuntu1) over (0.17+2.5-3ubuntu4) ... 341s Preparing to unpack .../11-libctf0_2.42.50.20240710-1ubuntu1_s390x.deb ... 341s Unpacking libctf0:s390x (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 341s Preparing to unpack .../12-libctf-nobfd0_2.42.50.20240710-1ubuntu1_s390x.deb ... 341s Unpacking libctf-nobfd0:s390x (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 341s Preparing to unpack .../13-binutils-s390x-linux-gnu_2.42.50.20240710-1ubuntu1_s390x.deb ... 341s Unpacking binutils-s390x-linux-gnu (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 341s Preparing to unpack .../14-libbinutils_2.42.50.20240710-1ubuntu1_s390x.deb ... 341s Unpacking libbinutils:s390x (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 341s Preparing to unpack .../15-binutils_2.42.50.20240710-1ubuntu1_s390x.deb ... 341s Unpacking binutils (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 341s Preparing to unpack .../16-binutils-common_2.42.50.20240710-1ubuntu1_s390x.deb ... 341s Unpacking binutils-common:s390x (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 341s Preparing to unpack .../17-libsframe1_2.42.50.20240710-1ubuntu1_s390x.deb ... 341s Unpacking libsframe1:s390x (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 341s Preparing to unpack .../18-libnss3_2%3a3.102-1_s390x.deb ... 341s Unpacking libnss3:s390x (2:3.102-1) over (2:3.101-1) ... 341s Setting up openssh-client (1:9.6p1-3ubuntu17) ... 341s Setting up binutils-common:s390x (2.42.50.20240710-1ubuntu1) ... 341s Setting up libnghttp2-14:s390x (1.62.1-2) ... 341s Setting up inetutils-telnet (2:2.5-5ubuntu1) ... 341s Setting up libctf-nobfd0:s390x (2.42.50.20240710-1ubuntu1) ... 341s Setting up libnss3:s390x (2:3.102-1) ... 341s Setting up locales (2.39-3.1ubuntu3) ... 341s Generating locales (this might take a while)... 343s en_US.UTF-8... done 343s Generation complete. 343s Setting up libsframe1:s390x (2.42.50.20240710-1ubuntu1) ... 343s Setting up libglib2.0-0t64:s390x (2.80.4-1ubuntu1) ... 343s No schema files found: doing nothing. 343s Setting up libglib2.0-data (2.80.4-1ubuntu1) ... 343s Setting up gir1.2-glib-2.0:s390x (2.80.4-1ubuntu1) ... 343s Setting up libbinutils:s390x (2.42.50.20240710-1ubuntu1) ... 343s Setting up libc-dev-bin (2.39-3.1ubuntu3) ... 343s Setting up openssl (3.2.2-1ubuntu1) ... 343s Installing new version of config file /etc/ssl/openssl.cnf ... 343s Setting up libc-devtools (2.39-3.1ubuntu3) ... 343s Setting up libctf0:s390x (2.42.50.20240710-1ubuntu1) ... 343s Setting up openssh-sftp-server (1:9.6p1-3ubuntu17) ... 343s Setting up binutils-s390x-linux-gnu (2.42.50.20240710-1ubuntu1) ... 343s Setting up telnet (0.17+2.5-5ubuntu1) ... 343s Setting up openssh-server (1:9.6p1-3ubuntu17) ... 343s Installing new version of config file /etc/pam.d/sshd ... 344s Setting up binutils (2.42.50.20240710-1ubuntu1) ... 344s Setting up libc6-dev:s390x (2.39-3.1ubuntu3) ... 344s Processing triggers for ufw (0.36.2-6) ... 344s Processing triggers for systemd (256-1ubuntu1) ... 345s Processing triggers for man-db (2.12.1-2) ... 346s Processing triggers for libc-bin (2.39-3.1ubuntu3) ... 346s Reading package lists... 347s Building dependency tree... 347s Reading state information... 347s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 347s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 347s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 348s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 348s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 349s Reading package lists... 349s Reading package lists... 349s Building dependency tree... 349s Reading state information... 349s Calculating upgrade... 349s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 349s Reading package lists... 349s Building dependency tree... 349s Reading state information... 350s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 350s autopkgtest [00:56:55]: rebooting testbed after setup commands that affected boot 385s Reading package lists... 385s Building dependency tree... 385s Reading state information... 386s Starting pkgProblemResolver with broken count: 0 386s Starting 2 pkgProblemResolver with broken count: 0 386s Done 386s The following additional packages will be installed: 386s fio libatomic1 libboost-iostreams1.83.0 libboost-thread1.83.0 386s libconfig-general-perl libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 386s libisns0t64 libnbd0 libopeniscsiusr librados2 librbd1 librdmacm1t64 lsscsi 386s open-iscsi tgt 386s Suggested packages: 386s fio-examples gnuplot tgt-glusterfs tgt-rbd 386s Recommended packages: 386s finalrd 386s The following NEW packages will be installed: 386s autopkgtest-satdep fio libatomic1 libboost-iostreams1.83.0 386s libboost-thread1.83.0 libconfig-general-perl libgfapi0 libgfrpc0 libgfxdr0 386s libglusterfs0 libisns0t64 libnbd0 libopeniscsiusr librados2 librbd1 386s librdmacm1t64 lsscsi open-iscsi tgt 386s 0 upgraded, 19 newly installed, 0 to remove and 0 not upgraded. 386s Need to get 9646 kB/9647 kB of archives. 386s After this operation, 39.0 MB of additional disk space will be used. 386s Get:1 /tmp/autopkgtest.rQ8TQq/2-autopkgtest-satdep.deb autopkgtest-satdep s390x 0 [728 B] 386s Get:2 http://ftpmaster.internal/ubuntu oracular/main s390x libopeniscsiusr s390x 2.1.10-1ubuntu1 [51.3 kB] 386s Get:3 http://ftpmaster.internal/ubuntu oracular/main s390x libisns0t64 s390x 0.101-1 [95.0 kB] 386s Get:4 http://ftpmaster.internal/ubuntu oracular/main s390x open-iscsi s390x 2.1.10-1ubuntu1 [330 kB] 387s Get:5 http://ftpmaster.internal/ubuntu oracular/main s390x librdmacm1t64 s390x 52.0-2 [73.1 kB] 387s Get:6 http://ftpmaster.internal/ubuntu oracular/universe s390x libconfig-general-perl all 2.65-2 [57.1 kB] 387s Get:7 http://ftpmaster.internal/ubuntu oracular/universe s390x tgt s390x 1:1.0.85-1.2ubuntu1 [235 kB] 387s Get:8 http://ftpmaster.internal/ubuntu oracular/universe s390x libgfxdr0 s390x 11.1-4ubuntu1 [20.1 kB] 387s Get:9 http://ftpmaster.internal/ubuntu oracular/universe s390x libglusterfs0 s390x 11.1-4ubuntu1 [280 kB] 387s Get:10 http://ftpmaster.internal/ubuntu oracular/universe s390x libgfrpc0 s390x 11.1-4ubuntu1 [41.1 kB] 387s Get:11 http://ftpmaster.internal/ubuntu oracular/universe s390x libgfapi0 s390x 11.1-4ubuntu1 [81.2 kB] 387s Get:12 http://ftpmaster.internal/ubuntu oracular/universe s390x libnbd0 s390x 1.20.2-1 [91.8 kB] 387s Get:13 http://ftpmaster.internal/ubuntu oracular/main s390x libboost-iostreams1.83.0 s390x 1.83.0-3ubuntu1 [258 kB] 387s Get:14 http://ftpmaster.internal/ubuntu oracular/main s390x libboost-thread1.83.0 s390x 1.83.0-3ubuntu1 [278 kB] 387s Get:15 http://ftpmaster.internal/ubuntu oracular/main s390x librados2 s390x 19.2.0~git20240301.4c76c50-0ubuntu7 [4106 kB] 387s Get:16 http://ftpmaster.internal/ubuntu oracular/main s390x libatomic1 s390x 14.1.0-1ubuntu1 [9378 B] 387s Get:17 http://ftpmaster.internal/ubuntu oracular/main s390x librbd1 s390x 19.2.0~git20240301.4c76c50-0ubuntu7 [2936 kB] 388s Get:18 http://ftpmaster.internal/ubuntu oracular/universe s390x fio s390x 3.37-1 [652 kB] 388s Get:19 http://ftpmaster.internal/ubuntu oracular/main s390x lsscsi s390x 0.32-1build1 [50.4 kB] 388s Preconfiguring packages ... 388s Fetched 9646 kB in 2s (5911 kB/s) 388s Selecting previously unselected package libopeniscsiusr. 388s (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 ... 54720 files and directories currently installed.) 388s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_s390x.deb ... 388s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 388s Selecting previously unselected package libisns0t64:s390x. 388s Preparing to unpack .../01-libisns0t64_0.101-1_s390x.deb ... 388s Unpacking libisns0t64:s390x (0.101-1) ... 388s Selecting previously unselected package open-iscsi. 388s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_s390x.deb ... 388s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 388s Selecting previously unselected package librdmacm1t64:s390x. 388s Preparing to unpack .../03-librdmacm1t64_52.0-2_s390x.deb ... 388s Unpacking librdmacm1t64:s390x (52.0-2) ... 388s Selecting previously unselected package libconfig-general-perl. 388s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 388s Unpacking libconfig-general-perl (2.65-2) ... 388s Selecting previously unselected package tgt. 388s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_s390x.deb ... 388s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 388s Selecting previously unselected package libgfxdr0:s390x. 388s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_s390x.deb ... 388s Unpacking libgfxdr0:s390x (11.1-4ubuntu1) ... 389s Selecting previously unselected package libglusterfs0:s390x. 389s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_s390x.deb ... 389s Unpacking libglusterfs0:s390x (11.1-4ubuntu1) ... 389s Selecting previously unselected package libgfrpc0:s390x. 389s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_s390x.deb ... 389s Unpacking libgfrpc0:s390x (11.1-4ubuntu1) ... 389s Selecting previously unselected package libgfapi0:s390x. 389s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_s390x.deb ... 389s Unpacking libgfapi0:s390x (11.1-4ubuntu1) ... 389s Selecting previously unselected package libnbd0. 389s Preparing to unpack .../10-libnbd0_1.20.2-1_s390x.deb ... 389s Unpacking libnbd0 (1.20.2-1) ... 389s Selecting previously unselected package libboost-iostreams1.83.0:s390x. 389s Preparing to unpack .../11-libboost-iostreams1.83.0_1.83.0-3ubuntu1_s390x.deb ... 389s Unpacking libboost-iostreams1.83.0:s390x (1.83.0-3ubuntu1) ... 389s Selecting previously unselected package libboost-thread1.83.0:s390x. 389s Preparing to unpack .../12-libboost-thread1.83.0_1.83.0-3ubuntu1_s390x.deb ... 389s Unpacking libboost-thread1.83.0:s390x (1.83.0-3ubuntu1) ... 389s Selecting previously unselected package librados2. 389s Preparing to unpack .../13-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_s390x.deb ... 389s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 389s Selecting previously unselected package libatomic1:s390x. 389s Preparing to unpack .../14-libatomic1_14.1.0-1ubuntu1_s390x.deb ... 389s Unpacking libatomic1:s390x (14.1.0-1ubuntu1) ... 389s Selecting previously unselected package librbd1. 389s Preparing to unpack .../15-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_s390x.deb ... 389s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 389s Selecting previously unselected package fio. 389s Preparing to unpack .../16-fio_3.37-1_s390x.deb ... 389s Unpacking fio (3.37-1) ... 389s Selecting previously unselected package lsscsi. 389s Preparing to unpack .../17-lsscsi_0.32-1build1_s390x.deb ... 389s Unpacking lsscsi (0.32-1build1) ... 389s Selecting previously unselected package autopkgtest-satdep. 389s Preparing to unpack .../18-2-autopkgtest-satdep.deb ... 389s Unpacking autopkgtest-satdep (0) ... 389s Setting up libconfig-general-perl (2.65-2) ... 389s Setting up libisns0t64:s390x (0.101-1) ... 389s Setting up libboost-thread1.83.0:s390x (1.83.0-3ubuntu1) ... 389s Setting up libnbd0 (1.20.2-1) ... 389s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 389s Setting up libglusterfs0:s390x (11.1-4ubuntu1) ... 389s Setting up libboost-iostreams1.83.0:s390x (1.83.0-3ubuntu1) ... 389s Setting up libatomic1:s390x (14.1.0-1ubuntu1) ... 389s Setting up lsscsi (0.32-1build1) ... 389s Setting up librdmacm1t64:s390x (52.0-2) ... 389s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 390s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 390s Setting up libgfxdr0:s390x (11.1-4ubuntu1) ... 390s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 390s Setting up open-iscsi (2.1.10-1ubuntu1) ... 391s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 391s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 391s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 391s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 391s Setting up libgfrpc0:s390x (11.1-4ubuntu1) ... 391s Setting up libgfapi0:s390x (11.1-4ubuntu1) ... 391s Setting up fio (3.37-1) ... 392s Setting up autopkgtest-satdep (0) ... 392s Processing triggers for man-db (2.12.1-2) ... 393s Processing triggers for initramfs-tools (0.142ubuntu30) ... 393s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 393s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 397s Using config file '/etc/zipl.conf' 397s Building bootmap in '/boot' 397s Adding IPL section 'ubuntu' (default) 397s Preparing boot device for LD-IPL: vda (0000). 397s Done. 397s Processing triggers for libc-bin (2.39-3.1ubuntu3) ... 400s (Reading database ... 54938 files and directories currently installed.) 400s Removing autopkgtest-satdep (0) ... 402s autopkgtest [00:57:47]: test tgtbasedmpaths: [----------------------- 402s + targetname=iqn.2016-11.foo.com:target.iscsi 402s + pwd 402s + cwd=/tmp/autopkgtest.rQ8TQq/build.w3L/src 402s + testdir=/mnt/tgtmpathtest 402s + localhost=127.0.0.1 402s + portal=127.0.0.1:3260 402s + maxpaths=4 402s + backfn=backingfile 402s + expectwwid=60000000000000000e00000000010001 402s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 402s + bglog=/tmp/autopkgtest.rQ8TQq/tgtbasedmpaths-artifacts/test-background.log 402s + fioprep=/tmp/autopkgtest.rQ8TQq/tgtbasedmpaths-artifacts/path-change-prep.fio 402s + fiovrfy=/tmp/autopkgtest.rQ8TQq/tgtbasedmpaths-artifacts/path-change-check.fio 402s + service tgt restart 403s + truncate --size 100M backingfile 403s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 403s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 403s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.rQ8TQq/build.w3L/src/backingfile 403s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 403s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 403s + echo login #1 403s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 403s login #1 403s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 403s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 403s + seq 2 4 403s + echo extra login #2 403s + iscsiadm --mode session -r 1 --op new 403s extra login #2 403s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 403s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 403s + echo extra login #3 403s + iscsiadm --mode session -r 1 --op new 403s extra login #3 403s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 403s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 403s + echo extra login #4 403s + iscsiadm --mode session -r 1 --op new 403s extra login #4 403s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 403s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 403s + udevadm settle 403s + sleep 5 408s + Status after initial setup 408s echo Status after initial setup 408s + tgtadm --lld iscsi --mode target --op show 408s Target 1: iqn.2016-11.foo.com:target.iscsi 408s System information: 408s Driver: iscsi 408s State: ready 408s I_T nexus information: 408s I_T nexus: 1 408s Initiator: iqn.2004-10.com.ubuntu:01:dfb4517af30 alias: autopkgtest 408s Connection: 0 408s IP Address: 127.0.0.1 408s I_T nexus: 2 408s Initiator: iqn.2004-10.com.ubuntu:01:dfb4517af30 alias: autopkgtest 408s Connection: 0 408s IP Address: 127.0.0.1 408s I_T nexus: 3 408s Initiator: iqn.2004-10.com.ubuntu:01:dfb4517af30 alias: autopkgtest 408s Connection: 0 408s IP Address: 127.0.0.1 408s I_T nexus: 4 408s Initiator: iqn.2004-10.com.ubuntu:01:dfb4517af30 alias: autopkgtest 408s Connection: 0 408s IP Address: 127.0.0.1 408s LUN information: 408s LUN: 0 408s Type: controller 408s SCSI ID: IET 00010000 408s SCSI SN: beaf10 408s Size: 0 MB, Block size: 1 408s Online: Yes 408s Removable media: No 408s Prevent removal: No 408s Readonly: No 408s SWP: No 408s Thin-provisioning: No 408s Backing store type: null 408s Backing store path: None 408s Backing store flags: 408s LUN: 1 408s Type: disk 408s SCSI ID: IET 00010001 408s SCSI SN: beaf11 408s Size: 105 MB, Block size: 512 408s Online: Yes 408s Removable media: No 408s Prevent removal: No 408s Readonly: No 408s SWP: No 408s Thin-provisioning: No 408s Backing store type: rdwr 408s Backing store path: /tmp/autopkgtest.rQ8TQq/build.w3L/src/backingfile 408s Backing store flags: 408s Account information: 408s ACL information: 408s ALL 408s + tgtadm --lld iscsi --op show --mode conn --tid 1 408s + iscsiadm --mode session -P 1 408s Session: 4 408s Connection: 0 408s Initiator: iqn.2004-10.com.ubuntu:01:dfb4517af30 408s IP Address: 127.0.0.1 408s Session: 3 408s Connection: 0 408s Initiator: iqn.2004-10.com.ubuntu:01:dfb4517af30 408s IP Address: 127.0.0.1 408s Session: 2 408s Connection: 0 408s Initiator: iqn.2004-10.com.ubuntu:01:dfb4517af30 408s IP Address: 127.0.0.1 408s Session: 1 408s Connection: 0 408s Initiator: iqn.2004-10.com.ubuntu:01:dfb4517af30 408s IP Address: 127.0.0.1 408s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 408s Current Portal: 127.0.0.1:3260,1 408s Persistent Portal: 127.0.0.1:3260,1 408s ********** 408s Interface: 408s ********** 408s Iface Name: default 408s Iface Transport: tcp 408s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:dfb4517af30 408s Iface IPaddress: 127.0.0.1 408s Iface HWaddress: default 408s Iface Netdev: default 408s SID: 1 408s iSCSI Connection State: LOGGED IN 408s iSCSI Session State: LOGGED_IN 408s Internal iscsid Session State: NO CHANGE 408s 408s ********** 408s Interface: 408s ********** 408s Iface Name: default 408s Iface Transport: tcp 408s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:dfb4517af30 408s Iface IPaddress: 127.0.0.1 408s Iface HWaddress: default 408s Iface Netdev: default 408s SID: 2 408s iSCSI Connection State: LOGGED IN 408s iSCSI Session State: LOGGED_IN 408s Internal iscsid Session State: NO CHANGE 408s 408s ********** 408s Interface: 408s ********** 408s Iface Name: default 408s Iface Transport: tcp 408s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:dfb4517af30 408s Iface IPaddress: 127.0.0.1 408s Iface HWaddress: default 408s Iface Netdev: default 408s SID: 3 408s iSCSI Connection State: LOGGED IN 408s iSCSI Session State: LOGGED_IN 408s Internal iscsid Session State: NO CHANGE 408s 408s ********** 408s Interface: 408s ********** 408s Iface Name: default 408s Iface Transport: tcp 408s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:dfb4517af30 408s Iface IPaddress: 127.0.0.1 408s Iface HWaddress: default 408s Iface Netdev: default 408s SID: 4 408s iSCSI Connection State: LOGGED IN 408s iSCSI Session State: LOGGED_IN 408s Internal iscsid Session State: NO CHANGE 408s + lsscsi -liv 408s [0:0:0:0] storage IET Controller 0001 - - 408s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 408s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 408s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 408s [1:0:0:0] storage IET Controller 0001 - - 408s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 408s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 408s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 408s [2:0:0:0] storage IET Controller 0001 - - 408s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 408s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 408s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 408s [3:0:0:0] storage IET Controller 0001 - - 408s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 408s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 408s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 408s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 408s NVMe module may not be loaded 408s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 408s + multipath -v3 -ll 408s 53.018369 | set open fds limit to 1073741816/1073741816 408s 53.018454 | loading /lib/multipath/libchecktur.so checker 408s 53.018550 | checker tur: message table size = 3 408s 53.018559 | loading /lib/multipath/libprioconst.so prioritizer 408s 53.018664 | _init_foreign: foreign library "nvme" is not enabled 408s 53.023352 | vda: device node name blacklisted 408s 53.023573 | sda: size = 204800 408s 53.023691 | sda: vendor = IET 408s 53.023714 | sda: product = VIRTUAL-DISK 408s 53.023730 | sda: rev = 0001 408s 53.024570 | sda: h:b:t:l = 0:0:0:1 408s 53.024908 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 53.024918 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 408s 53.024920 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 408s 53.025152 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 53.025163 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 53.025179 | sda: serial = beaf11 408s 53.025183 | sda: detect_checker = yes (setting: multipath internal) 408s 53.025426 | sda: path_checker = tur (setting: multipath internal) 408s 53.025436 | sda: checker timeout = 30 s (setting: kernel sysfs) 408s 53.025506 | sda: tur state = up 408s 53.025652 | sdb: size = 204800 408s 53.025780 | sdb: vendor = IET 408s 53.025805 | sdb: product = VIRTUAL-DISK 408s 53.025820 | sdb: rev = 0001 408s 53.026725 | sdb: h:b:t:l = 1:0:0:1 408s 53.027040 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 53.027054 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 408s 53.027056 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 408s 53.027426 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 53.027433 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 53.027445 | sdb: serial = beaf11 408s 53.027446 | sdb: detect_checker = yes (setting: multipath internal) 408s 53.027596 | sdb: path_checker = tur (setting: multipath internal) 408s 53.027624 | sdb: checker timeout = 30 s (setting: kernel sysfs) 408s 53.027731 | sdb: tur state = up 408s 53.027874 | sdc: size = 204800 408s 53.028054 | sdc: vendor = IET 408s 53.028084 | sdc: product = VIRTUAL-DISK 408s 53.028102 | sdc: rev = 0001 408s 53.029069 | sdc: h:b:t:l = 2:0:0:1 408s 53.029393 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 53.029406 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 408s 53.029407 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 408s 53.029562 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 53.029574 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 53.029587 | sdc: serial = beaf11 408s 53.029589 | sdc: detect_checker = yes (setting: multipath internal) 408s 53.029843 | sdc: path_checker = tur (setting: multipath internal) 408s 53.029858 | sdc: checker timeout = 30 s (setting: kernel sysfs) 408s 53.030024 | sdc: tur state = up 408s 53.030149 | sdd: size = 204800 408s 53.030283 | sdd: vendor = IET 408s 53.030305 | sdd: product = VIRTUAL-DISK 408s 53.030319 | sdd: rev = 0001 408s 53.031072 | sdd: h:b:t:l = 3:0:0:1 408s 53.031375 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 53.031383 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 408s 53.031385 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 408s 53.031703 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 53.031712 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 53.031726 | sdd: serial = beaf11 408s 53.031727 | sdd: detect_checker = yes (setting: multipath internal) 408s 53.031823 | sdd: path_checker = tur (setting: multipath internal) 408s 53.031835 | sdd: checker timeout = 30 s (setting: kernel sysfs) 408s 53.032018 | sdd: tur state = up 408s 53.032104 | loop0: device node name blacklisted 408s 53.032181 | loop1: device node name blacklisted 408s 53.032254 | loop2: device node name blacklisted 408s 53.032320 | loop3: device node name blacklisted 408s 53.032394 | loop4: device node name blacklisted 408s 53.032466 | loop5: device node name blacklisted 408s 53.032537 | loop6: device node name blacklisted 408s 53.032608 | loop7: device node name blacklisted 408s 53.032674 | dm-0: device node name blacklisted 408s 53.033459 | multipath-tools v0.9.4 (12/19, 2022) 408s 53.033483 | libdevmapper version 1.02.185 408s 53.033657 | kernel device mapper v4.48.0 408s 53.033681 | DM multipath kernel driver v1.14.0 408s 53.033798 | sda: size = 204800 408s 53.033811 | sda: vendor = IET 408s 53.033812 | sda: product = VIRTUAL-DISK 408s 53.033814 | sda: rev = 0001 408s 53.034653 | sda: h:b:t:l = 0:0:0:1 408s 53.034768 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 53.034790 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 53.034793 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 53.034806 | sda: serial = beaf11 408s 53.034913 | sda: tur state = up 408s 53.034925 | sda: uid = 360000000000000000e00000000010001 (udev) 408s 53.034927 | sda: detect_prio = yes (setting: multipath internal) 408s 53.034930 | sda: prio = const (setting: multipath internal) 408s 53.034931 | sda: prio args = "" (setting: multipath internal) 408s 53.034933 | sda: const prio = 1 408s 53.034951 | sdc: size = 204800 408s 53.034956 | sdc: vendor = IET 408s 53.034958 | sdc: product = VIRTUAL-DISK 408s 53.034960 | sdc: rev = 0001 408s 53.035797 | sdc: h:b:t:l = 2:0:0:1 408s 53.035896 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 53.035916 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 53.035919 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 53.035930 | sdc: serial = beaf11 408s 53.036075 | sdc: tur state = up 408s 53.036085 | sdc: uid = 360000000000000000e00000000010001 (udev) 408s 53.036087 | sdc: detect_prio = yes (setting: multipath internal) 408s 53.036088 | sdc: prio = const (setting: multipath internal) 408s 53.036090 | sdc: prio args = "" (setting: multipath internal) 408s 53.036096 | sdc: const prio = 1 408s 53.036110 | sdb: size = 204800 408s 53.036113 | sdb: vendor = IET 408s 53.036115 | sdb: product = VIRTUAL-DISK 408s 53.036117 | sdb: rev = 0001 408s 53.036878 | sdb: h:b:t:l = 1:0:0:1 408s 53.036976 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 53.036993 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 53.036995 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 53.037005 | sdb: serial = beaf11 408s 53.037130 | sdb: tur state = up 408s 53.037139 | sdb: uid = 360000000000000000e00000000010001 (udev) 408s 53.037140 | sdb: detect_prio = yes (setting: multipath internal) 408s 53.037142 | sdb: prio = const (setting: multipath internal) 408s 53.037144 | sdb: prio args = "" (setting: multipath internal) 408s 53.037145 | sdb: const prio = 1 408s 53.037158 | sdd: size = 204800 408s 53.037162 | sdd: vendor = IET 408s 53.037166 | sdd: product = VIRTUAL-DISK 408s 53.037170 | sdd: rev = 0001 408s 53.037989 | sdd: h:b:t:l = 3:0:0:1 408s 53.038161 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 408s 53.038192 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 408s 53.038195 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 408s 53.038210 | sdd: serial = beaf11 408s 53.038406 | sdd: tur state = up 408s 53.038420 | sdd: uid = 360000000000000000e00000000010001 (udev) 408s 53.038423 | sdd: detect_prio = yes (setting: multipath internal) 408s 53.038425 | sdd: prio = const (setting: multipath internal) 408s 53.038427 | sdd: prio args = "" (setting: multipath internal) 408s 53.038429 | sdd: const prio = 1 408s 53.039201 | unloading tur checker 408s 53.039239 | unloading const prioritizer 408s + dmsetup table 408s + echo Test WWN should now point to DM 408s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 408s + grep dm 408s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 408s mke2fs 1.47.1 (20-May-2024) 408s ===== paths list ===== 408s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 408s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK unknown 408s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 408s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 408s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 408s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 408s size=100M features='0' hwhandler='0' wp=rw 408s |-+- policy='service-time 0' prio=1 status=active 408s | `- 0:0:0:1 sda 8:0 active ready running 408s |-+- policy='service-time 0' prio=1 status=enabled 408s | `- 2:0:0:1 sdc 8:32 active ready running 408s |-+- policy='service-time 0' prio=1 status=enabled 408s | `- 1:0:0:1 sdb 8:16 active ready running 408s `-+- policy='service-time 0' prio=1 status=enabled 408s `- 3:0:0:1 sdd 8:48 active ready running 408s mpatha: 0 204800 multipath 0 0 4 1 service-time 0 1 2 8:0 1 1 service-time 0 1 2 8:32 1 1 service-time 0 1 2 8:16 1 1 service-time 0 1 2 8:48 1 1 408s Test WWN should now point to DM 408s ../../dm-0 408s Creating filesystem with 25600 4k blocks and 25600 inodes 408s 408s Allocating group tables: 0/1 done 408s Writing inode tables: 0/1 done 408s Creating journal (1024 blocks): done 408s Writing superblocks and filesystem accounting information: 0/1 done 408s 408s + udevadm settle 408s + sleep 3s 411s + mkdir -p /mnt/tgtmpathtest 411s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 411s + cat 411s + cat 411s + fio --max-jobs=4 /tmp/autopkgtest.rQ8TQq/tgtbasedmpaths-artifacts/path-change-prep.fio 411s 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 411s fio-3.37 411s Starting 1 thread 411s write-phase: Laying out IO file (1 file / 17592186044415MiB) 412s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91750400, buflen=65536 412s 412s write-phase: (groupid=0, jobs=1): err= 0: pid=4931: Sat Jul 13 00:57:57 2024 412s write: IOPS=2575, BW=161MiB/s (169MB/s)(87.5MiB/544msec); 0 zone resets 412s clat (usec): min=216, max=10254, avg=372.81, stdev=291.81 412s lat (usec): min=227, max=10266, avg=386.43, stdev=292.10 412s clat percentiles (usec): 412s | 1.00th=[ 231], 5.00th=[ 251], 10.00th=[ 269], 20.00th=[ 297], 412s | 30.00th=[ 314], 40.00th=[ 334], 50.00th=[ 355], 60.00th=[ 375], 412s | 70.00th=[ 400], 80.00th=[ 429], 90.00th=[ 465], 95.00th=[ 502], 412s | 99.00th=[ 586], 99.50th=[ 611], 99.90th=[ 3884], 99.95th=[10290], 412s | 99.99th=[10290] 412s bw ( KiB/s): min=165504, max=165504, per=100.00%, avg=165504.00, stdev= 0.00, samples=1 412s iops : min= 2586, max= 2586, avg=2586.00, stdev= 0.00, samples=1 412s lat (usec) : 250=4.85%, 500=89.94%, 750=4.85%, 1000=0.07% 412s lat (msec) : 2=0.07%, 4=0.07%, 20=0.07% 412s cpu : usr=4.05%, sys=7.73%, ctx=1404, majf=0, minf=0 412s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 412s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 412s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 412s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 412s latency : target=0, window=0, percentile=100.00%, depth=1 412s 412s Run status group 0 (all jobs): 412s WRITE: bw=161MiB/s (169MB/s), 161MiB/s-161MiB/s (169MB/s-169MB/s), io=87.5MiB (91.8MB), run=544-544msec 412s 412s Disk stats (read/write): 412s dm-0: ios=1/988, sectors=8/126464, merge=0/0, ticks=0/351, in_queue=352, util=81.14%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/119, aggrin_queue=119, aggrutil=83.46% 412s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 412s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 412s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 412s sda: ios=1/1402, sectors=8/179280, merge=0/0, ticks=1/479, in_queue=479, util=83.46% 412s Starting the path changes in background 412s + echo Starting the path changes in background 412s + date +Pre FIO %H:%M:%S.%N 412s Pre FIO 00:57:57.215257557 412s + fio --max-jobs=4 /tmp/autopkgtest.rQ8TQq/tgtbasedmpaths-artifacts/path-change-check.fio 412s 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 412s fio-3.37 412s Starting 1 thread 592s 592s verify-phase: (groupid=0, jobs=1): err= 0: pid=4942: Sat Jul 13 01:00:57 2024 592s read: IOPS=4628, BW=289MiB/s (303MB/s)(50.9GiB/180001msec) 592s clat (usec): min=72, max=163073, avg=194.29, stdev=398.17 592s lat (usec): min=72, max=163074, avg=194.38, stdev=398.18 592s clat percentiles (usec): 592s | 1.00th=[ 91], 5.00th=[ 102], 10.00th=[ 114], 20.00th=[ 131], 592s | 30.00th=[ 149], 40.00th=[ 165], 50.00th=[ 180], 60.00th=[ 196], 592s | 70.00th=[ 215], 80.00th=[ 237], 90.00th=[ 269], 95.00th=[ 297], 592s | 99.00th=[ 404], 99.50th=[ 523], 99.90th=[ 2057], 99.95th=[ 3752], 592s | 99.99th=[ 9110] 592s bw ( KiB/s): min=41088, max=466576, per=100.00%, avg=296637.79, stdev=49237.44, samples=359 592s iops : min= 642, max= 7290, avg=4634.90, stdev=769.33, samples=359 592s lat (usec) : 100=3.99%, 250=81.11%, 500=14.35%, 750=0.26%, 1000=0.08% 592s lat (msec) : 2=0.11%, 4=0.06%, 10=0.04%, 20=0.01%, 50=0.01% 592s lat (msec) : 100=0.01%, 250=0.01% 592s cpu : usr=10.29%, sys=8.22%, ctx=833363, majf=0, minf=16 592s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 592s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 592s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 592s issued rwts: total=833220,0,0,0 short=0,0,0,0 dropped=0,0,0,0 592s latency : target=0, window=0, percentile=100.00%, depth=1 592s 592s Run status group 0 (all jobs): 592s READ: bw=289MiB/s (303MB/s), 289MiB/s-289MiB/s (303MB/s-303MB/s), io=50.9GiB (54.6GB), run=180001-180001msec 592s 592s Disk stats (read/write): 592s dm-0: ios=833462/10, sectors=106602976/12928, merge=0/9, ticks=164218/97, in_queue=164379, util=100.00%, aggrios=55412/2, aggsectors=7086616/3232, aggrmerge=0/0, aggrticks=10264/8, aggrin_queue=10272, aggrutil=99.19% 592s sdd: ios=95354/5, sectors=12196608/56, merge=0/0, ticks=16097/2, in_queue=16099, util=39.03% 592s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 592s sdc: ios=86251/0, sectors=11028064/0, merge=0/0, ticks=16749/0, in_queue=16749, util=66.43% 592s sda: ios=40044/4, sectors=5121792/12872, merge=0/0, ticks=8210/30, in_queue=8242, util=99.19% 592s + date +Post FIO %H:%M:%S.%N 592s Post FIO 01:00:57.501580739 592s FIO verify test with changing paths - OK 592s Report log of background activity 592s + echo FIO verify test with changing paths - OK 592s + echo Report log of background activity 592s + cat /tmp/autopkgtest.rQ8TQq/tgtbasedmpaths-artifacts/test-background.log 592s + iscsiadm --mode session 592s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s + sleep 10s 592s + date +MP report (expect 4) %H:%M:%S.%N 592s MP report (expect 4) 00:58:07.224013145 592s + multipath -ll 592s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 592s size=100M features='0' hwhandler='0' wp=rw 592s |-+- policy='service-time 0' prio=1 status=active 592s | `- 0:0:0:1 sda 8:0 active ready running 592s |-+- policy='service-time 0' prio=1 status=enabled 592s | `- 2:0:0:1 sdc 8:32 active ready running 592s |-+- policy='service-time 0' prio=1 status=enabled 592s | `- 1:0:0:1 sdb 8:16 active ready running 592s `-+- policy='service-time 0' prio=1 status=enabled 592s `- 3:0:0:1 sdd 8:48 active ready running 592s + date +UN-plug path 1 %H:%M:%S.%N 592s UN-plug path 1 00:58:07.248336144 592s + iscsiadm --mode session -r 1 -u 592s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 592s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 592s + iscsiadm --mode session 592s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s + sleep 10s 592s + date +MP report (expect 3) %H:%M:%S.%N 592s MP report (expect 3) 00:58:17.442259957 592s + multipath -ll 592s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 592s size=100M features='0' hwhandler='0' wp=rw 592s |-+- policy='service-time 0' prio=1 status=active 592s | `- 2:0:0:1 sdc 8:32 active ready running 592s |-+- policy='service-time 0' prio=1 status=enabled 592s | `- 1:0:0:1 sdb 8:16 active ready running 592s `-+- policy='service-time 0' prio=1 status=enabled 592s `- 3:0:0:1 sdd 8:48 active ready running 592s + date +UN-plug path 2 %H:%M:%S.%N 592s UN-plug path 2 00:58:17.462317333 592s + iscsiadm --mode session -r 2 -u 592s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 592s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 592s + iscsiadm --mode session 592s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s + sleep 10s 592s + date +MP report (expect 2) %H:%M:%S.%N 592s MP report (expect 2) 00:58:27.679588533 592s + multipath -ll 592s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 592s size=100M features='0' hwhandler='0' wp=rw 592s |-+- policy='service-time 0' prio=1 status=active 592s | `- 2:0:0:1 sdc 8:32 active ready running 592s `-+- policy='service-time 0' prio=1 status=enabled 592s `- 3:0:0:1 sdd 8:48 active ready running 592s + date +UN-plug path 3 %H:%M:%S.%N 592s UN-plug path 3 00:58:27.695042959 592s + iscsiadm --mode session -r 3 -u 592s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 592s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 592s + iscsiadm --mode session 592s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s + sleep 10s 592s + date +MP report (expect 1) %H:%M:%S.%N 592s MP report (expect 1) 00:58:37.842392452 592s + multipath -ll 592s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 592s size=100M features='0' hwhandler='0' wp=rw 592s `-+- policy='service-time 0' prio=1 status=active 592s `- 3:0:0:1 sdd 8:48 active ready running 592s + date +Add paths 5/6/7/8 %H:%M:%S.%N 592s Add paths 5/6/7/8 00:58:37.857077140 592s + iscsiadm --mode session -r 4 --op new 592s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 592s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 592s + iscsiadm --mode session -r 4 --op new 592s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 592s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 592s + iscsiadm --mode session -r 4 --op new 592s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 592s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 592s + iscsiadm --mode session -r 4 --op new 592s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 592s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 592s + iscsiadm --mode session 592s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s + sleep 10s 592s + date +MP report (expect 5) %H:%M:%S.%N 592s MP report (expect 5) 00:58:47.948529114 592s + multipath -ll 592s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 592s size=100M features='0' hwhandler='0' wp=rw 592s |-+- policy='service-time 0' prio=1 status=active 592s | `- 3:0:0:1 sdd 8:48 active ready running 592s |-+- policy='service-time 0' prio=1 status=enabled 592s | `- 0:0:0:1 sda 8:0 active ready running 592s |-+- policy='service-time 0' prio=1 status=enabled 592s | `- 1:0:0:1 sdb 8:16 active ready running 592s |-+- policy='service-time 0' prio=1 status=enabled 592s | `- 2:0:0:1 sdc 8:32 active ready running 592s `-+- policy='service-time 0' prio=1 status=enabled 592s `- 4:0:0:1 sde 8:64 active ready running 592s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 592s UN-plug multiple paths 4/7/8 00:58:47.972065430 592s + iscsiadm --mode session -r 4 -u 592s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 592s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 592s + iscsiadm --mode session -r 7 -u 592s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 592s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 592s + iscsiadm --mode session -r 8 -u 592s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 592s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 592s + iscsiadm --mode session 592s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 592s + sleep 10s 592s + date +Restart multipath daemon %H:%M:%S.%N 592s Restart multipath daemon 00:58:58.480948722 592s + systemctl restart multipathd 592s + sleep 10s 592s + date +Final background report (expect 2) %H:%M:%S.%N 592s Final background report (expect 2) 00:59:08.578282841 592s + multipath -ll 592s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 592s size=100M features='0' hwhandler='0' wp=rw 592s |-+- policy='service-time 0' prio=1 status=active 592s | `- 0:0:0:1 sda 8:0 active ready running 592s `-+- policy='service-time 0' prio=1 status=enabled 592s `- 1:0:0:1 sdb 8:16 active ready running 592s Final stats 592s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 592s iSCSI SNMP: 592s txdata_octets: 29403432 592s rxdata_octets: 40120221076 592s noptx_pdus: 0 592s scsicmd_pdus: 612304 592s tmfcmd_pdus: 0 592s login_pdus: 0 592s text_pdus: 0 592s dataout_pdus: 0 592s logout_pdus: 0 592s snack_pdus: 0 592s noprx_pdus: 0 592s scsirsp_pdus: 612304 592s tmfrsp_pdus: 0 592s textrsp_pdus: 0 592s datain_pdus: 612271 592s logoutrsp_pdus: 0 592s r2t_pdus: 0 592s async_pdus: 0 592s rjt_pdus: 0 592s digest_err: 0 592s timeout_err: 0 592s iSCSI Extended: 592s tx_sendpage_failures: 0 592s rx_discontiguous_hdr: 0 592s eh_abort_cnt: 0 592s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 592s iSCSI SNMP: 592s txdata_octets: 7896 592s rxdata_octets: 1090372 592s noptx_pdus: 0 592s scsicmd_pdus: 135 592s tmfcmd_pdus: 0 592s login_pdus: 0 592s text_pdus: 0 592s dataout_pdus: 0 592s logout_pdus: 0 592s snack_pdus: 0 592s noprx_pdus: 0 592s scsirsp_pdus: 135 592s tmfrsp_pdus: 0 592s textrsp_pdus: 0 592s datain_pdus: 113 592s logoutrsp_pdus: 0 592s r2t_pdus: 0 592s async_pdus: 0 592s rjt_pdus: 0 592s digest_err: 0 592s timeout_err: 0 592s iSCSI Extended: 592s tx_sendpage_failures: 0 592s rx_discontiguous_hdr: 0 592s eh_abort_cnt: 0 592s + sync 592s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 592s + echo Final stats 592s + iscsiadm --mode session --stats 592s + journalctl --no-pager -u multipathd 592s + echo Check final path status 592s + multipath -ll 592s + multipath -ll 592s + grep --count status= 592s + diskc=2 592s + multipath -ll 592s + grep --count status=active 592s + diska=1 592s + multipath -ll 592s + grep --count status=enabled 592s Jul 11 13:41:06 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 592s Jul 11 13:41:07 ubuntu multipathd[359]: multipathd v0.9.4: start up 592s Jul 11 13:41:07 ubuntu multipathd[359]: reconfigure: setting up paths and maps 592s Jul 11 13:41:07 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 592s Jul 11 13:43:16 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 multipathd[359]: multipathd: shut down 592s Jul 11 13:43:16 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 592s Jul 11 13:43:16 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 systemd[1]: multipathd.service: Deactivated successfully. 592s Jul 11 13:43:16 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 592s -- Boot 4a2f5e5ec0d44d209bd8e16997377dcd -- 592s Jul 11 13:43:19 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 592s Jul 11 13:43:20 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 multipathd[312]: multipathd v0.9.4: start up 592s Jul 11 13:43:20 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 multipathd[312]: reconfigure: setting up paths and maps 592s Jul 11 13:43:20 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 592s Jul 11 13:43:45 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 multipathd[312]: multipathd: shut down 592s Jul 11 13:43:45 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 592s Jul 11 13:43:45 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 systemd[1]: multipathd.service: Deactivated successfully. 592s Jul 11 13:43:45 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 592s -- Boot 59c4da30489442beaf87dedc94666de7 -- 592s Jul 13 00:55:23 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 592s Jul 13 00:55:23 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 multipathd[366]: multipathd v0.9.4: start up 592s Jul 13 00:55:23 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 multipathd[366]: reconfigure: setting up paths and maps 592s Jul 13 00:55:23 ubuntuubuntu-oracular-daily-s390x-server-20240626-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 592s Jul 13 00:56:59 autopkgtest multipathd[366]: multipathd: shut down 592s Jul 13 00:56:59 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 592s Jul 13 00:56:59 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 592s Jul 13 00:56:59 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 592s -- Boot 8744dd300d8647fd9d9a0a03a375634f -- 592s Jul 13 00:57:01 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 592s Jul 13 00:57:01 autopkgtest multipathd[375]: multipathd v0.9.4: start up 592s Jul 13 00:57:01 autopkgtest multipathd[375]: reconfigure: setting up paths and maps 592s Jul 13 00:57:01 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 592s Jul 13 00:57:48 autopkgtest multipathd[375]: mpatha: addmap [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:32 1] 592s Jul 13 00:57:48 autopkgtest multipathd[375]: sdc [8:32]: path added to devmap mpatha 592s Jul 13 00:57:48 autopkgtest multipathd[375]: mpatha: performing delayed actions 592s Jul 13 00:57:48 autopkgtest multipathd[375]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:48 1] 592s Jul 13 00:58:07 autopkgtest multipathd[375]: sda: mark as failed 592s Jul 13 00:58:07 autopkgtest multipathd[375]: mpatha: remaining active paths: 3 592s Jul 13 00:58:07 autopkgtest multipathd[375]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:48 1] 592s Jul 13 00:58:07 autopkgtest multipathd[375]: check_removed_paths: sda: freeing path in removed state 592s Jul 13 00:58:07 autopkgtest multipathd[375]: 8:0: path removed from map mpatha 592s Jul 13 00:58:17 autopkgtest multipathd[375]: 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] 592s Jul 13 00:58:17 autopkgtest multipathd[375]: check_removed_paths: sdb: freeing path in removed state 592s Jul 13 00:58:17 autopkgtest multipathd[375]: 8:16: path removed from map mpatha 592s Jul 13 00:58:27 autopkgtest multipathd[375]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 592s Jul 13 00:58:27 autopkgtest multipathd[375]: check_removed_paths: sdc: freeing path in removed state 592s Jul 13 00:58:27 autopkgtest multipathd[375]: 8:32: path removed from map mpatha 592s Jul 13 00:58:37 autopkgtest multipathd[375]: 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] 592s Jul 13 00:58:38 autopkgtest multipathd[375]: sda [8:0]: path added to devmap mpatha 592s Jul 13 00:58:38 autopkgtest multipathd[375]: 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] 592s Jul 13 00:58:38 autopkgtest multipathd[375]: sdb [8:16]: path added to devmap mpatha 592s Jul 13 00:58:38 autopkgtest multipathd[375]: 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] 592s Jul 13 00:58:38 autopkgtest multipathd[375]: sdc [8:32]: path added to devmap mpatha 592s Jul 13 00:58:38 autopkgtest multipathd[375]: 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] 592s Jul 13 00:58:38 autopkgtest multipathd[375]: sde [8:64]: path added to devmap mpatha 592s Jul 13 00:58:48 autopkgtest multipathd[375]: 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] 592s Jul 13 00:58:48 autopkgtest multipathd[375]: check_removed_paths: sdd: freeing path in removed state 592s Jul 13 00:58:48 autopkgtest multipathd[375]: 8:48: path removed from map mpatha 592s Jul 13 00:58:48 autopkgtest multipathd[375]: 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] 592s Jul 13 00:58:48 autopkgtest multipathd[375]: check_removed_paths: sdc: freeing path in removed state 592s Jul 13 00:58:48 autopkgtest multipathd[375]: 8:32: path removed from map mpatha 592s Jul 13 00:58:48 autopkgtest multipathd[375]: 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] 592s Jul 13 00:58:48 autopkgtest multipathd[375]: check_removed_paths: sde: freeing path in removed state 592s Jul 13 00:58:48 autopkgtest multipathd[375]: 8:64: path removed from map mpatha 592s Jul 13 00:58:58 autopkgtest multipathd[375]: multipathd: shut down 592s Jul 13 00:58:58 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 592s Jul 13 00:58:58 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 592s Jul 13 00:58:58 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 592s Jul 13 00:58:58 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 592s Jul 13 00:58:58 autopkgtest multipathd[5276]: multipathd v0.9.4: start up 592s Jul 13 00:58:58 autopkgtest multipathd[5276]: reconfigure: setting up paths and maps 592s Jul 13 00:58:58 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 592s Check final path status 592s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 592s size=100M features='0' hwhandler='0' wp=rw 592s |-+- policy='service-time 0' prio=1 status=active 592s | `- 0:0:0:1 sda 8:0 active ready running 592s `-+- policy='service-time 0' prio=1 status=enabled 592s `- 1:0:0:1 sdb 8:16 active ready running 592s + diske=1 592s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 592s + echo OK 592s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 592s OK 592s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 592s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 592s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 592s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 592s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 593s autopkgtest [01:00:58]: test tgtbasedmpaths: -----------------------] 593s tgtbasedmpaths PASS 593s autopkgtest [01:00:58]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 594s autopkgtest [01:00:59]: @@@@@@@@@@@@@@@@@@@@ summary 594s kpartx-file-loopback PASS 594s tgtbasedmpaths PASS 608s nova [W] Using flock in scalingstack-bos01-s390x 608s Creating nova instance adt-oracular-s390x-multipath-tools-20240713-005105-juju-7f2275-prod-proposed-migration-environment-3-67e9df6d-4f8b-4c90-b56a-e56e14e8d9e3 from image adt/ubuntu-oracular-s390x-server-20240711.img (UUID cd7d8501-1120-4d80-87a5-5946a33c5d4a)... 608s nova [W] Using flock in scalingstack-bos01-s390x 608s Creating nova instance adt-oracular-s390x-multipath-tools-20240713-005105-juju-7f2275-prod-proposed-migration-environment-3-67e9df6d-4f8b-4c90-b56a-e56e14e8d9e3 from image adt/ubuntu-oracular-s390x-server-20240711.img (UUID cd7d8501-1120-4d80-87a5-5946a33c5d4a)...