0s autopkgtest [11:59:54]: starting date and time: 2024-05-02 11:59:54+0000 0s autopkgtest [11:59:54]: git checkout: 699e7f9f ssh-setup/nova: explicitely set 'fqdn' in cloud-init 0s autopkgtest [11:59:54]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.7m66n0sg/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:libaio --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=libaio/0.3.113-8 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos01-ppc64el-20.secgroup --name adt-oracular-ppc64el-multipath-tools-20240502-115954-juju-7f2275-prod-proposed-migration-environment-2-89469591-b31b-4f27-9ff5-674b6299af8d --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://us.ports.ubuntu.com/ubuntu-ports/ 130s autopkgtest [12:02:04]: testbed dpkg architecture: ppc64el 130s autopkgtest [12:02:04]: testbed apt version: 2.7.14build2 130s autopkgtest [12:02:04]: @@@@@@@@@@@@@@@@@@@@ test bed setup 131s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [64.7 kB] 131s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [2800 B] 131s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3496 B] 131s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.9 kB] 131s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [219 kB] 132s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [59.7 kB] 132s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1260 B] 132s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [146 kB] 132s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [756 B] 132s Fetched 537 kB in 1s (719 kB/s) 132s Reading package lists... 134s Reading package lists... 134s Building dependency tree... 134s Reading state information... 134s Calculating upgrade... 134s The following packages will be upgraded: 134s libaio1t64 135s 1 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 135s Need to get 8088 B of archives. 135s After this operation, 0 B of additional disk space will be used. 135s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libaio1t64 ppc64el 0.3.113-8 [8088 B] 135s Fetched 8088 B in 0s (55.6 kB/s) 135s (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 ... 72135 files and directories currently installed.) 135s Preparing to unpack .../libaio1t64_0.3.113-8_ppc64el.deb ... 135s Unpacking libaio1t64:ppc64el (0.3.113-8) over (0.3.113-6build1) ... 135s Setting up libaio1t64:ppc64el (0.3.113-8) ... 135s Processing triggers for libc-bin (2.39-0ubuntu8) ... 135s Reading package lists... 135s Building dependency tree... 135s Reading state information... 135s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 136s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 136s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 136s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 136s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 137s Reading package lists... 137s Reading package lists... 137s Building dependency tree... 137s Reading state information... 137s Calculating upgrade... 137s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 137s Reading package lists... 138s Building dependency tree... 138s Reading state information... 138s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 141s autopkgtest [12:02:15]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 141s autopkgtest [12:02:15]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 144s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 144s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 144s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 144s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 144s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 144s gpgv: issuer "steve.langasek@ubuntu.com" 144s gpgv: Can't check signature: No public key 144s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 144s autopkgtest [12:02:18]: testing package multipath-tools version 0.9.4-5ubuntu8 145s autopkgtest [12:02:19]: build not needed 145s autopkgtest [12:02:19]: test kpartx-file-loopback: preparing testbed 146s Reading package lists... 146s Building dependency tree... 146s Reading state information... 146s Starting pkgProblemResolver with broken count: 0 146s Starting 2 pkgProblemResolver with broken count: 0 146s Done 147s The following additional packages will be installed: 147s liburing2 qemu-utils 147s Recommended packages: 147s qemu-block-extra 147s The following NEW packages will be installed: 147s autopkgtest-satdep liburing2 qemu-utils 147s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 147s Need to get 2329 kB/2330 kB of archives. 147s After this operation, 15.4 MB of additional disk space will be used. 147s Get:1 /tmp/autopkgtest.s4fYGk/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 147s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.5-1build1 [26.0 kB] 147s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 148s Fetched 2329 kB in 1s (3380 kB/s) 148s Selecting previously unselected package liburing2:ppc64el. 148s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72135 files and directories currently installed.) 148s Preparing to unpack .../liburing2_2.5-1build1_ppc64el.deb ... 148s Unpacking liburing2:ppc64el (2.5-1build1) ... 148s Selecting previously unselected package qemu-utils. 148s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 148s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 148s Selecting previously unselected package autopkgtest-satdep. 148s Preparing to unpack .../1-autopkgtest-satdep.deb ... 148s Unpacking autopkgtest-satdep (0) ... 148s Setting up liburing2:ppc64el (2.5-1build1) ... 148s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 148s Setting up autopkgtest-satdep (0) ... 148s Processing triggers for man-db (2.12.0-4build2) ... 149s Processing triggers for libc-bin (2.39-0ubuntu8) ... 151s (Reading database ... 72155 files and directories currently installed.) 151s Removing autopkgtest-satdep (0) ... 152s autopkgtest [12:02:26]: test kpartx-file-loopback: [----------------------- 152s Formatting 'foo.img', fmt=raw size=20971520 153s Creating new GPT entries in memory. 153s Warning: The kernel is still using the old partition table. 153s The new table will be used at the next reboot or after you 153s run partprobe(8) or kpartx(8) 153s The operation has completed successfully. 153s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 153s standard_filename: OK 153s del devmap : loop0p1 153s No devices found 153s standard_filename_cleanup: OK 153s Formatting 'fou du FaFa.img', fmt=raw size=20971520 154s Creating new GPT entries in memory. 154s Warning: The kernel is still using the old partition table. 154s The new table will be used at the next reboot or after you 154s run partprobe(8) or kpartx(8) 154s The operation has completed successfully. 154s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 154s filename_with_spaces: OK 154s del devmap : loop0p1 154s No devices found 154s filename_with_spaces_cleanup: OK 154s autopkgtest [12:02:28]: test kpartx-file-loopback: -----------------------] 155s kpartx-file-loopback PASS 155s autopkgtest [12:02:29]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 155s autopkgtest [12:02:29]: test tgtbasedmpaths: preparing testbed 278s autopkgtest [12:04:32]: testbed dpkg architecture: ppc64el 279s autopkgtest [12:04:33]: testbed apt version: 2.7.14build2 279s autopkgtest [12:04:33]: @@@@@@@@@@@@@@@@@@@@ test bed setup 280s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [64.7 kB] 280s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [219 kB] 280s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3496 B] 280s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.9 kB] 280s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [2800 B] 280s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [59.7 kB] 280s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1260 B] 280s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [146 kB] 280s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [756 B] 280s Fetched 537 kB in 1s (553 kB/s) 280s Reading package lists... 283s Reading package lists... 283s Building dependency tree... 283s Reading state information... 283s Calculating upgrade... 283s The following packages will be upgraded: 283s libaio1t64 283s 1 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 283s Need to get 8088 B of archives. 283s After this operation, 0 B of additional disk space will be used. 283s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libaio1t64 ppc64el 0.3.113-8 [8088 B] 284s Fetched 8088 B in 0s (56.0 kB/s) 284s (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 ... 72135 files and directories currently installed.) 284s Preparing to unpack .../libaio1t64_0.3.113-8_ppc64el.deb ... 284s Unpacking libaio1t64:ppc64el (0.3.113-8) over (0.3.113-6build1) ... 284s Setting up libaio1t64:ppc64el (0.3.113-8) ... 284s Processing triggers for libc-bin (2.39-0ubuntu8) ... 284s Reading package lists... 284s Building dependency tree... 284s Reading state information... 284s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 285s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 285s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 285s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 285s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 286s Reading package lists... 286s Reading package lists... 286s Building dependency tree... 286s Reading state information... 286s Calculating upgrade... 287s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 287s Reading package lists... 287s Building dependency tree... 287s Reading state information... 287s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 291s Reading package lists... 291s Building dependency tree... 291s Reading state information... 291s Starting pkgProblemResolver with broken count: 0 291s Starting 2 pkgProblemResolver with broken count: 0 291s Done 291s The following additional packages will be installed: 291s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 291s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 291s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 291s librdmacm1t64 lsscsi open-iscsi tgt 291s Suggested packages: 291s fio-examples gnuplot tgt-glusterfs tgt-rbd 291s Recommended packages: 291s finalrd 291s The following NEW packages will be installed: 291s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 291s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 291s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 291s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 291s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 291s Need to get 10.8 MB/10.8 MB of archives. 291s After this operation, 49.9 MB of additional disk space will be used. 291s Get:1 /tmp/autopkgtest.s4fYGk/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 291s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu4 [54.4 kB] 292s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-0.3build3 [119 kB] 292s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu4 [389 kB] 292s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 292s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 292s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu6 [256 kB] 292s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4build3 [21.5 kB] 292s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4build3 [311 kB] 293s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4build3 [47.0 kB] 293s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4build3 [100 kB] 293s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.0-1 [97.3 kB] 293s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 293s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 293s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 293s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-2.1ubuntu3 [260 kB] 293s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-2.1ubuntu3 [280 kB] 293s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu6 [4050 kB] 294s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 294s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu6 [3612 kB] 295s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.36-1build2 [716 kB] 295s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 295s Preconfiguring packages ... 295s Fetched 10.8 MB in 3s (3204 kB/s) 295s Selecting previously unselected package libopeniscsiusr. 295s (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 ... 72135 files and directories currently installed.) 295s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu4_ppc64el.deb ... 295s Unpacking libopeniscsiusr (2.1.9-3ubuntu4) ... 295s Selecting previously unselected package libisns0t64:ppc64el. 295s Preparing to unpack .../01-libisns0t64_0.101-0.3build3_ppc64el.deb ... 295s Unpacking libisns0t64:ppc64el (0.101-0.3build3) ... 295s Selecting previously unselected package open-iscsi. 295s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu4_ppc64el.deb ... 295s Unpacking open-iscsi (2.1.9-3ubuntu4) ... 295s Selecting previously unselected package librdmacm1t64:ppc64el. 295s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 295s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 295s Selecting previously unselected package libconfig-general-perl. 295s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 295s Unpacking libconfig-general-perl (2.65-2) ... 295s Selecting previously unselected package tgt. 295s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu6_ppc64el.deb ... 295s Unpacking tgt (1:1.0.85-1.1ubuntu6) ... 295s Selecting previously unselected package libgfxdr0:ppc64el. 295s Preparing to unpack .../06-libgfxdr0_11.1-4build3_ppc64el.deb ... 295s Unpacking libgfxdr0:ppc64el (11.1-4build3) ... 295s Selecting previously unselected package libglusterfs0:ppc64el. 295s Preparing to unpack .../07-libglusterfs0_11.1-4build3_ppc64el.deb ... 295s Unpacking libglusterfs0:ppc64el (11.1-4build3) ... 295s Selecting previously unselected package libgfrpc0:ppc64el. 295s Preparing to unpack .../08-libgfrpc0_11.1-4build3_ppc64el.deb ... 295s Unpacking libgfrpc0:ppc64el (11.1-4build3) ... 295s Selecting previously unselected package libgfapi0:ppc64el. 295s Preparing to unpack .../09-libgfapi0_11.1-4build3_ppc64el.deb ... 295s Unpacking libgfapi0:ppc64el (11.1-4build3) ... 295s Selecting previously unselected package libnbd0. 295s Preparing to unpack .../10-libnbd0_1.20.0-1_ppc64el.deb ... 295s Unpacking libnbd0 (1.20.0-1) ... 295s Selecting previously unselected package libdaxctl1:ppc64el. 295s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 295s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 295s Selecting previously unselected package libndctl6:ppc64el. 295s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 295s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 295s Selecting previously unselected package libpmem1:ppc64el. 295s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 295s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 295s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 295s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 295s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 295s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 295s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-2.1ubuntu3_ppc64el.deb ... 295s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 295s Selecting previously unselected package librados2. 295s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu6_ppc64el.deb ... 295s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 296s Selecting previously unselected package libpmemobj1:ppc64el. 296s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 296s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 296s Selecting previously unselected package librbd1. 296s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu6_ppc64el.deb ... 296s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 296s Selecting previously unselected package fio. 296s Preparing to unpack .../19-fio_3.36-1build2_ppc64el.deb ... 296s Unpacking fio (3.36-1build2) ... 296s Selecting previously unselected package lsscsi. 296s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 296s Unpacking lsscsi (0.32-1build1) ... 296s Selecting previously unselected package autopkgtest-satdep. 296s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 296s Unpacking autopkgtest-satdep (0) ... 296s Setting up libconfig-general-perl (2.65-2) ... 296s Setting up libisns0t64:ppc64el (0.101-0.3build3) ... 296s Setting up libboost-thread1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 296s Setting up libnbd0 (1.20.0-1) ... 296s Setting up libopeniscsiusr (2.1.9-3ubuntu4) ... 296s Setting up libglusterfs0:ppc64el (11.1-4build3) ... 296s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-2.1ubuntu3) ... 296s Setting up lsscsi (0.32-1build1) ... 296s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 296s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 296s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 296s Setting up tgt (1:1.0.85-1.1ubuntu6) ... 296s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 297s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 297s Setting up libgfxdr0:ppc64el (11.1-4build3) ... 297s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 297s Setting up open-iscsi (2.1.9-3ubuntu4) ... 297s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 298s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 298s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 298s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 298s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu6) ... 298s Setting up libgfrpc0:ppc64el (11.1-4build3) ... 298s Setting up libgfapi0:ppc64el (11.1-4build3) ... 298s Setting up fio (3.36-1build2) ... 299s Setting up autopkgtest-satdep (0) ... 299s Processing triggers for man-db (2.12.0-4build2) ... 300s Processing triggers for initramfs-tools (0.142ubuntu25) ... 300s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 300s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 307s Processing triggers for libc-bin (2.39-0ubuntu8) ... 309s (Reading database ... 72376 files and directories currently installed.) 309s Removing autopkgtest-satdep (0) ... 311s autopkgtest [12:05:05]: test tgtbasedmpaths: [----------------------- 311s + targetname=iqn.2016-11.foo.com:target.iscsi 311s + pwd 311s + cwd=/tmp/autopkgtest.s4fYGk/build.ZGU/src 311s + testdir=/mnt/tgtmpathtest 311s + localhost=127.0.0.1 311s + portal=127.0.0.1:3260 311s + maxpaths=4 311s + backfn=backingfile 311s + expectwwid=60000000000000000e00000000010001 311s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 311s + bglog=/tmp/autopkgtest.s4fYGk/tgtbasedmpaths-artifacts/test-background.log 311s + fioprep=/tmp/autopkgtest.s4fYGk/tgtbasedmpaths-artifacts/path-change-prep.fio 311s + fiovrfy=/tmp/autopkgtest.s4fYGk/tgtbasedmpaths-artifacts/path-change-check.fio 311s + service tgt restart 312s + truncate --size 100M backingfile 312s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 312s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 312s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.s4fYGk/build.ZGU/src/backingfile 312s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 312s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 312s login #1 312s + echo login #1 312s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 312s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 312s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 312s + seq 2 4 312s + extra login #2 312s echo extra login #2 312s + iscsiadm --mode session -r 1 --op new 312s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 312s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 312s extra login #3 312s + echo extra login #3 312s + iscsiadm --mode session -r 1 --op new 312s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 312s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 312s + echo extra login #4 312s + iscsiadm --mode session -r 1 --op new 312s extra login #4 312s + udevadm settle 312s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 312s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 312s + sleep 5 317s Status after initial setup 317s + echo Status after initial setup 317s + tgtadm --lld iscsi --mode target --op show 317s Target 1: iqn.2016-11.foo.com:target.iscsi 317s System information: 317s Driver: iscsi 317s State: ready 317s I_T nexus information: 317s I_T nexus: 1 317s Initiator: iqn.2004-10.com.ubuntu:01:e86c77771864 alias: autopkgtest 317s Connection: 0 317s IP Address: 127.0.0.1 317s I_T nexus: 2 317s Initiator: iqn.2004-10.com.ubuntu:01:e86c77771864 alias: autopkgtest 317s Connection: 0 317s IP Address: 127.0.0.1 317s I_T nexus: 3 317s Initiator: iqn.2004-10.com.ubuntu:01:e86c77771864 alias: autopkgtest 317s Connection: 0 317s IP Address: 127.0.0.1 317s I_T nexus: 4 317s Initiator: iqn.2004-10.com.ubuntu:01:e86c77771864 alias: autopkgtest 317s Connection: 0 317s IP Address: 127.0.0.1 317s LUN information: 317s LUN: 0 317s Type: controller 317s SCSI ID: IET 00010000 317s SCSI SN: beaf10 317s Size: 0 MB, Block size: 1 317s Online: Yes 317s Removable media: No 317s Prevent removal: No 317s Readonly: No 317s SWP: No 317s Thin-provisioning: No 317s Backing store type: null 317s Backing store path: None 317s Backing store flags: 317s LUN: 1 317s Type: disk 317s SCSI ID: IET 00010001 317s SCSI SN: beaf11 317s Size: 105 MB, Block size: 512 317s Online: Yes 317s Removable media: No 317s Prevent removal: No 317s Readonly: No 317s SWP: No 317s Thin-provisioning: No 317s Backing store type: rdwr 317s Backing store path: /tmp/autopkgtest.s4fYGk/build.ZGU/src/backingfile 317s Backing store flags: 317s Account information: 317s ACL information: 317s ALL 317s + tgtadm --lld iscsi --op show --mode conn --tid 1 317s + iscsiadm --mode session -P 1 317s Session: 4 317s Connection: 0 317s Initiator: iqn.2004-10.com.ubuntu:01:e86c77771864 317s IP Address: 127.0.0.1 317s Session: 3 317s Connection: 0 317s Initiator: iqn.2004-10.com.ubuntu:01:e86c77771864 317s IP Address: 127.0.0.1 317s Session: 2 317s Connection: 0 317s Initiator: iqn.2004-10.com.ubuntu:01:e86c77771864 317s IP Address: 127.0.0.1 317s Session: 1 317s Connection: 0 317s Initiator: iqn.2004-10.com.ubuntu:01:e86c77771864 317s IP Address: 127.0.0.1 317s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 317s Current Portal: 127.0.0.1:3260,1 317s Persistent Portal: 127.0.0.1:3260,1 317s ********** 317s Interface: 317s ********** 317s Iface Name: default 317s Iface Transport: tcp 317s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:e86c77771864 317s Iface IPaddress: 127.0.0.1 317s Iface HWaddress: default 317s Iface Netdev: default 317s SID: 1 317s iSCSI Connection State: LOGGED IN 317s iSCSI Session State: LOGGED_IN 317s Internal iscsid Session State: NO CHANGE 317s 317s ********** 317s Interface: 317s ********** 317s Iface Name: default 317s Iface Transport: tcp 317s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:e86c77771864 317s Iface IPaddress: 127.0.0.1 317s Iface HWaddress: default 317s Iface Netdev: default 317s SID: 2 317s iSCSI Connection State: LOGGED IN 317s iSCSI Session State: LOGGED_IN 317s Internal iscsid Session State: NO CHANGE 317s 317s ********** 317s Interface: 317s ********** 317s Iface Name: default 317s Iface Transport: tcp 317s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:e86c77771864 317s Iface IPaddress: 127.0.0.1 317s Iface HWaddress: default 317s Iface Netdev: default 317s SID: 3 317s iSCSI Connection State: LOGGED IN 317s iSCSI Session State: LOGGED_IN 317s Internal iscsid Session State: NO CHANGE 317s 317s ********** 317s Interface: 317s ********** 317s Iface Name: default 317s Iface Transport: tcp 317s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:e86c77771864 317s Iface IPaddress: 127.0.0.1 317s Iface HWaddress: default 317s Iface Netdev: default 317s SID: 4 317s iSCSI Connection State: LOGGED IN 317s iSCSI Session State: LOGGED_IN 317s Internal iscsid Session State: NO CHANGE 317s + lsscsi -liv 317s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 317s + multipath -v3 -ll 317s 76.326753 | set open fds limit to 1048576/1048576 317s 76.326827 | loading /lib/multipath/libchecktur.so checker 317s 76.326920 | checker tur: message table size = 3 317s 76.326947 | loading /lib/multipath/libprioconst.so prioritizer 317s 76.327058 | _init_foreign: foreign library "nvme" is not enabled 317s 76.332402 | sda: size = 167772160 317s 76.332566 | sda: vendor = QEMU 317s 76.332607 | sda: product = QEMU HARDDISK 317s 76.332628 | sda: rev = 2.5+ 317s 76.333234 | sda: h:b:t:l = 0:0:0:0 317s 76.333541 | sda: tgt_node_name = 317s 76.333562 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 317s 76.333564 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 317s 76.333710 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 317s 76.333731 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 317s 76.333743 | __sysfs_attr_get_value: attribute '/sys/devices/pci0000:00/0000:00:02.0/virtio1/host0/target0:0:0/0:0:0:0/vpd_pg80' can not be opened: No such file or directory 317s 76.333747 | failed to read sysfs vpd pg80: No such file or directory 317s 76.333953 | sda: fail to get serial 317s 76.333974 | sda: detect_checker = yes (setting: multipath internal) 317s 76.334142 | sda: path_checker = tur (setting: multipath internal) 317s 76.334170 | sda: checker timeout = 30 s (setting: kernel sysfs) 317s 76.334308 | sda: tur state = up 317s 76.334611 | sdb: size = 204800 317s 76.334756 | sdb: vendor = IET 317s 76.334795 | sdb: product = VIRTUAL-DISK 317s 76.334815 | sdb: rev = 0001 317s 76.335453 | sdb: h:b:t:l = 1:0:0:1 317s 76.335807 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 317s 76.335827 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 317s 76.335830 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 317s 76.335981 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 317s 76.335985 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 317s 76.335999 | sdb: serial = beaf11 317s 76.336046 | sdb: detect_checker = yes (setting: multipath internal) 317s 76.336315 | sdb: path_checker = tur (setting: multipath internal) 317s 76.336337 | sdb: checker timeout = 30 s (setting: kernel sysfs) 317s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 317s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 317s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/pci0000:00/0000:00:02.0/virtio1/host0/target0:0:0/0:0:0:0] 317s [1:0:0:0] storage IET Controller 0001 - - 317s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 317s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 317s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb SIET_VIRTUAL-DISK_beaf11 317s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 317s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 317s [2:0:0:0] storage IET Controller 0001 - - 317s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 317s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 317s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 33000000100000001 317s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 317s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 317s [3:0:0:0] storage IET Controller 0001 - - 317s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 317s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 317s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 317s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 317s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 317s [4:0:0:0] storage IET Controller 0001 - - 317s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 317s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 317s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 317s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 317s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 317s NVMe module may not be loaded 317s 76.336501 | sdb: tur state = up 317s 76.336640 | sdc: size = 204800 317s 76.336783 | sdc: vendor = IET 317s 76.336822 | sdc: product = VIRTUAL-DISK 317s 76.336843 | sdc: rev = 0001 317s 76.337516 | sdc: h:b:t:l = 2:0:0:1 317s 76.337861 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 317s 76.337882 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 317s 76.337884 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 317s 76.338028 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 317s 76.338047 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 317s 76.338061 | sdc: serial = beaf11 317s 76.338063 | sdc: detect_checker = yes (setting: multipath internal) 317s 76.338273 | sdc: path_checker = tur (setting: multipath internal) 317s 76.338295 | sdc: checker timeout = 30 s (setting: kernel sysfs) 317s 76.338401 | sdc: tur state = up 317s 76.338542 | sdd: size = 204800 317s 76.338687 | sdd: vendor = IET 317s 76.338726 | sdd: product = VIRTUAL-DISK 317s 76.338747 | sdd: rev = 0001 317s 76.339414 | sdd: h:b:t:l = 3:0:0:1 317s 76.339760 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 317s 76.339781 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 317s 76.339783 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 317s 76.339935 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 317s 76.339955 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 317s 76.339969 | sdd: serial = beaf11 317s 76.339971 | sdd: detect_checker = yes (setting: multipath internal) 317s 76.340191 | sdd: path_checker = tur (setting: multipath internal) 317s 76.340217 | sdd: checker timeout = 30 s (setting: kernel sysfs) 317s 76.340322 | sdd: tur state = up 317s 76.340462 | sde: size = 204800 317s 76.340605 | sde: vendor = IET 317s 76.340644 | sde: product = VIRTUAL-DISK 317s 76.340665 | sde: rev = 0001 317s 76.341340 | sde: h:b:t:l = 4:0:0:1 317s 76.341684 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 317s 76.341704 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 317s 76.341707 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 317s 76.341856 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 317s 76.341876 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 317s 76.341890 | sde: serial = beaf11 317s 76.341892 | sde: detect_checker = yes (setting: multipath internal) 317s 76.342089 | sde: path_checker = tur (setting: multipath internal) 317s 76.342109 | sde: checker timeout = 30 s (setting: kernel sysfs) 317s 76.342262 | sde: tur state = up 317s 76.342370 | loop0: device node name blacklisted 317s 76.342472 | loop1: device node name blacklisted 317s 76.342570 | loop2: device node name blacklisted 317s 76.342669 | loop3: device node name blacklisted 317s 76.342767 | loop4: device node name blacklisted 317s 76.342864 | loop5: device node name blacklisted 317s 76.342961 | loop6: device node name blacklisted 317s 76.343058 | loop7: device node name blacklisted 317s 76.343163 | dm-0: device node name blacklisted 317s 76.344146 | multipath-tools v0.9.4 (12/19, 2022) 317s 76.344178 | libdevmapper version 1.02.185 317s 76.344312 | kernel device mapper v4.48.0 317s 76.344341 | DM multipath kernel driver v1.14.0 317s 76.344444 | sdb: size = 204800 317s 76.344465 | sdb: vendor = IET 317s 76.344468 | sdb: product = VIRTUAL-DISK 317s 76.344470 | sdb: rev = 0001 317s 76.345088 | sdb: h:b:t:l = 1:0:0:1 317s 76.345214 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 317s 76.345251 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 317s 76.345253 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 317s 76.345265 | sdb: serial = beaf11 317s 76.345419 | sdb: tur state = up 317s 76.345438 | sdb: uid = 360000000000000000e00000000010001 (udev) 317s 76.345441 | sdb: detect_prio = yes (setting: multipath internal) 317s 76.345444 | sdb: prio = const (setting: multipath internal) 317s 76.345446 | sdb: prio args = "" (setting: multipath internal) 317s 76.345448 | sdb: const prio = 1 317s 76.345471 | sdc: size = 204800 317s 76.345475 | sdc: vendor = IET 317s 76.345479 | sdc: product = VIRTUAL-DISK 317s 76.345481 | sdc: rev = 0001 317s 76.346087 | sdc: h:b:t:l = 2:0:0:1 317s 76.346241 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 317s 76.346278 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 317s 76.346281 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 317s 76.346292 | sdc: serial = beaf11 317s 76.346399 | sdc: tur state = up 317s 76.346419 | sdc: uid = 360000000000000000e00000000010001 (udev) 317s 76.346421 | sdc: detect_prio = yes (setting: multipath internal) 317s 76.346423 | sdc: prio = const (setting: multipath internal) 317s 76.346425 | sdc: prio args = "" (setting: multipath internal) 317s 76.346427 | sdc: const prio = 1 317s 76.346450 | sdd: size = 204800 317s 76.346454 | sdd: vendor = IET 317s 76.346456 | sdd: product = VIRTUAL-DISK 317s 76.346459 | sdd: rev = 0001 317s 76.347063 | sdd: h:b:t:l = 3:0:0:1 317s 76.347186 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 317s 76.347222 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 317s 76.347224 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 317s 76.347236 | sdd: serial = beaf11 317s 76.347341 | sdd: tur state = up 317s 76.347361 | sdd: uid = 360000000000000000e00000000010001 (udev) 317s 76.347363 | sdd: detect_prio = yes (setting: multipath internal) 317s 76.347366 | sdd: prio = const (setting: multipath internal) 317s 76.347368 | sdd: prio args = "" (setting: multipath internal) 317s 76.347370 | sdd: const prio = 1 317s 76.347392 | sde: size = 204800 317s 76.347396 | sde: vendor = IET 317s 76.347398 | sde: product = VIRTUAL-DISK 317s 76.347402 | sde: rev = 0001 317s 76.348029 | sde: h:b:t:l = 4:0:0:1 317s 76.348157 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 317s 76.348193 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 317s 76.348195 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 317s 76.348206 | sde: serial = beaf11 317s 76.348311 | sde: tur state = up 317s 76.348331 | sde: uid = 360000000000000000e00000000010001 (udev) 317s 76.348333 | sde: detect_prio = yes (setting: multipath internal) 317s 76.348336 | sde: prio = const (setting: multipath internal) 317s 76.348338 | sde: prio args = "" (setting: multipath internal) 317s 76.348340 | sde: const prio = 1 317s 76.349042 | unloading tur checker 317s 76.349088 | unloading const prioritizer 317s + dmsetup table 317s + echo Test WWN should now point to DM 317s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 317s + grep dm 317s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 317s mke2fs 1.47.0 (5-Feb-2023) 317s ===== paths list ===== 317s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 317s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 317s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 317s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 317s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 317s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 317s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 317s size=100M features='0' hwhandler='0' wp=rw 317s |-+- policy='service-time 0' prio=1 status=active 317s | `- 1:0:0:1 sdb 8:16 active ready running 317s |-+- policy='service-time 0' prio=1 status=enabled 317s | `- 2:0:0:1 sdc 8:32 active ready running 317s |-+- policy='service-time 0' prio=1 status=enabled 317s | `- 3:0:0:1 sdd 8:48 active ready running 317s `-+- policy='service-time 0' prio=1 status=enabled 317s `- 4:0:0:1 sde 8:64 active ready running 317s 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 317s Test WWN should now point to DM 317s ../../dm-0 317s Creating filesystem with 25600 4k blocks and 25600 inodes 317s 317s Allocating group tables: 0/1 done 317s Writing inode tables: 0/1 done 317s Creating journal (1024 blocks): done 317s Writing superblocks and filesystem accounting information: 0/1 + udevadm settle 317s done 317s 317s + sleep 3s 320s + mkdir -p /mnt/tgtmpathtest 320s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 320s + cat 320s + cat 320s + fio --max-jobs=4 /tmp/autopkgtest.s4fYGk/tgtbasedmpaths-artifacts/path-change-prep.fio 320s 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 320s fio-3.36 320s Starting 1 thread 320s write-phase: Laying out IO file (1 file / 17592186044415MiB) 321s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 321s 321s write-phase: (groupid=0, jobs=1): err= 0: pid=6310: Thu May 2 12:05:15 2024 321s write: IOPS=1817, BW=114MiB/s (119MB/s)(87.6MiB/772msec); 0 zone resets 321s clat (usec): min=392, max=2004, avg=528.22, stdev=96.52 321s lat (usec): min=413, max=2024, avg=548.61, stdev=96.69 321s clat percentiles (usec): 321s | 1.00th=[ 416], 5.00th=[ 437], 10.00th=[ 445], 20.00th=[ 461], 321s | 30.00th=[ 474], 40.00th=[ 510], 50.00th=[ 537], 60.00th=[ 553], 321s | 70.00th=[ 562], 80.00th=[ 570], 90.00th=[ 586], 95.00th=[ 603], 321s | 99.00th=[ 758], 99.50th=[ 971], 99.90th=[ 1876], 99.95th=[ 2008], 321s | 99.99th=[ 2008] 321s bw ( KiB/s): min=117632, max=117632, per=100.00%, avg=117632.00, stdev= 0.00, samples=1 321s iops : min= 1838, max= 1838, avg=1838.00, stdev= 0.00, samples=1 321s lat (usec) : 500=37.21%, 750=61.65%, 1000=0.57% 321s lat (msec) : 2=0.43%, 4=0.07% 321s cpu : usr=4.15%, sys=7.91%, ctx=1404, majf=0, minf=0 321s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 321s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 321s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 321s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 321s latency : target=0, window=0, percentile=100.00%, depth=1 321s 321s Run status group 0 (all jobs): 321s WRITE: bw=114MiB/s (119MB/s), 114MiB/s-114MiB/s (119MB/s-119MB/s), io=87.6MiB (91.9MB), run=772-772msec 321s 321s Disk stats (read/write): 321s dm-0: ios=1/1174, sectors=8/162808, merge=0/0, ticks=0/680, in_queue=685, util=90.69%, aggrios=0/351, aggsectors=2/48082, aggrmerge=0/0, aggrticks=1/181, aggrin_queue=182, aggrutil=90.74% 321s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 321s sdb: ios=2/1405, sectors=8/192328, merge=0/0, ticks=5/725, in_queue=730, util=90.74% 321s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 321s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 321s Starting the path changes in background 321s + echo Starting the path changes in background 321s + date +Pre FIO %H:%M:%S.%N 321s Pre FIO 12:05:15.662305813 321s + fio --max-jobs=4 /tmp/autopkgtest.s4fYGk/tgtbasedmpaths-artifacts/path-change-check.fio 321s 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 321s fio-3.36 321s Starting 1 thread 501s 501s verify-phase: (groupid=0, jobs=1): err= 0: pid=6317: Thu May 2 12:08:15 2024 501s read: IOPS=3367, BW=210MiB/s (221MB/s)(37.0GiB/180001msec) 501s clat (usec): min=85, max=51268, avg=273.98, stdev=168.92 501s lat (usec): min=85, max=51268, avg=274.10, stdev=168.93 501s clat percentiles (usec): 501s | 1.00th=[ 139], 5.00th=[ 161], 10.00th=[ 180], 20.00th=[ 198], 501s | 30.00th=[ 212], 40.00th=[ 223], 50.00th=[ 241], 60.00th=[ 281], 501s | 70.00th=[ 318], 80.00th=[ 351], 90.00th=[ 400], 95.00th=[ 433], 501s | 99.00th=[ 502], 99.50th=[ 693], 99.90th=[ 1156], 99.95th=[ 1418], 501s | 99.99th=[ 3130] 501s bw ( KiB/s): min=126464, max=351616, per=100.00%, avg=215794.43, stdev=53466.57, samples=359 501s iops : min= 1976, max= 5494, avg=3371.74, stdev=835.40, samples=359 501s lat (usec) : 100=0.16%, 250=52.49%, 500=46.28%, 750=0.64%, 1000=0.25% 501s lat (msec) : 2=0.16%, 4=0.02%, 10=0.01%, 20=0.01%, 50=0.01% 501s lat (msec) : 100=0.01% 501s cpu : usr=9.37%, sys=7.19%, ctx=606355, majf=0, minf=1 501s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 501s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 501s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 501s issued rwts: total=606236,0,0,0 short=0,0,0,0 dropped=0,0,0,0 501s latency : target=0, window=0, percentile=100.00%, depth=1 501s 501s Run status group 0 (all jobs): 501s READ: bw=210MiB/s (221MB/s), 210MiB/s-210MiB/s (221MB/s-221MB/s), io=37.0GiB (39.7GB), run=180001-180001msec 501s 501s Disk stats (read/write): 501s dm-0: ios=606352/7, sectors=77557176/120, merge=30/8, ticks=168201/38, in_queue=168271, util=100.00%, aggrios=39499/1, aggsectors=5052174/30, aggrmerge=0/0, aggrticks=10897/0, aggrin_queue=10898, aggrutil=99.15% 501s sdd: ios=33021/0, sectors=4223744/0, merge=0/0, ticks=8648/0, in_queue=8648, util=32.99% 501s sdb: ios=33901/7, sectors=4336128/120, merge=0/0, ticks=8371/3, in_queue=8375, util=99.15% 501s sde: ios=61105/0, sectors=7815936/0, merge=0/0, ticks=17668/0, in_queue=17667, util=40.04% 501s sdc: ios=29971/0, sectors=3832888/0, merge=0/0, ticks=8902/0, in_queue=8902, util=50.02% 501s + date +Post FIO %H:%M:%S.%N 501s + echo FIO verify test with changing paths - OK 501s + echo Report log of background activity 501s + cat /tmp/autopkgtest.s4fYGk/tgtbasedmpaths-artifacts/test-background.log 501s Post FIO 12:08:15.866612999 501s FIO verify test with changing paths - OK 501s Report log of background activity 501s + iscsiadm --mode session 501s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s + sleep 10s 501s + date +MP report (expect 4) %H:%M:%S.%N 501s MP report (expect 4) 12:05:25.668784286 501s + multipath -ll 501s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 501s size=100M features='0' hwhandler='0' wp=rw 501s |-+- policy='service-time 0' prio=1 status=active 501s | `- 1:0:0:1 sdb 8:16 active ready running 501s |-+- policy='service-time 0' prio=1 status=enabled 501s | `- 2:0:0:1 sdc 8:32 active ready running 501s |-+- policy='service-time 0' prio=1 status=enabled 501s | `- 3:0:0:1 sdd 8:48 active ready running 501s `-+- policy='service-time 0' prio=1 status=enabled 501s `- 4:0:0:1 sde 8:64 active ready running 501s + date +UN-plug path 1 %H:%M:%S.%N 501s UN-plug path 1 12:05:25.696857780 501s + iscsiadm --mode session -r 1 -u 501s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 501s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 501s + iscsiadm --mode session 501s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s + sleep 10s 501s + date +MP report (expect 3) %H:%M:%S.%N 501s MP report (expect 3) 12:05:35.790137808 501s + multipath -ll 501s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 501s size=100M features='0' hwhandler='0' wp=rw 501s |-+- policy='service-time 0' prio=1 status=active 501s | `- 2:0:0:1 sdc 8:32 active ready running 501s |-+- policy='service-time 0' prio=1 status=enabled 501s | `- 3:0:0:1 sdd 8:48 active ready running 501s `-+- policy='service-time 0' prio=1 status=enabled 501s `- 4:0:0:1 sde 8:64 active ready running 501s + date +UN-plug path 2 %H:%M:%S.%N 501s UN-plug path 2 12:05:35.814399614 501s + iscsiadm --mode session -r 2 -u 501s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 501s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 501s + iscsiadm --mode session 501s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s + sleep 10s 501s + date +MP report (expect 2) %H:%M:%S.%N 501s MP report (expect 2) 12:05:45.911902434 501s + multipath -ll 501s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 501s size=100M features='0' hwhandler='0' wp=rw 501s |-+- policy='service-time 0' prio=1 status=active 501s | `- 3:0:0:1 sdd 8:48 active ready running 501s `-+- policy='service-time 0' prio=1 status=enabled 501s `- 4:0:0:1 sde 8:64 active ready running 501s + date +UN-plug path 3 %H:%M:%S.%N 501s UN-plug path 3 12:05:45.930629663 501s + iscsiadm --mode session -r 3 -u 501s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 501s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 501s + iscsiadm --mode session 501s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s + sleep 10s 501s + date +MP report (expect 1) %H:%M:%S.%N 501s MP report (expect 1) 12:05:56.021931385 501s + multipath -ll 501s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 501s size=100M features='0' hwhandler='0' wp=rw 501s `-+- policy='service-time 0' prio=1 status=active 501s `- 4:0:0:1 sde 8:64 active ready running 501s + date +Add paths 5/6/7/8 %H:%M:%S.%N 501s Add paths 5/6/7/8 12:05:56.038106491 501s + iscsiadm --mode session -r 4 --op new 501s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 501s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 501s + iscsiadm --mode session -r 4 --op new 501s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 501s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 501s + iscsiadm --mode session -r 4 --op new 501s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 501s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 501s + iscsiadm --mode session -r 4 --op new 501s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 501s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 501s + iscsiadm --mode session 501s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s + sleep 10s 501s + date +MP report (expect 5) %H:%M:%S.%N 501s MP report (expect 5) 12:06:06.191329695 501s + multipath -ll 501s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 501s size=100M features='0' hwhandler='0' wp=rw 501s |-+- policy='service-time 0' prio=1 status=active 501s | `- 4:0:0:1 sde 8:64 active ready running 501s |-+- policy='service-time 0' prio=1 status=enabled 501s | `- 1:0:0:1 sdb 8:16 active ready running 501s |-+- policy='service-time 0' prio=1 status=enabled 501s | `- 2:0:0:1 sdc 8:32 active ready running 501s |-+- policy='service-time 0' prio=1 status=enabled 501s | `- 3:0:0:1 sdd 8:48 active ready running 501s `-+- policy='service-time 0' prio=1 status=enabled 501s `- 5:0:0:1 sdf 8:80 active ready running 501s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 501s UN-plug multiple paths 4/7/8 12:06:06.225219919 501s + iscsiadm --mode session -r 4 -u 501s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 501s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 501s + iscsiadm --mode session -r 7 -u 501s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 501s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 501s + iscsiadm --mode session -r 8 -u 501s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 501s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 501s + iscsiadm --mode session 501s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 501s + sleep 10s 501s + date +Restart multipath daemon %H:%M:%S.%N 501s Restart multipath daemon 12:06:16.526276185 501s + systemctl restart multipathd 501s + sleep 10s 501s + date +Final background report (expect 2) %H:%M:%S.%N 501s Final background report (expect 2) 12:06:26.608650871 501s + multipath -ll 501s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 501s size=100M features='0' hwhandler='0' wp=rw 501s |-+- policy='service-time 0' prio=1 status=active 501s | `- 1:0:0:1 sdb 8:16 active ready running 501s `-+- policy='service-time 0' prio=1 status=enabled 501s `- 2:0:0:1 sdc 8:32 active ready running 501s Final stats 501s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 501s iSCSI SNMP: 501s txdata_octets: 21478728 501s rxdata_octets: 29302559156 501s noptx_pdus: 0 501s scsicmd_pdus: 447206 501s tmfcmd_pdus: 0 501s login_pdus: 0 501s text_pdus: 0 501s dataout_pdus: 0 501s logout_pdus: 0 501s snack_pdus: 0 501s noprx_pdus: 0 501s scsirsp_pdus: 447206 501s tmfrsp_pdus: 0 501s textrsp_pdus: 0 501s datain_pdus: 447173 501s logoutrsp_pdus: 0 501s r2t_pdus: 0 501s async_pdus: 0 501s rjt_pdus: 0 501s digest_err: 0 501s timeout_err: 0 501s iSCSI Extended: 501s tx_sendpage_failures: 0 501s rx_discontiguous_hdr: 0 501s eh_abort_cnt: 0 501s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 501s iSCSI SNMP: 501s txdata_octets: 6552 501s rxdata_octets: 1515012 501s noptx_pdus: 0 501s scsicmd_pdus: 106 501s tmfcmd_pdus: 0 501s login_pdus: 0 501s text_pdus: 0 501s dataout_pdus: 0 501s logout_pdus: 0 501s snack_pdus: 0 501s noprx_pdus: 0 501s scsirsp_pdus: 106 501s tmfrsp_pdus: 0 501s textrsp_pdus: 0 501s datain_pdus: 83 501s logoutrsp_pdus: 0 501s r2t_pdus: 0 501s async_pdus: 0 501s rjt_pdus: 0 501s digest_err: 0 501s timeout_err: 0 501s iSCSI Extended: 501s tx_sendpage_failures: 0 501s rx_discontiguous_hdr: 0 501s eh_abort_cnt: 0 501s May 02 09:53:54 creation-test-1 multipathd[258]: multipathd v0.9.4: start up 501s May 02 09:53:54 creation-test-1 multipathd[258]: reconfigure: setting up paths and maps 501s May 02 09:53:54 creation-test-1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 501s May 02 09:54:52 adtubuntu-oracular-ppc64el-server-20240501 multipathd[258]: multipathd: shut down 501s May 02 09:54:52 adtubuntu-oracular-ppc64el-server-20240501 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 501s May 02 09:54:52 adtubuntu-oracular-ppc64el-server-20240501 systemd[1]: multipathd.service: Deactivated successfully. 501s May 02 09:54:52 adtubuntu-oracular-ppc64el-server-20240501 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 501s -- Boot 2564153e4af24b53b18667d2f2e478b0 -- 501s May 02 09:55:15 adtubuntu-oracular-ppc64el-server-20240501 multipathd[260]: multipathd v0.9.4: start up 501s May 02 09:55:15 adtubuntu-oracular-ppc64el-server-20240501 multipathd[260]: reconfigure: setting up paths and maps 501s May 02 09:55:15 adtubuntu-oracular-ppc64el-server-20240501 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 501s May 02 09:55:42 adtubuntu-oracular-ppc64el-server-20240501 multipathd[260]: multipathd: shut down 501s May 02 09:55:42 adtubuntu-oracular-ppc64el-server-20240501 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 501s May 02 09:55:42 adtubuntu-oracular-ppc64el-server-20240501 systemd[1]: multipathd.service: Deactivated successfully. 501s May 02 09:55:42 adtubuntu-oracular-ppc64el-server-20240501 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 501s -- Boot 18853e0b4b5b4da8b771a565b36f4ce7 -- 501s May 02 12:03:57 adtubuntu-oracular-ppc64el-server-20240501 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 501s May 02 12:03:57 adtubuntu-oracular-ppc64el-server-20240501 multipathd[329]: multipathd v0.9.4: start up 501s May 02 12:03:57 adtubuntu-oracular-ppc64el-server-20240501 multipathd[329]: reconfigure: setting up paths and maps 501s May 02 12:03:57 adtubuntu-oracular-ppc64el-server-20240501 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 501s May 02 12:05:06 autopkgtest multipathd[329]: 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] 501s May 02 12:05:06 autopkgtest multipathd[329]: sdc [8:32]: path added to devmap mpatha 501s May 02 12:05:06 autopkgtest multipathd[329]: mpatha: performing delayed actions 501s May 02 12:05:06 autopkgtest multipathd[329]: 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] 501s May 02 12:05:25 autopkgtest multipathd[329]: 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] 501s May 02 12:05:25 autopkgtest multipathd[329]: check_removed_paths: sdb: freeing path in removed state 501s May 02 12:05:25 autopkgtest multipathd[329]: 8:16: path removed from map mpatha 501s May 02 12:05:35 autopkgtest multipathd[329]: 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] 501s May 02 12:05:35 autopkgtest multipathd[329]: check_removed_paths: sdc: freeing path in removed state 501s May 02 12:05:35 autopkgtest multipathd[329]: 8:32: path removed from map mpatha 501s May 02 12:05:45 autopkgtest multipathd[329]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 501s May 02 12:05:45 autopkgtest multipathd[329]: check_removed_paths: sdd: freeing path in removed state 501s May 02 12:05:45 autopkgtest multipathd[329]: 8:48: path removed from map mpatha 501s May 02 12:05:56 autopkgtest multipathd[329]: 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] 501s May 02 12:05:56 autopkgtest multipathd[329]: sdb [8:16]: path added to devmap mpatha 501s May 02 12:05:56 autopkgtest multipathd[329]: 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] 501s May 02 12:05:56 autopkgtest multipathd[329]: sdc [8:32]: path added to devmap mpatha 501s May 02 12:05:56 autopkgtest multipathd[329]: 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] 501s May 02 12:05:56 autopkgtest multipathd[329]: sdd [8:48]: path added to devmap mpatha 501s May 02 12:05:56 autopkgtest multipathd[329]: 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] 501s May 02 12:05:56 autopkgtest multipathd[329]: sdf [8:80]: path added to devmap mpatha 501s May 02 12:06:06 autopkgtest multipathd[329]: sde: mark as failed 501s May 02 12:06:06 autopkgtest multipathd[329]: mpatha: remaining active paths: 4 501s May 02 12:06:06 autopkgtest multipathd[329]: 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] 501s May 02 12:06:06 autopkgtest multipathd[329]: check_removed_paths: sde: freeing path in removed state 501s May 02 12:06:06 autopkgtest multipathd[329]: 8:64: path removed from map mpatha 501s May 02 12:06:06 autopkgtest multipathd[329]: checker failed path 8:48 in map mpatha 501s May 02 12:06:06 autopkgtest multipathd[329]: mpatha: remaining active paths: 3 501s May 02 12:06:06 autopkgtest multipathd[329]: 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] 501s May 02 12:06:06 autopkgtest multipathd[329]: check_removed_paths: sdd: freeing path in removed state 501s May 02 12:06:06 autopkgtest multipathd[329]: 8:48: path removed from map mpatha 501s May 02 12:06:06 autopkgtest multipathd[329]: 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] 501s May 02 12:06:06 autopkgtest multipathd[329]: check_removed_paths: sdf: freeing path in removed state 501s May 02 12:06:06 autopkgtest multipathd[329]: 8:80: path removed from map mpatha 501s May 02 12:06:16 autopkgtest multipathd[329]: multipathd: shut down 501s May 02 12:06:16 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 501s May 02 12:06:16 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 501s May 02 12:06:16 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 501s May 02 12:06:16 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 501s May 02 12:06:16 autopkgtest multipathd[6696]: multipathd v0.9.4: start up 501s May 02 12:06:16 autopkgtest multipathd[6696]: reconfigure: setting up paths and maps 501s May 02 12:06:16 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 501s Check final path status 501s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 501s size=100M features='0' hwhandler='0' wp=rw 501s |-+- policy='service-time 0' prio=1 status=active 501s | `- 1:0:0:1 sdb 8:16 active ready running 501s `-+- policy='service-time 0' prio=1 status=enabled 501s `- 2:0:0:1 sdc 8:32 active ready running 501s + sync 501s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 501s + echo Final stats 501s + iscsiadm --mode session --stats 501s + journalctl --no-pager -u multipathd 501s + echo Check final path status 501s + multipath -ll 501s + multipath -ll 501s + grep --count status= 501s + diskc=2 501s + multipath -ll 501s + grep --count status=active 501s + diska=1 501s + multipath -ll 501s + grep --count status=enabled 501s + diske=1 501s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 501s + echo OK 501s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 501s OK 502s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 502s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 502s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 502s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 502s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 502s autopkgtest [12:08:16]: test tgtbasedmpaths: -----------------------] 502s autopkgtest [12:08:16]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 502s tgtbasedmpaths PASS 503s autopkgtest [12:08:17]: @@@@@@@@@@@@@@@@@@@@ summary 503s kpartx-file-loopback PASS 503s tgtbasedmpaths PASS 517s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240502-115954-juju-7f2275-prod-proposed-migration-environment-2-89469591-b31b-4f27-9ff5-674b6299af8d from image adt/ubuntu-oracular-ppc64el-server-20240502.img (UUID 9489dffc-ce38-4dbc-a2c0-b477b0ad52fa)... 517s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240502-115954-juju-7f2275-prod-proposed-migration-environment-2-89469591-b31b-4f27-9ff5-674b6299af8d from image adt/ubuntu-oracular-ppc64el-server-20240502.img (UUID 9489dffc-ce38-4dbc-a2c0-b477b0ad52fa)...