1s autopkgtest [18:51:30]: starting date and time: 2024-06-13 18:51:30+0000 1s autopkgtest [18:51:30]: git checkout: 433ed4cb Merge branch 'skia/nova_flock' into 'ubuntu/5.34+prod' 1s autopkgtest [18:51:30]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.z3q5q404/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:systemd --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=systemd/256-1ubuntu1 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos01-ppc64el-8.secgroup --name adt-oracular-ppc64el-multipath-tools-20240613-185129-juju-7f2275-prod-proposed-migration-environment-3-6b3cdc04-44ab-4606-a65c-f1ae3d256867 --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://us.ports.ubuntu.com/ubuntu-ports/ 224s autopkgtest [18:55:13]: testbed dpkg architecture: ppc64el 224s autopkgtest [18:55:13]: testbed apt version: 2.9.3 224s autopkgtest [18:55:13]: @@@@@@@@@@@@@@@@@@@@ test bed setup 237s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 238s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [363 kB] 238s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 238s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.7 kB] 238s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7052 B] 238s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [58.3 kB] 238s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1860 B] 238s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [324 kB] 238s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [2532 B] 238s Fetched 908 kB in 1s (1158 kB/s) 238s Reading package lists... 257s Reading package lists... 257s Building dependency tree... 257s Reading state information... 258s Calculating upgrade... 258s The following package was automatically installed and is no longer required: 258s systemd-dev 258s Use 'sudo apt autoremove' to remove it. 258s The following packages will be upgraded: 258s cryptsetup-bin dhcpcd-base dracut-install gir1.2-glib-2.0 libaudit-common 258s libaudit1 libcryptsetup12 libglib2.0-0t64 libglib2.0-data libnss-systemd 258s libpam-systemd libsystemd-shared libsystemd0 libtraceevent1 258s libtraceevent1-plugin libudev1 systemd systemd-dev systemd-resolved 258s systemd-sysv systemd-timesyncd udev xfsprogs 258s 23 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 258s Need to get 14.4 MB of archives. 258s After this operation, 1845 kB of additional disk space will be used. 258s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-dev all 256-1ubuntu1 [111 kB] 258s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-timesyncd ppc64el 256-1ubuntu1 [37.9 kB] 258s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-resolved ppc64el 256-1ubuntu1 [363 kB] 258s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd-shared ppc64el 256-1ubuntu1 [2471 kB] 259s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd0 ppc64el 256-1ubuntu1 [547 kB] 259s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-sysv ppc64el 256-1ubuntu1 [11.8 kB] 259s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnss-systemd ppc64el 256-1ubuntu1 [210 kB] 259s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpam-systemd ppc64el 256-1ubuntu1 [318 kB] 259s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd ppc64el 256-1ubuntu1 [3962 kB] 259s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el udev ppc64el 256-1ubuntu1 [2110 kB] 259s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libudev1 ppc64el 256-1ubuntu1 [218 kB] 259s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el libaudit-common all 1:3.1.2-4 [5780 B] 259s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libaudit1 ppc64el 1:3.1.2-4 [52.3 kB] 259s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libcryptsetup12 ppc64el 2:2.7.0-1ubuntu6 [375 kB] 259s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el dhcpcd-base ppc64el 1:10.0.8-2 [277 kB] 259s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el gir1.2-glib-2.0 ppc64el 2.80.3-1ubuntu1 [182 kB] 259s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libglib2.0-0t64 ppc64el 2.80.3-1ubuntu1 [1765 kB] 260s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el libglib2.0-data all 2.80.3-1ubuntu1 [49.3 kB] 260s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libtraceevent1-plugin ppc64el 1:1.8.2-1ubuntu3 [23.0 kB] 260s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el libtraceevent1 ppc64el 1:1.8.2-1ubuntu3 [77.9 kB] 260s Get:21 http://ftpmaster.internal/ubuntu oracular/main ppc64el cryptsetup-bin ppc64el 2:2.7.0-1ubuntu6 [227 kB] 260s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el dracut-install ppc64el 102-3ubuntu1 [35.7 kB] 260s Get:23 http://ftpmaster.internal/ubuntu oracular/main ppc64el xfsprogs ppc64el 6.8.0-2 [981 kB] 260s Fetched 14.4 MB in 2s (8048 kB/s) 260s (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 ... 72675 files and directories currently installed.) 260s Preparing to unpack .../systemd-dev_256-1ubuntu1_all.deb ... 260s Unpacking systemd-dev (256-1ubuntu1) over (255.4-1ubuntu8) ... 260s Preparing to unpack .../systemd-timesyncd_256-1ubuntu1_ppc64el.deb ... 260s Unpacking systemd-timesyncd (256-1ubuntu1) over (255.4-1ubuntu8) ... 260s Preparing to unpack .../systemd-resolved_256-1ubuntu1_ppc64el.deb ... 260s Unpacking systemd-resolved (256-1ubuntu1) over (255.4-1ubuntu8) ... 260s Preparing to unpack .../libsystemd-shared_256-1ubuntu1_ppc64el.deb ... 260s Unpacking libsystemd-shared:ppc64el (256-1ubuntu1) over (255.4-1ubuntu8) ... 260s Preparing to unpack .../libsystemd0_256-1ubuntu1_ppc64el.deb ... 260s Unpacking libsystemd0:ppc64el (256-1ubuntu1) over (255.4-1ubuntu8) ... 260s Setting up libsystemd0:ppc64el (256-1ubuntu1) ... 260s (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 ... 72677 files and directories currently installed.) 260s Preparing to unpack .../0-systemd-sysv_256-1ubuntu1_ppc64el.deb ... 260s Unpacking systemd-sysv (256-1ubuntu1) over (255.4-1ubuntu8) ... 260s Preparing to unpack .../1-libnss-systemd_256-1ubuntu1_ppc64el.deb ... 260s Unpacking libnss-systemd:ppc64el (256-1ubuntu1) over (255.4-1ubuntu8) ... 260s Preparing to unpack .../2-libpam-systemd_256-1ubuntu1_ppc64el.deb ... 260s Unpacking libpam-systemd:ppc64el (256-1ubuntu1) over (255.4-1ubuntu8) ... 260s Preparing to unpack .../3-systemd_256-1ubuntu1_ppc64el.deb ... 260s Unpacking systemd (256-1ubuntu1) over (255.4-1ubuntu8) ... 261s Preparing to unpack .../4-udev_256-1ubuntu1_ppc64el.deb ... 261s Unpacking udev (256-1ubuntu1) over (255.4-1ubuntu8) ... 261s Preparing to unpack .../5-libudev1_256-1ubuntu1_ppc64el.deb ... 261s Unpacking libudev1:ppc64el (256-1ubuntu1) over (255.4-1ubuntu8) ... 261s Setting up libudev1:ppc64el (256-1ubuntu1) ... 261s (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 ... 72737 files and directories currently installed.) 261s Preparing to unpack .../libaudit-common_1%3a3.1.2-4_all.deb ... 261s Unpacking libaudit-common (1:3.1.2-4) over (1:3.1.2-2.1build1) ... 261s Setting up libaudit-common (1:3.1.2-4) ... 261s (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 ... 72737 files and directories currently installed.) 261s Preparing to unpack .../libaudit1_1%3a3.1.2-4_ppc64el.deb ... 261s Unpacking libaudit1:ppc64el (1:3.1.2-4) over (1:3.1.2-2.1build1) ... 261s Setting up libaudit1:ppc64el (1:3.1.2-4) ... 261s (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 ... 72737 files and directories currently installed.) 261s Preparing to unpack .../0-libcryptsetup12_2%3a2.7.0-1ubuntu6_ppc64el.deb ... 261s Unpacking libcryptsetup12:ppc64el (2:2.7.0-1ubuntu6) over (2:2.7.0-1ubuntu5) ... 261s Preparing to unpack .../1-dhcpcd-base_1%3a10.0.8-2_ppc64el.deb ... 261s Unpacking dhcpcd-base (1:10.0.8-2) over (1:10.0.8-1) ... 261s Preparing to unpack .../2-gir1.2-glib-2.0_2.80.3-1ubuntu1_ppc64el.deb ... 261s Unpacking gir1.2-glib-2.0:ppc64el (2.80.3-1ubuntu1) over (2.80.2-1ubuntu1) ... 261s Preparing to unpack .../3-libglib2.0-0t64_2.80.3-1ubuntu1_ppc64el.deb ... 261s Unpacking libglib2.0-0t64:ppc64el (2.80.3-1ubuntu1) over (2.80.2-1ubuntu1) ... 261s Preparing to unpack .../4-libglib2.0-data_2.80.3-1ubuntu1_all.deb ... 261s Unpacking libglib2.0-data (2.80.3-1ubuntu1) over (2.80.2-1ubuntu1) ... 261s Preparing to unpack .../5-libtraceevent1-plugin_1%3a1.8.2-1ubuntu3_ppc64el.deb ... 261s Unpacking libtraceevent1-plugin:ppc64el (1:1.8.2-1ubuntu3) over (1:1.8.2-1ubuntu2) ... 261s Preparing to unpack .../6-libtraceevent1_1%3a1.8.2-1ubuntu3_ppc64el.deb ... 261s Unpacking libtraceevent1:ppc64el (1:1.8.2-1ubuntu3) over (1:1.8.2-1ubuntu2) ... 261s Preparing to unpack .../7-cryptsetup-bin_2%3a2.7.0-1ubuntu6_ppc64el.deb ... 261s Unpacking cryptsetup-bin (2:2.7.0-1ubuntu6) over (2:2.7.0-1ubuntu5) ... 261s Preparing to unpack .../8-dracut-install_102-3ubuntu1_ppc64el.deb ... 261s Unpacking dracut-install (102-3ubuntu1) over (060+5-8ubuntu2) ... 261s Preparing to unpack .../9-xfsprogs_6.8.0-2_ppc64el.deb ... 261s Unpacking xfsprogs (6.8.0-2) over (6.6.0-1ubuntu2) ... 261s Setting up systemd-dev (256-1ubuntu1) ... 261s Setting up libglib2.0-0t64:ppc64el (2.80.3-1ubuntu1) ... 261s No schema files found: doing nothing. 261s Setting up libglib2.0-data (2.80.3-1ubuntu1) ... 261s Setting up libsystemd-shared:ppc64el (256-1ubuntu1) ... 261s Setting up xfsprogs (6.8.0-2) ... 261s update-initramfs: deferring update (trigger activated) 262s Setting up dhcpcd-base (1:10.0.8-2) ... 262s Setting up gir1.2-glib-2.0:ppc64el (2.80.3-1ubuntu1) ... 262s Setting up dracut-install (102-3ubuntu1) ... 262s Setting up libtraceevent1:ppc64el (1:1.8.2-1ubuntu3) ... 262s Setting up libcryptsetup12:ppc64el (2:2.7.0-1ubuntu6) ... 262s Setting up cryptsetup-bin (2:2.7.0-1ubuntu6) ... 262s Setting up systemd (256-1ubuntu1) ... 262s Installing new version of config file /etc/systemd/journald.conf ... 262s Installing new version of config file /etc/systemd/logind.conf ... 262s Installing new version of config file /etc/systemd/networkd.conf ... 262s Installing new version of config file /etc/systemd/sleep.conf ... 262s Installing new version of config file /etc/systemd/system.conf ... 262s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 262s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 262s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 263s Setting up systemd-timesyncd (256-1ubuntu1) ... 263s Setting up udev (256-1ubuntu1) ... 264s Setting up libtraceevent1-plugin:ppc64el (1:1.8.2-1ubuntu3) ... 264s Setting up systemd-resolved (256-1ubuntu1) ... 264s Installing new version of config file /etc/systemd/resolved.conf ... 265s Setting up systemd-sysv (256-1ubuntu1) ... 265s Setting up libnss-systemd:ppc64el (256-1ubuntu1) ... 265s Setting up libpam-systemd:ppc64el (256-1ubuntu1) ... 265s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 265s Processing triggers for man-db (2.12.1-2) ... 266s Processing triggers for dbus (1.14.10-4ubuntu4) ... 266s Processing triggers for shared-mime-info (2.4-5) ... 266s Warning: program compiled against libxml 212 using older 209 267s Processing triggers for initramfs-tools (0.142ubuntu28) ... 267s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 267s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 275s Reading package lists... 275s Building dependency tree... 275s Reading state information... 275s The following packages will be REMOVED: 275s systemd-dev* 275s 0 upgraded, 0 newly installed, 1 to remove and 0 not upgraded. 275s After this operation, 760 kB disk space will be freed. 276s (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 ... 72737 files and directories currently installed.) 276s Removing systemd-dev (256-1ubuntu1) ... 276s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 276s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 276s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 276s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 277s Reading package lists... 277s Reading package lists... 278s Building dependency tree... 278s Reading state information... 278s Calculating upgrade... 278s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 278s Reading package lists... 278s Building dependency tree... 278s Reading state information... 278s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 279s autopkgtest [18:56:08]: rebooting testbed after setup commands that affected boot 316s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 363s autopkgtest [18:57:32]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 369s autopkgtest [18:57:38]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 375s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 375s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 375s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 375s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 375s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 375s gpgv: issuer "steve.langasek@ubuntu.com" 375s gpgv: Can't check signature: No public key 375s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 375s autopkgtest [18:57:44]: testing package multipath-tools version 0.9.4-5ubuntu8 376s autopkgtest [18:57:45]: build not needed 376s autopkgtest [18:57:45]: test kpartx-file-loopback: preparing testbed 379s Reading package lists... 379s Building dependency tree... 379s Reading state information... 379s Starting pkgProblemResolver with broken count: 0 379s Starting 2 pkgProblemResolver with broken count: 0 379s Done 379s The following additional packages will be installed: 379s liburing2 qemu-utils 379s Recommended packages: 379s qemu-block-extra 379s The following NEW packages will be installed: 379s autopkgtest-satdep liburing2 qemu-utils 379s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 379s Need to get 2330 kB/2331 kB of archives. 379s After this operation, 15.4 MB of additional disk space will be used. 379s Get:1 /tmp/autopkgtest.h6MXwZ/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 379s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 380s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 380s Fetched 2330 kB in 1s (3149 kB/s) 380s Selecting previously unselected package liburing2:ppc64el. 381s (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 ... 72690 files and directories currently installed.) 381s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 381s Unpacking liburing2:ppc64el (2.6-1) ... 381s Selecting previously unselected package qemu-utils. 381s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 381s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 381s Selecting previously unselected package autopkgtest-satdep. 381s Preparing to unpack .../1-autopkgtest-satdep.deb ... 381s Unpacking autopkgtest-satdep (0) ... 381s Setting up liburing2:ppc64el (2.6-1) ... 381s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 381s Setting up autopkgtest-satdep (0) ... 381s Processing triggers for man-db (2.12.1-2) ... 382s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 386s (Reading database ... 72710 files and directories currently installed.) 386s Removing autopkgtest-satdep (0) ... 387s autopkgtest [18:57:56]: test kpartx-file-loopback: [----------------------- 387s Formatting 'foo.img', fmt=raw size=20971520 388s Creating new GPT entries in memory. 388s Warning: The kernel is still using the old partition table. 388s The new table will be used at the next reboot or after you 388s run partprobe(8) or kpartx(8) 388s The operation has completed successfully. 388s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 388s standard_filename: OK 388s del devmap : loop0p1 388s No devices found 388s standard_filename_cleanup: OK 388s Formatting 'fou du FaFa.img', fmt=raw size=20971520 389s Creating new GPT entries in memory. 389s Warning: The kernel is still using the old partition table. 389s The new table will be used at the next reboot or after you 389s run partprobe(8) or kpartx(8) 389s The operation has completed successfully. 389s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 389s filename_with_spaces: OK 389s del devmap : loop0p1 389s No devices found 389s filename_with_spaces_cleanup: OK 390s autopkgtest [18:57:59]: test kpartx-file-loopback: -----------------------] 390s autopkgtest [18:57:59]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 390s kpartx-file-loopback PASS 391s autopkgtest [18:58:00]: test tgtbasedmpaths: preparing testbed 589s autopkgtest [19:01:18]: testbed dpkg architecture: ppc64el 589s autopkgtest [19:01:18]: testbed apt version: 2.9.3 589s autopkgtest [19:01:18]: @@@@@@@@@@@@@@@@@@@@ test bed setup 590s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 590s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7052 B] 590s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.7 kB] 590s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [363 kB] 590s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2576 B] 590s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [58.3 kB] 590s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1860 B] 590s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [324 kB] 590s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [2532 B] 590s Fetched 908 kB in 1s (1111 kB/s) 590s Reading package lists... 593s Reading package lists... 593s Building dependency tree... 593s Reading state information... 593s Calculating upgrade... 593s The following package was automatically installed and is no longer required: 593s systemd-dev 593s Use 'sudo apt autoremove' to remove it. 593s The following packages will be upgraded: 593s cryptsetup-bin dhcpcd-base dracut-install gir1.2-glib-2.0 libaudit-common 593s libaudit1 libcryptsetup12 libglib2.0-0t64 libglib2.0-data libnss-systemd 593s libpam-systemd libsystemd-shared libsystemd0 libtraceevent1 593s libtraceevent1-plugin libudev1 systemd systemd-dev systemd-resolved 593s systemd-sysv systemd-timesyncd udev xfsprogs 594s 23 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 594s Need to get 14.4 MB of archives. 594s After this operation, 1845 kB of additional disk space will be used. 594s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-dev all 256-1ubuntu1 [111 kB] 594s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-timesyncd ppc64el 256-1ubuntu1 [37.9 kB] 594s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-resolved ppc64el 256-1ubuntu1 [363 kB] 594s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd-shared ppc64el 256-1ubuntu1 [2471 kB] 594s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd0 ppc64el 256-1ubuntu1 [547 kB] 594s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-sysv ppc64el 256-1ubuntu1 [11.8 kB] 594s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnss-systemd ppc64el 256-1ubuntu1 [210 kB] 594s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpam-systemd ppc64el 256-1ubuntu1 [318 kB] 594s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd ppc64el 256-1ubuntu1 [3962 kB] 594s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el udev ppc64el 256-1ubuntu1 [2110 kB] 594s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libudev1 ppc64el 256-1ubuntu1 [218 kB] 594s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el libaudit-common all 1:3.1.2-4 [5780 B] 594s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libaudit1 ppc64el 1:3.1.2-4 [52.3 kB] 594s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libcryptsetup12 ppc64el 2:2.7.0-1ubuntu6 [375 kB] 594s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el dhcpcd-base ppc64el 1:10.0.8-2 [277 kB] 594s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el gir1.2-glib-2.0 ppc64el 2.80.3-1ubuntu1 [182 kB] 594s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libglib2.0-0t64 ppc64el 2.80.3-1ubuntu1 [1765 kB] 595s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el libglib2.0-data all 2.80.3-1ubuntu1 [49.3 kB] 595s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libtraceevent1-plugin ppc64el 1:1.8.2-1ubuntu3 [23.0 kB] 595s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el libtraceevent1 ppc64el 1:1.8.2-1ubuntu3 [77.9 kB] 595s Get:21 http://ftpmaster.internal/ubuntu oracular/main ppc64el cryptsetup-bin ppc64el 2:2.7.0-1ubuntu6 [227 kB] 595s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el dracut-install ppc64el 102-3ubuntu1 [35.7 kB] 595s Get:23 http://ftpmaster.internal/ubuntu oracular/main ppc64el xfsprogs ppc64el 6.8.0-2 [981 kB] 595s Fetched 14.4 MB in 1s (12.7 MB/s) 595s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72675 files and directories currently installed.) 595s Preparing to unpack .../systemd-dev_256-1ubuntu1_all.deb ... 595s Unpacking systemd-dev (256-1ubuntu1) over (255.4-1ubuntu8) ... 595s Preparing to unpack .../systemd-timesyncd_256-1ubuntu1_ppc64el.deb ... 595s Unpacking systemd-timesyncd (256-1ubuntu1) over (255.4-1ubuntu8) ... 595s Preparing to unpack .../systemd-resolved_256-1ubuntu1_ppc64el.deb ... 595s Unpacking systemd-resolved (256-1ubuntu1) over (255.4-1ubuntu8) ... 595s Preparing to unpack .../libsystemd-shared_256-1ubuntu1_ppc64el.deb ... 595s Unpacking libsystemd-shared:ppc64el (256-1ubuntu1) over (255.4-1ubuntu8) ... 595s Preparing to unpack .../libsystemd0_256-1ubuntu1_ppc64el.deb ... 595s Unpacking libsystemd0:ppc64el (256-1ubuntu1) over (255.4-1ubuntu8) ... 595s Setting up libsystemd0:ppc64el (256-1ubuntu1) ... 595s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72677 files and directories currently installed.) 595s Preparing to unpack .../0-systemd-sysv_256-1ubuntu1_ppc64el.deb ... 595s Unpacking systemd-sysv (256-1ubuntu1) over (255.4-1ubuntu8) ... 595s Preparing to unpack .../1-libnss-systemd_256-1ubuntu1_ppc64el.deb ... 595s Unpacking libnss-systemd:ppc64el (256-1ubuntu1) over (255.4-1ubuntu8) ... 595s Preparing to unpack .../2-libpam-systemd_256-1ubuntu1_ppc64el.deb ... 595s Unpacking libpam-systemd:ppc64el (256-1ubuntu1) over (255.4-1ubuntu8) ... 595s Preparing to unpack .../3-systemd_256-1ubuntu1_ppc64el.deb ... 595s Unpacking systemd (256-1ubuntu1) over (255.4-1ubuntu8) ... 596s Preparing to unpack .../4-udev_256-1ubuntu1_ppc64el.deb ... 596s Unpacking udev (256-1ubuntu1) over (255.4-1ubuntu8) ... 596s Preparing to unpack .../5-libudev1_256-1ubuntu1_ppc64el.deb ... 596s Unpacking libudev1:ppc64el (256-1ubuntu1) over (255.4-1ubuntu8) ... 596s Setting up libudev1:ppc64el (256-1ubuntu1) ... 596s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72737 files and directories currently installed.) 596s Preparing to unpack .../libaudit-common_1%3a3.1.2-4_all.deb ... 596s Unpacking libaudit-common (1:3.1.2-4) over (1:3.1.2-2.1build1) ... 596s Setting up libaudit-common (1:3.1.2-4) ... 596s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72737 files and directories currently installed.) 596s Preparing to unpack .../libaudit1_1%3a3.1.2-4_ppc64el.deb ... 596s Unpacking libaudit1:ppc64el (1:3.1.2-4) over (1:3.1.2-2.1build1) ... 596s Setting up libaudit1:ppc64el (1:3.1.2-4) ... 596s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72737 files and directories currently installed.) 596s Preparing to unpack .../0-libcryptsetup12_2%3a2.7.0-1ubuntu6_ppc64el.deb ... 596s Unpacking libcryptsetup12:ppc64el (2:2.7.0-1ubuntu6) over (2:2.7.0-1ubuntu5) ... 596s Preparing to unpack .../1-dhcpcd-base_1%3a10.0.8-2_ppc64el.deb ... 596s Unpacking dhcpcd-base (1:10.0.8-2) over (1:10.0.8-1) ... 596s Preparing to unpack .../2-gir1.2-glib-2.0_2.80.3-1ubuntu1_ppc64el.deb ... 596s Unpacking gir1.2-glib-2.0:ppc64el (2.80.3-1ubuntu1) over (2.80.2-1ubuntu1) ... 596s Preparing to unpack .../3-libglib2.0-0t64_2.80.3-1ubuntu1_ppc64el.deb ... 596s Unpacking libglib2.0-0t64:ppc64el (2.80.3-1ubuntu1) over (2.80.2-1ubuntu1) ... 596s Preparing to unpack .../4-libglib2.0-data_2.80.3-1ubuntu1_all.deb ... 596s Unpacking libglib2.0-data (2.80.3-1ubuntu1) over (2.80.2-1ubuntu1) ... 596s Preparing to unpack .../5-libtraceevent1-plugin_1%3a1.8.2-1ubuntu3_ppc64el.deb ... 596s Unpacking libtraceevent1-plugin:ppc64el (1:1.8.2-1ubuntu3) over (1:1.8.2-1ubuntu2) ... 596s Preparing to unpack .../6-libtraceevent1_1%3a1.8.2-1ubuntu3_ppc64el.deb ... 596s Unpacking libtraceevent1:ppc64el (1:1.8.2-1ubuntu3) over (1:1.8.2-1ubuntu2) ... 596s Preparing to unpack .../7-cryptsetup-bin_2%3a2.7.0-1ubuntu6_ppc64el.deb ... 596s Unpacking cryptsetup-bin (2:2.7.0-1ubuntu6) over (2:2.7.0-1ubuntu5) ... 596s Preparing to unpack .../8-dracut-install_102-3ubuntu1_ppc64el.deb ... 596s Unpacking dracut-install (102-3ubuntu1) over (060+5-8ubuntu2) ... 596s Preparing to unpack .../9-xfsprogs_6.8.0-2_ppc64el.deb ... 596s Unpacking xfsprogs (6.8.0-2) over (6.6.0-1ubuntu2) ... 596s Setting up systemd-dev (256-1ubuntu1) ... 596s Setting up libglib2.0-0t64:ppc64el (2.80.3-1ubuntu1) ... 596s No schema files found: doing nothing. 596s Setting up libglib2.0-data (2.80.3-1ubuntu1) ... 596s Setting up libsystemd-shared:ppc64el (256-1ubuntu1) ... 596s Setting up xfsprogs (6.8.0-2) ... 596s update-initramfs: deferring update (trigger activated) 597s Setting up dhcpcd-base (1:10.0.8-2) ... 597s Setting up gir1.2-glib-2.0:ppc64el (2.80.3-1ubuntu1) ... 597s Setting up dracut-install (102-3ubuntu1) ... 597s Setting up libtraceevent1:ppc64el (1:1.8.2-1ubuntu3) ... 597s Setting up libcryptsetup12:ppc64el (2:2.7.0-1ubuntu6) ... 597s Setting up cryptsetup-bin (2:2.7.0-1ubuntu6) ... 597s Setting up systemd (256-1ubuntu1) ... 597s Installing new version of config file /etc/systemd/journald.conf ... 597s Installing new version of config file /etc/systemd/logind.conf ... 597s Installing new version of config file /etc/systemd/networkd.conf ... 597s Installing new version of config file /etc/systemd/sleep.conf ... 597s Installing new version of config file /etc/systemd/system.conf ... 597s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 597s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 597s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 598s Setting up systemd-timesyncd (256-1ubuntu1) ... 598s Setting up udev (256-1ubuntu1) ... 599s Setting up libtraceevent1-plugin:ppc64el (1:1.8.2-1ubuntu3) ... 599s Setting up systemd-resolved (256-1ubuntu1) ... 599s Installing new version of config file /etc/systemd/resolved.conf ... 600s Setting up systemd-sysv (256-1ubuntu1) ... 600s Setting up libnss-systemd:ppc64el (256-1ubuntu1) ... 600s Setting up libpam-systemd:ppc64el (256-1ubuntu1) ... 600s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 600s Processing triggers for man-db (2.12.1-2) ... 601s Processing triggers for dbus (1.14.10-4ubuntu4) ... 601s Processing triggers for shared-mime-info (2.4-5) ... 601s Warning: program compiled against libxml 212 using older 209 601s Processing triggers for initramfs-tools (0.142ubuntu28) ... 601s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 601s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 609s Reading package lists... 609s Building dependency tree... 609s Reading state information... 609s The following packages will be REMOVED: 609s systemd-dev* 609s 0 upgraded, 0 newly installed, 1 to remove and 0 not upgraded. 609s After this operation, 760 kB disk space will be freed. 609s (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 ... 72737 files and directories currently installed.) 609s Removing systemd-dev (256-1ubuntu1) ... 610s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 610s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 610s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 610s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 611s Reading package lists... 611s Reading package lists... 611s Building dependency tree... 611s Reading state information... 611s Calculating upgrade... 611s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 611s Reading package lists... 611s Building dependency tree... 611s Reading state information... 612s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 612s autopkgtest [19:01:41]: rebooting testbed after setup commands that affected boot 646s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 670s Reading package lists... 670s Building dependency tree... 670s Reading state information... 671s Starting pkgProblemResolver with broken count: 0 671s Starting 2 pkgProblemResolver with broken count: 0 671s Done 671s The following additional packages will be installed: 671s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 671s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 671s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 671s librdmacm1t64 lsscsi open-iscsi tgt 671s Suggested packages: 671s fio-examples gnuplot tgt-glusterfs tgt-rbd 671s Recommended packages: 671s finalrd 671s The following NEW packages will be installed: 671s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 671s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 671s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 671s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 671s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 671s Need to get 10.7 MB/10.7 MB of archives. 671s After this operation, 49.0 MB of additional disk space will be used. 671s Get:1 /tmp/autopkgtest.h6MXwZ/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 671s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu4 [54.4 kB] 671s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 671s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu4 [389 kB] 672s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 672s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 672s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu6 [256 kB] 672s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4ubuntu1 [21.5 kB] 672s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4ubuntu1 [311 kB] 672s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4ubuntu1 [46.5 kB] 672s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4ubuntu1 [99.2 kB] 672s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.1-1 [97.4 kB] 672s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 672s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 672s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 672s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 672s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 672s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 672s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 672s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 672s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 672s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 672s Preconfiguring packages ... 672s Fetched 10.7 MB in 1s (9646 kB/s) 672s Selecting previously unselected package libopeniscsiusr. 673s (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 ... 72690 files and directories currently installed.) 673s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu4_ppc64el.deb ... 673s Unpacking libopeniscsiusr (2.1.9-3ubuntu4) ... 673s Selecting previously unselected package libisns0t64:ppc64el. 673s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 673s Unpacking libisns0t64:ppc64el (0.101-1) ... 673s Selecting previously unselected package open-iscsi. 673s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu4_ppc64el.deb ... 673s Unpacking open-iscsi (2.1.9-3ubuntu4) ... 673s Selecting previously unselected package librdmacm1t64:ppc64el. 673s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 673s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 673s Selecting previously unselected package libconfig-general-perl. 673s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 673s Unpacking libconfig-general-perl (2.65-2) ... 673s Selecting previously unselected package tgt. 673s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu6_ppc64el.deb ... 673s Unpacking tgt (1:1.0.85-1.1ubuntu6) ... 673s Selecting previously unselected package libgfxdr0:ppc64el. 673s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_ppc64el.deb ... 673s Unpacking libgfxdr0:ppc64el (11.1-4ubuntu1) ... 673s Selecting previously unselected package libglusterfs0:ppc64el. 673s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_ppc64el.deb ... 673s Unpacking libglusterfs0:ppc64el (11.1-4ubuntu1) ... 673s Selecting previously unselected package libgfrpc0:ppc64el. 673s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_ppc64el.deb ... 673s Unpacking libgfrpc0:ppc64el (11.1-4ubuntu1) ... 673s Selecting previously unselected package libgfapi0:ppc64el. 673s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_ppc64el.deb ... 673s Unpacking libgfapi0:ppc64el (11.1-4ubuntu1) ... 673s Selecting previously unselected package libnbd0. 673s Preparing to unpack .../10-libnbd0_1.20.1-1_ppc64el.deb ... 673s Unpacking libnbd0 (1.20.1-1) ... 673s Selecting previously unselected package libdaxctl1:ppc64el. 673s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 673s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 673s Selecting previously unselected package libndctl6:ppc64el. 673s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 673s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 673s Selecting previously unselected package libpmem1:ppc64el. 673s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 673s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 673s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 673s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 673s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 673s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 673s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 673s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 673s Selecting previously unselected package librados2. 673s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 673s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 673s Selecting previously unselected package libpmemobj1:ppc64el. 673s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 673s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 673s Selecting previously unselected package librbd1. 673s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 673s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 673s Selecting previously unselected package fio. 673s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 673s Unpacking fio (3.37-1) ... 673s Selecting previously unselected package lsscsi. 673s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 673s Unpacking lsscsi (0.32-1build1) ... 673s Selecting previously unselected package autopkgtest-satdep. 673s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 673s Unpacking autopkgtest-satdep (0) ... 673s Setting up libconfig-general-perl (2.65-2) ... 673s Setting up libisns0t64:ppc64el (0.101-1) ... 673s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 673s Setting up libnbd0 (1.20.1-1) ... 673s Setting up libopeniscsiusr (2.1.9-3ubuntu4) ... 673s Setting up libglusterfs0:ppc64el (11.1-4ubuntu1) ... 673s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 673s Setting up lsscsi (0.32-1build1) ... 673s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 673s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 673s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 673s Setting up tgt (1:1.0.85-1.1ubuntu6) ... 674s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 674s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 674s Setting up libgfxdr0:ppc64el (11.1-4ubuntu1) ... 674s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 674s Setting up open-iscsi (2.1.9-3ubuntu4) ... 675s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 676s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 676s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 676s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 676s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 676s Setting up libgfrpc0:ppc64el (11.1-4ubuntu1) ... 676s Setting up libgfapi0:ppc64el (11.1-4ubuntu1) ... 676s Setting up fio (3.37-1) ... 676s Setting up autopkgtest-satdep (0) ... 676s Processing triggers for man-db (2.12.1-2) ... 678s Processing triggers for initramfs-tools (0.142ubuntu28) ... 678s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 678s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 686s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 689s (Reading database ... 72931 files and directories currently installed.) 689s Removing autopkgtest-satdep (0) ... 697s autopkgtest [19:03:06]: test tgtbasedmpaths: [----------------------- 697s + targetname=iqn.2016-11.foo.com:target.iscsi 697s + pwd 697s + cwd=/tmp/autopkgtest.h6MXwZ/build.4Hd/src 697s + testdir=/mnt/tgtmpathtest 697s + localhost=127.0.0.1 697s + portal=127.0.0.1:3260 697s + maxpaths=4 697s + backfn=backingfile 697s + expectwwid=60000000000000000e00000000010001 697s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 697s + bglog=/tmp/autopkgtest.h6MXwZ/tgtbasedmpaths-artifacts/test-background.log 697s + fioprep=/tmp/autopkgtest.h6MXwZ/tgtbasedmpaths-artifacts/path-change-prep.fio 697s + fiovrfy=/tmp/autopkgtest.h6MXwZ/tgtbasedmpaths-artifacts/path-change-check.fio 697s + service tgt restart 697s + truncate --size 100M backingfile 697s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 697s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 697s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.h6MXwZ/build.4Hd/src/backingfile 697s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 697s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 697s + echo login #1 697s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 697s login #1 697s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 697s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 697s + seq 2 4 697s extra login #2 697s + echo extra login #2 697s + iscsiadm --mode session -r 1 --op new 697s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 697s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 697s extra login #3 697s + echo extra login #3 697s + iscsiadm --mode session -r 1 --op new 697s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 697s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 697s extra login #4 697s + echo extra login #4 697s + iscsiadm --mode session -r 1 --op new 697s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 697s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 697s + udevadm settle 697s + sleep 5 702s Status after initial setup 702s + echo Status after initial setup 702s + tgtadm --lld iscsi --mode target --op show 702s Target 1: iqn.2016-11.foo.com:target.iscsi 702s System information: 702s Driver: iscsi 702s State: ready 702s I_T nexus information: 702s I_T nexus: 1 702s Initiator: iqn.2004-10.com.ubuntu:01:efeea4ef29b alias: autopkgtest 702s Connection: 0 702s IP Address: 127.0.0.1 702s I_T nexus: 2 702s Initiator: iqn.2004-10.com.ubuntu:01:efeea4ef29b alias: autopkgtest 702s Connection: 0 702s IP Address: 127.0.0.1 702s I_T nexus: 3 702s Initiator: iqn.2004-10.com.ubuntu:01:efeea4ef29b alias: autopkgtest 702s Connection: 0 702s IP Address: 127.0.0.1 702s I_T nexus: 4 702s Initiator: iqn.2004-10.com.ubuntu:01:efeea4ef29b alias: autopkgtest 702s Connection: 0 702s IP Address: 127.0.0.1 702s LUN information: 702s LUN: 0 702s Type: controller 702s SCSI ID: IET 00010000 702s SCSI SN: beaf10 702s Size: 0 MB, Block size: 1 702s Online: Yes 702s Removable media: No 702s Prevent removal: No 702s Readonly: No 702s SWP: No 702s Thin-provisioning: No 702s Backing store type: null 702s Backing store path: None 702s Backing store flags: 702s LUN: 1 702s Type: disk 702s SCSI ID: IET 00010001 702s SCSI SN: beaf11 702s Size: 105 MB, Block size: 512 702s Online: Yes 702s Removable media: No 702s Prevent removal: No 702s Readonly: No 702s SWP: No 702s Thin-provisioning: No 702s Backing store type: rdwr 702s Backing store path: /tmp/autopkgtest.h6MXwZ/build.4Hd/src/backingfile 702s Backing store flags: 702s Account information: 702s ACL information: 702s ALL 702s + tgtadm --lld iscsi --op show --mode conn --tid 1 702s + iscsiadm --mode session -P 1 702s Session: 4 702s Connection: 0 702s Initiator: iqn.2004-10.com.ubuntu:01:efeea4ef29b 702s IP Address: 127.0.0.1 702s Session: 3 702s Connection: 0 702s Initiator: iqn.2004-10.com.ubuntu:01:efeea4ef29b 702s IP Address: 127.0.0.1 702s Session: 2 702s Connection: 0 702s Initiator: iqn.2004-10.com.ubuntu:01:efeea4ef29b 702s IP Address: 127.0.0.1 702s Session: 1 702s Connection: 0 702s Initiator: iqn.2004-10.com.ubuntu:01:efeea4ef29b 702s IP Address: 127.0.0.1 702s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 702s Current Portal: 127.0.0.1:3260,1 702s Persistent Portal: 127.0.0.1:3260,1 702s ********** 702s Interface: 702s ********** 702s Iface Name: default 702s Iface Transport: tcp 702s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:efeea4ef29b 702s Iface IPaddress: 127.0.0.1 702s Iface HWaddress: default 702s Iface Netdev: default 702s SID: 1 702s iSCSI Connection State: LOGGED IN 702s iSCSI Session State: LOGGED_IN 702s Internal iscsid Session State: NO CHANGE 702s 702s ********** 702s Interface: 702s ********** 702s Iface Name: default 702s Iface Transport: tcp 702s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:efeea4ef29b 702s Iface IPaddress: 127.0.0.1 702s Iface HWaddress: default 702s Iface Netdev: default 702s SID: 2 702s iSCSI Connection State: LOGGED IN 702s iSCSI Session State: LOGGED_IN 702s Internal iscsid Session State: NO CHANGE 702s 702s ********** 702s Interface: 702s ********** 702s Iface Name: default 702s Iface Transport: tcp 702s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:efeea4ef29b 702s Iface IPaddress: 127.0.0.1 702s Iface HWaddress: default 702s Iface Netdev: default 702s SID: 3 702s iSCSI Connection State: LOGGED IN 702s iSCSI Session State: LOGGED_IN 702s Internal iscsid Session State: NO CHANGE 702s 702s ********** 702s Interface: 702s ********** 702s Iface Name: default 702s Iface Transport: tcp 702s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:efeea4ef29b 702s Iface IPaddress: 127.0.0.1 702s Iface HWaddress: default 702s Iface Netdev: default 702s SID: 4 702s iSCSI Connection State: LOGGED IN 702s iSCSI Session State: LOGGED_IN 702s Internal iscsid Session State: NO CHANGE 702s + lsscsi -liv 703s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 703s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 703s 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] 703s [1:0:0:0] storage IET Controller 0001 - - 703s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 703s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 703s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 703s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 703s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 703s [2:0:0:0] storage IET Controller 0001 - - 703s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 703s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 703s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 703s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 703s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 703s [3:0:0:0] storage IET Controller 0001 - - 703s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 703s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 703s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 703s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 703s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 703s [4:0:0:0] storage IET Controller 0001 - - 703s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 703s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 703s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 703s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 703s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 703s NVMe module may not be loaded 703s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 703s + multipath -v3 -ll 703s 66.714392 | set open fds limit to 1073741816/1073741816 703s 66.714452 | loading /lib/multipath/libchecktur.so checker 703s 66.714529 | checker tur: message table size = 3 703s 66.714537 | loading /lib/multipath/libprioconst.so prioritizer 703s 66.714639 | _init_foreign: foreign library "nvme" is not enabled 703s 66.721682 | sda: size = 167772160 703s 66.721860 | sda: vendor = QEMU 703s 66.721908 | sda: product = QEMU HARDDISK 703s 66.721931 | sda: rev = 2.5+ 703s 66.722705 | sda: h:b:t:l = 0:0:0:0 703s 66.723042 | sda: tgt_node_name = 703s 66.723064 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 703s 66.723067 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 703s 66.723222 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 703s 66.723243 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 703s 66.723256 | __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 703s 66.723260 | failed to read sysfs vpd pg80: No such file or directory 703s 66.723527 | sda: fail to get serial 703s 66.723550 | sda: detect_checker = yes (setting: multipath internal) 703s 66.723737 | sda: path_checker = tur (setting: multipath internal) 703s 66.723760 | sda: checker timeout = 30 s (setting: kernel sysfs) 703s 66.724171 | sda: tur state = up 703s 66.724503 | sdb: size = 204800 703s 66.724659 | sdb: vendor = IET 703s 66.724733 | sdb: product = VIRTUAL-DISK 703s 66.724756 | sdb: rev = 0001 703s 66.725437 | sdb: h:b:t:l = 1:0:0:1 703s 66.725838 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 703s 66.725860 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 703s 66.725863 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 703s 66.726023 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 703s 66.726044 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 703s 66.726063 | sdb: serial = beaf11 703s 66.726066 | sdb: detect_checker = yes (setting: multipath internal) 703s 66.726288 | sdb: path_checker = tur (setting: multipath internal) 703s 66.726312 | sdb: checker timeout = 30 s (setting: kernel sysfs) 703s 66.726371 | sdb: tur state = up 703s 66.726537 | sdc: size = 204800 703s 66.726697 | sdc: vendor = IET 703s 66.726739 | sdc: product = VIRTUAL-DISK 703s 66.726762 | sdc: rev = 0001 703s 66.727455 | sdc: h:b:t:l = 2:0:0:1 703s 66.727834 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 703s 66.727856 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 703s 66.727858 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 703s 66.728116 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 703s 66.728137 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 703s 66.728152 | sdc: serial = beaf11 703s 66.728155 | sdc: detect_checker = yes (setting: multipath internal) 703s 66.728455 | sdc: path_checker = tur (setting: multipath internal) 703s 66.728477 | sdc: checker timeout = 30 s (setting: kernel sysfs) 703s 66.728657 | sdc: tur state = up 703s 66.728847 | sdd: size = 204800 703s 66.729031 | sdd: vendor = IET 703s 66.729072 | sdd: product = VIRTUAL-DISK 703s 66.729095 | sdd: rev = 0001 703s 66.729781 | sdd: h:b:t:l = 3:0:0:1 703s 66.730306 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 703s 66.730328 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 703s 66.730330 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 703s 66.730490 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 703s 66.730494 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 703s 66.730506 | sdd: serial = beaf11 703s 66.730509 | sdd: detect_checker = yes (setting: multipath internal) 703s 66.732451 | sdd: path_checker = tur (setting: multipath internal) 703s 66.732474 | sdd: checker timeout = 30 s (setting: kernel sysfs) 703s 66.732658 | sdd: tur state = up 703s 66.732813 | sde: size = 204800 703s 66.732971 | sde: vendor = IET 703s 66.733013 | sde: product = VIRTUAL-DISK 703s 66.733035 | sde: rev = 0001 703s 66.733883 | sde: h:b:t:l = 4:0:0:1 703s 66.734363 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 703s 66.734385 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 703s 66.734387 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 703s 66.734538 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 703s 66.734559 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 703s 66.734573 | sde: serial = beaf11 703s 66.734576 | sde: detect_checker = yes (setting: multipath internal) 703s 66.734815 | sde: path_checker = tur (setting: multipath internal) 703s 66.734836 | sde: checker timeout = 30 s (setting: kernel sysfs) 703s 66.735019 | sde: tur state = up 703s 66.735137 | loop0: device node name blacklisted 703s 66.735245 | loop1: device node name blacklisted 703s 66.735353 | loop2: device node name blacklisted 703s 66.735457 | loop3: device node name blacklisted 703s 66.735562 | loop4: device node name blacklisted 703s 66.735667 | loop5: device node name blacklisted 703s 66.735770 | loop6: device node name blacklisted 703s 66.735873 | loop7: device node name blacklisted 703s 66.735982 | dm-0: device node name blacklisted 703s 66.737044 | multipath-tools v0.9.4 (12/19, 2022) 703s 66.737074 | libdevmapper version 1.02.185 703s ===== paths list ===== 703s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 703s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 703s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 703s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 703s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 703s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 703s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 703s size=100M features='0' hwhandler='0' wp=rw 703s |-+- policy='service-time 0' prio=1 status=active 703s | `- 1:0:0:1 sdb 8:16 active ready running 703s |-+- policy='service-time 0' prio=1 status=enabled 703s | `- 2:0:0:1 sdc 8:32 active ready running 703s |-+- policy='service-time 0' prio=1 status=enabled 703s | `- 3:0:0:1 sdd 8:48 active ready running 703s `-+- policy='service-time 0' prio=1 status=enabled 703s `- 4:0:0:1 sde 8:64 active ready running 703s 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 703s Test WWN should now point to DM 703s ../../dm-0 703s Creating filesystem with 25600 4k blocks and 25600 inodes 703s 703s Allocating group tables: 0/1 done 703s Writing inode tables: 0/1 done 703s Creating journal (1024 blocks): done 703s Writing superblocks and filesystem accounting information: 0/1 66.737215 | kernel device mapper v4.48.0 703s 66.737245 | DM multipath kernel driver v1.14.0 703s 66.737354 | sdb: size = 204800 703s 66.737376 | sdb: vendor = IET 703s 66.737379 | sdb: product = VIRTUAL-DISK 703s 66.737382 | sdb: rev = 0001 703s 66.738192 | sdb: h:b:t:l = 1:0:0:1 703s 66.738333 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 703s 66.738375 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 703s 66.738378 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 703s 66.738391 | sdb: serial = beaf11 703s 66.738550 | sdb: tur state = up 703s 66.738572 | sdb: uid = 360000000000000000e00000000010001 (udev) 703s 66.738575 | sdb: detect_prio = yes (setting: multipath internal) 703s 66.738579 | sdb: prio = const (setting: multipath internal) 703s 66.738581 | sdb: prio args = "" (setting: multipath internal) 703s 66.738584 | sdb: const prio = 1 703s 66.738609 | sdc: size = 204800 703s 66.738614 | sdc: vendor = IET 703s 66.738616 | sdc: product = VIRTUAL-DISK 703s 66.738619 | sdc: rev = 0001 703s 66.739229 | sdc: h:b:t:l = 2:0:0:1 703s 66.739365 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 703s 66.739402 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 703s 66.739405 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 703s 66.739418 | sdc: serial = beaf11 703s 66.739623 | sdc: tur state = up 703s 66.739644 | sdc: uid = 360000000000000000e00000000010001 (udev) 703s 66.739647 | sdc: detect_prio = yes (setting: multipath internal) 703s 66.739649 | sdc: prio = const (setting: multipath internal) 703s 66.739651 | sdc: prio args = "" (setting: multipath internal) 703s 66.739654 | sdc: const prio = 1 703s 66.739678 | sdd: size = 204800 703s 66.739682 | sdd: vendor = IET 703s 66.739685 | sdd: product = VIRTUAL-DISK 703s 66.739687 | sdd: rev = 0001 703s 66.740542 | sdd: h:b:t:l = 3:0:0:1 703s 66.740682 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 703s 66.740720 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 703s 66.740723 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 703s 66.740736 | sdd: serial = beaf11 703s 66.740895 | sdd: tur state = up 703s 66.740916 | sdd: uid = 360000000000000000e00000000010001 (udev) 703s 66.740918 | sdd: detect_prio = yes (setting: multipath internal) 703s 66.740921 | sdd: prio = const (setting: multipath internal) 703s 66.740923 | sdd: prio args = "" (setting: multipath internal) 703s 66.740925 | sdd: const prio = 1 703s 66.740951 | sde: size = 204800 703s 66.740955 | sde: vendor = IET 703s 66.740958 | sde: product = VIRTUAL-DISK 703s 66.740960 | sde: rev = 0001 703s 66.741828 | sde: h:b:t:l = 4:0:0:1 703s 66.741995 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 703s 66.742166 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 703s 66.742169 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 703s 66.742183 | sde: serial = beaf11 703s 66.742358 | sde: tur state = up 703s 66.742380 | sde: uid = 360000000000000000e00000000010001 (udev) 703s 66.742383 | sde: detect_prio = yes (setting: multipath internal) 703s 66.742385 | sde: prio = const (setting: multipath internal) 703s 66.742387 | sde: prio args = "" (setting: multipath internal) 703s 66.742389 | sde: const prio = 1 703s 66.743165 | unloading tur checker 703s 66.743230 | unloading const prioritizer 703s + dmsetup table 703s + echo Test WWN should now point to DM 703s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 703s + grep dm 703s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 703s mke2fs 1.47.0 (5-Feb-2023) 703s done 703s 703s + udevadm settle 703s + sleep 3s 706s + mkdir -p /mnt/tgtmpathtest 706s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 706s + cat 706s + cat 706s + fio --max-jobs=4 /tmp/autopkgtest.h6MXwZ/tgtbasedmpaths-artifacts/path-change-prep.fio 706s 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 706s fio-3.37 706s Starting 1 thread 706s write-phase: Laying out IO file (1 file / 17592186044415MiB) 707s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 707s 707s write-phase: (groupid=0, jobs=1): err= 0: pid=5681: Thu Jun 13 19:03:16 2024 707s write: IOPS=2075, BW=130MiB/s (136MB/s)(87.6MiB/676msec); 0 zone resets 707s clat (usec): min=263, max=3841, avg=461.12, stdev=197.07 707s lat (usec): min=277, max=3861, avg=480.17, stdev=200.34 707s clat percentiles (usec): 707s | 1.00th=[ 293], 5.00th=[ 318], 10.00th=[ 334], 20.00th=[ 351], 707s | 30.00th=[ 375], 40.00th=[ 388], 50.00th=[ 412], 60.00th=[ 461], 707s | 70.00th=[ 519], 80.00th=[ 545], 90.00th=[ 586], 95.00th=[ 644], 707s | 99.00th=[ 1020], 99.50th=[ 1663], 99.90th=[ 2868], 99.95th=[ 3851], 707s | 99.99th=[ 3851] 707s bw ( KiB/s): min=140672, max=140672, per=100.00%, avg=140672.00, stdev= 0.00, samples=1 707s iops : min= 2198, max= 2198, avg=2198.00, stdev= 0.00, samples=1 707s lat (usec) : 500=66.36%, 750=31.36%, 1000=1.07% 707s lat (msec) : 2=0.78%, 4=0.36% 707s cpu : usr=6.07%, sys=7.85%, ctx=1404, majf=0, minf=0 707s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 707s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 707s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 707s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 707s latency : target=0, window=0, percentile=100.00%, depth=1 707s 707s Run status group 0 (all jobs): 707s WRITE: bw=130MiB/s (136MB/s), 130MiB/s-130MiB/s (136MB/s-136MB/s), io=87.6MiB (91.9MB), run=676-676msec 707s 707s Disk stats (read/write): 707s dm-0: ios=1/1347, sectors=8/172416, merge=0/0, ticks=1/599, in_queue=600, util=87.03%, aggrios=0/351, aggsectors=2/48082, aggrmerge=0/0, aggrticks=0/155, aggrin_queue=155, aggrutil=87.20% 707s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 707s sdb: ios=2/1404, sectors=8/192328, merge=0/0, ticks=1/620, in_queue=621, util=87.20% 707s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 707s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 707s Starting the path changes in background 707s + echo Starting the path changes in background 707s + date +Pre FIO %H:%M:%S.%N 707s Pre FIO 19:03:16.190114490 707s + fio --max-jobs=4 /tmp/autopkgtest.h6MXwZ/tgtbasedmpaths-artifacts/path-change-check.fio 707s 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 707s fio-3.37 707s Starting 1 thread 887s 887s verify-phase: (groupid=0, jobs=1): err= 0: pid=5688: Thu Jun 13 19:06:16 2024 887s read: IOPS=3099, BW=194MiB/s (203MB/s)(34.1GiB/180001msec) 887s clat (usec): min=87, max=52153, avg=299.45, stdev=281.22 887s lat (usec): min=87, max=52153, avg=299.56, stdev=281.23 887s clat percentiles (usec): 887s | 1.00th=[ 135], 5.00th=[ 151], 10.00th=[ 178], 20.00th=[ 198], 887s | 30.00th=[ 212], 40.00th=[ 239], 50.00th=[ 277], 60.00th=[ 302], 887s | 70.00th=[ 330], 80.00th=[ 363], 90.00th=[ 400], 95.00th=[ 453], 887s | 99.00th=[ 889], 99.50th=[ 1434], 99.90th=[ 3982], 99.95th=[ 5014], 887s | 99.99th=[ 8586] 887s bw ( KiB/s): min=123008, max=369280, per=100.00%, avg=198535.54, stdev=48601.28, samples=359 887s iops : min= 1922, max= 5770, avg=3102.06, stdev=759.43, samples=359 887s lat (usec) : 100=0.42%, 250=42.28%, 500=54.03%, 750=1.99%, 1000=0.46% 887s lat (msec) : 2=0.51%, 4=0.22%, 10=0.09%, 20=0.01%, 50=0.01% 887s lat (msec) : 100=0.01% 887s cpu : usr=8.54%, sys=8.38%, ctx=558047, majf=0, minf=1 887s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 887s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 887s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 887s issued rwts: total=557954,0,0,0 short=0,0,0,0 dropped=0,0,0,0 887s latency : target=0, window=0, percentile=100.00%, depth=1 887s 887s Run status group 0 (all jobs): 887s READ: bw=194MiB/s (203MB/s), 194MiB/s-194MiB/s (203MB/s-203MB/s), io=34.1GiB (36.6GB), run=180001-180001msec 887s 887s Disk stats (read/write): 887s dm-0: ios=557640/7, sectors=71377464/120, merge=31/8, ticks=171394/3, in_queue=171397, util=99.83%, aggrios=39890/1, aggsectors=5105838/30, aggrmerge=0/0, aggrticks=10844/0, aggrin_queue=10845, aggrutil=99.15% 887s sdd: ios=32143/0, sectors=4114304/0, merge=0/0, ticks=8571/0, in_queue=8571, util=32.93% 887s sdb: ios=35602/7, sectors=4556928/120, merge=0/0, ticks=8248/2, in_queue=8251, util=99.15% 887s sde: ios=62962/0, sectors=8059136/0, merge=0/0, ticks=17650/0, in_queue=17651, util=40.01% 887s sdc: ios=28855/0, sectors=3692984/0, merge=0/0, ticks=8907/0, in_queue=8907, util=50.17% 887s + date +Post FIO %H:%M:%S.%N 887s Post FIO 19:06:16.547986120 887s FIO verify test with changing paths - OK 887s Report log of background activity 887s + echo FIO verify test with changing paths - OK 887s + echo Report log of background activity 887s + cat /tmp/autopkgtest.h6MXwZ/tgtbasedmpaths-artifacts/test-background.log 887s + iscsiadm --mode session 887s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s + sleep 10s 887s + date +MP report (expect 4) %H:%M:%S.%N 887s MP report (expect 4) 19:03:26.197350844 887s + multipath -ll 887s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 887s size=100M features='0' hwhandler='0' wp=rw 887s |-+- policy='service-time 0' prio=1 status=active 887s | `- 1:0:0:1 sdb 8:16 active ready running 887s |-+- policy='service-time 0' prio=1 status=enabled 887s | `- 2:0:0:1 sdc 8:32 active ready running 887s |-+- policy='service-time 0' prio=1 status=enabled 887s | `- 3:0:0:1 sdd 8:48 active ready running 887s `-+- policy='service-time 0' prio=1 status=enabled 887s `- 4:0:0:1 sde 8:64 active ready running 887s + date +UN-plug path 1 %H:%M:%S.%N 887s UN-plug path 1 19:03:26.223468727 887s + iscsiadm --mode session -r 1 -u 887s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 887s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 887s + iscsiadm --mode session 887s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s + sleep 10s 887s + date +MP report (expect 3) %H:%M:%S.%N 887s MP report (expect 3) 19:03:36.331864460 887s + multipath -ll 887s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 887s size=100M features='0' hwhandler='0' wp=rw 887s |-+- policy='service-time 0' prio=1 status=active 887s | `- 2:0:0:1 sdc 8:32 active ready running 887s |-+- policy='service-time 0' prio=1 status=enabled 887s | `- 3:0:0:1 sdd 8:48 active ready running 887s `-+- policy='service-time 0' prio=1 status=enabled 887s `- 4:0:0:1 sde 8:64 active ready running 887s + date +UN-plug path 2 %H:%M:%S.%N 887s UN-plug path 2 19:03:36.355750239 887s + iscsiadm --mode session -r 2 -u 887s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 887s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 887s + iscsiadm --mode session 887s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s + sleep 10s 887s + date +MP report (expect 2) %H:%M:%S.%N 887s MP report (expect 2) 19:03:46.478227158 887s + multipath -ll 887s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 887s size=100M features='0' hwhandler='0' wp=rw 887s |-+- policy='service-time 0' prio=1 status=active 887s | `- 3:0:0:1 sdd 8:48 active ready running 887s `-+- policy='service-time 0' prio=1 status=enabled 887s `- 4:0:0:1 sde 8:64 active ready running 887s + date +UN-plug path 3 %H:%M:%S.%N 887s UN-plug path 3 19:03:46.498890736 887s + iscsiadm --mode session -r 3 -u 887s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 887s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 887s + iscsiadm --mode session 887s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s + sleep 10s 887s + date +MP report (expect 1) %H:%M:%S.%N 887s MP report (expect 1) 19:03:56.593690252 887s + multipath -ll 887s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 887s size=100M features='0' hwhandler='0' wp=rw 887s `-+- policy='service-time 0' prio=1 status=active 887s `- 4:0:0:1 sde 8:64 active ready running 887s + date +Add paths 5/6/7/8 %H:%M:%S.%N 887s Add paths 5/6/7/8 19:03:56.613834895 887s + iscsiadm --mode session -r 4 --op new 887s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 887s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 887s + iscsiadm --mode session -r 4 --op new 887s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 887s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 887s + iscsiadm --mode session -r 4 --op new 887s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 887s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 887s + iscsiadm --mode session -r 4 --op new 887s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 887s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 887s + iscsiadm --mode session 887s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s + sleep 10s 887s + date +MP report (expect 5) %H:%M:%S.%N 887s MP report (expect 5) 19:04:06.790318665 887s + multipath -ll 887s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 887s size=100M features='0' hwhandler='0' wp=rw 887s |-+- policy='service-time 0' prio=1 status=active 887s | `- 4:0:0:1 sde 8:64 active ready running 887s |-+- policy='service-time 0' prio=1 status=enabled 887s | `- 1:0:0:1 sdb 8:16 active ready running 887s |-+- policy='service-time 0' prio=1 status=enabled 887s | `- 2:0:0:1 sdc 8:32 active ready running 887s |-+- policy='service-time 0' prio=1 status=enabled 887s | `- 3:0:0:1 sdd 8:48 active ready running 887s `-+- policy='service-time 0' prio=1 status=enabled 887s `- 5:0:0:1 sdf 8:80 active ready running 887s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 887s UN-plug multiple paths 4/7/8 19:04:06.821663690 887s + iscsiadm --mode session -r 4 -u 887s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 887s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 887s + iscsiadm --mode session -r 7 -u 887s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 887s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 887s + iscsiadm --mode session -r 8 -u 887s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 887s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 887s + iscsiadm --mode session 887s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 887s + sleep 10s 887s + date +Restart multipath daemon %H:%M:%S.%N 887s Restart multipath daemon 19:04:17.150038520 887s + systemctl restart multipathd 887s + sleep 10s 887s + date +Final background report (expect 2) %H:%M:%S.%N 887s Final background report (expect 2) 19:04:27.243116858 887s + multipath -ll 887s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 887s size=100M features='0' hwhandler='0' wp=rw 887s |-+- policy='service-time 0' prio=1 status=active 887s | `- 1:0:0:1 sdb 8:16 active ready running 887s `-+- policy='service-time 0' prio=1 status=enabled 887s `- 2:0:0:1 sdc 8:32 active ready running 887s Final stats 887s + sync 887s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 887s + echo Final stats 887s + iscsiadm --mode session --stats 887s + journalctl --no-pager -u multipathd 887s + echo Check final path status 887s + multipath -ll 887s + grep --count status= 887s + multipath -ll 887s + diskc=2 887s + multipath -ll 887s + grep --count status=active 887s + diska=1 887s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 887s iSCSI SNMP: 887s txdata_octets: 19035336 887s rxdata_octets: 25985108276 887s noptx_pdus: 0 887s scsicmd_pdus: 396302 887s tmfcmd_pdus: 0 887s login_pdus: 0 887s text_pdus: 0 887s dataout_pdus: 0 887s logout_pdus: 0 887s snack_pdus: 0 887s noprx_pdus: 0 887s scsirsp_pdus: 396302 887s tmfrsp_pdus: 0 887s textrsp_pdus: 0 887s datain_pdus: 396271 887s logoutrsp_pdus: 0 887s r2t_pdus: 0 887s async_pdus: 0 887s rjt_pdus: 0 887s digest_err: 0 887s timeout_err: 0 887s iSCSI Extended: 887s tx_sendpage_failures: 0 887s rx_discontiguous_hdr: 0 887s eh_abort_cnt: 0 887s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 887s iSCSI SNMP: 887s txdata_octets: 6456 887s rxdata_octets: 1514916 887s noptx_pdus: 0 887s scsicmd_pdus: 104 887s tmfcmd_pdus: 0 887s login_pdus: 0 887s text_pdus: 0 887s dataout_pdus: 0 887s logout_pdus: 0 887s snack_pdus: 0 887s noprx_pdus: 0 887s scsirsp_pdus: 104 887s tmfrsp_pdus: 0 887s textrsp_pdus: 0 887s datain_pdus: 83 887s logoutrsp_pdus: 0 887s r2t_pdus: 0 887s async_pdus: 0 887s rjt_pdus: 0 887s digest_err: 0 887s timeout_err: 0 887s iSCSI Extended: 887s tx_sendpage_failures: 0 887s rx_discontiguous_hdr: 0 887s eh_abort_cnt: 0 887s Jun 12 17:58:33 adtubuntu-oracular-ppc64el-server-20240610 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 887s Jun 12 17:58:33 adtubuntu-oracular-ppc64el-server-20240610 multipathd[281]: multipathd v0.9.4: start up 887s Jun 12 17:58:33 adtubuntu-oracular-ppc64el-server-20240610 multipathd[281]: reconfigure: setting up paths and maps 887s Jun 12 17:58:33 adtubuntu-oracular-ppc64el-server-20240610 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 887s Jun 12 17:59:13 adtubuntu-oracular-ppc64el-server-20240611 multipathd[281]: multipathd: shut down 887s Jun 12 17:59:13 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 887s Jun 12 17:59:13 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: multipathd.service: Deactivated successfully. 887s Jun 12 17:59:13 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 887s -- Boot eb3890a22d3e44c38e4a72e6421d5c6b -- 887s Jun 12 17:59:38 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 887s Jun 12 17:59:38 adtubuntu-oracular-ppc64el-server-20240611 multipathd[285]: multipathd v0.9.4: start up 887s Jun 12 17:59:38 adtubuntu-oracular-ppc64el-server-20240611 multipathd[285]: reconfigure: setting up paths and maps 887s Jun 12 17:59:38 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 887s Jun 12 18:00:04 adtubuntu-oracular-ppc64el-server-20240611 multipathd[285]: multipathd: shut down 887s Jun 12 18:00:04 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 887s Jun 12 18:00:04 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: multipathd.service: Deactivated successfully. 887s Jun 12 18:00:04 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 887s -- Boot 7c1c80ab264946e0979e5b0059af19a2 -- 887s Jun 13 19:00:36 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 887s Jun 13 19:00:36 adtubuntu-oracular-ppc64el-server-20240611 multipathd[329]: multipathd v0.9.4: start up 887s Jun 13 19:00:36 adtubuntu-oracular-ppc64el-server-20240611 multipathd[329]: reconfigure: setting up paths and maps 887s Jun 13 19:00:36 adtubuntu-oracular-ppc64el-server-20240611 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 887s Jun 13 19:01:45 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 887s Jun 13 19:01:45 autopkgtest multipathd[329]: multipathd: shut down 887s Jun 13 19:01:45 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 887s Jun 13 19:01:45 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 887s -- Boot c50467881f6a49b3b6fc41de95ed55bd -- 887s Jun 13 19:02:08 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 887s Jun 13 19:02:08 autopkgtest multipathd[341]: multipathd v0.9.4: start up 887s Jun 13 19:02:08 autopkgtest multipathd[341]: reconfigure: setting up paths and maps 887s Jun 13 19:02:08 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 887s Jun 13 19:03:06 autopkgtest multipathd[341]: 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] 887s Jun 13 19:03:06 autopkgtest multipathd[341]: sdc [8:32]: path added to devmap mpatha 887s Jun 13 19:03:06 autopkgtest multipathd[341]: mpatha: performing delayed actions 887s Jun 13 19:03:06 autopkgtest multipathd[341]: 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] 887s Jun 13 19:03:26 autopkgtest multipathd[341]: sdb: mark as failed 887s Jun 13 19:03:26 autopkgtest multipathd[341]: mpatha: remaining active paths: 3 887s Jun 13 19:03:26 autopkgtest multipathd[341]: 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] 887s Jun 13 19:03:26 autopkgtest multipathd[341]: check_removed_paths: sdb: freeing path in removed state 887s Jun 13 19:03:26 autopkgtest multipathd[341]: 8:16: path removed from map mpatha 887s Jun 13 19:03:36 autopkgtest multipathd[341]: 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] 887s Jun 13 19:03:36 autopkgtest multipathd[341]: check_removed_paths: sdc: freeing path in removed state 887s Jun 13 19:03:36 autopkgtest multipathd[341]: 8:32: path removed from map mpatha 887s Jun 13 19:03:46 autopkgtest multipathd[341]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 887s Jun 13 19:03:46 autopkgtest multipathd[341]: check_removed_paths: sdd: freeing path in removed state 887s Jun 13 19:03:46 autopkgtest multipathd[341]: 8:48: path removed from map mpatha 887s Jun 13 19:03:56 autopkgtest multipathd[341]: 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] 887s Jun 13 19:03:56 autopkgtest multipathd[341]: sdb [8:16]: path added to devmap mpatha 887s Jun 13 19:03:56 autopkgtest multipathd[341]: 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] 887s Jun 13 19:03:56 autopkgtest multipathd[341]: sdc [8:32]: path added to devmap mpatha 887s Jun 13 19:03:56 autopkgtest multipathd[341]: 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] 887s Jun 13 19:03:56 autopkgtest multipathd[341]: sdd [8:48]: path added to devmap mpatha 887s Jun 13 19:03:56 autopkgtest multipathd[341]: 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] 887s Jun 13 19:03:56 autopkgtest multipathd[341]: sdf [8:80]: path added to devmap mpatha 887s Jun 13 19:04:06 autopkgtest multipathd[341]: sde: mark as failed 887s Jun 13 19:04:06 autopkgtest multipathd[341]: mpatha: remaining active paths: 4 887s Jun 13 19:04:06 autopkgtest multipathd[341]: 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] 887s Jun 13 19:04:06 autopkgtest multipathd[341]: check_removed_paths: sde: freeing path in removed state 887s Jun 13 19:04:06 autopkgtest multipathd[341]: 8:64: path removed from map mpatha 887s Jun 13 19:04:06 autopkgtest multipathd[341]: 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] 887s Jun 13 19:04:06 autopkgtest multipathd[341]: check_removed_paths: sdd: freeing path in removed state 887s Jun 13 19:04:06 autopkgtest multipathd[341]: 8:48: path removed from map mpatha 887s Jun 13 19:04:07 autopkgtest multipathd[341]: 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] 887s Jun 13 19:04:07 autopkgtest multipathd[341]: check_removed_paths: sdf: freeing path in removed state 887s Jun 13 19:04:07 autopkgtest multipathd[341]: 8:80: path removed from map mpatha 887s Jun 13 19:04:17 autopkgtest multipathd[341]: multipathd: shut down 887s Jun 13 19:04:17 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 887s Jun 13 19:04:17 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 887s Jun 13 19:04:17 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 887s Jun 13 19:04:17 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 887s Jun 13 19:04:17 autopkgtest multipathd[6065]: multipathd v0.9.4: start up 887s Jun 13 19:04:17 autopkgtest multipathd[6065]: reconfigure: setting up paths and maps 887s Jun 13 19:04:17 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 887s Check final path status 887s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 887s size=100M features='0' hwhandler='0' wp=rw 887s |-+- policy='service-time 0' prio=1 status=active 887s | `- 1:0:0:1 sdb 8:16 active ready running 887s `-+- policy='service-time 0' prio=1 status=enabled 887s `- 2:0:0:1 sdc 8:32 active ready running 887s + multipath -ll 887s + grep --count status=enabled 887s OK 887s + diske=1 887s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 887s + echo OK 887s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 887s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 887s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 887s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 887s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 887s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 888s autopkgtest [19:06:17]: test tgtbasedmpaths: -----------------------] 891s autopkgtest [19:06:20]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 891s tgtbasedmpaths PASS 891s autopkgtest [19:06:20]: @@@@@@@@@@@@@@@@@@@@ summary 891s kpartx-file-loopback PASS 891s tgtbasedmpaths PASS 913s nova [W] Using flock in scalingstack-bos01-ppc64el 913s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240613-185129-juju-7f2275-prod-proposed-migration-environment-3-6b3cdc04-44ab-4606-a65c-f1ae3d256867 from image adt/ubuntu-oracular-ppc64el-server-20240612.img (UUID 7abe9be2-6b8b-44d9-8daf-bd7bebbc8526)... 913s nova [W] Using flock in scalingstack-bos01-ppc64el 913s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240613-185129-juju-7f2275-prod-proposed-migration-environment-3-6b3cdc04-44ab-4606-a65c-f1ae3d256867 from image adt/ubuntu-oracular-ppc64el-server-20240612.img (UUID 7abe9be2-6b8b-44d9-8daf-bd7bebbc8526)...