0s autopkgtest [21:16:33]: starting date and time: 2024-10-04 21:16:33+0000 0s autopkgtest [21:16:33]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [21:16:33]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.5eymx0w_/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:lvm2 --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=lvm2/2.03.22-1ubuntu2 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos02-ppc64el-20.secgroup --name adt-oracular-ppc64el-multipath-tools-20241004-211633-juju-7f2275-prod-proposed-migration-environment-2-d59909f8-c494-4b5f-b9c6-0c3ddeee0ee6 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --net-id=net_prod-proposed-migration -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 73s autopkgtest [21:17:46]: testbed dpkg architecture: ppc64el 73s autopkgtest [21:17:46]: testbed apt version: 2.9.8 73s autopkgtest [21:17:46]: @@@@@@@@@@@@@@@@@@@@ test bed setup 74s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [265 kB] 75s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [163 kB] 75s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [20.0 kB] 75s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3692 B] 75s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [33.4 kB] 75s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [384 B] 75s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 75s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [131 kB] 75s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [4500 B] 75s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 76s Fetched 622 kB in 1s (893 kB/s) 76s Reading package lists... 79s Reading package lists... 79s Building dependency tree... 79s Reading state information... 79s Calculating upgrade... 79s The following packages will be upgraded: 79s dmsetup libdevmapper1.02.1 79s 2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 79s Need to get 273 kB of archives. 79s After this operation, 0 B of additional disk space will be used. 79s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libdevmapper1.02.1 ppc64el 2:1.02.196-1ubuntu2 [182 kB] 80s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dmsetup ppc64el 2:1.02.196-1ubuntu2 [91.8 kB] 80s Fetched 273 kB in 0s (595 kB/s) 80s (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 ... 73620 files and directories currently installed.) 80s Preparing to unpack .../libdevmapper1.02.1_2%3a1.02.196-1ubuntu2_ppc64el.deb ... 80s Unpacking libdevmapper1.02.1:ppc64el (2:1.02.196-1ubuntu2) over (2:1.02.196-1ubuntu1) ... 80s Preparing to unpack .../dmsetup_2%3a1.02.196-1ubuntu2_ppc64el.deb ... 80s Unpacking dmsetup (2:1.02.196-1ubuntu2) over (2:1.02.196-1ubuntu1) ... 81s Setting up libdevmapper1.02.1:ppc64el (2:1.02.196-1ubuntu2) ... 81s Setting up dmsetup (2:1.02.196-1ubuntu2) ... 81s Processing triggers for libc-bin (2.40-1ubuntu3) ... 81s Processing triggers for man-db (2.12.1-3) ... 81s Processing triggers for initramfs-tools (0.142ubuntu34) ... 81s update-initramfs: Generating /boot/initrd.img-6.11.0-8-generic 81s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 90s Reading package lists... 90s Building dependency tree... 90s Reading state information... 90s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 91s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 91s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 91s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 91s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 92s Reading package lists... 92s Reading package lists... 92s Building dependency tree... 92s Reading state information... 92s Calculating upgrade... 92s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 92s Reading package lists... 93s Building dependency tree... 93s Reading state information... 93s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 93s autopkgtest [21:18:06]: rebooting testbed after setup commands that affected boot 127s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 138s autopkgtest [21:18:51]: testbed running kernel: Linux 6.11.0-8-generic #8-Ubuntu SMP Mon Sep 16 13:49:23 UTC 2024 141s autopkgtest [21:18:54]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 144s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (dsc) [2772 B] 144s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (tar) [588 kB] 144s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (diff) [42.7 kB] 144s gpgv: Signature made Thu Sep 5 17:42:16 2024 UTC 144s gpgv: using RSA key 63EEFC3DE14D5146CE7F24BF34B8AD7D9529E793 144s gpgv: Can't check signature: No public key 144s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.9-1ubuntu3.dsc: no acceptable signature found 144s autopkgtest [21:18:57]: testing package multipath-tools version 0.9.9-1ubuntu3 144s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 144s autopkgtest [21:18:57]: build not needed 147s autopkgtest [21:19:00]: test kpartx-file-loopback: preparing testbed 147s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 148s Reading package lists... 148s Building dependency tree... 148s Reading state information... 148s Starting pkgProblemResolver with broken count: 0 148s Starting 2 pkgProblemResolver with broken count: 0 148s Done 148s The following additional packages will be installed: 148s liburing2 qemu-utils 148s Recommended packages: 148s qemu-block-extra 148s The following NEW packages will be installed: 148s autopkgtest-satdep liburing2 qemu-utils 148s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 148s Need to get 2431 kB/2432 kB of archives. 148s After this operation, 16.9 MB of additional disk space will be used. 148s Get:1 /tmp/autopkgtest.xWL77y/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 148s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 149s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:9.0.2+ds-4ubuntu5 [2404 kB] 149s Fetched 2431 kB in 1s (3459 kB/s) 149s Selecting previously unselected package liburing2:ppc64el. 150s (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 ... 73620 files and directories currently installed.) 150s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 150s Unpacking liburing2:ppc64el (2.6-1) ... 150s Selecting previously unselected package qemu-utils. 150s Preparing to unpack .../qemu-utils_1%3a9.0.2+ds-4ubuntu5_ppc64el.deb ... 150s Unpacking qemu-utils (1:9.0.2+ds-4ubuntu5) ... 150s Selecting previously unselected package autopkgtest-satdep. 150s Preparing to unpack .../1-autopkgtest-satdep.deb ... 150s Unpacking autopkgtest-satdep (0) ... 150s Setting up liburing2:ppc64el (2.6-1) ... 150s Setting up qemu-utils (1:9.0.2+ds-4ubuntu5) ... 150s Setting up autopkgtest-satdep (0) ... 150s Processing triggers for man-db (2.12.1-3) ... 151s Processing triggers for libc-bin (2.40-1ubuntu3) ... 153s (Reading database ... 73644 files and directories currently installed.) 153s Removing autopkgtest-satdep (0) ... 153s autopkgtest [21:19:06]: test kpartx-file-loopback: [----------------------- 154s Formatting 'foo.img', fmt=raw size=20971520 155s Creating new GPT entries in memory. 155s Warning: The kernel is still using the old partition table. 155s The new table will be used at the next reboot or after you 155s run partprobe(8) or kpartx(8) 155s The operation has completed successfully. 155s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 155s standard_filename: OK 155s del devmap : loop0p1 155s No devices found 155s standard_filename_cleanup: OK 155s Formatting 'fou du FaFa.img', fmt=raw size=20971520 156s Creating new GPT entries in memory. 156s Warning: The kernel is still using the old partition table. 156s The new table will be used at the next reboot or after you 156s run partprobe(8) or kpartx(8) 156s The operation has completed successfully. 156s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 156s filename_with_spaces: OK 156s del devmap : loop0p1 156s No devices found 156s filename_with_spaces_cleanup: OK 156s autopkgtest [21:19:09]: test kpartx-file-loopback: -----------------------] 157s kpartx-file-loopback PASS 157s autopkgtest [21:19:10]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 157s autopkgtest [21:19:10]: test tgtbasedmpaths: preparing testbed 262s autopkgtest [21:20:55]: testbed dpkg architecture: ppc64el 262s autopkgtest [21:20:55]: testbed apt version: 2.9.8 262s autopkgtest [21:20:55]: @@@@@@@@@@@@@@@@@@@@ test bed setup 263s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [265 kB] 264s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [163 kB] 264s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [20.0 kB] 264s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [3692 B] 264s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [33.4 kB] 264s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [384 B] 264s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 264s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [131 kB] 264s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [4500 B] 264s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 266s Fetched 622 kB in 1s (881 kB/s) 266s Reading package lists... 268s Reading package lists... 268s Building dependency tree... 268s Reading state information... 268s Calculating upgrade... 268s The following packages will be upgraded: 268s dmsetup libdevmapper1.02.1 268s 2 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 268s Need to get 273 kB of archives. 268s After this operation, 0 B of additional disk space will be used. 268s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libdevmapper1.02.1 ppc64el 2:1.02.196-1ubuntu2 [182 kB] 269s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dmsetup ppc64el 2:1.02.196-1ubuntu2 [91.8 kB] 269s Fetched 273 kB in 0s (556 kB/s) 269s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 73620 files and directories currently installed.) 269s Preparing to unpack .../libdevmapper1.02.1_2%3a1.02.196-1ubuntu2_ppc64el.deb ... 269s Unpacking libdevmapper1.02.1:ppc64el (2:1.02.196-1ubuntu2) over (2:1.02.196-1ubuntu1) ... 269s Preparing to unpack .../dmsetup_2%3a1.02.196-1ubuntu2_ppc64el.deb ... 269s Unpacking dmsetup (2:1.02.196-1ubuntu2) over (2:1.02.196-1ubuntu1) ... 269s Setting up libdevmapper1.02.1:ppc64el (2:1.02.196-1ubuntu2) ... 269s Setting up dmsetup (2:1.02.196-1ubuntu2) ... 269s Processing triggers for libc-bin (2.40-1ubuntu3) ... 269s Processing triggers for man-db (2.12.1-3) ... 270s Processing triggers for initramfs-tools (0.142ubuntu34) ... 270s update-initramfs: Generating /boot/initrd.img-6.11.0-8-generic 270s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 279s Reading package lists... 279s Building dependency tree... 279s Reading state information... 279s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 280s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 280s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 280s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 280s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 281s Reading package lists... 281s Reading package lists... 281s Building dependency tree... 281s Reading state information... 281s Calculating upgrade... 281s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 281s Reading package lists... 281s Building dependency tree... 281s Reading state information... 281s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 282s autopkgtest [21:21:15]: rebooting testbed after setup commands that affected boot 316s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 330s Reading package lists... 331s Building dependency tree... 331s Reading state information... 331s Starting pkgProblemResolver with broken count: 0 331s Starting 2 pkgProblemResolver with broken count: 0 331s Done 331s The following additional packages will be installed: 331s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 331s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 331s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 331s librdmacm1t64 lsscsi open-iscsi tgt 331s Suggested packages: 331s fio-examples gnuplot tgt-glusterfs tgt-rbd 331s Recommended packages: 331s finalrd 331s The following NEW packages will be installed: 331s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 331s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 331s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 331s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 331s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 331s Need to get 11.0 MB/11.0 MB of archives. 331s After this operation, 50.0 MB of additional disk space will be used. 331s Get:1 /tmp/autopkgtest.xWL77y/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 331s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 332s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 332s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 332s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2ubuntu1 [80.6 kB] 332s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 332s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 332s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-5ubuntu1 [21.7 kB] 332s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-5ubuntu1 [308 kB] 332s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-5ubuntu1 [46.3 kB] 332s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-5ubuntu1 [99.1 kB] 332s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.3-1 [99.2 kB] 332s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2.2ubuntu1 [23.7 kB] 332s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2.2ubuntu1 [73.4 kB] 332s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 332s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3.2ubuntu2 [260 kB] 332s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3.2ubuntu2 [281 kB] 332s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0-0ubuntu1 [4193 kB] 332s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 332s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0-0ubuntu1 [3714 kB] 332s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 332s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 333s Preconfiguring packages ... 333s Fetched 11.0 MB in 1s (11.2 MB/s) 333s Selecting previously unselected package libopeniscsiusr. 333s (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 ... 73620 files and directories currently installed.) 333s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 333s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 333s Selecting previously unselected package libisns0t64:ppc64el. 333s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 333s Unpacking libisns0t64:ppc64el (0.101-1) ... 333s Selecting previously unselected package open-iscsi. 333s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 333s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 333s Selecting previously unselected package librdmacm1t64:ppc64el. 333s Preparing to unpack .../03-librdmacm1t64_52.0-2ubuntu1_ppc64el.deb ... 333s Unpacking librdmacm1t64:ppc64el (52.0-2ubuntu1) ... 333s Selecting previously unselected package libconfig-general-perl. 333s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 333s Unpacking libconfig-general-perl (2.65-2) ... 333s Selecting previously unselected package tgt. 333s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 333s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 333s Selecting previously unselected package libgfxdr0:ppc64el. 333s Preparing to unpack .../06-libgfxdr0_11.1-5ubuntu1_ppc64el.deb ... 333s Unpacking libgfxdr0:ppc64el (11.1-5ubuntu1) ... 333s Selecting previously unselected package libglusterfs0:ppc64el. 333s Preparing to unpack .../07-libglusterfs0_11.1-5ubuntu1_ppc64el.deb ... 333s Unpacking libglusterfs0:ppc64el (11.1-5ubuntu1) ... 333s Selecting previously unselected package libgfrpc0:ppc64el. 333s Preparing to unpack .../08-libgfrpc0_11.1-5ubuntu1_ppc64el.deb ... 333s Unpacking libgfrpc0:ppc64el (11.1-5ubuntu1) ... 333s Selecting previously unselected package libgfapi0:ppc64el. 333s Preparing to unpack .../09-libgfapi0_11.1-5ubuntu1_ppc64el.deb ... 333s Unpacking libgfapi0:ppc64el (11.1-5ubuntu1) ... 333s Selecting previously unselected package libnbd0. 333s Preparing to unpack .../10-libnbd0_1.20.3-1_ppc64el.deb ... 333s Unpacking libnbd0 (1.20.3-1) ... 333s Selecting previously unselected package libdaxctl1:ppc64el. 333s Preparing to unpack .../11-libdaxctl1_77-2.2ubuntu1_ppc64el.deb ... 333s Unpacking libdaxctl1:ppc64el (77-2.2ubuntu1) ... 333s Selecting previously unselected package libndctl6:ppc64el. 333s Preparing to unpack .../12-libndctl6_77-2.2ubuntu1_ppc64el.deb ... 333s Unpacking libndctl6:ppc64el (77-2.2ubuntu1) ... 333s Selecting previously unselected package libpmem1:ppc64el. 333s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 333s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 333s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 333s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 333s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 333s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 333s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 333s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 333s Selecting previously unselected package librados2. 333s Preparing to unpack .../16-librados2_19.2.0-0ubuntu1_ppc64el.deb ... 333s Unpacking librados2 (19.2.0-0ubuntu1) ... 334s Selecting previously unselected package libpmemobj1:ppc64el. 334s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 334s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 334s Selecting previously unselected package librbd1. 334s Preparing to unpack .../18-librbd1_19.2.0-0ubuntu1_ppc64el.deb ... 334s Unpacking librbd1 (19.2.0-0ubuntu1) ... 334s Selecting previously unselected package fio. 334s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 334s Unpacking fio (3.37-1) ... 334s Selecting previously unselected package lsscsi. 334s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 334s Unpacking lsscsi (0.32-1build1) ... 334s Selecting previously unselected package autopkgtest-satdep. 334s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 334s Unpacking autopkgtest-satdep (0) ... 334s Setting up libconfig-general-perl (2.65-2) ... 334s Setting up libisns0t64:ppc64el (0.101-1) ... 334s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 334s Setting up libnbd0 (1.20.3-1) ... 334s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 334s Setting up libglusterfs0:ppc64el (11.1-5ubuntu1) ... 334s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 334s Setting up lsscsi (0.32-1build1) ... 334s Setting up libdaxctl1:ppc64el (77-2.2ubuntu1) ... 334s Setting up libndctl6:ppc64el (77-2.2ubuntu1) ... 334s Setting up librdmacm1t64:ppc64el (52.0-2ubuntu1) ... 334s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 334s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 335s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 335s Setting up libgfxdr0:ppc64el (11.1-5ubuntu1) ... 335s Setting up librados2 (19.2.0-0ubuntu1) ... 335s Setting up open-iscsi (2.1.10-1ubuntu1) ... 335s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 336s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 336s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 336s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 336s Setting up librbd1 (19.2.0-0ubuntu1) ... 336s Setting up libgfrpc0:ppc64el (11.1-5ubuntu1) ... 336s Setting up libgfapi0:ppc64el (11.1-5ubuntu1) ... 336s Setting up fio (3.37-1) ... 336s Setting up autopkgtest-satdep (0) ... 336s Processing triggers for man-db (2.12.1-3) ... 338s Processing triggers for initramfs-tools (0.142ubuntu34) ... 338s update-initramfs: Generating /boot/initrd.img-6.11.0-8-generic 338s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 346s Processing triggers for libc-bin (2.40-1ubuntu3) ... 348s (Reading database ... 73861 files and directories currently installed.) 348s Removing autopkgtest-satdep (0) ... 350s autopkgtest [21:22:23]: test tgtbasedmpaths: [----------------------- 350s + targetname=iqn.2016-11.foo.com:target.iscsi 350s + pwd 350s + cwd=/tmp/autopkgtest.xWL77y/build.1br/src 350s + testdir=/mnt/tgtmpathtest 350s + localhost=127.0.0.1 350s + portal=127.0.0.1:3260 350s + maxpaths=4 350s + backfn=backingfile 350s + expectwwid=60000000000000000e00000000010001 350s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 350s + bglog=/tmp/autopkgtest.xWL77y/tgtbasedmpaths-artifacts/test-background.log 350s + fioprep=/tmp/autopkgtest.xWL77y/tgtbasedmpaths-artifacts/path-change-prep.fio 350s + fiovrfy=/tmp/autopkgtest.xWL77y/tgtbasedmpaths-artifacts/path-change-check.fio 350s + mkdir -p /etc/multipath 350s + echo /360000000000000000e00000000010001/ 350s + service tgt restart 350s + truncate --size 100M backingfile 350s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 350s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 350s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.xWL77y/build.1br/src/backingfile 350s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 350s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 350s login #1 350s + echo login #1 350s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 350s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 350s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 350s + seq 2 4 350s extra login #2 350s + echo extra login #2 350s + iscsiadm --mode session -r 1 --op new 350s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 350s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 350s extra login #3 350s + echo extra login #3 350s + iscsiadm --mode session -r 1 --op new 350s + echo extra login #4 350s + iscsiadm --mode session -r 1 --op new 350s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 350s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 350s extra login #4 350s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 350s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 350s + udevadm settle 351s + sleep 5 356s Status after initial setup 356s + echo Status after initial setup 356s + tgtadm --lld iscsi --mode target --op show 356s Target 1: iqn.2016-11.foo.com:target.iscsi 356s System information: 356s Driver: iscsi 356s State: ready 356s I_T nexus information: 356s I_T nexus: 1 356s Initiator: iqn.2004-10.com.ubuntu:01:ecae2dfa2391 alias: autopkgtest 356s Connection: 0 356s IP Address: 127.0.0.1 356s I_T nexus: 2 356s Initiator: iqn.2004-10.com.ubuntu:01:ecae2dfa2391 alias: autopkgtest 356s Connection: 0 356s IP Address: 127.0.0.1 356s I_T nexus: 3 356s Initiator: iqn.2004-10.com.ubuntu:01:ecae2dfa2391 alias: autopkgtest 356s Connection: 0 356s IP Address: 127.0.0.1 356s I_T nexus: 4 356s Initiator: iqn.2004-10.com.ubuntu:01:ecae2dfa2391 alias: autopkgtest 356s Connection: 0 356s IP Address: 127.0.0.1 356s LUN information: 356s LUN: 0 356s Type: controller 356s SCSI ID: IET 00010000 356s SCSI SN: beaf10 356s Size: 0 MB, Block size: 1 356s Online: Yes 356s Removable media: No 356s Prevent removal: No 356s Readonly: No 356s SWP: No 356s Thin-provisioning: No 356s Backing store type: null 356s Backing store path: None 356s Backing store flags: 356s LUN: 1 356s Type: disk 356s SCSI ID: IET 00010001 356s SCSI SN: beaf11 356s Size: 105 MB, Block size: 512 356s Online: Yes 356s Removable media: No 356s Prevent removal: No 356s Readonly: No 356s SWP: No 356s Thin-provisioning: No 356s Backing store type: rdwr 356s Backing store path: /tmp/autopkgtest.xWL77y/build.1br/src/backingfile 356s Backing store flags: 356s Account information: 356s ACL information: 356s ALL 356s + tgtadm --lld iscsi --op show --mode conn --tid 1 356s + iscsiadm --mode session -P 1 356s Session: 4 356s Connection: 0 356s Initiator: iqn.2004-10.com.ubuntu:01:ecae2dfa2391 356s IP Address: 127.0.0.1 356s Session: 3 356s Connection: 0 356s Initiator: iqn.2004-10.com.ubuntu:01:ecae2dfa2391 356s IP Address: 127.0.0.1 356s Session: 2 356s Connection: 0 356s Initiator: iqn.2004-10.com.ubuntu:01:ecae2dfa2391 356s IP Address: 127.0.0.1 356s Session: 1 356s Connection: 0 356s Initiator: iqn.2004-10.com.ubuntu:01:ecae2dfa2391 356s IP Address: 127.0.0.1 356s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 356s Current Portal: 127.0.0.1:3260,1 356s Persistent Portal: 127.0.0.1:3260,1 356s ********** 356s Interface: 356s ********** 356s Iface Name: default 356s Iface Transport: tcp 356s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ecae2dfa2391 356s Iface IPaddress: 127.0.0.1 356s Iface HWaddress: default 356s Iface Netdev: default 356s SID: 1 356s iSCSI Connection State: LOGGED IN 356s iSCSI Session State: LOGGED_IN 356s Internal iscsid Session State: NO CHANGE 356s 356s ********** 356s Interface: 356s ********** 356s Iface Name: default 356s Iface Transport: tcp 356s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ecae2dfa2391 356s Iface IPaddress: 127.0.0.1 356s Iface HWaddress: default 356s Iface Netdev: default 356s SID: 2 356s iSCSI Connection State: LOGGED IN 356s iSCSI Session State: LOGGED_IN 356s Internal iscsid Session State: NO CHANGE 356s 356s ********** 356s Interface: 356s ********** 356s Iface Name: default 356s Iface Transport: tcp 356s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ecae2dfa2391 356s Iface IPaddress: 127.0.0.1 356s Iface HWaddress: default 356s Iface Netdev: default 356s SID: 3 356s iSCSI Connection State: LOGGED IN 356s iSCSI Session State: LOGGED_IN 356s Internal iscsid Session State: NO CHANGE 356s 356s ********** 356s Interface: 356s ********** 356s Iface Name: default 356s Iface Transport: tcp 356s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:ecae2dfa2391 356s Iface IPaddress: 127.0.0.1 356s Iface HWaddress: default 356s Iface Netdev: default 356s SID: 4 356s iSCSI Connection State: LOGGED IN 356s iSCSI Session State: LOGGED_IN 356s Internal iscsid Session State: NO CHANGE 356s + lsscsi -liv 356s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 356s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 356s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 356s 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] 356s [1:0:0:0] storage IET Controller 0001 - - 356s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 356s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 356s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 356s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 356s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 356s [2:0:0:0] storage IET Controller 0001 - - 356s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 356s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 356s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 356s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 356s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 356s [3:0:0:0] storage IET Controller 0001 - - 356s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 356s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 356s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 356s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 356s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 356s [4:0:0:0] storage IET Controller 0001 - - 356s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 356s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 356s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 33000000100000001 356s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 356s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 356s NVMe module may not be loaded 356s + multipath -v3 -ll 356s 47.916122 | set open fds limit to 1073741816/1073741816 356s 47.916176 | _read_bindings_file: reading /etc/multipath/bindings 356s 47.916200 | loading /usr/lib/multipath/libchecktur.so checker 356s 47.916310 | checker tur: message table size = 4 356s 47.916337 | loading /usr/lib/multipath/libprioconst.so prioritizer 356s 47.916468 | _init_foreign: foreign library "nvme" is not enabled 356s 47.922214 | sda: size = 167772160 356s 47.922382 | sda: vendor = QEMU 356s 47.922423 | sda: product = QEMU HARDDISK 356s 47.922445 | sda: rev = 2.5+ 356s 47.923050 | sda: h:b:t:l = 0:0:0:0 356s 47.923368 | sda: tgt_node_name = 356s 47.923388 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 356s 47.923391 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 356s 47.923532 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 356s 47.923553 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 356s 47.923566 | __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 356s 47.923570 | failed to read sysfs vpd pg80: No such file or directory 356s 47.923764 | sda: fail to get serial 356s 47.923784 | sda: detect_checker = yes (setting: multipath internal) 356s 47.923817 | sda checker timeout = 30 s (setting: kernel sysfs) 356s 47.923912 | sda: path_checker = tur (setting: multipath internal) 356s 47.923977 | sda: tur state = up 356s 47.924288 | sdb: size = 204800 356s 47.924443 | sdb: vendor = IET 356s 47.924482 | sdb: product = VIRTUAL-DISK 356s 47.924504 | sdb: rev = 0001 356s 47.925117 | sdb: h:b:t:l = 1:0:0:1 356s 47.925497 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 356s 47.925518 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 356s 47.925520 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 356s 47.925674 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 356s 47.925694 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 356s 47.925708 | sdb: serial = beaf11 356s 47.925711 | sdb: detect_checker = yes (setting: multipath internal) 356s 47.925737 | sdb checker timeout = 30 s (setting: kernel sysfs) 356s 47.925985 | sdb: path_checker = tur (setting: multipath internal) 356s 47.926177 | sdb: tur state = up 356s 47.926318 | sdc: size = 204800 356s 47.926466 | sdc: vendor = IET 356s 47.926505 | sdc: product = VIRTUAL-DISK 356s 47.926526 | sdc: rev = 0001 356s 47.927201 | sdc: h:b:t:l = 2:0:0:1 356s 47.927558 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 356s 47.927578 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 356s 47.927580 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 356s 47.927727 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 356s 47.927747 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 356s 47.927760 | sdc: serial = beaf11 356s 47.927763 | sdc: detect_checker = yes (setting: multipath internal) 356s 47.927789 | sdc checker timeout = 30 s (setting: kernel sysfs) 356s 47.927929 | sdc: path_checker = tur (setting: multipath internal) 356s 47.927997 | sdc: tur state = up 356s 47.928132 | sdd: size = 204800 356s 47.928281 | sdd: vendor = IET 356s 47.928319 | sdd: product = VIRTUAL-DISK 356s 47.928341 | sdd: rev = 0001 356s 47.929012 | sdd: h:b:t:l = 3:0:0:1 356s 47.929384 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 356s 47.983452 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 356s 47.983455 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 356s 47.983713 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 356s 47.983732 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 356s 47.983745 | sdd: serial = beaf11 356s 47.983747 | sdd: detect_checker = yes (setting: multipath internal) 356s 47.983782 | sdd checker timeout = 30 s (setting: kernel sysfs) 356s 47.983917 | sdd: path_checker = tur (setting: multipath internal) 356s 47.983980 | sdd: tur state = up 356s 47.984177 | sde: size = 204800 356s 47.984384 | sde: vendor = IET 356s 47.984420 | sde: product = VIRTUAL-DISK 356s 47.984440 | sde: rev = 0001 356s 47.985122 | sde: h:b:t:l = 4:0:0:1 356s 47.985518 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 356s 47.985537 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 356s 47.985539 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 356s 47.985716 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 356s 47.985734 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 356s 47.985747 | sde: serial = beaf11 356s 47.985749 | sde: detect_checker = yes (setting: multipath internal) 356s 47.985775 | sde checker timeout = 30 s (setting: kernel sysfs) 356s 47.985986 | sde: path_checker = tur (setting: multipath internal) 356s 47.986153 | sde: tur state = up 356s 47.986294 | loop0: device node name blacklisted 356s 47.986426 | loop1: device node name blacklisted 356s 47.986557 | loop2: device node name blacklisted 356s 47.986685 | loop3: device node name blacklisted 356s ===== paths list ===== 356s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 356s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK,2.5+ unknown 356s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 356s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 356s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 356s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 356s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 356s size=100M features='0' hwhandler='0' wp=rw 356s |-+- policy='service-time 0' prio=1 status=active 356s | `- 1:0:0:1 sdb 8:16 active ready running 356s |-+- policy='service-time 0' prio=1 status=enabled 356s | `- 2:0:0:1 sdc 8:32 active ready running 356s |-+- policy='service-time 0' prio=1 status=enabled 356s | `- 3:0:0:1 sdd 8:48 active ready running 356s `-+- policy='service-time 0' prio=1 status=enabled 356s `- 4:0:0:1 sde 8:64 active ready running 356s 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 356s 47.986822 | loop4: device node name blacklisted 356s 47.986954 | loop5: device node name blacklisted 356s 47.987048 | loop6: device node name blacklisted 356s 47.987141 | loop7: device node name blacklisted 356s 47.987239 | dm-0: device node name blacklisted 356s 47.988342 | multipath-tools v0.9.9 (05/03, 2024) 356s 47.988369 | libdevmapper version 1.02.196 356s 47.988501 | kernel device mapper v4.48.0 356s 47.988527 | DM multipath kernel driver v1.14.0 356s 47.988626 | sdb: size = 204800 356s 47.988646 | sdb: vendor = IET 356s 47.988649 | sdb: product = VIRTUAL-DISK 356s 47.988651 | sdb: rev = 0001 356s 47.989251 | sdb: h:b:t:l = 1:0:0:1 356s 47.989377 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 356s 47.989411 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 356s 47.989414 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 356s 47.989425 | sdb: serial = beaf11 356s 47.989634 | sdb: tur state = up 356s 47.989653 | sdb: uid = 360000000000000000e00000000010001 (udev) 356s 47.989655 | sdb: detect_prio = yes (setting: multipath internal) 356s 47.989658 | sdb: prio = const (setting: multipath internal) 356s 47.989660 | sdb: prio args = "" (setting: multipath internal) 356s 47.989663 | sdb: const prio = 1 356s 47.989684 | sdc: size = 204800 356s 47.989688 | sdc: vendor = IET 356s 47.989691 | sdc: product = VIRTUAL-DISK 356s 47.989693 | sdc: rev = 0001 356s 47.990265 | sdc: h:b:t:l = 2:0:0:1 356s 47.990387 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 356s 47.990420 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 356s 47.990423 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 356s 47.990434 | sdc: serial = beaf11 356s 47.990637 | sdc: tur state = up 356s 47.990655 | sdc: uid = 360000000000000000e00000000010001 (udev) 356s 47.990658 | sdc: detect_prio = yes (setting: multipath internal) 356s 47.990660 | sdc: prio = const (setting: multipath internal) 356s 47.990663 | sdc: prio args = "" (setting: multipath internal) 356s 47.990665 | sdc: const prio = 1 356s 47.990686 | sdd: size = 204800 356s 47.990691 | sdd: vendor = IET 356s 47.990693 | sdd: product = VIRTUAL-DISK 356s 47.990695 | sdd: rev = 0001 356s 47.991266 | sdd: h:b:t:l = 3:0:0:1 356s 47.991389 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 356s 47.991422 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 356s 47.991424 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 356s 47.991435 | sdd: serial = beaf11 356s 47.991629 | sdd: tur state = up 356s 47.991647 | sdd: uid = 360000000000000000e00000000010001 (udev) 356s 47.991649 | sdd: detect_prio = yes (setting: multipath internal) 356s 47.991652 | sdd: prio = const (setting: multipath internal) 356s 47.991654 | sdd: prio args = "" (setting: multipath internal) 356s 47.991656 | sdd: const prio = 1 356s 47.991677 | sde: size = 204800 356s 47.991682 | sde: vendor = IET 356s 47.991685 | sde: product = VIRTUAL-DISK 356s 47.991687 | sde: rev = 0001 356s 47.992280 | sde: h:b:t:l = 4:0:0:1 356s 47.992405 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 356s 47.992438 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 356s 47.992441 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 356s 47.992451 | sde: serial = beaf11 356s 47.993115 | sde: tur state = up 356s 47.993134 | sde: uid = 360000000000000000e00000000010001 (udev) 356s 47.993136 | sde: detect_prio = yes (setting: multipath internal) 356s 47.993150 | sde: prio = const (setting: multipath internal) 356s 47.993152 | sde: prio args = "" (setting: multipath internal) 356s 47.993154 | sde: const prio = 1 356s 47.993964 | unloading tur checker 356s 47.994007 | unloading const prioritizer 356s + dmsetup table 356s + grep . /etc/multipath/bindings /etc/multipath/wwids 356s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 356s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 356s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 356s /etc/multipath/bindings:# 356s /etc/multipath/bindings:# Format: 356s /etc/multipath/bindings:# alias wwid 356s /etc/multipath/bindings:# 356s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 356s /etc/multipath/wwids:/360000000000000000e00000000010001/ 356s ● multipathd.service - Device-Mapper Multipath Device Controller 356s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 356s Active: active (running) since Fri 2024-10-04 21:21:44 UTC; 44s ago 356s Invocation: 25d213d9a4c24d30890210ee00b0b7a1 356s TriggeredBy: ○ multipathd.socket 356s Main PID: 337 (multipathd) 356s Status: "up" 356s Tasks: 7 356s Memory: 31.8M (peak: 34.3M) 356s CPU: 41ms 356s CGroup: /system.slice/multipathd.service 356s └─337 /sbin/multipathd -d -s 356s 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 356s Oct 04 21:21:44 autopkgtest multipathd[337]: multipathd v0.9.9: start up 356s Oct 04 21:21:44 autopkgtest multipathd[337]: reconfigure: setting up paths and maps 356s Oct 04 21:21:44 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 356s Oct 04 21:22:23 autopkgtest multipathd[337]: updated bindings file /etc/multipath/bindings 356s Oct 04 21:22:23 autopkgtest multipathd[337]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:16 1] 356s Oct 04 21:22:24 autopkgtest multipathd[337]: sdb [8:16]: path added to devmap mpatha 356s Oct 04 21:22:24 autopkgtest multipathd[337]: mpatha: performing delayed actions 356s Oct 04 21:22:24 autopkgtest multipathd[337]: 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] 356s ○ multipathd.socket - multipathd control socket 356s Loaded: loaded (/usr/lib/systemd/system/multipathd.socket; static) 356s Active: inactive (dead) 356s Triggers: ● multipathd.service 356s Listen: @/org/kernel/linux/storage/multipathd (Stream) 356s total 0 356s drwxr-xr-x 2 root root 80 Oct 4 21:22 . 356s drwxr-xr-x 18 root root 4260 Oct 4 21:22 .. 356s crw------- 1 root root 10, 236 Oct 4 21:21 control 356s lrwxrwxrwx 1 root root 7 Oct 4 21:22 mpatha -> ../dm-0 356s journal 356s Oct 04 21:21:44 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 356s Oct 04 21:21:44 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 356s Oct 04 21:21:44 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 356s Oct 04 21:21:44 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 356s Oct 04 21:21:44 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 356s Oct 04 21:21:44 autopkgtest kernel: Activating Kernel Userspace Access Prevention 356s Oct 04 21:21:44 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 356s Oct 04 21:21:44 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x0000000003a00000 with 2.00 MiB pages (exec) 356s Oct 04 21:21:44 autopkgtest kernel: radix-mmu: Mapped 0x0000000003a00000-0x0000000200000000 with 2.00 MiB pages 356s Oct 04 21:21:44 autopkgtest kernel: lpar: Using radix MMU under hypervisor 356s Oct 04 21:21:44 autopkgtest kernel: Linux version 6.11.0-8-generic (buildd@bos01-ppc64el-009) (powerpc64le-linux-gnu-gcc-14 (Ubuntu 14.2.0-4ubuntu2) 14.2.0, GNU ld (GNU Binutils for Ubuntu) 2.43.1) #8-Ubuntu SMP Mon Sep 16 13:49:23 UTC 2024 (Ubuntu 6.11.0-8.8-generic 6.11.0) 356s Oct 04 21:21:44 autopkgtest kernel: Secure boot mode disabled 356s Oct 04 21:21:44 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc000000009454cd2 356s Oct 04 21:21:44 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (architected) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 356s Oct 04 21:21:44 autopkgtest kernel: printk: legacy bootconsole [udbg0] enabled 356s Oct 04 21:21:44 autopkgtest kernel: Partition configured for 4 cpus. 356s Oct 04 21:21:44 autopkgtest kernel: CPU maps initialized for 1 thread per core 356s Oct 04 21:21:44 autopkgtest kernel: (thread shift is 0) 356s Oct 04 21:21:44 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 356s Oct 04 21:21:44 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 356s Oct 04 21:21:44 autopkgtest kernel: ----------------------------------------------------- 356s Oct 04 21:21:44 autopkgtest kernel: phys_mem_size = 0x200000000 356s Oct 04 21:21:44 autopkgtest kernel: dcache_bsize = 0x80 356s Oct 04 21:21:44 autopkgtest kernel: icache_bsize = 0x80 356s Oct 04 21:21:44 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 356s Oct 04 21:21:44 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 356s Oct 04 21:21:44 autopkgtest kernel: always = 0x0000000380008181 356s Oct 04 21:21:44 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 356s Oct 04 21:21:44 autopkgtest kernel: mmu_features = 0x3c007641 356s Oct 04 21:21:44 autopkgtest kernel: firmware_features = 0x00000085455a445f 356s Oct 04 21:21:44 autopkgtest kernel: vmalloc start = 0xc008000000000000 356s Oct 04 21:21:44 autopkgtest kernel: IO start = 0xc00a000000000000 356s Oct 04 21:21:44 autopkgtest kernel: vmemmap start = 0xc00c000000000000 356s Oct 04 21:21:44 autopkgtest kernel: ----------------------------------------------------- 356s Oct 04 21:21:44 autopkgtest kernel: numa: NODE_DATA [mem 0x1fff10280-0x1fff17fff] 356s Oct 04 21:21:44 autopkgtest kernel: rfi-flush: fallback displacement flush available 356s Oct 04 21:21:44 autopkgtest kernel: rfi-flush: ori type flush available 356s Oct 04 21:21:44 autopkgtest kernel: rfi-flush: mttrig type flush available 356s Oct 04 21:21:44 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 356s Oct 04 21:21:44 autopkgtest kernel: count-cache-flush: software flush enabled. 356s Oct 04 21:21:44 autopkgtest kernel: link-stack-flush: software flush enabled. 356s Oct 04 21:21:44 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 356s Oct 04 21:21:44 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 356s Oct 04 21:21:44 autopkgtest kernel: stf-barrier: eieio barrier available 356s Oct 04 21:21:44 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 356s Oct 04 21:21:44 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 356s Oct 04 21:21:44 autopkgtest kernel: PPC64 nvram contains 65536 bytes 356s Oct 04 21:21:44 autopkgtest kernel: barrier-nospec: using ORI speculation barrier 356s Oct 04 21:21:44 autopkgtest + systemctl status multipathd.service 356s + ret_code=0 356s + systemctl status multipathd.socket 356s + ret_code=3 356s + [ 3 -eq 0 ] 356s + [ 3 -eq 3 ] 356s + ls -la /dev/mapper/ 356s + echo journal 356s + journalctl -b 356s kernel: barrier-nospec: patched 275 locations 356s Oct 04 21:21:44 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 356s Oct 04 21:21:44 autopkgtest kernel: Memory hole size: 0MB 356s Oct 04 21:21:44 autopkgtest kernel: Zone ranges: 356s Oct 04 21:21:44 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 356s Oct 04 21:21:44 autopkgtest kernel: Device empty 356s Oct 04 21:21:44 autopkgtest kernel: Movable zone start for each node 356s Oct 04 21:21:44 autopkgtest kernel: Early memory node ranges 356s Oct 04 21:21:44 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 356s Oct 04 21:21:44 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 356s Oct 04 21:21:44 autopkgtest kernel: percpu: Embedded 12 pages/cpu s619032 r0 d167400 u786432 356s Oct 04 21:21:44 autopkgtest kernel: pcpu-alloc: s619032 r0 d167400 u786432 alloc=12*65536 356s Oct 04 21:21:44 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 356s Oct 04 21:21:44 autopkgtest kernel: Kernel command line: BOOT_IMAGE=/boot/vmlinux-6.11.0-8-generic root=UUID=3f5e79c8-4933-4f96-841d-0a21474a3925 ro console=hvc0 earlyprintk 356s Oct 04 21:21:44 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.11.0-8-generic", will be passed to user space. 356s Oct 04 21:21:44 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 356s Oct 04 21:21:44 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 356s Oct 04 21:21:44 autopkgtest kernel: Fallback order for Node 0: 0 356s Oct 04 21:21:44 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 131072 356s Oct 04 21:21:44 autopkgtest kernel: Policy zone: Normal 356s Oct 04 21:21:44 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 356s Oct 04 21:21:44 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 356s Oct 04 21:21:44 autopkgtest kernel: ftrace: allocating 52900 entries in 20 pages 356s Oct 04 21:21:44 autopkgtest kernel: ftrace: allocated 20 pages with 2 groups 356s Oct 04 21:21:44 autopkgtest kernel: trace event string verifier disabled 356s Oct 04 21:21:44 autopkgtest kernel: rcu: Hierarchical RCU implementation. 356s Oct 04 21:21:44 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 356s Oct 04 21:21:44 autopkgtest kernel: Rude variant of Tasks RCU enabled. 356s Oct 04 21:21:44 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 356s Oct 04 21:21:44 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 356s Oct 04 21:21:44 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 356s Oct 04 21:21:44 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 356s Oct 04 21:21:44 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 356s Oct 04 21:21:44 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 356s Oct 04 21:21:44 autopkgtest kernel: xive: Using IRQ range [0-3] 356s Oct 04 21:21:44 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 356s Oct 04 21:21:44 autopkgtest kernel: xive: Using priority 6 for all interrupts 356s Oct 04 21:21:44 autopkgtest kernel: xive: Using 64kB queues 356s Oct 04 21:21:44 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 356s Oct 04 21:21:44 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 356s Oct 04 21:21:44 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 356s Oct 04 21:21:44 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 356s Oct 04 21:21:44 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 356s Oct 04 21:21:44 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 356s Oct 04 21:21:44 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 356s Oct 04 21:21:44 autopkgtest kernel: Console: colour dummy device 80x25 356s Oct 04 21:21:44 autopkgtest kernel: printk: legacy console [hvc0] enabled 356s Oct 04 21:21:44 autopkgtest kernel: printk: legacy bootconsole [udbg0] disabled 356s Oct 04 21:21:44 autopkgtest kernel: pid_max: default: 32768 minimum: 301 356s Oct 04 21:21:44 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,ima,evm 356s Oct 04 21:21:44 autopkgtest kernel: landlock: Up and running. 356s Oct 04 21:21:44 autopkgtest kernel: Yama: becoming mindful. 356s Oct 04 21:21:44 autopkgtest kernel: AppArmor: AppArmor initialized 356s Oct 04 21:21:44 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 356s Oct 04 21:21:44 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 356s Oct 04 21:21:44 autopkgtest kernel: POWER9 performance monitor hardware support registered 356s Oct 04 21:21:44 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 356s Oct 04 21:21:44 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 356s Oct 04 21:21:44 autopkgtest kernel: Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level 356s Oct 04 21:21:44 autopkgtest kernel: smp: Bringing up secondary CPUs ... 356s Oct 04 21:21:44 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 356s Oct 04 21:21:44 autopkgtest kernel: numa: Node 0 CPUs: 0-3 356s Oct 04 21:21:44 autopkgtest kernel: Memory: 8203648K/8388608K available (24384K kernel code, 4160K rwdata, 24768K rodata, 8768K init, 1851K bss, 157696K reserved, 0K cma-reserved) 356s Oct 04 21:21:44 autopkgtest kernel: devtmpfs: initialized 356s Oct 04 21:21:44 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 356s Oct 04 21:21:44 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 356s Oct 04 21:21:44 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 356s Oct 04 21:21:44 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 356s Oct 04 21:21:44 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 356s Oct 04 21:21:44 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 356s Oct 04 21:21:44 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 356s Oct 04 21:21:44 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 356s Oct 04 21:21:44 autopkgtest kernel: audit: initializing netlink subsys (disabled) 356s Oct 04 21:21:44 autopkgtest kernel: audit: type=2000 audit(1728076901.044:1): state=initialized audit_enabled=0 res=1 356s Oct 04 21:21:44 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 356s Oct 04 21:21:44 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 356s Oct 04 21:21:44 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 356s Oct 04 21:21:44 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 356s Oct 04 21:21:44 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 356s Oct 04 21:21:44 autopkgtest kernel: cpuidle: using governor ladder 356s Oct 04 21:21:44 autopkgtest kernel: cpuidle: using governor menu 356s Oct 04 21:21:44 autopkgtest kernel: RTAS daemon started 356s Oct 04 21:21:44 autopkgtest kernel: pstore: Using crash dump compression: deflate 356s Oct 04 21:21:44 autopkgtest kernel: pstore: Registered nvram as persistent store backend 356s Oct 04 21:21:44 autopkgtest kernel: EEH: pSeries platform initialized 356s Oct 04 21:21:44 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 356s Oct 04 21:21:44 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 356s Oct 04 21:21:44 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 356s Oct 04 21:21:44 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 356s Oct 04 21:21:44 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 356s Oct 04 21:21:44 autopkgtest kernel: iommu: Default domain type: Translated 356s Oct 04 21:21:44 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 356s Oct 04 21:21:44 autopkgtest kernel: SCSI subsystem initialized 356s Oct 04 21:21:44 autopkgtest kernel: libata version 3.00 loaded. 356s Oct 04 21:21:44 autopkgtest kernel: usbcore: registered new interface driver usbfs 356s Oct 04 21:21:44 autopkgtest kernel: usbcore: registered new interface driver hub 356s Oct 04 21:21:44 autopkgtest kernel: usbcore: registered new device driver usb 356s Oct 04 21:21:44 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 356s Oct 04 21:21:44 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 356s Oct 04 21:21:44 autopkgtest kernel: PTP clock support registered 356s Oct 04 21:21:44 autopkgtest kernel: EDAC MC: Ver: 3.0.0 356s Oct 04 21:21:44 autopkgtest kernel: NetLabel: Initializing 356s Oct 04 21:21:44 autopkgtest kernel: NetLabel: domain hash size = 128 356s Oct 04 21:21:44 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 356s Oct 04 21:21:44 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 356s Oct 04 21:21:44 autopkgtest kernel: mctp: management component transport protocol core 356s Oct 04 21:21:44 autopkgtest kernel: NET: Registered PF_MCTP protocol family 356s Oct 04 21:21:44 autopkgtest kernel: PCI: Probing PCI hardware 356s Oct 04 21:21:44 autopkgtest kernel: PCI host bridge to bus 0000:00 356s Oct 04 21:21:44 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 356s Oct 04 21:21:44 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 356s Oct 04 21:21:44 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 356s Oct 04 21:21:44 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 356s Oct 04 21:21:44 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 356s Oct 04 21:21:44 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 356s Oct 04 21:21:44 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 356s Oct 04 21:21:44 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 356s Oct 04 21:21:44 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 356s Oct 04 21:21:44 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 356s Oct 04 21:21:44 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 356s Oct 04 21:21:44 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 356s Oct 04 21:21:44 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 356s Oct 04 21:21:44 autopkgtest kernel: pci 0000:00:01.0: ibm,query-pe-dma-windows(2026) 800 8000000 20000000 returned 0, lb=80000000 ps=7 wn=1 356s Oct 04 21:21:44 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 356s Oct 04 21:21:44 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 356s Oct 04 21:21:44 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 356s Oct 04 21:21:44 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 356s Oct 04 21:21:44 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 356s Oct 04 21:21:44 autopkgtest kernel: PCI: Probing PCI hardware done 356s Oct 04 21:21:44 autopkgtest kernel: vgaarb: loaded 356s Oct 04 21:21:44 autopkgtest kernel: clocksource: Switched to clocksource timebase 356s Oct 04 21:21:44 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 356s Oct 04 21:21:44 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 356s Oct 04 21:21:44 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 356s Oct 04 21:21:44 autopkgtest kernel: NET: Registered PF_INET protocol family 356s Oct 04 21:21:44 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 356s Oct 04 21:21:44 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 356s Oct 04 21:21:44 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 356s Oct 04 21:21:44 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 356s Oct 04 21:21:44 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 356s Oct 04 21:21:44 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 356s Oct 04 21:21:44 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 356s Oct 04 21:21:44 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 356s Oct 04 21:21:44 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 356s Oct 04 21:21:44 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 356s Oct 04 21:21:44 autopkgtest kernel: NET: Registered PF_XDP protocol family 356s Oct 04 21:21:44 autopkgtest kernel: PCI: CLS 0 bytes, default 128 356s Oct 04 21:21:44 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 356s Oct 04 21:21:44 autopkgtest kernel: Initialise system trusted keyrings 356s Oct 04 21:21:44 autopkgtest kernel: Key type blacklist registered 356s Oct 04 21:21:44 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 356s Oct 04 21:21:44 autopkgtest kernel: zbud: loaded 356s Oct 04 21:21:44 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 356s Oct 04 21:21:44 autopkgtest kernel: fuse: init (API version 7.40) 356s Oct 04 21:21:44 autopkgtest kernel: integrity: Platform Keyring initialized 356s Oct 04 21:21:44 autopkgtest kernel: integrity: Machine keyring initialized 356s Oct 04 21:21:44 autopkgtest kernel: Key type asymmetric registered 356s Oct 04 21:21:44 autopkgtest kernel: Asymmetric key parser 'x509' registered 356s Oct 04 21:21:44 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 356s Oct 04 21:21:44 autopkgtest kernel: io scheduler mq-deadline registered 356s Oct 04 21:21:44 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 356s Oct 04 21:21:44 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 356s Oct 04 21:21:44 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) 356s Oct 04 21:21:44 autopkgtest kernel: virtio-pci 0000:00:02.0: enabling device (0100 -> 0103) 356s Oct 04 21:21:44 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 356s Oct 04 21:21:44 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 356s Oct 04 21:21:44 autopkgtest kernel: Non-volatile memory driver v1.3 356s Oct 04 21:21:44 autopkgtest kernel: Linux agpgart interface v0.103 356s Oct 04 21:21:44 autopkgtest kernel: loop: module loaded 356s Oct 04 21:21:44 autopkgtest kernel: virtio_scsi virtio1: 1/0/0 default/read/poll queues 356s Oct 04 21:21:44 autopkgtest kernel: scsi host0: Virtio SCSI HBA 356s Oct 04 21:21:44 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 356s Oct 04 21:21:44 autopkgtest kernel: PPP generic driver version 2.4.2 356s Oct 04 21:21:44 autopkgtest kernel: ohci-pci 0000:00:03.0: OHCI PCI host controller 356s Oct 04 21:21:44 autopkgtest kernel: ohci-pci 0000:00:03.0: new USB bus registered, assigned bus number 1 356s Oct 04 21:21:44 autopkgtest kernel: ohci-pci 0000:00:03.0: irq 20, io mem 0x200080090000 356s Oct 04 21:21:44 autopkgtest kernel: scsi 0:0:0:0: Direct-Access QEMU QEMU HARDDISK 2.5+ PQ: 0 ANSI: 5 356s Oct 04 21:21:44 autopkgtest kernel: Freeing initrd memory: 51520K 356s Oct 04 21:21:44 autopkgtest kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0 356s Oct 04 21:21:44 autopkgtest kernel: sd 0:0:0:0: Power-on or device reset occurred 356s Oct 04 21:21:44 autopkgtest kernel: sd 0:0:0:0: [sda] 167772160 512-byte logical blocks: (85.9 GB/80.0 GiB) 356s Oct 04 21:21:44 autopkgtest kernel: sd 0:0:0:0: [sda] Write Protect is off 356s Oct 04 21:21:44 autopkgtest kernel: sd 0:0:0:0: [sda] Mode Sense: 63 00 00 08 356s Oct 04 21:21:44 autopkgtest kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 356s Oct 04 21:21:44 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0001, bcdDevice= 6.11 356s Oct 04 21:21:44 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 356s Oct 04 21:21:44 autopkgtest kernel: usb usb1: Product: OHCI PCI host controller 356s Oct 04 21:21:44 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.11.0-8-generic ohci_hcd 356s Oct 04 21:21:44 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:03.0 356s Oct 04 21:21:44 autopkgtest kernel: hub 1-0:1.0: USB hub found 356s Oct 04 21:21:44 autopkgtest kernel: hub 1-0:1.0: 3 ports detected 356s Oct 04 21:21:44 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 356s Oct 04 21:21:44 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 356s Oct 04 21:21:44 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-10-04T21:21:41 UTC (1728076901) 356s Oct 04 21:21:44 autopkgtest kernel: i2c_dev: i2c /dev entries driver 356s Oct 04 21:21:44 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 356s Oct 04 21:21:44 autopkgtest kernel: device-mapper: uevent: version 1.0.3 356s Oct 04 21:21:44 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@lists.linux.dev 356s Oct 04 21:21:44 autopkgtest kernel: pseries_idle_driver registered 356s Oct 04 21:21:44 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 356s Oct 04 21:21:44 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 356s Oct 04 21:21:44 autopkgtest kernel: NET: Registered PF_INET6 protocol family 356s Oct 04 21:21:44 autopkgtest kernel: sda: sda1 sda2 356s Oct 04 21:21:44 autopkgtest kernel: sd 0:0:0:0: [sda] Attached SCSI disk 356s Oct 04 21:21:44 autopkgtest kernel: Segment Routing with IPv6 356s Oct 04 21:21:44 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 356s Oct 04 21:21:44 autopkgtest kernel: NET: Registered PF_PACKET protocol family 356s Oct 04 21:21:44 autopkgtest kernel: Key type dns_resolver registered 356s Oct 04 21:21:44 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 356s Oct 04 21:21:44 autopkgtest kernel: registered taskstats version 1 356s Oct 04 21:21:44 autopkgtest kernel: Loading compiled-in X.509 certificates 356s Oct 04 21:21:44 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d43630f15d3f0c00f59e22a0c5131b4ebd804093' 356s Oct 04 21:21:44 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 356s Oct 04 21:21:44 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 356s Oct 04 21:21:44 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 356s Oct 04 21:21:44 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 356s Oct 04 21:21:44 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 356s Oct 04 21:21:44 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 356s Oct 04 21:21:44 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 356s Oct 04 21:21:44 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 356s Oct 04 21:21:44 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 356s Oct 04 21:21:44 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 356s Oct 04 21:21:44 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 356s Oct 04 21:21:44 autopkgtest kernel: Demotion targets for Node 0: null 356s Oct 04 21:21:44 autopkgtest kernel: Key type .fscrypt registered 356s Oct 04 21:21:44 autopkgtest kernel: Key type fscrypt-provisioning registered 356s Oct 04 21:21:44 autopkgtest kernel: Key type encrypted registered 356s Oct 04 21:21:44 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 356s Oct 04 21:21:44 autopkgtest kernel: Secure boot mode disabled 356s Oct 04 21:21:44 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 356s Oct 04 21:21:44 autopkgtest kernel: Loading compiled-in module X.509 certificates 356s Oct 04 21:21:44 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d43630f15d3f0c00f59e22a0c5131b4ebd804093' 356s Oct 04 21:21:44 autopkgtest kernel: ima: Allocated hash algorithm: sha256 356s Oct 04 21:21:44 autopkgtest kernel: Secure boot mode disabled 356s Oct 04 21:21:44 autopkgtest kernel: Trusted boot mode disabled 356s Oct 04 21:21:44 autopkgtest kernel: ima: No architecture policies found 356s Oct 04 21:21:44 autopkgtest kernel: evm: Initialising EVM extended attributes: 356s Oct 04 21:21:44 autopkgtest kernel: evm: security.selinux 356s Oct 04 21:21:44 autopkgtest kernel: evm: security.SMACK64 356s Oct 04 21:21:44 autopkgtest kernel: evm: security.SMACK64EXEC 356s Oct 04 21:21:44 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 356s Oct 04 21:21:44 autopkgtest kernel: evm: security.SMACK64MMAP 356s Oct 04 21:21:44 autopkgtest kernel: evm: security.apparmor 356s Oct 04 21:21:44 autopkgtest kernel: evm: security.ima 356s Oct 04 21:21:44 autopkgtest kernel: evm: security.capability 356s Oct 04 21:21:44 autopkgtest kernel: evm: HMAC attrs: 0x1 356s Oct 04 21:21:44 autopkgtest kernel: SED: plpks not available 356s Oct 04 21:21:44 autopkgtest kernel: clk: Disabling unused clocks 356s Oct 04 21:21:44 autopkgtest kernel: PM: genpd: Disabling unused power domains 356s Oct 04 21:21:44 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 356s Oct 04 21:21:44 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8768K 356s Oct 04 21:21:44 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 356s Oct 04 21:21:44 autopkgtest kernel: Run /init as init process 356s Oct 04 21:21:44 autopkgtest kernel: with arguments: 356s Oct 04 21:21:44 autopkgtest kernel: /init 356s Oct 04 21:21:44 autopkgtest kernel: earlyprintk 356s Oct 04 21:21:44 autopkgtest kernel: with environment: 356s Oct 04 21:21:44 autopkgtest kernel: HOME=/ 356s Oct 04 21:21:44 autopkgtest kernel: TERM=linux 356s Oct 04 21:21:44 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.11.0-8-generic 356s Oct 04 21:21:44 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 356s Oct 04 21:21:44 autopkgtest kernel: raid6: vpermxor8 gen() 23261 MB/s 356s Oct 04 21:21:44 autopkgtest kernel: raid6: vpermxor4 gen() 20126 MB/s 356s Oct 04 21:21:44 autopkgtest kernel: raid6: vpermxor2 gen() 16230 MB/s 356s Oct 04 21:21:44 autopkgtest kernel: raid6: vpermxor1 gen() 13945 MB/s 356s Oct 04 21:21:44 autopkgtest kernel: raid6: altivecx8 gen() 14214 MB/s 356s Oct 04 21:21:44 autopkgtest kernel: raid6: altivecx4 gen() 13710 MB/s 356s Oct 04 21:21:44 autopkgtest kernel: raid6: altivecx2 gen() 11138 MB/s 356s Oct 04 21:21:44 autopkgtest kernel: raid6: altivecx1 gen() 8830 MB/s 356s Oct 04 21:21:44 autopkgtest kernel: raid6: int64x8 gen() 7435 MB/s 356s Oct 04 21:21:44 autopkgtest kernel: raid6: int64x4 gen() 8964 MB/s 356s Oct 04 21:21:44 autopkgtest kernel: raid6: int64x2 gen() 6890 MB/s 356s Oct 04 21:21:44 autopkgtest kernel: raid6: int64x1 gen() 5425 MB/s 356s Oct 04 21:21:44 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 23261 MB/s 356s Oct 04 21:21:44 autopkgtest kernel: raid6: using intx1 recovery algorithm 356s Oct 04 21:21:44 autopkgtest kernel: xor: measuring software checksum speed 356s Oct 04 21:21:44 autopkgtest kernel: 8regs : 17837 MB/sec 356s Oct 04 21:21:44 autopkgtest kernel: 8regs_prefetch : 16069 MB/sec 356s Oct 04 21:21:44 autopkgtest kernel: 32regs : 17840 MB/sec 356s Oct 04 21:21:44 autopkgtest kernel: 32regs_prefetch : 16085 MB/sec 356s Oct 04 21:21:44 autopkgtest kernel: altivec : 19913 MB/sec 356s Oct 04 21:21:44 autopkgtest kernel: xor: using function: altivec (19913 MB/sec) 356s Oct 04 21:21:44 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 356s Oct 04 21:21:44 autopkgtest kernel: EXT4-fs (sda1): orphan cleanup on readonly fs 356s Oct 04 21:21:44 autopkgtest kernel: EXT4-fs (sda1): mounted filesystem 3f5e79c8-4933-4f96-841d-0a21474a3925 ro with ordered data mode. Quota mode: none. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Inserted module 'autofs4' 356s Oct 04 21:21:44 autopkgtest systemd[1]: systemd 256.5-2ubuntu2 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) 356s Oct 04 21:21:44 autopkgtest systemd[1]: Detected virtualization kvm. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Detected architecture ppc64-le. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Hostname set to . 356s Oct 04 21:21:44 autopkgtest systemd[1]: bpf-restrict-fs: BPF LSM hook not enabled in the kernel, BPF LSM not supported. 356s Oct 04 21:21:44 autopkgtest kernel: NET: Registered PF_VSOCK protocol family 356s Oct 04 21:21:44 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. 356s Oct 04 21:21:44 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. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Queued start job for default target graphical.target. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Reached target swap.target - Swaps. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 356s Oct 04 21:21:44 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Sockets. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounting run-lock.mount - Legacy Locks Directory /run/lock... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting modprobe@dm_multipath.service - Load Kernel Module dm_multipath... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 356s Oct 04 21:21:44 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 356s Oct 04 21:21:44 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). 356s Oct 04 21:21:44 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). 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounted run-lock.mount - Legacy Locks Directory /run/lock. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 356s Oct 04 21:21:44 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 356s Oct 04 21:21:44 autopkgtest systemd-journald[291]: Collecting audit messages is disabled. 356s Oct 04 21:21:44 autopkgtest systemd[1]: modprobe@dm_multipath.service: Deactivated successfully. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished modprobe@dm_multipath.service - Load Kernel Module dm_multipath. 356s Oct 04 21:21:44 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 356s Oct 04 21:21:44 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 356s Oct 04 21:21:44 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 356s Oct 04 21:21:44 autopkgtest systemd-journald[291]: Journal started 356s Oct 04 21:21:44 autopkgtest systemd-journald[291]: Runtime Journal (/run/log/journal/e92a9a8d850f4a75b97a3af5b9ac7f06) is 8M, max 81M, 73M free. 356s Oct 04 21:21:44 autopkgtest kernel: EXT4-fs (sda1): re-mounted 3f5e79c8-4933-4f96-841d-0a21474a3925 r/w. Quota mode: none. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting cloud-init-main.service - Cloud-init: Single Process... 356s Oct 04 21:21:44 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 356s Oct 04 21:21:44 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 356s Oct 04 21:21:44 autopkgtest systemd-journald[291]: Time spent on flushing to /var/log/journal/e92a9a8d850f4a75b97a3af5b9ac7f06 is 16.865ms for 423 entries. 356s Oct 04 21:21:44 autopkgtest systemd-journald[291]: System Journal (/var/log/journal/e92a9a8d850f4a75b97a3af5b9ac7f06) is 18.9M, max 4G, 3.9G free. 356s Oct 04 21:21:44 autopkgtest systemd-journald[291]: Received client request to flush runtime journal. 356s Oct 04 21:21:44 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 356s Oct 04 21:21:44 autopkgtest multipathd[337]: multipathd v0.9.9: start up 356s Oct 04 21:21:44 autopkgtest multipathd[337]: reconfigure: setting up paths and maps 356s Oct 04 21:21:44 autopkgtest systemd-random-seed[343]: Kernel entropy pool is not initialized yet, waiting until it is. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 356s Oct 04 21:21:44 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 356s Oct 04 21:21:44 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 363 (systemd-binfmt) 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 356s Oct 04 21:21:44 autopkgtest systemd-tmpfiles[364]: /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 356s Oct 04 21:21:44 autopkgtest apparmor.systemd[360]: Restarting AppArmor 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 356s Oct 04 21:21:44 autopkgtest systemd-udevd[357]: Using default interface naming scheme 'v255'. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 356s Oct 04 21:21:44 autopkgtest apparmor.systemd[360]: Reloading AppArmor profiles 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. 356s Oct 04 21:21:44 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 356s Oct 04 21:21:44 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 356s Oct 04 21:21:44 autopkgtest kernel: audit: type=1400 audit(1728076904.672:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=382 comm="apparmor_parser" 356s Oct 04 21:21:44 autopkgtest kernel: audit: type=1400 audit(1728076904.672:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=381 comm="apparmor_parser" 356s Oct 04 21:21:44 autopkgtest kernel: audit: type=1400 audit(1728076904.672:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=383 comm="apparmor_parser" 356s Oct 04 21:21:44 autopkgtest kernel: audit: type=1400 audit(1728076904.672:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=384 comm="apparmor_parser" 356s Oct 04 21:21:44 autopkgtest kernel: audit: type=1400 audit(1728076904.676:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=387 comm="apparmor_parser" 356s Oct 04 21:21:44 autopkgtest kernel: audit: type=1400 audit(1728076904.676:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=388 comm="apparmor_parser" 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 356s Oct 04 21:21:44 autopkgtest kernel: audit: type=1400 audit(1728076904.676:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=389 comm="apparmor_parser" 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 356s Oct 04 21:21:44 autopkgtest kernel: audit: type=1400 audit(1728076904.680:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="cam" pid=392 comm="apparmor_parser" 356s Oct 04 21:21:44 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 356s Oct 04 21:21:44 autopkgtest kernel: audit: type=1400 audit(1728076904.684:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="busybox" pid=390 comm="apparmor_parser" 356s Oct 04 21:21:44 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 356s Oct 04 21:21:44 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 356s Oct 04 21:21:44 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 356s Oct 04 21:21:44 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). 356s Oct 04 21:21:44 autopkgtest systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 356s Oct 04 21:21:44 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 356s Oct 04 21:21:44 autopkgtest (udev-worker)[426]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 356s Oct 04 21:21:44 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 356s Oct 04 21:21:44 autopkgtest kernel: random: crng init done 356s Oct 04 21:21:44 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 391 ((resolved)) 356s Oct 04 21:21:45 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 356s Oct 04 21:21:45 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 356s Oct 04 21:21:45 autopkgtest systemd[1]: systemd-machine-id-commit.service - Save Transient machine-id to Disk was skipped because of an unmet condition check (ConditionPathIsMountPoint=/etc/machine-id). 356s Oct 04 21:21:45 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 356s Oct 04 21:21:45 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 356s Oct 04 21:21:45 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 356s Oct 04 21:21:45 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 356s Oct 04 21:21:45 autopkgtest systemd-resolved[391]: Positive Trust Anchors: 356s Oct 04 21:21:45 autopkgtest systemd-resolved[391]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 356s Oct 04 21:21:45 autopkgtest systemd-resolved[391]: 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 356s Oct 04 21:21:45 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 356s Oct 04 21:21:45 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 356s Oct 04 21:21:45 autopkgtest systemd-resolved[391]: Using system hostname 'autopkgtest'. 356s Oct 04 21:21:45 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 356s Oct 04 21:21:45 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 356s Oct 04 21:21:45 autopkgtest systemd[1]: Started cloud-init-main.service - Cloud-init: Single Process. 356s Oct 04 21:21:45 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 356s Oct 04 21:21:45 autopkgtest cloud-init[668]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu4 running 'init-local' at Fri, 04 Oct 2024 21:21:45 +0000. Up 4.54 seconds. 356s Oct 04 21:21:45 autopkgtest dhcpcd[671]: dhcpcd-10.0.8 starting 356s Oct 04 21:21:45 autopkgtest dhcpcd[674]: DUID 00:01:00:01:2e:92:91:f8:fa:16:3e:73:f2:d2 356s Oct 04 21:21:45 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 356s Oct 04 21:21:45 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 356s Oct 04 21:21:45 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 356s Oct 04 21:21:45 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 356s Oct 04 21:21:45 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 356s Oct 04 21:21:45 autopkgtest dhcpcd[674]: enp0s1: IAID 3e:b0:50:48 356s Oct 04 21:21:47 autopkgtest dhcpcd[674]: enp0s1: rebinding lease of 10.44.124.2 356s Oct 04 21:21:52 autopkgtest dhcpcd[674]: enp0s1: DHCP lease expired 356s Oct 04 21:21:52 autopkgtest dhcpcd[674]: enp0s1: soliciting a DHCP lease 356s Oct 04 21:21:52 autopkgtest dhcpcd[674]: enp0s1: offered 10.44.124.2 from 10.44.124.241 356s Oct 04 21:21:52 autopkgtest dhcpcd[674]: enp0s1: leased 10.44.124.2 for 86400 seconds 356s Oct 04 21:21:52 autopkgtest dhcpcd[674]: enp0s1: adding route to 10.44.124.0/24 356s Oct 04 21:21:52 autopkgtest dhcpcd[674]: enp0s1: adding host route to 169.254.169.254 via 10.44.124.1 356s Oct 04 21:21:52 autopkgtest dhcpcd[674]: enp0s1: adding default route via 10.44.124.1 356s Oct 04 21:21:52 autopkgtest dhcpcd[674]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 356s Oct 04 21:21:54 autopkgtest sh[664]: Completed socket interaction for boot stage local 356s Oct 04 21:21:54 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 356s Oct 04 21:21:54 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 356s Oct 04 21:21:54 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 356s Oct 04 21:21:54 autopkgtest systemd-networkd[705]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 356s Oct 04 21:21:54 autopkgtest systemd-networkd[705]: lo: Link UP 356s Oct 04 21:21:54 autopkgtest systemd-networkd[705]: lo: Gained carrier 356s Oct 04 21:21:54 autopkgtest systemd-networkd[705]: Enumeration completed 356s Oct 04 21:21:54 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 356s Oct 04 21:21:54 autopkgtest systemd-networkd[705]: enp0s1: Link UP 356s Oct 04 21:21:54 autopkgtest systemd-networkd[705]: enp0s1: Gained carrier 356s Oct 04 21:21:54 autopkgtest systemd-networkd[705]: enp0s1: Gained IPv6LL 356s Oct 04 21:21:54 autopkgtest systemd-timesyncd[394]: Network configuration changed, trying to establish connection. 356s Oct 04 21:21:54 autopkgtest systemd-timesyncd[394]: Network configuration changed, trying to establish connection. 356s Oct 04 21:21:54 autopkgtest systemd-timesyncd[394]: Network configuration changed, trying to establish connection. 356s Oct 04 21:21:54 autopkgtest systemd-networkd[705]: enp0s1: Link DOWN 356s Oct 04 21:21:54 autopkgtest systemd-networkd[705]: enp0s1: Lost carrier 356s Oct 04 21:21:54 autopkgtest systemd[1]: Reached target network.target - Network. 356s Oct 04 21:21:54 autopkgtest systemd-networkd[705]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 356s Oct 04 21:21:54 autopkgtest systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... 356s Oct 04 21:21:54 autopkgtest systemd-networkd[705]: enp0s1: Link UP 356s Oct 04 21:21:54 autopkgtest systemd-networkd[705]: enp0s1: Gained carrier 356s Oct 04 21:21:54 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 356s Oct 04 21:21:54 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 356s Oct 04 21:21:54 autopkgtest systemd-networkd[705]: enp0s1: DHCPv4 address 10.44.124.2/24, gateway 10.44.124.1 acquired from 10.44.124.241 356s Oct 04 21:21:54 autopkgtest systemd-timesyncd[394]: Network configuration changed, trying to establish connection. 356s Oct 04 21:21:54 autopkgtest systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. 356s Oct 04 21:21:56 autopkgtest systemd-networkd[705]: enp0s1: Gained IPv6LL 356s Oct 04 21:21:56 autopkgtest systemd-timesyncd[394]: Network configuration changed, trying to establish connection. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting cloud-init-network.service - Cloud-init: Network Stage... 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu4 running 'init' at Fri, 04 Oct 2024 21:21:56 +0000. Up 15.02 seconds. 356s Oct 04 21:21:56 autopkgtest systemd-timesyncd[394]: Contacted time server 185.125.190.58:123 (ntp.ubuntu.com). 356s Oct 04 21:21:56 autopkgtest systemd-timesyncd[394]: Initial clock synchronization to Fri 2024-10-04 21:21:56.072215 UTC. 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | enp0s1 | True | 10.44.124.2 | 255.255.255.0 | global | fa:16:3e:b0:50:48 | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | enp0s1 | True | fe80::f816:3eff:feb0:5048/64 | . | link | fa:16:3e:b0:50:48 | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | lo | True | ::1/128 | . | host | . | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info++++++++++++++++++++++++++++++++ 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | 0 | 0.0.0.0 | 10.44.124.1 | 0.0.0.0 | enp0s1 | UG | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | 1 | 10.44.124.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | 2 | 10.44.124.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | 3 | 91.189.91.130 | 10.44.124.1 | 255.255.255.255 | enp0s1 | UGH | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | 4 | 169.254.169.254 | 10.44.124.1 | 255.255.255.255 | enp0s1 | UGH | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: +-------+-------------+---------+-----------+-------+ 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | Route | Destination | Gateway | Interface | Flags | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: +-------+-------------+---------+-----------+-------+ 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | 2 | local | :: | enp0s1 | U | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: | 3 | multicast | :: | enp0s1 | U | 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: ci-info: +-------+-------------+---------+-----------+-------+ 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: 2024-10-04 21:21:56,269 - 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. 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: 2024-10-04 21:21:56,269 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 356s Oct 04 21:21:56 autopkgtest sh[716]: Completed socket interaction for boot stage network 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished cloud-init-network.service - Cloud-init: Network Stage. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 356s Oct 04 21:21:56 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). 356s Oct 04 21:21:56 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). 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started sysstat-collect.timer - Run system activity accounting tool every 10 minutes. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started sysstat-rotate.timer - Rotate daily system activity data file at midnight. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started sysstat-summary.timer - Generate summary of yesterday's process accounting. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 356s Oct 04 21:21:56 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). 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target paths.target - Path Units. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 356s Oct 04 21:21:56 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 356s Oct 04 21:21:56 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). 356s Oct 04 21:21:56 autopkgtest systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target ssh-access.target - SSH Access Available. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target basic.target - Basic System. 356s Oct 04 21:21:56 autopkgtest systemd[1]: System is tainted: unmerged-bin 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 356s Oct 04 21:21:56 autopkgtest (sh)[753]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 356s Oct 04 21:21:56 autopkgtest (sh)[753]: autopkgtest@ttyS1.service: Failed at step STDIN spawning /bin/sh: Input/output error 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 356s Oct 04 21:21:56 autopkgtest (cron)[755]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 356s Oct 04 21:21:56 autopkgtest cron[755]: (CRON) INFO (pidfile fd = 3) 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 356s Oct 04 21:21:56 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). 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 356s Oct 04 21:21:56 autopkgtest cron[755]: (CRON) INFO (Running @reboot jobs) 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 356s Oct 04 21:21:56 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 356s Oct 04 21:21:56 autopkgtest systemd[1]: opal_errd.service - opal_errd (PowerNV platform error handling) Service was skipped because of an unmet condition check (ConditionVirtualization=false). 356s Oct 04 21:21:56 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). 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting sysstat.service - Resets System Activity Logs... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 356s Oct 04 21:21:56 autopkgtest dbus-daemon[756]: [system] AppArmor D-Bus mediation is enabled 356s Oct 04 21:21:56 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). 356s Oct 04 21:21:56 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 356s Oct 04 21:21:56 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 356s Oct 04 21:21:56 autopkgtest dbus-daemon[756]: [system] Activating systemd to hand-off: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.0' (uid=998 pid=705 comm="/usr/lib/systemd/systemd-networkd" label="unconfined") 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 356s Oct 04 21:21:56 autopkgtest dbus-daemon[756]: [system] Successfully activated service 'org.freedesktop.systemd1' 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 356s Oct 04 21:21:56 autopkgtest udisksd[775]: udisks daemon version 2.10.1 starting 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting systemd-hostnamed.service - Hostname Service... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished sysstat.service - Resets System Activity Logs. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu4 running 'modules:config' at Fri, 04 Oct 2024 21:21:56 +0000. Up 15.29 seconds. 356s Oct 04 21:21:56 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 356s Oct 04 21:21:56 autopkgtest rng-tools-debian[823]: found /dev/hwrng but could not use it 356s Oct 04 21:21:56 autopkgtest rng-tools-debian[767]: * Configuring Hardware RNG entropy gatherer daemon 356s Oct 04 21:21:56 autopkgtest rng-tools-debian[767]: ...fail! 356s Oct 04 21:21:56 autopkgtest rng-tools-debian[825]: not starting: no hardware RNG device found 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 356s Oct 04 21:21:56 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 356s Oct 04 21:21:56 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 356s Oct 04 21:21:56 autopkgtest sh[760]: Completed socket interaction for boot stage config 356s Oct 04 21:21:56 autopkgtest systemd-logind[773]: New seat seat0. 356s Oct 04 21:21:56 autopkgtest kernel: kauditd_printk_skb: 110 callbacks suppressed 356s Oct 04 21:21:56 autopkgtest kernel: audit: type=1400 audit(1728076916.608:121): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=824 comm="apparmor_parser" 356s Oct 04 21:21:56 autopkgtest udisksd[775]: Acquired the name org.freedesktop.UDisks2 on the system message bus 356s Oct 04 21:21:56 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 356s Oct 04 21:21:56 autopkgtest dbus-daemon[756]: [system] Successfully activated service 'org.freedesktop.hostname1' 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 356s Oct 04 21:21:56 autopkgtest systemd-networkd[705]: Could not set hostname: Access denied 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started systemd-hostnamed.service - Hostname Service. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 356s Oct 04 21:21:56 autopkgtest sshd[841]: Server listening on 0.0.0.0 port 22. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 356s Oct 04 21:21:56 autopkgtest sshd[841]: Server listening on :: port 22. 356s Oct 04 21:21:56 autopkgtest rsyslogd[863]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2406.0] 356s Oct 04 21:21:56 autopkgtest rsyslogd[863]: rsyslogd's groupid changed to 102 356s Oct 04 21:21:56 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 356s Oct 04 21:21:56 autopkgtest rsyslogd[863]: rsyslogd's userid changed to 102 356s Oct 04 21:21:56 autopkgtest rsyslogd[863]: [origin software="rsyslogd" swVersion="8.2406.0" x-pid="863" x-info="https://www.rsyslog.com"] start 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 356s Oct 04 21:21:56 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 356s Oct 04 21:21:56 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu4 running 'modules:final' at Fri, 04 Oct 2024 21:21:56 +0000. Up 15.57 seconds. 356s Oct 04 21:21:56 autopkgtest cloud-init[668]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu4 finished at Fri, 04 Oct 2024 21:21:56 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 15.63 seconds 356s Oct 04 21:21:56 autopkgtest sh[876]: Completed socket interaction for boot stage final 356s Oct 04 21:21:56 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 356s Oct 04 21:21:56 autopkgtest systemd[1]: Startup finished in 2.834s (kernel) + 12.810s (userspace) = 15.644s. 356s Oct 04 21:21:56 autopkgtest kernel: fbcon: Taking over console 356s Oct 04 21:21:56 autopkgtest systemd[1]: cloud-init-main.service: Deactivated successfully. 356s Oct 04 21:21:56 autopkgtest systemd[1]: cloud-init-main.service: Consumed 1.301s CPU time, 113.9M memory peak. 356s Oct 04 21:21:56 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 356s Oct 04 21:21:57 autopkgtest sshd[866]: Accepted publickey for ubuntu from 10.136.6.184 port 41472 ssh2: RSA SHA256:h+sR5tlNZDfTFbz7cAH7wlRKfPAD8MpCdKJaoGeL2vg 356s Oct 04 21:21:57 autopkgtest sshd[866]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 356s Oct 04 21:21:57 autopkgtest sshd[866]: pam_systemd(sshd:session): New sd-bus connection (system-bus-pam-systemd-866) opened. 356s Oct 04 21:21:57 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 356s Oct 04 21:21:57 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 356s Oct 04 21:21:57 autopkgtest systemd-logind[773]: New session 1 of user ubuntu. 356s Oct 04 21:21:57 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 356s Oct 04 21:21:57 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 356s Oct 04 21:21:57 autopkgtest (systemd)[905]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 356s Oct 04 21:21:57 autopkgtest systemd-logind[773]: New session 2 of user ubuntu. 356s Oct 04 21:21:57 autopkgtest systemd[905]: Queued start job for default target default.target. 356s Oct 04 21:21:57 autopkgtest systemd[905]: Created slice app.slice - User Application Slice. 356s Oct 04 21:21:57 autopkgtest systemd[905]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 356s Oct 04 21:21:57 autopkgtest systemd[905]: Reached target paths.target - Paths. 356s Oct 04 21:21:57 autopkgtest systemd[905]: Reached target timers.target - Timers. 356s Oct 04 21:21:57 autopkgtest systemd[905]: Starting dbus.socket - D-Bus User Message Bus Socket... 356s Oct 04 21:21:57 autopkgtest systemd[905]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 356s Oct 04 21:21:57 autopkgtest systemd[905]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 356s Oct 04 21:21:57 autopkgtest systemd[905]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 356s Oct 04 21:21:57 autopkgtest systemd[905]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 356s Oct 04 21:21:57 autopkgtest systemd[905]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 356s Oct 04 21:21:57 autopkgtest systemd[905]: Listening on keyboxd.socket - GnuPG public key management service. 356s Oct 04 21:21:57 autopkgtest systemd[905]: Listening on dbus.socket - D-Bus User Message Bus Socket. 356s Oct 04 21:21:57 autopkgtest systemd[905]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 356s Oct 04 21:21:57 autopkgtest systemd[905]: Reached target sockets.target - Sockets. 356s Oct 04 21:21:57 autopkgtest systemd[905]: Reached target basic.target - Basic System. 356s Oct 04 21:21:57 autopkgtest systemd[905]: Reached target default.target - Main User Target. 356s Oct 04 21:21:57 autopkgtest systemd[905]: Startup finished in 145ms. 356s Oct 04 21:21:57 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 356s Oct 04 21:21:57 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 356s Oct 04 21:21:57 autopkgtest sudo[933]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 356s Oct 04 21:21:57 autopkgtest sudo[933]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:21:57 autopkgtest sudo[933]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:21:58 autopkgtest sudo[938]: 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' 356s Oct 04 21:21:58 autopkgtest sudo[938]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:21:58 autopkgtest sudo[938]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:21:58 autopkgtest sudo[950]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.xWL77y 356s Oct 04 21:21:58 autopkgtest sudo[950]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:21:58 autopkgtest sudo[950]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:21:58 autopkgtest sudo[960]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.xWL77y/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.xWL77y/autopkgtest-reboot' 356s Oct 04 21:21:58 autopkgtest sudo[960]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:21:58 autopkgtest sudo[960]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:21:58 autopkgtest sudo[972]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.xWL77y/autopkgtest-reboot 356s Oct 04 21:21:58 autopkgtest sudo[972]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:21:58 autopkgtest sudo[972]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:21:58 autopkgtest sudo[982]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.xWL77y/autopkgtest-reboot /tmp/autopkgtest-reboot 356s Oct 04 21:21:58 autopkgtest sudo[982]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:21:58 autopkgtest sudo[982]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:21:59 autopkgtest sudo[992]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.xWL77y/autopkgtest-reboot /sbin/autopkgtest-reboot 356s Oct 04 21:21:59 autopkgtest sudo[992]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:21:59 autopkgtest sudo[992]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:21:59 autopkgtest sudo[1002]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.xWL77y 356s Oct 04 21:21:59 autopkgtest sudo[1002]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:21:59 autopkgtest sudo[1002]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:21:59 autopkgtest sudo[1012]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.xWL77y/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.xWL77y/autopkgtest-reboot-prepare' 356s Oct 04 21:21:59 autopkgtest sudo[1012]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:21:59 autopkgtest sudo[1012]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:21:59 autopkgtest sudo[1024]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.xWL77y/autopkgtest-reboot-prepare 356s Oct 04 21:21:59 autopkgtest sudo[1024]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:21:59 autopkgtest sudo[1024]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:21:59 autopkgtest sudo[1034]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.xWL77y/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 356s Oct 04 21:21:59 autopkgtest sudo[1034]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:21:59 autopkgtest sudo[1034]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:00 autopkgtest sudo[1044]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 356s Oct 04 21:22:00 autopkgtest sudo[1044]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:00 autopkgtest sudo[1044]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:00 autopkgtest sudo[1054]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 356s Oct 04 21:22:00 autopkgtest sudo[1054]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:00 autopkgtest sudo[1054]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:00 autopkgtest sudo[1064]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.xWL77y/testbed-packages' 356s Oct 04 21:22:00 autopkgtest sudo[1064]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:00 autopkgtest sudo[1064]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:00 autopkgtest sudo[1075]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.xWL77y/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.xWL77y/autopkgtest-reboot' 356s Oct 04 21:22:00 autopkgtest sudo[1096]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:01 autopkgtest sudo[1096]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:01 autopkgtest sudo[1108]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.xWL77y/autopkgtest-reboot 356s Oct 04 21:22:01 autopkgtest sudo[1108]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:01 autopkgtest sudo[1108]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:01 autopkgtest sudo[1118]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.xWL77y/autopkgtest-reboot /tmp/autopkgtest-reboot 356s Oct 04 21:22:01 autopkgtest sudo[1118]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:01 autopkgtest sudo[1118]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:01 autopkgtest sudo[1128]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.xWL77y/autopkgtest-reboot /sbin/autopkgtest-reboot 356s Oct 04 21:22:01 autopkgtest sudo[1128]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:01 autopkgtest sudo[1128]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:01 autopkgtest sudo[1138]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.xWL77y 356s Oct 04 21:22:01 autopkgtest sudo[1138]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:01 autopkgtest sudo[1138]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:01 autopkgtest sudo[1148]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.xWL77y/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.xWL77y/autopkgtest-reboot-prepare' 356s Oct 04 21:22:01 autopkgtest sudo[1148]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:01 autopkgtest sudo[1148]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:02 autopkgtest sudo[1160]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.xWL77y/autopkgtest-reboot-prepare 356s Oct 04 21:22:02 autopkgtest sudo[1160]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:02 autopkgtest sudo[1160]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:02 autopkgtest sudo[1170]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.xWL77y/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 356s Oct 04 21:22:02 autopkgtest sudo[1170]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:02 autopkgtest sudo[1170]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:02 autopkgtest sudo[1180]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 356s Oct 04 21:22:02 autopkgtest sudo[1180]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:02 autopkgtest sudo[1180]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:02 autopkgtest sudo[1190]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 356s Oct 04 21:22:02 autopkgtest sudo[1190]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:02 autopkgtest sudo[1190]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:02 autopkgtest sudo[1199]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.xWL77y 356s Oct 04 21:22:02 autopkgtest sudo[1199]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:02 autopkgtest sudo[1199]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:03 autopkgtest sudo[1209]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.xWL77y/2-autopkgtest-satdep.deb' 356s Oct 04 21:22:03 autopkgtest sudo[1209]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:03 autopkgtest sudo[1209]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:03 autopkgtest sudo[1220]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.xWL77y/2-autopkgtest-satdep.deb 356s Oct 04 21:22:03 autopkgtest sudo[1220]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:03 autopkgtest sudo[1220]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:03 autopkgtest sudo[1230]: 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.xWL77y/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' 356s Oct 04 21:22:03 autopkgtest sudo[1230]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:07 autopkgtest systemd[1]: Reload requested from client PID 1470 ('systemctl') (unit session-1.scope)... 356s Oct 04 21:22:07 autopkgtest systemd[1]: Reloading... 356s Oct 04 21:22:07 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. 356s Oct 04 21:22:07 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. 356s Oct 04 21:22:07 autopkgtest systemd[1]: Reloading finished in 177 ms. 356s Oct 04 21:22:07 autopkgtest systemd[1]: Reload requested from client PID 1520 ('systemctl') (unit session-1.scope)... 356s Oct 04 21:22:07 autopkgtest systemd[1]: Reloading... 356s Oct 04 21:22:07 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. 356s Oct 04 21:22:07 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. 356s Oct 04 21:22:07 autopkgtest systemd[1]: Reloading finished in 179 ms. 356s Oct 04 21:22:07 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 356s Oct 04 21:22:07 autopkgtest tgtd[1566]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 356s Oct 04 21:22:07 autopkgtest tgtd[1566]: tgtd: work_timer_start(146) use timer_fd based scheduler 356s Oct 04 21:22:07 autopkgtest tgtd[1566]: tgtd: bs_init(387) use signalfd notification 356s Oct 04 21:22:08 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 356s Oct 04 21:22:08 autopkgtest systemd[1]: Reload requested from client PID 1594 ('systemctl') (unit session-1.scope)... 356s Oct 04 21:22:08 autopkgtest systemd[1]: Reloading... 356s Oct 04 21:22:08 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. 356s Oct 04 21:22:08 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. 356s Oct 04 21:22:08 autopkgtest systemd[1]: Reloading finished in 213 ms. 356s Oct 04 21:22:08 autopkgtest systemd[1]: Reload requested from client PID 1638 ('systemctl') (unit session-1.scope)... 356s Oct 04 21:22:08 autopkgtest systemd[1]: Reloading... 356s Oct 04 21:22:08 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. 356s Oct 04 21:22:08 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. 356s Oct 04 21:22:08 autopkgtest systemd[1]: Reloading finished in 189 ms. 356s Oct 04 21:22:08 autopkgtest systemd[1]: Reload requested from client PID 1684 ('systemctl') (unit session-1.scope)... 356s Oct 04 21:22:08 autopkgtest systemd[1]: Reloading... 356s Oct 04 21:22:08 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. 356s Oct 04 21:22:08 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. 356s Oct 04 21:22:08 autopkgtest systemd[1]: Reloading finished in 182 ms. 356s Oct 04 21:22:09 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 356s Oct 04 21:22:09 autopkgtest systemd[1]: Reload requested from client PID 1735 ('systemctl') (unit session-1.scope)... 356s Oct 04 21:22:09 autopkgtest systemd[1]: Reloading... 356s Oct 04 21:22:09 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. 356s Oct 04 21:22:09 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. 356s Oct 04 21:22:09 autopkgtest systemd[1]: Reloading finished in 167 ms. 356s Oct 04 21:22:09 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 356s Oct 04 21:22:09 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 356s Oct 04 21:22:09 autopkgtest systemd[1]: Reload requested from client PID 1790 ('systemctl') (unit session-1.scope)... 356s Oct 04 21:22:09 autopkgtest systemd[1]: Reloading... 356s Oct 04 21:22:09 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. 356s Oct 04 21:22:09 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. 356s Oct 04 21:22:09 autopkgtest systemd[1]: Reloading finished in 184 ms. 356s Oct 04 21:22:19 autopkgtest sudo[1230]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:19 autopkgtest sudo[5663]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 356s Oct 04 21:22:19 autopkgtest sudo[5663]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:19 autopkgtest sudo[5663]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:19 autopkgtest sudo[5673]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 356s Oct 04 21:22:19 autopkgtest sudo[5673]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:19 autopkgtest sudo[5673]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:19 autopkgtest sudo[5683]: 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 356s Oct 04 21:22:19 autopkgtest sudo[5683]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:20 autopkgtest sudo[5683]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:20 autopkgtest sudo[5696]: 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 356s Oct 04 21:22:20 autopkgtest sudo[5696]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:20 autopkgtest sudo[5696]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:21 autopkgtest sudo[5708]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 356s Oct 04 21:22:21 autopkgtest sudo[5708]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:21 autopkgtest sudo[5708]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:21 autopkgtest sudo[5720]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 356s Oct 04 21:22:21 autopkgtest sudo[5720]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:21 autopkgtest sudo[5720]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:21 autopkgtest sudo[5730]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.xWL77y/tgtbasedmpaths-packages.all' 356s Oct 04 21:22:21 autopkgtest sudo[5730]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 04 21:22:21 autopkgtest sudo[5730]: pam_unix(sudo:session): session closed for user root 356s Oct 04 21:22:21 autopkgtest sudo[5741]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 360s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 360s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 360s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 360s latency : target=0, window=0, percentile=100.00%, depth=1 360s 360s Run status group 0 (all jobs): 360s WRITE: bw=132MiB/s (138MB/s), 132MiB/s-132MiB/s (138MB/s-138MB/s), io=87.5MiB (91.8MB), run=665-665msec 360s 360s Disk stats (read/write): 360s dm-0: ios=1/1356, sectors=8/173568, merge=0/0, ticks=0/598, in_queue=599, util=78.81%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/151, aggrin_queue=151, aggrutil=75.00% 360s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 360s sdb: ios=1/1402, sectors=8/179280, merge=0/0, ticks=0/607, in_queue=607, util=75.00% 360s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 360s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 360s + echo Starting the path changes in background 360s + date +Pre FIO %H:%M:%S.%N 360s + fio --max-jobs=4 /tmp/autopkgtest.xWL77y/tgtbasedmpaths-artifacts/path-change-check.fio 360s Starting the path changes in background 360s Pre FIO 21:22:33.373538449 360s 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 360s fio-3.37 360s Starting 1 thread 540s 540s verify-phase: (groupid=0, jobs=1): err= 0: pid=6086: Fri Oct 4 21:25:33 2024 540s read: IOPS=3286, BW=205MiB/s (215MB/s)(36.1GiB/180001msec) 540s clat (usec): min=72, max=69354, avg=281.04, stdev=326.63 540s lat (usec): min=72, max=69354, avg=281.16, stdev=326.63 540s clat percentiles (usec): 540s | 1.00th=[ 94], 5.00th=[ 149], 10.00th=[ 169], 20.00th=[ 200], 540s | 30.00th=[ 235], 40.00th=[ 273], 50.00th=[ 289], 60.00th=[ 306], 540s | 70.00th=[ 314], 80.00th=[ 326], 90.00th=[ 347], 95.00th=[ 363], 540s | 99.00th=[ 717], 99.50th=[ 1057], 99.90th=[ 1565], 99.95th=[ 1991], 540s | 99.99th=[ 3392] 540s bw ( KiB/s): min=154036, max=420736, per=100.00%, avg=210558.44, stdev=39774.40, samples=359 540s iops : min= 2406, max= 6574, avg=3289.87, stdev=621.52, samples=359 540s lat (usec) : 100=1.55%, 250=32.01%, 500=65.21%, 750=0.26%, 1000=0.35% 540s lat (msec) : 2=0.57%, 4=0.04%, 10=0.01%, 20=0.01%, 50=0.01% 540s lat (msec) : 100=0.01% 540s cpu : usr=8.23%, sys=3.90%, ctx=591609, majf=0, minf=1 540s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 540s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 540s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 540s issued rwts: total=591533,0,0,0 short=0,0,0,0 dropped=0,0,0,0 540s latency : target=0, window=0, percentile=100.00%, depth=1 540s 540s Run status group 0 (all jobs): 540s READ: bw=205MiB/s (215MB/s), 205MiB/s-205MiB/s (215MB/s-215MB/s), io=36.1GiB (38.8GB), run=180001-180001msec 540s 540s Disk stats (read/write): 540s dm-0: ios=591804/10, sectors=75692472/12928, merge=0/9, ticks=165651/85, in_queue=165785, util=89.53%, aggrios=42117/2, aggsectors=5385934/3232, aggrmerge=0/0, aggrticks=10916/9, aggrin_queue=10925, aggrutil=81.15% 540s sdd: ios=30635/0, sectors=3918464/0, merge=0/0, ticks=8811/0, in_queue=8811, util=27.88% 540s sdb: ios=37916/9, sectors=4849536/12928, merge=0/0, ticks=8360/36, in_queue=8396, util=81.15% 540s sde: ios=69667/0, sectors=8910976/0, merge=0/0, ticks=17557/0, in_queue=17558, util=33.01% 540s sdc: ios=30250/0, sectors=3864760/0, merge=0/0, ticks=8938/0, in_queue=8938, util=42.77% 540s + date +Post FIO %H:%M:%S.%N 540s + echo FIO verify test with changing paths - OK 540s + echo Report log of background activity 540s + cat /tmp/autopkgtest.xWL77y/tgtbasedmpaths-artifacts/test-background.log 540s Post FIO 21:25:33.756383793 540s FIO verify test with changing paths - OK 540s Report log of background activity 540s + iscsiadm --mode session 540s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s + sleep 10s 540s + date +MP report (expect 4) %H:%M:%S.%N 540s MP report (expect 4) 21:22:43.382490597 540s + multipath -ll 540s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 540s size=100M features='0' hwhandler='0' wp=rw 540s |-+- policy='service-time 0' prio=1 status=active 540s | `- 1:0:0:1 sdb 8:16 active ready running 540s |-+- policy='service-time 0' prio=1 status=enabled 540s | `- 2:0:0:1 sdc 8:32 active ready running 540s |-+- policy='service-time 0' prio=1 status=enabled 540s | `- 3:0:0:1 sdd 8:48 active ready running 540s `-+- policy='service-time 0' prio=1 status=enabled 540s `- 4:0:0:1 sde 8:64 active ready running 540s + date +UN-plug path 1 %H:%M:%S.%N 540s UN-plug path 1 21:22:43.408499223 540s + iscsiadm --mode session -r 1 -u 540s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 540s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 540s + iscsiadm --mode session 540s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s + sleep 10s 540s + date +MP report (expect 3) %H:%M:%S.%N 540s MP report (expect 3) 21:22:53.510174294 540s + multipath -ll 540s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 540s size=100M features='0' hwhandler='0' wp=rw 540s |-+- policy='service-time 0' prio=1 status=active 540s | `- 2:0:0:1 sdc 8:32 active ready running 540s |-+- policy='service-time 0' prio=1 status=enabled 540s | `- 3:0:0:1 sdd 8:48 active ready running 540s `-+- policy='service-time 0' prio=1 status=enabled 540s `- 4:0:0:1 sde 8:64 active ready running 540s + date +UN-plug path 2 %H:%M:%S.%N 540s UN-plug path 2 21:22:53.531121795 540s + iscsiadm --mode session -r 2 -u 540s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 540s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 540s + iscsiadm --mode session 540s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s + sleep 10s 540s + date +MP report (expect 2) %H:%M:%S.%N 540s MP report (expect 2) 21:23:03.636750079 540s + multipath -ll 540s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 540s size=100M features='0' hwhandler='0' wp=rw 540s |-+- policy='service-time 0' prio=1 status=active 540s | `- 3:0:0:1 sdd 8:48 active ready running 540s `-+- policy='service-time 0' prio=1 status=enabled 540s `- 4:0:0:1 sde 8:64 active ready running 540s + date +UN-plug path 3 %H:%M:%S.%N 540s UN-plug path 3 21:23:03.654953303 540s + iscsiadm --mode session -r 3 -u 540s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 540s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 540s + iscsiadm --mode session 540s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s + sleep 10s 540s + date +MP report (expect 1) %H:%M:%S.%N 540s MP report (expect 1) 21:23:13.736490148 540s + multipath -ll 540s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 540s size=100M features='0' hwhandler='0' wp=rw 540s `-+- policy='service-time 0' prio=1 status=active 540s `- 4:0:0:1 sde 8:64 active ready running 540s + date +Add paths 5/6/7/8 %H:%M:%S.%N 540s Add paths 5/6/7/8 21:23:13.753572718 540s + iscsiadm --mode session -r 4 --op new 540s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 540s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 540s + iscsiadm --mode session -r 4 --op new 540s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 540s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 540s + iscsiadm --mode session -r 4 --op new 540s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 540s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 540s + iscsiadm --mode session -r 4 --op new 540s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 540s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 540s + iscsiadm --mode session 540s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s + sleep 10s 540s + date +MP report (expect 5) %H:%M:%S.%N 540s MP report (expect 5) 21:23:23.857307182 540s + multipath -ll 540s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 540s size=100M features='0' hwhandler='0' wp=rw 540s |-+- policy='service-time 0' prio=1 status=active 540s | `- 4:0:0:1 sde 8:64 active ready running 540s |-+- policy='service-time 0' prio=1 status=enabled 540s | `- 1:0:0:1 sdb 8:16 active ready running 540s |-+- policy='service-time 0' prio=1 status=enabled 540s | `- 2:0:0:1 sdc 8:32 active ready running 540s |-+- policy='service-time 0' prio=1 status=enabled 540s | `- 3:0:0:1 sdd 8:48 active ready running 540s `-+- policy='service-time 0' prio=1 status=enabled 540s `- 5:0:0:1 sdf 8:80 active ready running 540s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 540s UN-plug multiple paths 4/7/8 21:23:23.885878527 540s + iscsiadm --mode session -r 4 -u 540s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 540s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 540s + iscsiadm --mode session -r 7 -u 540s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 540s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 540s + iscsiadm --mode session -r 8 -u 540s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 540s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 540s + iscsiadm --mode session 540s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 540s + sleep 10s 540s + date +Restart multipath daemon %H:%M:%S.%N 540s Restart multipath daemon 21:23:34.169548493 540s + systemctl restart multipathd 540s + sleep 10s 540s + date +Final background report (expect 2) %H:%M:%S.%N 540s Final background report (expect 2) 21:23:44.260226322 540s + multipath -ll 540s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 540s size=100M features='0' hwhandler='0' wp=rw 540s |-+- policy='service-time 0' prio=1 status=active 540s | `- 1:0:0:1 sdb 8:16 active ready running 540s `-+- policy='service-time 0' prio=1 status=enabled 540s `- 2:0:0:1 sdc 8:32 active ready running 540s Final stats 540s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 540s iSCSI SNMP: 540s txdata_octets: 20215224 540s rxdata_octets: 27577109152 540s noptx_pdus: 0 540s scsicmd_pdus: 420883 540s tmfcmd_pdus: 0 540s login_pdus: 0 540s text_pdus: 0 540s dataout_pdus: 0 540s logout_pdus: 0 540s snack_pdus: 0 540s noprx_pdus: 0 540s scsirsp_pdus: 420883 540s tmfrsp_pdus: 0 540s textrsp_pdus: 0 540s datain_pdus: 420849 540s logoutrsp_pdus: 0 540s r2t_pdus: 0 540s async_pdus: 0 540s rjt_pdus: 0 540s digest_err: 0 540s timeout_err: 0 540s iSCSI Extended: 540s tx_sendpage_failures: 0 540s rx_discontiguous_hdr: 0 540s eh_abort_cnt: 0 540s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 540s iSCSI SNMP: 540s txdata_octets: 6744 540s rxdata_octets: 1515328 540s noptx_pdus: 0 540s scsicmd_pdus: 111 540s tmfcmd_pdus: 0 540s login_pdus: 0 540s text_pdus: 0 540s dataout_pdus: 0 540s logout_pdus: 0 540s snack_pdus: 0 540s noprx_pdus: 0 540s scsirsp_pdus: 111 540s tmfrsp_pdus: 0 540s textrsp_pdus: 0 540s datain_pdus: 87 540s logoutrsp_pdus: 0 540s r2t_pdus: 0 540s async_pdus: 0 540s rjt_pdus: 0 540s digest_err: 0 540s timeout_err: 0 540s iSCSI Extended: 540s tx_sendpage_failures: 0 540s rx_discontiguous_hdr: 0 540s eh_abort_cnt: 0 540s Oct 04 11:45:58 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 04 11:45:58 ubuntu multipathd[336]: multipathd v0.9.9: start up 540s Oct 04 11:45:58 ubuntu multipathd[336]: reconfigure: setting up paths and maps 540s Oct 04 11:45:58 ubuntu multipathd[336]: _check_bindings_file: failed to read header from /etc/multipath/bindings 540s Oct 04 11:45:58 ubuntu multipathd[336]: updated bindings file /etc/multipath/bindings 540s Oct 04 11:45:58 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 540s Oct 04 11:49:02 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 multipathd[336]: multipathd: shut down 540s Oct 04 11:49:02 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 04 11:49:02 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 systemd[1]: multipathd.service: Deactivated successfully. 540s Oct 04 11:49:02 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 540s -- Boot c01b242c28db4e869ccbf951d73ab5f0 -- 540s Oct 04 11:49:26 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 multipathd[267]: multipathd v0.9.9: start up 540s Oct 04 11:49:26 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 multipathd[267]: reconfigure: setting up paths and maps 540s Oct 04 11:49:26 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 540s Oct 04 11:49:46 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 multipathd[267]: multipathd: shut down 540s Oct 04 11:49:46 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 04 11:49:46 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 systemd[1]: multipathd.service: Deactivated successfully. 540s Oct 04 11:49:46 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 540s -- Boot 4d2462bb7cae4bc68d1b6284c4f9a592 -- 540s Oct 04 21:20:28 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 04 21:20:28 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 multipathd[335]: multipathd v0.9.9: start up 540s Oct 04 21:20:28 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 multipathd[335]: reconfigure: setting up paths and maps 540s Oct 04 21:20:28 auto-syncubuntu-oracular-daily-ppc64el-server-20241001-disk1 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 540s Oct 04 21:21:19 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 04 21:21:19 autopkgtest multipathd[335]: multipathd: shut down 540s Oct 04 21:21:19 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 540s Oct 04 21:21:19 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 540s -- Boot 78f93a51857848b3af54f220a7152590 -- 540s Oct 04 21:21:44 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 04 21:21:44 autopkgtest multipathd[337]: multipathd v0.9.9: start up 540s Oct 04 21:21:44 autopkgtest multipathd[337]: reconfigure: setting up paths and maps 540s Oct 04 21:21:44 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 540s Oct 04 21:22:23 autopkgtest multipathd[337]: updated bindings file /etc/multipath/bindings 540s Oct 04 21:22:23 autopkgtest multipathd[337]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:16 1] 540s Oct 04 21:22:24 autopkgtest multipathd[337]: sdb [8:16]: path added to devmap mpatha 540s Oct 04 21:22:24 autopkgtest multipathd[337]: mpatha: performing delayed actions 540s Oct 04 21:22:24 autopkgtest multipathd[337]: 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] 540s Oct 04 21:22:43 autopkgtest multipathd[337]: 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] 540s Oct 04 21:22:43 autopkgtest multipathd[337]: check_removed_paths: sdb: freeing path in removed state 540s Oct 04 21:22:43 autopkgtest multipathd[337]: 8:16: path removed from map mpatha 540s Oct 04 21:22:53 autopkgtest multipathd[337]: sdc: mark as failed 540s Oct 04 21:22:53 autopkgtest multipathd[337]: mpatha: remaining active paths: 2 540s Oct 04 21:22:53 autopkgtest multipathd[337]: 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] 540s Oct 04 21:22:53 autopkgtest multipathd[337]: check_removed_paths: sdc: freeing path in removed state 540s Oct 04 21:22:53 autopkgtest multipathd[337]: 8:32: path removed from map mpatha 540s Oct 04 21:23:03 autopkgtest multipathd[337]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 540s Oct 04 21:23:03 autopkgtest multipathd[337]: check_removed_paths: sdd: freeing path in removed state 540s Oct 04 21:23:03 autopkgtest multipathd[337]: 8:48: path removed from map mpatha 540s Oct 04 21:23:13 autopkgtest multipathd[337]: 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] 540s Oct 04 21:23:13 autopkgtest multipathd[337]: sdb [8:16]: path added to devmap mpatha 540s Oct 04 21:23:13 autopkgtest multipathd[337]: 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] 540s Oct 04 21:23:13 autopkgtest multipathd[337]: sdc [8:32]: path added to devmap mpatha 540s Oct 04 21:23:13 autopkgtest multipathd[337]: 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] 540s Oct 04 21:23:13 autopkgtest multipathd[337]: sdd [8:48]: path added to devmap mpatha 540s Oct 04 21:23:13 autopkgtest multipathd[337]: 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] 540s Oct 04 21:23:13 autopkgtest multipathd[337]: sdf [8:80]: path added to devmap mpatha 540s Oct 04 21:23:23 autopkgtest multipathd[337]: 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] 540s Oct 04 21:23:23 autopkgtest multipathd[337]: check_removed_paths: sde: freeing path in removed state 540s Oct 04 21:23:23 autopkgtest multipathd[337]: 8:64: path removed from map mpatha 540s Oct 04 21:23:24 autopkgtest multipathd[337]: 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] 540s Oct 04 21:23:24 autopkgtest multipathd[337]: check_removed_paths: sdd: freeing path in removed state 540s Oct 04 21:23:24 autopkgtest multipathd[337]: 8:48: path removed from map mpatha 540s Oct 04 21:23:24 autopkgtest multipathd[337]: 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] 540s Oct 04 21:23:24 autopkgtest multipathd[337]: check_removed_paths: sdf: freeing path in removed state 540s Oct 04 21:23:24 autopkgtest multipathd[337]: 8:80: path removed from map mpatha 540s Oct 04 21:23:34 autopkgtest multipathd[337]: multipathd: shut down 540s Oct 04 21:23:34 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 04 21:23:34 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 540s Oct 04 21:23:34 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 540s Oct 04 21:23:34 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 04 21:23:34 autopkgtest multipathd[6435]: multipathd v0.9.9: start up 540s Oct 04 21:23:34 autopkgtest multipathd[6435]: reconfigure: setting up paths and maps 540s Oct 04 21:23:34 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 540s Check final path status 540s + sync 540s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 540s + echo Final stats 540s + iscsiadm --mode session --stats 540s + journalctl --no-pager -u multipathd 540s + echo Check final path status 540s + multipath -ll 540s + multipath -ll 540s + grep --count status= 540s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 540s size=100M features='0' hwhandler='0' wp=rw 540s |-+- policy='service-time 0' prio=1 status=active 540s | `- 1:0:0:1 sdb 8:16 active ready running 540s `-+- policy='service-time 0' prio=1 status=enabled 540s `- 2:0:0:1 sdc 8:32 active ready running 540s + diskc=2 540s + multipath -ll 540s + grep --count status=active 540s + diska=1 540s + multipath -ll 540s + grep --count status=enabled 540s OK 540s + diske=1 540s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 540s + echo OK 540s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 541s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 541s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 541s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 541s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 541s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 541s autopkgtest [21:25:34]: test tgtbasedmpaths: -----------------------] 542s autopkgtest [21:25:35]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 542s tgtbasedmpaths PASS 542s autopkgtest [21:25:35]: @@@@@@@@@@@@@@@@@@@@ summary 542s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 542s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 542s kpartx-file-loopback PASS 542s tgtbasedmpaths PASS 553s nova [W] Using flock in scalingstack-bos02-ppc64el 553s Creating nova instance adt-oracular-ppc64el-multipath-tools-20241004-211633-juju-7f2275-prod-proposed-migration-environment-2-d59909f8-c494-4b5f-b9c6-0c3ddeee0ee6 from image adt/ubuntu-oracular-ppc64el-server-20241004.img (UUID c7f31235-6005-4231-8798-096ba24d0db9)... 553s nova [W] Using flock in scalingstack-bos02-ppc64el 553s Creating nova instance adt-oracular-ppc64el-multipath-tools-20241004-211633-juju-7f2275-prod-proposed-migration-environment-2-d59909f8-c494-4b5f-b9c6-0c3ddeee0ee6 from image adt/ubuntu-oracular-ppc64el-server-20241004.img (UUID c7f31235-6005-4231-8798-096ba24d0db9)...