0s autopkgtest [02:15:00]: starting date and time: 2024-10-18 02:15:00+0000 0s autopkgtest [02:15:00]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [02:15:00]: host juju-7f2275-prod-proposed-migration-environment-14; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.ejj30bkk/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:linux-meta,src:linux --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=linux-meta/6.11.0-9.9 linux/6.11.0-9.9' --setup-commands 'apt-get install -y ^kernel-testing--linux--full--preferred$ || apt-get install -y ^linux-image$ ^linux-headers$ || apt-get install -y ^linux-image-generic$ ^linux-headers-generic$' --setup-commands 'apt-get install -y ^kernel-testing--linux--modules-extra--preferred$ || apt-get install -y ^linux-modules-extra$ || :' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big-ppc64el --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-14@bos03-ppc64el-22.secgroup --name adt-oracular-ppc64el-multipath-tools-20241018-014920-juju-7f2275-prod-proposed-migration-environment-14-07460428-d1b1-4dba-a527-ff807afa9e6b --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-14 --net-id=net_prod-proposed-migration-ppc64el -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/ 60s autopkgtest [02:16:00]: testbed dpkg architecture: ppc64el 60s autopkgtest [02:16:00]: testbed apt version: 2.9.8 60s autopkgtest [02:16:00]: @@@@@@@@@@@@@@@@@@@@ test bed setup 61s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [265 kB] 62s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7016 B] 62s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [147 kB] 62s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2840 B] 62s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [18.6 kB] 62s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [20.4 kB] 62s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [744 B] 62s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 62s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [99.7 kB] 62s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [3856 B] 62s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 63s Fetched 566 kB in 1s (809 kB/s) 63s Reading package lists... 66s Reading package lists... 66s Building dependency tree... 66s Reading state information... 66s Calculating upgrade... 66s The following NEW packages will be installed: 66s linux-headers-6.11.0-9 linux-headers-6.11.0-9-generic 66s linux-image-6.11.0-9-generic linux-modules-6.11.0-9-generic 66s linux-modules-extra-6.11.0-9-generic linux-tools-6.11.0-9 66s linux-tools-6.11.0-9-generic 66s The following packages will be upgraded: 66s iproute2 linux-generic linux-headers-generic linux-headers-virtual 66s linux-image-generic linux-image-virtual linux-libc-dev linux-tools-common 66s linux-virtual 66s 9 upgraded, 7 newly installed, 0 to remove and 0 not upgraded. 66s Need to get 228 MB of archives. 66s After this operation, 333 MB of additional disk space will be used. 66s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el iproute2 ppc64el 6.10.0-2ubuntu1 [1409 kB] 67s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-6.11.0-9-generic ppc64el 6.11.0-9.9 [32.8 MB] 69s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-6.11.0-9-generic ppc64el 6.11.0-9.9 [63.9 MB] 71s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-extra-6.11.0-9-generic ppc64el 6.11.0-9.9 [105 MB] 77s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-generic ppc64el 6.11.0-9.9 [1736 B] 77s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-generic ppc64el 6.11.0-9.9 [10.8 kB] 77s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-virtual ppc64el 6.11.0-9.9 [1724 B] 77s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-virtual ppc64el 6.11.0-9.9 [10.8 kB] 77s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-virtual ppc64el 6.11.0-9.9 [1644 B] 77s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.11.0-9 all 6.11.0-9.9 [13.9 MB] 78s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.11.0-9-generic ppc64el 6.11.0-9.9 [3947 kB] 78s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-generic ppc64el 6.11.0-9.9 [10.7 kB] 78s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-libc-dev ppc64el 6.11.0-9.9 [1654 kB] 78s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-common all 6.11.0-9.9 [484 kB] 78s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-9 ppc64el 6.11.0-9.9 [5177 kB] 78s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-9-generic ppc64el 6.11.0-9.9 [1736 B] 79s Preconfiguring packages ... 79s Fetched 228 MB in 12s (18.7 MB/s) 79s (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 ... 73395 files and directories currently installed.) 79s Preparing to unpack .../00-iproute2_6.10.0-2ubuntu1_ppc64el.deb ... 79s Unpacking iproute2 (6.10.0-2ubuntu1) over (6.10.0-2) ... 79s Selecting previously unselected package linux-modules-6.11.0-9-generic. 79s Preparing to unpack .../01-linux-modules-6.11.0-9-generic_6.11.0-9.9_ppc64el.deb ... 79s Unpacking linux-modules-6.11.0-9-generic (6.11.0-9.9) ... 79s Selecting previously unselected package linux-image-6.11.0-9-generic. 79s Preparing to unpack .../02-linux-image-6.11.0-9-generic_6.11.0-9.9_ppc64el.deb ... 79s Unpacking linux-image-6.11.0-9-generic (6.11.0-9.9) ... 80s Selecting previously unselected package linux-modules-extra-6.11.0-9-generic. 80s Preparing to unpack .../03-linux-modules-extra-6.11.0-9-generic_6.11.0-9.9_ppc64el.deb ... 80s Unpacking linux-modules-extra-6.11.0-9-generic (6.11.0-9.9) ... 81s Preparing to unpack .../04-linux-generic_6.11.0-9.9_ppc64el.deb ... 81s Unpacking linux-generic (6.11.0-9.9) over (6.11.0-8.8) ... 81s Preparing to unpack .../05-linux-image-generic_6.11.0-9.9_ppc64el.deb ... 81s Unpacking linux-image-generic (6.11.0-9.9) over (6.11.0-8.8) ... 81s Preparing to unpack .../06-linux-virtual_6.11.0-9.9_ppc64el.deb ... 81s Unpacking linux-virtual (6.11.0-9.9) over (6.11.0-8.8) ... 81s Preparing to unpack .../07-linux-image-virtual_6.11.0-9.9_ppc64el.deb ... 81s Unpacking linux-image-virtual (6.11.0-9.9) over (6.11.0-8.8) ... 81s Preparing to unpack .../08-linux-headers-virtual_6.11.0-9.9_ppc64el.deb ... 81s Unpacking linux-headers-virtual (6.11.0-9.9) over (6.11.0-8.8) ... 81s Selecting previously unselected package linux-headers-6.11.0-9. 81s Preparing to unpack .../09-linux-headers-6.11.0-9_6.11.0-9.9_all.deb ... 81s Unpacking linux-headers-6.11.0-9 (6.11.0-9.9) ... 83s Selecting previously unselected package linux-headers-6.11.0-9-generic. 83s Preparing to unpack .../10-linux-headers-6.11.0-9-generic_6.11.0-9.9_ppc64el.deb ... 83s Unpacking linux-headers-6.11.0-9-generic (6.11.0-9.9) ... 84s Preparing to unpack .../11-linux-headers-generic_6.11.0-9.9_ppc64el.deb ... 84s Unpacking linux-headers-generic (6.11.0-9.9) over (6.11.0-8.8) ... 84s Preparing to unpack .../12-linux-libc-dev_6.11.0-9.9_ppc64el.deb ... 84s Unpacking linux-libc-dev:ppc64el (6.11.0-9.9) over (6.11.0-8.8) ... 84s Preparing to unpack .../13-linux-tools-common_6.11.0-9.9_all.deb ... 84s Unpacking linux-tools-common (6.11.0-9.9) over (6.11.0-8.8) ... 84s Selecting previously unselected package linux-tools-6.11.0-9. 84s Preparing to unpack .../14-linux-tools-6.11.0-9_6.11.0-9.9_ppc64el.deb ... 84s Unpacking linux-tools-6.11.0-9 (6.11.0-9.9) ... 84s Selecting previously unselected package linux-tools-6.11.0-9-generic. 84s Preparing to unpack .../15-linux-tools-6.11.0-9-generic_6.11.0-9.9_ppc64el.deb ... 84s Unpacking linux-tools-6.11.0-9-generic (6.11.0-9.9) ... 84s Setting up iproute2 (6.10.0-2ubuntu1) ... 84s Setting up linux-libc-dev:ppc64el (6.11.0-9.9) ... 84s Setting up linux-headers-6.11.0-9 (6.11.0-9.9) ... 84s Setting up linux-tools-common (6.11.0-9.9) ... 84s Setting up linux-modules-6.11.0-9-generic (6.11.0-9.9) ... 86s Setting up linux-modules-extra-6.11.0-9-generic (6.11.0-9.9) ... 88s Setting up linux-headers-6.11.0-9-generic (6.11.0-9.9) ... 88s Setting up linux-image-6.11.0-9-generic (6.11.0-9.9) ... 91s I: /boot/vmlinux is now a symlink to vmlinux-6.11.0-9-generic 91s I: /boot/initrd.img is now a symlink to initrd.img-6.11.0-9-generic 91s Setting up linux-tools-6.11.0-9 (6.11.0-9.9) ... 91s Setting up linux-image-virtual (6.11.0-9.9) ... 91s Setting up linux-tools-6.11.0-9-generic (6.11.0-9.9) ... 91s Setting up linux-image-generic (6.11.0-9.9) ... 91s Setting up linux-headers-generic (6.11.0-9.9) ... 91s Setting up linux-headers-virtual (6.11.0-9.9) ... 91s Setting up linux-generic (6.11.0-9.9) ... 91s Setting up linux-virtual (6.11.0-9.9) ... 91s Processing triggers for man-db (2.12.1-3) ... 93s Processing triggers for linux-image-6.11.0-9-generic (6.11.0-9.9) ... 93s /etc/kernel/postinst.d/initramfs-tools: 93s update-initramfs: Generating /boot/initrd.img-6.11.0-9-generic 93s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 100s /etc/kernel/postinst.d/zz-update-grub: 100s Sourcing file `/etc/default/grub' 100s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 100s Generating grub configuration file ... 100s Found linux image: /boot/vmlinux-6.11.0-9-generic 100s Found initrd image: /boot/initrd.img-6.11.0-9-generic 100s Found linux image: /boot/vmlinux-6.11.0-8-generic 100s Found initrd image: /boot/initrd.img-6.11.0-8-generic 100s Warning: os-prober will not be executed to detect other bootable partitions. 100s Systems on them will not be added to the GRUB boot configuration. 100s Check GRUB_DISABLE_OS_PROBER documentation entry. 100s Adding boot menu entry for UEFI Firmware Settings ... 100s done 100s Reading package lists... 100s Building dependency tree... 100s Reading state information... 101s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 101s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 101s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 101s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 101s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 102s Reading package lists... 102s Reading package lists... 102s Building dependency tree... 102s Reading state information... 103s Calculating upgrade... 103s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 103s Reading package lists... 103s Building dependency tree... 103s Reading state information... 103s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 103s Reading package lists... 103s Building dependency tree... 103s Reading state information... 104s linux-generic is already the newest version (6.11.0-9.9). 104s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 104s Reading package lists... 104s Building dependency tree... 104s Reading state information... 104s E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 104s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 104s Reading package lists... 104s Building dependency tree... 104s Reading state information... 104s E: Unable to locate package ^linux-modules-extra$ 104s E: Couldn't find any package by regex '^linux-modules-extra$' 105s autopkgtest [02:16:45]: rebooting testbed after setup commands that affected boot 137s autopkgtest [02:17:17]: testbed running kernel: Linux 6.11.0-9-generic #9-Ubuntu SMP Mon Oct 14 13:15:06 UTC 2024 139s autopkgtest [02:17:19]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 143s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (dsc) [2772 B] 143s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (tar) [588 kB] 143s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (diff) [42.7 kB] 143s gpgv: Signature made Thu Sep 5 17:42:16 2024 UTC 143s gpgv: using RSA key 63EEFC3DE14D5146CE7F24BF34B8AD7D9529E793 143s gpgv: Can't check signature: No public key 143s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.9-1ubuntu3.dsc: no acceptable signature found 143s autopkgtest [02:17:23]: 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 [02:17:24]: build not needed 144s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 144s autopkgtest [02:17:24]: test kpartx-file-loopback: preparing testbed 145s Reading package lists... 145s Building dependency tree... 145s Reading state information... 146s Starting pkgProblemResolver with broken count: 0 146s Starting 2 pkgProblemResolver with broken count: 0 146s Done 146s The following additional packages will be installed: 146s liburing2 qemu-utils 146s Recommended packages: 146s qemu-block-extra 146s The following NEW packages will be installed: 146s autopkgtest-satdep liburing2 qemu-utils 146s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 146s Need to get 2431 kB/2432 kB of archives. 146s After this operation, 16.9 MB of additional disk space will be used. 146s Get:1 /tmp/autopkgtest.H7nLmu/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 146s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 146s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:9.0.2+ds-4ubuntu5 [2404 kB] 147s Fetched 2431 kB in 1s (3553 kB/s) 147s Selecting previously unselected package liburing2:ppc64el. 147s (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 ... 110789 files and directories currently installed.) 147s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 147s Unpacking liburing2:ppc64el (2.6-1) ... 147s Selecting previously unselected package qemu-utils. 147s Preparing to unpack .../qemu-utils_1%3a9.0.2+ds-4ubuntu5_ppc64el.deb ... 147s Unpacking qemu-utils (1:9.0.2+ds-4ubuntu5) ... 147s Selecting previously unselected package autopkgtest-satdep. 147s Preparing to unpack .../1-autopkgtest-satdep.deb ... 147s Unpacking autopkgtest-satdep (0) ... 147s Setting up liburing2:ppc64el (2.6-1) ... 147s Setting up qemu-utils (1:9.0.2+ds-4ubuntu5) ... 147s Setting up autopkgtest-satdep (0) ... 147s Processing triggers for man-db (2.12.1-3) ... 149s Processing triggers for libc-bin (2.40-1ubuntu3) ... 152s (Reading database ... 110813 files and directories currently installed.) 152s Removing autopkgtest-satdep (0) ... 152s autopkgtest [02:17:32]: test kpartx-file-loopback: [----------------------- 152s Formatting 'foo.img', fmt=raw size=20971520 153s Creating new GPT entries in memory. 153s Warning: The kernel is still using the old partition table. 153s The new table will be used at the next reboot or after you 153s run partprobe(8) or kpartx(8) 153s The operation has completed successfully. 154s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 154s standard_filename: OK 154s del devmap : loop0p1 154s No devices found 154s standard_filename_cleanup: OK 154s Formatting 'fou du FaFa.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 filename_with_spaces: OK 155s del devmap : loop0p1 155s No devices found 155s filename_with_spaces_cleanup: OK 155s autopkgtest [02:17:35]: test kpartx-file-loopback: -----------------------] 155s autopkgtest [02:17:35]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 155s kpartx-file-loopback PASS 156s autopkgtest [02:17:36]: test tgtbasedmpaths: preparing testbed 247s autopkgtest [02:19:07]: testbed dpkg architecture: ppc64el 247s autopkgtest [02:19:07]: testbed apt version: 2.9.8 247s autopkgtest [02:19:07]: @@@@@@@@@@@@@@@@@@@@ test bed setup 248s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [265 kB] 249s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [7016 B] 249s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [147 kB] 249s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [18.6 kB] 249s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [2840 B] 249s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [20.4 kB] 249s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [744 B] 249s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 249s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [99.7 kB] 249s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [3856 B] 249s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 250s Fetched 566 kB in 1s (802 kB/s) 250s Reading package lists... 252s Reading package lists... 253s Building dependency tree... 253s Reading state information... 253s Calculating upgrade... 253s The following NEW packages will be installed: 253s linux-headers-6.11.0-9 linux-headers-6.11.0-9-generic 253s linux-image-6.11.0-9-generic linux-modules-6.11.0-9-generic 253s linux-modules-extra-6.11.0-9-generic linux-tools-6.11.0-9 253s linux-tools-6.11.0-9-generic 253s The following packages will be upgraded: 253s iproute2 linux-generic linux-headers-generic linux-headers-virtual 253s linux-image-generic linux-image-virtual linux-libc-dev linux-tools-common 253s linux-virtual 253s 9 upgraded, 7 newly installed, 0 to remove and 0 not upgraded. 253s Need to get 228 MB of archives. 253s After this operation, 333 MB of additional disk space will be used. 253s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el iproute2 ppc64el 6.10.0-2ubuntu1 [1409 kB] 253s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-6.11.0-9-generic ppc64el 6.11.0-9.9 [32.8 MB] 254s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-6.11.0-9-generic ppc64el 6.11.0-9.9 [63.9 MB] 256s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-extra-6.11.0-9-generic ppc64el 6.11.0-9.9 [105 MB] 260s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-generic ppc64el 6.11.0-9.9 [1736 B] 260s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-generic ppc64el 6.11.0-9.9 [10.8 kB] 260s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-virtual ppc64el 6.11.0-9.9 [1724 B] 260s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-virtual ppc64el 6.11.0-9.9 [10.8 kB] 260s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-virtual ppc64el 6.11.0-9.9 [1644 B] 260s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.11.0-9 all 6.11.0-9.9 [13.9 MB] 260s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.11.0-9-generic ppc64el 6.11.0-9.9 [3947 kB] 260s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-generic ppc64el 6.11.0-9.9 [10.7 kB] 260s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-libc-dev ppc64el 6.11.0-9.9 [1654 kB] 260s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-common all 6.11.0-9.9 [484 kB] 260s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-9 ppc64el 6.11.0-9.9 [5177 kB] 261s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-9-generic ppc64el 6.11.0-9.9 [1736 B] 261s Preconfiguring packages ... 261s Fetched 228 MB in 8s (29.5 MB/s) 261s (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 ... 73395 files and directories currently installed.) 261s Preparing to unpack .../00-iproute2_6.10.0-2ubuntu1_ppc64el.deb ... 261s Unpacking iproute2 (6.10.0-2ubuntu1) over (6.10.0-2) ... 261s Selecting previously unselected package linux-modules-6.11.0-9-generic. 261s Preparing to unpack .../01-linux-modules-6.11.0-9-generic_6.11.0-9.9_ppc64el.deb ... 261s Unpacking linux-modules-6.11.0-9-generic (6.11.0-9.9) ... 262s Selecting previously unselected package linux-image-6.11.0-9-generic. 262s Preparing to unpack .../02-linux-image-6.11.0-9-generic_6.11.0-9.9_ppc64el.deb ... 262s Unpacking linux-image-6.11.0-9-generic (6.11.0-9.9) ... 262s Selecting previously unselected package linux-modules-extra-6.11.0-9-generic. 262s Preparing to unpack .../03-linux-modules-extra-6.11.0-9-generic_6.11.0-9.9_ppc64el.deb ... 262s Unpacking linux-modules-extra-6.11.0-9-generic (6.11.0-9.9) ... 263s Preparing to unpack .../04-linux-generic_6.11.0-9.9_ppc64el.deb ... 263s Unpacking linux-generic (6.11.0-9.9) over (6.11.0-8.8) ... 263s Preparing to unpack .../05-linux-image-generic_6.11.0-9.9_ppc64el.deb ... 263s Unpacking linux-image-generic (6.11.0-9.9) over (6.11.0-8.8) ... 263s Preparing to unpack .../06-linux-virtual_6.11.0-9.9_ppc64el.deb ... 263s Unpacking linux-virtual (6.11.0-9.9) over (6.11.0-8.8) ... 263s Preparing to unpack .../07-linux-image-virtual_6.11.0-9.9_ppc64el.deb ... 263s Unpacking linux-image-virtual (6.11.0-9.9) over (6.11.0-8.8) ... 263s Preparing to unpack .../08-linux-headers-virtual_6.11.0-9.9_ppc64el.deb ... 263s Unpacking linux-headers-virtual (6.11.0-9.9) over (6.11.0-8.8) ... 263s Selecting previously unselected package linux-headers-6.11.0-9. 263s Preparing to unpack .../09-linux-headers-6.11.0-9_6.11.0-9.9_all.deb ... 263s Unpacking linux-headers-6.11.0-9 (6.11.0-9.9) ... 265s Selecting previously unselected package linux-headers-6.11.0-9-generic. 265s Preparing to unpack .../10-linux-headers-6.11.0-9-generic_6.11.0-9.9_ppc64el.deb ... 265s Unpacking linux-headers-6.11.0-9-generic (6.11.0-9.9) ... 266s Preparing to unpack .../11-linux-headers-generic_6.11.0-9.9_ppc64el.deb ... 266s Unpacking linux-headers-generic (6.11.0-9.9) over (6.11.0-8.8) ... 266s Preparing to unpack .../12-linux-libc-dev_6.11.0-9.9_ppc64el.deb ... 266s Unpacking linux-libc-dev:ppc64el (6.11.0-9.9) over (6.11.0-8.8) ... 266s Preparing to unpack .../13-linux-tools-common_6.11.0-9.9_all.deb ... 266s Unpacking linux-tools-common (6.11.0-9.9) over (6.11.0-8.8) ... 266s Selecting previously unselected package linux-tools-6.11.0-9. 266s Preparing to unpack .../14-linux-tools-6.11.0-9_6.11.0-9.9_ppc64el.deb ... 266s Unpacking linux-tools-6.11.0-9 (6.11.0-9.9) ... 266s Selecting previously unselected package linux-tools-6.11.0-9-generic. 266s Preparing to unpack .../15-linux-tools-6.11.0-9-generic_6.11.0-9.9_ppc64el.deb ... 266s Unpacking linux-tools-6.11.0-9-generic (6.11.0-9.9) ... 266s Setting up iproute2 (6.10.0-2ubuntu1) ... 266s Setting up linux-libc-dev:ppc64el (6.11.0-9.9) ... 266s Setting up linux-headers-6.11.0-9 (6.11.0-9.9) ... 266s Setting up linux-tools-common (6.11.0-9.9) ... 266s Setting up linux-modules-6.11.0-9-generic (6.11.0-9.9) ... 268s Setting up linux-modules-extra-6.11.0-9-generic (6.11.0-9.9) ... 270s Setting up linux-headers-6.11.0-9-generic (6.11.0-9.9) ... 270s Setting up linux-image-6.11.0-9-generic (6.11.0-9.9) ... 272s I: /boot/vmlinux is now a symlink to vmlinux-6.11.0-9-generic 272s I: /boot/initrd.img is now a symlink to initrd.img-6.11.0-9-generic 272s Setting up linux-tools-6.11.0-9 (6.11.0-9.9) ... 272s Setting up linux-image-virtual (6.11.0-9.9) ... 272s Setting up linux-tools-6.11.0-9-generic (6.11.0-9.9) ... 272s Setting up linux-image-generic (6.11.0-9.9) ... 272s Setting up linux-headers-generic (6.11.0-9.9) ... 272s Setting up linux-headers-virtual (6.11.0-9.9) ... 272s Setting up linux-generic (6.11.0-9.9) ... 272s Setting up linux-virtual (6.11.0-9.9) ... 272s Processing triggers for man-db (2.12.1-3) ... 274s Processing triggers for linux-image-6.11.0-9-generic (6.11.0-9.9) ... 274s /etc/kernel/postinst.d/initramfs-tools: 274s update-initramfs: Generating /boot/initrd.img-6.11.0-9-generic 274s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 280s /etc/kernel/postinst.d/zz-update-grub: 280s Sourcing file `/etc/default/grub' 280s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 280s Generating grub configuration file ... 281s Found linux image: /boot/vmlinux-6.11.0-9-generic 281s Found initrd image: /boot/initrd.img-6.11.0-9-generic 281s Found linux image: /boot/vmlinux-6.11.0-8-generic 281s Found initrd image: /boot/initrd.img-6.11.0-8-generic 281s Warning: os-prober will not be executed to detect other bootable partitions. 281s Systems on them will not be added to the GRUB boot configuration. 281s Check GRUB_DISABLE_OS_PROBER documentation entry. 281s Adding boot menu entry for UEFI Firmware Settings ... 281s done 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 Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 282s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 282s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 282s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 283s Reading package lists... 283s Reading package lists... 283s Building dependency tree... 283s Reading state information... 283s Calculating upgrade... 283s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 283s Reading package lists... 283s Building dependency tree... 283s Reading state information... 284s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 284s Reading package lists... 284s Building dependency tree... 284s Reading state information... 284s linux-generic is already the newest version (6.11.0-9.9). 284s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 284s Reading package lists... 285s Building dependency tree... 285s Reading state information... 285s E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 285s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 285s Reading package lists... 285s Building dependency tree... 285s Reading state information... 285s E: Unable to locate package ^linux-modules-extra$ 285s E: Couldn't find any package by regex '^linux-modules-extra$' 285s autopkgtest [02:19:45]: rebooting testbed after setup commands that affected boot 319s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 331s 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 332s The following NEW packages will be installed: 332s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 332s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 332s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 332s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 332s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 332s Need to get 11.0 MB/11.0 MB of archives. 332s After this operation, 50.0 MB of additional disk space will be used. 332s Get:1 /tmp/autopkgtest.H7nLmu/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [736 B] 332s 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-0ubuntu2 [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-0ubuntu2 [3714 kB] 333s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 333s 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 (10.5 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 ... 110789 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) ... 334s Selecting previously unselected package libglusterfs0:ppc64el. 334s Preparing to unpack .../07-libglusterfs0_11.1-5ubuntu1_ppc64el.deb ... 334s Unpacking libglusterfs0:ppc64el (11.1-5ubuntu1) ... 334s Selecting previously unselected package libgfrpc0:ppc64el. 334s Preparing to unpack .../08-libgfrpc0_11.1-5ubuntu1_ppc64el.deb ... 334s Unpacking libgfrpc0:ppc64el (11.1-5ubuntu1) ... 334s Selecting previously unselected package libgfapi0:ppc64el. 334s Preparing to unpack .../09-libgfapi0_11.1-5ubuntu1_ppc64el.deb ... 334s Unpacking libgfapi0:ppc64el (11.1-5ubuntu1) ... 334s Selecting previously unselected package libnbd0. 334s Preparing to unpack .../10-libnbd0_1.20.3-1_ppc64el.deb ... 334s Unpacking libnbd0 (1.20.3-1) ... 334s Selecting previously unselected package libdaxctl1:ppc64el. 334s Preparing to unpack .../11-libdaxctl1_77-2.2ubuntu1_ppc64el.deb ... 334s Unpacking libdaxctl1:ppc64el (77-2.2ubuntu1) ... 334s Selecting previously unselected package libndctl6:ppc64el. 334s Preparing to unpack .../12-libndctl6_77-2.2ubuntu1_ppc64el.deb ... 334s Unpacking libndctl6:ppc64el (77-2.2ubuntu1) ... 334s Selecting previously unselected package libpmem1:ppc64el. 334s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 334s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 334s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 334s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 334s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 334s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 334s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 334s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 334s Selecting previously unselected package librados2. 334s Preparing to unpack .../16-librados2_19.2.0-0ubuntu2_ppc64el.deb ... 334s Unpacking librados2 (19.2.0-0ubuntu2) ... 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-0ubuntu2_ppc64el.deb ... 334s Unpacking librbd1 (19.2.0-0ubuntu2) ... 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-0ubuntu2) ... 335s Setting up open-iscsi (2.1.10-1ubuntu1) ... 336s 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-0ubuntu2) ... 336s Setting up libgfrpc0:ppc64el (11.1-5ubuntu1) ... 337s Setting up libgfapi0:ppc64el (11.1-5ubuntu1) ... 337s Setting up fio (3.37-1) ... 337s Setting up autopkgtest-satdep (0) ... 337s 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-9-generic 338s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 345s Processing triggers for libc-bin (2.40-1ubuntu3) ... 348s (Reading database ... 111030 files and directories currently installed.) 348s Removing autopkgtest-satdep (0) ... 350s autopkgtest [02:20:50]: test tgtbasedmpaths: [----------------------- 350s + targetname=iqn.2016-11.foo.com:target.iscsi 350s + pwd 350s + cwd=/tmp/autopkgtest.H7nLmu/build.HQt/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.H7nLmu/tgtbasedmpaths-artifacts/test-background.log 350s + fioprep=/tmp/autopkgtest.H7nLmu/tgtbasedmpaths-artifacts/path-change-prep.fio 350s + fiovrfy=/tmp/autopkgtest.H7nLmu/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.H7nLmu/build.HQt/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 + echo login #1 350s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 350s login #1 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 + echo extra login #2 350s + iscsiadm --mode session -r 1 --op new 350s extra login #2 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 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 + 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 + udevadm settle 350s + sleep 5 355s Status after initial setup 355s + echo Status after initial setup 355s + tgtadm --lld iscsi --mode target --op show 355s Target 1: iqn.2016-11.foo.com:target.iscsi 355s System information: 355s Driver: iscsi 355s State: ready 355s I_T nexus information: 355s I_T nexus: 1 355s Initiator: iqn.2004-10.com.ubuntu:01:50698bb188be alias: autopkgtest 355s Connection: 0 355s IP Address: 127.0.0.1 355s I_T nexus: 2 355s Initiator: iqn.2004-10.com.ubuntu:01:50698bb188be alias: autopkgtest 355s Connection: 0 355s IP Address: 127.0.0.1 355s I_T nexus: 3 355s Initiator: iqn.2004-10.com.ubuntu:01:50698bb188be alias: autopkgtest 355s Connection: 0 355s IP Address: 127.0.0.1 355s I_T nexus: 4 355s Initiator: iqn.2004-10.com.ubuntu:01:50698bb188be alias: autopkgtest 355s Connection: 0 355s IP Address: 127.0.0.1 355s LUN information: 355s LUN: 0 355s Type: controller 355s SCSI ID: IET 00010000 355s SCSI SN: beaf10 355s Size: 0 MB, Block size: 1 355s Online: Yes 355s Removable media: No 355s Prevent removal: No 355s Readonly: No 355s SWP: No 355s Thin-provisioning: No 355s Backing store type: null 355s Backing store path: None 355s Backing store flags: 355s LUN: 1 355s Type: disk 355s SCSI ID: IET 00010001 355s SCSI SN: beaf11 355s Size: 105 MB, Block size: 512 355s Online: Yes 355s Removable media: No 355s Prevent removal: No 355s Readonly: No 355s SWP: No 355s Thin-provisioning: No 355s Backing store type: rdwr 355s Backing store path: /tmp/autopkgtest.H7nLmu/build.HQt/src/backingfile 355s Backing store flags: 355s Account information: 355s ACL information: 355s ALL 355s + tgtadm --lld iscsi --op show --mode conn --tid 1 355s + iscsiadm --mode session -P 1 355s Session: 4 355s Connection: 0 355s Initiator: iqn.2004-10.com.ubuntu:01:50698bb188be 355s IP Address: 127.0.0.1 355s Session: 3 355s Connection: 0 355s Initiator: iqn.2004-10.com.ubuntu:01:50698bb188be 355s IP Address: 127.0.0.1 355s Session: 2 355s Connection: 0 355s Initiator: iqn.2004-10.com.ubuntu:01:50698bb188be 355s IP Address: 127.0.0.1 355s Session: 1 355s Connection: 0 355s Initiator: iqn.2004-10.com.ubuntu:01:50698bb188be 355s IP Address: 127.0.0.1 355s + lsscsi -liv 355s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 355s Current Portal: 127.0.0.1:3260,1 355s Persistent Portal: 127.0.0.1:3260,1 355s ********** 355s Interface: 355s ********** 355s Iface Name: default 355s Iface Transport: tcp 355s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:50698bb188be 355s Iface IPaddress: 127.0.0.1 355s Iface HWaddress: default 355s Iface Netdev: default 355s SID: 1 355s iSCSI Connection State: LOGGED IN 355s iSCSI Session State: LOGGED_IN 355s Internal iscsid Session State: NO CHANGE 355s 355s ********** 355s Interface: 355s ********** 355s Iface Name: default 355s Iface Transport: tcp 355s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:50698bb188be 355s Iface IPaddress: 127.0.0.1 355s Iface HWaddress: default 355s Iface Netdev: default 355s SID: 2 355s iSCSI Connection State: LOGGED IN 355s iSCSI Session State: LOGGED_IN 355s Internal iscsid Session State: NO CHANGE 355s 355s ********** 355s Interface: 355s ********** 355s Iface Name: default 355s Iface Transport: tcp 355s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:50698bb188be 355s Iface IPaddress: 127.0.0.1 355s Iface HWaddress: default 355s Iface Netdev: default 355s SID: 3 355s iSCSI Connection State: LOGGED IN 355s iSCSI Session State: LOGGED_IN 355s Internal iscsid Session State: NO CHANGE 355s 355s ********** 355s Interface: 355s ********** 355s Iface Name: default 355s Iface Transport: tcp 355s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:50698bb188be 355s Iface IPaddress: 127.0.0.1 355s Iface HWaddress: default 355s Iface Netdev: default 355s SID: 4 355s iSCSI Connection State: LOGGED IN 355s iSCSI Session State: LOGGED_IN 355s Internal iscsid Session State: NO CHANGE 355s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 355s [0:0:0:0] storage IET Controller 0001 - - 355s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 355s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 355s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 355s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 355s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 355s [1:0:0:0] storage IET Controller 0001 - - 355s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 355s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 355s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 355s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 355s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 355s [2:0:0:0] storage IET Controller 0001 - - 355s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 355s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 355s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 1IET_00010001 355s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 355s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 355s [3:0:0:0] storage IET Controller 0001 - - 355s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 355s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 355s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 355s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 355s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 355s NVMe module may not be loaded 355s + multipath -v3 -ll 355s 56.637438 | set open fds limit to 1073741816/1073741816 355s 56.637472 | _read_bindings_file: reading /etc/multipath/bindings 355s 56.637493 | loading /usr/lib/multipath/libchecktur.so checker 355s 56.637568 | checker tur: message table size = 4 355s 56.637575 | loading /usr/lib/multipath/libprioconst.so prioritizer 355s 56.637675 | _init_foreign: foreign library "nvme" is not enabled 355s 56.642381 | vda: device node name blacklisted 355s 56.642680 | sda: size = 204800 355s 56.642827 | sda: vendor = IET 355s 56.642867 | sda: product = VIRTUAL-DISK 355s 56.642906 | sda: rev = 0001 355s 56.643585 | sda: h:b:t:l = 0:0:0:1 355s 56.643933 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 355s 56.643956 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 355s 56.643975 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 355s 56.644159 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 355s 56.644189 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 355s 56.644221 | sda: serial = beaf11 355s 56.644242 | sda: detect_checker = yes (setting: multipath internal) 355s 56.644284 | sda checker timeout = 30 s (setting: kernel sysfs) 355s 56.644511 | sda: path_checker = tur (setting: multipath internal) 355s 56.644642 | sda: tur state = up 355s 56.644782 | sdb: size = 204800 355s 56.644926 | sdb: vendor = IET 355s 56.644966 | sdb: product = VIRTUAL-DISK 355s 56.645007 | sdb: rev = 0001 355s 56.645630 | sdb: h:b:t:l = 1:0:0:1 355s 56.645979 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 355s 56.646002 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 355s 56.646021 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 355s 56.646179 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 355s 56.646203 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 355s 56.646235 | sdb: serial = beaf11 355s 56.646258 | sdb: detect_checker = yes (setting: multipath internal) 355s 56.646301 | sdb checker timeout = 30 s (setting: kernel sysfs) 355s 56.646443 | sdb: path_checker = tur (setting: multipath internal) 355s 56.646590 | sdb: tur state = up 355s 56.646728 | sdc: size = 204800 355s 56.646878 | sdc: vendor = IET 355s 56.646922 | sdc: product = VIRTUAL-DISK 355s 56.646964 | sdc: rev = 0001 355s 56.647720 | sdc: h:b:t:l = 2:0:0:1 355s 56.648112 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 355s 56.648143 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 355s 56.648162 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 355s 56.648324 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 355s 56.648348 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 355s 56.648384 | sdc: serial = beaf11 355s 56.648406 | sdc: detect_checker = yes (setting: multipath internal) 355s 56.648452 | sdc checker timeout = 30 s (setting: kernel sysfs) 355s 56.648628 | sdc: path_checker = tur (setting: multipath internal) 355s 56.648753 | sdc: tur state = up 355s 56.648903 | sdd: size = 204800 355s 56.649074 | sdd: vendor = IET 355s 56.649119 | sdd: product = VIRTUAL-DISK 355s 56.649162 | sdd: rev = 0001 355s 56.649843 | sdd: h:b:t:l = 3:0:0:1 355s 56.650218 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 355s 56.650242 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 355s 56.650263 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 355s 56.650426 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 355s 56.650450 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 355s 56.650505 | sdd: serial = beaf11 355s 56.650529 | sdd: detect_checker = yes (setting: multipath internal) 355s 56.650575 | sdd checker timeout = 30 s (setting: kernel sysfs) 355s 56.650735 | sdd: path_checker = tur (setting: multipath internal) 355s 56.650857 | sdd: tur state = up 355s 56.650974 | loop0: device node name blacklisted 355s 56.651097 | loop1: device node name blacklisted 355s 56.651209 | loop2: device node name blacklisted 355s 56.651318 | loop3: device node name blacklisted 355s 56.651426 | loop4: device node name blacklisted 355s 56.651535 | loop5: device node name blacklisted 355s 56.651643 | loop6: device node name blacklisted 355s 56.651752 | loop7: device node name blacklisted 355s 56.651864 | dm-0: device node name blacklisted 355s 56.652909 | multipath-tools v0.9.9 (05/03, 2024) 355s 56.652945 | libdevmapper version 1.02.196 355s 56.653105 | kernel device mapper v4.48.0 355s 56.653135 | DM multipath kernel driver v1.14.0 355s 56.653252 | sda: size = 204800 355s 56.653275 | sda: vendor = IET 355s 56.653295 | sda: product = VIRTUAL-DISK 355s 56.653314 | sda: rev = 0001 355s 56.653929 | sda: h:b:t:l = 0:0:0:1 355s 56.654067 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 355s 56.654105 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 355s 56.654124 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 355s 56.654152 | sda: serial = beaf11 355s 56.654264 | sda: tur state = up 355s 56.654293 | sda: uid = 360000000000000000e00000000010001 (udev) 355s 56.654312 | sda: detect_prio = yes (setting: multipath internal) 355s 56.654332 | sda: prio = const (setting: multipath internal) 355s 56.654350 | sda: prio args = "" (setting: multipath internal) 355s 56.654368 | sda: const prio = 1 355s 56.654406 | sdb: size = 204800 355s 56.654428 | sdb: vendor = IET 355s 56.654447 | sdb: product = VIRTUAL-DISK 355s 56.654466 | sdb: rev = 0001 355s 56.655077 | sdb: h:b:t:l = 1:0:0:1 355s 56.655203 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 355s 56.655239 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 355s 56.655259 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 355s 56.655287 | sdb: serial = beaf11 355s 56.655383 | sdb: tur state = up 355s 56.655404 | sdb: uid = 360000000000000000e00000000010001 (udev) 355s 56.655422 | sdb: detect_prio = yes (setting: multipath internal) 355s 56.655441 | sdb: prio = const (setting: multipath internal) 355s 56.655459 | sdb: prio args = "" (setting: multipath internal) 355s 56.655477 | sdb: const prio = 1 355s 56.655513 | sdd: size = 204800 355s 56.655535 | sdd: vendor = IET 355s 56.655554 | sdd: product = VIRTUAL-DISK 355s 56.655573 | sdd: rev = 0001 355s 56.656197 | sdd: h:b:t:l = 3:0:0:1 355s 56.656329 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 355s 56.656365 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 355s 56.656385 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 355s 56.656413 | sdd: serial = beaf11 355s 56.656700 | sdd: tur state = up 355s 56.656721 | sdd: uid = 360000000000000000e00000000010001 (udev) 355s 56.656740 | sdd: detect_prio = yes (setting: multipath internal) 355s 56.656759 | sdd: prio = const (setting: multipath internal) 355s 56.656777 | sdd: prio args = "" (setting: multipath internal) 355s 56.656796 | sdd: const prio = 1 355s 56.656832 | sdc: size = 204800 355s 56.656854 | sdc: vendor = IET 355s 56.656873 | sdc: product = VIRTUAL-DISK 355s 56.656892 | sdc: rev = 0001 355s 56.657480 | sdc: h:b:t:l = 2:0:0:1 355s 56.657606 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 355s 56.657644 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 355s 56.657665 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 355s 56.657693 | sdc: serial = beaf11 355s 56.657794 | sdc: tur state = up 355s 56.657815 | sdc: uid = 360000000000000000e00000000010001 (udev) 355s 56.657834 | sdc: detect_prio = yes (setting: multipath internal) 355s 56.657852 | sdc: prio = const (setting: multipath internal) 355s 56.657870 | sdc: prio args = "" (setting: multipath internal) 355s 56.657888 | sdc: const prio = 1 355s 56.658640 | unloading tur checker 355s 56.658692 | unloading const prioritizer 355s ===== paths list ===== 355s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 355s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 355s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 355s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 355s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 355s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 355s size=100M features='0' hwhandler='0' wp=rw 355s |-+- policy='service-time 0' prio=1 status=active 355s | `- 0:0:0:1 sda 8:0 active ready running 355s |-+- policy='service-time 0' prio=1 status=enabled 355s | `- 1:0:0:1 sdb 8:16 active ready running 355s |-+- policy='service-time 0' prio=1 status=enabled 355s | `- 3:0:0:1 sdd 8:48 active ready running 355s `-+- policy='service-time 0' prio=1 status=enabled 355s `- 2:0:0:1 sdc 8:32 active ready running 355s mpatha: 0 204800 multipath 0 0 4 1 service-time 0 1 2 8:0 1 1 service-time 0 1 2 8:16 1 1 service-time 0 1 2 8:48 1 1 service-time 0 1 2 8:32 1 1 355s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 355s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 355s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 355s /etc/multipath/bindings:# 355s /etc/multipath/bindings:# Format: 355s /etc/multipath/bindings:# alias wwid 355s /etc/multipath/bindings:# 355s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 355s /etc/multipath/wwids:/360000000000000000e00000000010001/ 355s ● multipathd.service - Device-Mapper Multipath Device Controller 355s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 355s Active: active (running) since Fri 2024-10-18 02:20:01 UTC; 54s ago 355s Invocation: 3634c4e9110b46c8914cb911c3fc5a8b 355s TriggeredBy: ○ multipathd.socket 355s Main PID: 328 (multipathd) 355s Status: "up" 355s Tasks: 7 355s Memory: 27.9M (peak: 37.4M) 355s CPU: 35ms 355s CGroup: /system.slice/multipathd.service 355s └─328 /sbin/multipathd -d -s 355s 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 355s Oct 18 02:20:01 autopkgtest multipathd[328]: multipathd v0.9.9: start up 355s Oct 18 02:20:01 autopkgtest multipathd[328]: reconfigure: setting up paths and maps 355s Oct 18 02:20:01 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 355s Oct 18 02:20:50 autopkgtest multipathd[328]: updated bindings file /etc/multipath/bindings 355s Oct 18 02:20:50 autopkgtest multipathd[328]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 355s Oct 18 02:20:50 autopkgtest multipathd[328]: sda [8:0]: path added to devmap mpatha 355s Oct 18 02:20:50 autopkgtest multipathd[328]: mpatha: performing delayed actions 355s Oct 18 02:20:50 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:32 1] 355s ○ multipathd.socket - multipathd control socket 355s Loaded: loaded (/usr/lib/systemd/system/multipathd.socket; static) 355s Active: inactive (dead) 355s Triggers: ● multipathd.service 355s Listen: @/org/kernel/linux/storage/multipathd (Stream) 355s total 0 355s drwxr-xr-x 2 root root 80 Oct 18 02:20 . 355s drwxr-xr-x 20 root root 4360 Oct 18 02:20 .. 355s crw------- 1 root root 10, 236 Oct 18 02:20 control 355s lrwxrwxrwx 1 root root 7 Oct 18 02:20 mpatha -> ../dm-0 355s journal 355s Oct 18 02:20:01 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 355s Oct 18 02:20:01 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 355s Oct 18 02:20:01 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 355s Oct 18 02:20:01 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 355s Oct 18 02:20:01 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 355s Oct 18 02:20:01 autopkgtest kernel: Activating Kernel Userspace Access Prevention 355s Oct 18 02:20:01 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 355s Oct 18 02:20:01 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x0000000003a00000 with 2.00 MiB pages (exec) 355s Oct 18 02:20:01 autopkgtest kernel: radix-mmu: Mapped 0x0000000003a00000-0x0000000040000000 with 2.00 MiB pages 355s Oct 18 02:20:01 autopkgtest kernel: radix-mmu: Mapped 0x0000000040000000-0x0000000200000000 with 1.00 GiB pages 355s Oct 18 02:20:01 autopkgtest kernel: lpar: Using radix MMU under hypervisor 355s Oct 18 02:20:01 autopkgtest kernel: Linux version 6.11.0-9-generic (buildd@bos03-ppc64el-024) (powerpc64le-linux-gnu-gcc-14 (Ubuntu 14.2.0-4ubuntu2) 14.2.0, GNU ld (GNU Binutils for Ubuntu) 2.43.1) #9-Ubuntu SMP Mon Oct 14 13:15:06 UTC 2024 (Ubuntu 6.11.0-9.9-generic 6.11.0) 355s Oct 18 02:20:01 autopkgtest kernel: Secure boot mode disabled 355s Oct 18 02:20:01 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc000000009455259 355s Oct 18 02:20:01 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (architected) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 355s Oct 18 02:20:01 autopkgtest kernel: Partition configured for 4 cpus. 355s Oct 18 02:20:01 autopkgtest kernel: CPU maps initialized for 1 thread per core 355s Oct 18 02:20:01 autopkgtest kernel: (thread shift is 0) 355s Oct 18 02:20:01 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 355s Oct 18 02:20:01 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 355s Oct 18 02:20:01 autopkgtest kernel: ----------------------------------------------------- 355s Oct 18 02:20:01 autopkgtest kernel: phys_mem_size = 0x200000000 355s Oct 18 02:20:01 autopkgtest kernel: dcache_bsize = 0x80 355s Oct 18 02:20:01 autopkgtest kernel: icache_bsize = 0x80 355s Oct 18 02:20:01 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 355s Oct 18 02:20:01 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 355s Oct 18 02:20:01 autopkgtest kernel: always = 0x0000000380008181 355s Oct 18 02:20:01 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 355s Oct 18 02:20:01 autopkgtest kernel: mmu_features = 0x3c007641 355s Oct 18 02:20:01 autopkgtest kernel: firmware_features = 0x00000285455a445f 355s Oct 18 02:20:01 autopkgtest kernel: vmalloc start = 0xc008000000000000 355s Oct 18 02:20:01 autopkgtest kernel: IO start = 0xc00a000000000000 355s Oct 18 02:20:01 autopkgtest kernel: vmemmap start = 0xc00c000000000000 355s Oct 18 02:20:01 autopkgtest kernel: ----------------------------------------------------- 355s Oct 18 02:20:01 autopkgtest kernel: numa: NODE_DATA [mem 0x1fff7c280-0x1fff83fff] 355s Oct 18 02:20:01 autopkgtest kernel: rfi-flush: fallback displacement flush available 355s Oct 18 02:20:01 autopkgtest kernel: rfi-flush: ori type flush available 355s Oct 18 02:20:01 autopkgtest kernel: rfi-flush: mttrig type flush available 355s Oct 18 02:20:01 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 355s Oct 18 02:20:01 autopkgtest kernel: count-cache-flush: hardware flush enabled. 355s Oct 18 02:20:01 autopkgtest kernel: link-stack-flush: software flush enabled. 355s Oct 18 02:20:01 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 355s Oct 18 02:20:01 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 355s Oct 18 02:20:01 autopkgtest kernel: stf-barrier: eieio barrier available 355s Oct 18 02:20:01 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 355s Oct 18 02:20:01 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 355s Oct 18 02:20:01 autopkgtest kernel: PPC64 nvram contains 65536 bytes 355s Oct 18 02:20:01 autopkgtest kernel: barrier-nospec: using ORI speculation bar+ dmsetup table 355s + grep . /etc/multipath/bindings /etc/multipath/wwids 355s + systemctl status multipathd.service 355s + ret_code=0 355s + systemctl status multipathd.socket 355s + ret_code=3 355s + [ 3 -eq 0 ] 355s + [ 3 -eq 3 ] 355s + ls -la /dev/mapper/ 355s + echo journal 355s + journalctl -b 355s rier 355s Oct 18 02:20:01 autopkgtest kernel: barrier-nospec: patched 275 locations 355s Oct 18 02:20:01 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 355s Oct 18 02:20:01 autopkgtest kernel: Memory hole size: 0MB 355s Oct 18 02:20:01 autopkgtest kernel: Zone ranges: 355s Oct 18 02:20:01 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 355s Oct 18 02:20:01 autopkgtest kernel: Device empty 355s Oct 18 02:20:01 autopkgtest kernel: Movable zone start for each node 355s Oct 18 02:20:01 autopkgtest kernel: Early memory node ranges 355s Oct 18 02:20:01 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 355s Oct 18 02:20:01 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 355s Oct 18 02:20:01 autopkgtest kernel: percpu: Embedded 12 pages/cpu s619032 r0 d167400 u786432 355s Oct 18 02:20:01 autopkgtest kernel: pcpu-alloc: s619032 r0 d167400 u786432 alloc=12*65536 355s Oct 18 02:20:01 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 355s Oct 18 02:20:01 autopkgtest kernel: Kernel command line: BOOT_IMAGE=/boot/vmlinux-6.11.0-9-generic root=UUID=af850f5d-75d9-4c88-aaf8-d0f70c524874 ro console=hvc0 earlyprintk 355s Oct 18 02:20:01 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.11.0-9-generic", will be passed to user space. 355s Oct 18 02:20:01 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 355s Oct 18 02:20:01 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 355s Oct 18 02:20:01 autopkgtest kernel: Fallback order for Node 0: 0 355s Oct 18 02:20:01 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 131072 355s Oct 18 02:20:01 autopkgtest kernel: Policy zone: Normal 355s Oct 18 02:20:01 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 355s Oct 18 02:20:01 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 355s Oct 18 02:20:01 autopkgtest kernel: ftrace: allocating 52900 entries in 20 pages 355s Oct 18 02:20:01 autopkgtest kernel: ftrace: allocated 20 pages with 2 groups 355s Oct 18 02:20:01 autopkgtest kernel: trace event string verifier disabled 355s Oct 18 02:20:01 autopkgtest kernel: rcu: Hierarchical RCU implementation. 355s Oct 18 02:20:01 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 355s Oct 18 02:20:01 autopkgtest kernel: Rude variant of Tasks RCU enabled. 355s Oct 18 02:20:01 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 355s Oct 18 02:20:01 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 355s Oct 18 02:20:01 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 355s Oct 18 02:20:01 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 355s Oct 18 02:20:01 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 355s Oct 18 02:20:01 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 355s Oct 18 02:20:01 autopkgtest kernel: xive: Using IRQ range [0-3] 355s Oct 18 02:20:01 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 355s Oct 18 02:20:01 autopkgtest kernel: xive: Using priority 6 for all interrupts 355s Oct 18 02:20:01 autopkgtest kernel: xive: Using 64kB queues 355s Oct 18 02:20:01 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 355s Oct 18 02:20:01 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 355s Oct 18 02:20:01 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 355s Oct 18 02:20:01 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 355s Oct 18 02:20:01 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 355s Oct 18 02:20:01 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 355s Oct 18 02:20:01 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 355s Oct 18 02:20:01 autopkgtest kernel: Console: colour dummy device 80x25 355s Oct 18 02:20:01 autopkgtest kernel: pid_max: default: 32768 minimum: 301 355s Oct 18 02:20:01 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,ima,evm 355s Oct 18 02:20:01 autopkgtest kernel: landlock: Up and running. 355s Oct 18 02:20:01 autopkgtest kernel: Yama: becoming mindful. 355s Oct 18 02:20:01 autopkgtest kernel: AppArmor: AppArmor initialized 355s Oct 18 02:20:01 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 355s Oct 18 02:20:01 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 355s Oct 18 02:20:01 autopkgtest kernel: POWER9 performance monitor hardware support registered 355s Oct 18 02:20:01 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 355s Oct 18 02:20:01 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 355s Oct 18 02:20:01 autopkgtest kernel: Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level 355s Oct 18 02:20:01 autopkgtest kernel: smp: Bringing up secondary CPUs ... 355s Oct 18 02:20:01 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 355s Oct 18 02:20:01 autopkgtest kernel: numa: Node 0 CPUs: 0-3 355s Oct 18 02:20:01 autopkgtest kernel: Memory: 8205248K/8388608K available (24384K kernel code, 4160K rwdata, 24768K rodata, 8768K init, 1851K bss, 157248K reserved, 0K cma-reserved) 355s Oct 18 02:20:01 autopkgtest kernel: devtmpfs: initialized 355s Oct 18 02:20:01 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 355s Oct 18 02:20:01 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 355s Oct 18 02:20:01 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 355s Oct 18 02:20:01 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 355s Oct 18 02:20:01 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 355s Oct 18 02:20:01 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 355s Oct 18 02:20:01 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 355s Oct 18 02:20:01 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 355s Oct 18 02:20:01 autopkgtest kernel: audit: initializing netlink subsys (disabled) 355s Oct 18 02:20:01 autopkgtest kernel: audit: type=2000 audit(1729217998.036:1): state=initialized audit_enabled=0 res=1 355s Oct 18 02:20:01 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 355s Oct 18 02:20:01 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 355s Oct 18 02:20:01 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 355s Oct 18 02:20:01 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 355s Oct 18 02:20:01 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 355s Oct 18 02:20:01 autopkgtest kernel: cpuidle: using governor ladder 355s Oct 18 02:20:01 autopkgtest kernel: cpuidle: using governor menu 355s Oct 18 02:20:01 autopkgtest kernel: RTAS daemon started 355s Oct 18 02:20:01 autopkgtest kernel: pstore: Using crash dump compression: deflate 355s Oct 18 02:20:01 autopkgtest kernel: pstore: Registered nvram as persistent store backend 355s Oct 18 02:20:01 autopkgtest kernel: EEH: pSeries platform initialized 355s Oct 18 02:20:01 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 355s Oct 18 02:20:01 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 355s Oct 18 02:20:01 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 355s Oct 18 02:20:01 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 355s Oct 18 02:20:01 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 355s Oct 18 02:20:01 autopkgtest kernel: iommu: Default domain type: Translated 355s Oct 18 02:20:01 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 355s Oct 18 02:20:01 autopkgtest kernel: SCSI subsystem initialized 355s Oct 18 02:20:01 autopkgtest kernel: libata version 3.00 loaded. 355s Oct 18 02:20:01 autopkgtest kernel: usbcore: registered new interface driver usbfs 355s Oct 18 02:20:01 autopkgtest kernel: usbcore: registered new interface driver hub 355s Oct 18 02:20:01 autopkgtest kernel: usbcore: registered new device driver usb 355s Oct 18 02:20:01 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 355s Oct 18 02:20:01 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 355s Oct 18 02:20:01 autopkgtest kernel: PTP clock support registered 355s Oct 18 02:20:01 autopkgtest kernel: EDAC MC: Ver: 3.0.0 355s Oct 18 02:20:01 autopkgtest kernel: NetLabel: Initializing 355s Oct 18 02:20:01 autopkgtest kernel: NetLabel: domain hash size = 128 355s Oct 18 02:20:01 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 355s Oct 18 02:20:01 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 355s Oct 18 02:20:01 autopkgtest kernel: mctp: management component transport protocol core 355s Oct 18 02:20:01 autopkgtest kernel: NET: Registered PF_MCTP protocol family 355s Oct 18 02:20:01 autopkgtest kernel: PCI: Probing PCI hardware 355s Oct 18 02:20:01 autopkgtest kernel: PCI host bridge to bus 0000:00 355s Oct 18 02:20:01 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 355s Oct 18 02:20:01 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 355s Oct 18 02:20:01 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 355s Oct 18 02:20:01 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:05.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:06.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:07.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 355s Oct 18 02:20:01 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 355s Oct 18 02:20:01 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 355s Oct 18 02:20:01 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 355s Oct 18 02:20:01 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 355s Oct 18 02:20:01 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:01.0: ibm,query-pe-dma-windows(2026) 800 8000000 20000000 returned 0, lb=80000000 ps=7 wn=1 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:05.0: Adding to iommu group 0 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:06.0: Adding to iommu group 0 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:07.0: Adding to iommu group 0 355s Oct 18 02:20:01 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 355s Oct 18 02:20:01 autopkgtest kernel: PCI: Probing PCI hardware done 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:07.0: vgaarb: setting as boot VGA device 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:07.0: vgaarb: bridge control possible 355s Oct 18 02:20:01 autopkgtest kernel: pci 0000:00:07.0: vgaarb: VGA device added: decodes=io+mem,owns=mem,locks=none 355s Oct 18 02:20:01 autopkgtest kernel: vgaarb: loaded 355s Oct 18 02:20:01 autopkgtest kernel: clocksource: Switched to clocksource timebase 355s Oct 18 02:20:01 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 355s Oct 18 02:20:01 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 355s Oct 18 02:20:01 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 355s Oct 18 02:20:01 autopkgtest kernel: NET: Registered PF_INET protocol family 355s Oct 18 02:20:01 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 355s Oct 18 02:20:01 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 355s Oct 18 02:20:01 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 355s Oct 18 02:20:01 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 355s Oct 18 02:20:01 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 355s Oct 18 02:20:01 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 355s Oct 18 02:20:01 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 355s Oct 18 02:20:01 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 355s Oct 18 02:20:01 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 355s Oct 18 02:20:01 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 355s Oct 18 02:20:01 autopkgtest kernel: NET: Registered PF_XDP protocol family 355s Oct 18 02:20:01 autopkgtest kernel: PCI: CLS 0 bytes, default 128 355s Oct 18 02:20:01 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 355s Oct 18 02:20:01 autopkgtest kernel: Initialise system trusted keyrings 355s Oct 18 02:20:01 autopkgtest kernel: Key type blacklist registered 355s Oct 18 02:20:01 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 355s Oct 18 02:20:01 autopkgtest kernel: zbud: loaded 355s Oct 18 02:20:01 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 355s Oct 18 02:20:01 autopkgtest kernel: fuse: init (API version 7.40) 355s Oct 18 02:20:01 autopkgtest kernel: integrity: Platform Keyring initialized 355s Oct 18 02:20:01 autopkgtest kernel: integrity: Machine keyring initialized 355s Oct 18 02:20:01 autopkgtest kernel: Key type asymmetric registered 355s Oct 18 02:20:01 autopkgtest kernel: Asymmetric key parser 'x509' registered 355s Oct 18 02:20:01 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 355s Oct 18 02:20:01 autopkgtest kernel: io scheduler mq-deadline registered 355s Oct 18 02:20:01 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 355s Oct 18 02:20:01 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 355s Oct 18 02:20:01 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) 355s Oct 18 02:20:01 autopkgtest kernel: virtio-pci 0000:00:03.0: enabling device (0100 -> 0103) 355s Oct 18 02:20:01 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 355s Oct 18 02:20:01 autopkgtest kernel: virtio-pci 0000:00:05.0: enabling device (0100 -> 0103) 355s Oct 18 02:20:01 autopkgtest kernel: virtio-pci 0000:00:06.0: enabling device (0100 -> 0103) 355s Oct 18 02:20:01 autopkgtest kernel: printk: legacy console [hvc0] enabled 355s Oct 18 02:20:01 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 355s Oct 18 02:20:01 autopkgtest kernel: Freeing initrd memory: 51520K 355s Oct 18 02:20:01 autopkgtest kernel: Non-volatile memory driver v1.3 355s Oct 18 02:20:01 autopkgtest kernel: Linux agpgart interface v0.103 355s Oct 18 02:20:01 autopkgtest kernel: loop: module loaded 355s Oct 18 02:20:01 autopkgtest kernel: virtio_blk virtio2: 4/0/0 default/read/poll queues 355s Oct 18 02:20:01 autopkgtest kernel: virtio_blk virtio2: [vda] 209715200 512-byte logical blocks (107 GB/100 GiB) 355s Oct 18 02:20:01 autopkgtest kernel: vda: vda1 vda2 355s Oct 18 02:20:01 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 355s Oct 18 02:20:01 autopkgtest kernel: PPP generic driver version 2.4.2 355s Oct 18 02:20:01 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 355s Oct 18 02:20:01 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 355s Oct 18 02:20:01 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-10-18T02:19:59 UTC (1729217999) 355s Oct 18 02:20:01 autopkgtest kernel: i2c_dev: i2c /dev entries driver 355s Oct 18 02:20:01 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 355s Oct 18 02:20:01 autopkgtest kernel: device-mapper: uevent: version 1.0.3 355s Oct 18 02:20:01 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@lists.linux.dev 355s Oct 18 02:20:01 autopkgtest kernel: pseries_idle_driver registered 355s Oct 18 02:20:01 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 355s Oct 18 02:20:01 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 355s Oct 18 02:20:01 autopkgtest kernel: NET: Registered PF_INET6 protocol family 355s Oct 18 02:20:01 autopkgtest kernel: Segment Routing with IPv6 355s Oct 18 02:20:01 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 355s Oct 18 02:20:01 autopkgtest kernel: NET: Registered PF_PACKET protocol family 355s Oct 18 02:20:01 autopkgtest kernel: Key type dns_resolver registered 355s Oct 18 02:20:01 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 355s Oct 18 02:20:01 autopkgtest kernel: registered taskstats version 1 355s Oct 18 02:20:01 autopkgtest kernel: Loading compiled-in X.509 certificates 355s Oct 18 02:20:01 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: ea022af66f4997dbe4e5fb80420684c0e4692ac5' 355s Oct 18 02:20:01 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 355s Oct 18 02:20:01 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 355s Oct 18 02:20:01 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 355s Oct 18 02:20:01 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 355s Oct 18 02:20:01 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 355s Oct 18 02:20:01 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 355s Oct 18 02:20:01 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 355s Oct 18 02:20:01 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 355s Oct 18 02:20:01 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 355s Oct 18 02:20:01 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 355s Oct 18 02:20:01 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 355s Oct 18 02:20:01 autopkgtest kernel: Demotion targets for Node 0: null 355s Oct 18 02:20:01 autopkgtest kernel: Key type .fscrypt registered 355s Oct 18 02:20:01 autopkgtest kernel: Key type fscrypt-provisioning registered 355s Oct 18 02:20:01 autopkgtest kernel: Key type encrypted registered 355s Oct 18 02:20:01 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 355s Oct 18 02:20:01 autopkgtest kernel: Secure boot mode disabled 355s Oct 18 02:20:01 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 355s Oct 18 02:20:01 autopkgtest kernel: Loading compiled-in module X.509 certificates 355s Oct 18 02:20:01 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: ea022af66f4997dbe4e5fb80420684c0e4692ac5' 355s Oct 18 02:20:01 autopkgtest kernel: ima: Allocated hash algorithm: sha256 355s Oct 18 02:20:01 autopkgtest kernel: Secure boot mode disabled 355s Oct 18 02:20:01 autopkgtest kernel: Trusted boot mode disabled 355s Oct 18 02:20:01 autopkgtest kernel: ima: No architecture policies found 355s Oct 18 02:20:01 autopkgtest kernel: evm: Initialising EVM extended attributes: 355s Oct 18 02:20:01 autopkgtest kernel: evm: security.selinux 355s Oct 18 02:20:01 autopkgtest kernel: evm: security.SMACK64 355s Oct 18 02:20:01 autopkgtest kernel: evm: security.SMACK64EXEC 355s Oct 18 02:20:01 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 355s Oct 18 02:20:01 autopkgtest kernel: evm: security.SMACK64MMAP 355s Oct 18 02:20:01 autopkgtest kernel: evm: security.apparmor 355s Oct 18 02:20:01 autopkgtest kernel: evm: security.ima 355s Oct 18 02:20:01 autopkgtest kernel: evm: security.capability 355s Oct 18 02:20:01 autopkgtest kernel: evm: HMAC attrs: 0x1 355s Oct 18 02:20:01 autopkgtest kernel: SED: plpks not available 355s Oct 18 02:20:01 autopkgtest kernel: clk: Disabling unused clocks 355s Oct 18 02:20:01 autopkgtest kernel: PM: genpd: Disabling unused power domains 355s Oct 18 02:20:01 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 355s Oct 18 02:20:01 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8768K 355s Oct 18 02:20:01 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 355s Oct 18 02:20:01 autopkgtest kernel: Run /init as init process 355s Oct 18 02:20:01 autopkgtest kernel: with arguments: 355s Oct 18 02:20:01 autopkgtest kernel: /init 355s Oct 18 02:20:01 autopkgtest kernel: earlyprintk 355s Oct 18 02:20:01 autopkgtest kernel: with environment: 355s Oct 18 02:20:01 autopkgtest kernel: HOME=/ 355s Oct 18 02:20:01 autopkgtest kernel: TERM=linux 355s Oct 18 02:20:01 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.11.0-9-generic 355s Oct 18 02:20:01 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 355s Oct 18 02:20:01 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 355s Oct 18 02:20:01 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 1 355s Oct 18 02:20:01 autopkgtest kernel: xhci_hcd 0000:00:02.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010 355s Oct 18 02:20:01 autopkgtest kernel: random: crng init done 355s Oct 18 02:20:01 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 355s Oct 18 02:20:01 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2 355s Oct 18 02:20:01 autopkgtest kernel: xhci_hcd 0000:00:02.0: Host supports USB 3.0 SuperSpeed 355s Oct 18 02:20:01 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.11 355s Oct 18 02:20:01 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 355s Oct 18 02:20:01 autopkgtest kernel: usb usb1: Product: xHCI Host Controller 355s Oct 18 02:20:01 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.11.0-9-generic xhci-hcd 355s Oct 18 02:20:01 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:02.0 355s Oct 18 02:20:01 autopkgtest kernel: hub 1-0:1.0: USB hub found 355s Oct 18 02:20:01 autopkgtest kernel: hub 1-0:1.0: 4 ports detected 355s Oct 18 02:20:01 autopkgtest kernel: usb usb2: We don't know the algorithms for LPM for this host, disabling LPM. 355s Oct 18 02:20:01 autopkgtest kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.11 355s Oct 18 02:20:01 autopkgtest kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 355s Oct 18 02:20:01 autopkgtest kernel: usb usb2: Product: xHCI Host Controller 355s Oct 18 02:20:01 autopkgtest kernel: usb usb2: Manufacturer: Linux 6.11.0-9-generic xhci-hcd 355s Oct 18 02:20:01 autopkgtest kernel: usb usb2: SerialNumber: 0000:00:02.0 355s Oct 18 02:20:01 autopkgtest kernel: hub 2-0:1.0: USB hub found 355s Oct 18 02:20:01 autopkgtest kernel: hub 2-0:1.0: 4 ports detected 355s Oct 18 02:20:01 autopkgtest kernel: [drm] Found bochs VGA, ID 0xb0c5. 355s Oct 18 02:20:01 autopkgtest kernel: [drm] Framebuffer size 16384 kB @ 0x200081000000, mmio @ 0x200082000000. 355s Oct 18 02:20:01 autopkgtest kernel: [drm] Found EDID data blob. 355s Oct 18 02:20:01 autopkgtest kernel: [drm] Initialized bochs-drm 1.0.0 for 0000:00:07.0 on minor 0 355s Oct 18 02:20:01 autopkgtest kernel: fbcon: Deferring console take-over 355s Oct 18 02:20:01 autopkgtest kernel: bochs-drm 0000:00:07.0: [drm] fb0: bochs-drmdrmfb frame buffer device 355s Oct 18 02:20:01 autopkgtest kernel: raid6: vpermxor8 gen() 22828 MB/s 355s Oct 18 02:20:01 autopkgtest kernel: raid6: vpermxor4 gen() 19869 MB/s 355s Oct 18 02:20:01 autopkgtest kernel: usb 1-1: new high-speed USB device number 2 using xhci_hcd 355s Oct 18 02:20:01 autopkgtest kernel: raid6: vpermxor2 gen() 16019 MB/s 355s Oct 18 02:20:01 autopkgtest kernel: raid6: vpermxor1 gen() 13488 MB/s 355s Oct 18 02:20:01 autopkgtest kernel: usb 1-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 355s Oct 18 02:20:01 autopkgtest kernel: usb 1-1: New USB device strings: Mfr=1, Product=4, SerialNumber=11 355s Oct 18 02:20:01 autopkgtest kernel: usb 1-1: Product: QEMU USB Keyboard 355s Oct 18 02:20:01 autopkgtest kernel: usb 1-1: Manufacturer: QEMU 355s Oct 18 02:20:01 autopkgtest kernel: usb 1-1: SerialNumber: 68284-pci@800000020000000:02.0-1 355s Oct 18 02:20:01 autopkgtest kernel: hid: raw HID events driver (C) Jiri Kosina 355s Oct 18 02:20:01 autopkgtest kernel: raid6: altivecx8 gen() 13828 MB/s 355s Oct 18 02:20:01 autopkgtest kernel: usbcore: registered new interface driver usbhid 355s Oct 18 02:20:01 autopkgtest kernel: usbhid: USB HID core driver 355s Oct 18 02:20:01 autopkgtest kernel: input: QEMU QEMU USB Keyboard as /devices/pci0000:00/0000:00:02.0/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input0 355s Oct 18 02:20:01 autopkgtest kernel: hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v1.11 Keyboard [QEMU QEMU USB Keyboard] on usb-0000:00:02.0-1/input0 355s Oct 18 02:20:01 autopkgtest kernel: raid6: altivecx4 gen() 13757 MB/s 355s Oct 18 02:20:01 autopkgtest kernel: usb 1-2: new high-speed USB device number 3 using xhci_hcd 355s Oct 18 02:20:01 autopkgtest kernel: raid6: altivecx2 gen() 11091 MB/s 355s Oct 18 02:20:01 autopkgtest kernel: raid6: altivecx1 gen() 8619 MB/s 355s Oct 18 02:20:01 autopkgtest kernel: usb 1-2: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 355s Oct 18 02:20:01 autopkgtest kernel: usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=9 355s Oct 18 02:20:01 autopkgtest kernel: usb 1-2: Product: QEMU USB Mouse 355s Oct 18 02:20:01 autopkgtest kernel: usb 1-2: Manufacturer: QEMU 355s Oct 18 02:20:01 autopkgtest kernel: usb 1-2: SerialNumber: 89126-pci@800000020000000:02.0-2 355s Oct 18 02:20:01 autopkgtest kernel: input: QEMU QEMU USB Mouse as /devices/pci0000:00/0000:00:02.0/usb1/1-2/1-2:1.0/0003:0627:0001.0002/input/input1 355s Oct 18 02:20:01 autopkgtest kernel: hid-generic 0003:0627:0001.0002: input,hidraw1: USB HID v0.01 Mouse [QEMU QEMU USB Mouse] on usb-0000:00:02.0-2/input0 355s Oct 18 02:20:01 autopkgtest kernel: raid6: int64x8 gen() 7171 MB/s 355s Oct 18 02:20:01 autopkgtest kernel: raid6: int64x4 gen() 8666 MB/s 355s Oct 18 02:20:01 autopkgtest kernel: raid6: int64x2 gen() 6580 MB/s 355s Oct 18 02:20:01 autopkgtest kernel: raid6: int64x1 gen() 5250 MB/s 355s Oct 18 02:20:01 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 22828 MB/s 355s Oct 18 02:20:01 autopkgtest kernel: raid6: using intx1 recovery algorithm 355s Oct 18 02:20:01 autopkgtest kernel: xor: measuring software checksum speed 355s Oct 18 02:20:01 autopkgtest kernel: 8regs : 17368 MB/sec 355s Oct 18 02:20:01 autopkgtest kernel: 8regs_prefetch : 15590 MB/sec 355s Oct 18 02:20:01 autopkgtest kernel: 32regs : 17369 MB/sec 355s Oct 18 02:20:01 autopkgtest kernel: 32regs_prefetch : 15650 MB/sec 355s Oct 18 02:20:01 autopkgtest kernel: altivec : 19427 MB/sec 355s Oct 18 02:20:01 autopkgtest kernel: xor: using function: altivec (19427 MB/sec) 355s Oct 18 02:20:01 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 355s Oct 18 02:20:01 autopkgtest kernel: EXT4-fs (vda1): orphan cleanup on readonly fs 355s Oct 18 02:20:01 autopkgtest kernel: EXT4-fs (vda1): mounted filesystem af850f5d-75d9-4c88-aaf8-d0f70c524874 ro with ordered data mode. Quota mode: none. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Inserted module 'autofs4' 355s Oct 18 02:20:01 autopkgtest systemd[1]: systemd 256.5-2ubuntu3 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) 355s Oct 18 02:20:01 autopkgtest systemd[1]: Detected virtualization kvm. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Detected architecture ppc64-le. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Hostname set to . 355s Oct 18 02:20:01 autopkgtest systemd[1]: bpf-restrict-fs: BPF LSM hook not enabled in the kernel, BPF LSM not supported. 355s Oct 18 02:20:01 autopkgtest kernel: NET: Registered PF_VSOCK protocol family 355s Oct 18 02:20:01 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. 355s Oct 18 02:20:01 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. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Queued start job for default target graphical.target. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Reached target swap.target - Swaps. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 355s Oct 18 02:20:01 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Sockets. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounting run-lock.mount - Legacy Locks Directory /run/lock... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting modprobe@dm_multipath.service - Load Kernel Module dm_multipath... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 355s Oct 18 02:20:01 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 355s Oct 18 02:20:01 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). 355s Oct 18 02:20:01 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). 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounted run-lock.mount - Legacy Locks Directory /run/lock. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 355s Oct 18 02:20:01 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 355s Oct 18 02:20:01 autopkgtest systemd[1]: modprobe@dm_multipath.service: Deactivated successfully. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished modprobe@dm_multipath.service - Load Kernel Module dm_multipath. 355s Oct 18 02:20:01 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 355s Oct 18 02:20:01 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 355s Oct 18 02:20:01 autopkgtest systemd-journald[280]: Collecting audit messages is disabled. 355s Oct 18 02:20:01 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 355s Oct 18 02:20:01 autopkgtest systemd-journald[280]: Journal started 355s Oct 18 02:20:01 autopkgtest systemd-journald[280]: Runtime Journal (/run/log/journal/07363006a08d46bfb19ca4c4d6aab1cc) is 8M, max 81M, 73M free. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 355s Oct 18 02:20:01 autopkgtest kernel: EXT4-fs (vda1): re-mounted af850f5d-75d9-4c88-aaf8-d0f70c524874 r/w. Quota mode: none. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting cloud-init-main.service - Cloud-init: Single Process... 355s Oct 18 02:20:01 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 355s Oct 18 02:20:01 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 355s Oct 18 02:20:01 autopkgtest systemd-journald[280]: Time spent on flushing to /var/log/journal/07363006a08d46bfb19ca4c4d6aab1cc is 25.278ms for 459 entries. 355s Oct 18 02:20:01 autopkgtest systemd-journald[280]: System Journal (/var/log/journal/07363006a08d46bfb19ca4c4d6aab1cc) is 18.8M, max 4G, 3.9G free. 355s Oct 18 02:20:01 autopkgtest systemd-journald[280]: Received client request to flush runtime journal. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 355s Oct 18 02:20:01 autopkgtest multipathd[328]: multipathd v0.9.9: start up 355s Oct 18 02:20:01 autopkgtest multipathd[328]: reconfigure: setting up paths and maps 355s Oct 18 02:20:01 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 355s Oct 18 02:20:01 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 355s Oct 18 02:20:01 autopkgtest apparmor.systemd[346]: Restarting AppArmor 355s Oct 18 02:20:01 autopkgtest apparmor.systemd[346]: Reloading AppArmor profiles 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 355s Oct 18 02:20:01 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 352 (systemd-binfmt) 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 355s Oct 18 02:20:01 autopkgtest systemd-tmpfiles[368]: /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 355s Oct 18 02:20:01 autopkgtest kernel: audit: type=1400 audit(1729218001.396:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=374 comm="apparmor_parser" 355s Oct 18 02:20:01 autopkgtest kernel: audit: type=1400 audit(1729218001.400:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=372 comm="apparmor_parser" 355s Oct 18 02:20:01 autopkgtest systemd-udevd[339]: Using default interface naming scheme 'v255'. 355s Oct 18 02:20:01 autopkgtest kernel: audit: type=1400 audit(1729218001.400:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=373 comm="apparmor_parser" 355s Oct 18 02:20:01 autopkgtest kernel: audit: type=1400 audit(1729218001.400:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=375 comm="apparmor_parser" 355s Oct 18 02:20:01 autopkgtest kernel: audit: type=1400 audit(1729218001.400:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=377 comm="apparmor_parser" 355s Oct 18 02:20:01 autopkgtest kernel: audit: type=1400 audit(1729218001.400:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=379 comm="apparmor_parser" 355s Oct 18 02:20:01 autopkgtest kernel: audit: type=1400 audit(1729218001.400:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=378 comm="apparmor_parser" 355s Oct 18 02:20:01 autopkgtest kernel: audit: type=1400 audit(1729218001.400:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="busybox" pid=380 comm="apparmor_parser" 355s Oct 18 02:20:01 autopkgtest kernel: audit: type=1400 audit(1729218001.404:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="cam" pid=381 comm="apparmor_parser" 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. 355s Oct 18 02:20:01 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 355s Oct 18 02:20:01 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 355s Oct 18 02:20:01 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 355s Oct 18 02:20:01 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). 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 355s Oct 18 02:20:01 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 355s Oct 18 02:20:01 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 355s Oct 18 02:20:01 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 355s Oct 18 02:20:01 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 355s Oct 18 02:20:01 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). 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 355s Oct 18 02:20:01 autopkgtest (udev-worker)[491]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 355s Oct 18 02:20:01 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Started cloud-init-main.service - Cloud-init: Single Process. 355s Oct 18 02:20:01 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 355s Oct 18 02:20:01 autopkgtest cloud-init[679]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu4 running 'init-local' at Fri, 18 Oct 2024 02:20:01 +0000. Up 2.81 seconds. 355s Oct 18 02:20:02 autopkgtest dhcpcd[682]: dhcpcd-10.0.8 starting 355s Oct 18 02:20:02 autopkgtest dhcpcd[685]: DUID 00:01:00:01:2e:a3:53:da:fa:16:3e:d9:f3:c0 355s Oct 18 02:20:02 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 355s Oct 18 02:20:02 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 355s Oct 18 02:20:02 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 355s Oct 18 02:20:02 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 355s Oct 18 02:20:02 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 355s Oct 18 02:20:02 autopkgtest dhcpcd[685]: enp0s1: IAID 3e:17:4a:3f 355s Oct 18 02:20:02 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 355s Oct 18 02:20:02 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 355s Oct 18 02:20:02 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 355s Oct 18 02:20:02 autopkgtest dhcpcd[685]: enp0s1: rebinding lease of 10.145.227.203 355s Oct 18 02:20:02 autopkgtest systemd-resolved[405]: Positive Trust Anchors: 355s Oct 18 02:20:02 autopkgtest systemd-resolved[405]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 355s Oct 18 02:20:02 autopkgtest systemd-resolved[405]: 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 355s Oct 18 02:20:02 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 355s Oct 18 02:20:02 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 355s Oct 18 02:20:02 autopkgtest dhcpcd[685]: enp0s1: leased 10.145.227.203 for 43200 seconds 355s Oct 18 02:20:02 autopkgtest dhcpcd[685]: enp0s1: adding route to 10.145.227.0/24 355s Oct 18 02:20:02 autopkgtest dhcpcd[685]: enp0s1: adding host route to 169.254.169.254 via 10.145.227.2 355s Oct 18 02:20:02 autopkgtest dhcpcd[685]: enp0s1: adding default route via 10.145.227.1 355s Oct 18 02:20:02 autopkgtest dhcpcd[685]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 355s Oct 18 02:20:02 autopkgtest systemd-resolved[405]: Using system hostname 'autopkgtest'. 355s Oct 18 02:20:02 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 355s Oct 18 02:20:02 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 355s Oct 18 02:20:16 autopkgtest sh[675]: Completed socket interaction for boot stage local 355s Oct 18 02:20:16 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 355s Oct 18 02:20:16 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 355s Oct 18 02:20:16 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 355s Oct 18 02:20:16 autopkgtest systemd-networkd[720]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 355s Oct 18 02:20:16 autopkgtest systemd-networkd[720]: lo: Link UP 355s Oct 18 02:20:16 autopkgtest systemd-networkd[720]: lo: Gained carrier 355s Oct 18 02:20:16 autopkgtest systemd-networkd[720]: Enumeration completed 355s Oct 18 02:20:16 autopkgtest systemd-networkd[720]: enp0s1: Link UP 355s Oct 18 02:20:16 autopkgtest systemd-networkd[720]: enp0s1: Gained carrier 355s Oct 18 02:20:16 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 355s Oct 18 02:20:16 autopkgtest systemd-networkd[720]: enp0s1: Gained IPv6LL 355s Oct 18 02:20:16 autopkgtest systemd-timesyncd[409]: Network configuration changed, trying to establish connection. 355s Oct 18 02:20:16 autopkgtest systemd-networkd[720]: enp0s1: Link DOWN 355s Oct 18 02:20:16 autopkgtest systemd-networkd[720]: enp0s1: Lost carrier 355s Oct 18 02:20:16 autopkgtest systemd[1]: Reached target network.target - Network. 355s Oct 18 02:20:16 autopkgtest systemd-timesyncd[409]: No network connectivity, watching for changes. 355s Oct 18 02:20:16 autopkgtest systemd-networkd[720]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 355s Oct 18 02:20:16 autopkgtest systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... 355s Oct 18 02:20:16 autopkgtest systemd-networkd[720]: enp0s1: Link UP 355s Oct 18 02:20:16 autopkgtest systemd-networkd[720]: enp0s1: Gained carrier 355s Oct 18 02:20:16 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 355s Oct 18 02:20:16 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 355s Oct 18 02:20:16 autopkgtest systemd-networkd[720]: enp0s1: DHCPv4 address 10.145.227.203/24, gateway 10.145.227.1 acquired from 10.145.227.1 355s Oct 18 02:20:16 autopkgtest systemd-timesyncd[409]: Network configuration changed, trying to establish connection. 355s Oct 18 02:20:16 autopkgtest systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. 355s Oct 18 02:20:17 autopkgtest systemd-timesyncd[409]: Contacted time server 185.125.190.57:123 (ntp.ubuntu.com). 355s Oct 18 02:20:17 autopkgtest systemd-timesyncd[409]: Initial clock synchronization to Fri 2024-10-18 02:20:16.635770 UTC. 355s Oct 18 02:20:18 autopkgtest systemd-networkd[720]: enp0s1: Gained IPv6LL 355s Oct 18 02:20:18 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 355s Oct 18 02:20:18 autopkgtest systemd[1]: Starting cloud-init-network.service - Cloud-init: Network Stage... 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu4 running 'init' at Fri, 18 Oct 2024 02:20:18 +0000. Up 19.05 seconds. 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | enp0s1 | True | 10.145.227.203 | 255.255.255.0 | global | fa:16:3e:17:4a:3f | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | enp0s1 | True | fe80::f816:3eff:fe17:4a3f/64 | . | link | fa:16:3e:17:4a:3f | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | lo | True | ::1/128 | . | host | . | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++++ 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | 0 | 0.0.0.0 | 10.145.227.1 | 0.0.0.0 | enp0s1 | UG | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | 1 | 10.145.227.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | 2 | 10.145.227.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | 3 | 10.145.227.2 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | 4 | 91.189.91.131 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | 5 | 91.189.91.132 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | 6 | 169.254.169.254 | 10.145.227.2 | 255.255.255.255 | enp0s1 | UGH | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: +-------+-------------+---------+-----------+-------+ 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | Route | Destination | Gateway | Interface | Flags | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: +-------+-------------+---------+-----------+-------+ 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | 2 | local | :: | enp0s1 | U | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: | 3 | multicast | :: | enp0s1 | U | 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: ci-info: +-------+-------------+---------+-----------+-------+ 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: 2024-10-18 02:20:18,305 - 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. 355s Oct 18 02:20:18 autopkgtest cloud-init[679]: 2024-10-18 02:20:18,305 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 355s Oct 18 02:20:18 autopkgtest sh[732]: Completed socket interaction for boot stage network 355s Oct 18 02:20:18 autopkgtest systemd[1]: Finished cloud-init-network.service - Cloud-init: Network Stage. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 356s Oct 18 02:20:18 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 18 02:20:18 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 18 02:20:18 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started sysstat-collect.timer - Run system activity accounting tool every 10 minutes. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started sysstat-rotate.timer - Rotate daily system activity data file at midnight. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started sysstat-summary.timer - Generate summary of yesterday's process accounting. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 356s Oct 18 02:20:18 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 18 02:20:18 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Reached target paths.target - Path Units. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 356s Oct 18 02:20:18 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 356s Oct 18 02:20:18 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). 356s Oct 18 02:20:18 autopkgtest systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). 356s Oct 18 02:20:18 autopkgtest systemd[1]: Reached target ssh-access.target - SSH Access Available. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Reached target basic.target - Basic System. 356s Oct 18 02:20:18 autopkgtest systemd[1]: System is tainted: unmerged-bin 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 356s Oct 18 02:20:18 autopkgtest (sh)[768]: autopkgtest@hvc1.service: Failed to set up standard input: No such device 356s Oct 18 02:20:18 autopkgtest (sh)[768]: autopkgtest@hvc1.service: Failed at step STDIN spawning /bin/sh: No such device 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 356s Oct 18 02:20:18 autopkgtest (sh)[769]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 356s Oct 18 02:20:18 autopkgtest (sh)[769]: autopkgtest@ttyS1.service: Failed at step STDIN spawning /bin/sh: Input/output error 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 356s Oct 18 02:20:18 autopkgtest (cron)[771]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 356s Oct 18 02:20:18 autopkgtest cron[771]: (CRON) INFO (pidfile fd = 3) 356s Oct 18 02:20:18 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 18 02:20:18 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 356s Oct 18 02:20:18 autopkgtest cron[771]: (CRON) INFO (Running @reboot jobs) 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 356s Oct 18 02:20:18 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 356s Oct 18 02:20:18 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 18 02:20:18 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 18 02:20:18 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting sysstat.service - Resets System Activity Logs... 356s Oct 18 02:20:18 autopkgtest dbus-daemon[772]: [system] AppArmor D-Bus mediation is enabled 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 356s Oct 18 02:20:18 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 18 02:20:18 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 356s Oct 18 02:20:18 autopkgtest systemd[1]: autopkgtest@hvc1.service: Deactivated successfully. 356s Oct 18 02:20:18 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 356s Oct 18 02:20:18 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 356s Oct 18 02:20:18 autopkgtest udisksd[794]: udisks daemon version 2.10.1 starting 356s Oct 18 02:20:18 autopkgtest systemd[1]: Finished sysstat.service - Resets System Activity Logs. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 356s Oct 18 02:20:18 autopkgtest cloud-init[679]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu4 running 'modules:config' at Fri, 18 Oct 2024 02:20:18 +0000. Up 19.28 seconds. 356s Oct 18 02:20:18 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 356s Oct 18 02:20:18 autopkgtest rngd[833]: rngd 2.4 starting up... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 356s Oct 18 02:20:18 autopkgtest rngd[833]: entropy feed to the kernel ready 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 356s Oct 18 02:20:18 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 356s Oct 18 02:20:18 autopkgtest sh[775]: Completed socket interaction for boot stage config 356s Oct 18 02:20:18 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 356s Oct 18 02:20:18 autopkgtest systemd-logind[790]: New seat seat0. 356s Oct 18 02:20:18 autopkgtest systemd-logind[790]: Watching system buttons on /dev/input/event0 (QEMU QEMU USB Keyboard) 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 356s Oct 18 02:20:18 autopkgtest udisksd[794]: Acquired the name org.freedesktop.UDisks2 on the system message bus 356s Oct 18 02:20:18 autopkgtest kernel: kauditd_printk_skb: 110 callbacks suppressed 356s Oct 18 02:20:18 autopkgtest kernel: audit: type=1400 audit(1729218018.575:121): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=852 comm="apparmor_parser" 356s Oct 18 02:20:18 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 356s Oct 18 02:20:18 autopkgtest rsyslogd[874]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2406.0] 356s Oct 18 02:20:18 autopkgtest rsyslogd[874]: rsyslogd's groupid changed to 102 356s Oct 18 02:20:18 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 356s Oct 18 02:20:18 autopkgtest rsyslogd[874]: rsyslogd's userid changed to 102 356s Oct 18 02:20:18 autopkgtest rsyslogd[874]: [origin software="rsyslogd" swVersion="8.2406.0" x-pid="874" x-info="https://www.rsyslog.com"] start 356s Oct 18 02:20:18 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 356s Oct 18 02:20:18 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 356s Oct 18 02:20:18 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 356s Oct 18 02:20:18 autopkgtest cloud-init[679]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu4 running 'modules:final' at Fri, 18 Oct 2024 02:20:18 +0000. Up 19.52 seconds. 356s Oct 18 02:20:18 autopkgtest cloud-init[679]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu4 finished at Fri, 18 Oct 2024 02:20:18 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 19.58 seconds 356s Oct 18 02:20:18 autopkgtest sh[884]: Completed socket interaction for boot stage final 356s Oct 18 02:20:18 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 356s Oct 18 02:20:18 autopkgtest systemd[1]: Startup finished in 1.678s (kernel) + 17.907s (userspace) = 19.586s. 356s Oct 18 02:20:18 autopkgtest kernel: fbcon: Taking over console 356s Oct 18 02:20:18 autopkgtest kernel: Console: switching to colour frame buffer device 128x48 356s Oct 18 02:20:18 autopkgtest systemd[1]: cloud-init-main.service: Deactivated successfully. 356s Oct 18 02:20:18 autopkgtest systemd[1]: cloud-init-main.service: Consumed 926ms CPU time, 111.1M memory peak. 356s Oct 18 02:20:18 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 356s Oct 18 02:20:19 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 356s Oct 18 02:20:19 autopkgtest sshd[934]: Server listening on 0.0.0.0 port 22. 356s Oct 18 02:20:19 autopkgtest sshd[934]: Server listening on :: port 22. 356s Oct 18 02:20:19 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 356s Oct 18 02:20:19 autopkgtest sshd[936]: Accepted publickey for ubuntu from 10.136.6.150 port 41616 ssh2: RSA SHA256:Gw9qjiDx3RIaYTDnVkitJKSxA3w8qwwDNReNp21Qo3I 356s Oct 18 02:20:19 autopkgtest sshd[936]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 356s Oct 18 02:20:19 autopkgtest sshd[936]: pam_systemd(sshd:session): New sd-bus connection (system-bus-pam-systemd-936) opened. 356s Oct 18 02:20:19 autopkgtest systemd-logind[790]: New session 1 of user ubuntu. 356s Oct 18 02:20:19 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 356s Oct 18 02:20:19 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 356s Oct 18 02:20:19 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 356s Oct 18 02:20:19 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 356s Oct 18 02:20:19 autopkgtest (systemd)[940]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 356s Oct 18 02:20:19 autopkgtest systemd-logind[790]: New session 2 of user ubuntu. 356s Oct 18 02:20:19 autopkgtest systemd[940]: Queued start job for default target default.target. 356s Oct 18 02:20:19 autopkgtest systemd[940]: Created slice app.slice - User Application Slice. 356s Oct 18 02:20:19 autopkgtest systemd[940]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 356s Oct 18 02:20:19 autopkgtest systemd[940]: Reached target paths.target - Paths. 356s Oct 18 02:20:19 autopkgtest systemd[940]: Reached target timers.target - Timers. 356s Oct 18 02:20:19 autopkgtest systemd[940]: Starting dbus.socket - D-Bus User Message Bus Socket... 356s Oct 18 02:20:19 autopkgtest systemd[940]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 356s Oct 18 02:20:19 autopkgtest systemd[940]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 356s Oct 18 02:20:19 autopkgtest systemd[940]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 356s Oct 18 02:20:19 autopkgtest systemd[940]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 356s Oct 18 02:20:19 autopkgtest systemd[940]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 356s Oct 18 02:20:19 autopkgtest systemd[940]: Listening on keyboxd.socket - GnuPG public key management service. 356s Oct 18 02:20:19 autopkgtest systemd[940]: Listening on dbus.socket - D-Bus User Message Bus Socket. 356s Oct 18 02:20:19 autopkgtest systemd[940]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 356s Oct 18 02:20:19 autopkgtest systemd[940]: Reached target sockets.target - Sockets. 356s Oct 18 02:20:19 autopkgtest systemd[940]: Reached target basic.target - Basic System. 356s Oct 18 02:20:19 autopkgtest systemd[940]: Reached target default.target - Main User Target. 356s Oct 18 02:20:19 autopkgtest systemd[940]: Startup finished in 127ms. 356s Oct 18 02:20:19 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 356s Oct 18 02:20:19 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 356s Oct 18 02:20:22 autopkgtest sudo[969]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 356s Oct 18 02:20:22 autopkgtest sudo[969]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:22 autopkgtest sudo[969]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:23 autopkgtest sudo[974]: 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 18 02:20:23 autopkgtest sudo[974]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:23 autopkgtest sudo[974]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:23 autopkgtest sudo[986]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.H7nLmu 356s Oct 18 02:20:23 autopkgtest sudo[986]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:23 autopkgtest sudo[986]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:23 autopkgtest sudo[996]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.H7nLmu/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.H7nLmu/autopkgtest-reboot' 356s Oct 18 02:20:23 autopkgtest sudo[996]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:23 autopkgtest sudo[996]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:23 autopkgtest sudo[1009]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.H7nLmu/autopkgtest-reboot 356s Oct 18 02:20:23 autopkgtest sudo[1009]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:23 autopkgtest sudo[1009]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:23 autopkgtest sudo[1019]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.H7nLmu/autopkgtest-reboot /tmp/autopkgtest-reboot 356s Oct 18 02:20:23 autopkgtest sudo[1019]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:23 autopkgtest sudo[1019]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:24 autopkgtest sudo[1029]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.H7nLmu/autopkgtest-reboot /sbin/autopkgtest-reboot 356s Oct 18 02:20:24 autopkgtest sudo[1029]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:24 autopkgtest sudo[1029]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:24 autopkgtest sudo[1039]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.H7nLmu 356s Oct 18 02:20:24 autopkgtest sudo[1039]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:24 autopkgtest sudo[1039]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:24 autopkgtest sudo[1049]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.H7nLmu/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.H7nLmu/autopkgtest-reboot-prepare' 356s Oct 18 02:20:24 autopkgtest sudo[1049]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:24 autopkgtest sudo[1049]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:24 autopkgtest sudo[1061]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.H7nLmu/autopkgtest-reboot-prepare 356s Oct 18 02:20:24 autopkgtest sudo[1061]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:24 autopkgtest sudo[1061]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:24 autopkgtest sudo[1071]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.H7nLmu/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 356s Oct 18 02:20:24 autopkgtest sudo[1071]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:24 autopkgtest sudo[1071]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:24 autopkgtest sudo[1081]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 356s Oct 18 02:20:24 autopkgtest sudo[1081]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:24 autopkgtest sudo[1081]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:25 autopkgtest sudo[1091]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 356s Oct 18 02:20:25 autopkgtest sudo[1091]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:25 autopkgtest sudo[1091]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:25 autopkgtest sudo[1101]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.H7nLmu/testbed-packages' 356s Oct 18 02:20:25 autopkgtest sudo[1101]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:25 autopkgtest sudo[1101]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:25 autopkgtest sudo[1112]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.H7nLmu/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.H7nLmu/autopkgtest-reboot' 356s Oct 18 02:20:25 autopkgtest sudo[1133]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:25 autopkgtest sudo[1133]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:26 autopkgtest sudo[1145]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.H7nLmu/autopkgtest-reboot 356s Oct 18 02:20:26 autopkgtest sudo[1145]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:26 autopkgtest sudo[1145]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:26 autopkgtest sudo[1155]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.H7nLmu/autopkgtest-reboot /tmp/autopkgtest-reboot 356s Oct 18 02:20:26 autopkgtest sudo[1155]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:26 autopkgtest sudo[1155]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:26 autopkgtest sudo[1165]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.H7nLmu/autopkgtest-reboot /sbin/autopkgtest-reboot 356s Oct 18 02:20:26 autopkgtest sudo[1165]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:26 autopkgtest sudo[1165]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:26 autopkgtest sudo[1175]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.H7nLmu 356s Oct 18 02:20:26 autopkgtest sudo[1175]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:26 autopkgtest sudo[1175]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:26 autopkgtest sudo[1185]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.H7nLmu/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.H7nLmu/autopkgtest-reboot-prepare' 356s Oct 18 02:20:26 autopkgtest sudo[1185]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:26 autopkgtest sudo[1185]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:26 autopkgtest sudo[1197]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.H7nLmu/autopkgtest-reboot-prepare 356s Oct 18 02:20:26 autopkgtest sudo[1197]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:26 autopkgtest sudo[1197]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:27 autopkgtest sudo[1207]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.H7nLmu/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 356s Oct 18 02:20:27 autopkgtest sudo[1207]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:27 autopkgtest sudo[1207]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:27 autopkgtest sudo[1217]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 356s Oct 18 02:20:27 autopkgtest sudo[1217]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:27 autopkgtest sudo[1217]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:27 autopkgtest sudo[1227]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 356s Oct 18 02:20:27 autopkgtest sudo[1227]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:27 autopkgtest sudo[1227]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:30 autopkgtest sudo[1236]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.H7nLmu 356s Oct 18 02:20:30 autopkgtest sudo[1236]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:30 autopkgtest sudo[1236]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:30 autopkgtest sudo[1246]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.H7nLmu/2-autopkgtest-satdep.deb' 356s Oct 18 02:20:30 autopkgtest sudo[1246]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:30 autopkgtest sudo[1246]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:30 autopkgtest sudo[1257]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.H7nLmu/2-autopkgtest-satdep.deb 356s Oct 18 02:20:30 autopkgtest sudo[1257]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:30 autopkgtest sudo[1257]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:31 autopkgtest sudo[1267]: 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.H7nLmu/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 18 02:20:31 autopkgtest sudo[1267]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:34 autopkgtest systemd[1]: Reload requested from client PID 1507 ('systemctl') (unit session-1.scope)... 356s Oct 18 02:20:34 autopkgtest systemd[1]: Reloading... 356s Oct 18 02:20:34 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 18 02:20:34 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 18 02:20:34 autopkgtest systemd[1]: Reloading finished in 216 ms. 356s Oct 18 02:20:34 autopkgtest systemd[1]: Reload requested from client PID 1553 ('systemctl') (unit session-1.scope)... 356s Oct 18 02:20:34 autopkgtest systemd[1]: Reloading... 356s Oct 18 02:20:35 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 18 02:20:35 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 18 02:20:35 autopkgtest systemd[1]: Reloading finished in 191 ms. 356s Oct 18 02:20:35 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 356s Oct 18 02:20:35 autopkgtest tgtd[1595]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 356s Oct 18 02:20:35 autopkgtest tgtd[1595]: tgtd: work_timer_start(146) use timer_fd based scheduler 356s Oct 18 02:20:35 autopkgtest tgtd[1595]: tgtd: bs_init(387) use signalfd notification 356s Oct 18 02:20:35 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 356s Oct 18 02:20:35 autopkgtest systemd[1]: Reload requested from client PID 1622 ('systemctl') (unit session-1.scope)... 356s Oct 18 02:20:35 autopkgtest systemd[1]: Reloading... 356s Oct 18 02:20:35 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 18 02:20:35 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 18 02:20:35 autopkgtest systemd[1]: Reloading finished in 205 ms. 356s Oct 18 02:20:35 autopkgtest systemd[1]: Reload requested from client PID 1661 ('systemctl') (unit session-1.scope)... 356s Oct 18 02:20:35 autopkgtest systemd[1]: Reloading... 356s Oct 18 02:20:35 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 18 02:20:35 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 18 02:20:36 autopkgtest systemd[1]: Reloading finished in 183 ms. 356s Oct 18 02:20:36 autopkgtest systemd[1]: Reload requested from client PID 1703 ('systemctl') (unit session-1.scope)... 356s Oct 18 02:20:36 autopkgtest systemd[1]: Reloading... 356s Oct 18 02:20:36 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 18 02:20:36 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 18 02:20:36 autopkgtest systemd[1]: Reloading finished in 204 ms. 356s Oct 18 02:20:36 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 356s Oct 18 02:20:36 autopkgtest systemd[1]: Reload requested from client PID 1750 ('systemctl') (unit session-1.scope)... 356s Oct 18 02:20:36 autopkgtest systemd[1]: Reloading... 356s Oct 18 02:20:36 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 18 02:20:36 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 18 02:20:36 autopkgtest systemd[1]: Reloading finished in 189 ms. 356s Oct 18 02:20:36 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 356s Oct 18 02:20:36 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 356s Oct 18 02:20:36 autopkgtest systemd[1]: Reload requested from client PID 1801 ('systemctl') (unit session-1.scope)... 356s Oct 18 02:20:36 autopkgtest systemd[1]: Reloading... 356s Oct 18 02:20:37 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 18 02:20:37 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 18 02:20:37 autopkgtest systemd[1]: Reloading finished in 171 ms. 356s Oct 18 02:20:45 autopkgtest sudo[1267]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:46 autopkgtest sudo[5675]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 356s Oct 18 02:20:46 autopkgtest sudo[5675]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:46 autopkgtest sudo[5675]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:46 autopkgtest sudo[5685]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 356s Oct 18 02:20:46 autopkgtest sudo[5685]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:46 autopkgtest sudo[5685]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:46 autopkgtest sudo[5695]: 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 18 02:20:46 autopkgtest sudo[5695]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:47 autopkgtest sudo[5695]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:47 autopkgtest sudo[5708]: 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 18 02:20:47 autopkgtest sudo[5708]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:47 autopkgtest sudo[5708]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:47 autopkgtest sudo[5720]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 356s Oct 18 02:20:47 autopkgtest sudo[5720]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:47 autopkgtest sudo[5720]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:47 autopkgtest sudo[5732]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 356s Oct 18 02:20:47 autopkgtest sudo[5732]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:48 autopkgtest sudo[5732]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:48 autopkgtest sudo[5742]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.H7nLmu/tgtbasedmpaths-packages.all' 356s Oct 18 02:20:48 autopkgtest sudo[5742]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 356s Oct 18 02:20:48 autopkgtest sudo[5742]: pam_unix(sudo:session): session closed for user root 356s Oct 18 02:20:48 autopkgtest sudo[5753]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 359s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 359s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 359s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 359s latency : target=0, window=0, percentile=100.00%, depth=1 359s 359s Run status group 0 (all jobs): 359s WRITE: bw=163MiB/s (171MB/s), 163MiB/s-163MiB/s (171MB/s-171MB/s), io=87.5MiB (91.8MB), run=536-536msec 359s 359s Disk stats (read/write): 359s dm-0: ios=1/1042, sectors=8/133376, merge=0/0, ticks=1/347, in_queue=347, util=69.39%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/115, aggrin_queue=115, aggrutil=69.11% 359s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 359s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 359s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 359s sda: ios=1/1402, sectors=8/179280, merge=0/0, ticks=1/463, in_queue=463, util=69.11% 359s + echo Starting the path changes in background 359s Starting the path changes in background 359s + date +Pre FIO %H:%M:%S.%N 359s Pre FIO 02:20:59.785760745 359s + fio --max-jobs=4 /tmp/autopkgtest.H7nLmu/tgtbasedmpaths-artifacts/path-change-check.fio 359s 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 359s fio-3.37 359s Starting 1 thread 540s 540s verify-phase: (groupid=0, jobs=1): err= 0: pid=6093: Fri Oct 18 02:24:00 2024 540s read: IOPS=5754, BW=360MiB/s (377MB/s)(63.2GiB/180001msec) 540s clat (usec): min=73, max=48160, avg=151.68, stdev=129.04 540s lat (usec): min=73, max=48160, avg=151.78, stdev=129.04 540s clat percentiles (usec): 540s | 1.00th=[ 88], 5.00th=[ 98], 10.00th=[ 106], 20.00th=[ 118], 540s | 30.00th=[ 127], 40.00th=[ 135], 50.00th=[ 143], 60.00th=[ 151], 540s | 70.00th=[ 159], 80.00th=[ 167], 90.00th=[ 182], 95.00th=[ 196], 540s | 99.00th=[ 619], 99.50th=[ 807], 99.90th=[ 1074], 99.95th=[ 1450], 540s | 99.99th=[ 2114] 540s bw ( KiB/s): min=177280, max=485888, per=100.00%, avg=368602.01, stdev=41168.85, samples=359 540s iops : min= 2770, max= 7592, avg=5759.41, stdev=643.26, samples=359 540s lat (usec) : 100=5.57%, 250=92.42%, 500=0.91%, 750=0.31%, 1000=0.69% 540s lat (msec) : 2=0.10%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01% 540s cpu : usr=13.49%, sys=6.00%, ctx=1035939, 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=1035809,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=360MiB/s (377MB/s), 360MiB/s-360MiB/s (377MB/s-377MB/s), io=63.2GiB (67.9GB), run=180001-180001msec 540s 540s Disk stats (read/write): 540s dm-0: ios=1035945/10, sectors=132501944/12928, merge=0/9, ticks=155457/69, in_queue=155570, util=80.48%, aggrios=74851/2, aggsectors=9572942/3232, aggrmerge=0/0, aggrticks=10024/6, aggrin_queue=10030, aggrutil=76.81% 540s sdd: ios=181304/0, sectors=23190400/0, merge=0/0, ticks=24324/0, in_queue=24324, util=44.00% 540s sdb: ios=57637/0, sectors=7367736/0, merge=0/0, ticks=8140/0, in_queue=8140, util=37.82% 540s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 540s sda: ios=60464/9, sectors=7733632/12928, merge=0/0, ticks=7632/24, in_queue=7658, util=76.81% 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.H7nLmu/tgtbasedmpaths-artifacts/test-background.log 540s Post FIO 02:24:00.123746776 540s FIO verify test with changing paths - OK 540s Report log of background activity 540s + sync 540s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 540s + echo Final stats 540s + iscsiadm --mode session --stats 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) 02:21:09.792116106 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 | `- 0:0:0:1 sda 8:0 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 | `- 3:0:0:1 sdd 8:48 active ready running 540s `-+- policy='service-time 0' prio=1 status=enabled 540s `- 2:0:0:1 sdc 8:32 active ready running 540s + date +UN-plug path 1 %H:%M:%S.%N 540s UN-plug path 1 02:21:09.813433226 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) 02:21:19.925476928 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 | `- 3:0:0:1 sdd 8:48 active ready running 540s `-+- policy='service-time 0' prio=1 status=enabled 540s `- 2:0:0:1 sdc 8:32 active ready running 540s + date +UN-plug path 2 %H:%M:%S.%N 540s UN-plug path 2 02:21:19.944041918 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) 02:21:30.037596054 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 `- 2:0:0:1 sdc 8:32 active ready running 540s + date +UN-plug path 3 %H:%M:%S.%N 540s UN-plug path 3 02:21:30.051517748 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) 02:21:40.164512998 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 + date +Add paths 5/6/7/8 %H:%M:%S.%N 540s Add paths 5/6/7/8 02:21:40.175281973 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) 02:21:50.237567780 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 | `- 1:0:0:1 sdb 8:16 active ready running 540s |-+- policy='service-time 0' prio=1 status=enabled 540s | `- 0:0:0:1 sda 8:0 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 `- 4:0:0:1 sde 8:64 active ready running 540s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 540s UN-plug multiple paths 4/7/8 02:21:50.260542833 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 02:22:00.524567760 540s + systemctl restart multipathd 540s + sleep 10s 540s + date +Final background report (expect 2) %H:%M:%S.%N 540s Final background report (expect 2) 02:22:10.605516674 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 `- 0:0:0:1 sda 8:0 active ready running 540s Final stats 540s + journalctl --no-pager -u multipathd 540s + echo Check final path status 540s + multipath -ll 540s + multipath -ll 540s + grep --count status= 540s + diskc=2 540s + multipath -ll 540s + grep --count status=active 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: 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 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: 35286792 540s rxdata_octets: 48155149296 540s noptx_pdus: 0 540s scsicmd_pdus: 734874 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: 734874 540s tmfrsp_pdus: 0 540s textrsp_pdus: 0 540s datain_pdus: 734839 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 17 04:49:29 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 17 04:49:29 ubuntu multipathd[356]: multipathd v0.9.9: start up 540s Oct 17 04:49:29 ubuntu multipathd[356]: reconfigure: setting up paths and maps 540s Oct 17 04:49:29 ubuntu multipathd[356]: _check_bindings_file: failed to read header from /etc/multipath/bindings 540s Oct 17 04:49:29 ubuntu multipathd[356]: updated bindings file /etc/multipath/bindings 540s Oct 17 04:49:29 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 540s Oct 17 04:52:10 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i multipathd[356]: multipathd: shut down 540s Oct 17 04:52:10 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 17 04:52:10 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 540s Oct 17 04:52:10 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 540s -- Boot 09d1c2af15974b09866214657d321e8b -- 540s Oct 17 04:52:23 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i multipathd[282]: multipathd v0.9.9: start up 540s Oct 17 04:52:23 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i multipathd[282]: reconfigure: setting up paths and maps 540s Oct 17 04:52:23 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 540s Oct 17 04:52:39 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i multipathd[282]: multipathd: shut down 540s Oct 17 04:52:39 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 17 04:52:39 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 540s Oct 17 04:52:39 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 540s -- Boot 4764e807e0114db08d9126b5f7b54a87 -- 540s Oct 18 02:18:40 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i multipathd[311]: multipathd v0.9.9: start up 540s Oct 18 02:18:40 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i multipathd[311]: reconfigure: setting up paths and maps 540s Oct 18 02:18:40 auto-syncubuntu-oracular-daily-ppc64el-server-20241009-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 540s Oct 18 02:19:49 autopkgtest multipathd[311]: multipathd: shut down 540s Oct 18 02:19:49 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 18 02:19:49 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 540s Oct 18 02:19:49 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 540s -- Boot b87b155dc0434ddc8a053a4154674791 -- 540s Oct 18 02:20:01 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 18 02:20:01 autopkgtest multipathd[328]: multipathd v0.9.9: start up 540s Oct 18 02:20:01 autopkgtest multipathd[328]: reconfigure: setting up paths and maps 540s Oct 18 02:20:01 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 540s Oct 18 02:20:50 autopkgtest multipathd[328]: updated bindings file /etc/multipath/bindings 540s Oct 18 02:20:50 autopkgtest multipathd[328]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 540s Oct 18 02:20:50 autopkgtest multipathd[328]: sda [8:0]: path added to devmap mpatha 540s Oct 18 02:20:50 autopkgtest multipathd[328]: mpatha: performing delayed actions 540s Oct 18 02:20:50 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:32 1] 540s Oct 18 02:21:09 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:32 1] 540s Oct 18 02:21:09 autopkgtest multipathd[328]: check_removed_paths: sda: freeing path in removed state 540s Oct 18 02:21:09 autopkgtest multipathd[328]: 8:0: path removed from map mpatha 540s Oct 18 02:21:19 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:32 1] 540s Oct 18 02:21:19 autopkgtest multipathd[328]: check_removed_paths: sdb: freeing path in removed state 540s Oct 18 02:21:19 autopkgtest multipathd[328]: 8:16: path removed from map mpatha 540s Oct 18 02:21:30 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 540s Oct 18 02:21:30 autopkgtest multipathd[328]: check_removed_paths: sdc: freeing path in removed state 540s Oct 18 02:21:30 autopkgtest multipathd[328]: 8:32: path removed from map mpatha 540s Oct 18 02:21:40 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:16 1] 540s Oct 18 02:21:40 autopkgtest multipathd[328]: sdb [8:16]: path added to devmap mpatha 540s Oct 18 02:21:40 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:0 1] 540s Oct 18 02:21:40 autopkgtest multipathd[328]: sda [8:0]: path added to devmap mpatha 540s Oct 18 02:21:40 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:32 1] 540s Oct 18 02:21:40 autopkgtest multipathd[328]: sdc [8:32]: path added to devmap mpatha 540s Oct 18 02:21:40 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 540s Oct 18 02:21:40 autopkgtest multipathd[328]: sde [8:64]: path added to devmap mpatha 540s Oct 18 02:21:50 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 540s Oct 18 02:21:50 autopkgtest multipathd[328]: check_removed_paths: sdd: freeing path in removed state 540s Oct 18 02:21:50 autopkgtest multipathd[328]: 8:48: path removed from map mpatha 540s Oct 18 02:21:50 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:64 1] 540s Oct 18 02:21:50 autopkgtest multipathd[328]: check_removed_paths: sdc: freeing path in removed state 540s Oct 18 02:21:50 autopkgtest multipathd[328]: 8:32: path removed from map mpatha 540s Oct 18 02:21:50 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:0 1] 540s Oct 18 02:21:50 autopkgtest multipathd[328]: check_removed_paths: sde: freeing path in removed state 540s Oct 18 02:21:50 autopkgtest multipathd[328]: 8:64: path removed from map mpatha 540s Oct 18 02:22:00 autopkgtest multipathd[328]: multipathd: shut down 540s Oct 18 02:22:00 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 18 02:22:00 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 540s Oct 18 02:22:00 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 540s Oct 18 02:22:00 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 540s Oct 18 02:22:00 autopkgtest multipathd[6445]: multipathd v0.9.9: start up 540s Oct 18 02:22:00 autopkgtest multipathd[6445]: reconfigure: setting up paths and maps 540s Oct 18 02:22:00 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 540s Check final path 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 `- 0:0:0:1 sda 8:0 active ready running 540s + diska=1 540s + multipath -ll 540s + grep --count status=enabled 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 540s OK 540s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 540s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 540s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 540s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 540s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 540s autopkgtest [02:24:00]: test tgtbasedmpaths: -----------------------] 541s tgtbasedmpaths PASS 541s autopkgtest [02:24:01]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 541s autopkgtest [02:24:01]: @@@@@@@@@@@@@@@@@@@@ summary 541s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 541s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 541s kpartx-file-loopback PASS 541s tgtbasedmpaths PASS 554s nova [W] Using flock in prodstack6-ppc64el 554s Creating nova instance adt-oracular-ppc64el-multipath-tools-20241018-014920-juju-7f2275-prod-proposed-migration-environment-14-07460428-d1b1-4dba-a527-ff807afa9e6b from image adt/ubuntu-oracular-ppc64el-server-20241017.img (UUID 5217ce93-bd1f-412a-b08e-ea30b96894e8)... 554s nova [W] Using flock in prodstack6-ppc64el 554s Creating nova instance adt-oracular-ppc64el-multipath-tools-20241018-014920-juju-7f2275-prod-proposed-migration-environment-14-07460428-d1b1-4dba-a527-ff807afa9e6b from image adt/ubuntu-oracular-ppc64el-server-20241017.img (UUID 5217ce93-bd1f-412a-b08e-ea30b96894e8)...