0s autopkgtest [03:39:39]: starting date and time: 2024-03-26 03:39:39+0000 0s autopkgtest [03:39:39]: git checkout: 4a1cd702 l/adt_testbed: don't blame the testbed for unsolvable build deps 0s autopkgtest [03:39:39]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.2ejxty9d/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --setup-commands /home/ubuntu/autopkgtest/setup-commands/setup-testbed --apt-pocket=proposed --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=qemu/1:8.2.1+ds-1ubuntu8 alsa-lib/1.2.11-1build1 at-spi2-core/2.51.90-3 ceph/19.2.0~git20240301.4c76c50-0ubuntu3 cups/2.4.7-1.2ubuntu1 curl/8.5.0-2ubuntu8 glib2.0/2.79.3-3ubuntu5 gnutls28/3.8.3-1.1ubuntu2 gtk+3.0/3.24.41-1.1ubuntu3 libpng1.6/1.6.43-3 libpsl/0.21.2-1.1 nettle/3.9.1-2.2 openssl/3.0.13-0ubuntu2 pipewire/1.0.4-2ubuntu2 usbredir/0.13.0-2.1 wp2latex/4.4~ds-1build1' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos02-arm64-10.secgroup --name adt-noble-arm64-multipath-tools-20240326-033939-juju-7f2275-prod-proposed-migration-environment-2 --image adt/ubuntu-noble-arm64-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 169s autopkgtest [03:42:28]: testbed dpkg architecture: arm64 169s autopkgtest [03:42:28]: testbed apt version: 2.7.12 169s autopkgtest [03:42:28]: @@@@@@@@@@@@@@@@@@@@ test bed setup 170s Get:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease [117 kB] 171s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/multiverse Sources [56.0 kB] 171s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/universe Sources [4027 kB] 172s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/main Sources [496 kB] 173s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/restricted Sources [7592 B] 173s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 Packages [714 kB] 173s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 c-n-f Metadata [3144 B] 173s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/restricted arm64 Packages [43.0 kB] 173s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/restricted arm64 c-n-f Metadata [116 B] 173s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/universe arm64 Packages [4310 kB] 173s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/universe arm64 c-n-f Metadata [8528 B] 173s Get:12 http://ftpmaster.internal/ubuntu noble-proposed/multiverse arm64 Packages [70.5 kB] 173s Get:13 http://ftpmaster.internal/ubuntu noble-proposed/multiverse arm64 c-n-f Metadata [116 B] 182s Fetched 9853 kB in 5s (1908 kB/s) 183s Reading package lists... 187s Reading package lists... 188s Building dependency tree... 188s Reading state information... 190s Calculating upgrade... 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... 193s 0 upgraded, 0 newly installed, 0 to remove and 247 not upgraded. 195s sh: Attempting to set up Debian/Ubuntu apt sources automatically 195s sh: Distribution appears to be Ubuntu 198s Reading package lists... 198s Building dependency tree... 198s Reading state information... 200s eatmydata is already the newest version (131-1). 200s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 200s Reading package lists... 201s Building dependency tree... 201s Reading state information... 202s dbus is already the newest version (1.14.10-4ubuntu1). 202s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 202s Reading package lists... 203s Building dependency tree... 203s Reading state information... 205s rng-tools-debian is already the newest version (2.4). 205s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 205s Reading package lists... 205s Building dependency tree... 205s Reading state information... 207s The following packages will be REMOVED: 207s cloud-init* python3-configobj* python3-debconf* 208s 0 upgraded, 0 newly installed, 3 to remove and 0 not upgraded. 208s After this operation, 3256 kB disk space will be freed. 208s (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 ... 75911 files and directories currently installed.) 208s Removing cloud-init (24.1.2-0ubuntu1) ... 210s Removing python3-configobj (5.0.8-3) ... 211s Removing python3-debconf (1.5.86) ... 211s Processing triggers for man-db (2.12.0-3) ... 213s (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 ... 75522 files and directories currently installed.) 213s Purging configuration files for cloud-init (24.1.2-0ubuntu1) ... 215s dpkg: warning: while removing cloud-init, directory '/etc/cloud/cloud.cfg.d' not empty so not removed 216s Processing triggers for rsyslog (8.2312.0-3ubuntu3) ... 216s invoke-rc.d: policy-rc.d denied execution of try-restart. 216s Reading package lists... 217s Building dependency tree... 217s Reading state information... 218s linux-generic is already the newest version (6.8.0-11.11+1). 218s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 219s Hit:1 http://ftpmaster.internal/ubuntu noble InRelease 219s Hit:2 http://ftpmaster.internal/ubuntu noble-updates InRelease 219s Hit:3 http://ftpmaster.internal/ubuntu noble-security InRelease 228s Reading package lists... 228s Reading package lists... 229s Building dependency tree... 229s Reading state information... 230s Calculating upgrade... 232s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 232s Reading package lists... 232s Building dependency tree... 232s Reading state information... 234s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 234s autopkgtest [03:43:33]: rebooting testbed after setup commands that affected boot 399s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 417s autopkgtest [03:46:36]: testbed running kernel: Linux 6.8.0-11-generic #11-Ubuntu SMP PREEMPT_DYNAMIC Wed Feb 14 02:53:31 UTC 2024 421s autopkgtest [03:46:40]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 427s Get:1 http://ftpmaster.internal/ubuntu noble/main multipath-tools 0.9.4-5ubuntu3 (dsc) [2733 B] 427s Get:2 http://ftpmaster.internal/ubuntu noble/main multipath-tools 0.9.4-5ubuntu3 (tar) [554 kB] 427s Get:3 http://ftpmaster.internal/ubuntu noble/main multipath-tools 0.9.4-5ubuntu3 (diff) [42.6 kB] 428s gpgv: Signature made Wed Sep 6 23:15:24 2023 UTC 428s gpgv: using RSA key 8A2044F84F716A85B77FF76311DF4294CCA39893 428s gpgv: Can't check signature: No public key 428s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu3.dsc: no acceptable signature found 428s autopkgtest [03:46:47]: testing package multipath-tools version 0.9.4-5ubuntu3 428s autopkgtest [03:46:47]: build not needed 429s autopkgtest [03:46:48]: test kpartx-file-loopback: preparing testbed 431s Reading package lists... 431s Building dependency tree... 431s Reading state information... 432s Starting pkgProblemResolver with broken count: 0 433s Starting 2 pkgProblemResolver with broken count: 0 433s Done 434s The following additional packages will be installed: 434s liburing2 qemu-utils 434s Recommended packages: 434s qemu-block-extra 434s The following NEW packages will be installed: 434s autopkgtest-satdep liburing2 qemu-utils 434s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 434s Need to get 2062 kB/2063 kB of archives. 434s After this operation, 11.7 MB of additional disk space will be used. 434s Get:1 /tmp/autopkgtest.8j04eT/1-autopkgtest-satdep.deb autopkgtest-satdep arm64 0 [716 B] 435s Get:2 http://ftpmaster.internal/ubuntu noble/main arm64 liburing2 arm64 2.5-1 [21.5 kB] 435s Get:3 http://ftpmaster.internal/ubuntu noble/main arm64 qemu-utils arm64 1:8.2.1+ds-1ubuntu1 [2041 kB] 436s Fetched 2062 kB in 1s (2909 kB/s) 436s Selecting previously unselected package liburing2:arm64. 437s (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 ... 75467 files and directories currently installed.) 437s Preparing to unpack .../liburing2_2.5-1_arm64.deb ... 437s Unpacking liburing2:arm64 (2.5-1) ... 437s Selecting previously unselected package qemu-utils. 437s Preparing to unpack .../qemu-utils_1%3a8.2.1+ds-1ubuntu1_arm64.deb ... 437s Unpacking qemu-utils (1:8.2.1+ds-1ubuntu1) ... 437s Selecting previously unselected package autopkgtest-satdep. 437s Preparing to unpack .../1-autopkgtest-satdep.deb ... 437s Unpacking autopkgtest-satdep (0) ... 437s Setting up liburing2:arm64 (2.5-1) ... 437s Setting up qemu-utils (1:8.2.1+ds-1ubuntu1) ... 437s Setting up autopkgtest-satdep (0) ... 437s Processing triggers for man-db (2.12.0-3) ... 439s Processing triggers for libc-bin (2.39-0ubuntu6) ... 446s (Reading database ... 75487 files and directories currently installed.) 446s Removing autopkgtest-satdep (0) ... 447s autopkgtest [03:47:06]: test kpartx-file-loopback: [----------------------- 447s Formatting 'foo.img', fmt=raw size=20971520 448s Creating new GPT entries in memory. 448s Warning: The kernel is still using the old partition table. 448s The new table will be used at the next reboot or after you 448s run partprobe(8) or kpartx(8) 448s The operation has completed successfully. 448s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 448s standard_filename: OK 448s del devmap : loop0p1 448s No devices found 448s standard_filename_cleanup: OK 448s Formatting 'fou du FaFa.img', fmt=raw size=20971520 449s Creating new GPT entries in memory. 449s Warning: The kernel is still using the old partition table. 449s The new table will be used at the next reboot or after you 449s run partprobe(8) or kpartx(8) 449s The operation has completed successfully. 449s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 450s filename_with_spaces: OK 450s del devmap : loop0p1 450s No devices found 450s filename_with_spaces_cleanup: OK 450s autopkgtest [03:47:09]: test kpartx-file-loopback: -----------------------] 451s kpartx-file-loopback PASS 451s autopkgtest [03:47:10]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 451s autopkgtest [03:47:10]: test tgtbasedmpaths: preparing testbed 610s autopkgtest [03:49:49]: testbed dpkg architecture: arm64 610s autopkgtest [03:49:49]: testbed apt version: 2.7.12 610s autopkgtest [03:49:49]: @@@@@@@@@@@@@@@@@@@@ test bed setup 611s Get:1 http://ftpmaster.internal/ubuntu noble-proposed InRelease [117 kB] 612s Get:2 http://ftpmaster.internal/ubuntu noble-proposed/multiverse Sources [56.0 kB] 612s Get:3 http://ftpmaster.internal/ubuntu noble-proposed/main Sources [496 kB] 612s Get:4 http://ftpmaster.internal/ubuntu noble-proposed/restricted Sources [7592 B] 612s Get:5 http://ftpmaster.internal/ubuntu noble-proposed/universe Sources [4027 kB] 612s Get:6 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 Packages [714 kB] 612s Get:7 http://ftpmaster.internal/ubuntu noble-proposed/main arm64 c-n-f Metadata [3144 B] 612s Get:8 http://ftpmaster.internal/ubuntu noble-proposed/restricted arm64 Packages [43.0 kB] 612s Get:9 http://ftpmaster.internal/ubuntu noble-proposed/restricted arm64 c-n-f Metadata [116 B] 612s Get:10 http://ftpmaster.internal/ubuntu noble-proposed/universe arm64 Packages [4310 kB] 612s Get:11 http://ftpmaster.internal/ubuntu noble-proposed/universe arm64 c-n-f Metadata [8528 B] 612s Get:12 http://ftpmaster.internal/ubuntu noble-proposed/multiverse arm64 Packages [70.5 kB] 612s Get:13 http://ftpmaster.internal/ubuntu noble-proposed/multiverse arm64 c-n-f Metadata [116 B] 621s Fetched 9853 kB in 3s (2892 kB/s) 622s Reading package lists... 626s Reading package lists... 627s Building dependency tree... 627s Reading state information... 628s Calculating upgrade... 629s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 629s Reading package lists... 630s Building dependency tree... 630s Reading state information... 632s 0 upgraded, 0 newly installed, 0 to remove and 247 not upgraded. 633s sh: Attempting to set up Debian/Ubuntu apt sources automatically 633s sh: Distribution appears to be Ubuntu 636s Reading package lists... 636s Building dependency tree... 636s Reading state information... 638s eatmydata is already the newest version (131-1). 638s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 638s Reading package lists... 638s Building dependency tree... 638s Reading state information... 640s dbus is already the newest version (1.14.10-4ubuntu1). 640s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 640s Reading package lists... 641s Building dependency tree... 641s Reading state information... 642s rng-tools-debian is already the newest version (2.4). 642s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 643s Reading package lists... 643s Building dependency tree... 643s Reading state information... 645s The following packages will be REMOVED: 645s cloud-init* python3-configobj* python3-debconf* 646s 0 upgraded, 0 newly installed, 3 to remove and 0 not upgraded. 646s After this operation, 3256 kB disk space will be freed. 646s (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 ... 75911 files and directories currently installed.) 646s Removing cloud-init (24.1.2-0ubuntu1) ... 648s Removing python3-configobj (5.0.8-3) ... 648s Removing python3-debconf (1.5.86) ... 648s Processing triggers for man-db (2.12.0-3) ... 649s (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 ... 75522 files and directories currently installed.) 649s Purging configuration files for cloud-init (24.1.2-0ubuntu1) ... 651s dpkg: warning: while removing cloud-init, directory '/etc/cloud/cloud.cfg.d' not empty so not removed 652s Processing triggers for rsyslog (8.2312.0-3ubuntu3) ... 652s invoke-rc.d: policy-rc.d denied execution of try-restart. 653s Reading package lists... 653s Building dependency tree... 653s Reading state information... 655s linux-generic is already the newest version (6.8.0-11.11+1). 655s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 656s Hit:1 http://ftpmaster.internal/ubuntu noble InRelease 656s Hit:2 http://ftpmaster.internal/ubuntu noble-updates InRelease 656s Hit:3 http://ftpmaster.internal/ubuntu noble-security InRelease 664s Reading package lists... 664s Reading package lists... 664s Building dependency tree... 664s Reading state information... 665s Calculating upgrade... 666s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 667s Reading package lists... 667s Building dependency tree... 667s Reading state information... 668s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 669s autopkgtest [03:50:48]: rebooting testbed after setup commands that affected boot 825s Reading package lists... 825s Building dependency tree... 825s Reading state information... 826s Starting pkgProblemResolver with broken count: 0 827s Starting 2 pkgProblemResolver with broken count: 0 827s Done 828s The following additional packages will be installed: 828s fio libaio1t64 libboost-iostreams1.83.0 libboost-thread1.83.0 828s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 828s libglusterfs0 libisns0 libnbd0 libndctl6 libopeniscsiusr libpmem1 828s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 828s Suggested packages: 828s fio-examples gnuplot tgt-glusterfs tgt-rbd 828s Recommended packages: 828s finalrd 828s The following NEW packages will be installed: 828s autopkgtest-satdep fio libaio1t64 libboost-iostreams1.83.0 828s libboost-thread1.83.0 libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 828s libgfxdr0 libglusterfs0 libisns0 libnbd0 libndctl6 libopeniscsiusr libpmem1 828s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 828s 0 upgraded, 23 newly installed, 0 to remove and 0 not upgraded. 828s Need to get 10.2 MB/10.2 MB of archives. 828s After this operation, 43.1 MB of additional disk space will be used. 828s Get:1 /tmp/autopkgtest.8j04eT/2-autopkgtest-satdep.deb autopkgtest-satdep arm64 0 [732 B] 828s Get:2 http://ftpmaster.internal/ubuntu noble/main arm64 libopeniscsiusr arm64 2.1.9-3ubuntu1 [47.2 kB] 829s Get:3 http://ftpmaster.internal/ubuntu noble/main arm64 libisns0 arm64 0.101-0.2 [93.8 kB] 829s Get:4 http://ftpmaster.internal/ubuntu noble/main arm64 open-iscsi arm64 2.1.9-3ubuntu1 [336 kB] 829s Get:5 http://ftpmaster.internal/ubuntu noble/main arm64 librdmacm1t64 arm64 50.0-2 [70.6 kB] 829s Get:6 http://ftpmaster.internal/ubuntu noble/universe arm64 libconfig-general-perl all 2.65-2 [57.1 kB] 829s Get:7 http://ftpmaster.internal/ubuntu noble/universe arm64 tgt arm64 1:1.0.85-1.1ubuntu2 [232 kB] 829s Get:8 http://ftpmaster.internal/ubuntu noble/main arm64 libaio1t64 arm64 0.3.113-6 [7312 B] 829s Get:9 http://ftpmaster.internal/ubuntu noble/universe arm64 libgfxdr0 arm64 11.1-4 [19.3 kB] 829s Get:10 http://ftpmaster.internal/ubuntu noble/universe arm64 libglusterfs0 arm64 11.1-4 [266 kB] 829s Get:11 http://ftpmaster.internal/ubuntu noble/universe arm64 libgfrpc0 arm64 11.1-4 [41.0 kB] 829s Get:12 http://ftpmaster.internal/ubuntu noble/universe arm64 libgfapi0 arm64 11.1-4 [78.4 kB] 829s Get:13 http://ftpmaster.internal/ubuntu noble/universe arm64 libnbd0 arm64 1.18.2-1build1 [87.3 kB] 829s Get:14 http://ftpmaster.internal/ubuntu noble/main arm64 libdaxctl1 arm64 77-2ubuntu1 [21.1 kB] 829s Get:15 http://ftpmaster.internal/ubuntu noble/main arm64 libndctl6 arm64 77-2ubuntu1 [63.1 kB] 829s Get:16 http://ftpmaster.internal/ubuntu noble/main arm64 libpmem1 arm64 1.13.1-1.1 [35.4 kB] 829s Get:17 http://ftpmaster.internal/ubuntu noble/main arm64 libboost-iostreams1.83.0 arm64 1.83.0-2ubuntu1 [339 kB] 829s Get:18 http://ftpmaster.internal/ubuntu noble/main arm64 libboost-thread1.83.0 arm64 1.83.0-2ubuntu1 [358 kB] 829s Get:19 http://ftpmaster.internal/ubuntu noble/main arm64 librados2 arm64 18.2.0-0ubuntu7 [3645 kB] 829s Get:20 http://ftpmaster.internal/ubuntu noble/main arm64 libpmemobj1 arm64 1.13.1-1.1 [115 kB] 829s Get:21 http://ftpmaster.internal/ubuntu noble/main arm64 librbd1 arm64 18.2.0-0ubuntu7 [3659 kB] 829s Get:22 http://ftpmaster.internal/ubuntu noble/universe arm64 fio arm64 3.36-1build1 [594 kB] 829s Get:23 http://ftpmaster.internal/ubuntu noble/main arm64 lsscsi arm64 0.32-1 [48.4 kB] 830s Preconfiguring packages ... 830s Fetched 10.2 MB in 1s (10.1 MB/s) 831s Selecting previously unselected package libopeniscsiusr. 831s (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 ... 75467 files and directories currently installed.) 831s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu1_arm64.deb ... 831s Unpacking libopeniscsiusr (2.1.9-3ubuntu1) ... 831s Selecting previously unselected package libisns0:arm64. 831s Preparing to unpack .../01-libisns0_0.101-0.2_arm64.deb ... 831s Unpacking libisns0:arm64 (0.101-0.2) ... 831s Selecting previously unselected package open-iscsi. 831s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu1_arm64.deb ... 831s Unpacking open-iscsi (2.1.9-3ubuntu1) ... 832s Selecting previously unselected package librdmacm1t64:arm64. 832s Preparing to unpack .../03-librdmacm1t64_50.0-2_arm64.deb ... 832s Unpacking librdmacm1t64:arm64 (50.0-2) ... 832s Selecting previously unselected package libconfig-general-perl. 832s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 832s Unpacking libconfig-general-perl (2.65-2) ... 832s Selecting previously unselected package tgt. 832s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu2_arm64.deb ... 832s Unpacking tgt (1:1.0.85-1.1ubuntu2) ... 832s Selecting previously unselected package libaio1t64:arm64. 832s Preparing to unpack .../06-libaio1t64_0.3.113-6_arm64.deb ... 832s Unpacking libaio1t64:arm64 (0.3.113-6) ... 832s Selecting previously unselected package libgfxdr0:arm64. 832s Preparing to unpack .../07-libgfxdr0_11.1-4_arm64.deb ... 832s Unpacking libgfxdr0:arm64 (11.1-4) ... 832s Selecting previously unselected package libglusterfs0:arm64. 832s Preparing to unpack .../08-libglusterfs0_11.1-4_arm64.deb ... 832s Unpacking libglusterfs0:arm64 (11.1-4) ... 832s Selecting previously unselected package libgfrpc0:arm64. 832s Preparing to unpack .../09-libgfrpc0_11.1-4_arm64.deb ... 832s Unpacking libgfrpc0:arm64 (11.1-4) ... 832s Selecting previously unselected package libgfapi0:arm64. 832s Preparing to unpack .../10-libgfapi0_11.1-4_arm64.deb ... 832s Unpacking libgfapi0:arm64 (11.1-4) ... 832s Selecting previously unselected package libnbd0. 832s Preparing to unpack .../11-libnbd0_1.18.2-1build1_arm64.deb ... 832s Unpacking libnbd0 (1.18.2-1build1) ... 832s Selecting previously unselected package libdaxctl1:arm64. 832s Preparing to unpack .../12-libdaxctl1_77-2ubuntu1_arm64.deb ... 832s Unpacking libdaxctl1:arm64 (77-2ubuntu1) ... 832s Selecting previously unselected package libndctl6:arm64. 832s Preparing to unpack .../13-libndctl6_77-2ubuntu1_arm64.deb ... 832s Unpacking libndctl6:arm64 (77-2ubuntu1) ... 833s Selecting previously unselected package libpmem1:arm64. 833s Preparing to unpack .../14-libpmem1_1.13.1-1.1_arm64.deb ... 833s Unpacking libpmem1:arm64 (1.13.1-1.1) ... 833s Selecting previously unselected package libboost-iostreams1.83.0:arm64. 833s Preparing to unpack .../15-libboost-iostreams1.83.0_1.83.0-2ubuntu1_arm64.deb ... 833s Unpacking libboost-iostreams1.83.0:arm64 (1.83.0-2ubuntu1) ... 833s Selecting previously unselected package libboost-thread1.83.0:arm64. 833s Preparing to unpack .../16-libboost-thread1.83.0_1.83.0-2ubuntu1_arm64.deb ... 833s Unpacking libboost-thread1.83.0:arm64 (1.83.0-2ubuntu1) ... 833s Selecting previously unselected package librados2. 833s Preparing to unpack .../17-librados2_18.2.0-0ubuntu7_arm64.deb ... 833s Unpacking librados2 (18.2.0-0ubuntu7) ... 833s Selecting previously unselected package libpmemobj1:arm64. 833s Preparing to unpack .../18-libpmemobj1_1.13.1-1.1_arm64.deb ... 833s Unpacking libpmemobj1:arm64 (1.13.1-1.1) ... 833s Selecting previously unselected package librbd1. 833s Preparing to unpack .../19-librbd1_18.2.0-0ubuntu7_arm64.deb ... 833s Unpacking librbd1 (18.2.0-0ubuntu7) ... 833s Selecting previously unselected package fio. 834s Preparing to unpack .../20-fio_3.36-1build1_arm64.deb ... 834s Unpacking fio (3.36-1build1) ... 834s Selecting previously unselected package lsscsi. 834s Preparing to unpack .../21-lsscsi_0.32-1_arm64.deb ... 834s Unpacking lsscsi (0.32-1) ... 834s Selecting previously unselected package autopkgtest-satdep. 834s Preparing to unpack .../22-2-autopkgtest-satdep.deb ... 834s Unpacking autopkgtest-satdep (0) ... 834s Setting up libconfig-general-perl (2.65-2) ... 834s Setting up libboost-thread1.83.0:arm64 (1.83.0-2ubuntu1) ... 834s Setting up libnbd0 (1.18.2-1build1) ... 834s Setting up libopeniscsiusr (2.1.9-3ubuntu1) ... 834s Setting up libglusterfs0:arm64 (11.1-4) ... 834s Setting up libboost-iostreams1.83.0:arm64 (1.83.0-2ubuntu1) ... 834s Setting up lsscsi (0.32-1) ... 834s Setting up libdaxctl1:arm64 (77-2ubuntu1) ... 834s Setting up libaio1t64:arm64 (0.3.113-6) ... 834s Setting up libisns0:arm64 (0.101-0.2) ... 834s Setting up libndctl6:arm64 (77-2ubuntu1) ... 834s Setting up librdmacm1t64:arm64 (50.0-2) ... 834s Setting up tgt (1:1.0.85-1.1ubuntu2) ... 835s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 837s Setting up libpmem1:arm64 (1.13.1-1.1) ... 837s Setting up libgfxdr0:arm64 (11.1-4) ... 837s Setting up librados2 (18.2.0-0ubuntu7) ... 837s Setting up open-iscsi (2.1.9-3ubuntu1) ... 839s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 841s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 841s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 842s Setting up libpmemobj1:arm64 (1.13.1-1.1) ... 842s Setting up librbd1 (18.2.0-0ubuntu7) ... 842s Setting up libgfrpc0:arm64 (11.1-4) ... 842s Setting up libgfapi0:arm64 (11.1-4) ... 842s Setting up fio (3.36-1build1) ... 843s Setting up autopkgtest-satdep (0) ... 843s Processing triggers for man-db (2.12.0-3) ... 845s Processing triggers for initramfs-tools (0.142ubuntu20) ... 845s update-initramfs: Generating /boot/initrd.img-6.8.0-11-generic 845s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 925s System running in EFI mode, skipping. 925s Processing triggers for libc-bin (2.39-0ubuntu6) ... 933s (Reading database ... 75712 files and directories currently installed.) 933s Removing autopkgtest-satdep (0) ... 935s autopkgtest [03:55:14]: test tgtbasedmpaths: [----------------------- 936s + targetname=iqn.2016-11.foo.com:target.iscsi 936s + pwd 936s + cwd=/tmp/autopkgtest.8j04eT/build.QUX/src 936s + testdir=/mnt/tgtmpathtest 936s + localhost=127.0.0.1 936s + portal=127.0.0.1:3260 936s + maxpaths=4 936s + backfn=backingfile 936s + expectwwid=60000000000000000e00000000010001 936s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 936s + bglog=/tmp/autopkgtest.8j04eT/tgtbasedmpaths-artifacts/test-background.log 936s + fioprep=/tmp/autopkgtest.8j04eT/tgtbasedmpaths-artifacts/path-change-prep.fio 936s + fiovrfy=/tmp/autopkgtest.8j04eT/tgtbasedmpaths-artifacts/path-change-check.fio 936s + service tgt restart 936s + truncate --size 100M backingfile 936s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 936s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 936s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.8j04eT/build.QUX/src/backingfile 936s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 937s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 937s + echo login #1 937s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 937s login #1 937s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 937s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 937s + seq 2 4 937s + echo extra login #2 937s extra login #2 937s + iscsiadm --mode session -r 1 --op new 937s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 937s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 937s + extra login #3 937s echo extra login #3 937s + iscsiadm --mode session -r 1 --op new 937s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 937s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 937s + echo extra login #4 937s + iscsiadm --mode session -r 1 --op new 937s extra login #4 937s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 937s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 937s + udevadm settle 937s + sleep 5 942s + echo Status after initial setup 942s + tgtadm --lld iscsi --mode target --op show 942s Status after initial setup 942s Target 1: iqn.2016-11.foo.com:target.iscsi 942s System information: 942s Driver: iscsi 942s State: ready 942s I_T nexus information: 942s I_T nexus: 1 942s Initiator: iqn.2004-10.com.ubuntu:01:ec1834f9edd8 alias: autopkgtest 942s Connection: 0 942s IP Address: 127.0.0.1 942s I_T nexus: 2 942s Initiator: iqn.2004-10.com.ubuntu:01:ec1834f9edd8 alias: autopkgtest 942s Connection: 0 942s IP Address: 127.0.0.1 942s I_T nexus: 3 942s Initiator: iqn.2004-10.com.ubuntu:01:ec1834f9edd8 alias: autopkgtest 942s Connection: 0 942s IP Address: 127.0.0.1 942s I_T nexus: 4 942s Initiator: iqn.2004-10.com.ubuntu:01:ec1834f9edd8 alias: autopkgtest 942s Connection: 0 942s IP Address: 127.0.0.1 942s LUN information: 942s LUN: 0 942s Type: controller 942s SCSI ID: IET 00010000 942s SCSI SN: beaf10 942s Size: 0 MB, Block size: 1 942s Online: Yes 942s Removable media: No 942s Prevent removal: No 942s Readonly: No 942s SWP: No 942s Thin-provisioning: No 942s Backing store type: null 942s Backing store path: None 942s Backing store flags: 942s LUN: 1 942s Type: disk 942s SCSI ID: IET 00010001 942s SCSI SN: beaf11 942s Size: 105 MB, Block size: 512 942s Online: Yes 942s Removable media: No 942s Prevent removal: No 942s Readonly: No 942s SWP: No 942s Thin-provisioning: No 942s Backing store type: rdwr 942s Backing store path: /tmp/autopkgtest.8j04eT/build.QUX/src/backingfile 942s Backing store flags: 942s Account information: 942s ACL information: 942s ALL 942s + tgtadm --lld iscsi --op show --mode conn --tid 1 942s Session: 4 942s Connection: 0 942s Initiator: iqn.2004-10.com.ubuntu:01:ec1834f9edd8 942s IP Address: 127.0.0.1 942s Session: 3 942s Connection: 0 942s Initiator: iqn.2004-10.com.ubuntu:01:ec1834f9edd8 942s IP Address: 127.0.0.1 942s Session: 2 942s Connection: 0 942s Initiator: iqn.2004-10.com.ubuntu:01:ec1834f9edd8 942s IP Address: 127.0.0.1 942s Session: 1 942s Connection: 0 942s Initiator: iqn.2004-10.com.ubuntu:01:ec1834f9edd8 942s IP Address: 127.0.0.1 942s + iscsiadm --mode session -P 1 942s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 942s Current Portal: 127.0.0.1:3260,1 942s Persistent Portal: 127.0.0.1:3260,1 942s ********** 942s Interface: 942s ********** 942s Iface Name: default 942s Iface Transport: tcp 942s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ec1834f9edd8 942s Iface IPaddress: 127.0.0.1 942s Iface HWaddress: default 942s Iface Netdev: default 942s SID: 1 942s iSCSI Connection State: LOGGED IN 942s iSCSI Session State: LOGGED_IN 942s Internal iscsid Session State: NO CHANGE 942s 942s ********** 942s Interface: 942s ********** 942s Iface Name: default 942s Iface Transport: tcp 942s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ec1834f9edd8 942s Iface IPaddress: 127.0.0.1 942s Iface HWaddress: default 942s Iface Netdev: default 942s SID: 2 942s iSCSI Connection State: LOGGED IN 942s iSCSI Session State: LOGGED_IN 942s Internal iscsid Session State: NO CHANGE 942s 942s ********** 942s Interface: 942s ********** 942s Iface Name: default 942s Iface Transport: tcp 942s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ec1834f9edd8 942s Iface IPaddress: 127.0.0.1 942s Iface HWaddress: default 942s Iface Netdev: default 942s SID: 3 942s iSCSI Connection State: LOGGED IN 942s iSCSI Session State: LOGGED_IN 942s Internal iscsid Session State: NO CHANGE 942s 942s ********** 942s Interface: 942s ********** 942s Iface Name: default 942s Iface Transport: tcp 942s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ec1834f9edd8 942s Iface IPaddress: 127.0.0.1 942s Iface HWaddress: default 942s Iface Netdev: default 942s SID: 4 942s iSCSI Connection State: LOGGED IN 942s iSCSI Session State: LOGGED_IN 942s Internal iscsid Session State: NO CHANGE 942s + lsscsi -liv 942s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 942s + multipath -v3 -ll 942s 135.599471 | set open fds limit to 1048576/1048576 942s 135.599834 | loading /lib/multipath/libchecktur.so checker 942s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 942s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 942s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/a003e00.virtio_mmio/virtio2/host0/target0:0:0/0:0:0:0] 942s [1:0:0:0] storage IET Controller 0001 - - 942s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 942s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 942s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 942s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 942s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 942s [2:0:0:0] storage IET Controller 0001 - - 942s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 942s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 942s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 942s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 942s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 942s [3:0:0:0] storage IET Controller 0001 - - 942s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 942s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 942s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 942s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 942s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 942s [4:0:0:0] storage IET Controller 0001 - - 942s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 942s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 942s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 33000000100000001 942s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 942s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 942s NVMe module may not be loaded 942s 135.600426 | checker tur: message table size = 3 942s 135.600523 | loading /lib/multipath/libprioconst.so prioritizer 942s 135.600978 | _init_foreign: foreign library "nvme" is not enabled 942s 135.628756 | sda: size = 167772160 942s 135.629529 | sda: vendor = QEMU 942s 135.629667 | sda: product = QEMU HARDDISK 942s 135.629784 | sda: rev = 2.5+ 943s 135.631351 | sda: h:b:t:l = 0:0:0:0 943s 135.632974 | sda: tgt_node_name = 943s 135.633060 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 943s 135.633074 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 943s 135.633687 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 943s 135.633740 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 943s 135.633804 | __sysfs_attr_get_value: attribute '/sys/devices/platform/a003e00.virtio_mmio/virtio2/host0/target0:0:0/0:0:0:0/vpd_pg80' can not be opened: No such file or directory 943s 135.633822 | failed to read sysfs vpd pg80: No such file or directory 943s 135.634205 | sda: fail to get serial 943s 135.634252 | sda: detect_checker = yes (setting: multipath internal) 943s 135.634685 | sda: path_checker = tur (setting: multipath internal) 943s 135.634727 | sda: checker timeout = 30 s (setting: kernel sysfs) 943s 135.634936 | sda: tur state = up 943s 135.636894 | sdb: size = 204800 943s 135.637594 | sdb: vendor = IET 943s 135.637722 | sdb: product = VIRTUAL-DISK 943s 135.637823 | sdb: rev = 0001 943s 135.639488 | sdb: h:b:t:l = 1:0:0:1 943s 135.641254 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 943s 135.641340 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 943s 135.641350 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 943s 135.641956 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 943s 135.642006 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 943s 135.642081 | sdb: serial = beaf11 943s 135.642116 | sdb: detect_checker = yes (setting: multipath internal) 943s 135.642996 | sdb: path_checker = tur (setting: multipath internal) 943s 135.643050 | sdb: checker timeout = 30 s (setting: kernel sysfs) 943s 135.643491 | sdb: tur state = up 943s 135.644249 | sdc: size = 204800 943s 135.644884 | sdc: vendor = IET 943s 135.645003 | sdc: product = VIRTUAL-DISK 943s 135.645078 | sdc: rev = 0001 943s 135.646626 | sdc: h:b:t:l = 2:0:0:1 943s 135.648201 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 943s 135.648284 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 943s 135.648292 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 943s 135.648806 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 943s 135.648855 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 943s 135.648921 | sdc: serial = beaf11 943s 135.648932 | sdc: detect_checker = yes (setting: multipath internal) 943s 135.649665 | sdc: path_checker = tur (setting: multipath internal) 943s 135.649713 | sdc: checker timeout = 30 s (setting: kernel sysfs) 943s 135.650036 | sdc: tur state = up 943s 135.650601 | sdd: size = 204800 943s 135.651189 | sdd: vendor = IET 943s 135.651297 | sdd: product = VIRTUAL-DISK 943s 135.651465 | sdd: rev = 0001 943s 135.653158 | sdd: h:b:t:l = 3:0:0:1 943s 135.655245 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 943s 135.655327 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 943s 135.655338 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 943s 135.656790 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 943s 135.656865 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 943s 135.656961 | sdd: serial = beaf11 943s 135.656999 | sdd: detect_checker = yes (setting: multipath internal) 943s 135.657664 | sdd: path_checker = tur (setting: multipath internal) 943s 135.657713 | sdd: checker timeout = 30 s (setting: kernel sysfs) 943s 135.658063 | sdd: tur state = up 943s 135.658757 | sde: size = 204800 943s 135.659547 | sde: vendor = IET 943s 135.659679 | sde: product = VIRTUAL-DISK 943s 135.659762 | sde: rev = 0001 943s 135.661407 | sde: h:b:t:l = 4:0:0:1 943s 135.663036 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 943s 135.663085 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 943s 135.663094 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 943s 135.663637 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 943s 135.663686 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 943s 135.663759 | sde: serial = beaf11 943s 135.663790 | sde: detect_checker = yes (setting: multipath internal) 943s 135.664624 | sde: path_checker = tur (setting: multipath internal) 943s 135.664710 | sde: checker timeout = 30 s (setting: kernel sysfs) 943s 135.665123 | sde: tur state = up 943s 135.665634 | loop0: device node name blacklisted 943s 135.666041 | loop1: device node name blacklisted 943s 135.666391 | loop2: device node name blacklisted 943s 135.666769 | loop3: device node name blacklisted 943s 135.667215 | loop4: device node name blacklisted 943s 135.667671 | loop5: device node name blacklisted 943s 135.668087 | loop6: device node name blacklisted 943s 135.668462 | loop7: device node name blacklisted 943s 135.668833 | dm-0: device node name blacklisted 943s 135.672649 | multipath-tools v0.9.4 (12/19, 2022) 943s 135.672760 | libdevmapper version 1.02.185 943s 135.673129 | kernel device mapper v4.48.0 943s 135.673209 | DM multipath kernel driver v1.14.0 943s 135.673635 | sdb: size = 204800 943s 135.673689 | sdb: vendor = IET 943s 135.673700 | sdb: product = VIRTUAL-DISK 943s 135.673708 | sdb: rev = 0001 943s 135.675168 | sdb: h:b:t:l = 1:0:0:1 943s 135.676279 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 943s 135.676438 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 943s 135.676470 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 943s 135.676535 | sdb: serial = beaf11 943s 135.677081 | sdb: tur state = up 943s 135.677122 | sdb: uid = 360000000000000000e00000000010001 (udev) 943s 135.677136 | sdb: detect_prio = yes (setting: multipath internal) 943s 135.677146 | sdb: prio = const (setting: multipath internal) 943s 135.677153 | sdb: prio args = "" (setting: multipath internal) 943s 135.677161 | sdb: const prio = 1 943s 135.677272 | sdc: size = 204800 943s 135.677321 | sdc: vendor = IET 943s 135.677333 | sdc: product = VIRTUAL-DISK 943s 135.677341 | sdc: rev = 0001 943s 135.679014 | sdc: h:b:t:l = 2:0:0:1 943s 135.679806 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 943s 135.679928 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 943s 135.679942 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 943s 135.680057 | sdc: serial = beaf11 943s 135.680517 | sdc: tur state = up 943s 135.680564 | sdc: uid = 360000000000000000e00000000010001 (udev) 943s 135.680575 | sdc: detect_prio = yes (setting: multipath internal) 943s 135.680587 | sdc: prio = const (setting: multipath internal) 943s 135.680594 | sdc: prio args = "" (setting: multipath internal) 943s 135.680601 | sdc: const prio = 1 943s 135.680717 | sdd: size = 204800 943s 135.680768 | sdd: vendor = IET 943s 135.680779 | sdd: product = VIRTUAL-DISK 943s 135.680788 | sdd: rev = 0001 943s 135.682326 | sdd: h:b:t:l = 3:0:0:1 943s 135.682952 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 943s 135.683079 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 943s 135.683121 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 943s 135.683194 | sdd: serial = beaf11 943s 135.683697 | sdd: tur state = up 943s 135.683747 | sdd: uid = 360000000000000000e00000000010001 (udev) 943s 135.683757 | sdd: detect_prio = yes (setting: multipath internal) 943s 135.683767 | sdd: prio = const (setting: multipath internal) 943s 135.683775 | sdd: prio args = "" (setting: multipath internal) 943s 135.683782 | sdd: const prio = 1 943s 135.683899 | sde: size = 204800 943s 135.683953 | sde: vendor = IET 943s 135.683963 | sde: product = VIRTUAL-DISK 943s 135.683972 | sde: rev = 0001 943s 135.685509 | sde: h:b:t:l = 4:0:0:1 943s 135.686133 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 943s 135.686262 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 943s 135.686306 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 943s 135.686373 | sde: serial = beaf11 943s 135.686808 | sde: tur state = up 943s 135.686849 | sde: uid = 360000000000000000e00000000010001 (udev) 943s 135.686859 | sde: detect_prio = yes (setting: multipath internal) 943s 135.686868 | sde: prio = const (setting: multipath internal) 943s 135.686875 | sde: prio args = "" (setting: multipath internal) 943s 135.686882 | sde: const prio = 1 943s ===== paths list ===== 943s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 943s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 943s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 943s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 943s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 943s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 943s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 943s size=100M features='0' hwhandler='0' wp=rw 943s |-+- policy='service-time 0' prio=1 status=active 943s | `- 1:0:0:1 sdb 8:16 active ready running 943s |-+- policy='service-time 0' prio=1 status=enabled 943s | `- 2:0:0:1 sdc 8:32 active ready running 943s |-+- policy='service-time 0' prio=1 status=enabled 943s | `- 3:0:0:1 sdd 8:48 active ready running 943s `-+- policy='service-time 0' prio=1 status=enabled 943s `- 4:0:0:1 sde 8:64 active ready running 943s 135.690276 | unloading tur checker 943s 135.690535 | unloading const prioritizer 943s + dmsetup table 943s 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 943s Test WWN should now point to DM 943s + echo Test WWN should now point to DM 943s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 943s + grep dm 943s ../../dm-0 943s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 943s mke2fs 1.47.0 (5-Feb-2023) 943s Creating filesystem with 25600 4k blocks and 25600 inodes 943s 943s Allocating group tables: 0/1 done 943s Writing inode tables: 0/1 done 943s Creating journal (1024 blocks): done 943s Writing superblocks and filesystem accounting information: 0/1 done 943s 943s + udevadm settle 943s + sleep 3s 946s + mkdir -p /mnt/tgtmpathtest 946s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 946s + cat 946s + cat 946s + fio --max-jobs=4 /tmp/autopkgtest.8j04eT/tgtbasedmpaths-artifacts/path-change-prep.fio 946s 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 946s fio-3.36 946s Starting 1 thread 946s write-phase: Laying out IO file (1 file / 17592186044415MiB) 948s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 949s 949s write-phase: (groupid=0, jobs=1): err= 0: pid=6327: Tue Mar 26 03:55:27 2024 949s write: IOPS=622, BW=38.9MiB/s (40.8MB/s)(87.6MiB/2253msec); 0 zone resets 949s clat (usec): min=1255, max=3303, avg=1574.13, stdev=193.64 949s lat (usec): min=1278, max=3328, avg=1598.60, stdev=194.43 949s clat percentiles (usec): 949s | 1.00th=[ 1287], 5.00th=[ 1319], 10.00th=[ 1352], 20.00th=[ 1401], 949s | 30.00th=[ 1434], 40.00th=[ 1483], 50.00th=[ 1549], 60.00th=[ 1614], 949s | 70.00th=[ 1680], 80.00th=[ 1745], 90.00th=[ 1827], 95.00th=[ 1893], 949s | 99.00th=[ 2073], 99.50th=[ 2114], 99.90th=[ 2999], 99.95th=[ 3294], 949s | 99.99th=[ 3294] 949s bw ( KiB/s): min=38528, max=44416, per=100.00%, avg=40320.00, stdev=2755.22, samples=4 949s iops : min= 602, max= 694, avg=630.00, stdev=43.05, samples=4 949s lat (msec) : 2=98.08%, 4=1.85% 949s cpu : usr=2.31%, sys=12.57%, ctx=1404, majf=0, minf=0 949s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 949s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 949s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 949s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 949s latency : target=0, window=0, percentile=100.00%, depth=1 949s 949s Run status group 0 (all jobs): 949s WRITE: bw=38.9MiB/s (40.8MB/s), 38.9MiB/s-38.9MiB/s (40.8MB/s-40.8MB/s), io=87.6MiB (91.9MB), run=2253-2253msec 949s 949s Disk stats (read/write): 949s dm-0: ios=1/1329, sectors=8/170112, merge=0/0, ticks=1/1900, in_queue=1901, util=95.81%, aggrios=0/351, aggsectors=2/44884, aggrmerge=0/0, aggrticks=0/495, aggrin_queue=496, aggrutil=95.11% 949s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 949s sdb: ios=1/1404, sectors=8/179536, merge=0/0, ticks=1/1983, in_queue=1984, util=95.11% 949s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 949s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 949s + echo Starting the path changes in background 949s Starting the path changes in background 949s + date +Pre FIO %H:%M:%S.%N 949s Pre FIO 03:55:27.988238024 949s + fio --max-jobs=4 /tmp/autopkgtest.8j04eT/tgtbasedmpaths-artifacts/path-change-check.fio 949s 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 949s fio-3.36 949s Starting 1 thread 1129s 1129s verify-phase: (groupid=0, jobs=1): err= 0: pid=6342: Tue Mar 26 03:58:28 2024 1129s read: IOPS=1386, BW=86.6MiB/s (90.9MB/s)(15.2GiB/180001msec) 1129s clat (usec): min=488, max=68031, avg=665.47, stdev=276.21 1129s lat (usec): min=488, max=68032, avg=666.29, stdev=276.23 1129s clat percentiles (usec): 1129s | 1.00th=[ 562], 5.00th=[ 578], 10.00th=[ 594], 20.00th=[ 611], 1129s | 30.00th=[ 627], 40.00th=[ 635], 50.00th=[ 652], 60.00th=[ 668], 1129s | 70.00th=[ 685], 80.00th=[ 709], 90.00th=[ 742], 95.00th=[ 766], 1129s | 99.00th=[ 848], 99.50th=[ 898], 99.90th=[ 1713], 99.95th=[ 3425], 1129s | 99.99th=[ 9503] 1129s bw ( KiB/s): min=36352, max=100096, per=100.00%, avg=88767.92, stdev=5977.57, samples=359 1129s iops : min= 568, max= 1564, avg=1386.92, stdev=93.37, samples=359 1129s lat (usec) : 500=0.01%, 750=92.20%, 1000=7.55% 1129s lat (msec) : 2=0.17%, 4=0.04%, 10=0.03%, 20=0.01%, 50=0.01% 1129s lat (msec) : 100=0.01% 1129s cpu : usr=8.91%, sys=16.88%, ctx=249599, majf=0, minf=16 1129s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 1129s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1129s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1129s issued rwts: total=249545,0,0,0 short=0,0,0,0 dropped=0,0,0,0 1129s latency : target=0, window=0, percentile=100.00%, depth=1 1129s 1129s Run status group 0 (all jobs): 1129s READ: bw=86.6MiB/s (90.9MB/s), 86.6MiB/s-86.6MiB/s (90.9MB/s-90.9MB/s), io=15.2GiB (16.4GB), run=180001-180001msec 1129s 1129s Disk stats (read/write): 1129s dm-0: ios=249615/9, sectors=31923808/12912, merge=0/8, ticks=151460/305, in_queue=151976, util=100.00%, aggrios=17672/2, aggsectors=2259288/3228, aggrmerge=0/0, aggrticks=10219/23, aggrin_queue=10243, aggrutil=99.16% 1129s sdd: ios=14393/0, sectors=1840896/0, merge=0/0, ticks=8110/0, in_queue=8111, util=33.23% 1129s sdb: ios=13328/8, sectors=1704576/12912, merge=0/0, ticks=8000/94, in_queue=8094, util=99.16% 1129s sde: ios=28769/0, sectors=3679872/0, merge=0/0, ticks=16586/0, in_queue=16586, util=40.26% 1129s sdc: ios=14198/0, sectors=1811808/0, merge=0/0, ticks=8183/0, in_queue=8183, util=50.38% 1129s + date +Post FIO %H:%M:%S.%N 1129s Post FIO 03:58:28.337837786 1129s + echo FIO verify test with changing paths - OK 1129s + echo Report log of background activity 1129s + cat /tmp/autopkgtest.8j04eT/tgtbasedmpaths-artifacts/test-background.log 1129s FIO verify test with changing paths - OK 1129s Report log of background activity 1129s + iscsiadm --mode session 1129s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s + sleep 10s 1129s + date +MP report (expect 4) %H:%M:%S.%N 1129s MP report (expect 4) 03:55:38.012004469 1129s + multipath -ll 1129s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1129s size=100M features='0' hwhandler='0' wp=rw 1129s |-+- policy='service-time 0' prio=1 status=active 1129s | `- 1:0:0:1 sdb 8:16 active ready running 1129s |-+- policy='service-time 0' prio=1 status=enabled 1129s | `- 2:0:0:1 sdc 8:32 active ready running 1129s |-+- policy='service-time 0' prio=1 status=enabled 1129s | `- 3:0:0:1 sdd 8:48 active ready running 1129s `-+- policy='service-time 0' prio=1 status=enabled 1129s `- 4:0:0:1 sde 8:64 active ready running 1129s + date +UN-plug path 1 %H:%M:%S.%N 1129s UN-plug path 1 03:55:38.095170824 1129s + iscsiadm --mode session -r 1 -u 1129s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1129s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1129s + iscsiadm --mode session 1129s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s + sleep 10s 1129s + date +MP report (expect 3) %H:%M:%S.%N 1129s MP report (expect 3) 03:55:48.269094227 1129s + multipath -ll 1129s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1129s size=100M features='0' hwhandler='0' wp=rw 1129s |-+- policy='service-time 0' prio=1 status=active 1129s | `- 2:0:0:1 sdc 8:32 active ready running 1129s |-+- policy='service-time 0' prio=1 status=enabled 1129s | `- 3:0:0:1 sdd 8:48 active ready running 1129s `-+- policy='service-time 0' prio=1 status=enabled 1129s `- 4:0:0:1 sde 8:64 active ready running 1129s + date +UN-plug path 2 %H:%M:%S.%N 1129s UN-plug path 2 03:55:48.351697159 1129s + iscsiadm --mode session -r 2 -u 1129s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1129s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1129s + iscsiadm --mode session 1129s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s + sleep 10s 1129s + date +MP report (expect 2) %H:%M:%S.%N 1129s MP report (expect 2) 03:55:58.513381034 1129s + multipath -ll 1129s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1129s size=100M features='0' hwhandler='0' wp=rw 1129s |-+- policy='service-time 0' prio=1 status=active 1129s | `- 3:0:0:1 sdd 8:48 active ready running 1129s `-+- policy='service-time 0' prio=1 status=enabled 1129s `- 4:0:0:1 sde 8:64 active ready running 1129s + date +UN-plug path 3 %H:%M:%S.%N 1129s UN-plug path 3 03:55:58.578021101 1129s + iscsiadm --mode session -r 3 -u 1129s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1129s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1129s + iscsiadm --mode session 1129s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s + sleep 10s 1129s + date +MP report (expect 1) %H:%M:%S.%N 1129s MP report (expect 1) 03:56:08.718518876 1129s + multipath -ll 1129s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1129s size=100M features='0' hwhandler='0' wp=rw 1129s `-+- policy='service-time 0' prio=1 status=active 1129s `- 4:0:0:1 sde 8:64 active ready running 1129s + date +Add paths 5/6/7/8 %H:%M:%S.%N 1129s Add paths 5/6/7/8 03:56:08.772177428 1129s + iscsiadm --mode session -r 4 --op new 1129s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1129s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1129s + iscsiadm --mode session -r 4 --op new 1129s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1129s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1129s + iscsiadm --mode session -r 4 --op new 1129s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1129s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1129s + iscsiadm --mode session -r 4 --op new 1129s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1129s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1129s + iscsiadm --mode session 1129s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s + sleep 10s 1129s + date +MP report (expect 5) %H:%M:%S.%N 1129s MP report (expect 5) 03:56:19.122645959 1129s + multipath -ll 1129s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1129s size=100M features='0' hwhandler='0' wp=rw 1129s |-+- policy='service-time 0' prio=1 status=active 1129s | `- 4:0:0:1 sde 8:64 active ready running 1129s |-+- policy='service-time 0' prio=1 status=enabled 1129s | `- 1:0:0:1 sdb 8:16 active ready running 1129s |-+- policy='service-time 0' prio=1 status=enabled 1129s | `- 2:0:0:1 sdc 8:32 active ready running 1129s |-+- policy='service-time 0' prio=1 status=enabled 1129s | `- 3:0:0:1 sdd 8:48 active ready running 1129s `-+- policy='service-time 0' prio=1 status=enabled 1129s `- 5:0:0:1 sdf 8:80 active ready running 1129s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 1129s UN-plug multiple paths 4/7/8 03:56:19.234633450 1129s + iscsiadm --mode session -r 4 -u 1129s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1129s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1129s + iscsiadm --mode session -r 7 -u 1129s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1129s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1129s + iscsiadm --mode session -r 8 -u 1129s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1129s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1129s + iscsiadm --mode session 1129s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1129s + sleep 10s 1129s + date +Restart multipath daemon %H:%M:%S.%N 1129s Restart multipath daemon 03:56:29.591398057 1129s + systemctl restart multipathd 1129s + sleep 10s 1129s + date +Final background report (expect 2) %H:%M:%S.%N 1129s Final background report (expect 2) 03:56:39.803310662 1129s + multipath -ll 1129s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1129s size=100M features='0' hwhandler='0' wp=rw 1129s |-+- policy='service-time 0' prio=1 status=active 1129s | `- 1:0:0:1 sdb 8:16 active ready running 1129s `-+- policy='service-time 0' prio=1 status=enabled 1129s `- 2:0:0:1 sdc 8:32 active ready running 1129s Final stats 1129s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1129s iSCSI SNMP: 1129s txdata_octets: 8577960 1129s rxdata_octets: 11686467492 1129s noptx_pdus: 0 1129s scsicmd_pdus: 178440 1129s tmfcmd_pdus: 0 1129s login_pdus: 0 1129s text_pdus: 0 1129s dataout_pdus: 0 1129s logout_pdus: 0 1129s snack_pdus: 0 1129s noprx_pdus: 0 1129s scsirsp_pdus: 178440 1129s tmfrsp_pdus: 0 1129s textrsp_pdus: 0 1129s datain_pdus: 178406 1129s logoutrsp_pdus: 0 1129s r2t_pdus: 0 1129s async_pdus: 0 1129s rjt_pdus: 0 1129s digest_err: 0 1129s timeout_err: 0 1129s iSCSI Extended: 1129s tx_sendpage_failures: 0 1129s rx_discontiguous_hdr: 0 1129s eh_abort_cnt: 0 1129s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1129s iSCSI SNMP: 1129s txdata_octets: 7560 1129s rxdata_octets: 1098116 1129s noptx_pdus: 0 1129s scsicmd_pdus: 128 1129s tmfcmd_pdus: 0 1129s login_pdus: 0 1129s text_pdus: 0 1129s dataout_pdus: 0 1129s logout_pdus: 0 1129s snack_pdus: 0 1129s noprx_pdus: 0 1129s scsirsp_pdus: 128 1129s tmfrsp_pdus: 0 1129s textrsp_pdus: 0 1129s datain_pdus: 104 1129s logoutrsp_pdus: 0 1129s r2t_pdus: 0 1129s async_pdus: 0 1129s rjt_pdus: 0 1129s digest_err: 0 1129s timeout_err: 0 1129s iSCSI Extended: 1129s tx_sendpage_failures: 0 1129s rx_discontiguous_hdr: 0 1129s eh_abort_cnt: 0 1129s + sync 1129s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1129s + echo Final stats 1129s + iscsiadm --mode session --stats 1129s + journalctl --no-pager -u multipathd 1129s Mar 25 07:57:38 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1129s Mar 25 07:57:39 ubuntu multipathd[314]: multipathd v0.9.4: start up 1129s Mar 25 07:57:39 ubuntu multipathd[314]: reconfigure: setting up paths and maps 1129s Mar 25 07:57:39 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1129s -- Boot ff154ffd7aca447d83a228c12e46ca93 -- 1129s Mar 25 08:07:05 auto-syncubuntu-noble-daily-arm64-server-20240312-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1129s Mar 25 08:07:05 auto-syncubuntu-noble-daily-arm64-server-20240312-disk1 multipathd[264]: multipathd v0.9.4: start up 1129s Mar 25 08:07:05 auto-syncubuntu-noble-daily-arm64-server-20240312-disk1 multipathd[264]: reconfigure: setting up paths and maps 1129s Mar 25 08:07:05 auto-syncubuntu-noble-daily-arm64-server-20240312-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1129s Mar 25 08:07:34 auto-syncubuntu-noble-daily-arm64-server-20240312-disk1 multipathd[264]: multipathd: shut down 1129s Mar 25 08:07:34 auto-syncubuntu-noble-daily-arm64-server-20240312-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1129s Mar 25 08:07:34 auto-syncubuntu-noble-daily-arm64-server-20240312-disk1 systemd[1]: multipathd.service: Deactivated successfully. 1129s Mar 25 08:07:34 auto-syncubuntu-noble-daily-arm64-server-20240312-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1129s -- Boot 4591455c8e434153893d3af754a2485d -- 1129s Mar 26 03:48:27 auto-syncubuntu-noble-daily-arm64-server-20240312-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1129s Mar 26 03:48:27 auto-syncubuntu-noble-daily-arm64-server-20240312-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1129s Mar 26 03:48:27 auto-syncubuntu-noble-daily-arm64-server-20240312-disk1 multipathd[310]: multipathd v0.9.4: start up 1129s Mar 26 03:48:27 auto-syncubuntu-noble-daily-arm64-server-20240312-disk1 multipathd[310]: reconfigure: setting up paths and maps 1129s Mar 26 03:50:53 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1129s Mar 26 03:50:53 autopkgtest multipathd[310]: multipathd: shut down 1129s Mar 26 03:50:53 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 1129s Mar 26 03:50:53 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1129s -- Boot 5bdaf2e7f3f74581aad3bdf1aa9f6f72 -- 1129s Mar 26 03:51:07 autopkgtest multipathd[276]: multipathd v0.9.4: start up 1129s Mar 26 03:51:07 autopkgtest multipathd[276]: reconfigure: setting up paths and maps 1129s Mar 26 03:51:07 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1129s -- Boot 8fee4f98f84647a8ab1cc9476b58e425 -- 1129s Mar 26 03:53:11 autopkgtest multipathd[272]: multipathd v0.9.4: start up 1129s Mar 26 03:53:11 autopkgtest multipathd[272]: reconfigure: setting up paths and maps 1129s Mar 26 03:53:11 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1129s Mar 26 03:55:16 autopkgtest multipathd[272]: 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] 1129s Mar 26 03:55:16 autopkgtest multipathd[272]: sdc [8:32]: path added to devmap mpatha 1129s Mar 26 03:55:16 autopkgtest multipathd[272]: mpatha: performing delayed actions 1129s Mar 26 03:55:16 autopkgtest multipathd[272]: 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] 1129s Mar 26 03:55:38 autopkgtest multipathd[272]: sdb: mark as failed 1129s Mar 26 03:55:38 autopkgtest multipathd[272]: mpatha: remaining active paths: 3 1129s Mar 26 03:55:38 autopkgtest multipathd[272]: 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] 1129s Mar 26 03:55:38 autopkgtest multipathd[272]: check_removed_paths: sdb: freeing path in removed state 1129s Mar 26 03:55:38 autopkgtest multipathd[272]: 8:16: path removed from map mpatha 1129s Mar 26 03:55:48 autopkgtest multipathd[272]: 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] 1129s Mar 26 03:55:48 autopkgtest multipathd[272]: check_removed_paths: sdc: freeing path in removed state 1129s Mar 26 03:55:48 autopkgtest multipathd[272]: 8:32: path removed from map mpatha 1129s Mar 26 03:55:58 autopkgtest multipathd[272]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 1129s Mar 26 03:55:58 autopkgtest multipathd[272]: check_removed_paths: sdd: freeing path in removed state 1129s Mar 26 03:55:58 autopkgtest multipathd[272]: 8:48: path removed from map mpatha 1129s Mar 26 03:56:09 autopkgtest multipathd[272]: 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] 1129s Mar 26 03:56:09 autopkgtest multipathd[272]: sdb [8:16]: path added to devmap mpatha 1129s Mar 26 03:56:09 autopkgtest multipathd[272]: 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] 1129s Mar 26 03:56:09 autopkgtest multipathd[272]: sdc [8:32]: path added to devmap mpatha 1129s Mar 26 03:56:09 autopkgtest multipathd[272]: 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] 1129s Mar 26 03:56:09 autopkgtest multipathd[272]: sdd [8:48]: path added to devmap mpatha 1129s Mar 26 03:56:09 autopkgtest multipathd[272]: 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] 1129s Mar 26 03:56:09 autopkgtest multipathd[272]: sdf [8:80]: path added to devmap mpatha 1129s Mar 26 03:56:19 autopkgtest multipathd[272]: sde: mark as failed 1129s Mar 26 03:56:19 autopkgtest multipathd[272]: mpatha: remaining active paths: 4 1129s Mar 26 03:56:19 autopkgtest multipathd[272]: 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] 1129s Mar 26 03:56:19 autopkgtest multipathd[272]: check_removed_paths: sde: freeing path in removed state 1129s Mar 26 03:56:19 autopkgtest multipathd[272]: 8:64: path removed from map mpatha 1129s Mar 26 03:56:19 autopkgtest multipathd[272]: 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] 1129s Mar 26 03:56:19 autopkgtest multipathd[272]: check_removed_paths: sdd: freeing path in removed state 1129s Mar 26 03:56:19 autopkgtest multipathd[272]: 8:48: path removed from map mpatha 1129s Mar 26 03:56:19 autopkgtest multipathd[272]: 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] 1129s Mar 26 03:56:19 autopkgtest multipathd[272]: check_removed_paths: sdf: freeing path in removed state 1129s Mar 26 03:56:19 autopkgtest multipathd[272]: 8:80: path removed from map mpatha 1129s Mar 26 03:56:29 autopkgtest multipathd[272]: multipathd: shut down 1129s Mar 26 03:56:29 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1129s Mar 26 03:56:29 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 1129s Mar 26 03:56:29 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1129s Mar 26 03:56:29 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1129s Mar 26 03:56:29 autopkgtest multipathd[6675]: multipathd v0.9.4: start up 1129s Mar 26 03:56:29 autopkgtest multipathd[6675]: reconfigure: setting up paths and maps 1129s Mar 26 03:56:29 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1129s + echo Check final path status 1129s + multipath -ll 1129s Check final path status 1129s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1129s size=100M features='0' hwhandler='0' wp=rw 1129s |-+- policy='service-time 0' prio=1 status=active 1129s | `- 1:0:0:1 sdb 8:16 active ready running 1129s `-+- policy='service-time 0' prio=1 status=enabled 1129s `- 2:0:0:1 sdc 8:32 active ready running 1129s + multipath -ll 1129s + grep --count status= 1129s + diskc=2 1129s + multipath -ll 1129s + grep --count status=active 1129s + diska=1 1129s + multipath -ll 1129s + grep --count status=enabled 1129s + diske=1 1129s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 1129s + echo OK 1129s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 1129s OK 1129s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1129s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1129s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1129s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1129s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 1130s autopkgtest [03:58:29]: test tgtbasedmpaths: -----------------------] 1130s tgtbasedmpaths PASS 1130s autopkgtest [03:58:29]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 1131s autopkgtest [03:58:30]: @@@@@@@@@@@@@@@@@@@@ summary 1131s kpartx-file-loopback PASS 1131s tgtbasedmpaths PASS 1142s Creating nova instance adt-noble-arm64-multipath-tools-20240326-033939-juju-7f2275-prod-proposed-migration-environment-2 from image adt/ubuntu-noble-arm64-server-20240325.img (UUID fbff6e39-d9aa-49f2-b0e3-b936ee7913ab)... 1142s Creating nova instance adt-noble-arm64-multipath-tools-20240326-033939-juju-7f2275-prod-proposed-migration-environment-2 from image adt/ubuntu-noble-arm64-server-20240325.img (UUID fbff6e39-d9aa-49f2-b0e3-b936ee7913ab)...