0s autopkgtest [18:09:58]: starting date and time: 2024-07-19 18:09:58+0000 0s autopkgtest [18:09:58]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [18:09:58]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.ej0zyvyi/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:linux-meta,src:linux-signed,src:linux --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=linux-meta/6.10.0-15.15 linux-signed/6.10.0-15.15 linux/6.10.0-15.15' --setup-commands 'apt-get install -y ^kernel-testing--linux--full--preferred$ || apt-get install -y ^linux-image$ ^linux-headers$ || apt-get install -y ^linux-image-generic$ ^linux-headers-generic$' --setup-commands 'apt-get install -y ^kernel-testing--linux--modules-extra--preferred$ || apt-get install -y ^linux-modules-extra$ || :' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@lcy02-80.secgroup --name adt-oracular-amd64-multipath-tools-20240719-180958-juju-7f2275-prod-proposed-migration-environment-3-589852d2-27ce-4a37-87c4-56e1b31f5eca --image adt/ubuntu-oracular-amd64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 42s autopkgtest [18:10:40]: testbed dpkg architecture: amd64 42s autopkgtest [18:10:40]: testbed apt version: 2.9.6 42s autopkgtest [18:10:40]: @@@@@@@@@@@@@@@@@@@@ test bed setup 43s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 43s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [372 kB] 43s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 43s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.7 kB] 43s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3232 B] 43s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 Packages [93.7 kB] 43s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main i386 Packages [58.7 kB] 43s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 c-n-f Metadata [2116 B] 43s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted amd64 Packages [34.9 kB] 43s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/restricted i386 Packages [6244 B] 43s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/restricted amd64 c-n-f Metadata [368 B] 43s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/universe i386 Packages [220 kB] 43s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/universe amd64 Packages [391 kB] 43s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/universe amd64 c-n-f Metadata [9900 B] 43s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse amd64 Packages [7996 B] 43s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse i386 Packages [3052 B] 43s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse amd64 c-n-f Metadata [276 B] 44s Fetched 1392 kB in 0s (5434 kB/s) 44s Reading package lists... 45s Reading package lists... 46s Building dependency tree... 46s Reading state information... 46s Calculating upgrade... 46s The following NEW packages will be installed: 46s libpython3.12t64 linux-headers-6.10.0-15 linux-headers-6.10.0-15-generic 46s linux-image-6.10.0-15-generic linux-modules-6.10.0-15-generic 46s linux-modules-extra-6.10.0-15-generic linux-tools-6.10.0-15 46s linux-tools-6.10.0-15-generic 46s The following packages will be upgraded: 46s libxml2 linux-generic linux-headers-generic linux-headers-virtual 46s linux-image-generic linux-image-virtual linux-libc-dev linux-tools-common 46s linux-virtual 46s 9 upgraded, 8 newly installed, 0 to remove and 0 not upgraded. 46s Need to get 196 MB of archives. 46s After this operation, 311 MB of additional disk space will be used. 46s Get:1 http://ftpmaster.internal/ubuntu oracular/main amd64 libxml2 amd64 2.12.7+dfsg-3 [642 kB] 46s Get:2 http://ftpmaster.internal/ubuntu oracular/main amd64 libpython3.12t64 amd64 3.12.4-1ubuntu1 [2341 kB] 46s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-modules-6.10.0-15-generic amd64 6.10.0-15.15 [39.3 MB] 46s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-image-6.10.0-15-generic amd64 6.10.0-15.15 [14.8 MB] 46s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-modules-extra-6.10.0-15-generic amd64 6.10.0-15.15 [114 MB] 47s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-generic amd64 6.10.0-15.15 [1728 B] 47s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-image-generic amd64 6.10.0-15.15 [10.5 kB] 47s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-virtual amd64 6.10.0-15.15 [1722 B] 47s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-image-virtual amd64 6.10.0-15.15 [10.4 kB] 47s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-headers-virtual amd64 6.10.0-15.15 [1644 B] 47s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-headers-6.10.0-15 all 6.10.0-15.15 [13.8 MB] 47s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-headers-6.10.0-15-generic amd64 6.10.0-15.15 [3760 kB] 47s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-headers-generic amd64 6.10.0-15.15 [10.3 kB] 47s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-libc-dev amd64 6.10.0-15.15 [1642 kB] 47s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-tools-common all 6.10.0-15.15 [474 kB] 47s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-tools-6.10.0-15 amd64 6.10.0-15.15 [5018 kB] 47s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-tools-6.10.0-15-generic amd64 6.10.0-15.15 [1802 B] 48s Fetched 196 MB in 1s (153 MB/s) 48s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 74486 files and directories currently installed.) 48s Preparing to unpack .../00-libxml2_2.12.7+dfsg-3_amd64.deb ... 48s Unpacking libxml2:amd64 (2.12.7+dfsg-3) over (2.9.14+dfsg-1.3ubuntu3) ... 48s Selecting previously unselected package libpython3.12t64:amd64. 48s Preparing to unpack .../01-libpython3.12t64_3.12.4-1ubuntu1_amd64.deb ... 48s Unpacking libpython3.12t64:amd64 (3.12.4-1ubuntu1) ... 48s Selecting previously unselected package linux-modules-6.10.0-15-generic. 48s Preparing to unpack .../02-linux-modules-6.10.0-15-generic_6.10.0-15.15_amd64.deb ... 48s Unpacking linux-modules-6.10.0-15-generic (6.10.0-15.15) ... 48s Selecting previously unselected package linux-image-6.10.0-15-generic. 48s Preparing to unpack .../03-linux-image-6.10.0-15-generic_6.10.0-15.15_amd64.deb ... 48s Unpacking linux-image-6.10.0-15-generic (6.10.0-15.15) ... 48s Selecting previously unselected package linux-modules-extra-6.10.0-15-generic. 48s Preparing to unpack .../04-linux-modules-extra-6.10.0-15-generic_6.10.0-15.15_amd64.deb ... 48s Unpacking linux-modules-extra-6.10.0-15-generic (6.10.0-15.15) ... 50s Preparing to unpack .../05-linux-generic_6.10.0-15.15_amd64.deb ... 50s Unpacking linux-generic (6.10.0-15.15) over (6.8.0-31.31) ... 50s Preparing to unpack .../06-linux-image-generic_6.10.0-15.15_amd64.deb ... 50s Unpacking linux-image-generic (6.10.0-15.15) over (6.8.0-31.31) ... 50s Preparing to unpack .../07-linux-virtual_6.10.0-15.15_amd64.deb ... 50s Unpacking linux-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 50s Preparing to unpack .../08-linux-image-virtual_6.10.0-15.15_amd64.deb ... 50s Unpacking linux-image-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 50s Preparing to unpack .../09-linux-headers-virtual_6.10.0-15.15_amd64.deb ... 50s Unpacking linux-headers-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 50s Selecting previously unselected package linux-headers-6.10.0-15. 50s Preparing to unpack .../10-linux-headers-6.10.0-15_6.10.0-15.15_all.deb ... 50s Unpacking linux-headers-6.10.0-15 (6.10.0-15.15) ... 52s Selecting previously unselected package linux-headers-6.10.0-15-generic. 53s Preparing to unpack .../11-linux-headers-6.10.0-15-generic_6.10.0-15.15_amd64.deb ... 53s Unpacking linux-headers-6.10.0-15-generic (6.10.0-15.15) ... 54s Preparing to unpack .../12-linux-headers-generic_6.10.0-15.15_amd64.deb ... 54s Unpacking linux-headers-generic (6.10.0-15.15) over (6.8.0-31.31) ... 54s Preparing to unpack .../13-linux-libc-dev_6.10.0-15.15_amd64.deb ... 54s Unpacking linux-libc-dev:amd64 (6.10.0-15.15) over (6.8.0-31.31) ... 54s Preparing to unpack .../14-linux-tools-common_6.10.0-15.15_all.deb ... 54s Unpacking linux-tools-common (6.10.0-15.15) over (6.8.0-31.31) ... 54s Selecting previously unselected package linux-tools-6.10.0-15. 54s Preparing to unpack .../15-linux-tools-6.10.0-15_6.10.0-15.15_amd64.deb ... 54s Unpacking linux-tools-6.10.0-15 (6.10.0-15.15) ... 54s Selecting previously unselected package linux-tools-6.10.0-15-generic. 54s Preparing to unpack .../16-linux-tools-6.10.0-15-generic_6.10.0-15.15_amd64.deb ... 54s Unpacking linux-tools-6.10.0-15-generic (6.10.0-15.15) ... 54s Setting up linux-headers-6.10.0-15 (6.10.0-15.15) ... 54s Setting up linux-headers-6.10.0-15-generic (6.10.0-15.15) ... 54s Setting up linux-libc-dev:amd64 (6.10.0-15.15) ... 54s Setting up linux-headers-generic (6.10.0-15.15) ... 54s Setting up libpython3.12t64:amd64 (3.12.4-1ubuntu1) ... 54s Setting up linux-modules-6.10.0-15-generic (6.10.0-15.15) ... 56s Setting up linux-tools-common (6.10.0-15.15) ... 56s Setting up libxml2:amd64 (2.12.7+dfsg-3) ... 56s Setting up linux-modules-extra-6.10.0-15-generic (6.10.0-15.15) ... 59s Setting up linux-image-6.10.0-15-generic (6.10.0-15.15) ... 60s I: /boot/vmlinuz is now a symlink to vmlinuz-6.10.0-15-generic 60s I: /boot/initrd.img is now a symlink to initrd.img-6.10.0-15-generic 60s Setting up linux-headers-virtual (6.10.0-15.15) ... 60s Setting up linux-tools-6.10.0-15 (6.10.0-15.15) ... 60s Setting up linux-image-virtual (6.10.0-15.15) ... 60s Setting up linux-image-generic (6.10.0-15.15) ... 60s Setting up linux-generic (6.10.0-15.15) ... 60s Setting up linux-virtual (6.10.0-15.15) ... 60s Setting up linux-tools-6.10.0-15-generic (6.10.0-15.15) ... 60s Processing triggers for man-db (2.12.1-2) ... 61s Processing triggers for libc-bin (2.39-0ubuntu9) ... 61s Processing triggers for linux-image-6.10.0-15-generic (6.10.0-15.15) ... 61s /etc/kernel/postinst.d/initramfs-tools: 61s update-initramfs: Generating /boot/initrd.img-6.10.0-15-generic 62s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 70s /etc/kernel/postinst.d/zz-update-grub: 70s Sourcing file `/etc/default/grub' 70s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 70s Sourcing file `/etc/default/grub.d/90-autopkgtest.cfg' 70s Generating grub configuration file ... 70s Found linux image: /boot/vmlinuz-6.10.0-15-generic 70s Found initrd image: /boot/initrd.img-6.10.0-15-generic 70s Found linux image: /boot/vmlinuz-6.8.0-31-generic 70s Found initrd image: /boot/initrd.img-6.8.0-31-generic 70s Warning: os-prober will not be executed to detect other bootable partitions. 70s Systems on them will not be added to the GRUB boot configuration. 70s Check GRUB_DISABLE_OS_PROBER documentation entry. 70s Adding boot menu entry for UEFI Firmware Settings ... 70s done 71s Reading package lists... 71s Building dependency tree... 71s Reading state information... 71s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 71s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 71s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 71s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 71s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 72s Reading package lists... 72s Reading package lists... 73s Building dependency tree... 73s Reading state information... 73s Calculating upgrade... 73s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 73s Reading package lists... 74s Building dependency tree... 74s Reading state information... 74s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 74s Reading package lists... 74s Building dependency tree... 74s Reading state information... 75s linux-generic is already the newest version (6.10.0-15.15). 75s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 75s Reading package lists... 75s Building dependency tree... 75s Reading state information... 75s E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 75s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 75s Reading package lists... 75s Building dependency tree... 75s Reading state information... 76s E: Unable to locate package ^linux-modules-extra$ 76s E: Couldn't find any package by regex '^linux-modules-extra$' 76s autopkgtest [18:11:14]: rebooting testbed after setup commands that affected boot 79s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 90s autopkgtest [18:11:28]: testbed running kernel: Linux 6.10.0-15-generic #15-Ubuntu SMP PREEMPT_DYNAMIC Thu Jul 4 11:50:02 UTC 2024 91s autopkgtest [18:11:29]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 92s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 92s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 92s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 93s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 93s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 93s gpgv: issuer "steve.langasek@ubuntu.com" 93s gpgv: Can't check signature: No public key 93s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 93s autopkgtest [18:11:31]: testing package multipath-tools version 0.9.4-5ubuntu8 93s autopkgtest [18:11:31]: build not needed 93s autopkgtest [18:11:31]: test kpartx-file-loopback: preparing testbed 93s Reading package lists... 94s Building dependency tree... 94s Reading state information... 94s Starting pkgProblemResolver with broken count: 0 94s Starting 2 pkgProblemResolver with broken count: 0 94s Done 94s The following additional packages will be installed: 94s liburing2 qemu-utils 94s Recommended packages: 94s qemu-block-extra 94s The following NEW packages will be installed: 94s autopkgtest-satdep liburing2 qemu-utils 95s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 95s Need to get 2240 kB/2241 kB of archives. 95s After this operation, 11.4 MB of additional disk space will be used. 95s Get:1 /tmp/autopkgtest.ETBuB0/1-autopkgtest-satdep.deb autopkgtest-satdep amd64 0 [720 B] 95s Get:2 http://ftpmaster.internal/ubuntu oracular/main amd64 liburing2 amd64 2.6-1 [22.3 kB] 95s Get:3 http://ftpmaster.internal/ubuntu oracular/main amd64 qemu-utils amd64 1:8.2.2+ds-0ubuntu1 [2218 kB] 95s Fetched 2240 kB in 0s (20.8 MB/s) 95s Selecting previously unselected package liburing2:amd64. 95s (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 ... 112888 files and directories currently installed.) 95s Preparing to unpack .../liburing2_2.6-1_amd64.deb ... 95s Unpacking liburing2:amd64 (2.6-1) ... 95s Selecting previously unselected package qemu-utils. 95s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_amd64.deb ... 95s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 95s Selecting previously unselected package autopkgtest-satdep. 95s Preparing to unpack .../1-autopkgtest-satdep.deb ... 95s Unpacking autopkgtest-satdep (0) ... 95s Setting up liburing2:amd64 (2.6-1) ... 95s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 95s Setting up autopkgtest-satdep (0) ... 95s Processing triggers for man-db (2.12.1-2) ... 96s Processing triggers for libc-bin (2.39-0ubuntu9) ... 99s (Reading database ... 112908 files and directories currently installed.) 99s Removing autopkgtest-satdep (0) ... 99s autopkgtest [18:11:37]: test kpartx-file-loopback: [----------------------- 99s Formatting 'foo.img', fmt=raw size=20971520 100s Creating new GPT entries in memory. 100s Warning: The kernel is still using the old partition table. 100s The new table will be used at the next reboot or after you 100s run partprobe(8) or kpartx(8) 100s The operation has completed successfully. 100s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 100s standard_filename: OK 100s del devmap : loop0p1 100s No devices found 100s standard_filename_cleanup: OK 100s Formatting 'fou du FaFa.img', fmt=raw size=20971520 101s Creating new GPT entries in memory. 101s Warning: The kernel is still using the old partition table. 101s The new table will be used at the next reboot or after you 101s run partprobe(8) or kpartx(8) 101s The operation has completed successfully. 101s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 101s filename_with_spaces: OK 101s del devmap : loop0p1 101s No devices found 101s filename_with_spaces_cleanup: OK 101s autopkgtest [18:11:39]: test kpartx-file-loopback: -----------------------] 102s autopkgtest [18:11:40]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 102s kpartx-file-loopback PASS 102s autopkgtest [18:11:40]: test tgtbasedmpaths: preparing testbed 158s autopkgtest [18:12:36]: testbed dpkg architecture: amd64 158s autopkgtest [18:12:36]: testbed apt version: 2.9.6 158s autopkgtest [18:12:36]: @@@@@@@@@@@@@@@@@@@@ test bed setup 159s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 159s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3232 B] 159s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.7 kB] 159s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 159s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [372 kB] 159s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 Packages [93.7 kB] 159s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main i386 Packages [58.7 kB] 159s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 c-n-f Metadata [2116 B] 159s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted i386 Packages [6244 B] 159s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/restricted amd64 Packages [34.9 kB] 159s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/restricted amd64 c-n-f Metadata [368 B] 159s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/universe i386 Packages [220 kB] 159s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/universe amd64 Packages [391 kB] 159s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/universe amd64 c-n-f Metadata [9900 B] 159s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse i386 Packages [3052 B] 159s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse amd64 Packages [7996 B] 159s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse amd64 c-n-f Metadata [276 B] 160s Fetched 1392 kB in 0s (6015 kB/s) 160s Reading package lists... 161s Reading package lists... 161s Building dependency tree... 161s Reading state information... 162s Calculating upgrade... 162s The following NEW packages will be installed: 162s libpython3.12t64 linux-headers-6.10.0-15 linux-headers-6.10.0-15-generic 162s linux-image-6.10.0-15-generic linux-modules-6.10.0-15-generic 162s linux-modules-extra-6.10.0-15-generic linux-tools-6.10.0-15 162s linux-tools-6.10.0-15-generic 162s The following packages will be upgraded: 162s libxml2 linux-generic linux-headers-generic linux-headers-virtual 162s linux-image-generic linux-image-virtual linux-libc-dev linux-tools-common 162s linux-virtual 162s 9 upgraded, 8 newly installed, 0 to remove and 0 not upgraded. 162s Need to get 196 MB of archives. 162s After this operation, 311 MB of additional disk space will be used. 162s Get:1 http://ftpmaster.internal/ubuntu oracular/main amd64 libxml2 amd64 2.12.7+dfsg-3 [642 kB] 162s Get:2 http://ftpmaster.internal/ubuntu oracular/main amd64 libpython3.12t64 amd64 3.12.4-1ubuntu1 [2341 kB] 162s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-modules-6.10.0-15-generic amd64 6.10.0-15.15 [39.3 MB] 162s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-image-6.10.0-15-generic amd64 6.10.0-15.15 [14.8 MB] 162s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-modules-extra-6.10.0-15-generic amd64 6.10.0-15.15 [114 MB] 163s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-generic amd64 6.10.0-15.15 [1728 B] 163s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-image-generic amd64 6.10.0-15.15 [10.5 kB] 163s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-virtual amd64 6.10.0-15.15 [1722 B] 163s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-image-virtual amd64 6.10.0-15.15 [10.4 kB] 163s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-headers-virtual amd64 6.10.0-15.15 [1644 B] 163s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-headers-6.10.0-15 all 6.10.0-15.15 [13.8 MB] 163s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-headers-6.10.0-15-generic amd64 6.10.0-15.15 [3760 kB] 163s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-headers-generic amd64 6.10.0-15.15 [10.3 kB] 163s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-libc-dev amd64 6.10.0-15.15 [1642 kB] 163s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-tools-common all 6.10.0-15.15 [474 kB] 164s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-tools-6.10.0-15 amd64 6.10.0-15.15 [5018 kB] 164s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main amd64 linux-tools-6.10.0-15-generic amd64 6.10.0-15.15 [1802 B] 164s Fetched 196 MB in 1s (131 MB/s) 164s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 74486 files and directories currently installed.) 164s Preparing to unpack .../00-libxml2_2.12.7+dfsg-3_amd64.deb ... 164s Unpacking libxml2:amd64 (2.12.7+dfsg-3) over (2.9.14+dfsg-1.3ubuntu3) ... 164s Selecting previously unselected package libpython3.12t64:amd64. 164s Preparing to unpack .../01-libpython3.12t64_3.12.4-1ubuntu1_amd64.deb ... 164s Unpacking libpython3.12t64:amd64 (3.12.4-1ubuntu1) ... 164s Selecting previously unselected package linux-modules-6.10.0-15-generic. 164s Preparing to unpack .../02-linux-modules-6.10.0-15-generic_6.10.0-15.15_amd64.deb ... 164s Unpacking linux-modules-6.10.0-15-generic (6.10.0-15.15) ... 165s Selecting previously unselected package linux-image-6.10.0-15-generic. 165s Preparing to unpack .../03-linux-image-6.10.0-15-generic_6.10.0-15.15_amd64.deb ... 165s Unpacking linux-image-6.10.0-15-generic (6.10.0-15.15) ... 165s Selecting previously unselected package linux-modules-extra-6.10.0-15-generic. 165s Preparing to unpack .../04-linux-modules-extra-6.10.0-15-generic_6.10.0-15.15_amd64.deb ... 165s Unpacking linux-modules-extra-6.10.0-15-generic (6.10.0-15.15) ... 166s Preparing to unpack .../05-linux-generic_6.10.0-15.15_amd64.deb ... 166s Unpacking linux-generic (6.10.0-15.15) over (6.8.0-31.31) ... 166s Preparing to unpack .../06-linux-image-generic_6.10.0-15.15_amd64.deb ... 166s Unpacking linux-image-generic (6.10.0-15.15) over (6.8.0-31.31) ... 166s Preparing to unpack .../07-linux-virtual_6.10.0-15.15_amd64.deb ... 166s Unpacking linux-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 166s Preparing to unpack .../08-linux-image-virtual_6.10.0-15.15_amd64.deb ... 166s Unpacking linux-image-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 166s Preparing to unpack .../09-linux-headers-virtual_6.10.0-15.15_amd64.deb ... 166s Unpacking linux-headers-virtual (6.10.0-15.15) over (6.8.0-31.31) ... 166s Selecting previously unselected package linux-headers-6.10.0-15. 166s Preparing to unpack .../10-linux-headers-6.10.0-15_6.10.0-15.15_all.deb ... 166s Unpacking linux-headers-6.10.0-15 (6.10.0-15.15) ... 169s Selecting previously unselected package linux-headers-6.10.0-15-generic. 169s Preparing to unpack .../11-linux-headers-6.10.0-15-generic_6.10.0-15.15_amd64.deb ... 169s Unpacking linux-headers-6.10.0-15-generic (6.10.0-15.15) ... 170s Preparing to unpack .../12-linux-headers-generic_6.10.0-15.15_amd64.deb ... 170s Unpacking linux-headers-generic (6.10.0-15.15) over (6.8.0-31.31) ... 170s Preparing to unpack .../13-linux-libc-dev_6.10.0-15.15_amd64.deb ... 170s Unpacking linux-libc-dev:amd64 (6.10.0-15.15) over (6.8.0-31.31) ... 171s Preparing to unpack .../14-linux-tools-common_6.10.0-15.15_all.deb ... 171s Unpacking linux-tools-common (6.10.0-15.15) over (6.8.0-31.31) ... 171s Selecting previously unselected package linux-tools-6.10.0-15. 171s Preparing to unpack .../15-linux-tools-6.10.0-15_6.10.0-15.15_amd64.deb ... 171s Unpacking linux-tools-6.10.0-15 (6.10.0-15.15) ... 171s Selecting previously unselected package linux-tools-6.10.0-15-generic. 171s Preparing to unpack .../16-linux-tools-6.10.0-15-generic_6.10.0-15.15_amd64.deb ... 171s Unpacking linux-tools-6.10.0-15-generic (6.10.0-15.15) ... 171s Setting up linux-headers-6.10.0-15 (6.10.0-15.15) ... 171s Setting up linux-headers-6.10.0-15-generic (6.10.0-15.15) ... 171s Setting up linux-libc-dev:amd64 (6.10.0-15.15) ... 171s Setting up linux-headers-generic (6.10.0-15.15) ... 171s Setting up libpython3.12t64:amd64 (3.12.4-1ubuntu1) ... 171s Setting up linux-modules-6.10.0-15-generic (6.10.0-15.15) ... 173s Setting up linux-tools-common (6.10.0-15.15) ... 173s Setting up libxml2:amd64 (2.12.7+dfsg-3) ... 173s Setting up linux-modules-extra-6.10.0-15-generic (6.10.0-15.15) ... 175s Setting up linux-image-6.10.0-15-generic (6.10.0-15.15) ... 177s I: /boot/vmlinuz is now a symlink to vmlinuz-6.10.0-15-generic 177s I: /boot/initrd.img is now a symlink to initrd.img-6.10.0-15-generic 177s Setting up linux-headers-virtual (6.10.0-15.15) ... 177s Setting up linux-tools-6.10.0-15 (6.10.0-15.15) ... 177s Setting up linux-image-virtual (6.10.0-15.15) ... 177s Setting up linux-image-generic (6.10.0-15.15) ... 177s Setting up linux-generic (6.10.0-15.15) ... 177s Setting up linux-virtual (6.10.0-15.15) ... 177s Setting up linux-tools-6.10.0-15-generic (6.10.0-15.15) ... 177s Processing triggers for man-db (2.12.1-2) ... 178s Processing triggers for libc-bin (2.39-0ubuntu9) ... 178s Processing triggers for linux-image-6.10.0-15-generic (6.10.0-15.15) ... 178s /etc/kernel/postinst.d/initramfs-tools: 178s update-initramfs: Generating /boot/initrd.img-6.10.0-15-generic 178s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 186s /etc/kernel/postinst.d/zz-update-grub: 186s Sourcing file `/etc/default/grub' 186s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 186s Sourcing file `/etc/default/grub.d/90-autopkgtest.cfg' 186s Generating grub configuration file ... 187s Found linux image: /boot/vmlinuz-6.10.0-15-generic 187s Found initrd image: /boot/initrd.img-6.10.0-15-generic 187s Found linux image: /boot/vmlinuz-6.8.0-31-generic 187s Found initrd image: /boot/initrd.img-6.8.0-31-generic 187s Warning: os-prober will not be executed to detect other bootable partitions. 187s Systems on them will not be added to the GRUB boot configuration. 187s Check GRUB_DISABLE_OS_PROBER documentation entry. 187s Adding boot menu entry for UEFI Firmware Settings ... 187s done 187s Reading package lists... 188s Building dependency tree... 188s Reading state information... 188s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 188s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 188s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 188s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 188s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 189s Reading package lists... 189s Reading package lists... 189s Building dependency tree... 189s Reading state information... 190s Calculating upgrade... 190s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 190s Reading package lists... 190s Building dependency tree... 190s Reading state information... 191s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 191s Reading package lists... 191s Building dependency tree... 191s Reading state information... 191s linux-generic is already the newest version (6.10.0-15.15). 191s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 191s Reading package lists... 192s Building dependency tree... 192s Reading state information... 192s E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 192s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 192s Reading package lists... 192s Building dependency tree... 192s Reading state information... 192s E: Unable to locate package ^linux-modules-extra$ 192s E: Couldn't find any package by regex '^linux-modules-extra$' 192s autopkgtest [18:13:10]: rebooting testbed after setup commands that affected boot 196s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 208s Reading package lists... 209s Building dependency tree... 209s Reading state information... 209s Starting pkgProblemResolver with broken count: 0 209s Starting 2 pkgProblemResolver with broken count: 0 209s Done 209s The following additional packages will be installed: 209s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 209s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 209s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 209s librdmacm1t64 lsscsi open-iscsi tgt 209s Suggested packages: 209s fio-examples gnuplot tgt-glusterfs tgt-rbd 209s Recommended packages: 209s finalrd 209s The following NEW packages will be installed: 209s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 209s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 209s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 209s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 209s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 209s Need to get 10.0 MB/10.0 MB of archives. 209s After this operation, 42.9 MB of additional disk space will be used. 209s Get:1 /tmp/autopkgtest.ETBuB0/2-autopkgtest-satdep.deb autopkgtest-satdep amd64 0 [728 B] 209s Get:2 http://ftpmaster.internal/ubuntu oracular/main amd64 libopeniscsiusr amd64 2.1.10-1ubuntu1 [49.7 kB] 209s Get:3 http://ftpmaster.internal/ubuntu oracular/main amd64 libisns0t64 amd64 0.101-1 [94.2 kB] 209s Get:4 http://ftpmaster.internal/ubuntu oracular/main amd64 open-iscsi amd64 2.1.10-1ubuntu1 [326 kB] 209s Get:5 http://ftpmaster.internal/ubuntu oracular/main amd64 librdmacm1t64 amd64 52.0-2 [70.7 kB] 209s Get:6 http://ftpmaster.internal/ubuntu oracular/universe amd64 libconfig-general-perl all 2.65-2 [57.1 kB] 209s Get:7 http://ftpmaster.internal/ubuntu oracular/universe amd64 tgt amd64 1:1.0.85-1.2ubuntu1 [234 kB] 209s Get:8 http://ftpmaster.internal/ubuntu oracular/universe amd64 libgfxdr0 amd64 11.1-4ubuntu1 [20.1 kB] 209s Get:9 http://ftpmaster.internal/ubuntu oracular/universe amd64 libglusterfs0 amd64 11.1-4ubuntu1 [266 kB] 209s Get:10 http://ftpmaster.internal/ubuntu oracular/universe amd64 libgfrpc0 amd64 11.1-4ubuntu1 [40.7 kB] 209s Get:11 http://ftpmaster.internal/ubuntu oracular/universe amd64 libgfapi0 amd64 11.1-4ubuntu1 [79.6 kB] 209s Get:12 http://ftpmaster.internal/ubuntu oracular/universe amd64 libnbd0 amd64 1.20.2-1 [94.1 kB] 209s Get:13 http://ftpmaster.internal/ubuntu oracular/main amd64 libdaxctl1 amd64 77-2ubuntu2 [21.4 kB] 209s Get:14 http://ftpmaster.internal/ubuntu oracular/main amd64 libndctl6 amd64 77-2ubuntu2 [62.8 kB] 209s Get:15 http://ftpmaster.internal/ubuntu oracular/main amd64 libpmem1 amd64 1.13.1-1.1ubuntu2 [84.8 kB] 209s Get:16 http://ftpmaster.internal/ubuntu oracular/main amd64 libboost-iostreams1.83.0 amd64 1.83.0-3ubuntu1 [259 kB] 209s Get:17 http://ftpmaster.internal/ubuntu oracular/main amd64 libboost-thread1.83.0 amd64 1.83.0-3ubuntu1 [276 kB] 209s Get:18 http://ftpmaster.internal/ubuntu oracular/main amd64 librados2 amd64 19.2.0~git20240301.4c76c50-0ubuntu7 [3915 kB] 210s Get:19 http://ftpmaster.internal/ubuntu oracular/main amd64 libpmemobj1 amd64 1.13.1-1.1ubuntu2 [116 kB] 210s Get:20 http://ftpmaster.internal/ubuntu oracular/main amd64 librbd1 amd64 19.2.0~git20240301.4c76c50-0ubuntu7 [3327 kB] 210s Get:21 http://ftpmaster.internal/ubuntu oracular/universe amd64 fio amd64 3.37-1 [594 kB] 210s Get:22 http://ftpmaster.internal/ubuntu oracular/main amd64 lsscsi amd64 0.32-1build1 [48.2 kB] 210s Preconfiguring packages ... 210s Fetched 10.0 MB in 0s (53.4 MB/s) 210s Selecting previously unselected package libopeniscsiusr. 210s (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 ... 112888 files and directories currently installed.) 210s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_amd64.deb ... 210s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 210s Selecting previously unselected package libisns0t64:amd64. 210s Preparing to unpack .../01-libisns0t64_0.101-1_amd64.deb ... 210s Unpacking libisns0t64:amd64 (0.101-1) ... 210s Selecting previously unselected package open-iscsi. 210s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_amd64.deb ... 211s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 211s Selecting previously unselected package librdmacm1t64:amd64. 211s Preparing to unpack .../03-librdmacm1t64_52.0-2_amd64.deb ... 211s Unpacking librdmacm1t64:amd64 (52.0-2) ... 211s Selecting previously unselected package libconfig-general-perl. 211s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 211s Unpacking libconfig-general-perl (2.65-2) ... 211s Selecting previously unselected package tgt. 211s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_amd64.deb ... 211s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 211s Selecting previously unselected package libgfxdr0:amd64. 211s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_amd64.deb ... 211s Unpacking libgfxdr0:amd64 (11.1-4ubuntu1) ... 211s Selecting previously unselected package libglusterfs0:amd64. 211s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_amd64.deb ... 211s Unpacking libglusterfs0:amd64 (11.1-4ubuntu1) ... 211s Selecting previously unselected package libgfrpc0:amd64. 211s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_amd64.deb ... 211s Unpacking libgfrpc0:amd64 (11.1-4ubuntu1) ... 211s Selecting previously unselected package libgfapi0:amd64. 211s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_amd64.deb ... 211s Unpacking libgfapi0:amd64 (11.1-4ubuntu1) ... 211s Selecting previously unselected package libnbd0. 211s Preparing to unpack .../10-libnbd0_1.20.2-1_amd64.deb ... 211s Unpacking libnbd0 (1.20.2-1) ... 211s Selecting previously unselected package libdaxctl1:amd64. 211s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_amd64.deb ... 211s Unpacking libdaxctl1:amd64 (77-2ubuntu2) ... 211s Selecting previously unselected package libndctl6:amd64. 211s Preparing to unpack .../12-libndctl6_77-2ubuntu2_amd64.deb ... 211s Unpacking libndctl6:amd64 (77-2ubuntu2) ... 211s Selecting previously unselected package libpmem1:amd64. 211s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_amd64.deb ... 211s Unpacking libpmem1:amd64 (1.13.1-1.1ubuntu2) ... 211s Selecting previously unselected package libboost-iostreams1.83.0:amd64. 211s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_amd64.deb ... 211s Unpacking libboost-iostreams1.83.0:amd64 (1.83.0-3ubuntu1) ... 211s Selecting previously unselected package libboost-thread1.83.0:amd64. 211s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_amd64.deb ... 211s Unpacking libboost-thread1.83.0:amd64 (1.83.0-3ubuntu1) ... 211s Selecting previously unselected package librados2. 211s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_amd64.deb ... 211s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 211s Selecting previously unselected package libpmemobj1:amd64. 211s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_amd64.deb ... 211s Unpacking libpmemobj1:amd64 (1.13.1-1.1ubuntu2) ... 211s Selecting previously unselected package librbd1. 211s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_amd64.deb ... 211s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 211s Selecting previously unselected package fio. 211s Preparing to unpack .../19-fio_3.37-1_amd64.deb ... 211s Unpacking fio (3.37-1) ... 211s Selecting previously unselected package lsscsi. 211s Preparing to unpack .../20-lsscsi_0.32-1build1_amd64.deb ... 211s Unpacking lsscsi (0.32-1build1) ... 211s Selecting previously unselected package autopkgtest-satdep. 211s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 211s Unpacking autopkgtest-satdep (0) ... 211s Setting up libconfig-general-perl (2.65-2) ... 211s Setting up libisns0t64:amd64 (0.101-1) ... 211s Setting up libboost-thread1.83.0:amd64 (1.83.0-3ubuntu1) ... 211s Setting up libnbd0 (1.20.2-1) ... 211s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 211s Setting up libglusterfs0:amd64 (11.1-4ubuntu1) ... 211s Setting up libboost-iostreams1.83.0:amd64 (1.83.0-3ubuntu1) ... 211s Setting up lsscsi (0.32-1build1) ... 211s Setting up libdaxctl1:amd64 (77-2ubuntu2) ... 211s Setting up libndctl6:amd64 (77-2ubuntu2) ... 211s Setting up librdmacm1t64:amd64 (52.0-2) ... 211s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 212s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 212s Setting up libpmem1:amd64 (1.13.1-1.1ubuntu2) ... 212s Setting up libgfxdr0:amd64 (11.1-4ubuntu1) ... 212s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 212s Setting up open-iscsi (2.1.10-1ubuntu1) ... 213s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 214s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 214s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 214s Setting up libpmemobj1:amd64 (1.13.1-1.1ubuntu2) ... 214s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 214s Setting up libgfrpc0:amd64 (11.1-4ubuntu1) ... 214s Setting up libgfapi0:amd64 (11.1-4ubuntu1) ... 214s Setting up fio (3.37-1) ... 214s Setting up autopkgtest-satdep (0) ... 214s Processing triggers for man-db (2.12.1-2) ... 216s Processing triggers for initramfs-tools (0.142ubuntu30) ... 216s update-initramfs: Generating /boot/initrd.img-6.10.0-15-generic 216s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 224s Processing triggers for libc-bin (2.39-0ubuntu9) ... 226s (Reading database ... 113129 files and directories currently installed.) 226s Removing autopkgtest-satdep (0) ... 227s autopkgtest [18:13:45]: test tgtbasedmpaths: [----------------------- 227s + targetname=iqn.2016-11.foo.com:target.iscsi 227s + pwd 227s + cwd=/tmp/autopkgtest.ETBuB0/build.zIz/src 227s + testdir=/mnt/tgtmpathtest 227s + localhost=127.0.0.1 227s + portal=127.0.0.1:3260 227s + maxpaths=4 227s + backfn=backingfile 227s + expectwwid=60000000000000000e00000000010001 227s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 227s + bglog=/tmp/autopkgtest.ETBuB0/tgtbasedmpaths-artifacts/test-background.log 227s + fioprep=/tmp/autopkgtest.ETBuB0/tgtbasedmpaths-artifacts/path-change-prep.fio 227s + fiovrfy=/tmp/autopkgtest.ETBuB0/tgtbasedmpaths-artifacts/path-change-check.fio 227s + service tgt restart 227s + truncate --size 100M backingfile 227s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 227s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 227s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.ETBuB0/build.zIz/src/backingfile 227s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 227s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 227s login #1 227s + echo login #1 227s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 227s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 227s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 227s + seq 2 4 227s + echo extra login #2 227s + iscsiadm --mode session -r 1 --op new 227s extra login #2 227s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 227s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 227s + echo extra login #3 227s + iscsiadm --mode session -r 1 --op new 227s extra login #3 227s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 227s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 227s + echo extra login #4 227s + iscsiadm --mode session -r 1 --op new 227s extra login #4 227s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 227s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 227s + udevadm settle 228s + sleep 5 233s Status after initial setup 233s + echo Status after initial setup 233s + tgtadm --lld iscsi --mode target --op show 233s Target 1: iqn.2016-11.foo.com:target.iscsi 233s System information: 233s Driver: iscsi 233s State: ready 233s I_T nexus information: 233s I_T nexus: 1 233s Initiator: iqn.2004-10.com.ubuntu:01:8b0adb0f7a2 alias: autopkgtest 233s Connection: 0 233s IP Address: 127.0.0.1 233s I_T nexus: 2 233s Initiator: iqn.2004-10.com.ubuntu:01:8b0adb0f7a2 alias: autopkgtest 233s Connection: 0 233s IP Address: 127.0.0.1 233s I_T nexus: 3 233s Initiator: iqn.2004-10.com.ubuntu:01:8b0adb0f7a2 alias: autopkgtest 233s Connection: 0 233s IP Address: 127.0.0.1 233s I_T nexus: 4 233s Initiator: iqn.2004-10.com.ubuntu:01:8b0adb0f7a2 alias: autopkgtest 233s Connection: 0 233s IP Address: 127.0.0.1 233s LUN information: 233s LUN: 0 233s Type: controller 233s SCSI ID: IET 00010000 233s SCSI SN: beaf10 233s Size: 0 MB, Block size: 1 233s Online: Yes 233s Removable media: No 233s Prevent removal: No 233s Readonly: No 233s SWP: No 233s Thin-provisioning: No 233s Backing store type: null 233s Backing store path: None 233s Backing store flags: 233s LUN: 1 233s Type: disk 233s SCSI ID: IET 00010001 233s SCSI SN: beaf11 233s Size: 105 MB, Block size: 512 233s Online: Yes 233s Removable media: No 233s Prevent removal: No 233s Readonly: No 233s SWP: No 233s Thin-provisioning: No 233s Backing store type: rdwr 233s Backing store path: /tmp/autopkgtest.ETBuB0/build.zIz/src/backingfile 233s Backing store flags: 233s Account information: 233s ACL information: 233s ALL 233s + tgtadm --lld iscsi --op show --mode conn --tid 1 233s Session: 4 233s Connection: 0 233s Initiator: iqn.2004-10.com.ubuntu:01:8b0adb0f7a2 233s IP Address: 127.0.0.1 233s Session: 3 233s Connection: 0 233s Initiator: iqn.2004-10.com.ubuntu:01:8b0adb0f7a2 233s IP Address: 127.0.0.1 233s Session: 2 233s Connection: 0 233s Initiator: iqn.2004-10.com.ubuntu:01:8b0adb0f7a2 233s IP Address: 127.0.0.1 233s Session: 1 233s Connection: 0 233s Initiator: iqn.2004-10.com.ubuntu:01:8b0adb0f7a2 233s IP Address: 127.0.0.1 233s + iscsiadm --mode session -P 1 233s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 233s Current Portal: 127.0.0.1:3260,1 233s Persistent Portal: 127.0.0.1:3260,1 233s ********** 233s Interface: 233s ********** 233s Iface Name: default 233s Iface Transport: tcp 233s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:8b0adb0f7a2 233s Iface IPaddress: 127.0.0.1 233s Iface HWaddress: default 233s Iface Netdev: default 233s SID: 1 233s iSCSI Connection State: LOGGED IN 233s iSCSI Session State: LOGGED_IN 233s Internal iscsid Session State: NO CHANGE 233s 233s ********** 233s Interface: 233s ********** 233s Iface Name: default 233s Iface Transport: tcp 233s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:8b0adb0f7a2 233s Iface IPaddress: 127.0.0.1 233s Iface HWaddress: default 233s Iface Netdev: default 233s SID: 2 233s iSCSI Connection State: LOGGED IN 233s iSCSI Session State: LOGGED_IN 233s Internal iscsid Session State: NO CHANGE 233s 233s ********** 233s Interface: 233s ********** 233s Iface Name: default 233s Iface Transport: tcp 233s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:8b0adb0f7a2 233s Iface IPaddress: 127.0.0.1 233s Iface HWaddress: default 233s Iface Netdev: default 233s SID: 3 233s iSCSI Connection State: LOGGED IN 233s iSCSI Session State: LOGGED_IN 233s Internal iscsid Session State: NO CHANGE 233s 233s ********** 233s Interface: 233s ********** 233s Iface Name: default 233s Iface Transport: tcp 233s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:8b0adb0f7a2 233s Iface IPaddress: 127.0.0.1 233s Iface HWaddress: default 233s Iface Netdev: default 233s SID: 4 233s iSCSI Connection State: LOGGED IN 233s iSCSI Session State: LOGGED_IN 233s Internal iscsid Session State: NO CHANGE 233s + lsscsi -liv 233s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 233s + multipath -v3 -ll 233s [2:0:0:0] storage IET Controller 0001 - - 233s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 233s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session1/target2:0:0/2:0:0:0] 233s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 233s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 233s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session1/target2:0:0/2:0:0:1] 233s [3:0:0:0] storage IET Controller 0001 - - 233s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 233s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session2/target3:0:0/3:0:0:0] 233s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 233s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 233s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session2/target3:0:0/3:0:0:1] 233s [4:0:0:0] storage IET Controller 0001 - - 233s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 233s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session3/target4:0:0/4:0:0:0] 233s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 233s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 233s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session3/target4:0:0/4:0:0:1] 233s [5:0:0:0] storage IET Controller 0001 - - 233s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 233s dir: /sys/bus/scsi/devices/5:0:0:0 [/sys/devices/platform/host5/session4/target5:0:0/5:0:0:0] 233s [5:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 233s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 233s dir: /sys/bus/scsi/devices/5:0:0:1 [/sys/devices/platform/host5/session4/target5:0:0/5:0:0:1] 233s NVMe module may not be loaded 233s 34.512287 | set open fds limit to 1073741816/1073741816 233s 34.512343 | loading /lib/multipath/libchecktur.so checker 233s 34.512429 | checker tur: message table size = 3 233s 34.512439 | loading /lib/multipath/libprioconst.so prioritizer 233s 34.512562 | _init_foreign: foreign library "nvme" is not enabled 233s 34.518046 | vda: device node name blacklisted 233s 34.518490 | sda: size = 204800 233s 34.518634 | sda: vendor = IET 233s 34.518656 | sda: product = VIRTUAL-DISK 233s 34.518676 | sda: rev = 0001 233s 34.519291 | sda: h:b:t:l = 2:0:0:1 233s 34.519652 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 233s 34.519659 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 233s 34.519661 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 233s 34.519892 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 233s 34.519901 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 233s 34.519916 | sda: serial = beaf11 233s 34.519918 | sda: detect_checker = yes (setting: multipath internal) 233s 34.520117 | sda: path_checker = tur (setting: multipath internal) 233s 34.520127 | sda: checker timeout = 30 s (setting: kernel sysfs) 233s 34.520189 | sda: tur state = up 233s 34.520340 | sdb: size = 204800 233s 34.520484 | sdb: vendor = IET 233s 34.520506 | sdb: product = VIRTUAL-DISK 233s 34.520526 | sdb: rev = 0001 233s 34.521175 | sdb: h:b:t:l = 3:0:0:1 233s 34.521559 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 233s 34.521567 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 233s 34.521569 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 233s 34.521708 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 233s 34.521714 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 233s 34.521727 | sdb: serial = beaf11 233s 34.521731 | sdb: detect_checker = yes (setting: multipath internal) 233s 34.521887 | sdb: path_checker = tur (setting: multipath internal) 233s 34.521897 | sdb: checker timeout = 30 s (setting: kernel sysfs) 233s 34.522030 | sdb: tur state = up 233s 34.522202 | sdc: size = 204800 233s 34.522383 | sdc: vendor = IET 233s 34.522412 | sdc: product = VIRTUAL-DISK 233s 34.522438 | sdc: rev = 0001 233s 34.522979 | sdc: h:b:t:l = 4:0:0:1 233s 34.523390 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 233s 34.523406 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 233s 34.523408 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 233s 34.523568 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 233s 34.523577 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 233s 34.523593 | sdc: serial = beaf11 233s 34.523596 | sdc: detect_checker = yes (setting: multipath internal) 233s 34.523735 | sdc: path_checker = tur (setting: multipath internal) 233s 34.523745 | sdc: checker timeout = 30 s (setting: kernel sysfs) 233s 34.523892 | sdc: tur state = up 233s 34.524137 | sdd: size = 204800 233s 34.524312 | sdd: vendor = IET 233s 34.524339 | sdd: product = VIRTUAL-DISK 233s 34.524362 | sdd: rev = 0001 233s 34.524926 | sdd: h:b:t:l = 5:0:0:1 233s 34.525320 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 233s 34.525332 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 233s 34.525334 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 233s 34.525494 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 233s 34.525502 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 233s 34.525519 | sdd: serial = beaf11 233s 34.525521 | sdd: detect_checker = yes (setting: multipath internal) 233s 34.525668 | sdd: path_checker = tur (setting: multipath internal) 233s 34.525679 | sdd: checker timeout = 30 s (setting: kernel sysfs) 233s 34.525782 | sdd: tur state = up 233s 34.525910 | loop0: device node name blacklisted 233s 34.526039 | loop1: device node name blacklisted 233s 34.526155 | loop2: device node name blacklisted 233s 34.526241 | loop3: device node name blacklisted 233s 34.526322 | loop4: device node name blacklisted 233s 34.526438 | loop5: device node name blacklisted 233s 34.526534 | loop6: device node name blacklisted 233s 34.526625 | loop7: device node name blacklisted 233s 34.526724 | dm-0: device node name blacklisted 233s 34.527758 | multipath-tools v0.9.4 (12/19, 2022) 233s 34.527777 | libdevmapper version 1.02.185 233s 34.527988 | kernel device mapper v4.48.0 233s 34.528014 | DM multipath kernel driver v1.14.0 233s 34.528119 | sda: size = 204800 233s 34.528127 | sda: vendor = IET 233s 34.528130 | sda: product = VIRTUAL-DISK 233s 34.528131 | sda: rev = 0001 233s 34.528624 | sda: h:b:t:l = 2:0:0:1 233s 34.528748 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 233s 34.528768 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 233s 34.528770 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 233s 34.528782 | sda: serial = beaf11 233s 34.528856 | sda: tur state = up 233s 34.528859 | sda: uid = 360000000000000000e00000000010001 (udev) 233s 34.528861 | sda: detect_prio = yes (setting: multipath internal) 233s 34.528864 | sda: prio = const (setting: multipath internal) 233s 34.528866 | sda: prio args = "" (setting: multipath internal) 233s 34.528868 | sda: const prio = 1 233s 34.528887 | sdb: size = 204800 233s 34.528893 | sdb: vendor = IET 233s 34.528895 | sdb: product = VIRTUAL-DISK 233s 34.528897 | sdb: rev = 0001 233s 34.529397 | sdb: h:b:t:l = 3:0:0:1 233s 34.529519 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 233s 34.529538 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 233s 34.529540 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 233s 34.529551 | sdb: serial = beaf11 233s 34.529628 | sdb: tur state = up 233s 34.529636 | sdb: uid = 360000000000000000e00000000010001 (udev) 233s 34.529638 | sdb: detect_prio = yes (setting: multipath internal) 233s 34.529640 | sdb: prio = const (setting: multipath internal) 233s 34.529642 | sdb: prio args = "" (setting: multipath internal) 233s 34.529644 | sdb: const prio = 1 233s 34.529663 | sdc: size = 204800 233s 34.529669 | sdc: vendor = IET 233s 34.529671 | sdc: product = VIRTUAL-DISK 233s 34.529673 | sdc: rev = 0001 233s 34.530186 | sdc: h:b:t:l = 4:0:0:1 233s 34.530311 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 233s 34.530330 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 233s 34.530332 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 233s 34.530344 | sdc: serial = beaf11 233s 34.530428 | sdc: tur state = up 233s 34.530435 | sdc: uid = 360000000000000000e00000000010001 (udev) 233s 34.530436 | sdc: detect_prio = yes (setting: multipath internal) 233s 34.530438 | sdc: prio = const (setting: multipath internal) 233s 34.530440 | sdc: prio args = "" (setting: multipath internal) 233s 34.530442 | sdc: const prio = 1 233s 34.530462 | sdd: size = 204800 233s 34.530467 | sdd: vendor = IET 233s 34.530469 | sdd: product = VIRTUAL-DISK 233s 34.530471 | sdd: rev = 0001 233s 34.530982 | sdd: h:b:t:l = 5:0:0:1 233s 34.531123 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 233s 34.531146 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 233s 34.531148 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 233s 34.531160 | sdd: serial = beaf11 233s 34.531230 | sdd: tur state = up 233s 34.531239 | sdd: uid = 360000000000000000e00000000010001 (udev) 233s 34.531241 | sdd: detect_prio = yes (setting: multipath internal) 233s 34.531243 | sdd: prio = const (setting: multipath internal) 233s 34.531244 | sdd: prio args = "" (setting: multipath internal) 233s 34.531246 | sdd: const prio = 1 233s ===== paths list ===== 233s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 233s 2:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK unknown 233s 3:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 233s 4:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 233s 5:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 233s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 233s size=100M features='0' hwhandler='0' wp=rw 233s |-+- policy='service-time 0' prio=1 status=active 233s | `- 2:0:0:1 sda 8:0 active ready running 233s |-+- policy='service-time 0' prio=1 status=enabled 233s | `- 3:0:0:1 sdb 8:16 active ready running 233s |-+- policy='service-time 0' prio=1 status=enabled 233s | `- 4:0:0:1 sdc 8:32 active ready running 233s `-+- policy='service-time 0' prio=1 status=enabled 233s `- 5:0:0:1 sdd 8:48 active ready running 233s mpatha: 0 204800 multipath 0 0 4 1 service-time 0 1 2 8:0 1 1 service-time 0 1 2 8:16 1 1 service-time 0 1 2 8:32 1 1 service-time 0 1 2 8:48 1 1 233s Test WWN should now point to DM 233s ../../dm-0 233s Creating filesystem with 25600 4k blocks and 25600 inodes 233s 233s Allocating group tables: 0/1 done 233s Writing inode tables: 0/134.531992 | unloading tur checker 233s 34.532037 | unloading const prioritizer 233s + dmsetup table 233s + echo Test WWN should now point to DM 233s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 233s + grep dm 233s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 233s mke2fs 1.47.1 (20-May-2024) 233s done 233s Creating journal (1024 blocks): done 233s Writing superblocks and filesystem accounting information: 0/1 done 233s 233s + udevadm settle 233s + sleep 3s 236s + mkdir -p /mnt/tgtmpathtest 236s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 236s + cat 236s + cat 236s + fio --max-jobs=4 /tmp/autopkgtest.ETBuB0/tgtbasedmpaths-artifacts/path-change-prep.fio 236s 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 236s fio-3.37 236s Starting 1 thread 236s write-phase: Laying out IO file (1 file / 17592186044415MiB) 237s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91750400, buflen=65536 237s 237s write-phase: (groupid=0, jobs=1): err= 0: pid=5710: Fri Jul 19 18:13:54 2024 237s write: IOPS=2643, BW=165MiB/s (173MB/s)(87.5MiB/530msec); 0 zone resets 237s clat (usec): min=297, max=980, avg=372.17, stdev=45.99 237s lat (usec): min=301, max=984, avg=376.05, stdev=46.20 237s clat percentiles (usec): 237s | 1.00th=[ 310], 5.00th=[ 318], 10.00th=[ 330], 20.00th=[ 343], 237s | 30.00th=[ 351], 40.00th=[ 359], 50.00th=[ 367], 60.00th=[ 375], 237s | 70.00th=[ 383], 80.00th=[ 396], 90.00th=[ 420], 95.00th=[ 441], 237s | 99.00th=[ 562], 99.50th=[ 611], 99.90th=[ 758], 99.95th=[ 979], 237s | 99.99th=[ 979] 237s bw ( KiB/s): min=169472, max=169472, per=100.00%, avg=169472.00, stdev= 0.00, samples=1 237s iops : min= 2648, max= 2648, avg=2648.00, stdev= 0.00, samples=1 237s lat (usec) : 500=98.36%, 750=1.43%, 1000=0.14% 237s cpu : usr=1.89%, sys=8.13%, ctx=1402, majf=0, minf=0 237s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 237s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 237s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 237s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 237s latency : target=0, window=0, percentile=100.00%, depth=1 237s 237s Run status group 0 (all jobs): 237s WRITE: bw=165MiB/s (173MB/s), 165MiB/s-165MiB/s (173MB/s-173MB/s), io=87.5MiB (91.8MB), run=530-530msec 237s 237s Disk stats (read/write): 237s dm-0: ios=1/1021, sectors=8/130688, merge=0/0, ticks=1/355, in_queue=357, util=72.10%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/120, aggrin_queue=120, aggrutil=72.73% 237s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 237s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 237s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 237s sda: ios=1/1402, sectors=8/179280, merge=0/0, ticks=0/480, in_queue=480, util=72.73% 237s Starting the path changes in background 237s + echo Starting the path changes in background 237s + date +Pre FIO %H:%M:%S.%N 237s Pre FIO 18:13:54.936495342 237s + fio --max-jobs=4 /tmp/autopkgtest.ETBuB0/tgtbasedmpaths-artifacts/path-change-check.fio 237s 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 237s fio-3.37 237s Starting 1 thread 417s 417s verify-phase: (groupid=0, jobs=1): err= 0: pid=5717: Fri Jul 19 18:16:55 2024 417s read: IOPS=6378, BW=399MiB/s (418MB/s)(70.1GiB/180001msec) 417s clat (usec): min=96, max=28778, avg=150.09, stdev=71.13 417s lat (usec): min=96, max=28778, avg=150.25, stdev=71.13 417s clat percentiles (usec): 417s | 1.00th=[ 106], 5.00th=[ 112], 10.00th=[ 116], 20.00th=[ 125], 417s | 30.00th=[ 133], 40.00th=[ 139], 50.00th=[ 145], 60.00th=[ 151], 417s | 70.00th=[ 159], 80.00th=[ 169], 90.00th=[ 184], 95.00th=[ 200], 417s | 99.00th=[ 247], 99.50th=[ 310], 99.90th=[ 502], 99.95th=[ 1045], 417s | 99.99th=[ 2180] 417s bw ( KiB/s): min=254464, max=502400, per=100.00%, avg=408501.10, stdev=47053.28, samples=359 417s iops : min= 3976, max= 7850, avg=6382.82, stdev=735.21, samples=359 417s lat (usec) : 100=0.01%, 250=99.07%, 500=0.82%, 750=0.04%, 1000=0.01% 417s lat (msec) : 2=0.04%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01% 417s cpu : usr=5.03%, sys=12.39%, ctx=1148195, majf=0, minf=16 417s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 417s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 417s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 417s issued rwts: total=1148061,0,0,0 short=0,0,0,0 dropped=0,0,0,0 417s latency : target=0, window=0, percentile=100.00%, depth=1 417s 417s Run status group 0 (all jobs): 417s READ: bw=399MiB/s (418MB/s), 399MiB/s-399MiB/s (418MB/s-418MB/s), io=70.1GiB (75.2GB), run=180001-180001msec 417s 417s Disk stats (read/write): 417s dm-0: ios=1148180/10, sectors=146858208/12928, merge=0/9, ticks=163779/145, in_queue=164046, util=88.81%, aggrios=77780/2, aggsectors=9947736/3232, aggrmerge=0/0, aggrticks=10580/5, aggrin_queue=10585, aggrutil=79.88% 417s sdd: ios=119449/5, sectors=15278592/56, merge=0/0, ticks=17081/2, in_queue=17083, util=32.55% 417s sdb: ios=66315/0, sectors=8478176/0, merge=0/0, ticks=8476/0, in_queue=8476, util=39.93% 417s sdc: ios=64724/0, sectors=8278656/0, merge=0/0, ticks=8415/0, in_queue=8415, util=26.66% 417s sda: ios=60635/4, sectors=7755520/12872, merge=0/0, ticks=8348/21, in_queue=8369, util=79.88% 417s Post FIO 18:16:55.280652874 417s FIO verify test with changing paths - OK 417s Report log of background activity 417s + iscsiadm --mode session 417s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s + sleep 10s 417s + date +MP report (expect 4) %H:%M:%S.%N 417s MP report (expect 4) 18:14:04.943646937 417s + multipath -ll 417s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 417s size=100M features='0' hwhandler='0' wp=rw 417s |-+- policy='service-time 0' prio=1 status=active 417s | `- 2:0:0:1 sda 8:0 active ready running 417s |-+- policy='service-time 0' prio=1 status=enabled 417s | `- 3:0:0:1 sdb 8:16 active ready running 417s |-+- policy='service-time 0' prio=1 status=enabled 417s | `- 4:0:0:1 sdc 8:32 active ready running 417s `-+- policy='service-time 0' prio=1 status=enabled 417s `- 5:0:0:1 sdd 8:48 active ready running 417s + date +UN-plug path 1 %H:%M:%S.%N 417s UN-plug path 1 18:14:04.966453121 417s + iscsiadm --mode session -r 1 -u 417s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 417s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 417s + iscsiadm --mode session 417s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s + sleep 10s 417s + date +MP report (expect 3) %H:%M:%S.%N 417s MP report (expect 3) 18:14:15.027706842 417s + multipath -ll 417s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 417s size=100M features='0' hwhandler='0' wp=rw 417s |-+- policy='service-time 0' prio=1 status=active 417s | `- 3:0:0:1 sdb 8:16 active ready running 417s |-+- policy='service-time 0' prio=1 status=enabled 417s | `- 4:0:0:1 sdc 8:32 active ready running 417s `-+- policy='service-time 0' prio=1 status=enabled 417s `- 5:0:0:1 sdd 8:48 active ready running 417s + date +UN-plug path 2 %H:%M:%S.%N 417s UN-plug path 2 18:14:15.049166361 417s + iscsiadm --mode session -r 2 -u 417s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 417s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 417s + iscsiadm --mode session 417s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s + sleep 10s 417s + date +MP report (expect 2) %H:%M:%S.%N 417s MP report (expect 2) 18:14:25.098638954 417s + multipath -ll 417s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 417s size=100M features='0' hwhandler='0' wp=rw 417s |-+- policy='service-time 0' prio=1 status=active 417s | `- 4:0:0:1 sdc 8:32 active ready running 417s `-+- policy='service-time 0' prio=1 status=enabled 417s `- 5:0:0:1 sdd 8:48 active ready running 417s + date +UN-plug path 3 %H:%M:%S.%N 417s UN-plug path 3 18:14:25.115153600 417s + iscsiadm --mode session -r 3 -u 417s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 417s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 417s + iscsiadm --mode session 417s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s + sleep 10s 417s + date +MP report (expect 1) %H:%M:%S.%N 417s MP report (expect 1) 18:14:35.148442659 417s + multipath -ll 417s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 417s size=100M features='0' hwhandler='0' wp=rw 417s `-+- policy='service-time 0' prio=1 status=active 417s `- 5:0:0:1 sdd 8:48 active ready running 417s + date +Add paths 5/6/7/8 %H:%M:%S.%N 417s Add paths 5/6/7/8 18:14:35.161248974 417s + iscsiadm --mode session -r 4 --op new 417s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 417s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 417s + iscsiadm --mode session -r 4 --op new 417s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 417s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 417s + iscsiadm --mode session -r 4 --op new 417s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 417s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 417s + iscsiadm --mode session -r 4 --op new 417s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 417s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 417s + iscsiadm --mode session 417s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s + sleep 10s 417s + date +MP report (expect 5) %H:%M:%S.%N 417s MP report (expect 5) 18:14:45.256839669 417s + multipath -ll 417s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 417s size=100M features='0' hwhandler='0' wp=rw 417s |-+- policy='service-time 0' prio=1 status=active 417s | `- 5:0:0:1 sdd 8:48 active ready running 417s |-+- policy='service-time 0' prio=1 status=enabled 417s | `- 2:0:0:1 sda 8:0 active ready running 417s |-+- policy='service-time 0' prio=1 status=enabled 417s | `- 3:0:0:1 sdb 8:16 active ready running 417s |-+- policy='service-time 0' prio=1 status=enabled 417s | `- 4:0:0:1 sdc 8:32 active ready running 417s `-+- policy='service-time 0' prio=1 status=enabled 417s `- 6:0:0:1 sde 8:64 active ready running 417s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 417s UN-plug multiple paths 4/7/8 18:14:45.282275766 417s + iscsiadm --mode session -r 4 -u 417s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 417s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 417s + iscsiadm --mode session -r 7 -u 417s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 417s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 417s + iscsiadm --mode session -r 8 -u 417s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 417s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 417s + iscsiadm --mode session 417s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 417s + sleep 10s 417s + date +Restart multipath daemon %H:%M:%S.%N 417s Restart multipath daemon 18:14:55.416759827 417s + systemctl restart multipathd 417s + sleep 10s 417s + date +Final background report (expect 2) %H:%M:%S.%N 417s Final background report (expect 2) 18:15:05.503719624 417s + multipath -ll 417s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 417s size=100M features='0' hwhandler='0' wp=rw 417s |-+- policy='service-time 0' prio=1 status=active 417s | `- 2:0:0:1 sda 8:0 active ready running 417s `-+- policy='service-time 0' prio=1 status=enabled 417s `- 3:0:0:1 sdb 8:16 active ready running 417s + date +Post FIO %H:%M:%S.%N 417s + echo FIO verify test with changing paths - OK 417s + echo Report log of background activity 417s + cat /tmp/autopkgtest.ETBuB0/tgtbasedmpaths-artifacts/test-background.log 417s + sync 417s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 417s Final stats 417s + echo Final stats 417s + iscsiadm --mode session --stats 417s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 417s iSCSI SNMP: 417s txdata_octets: 40120824 417s rxdata_octets: 54750926548 417s noptx_pdus: 0 417s scsicmd_pdus: 835583 417s tmfcmd_pdus: 0 417s login_pdus: 0 417s text_pdus: 0 417s dataout_pdus: 0 417s logout_pdus: 0 417s snack_pdus: 0 417s noprx_pdus: 0 417s scsirsp_pdus: 835583 417s tmfrsp_pdus: 0 417s textrsp_pdus: 0 417s datain_pdus: 835549 417s logoutrsp_pdus: 0 417s r2t_pdus: 0 417s async_pdus: 0 417s rjt_pdus: 0 417s digest_err: 0 417s timeout_err: 0 417s iSCSI Extended: 417s tx_sendpage_failures: 0 417s rx_discontiguous_hdr: 0 417s eh_abort_cnt: 0 417s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 417s iSCSI SNMP: 417s txdata_octets: 10440 417s rxdata_octets: 2162084 417s noptx_pdus: 0 417s scsicmd_pdus: 188 417s tmfcmd_pdus: 0 417s login_pdus: 0 417s text_pdus: 0 417s dataout_pdus: 0 417s logout_pdus: 0 417s snack_pdus: 0 417s noprx_pdus: 0 417s scsirsp_pdus: 188 417s tmfrsp_pdus: 0 417s textrsp_pdus: 0 417s datain_pdus: 164 417s logoutrsp_pdus: 0 417s r2t_pdus: 0 417s async_pdus: 0 417s rjt_pdus: 0 417s digest_err: 0 417s timeout_err: 0 417s iSCSI Extended: 417s tx_sendpage_failures: 0 417s rx_discontiguous_hdr: 0 417s eh_abort_cnt: 0 417s + journalctl --no-pager -u multipathd 417s Jul 19 12:13:19 adtubuntu-oracular-amd64-server-20240718 multipathd[318]: multipathd: shut down 417s Jul 19 12:13:19 adtubuntu-oracular-amd64-server-20240718 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 417s Jul 19 12:13:19 adtubuntu-oracular-amd64-server-20240718 systemd[1]: multipathd.service: Deactivated successfully. 417s Jul 19 12:13:19 adtubuntu-oracular-amd64-server-20240718 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 417s -- Boot 25c91c73d129415980c58f75720a7ea6 -- 417s Jul 19 18:12:09 adtubuntu-oracular-amd64-server-20240718 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 417s Jul 19 18:12:09 adtubuntu-oracular-amd64-server-20240718 multipathd[349]: multipathd v0.9.4: start up 417s Jul 19 18:12:09 adtubuntu-oracular-amd64-server-20240718 multipathd[349]: reconfigure: setting up paths and maps 417s Jul 19 18:12:09 adtubuntu-oracular-amd64-server-20240718 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 417s Jul 19 18:13:14 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 417s Jul 19 18:13:14 autopkgtest multipathd[349]: multipathd: shut down 417s Jul 19 18:13:14 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 417s Jul 19 18:13:14 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 417s -- Boot 320b1ebd0aff4c8d8f56410f1c8a91ab -- 417s Jul 19 18:13:19 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 417s Jul 19 18:13:20 autopkgtest multipathd[350]: multipathd v0.9.4: start up 417s Jul 19 18:13:20 autopkgtest multipathd[350]: reconfigure: setting up paths and maps 417s Jul 19 18:13:20 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 417s Jul 19 18:13:45 autopkgtest multipathd[350]: mpatha: addmap [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 417s Jul 19 18:13:45 autopkgtest multipathd[350]: sdb [8:16]: path added to devmap mpatha 417s Jul 19 18:13:45 autopkgtest multipathd[350]: mpatha: performing delayed actions 417s Jul 19 18:13:45 autopkgtest multipathd[350]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 417s Jul 19 18:14:04 autopkgtest multipathd[350]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 417s Jul 19 18:14:05 autopkgtest multipathd[350]: check_removed_paths: sda: freeing path in removed state 417s Jul 19 18:14:05 autopkgtest multipathd[350]: 8:0: path removed from map mpatha 417s Jul 19 18:14:15 autopkgtest multipathd[350]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 417s Jul 19 18:14:15 autopkgtest multipathd[350]: check_removed_paths: sdb: freeing path in removed state 417s Jul 19 18:14:15 autopkgtest multipathd[350]: 8:16: path removed from map mpatha 417s Jul 19 18:14:25 autopkgtest multipathd[350]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 417s Jul 19 18:14:25 autopkgtest multipathd[350]: check_removed_paths: sdc: freeing path in removed state 417s Jul 19 18:14:25 autopkgtest multipathd[350]: 8:32: path removed from map mpatha 417s Jul 19 18:14:35 autopkgtest multipathd[350]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1] 417s Jul 19 18:14:35 autopkgtest multipathd[350]: sda [8:0]: path added to devmap mpatha 417s Jul 19 18:14:35 autopkgtest multipathd[350]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 417s Jul 19 18:14:35 autopkgtest multipathd[350]: sdb [8:16]: path added to devmap mpatha 417s Jul 19 18:14:35 autopkgtest multipathd[350]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 417s Jul 19 18:14:35 autopkgtest multipathd[350]: sdc [8:32]: path added to devmap mpatha 417s Jul 19 18:14:35 autopkgtest multipathd[350]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 417s Jul 19 18:14:35 autopkgtest multipathd[350]: sde [8:64]: path added to devmap mpatha 417s Jul 19 18:14:45 autopkgtest multipathd[350]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 417s Jul 19 18:14:45 autopkgtest multipathd[350]: check_removed_paths: sdd: freeing path in removed state 417s Jul 19 18:14:45 autopkgtest multipathd[350]: 8:48: path removed from map mpatha 417s Jul 19 18:14:45 autopkgtest multipathd[350]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:64 1] 417s Jul 19 18:14:45 autopkgtest multipathd[350]: check_removed_paths: sdc: freeing path in removed state 417s Jul 19 18:14:45 autopkgtest multipathd[350]: 8:32: path removed from map mpatha 417s Jul 19 18:14:45 autopkgtest multipathd[350]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 417s Jul 19 18:14:45 autopkgtest multipathd[350]: check_removed_paths: sde: freeing path in removed state 417s Jul 19 18:14:45 autopkgtest multipathd[350]: 8:64: path removed from map mpatha 417s Jul 19 18:14:55 autopkgtest multipathd[350]: multipathd: shut down 417s Jul 19 18:14:55 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 417s Jul 19 18:14:55 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 417s Jul 19 18:14:55 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 417s Jul 19 18:14:55 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 417s Jul 19 18:14:55 autopkgtest multipathd[6063]: multipathd v0.9.4: start up 417s Jul 19 18:14:55 autopkgtest multipathd[6063]: reconfigure: setting up paths and maps 417s Jul 19 18:14:55 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 417s + echo Check final path status 417s + multipath -ll 417s Check final path status 417s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 417s size=100M features='0' hwhandler='0' wp=rw 417s |-+- policy='service-time 0' prio=1 status=active 417s | `- 2:0:0:1 sda 8:0 active ready running 417s `-+- policy='service-time 0' prio=1 status=enabled 417s `- 3:0:0:1 sdb 8:16 active ready running 417s + multipath -ll 417s + grep --count status= 417s + diskc=2 417s + multipath -ll 417s + grep --count status=active 417s + diska=1 417s + multipath -ll 417s + grep --count status=enabled 417s OK 417s + diske=1 417s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 417s + echo OK 417s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 417s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 417s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 417s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 417s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 417s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 417s autopkgtest [18:16:55]: test tgtbasedmpaths: -----------------------] 417s tgtbasedmpaths PASS 417s autopkgtest [18:16:55]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 418s autopkgtest [18:16:56]: @@@@@@@@@@@@@@@@@@@@ summary 418s kpartx-file-loopback PASS 418s tgtbasedmpaths PASS 430s nova [W] Skipping flock for amd64 430s Creating nova instance adt-oracular-amd64-multipath-tools-20240719-180958-juju-7f2275-prod-proposed-migration-environment-3-589852d2-27ce-4a37-87c4-56e1b31f5eca from image adt/ubuntu-oracular-amd64-server-20240719.img (UUID 57817864-9f58-4e96-bab2-7e516ea1dc40)... 430s nova [W] Skipping flock for amd64 430s Creating nova instance adt-oracular-amd64-multipath-tools-20240719-180958-juju-7f2275-prod-proposed-migration-environment-3-589852d2-27ce-4a37-87c4-56e1b31f5eca from image adt/ubuntu-oracular-amd64-server-20240719.img (UUID 57817864-9f58-4e96-bab2-7e516ea1dc40)...