[2019-02-04T15:46:37.0751 CET] [info] +++ setup notes +++ [2019-02-04T15:46:37.0751 CET] [info] start time: 2019-02-04 14:46:37 [2019-02-04T15:46:37.0751 CET] [info] running on abanc.test.toulouse-stg.fr.ibm.com:4 (Linux 4.20.6-200.fc29.ppc64le #1 SMP Thu Jan 31 15:31:01 UTC 2019 ppc64le) [2019-02-04T15:46:37.0757 CET] [debug] +++ worker notes +++ [2019-02-04T15:46:37.0757 CET] [debug] start time: 2019-02-04 14:46:37 [2019-02-04T15:46:37.0757 CET] [debug] running on abanc.test.toulouse-stg.fr.ibm.com:4 (Linux 4.20.6-200.fc29.ppc64le #1 SMP Thu Jan 31 15:31:01 UTC 2019 ppc64le) [2019-02-04T15:46:38.206 CET] [debug] Current version is 4.5-12.20190114gitdfe4780.fc29 [interface v13] [2019-02-04T15:46:38.212 CET] [debug] git hash in /var/lib/openqa/share/tests/fedora: 9e7fb8fb7057ed83abb143072f3bf9d50672f063 Smartmatch is experimental at /var/lib/openqa/share/tests/fedora/main.pm line 187. [2019-02-04T15:46:38.222 CET] [info] cmdsrv: daemon reachable under http://*:20043/GehXObffe2mb3Kc1/ [2019-02-04T15:46:38.224 CET] [info] Listening at "http://0.0.0.0:20043" Server available at http://0.0.0.0:20043 [2019-02-04T15:46:38.245 CET] [debug] scheduling _console_wait_login tests/_console_wait_login.pm [2019-02-04T15:46:38.274 CET] [debug] scheduling modularity_module_list tests/modularity_module_list.pm [2019-02-04T15:46:38.284 CET] [debug] scheduling modularity_enable_disable_module tests/modularity_enable_disable_module.pm [2019-02-04T15:46:38.285 CET] [debug] scheduling modularity_install_module tests/modularity_install_module.pm [2019-02-04T15:46:38.287 CET] [debug] init needles from /var/lib/openqa/share/tests/fedora/needles [2019-02-04T15:46:38.370 CET] [debug] loaded 534 needles [2019-02-04T15:46:38.375 CET] [debug] git hash in /var/lib/openqa/share/tests/fedora/needles: 9e7fb8fb7057ed83abb143072f3bf9d50672f063 14009: channel_out 15, channel_in 14 14014: cmdpipe 13, rsppipe 16 [2019-02-04T15:46:38.666 CET] [debug] started mgmt loop with pid 14014 remove_tree qemuscreenshot Use of uninitialized value in string ne at /usr/libexec/os-autoinst/backend/qemu.pm line 512. [2019-02-04T15:46:38.673 CET] [debug] running /usr/bin/chattr -f +C /var/lib/openqa/pool/4/raid [2019-02-04T15:46:38.679 CET] [debug] running /usr/bin/qemu-img info --output=json /var/lib/openqa/share/factory/hdd/00022463-disk_Server-dvd-iso_ppc64le.qcow2 [2019-02-04T15:46:38.690 CET] [debug] { "virtual-size": 10737418240, "filename": "/var/lib/openqa/share/factory/hdd/00022463-disk_Server-dvd-iso_ppc64le.qcow2", "cluster-size": 65536, "format": "qcow2", "actual-size": 933556224, "format-specific": { "type": "qcow2", "data": { "compat": "1.1", "lazy-refcounts": false, "refcount-bits": 16, "corrupt": false } }, "dirty-flag": false } [2019-02-04T15:46:38.691 CET] [debug] running /usr/bin/qemu-img info --output=json /var/lib/openqa/share/factory/iso/Fedora-Server-dvd-ppc64le-29-1.2.iso [2019-02-04T15:46:38.704 CET] [debug] { "virtual-size": 3209779200, "filename": "/var/lib/openqa/share/factory/iso/Fedora-Server-dvd-ppc64le-29-1.2.iso", "format": "raw", "actual-size": 3209781248, "dirty-flag": false } [2019-02-04T15:46:38.705 CET] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/share/factory/hdd/00022463-disk_Server-dvd-iso_ppc64le.qcow2 /var/lib/openqa/pool/4/raid/hd0-overlay0 10737418240 [2019-02-04T15:46:38.797 CET] [debug] Formatting '/var/lib/openqa/pool/4/raid/hd0-overlay0', fmt=qcow2 size=10737418240 backing_file=/var/lib/openqa/share/factory/hdd/00022463-disk_Server-dvd-iso_ppc64le.qcow2 cluster_size=65536 lazy_refcounts=off refcount_bits=16 [2019-02-04T15:46:38.797 CET] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/share/factory/iso/Fedora-Server-dvd-ppc64le-29-1.2.iso /var/lib/openqa/pool/4/raid/cd0-overlay0 3209779200 [2019-02-04T15:46:38.880 CET] [debug] Formatting '/var/lib/openqa/pool/4/raid/cd0-overlay0', fmt=qcow2 size=3209779200 backing_file=/var/lib/openqa/share/factory/iso/Fedora-Server-dvd-ppc64le-29-1.2.iso cluster_size=65536 lazy_refcounts=off refcount_bits=16 [2019-02-04T15:46:38.881 CET] [debug] starting: /usr/bin/qemu-system-ppc64 -g 1024x768 -vga std -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -soundhw ac97 -global isa-fdc.driveA= -m 4096 -machine usb=off -cpu host -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -boot order=c,menu=on,splash-time=5000 -device nec-usb-xhci -device usb-tablet -device usb-kbd -smp 1 -enable-kvm -no-shutdown -vnc :94,share=force-shared -device virtio-serial -chardev socket,path=virtio_console,server,nowait,id=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev socket,path=qmp_socket,server,nowait,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-overlay0-file,filename=/var/lib/openqa/pool/4/raid/hd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0-overlay0,file=hd0-overlay0-file,cache.no-flush=on -device virtio-blk,id=hd0-device,drive=hd0-overlay0,bootindex=0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/var/lib/openqa/pool/4/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0 Attempt 0 at /usr/libexec/os-autoinst/osutils.pm line 130. Attempt 1 at /usr/libexec/os-autoinst/osutils.pm line 130. Attempts terminated! at /usr/libexec/os-autoinst/osutils.pm line 136. [2019-02-04T15:46:40.885 CET] [debug] qmpsocket 14 /usr/libexec/os-autoinst/consoles/vnc_base.pm:58:{ 'connect_timeout' => 3, 'hostname' => 'localhost', 'port' => 5994 } Start CPU [2019-02-04T15:46:40.962 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"50850","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5994","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":910710,"seconds":1549291600}} [2019-02-04T15:46:40.962 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"50850","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5994","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":911262,"seconds":1549291600}} [2019-02-04T15:46:40.962 CET] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":962174,"seconds":1549291600}} [2019-02-04T15:46:40.964 CET] [debug] pointer type 1 0 640 480 -257 GOT GO [2019-02-04T15:46:40.964 CET] [debug] led state 0 1 1 -261 [2019-02-04T15:46:40.971 CET] [debug] QEMU: QEMU emulator version 3.0.0 (qemu-3.0.0-3.fc29) [2019-02-04T15:46:40.971 CET] [debug] QEMU: Copyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers [2019-02-04T15:46:40.972 CET] [debug] Snapshots are supported [2019-02-04T15:46:40.973 CET] [debug] ||| starting _console_wait_login tests/_console_wait_login.pm [2019-02-04T15:46:40.974 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/_console_wait_login.pm:19 called utils::boot_to_login_screen [2019-02-04T15:46:40.974 CET] [debug] <<< testapi::check_screen(mustmatch='login_screen', timeout=3) [2019-02-04T15:46:42.036 CET] [debug] no match: 2.0s, best candidate: login_gdm (0.00) [2019-02-04T15:46:43.017 CET] [debug] no match: 1.0s, best candidate: login_gdm (0.00) [2019-02-04T15:46:45.746 CET] [debug] WARNING: check_asserted_screen took 1.78 seconds for 4 candidate needles - make your needles more specific [2019-02-04T15:46:45.747 CET] [debug] no match: -0.0s, best candidate: login_gdm (0.00) [2019-02-04T15:46:46.254 CET] [debug] >>> testapi::_check_backend_response: match=login_screen timed out after 3 (check_screen) [2019-02-04T15:46:46.319 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/_console_wait_login.pm:19 called utils::boot_to_login_screen [2019-02-04T15:46:46.319 CET] [debug] <<< testapi::assert_screen(mustmatch='login_screen', timeout=300) [2019-02-04T15:46:46.789 CET] [debug] no match: 299.5s, best candidate: login_gdm (0.00) [2019-02-04T15:46:47.791 CET] [debug] no match: 298.5s, best candidate: login_gdm (0.00) [2019-02-04T15:46:48.790 CET] [debug] no match: 297.5s, best candidate: login_gdm (0.00) [2019-02-04T15:46:49.791 CET] [debug] no match: 296.5s, best candidate: login_gdm (0.00) [2019-02-04T15:46:50.983 CET] [debug] no match: 295.5s, best candidate: login_gdm (0.00) [2019-02-04T15:46:51.797 CET] [debug] no match: 294.5s, best candidate: login_gdm (0.00) [2019-02-04T15:46:52.754 CET] [debug] no change: 293.5s [2019-02-04T15:46:53.755 CET] [debug] no change: 292.5s [2019-02-04T15:46:54.756 CET] [debug] no change: 291.5s [2019-02-04T15:46:56.001 CET] [debug] no match: 290.5s, best candidate: login_gdm (0.00) [2019-02-04T15:46:56.758 CET] [debug] no change: 289.5s [2019-02-04T15:46:57.799 CET] [debug] no match: 288.5s, best candidate: login_gdm (0.00) [2019-02-04T15:46:58.760 CET] [debug] no change: 287.5s [2019-02-04T15:46:59.761 CET] [debug] no change: 286.5s [2019-02-04T15:47:02.484 CET] [debug] WARNING: check_asserted_screen took 1.72 seconds for 4 candidate needles - make your needles more specific [2019-02-04T15:47:02.486 CET] [debug] no match: 285.5s, best candidate: login_gdm (0.00) [2019-02-04T15:47:02.528 CET] [debug] no match: 283.8s, best candidate: login_gdm (0.00) [2019-02-04T15:47:03.535 CET] [debug] no match: 282.8s, best candidate: login_gdm (0.00) [2019-02-04T15:47:04.494 CET] [debug] no change: 281.8s [2019-02-04T15:47:05.932 CET] [debug] no match: 280.8s, best candidate: login_gdm (0.00) [2019-02-04T15:47:06.526 CET] [debug] no match: 279.8s, best candidate: login_gdm (0.00) [2019-02-04T15:47:07.653 CET] [debug] >>> testapi::_handle_found_needle: found text_console_login, similarity 1.00 @ 72/81 [2019-02-04T15:47:11.653 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/_console_wait_login.pm:25 called utils::console_login [2019-02-04T15:47:11.653 CET] [debug] <<< testapi::check_screen(mustmatch='user_console', timeout=0) [2019-02-04T15:47:12.146 CET] [debug] >>> testapi::_check_backend_response: match=user_console timed out after 0 (check_screen) [2019-02-04T15:47:12.183 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/_console_wait_login.pm:25 called utils::console_login [2019-02-04T15:47:12.183 CET] [debug] <<< testapi::check_screen(mustmatch=[ 'root_console', 'text_console_login' ], timeout=10) [2019-02-04T15:47:12.890 CET] [debug] >>> testapi::_handle_found_needle: found text_console_login, similarity 1.00 @ 72/81 [2019-02-04T15:47:12.890 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/_console_wait_login.pm:25 called utils::console_login [2019-02-04T15:47:12.891 CET] [debug] <<< testapi::type_string(string='root ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:47:13.414 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/_console_wait_login.pm:25 called utils::console_login [2019-02-04T15:47:13.414 CET] [debug] <<< testapi::check_screen(mustmatch=[ 'root_console', 'console_password_required' ], timeout=30) [2019-02-04T15:47:13.700 CET] [debug] no match: 29.7s, best candidate: console_password_required (0.00) [2019-02-04T15:47:14.806 CET] [debug] >>> testapi::_handle_found_needle: found console_password_required, similarity 1.00 @ 1/111 [2019-02-04T15:47:14.806 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/_console_wait_login.pm:25 called utils::console_login [2019-02-04T15:47:14.806 CET] [debug] <<< testapi::type_string(string='weakpassword', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:47:16.060 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/_console_wait_login.pm:25 called utils::console_login [2019-02-04T15:47:16.060 CET] [debug] <<< testapi::send_key(key='ret', do_wait=0) [2019-02-04T15:47:16.265 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/_console_wait_login.pm:25 called utils::console_login [2019-02-04T15:47:16.265 CET] [debug] <<< testapi::check_screen(mustmatch='root_console', timeout=30) [2019-02-04T15:47:16.295 CET] [debug] no match: 29.9s, best candidate: root_logged_in (0.00) [2019-02-04T15:47:17.438 CET] [debug] >>> testapi::_handle_found_needle: found root_logged_in, similarity 1.00 @ 137/144 [2019-02-04T15:47:17.442 CET] [debug] ||| finished _console_wait_login fedora/tests at 2019-02-04 14:47:17 (37 s) [2019-02-04T15:47:17.444 CET] [debug] Creating a VM snapshot lastgood [2019-02-04T15:47:17.444 CET] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[1]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":219188,"seconds":1549291625}} [2019-02-04T15:47:17.444 CET] [debug] EVENT {"data":{"offset":1},"event":"RTC_CHANGE","timestamp":{"microseconds":513852,"seconds":1549291633}} [2019-02-04T15:47:17.445 CET] [debug] Saving snapshot (Current VM state is running). [2019-02-04T15:47:17.487 CET] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":487608,"seconds":1549291637}} [2019-02-04T15:47:17.605 CET] [debug] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'hd0-overlay0','snapshot-file' => '/var/lib/openqa/pool/4/raid/hd0-overlay1','snapshot-node-name' => 'hd0-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}} [2019-02-04T15:47:17.701 CET] [debug] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'cd0-overlay0','snapshot-file' => '/var/lib/openqa/pool/4/raid/cd0-overlay1','snapshot-node-name' => 'cd0-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}} [2019-02-04T15:47:17.725 CET] [debug] EVENT {"data":{"status":"setup"},"event":"MIGRATION","timestamp":{"microseconds":724057,"seconds":1549291637}} [2019-02-04T15:47:18.225 CET] [debug] EVENT {"data":{"pass":1},"event":"MIGRATION_PASS","timestamp":{"microseconds":752133,"seconds":1549291637}} [2019-02-04T15:47:18.225 CET] [debug] EVENT {"data":{"status":"active"},"event":"MIGRATION","timestamp":{"microseconds":752271,"seconds":1549291637}} [2019-02-04T15:47:18.226 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:18.226 CET] [debug] Migrating remaining bytes: 4303376384 [2019-02-04T15:47:18.727 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:18.727 CET] [debug] Migrating remaining bytes: 4291862528 [2019-02-04T15:47:19.228 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:19.228 CET] [debug] Migrating remaining bytes: 4275367936 [2019-02-04T15:47:19.729 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:19.729 CET] [debug] Migrating remaining bytes: 4264341504 [2019-02-04T15:47:20.230 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:20.230 CET] [debug] Migrating remaining bytes: 4244598784 [2019-02-04T15:47:20.731 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:20.731 CET] [debug] Migrating remaining bytes: 4230881280 [2019-02-04T15:47:21.232 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:21.232 CET] [debug] Migrating remaining bytes: 4217303040 [2019-02-04T15:47:21.733 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:21.733 CET] [debug] Migrating remaining bytes: 3515310080 [2019-02-04T15:47:22.234 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:22.234 CET] [debug] Migrating remaining bytes: 3245490176 [2019-02-04T15:47:22.735 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:22.735 CET] [debug] Migrating remaining bytes: 2202447872 [2019-02-04T15:47:23.236 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:23.236 CET] [debug] Migrating remaining bytes: 736956416 [2019-02-04T15:47:23.737 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:23.737 CET] [debug] Migrating remaining bytes: 705617920 [2019-02-04T15:47:24.238 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:24.238 CET] [debug] Migrating remaining bytes: 677380096 [2019-02-04T15:47:24.739 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:24.739 CET] [debug] Migrating remaining bytes: 653758464 [2019-02-04T15:47:25.241 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:25.241 CET] [debug] Migrating remaining bytes: 638189568 [2019-02-04T15:47:25.742 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:25.742 CET] [debug] Migrating remaining bytes: 618696704 [2019-02-04T15:47:26.243 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:26.243 CET] [debug] Migrating remaining bytes: 597798912 [2019-02-04T15:47:26.744 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:26.744 CET] [debug] Migrating remaining bytes: 580186112 [2019-02-04T15:47:27.245 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:27.245 CET] [debug] Migrating remaining bytes: 561926144 [2019-02-04T15:47:27.746 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:27.746 CET] [debug] Migrating remaining bytes: 537731072 [2019-02-04T15:47:28.247 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:28.247 CET] [debug] Migrating remaining bytes: 511434752 [2019-02-04T15:47:28.748 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:28.748 CET] [debug] Migrating remaining bytes: 490418176 [2019-02-04T15:47:29.248 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:29.248 CET] [debug] Migrating remaining bytes: 462999552 [2019-02-04T15:47:29.749 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:29.749 CET] [debug] Migrating remaining bytes: 444850176 [2019-02-04T15:47:30.250 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:30.250 CET] [debug] Migrating remaining bytes: 426733568 [2019-02-04T15:47:30.751 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:30.751 CET] [debug] Migrating remaining bytes: 411045888 [2019-02-04T15:47:31.252 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:31.252 CET] [debug] Migrating remaining bytes: 389890048 [2019-02-04T15:47:31.753 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:31.753 CET] [debug] Migrating remaining bytes: 369229824 [2019-02-04T15:47:32.254 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:32.254 CET] [debug] Migrating remaining bytes: 350531584 [2019-02-04T15:47:32.755 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:32.755 CET] [debug] Migrating remaining bytes: 328392704 [2019-02-04T15:47:33.256 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:33.257 CET] [debug] Migrating remaining bytes: 296075264 [2019-02-04T15:47:33.757 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:33.757 CET] [debug] Migrating remaining bytes: 272297984 [2019-02-04T15:47:34.258 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:34.258 CET] [debug] Migrating remaining bytes: 259088384 [2019-02-04T15:47:34.759 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:34.759 CET] [debug] Migrating remaining bytes: 244199424 [2019-02-04T15:47:35.261 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:35.261 CET] [debug] Migrating remaining bytes: 228982784 [2019-02-04T15:47:35.762 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:35.762 CET] [debug] Migrating remaining bytes: 214384640 [2019-02-04T15:47:36.263 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:36.263 CET] [debug] Migrating remaining bytes: 195452928 [2019-02-04T15:47:36.764 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:36.764 CET] [debug] Migrating remaining bytes: 175951872 [2019-02-04T15:47:37.265 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:37.266 CET] [debug] Migrating remaining bytes: 149827584 [2019-02-04T15:47:37.766 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:37.766 CET] [debug] Migrating remaining bytes: 110743552 [2019-02-04T15:47:38.268 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:38.268 CET] [debug] Migrating remaining bytes: 89624576 [2019-02-04T15:47:38.769 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:38.769 CET] [debug] Migrating remaining bytes: 78802944 [2019-02-04T15:47:39.269 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:39.269 CET] [debug] Migrating remaining bytes: 68329472 [2019-02-04T15:47:39.771 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:39.771 CET] [debug] Migrating remaining bytes: 51965952 [2019-02-04T15:47:40.272 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:40.272 CET] [debug] Migrating remaining bytes: 32759808 [2019-02-04T15:47:40.772 CET] [debug] EVENT {"data":{"pass":2},"event":"MIGRATION_PASS","timestamp":{"microseconds":648222,"seconds":1549291660}} [2019-02-04T15:47:40.773 CET] [debug] EVENT {"data":{"pass":3},"event":"MIGRATION_PASS","timestamp":{"microseconds":658615,"seconds":1549291660}} [2019-02-04T15:47:40.773 CET] [debug] EVENT {"data":{"status":"completed"},"event":"MIGRATION","timestamp":{"microseconds":738611,"seconds":1549291660}} [2019-02-04T15:47:40.774 CET] [debug] Migrating total bytes: 4312072192 [2019-02-04T15:47:40.774 CET] [debug] Migrating remaining bytes: 0 [2019-02-04T15:47:40.775 CET] [debug] Snapshot complete [2019-02-04T15:47:40.833 CET] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":833776,"seconds":1549291660}} [2019-02-04T15:47:40.838 CET] [debug] ||| starting modularity_module_list tests/modularity_module_list.pm [2019-02-04T15:47:40.843 CET] [debug] QEMU: Formatting '/var/lib/openqa/pool/4/raid/hd0-overlay1', fmt=qcow2 size=10737418240 backing_file=/var/lib/openqa/pool/4/raid/hd0-overlay0 backing_fmt=qcow2 cluster_size=65536 lazy_refcounts=off refcount_bits=16 [2019-02-04T15:47:40.843 CET] [debug] QEMU: Formatting '/var/lib/openqa/pool/4/raid/cd0-overlay1', fmt=qcow2 size=3209779200 backing_file=/var/lib/openqa/pool/4/raid/cd0-overlay0 backing_fmt=qcow2 cluster_size=65536 lazy_refcounts=off refcount_bits=16 [2019-02-04T15:47:40.843 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:9 called installedtest::root_console [2019-02-04T15:47:40.843 CET] [debug] <<< testapi::send_key(key='ctrl-alt-f3', do_wait=0) [2019-02-04T15:47:45.051 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:9 called installedtest::root_console [2019-02-04T15:47:45.052 CET] [debug] <<< testapi::check_screen(mustmatch='user_console', timeout=0) [2019-02-04T15:47:45.549 CET] [debug] >>> testapi::_check_backend_response: match=user_console timed out after 0 (check_screen) [2019-02-04T15:47:45.592 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:9 called installedtest::root_console [2019-02-04T15:47:45.592 CET] [debug] <<< testapi::check_screen(mustmatch=[ 'root_console', 'text_console_login' ], timeout=10) [2019-02-04T15:47:46.221 CET] [debug] >>> testapi::_handle_found_needle: found text_console_login, similarity 1.00 @ 72/81 [2019-02-04T15:47:46.222 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:9 called installedtest::root_console [2019-02-04T15:47:46.222 CET] [debug] <<< testapi::type_string(string='root ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:47:46.767 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:9 called installedtest::root_console [2019-02-04T15:47:46.767 CET] [debug] <<< testapi::check_screen(mustmatch=[ 'root_console', 'console_password_required' ], timeout=30) [2019-02-04T15:47:47.080 CET] [debug] no match: 29.7s, best candidate: console_password_required (0.00) [2019-02-04T15:47:48.206 CET] [debug] >>> testapi::_handle_found_needle: found console_password_required, similarity 1.00 @ 1/111 [2019-02-04T15:47:48.206 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:9 called installedtest::root_console [2019-02-04T15:47:48.207 CET] [debug] <<< testapi::type_string(string='weakpassword', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:47:49.461 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:9 called installedtest::root_console [2019-02-04T15:47:49.461 CET] [debug] <<< testapi::send_key(key='ret', do_wait=0) [2019-02-04T15:47:49.686 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:9 called installedtest::root_console [2019-02-04T15:47:49.686 CET] [debug] <<< testapi::check_screen(mustmatch='root_console', timeout=30) [2019-02-04T15:47:49.701 CET] [debug] no match: 29.9s, best candidate: root_logged_in (0.00) [2019-02-04T15:47:50.833 CET] [debug] >>> testapi::_handle_found_needle: found root_logged_in, similarity 1.00 @ 137/144 [2019-02-04T15:47:50.833 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:17 called testapi::assert_script_run [2019-02-04T15:47:50.834 CET] [debug] <<< testapi::assert_script_run(cmd='dnf module list', wait=90, fail_message=undef) [2019-02-04T15:47:50.834 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:17 called testapi::assert_script_run [2019-02-04T15:47:50.834 CET] [debug] <<< testapi::type_string(string='dnf module list', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:47:52.406 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:17 called testapi::assert_script_run [2019-02-04T15:47:52.406 CET] [debug] <<< testapi::type_string(string=' ; echo KbrAy-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:47:55.547 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:17 called testapi::assert_script_run [2019-02-04T15:47:55.547 CET] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/KbrAy-\d+-/) [2019-02-04T15:49:04.725 CET] [debug] >>> testapi::wait_serial: (?^:KbrAy-\d+-): ok [2019-02-04T15:49:04.725 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:21 called testapi::assert_script_run [2019-02-04T15:49:04.725 CET] [debug] <<< testapi::assert_script_run(cmd='dnf module list --all', wait=90, fail_message=undef) [2019-02-04T15:49:04.725 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:21 called testapi::assert_script_run [2019-02-04T15:49:04.725 CET] [debug] <<< testapi::type_string(string='dnf module list --all', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:49:06.919 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:21 called testapi::assert_script_run [2019-02-04T15:49:06.920 CET] [debug] <<< testapi::type_string(string=' ; echo 2TsLF-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:49:10.064 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:21 called testapi::assert_script_run [2019-02-04T15:49:10.064 CET] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/2TsLF-\d+-/) [2019-02-04T15:49:14.218 CET] [debug] >>> testapi::wait_serial: (?^:2TsLF-\d+-): ok [2019-02-04T15:49:14.218 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:24 called testapi::assert_script_run [2019-02-04T15:49:14.218 CET] [debug] <<< testapi::assert_script_run(cmd='dnf module list --enabled', wait=90, fail_message=undef) [2019-02-04T15:49:14.218 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:24 called testapi::assert_script_run [2019-02-04T15:49:14.218 CET] [debug] <<< testapi::type_string(string='dnf module list --enabled', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:49:16.846 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:24 called testapi::assert_script_run [2019-02-04T15:49:16.846 CET] [debug] <<< testapi::type_string(string=' ; echo 0my8j-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:49:19.980 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:24 called testapi::assert_script_run [2019-02-04T15:49:19.980 CET] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/0my8j-\d+-/) [2019-02-04T15:49:24.122 CET] [debug] >>> testapi::wait_serial: (?^:0my8j-\d+-): ok [2019-02-04T15:49:24.122 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:27 called testapi::assert_script_run [2019-02-04T15:49:24.123 CET] [debug] <<< testapi::assert_script_run(cmd='dnf module list --disabled', wait=90, fail_message=undef) [2019-02-04T15:49:24.123 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:27 called testapi::assert_script_run [2019-02-04T15:49:24.123 CET] [debug] <<< testapi::type_string(string='dnf module list --disabled', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:49:26.842 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:27 called testapi::assert_script_run [2019-02-04T15:49:26.842 CET] [debug] <<< testapi::type_string(string=' ; echo TO1q9-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:49:29.977 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:27 called testapi::assert_script_run [2019-02-04T15:49:29.977 CET] [debug] <<< testapi::wait_serial(regexp=qr/TO1q9-\d+-/, timeout=90) [2019-02-04T15:49:34.135 CET] [debug] >>> testapi::wait_serial: (?^:TO1q9-\d+-): ok [2019-02-04T15:49:34.136 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:30 called testapi::assert_script_run [2019-02-04T15:49:34.136 CET] [debug] <<< testapi::assert_script_run(cmd='dnf module list --installed', wait=90, fail_message=undef) [2019-02-04T15:49:34.136 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:30 called testapi::assert_script_run [2019-02-04T15:49:34.136 CET] [debug] <<< testapi::type_string(string='dnf module list --installed', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:49:36.965 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:30 called testapi::assert_script_run [2019-02-04T15:49:36.965 CET] [debug] <<< testapi::type_string(string=' ; echo KYMvQ-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:49:40.126 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_module_list.pm:30 called testapi::assert_script_run [2019-02-04T15:49:40.126 CET] [debug] <<< testapi::wait_serial(regexp=qr/KYMvQ-\d+-/, timeout=90) [2019-02-04T15:49:44.269 CET] [debug] >>> testapi::wait_serial: (?^:KYMvQ-\d+-): ok [2019-02-04T15:49:44.270 CET] [debug] ||| finished modularity_module_list fedora/tests at 2019-02-04 14:49:44 (124 s) [2019-02-04T15:49:44.270 CET] [debug] ||| starting modularity_enable_disable_module tests/modularity_enable_disable_module.pm [2019-02-04T15:49:44.270 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:9 called installedtest::root_console [2019-02-04T15:49:44.271 CET] [debug] <<< testapi::send_key(key='ctrl-alt-f3', do_wait=0) [2019-02-04T15:49:48.477 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:9 called installedtest::root_console [2019-02-04T15:49:48.477 CET] [debug] <<< testapi::check_screen(mustmatch='user_console', timeout=0) [2019-02-04T15:49:48.945 CET] [debug] >>> testapi::_check_backend_response: match=user_console timed out after 0 (check_screen) [2019-02-04T15:49:48.981 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:9 called installedtest::root_console [2019-02-04T15:49:48.981 CET] [debug] <<< testapi::check_screen(mustmatch=[ 'root_console', 'text_console_login' ], timeout=10) [2019-02-04T15:49:49.491 CET] [debug] no match: 9.5s, best candidate: root_logged_in (0.00) [2019-02-04T15:49:50.480 CET] [debug] no change: 8.5s [2019-02-04T15:49:51.508 CET] [debug] no match: 7.5s, best candidate: root_logged_in (0.00) [2019-02-04T15:49:52.508 CET] [debug] no match: 6.4s, best candidate: root_logged_in (0.00) [2019-02-04T15:49:54.037 CET] [debug] >>> testapi::_handle_found_needle: found root_logged_in, similarity 1.00 @ 137/608 [2019-02-04T15:49:54.037 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:12 called utils::download_modularity_tests [2019-02-04T15:49:54.037 CET] [debug] <<< testapi::assert_script_run(cmd='curl -o /root/test.py https://pagure.io/fedora-qa/modularity_testing_scripts/raw/master/f/modular_functions.py', wait=90, fail_message=undef) [2019-02-04T15:49:54.037 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:12 called utils::download_modularity_tests [2019-02-04T15:49:54.037 CET] [debug] <<< testapi::type_string(string='curl -o /root/test.py https://pagure.io/fedora-qa/modularity_testing_scripts/raw/master/f/modular_functions.py', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:50:05.546 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:12 called utils::download_modularity_tests [2019-02-04T15:50:05.546 CET] [debug] <<< testapi::type_string(string=' ; echo gMw5A-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:50:08.728 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:12 called utils::download_modularity_tests [2019-02-04T15:50:08.728 CET] [debug] <<< testapi::wait_serial(regexp=qr/gMw5A-\d+-/, timeout=90) [2019-02-04T15:50:11.874 CET] [debug] >>> testapi::wait_serial: (?^:gMw5A-\d+-): ok [2019-02-04T15:50:11.874 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:12 called utils::download_modularity_tests [2019-02-04T15:50:11.874 CET] [debug] <<< testapi::assert_script_run(cmd='chmod 755 /root/test.py', wait=90, fail_message=undef) [2019-02-04T15:50:11.874 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:12 called utils::download_modularity_tests [2019-02-04T15:50:11.874 CET] [debug] <<< testapi::type_string(string='chmod 755 /root/test.py', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:50:14.279 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:12 called utils::download_modularity_tests [2019-02-04T15:50:14.279 CET] [debug] <<< testapi::type_string(string=' ; echo FWbwy-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:50:17.426 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:12 called utils::download_modularity_tests [2019-02-04T15:50:17.427 CET] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/FWbwy-\d+-/) [2019-02-04T15:50:18.563 CET] [debug] >>> testapi::wait_serial: (?^:FWbwy-\d+-): ok [2019-02-04T15:50:18.563 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:15 called testapi::assert_script_run [2019-02-04T15:50:18.563 CET] [debug] <<< testapi::assert_script_run(cmd='/root/test.py -m dwm -s 6.0 -a list', wait=90, fail_message=undef) [2019-02-04T15:50:18.571 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:15 called testapi::assert_script_run [2019-02-04T15:50:18.571 CET] [debug] <<< testapi::type_string(string='/root/test.py -m dwm -s 6.0 -a list', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:50:22.228 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:15 called testapi::assert_script_run [2019-02-04T15:50:22.228 CET] [debug] <<< testapi::type_string(string=' ; echo uesAO-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:50:25.367 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm:15 called testapi::assert_script_run [2019-02-04T15:50:25.367 CET] [debug] <<< testapi::wait_serial(regexp=qr/uesAO-\d+-/, timeout=90) [2019-02-04T15:50:29.521 CET] [debug] >>> testapi::wait_serial: (?^:uesAO-\d+-): ok [2019-02-04T15:50:29.662 CET] [debug] command '/root/test.py -m dwm -s 6.0 -a list' failed at /var/lib/openqa/share/tests/fedora/tests/modularity_enable_disable_module.pm line 15. [2019-02-04T15:50:29.663 CET] [debug] <<< testapi::check_screen(mustmatch='emergency_rescue', timeout=3) [2019-02-04T15:50:29.672 CET] [debug] no match: 2.9s, best candidate: emergency_rescue-20170119 (0.00) [2019-02-04T15:50:30.668 CET] [debug] no match: 1.9s, best candidate: emergency_rescue-20170119 (0.00) [2019-02-04T15:50:31.726 CET] [debug] no match: 0.9s, best candidate: emergency_rescue-20170119 (0.00) [2019-02-04T15:50:33.014 CET] [debug] >>> testapi::_check_backend_response: match=emergency_rescue timed out after 3 (check_screen) [2019-02-04T15:50:33.058 CET] [debug] <<< testapi::send_key(key='ctrl-alt-f6', do_wait=0) [2019-02-04T15:50:37.264 CET] [debug] <<< testapi::check_screen(mustmatch='user_console', timeout=0) [2019-02-04T15:50:37.752 CET] [debug] >>> testapi::_check_backend_response: match=user_console timed out after 0 (check_screen) [2019-02-04T15:50:37.804 CET] [debug] <<< testapi::check_screen(mustmatch=[ 'root_console', 'text_console_login' ], timeout=10) [2019-02-04T15:50:38.431 CET] [debug] >>> testapi::_handle_found_needle: found text_console_login, similarity 1.00 @ 72/81 [2019-02-04T15:50:38.431 CET] [debug] <<< testapi::type_string(string='root ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:50:38.956 CET] [debug] <<< testapi::check_screen(mustmatch=[ 'root_console', 'console_password_required' ], timeout=30) [2019-02-04T15:50:39.292 CET] [debug] no match: 29.6s, best candidate: console_password_required (0.00) [2019-02-04T15:50:40.434 CET] [debug] >>> testapi::_handle_found_needle: found console_password_required, similarity 1.00 @ 1/111 [2019-02-04T15:50:40.435 CET] [debug] <<< testapi::type_string(string='weakpassword', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:50:41.688 CET] [debug] <<< testapi::send_key(key='ret', do_wait=0) [2019-02-04T15:50:41.894 CET] [debug] <<< testapi::check_screen(mustmatch='root_console', timeout=30) [2019-02-04T15:50:41.915 CET] [debug] no match: 29.9s, best candidate: root_logged_in (0.00) [2019-02-04T15:50:43.058 CET] [debug] >>> testapi::_handle_found_needle: found root_logged_in, similarity 1.00 @ 137/144 Use of uninitialized value in string eq at /var/lib/openqa/share/tests/fedora/lib/utils.pm line 191. Use of uninitialized value in string eq at /var/lib/openqa/share/tests/fedora/lib/utils.pm line 196. [2019-02-04T15:50:43.058 CET] [debug] <<< testapi::check_screen(mustmatch='root_console_dracut', timeout=0) [2019-02-04T15:50:44.145 CET] [debug] >>> testapi::_check_backend_response: match=root_console_dracut timed out after 0 (check_screen) [2019-02-04T15:50:44.188 CET] [debug] <<< testapi::script_run(cmd='dnf -y --nogpgcheck install tar', wait=180) [2019-02-04T15:50:44.188 CET] [debug] <<< testapi::type_string(string='dnf -y --nogpgcheck install tar', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:50:47.445 CET] [debug] <<< testapi::type_string(string=' ; echo ROE55-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:50:50.618 CET] [debug] <<< testapi::wait_serial(regexp=qr/ROE55-\d+-/, timeout=180) [2019-02-04T15:50:55.763 CET] [debug] >>> testapi::wait_serial: (?^:ROE55-\d+-): ok [2019-02-04T15:50:55.763 CET] [debug] <<< testapi::assert_script_run(cmd='rpm -q tar', wait=90, fail_message=undef) [2019-02-04T15:50:55.763 CET] [debug] <<< testapi::type_string(string='rpm -q tar', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:50:56.820 CET] [debug] <<< testapi::type_string(string=' ; echo kFGj4-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:50:59.974 CET] [debug] <<< testapi::wait_serial(regexp=qr/kFGj4-\d+-/, timeout=90) [2019-02-04T15:51:01.122 CET] [debug] >>> testapi::wait_serial: (?^:kFGj4-\d+-): ok [2019-02-04T15:51:01.123 CET] [debug] <<< testapi::script_run(cmd='rpm -q tar', wait=undef) [2019-02-04T15:51:01.123 CET] [debug] <<< testapi::type_string(string='rpm -q tar', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:51:02.168 CET] [debug] <<< testapi::type_string(string=' ; echo AnUTU-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:51:05.323 CET] [debug] <<< testapi::wait_serial(timeout=30, regexp=qr/AnUTU-\d+-/) [2019-02-04T15:51:06.457 CET] [debug] >>> testapi::wait_serial: (?^:AnUTU-\d+-): ok [2019-02-04T15:51:06.458 CET] [debug] <<< testapi::script_run(cmd='ping -c 2 10.0.2.2', wait=undef) [2019-02-04T15:51:06.458 CET] [debug] <<< testapi::type_string(string='ping -c 2 10.0.2.2', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:51:08.342 CET] [debug] <<< testapi::type_string(string=' ; echo nG~_Y-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:51:11.483 CET] [debug] <<< testapi::wait_serial(timeout=30, regexp=qr/nG~_Y-\d+-/) [2019-02-04T15:51:14.618 CET] [debug] >>> testapi::wait_serial: (?^:nG~_Y-\d+-): ok [2019-02-04T15:51:14.618 CET] [debug] <<< testapi::script_run(cmd='test -n "$(ls -A /var/tmp/abrt)" && cd /var/tmp/abrt && tar czvf tmpabrt.tar.gz *', wait=undef) [2019-02-04T15:51:14.619 CET] [debug] <<< testapi::type_string(string='test -n "$(ls -A /var/tmp/abrt)" && cd /var/tmp/abrt && tar czvf tmpabrt.tar.gz *', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:51:23.080 CET] [debug] <<< testapi::type_string(string=' ; echo KBIT0-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:51:26.220 CET] [debug] <<< testapi::wait_serial(regexp=qr/KBIT0-\d+-/, timeout=30) [2019-02-04T15:51:27.390 CET] [debug] >>> testapi::wait_serial: (?^:KBIT0-\d+-): ok [2019-02-04T15:51:27.390 CET] [debug] <<< testapi::script_run(cmd='test -n "$(ls -A /var/spool/abrt)" && cd /var/spool/abrt && tar czvf spoolabrt.tar.gz *', wait=undef) [2019-02-04T15:51:27.390 CET] [debug] <<< testapi::type_string(string='test -n "$(ls -A /var/spool/abrt)" && cd /var/spool/abrt && tar czvf spoolabrt.tar.gz *', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:51:36.492 CET] [debug] <<< testapi::type_string(string=' ; echo kWuOo-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:51:39.637 CET] [debug] <<< testapi::wait_serial(regexp=qr/kWuOo-\d+-/, timeout=30) [2019-02-04T15:51:41.780 CET] [debug] >>> testapi::wait_serial: (?^:kWuOo-\d+-): ok [2019-02-04T15:51:41.780 CET] [debug] <<< testapi::upload_logs(file='/var/spool/abrt/spoolabrt.tar.gz', failok=0, timeout=90) [2019-02-04T15:51:41.781 CET] [debug] <<< testapi::assert_script_run(cmd='curl --form upload=@/var/spool/abrt/spoolabrt.tar.gz --form upname=modularity_enable_disable_module-spoolabrt.tar.gz http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/spoolabrt.tar.gz', wait=90, fail_message=undef) [2019-02-04T15:51:41.781 CET] [debug] <<< testapi::type_string(string='curl --form upload=@/var/spool/abrt/spoolabrt.tar.gz --form upname=modularity_enable_disable_module-spoolabrt.tar.gz http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/spoolabrt.tar.gz', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:52:00.845 CET] [debug] <<< testapi::type_string(string=' ; echo 192cU-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:52:03.978 CET] [debug] <<< testapi::wait_serial(regexp=qr/192cU-\d+-/, timeout=90) [2019-02-04T15:52:06.113 CET] [debug] >>> testapi::wait_serial: (?^:192cU-\d+-): ok [2019-02-04T15:52:06.113 CET] [debug] <<< testapi::script_run(cmd='test -n "$(ls -A /var/lib/systemd/coredump)" && cd /var/lib/systemd/coredump && tar czvf coredump.tar.gz *', wait=undef) [2019-02-04T15:52:06.113 CET] [debug] <<< testapi::type_string(string='test -n "$(ls -A /var/lib/systemd/coredump)" && cd /var/lib/systemd/coredump && tar czvf coredump.tar.gz *', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:52:17.220 CET] [debug] <<< testapi::type_string(string=' ; echo JIhgZ-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:52:20.359 CET] [debug] <<< testapi::wait_serial(regexp=qr/JIhgZ-\d+-/, timeout=30) [2019-02-04T15:52:21.511 CET] [debug] >>> testapi::wait_serial: (?^:JIhgZ-\d+-): ok [2019-02-04T15:52:21.512 CET] [debug] <<< testapi::script_run(cmd='tar czvf /tmp/var_log.tar.gz --exclude=\'lastlog\' /var/log', wait=undef) [2019-02-04T15:52:21.512 CET] [debug] <<< testapi::type_string(string='tar czvf /tmp/var_log.tar.gz --exclude=\'lastlog\' /var/log', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:52:27.482 CET] [debug] <<< testapi::type_string(string=' ; echo gWoBc-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:52:30.619 CET] [debug] <<< testapi::wait_serial(timeout=30, regexp=qr/gWoBc-\d+-/) [2019-02-04T15:52:32.770 CET] [debug] >>> testapi::wait_serial: (?^:gWoBc-\d+-): ok [2019-02-04T15:52:32.771 CET] [debug] <<< testapi::upload_logs(file='/tmp/var_log.tar.gz', failok=0, timeout=90) [2019-02-04T15:52:32.771 CET] [debug] <<< testapi::assert_script_run(cmd='curl --form upload=@/tmp/var_log.tar.gz --form upname=modularity_enable_disable_module-var_log.tar.gz http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/var_log.tar.gz', wait=90, fail_message=undef) [2019-02-04T15:52:32.771 CET] [debug] <<< testapi::type_string(string='curl --form upload=@/tmp/var_log.tar.gz --form upname=modularity_enable_disable_module-var_log.tar.gz http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/var_log.tar.gz', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:52:50.056 CET] [debug] <<< testapi::type_string(string=' ; echo SSenX-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:52:53.199 CET] [debug] <<< testapi::wait_serial(regexp=qr/SSenX-\d+-/, timeout=90) [2019-02-04T15:52:55.339 CET] [debug] >>> testapi::wait_serial: (?^:SSenX-\d+-): ok [2019-02-04T15:52:55.339 CET] [debug] <<< testapi::upload_logs(file='/etc/nsswitch.conf', failok=1, timeout=90, failok=1) [2019-02-04T15:52:55.339 CET] [debug] <<< testapi::script_run(cmd='curl --form upload=@/etc/nsswitch.conf --form upname=modularity_enable_disable_module-nsswitch.conf http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/nsswitch.conf', wait=90) [2019-02-04T15:52:55.339 CET] [debug] <<< testapi::type_string(string='curl --form upload=@/etc/nsswitch.conf --form upname=modularity_enable_disable_module-nsswitch.conf http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/nsswitch.conf', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:53:12.332 CET] [debug] <<< testapi::type_string(string=' ; echo Cv~rx-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:53:15.467 CET] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/Cv~rx-\d+-/) [2019-02-04T15:53:17.622 CET] [debug] >>> testapi::wait_serial: (?^:Cv~rx-\d+-): ok [2019-02-04T15:53:17.622 CET] [debug] <<< testapi::upload_logs(file='/root/imgbuild/pylorax.log', failok=1, timeout=90, failok=1) [2019-02-04T15:53:17.622 CET] [debug] <<< testapi::script_run(cmd='curl --form upload=@/root/imgbuild/pylorax.log --form upname=modularity_enable_disable_module-pylorax.log http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/pylorax.log', wait=90) [2019-02-04T15:53:17.623 CET] [debug] <<< testapi::type_string(string='curl --form upload=@/root/imgbuild/pylorax.log --form upname=modularity_enable_disable_module-pylorax.log http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/pylorax.log', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:53:34.993 CET] [debug] <<< testapi::type_string(string=' ; echo g8MvL-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:53:38.125 CET] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/g8MvL-\d+-/) [2019-02-04T15:53:40.283 CET] [debug] >>> testapi::wait_serial: (?^:g8MvL-\d+-): ok [2019-02-04T15:53:40.283 CET] [debug] <<< testapi::upload_logs(file='/root/imgbuild/lorax.log', failok=1, timeout=90, failok=1) [2019-02-04T15:53:40.283 CET] [debug] <<< testapi::script_run(cmd='curl --form upload=@/root/imgbuild/lorax.log --form upname=modularity_enable_disable_module-lorax.log http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/lorax.log', wait=90) [2019-02-04T15:53:40.284 CET] [debug] <<< testapi::type_string(string='curl --form upload=@/root/imgbuild/lorax.log --form upname=modularity_enable_disable_module-lorax.log http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/lorax.log', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:53:57.023 CET] [debug] <<< testapi::type_string(string=' ; echo lkLAC-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:54:00.158 CET] [debug] <<< testapi::wait_serial(regexp=qr/lkLAC-\d+-/, timeout=90) [2019-02-04T15:54:02.314 CET] [debug] >>> testapi::wait_serial: (?^:lkLAC-\d+-): ok [2019-02-04T15:54:02.314 CET] [debug] <<< testapi::upload_logs(file='/root/imgbuild/program.log', failok=1, timeout=90, failok=1) [2019-02-04T15:54:02.314 CET] [debug] <<< testapi::script_run(cmd='curl --form upload=@/root/imgbuild/program.log --form upname=modularity_enable_disable_module-program.log http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/program.log', wait=90) [2019-02-04T15:54:02.314 CET] [debug] <<< testapi::type_string(string='curl --form upload=@/root/imgbuild/program.log --form upname=modularity_enable_disable_module-program.log http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/program.log', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:54:19.669 CET] [debug] <<< testapi::type_string(string=' ; echo 6Otn5-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:54:22.804 CET] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/6Otn5-\d+-/) [2019-02-04T15:54:24.946 CET] [debug] >>> testapi::wait_serial: (?^:6Otn5-\d+-): ok [2019-02-04T15:54:24.947 CET] [debug] Loading a VM snapshot lastgood [2019-02-04T15:54:24.948 CET] [debug] Loading snapshot (Current VM state is running). [2019-02-04T15:54:24.986 CET] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":986368,"seconds":1549292064}} [2019-02-04T15:54:24.986 CET] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json [2019-02-04T15:54:26.996 CET] [debug] QEMU: qemu-system-ppc64: terminating on signal 15 from pid 14014 (/usr/bin/isotovideo: backend) [2019-02-04T15:54:27.001 CET] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/pool/4/raid/hd0-overlay0 /var/lib/openqa/pool/4/raid/hd0-overlay1 10737418240 [2019-02-04T15:54:27.102 CET] [debug] Formatting '/var/lib/openqa/pool/4/raid/hd0-overlay1', fmt=qcow2 size=10737418240 backing_file=/var/lib/openqa/pool/4/raid/hd0-overlay0 cluster_size=65536 lazy_refcounts=off refcount_bits=16 [2019-02-04T15:54:27.102 CET] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/pool/4/raid/cd0-overlay0 /var/lib/openqa/pool/4/raid/cd0-overlay1 3209779200 [2019-02-04T15:54:27.190 CET] [debug] Formatting '/var/lib/openqa/pool/4/raid/cd0-overlay1', fmt=qcow2 size=3209779200 backing_file=/var/lib/openqa/pool/4/raid/cd0-overlay0 cluster_size=65536 lazy_refcounts=off refcount_bits=16 [2019-02-04T15:54:27.190 CET] [debug] starting: /usr/bin/qemu-system-ppc64 -g 1024x768 -vga std -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -soundhw ac97 -global isa-fdc.driveA= -m 4096 -machine usb=off -cpu host -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -boot order=c,menu=on,splash-time=5000 -device nec-usb-xhci -device usb-tablet -device usb-kbd -smp 1 -enable-kvm -no-shutdown -vnc :94,share=force-shared -device virtio-serial -chardev socket,path=virtio_console,server,nowait,id=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev socket,path=qmp_socket,server,nowait,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-overlay1-file,filename=/var/lib/openqa/pool/4/raid/hd0-overlay1,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0-overlay1,file=hd0-overlay1-file,cache.no-flush=on -device virtio-blk,id=hd0-device,drive=hd0-overlay1,bootindex=0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay1-file,filename=/var/lib/openqa/pool/4/raid/cd0-overlay1,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay1,file=cd0-overlay1-file,cache.no-flush=on -device scsi-cd,id=cd0-device,drive=cd0-overlay1,serial=cd0 -incoming defer Attempt 0 at /usr/libexec/os-autoinst/osutils.pm line 130. Attempt 1 at /usr/libexec/os-autoinst/osutils.pm line 130. Attempts terminated! at /usr/libexec/os-autoinst/osutils.pm line 136. [2019-02-04T15:54:29.195 CET] [debug] qmpsocket 14 [2019-02-04T15:54:29.199 CET] [debug] EVENT {"data":{"status":"setup"},"event":"MIGRATION","timestamp":{"microseconds":199241,"seconds":1549292069}} [2019-02-04T15:54:30.201 CET] [debug] EVENT {"data":{"status":"active"},"event":"MIGRATION","timestamp":{"microseconds":203404,"seconds":1549292069}} [2019-02-04T15:54:32.606 CET] [debug] EVENT {"data":{"status":"completed"},"event":"MIGRATION","timestamp":{"microseconds":605959,"seconds":1549292072}} /usr/libexec/os-autoinst/consoles/vnc_base.pm:58:{ 'connect_timeout' => 3, 'hostname' => 'localhost', 'port' => 5994 } [2019-02-04T15:54:32.659 CET] [debug] Restored snapshot [2019-02-04T15:54:32.659 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"55214","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5994","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":607375,"seconds":1549292072}} [2019-02-04T15:54:32.659 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"55214","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5994","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":608790,"seconds":1549292072}} [2019-02-04T15:54:32.659 CET] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":659799,"seconds":1549292072}} [2019-02-04T15:54:32.718 CET] [debug] ||| starting modularity_install_module tests/modularity_install_module.pm [2019-02-04T15:54:32.768 CET] [debug] pointer type 1 0 1024 768 -257 [2019-02-04T15:54:32.768 CET] [debug] led state 0 1 1 -261 [2019-02-04T15:54:32.775 CET] [debug] QEMU: QEMU emulator version 3.0.0 (qemu-3.0.0-3.fc29) [2019-02-04T15:54:32.775 CET] [debug] QEMU: Copyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers [2019-02-04T15:54:32.781 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:8 called installedtest::root_console [2019-02-04T15:54:32.782 CET] [debug] <<< testapi::send_key(key='ctrl-alt-f3', do_wait=0) [2019-02-04T15:54:36.991 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:8 called installedtest::root_console [2019-02-04T15:54:36.991 CET] [debug] <<< testapi::check_screen(mustmatch='user_console', timeout=0) [2019-02-04T15:54:39.179 CET] [debug] WARNING: check_asserted_screen took 2.19 seconds for 6 candidate needles - make your needles more specific [2019-02-04T15:54:39.378 CET] [debug] >>> testapi::_check_backend_response: match=user_console timed out after 0 (check_screen) [2019-02-04T15:54:39.425 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:8 called installedtest::root_console [2019-02-04T15:54:39.425 CET] [debug] <<< testapi::check_screen(mustmatch=[ 'root_console', 'text_console_login' ], timeout=10) [2019-02-04T15:54:39.492 CET] [debug] no match: 9.9s, best candidate: root_logged_in (0.00) [2019-02-04T15:54:40.580 CET] [debug] >>> testapi::_handle_found_needle: found text_console_login, similarity 1.00 @ 72/81 [2019-02-04T15:54:40.580 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:8 called installedtest::root_console [2019-02-04T15:54:40.580 CET] [debug] <<< testapi::type_string(string='root ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:54:41.103 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:8 called installedtest::root_console [2019-02-04T15:54:41.103 CET] [debug] <<< testapi::check_screen(mustmatch=[ 'root_console', 'console_password_required' ], timeout=30) [2019-02-04T15:54:41.456 CET] [debug] no match: 29.6s, best candidate: console_password_required (0.00) [2019-02-04T15:54:42.590 CET] [debug] >>> testapi::_handle_found_needle: found console_password_required, similarity 1.00 @ 1/111 [2019-02-04T15:54:42.590 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:8 called installedtest::root_console [2019-02-04T15:54:42.590 CET] [debug] <<< testapi::type_string(string='weakpassword', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:54:43.848 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:8 called installedtest::root_console [2019-02-04T15:54:43.848 CET] [debug] <<< testapi::send_key(key='ret', do_wait=0) [2019-02-04T15:54:44.067 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:8 called installedtest::root_console [2019-02-04T15:54:44.067 CET] [debug] <<< testapi::check_screen(mustmatch='root_console', timeout=30) [2019-02-04T15:54:44.088 CET] [debug] no match: 29.9s, best candidate: root_logged_in (0.00) [2019-02-04T15:54:45.236 CET] [debug] >>> testapi::_handle_found_needle: found root_logged_in, similarity 1.00 @ 137/144 [2019-02-04T15:54:45.236 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:11 called utils::download_modularity_tests [2019-02-04T15:54:45.236 CET] [debug] <<< testapi::assert_script_run(cmd='curl -o /root/test.py https://pagure.io/fedora-qa/modularity_testing_scripts/raw/master/f/modular_functions.py', wait=90, fail_message=undef) [2019-02-04T15:54:45.236 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:11 called utils::download_modularity_tests [2019-02-04T15:54:45.236 CET] [debug] <<< testapi::type_string(string='curl -o /root/test.py https://pagure.io/fedora-qa/modularity_testing_scripts/raw/master/f/modular_functions.py', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:54:56.760 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:11 called utils::download_modularity_tests [2019-02-04T15:54:56.760 CET] [debug] <<< testapi::type_string(string=' ; echo gMw5A-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:54:59.900 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:11 called utils::download_modularity_tests [2019-02-04T15:54:59.900 CET] [debug] <<< testapi::wait_serial(regexp=qr/gMw5A-\d+-/, timeout=90) [2019-02-04T15:55:03.044 CET] [debug] >>> testapi::wait_serial: (?^:gMw5A-\d+-): ok [2019-02-04T15:55:03.044 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:11 called utils::download_modularity_tests [2019-02-04T15:55:03.044 CET] [debug] <<< testapi::assert_script_run(cmd='chmod 755 /root/test.py', wait=90, fail_message=undef) [2019-02-04T15:55:03.044 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:11 called utils::download_modularity_tests [2019-02-04T15:55:03.044 CET] [debug] <<< testapi::type_string(string='chmod 755 /root/test.py', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:55:05.453 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:11 called utils::download_modularity_tests [2019-02-04T15:55:05.454 CET] [debug] <<< testapi::type_string(string=' ; echo FWbwy-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:55:08.591 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:11 called utils::download_modularity_tests [2019-02-04T15:55:08.591 CET] [debug] <<< testapi::wait_serial(regexp=qr/FWbwy-\d+-/, timeout=90) [2019-02-04T15:55:09.737 CET] [debug] >>> testapi::wait_serial: (?^:FWbwy-\d+-): ok [2019-02-04T15:55:09.737 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:14 called testapi::assert_script_run [2019-02-04T15:55:09.737 CET] [debug] <<< testapi::assert_script_run(cmd='/root/test.py -m nodejs -s 8 -a list', wait=90, fail_message=undef) [2019-02-04T15:55:09.737 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:14 called testapi::assert_script_run [2019-02-04T15:55:09.737 CET] [debug] <<< testapi::type_string(string='/root/test.py -m nodejs -s 8 -a list', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:55:13.507 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:14 called testapi::assert_script_run [2019-02-04T15:55:13.507 CET] [debug] <<< testapi::type_string(string=' ; echo Vk69c-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:55:16.640 CET] [debug] /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm:14 called testapi::assert_script_run [2019-02-04T15:55:16.640 CET] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/Vk69c-\d+-/) [2019-02-04T15:56:30.835 CET] [debug] >>> testapi::wait_serial: (?^:Vk69c-\d+-): ok [2019-02-04T15:56:30.977 CET] [debug] command '/root/test.py -m nodejs -s 8 -a list' failed at /var/lib/openqa/share/tests/fedora/tests/modularity_install_module.pm line 14. [2019-02-04T15:56:30.977 CET] [debug] <<< testapi::check_screen(mustmatch='emergency_rescue', timeout=3) [2019-02-04T15:56:30.980 CET] [debug] no match: 2.9s, best candidate: emergency_rescue-20170119 (0.00) [2019-02-04T15:56:31.983 CET] [debug] no match: 1.9s, best candidate: emergency_rescue-20170119 (0.00) [2019-02-04T15:56:33.042 CET] [debug] no match: 0.9s, best candidate: emergency_rescue-20170119 (0.00) [2019-02-04T15:56:34.318 CET] [debug] >>> testapi::_check_backend_response: match=emergency_rescue timed out after 3 (check_screen) [2019-02-04T15:56:34.369 CET] [debug] <<< testapi::send_key(key='ctrl-alt-f6', do_wait=0) [2019-02-04T15:56:38.575 CET] [debug] <<< testapi::check_screen(mustmatch='user_console', timeout=0) [2019-02-04T15:56:39.043 CET] [debug] >>> testapi::_check_backend_response: match=user_console timed out after 0 (check_screen) [2019-02-04T15:56:39.090 CET] [debug] <<< testapi::check_screen(mustmatch=[ 'root_console', 'text_console_login' ], timeout=10) [2019-02-04T15:56:41.402 CET] [debug] >>> testapi::_handle_found_needle: found text_console_login, similarity 1.00 @ 72/81 [2019-02-04T15:56:41.403 CET] [debug] <<< testapi::type_string(string='root ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:56:41.926 CET] [debug] <<< testapi::check_screen(mustmatch=[ 'root_console', 'console_password_required' ], timeout=30) [2019-02-04T15:56:41.949 CET] [debug] no match: 29.9s, best candidate: console_password_required (0.00) [2019-02-04T15:56:43.091 CET] [debug] >>> testapi::_handle_found_needle: found console_password_required, similarity 1.00 @ 1/111 [2019-02-04T15:56:43.091 CET] [debug] <<< testapi::type_string(string='weakpassword', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:56:44.345 CET] [debug] <<< testapi::send_key(key='ret', do_wait=0) [2019-02-04T15:56:44.550 CET] [debug] <<< testapi::check_screen(mustmatch='root_console', timeout=30) [2019-02-04T15:56:44.571 CET] [debug] no match: 29.9s, best candidate: root_logged_in (0.00) [2019-02-04T15:56:45.712 CET] [debug] >>> testapi::_handle_found_needle: found root_logged_in, similarity 1.00 @ 137/144 Use of uninitialized value in string eq at /var/lib/openqa/share/tests/fedora/lib/utils.pm line 191. Use of uninitialized value in string eq at /var/lib/openqa/share/tests/fedora/lib/utils.pm line 196. [2019-02-04T15:56:45.712 CET] [debug] <<< testapi::check_screen(mustmatch='root_console_dracut', timeout=0) [2019-02-04T15:56:46.786 CET] [debug] >>> testapi::_check_backend_response: match=root_console_dracut timed out after 0 (check_screen) [2019-02-04T15:56:46.827 CET] [debug] <<< testapi::script_run(cmd='dnf -y --nogpgcheck install tar', wait=180) [2019-02-04T15:56:46.827 CET] [debug] <<< testapi::type_string(string='dnf -y --nogpgcheck install tar', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:56:50.076 CET] [debug] <<< testapi::type_string(string=' ; echo ROE55-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:56:53.210 CET] [debug] <<< testapi::wait_serial(timeout=180, regexp=qr/ROE55-\d+-/) [2019-02-04T15:56:58.354 CET] [debug] >>> testapi::wait_serial: (?^:ROE55-\d+-): ok [2019-02-04T15:56:58.354 CET] [debug] <<< testapi::assert_script_run(cmd='rpm -q tar', wait=90, fail_message=undef) [2019-02-04T15:56:58.354 CET] [debug] <<< testapi::type_string(string='rpm -q tar', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:56:59.399 CET] [debug] <<< testapi::type_string(string=' ; echo kFGj4-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:57:02.550 CET] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/kFGj4-\d+-/) [2019-02-04T15:57:03.678 CET] [debug] >>> testapi::wait_serial: (?^:kFGj4-\d+-): ok [2019-02-04T15:57:03.678 CET] [debug] <<< testapi::script_run(cmd='rpm -q tar', wait=undef) [2019-02-04T15:57:03.678 CET] [debug] <<< testapi::type_string(string='rpm -q tar', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:57:04.723 CET] [debug] <<< testapi::type_string(string=' ; echo AnUTU-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:57:07.866 CET] [debug] <<< testapi::wait_serial(timeout=30, regexp=qr/AnUTU-\d+-/) [2019-02-04T15:57:09.031 CET] [debug] >>> testapi::wait_serial: (?^:AnUTU-\d+-): ok [2019-02-04T15:57:09.031 CET] [debug] <<< testapi::script_run(cmd='ping -c 2 10.0.2.2', wait=undef) [2019-02-04T15:57:09.031 CET] [debug] <<< testapi::type_string(string='ping -c 2 10.0.2.2', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:57:10.917 CET] [debug] <<< testapi::type_string(string=' ; echo nG~_Y-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:57:14.063 CET] [debug] <<< testapi::wait_serial(timeout=30, regexp=qr/nG~_Y-\d+-/) [2019-02-04T15:57:16.213 CET] [debug] >>> testapi::wait_serial: (?^:nG~_Y-\d+-): ok [2019-02-04T15:57:16.213 CET] [debug] <<< testapi::script_run(cmd='test -n "$(ls -A /var/tmp/abrt)" && cd /var/tmp/abrt && tar czvf tmpabrt.tar.gz *', wait=undef) [2019-02-04T15:57:16.213 CET] [debug] <<< testapi::type_string(string='test -n "$(ls -A /var/tmp/abrt)" && cd /var/tmp/abrt && tar czvf tmpabrt.tar.gz *', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:57:24.678 CET] [debug] <<< testapi::type_string(string=' ; echo KBIT0-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:57:27.817 CET] [debug] <<< testapi::wait_serial(timeout=30, regexp=qr/KBIT0-\d+-/) [2019-02-04T15:57:28.975 CET] [debug] >>> testapi::wait_serial: (?^:KBIT0-\d+-): ok [2019-02-04T15:57:28.975 CET] [debug] <<< testapi::script_run(cmd='test -n "$(ls -A /var/spool/abrt)" && cd /var/spool/abrt && tar czvf spoolabrt.tar.gz *', wait=undef) [2019-02-04T15:57:28.975 CET] [debug] <<< testapi::type_string(string='test -n "$(ls -A /var/spool/abrt)" && cd /var/spool/abrt && tar czvf spoolabrt.tar.gz *', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:57:38.100 CET] [debug] <<< testapi::type_string(string=' ; echo kWuOo-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:57:41.241 CET] [debug] <<< testapi::wait_serial(timeout=30, regexp=qr/kWuOo-\d+-/) [2019-02-04T15:57:42.722 CET] [debug] >>> testapi::wait_serial: (?^:kWuOo-\d+-): ok [2019-02-04T15:57:42.723 CET] [debug] <<< testapi::upload_logs(file='/var/spool/abrt/spoolabrt.tar.gz', failok=0, timeout=90) [2019-02-04T15:57:42.723 CET] [debug] <<< testapi::assert_script_run(cmd='curl --form upload=@/var/spool/abrt/spoolabrt.tar.gz --form upname=modularity_install_module-spoolabrt.tar.gz http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/spoolabrt.tar.gz', wait=90, fail_message=undef) [2019-02-04T15:57:42.723 CET] [debug] <<< testapi::type_string(string='curl --form upload=@/var/spool/abrt/spoolabrt.tar.gz --form upname=modularity_install_module-spoolabrt.tar.gz http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/spoolabrt.tar.gz', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:58:01.029 CET] [debug] <<< testapi::type_string(string=' ; echo X_bVV-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:58:04.170 CET] [debug] <<< testapi::wait_serial(regexp=qr/X_bVV-\d+-/, timeout=90) [2019-02-04T15:58:06.324 CET] [debug] >>> testapi::wait_serial: (?^:X_bVV-\d+-): ok [2019-02-04T15:58:06.324 CET] [debug] <<< testapi::script_run(cmd='test -n "$(ls -A /var/lib/systemd/coredump)" && cd /var/lib/systemd/coredump && tar czvf coredump.tar.gz *', wait=undef) [2019-02-04T15:58:06.325 CET] [debug] <<< testapi::type_string(string='test -n "$(ls -A /var/lib/systemd/coredump)" && cd /var/lib/systemd/coredump && tar czvf coredump.tar.gz *', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:58:17.431 CET] [debug] <<< testapi::type_string(string=' ; echo JIhgZ-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:58:20.566 CET] [debug] <<< testapi::wait_serial(regexp=qr/JIhgZ-\d+-/, timeout=30) [2019-02-04T15:58:21.708 CET] [debug] >>> testapi::wait_serial: (?^:JIhgZ-\d+-): ok [2019-02-04T15:58:21.708 CET] [debug] <<< testapi::script_run(cmd='tar czvf /tmp/var_log.tar.gz --exclude=\'lastlog\' /var/log', wait=undef) [2019-02-04T15:58:21.708 CET] [debug] <<< testapi::type_string(string='tar czvf /tmp/var_log.tar.gz --exclude=\'lastlog\' /var/log', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:58:27.681 CET] [debug] <<< testapi::type_string(string=' ; echo gWoBc-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:58:30.823 CET] [debug] <<< testapi::wait_serial(regexp=qr/gWoBc-\d+-/, timeout=30) [2019-02-04T15:58:32.987 CET] [debug] >>> testapi::wait_serial: (?^:gWoBc-\d+-): ok [2019-02-04T15:58:32.987 CET] [debug] <<< testapi::upload_logs(file='/tmp/var_log.tar.gz', failok=0, timeout=90) [2019-02-04T15:58:32.987 CET] [debug] <<< testapi::assert_script_run(cmd='curl --form upload=@/tmp/var_log.tar.gz --form upname=modularity_install_module-var_log.tar.gz http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/var_log.tar.gz', wait=90, fail_message=undef) [2019-02-04T15:58:32.987 CET] [debug] <<< testapi::type_string(string='curl --form upload=@/tmp/var_log.tar.gz --form upname=modularity_install_module-var_log.tar.gz http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/var_log.tar.gz', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:58:49.539 CET] [debug] <<< testapi::type_string(string=' ; echo tPLjk-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:58:52.684 CET] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/tPLjk-\d+-/) [2019-02-04T15:58:54.832 CET] [debug] >>> testapi::wait_serial: (?^:tPLjk-\d+-): ok [2019-02-04T15:58:54.832 CET] [debug] <<< testapi::upload_logs(file='/etc/nsswitch.conf', failok=1, timeout=90, failok=1) [2019-02-04T15:58:54.832 CET] [debug] <<< testapi::script_run(cmd='curl --form upload=@/etc/nsswitch.conf --form upname=modularity_install_module-nsswitch.conf http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/nsswitch.conf', wait=90) [2019-02-04T15:58:54.832 CET] [debug] <<< testapi::type_string(string='curl --form upload=@/etc/nsswitch.conf --form upname=modularity_install_module-nsswitch.conf http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/nsswitch.conf', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:59:11.038 CET] [debug] <<< testapi::type_string(string=' ; echo pNenl-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:59:14.175 CET] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/pNenl-\d+-/) [2019-02-04T15:59:16.316 CET] [debug] >>> testapi::wait_serial: (?^:pNenl-\d+-): ok [2019-02-04T15:59:16.316 CET] [debug] <<< testapi::upload_logs(file='/root/imgbuild/pylorax.log', failok=1, timeout=90, failok=1) [2019-02-04T15:59:16.316 CET] [debug] <<< testapi::script_run(cmd='curl --form upload=@/root/imgbuild/pylorax.log --form upname=modularity_install_module-pylorax.log http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/pylorax.log', wait=90) [2019-02-04T15:59:16.316 CET] [debug] <<< testapi::type_string(string='curl --form upload=@/root/imgbuild/pylorax.log --form upname=modularity_install_module-pylorax.log http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/pylorax.log', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:59:32.947 CET] [debug] <<< testapi::type_string(string=' ; echo VCtqQ-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:59:36.083 CET] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/VCtqQ-\d+-/) [2019-02-04T15:59:38.215 CET] [debug] >>> testapi::wait_serial: (?^:VCtqQ-\d+-): ok [2019-02-04T15:59:38.215 CET] [debug] <<< testapi::upload_logs(file='/root/imgbuild/lorax.log', failok=1, timeout=90, failok=1) [2019-02-04T15:59:38.215 CET] [debug] <<< testapi::script_run(cmd='curl --form upload=@/root/imgbuild/lorax.log --form upname=modularity_install_module-lorax.log http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/lorax.log', wait=90) [2019-02-04T15:59:38.215 CET] [debug] <<< testapi::type_string(string='curl --form upload=@/root/imgbuild/lorax.log --form upname=modularity_install_module-lorax.log http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/lorax.log', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:59:54.224 CET] [debug] <<< testapi::type_string(string=' ; echo NGzFC-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T15:59:57.368 CET] [debug] <<< testapi::wait_serial(regexp=qr/NGzFC-\d+-/, timeout=90) [2019-02-04T15:59:59.518 CET] [debug] >>> testapi::wait_serial: (?^:NGzFC-\d+-): ok [2019-02-04T15:59:59.518 CET] [debug] <<< testapi::upload_logs(file='/root/imgbuild/program.log', failok=1, timeout=90, failok=1) [2019-02-04T15:59:59.518 CET] [debug] <<< testapi::script_run(cmd='curl --form upload=@/root/imgbuild/program.log --form upname=modularity_install_module-program.log http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/program.log', wait=90) [2019-02-04T15:59:59.519 CET] [debug] <<< testapi::type_string(string='curl --form upload=@/root/imgbuild/program.log --form upname=modularity_install_module-program.log http://10.0.2.2:20043/GehXObffe2mb3Kc1/uploadlog/program.log', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T16:00:16.156 CET] [debug] <<< testapi::type_string(string=' ; echo z1RjR-$?- > /dev/hvc0 ', max_interval=250, wait_screen_changes=0, wait_still_screen=0) [2019-02-04T16:00:19.295 CET] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/z1RjR-\d+-/) [2019-02-04T16:00:21.438 CET] [debug] >>> testapi::wait_serial: (?^:z1RjR-\d+-): ok [2019-02-04T16:00:21.440 CET] [debug] Loading a VM snapshot lastgood [2019-02-04T16:00:21.441 CET] [debug] Loading snapshot (Current VM state is running). [2019-02-04T16:00:21.488 CET] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":487846,"seconds":1549292421}} [2019-02-04T16:00:21.488 CET] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json [2019-02-04T16:00:23.496 CET] [debug] QEMU: qemu-system-ppc64: terminating on signal 15 from pid 14014 (/usr/bin/isotovideo: backend) [2019-02-04T16:00:23.529 CET] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/pool/4/raid/hd0-overlay0 /var/lib/openqa/pool/4/raid/hd0-overlay1 10737418240 [2019-02-04T16:00:24.386 CET] [debug] Formatting '/var/lib/openqa/pool/4/raid/hd0-overlay1', fmt=qcow2 size=10737418240 backing_file=/var/lib/openqa/pool/4/raid/hd0-overlay0 cluster_size=65536 lazy_refcounts=off refcount_bits=16 [2019-02-04T16:00:24.387 CET] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/pool/4/raid/cd0-overlay0 /var/lib/openqa/pool/4/raid/cd0-overlay1 3209779200 [2019-02-04T16:00:24.472 CET] [debug] Formatting '/var/lib/openqa/pool/4/raid/cd0-overlay1', fmt=qcow2 size=3209779200 backing_file=/var/lib/openqa/pool/4/raid/cd0-overlay0 cluster_size=65536 lazy_refcounts=off refcount_bits=16 [2019-02-04T16:00:24.473 CET] [debug] starting: /usr/bin/qemu-system-ppc64 -g 1024x768 -vga std -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -soundhw ac97 -global isa-fdc.driveA= -m 4096 -machine usb=off -cpu host -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -boot order=c,menu=on,splash-time=5000 -device nec-usb-xhci -device usb-tablet -device usb-kbd -smp 1 -enable-kvm -no-shutdown -vnc :94,share=force-shared -device virtio-serial -chardev socket,path=virtio_console,server,nowait,id=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev socket,path=qmp_socket,server,nowait,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-overlay1-file,filename=/var/lib/openqa/pool/4/raid/hd0-overlay1,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0-overlay1,file=hd0-overlay1-file,cache.no-flush=on -device virtio-blk,id=hd0-device,drive=hd0-overlay1,bootindex=0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay1-file,filename=/var/lib/openqa/pool/4/raid/cd0-overlay1,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay1,file=cd0-overlay1-file,cache.no-flush=on -device scsi-cd,id=cd0-device,drive=cd0-overlay1,serial=cd0 -incoming defer Attempt 0 at /usr/libexec/os-autoinst/osutils.pm line 130. Attempt 1 at /usr/libexec/os-autoinst/osutils.pm line 130. Attempts terminated! at /usr/libexec/os-autoinst/osutils.pm line 136. [2019-02-04T16:00:26.477 CET] [debug] qmpsocket 14 [2019-02-04T16:00:26.482 CET] [debug] EVENT {"data":{"status":"setup"},"event":"MIGRATION","timestamp":{"microseconds":481930,"seconds":1549292426}} [2019-02-04T16:00:27.483 CET] [debug] EVENT {"data":{"status":"active"},"event":"MIGRATION","timestamp":{"microseconds":485560,"seconds":1549292426}} [2019-02-04T16:00:30.250 CET] [debug] EVENT {"data":{"status":"completed"},"event":"MIGRATION","timestamp":{"microseconds":249956,"seconds":1549292430}} /usr/libexec/os-autoinst/consoles/vnc_base.pm:58:{ 'connect_timeout' => 3, 'hostname' => 'localhost', 'port' => 5994 } [2019-02-04T16:00:30.303 CET] [debug] pointer type 1 0 1024 768 -257 [2019-02-04T16:00:30.303 CET] [debug] led state 0 1 1 -261 [2019-02-04T16:00:30.309 CET] [debug] Restored snapshot [2019-02-04T16:00:30.309 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"58332","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5994","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":251470,"seconds":1549292430}} [2019-02-04T16:00:30.309 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"58332","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5994","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":252962,"seconds":1549292430}} [2019-02-04T16:00:30.309 CET] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":309667,"seconds":1549292430}} [2019-02-04T16:00:30.351 CET] [debug] [autotest] process exited: 0 [2019-02-04T16:00:30.353 CET] [debug] QEMU: QEMU emulator version 3.0.0 (qemu-3.0.0-3.fc29) [2019-02-04T16:00:30.354 CET] [debug] QEMU: Copyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers [2019-02-04T16:00:32.353 CET] [debug] commands process exited: 0 [2019-02-04T16:00:33.353 CET] [debug] isotovideo done [2019-02-04T16:00:33.354 CET] [debug] QEMU status is not shutdown it is running [2019-02-04T16:00:33.354 CET] [debug] BACKEND SHUTDOWN [2019-02-04T16:00:33.361 CET] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json last frame [2019-02-04T16:00:35.679 CET] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json [2019-02-04T16:00:35.680 CET] [debug] QEMU: qemu-system-ppc64: terminating on signal 15 from pid 14014 (/usr/bin/isotovideo: backend) [2019-02-04T16:00:35.680 CET] [debug] sending magic and exit [2019-02-04T16:00:35.680 CET] [debug] received magic close [2019-02-04T16:00:35.685 CET] [debug] backend process exited: 0 [2019-02-04T16:00:36.686 CET] [debug] killing backend process 14014 [2019-02-04T16:00:36.686 CET] [debug] done with backend process 14009: EXIT 0 [2019-02-04T16:00:36.0700 CET] [info] Isotovideo exit status: 0 [2019-02-04T16:00:36.0726 CET] [info] +++ worker notes +++ [2019-02-04T16:00:36.0726 CET] [info] end time: 2019-02-04 15:00:36 [2019-02-04T16:00:36.0726 CET] [info] result: done [2019-02-04T16:00:36.0726 CET] [info] uploading modularity_enable_disable_module-nsswitch.conf [2019-02-04T16:00:36.0751 CET] [info] uploading modularity_enable_disable_module-spoolabrt.tar.gz [2019-02-04T16:00:36.0770 CET] [info] uploading modularity_enable_disable_module-var_log.tar.gz [2019-02-04T16:00:36.0794 CET] [info] uploading modularity_install_module-nsswitch.conf [2019-02-04T16:00:36.0809 CET] [info] uploading modularity_install_module-spoolabrt.tar.gz [2019-02-04T16:00:36.0830 CET] [info] uploading modularity_install_module-var_log.tar.gz [2019-02-04T16:00:36.0854 CET] [info] uploading video.ogv [2019-02-04T16:00:36.0893 CET] [info] uploading video_time.vtt [2019-02-04T16:00:36.0912 CET] [info] uploading vars.json [2019-02-04T16:00:36.0928 CET] [info] uploading serial0.txt [2019-02-04T16:00:36.0945 CET] [info] uploading autoinst-log.txt