0s autopkgtest [21:33:17]: starting date and time: 2024-05-19 21:33:17+0000 0s autopkgtest [21:33:17]: git checkout: 699e7f9f ssh-setup/nova: explicitely set 'fqdn' in cloud-init 0s autopkgtest [21:33:17]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.4yd2fs4x/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:systemd,src:dhcpcd,src:dpdk,src:suricata --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=systemd/256~rc2-1ubuntu1 dhcpcd/1:10.0.6-5 dpdk/23.11.1-1 suricata/1:7.0.5-1' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos02-ppc64el-7.secgroup --name adt-oracular-ppc64el-multipath-tools-20240519-213316-juju-7f2275-prod-proposed-migration-environment-3-8e6051f9-cd72-4a84-8a09-bb588e814fe9 --image adt/ubuntu-oracular-ppc64el-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/ 137s autopkgtest [21:35:34]: testbed dpkg architecture: ppc64el 137s autopkgtest [21:35:34]: testbed apt version: 2.7.14build2 137s autopkgtest [21:35:34]: @@@@@@@@@@@@@@@@@@@@ test bed setup 138s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [73.9 kB] 138s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [7400 B] 138s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [1964 B] 138s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [108 kB] 138s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [1391 kB] 139s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [178 kB] 139s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [1660 kB] 139s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [15.1 kB] 140s Fetched 3436 kB in 2s (1778 kB/s) 140s Reading package lists... 142s Reading package lists... 143s Building dependency tree... 143s Reading state information... 143s Calculating upgrade... 143s The following package was automatically installed and is no longer required: 143s systemd-dev 143s Use 'sudo apt autoremove' to remove it. 143s The following packages will be upgraded: 143s apport apport-core-dump-handler dhcpcd-base eatmydata libbpf1 libcap-ng0 143s libdw1t64 libeatmydata1 libelf1t64 libnss-systemd libnss3 libnvme1t64 143s libpam-systemd libsharpyuv0 libslang2 libsystemd-shared libsystemd0 libudev1 143s libwebp7 libxcb1 pastebinit python-babel-localedata python3-apport 143s python3-babel python3-netaddr python3-problem-report systemd systemd-dev 143s systemd-resolved systemd-sysv systemd-timesyncd ubuntu-pro-client 143s ubuntu-pro-client-l10n udev 143s 34 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 143s Need to get 21.3 MB of archives. 143s After this operation, 1005 kB of additional disk space will be used. 143s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-dev all 256~rc2-1ubuntu1 [107 kB] 144s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-timesyncd ppc64el 256~rc2-1ubuntu1 [37.8 kB] 144s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-resolved ppc64el 256~rc2-1ubuntu1 [363 kB] 144s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd-shared ppc64el 256~rc2-1ubuntu1 [2463 kB] 144s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd0 ppc64el 256~rc2-1ubuntu1 [543 kB] 144s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-sysv ppc64el 256~rc2-1ubuntu1 [11.8 kB] 144s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnss-systemd ppc64el 256~rc2-1ubuntu1 [210 kB] 144s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpam-systemd ppc64el 256~rc2-1ubuntu1 [318 kB] 144s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd ppc64el 256~rc2-1ubuntu1 [3956 kB] 144s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el udev ppc64el 256~rc2-1ubuntu1 [2107 kB] 144s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libudev1 ppc64el 256~rc2-1ubuntu1 [213 kB] 144s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-problem-report all 2.28.1-0ubuntu4 [23.9 kB] 144s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-apport all 2.28.1-0ubuntu4 [92.1 kB] 144s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el apport-core-dump-handler all 2.28.1-0ubuntu4 [16.9 kB] 144s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el apport all 2.28.1-0ubuntu4 [83.4 kB] 144s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libcap-ng0 ppc64el 0.8.5-1 [16.0 kB] 144s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dhcpcd-base ppc64el 1:10.0.6-5 [273 kB] 144s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdw1t64 ppc64el 0.191-1 [303 kB] 144s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libelf1t64 ppc64el 0.191-1 [68.0 kB] 144s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el libbpf1 ppc64el 1:1.4.1-1 [220 kB] 144s Get:21 http://ftpmaster.internal/ubuntu oracular/main ppc64el libslang2 ppc64el 2.3.3-5 [503 kB] 144s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el ubuntu-pro-client-l10n ppc64el 32.1 [19.4 kB] 144s Get:23 http://ftpmaster.internal/ubuntu oracular/main ppc64el ubuntu-pro-client ppc64el 32.1 [229 kB] 144s Get:24 http://ftpmaster.internal/ubuntu oracular/main ppc64el libxcb1 ppc64el 1.17.0-1 [56.6 kB] 144s Get:25 http://ftpmaster.internal/ubuntu oracular/main ppc64el libeatmydata1 ppc64el 131-2 [7522 B] 144s Get:26 http://ftpmaster.internal/ubuntu oracular/main ppc64el eatmydata all 131-2 [5576 B] 144s Get:27 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnss3 ppc64el 2:3.100-1 [1848 kB] 144s Get:28 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnvme1t64 ppc64el 1.9-1 [100 kB] 144s Get:29 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsharpyuv0 ppc64el 1.4.0-0.1 [22.0 kB] 144s Get:30 http://ftpmaster.internal/ubuntu oracular/main ppc64el libwebp7 ppc64el 1.4.0-0.1 [309 kB] 144s Get:31 http://ftpmaster.internal/ubuntu oracular/main ppc64el pastebinit all 1.7.0-1 [14.9 kB] 144s Get:32 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-babel all 2.14.0-1 [96.4 kB] 144s Get:33 http://ftpmaster.internal/ubuntu oracular/main ppc64el python-babel-localedata all 2.14.0-1 [6385 kB] 145s Get:34 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-netaddr all 0.10.1-1 [322 kB] 145s Fetched 21.3 MB in 2s (14.2 MB/s) 145s (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.) 145s Preparing to unpack .../systemd-dev_256~rc2-1ubuntu1_all.deb ... 145s Unpacking systemd-dev (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 145s Preparing to unpack .../systemd-timesyncd_256~rc2-1ubuntu1_ppc64el.deb ... 145s Unpacking systemd-timesyncd (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 145s Preparing to unpack .../systemd-resolved_256~rc2-1ubuntu1_ppc64el.deb ... 145s Unpacking systemd-resolved (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 145s Preparing to unpack .../libsystemd-shared_256~rc2-1ubuntu1_ppc64el.deb ... 145s Unpacking libsystemd-shared:ppc64el (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 145s Preparing to unpack .../libsystemd0_256~rc2-1ubuntu1_ppc64el.deb ... 145s Unpacking libsystemd0:ppc64el (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 145s Setting up libsystemd0:ppc64el (256~rc2-1ubuntu1) ... 145s (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.) 145s Preparing to unpack .../0-systemd-sysv_256~rc2-1ubuntu1_ppc64el.deb ... 145s Unpacking systemd-sysv (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 146s Preparing to unpack .../1-libnss-systemd_256~rc2-1ubuntu1_ppc64el.deb ... 146s Unpacking libnss-systemd:ppc64el (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 146s Preparing to unpack .../2-libpam-systemd_256~rc2-1ubuntu1_ppc64el.deb ... 146s Unpacking libpam-systemd:ppc64el (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 146s Preparing to unpack .../3-systemd_256~rc2-1ubuntu1_ppc64el.deb ... 146s Unpacking systemd (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 146s Preparing to unpack .../4-udev_256~rc2-1ubuntu1_ppc64el.deb ... 146s Unpacking udev (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 146s Preparing to unpack .../5-libudev1_256~rc2-1ubuntu1_ppc64el.deb ... 146s Unpacking libudev1:ppc64el (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 146s Setting up libudev1:ppc64el (256~rc2-1ubuntu1) ... 146s (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 ... 72196 files and directories currently installed.) 146s Preparing to unpack .../python3-problem-report_2.28.1-0ubuntu4_all.deb ... 146s Unpacking python3-problem-report (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 146s Preparing to unpack .../python3-apport_2.28.1-0ubuntu4_all.deb ... 146s Unpacking python3-apport (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 146s Preparing to unpack .../apport-core-dump-handler_2.28.1-0ubuntu4_all.deb ... 146s Unpacking apport-core-dump-handler (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 146s Preparing to unpack .../apport_2.28.1-0ubuntu4_all.deb ... 146s Unpacking apport (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 147s Preparing to unpack .../libcap-ng0_0.8.5-1_ppc64el.deb ... 147s Unpacking libcap-ng0:ppc64el (0.8.5-1) over (0.8.4-2build2) ... 147s Setting up libcap-ng0:ppc64el (0.8.5-1) ... 147s (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 ... 72196 files and directories currently installed.) 147s Preparing to unpack .../00-dhcpcd-base_1%3a10.0.6-5_ppc64el.deb ... 147s Unpacking dhcpcd-base (1:10.0.6-5) over (1:10.0.6-1ubuntu3) ... 147s Preparing to unpack .../01-libdw1t64_0.191-1_ppc64el.deb ... 147s Unpacking libdw1t64:ppc64el (0.191-1) over (0.190-1.1build4) ... 147s Preparing to unpack .../02-libelf1t64_0.191-1_ppc64el.deb ... 147s Unpacking libelf1t64:ppc64el (0.191-1) over (0.190-1.1build4) ... 147s Preparing to unpack .../03-libbpf1_1%3a1.4.1-1_ppc64el.deb ... 147s Unpacking libbpf1:ppc64el (1:1.4.1-1) over (1:1.3.0-2build2) ... 147s Preparing to unpack .../04-libslang2_2.3.3-5_ppc64el.deb ... 147s Unpacking libslang2:ppc64el (2.3.3-5) over (2.3.3-3build2) ... 147s Preparing to unpack .../05-ubuntu-pro-client-l10n_32.1_ppc64el.deb ... 147s Unpacking ubuntu-pro-client-l10n (32.1) over (31.2.3) ... 147s Preparing to unpack .../06-ubuntu-pro-client_32.1_ppc64el.deb ... 147s Unpacking ubuntu-pro-client (32.1) over (31.2.3) ... 147s Preparing to unpack .../07-libxcb1_1.17.0-1_ppc64el.deb ... 147s Unpacking libxcb1:ppc64el (1.17.0-1) over (1.15-1ubuntu2) ... 147s Preparing to unpack .../08-libeatmydata1_131-2_ppc64el.deb ... 147s Unpacking libeatmydata1:ppc64el (131-2) over (131-1ubuntu1) ... 147s Preparing to unpack .../09-eatmydata_131-2_all.deb ... 147s Unpacking eatmydata (131-2) over (131-1ubuntu1) ... 147s Preparing to unpack .../10-libnss3_2%3a3.100-1_ppc64el.deb ... 147s Unpacking libnss3:ppc64el (2:3.100-1) over (2:3.98-1build1) ... 147s Preparing to unpack .../11-libnvme1t64_1.9-1_ppc64el.deb ... 147s Unpacking libnvme1t64 (1.9-1) over (1.8-3build1) ... 147s Preparing to unpack .../12-libsharpyuv0_1.4.0-0.1_ppc64el.deb ... 147s Unpacking libsharpyuv0:ppc64el (1.4.0-0.1) over (1.3.2-0.4build3) ... 147s Preparing to unpack .../13-libwebp7_1.4.0-0.1_ppc64el.deb ... 147s Unpacking libwebp7:ppc64el (1.4.0-0.1) over (1.3.2-0.4build3) ... 147s Preparing to unpack .../14-pastebinit_1.7.0-1_all.deb ... 147s Unpacking pastebinit (1.7.0-1) over (1.6.2-1) ... 147s Preparing to unpack .../15-python3-babel_2.14.0-1_all.deb ... 147s Unpacking python3-babel (2.14.0-1) over (2.10.3-3build1) ... 147s Preparing to unpack .../16-python-babel-localedata_2.14.0-1_all.deb ... 147s Unpacking python-babel-localedata (2.14.0-1) over (2.10.3-3build1) ... 148s Preparing to unpack .../17-python3-netaddr_0.10.1-1_all.deb ... 148s Unpacking python3-netaddr (0.10.1-1) over (0.8.0-2ubuntu1) ... 148s Setting up libsharpyuv0:ppc64el (1.4.0-0.1) ... 148s Setting up libxcb1:ppc64el (1.17.0-1) ... 148s Setting up python3-problem-report (2.28.1-0ubuntu4) ... 148s Setting up pastebinit (1.7.0-1) ... 148s Setting up systemd-dev (256~rc2-1ubuntu1) ... 148s Setting up libnss3:ppc64el (2:3.100-1) ... 148s Setting up libelf1t64:ppc64el (0.191-1) ... 148s Setting up python-babel-localedata (2.14.0-1) ... 148s Setting up python3-apport (2.28.1-0ubuntu4) ... 148s Setting up libdw1t64:ppc64el (0.191-1) ... 148s Setting up libslang2:ppc64el (2.3.3-5) ... 148s Setting up libnvme1t64 (1.9-1) ... 148s Setting up libsystemd-shared:ppc64el (256~rc2-1ubuntu1) ... 148s Setting up dhcpcd-base (1:10.0.6-5) ... 148s Setting up libwebp7:ppc64el (1.4.0-0.1) ... 148s Setting up python3-netaddr (0.10.1-1) ... 149s Setting up libeatmydata1:ppc64el (131-2) ... 149s Setting up ubuntu-pro-client (32.1) ... 149s Installing new version of config file /etc/apparmor.d/ubuntu_pro_apt_news ... 151s Setting up libbpf1:ppc64el (1:1.4.1-1) ... 151s Setting up ubuntu-pro-client-l10n (32.1) ... 151s Setting up eatmydata (131-2) ... 151s Setting up python3-babel (2.14.0-1) ... 151s Setting up systemd (256~rc2-1ubuntu1) ... 151s Installing new version of config file /etc/systemd/journald.conf ... 151s Installing new version of config file /etc/systemd/logind.conf ... 151s Installing new version of config file /etc/systemd/networkd.conf ... 151s Installing new version of config file /etc/systemd/sleep.conf ... 151s Installing new version of config file /etc/systemd/system.conf ... 152s Setting up systemd-timesyncd (256~rc2-1ubuntu1) ... 152s Setting up udev (256~rc2-1ubuntu1) ... 153s Setting up systemd-resolved (256~rc2-1ubuntu1) ... 154s Setting up systemd-sysv (256~rc2-1ubuntu1) ... 154s Setting up libnss-systemd:ppc64el (256~rc2-1ubuntu1) ... 154s Setting up libpam-systemd:ppc64el (256~rc2-1ubuntu1) ... 154s Setting up apport-core-dump-handler (2.28.1-0ubuntu4) ... 156s Setting up apport (2.28.1-0ubuntu4) ... 156s Installing new version of config file /etc/apport/crashdb.conf ... 157s apport-autoreport.service is a disabled or a static unit not running, not starting it. 157s Processing triggers for dbus (1.14.10-4ubuntu4) ... 157s Processing triggers for shared-mime-info (2.4-4) ... 157s Processing triggers for initramfs-tools (0.142ubuntu25) ... 157s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 157s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 166s Processing triggers for libc-bin (2.39-0ubuntu8) ... 166s Processing triggers for man-db (2.12.0-4build2) ... 168s Reading package lists... 168s Building dependency tree... 168s Reading state information... 168s The following packages will be REMOVED: 168s systemd-dev* 169s 0 upgraded, 0 newly installed, 1 to remove and 0 not upgraded. 169s After this operation, 756 kB disk space will be freed. 169s (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 ... 72470 files and directories currently installed.) 169s Removing systemd-dev (256~rc2-1ubuntu1) ... 170s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 170s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 170s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 170s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 171s Reading package lists... 171s Reading package lists... 171s Building dependency tree... 171s Reading state information... 172s Calculating upgrade... 172s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 172s Reading package lists... 172s Building dependency tree... 172s Reading state information... 172s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 173s autopkgtest [21:36:10]: rebooting testbed after setup commands that affected boot 177s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 210s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 220s autopkgtest [21:36:57]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 223s autopkgtest [21:37:00]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 227s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 227s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 227s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 227s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 227s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 227s gpgv: issuer "steve.langasek@ubuntu.com" 227s gpgv: Can't check signature: No public key 227s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 227s autopkgtest [21:37:04]: testing package multipath-tools version 0.9.4-5ubuntu8 228s autopkgtest [21:37:05]: build not needed 228s autopkgtest [21:37:05]: test kpartx-file-loopback: preparing testbed 229s Reading package lists... 229s Building dependency tree... 229s Reading state information... 230s Starting pkgProblemResolver with broken count: 0 230s Starting 2 pkgProblemResolver with broken count: 0 230s Done 230s The following additional packages will be installed: 230s liburing2 qemu-utils 230s Recommended packages: 230s qemu-block-extra 230s The following NEW packages will be installed: 230s autopkgtest-satdep liburing2 qemu-utils 230s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 230s Need to get 2329 kB/2330 kB of archives. 230s After this operation, 15.4 MB of additional disk space will be used. 230s Get:1 /tmp/autopkgtest.jTrtEh/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 230s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.5-1build1 [26.0 kB] 230s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 231s Fetched 2329 kB in 1s (3051 kB/s) 231s Selecting previously unselected package liburing2:ppc64el. 232s (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.) 232s Preparing to unpack .../liburing2_2.5-1build1_ppc64el.deb ... 232s Unpacking liburing2:ppc64el (2.5-1build1) ... 232s Selecting previously unselected package qemu-utils. 232s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 232s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 232s Selecting previously unselected package autopkgtest-satdep. 232s Preparing to unpack .../1-autopkgtest-satdep.deb ... 232s Unpacking autopkgtest-satdep (0) ... 232s Setting up liburing2:ppc64el (2.5-1build1) ... 232s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 232s Setting up autopkgtest-satdep (0) ... 232s Processing triggers for man-db (2.12.0-4build2) ... 233s Processing triggers for libc-bin (2.39-0ubuntu8) ... 236s (Reading database ... 72443 files and directories currently installed.) 236s Removing autopkgtest-satdep (0) ... 237s autopkgtest [21:37:14]: test kpartx-file-loopback: [----------------------- 237s Formatting 'foo.img', fmt=raw size=20971520 238s Creating new GPT entries in memory. 238s Warning: The kernel is still using the old partition table. 238s The new table will be used at the next reboot or after you 238s run partprobe(8) or kpartx(8) 238s The operation has completed successfully. 238s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 238s standard_filename: OK 238s del devmap : loop0p1 238s No devices found 238s standard_filename_cleanup: OK 238s Formatting 'fou du FaFa.img', fmt=raw size=20971520 239s Creating new GPT entries in memory. 239s Warning: The kernel is still using the old partition table. 239s The new table will be used at the next reboot or after you 239s run partprobe(8) or kpartx(8) 239s The operation has completed successfully. 239s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 239s filename_with_spaces: OK 239s del devmap : loop0p1 239s No devices found 239s filename_with_spaces_cleanup: OK 240s autopkgtest [21:37:17]: test kpartx-file-loopback: -----------------------] 240s kpartx-file-loopback PASS 240s autopkgtest [21:37:17]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 241s autopkgtest [21:37:18]: test tgtbasedmpaths: preparing testbed 386s autopkgtest [21:39:43]: testbed dpkg architecture: ppc64el 386s autopkgtest [21:39:43]: testbed apt version: 2.7.14build2 386s autopkgtest [21:39:43]: @@@@@@@@@@@@@@@@@@@@ test bed setup 387s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [73.9 kB] 388s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [1964 B] 388s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [7400 B] 388s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [108 kB] 388s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [1391 kB] 388s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [178 kB] 388s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [1660 kB] 388s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [15.1 kB] 389s Fetched 3436 kB in 1s (2571 kB/s) 389s Reading package lists... 391s Reading package lists... 391s Building dependency tree... 391s Reading state information... 391s Calculating upgrade... 391s The following package was automatically installed and is no longer required: 391s systemd-dev 391s Use 'sudo apt autoremove' to remove it. 391s The following packages will be upgraded: 391s apport apport-core-dump-handler dhcpcd-base eatmydata libbpf1 libcap-ng0 391s libdw1t64 libeatmydata1 libelf1t64 libnss-systemd libnss3 libnvme1t64 391s libpam-systemd libsharpyuv0 libslang2 libsystemd-shared libsystemd0 libudev1 391s libwebp7 libxcb1 pastebinit python-babel-localedata python3-apport 391s python3-babel python3-netaddr python3-problem-report systemd systemd-dev 391s systemd-resolved systemd-sysv systemd-timesyncd ubuntu-pro-client 391s ubuntu-pro-client-l10n udev 391s 34 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 391s Need to get 21.3 MB of archives. 391s After this operation, 1005 kB of additional disk space will be used. 391s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-dev all 256~rc2-1ubuntu1 [107 kB] 392s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-timesyncd ppc64el 256~rc2-1ubuntu1 [37.8 kB] 392s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-resolved ppc64el 256~rc2-1ubuntu1 [363 kB] 392s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd-shared ppc64el 256~rc2-1ubuntu1 [2463 kB] 392s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd0 ppc64el 256~rc2-1ubuntu1 [543 kB] 392s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-sysv ppc64el 256~rc2-1ubuntu1 [11.8 kB] 392s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnss-systemd ppc64el 256~rc2-1ubuntu1 [210 kB] 392s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpam-systemd ppc64el 256~rc2-1ubuntu1 [318 kB] 392s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd ppc64el 256~rc2-1ubuntu1 [3956 kB] 393s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el udev ppc64el 256~rc2-1ubuntu1 [2107 kB] 393s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libudev1 ppc64el 256~rc2-1ubuntu1 [213 kB] 393s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-problem-report all 2.28.1-0ubuntu4 [23.9 kB] 393s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-apport all 2.28.1-0ubuntu4 [92.1 kB] 393s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el apport-core-dump-handler all 2.28.1-0ubuntu4 [16.9 kB] 393s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el apport all 2.28.1-0ubuntu4 [83.4 kB] 393s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libcap-ng0 ppc64el 0.8.5-1 [16.0 kB] 393s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dhcpcd-base ppc64el 1:10.0.6-5 [273 kB] 394s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdw1t64 ppc64el 0.191-1 [303 kB] 394s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libelf1t64 ppc64el 0.191-1 [68.0 kB] 394s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el libbpf1 ppc64el 1:1.4.1-1 [220 kB] 394s Get:21 http://ftpmaster.internal/ubuntu oracular/main ppc64el libslang2 ppc64el 2.3.3-5 [503 kB] 394s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el ubuntu-pro-client-l10n ppc64el 32.1 [19.4 kB] 394s Get:23 http://ftpmaster.internal/ubuntu oracular/main ppc64el ubuntu-pro-client ppc64el 32.1 [229 kB] 394s Get:24 http://ftpmaster.internal/ubuntu oracular/main ppc64el libxcb1 ppc64el 1.17.0-1 [56.6 kB] 394s Get:25 http://ftpmaster.internal/ubuntu oracular/main ppc64el libeatmydata1 ppc64el 131-2 [7522 B] 394s Get:26 http://ftpmaster.internal/ubuntu oracular/main ppc64el eatmydata all 131-2 [5576 B] 394s Get:27 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnss3 ppc64el 2:3.100-1 [1848 kB] 394s Get:28 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnvme1t64 ppc64el 1.9-1 [100 kB] 394s Get:29 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsharpyuv0 ppc64el 1.4.0-0.1 [22.0 kB] 394s Get:30 http://ftpmaster.internal/ubuntu oracular/main ppc64el libwebp7 ppc64el 1.4.0-0.1 [309 kB] 394s Get:31 http://ftpmaster.internal/ubuntu oracular/main ppc64el pastebinit all 1.7.0-1 [14.9 kB] 394s Get:32 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-babel all 2.14.0-1 [96.4 kB] 394s Get:33 http://ftpmaster.internal/ubuntu oracular/main ppc64el python-babel-localedata all 2.14.0-1 [6385 kB] 395s Get:34 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-netaddr all 0.10.1-1 [322 kB] 396s Fetched 21.3 MB in 4s (5265 kB/s) 396s (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.) 396s Preparing to unpack .../systemd-dev_256~rc2-1ubuntu1_all.deb ... 396s Unpacking systemd-dev (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 396s Preparing to unpack .../systemd-timesyncd_256~rc2-1ubuntu1_ppc64el.deb ... 396s Unpacking systemd-timesyncd (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 396s Preparing to unpack .../systemd-resolved_256~rc2-1ubuntu1_ppc64el.deb ... 396s Unpacking systemd-resolved (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 396s Preparing to unpack .../libsystemd-shared_256~rc2-1ubuntu1_ppc64el.deb ... 396s Unpacking libsystemd-shared:ppc64el (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 396s Preparing to unpack .../libsystemd0_256~rc2-1ubuntu1_ppc64el.deb ... 396s Unpacking libsystemd0:ppc64el (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 396s Setting up libsystemd0:ppc64el (256~rc2-1ubuntu1) ... 396s (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.) 396s Preparing to unpack .../0-systemd-sysv_256~rc2-1ubuntu1_ppc64el.deb ... 396s Unpacking systemd-sysv (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 396s Preparing to unpack .../1-libnss-systemd_256~rc2-1ubuntu1_ppc64el.deb ... 396s Unpacking libnss-systemd:ppc64el (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 396s Preparing to unpack .../2-libpam-systemd_256~rc2-1ubuntu1_ppc64el.deb ... 396s Unpacking libpam-systemd:ppc64el (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 396s Preparing to unpack .../3-systemd_256~rc2-1ubuntu1_ppc64el.deb ... 396s Unpacking systemd (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 396s Preparing to unpack .../4-udev_256~rc2-1ubuntu1_ppc64el.deb ... 396s Unpacking udev (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 396s Preparing to unpack .../5-libudev1_256~rc2-1ubuntu1_ppc64el.deb ... 396s Unpacking libudev1:ppc64el (256~rc2-1ubuntu1) over (255.4-1ubuntu8) ... 396s Setting up libudev1:ppc64el (256~rc2-1ubuntu1) ... 396s (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 ... 72196 files and directories currently installed.) 396s Preparing to unpack .../python3-problem-report_2.28.1-0ubuntu4_all.deb ... 397s Unpacking python3-problem-report (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 397s Preparing to unpack .../python3-apport_2.28.1-0ubuntu4_all.deb ... 397s Unpacking python3-apport (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 397s Preparing to unpack .../apport-core-dump-handler_2.28.1-0ubuntu4_all.deb ... 397s Unpacking apport-core-dump-handler (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 397s Preparing to unpack .../apport_2.28.1-0ubuntu4_all.deb ... 397s Unpacking apport (2.28.1-0ubuntu4) over (2.28.1-0ubuntu2) ... 397s Preparing to unpack .../libcap-ng0_0.8.5-1_ppc64el.deb ... 397s Unpacking libcap-ng0:ppc64el (0.8.5-1) over (0.8.4-2build2) ... 397s Setting up libcap-ng0:ppc64el (0.8.5-1) ... 397s (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 ... 72196 files and directories currently installed.) 397s Preparing to unpack .../00-dhcpcd-base_1%3a10.0.6-5_ppc64el.deb ... 397s Unpacking dhcpcd-base (1:10.0.6-5) over (1:10.0.6-1ubuntu3) ... 397s Preparing to unpack .../01-libdw1t64_0.191-1_ppc64el.deb ... 397s Unpacking libdw1t64:ppc64el (0.191-1) over (0.190-1.1build4) ... 397s Preparing to unpack .../02-libelf1t64_0.191-1_ppc64el.deb ... 397s Unpacking libelf1t64:ppc64el (0.191-1) over (0.190-1.1build4) ... 397s Preparing to unpack .../03-libbpf1_1%3a1.4.1-1_ppc64el.deb ... 397s Unpacking libbpf1:ppc64el (1:1.4.1-1) over (1:1.3.0-2build2) ... 397s Preparing to unpack .../04-libslang2_2.3.3-5_ppc64el.deb ... 397s Unpacking libslang2:ppc64el (2.3.3-5) over (2.3.3-3build2) ... 397s Preparing to unpack .../05-ubuntu-pro-client-l10n_32.1_ppc64el.deb ... 397s Unpacking ubuntu-pro-client-l10n (32.1) over (31.2.3) ... 397s Preparing to unpack .../06-ubuntu-pro-client_32.1_ppc64el.deb ... 397s Unpacking ubuntu-pro-client (32.1) over (31.2.3) ... 397s Preparing to unpack .../07-libxcb1_1.17.0-1_ppc64el.deb ... 397s Unpacking libxcb1:ppc64el (1.17.0-1) over (1.15-1ubuntu2) ... 397s Preparing to unpack .../08-libeatmydata1_131-2_ppc64el.deb ... 397s Unpacking libeatmydata1:ppc64el (131-2) over (131-1ubuntu1) ... 397s Preparing to unpack .../09-eatmydata_131-2_all.deb ... 397s Unpacking eatmydata (131-2) over (131-1ubuntu1) ... 397s Preparing to unpack .../10-libnss3_2%3a3.100-1_ppc64el.deb ... 397s Unpacking libnss3:ppc64el (2:3.100-1) over (2:3.98-1build1) ... 397s Preparing to unpack .../11-libnvme1t64_1.9-1_ppc64el.deb ... 397s Unpacking libnvme1t64 (1.9-1) over (1.8-3build1) ... 397s Preparing to unpack .../12-libsharpyuv0_1.4.0-0.1_ppc64el.deb ... 397s Unpacking libsharpyuv0:ppc64el (1.4.0-0.1) over (1.3.2-0.4build3) ... 397s Preparing to unpack .../13-libwebp7_1.4.0-0.1_ppc64el.deb ... 397s Unpacking libwebp7:ppc64el (1.4.0-0.1) over (1.3.2-0.4build3) ... 397s Preparing to unpack .../14-pastebinit_1.7.0-1_all.deb ... 397s Unpacking pastebinit (1.7.0-1) over (1.6.2-1) ... 397s Preparing to unpack .../15-python3-babel_2.14.0-1_all.deb ... 397s Unpacking python3-babel (2.14.0-1) over (2.10.3-3build1) ... 397s Preparing to unpack .../16-python-babel-localedata_2.14.0-1_all.deb ... 397s Unpacking python-babel-localedata (2.14.0-1) over (2.10.3-3build1) ... 398s Preparing to unpack .../17-python3-netaddr_0.10.1-1_all.deb ... 398s Unpacking python3-netaddr (0.10.1-1) over (0.8.0-2ubuntu1) ... 398s Setting up libsharpyuv0:ppc64el (1.4.0-0.1) ... 398s Setting up libxcb1:ppc64el (1.17.0-1) ... 398s Setting up python3-problem-report (2.28.1-0ubuntu4) ... 398s Setting up pastebinit (1.7.0-1) ... 398s Setting up systemd-dev (256~rc2-1ubuntu1) ... 398s Setting up libnss3:ppc64el (2:3.100-1) ... 398s Setting up libelf1t64:ppc64el (0.191-1) ... 398s Setting up python-babel-localedata (2.14.0-1) ... 398s Setting up python3-apport (2.28.1-0ubuntu4) ... 398s Setting up libdw1t64:ppc64el (0.191-1) ... 398s Setting up libslang2:ppc64el (2.3.3-5) ... 398s Setting up libnvme1t64 (1.9-1) ... 398s Setting up libsystemd-shared:ppc64el (256~rc2-1ubuntu1) ... 398s Setting up dhcpcd-base (1:10.0.6-5) ... 398s Setting up libwebp7:ppc64el (1.4.0-0.1) ... 398s Setting up python3-netaddr (0.10.1-1) ... 398s Setting up libeatmydata1:ppc64el (131-2) ... 398s Setting up ubuntu-pro-client (32.1) ... 398s Installing new version of config file /etc/apparmor.d/ubuntu_pro_apt_news ... 400s Setting up libbpf1:ppc64el (1:1.4.1-1) ... 400s Setting up ubuntu-pro-client-l10n (32.1) ... 400s Setting up eatmydata (131-2) ... 400s Setting up python3-babel (2.14.0-1) ... 400s Setting up systemd (256~rc2-1ubuntu1) ... 400s Installing new version of config file /etc/systemd/journald.conf ... 400s Installing new version of config file /etc/systemd/logind.conf ... 400s Installing new version of config file /etc/systemd/networkd.conf ... 400s Installing new version of config file /etc/systemd/sleep.conf ... 400s Installing new version of config file /etc/systemd/system.conf ... 401s Setting up systemd-timesyncd (256~rc2-1ubuntu1) ... 401s Setting up udev (256~rc2-1ubuntu1) ... 402s Setting up systemd-resolved (256~rc2-1ubuntu1) ... 403s Setting up systemd-sysv (256~rc2-1ubuntu1) ... 403s Setting up libnss-systemd:ppc64el (256~rc2-1ubuntu1) ... 403s Setting up libpam-systemd:ppc64el (256~rc2-1ubuntu1) ... 403s Setting up apport-core-dump-handler (2.28.1-0ubuntu4) ... 404s Setting up apport (2.28.1-0ubuntu4) ... 404s Installing new version of config file /etc/apport/crashdb.conf ... 405s apport-autoreport.service is a disabled or a static unit not running, not starting it. 405s Processing triggers for dbus (1.14.10-4ubuntu4) ... 405s Processing triggers for shared-mime-info (2.4-4) ... 405s Processing triggers for initramfs-tools (0.142ubuntu25) ... 405s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 405s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 412s Processing triggers for libc-bin (2.39-0ubuntu8) ... 412s Processing triggers for man-db (2.12.0-4build2) ... 413s Reading package lists... 413s Building dependency tree... 413s Reading state information... 413s The following packages will be REMOVED: 413s systemd-dev* 413s 0 upgraded, 0 newly installed, 1 to remove and 0 not upgraded. 413s After this operation, 756 kB disk space will be freed. 414s (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 ... 72470 files and directories currently installed.) 414s Removing systemd-dev (256~rc2-1ubuntu1) ... 414s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 414s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 414s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 414s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 415s Reading package lists... 415s Reading package lists... 415s Building dependency tree... 415s Reading state information... 415s Calculating upgrade... 416s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 416s Reading package lists... 416s Building dependency tree... 416s Reading state information... 416s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 417s autopkgtest [21:40:14]: rebooting testbed after setup commands that affected boot 450s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 464s Reading package lists... 464s Building dependency tree... 464s Reading state information... 464s Starting pkgProblemResolver with broken count: 0 464s Starting 2 pkgProblemResolver with broken count: 0 464s Done 465s The following additional packages will be installed: 465s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 465s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 465s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 465s librdmacm1t64 lsscsi open-iscsi tgt 465s Suggested packages: 465s fio-examples gnuplot tgt-glusterfs tgt-rbd 465s Recommended packages: 465s finalrd 465s The following NEW packages will be installed: 465s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 465s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 465s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 465s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 465s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 465s Need to get 10.8 MB/10.8 MB of archives. 465s After this operation, 49.9 MB of additional disk space will be used. 465s Get:1 /tmp/autopkgtest.jTrtEh/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 465s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu4 [54.4 kB] 465s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-0.3build3 [119 kB] 465s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu4 [389 kB] 465s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 465s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 465s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu6 [256 kB] 465s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4build3 [21.5 kB] 465s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4build3 [311 kB] 465s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4build3 [47.0 kB] 465s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4build3 [100 kB] 465s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.1-1 [97.4 kB] 465s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 465s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 465s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 465s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-2.1ubuntu3 [260 kB] 465s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-2.1ubuntu3 [280 kB] 465s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu6 [4050 kB] 466s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 466s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu6 [3612 kB] 466s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 466s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 466s Preconfiguring packages ... 466s Fetched 10.8 MB in 1s (10.8 MB/s) 466s Selecting previously unselected package libopeniscsiusr. 466s (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.) 466s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu4_ppc64el.deb ... 466s Unpacking libopeniscsiusr (2.1.9-3ubuntu4) ... 466s Selecting previously unselected package libisns0t64:ppc64el. 466s Preparing to unpack .../01-libisns0t64_0.101-0.3build3_ppc64el.deb ... 466s Unpacking libisns0t64:ppc64el (0.101-0.3build3) ... 466s Selecting previously unselected package open-iscsi. 466s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu4_ppc64el.deb ... 466s Unpacking open-iscsi (2.1.9-3ubuntu4) ... 466s Selecting previously unselected package librdmacm1t64:ppc64el. 466s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 466s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 466s Selecting previously unselected package libconfig-general-perl. 466s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 466s Unpacking libconfig-general-perl (2.65-2) ... 466s Selecting previously unselected package tgt. 466s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu6_ppc64el.deb ... 466s Unpacking tgt (1:1.0.85-1.1ubuntu6) ... 466s Selecting previously unselected package libgfxdr0:ppc64el. 466s Preparing to unpack .../06-libgfxdr0_11.1-4build3_ppc64el.deb ... 466s Unpacking libgfxdr0:ppc64el (11.1-4build3) ... 466s Selecting previously unselected package libglusterfs0:ppc64el. 466s Preparing to unpack .../07-libglusterfs0_11.1-4build3_ppc64el.deb ... 466s Unpacking libglusterfs0:ppc64el (11.1-4build3) ... 466s Selecting previously unselected package libgfrpc0:ppc64el. 466s Preparing to unpack .../08-libgfrpc0_11.1-4build3_ppc64el.deb ... 466s Unpacking libgfrpc0:ppc64el (11.1-4build3) ... 466s Selecting previously unselected package libgfapi0:ppc64el. 466s Preparing to unpack .../09-libgfapi0_11.1-4build3_ppc64el.deb ... 466s Unpacking libgfapi0:ppc64el (11.1-4build3) ... 466s Selecting previously unselected package libnbd0. 466s Preparing to unpack .../10-libnbd0_1.20.1-1_ppc64el.deb ... 466s Unpacking libnbd0 (1.20.1-1) ... 466s Selecting previously unselected package libdaxctl1:ppc64el. 466s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 466s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 466s Selecting previously unselected package libndctl6:ppc64el. 466s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 466s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 466s Selecting previously unselected package libpmem1:ppc64el. 466s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 466s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 466s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 466s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 466s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 466s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 466s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 466s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 467s Selecting previously unselected package librados2. 467s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu6_ppc64el.deb ... 467s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 467s Selecting previously unselected package libpmemobj1:ppc64el. 467s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 467s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 467s Selecting previously unselected package librbd1. 467s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu6_ppc64el.deb ... 467s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 467s Selecting previously unselected package fio. 467s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 467s Unpacking fio (3.37-1) ... 467s Selecting previously unselected package lsscsi. 467s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 467s Unpacking lsscsi (0.32-1build1) ... 467s Selecting previously unselected package autopkgtest-satdep. 467s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 467s Unpacking autopkgtest-satdep (0) ... 467s Setting up libconfig-general-perl (2.65-2) ... 467s Setting up libisns0t64:ppc64el (0.101-0.3build3) ... 467s Setting up libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 467s Setting up libnbd0 (1.20.1-1) ... 467s Setting up libopeniscsiusr (2.1.9-3ubuntu4) ... 467s Setting up libglusterfs0:ppc64el (11.1-4build3) ... 467s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 467s Setting up lsscsi (0.32-1build1) ... 467s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 467s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 467s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 467s Setting up tgt (1:1.0.85-1.1ubuntu6) ... 467s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 468s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 468s Setting up libgfxdr0:ppc64el (11.1-4build3) ... 468s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 468s Setting up open-iscsi (2.1.9-3ubuntu4) ... 468s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 469s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 469s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 469s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 469s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 469s Setting up libgfrpc0:ppc64el (11.1-4build3) ... 469s Setting up libgfapi0:ppc64el (11.1-4build3) ... 469s Setting up fio (3.37-1) ... 470s Setting up autopkgtest-satdep (0) ... 470s Processing triggers for man-db (2.12.0-4build2) ... 471s Processing triggers for initramfs-tools (0.142ubuntu25) ... 471s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 471s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 478s Processing triggers for libc-bin (2.39-0ubuntu8) ... 480s (Reading database ... 72664 files and directories currently installed.) 480s Removing autopkgtest-satdep (0) ... 484s autopkgtest [21:41:21]: test tgtbasedmpaths: [----------------------- 485s + targetname=iqn.2016-11.foo.com:target.iscsi 485s + pwd 485s + cwd=/tmp/autopkgtest.jTrtEh/build.P5j/src 485s + testdir=/mnt/tgtmpathtest 485s + localhost=127.0.0.1 485s + portal=127.0.0.1:3260 485s + maxpaths=4 485s + backfn=backingfile 485s + expectwwid=60000000000000000e00000000010001 485s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 485s + bglog=/tmp/autopkgtest.jTrtEh/tgtbasedmpaths-artifacts/test-background.log 485s + fioprep=/tmp/autopkgtest.jTrtEh/tgtbasedmpaths-artifacts/path-change-prep.fio 485s + fiovrfy=/tmp/autopkgtest.jTrtEh/tgtbasedmpaths-artifacts/path-change-check.fio 485s + service tgt restart 485s + truncate --size 100M backingfile 485s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 485s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 485s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.jTrtEh/build.P5j/src/backingfile 485s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 485s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 485s login #1 485s + echo login #1 485s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 485s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 485s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 485s + seq 2 4 485s extra login #2 485s + echo extra login #2 485s + iscsiadm --mode session -r 1 --op new 485s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 485s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 485s extra login #3 485s + echo extra login #3 485s + iscsiadm --mode session -r 1 --op new 485s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 485s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 485s extra login #4 485s + echo extra login #4 485s + iscsiadm --mode session -r 1 --op new 485s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 485s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 485s + udevadm settle 485s + sleep 5 490s Status after initial setup 490s + echo Status after initial setup 490s + tgtadm --lld iscsi --mode target --op show 490s Target 1: iqn.2016-11.foo.com:target.iscsi 490s System information: 490s Driver: iscsi 490s State: ready 490s I_T nexus information: 490s I_T nexus: 1 490s Initiator: iqn.2004-10.com.ubuntu:01:8ba57264a8c7 alias: autopkgtest 490s Connection: 0 490s IP Address: 127.0.0.1 490s I_T nexus: 2 490s Initiator: iqn.2004-10.com.ubuntu:01:8ba57264a8c7 alias: autopkgtest 490s Connection: 0 490s IP Address: 127.0.0.1 490s I_T nexus: 3 490s Initiator: iqn.2004-10.com.ubuntu:01:8ba57264a8c7 alias: autopkgtest 490s Connection: 0 490s IP Address: 127.0.0.1 490s I_T nexus: 4 490s Initiator: iqn.2004-10.com.ubuntu:01:8ba57264a8c7 alias: autopkgtest 490s Connection: 0 490s IP Address: 127.0.0.1 490s LUN information: 490s LUN: 0 490s Type: controller 490s SCSI ID: IET 00010000 490s SCSI SN: beaf10 490s Size: 0 MB, Block size: 1 490s Online: Yes 490s Removable media: No 490s Prevent removal: No 490s Readonly: No 490s SWP: No 490s Thin-provisioning: No 490s Backing store type: null 490s Backing store path: None 490s Backing store flags: 490s LUN: 1 490s Type: disk 490s SCSI ID: IET 00010001 490s SCSI SN: beaf11 490s Size: 105 MB, Block size: 512 490s Online: Yes 490s Removable media: No 490s Prevent removal: No 490s Readonly: No 490s SWP: No 490s Thin-provisioning: No 490s Backing store type: rdwr 490s Backing store path: /tmp/autopkgtest.jTrtEh/build.P5j/src/backingfile 490s Backing store flags: 490s Account information: 490s ACL information: 490s ALL 490s + tgtadm --lld iscsi --op show --mode conn --tid 1 490s Session: 4 490s Connection: 0 490s Initiator: iqn.2004-10.com.ubuntu:01:8ba57264a8c7 490s IP Address: 127.0.0.1 490s Session: 3 490s Connection: 0 490s Initiator: iqn.2004-10.com.ubuntu:01:8ba57264a8c7 490s IP Address: 127.0.0.1 490s Session: 2 490s Connection: 0 490s Initiator: iqn.2004-10.com.ubuntu:01:8ba57264a8c7 490s IP Address: 127.0.0.1 490s Session: 1 490s Connection: 0 490s Initiator: iqn.2004-10.com.ubuntu:01:8ba57264a8c7 490s IP Address: 127.0.0.1 490s + iscsiadm --mode session -P 1 490s + lsscsi -liv 490s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 490s Current Portal: 127.0.0.1:3260,1 490s Persistent Portal: 127.0.0.1:3260,1 490s ********** 490s Interface: 490s ********** 490s Iface Name: default 490s Iface Transport: tcp 490s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:8ba57264a8c7 490s Iface IPaddress: 127.0.0.1 490s Iface HWaddress: default 490s Iface Netdev: default 490s SID: 1 490s iSCSI Connection State: LOGGED IN 490s iSCSI Session State: LOGGED_IN 490s Internal iscsid Session State: NO CHANGE 490s 490s ********** 490s Interface: 490s ********** 490s Iface Name: default 490s Iface Transport: tcp 490s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:8ba57264a8c7 490s Iface IPaddress: 127.0.0.1 490s Iface HWaddress: default 490s Iface Netdev: default 490s SID: 2 490s iSCSI Connection State: LOGGED IN 490s iSCSI Session State: LOGGED_IN 490s Internal iscsid Session State: NO CHANGE 490s 490s ********** 490s Interface: 490s ********** 490s Iface Name: default 490s Iface Transport: tcp 490s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:8ba57264a8c7 490s Iface IPaddress: 127.0.0.1 490s Iface HWaddress: default 490s Iface Netdev: default 490s SID: 3 490s iSCSI Connection State: LOGGED IN 490s iSCSI Session State: LOGGED_IN 490s Internal iscsid Session State: NO CHANGE 490s 490s ********** 490s Interface: 490s ********** 490s Iface Name: default 490s Iface Transport: tcp 490s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:8ba57264a8c7 490s Iface IPaddress: 127.0.0.1 490s Iface HWaddress: default 490s Iface Netdev: default 490s SID: 4 490s iSCSI Connection State: LOGGED IN 490s iSCSI Session State: LOGGED_IN 490s Internal iscsid Session State: NO CHANGE 490s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 490s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 490s 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] 490s [1:0:0:0] storage IET Controller 0001 - - 490s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 490s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 490s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 490s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 490s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 490s [2:0:0:0] storage IET Controller 0001 - - 490s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 490s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 490s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 490s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 490s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 490s [3:0:0:0] storage IET Controller 0001 - - 490s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 490s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 490s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 490s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 490s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 490s [4:0:0:0] storage IET Controller 0001 - - 490s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 490s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 490s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 490s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 490s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 490s NVMe module may not be loaded 490s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 490s + multipath -v3 -ll 490s 49.533453 | set open fds limit to 1048576/1048576 490s 49.533525 | loading /lib/multipath/libchecktur.so checker 490s 49.533601 | checker tur: message table size = 3 490s 49.533628 | loading /lib/multipath/libprioconst.so prioritizer 490s 49.533741 | _init_foreign: foreign library "nvme" is not enabled 490s 49.539142 | sda: size = 167772160 490s 49.539308 | sda: vendor = QEMU 490s 49.539351 | sda: product = QEMU HARDDISK 490s 49.539372 | sda: rev = 2.5+ 490s 49.539973 | sda: h:b:t:l = 0:0:0:0 490s 49.540306 | sda: tgt_node_name = 490s 49.540331 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 490s 49.540334 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 490s 49.540476 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 490s 49.540497 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 490s 49.540509 | __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 490s 49.540513 | failed to read sysfs vpd pg80: No such file or directory 490s 49.540726 | sda: fail to get serial 490s 49.540746 | sda: detect_checker = yes (setting: multipath internal) 490s 49.540923 | sda: path_checker = tur (setting: multipath internal) 490s 49.540945 | sda: checker timeout = 30 s (setting: kernel sysfs) 490s 49.541073 | sda: tur state = up 490s 49.541367 | sdb: size = 204800 490s 49.541530 | sdb: vendor = IET 490s 49.541572 | sdb: product = VIRTUAL-DISK 490s 49.541593 | sdb: rev = 0001 490s 49.542212 | sdb: h:b:t:l = 1:0:0:1 490s 49.542577 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 490s 49.542598 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 490s 49.542600 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 490s 49.542750 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 490s 49.542770 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 490s 49.542785 | sdb: serial = beaf11 490s 49.542788 | sdb: detect_checker = yes (setting: multipath internal) 490s 49.542991 | sdb: path_checker = tur (setting: multipath internal) 490s 49.543013 | sdb: checker timeout = 30 s (setting: kernel sysfs) 490s 49.543200 | sdb: tur state = up 490s 49.543343 | sdc: size = 204800 490s 49.543492 | sdc: vendor = IET 490s 49.543531 | sdc: product = VIRTUAL-DISK 490s 49.543552 | sdc: rev = 0001 490s 49.544238 | sdc: h:b:t:l = 2:0:0:1 490s 49.544603 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 490s 49.544624 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 490s 49.544626 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 490s 49.544768 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 490s 49.544789 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 490s 49.544803 | sdc: serial = beaf11 490s 49.544805 | sdc: detect_checker = yes (setting: multipath internal) 490s 49.545022 | sdc: path_checker = tur (setting: multipath internal) 490s 49.545044 | sdc: checker timeout = 30 s (setting: kernel sysfs) 490s 49.545211 | sdc: tur state = up 490s 49.545354 | sdd: size = 204800 490s 49.545518 | sdd: vendor = IET 490s 49.545558 | sdd: product = VIRTUAL-DISK 490s 49.545579 | sdd: rev = 0001 490s 49.546249 | sdd: h:b:t:l = 3:0:0:1 490s 49.546610 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 490s 49.546631 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 490s 49.546633 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 490s 49.546776 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 490s 49.546797 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 490s 49.546810 | sdd: serial = beaf11 490s 49.546812 | sdd: detect_checker = yes (setting: multipath internal) 490s 49.546973 | sdd: path_checker = tur (setting: multipath internal) 490s 49.546995 | sdd: checker timeout = 30 s (setting: kernel sysfs) 490s 49.547142 | sdd: tur state = up 490s 49.547285 | sde: size = 204800 490s 49.547433 | sde: vendor = IET 490s 49.547472 | sde: product = VIRTUAL-DISK 490s 49.547493 | sde: rev = 0001 490s 49.548199 | sde: h:b:t:l = 4:0:0:1 490s 49.548561 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 490s 49.548582 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 490s 49.548584 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 490s 49.548733 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 490s 49.548753 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 490s 49.548767 | sde: serial = beaf11 490s 49.548769 | sde: detect_checker = yes (setting: multipath internal) 490s 49.548962 | sde: path_checker = tur (setting: multipath internal) 490s 49.548984 | sde: checker timeout = 30 s (setting: kernel sysfs) 490s 49.549144 | sde: tur state = up 490s 49.549253 | loop0: device node name blacklisted 490s 49.549358 | loop1: device node name blacklisted 490s 49.549471 | loop2: device node name blacklisted 490s 49.549572 | loop3: device node name blacklisted 490s 49.549673 | loop4: device node name blacklisted 490s 49.549773 | loop5: device node name blacklisted 490s 49.549878 | loop6: device node name blacklisted 490s 49.549981 | loop7: device node name blacklisted 490s 49.550087 | dm-0: device node name blacklisted 490s 49.551035 | multipath-tools v0.9.4 (12/19, 2022) 490s 49.551062 | libdevmapper version 1.02.185 490s 49.551188 | kernel device mapper v4.48.0 490s 49.551215 | DM multipath kernel driver v1.14.0 490s 49.551316 | sdb: size = 204800 490s 49.551338 | sdb: vendor = IET 490s 49.551341 | sdb: product = VIRTUAL-DISK 490s 49.551344 | sdb: rev = 0001 490s 49.551968 | sdb: h:b:t:l = 1:0:0:1 490s 49.552106 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 490s 49.552147 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 490s 49.552150 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 490s 49.552162 | sdb: serial = beaf11 490s 49.552329 | sdb: tur state = up 490s 49.552350 | sdb: uid = 360000000000000000e00000000010001 (udev) 490s 49.552353 | sdb: detect_prio = yes (setting: multipath internal) 490s 49.552356 | sdb: prio = const (setting: multipath internal) 490s 49.552358 | sdb: prio args = "" (setting: multipath internal) 490s 49.552360 | sdb: const prio = 1 490s 49.552383 | sdc: size = 204800 490s 49.552387 | sdc: vendor = IET 490s 49.552389 | sdc: product = VIRTUAL-DISK 490s 49.552392 | sdc: rev = 0001 490s 49.553000 | sdc: h:b:t:l = 2:0:0:1 490s 49.553128 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 490s 49.553166 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 490s 49.553169 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 490s 49.553181 | sdc: serial = beaf11 490s 49.553307 | sdc: tur state = up 490s 49.553329 | sdc: uid = 360000000000000000e00000000010001 (udev) 490s 49.553331 | sdc: detect_prio = yes (setting: multipath internal) 490s 49.553334 | sdc: prio = const (setting: multipath internal) 490s 49.553336 | sdc: prio args = "" (setting: multipath internal) 490s 49.553338 | sdc: const prio = 1 490s 49.553360 | sdd: size = 204800 490s 49.553364 | sdd: vendor = IET 490s 49.553366 | sdd: product = VIRTUAL-DISK 490s 49.553369 | sdd: rev = 0001 490s 49.553986 | sdd: h:b:t:l = 3:0:0:1 490s 49.554114 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 490s 49.554152 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 490s 49.554155 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 490s 49.554166 | sdd: serial = beaf11 490s ===== paths list ===== 490s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 490s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 490s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 490s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 490s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 490s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 490s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 490s size=100M features='0' hwhandler='0' wp=rw 490s |-+- policy='service-time 0' prio=1 status=active 490s | `- 1:0:0:1 sdb 8:16 active ready running 490s |-+- policy='service-time 0' prio=1 status=enabled 490s | `- 2:0:0:1 sdc 8:32 active ready running 490s |-+- policy='service-time 0' prio=1 status=enabled 490s | `- 3:0:0:1 sdd 8:48 active ready running 490s `-+- policy='service-time 0' prio=1 status=enabled 490s `- 4:0:0:1 sde 8:64 active ready running 490s mpatha: 0 204800 multipath 0 0 4 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 service-time 0 1 2 8:64 1 1 490s Test WWN should now point to DM 490s ../../dm-0 490s Creating filesystem with 25600 4k blocks and 25600 inodes 490s 490s Allocating group tables: 0/1 done 490s Writing inode tables: 0/1 done 490s Creating journal (1024 blocks): done 490s Writing superblocks and filesystem accounting information: 0/1 49.554265 | sdd: tur state = up 490s 49.554287 | sdd: uid = 360000000000000000e00000000010001 (udev) 490s 49.554290 | sdd: detect_prio = yes (setting: multipath internal) 490s 49.554292 | sdd: prio = const (setting: multipath internal) 490s 49.554294 | sdd: prio args = "" (setting: multipath internal) 490s 49.554297 | sdd: const prio = 1 490s 49.554319 | sde: size = 204800 490s 49.554323 | sde: vendor = IET 490s 49.554326 | sde: product = VIRTUAL-DISK 490s 49.554328 | sde: rev = 0001 490s 49.554934 | sde: h:b:t:l = 4:0:0:1 490s 49.555061 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 490s 49.555097 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 490s 49.555100 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 490s 49.555111 | sde: serial = beaf11 490s 49.555259 | sde: tur state = up 490s 49.555279 | sde: uid = 360000000000000000e00000000010001 (udev) 490s 49.555282 | sde: detect_prio = yes (setting: multipath internal) 490s 49.555284 | sde: prio = const (setting: multipath internal) 490s 49.555287 | sde: prio args = "" (setting: multipath internal) 490s 49.555289 | sde: const prio = 1 490s 49.556069 | unloading tur checker 490s 49.556115 | unloading const prioritizer 490s + dmsetup table 490s + echo Test WWN should now point to DM 490s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 490s + grep dm 490s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 490s mke2fs 1.47.0 (5-Feb-2023) 490s done 490s 490s + udevadm settle 490s + sleep 3s 493s + mkdir -p /mnt/tgtmpathtest 493s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 493s + cat 493s + cat 493s + fio --max-jobs=4 /tmp/autopkgtest.jTrtEh/tgtbasedmpaths-artifacts/path-change-prep.fio 493s 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 493s fio-3.37 493s Starting 1 thread 493s write-phase: Laying out IO file (1 file / 17592186044415MiB) 494s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 494s 494s write-phase: (groupid=0, jobs=1): err= 0: pid=5671: Sun May 19 21:41:31 2024 494s write: IOPS=2195, BW=137MiB/s (144MB/s)(87.6MiB/639msec); 0 zone resets 494s clat (usec): min=272, max=4727, avg=438.32, stdev=202.91 494s lat (usec): min=292, max=4740, avg=453.88, stdev=203.68 494s clat percentiles (usec): 494s | 1.00th=[ 314], 5.00th=[ 330], 10.00th=[ 355], 20.00th=[ 367], 494s | 30.00th=[ 379], 40.00th=[ 388], 50.00th=[ 396], 60.00th=[ 408], 494s | 70.00th=[ 433], 80.00th=[ 482], 90.00th=[ 537], 95.00th=[ 619], 494s | 99.00th=[ 963], 99.50th=[ 1369], 99.90th=[ 3687], 99.95th=[ 4752], 494s | 99.99th=[ 4752] 494s bw ( KiB/s): min=136320, max=136320, per=97.08%, avg=136320.00, stdev= 0.00, samples=1 494s iops : min= 2130, max= 2130, avg=2130.00, stdev= 0.00, samples=1 494s lat (usec) : 500=85.10%, 750=12.97%, 1000=0.86% 494s lat (msec) : 2=0.71%, 4=0.21%, 10=0.07% 494s cpu : usr=4.55%, sys=7.37%, ctx=1404, majf=0, minf=0 494s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 494s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 494s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 494s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 494s latency : target=0, window=0, percentile=100.00%, depth=1 494s 494s Run status group 0 (all jobs): 494s WRITE: bw=137MiB/s (144MB/s), 137MiB/s-137MiB/s (144MB/s-144MB/s), io=87.6MiB (91.9MB), run=639-639msec 494s 494s Disk stats (read/write): 494s dm-0: ios=1/1404, sectors=8/179536, merge=0/1, ticks=0/583, in_queue=583, util=87.03%, aggrios=0/351, aggsectors=2/44884, aggrmerge=0/0, aggrticks=0/143, aggrin_queue=143, aggrutil=85.19% 494s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 494s sdb: ios=1/1404, sectors=8/179536, merge=0/0, ticks=0/572, in_queue=572, util=85.19% 494s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 494s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 494s + echo Starting the path changes in background 494s + date +Pre FIO %H:%M:%S.%N 494s Starting the path changes in background 494s + fio --max-jobs=4 /tmp/autopkgtest.jTrtEh/tgtbasedmpaths-artifacts/path-change-check.fio 494s Pre FIO 21:41:31.944656956 495s 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 495s fio-3.37 495s Starting 1 thread 675s + date +Post FIO %H:%M:%S.%N 675s 675s verify-phase: (groupid=0, jobs=1): err= 0: pid=5678: Sun May 19 21:44:32 2024 675s read: IOPS=3566, BW=223MiB/s (234MB/s)(39.2GiB/180001msec) 675s clat (usec): min=86, max=38028, avg=257.77, stdev=169.07 675s lat (usec): min=86, max=38028, avg=257.87, stdev=169.07 675s clat percentiles (usec): 675s | 1.00th=[ 95], 5.00th=[ 143], 10.00th=[ 151], 20.00th=[ 172], 675s | 30.00th=[ 198], 40.00th=[ 219], 50.00th=[ 251], 60.00th=[ 281], 675s | 70.00th=[ 306], 80.00th=[ 326], 90.00th=[ 359], 95.00th=[ 392], 675s | 99.00th=[ 474], 99.50th=[ 603], 99.90th=[ 1287], 99.95th=[ 1909], 675s | 99.99th=[ 4555] 675s bw ( KiB/s): min=146176, max=401408, per=100.00%, avg=228311.37, stdev=59836.48, samples=359 675s iops : min= 2284, max= 6272, avg=3567.33, stdev=934.95, samples=359 675s lat (usec) : 100=1.98%, 250=48.02%, 500=49.23%, 750=0.41%, 1000=0.15% 675s lat (msec) : 2=0.17%, 4=0.03%, 10=0.01%, 20=0.01%, 50=0.01% 675s cpu : usr=9.22%, sys=6.87%, ctx=642023, majf=0, minf=1 675s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 675s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 675s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 675s issued rwts: total=641920,0,0,0 short=0,0,0,0 dropped=0,0,0,0 675s latency : target=0, window=0, percentile=100.00%, depth=1 675s 675s Run status group 0 (all jobs): 675s READ: bw=223MiB/s (234MB/s), 223MiB/s-223MiB/s (234MB/s-234MB/s), io=39.2GiB (42.1GB), run=180001-180001msec 675s 675s Disk stats (read/write): 675s dm-0: ios=641920/9, sectors=82105400/12912, merge=20/8, ticks=165959/89, in_queue=166083, util=100.00%, aggrios=44422/2, aggsectors=5681486/3228, aggrmerge=0/0, aggrticks=10751/13, aggrin_queue=10764, aggrutil=99.17% 675s sdd: ios=40534/0, sectors=5184640/0, merge=0/0, ticks=8326/0, in_queue=8325, util=33.05% 675s sdb: ios=31859/8, sectors=4074880/12912, merge=0/0, ticks=8452/54, in_queue=8506, util=99.17% 675s sde: ios=73014/0, sectors=9339136/0, merge=0/0, ticks=17401/0, in_queue=17401, util=40.08% 675s sdc: ios=32282/0, sectors=4127288/0, merge=0/0, ticks=8826/0, in_queue=8827, util=50.14% 675s Post FIO 21:44:32.284542171 675s FIO verify test with changing paths - OK 675s Report log of background activity 675s + echo FIO verify test with changing paths - OK 675s + echo Report log of background activity 675s + cat /tmp/autopkgtest.jTrtEh/tgtbasedmpaths-artifacts/test-background.log 675s + iscsiadm --mode session 675s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s + sleep 10s 675s + date +MP report (expect 4) %H:%M:%S.%N 675s MP report (expect 4) 21:41:41.952352839 675s + multipath -ll 675s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 675s size=100M features='0' hwhandler='0' wp=rw 675s |-+- policy='service-time 0' prio=1 status=active 675s | `- 1:0:0:1 sdb 8:16 active ready running 675s |-+- policy='service-time 0' prio=1 status=enabled 675s | `- 2:0:0:1 sdc 8:32 active ready running 675s |-+- policy='service-time 0' prio=1 status=enabled 675s | `- 3:0:0:1 sdd 8:48 active ready running 675s `-+- policy='service-time 0' prio=1 status=enabled 675s `- 4:0:0:1 sde 8:64 active ready running 675s + date +UN-plug path 1 %H:%M:%S.%N 675s UN-plug path 1 21:41:41.976599983 675s + iscsiadm --mode session -r 1 -u 675s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 675s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 675s + iscsiadm --mode session 675s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s + sleep 10s 675s + date +MP report (expect 3) %H:%M:%S.%N 675s MP report (expect 3) 21:41:52.057074662 675s + multipath -ll 675s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 675s size=100M features='0' hwhandler='0' wp=rw 675s |-+- policy='service-time 0' prio=1 status=active 675s | `- 2:0:0:1 sdc 8:32 active ready running 675s |-+- policy='service-time 0' prio=1 status=enabled 675s | `- 3:0:0:1 sdd 8:48 active ready running 675s `-+- policy='service-time 0' prio=1 status=enabled 675s `- 4:0:0:1 sde 8:64 active ready running 675s + date +UN-plug path 2 %H:%M:%S.%N 675s UN-plug path 2 21:41:52.077968251 675s + iscsiadm --mode session -r 2 -u 675s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 675s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 675s + iscsiadm --mode session 675s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s + sleep 10s 675s + date +MP report (expect 2) %H:%M:%S.%N 675s MP report (expect 2) 21:42:02.197546623 675s + multipath -ll 675s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 675s size=100M features='0' hwhandler='0' wp=rw 675s |-+- policy='service-time 0' prio=1 status=active 675s | `- 3:0:0:1 sdd 8:48 active ready running 675s `-+- policy='service-time 0' prio=1 status=enabled 675s `- 4:0:0:1 sde 8:64 active ready running 675s + date +UN-plug path 3 %H:%M:%S.%N 675s UN-plug path 3 21:42:02.216308468 675s + iscsiadm --mode session -r 3 -u 675s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 675s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 675s + iscsiadm --mode session 675s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s + sleep 10s 675s + date +MP report (expect 1) %H:%M:%S.%N 675s MP report (expect 1) 21:42:12.312450200 675s + multipath -ll 675s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 675s size=100M features='0' hwhandler='0' wp=rw 675s `-+- policy='service-time 0' prio=1 status=active 675s `- 4:0:0:1 sde 8:64 active ready running 675s + date +Add paths 5/6/7/8 %H:%M:%S.%N 675s Add paths 5/6/7/8 21:42:12.329696060 675s + iscsiadm --mode session -r 4 --op new 675s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 675s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 675s + iscsiadm --mode session -r 4 --op new 675s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 675s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 675s + iscsiadm --mode session -r 4 --op new 675s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 675s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 675s + iscsiadm --mode session -r 4 --op new 675s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 675s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 675s + iscsiadm --mode session 675s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s + sleep 10s 675s + date +MP report (expect 5) %H:%M:%S.%N 675s MP report (expect 5) 21:42:22.496993202 675s + multipath -ll 675s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 675s size=100M features='0' hwhandler='0' wp=rw 675s |-+- policy='service-time 0' prio=1 status=active 675s | `- 4:0:0:1 sde 8:64 active ready running 675s |-+- policy='service-time 0' prio=1 status=enabled 675s | `- 1:0:0:1 sdb 8:16 active ready running 675s |-+- policy='service-time 0' prio=1 status=enabled 675s | `- 2:0:0:1 sdc 8:32 active ready running 675s |-+- policy='service-time 0' prio=1 status=enabled 675s | `- 3:0:0:1 sdd 8:48 active ready running 675s `-+- policy='service-time 0' prio=1 status=enabled 675s `- 5:0:0:1 sdf 8:80 active ready running 675s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 675s UN-plug multiple paths 4/7/8 21:42:22.526083804 675s + iscsiadm --mode session -r 4 -u 675s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 675s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 675s + iscsiadm --mode session -r 7 -u 675s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 675s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 675s + iscsiadm --mode session -r 8 -u 675s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 675s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 675s + iscsiadm --mode session 675s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 675s + sleep 10s 675s + date +Restart multipath daemon %H:%M:%S.%N 675s Restart multipath daemon 21:42:32.783099382 675s + systemctl restart multipathd 675s + sleep 10s 675s + date +Final background report (expect 2) %H:%M:%S.%N 675s Final background report (expect 2) 21:42:42.869411787 675s + multipath -ll 675s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 675s size=100M features='0' hwhandler='0' wp=rw 675s |-+- policy='service-time 0' prio=1 status=active 675s | `- 1:0:0:1 sdb 8:16 active ready running 675s `-+- policy='service-time 0' prio=1 status=enabled 675s `- 2:0:0:1 sdc 8:32 active ready running 675s Final stats 675s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 675s iSCSI SNMP: 675s txdata_octets: 22232904 675s rxdata_octets: 30332359604 675s noptx_pdus: 0 675s scsicmd_pdus: 462918 675s tmfcmd_pdus: 0 675s login_pdus: 0 675s text_pdus: 0 675s dataout_pdus: 0 675s logout_pdus: 0 675s snack_pdus: 0 675s noprx_pdus: 0 675s scsirsp_pdus: 462918 675s tmfrsp_pdus: 0 675s textrsp_pdus: 0 675s datain_pdus: 462885 675s logoutrsp_pdus: 0 675s r2t_pdus: 0 675s async_pdus: 0 675s rjt_pdus: 0 675s digest_err: 0 675s timeout_err: 0 675s iSCSI Extended: 675s tx_sendpage_failures: 0 675s rx_discontiguous_hdr: 0 675s eh_abort_cnt: 0 675s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 675s iSCSI SNMP: 675s txdata_octets: 6456 675s rxdata_octets: 1514916 675s noptx_pdus: 0 675s scsicmd_pdus: 105 675s tmfcmd_pdus: 0 675s login_pdus: 0 675s text_pdus: 0 675s dataout_pdus: 0 675s logout_pdus: 0 675s snack_pdus: 0 675s noprx_pdus: 0 675s scsirsp_pdus: 105 675s tmfrsp_pdus: 0 675s textrsp_pdus: 0 675s datain_pdus: 83 675s logoutrsp_pdus: 0 675s r2t_pdus: 0 675s async_pdus: 0 675s rjt_pdus: 0 675s digest_err: 0 675s timeout_err: 0 675s iSCSI Extended: 675s tx_sendpage_failures: 0 675s rx_discontiguous_hdr: 0 675s eh_abort_cnt: 0 675s May 09 10:16:05 adtubuntu-oracular-ppc64el-server-20240507 multipathd[261]: multipathd v0.9.4: start up 675s May 09 10:16:06 adtubuntu-oracular-ppc64el-server-20240507 multipathd[261]: reconfigure: setting up paths and maps 675s May 09 10:16:05 adtubuntu-oracular-ppc64el-server-20240507 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 675s May 09 10:17:22 adtubuntu-oracular-ppc64el-server-20240508 multipathd[261]: multipathd: shut down 675s May 09 10:17:22 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 675s May 09 10:17:22 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: multipathd.service: Deactivated successfully. 675s May 09 10:17:22 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 675s -- Boot 8055b427e6ec4dd3bb1991930f846ca7 -- 675s May 09 10:18:38 adtubuntu-oracular-ppc64el-server-20240508 multipathd[263]: multipathd v0.9.4: start up 675s May 09 10:18:38 adtubuntu-oracular-ppc64el-server-20240508 multipathd[263]: reconfigure: setting up paths and maps 675s May 09 10:18:37 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 675s May 09 10:19:50 adtubuntu-oracular-ppc64el-server-20240508 multipathd[263]: multipathd: shut down 675s May 09 10:19:50 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 675s May 09 10:19:50 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: multipathd.service: Deactivated successfully. 675s May 09 10:19:50 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 675s -- Boot cf711cb7475e4673a99120621b68c983 -- 675s May 19 21:39:20 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 675s May 19 21:39:20 adtubuntu-oracular-ppc64el-server-20240508 multipathd[334]: multipathd v0.9.4: start up 675s May 19 21:39:20 adtubuntu-oracular-ppc64el-server-20240508 multipathd[334]: reconfigure: setting up paths and maps 675s May 19 21:39:20 adtubuntu-oracular-ppc64el-server-20240508 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 675s May 19 21:40:17 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 675s May 19 21:40:17 autopkgtest multipathd[334]: multipathd: shut down 675s May 19 21:40:18 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 675s May 19 21:40:18 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 675s -- Boot 9fcfac0aaa414f5b811a35ee77714128 -- 675s May 19 21:40:41 autopkgtest multipathd[319]: multipathd v0.9.4: start up 675s May 19 21:40:41 autopkgtest multipathd[319]: reconfigure: setting up paths and maps 675s May 19 21:40:41 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 675s May 19 21:41:22 autopkgtest multipathd[319]: mpatha: addmap [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 675s May 19 21:41:22 autopkgtest multipathd[319]: sdc [8:32]: path added to devmap mpatha 675s May 19 21:41:22 autopkgtest multipathd[319]: mpatha: performing delayed actions 675s May 19 21:41:22 autopkgtest multipathd[319]: 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:64 1] 675s May 19 21:41:42 autopkgtest multipathd[319]: 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] 675s May 19 21:41:42 autopkgtest multipathd[319]: check_removed_paths: sdb: freeing path in removed state 675s May 19 21:41:42 autopkgtest multipathd[319]: 8:16: path removed from map mpatha 675s May 19 21:41:52 autopkgtest multipathd[319]: sdc: mark as failed 675s May 19 21:41:52 autopkgtest multipathd[319]: mpatha: remaining active paths: 2 675s May 19 21:41:52 autopkgtest multipathd[319]: 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] 675s May 19 21:41:52 autopkgtest multipathd[319]: check_removed_paths: sdc: freeing path in removed state 675s May 19 21:41:52 autopkgtest multipathd[319]: 8:32: path removed from map mpatha 675s May 19 21:42:02 autopkgtest multipathd[319]: sdd: mark as failed 675s May 19 21:42:02 autopkgtest multipathd[319]: mpatha: remaining active paths: 1 675s May 19 21:42:02 autopkgtest multipathd[319]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 675s May 19 21:42:02 autopkgtest multipathd[319]: check_removed_paths: sdd: freeing path in removed state 675s May 19 21:42:02 autopkgtest multipathd[319]: 8:48: path removed from map mpatha 675s May 19 21:42:12 autopkgtest multipathd[319]: 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] 675s May 19 21:42:12 autopkgtest multipathd[319]: sdb [8:16]: path added to devmap mpatha 675s May 19 21:42:12 autopkgtest multipathd[319]: 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] 675s May 19 21:42:12 autopkgtest multipathd[319]: sdc [8:32]: path added to devmap mpatha 675s May 19 21:42:12 autopkgtest multipathd[319]: 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] 675s May 19 21:42:12 autopkgtest multipathd[319]: sdd [8:48]: path added to devmap mpatha 675s May 19 21:42:12 autopkgtest multipathd[319]: 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] 675s May 19 21:42:12 autopkgtest multipathd[319]: sdf [8:80]: path added to devmap mpatha 675s May 19 21:42:22 autopkgtest multipathd[319]: 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] 675s May 19 21:42:22 autopkgtest multipathd[319]: check_removed_paths: sde: freeing path in removed state 675s May 19 21:42:22 autopkgtest multipathd[319]: 8:64: path removed from map mpatha 675s May 19 21:42:22 autopkgtest multipathd[319]: 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] 675s May 19 21:42:22 autopkgtest multipathd[319]: check_removed_paths: sdd: freeing path in removed state 675s May 19 21:42:22 autopkgtest multipathd[319]: 8:48: path removed from map mpatha 675s May 19 21:42:22 autopkgtest multipathd[319]: 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] 675s May 19 21:42:22 autopkgtest multipathd[319]: check_removed_paths: sdf: freeing path in removed state 675s May 19 21:42:22 autopkgtest multipathd[319]: 8:80: path removed from map mpatha 675s May 19 21:42:32 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 675s May 19 21:42:32 autopkgtest multipathd[319]: multipathd: shut down 675s May 19 21:42:32 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 675s May 19 21:42:32 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 675s May 19 21:42:32 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 675s May 19 21:42:32 autopkgtest multipathd[6043]: multipathd v0.9.4: start up 675s May 19 21:42:32 autopkgtest multipathd[6043]: reconfigure: setting up paths and maps 675s May 19 21:42:32 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 675s Check final path status 675s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 675s size=100M features='0' hwhandler='0' wp=rw 675s |-+- policy='service-time 0' prio=1 status=active 675s | `- 1:0:0:1 sdb 8:16 active ready running 675s `-+- policy='service-time 0' prio=1 status=enabled 675s `- 2:0:0:1 sdc 8:32 active ready running 675s + sync 675s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 675s + echo Final stats 675s + iscsiadm --mode session --stats 675s + journalctl --no-pager -u multipathd 675s + echo Check final path status 675s + multipath -ll 675s + multipath -ll 675s + grep --count status= 675s + diskc=2 675s + multipath -ll 675s + grep --count status=active 675s + diska=1 675s + multipath -ll 675s + grep --count status=enabled 675s + diske=1 675s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 675s + echo OK 675s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 675s OK 675s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 675s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 675s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 675s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 675s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 675s autopkgtest [21:44:32]: test tgtbasedmpaths: -----------------------] 676s tgtbasedmpaths PASS 676s autopkgtest [21:44:33]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 676s autopkgtest [21:44:33]: @@@@@@@@@@@@@@@@@@@@ summary 676s kpartx-file-loopback PASS 676s tgtbasedmpaths PASS 688s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240519-213316-juju-7f2275-prod-proposed-migration-environment-3-8e6051f9-cd72-4a84-8a09-bb588e814fe9 from image adt/ubuntu-oracular-ppc64el-server-20240509.img (UUID 1c85ce1c-4944-4b4e-a1c6-2159ec573517)... 688s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240519-213316-juju-7f2275-prod-proposed-migration-environment-3-8e6051f9-cd72-4a84-8a09-bb588e814fe9 from image adt/ubuntu-oracular-ppc64el-server-20240509.img (UUID 1c85ce1c-4944-4b4e-a1c6-2159ec573517)...