0s autopkgtest [13:26:48]: starting date and time: 2024-07-20 13:26:48+0000 0s autopkgtest [13:26:48]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [13:26:48]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.2hpnutir/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:gdisk --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=gdisk/1.0.10-2 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos01-ppc64el-16.secgroup --name adt-oracular-ppc64el-multipath-tools-20240720-132647-juju-7f2275-prod-proposed-migration-environment-2-e96df37d-868f-4fc2-8b99-a908cee7e287 --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/ 320s autopkgtest [13:32:08]: testbed dpkg architecture: ppc64el 321s autopkgtest [13:32:09]: testbed apt version: 2.9.6 321s autopkgtest [13:32:09]: @@@@@@@@@@@@@@@@@@@@ test bed setup 322s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 322s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [384 kB] 322s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [60.6 kB] 322s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 322s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4092 B] 322s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [88.0 kB] 322s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2116 B] 322s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 322s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 322s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [394 kB] 322s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [8952 B] 322s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1840 B] 322s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 324s Fetched 1080 kB in 1s (1433 kB/s) 324s Reading package lists... 326s Reading package lists... 326s Building dependency tree... 326s Reading state information... 326s Calculating upgrade... 326s The following packages will be upgraded: 326s gdisk 327s 1 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 327s Need to get 258 kB of archives. 327s After this operation, 0 B of additional disk space will be used. 327s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el gdisk ppc64el 1.0.10-2 [258 kB] 327s Fetched 258 kB in 0s (623 kB/s) 327s (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 ... 72765 files and directories currently installed.) 327s Preparing to unpack .../gdisk_1.0.10-2_ppc64el.deb ... 327s Unpacking gdisk (1.0.10-2) over (1.0.10-1build1) ... 327s Setting up gdisk (1.0.10-2) ... 327s Processing triggers for man-db (2.12.1-2) ... 328s Reading package lists... 328s Building dependency tree... 328s Reading state information... 328s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 329s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 329s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 329s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 329s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 330s Reading package lists... 330s Reading package lists... 330s Building dependency tree... 330s Reading state information... 330s Calculating upgrade... 330s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 330s Reading package lists... 330s Building dependency tree... 330s Reading state information... 330s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 333s autopkgtest [13:32:21]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 333s autopkgtest [13:32:21]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 336s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (dsc) [2770 B] 336s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (tar) [554 kB] 336s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.4-5ubuntu8 (diff) [42.7 kB] 336s gpgv: Signature made Sun Apr 7 00:31:08 2024 UTC 336s gpgv: using RSA key AC483F68DE728F43F2202FCA568D30F321B2133D 336s gpgv: issuer "steve.langasek@ubuntu.com" 336s gpgv: Can't check signature: No public key 336s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.4-5ubuntu8.dsc: no acceptable signature found 336s autopkgtest [13:32:24]: testing package multipath-tools version 0.9.4-5ubuntu8 336s autopkgtest [13:32:24]: build not needed 337s autopkgtest [13:32:25]: test kpartx-file-loopback: preparing testbed 338s Reading package lists... 338s Building dependency tree... 338s Reading state information... 338s Starting pkgProblemResolver with broken count: 0 338s Starting 2 pkgProblemResolver with broken count: 0 338s Done 339s The following additional packages will be installed: 339s liburing2 qemu-utils 339s Recommended packages: 339s qemu-block-extra 339s The following NEW packages will be installed: 339s autopkgtest-satdep liburing2 qemu-utils 339s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 339s Need to get 2330 kB/2331 kB of archives. 339s After this operation, 15.4 MB of additional disk space will be used. 339s Get:1 /tmp/autopkgtest.QfYMvG/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 339s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 339s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 340s Fetched 2330 kB in 1s (3409 kB/s) 340s Selecting previously unselected package liburing2:ppc64el. 340s (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 ... 72765 files and directories currently installed.) 340s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 340s Unpacking liburing2:ppc64el (2.6-1) ... 340s Selecting previously unselected package qemu-utils. 340s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 340s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 340s Selecting previously unselected package autopkgtest-satdep. 340s Preparing to unpack .../1-autopkgtest-satdep.deb ... 340s Unpacking autopkgtest-satdep (0) ... 340s Setting up liburing2:ppc64el (2.6-1) ... 340s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 340s Setting up autopkgtest-satdep (0) ... 340s Processing triggers for man-db (2.12.1-2) ... 341s Processing triggers for libc-bin (2.39-0ubuntu9) ... 342s (Reading database ... 72785 files and directories currently installed.) 342s Removing autopkgtest-satdep (0) ... 343s autopkgtest [13:32:31]: test kpartx-file-loopback: [----------------------- 343s Formatting 'foo.img', fmt=raw size=20971520 344s Creating new GPT entries in memory. 344s Warning: The kernel is still using the old partition table. 344s The new table will be used at the next reboot or after you 344s run partprobe(8) or kpartx(8) 344s The operation has completed successfully. 344s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 344s standard_filename: OK 344s del devmap : loop0p1 344s No devices found 344s standard_filename_cleanup: OK 344s Formatting 'fou du FaFa.img', fmt=raw size=20971520 345s Creating new GPT entries in memory. 345s Warning: The kernel is still using the old partition table. 345s The new table will be used at the next reboot or after you 345s run partprobe(8) or kpartx(8) 345s The operation has completed successfully. 345s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 345s filename_with_spaces: OK 345s del devmap : loop0p1 345s No devices found 345s filename_with_spaces_cleanup: OK 346s autopkgtest [13:32:34]: test kpartx-file-loopback: -----------------------] 346s autopkgtest [13:32:34]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 346s kpartx-file-loopback PASS 346s autopkgtest [13:32:34]: test tgtbasedmpaths: preparing testbed 521s autopkgtest [13:35:29]: testbed dpkg architecture: ppc64el 522s autopkgtest [13:35:30]: testbed apt version: 2.9.6 522s autopkgtest [13:35:30]: @@@@@@@@@@@@@@@@@@@@ test bed setup 523s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 523s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4092 B] 523s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [60.6 kB] 523s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [384 kB] 523s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 523s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [88.0 kB] 523s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2116 B] 523s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 523s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 523s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [394 kB] 523s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [8952 B] 523s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1840 B] 523s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 525s Fetched 1080 kB in 1s (1174 kB/s) 525s Reading package lists... 527s Reading package lists... 527s Building dependency tree... 527s Reading state information... 527s Calculating upgrade... 528s The following packages will be upgraded: 528s gdisk 528s 1 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 528s Need to get 258 kB of archives. 528s After this operation, 0 B of additional disk space will be used. 528s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el gdisk ppc64el 1.0.10-2 [258 kB] 528s Fetched 258 kB in 0s (640 kB/s) 528s (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 ... 72765 files and directories currently installed.) 528s Preparing to unpack .../gdisk_1.0.10-2_ppc64el.deb ... 528s Unpacking gdisk (1.0.10-2) over (1.0.10-1build1) ... 528s Setting up gdisk (1.0.10-2) ... 528s Processing triggers for man-db (2.12.1-2) ... 529s Reading package lists... 529s Building dependency tree... 529s Reading state information... 529s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 530s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 530s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 530s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 530s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 531s Reading package lists... 531s Reading package lists... 531s Building dependency tree... 531s Reading state information... 531s Calculating upgrade... 531s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 532s Reading package lists... 532s Building dependency tree... 532s Reading state information... 532s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 536s Reading package lists... 536s Building dependency tree... 536s Reading state information... 536s Starting pkgProblemResolver with broken count: 0 536s Starting 2 pkgProblemResolver with broken count: 0 536s Done 537s The following additional packages will be installed: 537s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 537s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 537s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 537s librdmacm1t64 lsscsi open-iscsi tgt 537s Suggested packages: 537s fio-examples gnuplot tgt-glusterfs tgt-rbd 537s Recommended packages: 537s finalrd 537s The following NEW packages will be installed: 537s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 537s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 537s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 537s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 537s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 537s Need to get 10.7 MB/10.7 MB of archives. 537s After this operation, 49.0 MB of additional disk space will be used. 537s Get:1 /tmp/autopkgtest.QfYMvG/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 537s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 537s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 537s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 537s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2 [80.5 kB] 537s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 537s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 537s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4ubuntu1 [21.5 kB] 537s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4ubuntu1 [311 kB] 537s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4ubuntu1 [46.5 kB] 537s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4ubuntu1 [99.2 kB] 537s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-1 [97.4 kB] 537s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 537s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 537s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 538s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 538s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 538s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 538s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 538s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 538s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 538s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 538s Preconfiguring packages ... 538s Fetched 10.7 MB in 1s (11.3 MB/s) 538s Selecting previously unselected package libopeniscsiusr. 538s (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 ... 72765 files and directories currently installed.) 538s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 538s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 538s Selecting previously unselected package libisns0t64:ppc64el. 538s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 538s Unpacking libisns0t64:ppc64el (0.101-1) ... 538s Selecting previously unselected package open-iscsi. 538s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 538s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 538s Selecting previously unselected package librdmacm1t64:ppc64el. 538s Preparing to unpack .../03-librdmacm1t64_52.0-2_ppc64el.deb ... 538s Unpacking librdmacm1t64:ppc64el (52.0-2) ... 538s Selecting previously unselected package libconfig-general-perl. 538s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 538s Unpacking libconfig-general-perl (2.65-2) ... 538s Selecting previously unselected package tgt. 538s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 538s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 538s Selecting previously unselected package libgfxdr0:ppc64el. 538s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_ppc64el.deb ... 538s Unpacking libgfxdr0:ppc64el (11.1-4ubuntu1) ... 538s Selecting previously unselected package libglusterfs0:ppc64el. 538s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_ppc64el.deb ... 538s Unpacking libglusterfs0:ppc64el (11.1-4ubuntu1) ... 538s Selecting previously unselected package libgfrpc0:ppc64el. 538s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_ppc64el.deb ... 538s Unpacking libgfrpc0:ppc64el (11.1-4ubuntu1) ... 538s Selecting previously unselected package libgfapi0:ppc64el. 538s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_ppc64el.deb ... 538s Unpacking libgfapi0:ppc64el (11.1-4ubuntu1) ... 538s Selecting previously unselected package libnbd0. 538s Preparing to unpack .../10-libnbd0_1.20.2-1_ppc64el.deb ... 538s Unpacking libnbd0 (1.20.2-1) ... 538s Selecting previously unselected package libdaxctl1:ppc64el. 538s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 538s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 539s Selecting previously unselected package libndctl6:ppc64el. 539s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 539s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 539s Selecting previously unselected package libpmem1:ppc64el. 539s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 539s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 539s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 539s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 539s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 539s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 539s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 539s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 539s Selecting previously unselected package librados2. 539s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 539s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 539s Selecting previously unselected package libpmemobj1:ppc64el. 539s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 539s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 539s Selecting previously unselected package librbd1. 539s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 539s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 539s Selecting previously unselected package fio. 539s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 539s Unpacking fio (3.37-1) ... 539s Selecting previously unselected package lsscsi. 539s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 539s Unpacking lsscsi (0.32-1build1) ... 539s Selecting previously unselected package autopkgtest-satdep. 539s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 539s Unpacking autopkgtest-satdep (0) ... 539s Setting up libconfig-general-perl (2.65-2) ... 539s Setting up libisns0t64:ppc64el (0.101-1) ... 539s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 539s Setting up libnbd0 (1.20.2-1) ... 539s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 539s Setting up libglusterfs0:ppc64el (11.1-4ubuntu1) ... 539s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 539s Setting up lsscsi (0.32-1build1) ... 539s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 539s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 539s Setting up librdmacm1t64:ppc64el (52.0-2) ... 539s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 539s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 540s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 540s Setting up libgfxdr0:ppc64el (11.1-4ubuntu1) ... 540s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 540s Setting up open-iscsi (2.1.10-1ubuntu1) ... 541s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 541s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 541s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 541s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 541s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 541s Setting up libgfrpc0:ppc64el (11.1-4ubuntu1) ... 541s Setting up libgfapi0:ppc64el (11.1-4ubuntu1) ... 541s Setting up fio (3.37-1) ... 542s Setting up autopkgtest-satdep (0) ... 542s Processing triggers for man-db (2.12.1-2) ... 543s Processing triggers for initramfs-tools (0.142ubuntu30) ... 543s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 543s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 550s Processing triggers for libc-bin (2.39-0ubuntu9) ... 553s (Reading database ... 73006 files and directories currently installed.) 553s Removing autopkgtest-satdep (0) ... 556s autopkgtest [13:36:04]: test tgtbasedmpaths: [----------------------- 556s + targetname=iqn.2016-11.foo.com:target.iscsi 556s + pwd 556s + cwd=/tmp/autopkgtest.QfYMvG/build.16N/src 556s + testdir=/mnt/tgtmpathtest 556s + localhost=127.0.0.1 556s + portal=127.0.0.1:3260 556s + maxpaths=4 556s + backfn=backingfile 556s + expectwwid=60000000000000000e00000000010001 556s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 556s + bglog=/tmp/autopkgtest.QfYMvG/tgtbasedmpaths-artifacts/test-background.log 556s + fioprep=/tmp/autopkgtest.QfYMvG/tgtbasedmpaths-artifacts/path-change-prep.fio 556s + fiovrfy=/tmp/autopkgtest.QfYMvG/tgtbasedmpaths-artifacts/path-change-check.fio 556s + service tgt restart 556s + truncate --size 100M backingfile 556s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 556s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 556s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.QfYMvG/build.16N/src/backingfile 556s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 556s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 556s login #1 556s + echo login #1 556s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 556s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 556s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 556s extra login #2 556s + seq 2 4 556s + echo extra login #2 556s + iscsiadm --mode session -r 1 --op new 556s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 556s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 556s extra login #3 556s + echo extra login #3 556s + iscsiadm --mode session -r 1 --op new 556s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 556s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 556s + echo extra login #4 556s + iscsiadm --mode session -r 1 --op new 556s extra login #4 556s + udevadm settle 556s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 556s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 556s + sleep 5 561s Status after initial setup 561s Target 1: iqn.2016-11.foo.com:target.iscsi 561s System information: 561s Driver: iscsi 561s State: ready 561s I_T nexus information: 561s I_T nexus: 1 561s Initiator: iqn.2004-10.com.ubuntu:01:da56f7d4d6c4 alias: autopkgtest 561s Connection: 0 561s IP Address: 127.0.0.1 561s I_T nexus: 2 561s Initiator: iqn.2004-10.com.ubuntu:01:da56f7d4d6c4 alias: autopkgtest 561s Connection: 0 561s IP Address: 127.0.0.1 561s I_T nexus: 3 561s Initiator: iqn.2004-10.com.ubuntu:01:da56f7d4d6c4 alias: autopkgtest 561s Connection: 0 561s IP Address: 127.0.0.1 561s I_T nexus: 4 561s Initiator: iqn.2004-10.com.ubuntu:01:da56f7d4d6c4 alias: autopkgtest 561s Connection: 0 561s IP Address: 127.0.0.1 561s LUN information: 561s LUN: 0 561s Type: controller 561s SCSI ID: IET 00010000 561s SCSI SN: beaf10 561s Size: 0 MB, Block size: 1 561s Online: Yes 561s Removable media: No 561s Prevent removal: No 561s Readonly: No 561s SWP: No 561s Thin-provisioning: No 561s Backing store type: null 561s Backing store path: None 561s Backing store flags: 561s LUN: 1 561s Type: disk 561s SCSI ID: IET 00010001 561s SCSI SN: beaf11 561s Size: 105 MB, Block size: 512 561s Online: Yes 561s Removable media: No 561s Prevent removal: No 561s Readonly: No 561s SWP: No 561s Thin-provisioning: No 561s Backing store type: rdwr 561s Backing store path: /tmp/autopkgtest.QfYMvG/build.16N/src/backingfile 561s Backing store flags: 561s Account information: 561s ACL information: 561s ALL 561s + echo Status after initial setup 561s + tgtadm --lld iscsi --mode target --op show 561s + tgtadm --lld iscsi --op show --mode conn --tid 1 561s Session: 4 561s Connection: 0 561s Initiator: iqn.2004-10.com.ubuntu:01:da56f7d4d6c4 561s IP Address: 127.0.0.1 561s Session: 3 561s Connection: 0 561s Initiator: iqn.2004-10.com.ubuntu:01:da56f7d4d6c4 561s IP Address: 127.0.0.1 561s Session: 2 561s Connection: 0 561s Initiator: iqn.2004-10.com.ubuntu:01:da56f7d4d6c4 561s IP Address: 127.0.0.1 561s Session: 1 561s Connection: 0 561s Initiator: iqn.2004-10.com.ubuntu:01:da56f7d4d6c4 561s IP Address: 127.0.0.1 561s + iscsiadm --mode session -P 1 562s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 562s Current Portal: 127.0.0.1:3260,1 562s Persistent Portal: 127.0.0.1:3260,1 562s ********** 562s Interface: 562s ********** 562s Iface Name: default 562s Iface Transport: tcp 562s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:da56f7d4d6c4 562s Iface IPaddress: 127.0.0.1 562s Iface HWaddress: default 562s Iface Netdev: default 562s SID: 1 562s iSCSI Connection State: LOGGED IN 562s iSCSI Session State: LOGGED_IN 562s Internal iscsid Session State: NO CHANGE 562s 562s ********** 562s Interface: 562s ********** 562s Iface Name: default 562s Iface Transport: tcp 562s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:da56f7d4d6c4 562s Iface IPaddress: 127.0.0.1 562s Iface HWaddress: default 562s Iface Netdev: default 562s SID: 2 562s iSCSI Connection State: LOGGED IN 562s iSCSI Session State: LOGGED_IN 562s Internal iscsid Session State: NO CHANGE 562s 562s ********** 562s Interface: 562s ********** 562s Iface Name: default 562s Iface Transport: tcp 562s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:da56f7d4d6c4 562s Iface IPaddress: 127.0.0.1 562s Iface HWaddress: default 562s Iface Netdev: default 562s SID: 3 562s iSCSI Connection State: LOGGED IN 562s iSCSI Session State: LOGGED_IN 562s Internal iscsid Session State: NO CHANGE 562s 562s ********** 562s Interface: 562s ********** 562s Iface Name: default 562s Iface Transport: tcp 562s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:da56f7d4d6c4 562s Iface IPaddress: 127.0.0.1 562s Iface HWaddress: default 562s Iface Netdev: default 562s SID: 4 562s iSCSI Connection State: LOGGED IN 562s iSCSI Session State: LOGGED_IN 562s Internal iscsid Session State: NO CHANGE 562s + lsscsi -liv 562s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 562s + multipath -v3 -ll 562s 82.725508 | set open fds limit to 1073741816/1073741816 562s 82.725595 | loading /lib/multipath/libchecktur.so checker 562s 82.725675 | checker tur: message table size = 3 562s 82.725704 | loading /lib/multipath/libprioconst.so prioritizer 562s 82.725815 | _init_foreign: foreign library "nvme" is not enabled 562s 82.731392 | sda: size = 167772160 562s 82.731562 | sda: vendor = QEMU 562s 82.731606 | sda: product = QEMU HARDDISK 562s 82.731628 | sda: rev = 2.5+ 562s 82.732271 | sda: h:b:t:l = 0:0:0:0 562s 82.732601 | sda: tgt_node_name = 562s 82.732623 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 562s 82.732626 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 562s 82.732782 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 562s 82.732805 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 562s 82.732817 | __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 562s 82.732822 | failed to read sysfs vpd pg80: No such file or directory 562s 82.733053 | sda: fail to get serial 562s 82.733076 | sda: detect_checker = yes (setting: multipath internal) 562s 82.733286 | sda: path_checker = tur (setting: multipath internal) 562s 82.733308 | sda: checker timeout = 30 s (setting: kernel sysfs) 562s 82.733465 | sda: tur state = up 562s 82.733783 | sdb: size = 204800 562s 82.733936 | sdb: vendor = IET 562s 82.733977 | sdb: product = VIRTUAL-DISK 562s 82.733999 | sdb: rev = 0001 562s 82.734625 | sdb: h:b:t:l = 1:0:0:1 562s 82.734995 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 562s 82.735017 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 562s 82.735019 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 562s 82.735176 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 562s 82.735198 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 562s 82.735215 | sdb: serial = beaf11 562s 82.735217 | sdb: detect_checker = yes (setting: multipath internal) 562s 82.735622 | sdb: path_checker = tur (setting: multipath internal) 562s 82.735644 | sdb: checker timeout = 30 s (setting: kernel sysfs) 562s 82.735831 | sdb: tur state = up 562s 82.735975 | sdc: size = 204800 562s 82.736138 | sdc: vendor = IET 562s 82.736183 | sdc: product = VIRTUAL-DISK 562s 82.736204 | sdc: rev = 0001 562s 82.736891 | sdc: h:b:t:l = 2:0:0:1 562s 82.737281 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 562s 82.737303 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 562s 82.737306 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 562s 82.737453 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 562s 82.737474 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 562s 82.737488 | sdc: serial = beaf11 562s 82.737491 | sdc: detect_checker = yes (setting: multipath internal) 562s 82.737729 | sdc: path_checker = tur (setting: multipath internal) 562s 82.737751 | sdc: checker timeout = 30 s (setting: kernel sysfs) 562s 82.737932 | sdc: tur state = up 562s 82.738083 | sdd: size = 204800 562s 82.738237 | sdd: vendor = IET 562s 82.738278 | sdd: product = VIRTUAL-DISK 562s 82.738300 | sdd: rev = 0001 562s 82.738973 | sdd: h:b:t:l = 3:0:0:1 562s 82.739351 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 562s 82.739372 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 562s 82.739375 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 562s 82.739523 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 562s 82.739545 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 562s 82.739559 | sdd: serial = beaf11 562s 82.739562 | sdd: detect_checker = yes (setting: multipath internal) 562s 82.739779 | sdd: path_checker = tur (setting: multipath internal) 562s 82.739801 | sdd: checker timeout = 30 s (setting: kernel sysfs) 562s 82.739908 | sdd: tur state = up 562s 82.740064 | sde: size = 204800 562s 82.740205 | sde: vendor = IET 562s 82.740246 | sde: product = VIRTUAL-DISK 562s 82.740268 | sde: rev = 0001 562s 82.740958 | sde: h:b:t:l = 4:0:0:1 562s 82.742148 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 562s 82.742214 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 562s 82.742218 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 562s 82.742487 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 562s 82.742522 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 562s 82.742547 | sde: serial = beaf11 562s 82.742551 | sde: detect_checker = yes (setting: multipath internal) 562s 82.742868 | sde: path_checker = tur (setting: multipath internal) 562s 82.742902 | sde: checker timeout = 30 s (setting: kernel sysfs) 562s 82.743027 | sde: tur state = up 562s 82.743216 | loop0: device node name blacklisted 562s 82.743388 | loop1: device node name blacklisted 562s 82.743556 | loop2: device node name blacklisted 562s 82.743721 | loop3: device node name blacklisted 562s 82.743885 | loop4: device node name blacklisted 562s 82.744066 | loop5: device node name blacklisted 562s 82.744216 | loop6: device node name blacklisted 562s 82.744381 | loop7: device node name blacklisted 562s 82.744558 | dm-0: device node name blacklisted 562s 82.746174 | multipath-tools v0.9.4 (12/19, 2022) 562s 82.746221 | libdevmapper version 1.02.185 562s 82.746443 | kernel device mapper v4.48.0 562s 82.746490 | DM multipath kernel driver v1.14.0 562s 82.746672 | sdb: size = 204800 562s 82.746706 | sdb: vendor = IET 562s 82.746711 | sdb: product = VIRTUAL-DISK 562s 82.746715 | sdb: rev = 0001 562s 82.747732 | sdb: h:b:t:l = 1:0:0:1 562s 82.747946 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 562s 82.748042 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 562s 82.748080 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 562s 82.748102 | sdb: serial = beaf11 562s 82.748329 | sdb: tur state = up 562s 82.748354 | sdb: uid = 360000000000000000e00000000010001 (udev) 562s 82.748358 | sdb: detect_prio = yes (setting: multipath internal) 562s 82.748362 | sdb: prio = const (setting: multipath internal) 562s 82.748364 | sdb: prio args = "" (setting: multipath internal) 562s 82.748367 | sdb: const prio = 1 562s 82.748398 | sdc: size = 204800 562s 82.748403 | sdc: vendor = IET 562s 82.748406 | sdc: product = VIRTUAL-DISK 562s 82.748409 | sdc: rev = 0001 562s 82.749094 | sdc: h:b:t:l = 2:0:0:1 562s 82.749253 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 562s 82.749297 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 562s 82.749300 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 562s 82.749314 | sdc: serial = beaf11 562s 82.749494 | sdc: tur state = up 562s 82.749518 | sdc: uid = 360000000000000000e00000000010001 (udev) 562s 82.749521 | sdc: detect_prio = yes (setting: multipath internal) 562s 82.749524 | sdc: prio = const (setting: multipath internal) 562s 82.749526 | sdc: prio args = "" (setting: multipath internal) 562s 82.749529 | sdc: const prio = 1 562s 82.749557 | sdd: size = 204800 562s 82.749564 | sdd: vendor = IET 562s 82.749567 | sdd: product = VIRTUAL-DISK 562s 82.749570 | sdd: rev = 0001 562s 82.750250 | sdd: h:b:t:l = 3:0:0:1 562s 82.750401 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 562s 82.750444 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 562s 82.750447 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 562s 82.750461 | sdd: serial = beaf11 562s 82.750630 | sdd: tur state = up 562s 82.750653 | sdd: uid = 360000000000000000e00000000010001 (udev) 562s 82.750656 | sdd: detect_prio = yes (setting: multipath internal) 562s 82.750659 | sdd: prio = const (setting: multipath internal) 562s 82.750661 | sdd: prio args = "" (setting: multipath internal) 562s 82.750664 | sdd: const prio = 1 562s 82.750688 | sde: size = 204800 562s 82.750693 | sde: vendor = IET 562s 82.750696 | sde: product = VIRTUAL-DISK 562s 82.750699 | sde: rev = 0001 562s 82.751376 | sde: h:b:t:l = 4:0:0:1 562s 82.751521 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 562s 82.751562 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 562s 82.751565 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 562s 82.751578 | sde: serial = beaf11 562s 82.751742 | sde: tur state = up 562s 82.751764 | sde: uid = 360000000000000000e00000000010001 (udev) 562s 82.751767 | sde: detect_prio = yes (setting: multipath internal) 562s 82.751770 | sde: prio = const (setting: multipath internal) 562s 82.751772 | sde: prio args = "" (setting: multipath internal) 562s 82.751775 | sde: const prio = 1 562s 82.752785 | unloading tur checker 562s 82.752871 | unloading const prioritizer 562s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 562s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 562s 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] 562s [1:0:0:0] storage IET Controller 0001 - - 562s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 562s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 562s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 562s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 562s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 562s [2:0:0:0] storage IET Controller 0001 - - 562s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 562s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 562s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 562s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 562s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 562s [3:0:0:0] storage IET Controller 0001 - - 562s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 562s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 562s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 562s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 562s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 562s [4:0:0:0] storage IET Controller 0001 - - 562s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 562s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 562s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 562s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 562s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 562s NVMe module may not be loaded 562s ===== paths list ===== 562s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 562s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK unknown 562s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK unknown 562s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK unknown 562s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK unknown 562s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK unknown 562s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 562s size=100M features='0' hwhandler='0' wp=rw 562s |-+- policy='service-time 0' prio=1 status=active 562s | `- 1:0:0:1 sdb 8:16 active ready running 562s |-+- policy='service-time 0' prio=1 status=enabled 562s | `- 2:0:0:1 sdc 8:32 active ready running 562s |-+- policy='service-time 0' prio=1 status=enabled 562s | `- 3:0:0:1 sdd 8:48 active ready running 562s `-+- policy='service-time 0' prio=1 status=enabled 562s `- 4:0:0:1 sde 8:64 active ready running 562s 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 562s Test WWN should now point to DM 562s ../../dm-0 562s Creating filesystem with 25600 4k blocks and 25600 inodes 562s 562s Allocating group tables: 0/1 done 562s Writing inode tables: 0/1 done 562s Creating journal (1024 blocks): + dmsetup table 562s + echo Test WWN should now point to DM 562s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 562s + grep dm 562s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 562s mke2fs 1.47.1 (20-May-2024) 562s done 562s Writing superblocks and filesystem accounting information: 0/1 done 562s 562s + udevadm settle 562s + sleep 3s 565s + mkdir -p /mnt/tgtmpathtest 565s + mount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 /mnt/tgtmpathtest 565s + cat 565s + cat 565s + fio --max-jobs=4 /tmp/autopkgtest.QfYMvG/tgtbasedmpaths-artifacts/path-change-prep.fio 565s 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 565s fio-3.37 565s Starting 1 thread 565s write-phase: Laying out IO file (1 file / 17592186044415MiB) 566s fio: io_u error on file /mnt/tgtmpathtest/datafile.tmp: No space left on device: write offset=91750400, buflen=65536 566s 566s write-phase: (groupid=0, jobs=1): err= 0: pid=6434: Sat Jul 20 13:36:14 2024 566s write: IOPS=2199, BW=137MiB/s (144MB/s)(87.5MiB/637msec); 0 zone resets 566s clat (usec): min=281, max=4055, avg=437.43, stdev=219.16 566s lat (usec): min=294, max=4068, avg=452.97, stdev=220.52 566s clat percentiles (usec): 566s | 1.00th=[ 310], 5.00th=[ 326], 10.00th=[ 334], 20.00th=[ 351], 566s | 30.00th=[ 363], 40.00th=[ 383], 50.00th=[ 396], 60.00th=[ 408], 566s | 70.00th=[ 429], 80.00th=[ 469], 90.00th=[ 537], 95.00th=[ 644], 566s | 99.00th=[ 1270], 99.50th=[ 1582], 99.90th=[ 3589], 99.95th=[ 4047], 566s | 99.99th=[ 4047] 566s bw ( KiB/s): min=141824, max=141824, per=100.00%, avg=141824.00, stdev= 0.00, samples=1 566s iops : min= 2216, max= 2216, avg=2216.00, stdev= 0.00, samples=1 566s lat (usec) : 500=85.22%, 750=12.28%, 1000=0.64% 566s lat (msec) : 2=1.36%, 4=0.36%, 10=0.07% 566s cpu : usr=4.56%, sys=8.65%, ctx=1402, majf=0, minf=0 566s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 566s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 566s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 566s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 566s latency : target=0, window=0, percentile=100.00%, depth=1 566s 566s Run status group 0 (all jobs): 566s WRITE: bw=137MiB/s (144MB/s), 137MiB/s-137MiB/s (144MB/s-144MB/s), io=87.5MiB (91.8MB), run=637-637msec 566s 566s Disk stats (read/write): 566s dm-0: ios=1/877, sectors=8/112256, merge=0/0, ticks=1/359, in_queue=359, util=80.82%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/142, aggrin_queue=143, aggrutil=84.66% 566s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 566s sdb: ios=1/1402, sectors=8/179280, merge=0/0, ticks=1/571, in_queue=572, util=84.66% 566s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 566s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 566s + echo Starting the path changes in background 566s Starting the path changes in background 566s + date +Pre FIO %H:%M:%S.%N 566s + fio --max-jobs=4 /tmp/autopkgtest.QfYMvG/tgtbasedmpaths-artifacts/path-change-check.fio 566s Pre FIO 13:36:14.231392715 566s 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 566s fio-3.37 566s Starting 1 thread 746s 746s verify-phase: (groupid=0, jobs=1): err= 0: pid=6441: Sat Jul 20 13:39:14 2024 746s read: IOPS=3238, BW=202MiB/s (212MB/s)(35.6GiB/180001msec) 746s clat (usec): min=86, max=45194, avg=285.96, stdev=172.44 746s lat (usec): min=86, max=45195, avg=286.07, stdev=172.44 746s clat percentiles (usec): 746s | 1.00th=[ 104], 5.00th=[ 163], 10.00th=[ 188], 20.00th=[ 210], 746s | 30.00th=[ 225], 40.00th=[ 262], 50.00th=[ 302], 60.00th=[ 314], 746s | 70.00th=[ 330], 80.00th=[ 347], 90.00th=[ 375], 95.00th=[ 396], 746s | 99.00th=[ 453], 99.50th=[ 519], 99.90th=[ 1254], 99.95th=[ 1827], 746s | 99.99th=[ 4293] 746s bw ( KiB/s): min=140928, max=396544, per=100.00%, avg=207565.46, stdev=44593.11, samples=359 746s iops : min= 2202, max= 6196, avg=3243.13, stdev=696.77, samples=359 746s lat (usec) : 100=0.75%, 250=37.28%, 500=61.40%, 750=0.31%, 1000=0.11% 746s lat (msec) : 2=0.11%, 4=0.03%, 10=0.01%, 20=0.01%, 50=0.01% 746s cpu : usr=8.53%, sys=6.29%, ctx=582949, majf=0, minf=1 746s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 746s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 746s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 746s issued rwts: total=582858,0,0,0 short=0,0,0,0 dropped=0,0,0,0 746s latency : target=0, window=0, percentile=100.00%, depth=1 746s 746s Run status group 0 (all jobs): 746s READ: bw=202MiB/s (212MB/s), 202MiB/s-202MiB/s (212MB/s-212MB/s), io=35.6GiB (38.2GB), run=180001-180001msec 746s 746s Disk stats (read/write): 746s dm-0: ios=583046/11, sectors=74573496/12944, merge=10/10, ticks=168875/71, in_queue=168991, util=100.00%, aggrios=39654/2, aggsectors=5071214/3236, aggrmerge=0/0, aggrticks=10911/6, aggrin_queue=10918, aggrutil=99.20% 746s sdd: ios=31931/0, sectors=4084224/0, merge=0/0, ticks=8641/0, in_queue=8640, util=32.98% 746s sdb: ios=29481/10, sectors=3770624/12944, merge=0/0, ticks=8567/27, in_queue=8593, util=99.20% 746s sde: ios=66448/0, sectors=8499200/0, merge=0/0, ticks=17591/0, in_queue=17591, util=40.05% 746s sdc: ios=30756/0, sectors=3930808/0, merge=0/0, ticks=8848/0, in_queue=8848, util=50.10% 746s + date +Post FIO %H:%M:%S.%N 746s + echo FIO verify test with changing paths - OK 746s + echo Report log of background activity 746s + cat /tmp/autopkgtest.QfYMvG/tgtbasedmpaths-artifacts/test-background.log 746s Post FIO 13:39:14.570877346 746s FIO verify test with changing paths - OK 746s Report log of background activity 746s + iscsiadm --mode session 746s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s + sleep 10s 746s + date +MP report (expect 4) %H:%M:%S.%N 746s MP report (expect 4) 13:36:24.239252751 746s + multipath -ll 746s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 746s size=100M features='0' hwhandler='0' wp=rw 746s |-+- policy='service-time 0' prio=1 status=active 746s | `- 1:0:0:1 sdb 8:16 active ready running 746s |-+- policy='service-time 0' prio=1 status=enabled 746s | `- 2:0:0:1 sdc 8:32 active ready running 746s |-+- policy='service-time 0' prio=1 status=enabled 746s | `- 3:0:0:1 sdd 8:48 active ready running 746s `-+- policy='service-time 0' prio=1 status=enabled 746s `- 4:0:0:1 sde 8:64 active ready running 746s + date +UN-plug path 1 %H:%M:%S.%N 746s UN-plug path 1 13:36:24.267197316 746s + iscsiadm --mode session -r 1 -u 746s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 746s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 746s + iscsiadm --mode session 746s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s + sleep 10s 746s + date +MP report (expect 3) %H:%M:%S.%N 746s MP report (expect 3) 13:36:34.367291008 746s + multipath -ll 746s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 746s size=100M features='0' hwhandler='0' wp=rw 746s |-+- policy='service-time 0' prio=1 status=active 746s | `- 2:0:0:1 sdc 8:32 active ready running 746s |-+- policy='service-time 0' prio=1 status=enabled 746s | `- 3:0:0:1 sdd 8:48 active ready running 746s `-+- policy='service-time 0' prio=1 status=enabled 746s `- 4:0:0:1 sde 8:64 active ready running 746s + date +UN-plug path 2 %H:%M:%S.%N 746s UN-plug path 2 13:36:34.390427102 746s + iscsiadm --mode session -r 2 -u 746s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 746s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 746s + iscsiadm --mode session 746s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s + sleep 10s 746s + date +MP report (expect 2) %H:%M:%S.%N 746s MP report (expect 2) 13:36:44.484885877 746s + multipath -ll 746s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 746s size=100M features='0' hwhandler='0' wp=rw 746s |-+- policy='service-time 0' prio=1 status=active 746s | `- 3:0:0:1 sdd 8:48 active ready running 746s `-+- policy='service-time 0' prio=1 status=enabled 746s `- 4:0:0:1 sde 8:64 active ready running 746s + date +UN-plug path 3 %H:%M:%S.%N 746s UN-plug path 3 13:36:44.504783900 746s + iscsiadm --mode session -r 3 -u 746s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 746s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 746s + iscsiadm --mode session 746s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s + sleep 10s 746s + date +MP report (expect 1) %H:%M:%S.%N 746s MP report (expect 1) 13:36:54.615302192 746s + multipath -ll 746s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 746s size=100M features='0' hwhandler='0' wp=rw 746s `-+- policy='service-time 0' prio=1 status=active 746s `- 4:0:0:1 sde 8:64 active ready running 746s + date +Add paths 5/6/7/8 %H:%M:%S.%N 746s Add paths 5/6/7/8 13:36:54.633650985 746s + iscsiadm --mode session -r 4 --op new 746s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 746s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 746s + iscsiadm --mode session -r 4 --op new 746s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 746s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 746s + iscsiadm --mode session -r 4 --op new 746s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 746s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 746s + iscsiadm --mode session -r 4 --op new 746s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 746s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 746s + iscsiadm --mode session 746s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s + sleep 10s 746s + date +MP report (expect 5) %H:%M:%S.%N 746s MP report (expect 5) 13:37:04.777316379 746s + multipath -ll 746s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 746s size=100M features='0' hwhandler='0' wp=rw 746s |-+- policy='service-time 0' prio=1 status=active 746s | `- 4:0:0:1 sde 8:64 active ready running 746s |-+- policy='service-time 0' prio=1 status=enabled 746s | `- 1:0:0:1 sdb 8:16 active ready running 746s |-+- policy='service-time 0' prio=1 status=enabled 746s | `- 2:0:0:1 sdc 8:32 active ready running 746s |-+- policy='service-time 0' prio=1 status=enabled 746s | `- 3:0:0:1 sdd 8:48 active ready running 746s `-+- policy='service-time 0' prio=1 status=enabled 746s `- 5:0:0:1 sdf 8:80 active ready running 746s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 746s UN-plug multiple paths 4/7/8 13:37:04.809847877 746s + iscsiadm --mode session -r 4 -u 746s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 746s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 746s + iscsiadm --mode session -r 7 -u 746s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 746s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 746s + iscsiadm --mode session -r 8 -u 746s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 746s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 746s + iscsiadm --mode session 746s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 746s + sleep 10s 746s + date +Restart multipath daemon %H:%M:%S.%N 746s Restart multipath daemon 13:37:15.081980520 746s + systemctl restart multipathd 746s + sleep 10s 746s + date +Final background report (expect 2) %H:%M:%S.%N 746s Final background report (expect 2) 13:37:25.189670312 746s + multipath -ll 746s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 746s size=100M features='0' hwhandler='0' wp=rw 746s |-+- policy='service-time 0' prio=1 status=active 746s | `- 1:0:0:1 sdb 8:16 active ready running 746s `-+- policy='service-time 0' prio=1 status=enabled 746s `- 2:0:0:1 sdc 8:32 active ready running 746s Final stats 746s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 746s iSCSI SNMP: 746s txdata_octets: 20344968 746s rxdata_octets: 27754579188 746s noptx_pdus: 0 746s scsicmd_pdus: 423586 746s tmfcmd_pdus: 0 746s login_pdus: 0 746s text_pdus: 0 746s dataout_pdus: 0 746s logout_pdus: 0 746s snack_pdus: 0 746s noprx_pdus: 0 746s scsirsp_pdus: 423586 746s tmfrsp_pdus: 0 746s textrsp_pdus: 0 746s datain_pdus: 423553 746s logoutrsp_pdus: 0 746s r2t_pdus: 0 746s async_pdus: 0 746s rjt_pdus: 0 746s digest_err: 0 746s timeout_err: 0 746s iSCSI Extended: 746s tx_sendpage_failures: 0 746s rx_discontiguous_hdr: 0 746s eh_abort_cnt: 0 746s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 746s iSCSI SNMP: 746s txdata_octets: 6456 746s rxdata_octets: 1514916 746s noptx_pdus: 0 746s scsicmd_pdus: 105 746s tmfcmd_pdus: 0 746s login_pdus: 0 746s text_pdus: 0 746s dataout_pdus: 0 746s logout_pdus: 0 746s snack_pdus: 0 746s noprx_pdus: 0 746s scsirsp_pdus: 105 746s tmfrsp_pdus: 0 746s textrsp_pdus: 0 746s datain_pdus: 83 746s logoutrsp_pdus: 0 746s r2t_pdus: 0 746s async_pdus: 0 746s rjt_pdus: 0 746s digest_err: 0 746s timeout_err: 0 746s iSCSI Extended: 746s tx_sendpage_failures: 0 746s rx_discontiguous_hdr: 0 746s eh_abort_cnt: 0 746s Jul 20 12:36:07 adtubuntu-oracular-ppc64el-server-20240719 multipathd[290]: multipathd: shut down 746s Jul 20 12:36:07 adtubuntu-oracular-ppc64el-server-20240719 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 746s Jul 20 12:36:07 adtubuntu-oracular-ppc64el-server-20240719 systemd[1]: multipathd.service: Deactivated successfully. 746s Jul 20 12:36:07 adtubuntu-oracular-ppc64el-server-20240719 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 746s -- Boot ee52a9f424c54bc5bd88b7007dc4476e -- 746s Jul 20 13:34:50 adtubuntu-oracular-ppc64el-server-20240719 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 746s Jul 20 13:34:50 adtubuntu-oracular-ppc64el-server-20240719 multipathd[343]: multipathd v0.9.4: start up 746s Jul 20 13:34:50 adtubuntu-oracular-ppc64el-server-20240719 multipathd[343]: reconfigure: setting up paths and maps 746s Jul 20 13:34:50 adtubuntu-oracular-ppc64el-server-20240719 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 746s Jul 20 13:36:04 autopkgtest multipathd[343]: 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] 746s Jul 20 13:36:04 autopkgtest multipathd[343]: sdc [8:32]: path added to devmap mpatha 746s Jul 20 13:36:04 autopkgtest multipathd[343]: mpatha: performing delayed actions 746s Jul 20 13:36:04 autopkgtest multipathd[343]: 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] 746s Jul 20 13:36:24 autopkgtest multipathd[343]: 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] 746s Jul 20 13:36:24 autopkgtest multipathd[343]: check_removed_paths: sdb: freeing path in removed state 746s Jul 20 13:36:24 autopkgtest multipathd[343]: 8:16: path removed from map mpatha 746s Jul 20 13:36:34 autopkgtest multipathd[343]: 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] 746s Jul 20 13:36:34 autopkgtest multipathd[343]: check_removed_paths: sdc: freeing path in removed state 746s Jul 20 13:36:34 autopkgtest multipathd[343]: 8:32: path removed from map mpatha 746s Jul 20 13:36:44 autopkgtest multipathd[343]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 746s Jul 20 13:36:44 autopkgtest multipathd[343]: check_removed_paths: sdd: freeing path in removed state 746s Jul 20 13:36:44 autopkgtest multipathd[343]: 8:48: path removed from map mpatha 746s Jul 20 13:36:54 autopkgtest multipathd[343]: 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] 746s Jul 20 13:36:54 autopkgtest multipathd[343]: sdb [8:16]: path added to devmap mpatha 746s Jul 20 13:36:54 autopkgtest multipathd[343]: 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] 746s Jul 20 13:36:54 autopkgtest multipathd[343]: sdc [8:32]: path added to devmap mpatha 746s Jul 20 13:36:54 autopkgtest multipathd[343]: 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] 746s Jul 20 13:36:54 autopkgtest multipathd[343]: sdd [8:48]: path added to devmap mpatha 746s Jul 20 13:36:54 autopkgtest multipathd[343]: 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] 746s Jul 20 13:36:54 autopkgtest multipathd[343]: sdf [8:80]: path added to devmap mpatha 746s Jul 20 13:37:04 autopkgtest multipathd[343]: 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] 746s Jul 20 13:37:04 autopkgtest multipathd[343]: check_removed_paths: sde: freeing path in removed state 746s Jul 20 13:37:04 autopkgtest multipathd[343]: 8:64: path removed from map mpatha 746s Jul 20 13:37:04 autopkgtest multipathd[343]: 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] 746s Jul 20 13:37:04 autopkgtest multipathd[343]: check_removed_paths: sdd: freeing path in removed state 746s Jul 20 13:37:04 autopkgtest multipathd[343]: 8:48: path removed from map mpatha 746s Jul 20 13:37:05 autopkgtest multipathd[343]: 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] 746s Jul 20 13:37:05 autopkgtest multipathd[343]: check_removed_paths: sdf: freeing path in removed state 746s Jul 20 13:37:05 autopkgtest multipathd[343]: 8:80: path removed from map mpatha 746s Jul 20 13:37:15 autopkgtest multipathd[343]: multipathd: shut down 746s Jul 20 13:37:15 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 746s Jul 20 13:37:15 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 746s Jul 20 13:37:15 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 746s Jul 20 13:37:15 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 746s Jul 20 13:37:15 autopkgtest multipathd[6826]: multipathd v0.9.4: start up 746s Jul 20 13:37:15 autopkgtest multipathd[6826]: reconfigure: setting up paths and maps 746s Jul 20 13:37:15 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 746s Check final path status 746s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 746s size=100M features='0' hwhandler='0' wp=rw 746s |-+- policy='service-time 0' prio=1 status=active 746s | `- 1:0:0:1 sdb 8:16 active ready running 746s `-+- policy='service-time 0' prio=1 status=enabled 746s `- 2:0:0:1 sdc 8:32 active ready running 746s + sync 746s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 746s + echo Final stats 746s + iscsiadm --mode session --stats 746s + journalctl --no-pager -u multipathd 746s + echo Check final path status 746s + multipath -ll 746s + multipath -ll 746s + grep --count status= 746s + diskc=2 746s + multipath -ll 746s + grep --count status=active 746s + diska=1 746s + multipath -ll 746s + grep --count status=enabled 746s OK 746s + diske=1 746s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 746s + echo OK 746s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 746s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 746s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 746s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 746s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 746s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 747s autopkgtest [13:39:15]: test tgtbasedmpaths: -----------------------] 747s autopkgtest [13:39:15]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 747s tgtbasedmpaths PASS 748s autopkgtest [13:39:16]: @@@@@@@@@@@@@@@@@@@@ summary 748s kpartx-file-loopback PASS 748s tgtbasedmpaths PASS 763s nova [W] Using flock in scalingstack-bos01-ppc64el 763s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240720-132647-juju-7f2275-prod-proposed-migration-environment-2-e96df37d-868f-4fc2-8b99-a908cee7e287 from image adt/ubuntu-oracular-ppc64el-server-20240720.img (UUID 9e0d1223-8d9c-4f47-a977-7dfc1ecc813d)... 763s nova [W] Using flock in scalingstack-bos01-ppc64el 763s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240720-132647-juju-7f2275-prod-proposed-migration-environment-2-e96df37d-868f-4fc2-8b99-a908cee7e287 from image adt/ubuntu-oracular-ppc64el-server-20240720.img (UUID 9e0d1223-8d9c-4f47-a977-7dfc1ecc813d)...