0s autopkgtest [18:35:43]: starting date and time: 2025-10-18 18:35:43+0000 0s autopkgtest [18:35:43]: git checkout: 4b346b80 nova: make wait_reboot return success even when a no-op 0s autopkgtest [18:35:43]: host juju-7f2275-prod-proposed-migration-environment-15; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.charimvn/out --timeout-copy=6000 --setup-commands /home/ubuntu/autopkgtest-cloud/worker-config-production/setup-canonical.sh --apt-pocket=proposed=src:python3-defaults --apt-upgrade fatrace --timeout-short=300 --timeout-copy=20000 --timeout-build=20000 --env=ADT_TEST_TRIGGERS=python3-defaults/3.13.7-2 -- ssh -s /home/ubuntu/autopkgtest/ssh-setup/nova -- --flavor autopkgtest-ppc64el --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-15@bos03-ppc64el-5.secgroup --name adt-resolute-ppc64el-fatrace-20251018-183543-juju-7f2275-prod-proposed-migration-environment-15-4e20812d-3274-496c-81ba-c429ccae8c59 --image adt/ubuntu-resolute-ppc64el-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-15 --net-id=net_prod-proposed-migration-ppc64el -e TERM=linux --mirror=http://ftpmaster.internal/ubuntu/ 4s Creating nova instance adt-resolute-ppc64el-fatrace-20251018-183543-juju-7f2275-prod-proposed-migration-environment-15-4e20812d-3274-496c-81ba-c429ccae8c59 from image adt/ubuntu-resolute-ppc64el-server-20251018.img (UUID 746a0a80-14f1-4bf7-89b6-cbb5ab236a4e)... 54s autopkgtest [18:36:37]: testbed dpkg architecture: ppc64el 54s autopkgtest [18:36:37]: testbed apt version: 3.1.8ubuntu1 54s autopkgtest [18:36:37]: @@@@@@@@@@@@@@@@@@@@ test bed setup 55s autopkgtest [18:36:38]: testbed release detected to be: None 55s autopkgtest [18:36:38]: updating testbed package index (apt update) 56s Get:1 http://ftpmaster.internal/ubuntu resolute-proposed InRelease [83.3 kB] 56s Hit:2 http://ftpmaster.internal/ubuntu resolute InRelease 56s Hit:3 http://ftpmaster.internal/ubuntu resolute-updates InRelease 56s Hit:4 http://ftpmaster.internal/ubuntu resolute-security InRelease 56s Get:5 http://ftpmaster.internal/ubuntu resolute-proposed/restricted Sources [5028 B] 56s Get:6 http://ftpmaster.internal/ubuntu resolute-proposed/universe Sources [456 kB] 57s Get:7 http://ftpmaster.internal/ubuntu resolute-proposed/main Sources [50.7 kB] 57s Get:8 http://ftpmaster.internal/ubuntu resolute-proposed/multiverse Sources [16.7 kB] 57s Get:9 http://ftpmaster.internal/ubuntu resolute-proposed/main ppc64el Packages [92.0 kB] 57s Get:10 http://ftpmaster.internal/ubuntu resolute-proposed/restricted ppc64el Packages [940 B] 57s Get:11 http://ftpmaster.internal/ubuntu resolute-proposed/universe ppc64el Packages [317 kB] 57s Get:12 http://ftpmaster.internal/ubuntu resolute-proposed/multiverse ppc64el Packages [4660 B] 57s Fetched 1026 kB in 1s (834 kB/s) 58s Reading package lists... 58s Failed to check for VM: Permission denied 59s Hit:1 http://ftpmaster.internal/ubuntu resolute-proposed InRelease 59s Hit:2 http://ftpmaster.internal/ubuntu resolute InRelease 59s Hit:3 http://ftpmaster.internal/ubuntu resolute-updates InRelease 59s Hit:4 http://ftpmaster.internal/ubuntu resolute-security InRelease 60s Reading package lists... 60s Reading package lists... 60s Building dependency tree... 60s Reading state information... 60s Calculating upgrade... 60s The following packages will be upgraded: 60s gir1.2-girepository-2.0 libgirepository-1.0-1 libpython3-stdlib python3 60s python3-minimal 60s 5 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 60s Need to get 185 kB of archives. 60s After this operation, 2048 B of additional disk space will be used. 60s Get:1 http://ftpmaster.internal/ubuntu resolute-proposed/main ppc64el python3-minimal ppc64el 3.13.7-2 [27.8 kB] 60s Get:2 http://ftpmaster.internal/ubuntu resolute-proposed/main ppc64el python3 ppc64el 3.13.7-2 [23.9 kB] 60s Get:3 http://ftpmaster.internal/ubuntu resolute-proposed/main ppc64el libpython3-stdlib ppc64el 3.13.7-2 [10.6 kB] 60s Get:4 http://ftpmaster.internal/ubuntu resolute/main ppc64el libgirepository-1.0-1 ppc64el 1.86.0-6 [97.4 kB] 60s Get:5 http://ftpmaster.internal/ubuntu resolute/main ppc64el gir1.2-girepository-2.0 ppc64el 1.86.0-6 [25.3 kB] 61s dpkg-preconfigure: unable to re-open stdin: No such file or directory 61s Fetched 185 kB in 0s (440 kB/s) 61s (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 ... 76461 files and directories currently installed.) 61s Preparing to unpack .../python3-minimal_3.13.7-2_ppc64el.deb ... 61s Unpacking python3-minimal (3.13.7-2) over (3.13.7-1) ... 61s Setting up python3-minimal (3.13.7-2) ... 61s (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 ... 76461 files and directories currently installed.) 61s Preparing to unpack .../python3_3.13.7-2_ppc64el.deb ... 61s running python pre-rtupdate hooks for python3.13... 61s Unpacking python3 (3.13.7-2) over (3.13.7-1) ... 61s Preparing to unpack .../libpython3-stdlib_3.13.7-2_ppc64el.deb ... 61s Unpacking libpython3-stdlib:ppc64el (3.13.7-2) over (3.13.7-1) ... 61s Preparing to unpack .../libgirepository-1.0-1_1.86.0-6_ppc64el.deb ... 61s Unpacking libgirepository-1.0-1:ppc64el (1.86.0-6) over (1.84.0-1) ... 61s Preparing to unpack .../gir1.2-girepository-2.0_1.86.0-6_ppc64el.deb ... 61s Unpacking gir1.2-girepository-2.0:ppc64el (1.86.0-6) over (1.84.0-1) ... 62s Setting up libgirepository-1.0-1:ppc64el (1.86.0-6) ... 62s Setting up libpython3-stdlib:ppc64el (3.13.7-2) ... 62s Setting up python3 (3.13.7-2) ... 62s running python rtupdate hooks for python3.13... 62s running python post-rtupdate hooks for python3.13... 62s Setting up gir1.2-girepository-2.0:ppc64el (1.86.0-6) ... 62s Processing triggers for man-db (2.13.1-1) ... 62s Processing triggers for libc-bin (2.42-0ubuntu3) ... 62s autopkgtest [18:36:45]: upgrading testbed (apt dist-upgrade and autopurge) 63s Reading package lists... 63s Building dependency tree... 63s Reading state information... 63s Calculating upgrade... 63s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 63s Reading package lists... 64s Building dependency tree... 64s Reading state information... 64s Solving dependencies... 64s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 66s autopkgtest [18:36:49]: testbed running kernel: Linux 6.17.0-5-generic #5-Ubuntu SMP PREEMPT_DYNAMIC Mon Sep 22 10:02:41 UTC 2025 66s autopkgtest [18:36:49]: @@@@@@@@@@@@@@@@@@@@ apt-source fatrace 68s Get:1 http://ftpmaster.internal/ubuntu resolute/universe fatrace 0.18.0-1 (dsc) [1888 B] 68s Get:2 http://ftpmaster.internal/ubuntu resolute/universe fatrace 0.18.0-1 (tar) [26.2 kB] 68s Get:3 http://ftpmaster.internal/ubuntu resolute/universe fatrace 0.18.0-1 (diff) [3772 B] 68s gpgv: Signature made Sun Jan 19 11:08:15 2025 UTC 68s gpgv: using RSA key 6C4B878B7E631F160557C3CDEE7BDDE4B86B5713 68s gpgv: Can't check signature: No public key 68s dpkg-source: warning: cannot verify inline signature for ./fatrace_0.18.0-1.dsc: no acceptable signature found 68s autopkgtest [18:36:51]: testing package fatrace version 0.18.0-1 69s autopkgtest [18:36:52]: build not needed 69s autopkgtest [18:36:52]: test fatrace: preparing testbed 69s Reading package lists... 69s Building dependency tree... 69s Reading state information... 69s Solving dependencies... 70s The following NEW packages will be installed: 70s fatrace 70s 0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 70s Need to get 14.7 kB of archives. 70s After this operation, 89.1 kB of additional disk space will be used. 70s Get:1 http://ftpmaster.internal/ubuntu resolute/universe ppc64el fatrace ppc64el 0.18.0-1 [14.7 kB] 70s Fetched 14.7 kB in 0s (68.0 kB/s) 70s Selecting previously unselected package fatrace. 70s (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 ... 76461 files and directories currently installed.) 70s Preparing to unpack .../fatrace_0.18.0-1_ppc64el.deb ... 70s Unpacking fatrace (0.18.0-1) ... 70s Setting up fatrace (0.18.0-1) ... 70s Processing triggers for man-db (2.13.1-1) ... 72s autopkgtest [18:36:55]: test fatrace: [----------------------- 72s starting fatrace... 73s read a file... 73s create a file... 73s waiting for fatrace... 74s checking log... 74s RC\?O\? \+/usr/bin/head$ not found in log 74s autopkgtest [18:36:57]: test fatrace: -----------------------] 75s fatrace FAIL stderr: RC\?O\? \+/usr/bin/head$ not found in log 75s autopkgtest [18:36:58]: test fatrace: - - - - - - - - - - results - - - - - - - - - - 75s autopkgtest [18:36:58]: test fatrace: - - - - - - - - - - stderr - - - - - - - - - - 75s RC\?O\? \+/usr/bin/head$ not found in log 75s autopkgtest [18:36:58]: test fatrace-currentmount: preparing testbed 76s Reading package lists... 76s Building dependency tree... 76s Reading state information... 76s Solving dependencies... 76s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 77s autopkgtest [18:37:00]: test fatrace-currentmount: [----------------------- 77s starting fatrace... 78s read a file... 78s create a file... 78s moving a file within the same directory 78s robustness against ELOOP 78s waiting for fatrace... 79s checking log... 79s ^rm(.*): D /tmp/autopkgtest.c9M14R/build.3rG/src$ not found in log 79s ^mv(.*): <>\? \+/tmp/autopkgtest.c9M14R/build.3rG/src not found in log 79s ^mv(.*): <\?> \+/tmp/autopkgtest.c9M14R/build.3rG/src not found in log 79s ^mv(.*): < /tmp/autopkgtest.c9M14R/build.3rG/src$ not found in log 79s ^mv(.*): > /tmp/autopkgtest.c9M14R/build.3rG/src/dest$ not found in log 79s ^rm(.*): D /tmp/autopkgtest.c9M14R/build.3rG/src$ not found in log 79s autopkgtest [18:37:02]: test fatrace-currentmount: -----------------------] 80s autopkgtest [18:37:03]: test fatrace-currentmount: - - - - - - - - - - results - - - - - - - - - - 80s fatrace-currentmount FAIL stderr: ^rm(.*): D /tmp/autopkgtest.c9M14R/build.3rG/src$ not found in log 80s autopkgtest [18:37:03]: test fatrace-currentmount: - - - - - - - - - - stderr - - - - - - - - - - 80s ^rm(.*): D /tmp/autopkgtest.c9M14R/build.3rG/src$ not found in log 80s ^mv(.*): <>\? \+/tmp/autopkgtest.c9M14R/build.3rG/src not found in log 80s ^mv(.*): <\?> \+/tmp/autopkgtest.c9M14R/build.3rG/src not found in log 80s ^mv(.*): < /tmp/autopkgtest.c9M14R/build.3rG/src$ not found in log 80s ^mv(.*): > /tmp/autopkgtest.c9M14R/build.3rG/src/dest$ not found in log 80s ^rm(.*): D /tmp/autopkgtest.c9M14R/build.3rG/src$ not found in log 80s autopkgtest [18:37:03]: test power-usage-report: preparing testbed 81s Reading package lists... 81s Building dependency tree... 81s Reading state information... 81s Solving dependencies... 81s The following NEW packages will be installed: 81s libnl-genl-3-200 powertop 81s 0 upgraded, 2 newly installed, 0 to remove and 0 not upgraded. 81s Need to get 221 kB of archives. 81s After this operation, 790 kB of additional disk space will be used. 81s Get:1 http://ftpmaster.internal/ubuntu resolute/main ppc64el libnl-genl-3-200 ppc64el 3.7.0-2build1 [13.9 kB] 81s Get:2 http://ftpmaster.internal/ubuntu resolute/main ppc64el powertop ppc64el 2.15-4 [207 kB] 82s Fetched 221 kB in 0s (450 kB/s) 82s Selecting previously unselected package libnl-genl-3-200:ppc64el. 82s (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 ... 76467 files and directories currently installed.) 82s Preparing to unpack .../libnl-genl-3-200_3.7.0-2build1_ppc64el.deb ... 82s Unpacking libnl-genl-3-200:ppc64el (3.7.0-2build1) ... 82s Selecting previously unselected package powertop. 82s Preparing to unpack .../powertop_2.15-4_ppc64el.deb ... 82s Unpacking powertop (2.15-4) ... 82s Setting up libnl-genl-3-200:ppc64el (3.7.0-2build1) ... 82s Setting up powertop (2.15-4) ... 82s Processing triggers for man-db (2.13.1-1) ... 82s Processing triggers for libc-bin (2.42-0ubuntu3) ... 83s autopkgtest [18:37:06]: test power-usage-report: [----------------------- 83s modprobe cpufreq_stats failed 83s RAPL device for cpu 0 83s RAPL device for cpu 0 83s RAPL device for cpu 1 83s RAPL device for cpu 1 83s Devfreq not enabled 83s glob returned GLOB_ABORTED 83s Preparing to take measurements 85s Taking 1 measurement(s) for a duration of 1 second(s) each. 87s PowerTOP outputting using base filename powertop.csv 87s Cannot load from file /var/cache/powertop/saved_results.powertop 87s Cannot load from file /var/cache/powertop/saved_parameters.powertop 87s File will be loaded after taking minimum number of measurement(s) with battery only 87s Cannot load from file /var/cache/powertop/saved_parameters.powertop 87s File will be loaded after taking minimum number of measurement(s) with battery only 87s /usr/sbin/power-usage-report:84: SyntaxWarning: invalid escape sequence '\d' 87s event_re = re.compile('(\d+.\d+) (\S+)\((\d+)\): ([A-Z]+) (.+)$') 87s Measurement will begin in 5 seconds. Please make sure that the 87s computer is idle, i. e. do not press keys, start or operate programs, and that 87s programs are not busy with active tasks other than the one you want to examine. 92s Starting measurement for 60 seconds... 92s modprobe cpufreq_stats failed 92s Loaded 0 prior measurements 92s RAPL device for cpu 0 92s RAPL device for cpu 0 92s RAPL device for cpu 1 92s RAPL device for cpu 1 92s Devfreq not enabled 92s glob returned GLOB_ABORTED 92s Preparing to take measurements 94s Taking 1 measurement(s) for a duration of 61 second(s) each. 155s PowerTOP outputting using base filename /tmp/powertopmi92jm_w.csv 155s Measurement complete. Generating report... 155s autopkgtest [18:38:18]: test power-usage-report: -----------------------] 156s power-usage-report PASS 156s autopkgtest [18:38:19]: test power-usage-report: - - - - - - - - - - results - - - - - - - - - - 156s autopkgtest [18:38:19]: @@@@@@@@@@@@@@@@@@@@ summary 156s fatrace FAIL stderr: RC\?O\? \+/usr/bin/head$ not found in log 156s fatrace-currentmount FAIL stderr: ^rm(.*): D /tmp/autopkgtest.c9M14R/build.3rG/src$ not found in log 156s power-usage-report PASS