1s autopkgtest [14:50:10]: starting date and time: 2024-09-10 14:50:10+0000 1s autopkgtest [14:50:10]: git checkout: fd3bed09 nova: allow more retries for quota issues 1s autopkgtest [14:50:10]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.zqefx5d9/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-7.7 linux/6.11.0-7.7' --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-2@bos03-ppc64el-30.secgroup --name adt-oracular-ppc64el-multipath-tools-20240910-145002-juju-7f2275-prod-proposed-migration-environment-2-06506f14-00d0-4698-bb25-06ac22aece33 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --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/ 392s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 398s autopkgtest [14:56:47]: testbed dpkg architecture: ppc64el 398s autopkgtest [14:56:47]: testbed apt version: 2.9.8 398s autopkgtest [14:56:47]: @@@@@@@@@@@@@@@@@@@@ test bed setup 399s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 399s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [47.4 kB] 399s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [635 kB] 399s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8424 B] 399s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [6600 B] 399s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [70.7 kB] 399s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [1928 B] 399s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1372 B] 399s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 399s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [625 kB] 399s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [15.1 kB] 399s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [3280 B] 399s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [340 B] 401s Fetched 1541 kB in 1s (1791 kB/s) 401s Reading package lists... 412s Reading package lists... 412s Building dependency tree... 412s Reading state information... 413s Calculating upgrade... 413s The following NEW packages will be installed: 413s libpython3.12t64 linux-headers-6.11.0-7 linux-headers-6.11.0-7-generic 413s linux-image-6.11.0-7-generic linux-modules-6.11.0-7-generic 413s linux-modules-extra-6.11.0-7-generic linux-tools-6.11.0-7 413s linux-tools-6.11.0-7-generic 413s The following packages will be upgraded: 413s libselinux1 libsemanage-common libsemanage2 linux-generic 413s linux-headers-generic linux-headers-virtual linux-image-generic 413s linux-image-virtual linux-libc-dev linux-tools-common linux-virtual 413s 11 upgraded, 8 newly installed, 0 to remove and 0 not upgraded. 413s Need to get 230 MB of archives. 413s After this operation, 344 MB of additional disk space will be used. 413s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el libselinux1 ppc64el 3.5-2ubuntu5 [99.0 kB] 413s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsemanage-common all 3.5-1build6 [10.2 kB] 413s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsemanage2 ppc64el 3.5-1build6 [115 kB] 413s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpython3.12t64 ppc64el 3.12.6-1 [2561 kB] 413s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-6.11.0-7-generic ppc64el 6.11.0-7.7 [32.8 MB] 414s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-6.11.0-7-generic ppc64el 6.11.0-7.7 [63.9 MB] 417s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-extra-6.11.0-7-generic ppc64el 6.11.0-7.7 [105 MB] 420s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-generic ppc64el 6.11.0-7.7 [1734 B] 420s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-generic ppc64el 6.11.0-7.7 [10.7 kB] 420s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-virtual ppc64el 6.11.0-7.7 [1722 B] 420s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-virtual ppc64el 6.11.0-7.7 [10.6 kB] 420s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-virtual ppc64el 6.11.0-7.7 [1646 B] 420s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.11.0-7 all 6.11.0-7.7 [13.9 MB] 421s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.11.0-7-generic ppc64el 6.11.0-7.7 [3945 kB] 421s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-generic ppc64el 6.11.0-7.7 [10.5 kB] 421s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-libc-dev ppc64el 6.11.0-7.7 [1653 kB] 421s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-common all 6.11.0-7.7 [483 kB] 421s Get:18 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-7 ppc64el 6.11.0-7.7 [5177 kB] 421s Get:19 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-7-generic ppc64el 6.11.0-7.7 [1742 B] 421s Fetched 230 MB in 8s (27.6 MB/s) 421s (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 ... 72411 files and directories currently installed.) 421s Preparing to unpack .../libselinux1_3.5-2ubuntu5_ppc64el.deb ... 421s Unpacking libselinux1:ppc64el (3.5-2ubuntu5) over (3.5-2ubuntu2) ... 421s Setting up libselinux1:ppc64el (3.5-2ubuntu5) ... 421s (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 ... 72411 files and directories currently installed.) 421s Preparing to unpack .../libsemanage-common_3.5-1build6_all.deb ... 421s Unpacking libsemanage-common (3.5-1build6) over (3.5-1build5) ... 422s Setting up libsemanage-common (3.5-1build6) ... 422s (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 ... 72411 files and directories currently installed.) 422s Preparing to unpack .../libsemanage2_3.5-1build6_ppc64el.deb ... 422s Unpacking libsemanage2:ppc64el (3.5-1build6) over (3.5-1build5) ... 422s Setting up libsemanage2:ppc64el (3.5-1build6) ... 422s Selecting previously unselected package libpython3.12t64:ppc64el. 422s (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 ... 72411 files and directories currently installed.) 422s Preparing to unpack .../00-libpython3.12t64_3.12.6-1_ppc64el.deb ... 422s Unpacking libpython3.12t64:ppc64el (3.12.6-1) ... 422s Selecting previously unselected package linux-modules-6.11.0-7-generic. 422s Preparing to unpack .../01-linux-modules-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 422s Unpacking linux-modules-6.11.0-7-generic (6.11.0-7.7) ... 422s Selecting previously unselected package linux-image-6.11.0-7-generic. 422s Preparing to unpack .../02-linux-image-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 422s Unpacking linux-image-6.11.0-7-generic (6.11.0-7.7) ... 422s Selecting previously unselected package linux-modules-extra-6.11.0-7-generic. 422s Preparing to unpack .../03-linux-modules-extra-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 422s Unpacking linux-modules-extra-6.11.0-7-generic (6.11.0-7.7) ... 423s Preparing to unpack .../04-linux-generic_6.11.0-7.7_ppc64el.deb ... 423s Unpacking linux-generic (6.11.0-7.7) over (6.8.0-31.31) ... 423s Preparing to unpack .../05-linux-image-generic_6.11.0-7.7_ppc64el.deb ... 423s Unpacking linux-image-generic (6.11.0-7.7) over (6.8.0-31.31) ... 423s Preparing to unpack .../06-linux-virtual_6.11.0-7.7_ppc64el.deb ... 423s Unpacking linux-virtual (6.11.0-7.7) over (6.8.0-31.31) ... 423s Preparing to unpack .../07-linux-image-virtual_6.11.0-7.7_ppc64el.deb ... 423s Unpacking linux-image-virtual (6.11.0-7.7) over (6.8.0-31.31) ... 423s Preparing to unpack .../08-linux-headers-virtual_6.11.0-7.7_ppc64el.deb ... 423s Unpacking linux-headers-virtual (6.11.0-7.7) over (6.8.0-31.31) ... 423s Selecting previously unselected package linux-headers-6.11.0-7. 423s Preparing to unpack .../09-linux-headers-6.11.0-7_6.11.0-7.7_all.deb ... 423s Unpacking linux-headers-6.11.0-7 (6.11.0-7.7) ... 425s Selecting previously unselected package linux-headers-6.11.0-7-generic. 425s Preparing to unpack .../10-linux-headers-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 425s Unpacking linux-headers-6.11.0-7-generic (6.11.0-7.7) ... 435s Preparing to unpack .../11-linux-headers-generic_6.11.0-7.7_ppc64el.deb ... 436s Unpacking linux-headers-generic (6.11.0-7.7) over (6.8.0-31.31) ... 436s Preparing to unpack .../12-linux-libc-dev_6.11.0-7.7_ppc64el.deb ... 436s Unpacking linux-libc-dev:ppc64el (6.11.0-7.7) over (6.8.0-31.31) ... 439s Preparing to unpack .../13-linux-tools-common_6.11.0-7.7_all.deb ... 439s Unpacking linux-tools-common (6.11.0-7.7) over (6.8.0-31.31) ... 439s Selecting previously unselected package linux-tools-6.11.0-7. 439s Preparing to unpack .../14-linux-tools-6.11.0-7_6.11.0-7.7_ppc64el.deb ... 439s Unpacking linux-tools-6.11.0-7 (6.11.0-7.7) ... 439s Selecting previously unselected package linux-tools-6.11.0-7-generic. 439s Preparing to unpack .../15-linux-tools-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 439s Unpacking linux-tools-6.11.0-7-generic (6.11.0-7.7) ... 439s Setting up linux-headers-6.11.0-7 (6.11.0-7.7) ... 439s Setting up linux-modules-6.11.0-7-generic (6.11.0-7.7) ... 439s Setting up linux-libc-dev:ppc64el (6.11.0-7.7) ... 439s Setting up linux-modules-extra-6.11.0-7-generic (6.11.0-7.7) ... 439s Setting up libpython3.12t64:ppc64el (3.12.6-1) ... 439s Setting up linux-image-6.11.0-7-generic (6.11.0-7.7) ... 439s I: /boot/vmlinux is now a symlink to vmlinux-6.11.0-7-generic 439s I: /boot/initrd.img is now a symlink to initrd.img-6.11.0-7-generic 439s Setting up linux-headers-6.11.0-7-generic (6.11.0-7.7) ... 439s Setting up linux-image-virtual (6.11.0-7.7) ... 439s Setting up linux-tools-common (6.11.0-7.7) ... 439s Setting up linux-tools-6.11.0-7 (6.11.0-7.7) ... 439s Setting up linux-image-generic (6.11.0-7.7) ... 439s Setting up linux-headers-generic (6.11.0-7.7) ... 439s Setting up linux-tools-6.11.0-7-generic (6.11.0-7.7) ... 439s Setting up linux-headers-virtual (6.11.0-7.7) ... 439s Setting up linux-generic (6.11.0-7.7) ... 439s Setting up linux-virtual (6.11.0-7.7) ... 439s Processing triggers for man-db (2.12.1-3) ... 439s Processing triggers for libc-bin (2.40-1ubuntu1) ... 439s Processing triggers for linux-image-6.11.0-7-generic (6.11.0-7.7) ... 439s /etc/kernel/postinst.d/initramfs-tools: 439s update-initramfs: Generating /boot/initrd.img-6.11.0-7-generic 439s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 441s /etc/kernel/postinst.d/zz-update-grub: 441s Sourcing file `/etc/default/grub' 441s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 441s Generating grub configuration file ... 441s Found linux image: /boot/vmlinux-6.11.0-7-generic 441s Found initrd image: /boot/initrd.img-6.11.0-7-generic 441s Found linux image: /boot/vmlinux-6.8.0-31-generic 441s Found initrd image: /boot/initrd.img-6.8.0-31-generic 441s Warning: os-prober will not be executed to detect other bootable partitions. 441s Systems on them will not be added to the GRUB boot configuration. 441s Check GRUB_DISABLE_OS_PROBER documentation entry. 441s Adding boot menu entry for UEFI Firmware Settings ... 441s done 441s Reading package lists... 441s Building dependency tree... 441s Reading state information... 442s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 452s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 452s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 452s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 452s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 453s Reading package lists... 453s Reading package lists... 453s Building dependency tree... 453s Reading state information... 453s Calculating upgrade... 454s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 454s Reading package lists... 454s Building dependency tree... 454s Reading state information... 454s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 465s Reading package lists... 465s Building dependency tree... 465s Reading state information... 465s linux-generic is already the newest version (6.11.0-7.7). 465s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 465s Reading package lists... 466s Building dependency tree... 466s Reading state information... 466s E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 466s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 466s Reading package lists... 466s Building dependency tree... 466s Reading state information... 466s E: Unable to locate package ^linux-modules-extra$ 466s E: Couldn't find any package by regex '^linux-modules-extra$' 466s autopkgtest [14:57:55]: rebooting testbed after setup commands that affected boot 512s autopkgtest [14:58:41]: testbed running kernel: Linux 6.11.0-7-generic #7-Ubuntu SMP Mon Sep 9 13:10:01 UTC 2024 554s autopkgtest [14:59:23]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 595s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (dsc) [2772 B] 595s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (tar) [588 kB] 595s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (diff) [42.7 kB] 595s gpgv: Signature made Thu Sep 5 17:42:16 2024 UTC 595s gpgv: using RSA key 63EEFC3DE14D5146CE7F24BF34B8AD7D9529E793 595s gpgv: Can't check signature: No public key 595s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.9-1ubuntu3.dsc: no acceptable signature found 595s autopkgtest [15:00:04]: testing package multipath-tools version 0.9.9-1ubuntu3 596s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 596s autopkgtest [15:00:05]: build not needed 603s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 603s autopkgtest [15:00:12]: test kpartx-file-loopback: preparing testbed 604s Reading package lists... 604s Building dependency tree... 604s Reading state information... 604s Starting pkgProblemResolver with broken count: 0 604s Starting 2 pkgProblemResolver with broken count: 0 604s Done 605s The following additional packages will be installed: 605s liburing2 qemu-utils 605s Recommended packages: 605s qemu-block-extra 605s The following NEW packages will be installed: 605s autopkgtest-satdep liburing2 qemu-utils 605s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 605s Need to get 2432 kB/2433 kB of archives. 605s After this operation, 16.9 MB of additional disk space will be used. 605s Get:1 /tmp/autopkgtest.zfQnqm/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 605s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 605s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:9.0.2+ds-4ubuntu3 [2405 kB] 606s Fetched 2432 kB in 1s (3784 kB/s) 606s Selecting previously unselected package liburing2:ppc64el. 606s (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 ... 109815 files and directories currently installed.) 606s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 606s Unpacking liburing2:ppc64el (2.6-1) ... 606s Selecting previously unselected package qemu-utils. 606s Preparing to unpack .../qemu-utils_1%3a9.0.2+ds-4ubuntu3_ppc64el.deb ... 606s Unpacking qemu-utils (1:9.0.2+ds-4ubuntu3) ... 606s Selecting previously unselected package autopkgtest-satdep. 606s Preparing to unpack .../1-autopkgtest-satdep.deb ... 606s Unpacking autopkgtest-satdep (0) ... 606s Setting up liburing2:ppc64el (2.6-1) ... 606s Setting up qemu-utils (1:9.0.2+ds-4ubuntu3) ... 606s Setting up autopkgtest-satdep (0) ... 606s Processing triggers for man-db (2.12.1-3) ... 607s Processing triggers for libc-bin (2.40-1ubuntu1) ... 664s (Reading database ... 109839 files and directories currently installed.) 664s Removing autopkgtest-satdep (0) ... 683s autopkgtest [15:01:32]: test kpartx-file-loopback: [----------------------- 683s Formatting 'foo.img', fmt=raw size=20971520 684s Creating new GPT entries in memory. 684s Warning: The kernel is still using the old partition table. 684s The new table will be used at the next reboot or after you 684s run partprobe(8) or kpartx(8) 684s The operation has completed successfully. 684s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 684s standard_filename: OK 684s del devmap : loop0p1 684s No devices found 684s standard_filename_cleanup: OK 684s Formatting 'fou du FaFa.img', fmt=raw size=20971520 685s Creating new GPT entries in memory. 685s Warning: The kernel is still using the old partition table. 685s The new table will be used at the next reboot or after you 685s run partprobe(8) or kpartx(8) 685s The operation has completed successfully. 685s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 685s filename_with_spaces: OK 685s del devmap : loop0p1 685s No devices found 685s filename_with_spaces_cleanup: OK 686s autopkgtest [15:01:35]: test kpartx-file-loopback: -----------------------] 686s autopkgtest [15:01:35]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 686s kpartx-file-loopback PASS 707s autopkgtest [15:01:56]: test tgtbasedmpaths: preparing testbed 952s autopkgtest [15:06:01]: testbed dpkg architecture: ppc64el 953s autopkgtest [15:06:02]: testbed apt version: 2.9.8 953s autopkgtest [15:06:02]: @@@@@@@@@@@@@@@@@@@@ test bed setup 956s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 957s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [47.4 kB] 957s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8424 B] 957s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [6600 B] 957s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [635 kB] 957s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [70.7 kB] 957s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [1928 B] 957s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1372 B] 957s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 957s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [625 kB] 957s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [15.1 kB] 957s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [3280 B] 957s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [340 B] 959s Fetched 1541 kB in 1s (1694 kB/s) 959s Reading package lists... 982s Reading package lists... 982s Building dependency tree... 982s Reading state information... 985s Calculating upgrade... 985s The following NEW packages will be installed: 985s libpython3.12t64 linux-headers-6.11.0-7 linux-headers-6.11.0-7-generic 985s linux-image-6.11.0-7-generic linux-modules-6.11.0-7-generic 985s linux-modules-extra-6.11.0-7-generic linux-tools-6.11.0-7 985s linux-tools-6.11.0-7-generic 985s The following packages will be upgraded: 985s libselinux1 libsemanage-common libsemanage2 linux-generic 985s linux-headers-generic linux-headers-virtual linux-image-generic 985s linux-image-virtual linux-libc-dev linux-tools-common linux-virtual 985s 11 upgraded, 8 newly installed, 0 to remove and 0 not upgraded. 985s Need to get 230 MB of archives. 985s After this operation, 344 MB of additional disk space will be used. 985s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el libselinux1 ppc64el 3.5-2ubuntu5 [99.0 kB] 985s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsemanage-common all 3.5-1build6 [10.2 kB] 985s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsemanage2 ppc64el 3.5-1build6 [115 kB] 985s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpython3.12t64 ppc64el 3.12.6-1 [2561 kB] 985s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-6.11.0-7-generic ppc64el 6.11.0-7.7 [32.8 MB] 985s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-6.11.0-7-generic ppc64el 6.11.0-7.7 [63.9 MB] 991s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-modules-extra-6.11.0-7-generic ppc64el 6.11.0-7.7 [105 MB] 993s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-generic ppc64el 6.11.0-7.7 [1734 B] 993s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-generic ppc64el 6.11.0-7.7 [10.7 kB] 993s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-virtual ppc64el 6.11.0-7.7 [1722 B] 993s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-image-virtual ppc64el 6.11.0-7.7 [10.6 kB] 993s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-virtual ppc64el 6.11.0-7.7 [1646 B] 993s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.11.0-7 all 6.11.0-7.7 [13.9 MB] 994s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-6.11.0-7-generic ppc64el 6.11.0-7.7 [3945 kB] 994s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-headers-generic ppc64el 6.11.0-7.7 [10.5 kB] 994s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-libc-dev ppc64el 6.11.0-7.7 [1653 kB] 994s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-common all 6.11.0-7.7 [483 kB] 994s Get:18 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-7 ppc64el 6.11.0-7.7 [5177 kB] 994s Get:19 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el linux-tools-6.11.0-7-generic ppc64el 6.11.0-7.7 [1742 B] 995s Fetched 230 MB in 12s (19.1 MB/s) 995s (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 ... 72411 files and directories currently installed.) 995s Preparing to unpack .../libselinux1_3.5-2ubuntu5_ppc64el.deb ... 995s Unpacking libselinux1:ppc64el (3.5-2ubuntu5) over (3.5-2ubuntu2) ... 995s Setting up libselinux1:ppc64el (3.5-2ubuntu5) ... 995s (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 ... 72411 files and directories currently installed.) 995s Preparing to unpack .../libsemanage-common_3.5-1build6_all.deb ... 995s Unpacking libsemanage-common (3.5-1build6) over (3.5-1build5) ... 995s Setting up libsemanage-common (3.5-1build6) ... 995s (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 ... 72411 files and directories currently installed.) 995s Preparing to unpack .../libsemanage2_3.5-1build6_ppc64el.deb ... 995s Unpacking libsemanage2:ppc64el (3.5-1build6) over (3.5-1build5) ... 995s Setting up libsemanage2:ppc64el (3.5-1build6) ... 995s Selecting previously unselected package libpython3.12t64:ppc64el. 995s (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 ... 72411 files and directories currently installed.) 995s Preparing to unpack .../00-libpython3.12t64_3.12.6-1_ppc64el.deb ... 995s Unpacking libpython3.12t64:ppc64el (3.12.6-1) ... 995s Selecting previously unselected package linux-modules-6.11.0-7-generic. 995s Preparing to unpack .../01-linux-modules-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 995s Unpacking linux-modules-6.11.0-7-generic (6.11.0-7.7) ... 996s Selecting previously unselected package linux-image-6.11.0-7-generic. 996s Preparing to unpack .../02-linux-image-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 996s Unpacking linux-image-6.11.0-7-generic (6.11.0-7.7) ... 996s Selecting previously unselected package linux-modules-extra-6.11.0-7-generic. 996s Preparing to unpack .../03-linux-modules-extra-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 996s Unpacking linux-modules-extra-6.11.0-7-generic (6.11.0-7.7) ... 997s Preparing to unpack .../04-linux-generic_6.11.0-7.7_ppc64el.deb ... 997s Unpacking linux-generic (6.11.0-7.7) over (6.8.0-31.31) ... 997s Preparing to unpack .../05-linux-image-generic_6.11.0-7.7_ppc64el.deb ... 997s Unpacking linux-image-generic (6.11.0-7.7) over (6.8.0-31.31) ... 997s Preparing to unpack .../06-linux-virtual_6.11.0-7.7_ppc64el.deb ... 997s Unpacking linux-virtual (6.11.0-7.7) over (6.8.0-31.31) ... 997s Preparing to unpack .../07-linux-image-virtual_6.11.0-7.7_ppc64el.deb ... 997s Unpacking linux-image-virtual (6.11.0-7.7) over (6.8.0-31.31) ... 997s Preparing to unpack .../08-linux-headers-virtual_6.11.0-7.7_ppc64el.deb ... 997s Unpacking linux-headers-virtual (6.11.0-7.7) over (6.8.0-31.31) ... 997s Selecting previously unselected package linux-headers-6.11.0-7. 997s Preparing to unpack .../09-linux-headers-6.11.0-7_6.11.0-7.7_all.deb ... 997s Unpacking linux-headers-6.11.0-7 (6.11.0-7.7) ... 1001s Selecting previously unselected package linux-headers-6.11.0-7-generic. 1001s Preparing to unpack .../10-linux-headers-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 1001s Unpacking linux-headers-6.11.0-7-generic (6.11.0-7.7) ... 1001s Preparing to unpack .../11-linux-headers-generic_6.11.0-7.7_ppc64el.deb ... 1001s Unpacking linux-headers-generic (6.11.0-7.7) over (6.8.0-31.31) ... 1001s Preparing to unpack .../12-linux-libc-dev_6.11.0-7.7_ppc64el.deb ... 1001s Unpacking linux-libc-dev:ppc64el (6.11.0-7.7) over (6.8.0-31.31) ... 1001s Preparing to unpack .../13-linux-tools-common_6.11.0-7.7_all.deb ... 1001s Unpacking linux-tools-common (6.11.0-7.7) over (6.8.0-31.31) ... 1001s Selecting previously unselected package linux-tools-6.11.0-7. 1001s Preparing to unpack .../14-linux-tools-6.11.0-7_6.11.0-7.7_ppc64el.deb ... 1001s Unpacking linux-tools-6.11.0-7 (6.11.0-7.7) ... 1001s Selecting previously unselected package linux-tools-6.11.0-7-generic. 1001s Preparing to unpack .../15-linux-tools-6.11.0-7-generic_6.11.0-7.7_ppc64el.deb ... 1001s Unpacking linux-tools-6.11.0-7-generic (6.11.0-7.7) ... 1001s Setting up linux-headers-6.11.0-7 (6.11.0-7.7) ... 1001s Setting up linux-modules-6.11.0-7-generic (6.11.0-7.7) ... 1003s Setting up linux-libc-dev:ppc64el (6.11.0-7.7) ... 1003s Setting up linux-modules-extra-6.11.0-7-generic (6.11.0-7.7) ... 1005s Setting up libpython3.12t64:ppc64el (3.12.6-1) ... 1005s Setting up linux-image-6.11.0-7-generic (6.11.0-7.7) ... 1007s I: /boot/vmlinux is now a symlink to vmlinux-6.11.0-7-generic 1007s I: /boot/initrd.img is now a symlink to initrd.img-6.11.0-7-generic 1007s Setting up linux-headers-6.11.0-7-generic (6.11.0-7.7) ... 1007s Setting up linux-image-virtual (6.11.0-7.7) ... 1007s Setting up linux-tools-common (6.11.0-7.7) ... 1007s Setting up linux-tools-6.11.0-7 (6.11.0-7.7) ... 1007s Setting up linux-image-generic (6.11.0-7.7) ... 1007s Setting up linux-headers-generic (6.11.0-7.7) ... 1007s Setting up linux-tools-6.11.0-7-generic (6.11.0-7.7) ... 1007s Setting up linux-headers-virtual (6.11.0-7.7) ... 1007s Setting up linux-generic (6.11.0-7.7) ... 1007s Setting up linux-virtual (6.11.0-7.7) ... 1007s Processing triggers for man-db (2.12.1-3) ... 1009s Processing triggers for libc-bin (2.40-1ubuntu1) ... 1009s Processing triggers for linux-image-6.11.0-7-generic (6.11.0-7.7) ... 1009s /etc/kernel/postinst.d/initramfs-tools: 1009s update-initramfs: Generating /boot/initrd.img-6.11.0-7-generic 1009s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 1017s /etc/kernel/postinst.d/zz-update-grub: 1017s Sourcing file `/etc/default/grub' 1017s Sourcing file `/etc/default/grub.d/50-cloudimg-settings.cfg' 1017s Generating grub configuration file ... 1018s Found linux image: /boot/vmlinux-6.11.0-7-generic 1018s Found initrd image: /boot/initrd.img-6.11.0-7-generic 1018s Found linux image: /boot/vmlinux-6.8.0-31-generic 1018s Found initrd image: /boot/initrd.img-6.8.0-31-generic 1018s Warning: os-prober will not be executed to detect other bootable partitions. 1018s Systems on them will not be added to the GRUB boot configuration. 1018s Check GRUB_DISABLE_OS_PROBER documentation entry. 1018s Adding boot menu entry for UEFI Firmware Settings ... 1018s done 1018s Reading package lists... 1018s Building dependency tree... 1018s Reading state information... 1018s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1019s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 1019s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 1019s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 1019s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 1020s Reading package lists... 1020s Reading package lists... 1020s Building dependency tree... 1020s Reading state information... 1020s Calculating upgrade... 1020s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1020s Reading package lists... 1021s Building dependency tree... 1021s Reading state information... 1021s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1028s Reading package lists... 1028s Building dependency tree... 1028s Reading state information... 1029s linux-generic is already the newest version (6.11.0-7.7). 1029s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1029s Reading package lists... 1029s Building dependency tree... 1029s Reading state information... 1030s E: Unable to locate package ^kernel-testing--linux--modules-extra--preferred$ 1030s E: Couldn't find any package by regex '^kernel-testing--linux--modules-extra--preferred$' 1030s Reading package lists... 1030s Building dependency tree... 1030s Reading state information... 1030s E: Unable to locate package ^linux-modules-extra$ 1030s E: Couldn't find any package by regex '^linux-modules-extra$' 1030s autopkgtest [15:07:19]: rebooting testbed after setup commands that affected boot 1037s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 1078s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 1278s Reading package lists... 1278s Building dependency tree... 1278s Reading state information... 1278s Starting pkgProblemResolver with broken count: 0 1278s Starting 2 pkgProblemResolver with broken count: 0 1278s Done 1278s The following additional packages will be installed: 1278s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 1278s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 1278s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 1278s librdmacm1t64 lsscsi open-iscsi tgt 1278s Suggested packages: 1278s fio-examples gnuplot tgt-glusterfs tgt-rbd 1278s Recommended packages: 1278s finalrd 1279s The following NEW packages will be installed: 1279s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 1279s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 1279s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 1279s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 1279s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 1279s Need to get 11.0 MB/11.0 MB of archives. 1279s After this operation, 50.0 MB of additional disk space will be used. 1279s Get:1 /tmp/autopkgtest.zfQnqm/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 1279s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 1279s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 1279s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 1279s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2ubuntu1 [80.6 kB] 1279s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 1279s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 1279s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-5ubuntu1 [21.7 kB] 1279s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-5ubuntu1 [308 kB] 1279s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-5ubuntu1 [46.3 kB] 1279s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-5ubuntu1 [99.1 kB] 1279s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-2 [98.5 kB] 1279s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2.2ubuntu1 [23.7 kB] 1279s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2.2ubuntu1 [73.4 kB] 1279s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 1279s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3.2ubuntu2 [260 kB] 1279s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3.2ubuntu2 [281 kB] 1279s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~rc2-0ubuntu1 [4194 kB] 1279s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 1279s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~rc2-0ubuntu1 [3714 kB] 1280s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 1280s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 1280s Preconfiguring packages ... 1280s Fetched 11.0 MB in 1s (11.1 MB/s) 1280s Selecting previously unselected package libopeniscsiusr. 1280s (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 ... 109815 files and directories currently installed.) 1280s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 1280s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 1280s Selecting previously unselected package libisns0t64:ppc64el. 1280s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 1280s Unpacking libisns0t64:ppc64el (0.101-1) ... 1280s Selecting previously unselected package open-iscsi. 1280s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 1281s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 1281s Selecting previously unselected package librdmacm1t64:ppc64el. 1281s Preparing to unpack .../03-librdmacm1t64_52.0-2ubuntu1_ppc64el.deb ... 1281s Unpacking librdmacm1t64:ppc64el (52.0-2ubuntu1) ... 1281s Selecting previously unselected package libconfig-general-perl. 1281s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 1281s Unpacking libconfig-general-perl (2.65-2) ... 1281s Selecting previously unselected package tgt. 1281s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 1281s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 1281s Selecting previously unselected package libgfxdr0:ppc64el. 1281s Preparing to unpack .../06-libgfxdr0_11.1-5ubuntu1_ppc64el.deb ... 1281s Unpacking libgfxdr0:ppc64el (11.1-5ubuntu1) ... 1281s Selecting previously unselected package libglusterfs0:ppc64el. 1281s Preparing to unpack .../07-libglusterfs0_11.1-5ubuntu1_ppc64el.deb ... 1281s Unpacking libglusterfs0:ppc64el (11.1-5ubuntu1) ... 1281s Selecting previously unselected package libgfrpc0:ppc64el. 1281s Preparing to unpack .../08-libgfrpc0_11.1-5ubuntu1_ppc64el.deb ... 1281s Unpacking libgfrpc0:ppc64el (11.1-5ubuntu1) ... 1281s Selecting previously unselected package libgfapi0:ppc64el. 1281s Preparing to unpack .../09-libgfapi0_11.1-5ubuntu1_ppc64el.deb ... 1281s Unpacking libgfapi0:ppc64el (11.1-5ubuntu1) ... 1281s Selecting previously unselected package libnbd0. 1281s Preparing to unpack .../10-libnbd0_1.20.2-2_ppc64el.deb ... 1281s Unpacking libnbd0 (1.20.2-2) ... 1281s Selecting previously unselected package libdaxctl1:ppc64el. 1281s Preparing to unpack .../11-libdaxctl1_77-2.2ubuntu1_ppc64el.deb ... 1281s Unpacking libdaxctl1:ppc64el (77-2.2ubuntu1) ... 1281s Selecting previously unselected package libndctl6:ppc64el. 1281s Preparing to unpack .../12-libndctl6_77-2.2ubuntu1_ppc64el.deb ... 1281s Unpacking libndctl6:ppc64el (77-2.2ubuntu1) ... 1281s Selecting previously unselected package libpmem1:ppc64el. 1281s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 1281s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 1281s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 1281s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 1281s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 1281s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 1281s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 1281s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 1281s Selecting previously unselected package librados2. 1281s Preparing to unpack .../16-librados2_19.2.0~rc2-0ubuntu1_ppc64el.deb ... 1281s Unpacking librados2 (19.2.0~rc2-0ubuntu1) ... 1281s Selecting previously unselected package libpmemobj1:ppc64el. 1281s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 1281s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 1281s Selecting previously unselected package librbd1. 1281s Preparing to unpack .../18-librbd1_19.2.0~rc2-0ubuntu1_ppc64el.deb ... 1281s Unpacking librbd1 (19.2.0~rc2-0ubuntu1) ... 1281s Selecting previously unselected package fio. 1281s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 1281s Unpacking fio (3.37-1) ... 1281s Selecting previously unselected package lsscsi. 1281s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 1281s Unpacking lsscsi (0.32-1build1) ... 1281s Selecting previously unselected package autopkgtest-satdep. 1281s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 1281s Unpacking autopkgtest-satdep (0) ... 1281s Setting up libconfig-general-perl (2.65-2) ... 1281s Setting up libisns0t64:ppc64el (0.101-1) ... 1281s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 1281s Setting up libnbd0 (1.20.2-2) ... 1281s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 1281s Setting up libglusterfs0:ppc64el (11.1-5ubuntu1) ... 1281s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 1281s Setting up lsscsi (0.32-1build1) ... 1281s Setting up libdaxctl1:ppc64el (77-2.2ubuntu1) ... 1281s Setting up libndctl6:ppc64el (77-2.2ubuntu1) ... 1281s Setting up librdmacm1t64:ppc64el (52.0-2ubuntu1) ... 1281s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 1282s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 1282s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 1282s Setting up libgfxdr0:ppc64el (11.1-5ubuntu1) ... 1282s Setting up librados2 (19.2.0~rc2-0ubuntu1) ... 1282s Setting up open-iscsi (2.1.10-1ubuntu1) ... 1283s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 1283s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 1283s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 1284s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 1284s Setting up librbd1 (19.2.0~rc2-0ubuntu1) ... 1284s Setting up libgfrpc0:ppc64el (11.1-5ubuntu1) ... 1284s Setting up libgfapi0:ppc64el (11.1-5ubuntu1) ... 1284s Setting up fio (3.37-1) ... 1284s Setting up autopkgtest-satdep (0) ... 1284s Processing triggers for man-db (2.12.1-3) ... 1286s Processing triggers for initramfs-tools (0.142ubuntu33) ... 1286s update-initramfs: Generating /boot/initrd.img-6.11.0-7-generic 1286s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 1296s Processing triggers for libc-bin (2.40-1ubuntu1) ... 1301s (Reading database ... 110056 files and directories currently installed.) 1301s Removing autopkgtest-satdep (0) ... 1316s autopkgtest [15:12:05]: test tgtbasedmpaths: [----------------------- 1316s + targetname=iqn.2016-11.foo.com:target.iscsi 1316s + pwd 1316s + cwd=/tmp/autopkgtest.zfQnqm/build.8bi/src 1316s + testdir=/mnt/tgtmpathtest 1316s + localhost=127.0.0.1 1316s + portal=127.0.0.1:3260 1316s + maxpaths=4 1316s + backfn=backingfile 1316s + expectwwid=60000000000000000e00000000010001 1316s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1316s + bglog=/tmp/autopkgtest.zfQnqm/tgtbasedmpaths-artifacts/test-background.log 1316s + fioprep=/tmp/autopkgtest.zfQnqm/tgtbasedmpaths-artifacts/path-change-prep.fio 1316s + fiovrfy=/tmp/autopkgtest.zfQnqm/tgtbasedmpaths-artifacts/path-change-check.fio 1316s + mkdir -p /etc/multipath 1316s + echo /360000000000000000e00000000010001/ 1316s + service tgt restart 1317s + truncate --size 100M backingfile 1317s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 1317s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 1317s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.zfQnqm/build.8bi/src/backingfile 1317s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 1317s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 1317s login #1 1317s + echo login #1 1317s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 1317s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1317s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1317s + seq 2 4 1317s + echo extra login #2 1317s + iscsiadm --mode session -r 1 --op new 1317s extra login #2 1317s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1317s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1317s extra login #3 1317s + echo extra login #3 1317s + iscsiadm --mode session -r 1 --op new 1317s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1317s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1317s + echo extra login #4 1317s + iscsiadm --mode session -r 1 --op new 1317s extra login #4 1317s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1317s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1317s + udevadm settle 1317s + sleep 5 1322s Status after initial setup 1322s + echo Status after initial setup 1322s + tgtadm --lld iscsi --mode target --op show 1322s + tgtadm --lld iscsi --op show --mode conn --tid 1 1322s Target 1: iqn.2016-11.foo.com:target.iscsi 1322s System information: 1322s Driver: iscsi 1322s State: ready 1322s I_T nexus information: 1322s I_T nexus: 1 1322s Initiator: iqn.2004-10.com.ubuntu:01:33c3ff1b1c33 alias: autopkgtest 1322s Connection: 0 1322s IP Address: 127.0.0.1 1322s I_T nexus: 2 1322s Initiator: iqn.2004-10.com.ubuntu:01:33c3ff1b1c33 alias: autopkgtest 1322s Connection: 0 1322s IP Address: 127.0.0.1 1322s I_T nexus: 3 1322s Initiator: iqn.2004-10.com.ubuntu:01:33c3ff1b1c33 alias: autopkgtest 1322s Connection: 0 1322s IP Address: 127.0.0.1 1322s I_T nexus: 4 1322s Initiator: iqn.2004-10.com.ubuntu:01:33c3ff1b1c33 alias: autopkgtest 1322s Connection: 0 1322s IP Address: 127.0.0.1 1322s LUN information: 1322s LUN: 0 1322s Type: controller 1322s SCSI ID: IET 00010000 1322s SCSI SN: beaf10 1322s Size: 0 MB, Block size: 1 1322s Online: Yes 1322s Removable media: No 1322s Prevent removal: No 1322s Readonly: No 1322s SWP: No 1322s Thin-provisioning: No 1322s Backing store type: null 1322s Backing store path: None 1322s Backing store flags: 1322s LUN: 1 1322s Type: disk 1322s SCSI ID: IET 00010001 1322s SCSI SN: beaf11 1322s Size: 105 MB, Block size: 512 1322s Online: Yes 1322s Removable media: No 1322s Prevent removal: No 1322s Readonly: No 1322s SWP: No 1322s Thin-provisioning: No 1322s Backing store type: rdwr 1322s Backing store path: /tmp/autopkgtest.zfQnqm/build.8bi/src/backingfile 1322s Backing store flags: 1322s Account information: 1322s ACL information: 1322s ALL 1322s + iscsiadm --mode session -P 1 1322s Session: 4 1322s Connection: 0 1322s Initiator: iqn.2004-10.com.ubuntu:01:33c3ff1b1c33 1322s IP Address: 127.0.0.1 1322s Session: 3 1322s Connection: 0 1322s Initiator: iqn.2004-10.com.ubuntu:01:33c3ff1b1c33 1322s IP Address: 127.0.0.1 1322s Session: 2 1322s Connection: 0 1322s Initiator: iqn.2004-10.com.ubuntu:01:33c3ff1b1c33 1322s IP Address: 127.0.0.1 1322s Session: 1 1322s Connection: 0 1322s Initiator: iqn.2004-10.com.ubuntu:01:33c3ff1b1c33 1322s IP Address: 127.0.0.1 1322s + lsscsi -liv 1322s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 1322s Current Portal: 127.0.0.1:3260,1 1322s Persistent Portal: 127.0.0.1:3260,1 1322s ********** 1322s Interface: 1322s ********** 1322s Iface Name: default 1322s Iface Transport: tcp 1322s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:33c3ff1b1c33 1322s Iface IPaddress: 127.0.0.1 1322s Iface HWaddress: default 1322s Iface Netdev: default 1322s SID: 1 1322s iSCSI Connection State: LOGGED IN 1322s iSCSI Session State: LOGGED_IN 1322s Internal iscsid Session State: NO CHANGE 1322s 1322s ********** 1322s Interface: 1322s ********** 1322s Iface Name: default 1322s Iface Transport: tcp 1322s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:33c3ff1b1c33 1322s Iface IPaddress: 127.0.0.1 1322s Iface HWaddress: default 1322s Iface Netdev: default 1322s SID: 2 1322s iSCSI Connection State: LOGGED IN 1322s iSCSI Session State: LOGGED_IN 1322s Internal iscsid Session State: NO CHANGE 1322s 1322s ********** 1322s Interface: 1322s ********** 1322s Iface Name: default 1322s Iface Transport: tcp 1322s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:33c3ff1b1c33 1322s Iface IPaddress: 127.0.0.1 1322s Iface HWaddress: default 1322s Iface Netdev: default 1322s SID: 3 1322s iSCSI Connection State: LOGGED IN 1322s iSCSI Session State: LOGGED_IN 1322s Internal iscsid Session State: NO CHANGE 1322s 1322s ********** 1322s Interface: 1322s ********** 1322s Iface Name: default 1322s Iface Transport: tcp 1322s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:33c3ff1b1c33 1322s Iface IPaddress: 127.0.0.1 1322s Iface HWaddress: default 1322s Iface Netdev: default 1322s SID: 4 1322s iSCSI Connection State: LOGGED IN 1322s iSCSI Session State: LOGGED_IN 1322s Internal iscsid Session State: NO CHANGE 1322s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 1322s + multipath -v3 -ll 1322s 275.417211 | set open fds limit to 1073741816/1073741816 1322s 275.417275 | _read_bindings_file: reading /etc/multipath/bindings 1322s 275.417317 | loading /usr/lib/multipath/libchecktur.so checker 1322s 275.417459 | checker tur: message table size = 4 1322s 275.417471 | loading /usr/lib/multipath/libprioconst.so prioritizer 1322s 275.417618 | _init_foreign: foreign library "nvme" is not enabled 1322s 275.424890 | vda: device node name blacklisted 1322s 275.425318 | sda: size = 204800 1322s 275.425515 | sda: vendor = IET 1322s 275.425549 | sda: product = VIRTUAL-DISK 1322s 275.425581 | sda: rev = 0001 1322s 275.426683 | sda: h:b:t:l = 0:0:0:1 1322s 275.427197 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1322s 275.427204 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 1322s 275.427208 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1322s 275.427454 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1322s 275.427461 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1322s 275.427481 | sda: serial = beaf11 1322s 275.427485 | sda: detect_checker = yes (setting: multipath internal) 1322s 275.427523 | sda checker timeout = 30 s (setting: kernel sysfs) 1322s 275.427809 | sda: path_checker = tur (setting: multipath internal) 1322s 275.427945 | sda: tur state = up 1322s [0:0:0:0] storage IET Controller 0001 - - 1322s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1322s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 1322s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 1322s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1322s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 1322s [1:0:0:0] storage IET Controller 0001 - - 1322s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1322s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 1322s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 1322s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1322s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 1322s [2:0:0:0] storage IET Controller 0001 - - 1322s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1322s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 1322s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 1322s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1322s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 1322s [3:0:0:0] storage IET Controller 0001 - - 1322s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1322s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 1322s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 1322s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1322s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 1322s NVMe module may not be loaded 1322s 275.428202 | sdb: size = 204800 1322s 275.428403 | sdb: vendor = IET 1322s 275.428436 | sdb: product = VIRTUAL-DISK 1322s 275.428466 | sdb: rev = 0001 1322s 275.429508 | sdb: h:b:t:l = 1:0:0:1 1322s 275.430008 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1322s 275.430015 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 1322s 275.430019 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1322s 275.430233 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1322s 275.430240 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1322s 275.430259 | sdb: serial = beaf11 1322s 275.430264 | sdb: detect_checker = yes (setting: multipath internal) 1322s 275.430302 | sdb checker timeout = 30 s (setting: kernel sysfs) 1322s 275.430485 | sdb: path_checker = tur (setting: multipath internal) 1322s 275.430631 | sdb: tur state = up 1322s 275.430809 | sdc: size = 204800 1322s 275.431004 | sdc: vendor = IET 1322s 275.431037 | sdc: product = VIRTUAL-DISK 1322s 275.431069 | sdc: rev = 0001 1322s 275.432166 | sdc: h:b:t:l = 2:0:0:1 1322s 275.432709 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1322s 275.432716 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 1322s 275.432720 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1322s 275.432943 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1322s 275.432952 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1322s 275.432978 | sdc: serial = beaf11 1322s 275.432984 | sdc: detect_checker = yes (setting: multipath internal) 1322s 275.433049 | sdc checker timeout = 30 s (setting: kernel sysfs) 1322s 275.433212 | sdc: path_checker = tur (setting: multipath internal) 1322s 275.433287 | sdc: tur state = up 1322s 275.433471 | sdd: size = 204800 1322s 275.433666 | sdd: vendor = IET 1322s 275.433699 | sdd: product = VIRTUAL-DISK 1322s 275.433729 | sdd: rev = 0001 1322s 275.434795 | sdd: h:b:t:l = 3:0:0:1 1322s 275.435299 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1322s 275.435305 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 1322s 275.435309 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1322s 275.435516 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1322s 275.435523 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1322s 275.435541 | sdd: serial = beaf11 1322s 275.435545 | sdd: detect_checker = yes (setting: multipath internal) 1322s 275.435582 | sdd checker timeout = 30 s (setting: kernel sysfs) 1322s 275.435755 | sdd: path_checker = tur (setting: multipath internal) 1322s 275.435886 | sdd: tur state = up 1322s 275.436039 | loop0: device node name blacklisted 1322s 275.436171 | loop1: device node name blacklisted 1322s 275.436296 | loop2: device node name blacklisted 1322s 275.436417 | loop3: device node name blacklisted 1322s 275.436539 | loop4: device node name blacklisted 1322s 275.436661 | loop5: device node name blacklisted 1322s 275.436786 | loop6: device node name blacklisted 1322s 275.436909 | loop7: device node name blacklisted 1322s 275.437077 | dm-0: device node name blacklisted 1322s 275.438621 | multipath-tools v0.9.9 (05/03, 2024) 1322s 275.438635 | libdevmapper version 1.02.196 1322s 275.438825 | kernel device mapper v4.48.0 1322s 275.438842 | DM multipath kernel driver v1.14.0 1322s 275.438985 | sda: size = 204800 1322s 275.438993 | sda: vendor = IET 1322s 275.438997 | sda: product = VIRTUAL-DISK 1322s 275.439001 | sda: rev = 0001 1322s 275.439989 | sda: h:b:t:l = 0:0:0:1 1322s 275.440167 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1322s 275.440200 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1322s 275.440204 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1322s 275.440222 | sda: serial = beaf11 1322s 275.440337 | sda: tur state = up 1322s 275.440345 | sda: uid = 360000000000000000e00000000010001 (udev) 1322s 275.440350 | sda: detect_prio = yes (setting: multipath internal) 1322s 275.440354 | sda: prio = const (setting: multipath internal) 1322s 275.440358 | sda: prio args = "" (setting: multipath internal) 1322s 275.440361 | sda: const prio = 1 1322s 275.440391 | sdb: size = 204800 1322s 275.440396 | sdb: vendor = IET 1322s 275.440400 | sdb: product = VIRTUAL-DISK 1322s 275.440404 | sdb: rev = 0001 1322s 275.441398 | sdb: h:b:t:l = 1:0:0:1 1322s 275.441563 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1322s 275.441590 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1322s 275.441595 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1322s 275.441613 | sdb: serial = beaf11 1322s 275.441732 | sdb: tur state = up 1322s 275.441738 | sdb: uid = 360000000000000000e00000000010001 (udev) 1322s 275.441742 | sdb: detect_prio = yes (setting: multipath internal) 1322s 275.441746 | sdb: prio = const (setting: multipath internal) 1322s 275.441749 | sdb: prio args = "" (setting: multipath internal) 1322s 275.441752 | sdb: const prio = 1 1322s 275.441782 | sdc: size = 204800 1322s 275.441788 | sdc: vendor = IET 1322s 275.441792 | sdc: product = VIRTUAL-DISK 1322s 275.441796 | sdc: rev = 0001 1322s 275.442761 | sdc: h:b:t:l = 2:0:0:1 1322s 275.442926 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1322s 275.442949 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1322s 275.442953 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1322s 275.442969 | sdc: serial = beaf11 1322s 275.443076 | sdc: tur state = up 1322s 275.443082 | sdc: uid = 360000000000000000e00000000010001 (udev) 1322s 275.443086 | sdc: detect_prio = yes (setting: multipath internal) 1322s 275.443089 | sdc: prio = const (setting: multipath internal) 1322s 275.443093 | sdc: prio args = "" (setting: multipath internal) 1322s 275.443096 | sdc: const prio = 1 1322s 275.443126 | sdd: size = 204800 1322s 275.443133 | sdd: vendor = IET 1322s 275.443137 | sdd: product = VIRTUAL-DISK 1322s 275.443141 | sdd: rev = 0001 1322s 275.444107 | sdd: h:b:t:l = 3:0:0:1 1322s 275.444228 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1322s 275.444246 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1322s 275.444249 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1322s 275.444260 | sdd: serial = beaf11 1322s 275.444362 | sdd: tur state = up 1322s 275.444367 | sdd: uid = 360000000000000000e00000000010001 (udev) 1322s 275.444371 | sdd: detect_prio = yes (setting: multipath internal) 1322s 275.444374 | sdd: prio = const (setting: multipath internal) 1322s 275.444377 | sdd: prio args = "" (setting: multipath internal) 1322s 275.444380 | sdd: const prio = 1 1322s 275.445519 | unloading tur checker 1322s 275.445573 | unloading const prioritizer 1322s ===== paths list ===== 1322s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 1322s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1322s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1322s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1322s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1322s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1322s size=100M features='0' hwhandler='0' wp=rw 1322s |-+- policy='service-time 0' prio=1 status=active 1322s | `- 0:0:0:1 sda 8:0 active ready running 1322s |-+- policy='service-time 0' prio=1 status=enabled 1322s | `- 1:0:0:1 sdb 8:16 active ready running 1322s |-+- policy='service-time 0' prio=1 status=enabled 1322s | `- 2:0:0:1 sdc 8:32 active ready running 1322s `-+- policy='service-time 0' prio=1 status=enabled 1322s `- 3:0:0:1 sdd 8:48 active ready running 1322s 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:32 1 1 service-time 0 1 2 8:48 1 1 1322s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 1322s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 1322s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 1322s /etc/multipath/bindings:# 1322s /etc/multipath/bindings:# Format: 1322s /etc/multipath/bindings:# alias wwid 1322s /etc/multipath/bindings:# 1322s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 1322s /etc/multipath/wwids:/360000000000000000e00000000010001/ 1322s + dmsetup table 1322s + grep . /etc/multipath/bindings /etc/multipath/wwids 1322s + systemctl status multipathd.service 1322s ● multipathd.service - Device-Mapper Multipath Device Controller 1322s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 1322s Active: active (running) since Tue 2024-09-10 15:07:38 UTC; 4min 32s ago 1322s Invocation: 6f306a0bb49d48ef990dd410dd961a37 1322s TriggeredBy: ○ multipathd.socket 1322s Main PID: 313 (multipathd) 1322s Status: "up" 1322s Tasks: 7 1322s Memory: 27.8M (peak: 34.3M) 1322s CPU: 58ms 1322s CGroup: /system.slice/multipathd.service 1322s └─313 /sbin/multipathd -d -s 1322s 1322s Sep 10 15:07:38 autopkgtest multipathd[313]: multipathd v0.9.9: start up 1322s Sep 10 15:07:38 autopkgtest multipathd[313]: reconfigure: setting up paths and maps 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1322s Sep 10 15:12:06 autopkgtest multipathd[313]: updated bindings file /etc/multipath/bindings 1322s Sep 10 15:12:06 autopkgtest multipathd[313]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 1322s Sep 10 15:12:06 autopkgtest multipathd[313]: sda [8:0]: path added to devmap mpatha 1322s Sep 10 15:12:06 autopkgtest multipathd[313]: mpatha: performing delayed actions 1322s Sep 10 15:12:06 autopkgtest multipathd[313]: 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:32 1 service-time 0 1 1 8:48 1] 1322s + ret_code=0 1322s + systemctl status multipathd.socket 1322s ○ multipathd.socket - multipathd control socket 1322s Loaded: loaded (/usr/lib/systemd/system/multipathd.socket; static) 1322s Active: inactive (dead) 1322s Triggers: ● multipathd.service 1322s Listen: @/org/kernel/linux/storage/multipathd (Stream) 1322s + ret_code=3 1322s + [ 3 -eq 0 ] 1322s + [ 3 -eq 3 ] 1322s + ls -la /dev/mapper/ 1322s + echo journal 1322s + journalctl -b 1322s total 0 1322s drwxr-xr-x 2 root root 80 Sep 10 15:12 . 1322s drwxr-xr-x 20 root root 4360 Sep 10 15:12 .. 1322s crw------- 1 root root 10, 236 Sep 10 15:07 control 1322s lrwxrwxrwx 1 root root 7 Sep 10 15:12 mpatha -> ../dm-0 1322s journal 1322s Sep 10 15:07:38 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 1322s Sep 10 15:07:38 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 1322s Sep 10 15:07:38 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 1322s Sep 10 15:07:38 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 1322s Sep 10 15:07:38 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 1322s Sep 10 15:07:38 autopkgtest kernel: Activating Kernel Userspace Access Prevention 1322s Sep 10 15:07:38 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 1322s Sep 10 15:07:38 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x0000000003a00000 with 2.00 MiB pages (exec) 1322s Sep 10 15:07:38 autopkgtest kernel: radix-mmu: Mapped 0x0000000003a00000-0x0000000040000000 with 2.00 MiB pages 1322s Sep 10 15:07:38 autopkgtest kernel: radix-mmu: Mapped 0x0000000040000000-0x0000000200000000 with 1.00 GiB pages 1322s Sep 10 15:07:38 autopkgtest kernel: lpar: Using radix MMU under hypervisor 1322s Sep 10 15:07:38 autopkgtest kernel: Linux version 6.11.0-7-generic (buildd@bos02-ppc64el-027) (powerpc64le-linux-gnu-gcc-14 (Ubuntu 14.2.0-4ubuntu2) 14.2.0, GNU ld (GNU Binutils for Ubuntu) 2.43.1) #7-Ubuntu SMP Mon Sep 9 13:10:01 UTC 2024 (Ubuntu 6.11.0-7.7-generic 6.11.0-rc7) 1322s Sep 10 15:07:38 autopkgtest kernel: Secure boot mode disabled 1322s Sep 10 15:07:38 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc000000009442a43 1322s Sep 10 15:07:38 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (architected) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 1322s Sep 10 15:07:38 autopkgtest kernel: Partition configured for 4 cpus. 1322s Sep 10 15:07:38 autopkgtest kernel: CPU maps initialized for 1 thread per core 1322s Sep 10 15:07:38 autopkgtest kernel: (thread shift is 0) 1322s Sep 10 15:07:38 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 1322s Sep 10 15:07:38 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 1322s Sep 10 15:07:38 autopkgtest kernel: ----------------------------------------------------- 1322s Sep 10 15:07:38 autopkgtest kernel: phys_mem_size = 0x200000000 1322s Sep 10 15:07:38 autopkgtest kernel: dcache_bsize = 0x80 1322s Sep 10 15:07:38 autopkgtest kernel: icache_bsize = 0x80 1322s Sep 10 15:07:38 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 1322s Sep 10 15:07:38 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 1322s Sep 10 15:07:38 autopkgtest kernel: always = 0x0000000380008181 1322s Sep 10 15:07:38 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 1322s Sep 10 15:07:38 autopkgtest kernel: mmu_features = 0x3c007641 1322s Sep 10 15:07:38 autopkgtest kernel: firmware_features = 0x00000285455a445f 1322s Sep 10 15:07:38 autopkgtest kernel: vmalloc start = 0xc008000000000000 1322s Sep 10 15:07:38 autopkgtest kernel: IO start = 0xc00a000000000000 1322s Sep 10 15:07:38 autopkgtest kernel: vmemmap start = 0xc00c000000000000 1322s Sep 10 15:07:38 autopkgtest kernel: ----------------------------------------------------- 1322s Sep 10 15:07:38 autopkgtest kernel: numa: NODE_DATA [mem 0x1fff7c280-0x1fff83fff] 1322s Sep 10 15:07:38 autopkgtest kernel: rfi-flush: fallback displacement flush available 1322s Sep 10 15:07:38 autopkgtest kernel: rfi-flush: ori type flush available 1322s Sep 10 15:07:38 autopkgtest kernel: rfi-flush: mttrig type flush available 1322s Sep 10 15:07:38 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 1322s Sep 10 15:07:38 autopkgtest kernel: count-cache-flush: hardware flush enabled. 1322s Sep 10 15:07:38 autopkgtest kernel: link-stack-flush: software flush enabled. 1322s Sep 10 15:07:38 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 1322s Sep 10 15:07:38 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 1322s Sep 10 15:07:38 autopkgtest kernel: stf-barrier: eieio barrier available 1322s Sep 10 15:07:38 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 1322s Sep 10 15:07:38 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 1322s Sep 10 15:07:38 autopkgtest kernel: PPC64 nvram contains 65536 bytes 1322s Sep 10 15:07:38 autopkgtest kernel: barrier-nospec: using ORI speculation barrier 1322s Sep 10 15:07:38 autopkgtest kernel: barrier-nospec: patched 275 locations 1322s Sep 10 15:07:38 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 1322s Sep 10 15:07:38 autopkgtest kernel: Memory hole size: 0MB 1322s Sep 10 15:07:38 autopkgtest kernel: Zone ranges: 1322s Sep 10 15:07:38 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 1322s Sep 10 15:07:38 autopkgtest kernel: Device empty 1322s Sep 10 15:07:38 autopkgtest kernel: Movable zone start for each node 1322s Sep 10 15:07:38 autopkgtest kernel: Early memory node ranges 1322s Sep 10 15:07:38 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 1322s Sep 10 15:07:38 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 1322s Sep 10 15:07:38 autopkgtest kernel: percpu: Embedded 12 pages/cpu s619032 r0 d167400 u786432 1322s Sep 10 15:07:38 autopkgtest kernel: pcpu-alloc: s619032 r0 d167400 u786432 alloc=12*65536 1322s Sep 10 15:07:38 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 1322s Sep 10 15:07:38 autopkgtest kernel: Kernel command line: BOOT_IMAGE=/boot/vmlinux-6.11.0-7-generic root=UUID=b421051a-5f17-47ac-ade0-d9d9c5a5c13f ro console=hvc0 earlyprintk 1322s Sep 10 15:07:38 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.11.0-7-generic", will be passed to user space. 1322s Sep 10 15:07:38 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 1322s Sep 10 15:07:38 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 1322s Sep 10 15:07:38 autopkgtest kernel: Fallback order for Node 0: 0 1322s Sep 10 15:07:38 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 131072 1322s Sep 10 15:07:38 autopkgtest kernel: Policy zone: Normal 1322s Sep 10 15:07:38 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 1322s Sep 10 15:07:38 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 1322s Sep 10 15:07:38 autopkgtest kernel: ftrace: allocating 52916 entries in 20 pages 1322s Sep 10 15:07:38 autopkgtest kernel: ftrace: allocated 20 pages with 2 groups 1322s Sep 10 15:07:38 autopkgtest kernel: trace event string verifier disabled 1322s Sep 10 15:07:38 autopkgtest kernel: rcu: Hierarchical RCU implementation. 1322s Sep 10 15:07:38 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 1322s Sep 10 15:07:38 autopkgtest kernel: Rude variant of Tasks RCU enabled. 1322s Sep 10 15:07:38 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 1322s Sep 10 15:07:38 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 1322s Sep 10 15:07:38 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 1322s Sep 10 15:07:38 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 1322s Sep 10 15:07:38 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 1322s Sep 10 15:07:38 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 1322s Sep 10 15:07:38 autopkgtest kernel: xive: Using IRQ range [0-3] 1322s Sep 10 15:07:38 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 1322s Sep 10 15:07:38 autopkgtest kernel: xive: Using priority 6 for all interrupts 1322s Sep 10 15:07:38 autopkgtest kernel: xive: Using 64kB queues 1322s Sep 10 15:07:38 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 1322s Sep 10 15:07:38 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 1322s Sep 10 15:07:38 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 1322s Sep 10 15:07:38 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 1322s Sep 10 15:07:38 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 1322s Sep 10 15:07:38 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 1322s Sep 10 15:07:38 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 1322s Sep 10 15:07:38 autopkgtest kernel: Console: colour dummy device 80x25 1322s Sep 10 15:07:38 autopkgtest kernel: pid_max: default: 32768 minimum: 301 1322s Sep 10 15:07:38 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,ima,evm 1322s Sep 10 15:07:38 autopkgtest kernel: landlock: Up and running. 1322s Sep 10 15:07:38 autopkgtest kernel: Yama: becoming mindful. 1322s Sep 10 15:07:38 autopkgtest kernel: AppArmor: AppArmor initialized 1322s Sep 10 15:07:38 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 1322s Sep 10 15:07:38 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 1322s Sep 10 15:07:38 autopkgtest kernel: POWER9 performance monitor hardware support registered 1322s Sep 10 15:07:38 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 1322s Sep 10 15:07:38 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 1322s Sep 10 15:07:38 autopkgtest kernel: Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level 1322s Sep 10 15:07:38 autopkgtest kernel: smp: Bringing up secondary CPUs ... 1322s Sep 10 15:07:38 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 1322s Sep 10 15:07:38 autopkgtest kernel: numa: Node 0 CPUs: 0-3 1322s Sep 10 15:07:38 autopkgtest kernel: Memory: 8202112K/8388608K available (24448K kernel code, 4160K rwdata, 24704K rodata, 8768K init, 1851K bss, 157184K reserved, 0K cma-reserved) 1322s Sep 10 15:07:38 autopkgtest kernel: devtmpfs: initialized 1322s Sep 10 15:07:38 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 1322s Sep 10 15:07:38 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 1322s Sep 10 15:07:38 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 1322s Sep 10 15:07:38 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 1322s Sep 10 15:07:38 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 1322s Sep 10 15:07:38 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 1322s Sep 10 15:07:38 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 1322s Sep 10 15:07:38 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 1322s Sep 10 15:07:38 autopkgtest kernel: audit: initializing netlink subsys (disabled) 1322s Sep 10 15:07:38 autopkgtest kernel: audit: type=2000 audit(1725980856.040:1): state=initialized audit_enabled=0 res=1 1322s Sep 10 15:07:38 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 1322s Sep 10 15:07:38 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 1322s Sep 10 15:07:38 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 1322s Sep 10 15:07:38 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 1322s Sep 10 15:07:38 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 1322s Sep 10 15:07:38 autopkgtest kernel: cpuidle: using governor ladder 1322s Sep 10 15:07:38 autopkgtest kernel: cpuidle: using governor menu 1322s Sep 10 15:07:38 autopkgtest kernel: RTAS daemon started 1322s Sep 10 15:07:38 autopkgtest kernel: pstore: Using crash dump compression: deflate 1322s Sep 10 15:07:38 autopkgtest kernel: pstore: Registered nvram as persistent store backend 1322s Sep 10 15:07:38 autopkgtest kernel: EEH: pSeries platform initialized 1322s Sep 10 15:07:38 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 1322s Sep 10 15:07:38 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 1322s Sep 10 15:07:38 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 1322s Sep 10 15:07:38 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 1322s Sep 10 15:07:38 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 1322s Sep 10 15:07:38 autopkgtest kernel: iommu: Default domain type: Translated 1322s Sep 10 15:07:38 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 1322s Sep 10 15:07:38 autopkgtest kernel: SCSI subsystem initialized 1322s Sep 10 15:07:38 autopkgtest kernel: libata version 3.00 loaded. 1322s Sep 10 15:07:38 autopkgtest kernel: usbcore: registered new interface driver usbfs 1322s Sep 10 15:07:38 autopkgtest kernel: usbcore: registered new interface driver hub 1322s Sep 10 15:07:38 autopkgtest kernel: usbcore: registered new device driver usb 1322s Sep 10 15:07:38 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 1322s Sep 10 15:07:38 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 1322s Sep 10 15:07:38 autopkgtest kernel: PTP clock support registered 1322s Sep 10 15:07:38 autopkgtest kernel: EDAC MC: Ver: 3.0.0 1322s Sep 10 15:07:38 autopkgtest kernel: NetLabel: Initializing 1322s Sep 10 15:07:38 autopkgtest kernel: NetLabel: domain hash size = 128 1322s Sep 10 15:07:38 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 1322s Sep 10 15:07:38 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 1322s Sep 10 15:07:38 autopkgtest kernel: mctp: management component transport protocol core 1322s Sep 10 15:07:38 autopkgtest kernel: NET: Registered PF_MCTP protocol family 1322s Sep 10 15:07:38 autopkgtest kernel: PCI: Probing PCI hardware 1322s Sep 10 15:07:38 autopkgtest kernel: PCI host bridge to bus 0000:00 1322s Sep 10 15:07:38 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 1322s Sep 10 15:07:38 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 1322s Sep 10 15:07:38 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 1322s Sep 10 15:07:38 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:05.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:06.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:07.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1322s Sep 10 15:07:38 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 1322s Sep 10 15:07:38 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 1322s Sep 10 15:07:38 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 1322s Sep 10 15:07:38 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 1322s Sep 10 15:07:38 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:01.0: ibm,query-pe-dma-windows(2026) 800 8000000 20000000 returned 0, lb=80000000 ps=7 wn=1 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:05.0: Adding to iommu group 0 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:06.0: Adding to iommu group 0 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:07.0: Adding to iommu group 0 1322s Sep 10 15:07:38 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 1322s Sep 10 15:07:38 autopkgtest kernel: PCI: Probing PCI hardware done 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:07.0: vgaarb: setting as boot VGA device 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:07.0: vgaarb: bridge control possible 1322s Sep 10 15:07:38 autopkgtest kernel: pci 0000:00:07.0: vgaarb: VGA device added: decodes=io+mem,owns=mem,locks=none 1322s Sep 10 15:07:38 autopkgtest kernel: vgaarb: loaded 1322s Sep 10 15:07:38 autopkgtest kernel: clocksource: Switched to clocksource timebase 1322s Sep 10 15:07:38 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 1322s Sep 10 15:07:38 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 1322s Sep 10 15:07:38 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 1322s Sep 10 15:07:38 autopkgtest kernel: NET: Registered PF_INET protocol family 1322s Sep 10 15:07:38 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 1322s Sep 10 15:07:38 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 1322s Sep 10 15:07:38 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 1322s Sep 10 15:07:38 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 1322s Sep 10 15:07:38 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 1322s Sep 10 15:07:38 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 1322s Sep 10 15:07:38 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 1322s Sep 10 15:07:38 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 1322s Sep 10 15:07:38 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 1322s Sep 10 15:07:38 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 1322s Sep 10 15:07:38 autopkgtest kernel: NET: Registered PF_XDP protocol family 1322s Sep 10 15:07:38 autopkgtest kernel: PCI: CLS 0 bytes, default 128 1322s Sep 10 15:07:38 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 1322s Sep 10 15:07:38 autopkgtest kernel: Initialise system trusted keyrings 1322s Sep 10 15:07:38 autopkgtest kernel: Key type blacklist registered 1322s Sep 10 15:07:38 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 1322s Sep 10 15:07:38 autopkgtest kernel: zbud: loaded 1322s Sep 10 15:07:38 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 1322s Sep 10 15:07:38 autopkgtest kernel: fuse: init (API version 7.40) 1322s Sep 10 15:07:38 autopkgtest kernel: integrity: Platform Keyring initialized 1322s Sep 10 15:07:38 autopkgtest kernel: integrity: Machine keyring initialized 1322s Sep 10 15:07:38 autopkgtest kernel: Key type asymmetric registered 1322s Sep 10 15:07:38 autopkgtest kernel: Asymmetric key parser 'x509' registered 1322s Sep 10 15:07:38 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 1322s Sep 10 15:07:38 autopkgtest kernel: io scheduler mq-deadline registered 1322s Sep 10 15:07:38 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 1322s Sep 10 15:07:38 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 1322s Sep 10 15:07:38 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) 1322s Sep 10 15:07:38 autopkgtest kernel: virtio-pci 0000:00:03.0: enabling device (0100 -> 0103) 1322s Sep 10 15:07:38 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 1322s Sep 10 15:07:38 autopkgtest kernel: virtio-pci 0000:00:05.0: enabling device (0100 -> 0103) 1322s Sep 10 15:07:38 autopkgtest kernel: virtio-pci 0000:00:06.0: enabling device (0100 -> 0103) 1322s Sep 10 15:07:38 autopkgtest kernel: printk: legacy console [hvc0] enabled 1322s Sep 10 15:07:38 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 1322s Sep 10 15:07:38 autopkgtest kernel: Freeing initrd memory: 51456K 1322s Sep 10 15:07:38 autopkgtest kernel: Non-volatile memory driver v1.3 1322s Sep 10 15:07:38 autopkgtest kernel: Linux agpgart interface v0.103 1322s Sep 10 15:07:38 autopkgtest kernel: loop: module loaded 1322s Sep 10 15:07:38 autopkgtest kernel: virtio_blk virtio2: 4/0/0 default/read/poll queues 1322s Sep 10 15:07:38 autopkgtest kernel: virtio_blk virtio2: [vda] 209715200 512-byte logical blocks (107 GB/100 GiB) 1322s Sep 10 15:07:38 autopkgtest kernel: vda: vda1 vda2 1322s Sep 10 15:07:38 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 1322s Sep 10 15:07:38 autopkgtest kernel: PPP generic driver version 2.4.2 1322s Sep 10 15:07:38 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 1322s Sep 10 15:07:38 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 1322s Sep 10 15:07:38 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-09-10T15:07:36 UTC (1725980856) 1322s Sep 10 15:07:38 autopkgtest kernel: i2c_dev: i2c /dev entries driver 1322s Sep 10 15:07:38 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 1322s Sep 10 15:07:38 autopkgtest kernel: device-mapper: uevent: version 1.0.3 1322s Sep 10 15:07:38 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@lists.linux.dev 1322s Sep 10 15:07:38 autopkgtest kernel: pseries_idle_driver registered 1322s Sep 10 15:07:38 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 1322s Sep 10 15:07:38 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 1322s Sep 10 15:07:38 autopkgtest kernel: NET: Registered PF_INET6 protocol family 1322s Sep 10 15:07:38 autopkgtest kernel: Segment Routing with IPv6 1322s Sep 10 15:07:38 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 1322s Sep 10 15:07:38 autopkgtest kernel: NET: Registered PF_PACKET protocol family 1322s Sep 10 15:07:38 autopkgtest kernel: Key type dns_resolver registered 1322s Sep 10 15:07:38 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 1322s Sep 10 15:07:38 autopkgtest kernel: registered taskstats version 1 1322s Sep 10 15:07:38 autopkgtest kernel: Loading compiled-in X.509 certificates 1322s Sep 10 15:07:38 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: 12384d98c3ac13d6e28ded7f2584c514f41d658f' 1322s Sep 10 15:07:38 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 1322s Sep 10 15:07:38 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 1322s Sep 10 15:07:38 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 1322s Sep 10 15:07:38 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 1322s Sep 10 15:07:38 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 1322s Sep 10 15:07:38 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 1322s Sep 10 15:07:38 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 1322s Sep 10 15:07:38 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 1322s Sep 10 15:07:38 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 1322s Sep 10 15:07:38 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 1322s Sep 10 15:07:38 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 1322s Sep 10 15:07:38 autopkgtest kernel: Demotion targets for Node 0: null 1322s Sep 10 15:07:38 autopkgtest kernel: Key type .fscrypt registered 1322s Sep 10 15:07:38 autopkgtest kernel: Key type fscrypt-provisioning registered 1322s Sep 10 15:07:38 autopkgtest kernel: Key type encrypted registered 1322s Sep 10 15:07:38 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 1322s Sep 10 15:07:38 autopkgtest kernel: Secure boot mode disabled 1322s Sep 10 15:07:38 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 1322s Sep 10 15:07:38 autopkgtest kernel: Loading compiled-in module X.509 certificates 1322s Sep 10 15:07:38 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: 12384d98c3ac13d6e28ded7f2584c514f41d658f' 1322s Sep 10 15:07:38 autopkgtest kernel: ima: Allocated hash algorithm: sha256 1322s Sep 10 15:07:38 autopkgtest kernel: Secure boot mode disabled 1322s Sep 10 15:07:38 autopkgtest kernel: Trusted boot mode disabled 1322s Sep 10 15:07:38 autopkgtest kernel: ima: No architecture policies found 1322s Sep 10 15:07:38 autopkgtest kernel: evm: Initialising EVM extended attributes: 1322s Sep 10 15:07:38 autopkgtest kernel: evm: security.selinux 1322s Sep 10 15:07:38 autopkgtest kernel: evm: security.SMACK64 1322s Sep 10 15:07:38 autopkgtest kernel: evm: security.SMACK64EXEC 1322s Sep 10 15:07:38 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 1322s Sep 10 15:07:38 autopkgtest kernel: evm: security.SMACK64MMAP 1322s Sep 10 15:07:38 autopkgtest kernel: evm: security.apparmor 1322s Sep 10 15:07:38 autopkgtest kernel: evm: security.ima 1322s Sep 10 15:07:38 autopkgtest kernel: evm: security.capability 1322s Sep 10 15:07:38 autopkgtest kernel: evm: HMAC attrs: 0x1 1322s Sep 10 15:07:38 autopkgtest kernel: SED: plpks not available 1322s Sep 10 15:07:38 autopkgtest kernel: clk: Disabling unused clocks 1322s Sep 10 15:07:38 autopkgtest kernel: PM: genpd: Disabling unused power domains 1322s Sep 10 15:07:38 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 1322s Sep 10 15:07:38 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8768K 1322s Sep 10 15:07:38 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 1322s Sep 10 15:07:38 autopkgtest kernel: Run /init as init process 1322s Sep 10 15:07:38 autopkgtest kernel: with arguments: 1322s Sep 10 15:07:38 autopkgtest kernel: /init 1322s Sep 10 15:07:38 autopkgtest kernel: earlyprintk 1322s Sep 10 15:07:38 autopkgtest kernel: with environment: 1322s Sep 10 15:07:38 autopkgtest kernel: HOME=/ 1322s Sep 10 15:07:38 autopkgtest kernel: TERM=linux 1322s Sep 10 15:07:38 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.11.0-7-generic 1322s Sep 10 15:07:38 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 1322s Sep 10 15:07:38 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 1 1322s Sep 10 15:07:38 autopkgtest kernel: xhci_hcd 0000:00:02.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010 1322s Sep 10 15:07:38 autopkgtest kernel: random: crng init done 1322s Sep 10 15:07:38 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 1322s Sep 10 15:07:38 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 1322s Sep 10 15:07:38 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2 1322s Sep 10 15:07:38 autopkgtest kernel: xhci_hcd 0000:00:02.0: Host supports USB 3.0 SuperSpeed 1322s Sep 10 15:07:38 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.11 1322s Sep 10 15:07:38 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 1322s Sep 10 15:07:38 autopkgtest kernel: usb usb1: Product: xHCI Host Controller 1322s Sep 10 15:07:38 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.11.0-7-generic xhci-hcd 1322s Sep 10 15:07:38 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:02.0 1322s Sep 10 15:07:38 autopkgtest kernel: hub 1-0:1.0: USB hub found 1322s Sep 10 15:07:38 autopkgtest kernel: hub 1-0:1.0: 4 ports detected 1322s Sep 10 15:07:38 autopkgtest kernel: usb usb2: We don't know the algorithms for LPM for this host, disabling LPM. 1322s Sep 10 15:07:38 autopkgtest kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.11 1322s Sep 10 15:07:38 autopkgtest kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 1322s Sep 10 15:07:38 autopkgtest kernel: usb usb2: Product: xHCI Host Controller 1322s Sep 10 15:07:38 autopkgtest kernel: usb usb2: Manufacturer: Linux 6.11.0-7-generic xhci-hcd 1322s Sep 10 15:07:38 autopkgtest kernel: usb usb2: SerialNumber: 0000:00:02.0 1322s Sep 10 15:07:38 autopkgtest kernel: hub 2-0:1.0: USB hub found 1322s Sep 10 15:07:38 autopkgtest kernel: hub 2-0:1.0: 4 ports detected 1322s Sep 10 15:07:38 autopkgtest kernel: [drm] Found bochs VGA, ID 0xb0c5. 1322s Sep 10 15:07:38 autopkgtest kernel: [drm] Framebuffer size 16384 kB @ 0x200081000000, mmio @ 0x200082000000. 1322s Sep 10 15:07:38 autopkgtest kernel: [drm] Found EDID data blob. 1322s Sep 10 15:07:38 autopkgtest kernel: [drm] Initialized bochs-drm 1.0.0 for 0000:00:07.0 on minor 0 1322s Sep 10 15:07:38 autopkgtest kernel: fbcon: Deferring console take-over 1322s Sep 10 15:07:38 autopkgtest kernel: bochs-drm 0000:00:07.0: [drm] fb0: bochs-drmdrmfb frame buffer device 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: vpermxor8 gen() 21574 MB/s 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: vpermxor4 gen() 18744 MB/s 1322s Sep 10 15:07:38 autopkgtest kernel: usb 1-1: new high-speed USB device number 2 using xhci_hcd 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: vpermxor2 gen() 15017 MB/s 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: vpermxor1 gen() 13529 MB/s 1322s Sep 10 15:07:38 autopkgtest kernel: usb 1-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 1322s Sep 10 15:07:38 autopkgtest kernel: usb 1-1: New USB device strings: Mfr=1, Product=4, SerialNumber=11 1322s Sep 10 15:07:38 autopkgtest kernel: usb 1-1: Product: QEMU USB Keyboard 1322s Sep 10 15:07:38 autopkgtest kernel: usb 1-1: Manufacturer: QEMU 1322s Sep 10 15:07:38 autopkgtest kernel: usb 1-1: SerialNumber: 68284-pci@800000020000000:02.0-1 1322s Sep 10 15:07:38 autopkgtest kernel: hid: raw HID events driver (C) Jiri Kosina 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: altivecx8 gen() 13212 MB/s 1322s Sep 10 15:07:38 autopkgtest kernel: usbcore: registered new interface driver usbhid 1322s Sep 10 15:07:38 autopkgtest kernel: usbhid: USB HID core driver 1322s Sep 10 15:07:38 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 1322s Sep 10 15:07:38 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 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: altivecx4 gen() 13728 MB/s 1322s Sep 10 15:07:38 autopkgtest kernel: usb 1-2: new high-speed USB device number 3 using xhci_hcd 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: altivecx2 gen() 10974 MB/s 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: altivecx1 gen() 8484 MB/s 1322s Sep 10 15:07:38 autopkgtest kernel: usb 1-2: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 1322s Sep 10 15:07:38 autopkgtest kernel: usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=9 1322s Sep 10 15:07:38 autopkgtest kernel: usb 1-2: Product: QEMU USB Mouse 1322s Sep 10 15:07:38 autopkgtest kernel: usb 1-2: Manufacturer: QEMU 1322s Sep 10 15:07:38 autopkgtest kernel: usb 1-2: SerialNumber: 89126-pci@800000020000000:02.0-2 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: int64x8 gen() 7207 MB/s 1322s Sep 10 15:07:38 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 1322s Sep 10 15:07:38 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 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: int64x4 gen() 8783 MB/s 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: int64x2 gen() 6720 MB/s 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: int64x1 gen() 5279 MB/s 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 21574 MB/s 1322s Sep 10 15:07:38 autopkgtest kernel: raid6: using intx1 recovery algorithm 1322s Sep 10 15:07:38 autopkgtest kernel: xor: measuring software checksum speed 1322s Sep 10 15:07:38 autopkgtest kernel: 8regs : 17850 MB/sec 1322s Sep 10 15:07:38 autopkgtest kernel: 8regs_prefetch : 15950 MB/sec 1322s Sep 10 15:07:38 autopkgtest kernel: 32regs : 17855 MB/sec 1322s Sep 10 15:07:38 autopkgtest kernel: 32regs_prefetch : 15853 MB/sec 1322s Sep 10 15:07:38 autopkgtest kernel: altivec : 19569 MB/sec 1322s Sep 10 15:07:38 autopkgtest kernel: xor: using function: altivec (19569 MB/sec) 1322s Sep 10 15:07:38 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 1322s Sep 10 15:07:38 autopkgtest kernel: EXT4-fs (vda1): orphan cleanup on readonly fs 1322s Sep 10 15:07:38 autopkgtest kernel: EXT4-fs (vda1): mounted filesystem b421051a-5f17-47ac-ade0-d9d9c5a5c13f ro with ordered data mode. Quota mode: none. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Inserted module 'autofs4' 1322s Sep 10 15:07:38 autopkgtest systemd[1]: systemd 256.4-2ubuntu1 running in system mode (+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -XKBCOMMON +UTMP +SYSVINIT +LIBARCHIVE) 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Detected virtualization kvm. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Detected architecture ppc64-le. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Hostname set to . 1322s Sep 10 15:07:38 autopkgtest systemd[1]: bpf-restrict-fs: BPF LSM hook not enabled in the kernel, BPF LSM not supported. 1322s Sep 10 15:07:38 autopkgtest kernel: NET: Registered PF_VSOCK protocol family 1322s Sep 10 15:07:38 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. 1322s Sep 10 15:07:38 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. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Queued start job for default target graphical.target. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Reached target swap.target - Swaps. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Sockets. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounting run-lock.mount - Legacy Locks Directory /run/lock... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting modprobe@dm_multipath.service - Load Kernel Module dm_multipath... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 1322s Sep 10 15:07:38 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). 1322s Sep 10 15:07:38 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). 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 1322s Sep 10 15:07:38 autopkgtest systemd-journald[284]: Collecting audit messages is disabled. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounted run-lock.mount - Legacy Locks Directory /run/lock. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: modprobe@dm_multipath.service: Deactivated successfully. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished modprobe@dm_multipath.service - Load Kernel Module dm_multipath. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 1322s Sep 10 15:07:38 autopkgtest kernel: EXT4-fs (vda1): re-mounted b421051a-5f17-47ac-ade0-d9d9c5a5c13f r/w. Quota mode: none. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 1322s Sep 10 15:07:38 autopkgtest systemd-journald[284]: Journal started 1322s Sep 10 15:07:38 autopkgtest systemd-journald[284]: Runtime Journal (/run/log/journal/dfe3593ae176490a978a99e3bcd2119a) is 8M, max 81M, 73M free. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting cloud-init-main.service - Cloud-init: Single Process... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 1322s Sep 10 15:07:38 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 1322s Sep 10 15:07:38 autopkgtest systemd-journald[284]: Time spent on flushing to /var/log/journal/dfe3593ae176490a978a99e3bcd2119a is 34.086ms for 461 entries. 1322s Sep 10 15:07:38 autopkgtest systemd-journald[284]: System Journal (/var/log/journal/dfe3593ae176490a978a99e3bcd2119a) is 18.9M, max 4G, 3.9G free. 1322s Sep 10 15:07:38 autopkgtest systemd-journald[284]: Received client request to flush runtime journal. 1322s Sep 10 15:07:38 autopkgtest multipathd[313]: multipathd v0.9.9: start up 1322s Sep 10 15:07:38 autopkgtest multipathd[313]: reconfigure: setting up paths and maps 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 1322s Sep 10 15:07:38 autopkgtest apparmor.systemd[351]: Restarting AppArmor 1322s Sep 10 15:07:38 autopkgtest apparmor.systemd[351]: Reloading AppArmor profiles 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 355 (systemd-binfmt) 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 1322s Sep 10 15:07:38 autopkgtest systemd-tmpfiles[372]: /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 1322s Sep 10 15:07:38 autopkgtest kernel: audit: type=1400 audit(1725980858.740:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=378 comm="apparmor_parser" 1322s Sep 10 15:07:38 autopkgtest kernel: audit: type=1400 audit(1725980858.740:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=380 comm="apparmor_parser" 1322s Sep 10 15:07:38 autopkgtest kernel: audit: type=1400 audit(1725980858.744:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=379 comm="apparmor_parser" 1322s Sep 10 15:07:38 autopkgtest systemd-udevd[358]: Using default interface naming scheme 'v255'. 1322s Sep 10 15:07:38 autopkgtest kernel: audit: type=1400 audit(1725980858.744:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=381 comm="apparmor_parser" 1322s Sep 10 15:07:38 autopkgtest kernel: audit: type=1400 audit(1725980858.744:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=383 comm="apparmor_parser" 1322s Sep 10 15:07:38 autopkgtest kernel: audit: type=1400 audit(1725980858.744:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=384 comm="apparmor_parser" 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 1322s Sep 10 15:07:38 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 1322s Sep 10 15:07:38 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 1322s Sep 10 15:07:38 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). 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 1322s Sep 10 15:07:38 autopkgtest kernel: audit: type=1400 audit(1725980858.748:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="busybox" pid=386 comm="apparmor_parser" 1322s Sep 10 15:07:38 autopkgtest kernel: audit: type=1400 audit(1725980858.748:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="cam" pid=388 comm="apparmor_parser" 1322s Sep 10 15:07:38 autopkgtest kernel: audit: type=1400 audit(1725980858.748:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=385 comm="apparmor_parser" 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 1322s Sep 10 15:07:38 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). 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. 1322s Sep 10 15:07:38 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 1322s Sep 10 15:07:38 autopkgtest (udev-worker)[436]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 1322s Sep 10 15:07:39 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 1322s Sep 10 15:07:39 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 1322s Sep 10 15:07:39 autopkgtest systemd[1]: Started cloud-init-main.service - Cloud-init: Single Process. 1322s Sep 10 15:07:39 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 1322s Sep 10 15:07:39 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 1322s Sep 10 15:07:39 autopkgtest cloud-init[685]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu1 running 'init-local' at Tue, 10 Sep 2024 15:07:39 +0000. Up 3.46 seconds. 1322s Sep 10 15:07:39 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 1322s Sep 10 15:07:39 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 1322s Sep 10 15:07:39 autopkgtest dhcpcd[691]: dhcpcd-10.0.8 starting 1322s Sep 10 15:07:39 autopkgtest systemd-resolved[392]: Positive Trust Anchors: 1322s Sep 10 15:07:39 autopkgtest systemd-resolved[392]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 1322s Sep 10 15:07:39 autopkgtest systemd-resolved[392]: 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 1322s Sep 10 15:07:39 autopkgtest dhcpcd[694]: DUID 00:01:00:01:2e:71:cd:c1:fa:16:3e:e7:13:df 1322s Sep 10 15:07:39 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 1322s Sep 10 15:07:39 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 1322s Sep 10 15:07:39 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 1322s Sep 10 15:07:39 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 1322s Sep 10 15:07:39 autopkgtest systemd-resolved[392]: Using system hostname 'autopkgtest'. 1322s Sep 10 15:07:39 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 1322s Sep 10 15:07:39 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 1322s Sep 10 15:07:39 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 1322s Sep 10 15:07:39 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 1322s Sep 10 15:07:39 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 1322s Sep 10 15:07:39 autopkgtest dhcpcd[694]: enp0s1: IAID 3e:d9:7b:91 1322s Sep 10 15:07:40 autopkgtest dhcpcd[694]: enp0s1: rebinding lease of 10.145.227.72 1322s Sep 10 15:07:40 autopkgtest dhcpcd[694]: enp0s1: leased 10.145.227.72 for 43200 seconds 1322s Sep 10 15:07:40 autopkgtest dhcpcd[694]: enp0s1: adding route to 10.145.227.0/24 1322s Sep 10 15:07:40 autopkgtest dhcpcd[694]: enp0s1: adding host route to 169.254.169.254 via 10.145.227.2 1322s Sep 10 15:07:40 autopkgtest dhcpcd[694]: enp0s1: adding default route via 10.145.227.1 1322s Sep 10 15:07:40 autopkgtest dhcpcd[694]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 1322s Sep 10 15:07:47 autopkgtest sh[680]: Completed socket interaction for boot stage local 1322s Sep 10 15:07:47 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 1322s Sep 10 15:07:47 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 1322s Sep 10 15:07:47 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 1322s Sep 10 15:07:47 autopkgtest systemd-networkd[725]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 1322s Sep 10 15:07:47 autopkgtest systemd-networkd[725]: lo: Link UP 1322s Sep 10 15:07:47 autopkgtest systemd-networkd[725]: lo: Gained carrier 1322s Sep 10 15:07:47 autopkgtest systemd-networkd[725]: Enumeration completed 1322s Sep 10 15:07:47 autopkgtest systemd-networkd[725]: enp0s1: Link UP 1322s Sep 10 15:07:47 autopkgtest systemd-networkd[725]: enp0s1: Gained carrier 1322s Sep 10 15:07:47 autopkgtest systemd-networkd[725]: enp0s1: Gained IPv6LL 1322s Sep 10 15:07:47 autopkgtest systemd-networkd[725]: enp0s1: Link DOWN 1322s Sep 10 15:07:47 autopkgtest systemd-networkd[725]: enp0s1: Lost carrier 1322s Sep 10 15:07:47 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 1322s Sep 10 15:07:47 autopkgtest systemd[1]: Reached target network.target - Network. 1322s Sep 10 15:07:47 autopkgtest systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... 1322s Sep 10 15:07:47 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 1322s Sep 10 15:07:47 autopkgtest systemd-networkd[725]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 1322s Sep 10 15:07:47 autopkgtest systemd-networkd[725]: enp0s1: Link UP 1322s Sep 10 15:07:47 autopkgtest systemd-networkd[725]: enp0s1: Gained carrier 1322s Sep 10 15:07:47 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 1322s Sep 10 15:07:47 autopkgtest systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. 1322s Sep 10 15:07:47 autopkgtest systemd-networkd[725]: enp0s1: DHCPv4 address 10.145.227.72/24, gateway 10.145.227.1 acquired from 10.145.227.1 1322s Sep 10 15:07:47 autopkgtest systemd-timesyncd[394]: Network configuration changed, trying to establish connection. 1322s Sep 10 15:07:49 autopkgtest systemd-networkd[725]: enp0s1: Gained IPv6LL 1322s Sep 10 15:07:49 autopkgtest systemd-timesyncd[394]: Network configuration changed, trying to establish connection. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Starting cloud-init-network.service - Cloud-init: Network Stage... 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu1 running 'init' at Tue, 10 Sep 2024 15:07:49 +0000. Up 13.51 seconds. 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | enp0s1 | True | 10.145.227.72 | 255.255.255.0 | global | fa:16:3e:d9:7b:91 | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | enp0s1 | True | fe80::f816:3eff:fed9:7b91/64 | . | link | fa:16:3e:d9:7b:91 | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | lo | True | ::1/128 | . | host | . | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++++ 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | 0 | 0.0.0.0 | 10.145.227.1 | 0.0.0.0 | enp0s1 | UG | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | 1 | 10.145.227.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | 2 | 10.145.227.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | 3 | 10.145.227.2 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | 4 | 91.189.91.131 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | 5 | 91.189.91.132 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | 6 | 169.254.169.254 | 10.145.227.2 | 255.255.255.255 | enp0s1 | UGH | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: +-------+-------------+---------+-----------+-------+ 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | Route | Destination | Gateway | Interface | Flags | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: +-------+-------------+---------+-----------+-------+ 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | 2 | local | :: | enp0s1 | U | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: | 3 | multicast | :: | enp0s1 | U | 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: ci-info: +-------+-------------+---------+-----------+-------+ 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: 2024-09-10 15:07:49,780 - 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. 1322s Sep 10 15:07:49 autopkgtest cloud-init[685]: 2024-09-10 15:07:49,780 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 1322s Sep 10 15:07:49 autopkgtest sh[736]: Completed socket interaction for boot stage network 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Finished cloud-init-network.service - Cloud-init: Network Stage. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 1322s Sep 10 15:07:49 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). 1322s Sep 10 15:07:49 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). 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Started sysstat-collect.timer - Run system activity accounting tool every 10 minutes. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Started sysstat-rotate.timer - Rotate daily system activity data file at midnight. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Started sysstat-summary.timer - Generate summary of yesterday's process accounting. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 1322s Sep 10 15:07:49 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). 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Reached target paths.target - Path Units. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 1322s Sep 10 15:07:49 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Reached target ssh-access.target - SSH Access Available. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Reached target basic.target - Basic System. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: System is tainted: unmerged-bin 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 1322s Sep 10 15:07:50 autopkgtest (sh)[771]: autopkgtest@hvc1.service: Failed to set up standard input: No such device 1322s Sep 10 15:07:50 autopkgtest (sh)[771]: autopkgtest@hvc1.service: Failed at step STDIN spawning /bin/sh: No such device 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 1322s Sep 10 15:07:50 autopkgtest (sh)[772]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 1322s Sep 10 15:07:50 autopkgtest (sh)[772]: autopkgtest@ttyS1.service: Failed at step STDIN spawning /bin/sh: Input/output error 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 1322s Sep 10 15:07:50 autopkgtest (cron)[774]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 1322s Sep 10 15:07:50 autopkgtest cron[774]: (CRON) INFO (pidfile fd = 3) 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 1322s Sep 10 15:07:50 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). 1322s Sep 10 15:07:50 autopkgtest cron[774]: (CRON) INFO (Running @reboot jobs) 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: opal_errd.service - opal_errd (PowerNV platform error handling) Service was skipped because of an unmet condition check (ConditionVirtualization=false). 1322s Sep 10 15:07:50 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). 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting sysstat.service - Resets System Activity Logs... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 1322s Sep 10 15:07:50 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). 1322s Sep 10 15:07:50 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: autopkgtest@hvc1.service: Deactivated successfully. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 1322s Sep 10 15:07:50 autopkgtest dbus-daemon[775]: [system] AppArmor D-Bus mediation is enabled 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Finished sysstat.service - Resets System Activity Logs. 1322s Sep 10 15:07:50 autopkgtest udisksd[795]: udisks daemon version 2.10.1 starting 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 1322s Sep 10 15:07:50 autopkgtest cloud-init[685]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu1 running 'modules:config' at Tue, 10 Sep 2024 15:07:50 +0000. Up 13.92 seconds. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 1322s Sep 10 15:07:50 autopkgtest rngd[848]: rngd 2.4 starting up... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 1322s Sep 10 15:07:50 autopkgtest rngd[848]: entropy feed to the kernel ready 1322s Sep 10 15:07:50 autopkgtest sh[778]: Completed socket interaction for boot stage config 1322s Sep 10 15:07:50 autopkgtest systemd-logind[791]: New seat seat0. 1322s Sep 10 15:07:50 autopkgtest systemd-logind[791]: Watching system buttons on /dev/input/event0 (QEMU QEMU USB Keyboard) 1322s Sep 10 15:07:50 autopkgtest kernel: kauditd_printk_skb: 110 callbacks suppressed 1322s Sep 10 15:07:50 autopkgtest kernel: audit: type=1400 audit(1725980870.196:121): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=835 comm="apparmor_parser" 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 1322s Sep 10 15:07:50 autopkgtest udisksd[795]: Acquired the name org.freedesktop.UDisks2 on the system message bus 1322s Sep 10 15:07:50 autopkgtest rsyslogd[872]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2406.0] 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 1322s Sep 10 15:07:50 autopkgtest rsyslogd[872]: rsyslogd's groupid changed to 102 1322s Sep 10 15:07:50 autopkgtest rsyslogd[872]: rsyslogd's userid changed to 102 1322s Sep 10 15:07:50 autopkgtest rsyslogd[872]: [origin software="rsyslogd" swVersion="8.2406.0" x-pid="872" x-info="https://www.rsyslog.com"] start 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 1322s Sep 10 15:07:50 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 1322s Sep 10 15:07:50 autopkgtest cloud-init[685]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu1 running 'modules:final' at Tue, 10 Sep 2024 15:07:50 +0000. Up 14.23 seconds. 1322s Sep 10 15:07:50 autopkgtest cloud-init[685]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu1 finished at Tue, 10 Sep 2024 15:07:50 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 14.31 seconds 1322s Sep 10 15:07:50 autopkgtest sh[886]: Completed socket interaction for boot stage final 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Startup finished in 1.844s (kernel) + 12.477s (userspace) = 14.322s. 1322s Sep 10 15:07:50 autopkgtest kernel: fbcon: Taking over console 1322s Sep 10 15:07:50 autopkgtest kernel: Console: switching to colour frame buffer device 128x48 1322s Sep 10 15:07:50 autopkgtest systemd[1]: cloud-init-main.service: Deactivated successfully. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: cloud-init-main.service: Unit process 684 (sh) remains running after unit stopped. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: cloud-init-main.service: Consumed 1.094s CPU time, 108M memory peak. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 1322s Sep 10 15:07:50 autopkgtest sshd[936]: Server listening on :: port 22. 1322s Sep 10 15:07:50 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 1322s Sep 10 15:07:51 autopkgtest sshd[938]: Accepted publickey for ubuntu from 10.136.6.184 port 60774 ssh2: RSA SHA256:h+sR5tlNZDfTFbz7cAH7wlRKfPAD8MpCdKJaoGeL2vg 1322s Sep 10 15:07:51 autopkgtest sshd[938]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 1322s Sep 10 15:07:51 autopkgtest sshd[938]: pam_systemd(sshd:session): New sd-bus connection (system-bus-pam-systemd-938) opened. 1322s Sep 10 15:07:51 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 1322s Sep 10 15:07:51 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 1322s Sep 10 15:07:51 autopkgtest systemd-logind[791]: New session 1 of user ubuntu. 1322s Sep 10 15:07:51 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 1322s Sep 10 15:07:51 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 1322s Sep 10 15:07:51 autopkgtest (systemd)[942]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 1322s Sep 10 15:07:51 autopkgtest systemd-logind[791]: New session 2 of user ubuntu. 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Queued start job for default target default.target. 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Created slice app.slice - User Application Slice. 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Reached target paths.target - Paths. 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Reached target timers.target - Timers. 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Starting dbus.socket - D-Bus User Message Bus Socket... 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Listening on keyboxd.socket - GnuPG public key management service. 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Listening on dbus.socket - D-Bus User Message Bus Socket. 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Reached target sockets.target - Sockets. 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Reached target basic.target - Basic System. 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Reached target default.target - Main User Target. 1322s Sep 10 15:07:51 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 1322s Sep 10 15:07:51 autopkgtest systemd[942]: Startup finished in 186ms. 1322s Sep 10 15:07:51 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 1322s Sep 10 15:08:19 autopkgtest systemd-timesyncd[394]: Contacted time server 185.125.190.56:123 (ntp.ubuntu.com). 1322s Sep 10 15:08:19 autopkgtest systemd-timesyncd[394]: Initial clock synchronization to Tue 2024-09-10 15:08:19.599965 UTC. 1322s Sep 10 15:08:21 autopkgtest sudo[971]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 1322s Sep 10 15:08:21 autopkgtest sudo[971]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:08:21 autopkgtest sudo[971]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:08:24 autopkgtest sudo[976]: 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' 1322s Sep 10 15:08:24 autopkgtest sudo[976]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:08:25 autopkgtest sudo[976]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:08:36 autopkgtest sudo[988]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.zfQnqm 1322s Sep 10 15:08:36 autopkgtest sudo[988]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:08:36 autopkgtest sudo[988]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:08:45 autopkgtest sudo[998]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.zfQnqm/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.zfQnqm/autopkgtest-reboot' 1322s Sep 10 15:08:45 autopkgtest sudo[998]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:08:45 autopkgtest sudo[998]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:08:57 autopkgtest sudo[1011]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.zfQnqm/autopkgtest-reboot 1322s Sep 10 15:08:57 autopkgtest sudo[1011]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:08:57 autopkgtest sudo[1011]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:09:14 autopkgtest sudo[1021]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.zfQnqm/autopkgtest-reboot /tmp/autopkgtest-reboot 1322s Sep 10 15:09:14 autopkgtest sudo[1021]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:09:14 autopkgtest sudo[1021]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:09:14 autopkgtest sudo[1031]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.zfQnqm/autopkgtest-reboot /sbin/autopkgtest-reboot 1322s Sep 10 15:09:14 autopkgtest sudo[1031]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:09:14 autopkgtest sudo[1031]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:09:14 autopkgtest sudo[1041]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.zfQnqm 1322s Sep 10 15:09:14 autopkgtest sudo[1041]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:09:14 autopkgtest sudo[1041]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:09:29 autopkgtest sudo[1051]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.zfQnqm/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.zfQnqm/autopkgtest-reboot-prepare' 1322s Sep 10 15:09:29 autopkgtest sudo[1051]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:09:29 autopkgtest sudo[1051]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:09:35 autopkgtest sudo[1063]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.zfQnqm/autopkgtest-reboot-prepare 1322s Sep 10 15:09:35 autopkgtest sudo[1063]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:09:35 autopkgtest sudo[1063]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:09:35 autopkgtest sudo[1073]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.zfQnqm/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 1322s Sep 10 15:09:35 autopkgtest sudo[1073]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:09:35 autopkgtest sudo[1073]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:09:35 autopkgtest sudo[1083]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 1322s Sep 10 15:09:35 autopkgtest sudo[1083]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:09:35 autopkgtest sudo[1083]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:09:44 autopkgtest sudo[1093]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 1322s Sep 10 15:09:44 autopkgtest sudo[1093]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:09:44 autopkgtest sudo[1093]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:10:03 autopkgtest systemd[1]: Starting sysstat-collect.service - system activity accounting tool... 1322s Sep 10 15:10:03 autopkgtest systemd[1]: sysstat-collect.service: Deactivated successfully. 1322s Sep 10 15:10:03 autopkgtest systemd[1]: Finished sysstat-collect.service - system activity accounting tool. 1322s Sep 10 15:10:07 autopkgtest sudo[1107]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.zfQnqm/testbed-packages' 1322s Sep 10 15:10:07 autopkgtest sudo[1107]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:10:07 autopkgtest sudo[1107]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:10:37 autopkgtest sudo[1118]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.zfQnqm/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.zfQnqm/autopkgtest-reboot' 1322s Sep 10 15:10:52 autopkgtest sudo[1139]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:10:52 autopkgtest sudo[1139]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:10:53 autopkgtest sudo[1151]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.zfQnqm/autopkgtest-reboot 1322s Sep 10 15:10:53 autopkgtest sudo[1151]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:10:53 autopkgtest sudo[1151]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:04 autopkgtest sudo[1161]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.zfQnqm/autopkgtest-reboot /tmp/autopkgtest-reboot 1322s Sep 10 15:11:04 autopkgtest sudo[1161]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:04 autopkgtest sudo[1161]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:05 autopkgtest sudo[1171]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.zfQnqm/autopkgtest-reboot /sbin/autopkgtest-reboot 1322s Sep 10 15:11:05 autopkgtest sudo[1171]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:05 autopkgtest sudo[1171]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:06 autopkgtest sudo[1181]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.zfQnqm 1322s Sep 10 15:11:06 autopkgtest sudo[1181]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:06 autopkgtest sudo[1181]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:07 autopkgtest sudo[1191]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.zfQnqm/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.zfQnqm/autopkgtest-reboot-prepare' 1322s Sep 10 15:11:07 autopkgtest sudo[1191]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:07 autopkgtest sudo[1191]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:08 autopkgtest sudo[1203]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.zfQnqm/autopkgtest-reboot-prepare 1322s Sep 10 15:11:08 autopkgtest sudo[1203]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:08 autopkgtest sudo[1203]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:09 autopkgtest sudo[1213]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.zfQnqm/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 1322s Sep 10 15:11:09 autopkgtest sudo[1213]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:09 autopkgtest sudo[1213]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:09 autopkgtest sudo[1223]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 1322s Sep 10 15:11:09 autopkgtest sudo[1223]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:09 autopkgtest sudo[1223]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:15 autopkgtest sudo[1233]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 1322s Sep 10 15:11:15 autopkgtest sudo[1233]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:15 autopkgtest sudo[1233]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:20 autopkgtest sudo[1242]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.zfQnqm 1322s Sep 10 15:11:20 autopkgtest sudo[1242]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:20 autopkgtest sudo[1242]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:24 autopkgtest sudo[1252]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.zfQnqm/2-autopkgtest-satdep.deb' 1322s Sep 10 15:11:24 autopkgtest sudo[1252]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:24 autopkgtest sudo[1252]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:26 autopkgtest sudo[1263]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.zfQnqm/2-autopkgtest-satdep.deb 1322s Sep 10 15:11:26 autopkgtest sudo[1263]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:26 autopkgtest sudo[1263]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:26 autopkgtest sudo[1273]: 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.zfQnqm/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' 1322s Sep 10 15:11:26 autopkgtest sudo[1273]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:30 autopkgtest systemd[1]: Reload requested from client PID 1513 ('systemctl') (unit session-1.scope)... 1322s Sep 10 15:11:30 autopkgtest systemd[1]: Reloading... 1322s Sep 10 15:11:30 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. 1322s Sep 10 15:11:30 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. 1322s Sep 10 15:11:30 autopkgtest systemd[1]: Reloading finished in 213 ms. 1322s Sep 10 15:11:31 autopkgtest systemd[1]: Starting apt-daily-upgrade.service - Daily apt upgrade and clean activities... 1322s Sep 10 15:11:31 autopkgtest systemd[1]: apt-daily-upgrade.service: Deactivated successfully. 1322s Sep 10 15:11:31 autopkgtest systemd[1]: Finished apt-daily-upgrade.service - Daily apt upgrade and clean activities. 1322s Sep 10 15:11:31 autopkgtest systemd[1]: Reload requested from client PID 1588 ('systemctl') (unit session-1.scope)... 1322s Sep 10 15:11:31 autopkgtest systemd[1]: Reloading... 1322s Sep 10 15:11:31 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. 1322s Sep 10 15:11:31 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. 1322s Sep 10 15:11:31 autopkgtest systemd[1]: Reloading finished in 198 ms. 1322s Sep 10 15:11:31 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 1322s Sep 10 15:11:31 autopkgtest tgtd[1633]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 1322s Sep 10 15:11:31 autopkgtest tgtd[1633]: tgtd: work_timer_start(146) use timer_fd based scheduler 1322s Sep 10 15:11:31 autopkgtest tgtd[1633]: tgtd: bs_init(387) use signalfd notification 1322s Sep 10 15:11:31 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 1322s Sep 10 15:11:31 autopkgtest systemd[1]: Reload requested from client PID 1661 ('systemctl') (unit session-1.scope)... 1322s Sep 10 15:11:31 autopkgtest systemd[1]: Reloading... 1322s Sep 10 15:11:31 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. 1322s Sep 10 15:11:31 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. 1322s Sep 10 15:11:32 autopkgtest systemd[1]: Reloading finished in 203 ms. 1322s Sep 10 15:11:32 autopkgtest systemd[1]: Reload requested from client PID 1703 ('systemctl') (unit session-1.scope)... 1322s Sep 10 15:11:32 autopkgtest systemd[1]: Reloading... 1322s Sep 10 15:11:32 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. 1322s Sep 10 15:11:32 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. 1322s Sep 10 15:11:32 autopkgtest systemd[1]: Reloading finished in 187 ms. 1322s Sep 10 15:11:32 autopkgtest systemd[1]: Reload requested from client PID 1748 ('systemctl') (unit session-1.scope)... 1322s Sep 10 15:11:32 autopkgtest systemd[1]: Reloading... 1322s Sep 10 15:11:32 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. 1322s Sep 10 15:11:32 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. 1322s Sep 10 15:11:32 autopkgtest systemd[1]: Reloading finished in 202 ms. 1322s Sep 10 15:11:32 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 1322s Sep 10 15:11:32 autopkgtest systemd[1]: Reload requested from client PID 1798 ('systemctl') (unit session-1.scope)... 1322s Sep 10 15:11:32 autopkgtest systemd[1]: Reloading... 1322s Sep 10 15:11:33 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. 1322s Sep 10 15:11:33 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. 1322s Sep 10 15:11:33 autopkgtest systemd[1]: Reloading finished in 209 ms. 1322s Sep 10 15:11:33 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 1322s Sep 10 15:11:33 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 1322s Sep 10 15:11:33 autopkgtest systemd[1]: Reload requested from client PID 1852 ('systemctl') (unit session-1.scope)... 1322s Sep 10 15:11:33 autopkgtest systemd[1]: Reloading... 1322s Sep 10 15:11:33 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. 1322s Sep 10 15:11:33 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. 1322s Sep 10 15:11:33 autopkgtest systemd[1]: Reloading finished in 178 ms. 1322s Sep 10 15:11:45 autopkgtest sudo[1273]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:46 autopkgtest sudo[5722]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 1322s Sep 10 15:11:46 autopkgtest sudo[5722]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:46 autopkgtest sudo[5722]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:46 autopkgtest sudo[5732]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 1322s Sep 10 15:11:46 autopkgtest sudo[5732]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:46 autopkgtest sudo[5732]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:47 autopkgtest sudo[5742]: 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 1322s Sep 10 15:11:47 autopkgtest sudo[5742]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:48 autopkgtest sudo[5742]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:49 autopkgtest sudo[5755]: 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 1322s Sep 10 15:11:49 autopkgtest sudo[5755]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:49 autopkgtest sudo[5755]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:50 autopkgtest sudo[5767]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 1322s Sep 10 15:11:50 autopkgtest sudo[5767]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:50 autopkgtest sudo[5767]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:50 autopkgtest sudo[5779]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 1322s Sep 10 15:11:50 autopkgtest sudo[5779]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:50 autopkgtest sudo[5779]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:51 autopkgtest sudo[5789]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.zfQnqm/tgtbasedmpaths-packages.all' 1322s Sep 10 15:11:51 autopkgtest sudo[5789]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1322s Sep 10 15:11:51 autopkgtest sudo[5789]: pam_unix(sudo:session): session closed for user root 1322s Sep 10 15:11:51 autopkgtest sudo[5800]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 1326s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1326s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1326s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 1326s latency : target=0, window=0, percentile=100.00%, depth=1 1326s 1326s Run status group 0 (all jobs): 1326s WRITE: bw=121MiB/s (127MB/s), 121MiB/s-121MiB/s (127MB/s-127MB/s), io=87.5MiB (91.8MB), run=725-725msec 1326s 1326s Disk stats (read/write): 1326s dm-0: ios=1/1199, sectors=8/153472, merge=0/0, ticks=1/582, in_queue=583, util=73.41%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/161, aggrin_queue=162, aggrutil=71.48% 1326s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 1326s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 1326s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 1326s sda: ios=1/1402, sectors=8/179280, merge=0/0, ticks=0/647, in_queue=648, util=71.48% 1326s + echo Starting the path changes in background 1326s Starting the path changes in background 1326s + date +Pre FIO %H:%M:%S.%N 1326s Pre FIO 15:12:15.863705800 1326s + fio --max-jobs=4 /tmp/autopkgtest.zfQnqm/tgtbasedmpaths-artifacts/path-change-check.fio 1326s 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 1326s fio-3.37 1326s Starting 1 thread 1507s 1507s verify-phase: (groupid=0, jobs=1): err= 0: pid=6141: Tue Sep 10 15:15:16 2024 1507s read: IOPS=4991, BW=312MiB/s (327MB/s)(54.8GiB/180001msec) 1507s clat (usec): min=71, max=45325, avg=174.30, stdev=166.57 1507s lat (usec): min=71, max=45325, avg=174.42, stdev=166.58 1507s clat percentiles (usec): 1507s | 1.00th=[ 88], 5.00th=[ 104], 10.00th=[ 114], 20.00th=[ 127], 1507s | 30.00th=[ 139], 40.00th=[ 151], 50.00th=[ 161], 60.00th=[ 172], 1507s | 70.00th=[ 182], 80.00th=[ 196], 90.00th=[ 217], 95.00th=[ 237], 1507s | 99.00th=[ 750], 99.50th=[ 1090], 99.90th=[ 1827], 99.95th=[ 2278], 1507s | 99.99th=[ 2999] 1507s bw ( KiB/s): min=60672, max=500736, per=100.00%, avg=319856.00, stdev=59830.10, samples=359 1507s iops : min= 948, max= 7824, avg=4997.72, stdev=934.84, samples=359 1507s lat (usec) : 100=3.84%, 250=92.66%, 500=2.22%, 750=0.28%, 1000=0.40% 1507s lat (msec) : 2=0.52%, 4=0.08%, 10=0.01%, 20=0.01%, 50=0.01% 1507s cpu : usr=13.99%, sys=6.66%, ctx=898626, majf=0, minf=1 1507s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 1507s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1507s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1507s issued rwts: total=898465,0,0,0 short=0,0,0,0 dropped=0,0,0,0 1507s latency : target=0, window=0, percentile=100.00%, depth=1 1507s 1507s Run status group 0 (all jobs): 1507s READ: bw=312MiB/s (327MB/s), 312MiB/s-312MiB/s (327MB/s-327MB/s), io=54.8GiB (58.9GB), run=180001-180001msec 1507s 1507s Disk stats (read/write): 1507s dm-0: ios=898754/10, sectors=114954040/12928, merge=0/9, ticks=154554/172, in_queue=154864, util=81.16%, aggrios=54831/2, aggsectors=7012302/3232, aggrmerge=0/0, aggrticks=10267/8, aggrin_queue=10275, aggrutil=74.94% 1507s sdd: ios=79273/0, sectors=10139648/0, merge=0/0, ticks=16809/0, in_queue=16809, util=31.63% 1507s sdb: ios=44639/0, sectors=5705272/0, merge=0/0, ticks=8224/0, in_queue=8224, util=37.44% 1507s sdc: ios=45405/0, sectors=5807744/0, merge=0/0, ticks=8122/0, in_queue=8122, util=25.37% 1507s sda: ios=50010/9, sectors=6396544/12928, merge=0/0, ticks=7914/33, in_queue=7947, util=74.94% 1507s Post FIO 15:15:16.202651765 1507s FIO verify test with changing paths - OK 1507s Report log of background activity 1507s + date +Post FIO %H:%M:%S.%N 1507s + echo FIO verify test with changing paths - OK 1507s + echo Report log of background activity 1507s + cat /tmp/autopkgtest.zfQnqm/tgtbasedmpaths-artifacts/test-background.log 1507s + iscsiadm --mode session 1507s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s + sleep 10s 1507s + date +MP report (expect 4) %H:%M:%S.%N 1507s MP report (expect 4) 15:12:25.870124376 1507s + multipath -ll 1507s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1507s size=100M features='0' hwhandler='0' wp=rw 1507s |-+- policy='service-time 0' prio=1 status=active 1507s | `- 0:0:0:1 sda 8:0 active ready running 1507s |-+- policy='service-time 0' prio=1 status=enabled 1507s | `- 1:0:0:1 sdb 8:16 active ready running 1507s |-+- policy='service-time 0' prio=1 status=enabled 1507s | `- 2:0:0:1 sdc 8:32 active ready running 1507s `-+- policy='service-time 0' prio=1 status=enabled 1507s `- 3:0:0:1 sdd 8:48 active ready running 1507s + date +UN-plug path 1 %H:%M:%S.%N 1507s UN-plug path 1 15:12:25.892858358 1507s + iscsiadm --mode session -r 1 -u 1507s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1507s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1507s + iscsiadm --mode session 1507s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s + sleep 10s 1507s + date +MP report (expect 3) %H:%M:%S.%N 1507s MP report (expect 3) 15:12:35.989394423 1507s + multipath -ll 1507s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1507s size=100M features='0' hwhandler='0' wp=rw 1507s |-+- policy='service-time 0' prio=1 status=active 1507s | `- 1:0:0:1 sdb 8:16 active ready running 1507s |-+- policy='service-time 0' prio=1 status=enabled 1507s | `- 2:0:0:1 sdc 8:32 active ready running 1507s `-+- policy='service-time 0' prio=1 status=enabled 1507s `- 3:0:0:1 sdd 8:48 active ready running 1507s + date +UN-plug path 2 %H:%M:%S.%N 1507s UN-plug path 2 15:12:36.016967392 1507s + iscsiadm --mode session -r 2 -u 1507s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1507s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1507s + iscsiadm --mode session 1507s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s + sleep 10s 1507s + date +MP report (expect 2) %H:%M:%S.%N 1507s MP report (expect 2) 15:12:46.116947351 1507s + multipath -ll 1507s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1507s size=100M features='0' hwhandler='0' wp=rw 1507s |-+- policy='service-time 0' prio=1 status=active 1507s | `- 2:0:0:1 sdc 8:32 active ready running 1507s `-+- policy='service-time 0' prio=1 status=enabled 1507s `- 3:0:0:1 sdd 8:48 active ready running 1507s + date +UN-plug path 3 %H:%M:%S.%N 1507s UN-plug path 3 15:12:46.141214561 1507s + iscsiadm --mode session -r 3 -u 1507s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1507s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1507s + iscsiadm --mode session 1507s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s + sleep 10s 1507s + date +MP report (expect 1) %H:%M:%S.%N 1507s MP report (expect 1) 15:12:56.236876699 1507s + multipath -ll 1507s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1507s size=100M features='0' hwhandler='0' wp=rw 1507s `-+- policy='service-time 0' prio=1 status=active 1507s `- 3:0:0:1 sdd 8:48 active ready running 1507s + date +Add paths 5/6/7/8 %H:%M:%S.%N 1507s Add paths 5/6/7/8 15:12:56.248886420 1507s + iscsiadm --mode session -r 4 --op new 1507s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1507s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1507s + iscsiadm --mode session -r 4 --op new 1507s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1507s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1507s + iscsiadm --mode session -r 4 --op new 1507s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1507s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1507s + iscsiadm --mode session -r 4 --op new 1507s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1507s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1507s + iscsiadm --mode session 1507s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s + sleep 10s 1507s + date +MP report (expect 5) %H:%M:%S.%N 1507s MP report (expect 5) 15:13:06.330292668 1507s + multipath -ll 1507s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1507s size=100M features='0' hwhandler='0' wp=rw 1507s |-+- policy='service-time 0' prio=1 status=active 1507s | `- 3:0:0:1 sdd 8:48 active ready running 1507s |-+- policy='service-time 0' prio=1 status=enabled 1507s | `- 0:0:0:1 sda 8:0 active ready running 1507s |-+- policy='service-time 0' prio=1 status=enabled 1507s | `- 1:0:0:1 sdb 8:16 active ready running 1507s |-+- policy='service-time 0' prio=1 status=enabled 1507s | `- 2:0:0:1 sdc 8:32 active ready running 1507s `-+- policy='service-time 0' prio=1 status=enabled 1507s `- 4:0:0:1 sde 8:64 active ready running 1507s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 1507s UN-plug multiple paths 4/7/8 15:13:06.358482615 1507s + iscsiadm --mode session -r 4 -u 1507s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1507s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1507s + iscsiadm --mode session -r 7 -u 1507s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1507s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1507s + iscsiadm --mode session -r 8 -u 1507s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1507s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1507s + iscsiadm --mode session 1507s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1507s + sleep 10s 1507s + date +Restart multipath daemon %H:%M:%S.%N 1507s Restart multipath daemon 15:13:16.654807018 1507s + systemctl restart multipathd 1507s + sleep 10s 1507s + date +Final background report (expect 2) %H:%M:%S.%N 1507s Final background report (expect 2) 15:13:26.756017211 1507s + multipath -ll 1507s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1507s size=100M features='0' hwhandler='0' wp=rw 1507s |-+- policy='service-time 0' prio=1 status=active 1507s | `- 0:0:0:1 sda 8:0 active ready running 1507s `-+- policy='service-time 0' prio=1 status=enabled 1507s `- 1:0:0:1 sdb 8:16 active ready running 1507s Final stats 1507s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1507s iSCSI SNMP: 1507s txdata_octets: 32497608 1507s rxdata_octets: 44346946736 1507s noptx_pdus: 0 1507s scsicmd_pdus: 676766 1507s tmfcmd_pdus: 0 1507s login_pdus: 0 1507s text_pdus: 0 1507s dataout_pdus: 0 1507s logout_pdus: 0 1507s snack_pdus: 0 1507s noprx_pdus: 0 1507s scsirsp_pdus: 676766 1507s tmfrsp_pdus: 0 1507s textrsp_pdus: 0 1507s datain_pdus: 676732 1507s logoutrsp_pdus: 0 1507s r2t_pdus: 0 1507s async_pdus: 0 1507s rjt_pdus: 0 1507s digest_err: 0 1507s timeout_err: 0 1507s iSCSI Extended: 1507s tx_sendpage_failures: 0 1507s rx_discontiguous_hdr: 0 1507s eh_abort_cnt: 0 1507s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1507s iSCSI SNMP: 1507s txdata_octets: 6744 1507s rxdata_octets: 1515328 1507s noptx_pdus: 0 1507s scsicmd_pdus: 111 1507s tmfcmd_pdus: 0 1507s login_pdus: 0 1507s text_pdus: 0 1507s dataout_pdus: 0 1507s logout_pdus: 0 1507s snack_pdus: 0 1507s noprx_pdus: 0 1507s scsirsp_pdus: 111 1507s tmfrsp_pdus: 0 1507s textrsp_pdus: 0 1507s datain_pdus: 87 1507s logoutrsp_pdus: 0 1507s r2t_pdus: 0 1507s async_pdus: 0 1507s rjt_pdus: 0 1507s digest_err: 0 1507s timeout_err:+ sync 1507s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1507s + echo Final stats 1507s + iscsiadm --mode session --stats 1507s + journalctl --no-pager -u multipathd 1507s + echo Check final path status 1507s + multipath -ll 1507s + multipath -ll 1507s + grep --count status= 1507s + diskc=2 1507s + multipath -ll 1507s + grep --count status=active 1507s + diska=1 1507s + multipath -ll 1507s + grep --count status=enabled 1507s 0 1507s iSCSI Extended: 1507s tx_sendpage_failures: 0 1507s rx_discontiguous_hdr: 0 1507s eh_abort_cnt: 0 1507s Sep 09 15:16:16 ubuntu multipathd[335]: multipathd v0.9.9: start up 1507s Sep 09 15:16:16 ubuntu multipathd[335]: reconfigure: setting up paths and maps 1507s Sep 09 15:16:16 ubuntu multipathd[335]: _check_bindings_file: failed to read header from /etc/multipath/bindings 1507s Sep 09 15:16:16 ubuntu multipathd[335]: updated bindings file /etc/multipath/bindings 1507s Sep 09 15:16:16 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1507s Sep 09 15:18:57 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1507s Sep 09 15:18:57 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i multipathd[335]: multipathd: shut down 1507s Sep 09 15:18:57 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 1507s Sep 09 15:18:57 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1507s -- Boot 5d97a3f9531d45eeacad9f45ba3ff199 -- 1507s Sep 09 15:19:09 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i multipathd[280]: multipathd v0.9.9: start up 1507s Sep 09 15:19:09 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i multipathd[280]: reconfigure: setting up paths and maps 1507s Sep 09 15:19:09 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1507s Sep 09 15:19:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i multipathd[280]: multipathd: shut down 1507s Sep 09 15:19:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1507s Sep 09 15:19:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 1507s Sep 09 15:19:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1507s -- Boot 8903232fc6b74c8396302f85a35ad672 -- 1507s Sep 10 15:04:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1507s Sep 10 15:04:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i multipathd[328]: multipathd v0.9.9: start up 1507s Sep 10 15:04:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i multipathd[328]: reconfigure: setting up paths and maps 1507s Sep 10 15:04:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1507s Sep 10 15:07:26 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1507s Sep 10 15:07:26 autopkgtest multipathd[328]: multipathd: shut down 1507s Sep 10 15:07:26 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 1507s Sep 10 15:07:26 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1507s -- Boot e39b18793ddf499bb713306f41034475 -- 1507s Sep 10 15:07:38 autopkgtest multipathd[313]: multipathd v0.9.9: start up 1507s Sep 10 15:07:38 autopkgtest multipathd[313]: reconfigure: setting up paths and maps 1507s Sep 10 15:07:38 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1507s Sep 10 15:12:06 autopkgtest multipathd[313]: updated bindings file /etc/multipath/bindings 1507s Sep 10 15:12:06 autopkgtest multipathd[313]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 1507s Sep 10 15:12:06 autopkgtest multipathd[313]: sda [8:0]: path added to devmap mpatha 1507s Sep 10 15:12:06 autopkgtest multipathd[313]: mpatha: performing delayed actions 1507s Sep 10 15:12:06 autopkgtest multipathd[313]: 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:32 1 service-time 0 1 1 8:48 1] 1507s Sep 10 15:12:25 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 1507s Sep 10 15:12:25 autopkgtest multipathd[313]: check_removed_paths: sda: freeing path in removed state 1507s Sep 10 15:12:25 autopkgtest multipathd[313]: 8:0: path removed from map mpatha 1507s Sep 10 15:12:36 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 1507s Sep 10 15:12:36 autopkgtest multipathd[313]: check_removed_paths: sdb: freeing path in removed state 1507s Sep 10 15:12:36 autopkgtest multipathd[313]: 8:16: path removed from map mpatha 1507s Sep 10 15:12:46 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 1507s Sep 10 15:12:46 autopkgtest multipathd[313]: check_removed_paths: sdc: freeing path in removed state 1507s Sep 10 15:12:46 autopkgtest multipathd[313]: 8:32: path removed from map mpatha 1507s Sep 10 15:12:56 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1] 1507s Sep 10 15:12:56 autopkgtest multipathd[313]: sda [8:0]: path added to devmap mpatha 1507s Sep 10 15:12:56 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 1507s Sep 10 15:12:56 autopkgtest multipathd[313]: sdb [8:16]: path added to devmap mpatha 1507s Sep 10 15:12:56 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 1507s Sep 10 15:12:56 autopkgtest multipathd[313]: sdc [8:32]: path added to devmap mpatha 1507s Sep 10 15:12:56 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 1507s Sep 10 15:12:56 autopkgtest multipathd[313]: sde [8:64]: path added to devmap mpatha 1507s Sep 10 15:13:06 autopkgtest multipathd[313]: 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:32 1 service-time 0 1 1 8:64 1] 1507s Sep 10 15:13:06 autopkgtest multipathd[313]: check_removed_paths: sdd: freeing path in removed state 1507s Sep 10 15:13:06 autopkgtest multipathd[313]: 8:48: path removed from map mpatha 1507s Sep 10 15:13:06 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:64 1] 1507s Sep 10 15:13:06 autopkgtest multipathd[313]: check_removed_paths: sdc: freeing path in removed state 1507s Sep 10 15:13:06 autopkgtest multipathd[313]: 8:32: path removed from map mpatha 1507s Sep 10 15:13:06 autopkgtest multipathd[313]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 1507s Sep 10 15:13:06 autopkgtest multipathd[313]: check_removed_paths: sde: freeing path in removed state 1507s Sep 10 15:13:06 autopkgtest multipathd[313]: 8:64: path removed from map mpatha 1507s Sep 10 15:13:16 autopkgtest multipathd[313]: multipathd: shut down 1507s Sep 10 15:13:16 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1507s Sep 10 15:13:16 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 1507s Sep 10 15:13:16 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1507s Sep 10 15:13:16 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1507s Sep 10 15:13:16 autopkgtest multipathd[6499]: multipathd v0.9.9: start up 1507s Sep 10 15:13:16 autopkgtest multipathd[6499]: reconfigure: setting up paths and maps 1507s Sep 10 15:13:16 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1507s Check final path status 1507s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1507s size=100M features='0' hwhandler='0' wp=rw 1507s |-+- policy='service-time 0' prio=1 status=active 1507s | `- 0:0:0:1 sda 8:0 active ready running 1507s `-+- policy='service-time 0' prio=1 status=enabled 1507s `- 1:0:0:1 sdb 8:16 active ready running 1507s + diske=1 1507s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 1507s + echo OK 1507s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 1507s OK 1507s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 1507s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1507s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1507s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1507s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1507s autopkgtest [15:15:16]: test tgtbasedmpaths: -----------------------] 1525s autopkgtest [15:15:34]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 1525s tgtbasedmpaths PASS 1531s autopkgtest [15:15:40]: @@@@@@@@@@@@@@@@@@@@ summary 1531s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 1531s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 1531s kpartx-file-loopback PASS 1531s tgtbasedmpaths PASS 1609s nova [W] Using flock in prodstack6-ppc64el 1609s flock: timeout while waiting to get lock 1609s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240910-145002-juju-7f2275-prod-proposed-migration-environment-2-06506f14-00d0-4698-bb25-06ac22aece33 from image adt/ubuntu-oracular-ppc64el-server-20240909.img (UUID 15f8af18-895e-46e8-b444-c48790acc71b)... 1609s nova [W] Using flock in prodstack6-ppc64el 1609s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240910-145002-juju-7f2275-prod-proposed-migration-environment-2-06506f14-00d0-4698-bb25-06ac22aece33 from image adt/ubuntu-oracular-ppc64el-server-20240909.img (UUID 15f8af18-895e-46e8-b444-c48790acc71b)...