0s autopkgtest [22:31:08]: starting date and time: 2024-08-09 22:31:08+0000 0s autopkgtest [22:31:08]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [22:31:08]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.18x34rqv/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:initramfs-tools --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=initramfs-tools/0.142ubuntu32 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big-ppc64el --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos03-ppc64el-38.secgroup --name adt-oracular-ppc64el-multipath-tools-20240809-223106-juju-7f2275-prod-proposed-migration-environment-3-872a2d39-da14-4b2c-8f79-7f86d296884e --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --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/ 215s autopkgtest [22:34:43]: testbed dpkg architecture: ppc64el 216s autopkgtest [22:34:44]: testbed apt version: 2.9.7 216s autopkgtest [22:34:44]: @@@@@@@@@@@@@@@@@@@@ test bed setup 223s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 224s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8452 B] 224s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [836 kB] 224s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [95.8 kB] 224s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [11.1 kB] 224s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [143 kB] 224s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [5544 B] 224s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1692 B] 224s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 224s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [746 kB] 224s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [22.9 kB] 224s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [5144 B] 224s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [436 B] 229s Fetched 2003 kB in 1s (1974 kB/s) 229s Reading package lists... 233s Reading package lists... 233s Building dependency tree... 233s Reading state information... 233s Calculating upgrade... 233s The following NEW packages will be installed: 233s systemd-cryptsetup 233s The following packages will be upgraded: 233s apport apport-core-dump-handler initramfs-tools initramfs-tools-bin 233s initramfs-tools-core libnss-systemd libpam-systemd libsystemd-shared 233s libsystemd0 libudev1 lto-disabled-list powermgmt-base python3-apport 233s python3-problem-report systemd systemd-dev systemd-resolved systemd-sysv 233s systemd-timesyncd udev 233s 20 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 233s Need to get 10.7 MB of archives. 233s After this operation, 162 kB disk space will be freed. 233s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnss-systemd ppc64el 256.4-2ubuntu1 [215 kB] 234s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-dev all 256.4-2ubuntu1 [113 kB] 234s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd ppc64el 256.4-2ubuntu1 [3740 kB] 234s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-timesyncd ppc64el 256.4-2ubuntu1 [42.4 kB] 234s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-resolved ppc64el 256.4-2ubuntu1 [370 kB] 234s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsystemd-shared ppc64el 256.4-2ubuntu1 [2490 kB] 234s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsystemd0 ppc64el 256.4-2ubuntu1 [564 kB] 234s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-sysv ppc64el 256.4-2ubuntu1 [11.9 kB] 234s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpam-systemd ppc64el 256.4-2ubuntu1 [326 kB] 234s Get:10 http://ftpmaster.internal/ubuntu oracular/main ppc64el udev ppc64el 256.4-2ubuntu1 [2141 kB] 234s Get:11 http://ftpmaster.internal/ubuntu oracular/main ppc64el libudev1 ppc64el 256.4-2ubuntu1 [223 kB] 234s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-problem-report all 2.30.0-0ubuntu1 [24.8 kB] 234s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-apport all 2.30.0-0ubuntu1 [93.1 kB] 234s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el apport-core-dump-handler all 2.30.0-0ubuntu1 [17.6 kB] 234s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el apport all 2.30.0-0ubuntu1 [84.6 kB] 234s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el powermgmt-base all 1.37+nmu1ubuntu1 [7332 B] 234s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools all 0.142ubuntu32 [7904 B] 234s Get:18 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools-core all 0.142ubuntu32 [50.1 kB] 234s Get:19 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools-bin ppc64el 0.142ubuntu32 [22.2 kB] 234s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el lto-disabled-list all 53 [12.2 kB] 234s Get:21 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-cryptsetup ppc64el 256.4-2ubuntu1 [127 kB] 234s Fetched 10.7 MB in 1s (10.2 MB/s) 235s (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 ... 72536 files and directories currently installed.) 235s Preparing to unpack .../0-libnss-systemd_256.4-2ubuntu1_ppc64el.deb ... 235s Unpacking libnss-systemd:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 235s Preparing to unpack .../1-systemd-dev_256.4-2ubuntu1_all.deb ... 235s Unpacking systemd-dev (256.4-2ubuntu1) over (256-1ubuntu1) ... 235s Preparing to unpack .../2-systemd_256.4-2ubuntu1_ppc64el.deb ... 235s Unpacking systemd (256.4-2ubuntu1) over (256-1ubuntu1) ... 235s Preparing to unpack .../3-systemd-timesyncd_256.4-2ubuntu1_ppc64el.deb ... 235s Unpacking systemd-timesyncd (256.4-2ubuntu1) over (256-1ubuntu1) ... 235s Preparing to unpack .../4-systemd-resolved_256.4-2ubuntu1_ppc64el.deb ... 235s Unpacking systemd-resolved (256.4-2ubuntu1) over (256-1ubuntu1) ... 235s Preparing to unpack .../5-libsystemd-shared_256.4-2ubuntu1_ppc64el.deb ... 235s Unpacking libsystemd-shared:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 235s Preparing to unpack .../6-libsystemd0_256.4-2ubuntu1_ppc64el.deb ... 235s Unpacking libsystemd0:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 235s Setting up libsystemd0:ppc64el (256.4-2ubuntu1) ... 235s Setting up libsystemd-shared:ppc64el (256.4-2ubuntu1) ... 235s Setting up systemd (256.4-2ubuntu1) ... 235s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 235s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 236s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 237s (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 ... 72461 files and directories currently installed.) 237s Preparing to unpack .../systemd-sysv_256.4-2ubuntu1_ppc64el.deb ... 237s Unpacking systemd-sysv (256.4-2ubuntu1) over (256-1ubuntu1) ... 237s Preparing to unpack .../libpam-systemd_256.4-2ubuntu1_ppc64el.deb ... 237s Unpacking libpam-systemd:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 237s Preparing to unpack .../udev_256.4-2ubuntu1_ppc64el.deb ... 237s Unpacking udev (256.4-2ubuntu1) over (256-1ubuntu1) ... 237s Preparing to unpack .../libudev1_256.4-2ubuntu1_ppc64el.deb ... 237s Unpacking libudev1:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 237s Setting up libudev1:ppc64el (256.4-2ubuntu1) ... 237s (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 ... 72462 files and directories currently installed.) 237s Preparing to unpack .../0-python3-problem-report_2.30.0-0ubuntu1_all.deb ... 237s Unpacking python3-problem-report (2.30.0-0ubuntu1) over (2.29.0-0ubuntu1) ... 237s Preparing to unpack .../1-python3-apport_2.30.0-0ubuntu1_all.deb ... 237s Unpacking python3-apport (2.30.0-0ubuntu1) over (2.29.0-0ubuntu1) ... 237s Preparing to unpack .../2-apport-core-dump-handler_2.30.0-0ubuntu1_all.deb ... 237s Unpacking apport-core-dump-handler (2.30.0-0ubuntu1) over (2.29.0-0ubuntu1) ... 237s Preparing to unpack .../3-apport_2.30.0-0ubuntu1_all.deb ... 237s Unpacking apport (2.30.0-0ubuntu1) over (2.29.0-0ubuntu1) ... 237s Preparing to unpack .../4-powermgmt-base_1.37+nmu1ubuntu1_all.deb ... 237s Unpacking powermgmt-base (1.37+nmu1ubuntu1) over (1.37+nmu1) ... 237s Preparing to unpack .../5-initramfs-tools_0.142ubuntu32_all.deb ... 237s Unpacking initramfs-tools (0.142ubuntu32) over (0.142ubuntu30) ... 237s Preparing to unpack .../6-initramfs-tools-core_0.142ubuntu32_all.deb ... 237s Unpacking initramfs-tools-core (0.142ubuntu32) over (0.142ubuntu30) ... 237s Preparing to unpack .../7-initramfs-tools-bin_0.142ubuntu32_ppc64el.deb ... 237s Unpacking initramfs-tools-bin (0.142ubuntu32) over (0.142ubuntu30) ... 237s Preparing to unpack .../8-lto-disabled-list_53_all.deb ... 237s Unpacking lto-disabled-list (53) over (52) ... 237s Selecting previously unselected package systemd-cryptsetup. 237s Preparing to unpack .../9-systemd-cryptsetup_256.4-2ubuntu1_ppc64el.deb ... 237s Unpacking systemd-cryptsetup (256.4-2ubuntu1) ... 237s Setting up powermgmt-base (1.37+nmu1ubuntu1) ... 237s Setting up systemd-sysv (256.4-2ubuntu1) ... 237s Setting up lto-disabled-list (53) ... 237s Setting up python3-problem-report (2.30.0-0ubuntu1) ... 238s Setting up libnss-systemd:ppc64el (256.4-2ubuntu1) ... 238s Setting up systemd-dev (256.4-2ubuntu1) ... 238s Setting up python3-apport (2.30.0-0ubuntu1) ... 238s Setting up systemd-cryptsetup (256.4-2ubuntu1) ... 238s Setting up systemd-timesyncd (256.4-2ubuntu1) ... 239s systemd-time-wait-sync.service is a disabled or a static unit not running, not starting it. 239s Setting up udev (256.4-2ubuntu1) ... 240s Setting up libpam-systemd:ppc64el (256.4-2ubuntu1) ... 240s Setting up systemd-resolved (256.4-2ubuntu1) ... 241s Setting up initramfs-tools-bin (0.142ubuntu32) ... 241s Setting up initramfs-tools-core (0.142ubuntu32) ... 241s Setting up initramfs-tools (0.142ubuntu32) ... 241s update-initramfs: deferring update (trigger activated) 241s Setting up apport-core-dump-handler (2.30.0-0ubuntu1) ... 242s Setting up apport (2.30.0-0ubuntu1) ... 243s apport-autoreport.service is a disabled or a static unit not running, not starting it. 243s Processing triggers for dbus (1.14.10-4ubuntu4) ... 243s Processing triggers for shared-mime-info (2.4-5) ... 243s Processing triggers for libc-bin (2.39-0ubuntu9) ... 243s Processing triggers for man-db (2.12.1-2) ... 245s Processing triggers for initramfs-tools (0.142ubuntu32) ... 245s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 245s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 255s Reading package lists... 255s Building dependency tree... 255s Reading state information... 256s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 266s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 266s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 266s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 266s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 268s Reading package lists... 268s Reading package lists... 268s Building dependency tree... 268s Reading state information... 268s Calculating upgrade... 268s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 268s Reading package lists... 269s Building dependency tree... 269s Reading state information... 269s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 269s autopkgtest [22:35:37]: rebooting testbed after setup commands that affected boot 273s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 312s autopkgtest [22:36:20]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 334s autopkgtest [22:36:42]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 341s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu2 (dsc) [2772 B] 341s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu2 (tar) [588 kB] 341s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu2 (diff) [42.4 kB] 341s gpgv: Signature made Tue Jul 23 21:24:22 2024 UTC 341s gpgv: using RSA key D09F8A854F1055BCFC482C4B23566B906047AFC8 341s gpgv: Can't check signature: No public key 341s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.9-1ubuntu2.dsc: no acceptable signature found 341s autopkgtest [22:36:48]: testing package multipath-tools version 0.9.9-1ubuntu2 345s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 345s autopkgtest [22:36:53]: build not needed 356s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 356s autopkgtest [22:37:04]: test kpartx-file-loopback: preparing testbed 361s Reading package lists... 361s Building dependency tree... 361s Reading state information... 362s Starting pkgProblemResolver with broken count: 0 362s Starting 2 pkgProblemResolver with broken count: 0 362s Done 362s The following additional packages will be installed: 362s liburing2 qemu-utils 362s Recommended packages: 362s qemu-block-extra 362s The following NEW packages will be installed: 362s autopkgtest-satdep liburing2 qemu-utils 362s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 362s Need to get 2330 kB/2331 kB of archives. 362s After this operation, 15.4 MB of additional disk space will be used. 362s Get:1 /tmp/autopkgtest.EXlFK5/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 362s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 362s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 363s Fetched 2330 kB in 1s (3524 kB/s) 363s Selecting previously unselected package liburing2:ppc64el. 363s (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 ... 72511 files and directories currently installed.) 363s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 363s Unpacking liburing2:ppc64el (2.6-1) ... 363s Selecting previously unselected package qemu-utils. 363s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 363s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 363s Selecting previously unselected package autopkgtest-satdep. 363s Preparing to unpack .../1-autopkgtest-satdep.deb ... 363s Unpacking autopkgtest-satdep (0) ... 363s Setting up liburing2:ppc64el (2.6-1) ... 363s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 363s Setting up autopkgtest-satdep (0) ... 363s Processing triggers for man-db (2.12.1-2) ... 365s Processing triggers for libc-bin (2.39-0ubuntu9) ... 380s (Reading database ... 72531 files and directories currently installed.) 380s Removing autopkgtest-satdep (0) ... 381s autopkgtest [22:37:29]: test kpartx-file-loopback: [----------------------- 381s Formatting 'foo.img', fmt=raw size=20971520 382s Creating new GPT entries in memory. 382s Warning: The kernel is still using the old partition table. 382s The new table will be used at the next reboot or after you 382s run partprobe(8) or kpartx(8) 382s The operation has completed successfully. 382s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 382s standard_filename: OK 382s del devmap : loop0p1 382s No devices found 382s standard_filename_cleanup: OK 382s Formatting 'fou du FaFa.img', fmt=raw size=20971520 383s Creating new GPT entries in memory. 383s Warning: The kernel is still using the old partition table. 383s The new table will be used at the next reboot or after you 383s run partprobe(8) or kpartx(8) 383s The operation has completed successfully. 383s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 383s filename_with_spaces: OK 383s del devmap : loop0p1 383s No devices found 384s filename_with_spaces_cleanup: OK 384s autopkgtest [22:37:32]: test kpartx-file-loopback: -----------------------] 385s kpartx-file-loopback PASS 385s autopkgtest [22:37:33]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 387s autopkgtest [22:37:35]: test tgtbasedmpaths: preparing testbed 575s autopkgtest [22:40:43]: testbed dpkg architecture: ppc64el 576s autopkgtest [22:40:44]: testbed apt version: 2.9.7 576s autopkgtest [22:40:44]: @@@@@@@@@@@@@@@@@@@@ test bed setup 598s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 598s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8452 B] 598s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [836 kB] 598s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [11.1 kB] 598s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [95.8 kB] 598s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [143 kB] 598s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [5544 B] 598s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1692 B] 598s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 598s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [746 kB] 598s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [22.9 kB] 598s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [5144 B] 598s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [436 B] 603s Fetched 2003 kB in 1s (2048 kB/s) 603s Reading package lists... 622s Reading package lists... 623s Building dependency tree... 623s Reading state information... 623s Calculating upgrade... 623s The following NEW packages will be installed: 623s systemd-cryptsetup 623s The following packages will be upgraded: 623s apport apport-core-dump-handler initramfs-tools initramfs-tools-bin 623s initramfs-tools-core libnss-systemd libpam-systemd libsystemd-shared 623s libsystemd0 libudev1 lto-disabled-list powermgmt-base python3-apport 623s python3-problem-report systemd systemd-dev systemd-resolved systemd-sysv 623s systemd-timesyncd udev 623s 20 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 623s Need to get 10.7 MB of archives. 623s After this operation, 162 kB disk space will be freed. 623s Get:1 http://ftpmaster.internal/ubuntu oracular/main ppc64el libnss-systemd ppc64el 256.4-2ubuntu1 [215 kB] 623s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-dev all 256.4-2ubuntu1 [113 kB] 623s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd ppc64el 256.4-2ubuntu1 [3740 kB] 624s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-timesyncd ppc64el 256.4-2ubuntu1 [42.4 kB] 624s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-resolved ppc64el 256.4-2ubuntu1 [370 kB] 624s Get:6 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsystemd-shared ppc64el 256.4-2ubuntu1 [2490 kB] 624s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el libsystemd0 ppc64el 256.4-2ubuntu1 [564 kB] 624s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-sysv ppc64el 256.4-2ubuntu1 [11.9 kB] 624s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpam-systemd ppc64el 256.4-2ubuntu1 [326 kB] 624s Get:10 http://ftpmaster.internal/ubuntu oracular/main ppc64el udev ppc64el 256.4-2ubuntu1 [2141 kB] 624s Get:11 http://ftpmaster.internal/ubuntu oracular/main ppc64el libudev1 ppc64el 256.4-2ubuntu1 [223 kB] 624s Get:12 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-problem-report all 2.30.0-0ubuntu1 [24.8 kB] 624s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-apport all 2.30.0-0ubuntu1 [93.1 kB] 624s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el apport-core-dump-handler all 2.30.0-0ubuntu1 [17.6 kB] 624s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el apport all 2.30.0-0ubuntu1 [84.6 kB] 624s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el powermgmt-base all 1.37+nmu1ubuntu1 [7332 B] 624s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools all 0.142ubuntu32 [7904 B] 624s Get:18 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools-core all 0.142ubuntu32 [50.1 kB] 624s Get:19 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el initramfs-tools-bin ppc64el 0.142ubuntu32 [22.2 kB] 624s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el lto-disabled-list all 53 [12.2 kB] 624s Get:21 http://ftpmaster.internal/ubuntu oracular/main ppc64el systemd-cryptsetup ppc64el 256.4-2ubuntu1 [127 kB] 624s Fetched 10.7 MB in 1s (10.5 MB/s) 624s (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 ... 72536 files and directories currently installed.) 624s Preparing to unpack .../0-libnss-systemd_256.4-2ubuntu1_ppc64el.deb ... 624s Unpacking libnss-systemd:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 624s Preparing to unpack .../1-systemd-dev_256.4-2ubuntu1_all.deb ... 624s Unpacking systemd-dev (256.4-2ubuntu1) over (256-1ubuntu1) ... 624s Preparing to unpack .../2-systemd_256.4-2ubuntu1_ppc64el.deb ... 624s Unpacking systemd (256.4-2ubuntu1) over (256-1ubuntu1) ... 625s Preparing to unpack .../3-systemd-timesyncd_256.4-2ubuntu1_ppc64el.deb ... 625s Unpacking systemd-timesyncd (256.4-2ubuntu1) over (256-1ubuntu1) ... 625s Preparing to unpack .../4-systemd-resolved_256.4-2ubuntu1_ppc64el.deb ... 625s Unpacking systemd-resolved (256.4-2ubuntu1) over (256-1ubuntu1) ... 625s Preparing to unpack .../5-libsystemd-shared_256.4-2ubuntu1_ppc64el.deb ... 625s Unpacking libsystemd-shared:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 625s Preparing to unpack .../6-libsystemd0_256.4-2ubuntu1_ppc64el.deb ... 625s Unpacking libsystemd0:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 625s Setting up libsystemd0:ppc64el (256.4-2ubuntu1) ... 625s Setting up libsystemd-shared:ppc64el (256.4-2ubuntu1) ... 625s Setting up systemd (256.4-2ubuntu1) ... 625s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 625s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 625s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 626s (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 ... 72461 files and directories currently installed.) 626s Preparing to unpack .../systemd-sysv_256.4-2ubuntu1_ppc64el.deb ... 626s Unpacking systemd-sysv (256.4-2ubuntu1) over (256-1ubuntu1) ... 626s Preparing to unpack .../libpam-systemd_256.4-2ubuntu1_ppc64el.deb ... 626s Unpacking libpam-systemd:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 626s Preparing to unpack .../udev_256.4-2ubuntu1_ppc64el.deb ... 626s Unpacking udev (256.4-2ubuntu1) over (256-1ubuntu1) ... 626s Preparing to unpack .../libudev1_256.4-2ubuntu1_ppc64el.deb ... 626s Unpacking libudev1:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 626s Setting up libudev1:ppc64el (256.4-2ubuntu1) ... 626s (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 ... 72462 files and directories currently installed.) 626s Preparing to unpack .../0-python3-problem-report_2.30.0-0ubuntu1_all.deb ... 626s Unpacking python3-problem-report (2.30.0-0ubuntu1) over (2.29.0-0ubuntu1) ... 626s Preparing to unpack .../1-python3-apport_2.30.0-0ubuntu1_all.deb ... 626s Unpacking python3-apport (2.30.0-0ubuntu1) over (2.29.0-0ubuntu1) ... 626s Preparing to unpack .../2-apport-core-dump-handler_2.30.0-0ubuntu1_all.deb ... 626s Unpacking apport-core-dump-handler (2.30.0-0ubuntu1) over (2.29.0-0ubuntu1) ... 626s Preparing to unpack .../3-apport_2.30.0-0ubuntu1_all.deb ... 626s Unpacking apport (2.30.0-0ubuntu1) over (2.29.0-0ubuntu1) ... 626s Preparing to unpack .../4-powermgmt-base_1.37+nmu1ubuntu1_all.deb ... 626s Unpacking powermgmt-base (1.37+nmu1ubuntu1) over (1.37+nmu1) ... 626s Preparing to unpack .../5-initramfs-tools_0.142ubuntu32_all.deb ... 626s Unpacking initramfs-tools (0.142ubuntu32) over (0.142ubuntu30) ... 626s Preparing to unpack .../6-initramfs-tools-core_0.142ubuntu32_all.deb ... 626s Unpacking initramfs-tools-core (0.142ubuntu32) over (0.142ubuntu30) ... 626s Preparing to unpack .../7-initramfs-tools-bin_0.142ubuntu32_ppc64el.deb ... 626s Unpacking initramfs-tools-bin (0.142ubuntu32) over (0.142ubuntu30) ... 626s Preparing to unpack .../8-lto-disabled-list_53_all.deb ... 626s Unpacking lto-disabled-list (53) over (52) ... 626s Selecting previously unselected package systemd-cryptsetup. 626s Preparing to unpack .../9-systemd-cryptsetup_256.4-2ubuntu1_ppc64el.deb ... 626s Unpacking systemd-cryptsetup (256.4-2ubuntu1) ... 626s Setting up powermgmt-base (1.37+nmu1ubuntu1) ... 626s Setting up systemd-sysv (256.4-2ubuntu1) ... 626s Setting up lto-disabled-list (53) ... 626s Setting up python3-problem-report (2.30.0-0ubuntu1) ... 627s Setting up libnss-systemd:ppc64el (256.4-2ubuntu1) ... 627s Setting up systemd-dev (256.4-2ubuntu1) ... 627s Setting up python3-apport (2.30.0-0ubuntu1) ... 627s Setting up systemd-cryptsetup (256.4-2ubuntu1) ... 627s Setting up systemd-timesyncd (256.4-2ubuntu1) ... 627s systemd-time-wait-sync.service is a disabled or a static unit not running, not starting it. 628s Setting up udev (256.4-2ubuntu1) ... 628s Setting up libpam-systemd:ppc64el (256.4-2ubuntu1) ... 629s Setting up systemd-resolved (256.4-2ubuntu1) ... 629s Setting up initramfs-tools-bin (0.142ubuntu32) ... 629s Setting up initramfs-tools-core (0.142ubuntu32) ... 629s Setting up initramfs-tools (0.142ubuntu32) ... 629s update-initramfs: deferring update (trigger activated) 629s Setting up apport-core-dump-handler (2.30.0-0ubuntu1) ... 630s Setting up apport (2.30.0-0ubuntu1) ... 631s apport-autoreport.service is a disabled or a static unit not running, not starting it. 631s Processing triggers for dbus (1.14.10-4ubuntu4) ... 631s Processing triggers for shared-mime-info (2.4-5) ... 632s Processing triggers for libc-bin (2.39-0ubuntu9) ... 632s Processing triggers for man-db (2.12.1-2) ... 633s Processing triggers for initramfs-tools (0.142ubuntu32) ... 633s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 633s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 642s Reading package lists... 642s Building dependency tree... 642s Reading state information... 642s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 642s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 643s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 643s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 643s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 644s Reading package lists... 644s Reading package lists... 644s Building dependency tree... 644s Reading state information... 644s Calculating upgrade... 645s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 645s Reading package lists... 645s Building dependency tree... 645s Reading state information... 645s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 645s autopkgtest [22:41:53]: rebooting testbed after setup commands that affected boot 655s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 717s Reading package lists... 717s Building dependency tree... 717s Reading state information... 718s Starting pkgProblemResolver with broken count: 0 718s Starting 2 pkgProblemResolver with broken count: 0 718s Done 718s The following additional packages will be installed: 718s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 718s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 718s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 718s librdmacm1t64 lsscsi open-iscsi tgt 718s Suggested packages: 718s fio-examples gnuplot tgt-glusterfs tgt-rbd 718s Recommended packages: 718s finalrd 718s The following NEW packages will be installed: 718s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 718s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 718s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 718s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 718s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 718s Need to get 10.7 MB/10.7 MB of archives. 718s After this operation, 49.0 MB of additional disk space will be used. 718s Get:1 /tmp/autopkgtest.EXlFK5/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 718s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 718s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 718s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 719s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2 [80.5 kB] 719s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 719s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 719s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-5ubuntu1 [21.7 kB] 719s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-5ubuntu1 [308 kB] 719s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-5ubuntu1 [46.3 kB] 719s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-5ubuntu1 [99.1 kB] 719s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-2 [98.5 kB] 719s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2.2ubuntu1 [23.7 kB] 719s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2.2ubuntu1 [73.4 kB] 719s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 719s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 719s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 719s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 719s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 719s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 719s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 719s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 719s Preconfiguring packages ... 719s Fetched 10.7 MB in 1s (11.2 MB/s) 719s Selecting previously unselected package libopeniscsiusr. 720s (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 ... 72511 files and directories currently installed.) 720s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 720s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 720s Selecting previously unselected package libisns0t64:ppc64el. 720s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 720s Unpacking libisns0t64:ppc64el (0.101-1) ... 720s Selecting previously unselected package open-iscsi. 720s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 720s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 720s Selecting previously unselected package librdmacm1t64:ppc64el. 720s Preparing to unpack .../03-librdmacm1t64_52.0-2_ppc64el.deb ... 720s Unpacking librdmacm1t64:ppc64el (52.0-2) ... 720s Selecting previously unselected package libconfig-general-perl. 720s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 720s Unpacking libconfig-general-perl (2.65-2) ... 720s Selecting previously unselected package tgt. 720s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 720s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 720s Selecting previously unselected package libgfxdr0:ppc64el. 720s Preparing to unpack .../06-libgfxdr0_11.1-5ubuntu1_ppc64el.deb ... 720s Unpacking libgfxdr0:ppc64el (11.1-5ubuntu1) ... 720s Selecting previously unselected package libglusterfs0:ppc64el. 720s Preparing to unpack .../07-libglusterfs0_11.1-5ubuntu1_ppc64el.deb ... 720s Unpacking libglusterfs0:ppc64el (11.1-5ubuntu1) ... 720s Selecting previously unselected package libgfrpc0:ppc64el. 720s Preparing to unpack .../08-libgfrpc0_11.1-5ubuntu1_ppc64el.deb ... 720s Unpacking libgfrpc0:ppc64el (11.1-5ubuntu1) ... 720s Selecting previously unselected package libgfapi0:ppc64el. 720s Preparing to unpack .../09-libgfapi0_11.1-5ubuntu1_ppc64el.deb ... 720s Unpacking libgfapi0:ppc64el (11.1-5ubuntu1) ... 720s Selecting previously unselected package libnbd0. 720s Preparing to unpack .../10-libnbd0_1.20.2-2_ppc64el.deb ... 720s Unpacking libnbd0 (1.20.2-2) ... 720s Selecting previously unselected package libdaxctl1:ppc64el. 720s Preparing to unpack .../11-libdaxctl1_77-2.2ubuntu1_ppc64el.deb ... 720s Unpacking libdaxctl1:ppc64el (77-2.2ubuntu1) ... 720s Selecting previously unselected package libndctl6:ppc64el. 720s Preparing to unpack .../12-libndctl6_77-2.2ubuntu1_ppc64el.deb ... 720s Unpacking libndctl6:ppc64el (77-2.2ubuntu1) ... 720s Selecting previously unselected package libpmem1:ppc64el. 720s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 720s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 720s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 720s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 720s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 720s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 720s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 720s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 720s Selecting previously unselected package librados2. 720s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 720s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 720s Selecting previously unselected package libpmemobj1:ppc64el. 720s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 720s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 720s Selecting previously unselected package librbd1. 720s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 720s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 721s Selecting previously unselected package fio. 721s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 721s Unpacking fio (3.37-1) ... 721s Selecting previously unselected package lsscsi. 721s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 721s Unpacking lsscsi (0.32-1build1) ... 721s Selecting previously unselected package autopkgtest-satdep. 721s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 721s Unpacking autopkgtest-satdep (0) ... 721s Setting up libconfig-general-perl (2.65-2) ... 721s Setting up libisns0t64:ppc64el (0.101-1) ... 721s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 721s Setting up libnbd0 (1.20.2-2) ... 721s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 721s Setting up libglusterfs0:ppc64el (11.1-5ubuntu1) ... 721s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 721s Setting up lsscsi (0.32-1build1) ... 721s Setting up libdaxctl1:ppc64el (77-2.2ubuntu1) ... 721s Setting up libndctl6:ppc64el (77-2.2ubuntu1) ... 721s Setting up librdmacm1t64:ppc64el (52.0-2) ... 721s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 721s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 722s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 722s Setting up libgfxdr0:ppc64el (11.1-5ubuntu1) ... 722s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 722s Setting up open-iscsi (2.1.10-1ubuntu1) ... 722s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 723s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 723s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 723s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 723s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 723s Setting up libgfrpc0:ppc64el (11.1-5ubuntu1) ... 723s Setting up libgfapi0:ppc64el (11.1-5ubuntu1) ... 723s Setting up fio (3.37-1) ... 724s Setting up autopkgtest-satdep (0) ... 724s Processing triggers for man-db (2.12.1-2) ... 725s Processing triggers for initramfs-tools (0.142ubuntu32) ... 725s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 725s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 734s Processing triggers for libc-bin (2.39-0ubuntu9) ... 737s (Reading database ... 72752 files and directories currently installed.) 737s Removing autopkgtest-satdep (0) ... 741s autopkgtest [22:43:29]: test tgtbasedmpaths: [----------------------- 741s + targetname=iqn.2016-11.foo.com:target.iscsi 741s + pwd 741s + cwd=/tmp/autopkgtest.EXlFK5/build.hjt/src 741s + testdir=/mnt/tgtmpathtest 741s + localhost=127.0.0.1 741s + portal=127.0.0.1:3260 741s + maxpaths=4 741s + backfn=backingfile 741s + expectwwid=60000000000000000e00000000010001 741s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 741s + bglog=/tmp/autopkgtest.EXlFK5/tgtbasedmpaths-artifacts/test-background.log 741s + fioprep=/tmp/autopkgtest.EXlFK5/tgtbasedmpaths-artifacts/path-change-prep.fio 741s + fiovrfy=/tmp/autopkgtest.EXlFK5/tgtbasedmpaths-artifacts/path-change-check.fio 741s + mkdir -p /etc/multipath 741s + echo /360000000000000000e00000000010001/ 741s + service tgt restart 741s + truncate --size 100M backingfile 741s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 741s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 741s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.EXlFK5/build.hjt/src/backingfile 741s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 741s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 741s login #1 741s + echo login #1 741s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 741s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 741s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 741s + seq 2 4 741s + echo extra login #2 741s + iscsiadm --mode session -r 1 --op new 741s extra login #2 741s + echo extra login #3 741s + iscsiadm --mode session -r 1 --op new 741s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 741s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 741s extra login #3 741s + echo extra login #4 741s + iscsiadm --mode session -r 1 --op new 741s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 741s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 741s extra login #4 742s + udevadm settle 742s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 742s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 742s + sleep 5 747s Status after initial setup 747s + echo Status after initial setup 747s + tgtadm --lld iscsi --mode target --op show 747s + tgtadm --lld iscsi --op show --mode conn --tid 1 747s + iscsiadm --mode session -P 1 747s + lsscsi -liv 747s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 747s + multipath -v3 -ll 747s 81.944368 | set open fds limit to 1073741816/1073741816 747s 81.944408 | _read_bindings_file: reading /etc/multipath/bindings 747s 81.944435 | loading /usr/lib/multipath/libchecktur.so checker 747s 81.944524 | checker tur: message table size = 4 747s 81.944532 | loading /usr/lib/multipath/libprioconst.so prioritizer 747s 81.944632 | _init_foreign: foreign library "nvme" is not enabled 747s 81.949492 | vda: device node name blacklisted 747s 81.949768 | sda: size = 204800 747s 81.949899 | sda: vendor = IET 747s 81.949921 | sda: product = VIRTUAL-DISK 747s 81.949942 | sda: rev = 0001 747s 81.950636 | sda: h:b:t:l = 0:0:0:1 747s 81.950977 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 747s 81.950982 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 747s 81.950985 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 747s 81.951154 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 747s 81.951159 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 747s 81.951173 | sda: serial = beaf11 747s 81.951177 | sda: detect_checker = yes (setting: multipath internal) 747s 81.951204 | sda checker timeout = 30 s (setting: kernel sysfs) 747s 81.951481 | sda: path_checker = tur (setting: multipath internal) 747s 81.951592 | sda: tur state = up 747s 81.951732 | sdb: size = 204800 747s 81.951863 | sdb: vendor = IET 747s 81.951886 | sdb: product = VIRTUAL-DISK 747s 81.951909 | sdb: rev = 0001 747s 81.952602 | sdb: h:b:t:l = 1:0:0:1 747s 81.952976 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 747s 81.952981 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 747s 81.952983 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 747s 81.953122 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 747s 81.953126 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 747s 81.953139 | sdb: serial = beaf11 747s 81.953141 | sdb: detect_checker = yes (setting: multipath internal) 747s 81.953170 | sdb checker timeout = 30 s (setting: kernel sysfs) 747s 81.953278 | sdb: path_checker = tur (setting: multipath internal) 747s 81.953335 | sdb: tur state = up 747s 81.953459 | sdc: size = 204800 747s 81.953588 | sdc: vendor = IET 747s 81.953610 | sdc: product = VIRTUAL-DISK 747s 81.953632 | sdc: rev = 0001 747s 81.954297 | sdc: h:b:t:l = 2:0:0:1 747s 81.954652 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 747s 81.954656 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 747s 81.954658 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 747s 81.954798 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 747s 81.954802 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 747s 81.954814 | sdc: serial = beaf11 747s 81.954817 | sdc: detect_checker = yes (setting: multipath internal) 747s 81.954843 | sdc checker timeout = 30 s (setting: kernel sysfs) 747s 81.954926 | sdc: path_checker = tur (setting: multipath internal) 747s 81.954988 | sdc: tur state = up 747s 81.955112 | sdd: size = 204800 747s 81.955241 | sdd: vendor = IET 747s 81.955263 | sdd: product = VIRTUAL-DISK 747s 81.955283 | sdd: rev = 0001 747s 81.955955 | sdd: h:b:t:l = 3:0:0:1 747s 81.956351 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 747s 81.956360 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 747s 81.956362 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 747s 81.956505 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 747s 81.956510 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 747s 81.956522 | sdd: serial = beaf11 747s 81.956525 | sdd: detect_checker = yes (setting: multipath internal) 747s 81.956551 | sdd checker timeout = 30 s (setting: kernel sysfs) 747s 81.956634 | sdd: path_checker = tur (setting: multipath internal) 747s 81.956696 | sdd: tur state = up 747s 81.956808 | loop0: device node name blacklisted 747s 81.956897 | loop1: device node name blacklisted 747s 81.956985 | loop2: device node name blacklisted 747s 81.957067 | loop3: device node name blacklisted 747s 81.957149 | loop4: device node name blacklisted 747s 81.957231 | loop5: device node name blacklisted 747s 81.957313 | loop6: device node name blacklisted 747s 81.957394 | loop7: device node name blacklisted 747s 81.957480 | dm-0: device node name blacklisted 747s 81.958539 | multipath-tools v0.9.9 (05/03, 2024) 747s 81.958550 | libdevmapper version 1.02.196 747s 81.958701 | kernel device mapper v4.48.0 747s 81.958713 | DM multipath kernel driver v1.14.0 747s 81.958820 | sda: size = 204800 747s 81.958825 | sda: vendor = IET 747s 81.958828 | sda: product = VIRTUAL-DISK 747s 81.958830 | sda: rev = 0001 747s 81.959452 | sda: h:b:t:l = 0:0:0:1 747s 81.959564 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 747s 81.959583 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 747s 81.959586 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 747s 81.959597 | sda: serial = beaf11 747s 81.959662 | sda: tur state = up 747s 81.959668 | sda: uid = 360000000000000000e00000000010001 (udev) 747s 81.959671 | sda: detect_prio = yes (setting: multipath internal) 747s 81.959674 | sda: prio = const (setting: multipath internal) 747s 81.959676 | sda: prio args = "" (setting: multipath internal) 747s 81.959679 | sda: const prio = 1 747s 81.959701 | sdb: size = 204800 747s 81.959706 | sdb: vendor = IET 747s 81.959709 | sdb: product = VIRTUAL-DISK 747s 81.959711 | sdb: rev = 0001 747s 81.960339 | sdb: h:b:t:l = 1:0:0:1 747s 81.960456 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 747s 81.960474 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 747s 81.960477 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 747s 81.960489 | sdb: serial = beaf11 747s 81.960546 | sdb: tur state = up 747s 81.960551 | sdb: uid = 360000000000000000e00000000010001 (udev) 747s 81.960554 | sdb: detect_prio = yes (setting: multipath internal) 747s 81.960556 | sdb: prio = const (setting: multipath internal) 747s 81.960558 | sdb: prio args = "" (setting: multipath internal) 747s 81.960561 | sdb: const prio = 1 747s 81.960582 | sdc: size = 204800 747s 81.960586 | sdc: vendor = IET 747s 81.960589 | sdc: product = VIRTUAL-DISK 747s 81.960591 | sdc: rev = 0001 747s 81.961209 | sdc: h:b:t:l = 2:0:0:1 747s 81.961321 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 747s 81.961340 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 747s 81.961343 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 747s 81.961354 | sdc: serial = beaf11 747s 81.961462 | sdc: tur state = up 747s 81.961468 | sdc: uid = 360000000000000000e00000000010001 (udev) 747s 81.961470 | sdc: detect_prio = yes (setting: multipath internal) 747s 81.961473 | sdc: prio = const (setting: multipath internal) 747s 81.961475 | sdc: prio args = "" (setting: multipath internal) 747s 81.961477 | sdc: const prio = 1 747s 81.961501 | sdd: size = 204800 747s 81.961505 | sdd: vendor = IET 747s 81.961507 | sdd: product = VIRTUAL-DISK 747s 81.961510 | sdd: rev = 0001 747s 81.962110 | sdd: h:b:t:l = 3:0:0:1 747s 81.962219 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 747s 81.962238 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 747s 81.962241 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 747s 81.962252 | sdd: serial = beaf11 747s 81.962325 | sdd: tur state = up 747s 81.962330 | sdd: uid = 360000000000000000e00000000010001 (udev) 747s 81.962333 | sdd: detect_prio = yes (setting: multipath internal) 747s 81.962335 | sdd: prio = const (setting: multipath internal) 747s 81.962337 | sdd: prio args = "" (setting: multipath internal) 747s 81.962339 | sdd: const prio = 1 747s 81.963117 | unloading tur checker 747s 81.963152 | unloading const prioritizer 747s + dmsetup table 747s + grep . /etc/multipath/bindings /etc/multipath/wwids 747s + systemctl status multipathd.service 747s + systemctl status multipathd.socket 747s + ls -la /dev/mapper/ 747s + echo journal 747s + journalctl -b 747s + echo Test WWN should now point to DM 747s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 747s + grep dm 747s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 747s mke2fs 1.47.1 (20-May-2024) 747s + udevadm settle 747s + sleep 3s 747s Target 1: iqn.2016-11.foo.com:target.iscsi 747s System information: 747s Driver: iscsi 747s State: ready 747s I_T nexus information: 747s I_T nexus: 1 747s Initiator: iqn.2004-10.com.ubuntu:01:6b1b95c3bbf5 alias: autopkgtest 747s Connection: 0 747s IP Address: 127.0.0.1 747s I_T nexus: 2 747s Initiator: iqn.2004-10.com.ubuntu:01:6b1b95c3bbf5 alias: autopkgtest 747s Connection: 0 747s IP Address: 127.0.0.1 747s I_T nexus: 3 747s Initiator: iqn.2004-10.com.ubuntu:01:6b1b95c3bbf5 alias: autopkgtest 747s Connection: 0 747s IP Address: 127.0.0.1 747s I_T nexus: 4 747s Initiator: iqn.2004-10.com.ubuntu:01:6b1b95c3bbf5 alias: autopkgtest 747s Connection: 0 747s IP Address: 127.0.0.1 747s LUN information: 747s LUN: 0 747s Type: controller 747s SCSI ID: IET 00010000 747s SCSI SN: beaf10 747s Size: 0 MB, Block size: 1 747s Online: Yes 747s Removable media: No 747s Prevent removal: No 747s Readonly: No 747s SWP: No 747s Thin-provisioning: No 747s Backing store type: null 747s Backing store path: None 747s Backing store flags: 747s LUN: 1 747s Type: disk 747s SCSI ID: IET 00010001 747s SCSI SN: beaf11 747s Size: 105 MB, Block size: 512 747s Online: Yes 747s Removable media: No 747s Prevent removal: No 747s Readonly: No 747s SWP: No 747s Thin-provisioning: No 747s Backing store type: rdwr 747s Backing store path: /tmp/autopkgtest.EXlFK5/build.hjt/src/backingfile 747s Backing store flags: 747s Account information: 747s ACL information: 747s ALL 747s Session: 4 747s Connection: 0 747s Initiator: iqn.2004-10.com.ubuntu:01:6b1b95c3bbf5 747s IP Address: 127.0.0.1 747s Session: 3 747s Connection: 0 747s Initiator: iqn.2004-10.com.ubuntu:01:6b1b95c3bbf5 747s IP Address: 127.0.0.1 747s Session: 2 747s Connection: 0 747s Initiator: iqn.2004-10.com.ubuntu:01:6b1b95c3bbf5 747s IP Address: 127.0.0.1 747s Session: 1 747s Connection: 0 747s Initiator: iqn.2004-10.com.ubuntu:01:6b1b95c3bbf5 747s IP Address: 127.0.0.1 747s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 747s Current Portal: 127.0.0.1:3260,1 747s Persistent Portal: 127.0.0.1:3260,1 747s ********** 747s Interface: 747s ********** 747s Iface Name: default 747s Iface Transport: tcp 747s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:6b1b95c3bbf5 747s Iface IPaddress: 127.0.0.1 747s Iface HWaddress: default 747s Iface Netdev: default 747s SID: 1 747s iSCSI Connection State: LOGGED IN 747s iSCSI Session State: LOGGED_IN 747s Internal iscsid Session State: NO CHANGE 747s 747s ********** 747s Interface: 747s ********** 747s Iface Name: default 747s Iface Transport: tcp 747s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:6b1b95c3bbf5 747s Iface IPaddress: 127.0.0.1 747s Iface HWaddress: default 747s Iface Netdev: default 747s SID: 2 747s iSCSI Connection State: LOGGED IN 747s iSCSI Session State: LOGGED_IN 747s Internal iscsid Session State: NO CHANGE 747s 747s ********** 747s Interface: 747s ********** 747s Iface Name: default 747s Iface Transport: tcp 747s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:6b1b95c3bbf5 747s Iface IPaddress: 127.0.0.1 747s Iface HWaddress: default 747s Iface Netdev: default 747s SID: 3 747s iSCSI Connection State: LOGGED IN 747s iSCSI Session State: LOGGED_IN 747s Internal iscsid Session State: NO CHANGE 747s 747s ********** 747s Interface: 747s ********** 747s Iface Name: default 747s Iface Transport: tcp 747s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:6b1b95c3bbf5 747s Iface IPaddress: 127.0.0.1 747s Iface HWaddress: default 747s Iface Netdev: default 747s SID: 4 747s iSCSI Connection State: LOGGED IN 747s iSCSI Session State: LOGGED_IN 747s Internal iscsid Session State: NO CHANGE 747s [0:0:0:0] storage IET Controller 0001 - - 747s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 747s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 747s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 747s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 747s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 747s [1:0:0:0] storage IET Controller 0001 - - 747s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 747s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 747s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 747s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 747s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 747s [2:0:0:0] storage IET Controller 0001 - - 747s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 747s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 747s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 747s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 747s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 747s [3:0:0:0] storage IET Controller 0001 - - 747s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 747s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 747s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 747s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 747s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 747s NVMe module may not be loaded 747s ===== paths list ===== 747s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 747s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 747s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 747s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 747s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 747s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 747s size=100M features='0' hwhandler='0' wp=rw 747s |-+- policy='service-time 0' prio=1 status=active 747s | `- 0:0:0:1 sda 8:0 active ready running 747s |-+- policy='service-time 0' prio=1 status=enabled 747s | `- 1:0:0:1 sdb 8:16 active ready running 747s |-+- policy='service-time 0' prio=1 status=enabled 747s | `- 2:0:0:1 sdc 8:32 active ready running 747s `-+- policy='service-time 0' prio=1 status=enabled 747s `- 3:0:0:1 sdd 8:48 active ready running 747s 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 747s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 747s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 747s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 747s /etc/multipath/bindings:# 747s /etc/multipath/bindings:# Format: 747s /etc/multipath/bindings:# alias wwid 747s /etc/multipath/bindings:# 747s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 747s /etc/multipath/wwids:/360000000000000000e00000000010001/ 747s ● multipathd.service - Device-Mapper Multipath Device Controller 747s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 747s Active: active (running) since Fri 2024-08-09 22:42:15 UTC; 1min 19s ago 747s Invocation: 9703e889ab4a4623a1d5acf302d90d01 747s TriggeredBy: ● multipathd.socket 747s Main PID: 309 (multipathd) 747s Status: "up" 747s Tasks: 7 747s Memory: 28.2M (peak: 38.3M) 747s CPU: 61ms 747s CGroup: /system.slice/multipathd.service 747s └─309 /sbin/multipathd -d -s 747s 747s Aug 09 22:42:15 autopkgtest multipathd[309]: multipathd v0.9.9: start up 747s Aug 09 22:42:15 autopkgtest multipathd[309]: reconfigure: setting up paths and maps 747s Aug 09 22:42:15 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 747s Aug 09 22:43:29 autopkgtest multipathd[309]: updated bindings file /etc/multipath/bindings 747s Aug 09 22:43:29 autopkgtest multipathd[309]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 747s Aug 09 22:43:30 autopkgtest multipathd[309]: sda [8:0]: path added to devmap mpatha 747s Aug 09 22:43:30 autopkgtest multipathd[309]: mpatha: performing delayed actions 747s Aug 09 22:43:30 autopkgtest multipathd[309]: 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] 747s ● multipathd.socket - multipathd control socket 747s Loaded: loaded (/usr/lib/systemd/system/multipathd.socket; enabled; preset: enabled) 747s Active: active (running) since Fri 2024-08-09 22:42:15 UTC; 1min 19s ago 747s Invocation: 4d5d049f325449baa48b9384cbfc2128 747s Triggers: ● multipathd.service 747s Listen: @/org/kernel/linux/storage/multipathd (Stream) 747s CGroup: /system.slice/multipathd.socket 747s 747s Notice: journal has been rotated since unit was started, output may be incomplete. 747s total 0 747s drwxr-xr-x 2 root root 80 Aug 9 22:43 . 747s drwxr-xr-x 20 root root 4360 Aug 9 22:43 .. 747s crw------- 1 root root 10, 236 Aug 9 22:42 control 747s lrwxrwxrwx 1 root root 7 Aug 9 22:43 mpatha -> ../dm-0 747s journal 747s Aug 09 22:42:15 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 747s Aug 09 22:42:15 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 747s Aug 09 22:42:15 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 747s Aug 09 22:42:15 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 747s Aug 09 22:42:15 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 747s Aug 09 22:42:15 autopkgtest kernel: Activating Kernel Userspace Access Prevention 747s Aug 09 22:42:15 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 747s Aug 09 22:42:15 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x00000000038a0000 with 64.0 KiB pages (exec) 747s Aug 09 22:42:15 autopkgtest kernel: radix-mmu: Mapped 0x00000000038a0000-0x0000000200000000 with 64.0 KiB pages 747s Aug 09 22:42:15 autopkgtest kernel: lpar: Using radix MMU under hypervisor 747s Aug 09 22:42:15 autopkgtest kernel: Linux version 6.8.0-31-generic (buildd@bos02-ppc64el-018) (powerpc64le-linux-gnu-gcc-13 (Ubuntu 13.2.0-23ubuntu4) 13.2.0, GNU ld (GNU Binutils for Ubuntu) 2.42) #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 (Ubuntu 6.8.0-31.31-generic 6.8.1) 747s Aug 09 22:42:15 autopkgtest kernel: Secure boot mode disabled 747s Aug 09 22:42:15 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc0000000093ea8ea 747s Aug 09 22:42:15 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (raw) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 747s Aug 09 22:42:15 autopkgtest kernel: Partition configured for 4 cpus. 747s Aug 09 22:42:15 autopkgtest kernel: CPU maps initialized for 1 thread per core 747s Aug 09 22:42:15 autopkgtest kernel: (thread shift is 0) 747s Aug 09 22:42:15 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 747s Aug 09 22:42:15 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 747s Aug 09 22:42:15 autopkgtest kernel: ----------------------------------------------------- 747s Aug 09 22:42:15 autopkgtest kernel: phys_mem_size = 0x200000000 747s Aug 09 22:42:15 autopkgtest kernel: dcache_bsize = 0x80 747s Aug 09 22:42:15 autopkgtest kernel: icache_bsize = 0x80 747s Aug 09 22:42:15 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 747s Aug 09 22:42:15 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 747s Aug 09 22:42:15 autopkgtest kernel: always = 0x0000000380008181 747s Aug 09 22:42:15 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 747s Aug 09 22:42:15 autopkgtest kernel: mmu_features = 0x3c007641 747s Aug 09 22:42:15 autopkgtest kernel: firmware_features = 0x00000285455a445f 747s Aug 09 22:42:15 autopkgtest kernel: vmalloc start = 0xc008000000000000 747s Aug 09 22:42:15 autopkgtest kernel: IO start = 0xc00a000000000000 747s Aug 09 22:42:15 autopkgtest kernel: vmemmap start = 0xc00c000000000000 747s Aug 09 22:42:15 autopkgtest kernel: ----------------------------------------------------- 747s Aug 09 22:42:15 autopkgtest kernel: numa: NODE_DATA [mem 0x1eff0c280-0x1eff13fff] 747s Aug 09 22:42:15 autopkgtest kernel: rfi-flush: fallback displacement flush available 747s Aug 09 22:42:15 autopkgtest kernel: rfi-flush: ori type flush available 747s Aug 09 22:42:15 autopkgtest kernel: rfi-flush: mttrig type flush available 747s Aug 09 22:42:15 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 747s Aug 09 22:42:15 autopkgtest kernel: count-cache-flush: hardware flush enabled. 747s Aug 09 22:42:15 autopkgtest kernel: link-stack-flush: software flush enabled. 747s Aug 09 22:42:15 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 747s Aug 09 22:42:15 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 747s Aug 09 22:42:15 autopkgtest kernel: stf-barrier: eieio barrier available 747s Aug 09 22:42:15 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 747s Aug 09 22:42:15 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 747s Aug 09 22:42:15 autopkgtest kernel: PPC64 nvram contains 65536 bytes 747s Aug 09 22:42:15 autopkgtest kernel: barrier-nospec: using ORI speculation barrier 747s Aug 09 22:42:15 autopkgtest kernel: barrier-nospec: patched 269 locations 747s Aug 09 22:42:15 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 747s Aug 09 22:42:15 autopkgtest kernel: Memory hole size: 0MB 747s Aug 09 22:42:15 autopkgtest kernel: Zone ranges: 747s Aug 09 22:42:15 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 747s Aug 09 22:42:15 autopkgtest kernel: Device empty 747s Aug 09 22:42:15 autopkgtest kernel: Movable zone start for each node 747s Aug 09 22:42:15 autopkgtest kernel: Early memory node ranges 747s Aug 09 22:42:15 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 747s Aug 09 22:42:15 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 747s Aug 09 22:42:15 autopkgtest kernel: percpu: Embedded 12 pages/cpu s609960 r0 d176472 u786432 747s Aug 09 22:42:15 autopkgtest kernel: pcpu-alloc: s609960 r0 d176472 u786432 alloc=12*65536 747s Aug 09 22:42:15 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 747s Aug 09 22:42:15 autopkgtest kernel: Kernel command line: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic root=UUID=55f4738b-dbc7-4aef-90fe-6bd3178557bc ro console=hvc0 earlyprintk 747s Aug 09 22:42:15 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic", will be passed to user space. 747s Aug 09 22:42:15 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 747s Aug 09 22:42:15 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 747s Aug 09 22:42:15 autopkgtest kernel: Fallback order for Node 0: 0 747s Aug 09 22:42:15 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 130944 747s Aug 09 22:42:15 autopkgtest kernel: Policy zone: Normal 747s Aug 09 22:42:15 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 747s Aug 09 22:42:15 autopkgtest kernel: Memory: 7969152K/8388608K available (23680K kernel code, 4096K rwdata, 25472K rodata, 8832K init, 1901K bss, 419456K reserved, 0K cma-reserved) 747s Aug 09 22:42:15 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 747s Aug 09 22:42:15 autopkgtest kernel: ftrace: allocating 51717 entries in 19 pages 747s Aug 09 22:42:15 autopkgtest kernel: ftrace: allocated 19 pages with 3 groups 747s Aug 09 22:42:15 autopkgtest kernel: trace event string verifier disabled 747s Aug 09 22:42:15 autopkgtest kernel: rcu: Hierarchical RCU implementation. 747s Aug 09 22:42:15 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 747s Aug 09 22:42:15 autopkgtest kernel: Rude variant of Tasks RCU enabled. 747s Aug 09 22:42:15 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 747s Aug 09 22:42:15 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 747s Aug 09 22:42:15 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 747s Aug 09 22:42:15 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 747s Aug 09 22:42:15 autopkgtest kernel: xive: Using IRQ range [0-3] 747s Aug 09 22:42:15 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 747s Aug 09 22:42:15 autopkgtest kernel: xive: Using priority 6 for all interrupts 747s Aug 09 22:42:15 autopkgtest kernel: xive: Using 64kB queues 747s Aug 09 22:42:15 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 747s Aug 09 22:42:15 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 747s Aug 09 22:42:15 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 747s Aug 09 22:42:15 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 747s Aug 09 22:42:15 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 747s Aug 09 22:42:15 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 747s Aug 09 22:42:15 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 747s Aug 09 22:42:15 autopkgtest kernel: Console: colour dummy device 80x25 747s Aug 09 22:42:15 autopkgtest kernel: pid_max: default: 32768 minimum: 301 747s Aug 09 22:42:15 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,integrity 747s Aug 09 22:42:15 autopkgtest kernel: landlock: Up and running. 747s Aug 09 22:42:15 autopkgtest kernel: Yama: becoming mindful. 747s Aug 09 22:42:15 autopkgtest kernel: AppArmor: AppArmor initialized 747s Aug 09 22:42:15 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 747s Aug 09 22:42:15 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 747s Aug 09 22:42:15 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 747s Aug 09 22:42:15 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 747s Aug 09 22:42:15 autopkgtest kernel: POWER9 performance monitor hardware support registered 747s Aug 09 22:42:15 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 747s Aug 09 22:42:15 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 747s Aug 09 22:42:15 autopkgtest kernel: smp: Bringing up secondary CPUs ... 747s Aug 09 22:42:15 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 747s Aug 09 22:42:15 autopkgtest kernel: numa: Node 0 CPUs: 0-3 747s Aug 09 22:42:15 autopkgtest kernel: devtmpfs: initialized 747s Aug 09 22:42:15 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 747s Aug 09 22:42:15 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 747s Aug 09 22:42:15 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 747s Aug 09 22:42:15 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 747s Aug 09 22:42:15 autopkgtest kernel: PCI: OF: PROBE_ONLY disabled 747s Aug 09 22:42:15 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 747s Aug 09 22:42:15 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 747s Aug 09 22:42:15 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 747s Aug 09 22:42:15 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 747s Aug 09 22:42:15 autopkgtest kernel: audit: initializing netlink subsys (disabled) 747s Aug 09 22:42:15 autopkgtest kernel: audit: type=2000 audit(1723243333.040:1): state=initialized audit_enabled=0 res=1 747s Aug 09 22:42:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 747s Aug 09 22:42:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 747s Aug 09 22:42:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 747s Aug 09 22:42:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 747s Aug 09 22:42:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 747s Aug 09 22:42:15 autopkgtest kernel: cpuidle: using governor ladder 747s Aug 09 22:42:15 autopkgtest kernel: cpuidle: using governor menu 747s Aug 09 22:42:15 autopkgtest kernel: RTAS daemon started 747s Aug 09 22:42:15 autopkgtest kernel: pstore: Using crash dump compression: deflate 747s Aug 09 22:42:15 autopkgtest kernel: pstore: Registered nvram as persistent store backend 747s Aug 09 22:42:15 autopkgtest kernel: EEH: pSeries platform initialized 747s Aug 09 22:42:15 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 747s Aug 09 22:42:15 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 747s Aug 09 22:42:15 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 747s Aug 09 22:42:15 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 747s Aug 09 22:42:15 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 747s Aug 09 22:42:15 autopkgtest kernel: iommu: Default domain type: Translated 747s Aug 09 22:42:15 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 747s Aug 09 22:42:15 autopkgtest kernel: SCSI subsystem initialized 747s Aug 09 22:42:15 autopkgtest kernel: libata version 3.00 loaded. 747s Aug 09 22:42:15 autopkgtest kernel: usbcore: registered new interface driver usbfs 747s Aug 09 22:42:15 autopkgtest kernel: usbcore: registered new interface driver hub 747s Aug 09 22:42:15 autopkgtest kernel: usbcore: registered new device driver usb 747s Aug 09 22:42:15 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 747s Aug 09 22:42:15 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 747s Aug 09 22:42:15 autopkgtest kernel: PTP clock support registered 747s Aug 09 22:42:15 autopkgtest kernel: EDAC MC: Ver: 3.0.0 747s Aug 09 22:42:15 autopkgtest kernel: NetLabel: Initializing 747s Aug 09 22:42:15 autopkgtest kernel: NetLabel: domain hash size = 128 747s Aug 09 22:42:15 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 747s Aug 09 22:42:15 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 747s Aug 09 22:42:15 autopkgtest kernel: mctp: management component transport protocol core 747s Aug 09 22:42:15 autopkgtest kernel: NET: Registered PF_MCTP protocol family 747s Aug 09 22:42:15 autopkgtest kernel: PCI: Probing PCI hardware 747s Aug 09 22:42:15 autopkgtest kernel: PCI host bridge to bus 0000:00 747s Aug 09 22:42:15 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 747s Aug 09 22:42:15 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 747s Aug 09 22:42:15 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 747s Aug 09 22:42:15 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:05.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:06.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:07.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 747s Aug 09 22:42:15 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 747s Aug 09 22:42:15 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 747s Aug 09 22:42:15 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 747s Aug 09 22:42:15 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 747s Aug 09 22:42:15 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:05.0: Adding to iommu group 0 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:06.0: Adding to iommu group 0 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:07.0: Adding to iommu group 0 747s Aug 09 22:42:15 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 747s Aug 09 22:42:15 autopkgtest kernel: PCI: Probing PCI hardware done 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:07.0: vgaarb: setting as boot VGA device 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:07.0: vgaarb: bridge control possible 747s Aug 09 22:42:15 autopkgtest kernel: pci 0000:00:07.0: vgaarb: VGA device added: decodes=io+mem,owns=mem,locks=none 747s Aug 09 22:42:15 autopkgtest kernel: vgaarb: loaded 747s Aug 09 22:42:15 autopkgtest kernel: clocksource: Switched to clocksource timebase 747s Aug 09 22:42:15 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 747s Aug 09 22:42:15 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 747s Aug 09 22:42:15 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 747s Aug 09 22:42:15 autopkgtest kernel: NET: Registered PF_INET protocol family 747s Aug 09 22:42:15 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 747s Aug 09 22:42:15 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 747s Aug 09 22:42:15 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 747s Aug 09 22:42:15 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 747s Aug 09 22:42:15 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 747s Aug 09 22:42:15 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 747s Aug 09 22:42:15 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 747s Aug 09 22:42:15 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 747s Aug 09 22:42:15 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 747s Aug 09 22:42:15 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 747s Aug 09 22:42:15 autopkgtest kernel: NET: Registered PF_XDP protocol family 747s Aug 09 22:42:15 autopkgtest kernel: PCI: CLS 0 bytes, default 128 747s Aug 09 22:42:15 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 747s Aug 09 22:42:15 autopkgtest kernel: Initialise system trusted keyrings 747s Aug 09 22:42:15 autopkgtest kernel: Key type blacklist registered 747s Aug 09 22:42:15 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 747s Aug 09 22:42:15 autopkgtest kernel: zbud: loaded 747s Aug 09 22:42:15 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 747s Aug 09 22:42:15 autopkgtest kernel: fuse: init (API version 7.39) 747s Aug 09 22:42:15 autopkgtest kernel: integrity: Platform Keyring initialized 747s Aug 09 22:42:15 autopkgtest kernel: integrity: Machine keyring initialized 747s Aug 09 22:42:15 autopkgtest kernel: Key type asymmetric registered 747s Aug 09 22:42:15 autopkgtest kernel: Asymmetric key parser 'x509' registered 747s Aug 09 22:42:15 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 747s Aug 09 22:42:15 autopkgtest kernel: io scheduler mq-deadline registered 747s Aug 09 22:42:15 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 747s Aug 09 22:42:15 autopkgtest kernel: virtio-pci 0000:00:01.0: ibm,query-pe-dma-windows(2026) 800 8000000 20000000 returned 0, lb=80000000 ps=7 wn=1 747s Aug 09 22:42:15 autopkgtest kernel: virtio-pci 0000:00:01.0: ibm,create-pe-dma-window(2027) 800 8000000 20000000 18 21 returned 0 (liobn = 0x80000001 starting addr = 8000000 0) 747s Aug 09 22:42:15 autopkgtest kernel: virtio-pci 0000:00:03.0: enabling device (0100 -> 0103) 747s Aug 09 22:42:15 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 747s Aug 09 22:42:15 autopkgtest kernel: virtio-pci 0000:00:05.0: enabling device (0100 -> 0103) 747s Aug 09 22:42:15 autopkgtest kernel: virtio-pci 0000:00:06.0: enabling device (0100 -> 0103) 747s Aug 09 22:42:15 autopkgtest kernel: printk: legacy console [hvc0] enabled 747s Aug 09 22:42:15 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 747s Aug 09 22:42:15 autopkgtest kernel: Freeing initrd memory: 51072K 747s Aug 09 22:42:15 autopkgtest kernel: Non-volatile memory driver v1.3 747s Aug 09 22:42:15 autopkgtest kernel: Linux agpgart interface v0.103 747s Aug 09 22:42:15 autopkgtest kernel: loop: module loaded 747s Aug 09 22:42:15 autopkgtest kernel: virtio_blk virtio2: 4/0/0 default/read/poll queues 747s Aug 09 22:42:15 autopkgtest kernel: virtio_blk virtio2: [vda] 209715200 512-byte logical blocks (107 GB/100 GiB) 747s Aug 09 22:42:15 autopkgtest kernel: vda: vda1 vda2 747s Aug 09 22:42:15 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 747s Aug 09 22:42:15 autopkgtest kernel: PPP generic driver version 2.4.2 747s Aug 09 22:42:15 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 747s Aug 09 22:42:15 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 747s Aug 09 22:42:15 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-08-09T22:42:13 UTC (1723243333) 747s Aug 09 22:42:15 autopkgtest kernel: i2c_dev: i2c /dev entries driver 747s Aug 09 22:42:15 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 747s Aug 09 22:42:15 autopkgtest kernel: device-mapper: uevent: version 1.0.3 747s Aug 09 22:42:15 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@redhat.com 747s Aug 09 22:42:15 autopkgtest kernel: pseries_idle_driver registered 747s Aug 09 22:42:15 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 747s Aug 09 22:42:15 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 747s Aug 09 22:42:15 autopkgtest kernel: NET: Registered PF_INET6 protocol family 747s Aug 09 22:42:15 autopkgtest kernel: Segment Routing with IPv6 747s Aug 09 22:42:15 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 747s Aug 09 22:42:15 autopkgtest kernel: NET: Registered PF_PACKET protocol family 747s Aug 09 22:42:15 autopkgtest kernel: Key type dns_resolver registered 747s Aug 09 22:42:15 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 747s Aug 09 22:42:15 autopkgtest kernel: drmem: No dynamic reconfiguration memory found 747s Aug 09 22:42:15 autopkgtest kernel: registered taskstats version 1 747s Aug 09 22:42:15 autopkgtest kernel: Loading compiled-in X.509 certificates 747s Aug 09 22:42:15 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 747s Aug 09 22:42:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 747s Aug 09 22:42:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 747s Aug 09 22:42:15 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 747s Aug 09 22:42:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 747s Aug 09 22:42:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 747s Aug 09 22:42:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 747s Aug 09 22:42:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 747s Aug 09 22:42:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 747s Aug 09 22:42:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 747s Aug 09 22:42:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 747s Aug 09 22:42:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 747s Aug 09 22:42:15 autopkgtest kernel: Key type .fscrypt registered 747s Aug 09 22:42:15 autopkgtest kernel: Key type fscrypt-provisioning registered 747s Aug 09 22:42:15 autopkgtest kernel: Key type encrypted registered 747s Aug 09 22:42:15 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 747s Aug 09 22:42:15 autopkgtest kernel: Secure boot mode disabled 747s Aug 09 22:42:15 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 747s Aug 09 22:42:15 autopkgtest kernel: Loading compiled-in module X.509 certificates 747s Aug 09 22:42:15 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 747s Aug 09 22:42:15 autopkgtest kernel: ima: Allocated hash algorithm: sha256 747s Aug 09 22:42:15 autopkgtest kernel: Secure boot mode disabled 747s Aug 09 22:42:15 autopkgtest kernel: Trusted boot mode disabled 747s Aug 09 22:42:15 autopkgtest kernel: ima: No architecture policies found 747s Aug 09 22:42:15 autopkgtest kernel: evm: Initialising EVM extended attributes: 747s Aug 09 22:42:15 autopkgtest kernel: evm: security.selinux 747s Aug 09 22:42:15 autopkgtest kernel: evm: security.SMACK64 747s Aug 09 22:42:15 autopkgtest kernel: evm: security.SMACK64EXEC 747s Aug 09 22:42:15 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 747s Aug 09 22:42:15 autopkgtest kernel: evm: security.SMACK64MMAP 747s Aug 09 22:42:15 autopkgtest kernel: evm: security.apparmor 747s Aug 09 22:42:15 autopkgtest kernel: evm: security.ima 747s Aug 09 22:42:15 autopkgtest kernel: evm: security.capability 747s Aug 09 22:42:15 autopkgtest kernel: evm: HMAC attrs: 0x1 747s Aug 09 22:42:15 autopkgtest kernel: SED: plpks not available 747s Aug 09 22:42:15 autopkgtest kernel: clk: Disabling unused clocks 747s Aug 09 22:42:15 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 747s Aug 09 22:42:15 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8832K 747s Aug 09 22:42:15 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 747s Aug 09 22:42:15 autopkgtest kernel: Run /init as init process 747s Aug 09 22:42:15 autopkgtest kernel: with arguments: 747s Aug 09 22:42:15 autopkgtest kernel: /init 747s Aug 09 22:42:15 autopkgtest kernel: earlyprintk 747s Aug 09 22:42:15 autopkgtest kernel: with environment: 747s Aug 09 22:42:15 autopkgtest kernel: HOME=/ 747s Aug 09 22:42:15 autopkgtest kernel: TERM=linux 747s Aug 09 22:42:15 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic 747s Aug 09 22:42:15 autopkgtest kernel: random: crng init done 747s Aug 09 22:42:15 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 747s Aug 09 22:42:15 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 747s Aug 09 22:42:15 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 1 747s Aug 09 22:42:15 autopkgtest kernel: xhci_hcd 0000:00:02.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010 747s Aug 09 22:42:15 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 747s Aug 09 22:42:15 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2 747s Aug 09 22:42:15 autopkgtest kernel: xhci_hcd 0000:00:02.0: Host supports USB 3.0 SuperSpeed 747s Aug 09 22:42:15 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.08 747s Aug 09 22:42:15 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 747s Aug 09 22:42:15 autopkgtest kernel: usb usb1: Product: xHCI Host Controller 747s Aug 09 22:42:15 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 747s Aug 09 22:42:15 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:02.0 747s Aug 09 22:42:15 autopkgtest kernel: hub 1-0:1.0: USB hub found 747s Aug 09 22:42:15 autopkgtest kernel: hub 1-0:1.0: 4 ports detected 747s Aug 09 22:42:15 autopkgtest kernel: usb usb2: We don't know the algorithms for LPM for this host, disabling LPM. 747s Aug 09 22:42:15 autopkgtest kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.08 747s Aug 09 22:42:15 autopkgtest kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 747s Aug 09 22:42:15 autopkgtest kernel: usb usb2: Product: xHCI Host Controller 747s Aug 09 22:42:15 autopkgtest kernel: usb usb2: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 747s Aug 09 22:42:15 autopkgtest kernel: usb usb2: SerialNumber: 0000:00:02.0 747s Aug 09 22:42:15 autopkgtest kernel: hub 2-0:1.0: USB hub found 747s Aug 09 22:42:15 autopkgtest kernel: hub 2-0:1.0: 4 ports detected 747s Aug 09 22:42:15 autopkgtest kernel: [drm] Found bochs VGA, ID 0xb0c5. 747s Aug 09 22:42:15 autopkgtest kernel: [drm] Framebuffer size 16384 kB @ 0x200081000000, mmio @ 0x200082000000. 747s Aug 09 22:42:15 autopkgtest kernel: [drm] Found EDID data blob. 747s Aug 09 22:42:15 autopkgtest kernel: [drm] Initialized bochs-drm 1.0.0 20130925 for 0000:00:07.0 on minor 0 747s Aug 09 22:42:15 autopkgtest kernel: fbcon: Deferring console take-over 747s Aug 09 22:42:15 autopkgtest kernel: bochs-drm 0000:00:07.0: [drm] fb0: bochs-drmdrmfb frame buffer device 747s Aug 09 22:42:15 autopkgtest kernel: raid6: vpermxor8 gen() 20460 MB/s 747s Aug 09 22:42:15 autopkgtest kernel: raid6: vpermxor4 gen() 17449 MB/s 747s Aug 09 22:42:15 autopkgtest kernel: usb 1-1: new high-speed USB device number 2 using xhci_hcd 747s Aug 09 22:42:15 autopkgtest kernel: raid6: vpermxor2 gen() 14589 MB/s 747s Aug 09 22:42:15 autopkgtest kernel: raid6: vpermxor1 gen() 12333 MB/s 747s Aug 09 22:42:15 autopkgtest kernel: usb 1-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 747s Aug 09 22:42:15 autopkgtest kernel: usb 1-1: New USB device strings: Mfr=1, Product=4, SerialNumber=11 747s Aug 09 22:42:15 autopkgtest kernel: usb 1-1: Product: QEMU USB Keyboard 747s Aug 09 22:42:15 autopkgtest kernel: usb 1-1: Manufacturer: QEMU 747s Aug 09 22:42:15 autopkgtest kernel: usb 1-1: SerialNumber: 68284-pci@800000020000000:02.0-1 747s Aug 09 22:42:15 autopkgtest kernel: hid: raw HID events driver (C) Jiri Kosina 747s Aug 09 22:42:15 autopkgtest kernel: usbcore: registered new interface driver usbhid 747s Aug 09 22:42:15 autopkgtest kernel: usbhid: USB HID core driver 747s Aug 09 22:42:15 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 747s Aug 09 22:42:15 autopkgtest kernel: raid6: altivecx8 gen() 13183 MB/s 747s Aug 09 22:42:15 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 747s Aug 09 22:42:15 autopkgtest kernel: raid6: altivecx4 gen() 13130 MB/s 747s Aug 09 22:42:15 autopkgtest kernel: usb 1-2: new high-speed USB device number 3 using xhci_hcd 747s Aug 09 22:42:15 autopkgtest kernel: raid6: altivecx2 gen() 10160 MB/s 747s Aug 09 22:42:15 autopkgtest kernel: raid6: altivecx1 gen() 7816 MB/s 747s Aug 09 22:42:15 autopkgtest kernel: usb 1-2: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 747s Aug 09 22:42:15 autopkgtest kernel: usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=9 747s Aug 09 22:42:15 autopkgtest kernel: usb 1-2: Product: QEMU USB Mouse 747s Aug 09 22:42:15 autopkgtest kernel: usb 1-2: Manufacturer: QEMU 747s Aug 09 22:42:15 autopkgtest kernel: usb 1-2: SerialNumber: 89126-pci@800000020000000:02.0-2 747s Aug 09 22:42:15 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 747s Aug 09 22:42:15 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 747s Aug 09 22:42:15 autopkgtest kernel: raid6: int64x8 gen() 6304 MB/s 747s Aug 09 22:42:15 autopkgtest kernel: raid6: int64x4 gen() 7359 MB/s 747s Aug 09 22:42:15 autopkgtest kernel: raid6: int64x2 gen() 5818 MB/s 747s Aug 09 22:42:15 autopkgtest kernel: raid6: int64x1 gen() 4587 MB/s 747s Aug 09 22:42:15 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 20460 MB/s 747s Aug 09 22:42:15 autopkgtest kernel: raid6: using intx1 recovery algorithm 747s Aug 09 22:42:15 autopkgtest kernel: xor: measuring software checksum speed 747s Aug 09 22:42:15 autopkgtest kernel: 8regs : 17353 MB/sec 747s Aug 09 22:42:15 autopkgtest kernel: 8regs_prefetch : 15496 MB/sec 747s Aug 09 22:42:15 autopkgtest kernel: 32regs : 17370 MB/sec 747s Aug 09 22:42:15 autopkgtest kernel: 32regs_prefetch : 15562 MB/sec 747s Aug 09 22:42:15 autopkgtest kernel: altivec : 19366 MB/sec 747s Aug 09 22:42:15 autopkgtest kernel: xor: using function: altivec (19366 MB/sec) 747s Aug 09 22:42:15 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 747s Aug 09 22:42:15 autopkgtest kernel: EXT4-fs (vda1): orphan cleanup on readonly fs 747s Aug 09 22:42:15 autopkgtest kernel: EXT4-fs (vda1): mounted filesystem 55f4738b-dbc7-4aef-90fe-6bd3178557bc ro with ordered data mode. Quota mode: none. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Inserted module 'autofs4' 747s Aug 09 22:42:15 autopkgtest systemd[1]: systemd 256.4-2ubuntu1 running in system mode (+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -XKBCOMMON +UTMP +SYSVINIT +LIBARCHIVE) 747s Aug 09 22:42:15 autopkgtest systemd[1]: Detected virtualization kvm. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Detected architecture ppc64-le. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Hostname set to . 747s Aug 09 22:42:15 autopkgtest systemd[1]: bpf-restrict-fs: BPF LSM hook not enabled in the kernel, BPF LSM not supported. 747s Aug 09 22:42:15 autopkgtest kernel: NET: Registered PF_VSOCK protocol family 747s Aug 09 22:42:15 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. 747s Aug 09 22:42:15 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. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Queued start job for default target graphical.target. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Reached target swap.target - Swaps. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Listening on multipathd.socket - multipathd control socket. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 747s Aug 09 22:42:15 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Sockets. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounting run-lock.mount - Legacy Locks Directory /run/lock... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting modprobe@dm_multipath.service - Load Kernel Module dm_multipath... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 747s Aug 09 22:42:15 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 747s Aug 09 22:42:15 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). 747s Aug 09 22:42:15 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). 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounted run-lock.mount - Legacy Locks Directory /run/lock. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 747s Aug 09 22:42:15 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 747s Aug 09 22:42:15 autopkgtest systemd[1]: modprobe@dm_multipath.service: Deactivated successfully. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished modprobe@dm_multipath.service - Load Kernel Module dm_multipath. 747s Aug 09 22:42:15 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 747s Aug 09 22:42:15 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 747s Aug 09 22:42:15 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. 747s Aug 09 22:42:15 autopkgtest systemd-journald[279]: Collecting audit messages is disabled. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 747s Aug 09 22:42:15 autopkgtest kernel: EXT4-fs (vda1): re-mounted 55f4738b-dbc7-4aef-90fe-6bd3178557bc r/w. Quota mode: none. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting cloud-init-main.service - Cloud-init: Single Process... 747s Aug 09 22:42:15 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 747s Aug 09 22:42:15 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 747s Aug 09 22:42:15 autopkgtest systemd-journald[279]: Journal started 747s Aug 09 22:42:15 autopkgtest systemd-journald[279]: Runtime Journal (/run/log/journal/86226d6488624c739b9342e0bcb40acc) is 8M, max 78.4M, 70.4M free. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 747s Aug 09 22:42:15 autopkgtest multipathd[309]: multipathd v0.9.9: start up 747s Aug 09 22:42:15 autopkgtest multipathd[309]: reconfigure: setting up paths and maps 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 747s Aug 09 22:42:15 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 747s Aug 09 22:42:15 autopkgtest systemd-journald[279]: Time spent on flushing to /var/log/journal/86226d6488624c739b9342e0bcb40acc is 19.987ms for 465 entries. 747s Aug 09 22:42:15 autopkgtest systemd-journald[279]: System Journal (/var/log/journal/86226d6488624c739b9342e0bcb40acc) is 19.1M, max 4G, 3.9G free. 747s Aug 09 22:42:15 autopkgtest systemd-journald[279]: Received client request to flush runtime journal. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 747s Aug 09 22:42:15 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 747s Aug 09 22:42:15 autopkgtest apparmor.systemd[348]: Restarting AppArmor 747s Aug 09 22:42:15 autopkgtest apparmor.systemd[348]: Reloading AppArmor profiles 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 747s Aug 09 22:42:15 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 353 (systemd-binfmt) 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 747s Aug 09 22:42:15 autopkgtest systemd-tmpfiles[370]: /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 747s Aug 09 22:42:15 autopkgtest kernel: audit: type=1400 audit(1723243335.584:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=375 comm="apparmor_parser" 747s Aug 09 22:42:15 autopkgtest kernel: audit: type=1400 audit(1723243335.584:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=376 comm="apparmor_parser" 747s Aug 09 22:42:15 autopkgtest kernel: audit: type=1400 audit(1723243335.588:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=377 comm="apparmor_parser" 747s Aug 09 22:42:15 autopkgtest kernel: audit: type=1400 audit(1723243335.588:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=374 comm="apparmor_parser" 747s Aug 09 22:42:15 autopkgtest kernel: audit: type=1400 audit(1723243335.588:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="busybox" pid=381 comm="apparmor_parser" 747s Aug 09 22:42:15 autopkgtest kernel: audit: type=1400 audit(1723243335.588:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=378 comm="apparmor_parser" 747s Aug 09 22:42:15 autopkgtest kernel: audit: type=1400 audit(1723243335.588:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=380 comm="apparmor_parser" 747s Aug 09 22:42:15 autopkgtest kernel: audit: type=1400 audit(1723243335.592:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="cam" pid=382 comm="apparmor_parser" 747s Aug 09 22:42:15 autopkgtest kernel: audit: type=1400 audit(1723243335.592:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=379 comm="apparmor_parser" 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. 747s Aug 09 22:42:15 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 747s Aug 09 22:42:15 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 747s Aug 09 22:42:15 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 747s Aug 09 22:42:15 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). 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 747s Aug 09 22:42:15 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 747s Aug 09 22:42:15 autopkgtest systemd-udevd[356]: Using default interface naming scheme 'v255'. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 747s Aug 09 22:42:15 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 747s Aug 09 22:42:15 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 747s Aug 09 22:42:15 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). 747s Aug 09 22:42:15 autopkgtest systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 747s Aug 09 22:42:15 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 747s Aug 09 22:42:15 autopkgtest (udev-worker)[497]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 747s Aug 09 22:42:15 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 747s Aug 09 22:42:16 autopkgtest systemd[1]: Started cloud-init-main.service - Cloud-init: Single Process. 747s Aug 09 22:42:16 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 747s Aug 09 22:42:16 autopkgtest cloud-init[678]: Cloud-init v. 24.4~1gedd92b71-0ubuntu1 running 'init-local' at Fri, 09 Aug 2024 22:42:16 +0000. Up 3.11 seconds. 747s Aug 09 22:42:16 autopkgtest dhcpcd[681]: dhcpcd-10.0.8 starting 747s Aug 09 22:42:16 autopkgtest dhcpcd[684]: DUID 00:01:00:01:2e:48:b4:0c:fa:16:3e:6f:dc:1d 747s Aug 09 22:42:16 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 747s Aug 09 22:42:16 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 747s Aug 09 22:42:16 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 747s Aug 09 22:42:16 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 747s Aug 09 22:42:16 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 747s Aug 09 22:42:16 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 747s Aug 09 22:42:16 autopkgtest dhcpcd[684]: enp0s1: IAID 3e:97:cd:ae 747s Aug 09 22:42:16 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 747s Aug 09 22:42:16 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 747s Aug 09 22:42:16 autopkgtest systemd-resolved[399]: Positive Trust Anchors: 747s Aug 09 22:42:16 autopkgtest systemd-resolved[399]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 747s Aug 09 22:42:16 autopkgtest systemd-resolved[399]: 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 747s Aug 09 22:42:16 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 747s Aug 09 22:42:16 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 747s Aug 09 22:42:16 autopkgtest systemd-resolved[399]: Using system hostname 'autopkgtest'. 747s Aug 09 22:42:16 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 747s Aug 09 22:42:16 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 747s Aug 09 22:42:17 autopkgtest dhcpcd[684]: enp0s1: rebinding lease of 10.145.227.145 747s Aug 09 22:42:17 autopkgtest dhcpcd[684]: enp0s1: leased 10.145.227.145 for 43200 seconds 747s Aug 09 22:42:17 autopkgtest dhcpcd[684]: enp0s1: adding route to 10.145.227.0/24 747s Aug 09 22:42:17 autopkgtest dhcpcd[684]: enp0s1: adding host route to 169.254.169.254 via 10.145.227.2 747s Aug 09 22:42:17 autopkgtest dhcpcd[684]: enp0s1: adding default route via 10.145.227.1 747s Aug 09 22:42:17 autopkgtest dhcpcd[684]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 747s Aug 09 22:42:23 autopkgtest sh[674]: Completed socket interaction for boot stage local 747s Aug 09 22:42:23 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 747s Aug 09 22:42:23 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 747s Aug 09 22:42:23 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 747s Aug 09 22:42:23 autopkgtest systemd-networkd[718]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 747s Aug 09 22:42:23 autopkgtest systemd-networkd[718]: lo: Link UP 747s Aug 09 22:42:23 autopkgtest systemd-networkd[718]: lo: Gained carrier 747s Aug 09 22:42:23 autopkgtest systemd-networkd[718]: Enumeration completed 747s Aug 09 22:42:23 autopkgtest systemd-networkd[718]: enp0s1: Link UP 747s Aug 09 22:42:23 autopkgtest systemd-networkd[718]: enp0s1: Gained carrier 747s Aug 09 22:42:23 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 747s Aug 09 22:42:23 autopkgtest systemd-timesyncd[400]: Network configuration changed, trying to establish connection. 747s Aug 09 22:42:23 autopkgtest systemd[1]: Reached target network.target - Network. 747s Aug 09 22:42:23 autopkgtest systemd-networkd[718]: enp0s1: Gained IPv6LL 747s Aug 09 22:42:23 autopkgtest systemd-networkd[718]: enp0s1: Link DOWN 747s Aug 09 22:42:23 autopkgtest systemd-networkd[718]: enp0s1: Lost carrier 747s Aug 09 22:42:23 autopkgtest systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... 747s Aug 09 22:42:23 autopkgtest systemd-networkd[718]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 747s Aug 09 22:42:23 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 747s Aug 09 22:42:23 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 747s Aug 09 22:42:23 autopkgtest systemd-networkd[718]: enp0s1: Link UP 747s Aug 09 22:42:23 autopkgtest systemd-networkd[718]: enp0s1: Gained carrier 747s Aug 09 22:42:23 autopkgtest systemd-networkd[718]: enp0s1: DHCPv4 address 10.145.227.145/24, gateway 10.145.227.1 acquired from 10.145.227.1 747s Aug 09 22:42:23 autopkgtest systemd-timesyncd[400]: Network configuration changed, trying to establish connection. 747s Aug 09 22:42:23 autopkgtest systemd-timesyncd[400]: Network configuration changed, trying to establish connection. 747s Aug 09 22:42:23 autopkgtest systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. 747s Aug 09 22:42:24 autopkgtest systemd-networkd[718]: enp0s1: Gained IPv6LL 747s Aug 09 22:42:24 autopkgtest systemd-timesyncd[400]: Network configuration changed, trying to establish connection. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting cloud-init-network.service - Cloud-init: Network Stage... 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: Cloud-init v. 24.4~1gedd92b71-0ubuntu1 running 'init' at Fri, 09 Aug 2024 22:42:24 +0000. Up 11.37 seconds. 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | enp0s1 | True | 10.145.227.145 | 255.255.255.0 | global | fa:16:3e:97:cd:ae | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | enp0s1 | True | fe80::f816:3eff:fe97:cdae/64 | . | link | fa:16:3e:97:cd:ae | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | lo | True | ::1/128 | . | host | . | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++++ 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | 0 | 0.0.0.0 | 10.145.227.1 | 0.0.0.0 | enp0s1 | UG | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | 1 | 10.145.227.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | 2 | 10.145.227.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | 3 | 10.145.227.2 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | 4 | 91.189.91.131 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | 5 | 91.189.91.132 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | 6 | 169.254.169.254 | 10.145.227.2 | 255.255.255.255 | enp0s1 | UGH | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: +-------+-------------+---------+-----------+-------+ 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | Route | Destination | Gateway | Interface | Flags | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: +-------+-------------+---------+-----------+-------+ 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | 2 | local | :: | enp0s1 | U | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: | 3 | multicast | :: | enp0s1 | U | 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: ci-info: +-------+-------------+---------+-----------+-------+ 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: 2024-08-09 22:42:24,657 - 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. 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: 2024-08-09 22:42:24,657 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 747s Aug 09 22:42:24 autopkgtest sh[727]: Completed socket interaction for boot stage network 747s Aug 09 22:42:24 autopkgtest systemd[1]: Finished cloud-init-network.service - Cloud-init: Network Stage. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 747s Aug 09 22:42:24 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). 747s Aug 09 22:42:24 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). 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started sysstat-collect.timer - Run system activity accounting tool every 10 minutes. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started sysstat-rotate.timer - Rotate daily system activity data file at midnight. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started sysstat-summary.timer - Generate summary of yesterday's process accounting. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 747s Aug 09 22:42:24 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). 747s Aug 09 22:42:24 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Reached target paths.target - Path Units. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 747s Aug 09 22:42:24 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 747s Aug 09 22:42:24 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). 747s Aug 09 22:42:24 autopkgtest systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). 747s Aug 09 22:42:24 autopkgtest systemd[1]: Reached target ssh-access.target - SSH Access Available. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Reached target basic.target - Basic System. 747s Aug 09 22:42:24 autopkgtest systemd[1]: System is tainted: unmerged-bin 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 747s Aug 09 22:42:24 autopkgtest (sh)[762]: autopkgtest@hvc1.service: Failed to set up standard input: No such device 747s Aug 09 22:42:24 autopkgtest (sh)[762]: autopkgtest@hvc1.service: Failed at step STDIN spawning /bin/sh: No such device 747s Aug 09 22:42:24 autopkgtest (sh)[763]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 747s Aug 09 22:42:24 autopkgtest (sh)[763]: autopkgtest@ttyS1.service: Failed at step STDIN spawning /bin/sh: Input/output error 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 747s Aug 09 22:42:24 autopkgtest (cron)[765]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 747s Aug 09 22:42:24 autopkgtest cron[765]: (CRON) INFO (pidfile fd = 3) 747s Aug 09 22:42:24 autopkgtest cron[765]: (CRON) INFO (Running @reboot jobs) 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 747s Aug 09 22:42:24 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). 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 747s Aug 09 22:42:24 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 747s Aug 09 22:42:24 autopkgtest systemd[1]: opal_errd.service - opal_errd (PowerNV platform error handling) Service was skipped because of an unmet condition check (ConditionVirtualization=false). 747s Aug 09 22:42:24 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). 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting sysstat.service - Resets System Activity Logs... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 747s Aug 09 22:42:24 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). 747s Aug 09 22:42:24 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 747s Aug 09 22:42:24 autopkgtest dbus-daemon[769]: [system] AppArmor D-Bus mediation is enabled 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 747s Aug 09 22:42:24 autopkgtest systemd[1]: autopkgtest@hvc1.service: Deactivated successfully. 747s Aug 09 22:42:24 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Finished sysstat.service - Resets System Activity Logs. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 747s Aug 09 22:42:24 autopkgtest udisksd[787]: udisks daemon version 2.10.1 starting 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 747s Aug 09 22:42:24 autopkgtest cloud-init[678]: Cloud-init v. 24.4~1gedd92b71-0ubuntu1 running 'modules:config' at Fri, 09 Aug 2024 22:42:24 +0000. Up 11.68 seconds. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 747s Aug 09 22:42:24 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 747s Aug 09 22:42:24 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 747s Aug 09 22:42:24 autopkgtest rngd[834]: rngd 2.4 starting up... 747s Aug 09 22:42:24 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 747s Aug 09 22:42:25 autopkgtest rngd[834]: entropy feed to the kernel ready 747s Aug 09 22:42:25 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 747s Aug 09 22:42:25 autopkgtest systemd-logind[782]: New seat seat0. 747s Aug 09 22:42:25 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 747s Aug 09 22:42:25 autopkgtest sh[768]: Completed socket interaction for boot stage config 747s Aug 09 22:42:25 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 747s Aug 09 22:42:25 autopkgtest systemd-logind[782]: Watching system buttons on /dev/input/event0 (QEMU QEMU USB Keyboard) 747s Aug 09 22:42:25 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 747s Aug 09 22:42:25 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 747s Aug 09 22:42:25 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 747s Aug 09 22:42:25 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 747s Aug 09 22:42:25 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 747s Aug 09 22:42:25 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 747s Aug 09 22:42:25 autopkgtest udisksd[787]: Acquired the name org.freedesktop.UDisks2 on the system message bus 747s Aug 09 22:42:25 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 747s Aug 09 22:42:25 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 747s Aug 09 22:42:25 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 747s Aug 09 22:42:25 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 747s Aug 09 22:42:25 autopkgtest kernel: kauditd_printk_skb: 108 callbacks suppressed 747s Aug 09 22:42:25 autopkgtest kernel: audit: type=1400 audit(1723243345.048:119): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=821 comm="apparmor_parser" 747s Aug 09 22:42:25 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 747s Aug 09 22:42:25 autopkgtest rsyslogd[867]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2406.0] 747s Aug 09 22:42:25 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 747s Aug 09 22:42:25 autopkgtest rsyslogd[867]: rsyslogd's groupid changed to 102 747s Aug 09 22:42:25 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 747s Aug 09 22:42:25 autopkgtest rsyslogd[867]: rsyslogd's userid changed to 102 747s Aug 09 22:42:25 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 747s Aug 09 22:42:25 autopkgtest rsyslogd[867]: [origin software="rsyslogd" swVersion="8.2406.0" x-pid="867" x-info="https://www.rsyslog.com"] start 747s Aug 09 22:42:25 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 747s Aug 09 22:42:25 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 747s Aug 09 22:42:25 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 747s Aug 09 22:42:25 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 747s Aug 09 22:42:25 autopkgtest cloud-init[678]: Cloud-init v. 24.4~1gedd92b71-0ubuntu1 running 'modules:final' at Fri, 09 Aug 2024 22:42:25 +0000. Up 12.03 seconds. 747s Aug 09 22:42:25 autopkgtest cloud-init[678]: Cloud-init v. 24.4~1gedd92b71-0ubuntu1 finished at Fri, 09 Aug 2024 22:42:25 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 12.10 seconds 747s Aug 09 22:42:25 autopkgtest sh[878]: Completed socket interaction for boot stage final 747s Aug 09 22:42:25 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 747s Aug 09 22:42:25 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 747s Aug 09 22:42:25 autopkgtest systemd[1]: Startup finished in 1.799s (kernel) + 10.311s (userspace) = 12.110s. 747s Aug 09 22:42:25 autopkgtest kernel: fbcon: Taking over console 747s Aug 09 22:42:25 autopkgtest kernel: Console: switching to colour frame buffer device 128x48 747s Aug 09 22:42:25 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 747s Aug 09 22:42:25 autopkgtest systemd[1]: cloud-init-main.service: Deactivated successfully. 747s Aug 09 22:42:25 autopkgtest systemd[1]: cloud-init-main.service: Unit process 677 (sh) remains running after unit stopped. 747s Aug 09 22:42:25 autopkgtest systemd[1]: cloud-init-main.service: Consumed 1.233s CPU time, 109.7M memory peak. 747s Aug 09 22:42:25 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 747s Aug 09 22:42:25 autopkgtest sshd[928]: Server listening on :: port 22. 747s Aug 09 22:42:25 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 747s Aug 09 22:42:26 autopkgtest sshd[930]: Accepted publickey for ubuntu from 10.136.6.201 port 52820 ssh2: RSA SHA256:YaYyKWTl9zFJEBK5G3u+MRj3WPJt+vEplFd0J96PUBw 747s Aug 09 22:42:26 autopkgtest sshd[930]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 747s Aug 09 22:42:26 autopkgtest sshd[930]: pam_systemd(sshd:session): New sd-bus connection (system-bus-pam-systemd-930) opened. 747s Aug 09 22:42:26 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 747s Aug 09 22:42:26 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 747s Aug 09 22:42:26 autopkgtest systemd-logind[782]: New session 1 of user ubuntu. 747s Aug 09 22:42:26 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 747s Aug 09 22:42:26 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 747s Aug 09 22:42:26 autopkgtest (systemd)[934]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 747s Aug 09 22:42:26 autopkgtest systemd-logind[782]: New session 2 of user ubuntu. 747s Aug 09 22:42:26 autopkgtest systemd[934]: Queued start job for default target default.target. 747s Aug 09 22:42:26 autopkgtest systemd[934]: Created slice app.slice - User Application Slice. 747s Aug 09 22:42:26 autopkgtest systemd[934]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 747s Aug 09 22:42:26 autopkgtest systemd[934]: Reached target paths.target - Paths. 747s Aug 09 22:42:26 autopkgtest systemd[934]: Reached target timers.target - Timers. 747s Aug 09 22:42:26 autopkgtest systemd[934]: Starting dbus.socket - D-Bus User Message Bus Socket... 747s Aug 09 22:42:26 autopkgtest systemd[934]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 747s Aug 09 22:42:26 autopkgtest systemd[934]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 747s Aug 09 22:42:26 autopkgtest systemd[934]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 747s Aug 09 22:42:26 autopkgtest systemd[934]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 747s Aug 09 22:42:26 autopkgtest systemd[934]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 747s Aug 09 22:42:26 autopkgtest systemd[934]: Listening on keyboxd.socket - GnuPG public key management service. 747s Aug 09 22:42:26 autopkgtest systemd[934]: Listening on dbus.socket - D-Bus User Message Bus Socket. 747s Aug 09 22:42:26 autopkgtest systemd[934]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 747s Aug 09 22:42:26 autopkgtest systemd[934]: Reached target sockets.target - Sockets. 747s Aug 09 22:42:26 autopkgtest systemd[934]: Reached target basic.target - Basic System. 747s Aug 09 22:42:26 autopkgtest systemd[934]: Reached target default.target - Main User Target. 747s Aug 09 22:42:26 autopkgtest systemd[934]: Startup finished in 151ms. 747s Aug 09 22:42:26 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 747s Aug 09 22:42:26 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 747s Aug 09 22:42:32 autopkgtest sudo[962]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 747s Aug 09 22:42:32 autopkgtest sudo[962]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:32 autopkgtest sudo[962]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:33 autopkgtest sudo[967]: 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' 747s Aug 09 22:42:33 autopkgtest sudo[967]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:33 autopkgtest sudo[967]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:39 autopkgtest sudo[979]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.EXlFK5 747s Aug 09 22:42:39 autopkgtest sudo[979]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:39 autopkgtest sudo[979]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:42 autopkgtest sudo[989]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.EXlFK5/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.EXlFK5/autopkgtest-reboot' 747s Aug 09 22:42:42 autopkgtest sudo[989]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:42 autopkgtest sudo[989]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:43 autopkgtest sudo[1001]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.EXlFK5/autopkgtest-reboot 747s Aug 09 22:42:43 autopkgtest sudo[1001]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:43 autopkgtest sudo[1001]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:44 autopkgtest sudo[1011]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.EXlFK5/autopkgtest-reboot /tmp/autopkgtest-reboot 747s Aug 09 22:42:44 autopkgtest sudo[1011]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:44 autopkgtest sudo[1011]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:47 autopkgtest sudo[1021]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.EXlFK5/autopkgtest-reboot /sbin/autopkgtest-reboot 747s Aug 09 22:42:47 autopkgtest sudo[1021]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:47 autopkgtest sudo[1021]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:47 autopkgtest sudo[1031]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.EXlFK5 747s Aug 09 22:42:47 autopkgtest sudo[1031]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:48 autopkgtest sudo[1031]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:48 autopkgtest sudo[1041]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.EXlFK5/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.EXlFK5/autopkgtest-reboot-prepare' 747s Aug 09 22:42:48 autopkgtest sudo[1041]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:48 autopkgtest sudo[1041]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:48 autopkgtest sudo[1053]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.EXlFK5/autopkgtest-reboot-prepare 747s Aug 09 22:42:48 autopkgtest sudo[1053]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:48 autopkgtest sudo[1053]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:49 autopkgtest sudo[1063]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.EXlFK5/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 747s Aug 09 22:42:49 autopkgtest sudo[1063]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:49 autopkgtest sudo[1063]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:50 autopkgtest sudo[1073]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 747s Aug 09 22:42:50 autopkgtest sudo[1073]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:50 autopkgtest sudo[1073]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:51 autopkgtest sudo[1083]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 747s Aug 09 22:42:51 autopkgtest sudo[1083]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:51 autopkgtest sudo[1083]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:51 autopkgtest sudo[1093]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.EXlFK5/testbed-packages' 747s Aug 09 22:42:51 autopkgtest sudo[1093]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:51 autopkgtest sudo[1093]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:51 autopkgtest sudo[1104]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.EXlFK5/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.EXlFK5/autopkgtest-reboot' 747s Aug 09 22:42:52 autopkgtest sudo[1125]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:53 autopkgtest sudo[1125]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:53 autopkgtest sudo[1137]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.EXlFK5/autopkgtest-reboot 747s Aug 09 22:42:53 autopkgtest sudo[1137]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:53 autopkgtest sudo[1137]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:53 autopkgtest sudo[1147]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.EXlFK5/autopkgtest-reboot /tmp/autopkgtest-reboot 747s Aug 09 22:42:53 autopkgtest sudo[1147]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:53 autopkgtest sudo[1147]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:54 autopkgtest sudo[1157]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.EXlFK5/autopkgtest-reboot /sbin/autopkgtest-reboot 747s Aug 09 22:42:54 autopkgtest sudo[1157]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:54 autopkgtest sudo[1157]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:54 autopkgtest sudo[1167]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.EXlFK5 747s Aug 09 22:42:54 autopkgtest sudo[1167]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:54 autopkgtest sudo[1167]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:54 autopkgtest systemd-timesyncd[400]: Contacted time server 185.125.190.56:123 (ntp.ubuntu.com). 747s Aug 09 22:42:54 autopkgtest systemd-timesyncd[400]: Initial clock synchronization to Fri 2024-08-09 22:42:54.675578 UTC. 747s Aug 09 22:42:55 autopkgtest sudo[1177]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.EXlFK5/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.EXlFK5/autopkgtest-reboot-prepare' 747s Aug 09 22:42:55 autopkgtest sudo[1177]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:55 autopkgtest sudo[1177]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:55 autopkgtest sudo[1189]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.EXlFK5/autopkgtest-reboot-prepare 747s Aug 09 22:42:55 autopkgtest sudo[1189]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:55 autopkgtest sudo[1189]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:56 autopkgtest sudo[1199]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.EXlFK5/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 747s Aug 09 22:42:56 autopkgtest sudo[1199]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:56 autopkgtest sudo[1199]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:56 autopkgtest sudo[1209]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 747s Aug 09 22:42:56 autopkgtest sudo[1209]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:56 autopkgtest sudo[1209]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:42:59 autopkgtest sudo[1219]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 747s Aug 09 22:42:59 autopkgtest sudo[1219]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:42:59 autopkgtest sudo[1219]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:43:03 autopkgtest sudo[1228]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.EXlFK5 747s Aug 09 22:43:03 autopkgtest sudo[1228]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:43:03 autopkgtest sudo[1228]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:43:04 autopkgtest sudo[1238]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.EXlFK5/2-autopkgtest-satdep.deb' 747s Aug 09 22:43:04 autopkgtest sudo[1238]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:43:05 autopkgtest sudo[1238]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:43:05 autopkgtest sudo[1249]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.EXlFK5/2-autopkgtest-satdep.deb 747s Aug 09 22:43:05 autopkgtest sudo[1249]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:43:05 autopkgtest sudo[1249]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:43:05 autopkgtest sudo[1259]: 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.EXlFK5/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' 747s Aug 09 22:43:05 autopkgtest sudo[1259]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:43:09 autopkgtest systemd[1]: Reload requested from client PID 1499 ('systemctl') (unit session-1.scope)... 747s Aug 09 22:43:09 autopkgtest systemd[1]: Reloading... 747s Aug 09 22:43: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. 747s Aug 09 22:43: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. 747s Aug 09 22:43:09 autopkgtest systemd[1]: Reloading finished in 217 ms. 747s Aug 09 22:43:09 autopkgtest systemd[1]: Reload requested from client PID 1549 ('systemctl') (unit session-1.scope)... 747s Aug 09 22:43:09 autopkgtest systemd[1]: Reloading... 747s Aug 09 22:43: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. 747s Aug 09 22:43: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. 747s Aug 09 22:43:09 autopkgtest systemd[1]: Reloading finished in 197 ms. 747s Aug 09 22:43:09 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 747s Aug 09 22:43:10 autopkgtest tgtd[1594]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 747s Aug 09 22:43:10 autopkgtest tgtd[1594]: tgtd: work_timer_start(146) use timer_fd based scheduler 747s Aug 09 22:43:10 autopkgtest tgtd[1594]: tgtd: bs_init(387) use signalfd notification 747s Aug 09 22:43:10 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 747s Aug 09 22:43:10 autopkgtest systemd[1]: Reload requested from client PID 1622 ('systemctl') (unit session-1.scope)... 747s Aug 09 22:43:10 autopkgtest systemd[1]: Reloading... 747s Aug 09 22:43: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. 747s Aug 09 22:43: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. 747s Aug 09 22:43:10 autopkgtest systemd[1]: Reloading finished in 202 ms. 747s Aug 09 22:43:10 autopkgtest systemd[1]: Reload requested from client PID 1664 ('systemctl') (unit session-1.scope)... 747s Aug 09 22:43:10 autopkgtest systemd[1]: Reloading... 747s Aug 09 22:43: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. 747s Aug 09 22:43: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. 747s Aug 09 22:43:10 autopkgtest systemd[1]: Reloading finished in 227 ms. 747s Aug 09 22:43:10 autopkgtest systemd[1]: Reload requested from client PID 1710 ('systemctl') (unit session-1.scope)... 747s Aug 09 22:43:10 autopkgtest systemd[1]: Reloading... 747s Aug 09 22:43: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. 747s Aug 09 22:43: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. 747s Aug 09 22:43:11 autopkgtest systemd[1]: Reloading finished in 226 ms. 747s Aug 09 22:43:11 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 747s Aug 09 22:43:11 autopkgtest systemd[1]: Reload requested from client PID 1760 ('systemctl') (unit session-1.scope)... 747s Aug 09 22:43:11 autopkgtest systemd[1]: Reloading... 747s Aug 09 22:43: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. 747s Aug 09 22:43: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. 747s Aug 09 22:43:11 autopkgtest systemd[1]: Reloading finished in 206 ms. 747s Aug 09 22:43:11 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 747s Aug 09 22:43:11 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 747s Aug 09 22:43:11 autopkgtest systemd[1]: Reload requested from client PID 1814 ('systemctl') (unit session-1.scope)... 747s Aug 09 22:43:11 autopkgtest systemd[1]: Reloading... 747s Aug 09 22:43: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. 747s Aug 09 22:43: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. 747s Aug 09 22:43:12 autopkgtest systemd[1]: Reloading finished in 226 ms. 747s Aug 09 22:43:22 autopkgtest sudo[1259]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:43:22 autopkgtest sudo[5257]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 747s Aug 09 22:43:22 autopkgtest sudo[5257]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:43:22 autopkgtest sudo[5257]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:43:22 autopkgtest sudo[5267]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 747s Aug 09 22:43:22 autopkgtest sudo[5267]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:43:22 autopkgtest sudo[5267]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:43:23 autopkgtest sudo[5277]: 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 747s Aug 09 22:43:23 autopkgtest sudo[5277]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:43:24 autopkgtest sudo[5277]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:43:24 autopkgtest sudo[5290]: 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 747s Aug 09 22:43:24 autopkgtest sudo[5290]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:43:25 autopkgtest sudo[5290]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:43:25 autopkgtest sudo[5302]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 747s Aug 09 22:43:25 autopkgtest sudo[5302]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:43:25 autopkgtest sudo[5302]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:43:25 autopkgtest sudo[5314]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 747s Aug 09 22:43:25 autopkgtest sudo[5314]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:43:25 autopkgtest sudo[5314]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:43:26 autopkgtest sudo[5324]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.EXlFK5/tgtbasedmpaths-packages.all' 747s Aug 09 22:43:26 autopkgtest sudo[5324]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 747s Aug 09 22:43:26 autopkgtest sudo[5324]: pam_unix(sudo:session): session closed for user root 747s Aug 09 22:43:26 autopkgtest sudo[5335]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 751s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 751s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 751s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 751s latency : target=0, window=0, percentile=100.00%, depth=1 751s 751s Run status group 0 (all jobs): 751s WRITE: bw=160MiB/s (168MB/s), 160MiB/s-160MiB/s (168MB/s-168MB/s), io=87.5MiB (91.8MB), run=546-546msec 751s 751s Disk stats (read/write): 751s dm-0: ios=1/1027, sectors=8/131456, merge=0/0, ticks=0/377, in_queue=377, util=80.82%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/119, aggrin_queue=119, aggrutil=83.01% 751s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 751s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 751s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 751s sda: ios=1/1402, sectors=8/179280, merge=0/0, ticks=0/478, in_queue=478, util=83.01% 751s + echo Starting the path changes in background 751s + date +Pre FIO %H:%M:%S.%N 751s Starting the path changes in background 751s Pre FIO 22:43:39.105563415 751s + fio --max-jobs=4 /tmp/autopkgtest.EXlFK5/tgtbasedmpaths-artifacts/path-change-check.fio 751s 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 751s fio-3.37 751s Starting 1 thread 931s 931s verify-phase: (groupid=0, jobs=1): err= 0: pid=5703: Fri Aug 9 22:46:39 2024 931s read: IOPS=5132, BW=321MiB/s (336MB/s)(56.4GiB/180001msec) 931s clat (usec): min=82, max=53069, avg=171.15, stdev=133.71 931s lat (usec): min=82, max=53069, avg=171.26, stdev=133.72 931s clat percentiles (usec): 931s | 1.00th=[ 102], 5.00th=[ 117], 10.00th=[ 124], 20.00th=[ 135], 931s | 30.00th=[ 145], 40.00th=[ 153], 50.00th=[ 159], 60.00th=[ 169], 931s | 70.00th=[ 180], 80.00th=[ 196], 90.00th=[ 221], 95.00th=[ 243], 931s | 99.00th=[ 322], 99.50th=[ 635], 99.90th=[ 1057], 99.95th=[ 1631], 931s | 99.99th=[ 2442] 931s bw ( KiB/s): min=143872, max=467200, per=100.00%, avg=329183.74, stdev=46621.32, samples=359 931s iops : min= 2248, max= 7300, avg=5143.43, stdev=728.47, samples=359 931s lat (usec) : 100=0.72%, 250=95.38%, 500=3.32%, 750=0.20%, 1000=0.26% 931s lat (msec) : 2=0.10%, 4=0.02%, 10=0.01%, 20=0.01%, 50=0.01% 931s lat (msec) : 100=0.01% 931s cpu : usr=13.28%, sys=7.33%, ctx=923970, majf=0, minf=1 931s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 931s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 931s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 931s issued rwts: total=923795,0,0,0 short=0,0,0,0 dropped=0,0,0,0 931s latency : target=0, window=0, percentile=100.00%, depth=1 931s 931s Run status group 0 (all jobs): 931s READ: bw=321MiB/s (336MB/s), 321MiB/s-321MiB/s (336MB/s-336MB/s), io=56.4GiB (60.5GB), run=180001-180001msec 931s 931s Disk stats (read/write): 931s dm-0: ios=924147/10, sectors=118204728/12928, merge=21/9, ticks=157515/98, in_queue=157668, util=100.00%, aggrios=63746/2, aggsectors=8153230/3232, aggrmerge=0/0, aggrticks=9892/10, aggrin_queue=9902, aggrutil=99.14% 931s sdd: ios=103350/0, sectors=13219328/0, merge=0/0, ticks=15753/0, in_queue=15753, util=39.67% 931s sdb: ios=52347/0, sectors=6693944/0, merge=0/0, ticks=7975/0, in_queue=7974, util=50.07% 931s sdc: ios=49803/0, sectors=6370176/0, merge=0/0, ticks=8083/0, in_queue=8083, util=33.44% 931s sda: ios=49486/9, sectors=6329472/12928, merge=0/0, ticks=7758/42, in_queue=7801, util=99.14% 931s + date +Post FIO %H:%M:%S.%N 931s Post FIO 22:46:39.450637207 931s FIO verify test with changing paths - OK 931s Report log of background activity 931s + echo FIO verify test with changing paths - OK 931s + echo Report log of background activity 931s + cat /tmp/autopkgtest.EXlFK5/tgtbasedmpaths-artifacts/test-background.log 931s + iscsiadm --mode session 931s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s + sleep 10s 931s + date +MP report (expect 4) %H:%M:%S.%N 931s MP report (expect 4) 22:43:49.114587611 931s + multipath -ll 931s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 931s size=100M features='0' hwhandler='0' wp=rw 931s |-+- policy='service-time 0' prio=1 status=active 931s | `- 0:0:0:1 sda 8:0 active ready running 931s |-+- policy='service-time 0' prio=1 status=enabled 931s | `- 1:0:0:1 sdb 8:16 active ready running 931s |-+- policy='service-time 0' prio=1 status=enabled 931s | `- 2:0:0:1 sdc 8:32 active ready running 931s `-+- policy='service-time 0' prio=1 status=enabled 931s `- 3:0:0:1 sdd 8:48 active ready running 931s + date +UN-plug path 1 %H:%M:%S.%N 931s UN-plug path 1 22:43:49.138287632 931s + iscsiadm --mode session -r 1 -u 931s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 931s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 931s + iscsiadm --mode session 931s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s + sleep 10s 931s + date +MP report (expect 3) %H:%M:%S.%N 931s MP report (expect 3) 22:43:59.255768937 931s + multipath -ll 931s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 931s size=100M features='0' hwhandler='0' wp=rw 931s |-+- policy='service-time 0' prio=1 status=active 931s | `- 1:0:0:1 sdb 8:16 active ready running 931s |-+- policy='service-time 0' prio=1 status=enabled 931s | `- 2:0:0:1 sdc 8:32 active ready running 931s `-+- policy='service-time 0' prio=1 status=enabled 931s `- 3:0:0:1 sdd 8:48 active ready running 931s + date +UN-plug path 2 %H:%M:%S.%N 931s UN-plug path 2 22:43:59.283536989 931s + iscsiadm --mode session -r 2 -u 931s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 931s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 931s + iscsiadm --mode session 931s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s + sleep 10s 931s + date +MP report (expect 2) %H:%M:%S.%N 931s MP report (expect 2) 22:44:09.402350891 931s + multipath -ll 931s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 931s size=100M features='0' hwhandler='0' wp=rw 931s |-+- policy='service-time 0' prio=1 status=active 931s | `- 2:0:0:1 sdc 8:32 active ready running 931s `-+- policy='service-time 0' prio=1 status=enabled 931s `- 3:0:0:1 sdd 8:48 active ready running 931s + date +UN-plug path 3 %H:%M:%S.%N 931s UN-plug path 3 22:44:09.419846359 931s + iscsiadm --mode session -r 3 -u 931s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 931s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 931s + iscsiadm --mode session 931s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s + sleep 10s 931s + date +MP report (expect 1) %H:%M:%S.%N 931s MP report (expect 1) 22:44:19.519699825 931s + multipath -ll 931s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 931s size=100M features='0' hwhandler='0' wp=rw 931s `-+- policy='service-time 0' prio=1 status=active 931s `- 3:0:0:1 sdd 8:48 active ready running 931s + date +Add paths 5/6/7/8 %H:%M:%S.%N 931s Add paths 5/6/7/8 22:44:19.534444118 931s + iscsiadm --mode session -r 4 --op new 931s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 931s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 931s + iscsiadm --mode session -r 4 --op new 931s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 931s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 931s + iscsiadm --mode session -r 4 --op new 931s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 931s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 931s + iscsiadm --mode session -r 4 --op new 931s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 931s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 931s + iscsiadm --mode session 931s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s + sleep 10s 931s + date +MP report (expect 5) %H:%M:%S.%N 931s MP report (expect 5) 22:44:29.629543209 931s + multipath -ll 931s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 931s size=100M features='0' hwhandler='0' wp=rw 931s |-+- policy='service-time 0' prio=1 status=active 931s | `- 3:0:0:1 sdd 8:48 active ready running 931s |-+- policy='service-time 0' prio=1 status=enabled 931s | `- 0:0:0:1 sda 8:0 active ready running 931s |-+- policy='service-time 0' prio=1 status=enabled 931s | `- 1:0:0:1 sdb 8:16 active ready running 931s |-+- policy='service-time 0' prio=1 status=enabled 931s | `- 4:0:0:1 sde 8:64 active ready running 931s `-+- policy='service-time 0' prio=1 status=enabled 931s `- 2:0:0:1 sdc 8:32 active ready running 931s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 931s UN-plug multiple paths 4/7/8 22:44:29.656569363 931s + iscsiadm --mode session -r 4 -u 931s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 931s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 931s + iscsiadm --mode session -r 7 -u 931s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 931s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 931s + iscsiadm --mode session -r 8 -u 931s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 931s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 931s + iscsiadm --mode session 931s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 931s + sleep 10s 931s + date +Restart multipath daemon %H:%M:%S.%N 931s Restart multipath daemon 22:44:39.948926782 931s + systemctl restart multipathd 931s + sleep 10s 931s + date +Final background report (expect 2) %H:%M:%S.%N 931s Final background report (expect 2) 22:44:50.041027670 931s + multipath -ll 931s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 931s size=100M features='0' hwhandler='0' wp=rw 931s |-+- policy='service-time 0' prio=1 status=active 931s | `- 0:0:0:1 sda 8:0 active ready running 931s `-+- policy='service-time 0' prio=1 status=enabled 931s `- 1:0:0:1 sdb 8:16 active ready running 931s Final stats 931s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 931s iSCSI SNMP: 931s txdata_octets: 32020728 931s rxdata_octets: 43696352612 931s noptx_pdus: 0 931s scsicmd_pdus: 666831 931s tmfcmd_pdus: 0 931s login_pdus: 0 931s text_pdus: 0 931s dataout_pdus: 0 931s logout_pdus: 0 931s snack_pdus: 0 931s noprx_pdus: 0 931s scsirsp_pdus: 666831 931s tmfrsp_pdus: 0 931s textrsp_pdus: 0 931s datain_pdus: 666798 931s logoutrsp_pdus: 0 931s r2t_pdus: 0 931s async_pdus: 0 931s rjt_pdus: 0 931s digest_err: 0 931s timeout_err: 0 931s iSCSI Extended: 931s tx_sendpage_failures: 0 931s rx_discontiguous_hdr: 0 931s eh_abort_cnt: 0 931s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 931s iSCSI SNMP: 931s txdata_octets: 6456 931s rxdata_octets: 1514916 931s noptx_pdus: 0 931s scsicmd_pdus: 105 931s tmfcmd_pdus: 0 931s login_pdus: 0 931s text_pdus: 0 931s dataout_pdus: 0 931s logout_pdus: 0 931s snack_pdus: 0 931s noprx_pdus: 0 931s scsirsp_pdus: 105 931s tmfrsp_pdus: 0 931s textrsp_pdus: 0 931s datain_pdus: 83 931s logoutrsp_pdus: 0 931s r2t_pdus: 0 931s async_pdus: 0 931s rjt_pdus: 0 931s digest_err: 0 931s timeout_err: 0 931s iSCSI Extended: 931s tx_sendpage_failures: 0 931s rx_discontiguous_hdr: 0 931s eh_abort_cnt: 0 931s + sync 931s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 931s + echo Final stats 931s + iscsiadm --mode session --stats 931s + journalctl --no-pager -u multipathd 931s Aug 09 11:03:39 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 931s Aug 09 11:03:39 ubuntu multipathd[365]: multipathd v0.9.4: start up 931s Aug 09 11:03:39 ubuntu multipathd[365]: reconfigure: setting up paths and maps 931s Aug 09 11:03:39 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 931s Aug 09 11:05:59 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[365]: multipathd: shut down 931s Aug 09 11:05:59 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 931s Aug 09 11:05:59 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 931s Aug 09 11:05:59 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 931s Aug 09 11:05:59 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 931s Aug 09 11:05:59 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[11829]: multipathd v0.9.4: start up 931s Aug 09 11:05:59 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[11829]: reconfigure: setting up paths and maps 931s Aug 09 11:05:59 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 931s Aug 09 11:10:30 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[11829]: multipathd: shut down 931s Aug 09 11:10:30 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 931s Aug 09 11:10:30 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 931s Aug 09 11:10:30 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 931s -- Boot 628da71b604a49fd9203bdc9250e65ff -- 931s Aug 09 11:10:43 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 931s Aug 09 11:10:43 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 931s Aug 09 11:10:43 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[304]: multipathd v0.9.9: start up 931s Aug 09 11:10:43 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[304]: reconfigure: setting up paths and maps 931s Aug 09 11:11:08 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 931s Aug 09 11:11:08 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[304]: multipathd: shut down 931s Aug 09 11:11:08 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 931s Aug 09 11:11:08 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 931s -- Boot b7e94ce9605648cbaac7e9487e8a8d0f -- 931s Aug 09 22:39:55 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[312]: multipathd v0.9.9: start up 931s Aug 09 22:39:55 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[312]: reconfigure: setting up paths and maps 931s Aug 09 22:39:55 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 931s Aug 09 22:42:03 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 931s Aug 09 22:42:03 autopkgtest multipathd[312]: multipathd: shut down 931s Aug 09 22:42:03 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 931s Aug 09 22:42:03 auto+ echo Check final path status 931s + multipath -ll 931s + multipath -ll 931s + grep --count status= 931s pkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 931s -- Boot 45a0eb18fe644516a481e16e3737e66c -- 931s Aug 09 22:42:15 autopkgtest multipathd[309]: multipathd v0.9.9: start up 931s Aug 09 22:42:15 autopkgtest multipathd[309]: reconfigure: setting up paths and maps 931s Aug 09 22:42:15 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 931s Aug 09 22:43:29 autopkgtest multipathd[309]: updated bindings file /etc/multipath/bindings 931s Aug 09 22:43:29 autopkgtest multipathd[309]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 931s Aug 09 22:43:30 autopkgtest multipathd[309]: sda [8:0]: path added to devmap mpatha 931s Aug 09 22:43:30 autopkgtest multipathd[309]: mpatha: performing delayed actions 931s Aug 09 22:43:30 autopkgtest multipathd[309]: 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] 931s Aug 09 22:43:49 autopkgtest multipathd[309]: 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] 931s Aug 09 22:43:49 autopkgtest multipathd[309]: check_removed_paths: sda: freeing path in removed state 931s Aug 09 22:43:49 autopkgtest multipathd[309]: 8:0: path removed from map mpatha 931s Aug 09 22:43:59 autopkgtest multipathd[309]: 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] 931s Aug 09 22:43:59 autopkgtest multipathd[309]: check_removed_paths: sdb: freeing path in removed state 931s Aug 09 22:43:59 autopkgtest multipathd[309]: 8:16: path removed from map mpatha 931s Aug 09 22:44:09 autopkgtest multipathd[309]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 931s Aug 09 22:44:09 autopkgtest multipathd[309]: check_removed_paths: sdc: freeing path in removed state 931s Aug 09 22:44:09 autopkgtest multipathd[309]: 8:32: path removed from map mpatha 931s Aug 09 22:44:19 autopkgtest multipathd[309]: 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] 931s Aug 09 22:44:19 autopkgtest multipathd[309]: sda [8:0]: path added to devmap mpatha 931s Aug 09 22:44:19 autopkgtest multipathd[309]: 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] 931s Aug 09 22:44:19 autopkgtest multipathd[309]: sdb [8:16]: path added to devmap mpatha 931s Aug 09 22:44:19 autopkgtest multipathd[309]: 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:64 1] 931s Aug 09 22:44:19 autopkgtest multipathd[309]: sde [8:64]: path added to devmap mpatha 931s Aug 09 22:44:19 autopkgtest multipathd[309]: 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:64 1 service-time 0 1 1 8:32 1] 931s Aug 09 22:44:19 autopkgtest multipathd[309]: sdc [8:32]: path added to devmap mpatha 931s Aug 09 22:44:29 autopkgtest multipathd[309]: 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:64 1 service-time 0 1 1 8:32 1] 931s Aug 09 22:44:29 autopkgtest multipathd[309]: check_removed_paths: sdd: freeing path in removed state 931s Aug 09 22:44:29 autopkgtest multipathd[309]: 8:48: path removed from map mpatha 931s Aug 09 22:44:29 autopkgtest multipathd[309]: 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] 931s Aug 09 22:44:29 autopkgtest multipathd[309]: check_removed_paths: sdc: freeing path in removed state 931s Aug 09 22:44:29 autopkgtest multipathd[309]: 8:32: path removed from map mpatha 931s Aug 09 22:44:29 autopkgtest multipathd[309]: 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] 931s Aug 09 22:44:29 autopkgtest multipathd[309]: check_removed_paths: sde: freeing path in removed state 931s Aug 09 22:44:29 autopkgtest multipathd[309]: 8:64: path removed from map mpatha 931s Aug 09 22:44:39 autopkgtest multipathd[309]: multipathd: shut down 931s Aug 09 22:44:39 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 931s Aug 09 22:44:39 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 931s Aug 09 22:44:39 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 931s Aug 09 22:44:40 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 931s Aug 09 22:44:40 autopkgtest multipathd[6083]: multipathd v0.9.9: start up 931s Aug 09 22:44:40 autopkgtest multipathd[6083]: reconfigure: setting up paths and maps 931s Aug 09 22:44:40 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 931s Check final path status 931s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 931s size=100M features='0' hwhandler='0' wp=rw 931s |-+- policy='service-time 0' prio=1 status=active 931s | `- 0:0:0:1 sda 8:0 active ready running 931s `-+- policy='service-time 0' prio=1 status=enabled 931s `- 1:0:0:1 sdb 8:16 active ready running 931s + diskc=2 931s + multipath -ll 931s + grep --count status=active 931s + diska=1 931s + multipath -ll 931s + grep --count status=enabled 931s + diske=1 931s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 931s + echo OK 931s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 931s OK 931s + Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 931s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 931s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 931s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 931s tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 932s autopkgtest [22:46:40]: test tgtbasedmpaths: -----------------------] 936s autopkgtest [22:46:44]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 936s tgtbasedmpaths PASS 937s autopkgtest [22:46:45]: @@@@@@@@@@@@@@@@@@@@ summary 937s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 937s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 937s kpartx-file-loopback PASS 937s tgtbasedmpaths PASS 979s nova [W] Using flock in prodstack6-ppc64el 979s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240809-223106-juju-7f2275-prod-proposed-migration-environment-3-872a2d39-da14-4b2c-8f79-7f86d296884e from image adt/ubuntu-oracular-ppc64el-server-20240809.img (UUID a8acd20b-0f2e-49f1-9c39-4d071949e087)... 979s nova [W] Using flock in prodstack6-ppc64el 979s flock: timeout while waiting to get lock 979s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240809-223106-juju-7f2275-prod-proposed-migration-environment-3-872a2d39-da14-4b2c-8f79-7f86d296884e from image adt/ubuntu-oracular-ppc64el-server-20240809.img (UUID a8acd20b-0f2e-49f1-9c39-4d071949e087)...