|
[2018-10-18T15:37:45.0012 CEST] [info] +++ setup notes +++
|
|
[2018-10-18T15:37:45.0012 CEST] [info] start time: 2018-10-18 13:37:45
|
|
[2018-10-18T15:37:45.0012 CEST] [info] running on openqaworker6:1 (Linux 4.4.104-39-default #1 SMP Thu Jan 4 08:11:03 UTC 2018 (7db1912) x86_64)
|
|
[2018-10-18T15:37:45.0032 CEST] [info] Downloading sle-15-SP1-x86_64-75.6-textmode@64bit.qcow2 from openqa.suse.de/tests/2188633/asset/hdd/sle-15-SP1-x86_64-75.6-textmode@64bit.qcow2
|
|
[2018-10-18T15:37:51.0007 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:37:51.0091 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:37:57.0004 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:37:57.0051 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:38:03.0005 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:38:03.0079 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:38:09.0003 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:38:09.0078 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:38:15.0009 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:38:15.0058 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:38:21.0016 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:38:21.0071 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:38:27.0004 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:38:27.0061 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:38:33.0057 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:38:33.0124 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:38:39.0153 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:38:39.0245 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:38:45.0020 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:38:45.0069 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:38:51.0136 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:38:51.0183 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:38:57.0148 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:38:57.0208 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:39:03.0180 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:39:03.0239 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:39:09.0185 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:39:09.0282 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:39:15.0003 CEST] [debug] POST http://openqa.suse.de/api/v1/jobs/2188633/status
|
|
[2018-10-18T15:39:15.0106 CEST] [debug] [Worker#1200] Update status so job '2188633' is not considered dead.
|
|
[2018-10-18T15:39:17.0645 CEST] [debug] CACHE: Health: Real size: 50586148864, Configured limit: 53687091200
|
|
[2018-10-18T15:39:17.0646 CEST] [info] CACHE: updating the /var/lib/openqa/cache/sle-15-SP1-x86_64-75.6-textmode@64bit.qcow2 with "3e3a0000-5787f6685a466" and 1043988480
|
|
[2018-10-18T15:39:17.0646 CEST] [debug] CACHE: Asset download successful to /var/lib/openqa/cache/sle-15-SP1-x86_64-75.6-textmode@64bit.qcow2, Cache size is: 51630137344
|
|
[2018-10-18T15:39:17.0648 CEST] [info] Downloading SLE-15-SP1-Installer-DVD-x86_64-Build75.6-Media1.iso from openqa.suse.de/tests/2188633/asset/iso/SLE-15-SP1-Installer-DVD-x86_64-Build75.6-Media1.iso
|
|
[2018-10-18T15:39:17.0700 CEST] [info] CACHE: updating the /var/lib/openqa/cache/SLE-15-SP1-Installer-DVD-x86_64-Build75.6-Media1.iso last usage
|
|
[2018-10-18T15:39:17.0700 CEST] [debug] CACHE: Content has not changed, not downloading the /var/lib/openqa/cache/SLE-15-SP1-Installer-DVD-x86_64-Build75.6-Media1.iso but updating last use
|
|
[2018-10-18T15:39:17.0702 CEST] [info] Downloading sle-15-SP1-x86_64-75.6-textmode@64bit-uefi-vars.qcow2 from openqa.suse.de/tests/2188633/asset/hdd/sle-15-SP1-x86_64-75.6-textmode@64bit-uefi-vars.qcow2
|
|
[2018-10-18T15:39:17.0760 CEST] [debug] CACHE: Download of /var/lib/openqa/cache/sle-15-SP1-x86_64-75.6-textmode@64bit-uefi-vars.qcow2 failed with: 404 - Not Found
|
|
[2018-10-18T15:39:17.0761 CEST] [debug] CACHE: removed /var/lib/openqa/cache/sle-15-SP1-x86_64-75.6-textmode@64bit-uefi-vars.qcow2
|
|
[2018-10-18T15:39:17.0884 CEST] [info] rsync: receiving incremental file list
|
|
|
|
[2018-10-18T15:39:19.0165 CEST] [info] rsync:
|
|
|
|
[2018-10-18T15:39:19.0236 CEST] [info] rsync: sent 2,599 bytes received 2,024,493 bytes 810,836.80 bytes/sec
|
|
|
|
[2018-10-18T15:39:19.0237 CEST] [info] rsync: total size is 7,786,917,950 speedup is 3,841.42
|
|
|
|
[2018-10-18T15:39:19.0388 CEST] [debug] +++ worker notes +++
|
|
[2018-10-18T15:39:19.0388 CEST] [debug] start time: 2018-10-18 13:39:19
|
|
[2018-10-18T15:39:19.0388 CEST] [debug] running on openqaworker6:1 (Linux 4.4.104-39-default #1 SMP Thu Jan 4 08:11:03 UTC 2018 (7db1912) x86_64)
|
|
[2018-10-18T15:39:20.0157 CEST] [debug] Current version is 4.5.1539790249.0e665154 [interface v13]
|
|
[2018-10-18T15:39:20.0165 CEST] [debug] git hash in /var/lib/openqa/cache/tests/sle: f64b1ad7ee6ee28c80ad4d9298fac959ee71ac8e
|
|
[2018-10-18T15:39:20.0178 CEST] [info] cmdsrv: daemon reachable under http://*:20013/mJdkzEZGeyb7og5e/
|
|
[2018-10-18T15:39:20.0181 CEST] [info] Listening at "http://[::]:20013"
|
|
Server available at http://[::]:20013
|
|
[2018-10-18T15:39:20.0250 CEST] [debug] default desktop: textmode
|
|
[2018-10-18T15:39:20.0250 CEST] [debug] usingenv DESKTOP=textmode
|
|
[2018-10-18T15:39:20.0250 CEST] [debug] usingenv TEXTMODE=1
|
|
[2018-10-18T15:39:20.0250 CEST] [debug] usingenv DISTRI=sle
|
|
[2018-10-18T15:39:20.0250 CEST] [debug] usingenv NOAUTOLOGIN=1
|
|
[2018-10-18T15:39:20.0250 CEST] [debug] usingenv QEMUCPU=qemu64
|
|
[2018-10-18T15:39:20.0250 CEST] [debug] usingenv INSTLANG=en_US
|
|
[2018-10-18T15:39:20.0250 CEST] [debug] usingenv DVD=1
|
|
[2018-10-18T15:39:20.0250 CEST] [debug] usingenv ISO=/var/lib/openqa/pool/1/SLE-15-SP1-Installer-DVD-x86_64-Build75.6-Media1.iso
|
|
[2018-10-18T15:39:20.0250 CEST] [debug] usingenv ISO_MAXSIZE=4700372992
|
|
[2018-10-18T15:39:20.0251 CEST] [debug] usingenv SYSTEM_ROLE=default
|
|
[2018-10-18T15:39:20.0251 CEST] [debug] usingenv SCC_REGISTER=installation
|
|
[2018-10-18T15:39:20.0251 CEST] [debug] usingenv SLE_PRODUCT=sles
|
|
[2018-10-18T15:39:20.0513 CEST] [debug] scheduling boot_to_desktop tests/boot/boot_to_desktop.pm
|
|
[2018-10-18T15:39:20.0515 CEST] [debug] scheduling systemd_testsuite tests/console/systemd_testsuite.pm
|
|
[2018-10-18T15:39:20.0521 CEST] [debug] init needles from /var/lib/openqa/cache/tests/sle/products/sle/needles
|
|
[2018-10-18T15:39:22.0177 CEST] [debug] loaded 7480 needles
|
|
[2018-10-18T15:39:22.0383 CEST] [debug] git hash in /var/lib/openqa/cache/tests/sle/products/sle/needles: 19f6f1e31380b5a90134cc3861596056dade02c8
|
|
28541: channel_out 15, channel_in 14
|
|
28618: cmdpipe 13, rsppipe 16
|
|
[2018-10-18T15:39:22.0698 CEST] [debug] started mgmt loop with pid 28618
|
|
remove_tree qemuscreenshot
|
|
[2018-10-18T15:39:22.0710 CEST] [debug] running /usr/bin/chattr -f +C /var/lib/openqa/pool/1/raid
|
|
[2018-10-18T15:39:22.0728 CEST] [debug] running /usr/bin/qemu-img info --output=json /var/lib/openqa/pool/1/sle-15-SP1-x86_64-75.6-textmode@64bit.qcow2
|
|
[2018-10-18T15:39:22.0747 CEST] [debug] {
|
|
"virtual-size": 42949672960,
|
|
"filename": "/var/lib/openqa/pool/1/sle-15-SP1-x86_64-75.6-textmode@64bit.qcow2",
|
|
"cluster-size": 65536,
|
|
"format": "qcow2",
|
|
"actual-size": 1045012480,
|
|
"format-specific": {
|
|
"type": "qcow2",
|
|
"data": {
|
|
"compat": "1.1",
|
|
"lazy-refcounts": false,
|
|
"refcount-bits": 16,
|
|
"corrupt": false
|
|
}
|
|
},
|
|
"dirty-flag": false
|
|
}
|
|
|
|
[2018-10-18T15:39:22.0748 CEST] [debug] running /usr/bin/qemu-img info --output=json /var/lib/openqa/pool/1/SLE-15-SP1-Installer-DVD-x86_64-Build75.6-Media1.iso
|
|
[2018-10-18T15:39:22.0766 CEST] [debug] {
|
|
"virtual-size": 668991488,
|
|
"filename": "/var/lib/openqa/pool/1/SLE-15-SP1-Installer-DVD-x86_64-Build75.6-Media1.iso",
|
|
"format": "raw",
|
|
"actual-size": 669650944,
|
|
"dirty-flag": false
|
|
}
|
|
|
|
[2018-10-18T15:39:22.0767 CEST] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/pool/1/sle-15-SP1-x86_64-75.6-textmode@64bit.qcow2 /var/lib/openqa/pool/1/raid/hd0-overlay0 42949672960
|
|
[2018-10-18T15:39:22.0789 CEST] [debug] Formatting '/var/lib/openqa/pool/1/raid/hd0-overlay0', fmt=qcow2 size=42949672960 backing_file=/var/lib/openqa/pool/1/sle-15-SP1-x86_64-75.6-textmode@64bit.qcow2 encryption=off cluster_size=65536 lazy_refcounts=off refcount_bits=16
|
|
|
|
[2018-10-18T15:39:22.0790 CEST] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/pool/1/SLE-15-SP1-Installer-DVD-x86_64-Build75.6-Media1.iso /var/lib/openqa/pool/1/raid/cd0-overlay0 668991488
|
|
[2018-10-18T15:39:22.0812 CEST] [debug] Formatting '/var/lib/openqa/pool/1/raid/cd0-overlay0', fmt=qcow2 size=668991488 backing_file=/var/lib/openqa/pool/1/SLE-15-SP1-Installer-DVD-x86_64-Build75.6-Media1.iso encryption=off cluster_size=65536 lazy_refcounts=off refcount_bits=16
|
|
|
|
[2018-10-18T15:39:22.0813 CEST] [debug] starting: /usr/bin/qemu-system-x86_64 -vga cirrus -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -soundhw ac97 -global isa-fdc.driveA= -m 2048 -cpu qemu64 -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 usb-ehci -device usb-tablet -smp 1 -enable-kvm -no-shutdown -vnc :91,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/1/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/1/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/lib/os-autoinst/osutils.pm line 131.
|
|
Attempt 1 at /usr/lib/os-autoinst/osutils.pm line 131.
|
|
Attempts terminated! at /usr/lib/os-autoinst/osutils.pm line 137.
|
|
[2018-10-18T15:39:24.0821 CEST] [debug] qmpsocket 9
|
|
/usr/lib/os-autoinst/consoles/vnc_base.pm:71:{
|
|
'port' => 5991,
|
|
'hostname' => 'localhost',
|
|
'connect_timeout' => 3
|
|
}
|
|
[2018-10-18T15:39:24.0894 CEST] [debug] pointer type 0 0 640 480 -257
|
|
[2018-10-18T15:39:24.0894 CEST] [debug] led state 0 1 1 -261
|
|
Start CPU
|
|
[2018-10-18T15:39:24.0907 CEST] [debug] EVENT {"event":"VNC_CONNECTED","data":{"server":{"host":"0.0.0.0","auth":"none","service":"5991","family":"ipv4","websocket":false},"client":{"host":"127.0.0.1","service":"45254","websocket":false,"family":"ipv4"}},"timestamp":{"seconds":1539869964,"microseconds":841014}}
|
|
[2018-10-18T15:39:24.0907 CEST] [debug] EVENT {"event":"VNC_INITIALIZED","data":{"server":{"host":"0.0.0.0","auth":"none","service":"5991","websocket":false,"family":"ipv4"},"client":{"host":"127.0.0.1","websocket":false,"family":"ipv4","service":"45254"}},"timestamp":{"microseconds":842611,"seconds":1539869964}}
|
|
[2018-10-18T15:39:24.0907 CEST] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":906373,"seconds":1539869964}}
|
|
GOT GO
|
|
|
|
[2018-10-18T15:39:24.0916 CEST] [debug] QEMU: QEMU emulator version 2.9.1(openSUSE Leap 42.3)
|
|
[2018-10-18T15:39:24.0916 CEST] [debug] QEMU: Copyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers
|
|
[2018-10-18T15:39:24.0920 CEST] [debug] Snapshots are supported
|
|
[2018-10-18T15:39:24.0921 CEST] [debug] ||| starting boot_to_desktop tests/boot/boot_to_desktop.pm
|
|
[2018-10-18T15:39:24.0930 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/boot/boot_to_desktop.pm:36 called opensusebasetest::wait_boot
|
|
[2018-10-18T15:39:24.0931 CEST] [debug] <<< testapi::check_screen(mustmatch=[
|
|
'grub2'
|
|
], timeout=80)
|
|
[2018-10-18T15:39:26.0443 CEST] [debug] WARNING: check_asserted_screen took 0.53 seconds for 24 candidate needles - make your needles more specific
|
|
[2018-10-18T15:39:26.0443 CEST] [debug] no match: 79.0s, best candidate: bootmenu-SLE-HPC-20180603 (0.00)
|
|
[2018-10-18T15:39:26.0909 CEST] [debug] no change: 78.0s
|
|
[2018-10-18T15:39:28.0126 CEST] [debug] no match: 77.0s, best candidate: bootmenu-SLE-HPC-20180603 (0.00)
|
|
[2018-10-18T15:39:29.0119 CEST] [debug] no match: 76.0s, best candidate: bootmenu-SLE-HPC-20180603 (0.00)
|
|
[2018-10-18T15:39:33.0586 CEST] [debug] WARNING: check_asserted_screen took 3.67 seconds for 24 candidate needles - make your needles more specific
|
|
[2018-10-18T15:39:33.0586 CEST] [debug] no match: 75.0s, best candidate: bootmenu-SLE-HPC-20180603 (0.00)
|
|
[2018-10-18T15:39:33.0966 CEST] [debug] no match: 71.3s, best candidate: bootmenu-SLE-HPC-20180603 (0.00)
|
|
[2018-10-18T15:39:38.0147 CEST] [debug] >>> testapi::_handle_found_needle: found bootmenu-SLES15-generic-20180131, similarity 1.00 @ 154/208
|
|
[2018-10-18T15:39:38.0148 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/boot/boot_to_desktop.pm:36 called opensusebasetest::wait_boot
|
|
[2018-10-18T15:39:38.0148 CEST] [debug] <<< testapi::send_key(key='ret', do_wait=0)
|
|
[2018-10-18T15:39:38.0357 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/boot/boot_to_desktop.pm:36 called opensusebasetest::wait_boot
|
|
[2018-10-18T15:39:38.0357 CEST] [debug] <<< testapi::assert_screen(mustmatch=[
|
|
'linux-login',
|
|
'emergency-shell',
|
|
'emergency-mode'
|
|
], timeout=200)
|
|
[2018-10-18T15:39:38.0981 CEST] [debug] WARNING: check_asserted_screen took 0.61 seconds for 24 candidate needles - make your needles more specific
|
|
[2018-10-18T15:39:38.0981 CEST] [debug] no match: 199.9s, best candidate: installation-autoyast-linuxlogin-20171204 (0.29)
|
|
[2018-10-18T15:39:39.0599 CEST] [debug] no match: 198.9s, best candidate: installation-autoyast-linuxlogin-20171204 (0.29)
|
|
[2018-10-18T15:39:40.0373 CEST] [debug] no change: 197.9s
|
|
[2018-10-18T15:39:41.0374 CEST] [debug] no change: 196.9s
|
|
[2018-10-18T15:39:41.0612 CEST] [debug] pointer type 1 0 800 599 -257
|
|
[2018-10-18T15:39:45.0855 CEST] [debug] WARNING: check_asserted_screen took 3.48 seconds for 24 candidate needles - make your needles more specific
|
|
[2018-10-18T15:39:45.0855 CEST] [debug] no match: 195.9s, best candidate: installation-autoyast-linuxlogin-20171204 (0.29)
|
|
[2018-10-18T15:39:46.0232 CEST] [debug] no match: 192.4s, best candidate: linux-login-bsc1055103-20170822 (0.00)
|
|
[2018-10-18T15:39:47.0060 CEST] [debug] no match: 191.5s, best candidate: linux-login-bsc1055103-20170822 (0.00)
|
|
[2018-10-18T15:39:51.0288 CEST] [debug] WARNING: check_asserted_screen took 3.43 seconds for 24 candidate needles - make your needles more specific
|
|
[2018-10-18T15:39:51.0291 CEST] [debug] no match: 190.5s, best candidate: linux-login-bsc1055103-20170822 (0.00)
|
|
[2018-10-18T15:39:51.0490 CEST] [debug] no match: 187.0s, best candidate: linux-login-bsc1055103-20170822 (0.00)
|
|
[2018-10-18T15:39:52.0293 CEST] [debug] no change: 186.0s
|
|
[2018-10-18T15:39:56.0900 CEST] [debug] WARNING: check_asserted_screen took 3.61 seconds for 24 candidate needles - make your needles more specific
|
|
[2018-10-18T15:39:56.0904 CEST] [debug] no match: 185.0s, best candidate: installation-autoyast-linuxlogin-20171204 (0.07)
|
|
[2018-10-18T15:39:57.0110 CEST] [debug] no match: 181.4s, best candidate: linux-login-bsc1055103-20170822 (0.00)
|
|
[2018-10-18T15:40:01.0214 CEST] [debug] WARNING: check_asserted_screen took 3.31 seconds for 24 candidate needles - make your needles more specific
|
|
[2018-10-18T15:40:01.0218 CEST] [debug] no match: 180.4s, best candidate: installation-autoyast-linuxlogin-20171204 (0.07)
|
|
[2018-10-18T15:40:01.0379 CEST] [debug] no match: 177.1s, best candidate: linux-login-bsc1055103-20170822 (0.00)
|
|
[2018-10-18T15:40:02.0422 CEST] [debug] no match: 176.1s, best candidate: linux-login-bsc1055103-20170822 (0.00)
|
|
[2018-10-18T15:40:06.0490 CEST] [debug] WARNING: check_asserted_screen took 3.27 seconds for 24 candidate needles - make your needles more specific
|
|
[2018-10-18T15:40:06.0494 CEST] [debug] no match: 175.1s, best candidate: installation-autoyast-linuxlogin-20171204 (0.07)
|
|
[2018-10-18T15:40:06.0691 CEST] [debug] no match: 171.8s, best candidate: linux-login-bsc1055103-20170822 (0.00)
|
|
[2018-10-18T15:40:10.0605 CEST] [debug] WARNING: check_asserted_screen took 3.11 seconds for 24 candidate needles - make your needles more specific
|
|
[2018-10-18T15:40:10.0608 CEST] [debug] no match: 170.8s, best candidate: installation-autoyast-linuxlogin-20171204 (0.07)
|
|
[2018-10-18T15:40:10.0796 CEST] [debug] no match: 167.7s, best candidate: linux-login-bsc1055103-20170822 (0.00)
|
|
[2018-10-18T15:40:11.0811 CEST] [debug] no match: 166.7s, best candidate: linux-login-bsc1055103-20170822 (0.00)
|
|
[2018-10-18T15:40:15.0851 CEST] [debug] >>> testapi::_handle_found_needle: found autoyast-system-login-console-minimal-20181012, similarity 1.00 @ 67/754
|
|
[2018-10-18T15:40:15.0854 CEST] [debug] ||| finished boot_to_desktop boot at 2018-10-18 13:40:15 (51 s)
|
|
[2018-10-18T15:40:15.0855 CEST] [debug] Creating a VM snapshot lastgood
|
|
[2018-10-18T15:40:15.0856 CEST] [debug] EVENT {"event":"NIC_RX_FILTER_CHANGED","data":{"path":"/machine/peripheral-anon/device[0]/virtio-backend"},"timestamp":{"seconds":1539869994,"microseconds":993236}}
|
|
[2018-10-18T15:40:15.0857 CEST] [debug] Saving snapshot (Current VM state is running).
|
|
[2018-10-18T15:40:15.0876 CEST] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":876247,"seconds":1539870015}}
|
|
[2018-10-18T15:40:16.0142 CEST] [debug] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'hd0-overlay0','snapshot-file' => '/var/lib/openqa/pool/1/raid/hd0-overlay1','snapshot-node-name' => 'hd0-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}}
|
|
[2018-10-18T15:40:16.0491 CEST] [debug] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'cd0-overlay0','snapshot-file' => '/var/lib/openqa/pool/1/raid/cd0-overlay1','snapshot-node-name' => 'cd0-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}}
|
|
[2018-10-18T15:40:16.0497 CEST] [debug] EVENT {"event":"MIGRATION","data":{"status":"setup"},"timestamp":{"microseconds":497371,"seconds":1539870016}}
|
|
[2018-10-18T15:40:16.0998 CEST] [debug] EVENT {"timestamp":{"seconds":1539870016,"microseconds":509530},"data":{"pass":1},"event":"MIGRATION_PASS"}
|
|
[2018-10-18T15:40:16.0998 CEST] [debug] EVENT {"timestamp":{"microseconds":509644,"seconds":1539870016},"data":{"status":"active"},"event":"MIGRATION"}
|
|
[2018-10-18T15:40:16.0999 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:16.0999 CEST] [debug] Migrating remaining bytes: 2133401600
|
|
[2018-10-18T15:40:17.0500 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:17.0500 CEST] [debug] Migrating remaining bytes: 1287360512
|
|
[2018-10-18T15:40:18.0001 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:18.0001 CEST] [debug] Migrating remaining bytes: 1222426624
|
|
[2018-10-18T15:40:18.0502 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:18.0502 CEST] [debug] Migrating remaining bytes: 654467072
|
|
[2018-10-18T15:40:19.0003 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:19.0003 CEST] [debug] Migrating remaining bytes: 644886528
|
|
[2018-10-18T15:40:19.0504 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:19.0504 CEST] [debug] Migrating remaining bytes: 623280128
|
|
[2018-10-18T15:40:20.0005 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:20.0006 CEST] [debug] Migrating remaining bytes: 312016896
|
|
[2018-10-18T15:40:20.0506 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:20.0506 CEST] [debug] Migrating remaining bytes: 302288896
|
|
[2018-10-18T15:40:21.0007 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:21.0007 CEST] [debug] Migrating remaining bytes: 294842368
|
|
[2018-10-18T15:40:21.0508 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:21.0508 CEST] [debug] Migrating remaining bytes: 286277632
|
|
[2018-10-18T15:40:22.0009 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:22.0009 CEST] [debug] Migrating remaining bytes: 278683648
|
|
[2018-10-18T15:40:22.0510 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:22.0510 CEST] [debug] Migrating remaining bytes: 270274560
|
|
[2018-10-18T15:40:23.0011 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:23.0011 CEST] [debug] Migrating remaining bytes: 262123520
|
|
[2018-10-18T15:40:23.0512 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:23.0513 CEST] [debug] Migrating remaining bytes: 248483840
|
|
[2018-10-18T15:40:24.0013 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:24.0014 CEST] [debug] Migrating remaining bytes: 238575616
|
|
[2018-10-18T15:40:24.0515 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:24.0515 CEST] [debug] Migrating remaining bytes: 228888576
|
|
[2018-10-18T15:40:25.0016 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:25.0016 CEST] [debug] Migrating remaining bytes: 215859200
|
|
[2018-10-18T15:40:25.0517 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:25.0517 CEST] [debug] Migrating remaining bytes: 205484032
|
|
[2018-10-18T15:40:26.0018 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:26.0018 CEST] [debug] Migrating remaining bytes: 197013504
|
|
[2018-10-18T15:40:26.0519 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:26.0519 CEST] [debug] Migrating remaining bytes: 188874752
|
|
[2018-10-18T15:40:27.0020 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:27.0020 CEST] [debug] Migrating remaining bytes: 181673984
|
|
[2018-10-18T15:40:27.0521 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:27.0521 CEST] [debug] Migrating remaining bytes: 174276608
|
|
[2018-10-18T15:40:28.0022 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:28.0022 CEST] [debug] Migrating remaining bytes: 165404672
|
|
[2018-10-18T15:40:28.0523 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:28.0523 CEST] [debug] Migrating remaining bytes: 153903104
|
|
[2018-10-18T15:40:29.0024 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:29.0024 CEST] [debug] Migrating remaining bytes: 139624448
|
|
[2018-10-18T15:40:29.0525 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:29.0525 CEST] [debug] Migrating remaining bytes: 129765376
|
|
[2018-10-18T15:40:30.0026 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:30.0026 CEST] [debug] Migrating remaining bytes: 119676928
|
|
[2018-10-18T15:40:30.0527 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:30.0527 CEST] [debug] Migrating remaining bytes: 107577344
|
|
[2018-10-18T15:40:31.0028 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:31.0028 CEST] [debug] Migrating remaining bytes: 93827072
|
|
[2018-10-18T15:40:31.0529 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:31.0529 CEST] [debug] Migrating remaining bytes: 84492288
|
|
[2018-10-18T15:40:32.0030 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:32.0030 CEST] [debug] Migrating remaining bytes: 76267520
|
|
[2018-10-18T15:40:32.0531 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:32.0531 CEST] [debug] Migrating remaining bytes: 65593344
|
|
[2018-10-18T15:40:33.0040 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:33.0040 CEST] [debug] Migrating remaining bytes: 52764672
|
|
[2018-10-18T15:40:33.0541 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:33.0541 CEST] [debug] Migrating remaining bytes: 35299328
|
|
[2018-10-18T15:40:34.0042 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:34.0042 CEST] [debug] Migrating remaining bytes: 17010688
|
|
[2018-10-18T15:40:34.0542 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:34.0542 CEST] [debug] Migrating remaining bytes: 4747264
|
|
[2018-10-18T15:40:35.0043 CEST] [debug] EVENT {"event":"MIGRATION_PASS","data":{"pass":2},"timestamp":{"microseconds":626938,"seconds":1539870034}}
|
|
[2018-10-18T15:40:35.0043 CEST] [debug] EVENT {"timestamp":{"microseconds":627787,"seconds":1539870034},"data":{"pass":3},"event":"MIGRATION_PASS"}
|
|
[2018-10-18T15:40:35.0043 CEST] [debug] EVENT {"timestamp":{"seconds":1539870034,"microseconds":633968},"data":{"status":"completed"},"event":"MIGRATION"}
|
|
[2018-10-18T15:40:35.0043 CEST] [debug] Migrating total bytes: 2152538112
|
|
[2018-10-18T15:40:35.0043 CEST] [debug] Migrating remaining bytes: 0
|
|
[2018-10-18T15:40:35.0044 CEST] [debug] Snapshot complete
|
|
[2018-10-18T15:40:35.0074 CEST] [debug] EVENT {"event":"RESUME","timestamp":{"seconds":1539870035,"microseconds":74480}}
|
|
[2018-10-18T15:40:35.0075 CEST] [debug] ||| starting systemd_testsuite tests/console/systemd_testsuite.pm
|
|
[2018-10-18T15:40:35.0081 CEST] [debug] QEMU: Formatting '/var/lib/openqa/pool/1/raid/hd0-overlay1', fmt=qcow2 size=42949672960 backing_file=/var/lib/openqa/pool/1/raid/hd0-overlay0 backing_fmt=qcow2 encryption=off cluster_size=65536 lazy_refcounts=off refcount_bits=16
|
|
[2018-10-18T15:40:35.0081 CEST] [debug] QEMU: Formatting '/var/lib/openqa/pool/1/raid/cd0-overlay1', fmt=qcow2 size=668991488 backing_file=/var/lib/openqa/pool/1/raid/cd0-overlay0 backing_fmt=qcow2 encryption=off cluster_size=65536 lazy_refcounts=off refcount_bits=16
|
|
[2018-10-18T15:40:35.0082 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:30 called testapi::select_console
|
|
[2018-10-18T15:40:35.0082 CEST] [debug] <<< testapi::select_console(testapi_console='root-console')
|
|
[2018-10-18T15:40:35.0313 CEST] [debug] activate_console, console: root-console, type: console
|
|
[2018-10-18T15:40:35.0313 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:30 called testapi::select_console
|
|
[2018-10-18T15:40:35.0313 CEST] [debug] <<< testapi::assert_screen(mustmatch=[
|
|
'tty6-selected',
|
|
'text-logged-in-root'
|
|
], timeout=60)
|
|
[2018-10-18T15:40:35.0596 CEST] [debug] no match: 59.9s, best candidate: proxymode_text-logged-in-root-20170705 (0.00)
|
|
[2018-10-18T15:40:36.0551 CEST] [debug] >>> testapi::_handle_found_needle: found tty6-selected-20171011, similarity 1.00 @ 761/31
|
|
[2018-10-18T15:40:36.0553 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:30 called testapi::select_console
|
|
[2018-10-18T15:40:36.0553 CEST] [debug] <<< testapi::type_string(string='root
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:40:36.0677 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:30 called testapi::select_console
|
|
[2018-10-18T15:40:36.0678 CEST] [debug] <<< testapi::assert_screen(mustmatch='password-prompt', timeout=30)
|
|
[2018-10-18T15:40:37.0615 CEST] [debug] >>> testapi::_handle_found_needle: found password-prompt-eurlatgr-20180130, similarity 1.00 @ 0/129
|
|
[2018-10-18T15:40:37.0615 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:30 called testapi::select_console
|
|
[2018-10-18T15:40:37.0615 CEST] [debug] <<< testapi::type_string(string='SECRET STRING', max_interval=100, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:40:38.0741 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:30 called testapi::select_console
|
|
[2018-10-18T15:40:38.0741 CEST] [debug] <<< testapi::send_key(key='ret', do_wait=0)
|
|
[2018-10-18T15:40:38.0947 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:30 called testapi::select_console
|
|
[2018-10-18T15:40:38.0947 CEST] [debug] <<< testapi::assert_screen(mustmatch='text-logged-in-root', timeout=30)
|
|
[2018-10-18T15:40:39.0085 CEST] [debug] no match: 29.9s, best candidate: proxymode_text-logged-in-root-20170705 (0.00)
|
|
[2018-10-18T15:40:40.0147 CEST] [debug] >>> testapi::_handle_found_needle: found text-logged-in-root-20151204, similarity 1.00 @ 63/160
|
|
[2018-10-18T15:40:40.0147 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:30 called testapi::select_console
|
|
[2018-10-18T15:40:40.0147 CEST] [debug] <<< testapi::type_string(string='which tput 2>&1 && PS1="\\[$(tput bold 2; tput setaf 1)\\]#\\[$(tput sgr0)\\] "
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:40:42.0032 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:30 called testapi::select_console
|
|
[2018-10-18T15:40:42.0032 CEST] [debug] <<< testapi::assert_screen(mustmatch='root-console', timeout=30)
|
|
[2018-10-18T15:40:42.0159 CEST] [debug] no match: 29.9s, best candidate: root-console-top-20170607 (0.68)
|
|
[2018-10-18T15:40:43.0216 CEST] [debug] >>> testapi::_handle_found_needle: found root-console-no_cursor-20170321, similarity 1.00 @ 0/192
|
|
[2018-10-18T15:40:43.0216 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:30 called testapi::select_console
|
|
[2018-10-18T15:40:43.0216 CEST] [debug] <<< testapi::type_string(string='setterm -blank 0', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:40:43.0613 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:30 called testapi::select_console
|
|
[2018-10-18T15:40:43.0613 CEST] [debug] <<< testapi::type_string(string=' ; echo YpuUt-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:40:44.0394 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:30 called testapi::select_console
|
|
[2018-10-18T15:40:44.0394 CEST] [debug] <<< testapi::wait_serial(regexp=qr/(?^:YpuUt-\d+-)/, timeout=30)
|
|
[2018-10-18T15:40:46.0547 CEST] [debug] >>> testapi::wait_serial: (?^:YpuUt-\d+-): ok
|
|
[2018-10-18T15:40:46.0548 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:30 called testapi::select_console
|
|
[2018-10-18T15:40:46.0548 CEST] [debug] <<< testapi::assert_screen(mustmatch='root-console', no_wait=1, timeout=30)
|
|
[2018-10-18T15:40:46.0842 CEST] [debug] >>> testapi::_handle_found_needle: found vino_server-root-console-20170406, similarity 1.00 @ 0/207
|
|
[2018-10-18T15:40:46.0842 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:31 called utils::zypper_call
|
|
[2018-10-18T15:40:46.0842 CEST] [debug] <<< testapi::script_run(cmd='zypper -n ar http://download.suse.de/ibs/QA:/SLE15/standard/ systemd-testrepo ; ( exit ${PIPESTATUS[0]} )', wait=700)
|
|
[2018-10-18T15:40:46.0842 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:31 called utils::zypper_call
|
|
[2018-10-18T15:40:46.0842 CEST] [debug] <<< testapi::type_string(string='zypper -n ar http://download.suse.de/ibs/QA:/SLE15/standard/ systemd-testrepo ; ( exit ${PIPESTATUS[0]} )', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:40:49.0498 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:31 called utils::zypper_call
|
|
[2018-10-18T15:40:49.0498 CEST] [debug] <<< testapi::type_string(string=' ; echo 8ox9F-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:40:50.0286 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:31 called utils::zypper_call
|
|
[2018-10-18T15:40:50.0287 CEST] [debug] <<< testapi::wait_serial(timeout=700, regexp=qr/(?^:8ox9F-\d+-)/)
|
|
[2018-10-18T15:40:54.0439 CEST] [debug] >>> testapi::wait_serial: (?^:8ox9F-\d+-): ok
|
|
[2018-10-18T15:40:54.0439 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:32 called utils::zypper_call
|
|
[2018-10-18T15:40:54.0439 CEST] [debug] <<< testapi::script_run(cmd='zypper -n --gpg-auto-import-keys ref ; ( exit ${PIPESTATUS[0]} )', wait=700)
|
|
[2018-10-18T15:40:54.0439 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:32 called utils::zypper_call
|
|
[2018-10-18T15:40:54.0439 CEST] [debug] <<< testapi::type_string(string='zypper -n --gpg-auto-import-keys ref ; ( exit ${PIPESTATUS[0]} )', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:40:56.0040 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:32 called utils::zypper_call
|
|
[2018-10-18T15:40:56.0040 CEST] [debug] <<< testapi::type_string(string=' ; echo 9HXEV-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:40:56.0821 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:32 called utils::zypper_call
|
|
[2018-10-18T15:40:56.0821 CEST] [debug] <<< testapi::wait_serial(timeout=700, regexp=qr/(?^:9HXEV-\d+-)/)
|
|
[2018-10-18T15:41:02.0985 CEST] [debug] >>> testapi::wait_serial: (?^:9HXEV-\d+-): ok
|
|
[2018-10-18T15:41:02.0985 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:33 called utils::zypper_call
|
|
[2018-10-18T15:41:02.0985 CEST] [debug] <<< testapi::script_run(cmd='zypper -n in systemd-qa-testsuite ; ( exit ${PIPESTATUS[0]} )', wait=700)
|
|
[2018-10-18T15:41:02.0985 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:33 called utils::zypper_call
|
|
[2018-10-18T15:41:02.0986 CEST] [debug] <<< testapi::type_string(string='zypper -n in systemd-qa-testsuite ; ( exit ${PIPESTATUS[0]} )', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:41:04.0507 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:33 called utils::zypper_call
|
|
[2018-10-18T15:41:04.0508 CEST] [debug] <<< testapi::type_string(string=' ; echo EPTg2-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:41:05.0284 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:33 called utils::zypper_call
|
|
[2018-10-18T15:41:05.0284 CEST] [debug] <<< testapi::wait_serial(timeout=700, regexp=qr/(?^:EPTg2-\d+-)/)
|
|
[2018-10-18T15:41:15.0465 CEST] [debug] >>> testapi::wait_serial: (?^:EPTg2-\d+-): ok
|
|
[2018-10-18T15:41:15.0465 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:36 called testapi::assert_script_run
|
|
[2018-10-18T15:41:15.0466 CEST] [debug] <<< testapi::assert_script_run(cmd='cd /var/opt/systemd-tests', wait=90, fail_message=undef)
|
|
[2018-10-18T15:41:15.0466 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:36 called testapi::assert_script_run
|
|
[2018-10-18T15:41:15.0466 CEST] [debug] <<< testapi::type_string(string='cd /var/opt/systemd-tests', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:41:16.0094 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:36 called testapi::assert_script_run
|
|
[2018-10-18T15:41:16.0094 CEST] [debug] <<< testapi::type_string(string=' ; echo OJZFF-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:41:16.0860 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:36 called testapi::assert_script_run
|
|
[2018-10-18T15:41:16.0860 CEST] [debug] <<< testapi::wait_serial(regexp=qr/(?^:OJZFF-\d+-)/, timeout=90)
|
|
[2018-10-18T15:41:18.0991 CEST] [debug] >>> testapi::wait_serial: (?^:OJZFF-\d+-): ok
|
|
[2018-10-18T15:41:18.0991 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:37 called testapi::assert_script_run
|
|
[2018-10-18T15:41:18.0991 CEST] [debug] <<< testapi::assert_script_run(cmd='./run-tests.sh --all 2>&1 | tee /tmp/testsuite.log', wait=2100, fail_message=undef)
|
|
[2018-10-18T15:41:18.0992 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:37 called testapi::assert_script_run
|
|
[2018-10-18T15:41:18.0992 CEST] [debug] <<< testapi::type_string(string='./run-tests.sh --all 2>&1 | tee /tmp/testsuite.log', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:41:20.0246 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:37 called testapi::assert_script_run
|
|
[2018-10-18T15:41:20.0247 CEST] [debug] <<< testapi::type_string(string=' ; echo xhHhm-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T15:41:21.0027 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:37 called testapi::assert_script_run
|
|
[2018-10-18T15:41:21.0027 CEST] [debug] <<< testapi::wait_serial(regexp=qr/(?^:xhHhm-\d+-)/, timeout=2100)
|
|
[2018-10-18T16:03:41.0605 CEST] [debug] >>> testapi::wait_serial: (?^:xhHhm-\d+-): ok
|
|
[2018-10-18T16:03:41.0605 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:38 called testapi::assert_script_run
|
|
[2018-10-18T16:03:41.0605 CEST] [debug] <<< testapi::assert_script_run(cmd='grep "# FAIL: 0" /tmp/testsuite.log', wait=90, fail_message=undef)
|
|
[2018-10-18T16:03:41.0605 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:38 called testapi::assert_script_run
|
|
[2018-10-18T16:03:41.0606 CEST] [debug] <<< testapi::type_string(string='grep "# FAIL: 0" /tmp/testsuite.log', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:03:42.0496 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:38 called testapi::assert_script_run
|
|
[2018-10-18T16:03:42.0497 CEST] [debug] <<< testapi::type_string(string=' ; echo fWleW-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:03:43.0258 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:38 called testapi::assert_script_run
|
|
[2018-10-18T16:03:43.0259 CEST] [debug] <<< testapi::wait_serial(regexp=qr/(?^:fWleW-\d+-)/, timeout=90)
|
|
[2018-10-18T16:03:45.0383 CEST] [debug] >>> testapi::wait_serial: (?^:fWleW-\d+-): ok
|
|
[2018-10-18T16:03:45.0523 CEST] [debug] command 'grep "# FAIL: 0" /tmp/testsuite.log' failed at /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm line 38.
|
|
|
|
[2018-10-18T16:03:45.0525 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:45.0525 CEST] [debug] <<< testapi::select_console(testapi_console='log-console')
|
|
[2018-10-18T16:03:45.0737 CEST] [debug] activate_console, console: log-console, type: console
|
|
[2018-10-18T16:03:45.0737 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:45.0737 CEST] [debug] <<< testapi::assert_screen(mustmatch=[
|
|
'tty5-selected',
|
|
'text-logged-in-root'
|
|
], timeout=60)
|
|
[2018-10-18T16:03:45.0968 CEST] [debug] no match: 59.9s, best candidate: proxymode_text-logged-in-root-20170705 (0.00)
|
|
[2018-10-18T16:03:46.0971 CEST] [debug] >>> testapi::_handle_found_needle: found tty5-selected-sle12-20180511, similarity 1.00 @ 71/110
|
|
[2018-10-18T16:03:46.0983 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:46.0983 CEST] [debug] <<< testapi::type_string(string='root
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:03:47.0108 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:47.0108 CEST] [debug] <<< testapi::assert_screen(mustmatch='password-prompt', timeout=30)
|
|
[2018-10-18T16:03:48.0101 CEST] [debug] >>> testapi::_handle_found_needle: found password-prompt-eurlatgr-20180130, similarity 1.00 @ 0/129
|
|
[2018-10-18T16:03:48.0101 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:48.0101 CEST] [debug] <<< testapi::type_string(string='SECRET STRING', max_interval=100, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:03:49.0228 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:49.0228 CEST] [debug] <<< testapi::send_key(key='ret', do_wait=0)
|
|
[2018-10-18T16:03:49.0435 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:49.0435 CEST] [debug] <<< testapi::assert_screen(mustmatch='text-logged-in-root', timeout=30)
|
|
[2018-10-18T16:03:49.0611 CEST] [debug] no match: 29.9s, best candidate: proxymode_text-logged-in-root-20170705 (0.00)
|
|
[2018-10-18T16:03:50.0631 CEST] [debug] >>> testapi::_handle_found_needle: found text-logged-in-root-20151204, similarity 1.00 @ 63/160
|
|
[2018-10-18T16:03:50.0632 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:50.0632 CEST] [debug] <<< testapi::type_string(string='which tput 2>&1 && PS1="\\[$(tput bold 2; tput setaf 1)\\]#\\[$(tput sgr0)\\] "
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:03:52.0502 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:52.0502 CEST] [debug] <<< testapi::assert_screen(mustmatch='log-console', timeout=30)
|
|
[2018-10-18T16:03:52.0601 CEST] [debug] no match: 29.9s, best candidate: root-console-top-20170607 (0.68)
|
|
[2018-10-18T16:03:53.0675 CEST] [debug] >>> testapi::_handle_found_needle: found root-console-no_cursor-20170321, similarity 1.00 @ 0/192
|
|
[2018-10-18T16:03:53.0675 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:53.0675 CEST] [debug] <<< testapi::type_string(string='setterm -blank 0', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:03:54.0071 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:54.0072 CEST] [debug] <<< testapi::type_string(string=' ; echo YpuUt-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:03:54.0849 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:54.0849 CEST] [debug] <<< testapi::wait_serial(timeout=30, regexp=qr/(?^:YpuUt-\d+-)/)
|
|
[2018-10-18T16:03:56.0979 CEST] [debug] >>> testapi::wait_serial: (?^:YpuUt-\d+-): ok
|
|
[2018-10-18T16:03:56.0979 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:56.0979 CEST] [debug] <<< testapi::assert_screen(mustmatch='log-console', timeout=30, no_wait=1)
|
|
[2018-10-18T16:03:57.0205 CEST] [debug] >>> testapi::_handle_found_needle: found vino_server-root-console-20170406, similarity 1.00 @ 0/207
|
|
[2018-10-18T16:03:57.0206 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:57.0206 CEST] [debug] <<< testapi::send_key(key='alt-sysrq-w', do_wait=0)
|
|
[2018-10-18T16:03:57.0413 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:57.0414 CEST] [debug] <<< testapi::wait_serial(regexp='SysRq : Show Blocked State', timeout=1)
|
|
[2018-10-18T16:03:58.0565 CEST] [debug] >>> testapi::wait_serial: SysRq : Show Blocked State: ok
|
|
[2018-10-18T16:03:58.0565 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:58.0565 CEST] [debug] <<< testapi::script_run(cmd='touch /tmp/test_ro || mount -t tmpfs /dev/shm /tmp', wait=undef)
|
|
[2018-10-18T16:03:58.0566 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:58.0566 CEST] [debug] <<< testapi::type_string(string='touch /tmp/test_ro || mount -t tmpfs /dev/shm /tmp', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:03:59.0804 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:03:59.0804 CEST] [debug] <<< testapi::type_string(string=' ; echo EXCCX-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:00.0573 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:00.0573 CEST] [debug] <<< testapi::wait_serial(regexp=qr/(?^:EXCCX-\d+-)/, timeout=30)
|
|
[2018-10-18T16:04:02.0722 CEST] [debug] >>> testapi::wait_serial: (?^:EXCCX-\d+-): ok
|
|
[2018-10-18T16:04:02.0722 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:02.0723 CEST] [debug] <<< testapi::assert_script_run(cmd='journalctl --no-pager -b 0 > /tmp/full_journal.log', wait=90, fail_message=undef)
|
|
[2018-10-18T16:04:02.0723 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:02.0723 CEST] [debug] <<< testapi::type_string(string='journalctl --no-pager -b 0 > /tmp/full_journal.log', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:03.0948 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:03.0948 CEST] [debug] <<< testapi::type_string(string=' ; echo _shae-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:04.0706 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:04.0707 CEST] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/(?^:_shae-\d+-)/)
|
|
[2018-10-18T16:04:06.0872 CEST] [debug] >>> testapi::wait_serial: (?^:_shae-\d+-): ok
|
|
[2018-10-18T16:04:06.0872 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:06.0872 CEST] [debug] <<< testapi::upload_logs(file='/tmp/full_journal.log', failok=0, timeout=90)
|
|
[2018-10-18T16:04:06.0872 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:06.0872 CEST] [debug] <<< testapi::assert_script_run(cmd='curl --form upload=@/tmp/full_journal.log --form upname=systemd_testsuite-full_journal.log http://10.0.2.2:20013/mJdkzEZGeyb7og5e/uploadlog/full_journal.log', wait=90, fail_message=undef)
|
|
[2018-10-18T16:04:06.0873 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:06.0873 CEST] [debug] <<< testapi::type_string(string='curl --form upload=@/tmp/full_journal.log --form upname=systemd_testsuite-full_journal.log http://10.0.2.2:20013/mJdkzEZGeyb7og5e/uploadlog/full_journal.log', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:10.0735 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:10.0735 CEST] [debug] <<< testapi::type_string(string=' ; echo tJYtc-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:11.0503 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:11.0504 CEST] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/(?^:tJYtc-\d+-)/)
|
|
[2018-10-18T16:04:14.0633 CEST] [debug] >>> testapi::wait_serial: (?^:tJYtc-\d+-): ok
|
|
[2018-10-18T16:04:14.0633 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:14.0633 CEST] [debug] <<< testapi::assert_script_run(cmd='dmesg > /tmp/dmesg.log', wait=90, fail_message=undef)
|
|
[2018-10-18T16:04:14.0634 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:14.0634 CEST] [debug] <<< testapi::type_string(string='dmesg > /tmp/dmesg.log', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:15.0176 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:15.0177 CEST] [debug] <<< testapi::type_string(string=' ; echo JJMA2-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:15.0935 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:15.0935 CEST] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/(?^:JJMA2-\d+-)/)
|
|
[2018-10-18T16:04:18.0065 CEST] [debug] >>> testapi::wait_serial: (?^:JJMA2-\d+-): ok
|
|
[2018-10-18T16:04:18.0065 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:18.0065 CEST] [debug] <<< testapi::upload_logs(file='/tmp/dmesg.log', failok=0, timeout=90)
|
|
[2018-10-18T16:04:18.0066 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:18.0066 CEST] [debug] <<< testapi::assert_script_run(cmd='curl --form upload=@/tmp/dmesg.log --form upname=systemd_testsuite-dmesg.log http://10.0.2.2:20013/mJdkzEZGeyb7og5e/uploadlog/dmesg.log', wait=90, fail_message=undef)
|
|
[2018-10-18T16:04:18.0066 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:18.0066 CEST] [debug] <<< testapi::type_string(string='curl --form upload=@/tmp/dmesg.log --form upname=systemd_testsuite-dmesg.log http://10.0.2.2:20013/mJdkzEZGeyb7og5e/uploadlog/dmesg.log', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:21.0386 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:21.0386 CEST] [debug] <<< testapi::type_string(string=' ; echo MuDys-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:22.0147 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:45 called consoletest::post_fail_hook
|
|
[2018-10-18T16:04:22.0148 CEST] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/(?^:MuDys-\d+-)/)
|
|
[2018-10-18T16:04:25.0298 CEST] [debug] >>> testapi::wait_serial: (?^:MuDys-\d+-): ok
|
|
[2018-10-18T16:04:25.0298 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:46 called testapi::assert_script_run
|
|
[2018-10-18T16:04:25.0299 CEST] [debug] <<< testapi::assert_script_run(cmd='cd /var/opt/systemd-tests/', wait=90, fail_message=undef)
|
|
[2018-10-18T16:04:25.0299 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:46 called testapi::assert_script_run
|
|
[2018-10-18T16:04:25.0299 CEST] [debug] <<< testapi::type_string(string='cd /var/opt/systemd-tests/', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:25.0938 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:46 called testapi::assert_script_run
|
|
[2018-10-18T16:04:25.0938 CEST] [debug] <<< testapi::type_string(string=' ; echo aiZx1-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:26.0698 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:46 called testapi::assert_script_run
|
|
[2018-10-18T16:04:26.0698 CEST] [debug] <<< testapi::wait_serial(regexp=qr/(?^:aiZx1-\d+-)/, timeout=90)
|
|
[2018-10-18T16:04:28.0861 CEST] [debug] >>> testapi::wait_serial: (?^:aiZx1-\d+-): ok
|
|
[2018-10-18T16:04:28.0862 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:47 called testapi::assert_script_run
|
|
[2018-10-18T16:04:28.0862 CEST] [debug] <<< testapi::assert_script_run(cmd='cp /tmp/testsuite.log logs/', wait=90, fail_message=undef)
|
|
[2018-10-18T16:04:28.0862 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:47 called testapi::assert_script_run
|
|
[2018-10-18T16:04:28.0862 CEST] [debug] <<< testapi::type_string(string='cp /tmp/testsuite.log logs/', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:29.0530 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:47 called testapi::assert_script_run
|
|
[2018-10-18T16:04:29.0531 CEST] [debug] <<< testapi::type_string(string=' ; echo ri7Jc-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:30.0289 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:47 called testapi::assert_script_run
|
|
[2018-10-18T16:04:30.0289 CEST] [debug] <<< testapi::wait_serial(timeout=90, regexp=qr/(?^:ri7Jc-\d+-)/)
|
|
[2018-10-18T16:04:32.0438 CEST] [debug] >>> testapi::wait_serial: (?^:ri7Jc-\d+-): ok
|
|
[2018-10-18T16:04:32.0438 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:48 called testapi::assert_script_run
|
|
[2018-10-18T16:04:32.0438 CEST] [debug] <<< testapi::assert_script_run(cmd='tar -cjf systemd-testsuite-logs.tar.bz2 logs/', wait=90, fail_message=undef)
|
|
[2018-10-18T16:04:32.0438 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:48 called testapi::assert_script_run
|
|
[2018-10-18T16:04:32.0439 CEST] [debug] <<< testapi::type_string(string='tar -cjf systemd-testsuite-logs.tar.bz2 logs/', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:33.0540 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:48 called testapi::assert_script_run
|
|
[2018-10-18T16:04:33.0541 CEST] [debug] <<< testapi::type_string(string=' ; echo HIKdz-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:34.0309 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:48 called testapi::assert_script_run
|
|
[2018-10-18T16:04:34.0309 CEST] [debug] <<< testapi::wait_serial(regexp=qr/(?^:HIKdz-\d+-)/, timeout=90)
|
|
[2018-10-18T16:04:36.0447 CEST] [debug] >>> testapi::wait_serial: (?^:HIKdz-\d+-): ok
|
|
[2018-10-18T16:04:36.0447 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:49 called testapi::upload_logs
|
|
[2018-10-18T16:04:36.0447 CEST] [debug] <<< testapi::upload_logs(file='systemd-testsuite-logs.tar.bz2', failok=0, timeout=90)
|
|
[2018-10-18T16:04:36.0447 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:49 called testapi::upload_logs
|
|
[2018-10-18T16:04:36.0448 CEST] [debug] <<< testapi::assert_script_run(cmd='curl --form upload=@systemd-testsuite-logs.tar.bz2 --form upname=systemd_testsuite-systemd-testsuite-logs.tar.bz2 http://10.0.2.2:20013/mJdkzEZGeyb7og5e/uploadlog/systemd-testsuite-logs.tar.bz2', wait=90, fail_message=undef)
|
|
[2018-10-18T16:04:36.0448 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:49 called testapi::upload_logs
|
|
[2018-10-18T16:04:36.0448 CEST] [debug] <<< testapi::type_string(string='curl --form upload=@systemd-testsuite-logs.tar.bz2 --form upname=systemd_testsuite-systemd-testsuite-logs.tar.bz2 http://10.0.2.2:20013/mJdkzEZGeyb7og5e/uploadlog/systemd-testsuite-logs.tar.bz2', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:41.0174 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:49 called testapi::upload_logs
|
|
[2018-10-18T16:04:41.0175 CEST] [debug] <<< testapi::type_string(string=' ; echo rovHN-$?- > /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:41.0940 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:49 called testapi::upload_logs
|
|
[2018-10-18T16:04:41.0940 CEST] [debug] <<< testapi::wait_serial(regexp=qr/(?^:rovHN-\d+-)/, timeout=90)
|
|
[2018-10-18T16:04:45.0093 CEST] [debug] >>> testapi::wait_serial: (?^:rovHN-\d+-): ok
|
|
[2018-10-18T16:04:45.0093 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:51 called testapi::script_output
|
|
[2018-10-18T16:04:45.0094 CEST] [debug] <<< testapi::type_string(string='cat - > /tmp/scriptZWkGH.sh;
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:45.0810 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:51 called testapi::script_output
|
|
[2018-10-18T16:04:45.0810 CEST] [debug] <<< testapi::type_string(string='sed --quiet \'s/[[0-9;]*m//g; /^FAIL:/p\' /tmp/testsuite.log
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:47.0289 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:51 called testapi::script_output
|
|
[2018-10-18T16:04:47.0289 CEST] [debug] <<< testapi::send_key(key='ctrl-d', do_wait=0)
|
|
[2018-10-18T16:04:47.0495 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:51 called testapi::script_output
|
|
[2018-10-18T16:04:47.0495 CEST] [debug] <<< testapi::type_string(string='(echo ZWkGH; bash -eox pipefail /tmp/scriptZWkGH.sh ; echo SCRIPT_FINISHEDZWkGH-$?-) | tee /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:50.0018 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:51 called testapi::script_output
|
|
[2018-10-18T16:04:50.0018 CEST] [debug] <<< testapi::wait_serial(record_output=1, regexp='SCRIPT_FINISHEDZWkGH-\\d+-', timeout=90)
|
|
[2018-10-18T16:04:52.0183 CEST] [debug] >>> testapi::wait_serial: SCRIPT_FINISHEDZWkGH-\d+-: ok
|
|
[2018-10-18T16:04:52.0183 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:53 called testapi::script_output
|
|
[2018-10-18T16:04:52.0183 CEST] [debug] <<< testapi::type_string(string='cat - > /tmp/scriptkICzV.sh;
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:52.0915 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:53 called testapi::script_output
|
|
[2018-10-18T16:04:52.0915 CEST] [debug] <<< testapi::type_string(string='cat logs/TEST-03-JOBS-run.log
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:53.0657 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:53 called testapi::script_output
|
|
[2018-10-18T16:04:53.0657 CEST] [debug] <<< testapi::send_key(key='ctrl-d', do_wait=0)
|
|
[2018-10-18T16:04:53.0863 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:53 called testapi::script_output
|
|
[2018-10-18T16:04:53.0863 CEST] [debug] <<< testapi::type_string(string='(echo kICzV; bash -eox pipefail /tmp/scriptkICzV.sh ; echo SCRIPT_FINISHEDkICzV-$?-) | tee /dev/ttyS0
|
|
', max_interval=250, wait_screen_changes=0, wait_still_screen=0)
|
|
[2018-10-18T16:04:56.0381 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:53 called testapi::script_output
|
|
[2018-10-18T16:04:56.0382 CEST] [debug] <<< testapi::wait_serial(record_output=1, timeout=90, regexp='SCRIPT_FINISHEDkICzV-\\d+-')
|
|
[2018-10-18T16:04:58.0540 CEST] [debug] >>> testapi::wait_serial: SCRIPT_FINISHEDkICzV-\d+-: ok
|
|
[2018-10-18T16:04:58.0544 CEST] [debug] /var/lib/openqa/cache/tests/sle/tests/console/systemd_testsuite.pm:54 called testapi::record_info
|
|
[2018-10-18T16:04:58.0545 CEST] [debug] <<< testapi::record_info(title='Failed test \'TEST-03-JOBS\'', output="Failed test 'TEST-03-JOBS'
|
|
TEST RUN: Job-related tests
|
|
+ /usr/bin/qemu-system-x86_64 -smp 1 -net none -m 512M -nographic -drive file=/var/tmp/systemd-test.knmVCK/rootdisk.img,format=raw,cache=unsafe -kernel /boot/vmlinuz-4.12.14-25.19-default -initrd /boot/initrd-4.12.14-25.19-default -append 'rd.hostonly=0 multipath=off systemd.mask=vboxdrv.service systemd.mask=vboxes.service systemd.mask=iscsiuio.socket systemd.mask=iscsid.socket console=ttyS0 root=/dev/sda1 raid=noautodetect loglevel=2 init=/usr/lib/systemd/systemd selinux=0 '
|
|
c[?7l[2J[0mSeaBIOS (version rel-1.11.2-0-gf9626cc-prebuilt.qemu-project.org)
|
|
Booting from ROM...
|
|
Probing EDD (edd=off to disable)... oc[?7l[2J
|
|
Welcome to [0;34mSUSE Linux Enterprise Server 15 SP1 dracut-044-18.3.6 (Initramfs)[0m!
|
|
|
|
[[0;32m OK [0m] Reached target Local File Systems.
|
|
[[0;32m OK [0m] Reached target Timers.
|
|
[[0;32m OK [0m] Reached target Swap.
|
|
[[0;32m OK [0m] Listening on udev Kernel Socket.
|
|
[[0;32m OK [0m] Listening on Journal Audit Socket.
|
|
[[0;32m OK [0m] Created slice System Slice.
|
|
[[0;32m OK [0m] Listening on udev Control Socket.
|
|
[[0;32m OK [0m] Listening on Journal Socket (/dev/log).
|
|
[[0;32m OK [0m] Reached target Slices.
|
|
[[0;32m OK [0m] Listening on Journal Socket.
|
|
[[0;32m OK [0m] Started Entropy Daemon based on the HAVEGE algorithm.
|
|
Starting dracut ask for additional cmdline parameters...
|
|
[[0;32m OK [0m] Reached target Sockets.
|
|
Starting Setup Virtual Console...
|
|
Starting Create list of required st\x{e2}\x{80}\x{a6}ce nodes for the current kernel...
|
|
Starting Journal Service...
|
|
Starting Load Kernel Modules...
|
|
[[0;32m OK [0m] Started Create list of required sta\x{e2}\x{80}\x{a6}vice nodes for the current kernel.
|
|
Starting Create Static Device Nodes in /dev...
|
|
[[0;32m OK [0m] Started Create Static Device Nodes in /dev.
|
|
[[0;32m OK [0m] Started Load Kernel Modules.
|
|
Starting Apply Kernel Variables...
|
|
[[0;32m OK [0m] Started dracut ask for additional cmdline parameters.
|
|
Starting dracut cmdline hook...
|
|
[[0;32m OK [0m] Started Journal Service.
|
|
[[0;32m OK [0m] Started Apply Kernel Variables.
|
|
[[0;32m OK [0m] Started Setup Virtual Console.
|
|
[[0;32m OK [0m] Started dracut cmdline hook.
|
|
Starting udev Kernel Device Manager...
|
|
[[0;32m OK [0m] Started udev Kernel Device Manager.
|
|
Starting dracut pre-trigger hook...
|
|
[[0;32m OK [0m] Started dracut pre-trigger hook.
|
|
Starting udev Coldplug all Devices...
|
|
[[0;32m OK [0m] Started udev Coldplug all Devices.
|
|
[[0;32m OK [0m] Reached target System Initialization.
|
|
Starting Show Plymouth Boot Screen...
|
|
[[0;32m OK [0m] Reached target Remote File Systems (Pre).
|
|
[[0;32m OK [0m] Reached target Remote File Systems.
|
|
[[0;32m OK [0m] Started Show Plymouth Boot Screen.
|
|
|
|
[[0;32m OK [0m] Reached target Paths.
|
|
|
|
[[0;32m OK [0m] Started Forward Password Requests to Plymouth Directory Watch.
|
|
|
|
[[0;32m OK [0m] Reached target Basic System.
|
|
|
|
[[0;32m OK [0m] Found device QEMU_HARDDISK systemd.
|
|
|
|
[[0;32m OK [0m] Reached target Initrd Root Device.
|
|
|
|
Starting File System Check on /dev/sda1...
|
|
|
|
[[0;32m OK [0m] Started File System Check on /dev/sda1.
|
|
|
|
Mounting /sysroot...
|
|
|
|
[[0;32m OK [0m] Mounted /sysroot.
|
|
|
|
[[0;32m OK [0m] Reached target Initrd Root File System.
|
|
|
|
Starting Reload Configuration from the Real Root...
|
|
|
|
[[0;32m OK [0m] Started Reload Configuration from the Real Root.
|
|
|
|
[[0;32m OK [0m] Reached target Initrd File Systems.
|
|
|
|
[[0;32m OK [0m] Reached target Initrd Default Target.
|
|
|
|
Starting Cleaning Up and Shutting Down Daemons...
|
|
|
|
[[0;32m OK [0m] Stopped target Remote File Systems.
|
|
|
|
[[0;32m OK [0m] Stopped target Timers.
|
|
|
|
Starting Plymouth switch root service...
|
|
|
|
Starting Setup Virtual Console...
|
|
|
|
[[0;32m OK [0m] Stopped target Remote File Systems (Pre).
|
|
|
|
[[0;32m OK [0m] Stopped dracut cmdline hook.
|
|
|
|
[[0;32m OK [0m] Stopped dracut ask for additional cmdline parameters.
|
|
|
|
[[0;32m OK [0m] Stopped target Initrd Default Target.
|
|
|
|
[[0;32m OK [0m] Stopped target Basic System.
|
|
|
|
[[0;32m OK [0m] Stopped target Paths.
|
|
|
|
[[0;32m OK [0m] Stopped target System Initialization.
|
|
|
|
[[0;32m OK [0m] Stopped target Swap.
|
|
|
|
[[0;32m OK [0m] Stopped udev Coldplug all Devices.
|
|
|
|
[[0;32m OK [0m] Stopped dracut pre-trigger hook.
|
|
|
|
Stopping udev Kernel Device Manager...
|
|
|
|
[[0;32m OK [0m] Stopped Apply Kernel Variables.
|
|
|
|
[[0;32m OK [0m] Stopped Load Kernel Modules.
|
|
|
|
[[0;32m OK [0m] Stopped target Local File Systems.
|
|
|
|
[[0;32m OK [0m] Stopped target Slices.
|
|
|
|
[[0;32m OK [0m] Stopped target Sockets.
|
|
|
|
[[0;32m OK [0m] Stopped target Initrd Root Device.
|
|
|
|
[[0;32m OK [0m] Stopped udev Kernel Device Manager.
|
|
|
|
[[0;32m OK [0m] Started Plymouth switch root service.
|
|
|
|
[[0;32m OK [0m] Started Setup Virtual Console.
|
|
|
|
[[0;32m OK [0m] Stopped Create Static Device Nodes in /dev.
|
|
|
|
[[0;32m OK [0m] Stopped Create list of required sta\x{e2}\x{80}\x{a6}vice nodes for the current kernel.
|
|
|
|
[[0;32m OK [0m] Closed udev Control Socket.
|
|
|
|
[[0;32m OK [0m] Closed udev Kernel Socket.
|
|
|
|
Starting Cleanup udevd DB...
|
|
|
|
[[0;32m OK [0m] Started Cleaning Up and Shutting Down Daemons.
|
|
|
|
[[0;32m OK [0m] Started Cleanup udevd DB.
|
|
|
|
[[0;32m OK [0m] Reached target Switch Root.
|
|
|
|
Starting Switch Root...
|
|
|
|
|
|
|
|
Welcome to [0;32mSUSE Linux Enterprise Server 15 SP1[0m!
|
|
|
|
|
|
|
|
[[0;32m OK [0m] Stopped Entropy Daemon based on the HAVEGE algorithm.
|
|
|
|
[[0;32m OK [0m] Stopped Switch Root.
|
|
|
|
[[0;32m OK [0m] Stopped Journal Service.
|
|
|
|
[[0;32m OK [0m] Stopped Entropy Daemon based on the HAVEGE algorithm.
|
|
|
|
[[0;32m OK [0m] Started Entropy Daemon based on the HAVEGE algorithm.
|
|
|
|
Starting Journal Service...
|
|
|
|
[[0;32m OK [0m] Stopped target Switch Root.
|
|
|
|
[[0;32m OK [0m] Set up automount Arbitrary Executab\x{e2}\x{80}\x{a6}rmats File System Automount Point.
|
|
|
|
[[0;32m OK [0m] Stopped target Initrd File Systems.
|
|
|
|
[[0;32m OK [0m] Listening on /dev/initctl Compatibility Named Pipe.
|
|
|
|
[[0;32m OK [0m] Stopped Forward Password Requests to Plymouth Directory Watch.
|
|
|
|
[[0;32m OK [0m] Reached target Swap.
|
|
Mounting POSIX Message Queue File System...
|
|
Starting Remount Root and Kernel File Systems...
|
|
[[0;32m OK [0m] Stopped target Initrd Root File System.
|
|
[[0;32m OK [0m] Reached target Login Prompts.
|
|
[[0;32m OK [0m] Listening on udev Kernel Socket.
|
|
Mounting Kernel Debug File System...
|
|
Mounting Huge Pages File System...
|
|
[[0;32m OK [0m] Listening on udev Control Socket.
|
|
[[0;32m OK [0m] Created slice User and Session Slice.
|
|
[[0;32m OK [0m] Reached target Slices.
|
|
Starting Apply Kernel Variables...
|
|
[[0;32m OK [0m] Listening on Process Core Dump Socket.
|
|
[[0;32m OK [0m] Mounted Kernel Debug File System.
|
|
[[0;32m OK [0m] Mounted POSIX Message Queue File System.
|
|
[[0;32m OK [0m] Mounted Huge Pages File System.
|
|
[[0;32m OK [0m] Stopped plymouth-start.service.
|
|
[[0;32m OK [0m] Reached target Paths.
|
|
[[0;32m OK [0m] Reached target Encrypted Volumes.
|
|
[[0;32m OK [0m] Started Remount Root and Kernel File Systems.
|
|
[[0;32m OK [0m] Started Journal Service.
|
|
Starting Flush Journal to Persistent Storage...
|
|
Starting Rebuild Hardware Database...
|
|
Starting Load/Save Random Seed...
|
|
Starting Create System Users...
|
|
[[0;32m OK [0m] Started Apply Kernel Variables.
|
|
[[0;32m OK [0m] Started Rebuild Hardware Database.
|
|
[[0;32m OK [0m] Started Load/Save Random Seed.
|
|
[[0;32m OK [0m] Started Create System Users.
|
|
Starting Create Static Device Nodes in /dev...
|
|
Starting udev Coldplug all Devices...
|
|
[[0;32m OK [0m] Started Create Static Device Nodes in /dev.
|
|
[[0;32m OK [0m] Reached target Local File Systems (Pre).
|
|
[[0;32m OK [0m] Reached target Local File Systems.
|
|
Starting Commit a transient machine-id on disk...
|
|
Starting Rebuild Journal Catalog...
|
|
Starting Restore /run/initramfs on shutdown...
|
|
Starting udev Kernel Device Manager...
|
|
[[0;32m OK [0m] Started Flush Journal to Persistent Storage.
|
|
[[0;32m OK [0m] Started Restore /run/initramfs on shutdown.
|
|
Starting Create Volatile Files and Directories...
|
|
[[0;32m OK [0m] Started Commit a transient machine-id on disk.
|
|
[[0;32m OK [0m] Started Rebuild Journal Catalog.
|
|
Starting Update is Completed...
|
|
[[0;32m OK [0m] Started udev Kernel Device Manager.
|
|
[[0;32m OK [0m] Started Create Volatile Files and Directories.
|
|
Starting Update UTMP about System Boot/Shutdown...
|
|
[[0;32m OK [0m] Started Update is Completed.
|
|
[[0;32m OK [0m] Started Update UTMP about System Boot/Shutdown.
|
|
[[0;32m OK [0m] Started udev Coldplug all Devices.
|
|
[[0;32m OK [0m] Reached target System Initialization.
|
|
[[0;32m OK [0m] Started Daily Cleanup of Temporary Directories.
|
|
[[0;32m OK [0m] Reached target Timers.
|
|
[[0;32m OK [0m] Listening on D-Bus System Message Bus Socket.
|
|
[[0;32m OK [0m] Reached target Sockets.
|
|
[[0;32m OK [0m] Reached target Basic System.
|
|
Starting Permit User Sessions...
|
|
[[0;32m OK [0m] Started D-Bus System Message Bus.
|
|
Starting Login Service...
|
|
[[0;32m OK [0m] Started Permit User Sessions.
|
|
[[0;32m OK [0m] Started Login Service.
|
|
[[0;32m OK [0m] Reached target Multi-User System.
|
|
Starting Update UTMP about System Runlevel Changes...
|
|
Starting Testsuite service...
|
|
[[0;32m OK [0m] Started Update UTMP about System Runlevel Changes.
|
|
Starting Sleep for 1 minute...
|
|
[[0;32m OK [0m] Started Hello World.
|
|
[[0;32m OK [0m] Stopped Sleep for 1 minute.
|
|
Starting Sleep for 1 minute...
|
|
[[0;32m OK [0m] Stopped Sleep for 1 minute.
|
|
Starting unstoppable.service...
|
|
[[0;32m OK [0m] Started unstoppable.service.
|
|
Stopping unstoppable.service...
|
|
Starting unstoppable.service...
|
|
[[0;32m OK [0m] Started unstoppable.service.
|
|
Stopping unstoppable.service...
|
|
[[0;32m OK [0m] Stopped unstoppable.service.
|
|
Starting unstoppable.service...
|
|
[[0;32m OK [0m] Started unstoppable.service.
|
|
[[0;32m OK [0m] Started Wait for 2 seconds.
|
|
[[0;32m OK [0m] Started Wait for 2 seconds.
|
|
[[0;32m OK [0m] Started Wait for 5 seconds and fail.
|
|
[[0m[0;31m* [0m] A start job is running for Testsuite service (33s / no limit)
|
|
[K[[0;1;31m*[0m[0;31m* [0m] A start job is running for Testsuite service (34s / no limit)
|
|
[K[[0;31m*[0;1;31m*[0m[0;31m* [0m] A start job is running for Testsuite service (34s / no limit)
|
|
[K[[0;1;31mFAILED[0m] Failed to start Testsuite service.
|
|
See 'systemctl status testsuite.service' for details.
|
|
Starting End the test...
|
|
[[0;32m OK [0m] Reached target Unmount All Filesystems.
|
|
Stopping unstoppable.service...
|
|
[[0;32m OK [0m] Stopped target Timers.
|
|
[[0;32m OK [0m] Stopped Daily Cleanup of Temporary Directories.
|
|
Stopping Restore /run/initramfs on shutdown...
|
|
[[0;32m OK [0m] Stopped target Multi-User System.
|
|
Stopping D-Bus System Message Bus...
|
|
[[0;32m OK [0m] Stopped target Login Prompts.
|
|
Stopping Login Service...
|
|
Stopping Permit User Sessions...
|
|
[[0;32m OK [0m] Stopped D-Bus System Message Bus.
|
|
[[0;32m OK [0m] Stopped Login Service.
|
|
[[0;32m OK [0m] Stopped End the test.
|
|
[[0;32m OK [0m] Stopped Restore /run/initramfs on shutdown.
|
|
[[0;32m OK [0m] Stopped unstoppable.service.
|
|
[[0;32m OK [0m] Stopped Permit User Sessions.
|
|
[[0;32m OK [0m] Stopped target Basic System.
|
|
[[0;32m OK [0m] Stopped target Paths.
|
|
[[0;32m OK [0m] Stopped target Slices.
|
|
[[0;32m OK [0m] Removed slice User and Session Slice.
|
|
[[0;32m OK [0m] Stopped target Sockets.
|
|
[[0;32m OK [0m] Closed D-Bus System Message Bus Socket.
|
|
[[0;32m OK [0m] Stopped target System Initialization.
|
|
[[0;32m OK [0m] Stopped Commit a transient machine-id on disk.
|
|
Stopping Update UTMP about System Boot/Shutdown...
|
|
Stopping Load/Save Random Seed...
|
|
[[0;32m OK [0m] Stopped Apply Kernel Variables.
|
|
[[0;32m OK [0m] Stopped target Encrypted Volumes.
|
|
[[0;32m OK [0m] Stopped Update is Completed.
|
|
[[0;32m OK [0m] Stopped Rebuild Journal Catalog.
|
|
[[0;32m OK [0m] Stopped Rebuild Hardware Database.
|
|
[[0;32m OK [0m] Stopped target Swap.
|
|
[[0;32m OK [0m] Stopped Load/Save Random Seed.
|
|
[[0;32m OK [0m] Stopped Update UTMP about System Boot/Shutdown.
|
|
[[0;32m OK [0m] Stopped Create Volatile Files and Directories.
|
|
[[0;32m OK [0m] Stopped target Local File Systems.
|
|
[[0;32m OK [0m] Stopped target Local File Systems (Pre).
|
|
[[0;32m OK [0m] Stopped Create Static Device Nodes in /dev.
|
|
[[0;32m OK [0m] Stopped Create System Users.
|
|
[[0;32m OK [0m] Stopped Remount Root and Kernel File Systems.
|
|
[[0;32m OK [0m] Reached target Shutdown.
|
|
[[0;32m OK [0m] Reached target Final Step.
|
|
Starting Power-Off...
|
|
[ 92.145013] reboot: Power down
|
|
-rw-r----- 1 root root 7733248 Oct 18 09:49 /var/tmp/systemd-test.knmVCK/journal/9be097ce844f4f44bab54c3cdbf21528/system.journal
|
|
TEST RUN: Job-related tests [FAILED]", result='fail')
|
|
[2018-10-18T16:04:58.0548 CEST] [debug] Loading a VM snapshot lastgood
|
|
[2018-10-18T16:04:58.0549 CEST] [debug] Loading snapshot (Current VM state is running).
|
|
[2018-10-18T16:04:58.0569 CEST] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":569069,"seconds":1539871498}}
|
|
[2018-10-18T16:04:58.0571 CEST] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
|
|
[2018-10-18T16:05:00.0595 CEST] [debug] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 28618 (/usr/bin/isotovideo: backen)
|
|
[2018-10-18T16:05:00.0878 CEST] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/pool/1/raid/hd0-overlay0 /var/lib/openqa/pool/1/raid/hd0-overlay1 42949672960
|
|
[2018-10-18T16:05:00.0896 CEST] [debug] Formatting '/var/lib/openqa/pool/1/raid/hd0-overlay1', fmt=qcow2 size=42949672960 backing_file=/var/lib/openqa/pool/1/raid/hd0-overlay0 encryption=off cluster_size=65536 lazy_refcounts=off refcount_bits=16
|
|
|
|
[2018-10-18T16:05:00.0896 CEST] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/pool/1/raid/cd0-overlay0 /var/lib/openqa/pool/1/raid/cd0-overlay1 668991488
|
|
[2018-10-18T16:05:00.0914 CEST] [debug] Formatting '/var/lib/openqa/pool/1/raid/cd0-overlay1', fmt=qcow2 size=668991488 backing_file=/var/lib/openqa/pool/1/raid/cd0-overlay0 encryption=off cluster_size=65536 lazy_refcounts=off refcount_bits=16
|
|
|
|
[2018-10-18T16:05:00.0914 CEST] [debug] starting: /usr/bin/qemu-system-x86_64 -vga cirrus -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -soundhw ac97 -global isa-fdc.driveA= -m 2048 -cpu qemu64 -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 usb-ehci -device usb-tablet -smp 1 -enable-kvm -no-shutdown -vnc :91,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/1/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/1/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/lib/os-autoinst/osutils.pm line 131.
|
|
Attempt 1 at /usr/lib/os-autoinst/osutils.pm line 131.
|
|
Attempts terminated! at /usr/lib/os-autoinst/osutils.pm line 137.
|
|
[2018-10-18T16:05:02.0922 CEST] [debug] qmpsocket 9
|
|
[2018-10-18T16:05:02.0926 CEST] [debug] EVENT {"data":{"status":"setup"},"timestamp":{"seconds":1539871502,"microseconds":926074},"event":"MIGRATION"}
|
|
[2018-10-18T16:05:03.0930 CEST] [debug] EVENT {"data":{"status":"active"},"timestamp":{"seconds":1539871502,"microseconds":934332},"event":"MIGRATION"}
|
|
[2018-10-18T16:05:05.0717 CEST] [debug] EVENT {"event":"MIGRATION","data":{"status":"completed"},"timestamp":{"seconds":1539871505,"microseconds":716903}}
|
|
/usr/lib/os-autoinst/consoles/vnc_base.pm:71:{
|
|
'port' => 5991,
|
|
'hostname' => 'localhost',
|
|
'connect_timeout' => 3
|
|
}
|
|
[2018-10-18T16:05:05.0774 CEST] [debug] pointer type 1 0 1024 768 -257
|
|
[2018-10-18T16:05:05.0774 CEST] [debug] led state 0 1 1 -261
|
|
[2018-10-18T16:05:05.0787 CEST] [debug] Restored snapshot
|
|
[2018-10-18T16:05:05.0787 CEST] [debug] EVENT {"data":{"client":{"websocket":false,"family":"ipv4","service":"42774","host":"127.0.0.1"},"server":{"service":"5991","websocket":false,"family":"ipv4","host":"0.0.0.0","auth":"none"}},"timestamp":{"seconds":1539871505,"microseconds":721395},"event":"VNC_CONNECTED"}
|
|
[2018-10-18T16:05:05.0787 CEST] [debug] EVENT {"data":{"server":{"service":"5991","websocket":false,"family":"ipv4","host":"0.0.0.0","auth":"none"},"client":{"family":"ipv4","websocket":false,"service":"42774","host":"127.0.0.1"}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":722076,"seconds":1539871505}}
|
|
[2018-10-18T16:05:05.0933 CEST] [debug] EVENT {"timestamp":{"microseconds":933625,"seconds":1539871505},"event":"RESUME"}
|
|
[2018-10-18T16:05:05.0941 CEST] [debug] QEMU: QEMU emulator version 2.9.1(openSUSE Leap 42.3)
|
|
[2018-10-18T16:05:05.0941 CEST] [debug] QEMU: Copyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers
|
|
[2018-10-18T16:05:05.0951 CEST] [debug] [autotest] process exited: 0
|
|
[2018-10-18T16:05:07.0960 CEST] [debug] commands process exited: 0
|
|
[2018-10-18T16:05:08.0961 CEST] [debug] isotovideo done
|
|
[2018-10-18T16:05:08.0962 CEST] [debug] QEMU status is not shutdown it is running
|
|
[2018-10-18T16:05:08.0962 CEST] [debug] BACKEND SHUTDOWN
|
|
[2018-10-18T16:05:08.0963 CEST] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
|
|
last frame
|
|
[2018-10-18T16:05:11.0041 CEST] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
|
|
[2018-10-18T16:05:11.0041 CEST] [debug] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 28618 (/usr/bin/isotovideo: backen)
|
|
[2018-10-18T16:05:11.0041 CEST] [debug] sending magic and exit
|
|
[2018-10-18T16:05:11.0042 CEST] [debug] received magic close
|
|
[2018-10-18T16:05:11.0053 CEST] [debug] backend process exited: 0
|
|
[2018-10-18T16:05:12.0055 CEST] [debug] killing backend process 28618
|
|
[2018-10-18T16:05:12.0055 CEST] [debug] done with backend process
|
|
28541: EXIT 0
|
|
[2018-10-18T16:05:12.0124 CEST] [info] Isotovideo exit status: 0
|
|
[2018-10-18T16:05:12.0186 CEST] [info] +++ worker notes +++
|
|
[2018-10-18T16:05:12.0186 CEST] [info] end time: 2018-10-18 14:05:12
|
|
[2018-10-18T16:05:12.0186 CEST] [info] result: done
|
|
[2018-10-18T16:05:12.0187 CEST] [info] uploading systemd_testsuite-dmesg.log
|
|
[2018-10-18T16:05:12.0245 CEST] [info] uploading systemd_testsuite-full_journal.log
|
|
[2018-10-18T16:05:12.0275 CEST] [info] uploading systemd_testsuite-systemd-testsuite-logs.tar.bz2
|
|
[2018-10-18T16:05:12.0307 CEST] [info] uploading video.ogv
|
|
[2018-10-18T16:05:12.0539 CEST] [info] uploading vars.json
|
|
[2018-10-18T16:05:12.0593 CEST] [info] uploading serial0.txt
|
|
[2018-10-18T16:05:12.0642 CEST] [info] uploading autoinst-log.txt
|