0s autopkgtest [23:25:18]: starting date and time: 2024-07-30 23:25:18+0000 0s autopkgtest [23:25:18]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [23:25:18]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.lifbne1a/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:systemd,src:debootstrap,src:dpdk,src:nftables,src:openssh --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=systemd/256.4-2ubuntu1 debootstrap/1.0.137ubuntu2 dpdk/23.11.1-2 nftables/1.1.0-2 openssh/1:9.7p1-7ubuntu1' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big-ppc64el --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos03-ppc64el-4.secgroup --name adt-oracular-ppc64el-multipath-tools-20240730-232518-juju-7f2275-prod-proposed-migration-environment-3-d254f06f-2231-40ff-93c4-56ca5f003403 --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/ 149s autopkgtest [23:27:47]: testbed dpkg architecture: ppc64el 149s autopkgtest [23:27:47]: testbed apt version: 2.9.6 149s autopkgtest [23:27:47]: @@@@@@@@@@@@@@@@@@@@ test bed setup 150s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 150s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 150s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [6372 B] 150s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.0 kB] 151s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [509 kB] 151s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [82.0 kB] 151s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2116 B] 151s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 151s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 151s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [477 kB] 152s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [8952 B] 152s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [3728 B] 152s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 155s Fetched 1277 kB in 3s (493 kB/s) 155s Reading package lists... 157s Reading package lists... 157s Building dependency tree... 157s Reading state information... 158s Calculating upgrade... 158s The following NEW packages will be installed: 158s systemd-cryptsetup 158s The following packages will be upgraded: 158s libnftables1 libnss-systemd libpam-systemd libsystemd-shared libsystemd0 158s libudev1 nftables openssh-client openssh-server openssh-sftp-server systemd 158s systemd-dev systemd-resolved systemd-sysv systemd-timesyncd udev 158s 16 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 158s Need to get 12.7 MB of archives. 158s After this operation, 96.3 kB disk space will be freed. 158s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-dev all 256.4-2ubuntu1 [113 kB] 158s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd ppc64el 256.4-2ubuntu1 [3740 kB] 164s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-timesyncd ppc64el 256.4-2ubuntu1 [42.4 kB] 164s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-resolved ppc64el 256.4-2ubuntu1 [370 kB] 165s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd-shared ppc64el 256.4-2ubuntu1 [2490 kB] 169s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd0 ppc64el 256.4-2ubuntu1 [564 kB] 170s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-sysv ppc64el 256.4-2ubuntu1 [11.9 kB] 170s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnss-systemd ppc64el 256.4-2ubuntu1 [215 kB] 170s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpam-systemd ppc64el 256.4-2ubuntu1 [326 kB] 171s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el udev ppc64el 256.4-2ubuntu1 [2141 kB] 174s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libudev1 ppc64el 256.4-2ubuntu1 [223 kB] 174s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el openssh-sftp-server ppc64el 1:9.7p1-7ubuntu1 [43.2 kB] 175s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el openssh-server ppc64el 1:9.7p1-7ubuntu1 [621 kB] 176s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el openssh-client ppc64el 1:9.7p1-7ubuntu1 [1102 kB] 177s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el nftables ppc64el 1.1.0-2 [70.9 kB] 177s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnftables1 ppc64el 1.1.0-2 [451 kB] 178s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-cryptsetup ppc64el 256.4-2ubuntu1 [127 kB] 179s Preconfiguring packages ... 179s Fetched 12.7 MB in 21s (616 kB/s) 179s (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 ... 72513 files and directories currently installed.) 179s Preparing to unpack .../0-systemd-dev_256.4-2ubuntu1_all.deb ... 179s Unpacking systemd-dev (256.4-2ubuntu1) over (256-1ubuntu1) ... 179s Preparing to unpack .../1-systemd_256.4-2ubuntu1_ppc64el.deb ... 179s Unpacking systemd (256.4-2ubuntu1) over (256-1ubuntu1) ... 179s Preparing to unpack .../2-systemd-timesyncd_256.4-2ubuntu1_ppc64el.deb ... 179s Unpacking systemd-timesyncd (256.4-2ubuntu1) over (256-1ubuntu1) ... 179s Preparing to unpack .../3-systemd-resolved_256.4-2ubuntu1_ppc64el.deb ... 179s Unpacking systemd-resolved (256.4-2ubuntu1) over (256-1ubuntu1) ... 179s Preparing to unpack .../4-libsystemd-shared_256.4-2ubuntu1_ppc64el.deb ... 179s Unpacking libsystemd-shared:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 179s Preparing to unpack .../5-libsystemd0_256.4-2ubuntu1_ppc64el.deb ... 179s Unpacking libsystemd0:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 179s Setting up libsystemd0:ppc64el (256.4-2ubuntu1) ... 179s Setting up libsystemd-shared:ppc64el (256.4-2ubuntu1) ... 179s Setting up systemd (256.4-2ubuntu1) ... 179s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 179s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 180s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 180s (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 ... 72438 files and directories currently installed.) 180s Preparing to unpack .../systemd-sysv_256.4-2ubuntu1_ppc64el.deb ... 180s Unpacking systemd-sysv (256.4-2ubuntu1) over (256-1ubuntu1) ... 180s Preparing to unpack .../libnss-systemd_256.4-2ubuntu1_ppc64el.deb ... 180s Unpacking libnss-systemd:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 180s Preparing to unpack .../libpam-systemd_256.4-2ubuntu1_ppc64el.deb ... 181s Unpacking libpam-systemd:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 181s Preparing to unpack .../udev_256.4-2ubuntu1_ppc64el.deb ... 181s Unpacking udev (256.4-2ubuntu1) over (256-1ubuntu1) ... 181s Preparing to unpack .../libudev1_256.4-2ubuntu1_ppc64el.deb ... 181s Unpacking libudev1:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 181s Setting up libudev1:ppc64el (256.4-2ubuntu1) ... 181s (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 ... 72439 files and directories currently installed.) 181s Preparing to unpack .../0-openssh-sftp-server_1%3a9.7p1-7ubuntu1_ppc64el.deb ... 181s Unpacking openssh-sftp-server (1:9.7p1-7ubuntu1) over (1:9.6p1-3ubuntu18) ... 181s Preparing to unpack .../1-openssh-server_1%3a9.7p1-7ubuntu1_ppc64el.deb ... 181s Unpacking openssh-server (1:9.7p1-7ubuntu1) over (1:9.6p1-3ubuntu18) ... 181s Preparing to unpack .../2-openssh-client_1%3a9.7p1-7ubuntu1_ppc64el.deb ... 181s Unpacking openssh-client (1:9.7p1-7ubuntu1) over (1:9.6p1-3ubuntu18) ... 181s Preparing to unpack .../3-nftables_1.1.0-2_ppc64el.deb ... 181s Unpacking nftables (1.1.0-2) over (1.0.9-2) ... 181s Preparing to unpack .../4-libnftables1_1.1.0-2_ppc64el.deb ... 181s Unpacking libnftables1:ppc64el (1.1.0-2) over (1.0.9-2) ... 181s Selecting previously unselected package systemd-cryptsetup. 181s Preparing to unpack .../5-systemd-cryptsetup_256.4-2ubuntu1_ppc64el.deb ... 181s Unpacking systemd-cryptsetup (256.4-2ubuntu1) ... 181s Setting up systemd-sysv (256.4-2ubuntu1) ... 181s Setting up libnftables1:ppc64el (1.1.0-2) ... 181s Setting up nftables (1.1.0-2) ... 182s Setting up openssh-client (1:9.7p1-7ubuntu1) ... 182s Setting up libnss-systemd:ppc64el (256.4-2ubuntu1) ... 182s Setting up systemd-dev (256.4-2ubuntu1) ... 182s Setting up systemd-cryptsetup (256.4-2ubuntu1) ... 182s Setting up systemd-timesyncd (256.4-2ubuntu1) ... 182s systemd-time-wait-sync.service is a disabled or a static unit not running, not starting it. 182s Setting up udev (256.4-2ubuntu1) ... 183s Setting up libpam-systemd:ppc64el (256.4-2ubuntu1) ... 183s Setting up systemd-resolved (256.4-2ubuntu1) ... 184s Setting up openssh-sftp-server (1:9.7p1-7ubuntu1) ... 184s Setting up openssh-server (1:9.7p1-7ubuntu1) ... 185s Processing triggers for ufw (0.36.2-6) ... 185s Processing triggers for man-db (2.12.1-2) ... 187s Processing triggers for dbus (1.14.10-4ubuntu4) ... 187s Processing triggers for shared-mime-info (2.4-5) ... 187s Processing triggers for initramfs-tools (0.142ubuntu30) ... 187s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 187s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 195s Processing triggers for libc-bin (2.39-0ubuntu9) ... 195s Reading package lists... 195s Building dependency tree... 195s Reading state information... 195s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 196s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 196s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 196s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 196s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 197s Reading package lists... 197s Reading package lists... 197s Building dependency tree... 197s Reading state information... 197s Calculating upgrade... 197s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 198s Reading package lists... 198s Building dependency tree... 198s Reading state information... 198s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 198s autopkgtest [23:28:36]: rebooting testbed after setup commands that affected boot 202s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 226s autopkgtest [23:29:04]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 229s autopkgtest [23:29:07]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 232s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu2 (dsc) [2772 B] 232s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu2 (tar) [588 kB] 232s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu2 (diff) [42.4 kB] 233s gpgv: Signature made Tue Jul 23 21:24:22 2024 UTC 233s gpgv: using RSA key D09F8A854F1055BCFC482C4B23566B906047AFC8 233s gpgv: Can't check signature: No public key 233s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.9-1ubuntu2.dsc: no acceptable signature found 233s autopkgtest [23:29:11]: testing package multipath-tools version 0.9.9-1ubuntu2 233s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 233s autopkgtest [23:29:11]: build not needed 234s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 234s autopkgtest [23:29:12]: test kpartx-file-loopback: preparing testbed 235s Reading package lists... 235s Building dependency tree... 235s Reading state information... 236s Starting pkgProblemResolver with broken count: 0 236s Starting 2 pkgProblemResolver with broken count: 0 236s Done 236s The following additional packages will be installed: 236s liburing2 qemu-utils 236s Recommended packages: 236s qemu-block-extra 236s The following NEW packages will be installed: 236s autopkgtest-satdep liburing2 qemu-utils 236s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 236s Need to get 2330 kB/2331 kB of archives. 236s After this operation, 15.4 MB of additional disk space will be used. 236s Get:1 /tmp/autopkgtest.lNxcFa/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [724 B] 236s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 236s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 240s Fetched 2330 kB in 4s (615 kB/s) 240s Selecting previously unselected package liburing2:ppc64el. 240s (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 ... 72488 files and directories currently installed.) 240s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 240s Unpacking liburing2:ppc64el (2.6-1) ... 240s Selecting previously unselected package qemu-utils. 240s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 240s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 240s Selecting previously unselected package autopkgtest-satdep. 240s Preparing to unpack .../1-autopkgtest-satdep.deb ... 240s Unpacking autopkgtest-satdep (0) ... 240s Setting up liburing2:ppc64el (2.6-1) ... 240s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 240s Setting up autopkgtest-satdep (0) ... 240s Processing triggers for man-db (2.12.1-2) ... 242s Processing triggers for libc-bin (2.39-0ubuntu9) ... 244s (Reading database ... 72508 files and directories currently installed.) 244s Removing autopkgtest-satdep (0) ... 245s autopkgtest [23:29:23]: test kpartx-file-loopback: [----------------------- 245s Formatting 'foo.img', fmt=raw size=20971520 246s Creating new GPT entries in memory. 246s Warning: The kernel is still using the old partition table. 246s The new table will be used at the next reboot or after you 246s run partprobe(8) or kpartx(8) 246s The operation has completed successfully. 246s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 246s standard_filename: OK 246s del devmap : loop0p1 246s No devices found 246s standard_filename_cleanup: OK 246s Formatting 'fou du FaFa.img', fmt=raw size=20971520 247s Creating new GPT entries in memory. 247s Warning: The kernel is still using the old partition table. 247s The new table will be used at the next reboot or after you 247s run partprobe(8) or kpartx(8) 247s The operation has completed successfully. 247s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 247s filename_with_spaces: OK 247s del devmap : loop0p1 247s No devices found 247s filename_with_spaces_cleanup: OK 248s autopkgtest [23:29:26]: test kpartx-file-loopback: -----------------------] 248s autopkgtest [23:29:26]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 248s kpartx-file-loopback PASS 249s autopkgtest [23:29:27]: test tgtbasedmpaths: preparing testbed 435s autopkgtest [23:32:33]: testbed dpkg architecture: ppc64el 436s autopkgtest [23:32:34]: testbed apt version: 2.9.6 436s autopkgtest [23:32:34]: @@@@@@@@@@@@@@@@@@@@ test bed setup 436s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 437s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [6372 B] 437s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [509 kB] 438s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 438s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [52.0 kB] 438s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [82.0 kB] 438s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2116 B] 438s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 438s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 438s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [477 kB] 439s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [8952 B] 439s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [3728 B] 439s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 442s Fetched 1277 kB in 3s (454 kB/s) 442s Reading package lists... 444s Reading package lists... 445s Building dependency tree... 445s Reading state information... 445s Calculating upgrade... 445s The following NEW packages will be installed: 445s systemd-cryptsetup 445s The following packages will be upgraded: 445s libnftables1 libnss-systemd libpam-systemd libsystemd-shared libsystemd0 445s libudev1 nftables openssh-client openssh-server openssh-sftp-server systemd 445s systemd-dev systemd-resolved systemd-sysv systemd-timesyncd udev 445s 16 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 445s Need to get 12.7 MB of archives. 445s After this operation, 96.3 kB disk space will be freed. 445s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-dev all 256.4-2ubuntu1 [113 kB] 446s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd ppc64el 256.4-2ubuntu1 [3740 kB] 451s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-timesyncd ppc64el 256.4-2ubuntu1 [42.4 kB] 451s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-resolved ppc64el 256.4-2ubuntu1 [370 kB] 452s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd-shared ppc64el 256.4-2ubuntu1 [2490 kB] 456s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd0 ppc64el 256.4-2ubuntu1 [564 kB] 457s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-sysv ppc64el 256.4-2ubuntu1 [11.9 kB] 457s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnss-systemd ppc64el 256.4-2ubuntu1 [215 kB] 457s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpam-systemd ppc64el 256.4-2ubuntu1 [326 kB] 458s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el udev ppc64el 256.4-2ubuntu1 [2141 kB] 461s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libudev1 ppc64el 256.4-2ubuntu1 [223 kB] 461s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el openssh-sftp-server ppc64el 1:9.7p1-7ubuntu1 [43.2 kB] 461s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el openssh-server ppc64el 1:9.7p1-7ubuntu1 [621 kB] 462s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el openssh-client ppc64el 1:9.7p1-7ubuntu1 [1102 kB] 464s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el nftables ppc64el 1.1.0-2 [70.9 kB] 464s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnftables1 ppc64el 1.1.0-2 [451 kB] 465s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-cryptsetup ppc64el 256.4-2ubuntu1 [127 kB] 465s Preconfiguring packages ... 465s Fetched 12.7 MB in 20s (632 kB/s) 466s (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 ... 72513 files and directories currently installed.) 466s Preparing to unpack .../0-systemd-dev_256.4-2ubuntu1_all.deb ... 466s Unpacking systemd-dev (256.4-2ubuntu1) over (256-1ubuntu1) ... 466s Preparing to unpack .../1-systemd_256.4-2ubuntu1_ppc64el.deb ... 466s Unpacking systemd (256.4-2ubuntu1) over (256-1ubuntu1) ... 466s Preparing to unpack .../2-systemd-timesyncd_256.4-2ubuntu1_ppc64el.deb ... 466s Unpacking systemd-timesyncd (256.4-2ubuntu1) over (256-1ubuntu1) ... 466s Preparing to unpack .../3-systemd-resolved_256.4-2ubuntu1_ppc64el.deb ... 466s Unpacking systemd-resolved (256.4-2ubuntu1) over (256-1ubuntu1) ... 466s Preparing to unpack .../4-libsystemd-shared_256.4-2ubuntu1_ppc64el.deb ... 466s Unpacking libsystemd-shared:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 466s Preparing to unpack .../5-libsystemd0_256.4-2ubuntu1_ppc64el.deb ... 466s Unpacking libsystemd0:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 466s Setting up libsystemd0:ppc64el (256.4-2ubuntu1) ... 466s Setting up libsystemd-shared:ppc64el (256.4-2ubuntu1) ... 466s Setting up systemd (256.4-2ubuntu1) ... 466s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 466s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 467s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 467s (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 ... 72438 files and directories currently installed.) 467s Preparing to unpack .../systemd-sysv_256.4-2ubuntu1_ppc64el.deb ... 467s Unpacking systemd-sysv (256.4-2ubuntu1) over (256-1ubuntu1) ... 467s Preparing to unpack .../libnss-systemd_256.4-2ubuntu1_ppc64el.deb ... 467s Unpacking libnss-systemd:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 467s Preparing to unpack .../libpam-systemd_256.4-2ubuntu1_ppc64el.deb ... 467s Unpacking libpam-systemd:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 467s Preparing to unpack .../udev_256.4-2ubuntu1_ppc64el.deb ... 467s Unpacking udev (256.4-2ubuntu1) over (256-1ubuntu1) ... 468s Preparing to unpack .../libudev1_256.4-2ubuntu1_ppc64el.deb ... 468s Unpacking libudev1:ppc64el (256.4-2ubuntu1) over (256-1ubuntu1) ... 468s Setting up libudev1:ppc64el (256.4-2ubuntu1) ... 468s (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 ... 72439 files and directories currently installed.) 468s Preparing to unpack .../0-openssh-sftp-server_1%3a9.7p1-7ubuntu1_ppc64el.deb ... 468s Unpacking openssh-sftp-server (1:9.7p1-7ubuntu1) over (1:9.6p1-3ubuntu18) ... 468s Preparing to unpack .../1-openssh-server_1%3a9.7p1-7ubuntu1_ppc64el.deb ... 468s Unpacking openssh-server (1:9.7p1-7ubuntu1) over (1:9.6p1-3ubuntu18) ... 468s Preparing to unpack .../2-openssh-client_1%3a9.7p1-7ubuntu1_ppc64el.deb ... 468s Unpacking openssh-client (1:9.7p1-7ubuntu1) over (1:9.6p1-3ubuntu18) ... 468s Preparing to unpack .../3-nftables_1.1.0-2_ppc64el.deb ... 468s Unpacking nftables (1.1.0-2) over (1.0.9-2) ... 468s Preparing to unpack .../4-libnftables1_1.1.0-2_ppc64el.deb ... 468s Unpacking libnftables1:ppc64el (1.1.0-2) over (1.0.9-2) ... 468s Selecting previously unselected package systemd-cryptsetup. 468s Preparing to unpack .../5-systemd-cryptsetup_256.4-2ubuntu1_ppc64el.deb ... 468s Unpacking systemd-cryptsetup (256.4-2ubuntu1) ... 468s Setting up systemd-sysv (256.4-2ubuntu1) ... 468s Setting up libnftables1:ppc64el (1.1.0-2) ... 468s Setting up nftables (1.1.0-2) ... 469s Setting up openssh-client (1:9.7p1-7ubuntu1) ... 469s Setting up libnss-systemd:ppc64el (256.4-2ubuntu1) ... 469s Setting up systemd-dev (256.4-2ubuntu1) ... 469s Setting up systemd-cryptsetup (256.4-2ubuntu1) ... 469s Setting up systemd-timesyncd (256.4-2ubuntu1) ... 469s systemd-time-wait-sync.service is a disabled or a static unit not running, not starting it. 469s Setting up udev (256.4-2ubuntu1) ... 470s Setting up libpam-systemd:ppc64el (256.4-2ubuntu1) ... 470s Setting up systemd-resolved (256.4-2ubuntu1) ... 471s Setting up openssh-sftp-server (1:9.7p1-7ubuntu1) ... 471s Setting up openssh-server (1:9.7p1-7ubuntu1) ... 472s Processing triggers for ufw (0.36.2-6) ... 472s Processing triggers for man-db (2.12.1-2) ... 474s Processing triggers for dbus (1.14.10-4ubuntu4) ... 474s Processing triggers for shared-mime-info (2.4-5) ... 475s Processing triggers for initramfs-tools (0.142ubuntu30) ... 475s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 475s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 485s Processing triggers for libc-bin (2.39-0ubuntu9) ... 485s Reading package lists... 485s Building dependency tree... 485s Reading state information... 486s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 486s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 486s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 486s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 486s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 487s Reading package lists... 487s Reading package lists... 487s Building dependency tree... 487s Reading state information... 488s Calculating upgrade... 488s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 488s Reading package lists... 488s Building dependency tree... 488s Reading state information... 488s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 488s autopkgtest [23:33:26]: rebooting testbed after setup commands that affected boot 492s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 522s Reading package lists... 522s Building dependency tree... 522s Reading state information... 522s Starting pkgProblemResolver with broken count: 0 522s Starting 2 pkgProblemResolver with broken count: 0 522s Done 522s The following additional packages will be installed: 522s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 522s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 522s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 522s librdmacm1t64 lsscsi open-iscsi tgt 522s Suggested packages: 522s fio-examples gnuplot tgt-glusterfs tgt-rbd 522s Recommended packages: 522s finalrd 522s The following NEW packages will be installed: 522s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 522s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 522s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 522s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 522s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 522s Need to get 10.7 MB/10.7 MB of archives. 522s After this operation, 49.0 MB of additional disk space will be used. 522s Get:1 /tmp/autopkgtest.lNxcFa/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 523s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 523s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 523s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 524s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2 [80.5 kB] 524s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 524s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 525s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4ubuntu1 [21.5 kB] 525s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4ubuntu1 [311 kB] 526s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4ubuntu1 [46.5 kB] 526s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4ubuntu1 [99.2 kB] 526s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-1 [97.4 kB] 526s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 526s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 527s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 527s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 527s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 528s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 537s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 537s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 545s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 547s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 547s Preconfiguring packages ... 547s Fetched 10.7 MB in 24s (442 kB/s) 547s Selecting previously unselected package libopeniscsiusr. 547s (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 ... 72488 files and directories currently installed.) 547s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 547s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 548s Selecting previously unselected package libisns0t64:ppc64el. 548s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 548s Unpacking libisns0t64:ppc64el (0.101-1) ... 548s Selecting previously unselected package open-iscsi. 548s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 548s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 548s Selecting previously unselected package librdmacm1t64:ppc64el. 548s Preparing to unpack .../03-librdmacm1t64_52.0-2_ppc64el.deb ... 548s Unpacking librdmacm1t64:ppc64el (52.0-2) ... 548s Selecting previously unselected package libconfig-general-perl. 548s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 548s Unpacking libconfig-general-perl (2.65-2) ... 548s Selecting previously unselected package tgt. 548s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 548s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 548s Selecting previously unselected package libgfxdr0:ppc64el. 548s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_ppc64el.deb ... 548s Unpacking libgfxdr0:ppc64el (11.1-4ubuntu1) ... 548s Selecting previously unselected package libglusterfs0:ppc64el. 548s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_ppc64el.deb ... 548s Unpacking libglusterfs0:ppc64el (11.1-4ubuntu1) ... 548s Selecting previously unselected package libgfrpc0:ppc64el. 548s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_ppc64el.deb ... 548s Unpacking libgfrpc0:ppc64el (11.1-4ubuntu1) ... 548s Selecting previously unselected package libgfapi0:ppc64el. 548s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_ppc64el.deb ... 548s Unpacking libgfapi0:ppc64el (11.1-4ubuntu1) ... 548s Selecting previously unselected package libnbd0. 548s Preparing to unpack .../10-libnbd0_1.20.2-1_ppc64el.deb ... 548s Unpacking libnbd0 (1.20.2-1) ... 548s Selecting previously unselected package libdaxctl1:ppc64el. 548s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 548s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 548s Selecting previously unselected package libndctl6:ppc64el. 548s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 548s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 548s Selecting previously unselected package libpmem1:ppc64el. 548s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 548s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 548s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 548s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 548s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 548s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 548s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 548s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 548s Selecting previously unselected package librados2. 548s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 548s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 548s Selecting previously unselected package libpmemobj1:ppc64el. 548s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 548s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 548s Selecting previously unselected package librbd1. 548s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 548s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 548s Selecting previously unselected package fio. 548s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 548s Unpacking fio (3.37-1) ... 548s Selecting previously unselected package lsscsi. 548s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 548s Unpacking lsscsi (0.32-1build1) ... 548s Selecting previously unselected package autopkgtest-satdep. 548s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 548s Unpacking autopkgtest-satdep (0) ... 548s Setting up libconfig-general-perl (2.65-2) ... 548s Setting up libisns0t64:ppc64el (0.101-1) ... 548s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 548s Setting up libnbd0 (1.20.2-1) ... 548s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 548s Setting up libglusterfs0:ppc64el (11.1-4ubuntu1) ... 548s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 548s Setting up lsscsi (0.32-1build1) ... 548s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 548s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 548s Setting up librdmacm1t64:ppc64el (52.0-2) ... 548s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 549s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 549s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 549s Setting up libgfxdr0:ppc64el (11.1-4ubuntu1) ... 549s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 549s Setting up open-iscsi (2.1.10-1ubuntu1) ... 550s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 550s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 550s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 551s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 551s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 551s Setting up libgfrpc0:ppc64el (11.1-4ubuntu1) ... 551s Setting up libgfapi0:ppc64el (11.1-4ubuntu1) ... 551s Setting up fio (3.37-1) ... 551s Setting up autopkgtest-satdep (0) ... 551s Processing triggers for man-db (2.12.1-2) ... 553s Processing triggers for initramfs-tools (0.142ubuntu30) ... 553s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 553s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 561s Processing triggers for libc-bin (2.39-0ubuntu9) ... 564s (Reading database ... 72729 files and directories currently installed.) 564s Removing autopkgtest-satdep (0) ... 566s autopkgtest [23:34:44]: test tgtbasedmpaths: [----------------------- 566s + targetname=iqn.2016-11.foo.com:target.iscsi 566s + pwd 566s + cwd=/tmp/autopkgtest.lNxcFa/build.yMh/src 566s + testdir=/mnt/tgtmpathtest 566s + localhost=127.0.0.1 566s + portal=127.0.0.1:3260 566s + maxpaths=4 566s + backfn=backingfile 566s + expectwwid=60000000000000000e00000000010001 566s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 566s + bglog=/tmp/autopkgtest.lNxcFa/tgtbasedmpaths-artifacts/test-background.log 566s + fioprep=/tmp/autopkgtest.lNxcFa/tgtbasedmpaths-artifacts/path-change-prep.fio 566s + fiovrfy=/tmp/autopkgtest.lNxcFa/tgtbasedmpaths-artifacts/path-change-check.fio 566s + mkdir -p /etc/multipath 566s + echo /360000000000000000e00000000010001/ 566s + service tgt restart 566s + truncate --size 100M backingfile 566s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 566s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 566s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.lNxcFa/build.yMh/src/backingfile 566s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 566s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 566s + echo login #1 566s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 566s login #1 567s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 567s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 567s + seq 2 4 567s extra login #2 567s + echo extra login #2 567s + iscsiadm --mode session -r 1 --op new 567s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 567s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 567s + echo extra login #3 567s + iscsiadm --mode session -r 1 --op new 567s extra login #3 567s + echo extra login #4 567s + iscsiadm --mode session -r 1 --op new 567s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 567s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 567s extra login #4 567s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 567s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 567s + udevadm settle 567s + sleep 5 572s + echo Status after initial setup 572s + tgtadm --lld iscsi --mode target --op show 572s Status after initial setup 572s Target 1: iqn.2016-11.foo.com:target.iscsi 572s System information: 572s Driver: iscsi 572s State: ready 572s I_T nexus information: 572s I_T nexus: 1 572s Initiator: iqn.2004-10.com.ubuntu:01:882241d0e43d alias: autopkgtest 572s Connection: 0 572s IP Address: 127.0.0.1 572s I_T nexus: 2 572s Initiator: iqn.2004-10.com.ubuntu:01:882241d0e43d alias: autopkgtest 572s Connection: 0 572s IP Address: 127.0.0.1 572s I_T nexus: 3 572s Initiator: iqn.2004-10.com.ubuntu:01:882241d0e43d alias: autopkgtest 572s Connection: 0 572s IP Address: 127.0.0.1 572s I_T nexus: 4 572s Initiator: iqn.2004-10.com.ubuntu:01:882241d0e43d alias: autopkgtest 572s Connection: 0 572s IP Address: 127.0.0.1 572s LUN information: 572s LUN: 0 572s Type: controller 572s SCSI ID: IET 00010000 572s SCSI SN: beaf10 572s Size: 0 MB, Block size: 1 572s Online: Yes 572s Removable media: No 572s Prevent removal: No 572s Readonly: No 572s SWP: No 572s Thin-provisioning: No 572s Backing store type: null 572s Backing store path: None 572s Backing store flags: 572s LUN: 1 572s Type: disk 572s SCSI ID: IET 00010001 572s SCSI SN: beaf11 572s Size: 105 MB, Block size: 512 572s Online: Yes 572s Removable media: No 572s Prevent removal: No 572s Readonly: No 572s SWP: No 572s Thin-provisioning: No 572s Backing store type: rdwr 572s Backing store path: /tmp/autopkgtest.lNxcFa/build.yMh/src/backingfile 572s Backing store flags: 572s Account information: 572s ACL information: 572s ALL 572s + tgtadm --lld iscsi --op show --mode conn --tid 1 572s + iscsiadm --mode session -P 1 572s Session: 4 572s Connection: 0 572s Initiator: iqn.2004-10.com.ubuntu:01:882241d0e43d 572s IP Address: 127.0.0.1 572s Session: 3 572s Connection: 0 572s Initiator: iqn.2004-10.com.ubuntu:01:882241d0e43d 572s IP Address: 127.0.0.1 572s Session: 2 572s Connection: 0 572s Initiator: iqn.2004-10.com.ubuntu:01:882241d0e43d 572s IP Address: 127.0.0.1 572s Session: 1 572s Connection: 0 572s Initiator: iqn.2004-10.com.ubuntu:01:882241d0e43d 572s IP Address: 127.0.0.1 572s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 572s Current Portal: 127.0.0.1:3260,1 572s Persistent Portal: 127.0.0.1:3260,1 572s ********** 572s Interface: 572s ********** 572s Iface Name: default 572s Iface Transport: tcp 572s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:882241d0e43d 572s Iface IPaddress: 127.0.0.1 572s Iface HWaddress: default 572s Iface Netdev: default 572s SID: 1 572s iSCSI Connection State: LOGGED IN 572s iSCSI Session State: LOGGED_IN 572s Internal iscsid Session State: NO CHANGE 572s 572s ********** 572s Interface: 572s ********** 572s Iface Name: default 572s Iface Transport: tcp 572s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:882241d0e43d 572s Iface IPaddress: 127.0.0.1 572s Iface HWaddress: default 572s Iface Netdev: default 572s SID: 2 572s iSCSI Connection State: LOGGED IN 572s iSCSI Session State: LOGGED_IN 572s Internal iscsid Session State: NO CHANGE 572s 572s ********** 572s Interface: 572s ********** 572s Iface Name: default 572s Iface Transport: tcp 572s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:882241d0e43d 572s Iface IPaddress: 127.0.0.1 572s Iface HWaddress: default 572s Iface Netdev: default 572s SID: 3 572s iSCSI Connection State: LOGGED IN 572s iSCSI Session State: LOGGED_IN 572s Internal iscsid Session State: NO CHANGE 572s 572s ********** 572s Interface: 572s ********** 572s Iface Name: default 572s Iface Transport: tcp 572s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:882241d0e43d 572s Iface IPaddress: 127.0.0.1 572s Iface HWaddress: default 572s Iface Netdev: default 572s SID: 4 572s iSCSI Connection State: LOGGED IN 572s iSCSI Session State: LOGGED_IN 572s Internal iscsid Session State: NO CHANGE 572s + lsscsi -liv 572s [0:0:0:0] storage IET Controller 0001 - - 572s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 572s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 572s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 572s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 572s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 572s [1:0:0:0] storage IET Controller 0001 - - 572s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 572s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 572s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 572s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 572s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 572s [2:0:0:0] storage IET Controller 0001 - - 572s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 572s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 572s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 33000000100000001 572s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 572s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 572s [3:0:0:0] storage IET Controller 0001 - - 572s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 572s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 572s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 572s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 572s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 572s NVMe module may not be loaded 572s ===== paths list ===== 572s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 572s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 572s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 572s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 572s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 572s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 572s size=100M features='0' hwhandler='0' wp=rw 572s |-+- policy='service-time 0' prio=1 status=active 572s | `- 0:0:0:1 sda 8:0 active ready running 572s |-+- policy='service-time 0' prio=1 status=enabled 572s | `- 1:0:0:1 sdb 8:16 active ready running 572s |-+- policy='service-time 0' prio=1 status=enabled 572s | `- 2:0:0:1 sdc 8:32 active ready running 572s `-+- policy='service-time 0' prio=1 status=enabled 572s `- 3:0:0:1 sdd 8:48 active ready running 572s 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 572s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 572s + multipath -v3 -ll 572s 70.028288 | set open fds limit to 1073741816/1073741816 572s 70.028325 | _read_bindings_file: reading /etc/multipath/bindings 572s 70.028350 | loading /usr/lib/multipath/libchecktur.so checker 572s 70.028494 | checker tur: message table size = 4 572s 70.028505 | loading /usr/lib/multipath/libprioconst.so prioritizer 572s 70.028660 | _init_foreign: foreign library "nvme" is not enabled 572s 70.033857 | vda: device node name blacklisted 572s 70.034162 | sda: size = 204800 572s 70.034298 | sda: vendor = IET 572s 70.034320 | sda: product = VIRTUAL-DISK 572s 70.034343 | sda: rev = 0001 572s 70.035127 | sda: h:b:t:l = 0:0:0:1 572s 70.035499 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 572s 70.035503 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 572s 70.035505 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 572s 70.035681 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 572s 70.035685 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 572s 70.035700 | sda: serial = beaf11 572s 70.035704 | sda: detect_checker = yes (setting: multipath internal) 572s 70.035733 | sda checker timeout = 30 s (setting: kernel sysfs) 572s 70.036660 | sda: path_checker = tur (setting: multipath internal) 572s 70.038932 | sda: tur state = up 572s 70.039063 | sdb: size = 204800 572s 70.039192 | sdb: vendor = IET 572s 70.039212 | sdb: product = VIRTUAL-DISK 572s 70.039233 | sdb: rev = 0001 572s 70.039902 | sdb: h:b:t:l = 1:0:0:1 572s 70.040292 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 572s 70.040301 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 572s 70.040303 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 572s 70.040446 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 572s 70.040449 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 572s 70.040462 | sdb: serial = beaf11 572s 70.040464 | sdb: detect_checker = yes (setting: multipath internal) 572s 70.040491 | sdb checker timeout = 30 s (setting: kernel sysfs) 572s 70.043523 | sdb: path_checker = tur (setting: multipath internal) 572s 70.045909 | sdb: tur state = up 572s 70.046091 | sdc: size = 204800 572s 70.046269 | sdc: vendor = IET 572s 70.046298 | sdc: product = VIRTUAL-DISK 572s 70.046329 | sdc: rev = 0001 572s 70.047267 | sdc: h:b:t:l = 2:0:0:1 572s 70.047766 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 572s 70.047771 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 572s 70.047774 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 572s 70.047969 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 572s 70.047973 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 572s 70.047990 | sdc: serial = beaf11 572s 70.047994 | sdc: detect_checker = yes (setting: multipath internal) 572s 70.048068 | sdc checker timeout = 30 s (setting: kernel sysfs) 572s 70.049555 | sdc: path_checker = tur (setting: multipath internal) 572s 70.051870 | sdc: tur state = up 572s 70.052080 | sdd: size = 204800 572s 70.052260 | sdd: vendor = IET 572s 70.052287 | sdd: product = VIRTUAL-DISK 572s 70.052315 | sdd: rev = 0001 572s 70.053204 | sdd: h:b:t:l = 3:0:0:1 572s 70.053646 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 572s 70.053650 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 572s 70.053653 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 572s 70.053904 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 572s 70.053911 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 572s 70.053928 | sdd: serial = beaf11 572s 70.053932 | sdd: detect_checker = yes (setting: multipath internal) 572s 70.053968 | sdd checker timeout = 30 s (setting: kernel sysfs) 572s 70.056074 | sdd: path_checker = tur (setting: multipath internal) 572s 70.057554 | sdd: tur state = up 572s 70.057683 | loop0: device node name blacklisted 572s 70.057794 | loop1: device node name blacklisted 572s 70.057923 | loop2: device node name blacklisted 572s 70.058031 | loop3: device node name blacklisted 572s 70.058137 | loop4: device node name blacklisted 572s 70.058243 | loop5: device node name blacklisted 572s 70.058347 | loop6: device node name blacklisted 572s 70.058451 | loop7: device node name blacklisted 572s 70.058564 | dm-0: device node name blacklisted 572s 70.059983 | multipath-tools v0.9.9 (05/03, 2024) 572s 70.059996 | libdevmapper version 1.02.196 572s 70.060213 | kernel device mapper v4.48.0 572s 70.060227 | DM multipath kernel driver v1.14.0 572s 70.060358 | sda: size = 204800 572s 70.060364 | sda: vendor = IET 572s 70.060368 | sda: product = VIRTUAL-DISK 572s 70.060371 | sda: rev = 0001 572s 70.061211 | sda: h:b:t:l = 0:0:0:1 572s 70.061345 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 572s 70.061366 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 572s 70.061369 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 572s 70.061382 | sda: serial = beaf11 572s 70.063389 | sda: tur state = up 572s 70.063398 | sda: uid = 360000000000000000e00000000010001 (udev) 572s 70.063401 | sda: detect_prio = yes (setting: multipath internal) 572s 70.063404 | sda: prio = const (setting: multipath internal) 572s 70.063406 | sda: prio args = "" (setting: multipath internal) 572s 70.063409 | sda: const prio = 1 572s 70.063436 | sdb: size = 204800 572s 70.063440 | sdb: vendor = IET 572s 70.063443 | sdb: product = VIRTUAL-DISK 572s 70.063446 | sdb: rev = 0001 572s 70.064183 | sdb: h:b:t:l = 1:0:0:1 572s 70.064317 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 572s 70.064338 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 572s 70.064342 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 572s 70.064355 | sdb: serial = beaf11 572s 70.065672 | sdb: tur state = up 572s 70.065679 | sdb: uid = 360000000000000000e00000000010001 (udev) 572s 70.065682 | sdb: detect_prio = yes (setting: multipath internal) 572s 70.065685 | sdb: prio = const (setting: multipath internal) 572s 70.065687 | sdb: prio args = "" (setting: multipath internal) 572s 70.065690 | sdb: const prio = 1 572s 70.065716 | sdc: size = 204800 572s 70.065720 | sdc: vendor = IET 572s 70.065723 | sdc: product = VIRTUAL-DISK 572s 70.065726 | sdc: rev = 0001 572s 70.066426 | sdc: h:b:t:l = 2:0:0:1 572s 70.066553 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 572s 70.066573 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 572s 70.066576 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 572s 70.066589 | sdc: serial = beaf11 572s 70.068765 | sdc: tur state = up 572s 70.068777 | sdc: uid = 360000000000000000e00000000010001 (udev) 572s 70.068780 | sdc: detect_prio = yes (setting: multipath internal) 572s 70.068782 | sdc: prio = const (setting: multipath internal) 572s 70.068785 | sdc: prio args = "" (setting: multipath internal) 572s 70.068787 | sdc: const prio = 1 572s 70.068814 | sdd: size = 204800 572s 70.068818 | sdd: vendor = IET 572s 70.068821 | sdd: product = VIRTUAL-DISK 572s 70.068824 | sdd: rev = 0001 572s 70.069598 | sdd: h:b:t:l = 3:0:0:1 572s 70.069745 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 572s 70.069768 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 572s 70.069772 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 572s 70.069787 | sdd: serial = beaf11 572s 70.072049 | sdd: tur state = up 572s 70.072063 | sdd: uid = 360000000000000000e00000000010001 (udev) 572s 70.072067 | sdd: detect_prio = yes (setting: multipath internal) 572s 70.072070 | sdd: prio = const (setting: multipath internal) 572s 70.072073 | sdd: prio args = "" (setting: multipath internal) 572s 70.072076 | sdd: const prio = 1 572s 70.074954 | unloading tur checker 572s 70.075011 | unloading const prioritizer 572s + dmsetup table 572s + grep . /etc/multipath/bindings /etc/multipath/wwids 572s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 572s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 572s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 572s /etc/multipath/bindings:# 572s /etc/multipath/bindings:# Format: 572s /etc/multipath/bindings:# alias wwid 572s /etc/multipath/bindings:# 572s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 572s /etc/multipath/wwids:/360000000000000000e00000000010001/ 572s + systemctl status multipathd.service 572s ● multipathd.service - Device-Mapper Multipath Device Controller 572s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 572s Active: active (running) since Tue 2024-07-30 23:33:42 UTC; 1min 7s ago 572s Invocation: dc7ddb91b35d44f5a6a2d3bc117cf789 572s TriggeredBy: ● multipathd.socket 572s Main PID: 326 (multipathd) 572s Status: "up" 572s Tasks: 7 572s Memory: 32.5M (peak: 38.6M) 572s CPU: 45ms 572s CGroup: /system.slice/multipathd.service 572s └─326 /sbin/multipathd -d -s 572s 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 572s Jul 30 23:33:42 autopkgtest multipathd[326]: multipathd v0.9.9: start up 572s Jul 30 23:33:42 autopkgtest multipathd[326]: reconfigure: setting up paths and maps 572s Jul 30 23:33:42 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 572s Jul 30 23:34:45 autopkgtest multipathd[326]: updated bindings file /etc/multipath/bindings 572s Jul 30 23:34:45 autopkgtest multipathd[326]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 572s Jul 30 23:34:45 autopkgtest multipathd[326]: sda [8:0]: path added to devmap mpatha 572s Jul 30 23:34:45 autopkgtest multipathd[326]: mpatha: performing delayed actions 572s Jul 30 23:34:45 autopkgtest multipathd[326]: 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] 572s + systemctl status multipathd.socket 572s ● multipathd.socket - multipathd control socket 572s Loaded: loaded (/usr/lib/systemd/system/multipathd.socket; enabled; preset: enabled) 572s Active: active (running) since Tue 2024-07-30 23:33:42 UTC; 1min 7s ago 572s Invocation: 214b556999914c4487f66d3e5863a5d7 572s Triggers: ● multipathd.service 572s Listen: @/org/kernel/linux/storage/multipathd (Stream) 572s CGroup: /system.slice/multipathd.socket 572s 572s Notice: journal has been rotated since unit was started, output may be incomplete. 572s + ls -la /dev/mapper/ 572s total 0 572s drwxr-xr-x 2 root root 80 Jul 30 23:34 . 572s drwxr-xr-x 20 root root 4360 Jul 30 23:34 .. 572s crw------- 1 root root 10, 236 Jul 30 23:33 control 572s lrwxrwxrwx 1 root root 7 Jul 30 23:34 mpatha -> ../dm-0 572s journal 572s + echo journal 572s + journalctl -b 572s Jul 30 23:33:42 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 572s Jul 30 23:33:42 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 572s Jul 30 23:33:42 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 572s Jul 30 23:33:42 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 572s Jul 30 23:33:42 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 572s Jul 30 23:33:42 autopkgtest kernel: Activating Kernel Userspace Access Prevention 572s Jul 30 23:33:42 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 572s Jul 30 23:33:42 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x00000000038a0000 with 64.0 KiB pages (exec) 572s Jul 30 23:33:42 autopkgtest kernel: radix-mmu: Mapped 0x00000000038a0000-0x0000000200000000 with 64.0 KiB pages 572s Jul 30 23:33:42 autopkgtest kernel: lpar: Using radix MMU under hypervisor 572s Jul 30 23:33:42 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) 572s Jul 30 23:33:42 autopkgtest kernel: Secure boot mode disabled 572s Jul 30 23:33:42 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc0000000093e9c35 572s Jul 30 23:33:42 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (raw) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 572s Jul 30 23:33:42 autopkgtest kernel: Partition configured for 4 cpus. 572s Jul 30 23:33:42 autopkgtest kernel: CPU maps initialized for 1 thread per core 572s Jul 30 23:33:42 autopkgtest kernel: (thread shift is 0) 572s Jul 30 23:33:42 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 572s Jul 30 23:33:42 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 572s Jul 30 23:33:42 autopkgtest kernel: ----------------------------------------------------- 572s Jul 30 23:33:42 autopkgtest kernel: phys_mem_size = 0x200000000 572s Jul 30 23:33:42 autopkgtest kernel: dcache_bsize = 0x80 572s Jul 30 23:33:42 autopkgtest kernel: icache_bsize = 0x80 572s Jul 30 23:33:42 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 572s Jul 30 23:33:42 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 572s Jul 30 23:33:42 autopkgtest kernel: always = 0x0000000380008181 572s Jul 30 23:33:42 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 572s Jul 30 23:33:42 autopkgtest kernel: mmu_features = 0x3c007641 572s Jul 30 23:33:42 autopkgtest kernel: firmware_features = 0x00000285455a445f 572s Jul 30 23:33:42 autopkgtest kernel: vmalloc start = 0xc008000000000000 572s Jul 30 23:33:42 autopkgtest kernel: IO start = 0xc00a000000000000 572s Jul 30 23:33:42 autopkgtest kernel: vmemmap start = 0xc00c000000000000 572s Jul 30 23:33:42 autopkgtest kernel: ----------------------------------------------------- 572s Jul 30 23:33:42 autopkgtest kernel: numa: NODE_DATA [mem 0x1eff0c280-0x1eff13fff] 572s Jul 30 23:33:42 autopkgtest kernel: rfi-flush: fallback displacement flush available 572s Jul 30 23:33:42 autopkgtest kernel: rfi-flush: ori type flush available 572s Jul 30 23:33:42 autopkgtest kernel: rfi-flush: mttrig type flush available 572s Jul 30 23:33:42 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 572s Jul 30 23:33:42 autopkgtest kernel: count-cache-flush: hardware flush enabled. 572s Jul 30 23:33:42 autopkgtest kernel: link-stack-flush: software flush enabled. 572s Jul 30 23:33:42 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 572s Jul 30 23:33:42 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 572s Jul 30 23:33:42 autopkgtest kernel: stf-barrier: eieio barrier available 572s Jul 30 23:33:42 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 572s Jul 30 23:33:42 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 572s Jul 30 23:33:42 autopkgtest kernel: PPC64 nvram contains 65536 bytes 572s Jul 30 23:33:42 autopkgtest kernel: barrier-nospec: using ORI speculation barrier 572s Jul 30 23:33:42 autopkgtest kernel: barrier-nospec: patched 269 locations 572s Jul 30 23:33:42 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 572s Jul 30 23:33:42 autopkgtest kernel: Memory hole size: 0MB 572s Jul 30 23:33:42 autopkgtest kernel: Zone ranges: 572s Jul 30 23:33:42 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 572s Jul 30 23:33:42 autopkgtest kernel: Device empty 572s Jul 30 23:33:42 autopkgtest kernel: Movable zone start for each node 572s Jul 30 23:33:42 autopkgtest kernel: Early memory node ranges 572s Jul 30 23:33:42 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 572s Jul 30 23:33:42 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 572s Jul 30 23:33:42 autopkgtest kernel: percpu: Embedded 12 pages/cpu s609960 r0 d176472 u786432 572s Jul 30 23:33:42 autopkgtest kernel: pcpu-alloc: s609960 r0 d176472 u786432 alloc=12*65536 572s Jul 30 23:33:42 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 572s Jul 30 23:33:42 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 572s Jul 30 23:33:42 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic", will be passed to user space. 572s Jul 30 23:33:42 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 572s Jul 30 23:33:42 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 572s Jul 30 23:33:42 autopkgtest kernel: Fallback order for Node 0: 0 572s Jul 30 23:33:42 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 130944 572s Jul 30 23:33:42 autopkgtest kernel: Policy zone: Normal 572s Jul 30 23:33:42 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 572s Jul 30 23:33:42 autopkgtest kernel: Memory: 7969152K/8388608K available (23680K kernel code, 4096K rwdata, 25472K rodata, 8832K init, 1901K bss, 419456K reserved, 0K cma-reserved) 572s Jul 30 23:33:42 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 572s Jul 30 23:33:42 autopkgtest kernel: ftrace: allocating 51717 entries in 19 pages 572s Jul 30 23:33:42 autopkgtest kernel: ftrace: allocated 19 pages with 3 groups 572s Jul 30 23:33:42 autopkgtest kernel: trace event string verifier disabled 572s Jul 30 23:33:42 autopkgtest kernel: rcu: Hierarchical RCU implementation. 572s Jul 30 23:33:42 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 572s Jul 30 23:33:42 autopkgtest kernel: Rude variant of Tasks RCU enabled. 572s Jul 30 23:33:42 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 572s Jul 30 23:33:42 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 572s Jul 30 23:33:42 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 572s Jul 30 23:33:42 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 572s Jul 30 23:33:42 autopkgtest kernel: xive: Using IRQ range [0-3] 572s Jul 30 23:33:42 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 572s Jul 30 23:33:42 autopkgtest kernel: xive: Using priority 6 for all interrupts 572s Jul 30 23:33:42 autopkgtest kernel: xive: Using 64kB queues 572s Jul 30 23:33:42 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 572s Jul 30 23:33:42 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 572s Jul 30 23:33:42 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 572s Jul 30 23:33:42 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 572s Jul 30 23:33:42 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 572s Jul 30 23:33:42 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 572s Jul 30 23:33:42 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 572s Jul 30 23:33:42 autopkgtest kernel: Console: colour dummy device 80x25 572s Jul 30 23:33:42 autopkgtest kernel: pid_max: default: 32768 minimum: 301 572s Jul 30 23:33:42 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,integrity 572s Jul 30 23:33:42 autopkgtest kernel: landlock: Up and running. 572s Jul 30 23:33:42 autopkgtest kernel: Yama: becoming mindful. 572s Jul 30 23:33:42 autopkgtest kernel: AppArmor: AppArmor initialized 572s Jul 30 23:33:42 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 572s Jul 30 23:33:42 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 572s Jul 30 23:33:42 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 572s Jul 30 23:33:42 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 572s Jul 30 23:33:42 autopkgtest kernel: POWER9 performance monitor hardware support registered 572s Jul 30 23:33:42 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 572s Jul 30 23:33:42 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 572s Jul 30 23:33:42 autopkgtest kernel: smp: Bringing up secondary CPUs ... 572s Jul 30 23:33:42 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 572s Jul 30 23:33:42 autopkgtest kernel: numa: Node 0 CPUs: 0-3 572s Jul 30 23:33:42 autopkgtest kernel: devtmpfs: initialized 572s Jul 30 23:33:42 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 572s Jul 30 23:33:42 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 572s Jul 30 23:33:42 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 572s Jul 30 23:33:42 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 572s Jul 30 23:33:42 autopkgtest kernel: PCI: OF: PROBE_ONLY disabled 572s Jul 30 23:33:42 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 572s Jul 30 23:33:42 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 572s Jul 30 23:33:42 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 572s Jul 30 23:33:42 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 572s Jul 30 23:33:42 autopkgtest kernel: audit: initializing netlink subsys (disabled) 572s Jul 30 23:33:42 autopkgtest kernel: audit: type=2000 audit(1722382420.040:1): state=initialized audit_enabled=0 res=1 572s Jul 30 23:33:42 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 572s Jul 30 23:33:42 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 572s Jul 30 23:33:42 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 572s Jul 30 23:33:42 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 572s Jul 30 23:33:42 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 572s Jul 30 23:33:42 autopkgtest kernel: cpuidle: using governor ladder 572s Jul 30 23:33:42 autopkgtest kernel: cpuidle: using governor menu 572s Jul 30 23:33:42 autopkgtest kernel: RTAS daemon started 572s Jul 30 23:33:42 autopkgtest kernel: pstore: Using crash dump compression: deflate 572s Jul 30 23:33:42 autopkgtest kernel: pstore: Registered nvram as persistent store backend 572s Jul 30 23:33:42 autopkgtest kernel: EEH: pSeries platform initialized 572s Jul 30 23:33:42 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 572s Jul 30 23:33:42 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 572s Jul 30 23:33:42 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 572s Jul 30 23:33:42 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 572s Jul 30 23:33:42 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 572s Jul 30 23:33:42 autopkgtest kernel: iommu: Default domain type: Translated 572s Jul 30 23:33:42 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 572s Jul 30 23:33:42 autopkgtest kernel: SCSI subsystem initialized 572s Jul 30 23:33:42 autopkgtest kernel: libata version 3.00 loaded. 572s Jul 30 23:33:42 autopkgtest kernel: usbcore: registered new interface driver usbfs 572s Jul 30 23:33:42 autopkgtest kernel: usbcore: registered new interface driver hub 572s Jul 30 23:33:42 autopkgtest kernel: usbcore: registered new device driver usb 572s Jul 30 23:33:42 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 572s Jul 30 23:33:42 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 572s Jul 30 23:33:42 autopkgtest kernel: PTP clock support registered 572s Jul 30 23:33:42 autopkgtest kernel: EDAC MC: Ver: 3.0.0 572s Jul 30 23:33:42 autopkgtest kernel: NetLabel: Initializing 572s Jul 30 23:33:42 autopkgtest kernel: NetLabel: domain hash size = 128 572s Jul 30 23:33:42 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 572s Jul 30 23:33:42 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 572s Jul 30 23:33:42 autopkgtest kernel: mctp: management component transport protocol core 572s Jul 30 23:33:42 autopkgtest kernel: NET: Registered PF_MCTP protocol family 572s Jul 30 23:33:42 autopkgtest kernel: PCI: Probing PCI hardware 572s Jul 30 23:33:42 autopkgtest kernel: PCI host bridge to bus 0000:00 572s Jul 30 23:33:42 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 572s Jul 30 23:33:42 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 572s Jul 30 23:33:42 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 572s Jul 30 23:33:42 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:05.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:06.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:07.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 572s Jul 30 23:33:42 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 572s Jul 30 23:33:42 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 572s Jul 30 23:33:42 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 572s Jul 30 23:33:42 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 572s Jul 30 23:33:42 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:05.0: Adding to iommu group 0 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:06.0: Adding to iommu group 0 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:07.0: Adding to iommu group 0 572s Jul 30 23:33:42 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 572s Jul 30 23:33:42 autopkgtest kernel: PCI: Probing PCI hardware done 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:07.0: vgaarb: setting as boot VGA device 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:07.0: vgaarb: bridge control possible 572s Jul 30 23:33:42 autopkgtest kernel: pci 0000:00:07.0: vgaarb: VGA device added: decodes=io+mem,owns=mem,locks=none 572s Jul 30 23:33:42 autopkgtest kernel: vgaarb: loaded 572s Jul 30 23:33:42 autopkgtest kernel: clocksource: Switched to clocksource timebase 572s Jul 30 23:33:42 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 572s Jul 30 23:33:42 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 572s Jul 30 23:33:42 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 572s Jul 30 23:33:42 autopkgtest kernel: NET: Registered PF_INET protocol family 572s Jul 30 23:33:42 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 572s Jul 30 23:33:42 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 572s Jul 30 23:33:42 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 572s Jul 30 23:33:42 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 572s Jul 30 23:33:42 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 572s Jul 30 23:33:42 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 572s Jul 30 23:33:42 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 572s Jul 30 23:33:42 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 572s Jul 30 23:33:42 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 572s Jul 30 23:33:42 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 572s Jul 30 23:33:42 autopkgtest kernel: NET: Registered PF_XDP protocol family 572s Jul 30 23:33:42 autopkgtest kernel: PCI: CLS 0 bytes, default 128 572s Jul 30 23:33:42 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 572s Jul 30 23:33:42 autopkgtest kernel: Initialise system trusted keyrings 572s Jul 30 23:33:42 autopkgtest kernel: Key type blacklist registered 572s Jul 30 23:33:42 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 572s Jul 30 23:33:42 autopkgtest kernel: zbud: loaded 572s Jul 30 23:33:42 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 572s Jul 30 23:33:42 autopkgtest kernel: fuse: init (API version 7.39) 572s Jul 30 23:33:42 autopkgtest kernel: integrity: Platform Keyring initialized 572s Jul 30 23:33:42 autopkgtest kernel: integrity: Machine keyring initialized 572s Jul 30 23:33:42 autopkgtest kernel: Key type asymmetric registered 572s Jul 30 23:33:42 autopkgtest kernel: Asymmetric key parser 'x509' registered 572s Jul 30 23:33:42 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 572s Jul 30 23:33:42 autopkgtest kernel: io scheduler mq-deadline registered 572s Jul 30 23:33:42 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 572s Jul 30 23:33:42 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 572s Jul 30 23:33:42 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) 572s Jul 30 23:33:42 autopkgtest kernel: virtio-pci 0000:00:03.0: enabling device (0100 -> 0103) 572s Jul 30 23:33:42 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 572s Jul 30 23:33:42 autopkgtest kernel: virtio-pci 0000:00:05.0: enabling device (0100 -> 0103) 572s Jul 30 23:33:42 autopkgtest kernel: virtio-pci 0000:00:06.0: enabling device (0100 -> 0103) 572s Jul 30 23:33:42 autopkgtest kernel: printk: legacy console [hvc0] enabled 572s Jul 30 23:33:42 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 572s Jul 30 23:33:42 autopkgtest kernel: Freeing initrd memory: 51072K 572s Jul 30 23:33:42 autopkgtest kernel: Non-volatile memory driver v1.3 572s Jul 30 23:33:42 autopkgtest kernel: Linux agpgart interface v0.103 572s Jul 30 23:33:42 autopkgtest kernel: loop: module loaded 572s Jul 30 23:33:42 autopkgtest kernel: virtio_blk virtio2: 4/0/0 default/read/poll queues 572s Jul 30 23:33:42 autopkgtest kernel: virtio_blk virtio2: [vda] 209715200 512-byte logical blocks (107 GB/100 GiB) 572s Jul 30 23:33:42 autopkgtest kernel: vda: vda1 vda2 572s Jul 30 23:33:42 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 572s Jul 30 23:33:42 autopkgtest kernel: PPP generic driver version 2.4.2 572s Jul 30 23:33:42 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 572s Jul 30 23:33:42 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 572s Jul 30 23:33:42 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-07-30T23:33:40 UTC (1722382420) 572s Jul 30 23:33:42 autopkgtest kernel: i2c_dev: i2c /dev entries driver 572s Jul 30 23:33:42 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 572s Jul 30 23:33:42 autopkgtest kernel: device-mapper: uevent: version 1.0.3 572s Jul 30 23:33:42 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@redhat.com 572s Jul 30 23:33:42 autopkgtest kernel: pseries_idle_driver registered 572s Jul 30 23:33:42 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 572s Jul 30 23:33:42 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 572s Jul 30 23:33:42 autopkgtest kernel: NET: Registered PF_INET6 protocol family 572s Jul 30 23:33:42 autopkgtest kernel: Segment Routing with IPv6 572s Jul 30 23:33:42 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 572s Jul 30 23:33:42 autopkgtest kernel: NET: Registered PF_PACKET protocol family 572s Jul 30 23:33:42 autopkgtest kernel: Key type dns_resolver registered 572s Jul 30 23:33:42 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 572s Jul 30 23:33:42 autopkgtest kernel: drmem: No dynamic reconfiguration memory found 572s Jul 30 23:33:42 autopkgtest kernel: registered taskstats version 1 572s Jul 30 23:33:42 autopkgtest kernel: Loading compiled-in X.509 certificates 572s Jul 30 23:33:42 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 572s Jul 30 23:33:42 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 572s Jul 30 23:33:42 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 572s Jul 30 23:33:42 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 572s Jul 30 23:33:42 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 572s Jul 30 23:33:42 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 572s Jul 30 23:33:42 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 572s Jul 30 23:33:42 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 572s Jul 30 23:33:42 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 572s Jul 30 23:33:42 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 572s Jul 30 23:33:42 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 572s Jul 30 23:33:42 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 572s Jul 30 23:33:42 autopkgtest kernel: Key type .fscrypt registered 572s Jul 30 23:33:42 autopkgtest kernel: Key type fscrypt-provisioning registered 572s Jul 30 23:33:42 autopkgtest kernel: Key type encrypted registered 572s Jul 30 23:33:42 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 572s Jul 30 23:33:42 autopkgtest kernel: Secure boot mode disabled 572s Jul 30 23:33:42 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 572s Jul 30 23:33:42 autopkgtest kernel: Loading compiled-in module X.509 certificates 572s Jul 30 23:33:42 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 572s Jul 30 23:33:42 autopkgtest kernel: ima: Allocated hash algorithm: sha256 572s Jul 30 23:33:42 autopkgtest kernel: Secure boot mode disabled 572s Jul 30 23:33:42 autopkgtest kernel: Trusted boot mode disabled 572s Jul 30 23:33:42 autopkgtest kernel: ima: No architecture policies found 572s Jul 30 23:33:42 autopkgtest kernel: evm: Initialising EVM extended attributes: 572s Jul 30 23:33:42 autopkgtest kernel: evm: security.selinux 572s Jul 30 23:33:42 autopkgtest kernel: evm: security.SMACK64 572s Jul 30 23:33:42 autopkgtest kernel: evm: security.SMACK64EXEC 572s Jul 30 23:33:42 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 572s Jul 30 23:33:42 autopkgtest kernel: evm: security.SMACK64MMAP 572s Jul 30 23:33:42 autopkgtest kernel: evm: security.apparmor 572s Jul 30 23:33:42 autopkgtest kernel: evm: security.ima 572s Jul 30 23:33:42 autopkgtest kernel: evm: security.capability 572s Jul 30 23:33:42 autopkgtest kernel: evm: HMAC attrs: 0x1 572s Jul 30 23:33:42 autopkgtest kernel: SED: plpks not available 572s Jul 30 23:33:42 autopkgtest kernel: clk: Disabling unused clocks 572s Jul 30 23:33:42 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 572s Jul 30 23:33:42 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8832K 572s Jul 30 23:33:42 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 572s Jul 30 23:33:42 autopkgtest kernel: Run /init as init process 572s Jul 30 23:33:42 autopkgtest kernel: with arguments: 572s Jul 30 23:33:42 autopkgtest kernel: /init 572s Jul 30 23:33:42 autopkgtest kernel: earlyprintk 572s Jul 30 23:33:42 autopkgtest kernel: with environment: 572s Jul 30 23:33:42 autopkgtest kernel: HOME=/ 572s Jul 30 23:33:42 autopkgtest kernel: TERM=linux 572s Jul 30 23:33:42 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic 572s Jul 30 23:33:42 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 572s Jul 30 23:33:42 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 572s Jul 30 23:33:42 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 1 572s Jul 30 23:33:42 autopkgtest kernel: xhci_hcd 0000:00:02.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010 572s Jul 30 23:33:42 autopkgtest kernel: random: crng init done 572s Jul 30 23:33:42 autopkgtest kernel: [drm] Found bochs VGA, ID 0xb0c5. 572s Jul 30 23:33:42 autopkgtest kernel: [drm] Framebuffer size 16384 kB @ 0x200081000000, mmio @ 0x200082000000. 572s Jul 30 23:33:42 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 572s Jul 30 23:33:42 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2 572s Jul 30 23:33:42 autopkgtest kernel: xhci_hcd 0000:00:02.0: Host supports USB 3.0 SuperSpeed 572s Jul 30 23:33:42 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.08 572s Jul 30 23:33:42 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 572s Jul 30 23:33:42 autopkgtest kernel: usb usb1: Product: xHCI Host Controller 572s Jul 30 23:33:42 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 572s Jul 30 23:33:42 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:02.0 572s Jul 30 23:33:42 autopkgtest kernel: [drm] Found EDID data blob. 572s Jul 30 23:33:42 autopkgtest kernel: [drm] Initialized bochs-drm 1.0.0 20130925 for 0000:00:07.0 on minor 0 572s Jul 30 23:33:42 autopkgtest kernel: hub 1-0:1.0: USB hub found 572s Jul 30 23:33:42 autopkgtest kernel: hub 1-0:1.0: 4 ports detected 572s Jul 30 23:33:42 autopkgtest kernel: fbcon: Deferring console take-over 572s Jul 30 23:33:42 autopkgtest kernel: bochs-drm 0000:00:07.0: [drm] fb0: bochs-drmdrmfb frame buffer device 572s Jul 30 23:33:42 autopkgtest kernel: usb usb2: We don't know the algorithms for LPM for this host, disabling LPM. 572s Jul 30 23:33:42 autopkgtest kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.08 572s Jul 30 23:33:42 autopkgtest kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 572s Jul 30 23:33:42 autopkgtest kernel: usb usb2: Product: xHCI Host Controller 572s Jul 30 23:33:42 autopkgtest kernel: usb usb2: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 572s Jul 30 23:33:42 autopkgtest kernel: usb usb2: SerialNumber: 0000:00:02.0 572s Jul 30 23:33:42 autopkgtest kernel: hub 2-0:1.0: USB hub found 572s Jul 30 23:33:42 autopkgtest kernel: hub 2-0:1.0: 4 ports detected 572s Jul 30 23:33:42 autopkgtest kernel: raid6: vpermxor8 gen() 22816 MB/s 572s Jul 30 23:33:42 autopkgtest kernel: raid6: vpermxor4 gen() 20003 MB/s 572s Jul 30 23:33:42 autopkgtest kernel: usb 1-1: new high-speed USB device number 2 using xhci_hcd 572s Jul 30 23:33:42 autopkgtest kernel: raid6: vpermxor2 gen() 15978 MB/s 572s Jul 30 23:33:42 autopkgtest kernel: raid6: vpermxor1 gen() 13675 MB/s 572s Jul 30 23:33:42 autopkgtest kernel: raid6: altivecx8 gen() 13916 MB/s 572s Jul 30 23:33:42 autopkgtest kernel: usb 1-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 572s Jul 30 23:33:42 autopkgtest kernel: usb 1-1: New USB device strings: Mfr=1, Product=4, SerialNumber=11 572s Jul 30 23:33:42 autopkgtest kernel: usb 1-1: Product: QEMU USB Keyboard 572s Jul 30 23:33:42 autopkgtest kernel: usb 1-1: Manufacturer: QEMU 572s Jul 30 23:33:42 autopkgtest kernel: usb 1-1: SerialNumber: 68284-pci@800000020000000:02.0-1 572s Jul 30 23:33:42 autopkgtest kernel: hid: raw HID events driver (C) Jiri Kosina 572s Jul 30 23:33:42 autopkgtest kernel: usbcore: registered new interface driver usbhid 572s Jul 30 23:33:42 autopkgtest kernel: usbhid: USB HID core driver 572s Jul 30 23:33:42 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 572s Jul 30 23:33:42 autopkgtest kernel: raid6: altivecx4 gen() 13781 MB/s 572s Jul 30 23:33:42 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 572s Jul 30 23:33:42 autopkgtest kernel: raid6: altivecx2 gen() 10705 MB/s 572s Jul 30 23:33:42 autopkgtest kernel: usb 1-2: new high-speed USB device number 3 using xhci_hcd 572s Jul 30 23:33:42 autopkgtest kernel: raid6: altivecx1 gen() 8759 MB/s 572s Jul 30 23:33:42 autopkgtest kernel: raid6: int64x8 gen() 7388 MB/s 572s Jul 30 23:33:42 autopkgtest kernel: usb 1-2: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 572s Jul 30 23:33:42 autopkgtest kernel: usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=9 572s Jul 30 23:33:42 autopkgtest kernel: usb 1-2: Product: QEMU USB Mouse 572s Jul 30 23:33:42 autopkgtest kernel: usb 1-2: Manufacturer: QEMU 572s Jul 30 23:33:42 autopkgtest kernel: usb 1-2: SerialNumber: 89126-pci@800000020000000:02.0-2 572s Jul 30 23:33:42 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 572s Jul 30 23:33:42 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 572s Jul 30 23:33:42 autopkgtest kernel: raid6: int64x4 gen() 8830 MB/s 572s Jul 30 23:33:42 autopkgtest kernel: raid6: int64x2 gen() 6673 MB/s 572s Jul 30 23:33:42 autopkgtest kernel: raid6: int64x1 gen() 5314 MB/s 572s Jul 30 23:33:42 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 22816 MB/s 572s Jul 30 23:33:42 autopkgtest kernel: raid6: using intx1 recovery algorithm 572s Jul 30 23:33:42 autopkgtest kernel: xor: measuring software checksum speed 572s Jul 30 23:33:42 autopkgtest kernel: 8regs : 15550 MB/sec 572s Jul 30 23:33:42 autopkgtest kernel: 8regs_prefetch : 13856 MB/sec 572s Jul 30 23:33:42 autopkgtest kernel: 32regs : 15543 MB/sec 572s Jul 30 23:33:42 autopkgtest kernel: 32regs_prefetch : 14085 MB/sec 572s Jul 30 23:33:42 autopkgtest kernel: altivec : 17332 MB/sec 572s Jul 30 23:33:42 autopkgtest kernel: xor: using function: altivec (17332 MB/sec) 572s Jul 30 23:33:42 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 572s Jul 30 23:33:42 autopkgtest kernel: EXT4-fs (vda1): orphan cleanup on readonly fs 572s Jul 30 23:33:42 autopkgtest kernel: EXT4-fs (vda1): mounted filesystem 55f4738b-dbc7-4aef-90fe-6bd3178557bc ro with ordered data mode. Quota mode: none. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Inserted module 'autofs4' 572s Jul 30 23:33:42 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) 572s Jul 30 23:33:42 autopkgtest systemd[1]: Detected virtualization kvm. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Detected architecture ppc64-le. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Hostname set to . 572s Jul 30 23:33:42 autopkgtest systemd[1]: bpf-restrict-fs: BPF LSM hook not enabled in the kernel, BPF LSM not supported. 572s Jul 30 23:33:42 autopkgtest kernel: NET: Registered PF_VSOCK protocol family 572s Jul 30 23:33:42 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. 572s Jul 30 23:33:42 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. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Queued start job for default target graphical.target. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Reached target swap.target - Swaps. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Listening on multipathd.socket - multipathd control socket. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 572s Jul 30 23:33:42 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Sockets. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounting run-lock.mount - Legacy Locks Directory /run/lock... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting modprobe@dm_multipath.service - Load Kernel Module dm_multipath... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 572s Jul 30 23:33:42 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 572s Jul 30 23:33:42 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). 572s Jul 30 23:33:42 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). 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 572s Jul 30 23:33:42 autopkgtest systemd-journald[281]: Collecting audit messages is disabled. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounted run-lock.mount - Legacy Locks Directory /run/lock. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 572s Jul 30 23:33:42 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 572s Jul 30 23:33:42 autopkgtest systemd[1]: modprobe@dm_multipath.service: Deactivated successfully. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished modprobe@dm_multipath.service - Load Kernel Module dm_multipath. 572s Jul 30 23:33:42 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 572s Jul 30 23:33:42 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 572s Jul 30 23:33:42 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 572s Jul 30 23:33:42 autopkgtest systemd-journald[281]: Journal started 572s Jul 30 23:33:42 autopkgtest systemd-journald[281]: Runtime Journal (/run/log/journal/55e2544062ce49859b49798ab095ecbd) is 8M, max 78.4M, 70.4M free. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 572s Jul 30 23:33:42 autopkgtest kernel: EXT4-fs (vda1): re-mounted 55f4738b-dbc7-4aef-90fe-6bd3178557bc r/w. Quota mode: none. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 572s Jul 30 23:33:42 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 572s Jul 30 23:33:42 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 572s Jul 30 23:33:42 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 572s Jul 30 23:33:42 autopkgtest systemd-journald[281]: Time spent on flushing to /var/log/journal/55e2544062ce49859b49798ab095ecbd is 41.622ms for 461 entries. 572s Jul 30 23:33:42 autopkgtest systemd-journald[281]: System Journal (/var/log/journal/55e2544062ce49859b49798ab095ecbd) is 19M, max 4G, 3.9G free. 572s Jul 30 23:33:42 autopkgtest systemd-journald[281]: Received client request to flush runtime journal. 572s Jul 30 23:33:42 autopkgtest multipathd[326]: multipathd v0.9.9: start up 572s Jul 30 23:33:42 autopkgtest multipathd[326]: reconfigure: setting up paths and maps 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 572s Jul 30 23:33:42 autopkgtest apparmor.systemd[348]: Restarting AppArmor 572s Jul 30 23:33:42 autopkgtest apparmor.systemd[348]: Reloading AppArmor profiles 572s Jul 30 23:33:42 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 572s Jul 30 23:33:42 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 572s Jul 30 23:33:42 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 351 (systemd-binfmt) 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 572s Jul 30 23:33:42 autopkgtest systemd-tmpfiles[365]: /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 572s Jul 30 23:33:42 autopkgtest systemd-udevd[341]: Using default interface naming scheme 'v255'. 572s Jul 30 23:33:42 autopkgtest kernel: audit: type=1400 audit(1722382422.568:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=374 comm="apparmor_parser" 572s Jul 30 23:33:42 autopkgtest kernel: audit: type=1400 audit(1722382422.568:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=376 comm="apparmor_parser" 572s Jul 30 23:33:42 autopkgtest kernel: audit: type=1400 audit(1722382422.568:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=375 comm="apparmor_parser" 572s Jul 30 23:33:42 autopkgtest kernel: audit: type=1400 audit(1722382422.568:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=377 comm="apparmor_parser" 572s Jul 30 23:33:42 autopkgtest kernel: audit: type=1400 audit(1722382422.576:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=378 comm="apparmor_parser" 572s Jul 30 23:33:42 autopkgtest kernel: audit: type=1400 audit(1722382422.576:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=380 comm="apparmor_parser" 572s Jul 30 23:33:42 autopkgtest kernel: audit: type=1400 audit(1722382422.576:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=379 comm="apparmor_parser" 572s Jul 30 23:33:42 autopkgtest kernel: audit: type=1400 audit(1722382422.576:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="busybox" pid=381 comm="apparmor_parser" 572s Jul 30 23:33:42 autopkgtest kernel: audit: type=1400 audit(1722382422.580:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="bwrap" pid=382 comm="apparmor_parser" 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. 572s Jul 30 23:33:42 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 572s Jul 30 23:33:42 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 572s Jul 30 23:33:42 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 572s Jul 30 23:33:42 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). 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 572s Jul 30 23:33:42 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 572s Jul 30 23:33:42 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 572s Jul 30 23:33:42 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 572s Jul 30 23:33:42 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 572s Jul 30 23:33:42 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). 572s Jul 30 23:33:42 autopkgtest systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 572s Jul 30 23:33:42 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 572s Jul 30 23:33:42 autopkgtest (udev-worker)[454]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 572s Jul 30 23:33:42 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 572s Jul 30 23:33:43 autopkgtest cloud-init[676]: Cloud-init v. 24.3~1g6e4153b3-0ubuntu1 running 'init-local' at Tue, 30 Jul 2024 23:33:43 +0000. Up 3.04 seconds. 572s Jul 30 23:33:43 autopkgtest dhcpcd[679]: dhcpcd-10.0.8 starting 572s Jul 30 23:33:43 autopkgtest dhcpcd[682]: DUID 00:01:00:01:2e:3b:8f:08:fa:16:3e:e9:e1:ee 572s Jul 30 23:33:43 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 572s Jul 30 23:33:43 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 572s Jul 30 23:33:43 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 572s Jul 30 23:33:43 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 572s Jul 30 23:33:43 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 572s Jul 30 23:33:43 autopkgtest dhcpcd[682]: enp0s1: IAID 3e:12:f3:78 572s Jul 30 23:33:43 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 572s Jul 30 23:33:43 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 572s Jul 30 23:33:43 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 572s Jul 30 23:33:43 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 572s Jul 30 23:33:43 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 572s Jul 30 23:33:43 autopkgtest systemd-resolved[402]: Positive Trust Anchors: 572s Jul 30 23:33:43 autopkgtest systemd-resolved[402]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 572s Jul 30 23:33:43 autopkgtest systemd-resolved[402]: 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 572s Jul 30 23:33:43 autopkgtest systemd-resolved[402]: Using system hostname 'autopkgtest'. 572s Jul 30 23:33:43 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 572s Jul 30 23:33:43 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 572s Jul 30 23:33:44 autopkgtest dhcpcd[682]: enp0s1: rebinding lease of 10.145.227.22 572s Jul 30 23:33:44 autopkgtest dhcpcd[682]: enp0s1: leased 10.145.227.22 for 43200 seconds 572s Jul 30 23:33:44 autopkgtest dhcpcd[682]: enp0s1: adding route to 10.145.227.0/24 572s Jul 30 23:33:44 autopkgtest dhcpcd[682]: enp0s1: adding host route to 169.254.169.254 via 10.145.227.2 572s Jul 30 23:33:44 autopkgtest dhcpcd[682]: enp0s1: adding default route via 10.145.227.1 572s Jul 30 23:33:44 autopkgtest dhcpcd[682]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 572s Jul 30 23:33:49 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 572s Jul 30 23:33:49 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 572s Jul 30 23:33:49 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 572s Jul 30 23:33:49 autopkgtest systemd-networkd[716]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 572s Jul 30 23:33:49 autopkgtest systemd-networkd[716]: lo: Link UP 572s Jul 30 23:33:49 autopkgtest systemd-networkd[716]: lo: Gained carrier 572s Jul 30 23:33:49 autopkgtest systemd-networkd[716]: Enumeration completed 572s Jul 30 23:33:49 autopkgtest systemd-networkd[716]: enp0s1: Link UP 572s Jul 30 23:33:49 autopkgtest systemd-networkd[716]: enp0s1: Gained carrier 572s Jul 30 23:33:49 autopkgtest systemd-timesyncd[408]: Network configuration changed, trying to establish connection. 572s Jul 30 23:33:49 autopkgtest systemd-networkd[716]: enp0s1: Gained IPv6LL 572s Jul 30 23:33:49 autopkgtest systemd-networkd[716]: enp0s1: Link DOWN 572s Jul 30 23:33:49 autopkgtest systemd-networkd[716]: enp0s1: Lost carrier 572s Jul 30 23:33:49 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 572s Jul 30 23:33:49 autopkgtest systemd[1]: Reached target network.target - Network. 572s Jul 30 23:33:49 autopkgtest systemd-networkd[716]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 572s Jul 30 23:33:49 autopkgtest systemd-networkd[716]: enp0s1: Link UP 572s Jul 30 23:33:49 autopkgtest systemd-networkd[716]: enp0s1: Gained carrier 572s Jul 30 23:33:49 autopkgtest systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... 572s Jul 30 23:33:49 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 572s Jul 30 23:33:49 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 572s Jul 30 23:33:49 autopkgtest systemd-networkd[716]: enp0s1: DHCPv4 address 10.145.227.22/24, gateway 10.145.227.1 acquired from 10.145.227.1 572s Jul 30 23:33:49 autopkgtest systemd-timesyncd[408]: Network configuration changed, trying to establish connection. 572s Jul 30 23:33:49 autopkgtest systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. 572s Jul 30 23:33:51 autopkgtest systemd-networkd[716]: enp0s1: Gained IPv6LL 572s Jul 30 23:33:51 autopkgtest systemd-timesyncd[408]: Network configuration changed, trying to establish connection. 572s Jul 30 23:33:51 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 572s Jul 30 23:33:51 autopkgtest systemd[1]: Starting cloud-init.service - Cloud-init: Network Stage... 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: Cloud-init v. 24.3~1g6e4153b3-0ubuntu1 running 'init' at Tue, 30 Jul 2024 23:33:51 +0000. Up 11.56 seconds. 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | enp0s1 | True | 10.145.227.22 | 255.255.255.0 | global | fa:16:3e:12:f3:78 | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | enp0s1 | True | fe80::f816:3eff:fe12:f378/64 | . | link | fa:16:3e:12:f3:78 | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | lo | True | ::1/128 | . | host | . | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++++ 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | 0 | 0.0.0.0 | 10.145.227.1 | 0.0.0.0 | enp0s1 | UG | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | 1 | 10.145.227.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | 2 | 10.145.227.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | 3 | 10.145.227.2 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | 4 | 91.189.91.131 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | 5 | 91.189.91.132 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | 6 | 169.254.169.254 | 10.145.227.2 | 255.255.255.255 | enp0s1 | UGH | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: +-------+-------------+---------+-----------+-------+ 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | Route | Destination | Gateway | Interface | Flags | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: +-------+-------------+---------+-----------+-------+ 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | 2 | local | :: | enp0s1 | U | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: | 3 | multicast | :: | enp0s1 | U | 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: ci-info: +-------+-------------+---------+-----------+-------+ 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: 2024-07-30 23:33:51,859 - 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. 572s Jul 30 23:33:51 autopkgtest cloud-init[726]: 2024-07-30 23:33:51,859 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Finished cloud-init.service - Cloud-init: Network Stage. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 572s Jul 30 23:33:52 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). 572s Jul 30 23:33:52 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). 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started sysstat-collect.timer - Run system activity accounting tool every 10 minutes. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started sysstat-rotate.timer - Rotate daily system activity data file at midnight. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started sysstat-summary.timer - Generate summary of yesterday's process accounting. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 572s Jul 30 23:33:52 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). 572s Jul 30 23:33:52 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Reached target paths.target - Path Units. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 572s Jul 30 23:33:52 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 572s Jul 30 23:33:52 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). 572s Jul 30 23:33:52 autopkgtest systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). 572s Jul 30 23:33:52 autopkgtest systemd[1]: Reached target ssh-access.target - SSH Access Available. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Reached target basic.target - Basic System. 572s Jul 30 23:33:52 autopkgtest systemd[1]: System is tainted: unmerged-bin 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 572s Jul 30 23:33:52 autopkgtest (sh)[761]: autopkgtest@hvc1.service: Failed to set up standard input: No such device 572s Jul 30 23:33:52 autopkgtest (sh)[761]: autopkgtest@hvc1.service: Failed at step STDIN spawning /bin/sh: No such device 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 572s Jul 30 23:33:52 autopkgtest (sh)[762]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 572s Jul 30 23:33:52 autopkgtest (sh)[762]: autopkgtest@ttyS1.service: Failed at step STDIN spawning /bin/sh: Input/output error 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 572s Jul 30 23:33:52 autopkgtest (cron)[764]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 572s Jul 30 23:33:52 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). 572s Jul 30 23:33:52 autopkgtest cron[764]: (CRON) INFO (pidfile fd = 3) 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 572s Jul 30 23:33:52 autopkgtest cron[764]: (CRON) INFO (Running @reboot jobs) 572s Jul 30 23:33:52 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 572s Jul 30 23:33:52 autopkgtest systemd[1]: opal_errd.service - opal_errd (PowerNV platform error handling) Service was skipped because of an unmet condition check (ConditionVirtualization=false). 572s Jul 30 23:33:52 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). 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting sysstat.service - Resets System Activity Logs... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 572s Jul 30 23:33:52 autopkgtest dbus-daemon[765]: [system] AppArmor D-Bus mediation is enabled 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 572s Jul 30 23:33:52 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). 572s Jul 30 23:33:52 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 572s Jul 30 23:33:52 autopkgtest systemd[1]: autopkgtest@hvc1.service: Deactivated successfully. 572s Jul 30 23:33:52 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Finished sysstat.service - Resets System Activity Logs. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 572s Jul 30 23:33:52 autopkgtest udisksd[783]: udisks daemon version 2.10.1 starting 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 572s Jul 30 23:33:52 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 572s Jul 30 23:33:52 autopkgtest rngd[824]: rngd 2.4 starting up... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 572s Jul 30 23:33:52 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 572s Jul 30 23:33:52 autopkgtest rngd[824]: entropy feed to the kernel ready 572s Jul 30 23:33:52 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 572s Jul 30 23:33:52 autopkgtest systemd-logind[777]: New seat seat0. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 572s Jul 30 23:33:52 autopkgtest systemd-logind[777]: Watching system buttons on /dev/input/event0 (QEMU QEMU USB Keyboard) 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 572s Jul 30 23:33:52 autopkgtest udisksd[783]: Acquired the name org.freedesktop.UDisks2 on the system message bus 572s Jul 30 23:33:52 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 572s Jul 30 23:33:52 autopkgtest kernel: kauditd_printk_skb: 110 callbacks suppressed 572s Jul 30 23:33:52 autopkgtest kernel: audit: type=1400 audit(1722382432.284:121): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=815 comm="apparmor_parser" 572s Jul 30 23:33:52 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 572s Jul 30 23:33:52 autopkgtest rsyslogd[857]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2406.0] 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 572s Jul 30 23:33:52 autopkgtest rsyslogd[857]: rsyslogd's groupid changed to 102 572s Jul 30 23:33:52 autopkgtest rsyslogd[857]: rsyslogd's userid changed to 102 572s Jul 30 23:33:52 autopkgtest rsyslogd[857]: [origin software="rsyslogd" swVersion="8.2406.0" x-pid="857" x-info="https://www.rsyslog.com"] start 572s Jul 30 23:33:52 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 572s Jul 30 23:33:52 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 572s Jul 30 23:33:52 autopkgtest cloud-init[869]: Cloud-init v. 24.3~1g6e4153b3-0ubuntu1 running 'modules:config' at Tue, 30 Jul 2024 23:33:52 +0000. Up 12.36 seconds. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 572s Jul 30 23:33:52 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 572s Jul 30 23:33:52 autopkgtest sshd[873]: Server listening on :: port 22. 572s Jul 30 23:33:52 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 572s Jul 30 23:33:53 autopkgtest cloud-init[880]: Cloud-init v. 24.3~1g6e4153b3-0ubuntu1 running 'modules:final' at Tue, 30 Jul 2024 23:33:53 +0000. Up 12.89 seconds. 572s Jul 30 23:33:53 autopkgtest cloud-init[880]: Cloud-init v. 24.3~1g6e4153b3-0ubuntu1 finished at Tue, 30 Jul 2024 23:33:53 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 12.96 seconds 572s Jul 30 23:33:53 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 572s Jul 30 23:33:53 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 572s Jul 30 23:33:53 autopkgtest systemd[1]: Startup finished in 1.762s (kernel) + 11.267s (userspace) = 13.030s. 572s Jul 30 23:33:53 autopkgtest kernel: fbcon: Taking over console 572s Jul 30 23:33:53 autopkgtest kernel: Console: switching to colour frame buffer device 128x48 572s Jul 30 23:33:53 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 572s Jul 30 23:33:53 autopkgtest sshd[875]: Accepted publickey for ubuntu from 10.136.6.201 port 52356 ssh2: RSA SHA256:YaYyKWTl9zFJEBK5G3u+MRj3WPJt+vEplFd0J96PUBw 572s Jul 30 23:33:53 autopkgtest sshd[875]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 572s Jul 30 23:33:53 autopkgtest sshd[875]: pam_systemd(sshd:session): New sd-bus connection (system-bus-pam-systemd-875) opened. 572s Jul 30 23:33:53 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 572s Jul 30 23:33:53 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 572s Jul 30 23:33:53 autopkgtest systemd-logind[777]: New session 1 of user ubuntu. 572s Jul 30 23:33:53 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 572s Jul 30 23:33:53 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 572s Jul 30 23:33:53 autopkgtest (systemd)[929]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 572s Jul 30 23:33:53 autopkgtest systemd-logind[777]: New session 2 of user ubuntu. 572s Jul 30 23:33:53 autopkgtest systemd[929]: Queued start job for default target default.target. 572s Jul 30 23:33:53 autopkgtest systemd[929]: Created slice app.slice - User Application Slice. 572s Jul 30 23:33:53 autopkgtest systemd[929]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 572s Jul 30 23:33:53 autopkgtest systemd[929]: Reached target paths.target - Paths. 572s Jul 30 23:33:53 autopkgtest systemd[929]: Reached target timers.target - Timers. 572s Jul 30 23:33:53 autopkgtest systemd[929]: Starting dbus.socket - D-Bus User Message Bus Socket... 572s Jul 30 23:33:53 autopkgtest systemd[929]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 572s Jul 30 23:33:53 autopkgtest systemd[929]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 572s Jul 30 23:33:53 autopkgtest systemd[929]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 572s Jul 30 23:33:53 autopkgtest systemd[929]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 572s Jul 30 23:33:53 autopkgtest systemd[929]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 572s Jul 30 23:33:53 autopkgtest systemd[929]: Listening on keyboxd.socket - GnuPG public key management service. 572s Jul 30 23:33:53 autopkgtest systemd[929]: Listening on dbus.socket - D-Bus User Message Bus Socket. 572s Jul 30 23:33:53 autopkgtest systemd[929]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 572s Jul 30 23:33:53 autopkgtest systemd[929]: Reached target sockets.target - Sockets. 572s Jul 30 23:33:53 autopkgtest systemd[929]: Reached target basic.target - Basic System. 572s Jul 30 23:33:53 autopkgtest systemd[929]: Reached target default.target - Main User Target. 572s Jul 30 23:33:53 autopkgtest systemd[929]: Startup finished in 134ms. 572s Jul 30 23:33:53 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 572s Jul 30 23:33:53 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 572s Jul 30 23:33:53 autopkgtest sudo[957]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 572s Jul 30 23:33:53 autopkgtest sudo[957]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:53 autopkgtest sudo[957]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:54 autopkgtest sudo[962]: 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' 572s Jul 30 23:33:54 autopkgtest sudo[962]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:54 autopkgtest sudo[962]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:54 autopkgtest sudo[974]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.lNxcFa 572s Jul 30 23:33:54 autopkgtest sudo[974]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:54 autopkgtest sudo[974]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:54 autopkgtest sudo[984]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.lNxcFa/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.lNxcFa/autopkgtest-reboot' 572s Jul 30 23:33:54 autopkgtest sudo[984]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:54 autopkgtest sudo[984]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:54 autopkgtest sudo[996]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.lNxcFa/autopkgtest-reboot 572s Jul 30 23:33:54 autopkgtest sudo[996]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:55 autopkgtest sudo[996]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:55 autopkgtest sudo[1006]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.lNxcFa/autopkgtest-reboot /tmp/autopkgtest-reboot 572s Jul 30 23:33:55 autopkgtest sudo[1006]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:55 autopkgtest sudo[1006]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:55 autopkgtest sudo[1016]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.lNxcFa/autopkgtest-reboot /sbin/autopkgtest-reboot 572s Jul 30 23:33:55 autopkgtest sudo[1016]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:55 autopkgtest sudo[1016]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:55 autopkgtest sudo[1026]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.lNxcFa 572s Jul 30 23:33:55 autopkgtest sudo[1026]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:55 autopkgtest sudo[1026]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:55 autopkgtest sudo[1036]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.lNxcFa/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.lNxcFa/autopkgtest-reboot-prepare' 572s Jul 30 23:33:55 autopkgtest sudo[1036]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:55 autopkgtest sudo[1036]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:55 autopkgtest sudo[1048]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.lNxcFa/autopkgtest-reboot-prepare 572s Jul 30 23:33:55 autopkgtest sudo[1048]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:56 autopkgtest sudo[1048]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:56 autopkgtest sudo[1058]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.lNxcFa/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 572s Jul 30 23:33:56 autopkgtest sudo[1058]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:56 autopkgtest sudo[1058]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:56 autopkgtest sudo[1068]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 572s Jul 30 23:33:56 autopkgtest sudo[1068]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:56 autopkgtest sudo[1068]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:56 autopkgtest sudo[1078]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 572s Jul 30 23:33:56 autopkgtest sudo[1078]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:56 autopkgtest sudo[1078]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:56 autopkgtest sudo[1088]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.lNxcFa/testbed-packages' 572s Jul 30 23:33:56 autopkgtest sudo[1088]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:56 autopkgtest sudo[1088]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:56 autopkgtest sudo[1099]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.lNxcFa/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.lNxcFa/autopkgtest-reboot' 572s Jul 30 23:33:57 autopkgtest sudo[1120]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:57 autopkgtest sudo[1120]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:57 autopkgtest sudo[1132]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.lNxcFa/autopkgtest-reboot 572s Jul 30 23:33:57 autopkgtest sudo[1132]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:57 autopkgtest sudo[1132]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:57 autopkgtest sudo[1142]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.lNxcFa/autopkgtest-reboot /tmp/autopkgtest-reboot 572s Jul 30 23:33:57 autopkgtest sudo[1142]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:57 autopkgtest sudo[1142]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:57 autopkgtest sudo[1152]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.lNxcFa/autopkgtest-reboot /sbin/autopkgtest-reboot 572s Jul 30 23:33:57 autopkgtest sudo[1152]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:57 autopkgtest sudo[1152]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:58 autopkgtest sudo[1162]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.lNxcFa 572s Jul 30 23:33:58 autopkgtest sudo[1162]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:58 autopkgtest sudo[1162]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:58 autopkgtest sudo[1172]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.lNxcFa/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.lNxcFa/autopkgtest-reboot-prepare' 572s Jul 30 23:33:58 autopkgtest sudo[1172]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:58 autopkgtest sudo[1172]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:58 autopkgtest sudo[1184]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.lNxcFa/autopkgtest-reboot-prepare 572s Jul 30 23:33:58 autopkgtest sudo[1184]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:58 autopkgtest sudo[1184]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:58 autopkgtest sudo[1194]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.lNxcFa/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 572s Jul 30 23:33:58 autopkgtest sudo[1194]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:58 autopkgtest sudo[1194]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:58 autopkgtest sudo[1204]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 572s Jul 30 23:33:58 autopkgtest sudo[1204]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:58 autopkgtest sudo[1204]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:59 autopkgtest sudo[1214]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 572s Jul 30 23:33:59 autopkgtest sudo[1214]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:59 autopkgtest sudo[1214]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:59 autopkgtest sudo[1223]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.lNxcFa 572s Jul 30 23:33:59 autopkgtest sudo[1223]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:59 autopkgtest sudo[1223]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:59 autopkgtest sudo[1233]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.lNxcFa/2-autopkgtest-satdep.deb' 572s Jul 30 23:33:59 autopkgtest sudo[1233]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:59 autopkgtest sudo[1233]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:59 autopkgtest sudo[1244]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.lNxcFa/2-autopkgtest-satdep.deb 572s Jul 30 23:33:59 autopkgtest sudo[1244]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:33:59 autopkgtest sudo[1244]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:33:59 autopkgtest sudo[1254]: 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.lNxcFa/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' 572s Jul 30 23:33:59 autopkgtest sudo[1254]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:34:21 autopkgtest systemd-timesyncd[408]: Contacted time server 91.189.91.157:123 (ntp.ubuntu.com). 572s Jul 30 23:34:21 autopkgtest systemd-timesyncd[408]: Initial clock synchronization to Tue 2024-07-30 23:34:20.995939 UTC. 572s Jul 30 23:34:26 autopkgtest systemd[1]: Reload requested from client PID 1494 ('systemctl') (unit session-1.scope)... 572s Jul 30 23:34:26 autopkgtest systemd[1]: Reloading... 572s Jul 30 23:34:27 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. 572s Jul 30 23:34:27 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. 572s Jul 30 23:34:27 autopkgtest systemd[1]: Reloading finished in 204 ms. 572s Jul 30 23:34:27 autopkgtest systemd[1]: Reload requested from client PID 1544 ('systemctl') (unit session-1.scope)... 572s Jul 30 23:34:27 autopkgtest systemd[1]: Reloading... 572s Jul 30 23:34:27 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. 572s Jul 30 23:34:27 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. 572s Jul 30 23:34:27 autopkgtest systemd[1]: Reloading finished in 208 ms. 572s Jul 30 23:34:27 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 572s Jul 30 23:34:27 autopkgtest tgtd[1589]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 572s Jul 30 23:34:27 autopkgtest tgtd[1589]: tgtd: work_timer_start(146) use timer_fd based scheduler 572s Jul 30 23:34:27 autopkgtest tgtd[1589]: tgtd: bs_init(387) use signalfd notification 572s Jul 30 23:34:27 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 572s Jul 30 23:34:27 autopkgtest systemd[1]: Reload requested from client PID 1617 ('systemctl') (unit session-1.scope)... 572s Jul 30 23:34:27 autopkgtest systemd[1]: Reloading... 572s Jul 30 23:34:28 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. 572s Jul 30 23:34:28 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. 572s Jul 30 23:34:28 autopkgtest systemd[1]: Reloading finished in 194 ms. 572s Jul 30 23:34:28 autopkgtest systemd[1]: Reload requested from client PID 1659 ('systemctl') (unit session-1.scope)... 572s Jul 30 23:34:28 autopkgtest systemd[1]: Reloading... 572s Jul 30 23:34:28 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. 572s Jul 30 23:34:28 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. 572s Jul 30 23:34:28 autopkgtest systemd[1]: Reloading finished in 198 ms. 572s Jul 30 23:34:28 autopkgtest systemd[1]: Reload requested from client PID 1704 ('systemctl') (unit session-1.scope)... 572s Jul 30 23:34:28 autopkgtest systemd[1]: Reloading... 572s Jul 30 23:34:28 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. 572s Jul 30 23:34:28 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. 572s Jul 30 23:34:28 autopkgtest systemd[1]: Reloading finished in 196 ms. 572s Jul 30 23:34:28 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 572s Jul 30 23:34:28 autopkgtest systemd[1]: Reload requested from client PID 1754 ('systemctl') (unit session-1.scope)... 572s Jul 30 23:34:28 autopkgtest systemd[1]: Reloading... 572s Jul 30 23:34:29 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. 572s Jul 30 23:34:29 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. 572s Jul 30 23:34:29 autopkgtest systemd[1]: Reloading finished in 198 ms. 572s Jul 30 23:34:29 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 572s Jul 30 23:34:29 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 572s Jul 30 23:34:29 autopkgtest systemd[1]: Reload requested from client PID 1808 ('systemctl') (unit session-1.scope)... 572s Jul 30 23:34:29 autopkgtest systemd[1]: Reloading... 572s Jul 30 23:34:29 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. 572s Jul 30 23:34:29 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. 572s Jul 30 23:34:29 autopkgtest systemd[1]: Reloading finished in 250 ms. 572s Jul 30 23:34:39 autopkgtest sudo[1254]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:34:39 autopkgtest sudo[5288]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 572s Jul 30 23:34:39 autopkgtest sudo[5288]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:34:39 autopkgtest sudo[5288]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:34:40 autopkgtest sudo[5298]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 572s Jul 30 23:34:40 autopkgtest sudo[5298]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:34:40 autopkgtest sudo[5298]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:34:40 autopkgtest sudo[5308]: 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 572s Jul 30 23:34:40 autopkgtest sudo[5308]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:34:41 autopkgtest sudo[5308]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:34:41 autopkgtest sudo[5321]: 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 572s Jul 30 23:34:41 autopkgtest sudo[5321]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:34:41 autopkgtest sudo[5321]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:34:41 autopkgtest sudo[5333]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 572s Jul 30 23:34:41 autopkgtest sudo[5333]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:34:42 autopkgtest sudo[5333]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:34:42 autopkgtest sudo[5345]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 572s Jul 30 23:34:42 autopkgtest sudo[5345]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:34:42 autopkgtest sudo[5345]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:34:42 autopkgtest sudo[5355]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.lNxcFa/tgtbasedmpaths-packages.all' 572s Jul 30 23:34:42 autopkgtest sudo[5355]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 572s Jul 30 23:34:42 autopkgtest sudo[5355]: pam_unix(sudo:session): session closed for user root 572s Jul 30 23:34:42 autopkgtest sudo[5366]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 576s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 576s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 576s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 576s latency : target=0, window=0, percentile=100.00%, depth=1 576s 576s Run status group 0 (all jobs): 576s WRITE: bw=110MiB/s (115MB/s), 110MiB/s-110MiB/s (115MB/s-115MB/s), io=87.5MiB (91.8MB), run=798-798msec 576s 576s Disk stats (read/write): 576s dm-0: ios=1/1093, sectors=8/152440, merge=0/0, ticks=1/707, in_queue=752, util=86.91%, aggrios=0/350, aggsectors=2/48018, aggrmerge=0/0, aggrticks=11/184, aggrin_queue=195, aggrutil=87.34% 576s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 576s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 576s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 576s sda: ios=2/1403, sectors=8/192072, merge=0/0, ticks=45/737, in_queue=783, util=87.34% 576s + echo Starting the path changes in background 576s + date +Pre FIO %H:%M:%S.%N 576s Starting the path changes in background 576s Pre FIO 23:34:54.663583945 576s + fio --max-jobs=4 /tmp/autopkgtest.lNxcFa/tgtbasedmpaths-artifacts/path-change-check.fio 576s 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 576s fio-3.37 576s Starting 1 thread 757s 757s verify-phase: (groupid=0, jobs=1): err= 0: pid=5718: Tue Jul 30 23:37:54 2024 757s read: IOPS=3674, BW=230MiB/s (241MB/s)(40.4GiB/180001msec) 757s clat (usec): min=85, max=58171, avg=245.65, stdev=267.76 757s lat (usec): min=86, max=58171, avg=245.78, stdev=267.77 757s clat percentiles (usec): 757s | 1.00th=[ 102], 5.00th=[ 127], 10.00th=[ 139], 20.00th=[ 157], 757s | 30.00th=[ 176], 40.00th=[ 192], 50.00th=[ 206], 60.00th=[ 223], 757s | 70.00th=[ 241], 80.00th=[ 265], 90.00th=[ 302], 95.00th=[ 351], 757s | 99.00th=[ 1254], 99.50th=[ 1680], 99.90th=[ 3261], 99.95th=[ 3687], 757s | 99.99th=[ 4948] 757s bw ( KiB/s): min=20864, max=409266, per=100.00%, avg=235541.89, stdev=59607.43, samples=359 757s iops : min= 326, max= 6394, avg=3680.28, stdev=931.35, samples=359 757s lat (usec) : 100=0.83%, 250=73.92%, 500=21.73%, 750=0.45%, 1000=0.73% 757s lat (msec) : 2=1.94%, 4=0.36%, 10=0.03%, 20=0.01%, 50=0.01% 757s lat (msec) : 100=0.01% 757s cpu : usr=10.71%, sys=6.05%, ctx=661670, majf=0, minf=1 757s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 757s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 757s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 757s issued rwts: total=661503,0,0,0 short=0,0,0,0 dropped=0,0,0,0 757s latency : target=0, window=0, percentile=100.00%, depth=1 757s 757s Run status group 0 (all jobs): 757s READ: bw=230MiB/s (241MB/s), 230MiB/s-230MiB/s (241MB/s-241MB/s), io=40.4GiB (43.4GB), run=180001-180001msec 757s 757s Disk stats (read/write): 757s dm-0: ios=661674/8, sectors=84631864/136, merge=19/9, ticks=168249/60, in_queue=168361, util=100.00%, aggrios=40117/2, aggsectors=5130830/34, aggrmerge=0/0, aggrticks=10673/1, aggrin_queue=10674, aggrutil=99.15% 757s sdd: ios=70757/0, sectors=9050240/0, merge=0/0, ticks=16941/0, in_queue=16941, util=39.94% 757s sdb: ios=28379/0, sectors=3627960/0, merge=0/0, ticks=8766/0, in_queue=8766, util=50.07% 757s sdc: ios=31452/0, sectors=4023040/0, merge=0/0, ticks=8646/0, in_queue=8646, util=33.42% 757s sda: ios=29882/8, sectors=3822080/136, merge=0/0, ticks=8339/7, in_queue=8346, util=99.15% 757s + date +Post FIO %H:%M:%S.%N 757s Post FIO 23:37:55.009428667 757s + echo FIO verify test with changing paths - OK 757s + echo Report log of background activity 757s + cat /tmp/autopkgtest.lNxcFa/tgtbasedmpaths-artifacts/test-background.log 757s FIO verify test with changing paths - OK 757s Report log of background activity 757s + iscsiadm --mode session 757s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s + sleep 10s 757s + date +MP report (expect 4) %H:%M:%S.%N 757s MP report (expect 4) 23:35:04.674277088 757s + multipath -ll 757s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 757s size=100M features='0' hwhandler='0' wp=rw 757s |-+- policy='service-time 0' prio=1 status=active 757s | `- 0:0:0:1 sda 8:0 active ready running 757s |-+- policy='service-time 0' prio=1 status=enabled 757s | `- 1:0:0:1 sdb 8:16 active ready running 757s |-+- policy='service-time 0' prio=1 status=enabled 757s | `- 2:0:0:1 sdc 8:32 active ready running 757s `-+- policy='service-time 0' prio=1 status=enabled 757s `- 3:0:0:1 sdd 8:48 active ready running 757s + date +UN-plug path 1 %H:%M:%S.%N 757s UN-plug path 1 23:35:04.700119535 757s + iscsiadm --mode session -r 1 -u 757s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 757s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 757s + iscsiadm --mode session 757s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s + sleep 10s 757s + date +MP report (expect 3) %H:%M:%S.%N 757s MP report (expect 3) 23:35:14.805044743 757s + multipath -ll 757s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 757s size=100M features='0' hwhandler='0' wp=rw 757s |-+- policy='service-time 0' prio=1 status=active 757s | `- 1:0:0:1 sdb 8:16 active ready running 757s |-+- policy='service-time 0' prio=1 status=enabled 757s | `- 2:0:0:1 sdc 8:32 active ready running 757s `-+- policy='service-time 0' prio=1 status=enabled 757s `- 3:0:0:1 sdd 8:48 active ready running 757s + date +UN-plug path 2 %H:%M:%S.%N 757s UN-plug path 2 23:35:14.833729945 757s + iscsiadm --mode session -r 2 -u 757s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 757s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 757s + iscsiadm --mode session 757s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s + sleep 10s 757s + date +MP report (expect 2) %H:%M:%S.%N 757s MP report (expect 2) 23:35:24.960476464 757s + multipath -ll 757s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 757s size=100M features='0' hwhandler='0' wp=rw 757s |-+- policy='service-time 0' prio=1 status=active 757s | `- 2:0:0:1 sdc 8:32 active ready running 757s `-+- policy='service-time 0' prio=1 status=enabled 757s `- 3:0:0:1 sdd 8:48 active ready running 757s + date +UN-plug path 3 %H:%M:%S.%N 757s UN-plug path 3 23:35:24.980183775 757s + iscsiadm --mode session -r 3 -u 757s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 757s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 757s + iscsiadm --mode session 757s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s + sleep 10s 757s + date +MP report (expect 1) %H:%M:%S.%N 757s MP report (expect 1) 23:35:35.073281882 757s + multipath -ll 757s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 757s size=100M features='0' hwhandler='0' wp=rw 757s `-+- policy='service-time 0' prio=1 status=active 757s `- 3:0:0:1 sdd 8:48 active ready running 757s + date +Add paths 5/6/7/8 %H:%M:%S.%N 757s Add paths 5/6/7/8 23:35:35.092392613 757s + iscsiadm --mode session -r 4 --op new 757s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 757s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 757s + iscsiadm --mode session -r 4 --op new 757s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 757s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 757s + iscsiadm --mode session -r 4 --op new 757s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 757s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 757s + iscsiadm --mode session -r 4 --op new 757s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 757s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 757s + iscsiadm --mode session 757s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s + sleep 10s 757s + date +MP report (expect 5) %H:%M:%S.%N 757s MP report (expect 5) 23:35:45.189687349 757s + multipath -ll 757s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 757s size=100M features='0' hwhandler='0' wp=rw 757s |-+- policy='service-time 0' prio=1 status=active 757s | `- 3:0:0:1 sdd 8:48 active ready running 757s |-+- policy='service-time 0' prio=1 status=enabled 757s | `- 0:0:0:1 sda 8:0 active ready running 757s |-+- policy='service-time 0' prio=1 status=enabled 757s | `- 1:0:0:1 sdb 8:16 active ready running 757s |-+- policy='service-time 0' prio=1 status=enabled 757s | `- 2:0:0:1 sdc 8:32 active ready running 757s `-+- policy='service-time 0' prio=1 status=enabled 757s `- 4:0:0:1 sde 8:64 active ready running 757s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 757s UN-plug multiple paths 4/7/8 23:35:45.226572438 757s + iscsiadm --mode session -r 4 -u 757s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 757s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 757s + iscsiadm --mode session -r 7 -u 757s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 757s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 757s + iscsiadm --mode session -r 8 -u 757s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 757s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 757s + iscsiadm --mode session 757s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 757s + sleep 10s 757s + date +Restart multipath daemon %H:%M:%S.%N 757s Restart multipath daemon 23:35:55.545588544 757s + systemctl restart multipathd 757s + sleep 10s 757s + date +Final background report (expect 2) %H:%M:%S.%N 757s Final background report (expect 2) 23:36:05.620142079 757s + multipath -ll 757s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 757s size=100M features='0' hwhandler='0' wp=rw 757s |-+- policy='service-time 0' prio=1 status=active 757s | `- 0:0:0:1 sda 8:0 active ready running 757s `-+- policy='service-time 0' prio=1 status=enabled 757s `- 1:0:0:1 sdb 8:16 active ready running 757s Final stats 757s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 757s iSCSI SNMP: 757s txdata_octets: 24048888 757s rxdata_octets: 32811895140 757s noptx_pdus: 0 757s scsicmd_pdus: 500751 757s tmfcmd_pdus: 0 757s login_pdus: 0 757s text_pdus: 0 757s dataout_pdus: 0 757s logout_pdus: 0 757s snack_pdus: 0 757s noprx_pdus: 0 757s scsirsp_pdus: 500751 757s tmfrsp_pdus: 0 757s textrsp_pdus: 0 757s datain_pdus: 500718 757s logoutrsp_pdus: 0 757s r2t_pdus: 0 757s async_pdus: 0 757s rjt_pdus: 0 757s digest_err: 0 757s timeout_err: 0 757s iSCSI Extended: 757s tx_sendpage_failures: 0 757s rx_discontiguous_hdr: 0 757s eh_abort_cnt: 0 757s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 757s iSCSI SNMP: 757s txdata_octets: 6456 757s rxdata_octets: 1514916 757s noptx_pdus: 0 757s scsicmd_pdus: 105 757s tmfcmd_pdus: 0 757s login_pdus: 0 757s text_pdus: 0 757s dataout_pdus: 0 757s logout_pdus: 0 757s snack_pdus: 0 757s noprx_pdus: 0 757s scsirsp_pdus: 105 757s tmfrsp_pdus: 0 757s textrsp_pdus: 0 757s datain_pdus: 83 757s logoutrsp_pdus: 0 757s r2t_pdus: 0 757s async_pdus: 0 757s rjt_pdus: 0 757s digest_err: 0 757s timeout_err: 0 757s iSCSI Extended: 757s tx_sendpage_failures: 0 757s rx_discontiguous_hdr: 0 757s eh_abort_cnt: 0 757s Jul 30 11:46:15 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 757s Jul 30 11:46:15 ubuntu multipathd[364]: multipathd v0.9.4: start up 757s Jul 30 11:46:15 ubuntu multipathd[364]: reconfigure: setting up paths and maps 757s Jul 30 11:46:15 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 757s Jul 30 11:48:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[364]: multipathd: shut down 757s Jul 30 11:48:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 757s Jul 30 11:48:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 757s Jul 30 11:48:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 757s Jul 30 11:48:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 757s Jul 30 11:48:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[11832]: multipathd v0.9.4: start up 757s Jul 30 11:48:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[11832]: reconfigure: setting up paths and maps 757s Jul 30 11:48:31 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 757s Jul 30 11:49:50 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 757s Jul 30 11:49:50 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[11832]: multipathd: shut down 757s Jul 30 11:49:50 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 757s Jul 30 11:49:50 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 757s -- Boot daa3a23e5730480ab695ff89d750ad0a -- 757s Jul 30 11:50:03 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 757s Jul 30 11:50:03 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[306]: multipathd v0.9.9: start up 757s Jul 30 11:50:03 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[306]: reconfigure: setting up paths and maps 757s Jul 30 11:50:03 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 757s Jul 30 11:50:18 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 757s Jul 30 11:50:18 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[306]: multipathd: shut down 757s Jul 30 11:50:18 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 757s Jul 30 11:50:18 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 757s -- Boot 58a3f9214ab549b4a394ac0bc4ca7567 -- 757s Jul 30 23:30:16 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 757s Jul 30 23:30:16 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[333]: multipathd v0.9.9: start up 757s Jul 30 23:30:16 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[333]: reconfigure: setting up paths and maps 757s Jul 30 23:30:16 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 757s Jul 30 23:33:30 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 757s Jul 30 23:33:30 autopkgtest multipathd[333]: multipathd: shut down 757s Jul 30 23:33:30 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 757s Jul 30 23:33:30 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 757s -- Boot c9570582c680430cb901077b2be57a24 -- 757s Jul 30 23:33:42 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 757s Jul 30 23:33:42 autopkgtest multipathd[326]: multipathd v0.9.9: start up 757s Jul 30 23:33:42 autopkgtest multipathd[326]: reconfigure: setting up paths and maps 757s Jul 30 23:33:42 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 757s Jul 30 23:34:45 autopkgtest multipathd[326]: updated bindings file /etc/multipath/bindings 757s Jul 30 23:34:45 autopkgtest multipathd[326]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 757s Jul 30 23:34:45 autopkgtest multipathd[326]: sda [8:0]: path added to devmap mpatha 757s Jul 30 23:34:45 autopkgtest multipathd[326]: mpatha: performing delayed actions 757s Jul 30 23:34:45 autopkgtest multipathd[326]: 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] 757s Jul 30 23:35:04 autopkgtest multipathd[326]: 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] 757s Jul 30 23:35:04 autopkgtest multipathd[326]: check_removed_paths: sda: freeing path in removed state 757s Jul 30 23:35:04 autopkgtest multipathd[326]: 8:0: path removed from map mpatha 757s Jul 30 23:35:14 autopkgtest multipathd[326]: 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] 757s Jul 30 23:35:14 autopkgtest multipathd[326]: check_removed_paths: sdb: freeing path in removed state 757s Jul 30 23:35:14 autopkgtest multipathd[326]: 8:16: path removed from map mpatha 757s Jul 30 23:35:25 autopkgtest multipathd[326]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 757s Jul 30 23:35:25 autopkgtest multipathd[326]: check_removed_paths: sdc: freeing path in removed state 757s Jul 30 23:35:25 autopkgtest multipathd[326]: 8:32: path removed from map mpatha 757s Jul 30 23:35:35 autopkgtest multipathd[326]: 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] 757s Jul 30 23:35:35 autopkgtest multipathd[326]: sda [8:0]: path added to devmap mpatha 757s Jul 30 23:35:35 autopkgtest multipathd[326]: 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] 757s Jul 30 23:35:35 autopkgtest multipathd[326]: sdb [8:16]: path added to devmap mpatha 757s Jul 30 23:35:35 autopkgtest multipathd[326]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 757s Jul 30 23:35:35 autopkgtest multipathd[326]: sdc [8:32]: path added to devmap mpatha 757s Jul 30 23:35:35 autopkgtest multipathd[326]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 757s Jul 30 23:35:35 autopkgtest multipathd[326]: sde [8:64]: path added to devmap mpatha 757s Jul 30 23:35:45 autopkgtest multipathd[326]: sdd: mark as failed 757s Jul 30 23:35:45 autopkgtest multipathd[326]: mpatha: remaining active paths: 4 757s Jul 30 23:35:45 autopkgtest multipathd[326]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 757s Jul 30 23:35:45 autopkgtest multipathd[326]: check_removed_paths: sdd: freeing path in removed state 757s Jul 30 23:35:45 autopkgtest multipathd[326]: 8:48: path removed from map mpatha 757s Jul 30 23:35:45 autopkgtest multipathd[326]: 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] 757s Jul 30 23:35:45 autopkgtest multipathd[326]: check_removed_paths: sdc: freeing path in removed state 757s Jul 30 23:35:45 autopkgtest multipathd[326]: 8:32: path removed from map mpatha 757s Jul 30 23:35:45 autopkgtest multipathd[326]: 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] 757s Jul 30 23:35:45 autopkgtest multipathd[326]: check_removed_paths: sde: freeing path in removed state 757s Jul 30 23:35:45 autopkgtest multipathd[326]: 8:64: path removed from map mpatha 757s Jul 30 23:35:55 autopkgtest multipathd[326]: multipathd: shut down 757s Jul 30 23:35:55 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 757s Jul 30 23:35:55 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 757s Jul 30 23:35:55 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 757s Jul 30 23:35:55 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 757s Jul 30 23:35:55 autopkgtest multipathd[6092]: multipathd v0.9.9: start up 757s Jul 30 23:35:55 autopkgtest multipathd[6092]: reconfigure: setting up paths and maps 757s Jul 30 23:35:55 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 757s Check final path status 757s + sync 757s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 757s + echo Final stats 757s + iscsiadm --mode session --stats 757s + journalctl --no-pager -u multipathd 757s + echo Check final path status 757s + multipath -ll 757s + multipath -ll 757s + grep --count status= 757s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 757s size=100M features='0' hwhandler='0' wp=rw 757s |-+- policy='service-time 0' prio=1 status=active 757s | `- 0:0:0:1 sda 8:0 active ready running 757s `-+- policy='service-time 0' prio=1 status=enabled 757s `- 1:0:0:1 sdb 8:16 active ready running 757s + diskc=2 757s + multipath -ll 757s + grep --count status=active 757s + diska=1 757s + grep --count status=enabled 757s + multipath -ll 757s OK 757s + diske=1 757s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 757s + echo OK 757s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 757s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 757s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 757s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 757s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 757s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 757s autopkgtest [23:37:55]: test tgtbasedmpaths: -----------------------] 758s tgtbasedmpaths PASS 758s autopkgtest [23:37:56]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 758s autopkgtest [23:37:56]: @@@@@@@@@@@@@@@@@@@@ summary 758s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 758s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 758s kpartx-file-loopback PASS 758s tgtbasedmpaths PASS 763s nova [W] Using flock in prodstack6-ppc64el 763s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240730-232518-juju-7f2275-prod-proposed-migration-environment-3-d254f06f-2231-40ff-93c4-56ca5f003403 from image adt/ubuntu-oracular-ppc64el-server-20240730.img (UUID 4f34630a-a275-4259-be36-01bd7a869e9c)... 763s nova [W] Using flock in prodstack6-ppc64el 763s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240730-232518-juju-7f2275-prod-proposed-migration-environment-3-d254f06f-2231-40ff-93c4-56ca5f003403 from image adt/ubuntu-oracular-ppc64el-server-20240730.img (UUID 4f34630a-a275-4259-be36-01bd7a869e9c)...