0s autopkgtest [20:47:27]: starting date and time: 2024-07-29 20:47:27+0000 0s autopkgtest [20:47:27]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [20:47:27]: host juju-7f2275-prod-proposed-migration-environment-2; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.d9zj9pmj/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:systemd,src:debootstrap,src:dpdk,src:nftables --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=systemd/256.4-1ubuntu3 debootstrap/1.0.137ubuntu2 dpdk/23.11.1-2 nftables/1.1.0-2' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-2@bos01-ppc64el-17.secgroup --name adt-oracular-ppc64el-multipath-tools-20240729-204727-juju-7f2275-prod-proposed-migration-environment-2-c4e89d95-e386-4b4f-8070-a18e389e33b5 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-2 --net-id=net_prod-proposed-migration -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://us.ports.ubuntu.com/ubuntu-ports/ 155s autopkgtest [20:50:02]: testbed dpkg architecture: ppc64el 156s autopkgtest [20:50:03]: testbed apt version: 2.9.6 156s autopkgtest [20:50:03]: @@@@@@@@@@@@@@@@@@@@ test bed setup 160s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 161s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4288 B] 161s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [48.2 kB] 161s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 161s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [495 kB] 161s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [80.7 kB] 161s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2116 B] 161s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 161s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 161s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [434 kB] 161s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [8952 B] 161s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1448 B] 161s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 163s Fetched 1211 kB in 1s (1451 kB/s) 163s Reading package lists... 199s Reading package lists... 199s Building dependency tree... 199s Reading state information... 199s Calculating upgrade... 199s The following NEW packages will be installed: 199s systemd-cryptsetup 199s The following packages will be upgraded: 199s gettext-base libnftables1 libnss-systemd libpam-systemd libsystemd-shared 199s libsystemd0 libudev1 nftables systemd systemd-resolved systemd-sysv 199s systemd-timesyncd udev 200s 13 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 200s Need to get 10.8 MB of archives. 200s After this operation, 171 kB disk space will be freed. 200s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd ppc64el 256.4-1ubuntu3 [3740 kB] 200s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-timesyncd ppc64el 256.4-1ubuntu3 [42.6 kB] 200s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-resolved ppc64el 256.4-1ubuntu3 [370 kB] 200s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd-shared ppc64el 256.4-1ubuntu3 [2490 kB] 200s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd0 ppc64el 256.4-1ubuntu3 [564 kB] 200s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-sysv ppc64el 256.4-1ubuntu3 [11.9 kB] 200s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnss-systemd ppc64el 256.4-1ubuntu3 [215 kB] 200s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpam-systemd ppc64el 256.4-1ubuntu3 [326 kB] 200s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el udev ppc64el 256.4-1ubuntu3 [2141 kB] 200s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libudev1 ppc64el 256.4-1ubuntu3 [223 kB] 200s Get:11 http://ftpmaster.internal/ubuntu oracular/main ppc64el gettext-base ppc64el 0.22.5-2 [42.8 kB] 200s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el nftables ppc64el 1.1.0-2 [70.9 kB] 200s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnftables1 ppc64el 1.1.0-2 [451 kB] 200s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-cryptsetup ppc64el 256.4-1ubuntu3 [127 kB] 201s Fetched 10.8 MB in 1s (11.1 MB/s) 201s (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 ... 72844 files and directories currently installed.) 201s Preparing to unpack .../systemd_256.4-1ubuntu3_ppc64el.deb ... 201s Unpacking systemd (256.4-1ubuntu3) over (256-1ubuntu1) ... 201s Preparing to unpack .../systemd-timesyncd_256.4-1ubuntu3_ppc64el.deb ... 201s Unpacking systemd-timesyncd (256.4-1ubuntu3) over (256-1ubuntu1) ... 201s Preparing to unpack .../systemd-resolved_256.4-1ubuntu3_ppc64el.deb ... 201s Unpacking systemd-resolved (256.4-1ubuntu3) over (256-1ubuntu1) ... 201s Preparing to unpack .../libsystemd-shared_256.4-1ubuntu3_ppc64el.deb ... 201s Unpacking libsystemd-shared:ppc64el (256.4-1ubuntu3) over (256-1ubuntu1) ... 201s Preparing to unpack .../libsystemd0_256.4-1ubuntu3_ppc64el.deb ... 201s Unpacking libsystemd0:ppc64el (256.4-1ubuntu3) over (256-1ubuntu1) ... 201s Setting up libsystemd0:ppc64el (256.4-1ubuntu3) ... 201s Setting up libsystemd-shared:ppc64el (256.4-1ubuntu3) ... 201s Setting up systemd (256.4-1ubuntu3) ... 201s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 201s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 202s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 202s (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 ... 72769 files and directories currently installed.) 202s Preparing to unpack .../systemd-sysv_256.4-1ubuntu3_ppc64el.deb ... 202s Unpacking systemd-sysv (256.4-1ubuntu3) over (256-1ubuntu1) ... 202s Preparing to unpack .../libnss-systemd_256.4-1ubuntu3_ppc64el.deb ... 202s Unpacking libnss-systemd:ppc64el (256.4-1ubuntu3) over (256-1ubuntu1) ... 202s Preparing to unpack .../libpam-systemd_256.4-1ubuntu3_ppc64el.deb ... 202s Unpacking libpam-systemd:ppc64el (256.4-1ubuntu3) over (256-1ubuntu1) ... 202s Preparing to unpack .../udev_256.4-1ubuntu3_ppc64el.deb ... 202s Unpacking udev (256.4-1ubuntu3) over (256-1ubuntu1) ... 203s Preparing to unpack .../libudev1_256.4-1ubuntu3_ppc64el.deb ... 203s Unpacking libudev1:ppc64el (256.4-1ubuntu3) over (256-1ubuntu1) ... 203s Setting up libudev1:ppc64el (256.4-1ubuntu3) ... 203s (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 ... 72770 files and directories currently installed.) 203s Preparing to unpack .../gettext-base_0.22.5-2_ppc64el.deb ... 203s Unpacking gettext-base (0.22.5-2) over (0.22.5-1) ... 203s Preparing to unpack .../nftables_1.1.0-2_ppc64el.deb ... 203s Unpacking nftables (1.1.0-2) over (1.0.9-2) ... 203s Preparing to unpack .../libnftables1_1.1.0-2_ppc64el.deb ... 203s Unpacking libnftables1:ppc64el (1.1.0-2) over (1.0.9-2) ... 203s Selecting previously unselected package systemd-cryptsetup. 203s Preparing to unpack .../systemd-cryptsetup_256.4-1ubuntu3_ppc64el.deb ... 203s Unpacking systemd-cryptsetup (256.4-1ubuntu3) ... 203s Setting up systemd-sysv (256.4-1ubuntu3) ... 203s Setting up libnftables1:ppc64el (1.1.0-2) ... 203s Setting up nftables (1.1.0-2) ... 203s Setting up gettext-base (0.22.5-2) ... 203s Setting up libnss-systemd:ppc64el (256.4-1ubuntu3) ... 203s Setting up systemd-cryptsetup (256.4-1ubuntu3) ... 203s Setting up systemd-timesyncd (256.4-1ubuntu3) ... 204s systemd-time-wait-sync.service is a disabled or a static unit not running, not starting it. 204s Setting up udev (256.4-1ubuntu3) ... 205s Setting up libpam-systemd:ppc64el (256.4-1ubuntu3) ... 205s Setting up systemd-resolved (256.4-1ubuntu3) ... 206s Processing triggers for libc-bin (2.39-0ubuntu9) ... 206s Processing triggers for man-db (2.12.1-2) ... 207s Processing triggers for dbus (1.14.10-4ubuntu4) ... 207s Processing triggers for shared-mime-info (2.4-5) ... 207s Processing triggers for initramfs-tools (0.142ubuntu30) ... 207s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 207s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 214s Reading package lists... 215s Building dependency tree... 215s Reading state information... 215s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 221s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 221s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 221s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 221s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 222s Reading package lists... 222s Reading package lists... 222s Building dependency tree... 222s Reading state information... 222s Calculating upgrade... 223s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 223s Reading package lists... 223s Building dependency tree... 223s Reading state information... 223s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 229s autopkgtest [20:51:16]: rebooting testbed after setup commands that affected boot 313s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 362s autopkgtest [20:53:29]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 454s autopkgtest [20:55:01]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 500s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu2 (dsc) [2772 B] 500s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu2 (tar) [588 kB] 500s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu2 (diff) [42.4 kB] 500s gpgv: Signature made Tue Jul 23 21:24:22 2024 UTC 500s gpgv: using RSA key D09F8A854F1055BCFC482C4B23566B906047AFC8 500s gpgv: Can't check signature: No public key 500s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.9-1ubuntu2.dsc: no acceptable signature found 500s autopkgtest [20:55:47]: testing package multipath-tools version 0.9.9-1ubuntu2 501s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 501s autopkgtest [20:55:48]: build not needed 504s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed.autopkgtest [20:55:51]: test kpartx-file-loopback: preparing testbed 504s 537s Reading package lists... 537s Building dependency tree... 537s Reading state information... 538s Starting pkgProblemResolver with broken count: 0 538s Starting 2 pkgProblemResolver with broken count: 0 538s Done 538s The following additional packages will be installed: 538s liburing2 qemu-utils 538s Recommended packages: 538s qemu-block-extra 538s The following NEW packages will be installed: 538s autopkgtest-satdep liburing2 qemu-utils 538s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 538s Need to get 2330 kB/2330 kB of archives. 538s After this operation, 15.4 MB of additional disk space will be used. 538s Get:1 /tmp/autopkgtest.pZgNe4/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [716 B] 538s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 538s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 539s Fetched 2330 kB in 1s (3417 kB/s) 539s Selecting previously unselected package liburing2:ppc64el. 539s (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 ... 72816 files and directories currently installed.) 539s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 539s Unpacking liburing2:ppc64el (2.6-1) ... 539s Selecting previously unselected package qemu-utils. 539s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 539s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 539s Selecting previously unselected package autopkgtest-satdep. 539s Preparing to unpack .../1-autopkgtest-satdep.deb ... 539s Unpacking autopkgtest-satdep (0) ... 539s Setting up liburing2:ppc64el (2.6-1) ... 539s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 539s Setting up autopkgtest-satdep (0) ... 539s Processing triggers for man-db (2.12.1-2) ... 540s Processing triggers for libc-bin (2.39-0ubuntu9) ... 549s (Reading database ... 72836 files and directories currently installed.) 549s Removing autopkgtest-satdep (0) ... 550s autopkgtest [20:56:37]: test kpartx-file-loopback: [----------------------- 550s Formatting 'foo.img', fmt=raw size=20971520 551s Creating new GPT entries in memory. 551s Warning: The kernel is still using the old partition table. 551s The new table will be used at the next reboot or after you 551s run partprobe(8) or kpartx(8) 551s The operation has completed successfully. 551s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 551s standard_filename: OK 551s del devmap : loop0p1 551s No devices found 551s standard_filename_cleanup: OK 551s Formatting 'fou du FaFa.img', fmt=raw size=20971520 552s Creating new GPT entries in memory. 552s Warning: The kernel is still using the old partition table. 552s The new table will be used at the next reboot or after you 552s run partprobe(8) or kpartx(8) 552s The operation has completed successfully. 552s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 552s filename_with_spaces: OK 552s del devmap : loop0p1 552s No devices found 552s filename_with_spaces_cleanup: OK 553s autopkgtest [20:56:40]: test kpartx-file-loopback: -----------------------] 554s autopkgtest [20:56:41]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 554s kpartx-file-loopback PASS 569s autopkgtest [20:56:56]: test tgtbasedmpaths: preparing testbed 943s autopkgtest [21:03:10]: testbed dpkg architecture: ppc64el 949s autopkgtest [21:03:16]: testbed apt version: 2.9.6 949s autopkgtest [21:03:16]: @@@@@@@@@@@@@@@@@@@@ test bed setup 998s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 999s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [4288 B] 999s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [495 kB] 999s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [48.2 kB] 999s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8548 B] 999s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [80.7 kB] 999s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [2116 B] 999s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1368 B] 999s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 999s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [434 kB] 999s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [8952 B] 999s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [1448 B] 999s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [120 B] 1001s Fetched 1211 kB in 1s (1404 kB/s) 1001s Reading package lists... 1010s Reading package lists... 1011s Building dependency tree... 1011s Reading state information... 1011s Calculating upgrade... 1011s The following NEW packages will be installed: 1011s systemd-cryptsetup 1011s The following packages will be upgraded: 1011s gettext-base libnftables1 libnss-systemd libpam-systemd libsystemd-shared 1011s libsystemd0 libudev1 nftables systemd systemd-resolved systemd-sysv 1011s systemd-timesyncd udev 1011s 13 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 1011s Need to get 10.8 MB of archives. 1011s After this operation, 171 kB disk space will be freed. 1011s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd ppc64el 256.4-1ubuntu3 [3740 kB] 1012s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-timesyncd ppc64el 256.4-1ubuntu3 [42.6 kB] 1012s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-resolved ppc64el 256.4-1ubuntu3 [370 kB] 1012s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd-shared ppc64el 256.4-1ubuntu3 [2490 kB] 1012s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsystemd0 ppc64el 256.4-1ubuntu3 [564 kB] 1012s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-sysv ppc64el 256.4-1ubuntu3 [11.9 kB] 1012s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnss-systemd ppc64el 256.4-1ubuntu3 [215 kB] 1012s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libpam-systemd ppc64el 256.4-1ubuntu3 [326 kB] 1012s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el udev ppc64el 256.4-1ubuntu3 [2141 kB] 1012s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libudev1 ppc64el 256.4-1ubuntu3 [223 kB] 1012s Get:11 http://ftpmaster.internal/ubuntu oracular/main ppc64el gettext-base ppc64el 0.22.5-2 [42.8 kB] 1012s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el nftables ppc64el 1.1.0-2 [70.9 kB] 1012s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libnftables1 ppc64el 1.1.0-2 [451 kB] 1012s Get:14 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el systemd-cryptsetup ppc64el 256.4-1ubuntu3 [127 kB] 1012s Fetched 10.8 MB in 1s (11.2 MB/s) 1013s (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 ... 72844 files and directories currently installed.) 1013s Preparing to unpack .../systemd_256.4-1ubuntu3_ppc64el.deb ... 1013s Unpacking systemd (256.4-1ubuntu3) over (256-1ubuntu1) ... 1013s Preparing to unpack .../systemd-timesyncd_256.4-1ubuntu3_ppc64el.deb ... 1013s Unpacking systemd-timesyncd (256.4-1ubuntu3) over (256-1ubuntu1) ... 1013s Preparing to unpack .../systemd-resolved_256.4-1ubuntu3_ppc64el.deb ... 1013s Unpacking systemd-resolved (256.4-1ubuntu3) over (256-1ubuntu1) ... 1013s Preparing to unpack .../libsystemd-shared_256.4-1ubuntu3_ppc64el.deb ... 1013s Unpacking libsystemd-shared:ppc64el (256.4-1ubuntu3) over (256-1ubuntu1) ... 1013s Preparing to unpack .../libsystemd0_256.4-1ubuntu3_ppc64el.deb ... 1013s Unpacking libsystemd0:ppc64el (256.4-1ubuntu3) over (256-1ubuntu1) ... 1013s Setting up libsystemd0:ppc64el (256.4-1ubuntu3) ... 1013s Setting up libsystemd-shared:ppc64el (256.4-1ubuntu3) ... 1013s Setting up systemd (256.4-1ubuntu3) ... 1013s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 1013s Created symlink '/run/systemd/system/tmp.mount' → '/dev/null'. 1013s /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 1014s (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 ... 72769 files and directories currently installed.) 1014s Preparing to unpack .../systemd-sysv_256.4-1ubuntu3_ppc64el.deb ... 1014s Unpacking systemd-sysv (256.4-1ubuntu3) over (256-1ubuntu1) ... 1014s Preparing to unpack .../libnss-systemd_256.4-1ubuntu3_ppc64el.deb ... 1014s Unpacking libnss-systemd:ppc64el (256.4-1ubuntu3) over (256-1ubuntu1) ... 1014s Preparing to unpack .../libpam-systemd_256.4-1ubuntu3_ppc64el.deb ... 1014s Unpacking libpam-systemd:ppc64el (256.4-1ubuntu3) over (256-1ubuntu1) ... 1014s Preparing to unpack .../udev_256.4-1ubuntu3_ppc64el.deb ... 1014s Unpacking udev (256.4-1ubuntu3) over (256-1ubuntu1) ... 1014s Preparing to unpack .../libudev1_256.4-1ubuntu3_ppc64el.deb ... 1014s Unpacking libudev1:ppc64el (256.4-1ubuntu3) over (256-1ubuntu1) ... 1014s Setting up libudev1:ppc64el (256.4-1ubuntu3) ... 1014s (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 ... 72770 files and directories currently installed.) 1014s Preparing to unpack .../gettext-base_0.22.5-2_ppc64el.deb ... 1014s Unpacking gettext-base (0.22.5-2) over (0.22.5-1) ... 1014s Preparing to unpack .../nftables_1.1.0-2_ppc64el.deb ... 1014s Unpacking nftables (1.1.0-2) over (1.0.9-2) ... 1014s Preparing to unpack .../libnftables1_1.1.0-2_ppc64el.deb ... 1014s Unpacking libnftables1:ppc64el (1.1.0-2) over (1.0.9-2) ... 1014s Selecting previously unselected package systemd-cryptsetup. 1014s Preparing to unpack .../systemd-cryptsetup_256.4-1ubuntu3_ppc64el.deb ... 1014s Unpacking systemd-cryptsetup (256.4-1ubuntu3) ... 1014s Setting up systemd-sysv (256.4-1ubuntu3) ... 1014s Setting up libnftables1:ppc64el (1.1.0-2) ... 1014s Setting up nftables (1.1.0-2) ... 1015s Setting up gettext-base (0.22.5-2) ... 1015s Setting up libnss-systemd:ppc64el (256.4-1ubuntu3) ... 1015s Setting up systemd-cryptsetup (256.4-1ubuntu3) ... 1015s Setting up systemd-timesyncd (256.4-1ubuntu3) ... 1016s systemd-time-wait-sync.service is a disabled or a static unit not running, not starting it. 1016s Setting up udev (256.4-1ubuntu3) ... 1017s Setting up libpam-systemd:ppc64el (256.4-1ubuntu3) ... 1017s Setting up systemd-resolved (256.4-1ubuntu3) ... 1017s Processing triggers for libc-bin (2.39-0ubuntu9) ... 1017s Processing triggers for man-db (2.12.1-2) ... 1018s Processing triggers for dbus (1.14.10-4ubuntu4) ... 1018s Processing triggers for shared-mime-info (2.4-5) ... 1019s Processing triggers for initramfs-tools (0.142ubuntu30) ... 1019s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 1019s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 1026s Reading package lists... 1027s Building dependency tree... 1027s Reading state information... 1027s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1027s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 1027s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 1027s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 1027s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 1028s Reading package lists... 1028s Reading package lists... 1029s Building dependency tree... 1029s Reading state information... 1029s Calculating upgrade... 1029s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1029s Reading package lists... 1029s Building dependency tree... 1029s Reading state information... 1030s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 1036s autopkgtest [21:04:43]: rebooting testbed after setup commands that affected boot 1080s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 1097s Reading package lists... 1098s Building dependency tree... 1098s Reading state information... 1098s Starting pkgProblemResolver with broken count: 0 1098s Starting 2 pkgProblemResolver with broken count: 0 1098s Done 1098s The following additional packages will be installed: 1098s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 1098s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 1098s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 1098s librdmacm1t64 lsscsi open-iscsi tgt 1098s Suggested packages: 1098s fio-examples gnuplot tgt-glusterfs tgt-rbd 1098s Recommended packages: 1098s finalrd 1098s The following NEW packages will be installed: 1098s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 1098s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 1098s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 1098s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 1098s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 1098s Need to get 10.7 MB/10.7 MB of archives. 1098s After this operation, 49.0 MB of additional disk space will be used. 1098s Get:1 /tmp/autopkgtest.pZgNe4/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 1098s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 1099s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 1099s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 1099s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2 [80.5 kB] 1099s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 1099s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 1099s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-4ubuntu1 [21.5 kB] 1099s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-4ubuntu1 [311 kB] 1099s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-4ubuntu1 [46.5 kB] 1099s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-4ubuntu1 [99.2 kB] 1099s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-1 [97.4 kB] 1099s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2ubuntu2 [23.7 kB] 1099s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2ubuntu2 [74.9 kB] 1099s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 1099s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3ubuntu1 [259 kB] 1099s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3ubuntu1 [279 kB] 1099s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [4026 kB] 1099s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 1099s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~git20240301.4c76c50-0ubuntu7 [3581 kB] 1099s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 1099s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 1099s Preconfiguring packages ... 1099s Fetched 10.7 MB in 1s (11.2 MB/s) 1099s Selecting previously unselected package libopeniscsiusr. 1100s (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 ... 72816 files and directories currently installed.) 1100s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 1100s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 1100s Selecting previously unselected package libisns0t64:ppc64el. 1100s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 1100s Unpacking libisns0t64:ppc64el (0.101-1) ... 1100s Selecting previously unselected package open-iscsi. 1100s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 1100s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 1100s Selecting previously unselected package librdmacm1t64:ppc64el. 1100s Preparing to unpack .../03-librdmacm1t64_52.0-2_ppc64el.deb ... 1100s Unpacking librdmacm1t64:ppc64el (52.0-2) ... 1100s Selecting previously unselected package libconfig-general-perl. 1100s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 1100s Unpacking libconfig-general-perl (2.65-2) ... 1100s Selecting previously unselected package tgt. 1100s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 1100s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 1100s Selecting previously unselected package libgfxdr0:ppc64el. 1100s Preparing to unpack .../06-libgfxdr0_11.1-4ubuntu1_ppc64el.deb ... 1100s Unpacking libgfxdr0:ppc64el (11.1-4ubuntu1) ... 1100s Selecting previously unselected package libglusterfs0:ppc64el. 1100s Preparing to unpack .../07-libglusterfs0_11.1-4ubuntu1_ppc64el.deb ... 1100s Unpacking libglusterfs0:ppc64el (11.1-4ubuntu1) ... 1100s Selecting previously unselected package libgfrpc0:ppc64el. 1100s Preparing to unpack .../08-libgfrpc0_11.1-4ubuntu1_ppc64el.deb ... 1100s Unpacking libgfrpc0:ppc64el (11.1-4ubuntu1) ... 1100s Selecting previously unselected package libgfapi0:ppc64el. 1100s Preparing to unpack .../09-libgfapi0_11.1-4ubuntu1_ppc64el.deb ... 1100s Unpacking libgfapi0:ppc64el (11.1-4ubuntu1) ... 1100s Selecting previously unselected package libnbd0. 1100s Preparing to unpack .../10-libnbd0_1.20.2-1_ppc64el.deb ... 1100s Unpacking libnbd0 (1.20.2-1) ... 1100s Selecting previously unselected package libdaxctl1:ppc64el. 1100s Preparing to unpack .../11-libdaxctl1_77-2ubuntu2_ppc64el.deb ... 1100s Unpacking libdaxctl1:ppc64el (77-2ubuntu2) ... 1100s Selecting previously unselected package libndctl6:ppc64el. 1100s Preparing to unpack .../12-libndctl6_77-2ubuntu2_ppc64el.deb ... 1100s Unpacking libndctl6:ppc64el (77-2ubuntu2) ... 1100s Selecting previously unselected package libpmem1:ppc64el. 1100s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 1100s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 1100s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 1100s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 1100s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 1100s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 1100s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3ubuntu1_ppc64el.deb ... 1100s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 1100s Selecting previously unselected package librados2. 1100s Preparing to unpack .../16-librados2_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 1100s Unpacking librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 1100s Selecting previously unselected package libpmemobj1:ppc64el. 1100s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 1100s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 1100s Selecting previously unselected package librbd1. 1100s Preparing to unpack .../18-librbd1_19.2.0~git20240301.4c76c50-0ubuntu7_ppc64el.deb ... 1100s Unpacking librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 1100s Selecting previously unselected package fio. 1100s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 1100s Unpacking fio (3.37-1) ... 1100s Selecting previously unselected package lsscsi. 1100s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 1100s Unpacking lsscsi (0.32-1build1) ... 1100s Selecting previously unselected package autopkgtest-satdep. 1100s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 1100s Unpacking autopkgtest-satdep (0) ... 1100s Setting up libconfig-general-perl (2.65-2) ... 1100s Setting up libisns0t64:ppc64el (0.101-1) ... 1100s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3ubuntu1) ... 1100s Setting up libnbd0 (1.20.2-1) ... 1100s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 1100s Setting up libglusterfs0:ppc64el (11.1-4ubuntu1) ... 1100s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3ubuntu1) ... 1100s Setting up lsscsi (0.32-1build1) ... 1100s Setting up libdaxctl1:ppc64el (77-2ubuntu2) ... 1100s Setting up libndctl6:ppc64el (77-2ubuntu2) ... 1100s Setting up librdmacm1t64:ppc64el (52.0-2) ... 1100s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 1101s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 1101s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 1101s Setting up libgfxdr0:ppc64el (11.1-4ubuntu1) ... 1101s Setting up librados2 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 1101s Setting up open-iscsi (2.1.10-1ubuntu1) ... 1102s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 1102s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 1102s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 1103s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 1103s Setting up librbd1 (19.2.0~git20240301.4c76c50-0ubuntu7) ... 1103s Setting up libgfrpc0:ppc64el (11.1-4ubuntu1) ... 1103s Setting up libgfapi0:ppc64el (11.1-4ubuntu1) ... 1103s Setting up fio (3.37-1) ... 1103s Setting up autopkgtest-satdep (0) ... 1103s Processing triggers for man-db (2.12.1-2) ... 1104s Processing triggers for initramfs-tools (0.142ubuntu30) ... 1104s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 1104s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 1113s Processing triggers for libc-bin (2.39-0ubuntu9) ... 1116s (Reading database ... 73057 files and directories currently installed.) 1116s Removing autopkgtest-satdep (0) ... 1129s autopkgtest [21:06:16]: test tgtbasedmpaths: [----------------------- 1129s + targetname=iqn.2016-11.foo.com:target.iscsi 1129s + pwd 1129s + cwd=/tmp/autopkgtest.pZgNe4/build.ekT/src 1129s + testdir=/mnt/tgtmpathtest 1129s + localhost=127.0.0.1 1129s + portal=127.0.0.1:3260 1129s + maxpaths=4 1129s + backfn=backingfile 1129s + expectwwid=60000000000000000e00000000010001 1129s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1129s + bglog=/tmp/autopkgtest.pZgNe4/tgtbasedmpaths-artifacts/test-background.log 1129s + fioprep=/tmp/autopkgtest.pZgNe4/tgtbasedmpaths-artifacts/path-change-prep.fio 1129s + fiovrfy=/tmp/autopkgtest.pZgNe4/tgtbasedmpaths-artifacts/path-change-check.fio 1129s + mkdir -p /etc/multipath 1129s + echo /360000000000000000e00000000010001/ 1129s + service tgt restart 1130s + truncate --size 100M backingfile 1130s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 1130s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 1130s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.pZgNe4/build.ekT/src/backingfile 1130s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 1130s + echo login #1 1130s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 1130s + seq 2 4 1130s + echo extra login #2 1130s + iscsiadm --mode session -r 1 --op new 1130s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 1130s login #1 1130s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1130s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1130s extra login #2 1130s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1130s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1130s extra login #3 1130s + echo extra login #3 1130s + iscsiadm --mode session -r 1 --op new 1130s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1130s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1130s extra login #4 1130s + echo extra login #4 1130s + iscsiadm --mode session -r 1 --op new 1130s + udevadm settle 1130s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1130s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1130s + sleep 5 1135s Status after initial setup 1135s Target 1: iqn.2016-11.foo.com:target.iscsi 1135s System information: 1135s Driver: iscsi 1135s State: ready 1135s I_T nexus information: 1135s I_T nexus: 1 1135s Initiator: iqn.2004-10.com.ubuntu:01:4564c89a240 alias: autopkgtest 1135s Connection: 0 1135s IP Address: 127.0.0.1 1135s I_T nexus: 2 1135s Initiator: iqn.2004-10.com.ubuntu:01:4564c89a240 alias: autopkgtest 1135s Connection: 0 1135s IP Address: 127.0.0.1 1135s I_T nexus: 3 1135s Initiator: iqn.2004-10.com.ubuntu:01:4564c89a240 alias: autopkgtest 1135s Connection: 0 1135s IP Address: 127.0.0.1 1135s I_T nexus: 4 1135s Initiator: iqn.2004-10.com.ubuntu:01:4564c89a240 alias: autopkgtest 1135s Connection: 0 1135s IP Address: 127.0.0.1 1135s LUN information: 1135s LUN: 0 1135s Type: controller 1135s SCSI ID: IET 00010000 1135s SCSI SN: beaf10 1135s Size: 0 MB, Block size: 1 1135s Online: Yes 1135s Removable media: No 1135s Prevent removal: No 1135s Readonly: No 1135s SWP: No 1135s Thin-provisioning: No 1135s Backing store type: null 1135s Backing store path: None 1135s Backing store flags: 1135s LUN: 1 1135s Type: disk 1135s SCSI ID: IET 00010001 1135s SCSI SN: beaf11 1135s Size: 105 MB, Block size: 512 1135s Online: Yes 1135s Removable media: No 1135s Prevent removal: No 1135s Readonly: No 1135s SWP: No 1135s Thin-provisioning: No 1135s Backing store type: rdwr 1135s Backing store path: /tmp/autopkgtest.pZgNe4/build.ekT/src/backingfile 1135s Backing store flags: 1135s Account information: 1135s ACL information: 1135s ALL 1135s + echo Status after initial setup 1135s + tgtadm --lld iscsi --mode target --op show 1135s + tgtadm --lld iscsi --op show --mode conn --tid 1 1135s Session: 4 1135s Connection: 0 1135s Initiator: iqn.2004-10.com.ubuntu:01:4564c89a240 1135s IP Address: 127.0.0.1 1135s Session: 3 1135s Connection: 0 1135s Initiator: iqn.2004-10.com.ubuntu:01:4564c89a240 1135s IP Address: 127.0.0.1 1135s Session: 2 1135s Connection: 0 1135s Initiator: iqn.2004-10.com.ubuntu:01:4564c89a240 1135s IP Address: 127.0.0.1 1135s Session: 1 1135s Connection: 0 1135s Initiator: iqn.2004-10.com.ubuntu:01:4564c89a240 1135s IP Address: 127.0.0.1 1135s + iscsiadm --mode session -P 1 1135s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 1135s Current Portal: 127.0.0.1:3260,1 1135s Persistent Portal: 127.0.0.1:3260,1 1135s ********** 1135s Interface: 1135s ********** 1135s Iface Name: default 1135s Iface Transport: tcp 1135s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:4564c89a240 1135s Iface IPaddress: 127.0.0.1 1135s Iface HWaddress: default 1135s Iface Netdev: default 1135s SID: 1 1135s iSCSI Connection State: LOGGED IN 1135s iSCSI Session State: LOGGED_IN 1135s Internal iscsid Session State: NO CHANGE 1135s 1135s ********** 1135s Interface: 1135s ********** 1135s Iface Name: default 1135s Iface Transport: tcp 1135s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:4564c89a240 1135s Iface IPaddress: 127.0.0.1 1135s Iface HWaddress: default 1135s Iface Netdev: default 1135s SID: 2 1135s iSCSI Connection State: LOGGED IN 1135s iSCSI Session State: LOGGED_IN 1135s Internal iscsid Session State: NO CHANGE 1135s 1135s ********** 1135s Interface: 1135s ********** 1135s Iface Name: default 1135s Iface Transport: tcp 1135s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:4564c89a240 1135s Iface IPaddress: 127.0.0.1 1135s Iface HWaddress: default 1135s Iface Netdev: default 1135s SID: 3 1135s iSCSI Connection State: LOGGED IN 1135s iSCSI Session State: LOGGED_IN 1135s Internal iscsid Session State: NO CHANGE 1135s 1135s ********** 1135s Interface: 1135s ********** 1135s Iface Name: default 1135s Iface Transport: tcp 1135s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:4564c89a240 1135s Iface IPaddress: 127.0.0.1 1135s Iface HWaddress: default 1135s Iface Netdev: default 1135s SID: 4 1135s iSCSI Connection State: LOGGED IN 1135s iSCSI Session State: LOGGED_IN 1135s Internal iscsid Session State: NO CHANGE 1135s [0:0:0:0] disk QEMU QEMU HARDDISK 2.5+ /dev/sda 0QEMU_QEMU_HARDDISK_drive-scsi0-0-0-0 1135s state=running queue_depth=128 scsi_level=6 type=0 device_blocked=0 timeout=30 1135s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/pci0000:00/0000:00:02.0/virtio1/host0/target0:0:0/0:0:0:0] 1135s [1:0:0:0] storage IET Controller 0001 - - 1135s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1135s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:0] 1135s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 1135s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1135s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session1/target1:0:0/1:0:0:1] 1135s [2:0:0:0] storage IET Controller 0001 - - 1135s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1135s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:0] 1135s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 360000000000000000e00000000010001 1135s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1135s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session2/target2:0:0/2:0:0:1] 1135s [3:0:0:0] storage IET Controller 0001 - - 1135s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1135s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:0] 1135s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 33000000100000001 1135s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1135s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session3/target3:0:0/3:0:0:1] 1135s [4:0:0:0] storage IET Controller 0001 - - 1135s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1135s dir: /sys/bus/scsi/devices/4:0:0:0 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:0] 1135s [4:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sde 360000000000000000e00000000010001 1135s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1135s dir: /sys/bus/scsi/devices/4:0:0:1 [/sys/devices/platform/host4/session4/target4:0:0/4:0:0:1] 1135s NVMe module may not be loaded 1135s + lsscsi -liv 1135s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 1135s + multipath -v3 -ll 1135s 70.654292 | set open fds limit to 1073741816/1073741816 1135s 70.654387 | _read_bindings_file: reading /etc/multipath/bindings 1135s 70.654423 | loading /usr/lib/multipath/libchecktur.so checker 1135s 70.654522 | checker tur: message table size = 4 1135s 70.654530 | loading /usr/lib/multipath/libprioconst.so prioritizer 1135s 70.654694 | _init_foreign: foreign library "nvme" is not enabled 1135s 70.660811 | sda: size = 167772160 1135s 70.660997 | sda: vendor = QEMU 1135s 70.661046 | sda: product = QEMU HARDDISK 1135s 70.661071 | sda: rev = 2.5+ 1135s 70.661699 | sda: h:b:t:l = 0:0:0:0 1135s 70.662036 | sda: tgt_node_name = 1135s 70.662060 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 1135s 70.662063 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1135s 70.662227 | sda: 10443 cyl, 255 heads, 63 sectors/track, start at 0 1135s 70.662251 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1135s 70.662264 | __sysfs_attr_get_value: attribute '/sys/devices/pci0000:00/0000:00:02.0/virtio1/host0/target0:0:0/0:0:0:0/vpd_pg80' cannot be opened: No such file or directory 1135s 70.662269 | failed to read sysfs vpd pg80: No such file or directory 1135s 70.662474 | sda: fail to get serial 1135s 70.662499 | sda: detect_checker = yes (setting: multipath internal) 1135s 70.662532 | sda checker timeout = 30 s (setting: kernel sysfs) 1135s 70.662754 | sda: path_checker = tur (setting: multipath internal) 1135s 70.662967 | sda: tur state = up 1135s 70.663307 | sdb: size = 204800 1135s 70.663443 | sdb: vendor = IET 1135s 70.663466 | sdb: product = VIRTUAL-DISK 1135s 70.663489 | sdb: rev = 0001 1135s 70.664166 | sdb: h:b:t:l = 1:0:0:1 1135s 70.664551 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1135s 70.664554 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 1135s 70.664556 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1135s 70.664712 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1135s 70.664715 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1135s 70.664731 | sdb: serial = beaf11 1135s 70.664734 | sdb: detect_checker = yes (setting: multipath internal) 1135s 70.664763 | sdb checker timeout = 30 s (setting: kernel sysfs) 1135s 70.667160 | sdb: path_checker = tur (setting: multipath internal) 1135s 70.667423 | sdb: tur state = up 1135s 70.667576 | sdc: size = 204800 1135s 70.667739 | sdc: vendor = IET 1135s 70.667785 | sdc: product = VIRTUAL-DISK 1135s 70.667808 | sdc: rev = 0001 1135s 70.668548 | sdc: h:b:t:l = 2:0:0:1 1135s 70.668944 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1135s 70.668968 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 1135s 70.668970 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1135s 70.669125 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1135s 70.669129 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1135s 70.669145 | sdc: serial = beaf11 1135s 70.669148 | sdc: detect_checker = yes (setting: multipath internal) 1135s 70.669178 | sdc checker timeout = 30 s (setting: kernel sysfs) 1135s 70.669485 | sdc: path_checker = tur (setting: multipath internal) 1135s 70.669751 | sdc: tur state = up 1135s 70.669918 | sdd: size = 204800 1135s 70.670083 | sdd: vendor = IET 1135s 70.670129 | sdd: product = VIRTUAL-DISK 1135s 70.670153 | sdd: rev = 0001 1135s 70.670872 | sdd: h:b:t:l = 3:0:0:1 1135s 70.671259 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1135s 70.671282 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 1135s 70.671285 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1135s 70.671437 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1135s 70.671460 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1135s 70.671475 | sdd: serial = beaf11 1135s 70.671478 | sdd: detect_checker = yes (setting: multipath internal) 1135s 70.671528 | sdd checker timeout = 30 s (setting: kernel sysfs) 1135s 70.671756 | sdd: path_checker = tur (setting: multipath internal) 1135s 70.671883 | sdd: tur state = up 1135s 70.672058 | sde: size = 204800 1135s 70.672211 | sde: vendor = IET 1135s 70.672372 | sde: product = VIRTUAL-DISK 1135s 70.672417 | sde: rev = 0001 1135s 70.673100 | sde: h:b:t:l = 4:0:0:1 1135s 70.673486 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1135s 70.673508 | sde: uid_attribute = ID_SERIAL (setting: multipath internal) 1135s 70.673510 | sde: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1135s 70.673663 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1135s 70.673686 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1135s 70.673701 | sde: serial = beaf11 1135s 70.673703 | sde: detect_checker = yes (setting: multipath internal) 1135s 70.673732 | sde checker timeout = 30 s (setting: kernel sysfs) 1135s 70.673929 | sde: path_checker = tur (setting: multipath internal) 1135s 70.674117 | sde: tur state = up 1135s 70.674234 | loop0: device node name blacklisted 1135s 70.674347 | loop1: device node name blacklisted 1135s 70.674571 | loop2: device node name blacklisted 1135s 70.674712 | loop3: device node name blacklisted 1135s 70.674803 | loop4: device node name blacklisted 1135s 70.674912 | loop5: device node name blacklisted 1135s 70.675022 | loop6: device node name blacklisted 1135s 70.675136 | loop7: device node name blacklisted 1135s 70.675233 | dm-0: device node name blacklisted 1135s 70.676479 | multipath-tools v0.9.9 (05/03, 2024) 1135s 70.676530 | libdevmapper version 1.02.196 1135s 70.676687 | kernel device mapper v4.48.0 1135s 70.676725 | DM multipath kernel driver v1.14.0 1135s 70.676857 | sdb: size = 204800 1135s 70.676884 | sdb: vendor = IET 1135s 70.676886 | sdb: product = VIRTUAL-DISK 1135s 70.676889 | sdb: rev = 0001 1135s 70.677521 | sdb: h:b:t:l = 1:0:0:1 1135s 70.677664 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1135s 70.677712 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1135s 70.677716 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1135s 70.677729 | sdb: serial = beaf11 1135s 70.677952 | sdb: tur state = up 1135s 70.677975 | sdb: uid = 360000000000000000e00000000010001 (udev) 1135s 70.677978 | sdb: detect_prio = yes (setting: multipath internal) 1135s 70.677982 | sdb: prio = const (setting: multipath internal) 1135s 70.677984 | sdb: prio args = "" (setting: multipath internal) 1135s 70.677987 | sdb: const prio = 1 1135s 70.678012 | sdc: size = 204800 1135s 70.678017 | sdc: vendor = IET 1135s 70.678019 | sdc: product = VIRTUAL-DISK 1135s 70.678022 | sdc: rev = 0001 1135s 70.678636 | sdc: h:b:t:l = 2:0:0:1 1135s 70.678789 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1135s 70.678810 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1135s 70.678813 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1135s 70.678826 | sdc: serial = beaf11 1135s 70.679114 | sdc: tur state = up 1135s 70.679138 | sdc: uid = 360000000000000000e00000000010001 (udev) 1135s 70.679140 | sdc: detect_prio = yes (setting: multipath internal) 1135s 70.679143 | sdc: prio = const (setting: multipath internal) 1135s 70.679145 | sdc: prio args = "" (setting: multipath internal) 1135s 70.679147 | sdc: const prio = 1 1135s 70.679172 | sdd: size = 204800 1135s 70.679176 | sdd: vendor = IET 1135s 70.679180 | sdd: product = VIRTUAL-DISK 1135s 70.679182 | sdd: rev = 0001 1135s ===== paths list ===== 1135s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 1135s 0:0:0:0 sda 8:0 -1 undef undef QEMU,QEMU HARDDISK,2.5+ unknown 1135s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1135s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1135s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1135s 4:0:0:1 sde 8:64 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1135s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1135s size=100M features='0' hwhandler='0' wp=rw 1135s |-+- policy='service-time 0' prio=1 status=active 1135s | `- 1:0:0:1 sdb 8:16 active ready running 1135s |-+- policy='service-time 0' prio=1 status=enabled 1135s | `- 2:0:0:1 sdc 8:32 active ready running 1135s |-+- policy='service-time 0' prio=1 status=enabled 1135s | `- 3:0:0:1 sdd 8:48 active ready running 1135s `-+- policy='service-time 0' prio=1 status=enabled 1135s `- 4:0:0:1 sde 8:64 active ready running 1135s 70.679792 | sdd: h:b:t:l = 3:0:0:1 1135s 70.679928 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1135s 70.679970 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1135s 70.679973 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1135s 70.679986 | sdd: serial = beaf11 1135s 70.680160 | sdd: tur state = up 1135s 70.680191 | sdd: uid = 360000000000000000e00000000010001 (udev) 1135s 70.680194 | sdd: detect_prio = yes (setting: multipath internal) 1135s 70.680196 | sdd: prio = const (setting: multipath internal) 1135s 70.680198 | sdd: prio args = "" (setting: multipath internal) 1135s 70.680201 | sdd: const prio = 1 1135s 70.680224 | sde: size = 204800 1135s 70.680229 | sde: vendor = IET 1135s 70.680232 | sde: product = VIRTUAL-DISK 1135s 70.680234 | sde: rev = 0001 1135s 70.680843 | sde: h:b:t:l = 4:0:0:1 1135s 70.680978 | sde: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1135s 70.681019 | sde: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1135s 70.681022 | sde: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1135s 70.681034 | sde: serial = beaf11 1135s 70.681213 | sde: tur state = up 1135s 70.681236 | sde: uid = 360000000000000000e00000000010001 (udev) 1135s 70.681239 | sde: detect_prio = yes (setting: multipath internal) 1135s 70.681241 | sde: prio = const (setting: multipath internal) 1135s 70.681243 | sde: prio args = "" (setting: multipath internal) 1135s 70.681245 | sde: const prio = 1 1135s 70.682395 | unloading tur checker 1135s 70.682491 | unloading const prioritizer 1135s + dmsetup table 1135s mpatha: 0 204800 multipath 0 0 4 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 service-time 0 1 2 8:64 1 1 1135s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 1135s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 1135s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 1135s /etc/multipath/bindings:# 1135s /etc/multipath/bindings:# Format: 1135s /etc/multipath/bindings:# alias wwid 1135s /etc/multipath/bindings:# 1135s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 1135s /etc/multipath/wwids:/360000000000000000e00000000010001/ 1135s ● multipathd.service - Device-Mapper Multipath Device Controller 1135s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 1135s Active: active (running) since Mon 2024-07-29 21:05:15 UTC; 1min 7s ago 1135s Invocation: 8b25b6ddee2e4067ac5b060461d786eb 1135s TriggeredBy: ● multipathd.socket 1135s Main PID: 336 (multipathd) 1135s Status: "up" 1135s Tasks: 7 1135s Memory: 28.1M (peak: 34.3M) 1135s CPU: 67ms 1135s CGroup: /system.slice/multipathd.service 1135s └─336 /sbin/multipathd -d -s 1135s 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1135s Jul 29 21:05:15 autopkgtest multipathd[336]: multipathd v0.9.9: start up 1135s Jul 29 21:05:15 autopkgtest multipathd[336]: reconfigure: setting up paths and maps 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1135s Jul 29 21:06:17 autopkgtest multipathd[336]: updated bindings file /etc/multipath/bindings 1135s Jul 29 21:06:17 autopkgtest multipathd[336]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:16 1] 1135s Jul 29 21:06:17 autopkgtest multipathd[336]: sdb [8:16]: path added to devmap mpatha 1135s Jul 29 21:06:17 autopkgtest multipathd[336]: mpatha: performing delayed actions 1135s Jul 29 21:06:17 autopkgtest multipathd[336]: mpatha: reload [0 204800 multipath 0 0 4 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 service-time 0 1 1 8:64 1] 1135s + grep . /etc/multipath/bindings /etc/multipath/wwids 1135s + systemctl status multipathd.service 1135s + systemctl status multipathd.socket 1135s ● multipathd.socket - multipathd control socket 1135s Loaded: loaded (/usr/lib/systemd/system/multipathd.socket; enabled; preset: enabled) 1135s Active: active (running) since Mon 2024-07-29 21:05:15 UTC; 1min 7s ago 1135s Invocation: 118b28f11d6e479fbd52164f0041b020 1135s Triggers: ● multipathd.service 1135s Listen: @/org/kernel/linux/storage/multipathd (Stream) 1135s CGroup: /system.slice/multipathd.socket 1135s 1135s Notice: journal has been rotated since unit was started, output may be incomplete. 1135s total 0 1135s drwxr-xr-x 2 root root 80 Jul 29 21:06 . 1135s drwxr-xr-x 18 root root 4260 Jul 29 21:06 .. 1135s crw------- 1 root root 10, 236 Jul 29 21:05 control 1135s lrwxrwxrwx 1 root root 7 Jul 29 21:06 mpatha -> ../dm-0 1135s journal 1135s + ls -la /dev/mapper/ 1135s + echo journal 1135s + journalctl -b 1135s Jul 29 21:05:15 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 1135s Jul 29 21:05:15 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 1135s Jul 29 21:05:15 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 1135s Jul 29 21:05:15 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 1135s Jul 29 21:05:15 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 1135s Jul 29 21:05:15 autopkgtest kernel: Activating Kernel Userspace Access Prevention 1135s Jul 29 21:05:15 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 1135s Jul 29 21:05:15 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x00000000038a0000 with 64.0 KiB pages (exec) 1135s Jul 29 21:05:15 autopkgtest kernel: radix-mmu: Mapped 0x00000000038a0000-0x0000000200000000 with 64.0 KiB pages 1135s Jul 29 21:05:15 autopkgtest kernel: lpar: Using radix MMU under hypervisor 1135s Jul 29 21:05:15 autopkgtest kernel: Linux version 6.8.0-31-generic (buildd@bos02-ppc64el-018) (powerpc64le-linux-gnu-gcc-13 (Ubuntu 13.2.0-23ubuntu4) 13.2.0, GNU ld (GNU Binutils for Ubuntu) 2.42) #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 (Ubuntu 6.8.0-31.31-generic 6.8.1) 1135s Jul 29 21:05:15 autopkgtest kernel: Secure boot mode disabled 1135s Jul 29 21:05:15 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc0000000093ed766 1135s Jul 29 21:05:15 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (raw) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 1135s Jul 29 21:05:15 autopkgtest kernel: printk: legacy bootconsole [udbg0] enabled 1135s Jul 29 21:05:15 autopkgtest kernel: Partition configured for 4 cpus. 1135s Jul 29 21:05:15 autopkgtest kernel: CPU maps initialized for 1 thread per core 1135s Jul 29 21:05:15 autopkgtest kernel: (thread shift is 0) 1135s Jul 29 21:05:15 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 1135s Jul 29 21:05:15 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 1135s Jul 29 21:05:15 autopkgtest kernel: ----------------------------------------------------- 1135s Jul 29 21:05:15 autopkgtest kernel: phys_mem_size = 0x200000000 1135s Jul 29 21:05:15 autopkgtest kernel: dcache_bsize = 0x80 1135s Jul 29 21:05:15 autopkgtest kernel: icache_bsize = 0x80 1135s Jul 29 21:05:15 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 1135s Jul 29 21:05:15 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 1135s Jul 29 21:05:15 autopkgtest kernel: always = 0x0000000380008181 1135s Jul 29 21:05:15 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 1135s Jul 29 21:05:15 autopkgtest kernel: mmu_features = 0x3c007641 1135s Jul 29 21:05:15 autopkgtest kernel: firmware_features = 0x00000085455a445f 1135s Jul 29 21:05:15 autopkgtest kernel: vmalloc start = 0xc008000000000000 1135s Jul 29 21:05:15 autopkgtest kernel: IO start = 0xc00a000000000000 1135s Jul 29 21:05:15 autopkgtest kernel: vmemmap start = 0xc00c000000000000 1135s Jul 29 21:05:15 autopkgtest kernel: ----------------------------------------------------- 1135s Jul 29 21:05:15 autopkgtest kernel: numa: NODE_DATA [mem 0x1eff10280-0x1eff17fff] 1135s Jul 29 21:05:15 autopkgtest kernel: rfi-flush: fallback displacement flush available 1135s Jul 29 21:05:15 autopkgtest kernel: rfi-flush: ori type flush available 1135s Jul 29 21:05:15 autopkgtest kernel: rfi-flush: mttrig type flush available 1135s Jul 29 21:05:15 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 1135s Jul 29 21:05:15 autopkgtest kernel: count-cache-flush: software flush enabled. 1135s Jul 29 21:05:15 autopkgtest kernel: link-stack-flush: software flush enabled. 1135s Jul 29 21:05:15 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 1135s Jul 29 21:05:15 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 1135s Jul 29 21:05:15 autopkgtest kernel: stf-barrier: eieio barrier available 1135s Jul 29 21:05:15 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 1135s Jul 29 21:05:15 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 1135s Jul 29 21:05:15 autopkgtest kernel: PPC64 nvram contains 65536 bytes 1135s Jul 29 21:05:15 autopkgtest kernel: barrier-nospec: using ORI speculation barrier 1135s Jul 29 21:05:15 autopkgtest kernel: barrier-nospec: patched 269 locations 1135s Jul 29 21:05:15 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 1135s Jul 29 21:05:15 autopkgtest kernel: Memory hole size: 0MB 1135s Jul 29 21:05:15 autopkgtest kernel: Zone ranges: 1135s Jul 29 21:05:15 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 1135s Jul 29 21:05:15 autopkgtest kernel: Device empty 1135s Jul 29 21:05:15 autopkgtest kernel: Movable zone start for each node 1135s Jul 29 21:05:15 autopkgtest kernel: Early memory node ranges 1135s Jul 29 21:05:15 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 1135s Jul 29 21:05:15 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 1135s Jul 29 21:05:15 autopkgtest kernel: percpu: Embedded 12 pages/cpu s609960 r0 d176472 u786432 1135s Jul 29 21:05:15 autopkgtest kernel: pcpu-alloc: s609960 r0 d176472 u786432 alloc=12*65536 1135s Jul 29 21:05:15 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 1135s Jul 29 21:05:15 autopkgtest kernel: Kernel command line: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic root=UUID=f999abd5-af41-40ac-8675-cf1e7d4878fb ro console=hvc0 earlyprintk 1135s Jul 29 21:05:15 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic", will be passed to user space. 1135s Jul 29 21:05:15 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 1135s Jul 29 21:05:15 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 1135s Jul 29 21:05:15 autopkgtest kernel: Fallback order for Node 0: 0 1135s Jul 29 21:05:15 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 130944 1135s Jul 29 21:05:15 autopkgtest kernel: Policy zone: Normal 1135s Jul 29 21:05:15 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 1135s Jul 29 21:05:15 autopkgtest kernel: Memory: 7969152K/8388608K available (23680K kernel code, 4096K rwdata, 25472K rodata, 8832K init, 1901K bss, 419456K reserved, 0K cma-reserved) 1135s Jul 29 21:05:15 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 1135s Jul 29 21:05:15 autopkgtest kernel: ftrace: allocating 51717 entries in 19 pages 1135s Jul 29 21:05:15 autopkgtest kernel: ftrace: allocated 19 pages with 3 groups 1135s Jul 29 21:05:15 autopkgtest kernel: trace event string verifier disabled 1135s Jul 29 21:05:15 autopkgtest kernel: rcu: Hierarchical RCU implementation. 1135s Jul 29 21:05:15 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 1135s Jul 29 21:05:15 autopkgtest kernel: Rude variant of Tasks RCU enabled. 1135s Jul 29 21:05:15 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 1135s Jul 29 21:05:15 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 1135s Jul 29 21:05:15 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 1135s Jul 29 21:05:15 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 1135s Jul 29 21:05:15 autopkgtest kernel: xive: Using IRQ range [0-3] 1135s Jul 29 21:05:15 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 1135s Jul 29 21:05:15 autopkgtest kernel: xive: Using priority 6 for all interrupts 1135s Jul 29 21:05:15 autopkgtest kernel: xive: Using 64kB queues 1135s Jul 29 21:05:15 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 1135s Jul 29 21:05:15 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 1135s Jul 29 21:05:15 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 1135s Jul 29 21:05:15 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 1135s Jul 29 21:05:15 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 1135s Jul 29 21:05:15 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 1135s Jul 29 21:05:15 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 1135s Jul 29 21:05:15 autopkgtest kernel: Console: colour dummy device 80x25 1135s Jul 29 21:05:15 autopkgtest kernel: printk: legacy console [hvc0] enabled 1135s Jul 29 21:05:15 autopkgtest kernel: printk: legacy bootconsole [udbg0] disabled 1135s Jul 29 21:05:15 autopkgtest kernel: pid_max: default: 32768 minimum: 301 1135s Jul 29 21:05:15 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,integrity 1135s Jul 29 21:05:15 autopkgtest kernel: landlock: Up and running. 1135s Jul 29 21:05:15 autopkgtest kernel: Yama: becoming mindful. 1135s Jul 29 21:05:15 autopkgtest kernel: AppArmor: AppArmor initialized 1135s Jul 29 21:05:15 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 1135s Jul 29 21:05:15 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 1135s Jul 29 21:05:15 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 1135s Jul 29 21:05:15 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 1135s Jul 29 21:05:15 autopkgtest kernel: POWER9 performance monitor hardware support registered 1135s Jul 29 21:05:15 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 1135s Jul 29 21:05:15 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 1135s Jul 29 21:05:15 autopkgtest kernel: smp: Bringing up secondary CPUs ... 1135s Jul 29 21:05:15 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 1135s Jul 29 21:05:15 autopkgtest kernel: numa: Node 0 CPUs: 0-3 1135s Jul 29 21:05:15 autopkgtest kernel: devtmpfs: initialized 1135s Jul 29 21:05:15 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 1135s Jul 29 21:05:15 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 1135s Jul 29 21:05:15 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 1135s Jul 29 21:05:15 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 1135s Jul 29 21:05:15 autopkgtest kernel: PCI: OF: PROBE_ONLY disabled 1135s Jul 29 21:05:15 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 1135s Jul 29 21:05:15 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 1135s Jul 29 21:05:15 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 1135s Jul 29 21:05:15 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 1135s Jul 29 21:05:15 autopkgtest kernel: audit: initializing netlink subsys (disabled) 1135s Jul 29 21:05:15 autopkgtest kernel: audit: type=2000 audit(1722287112.040:1): state=initialized audit_enabled=0 res=1 1135s Jul 29 21:05:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 1135s Jul 29 21:05:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 1135s Jul 29 21:05:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 1135s Jul 29 21:05:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 1135s Jul 29 21:05:15 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 1135s Jul 29 21:05:15 autopkgtest kernel: cpuidle: using governor ladder 1135s Jul 29 21:05:15 autopkgtest kernel: cpuidle: using governor menu 1135s Jul 29 21:05:15 autopkgtest kernel: RTAS daemon started 1135s Jul 29 21:05:15 autopkgtest kernel: pstore: Using crash dump compression: deflate 1135s Jul 29 21:05:15 autopkgtest kernel: pstore: Registered nvram as persistent store backend 1135s Jul 29 21:05:15 autopkgtest kernel: EEH: pSeries platform initialized 1135s Jul 29 21:05:15 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 1135s Jul 29 21:05:15 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 1135s Jul 29 21:05:15 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 1135s Jul 29 21:05:15 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 1135s Jul 29 21:05:15 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 1135s Jul 29 21:05:15 autopkgtest kernel: iommu: Default domain type: Translated 1135s Jul 29 21:05:15 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 1135s Jul 29 21:05:15 autopkgtest kernel: SCSI subsystem initialized 1135s Jul 29 21:05:15 autopkgtest kernel: libata version 3.00 loaded. 1135s Jul 29 21:05:15 autopkgtest kernel: usbcore: registered new interface driver usbfs 1135s Jul 29 21:05:15 autopkgtest kernel: usbcore: registered new interface driver hub 1135s Jul 29 21:05:15 autopkgtest kernel: usbcore: registered new device driver usb 1135s Jul 29 21:05:15 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 1135s Jul 29 21:05:15 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 1135s Jul 29 21:05:15 autopkgtest kernel: PTP clock support registered 1135s Jul 29 21:05:15 autopkgtest kernel: EDAC MC: Ver: 3.0.0 1135s Jul 29 21:05:15 autopkgtest kernel: NetLabel: Initializing 1135s Jul 29 21:05:15 autopkgtest kernel: NetLabel: domain hash size = 128 1135s Jul 29 21:05:15 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 1135s Jul 29 21:05:15 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 1135s Jul 29 21:05:15 autopkgtest kernel: mctp: management component transport protocol core 1135s Jul 29 21:05:15 autopkgtest kernel: NET: Registered PF_MCTP protocol family 1135s Jul 29 21:05:15 autopkgtest kernel: PCI: Probing PCI hardware 1135s Jul 29 21:05:15 autopkgtest kernel: PCI host bridge to bus 0000:00 1135s Jul 29 21:05:15 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 1135s Jul 29 21:05:15 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 1135s Jul 29 21:05:15 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 1135s Jul 29 21:05:15 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 1135s Jul 29 21:05:15 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1135s Jul 29 21:05:15 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1135s Jul 29 21:05:15 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1135s Jul 29 21:05:15 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1135s Jul 29 21:05:15 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 1135s Jul 29 21:05:15 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 1135s Jul 29 21:05:15 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 1135s Jul 29 21:05:15 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 1135s Jul 29 21:05:15 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 1135s Jul 29 21:05:15 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 1135s Jul 29 21:05:15 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 1135s Jul 29 21:05:15 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 1135s Jul 29 21:05:15 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 1135s Jul 29 21:05:15 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 1135s Jul 29 21:05:15 autopkgtest kernel: PCI: Probing PCI hardware done 1135s Jul 29 21:05:15 autopkgtest kernel: vgaarb: loaded 1135s Jul 29 21:05:15 autopkgtest kernel: clocksource: Switched to clocksource timebase 1135s Jul 29 21:05:15 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 1135s Jul 29 21:05:15 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 1135s Jul 29 21:05:15 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 1135s Jul 29 21:05:15 autopkgtest kernel: NET: Registered PF_INET protocol family 1135s Jul 29 21:05:15 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 1135s Jul 29 21:05:15 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 1135s Jul 29 21:05:15 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 1135s Jul 29 21:05:15 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 1135s Jul 29 21:05:15 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 1135s Jul 29 21:05:15 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 1135s Jul 29 21:05:15 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 1135s Jul 29 21:05:15 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 1135s Jul 29 21:05:15 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 1135s Jul 29 21:05:15 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 1135s Jul 29 21:05:15 autopkgtest kernel: NET: Registered PF_XDP protocol family 1135s Jul 29 21:05:15 autopkgtest kernel: PCI: CLS 0 bytes, default 128 1135s Jul 29 21:05:15 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 1135s Jul 29 21:05:15 autopkgtest kernel: Initialise system trusted keyrings 1135s Jul 29 21:05:15 autopkgtest kernel: Key type blacklist registered 1135s Jul 29 21:05:15 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 1135s Jul 29 21:05:15 autopkgtest kernel: zbud: loaded 1135s Jul 29 21:05:15 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 1135s Jul 29 21:05:15 autopkgtest kernel: fuse: init (API version 7.39) 1135s Jul 29 21:05:15 autopkgtest kernel: integrity: Platform Keyring initialized 1135s Jul 29 21:05:15 autopkgtest kernel: integrity: Machine keyring initialized 1135s Jul 29 21:05:15 autopkgtest kernel: Key type asymmetric registered 1135s Jul 29 21:05:15 autopkgtest kernel: Asymmetric key parser 'x509' registered 1135s Jul 29 21:05:15 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 1135s Jul 29 21:05:15 autopkgtest kernel: io scheduler mq-deadline registered 1135s Jul 29 21:05:15 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 1135s Jul 29 21:05:15 autopkgtest kernel: virtio-pci 0000:00:01.0: ibm,query-pe-dma-windows(2026) 800 8000000 20000000 returned 0, lb=80000000 ps=7 wn=1 1135s Jul 29 21:05:15 autopkgtest kernel: virtio-pci 0000:00:01.0: ibm,create-pe-dma-window(2027) 800 8000000 20000000 18 21 returned 0 (liobn = 0x80000001 starting addr = 8000000 0) 1135s Jul 29 21:05:15 autopkgtest kernel: virtio-pci 0000:00:02.0: enabling device (0100 -> 0103) 1135s Jul 29 21:05:15 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 1135s Jul 29 21:05:15 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 1135s Jul 29 21:05:15 autopkgtest kernel: Non-volatile memory driver v1.3 1135s Jul 29 21:05:15 autopkgtest kernel: Linux agpgart interface v0.103 1135s Jul 29 21:05:15 autopkgtest kernel: loop: module loaded 1135s Jul 29 21:05:15 autopkgtest kernel: virtio_scsi virtio1: 1/0/0 default/read/poll queues 1135s Jul 29 21:05:15 autopkgtest kernel: scsi host0: Virtio SCSI HBA 1135s Jul 29 21:05:15 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 1135s Jul 29 21:05:15 autopkgtest kernel: scsi 0:0:0:0: Direct-Access QEMU QEMU HARDDISK 2.5+ PQ: 0 ANSI: 5 1135s Jul 29 21:05:15 autopkgtest kernel: PPP generic driver version 2.4.2 1135s Jul 29 21:05:15 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 1135s Jul 29 21:05:15 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 1135s Jul 29 21:05:15 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-07-29T21:05:12 UTC (1722287112) 1135s Jul 29 21:05:15 autopkgtest kernel: i2c_dev: i2c /dev entries driver 1135s Jul 29 21:05:15 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 1135s Jul 29 21:05:15 autopkgtest kernel: device-mapper: uevent: version 1.0.3 1135s Jul 29 21:05:15 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@redhat.com 1135s Jul 29 21:05:15 autopkgtest kernel: pseries_idle_driver registered 1135s Jul 29 21:05:15 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 1135s Jul 29 21:05:15 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 1135s Jul 29 21:05:15 autopkgtest kernel: NET: Registered PF_INET6 protocol family 1135s Jul 29 21:05:15 autopkgtest kernel: sd 0:0:0:0: Power-on or device reset occurred 1135s Jul 29 21:05:15 autopkgtest kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0 1135s Jul 29 21:05:15 autopkgtest kernel: sd 0:0:0:0: [sda] 167772160 512-byte logical blocks: (85.9 GB/80.0 GiB) 1135s Jul 29 21:05:15 autopkgtest kernel: sd 0:0:0:0: [sda] Write Protect is off 1135s Jul 29 21:05:15 autopkgtest kernel: sd 0:0:0:0: [sda] Mode Sense: 63 00 00 08 1135s Jul 29 21:05:15 autopkgtest kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA 1135s Jul 29 21:05:15 autopkgtest kernel: sda: sda1 sda2 1135s Jul 29 21:05:15 autopkgtest kernel: sd 0:0:0:0: [sda] Attached SCSI disk 1135s Jul 29 21:05:15 autopkgtest kernel: Freeing initrd memory: 51072K 1135s Jul 29 21:05:15 autopkgtest kernel: Segment Routing with IPv6 1135s Jul 29 21:05:15 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 1135s Jul 29 21:05:15 autopkgtest kernel: NET: Registered PF_PACKET protocol family 1135s Jul 29 21:05:15 autopkgtest kernel: Key type dns_resolver registered 1135s Jul 29 21:05:15 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 1135s Jul 29 21:05:15 autopkgtest kernel: drmem: No dynamic reconfiguration memory found 1135s Jul 29 21:05:15 autopkgtest kernel: registered taskstats version 1 1135s Jul 29 21:05:15 autopkgtest kernel: Loading compiled-in X.509 certificates 1135s Jul 29 21:05:15 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 1135s Jul 29 21:05:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 1135s Jul 29 21:05:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 1135s Jul 29 21:05:15 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 1135s Jul 29 21:05:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 1135s Jul 29 21:05:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 1135s Jul 29 21:05:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 1135s Jul 29 21:05:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 1135s Jul 29 21:05:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 1135s Jul 29 21:05:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 1135s Jul 29 21:05:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 1135s Jul 29 21:05:15 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 1135s Jul 29 21:05:15 autopkgtest kernel: Key type .fscrypt registered 1135s Jul 29 21:05:15 autopkgtest kernel: Key type fscrypt-provisioning registered 1135s Jul 29 21:05:15 autopkgtest kernel: Key type encrypted registered 1135s Jul 29 21:05:15 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 1135s Jul 29 21:05:15 autopkgtest kernel: Secure boot mode disabled 1135s Jul 29 21:05:15 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 1135s Jul 29 21:05:15 autopkgtest kernel: Loading compiled-in module X.509 certificates 1135s Jul 29 21:05:15 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 1135s Jul 29 21:05:15 autopkgtest kernel: ima: Allocated hash algorithm: sha256 1135s Jul 29 21:05:15 autopkgtest kernel: Secure boot mode disabled 1135s Jul 29 21:05:15 autopkgtest kernel: Trusted boot mode disabled 1135s Jul 29 21:05:15 autopkgtest kernel: ima: No architecture policies found 1135s Jul 29 21:05:15 autopkgtest kernel: evm: Initialising EVM extended attributes: 1135s Jul 29 21:05:15 autopkgtest kernel: evm: security.selinux 1135s Jul 29 21:05:15 autopkgtest kernel: evm: security.SMACK64 1135s Jul 29 21:05:15 autopkgtest kernel: evm: security.SMACK64EXEC 1135s Jul 29 21:05:15 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 1135s Jul 29 21:05:15 autopkgtest kernel: evm: security.SMACK64MMAP 1135s Jul 29 21:05:15 autopkgtest kernel: evm: security.apparmor 1135s Jul 29 21:05:15 autopkgtest kernel: evm: security.ima 1135s Jul 29 21:05:15 autopkgtest kernel: evm: security.capability 1135s Jul 29 21:05:15 autopkgtest kernel: evm: HMAC attrs: 0x1 1135s Jul 29 21:05:15 autopkgtest kernel: SED: plpks not available 1135s Jul 29 21:05:15 autopkgtest kernel: clk: Disabling unused clocks 1135s Jul 29 21:05:15 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 1135s Jul 29 21:05:15 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8832K 1135s Jul 29 21:05:15 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 1135s Jul 29 21:05:15 autopkgtest kernel: Run /init as init process 1135s Jul 29 21:05:15 autopkgtest kernel: with arguments: 1135s Jul 29 21:05:15 autopkgtest kernel: /init 1135s Jul 29 21:05:15 autopkgtest kernel: earlyprintk 1135s Jul 29 21:05:15 autopkgtest kernel: with environment: 1135s Jul 29 21:05:15 autopkgtest kernel: HOME=/ 1135s Jul 29 21:05:15 autopkgtest kernel: TERM=linux 1135s Jul 29 21:05:15 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic 1135s Jul 29 21:05:15 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 1135s Jul 29 21:05:15 autopkgtest kernel: xhci_hcd 0000:00:03.0: xHCI Host Controller 1135s Jul 29 21:05:15 autopkgtest kernel: xhci_hcd 0000:00:03.0: new USB bus registered, assigned bus number 1 1135s Jul 29 21:05:15 autopkgtest kernel: xhci_hcd 0000:00:03.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010 1135s Jul 29 21:05:15 autopkgtest kernel: xhci_hcd 0000:00:03.0: xHCI Host Controller 1135s Jul 29 21:05:15 autopkgtest kernel: xhci_hcd 0000:00:03.0: new USB bus registered, assigned bus number 2 1135s Jul 29 21:05:15 autopkgtest kernel: xhci_hcd 0000:00:03.0: Host supports USB 3.0 SuperSpeed 1135s Jul 29 21:05:15 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.08 1135s Jul 29 21:05:15 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 1135s Jul 29 21:05:15 autopkgtest kernel: usb usb1: Product: xHCI Host Controller 1135s Jul 29 21:05:15 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 1135s Jul 29 21:05:15 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:03.0 1135s Jul 29 21:05:15 autopkgtest kernel: hub 1-0:1.0: USB hub found 1135s Jul 29 21:05:15 autopkgtest kernel: hub 1-0:1.0: 4 ports detected 1135s Jul 29 21:05:15 autopkgtest kernel: usb usb2: We don't know the algorithms for LPM for this host, disabling LPM. 1135s Jul 29 21:05:15 autopkgtest kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.08 1135s Jul 29 21:05:15 autopkgtest kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 1135s Jul 29 21:05:15 autopkgtest kernel: usb usb2: Product: xHCI Host Controller 1135s Jul 29 21:05:15 autopkgtest kernel: usb usb2: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 1135s Jul 29 21:05:15 autopkgtest kernel: usb usb2: SerialNumber: 0000:00:03.0 1135s Jul 29 21:05:15 autopkgtest kernel: hub 2-0:1.0: USB hub found 1135s Jul 29 21:05:15 autopkgtest kernel: hub 2-0:1.0: 4 ports detected 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: vpermxor8 gen() 20666 MB/s 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: vpermxor4 gen() 18521 MB/s 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: vpermxor2 gen() 14806 MB/s 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: vpermxor1 gen() 12726 MB/s 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: altivecx8 gen() 13183 MB/s 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: altivecx4 gen() 13113 MB/s 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: altivecx2 gen() 10248 MB/s 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: altivecx1 gen() 7869 MB/s 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: int64x8 gen() 6966 MB/s 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: int64x4 gen() 8537 MB/s 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: int64x2 gen() 6597 MB/s 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: int64x1 gen() 5226 MB/s 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 20666 MB/s 1135s Jul 29 21:05:15 autopkgtest kernel: raid6: using intx1 recovery algorithm 1135s Jul 29 21:05:15 autopkgtest kernel: xor: measuring software checksum speed 1135s Jul 29 21:05:15 autopkgtest kernel: 8regs : 17244 MB/sec 1135s Jul 29 21:05:15 autopkgtest kernel: 8regs_prefetch : 15421 MB/sec 1135s Jul 29 21:05:15 autopkgtest kernel: 32regs : 17223 MB/sec 1135s Jul 29 21:05:15 autopkgtest kernel: 32regs_prefetch : 15506 MB/sec 1135s Jul 29 21:05:15 autopkgtest kernel: altivec : 17422 MB/sec 1135s Jul 29 21:05:15 autopkgtest kernel: xor: using function: altivec (17422 MB/sec) 1135s Jul 29 21:05:15 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 1135s Jul 29 21:05:15 autopkgtest kernel: EXT4-fs (sda1): mounted filesystem f999abd5-af41-40ac-8675-cf1e7d4878fb ro with ordered data mode. Quota mode: none. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Inserted module 'autofs4' 1135s Jul 29 21:05:15 autopkgtest systemd[1]: systemd 256.4-1ubuntu3 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) 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Detected virtualization kvm. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Detected architecture ppc64-le. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Hostname set to . 1135s Jul 29 21:05:15 autopkgtest systemd[1]: bpf-restrict-fs: BPF LSM hook not enabled in the kernel, BPF LSM not supported. 1135s Jul 29 21:05:15 autopkgtest kernel: NET: Registered PF_VSOCK protocol family 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Configuration file /run/systemd/system/systemd-networkd-wait-online.service.d/10-netplan.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Configuration file /run/systemd/system/netplan-ovs-cleanup.service is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Queued start job for default target graphical.target. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Reached target swap.target - Swaps. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Listening on multipathd.socket - multipathd control socket. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Sockets. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounting run-lock.mount - Legacy Locks Directory /run/lock... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting modprobe@dm_multipath.service - Load Kernel Module dm_multipath... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 1135s Jul 29 21:05:15 autopkgtest systemd[1]: systemd-fsck-root.service - File System Check on Root Device was skipped because of an unmet condition check (ConditionPathExists=!/run/initramfs/fsck-root). 1135s Jul 29 21:05:15 autopkgtest systemd[1]: systemd-hibernate-clear.service - Clear Stale Hibernate Storage Info was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67). 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 1135s Jul 29 21:05:15 autopkgtest systemd-journald[284]: Collecting audit messages is disabled. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounted run-lock.mount - Legacy Locks Directory /run/lock. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: modprobe@dm_multipath.service: Deactivated successfully. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished modprobe@dm_multipath.service - Load Kernel Module dm_multipath. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 1135s Jul 29 21:05:15 autopkgtest systemd-journald[284]: Journal started 1135s Jul 29 21:05:15 autopkgtest systemd-journald[284]: Runtime Journal (/run/log/journal/f2b026c9c820405b87839afd42a274c3) is 8M, max 78.4M, 70.4M free. 1135s Jul 29 21:05:15 autopkgtest kernel: EXT4-fs (sda1): re-mounted f999abd5-af41-40ac-8675-cf1e7d4878fb r/w. Quota mode: none. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 1135s Jul 29 21:05:15 autopkgtest multipathd[336]: multipathd v0.9.9: start up 1135s Jul 29 21:05:15 autopkgtest systemd-random-seed[340]: Kernel entropy pool is not initialized yet, waiting until it is. 1135s Jul 29 21:05:15 autopkgtest multipathd[336]: reconfigure: setting up paths and maps 1135s Jul 29 21:05:15 autopkgtest systemd-journald[284]: Time spent on flushing to /var/log/journal/f2b026c9c820405b87839afd42a274c3 is 15.219ms for 437 entries. 1135s Jul 29 21:05:15 autopkgtest systemd-journald[284]: System Journal (/var/log/journal/f2b026c9c820405b87839afd42a274c3) is 16M, max 4G, 3.9G free. 1135s Jul 29 21:05:15 autopkgtest systemd-journald[284]: Received client request to flush runtime journal. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 1135s Jul 29 21:05:15 autopkgtest apparmor.systemd[355]: Restarting AppArmor 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 359 (systemd-binfmt) 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 1135s Jul 29 21:05:15 autopkgtest apparmor.systemd[355]: Reloading AppArmor profiles 1135s Jul 29 21:05:15 autopkgtest systemd-tmpfiles[367]: /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 1135s Jul 29 21:05:15 autopkgtest kernel: audit: type=1400 audit(1722287115.504:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=382 comm="apparmor_parser" 1135s Jul 29 21:05:15 autopkgtest kernel: audit: type=1400 audit(1722287115.504:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=379 comm="apparmor_parser" 1135s Jul 29 21:05:15 autopkgtest kernel: audit: type=1400 audit(1722287115.504:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=380 comm="apparmor_parser" 1135s Jul 29 21:05:15 autopkgtest kernel: audit: type=1400 audit(1722287115.508:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=381 comm="apparmor_parser" 1135s Jul 29 21:05:15 autopkgtest kernel: audit: type=1400 audit(1722287115.508:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=383 comm="apparmor_parser" 1135s Jul 29 21:05:15 autopkgtest kernel: audit: type=1400 audit(1722287115.508:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=385 comm="apparmor_parser" 1135s Jul 29 21:05:15 autopkgtest kernel: audit: type=1400 audit(1722287115.508:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=384 comm="apparmor_parser" 1135s Jul 29 21:05:15 autopkgtest kernel: audit: type=1400 audit(1722287115.512:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="busybox" pid=386 comm="apparmor_parser" 1135s Jul 29 21:05:15 autopkgtest kernel: audit: type=1400 audit(1722287115.512:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="cam" pid=388 comm="apparmor_parser" 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 1135s Jul 29 21:05:15 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 1135s Jul 29 21:05:15 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 1135s Jul 29 21:05:15 autopkgtest systemd-udevd[360]: Using default interface naming scheme 'v255'. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: systemd-ask-password-plymouth.path - Forward Password Requests to Plymouth Directory Watch was skipped because of an unmet condition check (ConditionPathExists=/run/plymouth/pid). 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 1135s Jul 29 21:05:15 autopkgtest (udev-worker)[446]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 1135s Jul 29 21:05:15 autopkgtest kernel: random: crng init done 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 1135s Jul 29 21:05:15 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 1135s Jul 29 21:05:15 autopkgtest systemd[1]: systemd-machine-id-commit.service - Save Transient machine-id to Disk was skipped because of an unmet condition check (ConditionPathIsMountPoint=/etc/machine-id). 1135s Jul 29 21:05:16 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 1135s Jul 29 21:05:16 autopkgtest cloud-init[659]: Cloud-init v. 24.3~1g6e4153b3-0ubuntu1 running 'init-local' at Mon, 29 Jul 2024 21:05:16 +0000. Up 4.09 seconds. 1135s Jul 29 21:05:16 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 1135s Jul 29 21:05:16 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 1135s Jul 29 21:05:16 autopkgtest dhcpcd[665]: dhcpcd-10.0.8 starting 1135s Jul 29 21:05:16 autopkgtest dhcpcd[668]: DUID 00:01:00:01:2d:c3:64:c3:fa:16:3e:9f:5d:b2 1135s Jul 29 21:05:16 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 1135s Jul 29 21:05:16 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 1135s Jul 29 21:05:16 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 1135s Jul 29 21:05:16 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 1135s Jul 29 21:05:16 autopkgtest systemd-resolved[401]: Positive Trust Anchors: 1135s Jul 29 21:05:16 autopkgtest systemd-resolved[401]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 1135s Jul 29 21:05:16 autopkgtest systemd-resolved[401]: 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 1135s Jul 29 21:05:16 autopkgtest systemd-resolved[401]: Using system hostname 'autopkgtest'. 1135s Jul 29 21:05:16 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 1135s Jul 29 21:05:16 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 1135s Jul 29 21:05:16 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 1135s Jul 29 21:05:16 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 1135s Jul 29 21:05:16 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 1135s Jul 29 21:05:16 autopkgtest dhcpcd[668]: enp0s1: IAID 3e:44:90:3b 1135s Jul 29 21:05:18 autopkgtest dhcpcd[668]: enp0s1: rebinding lease of 10.43.136.34 1135s Jul 29 21:05:23 autopkgtest dhcpcd[668]: enp0s1: DHCP lease expired 1135s Jul 29 21:05:23 autopkgtest dhcpcd[668]: enp0s1: soliciting a DHCP lease 1135s Jul 29 21:05:23 autopkgtest dhcpcd[668]: enp0s1: offered 10.43.136.34 from 10.43.136.8 1135s Jul 29 21:05:24 autopkgtest dhcpcd[668]: enp0s1: leased 10.43.136.34 for 86400 seconds 1135s Jul 29 21:05:24 autopkgtest dhcpcd[668]: enp0s1: adding route to 10.43.136.0/24 1135s Jul 29 21:05:24 autopkgtest dhcpcd[668]: enp0s1: adding host route to 169.254.169.254 via 10.43.136.1 1135s Jul 29 21:05:24 autopkgtest dhcpcd[668]: enp0s1: adding default route via 10.43.136.1 1135s Jul 29 21:05:24 autopkgtest dhcpcd[668]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 1135s Jul 29 21:05:29 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 1135s Jul 29 21:05:29 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 1135s Jul 29 21:05:29 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 1135s Jul 29 21:05:29 autopkgtest systemd-networkd[701]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 1135s Jul 29 21:05:29 autopkgtest systemd-networkd[701]: lo: Link UP 1135s Jul 29 21:05:29 autopkgtest systemd-networkd[701]: lo: Gained carrier 1135s Jul 29 21:05:29 autopkgtest systemd-networkd[701]: Enumeration completed 1135s Jul 29 21:05:29 autopkgtest systemd-networkd[701]: enp0s1: Link UP 1135s Jul 29 21:05:29 autopkgtest systemd-networkd[701]: enp0s1: Gained carrier 1135s Jul 29 21:05:29 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 1135s Jul 29 21:05:29 autopkgtest systemd-networkd[701]: enp0s1: Gained IPv6LL 1135s Jul 29 21:05:29 autopkgtest systemd-timesyncd[403]: Network configuration changed, trying to establish connection. 1135s Jul 29 21:05:29 autopkgtest systemd[1]: Reached target network.target - Network. 1135s Jul 29 21:05:29 autopkgtest systemd-networkd[701]: enp0s1: Link DOWN 1135s Jul 29 21:05:29 autopkgtest systemd-networkd[701]: enp0s1: Lost carrier 1135s Jul 29 21:05:29 autopkgtest systemd-timesyncd[403]: No network connectivity, watching for changes. 1135s Jul 29 21:05:29 autopkgtest systemd-networkd[701]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 1135s Jul 29 21:05:29 autopkgtest systemd-networkd[701]: enp0s1: Link UP 1135s Jul 29 21:05:29 autopkgtest systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... 1135s Jul 29 21:05:29 autopkgtest systemd-networkd[701]: enp0s1: Gained carrier 1135s Jul 29 21:05:29 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 1135s Jul 29 21:05:29 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 1135s Jul 29 21:05:30 autopkgtest systemd-networkd[701]: enp0s1: DHCPv4 address 10.43.136.34/24, gateway 10.43.136.1 acquired from 10.43.136.8 1135s Jul 29 21:05:30 autopkgtest systemd-timesyncd[403]: Network configuration changed, trying to establish connection. 1135s Jul 29 21:05:30 autopkgtest systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. 1135s Jul 29 21:05:29 autopkgtest systemd-timesyncd[403]: Contacted time server 91.189.91.157:123 (ntp.ubuntu.com). 1135s Jul 29 21:05:29 autopkgtest systemd-journald[284]: Time jumped backwards, rotating. 1135s Jul 29 21:05:29 autopkgtest systemd-resolved[401]: Clock change detected. Flushing caches. 1135s Jul 29 21:05:29 autopkgtest systemd-timesyncd[403]: Initial clock synchronization to Mon 2024-07-29 21:05:29.517271 UTC. 1135s Jul 29 21:05:30 autopkgtest systemd-networkd[701]: enp0s1: Gained IPv6LL 1135s Jul 29 21:05:30 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 1135s Jul 29 21:05:30 autopkgtest systemd[1]: Starting cloud-init.service - Cloud-init: Network Stage... 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: Cloud-init v. 24.3~1g6e4153b3-0ubuntu1 running 'init' at Mon, 29 Jul 2024 21:05:30 +0000. Up 19.25 seconds. 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | enp0s1 | True | 10.43.136.34 | 255.255.255.0 | global | fa:16:3e:44:90:3b | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | enp0s1 | True | fe80::f816:3eff:fe44:903b/64 | . | link | fa:16:3e:44:90:3b | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | lo | True | ::1/128 | . | host | . | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info++++++++++++++++++++++++++++++++ 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | 0 | 0.0.0.0 | 10.43.136.1 | 0.0.0.0 | enp0s1 | UG | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | 1 | 10.43.136.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | 2 | 10.43.136.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | 3 | 91.189.91.130 | 10.43.136.1 | 255.255.255.255 | enp0s1 | UGH | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | 4 | 169.254.169.254 | 10.43.136.1 | 255.255.255.255 | enp0s1 | UGH | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: +-------+-----------------+-------------+-----------------+-----------+-------+ 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: +-------+-------------+---------+-----------+-------+ 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | Route | Destination | Gateway | Interface | Flags | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: +-------+-------------+---------+-----------+-------+ 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | 2 | local | :: | enp0s1 | U | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: | 3 | multicast | :: | enp0s1 | U | 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: ci-info: +-------+-------------+---------+-----------+-------+ 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: 2024-07-29 21:05:31,244 - 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. 1135s Jul 29 21:05:31 autopkgtest cloud-init[714]: 2024-07-29 21:05:31,244 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Finished cloud-init.service - Cloud-init: Network Stage. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 1135s Jul 29 21:05:31 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). 1135s Jul 29 21:05:31 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). 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 1135s Jul 29 21:05:31 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). 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Reached target paths.target - Path Units. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Reached target ssh-access.target - SSH Access Available. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Reached target basic.target - Basic System. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: System is tainted: unmerged-bin 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 1135s Jul 29 21:05:31 autopkgtest (sh)[749]: autopkgtest@hvc1.service: Failed to set up standard input: No such device 1135s Jul 29 21:05:31 autopkgtest (sh)[749]: autopkgtest@hvc1.service: Failed at step STDIN spawning /bin/sh: No such device 1135s Jul 29 21:05:31 autopkgtest (sh)[750]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 1135s Jul 29 21:05:31 autopkgtest (sh)[750]: autopkgtest@ttyS1.service: Failed at step STDIN spawning /bin/sh: Input/output error 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 1135s Jul 29 21:05:31 autopkgtest (cron)[752]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 1135s Jul 29 21:05:31 autopkgtest cron[752]: (CRON) INFO (pidfile fd = 3) 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 1135s Jul 29 21:05:31 autopkgtest cron[752]: (CRON) INFO (Running @reboot jobs) 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 1135s Jul 29 21:05:31 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). 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 1135s Jul 29 21:05:31 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: opal_errd.service - opal_errd (PowerNV platform error handling) Service was skipped because of an unmet condition check (ConditionVirtualization=false). 1135s Jul 29 21:05:31 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). 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 1135s Jul 29 21:05:31 autopkgtest dbus-daemon[753]: [system] AppArmor D-Bus mediation is enabled 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 1135s Jul 29 21:05:31 autopkgtest dbus-daemon[753]: [system] Activating systemd to hand-off: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.0' (uid=998 pid=701 comm="/usr/lib/systemd/systemd-networkd" label="unconfined") 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 1135s Jul 29 21:05:31 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). 1135s Jul 29 21:05:31 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: autopkgtest@hvc1.service: Deactivated successfully. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 1135s Jul 29 21:05:31 autopkgtest dbus-daemon[753]: [system] Successfully activated service 'org.freedesktop.systemd1' 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting systemd-hostnamed.service - Hostname Service... 1135s Jul 29 21:05:31 autopkgtest udisksd[768]: udisks daemon version 2.10.1 starting 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 1135s Jul 29 21:05:31 autopkgtest rng-tools-debian[798]: found /dev/hwrng but could not use it 1135s Jul 29 21:05:31 autopkgtest rng-tools-debian[759]: * Configuring Hardware RNG entropy gatherer daemon 1135s Jul 29 21:05:31 autopkgtest rng-tools-debian[759]: ...fail! 1135s Jul 29 21:05:31 autopkgtest rng-tools-debian[806]: not starting: no hardware RNG device found 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 1135s Jul 29 21:05:31 autopkgtest systemd-logind[765]: New seat seat0. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 1135s Jul 29 21:05:31 autopkgtest kernel: kauditd_printk_skb: 110 callbacks suppressed 1135s Jul 29 21:05:31 autopkgtest kernel: audit: type=1400 audit(1722287131.605:121): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=804 comm="apparmor_parser" 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started systemd-hostnamed.service - Hostname Service. 1135s Jul 29 21:05:31 autopkgtest dbus-daemon[753]: [system] Successfully activated service 'org.freedesktop.hostname1' 1135s Jul 29 21:05:31 autopkgtest systemd-networkd[701]: Could not set hostname: Access denied 1135s Jul 29 21:05:31 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 1135s Jul 29 21:05:31 autopkgtest udisksd[768]: Acquired the name org.freedesktop.UDisks2 on the system message bus 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 1135s Jul 29 21:05:31 autopkgtest rsyslogd[824]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2406.0] 1135s Jul 29 21:05:31 autopkgtest rsyslogd[824]: rsyslogd's groupid changed to 102 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 1135s Jul 29 21:05:31 autopkgtest rsyslogd[824]: rsyslogd's userid changed to 102 1135s Jul 29 21:05:31 autopkgtest rsyslogd[824]: [origin software="rsyslogd" swVersion="8.2406.0" x-pid="824" x-info="https://www.rsyslog.com"] start 1135s Jul 29 21:05:31 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 1135s Jul 29 21:05:31 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 1135s Jul 29 21:05:31 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 1135s Jul 29 21:05:31 autopkgtest cloud-init[845]: Cloud-init v. 24.3~1g6e4153b3-0ubuntu1 running 'modules:config' at Mon, 29 Jul 2024 21:05:31 +0000. Up 20.14 seconds. 1135s Jul 29 21:05:32 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 1135s Jul 29 21:05:32 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 1135s Jul 29 21:05:32 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 1135s Jul 29 21:05:32 autopkgtest sshd[849]: Server listening on :: port 22. 1135s Jul 29 21:05:32 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 1135s Jul 29 21:05:32 autopkgtest cloud-init[856]: Cloud-init v. 24.3~1g6e4153b3-0ubuntu1 running 'modules:final' at Mon, 29 Jul 2024 21:05:32 +0000. Up 20.78 seconds. 1135s Jul 29 21:05:32 autopkgtest cloud-init[856]: Cloud-init v. 24.3~1g6e4153b3-0ubuntu1 finished at Mon, 29 Jul 2024 21:05:32 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 20.90 seconds 1135s Jul 29 21:05:32 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 1135s Jul 29 21:05:32 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 1135s Jul 29 21:05:32 autopkgtest systemd[1]: Startup finished in 2.720s (kernel) + 18.252s (userspace) = 20.973s. 1135s Jul 29 21:05:32 autopkgtest kernel: fbcon: Taking over console 1135s Jul 29 21:05:32 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 1135s Jul 29 21:05:32 autopkgtest sshd[851]: Accepted publickey for ubuntu from 10.136.6.184 port 51674 ssh2: RSA SHA256:h+sR5tlNZDfTFbz7cAH7wlRKfPAD8MpCdKJaoGeL2vg 1135s Jul 29 21:05:32 autopkgtest sshd[851]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 1135s Jul 29 21:05:32 autopkgtest sshd[851]: pam_systemd(sshd:session): New sd-bus connection (system-bus-pam-systemd-851) opened. 1135s Jul 29 21:05:32 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 1135s Jul 29 21:05:32 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 1135s Jul 29 21:05:32 autopkgtest systemd-logind[765]: New session 1 of user ubuntu. 1135s Jul 29 21:05:32 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 1135s Jul 29 21:05:32 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 1135s Jul 29 21:05:32 autopkgtest (systemd)[884]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 1135s Jul 29 21:05:32 autopkgtest systemd-logind[765]: New session 2 of user ubuntu. 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Queued start job for default target default.target. 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Created slice app.slice - User Application Slice. 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Reached target paths.target - Paths. 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Reached target timers.target - Timers. 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Starting dbus.socket - D-Bus User Message Bus Socket... 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Listening on keyboxd.socket - GnuPG public key management service. 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Listening on dbus.socket - D-Bus User Message Bus Socket. 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Reached target sockets.target - Sockets. 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Reached target basic.target - Basic System. 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Reached target default.target - Main User Target. 1135s Jul 29 21:05:33 autopkgtest systemd[884]: Startup finished in 130ms. 1135s Jul 29 21:05:33 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 1135s Jul 29 21:05:33 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 1135s Jul 29 21:05:33 autopkgtest sudo[912]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 1135s Jul 29 21:05:33 autopkgtest sudo[912]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:33 autopkgtest sudo[912]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:33 autopkgtest sudo[917]: 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' 1135s Jul 29 21:05:33 autopkgtest sudo[917]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:33 autopkgtest sudo[917]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:34 autopkgtest sudo[929]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.pZgNe4 1135s Jul 29 21:05:34 autopkgtest sudo[929]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:34 autopkgtest sudo[929]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:34 autopkgtest sudo[939]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.pZgNe4/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.pZgNe4/autopkgtest-reboot' 1135s Jul 29 21:05:34 autopkgtest sudo[939]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:34 autopkgtest sudo[939]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:34 autopkgtest sudo[951]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.pZgNe4/autopkgtest-reboot 1135s Jul 29 21:05:34 autopkgtest sudo[951]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:34 autopkgtest sudo[951]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:34 autopkgtest sudo[961]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.pZgNe4/autopkgtest-reboot /tmp/autopkgtest-reboot 1135s Jul 29 21:05:34 autopkgtest sudo[961]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:34 autopkgtest sudo[961]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:34 autopkgtest sudo[971]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.pZgNe4/autopkgtest-reboot /sbin/autopkgtest-reboot 1135s Jul 29 21:05:34 autopkgtest sudo[971]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:34 autopkgtest sudo[971]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:35 autopkgtest sudo[981]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.pZgNe4 1135s Jul 29 21:05:35 autopkgtest sudo[981]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:35 autopkgtest sudo[981]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:35 autopkgtest sudo[991]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.pZgNe4/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.pZgNe4/autopkgtest-reboot-prepare' 1135s Jul 29 21:05:35 autopkgtest sudo[991]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:35 autopkgtest sudo[991]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:35 autopkgtest sudo[1003]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.pZgNe4/autopkgtest-reboot-prepare 1135s Jul 29 21:05:35 autopkgtest sudo[1003]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:35 autopkgtest sudo[1003]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:36 autopkgtest sudo[1013]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.pZgNe4/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 1135s Jul 29 21:05:36 autopkgtest sudo[1013]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:36 autopkgtest sudo[1013]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:36 autopkgtest sudo[1023]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 1135s Jul 29 21:05:36 autopkgtest sudo[1023]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:36 autopkgtest sudo[1023]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:36 autopkgtest sudo[1033]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 1135s Jul 29 21:05:36 autopkgtest sudo[1033]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:36 autopkgtest sudo[1033]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:37 autopkgtest sudo[1043]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.pZgNe4/testbed-packages' 1135s Jul 29 21:05:37 autopkgtest sudo[1043]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:37 autopkgtest sudo[1043]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:37 autopkgtest sudo[1054]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.pZgNe4/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.pZgNe4/autopkgtest-reboot' 1135s Jul 29 21:05:38 autopkgtest sudo[1075]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:38 autopkgtest sudo[1075]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:38 autopkgtest sudo[1087]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.pZgNe4/autopkgtest-reboot 1135s Jul 29 21:05:38 autopkgtest sudo[1087]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:38 autopkgtest sudo[1087]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:39 autopkgtest sudo[1097]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.pZgNe4/autopkgtest-reboot /tmp/autopkgtest-reboot 1135s Jul 29 21:05:39 autopkgtest sudo[1097]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:39 autopkgtest sudo[1097]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:39 autopkgtest sudo[1107]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.pZgNe4/autopkgtest-reboot /sbin/autopkgtest-reboot 1135s Jul 29 21:05:39 autopkgtest sudo[1107]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:39 autopkgtest sudo[1107]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:39 autopkgtest sudo[1117]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.pZgNe4 1135s Jul 29 21:05:39 autopkgtest sudo[1117]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:39 autopkgtest sudo[1117]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:40 autopkgtest sudo[1127]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.pZgNe4/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.pZgNe4/autopkgtest-reboot-prepare' 1135s Jul 29 21:05:40 autopkgtest sudo[1127]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:40 autopkgtest sudo[1127]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:40 autopkgtest sudo[1139]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.pZgNe4/autopkgtest-reboot-prepare 1135s Jul 29 21:05:40 autopkgtest sudo[1139]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:40 autopkgtest sudo[1139]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:41 autopkgtest sudo[1149]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.pZgNe4/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 1135s Jul 29 21:05:41 autopkgtest sudo[1149]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:41 autopkgtest sudo[1149]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:41 autopkgtest sudo[1159]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 1135s Jul 29 21:05:41 autopkgtest sudo[1159]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:41 autopkgtest sudo[1159]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:42 autopkgtest sudo[1169]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 1135s Jul 29 21:05:42 autopkgtest sudo[1169]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:42 autopkgtest sudo[1169]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:43 autopkgtest sudo[1178]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.pZgNe4 1135s Jul 29 21:05:43 autopkgtest sudo[1178]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:43 autopkgtest sudo[1178]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:43 autopkgtest sudo[1188]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.pZgNe4/2-autopkgtest-satdep.deb' 1135s Jul 29 21:05:43 autopkgtest sudo[1188]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:43 autopkgtest sudo[1188]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:44 autopkgtest sudo[1199]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.pZgNe4/2-autopkgtest-satdep.deb 1135s Jul 29 21:05:44 autopkgtest sudo[1199]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:44 autopkgtest sudo[1199]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:05:44 autopkgtest sudo[1209]: 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.pZgNe4/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' 1135s Jul 29 21:05:44 autopkgtest sudo[1209]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:05:47 autopkgtest systemd[1]: Reload requested from client PID 1449 ('systemctl') (unit session-1.scope)... 1135s Jul 29 21:05:47 autopkgtest systemd[1]: Reloading... 1135s Jul 29 21:05: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. 1135s Jul 29 21:05: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. 1135s Jul 29 21:05:48 autopkgtest systemd[1]: Reloading finished in 211 ms. 1135s Jul 29 21:05:48 autopkgtest systemd[1]: Reload requested from client PID 1499 ('systemctl') (unit session-1.scope)... 1135s Jul 29 21:05:48 autopkgtest systemd[1]: Reloading... 1135s Jul 29 21:05: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. 1135s Jul 29 21:05: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. 1135s Jul 29 21:05:48 autopkgtest systemd[1]: Reloading finished in 179 ms. 1135s Jul 29 21:05:48 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 1135s Jul 29 21:05:48 autopkgtest tgtd[1545]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 1135s Jul 29 21:05:48 autopkgtest tgtd[1545]: tgtd: work_timer_start(146) use timer_fd based scheduler 1135s Jul 29 21:05:48 autopkgtest tgtd[1545]: tgtd: bs_init(387) use signalfd notification 1135s Jul 29 21:05:48 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 1135s Jul 29 21:05:48 autopkgtest systemd[1]: Reload requested from client PID 1573 ('systemctl') (unit session-1.scope)... 1135s Jul 29 21:05:48 autopkgtest systemd[1]: Reloading... 1135s Jul 29 21:05: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. 1135s Jul 29 21:05: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. 1135s Jul 29 21:05:49 autopkgtest systemd[1]: Reloading finished in 198 ms. 1135s Jul 29 21:05:49 autopkgtest systemd[1]: Reload requested from client PID 1617 ('systemctl') (unit session-1.scope)... 1135s Jul 29 21:05:49 autopkgtest systemd[1]: Reloading... 1135s Jul 29 21:05: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. 1135s Jul 29 21:05: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. 1135s Jul 29 21:05:49 autopkgtest systemd[1]: Reloading finished in 186 ms. 1135s Jul 29 21:05:49 autopkgtest systemd[1]: Reload requested from client PID 1663 ('systemctl') (unit session-1.scope)... 1135s Jul 29 21:05:49 autopkgtest systemd[1]: Reloading... 1135s Jul 29 21:05: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. 1135s Jul 29 21:05: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. 1135s Jul 29 21:05:49 autopkgtest systemd[1]: Reloading finished in 178 ms. 1135s Jul 29 21:05:49 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 1135s Jul 29 21:05:49 autopkgtest systemd[1]: Reload requested from client PID 1714 ('systemctl') (unit session-1.scope)... 1135s Jul 29 21:05:49 autopkgtest systemd[1]: Reloading... 1135s Jul 29 21:05: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. 1135s Jul 29 21:05: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. 1135s Jul 29 21:05:50 autopkgtest systemd[1]: Reloading finished in 188 ms. 1135s Jul 29 21:05:50 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 1135s Jul 29 21:05:50 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 1135s Jul 29 21:05:50 autopkgtest systemd[1]: Reload requested from client PID 1769 ('systemctl') (unit session-1.scope)... 1135s Jul 29 21:05:50 autopkgtest systemd[1]: Reloading... 1135s Jul 29 21:05: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. 1135s Jul 29 21:05: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. 1135s Jul 29 21:05:50 autopkgtest systemd[1]: Reloading finished in 189 ms. 1135s Jul 29 21:06:00 autopkgtest sudo[1209]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:06:00 autopkgtest sudo[5250]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 1135s Jul 29 21:06:00 autopkgtest sudo[5250]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:06:00 autopkgtest sudo[5250]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:06:00 autopkgtest sudo[5260]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 1135s Jul 29 21:06:00 autopkgtest sudo[5260]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:06:00 autopkgtest sudo[5260]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:06:01 autopkgtest sudo[5270]: 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 1135s Jul 29 21:06:01 autopkgtest sudo[5270]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:06:01 autopkgtest systemd[1]: systemd-hostnamed.service: Deactivated successfully. 1135s Jul 29 21:06:02 autopkgtest sudo[5270]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:06:02 autopkgtest sudo[5286]: 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 1135s Jul 29 21:06:02 autopkgtest sudo[5286]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:06:02 autopkgtest sudo[5286]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:06:02 autopkgtest sudo[5298]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 1135s Jul 29 21:06:02 autopkgtest sudo[5298]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:06:02 autopkgtest sudo[5298]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:06:03 autopkgtest sudo[5310]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 1135s Jul 29 21:06:03 autopkgtest sudo[5310]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:06:03 autopkgtest sudo[5310]: pam_unix(sudo:session): session closed for user root 1135s Jul 29 21:06:03 autopkgtest sudo[5320]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.pZgNe4/tgtbasedmpaths-packages.all' 1135s Jul 29 21:06:03 autopkgtest sudo[5320]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1135s Jul 29 21:06:03 autopkgtest sudo[5320]: pam_unix(sudo:session+ echo Test WWN should now point to DM 1135s + readlink /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1135s + grep dm 1135s + mkfs.ext4 -F /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1135s mke2fs 1.47.1 (20-May-2024) 1135s + udevadm settle 1135s + sleep 3s 1135s ): session closed for user root 1135s Jul 29 21:06:04 autopkgtest sudo[5331]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 1139s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1139s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1139s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 1139s latency : target=0, window=0, percentile=100.00%, depth=1 1139s 1139s Run status group 0 (all jobs): 1139s WRITE: bw=116MiB/s (122MB/s), 116MiB/s-116MiB/s (122MB/s-122MB/s), io=87.5MiB (91.8MB), run=752-752msec 1139s 1139s Disk stats (read/write): 1139s dm-0: ios=1/1186, sectors=8/151808, merge=0/0, ticks=1/580, in_queue=581, util=87.03%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/165, aggrin_queue=165, aggrutil=86.60% 1139s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 1139s sdb: ios=1/1402, sectors=8/179280, merge=0/0, ticks=1/662, in_queue=662, util=86.60% 1139s sde: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 1139s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 1139s Starting the path changes in background 1139s + echo Starting the path changes in background 1139s + date +Pre FIO %H:%M:%S.%N 1139s Pre FIO 21:06:26.687061263 1139s + fio --max-jobs=4 /tmp/autopkgtest.pZgNe4/tgtbasedmpaths-artifacts/path-change-check.fio 1139s 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 1139s fio-3.37 1139s Starting 1 thread 1320s 1320s verify-phase: (groupid=0, jobs=1): err= 0: pid=5680: Mon Jul 29 21:09:27 2024 1320s read: IOPS=2785, BW=174MiB/s (183MB/s)(30.6GiB/180001msec) 1320s clat (usec): min=91, max=47855, avg=335.71, stdev=337.72 1320s lat (usec): min=91, max=47855, avg=335.82, stdev=337.72 1320s clat percentiles (usec): 1320s | 1.00th=[ 153], 5.00th=[ 186], 10.00th=[ 204], 20.00th=[ 223], 1320s | 30.00th=[ 241], 40.00th=[ 281], 50.00th=[ 310], 60.00th=[ 330], 1320s | 70.00th=[ 355], 80.00th=[ 388], 90.00th=[ 424], 95.00th=[ 490], 1320s | 99.00th=[ 1172], 99.50th=[ 1909], 99.90th=[ 4621], 99.95th=[ 6259], 1320s | 99.99th=[11076] 1320s bw ( KiB/s): min=93696, max=356608, per=100.00%, avg=178577.64, stdev=40444.06, samples=359 1320s iops : min= 1464, max= 5572, avg=2790.20, stdev=631.94, samples=359 1320s lat (usec) : 100=0.05%, 250=32.91%, 500=62.47%, 750=2.76%, 1000=0.57% 1320s lat (msec) : 2=0.77%, 4=0.32%, 10=0.14%, 20=0.01%, 50=0.01% 1320s cpu : usr=7.40%, sys=7.71%, ctx=501488, majf=0, minf=1 1320s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 1320s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1320s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1320s issued rwts: total=501425,0,0,0 short=0,0,0,0 dropped=0,0,0,0 1320s latency : target=0, window=0, percentile=100.00%, depth=1 1320s 1320s Run status group 0 (all jobs): 1320s READ: bw=174MiB/s (183MB/s), 174MiB/s-174MiB/s (183MB/s-183MB/s), io=30.6GiB (32.9GB), run=180001-180001msec 1320s 1320s Disk stats (read/write): 1320s dm-0: ios=501631/11, sectors=64161336/12944, merge=22/10, ticks=172019/83, in_queue=172148, util=99.81%, aggrios=35462/2, aggsectors=4535470/3236, aggrmerge=0/0, aggrticks=11017/9, aggrin_queue=11026, aggrutil=99.16% 1320s sdd: ios=26802/0, sectors=3428224/0, merge=0/0, ticks=8800/0, in_queue=8800, util=33.02% 1320s sdb: ios=26459/10, sectors=3384192/12944, merge=0/0, ticks=8636/37, in_queue=8673, util=99.16% 1320s sde: ios=60710/0, sectors=7765248/0, merge=0/0, ticks=17734/0, in_queue=17734, util=40.03% 1320s sdc: ios=27878/0, sectors=3564216/0, merge=0/0, ticks=8898/0, in_queue=8898, util=50.14% 1320s Post FIO 21:09:27.059765964 1320s + date +Post FIO %H:%M:%S.%N 1320s FIO verify test with changing paths - OK 1320s Report log of background activity 1320s + echo FIO verify test with changing paths - OK 1320s + echo Report log of background activity 1320s + cat /tmp/autopkgtest.pZgNe4/tgtbasedmpaths-artifacts/test-background.log 1320s + sync 1320s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1320s + echo Final stats 1320s + iscsiadm --mode session --stats 1320s + journalctl --no-pager -u multipathd 1320s + iscsiadm --mode session 1320s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s + sleep 10s 1320s + date +MP report (expect 4) %H:%M:%S.%N 1320s MP report (expect 4) 21:06:36.695897248 1320s + multipath -ll 1320s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1320s size=100M features='0' hwhandler='0' wp=rw 1320s |-+- policy='service-time 0' prio=1 status=active 1320s | `- 1:0:0:1 sdb 8:16 active ready running 1320s |-+- policy='service-time 0' prio=1 status=enabled 1320s | `- 2:0:0:1 sdc 8:32 active ready running 1320s |-+- policy='service-time 0' prio=1 status=enabled 1320s | `- 3:0:0:1 sdd 8:48 active ready running 1320s `-+- policy='service-time 0' prio=1 status=enabled 1320s `- 4:0:0:1 sde 8:64 active ready running 1320s + date +UN-plug path 1 %H:%M:%S.%N 1320s UN-plug path 1 21:06:36.725867464 1320s + iscsiadm --mode session -r 1 -u 1320s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1320s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1320s + iscsiadm --mode session 1320s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s + sleep 10s 1320s + date +MP report (expect 3) %H:%M:%S.%N 1320s MP report (expect 3) 21:06:46.822309319 1320s + multipath -ll 1320s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1320s size=100M features='0' hwhandler='0' wp=rw 1320s |-+- policy='service-time 0' prio=1 status=active 1320s | `- 2:0:0:1 sdc 8:32 active ready running 1320s |-+- policy='service-time 0' prio=1 status=enabled 1320s | `- 3:0:0:1 sdd 8:48 active ready running 1320s `-+- policy='service-time 0' prio=1 status=enabled 1320s `- 4:0:0:1 sde 8:64 active ready running 1320s + date +UN-plug path 2 %H:%M:%S.%N 1320s UN-plug path 2 21:06:46.853017900 1320s + iscsiadm --mode session -r 2 -u 1320s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1320s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1320s + iscsiadm --mode session 1320s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s + sleep 10s 1320s + date +MP report (expect 2) %H:%M:%S.%N 1320s MP report (expect 2) 21:06:56.954733356 1320s + multipath -ll 1320s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1320s size=100M features='0' hwhandler='0' wp=rw 1320s |-+- policy='service-time 0' prio=1 status=active 1320s | `- 3:0:0:1 sdd 8:48 active ready running 1320s `-+- policy='service-time 0' prio=1 status=enabled 1320s `- 4:0:0:1 sde 8:64 active ready running 1320s + date +UN-plug path 3 %H:%M:%S.%N 1320s UN-plug path 3 21:06:56.975355828 1320s + iscsiadm --mode session -r 3 -u 1320s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1320s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1320s + iscsiadm --mode session 1320s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s + sleep 10s 1320s + date +MP report (expect 1) %H:%M:%S.%N 1320s MP report (expect 1) 21:07:07.081061864 1320s + multipath -ll 1320s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1320s size=100M features='0' hwhandler='0' wp=rw 1320s `-+- policy='service-time 0' prio=1 status=active 1320s `- 4:0:0:1 sde 8:64 active ready running 1320s + date +Add paths 5/6/7/8 %H:%M:%S.%N 1320s Add paths 5/6/7/8 21:07:07.101025175 1320s + iscsiadm --mode session -r 4 --op new 1320s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1320s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1320s + iscsiadm --mode session -r 4 --op new 1320s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1320s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1320s + iscsiadm --mode session -r 4 --op new 1320s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1320s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1320s + iscsiadm --mode session -r 4 --op new 1320s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1320s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1320s + iscsiadm --mode session 1320s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s + sleep 10s 1320s + date +MP report (expect 5) %H:%M:%S.%N 1320s MP report (expect 5) 21:07:17.254145234 1320s + multipath -ll 1320s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1320s size=100M features='0' hwhandler='0' wp=rw 1320s |-+- policy='service-time 0' prio=1 status=active 1320s | `- 4:0:0:1 sde 8:64 active ready running 1320s |-+- policy='service-time 0' prio=1 status=enabled 1320s | `- 1:0:0:1 sdb 8:16 active ready running 1320s |-+- policy='service-time 0' prio=1 status=enabled 1320s | `- 2:0:0:1 sdc 8:32 active ready running 1320s |-+- policy='service-time 0' prio=1 status=enabled 1320s | `- 3:0:0:1 sdd 8:48 active ready running 1320s `-+- policy='service-time 0' prio=1 status=enabled 1320s `- 5:0:0:1 sdf 8:80 active ready running 1320s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 1320s UN-plug multiple paths 4/7/8 21:07:17.287724528 1320s + iscsiadm --mode session -r 4 -u 1320s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1320s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1320s + iscsiadm --mode session -r 7 -u 1320s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1320s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1320s + iscsiadm --mode session -r 8 -u 1320s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1320s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1320s + iscsiadm --mode session 1320s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1320s + sleep 10s 1320s + date +Restart multipath daemon %H:%M:%S.%N 1320s Restart multipath daemon 21:07:27.616838311 1320s + systemctl restart multipathd 1320s + sleep 10s 1320s + date +Final background report (expect 2) %H:%M:%S.%N 1320s Final background report (expect 2) 21:07:37.723540797 1320s + multipath -ll 1320s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1320s size=100M features='0' hwhandler='0' wp=rw 1320s |-+- policy='service-time 0' prio=1 status=active 1320s | `- 1:0:0:1 sdb 8:16 active ready running 1320s `-+- policy='service-time 0' prio=1 status=enabled 1320s `- 2:0:0:1 sdc 8:32 active ready running 1320s Final stats 1320s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1320s iSCSI SNMP: 1320s txdata_octets: 17227512 1320s rxdata_octets: 23498109796 1320s noptx_pdus: 0 1320s scsicmd_pdus: 358639 1320s tmfcmd_pdus: 0 1320s login_pdus: 0 1320s text_pdus: 0 1320s dataout_pdus: 0 1320s logout_pdus: 0 1320s snack_pdus: 0 1320s noprx_pdus: 0 1320s scsirsp_pdus: 358639 1320s tmfrsp_pdus: 0 1320s textrsp_pdus: 0 1320s datain_pdus: 358606 1320s logoutrsp_pdus: 0 1320s r2t_pdus: 0 1320s async_pdus: 0 1320s rjt_pdus: 0 1320s digest_err: 0 1320s timeout_err: 0 1320s iSCSI Extended: 1320s tx_sendpage_failures: 0 1320s rx_discontiguous_hdr: 0 1320s eh_abort_cnt: 0 1320s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1320s iSCSI SNMP: 1320s txdata_octets: 7320 1320s rxdata_octets: 2826500 1320s noptx_pdus: 0 1320s scsicmd_pdus: 123 1320s tmfcmd_pdus: 0 1320s login_pdus: 0 1320s text_pdus: 0 1320s dataout_pdus: 0 1320s logout_pdus: 0 1320s snack_pdus: 0 1320s noprx_pdus: 0 1320s scsirsp_pdus: 123 1320s tmfrsp_pdus: 0 1320s textrsp_pdus: 0 1320s datain_pdus: 101 1320s logoutrsp_pdus: 0 1320s r2t_pdus: 0 1320s async_pdus: 0 1320s rjt_pdus: 0 1320s digest_err: 0 1320s timeout_err: 0 1320s iSCSI Extended: 1320s tx_sendpage_failures: 0 1320s rx_discontiguous_hdr: 0 1320s eh_abort_cnt: 0 1320s + echo Check final path status 1320s + multipath -ll 1320s + multipath -ll 1320s + grep --count status= 1320s Jul 29 18:09:11 adtubuntu-oracular-ppc64el-server-20240728 multipathd[296]: multipathd: shut down 1320s Jul 29 18:09:11 adtubuntu-oracular-ppc64el-server-20240728 systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1320s Jul 29 18:09:11 adtubuntu-oracular-ppc64el-server-20240728 systemd[1]: multipathd.service: Deactivated successfully. 1320s Jul 29 18:09:11 adtubuntu-oracular-ppc64el-server-20240728 systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1320s -- Boot a428bb85e534469e898d03c79107276c -- 1320s Jul 29 21:02:16 adtubuntu-oracular-ppc64el-server-20240728 systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1320s Jul 29 21:02:16 adtubuntu-oracular-ppc64el-server-20240728 multipathd[343]: multipathd v0.9.9: start up 1320s Jul 29 21:02:16 adtubuntu-oracular-ppc64el-server-20240728 multipathd[343]: reconfigure: setting up paths and maps 1320s Jul 29 21:02:16 adtubuntu-oracular-ppc64el-server-20240728 systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1320s Jul 29 21:04:52 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1320s Jul 29 21:04:52 autopkgtest multipathd[343]: multipathd: shut down 1320s Jul 29 21:04:52 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 1320s Jul 29 21:04:52 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1320s -- Boot 3c0d54539a594aaf9cbd8d423ce3f738 -- 1320s Jul 29 21:05:15 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1320s Jul 29 21:05:15 autopkgtest multipathd[336]: multipathd v0.9.9: start up 1320s Jul 29 21:05:15 autopkgtest multipathd[336]: reconfigure: setting up paths and maps 1320s Jul 29 21:05:15 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1320s Jul 29 21:06:17 autopkgtest multipathd[336]: updated bindings file /etc/multipath/bindings 1320s Jul 29 21:06:17 autopkgtest multipathd[336]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:16 1] 1320s Jul 29 21:06:17 autopkgtest multipathd[336]: sdb [8:16]: path added to devmap mpatha 1320s Jul 29 21:06:17 autopkgtest multipathd[336]: mpatha: performing delayed actions 1320s Jul 29 21:06:17 autopkgtest multipathd[336]: mpatha: reload [0 204800 multipath 0 0 4 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 service-time 0 1 1 8:64 1] 1320s Jul 29 21:06:36 autopkgtest multipathd[336]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 1320s Jul 29 21:06:36 autopkgtest multipathd[336]: check_removed_paths: sdb: freeing path in removed state 1320s Jul 29 21:06:36 autopkgtest multipathd[336]: 8:16: path removed from map mpatha 1320s Jul 29 21:06:46 autopkgtest multipathd[336]: sdc: mark as failed 1320s Jul 29 21:06:46 autopkgtest multipathd[336]: mpatha: remaining active paths: 2 1320s Jul 29 21:06:46 autopkgtest multipathd[336]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:64 1] 1320s Jul 29 21:06:46 autopkgtest multipathd[336]: check_removed_paths: sdc: freeing path in removed state 1320s Jul 29 21:06:46 autopkgtest multipathd[336]: 8:32: path removed from map mpatha 1320s Jul 29 21:06:57 autopkgtest multipathd[336]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:64 1] 1320s Jul 29 21:06:57 autopkgtest multipathd[336]: check_removed_paths: sdd: freeing path in removed state 1320s Jul 29 21:06:57 autopkgtest multipathd[336]: 8:48: path removed from map mpatha 1320s Jul 29 21:07:07 autopkgtest multipathd[336]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1] 1320s Jul 29 21:07:07 autopkgtest multipathd[336]: sdb [8:16]: path added to devmap mpatha 1320s Jul 29 21:07:07 autopkgtest multipathd[336]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:64 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 1320s Jul 29 21:07:07 autopkgtest multipathd[336]: sdc [8:32]: path added to devmap mpatha 1320s Jul 29 21:07:07 autopkgtest multipathd[336]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:64 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] 1320s Jul 29 21:07:07 autopkgtest multipathd[336]: sdd [8:48]: path added to devmap mpatha 1320s Jul 29 21:07:07 autopkgtest multipathd[336]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:64 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 service-time 0 1 1 8:80 1] 1320s Jul 29 21:07:07 autopkgtest multipathd[336]: sdf [8:80]: path added to devmap mpatha 1320s Jul 29 21:07:17 autopkgtest multipathd[336]: mpatha: reload [0 204800 multipath 0 0 4 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 service-time 0 1 1 8:80 1] 1320s Jul 29 21:07:17 autopkgtest multipathd[336]: check_removed_paths: sde: freeing path in removed state 1320s Jul 29 21:07:17 autopkgtest multipathd[336]: 8:64: path removed from map mpatha 1320s Jul 29 21:07:17 autopkgtest multipathd[336]: 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:80 1] 1320s Jul 29 21:07:17 autopkgtest multipathd[336]: check_removed_paths: sdd: freeing path in removed state 1320s Jul 29 21:07:17 autopkgtest multipathd[336]: 8:48: path removed from map mpatha 1320s Jul 29 21:07:17 autopkgtest multipathd[336]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 1320s Jul 29 21:07:17 autopkgtest multipathd[336]: check_removed_paths: sdf: freeing path in removed state 1320s Jul 29 21:07:17 autopkgtest multipathd[336]: 8:80: path removed from map mpatha 1320s Jul 29 21:07:27 autopkgtest multipathd[336]: multipathd: shut down 1320s Jul 29 21:07:27 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1320s Jul 29 21:07:27 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 1320s Jul 29 21:07:27 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1320s Jul 29 21:07:27 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1320s Jul 29 21:07:27 autopkgtest multipathd[6053]: multipathd v0.9.9: start up 1320s Jul 29 21:07:27 autopkgtest multipathd[6053]: reconfigure: setting up paths and maps 1320s Jul 29 21:07:27 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1320s Check final path status 1320s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1320s size=100M features='0' hwhandler='0' wp=rw 1320s |-+- policy='service-time 0' prio=1 status=active 1320s | `- 1:0:0:1 sdb 8:16 active ready running 1320s `-+- policy='service-time 0' prio=1 status=enabled 1320s `- 2:0:0:1 sdc 8:32 active ready running 1320s + diskc=2 1320s + multipath -ll 1320s + grep --count status=active 1320s + diska=1 1320s + multipath -ll 1320s + grep --count status=enabled 1320s OK 1320s + diske=1 1320s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 1320s + echo OK 1320s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 1320s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1320s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1320s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1320s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1320s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 1320s autopkgtest [21:09:27]: test tgtbasedmpaths: -----------------------] 1321s autopkgtest [21:09:28]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 1321s tgtbasedmpaths PASS 1324s autopkgtest [21:09:31]: @@@@@@@@@@@@@@@@@@@@ summary 1324s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 1324s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 1324s kpartx-file-loopback PASS 1324s tgtbasedmpaths PASS 1336s nova [W] Using flock in scalingstack-bos01-ppc64el 1336s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240729-204727-juju-7f2275-prod-proposed-migration-environment-2-c4e89d95-e386-4b4f-8070-a18e389e33b5 from image adt/ubuntu-oracular-ppc64el-server-20240729.img (UUID 3d203724-7e4a-41ec-8381-eb71d979ad49)... 1336s nova [W] Using flock in scalingstack-bos01-ppc64el 1336s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240729-204727-juju-7f2275-prod-proposed-migration-environment-2-c4e89d95-e386-4b4f-8070-a18e389e33b5 from image adt/ubuntu-oracular-ppc64el-server-20240729.img (UUID 3d203724-7e4a-41ec-8381-eb71d979ad49)...