0s autopkgtest [01:51:00]: starting date and time: 2024-05-20 01:51:00+0000 0s autopkgtest [01:51:00]: git checkout: 699e7f9f ssh-setup/nova: explicitely set 'fqdn' in cloud-init 0s autopkgtest [01:51:00]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.k8l4coog/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:initramfs-tools --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=initramfs-tools/0.142ubuntu27 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos02-ppc64el-17.secgroup --name adt-oracular-ppc64el-multipath-tools-20240520-015100-juju-7f2275-prod-proposed-migration-environment-2-47fa88be-9345-4f51-b10b-0fe0e919ad32 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,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/ 153s autopkgtest [01:53:33]: testbed dpkg architecture: ppc64el 154s autopkgtest [01:53:34]: testbed apt version: 2.7.14build2 154s autopkgtest [01:53:34]: @@@@@@@@@@@@@@@@@@@@ test bed setup 155s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [73.9 kB] 155s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [1400 kB] 156s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [8060 B] 156s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [1964 B] 156s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [107 kB] 156s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [176 kB] 156s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [1670 kB] 156s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [15.4 kB] 156s Fetched 3453 kB in 2s (1823 kB/s) 156s Reading package lists... 159s Reading package lists... 159s Building dependency tree... 159s Reading state information... 159s Calculating upgrade... 159s The following packages will be upgraded: 159s apparmor apport apport-core-dump-handler dhcpcd-base eatmydata 159s initramfs-tools initramfs-tools-bin initramfs-tools-core libapparmor1 159s libbpf1 libcap-ng0 libdw1t64 libeatmydata1 libelf1t64 libnss3 libnvme1t64 159s libsharpyuv0 libslang2 libwebp7 libxcb1 pastebinit python-babel-localedata 159s python3-apport python3-babel python3-netaddr python3-problem-report 159s ubuntu-pro-client ubuntu-pro-client-l10n 159s 28 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 159s Need to get 11.9 MB of archives. 159s After this operation, 703 kB disk space will be freed. 159s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-problem-report all 2.28.1-0ubuntu4 [23.9 kB] 160s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-apport all 2.28.1-0ubuntu4 [92.1 kB] 160s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el apport-core-dump-handler all 2.28.1-0ubuntu4 [16.9 kB] 160s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el apport all 2.28.1-0ubuntu4 [83.4 kB] 160s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el libcap-ng0 ppc64el 0.8.5-1 [16.0 kB] 160s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el dhcpcd-base ppc64el 1:10.0.6-4 [273 kB] 160s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el libapparmor1 ppc64el 4.0.1-0ubuntu1 [55.1 kB] 160s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdw1t64 ppc64el 0.191-1 [303 kB] 160s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el libelf1t64 ppc64el 0.191-1 [68.0 kB] 160s Get:10 http://ftpmaster.internal/ubuntu oracular/main ppc64el libbpf1 ppc64el 1:1.4.1-1 [220 kB] 160s Get:11 http://ftpmaster.internal/ubuntu oracular/main ppc64el libslang2 ppc64el 2.3.3-5 [503 kB] 160s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el ubuntu-pro-client-l10n ppc64el 32.1 [19.4 kB] 160s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el ubuntu-pro-client ppc64el 32.1 [229 kB] 160s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el apparmor ppc64el 4.0.1-0ubuntu1 [748 kB] 161s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libxcb1 ppc64el 1.17.0-1 [56.6 kB] 161s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libeatmydata1 ppc64el 131-2 [7522 B] 161s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el eatmydata all 131-2 [5576 B] 161s Get:18 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools all 0.142ubuntu27 [7898 B] 161s Get:19 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools-core all 0.142ubuntu27 [49.5 kB] 161s Get:20 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools-bin ppc64el 0.142ubuntu27 [21.6 kB] 161s Get:21 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnss3 ppc64el 2:3.100-1 [1848 kB] 161s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnvme1t64 ppc64el 1.9-1 [100 kB] 161s Get:23 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsharpyuv0 ppc64el 1.4.0-0.1 [22.0 kB] 161s Get:24 http://ftpmaster.internal/ubuntu oracular/main ppc64el libwebp7 ppc64el 1.4.0-0.1 [309 kB] 161s Get:25 http://ftpmaster.internal/ubuntu oracular/main ppc64el pastebinit all 1.7.0-1 [14.9 kB] 161s Get:26 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-babel all 2.14.0-1 [96.4 kB] 161s Get:27 http://ftpmaster.internal/ubuntu oracular/main ppc64el python-babel-localedata all 2.14.0-1 [6385 kB] 162s Get:28 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-netaddr all 0.10.1-1 [322 kB] 162s Preconfiguring packages ... 162s Fetched 11.9 MB in 3s (4292 kB/s) 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 ... 72144 files and directories currently installed.) 162s Preparing to unpack .../python3-problem-report_2.28.1-0ubuntu4_all.deb ... 162s Unpacking python3-problem-report (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 162s Preparing to unpack .../python3-apport_2.28.1-0ubuntu4_all.deb ... 163s Unpacking python3-apport (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 163s Preparing to unpack .../apport-core-dump-handler_2.28.1-0ubuntu4_all.deb ... 163s Unpacking apport-core-dump-handler (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 163s Preparing to unpack .../apport_2.28.1-0ubuntu4_all.deb ... 163s Unpacking apport (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 163s Preparing to unpack .../libcap-ng0_0.8.5-1_ppc64el.deb ... 163s Unpacking libcap-ng0:ppc64el (0.8.5-1) over (0.8.4-2build2) ... 163s Setting up libcap-ng0:ppc64el (0.8.5-1) ... 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 ... 72144 files and directories currently installed.) 163s Preparing to unpack .../00-dhcpcd-base_1%3a10.0.6-4_ppc64el.deb ... 163s Unpacking dhcpcd-base (1:10.0.6-4) over (1:10.0.6-1ubuntu3) ... 163s Preparing to unpack .../01-libapparmor1_4.0.1-0ubuntu1_ppc64el.deb ... 163s Unpacking libapparmor1:ppc64el (4.0.1-0ubuntu1) over (4.0.0-beta3-0ubuntu3) ... 163s Preparing to unpack .../02-libdw1t64_0.191-1_ppc64el.deb ... 163s Unpacking libdw1t64:ppc64el (0.191-1) over (0.190-1.1build4) ... 163s Preparing to unpack .../03-libelf1t64_0.191-1_ppc64el.deb ... 163s Unpacking libelf1t64:ppc64el (0.191-1) over (0.190-1.1build4) ... 163s Preparing to unpack .../04-libbpf1_1%3a1.4.1-1_ppc64el.deb ... 163s Unpacking libbpf1:ppc64el (1:1.4.1-1) over (1:1.3.0-2build2) ... 163s Preparing to unpack .../05-libslang2_2.3.3-5_ppc64el.deb ... 163s Unpacking libslang2:ppc64el (2.3.3-5) over (2.3.3-3build2) ... 163s Preparing to unpack .../06-ubuntu-pro-client-l10n_32.1_ppc64el.deb ... 163s Unpacking ubuntu-pro-client-l10n (32.1) over (31.2.3) ... 163s Preparing to unpack .../07-ubuntu-pro-client_32.1_ppc64el.deb ... 163s Unpacking ubuntu-pro-client (32.1) over (31.2.3) ... 163s Preparing to unpack .../08-apparmor_4.0.1-0ubuntu1_ppc64el.deb ... 164s Unpacking apparmor (4.0.1-0ubuntu1) over (4.0.0-beta3-0ubuntu3) ... 164s Preparing to unpack .../09-libxcb1_1.17.0-1_ppc64el.deb ... 164s Unpacking libxcb1:ppc64el (1.17.0-1) over (1.15-1ubuntu2) ... 164s Preparing to unpack .../10-libeatmydata1_131-2_ppc64el.deb ... 164s Unpacking libeatmydata1:ppc64el (131-2) over (131-1ubuntu1) ... 164s Preparing to unpack .../11-eatmydata_131-2_all.deb ... 164s Unpacking eatmydata (131-2) over (131-1ubuntu1) ... 164s Preparing to unpack .../12-initramfs-tools_0.142ubuntu27_all.deb ... 164s Unpacking initramfs-tools (0.142ubuntu27) over (0.142ubuntu25) ... 164s Preparing to unpack .../13-initramfs-tools-core_0.142ubuntu27_all.deb ... 164s Unpacking initramfs-tools-core (0.142ubuntu27) over (0.142ubuntu25) ... 164s Preparing to unpack .../14-initramfs-tools-bin_0.142ubuntu27_ppc64el.deb ... 164s Unpacking initramfs-tools-bin (0.142ubuntu27) over (0.142ubuntu25) ... 164s Preparing to unpack .../15-libnss3_2%3a3.100-1_ppc64el.deb ... 164s Unpacking libnss3:ppc64el (2:3.100-1) over (2:3.98-1build1) ... 164s Preparing to unpack .../16-libnvme1t64_1.9-1_ppc64el.deb ... 164s Unpacking libnvme1t64 (1.9-1) over (1.8-3build1) ... 164s Preparing to unpack .../17-libsharpyuv0_1.4.0-0.1_ppc64el.deb ... 164s Unpacking libsharpyuv0:ppc64el (1.4.0-0.1) over (1.3.2-0.4build3) ... 164s Preparing to unpack .../18-libwebp7_1.4.0-0.1_ppc64el.deb ... 164s Unpacking libwebp7:ppc64el (1.4.0-0.1) over (1.3.2-0.4build3) ... 164s Preparing to unpack .../19-pastebinit_1.7.0-1_all.deb ... 164s Unpacking pastebinit (1.7.0-1) over (1.6.2-1) ... 164s Preparing to unpack .../20-python3-babel_2.14.0-1_all.deb ... 164s Unpacking python3-babel (2.14.0-1) over (2.10.3-3build1) ... 164s Preparing to unpack .../21-python-babel-localedata_2.14.0-1_all.deb ... 164s Unpacking python-babel-localedata (2.14.0-1) over (2.10.3-3build1) ... 165s Preparing to unpack .../22-python3-netaddr_0.10.1-1_all.deb ... 165s Unpacking python3-netaddr (0.10.1-1) over (0.8.0-2ubuntu1) ... 165s Setting up libsharpyuv0:ppc64el (1.4.0-0.1) ... 165s Setting up libapparmor1:ppc64el (4.0.1-0ubuntu1) ... 165s Setting up libxcb1:ppc64el (1.17.0-1) ... 165s Setting up python3-problem-report (2.28.1-0ubuntu4) ... 165s Setting up pastebinit (1.7.0-1) ... 165s Setting up libnss3:ppc64el (2:3.100-1) ... 165s Setting up libelf1t64:ppc64el (0.191-1) ... 165s Setting up python-babel-localedata (2.14.0-1) ... 165s Setting up python3-apport (2.28.1-0ubuntu4) ... 165s Setting up libdw1t64:ppc64el (0.191-1) ... 165s Setting up apparmor (4.0.1-0ubuntu1) ... 165s Installing new version of config file /etc/apparmor.d/abstractions/authentication ... 165s Installing new version of config file /etc/apparmor.d/abstractions/samba ... 165s Installing new version of config file /etc/apparmor.d/firefox ... 166s Reloading AppArmor profiles 166s Setting up libslang2:ppc64el (2.3.3-5) ... 166s Setting up libnvme1t64 (1.9-1) ... 166s Setting up dhcpcd-base (1:10.0.6-4) ... 166s Setting up libwebp7:ppc64el (1.4.0-0.1) ... 166s Setting up python3-netaddr (0.10.1-1) ... 167s Setting up libeatmydata1:ppc64el (131-2) ... 167s Setting up ubuntu-pro-client (32.1) ... 167s Installing new version of config file /etc/apparmor.d/ubuntu_pro_apt_news ... 168s Setting up libbpf1:ppc64el (1:1.4.1-1) ... 168s Setting up initramfs-tools-bin (0.142ubuntu27) ... 168s Setting up ubuntu-pro-client-l10n (32.1) ... 168s Setting up eatmydata (131-2) ... 168s Setting up python3-babel (2.14.0-1) ... 168s Setting up initramfs-tools-core (0.142ubuntu27) ... 168s Setting up initramfs-tools (0.142ubuntu27) ... 168s update-initramfs: deferring update (trigger activated) 168s Setting up apport-core-dump-handler (2.28.1-0ubuntu4) ... 169s Setting up apport (2.28.1-0ubuntu4) ... 169s Installing new version of config file /etc/apport/crashdb.conf ... 170s apport-autoreport.service is a disabled or a static unit not running, not starting it. 170s Processing triggers for libc-bin (2.39-0ubuntu8) ... 170s Processing triggers for man-db (2.12.0-4build2) ... 171s Processing triggers for initramfs-tools (0.142ubuntu27) ... 171s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 171s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 179s Reading package lists... 179s Building dependency tree... 179s Reading state information... 179s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 179s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 179s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 180s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 180s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 180s Reading package lists... 180s Reading package lists... 181s Building dependency tree... 181s Reading state information... 181s Calculating upgrade... 181s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 181s Reading package lists... 181s Building dependency tree... 181s Reading state information... 181s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 181s autopkgtest [01:54:01]: rebooting testbed after setup commands that affected boot 215s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 226s autopkgtest [01:54:46]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 228s autopkgtest [01:54:48]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 232s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 232s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 232s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 232s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 232s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 232s gpgv: issuer "steve.langasek@ubuntu.com" 232s gpgv: Can't check signature: No public key 232s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 232s autopkgtest [01:54:52]: testing package multipath-tools version 0.9.4-5ubuntu8 233s autopkgtest [01:54:53]: build not needed 234s autopkgtest [01:54:54]: test kpartx-file-loopback: preparing testbed 235s Reading package lists... 235s Building dependency tree... 235s Reading state information... 236s Starting pkgProblemResolver with broken count: 0 236s Starting 2 pkgProblemResolver with broken count: 0 236s Done 236s The following additional packages will be installed: 236s liburing2 qemu-utils 236s Recommended packages: 236s qemu-block-extra 236s The following NEW packages will be installed: 236s autopkgtest-satdep liburing2 qemu-utils 236s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 236s Need to get 2329 kB/2330 kB of archives. 236s After this operation, 15.4 MB of additional disk space will be used. 236s Get:1 /tmp/autopkgtest.jtBdyL/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 236s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.5-1build1 [26.0 kB] 236s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 238s Fetched 2329 kB in 2s (1479 kB/s) 238s Selecting previously unselected package liburing2:ppc64el. 238s (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 ... 72423 files and directories currently installed.) 238s Preparing to unpack .../liburing2_2.5-1build1_ppc64el.deb ... 238s Unpacking liburing2:ppc64el (2.5-1build1) ... 238s Selecting previously unselected package qemu-utils. 238s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 238s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 238s Selecting previously unselected package autopkgtest-satdep. 238s Preparing to unpack .../1-autopkgtest-satdep.deb ... 238s Unpacking autopkgtest-satdep (0) ... 238s Setting up liburing2:ppc64el (2.5-1build1) ... 238s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 238s Setting up autopkgtest-satdep (0) ... 238s Processing triggers for man-db (2.12.0-4build2) ... 239s Processing triggers for libc-bin (2.39-0ubuntu8) ... 241s (Reading database ... 72443 files and directories currently installed.) 241s Removing autopkgtest-satdep (0) ... 242s autopkgtest [01:55:02]: test kpartx-file-loopback: [----------------------- 242s Formatting 'foo.img', fmt=raw size=20971520 243s Creating new GPT entries in memory. 243s Warning: The kernel is still using the old partition table. 243s The new table will be used at the next reboot or after you 243s run partprobe(8) or kpartx(8) 243s The operation has completed successfully. 243s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 243s standard_filename: OK 243s del devmap : loop0p1 243s No devices found 243s standard_filename_cleanup: OK 243s Formatting 'fou du FaFa.img', fmt=raw size=20971520 244s Creating new GPT entries in memory. 244s Warning: The kernel is still using the old partition table. 244s The new table will be used at the next reboot or after you 244s run partprobe(8) or kpartx(8) 244s The operation has completed successfully. 244s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 244s filename_with_spaces: OK 244s del devmap : loop0p1 244s No devices found 244s filename_with_spaces_cleanup: OK 244s autopkgtest [01:55:04]: test kpartx-file-loopback: -----------------------] 245s kpartx-file-loopback PASS 245s autopkgtest [01:55:05]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 245s autopkgtest [01:55:05]: test tgtbasedmpaths: preparing testbed 347s autopkgtest [01:56:47]: testbed dpkg architecture: ppc64el 347s autopkgtest [01:56:47]: testbed apt version: 2.7.14build2 347s autopkgtest [01:56:47]: @@@@@@@@@@@@@@@@@@@@ test bed setup 348s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [73.9 kB] 348s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [107 kB] 349s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [1400 kB] 349s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [1964 B] 349s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [8060 B] 349s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [176 kB] 349s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [1670 kB] 349s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [15.4 kB] 349s Fetched 3453 kB in 1s (2580 kB/s) 349s Reading package lists... 352s Reading package lists... 352s Building dependency tree... 352s Reading state information... 352s Calculating upgrade... 352s The following packages will be upgraded: 352s apparmor apport apport-core-dump-handler dhcpcd-base eatmydata 352s initramfs-tools initramfs-tools-bin initramfs-tools-core libapparmor1 352s libbpf1 libcap-ng0 libdw1t64 libeatmydata1 libelf1t64 libnss3 libnvme1t64 352s libsharpyuv0 libslang2 libwebp7 libxcb1 pastebinit python-babel-localedata 352s python3-apport python3-babel python3-netaddr python3-problem-report 352s ubuntu-pro-client ubuntu-pro-client-l10n 352s 28 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 352s Need to get 11.9 MB of archives. 352s After this operation, 703 kB disk space will be freed. 352s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-problem-report all 2.28.1-0ubuntu4 [23.9 kB] 352s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-apport all 2.28.1-0ubuntu4 [92.1 kB] 353s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el apport-core-dump-handler all 2.28.1-0ubuntu4 [16.9 kB] 353s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el apport all 2.28.1-0ubuntu4 [83.4 kB] 353s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el libcap-ng0 ppc64el 0.8.5-1 [16.0 kB] 353s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el dhcpcd-base ppc64el 1:10.0.6-4 [273 kB] 353s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el libapparmor1 ppc64el 4.0.1-0ubuntu1 [55.1 kB] 353s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdw1t64 ppc64el 0.191-1 [303 kB] 353s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el libelf1t64 ppc64el 0.191-1 [68.0 kB] 353s Get:10 http://ftpmaster.internal/ubuntu oracular/main ppc64el libbpf1 ppc64el 1:1.4.1-1 [220 kB] 353s Get:11 http://ftpmaster.internal/ubuntu oracular/main ppc64el libslang2 ppc64el 2.3.3-5 [503 kB] 353s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el ubuntu-pro-client-l10n ppc64el 32.1 [19.4 kB] 353s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el ubuntu-pro-client ppc64el 32.1 [229 kB] 353s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el apparmor ppc64el 4.0.1-0ubuntu1 [748 kB] 353s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libxcb1 ppc64el 1.17.0-1 [56.6 kB] 353s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libeatmydata1 ppc64el 131-2 [7522 B] 353s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el eatmydata all 131-2 [5576 B] 353s Get:18 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools all 0.142ubuntu27 [7898 B] 353s Get:19 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools-core all 0.142ubuntu27 [49.5 kB] 353s Get:20 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools-bin ppc64el 0.142ubuntu27 [21.6 kB] 353s Get:21 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnss3 ppc64el 2:3.100-1 [1848 kB] 353s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnvme1t64 ppc64el 1.9-1 [100 kB] 353s Get:23 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsharpyuv0 ppc64el 1.4.0-0.1 [22.0 kB] 353s Get:24 http://ftpmaster.internal/ubuntu oracular/main ppc64el libwebp7 ppc64el 1.4.0-0.1 [309 kB] 353s Get:25 http://ftpmaster.internal/ubuntu oracular/main ppc64el pastebinit all 1.7.0-1 [14.9 kB] 353s Get:26 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-babel all 2.14.0-1 [96.4 kB] 353s Get:27 http://ftpmaster.internal/ubuntu oracular/main ppc64el python-babel-localedata all 2.14.0-1 [6385 kB] 354s Get:28 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-netaddr all 0.10.1-1 [322 kB] 354s Preconfiguring packages ... 354s Fetched 11.9 MB in 2s (6600 kB/s) 355s (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 ... 72144 files and directories currently installed.) 355s Preparing to unpack .../python3-problem-report_2.28.1-0ubuntu4_all.deb ... 355s Unpacking python3-problem-report (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 355s Preparing to unpack .../python3-apport_2.28.1-0ubuntu4_all.deb ... 355s Unpacking python3-apport (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 355s Preparing to unpack .../apport-core-dump-handler_2.28.1-0ubuntu4_all.deb ... 355s Unpacking apport-core-dump-handler (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 355s Preparing to unpack .../apport_2.28.1-0ubuntu4_all.deb ... 355s Unpacking apport (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 355s Preparing to unpack .../libcap-ng0_0.8.5-1_ppc64el.deb ... 355s Unpacking libcap-ng0:ppc64el (0.8.5-1) over (0.8.4-2build2) ... 355s Setting up libcap-ng0:ppc64el (0.8.5-1) ... 355s (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 ... 72144 files and directories currently installed.) 355s Preparing to unpack .../00-dhcpcd-base_1%3a10.0.6-4_ppc64el.deb ... 355s Unpacking dhcpcd-base (1:10.0.6-4) over (1:10.0.6-1ubuntu3) ... 355s Preparing to unpack .../01-libapparmor1_4.0.1-0ubuntu1_ppc64el.deb ... 355s Unpacking libapparmor1:ppc64el (4.0.1-0ubuntu1) over (4.0.0-beta3-0ubuntu3) ... 355s Preparing to unpack .../02-libdw1t64_0.191-1_ppc64el.deb ... 355s Unpacking libdw1t64:ppc64el (0.191-1) over (0.190-1.1build4) ... 355s Preparing to unpack .../03-libelf1t64_0.191-1_ppc64el.deb ... 355s Unpacking libelf1t64:ppc64el (0.191-1) over (0.190-1.1build4) ... 355s Preparing to unpack .../04-libbpf1_1%3a1.4.1-1_ppc64el.deb ... 355s Unpacking libbpf1:ppc64el (1:1.4.1-1) over (1:1.3.0-2build2) ... 355s Preparing to unpack .../05-libslang2_2.3.3-5_ppc64el.deb ... 355s Unpacking libslang2:ppc64el (2.3.3-5) over (2.3.3-3build2) ... 355s Preparing to unpack .../06-ubuntu-pro-client-l10n_32.1_ppc64el.deb ... 355s Unpacking ubuntu-pro-client-l10n (32.1) over (31.2.3) ... 355s Preparing to unpack .../07-ubuntu-pro-client_32.1_ppc64el.deb ... 355s Unpacking ubuntu-pro-client (32.1) over (31.2.3) ... 355s Preparing to unpack .../08-apparmor_4.0.1-0ubuntu1_ppc64el.deb ... 356s Unpacking apparmor (4.0.1-0ubuntu1) over (4.0.0-beta3-0ubuntu3) ... 356s Preparing to unpack .../09-libxcb1_1.17.0-1_ppc64el.deb ... 356s Unpacking libxcb1:ppc64el (1.17.0-1) over (1.15-1ubuntu2) ... 356s Preparing to unpack .../10-libeatmydata1_131-2_ppc64el.deb ... 356s Unpacking libeatmydata1:ppc64el (131-2) over (131-1ubuntu1) ... 356s Preparing to unpack .../11-eatmydata_131-2_all.deb ... 356s Unpacking eatmydata (131-2) over (131-1ubuntu1) ... 356s Preparing to unpack .../12-initramfs-tools_0.142ubuntu27_all.deb ... 356s Unpacking initramfs-tools (0.142ubuntu27) over (0.142ubuntu25) ... 356s Preparing to unpack .../13-initramfs-tools-core_0.142ubuntu27_all.deb ... 356s Unpacking initramfs-tools-core (0.142ubuntu27) over (0.142ubuntu25) ... 356s Preparing to unpack .../14-initramfs-tools-bin_0.142ubuntu27_ppc64el.deb ... 356s Unpacking initramfs-tools-bin (0.142ubuntu27) over (0.142ubuntu25) ... 356s Preparing to unpack .../15-libnss3_2%3a3.100-1_ppc64el.deb ... 356s Unpacking libnss3:ppc64el (2:3.100-1) over (2:3.98-1build1) ... 356s Preparing to unpack .../16-libnvme1t64_1.9-1_ppc64el.deb ... 356s Unpacking libnvme1t64 (1.9-1) over (1.8-3build1) ... 356s Preparing to unpack .../17-libsharpyuv0_1.4.0-0.1_ppc64el.deb ... 356s Unpacking libsharpyuv0:ppc64el (1.4.0-0.1) over (1.3.2-0.4build3) ... 356s Preparing to unpack .../18-libwebp7_1.4.0-0.1_ppc64el.deb ... 356s Unpacking libwebp7:ppc64el (1.4.0-0.1) over (1.3.2-0.4build3) ... 356s Preparing to unpack .../19-pastebinit_1.7.0-1_all.deb ... 356s Unpacking pastebinit (1.7.0-1) over (1.6.2-1) ... 356s Preparing to unpack .../20-python3-babel_2.14.0-1_all.deb ... 356s Unpacking python3-babel (2.14.0-1) over (2.10.3-3build1) ... 357s Preparing to unpack .../21-python-babel-localedata_2.14.0-1_all.deb ... 357s Unpacking python-babel-localedata (2.14.0-1) over (2.10.3-3build1) ... 357s Preparing to unpack .../22-python3-netaddr_0.10.1-1_all.deb ... 357s Unpacking python3-netaddr (0.10.1-1) over (0.8.0-2ubuntu1) ... 357s Setting up libsharpyuv0:ppc64el (1.4.0-0.1) ... 357s Setting up libapparmor1:ppc64el (4.0.1-0ubuntu1) ... 357s Setting up libxcb1:ppc64el (1.17.0-1) ... 357s Setting up python3-problem-report (2.28.1-0ubuntu4) ... 357s Setting up pastebinit (1.7.0-1) ... 357s Setting up libnss3:ppc64el (2:3.100-1) ... 357s Setting up libelf1t64:ppc64el (0.191-1) ... 357s Setting up python-babel-localedata (2.14.0-1) ... 357s Setting up python3-apport (2.28.1-0ubuntu4) ... 357s Setting up libdw1t64:ppc64el (0.191-1) ... 357s Setting up apparmor (4.0.1-0ubuntu1) ... 357s Installing new version of config file /etc/apparmor.d/abstractions/authentication ... 357s Installing new version of config file /etc/apparmor.d/abstractions/samba ... 357s Installing new version of config file /etc/apparmor.d/firefox ... 358s Reloading AppArmor profiles 359s Setting up libslang2:ppc64el (2.3.3-5) ... 359s Setting up libnvme1t64 (1.9-1) ... 359s Setting up dhcpcd-base (1:10.0.6-4) ... 359s Setting up libwebp7:ppc64el (1.4.0-0.1) ... 359s Setting up python3-netaddr (0.10.1-1) ... 359s Setting up libeatmydata1:ppc64el (131-2) ... 359s Setting up ubuntu-pro-client (32.1) ... 359s Installing new version of config file /etc/apparmor.d/ubuntu_pro_apt_news ... 361s Setting up libbpf1:ppc64el (1:1.4.1-1) ... 361s Setting up initramfs-tools-bin (0.142ubuntu27) ... 361s Setting up ubuntu-pro-client-l10n (32.1) ... 361s Setting up eatmydata (131-2) ... 361s Setting up python3-babel (2.14.0-1) ... 361s Setting up initramfs-tools-core (0.142ubuntu27) ... 361s Setting up initramfs-tools (0.142ubuntu27) ... 361s update-initramfs: deferring update (trigger activated) 361s Setting up apport-core-dump-handler (2.28.1-0ubuntu4) ... 362s Setting up apport (2.28.1-0ubuntu4) ... 362s Installing new version of config file /etc/apport/crashdb.conf ... 362s apport-autoreport.service is a disabled or a static unit not running, not starting it. 362s Processing triggers for libc-bin (2.39-0ubuntu8) ... 363s Processing triggers for man-db (2.12.0-4build2) ... 364s Processing triggers for initramfs-tools (0.142ubuntu27) ... 364s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 364s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 371s Reading package lists... 371s Building dependency tree... 371s Reading state information... 371s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 371s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 371s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 372s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 372s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 373s Reading package lists... 373s Reading package lists... 373s Building dependency tree... 373s Reading state information... 373s Calculating upgrade... 373s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 373s Reading package lists... 373s Building dependency tree... 373s Reading state information... 373s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 374s autopkgtest [01:57:14]: rebooting testbed after setup commands that affected boot 407s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 420s Reading package lists... 420s Building dependency tree... 420s Reading state information... 420s Starting pkgProblemResolver with broken count: 0 420s Starting 2 pkgProblemResolver with broken count: 0 420s Done 420s The following additional packages will be installed: 420s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 420s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 420s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 420s librdmacm1t64 lsscsi open-iscsi tgt 420s Suggested packages: 420s fio-examples gnuplot tgt-glusterfs tgt-rbd 420s Recommended packages: 420s finalrd 420s The following NEW packages will be installed: 420s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 420s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 420s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 420s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 420s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 420s Need to get 10.8 MB/10.8 MB of archives. 420s After this operation, 49.9 MB of additional disk space will be used. 420s Get:1 /tmp/autopkgtest.jtBdyL/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [736 B] 421s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu4 [54.4 kB] 421s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-0.3build3 [119 kB] 421s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu4 [389 kB] 421s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 421s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 421s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu6 [256 kB] 421s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4build3 [21.5 kB] 421s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4build3 [311 kB] 421s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4build3 [47.0 kB] 421s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4build3 [100 kB] 421s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.1-1 [97.4 kB] 421s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 421s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 421s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 421s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-2.1ubuntu3 [260 kB] 421s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-2.1ubuntu3 [280 kB] 421s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu6 [4050 kB] 422s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 422s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu6 [3612 kB] 422s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 422s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 422s Preconfiguring packages ... 422s Fetched 10.8 MB in 2s (6769 kB/s) 422s Selecting previously unselected package libopeniscsiusr. 423s (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 ... 72423 files and directories currently installed.) 423s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu4_ppc64el.deb ... 423s Unpacking libopeniscsiusr (2.1.9-3ubuntu4) ... 423s Selecting previously unselected package libisns0t64:ppc64el. 423s Preparing to unpack .../01-libisns0t64_0.101-0.3build3_ppc64el.deb ... 423s Unpacking libisns0t64:ppc64el (0.101-0.3build3) ... 423s Selecting previously unselected package open-iscsi. 423s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu4_ppc64el.deb ... 423s Unpacking open-iscsi (2.1.9-3ubuntu4) ... 423s Selecting previously unselected package librdmacm1t64:ppc64el. 423s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 423s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 423s Selecting previously unselected package libconfig-general-perl. 423s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 423s Unpacking libconfig-general-perl (2.65-2) ... 423s Selecting previously unselected package tgt. 423s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu6_ppc64el.deb ... 423s Unpacking tgt (1:1.0.85-1.1ubuntu6) ... 423s Selecting previously unselected package libgfxdr0:ppc64el. 423s Preparing to unpack .../06-libgfxdr0_11.1-4build3_ppc64el.deb ... 423s Unpacking libgfxdr0:ppc64el (11.1-4build3) ... 423s Selecting previously unselected package libglusterfs0:ppc64el. 423s Preparing to unpack .../07-libglusterfs0_11.1-4build3_ppc64el.deb ... 423s Unpacking libglusterfs0:ppc64el (11.1-4build3) ... 423s Selecting previously unselected package libgfrpc0:ppc64el. 423s Preparing to unpack .../08-libgfrpc0_11.1-4build3_ppc64el.deb ... 423s Unpacking libgfrpc0:ppc64el (11.1-4build3) ... 423s Selecting previously unselected package libgfapi0:ppc64el. 423s Preparing to unpack .../09-libgfapi0_11.1-4build3_ppc64el.deb ... 423s Unpacking libgfapi0:ppc64el (11.1-4build3) ... 423s Selecting previously unselected package libnbd0. 423s Preparing to unpack .../10-libnbd0_1.20.1-1_ppc64el.deb ... 423s Unpacking libnbd0 (1.20.1-1) ... 423s Selecting previously unselected package libdaxctl1:ppc64el. 423s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 423s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 423s Selecting previously unselected package libndctl6:ppc64el. 423s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 423s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 423s Selecting previously unselected package libpmem1:ppc64el. 423s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 423s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 423s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 423s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 423s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 423s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 423s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 423s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 423s Selecting previously unselected package librados2. 423s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu6_ppc64el.deb ... 423s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 423s Selecting previously unselected package libpmemobj1:ppc64el. 423s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 423s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 423s Selecting previously unselected package librbd1. 423s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu6_ppc64el.deb ... 423s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 423s Selecting previously unselected package fio. 423s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 423s Unpacking fio (3.37-1) ... 423s Selecting previously unselected package lsscsi. 423s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 423s Unpacking lsscsi (0.32-1build1) ... 423s Selecting previously unselected package autopkgtest-satdep. 423s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 423s Unpacking autopkgtest-satdep (0) ... 423s Setting up libconfig-general-perl (2.65-2) ... 423s Setting up libisns0t64:ppc64el (0.101-0.3build3) ... 423s Setting up libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 423s Setting up libnbd0 (1.20.1-1) ... 423s Setting up libopeniscsiusr (2.1.9-3ubuntu4) ... 423s Setting up libglusterfs0:ppc64el (11.1-4build3) ... 423s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 423s Setting up lsscsi (0.32-1build1) ... 423s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 423s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 423s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 423s Setting up tgt (1:1.0.85-1.1ubuntu6) ... 424s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 424s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 424s Setting up libgfxdr0:ppc64el (11.1-4build3) ... 424s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 424s Setting up open-iscsi (2.1.9-3ubuntu4) ... 425s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 425s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 425s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 426s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 426s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 426s Setting up libgfrpc0:ppc64el (11.1-4build3) ... 426s Setting up libgfapi0:ppc64el (11.1-4build3) ... 426s Setting up fio (3.37-1) ... 426s Setting up autopkgtest-satdep (0) ... 426s Processing triggers for man-db (2.12.0-4build2) ... 427s Processing triggers for initramfs-tools (0.142ubuntu27) ... 427s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 427s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 435s Processing triggers for libc-bin (2.39-0ubuntu8) ... 437s (Reading database ... 72664 files and directories currently installed.) 437s Removing autopkgtest-satdep (0) ... 439s autopkgtest [01:58:19]: test tgtbasedmpaths: [----------------------- 439s + targetname=iqn.2016-11.foo.com:target.iscsi 439s + pwd 439s + cwd=/tmp/autopkgtest.jtBdyL/build.bAG/src 439s + testdir=/mnt/tgtmpathtest 439s + localhost=127.0.0.1 439s + portal=127.0.0.1:3260 439s + maxpaths=4 439s + backfn=backingfile 439s + expectwwid=60000000000000000e00000000010001 439s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 439s + bglog=/tmp/autopkgtest.jtBdyL/tgtbasedmpaths-artifacts/test-background.log 439s + fioprep=/tmp/autopkgtest.jtBdyL/tgtbasedmpaths-artifacts/path-change-prep.fio 439s + fiovrfy=/tmp/autopkgtest.jtBdyL/tgtbasedmpaths-artifacts/path-change-check.fio 439s + service tgt restart 440s + truncate --size 100M backingfile 440s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 440s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 440s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.jtBdyL/build.bAG/src/backingfile 440s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 440s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 440s + echo login #1 440s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 440s login #1 440s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 440s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 440s + seq 2 4 440s extra login #2 440s + echo extra login #2 440s + iscsiadm --mode session -r 1 --op new 440s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 440s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 440s + echo extra login #3 440s + iscsiadm --mode session -r 1 --op new 440s extra login #3 440s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 440s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 440s + echo extra login #4 440s + extra login #4 440s iscsiadm --mode session -r 1 --op new 440s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 440s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 440s + udevadm settle 440s + sleep 5 445s + echo Status after initial setup 445s + tgtadm --lld iscsi --mode target --op show 445s Status after initial setup 445s Target 1: iqn.2016-11.foo.com:target.iscsi 445s System information: 445s Driver: iscsi 445s State: ready 445s I_T nexus information: 445s I_T nexus: 1 445s Initiator: iqn.2004-10.com.ubuntu:01:0b6e75f7b3e alias: autopkgtest 445s Connection: 0 445s IP Address: 127.0.0.1 445s I_T nexus: 2 445s Initiator: iqn.2004-10.com.ubuntu:01:0b6e75f7b3e alias: autopkgtest 445s Connection: 0 445s IP Address: 127.0.0.1 445s I_T nexus: 3 445s Initiator: iqn.2004-10.com.ubuntu:01:0b6e75f7b3e alias: autopkgtest 445s Connection: 0 445s IP Address: 127.0.0.1 445s I_T nexus: 4 445s Initiator: iqn.2004-10.com.ubuntu:01:0b6e75f7b3e alias: autopkgtest 445s Connection: 0 445s IP Address: 127.0.0.1 445s LUN information: 445s LUN: 0 445s Type: controller 445s SCSI ID: IET 00010000 445s SCSI SN: beaf10 445s Size: 0 MB, Block size: 1 445s Online: Yes 445s Removable media: No 445s Prevent removal: No 445s Readonly: No 445s SWP: No 445s Thin-provisioning: No 445s Backing store type: null 445s Backing store path: None 445s Backing store flags: 445s LUN: 1 445s Type: disk 445s SCSI ID: IET 00010001 445s SCSI SN: beaf11 445s Size: 105 MB, Block size: 512 445s Online: Yes 445s Removable media: No 445s Prevent removal: No 445s Readonly: No 445s SWP: No 445s Thin-provisioning: No 445s Backing store type: rdwr 445s Backing store path: /tmp/autopkgtest.jtBdyL/build.bAG/src/backingfile 445s Backing store flags: 445s Account information: 445s ACL information: 445s ALL 445s + tgtadm --lld iscsi --op show --mode conn --tid 1 445s Session: 4 445s Connection: 0 445s Initiator: iqn.2004-10.com.ubuntu:01:0b6e75f7b3e 445s IP Address: 127.0.0.1 445s Session: 3 445s Connection: 0 445s Initiator: iqn.2004-10.com.ubuntu:01:0b6e75f7b3e 445s IP Address: 127.0.0.1 445s Session: 2 445s Connection: 0 445s Initiator: iqn.2004-10.com.ubuntu:01:0b6e75f7b3e 445s IP Address: 127.0.0.1 445s Session: 1 445s Connection: 0 445s Initiator: iqn.2004-10.com.ubuntu:01:0b6e75f7b3e 445s IP Address: 127.0.0.1 445s + iscsiadm --mode session -P 1 445s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 445s Current Portal: 127.0.0.1:3260,1 445s Persistent Portal: 127.0.0.1:3260,1 445s ********** 445s Interface: 445s ********** 445s Iface Name: default 445s Iface Transport: tcp 445s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:0b6e75f7b3e 445s Iface IPaddress: 127.0.0.1 445s Iface HWaddress: default 445s Iface Netdev: default 445s SID: 1 445s iSCSI Connection State: LOGGED IN 445s iSCSI Session State: LOGGED_IN 445s Internal iscsid Session State: NO CHANGE 445s 445s ********** 445s Interface: 445s ********** 445s Iface Name: default 445s Iface Transport: tcp 445s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:0b6e75f7b3e 445s Iface IPaddress: 127.0.0.1 445s Iface HWaddress: default 445s Iface Netdev: default 445s SID: 2 445s iSCSI Connection State: LOGGED IN 445s iSCSI Session State: LOGGED_IN 445s Internal iscsid Session State: NO CHANGE 445s 445s ********** 445s Interface: 445s ********** 445s Iface Name: default 445s Iface Transport: tcp 445s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:0b6e75f7b3e 445s Iface IPaddress: 127.0.0.1 445s Iface HWaddress: default 445s Iface Netdev: default 445s SID: 3 445s iSCSI Connection State: LOGGED IN 445s iSCSI Session State: LOGGED_IN 445s Internal iscsid Session State: NO CHANGE 445s 445s ********** 445s Interface: 445s ********** 445s Iface Name: default 445s Iface Transport: tcp 445s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:0b6e75f7b3e 445s Iface IPaddress: 127.0.0.1 445s Iface HWaddress: default 445s Iface Netdev: default 445s SID: 4 445s iSCSI Connection State: LOGGED IN 445s iSCSI Session State: LOGGED_IN 445s Internal iscsid Session State: NO CHANGE 445s + lsscsi -liv 445s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 445s + multipath -v3 -ll 445s 47.181742 | [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 445s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 445s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/pci0000:00/0000:00:02.0/virtio1/host0/target0:0:0/0:0:0:0] 445s [1:0:0:0] storage IET Controller 0001 - - 445s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 445s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 445s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 33000000100000001 445s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 445s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 445s [2:0:0:0] storage IET Controller 0001 - - 445s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 445s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 445s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 445s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 445s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 445s [3:0:0:0] storage IET Controller 0001 - - 445s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 445s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 445s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 445s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 445s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 445s [4:0:0:0] storage IET Controller 0001 - - 445s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 445s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 445s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 445s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 445s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 445s NVMe module may not be loaded 445s set open fds limit to 1048576/1048576 445s 47.181862 | loading /lib/multipath/libchecktur.so checker 445s 47.181970 | checker tur: message table size = 3 445s 47.181980 | loading /lib/multipath/libprioconst.so prioritizer 445s 47.182104 | _init_foreign: foreign library "nvme" is not enabled 445s 47.188344 | sda: size = 167772160 445s 47.188569 | sda: vendor = QEMU 445s 47.188625 | sda: product = QEMU HARDDISK 445s 47.188658 | sda: rev = 2.5+ 445s 47.189472 | sda: h:b:t:l = 0:0:0:0 445s 47.189891 | sda: tgt_node_name = 445s 47.189920 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 445s 47.189924 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 445s 47.190127 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 445s 47.190156 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 445s 47.190173 | __sysfs_attr_get_value: attribute '/sys/devices/pci0000:00/0000:00:02.0/virtio1/host0/target0:0:0/0:0:0:0/vpd_pg80' can not be opened: No such file or directory 445s 47.190179 | failed to read sysfs vpd pg80: No such file or directory 445s 47.190437 | sda: fail to get serial 445s 47.190465 | sda: detect_checker = yes (setting: multipath internal) 445s 47.191659 | sda: path_checker = tur (setting: multipath internal) 445s 47.191689 | sda: checker timeout = 30 s (setting: kernel sysfs) 445s 47.192788 | sda: tur state = up 445s 47.193103 | sdb: size = 204800 445s 47.193265 | sdb: vendor = IET 445s 47.193309 | sdb: product = VIRTUAL-DISK 445s 47.193333 | sdb: rev = 0001 445s 47.193992 | sdb: h:b:t:l = 1:0:0:1 445s 47.194379 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 445s 47.194402 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 445s 47.194404 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 445s 47.194569 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 445s 47.194592 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 445s 47.194610 | sdb: serial = beaf11 445s 47.194613 | sdb: detect_checker = yes (setting: multipath internal) 445s 47.194988 | sdb: path_checker = tur (setting: multipath internal) 445s 47.195012 | sdb: checker timeout = 30 s (setting: kernel sysfs) 445s 47.195264 | sdb: tur state = up 445s 47.195420 | sdc: size = 204800 445s 47.195578 | sdc: vendor = IET 445s 47.195622 | sdc: product = VIRTUAL-DISK 445s 47.195647 | sdc: rev = 0001 445s 47.196373 | sdc: h:b:t:l = 2:0:0:1 445s 47.196755 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 445s 47.196778 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 445s 47.196781 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 445s 47.196938 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 445s 47.196961 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 445s 47.196977 | sdc: serial = beaf11 445s 47.196979 | sdc: detect_checker = yes (setting: multipath internal) 445s 47.197245 | sdc: path_checker = tur (setting: multipath internal) 445s 47.197269 | sdc: checker timeout = 30 s (setting: kernel sysfs) 445s 47.197508 | sdc: tur state = up 445s 47.197666 | sdd: size = 204800 445s 47.197825 | sdd: vendor = IET 445s 47.197868 | sdd: product = VIRTUAL-DISK 445s 47.197892 | sdd: rev = 0001 445s 47.198611 | sdd: h:b:t:l = 3:0:0:1 445s 47.198989 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 445s 47.199011 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 445s 47.199014 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 445s 47.199178 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 445s 47.199201 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 445s 47.199228 | sdd: serial = beaf11 445s 47.199230 | sdd: detect_checker = yes (setting: multipath internal) 445s 47.199488 | sdd: path_checker = tur (setting: multipath internal) 445s 47.199511 | sdd: checker timeout = 30 s (setting: kernel sysfs) 445s 47.199699 | sdd: tur state = up 445s 47.199854 | sde: size = 204800 445s 47.200020 | sde: vendor = IET 445s 47.200049 | sde: product = VIRTUAL-DISK 445s 47.200095 | sde: rev = 0001 445s 47.200809 | sde: h:b:t:l = 4:0:0:1 445s 47.201186 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 445s 47.201209 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 445s 47.201211 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 445s 47.201377 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 445s 47.201399 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 445s 47.201415 | sde: serial = beaf11 445s 47.201418 | sde: detect_checker = yes (setting: multipath internal) 445s 47.201665 | sde: path_checker = tur (setting: multipath internal) 445s 47.201688 | sde: checker timeout = 30 s (setting: kernel sysfs) 445s 47.201872 | sde: tur state = up 445s 47.201986 | loop0: device node name blacklisted 445s 47.202094 | loop1: device node name blacklisted 445s 47.202201 | loop2: device node name blacklisted 445s 47.202305 | loop3: device node name blacklisted 445s 47.202409 | loop4: device node name blacklisted 445s 47.202511 | loop5: device node name blacklisted 445s 47.202615 | loop6: device node name blacklisted 445s 47.202717 | loop7: device node name blacklisted 445s 47.202824 | dm-0: device node name blacklisted 445s 47.203792 | multipath-tools v0.9.4 (12/19, 2022) 445s 47.203821 | libdevmapper version 1.02.185 445s 47.203979 | kernel device mapper v4.48.0 445s 47.204043 | DM multipath kernel driver v1.14.0 445s 47.204169 | sdc: size = 204800 445s 47.204193 | sdc: vendor = IET 445s 47.204196 | sdc: product = VIRTUAL-DISK 445s 47.204198 | sdc: rev = 0001 445s 47.204817 | sdc: h:b:t:l = 2:0:0:1 445s 47.204948 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 445s 47.204987 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 445s 47.204990 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 445s 47.205002 | sdc: serial = beaf11 445s 47.205214 | sdc: tur state = up 445s 47.205235 | sdc: uid = 360000000000000000e00000000010001 (udev) 445s 47.205239 | sdc: detect_prio = yes (setting: multipath internal) 445s 47.205243 | sdc: prio = const (setting: multipath internal) 445s 47.205245 | sdc: prio args = "" (setting: multipath internal) 445s 47.205247 | sdc: const prio = 1 445s 47.205270 | sdb: size = 204800 445s 47.205275 | sdb: vendor = IET 445s 47.205278 | sdb: product = VIRTUAL-DISK 445s 47.205280 | sdb: rev = 0001 445s 47.205884 | sdb: h:b:t:l = 1:0:0:1 445s 47.206013 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 445s 47.206051 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 445s 47.206053 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 445s 47.206066 | sdb: serial = beaf11 445s 47.206246 | sdb: tur state = up 445s 47.206267 | sdb: uid = 360000000000000000e00000000010001 (udev) 445s 47.206270 | sdb: detect_prio = yes (setting: multipath internal) 445s 47.206272 | sdb: prio = const (setting: multipath internal) 445s 47.206274 | sdb: prio args = "" (setting: multipath internal) 445s 47.206277 | sdb: const prio = 1 445s 47.206300 | sdd: size = 204800 445s 47.206305 | sdd: vendor = IET 445s 47.206308 | sdd: product = VIRTUAL-DISK 445s 47.206310 | sdd: rev = 0001 445s 47.206913 | sdd: h:b:t:l = 3:0:0:1 445s 47.207043 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 445s 47.207081 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 445s 47.207084 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 445s 47.207096 | sdd: serial = beaf11 445s 47.207307 | sdd: tur state = up 445s 47.207329 | sdd: uid = 360000000000000000e00000000010001 (udev) 445s 47.207331 | sdd: detect_prio = yes (setting: multipath internal) 445s 47.207334 | sdd: prio = const (setting: multipath internal) 445s 47.207336 | sdd: prio args = "" (setting: multipath internal) 445s 47.207338 | sdd: const prio = 1 445s 47.207361 | sde: size = 204800 445s 47.207365 | sde: vendor = IET 445s 47.207368 | sde: product = VIRTUAL-DISK 445s 47.207371 | sde: rev = 0001 445s 47.207969 | sde: h:b:t:l = 4:0:0:1 445s 47.208134 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 445s 47.208179 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 445s 47.208182 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 445s 47.208193 | sde: serial = beaf11 445s 47.208372 | sde: tur state = up 445s 47.208395 | sde: uid = 360000000000000000e00000000010001 (udev) 445s 47.208397 | sde: detect_prio = yes (setting: multipath internal) 445s 47.208400 | sde: prio = const (setting: multipath internal) 445s 47.208402 | sde: prio args = "" (setting: multipath internal) 445s 47.208404 | sde: const prio = 1 445s 47.209207 | unloading tur checker 445s 47.209249 | unloading const prioritizer 445s ===== paths list ===== 445s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 445s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 445s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 445s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 445s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 445s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 445s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 445s size=100M features='0' hwhandler='0' wp=rw 445s |-+- policy='service-time 0' prio=1 status=active 445s | `- 2:0:0:1 sdc 8:32 active ready running 445s |-+- policy='service-time 0' prio=1 status=enabled 445s | `- 1:0:0:1 sdb 8:16 active ready running 445s |-+- policy='service-time 0' prio=1 status=enabled 445s | `- 3:0:0:1 sdd 8:48 active ready running 445s `-+- policy='service-time 0' prio=1 status=enabled 445s `- 4:0:0:1 sde 8:64 active ready running 445s mpatha: 0 204800 multipath 0 0 4 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 service-time 0 1 2 8:64 1 1 445s Test WWN should now point to DM 445s ../../dm-0 445s Creating filesystem with 25600 4k blocks and 25600 inodes 445s 445s Allocating group tables: 0/1 done 445s Writing inode tables: 0/1 done 445s Creating journal (1024 blocks): done 445s Writing superblocks and filesystem accounting information: 0/1 + dmsetup table 445s + echo Test WWN should now point to DM 445s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 445s + grep dm 445s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 445s mke2fs 1.47.0 (5-Feb-2023) 445s done 445s 445s + udevadm settle 445s + sleep 3s 448s + mkdir -p /mnt/tgtmpathtest 448s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 448s + cat 448s + cat 448s + fio --max-jobs=4 /tmp/autopkgtest.jtBdyL/tgtbasedmpaths-artifacts/path-change-prep.fio 448s 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 448s fio-3.37 448s Starting 1 thread 448s write-phase: Laying out IO file (1 file / 17592186044415MiB) 449s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 449s 449s write-phase: (groupid=0, jobs=1): err= 0: pid=5616: Mon May 20 01:58:29 2024 449s write: IOPS=1771, BW=111MiB/s (116MB/s)(87.6MiB/792msec); 0 zone resets 449s clat (usec): min=259, max=7930, avg=540.53, stdev=273.91 449s lat (usec): min=279, max=7947, avg=562.77, stdev=275.31 449s clat percentiles (usec): 449s | 1.00th=[ 306], 5.00th=[ 367], 10.00th=[ 400], 20.00th=[ 437], 449s | 30.00th=[ 453], 40.00th=[ 474], 50.00th=[ 510], 60.00th=[ 545], 449s | 70.00th=[ 578], 80.00th=[ 603], 90.00th=[ 644], 95.00th=[ 693], 449s | 99.00th=[ 1418], 99.50th=[ 1860], 99.90th=[ 3032], 99.95th=[ 7963], 449s | 99.99th=[ 7963] 449s bw ( KiB/s): min=103089, max=103089, per=90.99%, avg=103089.00, stdev= 0.00, samples=1 449s iops : min= 1610, max= 1610, avg=1610.00, stdev= 0.00, samples=1 449s lat (usec) : 500=47.68%, 750=48.75%, 1000=1.35% 449s lat (msec) : 2=1.78%, 4=0.29%, 10=0.07% 449s cpu : usr=5.18%, sys=5.18%, ctx=1405, majf=0, minf=0 449s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 449s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 449s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 449s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 449s latency : target=0, window=0, percentile=100.00%, depth=1 449s 449s Run status group 0 (all jobs): 449s WRITE: bw=111MiB/s (116MB/s), 111MiB/s-111MiB/s (116MB/s-116MB/s), io=87.6MiB (91.9MB), run=792-792msec 449s 449s Disk stats (read/write): 449s dm-0: ios=1/1060, sectors=8/135680, merge=0/0, ticks=4/592, in_queue=595, util=87.03%, aggrios=0/351, aggsectors=2/44884, aggrmerge=0/0, aggrticks=0/178, aggrin_queue=179, aggrutil=87.42% 449s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 449s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 449s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 449s sdc: ios=1/1404, sectors=8/179536, merge=0/0, ticks=3/712, in_queue=717, util=87.42% 449s Starting the path changes in background 449s + echo Starting the path changes in background 449s + date +Pre FIO %H:%M:%S.%N 449s + fio --max-jobs=4 /tmp/autopkgtest.jtBdyL/tgtbasedmpaths-artifacts/path-change-check.fio 449s Pre FIO 01:58:29.591855622 449s 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 449s fio-3.37 449s Starting 1 thread 629s 629s verify-phase: (groupid=0, jobs=1): err= 0: pid=5623: Mon May 20 02:01:29 2024 629s read: IOPS=3368, BW=211MiB/s (221MB/s)(37.0GiB/180001msec) 629s clat (usec): min=84, max=54063, avg=274.09, stdev=282.75 629s lat (usec): min=84, max=54063, avg=274.20, stdev=282.76 629s clat percentiles (usec): 629s | 1.00th=[ 117], 5.00th=[ 151], 10.00th=[ 174], 20.00th=[ 190], 629s | 30.00th=[ 204], 40.00th=[ 217], 50.00th=[ 241], 60.00th=[ 281], 629s | 70.00th=[ 314], 80.00th=[ 351], 90.00th=[ 396], 95.00th=[ 433], 629s | 99.00th=[ 545], 99.50th=[ 963], 99.90th=[ 1483], 99.95th=[ 1893], 629s | 99.99th=[ 7439] 629s bw ( KiB/s): min=127488, max=427648, per=100.00%, avg=215845.84, stdev=54214.36, samples=359 629s iops : min= 1992, max= 6682, avg=3372.58, stdev=847.11, samples=359 629s lat (usec) : 100=0.71%, 250=51.80%, 500=46.28%, 750=0.45%, 1000=0.30% 629s lat (msec) : 2=0.41%, 4=0.03%, 10=0.01%, 20=0.01%, 50=0.01% 629s lat (msec) : 100=0.01% 629s cpu : usr=9.43%, sys=7.24%, ctx=606391, majf=0, minf=1 629s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 629s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 629s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 629s issued rwts: total=606320,0,0,0 short=0,0,0,0 dropped=0,0,0,0 629s latency : target=0, window=0, percentile=100.00%, depth=1 629s 629s Run status group 0 (all jobs): 629s READ: bw=211MiB/s (221MB/s), 211MiB/s-211MiB/s (221MB/s-221MB/s), io=37.0GiB (39.7GB), run=180001-180001msec 629s 629s Disk stats (read/write): 629s dm-0: ios=606519/9, sectors=77578552/12912, merge=30/8, ticks=169672/84, in_queue=169797, util=99.94%, aggrios=40697/2, aggsectors=5205326/3228, aggrmerge=0/0, aggrticks=10941/10, aggrin_queue=10952, aggrutil=99.57% 629s sdd: ios=28227/0, sectors=3610496/0, merge=0/0, ticks=8830/0, in_queue=8829, util=32.96% 629s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 629s sde: ios=67548/0, sectors=8640000/0, merge=0/0, ticks=17545/0, in_queue=17545, util=40.01% 629s sdc: ios=67013/8, sectors=8570808/12912, merge=0/0, ticks=17392/43, in_queue=17434, util=99.57% 629s Post FIO 02:01:29.958003003 629s FIO verify test with changing paths - OK 629s Report log of background activity 629s + date +Post FIO %H:%M:%S.%N 629s + echo FIO verify test with changing paths - OK 629s + echo Report log of background activity 629s + cat /tmp/autopkgtest.jtBdyL/tgtbasedmpaths-artifacts/test-background.log 630s + iscsiadm --mode session 630s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s + sleep 10s 630s + date +MP report (expect 4) %H:%M:%S.%N 630s MP report (expect 4) 01:58:39.598298428 630s + multipath -ll 630s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 630s size=100M features='0' hwhandler='0' wp=rw 630s |-+- policy='service-time 0' prio=1 status=active 630s | `- 2:0:0:1 sdc 8:32 active ready running 630s |-+- policy='service-time 0' prio=1 status=enabled 630s | `- 1:0:0:1 sdb 8:16 active ready running 630s |-+- policy='service-time 0' prio=1 status=enabled 630s | `- 3:0:0:1 sdd 8:48 active ready running 630s `-+- policy='service-time 0' prio=1 status=enabled 630s `- 4:0:0:1 sde 8:64 active ready running 630s + date +UN-plug path 1 %H:%M:%S.%N 630s UN-plug path 1 01:58:39.626091313 630s + iscsiadm --mode session -r 1 -u 630s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 630s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 630s + iscsiadm --mode session 630s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s + sleep 10s 630s + date +MP report (expect 3) %H:%M:%S.%N 630s MP report (expect 3) 01:58:49.736864825 630s + multipath -ll 630s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 630s size=100M features='0' hwhandler='0' wp=rw 630s |-+- policy='service-time 0' prio=1 status=active 630s | `- 2:0:0:1 sdc 8:32 active ready running 630s |-+- policy='service-time 0' prio=1 status=enabled 630s | `- 3:0:0:1 sdd 8:48 active ready running 630s `-+- policy='service-time 0' prio=1 status=enabled 630s `- 4:0:0:1 sde 8:64 active ready running 630s + date +UN-plug path 2 %H:%M:%S.%N 630s UN-plug path 2 01:58:49.757702940 630s + iscsiadm --mode session -r 2 -u 630s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 630s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 630s + iscsiadm --mode session 630s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s + sleep 10s 630s + date +MP report (expect 2) %H:%M:%S.%N 630s MP report (expect 2) 01:58:59.869327797 630s + multipath -ll 630s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 630s size=100M features='0' hwhandler='0' wp=rw 630s |-+- policy='service-time 0' prio=1 status=active 630s | `- 3:0:0:1 sdd 8:48 active ready running 630s `-+- policy='service-time 0' prio=1 status=enabled 630s `- 4:0:0:1 sde 8:64 active ready running 630s + date +UN-plug path 3 %H:%M:%S.%N 630s UN-plug path 3 01:58:59.887678405 630s + iscsiadm --mode session -r 3 -u 630s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 630s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 630s + iscsiadm --mode session 630s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s + sleep 10s 630s + date +MP report (expect 1) %H:%M:%S.%N 630s MP report (expect 1) 01:59:09.993162329 630s + multipath -ll 630s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 630s size=100M features='0' hwhandler='0' wp=rw 630s `-+- policy='service-time 0' prio=1 status=active 630s `- 4:0:0:1 sde 8:64 active ready running 630s + date +Add paths 5/6/7/8 %H:%M:%S.%N 630s Add paths 5/6/7/8 01:59:10.007745385 630s + iscsiadm --mode session -r 4 --op new 630s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 630s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 630s + iscsiadm --mode session -r 4 --op new 630s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 630s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 630s + iscsiadm --mode session -r 4 --op new 630s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 630s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 630s + iscsiadm --mode session -r 4 --op new 630s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 630s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 630s + iscsiadm --mode session 630s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s + sleep 10s 630s + date +MP report (expect 5) %H:%M:%S.%N 630s MP report (expect 5) 01:59:20.149781032 630s + multipath -ll 630s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 630s size=100M features='0' hwhandler='0' wp=rw 630s |-+- policy='service-time 0' prio=1 status=active 630s | `- 4:0:0:1 sde 8:64 active ready running 630s |-+- policy='service-time 0' prio=1 status=enabled 630s | `- 1:0:0:1 sdb 8:16 active ready running 630s |-+- policy='service-time 0' prio=1 status=enabled 630s | `- 2:0:0:1 sdc 8:32 active ready running 630s |-+- policy='service-time 0' prio=1 status=enabled 630s | `- 3:0:0:1 sdd 8:48 active ready running 630s `-+- policy='service-time 0' prio=1 status=enabled 630s `- 5:0:0:1 sdf 8:80 active ready running 630s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 630s UN-plug multiple paths 4/7/8 01:59:20.178762005 630s + iscsiadm --mode session -r 4 -u 630s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 630s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 630s + iscsiadm --mode session -r 7 -u 630s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 630s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 630s + iscsiadm --mode session -r 8 -u 630s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 630s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 630s + iscsiadm --mode session 630s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 630s + sleep 10s 630s + date +Restart multipath daemon %H:%M:%S.%N 630s Restart multipath daemon 01:59:30.468473382 630s + systemctl restart multipathd 630s + sleep 10s 630s + date +Final background report (expect 2) %H:%M:%S.%N 630s Final background report (expect 2) 01:59:40.558949774 630s + multipath -ll 630s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 630s size=100M features='0' hwhandler='0' wp=rw 630s |-+- policy='service-time 0' prio=1 status=active 630s | `- 1:0:0:1 sdb 8:16 active ready running 630s `-+- policy='service-time 0' prio=1 status=enabled 630s `- 2:0:0:1 sdc 8:32 active ready running 630s Final stats 630s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 630s iSCSI SNMP: 630s txdata_octets: 21290712 630s rxdata_octets: 29045797700 630s noptx_pdus: 0 630s scsicmd_pdus: 443289 630s tmfcmd_pdus: 0 630s login_pdus: 0 630s text_pdus: 0 630s dataout_pdus: 0 630s logout_pdus: 0 630s snack_pdus: 0 630s noprx_pdus: 0 630s scsirsp_pdus: 443289 630s tmfrsp_pdus: 0 630s textrsp_pdus: 0 630s datain_pdus: 443255 630s logoutrsp_pdus: 0 630s r2t_pdus: 0 630s async_pdus: 0 630s rjt_pdus: 0 630s digest_err: 0 630s timeout_err: 0 630s iSCSI Extended: 630s tx_sendpage_failures: 0 630s rx_discontiguous_hdr: 0 630s eh_abort_cnt: 0 630s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 630s iSCSI SNMP: 630s txdata_octets: 6552 630s rxdata_octets: 1515012 630s noptx_pdus: 0 630s scsicmd_pdus: 105 630s tmfcmd_pdus: 0 630s login_pdus: 0 630s text_pdus: 0 630s dataout_pdus: 0 630s logout_pdus: 0 630s snack_pdus: 0 630s noprx_pdus: 0 630s scsirsp_pdus: 105 630s tmfrsp_pdus: 0 630s textrsp_pdus: 0 630s datain_pdus: 83 630s logoutrsp_pdus: 0 630s r2t_pdus: 0 630s async_pdus: 0 630s rjt_pdus: 0 630s digest_err: 0 630s timeout_err: 0 630s iSCSI Extended: 630s tx_sendpage_failures: 0 630s rx_discontiguous_hdr: 0 630s eh_abort_cnt: 0 630s May 09 10:16:05 adtubuntu-oracular-ppc64el-server-20240507 multipathd[261]: multipathd v0.9.4: start up 630s May 09 10:16:06 adtubuntu-oracular-ppc64el-server-20240507 multipathd[261]: reconfigure: setting up paths and maps 630s May 09 10:16:05 adtubuntu-oracular-ppc64el-server-20240507 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 630s May 09 10:17:22 adtubuntu-oracular-ppc64el-server-20240508 multipathd[261]: multipathd: shut down 630s May 09 10:17:22 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 630s May 09 10:17:22 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: multipathd.service: Deactivated successfully. 630s May 09 10:17:22 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 630s -- Boot 8055b427e6ec4dd3bb1991930f846ca7 -- 630s May 09 10:18:38 adtubuntu-oracular-ppc64el-server-20240508 multipathd[263]: multipathd v0.9.4: start up 630s May 09 10:18:38 adtubuntu-oracular-ppc64el-server-20240508 multipathd[263]: reconfigure: setting up paths and maps 630s May 09 10:18:37 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 630s May 09 10:19:50 adtubuntu-oracular-ppc64el-server-20240508 multipathd[263]: multipathd: shut down 630s May 09 10:19:50 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 630s May 09 10:19:50 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: multipathd.service: Deactivated successfully. 630s May 09 10:19:50 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 630s -- Boot 61f93651e0fe46dab23d397c73070176 -- 630s May 20 01:56:25 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 630s May 20 01:56:25 adtubuntu-oracular-ppc64el-server-20240508 multipathd[334]: multipathd v0.9.4: start up 630s May 20 01:56:25 adtubuntu-oracular-ppc64el-server-20240508 multipathd[334]: reconfigure: setting up paths and maps 630s May 20 01:56:25 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 630s May 20 01:57:17 autopkgtest multipathd[334]: multipathd: shut down 630s May 20 01:57:17 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 630s May 20 01:57:17 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 630s May 20 01:57:17 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 630s -- Boot 6c5a5c85a32843738364bf5d674b5419 -- 630s May 20 01:57:41 autopkgtest multipathd[313]: multipathd v0.9.4: start up 630s May 20 01:57:41 autopkgtest multipathd[313]: reconfigure: setting up paths and maps 630s May 20 01:57:41 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 630s May 20 01:58:20 autopkgtest multipathd[313]: mpatha: addmap [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:16 1] 630s May 20 01:58:20 autopkgtest multipathd[313]: sdc [8:32]: path added to devmap mpatha 630s May 20 01:58:20 autopkgtest multipathd[313]: mpatha: sdb - tur checker reports path is up 630s May 20 01:58:20 autopkgtest multipathd[313]: 8:16: reinstated 630s May 20 01:58:20 autopkgtest multipathd[313]: mpatha: remaining active paths: 2 630s May 20 01:58:20 autopkgtest multipathd[313]: mpatha: performing delayed actions 630s May 20 01:58:20 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 4 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 service-time 0 1 1 8:64 1] 630s May 20 01:58:39 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 630s May 20 01:58:39 autopkgtest multipathd[313]: check_removed_paths: sdb: freeing path in removed state 630s May 20 01:58:39 autopkgtest multipathd[313]: 8:16: path removed from map mpat+ sync 630s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 630s + echo Final stats 630s + iscsiadm --mode session --stats 630s + journalctl --no-pager -u multipathd 630s ha 630s May 20 01:58:49 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 630s May 20 01:58:49 autopkgtest multipathd[313]: check_removed_paths: sdc: freeing path in removed state 630s May 20 01:58:49 autopkgtest multipathd[313]: 8:32: path removed from map mpatha 630s May 20 01:58:59 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 630s May 20 01:58:59 autopkgtest multipathd[313]: check_removed_paths: sdd: freeing path in removed state 630s May 20 01:58:59 autopkgtest multipathd[313]: 8:48: path removed from map mpatha 630s May 20 01:59:10 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1] 630s May 20 01:59:10 autopkgtest multipathd[313]: sdb [8:16]: path added to devmap mpatha 630s May 20 01:59:10 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 630s May 20 01:59:10 autopkgtest multipathd[313]: sdc [8:32]: path added to devmap mpatha 630s May 20 01:59:10 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 630s May 20 01:59:10 autopkgtest multipathd[313]: sdd [8:48]: path added to devmap mpatha 630s May 20 01:59:10 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:80 1] 630s May 20 01:59:10 autopkgtest multipathd[313]: sdf [8:80]: path added to devmap mpatha 630s May 20 01:59:20 autopkgtest multipathd[313]: sde: mark as failed 630s May 20 01:59:20 autopkgtest multipathd[313]: mpatha: remaining active paths: 4 630s May 20 01:59:20 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:80 1] 630s May 20 01:59:20 autopkgtest multipathd[313]: check_removed_paths: sde: freeing path in removed state 630s May 20 01:59:20 autopkgtest multipathd[313]: 8:64: path removed from map mpatha 630s May 20 01:59:20 autopkgtest multipathd[313]: checker failed path 8:48 in map mpatha 630s May 20 01:59:20 autopkgtest multipathd[313]: mpatha: remaining active paths: 3 630s May 20 01:59:20 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:80 1] 630s May 20 01:59:20 autopkgtest multipathd[313]: check_removed_paths: sdd: freeing path in removed state 630s May 20 01:59:20 autopkgtest multipathd[313]: 8:48: path removed from map mpatha 630s May 20 01:59:20 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 630s May 20 01:59:20 autopkgtest multipathd[313]: check_removed_paths: sdf: freeing path in removed state 630s May 20 01:59:20 autopkgtest multipathd[313]: 8:80: path removed from map mpatha 630s May 20 01:59:30 autopkgtest multipathd[313]: multipathd: shut down 630s May 20 01:59:30 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 630s May 20 01:59:30 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 630s May 20 01:59:30 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 630s May 20 01:59:30 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 630s May 20 01:59:30 autopkgtest multipathd[5993]: multipathd v0.9.4: start up 630s May 20 01:59:30 autopkgtest multipathd[5993]: reconfigure: setting up paths and maps 630s May 20 01:59:30 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 630s Check final path status 630s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 630s size=100M features='0' hwhandler='0' wp=rw 630s |-+- policy='service-time 0' prio=1 status=active 630s | `- 1:0:0:1 sdb 8:16 active ready running 630s `-+- policy='service-time 0' prio=1 status=enabled 630s `- 2:0:0:1 sdc 8:32 active ready running 630s OK 630s + echo Check final path status 630s + multipath -ll 630s + multipath -ll 630s + grep --count status= 630s + diskc=2 630s + multipath -ll 630s + grep --count status=active 630s + diska=1 630s + multipath -ll 630s + grep --count status=enabled 630s + diske=1 630s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 630s + echo OK 630s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 630s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 630s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 630s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 630s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 630s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 630s autopkgtest [02:01:30]: test tgtbasedmpaths: -----------------------] 631s autopkgtest [02:01:31]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 631s tgtbasedmpaths PASS 631s autopkgtest [02:01:31]: @@@@@@@@@@@@@@@@@@@@ summary 631s kpartx-file-loopback PASS 631s tgtbasedmpaths PASS 642s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240520-015100-juju-7f2275-prod-proposed-migration-environment-2-47fa88be-9345-4f51-b10b-0fe0e919ad32 from image adt/ubuntu-oracular-ppc64el-server-20240509.img (UUID 1c85ce1c-4944-4b4e-a1c6-2159ec573517)... 642s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240520-015100-juju-7f2275-prod-proposed-migration-environment-2-47fa88be-9345-4f51-b10b-0fe0e919ad32 from image adt/ubuntu-oracular-ppc64el-server-20240509.img (UUID 1c85ce1c-4944-4b4e-a1c6-2159ec573517)...