0s autopkgtest [16:19:19]: starting date and time: 2024-06-04 16:19:19+0000 0s autopkgtest [16:19:19]: git checkout: 433ed4cb Merge branch 'skia/nova_flock' into 'ubuntu/5.34+prod' 0s autopkgtest [16:19:19]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.3_kyq9c1/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:dracut --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=dracut/060+5-8ubuntu2 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos01-ppc64el-19.secgroup --name adt-oracular-ppc64el-multipath-tools-20240604-161918-juju-7f2275-prod-proposed-migration-environment-2-6294878f-f58a-459a-b484-4ddffb00045d --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/ 106s autopkgtest [16:21:05]: testbed dpkg architecture: ppc64el 106s autopkgtest [16:21:05]: testbed apt version: 2.9.3 106s autopkgtest [16:21:05]: @@@@@@@@@@@@@@@@@@@@ test bed setup 107s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 107s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [421 kB] 108s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [5784 B] 108s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [42.2 kB] 108s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [1680 B] 108s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [68.5 kB] 108s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1152 B] 108s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [401 kB] 108s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1392 B] 108s Fetched 1052 kB in 1s (916 kB/s) 108s Reading package lists... 110s Reading package lists... 110s Building dependency tree... 110s Reading state information... 111s Calculating upgrade... 111s The following packages will be upgraded: 111s dracut-install libncurses6 libncursesw6 libtinfo6 ncurses-base ncurses-bin 111s ncurses-term tmux 111s 8 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 111s Need to get 1598 kB of archives. 111s After this operation, 52.2 kB disk space will be freed. 111s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el ncurses-bin ppc64el 6.5-2 [202 kB] 111s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el ncurses-base all 6.5-2 [25.8 kB] 111s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el ncurses-term all 6.5-2 [275 kB] 111s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el libncurses6 ppc64el 6.5-2 [146 kB] 111s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el libncursesw6 ppc64el 6.5-2 [183 kB] 111s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el libtinfo6 ppc64el 6.5-2 [129 kB] 111s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el tmux ppc64el 3.4-5 [602 kB] 111s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dracut-install ppc64el 060+5-8ubuntu2 [35.3 kB] 112s Fetched 1598 kB in 1s (2517 kB/s) 112s (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 ... 72606 files and directories currently installed.) 112s Preparing to unpack .../ncurses-bin_6.5-2_ppc64el.deb ... 112s Unpacking ncurses-bin (6.5-2) over (6.4+20240113-1ubuntu2) ... 112s Setting up ncurses-bin (6.5-2) ... 112s (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 ... 72606 files and directories currently installed.) 112s Preparing to unpack .../ncurses-base_6.5-2_all.deb ... 112s Unpacking ncurses-base (6.5-2) over (6.4+20240113-1ubuntu2) ... 112s Setting up ncurses-base (6.5-2) ... 112s (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 ... 72606 files and directories currently installed.) 112s Preparing to unpack .../ncurses-term_6.5-2_all.deb ... 112s Unpacking ncurses-term (6.5-2) over (6.4+20240113-1ubuntu2) ... 113s Preparing to unpack .../libncurses6_6.5-2_ppc64el.deb ... 113s Unpacking libncurses6:ppc64el (6.5-2) over (6.4+20240113-1ubuntu2) ... 113s Preparing to unpack .../libncursesw6_6.5-2_ppc64el.deb ... 113s Unpacking libncursesw6:ppc64el (6.5-2) over (6.4+20240113-1ubuntu2) ... 113s Preparing to unpack .../libtinfo6_6.5-2_ppc64el.deb ... 113s Unpacking libtinfo6:ppc64el (6.5-2) over (6.4+20240113-1ubuntu2) ... 113s Setting up libtinfo6:ppc64el (6.5-2) ... 113s (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 ... 72611 files and directories currently installed.) 113s Preparing to unpack .../tmux_3.4-5_ppc64el.deb ... 113s Unpacking tmux (3.4-5) over (3.4-1build1) ... 113s Preparing to unpack .../dracut-install_060+5-8ubuntu2_ppc64el.deb ... 113s Unpacking dracut-install (060+5-8ubuntu2) over (060+5-8ubuntu1) ... 113s Setting up libncurses6:ppc64el (6.5-2) ... 113s Setting up libncursesw6:ppc64el (6.5-2) ... 113s Setting up dracut-install (060+5-8ubuntu2) ... 113s Setting up tmux (3.4-5) ... 113s Setting up ncurses-term (6.5-2) ... 113s Processing triggers for man-db (2.12.1-1) ... 114s Processing triggers for debianutils (5.17build1) ... 114s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 114s Reading package lists... 114s Building dependency tree... 114s Reading state information... 114s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 115s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 115s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 115s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 115s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 116s Reading package lists... 116s Reading package lists... 116s Building dependency tree... 116s Reading state information... 116s Calculating upgrade... 116s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 116s Reading package lists... 116s Building dependency tree... 116s Reading state information... 117s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 121s autopkgtest [16:21:20]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 121s autopkgtest [16:21:20]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 125s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 125s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 125s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 125s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 125s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 125s gpgv: issuer "steve.langasek@ubuntu.com" 125s gpgv: Can't check signature: No public key 125s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 125s autopkgtest [16:21:24]: testing package multipath-tools version 0.9.4-5ubuntu8 126s autopkgtest [16:21:25]: build not needed 130s autopkgtest [16:21:29]: test kpartx-file-loopback: preparing testbed 131s Reading package lists... 131s Building dependency tree... 131s Reading state information... 131s Starting pkgProblemResolver with broken count: 0 131s Starting 2 pkgProblemResolver with broken count: 0 131s Done 132s The following additional packages will be installed: 132s liburing2 qemu-utils 132s Recommended packages: 132s qemu-block-extra 132s The following NEW packages will be installed: 132s autopkgtest-satdep liburing2 qemu-utils 132s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 132s Need to get 2330 kB/2331 kB of archives. 132s After this operation, 15.4 MB of additional disk space will be used. 132s Get:1 /tmp/autopkgtest.2Rdcy8/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 132s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 132s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 134s Fetched 2330 kB in 2s (1025 kB/s) 134s Selecting previously unselected package liburing2:ppc64el. 134s (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 ... 72612 files and directories currently installed.) 134s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 134s Unpacking liburing2:ppc64el (2.6-1) ... 134s Selecting previously unselected package qemu-utils. 134s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 134s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 134s Selecting previously unselected package autopkgtest-satdep. 134s Preparing to unpack .../1-autopkgtest-satdep.deb ... 134s Unpacking autopkgtest-satdep (0) ... 134s Setting up liburing2:ppc64el (2.6-1) ... 134s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 134s Setting up autopkgtest-satdep (0) ... 134s Processing triggers for man-db (2.12.1-1) ... 135s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 137s (Reading database ... 72632 files and directories currently installed.) 137s Removing autopkgtest-satdep (0) ... 138s autopkgtest [16:21:37]: test kpartx-file-loopback: [----------------------- 138s Formatting 'foo.img', fmt=raw size=20971520 139s Creating new GPT entries in memory. 139s Warning: The kernel is still using the old partition table. 139s The new table will be used at the next reboot or after you 139s run partprobe(8) or kpartx(8) 139s The operation has completed successfully. 139s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 139s standard_filename: OK 139s del devmap : loop0p1 139s No devices found 139s standard_filename_cleanup: OK 139s Formatting 'fou du FaFa.img', fmt=raw size=20971520 140s Creating new GPT entries in memory. 140s Warning: The kernel is still using the old partition table. 140s The new table will be used at the next reboot or after you 140s run partprobe(8) or kpartx(8) 140s The operation has completed successfully. 140s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 140s filename_with_spaces: OK 140s del devmap : loop0p1 140s No devices found 140s filename_with_spaces_cleanup: OK 141s autopkgtest [16:21:40]: test kpartx-file-loopback: -----------------------] 141s kpartx-file-loopback PASS 141s autopkgtest [16:21:40]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 141s autopkgtest [16:21:40]: test tgtbasedmpaths: preparing testbed 253s autopkgtest [16:23:32]: testbed dpkg architecture: ppc64el 253s autopkgtest [16:23:32]: testbed apt version: 2.9.3 253s autopkgtest [16:23:32]: @@@@@@@@@@@@@@@@@@@@ test bed setup 254s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [110 kB] 254s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [1680 B] 254s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [42.2 kB] 254s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [421 kB] 254s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [5784 B] 254s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [68.5 kB] 254s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1152 B] 254s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [401 kB] 254s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1392 B] 254s Fetched 1052 kB in 1s (1245 kB/s) 255s Reading package lists... 257s Reading package lists... 257s Building dependency tree... 257s Reading state information... 257s Calculating upgrade... 257s The following packages will be upgraded: 257s dracut-install libncurses6 libncursesw6 libtinfo6 ncurses-base ncurses-bin 257s ncurses-term tmux 257s 8 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 257s Need to get 1598 kB of archives. 257s After this operation, 52.2 kB disk space will be freed. 257s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el ncurses-bin ppc64el 6.5-2 [202 kB] 258s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el ncurses-base all 6.5-2 [25.8 kB] 258s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el ncurses-term all 6.5-2 [275 kB] 258s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el libncurses6 ppc64el 6.5-2 [146 kB] 258s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el libncursesw6 ppc64el 6.5-2 [183 kB] 258s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el libtinfo6 ppc64el 6.5-2 [129 kB] 258s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el tmux ppc64el 3.4-5 [602 kB] 258s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dracut-install ppc64el 060+5-8ubuntu2 [35.3 kB] 258s Fetched 1598 kB in 1s (2816 kB/s) 258s (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 ... 72606 files and directories currently installed.) 258s Preparing to unpack .../ncurses-bin_6.5-2_ppc64el.deb ... 258s Unpacking ncurses-bin (6.5-2) over (6.4+20240113-1ubuntu2) ... 258s Setting up ncurses-bin (6.5-2) ... 258s (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 ... 72606 files and directories currently installed.) 258s Preparing to unpack .../ncurses-base_6.5-2_all.deb ... 258s Unpacking ncurses-base (6.5-2) over (6.4+20240113-1ubuntu2) ... 258s Setting up ncurses-base (6.5-2) ... 258s (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 ... 72606 files and directories currently installed.) 258s Preparing to unpack .../ncurses-term_6.5-2_all.deb ... 258s Unpacking ncurses-term (6.5-2) over (6.4+20240113-1ubuntu2) ... 259s Preparing to unpack .../libncurses6_6.5-2_ppc64el.deb ... 259s Unpacking libncurses6:ppc64el (6.5-2) over (6.4+20240113-1ubuntu2) ... 259s Preparing to unpack .../libncursesw6_6.5-2_ppc64el.deb ... 259s Unpacking libncursesw6:ppc64el (6.5-2) over (6.4+20240113-1ubuntu2) ... 259s Preparing to unpack .../libtinfo6_6.5-2_ppc64el.deb ... 259s Unpacking libtinfo6:ppc64el (6.5-2) over (6.4+20240113-1ubuntu2) ... 259s Setting up libtinfo6:ppc64el (6.5-2) ... 259s (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 ... 72611 files and directories currently installed.) 259s Preparing to unpack .../tmux_3.4-5_ppc64el.deb ... 259s Unpacking tmux (3.4-5) over (3.4-1build1) ... 259s Preparing to unpack .../dracut-install_060+5-8ubuntu2_ppc64el.deb ... 259s Unpacking dracut-install (060+5-8ubuntu2) over (060+5-8ubuntu1) ... 259s Setting up libncurses6:ppc64el (6.5-2) ... 259s Setting up libncursesw6:ppc64el (6.5-2) ... 259s Setting up dracut-install (060+5-8ubuntu2) ... 259s Setting up tmux (3.4-5) ... 259s Setting up ncurses-term (6.5-2) ... 259s Processing triggers for man-db (2.12.1-1) ... 260s Processing triggers for debianutils (5.17build1) ... 260s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 260s Reading package lists... 260s Building dependency tree... 260s Reading state information... 260s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 261s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 261s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 261s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 261s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 262s Reading package lists... 262s Reading package lists... 262s Building dependency tree... 262s Reading state information... 262s Calculating upgrade... 262s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 262s Reading package lists... 262s Building dependency tree... 262s Reading state information... 262s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 266s Reading package lists... 266s Building dependency tree... 266s Reading state information... 266s Starting pkgProblemResolver with broken count: 0 266s Starting 2 pkgProblemResolver with broken count: 0 266s Done 266s The following additional packages will be installed: 266s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 266s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 266s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 266s librdmacm1t64 lsscsi open-iscsi tgt 266s Suggested packages: 266s fio-examples gnuplot tgt-glusterfs tgt-rbd 266s Recommended packages: 266s finalrd 266s The following NEW packages will be installed: 266s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 266s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 266s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 266s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 266s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 266s Need to get 10.7 MB/10.7 MB of archives. 266s After this operation, 49.1 MB of additional disk space will be used. 266s Get:1 /tmp/autopkgtest.2Rdcy8/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 267s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.9-3ubuntu4 [54.4 kB] 267s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 267s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.9-3ubuntu4 [389 kB] 267s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 50.0-2build2 [80.9 kB] 267s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 267s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.1ubuntu6 [256 kB] 267s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4build3 [21.5 kB] 267s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4build3 [311 kB] 267s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4build3 [47.0 kB] 267s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4build3 [100 kB] 267s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.1-1 [97.4 kB] 267s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 267s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 267s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 267s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 267s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 267s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 267s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 268s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 268s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 268s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 269s Preconfiguring packages ... 269s Fetched 10.7 MB in 2s (5864 kB/s) 269s Selecting previously unselected package libopeniscsiusr. 269s (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 ... 72612 files and directories currently installed.) 269s Preparing to unpack .../00-libopeniscsiusr_2.1.9-3ubuntu4_ppc64el.deb ... 269s Unpacking libopeniscsiusr (2.1.9-3ubuntu4) ... 269s Selecting previously unselected package libisns0t64:ppc64el. 269s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 269s Unpacking libisns0t64:ppc64el (0.101-1) ... 269s Selecting previously unselected package open-iscsi. 269s Preparing to unpack .../02-open-iscsi_2.1.9-3ubuntu4_ppc64el.deb ... 269s Unpacking open-iscsi (2.1.9-3ubuntu4) ... 269s Selecting previously unselected package librdmacm1t64:ppc64el. 269s Preparing to unpack .../03-librdmacm1t64_50.0-2build2_ppc64el.deb ... 269s Unpacking librdmacm1t64:ppc64el (50.0-2build2) ... 269s Selecting previously unselected package libconfig-general-perl. 269s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 269s Unpacking libconfig-general-perl (2.65-2) ... 269s Selecting previously unselected package tgt. 269s Preparing to unpack .../05-tgt_1%3a1.0.85-1.1ubuntu6_ppc64el.deb ... 269s Unpacking tgt (1:1.0.85-1.1ubuntu6) ... 269s Selecting previously unselected package libgfxdr0:ppc64el. 269s Preparing to unpack .../06-libgfxdr0_11.1-4build3_ppc64el.deb ... 269s Unpacking libgfxdr0:ppc64el (11.1-4build3) ... 269s Selecting previously unselected package libglusterfs0:ppc64el. 269s Preparing to unpack .../07-libglusterfs0_11.1-4build3_ppc64el.deb ... 269s Unpacking libglusterfs0:ppc64el (11.1-4build3) ... 269s Selecting previously unselected package libgfrpc0:ppc64el. 269s Preparing to unpack .../08-libgfrpc0_11.1-4build3_ppc64el.deb ... 269s Unpacking libgfrpc0:ppc64el (11.1-4build3) ... 269s Selecting previously unselected package libgfapi0:ppc64el. 269s Preparing to unpack .../09-libgfapi0_11.1-4build3_ppc64el.deb ... 269s Unpacking libgfapi0:ppc64el (11.1-4build3) ... 269s Selecting previously unselected package libnbd0. 269s Preparing to unpack .../10-libnbd0_1.20.1-1_ppc64el.deb ... 269s Unpacking libnbd0 (1.20.1-1) ... 269s Selecting previously unselected package libdaxctl1:ppc64el. 269s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 269s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 269s Selecting previously unselected package libndctl6:ppc64el. 269s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 269s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 269s Selecting previously unselected package libpmem1:ppc64el. 269s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 269s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 269s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 269s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 269s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 269s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 269s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 269s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 269s Selecting previously unselected package librados2. 269s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 269s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 269s Selecting previously unselected package libpmemobj1:ppc64el. 269s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 269s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 269s Selecting previously unselected package librbd1. 269s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 269s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 269s Selecting previously unselected package fio. 269s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 269s Unpacking fio (3.37-1) ... 269s Selecting previously unselected package lsscsi. 269s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 269s Unpacking lsscsi (0.32-1build1) ... 269s Selecting previously unselected package autopkgtest-satdep. 269s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 269s Unpacking autopkgtest-satdep (0) ... 269s Setting up libconfig-general-perl (2.65-2) ... 269s Setting up libisns0t64:ppc64el (0.101-1) ... 269s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 269s Setting up libnbd0 (1.20.1-1) ... 269s Setting up libopeniscsiusr (2.1.9-3ubuntu4) ... 269s Setting up libglusterfs0:ppc64el (11.1-4build3) ... 269s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 269s Setting up lsscsi (0.32-1build1) ... 269s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 269s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 269s Setting up librdmacm1t64:ppc64el (50.0-2build2) ... 269s Setting up tgt (1:1.0.85-1.1ubuntu6) ... 270s Created symlink /etc/systemd/system/multi-user.target.wants/tgt.service → /usr/lib/systemd/system/tgt.service. 270s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 270s Setting up libgfxdr0:ppc64el (11.1-4build3) ... 270s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 270s Setting up open-iscsi (2.1.9-3ubuntu4) ... 271s Created symlink /etc/systemd/system/sockets.target.wants/iscsid.socket → /usr/lib/systemd/system/iscsid.socket. 271s Created symlink /etc/systemd/system/iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 271s Created symlink /etc/systemd/system/sysinit.target.wants/open-iscsi.service → /usr/lib/systemd/system/open-iscsi.service. 272s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 272s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 272s Setting up libgfrpc0:ppc64el (11.1-4build3) ... 272s Setting up libgfapi0:ppc64el (11.1-4build3) ... 272s Setting up fio (3.37-1) ... 272s Setting up autopkgtest-satdep (0) ... 272s Processing triggers for man-db (2.12.1-1) ... 273s Processing triggers for initramfs-tools (0.142ubuntu27) ... 273s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 273s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 280s Processing triggers for libc-bin (2.39-0ubuntu8.1) ... 282s (Reading database ... 72853 files and directories currently installed.) 282s Removing autopkgtest-satdep (0) ... 284s autopkgtest [16:24:03]: test tgtbasedmpaths: [----------------------- 284s + targetname=iqn.2016-11.foo.com:target.iscsi 284s + pwd 284s + cwd=/tmp/autopkgtest.2Rdcy8/build.dtX/src 284s + testdir=/mnt/tgtmpathtest 284s + localhost=127.0.0.1 284s + portal=127.0.0.1:3260 284s + maxpaths=4 284s + backfn=backingfile 284s + expectwwid=60000000000000000e00000000010001 284s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 284s + bglog=/tmp/autopkgtest.2Rdcy8/tgtbasedmpaths-artifacts/test-background.log 284s + fioprep=/tmp/autopkgtest.2Rdcy8/tgtbasedmpaths-artifacts/path-change-prep.fio 284s + fiovrfy=/tmp/autopkgtest.2Rdcy8/tgtbasedmpaths-artifacts/path-change-check.fio 284s + service tgt restart 284s + truncate --size 100M backingfile 284s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 284s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 284s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.2Rdcy8/build.dtX/src/backingfile 284s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 284s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 284s login #1 284s + echo login #1 284s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 284s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 284s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 284s + seq 2 4 284s + echo extra login #2 284s + iscsiadm --mode session -r 1 --op new 284s extra login #2 284s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 284s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 284s + echo extra login #3 284s + iscsiadm --mode session -r 1 --op new 284s extra login #3 284s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 284s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 284s extra login #4 284s + echo extra login #4 284s + iscsiadm --mode session -r 1 --op new 284s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 284s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 284s + udevadm settle 284s + sleep 5 289s Status after initial setup 289s + echo Status after initial setup 289s + tgtadm --lld iscsi --mode target --op show 289s Target 1: iqn.2016-11.foo.com:target.iscsi 289s System information: 289s Driver: iscsi 289s State: ready 289s I_T nexus information: 289s I_T nexus: 1 289s Initiator: iqn.2004-10.com.ubuntu:01:179b64ee9dfe alias: autopkgtest 289s Connection: 0 289s IP Address: 127.0.0.1 289s I_T nexus: 2 289s Initiator: iqn.2004-10.com.ubuntu:01:179b64ee9dfe alias: autopkgtest 289s Connection: 0 289s IP Address: 127.0.0.1 289s I_T nexus: 3 289s Initiator: iqn.2004-10.com.ubuntu:01:179b64ee9dfe alias: autopkgtest 289s Connection: 0 289s IP Address: 127.0.0.1 289s I_T nexus: 4 289s Initiator: iqn.2004-10.com.ubuntu:01:179b64ee9dfe alias: autopkgtest 289s Connection: 0 289s IP Address: 127.0.0.1 289s LUN information: 289s LUN: 0 289s Type: controller 289s SCSI ID: IET 00010000 289s SCSI SN: beaf10 289s Size: 0 MB, Block size: 1 289s Online: Yes 289s Removable media: No 289s Prevent removal: No 289s Readonly: No 289s SWP: No 289s Thin-provisioning: No 289s Backing store type: null 289s Backing store path: None 289s Backing store flags: 289s LUN: 1 289s Type: disk 289s SCSI ID: IET 00010001 289s SCSI SN: beaf11 289s Size: 105 MB, Block size: 512 289s Online: Yes 289s Removable media: No 289s Prevent removal: No 289s Readonly: No 289s SWP: No 289s Thin-provisioning: No 289s Backing store type: rdwr 289s Backing store path: /tmp/autopkgtest.2Rdcy8/build.dtX/src/backingfile 289s Backing store flags: 289s Account information: 289s ACL information: 289s ALL 289s + tgtadm --lld iscsi --op show --mode conn --tid 1 289s Session: 4 289s Connection: 0 289s Initiator: iqn.2004-10.com.ubuntu:01:179b64ee9dfe 289s IP Address: 127.0.0.1 289s Session: 3 289s Connection: 0 289s Initiator: iqn.2004-10.com.ubuntu:01:179b64ee9dfe 289s IP Address: 127.0.0.1 289s Session: 2 289s Connection: 0 289s Initiator: iqn.2004-10.com.ubuntu:01:179b64ee9dfe 289s IP Address: 127.0.0.1 289s Session: 1 289s Connection: 0 289s Initiator: iqn.2004-10.com.ubuntu:01:179b64ee9dfe 289s IP Address: 127.0.0.1 289s + iscsiadm --mode session -P 1 289s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 289s Current Portal: 127.0.0.1:3260,1 289s Persistent Portal: 127.0.0.1:3260,1 289s ********** 289s Interface: 289s ********** 289s Iface Name: default 289s Iface Transport: tcp 289s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:179b64ee9dfe 289s Iface IPaddress: 127.0.0.1 289s Iface HWaddress: default 289s Iface Netdev: default 289s SID: 1 289s iSCSI Connection State: LOGGED IN 289s iSCSI Session State: LOGGED_IN 289s Internal iscsid Session State: NO CHANGE 289s 289s ********** 289s Interface: 289s ********** 289s Iface Name: default 289s Iface Transport: tcp 289s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:179b64ee9dfe 289s Iface IPaddress: 127.0.0.1 289s Iface HWaddress: default 289s Iface Netdev: default 289s SID: 2 289s iSCSI Connection State: LOGGED IN 289s iSCSI Session State: LOGGED_IN 289s Internal iscsid Session State: NO CHANGE 289s 289s ********** 289s Interface: 289s ********** 289s Iface Name: default 289s Iface Transport: tcp 289s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:179b64ee9dfe 289s Iface IPaddress: 127.0.0.1 289s Iface HWaddress: default 289s Iface Netdev: default 289s SID: 3 289s iSCSI Connection State: LOGGED IN 289s iSCSI Session State: LOGGED_IN 289s Internal iscsid Session State: NO CHANGE 289s 289s ********** 289s Interface: 289s ********** 289s Iface Name: default 289s Iface Transport: tcp 289s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:179b64ee9dfe 289s Iface IPaddress: 127.0.0.1 289s Iface HWaddress: default 289s Iface Netdev: default 289s SID: 4 289s iSCSI Connection State: LOGGED IN 289s iSCSI Session State: LOGGED_IN 289s Internal iscsid Session State: NO CHANGE 289s + lsscsi -liv 289s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 289s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 289s 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] 289s [1:0:0:0] storage IET Controller 0001 - - 289s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 289s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 289s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 289s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 289s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 289s [2:0:0:0] storage IET Controller 0001 - - 289s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 289s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 289s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 289s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 289s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 289s [3:0:0:0] storage IET Controller 0001 - - 289s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 289s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 289s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 289s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 289s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 289s [4:0:0:0] storage IET Controller 0001 - - 289s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 289s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 289s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde SIET_VIRTUAL-DISK_beaf11 289s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 289s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 289s NVMe module may not be loaded 289s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 289s + multipath -v3 -ll 289s 69.534631 | set open fds limit to 1048576/1048576 289s 69.534686 | loading /lib/multipath/libchecktur.so checker 289s 69.534777 | checker tur: message table size = 3 289s 69.534785 | loading /lib/multipath/libprioconst.so prioritizer 289s 69.534890 | _init_foreign: foreign library "nvme" is not enabled 289s 69.540170 | sda: size = 167772160 289s 69.540365 | sda: vendor = QEMU 289s 69.540432 | sda: product = QEMU HARDDISK 289s 69.540478 | sda: rev = 2.5+ 289s 69.541102 | sda: h:b:t:l = 0:0:0:0 289s 69.541427 | sda: tgt_node_name = 289s 69.541471 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 289s 69.541494 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 289s 69.541658 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 289s 69.541702 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 289s 69.541734 | __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 289s 69.541785 | failed to read sysfs vpd pg80: No such file or directory 289s 69.542002 | sda: fail to get serial 289s 69.542046 | sda: detect_checker = yes (setting: multipath internal) 289s 69.542278 | sda: path_checker = tur (setting: multipath internal) 289s 69.542326 | sda: checker timeout = 30 s (setting: kernel sysfs) 289s 69.542488 | sda: tur state = up 289s 69.542834 | sdb: size = 204800 289s 69.543009 | sdb: vendor = IET 289s 69.543072 | sdb: product = VIRTUAL-DISK 289s 69.543118 | sdb: rev = 0001 289s 69.543770 | sdb: h:b:t:l = 1:0:0:1 289s 69.544165 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 289s 69.544218 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 289s 69.544240 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 289s 69.544408 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 289s 69.544450 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 289s 69.544485 | sdb: serial = beaf11 289s 69.544507 | sdb: detect_checker = yes (setting: multipath internal) 289s 69.544847 | sdb: path_checker = tur (setting: multipath internal) 289s 69.544890 | sdb: checker timeout = 30 s (setting: kernel sysfs) 289s 69.545135 | sdb: tur state = up 289s 69.545292 | sdc: size = 204800 289s 69.545458 | sdc: vendor = IET 289s 69.545521 | sdc: product = VIRTUAL-DISK 289s 69.545565 | sdc: rev = 0001 289s 69.546258 | sdc: h:b:t:l = 2:0:0:1 289s 69.546618 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 289s 69.546662 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 289s 69.546684 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 289s 69.546848 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 289s 69.546891 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 289s 69.546930 | sdc: serial = beaf11 289s 69.546969 | sdc: detect_checker = yes (setting: multipath internal) 289s 69.547257 | sdc: path_checker = tur (setting: multipath internal) 289s 69.547299 | sdc: checker timeout = 30 s (setting: kernel sysfs) 289s 69.547537 | sdc: tur state = up 289s 69.547697 | sdd: size = 204800 289s 69.547865 | sdd: vendor = IET 289s 69.547950 | sdd: product = VIRTUAL-DISK 289s 69.547994 | sdd: rev = 0001 289s 69.548715 | sdd: h:b:t:l = 3:0:0:1 289s 69.549087 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 289s 69.549130 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 289s 69.549152 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 289s 69.549296 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 289s 69.549299 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 289s 69.549311 | sdd: serial = beaf11 289s 69.549313 | sdd: detect_checker = yes (setting: multipath internal) 289s 69.549577 | sdd: path_checker = tur (setting: multipath internal) 289s 69.549584 | sdd: checker timeout = 30 s (setting: kernel sysfs) 289s 69.549805 | sdd: tur state = up 289s 69.549927 | sde: size = 204800 289s 69.550048 | sde: vendor = IET 289s 69.550067 | sde: product = VIRTUAL-DISK 289s 69.550087 | sde: rev = 0001 289s 69.550738 | sde: h:b:t:l = 4:0:0:1 289s 69.551053 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 289s 69.551056 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 289s 69.551058 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 289s 69.551197 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 289s 69.551200 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 289s 69.551212 | sde: serial = beaf11 289s 69.551214 | sde: detect_checker = yes (setting: multipath internal) 289s 69.551601 | sde: path_checker = tur (setting: multipath internal) 289s 69.551607 | sde: checker timeout = 30 s (setting: kernel sysfs) 289s 69.551837 | sde: tur state = up 289s 69.551940 | loop0: device node name blacklisted 289s 69.552081 | loop1: device node name blacklisted 289s 69.552190 | loop2: device node name blacklisted 289s 69.552314 | loop3: device node name blacklisted 289s 69.552437 | loop4: device node name blacklisted 289s 69.552560 | loop5: device node name blacklisted 289s 69.552682 | loop6: device node name blacklisted 289s 69.552760 | loop7: device node name blacklisted 289s 69.552840 | dm-0: device node name blacklisted 289s 69.553726 | multipath-tools v0.9.4 (12/19, 2022) 289s 69.553735 | libdevmapper version 1.02.185 289s 69.553860 | kernel device mapper v4.48.0 289s 69.553870 | DM multipath kernel driver v1.14.0 289s 69.553967 | sdb: size = 204800 289s 69.553971 | sdb: vendor = IET 289s 69.553973 | sdb: product = VIRTUAL-DISK 289s 69.553976 | sdb: rev = 0001 289s 69.554577 | sdb: h:b:t:l = 1:0:0:1 289s 69.554681 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 289s 69.554698 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 289s 69.554701 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 289s 69.554712 | sdb: serial = beaf11 289s ===== paths list ===== 289s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 289s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 289s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 289s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 289s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 289s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 289s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 289s size=100M features='0' hwhandler='0' wp=rw 289s |-+- policy='service-time 0' prio=1 status=active 289s | `- 1:0:0:1 sdb 8:16 active ready running 289s |-+- policy='service-time 0' prio=1 status=enabled 289s | `- 2:0:0:1 sdc 8:32 active ready running 289s |-+- policy='service-time 0' prio=1 status=enabled 289s | `- 3:0:0:1 sdd 8:48 active ready running 289s `-+- policy='service-time 0' prio=1 status=enabled 289s `- 4:0:0:1 sde 8:64 active ready running 289s 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 289s Test WWN should now point to DM 289s ../../dm-0 289s Creating filesystem with 25600 4k blocks and 25600 inodes 289s 289s Allocating group tables: 0/1 done 289s Writing inode tables: 0/1 done 289s Creating journal (1024 blocks): done 289s Writing superblocks and filesystem accounting information: 0/1 69.554920 | sdb: tur state = up 289s 69.554927 | sdb: uid = 360000000000000000e00000000010001 (udev) 289s 69.554930 | sdb: detect_prio = yes (setting: multipath internal) 289s 69.554933 | sdb: prio = const (setting: multipath internal) 289s 69.554935 | sdb: prio args = "" (setting: multipath internal) 289s 69.554937 | sdb: const prio = 1 289s 69.554960 | sdc: size = 204800 289s 69.554964 | sdc: vendor = IET 289s 69.554966 | sdc: product = VIRTUAL-DISK 289s 69.554969 | sdc: rev = 0001 289s 69.555556 | sdc: h:b:t:l = 2:0:0:1 289s 69.555659 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 289s 69.555677 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 289s 69.555679 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 289s 69.555691 | sdc: serial = beaf11 289s 69.555914 | sdc: tur state = up 289s 69.555920 | sdc: uid = 360000000000000000e00000000010001 (udev) 289s 69.555922 | sdc: detect_prio = yes (setting: multipath internal) 289s 69.555925 | sdc: prio = const (setting: multipath internal) 289s 69.555927 | sdc: prio args = "" (setting: multipath internal) 289s 69.555929 | sdc: const prio = 1 289s 69.555950 | sdd: size = 204800 289s 69.555953 | sdd: vendor = IET 289s 69.555956 | sdd: product = VIRTUAL-DISK 289s 69.555958 | sdd: rev = 0001 289s 69.556564 | sdd: h:b:t:l = 3:0:0:1 289s 69.556672 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 289s 69.556689 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 289s 69.556692 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 289s 69.556703 | sdd: serial = beaf11 289s 69.556935 | sdd: tur state = up 289s 69.556943 | sdd: uid = 360000000000000000e00000000010001 (udev) 289s 69.556945 | sdd: detect_prio = yes (setting: multipath internal) 289s 69.556947 | sdd: prio = const (setting: multipath internal) 289s 69.556949 | sdd: prio args = "" (setting: multipath internal) 289s 69.556951 | sdd: const prio = 1 289s 69.556973 | sde: size = 204800 289s 69.556977 | sde: vendor = IET 289s 69.556979 | sde: product = VIRTUAL-DISK 289s 69.556982 | sde: rev = 0001 289s 69.557564 | sde: h:b:t:l = 4:0:0:1 289s 69.557666 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 289s 69.557683 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 289s 69.557686 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 289s 69.557697 | sde: serial = beaf11 289s 69.557923 | sde: tur state = up 289s 69.557930 | sde: uid = 360000000000000000e00000000010001 (udev) 289s 69.557932 | sde: detect_prio = yes (setting: multipath internal) 289s 69.557935 | sde: prio = const (setting: multipath internal) 289s 69.557937 | sde: prio args = "" (setting: multipath internal) 289s 69.557939 | sde: const prio = 1 289s 69.558689 | unloading tur checker 289s 69.558714 | unloading const prioritizer 289s + dmsetup table 289s + echo Test WWN should now point to DM 289s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 289s + grep dm 289s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 289s mke2fs 1.47.0 (5-Feb-2023) 289s done 289s 289s + udevadm settle 289s + sleep 3s 292s + mkdir -p /mnt/tgtmpathtest 292s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 292s + cat 292s + cat 292s + fio --max-jobs=4 /tmp/autopkgtest.2Rdcy8/tgtbasedmpaths-artifacts/path-change-prep.fio 292s 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 292s fio-3.37 292s Starting 1 thread 292s write-phase: Laying out IO file (1 file / 17592186044415MiB) 293s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91881472, buflen=65536 293s 293s write-phase: (groupid=0, jobs=1): err= 0: pid=6450: Tue Jun 4 16:24:12 2024 293s write: IOPS=2322, BW=145MiB/s (152MB/s)(87.6MiB/604msec); 0 zone resets 293s clat (usec): min=224, max=5306, avg=412.52, stdev=210.06 293s lat (usec): min=238, max=5319, avg=428.74, stdev=210.45 293s clat percentiles (usec): 293s | 1.00th=[ 245], 5.00th=[ 297], 10.00th=[ 318], 20.00th=[ 359], 293s | 30.00th=[ 371], 40.00th=[ 379], 50.00th=[ 388], 60.00th=[ 404], 293s | 70.00th=[ 424], 80.00th=[ 449], 90.00th=[ 498], 95.00th=[ 537], 293s | 99.00th=[ 644], 99.50th=[ 1057], 99.90th=[ 4228], 99.95th=[ 5276], 293s | 99.99th=[ 5276] 293s bw ( KiB/s): min=145792, max=145792, per=98.14%, avg=145792.00, stdev= 0.00, samples=1 293s iops : min= 2278, max= 2278, avg=2278.00, stdev= 0.00, samples=1 293s lat (usec) : 250=1.35%, 500=89.38%, 750=8.48%, 1000=0.14% 293s lat (msec) : 2=0.29%, 4=0.14%, 10=0.14% 293s cpu : usr=2.99%, sys=9.12%, ctx=1404, majf=0, minf=0 293s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 293s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 293s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 293s issued rwts: total=0,1403,0,0 short=0,0,0,0 dropped=0,0,0,0 293s latency : target=0, window=0, percentile=100.00%, depth=1 293s 293s Run status group 0 (all jobs): 293s WRITE: bw=145MiB/s (152MB/s), 145MiB/s-145MiB/s (152MB/s-152MB/s), io=87.6MiB (91.9MB), run=604-604msec 293s 293s Disk stats (read/write): 293s dm-0: ios=1/868, sectors=8/111104, merge=0/0, ticks=0/357, in_queue=357, util=79.84%, aggrios=0/351, aggsectors=2/44884, aggrmerge=0/0, aggrticks=0/134, aggrin_queue=135, aggrutil=84.56% 293s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 293s sdb: ios=1/1404, sectors=8/179536, merge=0/0, ticks=1/539, in_queue=540, util=84.56% 293s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 293s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 293s Starting the path changes in background 293s + echo Starting the path changes in background 293s + date +Pre FIO %H:%M:%S.%N 293s Pre FIO 16:24:12.708919830 293s + fio --max-jobs=4 /tmp/autopkgtest.2Rdcy8/tgtbasedmpaths-artifacts/path-change-check.fio 293s 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 293s fio-3.37 293s Starting 1 thread 474s 474s verify-phase: (groupid=0, jobs=1): err= 0: pid=6457: Tue Jun 4 16:27:13 2024 474s read: IOPS=3549, BW=222MiB/s (233MB/s)(39.0GiB/180001msec) 474s clat (usec): min=85, max=47058, avg=259.07, stdev=174.15 474s lat (usec): min=85, max=47058, avg=259.19, stdev=174.16 474s clat percentiles (usec): 474s | 1.00th=[ 135], 5.00th=[ 151], 10.00th=[ 180], 20.00th=[ 194], 474s | 30.00th=[ 204], 40.00th=[ 212], 50.00th=[ 227], 60.00th=[ 249], 474s | 70.00th=[ 285], 80.00th=[ 326], 90.00th=[ 383], 95.00th=[ 420], 474s | 99.00th=[ 494], 99.50th=[ 668], 99.90th=[ 1205], 99.95th=[ 1532], 474s | 99.99th=[ 3523] 474s bw ( KiB/s): min=120817, max=367872, per=100.00%, avg=227376.84, stdev=51630.51, samples=359 474s iops : min= 1887, max= 5748, avg=3552.73, stdev=806.74, samples=359 474s lat (usec) : 100=0.45%, 250=59.69%, 500=38.93%, 750=0.50%, 1000=0.21% 474s lat (msec) : 2=0.20%, 4=0.02%, 10=0.01%, 20=0.01%, 50=0.01% 474s cpu : usr=9.75%, sys=7.77%, ctx=638960, majf=0, minf=1 474s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 474s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 474s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 474s issued rwts: total=638858,0,0,0 short=0,0,0,0 dropped=0,0,0,0 474s latency : target=0, window=0, percentile=100.00%, depth=1 474s 474s Run status group 0 (all jobs): 474s READ: bw=222MiB/s (233MB/s), 222MiB/s-222MiB/s (233MB/s-233MB/s), io=39.0GiB (41.9GB), run=180001-180001msec 474s 474s Disk stats (read/write): 474s dm-0: ios=638975/9, sectors=81730104/12912, merge=31/8, ticks=166173/70, in_queue=166284, util=99.98%, aggrios=42256/2, aggsectors=5404718/3228, aggrmerge=0/0, aggrticks=10785/7, aggrin_queue=10792, aggrutil=99.12% 474s sdd: ios=36840/0, sectors=4712192/0, merge=0/0, ticks=8462/0, in_queue=8462, util=32.97% 474s sdb: ios=27003/8, sectors=3453696/12912, merge=0/0, ticks=8708/29, in_queue=8737, util=99.12% 474s sde: ios=74902/0, sectors=9580544/0, merge=0/0, ticks=17127/0, in_queue=17127, util=39.77% 474s sdc: ios=30279/0, sectors=3872440/0, merge=0/0, ticks=8844/0, in_queue=8844, util=50.04% 474s + date +Post FIO %H:%M:%S.%N 474s + echo FIO verify test with changing paths - OK 474s + echo Report log of background activity 474s + cat /tmp/autopkgtest.2Rdcy8/tgtbasedmpaths-artifacts/test-background.log 474s Post FIO 16:27:13.045885165 474s FIO verify test with changing paths - OK 474s Report log of background activity 474s + iscsiadm --mode session 474s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s + sleep 10s 474s + date +MP report (expect 4) %H:%M:%S.%N 474s MP report (expect 4) 16:24:22.715397342 474s + multipath -ll 474s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 474s size=100M features='0' hwhandler='0' wp=rw 474s |-+- policy='service-time 0' prio=1 status=active 474s | `- 1:0:0:1 sdb 8:16 active ready running 474s |-+- policy='service-time 0' prio=1 status=enabled 474s | `- 2:0:0:1 sdc 8:32 active ready running 474s |-+- policy='service-time 0' prio=1 status=enabled 474s | `- 3:0:0:1 sdd 8:48 active ready running 474s `-+- policy='service-time 0' prio=1 status=enabled 474s `- 4:0:0:1 sde 8:64 active ready running 474s + date +UN-plug path 1 %H:%M:%S.%N 474s UN-plug path 1 16:24:22.745094193 474s + iscsiadm --mode session -r 1 -u 474s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 474s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 474s + iscsiadm --mode session 474s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s + sleep 10s 474s + date +MP report (expect 3) %H:%M:%S.%N 474s MP report (expect 3) 16:24:32.841248861 474s + multipath -ll 474s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 474s size=100M features='0' hwhandler='0' wp=rw 474s |-+- policy='service-time 0' prio=1 status=active 474s | `- 2:0:0:1 sdc 8:32 active ready running 474s |-+- policy='service-time 0' prio=1 status=enabled 474s | `- 3:0:0:1 sdd 8:48 active ready running 474s `-+- policy='service-time 0' prio=1 status=enabled 474s `- 4:0:0:1 sde 8:64 active ready running 474s + date +UN-plug path 2 %H:%M:%S.%N 474s UN-plug path 2 16:24:32.866962558 474s + iscsiadm --mode session -r 2 -u 474s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 474s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 474s + iscsiadm --mode session 474s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s + sleep 10s 474s + date +MP report (expect 2) %H:%M:%S.%N 474s MP report (expect 2) 16:24:42.957679396 474s + multipath -ll 474s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 474s size=100M features='0' hwhandler='0' wp=rw 474s |-+- policy='service-time 0' prio=1 status=active 474s | `- 3:0:0:1 sdd 8:48 active ready running 474s `-+- policy='service-time 0' prio=1 status=enabled 474s `- 4:0:0:1 sde 8:64 active ready running 474s + date +UN-plug path 3 %H:%M:%S.%N 474s UN-plug path 3 16:24:42.975329217 474s + iscsiadm --mode session -r 3 -u 474s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 474s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 474s + iscsiadm --mode session 474s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s + sleep 10s 474s + date +MP report (expect 1) %H:%M:%S.%N 474s MP report (expect 1) 16:24:53.064412622 474s + multipath -ll 474s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 474s size=100M features='0' hwhandler='0' wp=rw 474s `-+- policy='service-time 0' prio=1 status=active 474s `- 4:0:0:1 sde 8:64 active ready running 474s + date +Add paths 5/6/7/8 %H:%M:%S.%N 474s Add paths 5/6/7/8 16:24:53.079607539 474s + iscsiadm --mode session -r 4 --op new 474s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 474s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 474s + iscsiadm --mode session -r 4 --op new 474s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 474s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 474s + iscsiadm --mode session -r 4 --op new 474s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 474s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 474s + iscsiadm --mode session -r 4 --op new 474s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 474s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 474s + iscsiadm --mode session 474s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s + sleep 10s 474s + date +MP report (expect 5) %H:%M:%S.%N 474s MP report (expect 5) 16:25:03.220414719 474s + multipath -ll 474s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 474s size=100M features='0' hwhandler='0' wp=rw 474s |-+- policy='service-time 0' prio=1 status=active 474s | `- 4:0:0:1 sde 8:64 active ready running 474s |-+- policy='service-time 0' prio=1 status=enabled 474s | `- 1:0:0:1 sdb 8:16 active ready running 474s |-+- policy='service-time 0' prio=1 status=enabled 474s | `- 2:0:0:1 sdc 8:32 active ready running 474s |-+- policy='service-time 0' prio=1 status=enabled 474s | `- 3:0:0:1 sdd 8:48 active ready running 474s `-+- policy='service-time 0' prio=1 status=enabled 474s `- 5:0:0:1 sdf 8:80 active ready running 474s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 474s UN-plug multiple paths 4/7/8 16:25:03.250516749 474s + iscsiadm --mode session -r 4 -u 474s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 474s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 474s + iscsiadm --mode session -r 7 -u 474s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 474s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 474s + iscsiadm --mode session -r 8 -u 474s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 474s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 474s + iscsiadm --mode session 474s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 474s + sleep 10s 474s + date +Restart multipath daemon %H:%M:%S.%N 474s Restart multipath daemon 16:25:13.545665556 474s + systemctl restart multipathd 474s + sleep 10s 474s + date +Final background report (expect 2) %H:%M:%S.%N 474s Final background report (expect 2) 16:25:23.613742687 474s + multipath -ll 474s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 474s size=100M features='0' hwhandler='0' wp=rw 474s |-+- policy='service-time 0' prio=1 status=active 474s | `- 1:0:0:1 sdb 8:16 active ready running 474s `-+- policy='service-time 0' prio=1 status=enabled 474s `- 2:0:0:1 sdc 8:32 active ready running 474s Final stats 474s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 474s iSCSI SNMP: 474s txdata_octets: 22499976 474s rxdata_octets: 30696875764 474s noptx_pdus: 0 474s scsicmd_pdus: 468482 474s tmfcmd_pdus: 0 474s login_pdus: 0 474s text_pdus: 0 474s dataout_pdus: 0 474s logout_pdus: 0 474s snack_pdus: 0 474s noprx_pdus: 0 474s scsirsp_pdus: 468482 474s tmfrsp_pdus: 0 474s textrsp_pdus: 0 474s datain_pdus: 468448 474s logoutrsp_pdus: 0 474s r2t_pdus: 0 474s async_pdus: 0 474s rjt_pdus: 0 474s digest_err: 0 474s timeout_err: 0 474s iSCSI Extended: 474s tx_sendpage_failures: 0 474s rx_discontiguous_hdr: 0 474s eh_abort_cnt: 0 474s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 474s iSCSI SNMP: 474s txdata_octets: 6504 474s rxdata_octets: 1514964 474s noptx_pdus: 0 474s scsicmd_pdus: 105 474s tmfcmd_pdus: 0 474s login_pdus: 0 474s text_pdus: 0 474s dataout_pdus: 0 474s logout_pdus: 0 474s snack_pdus: 0 474s noprx_pdus: 0 474s scsirsp_pdus: 105 474s tmfrsp_pdus: 0 474s textrsp_pdus: 0 474s datain_pdus: 83 474s logoutrsp_pdus: 0 474s r2t_pdus: 0 474s async_pdus: 0 474s rjt_pdus: 0 474s digest_err: 0 474s timeout_err: 0 474s iSCSI Extended: 474s tx_sendpage_failures: 0 474s rx_discontiguous_hdr: 0 474s eh_abort_cnt: 0 474s + sync 474s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 474s + echo Final stats 474s + iscsiadm --mode session --stats 474s + journalctl --no-pager -u multipathd 474s Jun 04 10:52:39 adtubuntu-oracular-ppc64el-server-20240602 multipathd[263]: multipathd v0.9.4: start up 474s Jun 04 10:52:39 adtubuntu-oracular-ppc64el-server-20240602 multipathd[263]: reconfigure: setting up paths and maps 474s Jun 04 10:52:39 adtubuntu-oracular-ppc64el-server-20240602 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 474s Jun 04 10:53:21 adtubuntu-oracular-ppc64el-server-20240603 multipathd[263]: multipathd: shut down 474s Jun 04 10:53:21 adtubuntu-oracular-ppc64el-server-20240603 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 474s Jun 04 10:53:21 adtubuntu-oracular-ppc64el-server-20240603 systemd[1]: multipathd.service: Deactivated successfully. 474s Jun 04 10:53:21 adtubuntu-oracular-ppc64el-server-20240603 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 474s -- Boot f47036adce8849319af0a2103074eeb3 -- 474s Jun 04 10:53:44 adtubuntu-oracular-ppc64el-server-20240603 multipathd[263]: multipathd v0.9.4: start up 474s Jun 04 10:53:44 adtubuntu-oracular-ppc64el-server-20240603 multipathd[263]: reconfigure: setting up paths and maps 474s Jun 04 10:53:44 adtubuntu-oracular-ppc64el-server-20240603 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 474s Jun 04 10:54:11 adtubuntu-oracular-ppc64el-server-20240603 multipathd[263]: multipathd: shut down 474s Jun 04 10:54:11 adtubuntu-oracular-ppc64el-server-20240603 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 474s Jun 04 10:54:11 adtubuntu-oracular-ppc64el-server-20240603 systemd[1]: multipathd.service: Deactivated successfully. 474s Jun 04 10:54:11 adtubuntu-oracular-ppc64el-server-20240603 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 474s -- Boot d6b0070bae3c4c98979761ab4962543b -- 474s Jun 04 16:23:02 adtubuntu-oracular-ppc64el-server-20240603 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 474s Jun 04 16:23:02 adtubuntu-oracular-ppc64el-server-20240603 multipathd[334]: multipathd v0.9.4: start up 474s Jun 04 16:23:02 adtubuntu-oracular-ppc64el-server-20240603 multipathd[334]: reconfigure: setting up paths and maps 474s Jun 04 16:23:02 adtubuntu-oracular-ppc64el-server-20240603 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 474s Jun 04 16:24:03 autopkgtest multipathd[334]: 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] 474s Jun 04 16:24:03 autopkgtest multipathd[334]: sdc [8:32]: path added to devmap mpatha 474s Jun 04 16:24:03 autopkgtest multipathd[334]: mpatha: performing delayed actions 474s Jun 04 16:24:03 autopkgtest multipathd[334]: 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] 474s Jun 04 16:24:22 autopkgtest multipathd[334]: 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] 474s Jun 04 16:24:22 autopkgtest multipathd[334]: check_removed_paths: sdb: freeing path in removed state 474s Jun 04 16:24:22 autopkgtest multipathd[334]: 8:16: path removed from map mpatha 474s Jun 04 16:24:32 autopkgtest multipathd[334]: 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] 474s Jun 04 16:24:32 autopkgtest multipathd[334]: check_removed_paths: sdc: freeing path in removed state 474s Jun 04 16:24:32 autopkgtest multipathd[334]: 8:32: path removed from map mpatha 474s Jun 04 16:24:43 autopkgtest multipathd[334]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 474s Jun 04 16:24:43 autopkgtest multipathd[334]: check_removed_paths: sdd: freeing path in removed state 474s Jun 04 16:24:43 autopkgtest multipathd[334]: 8:48: path removed from map mpatha 474s Jun 04 16:24:53 autopkgtest multipathd[334]: 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] 474s Jun 04 16:24:53 autopkgtest multipathd[334]: sdb [8:16]: path added to devmap mpatha 474s Jun 04 16:24:53 autopkgtest multipathd[334]: mpatha: reload [0 204800 multipa+ echo Check final path status 474s + multipath -ll 474s + multipath -ll 474s + grep --count status= 474s + diskc=2 474s + multipath -ll 474s + grep --count status=active 474s th 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] 474s Jun 04 16:24:53 autopkgtest multipathd[334]: sdc [8:32]: path added to devmap mpatha 474s Jun 04 16:24:53 autopkgtest multipathd[334]: 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] 474s Jun 04 16:24:53 autopkgtest multipathd[334]: sdd [8:48]: path added to devmap mpatha 474s Jun 04 16:24:53 autopkgtest multipathd[334]: 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] 474s Jun 04 16:24:53 autopkgtest multipathd[334]: sdf [8:80]: path added to devmap mpatha 474s Jun 04 16:25:03 autopkgtest multipathd[334]: 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] 474s Jun 04 16:25:03 autopkgtest multipathd[334]: check_removed_paths: sde: freeing path in removed state 474s Jun 04 16:25:03 autopkgtest multipathd[334]: 8:64: path removed from map mpatha 474s Jun 04 16:25:03 autopkgtest multipathd[334]: 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] 474s Jun 04 16:25:03 autopkgtest multipathd[334]: check_removed_paths: sdd: freeing path in removed state 474s Jun 04 16:25:03 autopkgtest multipathd[334]: 8:48: path removed from map mpatha 474s Jun 04 16:25:03 autopkgtest multipathd[334]: 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] 474s Jun 04 16:25:03 autopkgtest multipathd[334]: check_removed_paths: sdf: freeing path in removed state 474s Jun 04 16:25:03 autopkgtest multipathd[334]: 8:80: path removed from map mpatha 474s Jun 04 16:25:13 autopkgtest multipathd[334]: multipathd: shut down 474s Jun 04 16:25:13 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 474s Jun 04 16:25:13 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 474s Jun 04 16:25:13 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 474s Jun 04 16:25:13 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 474s Jun 04 16:25:13 autopkgtest multipathd[6818]: multipathd v0.9.4: start up 474s Jun 04 16:25:13 autopkgtest multipathd[6818]: reconfigure: setting up paths and maps 474s Jun 04 16:25:13 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 474s Check final path status 474s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 474s size=100M features='0' hwhandler='0' wp=rw 474s |-+- policy='service-time 0' prio=1 status=active 474s | `- 1:0:0:1 sdb 8:16 active ready running 474s `-+- policy='service-time 0' prio=1 status=enabled 474s `- 2:0:0:1 sdc 8:32 active ready running 474s + diska=1 474s + multipath -ll 474s + grep --count status=enabled 474s OK 474s + diske=1 474s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 474s + echo OK 474s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 474s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 474s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 474s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 474s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 474s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 474s autopkgtest [16:27:13]: test tgtbasedmpaths: -----------------------] 475s autopkgtest [16:27:14]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 475s tgtbasedmpaths PASS 475s autopkgtest [16:27:14]: @@@@@@@@@@@@@@@@@@@@ summary 475s kpartx-file-loopback PASS 475s tgtbasedmpaths PASS 481s nova [W] Using flock in scalingstack-bos01-ppc64el 481s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240604-161918-juju-7f2275-prod-proposed-migration-environment-2-6294878f-f58a-459a-b484-4ddffb00045d from image adt/ubuntu-oracular-ppc64el-server-20240604.img (UUID 9cf47254-9383-47b5-958b-d04c3257de42)... 481s nova [W] Using flock in scalingstack-bos01-ppc64el 481s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240604-161918-juju-7f2275-prod-proposed-migration-environment-2-6294878f-f58a-459a-b484-4ddffb00045d from image adt/ubuntu-oracular-ppc64el-server-20240604.img (UUID 9cf47254-9383-47b5-958b-d04c3257de42)...