0s autopkgtest [23:10:51]: starting date and time: 2024-05-31 23:10:51+0000 0s autopkgtest [23:10:51]: git checkout: 930f72e5 setup-testbed: don't install 'Recommends' for 'linux-generic' 0s autopkgtest [23:10:51]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.4wngjn1z/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:systemd,src:collectd,src:dpdk --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=systemd/256~rc3-5ubuntu1 collectd/5.12.0-18build1 dpdk/23.11.1-1' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos02-ppc64el-9.secgroup --name adt-oracular-ppc64el-multipath-tools-20240531-231050-juju-7f2275-prod-proposed-migration-environment-2-dff8c86b-d1a7-44d4-8820-f28751a56d85 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 142s autopkgtest [23:13:13]: testbed dpkg architecture: ppc64el 142s autopkgtest [23:13:13]: testbed apt version: 2.9.3 142s autopkgtest [23:13:13]: @@@@@@@@@@@@@@@@@@@@ test bed setup 143s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 144s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [394 kB] 144s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [4792 B] 144s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [1680 B] 144s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [55.7 kB] 144s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [94.4 kB] 144s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [378 kB] 144s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1392 B] 144s Fetched 1041 kB in 1s (1241 kB/s) 144s Reading package lists... 146s Reading package lists... 147s Building dependency tree... 147s Reading state information... 147s Calculating upgrade... 147s The following package was automatically installed and is no longer required: 147s systemd-dev 147s Use 'sudo apt autoremove' to remove it. 147s The following packages will be upgraded: 147s dhcpcd-base libnss-systemd libpam-systemd libsystemd-shared libsystemd0 147s libudev1 systemd systemd-dev systemd-resolved systemd-sysv systemd-timesyncd 147s udev 147s 12 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 147s Need to get 10.6 MB of archives. 147s After this operation, 1789 kB of additional disk space will be used. 147s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-dev all 256~rc3-5ubuntu1 [110 kB] 147s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-timesyncd ppc64el 256~rc3-5ubuntu1 [37.9 kB] 147s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-resolved ppc64el 256~rc3-5ubuntu1 [363 kB] 147s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd-shared ppc64el 256~rc3-5ubuntu1 [2467 kB] 148s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd0 ppc64el 256~rc3-5ubuntu1 [546 kB] 148s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-sysv ppc64el 256~rc3-5ubuntu1 [11.9 kB] 148s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnss-systemd ppc64el 256~rc3-5ubuntu1 [210 kB] 148s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpam-systemd ppc64el 256~rc3-5ubuntu1 [318 kB] 148s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd ppc64el 256~rc3-5ubuntu1 [3958 kB] 148s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el udev ppc64el 256~rc3-5ubuntu1 [2105 kB] 148s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libudev1 ppc64el 256~rc3-5ubuntu1 [216 kB] 148s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el dhcpcd-base ppc64el 1:10.0.8-1 [277 kB] 148s Fetched 10.6 MB in 1s (10.2 MB/s) 148s (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 ... 72596 files and directories currently installed.) 148s Preparing to unpack .../systemd-dev_256~rc3-5ubuntu1_all.deb ... 148s Unpacking systemd-dev (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 148s Preparing to unpack .../systemd-timesyncd_256~rc3-5ubuntu1_ppc64el.deb ... 148s Unpacking systemd-timesyncd (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 148s Preparing to unpack .../systemd-resolved_256~rc3-5ubuntu1_ppc64el.deb ... 148s Unpacking systemd-resolved (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 148s Preparing to unpack .../libsystemd-shared_256~rc3-5ubuntu1_ppc64el.deb ... 148s Unpacking libsystemd-shared:ppc64el (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 149s Preparing to unpack .../libsystemd0_256~rc3-5ubuntu1_ppc64el.deb ... 149s Unpacking libsystemd0:ppc64el (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 149s Setting up libsystemd0:ppc64el (256~rc3-5ubuntu1) ... 149s (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 ... 72598 files and directories currently installed.) 149s Preparing to unpack .../0-systemd-sysv_256~rc3-5ubuntu1_ppc64el.deb ... 149s Unpacking systemd-sysv (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 149s Preparing to unpack .../1-libnss-systemd_256~rc3-5ubuntu1_ppc64el.deb ... 149s Unpacking libnss-systemd:ppc64el (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 149s Preparing to unpack .../2-libpam-systemd_256~rc3-5ubuntu1_ppc64el.deb ... 149s Unpacking libpam-systemd:ppc64el (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 149s Preparing to unpack .../3-systemd_256~rc3-5ubuntu1_ppc64el.deb ... 149s Unpacking systemd (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 149s Preparing to unpack .../4-udev_256~rc3-5ubuntu1_ppc64el.deb ... 149s Unpacking udev (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 149s Preparing to unpack .../5-libudev1_256~rc3-5ubuntu1_ppc64el.deb ... 149s Unpacking libudev1:ppc64el (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 149s Setting up libudev1:ppc64el (256~rc3-5ubuntu1) ... 149s (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 ... 72657 files and directories currently installed.) 149s Preparing to unpack .../dhcpcd-base_1%3a10.0.8-1_ppc64el.deb ... 149s Unpacking dhcpcd-base (1:10.0.8-1) over (1:10.0.6-5) ... 149s Setting up systemd-dev (256~rc3-5ubuntu1) ... 149s Setting up libsystemd-shared:ppc64el (256~rc3-5ubuntu1) ... 149s Setting up dhcpcd-base (1:10.0.8-1) ... 149s Setting up systemd (256~rc3-5ubuntu1) ... 149s Installing new version of config file /etc/systemd/journald.conf ... 149s Installing new version of config file /etc/systemd/logind.conf ... 149s Installing new version of config file /etc/systemd/networkd.conf ... 149s Installing new version of config file /etc/systemd/sleep.conf ... 149s Installing new version of config file /etc/systemd/system.conf ... 149s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 149s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 150s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 150s Setting up systemd-timesyncd (256~rc3-5ubuntu1) ... 151s Setting up udev (256~rc3-5ubuntu1) ... 152s Setting up systemd-resolved (256~rc3-5ubuntu1) ... 152s Installing new version of config file /etc/systemd/resolved.conf ... 153s Setting up systemd-sysv (256~rc3-5ubuntu1) ... 153s Setting up libnss-systemd:ppc64el (256~rc3-5ubuntu1) ... 153s Setting up libpam-systemd:ppc64el (256~rc3-5ubuntu1) ... 153s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 153s Processing triggers for man-db (2.12.1-1) ... 154s Processing triggers for dbus (1.14.10-4ubuntu4) ... 154s Processing triggers for shared-mime-info (2.4-4) ... 154s Processing triggers for initramfs-tools (0.142ubuntu27) ... 154s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 155s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 163s Reading package lists... 163s Building dependency tree... 163s Reading state information... 163s The following packages will be REMOVED: 163s systemd-dev* 163s 0 upgraded, 0 newly installed, 1 to remove and 0 not upgraded. 163s After this operation, 758 kB disk space will be freed. 163s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72657 files and directories currently installed.) 163s Removing systemd-dev (256~rc3-5ubuntu1) ... 164s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 164s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 164s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 164s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 165s Reading package lists... 165s Reading package lists... 165s Building dependency tree... 165s Reading state information... 166s Calculating upgrade... 166s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 166s Reading package lists... 166s Building dependency tree... 166s Reading state information... 166s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 166s autopkgtest [23:13:37]: rebooting testbed after setup commands that affected boot 200s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 213s autopkgtest [23:14:24]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 216s autopkgtest [23:14:27]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 219s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 219s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 219s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 219s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 219s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 219s gpgv: issuer "steve.langasek@ubuntu.com" 219s gpgv: Can't check signature: No public key 219s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 219s autopkgtest [23:14:30]: testing package multipath-tools version 0.9.4-5ubuntu8 220s autopkgtest [23:14:31]: build not needed 220s autopkgtest [23:14:31]: test kpartx-file-loopback: preparing testbed 221s Reading package lists... 221s Building dependency tree... 221s Reading state information... 221s Starting pkgProblemResolver with broken count: 0 221s Starting 2 pkgProblemResolver with broken count: 0 221s Done 222s The following additional packages will be installed: 222s liburing2 qemu-utils 222s Recommended packages: 222s qemu-block-extra 222s The following NEW packages will be installed: 222s autopkgtest-satdep liburing2 qemu-utils 222s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 222s Need to get 2330 kB/2331 kB of archives. 222s After this operation, 15.4 MB of additional disk space will be used. 222s Get:1 /tmp/autopkgtest.gsdqlQ/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 222s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 222s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 223s Fetched 2330 kB in 1s (2065 kB/s) 223s Selecting previously unselected package liburing2:ppc64el. 223s (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 ... 72610 files and directories currently installed.) 223s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 223s Unpacking liburing2:ppc64el (2.6-1) ... 223s Selecting previously unselected package qemu-utils. 223s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 223s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 223s Selecting previously unselected package autopkgtest-satdep. 223s Preparing to unpack .../1-autopkgtest-satdep.deb ... 223s Unpacking autopkgtest-satdep (0) ... 223s Setting up liburing2:ppc64el (2.6-1) ... 223s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 223s Setting up autopkgtest-satdep (0) ... 223s Processing triggers for man-db (2.12.1-1) ... 224s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 227s (Reading database ... 72630 files and directories currently installed.) 227s Removing autopkgtest-satdep (0) ... 227s autopkgtest [23:14:38]: test kpartx-file-loopback: [----------------------- 227s Formatting 'foo.img', fmt=raw size=20971520 228s Creating new GPT entries in memory. 228s Warning: The kernel is still using the old partition table. 228s The new table will be used at the next reboot or after you 228s run partprobe(8) or kpartx(8) 228s The operation has completed successfully. 228s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 228s standard_filename: OK 229s del devmap : loop0p1 229s No devices found 229s standard_filename_cleanup: OK 229s Formatting 'fou du FaFa.img', fmt=raw size=20971520 230s Creating new GPT entries in memory. 230s Warning: The kernel is still using the old partition table. 230s The new table will be used at the next reboot or after you 230s run partprobe(8) or kpartx(8) 230s The operation has completed successfully. 230s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 230s filename_with_spaces: OK 230s del devmap : loop0p1 230s No devices found 230s filename_with_spaces_cleanup: OK 230s autopkgtest [23:14:41]: test kpartx-file-loopback: -----------------------] 230s autopkgtest [23:14:41]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 230s kpartx-file-loopback PASS 231s autopkgtest [23:14:42]: test tgtbasedmpaths: preparing testbed 333s autopkgtest [23:16:24]: testbed dpkg architecture: ppc64el 334s autopkgtest [23:16:25]: testbed apt version: 2.9.3 334s autopkgtest [23:16:25]: @@@@@@@@@@@@@@@@@@@@ test bed setup 334s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 335s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [1680 B] 335s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [4792 B] 335s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [55.7 kB] 335s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [394 kB] 335s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [94.4 kB] 335s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [378 kB] 335s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1392 B] 335s Fetched 1041 kB in 1s (1239 kB/s) 335s Reading package lists... 337s Reading package lists... 338s Building dependency tree... 338s Reading state information... 338s Calculating upgrade... 338s The following package was automatically installed and is no longer required: 338s systemd-dev 338s Use 'sudo apt autoremove' to remove it. 338s The following packages will be upgraded: 338s dhcpcd-base libnss-systemd libpam-systemd libsystemd-shared libsystemd0 338s libudev1 systemd systemd-dev systemd-resolved systemd-sysv systemd-timesyncd 338s udev 338s 12 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 338s Need to get 10.6 MB of archives. 338s After this operation, 1789 kB of additional disk space will be used. 338s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-dev all 256~rc3-5ubuntu1 [110 kB] 338s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-timesyncd ppc64el 256~rc3-5ubuntu1 [37.9 kB] 338s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-resolved ppc64el 256~rc3-5ubuntu1 [363 kB] 338s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd-shared ppc64el 256~rc3-5ubuntu1 [2467 kB] 339s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd0 ppc64el 256~rc3-5ubuntu1 [546 kB] 339s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-sysv ppc64el 256~rc3-5ubuntu1 [11.9 kB] 339s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnss-systemd ppc64el 256~rc3-5ubuntu1 [210 kB] 339s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpam-systemd ppc64el 256~rc3-5ubuntu1 [318 kB] 339s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd ppc64el 256~rc3-5ubuntu1 [3958 kB] 339s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el udev ppc64el 256~rc3-5ubuntu1 [2105 kB] 339s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libudev1 ppc64el 256~rc3-5ubuntu1 [216 kB] 339s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el dhcpcd-base ppc64el 1:10.0.8-1 [277 kB] 339s Fetched 10.6 MB in 1s (9710 kB/s) 339s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72596 files and directories currently installed.) 339s Preparing to unpack .../systemd-dev_256~rc3-5ubuntu1_all.deb ... 339s Unpacking systemd-dev (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 340s Preparing to unpack .../systemd-timesyncd_256~rc3-5ubuntu1_ppc64el.deb ... 340s Unpacking systemd-timesyncd (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 340s Preparing to unpack .../systemd-resolved_256~rc3-5ubuntu1_ppc64el.deb ... 340s Unpacking systemd-resolved (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 340s Preparing to unpack .../libsystemd-shared_256~rc3-5ubuntu1_ppc64el.deb ... 340s Unpacking libsystemd-shared:ppc64el (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 340s Preparing to unpack .../libsystemd0_256~rc3-5ubuntu1_ppc64el.deb ... 340s Unpacking libsystemd0:ppc64el (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 340s Setting up libsystemd0:ppc64el (256~rc3-5ubuntu1) ... 340s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72598 files and directories currently installed.) 340s Preparing to unpack .../0-systemd-sysv_256~rc3-5ubuntu1_ppc64el.deb ... 340s Unpacking systemd-sysv (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 340s Preparing to unpack .../1-libnss-systemd_256~rc3-5ubuntu1_ppc64el.deb ... 340s Unpacking libnss-systemd:ppc64el (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 340s Preparing to unpack .../2-libpam-systemd_256~rc3-5ubuntu1_ppc64el.deb ... 340s Unpacking libpam-systemd:ppc64el (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 340s Preparing to unpack .../3-systemd_256~rc3-5ubuntu1_ppc64el.deb ... 340s Unpacking systemd (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 340s Preparing to unpack .../4-udev_256~rc3-5ubuntu1_ppc64el.deb ... 340s Unpacking udev (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 340s Preparing to unpack .../5-libudev1_256~rc3-5ubuntu1_ppc64el.deb ... 340s Unpacking libudev1:ppc64el (256~rc3-5ubuntu1) over (255.4-1ubuntu8) ... 340s Setting up libudev1:ppc64el (256~rc3-5ubuntu1) ... 340s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72657 files and directories currently installed.) 340s Preparing to unpack .../dhcpcd-base_1%3a10.0.8-1_ppc64el.deb ... 340s Unpacking dhcpcd-base (1:10.0.8-1) over (1:10.0.6-5) ... 340s Setting up systemd-dev (256~rc3-5ubuntu1) ... 340s Setting up libsystemd-shared:ppc64el (256~rc3-5ubuntu1) ... 340s Setting up dhcpcd-base (1:10.0.8-1) ... 340s Setting up systemd (256~rc3-5ubuntu1) ... 340s Installing new version of config file /etc/systemd/journald.conf ... 340s Installing new version of config file /etc/systemd/logind.conf ... 340s Installing new version of config file /etc/systemd/networkd.conf ... 340s Installing new version of config file /etc/systemd/sleep.conf ... 340s Installing new version of config file /etc/systemd/system.conf ... 340s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 340s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 341s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 341s Setting up systemd-timesyncd (256~rc3-5ubuntu1) ... 342s Setting up udev (256~rc3-5ubuntu1) ... 343s Setting up systemd-resolved (256~rc3-5ubuntu1) ... 343s Installing new version of config file /etc/systemd/resolved.conf ... 344s Setting up systemd-sysv (256~rc3-5ubuntu1) ... 344s Setting up libnss-systemd:ppc64el (256~rc3-5ubuntu1) ... 344s Setting up libpam-systemd:ppc64el (256~rc3-5ubuntu1) ... 344s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 344s Processing triggers for man-db (2.12.1-1) ... 345s Processing triggers for dbus (1.14.10-4ubuntu4) ... 345s Processing triggers for shared-mime-info (2.4-4) ... 345s Processing triggers for initramfs-tools (0.142ubuntu27) ... 346s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 346s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 353s Reading package lists... 353s Building dependency tree... 353s Reading state information... 354s The following packages will be REMOVED: 354s systemd-dev* 354s 0 upgraded, 0 newly installed, 1 to remove and 0 not upgraded. 354s After this operation, 758 kB disk space will be freed. 354s (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 ... 72657 files and directories currently installed.) 354s Removing systemd-dev (256~rc3-5ubuntu1) ... 354s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 355s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 355s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 355s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 356s Reading package lists... 356s Reading package lists... 356s Building dependency tree... 356s Reading state information... 356s Calculating upgrade... 356s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 356s Reading package lists... 356s Building dependency tree... 356s Reading state information... 357s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 357s autopkgtest [23:16:48]: rebooting testbed after setup commands that affected boot 361s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 394s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 407s Reading package lists... 407s Building dependency tree... 407s Reading state information... 408s Starting pkgProblemResolver with broken count: 0 408s Starting 2 pkgProblemResolver with broken count: 0 408s Done 408s The following additional packages will be installed: 408s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 408s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 408s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 408s librdmacm1t64 lsscsi open-iscsi tgt 408s Suggested packages: 408s fio-examples gnuplot tgt-glusterfs tgt-rbd 408s Recommended packages: 408s finalrd 408s The following NEW packages will be installed: 408s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 408s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 408s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 408s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 408s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 408s Need to get 10.7 MB/10.7 MB of archives. 408s After this operation, 49.1 MB of additional disk space will be used. 408s Get:1 /tmp/autopkgtest.gsdqlQ/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 408s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu4 [54.4 kB] 408s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 408s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu4 [389 kB] 408s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 408s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 408s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu6 [256 kB] 408s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4build3 [21.5 kB] 409s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4build3 [311 kB] 409s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4build3 [47.0 kB] 409s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4build3 [100 kB] 409s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.1-1 [97.4 kB] 409s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 409s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 409s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 409s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-2.1ubuntu3 [260 kB] 409s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-2.1ubuntu3 [280 kB] 409s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 409s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 409s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 409s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 409s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 409s Preconfiguring packages ... 409s Fetched 10.7 MB in 1s (11.0 MB/s) 409s Selecting previously unselected package libopeniscsiusr. 409s (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 ... 72610 files and directories currently installed.) 409s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu4_ppc64el.deb ... 409s Unpacking libopeniscsiusr (2.1.9-3ubuntu4) ... 409s Selecting previously unselected package libisns0t64:ppc64el. 409s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 409s Unpacking libisns0t64:ppc64el (0.101-1) ... 409s Selecting previously unselected package open-iscsi. 410s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu4_ppc64el.deb ... 410s Unpacking open-iscsi (2.1.9-3ubuntu4) ... 410s Selecting previously unselected package librdmacm1t64:ppc64el. 410s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 410s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 410s Selecting previously unselected package libconfig-general-perl. 410s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 410s Unpacking libconfig-general-perl (2.65-2) ... 410s Selecting previously unselected package tgt. 410s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu6_ppc64el.deb ... 410s Unpacking tgt (1:1.0.85-1.1ubuntu6) ... 410s Selecting previously unselected package libgfxdr0:ppc64el. 410s Preparing to unpack .../06-libgfxdr0_11.1-4build3_ppc64el.deb ... 410s Unpacking libgfxdr0:ppc64el (11.1-4build3) ... 410s Selecting previously unselected package libglusterfs0:ppc64el. 410s Preparing to unpack .../07-libglusterfs0_11.1-4build3_ppc64el.deb ... 410s Unpacking libglusterfs0:ppc64el (11.1-4build3) ... 410s Selecting previously unselected package libgfrpc0:ppc64el. 410s Preparing to unpack .../08-libgfrpc0_11.1-4build3_ppc64el.deb ... 410s Unpacking libgfrpc0:ppc64el (11.1-4build3) ... 410s Selecting previously unselected package libgfapi0:ppc64el. 410s Preparing to unpack .../09-libgfapi0_11.1-4build3_ppc64el.deb ... 410s Unpacking libgfapi0:ppc64el (11.1-4build3) ... 410s Selecting previously unselected package libnbd0. 410s Preparing to unpack .../10-libnbd0_1.20.1-1_ppc64el.deb ... 410s Unpacking libnbd0 (1.20.1-1) ... 410s Selecting previously unselected package libdaxctl1:ppc64el. 410s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 410s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 410s Selecting previously unselected package libndctl6:ppc64el. 410s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 410s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 410s Selecting previously unselected package libpmem1:ppc64el. 410s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 410s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 410s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 410s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 410s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 410s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 410s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 410s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 410s Selecting previously unselected package librados2. 410s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 410s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 410s Selecting previously unselected package libpmemobj1:ppc64el. 410s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 410s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 410s Selecting previously unselected package librbd1. 410s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 410s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 410s Selecting previously unselected package fio. 410s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 410s Unpacking fio (3.37-1) ... 410s Selecting previously unselected package lsscsi. 410s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 410s Unpacking lsscsi (0.32-1build1) ... 410s Selecting previously unselected package autopkgtest-satdep. 410s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 410s Unpacking autopkgtest-satdep (0) ... 410s Setting up libconfig-general-perl (2.65-2) ... 410s Setting up libisns0t64:ppc64el (0.101-1) ... 410s Setting up libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 410s Setting up libnbd0 (1.20.1-1) ... 410s Setting up libopeniscsiusr (2.1.9-3ubuntu4) ... 410s Setting up libglusterfs0:ppc64el (11.1-4build3) ... 410s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 410s Setting up lsscsi (0.32-1build1) ... 410s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 410s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 410s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 410s Setting up tgt (1:1.0.85-1.1ubuntu6) ... 411s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 411s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 411s Setting up libgfxdr0:ppc64el (11.1-4build3) ... 411s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 411s Setting up open-iscsi (2.1.9-3ubuntu4) ... 412s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 413s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 413s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 413s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 413s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 413s Setting up libgfrpc0:ppc64el (11.1-4build3) ... 413s Setting up libgfapi0:ppc64el (11.1-4build3) ... 413s Setting up fio (3.37-1) ... 413s Setting up autopkgtest-satdep (0) ... 413s Processing triggers for man-db (2.12.1-1) ... 415s Processing triggers for initramfs-tools (0.142ubuntu27) ... 415s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 415s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 423s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 425s (Reading database ... 72851 files and directories currently installed.) 425s Removing autopkgtest-satdep (0) ... 427s autopkgtest [23:17:58]: test tgtbasedmpaths: [----------------------- 427s + targetname=iqn.2016-11.foo.com:target.iscsi 427s + pwd 427s + cwd=/tmp/autopkgtest.gsdqlQ/build.pVu/src 427s + testdir=/mnt/tgtmpathtest 427s + localhost=127.0.0.1 427s + portal=127.0.0.1:3260 427s + maxpaths=4 427s + backfn=backingfile 427s + expectwwid=60000000000000000e00000000010001 427s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 427s + bglog=/tmp/autopkgtest.gsdqlQ/tgtbasedmpaths-artifacts/test-background.log 427s + fioprep=/tmp/autopkgtest.gsdqlQ/tgtbasedmpaths-artifacts/path-change-prep.fio 427s + fiovrfy=/tmp/autopkgtest.gsdqlQ/tgtbasedmpaths-artifacts/path-change-check.fio 427s + service tgt restart 428s + truncate --size 100M backingfile 428s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 428s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 428s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.gsdqlQ/build.pVu/src/backingfile 428s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 428s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 428s login #1 428s + echo login #1 428s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 428s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 428s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 428s + seq 2 4 428s extra login #2 428s + echo extra login #2 428s + iscsiadm --mode session -r 1 --op new 428s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 428s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 428s extra login #3 428s + echo extra login #3 428s + iscsiadm --mode session -r 1 --op new 428s + echo extra login #4 428s + iscsiadm --mode session -r 1 --op new 428s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 428s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 428s extra login #4 428s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 428s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 428s + udevadm settle 428s + sleep 5 433s Status after initial setup 433s + echo Status after initial setup 433s + tgtadm --lld iscsi --mode target --op show 433s Target 1: iqn.2016-11.foo.com:target.iscsi 433s System information: 433s Driver: iscsi 433s State: ready 433s I_T nexus information: 433s I_T nexus: 1 433s Initiator: iqn.2004-10.com.ubuntu:01:be83a42a2db4 alias: autopkgtest 433s Connection: 0 433s IP Address: 127.0.0.1 433s I_T nexus: 2 433s Initiator: iqn.2004-10.com.ubuntu:01:be83a42a2db4 alias: autopkgtest 433s Connection: 0 433s IP Address: 127.0.0.1 433s I_T nexus: 3 433s Initiator: iqn.2004-10.com.ubuntu:01:be83a42a2db4 alias: autopkgtest 433s Connection: 0 433s IP Address: 127.0.0.1 433s I_T nexus: 4 433s Initiator: iqn.2004-10.com.ubuntu:01:be83a42a2db4 alias: autopkgtest 433s Connection: 0 433s IP Address: 127.0.0.1 433s LUN information: 433s LUN: 0 433s Type: controller 433s SCSI ID: IET 00010000 433s SCSI SN: beaf10 433s Size: 0 MB, Block size: 1 433s Online: Yes 433s Removable media: No 433s Prevent removal: No 433s Readonly: No 433s SWP: No 433s Thin-provisioning: No 433s Backing store type: null 433s Backing store path: None 433s Backing store flags: 433s LUN: 1 433s Type: disk 433s SCSI ID: IET 00010001 433s SCSI SN: beaf11 433s Size: 105 MB, Block size: 512 433s Online: Yes 433s Removable media: No 433s Prevent removal: No 433s Readonly: No 433s SWP: No 433s Thin-provisioning: No 433s Backing store type: rdwr 433s Backing store path: /tmp/autopkgtest.gsdqlQ/build.pVu/src/backingfile 433s Backing store flags: 433s Account information: 433s ACL information: 433s ALL 433s + tgtadm --lld iscsi --op show --mode conn --tid 1 433s Session: 4 433s Connection: 0 433s Initiator: iqn.2004-10.com.ubuntu:01:be83a42a2db4 433s IP Address: 127.0.0.1 433s Session: 3 433s Connection: 0 433s Initiator: iqn.2004-10.com.ubuntu:01:be83a42a2db4 433s IP Address: 127.0.0.1 433s Session: 2 433s Connection: 0 433s Initiator: iqn.2004-10.com.ubuntu:01:be83a42a2db4 433s IP Address: 127.0.0.1 433s Session: 1 433s Connection: 0 433s Initiator: iqn.2004-10.com.ubuntu:01:be83a42a2db4 433s IP Address: 127.0.0.1 433s + iscsiadm --mode session -P 1 433s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 433s Current Portal: 127.0.0.1:3260,1 433s Persistent Portal: 127.0.0.1:3260,1 433s ********** 433s Interface: 433s ********** 433s Iface Name: default 433s Iface Transport: tcp 433s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:be83a42a2db4 433s Iface IPaddress: 127.0.0.1 433s Iface HWaddress: default 433s Iface Netdev: default 433s SID: 1 433s iSCSI Connection State: LOGGED IN 433s iSCSI Session State: LOGGED_IN 433s Internal iscsid Session State: NO CHANGE 433s 433s ********** 433s Interface: 433s ********** 433s Iface Name: default 433s Iface Transport: tcp 433s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:be83a42a2db4 433s Iface IPaddress: 127.0.0.1 433s Iface HWaddress: default 433s Iface Netdev: default 433s SID: 2 433s iSCSI Connection State: LOGGED IN 433s iSCSI Session State: LOGGED_IN 433s Internal iscsid Session State: NO CHANGE 433s 433s ********** 433s Interface: 433s ********** 433s Iface Name: default 433s Iface Transport: tcp 433s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:be83a42a2db4 433s Iface IPaddress: 127.0.0.1 433s Iface HWaddress: default 433s Iface Netdev: default 433s SID: 3 433s iSCSI Connection State: LOGGED IN 433s iSCSI Session State: LOGGED_IN 433s Internal iscsid Session State: NO CHANGE 433s 433s ********** 433s Interface: 433s ********** 433s Iface Name: default 433s Iface Transport: tcp 433s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:be83a42a2db4 433s Iface IPaddress: 127.0.0.1 433s Iface HWaddress: default 433s Iface Netdev: default 433s SID: 4 433s iSCSI Connection State: LOGGED IN 433s iSCSI Session State: LOGGED_IN 433s Internal iscsid Session State: NO CHANGE 433s + lsscsi -liv 433s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 433s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 433s 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] 433s [1:0:0:0] storage IET Controller 0001 - - 433s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 433s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 433s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 433s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 433s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 433s [2:0:0:0] storage IET Controller 0001 - - 433s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 433s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 433s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 433s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 433s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 433s [3:0:0:0] storage IET Controller 0001 - - 433s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 433s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 433s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 433s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 433s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 433s [4:0:0:0] storage IET Controller 0001 - - 433s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 433s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 433s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 433s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 433s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 433s NVMe module may not be loaded 433s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 433s + multipath -v3 -ll 433s 49.713889 | set open fds limit to 1073741816/1073741816 433s 49.713987 | loading /lib/multipath/libchecktur.so checker 433s 49.714091 | checker tur: message table size = 3 433s 49.714124 | loading /lib/multipath/libprioconst.so prioritizer 433s 49.714265 | _init_foreign: foreign library "nvme" is not enabled 433s 49.721062 | sda: size = 167772160 433s 49.721268 | sda: vendor = QEMU 433s 49.721293 | sda: product = QEMU HARDDISK 433s 49.721319 | sda: rev = 2.5+ 433s 49.722023 | sda: h:b:t:l = 0:0:0:0 433s 49.722410 | sda: tgt_node_name = 433s 49.722434 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 433s 49.722437 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 433s 49.722611 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 433s 49.722635 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 433s 49.722649 | __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 433s 49.722653 | failed to read sysfs vpd pg80: No such file or directory 433s 49.722994 | sda: fail to get serial 433s 49.723020 | sda: detect_checker = yes (setting: multipath internal) 433s 49.723250 | sda: path_checker = tur (setting: multipath internal) 433s 49.723255 | sda: checker timeout = 30 s (setting: kernel sysfs) 433s 49.723490 | sda: tur state = up 433s 49.723872 | sdb: size = 204800 433s 49.724096 | sdb: vendor = IET 433s 49.724147 | sdb: product = VIRTUAL-DISK 433s 49.724173 | sdb: rev = 0001 433s 49.724936 | sdb: h:b:t:l = 1:0:0:1 433s 49.725387 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 433s 49.725411 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 433s 49.725413 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 433s 49.725591 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 433s 49.725613 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 433s 49.725632 | sdb: serial = beaf11 433s 49.725635 | sdb: detect_checker = yes (setting: multipath internal) 433s 49.725996 | sdb: path_checker = tur (setting: multipath internal) 433s 49.726021 | sdb: checker timeout = 30 s (setting: kernel sysfs) 433s 49.726253 | sdb: tur state = up 433s 49.726420 | sdc: size = 204800 433s 49.726595 | sdc: vendor = IET 433s 49.726641 | sdc: product = VIRTUAL-DISK 433s 49.726665 | sdc: rev = 0001 433s 49.727423 | sdc: h:b:t:l = 2:0:0:1 433s 49.727843 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 433s 49.727865 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 433s 49.727867 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 433s 49.728043 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 433s 49.728066 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 433s 49.728082 | sdc: serial = beaf11 433s 49.728085 | sdc: detect_checker = yes (setting: multipath internal) 433s 49.728405 | sdc: path_checker = tur (setting: multipath internal) 433s 49.728431 | sdc: checker timeout = 30 s (setting: kernel sysfs) 433s 49.728652 | sdc: tur state = up 433s 49.728829 | sdd: size = 204800 433s 49.728989 | sdd: vendor = IET 433s 49.729014 | sdd: product = VIRTUAL-DISK 433s 49.729039 | sdd: rev = 0001 433s 49.729807 | sdd: h:b:t:l = 3:0:0:1 433s 49.730245 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 433s 49.730268 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 433s 49.730271 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 433s 49.730439 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 433s 49.730464 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 433s 49.730481 | sdd: serial = beaf11 433s 49.730485 | sdd: detect_checker = yes (setting: multipath internal) 433s 49.730770 | sdd: path_checker = tur (setting: multipath internal) 433s 49.730796 | sdd: checker timeout = 30 s (setting: kernel sysfs) 433s 49.730981 | sdd: tur state = up 433s 49.731156 | sde: size = 204800 433s 49.731338 | sde: vendor = IET 433s 49.731384 | sde: product = VIRTUAL-DISK 433s 49.731410 | sde: rev = 0001 433s 49.732190 | sde: h:b:t:l = 4:0:0:1 433s 49.732657 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 433s 49.732682 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 433s 49.732685 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 433s 49.732862 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 433s 49.732865 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 433s 49.732881 | sde: serial = beaf11 433s 49.732883 | sde: detect_checker = yes (setting: multipath internal) 433s 49.733128 | sde: path_checker = tur (setting: multipath internal) 433s 49.733154 | sde: checker timeout = 30 s (setting: kernel sysfs) 433s 49.733366 | sde: tur state = up 433s 49.733496 | loop0: device node name blacklisted 433s 49.733596 | loop1: device node name blacklisted 433s 49.733715 | loop2: device node name blacklisted 433s 49.733834 | loop3: device node name blacklisted 433s 49.733950 | loop4: device node name blacklisted 433s 49.734070 | loop5: device node name blacklisted 433s 49.734192 | loop6: device node name blacklisted 433s 49.734307 | loop7: device node name blacklisted 433s 49.734431 | dm-0: device node name blacklisted 433s 49.735554 | multipath-tools v0.9.4 (12/19, 2022) 433s 49.735587 | libdevmapper version 1.02.185 433s 49.735733 | kernel device mapper v4.48.0 433s 49.735764 | DM multipath kernel driver v1.14.0 433s 49.735883 | sdb: size = 204800 433s 49.735907 | sdb: vendor = IET 433s 49.735910 | sdb: product = VIRTUAL-DISK 433s 49.735913 | sdb: rev = 0001 433s 49.736663 | sdb: h:b:t:l = 1:0:0:1 433s 49.736821 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 433s 49.736864 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 433s 49.736867 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 433s 49.736881 | sdb: serial = beaf11 433s 49.737155 | sdb: tur state = up 433s 49.737178 | sdb: uid = 360000000000000000e00000000010001 (udev) 433s 49.737181 | sdb: detect_prio = yes (setting: multipath internal) 433s 49.737184 | sdb: prio = const (setting: multipath internal) 433s 49.737186 | sdb: prio args = "" (setting: multipath internal) 433s 49.737189 | sdb: const prio = 1 433s 49.737216 | sdc: size = 204800 433s 49.737221 | sdc: vendor = IET 433s 49.737223 | sdc: product = VIRTUAL-DISK 433s 49.737228 | sdc: rev = 0001 433s 49.737915 | sdc: h:b:t:l = 2:0:0:1 433s 49.738066 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 433s 49.738110 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 433s 49.738113 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 433s 49.738126 | sdc: serial = beaf11 433s 49.738332 | sdc: tur state = up 433s 49.738976 | sdc: uid = 360000000000000000e00000000010001 (udev) 433s 49.738979 | sdc: detect_prio = yes (setting: multipath internal) 433s 49.738982 | sdc: prio = const (setting: multipath internal) 433s 49.738985 | sdc: prio args = "" (setting: multipath internal) 433s 49.738987 | sdc: const prio = 1 433s 49.739014 | sdd: size = 204800 433s 49.739018 | sdd: vendor = IET 433s 49.739021 | sdd: product = VIRTUAL-DISK 433s 49.739024 | sdd: rev = 0001 433s 49.739698 | sdd: h:b:t:l = 3:0:0:1 433s 49.739848 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 433s 49.739890 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 433s 49.739893 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 433s 49.739906 | sdd: serial = beaf11 433s 49.740033 | sdd: tur state = up 433s 49.740056 | sdd: uid = 360000000000000000e00000000010001 (udev) 433s 49.740059 | sdd: detect_prio = yes (setting: multipath internal) 433s 49.740062 | sdd: prio = const (setting: multipath internal) 433s 49.740066 | sdd: prio args = "" (setting: multipath internal) 433s 49.740069 | sdd: const prio = 1 433s 49.740094 | sde: size = 204800 433s 49.740098 | sde: vendor = IET 433s 49.740101 | sde: product = VIRTUAL-DISK 433s 49.740104 | sde: rev = 0001 433s ===== paths list ===== 433s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 433s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 433s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 433s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 433s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 433s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 433s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 433s size=100M features='0' hwhandler='0' wp=rw 433s |-+- policy='service-time 0' prio=1 status=active 433s | `- 1:0:0:1 sdb 8:16 active ready running 433s |-+- policy='service-time 0' prio=1 status=enabled 433s | `- 2:0:0:1 sdc 8:32 active ready running 433s |-+- policy='service-time 0' prio=1 status=enabled 433s | `- 3:0:0:1 sdd 8:48 active ready running 433s `-+- policy='service-time 0' prio=1 status=enabled 433s `- 4:0:0:1 sde 8:64 active ready running 433s 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 433s Test WWN should now point to DM 433s ../../dm-0 433s Creating filesystem with 25600 4k blocks and 25600 inodes 433s 433s Allocating group tables: 0/1 done 433s Writing inode tables: 0/1 done 433s Creating journal (1024 blocks): 49.740794 | sde: h:b:t:l = 4:0:0:1 433s 49.740944 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 433s 49.740985 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 433s 49.740988 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 433s 49.741002 | sde: serial = beaf11 433s 49.741176 | sde: tur state = up 433s 49.741197 | sde: uid = 360000000000000000e00000000010001 (udev) 433s 49.741200 | sde: detect_prio = yes (setting: multipath internal) 433s 49.741203 | sde: prio = const (setting: multipath internal) 433s 49.741205 | sde: prio args = "" (setting: multipath internal) 433s 49.741208 | sde: const prio = 1 433s 49.743656 | unloading tur checker 433s 49.743729 | unloading const prioritizer 433s + dmsetup table 433s + echo Test WWN should now point to DM 433s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 433s + grep dm 433s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 433s mke2fs 1.47.0 (5-Feb-2023) 433s done 433s Writing superblocks and filesystem accounting information: 0/1 done 433s 433s + udevadm settle 433s + sleep 3s 436s + mkdir -p /mnt/tgtmpathtest 436s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 436s + cat 436s + cat 436s + fio --max-jobs=4 /tmp/autopkgtest.gsdqlQ/tgtbasedmpaths-artifacts/path-change-prep.fio 436s 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 436s fio-3.37 436s Starting 1 thread 436s write-phase: Laying out IO file (1 file / 17592186044415MiB) 437s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 437s 437s write-phase: (groupid=0, jobs=1): err= 0: pid=5681: Fri May 31 23:18:08 2024 437s write: IOPS=2202, BW=138MiB/s (144MB/s)(87.6MiB/637msec); 0 zone resets 437s clat (usec): min=305, max=5281, avg=436.79, stdev=160.76 437s lat (usec): min=320, max=5296, avg=452.53, stdev=161.16 437s clat percentiles (usec): 437s | 1.00th=[ 343], 5.00th=[ 347], 10.00th=[ 347], 20.00th=[ 351], 437s | 30.00th=[ 367], 40.00th=[ 437], 50.00th=[ 449], 60.00th=[ 457], 437s | 70.00th=[ 461], 80.00th=[ 469], 90.00th=[ 502], 95.00th=[ 529], 437s | 99.00th=[ 619], 99.50th=[ 996], 99.90th=[ 1893], 99.95th=[ 5276], 437s | 99.99th=[ 5276] 437s bw ( KiB/s): min=141824, max=141824, per=100.00%, avg=141824.00, stdev= 0.00, samples=1 437s iops : min= 2216, max= 2216, avg=2216.00, stdev= 0.00, samples=1 437s lat (usec) : 500=89.88%, 750=9.34%, 1000=0.21% 437s lat (msec) : 2=0.43%, 10=0.07% 437s cpu : usr=4.25%, sys=10.69%, ctx=1404, majf=0, minf=0 437s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 437s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 437s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 437s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 437s latency : target=0, window=0, percentile=100.00%, depth=1 437s 437s Run status group 0 (all jobs): 437s WRITE: bw=138MiB/s (144MB/s), 138MiB/s-138MiB/s (144MB/s-144MB/s), io=87.6MiB (91.9MB), run=637-637msec 437s 437s Disk stats (read/write): 437s dm-0: ios=1/855, sectors=8/109440, merge=0/0, ticks=1/398, in_queue=399, util=80.00%, aggrios=0/350, aggsectors=2/44884, aggrmerge=0/0, aggrticks=0/142, aggrin_queue=142, aggrutil=84.66% 437s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 437s sdb: ios=1/1403, sectors=8/179536, merge=0/0, ticks=0/570, in_queue=571, util=84.66% 437s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 437s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 437s Starting the path changes in background 437s + echo Starting the path changes in background 437s + date +Pre FIO %H:%M:%S.%N 437s Pre FIO 23:18:08.608447545 437s + fio --max-jobs=4 /tmp/autopkgtest.gsdqlQ/tgtbasedmpaths-artifacts/path-change-check.fio 437s 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 437s fio-3.37 437s Starting 1 thread 617s 617s verify-phase: (groupid=0, jobs=1): err= 0: pid=5688: Fri May 31 23:21:08 2024 617s read: IOPS=2852, BW=178MiB/s (187MB/s)(31.3GiB/180001msec) 617s clat (usec): min=96, max=53466, avg=325.18, stdev=233.48 617s lat (usec): min=96, max=53466, avg=325.32, stdev=233.48 617s clat percentiles (usec): 617s | 1.00th=[ 151], 5.00th=[ 172], 10.00th=[ 204], 20.00th=[ 227], 617s | 30.00th=[ 262], 40.00th=[ 302], 50.00th=[ 318], 60.00th=[ 334], 617s | 70.00th=[ 359], 80.00th=[ 392], 90.00th=[ 420], 95.00th=[ 453], 617s | 99.00th=[ 758], 99.50th=[ 1188], 99.90th=[ 2737], 99.95th=[ 3654], 617s | 99.99th=[ 6325] 617s bw ( KiB/s): min=129792, max=330752, per=100.00%, avg=182775.54, stdev=35221.67, samples=359 617s iops : min= 2028, max= 5168, avg=2855.81, stdev=550.34, samples=359 617s lat (usec) : 100=0.01%, 250=28.02%, 500=69.26%, 750=1.70%, 1000=0.35% 617s lat (msec) : 2=0.48%, 4=0.14%, 10=0.04%, 20=0.01%, 50=0.01% 617s lat (msec) : 100=0.01% 617s cpu : usr=8.34%, sys=7.27%, ctx=513451, majf=0, minf=1 617s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 617s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 617s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 617s issued rwts: total=513365,0,0,0 short=0,0,0,0 dropped=0,0,0,0 617s latency : target=0, window=0, percentile=100.00%, depth=1 617s 617s Run status group 0 (all jobs): 617s READ: bw=178MiB/s (187MB/s), 178MiB/s-178MiB/s (187MB/s-187MB/s), io=31.3GiB (33.6GB), run=180001-180001msec 617s 617s Disk stats (read/write): 617s dm-0: ios=513170/9, sectors=65683384/12912, merge=16/8, ticks=173150/28, in_queue=173179, util=99.97%, aggrios=38124/2, aggsectors=4879278/3228, aggrmerge=0/0, aggrticks=10715/6, aggrin_queue=10721, aggrutil=99.14% 617s sdd: ios=28882/0, sectors=3696896/0, merge=0/0, ticks=8612/0, in_queue=8611, util=32.95% 617s sdb: ios=31669/8, sectors=4053376/12912, merge=0/0, ticks=8278/27, in_queue=8305, util=99.14% 617s sde: ios=63695/0, sectors=8152960/0, merge=0/0, ticks=17165/0, in_queue=17165, util=39.71% 617s sdc: ios=28252/0, sectors=3613880/0, merge=0/0, ticks=8805/0, in_queue=8805, util=50.05% 617s + date +Post FIO %H:%M:%S.%N 617s Post FIO 23:21:08.947574976 617s FIO verify test with changing paths - OK 617s + echo FIO verify test with changing paths - OK 618s + echoReport log of background activity 618s Report log of background activity 618s + cat /tmp/autopkgtest.gsdqlQ/tgtbasedmpaths-artifacts/test-background.log 618s + iscsiadm --mode session 618s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s + sleep 10s 618s + date +MP report (expect 4) %H:%M:%S.%N 618s MP report (expect 4) 23:18:18.612618760 618s + multipath -ll 618s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 618s size=100M features='0' hwhandler='0' wp=rw 618s |-+- policy='service-time 0' prio=1 status=active 618s | `- 1:0:0:1 sdb 8:16 active ready running 618s |-+- policy='service-time 0' prio=1 status=enabled 618s | `- 2:0:0:1 sdc 8:32 active ready running 618s |-+- policy='service-time 0' prio=1 status=enabled 618s | `- 3:0:0:1 sdd 8:48 active ready running 618s `-+- policy='service-time 0' prio=1 status=enabled 618s `- 4:0:0:1 sde 8:64 active ready running 618s + date +UN-plug path 1 %H:%M:%S.%N 618s UN-plug path 1 23:18:18.641561993 618s + iscsiadm --mode session -r 1 -u 618s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 618s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 618s + iscsiadm --mode session 618s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s + sleep 10s 618s + date +MP report (expect 3) %H:%M:%S.%N 618s MP report (expect 3) 23:18:28.755732110 618s + multipath -ll 618s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 618s size=100M features='0' hwhandler='0' wp=rw 618s |-+- policy='service-time 0' prio=1 status=active 618s | `- 2:0:0:1 sdc 8:32 active ready running 618s |-+- policy='service-time 0' prio=1 status=enabled 618s | `- 3:0:0:1 sdd 8:48 active ready running 618s `-+- policy='service-time 0' prio=1 status=enabled 618s `- 4:0:0:1 sde 8:64 active ready running 618s + date +UN-plug path 2 %H:%M:%S.%N 618s UN-plug path 2 23:18:28.781770643 618s + iscsiadm --mode session -r 2 -u 618s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 618s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 618s + iscsiadm --mode session 618s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s + sleep 10s 618s + date +MP report (expect 2) %H:%M:%S.%N 618s MP report (expect 2) 23:18:38.863395534 618s + multipath -ll 618s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 618s size=100M features='0' hwhandler='0' wp=rw 618s |-+- policy='service-time 0' prio=1 status=active 618s | `- 3:0:0:1 sdd 8:48 active ready running 618s `-+- policy='service-time 0' prio=1 status=enabled 618s `- 4:0:0:1 sde 8:64 active ready running 618s + date +UN-plug path 3 %H:%M:%S.%N 618s UN-plug path 3 23:18:38.883875935 618s + iscsiadm --mode session -r 3 -u 618s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 618s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 618s + iscsiadm --mode session 618s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s + sleep 10s 618s + date +MP report (expect 1) %H:%M:%S.%N 618s MP report (expect 1) 23:18:48.969730432 618s + multipath -ll 618s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 618s size=100M features='0' hwhandler='0' wp=rw 618s `-+- policy='service-time 0' prio=1 status=active 618s `- 4:0:0:1 sde 8:64 active ready running 618s + date +Add paths 5/6/7/8 %H:%M:%S.%N 618s Add paths 5/6/7/8 23:18:48.985665687 618s + iscsiadm --mode session -r 4 --op new 618s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 618s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 618s + iscsiadm --mode session -r 4 --op new 618s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 618s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 618s + iscsiadm --mode session -r 4 --op new 618s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 618s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 618s + iscsiadm --mode session -r 4 --op new 618s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 618s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 618s + iscsiadm --mode session 618s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s + sleep 10s 618s + date +MP report (expect 5) %H:%M:%S.%N 618s MP report (expect 5) 23:18:59.111692995 618s + multipath -ll 618s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 618s size=100M features='0' hwhandler='0' wp=rw 618s |-+- policy='service-time 0' prio=1 status=active 618s | `- 4:0:0:1 sde 8:64 active ready running 618s |-+- policy='service-time 0' prio=1 status=enabled 618s | `- 1:0:0:1 sdb 8:16 active ready running 618s |-+- policy='service-time 0' prio=1 status=enabled 618s | `- 2:0:0:1 sdc 8:32 active ready running 618s |-+- policy='service-time 0' prio=1 status=enabled 618s | `- 3:0:0:1 sdd 8:48 active ready running 618s `-+- policy='service-time 0' prio=1 status=enabled 618s `- 5:0:0:1 sdf 8:80 active ready running 618s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 618s UN-plug multiple paths 4/7/8 23:18:59.146412860 618s + iscsiadm --mode session -r 4 -u 618s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 618s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 618s + iscsiadm --mode session -r 7 -u 618s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 618s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 618s + iscsiadm --mode session -r 8 -u 618s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 618s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 618s + iscsiadm --mode session 618s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 618s + sleep 10s 618s + date +Restart multipath daemon %H:%M:%S.%N 618s Restart multipath daemon 23:19:09.461099823 618s + systemctl restart multipathd 618s + sleep 10s 618s + date +Final background report (expect 2) %H:%M:%S.%N 618s Final background report (expect 2) 23:19:19.565289232 618s + multipath -ll 618s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 618s size=100M features='0' hwhandler='0' wp=rw 618s |-+- policy='service-time 0' prio=1 status=active 618s | `- 1:0:0:1 sdb 8:16 active ready running 618s `-+- policy='service-time 0' prio=1 status=enabled 618s `- 2:0:0:1 sdc 8:32 active ready running 618s Final stats 618s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 618s iSCSI SNMP: 618s txdata_octets: 17212632 618s rxdata_octets: 23494555972 618s noptx_pdus: 0 618s scsicmd_pdus: 358329 618s tmfcmd_pdus: 0 618s login_pdus: 0 618s text_pdus: 0 618s dataout_pdus: 0 618s logout_pdus: 0 618s snack_pdus: 0 618s noprx_pdus: 0 618s scsirsp_pdus: 358329 618s tmfrsp_pdus: 0 618s textrsp_pdus: 0 618s datain_pdus: 358296 618s logoutrsp_pdus: 0 618s r2t_pdus: 0 618s async_pdus: 0 618s rjt_pdus: 0 618s digest_err: 0 618s timeout_err: 0 618s iSCSI Extended: 618s tx_sendpage_failures: 0 618s rx_discontiguous_hdr: 0 618s eh_abort_cnt: 0 618s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 618s iSCSI SNMP: 618s txdata_octets: 7320 618s rxdata_octets: 2826500 618s noptx_pdus: 0 618s scsicmd_pdus: 123 618s tmfcmd_pdus: 0 618s login_pdus: 0 618s text_pdus: 0 618s dataout_pdus: 0 618s logout_pdus: 0 618s snack_pdus: 0 618s noprx_pdus: 0 618s scsirsp_pdus: 123 618s tmfrsp_pdus: 0 618s textrsp_pdus: 0 618s datain_pdus: 101 618s logoutrsp_pdus: 0 618s r2t_pdus: 0 618s async_pdus: 0 618s rjt_pdus: 0 618s digest_err: 0 618s timeout_err: 0 618s iSCSI Extended: 618s tx_sendpage_failures: 0 618s rx_discontiguous_hdr: 0 618s eh_abort_cnt: 0 618s + sync 618s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 618s + echo Final stats 618s + iscsiadm --mode session --stats 618s + journalctl --no-pager -u multipathd 618s May 31 11:52:57 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 618s May 31 11:52:57 ubuntu multipathd[330]: multipathd v0.9.4: start up 618s May 31 11:52:57 ubuntu multipathd[330]: reconfigure: setting up paths and maps 618s May 31 11:52:57 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 618s May 31 11:55:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 multipathd[330]: multipathd: shut down 618s May 31 11:55:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 618s May 31 11:55:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 systemd[1]: multipathd.service: Deactivated successfully. 618s May 31 11:55:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 618s -- Boot abb58c27487347cfb49df50b43e2e206 -- 618s May 31 11:55:32 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 multipathd[260]: multipathd v0.9.4: start up 618s May 31 11:55:32 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 multipathd[260]: reconfigure: setting up paths and maps 618s May 31 11:55:32 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 618s May 31 11:55:51 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 multipathd[260]: multipathd: shut down 618s May 31 11:55:51 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 618s May 31 11:55:51 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 systemd[1]: multipathd.service: Deactivated successfully. 618s May 31 11:55:51 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 618s -- Boot 278942dda00d44c99550d6fc46e90592 -- 618s May 31 23:15:56 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 618s May 31 23:15:56 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 multipathd[334]: multipathd v0.9.4: start up 618s May 31 23:15:56 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 multipathd[334]: reconfigure: setting up paths and maps 618s May 31 23:15:56 auto-syncubuntu-oracular-daily-ppc64el-server-20240530-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 618s May 31 23:16:52 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 618s May 31 23:16:52 autopkgtest multipathd[334]: multipathd: shut down 618s May 31 23:16:52 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 618s May 31 23:16:52 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 618s -- Boot aa1b9eec21564458bd990d36d3cbcdc9 -- 618s May 31 23:17:18 autopkgtest multipathd[323]: multipathd v0.9.4: start up 618s May 31 23:17:18 autopkgtest multipathd[323]: reconfigure: setting up paths and maps 618s May 31 23:17:18 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 618s May 31 23:17:59 autopkgtest multipathd[323]: 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] 618s May 31 23:17:59 autopkgtest multipathd[323]: sdc [8:32]: path added to devmap mpatha 618s May 31 23:17:59 autopkgtest multipathd[323]: mpatha: performing delayed actions 618s May 31 23:17:59 autopkgtest multipathd[323]: 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] 618s May 31 23:18:18 autopkgtest multipathd[323]: 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] 618s May 31 23:18:18 autopkgtest multipathd[323]: check_removed_paths: sdb: freeing path in removed state 618s May 31 23:18:18 autopkgtest multipathd[323]: 8:16: path removed from map mpatha 618s May 31 23:18:28 autopkgtest multipathd[323]: 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] 618s May 31 23:18:28 autopkgtest multipathd[323]: check_removed_paths: sdc: freeing path in removed state 618s May 31 23:18:28 autopkgtest multipathd[323]: 8:32: path removed from map mpatha 618s May 31 23:18:38 autopkgtest multipathd[323]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 618s May 31 23:18:38 autopkgtest multipathd[323]: check_removed_paths: sdd: freeing path in removed state 618s May 31 23:18:38 autopkgtest multipathd[323]: 8:48: path removed from map mpatha 618s May 31 23:18:49 autopkgtest multipathd[323]: 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] 618s May 31 23:18:49 autopkgtest multipathd[323]: sdb [8:16]: path added to devmap mpatha 618s May 31 23:18:49 autopkgtest multipathd[323]: 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] 618s May 31 23:18:49 autopkgtest multipathd[323]: sdc [8:32]: path added to devmap mpatha 618s May 31 23:18:49 autopkgtest multipathd[323]: 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] 618s May 31 23:18:49 autopkgtest multipathd[323]: sdd [8:48]: path added to devmap mpatha 618s May 31 23:18:49 autopkgtest multipathd[323]: 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] 618s May 31 23:18:49 autopkgtest multipathd[323]: sdf [8:80]: path added to devmap mpatha 618s May 31 23:18:59 autopkgtest multipathd[323]: 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] 618s May 31 23:18:59 autopkgtest multipathd[323]: check_removed_paths: sde: freeing path in removed state 618s May 31 23:18:59 autopkgtest multipathd[323]: 8:64: path removed from map mpatha 618s May 31 23:18:59 autopkgtest multipathd[323]: 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] 618s May 31 23:18:59 autopkgtest multipathd[323]: check_removed_paths: sdd: freeing path in removed state 618s May 31 23:18:59 autopkgtest multipathd[323]: 8:48: path removed from map mpatha 618s May 31 23:18:59 autopkgtest multipathd[323]: 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] 618s May 31 23:18:59 autopkgtest multipathd[323]: check_removed_paths: sdf: freeing path in removed state 618s May 31 23:18:59 autopkgtest multipathd[323]: 8:80: path removed from map mpatha 618s May 31 23:19:09 autopkgtest multipathd[323]: multipathd: shut down 618s May 31 23:19:09 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 618s May 31 23:19:09 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 618s May 31 23:19:09 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 618s May 31 23:19:09 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 618s May 31 23:19:09 autopkgtest multipathd[6047]: multipathd v0.9.4: start up 618s May 31 23:19:09 autopkgtest multipathd[6047]: reconfigure: setting up paths and maps 618s May 31 23:19:09 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 618s Check final path status 618s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 618s size=100M features='0' hwhandler='0' wp=rw 618s |-+- policy='service-time 0' prio=1 status=active 618s | `- 1:0:0:1 sdb 8:16 active ready running 618s `-+- policy='service-time 0' prio=1 status=enabled 618s `- 2:0:0:1 sdc 8:32 active ready running 618s + echo Check final path status 618s + multipath -ll 618s + multipath -ll 618s + grep --count status= 618s + diskc=2 618s + multipath -ll 618s + grep --count status=active 618s + diska=1 618s + multipath -ll 618s + grep --count status=enabled 618s OK 618s + diske=1 618s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 618s + echo OK 618s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 618s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 618s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 618s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 618s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 618s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 618s autopkgtest [23:21:09]: test tgtbasedmpaths: -----------------------] 619s autopkgtest [23:21:10]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 619s tgtbasedmpaths PASS 619s autopkgtest [23:21:10]: @@@@@@@@@@@@@@@@@@@@ summary 619s kpartx-file-loopback PASS 619s tgtbasedmpaths PASS 630s Using flock in scalingstack-bos02-ppc64el 630s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240531-231050-juju-7f2275-prod-proposed-migration-environment-2-dff8c86b-d1a7-44d4-8820-f28751a56d85 from image adt/ubuntu-oracular-ppc64el-server-20240531.img (UUID 343f90d2-9cee-44e1-9dda-2e7632e4acbe)... 630s Using flock in scalingstack-bos02-ppc64el 630s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240531-231050-juju-7f2275-prod-proposed-migration-environment-2-dff8c86b-d1a7-44d4-8820-f28751a56d85 from image adt/ubuntu-oracular-ppc64el-server-20240531.img (UUID 343f90d2-9cee-44e1-9dda-2e7632e4acbe)...