1s autopkgtest [17:14:56]: starting date and time: 2024-07-12 17:14:56+0000 1s autopkgtest [17:14:56]: git checkout: fd3bed09 nova: allow more retries for quota issues 1s autopkgtest [17:14:56]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.scmz6r4f/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@lcy02-2.secgroup --name adt-oracular-amd64-multipath-tools-20240712-171455-juju-7f2275-prod-proposed-migration-environment-3-0a5b088a-8665-4357-9dbb-8906b3dbe003 --image adt/ubuntu-oracular-amd64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 132s autopkgtest [17:17:05]: testbed dpkg architecture: amd64 142s autopkgtest [17:17:17]: testbed apt version: 2.9.6 142s autopkgtest [17:17:17]: @@@@@@@@@@@@@@@@@@@@ test bed setup 144s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 144s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [334 kB] 144s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [46.6 kB] 144s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 144s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 144s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main i386 Packages [70.9 kB] 144s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 Packages [98.2 kB] 144s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 c-n-f Metadata [2104 B] 144s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted amd64 Packages [34.9 kB] 144s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/restricted i386 Packages [6244 B] 144s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/restricted amd64 c-n-f Metadata [368 B] 144s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/universe i386 Packages [224 kB] 144s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/universe amd64 Packages [368 kB] 144s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/universe amd64 c-n-f Metadata [9228 B] 144s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse i386 Packages [3052 B] 144s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse amd64 Packages [7644 B] 144s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse amd64 c-n-f Metadata [276 B] 146s Fetched 1342 kB in 0s (5029 kB/s) 146s Reading package lists... 159s Reading package lists... 159s Building dependency tree... 159s Reading state information... 160s Calculating upgrade... 160s The following packages will be upgraded: 160s binutils binutils-common binutils-x86-64-linux-gnu gir1.2-glib-2.0 160s inetutils-telnet libbinutils libc-bin libc-dev-bin libc-devtools libc6 160s libc6-dev libctf-nobfd0 libctf0 libglib2.0-0t64 libglib2.0-data libgprofng0 160s libnghttp2-14 libnss3 libsframe1 libssl3t64 locales openssh-client 160s openssh-server openssh-sftp-server openssl telnet 160s 26 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 160s Need to get 22.8 MB of archives. 160s After this operation, 444 kB of additional disk space will be used. 160s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 libc-devtools amd64 2.39-3.1ubuntu3 [29.3 kB] 160s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 libc6-dev amd64 2.39-3.1ubuntu3 [2120 kB] 160s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 libc-dev-bin amd64 2.39-3.1ubuntu3 [20.4 kB] 160s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 libc6 amd64 2.39-3.1ubuntu3 [3262 kB] 160s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 libc-bin amd64 2.39-3.1ubuntu3 [680 kB] 160s Get:6 http://ftpmaster.internal/ubuntu oracular/main amd64 libssl3t64 amd64 3.2.2-1ubuntu1 [2138 kB] 160s Get:7 http://ftpmaster.internal/ubuntu oracular/main amd64 openssh-sftp-server amd64 1:9.6p1-3ubuntu17 [37.1 kB] 160s Get:8 http://ftpmaster.internal/ubuntu oracular/main amd64 openssh-server amd64 1:9.6p1-3ubuntu17 [509 kB] 160s Get:9 http://ftpmaster.internal/ubuntu oracular/main amd64 openssh-client amd64 1:9.6p1-3ubuntu17 [905 kB] 160s Get:10 http://ftpmaster.internal/ubuntu oracular/main amd64 gir1.2-glib-2.0 amd64 2.80.4-1ubuntu1 [182 kB] 160s Get:11 http://ftpmaster.internal/ubuntu oracular/main amd64 libglib2.0-0t64 amd64 2.80.4-1ubuntu1 [1545 kB] 160s Get:12 http://ftpmaster.internal/ubuntu oracular/main amd64 libglib2.0-data all 2.80.4-1ubuntu1 [49.3 kB] 160s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 locales all 2.39-3.1ubuntu3 [4220 kB] 160s Get:14 http://ftpmaster.internal/ubuntu oracular/main amd64 openssl amd64 3.2.2-1ubuntu1 [1122 kB] 160s Get:15 http://ftpmaster.internal/ubuntu oracular/main amd64 inetutils-telnet amd64 2:2.5-5ubuntu1 [105 kB] 160s Get:16 http://ftpmaster.internal/ubuntu oracular/main amd64 libnghttp2-14 amd64 1.62.1-2 [75.1 kB] 160s Get:17 http://ftpmaster.internal/ubuntu oracular/main amd64 telnet all 0.17+2.5-5ubuntu1 [3688 B] 160s Get:18 http://ftpmaster.internal/ubuntu oracular/main amd64 libgprofng0 amd64 2.42.50.20240710-1ubuntu1 [860 kB] 160s Get:19 http://ftpmaster.internal/ubuntu oracular/main amd64 libctf0 amd64 2.42.50.20240710-1ubuntu1 [95.6 kB] 160s Get:20 http://ftpmaster.internal/ubuntu oracular/main amd64 libctf-nobfd0 amd64 2.42.50.20240710-1ubuntu1 [97.6 kB] 160s Get:21 http://ftpmaster.internal/ubuntu oracular/main amd64 binutils-x86-64-linux-gnu amd64 2.42.50.20240710-1ubuntu1 [2477 kB] 160s Get:22 http://ftpmaster.internal/ubuntu oracular/main amd64 libbinutils amd64 2.42.50.20240710-1ubuntu1 [574 kB] 160s Get:23 http://ftpmaster.internal/ubuntu oracular/main amd64 binutils amd64 2.42.50.20240710-1ubuntu1 [18.1 kB] 160s Get:24 http://ftpmaster.internal/ubuntu oracular/main amd64 binutils-common amd64 2.42.50.20240710-1ubuntu1 [243 kB] 160s Get:25 http://ftpmaster.internal/ubuntu oracular/main amd64 libsframe1 amd64 2.42.50.20240710-1ubuntu1 [14.4 kB] 160s Get:26 http://ftpmaster.internal/ubuntu oracular/main amd64 libnss3 amd64 2:3.102-1 [1399 kB] 161s Preconfiguring packages ... 161s Fetched 22.8 MB in 0s (93.6 MB/s) 161s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 74487 files and directories currently installed.) 161s Preparing to unpack .../libc-devtools_2.39-3.1ubuntu3_amd64.deb ... 161s Unpacking libc-devtools (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 161s Preparing to unpack .../libc6-dev_2.39-3.1ubuntu3_amd64.deb ... 161s Unpacking libc6-dev:amd64 (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 161s Preparing to unpack .../libc-dev-bin_2.39-3.1ubuntu3_amd64.deb ... 161s Unpacking libc-dev-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 161s Preparing to unpack .../libc6_2.39-3.1ubuntu3_amd64.deb ... 162s Unpacking libc6:amd64 (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 162s Setting up libc6:amd64 (2.39-3.1ubuntu3) ... 162s Error: Could not restart systemd, systemd binary not working 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 ... 74487 files and directories currently installed.) 162s Preparing to unpack .../libc-bin_2.39-3.1ubuntu3_amd64.deb ... 162s Unpacking libc-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 162s Setting up libc-bin (2.39-3.1ubuntu3) ... 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 ... 74487 files and directories currently installed.) 162s Preparing to unpack .../libssl3t64_3.2.2-1ubuntu1_amd64.deb ... 162s Unpacking libssl3t64:amd64 (3.2.2-1ubuntu1) over (3.2.1-3ubuntu1) ... 162s Setting up libssl3t64:amd64 (3.2.2-1ubuntu1) ... 163s (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 ... 74487 files and directories currently installed.) 163s Preparing to unpack .../00-openssh-sftp-server_1%3a9.6p1-3ubuntu17_amd64.deb ... 163s Unpacking openssh-sftp-server (1:9.6p1-3ubuntu17) over (1:9.6p1-3ubuntu15) ... 163s Preparing to unpack .../01-openssh-server_1%3a9.6p1-3ubuntu17_amd64.deb ... 163s Unpacking openssh-server (1:9.6p1-3ubuntu17) over (1:9.6p1-3ubuntu15) ... 163s Preparing to unpack .../02-openssh-client_1%3a9.6p1-3ubuntu17_amd64.deb ... 163s Unpacking openssh-client (1:9.6p1-3ubuntu17) over (1:9.6p1-3ubuntu15) ... 163s Preparing to unpack .../03-gir1.2-glib-2.0_2.80.4-1ubuntu1_amd64.deb ... 163s Unpacking gir1.2-glib-2.0:amd64 (2.80.4-1ubuntu1) over (2.80.3-1ubuntu1) ... 163s Preparing to unpack .../04-libglib2.0-0t64_2.80.4-1ubuntu1_amd64.deb ... 163s Unpacking libglib2.0-0t64:amd64 (2.80.4-1ubuntu1) over (2.80.3-1ubuntu1) ... 163s Preparing to unpack .../05-libglib2.0-data_2.80.4-1ubuntu1_all.deb ... 163s Unpacking libglib2.0-data (2.80.4-1ubuntu1) over (2.80.3-1ubuntu1) ... 163s Preparing to unpack .../06-locales_2.39-3.1ubuntu3_all.deb ... 163s Unpacking locales (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 163s Preparing to unpack .../07-openssl_3.2.2-1ubuntu1_amd64.deb ... 163s Unpacking openssl (3.2.2-1ubuntu1) over (3.2.1-3ubuntu1) ... 163s Preparing to unpack .../08-inetutils-telnet_2%3a2.5-5ubuntu1_amd64.deb ... 163s Unpacking inetutils-telnet (2:2.5-5ubuntu1) over (2:2.5-3ubuntu4) ... 163s Preparing to unpack .../09-libnghttp2-14_1.62.1-2_amd64.deb ... 163s Unpacking libnghttp2-14:amd64 (1.62.1-2) over (1.62.1-1) ... 164s Preparing to unpack .../10-telnet_0.17+2.5-5ubuntu1_all.deb ... 164s Unpacking telnet (0.17+2.5-5ubuntu1) over (0.17+2.5-3ubuntu4) ... 164s Preparing to unpack .../11-libgprofng0_2.42.50.20240710-1ubuntu1_amd64.deb ... 164s Unpacking libgprofng0:amd64 (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 164s Preparing to unpack .../12-libctf0_2.42.50.20240710-1ubuntu1_amd64.deb ... 164s Unpacking libctf0:amd64 (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 164s Preparing to unpack .../13-libctf-nobfd0_2.42.50.20240710-1ubuntu1_amd64.deb ... 164s Unpacking libctf-nobfd0:amd64 (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 164s Preparing to unpack .../14-binutils-x86-64-linux-gnu_2.42.50.20240710-1ubuntu1_amd64.deb ... 164s Unpacking binutils-x86-64-linux-gnu (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 164s Preparing to unpack .../15-libbinutils_2.42.50.20240710-1ubuntu1_amd64.deb ... 164s Unpacking libbinutils:amd64 (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 164s Preparing to unpack .../16-binutils_2.42.50.20240710-1ubuntu1_amd64.deb ... 164s Unpacking binutils (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 164s Preparing to unpack .../17-binutils-common_2.42.50.20240710-1ubuntu1_amd64.deb ... 164s Unpacking binutils-common:amd64 (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 164s Preparing to unpack .../18-libsframe1_2.42.50.20240710-1ubuntu1_amd64.deb ... 164s Unpacking libsframe1:amd64 (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 164s Preparing to unpack .../19-libnss3_2%3a3.102-1_amd64.deb ... 164s Unpacking libnss3:amd64 (2:3.102-1) over (2:3.101-1) ... 164s Setting up openssh-client (1:9.6p1-3ubuntu17) ... 164s Setting up binutils-common:amd64 (2.42.50.20240710-1ubuntu1) ... 164s Setting up libnghttp2-14:amd64 (1.62.1-2) ... 164s Setting up inetutils-telnet (2:2.5-5ubuntu1) ... 164s Setting up libctf-nobfd0:amd64 (2.42.50.20240710-1ubuntu1) ... 164s Setting up libnss3:amd64 (2:3.102-1) ... 164s Setting up locales (2.39-3.1ubuntu3) ... 165s Generating locales (this might take a while)... 167s en_US.UTF-8... done 167s Generation complete. 167s Setting up libsframe1:amd64 (2.42.50.20240710-1ubuntu1) ... 167s Setting up libglib2.0-0t64:amd64 (2.80.4-1ubuntu1) ... 167s No schema files found: doing nothing. 167s Setting up libglib2.0-data (2.80.4-1ubuntu1) ... 167s Setting up gir1.2-glib-2.0:amd64 (2.80.4-1ubuntu1) ... 167s Setting up libbinutils:amd64 (2.42.50.20240710-1ubuntu1) ... 167s Setting up libc-dev-bin (2.39-3.1ubuntu3) ... 167s Setting up openssl (3.2.2-1ubuntu1) ... 167s Installing new version of config file /etc/ssl/openssl.cnf ... 167s Setting up libc-devtools (2.39-3.1ubuntu3) ... 167s Setting up libctf0:amd64 (2.42.50.20240710-1ubuntu1) ... 167s Setting up openssh-sftp-server (1:9.6p1-3ubuntu17) ... 167s Setting up telnet (0.17+2.5-5ubuntu1) ... 167s Setting up openssh-server (1:9.6p1-3ubuntu17) ... 167s Installing new version of config file /etc/pam.d/sshd ... 168s Setting up libgprofng0:amd64 (2.42.50.20240710-1ubuntu1) ... 168s Setting up libc6-dev:amd64 (2.39-3.1ubuntu3) ... 168s Setting up binutils-x86-64-linux-gnu (2.42.50.20240710-1ubuntu1) ... 168s Setting up binutils (2.42.50.20240710-1ubuntu1) ... 168s Processing triggers for libc-bin (2.39-3.1ubuntu3) ... 168s Processing triggers for ufw (0.36.2-6) ... 168s Processing triggers for systemd (256-1ubuntu1) ... 169s Processing triggers for man-db (2.12.1-2) ... 171s Reading package lists... 171s Building dependency tree... 171s Reading state information... 172s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 172s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 172s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 172s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 172s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 174s Reading package lists... 174s Reading package lists... 174s Building dependency tree... 174s Reading state information... 175s Calculating upgrade... 175s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 175s Reading package lists... 175s Building dependency tree... 176s Reading state information... 176s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 179s autopkgtest [17:17:54]: rebooting testbed after setup commands that affected boot 237s autopkgtest [17:18:52]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP PREEMPT_DYNAMIC Sat Apr 20 00:40:06 UTC 2024 252s autopkgtest [17:19:07]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 270s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 270s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 270s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 270s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 270s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 270s gpgv: issuer "steve.langasek@ubuntu.com" 270s gpgv: Can't check signature: No public key 270s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 270s autopkgtest [17:19:25]: testing package multipath-tools version 0.9.4-5ubuntu8 271s autopkgtest [17:19:26]: build not needed 271s autopkgtest [17:19:26]: test kpartx-file-loopback: preparing testbed 357s Reading package lists... 357s Building dependency tree... 357s Reading state information... 357s Starting pkgProblemResolver with broken count: 0 357s Starting 2 pkgProblemResolver with broken count: 0 357s Done 357s The following additional packages will be installed: 357s liburing2 qemu-utils 357s Recommended packages: 357s qemu-block-extra 357s The following NEW packages will be installed: 357s autopkgtest-satdep liburing2 qemu-utils 357s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 357s Need to get 2240 kB/2241 kB of archives. 357s After this operation, 11.4 MB of additional disk space will be used. 357s Get:1 /tmp/autopkgtest.l7dREy/1-autopkgtest-satdep.deb autopkgtest-satdep amd64 0 [720 B] 357s Get:2 http://ftpmaster.internal/ubuntu oracular/main amd64 liburing2 amd64 2.6-1 [22.3 kB] 357s Get:3 http://ftpmaster.internal/ubuntu oracular/main amd64 qemu-utils amd64 1:8.2.2+ds-0ubuntu1 [2218 kB] 357s Fetched 2240 kB in 0s (32.7 MB/s) 357s Selecting previously unselected package liburing2:amd64. 357s (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 ... 74486 files and directories currently installed.) 357s Preparing to unpack .../liburing2_2.6-1_amd64.deb ... 357s Unpacking liburing2:amd64 (2.6-1) ... 357s Selecting previously unselected package qemu-utils. 357s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_amd64.deb ... 357s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 357s Selecting previously unselected package autopkgtest-satdep. 357s Preparing to unpack .../1-autopkgtest-satdep.deb ... 357s Unpacking autopkgtest-satdep (0) ... 357s Setting up liburing2:amd64 (2.6-1) ... 357s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 357s Setting up autopkgtest-satdep (0) ... 357s Processing triggers for man-db (2.12.1-2) ... 357s Processing triggers for libc-bin (2.39-3.1ubuntu3) ... 373s (Reading database ... 74506 files and directories currently installed.) 373s Removing autopkgtest-satdep (0) ... 383s autopkgtest [17:21:18]: test kpartx-file-loopback: [----------------------- 384s Formatting 'foo.img', fmt=raw size=20971520 385s Creating new GPT entries in memory. 385s Warning: The kernel is still using the old partition table. 385s The new table will be used at the next reboot or after you 385s run partprobe(8) or kpartx(8) 385s The operation has completed successfully. 385s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 385s standard_filename: OK 385s del devmap : loop0p1 385s No devices found 385s standard_filename_cleanup: OK 385s Formatting 'fou du FaFa.img', fmt=raw size=20971520 386s Creating new GPT entries in memory. 386s Warning: The kernel is still using the old partition table. 386s The new table will be used at the next reboot or after you 386s run partprobe(8) or kpartx(8) 386s The operation has completed successfully. 386s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 386s filename_with_spaces: OK 386s del devmap : loop0p1 386s No devices found 386s filename_with_spaces_cleanup: OK 386s autopkgtest [17:21:21]: test kpartx-file-loopback: -----------------------] 391s autopkgtest [17:21:26]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 391s kpartx-file-loopback PASS 396s autopkgtest [17:21:31]: test tgtbasedmpaths: preparing testbed 586s autopkgtest [17:24:41]: testbed dpkg architecture: amd64 586s autopkgtest [17:24:41]: testbed apt version: 2.9.6 586s autopkgtest [17:24:41]: @@@@@@@@@@@@@@@@@@@@ test bed setup 587s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 588s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 588s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [46.6 kB] 588s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [334 kB] 588s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 588s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main i386 Packages [70.9 kB] 588s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 Packages [98.2 kB] 588s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 c-n-f Metadata [2104 B] 588s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted i386 Packages [6244 B] 588s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/restricted amd64 Packages [34.9 kB] 588s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/restricted amd64 c-n-f Metadata [368 B] 588s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/universe amd64 Packages [368 kB] 588s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/universe i386 Packages [224 kB] 588s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/universe amd64 c-n-f Metadata [9228 B] 588s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse amd64 Packages [7644 B] 588s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse i386 Packages [3052 B] 588s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse amd64 c-n-f Metadata [276 B] 589s Fetched 1342 kB in 0s (5226 kB/s) 589s Reading package lists... 593s Reading package lists... 593s Building dependency tree... 593s Reading state information... 593s Calculating upgrade... 594s The following packages will be upgraded: 594s binutils binutils-common binutils-x86-64-linux-gnu gir1.2-glib-2.0 594s inetutils-telnet libbinutils libc-bin libc-dev-bin libc-devtools libc6 594s libc6-dev libctf-nobfd0 libctf0 libglib2.0-0t64 libglib2.0-data libgprofng0 594s libnghttp2-14 libnss3 libsframe1 libssl3t64 locales openssh-client 594s openssh-server openssh-sftp-server openssl telnet 594s 26 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 594s Need to get 22.8 MB of archives. 594s After this operation, 444 kB of additional disk space will be used. 594s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 libc-devtools amd64 2.39-3.1ubuntu3 [29.3 kB] 594s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 libc6-dev amd64 2.39-3.1ubuntu3 [2120 kB] 594s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 libc-dev-bin amd64 2.39-3.1ubuntu3 [20.4 kB] 594s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 libc6 amd64 2.39-3.1ubuntu3 [3262 kB] 594s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 libc-bin amd64 2.39-3.1ubuntu3 [680 kB] 594s Get:6 http://ftpmaster.internal/ubuntu oracular/main amd64 libssl3t64 amd64 3.2.2-1ubuntu1 [2138 kB] 594s Get:7 http://ftpmaster.internal/ubuntu oracular/main amd64 openssh-sftp-server amd64 1:9.6p1-3ubuntu17 [37.1 kB] 594s Get:8 http://ftpmaster.internal/ubuntu oracular/main amd64 openssh-server amd64 1:9.6p1-3ubuntu17 [509 kB] 594s Get:9 http://ftpmaster.internal/ubuntu oracular/main amd64 openssh-client amd64 1:9.6p1-3ubuntu17 [905 kB] 594s Get:10 http://ftpmaster.internal/ubuntu oracular/main amd64 gir1.2-glib-2.0 amd64 2.80.4-1ubuntu1 [182 kB] 594s Get:11 http://ftpmaster.internal/ubuntu oracular/main amd64 libglib2.0-0t64 amd64 2.80.4-1ubuntu1 [1545 kB] 594s Get:12 http://ftpmaster.internal/ubuntu oracular/main amd64 libglib2.0-data all 2.80.4-1ubuntu1 [49.3 kB] 594s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 locales all 2.39-3.1ubuntu3 [4220 kB] 594s Get:14 http://ftpmaster.internal/ubuntu oracular/main amd64 openssl amd64 3.2.2-1ubuntu1 [1122 kB] 594s Get:15 http://ftpmaster.internal/ubuntu oracular/main amd64 inetutils-telnet amd64 2:2.5-5ubuntu1 [105 kB] 594s Get:16 http://ftpmaster.internal/ubuntu oracular/main amd64 libnghttp2-14 amd64 1.62.1-2 [75.1 kB] 594s Get:17 http://ftpmaster.internal/ubuntu oracular/main amd64 telnet all 0.17+2.5-5ubuntu1 [3688 B] 594s Get:18 http://ftpmaster.internal/ubuntu oracular/main amd64 libgprofng0 amd64 2.42.50.20240710-1ubuntu1 [860 kB] 594s Get:19 http://ftpmaster.internal/ubuntu oracular/main amd64 libctf0 amd64 2.42.50.20240710-1ubuntu1 [95.6 kB] 594s Get:20 http://ftpmaster.internal/ubuntu oracular/main amd64 libctf-nobfd0 amd64 2.42.50.20240710-1ubuntu1 [97.6 kB] 594s Get:21 http://ftpmaster.internal/ubuntu oracular/main amd64 binutils-x86-64-linux-gnu amd64 2.42.50.20240710-1ubuntu1 [2477 kB] 594s Get:22 http://ftpmaster.internal/ubuntu oracular/main amd64 libbinutils amd64 2.42.50.20240710-1ubuntu1 [574 kB] 594s Get:23 http://ftpmaster.internal/ubuntu oracular/main amd64 binutils amd64 2.42.50.20240710-1ubuntu1 [18.1 kB] 594s Get:24 http://ftpmaster.internal/ubuntu oracular/main amd64 binutils-common amd64 2.42.50.20240710-1ubuntu1 [243 kB] 594s Get:25 http://ftpmaster.internal/ubuntu oracular/main amd64 libsframe1 amd64 2.42.50.20240710-1ubuntu1 [14.4 kB] 594s Get:26 http://ftpmaster.internal/ubuntu oracular/main amd64 libnss3 amd64 2:3.102-1 [1399 kB] 594s Preconfiguring packages ... 594s Fetched 22.8 MB in 0s (72.3 MB/s) 595s (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 ... 74487 files and directories currently installed.) 595s Preparing to unpack .../libc-devtools_2.39-3.1ubuntu3_amd64.deb ... 595s Unpacking libc-devtools (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 595s Preparing to unpack .../libc6-dev_2.39-3.1ubuntu3_amd64.deb ... 595s Unpacking libc6-dev:amd64 (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 595s Preparing to unpack .../libc-dev-bin_2.39-3.1ubuntu3_amd64.deb ... 595s Unpacking libc-dev-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 595s Preparing to unpack .../libc6_2.39-3.1ubuntu3_amd64.deb ... 595s Unpacking libc6:amd64 (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 595s Setting up libc6:amd64 (2.39-3.1ubuntu3) ... 596s Error: Could not restart systemd, systemd binary not working 596s (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 ... 74487 files and directories currently installed.) 596s Preparing to unpack .../libc-bin_2.39-3.1ubuntu3_amd64.deb ... 596s Unpacking libc-bin (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 596s Setting up libc-bin (2.39-3.1ubuntu3) ... 596s (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 ... 74487 files and directories currently installed.) 596s Preparing to unpack .../libssl3t64_3.2.2-1ubuntu1_amd64.deb ... 596s Unpacking libssl3t64:amd64 (3.2.2-1ubuntu1) over (3.2.1-3ubuntu1) ... 596s Setting up libssl3t64:amd64 (3.2.2-1ubuntu1) ... 596s (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 ... 74487 files and directories currently installed.) 596s Preparing to unpack .../00-openssh-sftp-server_1%3a9.6p1-3ubuntu17_amd64.deb ... 596s Unpacking openssh-sftp-server (1:9.6p1-3ubuntu17) over (1:9.6p1-3ubuntu15) ... 596s Preparing to unpack .../01-openssh-server_1%3a9.6p1-3ubuntu17_amd64.deb ... 596s Unpacking openssh-server (1:9.6p1-3ubuntu17) over (1:9.6p1-3ubuntu15) ... 596s Preparing to unpack .../02-openssh-client_1%3a9.6p1-3ubuntu17_amd64.deb ... 596s Unpacking openssh-client (1:9.6p1-3ubuntu17) over (1:9.6p1-3ubuntu15) ... 596s Preparing to unpack .../03-gir1.2-glib-2.0_2.80.4-1ubuntu1_amd64.deb ... 596s Unpacking gir1.2-glib-2.0:amd64 (2.80.4-1ubuntu1) over (2.80.3-1ubuntu1) ... 596s Preparing to unpack .../04-libglib2.0-0t64_2.80.4-1ubuntu1_amd64.deb ... 596s Unpacking libglib2.0-0t64:amd64 (2.80.4-1ubuntu1) over (2.80.3-1ubuntu1) ... 596s Preparing to unpack .../05-libglib2.0-data_2.80.4-1ubuntu1_all.deb ... 596s Unpacking libglib2.0-data (2.80.4-1ubuntu1) over (2.80.3-1ubuntu1) ... 596s Preparing to unpack .../06-locales_2.39-3.1ubuntu3_all.deb ... 596s Unpacking locales (2.39-3.1ubuntu3) over (2.39-0ubuntu9) ... 597s Preparing to unpack .../07-openssl_3.2.2-1ubuntu1_amd64.deb ... 597s Unpacking openssl (3.2.2-1ubuntu1) over (3.2.1-3ubuntu1) ... 597s Preparing to unpack .../08-inetutils-telnet_2%3a2.5-5ubuntu1_amd64.deb ... 597s Unpacking inetutils-telnet (2:2.5-5ubuntu1) over (2:2.5-3ubuntu4) ... 597s Preparing to unpack .../09-libnghttp2-14_1.62.1-2_amd64.deb ... 597s Unpacking libnghttp2-14:amd64 (1.62.1-2) over (1.62.1-1) ... 597s Preparing to unpack .../10-telnet_0.17+2.5-5ubuntu1_all.deb ... 597s Unpacking telnet (0.17+2.5-5ubuntu1) over (0.17+2.5-3ubuntu4) ... 597s Preparing to unpack .../11-libgprofng0_2.42.50.20240710-1ubuntu1_amd64.deb ... 597s Unpacking libgprofng0:amd64 (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 597s Preparing to unpack .../12-libctf0_2.42.50.20240710-1ubuntu1_amd64.deb ... 597s Unpacking libctf0:amd64 (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 597s Preparing to unpack .../13-libctf-nobfd0_2.42.50.20240710-1ubuntu1_amd64.deb ... 597s Unpacking libctf-nobfd0:amd64 (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 597s Preparing to unpack .../14-binutils-x86-64-linux-gnu_2.42.50.20240710-1ubuntu1_amd64.deb ... 597s Unpacking binutils-x86-64-linux-gnu (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 597s Preparing to unpack .../15-libbinutils_2.42.50.20240710-1ubuntu1_amd64.deb ... 597s Unpacking libbinutils:amd64 (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 597s Preparing to unpack .../16-binutils_2.42.50.20240710-1ubuntu1_amd64.deb ... 597s Unpacking binutils (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 597s Preparing to unpack .../17-binutils-common_2.42.50.20240710-1ubuntu1_amd64.deb ... 597s Unpacking binutils-common:amd64 (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 597s Preparing to unpack .../18-libsframe1_2.42.50.20240710-1ubuntu1_amd64.deb ... 597s Unpacking libsframe1:amd64 (2.42.50.20240710-1ubuntu1) over (2.42.50.20240625-1ubuntu1) ... 597s Preparing to unpack .../19-libnss3_2%3a3.102-1_amd64.deb ... 597s Unpacking libnss3:amd64 (2:3.102-1) over (2:3.101-1) ... 597s Setting up openssh-client (1:9.6p1-3ubuntu17) ... 597s Setting up binutils-common:amd64 (2.42.50.20240710-1ubuntu1) ... 597s Setting up libnghttp2-14:amd64 (1.62.1-2) ... 597s Setting up inetutils-telnet (2:2.5-5ubuntu1) ... 597s Setting up libctf-nobfd0:amd64 (2.42.50.20240710-1ubuntu1) ... 597s Setting up libnss3:amd64 (2:3.102-1) ... 597s Setting up locales (2.39-3.1ubuntu3) ... 598s Generating locales (this might take a while)... 600s en_US.UTF-8... done 600s Generation complete. 600s Setting up libsframe1:amd64 (2.42.50.20240710-1ubuntu1) ... 600s Setting up libglib2.0-0t64:amd64 (2.80.4-1ubuntu1) ... 600s No schema files found: doing nothing. 600s Setting up libglib2.0-data (2.80.4-1ubuntu1) ... 600s Setting up gir1.2-glib-2.0:amd64 (2.80.4-1ubuntu1) ... 600s Setting up libbinutils:amd64 (2.42.50.20240710-1ubuntu1) ... 600s Setting up libc-dev-bin (2.39-3.1ubuntu3) ... 600s Setting up openssl (3.2.2-1ubuntu1) ... 600s Installing new version of config file /etc/ssl/openssl.cnf ... 600s Setting up libc-devtools (2.39-3.1ubuntu3) ... 600s Setting up libctf0:amd64 (2.42.50.20240710-1ubuntu1) ... 600s Setting up openssh-sftp-server (1:9.6p1-3ubuntu17) ... 600s Setting up telnet (0.17+2.5-5ubuntu1) ... 600s Setting up openssh-server (1:9.6p1-3ubuntu17) ... 600s Installing new version of config file /etc/pam.d/sshd ... 601s Setting up libgprofng0:amd64 (2.42.50.20240710-1ubuntu1) ... 601s Setting up libc6-dev:amd64 (2.39-3.1ubuntu3) ... 601s Setting up binutils-x86-64-linux-gnu (2.42.50.20240710-1ubuntu1) ... 601s Setting up binutils (2.42.50.20240710-1ubuntu1) ... 601s Processing triggers for libc-bin (2.39-3.1ubuntu3) ... 601s Processing triggers for ufw (0.36.2-6) ... 601s Processing triggers for systemd (256-1ubuntu1) ... 601s Processing triggers for man-db (2.12.1-2) ... 603s Reading package lists... 603s Building dependency tree... 603s Reading state information... 604s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 604s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 604s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 604s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 604s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 606s Reading package lists... 606s Reading package lists... 606s Building dependency tree... 606s Reading state information... 606s Calculating upgrade... 607s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 607s Reading package lists... 607s Building dependency tree... 607s Reading state information... 607s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 607s autopkgtest [17:25:02]: rebooting testbed after setup commands that affected boot 706s Reading package lists... 707s Building dependency tree... 707s Reading state information... 707s Starting pkgProblemResolver with broken count: 0 707s Starting 2 pkgProblemResolver with broken count: 0 707s Done 708s The following additional packages will be installed: 708s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 708s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 708s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 708s librdmacm1t64 lsscsi open-iscsi tgt 708s Suggested packages: 708s fio-examples gnuplot tgt-glusterfs tgt-rbd 708s Recommended packages: 708s finalrd 708s The following NEW packages will be installed: 708s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 708s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 708s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 708s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 708s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 708s Need to get 10.0 MB/10.0 MB of archives. 708s After this operation, 42.9 MB of additional disk space will be used. 708s Get:1 /tmp/autopkgtest.l7dREy/2-autopkgtest-satdep.deb autopkgtest-satdep amd64 0 [728 B] 708s Get:2 http://ftpmaster.internal/ubuntu oracular/main amd64 libopeniscsiusr amd64 2.1.10-1ubuntu1 [49.7 kB] 708s Get:3 http://ftpmaster.internal/ubuntu oracular/main amd64 libisns0t64 amd64 0.101-1 [94.2 kB] 708s Get:4 http://ftpmaster.internal/ubuntu oracular/main amd64 open-iscsi amd64 2.1.10-1ubuntu1 [326 kB] 708s Get:5 http://ftpmaster.internal/ubuntu oracular/main amd64 librdmacm1t64 amd64 52.0-2 [70.7 kB] 708s Get:6 http://ftpmaster.internal/ubuntu oracular/universe amd64 libconfig-general-perl all 2.65-2 [57.1 kB] 708s Get:7 http://ftpmaster.internal/ubuntu oracular/universe amd64 tgt amd64 1:1.0.85-1.2ubuntu1 [234 kB] 708s Get:8 http://ftpmaster.internal/ubuntu oracular/universe amd64 libgfxdr0 amd64 11.1-4ubuntu1 [20.1 kB] 708s Get:9 http://ftpmaster.internal/ubuntu oracular/universe amd64 libglusterfs0 amd64 11.1-4ubuntu1 [266 kB] 708s Get:10 http://ftpmaster.internal/ubuntu oracular/universe amd64 libgfrpc0 amd64 11.1-4ubuntu1 [40.7 kB] 708s Get:11 http://ftpmaster.internal/ubuntu oracular/universe amd64 libgfapi0 amd64 11.1-4ubuntu1 [79.6 kB] 708s Get:12 http://ftpmaster.internal/ubuntu oracular/universe amd64 libnbd0 amd64 1.20.2-1 [94.1 kB] 708s Get:13 http://ftpmaster.internal/ubuntu oracular/main amd64 libdaxctl1 amd64 77-2ubuntu2 [21.4 kB] 708s Get:14 http://ftpmaster.internal/ubuntu oracular/main amd64 libndctl6 amd64 77-2ubuntu2 [62.8 kB] 708s Get:15 http://ftpmaster.internal/ubuntu oracular/main amd64 libpmem1 amd64 1.13.1-1.1ubuntu2 [84.8 kB] 708s Get:16 http://ftpmaster.internal/ubuntu oracular/main amd64 libboost-iostreams1.83.0 amd64 1.83.0-3ubuntu1 [259 kB] 708s Get:17 http://ftpmaster.internal/ubuntu oracular/main amd64 libboost-thread1.83.0 amd64 1.83.0-3ubuntu1 [276 kB] 708s Get:18 http://ftpmaster.internal/ubuntu oracular/main amd64 librados2 amd64 19.2.0~git20240301.4c76c50-0ubuntu7 [3915 kB] 708s Get:19 http://ftpmaster.internal/ubuntu oracular/main amd64 libpmemobj1 amd64 1.13.1-1.1ubuntu2 [116 kB] 708s Get:20 http://ftpmaster.internal/ubuntu oracular/main amd64 librbd1 amd64 19.2.0~git20240301.4c76c50-0ubuntu7 [3327 kB] 708s Get:21 http://ftpmaster.internal/ubuntu oracular/universe amd64 fio amd64 3.37-1 [594 kB] 708s Get:22 http://ftpmaster.internal/ubuntu oracular/main amd64 lsscsi amd64 0.32-1build1 [48.2 kB] 708s Preconfiguring packages ... 708s Fetched 10.0 MB in 0s (33.5 MB/s) 708s Selecting previously unselected package libopeniscsiusr. 709s (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 ... 74486 files and directories currently installed.) 709s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_amd64.deb ... 709s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 709s Selecting previously unselected package libisns0t64:amd64. 709s Preparing to unpack .../01-libisns0t64_0.101-1_amd64.deb ... 709s Unpacking libisns0t64:amd64 (0.101-1) ... 709s Selecting previously unselected package open-iscsi. 709s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_amd64.deb ... 709s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 709s Selecting previously unselected package librdmacm1t64:amd64. 709s Preparing to unpack .../03-librdmacm1t64_52.0-2_amd64.deb ... 709s Unpacking librdmacm1t64:amd64 (52.0-2) ... 709s Selecting previously unselected package libconfig-general-perl. 709s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 709s Unpacking libconfig-general-perl (2.65-2) ... 709s Selecting previously unselected package tgt. 709s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_amd64.deb ... 709s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 709s Selecting previously unselected package libgfxdr0:amd64. 709s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_amd64.deb ... 709s Unpacking libgfxdr0:amd64 (11.1-4ubuntu1) ... 709s Selecting previously unselected package libglusterfs0:amd64. 709s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_amd64.deb ... 709s Unpacking libglusterfs0:amd64 (11.1-4ubuntu1) ... 709s Selecting previously unselected package libgfrpc0:amd64. 709s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_amd64.deb ... 709s Unpacking libgfrpc0:amd64 (11.1-4ubuntu1) ... 709s Selecting previously unselected package libgfapi0:amd64. 709s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_amd64.deb ... 709s Unpacking libgfapi0:amd64 (11.1-4ubuntu1) ... 709s Selecting previously unselected package libnbd0. 709s Preparing to unpack .../10-libnbd0_1.20.2-1_amd64.deb ... 709s Unpacking libnbd0 (1.20.2-1) ... 709s Selecting previously unselected package libdaxctl1:amd64. 709s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_amd64.deb ... 709s Unpacking libdaxctl1:amd64 (77-2ubuntu2) ... 709s Selecting previously unselected package libndctl6:amd64. 709s Preparing to unpack .../12-libndctl6_77-2ubuntu2_amd64.deb ... 709s Unpacking libndctl6:amd64 (77-2ubuntu2) ... 709s Selecting previously unselected package libpmem1:amd64. 709s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_amd64.deb ... 709s Unpacking libpmem1:amd64 (1.13.1-1.1ubuntu2) ... 709s Selecting previously unselected package libboost-iostreams1.83.0:amd64. 709s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_amd64.deb ... 709s Unpacking libboost-iostreams1.83.0:amd64 (1.83.0-3ubuntu1) ... 709s Selecting previously unselected package libboost-thread1.83.0:amd64. 709s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_amd64.deb ... 709s Unpacking libboost-thread1.83.0:amd64 (1.83.0-3ubuntu1) ... 709s Selecting previously unselected package librados2. 709s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_amd64.deb ... 709s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 709s Selecting previously unselected package libpmemobj1:amd64. 709s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_amd64.deb ... 709s Unpacking libpmemobj1:amd64 (1.13.1-1.1ubuntu2) ... 709s Selecting previously unselected package librbd1. 709s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_amd64.deb ... 709s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 709s Selecting previously unselected package fio. 709s Preparing to unpack .../19-fio_3.37-1_amd64.deb ... 709s Unpacking fio (3.37-1) ... 709s Selecting previously unselected package lsscsi. 709s Preparing to unpack .../20-lsscsi_0.32-1build1_amd64.deb ... 709s Unpacking lsscsi (0.32-1build1) ... 709s Selecting previously unselected package autopkgtest-satdep. 709s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 709s Unpacking autopkgtest-satdep (0) ... 709s Setting up libconfig-general-perl (2.65-2) ... 709s Setting up libisns0t64:amd64 (0.101-1) ... 709s Setting up libboost-thread1.83.0:amd64 (1.83.0-3ubuntu1) ... 709s Setting up libnbd0 (1.20.2-1) ... 709s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 709s Setting up libglusterfs0:amd64 (11.1-4ubuntu1) ... 709s Setting up libboost-iostreams1.83.0:amd64 (1.83.0-3ubuntu1) ... 709s Setting up lsscsi (0.32-1build1) ... 709s Setting up libdaxctl1:amd64 (77-2ubuntu2) ... 709s Setting up libndctl6:amd64 (77-2ubuntu2) ... 709s Setting up librdmacm1t64:amd64 (52.0-2) ... 709s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 710s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 710s Setting up libpmem1:amd64 (1.13.1-1.1ubuntu2) ... 710s Setting up libgfxdr0:amd64 (11.1-4ubuntu1) ... 710s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 710s Setting up open-iscsi (2.1.10-1ubuntu1) ... 711s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 712s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 712s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 712s Setting up libpmemobj1:amd64 (1.13.1-1.1ubuntu2) ... 712s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 712s Setting up libgfrpc0:amd64 (11.1-4ubuntu1) ... 712s Setting up libgfapi0:amd64 (11.1-4ubuntu1) ... 712s Setting up fio (3.37-1) ... 712s Setting up autopkgtest-satdep (0) ... 712s Processing triggers for man-db (2.12.1-2) ... 714s Processing triggers for initramfs-tools (0.142ubuntu30) ... 714s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 714s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 723s Processing triggers for libc-bin (2.39-3.1ubuntu3) ... 730s (Reading database ... 74727 files and directories currently installed.) 730s Removing autopkgtest-satdep (0) ... 750s autopkgtest [17:27:25]: test tgtbasedmpaths: [----------------------- 750s + targetname=iqn.2016-11.foo.com:target.iscsi 750s + pwd 750s + cwd=/tmp/autopkgtest.l7dREy/build.mqH/src 750s + testdir=/mnt/tgtmpathtest 750s + localhost=127.0.0.1 750s + portal=127.0.0.1:3260 750s + maxpaths=4 750s + backfn=backingfile 750s + expectwwid=60000000000000000e00000000010001 750s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 750s + bglog=/tmp/autopkgtest.l7dREy/tgtbasedmpaths-artifacts/test-background.log 750s + fioprep=/tmp/autopkgtest.l7dREy/tgtbasedmpaths-artifacts/path-change-prep.fio 750s + fiovrfy=/tmp/autopkgtest.l7dREy/tgtbasedmpaths-artifacts/path-change-check.fio 750s + service tgt restart 751s + truncate --size 100M backingfile 751s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 751s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 751s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.l7dREy/build.mqH/src/backingfile 751s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 751s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 751s + echo login #1 751s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 751s login #1 751s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 751s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 751s + seq 2 4 751s + echo extra login #2 751s + iscsiadm --mode session -r 1 --op new 751s extra login #2 751s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 751s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 751s + echo extra login #3 751s + iscsiadm --mode session -r 1 --op new 751s extra login #3 751s + echo extra login #4 751s + iscsiadm --mode session -r 1 --op new 751s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 751s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 751s extra login #4 751s + udevadm settle 751s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 751s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 751s + sleep 5 756s Status after initial setup 756s Target 1: iqn.2016-11.foo.com:target.iscsi 756s System information: 756s Driver: iscsi 756s State: ready 756s I_T nexus information: 756s I_T nexus: 1 756s Initiator: iqn.2004-10.com.ubuntu:01:ef4a88404b7a alias: autopkgtest 756s Connection: 0 756s IP Address: 127.0.0.1 756s I_T nexus: 2 756s Initiator: iqn.2004-10.com.ubuntu:01:ef4a88404b7a alias: autopkgtest 756s Connection: 0 756s IP Address: 127.0.0.1 756s I_T nexus: 3 756s Initiator: iqn.2004-10.com.ubuntu:01:ef4a88404b7a alias: autopkgtest 756s Connection: 0 756s IP Address: 127.0.0.1 756s I_T nexus: 4 756s Initiator: iqn.2004-10.com.ubuntu:01:ef4a88404b7a alias: autopkgtest 756s Connection: 0 756s IP Address: 127.0.0.1 756s LUN information: 756s LUN: 0 756s Type: controller 756s SCSI ID: IET 00010000 756s SCSI SN: beaf10 756s Size: 0 MB, Block size: 1 756s Online: Yes 756s Removable media: No 756s Prevent removal: No 756s Readonly: No 756s SWP: No 756s Thin-provisioning: No 756s Backing store type: null 756s Backing store path: None 756s Backing store flags: 756s LUN: 1 756s Type: disk 756s SCSI ID: IET 00010001 756s SCSI SN: beaf11 756s Size: 105 MB, Block size: 512 756s Online: Yes 756s Removable media: No 756s Prevent removal: No 756s Readonly: No 756s SWP: No 756s Thin-provisioning: No 756s Backing store type: rdwr 756s Backing store path: /tmp/autopkgtest.l7dREy/build.mqH/src/backingfile 756s Backing store flags: 756s Account information: 756s ACL information: 756s ALL 756s + echo Status after initial setup 756s + tgtadm --lld iscsi --mode target --op show 756s + tgtadm --lld iscsi --op show --mode conn --tid 1 756s + iscsiadm --mode session -P 1 756s Session: 4 756s Connection: 0 756s Initiator: iqn.2004-10.com.ubuntu:01:ef4a88404b7a 756s IP Address: 127.0.0.1 756s Session: 3 756s Connection: 0 756s Initiator: iqn.2004-10.com.ubuntu:01:ef4a88404b7a 756s IP Address: 127.0.0.1 756s Session: 2 756s Connection: 0 756s Initiator: iqn.2004-10.com.ubuntu:01:ef4a88404b7a 756s IP Address: 127.0.0.1 756s Session: 1 756s Connection: 0 756s Initiator: iqn.2004-10.com.ubuntu:01:ef4a88404b7a 756s IP Address: 127.0.0.1 756s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 756s Current Portal: 127.0.0.1:3260,1 756s Persistent Portal: 127.0.0.1:3260,1 756s ********** 756s Interface: 756s ********** 756s Iface Name: default 756s Iface Transport: tcp 756s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ef4a88404b7a 756s Iface IPaddress: 127.0.0.1 756s Iface HWaddress: default 756s Iface Netdev: default 756s SID: 1 756s iSCSI Connection State: LOGGED IN 756s iSCSI Session State: LOGGED_IN 756s Internal iscsid Session State: NO CHANGE 756s 756s ********** 756s Interface: 756s ********** 756s Iface Name: default 756s Iface Transport: tcp 756s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ef4a88404b7a 756s Iface IPaddress: 127.0.0.1 756s Iface HWaddress: default 756s Iface Netdev: default 756s SID: 2 756s iSCSI Connection State: LOGGED IN 756s iSCSI Session State: LOGGED_IN 756s Internal iscsid Session State: NO CHANGE 756s 756s ********** 756s Interface: 756s ********** 756s Iface Name: default 756s Iface Transport: tcp 756s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ef4a88404b7a 756s Iface IPaddress: 127.0.0.1 756s Iface HWaddress: default 756s Iface Netdev: default 756s SID: 3 756s iSCSI Connection State: LOGGED IN 756s iSCSI Session State: LOGGED_IN 756s Internal iscsid Session State: NO CHANGE 756s 756s ********** 756s Interface: 756s ********** 756s Iface Name: default 756s Iface Transport: tcp 756s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ef4a88404b7a 756s Iface IPaddress: 127.0.0.1 756s Iface HWaddress: default 756s Iface Netdev: default 756s SID: 4 756s iSCSI Connection State: LOGGED IN 756s iSCSI Session State: LOGGED_IN 756s Internal iscsid Session State: NO CHANGE 756s + lsscsi -liv 756s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 756s [2:0:0:0] storage IET Controller 0001 - - 756s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 756s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session1/target2:0:0/2:0:0:0] 756s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 756s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 756s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session1/target2:0:0/2:0:0:1] 756s [3:0:0:0] storage IET Controller 0001 - - 756s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 756s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session2/target3:0:0/3:0:0:0] 756s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 756s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 756s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session2/target3:0:0/3:0:0:1] 756s [4:0:0:0] storage IET Controller 0001 - - 756s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 756s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session3/target4:0:0/4:0:0:0] 756s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 756s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 756s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session3/target4:0:0/4:0:0:1] 756s [5:0:0:0] storage IET Controller 0001 - - 756s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 756s dir: /sys/bus/scsi/devices/5:0:0:0 [/sys/devices/platform/host5/session4/target5:0:0/5:0:0:0] 756s [5:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 756s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 756s dir: /sys/bus/scsi/devices/5:0:0:1 [/sys/devices/platform/host5/session4/target5:0:0/5:0:0:1] 756s NVMe module may not be loaded 756s + multipath -v3 -ll 756s 142.198355 | set open fds limit to 1073741816/1073741816 756s 142.198451 | loading /lib/multipath/libchecktur.so checker 756s 142.198641 | checker tur: message table size = 3 756s 142.198657 | loading /lib/multipath/libprioconst.so prioritizer 756s 142.198788 | _init_foreign: foreign library "nvme" is not enabled 756s 142.205818 | vda: device node name blacklisted 756s 142.206376 | sda: size = 204800 756s 142.206573 | sda: vendor = IET 756s 142.206606 | sda: product = VIRTUAL-DISK 756s 142.206633 | sda: rev = 0001 756s 142.207476 | sda: h:b:t:l = 2:0:0:1 756s 142.207933 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 756s 142.207943 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 756s 142.207945 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 756s 142.208209 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 756s 142.208223 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 756s 142.208241 | sda: serial = beaf11 756s 142.208248 | sda: detect_checker = yes (setting: multipath internal) 756s 142.208502 | sda: path_checker = tur (setting: multipath internal) 756s 142.208513 | sda: checker timeout = 30 s (setting: kernel sysfs) 756s 142.208598 | sda: tur state = up 756s 142.208767 | sdb: size = 204800 756s 142.208950 | sdb: vendor = IET 756s 142.208979 | sdb: product = VIRTUAL-DISK 756s 142.209029 | sdb: rev = 0001 756s 142.209781 | sdb: h:b:t:l = 3:0:0:1 756s 142.210242 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 756s 142.210255 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 756s 142.210257 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 756s 142.210437 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 756s 142.210447 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 756s 142.210463 | sdb: serial = beaf11 756s 142.210469 | sdb: detect_checker = yes (setting: multipath internal) 756s 142.210634 | sdb: path_checker = tur (setting: multipath internal) 756s 142.210643 | sdb: checker timeout = 30 s (setting: kernel sysfs) 756s 142.210751 | sdb: tur state = up 756s 142.210915 | sdc: size = 204800 756s 142.211116 | sdc: vendor = IET 756s 142.211149 | sdc: product = VIRTUAL-DISK 756s 142.211176 | sdc: rev = 0001 756s 142.211891 | sdc: h:b:t:l = 4:0:0:1 756s 142.212353 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 756s 142.212365 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 756s 142.212368 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 756s 142.212541 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 756s 142.212551 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 756s 142.212567 | sdc: serial = beaf11 756s 142.212573 | sdc: detect_checker = yes (setting: multipath internal) 756s 142.212751 | sdc: path_checker = tur (setting: multipath internal) 756s 142.212761 | sdc: checker timeout = 30 s (setting: kernel sysfs) 756s 142.212864 | sdc: tur state = up 756s 142.213051 | sdd: size = 204800 756s 142.213231 | sdd: vendor = IET 756s 142.213260 | sdd: product = VIRTUAL-DISK 756s 142.213283 | sdd: rev = 0001 756s 142.213958 | sdd: h:b:t:l = 5:0:0:1 756s 142.214402 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 756s 142.214416 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 756s 142.214418 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 756s 142.214585 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 756s 142.214594 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 756s 142.214618 | sdd: serial = beaf11 756s 142.214625 | sdd: detect_checker = yes (setting: multipath internal) 756s 142.214790 | sdd: path_checker = tur (setting: multipath internal) 756s 142.214804 | sdd: checker timeout = 30 s (setting: kernel sysfs) 756s 142.214975 | sdd: tur state = up 756s 142.215140 | loop0: device node name blacklisted 756s 142.215255 | loop1: device node name blacklisted 756s 142.215362 | loop2: device node name blacklisted 756s 142.215508 | loop3: device node name blacklisted 756s 142.215614 | loop4: device node name blacklisted 756s 142.215720 | loop5: device node name blacklisted 756s 142.215825 | loop6: device node name blacklisted 756s 142.215930 | loop7: device node name blacklisted 756s 142.216068 | dm-0: device node name blacklisted 756s 142.217236 | multipath-tools v0.9.4 (12/19, 2022) 756s 142.217258 | libdevmapper version 1.02.185 756s 142.217495 | kernel device mapper v4.48.0 756s 142.217517 | DM multipath kernel driver v1.14.0 756s 142.217644 | sda: size = 204800 756s 142.217654 | sda: vendor = IET 756s 142.217656 | sda: product = VIRTUAL-DISK 756s 142.217659 | sda: rev = 0001 756s 142.218336 | sda: h:b:t:l = 2:0:0:1 756s 142.218496 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 756s 142.218521 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 756s 142.218524 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 756s 142.218540 | sda: serial = beaf11 756s 142.218656 | sda: tur state = up 756s 142.218664 | sda: uid = 360000000000000000e00000000010001 (udev) 756s 142.218666 | sda: detect_prio = yes (setting: multipath internal) 756s 142.218669 | sda: prio = const (setting: multipath internal) 756s 142.218672 | sda: prio args = "" (setting: multipath internal) 756s 142.218674 | sda: const prio = 1 756s 142.218700 | sdb: size = 204800 756s 142.218707 | sdb: vendor = IET 756s 142.218709 | sdb: product = VIRTUAL-DISK 756s 142.218712 | sdb: rev = 0001 756s 142.219353 | sdb: h:b:t:l = 3:0:0:1 756s ===== paths list ===== 756s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 756s 2:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK unknown 756s 3:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 756s 4:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 756s 5:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 756s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 756s size=100M features='0' hwhandler='0' wp=rw 756s |-+- policy='service-time 0' prio=1 status=active 756s | `- 2:0:0:1 sda 8:0 active ready running 756s |-+- policy='service-time 0' prio=1 status=enabled 756s | `- 3:0:0:1 sdb 8:16 active ready running 756s |-+- policy='service-time 0' prio=1 status=enabled 756s | `- 4:0:0:1 sdc 8:32 active ready running 756s `-+- policy='service-time 0' prio=1 status=enabled 756s `- 5:0:0:1 sdd 8:48 active ready running 756s 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 756s Test WWN should now point to DM 756s 142.219523 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 756s 142.219545 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 756s 142.219547 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 756s 142.219561 | sdb: serial = beaf11 756s 142.219645 | sdb: tur state = up 756s 142.219653 | sdb: uid = 360000000000000000e00000000010001 (udev) 756s 142.219655 | sdb: detect_prio = yes (setting: multipath internal) 756s 142.219657 | sdb: prio = const (setting: multipath internal) 756s 142.219659 | sdb: prio args = "" (setting: multipath internal) 756s 142.219662 | sdb: const prio = 1 756s 142.219687 | sdc: size = 204800 756s 142.219692 | sdc: vendor = IET 756s 142.219695 | sdc: product = VIRTUAL-DISK 756s 142.219697 | sdc: rev = 0001 756s 142.220341 | sdc: h:b:t:l = 4:0:0:1 756s 142.220489 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 756s 142.220512 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 756s 142.220515 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 756s 142.220530 | sdc: serial = beaf11 756s 142.220617 | sdc: tur state = up 756s 142.220625 | sdc: uid = 360000000000000000e00000000010001 (udev) 756s 142.220627 | sdc: detect_prio = yes (setting: multipath internal) 756s 142.220630 | sdc: prio = const (setting: multipath internal) 756s 142.220632 | sdc: prio args = "" (setting: multipath internal) 756s 142.220634 | sdc: const prio = 1 756s 142.220660 | sdd: size = 204800 756s 142.220665 | sdd: vendor = IET 756s 142.220667 | sdd: product = VIRTUAL-DISK 756s 142.220670 | sdd: rev = 0001 756s 142.221315 | sdd: h:b:t:l = 5:0:0:1 756s 142.221459 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 756s 142.221483 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 756s 142.221486 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 756s 142.221500 | sdd: serial = beaf11 756s 142.221595 | sdd: tur state = up 756s 142.221607 | sdd: uid = 360000000000000000e00000000010001 (udev) 756s 142.221610 | sdd: detect_prio = yes (setting: multipath internal) 756s 142.221612 | sdd: prio = const (setting: multipath internal) 756s 142.221614 | sdd: prio args = "" (setting: multipath internal) 756s 142.221617 | sdd: const prio = 1 756s 142.222512 | unloading tur checker 756s 142.222552 | unloading const prioritizer 756s + dmsetup table 756s + echo Test WWN should now point to DM 756s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 756s + grep dm 756s ../../dm-0 756s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 756s mke2fs 1.47.1 (20-May-2024) 756s Creating filesystem with 25600 4k blocks and 25600 inodes 756s 756s Allocating group tables: 0/1 done 756s Writing inode tables: 0/1 done 756s Creating journal (1024 blocks): done 756s Writing superblocks and filesystem accounting information: 0/1 done 756s 756s + udevadm settle 756s + sleep 3s 759s + mkdir -p /mnt/tgtmpathtest 759s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 759s + cat 759s + cat 759s + fio --max-jobs=4 /tmp/autopkgtest.l7dREy/tgtbasedmpaths-artifacts/path-change-prep.fio 759s 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 759s fio-3.37 759s Starting 1 thread 759s write-phase: Laying out IO file (1 file / 17592186044415MiB) 760s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91750400, buflen=65536 760s 760s write-phase: (groupid=0, jobs=1): err= 0: pid=5678: Fri Jul 12 17:27:35 2024 760s write: IOPS=2501, BW=156MiB/s (164MB/s)(87.5MiB/560msec); 0 zone resets 760s clat (usec): min=272, max=1531, avg=393.50, stdev=76.39 760s lat (usec): min=275, max=1535, avg=397.81, stdev=76.63 760s clat percentiles (usec): 760s | 1.00th=[ 289], 5.00th=[ 306], 10.00th=[ 318], 20.00th=[ 338], 760s | 30.00th=[ 359], 40.00th=[ 375], 50.00th=[ 388], 60.00th=[ 400], 760s | 70.00th=[ 412], 80.00th=[ 433], 90.00th=[ 465], 95.00th=[ 502], 760s | 99.00th=[ 594], 99.50th=[ 742], 99.90th=[ 1156], 99.95th=[ 1532], 760s | 99.99th=[ 1532] 760s bw ( KiB/s): min=159104, max=159104, per=99.44%, avg=159104.00, stdev= 0.00, samples=1 760s iops : min= 2486, max= 2486, avg=2486.00, stdev= 0.00, samples=1 760s lat (usec) : 500=94.50%, 750=4.93%, 1000=0.29% 760s lat (msec) : 2=0.21% 760s cpu : usr=1.07%, sys=10.20%, ctx=1403, majf=0, minf=0 760s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 760s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 760s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 760s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 760s latency : target=0, window=0, percentile=100.00%, depth=1 760s 760s Run status group 0 (all jobs): 760s WRITE: bw=156MiB/s (164MB/s), 156MiB/s-156MiB/s (164MB/s-164MB/s), io=87.5MiB (91.8MB), run=560-560msec 760s 760s Disk stats (read/write): 760s dm-0: ios=1/920, sectors=8/117760, merge=0/0, ticks=1/381, in_queue=381, util=79.75%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/125, aggrin_queue=125, aggrutil=82.96% 760s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 760s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 760s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 760s sda: ios=1/1402, sectors=8/179280, merge=0/0, ticks=1/501, in_queue=501, util=82.96% 760s + echo Starting the path changes in background 760s Starting the path changes in background 760s + date +Pre FIO %H:%M:%S.%N 760s Pre FIO 17:27:35.570801557 760s + fio --max-jobs=4 /tmp/autopkgtest.l7dREy/tgtbasedmpaths-artifacts/path-change-check.fio 760s 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 760s fio-3.37 760s Starting 1 thread 940s 940s verify-phase: (groupid=0, jobs=1): err= 0: pid=5685: Fri Jul 12 17:30:35 2024 940s read: IOPS=5993, BW=375MiB/s (393MB/s)(65.8GiB/180001msec) 940s clat (usec): min=100, max=32635, avg=160.25, stdev=82.32 940s lat (usec): min=100, max=32635, avg=160.43, stdev=82.34 940s clat percentiles (usec): 940s | 1.00th=[ 113], 5.00th=[ 119], 10.00th=[ 124], 20.00th=[ 133], 940s | 30.00th=[ 141], 40.00th=[ 147], 50.00th=[ 153], 60.00th=[ 161], 940s | 70.00th=[ 169], 80.00th=[ 180], 90.00th=[ 198], 95.00th=[ 217], 940s | 99.00th=[ 269], 99.50th=[ 318], 99.90th=[ 1057], 99.95th=[ 1614], 940s | 99.99th=[ 2376] 940s bw ( KiB/s): min=231808, max=461312, per=100.00%, avg=383807.74, stdev=40123.81, samples=359 940s iops : min= 3622, max= 7208, avg=5997.00, stdev=626.93, samples=359 940s lat (usec) : 250=98.37%, 500=1.42%, 750=0.06%, 1000=0.04% 940s lat (msec) : 2=0.08%, 4=0.02%, 10=0.01%, 20=0.01%, 50=0.01% 940s cpu : usr=4.81%, sys=13.18%, ctx=1079188, majf=0, minf=16 940s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 940s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 940s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 940s issued rwts: total=1078761,0,0,0 short=0,0,0,0 dropped=0,0,0,0 940s latency : target=0, window=0, percentile=100.00%, depth=1 940s 940s Run status group 0 (all jobs): 940s READ: bw=375MiB/s (393MB/s), 375MiB/s-375MiB/s (393MB/s-393MB/s), io=65.8GiB (70.7GB), run=180001-180001msec 940s 940s Disk stats (read/write): 940s dm-0: ios=1078870/11, sectors=137992800/12944, merge=0/10, ticks=165103/199, in_queue=165476, util=99.93%, aggrios=75082/2, aggsectors=9602680/3236, aggrmerge=0/0, aggrticks=10348/6, aggrin_queue=10354, aggrutil=99.08% 940s sdd: ios=119391/6, sectors=15271168/64, merge=0/0, ticks=16665/2, in_queue=16667, util=40.03% 940s sdb: ios=60710/0, sectors=7761376/0, merge=0/0, ticks=8300/0, in_queue=8300, util=50.23% 940s sdc: ios=63618/0, sectors=8137216/0, merge=0/0, ticks=8184/0, in_queue=8184, util=33.19% 940s sda: ios=56612/4, sectors=7240960/12880, merge=0/0, ticks=8244/22, in_queue=8267, util=99.08% 940s + date +Post FIO %H:%M:%S.%N 940s + echo FIO verify test with changing paths - OK 940s + echo Report log of background activity 940s + cat /tmp/autopkgtest.l7dREy/tgtbasedmpaths-artifacts/test-background.log 940s Post FIO 17:30:35.919523605 940s FIO verify test with changing paths - OK 940s Report log of background activity 940s + sync 940s + iscsiadm --mode session 940s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s + sleep 10s 940s + date +MP report (expect 4) %H:%M:%S.%N 940s MP report (expect 4) 17:27:45.579244064 940s + multipath -ll 940s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 940s size=100M features='0' hwhandler='0' wp=rw 940s |-+- policy='service-time 0' prio=1 status=active 940s | `- 2:0:0:1 sda 8:0 active ready running 940s |-+- policy='service-time 0' prio=1 status=enabled 940s | `- 3:0:0:1 sdb 8:16 active ready running 940s |-+- policy='service-time 0' prio=1 status=enabled 940s | `- 4:0:0:1 sdc 8:32 active ready running 940s `-+- policy='service-time 0' prio=1 status=enabled 940s `- 5:0:0:1 sdd 8:48 active ready running 940s + date +UN-plug path 1 %H:%M:%S.%N 940s UN-plug path 1 17:27:45.600944339 940s + iscsiadm --mode session -r 1 -u 940s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 940s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 940s + iscsiadm --mode session 940s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s + sleep 10s 940s + date +MP report (expect 3) %H:%M:%S.%N 940s MP report (expect 3) 17:27:55.651823700 940s + multipath -ll 940s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 940s size=100M features='0' hwhandler='0' wp=rw 940s |-+- policy='service-time 0' prio=1 status=active 940s | `- 3:0:0:1 sdb 8:16 active ready running 940s |-+- policy='service-time 0' prio=1 status=enabled 940s | `- 4:0:0:1 sdc 8:32 active ready running 940s `-+- policy='service-time 0' prio=1 status=enabled 940s `- 5:0:0:1 sdd 8:48 active ready running 940s + date +UN-plug path 2 %H:%M:%S.%N 940s UN-plug path 2 17:27:55.675679430 940s + iscsiadm --mode session -r 2 -u 940s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 940s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 940s + iscsiadm --mode session 940s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s + sleep 10s 940s + date +MP report (expect 2) %H:%M:%S.%N 940s MP report (expect 2) 17:28:05.736900591 940s + multipath -ll 940s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 940s size=100M features='0' hwhandler='0' wp=rw 940s |-+- policy='service-time 0' prio=1 status=active 940s | `- 4:0:0:1 sdc 8:32 active ready running 940s `-+- policy='service-time 0' prio=1 status=enabled 940s `- 5:0:0:1 sdd 8:48 active ready running 940s + date +UN-plug path 3 %H:%M:%S.%N 940s UN-plug path 3 17:28:05.757921585 940s + iscsiadm --mode session -r 3 -u 940s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 940s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 940s + iscsiadm --mode session 940s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s + sleep 10s 940s + date +MP report (expect 1) %H:%M:%S.%N 940s MP report (expect 1) 17:28:15.817242373 940s + multipath -ll 940s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 940s size=100M features='0' hwhandler='0' wp=rw 940s `-+- policy='service-time 0' prio=1 status=active 940s `- 5:0:0:1 sdd 8:48 active ready running 940s + date +Add paths 5/6/7/8 %H:%M:%S.%N 940s Add paths 5/6/7/8 17:28:15.831274106 940s + iscsiadm --mode session -r 4 --op new 940s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 940s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 940s + iscsiadm --mode session -r 4 --op new 940s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 940s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 940s + iscsiadm --mode session -r 4 --op new 940s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 940s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 940s + iscsiadm --mode session -r 4 --op new 940s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 940s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 940s + iscsiadm --mode session 940s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s + sleep 10s 940s + date +MP report (expect 5) %H:%M:%S.%N 940s MP report (expect 5) 17:28:25.918586944 940s + multipath -ll 940s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 940s size=100M features='0' hwhandler='0' wp=rw 940s |-+- policy='service-time 0' prio=1 status=active 940s | `- 5:0:0:1 sdd 8:48 active ready running 940s |-+- policy='service-time 0' prio=1 status=enabled 940s | `- 2:0:0:1 sda 8:0 active ready running 940s |-+- policy='service-time 0' prio=1 status=enabled 940s | `- 3:0:0:1 sdb 8:16 active ready running 940s |-+- policy='service-time 0' prio=1 status=enabled 940s | `- 4:0:0:1 sdc 8:32 active ready running 940s `-+- policy='service-time 0' prio=1 status=enabled 940s `- 6:0:0:1 sde 8:64 active ready running 940s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 940s UN-plug multiple paths 4/7/8 17:28:25.944711061 940s + iscsiadm --mode session -r 4 -u 940s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 940s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 940s + iscsiadm --mode session -r 7 -u 940s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 940s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 940s + iscsiadm --mode session -r 8 -u 940s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 940s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 940s + iscsiadm --mode session 940s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 940s + sleep 10s 940s + date +Restart multipath daemon %H:%M:%S.%N 940s Restart multipath daemon 17:28:36.069107022 940s + systemctl restart multipathd 940s + sleep 10s 940s + date +Final background report (expect 2) %H:%M:%S.%N 940s Final background report (expect 2) 17:28:46.160243739 940s + multipath -ll 940s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 940s size=100M features='0' hwhandler='0' wp=rw 940s |-+- policy='service-time 0' prio=1 status=active 940s | `- 2:0:0:1 sda 8:0 active ready running 940s `-+- policy='service-time 0' prio=1 status=enabled 940s `- 3:0:0:1 sdb 8:16 active ready running 940s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 940s + echo Final stats 940s + iscsiadm --mode session --stats 940s Final stats 940s + journalctl --no-pager -u multipathd 940s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 940s iSCSI SNMP: 940s txdata_octets: 37316856 940s rxdata_octets: 50922851684 940s noptx_pdus: 0 940s scsicmd_pdus: 777167 940s tmfcmd_pdus: 0 940s login_pdus: 0 940s text_pdus: 0 940s dataout_pdus: 0 940s logout_pdus: 0 940s snack_pdus: 0 940s noprx_pdus: 0 940s scsirsp_pdus: 777167 940s tmfrsp_pdus: 0 940s textrsp_pdus: 0 940s datain_pdus: 777135 940s logoutrsp_pdus: 0 940s r2t_pdus: 0 940s async_pdus: 0 940s rjt_pdus: 0 940s digest_err: 0 940s timeout_err: 0 940s iSCSI Extended: 940s tx_sendpage_failures: 0 940s rx_discontiguous_hdr: 0 940s eh_abort_cnt: 0 940s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 940s iSCSI SNMP: 940s txdata_octets: 7992 940s rxdata_octets: 1098660 940s noptx_pdus: 0 940s scsicmd_pdus: 137 940s tmfcmd_pdus: 0 940s login_pdus: 0 940s text_pdus: 0 940s dataout_pdus: 0 940s logout_pdus: 0 940s snack_pdus: 0 940s noprx_pdus: 0 940s scsirsp_pdus: 137 940s tmfrsp_pdus: 0 940s textrsp_pdus: 0 940s datain_pdus: 115 940s logoutrsp_pdus: 0 940s r2t_pdus: 0 940s async_pdus: 0 940s rjt_pdus: 0 940s digest_err: 0 940s timeout_err: 0 940s iSCSI Extended: 940s tx_sendpage_failures: 0 940s rx_discontiguous_hdr: 0 940s eh_abort_cnt: 0 940s Jul 11 15:58:28 adtubuntu-oracular-amd64-server-20240709 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 940s Jul 11 15:58:28 adtubuntu-oracular-amd64-server-20240709 multipathd[309]: multipathd v0.9.4: start up 940s Jul 11 15:58:28 adtubuntu-oracular-amd64-server-20240709 multipathd[309]: reconfigure: setting up paths and maps 940s Jul 11 15:58:28 adtubuntu-oracular-amd64-server-20240709 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 940s Jul 11 15:59:29 adtubuntu-oracular-amd64-server-20240710 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 940s Jul 11 15:59:29 adtubuntu-oracular-amd64-server-20240710 multipathd[309]: multipathd: shut down 940s Jul 11 15:59:29 adtubuntu-oracular-amd64-server-20240710 systemd[1]: multipathd.service: Deactivated successfully. 940s Jul 11 15:59:29 adtubuntu-oracular-amd64-server-20240710 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 940s -- Boot 197ad49650874886964980d4dd679f68 -- 940s Jul 11 15:59:38 adtubuntu-oracular-amd64-server-20240710 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 940s Jul 11 15:59:38 adtubuntu-oracular-amd64-server-20240710 multipathd[319]: multipathd v0.9.4: start up 940s Jul 11 15:59:38 adtubuntu-oracular-amd64-server-20240710 multipathd[319]: reconfigure: setting up paths and maps 940s Jul 11 15:59:38 adtubuntu-oracular-amd64-server-20240710 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 940s Jul 11 15:59:43 adtubuntu-oracular-amd64-server-20240710 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 940s Jul 11 15:59:43 adtubuntu-oracular-amd64-server-20240710 multipathd[319]: multipathd: shut down 940s Jul 11 15:59:43 adtubuntu-oracular-amd64-server-20240710 systemd[1]: multipathd.service: Deactivated successfully. 940s Jul 11 15:59:43 adtubuntu-oracular-amd64-server-20240710 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 940s -- Boot c9ffc509a5164ef2bc13af43c27ab364 -- 940s Jul 12 17:24:04 adtubuntu-oracular-amd64-server-20240710 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 940s Jul 12 17:24:04 adtubuntu-oracular-amd64-server-20240710 multipathd[349]: multipathd v0.9.4: start up 940s Jul 12 17:24:04 adtubuntu-oracular-amd64-server-20240710 multipathd[349]: reconfigure: setting up paths and maps 940s Jul 12 17:24:04 adtubuntu-oracular-amd64-server-20240710 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 940s Jul 12 17:25:06 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 940s Jul 12 17:25:06 autopkgtest multipathd[349]: multipathd: shut down 940s Jul 12 17:25:06 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 940s Jul 12 17:25:06 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 940s -- Boot 82430337724c4086adcd9563a4b140be -- 940s Jul 12 17:25:13 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 940s Jul 12 17:25:13 autopkgtest multipathd[347]: multipathd v0.9.4: start up 940s Jul 12 17:25:13 autopkgtest multipathd[347]: reconfigure: setting up paths and maps 940s Jul 12 17:25:13 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 940s Jul 12 17:27:26 autopkgtest multipathd[347]: 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] 940s Jul 12 17:27:26 autopkgtest multipathd[347]: sdb [8:16]: path added to devmap mpatha 940s Jul 12 17:27:26 autopkgtest multipathd[347]: mpatha: performing delayed actions 940s Jul 12 17:27:26 autopkgtest multipathd[347]: 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] 940s Jul 12 17:27:45 autopkgtest multipathd[347]: sda: mark as failed 940s Jul 12 17:27:45 autopkgtest multipathd[347]: mpatha: remaining active paths: 3 940s Jul 12 17:27:45 autopkgtest multipathd[347]: 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] 940s Jul 12 17:27:45 autopkgtest multipathd[347]: check_removed_paths: sda: freeing path in removed state 940s Jul 12 17:27:45 autopkgtest multipathd[347]: 8:0: path removed from map mpatha 940s Jul 12 17:27:55 autopkgtest multipathd[347]: 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] 940s Jul 12 17:27:55 autopkgtest multipathd[347]: check_removed_paths: sdb: freeing path in removed state 940s Jul 12 17:27:55 autopkgtest multipathd[347]: 8:16: path removed from map mpatha 940s Jul 12 17:28:05 autopkgtest multipathd[347]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 940s Jul 12 17:28:05 autopkgtest multipathd[347]: check_removed_paths: sdc: freeing path in removed state 940s Jul 12 17:28:05 autopkgtest multipathd[347]: 8:32: path removed from map mpatha 940s Jul 12 17:28:15 autopkgtest multipathd[347]: 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] 940s Jul 12 17:28:15 autopkgtest multipathd[347]: sda [8:0]: path added to devmap mpatha 940s Jul 12 17:28:15 autopkgtest multipathd[347]: 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] 940s Jul 12 17:28:15 autopkgtest multipathd[347]: sdb [8:16]: path added to devmap mpatha 940s Jul 12 17:28:15 autopkgtest multipathd[347]: 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] 940s Jul 12 17:28:15 autopkgtest multipathd[347]: sdc [8:32]: path added to devmap mpatha 940s Jul 12 17:28:15 autopkgtest multipathd[347]: 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] 940s Jul 12 17:28:16 autopkgtest multipathd[347]: sde [8:64]: path added to devmap mpatha 940s Jul 12 17:28:25 autopkgtest multipathd[347]: 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] 940s Jul 12 17:28:25 autopkgtest multipathd[347]: check_removed_paths: sdd: freeing path in removed state 940s Jul 12 17:28:25 autopkgtest multipathd[347]: 8:48: path removed from map mpatha 940s Jul 12 17:28:26 autopkgtest multipathd[347]: 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] 940s Jul 12 17:28:26 autopkgtest multipathd[347]: check_removed_paths: sdc: freeing path in removed state 940s Jul 12 17:28:26 autopkgtest multipathd[347]: 8:32: path removed from map mpatha 940s Jul 12 17:28:26 autopkgtest multipathd[347]: 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] 940s Jul 12 17:28:26 autopkgtest multipathd[347]: check_removed_paths: sde: freeing path in removed state 940s Jul 12 17:28:26 autopkgtest multipathd[347]: 8:64: path removed from map mpatha 940s Jul 12 17:28:36 autopkgtest multipathd[347]: multipathd: shut down 940s Jul 12 17:28:36 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 940s Jul 12 17:28:36 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 940s Jul 12 17:28:36 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 940s Jul 12 17:28:36 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 940s Jul 12 17:28:36 autopkgtest multipathd[6040]: multipathd v0.9.4: start up 940s Jul 12 17:28:36 autopkgtest multipathd[6040]: reconfigure: setting up paths and maps 940s Jul 12 17:28:36 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 940s + echo Check final path status 940s + multipath -ll 940s Check final path status 940s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 944s size=100M features='0' hwhandler='0' wp=rw 944s |-+- policy='service-time 0' prio=1 status=active 944s | `- 2:0:0:1 sda 8:0 active ready running 944s `-+- policy='service-time 0' prio=1 status=enabled 944s `- 3:0:0:1 sdb 8:16 active ready running 944s + multipath -ll 944s + grep --count status= 944s + diskc=2 944s + multipath -ll 944s + grep --count status=active 944s + diska=1 944s + multipath -ll 944s + grep --count status=enabled 944s + diske=1 944s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 944s + echo OK 944s OK 944s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 944s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 944s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 944s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 944s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 944s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 944s autopkgtest [17:30:36]: test tgtbasedmpaths: -----------------------] 950s tgtbasedmpaths PASS 950s autopkgtest [17:30:45]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 950s autopkgtest [17:30:45]: @@@@@@@@@@@@@@@@@@@@ summary 950s kpartx-file-loopback PASS 950s tgtbasedmpaths PASS 1014s nova [W] Skipping flock for amd64 1014s Creating nova instance adt-oracular-amd64-multipath-tools-20240712-171455-juju-7f2275-prod-proposed-migration-environment-3-0a5b088a-8665-4357-9dbb-8906b3dbe003 from image adt/ubuntu-oracular-amd64-server-20240711.img (UUID 4d65b1cc-a829-44fc-a8ac-cdd52093f9db)... 1014s nova [W] Skipping flock for amd64 1014s Creating nova instance adt-oracular-amd64-multipath-tools-20240712-171455-juju-7f2275-prod-proposed-migration-environment-3-0a5b088a-8665-4357-9dbb-8906b3dbe003 from image adt/ubuntu-oracular-amd64-server-20240711.img (UUID 4d65b1cc-a829-44fc-a8ac-cdd52093f9db)...