0s autopkgtest [17:14:22]: starting date and time: 2024-09-09 17:14:22+0000 0s autopkgtest [17:14:22]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [17:14:22]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.scsh865e/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:systemd --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=systemd/256.5-2ubuntu2 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big-ppc64el --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos03-ppc64el-36.secgroup --name adt-oracular-ppc64el-multipath-tools-20240909-171422-juju-7f2275-prod-proposed-migration-environment-2-dfcc926e-cc0e-4e9a-8fef-a9dbd88708c3 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --net-id=net_prod-proposed-migration-ppc64el -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 378s autopkgtest [17:20:40]: testbed dpkg architecture: ppc64el 389s autopkgtest [17:20:51]: testbed apt version: 2.9.8 389s autopkgtest [17:20:51]: @@@@@@@@@@@@@@@@@@@@ test bed setup 399s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 399s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [7284 B] 400s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8424 B] 400s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.7 kB] 400s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [712 kB] 400s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [49.6 kB] 400s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [1252 B] 400s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1372 B] 400s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 400s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [654 kB] 400s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [14.2 kB] 400s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [3616 B] 400s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [340 B] 401s Fetched 1617 kB in 1s (1794 kB/s) 402s Reading package lists... 419s Reading package lists... 419s Building dependency tree... 419s Reading state information... 419s Calculating upgrade... 419s The following packages will be upgraded: 419s libnss-systemd libpam-systemd libsystemd-shared libsystemd0 libudev1 systemd 419s systemd-cryptsetup systemd-dev systemd-resolved systemd-sysv 419s systemd-timesyncd udev 419s 12 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 419s Need to get 10.4 MB of archives. 419s After this operation, 12.3 kB of additional disk space will be used. 419s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-dev all 256.5-2ubuntu2 [114 kB] 420s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-timesyncd ppc64el 256.5-2ubuntu2 [42.4 kB] 420s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-resolved ppc64el 256.5-2ubuntu2 [368 kB] 420s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-cryptsetup ppc64el 256.5-2ubuntu2 [127 kB] 420s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd-shared ppc64el 256.5-2ubuntu2 [2502 kB] 420s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd0 ppc64el 256.5-2ubuntu2 [564 kB] 420s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-sysv ppc64el 256.5-2ubuntu2 [11.9 kB] 420s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnss-systemd ppc64el 256.5-2ubuntu2 [214 kB] 420s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpam-systemd ppc64el 256.5-2ubuntu2 [326 kB] 420s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd ppc64el 256.5-2ubuntu2 [3746 kB] 420s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el udev ppc64el 256.5-2ubuntu2 [2140 kB] 420s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libudev1 ppc64el 256.5-2ubuntu2 [223 kB] 420s Fetched 10.4 MB in 1s (10.3 MB/s) 421s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72411 files and directories currently installed.) 421s Preparing to unpack .../0-systemd-dev_256.5-2ubuntu2_all.deb ... 421s Unpacking systemd-dev (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 421s Preparing to unpack .../1-systemd-timesyncd_256.5-2ubuntu2_ppc64el.deb ... 421s Unpacking systemd-timesyncd (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 421s Preparing to unpack .../2-systemd-resolved_256.5-2ubuntu2_ppc64el.deb ... 421s Unpacking systemd-resolved (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 421s Preparing to unpack .../3-systemd-cryptsetup_256.5-2ubuntu2_ppc64el.deb ... 421s Unpacking systemd-cryptsetup (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 421s Preparing to unpack .../4-libsystemd-shared_256.5-2ubuntu2_ppc64el.deb ... 421s Unpacking libsystemd-shared:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 421s Preparing to unpack .../5-libsystemd0_256.5-2ubuntu2_ppc64el.deb ... 421s Unpacking libsystemd0:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 421s Setting up libsystemd0:ppc64el (256.5-2ubuntu2) ... 421s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72411 files and directories currently installed.) 421s Preparing to unpack .../0-systemd-sysv_256.5-2ubuntu2_ppc64el.deb ... 421s Unpacking systemd-sysv (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 421s Preparing to unpack .../1-libnss-systemd_256.5-2ubuntu2_ppc64el.deb ... 421s Unpacking libnss-systemd:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 421s Preparing to unpack .../2-libpam-systemd_256.5-2ubuntu2_ppc64el.deb ... 421s Unpacking libpam-systemd:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 421s Preparing to unpack .../3-systemd_256.5-2ubuntu2_ppc64el.deb ... 421s Unpacking systemd (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 421s Preparing to unpack .../4-udev_256.5-2ubuntu2_ppc64el.deb ... 421s Unpacking udev (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 421s Preparing to unpack .../5-libudev1_256.5-2ubuntu2_ppc64el.deb ... 421s Unpacking libudev1:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 421s Setting up libudev1:ppc64el (256.5-2ubuntu2) ... 421s Setting up systemd-dev (256.5-2ubuntu2) ... 421s Setting up libsystemd-shared:ppc64el (256.5-2ubuntu2) ... 421s Setting up systemd (256.5-2ubuntu2) ... 421s Installing new version of config file /etc/systemd/journald.conf ... 421s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 421s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 422s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 422s Setting up systemd-cryptsetup (256.5-2ubuntu2) ... 422s Setting up systemd-timesyncd (256.5-2ubuntu2) ... 423s systemd-time-wait-sync.service is a disabled or a static unit not running, not starting it. 423s Setting up udev (256.5-2ubuntu2) ... 423s Setting up systemd-resolved (256.5-2ubuntu2) ... 424s Setting up systemd-sysv (256.5-2ubuntu2) ... 424s Setting up libnss-systemd:ppc64el (256.5-2ubuntu2) ... 424s Setting up libpam-systemd:ppc64el (256.5-2ubuntu2) ... 424s Processing triggers for libc-bin (2.40-1ubuntu1) ... 424s Processing triggers for man-db (2.12.1-3) ... 426s Processing triggers for dbus (1.14.10-4ubuntu5) ... 426s Processing triggers for shared-mime-info (2.4-5) ... 426s Processing triggers for initramfs-tools (0.142ubuntu33) ... 426s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 426s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 433s Reading package lists... 433s Building dependency tree... 433s Reading state information... 434s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 438s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 438s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 438s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 439s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 439s Reading package lists... 439s Reading package lists... 440s Building dependency tree... 440s Reading state information... 440s Calculating upgrade... 440s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 440s Reading package lists... 440s Building dependency tree... 440s Reading state information... 440s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 441s autopkgtest [17:21:43]: rebooting testbed after setup commands that affected boot 564s autopkgtest [17:23:46]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 731s autopkgtest [17:26:33]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 903s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (dsc) [2772 B] 903s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (tar) [588 kB] 903s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu3 (diff) [42.7 kB] 904s gpgv: Signature made Thu Sep 5 17:42:16 2024 UTC 904s gpgv: using RSA key 63EEFC3DE14D5146CE7F24BF34B8AD7D9529E793 904s gpgv: Can't check signature: No public key 904s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.9-1ubuntu3.dsc: no acceptable signature found 904s autopkgtest [17:29:26]: testing package multipath-tools version 0.9.9-1ubuntu3 910s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 910s autopkgtest [17:29:32]: build not needed 921s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 921s autopkgtest [17:29:43]: test kpartx-file-loopback: preparing testbed 973s Reading package lists... 974s Building dependency tree... 974s Reading state information... 974s Starting pkgProblemResolver with broken count: 0 974s Starting 2 pkgProblemResolver with broken count: 0 974s Done 974s The following additional packages will be installed: 974s liburing2 qemu-utils 974s Recommended packages: 974s qemu-block-extra 974s The following NEW packages will be installed: 974s autopkgtest-satdep liburing2 qemu-utils 974s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 974s Need to get 2432 kB/2433 kB of archives. 974s After this operation, 16.9 MB of additional disk space will be used. 974s Get:1 /tmp/autopkgtest.d4ADz3/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 974s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 974s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:9.0.2+ds-4ubuntu3 [2405 kB] 975s Fetched 2432 kB in 1s (3538 kB/s) 975s Selecting previously unselected package liburing2:ppc64el. 975s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72411 files and directories currently installed.) 975s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 975s Unpacking liburing2:ppc64el (2.6-1) ... 975s Selecting previously unselected package qemu-utils. 975s Preparing to unpack .../qemu-utils_1%3a9.0.2+ds-4ubuntu3_ppc64el.deb ... 975s Unpacking qemu-utils (1:9.0.2+ds-4ubuntu3) ... 975s Selecting previously unselected package autopkgtest-satdep. 975s Preparing to unpack .../1-autopkgtest-satdep.deb ... 975s Unpacking autopkgtest-satdep (0) ... 975s Setting up liburing2:ppc64el (2.6-1) ... 975s Setting up qemu-utils (1:9.0.2+ds-4ubuntu3) ... 975s Setting up autopkgtest-satdep (0) ... 975s Processing triggers for man-db (2.12.1-3) ... 977s Processing triggers for libc-bin (2.40-1ubuntu1) ... 992s (Reading database ... 72435 files and directories currently installed.) 992s Removing autopkgtest-satdep (0) ... 1003s autopkgtest [17:31:05]: test kpartx-file-loopback: [----------------------- 1007s Formatting 'foo.img', fmt=raw size=20971520 1008s Creating new GPT entries in memory. 1008s Warning: The kernel is still using the old partition table. 1008s The new table will be used at the next reboot or after you 1008s run partprobe(8) or kpartx(8) 1008s The operation has completed successfully. 1008s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 1008s standard_filename: OK 1008s del devmap : loop0p1 1008s No devices found 1008s standard_filename_cleanup: OK 1008s Formatting 'fou du FaFa.img', fmt=raw size=20971520 1009s Creating new GPT entries in memory. 1009s Warning: The kernel is still using the old partition table. 1009s The new table will be used at the next reboot or after you 1009s run partprobe(8) or kpartx(8) 1009s The operation has completed successfully. 1009s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 1009s filename_with_spaces: OK 1009s del devmap : loop0p1 1009s No devices found 1009s filename_with_spaces_cleanup: OK 1010s autopkgtest [17:31:12]: test kpartx-file-loopback: -----------------------] 1022s kpartx-file-loopback PASS 1022s autopkgtest [17:31:24]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 1034s autopkgtest [17:31:36]: test tgtbasedmpaths: preparing testbed 1277s autopkgtest [17:35:39]: testbed dpkg architecture: ppc64el 1278s autopkgtest [17:35:40]: testbed apt version: 2.9.8 1278s autopkgtest [17:35:40]: @@@@@@@@@@@@@@@@@@@@ test bed setup 1292s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 1293s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [7284 B] 1293s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [712 kB] 1293s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [38.7 kB] 1293s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8424 B] 1293s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [49.6 kB] 1293s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [1252 B] 1293s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1372 B] 1293s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 1293s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [654 kB] 1293s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [14.2 kB] 1293s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [3616 B] 1293s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [340 B] 1295s Fetched 1617 kB in 1s (1738 kB/s) 1295s Reading package lists... 1298s Reading package lists... 1298s Building dependency tree... 1298s Reading state information... 1298s Calculating upgrade... 1298s The following packages will be upgraded: 1298s libnss-systemd libpam-systemd libsystemd-shared libsystemd0 libudev1 systemd 1298s systemd-cryptsetup systemd-dev systemd-resolved systemd-sysv 1298s systemd-timesyncd udev 1298s 12 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1298s Need to get 10.4 MB of archives. 1298s After this operation, 12.3 kB of additional disk space will be used. 1298s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-dev all 256.5-2ubuntu2 [114 kB] 1299s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-timesyncd ppc64el 256.5-2ubuntu2 [42.4 kB] 1299s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-resolved ppc64el 256.5-2ubuntu2 [368 kB] 1299s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-cryptsetup ppc64el 256.5-2ubuntu2 [127 kB] 1299s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd-shared ppc64el 256.5-2ubuntu2 [2502 kB] 1299s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd0 ppc64el 256.5-2ubuntu2 [564 kB] 1299s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-sysv ppc64el 256.5-2ubuntu2 [11.9 kB] 1299s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnss-systemd ppc64el 256.5-2ubuntu2 [214 kB] 1299s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpam-systemd ppc64el 256.5-2ubuntu2 [326 kB] 1299s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd ppc64el 256.5-2ubuntu2 [3746 kB] 1299s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el udev ppc64el 256.5-2ubuntu2 [2140 kB] 1299s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libudev1 ppc64el 256.5-2ubuntu2 [223 kB] 1300s Fetched 10.4 MB in 1s (11.7 MB/s) 1300s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72411 files and directories currently installed.) 1300s Preparing to unpack .../0-systemd-dev_256.5-2ubuntu2_all.deb ... 1300s Unpacking systemd-dev (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 1300s Preparing to unpack .../1-systemd-timesyncd_256.5-2ubuntu2_ppc64el.deb ... 1300s Unpacking systemd-timesyncd (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 1300s Preparing to unpack .../2-systemd-resolved_256.5-2ubuntu2_ppc64el.deb ... 1300s Unpacking systemd-resolved (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 1300s Preparing to unpack .../3-systemd-cryptsetup_256.5-2ubuntu2_ppc64el.deb ... 1300s Unpacking systemd-cryptsetup (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 1300s Preparing to unpack .../4-libsystemd-shared_256.5-2ubuntu2_ppc64el.deb ... 1300s Unpacking libsystemd-shared:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 1300s Preparing to unpack .../5-libsystemd0_256.5-2ubuntu2_ppc64el.deb ... 1300s Unpacking libsystemd0:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 1300s Setting up libsystemd0:ppc64el (256.5-2ubuntu2) ... 1300s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72411 files and directories currently installed.) 1300s Preparing to unpack .../0-systemd-sysv_256.5-2ubuntu2_ppc64el.deb ... 1300s Unpacking systemd-sysv (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 1300s Preparing to unpack .../1-libnss-systemd_256.5-2ubuntu2_ppc64el.deb ... 1300s Unpacking libnss-systemd:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 1300s Preparing to unpack .../2-libpam-systemd_256.5-2ubuntu2_ppc64el.deb ... 1300s Unpacking libpam-systemd:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 1300s Preparing to unpack .../3-systemd_256.5-2ubuntu2_ppc64el.deb ... 1300s Unpacking systemd (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 1300s Preparing to unpack .../4-udev_256.5-2ubuntu2_ppc64el.deb ... 1300s Unpacking udev (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 1301s Preparing to unpack .../5-libudev1_256.5-2ubuntu2_ppc64el.deb ... 1301s Unpacking libudev1:ppc64el (256.5-2ubuntu2) over (256.4-2ubuntu1) ... 1301s Setting up libudev1:ppc64el (256.5-2ubuntu2) ... 1301s Setting up systemd-dev (256.5-2ubuntu2) ... 1301s Setting up libsystemd-shared:ppc64el (256.5-2ubuntu2) ... 1301s Setting up systemd (256.5-2ubuntu2) ... 1301s Installing new version of config file /etc/systemd/journald.conf ... 1301s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 1301s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 1302s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 1302s Setting up systemd-cryptsetup (256.5-2ubuntu2) ... 1302s Setting up systemd-timesyncd (256.5-2ubuntu2) ... 1302s systemd-time-wait-sync.service is a disabled or a static unit not running, not starting it. 1302s Setting up udev (256.5-2ubuntu2) ... 1303s Setting up systemd-resolved (256.5-2ubuntu2) ... 1304s Setting up systemd-sysv (256.5-2ubuntu2) ... 1304s Setting up libnss-systemd:ppc64el (256.5-2ubuntu2) ... 1304s Setting up libpam-systemd:ppc64el (256.5-2ubuntu2) ... 1304s Processing triggers for libc-bin (2.40-1ubuntu1) ... 1304s Processing triggers for man-db (2.12.1-3) ... 1306s Processing triggers for dbus (1.14.10-4ubuntu5) ... 1306s Processing triggers for shared-mime-info (2.4-5) ... 1306s Processing triggers for initramfs-tools (0.142ubuntu33) ... 1306s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 1306s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 1316s Reading package lists... 1316s Building dependency tree... 1316s Reading state information... 1316s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1335s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 1336s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 1336s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 1336s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 1337s Reading package lists... 1337s Reading package lists... 1339s Building dependency tree... 1339s autopkgtest [17:36:40]: rebooting testbed after setup commands that affected boot 1339s Reading state information... 1339s Calculating upgrade... 1339s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1339s Reading package lists... 1339s Building dependency tree... 1339s Reading state information... 1339s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1342s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 1642s Reading package lists... 1643s Building dependency tree... 1643s Reading state information... 1643s Starting pkgProblemResolver with broken count: 0 1643s Starting 2 pkgProblemResolver with broken count: 0 1643s Done 1643s The following additional packages will be installed: 1643s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 1643s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 1643s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 1643s librdmacm1t64 lsscsi open-iscsi tgt 1643s Suggested packages: 1643s fio-examples gnuplot tgt-glusterfs tgt-rbd 1643s Recommended packages: 1643s finalrd 1643s The following NEW packages will be installed: 1643s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 1643s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 1643s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 1643s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 1643s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 1643s Need to get 11.0 MB/11.0 MB of archives. 1643s After this operation, 50.0 MB of additional disk space will be used. 1643s Get:1 /tmp/autopkgtest.d4ADz3/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 1643s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 1644s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 1644s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 1644s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2ubuntu1 [80.6 kB] 1644s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 1644s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 1644s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-5ubuntu1 [21.7 kB] 1644s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-5ubuntu1 [308 kB] 1644s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-5ubuntu1 [46.3 kB] 1644s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-5ubuntu1 [99.1 kB] 1644s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-2 [98.5 kB] 1644s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2.2ubuntu1 [23.7 kB] 1644s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2.2ubuntu1 [73.4 kB] 1644s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 1644s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3.2ubuntu2 [260 kB] 1644s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3.2ubuntu2 [281 kB] 1644s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~rc2-0ubuntu1 [4194 kB] 1644s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 1644s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~rc2-0ubuntu1 [3714 kB] 1644s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 1644s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 1645s Preconfiguring packages ... 1645s Fetched 11.0 MB in 1s (11.1 MB/s) 1645s Selecting previously unselected package libopeniscsiusr. 1645s (Reading database ... (Reading database ... 5% (Reading database ... 10% (Reading database ... 15% (Reading database ... 20% (Reading database ... 25% (Reading database ... 30% (Reading database ... 35% (Reading database ... 40% (Reading database ... 45% (Reading database ... 50% (Reading database ... 55% (Reading database ... 60% (Reading database ... 65% (Reading database ... 70% (Reading database ... 75% (Reading database ... 80% (Reading database ... 85% (Reading database ... 90% (Reading database ... 95% (Reading database ... 100% (Reading database ... 72411 files and directories currently installed.) 1645s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 1645s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 1645s Selecting previously unselected package libisns0t64:ppc64el. 1645s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 1645s Unpacking libisns0t64:ppc64el (0.101-1) ... 1645s Selecting previously unselected package open-iscsi. 1645s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 1645s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 1645s Selecting previously unselected package librdmacm1t64:ppc64el. 1645s Preparing to unpack .../03-librdmacm1t64_52.0-2ubuntu1_ppc64el.deb ... 1645s Unpacking librdmacm1t64:ppc64el (52.0-2ubuntu1) ... 1645s Selecting previously unselected package libconfig-general-perl. 1645s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 1645s Unpacking libconfig-general-perl (2.65-2) ... 1645s Selecting previously unselected package tgt. 1645s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 1645s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 1645s Selecting previously unselected package libgfxdr0:ppc64el. 1645s Preparing to unpack .../06-libgfxdr0_11.1-5ubuntu1_ppc64el.deb ... 1645s Unpacking libgfxdr0:ppc64el (11.1-5ubuntu1) ... 1645s Selecting previously unselected package libglusterfs0:ppc64el. 1645s Preparing to unpack .../07-libglusterfs0_11.1-5ubuntu1_ppc64el.deb ... 1645s Unpacking libglusterfs0:ppc64el (11.1-5ubuntu1) ... 1645s Selecting previously unselected package libgfrpc0:ppc64el. 1645s Preparing to unpack .../08-libgfrpc0_11.1-5ubuntu1_ppc64el.deb ... 1645s Unpacking libgfrpc0:ppc64el (11.1-5ubuntu1) ... 1645s Selecting previously unselected package libgfapi0:ppc64el. 1645s Preparing to unpack .../09-libgfapi0_11.1-5ubuntu1_ppc64el.deb ... 1645s Unpacking libgfapi0:ppc64el (11.1-5ubuntu1) ... 1645s Selecting previously unselected package libnbd0. 1645s Preparing to unpack .../10-libnbd0_1.20.2-2_ppc64el.deb ... 1645s Unpacking libnbd0 (1.20.2-2) ... 1645s Selecting previously unselected package libdaxctl1:ppc64el. 1645s Preparing to unpack .../11-libdaxctl1_77-2.2ubuntu1_ppc64el.deb ... 1645s Unpacking libdaxctl1:ppc64el (77-2.2ubuntu1) ... 1645s Selecting previously unselected package libndctl6:ppc64el. 1645s Preparing to unpack .../12-libndctl6_77-2.2ubuntu1_ppc64el.deb ... 1645s Unpacking libndctl6:ppc64el (77-2.2ubuntu1) ... 1645s Selecting previously unselected package libpmem1:ppc64el. 1645s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 1645s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 1645s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 1645s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 1645s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 1645s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 1645s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3.2ubuntu2_ppc64el.deb ... 1645s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 1646s Selecting previously unselected package librados2. 1646s Preparing to unpack .../16-librados2_19.2.0~rc2-0ubuntu1_ppc64el.deb ... 1665s Unpacking librados2 (19.2.0~rc2-0ubuntu1) ... 1665s Selecting previously unselected package libpmemobj1:ppc64el. 1665s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 1665s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 1665s Selecting previously unselected package librbd1. 1665s Preparing to unpack .../18-librbd1_19.2.0~rc2-0ubuntu1_ppc64el.deb ... 1665s Unpacking librbd1 (19.2.0~rc2-0ubuntu1) ... 1665s Selecting previously unselected package fio. 1665s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 1665s Unpacking fio (3.37-1) ... 1665s Selecting previously unselected package lsscsi. 1665s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 1665s Unpacking lsscsi (0.32-1build1) ... 1665s Selecting previously unselected package autopkgtest-satdep. 1665s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 1665s Unpacking autopkgtest-satdep (0) ... 1665s Setting up libconfig-general-perl (2.65-2) ... 1665s Setting up libisns0t64:ppc64el (0.101-1) ... 1665s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 1665s Setting up libnbd0 (1.20.2-2) ... 1665s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 1665s Setting up libglusterfs0:ppc64el (11.1-5ubuntu1) ... 1665s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3.2ubuntu2) ... 1665s Setting up lsscsi (0.32-1build1) ... 1665s Setting up libdaxctl1:ppc64el (77-2.2ubuntu1) ... 1665s Setting up libndctl6:ppc64el (77-2.2ubuntu1) ... 1665s Setting up librdmacm1t64:ppc64el (52.0-2ubuntu1) ... 1665s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 1665s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 1665s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 1665s Setting up libgfxdr0:ppc64el (11.1-5ubuntu1) ... 1665s Setting up librados2 (19.2.0~rc2-0ubuntu1) ... 1665s Setting up open-iscsi (2.1.10-1ubuntu1) ... 1665s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 1665s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 1665s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 1665s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 1665s Setting up librbd1 (19.2.0~rc2-0ubuntu1) ... 1665s Setting up libgfrpc0:ppc64el (11.1-5ubuntu1) ... 1665s Setting up libgfapi0:ppc64el (11.1-5ubuntu1) ... 1665s Setting up fio (3.37-1) ... 1665s Setting up autopkgtest-satdep (0) ... 1665s Processing triggers for man-db (2.12.1-3) ... 1665s Processing triggers for initramfs-tools (0.142ubuntu33) ... 1665s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 1665s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 1665s Processing triggers for libc-bin (2.40-1ubuntu1) ... 1707s (Reading database ... 72652 files and directories currently installed.) 1707s Removing autopkgtest-satdep (0) ... 1771s autopkgtest [17:43:53]: test tgtbasedmpaths: [----------------------- 1772s + targetname=iqn.2016-11.foo.com:target.iscsi 1772s + pwd 1772s + cwd=/tmp/autopkgtest.d4ADz3/build.orA/src 1772s + testdir=/mnt/tgtmpathtest 1772s + localhost=127.0.0.1 1772s + portal=127.0.0.1:3260 1772s + maxpaths=4 1772s + backfn=backingfile 1772s + expectwwid=60000000000000000e00000000010001 1772s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1772s + bglog=/tmp/autopkgtest.d4ADz3/tgtbasedmpaths-artifacts/test-background.log 1772s + fioprep=/tmp/autopkgtest.d4ADz3/tgtbasedmpaths-artifacts/path-change-prep.fio 1772s + fiovrfy=/tmp/autopkgtest.d4ADz3/tgtbasedmpaths-artifacts/path-change-check.fio 1772s + mkdir -p /etc/multipath 1772s + echo /360000000000000000e00000000010001/ 1772s + service tgt restart 1772s + truncate --size 100M backingfile 1772s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 1772s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 1772s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.d4ADz3/build.orA/src/backingfile 1772s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 1772s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 1772s + echo login #1 1772s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 1772s login #1 1772s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1772s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1772s + seq 2 4 1772s extra login #2 1772s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1772s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1772s + echo extra login #2 1772s + iscsiadm --mode session -r 1 --op new 1772s extra login #3 1772s + echo extra login #3 1772s + iscsiadm --mode session -r 1 --op new 1772s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1772s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1772s extra login #4 1772s + echo extra login #4 1772s + iscsiadm --mode session -r 1 --op new 1772s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1772s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1772s + udevadm settle 1772s + sleep 5 1780s Status after initial setup 1780s + echo Status after initial setup 1780s + tgtadm --lld iscsi --mode target --op show 1780s + tgtadm --lld iscsi --op show --mode conn --tid 1 1780s + iscsiadm --mode session -P 1 1780s + lsscsi -liv 1780s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 1780s + multipath -v3 -ll 1780s 425.598565 | set open fds limit to 1073741816/1073741816 1780s 425.598598 | _read_bindings_file: reading /etc/multipath/bindings 1780s 425.598622 | loading /usr/lib/multipath/libchecktur.so checker 1780s 425.598691 | checker tur: message table size = 4 1780s 425.598698 | loading /usr/lib/multipath/libprioconst.so prioritizer 1780s 425.598795 | _init_foreign: foreign library "nvme" is not enabled 1780s 425.603715 | vda: device node name blacklisted 1780s 425.604056 | sda: size = 204800 1780s 425.604216 | sda: vendor = IET 1780s 425.604259 | sda: product = VIRTUAL-DISK 1780s 425.604300 | sda: rev = 0001 1780s 425.605035 | sda: h:b:t:l = 0:0:0:1 1780s 425.605405 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1780s 425.605429 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 1780s 425.605449 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1780s 425.605632 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1780s 425.605655 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1780s 425.605686 | sda: serial = beaf11 1780s 425.605707 | sda: detect_checker = yes (setting: multipath internal) 1780s 425.605753 | sda checker timeout = 30 s (setting: kernel sysfs) 1780s 425.605993 | sda: path_checker = tur (setting: multipath internal) 1780s 425.606119 | sda: tur state = up 1780s 425.606267 | sdb: size = 204800 1780s 425.606437 | sdb: vendor = IET 1780s 425.606487 | sdb: product = VIRTUAL-DISK 1780s 425.606535 | sdb: rev = 0001 1780s 425.607299 | sdb: h:b:t:l = 1:0:0:1 1780s 425.607734 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1780s 425.607764 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 1780s 425.607788 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1780s 425.607975 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1780s 425.608007 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1780s 425.608054 | sdb: serial = beaf11 1780s 425.608079 | sdb: detect_checker = yes (setting: multipath internal) 1780s 425.608131 | sdb checker timeout = 30 s (setting: kernel sysfs) 1780s 425.608289 | sdb: path_checker = tur (setting: multipath internal) 1780s 425.608422 | sdb: tur state = up 1780s 425.608593 | sdc: size = 204800 1780s 425.608770 | sdc: vendor = IET 1780s 425.608824 | sdc: product = VIRTUAL-DISK 1780s 425.608872 | sdc: rev = 0001 1780s 425.609594 | sdc: h:b:t:l = 2:0:0:1 1780s 425.610085 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1780s 425.610118 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 1780s 425.610142 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1780s 425.610342 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1780s 425.610377 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1780s 425.610418 | sdc: serial = beaf11 1780s 425.610443 | sdc: detect_checker = yes (setting: multipath internal) 1780s 425.610496 | sdc checker timeout = 30 s (setting: kernel sysfs) 1780s 425.610653 | sdc: path_checker = tur (setting: multipath internal) 1780s 425.610779 | sdc: tur state = up 1780s 425.610951 | sdd: size = 204800 1780s 425.611131 | sdd: vendor = IET 1780s 425.611181 | sdd: product = VIRTUAL-DISK 1780s 425.611229 | sdd: rev = 0001 1780s 425.611992 | sdd: h:b:t:l = 3:0:0:1 1780s 425.612418 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1780s 425.612444 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 1780s 425.612465 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1780s 425.612626 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1780s 425.612650 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1780s 425.612681 | sdd: serial = beaf11 1780s 425.612702 | sdd: detect_checker = yes (setting: multipath internal) 1780s 425.612749 | sdd checker timeout = 30 s (setting: kernel sysfs) 1780s 425.612864 | sdd: path_checker = tur (setting: multipath internal) 1780s 425.613657 | sdd: tur state = up 1780s 425.613772 | loop0: device node name blacklisted 1780s 425.613914 | loop1: device node name blacklisted 1780s 425.614028 | loop2: device node name blacklisted 1780s 425.614138 | loop3: device node name blacklisted 1780s 425.614248 | loop4: device node name blacklisted 1780s 425.614357 | loop5: device node name blacklisted 1780s 425.614465 | loop6: device node name blacklisted 1780s 425.614573 | loop7: device node name blacklisted 1780s 425.614683 | dm-0: device node name blacklisted 1780s 425.615792 | multipath-tools v0.9.9 (05/03, 2024) 1780s 425.615824 | libdevmapper version 1.02.196 1780s 425.615979 | kernel device mapper v4.48.0 1780s 425.616019 | DM multipath kernel driver v1.14.0 1780s 425.616153 | sda: size = 204800 1780s 425.616179 | sda: vendor = IET 1780s 425.616201 | sda: product = VIRTUAL-DISK 1780s 425.616221 | sda: rev = 0001 1780s 425.616837 | sda: h:b:t:l = 0:0:0:1 1780s 425.616976 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1780s 425.617018 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1780s 425.617040 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1780s 425.617070 | sda: serial = beaf11 1780s 425.617194 | sda: tur state = up 1780s 425.617219 | sda: uid = 360000000000000000e00000000010001 (udev) 1780s 425.617240 | sda: detect_prio = yes (setting: multipath internal) 1780s 425.617261 | sda: prio = const (setting: multipath internal) 1780s 425.617281 | sda: prio args = "" (setting: multipath internal) 1780s 425.617302 | sda: const prio = 1 1780s 425.617326 | sdb: size = 204800 1780s 425.617330 | sdb: vendor = IET 1780s 425.617332 | sdb: product = VIRTUAL-DISK 1780s 425.617335 | sdb: rev = 0001 1780s 425.617916 | sdb: h:b:t:l = 1:0:0:1 1780s 425.618027 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1780s 425.618045 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1780s 425.618048 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1780s 425.618059 | sdb: serial = beaf11 1780s 425.618172 | sdb: tur state = up 1780s 425.618179 | sdb: uid = 360000000000000000e00000000010001 (udev) 1780s 425.618181 | sdb: detect_prio = yes (setting: multipath internal) 1780s 425.618184 | sdb: prio = const (setting: multipath internal) 1780s 425.618186 | sdb: prio args = "" (setting: multipath internal) 1780s 425.618188 | sdb: const prio = 1 1780s 425.618211 | sdc: size = 204800 1780s 425.618215 | sdc: vendor = IET 1780s 425.618217 | sdc: product = VIRTUAL-DISK 1780s 425.618219 | sdc: rev = 0001 1780s 425.618798 | sdc: h:b:t:l = 2:0:0:1 1780s 425.618909 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1780s 425.618927 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1780s 425.618930 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1780s 425.618941 | sdc: serial = beaf11 1780s 425.619049 | sdc: tur state = up 1780s 425.619056 | sdc: uid = 360000000000000000e00000000010001 (udev) 1780s 425.619058 | sdc: detect_prio = yes (setting: multipath internal) 1780s 425.619061 | sdc: prio = const (setting: multipath internal) 1780s 425.619063 | sdc: prio args = "" (setting: multipath internal) 1780s 425.619065 | sdc: const prio = 1 1780s 425.619086 | sdd: size = 204800 1780s 425.619090 | sdd: vendor = IET 1780s 425.619093 | sdd: product = VIRTUAL-DISK 1780s 425.619096 | sdd: rev = 0001 1780s 425.619685 | sdd: h:b:t:l = 3:0:0:1 1780s 425.619800 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1780s 425.619817 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1780s 425.619820 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1780s 425.619832 | sdd: serial = beaf11 1780s 425.619942 | sdd: tur state = up 1780s 425.619948 | sdd: uid = 360000000000000000e00000000010001 (udev) 1780s 425.619950 | sdd: detect_prio = yes (setting: multipath internal) 1780s 425.619953 | sdd: prio = const (setting: multipath internal) 1780s 425.619955 | sdd: prio args = "" (setting: multipath internal) 1780s 425.619957 | sdd: const prio = 1 1780s 425.620745 | unloading tur checker 1780s 425.620778 | unloading const prioritizer 1780s + dmsetup table 1780s + grep . /etc/multipath/bindings /etc/multipath/wwids 1780s + systemctl status multipathd.service 1780s + ret_code=0 1780s + systemctl status multipathd.socket 1780s + ret_code=3 1780s + [ 3 -eq 0 ] 1780s + [ 3 -eq 3 ] 1780s + ls -la /dev/mapper/ 1780s + echo journal 1780s + journalctl -b 1780s + echo Test WWN should now point to DM 1780s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1780s + grep dm 1780s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1780s mke2fs 1.47.1 (20-May-2024) 1780s + udevadm settle 1780s + sleep 3s 1780s Target 1: iqn.2016-11.foo.com:target.iscsi 1780s System information: 1780s Driver: iscsi 1780s State: ready 1780s I_T nexus information: 1780s I_T nexus: 1 1780s Initiator: iqn.2004-10.com.ubuntu:01:a1f4b44aafa6 alias: autopkgtest 1780s Connection: 0 1780s IP Address: 127.0.0.1 1780s I_T nexus: 2 1780s Initiator: iqn.2004-10.com.ubuntu:01:a1f4b44aafa6 alias: autopkgtest 1780s Connection: 0 1780s IP Address: 127.0.0.1 1780s I_T nexus: 3 1780s Initiator: iqn.2004-10.com.ubuntu:01:a1f4b44aafa6 alias: autopkgtest 1780s Connection: 0 1780s IP Address: 127.0.0.1 1780s I_T nexus: 4 1780s Initiator: iqn.2004-10.com.ubuntu:01:a1f4b44aafa6 alias: autopkgtest 1780s Connection: 0 1780s IP Address: 127.0.0.1 1780s LUN information: 1780s LUN: 0 1780s Type: controller 1780s SCSI ID: IET 00010000 1780s SCSI SN: beaf10 1780s Size: 0 MB, Block size: 1 1780s Online: Yes 1780s Removable media: No 1780s Prevent removal: No 1780s Readonly: No 1780s SWP: No 1780s Thin-provisioning: No 1780s Backing store type: null 1780s Backing store path: None 1780s Backing store flags: 1780s LUN: 1 1780s Type: disk 1780s SCSI ID: IET 00010001 1780s SCSI SN: beaf11 1780s Size: 105 MB, Block size: 512 1780s Online: Yes 1780s Removable media: No 1780s Prevent removal: No 1780s Readonly: No 1780s SWP: No 1780s Thin-provisioning: No 1780s Backing store type: rdwr 1780s Backing store path: /tmp/autopkgtest.d4ADz3/build.orA/src/backingfile 1780s Backing store flags: 1780s Account information: 1780s ACL information: 1780s ALL 1780s Session: 4 1780s Connection: 0 1780s Initiator: iqn.2004-10.com.ubuntu:01:a1f4b44aafa6 1780s IP Address: 127.0.0.1 1780s Session: 3 1780s Connection: 0 1780s Initiator: iqn.2004-10.com.ubuntu:01:a1f4b44aafa6 1780s IP Address: 127.0.0.1 1780s Session: 2 1780s Connection: 0 1780s Initiator: iqn.2004-10.com.ubuntu:01:a1f4b44aafa6 1780s IP Address: 127.0.0.1 1780s Session: 1 1780s Connection: 0 1780s Initiator: iqn.2004-10.com.ubuntu:01:a1f4b44aafa6 1780s IP Address: 127.0.0.1 1780s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 1780s Current Portal: 127.0.0.1:3260,1 1780s Persistent Portal: 127.0.0.1:3260,1 1780s ********** 1780s Interface: 1780s ********** 1780s Iface Name: default 1780s Iface Transport: tcp 1780s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:a1f4b44aafa6 1780s Iface IPaddress: 127.0.0.1 1780s Iface HWaddress: default 1780s Iface Netdev: default 1780s SID: 1 1780s iSCSI Connection State: LOGGED IN 1780s iSCSI Session State: LOGGED_IN 1780s Internal iscsid Session State: NO CHANGE 1780s 1780s ********** 1780s Interface: 1780s ********** 1780s Iface Name: default 1780s Iface Transport: tcp 1780s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:a1f4b44aafa6 1780s Iface IPaddress: 127.0.0.1 1780s Iface HWaddress: default 1780s Iface Netdev: default 1780s SID: 2 1780s iSCSI Connection State: LOGGED IN 1780s iSCSI Session State: LOGGED_IN 1780s Internal iscsid Session State: NO CHANGE 1780s 1780s ********** 1780s Interface: 1780s ********** 1780s Iface Name: default 1780s Iface Transport: tcp 1780s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:a1f4b44aafa6 1780s Iface IPaddress: 127.0.0.1 1780s Iface HWaddress: default 1780s Iface Netdev: default 1780s SID: 3 1780s iSCSI Connection State: LOGGED IN 1780s iSCSI Session State: LOGGED_IN 1780s Internal iscsid Session State: NO CHANGE 1780s 1780s ********** 1780s Interface: 1780s ********** 1780s Iface Name: default 1780s Iface Transport: tcp 1780s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:a1f4b44aafa6 1780s Iface IPaddress: 127.0.0.1 1780s Iface HWaddress: default 1780s Iface Netdev: default 1780s SID: 4 1780s iSCSI Connection State: LOGGED IN 1780s iSCSI Session State: LOGGED_IN 1780s Internal iscsid Session State: NO CHANGE 1780s [0:0:0:0] storage IET Controller 0001 - - 1780s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1780s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 1780s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 1780s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1780s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 1780s [1:0:0:0] storage IET Controller 0001 - - 1780s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1780s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 1780s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 1780s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1780s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 1780s [2:0:0:0] storage IET Controller 0001 - - 1780s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1780s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 1780s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 33000000100000001 1780s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1780s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 1780s [3:0:0:0] storage IET Controller 0001 - - 1780s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1780s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 1780s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 1780s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1780s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 1780s NVMe module may not be loaded 1780s ===== paths list ===== 1780s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 1780s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1780s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1780s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1780s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1780s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1780s size=100M features='0' hwhandler='0' wp=rw 1780s |-+- policy='service-time 0' prio=1 status=active 1780s | `- 0:0:0:1 sda 8:0 active ready running 1780s |-+- policy='service-time 0' prio=1 status=enabled 1780s | `- 1:0:0:1 sdb 8:16 active ready running 1780s |-+- policy='service-time 0' prio=1 status=enabled 1780s | `- 2:0:0:1 sdc 8:32 active ready running 1780s `-+- policy='service-time 0' prio=1 status=enabled 1780s `- 3:0:0:1 sdd 8:48 active ready running 1780s 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 1780s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 1780s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 1780s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 1780s /etc/multipath/bindings:# 1780s /etc/multipath/bindings:# Format: 1780s /etc/multipath/bindings:# alias wwid 1780s /etc/multipath/bindings:# 1780s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 1780s /etc/multipath/wwids:/360000000000000000e00000000010001/ 1780s ● multipathd.service - Device-Mapper Multipath Device Controller 1780s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 1780s Active: active (running) since Mon 2024-09-09 17:36:57 UTC; 7min ago 1780s Invocation: 321c2dcf60af4248b35744cba339c480 1780s TriggeredBy: ○ multipathd.socket 1780s Main PID: 328 (multipathd) 1780s Status: "up" 1780s Tasks: 7 1780s Memory: 27.9M (peak: 36.8M) 1780s CPU: 95ms 1780s CGroup: /system.slice/multipathd.service 1780s └─328 /sbin/multipathd -d -s 1780s 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1780s Sep 09 17:36:57 autopkgtest multipathd[328]: multipathd v0.9.9: start up 1780s Sep 09 17:36:57 autopkgtest multipathd[328]: reconfigure: setting up paths and maps 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1780s Sep 09 17:43:54 autopkgtest multipathd[328]: updated bindings file /etc/multipath/bindings 1780s Sep 09 17:43:54 autopkgtest multipathd[328]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 1780s Sep 09 17:43:54 autopkgtest multipathd[328]: sda [8:0]: path added to devmap mpatha 1780s Sep 09 17:43:54 autopkgtest multipathd[328]: mpatha: performing delayed actions 1780s Sep 09 17:43:54 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 1780s ○ multipathd.socket - multipathd control socket 1780s Loaded: loaded (/usr/lib/systemd/system/multipathd.socket; static) 1780s Active: inactive (dead) 1780s Triggers: ● multipathd.service 1780s Listen: @/org/kernel/linux/storage/multipathd (Stream) 1780s total 0 1780s drwxr-xr-x 2 root root 80 Sep 9 17:43 . 1780s drwxr-xr-x 20 root root 4360 Sep 9 17:43 .. 1780s crw------- 1 root root 10, 236 Sep 9 17:36 control 1780s lrwxrwxrwx 1 root root 7 Sep 9 17:43 mpatha -> ../dm-0 1780s journal 1780s Sep 09 17:36:57 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 1780s Sep 09 17:36:57 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 1780s Sep 09 17:36:57 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 1780s Sep 09 17:36:57 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 1780s Sep 09 17:36:57 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 1780s Sep 09 17:36:57 autopkgtest kernel: Activating Kernel Userspace Access Prevention 1780s Sep 09 17:36:57 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 1780s Sep 09 17:36:57 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x00000000038a0000 with 64.0 KiB pages (exec) 1780s Sep 09 17:36:57 autopkgtest kernel: radix-mmu: Mapped 0x00000000038a0000-0x0000000200000000 with 64.0 KiB pages 1780s Sep 09 17:36:57 autopkgtest kernel: lpar: Using radix MMU under hypervisor 1780s Sep 09 17:36:57 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) 1780s Sep 09 17:36:57 autopkgtest kernel: Secure boot mode disabled 1780s Sep 09 17:36:57 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc0000000093ce0bb 1780s Sep 09 17:36:57 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (raw) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 1780s Sep 09 17:36:57 autopkgtest kernel: Partition configured for 4 cpus. 1780s Sep 09 17:36:57 autopkgtest kernel: CPU maps initialized for 1 thread per core 1780s Sep 09 17:36:57 autopkgtest kernel: (thread shift is 0) 1780s Sep 09 17:36:57 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 1780s Sep 09 17:36:57 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 1780s Sep 09 17:36:57 autopkgtest kernel: ----------------------------------------------------- 1780s Sep 09 17:36:57 autopkgtest kernel: phys_mem_size = 0x200000000 1780s Sep 09 17:36:57 autopkgtest kernel: dcache_bsize = 0x80 1780s Sep 09 17:36:57 autopkgtest kernel: icache_bsize = 0x80 1780s Sep 09 17:36:57 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 1780s Sep 09 17:36:57 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 1780s Sep 09 17:36:57 autopkgtest kernel: always = 0x0000000380008181 1780s Sep 09 17:36:57 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 1780s Sep 09 17:36:57 autopkgtest kernel: mmu_features = 0x3c007641 1780s Sep 09 17:36:57 autopkgtest kernel: firmware_features = 0x00000285455a445f 1780s Sep 09 17:36:57 autopkgtest kernel: vmalloc start = 0xc008000000000000 1780s Sep 09 17:36:57 autopkgtest kernel: IO start = 0xc00a000000000000 1780s Sep 09 17:36:57 autopkgtest kernel: vmemmap start = 0xc00c000000000000 1780s Sep 09 17:36:57 autopkgtest kernel: ----------------------------------------------------- 1780s Sep 09 17:36:57 autopkgtest kernel: numa: NODE_DATA [mem 0x1eff0c280-0x1eff13fff] 1780s Sep 09 17:36:57 autopkgtest kernel: rfi-flush: fallback displacement flush available 1780s Sep 09 17:36:57 autopkgtest kernel: rfi-flush: ori type flush available 1780s Sep 09 17:36:57 autopkgtest kernel: rfi-flush: mttrig type flush available 1780s Sep 09 17:36:57 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 1780s Sep 09 17:36:57 autopkgtest kernel: count-cache-flush: hardware flush enabled. 1780s Sep 09 17:36:57 autopkgtest kernel: link-stack-flush: software flush enabled. 1780s Sep 09 17:36:57 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 1780s Sep 09 17:36:57 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 1780s Sep 09 17:36:57 autopkgtest kernel: stf-barrier: eieio barrier available 1780s Sep 09 17:36:57 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 1780s Sep 09 17:36:57 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 1780s Sep 09 17:36:57 autopkgtest kernel: PPC64 nvram contains 65536 bytes 1780s Sep 09 17:36:57 autopkgtest kernel: barrier-nospec: using ORI speculation barrier 1780s Sep 09 17:36:57 autopkgtest kernel: barrier-nospec: patched 269 locations 1780s Sep 09 17:36:57 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 1780s Sep 09 17:36:57 autopkgtest kernel: Memory hole size: 0MB 1780s Sep 09 17:36:57 autopkgtest kernel: Zone ranges: 1780s Sep 09 17:36:57 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 1780s Sep 09 17:36:57 autopkgtest kernel: Device empty 1780s Sep 09 17:36:57 autopkgtest kernel: Movable zone start for each node 1780s Sep 09 17:36:57 autopkgtest kernel: Early memory node ranges 1780s Sep 09 17:36:57 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 1780s Sep 09 17:36:57 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 1780s Sep 09 17:36:57 autopkgtest kernel: percpu: Embedded 12 pages/cpu s609960 r0 d176472 u786432 1780s Sep 09 17:36:57 autopkgtest kernel: pcpu-alloc: s609960 r0 d176472 u786432 alloc=12*65536 1780s Sep 09 17:36:57 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 1780s Sep 09 17:36:57 autopkgtest kernel: Kernel command line: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic root=UUID=b421051a-5f17-47ac-ade0-d9d9c5a5c13f ro console=hvc0 earlyprintk 1780s Sep 09 17:36:57 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic", will be passed to user space. 1780s Sep 09 17:36:57 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 1780s Sep 09 17:36:57 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 1780s Sep 09 17:36:57 autopkgtest kernel: Fallback order for Node 0: 0 1780s Sep 09 17:36:57 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 130944 1780s Sep 09 17:36:57 autopkgtest kernel: Policy zone: Normal 1780s Sep 09 17:36:57 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 1780s Sep 09 17:36:57 autopkgtest kernel: Memory: 7969280K/8388608K available (23680K kernel code, 4096K rwdata, 25472K rodata, 8832K init, 1901K bss, 419328K reserved, 0K cma-reserved) 1780s Sep 09 17:36:57 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 1780s Sep 09 17:36:57 autopkgtest kernel: ftrace: allocating 51717 entries in 19 pages 1780s Sep 09 17:36:57 autopkgtest kernel: ftrace: allocated 19 pages with 3 groups 1780s Sep 09 17:36:57 autopkgtest kernel: trace event string verifier disabled 1780s Sep 09 17:36:57 autopkgtest kernel: rcu: Hierarchical RCU implementation. 1780s Sep 09 17:36:57 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 1780s Sep 09 17:36:57 autopkgtest kernel: Rude variant of Tasks RCU enabled. 1780s Sep 09 17:36:57 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 1780s Sep 09 17:36:57 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 1780s Sep 09 17:36:57 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 1780s Sep 09 17:36:57 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 1780s Sep 09 17:36:57 autopkgtest kernel: xive: Using IRQ range [0-3] 1780s Sep 09 17:36:57 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 1780s Sep 09 17:36:57 autopkgtest kernel: xive: Using priority 6 for all interrupts 1780s Sep 09 17:36:57 autopkgtest kernel: xive: Using 64kB queues 1780s Sep 09 17:36:57 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 1780s Sep 09 17:36:57 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 1780s Sep 09 17:36:57 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 1780s Sep 09 17:36:57 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 1780s Sep 09 17:36:57 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 1780s Sep 09 17:36:57 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 1780s Sep 09 17:36:57 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 1780s Sep 09 17:36:57 autopkgtest kernel: Console: colour dummy device 80x25 1780s Sep 09 17:36:57 autopkgtest kernel: pid_max: default: 32768 minimum: 301 1780s Sep 09 17:36:57 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,integrity 1780s Sep 09 17:36:57 autopkgtest kernel: landlock: Up and running. 1780s Sep 09 17:36:57 autopkgtest kernel: Yama: becoming mindful. 1780s Sep 09 17:36:57 autopkgtest kernel: AppArmor: AppArmor initialized 1780s Sep 09 17:36:57 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 1780s Sep 09 17:36:57 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 1780s Sep 09 17:36:57 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 1780s Sep 09 17:36:57 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 1780s Sep 09 17:36:57 autopkgtest kernel: POWER9 performance monitor hardware support registered 1780s Sep 09 17:36:57 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 1780s Sep 09 17:36:57 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 1780s Sep 09 17:36:57 autopkgtest kernel: smp: Bringing up secondary CPUs ... 1780s Sep 09 17:36:57 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 1780s Sep 09 17:36:57 autopkgtest kernel: numa: Node 0 CPUs: 0-3 1780s Sep 09 17:36:57 autopkgtest kernel: devtmpfs: initialized 1780s Sep 09 17:36:57 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 1780s Sep 09 17:36:57 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 1780s Sep 09 17:36:57 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 1780s Sep 09 17:36:57 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 1780s Sep 09 17:36:57 autopkgtest kernel: PCI: OF: PROBE_ONLY disabled 1780s Sep 09 17:36:57 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 1780s Sep 09 17:36:57 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 1780s Sep 09 17:36:57 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 1780s Sep 09 17:36:57 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 1780s Sep 09 17:36:57 autopkgtest kernel: audit: initializing netlink subsys (disabled) 1780s Sep 09 17:36:57 autopkgtest kernel: audit: type=2000 audit(1725903414.040:1): state=initialized audit_enabled=0 res=1 1780s Sep 09 17:36:57 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 1780s Sep 09 17:36:57 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 1780s Sep 09 17:36:57 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 1780s Sep 09 17:36:57 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 1780s Sep 09 17:36:57 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 1780s Sep 09 17:36:57 autopkgtest kernel: cpuidle: using governor ladder 1780s Sep 09 17:36:57 autopkgtest kernel: cpuidle: using governor menu 1780s Sep 09 17:36:57 autopkgtest kernel: RTAS daemon started 1780s Sep 09 17:36:57 autopkgtest kernel: pstore: Using crash dump compression: deflate 1780s Sep 09 17:36:57 autopkgtest kernel: pstore: Registered nvram as persistent store backend 1780s Sep 09 17:36:57 autopkgtest kernel: EEH: pSeries platform initialized 1780s Sep 09 17:36:57 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 1780s Sep 09 17:36:57 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 1780s Sep 09 17:36:57 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 1780s Sep 09 17:36:57 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 1780s Sep 09 17:36:57 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 1780s Sep 09 17:36:57 autopkgtest kernel: iommu: Default domain type: Translated 1780s Sep 09 17:36:57 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 1780s Sep 09 17:36:57 autopkgtest kernel: SCSI subsystem initialized 1780s Sep 09 17:36:57 autopkgtest kernel: libata version 3.00 loaded. 1780s Sep 09 17:36:57 autopkgtest kernel: usbcore: registered new interface driver usbfs 1780s Sep 09 17:36:57 autopkgtest kernel: usbcore: registered new interface driver hub 1780s Sep 09 17:36:57 autopkgtest kernel: usbcore: registered new device driver usb 1780s Sep 09 17:36:57 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 1780s Sep 09 17:36:57 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 1780s Sep 09 17:36:57 autopkgtest kernel: PTP clock support registered 1780s Sep 09 17:36:57 autopkgtest kernel: EDAC MC: Ver: 3.0.0 1780s Sep 09 17:36:57 autopkgtest kernel: NetLabel: Initializing 1780s Sep 09 17:36:57 autopkgtest kernel: NetLabel: domain hash size = 128 1780s Sep 09 17:36:57 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 1780s Sep 09 17:36:57 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 1780s Sep 09 17:36:57 autopkgtest kernel: mctp: management component transport protocol core 1780s Sep 09 17:36:57 autopkgtest kernel: NET: Registered PF_MCTP protocol family 1780s Sep 09 17:36:57 autopkgtest kernel: PCI: Probing PCI hardware 1780s Sep 09 17:36:57 autopkgtest kernel: PCI host bridge to bus 0000:00 1780s Sep 09 17:36:57 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 1780s Sep 09 17:36:57 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 1780s Sep 09 17:36:57 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 1780s Sep 09 17:36:57 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:05.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:06.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:07.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1780s Sep 09 17:36:57 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 1780s Sep 09 17:36:57 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 1780s Sep 09 17:36:57 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 1780s Sep 09 17:36:57 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 1780s Sep 09 17:36:57 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:05.0: Adding to iommu group 0 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:06.0: Adding to iommu group 0 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:07.0: Adding to iommu group 0 1780s Sep 09 17:36:57 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 1780s Sep 09 17:36:57 autopkgtest kernel: PCI: Probing PCI hardware done 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:07.0: vgaarb: setting as boot VGA device 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:07.0: vgaarb: bridge control possible 1780s Sep 09 17:36:57 autopkgtest kernel: pci 0000:00:07.0: vgaarb: VGA device added: decodes=io+mem,owns=mem,locks=none 1780s Sep 09 17:36:57 autopkgtest kernel: vgaarb: loaded 1780s Sep 09 17:36:57 autopkgtest kernel: clocksource: Switched to clocksource timebase 1780s Sep 09 17:36:57 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 1780s Sep 09 17:36:57 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 1780s Sep 09 17:36:57 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 1780s Sep 09 17:36:57 autopkgtest kernel: NET: Registered PF_INET protocol family 1780s Sep 09 17:36:57 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 1780s Sep 09 17:36:57 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 1780s Sep 09 17:36:57 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 1780s Sep 09 17:36:57 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 1780s Sep 09 17:36:57 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 1780s Sep 09 17:36:57 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 1780s Sep 09 17:36:57 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 1780s Sep 09 17:36:57 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 1780s Sep 09 17:36:57 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 1780s Sep 09 17:36:57 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 1780s Sep 09 17:36:57 autopkgtest kernel: NET: Registered PF_XDP protocol family 1780s Sep 09 17:36:57 autopkgtest kernel: PCI: CLS 0 bytes, default 128 1780s Sep 09 17:36:57 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 1780s Sep 09 17:36:57 autopkgtest kernel: Initialise system trusted keyrings 1780s Sep 09 17:36:57 autopkgtest kernel: Key type blacklist registered 1780s Sep 09 17:36:57 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 1780s Sep 09 17:36:57 autopkgtest kernel: zbud: loaded 1780s Sep 09 17:36:57 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 1780s Sep 09 17:36:57 autopkgtest kernel: fuse: init (API version 7.39) 1780s Sep 09 17:36:57 autopkgtest kernel: integrity: Platform Keyring initialized 1780s Sep 09 17:36:57 autopkgtest kernel: integrity: Machine keyring initialized 1780s Sep 09 17:36:57 autopkgtest kernel: Key type asymmetric registered 1780s Sep 09 17:36:57 autopkgtest kernel: Asymmetric key parser 'x509' registered 1780s Sep 09 17:36:57 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 1780s Sep 09 17:36:57 autopkgtest kernel: io scheduler mq-deadline registered 1780s Sep 09 17:36:57 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 1780s Sep 09 17:36:57 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 1780s Sep 09 17:36:57 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) 1780s Sep 09 17:36:57 autopkgtest kernel: virtio-pci 0000:00:03.0: enabling device (0100 -> 0103) 1780s Sep 09 17:36:57 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 1780s Sep 09 17:36:57 autopkgtest kernel: virtio-pci 0000:00:05.0: enabling device (0100 -> 0103) 1780s Sep 09 17:36:57 autopkgtest kernel: virtio-pci 0000:00:06.0: enabling device (0100 -> 0103) 1780s Sep 09 17:36:57 autopkgtest kernel: printk: legacy console [hvc0] enabled 1780s Sep 09 17:36:57 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 1780s Sep 09 17:36:57 autopkgtest kernel: Freeing initrd memory: 50944K 1780s Sep 09 17:36:57 autopkgtest kernel: Non-volatile memory driver v1.3 1780s Sep 09 17:36:57 autopkgtest kernel: Linux agpgart interface v0.103 1780s Sep 09 17:36:57 autopkgtest kernel: loop: module loaded 1780s Sep 09 17:36:57 autopkgtest kernel: virtio_blk virtio2: 4/0/0 default/read/poll queues 1780s Sep 09 17:36:57 autopkgtest kernel: virtio_blk virtio2: [vda] 209715200 512-byte logical blocks (107 GB/100 GiB) 1780s Sep 09 17:36:57 autopkgtest kernel: vda: vda1 vda2 1780s Sep 09 17:36:57 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 1780s Sep 09 17:36:57 autopkgtest kernel: PPP generic driver version 2.4.2 1780s Sep 09 17:36:57 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 1780s Sep 09 17:36:57 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 1780s Sep 09 17:36:57 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-09-09T17:36:55 UTC (1725903415) 1780s Sep 09 17:36:57 autopkgtest kernel: i2c_dev: i2c /dev entries driver 1780s Sep 09 17:36:57 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 1780s Sep 09 17:36:57 autopkgtest kernel: device-mapper: uevent: version 1.0.3 1780s Sep 09 17:36:57 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@redhat.com 1780s Sep 09 17:36:57 autopkgtest kernel: pseries_idle_driver registered 1780s Sep 09 17:36:57 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 1780s Sep 09 17:36:57 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 1780s Sep 09 17:36:57 autopkgtest kernel: NET: Registered PF_INET6 protocol family 1780s Sep 09 17:36:57 autopkgtest kernel: Segment Routing with IPv6 1780s Sep 09 17:36:57 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 1780s Sep 09 17:36:57 autopkgtest kernel: NET: Registered PF_PACKET protocol family 1780s Sep 09 17:36:57 autopkgtest kernel: Key type dns_resolver registered 1780s Sep 09 17:36:57 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 1780s Sep 09 17:36:57 autopkgtest kernel: drmem: No dynamic reconfiguration memory found 1780s Sep 09 17:36:57 autopkgtest kernel: registered taskstats version 1 1780s Sep 09 17:36:57 autopkgtest kernel: Loading compiled-in X.509 certificates 1780s Sep 09 17:36:57 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 1780s Sep 09 17:36:57 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 1780s Sep 09 17:36:57 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 1780s Sep 09 17:36:57 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 1780s Sep 09 17:36:57 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 1780s Sep 09 17:36:57 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 1780s Sep 09 17:36:57 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 1780s Sep 09 17:36:57 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 1780s Sep 09 17:36:57 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 1780s Sep 09 17:36:57 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 1780s Sep 09 17:36:57 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 1780s Sep 09 17:36:57 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 1780s Sep 09 17:36:57 autopkgtest kernel: Key type .fscrypt registered 1780s Sep 09 17:36:57 autopkgtest kernel: Key type fscrypt-provisioning registered 1780s Sep 09 17:36:57 autopkgtest kernel: Key type encrypted registered 1780s Sep 09 17:36:57 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 1780s Sep 09 17:36:57 autopkgtest kernel: Secure boot mode disabled 1780s Sep 09 17:36:57 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 1780s Sep 09 17:36:57 autopkgtest kernel: Loading compiled-in module X.509 certificates 1780s Sep 09 17:36:57 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 1780s Sep 09 17:36:57 autopkgtest kernel: ima: Allocated hash algorithm: sha256 1780s Sep 09 17:36:57 autopkgtest kernel: Secure boot mode disabled 1780s Sep 09 17:36:57 autopkgtest kernel: Trusted boot mode disabled 1780s Sep 09 17:36:57 autopkgtest kernel: ima: No architecture policies found 1780s Sep 09 17:36:57 autopkgtest kernel: evm: Initialising EVM extended attributes: 1780s Sep 09 17:36:57 autopkgtest kernel: evm: security.selinux 1780s Sep 09 17:36:57 autopkgtest kernel: evm: security.SMACK64 1780s Sep 09 17:36:57 autopkgtest kernel: evm: security.SMACK64EXEC 1780s Sep 09 17:36:57 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 1780s Sep 09 17:36:57 autopkgtest kernel: evm: security.SMACK64MMAP 1780s Sep 09 17:36:57 autopkgtest kernel: evm: security.apparmor 1780s Sep 09 17:36:57 autopkgtest kernel: evm: security.ima 1780s Sep 09 17:36:57 autopkgtest kernel: evm: security.capability 1780s Sep 09 17:36:57 autopkgtest kernel: evm: HMAC attrs: 0x1 1780s Sep 09 17:36:57 autopkgtest kernel: SED: plpks not available 1780s Sep 09 17:36:57 autopkgtest kernel: clk: Disabling unused clocks 1780s Sep 09 17:36:57 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 1780s Sep 09 17:36:57 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8832K 1780s Sep 09 17:36:57 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 1780s Sep 09 17:36:57 autopkgtest kernel: Run /init as init process 1780s Sep 09 17:36:57 autopkgtest kernel: with arguments: 1780s Sep 09 17:36:57 autopkgtest kernel: /init 1780s Sep 09 17:36:57 autopkgtest kernel: earlyprintk 1780s Sep 09 17:36:57 autopkgtest kernel: with environment: 1780s Sep 09 17:36:57 autopkgtest kernel: HOME=/ 1780s Sep 09 17:36:57 autopkgtest kernel: TERM=linux 1780s Sep 09 17:36:57 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic 1780s Sep 09 17:36:57 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 1780s Sep 09 17:36:57 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 1780s Sep 09 17:36:57 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 1 1780s Sep 09 17:36:57 autopkgtest kernel: xhci_hcd 0000:00:02.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010 1780s Sep 09 17:36:57 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 1780s Sep 09 17:36:57 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2 1780s Sep 09 17:36:57 autopkgtest kernel: xhci_hcd 0000:00:02.0: Host supports USB 3.0 SuperSpeed 1780s Sep 09 17:36:57 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.08 1780s Sep 09 17:36:57 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 1780s Sep 09 17:36:57 autopkgtest kernel: usb usb1: Product: xHCI Host Controller 1780s Sep 09 17:36:57 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 1780s Sep 09 17:36:57 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:02.0 1780s Sep 09 17:36:57 autopkgtest kernel: hub 1-0:1.0: USB hub found 1780s Sep 09 17:36:57 autopkgtest kernel: hub 1-0:1.0: 4 ports detected 1780s Sep 09 17:36:57 autopkgtest kernel: usb usb2: We don't know the algorithms for LPM for this host, disabling LPM. 1780s Sep 09 17:36:57 autopkgtest kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.08 1780s Sep 09 17:36:57 autopkgtest kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 1780s Sep 09 17:36:57 autopkgtest kernel: usb usb2: Product: xHCI Host Controller 1780s Sep 09 17:36:57 autopkgtest kernel: usb usb2: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 1780s Sep 09 17:36:57 autopkgtest kernel: usb usb2: SerialNumber: 0000:00:02.0 1780s Sep 09 17:36:57 autopkgtest kernel: random: crng init done 1780s Sep 09 17:36:57 autopkgtest kernel: hub 2-0:1.0: USB hub found 1780s Sep 09 17:36:57 autopkgtest kernel: hub 2-0:1.0: 4 ports detected 1780s Sep 09 17:36:57 autopkgtest kernel: [drm] Found bochs VGA, ID 0xb0c5. 1780s Sep 09 17:36:57 autopkgtest kernel: [drm] Framebuffer size 16384 kB @ 0x200081000000, mmio @ 0x200082000000. 1780s Sep 09 17:36:57 autopkgtest kernel: [drm] Found EDID data blob. 1780s Sep 09 17:36:57 autopkgtest kernel: [drm] Initialized bochs-drm 1.0.0 20130925 for 0000:00:07.0 on minor 0 1780s Sep 09 17:36:57 autopkgtest kernel: fbcon: Deferring console take-over 1780s Sep 09 17:36:57 autopkgtest kernel: bochs-drm 0000:00:07.0: [drm] fb0: bochs-drmdrmfb frame buffer device 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: vpermxor8 gen() 21679 MB/s 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: vpermxor4 gen() 18820 MB/s 1780s Sep 09 17:36:57 autopkgtest kernel: usb 1-1: new high-speed USB device number 2 using xhci_hcd 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: vpermxor2 gen() 14572 MB/s 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: vpermxor1 gen() 12421 MB/s 1780s Sep 09 17:36:57 autopkgtest kernel: usb 1-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 1780s Sep 09 17:36:57 autopkgtest kernel: usb 1-1: New USB device strings: Mfr=1, Product=4, SerialNumber=11 1780s Sep 09 17:36:57 autopkgtest kernel: usb 1-1: Product: QEMU USB Keyboard 1780s Sep 09 17:36:57 autopkgtest kernel: usb 1-1: Manufacturer: QEMU 1780s Sep 09 17:36:57 autopkgtest kernel: usb 1-1: SerialNumber: 68284-pci@800000020000000:02.0-1 1780s Sep 09 17:36:57 autopkgtest kernel: hid: raw HID events driver (C) Jiri Kosina 1780s Sep 09 17:36:57 autopkgtest kernel: usbcore: registered new interface driver usbhid 1780s Sep 09 17:36:57 autopkgtest kernel: usbhid: USB HID core driver 1780s Sep 09 17:36:57 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 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: altivecx8 gen() 13453 MB/s 1780s Sep 09 17:36:57 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 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: altivecx4 gen() 13224 MB/s 1780s Sep 09 17:36:57 autopkgtest kernel: usb 1-2: new high-speed USB device number 3 using xhci_hcd 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: altivecx2 gen() 10576 MB/s 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: altivecx1 gen() 8009 MB/s 1780s Sep 09 17:36:57 autopkgtest kernel: usb 1-2: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 1780s Sep 09 17:36:57 autopkgtest kernel: usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=9 1780s Sep 09 17:36:57 autopkgtest kernel: usb 1-2: Product: QEMU USB Mouse 1780s Sep 09 17:36:57 autopkgtest kernel: usb 1-2: Manufacturer: QEMU 1780s Sep 09 17:36:57 autopkgtest kernel: usb 1-2: SerialNumber: 89126-pci@800000020000000:02.0-2 1780s Sep 09 17:36:57 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 1780s Sep 09 17:36:57 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 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: int64x8 gen() 7218 MB/s 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: int64x4 gen() 8548 MB/s 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: int64x2 gen() 6462 MB/s 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: int64x1 gen() 5156 MB/s 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 21679 MB/s 1780s Sep 09 17:36:57 autopkgtest kernel: raid6: using intx1 recovery algorithm 1780s Sep 09 17:36:57 autopkgtest kernel: xor: measuring software checksum speed 1780s Sep 09 17:36:57 autopkgtest kernel: 8regs : 12988 MB/sec 1780s Sep 09 17:36:57 autopkgtest kernel: 8regs_prefetch : 10684 MB/sec 1780s Sep 09 17:36:57 autopkgtest kernel: 32regs : 12702 MB/sec 1780s Sep 09 17:36:57 autopkgtest kernel: 32regs_prefetch : 10710 MB/sec 1780s Sep 09 17:36:57 autopkgtest kernel: altivec : 15416 MB/sec 1780s Sep 09 17:36:57 autopkgtest kernel: xor: using function: altivec (15416 MB/sec) 1780s Sep 09 17:36:57 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 1780s Sep 09 17:36:57 autopkgtest kernel: EXT4-fs (vda1): orphan cleanup on readonly fs 1780s Sep 09 17:36:57 autopkgtest kernel: EXT4-fs (vda1): mounted filesystem b421051a-5f17-47ac-ade0-d9d9c5a5c13f ro with ordered data mode. Quota mode: none. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Inserted module 'autofs4' 1780s Sep 09 17:36:57 autopkgtest systemd[1]: systemd 256.5-2ubuntu2 running in system mode (+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -XKBCOMMON +UTMP +SYSVINIT +LIBARCHIVE) 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Detected virtualization kvm. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Detected architecture ppc64-le. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Hostname set to . 1780s Sep 09 17:36:57 autopkgtest systemd[1]: bpf-restrict-fs: BPF LSM hook not enabled in the kernel, BPF LSM not supported. 1780s Sep 09 17:36:57 autopkgtest kernel: NET: Registered PF_VSOCK protocol family 1780s Sep 09 17:36:57 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. 1780s Sep 09 17:36:57 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. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Queued start job for default target graphical.target. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Reached target swap.target - Swaps. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Sockets. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounting run-lock.mount - Legacy Locks Directory /run/lock... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting modprobe@dm_multipath.service - Load Kernel Module dm_multipath... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 1780s Sep 09 17:36:57 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). 1780s Sep 09 17:36:57 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). 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 1780s Sep 09 17:36:57 autopkgtest systemd-journald[281]: Collecting audit messages is disabled. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounted run-lock.mount - Legacy Locks Directory /run/lock. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: modprobe@dm_multipath.service: Deactivated successfully. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished modprobe@dm_multipath.service - Load Kernel Module dm_multipath. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 1780s Sep 09 17:36:57 autopkgtest systemd-journald[281]: Journal started 1780s Sep 09 17:36:57 autopkgtest systemd-journald[281]: Runtime Journal (/run/log/journal/dfe3593ae176490a978a99e3bcd2119a) is 8M, max 78.4M, 70.4M free. 1780s Sep 09 17:36:57 autopkgtest kernel: EXT4-fs (vda1): re-mounted b421051a-5f17-47ac-ade0-d9d9c5a5c13f r/w. Quota mode: none. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting cloud-init-main.service - Cloud-init: Single Process... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 1780s Sep 09 17:36:57 autopkgtest systemd-journald[281]: Time spent on flushing to /var/log/journal/dfe3593ae176490a978a99e3bcd2119a is 39.235ms for 462 entries. 1780s Sep 09 17:36:57 autopkgtest systemd-journald[281]: System Journal (/var/log/journal/dfe3593ae176490a978a99e3bcd2119a) is 18.9M, max 4G, 3.9G free. 1780s Sep 09 17:36:57 autopkgtest systemd-journald[281]: Received client request to flush runtime journal. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 1780s Sep 09 17:36:57 autopkgtest multipathd[328]: multipathd v0.9.9: start up 1780s Sep 09 17:36:57 autopkgtest multipathd[328]: reconfigure: setting up paths and maps 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 1780s Sep 09 17:36:57 autopkgtest apparmor.systemd[352]: Restarting AppArmor 1780s Sep 09 17:36:57 autopkgtest apparmor.systemd[352]: Reloading AppArmor profiles 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 356 (systemd-binfmt) 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 1780s Sep 09 17:36:57 autopkgtest systemd-tmpfiles[376]: /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 1780s Sep 09 17:36:57 autopkgtest kernel: audit: type=1400 audit(1725903417.712:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=383 comm="apparmor_parser" 1780s Sep 09 17:36:57 autopkgtest kernel: audit: type=1400 audit(1725903417.712:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=382 comm="apparmor_parser" 1780s Sep 09 17:36:57 autopkgtest kernel: audit: type=1400 audit(1725903417.712:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=384 comm="apparmor_parser" 1780s Sep 09 17:36:57 autopkgtest kernel: audit: type=1400 audit(1725903417.712:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=385 comm="apparmor_parser" 1780s Sep 09 17:36:57 autopkgtest kernel: audit: type=1400 audit(1725903417.716:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=387 comm="apparmor_parser" 1780s Sep 09 17:36:57 autopkgtest systemd-udevd[345]: Using default interface naming scheme 'v255'. 1780s Sep 09 17:36:57 autopkgtest kernel: audit: type=1400 audit(1725903417.716:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=388 comm="apparmor_parser" 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 1780s Sep 09 17:36:57 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 1780s Sep 09 17:36:57 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 1780s Sep 09 17:36:57 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). 1780s Sep 09 17:36:57 autopkgtest kernel: audit: type=1400 audit(1725903417.720:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="busybox" pid=390 comm="apparmor_parser" 1780s Sep 09 17:36:57 autopkgtest kernel: audit: type=1400 audit(1725903417.720:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="cam" pid=391 comm="apparmor_parser" 1780s Sep 09 17:36:57 autopkgtest kernel: audit: type=1400 audit(1725903417.720:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=389 comm="apparmor_parser" 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 1780s Sep 09 17:36:57 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). 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 1780s Sep 09 17:36:57 autopkgtest systemd-resolved[398]: Positive Trust Anchors: 1780s Sep 09 17:36:57 autopkgtest systemd-resolved[398]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 1780s Sep 09 17:36:57 autopkgtest systemd-resolved[398]: 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 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 1780s Sep 09 17:36:57 autopkgtest systemd-resolved[398]: Using system hostname 'autopkgtest'. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 1780s Sep 09 17:36:57 autopkgtest (udev-worker)[489]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 1780s Sep 09 17:36:57 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 1780s Sep 09 17:36:58 autopkgtest systemd[1]: Started cloud-init-main.service - Cloud-init: Single Process. 1780s Sep 09 17:36:58 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 1780s Sep 09 17:36:58 autopkgtest cloud-init[690]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu1 running 'init-local' at Mon, 09 Sep 2024 17:36:58 +0000. Up 3.27 seconds. 1780s Sep 09 17:36:58 autopkgtest dhcpcd[693]: dhcpcd-10.0.8 starting 1780s Sep 09 17:36:58 autopkgtest dhcpcd[696]: DUID 00:01:00:01:2e:71:cd:c1:fa:16:3e:e7:13:df 1780s Sep 09 17:36:58 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 1780s Sep 09 17:36:58 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 1780s Sep 09 17:36:58 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 1780s Sep 09 17:36:58 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 1780s Sep 09 17:36:58 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 1780s Sep 09 17:36:58 autopkgtest dhcpcd[696]: enp0s1: IAID 3e:be:01:79 1780s Sep 09 17:37:00 autopkgtest dhcpcd[696]: enp0s1: rebinding lease of 10.145.227.79 1780s Sep 09 17:37:00 autopkgtest dhcpcd[696]: enp0s1: leased 10.145.227.79 for 43200 seconds 1780s Sep 09 17:37:00 autopkgtest dhcpcd[696]: enp0s1: adding route to 10.145.227.0/24 1780s Sep 09 17:37:00 autopkgtest dhcpcd[696]: enp0s1: adding host route to 169.254.169.254 via 10.145.227.2 1780s Sep 09 17:37:00 autopkgtest dhcpcd[696]: enp0s1: adding default route via 10.145.227.1 1780s Sep 09 17:37:00 autopkgtest dhcpcd[696]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 1780s Sep 09 17:37:05 autopkgtest sh[686]: Completed socket interaction for boot stage local 1780s Sep 09 17:37:05 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 1780s Sep 09 17:37:05 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 1780s Sep 09 17:37:05 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 1780s Sep 09 17:37:06 autopkgtest systemd-networkd[725]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 1780s Sep 09 17:37:06 autopkgtest systemd-networkd[725]: lo: Link UP 1780s Sep 09 17:37:06 autopkgtest systemd-networkd[725]: lo: Gained carrier 1780s Sep 09 17:37:06 autopkgtest systemd-networkd[725]: Enumeration completed 1780s Sep 09 17:37:06 autopkgtest systemd-networkd[725]: enp0s1: Link UP 1780s Sep 09 17:37:06 autopkgtest systemd-networkd[725]: enp0s1: Gained carrier 1780s Sep 09 17:37:06 autopkgtest systemd-networkd[725]: enp0s1: Gained IPv6LL 1780s Sep 09 17:37:06 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 1780s Sep 09 17:37:06 autopkgtest systemd-timesyncd[401]: Network configuration changed, trying to establish connection. 1780s Sep 09 17:37:06 autopkgtest systemd-networkd[725]: enp0s1: Link DOWN 1780s Sep 09 17:37:06 autopkgtest systemd-networkd[725]: enp0s1: Lost carrier 1780s Sep 09 17:37:06 autopkgtest systemd[1]: Reached target network.target - Network. 1780s Sep 09 17:37:06 autopkgtest systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... 1780s Sep 09 17:37:06 autopkgtest systemd-networkd[725]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 1780s Sep 09 17:37:06 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 1780s Sep 09 17:37:06 autopkgtest systemd-networkd[725]: enp0s1: Link UP 1780s Sep 09 17:37:06 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 1780s Sep 09 17:37:06 autopkgtest systemd-networkd[725]: enp0s1: Gained carrier 1780s Sep 09 17:37:06 autopkgtest systemd-networkd[725]: enp0s1: DHCPv4 address 10.145.227.79/24, gateway 10.145.227.1 acquired from 10.145.227.1 1780s Sep 09 17:37:06 autopkgtest systemd-timesyncd[401]: Network configuration changed, trying to establish connection. 1780s Sep 09 17:37:06 autopkgtest systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. 1780s Sep 09 17:37:07 autopkgtest systemd-networkd[725]: enp0s1: Gained IPv6LL 1780s Sep 09 17:37:07 autopkgtest systemd-timesyncd[401]: Network configuration changed, trying to establish connection. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting cloud-init-network.service - Cloud-init: Network Stage... 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu1 running 'init' at Mon, 09 Sep 2024 17:37:07 +0000. Up 12.15 seconds. 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: ++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: +--------+------+-----------------------------+---------------+--------+-------------------+ 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: +--------+------+-----------------------------+---------------+--------+-------------------+ 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | enp0s1 | True | 10.145.227.79 | 255.255.255.0 | global | fa:16:3e:be:01:79 | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | enp0s1 | True | fe80::f816:3eff:febe:179/64 | . | link | fa:16:3e:be:01:79 | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | lo | True | ::1/128 | . | host | . | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: +--------+------+-----------------------------+---------------+--------+-------------------+ 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++++ 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | 0 | 0.0.0.0 | 10.145.227.1 | 0.0.0.0 | enp0s1 | UG | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | 1 | 10.145.227.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | 2 | 10.145.227.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | 3 | 10.145.227.2 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | 4 | 91.189.91.131 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | 5 | 91.189.91.132 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | 6 | 169.254.169.254 | 10.145.227.2 | 255.255.255.255 | enp0s1 | UGH | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: +-------+-------------+---------+-----------+-------+ 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | Route | Destination | Gateway | Interface | Flags | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: +-------+-------------+---------+-----------+-------+ 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | 2 | local | :: | enp0s1 | U | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: | 3 | multicast | :: | enp0s1 | U | 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: ci-info: +-------+-------------+---------+-----------+-------+ 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: 2024-09-09 17:37:07,447 - 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. 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: 2024-09-09 17:37:07,448 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 1780s Sep 09 17:37:07 autopkgtest sh[736]: Completed socket interaction for boot stage network 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Finished cloud-init-network.service - Cloud-init: Network Stage. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 1780s Sep 09 17:37:07 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). 1780s Sep 09 17:37:07 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). 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started sysstat-collect.timer - Run system activity accounting tool every 10 minutes. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started sysstat-rotate.timer - Rotate daily system activity data file at midnight. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started sysstat-summary.timer - Generate summary of yesterday's process accounting. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 1780s Sep 09 17:37:07 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). 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Reached target paths.target - Path Units. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Reached target ssh-access.target - SSH Access Available. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Reached target basic.target - Basic System. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: System is tainted: unmerged-bin 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 1780s Sep 09 17:37:07 autopkgtest (sh)[771]: autopkgtest@hvc1.service: Failed to set up standard input: No such device 1780s Sep 09 17:37:07 autopkgtest (sh)[771]: autopkgtest@hvc1.service: Failed at step STDIN spawning /bin/sh: No such device 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 1780s Sep 09 17:37:07 autopkgtest (sh)[772]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 1780s Sep 09 17:37:07 autopkgtest (sh)[772]: autopkgtest@ttyS1.service: Failed at step STDIN spawning /bin/sh: Input/output error 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 1780s Sep 09 17:37:07 autopkgtest (cron)[774]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 1780s Sep 09 17:37:07 autopkgtest cron[774]: (CRON) INFO (pidfile fd = 3) 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 1780s Sep 09 17:37:07 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). 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 1780s Sep 09 17:37:07 autopkgtest cron[774]: (CRON) INFO (Running @reboot jobs) 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: opal_errd.service - opal_errd (PowerNV platform error handling) Service was skipped because of an unmet condition check (ConditionVirtualization=false). 1780s Sep 09 17:37:07 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). 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 1780s Sep 09 17:37:07 autopkgtest dbus-daemon[778]: [system] AppArmor D-Bus mediation is enabled 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting sysstat.service - Resets System Activity Logs... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 1780s Sep 09 17:37:07 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). 1780s Sep 09 17:37:07 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: autopkgtest@hvc1.service: Deactivated successfully. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 1780s Sep 09 17:37:07 autopkgtest udisksd[795]: udisks daemon version 2.10.1 starting 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Finished sysstat.service - Resets System Activity Logs. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 1780s Sep 09 17:37:07 autopkgtest cloud-init[690]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu1 running 'modules:config' at Mon, 09 Sep 2024 17:37:07 +0000. Up 12.51 seconds. 1780s Sep 09 17:37:07 autopkgtest systemd-logind[791]: New seat seat0. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 1780s Sep 09 17:37:07 autopkgtest rngd[867]: rngd 2.4 starting up... 1780s Sep 09 17:37:07 autopkgtest systemd-logind[791]: Watching system buttons on /dev/input/event0 (QEMU QEMU USB Keyboard) 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 1780s Sep 09 17:37:07 autopkgtest rngd[867]: entropy feed to the kernel ready 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 1780s Sep 09 17:37:07 autopkgtest kernel: kauditd_printk_skb: 110 callbacks suppressed 1780s Sep 09 17:37:07 autopkgtest kernel: audit: type=1400 audit(1725903427.820:121): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=831 comm="apparmor_parser" 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 1780s Sep 09 17:37:07 autopkgtest udisksd[795]: Acquired the name org.freedesktop.UDisks2 on the system message bus 1780s Sep 09 17:37:07 autopkgtest sh[777]: Completed socket interaction for boot stage config 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 1780s Sep 09 17:37:07 autopkgtest rsyslogd[876]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2406.0] 1780s Sep 09 17:37:07 autopkgtest rsyslogd[876]: rsyslogd's groupid changed to 102 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 1780s Sep 09 17:37:07 autopkgtest rsyslogd[876]: rsyslogd's userid changed to 102 1780s Sep 09 17:37:07 autopkgtest rsyslogd[876]: [origin software="rsyslogd" swVersion="8.2406.0" x-pid="876" x-info="https://www.rsyslog.com"] start 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 1780s Sep 09 17:37:07 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 1780s Sep 09 17:37:07 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 1780s Sep 09 17:37:08 autopkgtest cloud-init[690]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu1 running 'modules:final' at Mon, 09 Sep 2024 17:37:07 +0000. Up 12.81 seconds. 1780s Sep 09 17:37:08 autopkgtest cloud-init[690]: Cloud-init v. 24.4~3+really24.3.1-0ubuntu1 finished at Mon, 09 Sep 2024 17:37:08 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 12.88 seconds 1780s Sep 09 17:37:08 autopkgtest sh[893]: Completed socket interaction for boot stage final 1780s Sep 09 17:37:08 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 1780s Sep 09 17:37:08 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 1780s Sep 09 17:37:08 autopkgtest systemd[1]: Startup finished in 1.849s (kernel) + 11.042s (userspace) = 12.891s. 1780s Sep 09 17:37:08 autopkgtest kernel: fbcon: Taking over console 1780s Sep 09 17:37:08 autopkgtest kernel: Console: switching to colour frame buffer device 128x48 1780s Sep 09 17:37:08 autopkgtest systemd[1]: cloud-init-main.service: Deactivated successfully. 1780s Sep 09 17:37:08 autopkgtest systemd[1]: cloud-init-main.service: Unit process 689 (sh) remains running after unit stopped. 1780s Sep 09 17:37:08 autopkgtest systemd[1]: cloud-init-main.service: Unit process 690 (tee) remains running after unit stopped. 1780s Sep 09 17:37:08 autopkgtest systemd[1]: cloud-init-main.service: Consumed 1.228s CPU time, 106.3M memory peak. 1780s Sep 09 17:37:08 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 1780s Sep 09 17:37:08 autopkgtest sshd[944]: Server listening on :: port 22. 1780s Sep 09 17:37:08 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 1780s Sep 09 17:37:08 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 1780s Sep 09 17:37:08 autopkgtest sshd[945]: Accepted publickey for ubuntu from 10.136.6.184 port 52972 ssh2: RSA SHA256:h+sR5tlNZDfTFbz7cAH7wlRKfPAD8MpCdKJaoGeL2vg 1780s Sep 09 17:37:08 autopkgtest sshd[945]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 1780s Sep 09 17:37:08 autopkgtest sshd[945]: pam_systemd(sshd:session): New sd-bus connection (system-bus-pam-systemd-945) opened. 1780s Sep 09 17:37:08 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 1780s Sep 09 17:37:08 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 1780s Sep 09 17:37:08 autopkgtest systemd-logind[791]: New session 1 of user ubuntu. 1780s Sep 09 17:37:08 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 1780s Sep 09 17:37:08 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 1780s Sep 09 17:37:08 autopkgtest (systemd)[949]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 1780s Sep 09 17:37:08 autopkgtest systemd-logind[791]: New session 2 of user ubuntu. 1780s Sep 09 17:37:08 autopkgtest systemd[949]: Queued start job for default target default.target. 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Created slice app.slice - User Application Slice. 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Reached target paths.target - Paths. 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Reached target timers.target - Timers. 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Starting dbus.socket - D-Bus User Message Bus Socket... 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Listening on keyboxd.socket - GnuPG public key management service. 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Listening on dbus.socket - D-Bus User Message Bus Socket. 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Reached target sockets.target - Sockets. 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Reached target basic.target - Basic System. 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Reached target default.target - Main User Target. 1780s Sep 09 17:37:09 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 1780s Sep 09 17:37:09 autopkgtest systemd[949]: Startup finished in 206ms. 1780s Sep 09 17:37:09 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 1780s Sep 09 17:37:14 autopkgtest sudo[977]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 1780s Sep 09 17:37:14 autopkgtest sudo[977]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:37:14 autopkgtest sudo[977]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:37:36 autopkgtest systemd-timesyncd[401]: Contacted time server 185.125.190.58:123 (ntp.ubuntu.com). 1780s Sep 09 17:37:36 autopkgtest systemd-timesyncd[401]: Initial clock synchronization to Mon 2024-09-09 17:37:36.591506 UTC. 1780s Sep 09 17:37:36 autopkgtest systemd-resolved[398]: Clock change detected. Flushing caches. 1780s Sep 09 17:37:52 autopkgtest sudo[983]: 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' 1780s Sep 09 17:37:52 autopkgtest sudo[983]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:37:52 autopkgtest sudo[983]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:37:52 autopkgtest sudo[995]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.d4ADz3 1780s Sep 09 17:37:52 autopkgtest sudo[995]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:37:52 autopkgtest sudo[995]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:37:58 autopkgtest sudo[1005]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.d4ADz3/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.d4ADz3/autopkgtest-reboot' 1780s Sep 09 17:37:58 autopkgtest sudo[1005]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:37:58 autopkgtest sudo[1005]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:38:20 autopkgtest sudo[1017]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.d4ADz3/autopkgtest-reboot 1780s Sep 09 17:38:20 autopkgtest sudo[1017]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:38:20 autopkgtest sudo[1017]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:38:20 autopkgtest sudo[1027]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.d4ADz3/autopkgtest-reboot /tmp/autopkgtest-reboot 1780s Sep 09 17:38:20 autopkgtest sudo[1027]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:38:20 autopkgtest sudo[1027]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:38:31 autopkgtest sudo[1037]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.d4ADz3/autopkgtest-reboot /sbin/autopkgtest-reboot 1780s Sep 09 17:38:31 autopkgtest sudo[1037]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:38:31 autopkgtest sudo[1037]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:38:31 autopkgtest sudo[1047]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.d4ADz3 1780s Sep 09 17:38:31 autopkgtest sudo[1047]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:38:31 autopkgtest sudo[1047]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:38:57 autopkgtest sudo[1057]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.d4ADz3/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.d4ADz3/autopkgtest-reboot-prepare' 1780s Sep 09 17:38:57 autopkgtest sudo[1057]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:38:57 autopkgtest sudo[1057]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:38:57 autopkgtest sudo[1069]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.d4ADz3/autopkgtest-reboot-prepare 1780s Sep 09 17:38:57 autopkgtest sudo[1069]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:38:57 autopkgtest sudo[1069]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:39:20 autopkgtest sudo[1079]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.d4ADz3/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 1780s Sep 09 17:39:20 autopkgtest sudo[1079]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:39:20 autopkgtest sudo[1079]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:39:21 autopkgtest sudo[1089]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 1780s Sep 09 17:39:21 autopkgtest sudo[1089]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:39:21 autopkgtest sudo[1089]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:39:21 autopkgtest sudo[1099]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 1780s Sep 09 17:39:21 autopkgtest sudo[1099]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:39:21 autopkgtest sudo[1099]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:39:28 autopkgtest sudo[1109]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.d4ADz3/testbed-packages' 1780s Sep 09 17:39:28 autopkgtest sudo[1109]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:39:28 autopkgtest sudo[1109]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:39:29 autopkgtest sudo[1120]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.d4ADz3/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.d4ADz3/autopkgtest-reboot' 1780s Sep 09 17:39:31 autopkgtest sudo[1141]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:39:31 autopkgtest sudo[1141]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:39:46 autopkgtest sudo[1153]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.d4ADz3/autopkgtest-reboot 1780s Sep 09 17:39:46 autopkgtest sudo[1153]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:39:46 autopkgtest sudo[1153]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:39:51 autopkgtest sudo[1163]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.d4ADz3/autopkgtest-reboot /tmp/autopkgtest-reboot 1780s Sep 09 17:39:51 autopkgtest sudo[1163]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:39:51 autopkgtest sudo[1163]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:39:52 autopkgtest sudo[1173]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.d4ADz3/autopkgtest-reboot /sbin/autopkgtest-reboot 1780s Sep 09 17:39:52 autopkgtest sudo[1173]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:39:52 autopkgtest sudo[1173]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:39:58 autopkgtest sudo[1183]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.d4ADz3 1780s Sep 09 17:39:58 autopkgtest sudo[1183]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:39:58 autopkgtest sudo[1183]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:39:58 autopkgtest sudo[1193]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.d4ADz3/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.d4ADz3/autopkgtest-reboot-prepare' 1780s Sep 09 17:39:58 autopkgtest sudo[1193]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:39:58 autopkgtest sudo[1193]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:40:09 autopkgtest sudo[1205]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.d4ADz3/autopkgtest-reboot-prepare 1780s Sep 09 17:40:09 autopkgtest sudo[1205]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:40:09 autopkgtest sudo[1205]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:40:12 autopkgtest sudo[1215]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.d4ADz3/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 1780s Sep 09 17:40:12 autopkgtest sudo[1215]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:40:12 autopkgtest sudo[1215]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:40:19 autopkgtest sudo[1225]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 1780s Sep 09 17:40:19 autopkgtest sudo[1225]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:40:19 autopkgtest sudo[1225]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:40:19 autopkgtest sudo[1235]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 1780s Sep 09 17:40:19 autopkgtest sudo[1235]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:40:19 autopkgtest sudo[1235]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:40:20 autopkgtest systemd[1]: Starting sysstat-collect.service - system activity accounting tool... 1780s Sep 09 17:40:20 autopkgtest systemd[1]: sysstat-collect.service: Deactivated successfully. 1780s Sep 09 17:40:20 autopkgtest systemd[1]: Finished sysstat-collect.service - system activity accounting tool. 1780s Sep 09 17:40:40 autopkgtest sudo[1248]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.d4ADz3 1780s Sep 09 17:40:40 autopkgtest sudo[1248]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:40:40 autopkgtest sudo[1248]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:41:06 autopkgtest sudo[1258]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.d4ADz3/2-autopkgtest-satdep.deb' 1780s Sep 09 17:41:06 autopkgtest sudo[1258]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:41:06 autopkgtest sudo[1258]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:41:27 autopkgtest sudo[1269]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.d4ADz3/2-autopkgtest-satdep.deb 1780s Sep 09 17:41:27 autopkgtest sudo[1269]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:41:27 autopkgtest sudo[1269]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:41:44 autopkgtest sudo[1279]: 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.d4ADz3/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' 1780s Sep 09 17:41:44 autopkgtest sudo[1279]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:41:48 autopkgtest systemd[1]: Reload requested from client PID 1519 ('systemctl') (unit session-1.scope)... 1780s Sep 09 17:41:48 autopkgtest systemd[1]: Reloading... 1780s Sep 09 17:41:48 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. 1780s Sep 09 17:41:48 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. 1780s Sep 09 17:41:48 autopkgtest systemd[1]: Reloading finished in 226 ms. 1780s Sep 09 17:41:48 autopkgtest systemd[1]: Reload requested from client PID 1568 ('systemctl') (unit session-1.scope)... 1780s Sep 09 17:41:48 autopkgtest systemd[1]: Reloading... 1780s Sep 09 17:41:48 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. 1780s Sep 09 17:41:48 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. 1780s Sep 09 17:41:48 autopkgtest systemd[1]: Reloading finished in 205 ms. 1780s Sep 09 17:41:49 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 1780s Sep 09 17:41:49 autopkgtest tgtd[1613]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 1780s Sep 09 17:41:49 autopkgtest tgtd[1613]: tgtd: work_timer_start(146) use timer_fd based scheduler 1780s Sep 09 17:41:49 autopkgtest tgtd[1613]: tgtd: bs_init(387) use signalfd notification 1780s Sep 09 17:41:49 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 1780s Sep 09 17:41:49 autopkgtest systemd[1]: Reload requested from client PID 1640 ('systemctl') (unit session-1.scope)... 1780s Sep 09 17:41:49 autopkgtest systemd[1]: Reloading... 1780s Sep 09 17:41:49 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 1780s Sep 09 17:41:49 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 1780s Sep 09 17:41:49 autopkgtest systemd[1]: Reloading finished in 218 ms. 1780s Sep 09 17:41:49 autopkgtest systemd[1]: Reload requested from client PID 1682 ('systemctl') (unit session-1.scope)... 1780s Sep 09 17:41:49 autopkgtest systemd[1]: Reloading... 1780s Sep 09 17:41:49 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 1780s Sep 09 17:41:49 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 1780s Sep 09 17:41:49 autopkgtest systemd[1]: Reloading finished in 188 ms. 1780s Sep 09 17:41:50 autopkgtest systemd[1]: Reload requested from client PID 1727 ('systemctl') (unit session-1.scope)... 1780s Sep 09 17:41:50 autopkgtest systemd[1]: Reloading... 1780s Sep 09 17:41:50 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. 1780s Sep 09 17:41:50 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. 1780s Sep 09 17:41:50 autopkgtest systemd[1]: Reloading finished in 185 ms. 1780s Sep 09 17:41:50 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 1780s Sep 09 17:41:50 autopkgtest systemd[1]: Reload requested from client PID 1777 ('systemctl') (unit session-1.scope)... 1780s Sep 09 17:41:50 autopkgtest systemd[1]: Reloading... 1780s Sep 09 17:41:50 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. 1780s Sep 09 17:41:50 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. 1780s Sep 09 17:41:50 autopkgtest systemd[1]: Reloading finished in 175 ms. 1780s Sep 09 17:41:50 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 1780s Sep 09 17:41:50 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 1780s Sep 09 17:41:50 autopkgtest systemd[1]: Reload requested from client PID 1831 ('systemctl') (unit session-1.scope)... 1780s Sep 09 17:41:50 autopkgtest systemd[1]: Reloading... 1780s Sep 09 17:41:50 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. 1780s Sep 09 17:41:50 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. 1780s Sep 09 17:41:50 autopkgtest systemd[1]: Reloading finished in 203 ms. 1780s Sep 09 17:42:02 autopkgtest sudo[1279]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:42:03 autopkgtest sudo[5681]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 1780s Sep 09 17:42:03 autopkgtest sudo[5681]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:42:03 autopkgtest sudo[5681]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:42:03 autopkgtest sudo[5691]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 1780s Sep 09 17:42:03 autopkgtest sudo[5691]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:42:03 autopkgtest sudo[5691]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:42:05 autopkgtest sudo[5701]: 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 1780s Sep 09 17:42:05 autopkgtest sudo[5701]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:42:06 autopkgtest sudo[5701]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:42:08 autopkgtest iprinit[816]: Timeout reached. Ensure the sg module is loaded, then run iprinit manually to ensure all ipr RAID adapters are running optimally 1780s Sep 09 17:42:14 autopkgtest sudo[5714]: 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 1780s Sep 09 17:42:14 autopkgtest sudo[5714]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:42:15 autopkgtest sudo[5714]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:42:38 autopkgtest sudo[5726]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 1780s Sep 09 17:42:38 autopkgtest sudo[5726]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:42:38 autopkgtest sudo[5726]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:42:40 autopkgtest systemd[949]: launchpadlib-cache-clean.service - Clean up old files in the Launchpadlib cache was skipped because of an unmet condition check (ConditionPathExists=/home/ubuntu/.launchpadlib/api.launchpad.net/cache). 1780s Sep 09 17:42:49 autopkgtest sudo[5738]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 1780s Sep 09 17:42:49 autopkgtest sudo[5738]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:42:49 autopkgtest sudo[5738]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:42:50 autopkgtest sudo[5748]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.d4ADz3/tgtbasedmpaths-packages.all' 1780s Sep 09 17:42:50 autopkgtest sudo[5748]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1780s Sep 09 17:42:50 autopkgtest sudo[5748]: pam_unix(sudo:session): session closed for user root 1780s Sep 09 17:43:09 autopkgtest sudo[5759]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 1781s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1781s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1781s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 1781s latency : target=0, window=0, percentile=100.00%, depth=1 1781s 1781s Run status group 0 (all jobs): 1781s WRITE: bw=187MiB/s (196MB/s), 187MiB/s-187MiB/s (196MB/s-196MB/s), io=87.5MiB (91.8MB), run=469-469msec 1781s 1781s Disk stats (read/write): 1781s dm-0: ios=1/1140, sectors=8/146048, merge=0/0, ticks=0/389, in_queue=389, util=79.84%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/99, aggrin_queue=99, aggrutil=78.15% 1781s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 1781s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 1781s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 1781s sda: ios=1/1402, sectors=8/179280, merge=0/0, ticks=0/398, in_queue=398, util=78.15% 1781s + echo Starting the path changes in background 1781s + date +Pre FIO %H:%M:%S.%N 1781s + fio --max-jobs=4 /tmp/autopkgtest.d4ADz3/tgtbasedmpaths-artifacts/path-change-check.fio 1781s Starting the path changes in background 1781s Pre FIO 17:44:03.813385735 1781s 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 1781s fio-3.37 1781s Starting 1 thread 1964s 1964s verify-phase: (groupid=0, jobs=1): err= 0: pid=6120: Mon Sep 9 17:47:04 2024 1964s read: IOPS=4547, BW=284MiB/s (298MB/s)(50.0GiB/180001msec) 1964s clat (usec): min=85, max=55313, avg=194.50, stdev=180.08 1964s lat (usec): min=85, max=55313, avg=194.62, stdev=180.08 1964s clat percentiles (usec): 1964s | 1.00th=[ 111], 5.00th=[ 124], 10.00th=[ 133], 20.00th=[ 145], 1964s | 30.00th=[ 155], 40.00th=[ 165], 50.00th=[ 176], 60.00th=[ 186], 1964s | 70.00th=[ 198], 80.00th=[ 215], 90.00th=[ 239], 95.00th=[ 269], 1964s | 99.00th=[ 914], 99.50th=[ 1188], 99.90th=[ 1893], 99.95th=[ 2311], 1964s | 99.99th=[ 3458] 1964s bw ( KiB/s): min=146688, max=411392, per=100.00%, avg=291478.55, stdev=47454.00, samples=359 1964s iops : min= 2292, max= 6428, avg=4554.32, stdev=741.47, samples=359 1964s lat (usec) : 100=0.11%, 250=92.27%, 500=6.08%, 750=0.26%, 1000=0.43% 1964s lat (msec) : 2=0.78%, 4=0.08%, 10=0.01%, 20=0.01%, 50=0.01% 1964s lat (msec) : 100=0.01% 1964s cpu : usr=12.49%, sys=7.02%, ctx=818694, majf=0, minf=1 1964s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 1964s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1964s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1964s issued rwts: total=818507,0,0,0 short=0,0,0,0 dropped=0,0,0,0 1964s latency : target=0, window=0, percentile=100.00%, depth=1 1964s 1964s Run status group 0 (all jobs): 1964s READ: bw=284MiB/s (298MB/s), 284MiB/s-284MiB/s (298MB/s-298MB/s), io=50.0GiB (53.6GB), run=180001-180001msec 1964s 1964s Disk stats (read/write): 1964s dm-0: ios=818798/11, sectors=104729656/12944, merge=20/10, ticks=162175/187, in_queue=162507, util=100.00%, aggrios=56935/2, aggsectors=7282030/3236, aggrmerge=0/0, aggrticks=10032/10, aggrin_queue=10043, aggrutil=99.16% 1964s sdd: ios=90736/0, sectors=11605888/0, merge=0/0, ticks=16086/0, in_queue=16086, util=39.72% 1964s sdb: ios=43317/0, sectors=5538744/0, merge=0/0, ticks=8183/0, in_queue=8183, util=50.04% 1964s sdc: ios=43416/0, sectors=5553280/0, merge=0/0, ticks=8039/0, in_queue=8039, util=32.91% 1964s sda: ios=50273/10, sectors=6430208/12944, merge=0/0, ticks=7823/42, in_queue=7866, util=99.16% 1964s + date +Post FIO %H:%M:%S.%N 1964s + echo FIO verify test with changing paths - OK 1964s + echo Report log of background activity 1964s + cat /tmp/autopkgtest.d4ADz3/tgtbasedmpaths-artifacts/test-background.log 1964s + sync 1964s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1964s + echo Final stats 1964s + iscsiadm --mode session --stats 1964s + journalctl --no-pager -u multipathd 1964s + echo Check final path status 1964s + multipath -ll 1964s + multipath -ll 1964s + grep --count status= 1964s + diskc=2 1964s + multipath -ll 1964s + grep --count status=active 1964s + diska=1 1964s + multipath -ll 1964s + grep --count status=enabled 1964s + diske=1 1964s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 1964s + echo OK 1964s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 1964s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 1964s autopkgtest [17:47:04]: test tgtbasedmpaths: -----------------------] 1964s Post FIO 17:47:04.157324317 1964s FIO verify test with changing paths - OK 1964s Report log of background activity 1964s + iscsiadm --mode session 1964s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s + sleep 10s 1964s + date +MP report (expect 4) %H:%M:%S.%N 1964s MP report (expect 4) 17:44:13.826983309 1964s + multipath -ll 1964s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1964s size=100M features='0' hwhandler='0' wp=rw 1964s |-+- policy='service-time 0' prio=1 status=active 1964s | `- 0:0:0:1 sda 8:0 active ready running 1964s |-+- policy='service-time 0' prio=1 status=enabled 1964s | `- 1:0:0:1 sdb 8:16 active ready running 1964s |-+- policy='service-time 0' prio=1 status=enabled 1964s | `- 2:0:0:1 sdc 8:32 active ready running 1964s `-+- policy='service-time 0' prio=1 status=enabled 1964s `- 3:0:0:1 sdd 8:48 active ready running 1964s + date +UN-plug path 1 %H:%M:%S.%N 1964s UN-plug path 1 17:44:13.858909594 1964s + iscsiadm --mode session -r 1 -u 1964s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1964s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1964s + iscsiadm --mode session 1964s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s + sleep 10s 1964s + date +MP report (expect 3) %H:%M:%S.%N 1964s MP report (expect 3) 17:44:23.953059420 1964s + multipath -ll 1964s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1964s size=100M features='0' hwhandler='0' wp=rw 1964s |-+- policy='service-time 0' prio=1 status=active 1964s | `- 1:0:0:1 sdb 8:16 active ready running 1964s |-+- policy='service-time 0' prio=1 status=enabled 1964s | `- 2:0:0:1 sdc 8:32 active ready running 1964s `-+- policy='service-time 0' prio=1 status=enabled 1964s `- 3:0:0:1 sdd 8:48 active ready running 1964s + date +UN-plug path 2 %H:%M:%S.%N 1964s UN-plug path 2 17:44:23.986924472 1964s + iscsiadm --mode session -r 2 -u 1964s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1964s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1964s + iscsiadm --mode session 1964s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s + sleep 10s 1964s + date +MP report (expect 2) %H:%M:%S.%N 1964s MP report (expect 2) 17:44:34.063737704 1964s + multipath -ll 1964s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1964s size=100M features='0' hwhandler='0' wp=rw 1964s |-+- policy='service-time 0' prio=1 status=active 1964s | `- 2:0:0:1 sdc 8:32 active ready running 1964s `-+- policy='service-time 0' prio=1 status=enabled 1964s `- 3:0:0:1 sdd 8:48 active ready running 1964s + date +UN-plug path 3 %H:%M:%S.%N 1964s UN-plug path 3 17:44:34.083399221 1964s + iscsiadm --mode session -r 3 -u 1964s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1964s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1964s + iscsiadm --mode session 1964s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s + sleep 10s 1964s + date +MP report (expect 1) %H:%M:%S.%N 1964s MP report (expect 1) 17:44:44.201490138 1964s + multipath -ll 1964s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1964s size=100M features='0' hwhandler='0' wp=rw 1964s `-+- policy='service-time 0' prio=1 status=active 1964s `- 3:0:0:1 sdd 8:48 active ready running 1964s + date +Add paths 5/6/7/8 %H:%M:%S.%N 1964s Add paths 5/6/7/8 17:44:44.215250130 1964s + iscsiadm --mode session -r 4 --op new 1964s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1964s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1964s + iscsiadm --mode session -r 4 --op new 1964s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1964s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1964s + iscsiadm --mode session -r 4 --op new 1964s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1964s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1964s + iscsiadm --mode session -r 4 --op new 1964s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1964s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1964s + iscsiadm --mode session 1964s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s + sleep 10s 1964s + date +MP report (expect 5) %H:%M:%S.%N 1964s MP report (expect 5) 17:44:54.301041973 1964s + multipath -ll 1964s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1964s size=100M features='0' hwhandler='0' wp=rw 1964s |-+- policy='service-time 0' prio=1 status=active 1964s | `- 3:0:0:1 sdd 8:48 active ready running 1964s |-+- policy='service-time 0' prio=1 status=enabled 1964s | `- 0:0:0:1 sda 8:0 active ready running 1964s |-+- policy='service-time 0' prio=1 status=enabled 1964s | `- 1:0:0:1 sdb 8:16 active ready running 1964s |-+- policy='service-time 0' prio=1 status=enabled 1964s | `- 2:0:0:1 sdc 8:32 active ready running 1964s `-+- policy='service-time 0' prio=1 status=enabled 1964s `- 4:0:0:1 sde 8:64 active ready running 1964s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 1964s UN-plug multiple paths 4/7/8 17:44:54.327742987 1964s + iscsiadm --mode session -r 4 -u 1964s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1964s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1964s + iscsiadm --mode session -r 7 -u 1964s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1964s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1964s + iscsiadm --mode session -r 8 -u 1964s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1964s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1964s + iscsiadm --mode session 1964s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1964s + sleep 10s 1964s + date +Restart multipath daemon %H:%M:%S.%N 1964s Restart multipath daemon 17:45:04.585812495 1964s + systemctl restart multipathd 1964s + sleep 10s 1964s + date +Final background report (expect 2) %H:%M:%S.%N 1964s Final background report (expect 2) 17:45:14.676337233 1964s + multipath -ll 1964s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1964s size=100M features='0' hwhandler='0' wp=rw 1964s |-+- policy='service-time 0' prio=1 status=active 1964s | `- 0:0:0:1 sda 8:0 active ready running 1964s `-+- policy='service-time 0' prio=1 status=enabled 1964s `- 1:0:0:1 sdb 8:16 active ready running 1964s Final stats 1964s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1964s iSCSI SNMP: 1964s txdata_octets: 28255704 1964s rxdata_octets: 38555613764 1964s noptx_pdus: 0 1964s scsicmd_pdus: 588393 1964s tmfcmd_pdus: 0 1964s login_pdus: 0 1964s text_pdus: 0 1964s dataout_pdus: 0 1964s logout_pdus: 0 1964s snack_pdus: 0 1964s noprx_pdus: 0 1964s scsirsp_pdus: 588393 1964s tmfrsp_pdus: 0 1964s textrsp_pdus: 0 1964s datain_pdus: 588361 1964s logoutrsp_pdus: 0 1964s r2t_pdus: 0 1964s async_pdus: 0 1964s rjt_pdus: 0 1964s digest_err: 0 1964s timeout_err: 0 1964s iSCSI Extended: 1964s tx_sendpage_failures: 0 1964s rx_discontiguous_hdr: 0 1964s eh_abort_cnt: 0 1964s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1964s iSCSI SNMP: 1964s txdata_octets: 6504 1964s rxdata_octets: 1580500 1964s noptx_pdus: 0 1964s scsicmd_pdus: 106 1964s tmfcmd_pdus: 0 1964s login_pdus: 0 1964s text_pdus: 0 1964s dataout_pdus: 0 1964s logout_pdus: 0 1964s snack_pdus: 0 1964s noprx_pdus: 0 1964s scsirsp_pdus: 106 1964s tmfrsp_pdus: 0 1964s textrsp_pdus: 0 1964s datain_pdus: 84 1964s logoutrsp_pdus: 0 1964s r2t_pdus: 0 1964s async_pdus: 0 1964s rjt_pdus: 0 1964s digest_err: 0 1964s timeout_err: 0 1964s iSCSI Extended: 1964s tx_sendpage_failures: 0 1964s rx_discontiguous_hdr: 0 1964s eh_abort_cnt: 0 1964s Sep 09 15:16:16 ubuntu multipathd[335]: multipathd v0.9.9: start up 1964s Sep 09 15:16:16 ubuntu multipathd[335]: reconfigure: setting up paths and maps 1964s Sep 09 15:16:16 ubuntu multipathd[335]: _check_bindings_file: failed to read header from /etc/multipath/bindings 1964s Sep 09 15:16:16 ubuntu multipathd[335]: updated bindings file /etc/multipath/bindings 1964s Sep 09 15:16:16 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1964s Sep 09 15:18:57 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1964s Sep 09 15:18:57 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i multipathd[335]: multipathd: shut down 1964s Sep 09 15:18:57 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 1964s Sep 09 15:18:57 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1964s -- Boot 5d97a3f9531d45eeacad9f45ba3ff199 -- 1964s Sep 09 15:19:09 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i multipathd[280]: multipathd v0.9.9: start up 1964s Sep 09 15:19:09 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i multipathd[280]: reconfigure: setting up paths and maps 1964s Sep 09 15:19:09 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1964s Sep 09 15:19:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i multipathd[280]: multipathd: shut down 1964s Sep 09 15:19:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1964s Sep 09 15:19:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 1964s Sep 09 15:19:25 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1964s -- Boot 7986534b7dd24384b3afc89fdbc51bdf -- 1964s Sep 09 17:34:42 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i multipathd[311]: multipathd v0.9.9: start up 1964s Sep 09 17:34:42 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i multipathd[311]: reconfigure: setting up paths and maps 1964s Sep 09 17:34:42 auto-syncubuntu-oracular-daily-ppc64el-server-20240908-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1964s Sep 09 17:36:44 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1964s Sep 09 17:36:44 autopkgtest multipathd[311]: multipathd: shut down 1964s Sep 09 17:36:44 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 1964s Sep 09 17:36:44 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1964s -- Boot 4911a21aa9b34100abfc1d47a2560e71 -- 1964s Sep 09 17:36:57 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1964s Sep 09 17:36:57 autopkgtest multipathd[328]: multipathd v0.9.9: start up 1964s Sep 09 17:36:57 autopkgtest multipathd[328]: reconfigure: setting up paths and maps 1964s Sep 09 17:36:57 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1964s Sep 09 17:43:54 autopkgtest multipathd[328]: updated bindings file /etc/multipath/bindings 1964s Sep 09 17:43:54 autopkgtest multipathd[328]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 1964s Sep 09 17:43:54 autopkgtest multipathd[328]: sda [8:0]: path added to devmap mpatha 1964s Sep 09 17:43:54 autopkgtest multipathd[328]: mpatha: performing delayed actions 1964s Sep 09 17:43:54 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 1964s Sep 09 17:44:13 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 1964s Sep 09 17:44:13 autopkgtest multipathd[328]: check_removed_paths: sda: freeing path in removed state 1964s Sep 09 17:44:13 autopkgtest multipathd[328]: 8:0: path removed from map mpatha 1964s Sep 09 17:44:24 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 1964s Sep 09 17:44:24 autopkgtest multipathd[328]: check_removed_paths: sdb: freeing path in removed state 1964s Sep 09 17:44:24 autopkgtest multipathd[328]: 8:16: path removed from map mpatha 1964s Sep 09 17:44:34 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 1964s Sep 09 17:44:34 autopkgtest multipathd[328]: check_removed_paths: sdc: freeing path in removed state 1964s Sep 09 17:44:34 autopkgtest multipathd[328]: 8:32: path removed from map mpatha 1964s Sep 09 17:44:44 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1] 1964s Sep 09 17:44:44 autopkgtest multipathd[328]: sda [8:0]: path added to devmap mpatha 1964s Sep 09 17:44:44 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 1964s Sep 09 17:44:44 autopkgtest multipathd[328]: sdb [8:16]: path added to devmap mpatha 1964s Sep 09 17:44:44 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 1964s Sep 09 17:44:44 autopkgtest multipathd[328]: sdc [8:32]: path added to devmap mpatha 1964s Sep 09 17:44:44 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 1964s Sep 09 17:44:44 autopkgtest multipathd[328]: sde [8:64]: path added to devmap mpatha 1964s Sep 09 17:44:54 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 1964s Sep 09 17:44:54 autopkgtest multipathd[328]: check_removed_paths: sdd: freeing path in removed state 1964s Sep 09 17:44:54 autopkgtest multipathd[328]: 8:48: path removed from map mpatha 1964s Sep 09 17:44:54 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:64 1] 1964s Sep 09 17:44:54 autopkgtest multipathd[328]: check_removed_paths: sdc: freeing path in removed state 1964s Sep 09 17:44:54 autopkgtest multipathd[328]: 8:32: path removed from map mpatha 1964s Sep 09 17:44:54 autopkgtest multipathd[328]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 1964s Sep 09 17:44:54 autopkgtest multipathd[328]: check_removed_paths: sde: freeing path in removed state 1964s Sep 09 17:44:54 autopkgtest multipathd[328]: 8:64: path removed from map mpatha 1964s Sep 09 17:45:04 autopkgtest multipathd[328]: multipathd: shut down 1964s Sep 09 17:45:04 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1964s Sep 09 17:45:04 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 1964s Sep 09 17:45:04 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1964s Sep 09 17:45:04 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1964s Sep 09 17:45:04 autopkgtest multipathd[6497]: multipathd v0.9.9: start up 1964s Sep 09 17:45:04 autopkgtest multipathd[6497]: reconfigure: setting up paths and maps 1964s Sep 09 17:45:04 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1964s Check final path status 1964s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1964s size=100M features='0' hwhandler='0' wp=rw 1964s |-+- policy='service-time 0' prio=1 status=active 1964s | `- 0:0:0:1 sda 8:0 active ready running 1964s `-+- policy='service-time 0' prio=1 status=enabled 1964s `- 1:0:0:1 sdb 8:16 active ready running 1964s OK 1964s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1964s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1964s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1964s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1977s autopkgtest [17:47:19]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 1977s tgtbasedmpaths PASS 1983s autopkgtest [17:47:25]: @@@@@@@@@@@@@@@@@@@@ summary 1983s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 1983s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 1983s kpartx-file-loopback PASS 1983s tgtbasedmpaths PASS 2073s nova [W] Using flock in prodstack6-ppc64el 2073s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240909-171422-juju-7f2275-prod-proposed-migration-environment-2-dfcc926e-cc0e-4e9a-8fef-a9dbd88708c3 from image adt/ubuntu-oracular-ppc64el-server-20240909.img (UUID 15f8af18-895e-46e8-b444-c48790acc71b)... 2073s nova [W] Using flock in prodstack6-ppc64el 2073s flock: timeout while waiting to get lock 2073s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240909-171422-juju-7f2275-prod-proposed-migration-environment-2-dfcc926e-cc0e-4e9a-8fef-a9dbd88708c3 from image adt/ubuntu-oracular-ppc64el-server-20240909.img (UUID 15f8af18-895e-46e8-b444-c48790acc71b)...