0s autopkgtest [19:19:01]: starting date and time: 2024-09-05 19:19:01+0000 0s autopkgtest [19:19:01]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [19:19:01]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.xcugvadi/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:multipath-tools --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=multipath-tools/0.9.9-1ubuntu3 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos01-ppc64el-21.secgroup --name adt-oracular-ppc64el-multipath-tools-20240905-191900-juju-7f2275-prod-proposed-migration-environment-3-1e659f0f-4d61-4447-a458-1ad2e7248ef8 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://us.ports.ubuntu.com/ubuntu-ports/ 121s autopkgtest [19:21:02]: testbed dpkg architecture: ppc64el 121s autopkgtest [19:21:02]: testbed apt version: 2.9.8 121s autopkgtest [19:21:02]: @@@@@@@@@@@@@@@@@@@@ test bed setup 122s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 123s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [8820 B] 123s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [679 kB] 123s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.9 kB] 123s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8376 B] 123s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [45.9 kB] 123s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [1064 B] 123s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1372 B] 123s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 123s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [616 kB] 123s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [14.8 kB] 123s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [4656 B] 123s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [340 B] 125s Fetched 1546 kB in 1s (1673 kB/s) 125s Reading package lists... 127s Reading package lists... 127s Building dependency tree... 127s Reading state information... 127s Calculating upgrade... 127s The following packages will be upgraded: 127s kpartx multipath-tools 128s 2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 128s Need to get 390 kB of archives. 128s After this operation, 2048 B of additional disk space will be used. 128s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el kpartx ppc64el 0.9.9-1ubuntu3 [37.6 kB] 128s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el multipath-tools ppc64el 0.9.9-1ubuntu3 [353 kB] 128s Fetched 390 kB in 0s (782 kB/s) 128s (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 ... 72467 files and directories currently installed.) 128s Preparing to unpack .../kpartx_0.9.9-1ubuntu3_ppc64el.deb ... 128s Unpacking kpartx (0.9.9-1ubuntu3) over (0.9.9-1ubuntu2) ... 128s Preparing to unpack .../multipath-tools_0.9.9-1ubuntu3_ppc64el.deb ... 128s Unpacking multipath-tools (0.9.9-1ubuntu3) over (0.9.9-1ubuntu2) ... 129s Setting up kpartx (0.9.9-1ubuntu3) ... 129s Setting up multipath-tools (0.9.9-1ubuntu3) ... 129s Processing triggers for man-db (2.12.1-3) ... 130s Processing triggers for libc-bin (2.40-1ubuntu1) ... 130s Reading package lists... 130s Building dependency tree... 130s Reading state information... 130s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 131s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 131s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 131s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 131s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 132s Reading package lists... 132s Reading package lists... 132s Building dependency tree... 132s Reading state information... 132s Calculating upgrade... 132s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 132s Reading package lists... 133s Building dependency tree... 133s Reading state information... 133s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 133s autopkgtest [19:21:14]: rebooting testbed after setup commands that affected boot 167s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 182s autopkgtest [19:22:03]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 185s autopkgtest [19:22:06]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 188s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main multipath-tools 0.9.9-1ubuntu3 (dsc) [2772 B] 188s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main multipath-tools 0.9.9-1ubuntu3 (tar) [588 kB] 188s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main multipath-tools 0.9.9-1ubuntu3 (diff) [42.7 kB] 188s gpgv: Signature made Thu Sep 5 17:42:16 2024 UTC 188s gpgv: using RSA key 63EEFC3DE14D5146CE7F24BF34B8AD7D9529E793 188s gpgv: Can't check signature: No public key 188s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.9-1ubuntu3.dsc: no acceptable signature found 188s autopkgtest [19:22:09]: testing package multipath-tools version 0.9.9-1ubuntu3 188s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 188s autopkgtest [19:22:09]: build not needed 189s autopkgtest [19:22:10]: test kpartx-file-loopback: preparing testbed 189s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 190s Reading package lists... 190s Building dependency tree... 190s Reading state information... 191s Starting pkgProblemResolver with broken count: 0 191s Starting 2 pkgProblemResolver with broken count: 0 191s Done 191s The following additional packages will be installed: 191s liburing2 qemu-utils 191s Recommended packages: 191s qemu-block-extra 191s The following NEW packages will be installed: 191s autopkgtest-satdep liburing2 qemu-utils 191s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 191s Need to get 2432 kB/2433 kB of archives. 191s After this operation, 16.9 MB of additional disk space will be used. 191s Get:1 /tmp/autopkgtest.emREIN/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 191s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 191s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:9.0.2+ds-4ubuntu2 [2405 kB] 192s Fetched 2432 kB in 1s (3214 kB/s) 192s Selecting previously unselected package liburing2:ppc64el. 192s (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 ... 72467 files and directories currently installed.) 192s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 192s Unpacking liburing2:ppc64el (2.6-1) ... 192s Selecting previously unselected package qemu-utils. 192s Preparing to unpack .../qemu-utils_1%3a9.0.2+ds-4ubuntu2_ppc64el.deb ... 192s Unpacking qemu-utils (1:9.0.2+ds-4ubuntu2) ... 192s Selecting previously unselected package autopkgtest-satdep. 192s Preparing to unpack .../1-autopkgtest-satdep.deb ... 192s Unpacking autopkgtest-satdep (0) ... 192s Setting up liburing2:ppc64el (2.6-1) ... 192s Setting up qemu-utils (1:9.0.2+ds-4ubuntu2) ... 192s Setting up autopkgtest-satdep (0) ... 192s Processing triggers for man-db (2.12.1-3) ... 193s Processing triggers for libc-bin (2.40-1ubuntu1) ... 195s (Reading database ... 72491 files and directories currently installed.) 195s Removing autopkgtest-satdep (0) ... 196s autopkgtest [19:22:17]: test kpartx-file-loopback: [----------------------- 196s Formatting 'foo.img', fmt=raw size=20971520 197s Creating new GPT entries in memory. 197s Warning: The kernel is still using the old partition table. 197s The new table will be used at the next reboot or after you 197s run partprobe(8) or kpartx(8) 197s The operation has completed successfully. 197s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 197s standard_filename: OK 197s del devmap : loop0p1 197s No devices found 197s standard_filename_cleanup: OK 197s Formatting 'fou du FaFa.img', fmt=raw size=20971520 198s Creating new GPT entries in memory. 198s Warning: The kernel is still using the old partition table. 198s The new table will be used at the next reboot or after you 198s run partprobe(8) or kpartx(8) 198s The operation has completed successfully. 198s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 198s filename_with_spaces: OK 198s del devmap : loop0p1 198s No devices found 198s filename_with_spaces_cleanup: OK 199s autopkgtest [19:22:20]: test kpartx-file-loopback: -----------------------] 199s kpartx-file-loopback PASS 199s autopkgtest [19:22:20]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 200s autopkgtest [19:22:21]: test tgtbasedmpaths: preparing testbed 306s autopkgtest [19:24:07]: testbed dpkg architecture: ppc64el 306s autopkgtest [19:24:07]: testbed apt version: 2.9.8 306s autopkgtest [19:24:07]: @@@@@@@@@@@@@@@@@@@@ test bed setup 307s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 307s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [8820 B] 307s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8376 B] 307s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [679 kB] 307s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.9 kB] 307s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [45.9 kB] 307s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [1064 B] 307s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1372 B] 307s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 307s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [616 kB] 307s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [14.8 kB] 307s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [4656 B] 307s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [340 B] 309s Fetched 1546 kB in 1s (1721 kB/s) 309s Reading package lists... 311s Reading package lists... 312s Building dependency tree... 312s Reading state information... 312s Calculating upgrade... 312s The following packages will be upgraded: 312s kpartx multipath-tools 312s 2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 312s Need to get 390 kB of archives. 312s After this operation, 2048 B of additional disk space will be used. 312s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el kpartx ppc64el 0.9.9-1ubuntu3 [37.6 kB] 312s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el multipath-tools ppc64el 0.9.9-1ubuntu3 [353 kB] 313s Fetched 390 kB in 0s (955 kB/s) 313s (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 ... 72467 files and directories currently installed.) 313s Preparing to unpack .../kpartx_0.9.9-1ubuntu3_ppc64el.deb ... 313s Unpacking kpartx (0.9.9-1ubuntu3) over (0.9.9-1ubuntu2) ... 313s Preparing to unpack .../multipath-tools_0.9.9-1ubuntu3_ppc64el.deb ... 313s Unpacking multipath-tools (0.9.9-1ubuntu3) over (0.9.9-1ubuntu2) ... 313s Setting up kpartx (0.9.9-1ubuntu3) ... 313s Setting up multipath-tools (0.9.9-1ubuntu3) ... 313s Processing triggers for man-db (2.12.1-3) ... 314s Processing triggers for libc-bin (2.40-1ubuntu1) ... 314s Reading package lists... 314s Building dependency tree... 314s Reading state information... 314s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 315s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 315s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 315s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 315s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 316s Reading package lists... 316s Reading package lists... 316s Building dependency tree... 316s Reading state information... 316s Calculating upgrade... 316s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 316s Reading package lists... 317s Building dependency tree... 317s Reading state information... 317s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 317s autopkgtest [19:24:18]: rebooting testbed after setup commands that affected boot 321s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 354s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 367s Reading package lists... 367s Building dependency tree... 367s Reading state information... 368s Starting pkgProblemResolver with broken count: 0 368s Starting 2 pkgProblemResolver with broken count: 0 368s Done 368s The following additional packages will be installed: 368s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 368s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 368s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 368s librdmacm1t64 lsscsi open-iscsi tgt 368s Suggested packages: 368s fio-examples gnuplot tgt-glusterfs tgt-rbd 368s Recommended packages: 368s finalrd 368s The following NEW packages will be installed: 368s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 368s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 368s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 368s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 368s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 368s Need to get 11.0 MB/11.0 MB of archives. 368s After this operation, 50.0 MB of additional disk space will be used. 368s Get:1 /tmp/autopkgtest.emREIN/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 368s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 368s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 368s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 369s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2ubuntu1 [80.6 kB] 369s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 369s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 369s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-5ubuntu1 [21.7 kB] 369s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-5ubuntu1 [308 kB] 369s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-5ubuntu1 [46.3 kB] 369s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-5ubuntu1 [99.1 kB] 369s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-2 [98.5 kB] 369s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2.2ubuntu1 [23.7 kB] 369s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2.2ubuntu1 [73.4 kB] 369s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 369s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3.2ubuntu2 [260 kB] 369s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3.2ubuntu2 [281 kB] 369s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~rc2-0ubuntu1 [4194 kB] 369s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 369s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~rc2-0ubuntu1 [3714 kB] 369s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 369s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 369s Preconfiguring packages ... 369s Fetched 11.0 MB in 1s (11.8 MB/s) 369s Selecting previously unselected package libopeniscsiusr. 369s (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 ... 72467 files and directories currently installed.) 369s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 369s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 369s Selecting previously unselected package libisns0t64:ppc64el. 369s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 369s Unpacking libisns0t64:ppc64el (0.101-1) ... 369s Selecting previously unselected package open-iscsi. 369s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 370s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 370s Selecting previously unselected package librdmacm1t64:ppc64el. 370s Preparing to unpack .../03-librdmacm1t64_52.0-2ubuntu1_ppc64el.deb ... 370s Unpacking librdmacm1t64:ppc64el (52.0-2ubuntu1) ... 370s Selecting previously unselected package libconfig-general-perl. 370s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 370s Unpacking libconfig-general-perl (2.65-2) ... 370s Selecting previously unselected package tgt. 370s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 370s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 370s Selecting previously unselected package libgfxdr0:ppc64el. 370s Preparing to unpack .../06-libgfxdr0_11.1-5ubuntu1_ppc64el.deb ... 370s Unpacking libgfxdr0:ppc64el (11.1-5ubuntu1) ... 370s Selecting previously unselected package libglusterfs0:ppc64el. 370s Preparing to unpack .../07-libglusterfs0_11.1-5ubuntu1_ppc64el.deb ... 370s Unpacking libglusterfs0:ppc64el (11.1-5ubuntu1) ... 370s Selecting previously unselected package libgfrpc0:ppc64el. 370s Preparing to unpack .../08-libgfrpc0_11.1-5ubuntu1_ppc64el.deb ... 370s Unpacking libgfrpc0:ppc64el (11.1-5ubuntu1) ... 370s Selecting previously unselected package libgfapi0:ppc64el. 370s Preparing to unpack .../09-libgfapi0_11.1-5ubuntu1_ppc64el.deb ... 370s Unpacking libgfapi0:ppc64el (11.1-5ubuntu1) ... 370s Selecting previously unselected package libnbd0. 370s Preparing to unpack .../10-libnbd0_1.20.2-2_ppc64el.deb ... 370s Unpacking libnbd0 (1.20.2-2) ... 370s Selecting previously unselected package libdaxctl1:ppc64el. 370s Preparing to unpack .../11-libdaxctl1_77-2.2ubuntu1_ppc64el.deb ... 370s Unpacking libdaxctl1:ppc64el (77-2.2ubuntu1) ... 370s Selecting previously unselected package libndctl6:ppc64el. 370s Preparing to unpack .../12-libndctl6_77-2.2ubuntu1_ppc64el.deb ... 370s Unpacking libndctl6:ppc64el (77-2.2ubuntu1) ... 370s Selecting previously unselected package libpmem1:ppc64el. 370s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 370s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 370s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 370s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 370s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 370s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 370s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 370s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 370s Selecting previously unselected package librados2. 370s Preparing to unpack .../16-librados2_19.2.0~rc2-0ubuntu1_ppc64el.deb ... 370s Unpacking librados2 (19.2.0~rc2-0ubuntu1) ... 370s Selecting previously unselected package libpmemobj1:ppc64el. 370s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 370s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 370s Selecting previously unselected package librbd1. 370s Preparing to unpack .../18-librbd1_19.2.0~rc2-0ubuntu1_ppc64el.deb ... 370s Unpacking librbd1 (19.2.0~rc2-0ubuntu1) ... 370s Selecting previously unselected package fio. 370s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 370s Unpacking fio (3.37-1) ... 370s Selecting previously unselected package lsscsi. 370s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 370s Unpacking lsscsi (0.32-1build1) ... 370s Selecting previously unselected package autopkgtest-satdep. 370s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 370s Unpacking autopkgtest-satdep (0) ... 370s Setting up libconfig-general-perl (2.65-2) ... 370s Setting up libisns0t64:ppc64el (0.101-1) ... 370s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 370s Setting up libnbd0 (1.20.2-2) ... 370s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 370s Setting up libglusterfs0:ppc64el (11.1-5ubuntu1) ... 370s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 370s Setting up lsscsi (0.32-1build1) ... 370s Setting up libdaxctl1:ppc64el (77-2.2ubuntu1) ... 370s Setting up libndctl6:ppc64el (77-2.2ubuntu1) ... 370s Setting up librdmacm1t64:ppc64el (52.0-2ubuntu1) ... 370s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 371s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 371s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 371s Setting up libgfxdr0:ppc64el (11.1-5ubuntu1) ... 371s Setting up librados2 (19.2.0~rc2-0ubuntu1) ... 371s Setting up open-iscsi (2.1.10-1ubuntu1) ... 372s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 372s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 372s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 372s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 372s Setting up librbd1 (19.2.0~rc2-0ubuntu1) ... 372s Setting up libgfrpc0:ppc64el (11.1-5ubuntu1) ... 372s Setting up libgfapi0:ppc64el (11.1-5ubuntu1) ... 372s Setting up fio (3.37-1) ... 373s Setting up autopkgtest-satdep (0) ... 373s Processing triggers for man-db (2.12.1-3) ... 374s Processing triggers for initramfs-tools (0.142ubuntu33) ... 374s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 374s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 382s Processing triggers for libc-bin (2.40-1ubuntu1) ... 384s (Reading database ... 72708 files and directories currently installed.) 384s Removing autopkgtest-satdep (0) ... 386s autopkgtest [19:25:27]: test tgtbasedmpaths: [----------------------- 386s + targetname=iqn.2016-11.foo.com:target.iscsi 386s + pwd 386s + cwd=/tmp/autopkgtest.emREIN/build.Bmn/src 386s + testdir=/mnt/tgtmpathtest 386s + localhost=127.0.0.1 386s + portal=127.0.0.1:3260 386s + maxpaths=4 386s + backfn=backingfile 386s + expectwwid=60000000000000000e00000000010001 386s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 386s + bglog=/tmp/autopkgtest.emREIN/tgtbasedmpaths-artifacts/test-background.log 386s + fioprep=/tmp/autopkgtest.emREIN/tgtbasedmpaths-artifacts/path-change-prep.fio 386s + fiovrfy=/tmp/autopkgtest.emREIN/tgtbasedmpaths-artifacts/path-change-check.fio 386s + mkdir -p /etc/multipath 386s + echo /360000000000000000e00000000010001/ 386s + service tgt restart 387s + truncate --size 100M backingfile 387s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 387s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 387s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.emREIN/build.Bmn/src/backingfile 387s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 387s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 387s login #1 387s + echo login #1 387s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 387s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 387s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 387s + seq 2 4 387s extra login #2 387s + echo extra login #2 387s + iscsiadm --mode session -r 1 --op new 387s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 387s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 387s extra login #3 387s + echo extra login #3 387s + iscsiadm --mode session -r 1 --op new 387s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 387s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 387s extra login #4 387s + echo extra login #4 387s + iscsiadm --mode session -r 1 --op new 387s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 387s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 387s + udevadm settle 387s + sleep 5 392s Status after initial setup 392s + echo Status after initial setup 392s + tgtadm --lld iscsi --mode target --op show 392s Target 1: iqn.2016-11.foo.com:target.iscsi 392s System information: 392s Driver: iscsi 392s State: ready 392s I_T nexus information: 392s I_T nexus: 1 392s Initiator: iqn.2004-10.com.ubuntu:01:e442d5d9759 alias: autopkgtest 392s Connection: 0 392s IP Address: 127.0.0.1 392s I_T nexus: 2 392s Initiator: iqn.2004-10.com.ubuntu:01:e442d5d9759 alias: autopkgtest 392s Connection: 0 392s IP Address: 127.0.0.1 392s I_T nexus: 3 392s Initiator: iqn.2004-10.com.ubuntu:01:e442d5d9759 alias: autopkgtest 392s Connection: 0 392s IP Address: 127.0.0.1 392s I_T nexus: 4 392s Initiator: iqn.2004-10.com.ubuntu:01:e442d5d9759 alias: autopkgtest 392s Connection: 0 392s IP Address: 127.0.0.1 392s LUN information: 392s LUN: 0 392s Type: controller 392s SCSI ID: IET 00010000 392s SCSI SN: beaf10 392s Size: 0 MB, Block size: 1 392s Online: Yes 392s Removable media: No 392s Prevent removal: No 392s Readonly: No 392s SWP: No 392s Thin-provisioning: No 392s Backing store type: null 392s Backing store path: None 392s Backing store flags: 392s LUN: 1 392s Type: disk 392s SCSI ID: IET 00010001 392s SCSI SN: beaf11 392s Size: 105 MB, Block size: 512 392s Online: Yes 392s Removable media: No 392s Prevent removal: No 392s Readonly: No 392s SWP: No 392s Thin-provisioning: No 392s Backing store type: rdwr 392s Backing store path: /tmp/autopkgtest.emREIN/build.Bmn/src/backingfile 392s Backing store flags: 392s Account information: 392s ACL information: 392s ALL 392s Session: 4 392s Connection: 0 392s Initiator: iqn.2004-10.com.ubuntu:01:e442d5d9759 392s IP Address: 127.0.0.1 392s Session: 3 392s Connection: 0 392s Initiator: iqn.2004-10.com.ubuntu:01:e442d5d9759 392s IP Address: 127.0.0.1 392s Session: 2 392s Connection: 0 392s Initiator: iqn.2004-10.com.ubuntu:01:e442d5d9759 392s IP Address: 127.0.0.1 392s Session: 1 392s Connection: 0 392s Initiator: iqn.2004-10.com.ubuntu:01:e442d5d9759 392s IP Address: 127.0.0.1 392s + tgtadm --lld iscsi --op show --mode conn --tid 1 392s + iscsiadm --mode session -P 1 392s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 392s Current Portal: 127.0.0.1:3260,1 392s Persistent Portal: 127.0.0.1:3260,1 392s ********** 392s Interface: 392s ********** 392s Iface Name: default 392s Iface Transport: tcp 392s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:e442d5d9759 392s Iface IPaddress: 127.0.0.1 392s Iface HWaddress: default 392s Iface Netdev: default 392s SID: 1 392s iSCSI Connection State: LOGGED IN 392s iSCSI Session State: LOGGED_IN 392s Internal iscsid Session State: NO CHANGE 392s 392s ********** 392s Interface: 392s ********** 392s Iface Name: default 392s Iface Transport: tcp 392s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:e442d5d9759 392s Iface IPaddress: 127.0.0.1 392s Iface HWaddress: default 392s Iface Netdev: default 392s SID: 2 392s iSCSI Connection State: LOGGED IN 392s iSCSI Session State: LOGGED_IN 392s Internal iscsid Session State: NO CHANGE 392s 392s ********** 392s Interface: 392s ********** 392s Iface Name: default 392s Iface Transport: tcp 392s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:e442d5d9759 392s Iface IPaddress: 127.0.0.1 392s Iface HWaddress: default 392s Iface Netdev: default 392s SID: 3 392s iSCSI Connection State: LOGGED IN 392s iSCSI Session State: LOGGED_IN 392s Internal iscsid Session State: NO CHANGE 392s 392s ********** 392s Interface: 392s ********** 392s Iface Name: default 392s Iface Transport: tcp 392s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:e442d5d9759 392s Iface IPaddress: 127.0.0.1 392s Iface HWaddress: default 392s Iface Netdev: default 392s SID: 4 392s iSCSI Connection State: LOGGED IN 392s iSCSI Session State: LOGGED_IN 392s Internal iscsid Session State: NO CHANGE 392s + lsscsi -liv 392s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 392s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 392s 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] 392s [1:0:0:0] storage IET Controller 0001 - - 392s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 392s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 392s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 392s [2:0:0:0] storage IET Controller 0001 - - 392s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 392s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 392s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 392s [3:0:0:0] storage IET Controller 0001 - - 392s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 392s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 392s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 392s [4:0:0:0] storage IET Controller 0001 - - 392s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 392s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 33000000100000001 392s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 392s NVMe module may not be loaded 392s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 392s + multipath -v3 -ll 392s 51.135886 | set open fds limit to 1073741816/1073741816 392s 51.135926 | _read_bindings_file: reading /etc/multipath/bindings 392s 51.135955 | loading /usr/lib/multipath/libchecktur.so checker 392s 51.136077 | checker tur: message table size = 4 392s 51.136111 | loading /usr/lib/multipath/libprioconst.so prioritizer 392s 51.136239 | _init_foreign: foreign library "nvme" is not enabled 392s 51.142032 | sda: size = 167772160 392s 51.142208 | sda: vendor = QEMU 392s 51.142251 | sda: product = QEMU HARDDISK 392s 51.142275 | sda: rev = 2.5+ 392s 51.142857 | sda: h:b:t:l = 0:0:0:0 392s 51.143190 | sda: tgt_node_name = 392s 51.143211 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 392s 51.143214 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 392s 51.143364 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 392s 51.143385 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 51.143399 | __sysfs_attr_get_value: attribute '/sys/devices/pci0000:00/0000:00:02.0/virtio1/host0/target0:0:0/0:0:0:0/vpd_pg80' cannot be opened: No such file or directory 392s 51.143404 | failed to read sysfs vpd pg80: No such file or directory 392s 51.143583 | sda: fail to get serial 392s 51.143604 | sda: detect_checker = yes (setting: multipath internal) 392s 51.143636 | sda checker timeout = 30 s (setting: kernel sysfs) 392s 51.143730 | sda: path_checker = tur (setting: multipath internal) 392s 51.143821 | sda: tur state = up 392s 51.144137 | sdb: size = 204800 392s 51.144297 | sdb: vendor = IET 392s 51.144338 | sdb: product = VIRTUAL-DISK 392s 51.144361 | sdb: rev = 0001 392s 51.144953 | sdb: h:b:t:l = 1:0:0:1 392s 51.145351 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 51.145372 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 392s 51.145375 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 392s 51.145528 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 51.145549 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 51.145565 | sdb: serial = beaf11 392s 51.145568 | sdb: detect_checker = yes (setting: multipath internal) 392s 51.145596 | sdb checker timeout = 30 s (setting: kernel sysfs) 392s 51.145861 | sdb: path_checker = tur (setting: multipath internal) 392s 51.146071 | sdb: tur state = up 392s 51.146219 | sdc: size = 204800 392s 51.146375 | sdc: vendor = IET 392s 51.146416 | sdc: product = VIRTUAL-DISK 392s 51.146439 | sdc: rev = 0001 392s 51.147088 | sdc: h:b:t:l = 2:0:0:1 392s 51.147474 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 51.147495 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 392s 51.147498 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 392s 51.147646 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 51.147666 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 51.147682 | sdc: serial = beaf11 392s 51.147684 | sdc: detect_checker = yes (setting: multipath internal) 392s 51.147712 | sdc checker timeout = 30 s (setting: kernel sysfs) 392s 51.147874 | sdc: path_checker = tur (setting: multipath internal) 392s 51.148025 | sdc: tur state = up 392s 51.148163 | sdd: size = 204800 392s 51.148319 | sdd: vendor = IET 392s 51.148360 | sdd: product = VIRTUAL-DISK 392s 51.148383 | sdd: rev = 0001 392s 51.149048 | sdd: h:b:t:l = 3:0:0:1 392s 51.149426 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 51.149447 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 392s 51.149449 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 392s 51.149595 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 51.149616 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 51.149631 | sdd: serial = beaf11 392s 51.149633 | sdd: detect_checker = yes (setting: multipath internal) 392s 51.149668 | sdd checker timeout = 30 s (setting: kernel sysfs) 392s 51.149850 | sdd: path_checker = tur (setting: multipath internal) 392s 51.150075 | sdd: tur state = up 392s 51.150223 | sde: size = 204800 392s 51.150379 | sde: vendor = IET 392s 51.150420 | sde: product = VIRTUAL-DISK 392s 51.150443 | sde: rev = 0001 392s 51.151091 | sde: h:b:t:l = 4:0:0:1 392s 51.151469 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 51.151490 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 392s 51.151493 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 392s 51.151638 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 51.151658 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 51.151674 | sde: serial = beaf11 392s 51.151676 | sde: detect_checker = yes (setting: multipath internal) 392s 51.151704 | sde checker timeout = 30 s (setting: kernel sysfs) 392s 51.151858 | sde: path_checker = tur (setting: multipath internal) 392s 51.151993 | sde: tur state = up 392s 51.152099 | loop0: device node name blacklisted 392s 51.152235 | loop1: device node name blacklisted 392s 51.152342 | loop2: device node name blacklisted 392s 51.152448 | loop3: device node name blacklisted 392s 51.152553 | loop4: device node name blacklisted 392s 51.152657 | loop5: device node name blacklisted 392s 51.152761 | loop6: device node name blacklisted 392s 51.152866 | loop7: device node name blacklisted 392s 51.153005 | dm-0: device node name blacklisted 392s 51.154185 | multipath-tools v0.9.9 (05/03, 2024) 392s 51.154213 | libdevmapper version 1.02.196 392s 51.154342 | kernel device mapper v4.48.0 392s 51.154371 | DM multipath kernel driver v1.14.0 392s 51.154479 | sdb: size = 204800 392s 51.154501 | sdb: vendor = IET 392s 51.154504 | sdb: product = VIRTUAL-DISK 392s 51.154507 | sdb: rev = 0001 392s 51.155098 | sdb: h:b:t:l = 1:0:0:1 392s 51.155232 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 51.155270 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 51.155273 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 51.155286 | sdb: serial = beaf11 392s 51.155457 | sdb: tur state = up 392s 51.155479 | sdb: uid = 360000000000000000e00000000010001 (udev) 392s 51.155482 | sdb: detect_prio = yes (setting: multipath internal) 392s 51.155486 | sdb: prio = const (setting: multipath internal) 392s 51.155488 | sdb: prio args = "" (setting: multipath internal) 392s 51.155490 | sdb: const prio = 1 392s 51.155514 | sdc: size = 204800 392s 51.155518 | sdc: vendor = IET 392s 51.155521 | sdc: product = VIRTUAL-DISK 392s 51.155523 | sdc: rev = 0001 392s 51.156137 | sdc: h:b:t:l = 2:0:0:1 392s 51.156276 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 51.156315 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 51.156318 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 51.156330 | sdc: serial = beaf11 392s 51.156516 | sdc: tur state = up 392s 51.156537 | sdc: uid = 360000000000000000e00000000010001 (udev) 392s 51.156539 | sdc: detect_prio = yes (setting: multipath internal) 392s 51.156542 | sdc: prio = const (setting: multipath internal) 392s 51.156544 | sdc: prio args = "" (setting: multipath internal) 392s 51.156546 | sdc: const prio = 1 392s 51.156569 | sdd: size = 204800 392s 51.156574 | sdd: vendor = IET 392s 51.156576 | sdd: product = VIRTUAL-DISK 392s 51.156580 | sdd: rev = 0001 392s 51.157190 | sdd: h:b:t:l = 3:0:0:1 392s 51.157326 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 51.157364 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 51.157367 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 51.157379 | sdd: serial = beaf11 392s 51.157545 | sdd: tur state = up 392s 51.157567 | sdd: uid = 360000000000000000e00000000010001 (udev) 392s 51.157569 | sdd: detect_prio = yes (setting: multipath internal) 392s 51.157572 | sdd: prio = const (setting: multipath internal) 392s 51.157574 | sdd: prio args = "" (setting: multipath internal) 392s 51.157576 | sdd: const prio = 1 392s 51.157600 | sde: size = 204800 392s 51.157604 | sde: vendor = IET 392s 51.157607 | sde: product = VIRTUAL-DISK 392s 51.157609 | sde: rev = 0001 392s 51.158189 | sde: h:b:t:l = 4:0:0:1 392s 51.158325 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 51.159557 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 51.159621 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 51.159648 | sde: serial = beaf11 392s 51.159928 | sde: tur state = up 392s 51.159958 | sde: uid = 360000000000000000e00000000010001 (udev) 392s 51.159961 | sde: detect_prio = yes (setting: multipath internal) 392s 51.159965 | sde: prio = const (setting: multipath internal) 392s 51.159967 | sde: prio args = "" (setting: multipath internal) 392s 51.159970 | sde: const prio = 1 392s 51.161305 | unloading tur checker 392s 51.161434 | unloading const prioritizer 392s ===== paths list ===== 392s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 392s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK,2.5+ unknown 392s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 392s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 392s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 392s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 392s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 392s size=100M features='0' hwhandler='0' wp=rw 392s |-+- policy='service-time 0' prio=1 status=active 392s | `- 1:0:0:1 sdb 8:16 active ready running 392s |-+- policy='service-time 0' prio=1 status=enabled 392s | `- 2:0:0:1 sdc 8:32 active ready running 392s |-+- policy='service-time 0' prio=1 status=enabled 392s | `- 3:0:0:1 sdd 8:48 active ready running 392s `-+- policy='service-time 0' prio=1 status=enabled 392s `- 4:0:0:1 sde 8:64 active ready running 392s 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 392s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 392s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 392s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 392s /etc/multipath/bindings:# 392s /etc/multipath/bindings:# Format: 392s /etc/multipath/bindings:# alias wwid 392s /etc/multipath/bindings:# 392s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 392s /etc/multipath/wwids:/360000000000000000e00000000010001/ 392s ● multipathd.service - Device-Mapper Multipath Device Controller 392s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 392s Active: active (running) since Thu 2024-09-05 19:24:45 UTC; 47s ago 392s Invocation: 8dc06ae8359648f898e82a33d33340c2 392s TriggeredBy: ● multipathd.socket 392s Main PID: 341 (multipathd) 392s Status: "up" 392s Tasks: 7 392s Memory: 27.8M (peak: 38M) 392s CPU: 56ms 392s CGroup: /system.slice/multipathd.service 392s └─341 /sbin/multipathd -d -s 392s 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 392s Sep 05 19:24:45 autopkgtest multipathd[341]: multipathd v0.9.9: start up 392s Sep 05 19:24:45 autopkgtest multipathd[341]: reconfigure: setting up paths and maps 392s Sep 05 19:24:45 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 392s Sep 05 19:25:28 autopkgtest multipathd[341]: updated bindings file /etc/multipath/bindings 392s Sep 05 19:25:28 autopkgtest multipathd[341]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:16 1] 392s Sep 05 19:25:28 autopkgtest multipathd[341]: sdb [8:16]: path added to devmap mpatha 392s Sep 05 19:25:28 autopkgtest multipathd[341]: mpatha: performing delayed actions 392s Sep 05 19:25:28 autopkgtest multipathd[341]: 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] 392s ● multipathd.socket - multipathd control socket 392s Loaded: loaded (/usr/lib/systemd/system/multipathd.socket; enabled; preset: enabled) 392s Active: active (running) since Thu 2024-09-05 19:24:45 UTC; 48s ago 392s Invocation: 4e25134a187e4969b1b8c984ad71c2f4 392s Triggers: ● multipathd.service 392s Listen: @/org/kernel/linux/storage/multipathd (Stream) 392s CGroup: /system.slice/multipathd.socket 392s 392s Notice: journal has been rotated since unit was started, output may be incomplete. 392s total 0 392s drwxr-xr-x 2 root root 80 Sep 5 19:25 . 392s drwxr-xr-x 18 root root 4260 Sep 5 19:25 .. 392s crw------- 1 root root 10, 236 Sep 5 19:24 control 392s lrwxrwxrwx 1 root root 7 Sep 5 19:25 mpatha -> ../dm-0 392s journal 392s + dmsetup table 392s + grep . /etc/multipath/bindings /etc/multipath/wwids 392s + systemctl status multipathd.service 392s + ret_code=0 392s + systemctl status multipathd.socket 392s + [ 0 -eq 0 ] 392s + ls -la /dev/mapper/ 392s + echo journal 392s + journalctl -b 392s Sep 05 19:24:45 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 392s Sep 05 19:24:45 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 392s Sep 05 19:24:45 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 392s Sep 05 19:24:45 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 392s Sep 05 19:24:45 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 392s Sep 05 19:24:45 autopkgtest kernel: Activating Kernel Userspace Access Prevention 392s Sep 05 19:24:45 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 392s Sep 05 19:24:45 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x00000000038a0000 with 64.0 KiB pages (exec) 392s Sep 05 19:24:45 autopkgtest kernel: radix-mmu: Mapped 0x00000000038a0000-0x0000000200000000 with 64.0 KiB pages 392s Sep 05 19:24:45 autopkgtest kernel: lpar: Using radix MMU under hypervisor 392s Sep 05 19:24:45 autopkgtest kernel: Linux version 6.8.0-31-generic (buildd@bos02-ppc64el-018) (powerpc64le-linux-gnu-gcc-13 (Ubuntu 13.2.0-23ubuntu4) 13.2.0, GNU ld (GNU Binutils for Ubuntu) 2.42) #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 (Ubuntu 6.8.0-31.31-generic 6.8.1) 392s Sep 05 19:24:45 autopkgtest kernel: Secure boot mode disabled 392s Sep 05 19:24:45 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc0000000093ce0a8 392s Sep 05 19:24:45 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (raw) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 392s Sep 05 19:24:45 autopkgtest kernel: printk: legacy bootconsole [udbg0] enabled 392s Sep 05 19:24:45 autopkgtest kernel: Partition configured for 4 cpus. 392s Sep 05 19:24:45 autopkgtest kernel: CPU maps initialized for 1 thread per core 392s Sep 05 19:24:45 autopkgtest kernel: (thread shift is 0) 392s Sep 05 19:24:45 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 392s Sep 05 19:24:45 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 392s Sep 05 19:24:45 autopkgtest kernel: ----------------------------------------------------- 392s Sep 05 19:24:45 autopkgtest kernel: phys_mem_size = 0x200000000 392s Sep 05 19:24:45 autopkgtest kernel: dcache_bsize = 0x80 392s Sep 05 19:24:45 autopkgtest kernel: icache_bsize = 0x80 392s Sep 05 19:24:45 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 392s Sep 05 19:24:45 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 392s Sep 05 19:24:45 autopkgtest kernel: always = 0x0000000380008181 392s Sep 05 19:24:45 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 392s Sep 05 19:24:45 autopkgtest kernel: mmu_features = 0x3c007641 392s Sep 05 19:24:45 autopkgtest kernel: firmware_features = 0x00000085455a445f 392s Sep 05 19:24:45 autopkgtest kernel: vmalloc start = 0xc008000000000000 392s Sep 05 19:24:45 autopkgtest kernel: IO start = 0xc00a000000000000 392s Sep 05 19:24:45 autopkgtest kernel: vmemmap start = 0xc00c000000000000 392s Sep 05 19:24:45 autopkgtest kernel: ----------------------------------------------------- 392s Sep 05 19:24:45 autopkgtest kernel: numa: NODE_DATA [mem 0x1eff10280-0x1eff17fff] 392s Sep 05 19:24:45 autopkgtest kernel: rfi-flush: fallback displacement flush available 392s Sep 05 19:24:45 autopkgtest kernel: rfi-flush: ori type flush available 392s Sep 05 19:24:45 autopkgtest kernel: rfi-flush: mttrig type flush available 392s Sep 05 19:24:45 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 392s Sep 05 19:24:45 autopkgtest kernel: count-cache-flush: software flush enabled. 392s Sep 05 19:24:45 autopkgtest kernel: link-stack-flush: software flush enabled. 392s Sep 05 19:24:45 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 392s Sep 05 19:24:45 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 392s Sep 05 19:24:45 autopkgtest kernel: stf-barrier: eieio barrier available 392s Sep 05 19:24:45 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 392s Sep 05 19:24:45 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 392s Sep 05 19:24:45 autopkgtest kernel: PPC64 nvram contains 65536 bytes 392s Sep 05 19:24:45 autopkgtest kernel: barrier-nospec: using ORI speculation barrier 392s Sep 05 19:24:45 autopkgtest kernel: barrier-nospec: patched 269 locations 392s Sep 05 19:24:45 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 392s Sep 05 19:24:45 autopkgtest kernel: Memory hole size: 0MB 392s Sep 05 19:24:45 autopkgtest kernel: Zone ranges: 392s Sep 05 19:24:45 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 392s Sep 05 19:24:45 autopkgtest kernel: Device empty 392s Sep 05 19:24:45 autopkgtest kernel: Movable zone start for each node 392s Sep 05 19:24:45 autopkgtest kernel: Early memory node ranges 392s Sep 05 19:24:45 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 392s Sep 05 19:24:45 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 392s Sep 05 19:24:45 autopkgtest kernel: percpu: Embedded 12 pages/cpu s609960 r0 d176472 u786432 392s Sep 05 19:24:45 autopkgtest kernel: pcpu-alloc: s609960 r0 d176472 u786432 alloc=12*65536 392s Sep 05 19:24:45 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 392s Sep 05 19:24:45 autopkgtest kernel: Kernel command line: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic root=UUID=f999abd5-af41-40ac-8675-cf1e7d4878fb ro console=hvc0 earlyprintk 392s Sep 05 19:24:45 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic", will be passed to user space. 392s Sep 05 19:24:45 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 392s Sep 05 19:24:45 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 392s Sep 05 19:24:45 autopkgtest kernel: Fallback order for Node 0: 0 392s Sep 05 19:24:45 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 130944 392s Sep 05 19:24:45 autopkgtest kernel: Policy zone: Normal 392s Sep 05 19:24:45 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 392s Sep 05 19:24:45 autopkgtest kernel: Memory: 7969280K/8388608K available (23680K kernel code, 4096K rwdata, 25472K rodata, 8832K init, 1901K bss, 419328K reserved, 0K cma-reserved) 392s Sep 05 19:24:45 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 392s Sep 05 19:24:45 autopkgtest kernel: ftrace: allocating 51717 entries in 19 pages 392s Sep 05 19:24:45 autopkgtest kernel: ftrace: allocated 19 pages with 3 groups 392s Sep 05 19:24:45 autopkgtest kernel: trace event string verifier disabled 392s Sep 05 19:24:45 autopkgtest kernel: rcu: Hierarchical RCU implementation. 392s Sep 05 19:24:45 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 392s Sep 05 19:24:45 autopkgtest kernel: Rude variant of Tasks RCU enabled. 392s Sep 05 19:24:45 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 392s Sep 05 19:24:45 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 392s Sep 05 19:24:45 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 392s Sep 05 19:24:45 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 392s Sep 05 19:24:45 autopkgtest kernel: xive: Using IRQ range [0-3] 392s Sep 05 19:24:45 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 392s Sep 05 19:24:45 autopkgtest kernel: xive: Using priority 6 for all interrupts 392s Sep 05 19:24:45 autopkgtest kernel: xive: Using 64kB queues 392s Sep 05 19:24:45 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 392s Sep 05 19:24:45 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 392s Sep 05 19:24:45 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 392s Sep 05 19:24:45 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 392s Sep 05 19:24:45 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 392s Sep 05 19:24:45 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 392s Sep 05 19:24:45 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 392s Sep 05 19:24:45 autopkgtest kernel: Console: colour dummy device 80x25 392s Sep 05 19:24:45 autopkgtest kernel: printk: legacy console [hvc0] enabled 392s Sep 05 19:24:45 autopkgtest kernel: printk: legacy bootconsole [udbg0] disabled 392s Sep 05 19:24:45 autopkgtest kernel: pid_max: default: 32768 minimum: 301 392s Sep 05 19:24:45 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,integrity 392s Sep 05 19:24:45 autopkgtest kernel: landlock: Up and running. 392s Sep 05 19:24:45 autopkgtest kernel: Yama: becoming mindful. 392s Sep 05 19:24:45 autopkgtest kernel: AppArmor: AppArmor initialized 392s Sep 05 19:24:45 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 392s Sep 05 19:24:45 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 392s Sep 05 19:24:45 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 392s Sep 05 19:24:45 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 392s Sep 05 19:24:45 autopkgtest kernel: POWER9 performance monitor hardware support registered 392s Sep 05 19:24:45 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 392s Sep 05 19:24:45 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 392s Sep 05 19:24:45 autopkgtest kernel: smp: Bringing up secondary CPUs ... 392s Sep 05 19:24:45 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 392s Sep 05 19:24:45 autopkgtest kernel: numa: Node 0 CPUs: 0-3 392s Sep 05 19:24:45 autopkgtest kernel: devtmpfs: initialized 392s Sep 05 19:24:45 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 392s Sep 05 19:24:45 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 392s Sep 05 19:24:45 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 392s Sep 05 19:24:45 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 392s Sep 05 19:24:45 autopkgtest kernel: PCI: OF: PROBE_ONLY disabled 392s Sep 05 19:24:45 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 392s Sep 05 19:24:45 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 392s Sep 05 19:24:45 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 392s Sep 05 19:24:45 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 392s Sep 05 19:24:45 autopkgtest kernel: audit: initializing netlink subsys (disabled) 392s Sep 05 19:24:45 autopkgtest kernel: audit: type=2000 audit(1725564282.040:1): state=initialized audit_enabled=0 res=1 392s Sep 05 19:24:45 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 392s Sep 05 19:24:45 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 392s Sep 05 19:24:45 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 392s Sep 05 19:24:45 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 392s Sep 05 19:24:45 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 392s Sep 05 19:24:45 autopkgtest kernel: cpuidle: using governor ladder 392s Sep 05 19:24:45 autopkgtest kernel: cpuidle: using governor menu 392s Sep 05 19:24:45 autopkgtest kernel: RTAS daemon started 392s Sep 05 19:24:45 autopkgtest kernel: pstore: Using crash dump compression: deflate 392s Sep 05 19:24:45 autopkgtest kernel: pstore: Registered nvram as persistent store backend 392s Sep 05 19:24:45 autopkgtest kernel: EEH: pSeries platform initialized 392s Sep 05 19:24:45 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 392s Sep 05 19:24:45 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 392s Sep 05 19:24:45 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 392s Sep 05 19:24:45 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 392s Sep 05 19:24:45 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 392s Sep 05 19:24:45 autopkgtest kernel: iommu: Default domain type: Translated 392s Sep 05 19:24:45 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 392s Sep 05 19:24:45 autopkgtest kernel: SCSI subsystem initialized 392s Sep 05 19:24:45 autopkgtest kernel: libata version 3.00 loaded. 392s Sep 05 19:24:45 autopkgtest kernel: usbcore: registered new interface driver usbfs 392s Sep 05 19:24:45 autopkgtest kernel: usbcore: registered new interface driver hub 392s Sep 05 19:24:45 autopkgtest kernel: usbcore: registered new device driver usb 392s Sep 05 19:24:45 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 392s Sep 05 19:24:45 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 392s Sep 05 19:24:45 autopkgtest kernel: PTP clock support registered 392s Sep 05 19:24:45 autopkgtest kernel: EDAC MC: Ver: 3.0.0 392s Sep 05 19:24:45 autopkgtest kernel: NetLabel: Initializing 392s Sep 05 19:24:45 autopkgtest kernel: NetLabel: domain hash size = 128 392s Sep 05 19:24:45 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 392s Sep 05 19:24:45 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 392s Sep 05 19:24:45 autopkgtest kernel: mctp: management component transport protocol core 392s Sep 05 19:24:45 autopkgtest kernel: NET: Registered PF_MCTP protocol family 392s Sep 05 19:24:45 autopkgtest kernel: PCI: Probing PCI hardware 392s Sep 05 19:24:45 autopkgtest kernel: PCI host bridge to bus 0000:00 392s Sep 05 19:24:45 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 392s Sep 05 19:24:45 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 392s Sep 05 19:24:45 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 392s Sep 05 19:24:45 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 392s Sep 05 19:24:45 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 392s Sep 05 19:24:45 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 392s Sep 05 19:24:45 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 392s Sep 05 19:24:45 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 392s Sep 05 19:24:45 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 392s Sep 05 19:24:45 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 392s Sep 05 19:24:45 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 392s Sep 05 19:24:45 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 392s Sep 05 19:24:45 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 392s Sep 05 19:24:45 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 392s Sep 05 19:24:45 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 392s Sep 05 19:24:45 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 392s Sep 05 19:24:45 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 392s Sep 05 19:24:45 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 392s Sep 05 19:24:45 autopkgtest kernel: PCI: Probing PCI hardware done 392s Sep 05 19:24:45 autopkgtest kernel: vgaarb: loaded 392s Sep 05 19:24:45 autopkgtest kernel: clocksource: Switched to clocksource timebase 392s Sep 05 19:24:45 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 392s Sep 05 19:24:45 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 392s Sep 05 19:24:45 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 392s Sep 05 19:24:45 autopkgtest kernel: NET: Registered PF_INET protocol family 392s Sep 05 19:24:45 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 392s Sep 05 19:24:45 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 392s Sep 05 19:24:45 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 392s Sep 05 19:24:45 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 392s Sep 05 19:24:45 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 392s Sep 05 19:24:45 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 392s Sep 05 19:24:45 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 392s Sep 05 19:24:45 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 392s Sep 05 19:24:45 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 392s Sep 05 19:24:45 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 392s Sep 05 19:24:45 autopkgtest kernel: NET: Registered PF_XDP protocol family 392s Sep 05 19:24:45 autopkgtest kernel: PCI: CLS 0 bytes, default 128 392s Sep 05 19:24:45 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 392s Sep 05 19:24:45 autopkgtest kernel: Initialise system trusted keyrings 392s Sep 05 19:24:45 autopkgtest kernel: Key type blacklist registered 392s Sep 05 19:24:45 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 392s Sep 05 19:24:45 autopkgtest kernel: zbud: loaded 392s Sep 05 19:24:45 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 392s Sep 05 19:24:45 autopkgtest kernel: fuse: init (API version 7.39) 392s Sep 05 19:24:45 autopkgtest kernel: integrity: Platform Keyring initialized 392s Sep 05 19:24:45 autopkgtest kernel: integrity: Machine keyring initialized 392s Sep 05 19:24:45 autopkgtest kernel: Key type asymmetric registered 392s Sep 05 19:24:45 autopkgtest kernel: Asymmetric key parser 'x509' registered 392s Sep 05 19:24:45 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 392s Sep 05 19:24:45 autopkgtest kernel: io scheduler mq-deadline registered 392s Sep 05 19:24:45 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 392s Sep 05 19:24:45 autopkgtest kernel: virtio-pci 0000:00:01.0: ibm,query-pe-dma-windows(2026) 800 8000000 20000000 returned 0, lb=80000000 ps=7 wn=1 392s Sep 05 19:24:45 autopkgtest kernel: virtio-pci 0000:00:01.0: ibm,create-pe-dma-window(2027) 800 8000000 20000000 18 21 returned 0 (liobn = 0x80000001 starting addr = 8000000 0) 392s Sep 05 19:24:45 autopkgtest kernel: virtio-pci 0000:00:02.0: enabling device (0100 -> 0103) 392s Sep 05 19:24:45 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 392s Sep 05 19:24:45 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 392s Sep 05 19:24:45 autopkgtest kernel: Non-volatile memory driver v1.3 392s Sep 05 19:24:45 autopkgtest kernel: Linux agpgart interface v0.103 392s Sep 05 19:24:45 autopkgtest kernel: loop: module loaded 392s Sep 05 19:24:45 autopkgtest kernel: virtio_scsi virtio1: 1/0/0 default/read/poll queues 392s Sep 05 19:24:45 autopkgtest kernel: scsi host0: Virtio SCSI HBA 392s Sep 05 19:24:45 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 392s Sep 05 19:24:45 autopkgtest kernel: scsi 0:0:0:0: Direct-Access QEMU QEMU HARDDISK 2.5+ PQ: 0 ANSI: 5 392s Sep 05 19:24:45 autopkgtest kernel: PPP generic driver version 2.4.2 392s Sep 05 19:24:45 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 392s Sep 05 19:24:45 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 392s Sep 05 19:24:45 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-09-05T19:24:42 UTC (1725564282) 392s Sep 05 19:24:45 autopkgtest kernel: i2c_dev: i2c /dev entries driver 392s Sep 05 19:24:45 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 392s Sep 05 19:24:45 autopkgtest kernel: device-mapper: uevent: version 1.0.3 392s Sep 05 19:24:45 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@redhat.com 392s Sep 05 19:24:45 autopkgtest kernel: pseries_idle_driver registered 392s Sep 05 19:24:45 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 392s Sep 05 19:24:45 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 392s Sep 05 19:24:45 autopkgtest kernel: NET: Registered PF_INET6 protocol family 392s Sep 05 19:24:45 autopkgtest kernel: scsi 0:0:0:0: Attached scsi generic sg0 type 0 392s Sep 05 19:24:45 autopkgtest kernel: sd 0:0:0:0: Power-on or device reset occurred 392s Sep 05 19:24:45 autopkgtest kernel: sd 0:0:0:0: [sda] 167772160 512-byte logical blocks: (85.9 GB/80.0 GiB) 392s Sep 05 19:24:45 autopkgtest kernel: sd 0:0:0:0: [sda] Write Protect is off 392s Sep 05 19:24:45 autopkgtest kernel: sd 0:0:0:0: [sda] Mode Sense: 63 00 00 08 392s Sep 05 19:24:45 autopkgtest kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 392s Sep 05 19:24:45 autopkgtest kernel: sda: sda1 sda2 392s Sep 05 19:24:45 autopkgtest kernel: sd 0:0:0:0: [sda] Attached SCSI disk 392s Sep 05 19:24:45 autopkgtest kernel: Freeing initrd memory: 50944K 392s Sep 05 19:24:45 autopkgtest kernel: Segment Routing with IPv6 392s Sep 05 19:24:45 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 392s Sep 05 19:24:45 autopkgtest kernel: NET: Registered PF_PACKET protocol family 392s Sep 05 19:24:45 autopkgtest kernel: Key type dns_resolver registered 392s Sep 05 19:24:45 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 392s Sep 05 19:24:45 autopkgtest kernel: drmem: No dynamic reconfiguration memory found 392s Sep 05 19:24:45 autopkgtest kernel: registered taskstats version 1 392s Sep 05 19:24:45 autopkgtest kernel: Loading compiled-in X.509 certificates 392s Sep 05 19:24:45 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 392s Sep 05 19:24:45 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 392s Sep 05 19:24:45 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 392s Sep 05 19:24:45 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 392s Sep 05 19:24:45 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 392s Sep 05 19:24:45 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 392s Sep 05 19:24:45 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 392s Sep 05 19:24:45 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 392s Sep 05 19:24:45 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 392s Sep 05 19:24:45 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 392s Sep 05 19:24:45 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 392s Sep 05 19:24:45 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 392s Sep 05 19:24:45 autopkgtest kernel: Key type .fscrypt registered 392s Sep 05 19:24:45 autopkgtest kernel: Key type fscrypt-provisioning registered 392s Sep 05 19:24:45 autopkgtest kernel: Key type encrypted registered 392s Sep 05 19:24:45 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 392s Sep 05 19:24:45 autopkgtest kernel: Secure boot mode disabled 392s Sep 05 19:24:45 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 392s Sep 05 19:24:45 autopkgtest kernel: Loading compiled-in module X.509 certificates 392s Sep 05 19:24:45 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 392s Sep 05 19:24:45 autopkgtest kernel: ima: Allocated hash algorithm: sha256 392s Sep 05 19:24:45 autopkgtest kernel: Secure boot mode disabled 392s Sep 05 19:24:45 autopkgtest kernel: Trusted boot mode disabled 392s Sep 05 19:24:45 autopkgtest kernel: ima: No architecture policies found 392s Sep 05 19:24:45 autopkgtest kernel: evm: Initialising EVM extended attributes: 392s Sep 05 19:24:45 autopkgtest kernel: evm: security.selinux 392s Sep 05 19:24:45 autopkgtest kernel: evm: security.SMACK64 392s Sep 05 19:24:45 autopkgtest kernel: evm: security.SMACK64EXEC 392s Sep 05 19:24:45 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 392s Sep 05 19:24:45 autopkgtest kernel: evm: security.SMACK64MMAP 392s Sep 05 19:24:45 autopkgtest kernel: evm: security.apparmor 392s Sep 05 19:24:45 autopkgtest kernel: evm: security.ima 392s Sep 05 19:24:45 autopkgtest kernel: evm: security.capability 392s Sep 05 19:24:45 autopkgtest kernel: evm: HMAC attrs: 0x1 392s Sep 05 19:24:45 autopkgtest kernel: SED: plpks not available 392s Sep 05 19:24:45 autopkgtest kernel: clk: Disabling unused clocks 392s Sep 05 19:24:45 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 392s Sep 05 19:24:45 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8832K 392s Sep 05 19:24:45 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 392s Sep 05 19:24:45 autopkgtest kernel: Run /init as init process 392s Sep 05 19:24:45 autopkgtest kernel: with arguments: 392s Sep 05 19:24:45 autopkgtest kernel: /init 392s Sep 05 19:24:45 autopkgtest kernel: earlyprintk 392s Sep 05 19:24:45 autopkgtest kernel: with environment: 392s Sep 05 19:24:45 autopkgtest kernel: HOME=/ 392s Sep 05 19:24:45 autopkgtest kernel: TERM=linux 392s Sep 05 19:24:45 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic 392s Sep 05 19:24:45 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 392s Sep 05 19:24:45 autopkgtest kernel: xhci_hcd 0000:00:03.0: xHCI Host Controller 392s Sep 05 19:24:45 autopkgtest kernel: xhci_hcd 0000:00:03.0: new USB bus registered, assigned bus number 1 392s Sep 05 19:24:45 autopkgtest kernel: xhci_hcd 0000:00:03.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010 392s Sep 05 19:24:45 autopkgtest kernel: xhci_hcd 0000:00:03.0: xHCI Host Controller 392s Sep 05 19:24:45 autopkgtest kernel: xhci_hcd 0000:00:03.0: new USB bus registered, assigned bus number 2 392s Sep 05 19:24:45 autopkgtest kernel: xhci_hcd 0000:00:03.0: Host supports USB 3.0 SuperSpeed 392s Sep 05 19:24:45 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.08 392s Sep 05 19:24:45 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 392s Sep 05 19:24:45 autopkgtest kernel: usb usb1: Product: xHCI Host Controller 392s Sep 05 19:24:45 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 392s Sep 05 19:24:45 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:03.0 392s Sep 05 19:24:45 autopkgtest kernel: hub 1-0:1.0: USB hub found 392s Sep 05 19:24:45 autopkgtest kernel: hub 1-0:1.0: 4 ports detected 392s Sep 05 19:24:45 autopkgtest kernel: usb usb2: We don't know the algorithms for LPM for this host, disabling LPM. 392s Sep 05 19:24:45 autopkgtest kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.08 392s Sep 05 19:24:45 autopkgtest kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 392s Sep 05 19:24:45 autopkgtest kernel: usb usb2: Product: xHCI Host Controller 392s Sep 05 19:24:45 autopkgtest kernel: usb usb2: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 392s Sep 05 19:24:45 autopkgtest kernel: usb usb2: SerialNumber: 0000:00:03.0 392s Sep 05 19:24:45 autopkgtest kernel: hub 2-0:1.0: USB hub found 392s Sep 05 19:24:45 autopkgtest kernel: hub 2-0:1.0: 4 ports detected 392s Sep 05 19:24:45 autopkgtest kernel: raid6: vpermxor8 gen() 21738 MB/s 392s Sep 05 19:24:45 autopkgtest kernel: raid6: vpermxor4 gen() 18615 MB/s 392s Sep 05 19:24:45 autopkgtest kernel: raid6: vpermxor2 gen() 15585 MB/s 392s Sep 05 19:24:45 autopkgtest kernel: raid6: vpermxor1 gen() 13160 MB/s 392s Sep 05 19:24:45 autopkgtest kernel: raid6: altivecx8 gen() 13845 MB/s 392s Sep 05 19:24:45 autopkgtest kernel: raid6: altivecx4 gen() 13769 MB/s 392s Sep 05 19:24:45 autopkgtest kernel: raid6: altivecx2 gen() 11115 MB/s 392s Sep 05 19:24:45 autopkgtest kernel: raid6: altivecx1 gen() 8613 MB/s 392s Sep 05 19:24:45 autopkgtest kernel: raid6: int64x8 gen() 7101 MB/s 392s Sep 05 19:24:45 autopkgtest kernel: raid6: int64x4 gen() 8548 MB/s 392s Sep 05 19:24:45 autopkgtest kernel: raid6: int64x2 gen() 6199 MB/s 392s Sep 05 19:24:45 autopkgtest kernel: raid6: int64x1 gen() 5203 MB/s 392s Sep 05 19:24:45 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 21738 MB/s 392s Sep 05 19:24:45 autopkgtest kernel: raid6: using intx1 recovery algorithm 392s Sep 05 19:24:45 autopkgtest kernel: xor: measuring software checksum speed 392s Sep 05 19:24:45 autopkgtest kernel: 8regs : 17371 MB/sec 392s Sep 05 19:24:45 autopkgtest kernel: 8regs_prefetch : 15548 MB/sec 392s Sep 05 19:24:45 autopkgtest kernel: 32regs : 17365 MB/sec 392s Sep 05 19:24:45 autopkgtest kernel: 32regs_prefetch : 15576 MB/sec 392s Sep 05 19:24:45 autopkgtest kernel: altivec : 19397 MB/sec 392s Sep 05 19:24:45 autopkgtest kernel: xor: using function: altivec (19397 MB/sec) 392s Sep 05 19:24:45 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 392s Sep 05 19:24:45 autopkgtest kernel: EXT4-fs (sda1): mounted filesystem f999abd5-af41-40ac-8675-cf1e7d4878fb ro with ordered data mode. Quota mode: none. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Inserted module 'autofs4' 392s Sep 05 19:24:45 autopkgtest systemd[1]: systemd 256.4-2ubuntu1 running in system mode (+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -XKBCOMMON +UTMP +SYSVINIT +LIBARCHIVE) 392s Sep 05 19:24:45 autopkgtest systemd[1]: Detected virtualization kvm. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Detected architecture ppc64-le. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Hostname set to . 392s Sep 05 19:24:45 autopkgtest systemd[1]: bpf-restrict-fs: BPF LSM hook not enabled in the kernel, BPF LSM not supported. 392s Sep 05 19:24:45 autopkgtest kernel: NET: Registered PF_VSOCK protocol family 392s Sep 05 19:24:45 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Queued start job for default target graphical.target. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Reached target swap.target - Swaps. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Listening on multipathd.socket - multipathd control socket. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 392s Sep 05 19:24:45 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Sockets. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounting run-lock.mount - Legacy Locks Directory /run/lock... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting modprobe@dm_multipath.service - Load Kernel Module dm_multipath... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 392s Sep 05 19:24:45 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 392s Sep 05 19:24:45 autopkgtest systemd[1]: systemd-fsck-root.service - File System Check on Root Device was skipped because of an unmet condition check (ConditionPathExists=!/run/initramfs/fsck-root). 392s Sep 05 19:24:45 autopkgtest systemd[1]: systemd-hibernate-clear.service - Clear Stale Hibernate Storage Info was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67). 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 392s Sep 05 19:24:45 autopkgtest systemd-journald[287]: Collecting audit messages is disabled. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounted run-lock.mount - Legacy Locks Directory /run/lock. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 392s Sep 05 19:24:45 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 392s Sep 05 19:24:45 autopkgtest systemd[1]: modprobe@dm_multipath.service: Deactivated successfully. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished modprobe@dm_multipath.service - Load Kernel Module dm_multipath. 392s Sep 05 19:24:45 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 392s Sep 05 19:24:45 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 392s Sep 05 19:24:45 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 392s Sep 05 19:24:45 autopkgtest kernel: EXT4-fs (sda1): re-mounted f999abd5-af41-40ac-8675-cf1e7d4878fb r/w. Quota mode: none. 392s Sep 05 19:24:45 autopkgtest systemd-journald[287]: Journal started 392s Sep 05 19:24:45 autopkgtest systemd-journald[287]: Runtime Journal (/run/log/journal/f2b026c9c820405b87839afd42a274c3) is 8M, max 78.4M, 70.4M free. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting cloud-init-main.service - Cloud-init: Single Process... 392s Sep 05 19:24:45 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 392s Sep 05 19:24:45 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 392s Sep 05 19:24:45 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 392s Sep 05 19:24:45 autopkgtest systemd-random-seed[344]: Kernel entropy pool is not initialized yet, waiting until it is. 392s Sep 05 19:24:45 autopkgtest multipathd[341]: multipathd v0.9.9: start up 392s Sep 05 19:24:45 autopkgtest systemd-journald[287]: Time spent on flushing to /var/log/journal/f2b026c9c820405b87839afd42a274c3 is 19.020ms for 436 entries. 392s Sep 05 19:24:45 autopkgtest systemd-journald[287]: System Journal (/var/log/journal/f2b026c9c820405b87839afd42a274c3) is 16M, max 4G, 3.9G free. 392s Sep 05 19:24:45 autopkgtest systemd-journald[287]: Received client request to flush runtime journal. 392s Sep 05 19:24:45 autopkgtest multipathd[341]: reconfigure: setting up paths and maps 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 392s Sep 05 19:24:45 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 392s Sep 05 19:24:45 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 361 (systemd-binfmt) 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 392s Sep 05 19:24:45 autopkgtest apparmor.systemd[358]: Restarting AppArmor 392s Sep 05 19:24:45 autopkgtest systemd-tmpfiles[369]: /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 392s Sep 05 19:24:45 autopkgtest apparmor.systemd[358]: Reloading AppArmor profiles 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. 392s Sep 05 19:24:45 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 392s Sep 05 19:24:45 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 392s Sep 05 19:24:45 autopkgtest kernel: audit: type=1400 audit(1725564285.524:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=385 comm="apparmor_parser" 392s Sep 05 19:24:45 autopkgtest kernel: audit: type=1400 audit(1725564285.524:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=387 comm="apparmor_parser" 392s Sep 05 19:24:45 autopkgtest kernel: audit: type=1400 audit(1725564285.524:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=386 comm="apparmor_parser" 392s Sep 05 19:24:45 autopkgtest kernel: audit: type=1400 audit(1725564285.524:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=384 comm="apparmor_parser" 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 392s Sep 05 19:24:45 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 392s Sep 05 19:24:45 autopkgtest systemd-udevd[363]: Using default interface naming scheme 'v255'. 392s Sep 05 19:24:45 autopkgtest kernel: audit: type=1400 audit(1725564285.532:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=392 comm="apparmor_parser" 392s Sep 05 19:24:45 autopkgtest kernel: audit: type=1400 audit(1725564285.536:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=394 comm="apparmor_parser" 392s Sep 05 19:24:45 autopkgtest kernel: audit: type=1400 audit(1725564285.536:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=393 comm="apparmor_parser" 392s Sep 05 19:24:45 autopkgtest kernel: audit: type=1400 audit(1725564285.536:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="busybox" pid=395 comm="apparmor_parser" 392s Sep 05 19:24:45 autopkgtest kernel: audit: type=1400 audit(1725564285.540:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="cam" pid=396 comm="apparmor_parser" 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 392s Sep 05 19:24:45 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 392s Sep 05 19:24:45 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 392s Sep 05 19:24:45 autopkgtest systemd[1]: systemd-ask-password-plymouth.path - Forward Password Requests to Plymouth Directory Watch was skipped because of an unmet condition check (ConditionPathExists=/run/plymouth/pid). 392s Sep 05 19:24:45 autopkgtest systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. 392s Sep 05 19:24:45 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 392s Sep 05 19:24:45 autopkgtest (udev-worker)[426]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 392s Sep 05 19:24:45 autopkgtest kernel: random: crng init done 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 392s Sep 05 19:24:45 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 388 ((resolved)) 392s Sep 05 19:24:45 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 392s Sep 05 19:24:45 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 392s Sep 05 19:24:45 autopkgtest systemd[1]: systemd-machine-id-commit.service - Save Transient machine-id to Disk was skipped because of an unmet condition check (ConditionPathIsMountPoint=/etc/machine-id). 392s Sep 05 19:24:45 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 392s Sep 05 19:24:46 autopkgtest systemd[1]: Started cloud-init-main.service - Cloud-init: Single Process. 392s Sep 05 19:24:46 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 392s Sep 05 19:24:46 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 392s Sep 05 19:24:46 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 392s Sep 05 19:24:46 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 392s Sep 05 19:24:46 autopkgtest systemd-resolved[388]: Positive Trust Anchors: 392s Sep 05 19:24:46 autopkgtest systemd-resolved[388]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 392s Sep 05 19:24:46 autopkgtest systemd-resolved[388]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 170.0.0.192.in-addr.arpa 171.0.0.192.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa ipv4only.arpa resolver.arpa corp home internal intranet lan local private test 392s Sep 05 19:24:46 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 392s Sep 05 19:24:46 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 392s Sep 05 19:24:46 autopkgtest systemd-resolved[388]: Using system hostname 'autopkgtest'. 392s Sep 05 19:24:46 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 392s Sep 05 19:24:46 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 392s Sep 05 19:24:46 autopkgtest cloud-init[672]: Cloud-init v. 24.4~2g2e4c39b7-0ubuntu1 running 'init-local' at Thu, 05 Sep 2024 19:24:46 +0000. Up 4.19 seconds. 392s Sep 05 19:24:46 autopkgtest dhcpcd[675]: dhcpcd-10.0.8 starting 392s Sep 05 19:24:46 autopkgtest dhcpcd[678]: DUID 00:01:00:01:2d:c3:64:c3:fa:16:3e:9f:5d:b2 392s Sep 05 19:24:46 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 392s Sep 05 19:24:46 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 392s Sep 05 19:24:46 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 392s Sep 05 19:24:46 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 392s Sep 05 19:24:46 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 392s Sep 05 19:24:46 autopkgtest dhcpcd[678]: enp0s1: IAID 3e:df:23:cd 392s Sep 05 19:24:46 autopkgtest dhcpcd[678]: enp0s1: rebinding lease of 10.43.136.50 392s Sep 05 19:24:51 autopkgtest dhcpcd[678]: enp0s1: DHCP lease expired 392s Sep 05 19:24:51 autopkgtest dhcpcd[678]: enp0s1: soliciting a DHCP lease 392s Sep 05 19:24:51 autopkgtest dhcpcd[678]: enp0s1: offered 10.43.136.50 from 10.43.136.8 392s Sep 05 19:24:51 autopkgtest dhcpcd[678]: enp0s1: leased 10.43.136.50 for 86400 seconds 392s Sep 05 19:24:51 autopkgtest dhcpcd[678]: enp0s1: adding route to 10.43.136.0/24 392s Sep 05 19:24:51 autopkgtest dhcpcd[678]: enp0s1: adding host route to 169.254.169.254 via 10.43.136.1 392s Sep 05 19:24:51 autopkgtest dhcpcd[678]: enp0s1: adding default route via 10.43.136.1 392s Sep 05 19:24:51 autopkgtest dhcpcd[678]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 392s Sep 05 19:24:59 autopkgtest sh[664]: Completed socket interaction for boot stage local 392s Sep 05 19:24:59 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 392s Sep 05 19:24:59 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 392s Sep 05 19:24:59 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 392s Sep 05 19:24:59 autopkgtest systemd-networkd[713]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 392s Sep 05 19:24:59 autopkgtest systemd-networkd[713]: lo: Link UP 392s Sep 05 19:24:59 autopkgtest systemd-networkd[713]: lo: Gained carrier 392s Sep 05 19:24:59 autopkgtest systemd-networkd[713]: Enumeration completed 392s Sep 05 19:24:59 autopkgtest systemd-networkd[713]: enp0s1: Link UP 392s Sep 05 19:24:59 autopkgtest systemd-networkd[713]: enp0s1: Gained carrier 392s Sep 05 19:24:59 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 392s Sep 05 19:24:59 autopkgtest systemd-networkd[713]: enp0s1: Gained IPv6LL 392s Sep 05 19:24:59 autopkgtest systemd[1]: Reached target network.target - Network. 392s Sep 05 19:24:59 autopkgtest systemd-timesyncd[389]: Network configuration changed, trying to establish connection. 392s Sep 05 19:24:59 autopkgtest systemd-networkd[713]: enp0s1: Link DOWN 392s Sep 05 19:24:59 autopkgtest systemd-networkd[713]: enp0s1: Lost carrier 392s Sep 05 19:24:59 autopkgtest systemd-timesyncd[389]: No network connectivity, watching for changes. 392s Sep 05 19:24:59 autopkgtest systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... 392s Sep 05 19:24:59 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 392s Sep 05 19:24:59 autopkgtest systemd-networkd[713]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 392s Sep 05 19:24:59 autopkgtest systemd-networkd[713]: enp0s1: Link UP 392s Sep 05 19:24:59 autopkgtest systemd-networkd[713]: enp0s1: Gained carrier 392s Sep 05 19:24:59 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 392s Sep 05 19:24:59 autopkgtest systemd-networkd[713]: enp0s1: DHCPv4 address 10.43.136.50/24, gateway 10.43.136.1 acquired from 10.43.136.8 392s Sep 05 19:24:59 autopkgtest systemd-timesyncd[389]: Network configuration changed, trying to establish connection. 392s Sep 05 19:24:59 autopkgtest systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. 392s Sep 05 19:24:59 autopkgtest systemd-timesyncd[389]: Contacted time server 185.125.190.57:123 (ntp.ubuntu.com). 392s Sep 05 19:24:59 autopkgtest systemd-timesyncd[389]: Initial clock synchronization to Thu 2024-09-05 19:24:59.382093 UTC. 392s Sep 05 19:25:01 autopkgtest systemd-networkd[713]: enp0s1: Gained IPv6LL 392s Sep 05 19:25:01 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting cloud-init-network.service - Cloud-init: Network Stage... 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: Cloud-init v. 24.4~2g2e4c39b7-0ubuntu1 running 'init' at Thu, 05 Sep 2024 19:25:01 +0000. Up 19.23 seconds. 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | enp0s1 | True | 10.43.136.50 | 255.255.255.0 | global | fa:16:3e:df:23:cd | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | enp0s1 | True | fe80::f816:3eff:fedf:23cd/64 | . | link | fa:16:3e:df:23:cd | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | lo | True | ::1/128 | . | host | . | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info++++++++++++++++++++++++++++++++ 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | 0 | 0.0.0.0 | 10.43.136.1 | 0.0.0.0 | enp0s1 | UG | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | 1 | 10.43.136.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | 2 | 10.43.136.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | 3 | 91.189.91.130 | 10.43.136.1 | 255.255.255.255 | enp0s1 | UGH | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | 4 | 169.254.169.254 | 10.43.136.1 | 255.255.255.255 | enp0s1 | UGH | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: +-------+-------------+---------+-----------+-------+ 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | Route | Destination | Gateway | Interface | Flags | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: +-------+-------------+---------+-----------+-------+ 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | 2 | local | :: | enp0s1 | U | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: | 3 | multicast | :: | enp0s1 | U | 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: ci-info: +-------+-------------+---------+-----------+-------+ 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: 2024-09-05 19:25:01,672 - log.py[DEPRECATED]: Deprecated cloud-config provided: apt_update: Deprecated in version 22.2. Use ``package_update`` instead., apt_upgrade: Deprecated in version 22.2. Use ``package_upgrade`` instead. 392s Sep 05 19:25:01 autopkgtest cloud-init[672]: 2024-09-05 19:25:01,672 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 392s Sep 05 19:25:01 autopkgtest sh[724]: Completed socket interaction for boot stage network 392s Sep 05 19:25:01 autopkgtest systemd[1]: Finished cloud-init-network.service - Cloud-init: Network Stage. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 392s Sep 05 19:25:01 autopkgtest systemd[1]: apport-autoreport.path - Process error reports when automatic reporting is enabled (file watch) was skipped because of an unmet condition check (ConditionPathExists=/var/lib/apport/autoreport). 392s Sep 05 19:25:01 autopkgtest systemd[1]: apport-autoreport.timer - Process error reports when automatic reporting is enabled (timer based) was skipped because of an unmet condition check (ConditionPathExists=/var/lib/apport/autoreport). 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started sysstat-collect.timer - Run system activity accounting tool every 10 minutes. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started sysstat-rotate.timer - Rotate daily system activity data file at midnight. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started sysstat-summary.timer - Generate summary of yesterday's process accounting. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 392s Sep 05 19:25:01 autopkgtest systemd[1]: ua-timer.timer - Ubuntu Pro Timer for running repeated jobs was skipped because of an unmet condition check (ConditionPathExists=/var/lib/ubuntu-advantage/private/machine-token.json). 392s Sep 05 19:25:01 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Reached target paths.target - Path Units. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 392s Sep 05 19:25:01 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 392s Sep 05 19:25:01 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 392s Sep 05 19:25:01 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). 392s Sep 05 19:25:01 autopkgtest systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). 392s Sep 05 19:25:01 autopkgtest systemd[1]: Reached target ssh-access.target - SSH Access Available. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Reached target basic.target - Basic System. 392s Sep 05 19:25:01 autopkgtest systemd[1]: System is tainted: unmerged-bin 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 392s Sep 05 19:25:01 autopkgtest (sh)[759]: autopkgtest@hvc1.service: Failed to set up standard input: No such device 392s Sep 05 19:25:01 autopkgtest (sh)[759]: autopkgtest@hvc1.service: Failed at step STDIN spawning /bin/sh: No such device 392s Sep 05 19:25:01 autopkgtest (sh)[760]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 392s Sep 05 19:25:01 autopkgtest (sh)[760]: autopkgtest@ttyS1.service: Failed at step STDIN spawning /bin/sh: Input/output error 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 392s Sep 05 19:25:01 autopkgtest (cron)[762]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 392s Sep 05 19:25:01 autopkgtest systemd[1]: getty-static.service - getty on tty2-tty6 if dbus and logind are not available was skipped because of an unmet condition check (ConditionPathExists=!/usr/bin/dbus-daemon). 392s Sep 05 19:25:01 autopkgtest cron[762]: (CRON) INFO (pidfile fd = 3) 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 392s Sep 05 19:25:01 autopkgtest cron[762]: (CRON) INFO (Running @reboot jobs) 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 392s Sep 05 19:25:01 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 392s Sep 05 19:25:01 autopkgtest systemd[1]: opal_errd.service - opal_errd (PowerNV platform error handling) Service was skipped because of an unmet condition check (ConditionVirtualization=false). 392s Sep 05 19:25:01 autopkgtest systemd[1]: pollinate.service - Pollinate to seed the pseudo random number generator was skipped because of an unmet condition check (ConditionPathExists=!/var/cache/pollinate/seeded). 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 392s Sep 05 19:25:01 autopkgtest dbus-daemon[763]: [system] AppArmor D-Bus mediation is enabled 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting sysstat.service - Resets System Activity Logs... 392s Sep 05 19:25:01 autopkgtest dbus-daemon[763]: [system] Activating systemd to hand-off: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.2' (uid=998 pid=713 comm="/usr/lib/systemd/systemd-networkd" label="unconfined") 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 392s Sep 05 19:25:01 autopkgtest systemd[1]: ua-reboot-cmds.service - Ubuntu Pro reboot cmds was skipped because of an unmet condition check (ConditionPathExists=/var/lib/ubuntu-advantage/private/machine-token.json). 392s Sep 05 19:25:01 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 392s Sep 05 19:25:01 autopkgtest systemd[1]: autopkgtest@hvc1.service: Deactivated successfully. 392s Sep 05 19:25:01 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 392s Sep 05 19:25:01 autopkgtest dbus-daemon[763]: [system] Successfully activated service 'org.freedesktop.systemd1' 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 392s Sep 05 19:25:01 autopkgtest udisksd[783]: udisks daemon version 2.10.1 starting 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Finished sysstat.service - Resets System Activity Logs. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 392s Sep 05 19:25:01 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting systemd-hostnamed.service - Hostname Service... 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 392s Sep 05 19:25:01 autopkgtest rng-tools-debian[824]: found /dev/hwrng but could not use it 392s Sep 05 19:25:01 autopkgtest rng-tools-debian[828]: not starting: no hardware RNG device found 392s Sep 05 19:25:01 autopkgtest rng-tools-debian[773]: * Configuring Hardware RNG entropy gatherer daemon 392s Sep 05 19:25:01 autopkgtest rng-tools-debian[773]: ...fail! 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 392s Sep 05 19:25:01 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 392s Sep 05 19:25:01 autopkgtest sshd[829]: Server listening on :: port 22. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 392s Sep 05 19:25:01 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 392s Sep 05 19:25:01 autopkgtest systemd-logind[780]: New seat seat0. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 392s Sep 05 19:25:01 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 392s Sep 05 19:25:02 autopkgtest kernel: kauditd_printk_skb: 110 callbacks suppressed 392s Sep 05 19:25:02 autopkgtest kernel: audit: type=1400 audit(1725564302.028:121): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=841 comm="apparmor_parser" 392s Sep 05 19:25:02 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 392s Sep 05 19:25:02 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 392s Sep 05 19:25:02 autopkgtest udisksd[783]: Acquired the name org.freedesktop.UDisks2 on the system message bus 392s Sep 05 19:25:02 autopkgtest systemd[1]: Started systemd-hostnamed.service - Hostname Service. 392s Sep 05 19:25:02 autopkgtest dbus-daemon[763]: [system] Successfully activated service 'org.freedesktop.hostname1' 392s Sep 05 19:25:02 autopkgtest systemd-networkd[713]: Could not set hostname: Access denied 392s Sep 05 19:25:02 autopkgtest cloud-init[672]: Cloud-init v. 24.4~2g2e4c39b7-0ubuntu1 running 'modules:config' at Thu, 05 Sep 2024 19:25:01 +0000. Up 19.71 seconds. 392s Sep 05 19:25:02 autopkgtest rsyslogd[852]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2406.0] 392s Sep 05 19:25:02 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 392s Sep 05 19:25:02 autopkgtest rsyslogd[852]: rsyslogd's groupid changed to 102 392s Sep 05 19:25:02 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 392s Sep 05 19:25:02 autopkgtest rsyslogd[852]: rsyslogd's userid changed to 102 392s Sep 05 19:25:02 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 392s Sep 05 19:25:02 autopkgtest rsyslogd[852]: [origin software="rsyslogd" swVersion="8.2406.0" x-pid="852" x-info="https://www.rsyslog.com"] start 392s Sep 05 19:25:02 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 392s Sep 05 19:25:02 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 392s Sep 05 19:25:02 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 392s Sep 05 19:25:02 autopkgtest sh[766]: Completed socket interaction for boot stage config 392s Sep 05 19:25:02 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 392s Sep 05 19:25:02 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 392s Sep 05 19:25:02 autopkgtest cloud-init[672]: Cloud-init v. 24.4~2g2e4c39b7-0ubuntu1 running 'modules:final' at Thu, 05 Sep 2024 19:25:02 +0000. Up 20.04 seconds. 392s Sep 05 19:25:02 autopkgtest cloud-init[672]: Cloud-init v. 24.4~2g2e4c39b7-0ubuntu1 finished at Thu, 05 Sep 2024 19:25:02 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 20.18 seconds 392s Sep 05 19:25:02 autopkgtest sh[864]: Completed socket interaction for boot stage final 392s Sep 05 19:25:02 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 392s Sep 05 19:25:02 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 392s Sep 05 19:25:02 autopkgtest systemd[1]: Startup finished in 2.687s (kernel) + 17.508s (userspace) = 20.195s. 392s Sep 05 19:25:02 autopkgtest kernel: fbcon: Taking over console 392s Sep 05 19:25:02 autopkgtest systemd[1]: cloud-init-main.service: Deactivated successfully. 392s Sep 05 19:25:02 autopkgtest systemd[1]: cloud-init-main.service: Unit process 671 (sh) remains running after unit stopped. 392s Sep 05 19:25:02 autopkgtest systemd[1]: cloud-init-main.service: Consumed 2.004s CPU time, 109.1M memory peak. 392s Sep 05 19:25:02 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 392s Sep 05 19:25:02 autopkgtest sshd[844]: Accepted publickey for ubuntu from 10.136.6.201 port 36556 ssh2: RSA SHA256:YaYyKWTl9zFJEBK5G3u+MRj3WPJt+vEplFd0J96PUBw 392s Sep 05 19:25:02 autopkgtest sshd[844]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 392s Sep 05 19:25:02 autopkgtest sshd[844]: pam_systemd(sshd:session): New sd-bus connection (system-bus-pam-systemd-844) opened. 392s Sep 05 19:25:02 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 392s Sep 05 19:25:02 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 392s Sep 05 19:25:02 autopkgtest systemd-logind[780]: New session 1 of user ubuntu. 392s Sep 05 19:25:02 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 392s Sep 05 19:25:02 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 392s Sep 05 19:25:02 autopkgtest (systemd)[893]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 392s Sep 05 19:25:02 autopkgtest systemd-logind[780]: New session 2 of user ubuntu. 392s Sep 05 19:25:02 autopkgtest systemd[893]: Queued start job for default target default.target. 392s Sep 05 19:25:02 autopkgtest systemd[893]: Created slice app.slice - User Application Slice. 392s Sep 05 19:25:02 autopkgtest systemd[893]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 392s Sep 05 19:25:02 autopkgtest systemd[893]: Reached target paths.target - Paths. 392s Sep 05 19:25:02 autopkgtest systemd[893]: Reached target timers.target - Timers. 392s Sep 05 19:25:02 autopkgtest systemd[893]: Starting dbus.socket - D-Bus User Message Bus Socket... 392s Sep 05 19:25:02 autopkgtest systemd[893]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 392s Sep 05 19:25:02 autopkgtest systemd[893]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 392s Sep 05 19:25:02 autopkgtest systemd[893]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 392s Sep 05 19:25:02 autopkgtest systemd[893]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 392s Sep 05 19:25:02 autopkgtest systemd[893]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 392s Sep 05 19:25:02 autopkgtest systemd[893]: Listening on keyboxd.socket - GnuPG public key management service. 392s Sep 05 19:25:02 autopkgtest systemd[893]: Listening on dbus.socket - D-Bus User Message Bus Socket. 392s Sep 05 19:25:02 autopkgtest systemd[893]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 392s Sep 05 19:25:02 autopkgtest systemd[893]: Reached target sockets.target - Sockets. 392s Sep 05 19:25:02 autopkgtest systemd[893]: Reached target basic.target - Basic System. 392s Sep 05 19:25:02 autopkgtest systemd[893]: Reached target default.target - Main User Target. 392s Sep 05 19:25:02 autopkgtest systemd[893]: Startup finished in 111ms. 392s Sep 05 19:25:02 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 392s Sep 05 19:25:02 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 392s Sep 05 19:25:03 autopkgtest sudo[921]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 392s Sep 05 19:25:03 autopkgtest sudo[921]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:03 autopkgtest sudo[921]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:03 autopkgtest sudo[926]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper /bin/sh -ec 'for d in /var/cache /home; do if [ -e $d/autopkgtest-tmpdir.tar ]; then /bin/tar --warning=none --extract --absolute-names -f $d/autopkgtest-tmpdir.tar; /bin/rm $d/autopkgtest-tmpdir.tar; exit 0; fi; done; exit 1' 392s Sep 05 19:25:03 autopkgtest sudo[926]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:03 autopkgtest sudo[926]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:03 autopkgtest sudo[938]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.emREIN 392s Sep 05 19:25:03 autopkgtest sudo[938]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:03 autopkgtest sudo[938]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:03 autopkgtest sudo[948]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.emREIN/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.emREIN/autopkgtest-reboot' 392s Sep 05 19:25:03 autopkgtest sudo[948]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:03 autopkgtest sudo[948]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:03 autopkgtest sudo[960]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.emREIN/autopkgtest-reboot 392s Sep 05 19:25:03 autopkgtest sudo[960]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:03 autopkgtest sudo[960]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:04 autopkgtest sudo[970]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.emREIN/autopkgtest-reboot /tmp/autopkgtest-reboot 392s Sep 05 19:25:04 autopkgtest sudo[970]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:04 autopkgtest sudo[970]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:04 autopkgtest sudo[980]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.emREIN/autopkgtest-reboot /sbin/autopkgtest-reboot 392s Sep 05 19:25:04 autopkgtest sudo[980]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:04 autopkgtest sudo[980]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:04 autopkgtest sudo[990]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.emREIN 392s Sep 05 19:25:04 autopkgtest sudo[990]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:04 autopkgtest sudo[990]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:04 autopkgtest sudo[1000]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.emREIN/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.emREIN/autopkgtest-reboot-prepare' 392s Sep 05 19:25:04 autopkgtest sudo[1000]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:04 autopkgtest sudo[1000]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:04 autopkgtest sudo[1012]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.emREIN/autopkgtest-reboot-prepare 392s Sep 05 19:25:04 autopkgtest sudo[1012]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:04 autopkgtest sudo[1012]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:05 autopkgtest sudo[1022]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.emREIN/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 392s Sep 05 19:25:05 autopkgtest sudo[1022]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:05 autopkgtest sudo[1022]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:05 autopkgtest sudo[1032]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 392s Sep 05 19:25:05 autopkgtest sudo[1032]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:05 autopkgtest sudo[1032]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:05 autopkgtest sudo[1042]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 392s Sep 05 19:25:05 autopkgtest sudo[1042]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:05 autopkgtest sudo[1042]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:05 autopkgtest sudo[1052]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.emREIN/testbed-packages' 392s Sep 05 19:25:05 autopkgtest sudo[1052]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:05 autopkgtest sudo[1052]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:05 autopkgtest sudo[1063]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.emREIN/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.emREIN/autopkgtest-reboot' 392s Sep 05 19:25:06 autopkgtest sudo[1084]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:06 autopkgtest sudo[1084]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:06 autopkgtest sudo[1096]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.emREIN/autopkgtest-reboot 392s Sep 05 19:25:06 autopkgtest sudo[1096]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:06 autopkgtest sudo[1096]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:06 autopkgtest sudo[1106]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.emREIN/autopkgtest-reboot /tmp/autopkgtest-reboot 392s Sep 05 19:25:06 autopkgtest sudo[1106]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:06 autopkgtest sudo[1106]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:06 autopkgtest sudo[1116]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.emREIN/autopkgtest-reboot /sbin/autopkgtest-reboot 392s Sep 05 19:25:06 autopkgtest sudo[1116]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:06 autopkgtest sudo[1116]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:06 autopkgtest sudo[1126]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.emREIN 392s Sep 05 19:25:06 autopkgtest sudo[1126]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:06 autopkgtest sudo[1126]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:07 autopkgtest sudo[1136]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.emREIN/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.emREIN/autopkgtest-reboot-prepare' 392s Sep 05 19:25:07 autopkgtest sudo[1136]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:07 autopkgtest sudo[1136]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:07 autopkgtest sudo[1148]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.emREIN/autopkgtest-reboot-prepare 392s Sep 05 19:25:07 autopkgtest sudo[1148]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:07 autopkgtest sudo[1148]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:07 autopkgtest sudo[1158]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.emREIN/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 392s Sep 05 19:25:07 autopkgtest sudo[1158]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:07 autopkgtest sudo[1158]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:07 autopkgtest sudo[1168]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 392s Sep 05 19:25:07 autopkgtest sudo[1168]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:07 autopkgtest sudo[1168]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:07 autopkgtest sudo[1178]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 392s Sep 05 19:25:07 autopkgtest sudo[1178]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:07 autopkgtest sudo[1178]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:08 autopkgtest sudo[1187]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.emREIN 392s Sep 05 19:25:08 autopkgtest sudo[1187]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:08 autopkgtest sudo[1187]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:08 autopkgtest sudo[1197]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.emREIN/2-autopkgtest-satdep.deb' 392s Sep 05 19:25:08 autopkgtest sudo[1197]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:08 autopkgtest sudo[1197]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:08 autopkgtest sudo[1208]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.emREIN/2-autopkgtest-satdep.deb 392s Sep 05 19:25:08 autopkgtest sudo[1208]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:08 autopkgtest sudo[1208]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:08 autopkgtest sudo[1218]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper env DEBIAN_FRONTEND=noninteractive APT_LISTBUGS_FRONTEND=none APT_LISTCHANGES_FRONTEND=none /bin/sh -ec '/usr/bin/eatmydata apt-get install --assume-yes /tmp/autopkgtest.emREIN/2-autopkgtest-satdep.deb -o APT::Status-Fd=3 -o APT::Install-Recommends=false -o Dpkg::Options::=--force-confnew -o Debug::pkgProblemResolver=true 3>&2 2>&1' 392s Sep 05 19:25:08 autopkgtest sudo[1218]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:11 autopkgtest systemd[1]: Reload requested from client PID 1458 ('systemctl') (unit session-1.scope)... 392s Sep 05 19:25:11 autopkgtest systemd[1]: Reloading... 392s Sep 05 19:25:11 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:11 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:11 autopkgtest systemd[1]: Reloading finished in 214 ms. 392s Sep 05 19:25:12 autopkgtest systemd[1]: Reload requested from client PID 1508 ('systemctl') (unit session-1.scope)... 392s Sep 05 19:25:12 autopkgtest systemd[1]: Reloading... 392s Sep 05 19:25:12 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:12 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:12 autopkgtest systemd[1]: Reloading finished in 184 ms. 392s Sep 05 19:25:12 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 392s Sep 05 19:25:12 autopkgtest tgtd[1554]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 392s Sep 05 19:25:12 autopkgtest tgtd[1554]: tgtd: work_timer_start(146) use timer_fd based scheduler 392s Sep 05 19:25:12 autopkgtest tgtd[1554]: tgtd: bs_init(387) use signalfd notification 392s Sep 05 19:25:12 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 392s Sep 05 19:25:12 autopkgtest systemd[1]: Reload requested from client PID 1581 ('systemctl') (unit session-1.scope)... 392s Sep 05 19:25:12 autopkgtest systemd[1]: Reloading... 392s Sep 05 19:25:12 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:12 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:12 autopkgtest systemd[1]: Reloading finished in 178 ms. 392s Sep 05 19:25:12 autopkgtest systemd[1]: Reload requested from client PID 1624 ('systemctl') (unit session-1.scope)... 392s Sep 05 19:25:12 autopkgtest systemd[1]: Reloading... 392s Sep 05 19:25:12 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:12 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:13 autopkgtest systemd[1]: Reloading finished in 182 ms. 392s Sep 05 19:25:13 autopkgtest systemd[1]: Reload requested from client PID 1670 ('systemctl') (unit session-1.scope)... 392s Sep 05 19:25:13 autopkgtest systemd[1]: Reloading... 392s Sep 05 19:25:13 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:13 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:13 autopkgtest systemd[1]: Reloading finished in 176 ms. 392s Sep 05 19:25:13 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 392s Sep 05 19:25:13 autopkgtest systemd[1]: Reload requested from client PID 1721 ('systemctl') (unit session-1.scope)... 392s Sep 05 19:25:13 autopkgtest systemd[1]: Reloading... 392s Sep 05 19:25:13 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:13 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:13 autopkgtest systemd[1]: Reloading finished in 170 ms. 392s Sep 05 19:25:13 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 392s Sep 05 19:25:13 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 392s Sep 05 19:25:13 autopkgtest systemd[1]: Reload requested from client PID 1776 ('systemctl') (unit session-1.scope)... 392s Sep 05 19:25:13 autopkgtest systemd[1]: Reloading... 392s Sep 05 19:25:14 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:14 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 05 19:25:14 autopkgtest systemd[1]: Reloading finished in 189 ms. 392s Sep 05 19:25:23 autopkgtest sudo[1218]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:23 autopkgtest sudo[5625]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 392s Sep 05 19:25:23 autopkgtest sudo[5625]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:23 autopkgtest sudo[5625]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:23 autopkgtest sudo[5635]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 392s Sep 05 19:25:23 autopkgtest sudo[5635]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:23 autopkgtest sudo[5635]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:24 autopkgtest sudo[5645]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-get --simulate --quiet -o APT::Get::Show-User-Simulation-Note=False --auto-remove purge autopkgtest-satdep 392s Sep 05 19:25:24 autopkgtest sudo[5645]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:24 autopkgtest sudo[5645]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:25 autopkgtest sudo[5658]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq fio librbd1 librados2 libboost-iostreams1.83.0 libboost-thread1.83.0 tgt libconfig-general-perl libpmemobj1 libpmem1 libndctl6 libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 open-iscsi libisns0t64 libnbd0 libopeniscsiusr librdmacm1t64 392s Sep 05 19:25:25 autopkgtest sudo[5658]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:25 autopkgtest sudo[5658]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:25 autopkgtest sudo[5670]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 392s Sep 05 19:25:25 autopkgtest sudo[5670]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:25 autopkgtest sudo[5670]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:25 autopkgtest sudo[5682]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 392s Sep 05 19:25:25 autopkgtest sudo[5682]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:25 autopkgtest sudo[5682]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:26 autopkgtest sudo[5692]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.emREIN/tgtbasedmpaths-packages.all' 392s Sep 05 19:25:26 autopkgtest sudo[5692]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 05 19:25:26 autopkgtest sudo[5692]: pam_unix(sudo:session): session closed for user root 392s Sep 05 19:25:26 autopkgtest sudo[5703]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 396s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 396s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 396s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 396s latency : target=0, window=0, percentile=100.00%, depth=1 396s 396s Run status group 0 (all jobs): 396s WRITE: bw=138MiB/s (145MB/s), 138MiB/s-138MiB/s (145MB/s-145MB/s), io=87.5MiB (91.8MB), run=634-634msec 396s 396s Disk stats (read/write): 396s dm-0: ios=1/1404, sectors=8/192072, merge=0/1, ticks=1/629, in_queue=658, util=86.41%, aggrios=0/350, aggsectors=2/48018, aggrmerge=0/0, aggrticks=7/148, aggrin_queue=155, aggrutil=84.46% 396s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 396s sdb: ios=2/1403, sectors=8/192072, merge=0/0, ticks=29/593, in_queue=623, util=84.46% 396s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 396s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 396s + echo Starting the path changes in background 396s Starting the path changes in background 396s + date +Pre FIO %H:%M:%S.%N 396s Pre FIO 19:25:37.645816403 396s + fio --max-jobs=4 /tmp/autopkgtest.emREIN/tgtbasedmpaths-artifacts/path-change-check.fio 396s 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 396s fio-3.37 396s Starting 1 thread 577s 577s verify-phase: (groupid=0, jobs=1): err= 0: pid=6047: Thu Sep 5 19:28:37 2024 577s read: IOPS=3770, BW=236MiB/s (247MB/s)(41.4GiB/180001msec) 577s clat (usec): min=88, max=43500, avg=242.79, stdev=158.41 577s lat (usec): min=88, max=43500, avg=242.90, stdev=158.42 577s clat percentiles (usec): 577s | 1.00th=[ 98], 5.00th=[ 151], 10.00th=[ 159], 20.00th=[ 188], 577s | 30.00th=[ 200], 40.00th=[ 210], 50.00th=[ 219], 60.00th=[ 237], 577s | 70.00th=[ 277], 80.00th=[ 302], 90.00th=[ 338], 95.00th=[ 367], 577s | 99.00th=[ 437], 99.50th=[ 474], 99.90th=[ 1074], 99.95th=[ 1614], 577s | 99.99th=[ 3851] 577s bw ( KiB/s): min=138388, max=437376, per=100.00%, avg=241627.22, stdev=50695.47, samples=359 577s iops : min= 2162, max= 6834, avg=3775.41, stdev=792.12, samples=359 577s lat (usec) : 100=1.28%, 250=61.62%, 500=36.68%, 750=0.19%, 1000=0.11% 577s lat (msec) : 2=0.08%, 4=0.03%, 10=0.01%, 20=0.01%, 50=0.01% 577s cpu : usr=10.09%, sys=7.67%, ctx=678747, majf=0, minf=1 577s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 577s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 577s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 577s issued rwts: total=678665,0,0,0 short=0,0,0,0 dropped=0,0,0,0 577s latency : target=0, window=0, percentile=100.00%, depth=1 577s 577s Run status group 0 (all jobs): 577s READ: bw=236MiB/s (247MB/s), 236MiB/s-236MiB/s (247MB/s-247MB/s), io=41.4GiB (44.5GB), run=180001-180001msec 577s 577s Disk stats (read/write): 577s dm-0: ios=678890/8, sectors=86832952/136, merge=11/9, ticks=164806/22, in_queue=164844, util=100.00%, aggrios=47010/2, aggsectors=6012238/34, aggrmerge=0/0, aggrticks=10550/1, aggrin_queue=10552, aggrutil=99.13% 577s sdd: ios=39004/0, sectors=4988928/0, merge=0/0, ticks=8365/0, in_queue=8365, util=33.01% 577s sdb: ios=35124/8, sectors=4492544/136, merge=0/0, ticks=8310/7, in_queue=8316, util=99.13% 577s sde: ios=79415/0, sectors=10157824/0, merge=0/0, ticks=16842/0, in_queue=16842, util=39.69% 577s sdc: ios=34499/0, sectors=4409656/0, merge=0/0, ticks=8684/0, in_queue=8685, util=50.10% 577s + date +Post FIO %H:%M:%S.%N 577s Post FIO 19:28:37.984136219 577s FIO verify test with changing paths - OK 577s Report log of background activity 577s + echo FIO verify test with changing paths - OK 577s + echo Report log of background activity 577s + cat /tmp/autopkgtest.emREIN/tgtbasedmpaths-artifacts/test-background.log 577s + iscsiadm --mode session 577s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s + sleep 10s 577s + date +MP report (expect 4) %H:%M:%S.%N 577s MP report (expect 4) 19:25:47.652470829 577s + multipath -ll 577s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 577s size=100M features='0' hwhandler='0' wp=rw 577s |-+- policy='service-time 0' prio=1 status=active 577s | `- 1:0:0:1 sdb 8:16 active ready running 577s |-+- policy='service-time 0' prio=1 status=enabled 577s | `- 2:0:0:1 sdc 8:32 active ready running 577s |-+- policy='service-time 0' prio=1 status=enabled 577s | `- 3:0:0:1 sdd 8:48 active ready running 577s `-+- policy='service-time 0' prio=1 status=enabled 577s `- 4:0:0:1 sde 8:64 active ready running 577s + date +UN-plug path 1 %H:%M:%S.%N 577s UN-plug path 1 19:25:47.677362080 577s + iscsiadm --mode session -r 1 -u 577s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 577s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 577s + iscsiadm --mode session 577s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s + sleep 10s 577s + date +MP report (expect 3) %H:%M:%S.%N 577s MP report (expect 3) 19:25:57.772730107 577s + multipath -ll 577s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 577s size=100M features='0' hwhandler='0' wp=rw 577s |-+- policy='service-time 0' prio=1 status=active 577s | `- 2:0:0:1 sdc 8:32 active ready running 577s |-+- policy='service-time 0' prio=1 status=enabled 577s | `- 3:0:0:1 sdd 8:48 active ready running 577s `-+- policy='service-time 0' prio=1 status=enabled 577s `- 4:0:0:1 sde 8:64 active ready running 577s + date +UN-plug path 2 %H:%M:%S.%N 577s UN-plug path 2 19:25:57.796127125 577s + iscsiadm --mode session -r 2 -u 577s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 577s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 577s + iscsiadm --mode session 577s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s + sleep 10s 577s + date +MP report (expect 2) %H:%M:%S.%N 577s MP report (expect 2) 19:26:07.899226214 577s + multipath -ll 577s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 577s size=100M features='0' hwhandler='0' wp=rw 577s |-+- policy='service-time 0' prio=1 status=active 577s | `- 3:0:0:1 sdd 8:48 active ready running 577s `-+- policy='service-time 0' prio=1 status=enabled 577s `- 4:0:0:1 sde 8:64 active ready running 577s + date +UN-plug path 3 %H:%M:%S.%N 577s UN-plug path 3 19:26:07.919371577 577s + iscsiadm --mode session -r 3 -u 577s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 577s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 577s + iscsiadm --mode session 577s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s + sleep 10s 577s + date +MP report (expect 1) %H:%M:%S.%N 577s MP report (expect 1) 19:26:17.997212202 577s + multipath -ll 577s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 577s size=100M features='0' hwhandler='0' wp=rw 577s `-+- policy='service-time 0' prio=1 status=active 577s `- 4:0:0:1 sde 8:64 active ready running 577s + date +Add paths 5/6/7/8 %H:%M:%S.%N 577s Add paths 5/6/7/8 19:26:18.010823378 577s + iscsiadm --mode session -r 4 --op new 577s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 577s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 577s + iscsiadm --mode session -r 4 --op new 577s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 577s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 577s + iscsiadm --mode session -r 4 --op new 577s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 577s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 577s + iscsiadm --mode session -r 4 --op new 577s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 577s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 577s + iscsiadm --mode session 577s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s + sleep 10s 577s + date +MP report (expect 5) %H:%M:%S.%N 577s MP report (expect 5) 19:26:28.137064205 577s + multipath -ll 577s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 577s size=100M features='0' hwhandler='0' wp=rw 577s |-+- policy='service-time 0' prio=1 status=active 577s | `- 4:0:0:1 sde 8:64 active ready running 577s |-+- policy='service-time 0' prio=1 status=enabled 577s | `- 1:0:0:1 sdb 8:16 active ready running 577s |-+- policy='service-time 0' prio=1 status=enabled 577s | `- 2:0:0:1 sdc 8:32 active ready running 577s |-+- policy='service-time 0' prio=1 status=enabled 577s | `- 3:0:0:1 sdd 8:48 active ready running 577s `-+- policy='service-time 0' prio=1 status=enabled 577s `- 5:0:0:1 sdf 8:80 active ready running 577s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 577s UN-plug multiple paths 4/7/8 19:26:28.170570511 577s + iscsiadm --mode session -r 4 -u 577s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 577s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 577s + iscsiadm --mode session -r 7 -u 577s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 577s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 577s + iscsiadm --mode session -r 8 -u 577s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 577s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 577s + iscsiadm --mode session 577s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 577s + sleep 10s 577s + date +Restart multipath daemon %H:%M:%S.%N 577s Restart multipath daemon 19:26:38.449345834 577s + systemctl restart multipathd 577s + sleep 10s 577s + date +Final background report (expect 2) %H:%M:%S.%N 577s Final background report (expect 2) 19:26:48.536292864 577s + multipath -ll 577s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 577s size=100M features='0' hwhandler='0' wp=rw 577s |-+- policy='service-time 0' prio=1 status=active 577s | `- 1:0:0:1 sdb 8:16 active ready running 577s `-+- policy='service-time 0' prio=1 status=enabled 577s `- 2:0:0:1 sdc 8:32 active ready running 577s Final stats 577s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 577s iSCSI SNMP: 577s txdata_octets: 23473992 577s rxdata_octets: 32026985396 577s noptx_pdus: 0 577s scsicmd_pdus: 488774 577s tmfcmd_pdus: 0 577s login_pdus: 0 577s text_pdus: 0 577s dataout_pdus: 0 577s logout_pdus: 0 577s snack_pdus: 0 577s noprx_pdus: 0 577s scsirsp_pdus: 488774 577s tmfrsp_pdus: 0 577s textrsp_pdus: 0 577s datain_pdus: 488741 577s logoutrsp_pdus: 0 577s r2t_pdus: 0 577s async_pdus: 0 577s rjt_pdus: 0 577s digest_err: 0 577s timeout_err: 0 577s iSCSI Extended: 577s tx_sendpage_failures: 0 577s rx_discontiguous_hdr: 0 577s eh_abort_cnt: 0 577s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 577s iSCSI SNMP: 577s txdata_octets: 7416 577s rxdata_octets: 2957668 577s noptx_pdus: 0 577s scsicmd_pdus: 125 577s tmfcmd_pdus: 0 577s login_pdus: 0 577s text_pdus: 0 577s dataout_pdus: 0 577s logout_pdus: 0 577s snack_pdus: 0 577s noprx_pdus: 0 577s scsirsp_pdus: 125 577s tmfrsp_pdus: 0 577s textrsp_pdus: 0 577s datain_pdus: 103 577s logoutrsp_pdus: 0 577s r2t_pdus: 0 577s async_pdus: 0 577s rjt_pdus: 0 577s digest_err: 0 577s timeout_err: 0 577s iSCSI Extended: 577s tx_sendpage_failures: 0 577s rx_discontiguous_hdr: 0 577s eh_abort_cnt: 0 577s Sep 05 17:26:29 adtubuntu-oracular-ppc64el-server-20240904 multipathd[269]: multipathd: shut down 577s Sep 05 17:26:29 adtubuntu-oracular-ppc64el-server-20240904 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 577s Sep 05 17:26:29 adtubuntu-oracular-ppc64el-server-20240904 systemd[1]: multipathd.service: Deactivated successfully. 577s Sep 05 17:26:29 adtubuntu-oracular-ppc64el-server-20240904 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 577s -- Boot fa76e21a67e241d490529b9d01150a87 -- 577s Sep 05 19:23:35 adtubuntu-oracular-ppc64el-server-20240904 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 577s Sep 05 19:23:35 adtubuntu-oracular-ppc64el-server-20240904 multipathd[338]: multipathd v0.9.9: start up 577s Sep 05 19:23:35 adtubuntu-oracular-ppc64el-server-20240904 multipathd[338]: reconfigure: setting up paths and maps 577s Sep 05 19:23:35 adtubuntu-oracular-ppc64el-server-20240904 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 577s Sep 05 19:24:22 autopkgtest multipathd[338]: multipathd: shut down 577s Sep 05 19:24:22 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 577s Sep 05 19:24:22 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 577s Sep 05 19:24:22 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 577s -- Boot 9f6990e7a6e3452482ce46e3d672b0fd -- 577s Sep 05 19:24:45 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 577s Sep 05 19:24:45 autopkgtest multipathd[341]: multipathd v0.9.9: start up 577s Sep 05 19:24:45 autopkgtest multipathd[341]: reconfigure: setting up paths and maps 577s Sep 05 19:24:45 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 577s Sep 05 19:25:28 autopkgtest multipathd[341]: updated bindings file /etc/multipath/bindings 577s Sep 05 19:25:28 autopkgtest multipathd[341]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:16 1] 577s Sep 05 19:25:28 autopkgtest multipathd[341]: sdb [8:16]: path added to devmap mpatha 577s Sep 05 19:25:28 autopkgtest multipathd[341]: mpatha: performing delayed actions 577s Sep 05 19:25:28 autopkgtest multipathd[341]: 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] 577s Sep 05 19:25:47 autopkgtest multipathd[341]: 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] 577s Sep 05 19:25:47 autopkgtest multipathd[341]: check_removed_paths: sdb: freeing path in removed state 577s Sep 05 19:25:47 autopkgtest multipathd[341]: 8:16: path removed from map mpatha 577s Sep 05 19:25:57 autopkgtest multipathd[341]: 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] 577s Sep 05 19:25:57 autopkgtest multipathd[341]: check_removed_paths: sdc: freeing path in removed state 577s Sep 05 19:25:57 autopkgtest multipathd[341]: 8:32: path removed from map mpatha 577s Sep 05 19:26:07 autopkgtest multipathd[341]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 577s Sep 05 19:26:07 autopkgtest multipathd[341]: check_removed_paths: sdd: freeing path in removed state 577s Sep 05 19:26:07 autopkgtest multipathd[341]: 8:48: path removed from map mpatha 577s Sep 05 19:26:18 autopkgtest multipathd[341]: 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] 577s Sep 05 19:26:18 autopkgtest multipathd[341]: sdb [8:16]: path added to devmap mpatha 577s Sep 05 19:26:18 autopkgtest multipathd[341]: 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] 577s Sep 05 19:26:18 autopkgtest multipathd[341]: sdc [8:32]: path added to devmap mpatha 577s Sep 05 19:26:18 autopkgtest multipathd[341]: 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] 577s Sep 05 19:26:18 autopkgtest multipathd[341]: sdd [8:48]: path added to devmap mpatha 577s Sep 05 19:26:18 autopkgtest multipathd[341]: 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] 577s Sep 05 19:26:18 autopkgtest multipathd[341]: sdf [8:80]: path added to devmap mpatha 577s Sep 05 19:26:28 autopkgtest multipathd[341]: 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] 577s Sep 05 19:26:28 autopkgtest multipathd[341]: check_removed_paths: sde: freeing path in removed state 577s Sep 05 19:26:28 autopkgtest multipathd[341]: 8:64: path removed from map mpatha 577s Sep 05 19:26:28 autopkgtest multipathd[341]: 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] 577s Sep 05 19:26:28 autopkgtest multipathd[341]: check_removed_paths: sdd: freeing path in removed state 577s Sep 05 19:26:28 autopkgtest multipathd[341]: 8:48: path removed from map mpatha 577s Sep 05 19:26:28 autopkgtest multipathd[341]: 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] 577s Sep 05 19:26:28 autopkgtest multipathd[341]: check_removed_paths: sdf: freeing path in removed state 577s Sep 05 19:26:28 autopkgtest multipathd[341]: 8:80: path removed from map mpatha 577s Sep 05 19:26:38 autopkgtest multipathd[341]: multipathd: shut down 577s Sep 05 19:26:38 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 577s Sep 05 19:26:38 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 577s Sep 05 19:26:38 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 577s Sep 05 19:26:38 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 577s Sep 05 19:26:38 autopkgtest multipathd[6420]: multipathd v0.9.9: start up 577s Sep 05 19:26:38 autopkgtest multipathd[6420]: reconfigure: setting up paths and maps 577s Sep 05 19:26:38 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 577s Check final path status 577s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 577s size=100M features='0' hwhandler='0' wp=rw 577s |-+- policy='service-time 0' prio=1 status=active 577s | `- 1:0:0:1 sdb 8:16 active ready running 577s `-+- policy='service-time 0' prio=1 status=enabled 577s `- 2:0:0:1 sdc 8:32 active ready running 577s + sync 577s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 577s + echo Final stats 577s + iscsiadm --mode session --stats 577s + journalctl --no-pager -u multipathd 577s + echo Check final path status 577s + multipath -ll 577s + multipath -ll 577s + grep --count status= 577s + diskc=2 577s + multipath -ll 577s + grep --count status=active 577s + diska=1 577s + multipath -ll 577s + grep --count status=enabled 577s OK 577s + diske=1 577s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 577s + echo OK 577s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 577s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 577s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 577s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 577s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 577s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 577s autopkgtest [19:28:38]: test tgtbasedmpaths: -----------------------] 578s autopkgtest [19:28:39]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 578s tgtbasedmpaths PASS 578s autopkgtest [19:28:39]: @@@@@@@@@@@@@@@@@@@@ summary 578s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 578s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 578s kpartx-file-loopback PASS 578s tgtbasedmpaths PASS 593s nova [W] Using flock in scalingstack-bos01-ppc64el 593s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240905-191900-juju-7f2275-prod-proposed-migration-environment-3-1e659f0f-4d61-4447-a458-1ad2e7248ef8 from image adt/ubuntu-oracular-ppc64el-server-20240905.img (UUID 4af778cb-bb33-43ce-9fef-0e9ee84d73e0)... 593s nova [W] Using flock in scalingstack-bos01-ppc64el 593s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240905-191900-juju-7f2275-prod-proposed-migration-environment-3-1e659f0f-4d61-4447-a458-1ad2e7248ef8 from image adt/ubuntu-oracular-ppc64el-server-20240905.img (UUID 4af778cb-bb33-43ce-9fef-0e9ee84d73e0)...