0s autopkgtest [18:10:25]: starting date and time: 2024-07-19 18:10:25+0000 0s autopkgtest [18:10:25]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [18:10:25]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.wohgwbcs/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-1ubuntu1 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos02-ppc64el-13.secgroup --name adt-oracular-ppc64el-multipath-tools-20240719-181024-juju-7f2275-prod-proposed-migration-environment-3-67678cb5-a0f6-4962-8b45-754a68dce57f --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://ftpmaster.internal/ubuntu/ 90s autopkgtest [18:11:55]: testbed dpkg architecture: ppc64el 90s autopkgtest [18:11:55]: testbed apt version: 2.9.6 90s autopkgtest [18:11:55]: @@@@@@@@@@@@@@@@@@@@ test bed setup 96s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 96s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.7 kB] 96s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [372 kB] 97s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3232 B] 97s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 97s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [73.6 kB] 97s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2116 B] 97s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 97s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 97s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [376 kB] 97s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [8952 B] 97s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1840 B] 97s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 98s Fetched 1027 kB in 6s (178 kB/s) 98s Reading package lists... 101s Reading package lists... 101s Building dependency tree... 101s Reading state information... 101s Calculating upgrade... 101s The following packages will be upgraded: 101s dash kpartx libudisks2-0 libxml2 multipath-tools udisks2 101s 6 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 101s Need to get 1749 kB of archives. 101s After this operation, 421 kB disk space will be freed. 101s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el dash ppc64el 0.5.12-9ubuntu1 [108 kB] 101s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libxml2 ppc64el 2.12.7+dfsg-3 [728 kB] 102s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el udisks2 ppc64el 2.10.1-9ubuntu1 [342 kB] 102s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el libudisks2-0 ppc64el 2.10.1-9ubuntu1 [181 kB] 102s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el kpartx ppc64el 0.9.9-1ubuntu1 [37.1 kB] 102s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el multipath-tools ppc64el 0.9.9-1ubuntu1 [352 kB] 102s Fetched 1749 kB in 1s (2487 kB/s) 102s (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 ... 72754 files and directories currently installed.) 102s Preparing to unpack .../dash_0.5.12-9ubuntu1_ppc64el.deb ... 102s Unpacking dash (0.5.12-9ubuntu1) over (0.5.12-6ubuntu5) ... 102s Setting up dash (0.5.12-9ubuntu1) ... 102s (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 ... 72754 files and directories currently installed.) 102s Preparing to unpack .../libxml2_2.12.7+dfsg-3_ppc64el.deb ... 102s Unpacking libxml2:ppc64el (2.12.7+dfsg-3) over (2.9.14+dfsg-1.3ubuntu3) ... 102s Preparing to unpack .../udisks2_2.10.1-9ubuntu1_ppc64el.deb ... 102s Unpacking udisks2 (2.10.1-9ubuntu1) over (2.10.1-9) ... 102s Preparing to unpack .../libudisks2-0_2.10.1-9ubuntu1_ppc64el.deb ... 102s Unpacking libudisks2-0:ppc64el (2.10.1-9ubuntu1) over (2.10.1-9) ... 102s Preparing to unpack .../kpartx_0.9.9-1ubuntu1_ppc64el.deb ... 102s Unpacking kpartx (0.9.9-1ubuntu1) over (0.9.4-5ubuntu8) ... 102s Preparing to unpack .../multipath-tools_0.9.9-1ubuntu1_ppc64el.deb ... 102s Unpacking multipath-tools (0.9.9-1ubuntu1) over (0.9.4-5ubuntu8) ... 102s dpkg: warning: unable to delete old directory '/lib/multipath': Directory not empty 102s Setting up kpartx (0.9.9-1ubuntu1) ... 102s Setting up libxml2:ppc64el (2.12.7+dfsg-3) ... 102s Setting up libudisks2-0:ppc64el (2.10.1-9ubuntu1) ... 102s Setting up udisks2 (2.10.1-9ubuntu1) ... 103s Setting up multipath-tools (0.9.9-1ubuntu1) ... 103s Processing triggers for debianutils (5.20) ... 103s Processing triggers for libc-bin (2.39-0ubuntu9) ... 103s Processing triggers for man-db (2.12.1-2) ... 105s Processing triggers for dbus (1.14.10-4ubuntu4) ... 105s Reading package lists... 105s Building dependency tree... 105s Reading state information... 105s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 105s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 105s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 105s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 106s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 106s Reading package lists... 106s Reading package lists... 107s Building dependency tree... 107s Reading state information... 107s Calculating upgrade... 107s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 107s Reading package lists... 107s Building dependency tree... 107s Reading state information... 107s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 108s autopkgtest [18:12:13]: rebooting testbed after setup commands that affected boot 141s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 152s autopkgtest [18:12:57]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 155s autopkgtest [18:13:00]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 158s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main multipath-tools 0.9.9-1ubuntu1 (dsc) [2772 B] 158s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main multipath-tools 0.9.9-1ubuntu1 (tar) [588 kB] 158s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main multipath-tools 0.9.9-1ubuntu1 (diff) [42.6 kB] 158s gpgv: Signature made Fri Jul 19 16:08:28 2024 UTC 158s gpgv: using RSA key 92978A6E195E4921825F7FF0F34F09744E9F5DD9 158s gpgv: Can't check signature: No public key 158s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.9-1ubuntu1.dsc: no acceptable signature found 158s autopkgtest [18:13:03]: testing package multipath-tools version 0.9.9-1ubuntu1 158s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 158s autopkgtest [18:13:03]: build not needed 159s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 159s autopkgtest [18:13:04]: test kpartx-file-loopback: preparing testbed 160s Reading package lists... 160s Building dependency tree... 160s Reading state information... 160s Starting pkgProblemResolver with broken count: 0 160s Starting 2 pkgProblemResolver with broken count: 0 160s Done 160s The following additional packages will be installed: 160s liburing2 qemu-utils 160s Recommended packages: 160s qemu-block-extra 160s The following NEW packages will be installed: 160s autopkgtest-satdep liburing2 qemu-utils 160s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 160s Need to get 2330 kB/2331 kB of archives. 160s After this operation, 15.4 MB of additional disk space will be used. 160s Get:1 /tmp/autopkgtest.8AodB3/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 161s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 161s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 161s Fetched 2330 kB in 1s (3391 kB/s) 161s Selecting previously unselected package liburing2:ppc64el. 162s (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 ... 72754 files and directories currently installed.) 162s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 162s Unpacking liburing2:ppc64el (2.6-1) ... 162s Selecting previously unselected package qemu-utils. 162s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 162s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 162s Selecting previously unselected package autopkgtest-satdep. 162s Preparing to unpack .../1-autopkgtest-satdep.deb ... 162s Unpacking autopkgtest-satdep (0) ... 162s Setting up liburing2:ppc64el (2.6-1) ... 162s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 162s Setting up autopkgtest-satdep (0) ... 162s Processing triggers for man-db (2.12.1-2) ... 163s Processing triggers for libc-bin (2.39-0ubuntu9) ... 165s (Reading database ... 72774 files and directories currently installed.) 165s Removing autopkgtest-satdep (0) ... 166s autopkgtest [18:13:11]: test kpartx-file-loopback: [----------------------- 166s Formatting 'foo.img', fmt=raw size=20971520 167s Creating new GPT entries in memory. 167s Warning: The kernel is still using the old partition table. 167s The new table will be used at the next reboot or after you 167s run partprobe(8) or kpartx(8) 167s The operation has completed successfully. 167s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 167s standard_filename: OK 167s del devmap : loop0p1 167s No devices found 167s standard_filename_cleanup: OK 167s Formatting 'fou du FaFa.img', fmt=raw size=20971520 168s Creating new GPT entries in memory. 168s Warning: The kernel is still using the old partition table. 168s The new table will be used at the next reboot or after you 168s run partprobe(8) or kpartx(8) 168s The operation has completed successfully. 168s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 168s filename_with_spaces: OK 168s del devmap : loop0p1 168s No devices found 168s filename_with_spaces_cleanup: OK 169s autopkgtest [18:13:14]: test kpartx-file-loopback: -----------------------] 169s autopkgtest [18:13:14]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 169s kpartx-file-loopback PASS 169s autopkgtest [18:13:14]: test tgtbasedmpaths: preparing testbed 253s autopkgtest [18:14:38]: testbed dpkg architecture: ppc64el 253s autopkgtest [18:14:38]: testbed apt version: 2.9.6 253s autopkgtest [18:14:38]: @@@@@@@@@@@@@@@@@@@@ test bed setup 254s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 254s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.7 kB] 254s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3232 B] 254s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [372 kB] 254s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 254s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [73.6 kB] 254s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2116 B] 254s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 254s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 254s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [376 kB] 254s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [8952 B] 254s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1840 B] 254s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 256s Fetched 1027 kB in 1s (1293 kB/s) 256s Reading package lists... 258s Reading package lists... 258s Building dependency tree... 258s Reading state information... 258s Calculating upgrade... 258s The following packages will be upgraded: 258s dash kpartx libudisks2-0 libxml2 multipath-tools udisks2 259s 6 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 259s Need to get 1749 kB of archives. 259s After this operation, 421 kB disk space will be freed. 259s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el dash ppc64el 0.5.12-9ubuntu1 [108 kB] 259s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libxml2 ppc64el 2.12.7+dfsg-3 [728 kB] 259s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el udisks2 ppc64el 2.10.1-9ubuntu1 [342 kB] 259s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el libudisks2-0 ppc64el 2.10.1-9ubuntu1 [181 kB] 259s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el kpartx ppc64el 0.9.9-1ubuntu1 [37.1 kB] 259s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el multipath-tools ppc64el 0.9.9-1ubuntu1 [352 kB] 259s Fetched 1749 kB in 1s (2647 kB/s) 260s (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 ... 72754 files and directories currently installed.) 260s Preparing to unpack .../dash_0.5.12-9ubuntu1_ppc64el.deb ... 260s Unpacking dash (0.5.12-9ubuntu1) over (0.5.12-6ubuntu5) ... 260s Setting up dash (0.5.12-9ubuntu1) ... 260s (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 ... 72754 files and directories currently installed.) 260s Preparing to unpack .../libxml2_2.12.7+dfsg-3_ppc64el.deb ... 260s Unpacking libxml2:ppc64el (2.12.7+dfsg-3) over (2.9.14+dfsg-1.3ubuntu3) ... 260s Preparing to unpack .../udisks2_2.10.1-9ubuntu1_ppc64el.deb ... 260s Unpacking udisks2 (2.10.1-9ubuntu1) over (2.10.1-9) ... 260s Preparing to unpack .../libudisks2-0_2.10.1-9ubuntu1_ppc64el.deb ... 260s Unpacking libudisks2-0:ppc64el (2.10.1-9ubuntu1) over (2.10.1-9) ... 260s Preparing to unpack .../kpartx_0.9.9-1ubuntu1_ppc64el.deb ... 260s Unpacking kpartx (0.9.9-1ubuntu1) over (0.9.4-5ubuntu8) ... 260s Preparing to unpack .../multipath-tools_0.9.9-1ubuntu1_ppc64el.deb ... 260s Unpacking multipath-tools (0.9.9-1ubuntu1) over (0.9.4-5ubuntu8) ... 260s dpkg: warning: unable to delete old directory '/lib/multipath': Directory not empty 260s Setting up kpartx (0.9.9-1ubuntu1) ... 260s Setting up libxml2:ppc64el (2.12.7+dfsg-3) ... 260s Setting up libudisks2-0:ppc64el (2.10.1-9ubuntu1) ... 260s Setting up udisks2 (2.10.1-9ubuntu1) ... 260s Setting up multipath-tools (0.9.9-1ubuntu1) ... 261s Processing triggers for debianutils (5.20) ... 261s Processing triggers for libc-bin (2.39-0ubuntu9) ... 261s Processing triggers for man-db (2.12.1-2) ... 263s Processing triggers for dbus (1.14.10-4ubuntu4) ... 263s Reading package lists... 263s Building dependency tree... 263s Reading state information... 263s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 263s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 263s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 264s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 264s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 264s Reading package lists... 264s Reading package lists... 265s Building dependency tree... 265s Reading state information... 265s Calculating upgrade... 265s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 265s Reading package lists... 265s Building dependency tree... 265s Reading state information... 265s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 265s autopkgtest [18:14:50]: rebooting testbed after setup commands that affected boot 299s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 311s Reading package lists... 312s Building dependency tree... 312s Reading state information... 312s Starting pkgProblemResolver with broken count: 0 312s Starting 2 pkgProblemResolver with broken count: 0 312s Done 312s The following additional packages will be installed: 312s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 312s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 312s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 312s librdmacm1t64 lsscsi open-iscsi tgt 312s Suggested packages: 312s fio-examples gnuplot tgt-glusterfs tgt-rbd 312s Recommended packages: 312s finalrd 312s The following NEW packages will be installed: 312s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 312s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 312s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 312s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 312s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 312s Need to get 10.7 MB/10.7 MB of archives. 312s After this operation, 49.0 MB of additional disk space will be used. 312s Get:1 /tmp/autopkgtest.8AodB3/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 312s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 312s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 312s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 313s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2 [80.5 kB] 313s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 313s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 313s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4ubuntu1 [21.5 kB] 313s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4ubuntu1 [311 kB] 313s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4ubuntu1 [46.5 kB] 313s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4ubuntu1 [99.2 kB] 313s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-1 [97.4 kB] 313s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 313s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 313s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 313s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 313s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 313s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 313s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 313s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 313s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 313s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 313s Preconfiguring packages ... 313s Fetched 10.7 MB in 1s (11.7 MB/s) 313s Selecting previously unselected package libopeniscsiusr. 314s (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 ... 72754 files and directories currently installed.) 314s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 314s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 314s Selecting previously unselected package libisns0t64:ppc64el. 314s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 314s Unpacking libisns0t64:ppc64el (0.101-1) ... 314s Selecting previously unselected package open-iscsi. 314s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 314s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 314s Selecting previously unselected package librdmacm1t64:ppc64el. 314s Preparing to unpack .../03-librdmacm1t64_52.0-2_ppc64el.deb ... 314s Unpacking librdmacm1t64:ppc64el (52.0-2) ... 314s Selecting previously unselected package libconfig-general-perl. 314s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 314s Unpacking libconfig-general-perl (2.65-2) ... 314s Selecting previously unselected package tgt. 314s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 314s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 314s Selecting previously unselected package libgfxdr0:ppc64el. 314s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_ppc64el.deb ... 314s Unpacking libgfxdr0:ppc64el (11.1-4ubuntu1) ... 314s Selecting previously unselected package libglusterfs0:ppc64el. 314s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_ppc64el.deb ... 314s Unpacking libglusterfs0:ppc64el (11.1-4ubuntu1) ... 314s Selecting previously unselected package libgfrpc0:ppc64el. 314s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_ppc64el.deb ... 314s Unpacking libgfrpc0:ppc64el (11.1-4ubuntu1) ... 314s Selecting previously unselected package libgfapi0:ppc64el. 314s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_ppc64el.deb ... 314s Unpacking libgfapi0:ppc64el (11.1-4ubuntu1) ... 314s Selecting previously unselected package libnbd0. 314s Preparing to unpack .../10-libnbd0_1.20.2-1_ppc64el.deb ... 314s Unpacking libnbd0 (1.20.2-1) ... 314s Selecting previously unselected package libdaxctl1:ppc64el. 314s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 314s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 314s Selecting previously unselected package libndctl6:ppc64el. 314s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 314s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 314s Selecting previously unselected package libpmem1:ppc64el. 314s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 314s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 314s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 314s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 314s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 314s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 314s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 314s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 314s Selecting previously unselected package librados2. 314s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 314s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 314s Selecting previously unselected package libpmemobj1:ppc64el. 314s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 314s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 314s Selecting previously unselected package librbd1. 314s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 314s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 314s Selecting previously unselected package fio. 314s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 314s Unpacking fio (3.37-1) ... 314s Selecting previously unselected package lsscsi. 314s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 314s Unpacking lsscsi (0.32-1build1) ... 314s Selecting previously unselected package autopkgtest-satdep. 314s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 314s Unpacking autopkgtest-satdep (0) ... 314s Setting up libconfig-general-perl (2.65-2) ... 314s Setting up libisns0t64:ppc64el (0.101-1) ... 314s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 314s Setting up libnbd0 (1.20.2-1) ... 314s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 314s Setting up libglusterfs0:ppc64el (11.1-4ubuntu1) ... 314s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 314s Setting up lsscsi (0.32-1build1) ... 314s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 314s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 314s Setting up librdmacm1t64:ppc64el (52.0-2) ... 314s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 315s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 315s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 315s Setting up libgfxdr0:ppc64el (11.1-4ubuntu1) ... 315s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 315s Setting up open-iscsi (2.1.10-1ubuntu1) ... 316s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 316s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 316s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 317s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 317s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 317s Setting up libgfrpc0:ppc64el (11.1-4ubuntu1) ... 317s Setting up libgfapi0:ppc64el (11.1-4ubuntu1) ... 317s Setting up fio (3.37-1) ... 317s Setting up autopkgtest-satdep (0) ... 317s Processing triggers for man-db (2.12.1-2) ... 318s Processing triggers for initramfs-tools (0.142ubuntu30) ... 319s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 319s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 326s Processing triggers for libc-bin (2.39-0ubuntu9) ... 329s (Reading database ... 72995 files and directories currently installed.) 329s Removing autopkgtest-satdep (0) ... 330s autopkgtest [18:15:55]: test tgtbasedmpaths: [----------------------- 331s + targetname=iqn.2016-11.foo.com:target.iscsi 331s + pwd 331s + cwd=/tmp/autopkgtest.8AodB3/build.xw7/src 331s + testdir=/mnt/tgtmpathtest 331s + localhost=127.0.0.1 331s + portal=127.0.0.1:3260 331s + maxpaths=4 331s + backfn=backingfile 331s + expectwwid=60000000000000000e00000000010001 331s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 331s + bglog=/tmp/autopkgtest.8AodB3/tgtbasedmpaths-artifacts/test-background.log 331s + fioprep=/tmp/autopkgtest.8AodB3/tgtbasedmpaths-artifacts/path-change-prep.fio 331s + fiovrfy=/tmp/autopkgtest.8AodB3/tgtbasedmpaths-artifacts/path-change-check.fio 331s + mkdir -p /etc/multipath 331s + echo /360000000000000000e00000000010001/ 331s + service tgt restart 331s + truncate --size 100M backingfile 331s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 331s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 331s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.8AodB3/build.xw7/src/backingfile 331s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 331s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 331s login #1 331s + echo login #1 331s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 331s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 331s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 331s + seq 2 4 331s extra login #2 331s + echo extra login #2 331s + iscsiadm --mode session -r 1 --op new 331s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 331s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 331s extra login #3 331s + echo extra login #3 331s + iscsiadm --mode session -r 1 --op new 331s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 331s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 331s + echo extra login #4 331s + iscsiadm --mode session -r 1 --op new 331s extra login #4 331s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 331s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 331s + udevadm settle 331s + sleep 5 336s Status after initial setup 336s Target 1: iqn.2016-11.foo.com:target.iscsi 336s System information: 336s Driver: iscsi 336s State: ready 336s I_T nexus information: 336s I_T nexus: 1 336s Initiator: iqn.2004-10.com.ubuntu:01:eb907d4c1cc4 alias: autopkgtest 336s Connection: 0 336s IP Address: 127.0.0.1 336s I_T nexus: 2 336s Initiator: iqn.2004-10.com.ubuntu:01:eb907d4c1cc4 alias: autopkgtest 336s Connection: 0 336s IP Address: 127.0.0.1 336s I_T nexus: 3 336s Initiator: iqn.2004-10.com.ubuntu:01:eb907d4c1cc4 alias: autopkgtest 336s Connection: 0 336s IP Address: 127.0.0.1 336s I_T nexus: 4 336s Initiator: iqn.2004-10.com.ubuntu:01:eb907d4c1cc4 alias: autopkgtest 336s Connection: 0 336s IP Address: 127.0.0.1 336s LUN information: 336s LUN: 0 336s Type: controller 336s SCSI ID: IET 00010000 336s SCSI SN: beaf10 336s Size: 0 MB, Block size: 1 336s Online: Yes 336s Removable media: No 336s Prevent removal: No 336s Readonly: No 336s SWP: No 336s Thin-provisioning: No 336s Backing store type: null 336s Backing store path: None 336s Backing store flags: 336s LUN: 1 336s Type: disk 336s SCSI ID: IET 00010001 336s SCSI SN: beaf11 336s Size: 105 MB, Block size: 512 336s Online: Yes 336s Removable media: No 336s Prevent removal: No 336s Readonly: No 336s SWP: No 336s Thin-provisioning: No 336s Backing store type: rdwr 336s Backing store path: /tmp/autopkgtest.8AodB3/build.xw7/src/backingfile 336s Backing store flags: 336s Account information: 336s ACL information: 336s ALL 336s + echo Status after initial setup 336s + tgtadm --lld iscsi --mode target --op show 336s Session: 4 336s Connection: 0 336s Initiator: iqn.2004-10.com.ubuntu:01:eb907d4c1cc4 336s IP Address: 127.0.0.1 336s Session: 3 336s Connection: 0 336s Initiator: iqn.2004-10.com.ubuntu:01:eb907d4c1cc4 336s IP Address: 127.0.0.1 336s Session: 2 336s Connection: 0 336s Initiator: iqn.2004-10.com.ubuntu:01:eb907d4c1cc4 336s IP Address: 127.0.0.1 336s Session: 1 336s Connection: 0 336s Initiator: iqn.2004-10.com.ubuntu:01:eb907d4c1cc4 336s IP Address: 127.0.0.1 336s + tgtadm --lld iscsi --op show --mode conn --tid 1 336s + iscsiadm --mode session -P 1 336s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 336s Current Portal: 127.0.0.1:3260,1 336s Persistent Portal: 127.0.0.1:3260,1 336s ********** 336s Interface: 336s ********** 336s Iface Name: default 336s Iface Transport: tcp 336s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:eb907d4c1cc4 336s Iface IPaddress: 127.0.0.1 336s Iface HWaddress: default 336s Iface Netdev: default 336s SID: 1 336s iSCSI Connection State: LOGGED IN 336s iSCSI Session State: LOGGED_IN 336s Internal iscsid Session State: NO CHANGE 336s 336s ********** 336s Interface: 336s ********** 336s Iface Name: default 336s Iface Transport: tcp 336s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:eb907d4c1cc4 336s Iface IPaddress: 127.0.0.1 336s Iface HWaddress: default 336s Iface Netdev: default 336s SID: 2 336s iSCSI Connection State: LOGGED IN 336s iSCSI Session State: LOGGED_IN 336s Internal iscsid Session State: NO CHANGE 336s 336s ********** 336s Interface: 336s ********** 336s Iface Name: default 336s Iface Transport: tcp 336s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:eb907d4c1cc4 336s Iface IPaddress: 127.0.0.1 336s Iface HWaddress: default 336s Iface Netdev: default 336s SID: 3 336s iSCSI Connection State: LOGGED IN 336s iSCSI Session State: LOGGED_IN 336s Internal iscsid Session State: NO CHANGE 336s 336s ********** 336s Interface: 336s ********** 336s Iface Name: default 336s Iface Transport: tcp 336s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:eb907d4c1cc4 336s Iface IPaddress: 127.0.0.1 336s Iface HWaddress: default 336s Iface Netdev: default 336s SID: 4 336s iSCSI Connection State: LOGGED IN 336s iSCSI Session State: LOGGED_IN 336s Internal iscsid Session State: NO CHANGE 336s + lsscsi -liv 336s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 336s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 336s 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] 336s [1:0:0:0] storage IET Controller 0001 - - 336s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 336s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 336s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 336s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 336s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 336s [2:0:0:0] storage IET Controller 0001 - - 336s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 336s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 336s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 336s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 336s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 336s [3:0:0:0] storage IET Controller 0001 - - 336s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 336s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 336s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 336s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 336s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 336s [4:0:0:0] storage IET Controller 0001 - - 336s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 336s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 336s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 33000000100000001 336s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 336s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 336s NVMe module may not be loaded 336s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 336s + multipath -v3 -ll 336s 45.775985 | set open fds limit to 1073741816/1073741816 336s 45.776048 | _read_bindings_file: reading /etc/multipath/bindings 336s 45.776117 | loading /usr/lib/multipath/libchecktur.so checker 336s 45.776212 | checker tur: message table size = 4 336s 45.776270 | loading /usr/lib/multipath/libprioconst.so prioritizer 336s 45.776383 | _init_foreign: foreign library "nvme" is not enabled 336s 45.781819 | sda: size = 167772160 336s 45.781984 | sda: vendor = QEMU 336s 45.782025 | sda: product = QEMU HARDDISK 336s 45.782047 | sda: rev = 2.5+ 336s 45.782653 | sda: h:b:t:l = 0:0:0:0 336s 45.782969 | sda: tgt_node_name = 336s 45.782990 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 336s 45.782992 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 336s 45.783139 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 336s 45.783160 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 336s 45.783171 | __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 336s 45.783175 | failed to read sysfs vpd pg80: No such file or directory 336s 45.783410 | sda: fail to get serial 336s 45.783430 | sda: detect_checker = yes (setting: multipath internal) 336s 45.783463 | sda checker timeout = 30 s (setting: kernel sysfs) 336s 45.783647 | sda: path_checker = tur (setting: multipath internal) 336s 45.783816 | sda: tur state = up 336s 45.784134 | sdb: size = 204800 336s 45.784287 | sdb: vendor = IET 336s 45.784328 | sdb: product = VIRTUAL-DISK 336s 45.784349 | sdb: rev = 0001 336s 45.784979 | sdb: h:b:t:l = 1:0:0:1 336s 45.785342 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 336s 45.785362 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 336s 45.785365 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 336s 45.785517 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 336s 45.785537 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 336s 45.785551 | sdb: serial = beaf11 336s 45.785554 | sdb: detect_checker = yes (setting: multipath internal) 336s 45.785581 | sdb checker timeout = 30 s (setting: kernel sysfs) 336s 45.785824 | sdb: path_checker = tur (setting: multipath internal) 336s 45.786025 | sdb: tur state = up 336s 45.786165 | sdc: size = 204800 336s 45.786312 | sdc: vendor = IET 336s 45.786351 | sdc: product = VIRTUAL-DISK 336s 45.786372 | sdc: rev = 0001 336s 45.787041 | sdc: h:b:t:l = 2:0:0:1 336s 45.787398 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 336s 45.787418 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 336s 45.787420 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 336s 45.787566 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 336s 45.787586 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 336s 45.787600 | sdc: serial = beaf11 336s 45.787602 | sdc: detect_checker = yes (setting: multipath internal) 336s 45.787629 | sdc checker timeout = 30 s (setting: kernel sysfs) 336s 45.787814 | sdc: path_checker = tur (setting: multipath internal) 336s 45.787907 | sdc: tur state = up 336s 45.788039 | sdd: size = 204800 336s 45.788175 | sdd: vendor = IET 336s 45.788215 | sdd: product = VIRTUAL-DISK 336s 45.788236 | sdd: rev = 0001 336s 45.788933 | sdd: h:b:t:l = 3:0:0:1 336s 45.789289 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 336s 45.789309 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 336s 45.789312 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 336s 45.789462 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 336s 45.789482 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 336s 45.789496 | sdd: serial = beaf11 336s 45.789498 | sdd: detect_checker = yes (setting: multipath internal) 336s 45.789533 | sdd checker timeout = 30 s (setting: kernel sysfs) 336s 45.789712 | sdd: path_checker = tur (setting: multipath internal) 336s 45.789905 | sdd: tur state = up 336s 45.790047 | sde: size = 204800 336s 45.790195 | sde: vendor = IET 336s 45.790234 | sde: product = VIRTUAL-DISK 336s 45.790254 | sde: rev = 0001 336s 45.790925 | sde: h:b:t:l = 4:0:0:1 336s 45.791282 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 336s 45.791302 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 336s 45.791305 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 336s 45.791446 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 336s 45.791466 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 336s 45.791480 | sde: serial = beaf11 336s 45.791482 | sde: detect_checker = yes (setting: multipath internal) 336s 45.791509 | sde checker timeout = 30 s (setting: kernel sysfs) 336s 45.791683 | sde: path_checker = tur (setting: multipath internal) 336s 45.791843 | sde: tur state = up 336s 45.791949 | loop0: device node name blacklisted 336s 45.792094 | loop1: device node name blacklisted 336s 45.792201 | loop2: device node name blacklisted 336s 45.792301 | loop3: device node name blacklisted 336s 45.792401 | loop4: device node name blacklisted 336s 45.792498 | loop5: device node name blacklisted 336s 45.792597 | loop6: device node name blacklisted 336s 45.792694 | loop7: device node name blacklisted 336s 45.792813 | dm-0: device node name blacklisted 336s 45.793936 | multipath-tools v0.9.9 (05/03, 2024) 336s 45.793963 | libdevmapper version 1.02.185 336s 45.794096 | kernel device mapper v4.48.0 336s 45.794124 | DM multipath kernel driver v1.14.0 336s 45.794225 | sdb: size = 204800 336s 45.794247 | sdb: vendor = IET 336s 45.794249 | sdb: product = VIRTUAL-DISK 336s 45.794252 | sdb: rev = 0001 336s 45.794870 | sdb: h:b:t:l = 1:0:0:1 336s 45.794999 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 336s 45.795035 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 336s 45.795038 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 336s 45.795049 | sdb: serial = beaf11 336s 45.795227 | sdb: tur state = up 336s 45.795247 | sdb: uid = 360000000000000000e00000000010001 (udev) 336s 45.795250 | sdb: detect_prio = yes (setting: multipath internal) 336s 45.795253 | sdb: prio = const (setting: multipath internal) 336s 45.795255 | sdb: prio args = "" (setting: multipath internal) 336s 45.795257 | sdb: const prio = 1 336s 45.795279 | sdc: size = 204800 336s 45.795283 | sdc: vendor = IET 336s 45.795286 | sdc: product = VIRTUAL-DISK 336s 45.795288 | sdc: rev = 0001 336s 45.795894 | sdc: h:b:t:l = 2:0:0:1 336s 45.796058 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 336s 45.796098 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 336s 45.796100 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 336s 45.796112 | sdc: serial = beaf11 336s 45.796269 | sdc: tur state = up 336s 45.796289 | sdc: uid = 360000000000000000e00000000010001 (udev) 336s 45.796291 | sdc: detect_prio = yes (setting: multipath internal) 336s 45.796293 | sdc: prio = const (setting: multipath internal) 336s 45.796295 | sdc: prio args = "" (setting: multipath internal) 336s 45.796298 | sdc: const prio = 1 336s 45.796320 | sdd: size = 204800 336s 45.796323 | sdd: vendor = IET 336s 45.796326 | sdd: product = VIRTUAL-DISK 336s 45.796329 | sdd: rev = 0001 336s 45.796945 | sdd: h:b:t:l = 3:0:0:1 336s 45.797074 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 336s 45.797110 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 336s 45.797113 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 336s 45.797124 | sdd: serial = beaf11 336s 45.797272 | sdd: tur state = up 336s 45.797292 | sdd: uid = 360000000000000000e00000000010001 (udev) 336s 45.797294 | sdd: detect_prio = yes (setting: multipath internal) 336s 45.797296 | sdd: prio = const (setting: multipath internal) 336s 45.797299 | sdd: prio args = "" (setting: multipath internal) 336s 45.797301 | sdd: const prio = 1 336s 45.797322 | sde: size = 204800 336s 45.797326 | sde: vendor = IET 336s 45.797328 | sde: product = VIRTUAL-DISK 336s 45.797331 | sde: rev = 0001 336s 45.797936 | sde: h:b:t:l = 4:0:0:1 336s 45.798062 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 336s 45.798098 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 336s 45.798101 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 336s 45.798112 | sde: serial = beaf11 336s 45.798257 | sde: tur state = up 336s 45.798277 | sde: uid = 360000000000000000e00000000010001 (udev) 336s 45.798279 | sde: detect_prio = yes (setting: multipath internal) 336s 45.798281 | sde: prio = const (setting: multipath internal) 336s 45.798283 | sde: prio args = "" (setting: multipath internal) 336s 45.798286 | sde: const prio = 1 336s 45.799154 | unloading tur checker 336s 45.799203 | unloading const prioritizer 336s ===== paths list ===== 336s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 336s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK,2.5+ unknown 336s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 336s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 336s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 336s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 336s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 336s size=100M features='0' hwhandler='0' wp=rw 336s |-+- policy='service-time 0' prio=1 status=active 336s | `- 1:0:0:1 sdb 8:16 active ready running 336s |-+- policy='service-time 0' prio=1 status=enabled 336s | `- 2:0:0:1 sdc 8:32 active ready running 336s |-+- policy='service-time 0' prio=1 status=enabled 336s | `- 3:0:0:1 sdd 8:48 active ready running 336s `-+- policy='service-time 0' prio=1 status=enabled 336s `- 4:0:0:1 sde 8:64 active ready running 336s 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 336s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 336s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 336s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 336s /etc/multipath/bindings:# 336s /etc/multipath/bindings:# Format: 336s /etc/multipath/bindings:# alias wwid 336s /etc/multipath/bindings:# 336s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 336s /etc/multipath/wwids:/360000000000000000e00000000010001/ 336s ● multipathd.service - Device-Mapper Multipath Device Controller 336s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 336s Active: active (running) since Fri 2024-07-19 18:15:18 UTC; 43s ago 336s Invocation: d9bc4a9670b841cbaeb083b91d4d6586 336s TriggeredBy: ● multipathd.socket 336s Main PID: 343 (multipathd) 336s Status: "up" 336s Tasks: 7 336s Memory: 32.3M (peak: 34.8M) 336s CPU: 58ms 336s CGroup: /system.slice/multipathd.service 336s └─343 /sbin/multipathd -d -s 336s 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 336s Jul 19 18:15:18 autopkgtest multipathd[343]: multipathd v0.9.9: start up 336s Jul 19 18:15:18 autopkgtest multipathd[343]: reconfigure: setting up paths and maps 336s Jul 19 18:15:18 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 336s Jul 19 18:15:55 autopkgtest multipathd[343]: updated bindings file /etc/multipath/bindings 336s Jul 19 18:15:55 autopkgtest multipathd[343]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:16 1] 336s Jul 19 18:15:55 autopkgtest multipathd[343]: sdb [8:16]: path added to devmap mpatha 336s Jul 19 18:15:55 autopkgtest multipathd[343]: mpatha: performing delayed actions 336s Jul 19 18:15:55 autopkgtest multipathd[343]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 336s ● multipathd.socket - multipathd control socket 336s Loaded: loaded (/usr/lib/systemd/system/multipathd.socket; enabled; preset: enabled) 336s Active: active (running) since Fri 2024-07-19 18:15:18 UTC; 43s ago 336s Invocation: 912f90dd0fd844008f488ec5ab040de8 336s Triggers: ● multipathd.service 336s Listen: @/org/kernel/linux/storage/multipathd (Stream) 336s CGroup: /system.slice/multipathd.socket 336s 336s Notice: journal has been rotated since unit was started, output may be incomplete. 336s total 0 336s drwxr-xr-x 2 root root 80 Jul 19 18:15 . 336s drwxr-xr-x 18 root root 4260 Jul 19 18:15 .. 336s crw------- 1 root root 10, 236 Jul 19 18:15 control 336s lrwxrwxrwx 1 root root 7 Jul 19 18:15 mpatha -> ../dm-0 336s journal 336s + dmsetup table 336s + grep . /etc/multipath/bindings /etc/multipath/wwids 336s + systemctl status multipathd.service 336s + systemctl status multipathd.socket 336s + ls -la /dev/mapper/ 336s + echo journal 336s + journalctl -b 336s Jul 19 18:15:15 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 336s Jul 19 18:15:15 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 336s Jul 19 18:15:15 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 336s Jul 19 18:15:15 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 336s Jul 19 18:15:15 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 336s Jul 19 18:15:15 autopkgtest kernel: Activating Kernel Userspace Access Prevention 336s Jul 19 18:15:15 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 336s Jul 19 18:15:15 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x00000000038a0000 with 64.0 KiB pages (exec) 336s Jul 19 18:15:15 autopkgtest kernel: radix-mmu: Mapped 0x00000000038a0000-0x0000000200000000 with 64.0 KiB pages 336s Jul 19 18:15:15 autopkgtest kernel: lpar: Using radix MMU under hypervisor 336s Jul 19 18:15:15 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) 336s Jul 19 18:15:15 autopkgtest kernel: Secure boot mode disabled 336s Jul 19 18:15:15 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc0000000094ec15e 336s Jul 19 18:15:15 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (raw) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 336s Jul 19 18:15:15 autopkgtest kernel: printk: legacy bootconsole [udbg0] enabled 336s Jul 19 18:15:15 autopkgtest kernel: Partition configured for 4 cpus. 336s Jul 19 18:15:15 autopkgtest kernel: CPU maps initialized for 1 thread per core 336s Jul 19 18:15:15 autopkgtest kernel: (thread shift is 0) 336s Jul 19 18:15:15 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 336s Jul 19 18:15:15 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 336s Jul 19 18:15:15 autopkgtest kernel: ----------------------------------------------------- 336s Jul 19 18:15:15 autopkgtest kernel: phys_mem_size = 0x200000000 336s Jul 19 18:15:15 autopkgtest kernel: dcache_bsize = 0x80 336s Jul 19 18:15:15 autopkgtest kernel: icache_bsize = 0x80 336s Jul 19 18:15:15 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 336s Jul 19 18:15:15 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 336s Jul 19 18:15:15 autopkgtest kernel: always = 0x0000000380008181 336s Jul 19 18:15:15 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 336s Jul 19 18:15:15 autopkgtest kernel: mmu_features = 0x3c007641 336s Jul 19 18:15:15 autopkgtest kernel: firmware_features = 0x00000085455a445f 336s Jul 19 18:15:15 autopkgtest kernel: vmalloc start = 0xc008000000000000 336s Jul 19 18:15:15 autopkgtest kernel: IO start = 0xc00a000000000000 336s Jul 19 18:15:15 autopkgtest kernel: vmemmap start = 0xc00c000000000000 336s Jul 19 18:15:15 autopkgtest kernel: ----------------------------------------------------- 336s Jul 19 18:15:15 autopkgtest kernel: numa: NODE_DATA [mem 0x1eff10280-0x1eff17fff] 336s Jul 19 18:15:15 autopkgtest kernel: rfi-flush: fallback displacement flush available 336s Jul 19 18:15:15 autopkgtest kernel: rfi-flush: ori type flush available 336s Jul 19 18:15:15 autopkgtest kernel: rfi-flush: mttrig type flush available 336s Jul 19 18:15:15 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 336s Jul 19 18:15:15 autopkgtest kernel: count-cache-flush: software flush enabled. 336s Jul 19 18:15:15 autopkgtest kernel: link-stack-flush: software flush enabled. 336s Jul 19 18:15:15 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 336s Jul 19 18:15:15 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 336s Jul 19 18:15:15 autopkgtest kernel: stf-barrier: eieio barrier available 336s Jul 19 18:15:15 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 336s Jul 19 18:15:15 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 336s Jul 19 18:15:15 autopkgtest kernel: PPC64 nvram contains 65536 bytes 336s Jul 19 18:15:15 autopkgtest kernel: barrier-nospec: using ORI speculation barrier 336s Jul 19 18:15:15 autopkgtest kernel: barrier-nospec: patched 269 locations 336s Jul 19 18:15:15 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 336s Jul 19 18:15:15 autopkgtest kernel: Memory hole size: 0MB 336s Jul 19 18:15:15 autopkgtest kernel: Zone ranges: 336s Jul 19 18:15:15 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 336s Jul 19 18:15:15 autopkgtest kernel: Device empty 336s Jul 19 18:15:15 autopkgtest kernel: Movable zone start for each node 336s Jul 19 18:15:15 autopkgtest kernel: Early memory node ranges 336s Jul 19 18:15:15 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 336s Jul 19 18:15:15 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 336s Jul 19 18:15:15 autopkgtest kernel: percpu: Embedded 12 pages/cpu s609960 r0 d176472 u786432 336s Jul 19 18:15:15 autopkgtest kernel: pcpu-alloc: s609960 r0 d176472 u786432 alloc=12*65536 336s Jul 19 18:15:15 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 336s Jul 19 18:15:15 autopkgtest kernel: Kernel command line: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic root=UUID=a7a7eb95-072e-451f-aab9-f64fe5535e24 ro console=hvc0 earlyprintk 336s Jul 19 18:15:15 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic", will be passed to user space. 336s Jul 19 18:15:15 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 336s Jul 19 18:15:15 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 336s Jul 19 18:15:15 autopkgtest kernel: Fallback order for Node 0: 0 336s Jul 19 18:15:15 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 130944 336s Jul 19 18:15:15 autopkgtest kernel: Policy zone: Normal 336s Jul 19 18:15:15 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 336s Jul 19 18:15:15 autopkgtest kernel: Memory: 7968128K/8388608K available (23680K kernel code, 4096K rwdata, 25472K rodata, 8832K init, 1901K bss, 420480K reserved, 0K cma-reserved) 336s Jul 19 18:15:15 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 336s Jul 19 18:15:15 autopkgtest kernel: ftrace: allocating 51717 entries in 19 pages 336s Jul 19 18:15:15 autopkgtest kernel: ftrace: allocated 19 pages with 3 groups 336s Jul 19 18:15:15 autopkgtest kernel: trace event string verifier disabled 336s Jul 19 18:15:15 autopkgtest kernel: rcu: Hierarchical RCU implementation. 336s Jul 19 18:15:15 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 336s Jul 19 18:15:15 autopkgtest kernel: Rude variant of Tasks RCU enabled. 336s Jul 19 18:15:15 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 336s Jul 19 18:15:15 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 336s Jul 19 18:15:15 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 336s Jul 19 18:15:15 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 336s Jul 19 18:15:15 autopkgtest kernel: xive: Using IRQ range [0-3] 336s Jul 19 18:15:15 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 336s Jul 19 18:15:15 autopkgtest kernel: xive: Using priority 6 for all interrupts 336s Jul 19 18:15:15 autopkgtest kernel: xive: Using 64kB queues 336s Jul 19 18:15:15 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 336s Jul 19 18:15:15 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 336s Jul 19 18:15:15 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 336s Jul 19 18:15:15 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 336s Jul 19 18:15:15 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 336s Jul 19 18:15:15 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 336s Jul 19 18:15:15 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 336s Jul 19 18:15:15 autopkgtest kernel: Console: colour dummy device 80x25 336s Jul 19 18:15:15 autopkgtest kernel: printk: legacy console [hvc0] enabled 336s Jul 19 18:15:15 autopkgtest kernel: printk: legacy bootconsole [udbg0] disabled 336s Jul 19 18:15:15 autopkgtest kernel: pid_max: default: 32768 minimum: 301 336s Jul 19 18:15:15 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,integrity 336s Jul 19 18:15:15 autopkgtest kernel: landlock: Up and running. 336s Jul 19 18:15:15 autopkgtest kernel: Yama: becoming mindful. 336s Jul 19 18:15:15 autopkgtest kernel: AppArmor: AppArmor initialized 336s Jul 19 18:15:15 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 336s Jul 19 18:15:15 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 336s Jul 19 18:15:15 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 336s Jul 19 18:15:15 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 336s Jul 19 18:15:15 autopkgtest kernel: POWER9 performance monitor hardware support registered 336s Jul 19 18:15:15 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 336s Jul 19 18:15:15 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 336s Jul 19 18:15:15 autopkgtest kernel: smp: Bringing up secondary CPUs ... 336s Jul 19 18:15:15 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 336s Jul 19 18:15:15 autopkgtest kernel: numa: Node 0 CPUs: 0-3 336s Jul 19 18:15:15 autopkgtest kernel: devtmpfs: initialized 336s Jul 19 18:15:15 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 336s Jul 19 18:15:15 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 336s Jul 19 18:15:15 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 336s Jul 19 18:15:15 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 336s Jul 19 18:15:15 autopkgtest kernel: PCI: OF: PROBE_ONLY disabled 336s Jul 19 18:15:15 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 336s Jul 19 18:15:15 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 336s Jul 19 18:15:15 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 336s Jul 19 18:15:15 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 336s Jul 19 18:15:15 autopkgtest kernel: audit: initializing netlink subsys (disabled) 336s Jul 19 18:15:15 autopkgtest kernel: audit: type=2000 audit(1721412914.040:1): state=initialized audit_enabled=0 res=1 336s Jul 19 18:15:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 336s Jul 19 18:15:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 336s Jul 19 18:15:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 336s Jul 19 18:15:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 336s Jul 19 18:15:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 336s Jul 19 18:15:15 autopkgtest kernel: cpuidle: using governor ladder 336s Jul 19 18:15:15 autopkgtest kernel: cpuidle: using governor menu 336s Jul 19 18:15:15 autopkgtest kernel: RTAS daemon started 336s Jul 19 18:15:15 autopkgtest kernel: pstore: Using crash dump compression: deflate 336s Jul 19 18:15:15 autopkgtest kernel: pstore: Registered nvram as persistent store backend 336s Jul 19 18:15:15 autopkgtest kernel: EEH: pSeries platform initialized 336s Jul 19 18:15:15 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 336s Jul 19 18:15:15 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 336s Jul 19 18:15:15 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 336s Jul 19 18:15:15 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 336s Jul 19 18:15:15 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 336s Jul 19 18:15:15 autopkgtest kernel: iommu: Default domain type: Translated 336s Jul 19 18:15:15 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 336s Jul 19 18:15:15 autopkgtest kernel: SCSI subsystem initialized 336s Jul 19 18:15:15 autopkgtest kernel: libata version 3.00 loaded. 336s Jul 19 18:15:15 autopkgtest kernel: usbcore: registered new interface driver usbfs 336s Jul 19 18:15:15 autopkgtest kernel: usbcore: registered new interface driver hub 336s Jul 19 18:15:15 autopkgtest kernel: usbcore: registered new device driver usb 336s Jul 19 18:15:15 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 336s Jul 19 18:15:15 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 336s Jul 19 18:15:15 autopkgtest kernel: PTP clock support registered 336s Jul 19 18:15:15 autopkgtest kernel: EDAC MC: Ver: 3.0.0 336s Jul 19 18:15:15 autopkgtest kernel: NetLabel: Initializing 336s Jul 19 18:15:15 autopkgtest kernel: NetLabel: domain hash size = 128 336s Jul 19 18:15:15 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 336s Jul 19 18:15:15 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 336s Jul 19 18:15:15 autopkgtest kernel: mctp: management component transport protocol core 336s Jul 19 18:15:15 autopkgtest kernel: NET: Registered PF_MCTP protocol family 336s Jul 19 18:15:15 autopkgtest kernel: PCI: Probing PCI hardware 336s Jul 19 18:15:15 autopkgtest kernel: PCI host bridge to bus 0000:00 336s Jul 19 18:15:15 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 336s Jul 19 18:15:15 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 336s Jul 19 18:15:15 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 336s Jul 19 18:15:15 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 336s Jul 19 18:15:15 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 336s Jul 19 18:15:15 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 336s Jul 19 18:15:15 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 336s Jul 19 18:15:15 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 336s Jul 19 18:15:15 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 336s Jul 19 18:15:15 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 336s Jul 19 18:15:15 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 336s Jul 19 18:15:15 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 336s Jul 19 18:15:15 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 336s Jul 19 18:15:15 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 336s Jul 19 18:15:15 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 336s Jul 19 18:15:15 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 336s Jul 19 18:15:15 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 336s Jul 19 18:15:15 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 336s Jul 19 18:15:15 autopkgtest kernel: PCI: Probing PCI hardware done 336s Jul 19 18:15:15 autopkgtest kernel: vgaarb: loaded 336s Jul 19 18:15:15 autopkgtest kernel: clocksource: Switched to clocksource timebase 336s Jul 19 18:15:15 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 336s Jul 19 18:15:15 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 336s Jul 19 18:15:15 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 336s Jul 19 18:15:15 autopkgtest kernel: NET: Registered PF_INET protocol family 336s Jul 19 18:15:15 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 336s Jul 19 18:15:15 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 336s Jul 19 18:15:15 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 336s Jul 19 18:15:15 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 336s Jul 19 18:15:15 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 336s Jul 19 18:15:15 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 336s Jul 19 18:15:15 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 336s Jul 19 18:15:15 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 336s Jul 19 18:15:15 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 336s Jul 19 18:15:15 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 336s Jul 19 18:15:15 autopkgtest kernel: NET: Registered PF_XDP protocol family 336s Jul 19 18:15:15 autopkgtest kernel: PCI: CLS 0 bytes, default 128 336s Jul 19 18:15:15 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 336s Jul 19 18:15:15 autopkgtest kernel: Initialise system trusted keyrings 336s Jul 19 18:15:15 autopkgtest kernel: Key type blacklist registered 336s Jul 19 18:15:15 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 336s Jul 19 18:15:15 autopkgtest kernel: zbud: loaded 336s Jul 19 18:15:15 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 336s Jul 19 18:15:15 autopkgtest kernel: fuse: init (API version 7.39) 336s Jul 19 18:15:15 autopkgtest kernel: integrity: Platform Keyring initialized 336s Jul 19 18:15:15 autopkgtest kernel: integrity: Machine keyring initialized 336s Jul 19 18:15:15 autopkgtest kernel: Key type asymmetric registered 336s Jul 19 18:15:15 autopkgtest kernel: Asymmetric key parser 'x509' registered 336s Jul 19 18:15:15 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 336s Jul 19 18:15:15 autopkgtest kernel: io scheduler mq-deadline registered 336s Jul 19 18:15:15 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 336s Jul 19 18:15:15 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 336s Jul 19 18:15:15 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) 336s Jul 19 18:15:15 autopkgtest kernel: virtio-pci 0000:00:02.0: enabling device (0100 -> 0103) 336s Jul 19 18:15:15 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 336s Jul 19 18:15:15 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 336s Jul 19 18:15:15 autopkgtest kernel: Non-volatile memory driver v1.3 336s Jul 19 18:15:15 autopkgtest kernel: Linux agpgart interface v0.103 336s Jul 19 18:15:15 autopkgtest kernel: loop: module loaded 336s Jul 19 18:15:15 autopkgtest kernel: virtio_scsi virtio1: 1/0/0 default/read/poll queues 336s Jul 19 18:15:15 autopkgtest kernel: Freeing initrd memory: 52096K 336s Jul 19 18:15:15 autopkgtest kernel: scsi host0: Virtio SCSI HBA 336s Jul 19 18:15:15 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 336s Jul 19 18:15:15 autopkgtest kernel: PPP generic driver version 2.4.2 336s Jul 19 18:15:15 autopkgtest kernel: scsi 0:0:0:0: Direct-Access QEMU QEMU HARDDISK 2.5+ PQ: 0 ANSI: 5 336s Jul 19 18:15:15 autopkgtest kernel: ohci-pci 0000:00:03.0: OHCI PCI host controller 336s Jul 19 18:15:15 autopkgtest kernel: ohci-pci 0000:00:03.0: new USB bus registered, assigned bus number 1 336s Jul 19 18:15:15 autopkgtest kernel: ohci-pci 0000:00:03.0: irq 20, io mem 0x200080090000 336s Jul 19 18:15:15 autopkgtest kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0 336s Jul 19 18:15:15 autopkgtest kernel: sd 0:0:0:0: Power-on or device reset occurred 336s Jul 19 18:15:15 autopkgtest kernel: sd 0:0:0:0: [sda] 167772160 512-byte logical blocks: (85.9 GB/80.0 GiB) 336s Jul 19 18:15:15 autopkgtest kernel: sd 0:0:0:0: [sda] Write Protect is off 336s Jul 19 18:15:15 autopkgtest kernel: sd 0:0:0:0: [sda] Mode Sense: 63 00 00 08 336s Jul 19 18:15:15 autopkgtest kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 336s Jul 19 18:15:15 autopkgtest kernel: sda: sda1 sda2 336s Jul 19 18:15:15 autopkgtest kernel: sd 0:0:0:0: [sda] Attached SCSI disk 336s Jul 19 18:15:15 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 6.08 336s Jul 19 18:15:15 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 336s Jul 19 18:15:15 autopkgtest kernel: usb usb1: Product: OHCI PCI host controller 336s Jul 19 18:15:15 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.8.0-31-generic ohci_hcd 336s Jul 19 18:15:15 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:03.0 336s Jul 19 18:15:15 autopkgtest kernel: hub 1-0:1.0: USB hub found 336s Jul 19 18:15:15 autopkgtest kernel: hub 1-0:1.0: 3 ports detected 336s Jul 19 18:15:15 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 336s Jul 19 18:15:15 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 336s Jul 19 18:15:15 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-07-19T18:15:15 UTC (1721412915) 336s Jul 19 18:15:15 autopkgtest kernel: i2c_dev: i2c /dev entries driver 336s Jul 19 18:15:15 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 336s Jul 19 18:15:15 autopkgtest kernel: device-mapper: uevent: version 1.0.3 336s Jul 19 18:15:15 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@redhat.com 336s Jul 19 18:15:15 autopkgtest kernel: pseries_idle_driver registered 336s Jul 19 18:15:15 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 336s Jul 19 18:15:15 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 336s Jul 19 18:15:15 autopkgtest kernel: NET: Registered PF_INET6 protocol family 336s Jul 19 18:15:15 autopkgtest kernel: Segment Routing with IPv6 336s Jul 19 18:15:15 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 336s Jul 19 18:15:15 autopkgtest kernel: NET: Registered PF_PACKET protocol family 336s Jul 19 18:15:15 autopkgtest kernel: Key type dns_resolver registered 336s Jul 19 18:15:15 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 336s Jul 19 18:15:15 autopkgtest kernel: drmem: No dynamic reconfiguration memory found 336s Jul 19 18:15:15 autopkgtest kernel: registered taskstats version 1 336s Jul 19 18:15:15 autopkgtest kernel: Loading compiled-in X.509 certificates 336s Jul 19 18:15:15 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 336s Jul 19 18:15:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 336s Jul 19 18:15:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 336s Jul 19 18:15:15 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 336s Jul 19 18:15:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 336s Jul 19 18:15:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 336s Jul 19 18:15:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 336s Jul 19 18:15:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 336s Jul 19 18:15:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 336s Jul 19 18:15:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 336s Jul 19 18:15:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 336s Jul 19 18:15:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 336s Jul 19 18:15:15 autopkgtest kernel: Key type .fscrypt registered 336s Jul 19 18:15:15 autopkgtest kernel: Key type fscrypt-provisioning registered 336s Jul 19 18:15:15 autopkgtest kernel: Key type encrypted registered 336s Jul 19 18:15:15 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 336s Jul 19 18:15:15 autopkgtest kernel: Secure boot mode disabled 336s Jul 19 18:15:15 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 336s Jul 19 18:15:15 autopkgtest kernel: Loading compiled-in module X.509 certificates 336s Jul 19 18:15:15 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 336s Jul 19 18:15:15 autopkgtest kernel: ima: Allocated hash algorithm: sha256 336s Jul 19 18:15:15 autopkgtest kernel: Secure boot mode disabled 336s Jul 19 18:15:15 autopkgtest kernel: Trusted boot mode disabled 336s Jul 19 18:15:15 autopkgtest kernel: ima: No architecture policies found 336s Jul 19 18:15:15 autopkgtest kernel: evm: Initialising EVM extended attributes: 336s Jul 19 18:15:15 autopkgtest kernel: evm: security.selinux 336s Jul 19 18:15:15 autopkgtest kernel: evm: security.SMACK64 336s Jul 19 18:15:15 autopkgtest kernel: evm: security.SMACK64EXEC 336s Jul 19 18:15:15 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 336s Jul 19 18:15:15 autopkgtest kernel: evm: security.SMACK64MMAP 336s Jul 19 18:15:15 autopkgtest kernel: evm: security.apparmor 336s Jul 19 18:15:15 autopkgtest kernel: evm: security.ima 336s Jul 19 18:15:15 autopkgtest kernel: evm: security.capability 336s Jul 19 18:15:15 autopkgtest kernel: evm: HMAC attrs: 0x1 336s Jul 19 18:15:15 autopkgtest kernel: SED: plpks not available 336s Jul 19 18:15:15 autopkgtest kernel: clk: Disabling unused clocks 336s Jul 19 18:15:15 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 336s Jul 19 18:15:15 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8832K 336s Jul 19 18:15:15 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 336s Jul 19 18:15:15 autopkgtest kernel: Run /init as init process 336s Jul 19 18:15:15 autopkgtest kernel: with arguments: 336s Jul 19 18:15:15 autopkgtest kernel: /init 336s Jul 19 18:15:15 autopkgtest kernel: earlyprintk 336s Jul 19 18:15:15 autopkgtest kernel: with environment: 336s Jul 19 18:15:15 autopkgtest kernel: HOME=/ 336s Jul 19 18:15:15 autopkgtest kernel: TERM=linux 336s Jul 19 18:15:15 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic 336s Jul 19 18:15:15 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 336s Jul 19 18:15:16 autopkgtest kernel: raid6: vpermxor8 gen() 23630 MB/s 336s Jul 19 18:15:16 autopkgtest kernel: raid6: vpermxor4 gen() 20636 MB/s 336s Jul 19 18:15:16 autopkgtest kernel: raid6: vpermxor2 gen() 16558 MB/s 336s Jul 19 18:15:17 autopkgtest kernel: raid6: vpermxor1 gen() 13916 MB/s 336s Jul 19 18:15:17 autopkgtest kernel: raid6: altivecx8 gen() 14425 MB/s 336s Jul 19 18:15:17 autopkgtest kernel: raid6: altivecx4 gen() 14273 MB/s 336s Jul 19 18:15:17 autopkgtest kernel: raid6: altivecx2 gen() 11138 MB/s 336s Jul 19 18:15:17 autopkgtest kernel: raid6: altivecx1 gen() 8636 MB/s 336s Jul 19 18:15:17 autopkgtest kernel: raid6: int64x8 gen() 7212 MB/s 336s Jul 19 18:15:17 autopkgtest kernel: raid6: int64x4 gen() 8753 MB/s 336s Jul 19 18:15:17 autopkgtest kernel: raid6: int64x2 gen() 6849 MB/s 336s Jul 19 18:15:17 autopkgtest kernel: raid6: int64x1 gen() 5103 MB/s 336s Jul 19 18:15:17 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 23630 MB/s 336s Jul 19 18:15:17 autopkgtest kernel: raid6: using intx1 recovery algorithm 336s Jul 19 18:15:17 autopkgtest kernel: xor: measuring software checksum speed 336s Jul 19 18:15:17 autopkgtest kernel: 8regs : 17836 MB/sec 336s Jul 19 18:15:17 autopkgtest kernel: 8regs_prefetch : 15974 MB/sec 336s Jul 19 18:15:17 autopkgtest kernel: 32regs : 17807 MB/sec 336s Jul 19 18:15:17 autopkgtest kernel: 32regs_prefetch : 15969 MB/sec 336s Jul 19 18:15:17 autopkgtest kernel: altivec : 19933 MB/sec 336s Jul 19 18:15:17 autopkgtest kernel: xor: using function: altivec (19933 MB/sec) 336s Jul 19 18:15:17 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 336s Jul 19 18:15:17 autopkgtest kernel: EXT4-fs (sda1): orphan cleanup on readonly fs 336s Jul 19 18:15:17 autopkgtest kernel: EXT4-fs (sda1): mounted filesystem a7a7eb95-072e-451f-aab9-f64fe5535e24 ro with ordered data mode. Quota mode: none. 336s Jul 19 18:15:17 autopkgtest systemd[1]: Inserted module 'autofs4' 336s Jul 19 18:15:17 autopkgtest systemd[1]: systemd 256-1ubuntu1 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) 336s Jul 19 18:15:17 autopkgtest systemd[1]: Detected virtualization kvm. 336s Jul 19 18:15:17 autopkgtest systemd[1]: Detected architecture ppc64-le. 336s Jul 19 18:15:17 autopkgtest systemd[1]: Hostname set to . 336s Jul 19 18:15:18 autopkgtest systemd[1]: bpf-restrict-fs: BPF LSM hook not enabled in the kernel, BPF LSM not supported. 336s Jul 19 18:15:18 autopkgtest kernel: NET: Registered PF_VSOCK protocol family 336s Jul 19 18:15:18 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. 336s Jul 19 18:15:18 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. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Queued start job for default target graphical.target. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Reached target swap.target - Swaps. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Listening on multipathd.socket - multipathd control socket. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 336s Jul 19 18:15:18 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Sockets. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounting run-lock.mount - Legacy Locks Directory /run/lock... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting modprobe@dm_mod.service - Load Kernel Module dm_mod... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting modprobe@dm_multipath.service - Load Kernel Module dm_multipath... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting modprobe@loop.service - Load Kernel Module loop... 336s Jul 19 18:15:18 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 336s Jul 19 18:15:18 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). 336s Jul 19 18:15:18 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). 336s Jul 19 18:15:18 autopkgtest systemd-journald[286]: Collecting audit messages is disabled. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounted run-lock.mount - Legacy Locks Directory /run/lock. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 336s Jul 19 18:15:18 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 336s Jul 19 18:15:18 autopkgtest systemd[1]: modprobe@dm_mod.service: Deactivated successfully. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished modprobe@dm_mod.service - Load Kernel Module dm_mod. 336s Jul 19 18:15:18 autopkgtest systemd[1]: modprobe@dm_multipath.service: Deactivated successfully. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished modprobe@dm_multipath.service - Load Kernel Module dm_multipath. 336s Jul 19 18:15:18 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 336s Jul 19 18:15:18 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 336s Jul 19 18:15:18 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 336s Jul 19 18:15:18 autopkgtest systemd[1]: modprobe@loop.service: Deactivated successfully. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished modprobe@loop.service - Load Kernel Module loop. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 336s Jul 19 18:15:18 autopkgtest systemd-journald[286]: Journal started 336s Jul 19 18:15:18 autopkgtest systemd-journald[286]: Runtime Journal (/run/log/journal/f445f116f66b4a399d8f5734bd9847c3) is 8M, max 78.4M, 70.4M free. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 336s Jul 19 18:15:18 autopkgtest systemd[1]: systemd-repart.service - Repartition Root Disk was skipped because no trigger condition checks were met. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 336s Jul 19 18:15:18 autopkgtest kernel: EXT4-fs (sda1): re-mounted a7a7eb95-072e-451f-aab9-f64fe5535e24 r/w. Quota mode: none. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 336s Jul 19 18:15:18 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 336s Jul 19 18:15:18 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 336s Jul 19 18:15:18 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 336s Jul 19 18:15:18 autopkgtest systemd-random-seed[346]: Kernel entropy pool is not initialized yet, waiting until it is. 336s Jul 19 18:15:18 autopkgtest systemd-journald[286]: Time spent on flushing to /var/log/journal/f445f116f66b4a399d8f5734bd9847c3 is 22.526ms for 432 entries. 336s Jul 19 18:15:18 autopkgtest systemd-journald[286]: System Journal (/var/log/journal/f445f116f66b4a399d8f5734bd9847c3) is 19M, max 4G, 3.9G free. 336s Jul 19 18:15:18 autopkgtest systemd-journald[286]: Received client request to flush runtime journal. 336s Jul 19 18:15:18 autopkgtest multipathd[343]: multipathd v0.9.9: start up 336s Jul 19 18:15:18 autopkgtest multipathd[343]: reconfigure: setting up paths and maps 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 336s Jul 19 18:15:18 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create Volatile Files and Directories... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 336s Jul 19 18:15:18 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 365 (systemd-binfmt) 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 336s Jul 19 18:15:18 autopkgtest apparmor.systemd[361]: Restarting AppArmor 336s Jul 19 18:15:18 autopkgtest systemd-tmpfiles[372]: /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 336s Jul 19 18:15:18 autopkgtest apparmor.systemd[361]: Reloading AppArmor profiles 336s Jul 19 18:15:18 autopkgtest systemd-udevd[353]: Using default interface naming scheme 'v255'. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create Volatile Files and Directories. 336s Jul 19 18:15:18 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 336s Jul 19 18:15:18 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 336s Jul 19 18:15:18 autopkgtest kernel: audit: type=1400 audit(1721412918.420:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=385 comm="apparmor_parser" 336s Jul 19 18:15:18 autopkgtest kernel: audit: type=1400 audit(1721412918.420:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=384 comm="apparmor_parser" 336s Jul 19 18:15:18 autopkgtest kernel: audit: type=1400 audit(1721412918.420:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=386 comm="apparmor_parser" 336s Jul 19 18:15:18 autopkgtest kernel: audit: type=1400 audit(1721412918.420:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=387 comm="apparmor_parser" 336s Jul 19 18:15:18 autopkgtest kernel: audit: type=1400 audit(1721412918.420:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=389 comm="apparmor_parser" 336s Jul 19 18:15:18 autopkgtest kernel: audit: type=1400 audit(1721412918.424:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=391 comm="apparmor_parser" 336s Jul 19 18:15:18 autopkgtest kernel: audit: type=1400 audit(1721412918.424:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="busybox" pid=392 comm="apparmor_parser" 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 336s Jul 19 18:15:18 autopkgtest kernel: audit: type=1400 audit(1721412918.424:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=390 comm="apparmor_parser" 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 336s Jul 19 18:15:18 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 336s Jul 19 18:15:18 autopkgtest kernel: audit: type=1400 audit(1721412918.428:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="cam" pid=395 comm="apparmor_parser" 336s Jul 19 18:15:18 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 336s Jul 19 18:15:18 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 336s Jul 19 18:15:18 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 336s Jul 19 18:15:18 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 336s Jul 19 18:15:18 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). 336s Jul 19 18:15:18 autopkgtest systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 336s Jul 19 18:15:18 autopkgtest (udev-worker)[454]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 336s Jul 19 18:15:18 autopkgtest kernel: random: crng init done 336s Jul 19 18:15:18 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 336s Jul 19 18:15:18 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 336s Jul 19 18:15:18 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). 336s Jul 19 18:15:18 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 336s Jul 19 18:15:19 autopkgtest cloud-init[664]: Cloud-init v. 24.2-0ubuntu1 running 'init-local' at Fri, 19 Jul 2024 18:15:19 +0000. Up 4.01 seconds. 336s Jul 19 18:15:19 autopkgtest dhcpcd[667]: dhcpcd-10.0.8 starting 336s Jul 19 18:15:19 autopkgtest dhcpcd[670]: DUID 00:01:00:01:2e:2c:27:32:fa:16:3e:e6:68:77 336s Jul 19 18:15:19 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 336s Jul 19 18:15:19 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 336s Jul 19 18:15:19 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 336s Jul 19 18:15:19 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 336s Jul 19 18:15:19 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 336s Jul 19 18:15:19 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 336s Jul 19 18:15:19 autopkgtest dhcpcd[670]: enp0s1: IAID 3e:0f:43:98 336s Jul 19 18:15:19 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 336s Jul 19 18:15:19 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 336s Jul 19 18:15:19 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 336s Jul 19 18:15:19 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 336s Jul 19 18:15:19 autopkgtest systemd-resolved[393]: Positive Trust Anchors: 336s Jul 19 18:15:19 autopkgtest systemd-resolved[393]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 336s Jul 19 18:15:19 autopkgtest systemd-resolved[393]: 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 336s Jul 19 18:15:19 autopkgtest systemd-resolved[393]: Using system hostname 'autopkgtest'. 336s Jul 19 18:15:19 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 336s Jul 19 18:15:19 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 336s Jul 19 18:15:19 autopkgtest dhcpcd[670]: enp0s1: rebinding lease of 10.44.124.175 336s Jul 19 18:15:24 autopkgtest dhcpcd[670]: enp0s1: DHCP lease expired 336s Jul 19 18:15:24 autopkgtest dhcpcd[670]: enp0s1: soliciting a DHCP lease 336s Jul 19 18:15:24 autopkgtest dhcpcd[670]: enp0s1: offered 10.44.124.175 from 10.44.124.241 336s Jul 19 18:15:24 autopkgtest dhcpcd[670]: enp0s1: leased 10.44.124.175 for 86400 seconds 336s Jul 19 18:15:24 autopkgtest dhcpcd[670]: enp0s1: adding route to 10.44.124.0/24 336s Jul 19 18:15:24 autopkgtest dhcpcd[670]: enp0s1: adding host route to 169.254.169.254 via 10.44.124.1 336s Jul 19 18:15:24 autopkgtest dhcpcd[670]: enp0s1: adding default route via 10.44.124.1 336s Jul 19 18:15:24 autopkgtest dhcpcd[670]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 336s Jul 19 18:15:26 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 336s Jul 19 18:15:26 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 336s Jul 19 18:15:26 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 336s Jul 19 18:15:26 autopkgtest systemd-networkd[707]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 336s Jul 19 18:15:26 autopkgtest systemd-networkd[707]: lo: Link UP 336s Jul 19 18:15:26 autopkgtest systemd-networkd[707]: lo: Gained carrier 336s Jul 19 18:15:26 autopkgtest systemd-networkd[707]: Enumeration completed 336s Jul 19 18:15:26 autopkgtest systemd-networkd[707]: enp0s1: Link UP 336s Jul 19 18:15:26 autopkgtest systemd-networkd[707]: enp0s1: Gained carrier 336s Jul 19 18:15:26 autopkgtest systemd-networkd[707]: enp0s1: Gained IPv6LL 336s Jul 19 18:15:26 autopkgtest systemd-timesyncd[396]: Network configuration changed, trying to establish connection. 336s Jul 19 18:15:26 autopkgtest systemd-timesyncd[396]: Network configuration changed, trying to establish connection. 336s Jul 19 18:15:26 autopkgtest systemd-networkd[707]: enp0s1: Link DOWN 336s Jul 19 18:15:26 autopkgtest systemd-networkd[707]: enp0s1: Lost carrier 336s Jul 19 18:15:26 autopkgtest systemd-timesyncd[396]: Network configuration changed, trying to establish connection. 336s Jul 19 18:15:26 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 336s Jul 19 18:15:26 autopkgtest systemd[1]: Reached target network.target - Network. 336s Jul 19 18:15:26 autopkgtest systemd-networkd[707]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 336s Jul 19 18:15:26 autopkgtest systemd-networkd[707]: enp0s1: Link UP 336s Jul 19 18:15:26 autopkgtest systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... 336s Jul 19 18:15:26 autopkgtest systemd-networkd[707]: enp0s1: Gained carrier 336s Jul 19 18:15:26 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 336s Jul 19 18:15:26 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 336s Jul 19 18:15:26 autopkgtest systemd-networkd[707]: enp0s1: DHCPv4 address 10.44.124.175/24, gateway 10.44.124.1 acquired from 10.44.124.241 336s Jul 19 18:15:26 autopkgtest systemd-timesyncd[396]: Network configuration changed, trying to establish connection. 336s Jul 19 18:15:26 autopkgtest systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. 336s Jul 19 18:15:28 autopkgtest systemd-networkd[707]: enp0s1: Gained IPv6LL 336s Jul 19 18:15:28 autopkgtest systemd-timesyncd[396]: Network configuration changed, trying to establish connection. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting cloud-init.service - Cloud-init: Network Stage... 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: Cloud-init v. 24.2-0ubuntu1 running 'init' at Fri, 19 Jul 2024 18:15:28 +0000. Up 13.32 seconds. 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | enp0s1 | True | 10.44.124.175 | 255.255.255.0 | global | fa:16:3e:0f:43:98 | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | enp0s1 | True | fe80::f816:3eff:fe0f:4398/64 | . | link | fa:16:3e:0f:43:98 | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | lo | True | ::1/128 | . | host | . | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info++++++++++++++++++++++++++++++++ 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | 0 | 0.0.0.0 | 10.44.124.1 | 0.0.0.0 | enp0s1 | UG | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | 1 | 10.44.124.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | 2 | 10.44.124.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | 3 | 91.189.91.130 | 10.44.124.1 | 255.255.255.255 | enp0s1 | UGH | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | 4 | 169.254.169.254 | 10.44.124.1 | 255.255.255.255 | enp0s1 | UGH | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: +-------+-------------+---------+-----------+-------+ 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | Route | Destination | Gateway | Interface | Flags | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: +-------+-------------+---------+-----------+-------+ 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | 2 | local | :: | enp0s1 | U | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: | 3 | multicast | :: | enp0s1 | U | 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: ci-info: +-------+-------------+---------+-----------+-------+ 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: 2024-07-19 18:15:28,632 - 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. 336s Jul 19 18:15:28 autopkgtest cloud-init[719]: 2024-07-19 18:15:28,632 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Finished cloud-init.service - Cloud-init: Network Stage. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 336s Jul 19 18:15:28 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). 336s Jul 19 18:15:28 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). 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started sysstat-collect.timer - Run system activity accounting tool every 10 minutes. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started sysstat-rotate.timer - Rotate daily system activity data file at midnight. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started sysstat-summary.timer - Generate summary of yesterday's process accounting. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 336s Jul 19 18:15:28 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). 336s Jul 19 18:15:28 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Reached target paths.target - Path Units. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 336s Jul 19 18:15:28 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 336s Jul 19 18:15:28 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). 336s Jul 19 18:15:28 autopkgtest systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). 336s Jul 19 18:15:28 autopkgtest systemd[1]: Reached target ssh-access.target - SSH Access Available. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Reached target basic.target - Basic System. 336s Jul 19 18:15:28 autopkgtest systemd[1]: System is tainted: unmerged-bin 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 336s Jul 19 18:15:28 autopkgtest (sh)[756]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 336s Jul 19 18:15:28 autopkgtest (sh)[756]: autopkgtest@ttyS1.service: Failed at step STDIN spawning /bin/sh: Input/output error 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 336s Jul 19 18:15:28 autopkgtest (cron)[758]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 336s Jul 19 18:15:28 autopkgtest cron[758]: (CRON) INFO (pidfile fd = 3) 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 336s Jul 19 18:15:28 autopkgtest cron[758]: (CRON) INFO (Running @reboot jobs) 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 336s Jul 19 18:15:28 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). 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 336s Jul 19 18:15:28 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 336s Jul 19 18:15:28 autopkgtest systemd[1]: opal_errd.service - opal_errd (PowerNV platform error handling) Service was skipped because of an unmet condition check (ConditionVirtualization=false). 336s Jul 19 18:15:28 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). 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 336s Jul 19 18:15:28 autopkgtest dbus-daemon[759]: [system] AppArmor D-Bus mediation is enabled 336s Jul 19 18:15:28 autopkgtest dbus-daemon[759]: [system] Activating systemd to hand-off: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.0' (uid=998 pid=707 comm="/usr/lib/systemd/systemd-networkd" label="unconfined") 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting sysstat.service - Resets System Activity Logs... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 336s Jul 19 18:15:28 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). 336s Jul 19 18:15:28 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 336s Jul 19 18:15:28 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Finished sysstat.service - Resets System Activity Logs. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 336s Jul 19 18:15:28 autopkgtest udisksd[777]: udisks daemon version 2.10.1 starting 336s Jul 19 18:15:28 autopkgtest dbus-daemon[759]: [system] Successfully activated service 'org.freedesktop.systemd1' 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting systemd-hostnamed.service - Hostname Service... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 336s Jul 19 18:15:28 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 336s Jul 19 18:15:28 autopkgtest rng-tools-debian[817]: found /dev/hwrng but could not use it 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 336s Jul 19 18:15:28 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 336s Jul 19 18:15:28 autopkgtest rng-tools-debian[820]: not starting: no hardware RNG device found 336s Jul 19 18:15:28 autopkgtest rng-tools-debian[766]: * Configuring Hardware RNG entropy gatherer daemon 336s Jul 19 18:15:28 autopkgtest rng-tools-debian[766]: ...fail! 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 336s Jul 19 18:15:28 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 336s Jul 19 18:15:28 autopkgtest systemd-logind[774]: New seat seat0. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 336s Jul 19 18:15:28 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 336s Jul 19 18:15:28 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 336s Jul 19 18:15:28 autopkgtest kernel: kauditd_printk_skb: 110 callbacks suppressed 336s Jul 19 18:15:28 autopkgtest kernel: audit: type=1400 audit(1721412928.972:121): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=794 comm="apparmor_parser" 336s Jul 19 18:15:28 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 336s Jul 19 18:15:28 autopkgtest udisksd[777]: Acquired the name org.freedesktop.UDisks2 on the system message bus 336s Jul 19 18:15:29 autopkgtest systemd[1]: Started systemd-hostnamed.service - Hostname Service. 336s Jul 19 18:15:29 autopkgtest dbus-daemon[759]: [system] Successfully activated service 'org.freedesktop.hostname1' 336s Jul 19 18:15:29 autopkgtest systemd-networkd[707]: Could not set hostname: Access denied 336s Jul 19 18:15:29 autopkgtest rsyslogd[832]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2312.0] 336s Jul 19 18:15:29 autopkgtest rsyslogd[832]: rsyslogd's groupid changed to 102 336s Jul 19 18:15:29 autopkgtest rsyslogd[832]: rsyslogd's userid changed to 102 336s Jul 19 18:15:29 autopkgtest rsyslogd[832]: [origin software="rsyslogd" swVersion="8.2312.0" x-pid="832" x-info="https://www.rsyslog.com"] start 336s Jul 19 18:15:29 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 336s Jul 19 18:15:29 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 336s Jul 19 18:15:29 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 336s Jul 19 18:15:29 autopkgtest sshd[845]: Server listening on :: port 22. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 336s Jul 19 18:15:29 autopkgtest cloud-init[852]: Cloud-init v. 24.2-0ubuntu1 running 'modules:config' at Fri, 19 Jul 2024 18:15:29 +0000. Up 14.01 seconds. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 336s Jul 19 18:15:29 autopkgtest sshd[847]: Accepted publickey for ubuntu from 10.136.6.201 port 39174 ssh2: RSA SHA256:YaYyKWTl9zFJEBK5G3u+MRj3WPJt+vEplFd0J96PUBw 336s Jul 19 18:15:29 autopkgtest sshd[847]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 336s Jul 19 18:15:29 autopkgtest sshd[847]: pam_systemd(sshd:session): New sd-bus connection (system-bus-pam-systemd-847) opened. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 336s Jul 19 18:15:29 autopkgtest systemd-logind[774]: New session 1 of user ubuntu. 336s Jul 19 18:15:29 autopkgtest cloud-init[859]: Cloud-init v. 24.2-0ubuntu1 running 'modules:final' at Fri, 19 Jul 2024 18:15:29 +0000. Up 14.48 seconds. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 336s Jul 19 18:15:29 autopkgtest cloud-init[859]: Cloud-init v. 24.2-0ubuntu1 finished at Fri, 19 Jul 2024 18:15:29 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 14.56 seconds 336s Jul 19 18:15:29 autopkgtest (systemd)[861]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 336s Jul 19 18:15:29 autopkgtest systemd-logind[774]: New session 2 of user ubuntu. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 336s Jul 19 18:15:29 autopkgtest systemd[861]: Queued start job for default target default.target. 336s Jul 19 18:15:29 autopkgtest systemd[861]: Created slice app.slice - User Application Slice. 336s Jul 19 18:15:29 autopkgtest systemd[861]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 336s Jul 19 18:15:29 autopkgtest systemd[861]: Reached target paths.target - Paths. 336s Jul 19 18:15:29 autopkgtest systemd[861]: Reached target timers.target - Timers. 336s Jul 19 18:15:29 autopkgtest systemd[861]: Starting dbus.socket - D-Bus User Message Bus Socket... 336s Jul 19 18:15:29 autopkgtest systemd[861]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 336s Jul 19 18:15:29 autopkgtest systemd[861]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 336s Jul 19 18:15:29 autopkgtest systemd[861]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 336s Jul 19 18:15:29 autopkgtest systemd[861]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 336s Jul 19 18:15:29 autopkgtest systemd[861]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 336s Jul 19 18:15:29 autopkgtest systemd[861]: Listening on keyboxd.socket - GnuPG public key management service. 336s Jul 19 18:15:29 autopkgtest systemd[861]: Listening on dbus.socket - D-Bus User Message Bus Socket. 336s Jul 19 18:15:29 autopkgtest systemd[861]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 336s Jul 19 18:15:29 autopkgtest systemd[861]: Reached target sockets.target - Sockets. 336s Jul 19 18:15:29 autopkgtest systemd[861]: Reached target basic.target - Basic System. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 336s Jul 19 18:15:29 autopkgtest systemd[861]: Reached target default.target - Main User Target. 336s Jul 19 18:15:29 autopkgtest systemd[861]: Startup finished in 178ms. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 336s Jul 19 18:15:29 autopkgtest systemd[1]: Startup finished in 2.725s (kernel) + 12.037s (userspace) = 14.762s. 336s Jul 19 18:15:29 autopkgtest kernel: fbcon: Taking over console 336s Jul 19 18:15:30 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 336s Jul 19 18:15:30 autopkgtest sudo[911]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 336s Jul 19 18:15:30 autopkgtest sudo[911]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:30 autopkgtest sudo[911]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:30 autopkgtest sudo[916]: 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' 336s Jul 19 18:15:30 autopkgtest sudo[916]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:30 autopkgtest sudo[916]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:30 autopkgtest sudo[928]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.8AodB3 336s Jul 19 18:15:30 autopkgtest sudo[928]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:30 autopkgtest sudo[928]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:31 autopkgtest sudo[938]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.8AodB3/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.8AodB3/autopkgtest-reboot' 336s Jul 19 18:15:31 autopkgtest sudo[938]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:31 autopkgtest sudo[938]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:31 autopkgtest sudo[950]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.8AodB3/autopkgtest-reboot 336s Jul 19 18:15:31 autopkgtest sudo[950]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:31 autopkgtest sudo[950]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:31 autopkgtest sudo[960]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.8AodB3/autopkgtest-reboot /tmp/autopkgtest-reboot 336s Jul 19 18:15:31 autopkgtest sudo[960]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:31 autopkgtest sudo[960]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:31 autopkgtest sudo[970]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.8AodB3/autopkgtest-reboot /sbin/autopkgtest-reboot 336s Jul 19 18:15:31 autopkgtest sudo[970]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:31 autopkgtest sudo[970]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:31 autopkgtest sudo[980]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.8AodB3 336s Jul 19 18:15:31 autopkgtest sudo[980]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:31 autopkgtest sudo[980]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:31 autopkgtest sudo[990]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.8AodB3/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.8AodB3/autopkgtest-reboot-prepare' 336s Jul 19 18:15:31 autopkgtest sudo[990]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:32 autopkgtest sudo[990]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:32 autopkgtest sudo[1002]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.8AodB3/autopkgtest-reboot-prepare 336s Jul 19 18:15:32 autopkgtest sudo[1002]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:32 autopkgtest sudo[1002]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:32 autopkgtest sudo[1012]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.8AodB3/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 336s Jul 19 18:15:32 autopkgtest sudo[1012]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:32 autopkgtest sudo[1012]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:32 autopkgtest sudo[1022]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 336s Jul 19 18:15:32 autopkgtest sudo[1022]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:32 autopkgtest sudo[1022]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:32 autopkgtest sudo[1032]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 336s Jul 19 18:15:32 autopkgtest sudo[1032]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:32 autopkgtest sudo[1032]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:32 autopkgtest sudo[1042]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.8AodB3/testbed-packages' 336s Jul 19 18:15:32 autopkgtest sudo[1042]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:32 autopkgtest sudo[1042]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:33 autopkgtest sudo[1053]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.8AodB3/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.8AodB3/autopkgtest-reboot' 336s Jul 19 18:15:33 autopkgtest sudo[1074]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:33 autopkgtest sudo[1074]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:33 autopkgtest sudo[1086]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.8AodB3/autopkgtest-reboot 336s Jul 19 18:15:33 autopkgtest sudo[1086]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:33 autopkgtest sudo[1086]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:33 autopkgtest sudo[1096]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.8AodB3/autopkgtest-reboot /tmp/autopkgtest-reboot 336s Jul 19 18:15:33 autopkgtest sudo[1096]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:33 autopkgtest sudo[1096]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:34 autopkgtest sudo[1106]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.8AodB3/autopkgtest-reboot /sbin/autopkgtest-reboot 336s Jul 19 18:15:34 autopkgtest sudo[1106]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:34 autopkgtest sudo[1106]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:34 autopkgtest sudo[1116]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.8AodB3 336s Jul 19 18:15:34 autopkgtest sudo[1116]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:34 autopkgtest sudo[1116]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:34 autopkgtest sudo[1126]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.8AodB3/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.8AodB3/autopkgtest-reboot-prepare' 336s Jul 19 18:15:34 autopkgtest sudo[1126]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:34 autopkgtest sudo[1126]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:34 autopkgtest sudo[1138]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.8AodB3/autopkgtest-reboot-prepare 336s Jul 19 18:15:34 autopkgtest sudo[1138]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:34 autopkgtest sudo[1138]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:34 autopkgtest sudo[1148]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.8AodB3/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 336s Jul 19 18:15:34 autopkgtest sudo[1148]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:34 autopkgtest sudo[1148]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:34 autopkgtest sudo[1158]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 336s Jul 19 18:15:34 autopkgtest sudo[1158]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:34 autopkgtest sudo[1158]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:35 autopkgtest sudo[1168]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 336s Jul 19 18:15:35 autopkgtest sudo[1168]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:35 autopkgtest sudo[1168]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:35 autopkgtest sudo[1177]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.8AodB3 336s Jul 19 18:15:35 autopkgtest sudo[1177]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:35 autopkgtest sudo[1177]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:35 autopkgtest sudo[1187]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.8AodB3/2-autopkgtest-satdep.deb' 336s Jul 19 18:15:35 autopkgtest sudo[1187]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:35 autopkgtest sudo[1187]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:35 autopkgtest sudo[1198]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.8AodB3/2-autopkgtest-satdep.deb 336s Jul 19 18:15:35 autopkgtest sudo[1198]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:35 autopkgtest sudo[1198]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:35 autopkgtest sudo[1208]: 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.8AodB3/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' 336s Jul 19 18:15:35 autopkgtest sudo[1208]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:39 autopkgtest systemd[1]: Reload requested from client PID 1448 ('systemctl') (unit session-1.scope)... 336s Jul 19 18:15:39 autopkgtest systemd[1]: Reloading... 336s Jul 19 18:15:39 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. 336s Jul 19 18:15:39 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. 336s Jul 19 18:15:39 autopkgtest systemd[1]: Reloading finished in 200 ms. 336s Jul 19 18:15:39 autopkgtest systemd[1]: Reload requested from client PID 1498 ('systemctl') (unit session-1.scope)... 336s Jul 19 18:15:39 autopkgtest systemd[1]: Reloading... 336s Jul 19 18:15:39 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. 336s Jul 19 18:15:39 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. 336s Jul 19 18:15:39 autopkgtest systemd[1]: Reloading finished in 220 ms. 336s Jul 19 18:15:39 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 336s Jul 19 18:15:39 autopkgtest tgtd[1544]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 336s Jul 19 18:15:39 autopkgtest tgtd[1544]: tgtd: work_timer_start(146) use timer_fd based scheduler 336s Jul 19 18:15:39 autopkgtest tgtd[1544]: tgtd: bs_init(387) use signalfd notification 336s Jul 19 18:15:39 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 336s Jul 19 18:15:40 autopkgtest systemd[1]: Reload requested from client PID 1572 ('systemctl') (unit session-1.scope)... 336s Jul 19 18:15:40 autopkgtest systemd[1]: Reloading... 336s Jul 19 18:15:40 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. 336s Jul 19 18:15:40 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. 336s Jul 19 18:15:40 autopkgtest systemd[1]: Reloading finished in 199 ms. 336s Jul 19 18:15:40 autopkgtest systemd[1]: Reload requested from client PID 1615 ('systemctl') (unit session-1.scope)... 336s Jul 19 18:15:40 autopkgtest systemd[1]: Reloading... 336s Jul 19 18:15:40 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. 336s Jul 19 18:15:40 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. 336s Jul 19 18:15:40 autopkgtest systemd[1]: Reloading finished in 205 ms. 336s Jul 19 18:15:40 autopkgtest systemd[1]: Reload requested from client PID 1661 ('systemctl') (unit session-1.scope)... 336s Jul 19 18:15:40 autopkgtest systemd[1]: Reloading... 336s Jul 19 18:15:40 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. 336s Jul 19 18:15:40 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. 336s Jul 19 18:15:40 autopkgtest systemd[1]: Reloading finished in 205 ms. 336s Jul 19 18:15:40 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 336s Jul 19 18:15:41 autopkgtest systemd[1]: Reload requested from client PID 1712 ('systemctl') (unit session-1.scope)... 336s Jul 19 18:15:41 autopkgtest systemd[1]: Reloading... 336s Jul 19 18:15:41 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. 336s Jul 19 18:15:41 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. 336s Jul 19 18:15:41 autopkgtest systemd[1]: Reloading finished in 219 ms. 336s Jul 19 18:15:41 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 336s Jul 19 18:15:41 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 336s Jul 19 18:15:41 autopkgtest systemd[1]: Reload requested from client PID 1767 ('systemctl') (unit session-1.scope)... 336s Jul 19 18:15:41 autopkgtest systemd[1]: Reloading... 336s Jul 19 18:15:41 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. 336s Jul 19 18:15:41 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. 336s Jul 19 18:15:41 autopkgtest systemd[1]: Reloading finished in 206 ms. 336s Jul 19 18:15:51 autopkgtest sudo[1208]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:51 autopkgtest sudo[5249]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 336s Jul 19 18:15:51 autopkgtest sudo[5249]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:51 autopkgtest sudo[5249]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:51 autopkgtest sudo[5259]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 336s Jul 19 18:15:51 autopkgtest sudo[5259]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:51 autopkgtest sudo[5259]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:51 autopkgtest sudo[5269]: 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 336s Jul 19 18:15:51 autopkgtest sudo[5269]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:52 autopkgtest sudo[5269]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:52 autopkgtest sudo[5282]: 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 336s Jul 19 18:15:52 autopkgtest sudo[5282]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:52 autopkgtest sudo[5282]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:52 autopkgtest sudo[5294]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 336s Jul 19 18:15:52 autopkgtest sudo[5294]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:53 autopkgtest sudo[5294]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:53 autopkgtest sudo[5306]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 336s Jul 19 18:15:53 autopkgtest sudo[5306]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:53 autopkgtest sudo[5306]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:53 autopkgtest sudo[5316]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.8AodB3/tgtbasedmpaths-packages.all' 336s Jul 19 18:15:53 autopkgtest sudo[5316]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 336s Jul 19 18:15:53 autopkgtest sudo[5316]: pam_unix(sudo:session): session closed for user root 336s Jul 19 18:15:53 autopkgtest sudo[5327]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 340s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 340s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 340s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 340s latency : target=0, window=0, percentile=100.00%, depth=1 340s 340s Run status group 0 (all jobs): 340s WRITE: bw=147MiB/s (154MB/s), 147MiB/s-147MiB/s (154MB/s-154MB/s), io=87.5MiB (91.8MB), run=596-596msec 340s 340s Disk stats (read/write): 340s dm-0: ios=1/914, sectors=8/116992, merge=0/0, ticks=1/363, in_queue=363, util=70.06%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/134, aggrin_queue=134, aggrutil=83.01% 340s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 340s sdb: ios=1/1402, sectors=8/179280, merge=0/0, ticks=0/539, in_queue=539, util=83.01% 340s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 340s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 340s Starting the path changes in background 340s + echo Starting the path changes in background 340s + date +Pre FIO %H:%M:%S.%N 340s Pre FIO 18:16:05.770691908 340s + fio --max-jobs=4 /tmp/autopkgtest.8AodB3/tgtbasedmpaths-artifacts/path-change-check.fio 340s 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 340s fio-3.37 340s Starting 1 thread 521s 521s verify-phase: (groupid=0, jobs=1): err= 0: pid=5679: Fri Jul 19 18:19:06 2024 521s read: IOPS=3449, BW=216MiB/s (226MB/s)(37.9GiB/180001msec) 521s clat (usec): min=85, max=71981, avg=267.36, stdev=359.93 521s lat (usec): min=86, max=71981, avg=267.46, stdev=359.93 521s clat percentiles (usec): 521s | 1.00th=[ 133], 5.00th=[ 151], 10.00th=[ 165], 20.00th=[ 192], 521s | 30.00th=[ 206], 40.00th=[ 217], 50.00th=[ 233], 60.00th=[ 258], 521s | 70.00th=[ 293], 80.00th=[ 334], 90.00th=[ 375], 95.00th=[ 424], 521s | 99.00th=[ 685], 99.50th=[ 1057], 99.90th=[ 1516], 99.95th=[ 1795], 521s | 99.99th=[10028] 521s bw ( KiB/s): min=117226, max=368768, per=100.00%, avg=220982.89, stdev=53850.15, samples=359 521s iops : min= 1831, max= 5762, avg=3452.77, stdev=841.40, samples=359 521s lat (usec) : 100=0.55%, 250=55.60%, 500=42.48%, 750=0.42%, 1000=0.35% 521s lat (msec) : 2=0.55%, 4=0.03%, 10=0.01%, 20=0.01%, 50=0.01% 521s lat (msec) : 100=0.01% 521s cpu : usr=9.76%, sys=7.34%, ctx=621002, majf=0, minf=1 521s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 521s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 521s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 521s issued rwts: total=620894,0,0,0 short=0,0,0,0 dropped=0,0,0,0 521s latency : target=0, window=0, percentile=100.00%, depth=1 521s 521s Run status group 0 (all jobs): 521s READ: bw=216MiB/s (226MB/s), 216MiB/s-216MiB/s (226MB/s-226MB/s), io=37.9GiB (40.7GB), run=180001-180001msec 521s 521s Disk stats (read/write): 521s dm-0: ios=621214/10, sectors=79456824/12928, merge=20/9, ticks=167270/68, in_queue=167381, util=99.86%, aggrios=42082/2, aggsectors=5382126/3232, aggrmerge=0/0, aggrticks=10747/6, aggrin_queue=10753, aggrutil=99.17% 521s sdd: ios=33089/0, sectors=4232448/0, merge=0/0, ticks=8574/0, in_queue=8573, util=32.94% 521s sdb: ios=29706/9, sectors=3799424/12928, merge=0/0, ticks=8511/24, in_queue=8535, util=99.17% 521s sde: ios=71034/0, sectors=9085824/0, merge=0/0, ticks=17202/0, in_queue=17202, util=39.76% 521s sdc: ios=34499/0, sectors=4410808/0, merge=0/0, ticks=8702/0, in_queue=8702, util=50.15% 521s + date +Post FIO %H:%M:%S.%N 521s Post FIO 18:19:06.174756751 521s FIO verify test with changing paths - OK 521s Report log of background activity 521s + echo FIO verify test with changing paths - OK 521s + echo Report log of background activity 521s + cat /tmp/autopkgtest.8AodB3/tgtbasedmpaths-artifacts/test-background.log 521s + iscsiadm --mode session 521s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s + sleep 10s 521s + date +MP report (expect 4) %H:%M:%S.%N 521s MP report (expect 4) 18:16:15.776948107 521s + multipath -ll 521s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 521s size=100M features='0' hwhandler='0' wp=rw 521s |-+- policy='service-time 0' prio=1 status=active 521s | `- 1:0:0:1 sdb 8:16 active ready running 521s |-+- policy='service-time 0' prio=1 status=enabled 521s | `- 2:0:0:1 sdc 8:32 active ready running 521s |-+- policy='service-time 0' prio=1 status=enabled 521s | `- 3:0:0:1 sdd 8:48 active ready running 521s `-+- policy='service-time 0' prio=1 status=enabled 521s `- 4:0:0:1 sde 8:64 active ready running 521s + date +UN-plug path 1 %H:%M:%S.%N 521s UN-plug path 1 18:16:15.802622880 521s + iscsiadm --mode session -r 1 -u 521s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 521s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 521s + iscsiadm --mode session 521s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s + sleep 10s 521s + date +MP report (expect 3) %H:%M:%S.%N 521s MP report (expect 3) 18:16:25.905135126 521s + multipath -ll 521s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 521s size=100M features='0' hwhandler='0' wp=rw 521s |-+- policy='service-time 0' prio=1 status=active 521s | `- 2:0:0:1 sdc 8:32 active ready running 521s |-+- policy='service-time 0' prio=1 status=enabled 521s | `- 3:0:0:1 sdd 8:48 active ready running 521s `-+- policy='service-time 0' prio=1 status=enabled 521s `- 4:0:0:1 sde 8:64 active ready running 521s + date +UN-plug path 2 %H:%M:%S.%N 521s UN-plug path 2 18:16:25.928947443 521s + iscsiadm --mode session -r 2 -u 521s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 521s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 521s + iscsiadm --mode session 521s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s + sleep 10s 521s + date +MP report (expect 2) %H:%M:%S.%N 521s MP report (expect 2) 18:16:36.040488413 521s + multipath -ll 521s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 521s size=100M features='0' hwhandler='0' wp=rw 521s |-+- policy='service-time 0' prio=1 status=active 521s | `- 3:0:0:1 sdd 8:48 active ready running 521s `-+- policy='service-time 0' prio=1 status=enabled 521s `- 4:0:0:1 sde 8:64 active ready running 521s + date +UN-plug path 3 %H:%M:%S.%N 521s UN-plug path 3 18:16:36.058655595 521s + iscsiadm --mode session -r 3 -u 521s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 521s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 521s + iscsiadm --mode session 521s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s + sleep 10s 521s + date +MP report (expect 1) %H:%M:%S.%N 521s MP report (expect 1) 18:16:46.139039028 521s + multipath -ll 521s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 521s size=100M features='0' hwhandler='0' wp=rw 521s `-+- policy='service-time 0' prio=1 status=active 521s `- 4:0:0:1 sde 8:64 active ready running 521s + date +Add paths 5/6/7/8 %H:%M:%S.%N 521s Add paths 5/6/7/8 18:16:46.152961897 521s + iscsiadm --mode session -r 4 --op new 521s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 521s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 521s + iscsiadm --mode session -r 4 --op new 521s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 521s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 521s + iscsiadm --mode session -r 4 --op new 521s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 521s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 521s + iscsiadm --mode session -r 4 --op new 521s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 521s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 521s + iscsiadm --mode session 521s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s + sleep 10s 521s + date +MP report (expect 5) %H:%M:%S.%N 521s MP report (expect 5) 18:16:56.262065987 521s + multipath -ll 521s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 521s size=100M features='0' hwhandler='0' wp=rw 521s |-+- policy='service-time 0' prio=1 status=active 521s | `- 4:0:0:1 sde 8:64 active ready running 521s |-+- policy='service-time 0' prio=1 status=enabled 521s | `- 1:0:0:1 sdb 8:16 active ready running 521s |-+- policy='service-time 0' prio=1 status=enabled 521s | `- 2:0:0:1 sdc 8:32 active ready running 521s |-+- policy='service-time 0' prio=1 status=enabled 521s | `- 3:0:0:1 sdd 8:48 active ready running 521s `-+- policy='service-time 0' prio=1 status=enabled 521s `- 5:0:0:1 sdf 8:80 active ready running 521s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 521s UN-plug multiple paths 4/7/8 18:16:56.291156960 521s + iscsiadm --mode session -r 4 -u 521s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 521s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 521s + iscsiadm --mode session -r 7 -u 521s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 521s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 521s + iscsiadm --mode session -r 8 -u 521s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 521s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 521s + iscsiadm --mode session 521s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 521s + sleep 10s 521s + date +Restart multipath daemon %H:%M:%S.%N 521s Restart multipath daemon 18:17:06.560668998 521s + systemctl restart multipathd 521s + sleep 10s 521s + date +Final background report (expect 2) %H:%M:%S.%N 521s Final background report (expect 2) 18:17:16.651244877 521s + multipath -ll 521s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 521s size=100M features='0' hwhandler='0' wp=rw 521s |-+- policy='service-time 0' prio=1 status=active 521s | `- 1:0:0:1 sdb 8:16 active ready running 521s `-+- policy='service-time 0' prio=1 status=enabled 521s `- 2:0:0:1 sdc 8:32 active ready running 521s Final stats 521s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 521s iSCSI SNMP: 521s txdata_octets: 21648840 521s rxdata_octets: 29534792244 521s noptx_pdus: 0 521s scsicmd_pdus: 450750 521s tmfcmd_pdus: 0 521s login_pdus: 0 521s text_pdus: 0 521s dataout_pdus: 0 521s logout_pdus: 0 521s snack_pdus: 0 521s noprx_pdus: 0 521s scsirsp_pdus: 450750 521s tmfrsp_pdus: 0 521s textrsp_pdus: 0 521s datain_pdus: 450717 521s logoutrsp_pdus: 0 521s r2t_pdus: 0 521s async_pdus: 0 521s rjt_pdus: 0 521s digest_err: 0 521s timeout_err: 0 521s iSCSI Extended: 521s tx_sendpage_failures: 0 521s rx_discontiguous_hdr: 0 521s eh_abort_cnt: 0 521s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 521s iSCSI SNMP: 521s txdata_octets: 6360 521s rxdata_octets: 1514820 521s noptx_pdus: 0 521s scsicmd_pdus: 103 521s tmfcmd_pdus: 0 521s login_pdus: 0 521s text_pdus: 0 521s dataout_pdus: 0 521s logout_pdus: 0 521s snack_pdus: 0 521s noprx_pdus: 0 521s scsirsp_pdus: 103 521s tmfrsp_pdus: 0 521s textrsp_pdus: 0 521s datain_pdus: 83 521s logoutrsp_pdus: 0 521s r2t_pdus: 0 521s async_pdus: 0 521s rjt_pdus: 0 521s digest_err: 0 521s timeout_err: 0 521s iSCSI Extended: 521s tx_sendpage_failures: 0 521s rx_discontiguous_hdr: 0 521s eh_abort_cnt: 0 521s + sync 521s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 521s + echo Final stats 521s + iscsiadm --mode session --stats 521s + journalctl --no-pager -u multipathd 521s Jul 18 19:19:12 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 521s Jul 18 19:19:12 ubuntu multipathd[329]: multipathd v0.9.4: start up 521s Jul 18 19:19:12 ubuntu multipathd[329]: reconfigure: setting up paths and maps 521s Jul 18 19:19:12 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 521s Jul 18 19:22:11 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 multipathd[329]: multipathd: shut down 521s Jul 18 19:22:11 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 521s Jul 18 19:22:11 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 systemd[1]: multipathd.service: Deactivated successfully. 521s Jul 18 19:22:11 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 521s -- Boot e061583029b24e33ae8a18beeeae36e5 -- 521s Jul 18 19:22:37 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 521s Jul 18 19:22:37 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 multipathd[289]: multipathd v0.9.4: start up 521s Jul 18 19:22:37 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 multipathd[289]: reconfigure: setting up paths and maps 521s Jul 18 19:22:37 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 521s Jul 18 19:22:56 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 multipathd[289]: multipathd: shut down 521s Jul 18 19:22:56 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 521s Jul 18 19:22:56 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 systemd[1]: multipathd.service: Deactivated successfully. 521s Jul 18 19:22:56 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 521s -- Boot 84ce3e5806f2413fb9d4930160f12020 -- 521s Jul 19 18:14:13 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 521s Jul 19 18:14:13 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 multipathd[341]: multipathd v0.9.4: start up 521s Jul 19 18:14:13 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 multipathd[341]: reconfigure: setting up paths and maps 521s Jul 19 18:14:13 auto-syncubuntu-oracular-daily-ppc64el-server-20240627-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 521s Jul 19 18:14:53 autopkgtest multipathd[341]: multipathd: shut down 521s Jul 19 18:14:53 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 521s Jul 19 18:14:53 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 521s Jul 19 18:14:53 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 521s -- Boot c2ca0e1c94504a308b205c06bcaf6f7d -- 521s Jul 19 18:15:18 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 521s Jul 19 18:15:18 autopkgtest multipathd[343]: multipathd v0.9.9: start up 521s Jul 19 18:15:18 autopkgtest multipathd[343]: reconfigure: setting up paths and maps 521s Jul 19 18:15:18 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 521s Jul 19 18:15:55 autopkgtest multipathd[343]: updated bindings file /etc/multipath/bindings 521s Jul 19 18:15:55 autopkgtest multipathd[343]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:16 1] 521s Jul 19 18:15:55 autopkgtest multipathd[343]: sdb [8:16]: path added to devmap mpatha 521s Jul 19 18:15:55 autopkgtest multipathd[343]: mpatha: performing delayed actions 521s Jul 19 18:15:55 autopkgtest multipathd[343]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 521s Jul 19 18:16:15 autopkgtest multipathd[343]: sdb: mark as failed 521s Jul 19 18:16:15 autopkgtest multipathd[343]: mpatha: remaining active paths: 3 521s Jul 19 18:16:15 autopkgtest multipathd[343]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 521s Jul 19 18:16:15 autopkgtest multipathd[343]: check_removed_paths: sdb: freeing path in removed state 521s Jul 19 18:16:15 autopkgtest multipathd[343]: 8:16: path removed from map mpatha 521s Jul 19 18:16:25 autopkgtest multipathd[343]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 521s Jul 19 18:16:25 autopkgtest multipathd[343]: check_removed_paths: sdc: freeing path in removed state 521s Jul 19 18:16:25 autopkgtest multipathd[343]: 8:32: path removed from map mpatha 521s Jul 19 18:16:36 autopkgtest multipathd[343]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 521s Jul 19 18:16:36 autopkgtest multipathd[343]: check_removed_paths: sdd: freeing path in removed state 521s Jul 19 18:16:36 autopkgtest multipathd[343]: 8:48: path removed from map mpatha 521s Jul 19 18:16:46 autopkgtest multipathd[343]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1] 521s Jul 19 18:16:46 autopkgtest multipathd[343]: sdb [8:16]: path added to devmap mpatha 521s Jul 19 18:16:46 autopkgtest multipathd[343]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 521s Jul 19 18:16:46 autopkgtest multipathd[343]: sdc [8:32]: path added to devmap mpatha 521s Jul 19 18:16:46 autopkgtest multipathd[343]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 521s Jul 19 18:16:46 autopkgtest multipathd[343]: sdd [8:48]: path added to devmap mpatha 521s Jul 19 18:16:46 autopkgtest multipathd[343]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:80 1] 521s Jul 19 18:16:46 autopkgtest multipathd[343]: sdf [8:80]: path added to devmap mpatha 521s Jul 19 18:16:56 autopkgtest multipathd[343]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:80 1] 521s Jul 19 18:16:56 autopkgtest multipathd[343]: check_removed_paths: sde: freeing path in removed state 521s Jul 19 18:16:56 autopkgtest multipathd[343]: 8:64: path removed from map mpatha 521s Jul 19 18:16:56 autopkgtest multipathd[343]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:80 1] 521s Jul 19 18:16:56 autopkgtest multipathd[343]: check_removed_paths: sdd: freeing path in removed state 521s Jul 19 18:16:56 autopkgtest multipathd[343]: 8:48: path removed from map mpatha 521s Jul 19 18:16:56 autopkgtest multipathd[343]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 521s Jul 19 18:16:56 autopkgtest multipathd[343]: check_removed_paths: sdf: freeing path in removed state 521s Jul 19 18:16:56 autopkgtest multipathd[343]: 8:80: path removed from map mpatha 521s Jul 19 18:17:06 autopkgtest multipathd[343]: multipathd: shut down 521s Jul 19 18:17:06 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 521s Jul 19 18:17:06 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 521s Jul 19 18:17:06 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 521s Jul 19 18:17:06 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 521s Jul 19 18:17:06 autopkgtest multipathd[6054]: multipathd v0.9.9: start up 521s Jul 19 18:17:06 autopkgtest multipathd[6054]: reconfigure: setting up paths and maps 521s Jul 19 18:17:06 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 521s Check final path status 521s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 521s size=100M features='0' hwhandler='0' wp=rw 521s |-+- policy='service-time 0' prio=1 status=active 521s | `- 1:0:0:1 sdb 8:16 active ready running 521s `-+- policy='service-time 0' prio=1 status=enabled 521s `- 2:0:0:1 sdc 8:32 active ready running 521s + echo Check final path status 521s + multipath -ll 521s + multipath -ll 521s + grep --count status= 521s + diskc=2 521s + multipath -ll 521s + grep --count status=active 521s + diska=1 521s + multipath -ll 521s + grep --count status=enabled 521s OK 521s + diske=1 521s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 521s + echo OK 521s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 521s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 521s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 521s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 521s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 521s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 521s autopkgtest [18:19:06]: test tgtbasedmpaths: -----------------------] 522s tgtbasedmpaths PASS 522s autopkgtest [18:19:07]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 522s autopkgtest [18:19:07]: @@@@@@@@@@@@@@@@@@@@ summary 522s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 522s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 522s kpartx-file-loopback PASS 522s tgtbasedmpaths PASS 533s nova [W] Using flock in scalingstack-bos02-ppc64el 533s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240719-181024-juju-7f2275-prod-proposed-migration-environment-3-67678cb5-a0f6-4962-8b45-754a68dce57f from image adt/ubuntu-oracular-ppc64el-server-20240718.img (UUID 6fad9917-f273-44a6-b1d3-11b852a5c60f)... 533s nova [W] Using flock in scalingstack-bos02-ppc64el 533s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240719-181024-juju-7f2275-prod-proposed-migration-environment-3-67678cb5-a0f6-4962-8b45-754a68dce57f from image adt/ubuntu-oracular-ppc64el-server-20240718.img (UUID 6fad9917-f273-44a6-b1d3-11b852a5c60f)...