0s autopkgtest [17:55:44]: starting date and time: 2025-10-18 17:55:44+0000 0s autopkgtest [17:55:44]: git checkout: 4b346b80 nova: make wait_reboot return success even when a no-op 0s autopkgtest [17:55:44]: host juju-7f2275-prod-proposed-migration-environment-20; command line: /home/ubuntu/autopkgtest/runner/autopkgtest --output-dir /tmp/autopkgtest-work.1gjz9ifz/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-s390x --security-groups autopkgtest-juju-7f2275-prod-proposed-migration-environment-20@bos03-s390x-10.secgroup --name adt-resolute-s390x-fatrace-20251018-175544-juju-7f2275-prod-proposed-migration-environment-20-b8d6d07e-c01f-4981-8333-cbb48522050d --image adt/ubuntu-resolute-s390x-server --keyname testbed-juju-7f2275-prod-proposed-migration-environment-20 --net-id=net_prod-proposed-migration-s390x -e TERM=linux --mirror=http://ftpmaster.internal/ubuntu/ 3s Creating nova instance adt-resolute-s390x-fatrace-20251018-175544-juju-7f2275-prod-proposed-migration-environment-20-b8d6d07e-c01f-4981-8333-cbb48522050d from image adt/ubuntu-resolute-s390x-server-20251018.img (UUID c47ab411-f9be-46ce-b861-20d934d06dba)... 46s autopkgtest [17:56:30]: testbed dpkg architecture: s390x 46s autopkgtest [17:56:30]: testbed apt version: 3.1.6ubuntu2 47s autopkgtest [17:56:31]: @@@@@@@@@@@@@@@@@@@@ test bed setup 47s autopkgtest [17:56:31]: testbed release detected to be: None 47s autopkgtest [17:56:31]: updating testbed package index (apt update) 48s Get:1 http://ftpmaster.internal/ubuntu resolute-proposed InRelease [83.3 kB] 48s Hit:2 http://ftpmaster.internal/ubuntu resolute InRelease 48s Hit:3 http://ftpmaster.internal/ubuntu resolute-updates InRelease 48s Hit:4 http://ftpmaster.internal/ubuntu resolute-security InRelease 48s Get:5 http://ftpmaster.internal/ubuntu resolute-proposed/main Sources [28.4 kB] 48s Get:6 http://ftpmaster.internal/ubuntu resolute-proposed/universe Sources [345 kB] 48s Get:7 http://ftpmaster.internal/ubuntu resolute-proposed/multiverse Sources [15.4 kB] 48s Get:8 http://ftpmaster.internal/ubuntu resolute-proposed/restricted Sources [5028 B] 48s Get:9 http://ftpmaster.internal/ubuntu resolute-proposed/main s390x Packages [74.0 kB] 48s Get:10 http://ftpmaster.internal/ubuntu resolute-proposed/restricted s390x Packages [940 B] 48s Get:11 http://ftpmaster.internal/ubuntu resolute-proposed/universe s390x Packages [226 kB] 49s Get:12 http://ftpmaster.internal/ubuntu resolute-proposed/multiverse s390x Packages [3812 B] 49s Fetched 781 kB in 1s (857 kB/s) 49s Reading package lists... 50s Hit:1 http://ftpmaster.internal/ubuntu resolute-proposed InRelease 50s Hit:2 http://ftpmaster.internal/ubuntu resolute InRelease 50s Hit:3 http://ftpmaster.internal/ubuntu resolute-updates InRelease 50s Hit:4 http://ftpmaster.internal/ubuntu resolute-security InRelease 51s Reading package lists... 51s Reading package lists... 51s Building dependency tree... 51s Reading state information... 51s Calculating upgrade... 51s The following packages will be upgraded: 51s apt gir1.2-girepository-2.0 libapt-pkg7.0 libgirepository-1.0-1 51s libpython3-stdlib lto-disabled-list python3 python3-minimal 51s 8 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 51s Need to get 2763 kB of archives. 51s After this operation, 14.3 kB of additional disk space will be used. 51s Get:1 http://ftpmaster.internal/ubuntu resolute-proposed/main s390x python3-minimal s390x 3.13.7-2 [27.8 kB] 51s Get:2 http://ftpmaster.internal/ubuntu resolute-proposed/main s390x python3 s390x 3.13.7-2 [23.9 kB] 51s Get:3 http://ftpmaster.internal/ubuntu resolute-proposed/main s390x libpython3-stdlib s390x 3.13.7-2 [10.6 kB] 51s Get:4 http://ftpmaster.internal/ubuntu resolute/main s390x libapt-pkg7.0 s390x 3.1.8ubuntu1 [1144 kB] 52s Get:5 http://ftpmaster.internal/ubuntu resolute/main s390x apt s390x 3.1.8ubuntu1 [1432 kB] 52s Get:6 http://ftpmaster.internal/ubuntu resolute/main s390x libgirepository-1.0-1 s390x 1.86.0-6 [86.9 kB] 52s Get:7 http://ftpmaster.internal/ubuntu resolute/main s390x gir1.2-girepository-2.0 s390x 1.86.0-6 [25.1 kB] 52s Get:8 http://ftpmaster.internal/ubuntu resolute/main s390x lto-disabled-list all 71 [12.5 kB] 52s dpkg-preconfigure: unable to re-open stdin: No such file or directory 52s Fetched 2763 kB in 1s (2942 kB/s) 52s (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 ... 56852 files and directories currently installed.) 52s Preparing to unpack .../python3-minimal_3.13.7-2_s390x.deb ... 52s Unpacking python3-minimal (3.13.7-2) over (3.13.7-1) ... 52s Setting up python3-minimal (3.13.7-2) ... 52s (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 ... 56852 files and directories currently installed.) 52s Preparing to unpack .../0-python3_3.13.7-2_s390x.deb ... 52s running python pre-rtupdate hooks for python3.13... 52s Unpacking python3 (3.13.7-2) over (3.13.7-1) ... 52s Preparing to unpack .../1-libpython3-stdlib_3.13.7-2_s390x.deb ... 52s Unpacking libpython3-stdlib:s390x (3.13.7-2) over (3.13.7-1) ... 52s Preparing to unpack .../2-libapt-pkg7.0_3.1.8ubuntu1_s390x.deb ... 52s Unpacking libapt-pkg7.0:s390x (3.1.8ubuntu1) over (3.1.6ubuntu2) ... 53s Preparing to unpack .../3-apt_3.1.8ubuntu1_s390x.deb ... 53s Unpacking apt (3.1.8ubuntu1) over (3.1.6ubuntu2) ... 53s Preparing to unpack .../4-libgirepository-1.0-1_1.86.0-6_s390x.deb ... 53s Unpacking libgirepository-1.0-1:s390x (1.86.0-6) over (1.84.0-1) ... 53s Preparing to unpack .../5-gir1.2-girepository-2.0_1.86.0-6_s390x.deb ... 53s Unpacking gir1.2-girepository-2.0:s390x (1.86.0-6) over (1.84.0-1) ... 53s Preparing to unpack .../6-lto-disabled-list_71_all.deb ... 53s Unpacking lto-disabled-list (71) over (69) ... 53s Setting up lto-disabled-list (71) ... 53s Setting up libgirepository-1.0-1:s390x (1.86.0-6) ... 53s Setting up libapt-pkg7.0:s390x (3.1.8ubuntu1) ... 53s Setting up libpython3-stdlib:s390x (3.13.7-2) ... 53s Setting up apt (3.1.8ubuntu1) ... 53s Setting up python3 (3.13.7-2) ... 53s running python rtupdate hooks for python3.13... 53s running python post-rtupdate hooks for python3.13... 53s Setting up gir1.2-girepository-2.0:s390x (1.86.0-6) ... 53s Processing triggers for man-db (2.13.1-1) ... 55s Processing triggers for libc-bin (2.42-0ubuntu3) ... 55s autopkgtest [17:56:39]: upgrading testbed (apt dist-upgrade and autopurge) 56s Reading package lists... 56s Building dependency tree... 56s Reading state information... 56s Calculating upgrade... 56s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 56s Reading package lists... 56s Building dependency tree... 56s Reading state information... 56s Solving dependencies... 56s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 56s autopkgtest [17:56:40]: rebooting testbed after setup commands that affected boot 70s autopkgtest [17:56:54]: testbed running kernel: Linux 6.17.0-5-generic #5-Ubuntu SMP Mon Sep 22 08:56:47 UTC 2025 72s autopkgtest [17:56:56]: @@@@@@@@@@@@@@@@@@@@ apt-source fatrace 73s Get:1 http://ftpmaster.internal/ubuntu resolute/universe fatrace 0.18.0-1 (dsc) [1888 B] 73s Get:2 http://ftpmaster.internal/ubuntu resolute/universe fatrace 0.18.0-1 (tar) [26.2 kB] 73s Get:3 http://ftpmaster.internal/ubuntu resolute/universe fatrace 0.18.0-1 (diff) [3772 B] 73s gpgv: Signature made Sun Jan 19 11:08:15 2025 UTC 73s gpgv: using RSA key 6C4B878B7E631F160557C3CDEE7BDDE4B86B5713 73s gpgv: Can't check signature: No public key 73s dpkg-source: warning: cannot verify inline signature for ./fatrace_0.18.0-1.dsc: no acceptable signature found 74s autopkgtest [17:56:58]: testing package fatrace version 0.18.0-1 74s autopkgtest [17:56:58]: build not needed 74s autopkgtest [17:56:58]: test fatrace: preparing testbed 74s Reading package lists... 75s Building dependency tree... 75s Reading state information... 75s Solving dependencies... 75s The following NEW packages will be installed: 75s fatrace 75s 0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 75s Need to get 13.9 kB of archives. 75s After this operation, 39.9 kB of additional disk space will be used. 75s Get:1 http://ftpmaster.internal/ubuntu resolute/universe s390x fatrace s390x 0.18.0-1 [13.9 kB] 75s Fetched 13.9 kB in 0s (62.7 kB/s) 75s Selecting previously unselected package fatrace. 75s (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 ... 56852 files and directories currently installed.) 75s Preparing to unpack .../fatrace_0.18.0-1_s390x.deb ... 75s Unpacking fatrace (0.18.0-1) ... 75s Setting up fatrace (0.18.0-1) ... 75s Processing triggers for man-db (2.13.1-1) ... 77s autopkgtest [17:57:01]: test fatrace: [----------------------- 77s starting fatrace... 78s read a file... 78s create a file... 78s waiting for fatrace... 79s checking log... 79s RC\?O\? \+/usr/bin/head$ not found in log 79s ^bash(.* C\?WO\? \+/etc/test.txt not found in log 79s autopkgtest [17:57:03]: test fatrace: -----------------------] 80s fatrace FAIL stderr: RC\?O\? \+/usr/bin/head$ not found in log 80s autopkgtest [17:57:04]: test fatrace: - - - - - - - - - - results - - - - - - - - - - 80s autopkgtest [17:57:04]: test fatrace: - - - - - - - - - - stderr - - - - - - - - - - 80s RC\?O\? \+/usr/bin/head$ not found in log 80s ^bash(.* C\?WO\? \+/etc/test.txt not found in log 80s autopkgtest [17:57:04]: test fatrace-currentmount: preparing testbed 80s Reading package lists... 80s Building dependency tree... 80s Reading state information... 81s Solving dependencies... 81s 0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded. 81s autopkgtest [17:57:05]: test fatrace-currentmount: [----------------------- 81s starting fatrace... 82s read a file... 82s create a file... 82s moving a file within the same directory 82s robustness against ELOOP 83s waiting for fatrace... 84s checking log... 84s autopkgtest [17:57:08]: test fatrace-currentmount: -----------------------] 84s autopkgtest [17:57:08]: test fatrace-currentmount: - - - - - - - - - - results - - - - - - - - - - 84s fatrace-currentmount PASS 85s autopkgtest [17:57:09]: test power-usage-report: preparing testbed 85s Reading package lists... 85s Building dependency tree... 85s Reading state information... 85s Solving dependencies... 85s The following NEW packages will be installed: 85s powertop 85s 0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded. 85s Need to get 194 kB of archives. 85s After this operation, 610 kB of additional disk space will be used. 85s Get:1 http://ftpmaster.internal/ubuntu resolute/main s390x powertop s390x 2.15-4 [194 kB] 86s Fetched 194 kB in 0s (406 kB/s) 86s Selecting previously unselected package powertop. 86s (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 ... 56858 files and directories currently installed.) 86s Preparing to unpack .../powertop_2.15-4_s390x.deb ... 86s Unpacking powertop (2.15-4) ... 86s Setting up powertop (2.15-4) ... 86s Processing triggers for man-db (2.13.1-1) ... 87s autopkgtest [17:57:11]: test power-usage-report: [----------------------- 87s modprobe cpufreq_stats failed 87s Devfreq not enabled 87s glob returned GLOB_ABORTED 87s Preparing to take measurements 88s Taking 1 measurement(s) for a duration of 1 second(s) each. 89s PowerTOP outputting using base filename powertop.csv 89s Cannot load from file /var/cache/powertop/saved_results.powertop 89s Cannot load from file /var/cache/powertop/saved_parameters.powertop 89s File will be loaded after taking minimum number of measurement(s) with battery only 89s Cannot load from file /var/cache/powertop/saved_parameters.powertop 89s File will be loaded after taking minimum number of measurement(s) with battery only 89s /usr/sbin/power-usage-report:84: SyntaxWarning: invalid escape sequence '\d' 89s event_re = re.compile('(\d+.\d+) (\S+)\((\d+)\): ([A-Z]+) (.+)$') 89s Measurement will begin in 5 seconds. Please make sure that the 89s computer is idle, i. e. do not press keys, start or operate programs, and that 89s programs are not busy with active tasks other than the one you want to examine. 94s Starting measurement for 60 seconds... 94s modprobe cpufreq_stats failed 94s Loaded 0 prior measurements 94s Devfreq not enabled 94s glob returned GLOB_ABORTED 94s Preparing to take measurements 95s Taking 1 measurement(s) for a duration of 61 second(s) each. 156s PowerTOP outputting using base filename /tmp/powertopzyz6e2mx.csv 156s Measurement complete. Generating report... 157s autopkgtest [17:58:21]: test power-usage-report: -----------------------] 157s power-usage-report PASS 157s autopkgtest [17:58:21]: test power-usage-report: - - - - - - - - - - results - - - - - - - - - - 157s autopkgtest [17:58:21]: @@@@@@@@@@@@@@@@@@@@ summary 157s fatrace FAIL stderr: RC\?O\? \+/usr/bin/head$ not found in log 157s fatrace-currentmount PASS 157s power-usage-report PASS