0s autopkgtest [08:42:27]: starting date and time: 2024-08-17 08:42:27+0000 0s autopkgtest [08:42:27]: git checkout: fd3bed09 nova: allow more retries for quota issues 0s autopkgtest [08:42:27]: host juju-7f2275-prod-proposed-migration-environment-3; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.69smxmzz/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:util-linux,src:autopkgtest,src:dracut,src:netavark --apt-upgrade multipath-tools --timeout-short=300 --timeout-copy=20000 --timeout-test=20000 --timeout-build=20000 '--env=ADT_TEST_TRIGGERS=util-linux/2.40.2-1ubuntu1 autopkgtest/5.38ubuntu1 dracut/103-1ubuntu1 netavark/1.9.0-4' -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-big-ppc64el --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-3@bos03-ppc64el-2.secgroup --name adt-oracular-ppc64el-multipath-tools-20240817-084217-juju-7f2275-prod-proposed-migration-environment-3-83d83c4d-6e0a-4796-83a0-5527afd8e190 --image adt/ubuntu-oracular-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-3 --net-id=net_prod-proposed-migration-ppc64el -e TERM=linux -e ''"'"'http_proxy=http://squid.internal:3128'"'"'' -e ''"'"'https_proxy=http://squid.internal:3128'"'"'' -e ''"'"'no_proxy=127.0.0.1,127.0.1.1,login.ubuntu.com,localhost,localdomain,novalocal,internal,archive.ubuntu.com,ports.ubuntu.com,security.ubuntu.com,ddebs.ubuntu.com,changelogs.ubuntu.com,keyserver.ubuntu.com,launchpadlibrarian.net,launchpadcontent.net,launchpad.net,10.24.0.0/24,keystone.ps5.canonical.com,objectstorage.prodstack5.canonical.com'"'"'' --mirror=http://ftpmaster.internal/ubuntu/ 652s autopkgtest [08:53:19]: testbed dpkg architecture: ppc64el 652s autopkgtest [08:53:19]: testbed apt version: 2.9.7 652s autopkgtest [08:53:19]: @@@@@@@@@@@@@@@@@@@@ test bed setup 657s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 657s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [10.4 kB] 658s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [67.9 kB] 658s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [808 kB] 659s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8452 B] 659s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [103 kB] 659s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [3992 B] 659s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1692 B] 659s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 659s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [768 kB] 661s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [20.0 kB] 661s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [5620 B] 661s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [372 B] 665s Fetched 1924 kB in 4s (496 kB/s) 665s Reading package lists... 668s Reading package lists... 668s Building dependency tree... 668s Reading state information... 668s Calculating upgrade... 668s The following packages will be upgraded: 668s apt apt-utils bsdextrautils bsdutils dracut-install eject fdisk 668s libapt-pkg6.0t64 libblkid1 libfdisk1 libmount1 libsmartcols1 libuuid1 mount 668s python3-yaml util-linux uuid-runtime 668s 17 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 668s Need to get 5415 kB of archives. 668s After this operation, 243 kB disk space will be freed. 668s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el bsdutils ppc64el 1:2.40.2-1ubuntu1 [104 kB] 669s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libblkid1 ppc64el 2.40.2-1ubuntu1 [159 kB] 669s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libmount1 ppc64el 2.40.2-1ubuntu1 [188 kB] 669s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsmartcols1 ppc64el 2.40.2-1ubuntu1 [107 kB] 669s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libuuid1 ppc64el 2.40.2-1ubuntu1 [43.6 kB] 669s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el util-linux ppc64el 2.40.2-1ubuntu1 [1181 kB] 671s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el libapt-pkg6.0t64 ppc64el 2.9.8 [1113 kB] 672s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el apt ppc64el 2.9.8 [1434 kB] 674s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el apt-utils ppc64el 2.9.8 [229 kB] 675s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el mount ppc64el 2.40.2-1ubuntu1 [145 kB] 675s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el uuid-runtime ppc64el 2.40.2-1ubuntu1 [53.1 kB] 675s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el eject ppc64el 2.40.2-1ubuntu1 [46.1 kB] 675s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libfdisk1 ppc64el 2.40.2-1ubuntu1 [187 kB] 675s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-yaml ppc64el 6.0.2-1 [140 kB] 676s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el bsdextrautils ppc64el 2.40.2-1ubuntu1 [98.0 kB] 676s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dracut-install ppc64el 103-1ubuntu1 [37.2 kB] 676s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el fdisk ppc64el 2.40.2-1ubuntu1 [151 kB] 676s Fetched 5415 kB in 8s (697 kB/s) 677s (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 ... 72521 files and directories currently installed.) 677s Preparing to unpack .../bsdutils_1%3a2.40.2-1ubuntu1_ppc64el.deb ... 677s Unpacking bsdutils (1:2.40.2-1ubuntu1) over (1:2.39.3-9ubuntu6) ... 677s Setting up bsdutils (1:2.40.2-1ubuntu1) ... 677s (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 ... 72522 files and directories currently installed.) 677s Preparing to unpack .../libblkid1_2.40.2-1ubuntu1_ppc64el.deb ... 677s Unpacking libblkid1:ppc64el (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 677s Setting up libblkid1:ppc64el (2.40.2-1ubuntu1) ... 677s (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 ... 72523 files and directories currently installed.) 677s Preparing to unpack .../libmount1_2.40.2-1ubuntu1_ppc64el.deb ... 677s Unpacking libmount1:ppc64el (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 677s Setting up libmount1:ppc64el (2.40.2-1ubuntu1) ... 677s (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 ... 72524 files and directories currently installed.) 677s Preparing to unpack .../libsmartcols1_2.40.2-1ubuntu1_ppc64el.deb ... 677s Unpacking libsmartcols1:ppc64el (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 677s Setting up libsmartcols1:ppc64el (2.40.2-1ubuntu1) ... 677s (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 ... 72525 files and directories currently installed.) 677s Preparing to unpack .../libuuid1_2.40.2-1ubuntu1_ppc64el.deb ... 677s Unpacking libuuid1:ppc64el (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 677s Setting up libuuid1:ppc64el (2.40.2-1ubuntu1) ... 677s (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 ... 72526 files and directories currently installed.) 677s Preparing to unpack .../util-linux_2.40.2-1ubuntu1_ppc64el.deb ... 677s Unpacking util-linux (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 677s Setting up util-linux (2.40.2-1ubuntu1) ... 678s fstrim.service is a disabled or a static unit not running, not starting it. 678s (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 ... 72497 files and directories currently installed.) 678s Preparing to unpack .../libapt-pkg6.0t64_2.9.8_ppc64el.deb ... 678s Unpacking libapt-pkg6.0t64:ppc64el (2.9.8) over (2.9.7) ... 678s Setting up libapt-pkg6.0t64:ppc64el (2.9.8) ... 678s (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 ... 72497 files and directories currently installed.) 678s Preparing to unpack .../archives/apt_2.9.8_ppc64el.deb ... 678s Unpacking apt (2.9.8) over (2.9.7) ... 678s Setting up apt (2.9.8) ... 679s (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 ... 72497 files and directories currently installed.) 679s Preparing to unpack .../0-apt-utils_2.9.8_ppc64el.deb ... 679s Unpacking apt-utils (2.9.8) over (2.9.7) ... 679s Preparing to unpack .../1-mount_2.40.2-1ubuntu1_ppc64el.deb ... 679s Unpacking mount (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 679s Preparing to unpack .../2-uuid-runtime_2.40.2-1ubuntu1_ppc64el.deb ... 679s Unpacking uuid-runtime (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 679s Preparing to unpack .../3-eject_2.40.2-1ubuntu1_ppc64el.deb ... 679s Unpacking eject (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 679s Preparing to unpack .../4-libfdisk1_2.40.2-1ubuntu1_ppc64el.deb ... 679s Unpacking libfdisk1:ppc64el (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 679s Preparing to unpack .../5-python3-yaml_6.0.2-1_ppc64el.deb ... 679s Unpacking python3-yaml (6.0.2-1) over (6.0.1-2build2) ... 679s Preparing to unpack .../6-bsdextrautils_2.40.2-1ubuntu1_ppc64el.deb ... 679s Unpacking bsdextrautils (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 679s Preparing to unpack .../7-dracut-install_103-1ubuntu1_ppc64el.deb ... 679s Unpacking dracut-install (103-1ubuntu1) over (102-3ubuntu4) ... 679s Preparing to unpack .../8-fdisk_2.40.2-1ubuntu1_ppc64el.deb ... 679s Unpacking fdisk (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 679s Setting up apt-utils (2.9.8) ... 679s Setting up bsdextrautils (2.40.2-1ubuntu1) ... 679s Setting up python3-yaml (6.0.2-1) ... 679s Setting up eject (2.40.2-1ubuntu1) ... 679s Setting up libfdisk1:ppc64el (2.40.2-1ubuntu1) ... 679s Setting up dracut-install (103-1ubuntu1) ... 679s Setting up mount (2.40.2-1ubuntu1) ... 679s Setting up uuid-runtime (2.40.2-1ubuntu1) ... 679s Installing new version of config file /etc/init.d/uuidd ... 680s uuidd.service is a disabled or a static unit not running, not starting it. 680s Setting up fdisk (2.40.2-1ubuntu1) ... 680s Processing triggers for man-db (2.12.1-3) ... 682s Processing triggers for libc-bin (2.39-0ubuntu9) ... 684s Reading package lists... 684s Building dependency tree... 684s Reading state information... 684s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 685s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 685s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 685s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 685s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 686s Reading package lists... 686s Reading package lists... 686s Building dependency tree... 686s Reading state information... 686s Calculating upgrade... 686s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 686s Reading package lists... 686s Building dependency tree... 686s Reading state information... 687s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 687s autopkgtest [08:53:54]: rebooting testbed after setup commands that affected boot 723s autopkgtest [08:54:30]: testbed running kernel: Linux 6.8.0-31-generic #31-Ubuntu SMP Sat Apr 20 00:05:55 UTC 2024 726s autopkgtest [08:54:33]: @@@@@@@@@@@@@@@@@@@@ apt-source multipath-tools 731s Get:1 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu2 (dsc) [2772 B] 731s Get:2 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu2 (tar) [588 kB] 731s Get:3 http://ftpmaster.internal/ubuntu oracular/main multipath-tools 0.9.9-1ubuntu2 (diff) [42.4 kB] 731s gpgv: Signature made Tue Jul 23 21:24:22 2024 UTC 731s gpgv: using RSA key D09F8A854F1055BCFC482C4B23566B906047AFC8 731s gpgv: Can't check signature: No public key 731s dpkg-source: warning: cannot verify inline signature for ./multipath-tools_0.9.9-1ubuntu2.dsc: no acceptable signature found 731s autopkgtest [08:54:38]: testing package multipath-tools version 0.9.9-1ubuntu2 732s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 732s autopkgtest [08:54:39]: build not needed 733s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 733s autopkgtest [08:54:40]: test kpartx-file-loopback: preparing testbed 734s Reading package lists... 734s Building dependency tree... 734s Reading state information... 734s Starting pkgProblemResolver with broken count: 0 734s Starting 2 pkgProblemResolver with broken count: 0 734s Done 735s The following additional packages will be installed: 735s liburing2 qemu-utils 735s Recommended packages: 735s qemu-block-extra 735s The following NEW packages will be installed: 735s autopkgtest-satdep liburing2 qemu-utils 735s 0 upgraded, 3 newly installed, 0 to remove and 0 not upgraded. 735s Need to get 2330 kB/2331 kB of archives. 735s After this operation, 15.4 MB of additional disk space will be used. 735s Get:1 /tmp/autopkgtest.jpNmps/1-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [720 B] 735s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el liburing2 ppc64el 2.6-1 [26.9 kB] 735s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el qemu-utils ppc64el 1:8.2.2+ds-0ubuntu1 [2303 kB] 738s Fetched 2330 kB in 3s (886 kB/s) 738s Selecting previously unselected package liburing2:ppc64el. 738s (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 ... 72504 files and directories currently installed.) 738s Preparing to unpack .../liburing2_2.6-1_ppc64el.deb ... 738s Unpacking liburing2:ppc64el (2.6-1) ... 738s Selecting previously unselected package qemu-utils. 738s Preparing to unpack .../qemu-utils_1%3a8.2.2+ds-0ubuntu1_ppc64el.deb ... 738s Unpacking qemu-utils (1:8.2.2+ds-0ubuntu1) ... 738s Selecting previously unselected package autopkgtest-satdep. 738s Preparing to unpack .../1-autopkgtest-satdep.deb ... 738s Unpacking autopkgtest-satdep (0) ... 738s Setting up liburing2:ppc64el (2.6-1) ... 738s Setting up qemu-utils (1:8.2.2+ds-0ubuntu1) ... 738s Setting up autopkgtest-satdep (0) ... 738s Processing triggers for man-db (2.12.1-3) ... 740s Processing triggers for libc-bin (2.39-0ubuntu9) ... 743s (Reading database ... 72524 files and directories currently installed.) 743s Removing autopkgtest-satdep (0) ... 744s autopkgtest [08:54:51]: test kpartx-file-loopback: [----------------------- 744s Formatting 'foo.img', fmt=raw size=20971520 745s Creating new GPT entries in memory. 745s Warning: The kernel is still using the old partition table. 745s The new table will be used at the next reboot or after you 745s run partprobe(8) or kpartx(8) 745s The operation has completed successfully. 745s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 745s standard_filename: OK 745s del devmap : loop0p1 745s No devices found 745s standard_filename_cleanup: OK 745s Formatting 'fou du FaFa.img', fmt=raw size=20971520 746s Creating new GPT entries in memory. 746s Warning: The kernel is still using the old partition table. 746s The new table will be used at the next reboot or after you 746s run partprobe(8) or kpartx(8) 746s The operation has completed successfully. 746s add map loop0p1 (252:0): 0 38879 linear 7:0 2048 746s filename_with_spaces: OK 746s del devmap : loop0p1 746s No devices found 746s filename_with_spaces_cleanup: OK 747s autopkgtest [08:54:54]: test kpartx-file-loopback: -----------------------] 747s autopkgtest [08:54:54]: test kpartx-file-loopback: - - - - - - - - - - results - - - - - - - - - - 747s kpartx-file-loopback PASS 748s autopkgtest [08:54:55]: test tgtbasedmpaths: preparing testbed 916s autopkgtest [08:57:43]: testbed dpkg architecture: ppc64el 916s autopkgtest [08:57:43]: testbed apt version: 2.9.7 916s autopkgtest [08:57:43]: @@@@@@@@@@@@@@@@@@@@ test bed setup 917s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease [126 kB] 917s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main Sources [67.9 kB] 918s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/universe Sources [808 kB] 918s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/restricted Sources [8452 B] 918s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse Sources [10.4 kB] 918s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el Packages [103 kB] 918s Get:7 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el c-n-f Metadata [3992 B] 918s Get:8 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el Packages [1692 B] 918s Get:9 http://ftpmaster.internal/ubuntu oracular-proposed/restricted ppc64el c-n-f Metadata [120 B] 918s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el Packages [768 kB] 918s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/universe ppc64el c-n-f Metadata [20.0 kB] 918s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el Packages [5620 B] 918s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/multiverse ppc64el c-n-f Metadata [372 B] 922s Fetched 1924 kB in 1s (1768 kB/s) 922s Reading package lists... 924s Reading package lists... 924s Building dependency tree... 924s Reading state information... 925s Calculating upgrade... 925s The following packages will be upgraded: 925s apt apt-utils bsdextrautils bsdutils dracut-install eject fdisk 925s libapt-pkg6.0t64 libblkid1 libfdisk1 libmount1 libsmartcols1 libuuid1 mount 925s python3-yaml util-linux uuid-runtime 925s 17 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 925s Need to get 5415 kB of archives. 925s After this operation, 243 kB disk space will be freed. 925s Get:1 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el bsdutils ppc64el 1:2.40.2-1ubuntu1 [104 kB] 925s Get:2 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libblkid1 ppc64el 2.40.2-1ubuntu1 [159 kB] 926s Get:3 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libmount1 ppc64el 2.40.2-1ubuntu1 [188 kB] 926s Get:4 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libsmartcols1 ppc64el 2.40.2-1ubuntu1 [107 kB] 926s Get:5 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libuuid1 ppc64el 2.40.2-1ubuntu1 [43.6 kB] 926s Get:6 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el util-linux ppc64el 2.40.2-1ubuntu1 [1181 kB] 926s Get:7 http://ftpmaster.internal/ubuntu oracular/main ppc64el libapt-pkg6.0t64 ppc64el 2.9.8 [1113 kB] 926s Get:8 http://ftpmaster.internal/ubuntu oracular/main ppc64el apt ppc64el 2.9.8 [1434 kB] 926s Get:9 http://ftpmaster.internal/ubuntu oracular/main ppc64el apt-utils ppc64el 2.9.8 [229 kB] 926s Get:10 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el mount ppc64el 2.40.2-1ubuntu1 [145 kB] 926s Get:11 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el uuid-runtime ppc64el 2.40.2-1ubuntu1 [53.1 kB] 926s Get:12 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el eject ppc64el 2.40.2-1ubuntu1 [46.1 kB] 926s Get:13 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el libfdisk1 ppc64el 2.40.2-1ubuntu1 [187 kB] 926s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el python3-yaml ppc64el 6.0.2-1 [140 kB] 926s Get:15 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el bsdextrautils ppc64el 2.40.2-1ubuntu1 [98.0 kB] 926s Get:16 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el dracut-install ppc64el 103-1ubuntu1 [37.2 kB] 926s Get:17 http://ftpmaster.internal/ubuntu oracular-proposed/main ppc64el fdisk ppc64el 2.40.2-1ubuntu1 [151 kB] 926s Fetched 5415 kB in 1s (5884 kB/s) 927s (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 ... 72521 files and directories currently installed.) 927s Preparing to unpack .../bsdutils_1%3a2.40.2-1ubuntu1_ppc64el.deb ... 927s Unpacking bsdutils (1:2.40.2-1ubuntu1) over (1:2.39.3-9ubuntu6) ... 927s Setting up bsdutils (1:2.40.2-1ubuntu1) ... 927s (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 ... 72522 files and directories currently installed.) 927s Preparing to unpack .../libblkid1_2.40.2-1ubuntu1_ppc64el.deb ... 927s Unpacking libblkid1:ppc64el (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 927s Setting up libblkid1:ppc64el (2.40.2-1ubuntu1) ... 927s (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 ... 72523 files and directories currently installed.) 927s Preparing to unpack .../libmount1_2.40.2-1ubuntu1_ppc64el.deb ... 927s Unpacking libmount1:ppc64el (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 927s Setting up libmount1:ppc64el (2.40.2-1ubuntu1) ... 927s (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 ... 72524 files and directories currently installed.) 927s Preparing to unpack .../libsmartcols1_2.40.2-1ubuntu1_ppc64el.deb ... 927s Unpacking libsmartcols1:ppc64el (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 927s Setting up libsmartcols1:ppc64el (2.40.2-1ubuntu1) ... 927s (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 ... 72525 files and directories currently installed.) 927s Preparing to unpack .../libuuid1_2.40.2-1ubuntu1_ppc64el.deb ... 927s Unpacking libuuid1:ppc64el (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 927s Setting up libuuid1:ppc64el (2.40.2-1ubuntu1) ... 927s (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 ... 72526 files and directories currently installed.) 927s Preparing to unpack .../util-linux_2.40.2-1ubuntu1_ppc64el.deb ... 927s Unpacking util-linux (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 927s Setting up util-linux (2.40.2-1ubuntu1) ... 928s fstrim.service is a disabled or a static unit not running, not starting it. 928s (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 ... 72497 files and directories currently installed.) 928s Preparing to unpack .../libapt-pkg6.0t64_2.9.8_ppc64el.deb ... 928s Unpacking libapt-pkg6.0t64:ppc64el (2.9.8) over (2.9.7) ... 928s Setting up libapt-pkg6.0t64:ppc64el (2.9.8) ... 928s (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 ... 72497 files and directories currently installed.) 928s Preparing to unpack .../archives/apt_2.9.8_ppc64el.deb ... 928s Unpacking apt (2.9.8) over (2.9.7) ... 928s Setting up apt (2.9.8) ... 929s (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 ... 72497 files and directories currently installed.) 929s Preparing to unpack .../0-apt-utils_2.9.8_ppc64el.deb ... 929s Unpacking apt-utils (2.9.8) over (2.9.7) ... 929s Preparing to unpack .../1-mount_2.40.2-1ubuntu1_ppc64el.deb ... 929s Unpacking mount (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 929s Preparing to unpack .../2-uuid-runtime_2.40.2-1ubuntu1_ppc64el.deb ... 929s Unpacking uuid-runtime (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 929s Preparing to unpack .../3-eject_2.40.2-1ubuntu1_ppc64el.deb ... 929s Unpacking eject (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 929s Preparing to unpack .../4-libfdisk1_2.40.2-1ubuntu1_ppc64el.deb ... 929s Unpacking libfdisk1:ppc64el (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 929s Preparing to unpack .../5-python3-yaml_6.0.2-1_ppc64el.deb ... 929s Unpacking python3-yaml (6.0.2-1) over (6.0.1-2build2) ... 929s Preparing to unpack .../6-bsdextrautils_2.40.2-1ubuntu1_ppc64el.deb ... 929s Unpacking bsdextrautils (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 929s Preparing to unpack .../7-dracut-install_103-1ubuntu1_ppc64el.deb ... 929s Unpacking dracut-install (103-1ubuntu1) over (102-3ubuntu4) ... 929s Preparing to unpack .../8-fdisk_2.40.2-1ubuntu1_ppc64el.deb ... 929s Unpacking fdisk (2.40.2-1ubuntu1) over (2.39.3-9ubuntu6) ... 929s Setting up apt-utils (2.9.8) ... 929s Setting up bsdextrautils (2.40.2-1ubuntu1) ... 929s Setting up python3-yaml (6.0.2-1) ... 929s Setting up eject (2.40.2-1ubuntu1) ... 929s Setting up libfdisk1:ppc64el (2.40.2-1ubuntu1) ... 929s Setting up dracut-install (103-1ubuntu1) ... 929s Setting up mount (2.40.2-1ubuntu1) ... 929s Setting up uuid-runtime (2.40.2-1ubuntu1) ... 929s Installing new version of config file /etc/init.d/uuidd ... 930s uuidd.service is a disabled or a static unit not running, not starting it. 930s Setting up fdisk (2.40.2-1ubuntu1) ... 930s Processing triggers for man-db (2.12.1-3) ... 932s Processing triggers for libc-bin (2.39-0ubuntu9) ... 933s Reading package lists... 934s Building dependency tree... 934s Reading state information... 934s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 934s Hit:1 http://ftpmaster.internal/ubuntu oracular-proposed InRelease 934s Hit:2 http://ftpmaster.internal/ubuntu oracular InRelease 934s Hit:3 http://ftpmaster.internal/ubuntu oracular-updates InRelease 935s Hit:4 http://ftpmaster.internal/ubuntu oracular-security InRelease 936s Reading package lists... 936s Reading package lists... 936s Building dependency tree... 936s Reading state information... 936s Calculating upgrade... 936s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 936s Reading package lists... 937s Building dependency tree... 937s Reading state information... 937s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 937s autopkgtest [08:58:04]: rebooting testbed after setup commands that affected boot 971s autopkgtest-virt-ssh: WARNING: ssh connection failed. Retrying in 3 seconds... 982s Reading package lists... 983s Building dependency tree... 983s Reading state information... 983s Starting pkgProblemResolver with broken count: 0 983s Starting 2 pkgProblemResolver with broken count: 0 983s Done 983s The following additional packages will be installed: 983s fio libboost-iostreams1.83.0 libboost-thread1.83.0 libconfig-general-perl 983s libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 libglusterfs0 libisns0t64 libnbd0 983s libndctl6 libopeniscsiusr libpmem1 libpmemobj1 librados2 librbd1 983s librdmacm1t64 lsscsi open-iscsi tgt 983s Suggested packages: 983s fio-examples gnuplot tgt-glusterfs tgt-rbd 983s Recommended packages: 983s finalrd 983s The following NEW packages will be installed: 983s autopkgtest-satdep fio libboost-iostreams1.83.0 libboost-thread1.83.0 983s libconfig-general-perl libdaxctl1 libgfapi0 libgfrpc0 libgfxdr0 983s libglusterfs0 libisns0t64 libnbd0 libndctl6 libopeniscsiusr libpmem1 983s libpmemobj1 librados2 librbd1 librdmacm1t64 lsscsi open-iscsi tgt 983s 0 upgraded, 22 newly installed, 0 to remove and 0 not upgraded. 983s Need to get 10.9 MB/10.9 MB of archives. 983s After this operation, 49.6 MB of additional disk space will be used. 983s Get:1 /tmp/autopkgtest.jpNmps/2-autopkgtest-satdep.deb autopkgtest-satdep ppc64el 0 [732 B] 983s Get:2 http://ftpmaster.internal/ubuntu oracular/main ppc64el libopeniscsiusr ppc64el 2.1.10-1ubuntu1 [54.9 kB] 984s Get:3 http://ftpmaster.internal/ubuntu oracular/main ppc64el libisns0t64 ppc64el 0.101-1 [117 kB] 984s Get:4 http://ftpmaster.internal/ubuntu oracular/main ppc64el open-iscsi ppc64el 2.1.10-1ubuntu1 [385 kB] 985s Get:5 http://ftpmaster.internal/ubuntu oracular/main ppc64el librdmacm1t64 ppc64el 52.0-2 [80.5 kB] 985s Get:6 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libconfig-general-perl all 2.65-2 [57.1 kB] 985s Get:7 http://ftpmaster.internal/ubuntu oracular/universe ppc64el tgt ppc64el 1:1.0.85-1.2ubuntu1 [254 kB] 985s Get:8 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfxdr0 ppc64el 11.1-5ubuntu1 [21.7 kB] 985s Get:9 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libglusterfs0 ppc64el 11.1-5ubuntu1 [308 kB] 985s Get:10 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfrpc0 ppc64el 11.1-5ubuntu1 [46.3 kB] 985s Get:11 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libgfapi0 ppc64el 11.1-5ubuntu1 [99.1 kB] 985s Get:12 http://ftpmaster.internal/ubuntu oracular/universe ppc64el libnbd0 ppc64el 1.20.2-2 [98.5 kB] 985s Get:13 http://ftpmaster.internal/ubuntu oracular/main ppc64el libdaxctl1 ppc64el 77-2.2ubuntu1 [23.7 kB] 985s Get:14 http://ftpmaster.internal/ubuntu oracular/main ppc64el libndctl6 ppc64el 77-2.2ubuntu1 [73.4 kB] 985s Get:15 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmem1 ppc64el 1.13.1-1.1ubuntu2 [41.1 kB] 985s Get:16 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-iostreams1.83.0 ppc64el 1.83.0-3.1ubuntu1 [259 kB] 985s Get:17 http://ftpmaster.internal/ubuntu oracular/main ppc64el libboost-thread1.83.0 ppc64el 1.83.0-3.1ubuntu1 [281 kB] 985s Get:18 http://ftpmaster.internal/ubuntu oracular/main ppc64el librados2 ppc64el 19.2.0~is.really.19.1.0-0ubuntu2 [4151 kB] 985s Get:19 http://ftpmaster.internal/ubuntu oracular/main ppc64el libpmemobj1 ppc64el 1.13.1-1.1ubuntu2 [143 kB] 985s Get:20 http://ftpmaster.internal/ubuntu oracular/main ppc64el librbd1 ppc64el 19.2.0~is.really.19.1.0-0ubuntu2 [3684 kB] 985s Get:21 http://ftpmaster.internal/ubuntu oracular/universe ppc64el fio ppc64el 3.37-1 [716 kB] 985s Get:22 http://ftpmaster.internal/ubuntu oracular/main ppc64el lsscsi ppc64el 0.32-1build1 [54.0 kB] 986s Preconfiguring packages ... 986s Fetched 10.9 MB in 2s (5971 kB/s) 986s Selecting previously unselected package libopeniscsiusr. 986s (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 ... 72504 files and directories currently installed.) 986s Preparing to unpack .../00-libopeniscsiusr_2.1.10-1ubuntu1_ppc64el.deb ... 986s Unpacking libopeniscsiusr (2.1.10-1ubuntu1) ... 986s Selecting previously unselected package libisns0t64:ppc64el. 986s Preparing to unpack .../01-libisns0t64_0.101-1_ppc64el.deb ... 986s Unpacking libisns0t64:ppc64el (0.101-1) ... 986s Selecting previously unselected package open-iscsi. 986s Preparing to unpack .../02-open-iscsi_2.1.10-1ubuntu1_ppc64el.deb ... 986s Unpacking open-iscsi (2.1.10-1ubuntu1) ... 986s Selecting previously unselected package librdmacm1t64:ppc64el. 986s Preparing to unpack .../03-librdmacm1t64_52.0-2_ppc64el.deb ... 986s Unpacking librdmacm1t64:ppc64el (52.0-2) ... 986s Selecting previously unselected package libconfig-general-perl. 986s Preparing to unpack .../04-libconfig-general-perl_2.65-2_all.deb ... 986s Unpacking libconfig-general-perl (2.65-2) ... 986s Selecting previously unselected package tgt. 986s Preparing to unpack .../05-tgt_1%3a1.0.85-1.2ubuntu1_ppc64el.deb ... 986s Unpacking tgt (1:1.0.85-1.2ubuntu1) ... 986s Selecting previously unselected package libgfxdr0:ppc64el. 986s Preparing to unpack .../06-libgfxdr0_11.1-5ubuntu1_ppc64el.deb ... 986s Unpacking libgfxdr0:ppc64el (11.1-5ubuntu1) ... 986s Selecting previously unselected package libglusterfs0:ppc64el. 986s Preparing to unpack .../07-libglusterfs0_11.1-5ubuntu1_ppc64el.deb ... 986s Unpacking libglusterfs0:ppc64el (11.1-5ubuntu1) ... 986s Selecting previously unselected package libgfrpc0:ppc64el. 986s Preparing to unpack .../08-libgfrpc0_11.1-5ubuntu1_ppc64el.deb ... 986s Unpacking libgfrpc0:ppc64el (11.1-5ubuntu1) ... 986s Selecting previously unselected package libgfapi0:ppc64el. 986s Preparing to unpack .../09-libgfapi0_11.1-5ubuntu1_ppc64el.deb ... 986s Unpacking libgfapi0:ppc64el (11.1-5ubuntu1) ... 986s Selecting previously unselected package libnbd0. 986s Preparing to unpack .../10-libnbd0_1.20.2-2_ppc64el.deb ... 986s Unpacking libnbd0 (1.20.2-2) ... 986s Selecting previously unselected package libdaxctl1:ppc64el. 986s Preparing to unpack .../11-libdaxctl1_77-2.2ubuntu1_ppc64el.deb ... 986s Unpacking libdaxctl1:ppc64el (77-2.2ubuntu1) ... 986s Selecting previously unselected package libndctl6:ppc64el. 986s Preparing to unpack .../12-libndctl6_77-2.2ubuntu1_ppc64el.deb ... 986s Unpacking libndctl6:ppc64el (77-2.2ubuntu1) ... 986s Selecting previously unselected package libpmem1:ppc64el. 986s Preparing to unpack .../13-libpmem1_1.13.1-1.1ubuntu2_ppc64el.deb ... 986s Unpacking libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 986s Selecting previously unselected package libboost-iostreams1.83.0:ppc64el. 986s Preparing to unpack .../14-libboost-iostreams1.83.0_1.83.0-3.1ubuntu1_ppc64el.deb ... 986s Unpacking libboost-iostreams1.83.0:ppc64el (1.83.0-3.1ubuntu1) ... 986s Selecting previously unselected package libboost-thread1.83.0:ppc64el. 986s Preparing to unpack .../15-libboost-thread1.83.0_1.83.0-3.1ubuntu1_ppc64el.deb ... 986s Unpacking libboost-thread1.83.0:ppc64el (1.83.0-3.1ubuntu1) ... 986s Selecting previously unselected package librados2. 986s Preparing to unpack .../16-librados2_19.2.0~is.really.19.1.0-0ubuntu2_ppc64el.deb ... 986s Unpacking librados2 (19.2.0~is.really.19.1.0-0ubuntu2) ... 986s Selecting previously unselected package libpmemobj1:ppc64el. 986s Preparing to unpack .../17-libpmemobj1_1.13.1-1.1ubuntu2_ppc64el.deb ... 986s Unpacking libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 986s Selecting previously unselected package librbd1. 986s Preparing to unpack .../18-librbd1_19.2.0~is.really.19.1.0-0ubuntu2_ppc64el.deb ... 986s Unpacking librbd1 (19.2.0~is.really.19.1.0-0ubuntu2) ... 987s Selecting previously unselected package fio. 987s Preparing to unpack .../19-fio_3.37-1_ppc64el.deb ... 987s Unpacking fio (3.37-1) ... 987s Selecting previously unselected package lsscsi. 987s Preparing to unpack .../20-lsscsi_0.32-1build1_ppc64el.deb ... 987s Unpacking lsscsi (0.32-1build1) ... 987s Selecting previously unselected package autopkgtest-satdep. 987s Preparing to unpack .../21-2-autopkgtest-satdep.deb ... 987s Unpacking autopkgtest-satdep (0) ... 987s Setting up libconfig-general-perl (2.65-2) ... 987s Setting up libisns0t64:ppc64el (0.101-1) ... 987s Setting up libboost-thread1.83.0:ppc64el (1.83.0-3.1ubuntu1) ... 987s Setting up libnbd0 (1.20.2-2) ... 987s Setting up libopeniscsiusr (2.1.10-1ubuntu1) ... 987s Setting up libglusterfs0:ppc64el (11.1-5ubuntu1) ... 987s Setting up libboost-iostreams1.83.0:ppc64el (1.83.0-3.1ubuntu1) ... 987s Setting up lsscsi (0.32-1build1) ... 987s Setting up libdaxctl1:ppc64el (77-2.2ubuntu1) ... 987s Setting up libndctl6:ppc64el (77-2.2ubuntu1) ... 987s Setting up librdmacm1t64:ppc64el (52.0-2) ... 987s Setting up tgt (1:1.0.85-1.2ubuntu1) ... 987s Created symlink '/etc/systemd/system/multi-user.target.wants/tgt.service' → '/usr/lib/systemd/system/tgt.service'. 988s Setting up libpmem1:ppc64el (1.13.1-1.1ubuntu2) ... 988s Setting up libgfxdr0:ppc64el (11.1-5ubuntu1) ... 988s Setting up librados2 (19.2.0~is.really.19.1.0-0ubuntu2) ... 988s Setting up open-iscsi (2.1.10-1ubuntu1) ... 988s Created symlink '/etc/systemd/system/sockets.target.wants/iscsid.socket' → '/usr/lib/systemd/system/iscsid.socket'. 989s Created symlink '/etc/systemd/system/iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 989s Created symlink '/etc/systemd/system/sysinit.target.wants/open-iscsi.service' → '/usr/lib/systemd/system/open-iscsi.service'. 989s Setting up libpmemobj1:ppc64el (1.13.1-1.1ubuntu2) ... 989s Setting up librbd1 (19.2.0~is.really.19.1.0-0ubuntu2) ... 989s Setting up libgfrpc0:ppc64el (11.1-5ubuntu1) ... 989s Setting up libgfapi0:ppc64el (11.1-5ubuntu1) ... 989s Setting up fio (3.37-1) ... 990s Setting up autopkgtest-satdep (0) ... 990s Processing triggers for man-db (2.12.1-3) ... 991s Processing triggers for initramfs-tools (0.142ubuntu32) ... 991s update-initramfs: Generating /boot/initrd.img-6.8.0-31-generic 991s W: No lz4 in /usr/bin:/sbin:/bin, using gzip 999s Processing triggers for libc-bin (2.39-0ubuntu9) ... 1003s (Reading database ... 72745 files and directories currently installed.) 1003s Removing autopkgtest-satdep (0) ... 1005s autopkgtest [08:59:12]: test tgtbasedmpaths: [----------------------- 1006s + targetname=iqn.2016-11.foo.com:target.iscsi 1006s + pwd 1006s + cwd=/tmp/autopkgtest.jpNmps/build.aIe/src 1006s + testdir=/mnt/tgtmpathtest 1006s + localhost=127.0.0.1 1006s + portal=127.0.0.1:3260 1006s + maxpaths=4 1006s + backfn=backingfile 1006s + expectwwid=60000000000000000e00000000010001 1006s + testdisk=/dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1006s + bglog=/tmp/autopkgtest.jpNmps/tgtbasedmpaths-artifacts/test-background.log 1006s + fioprep=/tmp/autopkgtest.jpNmps/tgtbasedmpaths-artifacts/path-change-prep.fio 1006s + fiovrfy=/tmp/autopkgtest.jpNmps/tgtbasedmpaths-artifacts/path-change-check.fio 1006s + mkdir -p /etc/multipath 1006s + echo /360000000000000000e00000000010001/ 1006s + service tgt restart 1006s + truncate --size 100M backingfile 1006s + tgtadm --lld iscsi --op new --mode target --tid 1 -T iqn.2016-11.foo.com:target.iscsi 1006s + tgtadm --lld iscsi --op bind --mode target --tid 1 -I ALL 1006s + tgtadm --lld iscsi --op new --mode logicalunit --tid 1 --lun 1 -b /tmp/autopkgtest.jpNmps/build.aIe/src/backingfile 1006s + iscsiadm --mode discovery --type sendtargets --portal 127.0.0.1 1006s + echo login #1 1006s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --login 1006s 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi 1006s login #1 1006s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1006s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1006s + seq 2 4 1006s extra login #2 1006s + echo extra login #2 1006s + iscsiadm --mode session -r 1 --op new 1006s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1006s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1006s + echo extra login #3 1006s + iscsiadm --mode session -r 1 --op new 1006s extra login #3 1006s + echo extra login #4 1006s + iscsiadm --mode session -r 1 --op new 1006s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1006s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1006s extra login #4 1006s + udevadm settle 1006s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1006s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1006s + sleep 5 1011s Status after initial setup 1011s Target 1: iqn.2016-11.foo.com:target.iscsi 1011s System information: 1011s Driver: iscsi 1011s State: ready 1011s I_T nexus information: 1011s I_T nexus: 1 1011s Initiator: iqn.2004-10.com.ubuntu:01:b34e35b2138e alias: autopkgtest 1011s Connection: 0 1011s IP Address: 127.0.0.1 1011s I_T nexus: 2 1011s Initiator: iqn.2004-10.com.ubuntu:01:b34e35b2138e alias: autopkgtest 1011s Connection: 0 1011s IP Address: 127.0.0.1 1011s I_T nexus: 3 1011s Initiator: iqn.2004-10.com.ubuntu:01:b34e35b2138e alias: autopkgtest 1011s Connection: 0 1011s IP Address: 127.0.0.1 1011s I_T nexus: 4 1011s Initiator: iqn.2004-10.com.ubuntu:01:b34e35b2138e alias: autopkgtest 1011s Connection: 0 1011s IP Address: 127.0.0.1 1011s LUN information: 1011s LUN: 0 1011s Type: controller 1011s SCSI ID: IET 00010000 1011s SCSI SN: beaf10 1011s Size: 0 MB, Block size: 1 1011s Online: Yes 1011s Removable media: No 1011s Prevent removal: No 1011s Readonly: No 1011s SWP: No 1011s Thin-provisioning: No 1011s Backing store type: null 1011s Backing store path: None 1011s Backing store flags: 1011s LUN: 1 1011s Type: disk 1011s SCSI ID: IET 00010001 1011s SCSI SN: beaf11 1011s Size: 105 MB, Block size: 512 1011s Online: Yes 1011s Removable media: No 1011s Prevent removal: No 1011s Readonly: No 1011s SWP: No 1011s Thin-provisioning: No 1011s Backing store type: rdwr 1011s Backing store path: /tmp/autopkgtest.jpNmps/build.aIe/src/backingfile 1011s Backing store flags: 1011s Account information: 1011s ACL information: 1011s ALL 1011s Session: 4 1011s Connection: 0 1011s Initiator: iqn.2004-10.com.ubuntu:01:b34e35b2138e 1011s IP Address: 127.0.0.1 1011s Session: 3 1011s Connection: 0 1011s Initiator: iqn.2004-10.com.ubuntu:01:b34e35b2138e 1011s IP Address: 127.0.0.1 1011s Session: 2 1011s Connection: 0 1011s Initiator: iqn.2004-10.com.ubuntu:01:b34e35b2138e 1011s IP Address: 127.0.0.1 1011s Session: 1 1011s Connection: 0 1011s Initiator: iqn.2004-10.com.ubuntu:01:b34e35b2138e 1011s IP Address: 127.0.0.1 1011s + echo Status after initial setup 1011s + tgtadm --lld iscsi --mode target --op show 1011s + tgtadm --lld iscsi --op show --mode conn --tid 1 1011s + iscsiadm --mode session -P 1 1011s Target: iqn.2016-11.foo.com:target.iscsi (non-flash) 1011s Current Portal: 127.0.0.1:3260,1 1011s Persistent Portal: 127.0.0.1:3260,1 1011s ********** 1011s Interface: 1011s ********** 1011s Iface Name: default 1011s Iface Transport: tcp 1011s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:b34e35b2138e 1011s Iface IPaddress: 127.0.0.1 1011s Iface HWaddress: default 1011s Iface Netdev: default 1011s SID: 1 1011s iSCSI Connection State: LOGGED IN 1011s iSCSI Session State: LOGGED_IN 1011s Internal iscsid Session State: NO CHANGE 1011s 1011s ********** 1011s Interface: 1011s ********** 1011s Iface Name: default 1011s Iface Transport: tcp 1011s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:b34e35b2138e 1011s Iface IPaddress: 127.0.0.1 1011s Iface HWaddress: default 1011s Iface Netdev: default 1011s SID: 2 1011s iSCSI Connection State: LOGGED IN 1011s iSCSI Session State: LOGGED_IN 1011s Internal iscsid Session State: NO CHANGE 1011s 1011s ********** 1011s Interface: 1011s ********** 1011s Iface Name: default 1011s Iface Transport: tcp 1011s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:b34e35b2138e 1011s Iface IPaddress: 127.0.0.1 1011s Iface HWaddress: default 1011s Iface Netdev: default 1011s SID: 3 1011s iSCSI Connection State: LOGGED IN 1011s iSCSI Session State: LOGGED_IN 1011s Internal iscsid Session State: NO CHANGE 1011s 1011s ********** 1011s Interface: 1011s ********** 1011s Iface Name: default 1011s Iface Transport: tcp 1011s Iface Initiatorname: iqn.2004-10.com.ubuntu:01:b34e35b2138e 1011s Iface IPaddress: 127.0.0.1 1011s Iface HWaddress: default 1011s Iface Netdev: default 1011s SID: 4 1011s iSCSI Connection State: LOGGED IN 1011s iSCSI Session State: LOGGED_IN 1011s Internal iscsid Session State: NO CHANGE 1011s [0:0:0:0] storage IET Controller 0001 - - 1011s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1011s dir: /sys/bus/scsi/devices/0:0:0:0 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:0] 1011s [0:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sda 360000000000000000e00000000010001 1011s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1011s dir: /sys/bus/scsi/devices/0:0:0:1 [/sys/devices/platform/host0/session1/target0:0:0/0:0:0:1] 1011s [1:0:0:0] storage IET Controller 0001 - - 1011s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1011s dir: /sys/bus/scsi/devices/1:0:0:0 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:0] 1011s [1:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdb 360000000000000000e00000000010001 1011s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1011s dir: /sys/bus/scsi/devices/1:0:0:1 [/sys/devices/platform/host1/session2/target1:0:0/1:0:0:1] 1011s [2:0:0:0] storage IET Controller 0001 - - 1011s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1011s dir: /sys/bus/scsi/devices/2:0:0:0 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:0] 1011s [2:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdc 33000000100000001 1011s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1011s dir: /sys/bus/scsi/devices/2:0:0:1 [/sys/devices/platform/host2/session3/target2:0:0/2:0:0:1] 1011s [3:0:0:0] storage IET Controller 0001 - - 1011s state=running queue_depth=32 scsi_level=6 type=12 device_blocked=0 timeout=30 1011s dir: /sys/bus/scsi/devices/3:0:0:0 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:0] 1011s [3:0:0:1] disk IET VIRTUAL-DISK 0001 /dev/sdd 360000000000000000e00000000010001 1011s state=running queue_depth=32 scsi_level=6 type=0 device_blocked=0 timeout=30 1011s dir: /sys/bus/scsi/devices/3:0:0:1 [/sys/devices/platform/host3/session4/target3:0:0/3:0:0:1] 1011s NVMe module may not be loaded 1011s + lsscsi -liv 1011s list_ndevices: scandir: /sys/class/nvme/: No such file or directory 1011s + multipath -v3 -ll 1011s 60.340296 | set open fds limit to 1073741816/1073741816 1011s 60.340360 | _read_bindings_file: reading /etc/multipath/bindings 1011s 60.340398 | loading /usr/lib/multipath/libchecktur.so checker 1011s 60.340521 | checker tur: message table size = 4 1011s 60.340531 | loading /usr/lib/multipath/libprioconst.so prioritizer 1011s 60.340673 | _init_foreign: foreign library "nvme" is not enabled 1011s 60.347295 | vda: device node name blacklisted 1011s 60.347730 | sda: size = 204800 1011s 60.348004 | sda: vendor = IET 1011s 60.348065 | sda: product = VIRTUAL-DISK 1011s 60.348112 | sda: rev = 0001 1011s 60.349110 | sda: h:b:t:l = 0:0:0:1 1011s 60.349570 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1011s 60.349577 | sda: uid_attribute = ID_SERIAL (setting: multipath internal) 1011s 60.349585 | sda: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1011s 60.349972 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1011s 60.349982 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1011s 60.350017 | sda: serial = beaf11 1011s 60.350024 | sda: detect_checker = yes (setting: multipath internal) 1011s 60.350078 | sda checker timeout = 30 s (setting: kernel sysfs) 1011s 60.350934 | sda: path_checker = tur (setting: multipath internal) 1011s 60.351660 | sda: tur state = up 1011s 60.351859 | sdb: size = 204800 1011s 60.351991 | sdb: vendor = IET 1011s 60.352013 | sdb: product = VIRTUAL-DISK 1011s 60.352054 | sdb: rev = 0001 1011s 60.353067 | sdb: h:b:t:l = 1:0:0:1 1011s 60.353665 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1011s 60.353668 | sdb: uid_attribute = ID_SERIAL (setting: multipath internal) 1011s 60.353670 | sdb: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1011s 60.353890 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1011s 60.353896 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1011s 60.353911 | sdb: serial = beaf11 1011s 60.353914 | sdb: detect_checker = yes (setting: multipath internal) 1011s 60.353942 | sdb checker timeout = 30 s (setting: kernel sysfs) 1011s 60.354670 | sdb: path_checker = tur (setting: multipath internal) 1011s 60.355841 | sdb: tur state = up 1011s 60.356064 | sdc: size = 204800 1011s 60.356242 | sdc: vendor = IET 1011s 60.356277 | sdc: product = VIRTUAL-DISK 1011s 60.356316 | sdc: rev = 0001 1011s 60.357444 | sdc: h:b:t:l = 2:0:0:1 1011s 60.357877 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1011s 60.357882 | sdc: uid_attribute = ID_SERIAL (setting: multipath internal) 1011s 60.357886 | sdc: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1011s 60.358172 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1011s 60.358181 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1011s 60.358220 | sdc: serial = beaf11 1011s 60.358228 | sdc: detect_checker = yes (setting: multipath internal) 1011s 60.358266 | sdc checker timeout = 30 s (setting: kernel sysfs) 1011s 60.359161 | sdc: path_checker = tur (setting: multipath internal) 1011s 60.360233 | sdc: tur state = up 1011s 60.360409 | sdd: size = 204800 1011s 60.360600 | sdd: vendor = IET 1011s 60.360622 | sdd: product = VIRTUAL-DISK 1011s 60.360643 | sdd: rev = 0001 1011s 60.361525 | sdd: h:b:t:l = 3:0:0:1 1011s 60.361923 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1011s 60.361927 | sdd: uid_attribute = ID_SERIAL (setting: multipath internal) 1011s 60.361936 | sdd: recheck_wwid = 1 (setting: multipath.conf defaults/devices section) 1011s 60.362126 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1011s 60.362130 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1011s 60.362144 | sdd: serial = beaf11 1011s 60.362146 | sdd: detect_checker = yes (setting: multipath internal) 1011s 60.362173 | sdd checker timeout = 30 s (setting: kernel sysfs) 1011s 60.363104 | sdd: path_checker = tur (setting: multipath internal) 1011s 60.363234 | sdd: tur state = up 1011s 60.363340 | loop0: device node name blacklisted 1011s 60.363428 | loop1: device node name blacklisted 1011s 60.363588 | loop2: device node name blacklisted 1011s 60.363753 | loop3: device node name blacklisted 1011s 60.363859 | loop4: device node name blacklisted 1011s 60.363943 | loop5: device node name blacklisted 1011s 60.364068 | loop6: device node name blacklisted 1011s 60.364208 | loop7: device node name blacklisted 1011s 60.364332 | dm-0: device node name blacklisted 1011s 60.365660 | multipath-tools v0.9.9 (05/03, 2024) 1011s 60.365685 | libdevmapper version 1.02.196 1011s 60.365839 | kernel device mapper v4.48.0 1011s 60.365854 | DM multipath kernel driver v1.14.0 1011s 60.365989 | sda: size = 204800 1011s 60.365994 | sda: vendor = IET 1011s 60.365997 | sda: product = VIRTUAL-DISK 1011s 60.365999 | sda: rev = 0001 1011s 60.367061 | sda: h:b:t:l = 0:0:0:1 1011s 60.367325 | sda: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1011s 60.367373 | sda: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1011s 60.367379 | sda: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1011s 60.367403 | sda: serial = beaf11 1011s ===== paths list ===== 1011s uuid hcil dev dev_t pri dm_st chk_st vend/prod/rev dev_st 1011s 0:0:0:1 sda 8:0 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1011s 1:0:0:1 sdb 8:16 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1011s 2:0:0:1 sdc 8:32 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1011s 3:0:0:1 sdd 8:48 -1 undef undef IET,VIRTUAL-DISK,0001 unknown 1011s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1011s size=100M features='0' hwhandler='0' wp=rw 1011s |-+- policy='service-time 0' prio=1 status=active 1011s | `- 0:0:0:1 sda 8:0 active ready running 1011s |-+- policy='service-time 0' prio=1 status=enabled 1011s | `- 1:0:0:1 sdb 8:16 active ready running 1011s |-+- policy='service-time 0' prio=1 status=enabled 1011s | `- 2:0:0:1 sdc 8:32 active ready running 1011s `-+- policy='service-time 0' prio=1 status=enabled 1011s `- 3:0:0:1 sdd 8:48 active ready running 1011s mpatha: 0 204800 multipath 0 0 4 1 service-time 0 1 2 8:0 1 1 service-time 0 1 2 8:16 1 1 service-time 0 1 2 8:32 1 1 service-time 0 1 2 8:48 1 1 1011s /etc/multipath/bindings:# Multipath bindings, Version : 1.0 1011s /etc/multipath/bindings:# NOTE: this file is automatically maintained by the multipath program. 1011s /etc/multipath/bindings:# You should not need to edit this file in normal circumstances. 1011s /etc/multipath/bindings:# 1011s /etc/multipath/bindings:# Format: 1011s /etc/multipath/bindings:# alias wwid 1011s /etc/multipath/bindings:# 1011s /etc/multipath/bindings:mpatha 360000000000000000e00000000010001 1011s /etc/multipath/wwids:/360000000000000000e00000000010001/ 1011s ● multipathd.service - Device-Mapper Multipath Device Controller 1011s Loaded: loaded (/usr/lib/systemd/system/multipathd.service; enabled; preset: enabled) 1011s Active: active (running) since Sat 2024-08-17 08:58:20 UTC; 58s ago 1011s Invocation: 24b5065da52f488a844a12842018ad38 1011s TriggeredBy: ● multipathd.socket 1011s Main PID: 331 (multipathd) 1011s Status: "up" 1011s Tasks: 7 1011s Memory: 32.5M (peak: 34.8M) 1011s CPU: 47ms 1011s CGroup: /system.slice/multipathd.service 1011s └─331 /sbin/multipathd -d -s 1011s 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1011s Aug 17 08:58:20 autopkgtest multipathd[331]: multipathd v0.9.9: start up 1011s Aug 17 08:58:20 autopkgtest multipathd[331]: reconfigure: setting up paths and maps 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1011s Aug 17 08:59:13 autopkgtest multipathd[331]: updated bindings file /etc/multipath/bindings 1011s Aug 17 08:59:13 autopkgtest multipathd[331]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 1011s Aug 17 08:59:13 autopkgtest multipathd[331]: sda [8:0]: path added to devmap mpatha 1011s Aug 17 08:59:13 autopkgtest multipathd[331]: mpatha: performing delayed actions 1011s Aug 17 08:59:13 autopkgtest multipathd[331]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 1011s 60.368133 | sda: tur state = up 1011s 60.368149 | sda: uid = 360000000000000000e00000000010001 (udev) 1011s 60.368152 | sda: detect_prio = yes (setting: multipath internal) 1011s 60.368156 | sda: prio = const (setting: multipath internal) 1011s 60.368158 | sda: prio args = "" (setting: multipath internal) 1011s 60.368160 | sda: const prio = 1 1011s 60.368185 | sdb: size = 204800 1011s 60.368189 | sdb: vendor = IET 1011s 60.368192 | sdb: product = VIRTUAL-DISK 1011s 60.368194 | sdb: rev = 0001 1011s 60.369233 | sdb: h:b:t:l = 1:0:0:1 1011s 60.369368 | sdb: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1011s 60.369389 | sdb: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1011s 60.369392 | sdb: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1011s 60.369414 | sdb: serial = beaf11 1011s 60.371144 | sdb: tur state = up 1011s 60.371152 | sdb: uid = 360000000000000000e00000000010001 (udev) 1011s 60.371155 | sdb: detect_prio = yes (setting: multipath internal) 1011s 60.371157 | sdb: prio = const (setting: multipath internal) 1011s 60.371159 | sdb: prio args = "" (setting: multipath internal) 1011s 60.371161 | sdb: const prio = 1 1011s 60.371188 | sdc: size = 204800 1011s 60.371192 | sdc: vendor = IET 1011s 60.371195 | sdc: product = VIRTUAL-DISK 1011s 60.371197 | sdc: rev = 0001 1011s 60.371982 | sdc: h:b:t:l = 2:0:0:1 1011s 60.372127 | sdc: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1011s 60.372192 | sdc: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1011s 60.372199 | sdc: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1011s 60.372225 | sdc: serial = beaf11 1011s 60.373800 | sdc: tur state = up 1011s 60.373808 | sdc: uid = 360000000000000000e00000000010001 (udev) 1011s 60.373810 | sdc: detect_prio = yes (setting: multipath internal) 1011s 60.373813 | sdc: prio = const (setting: multipath internal) 1011s 60.373815 | sdc: prio args = "" (setting: multipath internal) 1011s 60.373817 | sdc: const prio = 1 1011s 60.373848 | sdd: size = 204800 1011s 60.373856 | sdd: vendor = IET 1011s 60.373860 | sdd: product = VIRTUAL-DISK 1011s 60.373864 | sdd: rev = 0001 1011s 60.374613 | sdd: h:b:t:l = 3:0:0:1 1011s 60.374775 | sdd: tgt_node_name = iqn.2016-11.foo.com:target.iscsi 1011s 60.374796 | sdd: 1024 cyl, 4 heads, 50 sectors/track, start at 0 1011s 60.374799 | sdd: vpd_vendor_id = 0 "undef" (setting: multipath internal) 1011s 60.374812 | sdd: serial = beaf11 1011s 60.376113 | sdd: tur state = up 1011s 60.376148 | sdd: uid = 360000000000000000e00000000010001 (udev) 1011s 60.376152 | sdd: detect_prio = yes (setting: multipath internal) 1011s 60.376157 | sdd: prio = const (setting: multipath internal) 1011s 60.376160 | sdd: prio args = "" (setting: multipath internal) 1011s 60.376164 | sdd: const prio = 1 1011s 60.377261 | unloading tur checker 1011s 60.377358 | unloading const prioritizer 1011s + dmsetup table 1011s + grep . /etc/multipath/bindings /etc/multipath/wwids 1011s + systemctl status multipathd.service 1011s + systemctl status multipathd.socket 1011s ● multipathd.socket - multipathd control socket 1011s Loaded: loaded (/usr/lib/systemd/system/multipathd.socket; enabled; preset: enabled) 1011s Active: active (running) since Sat 2024-08-17 08:58:20 UTC; 58s ago 1011s Invocation: 89d2e9523c674f86bbcef2ae4552e4f4 1011s Triggers: ● multipathd.service 1011s Listen: @/org/kernel/linux/storage/multipathd (Stream) 1011s CGroup: /system.slice/multipathd.socket 1011s 1011s Notice: journal has been rotated since unit was started, output may be incomplete. 1011s + ls -la /dev/mapper/ 1011s total 0 1011s drwxr-xr-x 2 root root 80 Aug 17 08:59 . 1011s drwxr-xr-x 20 root root 4360 Aug 17 08:59 .. 1011s crw------- 1 root root 10, 236 Aug 17 08:58 control 1011s lrwxrwxrwx 1 root root 7 Aug 17 08:59 mpatha -> ../dm-0 1011s journal 1011s + echo journal 1011s + journalctl -b 1011s Aug 17 08:58:20 autopkgtest kernel: radix-mmu: Page sizes from device-tree: 1011s Aug 17 08:58:20 autopkgtest kernel: radix-mmu: Page size shift = 12 AP=0x0 1011s Aug 17 08:58:20 autopkgtest kernel: radix-mmu: Page size shift = 16 AP=0x5 1011s Aug 17 08:58:20 autopkgtest kernel: radix-mmu: Page size shift = 21 AP=0x1 1011s Aug 17 08:58:20 autopkgtest kernel: radix-mmu: Page size shift = 30 AP=0x2 1011s Aug 17 08:58:20 autopkgtest kernel: Activating Kernel Userspace Access Prevention 1011s Aug 17 08:58:20 autopkgtest kernel: Activating Kernel Userspace Execution Prevention 1011s Aug 17 08:58:20 autopkgtest kernel: radix-mmu: Mapped 0x0000000000000000-0x00000000038a0000 with 64.0 KiB pages (exec) 1011s Aug 17 08:58:20 autopkgtest kernel: radix-mmu: Mapped 0x00000000038a0000-0x0000000200000000 with 64.0 KiB pages 1011s Aug 17 08:58:20 autopkgtest kernel: lpar: Using radix MMU under hypervisor 1011s Aug 17 08:58:20 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) 1011s Aug 17 08:58:20 autopkgtest kernel: Secure boot mode disabled 1011s Aug 17 08:58:20 autopkgtest kernel: Found initrd at 0xc000000006200000:0xc0000000094f4af5 1011s Aug 17 08:58:20 autopkgtest kernel: Hardware name: IBM pSeries (emulated by qemu) POWER9 (raw) 0x4e1203 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries 1011s Aug 17 08:58:20 autopkgtest kernel: Partition configured for 4 cpus. 1011s Aug 17 08:58:20 autopkgtest kernel: CPU maps initialized for 1 thread per core 1011s Aug 17 08:58:20 autopkgtest kernel: (thread shift is 0) 1011s Aug 17 08:58:20 autopkgtest kernel: Allocated 3360 bytes for 4 pacas 1011s Aug 17 08:58:20 autopkgtest kernel: numa: Partition configured for 1 NUMA nodes. 1011s Aug 17 08:58:20 autopkgtest kernel: ----------------------------------------------------- 1011s Aug 17 08:58:20 autopkgtest kernel: phys_mem_size = 0x200000000 1011s Aug 17 08:58:20 autopkgtest kernel: dcache_bsize = 0x80 1011s Aug 17 08:58:20 autopkgtest kernel: icache_bsize = 0x80 1011s Aug 17 08:58:20 autopkgtest kernel: cpu_features = 0x0001c06b8f4f9187 1011s Aug 17 08:58:20 autopkgtest kernel: possible = 0x001ffbfbcf5fb187 1011s Aug 17 08:58:20 autopkgtest kernel: always = 0x0000000380008181 1011s Aug 17 08:58:20 autopkgtest kernel: cpu_user_features = 0xdc0065c2 0xaef00000 1011s Aug 17 08:58:20 autopkgtest kernel: mmu_features = 0x3c007641 1011s Aug 17 08:58:20 autopkgtest kernel: firmware_features = 0x00000285455a445f 1011s Aug 17 08:58:20 autopkgtest kernel: vmalloc start = 0xc008000000000000 1011s Aug 17 08:58:20 autopkgtest kernel: IO start = 0xc00a000000000000 1011s Aug 17 08:58:20 autopkgtest kernel: vmemmap start = 0xc00c000000000000 1011s Aug 17 08:58:20 autopkgtest kernel: ----------------------------------------------------- 1011s Aug 17 08:58:20 autopkgtest kernel: numa: NODE_DATA [mem 0x1eff0c280-0x1eff13fff] 1011s Aug 17 08:58:20 autopkgtest kernel: rfi-flush: fallback displacement flush available 1011s Aug 17 08:58:20 autopkgtest kernel: rfi-flush: ori type flush available 1011s Aug 17 08:58:20 autopkgtest kernel: rfi-flush: mttrig type flush available 1011s Aug 17 08:58:20 autopkgtest kernel: rfi-flush: patched 12 locations (ori+mttrig type flush) 1011s Aug 17 08:58:20 autopkgtest kernel: count-cache-flush: hardware flush enabled. 1011s Aug 17 08:58:20 autopkgtest kernel: link-stack-flush: software flush enabled. 1011s Aug 17 08:58:20 autopkgtest kernel: entry-flush: patched 61 locations (ori+mttrig type flush) 1011s Aug 17 08:58:20 autopkgtest kernel: uaccess-flush: patched 1 locations (ori+mttrig type flush) 1011s Aug 17 08:58:20 autopkgtest kernel: stf-barrier: eieio barrier available 1011s Aug 17 08:58:20 autopkgtest kernel: stf-barrier: patched 61 entry locations (eieio barrier) 1011s Aug 17 08:58:20 autopkgtest kernel: stf-barrier: patched 12 exit locations (eieio barrier) 1011s Aug 17 08:58:20 autopkgtest kernel: PPC64 nvram contains 65536 bytes 1011s Aug 17 08:58:20 autopkgtest kernel: barrier-nospec: using ORI speculation barrier 1011s Aug 17 08:58:20 autopkgtest kernel: barrier-nospec: patched 269 locations 1011s Aug 17 08:58:20 autopkgtest kernel: Top of RAM: 0x200000000, Total RAM: 0x200000000 1011s Aug 17 08:58:20 autopkgtest kernel: Memory hole size: 0MB 1011s Aug 17 08:58:20 autopkgtest kernel: Zone ranges: 1011s Aug 17 08:58:20 autopkgtest kernel: Normal [mem 0x0000000000000000-0x00000001ffffffff] 1011s Aug 17 08:58:20 autopkgtest kernel: Device empty 1011s Aug 17 08:58:20 autopkgtest kernel: Movable zone start for each node 1011s Aug 17 08:58:20 autopkgtest kernel: Early memory node ranges 1011s Aug 17 08:58:20 autopkgtest kernel: node 0: [mem 0x0000000000000000-0x00000001ffffffff] 1011s Aug 17 08:58:20 autopkgtest kernel: Initmem setup node 0 [mem 0x0000000000000000-0x00000001ffffffff] 1011s Aug 17 08:58:20 autopkgtest kernel: percpu: Embedded 12 pages/cpu s609960 r0 d176472 u786432 1011s Aug 17 08:58:20 autopkgtest kernel: pcpu-alloc: s609960 r0 d176472 u786432 alloc=12*65536 1011s Aug 17 08:58:20 autopkgtest kernel: pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 1011s Aug 17 08:58:20 autopkgtest kernel: Kernel command line: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic root=UUID=55f4738b-dbc7-4aef-90fe-6bd3178557bc ro console=hvc0 earlyprintk 1011s Aug 17 08:58:20 autopkgtest kernel: Unknown kernel command line parameters "earlyprintk BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic", will be passed to user space. 1011s Aug 17 08:58:20 autopkgtest kernel: Dentry cache hash table entries: 1048576 (order: 7, 8388608 bytes, linear) 1011s Aug 17 08:58:20 autopkgtest kernel: Inode-cache hash table entries: 524288 (order: 6, 4194304 bytes, linear) 1011s Aug 17 08:58:20 autopkgtest kernel: Fallback order for Node 0: 0 1011s Aug 17 08:58:20 autopkgtest kernel: Built 1 zonelists, mobility grouping on. Total pages: 130944 1011s Aug 17 08:58:20 autopkgtest kernel: Policy zone: Normal 1011s Aug 17 08:58:20 autopkgtest kernel: mem auto-init: stack:all(zero), heap alloc:on, heap free:off 1011s Aug 17 08:58:20 autopkgtest kernel: Memory: 7968064K/8388608K available (23680K kernel code, 4096K rwdata, 25472K rodata, 8832K init, 1901K bss, 420544K reserved, 0K cma-reserved) 1011s Aug 17 08:58:20 autopkgtest kernel: SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 1011s Aug 17 08:58:20 autopkgtest kernel: ftrace: allocating 51717 entries in 19 pages 1011s Aug 17 08:58:20 autopkgtest kernel: ftrace: allocated 19 pages with 3 groups 1011s Aug 17 08:58:20 autopkgtest kernel: trace event string verifier disabled 1011s Aug 17 08:58:20 autopkgtest kernel: rcu: Hierarchical RCU implementation. 1011s Aug 17 08:58:20 autopkgtest kernel: rcu: RCU restricting CPUs from NR_CPUS=2048 to nr_cpu_ids=4. 1011s Aug 17 08:58:20 autopkgtest kernel: Rude variant of Tasks RCU enabled. 1011s Aug 17 08:58:20 autopkgtest kernel: Tracing variant of Tasks RCU enabled. 1011s Aug 17 08:58:20 autopkgtest kernel: rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. 1011s Aug 17 08:58:20 autopkgtest kernel: rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 1011s Aug 17 08:58:20 autopkgtest kernel: NR_IRQS: 512, nr_irqs: 512, preallocated irqs: 16 1011s Aug 17 08:58:20 autopkgtest kernel: xive: Using IRQ range [0-3] 1011s Aug 17 08:58:20 autopkgtest kernel: xive: Interrupt handling initialized with spapr backend 1011s Aug 17 08:58:20 autopkgtest kernel: xive: Using priority 6 for all interrupts 1011s Aug 17 08:58:20 autopkgtest kernel: xive: Using 64kB queues 1011s Aug 17 08:58:20 autopkgtest kernel: rcu: srcu_init: Setting srcu_struct sizes based on contention. 1011s Aug 17 08:58:20 autopkgtest kernel: time_init: decrementer frequency = 512.000000 MHz 1011s Aug 17 08:58:20 autopkgtest kernel: time_init: processor frequency = 2700.000000 MHz 1011s Aug 17 08:58:20 autopkgtest kernel: time_init: 56 bit decrementer (max: 7fffffffffffff) 1011s Aug 17 08:58:20 autopkgtest kernel: clocksource: timebase: mask: 0xffffffffffffffff max_cycles: 0x761537d007, max_idle_ns: 440795202126 ns 1011s Aug 17 08:58:20 autopkgtest kernel: clocksource: timebase mult[1f40000] shift[24] registered 1011s Aug 17 08:58:20 autopkgtest kernel: clockevent: decrementer mult[83126f] shift[24] cpu[0] 1011s Aug 17 08:58:20 autopkgtest kernel: Console: colour dummy device 80x25 1011s Aug 17 08:58:20 autopkgtest kernel: pid_max: default: 32768 minimum: 301 1011s Aug 17 08:58:20 autopkgtest kernel: LSM: initializing lsm=lockdown,capability,landlock,yama,apparmor,integrity 1011s Aug 17 08:58:20 autopkgtest kernel: landlock: Up and running. 1011s Aug 17 08:58:20 autopkgtest kernel: Yama: becoming mindful. 1011s Aug 17 08:58:20 autopkgtest kernel: AppArmor: AppArmor initialized 1011s Aug 17 08:58:20 autopkgtest kernel: Mount-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 1011s Aug 17 08:58:20 autopkgtest kernel: Mountpoint-cache hash table entries: 16384 (order: 1, 131072 bytes, linear) 1011s Aug 17 08:58:20 autopkgtest kernel: RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 1011s Aug 17 08:58:20 autopkgtest kernel: RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. 1011s Aug 17 08:58:20 autopkgtest kernel: POWER9 performance monitor hardware support registered 1011s Aug 17 08:58:20 autopkgtest kernel: rcu: Hierarchical SRCU implementation. 1011s Aug 17 08:58:20 autopkgtest kernel: rcu: Max phase no-delay instances is 1000. 1011s Aug 17 08:58:20 autopkgtest kernel: smp: Bringing up secondary CPUs ... 1011s Aug 17 08:58:20 autopkgtest kernel: smp: Brought up 1 node, 4 CPUs 1011s Aug 17 08:58:20 autopkgtest kernel: numa: Node 0 CPUs: 0-3 1011s Aug 17 08:58:20 autopkgtest kernel: devtmpfs: initialized 1011s Aug 17 08:58:20 autopkgtest kernel: PCI host bridge /pci@800000020000000 ranges: 1011s Aug 17 08:58:20 autopkgtest kernel: IO 0x0000200000000000..0x000020000000ffff -> 0x0000000000000000 1011s Aug 17 08:58:20 autopkgtest kernel: MEM 0x0000200080000000..0x00002000ffffffff -> 0x0000000080000000 1011s Aug 17 08:58:20 autopkgtest kernel: MEM 0x0000210000000000..0x000021ffffffffff -> 0x0000210000000000 1011s Aug 17 08:58:20 autopkgtest kernel: PCI: OF: PROBE_ONLY disabled 1011s Aug 17 08:58:20 autopkgtest kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns 1011s Aug 17 08:58:20 autopkgtest kernel: futex hash table entries: 1024 (order: 1, 131072 bytes, linear) 1011s Aug 17 08:58:20 autopkgtest kernel: pinctrl core: initialized pinctrl subsystem 1011s Aug 17 08:58:20 autopkgtest kernel: NET: Registered PF_NETLINK/PF_ROUTE protocol family 1011s Aug 17 08:58:20 autopkgtest kernel: audit: initializing netlink subsys (disabled) 1011s Aug 17 08:58:20 autopkgtest kernel: audit: type=2000 audit(1723885098.036:1): state=initialized audit_enabled=0 res=1 1011s Aug 17 08:58:20 autopkgtest kernel: thermal_sys: Registered thermal governor 'fair_share' 1011s Aug 17 08:58:20 autopkgtest kernel: thermal_sys: Registered thermal governor 'bang_bang' 1011s Aug 17 08:58:20 autopkgtest kernel: thermal_sys: Registered thermal governor 'step_wise' 1011s Aug 17 08:58:20 autopkgtest kernel: thermal_sys: Registered thermal governor 'user_space' 1011s Aug 17 08:58:20 autopkgtest kernel: thermal_sys: Registered thermal governor 'power_allocator' 1011s Aug 17 08:58:20 autopkgtest kernel: cpuidle: using governor ladder 1011s Aug 17 08:58:20 autopkgtest kernel: cpuidle: using governor menu 1011s Aug 17 08:58:20 autopkgtest kernel: RTAS daemon started 1011s Aug 17 08:58:20 autopkgtest kernel: pstore: Using crash dump compression: deflate 1011s Aug 17 08:58:20 autopkgtest kernel: pstore: Registered nvram as persistent store backend 1011s Aug 17 08:58:20 autopkgtest kernel: EEH: pSeries platform initialized 1011s Aug 17 08:58:20 autopkgtest kernel: kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. 1011s Aug 17 08:58:20 autopkgtest kernel: HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages 1011s Aug 17 08:58:20 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page 1011s Aug 17 08:58:20 autopkgtest kernel: HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages 1011s Aug 17 08:58:20 autopkgtest kernel: HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page 1011s Aug 17 08:58:20 autopkgtest kernel: iommu: Default domain type: Translated 1011s Aug 17 08:58:20 autopkgtest kernel: iommu: DMA domain TLB invalidation policy: strict mode 1011s Aug 17 08:58:20 autopkgtest kernel: SCSI subsystem initialized 1011s Aug 17 08:58:20 autopkgtest kernel: libata version 3.00 loaded. 1011s Aug 17 08:58:20 autopkgtest kernel: usbcore: registered new interface driver usbfs 1011s Aug 17 08:58:20 autopkgtest kernel: usbcore: registered new interface driver hub 1011s Aug 17 08:58:20 autopkgtest kernel: usbcore: registered new device driver usb 1011s Aug 17 08:58:20 autopkgtest kernel: pps_core: LinuxPPS API ver. 1 registered 1011s Aug 17 08:58:20 autopkgtest kernel: pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti 1011s Aug 17 08:58:20 autopkgtest kernel: PTP clock support registered 1011s Aug 17 08:58:20 autopkgtest kernel: EDAC MC: Ver: 3.0.0 1011s Aug 17 08:58:20 autopkgtest kernel: NetLabel: Initializing 1011s Aug 17 08:58:20 autopkgtest kernel: NetLabel: domain hash size = 128 1011s Aug 17 08:58:20 autopkgtest kernel: NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO 1011s Aug 17 08:58:20 autopkgtest kernel: NetLabel: unlabeled traffic allowed by default 1011s Aug 17 08:58:20 autopkgtest kernel: mctp: management component transport protocol core 1011s Aug 17 08:58:20 autopkgtest kernel: NET: Registered PF_MCTP protocol family 1011s Aug 17 08:58:20 autopkgtest kernel: PCI: Probing PCI hardware 1011s Aug 17 08:58:20 autopkgtest kernel: PCI host bridge to bus 0000:00 1011s Aug 17 08:58:20 autopkgtest kernel: pci_bus 0000:00: root bus resource [io 0x10000-0x1ffff] (bus address [0x0000-0xffff]) 1011s Aug 17 08:58:20 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x200080000000-0x2000ffffffff] (bus address [0x80000000-0xffffffff]) 1011s Aug 17 08:58:20 autopkgtest kernel: pci_bus 0000:00: root bus resource [mem 0x210000000000-0x21ffffffffff 64bit] 1011s Aug 17 08:58:20 autopkgtest kernel: pci_bus 0000:00: root bus resource [bus 00-ff] 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:01.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:02.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:03.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:04.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:05.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:06.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:07.0: No hypervisor support for SR-IOV on this device, IOV BARs disabled. 1011s Aug 17 08:58:20 autopkgtest kernel: IOMMU table initialized, virtual merging enabled 1011s Aug 17 08:58:20 autopkgtest kernel: PCI 0000:00 Cannot reserve Legacy IO [io 0x10000-0x10fff] 1011s Aug 17 08:58:20 autopkgtest kernel: pci_bus 0000:00: resource 4 [io 0x10000-0x1ffff] 1011s Aug 17 08:58:20 autopkgtest kernel: pci_bus 0000:00: resource 5 [mem 0x200080000000-0x2000ffffffff] 1011s Aug 17 08:58:20 autopkgtest kernel: pci_bus 0000:00: resource 6 [mem 0x210000000000-0x21ffffffffff 64bit] 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:01.0: Adding to iommu group 0 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:02.0: Adding to iommu group 0 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:03.0: Adding to iommu group 0 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:04.0: Adding to iommu group 0 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:05.0: Adding to iommu group 0 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:06.0: Adding to iommu group 0 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:07.0: Adding to iommu group 0 1011s Aug 17 08:58:20 autopkgtest kernel: EEH: No capable adapters found: recovery disabled. 1011s Aug 17 08:58:20 autopkgtest kernel: PCI: Probing PCI hardware done 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:07.0: vgaarb: setting as boot VGA device 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:07.0: vgaarb: bridge control possible 1011s Aug 17 08:58:20 autopkgtest kernel: pci 0000:00:07.0: vgaarb: VGA device added: decodes=io+mem,owns=mem,locks=none 1011s Aug 17 08:58:20 autopkgtest kernel: vgaarb: loaded 1011s Aug 17 08:58:20 autopkgtest kernel: clocksource: Switched to clocksource timebase 1011s Aug 17 08:58:20 autopkgtest kernel: VFS: Disk quotas dquot_6.6.0 1011s Aug 17 08:58:20 autopkgtest kernel: VFS: Dquot-cache hash table entries: 8192 (order 0, 65536 bytes) 1011s Aug 17 08:58:20 autopkgtest kernel: AppArmor: AppArmor Filesystem Enabled 1011s Aug 17 08:58:20 autopkgtest kernel: NET: Registered PF_INET protocol family 1011s Aug 17 08:58:20 autopkgtest kernel: IP idents hash table entries: 131072 (order: 4, 1048576 bytes, linear) 1011s Aug 17 08:58:20 autopkgtest kernel: tcp_listen_portaddr_hash hash table entries: 4096 (order: 0, 65536 bytes, linear) 1011s Aug 17 08:58:20 autopkgtest kernel: Table-perturb hash table entries: 65536 (order: 2, 262144 bytes, linear) 1011s Aug 17 08:58:20 autopkgtest kernel: TCP established hash table entries: 65536 (order: 3, 524288 bytes, linear) 1011s Aug 17 08:58:20 autopkgtest kernel: TCP bind hash table entries: 65536 (order: 5, 2097152 bytes, linear) 1011s Aug 17 08:58:20 autopkgtest kernel: TCP: Hash tables configured (established 65536 bind 65536) 1011s Aug 17 08:58:20 autopkgtest kernel: MPTCP token hash table entries: 8192 (order: 1, 196608 bytes, linear) 1011s Aug 17 08:58:20 autopkgtest kernel: UDP hash table entries: 4096 (order: 1, 131072 bytes, linear) 1011s Aug 17 08:58:20 autopkgtest kernel: UDP-Lite hash table entries: 4096 (order: 1, 131072 bytes, linear) 1011s Aug 17 08:58:20 autopkgtest kernel: NET: Registered PF_UNIX/PF_LOCAL protocol family 1011s Aug 17 08:58:20 autopkgtest kernel: NET: Registered PF_XDP protocol family 1011s Aug 17 08:58:20 autopkgtest kernel: PCI: CLS 0 bytes, default 128 1011s Aug 17 08:58:20 autopkgtest kernel: Trying to unpack rootfs image as initramfs... 1011s Aug 17 08:58:20 autopkgtest kernel: Initialise system trusted keyrings 1011s Aug 17 08:58:20 autopkgtest kernel: Key type blacklist registered 1011s Aug 17 08:58:20 autopkgtest kernel: workingset: timestamp_bits=38 max_order=17 bucket_order=0 1011s Aug 17 08:58:20 autopkgtest kernel: zbud: loaded 1011s Aug 17 08:58:20 autopkgtest kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher 1011s Aug 17 08:58:20 autopkgtest kernel: fuse: init (API version 7.39) 1011s Aug 17 08:58:20 autopkgtest kernel: integrity: Platform Keyring initialized 1011s Aug 17 08:58:20 autopkgtest kernel: integrity: Machine keyring initialized 1011s Aug 17 08:58:20 autopkgtest kernel: Key type asymmetric registered 1011s Aug 17 08:58:20 autopkgtest kernel: Asymmetric key parser 'x509' registered 1011s Aug 17 08:58:20 autopkgtest kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243) 1011s Aug 17 08:58:20 autopkgtest kernel: io scheduler mq-deadline registered 1011s Aug 17 08:58:20 autopkgtest kernel: virtio-pci 0000:00:01.0: enabling device (0100 -> 0103) 1011s Aug 17 08:58:20 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 1011s Aug 17 08:58:20 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) 1011s Aug 17 08:58:20 autopkgtest kernel: virtio-pci 0000:00:03.0: enabling device (0100 -> 0103) 1011s Aug 17 08:58:20 autopkgtest kernel: virtio-pci 0000:00:04.0: enabling device (0100 -> 0103) 1011s Aug 17 08:58:20 autopkgtest kernel: virtio-pci 0000:00:05.0: enabling device (0100 -> 0103) 1011s Aug 17 08:58:20 autopkgtest kernel: virtio-pci 0000:00:06.0: enabling device (0100 -> 0103) 1011s Aug 17 08:58:20 autopkgtest kernel: printk: legacy console [hvc0] enabled 1011s Aug 17 08:58:20 autopkgtest kernel: Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled 1011s Aug 17 08:58:20 autopkgtest kernel: Freeing initrd memory: 52160K 1011s Aug 17 08:58:20 autopkgtest kernel: Non-volatile memory driver v1.3 1011s Aug 17 08:58:20 autopkgtest kernel: Linux agpgart interface v0.103 1011s Aug 17 08:58:20 autopkgtest kernel: loop: module loaded 1011s Aug 17 08:58:20 autopkgtest kernel: virtio_blk virtio2: 4/0/0 default/read/poll queues 1011s Aug 17 08:58:20 autopkgtest kernel: virtio_blk virtio2: [vda] 209715200 512-byte logical blocks (107 GB/100 GiB) 1011s Aug 17 08:58:20 autopkgtest kernel: vda: vda1 vda2 1011s Aug 17 08:58:20 autopkgtest kernel: tun: Universal TUN/TAP device driver, 1.6 1011s Aug 17 08:58:20 autopkgtest kernel: PPP generic driver version 2.4.2 1011s Aug 17 08:58:20 autopkgtest kernel: mousedev: PS/2 mouse device common for all mice 1011s Aug 17 08:58:20 autopkgtest kernel: rtc-generic rtc-generic: registered as rtc0 1011s Aug 17 08:58:20 autopkgtest kernel: rtc-generic rtc-generic: setting system clock to 2024-08-17T08:58:18 UTC (1723885098) 1011s Aug 17 08:58:20 autopkgtest kernel: i2c_dev: i2c /dev entries driver 1011s Aug 17 08:58:20 autopkgtest kernel: device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. 1011s Aug 17 08:58:20 autopkgtest kernel: device-mapper: uevent: version 1.0.3 1011s Aug 17 08:58:20 autopkgtest kernel: device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@redhat.com 1011s Aug 17 08:58:20 autopkgtest kernel: pseries_idle_driver registered 1011s Aug 17 08:58:20 autopkgtest kernel: ledtrig-cpu: registered to indicate activity on CPUs 1011s Aug 17 08:58:20 autopkgtest kernel: drop_monitor: Initializing network drop monitor service 1011s Aug 17 08:58:20 autopkgtest kernel: NET: Registered PF_INET6 protocol family 1011s Aug 17 08:58:20 autopkgtest kernel: Segment Routing with IPv6 1011s Aug 17 08:58:20 autopkgtest kernel: In-situ OAM (IOAM) with IPv6 1011s Aug 17 08:58:20 autopkgtest kernel: NET: Registered PF_PACKET protocol family 1011s Aug 17 08:58:20 autopkgtest kernel: Key type dns_resolver registered 1011s Aug 17 08:58:20 autopkgtest kernel: secvar-sysfs: Failed to retrieve secvar operations 1011s Aug 17 08:58:20 autopkgtest kernel: drmem: No dynamic reconfiguration memory found 1011s Aug 17 08:58:20 autopkgtest kernel: registered taskstats version 1 1011s Aug 17 08:58:20 autopkgtest kernel: Loading compiled-in X.509 certificates 1011s Aug 17 08:58:20 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 1011s Aug 17 08:58:20 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Live Patch Signing: 14df34d1a87cf37625abec039ef2bf521249b969' 1011s Aug 17 08:58:20 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Kernel Module Signing: 88f752e560a1e0737e31163a466ad7b70a850c19' 1011s Aug 17 08:58:20 autopkgtest kernel: blacklist: Loading compiled-in revocation X.509 certificates 1011s Aug 17 08:58:20 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing: 61482aa2830d0ab2ad5af10b7250da9033ddcef0' 1011s Aug 17 08:58:20 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2017): 242ade75ac4a15e50d50c84b0d45ff3eae707a03' 1011s Aug 17 08:58:20 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (ESM 2018): 365188c1d374d6b07c3c8f240f8ef722433d6a8b' 1011s Aug 17 08:58:20 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2019): c0746fd6c5da3ae827864651ad66ae47fe24b3e8' 1011s Aug 17 08:58:20 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v1): a8d54bbb3825cfb94fa13c9f8a594a195c107b8d' 1011s Aug 17 08:58:20 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v2): 4cf046892d6fd3c9a5b03f98d845f90851dc6a8c' 1011s Aug 17 08:58:20 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (2021 v3): 100437bb6de6e469b581e61cd66bce3ef4ed53af' 1011s Aug 17 08:58:20 autopkgtest kernel: Loaded X.509 cert 'Canonical Ltd. Secure Boot Signing (Ubuntu Core 2019): c1d57b8f6b743f23ee41f4f7ee292f06eecadfb9' 1011s Aug 17 08:58:20 autopkgtest kernel: Key type .fscrypt registered 1011s Aug 17 08:58:20 autopkgtest kernel: Key type fscrypt-provisioning registered 1011s Aug 17 08:58:20 autopkgtest kernel: Key type encrypted registered 1011s Aug 17 08:58:20 autopkgtest kernel: AppArmor: AppArmor sha256 policy hashing enabled 1011s Aug 17 08:58:20 autopkgtest kernel: Secure boot mode disabled 1011s Aug 17 08:58:20 autopkgtest kernel: ima: No TPM chip found, activating TPM-bypass! 1011s Aug 17 08:58:20 autopkgtest kernel: Loading compiled-in module X.509 certificates 1011s Aug 17 08:58:20 autopkgtest kernel: Loaded X.509 cert 'Build time autogenerated kernel key: d20be259617023e52b002c562b3536c6f73da543' 1011s Aug 17 08:58:20 autopkgtest kernel: ima: Allocated hash algorithm: sha256 1011s Aug 17 08:58:20 autopkgtest kernel: Secure boot mode disabled 1011s Aug 17 08:58:20 autopkgtest kernel: Trusted boot mode disabled 1011s Aug 17 08:58:20 autopkgtest kernel: ima: No architecture policies found 1011s Aug 17 08:58:20 autopkgtest kernel: evm: Initialising EVM extended attributes: 1011s Aug 17 08:58:20 autopkgtest kernel: evm: security.selinux 1011s Aug 17 08:58:20 autopkgtest kernel: evm: security.SMACK64 1011s Aug 17 08:58:20 autopkgtest kernel: evm: security.SMACK64EXEC 1011s Aug 17 08:58:20 autopkgtest kernel: evm: security.SMACK64TRANSMUTE 1011s Aug 17 08:58:20 autopkgtest kernel: evm: security.SMACK64MMAP 1011s Aug 17 08:58:20 autopkgtest kernel: evm: security.apparmor 1011s Aug 17 08:58:20 autopkgtest kernel: evm: security.ima 1011s Aug 17 08:58:20 autopkgtest kernel: evm: security.capability 1011s Aug 17 08:58:20 autopkgtest kernel: evm: HMAC attrs: 0x1 1011s Aug 17 08:58:20 autopkgtest kernel: SED: plpks not available 1011s Aug 17 08:58:20 autopkgtest kernel: clk: Disabling unused clocks 1011s Aug 17 08:58:20 autopkgtest kernel: integrity: Unable to open file: /etc/keys/x509_evm.der (-2) 1011s Aug 17 08:58:20 autopkgtest kernel: Freeing unused kernel image (initmem) memory: 8832K 1011s Aug 17 08:58:20 autopkgtest kernel: Checked W+X mappings: passed, no W+X pages found 1011s Aug 17 08:58:20 autopkgtest kernel: Run /init as init process 1011s Aug 17 08:58:20 autopkgtest kernel: with arguments: 1011s Aug 17 08:58:20 autopkgtest kernel: /init 1011s Aug 17 08:58:20 autopkgtest kernel: earlyprintk 1011s Aug 17 08:58:20 autopkgtest kernel: with environment: 1011s Aug 17 08:58:20 autopkgtest kernel: HOME=/ 1011s Aug 17 08:58:20 autopkgtest kernel: TERM=linux 1011s Aug 17 08:58:20 autopkgtest kernel: BOOT_IMAGE=/boot/vmlinux-6.8.0-31-generic 1011s Aug 17 08:58:20 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 1011s Aug 17 08:58:20 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 1 1011s Aug 17 08:58:20 autopkgtest kernel: xhci_hcd 0000:00:02.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010 1011s Aug 17 08:58:20 autopkgtest kernel: xhci_hcd 0000:00:02.0: xHCI Host Controller 1011s Aug 17 08:58:20 autopkgtest kernel: xhci_hcd 0000:00:02.0: new USB bus registered, assigned bus number 2 1011s Aug 17 08:58:20 autopkgtest kernel: xhci_hcd 0000:00:02.0: Host supports USB 3.0 SuperSpeed 1011s Aug 17 08:58:20 autopkgtest kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.08 1011s Aug 17 08:58:20 autopkgtest kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 1011s Aug 17 08:58:20 autopkgtest kernel: usb usb1: Product: xHCI Host Controller 1011s Aug 17 08:58:20 autopkgtest kernel: usb usb1: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 1011s Aug 17 08:58:20 autopkgtest kernel: usb usb1: SerialNumber: 0000:00:02.0 1011s Aug 17 08:58:20 autopkgtest kernel: hub 1-0:1.0: USB hub found 1011s Aug 17 08:58:20 autopkgtest kernel: hub 1-0:1.0: 4 ports detected 1011s Aug 17 08:58:20 autopkgtest kernel: random: crng init done 1011s Aug 17 08:58:20 autopkgtest kernel: usb usb2: We don't know the algorithms for LPM for this host, disabling LPM. 1011s Aug 17 08:58:20 autopkgtest kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.08 1011s Aug 17 08:58:20 autopkgtest kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 1011s Aug 17 08:58:20 autopkgtest kernel: usb usb2: Product: xHCI Host Controller 1011s Aug 17 08:58:20 autopkgtest kernel: usb usb2: Manufacturer: Linux 6.8.0-31-generic xhci-hcd 1011s Aug 17 08:58:20 autopkgtest kernel: usb usb2: SerialNumber: 0000:00:02.0 1011s Aug 17 08:58:20 autopkgtest kernel: hub 2-0:1.0: USB hub found 1011s Aug 17 08:58:20 autopkgtest kernel: hub 2-0:1.0: 4 ports detected 1011s Aug 17 08:58:20 autopkgtest kernel: virtio_net virtio0 enp0s1: renamed from eth0 1011s Aug 17 08:58:20 autopkgtest kernel: [drm] Found bochs VGA, ID 0xb0c5. 1011s Aug 17 08:58:20 autopkgtest kernel: [drm] Framebuffer size 16384 kB @ 0x200081000000, mmio @ 0x200082000000. 1011s Aug 17 08:58:20 autopkgtest kernel: [drm] Found EDID data blob. 1011s Aug 17 08:58:20 autopkgtest kernel: [drm] Initialized bochs-drm 1.0.0 20130925 for 0000:00:07.0 on minor 0 1011s Aug 17 08:58:20 autopkgtest kernel: fbcon: Deferring console take-over 1011s Aug 17 08:58:20 autopkgtest kernel: bochs-drm 0000:00:07.0: [drm] fb0: bochs-drmdrmfb frame buffer device 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: vpermxor8 gen() 21820 MB/s 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: vpermxor4 gen() 19470 MB/s 1011s Aug 17 08:58:20 autopkgtest kernel: usb 1-1: new high-speed USB device number 2 using xhci_hcd 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: vpermxor2 gen() 15744 MB/s 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: vpermxor1 gen() 13283 MB/s 1011s Aug 17 08:58:20 autopkgtest kernel: usb 1-1: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 1011s Aug 17 08:58:20 autopkgtest kernel: usb 1-1: New USB device strings: Mfr=1, Product=4, SerialNumber=11 1011s Aug 17 08:58:20 autopkgtest kernel: usb 1-1: Product: QEMU USB Keyboard 1011s Aug 17 08:58:20 autopkgtest kernel: usb 1-1: Manufacturer: QEMU 1011s Aug 17 08:58:20 autopkgtest kernel: usb 1-1: SerialNumber: 68284-pci@800000020000000:02.0-1 1011s Aug 17 08:58:20 autopkgtest kernel: hid: raw HID events driver (C) Jiri Kosina 1011s Aug 17 08:58:20 autopkgtest kernel: usbcore: registered new interface driver usbhid 1011s Aug 17 08:58:20 autopkgtest kernel: usbhid: USB HID core driver 1011s Aug 17 08:58:20 autopkgtest kernel: input: QEMU QEMU USB Keyboard as /devices/pci0000:00/0000:00:02.0/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input0 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: altivecx8 gen() 13599 MB/s 1011s Aug 17 08:58:20 autopkgtest kernel: hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v1.11 Keyboard [QEMU QEMU USB Keyboard] on usb-0000:00:02.0-1/input0 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: altivecx4 gen() 13845 MB/s 1011s Aug 17 08:58:20 autopkgtest kernel: usb 1-2: new high-speed USB device number 3 using xhci_hcd 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: altivecx2 gen() 11003 MB/s 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: altivecx1 gen() 8566 MB/s 1011s Aug 17 08:58:20 autopkgtest kernel: usb 1-2: New USB device found, idVendor=0627, idProduct=0001, bcdDevice= 0.00 1011s Aug 17 08:58:20 autopkgtest kernel: usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=9 1011s Aug 17 08:58:20 autopkgtest kernel: usb 1-2: Product: QEMU USB Mouse 1011s Aug 17 08:58:20 autopkgtest kernel: usb 1-2: Manufacturer: QEMU 1011s Aug 17 08:58:20 autopkgtest kernel: usb 1-2: SerialNumber: 89126-pci@800000020000000:02.0-2 1011s Aug 17 08:58:20 autopkgtest kernel: input: QEMU QEMU USB Mouse as /devices/pci0000:00/0000:00:02.0/usb1/1-2/1-2:1.0/0003:0627:0001.0002/input/input1 1011s Aug 17 08:58:20 autopkgtest kernel: hid-generic 0003:0627:0001.0002: input,hidraw1: USB HID v0.01 Mouse [QEMU QEMU USB Mouse] on usb-0000:00:02.0-2/input0 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: int64x8 gen() 7037 MB/s 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: int64x4 gen() 8132 MB/s 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: int64x2 gen() 6298 MB/s 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: int64x1 gen() 5126 MB/s 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: using algorithm vpermxor8 gen() 21820 MB/s 1011s Aug 17 08:58:20 autopkgtest kernel: raid6: using intx1 recovery algorithm 1011s Aug 17 08:58:20 autopkgtest kernel: xor: measuring software checksum speed 1011s Aug 17 08:58:20 autopkgtest kernel: 8regs : 17478 MB/sec 1011s Aug 17 08:58:20 autopkgtest kernel: 8regs_prefetch : 15597 MB/sec 1011s Aug 17 08:58:20 autopkgtest kernel: 32regs : 17548 MB/sec 1011s Aug 17 08:58:20 autopkgtest kernel: 32regs_prefetch : 15733 MB/sec 1011s Aug 17 08:58:20 autopkgtest kernel: altivec : 19447 MB/sec 1011s Aug 17 08:58:20 autopkgtest kernel: xor: using function: altivec (19447 MB/sec) 1011s Aug 17 08:58:20 autopkgtest kernel: Btrfs loaded, zoned=yes, fsverity=yes 1011s Aug 17 08:58:20 autopkgtest kernel: EXT4-fs (vda1): orphan cleanup on readonly fs 1011s Aug 17 08:58:20 autopkgtest kernel: EXT4-fs (vda1): mounted filesystem 55f4738b-dbc7-4aef-90fe-6bd3178557bc ro with ordered data mode. Quota mode: none. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Inserted module 'autofs4' 1011s Aug 17 08:58:20 autopkgtest systemd[1]: systemd 256.4-2ubuntu1 running in system mode (+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT -GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY +P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD +BPF_FRAMEWORK -XKBCOMMON +UTMP +SYSVINIT +LIBARCHIVE) 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Detected virtualization kvm. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Detected architecture ppc64-le. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Hostname set to . 1011s Aug 17 08:58:20 autopkgtest systemd[1]: bpf-restrict-fs: BPF LSM hook not enabled in the kernel, BPF LSM not supported. 1011s Aug 17 08:58:20 autopkgtest kernel: NET: Registered PF_VSOCK protocol family 1011s Aug 17 08:58:20 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. 1011s Aug 17 08:58:20 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. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Queued start job for default target graphical.target. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Created slice system-autopkgtest.slice - Slice /system/autopkgtest. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Created slice system-modprobe.slice - Slice /system/modprobe. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Created slice system-serial\x2dgetty.slice - Slice /system/serial-getty. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Created slice user.slice - User and Session Slice. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Started systemd-ask-password-wall.path - Forward Password Requests to Wall Directory Watch. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Set up automount proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats File System Automount Point. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Reached target integritysetup.target - Local Integrity Protected Volumes. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Reached target remote-fs.target - Remote File Systems. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Reached target slices.target - Slice Units. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Reached target swap.target - Swaps. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Reached target veritysetup.target - Local Verity Protected Volumes. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Listening on multipathd.socket - multipathd control socket. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Listening on syslog.socket - Syslog Socket. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Listening on systemd-creds.socket - Credential Encryption/Decryption. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Listening on systemd-fsckd.socket - fsck to fsckd communication Socket. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Listening on systemd-initctl.socket - initctl Compatibility Named Pipe. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Listening on systemd-journald-dev-log.socket - Journal Socket (/dev/log). 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Listening on systemd-journald.socket - Journal Sockets. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Listening on systemd-networkd.socket - Network Service Netlink Socket. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Listening on systemd-udevd-control.socket - udev Control Socket. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Listening on systemd-udevd-kernel.socket - udev Kernel Socket. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounting dev-hugepages.mount - Huge Pages File System... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounting dev-mqueue.mount - POSIX Message Queue File System... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounting run-lock.mount - Legacy Locks Directory /run/lock... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounting sys-kernel-debug.mount - Kernel Debug File System... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounting sys-kernel-tracing.mount - Kernel Trace File System... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-journald.service - Journal Service... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting keyboard-setup.service - Set the console keyboard layout... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting kmod-static-nodes.service - Create List of Static Device Nodes... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting modprobe@configfs.service - Load Kernel Module configfs... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting modprobe@dm_multipath.service - Load Kernel Module dm_multipath... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting modprobe@drm.service - Load Kernel Module drm... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting modprobe@efi_pstore.service - Load Kernel Module efi_pstore... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting modprobe@fuse.service - Load Kernel Module fuse... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl). 1011s Aug 17 08:58:20 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). 1011s Aug 17 08:58:20 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). 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-modules-load.service - Load Kernel Modules... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-remount-fs.service - Remount Root and Kernel File Systems... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-udev-load-credentials.service - Load udev Rules from Credentials... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-udev-trigger.service - Coldplug All udev Devices... 1011s Aug 17 08:58:20 autopkgtest systemd-journald[282]: Collecting audit messages is disabled. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounted dev-mqueue.mount - POSIX Message Queue File System. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounted run-lock.mount - Legacy Locks Directory /run/lock. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounted sys-kernel-debug.mount - Kernel Debug File System. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounted sys-kernel-tracing.mount - Kernel Trace File System. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished kmod-static-nodes.service - Create List of Static Device Nodes. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: modprobe@configfs.service: Deactivated successfully. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished modprobe@configfs.service - Load Kernel Module configfs. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: modprobe@dm_multipath.service: Deactivated successfully. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished modprobe@dm_multipath.service - Load Kernel Module dm_multipath. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: modprobe@drm.service: Deactivated successfully. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished modprobe@drm.service - Load Kernel Module drm. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: modprobe@efi_pstore.service: Deactivated successfully. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: modprobe@fuse.service: Deactivated successfully. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished modprobe@fuse.service - Load Kernel Module fuse. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished systemd-modules-load.service - Load Kernel Modules. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished systemd-udev-load-credentials.service - Load udev Rules from Credentials. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounting sys-fs-fuse-connections.mount - FUSE Control File System... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounting sys-kernel-config.mount - Kernel Configuration File System... 1011s Aug 17 08:58:20 autopkgtest systemd-journald[282]: Journal started 1011s Aug 17 08:58:20 autopkgtest systemd-journald[282]: Runtime Journal (/run/log/journal/05b0063ce8e942a2a9f1e2dda7f4ea71) is 8M, max 78.4M, 70.4M free. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-sysctl.service - Apply Kernel Variables... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Started systemd-journald.service - Journal Service. 1011s Aug 17 08:58:20 autopkgtest kernel: EXT4-fs (vda1): re-mounted 55f4738b-dbc7-4aef-90fe-6bd3178557bc r/w. Quota mode: none. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished systemd-remount-fs.service - Remount Root and Kernel File Systems. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished keyboard-setup.service - Set the console keyboard layout. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounted sys-fs-fuse-connections.mount - FUSE Control File System. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounted sys-kernel-config.mount - Kernel Configuration File System. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting cloud-init-main.service - Cloud-init: Single Process... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: systemd-hwdb-update.service - Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc). 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-journal-flush.service - Flush Journal to Persistent Storage... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: systemd-pstore.service - Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore). 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-random-seed.service - Load/Save OS Random Seed... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished systemd-sysctl.service - Apply Kernel Variables. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes in /dev gracefully. 1011s Aug 17 08:58:20 autopkgtest systemd-journald[282]: Time spent on flushing to /var/log/journal/05b0063ce8e942a2a9f1e2dda7f4ea71 is 37.057ms for 460 entries. 1011s Aug 17 08:58:20 autopkgtest systemd-journald[282]: System Journal (/var/log/journal/05b0063ce8e942a2a9f1e2dda7f4ea71) is 19.1M, max 4G, 3.9G free. 1011s Aug 17 08:58:20 autopkgtest systemd-journald[282]: Received client request to flush runtime journal. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: systemd-sysusers.service - Create System Users was skipped because no trigger condition checks were met. 1011s Aug 17 08:58:20 autopkgtest multipathd[331]: multipathd v0.9.9: start up 1011s Aug 17 08:58:20 autopkgtest multipathd[331]: reconfigure: setting up paths and maps 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished systemd-udev-trigger.service - Coldplug All udev Devices. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Reached target local-fs-pre.target - Preparation for Local File Systems. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Reached target local-fs.target - Local File Systems. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Listening on systemd-sysext.socket - System Extension Image Management. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting apparmor.service - Load AppArmor profiles... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting console-setup.service - Set console font and keymap... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: ldconfig.service - Rebuild Dynamic Linker Cache was skipped because no trigger condition checks were met. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-binfmt.service - Set Up Additional Binary Formats... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting ufw.service - Uncomplicated firewall... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished systemd-random-seed.service - Load/Save OS Random Seed. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished ufw.service - Uncomplicated firewall. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 353 (systemd-binfmt) 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished systemd-journal-flush.service - Flush Journal to Persistent Storage. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounting proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-tmpfiles-setup.service - Create System Files and Directories... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished console-setup.service - Set console font and keymap. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished plymouth-read-write.service - Tell Plymouth To Write Out Runtime Data. 1011s Aug 17 08:58:20 autopkgtest apparmor.systemd[350]: Restarting AppArmor 1011s Aug 17 08:58:20 autopkgtest apparmor.systemd[350]: Reloading AppArmor profiles 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Mounted proc-sys-fs-binfmt_misc.mount - Arbitrary Executable File Formats File System. 1011s Aug 17 08:58:20 autopkgtest systemd-tmpfiles[367]: /usr/lib/tmpfiles.d/legacy.conf:13: Duplicate line for path "/run/lock", ignoring. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished systemd-binfmt.service - Set Up Additional Binary Formats. 1011s Aug 17 08:58:20 autopkgtest kernel: audit: type=1400 audit(1723885100.496:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=384 comm="apparmor_parser" 1011s Aug 17 08:58:20 autopkgtest kernel: audit: type=1400 audit(1723885100.496:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=383 comm="apparmor_parser" 1011s Aug 17 08:58:20 autopkgtest kernel: audit: type=1400 audit(1723885100.496:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="1password" pid=381 comm="apparmor_parser" 1011s Aug 17 08:58:20 autopkgtest kernel: audit: type=1400 audit(1723885100.496:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="Discord" pid=382 comm="apparmor_parser" 1011s Aug 17 08:58:20 autopkgtest kernel: audit: type=1400 audit(1723885100.496:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="brave" pid=386 comm="apparmor_parser" 1011s Aug 17 08:58:20 autopkgtest kernel: audit: type=1400 audit(1723885100.496:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="balena-etcher" pid=385 comm="apparmor_parser" 1011s Aug 17 08:58:20 autopkgtest kernel: audit: type=1400 audit(1723885100.500:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="buildah" pid=387 comm="apparmor_parser" 1011s Aug 17 08:58:20 autopkgtest kernel: audit: type=1400 audit(1723885100.500:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="busybox" pid=388 comm="apparmor_parser" 1011s Aug 17 08:58:20 autopkgtest kernel: audit: type=1400 audit(1723885100.500:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="cam" pid=389 comm="apparmor_parser" 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished systemd-tmpfiles-setup.service - Create System Files and Directories. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: systemd-firstboot.service - First Boot Wizard was skipped because of an unmet condition check (ConditionFirstBoot=yes). 1011s Aug 17 08:58:20 autopkgtest systemd[1]: first-boot-complete.target - First Boot Complete was skipped because of an unmet condition check (ConditionFirstBoot=yes). 1011s Aug 17 08:58:20 autopkgtest systemd[1]: systemd-journal-catalog-update.service - Rebuild Journal Catalog was skipped because of an unmet condition check (ConditionNeedsUpdate=/var). 1011s Aug 17 08:58:20 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). 1011s Aug 17 08:58:20 autopkgtest systemd-udevd[343]: Using default interface naming scheme 'v255'. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-resolved.service - Network Name Resolution... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: systemd-update-done.service - Update is Completed was skipped because no trigger condition checks were met. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Starting systemd-update-utmp.service - Record System Boot/Shutdown in UTMP... 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished systemd-update-utmp.service - Record System Boot/Shutdown in UTMP. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Started systemd-udevd.service - Rule-based Manager for Device Events and Files. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: plymouth-start.service - Show Plymouth Boot Screen was skipped because of an unmet condition check (ConditionKernelCommandLine=splash). 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Started systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch. 1011s Aug 17 08:58:20 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). 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Reached target cryptsetup.target - Local Encrypted Volumes. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Found device dev-hvc0.device - /dev/hvc0. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Reached target time-set.target - System Time Set. 1011s Aug 17 08:58:20 autopkgtest systemd-resolved[399]: Positive Trust Anchors: 1011s Aug 17 08:58:20 autopkgtest systemd-resolved[399]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d 1011s Aug 17 08:58:20 autopkgtest (udev-worker)[454]: enp0s1: Could not set WakeOnLan to off, ignoring: Operation not supported 1011s Aug 17 08:58:20 autopkgtest systemd-resolved[399]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 170.0.0.192.in-addr.arpa 171.0.0.192.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa ipv4only.arpa resolver.arpa corp home internal intranet lan local private test 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Finished apparmor.service - Load AppArmor profiles. 1011s Aug 17 08:58:20 autopkgtest systemd-resolved[399]: Using system hostname 'autopkgtest'. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Started systemd-resolved.service - Network Name Resolution. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Reached target nss-lookup.target - Host and Network Name Lookups. 1011s Aug 17 08:58:20 autopkgtest systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. 1011s Aug 17 08:58:21 autopkgtest systemd[1]: Started cloud-init-main.service - Cloud-init: Single Process. 1011s Aug 17 08:58:21 autopkgtest systemd[1]: Starting cloud-init-local.service - Cloud-init: Local Stage (pre-network)... 1011s Aug 17 08:58:21 autopkgtest cloud-init[686]: Cloud-init v. 24.4~2g2e4c39b7-0ubuntu1 running 'init-local' at Sat, 17 Aug 2024 08:58:21 +0000. Up 2.81 seconds. 1011s Aug 17 08:58:21 autopkgtest dhcpcd[689]: dhcpcd-10.0.8 starting 1011s Aug 17 08:58:21 autopkgtest dhcpcd[692]: DUID 00:01:00:01:2e:52:ac:33:fa:16:3e:fd:ff:dd 1011s Aug 17 08:58:21 autopkgtest kernel: 8021q: 802.1Q VLAN Support v1.8 1011s Aug 17 08:58:21 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 1011s Aug 17 08:58:21 autopkgtest kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database 1011s Aug 17 08:58:21 autopkgtest kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' 1011s Aug 17 08:58:21 autopkgtest kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' 1011s Aug 17 08:58:21 autopkgtest dhcpcd[692]: enp0s1: IAID 3e:1a:cf:60 1011s Aug 17 08:58:21 autopkgtest dhcpcd[692]: enp0s1: rebinding lease of 10.145.227.46 1011s Aug 17 08:58:21 autopkgtest dhcpcd[692]: enp0s1: leased 10.145.227.46 for 43200 seconds 1011s Aug 17 08:58:21 autopkgtest dhcpcd[692]: enp0s1: adding route to 10.145.227.0/24 1011s Aug 17 08:58:21 autopkgtest dhcpcd[692]: enp0s1: adding host route to 169.254.169.254 via 10.145.227.2 1011s Aug 17 08:58:21 autopkgtest dhcpcd[692]: enp0s1: adding default route via 10.145.227.1 1011s Aug 17 08:58:21 autopkgtest dhcpcd[692]: control command: /usr/sbin/dhcpcd --dumplease --ipv4only enp0s1 1011s Aug 17 08:58:37 autopkgtest sh[682]: Completed socket interaction for boot stage local 1011s Aug 17 08:58:37 autopkgtest systemd[1]: Finished cloud-init-local.service - Cloud-init: Local Stage (pre-network). 1011s Aug 17 08:58:37 autopkgtest systemd[1]: Reached target network-pre.target - Preparation for Network. 1011s Aug 17 08:58:37 autopkgtest systemd[1]: Starting systemd-networkd.service - Network Configuration... 1011s Aug 17 08:58:37 autopkgtest systemd-networkd[721]: /run/systemd/network/10-netplan-enp0s1.network: MTUBytes= in [Link] section and UseMTU= in [DHCP] section are set. Disabling UseMTU=. 1011s Aug 17 08:58:37 autopkgtest systemd-networkd[721]: lo: Link UP 1011s Aug 17 08:58:37 autopkgtest systemd-networkd[721]: lo: Gained carrier 1011s Aug 17 08:58:37 autopkgtest systemd-networkd[721]: Enumeration completed 1011s Aug 17 08:58:37 autopkgtest systemd-networkd[721]: enp0s1: Link UP 1011s Aug 17 08:58:37 autopkgtest systemd-networkd[721]: enp0s1: Gained carrier 1011s Aug 17 08:58:37 autopkgtest systemd[1]: Started systemd-networkd.service - Network Configuration. 1011s Aug 17 08:58:37 autopkgtest systemd-timesyncd[402]: Network configuration changed, trying to establish connection. 1011s Aug 17 08:58:37 autopkgtest systemd-networkd[721]: enp0s1: Gained IPv6LL 1011s Aug 17 08:58:37 autopkgtest systemd[1]: Reached target network.target - Network. 1011s Aug 17 08:58:37 autopkgtest systemd-networkd[721]: enp0s1: Link DOWN 1011s Aug 17 08:58:37 autopkgtest systemd-networkd[721]: enp0s1: Lost carrier 1011s Aug 17 08:58:37 autopkgtest systemd-timesyncd[402]: No network connectivity, watching for changes. 1011s Aug 17 08:58:37 autopkgtest systemd-networkd[721]: enp0s1: Configuring with /run/systemd/network/10-netplan-enp0s1.network. 1011s Aug 17 08:58:37 autopkgtest systemd[1]: Starting systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd... 1011s Aug 17 08:58:37 autopkgtest systemd-networkd[721]: enp0s1: Link UP 1011s Aug 17 08:58:37 autopkgtest systemd-networkd[721]: enp0s1: Gained carrier 1011s Aug 17 08:58:37 autopkgtest kernel: 8021q: adding VLAN 0 to HW filter on device enp0s1 1011s Aug 17 08:58:37 autopkgtest systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured... 1011s Aug 17 08:58:37 autopkgtest systemd-networkd[721]: enp0s1: DHCPv4 address 10.145.227.46/24, gateway 10.145.227.1 acquired from 10.145.227.1 1011s Aug 17 08:58:37 autopkgtest systemd-timesyncd[402]: Network configuration changed, trying to establish connection. 1011s Aug 17 08:58:37 autopkgtest systemd[1]: Finished systemd-networkd-persistent-storage.service - Enable Persistent Storage in systemd-networkd. 1011s Aug 17 08:58:37 autopkgtest systemd-timesyncd[402]: Contacted time server 91.189.91.157:123 (ntp.ubuntu.com). 1011s Aug 17 08:58:37 autopkgtest systemd-timesyncd[402]: Initial clock synchronization to Sat 2024-08-17 08:58:37.674053 UTC. 1011s Aug 17 08:58:39 autopkgtest systemd-networkd[721]: enp0s1: Gained IPv6LL 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Finished systemd-networkd-wait-online.service - Wait for Network to be Configured. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting cloud-init-network.service - Cloud-init: Network Stage... 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: Cloud-init v. 24.4~2g2e4c39b7-0ubuntu1 running 'init' at Sat, 17 Aug 2024 08:58:39 +0000. Up 21.21 seconds. 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | enp0s1 | True | 10.145.227.46 | 255.255.255.0 | global | fa:16:3e:1a:cf:60 | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | enp0s1 | True | fe80::f816:3eff:fe1a:cf60/64 | . | link | fa:16:3e:1a:cf:60 | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | lo | True | ::1/128 | . | host | . | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: ++++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++++ 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | 0 | 0.0.0.0 | 10.145.227.1 | 0.0.0.0 | enp0s1 | UG | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | 1 | 10.145.227.0 | 0.0.0.0 | 255.255.255.0 | enp0s1 | U | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | 2 | 10.145.227.1 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | 3 | 10.145.227.2 | 0.0.0.0 | 255.255.255.255 | enp0s1 | UH | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | 4 | 91.189.91.131 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | 5 | 91.189.91.132 | 10.145.227.1 | 255.255.255.255 | enp0s1 | UGH | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | 6 | 169.254.169.254 | 10.145.227.2 | 255.255.255.255 | enp0s1 | UGH | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: +-------+-----------------+--------------+-----------------+-----------+-------+ 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: +-------+-------------+---------+-----------+-------+ 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | Route | Destination | Gateway | Interface | Flags | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: +-------+-------------+---------+-----------+-------+ 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | 0 | fe80::/64 | :: | enp0s1 | U | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | 2 | local | :: | enp0s1 | U | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: | 3 | multicast | :: | enp0s1 | U | 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: ci-info: +-------+-------------+---------+-----------+-------+ 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: 2024-08-17 08:58:39,592 - 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. 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: 2024-08-17 08:58:39,592 - schema.py[WARNING]: cloud-config failed schema validation! You may run 'sudo cloud-init schema --system' to check the details. 1011s Aug 17 08:58:39 autopkgtest sh[732]: Completed socket interaction for boot stage network 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Finished cloud-init-network.service - Cloud-init: Network Stage. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Reached target cloud-config.target - Cloud-config availability. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Reached target network-online.target - Network is Online. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Reached target sysinit.target - System Initialization. 1011s Aug 17 08:58:39 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). 1011s Aug 17 08:58:39 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). 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started apt-daily.timer - Daily apt download activities. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started apt-daily-upgrade.timer - Daily apt upgrade and clean activities. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started dpkg-db-backup.timer - Daily dpkg database backup timer. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started fstrim.timer - Discard unused filesystem blocks once a week. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started fwupd-refresh.timer - Refresh fwupd metadata regularly. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started logrotate.timer - Daily rotation of log files. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started man-db.timer - Daily man-db regeneration. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started motd-news.timer - Message of the Day. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started sysstat-collect.timer - Run system activity accounting tool every 10 minutes. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started sysstat-rotate.timer - Rotate daily system activity data file at midnight. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started sysstat-summary.timer - Generate summary of yesterday's process accounting. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. 1011s Aug 17 08:58:39 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). 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Reached target boot-complete.target - Boot Completion Check. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Reached target paths.target - Path Units. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Reached target timers.target - Timer Units. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: apport-forward.socket - Unix socket for apport crash forwarding was skipped because of an unmet condition check (ConditionVirtualization=container). 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Listening on cloud-init-hotplugd.socket - cloud-init hotplug hook socket. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Listening on dbus.socket - D-Bus System Message Bus Socket. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting lxd-installer.socket - Helper to install lxd snap on demand... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Listening on ssh.socket - OpenBSD Secure Shell server socket. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Listening on sshd-unix-local.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Listening on sshd-vsock.socket - OpenSSH Server Socket (systemd-ssh-generator, AF_VSOCK). 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Reached target ssh-access.target - SSH Access Available. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Listening on systemd-hostnamed.socket - Hostname Service Socket. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Listening on uuidd.socket - UUID daemon activation socket. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Listening on lxd-installer.socket - Helper to install lxd snap on demand. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Reached target sockets.target - Socket Units. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Reached target basic.target - Basic System. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: System is tainted: unmerged-bin 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting apport.service - automatic crash report generation... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started autopkgtest@hvc1.service - autopkgtest root shell on hvc1. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started autopkgtest@ttyS1.service - autopkgtest root shell on ttyS1. 1011s Aug 17 08:58:39 autopkgtest (sh)[767]: autopkgtest@hvc1.service: Failed to set up standard input: No such device 1011s Aug 17 08:58:39 autopkgtest (sh)[767]: autopkgtest@hvc1.service: Failed at step STDIN spawning /bin/sh: No such device 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting cloud-config.service - Cloud-init: Config Stage... 1011s Aug 17 08:58:39 autopkgtest (sh)[768]: autopkgtest@ttyS1.service: Failed to set up standard input: Input/output error 1011s Aug 17 08:58:39 autopkgtest (sh)[768]: autopkgtest@ttyS1.service: Failed at step STDIN spawning /bin/sh: Input/output error 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started cron.service - Regular background program processing daemon. 1011s Aug 17 08:58:39 autopkgtest (cron)[770]: cron.service: Referenced but unset environment variable evaluates to an empty string: EXTRA_OPTS 1011s Aug 17 08:58:39 autopkgtest cron[770]: (CRON) INFO (pidfile fd = 3) 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting dbus.service - D-Bus System Message Bus... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started dmesg.service - Save initial kernel messages after boot. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots... 1011s Aug 17 08:58:39 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). 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting grub-common.service - Record successful boot for GRUB... 1011s Aug 17 08:58:39 autopkgtest cron[770]: (CRON) INFO (Running @reboot jobs) 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting iprdump.service - IBM Power Raid dump daemon... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: networkd-dispatcher.service - Dispatcher daemon for systemd-networkd was skipped because no trigger condition checks were met. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: opal_errd.service - opal_errd (PowerNV platform error handling) Service was skipped because of an unmet condition check (ConditionVirtualization=false). 1011s Aug 17 08:58:39 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). 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting rc-local.service - /etc/rc.local Compatibility... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting rng-tools-debian.service - LSB: rng-tools (Debian variant)... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting rsyslog.service - System Logging Service... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting sysstat.service - Resets System Activity Logs... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting systemd-logind.service - User Login Management... 1011s Aug 17 08:58:39 autopkgtest dbus-daemon[771]: [system] AppArmor D-Bus mediation is enabled 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting systemd-user-sessions.service - Permit User Sessions... 1011s Aug 17 08:58:39 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). 1011s Aug 17 08:58:39 autopkgtest systemd[1]: ubuntu-advantage.service - Ubuntu Pro Background Auto Attach was skipped because no trigger condition checks were met. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting udisks2.service - Disk Manager... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started dbus.service - D-Bus System Message Bus. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: autopkgtest@hvc1.service: Deactivated successfully. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: autopkgtest@ttyS1.service: Deactivated successfully. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started iprdump.service - IBM Power Raid dump daemon. 1011s Aug 17 08:58:39 autopkgtest cloud-init[686]: Cloud-init v. 24.4~2g2e4c39b7-0ubuntu1 running 'modules:config' at Sat, 17 Aug 2024 08:58:39 +0000. Up 21.52 seconds. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Finished systemd-user-sessions.service - Permit User Sessions. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started rc-local.service - /etc/rc.local Compatibility. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting iprinit.service - IBM Power Raid init daemon... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting iprupdate.service - IBM Power Raid update daemon... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting plymouth-quit-wait.service - Hold until boot process finishes up... 1011s Aug 17 08:58:39 autopkgtest udisksd[791]: udisks daemon version 2.10.1 starting 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting plymouth-quit.service - Terminate Plymouth Boot Screen... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started rtas_errd.service - ppc64-diag rtas_errd (platform error handling) Service. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Finished sysstat.service - Resets System Activity Logs. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started iprinit.service - IBM Power Raid init daemon. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started iprupdate.service - IBM Power Raid update daemon. 1011s Aug 17 08:58:39 autopkgtest rngd[828]: rngd 2.4 starting up... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started rng-tools-debian.service - LSB: rng-tools (Debian variant). 1011s Aug 17 08:58:39 autopkgtest rngd[828]: entropy feed to the kernel ready 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Finished plymouth-quit-wait.service - Hold until boot process finishes up. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Reached target iprutils.target - IBM Power Raid utilities. 1011s Aug 17 08:58:39 autopkgtest sh[774]: Completed socket interaction for boot stage config 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started serial-getty@hvc0.service - Serial Getty on hvc0. 1011s Aug 17 08:58:39 autopkgtest systemd-logind[787]: New seat seat0. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting setvtrgb.service - Set console scheme... 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Finished cloud-config.service - Cloud-init: Config Stage. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: e2scrub_reap.service: Deactivated successfully. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Finished e2scrub_reap.service - Remove Stale Online ext4 Metadata Check Snapshots. 1011s Aug 17 08:58:39 autopkgtest systemd-logind[787]: Watching system buttons on /dev/input/event0 (QEMU QEMU USB Keyboard) 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Finished plymouth-quit.service - Terminate Plymouth Boot Screen. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started systemd-logind.service - User Login Management. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: grub-common.service: Deactivated successfully. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Finished grub-common.service - Record successful boot for GRUB. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Finished setvtrgb.service - Set console scheme. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Created slice system-getty.slice - Slice /system/getty. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started getty@tty1.service - Getty on tty1. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Reached target getty.target - Login Prompts. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Starting grub-initrd-fallback.service - GRUB failed boot detection... 1011s Aug 17 08:58:39 autopkgtest kernel: kauditd_printk_skb: 108 callbacks suppressed 1011s Aug 17 08:58:39 autopkgtest kernel: audit: type=1400 audit(1723885119.928:119): apparmor="STATUS" operation="profile_replace" info="same as current profile, skipping" profile="unconfined" name="rsyslogd" pid=818 comm="apparmor_parser" 1011s Aug 17 08:58:39 autopkgtest systemd[1]: grub-initrd-fallback.service: Deactivated successfully. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Finished grub-initrd-fallback.service - GRUB failed boot detection. 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started udisks2.service - Disk Manager. 1011s Aug 17 08:58:39 autopkgtest udisksd[791]: Acquired the name org.freedesktop.UDisks2 on the system message bus 1011s Aug 17 08:58:39 autopkgtest rsyslogd[867]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.2406.0] 1011s Aug 17 08:58:39 autopkgtest rsyslogd[867]: rsyslogd's groupid changed to 102 1011s Aug 17 08:58:39 autopkgtest systemd[1]: Started rsyslog.service - System Logging Service. 1011s Aug 17 08:58:39 autopkgtest rsyslogd[867]: rsyslogd's userid changed to 102 1011s Aug 17 08:58:39 autopkgtest rsyslogd[867]: [origin software="rsyslogd" swVersion="8.2406.0" x-pid="867" x-info="https://www.rsyslog.com"] start 1011s Aug 17 08:58:40 autopkgtest systemd[1]: Finished apport.service - automatic crash report generation. 1011s Aug 17 08:58:40 autopkgtest systemd[1]: Reached target multi-user.target - Multi-User System. 1011s Aug 17 08:58:40 autopkgtest systemd[1]: Reached target graphical.target - Graphical Interface. 1011s Aug 17 08:58:40 autopkgtest systemd[1]: Starting cloud-final.service - Cloud-init: Final Stage... 1011s Aug 17 08:58:40 autopkgtest systemd[1]: Starting systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP... 1011s Aug 17 08:58:40 autopkgtest systemd[1]: systemd-update-utmp-runlevel.service: Deactivated successfully. 1011s Aug 17 08:58:40 autopkgtest systemd[1]: Finished systemd-update-utmp-runlevel.service - Record Runlevel Change in UTMP. 1011s Aug 17 08:58:40 autopkgtest cloud-init[686]: Cloud-init v. 24.4~2g2e4c39b7-0ubuntu1 running 'modules:final' at Sat, 17 Aug 2024 08:58:40 +0000. Up 21.83 seconds. 1011s Aug 17 08:58:40 autopkgtest cloud-init[686]: Cloud-init v. 24.4~2g2e4c39b7-0ubuntu1 finished at Sat, 17 Aug 2024 08:58:40 +0000. Datasource DataSourceOpenStackLocal [net,ver=2]. Up 21.90 seconds 1011s Aug 17 08:58:40 autopkgtest sh[881]: Completed socket interaction for boot stage final 1011s Aug 17 08:58:40 autopkgtest systemd[1]: Finished cloud-final.service - Cloud-init: Final Stage. 1011s Aug 17 08:58:40 autopkgtest systemd[1]: Reached target cloud-init.target - Cloud-init target. 1011s Aug 17 08:58:40 autopkgtest systemd[1]: Startup finished in 1.628s (kernel) + 20.285s (userspace) = 21.913s. 1011s Aug 17 08:58:40 autopkgtest kernel: fbcon: Taking over console 1011s Aug 17 08:58:40 autopkgtest kernel: Console: switching to colour frame buffer device 128x48 1011s Aug 17 08:58:40 autopkgtest systemd[1]: cloud-init-main.service: Deactivated successfully. 1011s Aug 17 08:58:40 autopkgtest systemd[1]: cloud-init-main.service: Unit process 685 (sh) remains running after unit stopped. 1011s Aug 17 08:58:40 autopkgtest systemd[1]: cloud-init-main.service: Unit process 686 (tee) remains running after unit stopped. 1011s Aug 17 08:58:40 autopkgtest systemd[1]: cloud-init-main.service: Consumed 1.128s CPU time, 103.5M memory peak. 1011s Aug 17 08:58:40 autopkgtest systemd[1]: dmesg.service: Deactivated successfully. 1011s Aug 17 08:58:41 autopkgtest systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... 1011s Aug 17 08:58:41 autopkgtest sshd[932]: Server listening on :: port 22. 1011s Aug 17 08:58:41 autopkgtest systemd[1]: Started ssh.service - OpenBSD Secure Shell server. 1011s Aug 17 08:58:42 autopkgtest sshd[933]: Accepted publickey for ubuntu from 10.136.6.201 port 60846 ssh2: RSA SHA256:YaYyKWTl9zFJEBK5G3u+MRj3WPJt+vEplFd0J96PUBw 1011s Aug 17 08:58:42 autopkgtest sshd[933]: pam_unix(sshd:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 1011s Aug 17 08:58:42 autopkgtest sshd[933]: pam_systemd(sshd:session): New sd-bus connection (system-bus-pam-systemd-933) opened. 1011s Aug 17 08:58:42 autopkgtest systemd-logind[787]: New session 1 of user ubuntu. 1011s Aug 17 08:58:42 autopkgtest systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. 1011s Aug 17 08:58:42 autopkgtest systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... 1011s Aug 17 08:58:42 autopkgtest systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. 1011s Aug 17 08:58:42 autopkgtest systemd[1]: Starting user@1000.service - User Manager for UID 1000... 1011s Aug 17 08:58:42 autopkgtest (systemd)[937]: pam_unix(systemd-user:session): session opened for user ubuntu(uid=1000) by ubuntu(uid=0) 1011s Aug 17 08:58:42 autopkgtest systemd-logind[787]: New session 2 of user ubuntu. 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Queued start job for default target default.target. 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Created slice app.slice - User Application Slice. 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Started launchpadlib-cache-clean.timer - Clean up old files in the Launchpadlib cache. 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Reached target paths.target - Paths. 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Reached target timers.target - Timers. 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Starting dbus.socket - D-Bus User Message Bus Socket... 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Listening on dirmngr.socket - GnuPG network certificate management daemon. 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Starting gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation)... 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Listening on keyboxd.socket - GnuPG public key management service. 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Listening on dbus.socket - D-Bus User Message Bus Socket. 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Reached target sockets.target - Sockets. 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Reached target basic.target - Basic System. 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Reached target default.target - Main User Target. 1011s Aug 17 08:58:42 autopkgtest systemd[937]: Startup finished in 126ms. 1011s Aug 17 08:58:42 autopkgtest systemd[1]: Started user@1000.service - User Manager for UID 1000. 1011s Aug 17 08:58:42 autopkgtest systemd[1]: Started session-1.scope - Session 1 of User ubuntu. 1011s Aug 17 08:58:43 autopkgtest sudo[965]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/bin/true 1011s Aug 17 08:58:43 autopkgtest sudo[965]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:43 autopkgtest sudo[965]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:43 autopkgtest sudo[970]: 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' 1011s Aug 17 08:58:43 autopkgtest sudo[970]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:43 autopkgtest sudo[970]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:43 autopkgtest sudo[982]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.jpNmps 1011s Aug 17 08:58:43 autopkgtest sudo[982]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:43 autopkgtest sudo[982]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:43 autopkgtest sudo[992]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.jpNmps/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.jpNmps/autopkgtest-reboot' 1011s Aug 17 08:58:43 autopkgtest sudo[992]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:44 autopkgtest sudo[992]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:44 autopkgtest sudo[1004]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.jpNmps/autopkgtest-reboot 1011s Aug 17 08:58:44 autopkgtest sudo[1004]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:44 autopkgtest sudo[1004]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:44 autopkgtest sudo[1014]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.jpNmps/autopkgtest-reboot /tmp/autopkgtest-reboot 1011s Aug 17 08:58:44 autopkgtest sudo[1014]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:44 autopkgtest sudo[1014]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:44 autopkgtest sudo[1024]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.jpNmps/autopkgtest-reboot /sbin/autopkgtest-reboot 1011s Aug 17 08:58:44 autopkgtest sudo[1024]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:44 autopkgtest sudo[1024]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:44 autopkgtest sudo[1034]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.jpNmps 1011s Aug 17 08:58:44 autopkgtest sudo[1034]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:44 autopkgtest sudo[1034]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:44 autopkgtest sudo[1044]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.jpNmps/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.jpNmps/autopkgtest-reboot-prepare' 1011s Aug 17 08:58:44 autopkgtest sudo[1044]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:45 autopkgtest sudo[1044]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:45 autopkgtest sudo[1056]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.jpNmps/autopkgtest-reboot-prepare 1011s Aug 17 08:58:45 autopkgtest sudo[1056]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:45 autopkgtest sudo[1056]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:45 autopkgtest sudo[1066]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.jpNmps/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 1011s Aug 17 08:58:45 autopkgtest sudo[1066]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:45 autopkgtest sudo[1066]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:45 autopkgtest sudo[1076]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 1011s Aug 17 08:58:45 autopkgtest sudo[1076]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:45 autopkgtest sudo[1076]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:45 autopkgtest sudo[1086]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'command -v eatmydata' 1011s Aug 17 08:58:45 autopkgtest sudo[1086]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:45 autopkgtest sudo[1086]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:45 autopkgtest sudo[1096]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.jpNmps/testbed-packages' 1011s Aug 17 08:58:45 autopkgtest sudo[1096]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:45 autopkgtest sudo[1096]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:46 autopkgtest sudo[1107]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat /tmp/autopkgtest.jpNmps/autopkgtest-reboot; chmod +x -- /tmp/autopkgtest.jpNmps/autopkgtest-reboot' 1011s Aug 17 08:58:46 autopkgtest sudo[1128]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:46 autopkgtest sudo[1128]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:46 autopkgtest sudo[1140]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.jpNmps/autopkgtest-reboot 1011s Aug 17 08:58:46 autopkgtest sudo[1140]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:46 autopkgtest sudo[1140]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:47 autopkgtest sudo[1150]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.jpNmps/autopkgtest-reboot /tmp/autopkgtest-reboot 1011s Aug 17 08:58:47 autopkgtest sudo[1150]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:47 autopkgtest sudo[1150]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:47 autopkgtest sudo[1160]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.jpNmps/autopkgtest-reboot /sbin/autopkgtest-reboot 1011s Aug 17 08:58:47 autopkgtest sudo[1160]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:47 autopkgtest sudo[1160]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:47 autopkgtest sudo[1170]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.jpNmps 1011s Aug 17 08:58:47 autopkgtest sudo[1170]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:47 autopkgtest sudo[1170]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:47 autopkgtest sudo[1180]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.jpNmps/autopkgtest-reboot-prepare; chmod +x -- /tmp/autopkgtest.jpNmps/autopkgtest-reboot-prepare' 1011s Aug 17 08:58:47 autopkgtest sudo[1180]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:47 autopkgtest sudo[1180]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:47 autopkgtest sudo[1192]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chmod -R 0755 -- /tmp/autopkgtest.jpNmps/autopkgtest-reboot-prepare 1011s Aug 17 08:58:47 autopkgtest sudo[1192]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:47 autopkgtest sudo[1192]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:48 autopkgtest sudo[1202]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper ln -fns /tmp/autopkgtest.jpNmps/autopkgtest-reboot-prepare /tmp/autopkgtest-reboot-prepare 1011s Aug 17 08:58:48 autopkgtest sudo[1202]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:48 autopkgtest sudo[1202]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:48 autopkgtest sudo[1212]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper uname -srv 1011s Aug 17 08:58:48 autopkgtest sudo[1212]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:48 autopkgtest sudo[1212]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:48 autopkgtest sudo[1222]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper test -w /var/lib/dpkg/status 1011s Aug 17 08:58:48 autopkgtest sudo[1222]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:48 autopkgtest sudo[1222]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:48 autopkgtest sudo[1231]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper mkdir -p /tmp/autopkgtest.jpNmps 1011s Aug 17 08:58:48 autopkgtest sudo[1231]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:48 autopkgtest sudo[1231]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:48 autopkgtest sudo[1241]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat >/tmp/autopkgtest.jpNmps/2-autopkgtest-satdep.deb' 1011s Aug 17 08:58:48 autopkgtest sudo[1241]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:49 autopkgtest sudo[1241]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:49 autopkgtest sudo[1252]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper chown -R ubuntu -- /tmp/autopkgtest.jpNmps/2-autopkgtest-satdep.deb 1011s Aug 17 08:58:49 autopkgtest sudo[1252]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:49 autopkgtest sudo[1252]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:58:49 autopkgtest sudo[1262]: 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.jpNmps/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' 1011s Aug 17 08:58:49 autopkgtest sudo[1262]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:58:54 autopkgtest systemd[1]: Reload requested from client PID 1502 ('systemctl') (unit session-1.scope)... 1011s Aug 17 08:58:54 autopkgtest systemd[1]: Reloading... 1011s Aug 17 08:58:54 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. 1011s Aug 17 08:58:54 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. 1011s Aug 17 08:58:54 autopkgtest systemd[1]: Reloading finished in 217 ms. 1011s Aug 17 08:58:54 autopkgtest systemd[1]: Starting fwupd-refresh.service - Refresh fwupd metadata and update motd... 1011s Aug 17 08:58:54 autopkgtest dbus-daemon[771]: [system] Activating via systemd: service name='org.freedesktop.fwupd' unit='fwupd.service' requested by ':1.11' (uid=990 pid=1545 comm="/usr/bin/fwupdmgr refresh" label="unconfined") 1011s Aug 17 08:58:54 autopkgtest systemd[1]: Starting fwupd.service - Firmware update daemon... 1011s Aug 17 08:58:54 autopkgtest systemd[1]: Reload requested from client PID 1558 ('systemctl') (unit session-1.scope)... 1011s Aug 17 08:58:54 autopkgtest systemd[1]: Reloading... 1011s Aug 17 08:58:54 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. 1011s Aug 17 08:58:54 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. 1011s Aug 17 08:58:54 autopkgtest systemd[1]: Reloading finished in 220 ms. 1011s Aug 17 08:58:54 autopkgtest systemd[1]: Starting tgt.service - (i)SCSI target daemon... 1011s Aug 17 08:58:54 autopkgtest tgtd[1605]: tgtd: iser_ib_init(3431) Failed to initialize RDMA; load kernel modules? 1011s Aug 17 08:58:54 autopkgtest tgtd[1605]: tgtd: work_timer_start(146) use timer_fd based scheduler 1011s Aug 17 08:58:54 autopkgtest tgtd[1605]: tgtd: bs_init(387) use signalfd notification 1011s Aug 17 08:58:55 autopkgtest systemd[1]: Started tgt.service - (i)SCSI target daemon. 1011s Aug 17 08:58:55 autopkgtest systemd[1]: Reload requested from client PID 1638 ('systemctl') (unit session-1.scope)... 1011s Aug 17 08:58:55 autopkgtest systemd[1]: Reloading... 1011s Aug 17 08:58:55 autopkgtest fwupd[1554]: 08:58:55.250 FuMain Daemon ready for requests (locale C.UTF-8) 1011s Aug 17 08:58:55 autopkgtest dbus-daemon[771]: [system] Successfully activated service 'org.freedesktop.fwupd' 1011s Aug 17 08:58:55 autopkgtest fwupdmgr[1545]: Updating lvfs 1011s Aug 17 08:58:55 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. 1011s Aug 17 08:58:55 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. 1011s Aug 17 08:58:55 autopkgtest systemd[1]: Reloading finished in 243 ms. 1011s Aug 17 08:58:55 autopkgtest systemd[1]: fwupd-refresh.service: Main process exited, code=exited, status=1/FAILURE 1011s Aug 17 08:58:55 autopkgtest systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'. 1011s Aug 17 08:58:55 autopkgtest systemd[1]: Failed to start fwupd-refresh.service - Refresh fwupd metadata and update motd. 1011s Aug 17 08:58:55 autopkgtest systemd[1]: Started fwupd.service - Firmware update daemon. 1011s Aug 17 08:58:55 autopkgtest systemd[1]: Reload requested from client PID 1685 ('systemctl') (unit session-1.scope)... 1011s Aug 17 08:58:55 autopkgtest systemd[1]: Reloading... 1011s Aug 17 08:58:55 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. 1011s Aug 17 08:58:55 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. 1011s Aug 17 08:58:55 autopkgtest systemd[1]: Reloading finished in 210 ms. 1011s Aug 17 08:58:55 autopkgtest systemd[1]: Reload requested from client PID 1731 ('systemctl') (unit session-1.scope)... 1011s Aug 17 08:58:55 autopkgtest systemd[1]: Reloading... 1011s Aug 17 08:58:55 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. 1011s Aug 17 08:58:56 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. 1011s Aug 17 08:58:56 autopkgtest systemd[1]: Reloading finished in 235 ms. 1011s Aug 17 08:58:56 autopkgtest systemd[1]: Listening on iscsid.socket - Open-iSCSI iscsid Socket. 1011s Aug 17 08:58:56 autopkgtest systemd[1]: Reload requested from client PID 1782 ('systemctl') (unit session-1.scope)... 1011s Aug 17 08:58:56 autopkgtest systemd[1]: Reloading... 1011s Aug 17 08:58:56 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. 1011s Aug 17 08:58:56 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. 1011s Aug 17 08:58:56 autopkgtest systemd[1]: Reloading finished in 223 ms. 1011s Aug 17 08:58:56 autopkgtest systemd[1]: open-iscsi.service - Login to default iSCSI targets was skipped because no trigger condition checks were met. 1011s Aug 17 08:58:56 autopkgtest systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems. 1011s Aug 17 08:58:56 autopkgtest systemd[1]: Reload requested from client PID 1837 ('systemctl') (unit session-1.scope)... 1011s Aug 17 08:58:56 autopkgtest systemd[1]: Reloading... 1011s Aug 17 08:58:56 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. 1011s Aug 17 08:58:56 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. 1011s Aug 17 08:58:57 autopkgtest systemd[1]: Reloading finished in 237 ms. 1011s Aug 17 08:59:07 autopkgtest sudo[1262]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:59:07 autopkgtest sudo[5280]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg-query --show -f ${Status} multipath-tools 1011s Aug 17 08:59:07 autopkgtest sudo[5280]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:59:07 autopkgtest sudo[5280]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:59:07 autopkgtest sudo[5290]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --status autopkgtest-satdep 1011s Aug 17 08:59:07 autopkgtest sudo[5290]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:59:07 autopkgtest sudo[5290]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:59:07 autopkgtest sudo[5300]: 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 1011s Aug 17 08:59:07 autopkgtest sudo[5300]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:59:08 autopkgtest sudo[5300]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:59:09 autopkgtest sudo[5313]: 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 1011s Aug 17 08:59:09 autopkgtest sudo[5313]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:59:09 autopkgtest sudo[5313]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:59:09 autopkgtest sudo[5325]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper apt-mark manual -qq lsscsi 1011s Aug 17 08:59:09 autopkgtest sudo[5325]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:59:09 autopkgtest sudo[5325]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:59:10 autopkgtest sudo[5337]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper dpkg --purge autopkgtest-satdep 1011s Aug 17 08:59:10 autopkgtest sudo[5337]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:59:10 autopkgtest sudo[5337]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:59:10 autopkgtest sudo[5347]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'dpkg-query --show -f \'${Package}\\t${Version}\\n\' > /tmp/autopkgtest.jpNmps/tgtbasedmpaths-packages.all' 1011s Aug 17 08:59:10 autopkgtest sudo[5347]: pam_unix(sudo:session): session opened for user root(uid=0) by ubuntu(uid=1000) 1011s Aug 17 08:59:10 autopkgtest sudo[5347]: pam_unix(sudo:session): session closed for user root 1011s Aug 17 08:59:10 autopkgtest sudo[5358]: ubuntu : PWD=/home/ubuntu ; USER=root ; COMMAND=/var/tmp/autopkgtest-run-wrapper sh -ec 'cat =64=0.0% 1015s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1015s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1015s issued rwts: total=0,1401,0,0 short=0,0,0,0 dropped=0,0,0,0 1015s latency : target=0, window=0, percentile=100.00%, depth=1 1015s 1015s Run status group 0 (all jobs): 1015s WRITE: bw=153MiB/s (161MB/s), 153MiB/s-153MiB/s (161MB/s-161MB/s), io=87.5MiB (91.8MB), run=571-571msec 1015s 1015s Disk stats (read/write): 1015s dm-0: ios=1/850, sectors=8/108800, merge=0/0, ticks=2/381, in_queue=382, util=80.66%, aggrios=0/350, aggsectors=2/44820, aggrmerge=0/0, aggrticks=0/123, aggrin_queue=124, aggrutil=84.09% 1015s sdd: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 1015s sdb: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 1015s sdc: ios=0/0, sectors=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00% 1015s sda: ios=1/1402, sectors=8/179280, merge=0/0, ticks=2/495, in_queue=496, util=84.09% 1015s + echo Starting the path changes in background 1015s + date +Pre FIO %H:%M:%S.%N 1015s + fio --max-jobs=4 /tmp/autopkgtest.jpNmps/tgtbasedmpaths-artifacts/path-change-check.fio 1015s Starting the path changes in background 1015s Pre FIO 08:59:22.688342555 1015s 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 1015s fio-3.37 1015s Starting 1 thread 1196s + date +Post FIO %H:%M:%S.%N 1196s + echo FIO verify test with changing paths - OK 1196s + echo Report log of background activity 1196s + cat /tmp/autopkgtest.jpNmps/tgtbasedmpaths-artifacts/test-background.log 1196s 1196s verify-phase: (groupid=0, jobs=1): err= 0: pid=5708: Sat Aug 17 09:02:23 2024 1196s read: IOPS=4804, BW=300MiB/s (315MB/s)(52.8GiB/180001msec) 1196s clat (usec): min=82, max=48632, avg=185.71, stdev=162.27 1196s lat (usec): min=82, max=48632, avg=185.80, stdev=162.28 1196s clat percentiles (usec): 1196s | 1.00th=[ 103], 5.00th=[ 119], 10.00th=[ 128], 20.00th=[ 139], 1196s | 30.00th=[ 147], 40.00th=[ 157], 50.00th=[ 167], 60.00th=[ 178], 1196s | 70.00th=[ 186], 80.00th=[ 200], 90.00th=[ 223], 95.00th=[ 251], 1196s | 99.00th=[ 816], 99.50th=[ 889], 99.90th=[ 1565], 99.95th=[ 1827], 1196s | 99.99th=[ 2933] 1196s bw ( KiB/s): min=81280, max=443776, per=100.00%, avg=307881.51, stdev=46073.00, samples=359 1196s iops : min= 1270, max= 6934, avg=4810.59, stdev=719.87, samples=359 1196s lat (usec) : 100=0.61%, 250=94.31%, 500=2.84%, 750=0.73%, 1000=1.19% 1196s lat (msec) : 2=0.27%, 4=0.03%, 10=0.01%, 20=0.01%, 50=0.01% 1196s cpu : usr=11.78%, sys=6.53%, ctx=864928, majf=0, minf=1 1196s IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% 1196s submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1196s complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% 1196s issued rwts: total=864741,0,0,0 short=0,0,0,0 dropped=0,0,0,0 1196s latency : target=0, window=0, percentile=100.00%, depth=1 1196s 1196s Run status group 0 (all jobs): 1196s READ: bw=300MiB/s (315MB/s), 300MiB/s-300MiB/s (315MB/s-315MB/s), io=52.8GiB (56.7GB), run=180001-180001msec 1196s 1196s Disk stats (read/write): 1196s dm-0: ios=864942/13, sectors=110633272/12960, merge=32/10, ticks=165064/81, in_queue=165194, util=100.00%, aggrios=56290/3, aggsectors=7199822/3240, aggrmerge=0/0, aggrticks=10353/7, aggrin_queue=10361, aggrutil=99.10% 1196s sdd: ios=87287/0, sectors=11164672/0, merge=0/0, ticks=16718/0, in_queue=16718, util=39.78% 1196s sdb: ios=49146/0, sectors=6285880/0, merge=0/0, ticks=8282/0, in_queue=8282, util=50.13% 1196s sdc: ios=49826/0, sectors=6373120/0, merge=0/0, ticks=8081/0, in_queue=8082, util=33.10% 1196s sda: ios=38901/12, sectors=4975616/12960, merge=0/0, ticks=8332/31, in_queue=8364, util=99.10% 1196s Post FIO 09:02:23.030538401 1196s FIO verify test with changing paths - OK 1196s Report log of background activity 1196s + sync 1196s + umount /dev/disk/by-id/wwn-0x60000000000000000e00000000010001 1196s + echo Final stats 1196s + iscsiadm --mode session --stats 1196s + journalctl --no-pager -u multipathd 1196s + echo Check final path status 1196s + multipath -ll 1196s + multipath -ll 1196s + grep --count status= 1196s + diskc=2 1196s + multipath -ll 1196s + grep --count status=active 1196s + iscsiadm --mode session 1196s tcp: [1] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s + sleep 10s 1196s + date +MP report (expect 4) %H:%M:%S.%N 1196s MP report (expect 4) 08:59:32.695465060 1196s + multipath -ll 1196s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1196s size=100M features='0' hwhandler='0' wp=rw 1196s |-+- policy='service-time 0' prio=1 status=active 1196s | `- 0:0:0:1 sda 8:0 active ready running 1196s |-+- policy='service-time 0' prio=1 status=enabled 1196s | `- 1:0:0:1 sdb 8:16 active ready running 1196s |-+- policy='service-time 0' prio=1 status=enabled 1196s | `- 2:0:0:1 sdc 8:32 active ready running 1196s `-+- policy='service-time 0' prio=1 status=enabled 1196s `- 3:0:0:1 sdd 8:48 active ready running 1196s + date +UN-plug path 1 %H:%M:%S.%N 1196s UN-plug path 1 08:59:32.720209893 1196s + iscsiadm --mode session -r 1 -u 1196s Logging out of session [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1196s Logout of [sid: 1, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1196s + iscsiadm --mode session 1196s tcp: [2] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s + sleep 10s 1196s + date +MP report (expect 3) %H:%M:%S.%N 1196s MP report (expect 3) 08:59:42.804497487 1196s + multipath -ll 1196s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1196s size=100M features='0' hwhandler='0' wp=rw 1196s |-+- policy='service-time 0' prio=1 status=active 1196s | `- 1:0:0:1 sdb 8:16 active ready running 1196s |-+- policy='service-time 0' prio=1 status=enabled 1196s | `- 2:0:0:1 sdc 8:32 active ready running 1196s `-+- policy='service-time 0' prio=1 status=enabled 1196s `- 3:0:0:1 sdd 8:48 active ready running 1196s + date +UN-plug path 2 %H:%M:%S.%N 1196s UN-plug path 2 08:59:42.824984647 1196s + iscsiadm --mode session -r 2 -u 1196s Logging out of session [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1196s Logout of [sid: 2, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1196s + iscsiadm --mode session 1196s tcp: [3] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s + sleep 10s 1196s + date +MP report (expect 2) %H:%M:%S.%N 1196s MP report (expect 2) 08:59:52.919889640 1196s + multipath -ll 1196s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1196s size=100M features='0' hwhandler='0' wp=rw 1196s |-+- policy='service-time 0' prio=1 status=active 1196s | `- 2:0:0:1 sdc 8:32 active ready running 1196s `-+- policy='service-time 0' prio=1 status=enabled 1196s `- 3:0:0:1 sdd 8:48 active ready running 1196s + date +UN-plug path 3 %H:%M:%S.%N 1196s UN-plug path 3 08:59:52.934700425 1196s + iscsiadm --mode session -r 3 -u 1196s Logging out of session [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1196s Logout of [sid: 3, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1196s + iscsiadm --mode session 1196s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s + sleep 10s 1196s + date +MP report (expect 1) %H:%M:%S.%N 1196s MP report (expect 1) 09:00:03.035455440 1196s + multipath -ll 1196s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1196s size=100M features='0' hwhandler='0' wp=rw 1196s `-+- policy='service-time 0' prio=1 status=active 1196s `- 3:0:0:1 sdd 8:48 active ready running 1196s + date +Add paths 5/6/7/8 %H:%M:%S.%N 1196s Add paths 5/6/7/8 09:00:03.047580656 1196s + iscsiadm --mode session -r 4 --op new 1196s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1196s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1196s + iscsiadm --mode session -r 4 --op new 1196s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1196s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1196s + iscsiadm --mode session -r 4 --op new 1196s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1196s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1196s + iscsiadm --mode session -r 4 --op new 1196s Logging in to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] (multiple) 1196s Login to [iface: default, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1196s + iscsiadm --mode session 1196s tcp: [4] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s tcp: [7] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s tcp: [8] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s + sleep 10s 1196s + date +MP report (expect 5) %H:%M:%S.%N 1196s MP report (expect 5) 09:00:13.137188959 1196s + multipath -ll 1196s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1196s size=100M features='0' hwhandler='0' wp=rw 1196s |-+- policy='service-time 0' prio=1 status=active 1196s | `- 3:0:0:1 sdd 8:48 active ready running 1196s |-+- policy='service-time 0' prio=1 status=enabled 1196s | `- 0:0:0:1 sda 8:0 active ready running 1196s |-+- policy='service-time 0' prio=1 status=enabled 1196s | `- 1:0:0:1 sdb 8:16 active ready running 1196s |-+- policy='service-time 0' prio=1 status=enabled 1196s | `- 2:0:0:1 sdc 8:32 active ready running 1196s `-+- policy='service-time 0' prio=1 status=enabled 1196s `- 4:0:0:1 sde 8:64 active ready running 1196s + date +UN-plug multiple paths 4/7/8 %H:%M:%S.%N 1196s UN-plug multiple paths 4/7/8 09:00:13.162334966 1196s + iscsiadm --mode session -r 4 -u 1196s Logging out of session [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1196s Logout of [sid: 4, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1196s + iscsiadm --mode session -r 7 -u 1196s Logging out of session [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1196s Logout of [sid: 7, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1196s + iscsiadm --mode session -r 8 -u 1196s Logging out of session [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1196s Logout of [sid: 8, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1196s + iscsiadm --mode session 1196s tcp: [5] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s tcp: [6] 127.0.0.1:3260,1 iqn.2016-11.foo.com:target.iscsi (non-flash) 1196s + sleep 10s 1196s + date +Restart multipath daemon %H:%M:%S.%N 1196s Restart multipath daemon 09:00:23.448505346 1196s + systemctl restart multipathd 1196s + sleep 10s 1196s + date +Final background report (expect 2) %H:%M:%S.%N 1196s Final background report (expect 2) 09:00:33.536258805 1196s + multipath -ll 1196s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1196s size=100M features='0' hwhandler='0' wp=rw 1196s |-+- policy='service-time 0' prio=1 status=active 1196s | `- 0:0:0:1 sda 8:0 active ready running 1196s `-+- policy='service-time 0' prio=1 status=enabled 1196s `- 1:0:0:1 sdb 8:16 active ready running 1196s Final stats 1196s Stats for session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1196s iSCSI SNMP: 1196s txdata_octets: 30614424 1196s rxdata_octets: 41776052228 1196s noptx_pdus: 0 1196s scsicmd_pdus: 637533 1196s tmfcmd_pdus: 0 1196s login_pdus: 0 1196s text_pdus: 0 1196s dataout_pdus: 0 1196s logout_pdus: 0 1196s snack_pdus: 0 1196s noprx_pdus: 0 1196s scsirsp_pdus: 637533 1196s tmfrsp_pdus: 0 1196s textrsp_pdus: 0 1196s datain_pdus: 637500 1196s logoutrsp_pdus: 0 1196s r2t_pdus: 0 1196s async_pdus: 0 1196s rjt_pdus: 0 1196s digest_err: 0 1196s timeout_err: 0 1196s iSCSI Extended: 1196s tx_sendpage_failures: 0 1196s rx_discontiguous_hdr: 0 1196s eh_abort_cnt: 0 1196s Stats for session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1196s iSCSI SNMP: 1196s txdata_octets: 6504 1196s rxdata_octets: 1580500 1196s noptx_pdus: 0 1196s scsicmd_pdus: 106 1196s tmfcmd_pdus: 0 1196s login_pdus: 0 1196s text_pdus: 0 1196s dataout_pdus: 0 1196s logout_pdus: 0 1196s snack_pdus: 0 1196s noprx_pdus: 0 1196s scsirsp_pdus: 106 1196s tmfrsp_pdus: 0 1196s textrsp_pdus: 0 1196s datain_pdus: 84 1196s logoutrsp_pdus: 0 1196s r2t_pdus: 0 1196s async_pdus: 0 1196s rjt_pdus: 0 1196s digest_err: 0 1196s timeout_err: 0 1196s iSCSI Extended: 1196s tx_sendpage_failures: 0 1196s rx_discontiguous_hdr: 0 1196s eh_abort_cnt: 0 1196s Aug 17 00:32:50 ubuntu systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1196s Aug 17 00:32:50 ubuntu multipathd[361]: multipathd v0.9.4: start up 1196s Aug 17 00:32:50 ubuntu multipathd[361]: reconfigure: setting up paths and maps 1196s Aug 17 00:32:50 ubuntu systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1196s Aug 17 00:35:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[361]: multipathd: shut down 1196s Aug 17 00:35:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1196s Aug 17 00:35:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 1196s Aug 17 00:35:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1196s Aug 17 00:35:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1196s Aug 17 00:35:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[11840]: multipathd v0.9.4: start up 1196s Aug 17 00:35:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[11840]: reconfigure: setting up paths and maps 1196s Aug 17 00:35:06 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1196s Aug 17 00:38:36 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[11840]: multipathd: shut down 1196s Aug 17 00:38:36 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1196s Aug 17 00:38:36 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 1196s Aug 17 00:38:36 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1196s -- Boot 479edfd2b5fb42f99d821d06fc6337df -- 1196s Aug 17 00:38:48 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1196s Aug 17 00:38:48 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[299]: multipathd v0.9.9: start up 1196s Aug 17 00:38:48 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[299]: reconfigure: setting up paths and maps 1196s Aug 17 00:38:48 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1196s Aug 17 00:39:04 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1196s Aug 17 00:39:04 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[299]: multipathd: shut down 1196s Aug 17 00:39:04 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: multipathd.service: Deactivated successfully. 1196s Aug 17 00:39:04 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1196s -- Boot 151feb3e5eeb4f26896e201ac2ad26ea -- 1196s Aug 17 08:57:09 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[311]: multipathd v0.9.9: start up 1196s Aug 17 08:57:09 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i multipathd[311]: reconfigure: setting up paths and maps 1196s Aug 17 08:57:09 auto-syncubuntu-oracular-daily-ppc64el-server-20240719-disk1-i systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1196s Aug 17 08:58:08 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1196s Aug 17 08:58:08 autopkgtest multipathd[311]: multipathd: shut down 1196s Aug 17 08:58:08 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 1196s Aug 17 08:58:08 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1196s -- Boot 46c34ccc328943fd8a73455441c89211 -- 1196s Aug 17 08:58:20 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1196s Aug 17 08:58:20 autopkgtest multipathd[331]: multipathd v0.9.9: start up 1196s Aug 17 08:58:20 autopkgtest multipathd[331]: reconfigure: setting up paths and maps 1196s Aug 17 08:58:20 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1196s Aug 17 08:59:13 autopkgtest multipathd[331]: updated bindings file /etc/multipath/bindings 1196s Aug 17 08:59:13 autopkgtest multipathd[331]: mpatha: addmap [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:0 1] 1196s Aug 17 08:59:13 autopkgtest multipathd[331]: sda [8:0]: path added to devmap mpatha 1196s Aug 17 08:59:13 autopkgtest multipathd[331]: mpatha: performing delayed actions 1196s Aug 17 08:59:13 autopkgtest multipathd[331]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 1196s Aug 17 08:59:32 autopkgtest multipathd[331]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 1196s Aug 17 08:59:32 autopkgtest multipathd[331]: check_removed_paths: sda: freeing path in removed state 1196s Aug 17 08:59:32 autopkgtest multipathd[331]: 8:0: path removed from map mpatha 1196s Aug 17 08:59:42 autopkgtest multipathd[331]: sdb: mark as failed 1196s Aug 17 08:59:42 autopkgtest multipathd[331]: mpatha: remaining active paths: 2 1196s Aug 17 08:59:42 autopkgtest multipathd[331]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:48 1] 1196s Aug 17 08:59:42 autopkgtest multipathd[331]: check_removed_paths: sdb: freeing path in removed state 1196s Aug 17 08:59:42 autopkgtest multipathd[331]: 8:16: path removed from map mpatha 1196s Aug 17 08:59:52 autopkgtest multipathd[331]: mpatha: reload [0 204800 multipath 0 0 1 1 service-time 0 1 1 8:48 1] 1196s Aug 17 08:59:52 autopkgtest multipathd[331]: check_removed_paths: sdc: freeing path in removed state 1196s Aug 17 08:59:52 autopkgtest multipathd[331]: 8:32: path removed from map mpatha 1196s Aug 17 09:00:03 autopkgtest multipathd[331]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1] 1196s Aug 17 09:00:03 autopkgtest multipathd[331]: sda [8:0]: path added to devmap mpatha 1196s Aug 17 09:00:03 autopkgtest multipathd[331]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 1196s Aug 17 09:00:03 autopkgtest multipathd[331]: sdb [8:16]: path added to devmap mpatha 1196s Aug 17 09:00:03 autopkgtest multipathd[331]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1] 1196s Aug 17 09:00:03 autopkgtest multipathd[331]: sdc [8:32]: path added to devmap mpatha 1196s Aug 17 09:00:03 autopkgtest multipathd[331]: mpatha: reload [0 204800 multipath 0 0 5 1 service-time 0 1 1 8:48 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 1196s Aug 17 09:00:03 autopkgtest multipathd[331]: sde [8:64]: path added to devmap mpatha 1196s Aug 17 09:00:13 autopkgtest multipathd[331]: mpatha: reload [0 204800 multipath 0 0 4 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:32 1 service-time 0 1 1 8:64 1] 1196s Aug 17 09:00:13 autopkgtest multipathd[331]: check_removed_paths: sdd: freeing path in removed state 1196s Aug 17 09:00:13 autopkgtest multipathd[331]: 8:48: path removed from map mpatha 1196s Aug 17 09:00:13 autopkgtest multipathd[331]: mpatha: reload [0 204800 multipath 0 0 3 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1 service-time 0 1 1 8:64 1] 1196s Aug 17 09:00:13 autopkgtest multipathd[331]: check_removed_paths: sdc: freeing path in removed state 1196s Aug 17 09:00:13 autopkgtest multipathd[331]: 8:32: path removed from map mpatha 1196s Aug 17 09:00:13 autopkgtest multipathd[331]: mpatha: reload [0 204800 multipath 0 0 2 1 service-time 0 1 1 8:0 1 service-time 0 1 1 8:16 1] 1196s Aug 17 09:00:13 autopkgtest multipathd[331]: check_removed_paths: sde: freeing path in removed state 1196s Aug 17 09:00:13 autopkgtest multipathd[331]: 8:64: path removed from map mpatha 1196s Aug 17 09:00:23 autopkgtest multipathd[331]: multipathd: shut down 1196s Aug 17 09:00:23 autopkgtest systemd[1]: Stopping multipathd.service - Device-Mapper Multipath Device Controller... 1196s Aug 17 09:00:23 autopkgtest systemd[1]: multipathd.service: Deactivated successfully. 1196s Aug 17 09:00:23 autopkgtest systemd[1]: Stopped multipathd.service - Device-Mapper Multipath Device Controller. 1196s Aug 17 09:00:23 autopkgtest systemd[1]: Starting multipathd.service - Device-Mapper Multipath Device Controller... 1196s Aug 17 09:00:23 autopkgtest multipathd[6082]: multipathd v0.9.9: start up 1196s Aug 17 09:00:23 autopkgtest multipathd[6082]: reconfigure: setting up paths and maps 1196s Aug 17 09:00:23 autopkgtest systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller. 1196s Check final path status 1196s mpatha (360000000000000000e00000000010001) dm-0 IET,VIRTUAL-DISK 1196s size=100M features='0' hwhandler='0' wp=rw 1196s |-+- policy='service-time 0' prio=1 status=active 1196s | `- 0:0:0:1 sda 8:0 active ready running 1196s `-+- policy='service-time 0' prio=1 status=enabled 1196s `- 1:0:0:1 sdb 8:16 active ready running 1196s + diska=1 1196s + multipath -ll 1196s + grep --count status=enabled 1196s + diske=1 1196s + [ 2 -ne 2 -o 1 -ne 1 -o 1 -ne 1 ] 1196s + echo OK 1196s + iscsiadm --mode node --targetname iqn.2016-11.foo.com:target.iscsi --portal 127.0.0.1:3260 --logout 1196s OK 1196s Logging out of session [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1196s Logging out of session [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] 1196s Logout of [sid: 5, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1196s Logout of [sid: 6, target: iqn.2016-11.foo.com:target.iscsi, portal: 127.0.0.1,3260] successful. 1196s + tgtadm --lld iscsi --op delete --mode logicalunit --tid 1 --lun 1 1196s autopkgtest [09:02:23]: test tgtbasedmpaths: -----------------------] 1197s tgtbasedmpaths PASS 1197s autopkgtest [09:02:24]: test tgtbasedmpaths: - - - - - - - - - - results - - - - - - - - - - 1197s autopkgtest [09:02:24]: @@@@@@@@@@@@@@@@@@@@ summary 1197s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 1197s initramfs SKIP Test lists explicitly supported architectures, but the current architecture ppc64el isn't listed. 1197s kpartx-file-loopback PASS 1197s tgtbasedmpaths PASS 1202s nova [W] Using flock in prodstack6-ppc64el 1202s flock: timeout while waiting to get lock 1202s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240817-084217-juju-7f2275-prod-proposed-migration-environment-3-83d83c4d-6e0a-4796-83a0-5527afd8e190 from image adt/ubuntu-oracular-ppc64el-server-20240817.img (UUID 25ee6b42-341e-4fe4-96e9-60187b363f19)... 1202s nova [W] Using flock in prodstack6-ppc64el 1202s Creating nova instance adt-oracular-ppc64el-multipath-tools-20240817-084217-juju-7f2275-prod-proposed-migration-environment-3-83d83c4d-6e0a-4796-83a0-5527afd8e190 from image adt/ubuntu-oracular-ppc64el-server-20240817.img (UUID 25ee6b42-341e-4fe4-96e9-60187b363f19)...