0s autopkgtest [23:02:01]: starting date and time: 2024-09-11 23:02:01+0000 0s autopkgtest [23:02:01]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [23:02:01]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.160ihtu3/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:qemu --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=qemu/1:9.0.2+ds-4ubuntu5 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big-ppc64el --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos03-ppc64el-12.secgroup --name adt-oracular-ppc64el-multipath-tools-20240911-230159-juju-7f2275-prod-proposed-migration-environment-2-a14f07f4-836c-4c2a-9b59-fafa99654ee3 --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/ 136s autopkgtest [23:04:17]: testbed dpkg architecture: ppc64el 136s autopkgtest [23:04:17]: testbed apt version: 2.9.8 136s autopkgtest [23:04:17]: @@@@@@@@@@@@@@@@@@@@ test bed setup 137s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 138s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [10.9 kB] 138s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [260 kB] 138s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [34.4 kB] 138s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4496 B] 138s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [51.9 kB] 138s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [1332 B] 138s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1372 B] 138s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 138s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [219 kB] 138s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [7096 B] 138s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [764 B] 138s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 140s Fetched 718 kB in 1s (943 kB/s) 140s Reading package lists... 143s Reading package lists... 143s Building dependency tree... 143s Reading state information... 143s Calculating upgrade... 143s The following packages will be upgraded: 143s gcc-14-base libatomic1 libgcc-s1 libnss-systemd libpam-systemd libstdc++6 143s libsystemd-shared libsystemd0 libudev1 systemd systemd-cryptsetup 143s systemd-dev systemd-resolved systemd-sysv systemd-timesyncd udev vim-common 143s vim-tiny xxd 143s 19 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 143s Need to get 12.9 MB of archives. 143s After this operation, 12.3 kB of additional disk space will be used. 143s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnss-systemd ppc64el 256.5-2ubuntu2 [214 kB] 144s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-dev all 256.5-2ubuntu2 [114 kB] 144s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-timesyncd ppc64el 256.5-2ubuntu2 [42.4 kB] 144s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-resolved ppc64el 256.5-2ubuntu2 [368 kB] 144s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-cryptsetup ppc64el 256.5-2ubuntu2 [127 kB] 144s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsystemd-shared ppc64el 256.5-2ubuntu2 [2502 kB] 144s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsystemd0 ppc64el 256.5-2ubuntu2 [564 kB] 144s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-sysv ppc64el 256.5-2ubuntu2 [11.9 kB] 144s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpam-systemd ppc64el 256.5-2ubuntu2 [326 kB] 144s Get:10 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd ppc64el 256.5-2ubuntu2 [3746 kB] 145s Get:11 http://ftpmaster.internal/ubuntu oracular/main ppc64el udev ppc64el 256.5-2ubuntu2 [2140 kB] 145s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el libudev1 ppc64el 256.5-2ubuntu2 [223 kB] 145s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libatomic1 ppc64el 14.2.0-4ubuntu2 [10.7 kB] 145s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el gcc-14-base ppc64el 14.2.0-4ubuntu2 [50.8 kB] 145s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libstdc++6 ppc64el 14.2.0-4ubuntu2 [886 kB] 145s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgcc-s1 ppc64el 14.2.0-4ubuntu2 [39.1 kB] 145s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el vim-tiny ppc64el 2:9.1.0496-1ubuntu5 [1068 kB] 146s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el vim-common all 2:9.1.0496-1ubuntu5 [387 kB] 146s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el xxd ppc64el 2:9.1.0496-1ubuntu5 [64.8 kB] 146s Fetched 12.9 MB in 3s (5086 kB/s) 146s (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 ... 72442 files and directories currently installed.) 146s Preparing to unpack .../0-libnss-systemd_256.5-2ubuntu2_ppc64el.deb ... 146s Unpacking libnss-systemd:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 146s Preparing to unpack .../1-systemd-dev_256.5-2ubuntu2_all.deb ... 146s Unpacking systemd-dev (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 146s Preparing to unpack .../2-systemd-timesyncd_256.5-2ubuntu2_ppc64el.deb ... 146s Unpacking systemd-timesyncd (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 146s Preparing to unpack .../3-systemd-resolved_256.5-2ubuntu2_ppc64el.deb ... 146s Unpacking systemd-resolved (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 146s Preparing to unpack .../4-systemd-cryptsetup_256.5-2ubuntu2_ppc64el.deb ... 146s Unpacking systemd-cryptsetup (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 146s Preparing to unpack .../5-libsystemd-shared_256.5-2ubuntu2_ppc64el.deb ... 146s Unpacking libsystemd-shared:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 147s Preparing to unpack .../6-libsystemd0_256.5-2ubuntu2_ppc64el.deb ... 147s Unpacking libsystemd0:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 147s Setting up libsystemd0:ppc64el (256.5-2ubuntu2) ... 147s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72442 files and directories currently installed.) 147s Preparing to unpack .../systemd-sysv_256.5-2ubuntu2_ppc64el.deb ... 147s Unpacking systemd-sysv (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 147s Preparing to unpack .../libpam-systemd_256.5-2ubuntu2_ppc64el.deb ... 147s Unpacking libpam-systemd:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 147s Preparing to unpack .../systemd_256.5-2ubuntu2_ppc64el.deb ... 147s Unpacking systemd (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 147s Preparing to unpack .../udev_256.5-2ubuntu2_ppc64el.deb ... 147s Unpacking udev (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 147s Preparing to unpack .../libudev1_256.5-2ubuntu2_ppc64el.deb ... 147s Unpacking libudev1:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 147s Setting up libudev1:ppc64el (256.5-2ubuntu2) ... 147s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72442 files and directories currently installed.) 147s Preparing to unpack .../libatomic1_14.2.0-4ubuntu2_ppc64el.deb ... 147s Unpacking libatomic1:ppc64el (14.2.0-4ubuntu2) over (14.2.0-4ubuntu1) ... 147s Preparing to unpack .../gcc-14-base_14.2.0-4ubuntu2_ppc64el.deb ... 147s Unpacking gcc-14-base:ppc64el (14.2.0-4ubuntu2) over (14.2.0-4ubuntu1) ... 147s Setting up gcc-14-base:ppc64el (14.2.0-4ubuntu2) ... 147s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72442 files and directories currently installed.) 147s Preparing to unpack .../libstdc++6_14.2.0-4ubuntu2_ppc64el.deb ... 147s Unpacking libstdc++6:ppc64el (14.2.0-4ubuntu2) over (14.2.0-4ubuntu1) ... 147s Setting up libstdc++6:ppc64el (14.2.0-4ubuntu2) ... 147s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72442 files and directories currently installed.) 147s Preparing to unpack .../libgcc-s1_14.2.0-4ubuntu2_ppc64el.deb ... 147s Unpacking libgcc-s1:ppc64el (14.2.0-4ubuntu2) over (14.2.0-4ubuntu1) ... 147s Setting up libgcc-s1:ppc64el (14.2.0-4ubuntu2) ... 148s (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 ... 72442 files and directories currently installed.) 148s Preparing to unpack .../vim-tiny_2%3a9.1.0496-1ubuntu5_ppc64el.deb ... 148s Unpacking vim-tiny (2:9.1.0496-1ubuntu5) over (2:9.1.0496-1ubuntu4) ... 148s Preparing to unpack .../vim-common_2%3a9.1.0496-1ubuntu5_all.deb ... 148s Unpacking vim-common (2:9.1.0496-1ubuntu5) over (2:9.1.0496-1ubuntu4) ... 148s Preparing to unpack .../xxd_2%3a9.1.0496-1ubuntu5_ppc64el.deb ... 148s Unpacking xxd (2:9.1.0496-1ubuntu5) over (2:9.1.0496-1ubuntu4) ... 148s Setting up systemd-dev (256.5-2ubuntu2) ... 148s Setting up xxd (2:9.1.0496-1ubuntu5) ... 148s Setting up vim-common (2:9.1.0496-1ubuntu5) ... 148s Setting up libatomic1:ppc64el (14.2.0-4ubuntu2) ... 148s Setting up libsystemd-shared:ppc64el (256.5-2ubuntu2) ... 148s Setting up systemd (256.5-2ubuntu2) ... 148s Installing new version of config file /etc/systemd/journald.conf ... 148s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 148s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 148s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 149s Setting up vim-tiny (2:9.1.0496-1ubuntu5) ... 149s Setting up systemd-cryptsetup (256.5-2ubuntu2) ... 149s Setting up systemd-timesyncd (256.5-2ubuntu2) ... 149s systemd-time-wait-sync.service is a disabled or a static unit not running, not starting it. 150s Setting up udev (256.5-2ubuntu2) ... 150s Setting up systemd-resolved (256.5-2ubuntu2) ... 151s Setting up systemd-sysv (256.5-2ubuntu2) ... 151s Setting up libnss-systemd:ppc64el (256.5-2ubuntu2) ... 151s Setting up libpam-systemd:ppc64el (256.5-2ubuntu2) ... 151s Processing triggers for libc-bin (2.40-1ubuntu1) ... 151s Processing triggers for man-db (2.12.1-3) ... 153s Processing triggers for dbus (1.14.10-4ubuntu5) ... 153s Processing triggers for shared-mime-info (2.4-5) ... 153s Processing triggers for initramfs-tools (0.142ubuntu33) ... 154s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 154s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 162s Reading package lists... 162s Building dependency tree... 162s Reading state information... 163s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 163s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 163s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 163s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 163s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 164s Reading package lists... 164s Reading package lists... 165s Building dependency tree... 165s Reading state information... 165s Calculating upgrade... 165s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 165s Reading package lists... 165s Building dependency tree... 165s Reading state information... 166s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 166s autopkgtest [23:04:47]: rebooting testbed after setup commands that affected boot 170s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 205s autopkgtest [23:05:26]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 208s autopkgtest [23:05:29]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 211s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (dsc) [2772 B] 211s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (tar) [588 kB] 211s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (diff) [42.7 kB] 211s gpgv: Signature made Thu Sep 5 17:42:16 2024 UTC 211s gpgv: using RSA key 63EEFC3DE14D5146CE7F24BF34B8AD7D9529E793 211s gpgv: Can't check signature: No public key 211s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.9-1ubuntu3.dsc: no acceptable signature found 212s autopkgtest [23:05:33]: testing package multipath-tools version 0.9.9-1ubuntu3 212s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 212s autopkgtest [23:05:33]: build not needed 213s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 213s autopkgtest [23:05:34]: test kpartx-file-loopback: preparing testbed 214s Reading package lists... 214s Building dependency tree... 214s Reading state information... 214s Starting pkgProblemResolver with broken count: 0 214s Starting 2 pkgProblemResolver with broken count: 0 214s Done 214s The following additional packages will be installed: 214s liburing2 qemu-utils 214s Recommended packages: 214s qemu-block-extra 214s The following NEW packages will be installed: 214s autopkgtest-satdep liburing2 qemu-utils 214s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 214s Need to get 2431 kB/2432 kB of archives. 214s After this operation, 16.9 MB of additional disk space will be used. 214s Get:1 /tmp/autopkgtest.kY2Ex2/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 215s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 215s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el qemu-utils ppc64el 1:9.0.2+ds-4ubuntu5 [2404 kB] 215s Fetched 2431 kB in 1s (3346 kB/s) 215s Selecting previously unselected package liburing2:ppc64el. 216s (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 ... 72442 files and directories currently installed.) 216s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 216s Unpacking liburing2:ppc64el (2.6-1) ... 216s Selecting previously unselected package qemu-utils. 216s Preparing to unpack .../qemu-utils_1%3a9.0.2+ds-4ubuntu5_ppc64el.deb ... 216s Unpacking qemu-utils (1:9.0.2+ds-4ubuntu5) ... 216s Selecting previously unselected package autopkgtest-satdep. 216s Preparing to unpack .../1-autopkgtest-satdep.deb ... 216s Unpacking autopkgtest-satdep (0) ... 216s Setting up liburing2:ppc64el (2.6-1) ... 216s Setting up qemu-utils (1:9.0.2+ds-4ubuntu5) ... 216s Setting up autopkgtest-satdep (0) ... 216s Processing triggers for man-db (2.12.1-3) ... 217s Processing triggers for libc-bin (2.40-1ubuntu1) ... 220s (Reading database ... 72466 files and directories currently installed.) 220s Removing autopkgtest-satdep (0) ... 221s autopkgtest [23:05:42]: test kpartx-file-loopback: [----------------------- 221s Formatting 'foo.img', fmt=raw size=20971520 222s Creating new GPT entries in memory. 222s Warning: The kernel is still using the old partition table. 222s The new table will be used at the next reboot or after you 222s run partprobe(8) or kpartx(8) 222s The operation has completed successfully. 222s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 222s standard_filename: OK 222s del devmap : loop0p1 222s No devices found 222s standard_filename_cleanup: OK 222s Formatting 'fou du FaFa.img', fmt=raw size=20971520 223s Creating new GPT entries in memory. 223s Warning: The kernel is still using the old partition table. 223s The new table will be used at the next reboot or after you 223s run partprobe(8) or kpartx(8) 223s The operation has completed successfully. 223s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 223s filename_with_spaces: OK 223s del devmap : loop0p1 223s No devices found 223s filename_with_spaces_cleanup: OK 223s autopkgtest [23:05:44]: test kpartx-file-loopback: -----------------------] 224s autopkgtest [23:05:45]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 224s kpartx-file-loopback PASS 224s autopkgtest [23:05:45]: test tgtbasedmpaths: preparing testbed 304s autopkgtest [23:07:05]: testbed dpkg architecture: ppc64el 304s autopkgtest [23:07:05]: testbed apt version: 2.9.8 304s autopkgtest [23:07:05]: @@@@@@@@@@@@@@@@@@@@ test bed setup 305s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 305s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [260 kB] 305s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [10.9 kB] 305s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [34.4 kB] 305s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4496 B] 305s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [51.9 kB] 305s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [1332 B] 305s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1372 B] 305s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 305s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [219 kB] 305s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [7096 B] 305s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [764 B] 306s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 307s Fetched 718 kB in 1s (1028 kB/s) 307s Reading package lists... 310s Reading package lists... 310s Building dependency tree... 310s Reading state information... 310s Calculating upgrade... 310s The following packages will be upgraded: 310s gcc-14-base libatomic1 libgcc-s1 libnss-systemd libpam-systemd libstdc++6 310s libsystemd-shared libsystemd0 libudev1 systemd systemd-cryptsetup 310s systemd-dev systemd-resolved systemd-sysv systemd-timesyncd udev vim-common 310s vim-tiny xxd 310s 19 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 310s Need to get 12.9 MB of archives. 310s After this operation, 12.3 kB of additional disk space will be used. 310s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnss-systemd ppc64el 256.5-2ubuntu2 [214 kB] 311s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-dev all 256.5-2ubuntu2 [114 kB] 311s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-timesyncd ppc64el 256.5-2ubuntu2 [42.4 kB] 311s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-resolved ppc64el 256.5-2ubuntu2 [368 kB] 311s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-cryptsetup ppc64el 256.5-2ubuntu2 [127 kB] 311s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsystemd-shared ppc64el 256.5-2ubuntu2 [2502 kB] 311s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsystemd0 ppc64el 256.5-2ubuntu2 [564 kB] 311s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-sysv ppc64el 256.5-2ubuntu2 [11.9 kB] 311s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpam-systemd ppc64el 256.5-2ubuntu2 [326 kB] 311s Get:10 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd ppc64el 256.5-2ubuntu2 [3746 kB] 311s Get:11 http://ftpmaster.internal/ubuntu oracular/main ppc64el udev ppc64el 256.5-2ubuntu2 [2140 kB] 311s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el libudev1 ppc64el 256.5-2ubuntu2 [223 kB] 311s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libatomic1 ppc64el 14.2.0-4ubuntu2 [10.7 kB] 311s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el gcc-14-base ppc64el 14.2.0-4ubuntu2 [50.8 kB] 311s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libstdc++6 ppc64el 14.2.0-4ubuntu2 [886 kB] 311s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libgcc-s1 ppc64el 14.2.0-4ubuntu2 [39.1 kB] 311s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el vim-tiny ppc64el 2:9.1.0496-1ubuntu5 [1068 kB] 311s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el vim-common all 2:9.1.0496-1ubuntu5 [387 kB] 311s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el xxd ppc64el 2:9.1.0496-1ubuntu5 [64.8 kB] 312s Fetched 12.9 MB in 1s (10.4 MB/s) 312s (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 ... 72442 files and directories currently installed.) 312s Preparing to unpack .../0-libnss-systemd_256.5-2ubuntu2_ppc64el.deb ... 312s Unpacking libnss-systemd:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 312s Preparing to unpack .../1-systemd-dev_256.5-2ubuntu2_all.deb ... 312s Unpacking systemd-dev (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 312s Preparing to unpack .../2-systemd-timesyncd_256.5-2ubuntu2_ppc64el.deb ... 312s Unpacking systemd-timesyncd (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 312s Preparing to unpack .../3-systemd-resolved_256.5-2ubuntu2_ppc64el.deb ... 312s Unpacking systemd-resolved (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 312s Preparing to unpack .../4-systemd-cryptsetup_256.5-2ubuntu2_ppc64el.deb ... 312s Unpacking systemd-cryptsetup (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 312s Preparing to unpack .../5-libsystemd-shared_256.5-2ubuntu2_ppc64el.deb ... 312s Unpacking libsystemd-shared:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 312s Preparing to unpack .../6-libsystemd0_256.5-2ubuntu2_ppc64el.deb ... 312s Unpacking libsystemd0:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 312s Setting up libsystemd0:ppc64el (256.5-2ubuntu2) ... 312s (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 ... 72442 files and directories currently installed.) 312s Preparing to unpack .../systemd-sysv_256.5-2ubuntu2_ppc64el.deb ... 312s Unpacking systemd-sysv (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 312s Preparing to unpack .../libpam-systemd_256.5-2ubuntu2_ppc64el.deb ... 312s Unpacking libpam-systemd:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 312s Preparing to unpack .../systemd_256.5-2ubuntu2_ppc64el.deb ... 312s Unpacking systemd (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 313s Preparing to unpack .../udev_256.5-2ubuntu2_ppc64el.deb ... 313s Unpacking udev (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 313s Preparing to unpack .../libudev1_256.5-2ubuntu2_ppc64el.deb ... 313s Unpacking libudev1:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 313s Setting up libudev1:ppc64el (256.5-2ubuntu2) ... 313s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72442 files and directories currently installed.) 313s Preparing to unpack .../libatomic1_14.2.0-4ubuntu2_ppc64el.deb ... 313s Unpacking libatomic1:ppc64el (14.2.0-4ubuntu2) over (14.2.0-4ubuntu1) ... 313s Preparing to unpack .../gcc-14-base_14.2.0-4ubuntu2_ppc64el.deb ... 313s Unpacking gcc-14-base:ppc64el (14.2.0-4ubuntu2) over (14.2.0-4ubuntu1) ... 313s Setting up gcc-14-base:ppc64el (14.2.0-4ubuntu2) ... 313s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72442 files and directories currently installed.) 313s Preparing to unpack .../libstdc++6_14.2.0-4ubuntu2_ppc64el.deb ... 313s Unpacking libstdc++6:ppc64el (14.2.0-4ubuntu2) over (14.2.0-4ubuntu1) ... 313s Setting up libstdc++6:ppc64el (14.2.0-4ubuntu2) ... 313s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72442 files and directories currently installed.) 313s Preparing to unpack .../libgcc-s1_14.2.0-4ubuntu2_ppc64el.deb ... 313s Unpacking libgcc-s1:ppc64el (14.2.0-4ubuntu2) over (14.2.0-4ubuntu1) ... 313s Setting up libgcc-s1:ppc64el (14.2.0-4ubuntu2) ... 313s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72442 files and directories currently installed.) 313s Preparing to unpack .../vim-tiny_2%3a9.1.0496-1ubuntu5_ppc64el.deb ... 313s Unpacking vim-tiny (2:9.1.0496-1ubuntu5) over (2:9.1.0496-1ubuntu4) ... 313s Preparing to unpack .../vim-common_2%3a9.1.0496-1ubuntu5_all.deb ... 313s Unpacking vim-common (2:9.1.0496-1ubuntu5) over (2:9.1.0496-1ubuntu4) ... 313s Preparing to unpack .../xxd_2%3a9.1.0496-1ubuntu5_ppc64el.deb ... 313s Unpacking xxd (2:9.1.0496-1ubuntu5) over (2:9.1.0496-1ubuntu4) ... 313s Setting up systemd-dev (256.5-2ubuntu2) ... 313s Setting up xxd (2:9.1.0496-1ubuntu5) ... 313s Setting up vim-common (2:9.1.0496-1ubuntu5) ... 313s Setting up libatomic1:ppc64el (14.2.0-4ubuntu2) ... 313s Setting up libsystemd-shared:ppc64el (256.5-2ubuntu2) ... 313s Setting up systemd (256.5-2ubuntu2) ... 313s Installing new version of config file /etc/systemd/journald.conf ... 313s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 313s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 313s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 314s Setting up vim-tiny (2:9.1.0496-1ubuntu5) ... 314s Setting up systemd-cryptsetup (256.5-2ubuntu2) ... 314s Setting up systemd-timesyncd (256.5-2ubuntu2) ... 315s systemd-time-wait-sync.service is a disabled or a static unit not running, not starting it. 315s Setting up udev (256.5-2ubuntu2) ... 316s Setting up systemd-resolved (256.5-2ubuntu2) ... 316s Setting up systemd-sysv (256.5-2ubuntu2) ... 316s Setting up libnss-systemd:ppc64el (256.5-2ubuntu2) ... 316s Setting up libpam-systemd:ppc64el (256.5-2ubuntu2) ... 316s Processing triggers for libc-bin (2.40-1ubuntu1) ... 316s Processing triggers for man-db (2.12.1-3) ... 319s Processing triggers for dbus (1.14.10-4ubuntu5) ... 319s Processing triggers for shared-mime-info (2.4-5) ... 319s Processing triggers for initramfs-tools (0.142ubuntu33) ... 319s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 319s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 329s Reading package lists... 329s Building dependency tree... 329s Reading state information... 329s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 329s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 329s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 330s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 330s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 331s Reading package lists... 331s Reading package lists... 331s Building dependency tree... 331s Reading state information... 331s Calculating upgrade... 331s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 331s Reading package lists... 331s Building dependency tree... 331s Reading state information... 331s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 332s autopkgtest [23:07:33]: rebooting testbed after setup commands that affected boot 335s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 364s Reading package lists... 364s Building dependency tree... 364s Reading state information... 364s Starting pkgProblemResolver with broken count: 0 364s Starting 2 pkgProblemResolver with broken count: 0 364s Done 365s The following additional packages will be installed: 365s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 365s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 365s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 365s librdmacm1t64 lsscsi open-iscsi tgt 365s Suggested packages: 365s fio-examples gnuplot tgt-glusterfs tgt-rbd 365s Recommended packages: 365s finalrd 365s The following NEW packages will be installed: 365s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 365s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 365s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 365s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 365s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 365s Need to get 11.0 MB/11.0 MB of archives. 365s After this operation, 50.0 MB of additional disk space will be used. 365s Get:1 /tmp/autopkgtest.kY2Ex2/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [736 B] 365s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 365s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 365s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 365s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2ubuntu1 [80.6 kB] 365s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 365s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 365s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-5ubuntu1 [21.7 kB] 365s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-5ubuntu1 [308 kB] 365s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-5ubuntu1 [46.3 kB] 365s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-5ubuntu1 [99.1 kB] 365s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-2build1 [98.5 kB] 365s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2.2ubuntu1 [23.7 kB] 365s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2.2ubuntu1 [73.4 kB] 365s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 365s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3.2ubuntu2 [260 kB] 365s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3.2ubuntu2 [281 kB] 365s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~rc2-0ubuntu1 [4194 kB] 366s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 366s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~rc2-0ubuntu1 [3714 kB] 366s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 366s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 366s Preconfiguring packages ... 366s Fetched 11.0 MB in 1s (11.1 MB/s) 366s Selecting previously unselected package libopeniscsiusr. 366s (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 ... 72442 files and directories currently installed.) 366s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 366s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 366s Selecting previously unselected package libisns0t64:ppc64el. 366s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 366s Unpacking libisns0t64:ppc64el (0.101-1) ... 366s Selecting previously unselected package open-iscsi. 366s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 367s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 367s Selecting previously unselected package librdmacm1t64:ppc64el. 367s Preparing to unpack .../03-librdmacm1t64_52.0-2ubuntu1_ppc64el.deb ... 367s Unpacking librdmacm1t64:ppc64el (52.0-2ubuntu1) ... 367s Selecting previously unselected package libconfig-general-perl. 367s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 367s Unpacking libconfig-general-perl (2.65-2) ... 367s Selecting previously unselected package tgt. 367s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 367s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 367s Selecting previously unselected package libgfxdr0:ppc64el. 367s Preparing to unpack .../06-libgfxdr0_11.1-5ubuntu1_ppc64el.deb ... 367s Unpacking libgfxdr0:ppc64el (11.1-5ubuntu1) ... 367s Selecting previously unselected package libglusterfs0:ppc64el. 367s Preparing to unpack .../07-libglusterfs0_11.1-5ubuntu1_ppc64el.deb ... 367s Unpacking libglusterfs0:ppc64el (11.1-5ubuntu1) ... 367s Selecting previously unselected package libgfrpc0:ppc64el. 367s Preparing to unpack .../08-libgfrpc0_11.1-5ubuntu1_ppc64el.deb ... 367s Unpacking libgfrpc0:ppc64el (11.1-5ubuntu1) ... 367s Selecting previously unselected package libgfapi0:ppc64el. 367s Preparing to unpack .../09-libgfapi0_11.1-5ubuntu1_ppc64el.deb ... 367s Unpacking libgfapi0:ppc64el (11.1-5ubuntu1) ... 367s Selecting previously unselected package libnbd0. 367s Preparing to unpack .../10-libnbd0_1.20.2-2build1_ppc64el.deb ... 367s Unpacking libnbd0 (1.20.2-2build1) ... 367s Selecting previously unselected package libdaxctl1:ppc64el. 367s Preparing to unpack .../11-libdaxctl1_77-2.2ubuntu1_ppc64el.deb ... 367s Unpacking libdaxctl1:ppc64el (77-2.2ubuntu1) ... 367s Selecting previously unselected package libndctl6:ppc64el. 367s Preparing to unpack .../12-libndctl6_77-2.2ubuntu1_ppc64el.deb ... 367s Unpacking libndctl6:ppc64el (77-2.2ubuntu1) ... 367s Selecting previously unselected package libpmem1:ppc64el. 367s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 367s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 367s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 367s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 367s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 367s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 367s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 367s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 367s Selecting previously unselected package librados2. 367s Preparing to unpack .../16-librados2_19.2.0~rc2-0ubuntu1_ppc64el.deb ... 367s Unpacking librados2 (19.2.0~rc2-0ubuntu1) ... 367s Selecting previously unselected package libpmemobj1:ppc64el. 367s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 367s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 367s Selecting previously unselected package librbd1. 367s Preparing to unpack .../18-librbd1_19.2.0~rc2-0ubuntu1_ppc64el.deb ... 367s Unpacking librbd1 (19.2.0~rc2-0ubuntu1) ... 367s Selecting previously unselected package fio. 367s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 367s Unpacking fio (3.37-1) ... 367s Selecting previously unselected package lsscsi. 367s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 367s Unpacking lsscsi (0.32-1build1) ... 367s Selecting previously unselected package autopkgtest-satdep. 367s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 367s Unpacking autopkgtest-satdep (0) ... 367s Setting up libconfig-general-perl (2.65-2) ... 367s Setting up libisns0t64:ppc64el (0.101-1) ... 367s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 367s Setting up libnbd0 (1.20.2-2build1) ... 367s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 367s Setting up libglusterfs0:ppc64el (11.1-5ubuntu1) ... 367s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 367s Setting up lsscsi (0.32-1build1) ... 367s Setting up libdaxctl1:ppc64el (77-2.2ubuntu1) ... 367s Setting up libndctl6:ppc64el (77-2.2ubuntu1) ... 367s Setting up librdmacm1t64:ppc64el (52.0-2ubuntu1) ... 367s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 368s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 368s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 368s Setting up libgfxdr0:ppc64el (11.1-5ubuntu1) ... 368s Setting up librados2 (19.2.0~rc2-0ubuntu1) ... 368s Setting up open-iscsi (2.1.10-1ubuntu1) ... 369s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 370s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 370s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 370s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 370s Setting up librbd1 (19.2.0~rc2-0ubuntu1) ... 370s Setting up libgfrpc0:ppc64el (11.1-5ubuntu1) ... 370s Setting up libgfapi0:ppc64el (11.1-5ubuntu1) ... 370s Setting up fio (3.37-1) ... 370s Setting up autopkgtest-satdep (0) ... 370s Processing triggers for man-db (2.12.1-3) ... 372s Processing triggers for initramfs-tools (0.142ubuntu33) ... 372s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 372s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 381s Processing triggers for libc-bin (2.40-1ubuntu1) ... 384s (Reading database ... 72683 files and directories currently installed.) 384s Removing autopkgtest-satdep (0) ... 386s autopkgtest [23:08:27]: test tgtbasedmpaths: [----------------------- 386s + targetname=iqn.2016-11.foo.com:target.iscsi 386s + pwd 386s + cwd=/tmp/autopkgtest.kY2Ex2/build.5vP/src 386s + testdir=/mnt/tgtmpathtest 386s + localhost=127.0.0.1 386s + portal=127.0.0.1:3260 386s + maxpaths=4 386s + backfn=backingfile 386s + expectwwid=60000000000000000e00000000010001 386s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 386s + bglog=/tmp/autopkgtest.kY2Ex2/tgtbasedmpaths-artifacts/test-background.log 386s + fioprep=/tmp/autopkgtest.kY2Ex2/tgtbasedmpaths-artifacts/path-change-prep.fio 386s + fiovrfy=/tmp/autopkgtest.kY2Ex2/tgtbasedmpaths-artifacts/path-change-check.fio 386s + mkdir -p /etc/multipath 386s + echo /360000000000000000e00000000010001/ 386s + service tgt restart 386s + truncate --size 100M backingfile 386s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 386s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 386s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.kY2Ex2/build.5vP/src/backingfile 386s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 386s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 386s login #1 386s + echo login #1 386s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 386s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 386s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 386s + seq 2 4 386s extra login #2 386s + echo extra login #2 386s + iscsiadm --mode session -r 1 --op new 386s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 386s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 386s extra login #3 386s + echo extra login #3 386s + iscsiadm --mode session -r 1 --op new 386s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 386s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 386s + echo extra login #4 386s + iscsiadm --mode session -r 1 --op new 386s extra login #4 387s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 387s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 387s + udevadm settle 387s + sleep 5 392s Status after initial setup 392s + echo Status after initial setup 392s + tgtadm --lld iscsi --mode target --op show 392s Target 1: iqn.2016-11.foo.com:target.iscsi 392s System information: 392s Driver: iscsi 392s State: ready 392s I_T nexus information: 392s I_T nexus: 1 392s Initiator: iqn.2004-10.com.ubuntu:01:303ff549834 alias: autopkgtest 392s Connection: 0 392s IP Address: 127.0.0.1 392s I_T nexus: 2 392s Initiator: iqn.2004-10.com.ubuntu:01:303ff549834 alias: autopkgtest 392s Connection: 0 392s IP Address: 127.0.0.1 392s I_T nexus: 3 392s Initiator: iqn.2004-10.com.ubuntu:01:303ff549834 alias: autopkgtest 392s Connection: 0 392s IP Address: 127.0.0.1 392s I_T nexus: 4 392s Initiator: iqn.2004-10.com.ubuntu:01:303ff549834 alias: autopkgtest 392s Connection: 0 392s IP Address: 127.0.0.1 392s LUN information: 392s LUN: 0 392s Type: controller 392s SCSI ID: IET 00010000 392s SCSI SN: beaf10 392s Size: 0 MB, Block size: 1 392s Online: Yes 392s Removable media: No 392s Prevent removal: No 392s Readonly: No 392s SWP: No 392s Thin-provisioning: No 392s Backing store type: null 392s Backing store path: None 392s Backing store flags: 392s LUN: 1 392s Type: disk 392s SCSI ID: IET 00010001 392s SCSI SN: beaf11 392s Size: 105 MB, Block size: 512 392s Online: Yes 392s Removable media: No 392s Prevent removal: No 392s Readonly: No 392s SWP: No 392s Thin-provisioning: No 392s Backing store type: rdwr 392s Backing store path: /tmp/autopkgtest.kY2Ex2/build.5vP/src/backingfile 392s Backing store flags: 392s Account information: 392s ACL information: 392s ALL 392s + tgtadm --lld iscsi --op show --mode conn --tid 1 392s Session: 4 392s Connection: 0 392s Initiator: iqn.2004-10.com.ubuntu:01:303ff549834 392s IP Address: 127.0.0.1 392s Session: 3 392s Connection: 0 392s Initiator: iqn.2004-10.com.ubuntu:01:303ff549834 392s IP Address: 127.0.0.1 392s Session: 2 392s Connection: 0 392s Initiator: iqn.2004-10.com.ubuntu:01:303ff549834 392s IP Address: 127.0.0.1 392s Session: 1 392s Connection: 0 392s Initiator: iqn.2004-10.com.ubuntu:01:303ff549834 392s IP Address: 127.0.0.1 392s + iscsiadm --mode session -P 1 392s + lsscsi -liv 392s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 392s Current Portal: 127.0.0.1:3260,1 392s Persistent Portal: 127.0.0.1:3260,1 392s ********** 392s Interface: 392s ********** 392s Iface Name: default 392s Iface Transport: tcp 392s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:303ff549834 392s Iface IPaddress: 127.0.0.1 392s Iface HWaddress: default 392s Iface Netdev: default 392s SID: 1 392s iSCSI Connection State: LOGGED IN 392s iSCSI Session State: LOGGED_IN 392s Internal iscsid Session State: NO CHANGE 392s 392s ********** 392s Interface: 392s ********** 392s Iface Name: default 392s Iface Transport: tcp 392s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:303ff549834 392s Iface IPaddress: 127.0.0.1 392s Iface HWaddress: default 392s Iface Netdev: default 392s SID: 2 392s iSCSI Connection State: LOGGED IN 392s iSCSI Session State: LOGGED_IN 392s Internal iscsid Session State: NO CHANGE 392s 392s ********** 392s Interface: 392s ********** 392s Iface Name: default 392s Iface Transport: tcp 392s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:303ff549834 392s Iface IPaddress: 127.0.0.1 392s Iface HWaddress: default 392s Iface Netdev: default 392s SID: 3 392s iSCSI Connection State: LOGGED IN 392s iSCSI Session State: LOGGED_IN 392s Internal iscsid Session State: NO CHANGE 392s 392s ********** 392s Interface: 392s ********** 392s Iface Name: default 392s Iface Transport: tcp 392s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:303ff549834 392s Iface IPaddress: 127.0.0.1 392s Iface HWaddress: default 392s Iface Netdev: default 392s SID: 4 392s iSCSI Connection State: LOGGED IN 392s iSCSI Session State: LOGGED_IN 392s Internal iscsid Session State: NO CHANGE 392s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 392s + multipath -v3 -ll 392s 46.842300 | set open fds limit to 1073741816/1073741816 392s 46.842334 | _read_bindings_file: reading /etc/multipath/bindings 392s 46.842362 | loading /usr/lib/multipath/libchecktur.so checker 392s 46.842475 | checker tur: message table size = 4 392s 46.842483 | loading /usr/lib/multipath/libprioconst.so prioritizer 392s 46.842624 | _init_foreign: foreign library "nvme" is not enabled 392s 46.848174 | vda: device node name blacklisted 392s 46.848529 | sda: size = 204800 392s 46.848702 | sda: vendor = IET 392s 46.848729 | sda: product = VIRTUAL-DISK 392s 46.848797 | sda: rev = 0001 392s 46.849592 | sda: h:b:t:l = 0:0:0:1 392s 46.850006 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 46.850011 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 392s 46.850014 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 392s 46.850223 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 46.850227 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 46.850244 | sda: serial = beaf11 392s 46.850247 | sda: detect_checker = yes (setting: multipath internal) 392s 46.850279 | sda checker timeout = 30 s (setting: kernel sysfs) 392s 46.851033 | sda: path_checker = tur (setting: multipath internal) 392s 46.851247 | sda: tur state = up 392s 46.851491 | sdb: size = 204800 392s 46.851695 | sdb: vendor = IET 392s 46.851723 | sdb: product = VIRTUAL-DISK 392s 46.851747 | sdb: rev = 0001 392s 46.852503 | sdb: h:b:t:l = 1:0:0:1 392s 46.852931 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 46.852939 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 392s 46.852943 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 392s 46.853129 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 46.853135 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 46.853150 | sdb: serial = beaf11 392s 46.853153 | sdb: detect_checker = yes (setting: multipath internal) 392s 46.853184 | sdb checker timeout = 30 s (setting: kernel sysfs) 392s 46.853349 | sdb: path_checker = tur (setting: multipath internal) 392s 46.853503 | sdb: tur state = up 392s 46.853652 | sdc: size = 204800 392s 46.853805 | sdc: vendor = IET 392s 46.853831 | sdc: product = VIRTUAL-DISK 392s 46.853855 | sdc: rev = 0001 392s 46.854683 | sdc: h:b:t:l = 2:0:0:1 392s 46.855072 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 46.855077 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 392s 46.855079 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 392s [0:0:0:0] storage IET Controller 0001 - - 392s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 392s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 392s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 392s [1:0:0:0] storage IET Controller 0001 - - 392s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 392s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 392s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 392s [2:0:0:0] storage IET Controller 0001 - - 392s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 392s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 392s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 392s [3:0:0:0] storage IET Controller 0001 - - 392s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 392s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 392s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 392s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 392s NVMe module may not be loaded 392s 46.855234 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 46.855239 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 46.855252 | sdc: serial = beaf11 392s 46.855254 | sdc: detect_checker = yes (setting: multipath internal) 392s 46.855281 | sdc checker timeout = 30 s (setting: kernel sysfs) 392s 46.855437 | sdc: path_checker = tur (setting: multipath internal) 392s 46.855539 | sdc: tur state = up 392s 46.855678 | sdd: size = 204800 392s 46.855816 | sdd: vendor = IET 392s 46.855839 | sdd: product = VIRTUAL-DISK 392s 46.855860 | sdd: rev = 0001 392s 46.856534 | sdd: h:b:t:l = 3:0:0:1 392s 46.857005 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 46.857010 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 392s 46.857013 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 392s 46.857158 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 46.857163 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 46.857175 | sdd: serial = beaf11 392s 46.857178 | sdd: detect_checker = yes (setting: multipath internal) 392s 46.857205 | sdd checker timeout = 30 s (setting: kernel sysfs) 392s 46.857346 | sdd: path_checker = tur (setting: multipath internal) 392s 46.857405 | sdd: tur state = up 392s 46.857502 | loop0: device node name blacklisted 392s 46.857590 | loop1: device node name blacklisted 392s 46.857675 | loop2: device node name blacklisted 392s 46.857759 | loop3: device node name blacklisted 392s 46.857844 | loop4: device node name blacklisted 392s 46.857927 | loop5: device node name blacklisted 392s 46.858010 | loop6: device node name blacklisted 392s 46.858094 | loop7: device node name blacklisted 392s 46.858186 | dm-0: device node name blacklisted 392s 46.859251 | multipath-tools v0.9.9 (05/03, 2024) 392s 46.859262 | libdevmapper version 1.02.196 392s 46.859459 | kernel device mapper v4.48.0 392s 46.859483 | DM multipath kernel driver v1.14.0 392s 46.859623 | sda: size = 204800 392s 46.859630 | sda: vendor = IET 392s 46.859632 | sda: product = VIRTUAL-DISK 392s 46.859635 | sda: rev = 0001 392s 46.860239 | sda: h:b:t:l = 0:0:0:1 392s 46.860363 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 46.860384 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 46.860387 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 46.860399 | sda: serial = beaf11 392s 46.860477 | sda: tur state = up 392s 46.860483 | sda: uid = 360000000000000000e00000000010001 (udev) 392s 46.860486 | sda: detect_prio = yes (setting: multipath internal) 392s 46.860489 | sda: prio = const (setting: multipath internal) 392s 46.860491 | sda: prio args = "" (setting: multipath internal) 392s 46.860494 | sda: const prio = 1 392s 46.860518 | sdb: size = 204800 392s 46.860524 | sdb: vendor = IET 392s 46.860526 | sdb: product = VIRTUAL-DISK 392s 46.860529 | sdb: rev = 0001 392s 46.861114 | sdb: h:b:t:l = 1:0:0:1 392s 46.861228 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 46.861249 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 46.861251 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 46.861264 | sdb: serial = beaf11 392s 46.861390 | sdb: tur state = up 392s 46.861397 | sdb: uid = 360000000000000000e00000000010001 (udev) 392s 46.861399 | sdb: detect_prio = yes (setting: multipath internal) 392s 46.861402 | sdb: prio = const (setting: multipath internal) 392s 46.861404 | sdb: prio args = "" (setting: multipath internal) 392s 46.861406 | sdb: const prio = 1 392s 46.861432 | sdc: size = 204800 392s 46.861437 | sdc: vendor = IET 392s 46.861439 | sdc: product = VIRTUAL-DISK 392s 46.861442 | sdc: rev = 0001 392s 46.862051 | sdc: h:b:t:l = 2:0:0:1 392s 46.862169 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 46.862190 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 46.862192 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 46.862204 | sdc: serial = beaf11 392s 46.862296 | sdc: tur state = up 392s 46.862301 | sdc: uid = 360000000000000000e00000000010001 (udev) 392s 46.862304 | sdc: detect_prio = yes (setting: multipath internal) 392s 46.862306 | sdc: prio = const (setting: multipath internal) 392s 46.862308 | sdc: prio args = "" (setting: multipath internal) 392s 46.862311 | sdc: const prio = 1 392s 46.862333 | sdd: size = 204800 392s 46.862338 | sdd: vendor = IET 392s 46.862341 | sdd: product = VIRTUAL-DISK 392s 46.862343 | sdd: rev = 0001 392s 46.862920 | sdd: h:b:t:l = 3:0:0:1 392s ===== paths list ===== 392s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 392s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 392s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 392s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 392s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 392s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 392s size=100M features='0' hwhandler='0' wp=rw 392s |-+- policy='service-time 0' prio=1 status=active 392s | `- 0:0:0:1 sda 8:0 active ready running 392s |-+- policy='service-time 0' prio=1 status=enabled 392s | `- 1:0:0:1 sdb 8:16 active ready running 392s |-+- policy='service-time 0' prio=1 status=enabled 392s | `- 2:0:0:1 sdc 8:32 active ready running 392s `-+- policy='service-time 0' prio=1 status=enabled 392s `- 3:0:0:1 sdd 8:48 active ready running 392s 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 392s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 392s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 392s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 392s /etc/multipath/bindings:# 392s /etc/multipath/bindings:# Format: 392s /etc/multipath/bindings:# alias wwid 392s /etc/multipath/bindings:# 392s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 392s /etc/multipath/wwids:/360000000000000000e00000000010001/ 392s 46.863031 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 392s 46.863051 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 392s 46.863054 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 392s 46.863066 | sdd: serial = beaf11 392s 46.863126 | sdd: tur state = up 392s 46.863131 | sdd: uid = 360000000000000000e00000000010001 (udev) 392s 46.863134 | sdd: detect_prio = yes (setting: multipath internal) 392s 46.863137 | sdd: prio = const (setting: multipath internal) 392s 46.863139 | sdd: prio args = "" (setting: multipath internal) 392s 46.863141 | sdd: const prio = 1 392s 46.865196 | unloading tur checker 392s 46.865258 | unloading const prioritizer 392s + dmsetup table 392s + grep . /etc/multipath/bindings /etc/multipath/wwids 392s + systemctl status multipathd.service 392s ● multipathd.service - Device-Mapper Multipath Device Controller 392s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 392s Active: active (running) since Wed 2024-09-11 23:07:49 UTC; 43s ago 392s Invocation: 778df317d39a4b468f26c4f6ae76ebaa 392s TriggeredBy: ○ multipathd.socket 392s Main PID: 328 (multipathd) 392s Status: "up" 392s Tasks: 7 392s Memory: 27.8M (peak: 35.3M) 392s CPU: 48ms 392s CGroup: /system.slice/multipathd.service 392s └─328 /sbin/multipathd -d -s 392s 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 392s Sep 11 23:07:49 autopkgtest multipathd[328]: multipathd v0.9.9: start up 392s Sep 11 23:07:49 autopkgtest multipathd[328]: reconfigure: setting up paths and maps 392s Sep 11 23:07:49 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 392s Sep 11 23:08:27 autopkgtest multipathd[328]: updated bindings file /etc/multipath/bindings 392s Sep 11 23:08:27 autopkgtest multipathd[328]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 392s Sep 11 23:08:28 autopkgtest multipathd[328]: sda [8:0]: path added to devmap mpatha 392s Sep 11 23:08:28 autopkgtest multipathd[328]: mpatha: performing delayed actions 392s Sep 11 23:08:28 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 392s ○ multipathd.socket - multipathd control socket 392s Loaded: loaded (/usr/lib/systemd/system/multipathd.socket; static) 392s Active: inactive (dead) 392s Triggers: ● multipathd.service 392s Listen: @/org/kernel/linux/storage/multipathd (Stream) 392s total 0 392s drwxr-xr-x 2 root root 80 Sep 11 23:08 . 392s drwxr-xr-x 20 root root 4360 Sep 11 23:08 .. 392s crw------- 1 root root 10, 236 Sep 11 23:07 control 392s lrwxrwxrwx 1 root root 7 Sep 11 23:08 mpatha -> ../dm-0 392s journal 392s + ret_code=0 392s + systemctl status multipathd.socket 392s + ret_code=3 392s + [ 3 -eq 0 ] 392s + [ 3 -eq 3 ] 392s + ls -la /dev/mapper/ 392s + echo journal 392s + journalctl -b 392s Sep 11 23:07:49 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 392s Sep 11 23:07:49 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 392s Sep 11 23:07:49 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 392s Sep 11 23:07:49 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 392s Sep 11 23:07:49 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 392s Sep 11 23:07:49 autopkgtest kernel: Activating Kernel Userspace Access Prevention 392s Sep 11 23:07:49 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 392s Sep 11 23:07:49 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x00000000038a0000 with 64.0 KiB pages (exec) 392s Sep 11 23:07:49 autopkgtest kernel: radix-mmu: Mapped 0x00000000038a0000-0x0000000200000000 with 64.0 KiB pages 392s Sep 11 23:07:49 autopkgtest kernel: lpar: Using radix MMU under hypervisor 392s Sep 11 23:07:49 autopkgtest kernel: Linux version 6.8.0-31-generic (buildd@bos02-ppc64el-018) (powerpc64le-linux-gnu-gcc-13 (Ubuntu 13.2.0-23ubuntu4) 13.2.0, GNU ld (GNU Binutils for Ubuntu) 2.42) #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 (Ubuntu 6.8.0-31.31-generic 6.8.1) 392s Sep 11 23:07:49 autopkgtest kernel: Secure boot mode disabled 392s Sep 11 23:07:49 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc0000000093cd7ee 392s Sep 11 23:07:49 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (raw) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 392s Sep 11 23:07:49 autopkgtest kernel: Partition configured for 4 cpus. 392s Sep 11 23:07:49 autopkgtest kernel: CPU maps initialized for 1 thread per core 392s Sep 11 23:07:49 autopkgtest kernel: (thread shift is 0) 392s Sep 11 23:07:49 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 392s Sep 11 23:07:49 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 392s Sep 11 23:07:49 autopkgtest kernel: ----------------------------------------------------- 392s Sep 11 23:07:49 autopkgtest kernel: phys_mem_size = 0x200000000 392s Sep 11 23:07:49 autopkgtest kernel: dcache_bsize = 0x80 392s Sep 11 23:07:49 autopkgtest kernel: icache_bsize = 0x80 392s Sep 11 23:07:49 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 392s Sep 11 23:07:49 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 392s Sep 11 23:07:49 autopkgtest kernel: always = 0x0000000380008181 392s Sep 11 23:07:49 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 392s Sep 11 23:07:49 autopkgtest kernel: mmu_features = 0x3c007641 392s Sep 11 23:07:49 autopkgtest kernel: firmware_features = 0x00000285455a445f 392s Sep 11 23:07:49 autopkgtest kernel: vmalloc start = 0xc008000000000000 392s Sep 11 23:07:49 autopkgtest kernel: IO start = 0xc00a000000000000 392s Sep 11 23:07:49 autopkgtest kernel: vmemmap start = 0xc00c000000000000 392s Sep 11 23:07:49 autopkgtest kernel: ----------------------------------------------------- 392s Sep 11 23:07:49 autopkgtest kernel: numa: NODE_DATA [mem 0x1eff0c280-0x1eff13fff] 392s Sep 11 23:07:49 autopkgtest kernel: rfi-flush: fallback displacement flush available 392s Sep 11 23:07:49 autopkgtest kernel: rfi-flush: ori type flush available 392s Sep 11 23:07:49 autopkgtest kernel: rfi-flush: mttrig type flush available 392s Sep 11 23:07:49 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 392s Sep 11 23:07:49 autopkgtest kernel: count-cache-flush: hardware flush enabled. 392s Sep 11 23:07:49 autopkgtest kernel: link-stack-flush: software flush enabled. 392s Sep 11 23:07:49 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 392s Sep 11 23:07:49 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 392s Sep 11 23:07:49 autopkgtest kernel: stf-barrier: eieio barrier available 392s Sep 11 23:07:49 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 392s Sep 11 23:07:49 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 392s Sep 11 23:07:49 autopkgtest kernel: PPC64 nvram contains 65536 bytes 392s Sep 11 23:07:49 autopkgtest kernel: barrier-nospec: using ORI speculation barrier 392s Sep 11 23:07:49 autopkgtest kernel: barrier-nospec: patched 269 locations 392s Sep 11 23:07:49 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 392s Sep 11 23:07:49 autopkgtest kernel: Memory hole size: 0MB 392s Sep 11 23:07:49 autopkgtest kernel: Zone ranges: 392s Sep 11 23:07:49 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 392s Sep 11 23:07:49 autopkgtest kernel: Device empty 392s Sep 11 23:07:49 autopkgtest kernel: Movable zone start for each node 392s Sep 11 23:07:49 autopkgtest kernel: Early memory node ranges 392s Sep 11 23:07:49 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 392s Sep 11 23:07:49 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 392s Sep 11 23:07:49 autopkgtest kernel: percpu: Embedded 12 pages/cpu s609960 r0 d176472 u786432 392s Sep 11 23:07:49 autopkgtest kernel: pcpu-alloc: s609960 r0 d176472 u786432 alloc=12*65536 392s Sep 11 23:07:49 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 392s Sep 11 23:07:49 autopkgtest kernel: Kernel command line: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic root=UUID=657a72a9-f878-4085-b334-21a63fc7c218 ro console=hvc0 earlyprintk 392s Sep 11 23:07:49 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic", will be passed to user space. 392s Sep 11 23:07:49 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 392s Sep 11 23:07:49 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 392s Sep 11 23:07:49 autopkgtest kernel: Fallback order for Node 0: 0 392s Sep 11 23:07:49 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 130944 392s Sep 11 23:07:49 autopkgtest kernel: Policy zone: Normal 392s Sep 11 23:07:49 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 392s Sep 11 23:07:49 autopkgtest kernel: Memory: 7969280K/8388608K available (23680K kernel code, 4096K rwdata, 25472K rodata, 8832K init, 1901K bss, 419328K reserved, 0K cma-reserved) 392s Sep 11 23:07:49 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 392s Sep 11 23:07:49 autopkgtest kernel: ftrace: allocating 51717 entries in 19 pages 392s Sep 11 23:07:49 autopkgtest kernel: ftrace: allocated 19 pages with 3 groups 392s Sep 11 23:07:49 autopkgtest kernel: trace event string verifier disabled 392s Sep 11 23:07:49 autopkgtest kernel: rcu: Hierarchical RCU implementation. 392s Sep 11 23:07:49 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 392s Sep 11 23:07:49 autopkgtest kernel: Rude variant of Tasks RCU enabled. 392s Sep 11 23:07:49 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 392s Sep 11 23:07:49 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 392s Sep 11 23:07:49 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 392s Sep 11 23:07:49 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 392s Sep 11 23:07:49 autopkgtest kernel: xive: Using IRQ range [0-3] 392s Sep 11 23:07:49 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 392s Sep 11 23:07:49 autopkgtest kernel: xive: Using priority 6 for all interrupts 392s Sep 11 23:07:49 autopkgtest kernel: xive: Using 64kB queues 392s Sep 11 23:07:49 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 392s Sep 11 23:07:49 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 392s Sep 11 23:07:49 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 392s Sep 11 23:07:49 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 392s Sep 11 23:07:49 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 392s Sep 11 23:07:49 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 392s Sep 11 23:07:49 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 392s Sep 11 23:07:49 autopkgtest kernel: Console: colour dummy device 80x25 392s Sep 11 23:07:49 autopkgtest kernel: pid_max: default: 32768 minimum: 301 392s Sep 11 23:07:49 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,integrity 392s Sep 11 23:07:49 autopkgtest kernel: landlock: Up and running. 392s Sep 11 23:07:49 autopkgtest kernel: Yama: becoming mindful. 392s Sep 11 23:07:49 autopkgtest kernel: AppArmor: AppArmor initialized 392s Sep 11 23:07:49 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 392s Sep 11 23:07:49 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 392s Sep 11 23:07:49 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 392s Sep 11 23:07:49 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 392s Sep 11 23:07:49 autopkgtest kernel: POWER9 performance monitor hardware support registered 392s Sep 11 23:07:49 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 392s Sep 11 23:07:49 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 392s Sep 11 23:07:49 autopkgtest kernel: smp: Bringing up secondary CPUs ... 392s Sep 11 23:07:49 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 392s Sep 11 23:07:49 autopkgtest kernel: numa: Node 0 CPUs: 0-3 392s Sep 11 23:07:49 autopkgtest kernel: devtmpfs: initialized 392s Sep 11 23:07:49 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 392s Sep 11 23:07:49 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 392s Sep 11 23:07:49 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 392s Sep 11 23:07:49 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 392s Sep 11 23:07:49 autopkgtest kernel: PCI: OF: PROBE_ONLY disabled 392s Sep 11 23:07:49 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 392s Sep 11 23:07:49 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 392s Sep 11 23:07:49 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 392s Sep 11 23:07:49 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 392s Sep 11 23:07:49 autopkgtest kernel: audit: initializing netlink subsys (disabled) 392s Sep 11 23:07:49 autopkgtest kernel: audit: type=2000 audit(1726096066.036:1): state=initialized audit_enabled=0 res=1 392s Sep 11 23:07:49 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 392s Sep 11 23:07:49 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 392s Sep 11 23:07:49 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 392s Sep 11 23:07:49 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 392s Sep 11 23:07:49 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 392s Sep 11 23:07:49 autopkgtest kernel: cpuidle: using governor ladder 392s Sep 11 23:07:49 autopkgtest kernel: cpuidle: using governor menu 392s Sep 11 23:07:49 autopkgtest kernel: RTAS daemon started 392s Sep 11 23:07:49 autopkgtest kernel: pstore: Using crash dump compression: deflate 392s Sep 11 23:07:49 autopkgtest kernel: pstore: Registered nvram as persistent store backend 392s Sep 11 23:07:49 autopkgtest kernel: EEH: pSeries platform initialized 392s Sep 11 23:07:49 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 392s Sep 11 23:07:49 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 392s Sep 11 23:07:49 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 392s Sep 11 23:07:49 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 392s Sep 11 23:07:49 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 392s Sep 11 23:07:49 autopkgtest kernel: iommu: Default domain type: Translated 392s Sep 11 23:07:49 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 392s Sep 11 23:07:49 autopkgtest kernel: SCSI subsystem initialized 392s Sep 11 23:07:49 autopkgtest kernel: libata version 3.00 loaded. 392s Sep 11 23:07:49 autopkgtest kernel: usbcore: registered new interface driver usbfs 392s Sep 11 23:07:49 autopkgtest kernel: usbcore: registered new interface driver hub 392s Sep 11 23:07:49 autopkgtest kernel: usbcore: registered new device driver usb 392s Sep 11 23:07:49 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 392s Sep 11 23:07:49 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 392s Sep 11 23:07:49 autopkgtest kernel: PTP clock support registered 392s Sep 11 23:07:49 autopkgtest kernel: EDAC MC: Ver: 3.0.0 392s Sep 11 23:07:49 autopkgtest kernel: NetLabel: Initializing 392s Sep 11 23:07:49 autopkgtest kernel: NetLabel: domain hash size = 128 392s Sep 11 23:07:49 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 392s Sep 11 23:07:49 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 392s Sep 11 23:07:49 autopkgtest kernel: mctp: management component transport protocol core 392s Sep 11 23:07:49 autopkgtest kernel: NET: Registered PF_MCTP protocol family 392s Sep 11 23:07:49 autopkgtest kernel: PCI: Probing PCI hardware 392s Sep 11 23:07:49 autopkgtest kernel: PCI host bridge to bus 0000:00 392s Sep 11 23:07:49 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 392s Sep 11 23:07:49 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 392s Sep 11 23:07:49 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 392s Sep 11 23:07:49 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:05.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:06.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:07.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 392s Sep 11 23:07:49 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 392s Sep 11 23:07:49 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 392s Sep 11 23:07:49 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 392s Sep 11 23:07:49 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 392s Sep 11 23:07:49 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:05.0: Adding to iommu group 0 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:06.0: Adding to iommu group 0 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:07.0: Adding to iommu group 0 392s Sep 11 23:07:49 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 392s Sep 11 23:07:49 autopkgtest kernel: PCI: Probing PCI hardware done 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:07.0: vgaarb: setting as boot VGA device 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:07.0: vgaarb: bridge control possible 392s Sep 11 23:07:49 autopkgtest kernel: pci 0000:00:07.0: vgaarb: VGA device added: decodes=io+mem,owns=mem,locks=none 392s Sep 11 23:07:49 autopkgtest kernel: vgaarb: loaded 392s Sep 11 23:07:49 autopkgtest kernel: clocksource: Switched to clocksource timebase 392s Sep 11 23:07:49 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 392s Sep 11 23:07:49 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 392s Sep 11 23:07:49 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 392s Sep 11 23:07:49 autopkgtest kernel: NET: Registered PF_INET protocol family 392s Sep 11 23:07:49 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 392s Sep 11 23:07:49 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 392s Sep 11 23:07:49 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 392s Sep 11 23:07:49 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 392s Sep 11 23:07:49 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 392s Sep 11 23:07:49 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 392s Sep 11 23:07:49 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 392s Sep 11 23:07:49 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 392s Sep 11 23:07:49 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 392s Sep 11 23:07:49 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 392s Sep 11 23:07:49 autopkgtest kernel: NET: Registered PF_XDP protocol family 392s Sep 11 23:07:49 autopkgtest kernel: PCI: CLS 0 bytes, default 128 392s Sep 11 23:07:49 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 392s Sep 11 23:07:49 autopkgtest kernel: Initialise system trusted keyrings 392s Sep 11 23:07:49 autopkgtest kernel: Key type blacklist registered 392s Sep 11 23:07:49 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 392s Sep 11 23:07:49 autopkgtest kernel: zbud: loaded 392s Sep 11 23:07:49 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 392s Sep 11 23:07:49 autopkgtest kernel: fuse: init (API version 7.39) 392s Sep 11 23:07:49 autopkgtest kernel: integrity: Platform Keyring initialized 392s Sep 11 23:07:49 autopkgtest kernel: integrity: Machine keyring initialized 392s Sep 11 23:07:49 autopkgtest kernel: Key type asymmetric registered 392s Sep 11 23:07:49 autopkgtest kernel: Asymmetric key parser 'x509' registered 392s Sep 11 23:07:49 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 392s Sep 11 23:07:49 autopkgtest kernel: io scheduler mq-deadline registered 392s Sep 11 23:07:49 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 392s Sep 11 23:07:49 autopkgtest kernel: virtio-pci 0000:00:01.0: ibm,query-pe-dma-windows(2026) 800 8000000 20000000 returned 0, lb=80000000 ps=7 wn=1 392s Sep 11 23:07:49 autopkgtest kernel: virtio-pci 0000:00:01.0: ibm,create-pe-dma-window(2027) 800 8000000 20000000 18 21 returned 0 (liobn = 0x80000001 starting addr = 8000000 0) 392s Sep 11 23:07:49 autopkgtest kernel: virtio-pci 0000:00:03.0: enabling device (0100 -> 0103) 392s Sep 11 23:07:49 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 392s Sep 11 23:07:49 autopkgtest kernel: virtio-pci 0000:00:05.0: enabling device (0100 -> 0103) 392s Sep 11 23:07:49 autopkgtest kernel: virtio-pci 0000:00:06.0: enabling device (0100 -> 0103) 392s Sep 11 23:07:49 autopkgtest kernel: printk: legacy console [hvc0] enabled 392s Sep 11 23:07:49 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 392s Sep 11 23:07:49 autopkgtest kernel: Freeing initrd memory: 50944K 392s Sep 11 23:07:49 autopkgtest kernel: Non-volatile memory driver v1.3 392s Sep 11 23:07:49 autopkgtest kernel: Linux agpgart interface v0.103 392s Sep 11 23:07:49 autopkgtest kernel: loop: module loaded 392s Sep 11 23:07:49 autopkgtest kernel: virtio_blk virtio2: 4/0/0 default/read/poll queues 392s Sep 11 23:07:49 autopkgtest kernel: virtio_blk virtio2: [vda] 209715200 512-byte logical blocks (107 GB/100 GiB) 392s Sep 11 23:07:49 autopkgtest kernel: vda: vda1 vda2 392s Sep 11 23:07:49 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 392s Sep 11 23:07:49 autopkgtest kernel: PPP generic driver version 2.4.2 392s Sep 11 23:07:49 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 392s Sep 11 23:07:49 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 392s Sep 11 23:07:49 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-09-11T23:07:47 UTC (1726096067) 392s Sep 11 23:07:49 autopkgtest kernel: i2c_dev: i2c /dev entries driver 392s Sep 11 23:07:49 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 392s Sep 11 23:07:49 autopkgtest kernel: device-mapper: uevent: version 1.0.3 392s Sep 11 23:07:49 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@redhat.com 392s Sep 11 23:07:49 autopkgtest kernel: pseries_idle_driver registered 392s Sep 11 23:07:49 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 392s Sep 11 23:07:49 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 392s Sep 11 23:07:49 autopkgtest kernel: NET: Registered PF_INET6 protocol family 392s Sep 11 23:07:49 autopkgtest kernel: Segment Routing with IPv6 392s Sep 11 23:07:49 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 392s Sep 11 23:07:49 autopkgtest kernel: NET: Registered PF_PACKET protocol family 392s Sep 11 23:07:49 autopkgtest kernel: Key type dns_resolver registered 392s Sep 11 23:07:49 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 392s Sep 11 23:07:49 autopkgtest kernel: drmem: No dynamic reconfiguration memory found 392s Sep 11 23:07:49 autopkgtest kernel: registered taskstats version 1 392s Sep 11 23:07:49 autopkgtest kernel: Loading compiled-in X.509 certificates 392s Sep 11 23:07:49 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 392s Sep 11 23:07:49 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 392s Sep 11 23:07:49 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 392s Sep 11 23:07:49 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 392s Sep 11 23:07:49 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 392s Sep 11 23:07:49 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 392s Sep 11 23:07:49 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 392s Sep 11 23:07:49 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 392s Sep 11 23:07:49 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 392s Sep 11 23:07:49 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 392s Sep 11 23:07:49 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 392s Sep 11 23:07:49 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 392s Sep 11 23:07:49 autopkgtest kernel: Key type .fscrypt registered 392s Sep 11 23:07:49 autopkgtest kernel: Key type fscrypt-provisioning registered 392s Sep 11 23:07:49 autopkgtest kernel: Key type encrypted registered 392s Sep 11 23:07:49 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 392s Sep 11 23:07:49 autopkgtest kernel: Secure boot mode disabled 392s Sep 11 23:07:49 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 392s Sep 11 23:07:49 autopkgtest kernel: Loading compiled-in module X.509 certificates 392s Sep 11 23:07:49 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 392s Sep 11 23:07:49 autopkgtest kernel: ima: Allocated hash algorithm: sha256 392s Sep 11 23:07:49 autopkgtest kernel: Secure boot mode disabled 392s Sep 11 23:07:49 autopkgtest kernel: Trusted boot mode disabled 392s Sep 11 23:07:49 autopkgtest kernel: ima: No architecture policies found 392s Sep 11 23:07:49 autopkgtest kernel: evm: Initialising EVM extended attributes: 392s Sep 11 23:07:49 autopkgtest kernel: evm: security.selinux 392s Sep 11 23:07:49 autopkgtest kernel: evm: security.SMACK64 392s Sep 11 23:07:49 autopkgtest kernel: evm: security.SMACK64EXEC 392s Sep 11 23:07:49 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 392s Sep 11 23:07:49 autopkgtest kernel: evm: security.SMACK64MMAP 392s Sep 11 23:07:49 autopkgtest kernel: evm: security.apparmor 392s Sep 11 23:07:49 autopkgtest kernel: evm: security.ima 392s Sep 11 23:07:49 autopkgtest kernel: evm: security.capability 392s Sep 11 23:07:49 autopkgtest kernel: evm: HMAC attrs: 0x1 392s Sep 11 23:07:49 autopkgtest kernel: SED: plpks not available 392s Sep 11 23:07:49 autopkgtest kernel: clk: Disabling unused clocks 392s Sep 11 23:07:49 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 392s Sep 11 23:07:49 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8832K 392s Sep 11 23:07:49 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 392s Sep 11 23:07:49 autopkgtest kernel: Run /init as init process 392s Sep 11 23:07:49 autopkgtest kernel: with arguments: 392s Sep 11 23:07:49 autopkgtest kernel: /init 392s Sep 11 23:07:49 autopkgtest kernel: earlyprintk 392s Sep 11 23:07:49 autopkgtest kernel: with environment: 392s Sep 11 23:07:49 autopkgtest kernel: HOME=/ 392s Sep 11 23:07:49 autopkgtest kernel: TERM=linux 392s Sep 11 23:07:49 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic 392s Sep 11 23:07:49 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 392s Sep 11 23:07:49 autopkgtest kernel: random: crng init done 392s Sep 11 23:07:49 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 392s Sep 11 23:07:49 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 1 392s Sep 11 23:07:49 autopkgtest kernel: xhci_hcd 0000:00:02.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010 392s Sep 11 23:07:49 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 392s Sep 11 23:07:49 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2 392s Sep 11 23:07:49 autopkgtest kernel: xhci_hcd 0000:00:02.0: Host supports USB 3.0 SuperSpeed 392s Sep 11 23:07:49 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.08 392s Sep 11 23:07:49 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 392s Sep 11 23:07:49 autopkgtest kernel: usb usb1: Product: xHCI Host Controller 392s Sep 11 23:07:49 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 392s Sep 11 23:07:49 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:02.0 392s Sep 11 23:07:49 autopkgtest kernel: hub 1-0:1.0: USB hub found 392s Sep 11 23:07:49 autopkgtest kernel: [drm] Found bochs VGA, ID 0xb0c5. 392s Sep 11 23:07:49 autopkgtest kernel: hub 1-0:1.0: 4 ports detected 392s Sep 11 23:07:49 autopkgtest kernel: [drm] Framebuffer size 16384 kB @ 0x200081000000, mmio @ 0x200082000000. 392s Sep 11 23:07:49 autopkgtest kernel: [drm] Found EDID data blob. 392s Sep 11 23:07:49 autopkgtest kernel: [drm] Initialized bochs-drm 1.0.0 20130925 for 0000:00:07.0 on minor 0 392s Sep 11 23:07:49 autopkgtest kernel: usb usb2: We don't know the algorithms for LPM for this host, disabling LPM. 392s Sep 11 23:07:49 autopkgtest kernel: fbcon: Deferring console take-over 392s Sep 11 23:07:49 autopkgtest kernel: bochs-drm 0000:00:07.0: [drm] fb0: bochs-drmdrmfb frame buffer device 392s Sep 11 23:07:49 autopkgtest kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.08 392s Sep 11 23:07:49 autopkgtest kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 392s Sep 11 23:07:49 autopkgtest kernel: usb usb2: Product: xHCI Host Controller 392s Sep 11 23:07:49 autopkgtest kernel: usb usb2: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 392s Sep 11 23:07:49 autopkgtest kernel: usb usb2: SerialNumber: 0000:00:02.0 392s Sep 11 23:07:49 autopkgtest kernel: hub 2-0:1.0: USB hub found 392s Sep 11 23:07:49 autopkgtest kernel: hub 2-0:1.0: 4 ports detected 392s Sep 11 23:07:49 autopkgtest kernel: raid6: vpermxor8 gen() 19500 MB/s 392s Sep 11 23:07:49 autopkgtest kernel: raid6: vpermxor4 gen() 16716 MB/s 392s Sep 11 23:07:49 autopkgtest kernel: usb 1-1: new high-speed USB device number 2 using xhci_hcd 392s Sep 11 23:07:49 autopkgtest kernel: raid6: vpermxor2 gen() 15632 MB/s 392s Sep 11 23:07:49 autopkgtest kernel: raid6: vpermxor1 gen() 11361 MB/s 392s Sep 11 23:07:49 autopkgtest kernel: usb 1-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 392s Sep 11 23:07:49 autopkgtest kernel: usb 1-1: New USB device strings: Mfr=1, Product=4, SerialNumber=11 392s Sep 11 23:07:49 autopkgtest kernel: usb 1-1: Product: QEMU USB Keyboard 392s Sep 11 23:07:49 autopkgtest kernel: usb 1-1: Manufacturer: QEMU 392s Sep 11 23:07:49 autopkgtest kernel: usb 1-1: SerialNumber: 68284-pci@800000020000000:02.0-1 392s Sep 11 23:07:49 autopkgtest kernel: hid: raw HID events driver (C) Jiri Kosina 392s Sep 11 23:07:49 autopkgtest kernel: usbcore: registered new interface driver usbhid 392s Sep 11 23:07:49 autopkgtest kernel: usbhid: USB HID core driver 392s Sep 11 23:07:49 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 392s Sep 11 23:07:49 autopkgtest kernel: raid6: altivecx8 gen() 13353 MB/s 392s Sep 11 23:07:49 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 392s Sep 11 23:07:49 autopkgtest kernel: raid6: altivecx4 gen() 11572 MB/s 392s Sep 11 23:07:49 autopkgtest kernel: usb 1-2: new high-speed USB device number 3 using xhci_hcd 392s Sep 11 23:07:49 autopkgtest kernel: raid6: altivecx2 gen() 9984 MB/s 392s Sep 11 23:07:49 autopkgtest kernel: raid6: altivecx1 gen() 8478 MB/s 392s Sep 11 23:07:49 autopkgtest kernel: usb 1-2: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 392s Sep 11 23:07:49 autopkgtest kernel: usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=9 392s Sep 11 23:07:49 autopkgtest kernel: usb 1-2: Product: QEMU USB Mouse 392s Sep 11 23:07:49 autopkgtest kernel: usb 1-2: Manufacturer: QEMU 392s Sep 11 23:07:49 autopkgtest kernel: usb 1-2: SerialNumber: 89126-pci@800000020000000:02.0-2 392s Sep 11 23:07:49 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 392s Sep 11 23:07:49 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 392s Sep 11 23:07:49 autopkgtest kernel: raid6: int64x8 gen() 6697 MB/s 392s Sep 11 23:07:49 autopkgtest kernel: raid6: int64x4 gen() 7236 MB/s 392s Sep 11 23:07:49 autopkgtest kernel: raid6: int64x2 gen() 5378 MB/s 392s Sep 11 23:07:49 autopkgtest kernel: raid6: int64x1 gen() 4845 MB/s 392s Sep 11 23:07:49 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 19500 MB/s 392s Sep 11 23:07:49 autopkgtest kernel: raid6: using intx1 recovery algorithm 392s Sep 11 23:07:49 autopkgtest kernel: xor: measuring software checksum speed 392s Sep 11 23:07:49 autopkgtest kernel: 8regs : 16934 MB/sec 392s Sep 11 23:07:49 autopkgtest kernel: 8regs_prefetch : 14538 MB/sec 392s Sep 11 23:07:49 autopkgtest kernel: 32regs : 17327 MB/sec 392s Sep 11 23:07:49 autopkgtest kernel: 32regs_prefetch : 15680 MB/sec 392s Sep 11 23:07:49 autopkgtest kernel: altivec : 18968 MB/sec 392s Sep 11 23:07:49 autopkgtest kernel: xor: using function: altivec (18968 MB/sec) 392s Sep 11 23:07:49 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 392s Sep 11 23:07:49 autopkgtest kernel: EXT4-fs (vda1): orphan cleanup on readonly fs 392s Sep 11 23:07:49 autopkgtest kernel: EXT4-fs (vda1): mounted filesystem 657a72a9-f878-4085-b334-21a63fc7c218 ro with ordered data mode. Quota mode: none. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Inserted module 'autofs4' 392s Sep 11 23:07:49 autopkgtest systemd[1]: systemd 256.5-2ubuntu2 running in system mode (+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -XKBCOMMON +UTMP +SYSVINIT +LIBARCHIVE) 392s Sep 11 23:07:49 autopkgtest systemd[1]: Detected virtualization kvm. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Detected architecture ppc64-le. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Hostname set to . 392s Sep 11 23:07:49 autopkgtest systemd[1]: bpf-restrict-fs: BPF LSM hook not enabled in the kernel, BPF LSM not supported. 392s Sep 11 23:07:49 autopkgtest kernel: NET: Registered PF_VSOCK protocol family 392s Sep 11 23:07:49 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Queued start job for default target graphical.target. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Reached target swap.target - Swaps. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 392s Sep 11 23:07:49 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Sockets. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounting run-lock.mount - Legacy Locks Directory /run/lock... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting modprobe@dm_multipath.service - Load Kernel Module dm_multipath... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 392s Sep 11 23:07:49 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 392s Sep 11 23:07:49 autopkgtest systemd[1]: systemd-fsck-root.service - File System Check on Root Device was skipped because of an unmet condition check (ConditionPathExists=!/run/initramfs/fsck-root). 392s Sep 11 23:07:49 autopkgtest systemd[1]: systemd-hibernate-clear.service - Clear Stale Hibernate Storage Info was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67). 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 392s Sep 11 23:07:49 autopkgtest systemd-journald[282]: Collecting audit messages is disabled. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounted run-lock.mount - Legacy Locks Directory /run/lock. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 392s Sep 11 23:07:49 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 392s Sep 11 23:07:49 autopkgtest systemd[1]: modprobe@dm_multipath.service: Deactivated successfully. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished modprobe@dm_multipath.service - Load Kernel Module dm_multipath. 392s Sep 11 23:07:49 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 392s Sep 11 23:07:49 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 392s Sep 11 23:07:49 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 392s Sep 11 23:07:49 autopkgtest systemd-journald[282]: Journal started 392s Sep 11 23:07:49 autopkgtest systemd-journald[282]: Runtime Journal (/run/log/journal/6b22c00fdca94942b65cc88cb7c7873e) is 8M, max 78.4M, 70.4M free. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 392s Sep 11 23:07:49 autopkgtest kernel: EXT4-fs (vda1): re-mounted 657a72a9-f878-4085-b334-21a63fc7c218 r/w. Quota mode: none. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting cloud-init-main.service - Cloud-init: Single Process... 392s Sep 11 23:07:49 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 392s Sep 11 23:07:49 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 392s Sep 11 23:07:49 autopkgtest systemd-journald[282]: Time spent on flushing to /var/log/journal/6b22c00fdca94942b65cc88cb7c7873e is 41.568ms for 458 entries. 392s Sep 11 23:07:49 autopkgtest systemd-journald[282]: System Journal (/var/log/journal/6b22c00fdca94942b65cc88cb7c7873e) is 19M, max 4G, 3.9G free. 392s Sep 11 23:07:49 autopkgtest systemd-journald[282]: Received client request to flush runtime journal. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 392s Sep 11 23:07:49 autopkgtest multipathd[328]: multipathd v0.9.9: start up 392s Sep 11 23:07:49 autopkgtest multipathd[328]: reconfigure: setting up paths and maps 392s Sep 11 23:07:49 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 392s Sep 11 23:07:49 autopkgtest apparmor.systemd[348]: Restarting AppArmor 392s Sep 11 23:07:49 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 392s Sep 11 23:07:49 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 392s Sep 11 23:07:49 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 352 (systemd-binfmt) 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... 392s Sep 11 23:07:49 autopkgtest apparmor.systemd[348]: Reloading AppArmor profiles 392s Sep 11 23:07:49 autopkgtest systemd-tmpfiles[367]: /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 392s Sep 11 23:07:49 autopkgtest systemd-udevd[347]: Using default interface naming scheme 'v255'. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 392s Sep 11 23:07:49 autopkgtest kernel: audit: type=1400 audit(1726096069.596:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=373 comm="apparmor_parser" 392s Sep 11 23:07:49 autopkgtest kernel: audit: type=1400 audit(1726096069.596:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=376 comm="apparmor_parser" 392s Sep 11 23:07:49 autopkgtest kernel: audit: type=1400 audit(1726096069.596:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=374 comm="apparmor_parser" 392s Sep 11 23:07:49 autopkgtest kernel: audit: type=1400 audit(1726096069.596:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=375 comm="apparmor_parser" 392s Sep 11 23:07:49 autopkgtest kernel: audit: type=1400 audit(1726096069.600:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=379 comm="apparmor_parser" 392s Sep 11 23:07:49 autopkgtest kernel: audit: type=1400 audit(1726096069.600:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=380 comm="apparmor_parser" 392s Sep 11 23:07:49 autopkgtest kernel: audit: type=1400 audit(1726096069.600:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=381 comm="apparmor_parser" 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. 392s Sep 11 23:07:49 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 392s Sep 11 23:07:49 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 392s Sep 11 23:07:49 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 392s Sep 11 23:07:49 autopkgtest systemd[1]: systemd-machine-id-commit.service - Save Transient machine-id to Disk was skipped because of an unmet condition check (ConditionPathIsMountPoint=/etc/machine-id). 392s Sep 11 23:07:49 autopkgtest kernel: audit: type=1400 audit(1726096069.604:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="cam" pid=383 comm="apparmor_parser" 392s Sep 11 23:07:49 autopkgtest kernel: audit: type=1400 audit(1726096069.604:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="busybox" pid=382 comm="apparmor_parser" 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 392s Sep 11 23:07:49 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 392s Sep 11 23:07:49 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 392s Sep 11 23:07:49 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 392s Sep 11 23:07:49 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 392s Sep 11 23:07:49 autopkgtest systemd[1]: systemd-ask-password-plymouth.path - Forward Password Requests to Plymouth Directory Watch was skipped because of an unmet condition check (ConditionPathExists=/run/plymouth/pid). 392s Sep 11 23:07:49 autopkgtest systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 392s Sep 11 23:07:49 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 392s Sep 11 23:07:49 autopkgtest (udev-worker)[467]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 392s Sep 11 23:07:49 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 392s Sep 11 23:07:50 autopkgtest systemd[1]: Started cloud-init-main.service - Cloud-init: Single Process. 392s Sep 11 23:07:50 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 392s Sep 11 23:07:50 autopkgtest cloud-init[681]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 running 'init-local' at Wed, 11 Sep 2024 23:07:50 +0000. Up 3.10 seconds. 392s Sep 11 23:07:50 autopkgtest dhcpcd[684]: dhcpcd-10.0.8 starting 392s Sep 11 23:07:50 autopkgtest dhcpcd[687]: DUID 00:01:00:01:2e:74:7d:3d:fa:16:3e:c1:1f:7b 392s Sep 11 23:07:50 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 392s Sep 11 23:07:50 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 392s Sep 11 23:07:50 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 392s Sep 11 23:07:50 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 392s Sep 11 23:07:50 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 392s Sep 11 23:07:50 autopkgtest dhcpcd[687]: enp0s1: IAID 3e:43:0e:da 392s Sep 11 23:07:50 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 392s Sep 11 23:07:50 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 392s Sep 11 23:07:50 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 392s Sep 11 23:07:50 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 392s Sep 11 23:07:50 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 392s Sep 11 23:07:50 autopkgtest systemd-resolved[393]: Positive Trust Anchors: 392s Sep 11 23:07:50 autopkgtest systemd-resolved[393]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 392s Sep 11 23:07:50 autopkgtest systemd-resolved[393]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 170.0.0.192.in-addr.arpa 171.0.0.192.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa ipv4only.arpa resolver.arpa corp home internal intranet lan local private test 392s Sep 11 23:07:50 autopkgtest systemd-resolved[393]: Using system hostname 'autopkgtest'. 392s Sep 11 23:07:50 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 392s Sep 11 23:07:50 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 392s Sep 11 23:07:50 autopkgtest dhcpcd[687]: enp0s1: rebinding lease of 10.145.227.75 392s Sep 11 23:07:50 autopkgtest dhcpcd[687]: enp0s1: leased 10.145.227.75 for 43200 seconds 392s Sep 11 23:07:50 autopkgtest dhcpcd[687]: enp0s1: adding route to 10.145.227.0/24 392s Sep 11 23:07:50 autopkgtest dhcpcd[687]: enp0s1: adding host route to 169.254.169.254 via 10.145.227.2 392s Sep 11 23:07:50 autopkgtest dhcpcd[687]: enp0s1: adding default route via 10.145.227.1 392s Sep 11 23:07:50 autopkgtest dhcpcd[687]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 392s Sep 11 23:07:55 autopkgtest sh[677]: Completed socket interaction for boot stage local 392s Sep 11 23:07:55 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 392s Sep 11 23:07:55 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 392s Sep 11 23:07:55 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 392s Sep 11 23:07:56 autopkgtest systemd-networkd[721]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 392s Sep 11 23:07:56 autopkgtest systemd-networkd[721]: lo: Link UP 392s Sep 11 23:07:56 autopkgtest systemd-networkd[721]: lo: Gained carrier 392s Sep 11 23:07:56 autopkgtest systemd-networkd[721]: Enumeration completed 392s Sep 11 23:07:56 autopkgtest systemd-networkd[721]: enp0s1: Link UP 392s Sep 11 23:07:56 autopkgtest systemd-networkd[721]: enp0s1: Gained carrier 392s Sep 11 23:07:56 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 392s Sep 11 23:07:56 autopkgtest systemd-networkd[721]: enp0s1: Gained IPv6LL 392s Sep 11 23:07:56 autopkgtest systemd-timesyncd[394]: Network configuration changed, trying to establish connection. 392s Sep 11 23:07:56 autopkgtest systemd-networkd[721]: enp0s1: Link DOWN 392s Sep 11 23:07:56 autopkgtest systemd-networkd[721]: enp0s1: Lost carrier 392s Sep 11 23:07:56 autopkgtest systemd[1]: Reached target network.target - Network. 392s Sep 11 23:07:56 autopkgtest systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... 392s Sep 11 23:07:56 autopkgtest systemd-networkd[721]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 392s Sep 11 23:07:56 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 392s Sep 11 23:07:56 autopkgtest systemd-networkd[721]: enp0s1: Link UP 392s Sep 11 23:07:56 autopkgtest systemd-networkd[721]: enp0s1: Gained carrier 392s Sep 11 23:07:56 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 392s Sep 11 23:07:56 autopkgtest systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. 392s Sep 11 23:07:56 autopkgtest systemd-networkd[721]: enp0s1: DHCPv4 address 10.145.227.75/24, gateway 10.145.227.1 acquired from 10.145.227.1 392s Sep 11 23:07:56 autopkgtest systemd-timesyncd[394]: Network configuration changed, trying to establish connection. 392s Sep 11 23:07:57 autopkgtest systemd-networkd[721]: enp0s1: Gained IPv6LL 392s Sep 11 23:07:57 autopkgtest systemd-timesyncd[394]: Network configuration changed, trying to establish connection. 392s Sep 11 23:07:57 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 392s Sep 11 23:07:57 autopkgtest systemd[1]: Starting cloud-init-network.service - Cloud-init: Network Stage... 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 running 'init' at Wed, 11 Sep 2024 23:07:57 +0000. Up 10.74 seconds. 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: ++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: +--------+------+-----------------------------+---------------+--------+-------------------+ 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: +--------+------+-----------------------------+---------------+--------+-------------------+ 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | enp0s1 | True | 10.145.227.75 | 255.255.255.0 | global | fa:16:3e:43:0e:da | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | enp0s1 | True | fe80::f816:3eff:fe43:eda/64 | . | link | fa:16:3e:43:0e:da | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | lo | True | ::1/128 | . | host | . | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: +--------+------+-----------------------------+---------------+--------+-------------------+ 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++++ 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | 0 | 0.0.0.0 | 10.145.227.1 | 0.0.0.0 | enp0s1 | UG | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | 1 | 10.145.227.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | 2 | 10.145.227.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | 3 | 10.145.227.2 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | 4 | 91.189.91.131 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | 5 | 91.189.91.132 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | 6 | 169.254.169.254 | 10.145.227.2 | 255.255.255.255 | enp0s1 | UGH | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: +-------+-------------+---------+-----------+-------+ 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | Route | Destination | Gateway | Interface | Flags | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: +-------+-------------+---------+-----------+-------+ 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | 2 | local | :: | enp0s1 | U | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: | 3 | multicast | :: | enp0s1 | U | 392s Sep 11 23:07:57 autopkgtest cloud-init[681]: ci-info: +-------+-------------+---------+-----------+-------+ 392s Sep 11 23:07:58 autopkgtest cloud-init[681]: 2024-09-11 23:07:58,089 - log.py[DEPRECATED]: Deprecated cloud-config provided: apt_update: Deprecated in version 22.2. Use **package_update** instead., apt_upgrade: Deprecated in version 22.2. Use **package_upgrade** instead. 392s Sep 11 23:07:58 autopkgtest cloud-init[681]: 2024-09-11 23:07:58,089 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 392s Sep 11 23:07:58 autopkgtest sh[732]: Completed socket interaction for boot stage network 392s Sep 11 23:07:58 autopkgtest systemd[1]: Finished cloud-init-network.service - Cloud-init: Network Stage. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 392s Sep 11 23:07:58 autopkgtest systemd[1]: apport-autoreport.path - Process error reports when automatic reporting is enabled (file watch) was skipped because of an unmet condition check (ConditionPathExists=/var/lib/apport/autoreport). 392s Sep 11 23:07:58 autopkgtest systemd[1]: apport-autoreport.timer - Process error reports when automatic reporting is enabled (timer based) was skipped because of an unmet condition check (ConditionPathExists=/var/lib/apport/autoreport). 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started sysstat-collect.timer - Run system activity accounting tool every 10 minutes. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started sysstat-rotate.timer - Rotate daily system activity data file at midnight. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started sysstat-summary.timer - Generate summary of yesterday's process accounting. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 392s Sep 11 23:07:58 autopkgtest systemd[1]: ua-timer.timer - Ubuntu Pro Timer for running repeated jobs was skipped because of an unmet condition check (ConditionPathExists=/var/lib/ubuntu-advantage/private/machine-token.json). 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target paths.target - Path Units. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 392s Sep 11 23:07:58 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 392s Sep 11 23:07:58 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). 392s Sep 11 23:07:58 autopkgtest systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target ssh-access.target - SSH Access Available. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target basic.target - Basic System. 392s Sep 11 23:07:58 autopkgtest systemd[1]: System is tainted: unmerged-bin 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 392s Sep 11 23:07:58 autopkgtest (sh)[767]: autopkgtest@hvc1.service: Failed to set up standard input: No such device 392s Sep 11 23:07:58 autopkgtest (sh)[767]: autopkgtest@hvc1.service: Failed at step STDIN spawning /bin/sh: No such device 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 392s Sep 11 23:07:58 autopkgtest (sh)[768]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 392s Sep 11 23:07:58 autopkgtest (sh)[768]: autopkgtest@ttyS1.service: Failed at step STDIN spawning /bin/sh: Input/output error 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 392s Sep 11 23:07:58 autopkgtest (cron)[770]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 392s Sep 11 23:07:58 autopkgtest systemd[1]: getty-static.service - getty on tty2-tty6 if dbus and logind are not available was skipped because of an unmet condition check (ConditionPathExists=!/usr/bin/dbus-daemon). 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 392s Sep 11 23:07:58 autopkgtest cron[770]: (CRON) INFO (pidfile fd = 3) 392s Sep 11 23:07:58 autopkgtest cron[770]: (CRON) INFO (Running @reboot jobs) 392s Sep 11 23:07:58 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 392s Sep 11 23:07:58 autopkgtest systemd[1]: opal_errd.service - opal_errd (PowerNV platform error handling) Service was skipped because of an unmet condition check (ConditionVirtualization=false). 392s Sep 11 23:07:58 autopkgtest systemd[1]: pollinate.service - Pollinate to seed the pseudo random number generator was skipped because of an unmet condition check (ConditionPathExists=!/var/cache/pollinate/seeded). 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting sysstat.service - Resets System Activity Logs... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 392s Sep 11 23:07:58 autopkgtest systemd[1]: ua-reboot-cmds.service - Ubuntu Pro reboot cmds was skipped because of an unmet condition check (ConditionPathExists=/var/lib/ubuntu-advantage/private/machine-token.json). 392s Sep 11 23:07:58 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 392s Sep 11 23:07:58 autopkgtest systemd[1]: autopkgtest@hvc1.service: Deactivated successfully. 392s Sep 11 23:07:58 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 392s Sep 11 23:07:58 autopkgtest dbus-daemon[771]: [system] AppArmor D-Bus mediation is enabled 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 392s Sep 11 23:07:58 autopkgtest udisksd[788]: udisks daemon version 2.10.1 starting 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Finished sysstat.service - Resets System Activity Logs. 392s Sep 11 23:07:58 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 392s Sep 11 23:07:58 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 392s Sep 11 23:07:58 autopkgtest rngd[847]: rngd 2.4 starting up... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 392s Sep 11 23:07:58 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 392s Sep 11 23:07:58 autopkgtest rngd[847]: entropy feed to the kernel ready 392s Sep 11 23:07:58 autopkgtest systemd-logind[786]: New seat seat0. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 392s Sep 11 23:07:58 autopkgtest cloud-init[681]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 running 'modules:config' at Wed, 11 Sep 2024 23:07:58 +0000. Up 11.16 seconds. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 392s Sep 11 23:07:58 autopkgtest systemd-logind[786]: Watching system buttons on /dev/input/event0 (QEMU QEMU USB Keyboard) 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 392s Sep 11 23:07:58 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 392s Sep 11 23:07:58 autopkgtest kernel: kauditd_printk_skb: 110 callbacks suppressed 392s Sep 11 23:07:58 autopkgtest kernel: audit: type=1400 audit(1726096078.452:121): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=840 comm="apparmor_parser" 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 392s Sep 11 23:07:58 autopkgtest udisksd[788]: Acquired the name org.freedesktop.UDisks2 on the system message bus 392s Sep 11 23:07:58 autopkgtest sh[774]: Completed socket interaction for boot stage config 392s Sep 11 23:07:58 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 392s Sep 11 23:07:58 autopkgtest rsyslogd[872]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2406.0] 392s Sep 11 23:07:58 autopkgtest rsyslogd[872]: rsyslogd's groupid changed to 102 392s Sep 11 23:07:58 autopkgtest rsyslogd[872]: rsyslogd's userid changed to 102 392s Sep 11 23:07:58 autopkgtest rsyslogd[872]: [origin software="rsyslogd" swVersion="8.2406.0" x-pid="872" x-info="https://www.rsyslog.com"] start 392s Sep 11 23:07:58 autopkgtest sshd[877]: Server listening on :: port 22. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 392s Sep 11 23:07:58 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 392s Sep 11 23:07:58 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 392s Sep 11 23:07:58 autopkgtest cloud-init[681]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 running 'modules:final' at Wed, 11 Sep 2024 23:07:58 +0000. Up 11.47 seconds. 392s Sep 11 23:07:58 autopkgtest cloud-init[681]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu2 finished at Wed, 11 Sep 2024 23:07:58 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 11.55 seconds 392s Sep 11 23:07:58 autopkgtest sh[889]: Completed socket interaction for boot stage final 392s Sep 11 23:07:58 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 392s Sep 11 23:07:58 autopkgtest systemd[1]: Startup finished in 1.781s (kernel) + 9.782s (userspace) = 11.564s. 392s Sep 11 23:07:58 autopkgtest kernel: fbcon: Taking over console 392s Sep 11 23:07:58 autopkgtest kernel: Console: switching to colour frame buffer device 128x48 392s Sep 11 23:07:58 autopkgtest systemd[1]: cloud-init-main.service: Deactivated successfully. 392s Sep 11 23:07:58 autopkgtest systemd[1]: cloud-init-main.service: Unit process 680 (sh) remains running after unit stopped. 392s Sep 11 23:07:58 autopkgtest systemd[1]: cloud-init-main.service: Consumed 1.209s CPU time, 109.3M memory peak. 392s Sep 11 23:07:58 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 392s Sep 11 23:07:59 autopkgtest sshd[882]: Accepted publickey for ubuntu from 10.136.6.184 port 37466 ssh2: RSA SHA256:h+sR5tlNZDfTFbz7cAH7wlRKfPAD8MpCdKJaoGeL2vg 392s Sep 11 23:07:59 autopkgtest sshd[882]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 392s Sep 11 23:07:59 autopkgtest sshd[882]: pam_systemd(sshd:session): New sd-bus connection (system-bus-pam-systemd-882) opened. 392s Sep 11 23:07:59 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 392s Sep 11 23:07:59 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 392s Sep 11 23:07:59 autopkgtest systemd-logind[786]: New session 1 of user ubuntu. 392s Sep 11 23:07:59 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 392s Sep 11 23:07:59 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 392s Sep 11 23:07:59 autopkgtest (systemd)[941]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 392s Sep 11 23:07:59 autopkgtest systemd-logind[786]: New session 2 of user ubuntu. 392s Sep 11 23:07:59 autopkgtest systemd[941]: Queued start job for default target default.target. 392s Sep 11 23:07:59 autopkgtest systemd[941]: Created slice app.slice - User Application Slice. 392s Sep 11 23:07:59 autopkgtest systemd[941]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 392s Sep 11 23:07:59 autopkgtest systemd[941]: Reached target paths.target - Paths. 392s Sep 11 23:07:59 autopkgtest systemd[941]: Reached target timers.target - Timers. 392s Sep 11 23:07:59 autopkgtest systemd[941]: Starting dbus.socket - D-Bus User Message Bus Socket... 392s Sep 11 23:07:59 autopkgtest systemd[941]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 392s Sep 11 23:07:59 autopkgtest systemd[941]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 392s Sep 11 23:07:59 autopkgtest systemd[941]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 392s Sep 11 23:07:59 autopkgtest systemd[941]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 392s Sep 11 23:07:59 autopkgtest systemd[941]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 392s Sep 11 23:07:59 autopkgtest systemd[941]: Listening on keyboxd.socket - GnuPG public key management service. 392s Sep 11 23:07:59 autopkgtest systemd[941]: Listening on dbus.socket - D-Bus User Message Bus Socket. 392s Sep 11 23:07:59 autopkgtest systemd[941]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 392s Sep 11 23:07:59 autopkgtest systemd[941]: Reached target sockets.target - Sockets. 392s Sep 11 23:07:59 autopkgtest systemd[941]: Reached target basic.target - Basic System. 392s Sep 11 23:07:59 autopkgtest systemd[941]: Reached target default.target - Main User Target. 392s Sep 11 23:07:59 autopkgtest systemd[941]: Startup finished in 149ms. 392s Sep 11 23:07:59 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 392s Sep 11 23:07:59 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 392s Sep 11 23:07:59 autopkgtest sudo[969]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 392s Sep 11 23:07:59 autopkgtest sudo[969]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:07:59 autopkgtest sudo[969]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:00 autopkgtest sudo[974]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper /bin/sh -ec 'for d in /var/cache /home; do if [ -e $d/autopkgtest-tmpdir.tar ]; then /bin/tar --warning=none --extract --absolute-names -f $d/autopkgtest-tmpdir.tar; /bin/rm $d/autopkgtest-tmpdir.tar; exit 0; fi; done; exit 1' 392s Sep 11 23:08:00 autopkgtest sudo[974]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:00 autopkgtest sudo[974]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:00 autopkgtest sudo[986]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.kY2Ex2 392s Sep 11 23:08:00 autopkgtest sudo[986]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:00 autopkgtest sudo[986]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:00 autopkgtest sudo[996]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.kY2Ex2/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot' 392s Sep 11 23:08:00 autopkgtest sudo[996]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:00 autopkgtest sudo[996]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:00 autopkgtest sudo[1008]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot 392s Sep 11 23:08:00 autopkgtest sudo[1008]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:00 autopkgtest sudo[1008]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:00 autopkgtest sudo[1018]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot /tmp/autopkgtest-reboot 392s Sep 11 23:08:00 autopkgtest sudo[1018]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:00 autopkgtest sudo[1018]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:01 autopkgtest sudo[1028]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot /sbin/autopkgtest-reboot 392s Sep 11 23:08:01 autopkgtest sudo[1028]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:01 autopkgtest sudo[1028]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:01 autopkgtest sudo[1038]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.kY2Ex2 392s Sep 11 23:08:01 autopkgtest sudo[1038]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:01 autopkgtest sudo[1038]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:01 autopkgtest sudo[1048]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.kY2Ex2/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot-prepare' 392s Sep 11 23:08:01 autopkgtest sudo[1048]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:01 autopkgtest sudo[1048]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:01 autopkgtest sudo[1060]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot-prepare 392s Sep 11 23:08:01 autopkgtest sudo[1060]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:01 autopkgtest sudo[1060]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:01 autopkgtest sudo[1070]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 392s Sep 11 23:08:01 autopkgtest sudo[1070]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:01 autopkgtest sudo[1070]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:01 autopkgtest sudo[1080]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 392s Sep 11 23:08:01 autopkgtest sudo[1080]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:02 autopkgtest sudo[1080]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:02 autopkgtest sudo[1090]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 392s Sep 11 23:08:02 autopkgtest sudo[1090]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:02 autopkgtest sudo[1090]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:02 autopkgtest sudo[1100]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.kY2Ex2/testbed-packages' 392s Sep 11 23:08:02 autopkgtest sudo[1100]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:02 autopkgtest sudo[1100]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:02 autopkgtest sudo[1111]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot' 392s Sep 11 23:08:02 autopkgtest sudo[1132]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:03 autopkgtest sudo[1132]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:03 autopkgtest sudo[1144]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot 392s Sep 11 23:08:03 autopkgtest sudo[1144]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:03 autopkgtest sudo[1144]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:03 autopkgtest sudo[1154]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot /tmp/autopkgtest-reboot 392s Sep 11 23:08:03 autopkgtest sudo[1154]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:03 autopkgtest sudo[1154]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:03 autopkgtest sudo[1164]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot /sbin/autopkgtest-reboot 392s Sep 11 23:08:03 autopkgtest sudo[1164]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:03 autopkgtest sudo[1164]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:03 autopkgtest sudo[1174]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.kY2Ex2 392s Sep 11 23:08:03 autopkgtest sudo[1174]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:03 autopkgtest sudo[1174]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:03 autopkgtest sudo[1184]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.kY2Ex2/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot-prepare' 392s Sep 11 23:08:03 autopkgtest sudo[1184]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:04 autopkgtest sudo[1184]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:04 autopkgtest sudo[1196]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot-prepare 392s Sep 11 23:08:04 autopkgtest sudo[1196]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:04 autopkgtest sudo[1196]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:04 autopkgtest sudo[1206]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.kY2Ex2/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 392s Sep 11 23:08:04 autopkgtest sudo[1206]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:04 autopkgtest sudo[1206]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:04 autopkgtest sudo[1216]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 392s Sep 11 23:08:04 autopkgtest sudo[1216]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:04 autopkgtest sudo[1216]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:04 autopkgtest sudo[1226]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 392s Sep 11 23:08:04 autopkgtest sudo[1226]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:04 autopkgtest sudo[1226]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:05 autopkgtest sudo[1235]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.kY2Ex2 392s Sep 11 23:08:05 autopkgtest sudo[1235]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:05 autopkgtest sudo[1235]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:05 autopkgtest sudo[1245]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.kY2Ex2/2-autopkgtest-satdep.deb' 392s Sep 11 23:08:05 autopkgtest sudo[1245]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:05 autopkgtest sudo[1245]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:05 autopkgtest sudo[1256]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.kY2Ex2/2-autopkgtest-satdep.deb 392s Sep 11 23:08:05 autopkgtest sudo[1256]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:05 autopkgtest sudo[1256]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:05 autopkgtest sudo[1266]: 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.kY2Ex2/2-autopkgtest-satdep.deb -o APT::Status-Fd=3 -o APT::Install-Recommends=false -o Dpkg::Options::=--force-confnew -o Debug::pkgProblemResolver=true 3>&2 2>&1' 392s Sep 11 23:08:05 autopkgtest sudo[1266]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:09 autopkgtest systemd[1]: Reload requested from client PID 1506 ('systemctl') (unit session-1.scope)... 392s Sep 11 23:08:09 autopkgtest systemd[1]: Reloading... 392s Sep 11 23:08:09 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:09 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:09 autopkgtest systemd[1]: Reloading finished in 197 ms. 392s Sep 11 23:08:09 autopkgtest systemd[1]: Reload requested from client PID 1556 ('systemctl') (unit session-1.scope)... 392s Sep 11 23:08:09 autopkgtest systemd[1]: Reloading... 392s Sep 11 23:08:10 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:10 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:10 autopkgtest systemd[1]: Reloading finished in 232 ms. 392s Sep 11 23:08:10 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 392s Sep 11 23:08:10 autopkgtest tgtd[1601]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 392s Sep 11 23:08:10 autopkgtest tgtd[1601]: tgtd: work_timer_start(146) use timer_fd based scheduler 392s Sep 11 23:08:10 autopkgtest tgtd[1601]: tgtd: bs_init(387) use signalfd notification 392s Sep 11 23:08:10 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 392s Sep 11 23:08:10 autopkgtest systemd[1]: Reload requested from client PID 1629 ('systemctl') (unit session-1.scope)... 392s Sep 11 23:08:10 autopkgtest systemd[1]: Reloading... 392s Sep 11 23:08:10 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:10 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:10 autopkgtest systemd[1]: Reloading finished in 248 ms. 392s Sep 11 23:08:10 autopkgtest systemd[1]: Reload requested from client PID 1671 ('systemctl') (unit session-1.scope)... 392s Sep 11 23:08:10 autopkgtest systemd[1]: Reloading... 392s Sep 11 23:08:11 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:11 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:11 autopkgtest systemd[1]: Reloading finished in 283 ms. 392s Sep 11 23:08:11 autopkgtest systemd[1]: Reload requested from client PID 1716 ('systemctl') (unit session-1.scope)... 392s Sep 11 23:08:11 autopkgtest systemd[1]: Reloading... 392s Sep 11 23:08:11 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:11 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:11 autopkgtest systemd[1]: Reloading finished in 256 ms. 392s Sep 11 23:08:11 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 392s Sep 11 23:08:11 autopkgtest systemd[1]: Reload requested from client PID 1766 ('systemctl') (unit session-1.scope)... 392s Sep 11 23:08:11 autopkgtest systemd[1]: Reloading... 392s Sep 11 23:08:11 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:11 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:12 autopkgtest systemd[1]: Reloading finished in 224 ms. 392s Sep 11 23:08:12 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 392s Sep 11 23:08:12 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 392s Sep 11 23:08:12 autopkgtest systemd[1]: Reload requested from client PID 1820 ('systemctl') (unit session-1.scope)... 392s Sep 11 23:08:12 autopkgtest systemd[1]: Reloading... 392s Sep 11 23:08:12 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:12 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 392s Sep 11 23:08:12 autopkgtest systemd[1]: Reloading finished in 205 ms. 392s Sep 11 23:08:23 autopkgtest sudo[1266]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:24 autopkgtest sudo[5668]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 392s Sep 11 23:08:24 autopkgtest sudo[5668]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:24 autopkgtest sudo[5668]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:24 autopkgtest sudo[5678]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 392s Sep 11 23:08:24 autopkgtest sudo[5678]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:24 autopkgtest sudo[5678]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:24 autopkgtest sudo[5688]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-get --simulate --quiet -o APT::Get::Show-User-Simulation-Note=False --auto-remove purge autopkgtest-satdep 392s Sep 11 23:08:24 autopkgtest sudo[5688]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:25 autopkgtest sudo[5688]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:25 autopkgtest sudo[5701]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq fio librbd1 librados2 libboost-iostreams1.83.0 libboost-thread1.83.0 tgt libconfig-general-perl libpmemobj1 libpmem1 libndctl6 libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 open-iscsi libisns0t64 libnbd0 libopeniscsiusr librdmacm1t64 392s Sep 11 23:08:25 autopkgtest sudo[5701]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:25 autopkgtest sudo[5701]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:25 autopkgtest sudo[5713]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 392s Sep 11 23:08:25 autopkgtest sudo[5713]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:26 autopkgtest sudo[5713]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:26 autopkgtest sudo[5725]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 392s Sep 11 23:08:26 autopkgtest sudo[5725]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:26 autopkgtest sudo[5725]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:26 autopkgtest sudo[5735]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.kY2Ex2/tgtbasedmpaths-packages.all' 392s Sep 11 23:08:26 autopkgtest sudo[5735]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 392s Sep 11 23:08:26 autopkgtest sudo[5735]: pam_unix(sudo:session): session closed for user root 392s Sep 11 23:08:26 autopkgtest sudo[5746]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 396s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 396s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 396s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 396s latency : target=0, window=0, percentile=100.00%, depth=1 396s 396s Run status group 0 (all jobs): 396s WRITE: bw=120MiB/s (126MB/s), 120MiB/s-120MiB/s (126MB/s-126MB/s), io=87.5MiB (91.8MB), run=731-731msec 396s 396s Disk stats (read/write): 396s dm-0: ios=1/1205, sectors=8/154240, merge=0/0, ticks=2/636, in_queue=637, util=86.30%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/161, aggrin_queue=161, aggrutil=86.52% 396s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 396s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 396s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 396s sda: ios=1/1402, sectors=8/179280, merge=0/0, ticks=1/644, in_queue=645, util=86.52% 396s + echo Starting the path changes in background 396s + date +Pre FIO %H:%M:%S.%N 396s Starting the path changes in background 396s Pre FIO 23:08:37.419488904 396s + fio --max-jobs=4 /tmp/autopkgtest.kY2Ex2/tgtbasedmpaths-artifacts/path-change-check.fio 396s verify-phase: (g=0): rw=read, bs=(R) 64.0KiB-64.0KiB, (W) 64.0KiB-64.0KiB, (T) 64.0KiB-64.0KiB, ioengine=sync, iodepth=1 396s fio-3.37 396s Starting 1 thread 576s 576s verify-phase: (groupid=0, jobs=1): err= 0: pid=6106: Wed Sep 11 23:11:37 2024 576s read: IOPS=3886, BW=243MiB/s (255MB/s)(42.7GiB/180001msec) 576s clat (usec): min=84, max=45370, avg=231.76, stdev=281.17 576s lat (usec): min=84, max=45371, avg=231.89, stdev=281.17 576s clat percentiles (usec): 576s | 1.00th=[ 101], 5.00th=[ 121], 10.00th=[ 128], 20.00th=[ 143], 576s | 30.00th=[ 155], 40.00th=[ 169], 50.00th=[ 184], 60.00th=[ 200], 576s | 70.00th=[ 221], 80.00th=[ 245], 90.00th=[ 285], 95.00th=[ 338], 576s | 99.00th=[ 1336], 99.50th=[ 1942], 99.90th=[ 3294], 99.95th=[ 3720], 576s | 99.99th=[ 5014] 576s bw ( KiB/s): min=41728, max=428633, per=100.00%, avg=248930.55, stdev=71662.09, samples=359 576s iops : min= 652, max= 6697, avg=3889.50, stdev=1119.72, samples=359 576s lat (usec) : 100=0.92%, 250=80.75%, 500=14.69%, 750=0.46%, 1000=0.72% 576s lat (msec) : 2=1.98%, 4=0.44%, 10=0.04%, 20=0.01%, 50=0.01% 576s cpu : usr=10.98%, sys=6.13%, ctx=699665, majf=0, minf=1 576s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 576s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 576s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 576s issued rwts: total=699494,0,0,0 short=0,0,0,0 dropped=0,0,0,0 576s latency : target=0, window=0, percentile=100.00%, depth=1 576s 576s Run status group 0 (all jobs): 576s READ: bw=243MiB/s (255MB/s), 243MiB/s-243MiB/s (255MB/s-255MB/s), io=42.7GiB (45.8GB), run=180001-180001msec 576s 576s Disk stats (read/write): 576s dm-0: ios=699694/10, sectors=89493944/12928, merge=11/9, ticks=166343/122, in_queue=166557, util=99.99%, aggrios=41269/2, aggsectors=5277934/3232, aggrmerge=0/0, aggrticks=10553/7, aggrin_queue=10560, aggrutil=99.17% 576s sdd: ios=67246/0, sectors=8601472/0, merge=0/0, ticks=17021/0, in_queue=17021, util=39.95% 576s sdb: ios=33583/0, sectors=4292536/0, merge=0/0, ticks=8516/0, in_queue=8516, util=50.07% 576s sdc: ios=30172/0, sectors=3859328/0, merge=0/0, ticks=8449/0, in_queue=8449, util=32.96% 576s sda: ios=34076/9, sectors=4358400/12928, merge=0/0, ticks=8227/29, in_queue=8256, util=99.17% 576s Post FIO 23:11:37.758104410 576s FIO verify test with changing paths - OK 576s Report log of background activity 576s + date +Post FIO %H:%M:%S.%N 576s + echo FIO verify test with changing paths - OK 576s + echo Report log of background activity 576s + cat /tmp/autopkgtest.kY2Ex2/tgtbasedmpaths-artifacts/test-background.log 576s + sync 576s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 576s + echo Final stats 576s + iscsiadm --mode session --stats 576s + journalctl --no-pager -u multipathd 576s + echo Check final path status 576s + multipath -ll 576s + grep --count status= 576s + multipath -ll 576s + iscsiadm --mode session 576s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s + sleep 10s 576s + date +MP report (expect 4) %H:%M:%S.%N 576s MP report (expect 4) 23:08:47.428296060 576s + multipath -ll 576s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 576s size=100M features='0' hwhandler='0' wp=rw 576s |-+- policy='service-time 0' prio=1 status=active 576s | `- 0:0:0:1 sda 8:0 active ready running 576s |-+- policy='service-time 0' prio=1 status=enabled 576s | `- 1:0:0:1 sdb 8:16 active ready running 576s |-+- policy='service-time 0' prio=1 status=enabled 576s | `- 2:0:0:1 sdc 8:32 active ready running 576s `-+- policy='service-time 0' prio=1 status=enabled 576s `- 3:0:0:1 sdd 8:48 active ready running 576s + date +UN-plug path 1 %H:%M:%S.%N 576s UN-plug path 1 23:08:47.458049101 576s + iscsiadm --mode session -r 1 -u 576s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 576s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 576s + iscsiadm --mode session 576s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s + sleep 10s 576s + date +MP report (expect 3) %H:%M:%S.%N 576s MP report (expect 3) 23:08:57.555219088 576s + multipath -ll 576s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 576s size=100M features='0' hwhandler='0' wp=rw 576s |-+- policy='service-time 0' prio=1 status=active 576s | `- 1:0:0:1 sdb 8:16 active ready running 576s |-+- policy='service-time 0' prio=1 status=enabled 576s | `- 2:0:0:1 sdc 8:32 active ready running 576s `-+- policy='service-time 0' prio=1 status=enabled 576s `- 3:0:0:1 sdd 8:48 active ready running 576s + date +UN-plug path 2 %H:%M:%S.%N 576s UN-plug path 2 23:08:57.585037314 576s + iscsiadm --mode session -r 2 -u 576s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 576s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 576s + iscsiadm --mode session 576s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s + sleep 10s 576s + date +MP report (expect 2) %H:%M:%S.%N 576s MP report (expect 2) 23:09:07.695029161 576s + multipath -ll 576s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 576s size=100M features='0' hwhandler='0' wp=rw 576s |-+- policy='service-time 0' prio=1 status=active 576s | `- 2:0:0:1 sdc 8:32 active ready running 576s `-+- policy='service-time 0' prio=1 status=enabled 576s `- 3:0:0:1 sdd 8:48 active ready running 576s + date +UN-plug path 3 %H:%M:%S.%N 576s UN-plug path 3 23:09:07.713540557 576s + iscsiadm --mode session -r 3 -u 576s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 576s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 576s + iscsiadm --mode session 576s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s + sleep 10s 576s + date +MP report (expect 1) %H:%M:%S.%N 576s MP report (expect 1) 23:09:17.814198111 576s + multipath -ll 576s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 576s size=100M features='0' hwhandler='0' wp=rw 576s `-+- policy='service-time 0' prio=1 status=active 576s `- 3:0:0:1 sdd 8:48 active ready running 576s + date +Add paths 5/6/7/8 %H:%M:%S.%N 576s Add paths 5/6/7/8 23:09:17.826884428 576s + iscsiadm --mode session -r 4 --op new 576s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 576s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 576s + iscsiadm --mode session -r 4 --op new 576s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 576s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 576s + iscsiadm --mode session -r 4 --op new 576s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 576s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 576s + iscsiadm --mode session -r 4 --op new 576s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 576s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 576s + iscsiadm --mode session 576s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s + sleep 10s 576s + date +MP report (expect 5) %H:%M:%S.%N 576s MP report (expect 5) 23:09:27.952186984 576s + multipath -ll 576s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 576s size=100M features='0' hwhandler='0' wp=rw 576s |-+- policy='service-time 0' prio=1 status=active 576s | `- 3:0:0:1 sdd 8:48 active ready running 576s |-+- policy='service-time 0' prio=1 status=enabled 576s | `- 0:0:0:1 sda 8:0 active ready running 576s |-+- policy='service-time 0' prio=1 status=enabled 576s | `- 1:0:0:1 sdb 8:16 active ready running 576s |-+- policy='service-time 0' prio=1 status=enabled 576s | `- 2:0:0:1 sdc 8:32 active ready running 576s `-+- policy='service-time 0' prio=1 status=enabled 576s `- 4:0:0:1 sde 8:64 active ready running 576s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 576s UN-plug multiple paths 4/7/8 23:09:27.995618886 576s + iscsiadm --mode session -r 4 -u 576s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 576s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 576s + iscsiadm --mode session -r 7 -u 576s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 576s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 576s + iscsiadm --mode session -r 8 -u 576s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 576s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 576s + iscsiadm --mode session 576s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 576s + sleep 10s 576s + date +Restart multipath daemon %H:%M:%S.%N 576s Restart multipath daemon 23:09:38.310227255 576s + systemctl restart multipathd 576s + sleep 10s 576s + date +Final background report (expect 2) %H:%M:%S.%N 576s Final background report (expect 2) 23:09:48.388320352 576s + multipath -ll 576s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 576s size=100M features='0' hwhandler='0' wp=rw 576s |-+- policy='service-time 0' prio=1 status=active 576s | `- 0:0:0:1 sda 8:0 active ready running 576s `-+- policy='service-time 0' prio=1 status=enabled 576s `- 1:0:0:1 sdb 8:16 active ready running 576s Final stats 576s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 576s iSCSI SNMP: 576s txdata_octets: 25605432 576s rxdata_octets: 34937211300 576s noptx_pdus: 0 576s scsicmd_pdus: 533179 576s tmfcmd_pdus: 0 576s login_pdus: 0 576s text_pdus: 0 576s dataout_pdus: 0 576s logout_pdus: 0 576s snack_pdus: 0 576s noprx_pdus: 0 576s scsirsp_pdus: 533179 576s tmfrsp_pdus: 0 576s textrsp_pdus: 0 576s datain_pdus: 533147 576s logoutrsp_pdus: 0 576s r2t_pdus: 0 576s async_pdus: 0 576s rjt_pdus: 0 576s digest_err: 0 576s timeout_err: 0 576s iSCSI Extended: 576s tx_sendpage_failures: 0 576s rx_discontiguous_hdr: 0 576s eh_abort_cnt: 0 576s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 576s iSCSI SNMP: 576s txdata_octets: 6504 576s rxdata_octets: 1580500 576s noptx_pdus: 0 576s scsicmd_pdus: 106 576s tmfcmd_pdus: 0 576s login_pdus: 0 576s text_pdus: 0 576s dataout_pdus: 0 576s logout_pdus: 0 576s snack_pdus: 0 576s noprx_pdus: 0 576s scsirsp_pdus: 106 576s tmfrsp_pdus: 0 576s textrsp_pdus: 0 576s datain_pdus: 84 576s logoutrsp_pdus: 0 576s r2t_pdus: 0 576s async_pdus: 0 576s rjt_pdus: 0 576s digest_err: 0 576s timeout_err: 0 576s iSCSI Extended: 576s tx_sendpage_failures: 0 576s rx_discontiguous_hdr: 0 576s eh_abort_cnt: 0 576s Sep 11 16:09:32 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 576s Sep 11 16:09:32 ubuntu multipathd[336]: multipathd v0.9.9: start up 576s Sep 11 16:09:32 ubuntu multipathd[336]: reconfigure: setting up paths and maps 576s Sep 11 16:09:32 ubuntu multipathd[336]: _check_bindings_file: failed to read header from /etc/multipath/bindings 576s Sep 11 16:09:32 ubuntu multipathd[336]: updated bindings file /etc/multipath/bindings 576s Sep 11 16:09:32 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 576s Sep 11 16:14:41 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i multipathd[336]: multipathd: shut down 576s Sep 11 16:14:41 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 576s Sep 11 16:14:41 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 576s Sep 11 16:14:41 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 576s -- Boot f16438a16e9e4d7885fe53c2f928d6a5 -- 576s Sep 11 16:14:55 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i multipathd[283]: multipathd v0.9.9: start up 576s Sep 11 16:14:55 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i multipathd[283]: reconfigure: setting up paths and maps 576s Sep 11 16:14:55 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 576s Sep 11 16:15:09 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i multipathd[283]: multipathd: shut down 576s Sep 11 16:15:09 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 576s Sep 11 16:15:09 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 576s Sep 11 16:15:09 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 576s -- Boot 7203242d4b2d43938401316b5d11c0bd -- 576s Sep 11 23:06:36 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i multipathd[312]: multipathd v0.9.9: start up 576s Sep 11 23:06:36 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i multipathd[312]: reconfigure: setting up paths and maps 576s Sep 11 23:06:36 auto-syncubuntu-oracular-daily-ppc64el-server-20240910-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 576s Sep 11 23:07:37 autopkgtest multipathd[312]: multipathd: shut down 576s Sep 11 23:07:37 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 576s Sep 11 23:07:37 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 576s Sep 11 23:07:37 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 576s -- Boot dc235b595b304021a5ed81d2d59e7d08 -- 576s Sep 11 23:07:49 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 576s Sep 11 23:07:49 autopkgtest multipathd[328]: multipathd v0.9.9: start up 576s Sep 11 23:07:49 autopkgtest multipathd[328]: reconfigure: setting up paths and maps 576s Sep 11 23:07:49 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 576s Sep 11 23:08:27 autopkgtest multipathd[328]: updated bindings file /etc/multipath/bindings 576s Sep 11 23:08:27 autopkgtest multipathd[328]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 576s Sep 11 23:08:28 autopkgtest multipathd[328]: sda [8:0]: path added to devmap mpatha 576s Sep 11 23:08:28 autopkgtest multipathd[328]: mpatha: performing delayed actions 576s Sep 11 23:08:28 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 576s Sep 11 23:08:47 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 576s Sep 11 23:08:47 autopkgtest multipathd[328]: check_removed_paths: sda: freeing path in removed state 576s Sep 11 23:08:47 autopkgtest multipathd[328]: 8:0: path removed from map mpatha 576s Sep 11 23:08:57 autopkgtest multipathd[328]: 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] 576s Sep 11 23:08:57 autopkgtest multipathd[328]: check_removed_paths: sdb: freeing path in removed state 576s Sep 11 23:08:57 autopkgtest multipathd[328]: 8:16: path removed from map mpatha 576s Sep 11 23:09:07 autopkgtest multipathd[328]: sdc: mark as failed 576s Sep 11 23:09:07 autopkgtest multipathd[328]: mpatha: remaining active paths: 1 576s Sep 11 23:09:07 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 576s Sep 11 23:09:07 autopkgtest multipathd[328]: check_removed_paths: sdc: freeing path in removed state 576s Sep 11 23:09:07 autopkgtest multipathd[328]: 8:32: path removed from map mpatha 576s Sep 11 23:09:17 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1] 576s Sep 11 23:09:17 autopkgtest multipathd[328]: sda [8:0]: path added to devmap mpatha 576s Sep 11 23:09:17 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 576s Sep 11 23:09:18 autopkgtest multipathd[328]: sdb [8:16]: path added to devmap mpatha 576s Sep 11 23:09:18 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 576s Sep 11 23:09:18 autopkgtest multipathd[328]: sdc [8:32]: path added to devmap mpatha 576s Sep 11 23:09:18 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8: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] 576s Sep 11 23:09:18 autopkgtest multipathd[328]: sde [8:64]: path added to devmap mpatha 576s Sep 11 23:09:28 autopkgtest multipathd[328]: sdd: mark as failed 576s Sep 11 23:09:28 autopkgtest multipathd[328]: mpatha: remaining active paths: 4 576s Sep 11 23:09:28 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 576s Sep 11 23:09:28 autopkgtest multipathd[328]: check_removed_paths: sdd: freeing path in removed state 576s Sep 11 23:09:28 autopkgtest multipathd[328]: 8:48: path removed from map mpatha 576s Sep 11 23:09:28 autopkgtest multipathd[328]: 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] 576s Sep 11 23:09:28 autopkgtest multipathd[328]: check_removed_paths: sdc: freeing path in removed state 576s Sep 11 23:09:28 autopkgtest multipathd[328]: 8:32: path removed from map mpatha 576s Sep 11 23:09:28 autopkgtest multipathd[328]: 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] 576s Sep 11 23:09:28 autopkgtest multipathd[328]: check_removed_paths: sde: freeing path in removed state 576s Sep 11 23:09:28 autopkgtest multipathd[328]: 8:64: path removed from map mpatha 576s Sep 11 23:09:38 autopkgtest multipathd[328]: multipathd: shut down 576s Sep 11 23:09:38 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 576s Sep 11 23:09:38 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 576s Sep 11 23:09:38 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 576s Sep 11 23:09:38 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 576s Sep 11 23:09:38 autopkgtest multipathd[6489]: multipathd v0.9.9: start up 576s Sep 11 23:09:38 autopkgtest multipathd[6489]: reconfigure: setting up paths and maps 576s Sep 11 23:09:38 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 576s Check final path status 576s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 576s size=100M features='0' hwhandler='0' wp=rw 576s |-+- policy='service-time 0' prio=1 status=active 576s | `- 0:0:0:1 sda 8:0 active ready running 576s `-+- policy='service-time 0' prio=1 status=enabled 576s `- 1:0:0:1 sdb 8:16 active ready running 576s + diskc=2 576s + multipath -ll 576s + grep --count status=active 576s + diska=1 576s + multipath -ll 576s + grep --count status=enabled 576s OK 576s + diske=1 576s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 576s + echo OK 576s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 576s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 576s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 576s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 576s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 576s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 577s autopkgtest [23:11:38]: test tgtbasedmpaths: -----------------------] 577s autopkgtest [23:11:38]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 577s tgtbasedmpaths PASS 578s autopkgtest [23:11:39]: @@@@@@@@@@@@@@@@@@@@ summary 578s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 578s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 578s kpartx-file-loopback PASS 578s tgtbasedmpaths PASS 589s nova [W] Using flock in prodstack6-ppc64el 589s flock: timeout while waiting to get lock 589s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240911-230159-juju-7f2275-prod-proposed-migration-environment-2-a14f07f4-836c-4c2a-9b59-fafa99654ee3 from image adt/ubuntu-oracular-ppc64el-server-20240911.img (UUID 4e9259a6-40bf-4521-802e-b93d7cf4a311)... 589s nova [W] Using flock in prodstack6-ppc64el 589s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240911-230159-juju-7f2275-prod-proposed-migration-environment-2-a14f07f4-836c-4c2a-9b59-fafa99654ee3 from image adt/ubuntu-oracular-ppc64el-server-20240911.img (UUID 4e9259a6-40bf-4521-802e-b93d7cf4a311)...