QA » openQA Project » openQA Tests

On https://openqa.opensuse.org/tests/869018 where firstboot test fails (probably due to some wayland crash), save_memory_dump is called, but fails with sysread failed: after memory dump completed.
Selecting root console works though, but export_logs() is not called.
Log:

[2019-03-04T21:27:40.169 CET] [debug] <<< testapi::save_memory_dump(filename='first_boot')
[2019-03-04T21:27:40.169 CET] [debug] Trying to save machine state
[2019-03-04T21:27:40.171 CET] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[1]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":550666,"seconds":1551727612}}
[2019-03-04T21:27:40.171 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"43196","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":816757,"seconds":1551728259}}
[2019-03-04T21:27:40.171 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"43822","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":818214,"seconds":1551728259}}
[2019-03-04T21:27:40.172 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"43822","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":822536,"seconds":1551728259}}
[2019-03-04T21:27:40.172 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"43822","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":54744,"seconds":1551728544}}
[2019-03-04T21:27:40.172 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44030","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":55369,"seconds":1551728544}}
[2019-03-04T21:27:40.172 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44030","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":59777,"seconds":1551728544}}
[2019-03-04T21:27:40.172 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44030","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":598405,"seconds":1551728592}}
[2019-03-04T21:27:40.173 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44072","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":598855,"seconds":1551728592}}
[2019-03-04T21:27:40.173 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44072","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":608763,"seconds":1551728592}}
[2019-03-04T21:27:40.173 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44072","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":145326,"seconds":1551728641}}
[2019-03-04T21:27:40.173 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44104","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":145772,"seconds":1551728641}}
[2019-03-04T21:27:40.173 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44104","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":160741,"seconds":1551728641}}
[2019-03-04T21:27:40.174 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44222","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":751338,"seconds":1551728728}}
[2019-03-04T21:27:40.174 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44104","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":751555,"seconds":1551728728}}
[2019-03-04T21:27:40.174 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44222","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":752581,"seconds":1551728728}}
[2019-03-04T21:27:40.174 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44222","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":759612,"seconds":1551728774}}
[2019-03-04T21:27:40.174 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44264","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":760246,"seconds":1551728774}}
[2019-03-04T21:27:40.174 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44264","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":766604,"seconds":1551728774}}
[2019-03-04T21:27:40.175 CET] [debug] EVENT {"data":{"guest":true},"event":"RESET","timestamp":{"microseconds":989644,"seconds":1551728932}}
[2019-03-04T21:27:40.175 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44264","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":65137,"seconds":1551729041}}
[2019-03-04T21:27:40.175 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44568","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":66049,"seconds":1551729041}}
[2019-03-04T21:27:40.175 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"44568","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5998","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":68519,"seconds":1551729041}}
[2019-03-04T21:27:40.175 CET] [debug] Migrating the machine (Current VM state is running).
[2019-03-04T21:27:40.210 CET] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":210482,"seconds":1551731260}}
[2019-03-04T21:27:40.213 CET] [debug] EVENT {"data":{"status":"setup"},"event":"MIGRATION","timestamp":{"microseconds":213212,"seconds":1551731260}}
[2019-03-04T21:27:40.716 CET] [debug] EVENT {"data":{"pass":1},"event":"MIGRATION_PASS","timestamp":{"microseconds":215361,"seconds":1551731260}}
[2019-03-04T21:27:40.717 CET] [debug] EVENT {"data":{"status":"active"},"event":"MIGRATION","timestamp":{"microseconds":215414,"seconds":1551731260}}
[2019-03-04T21:27:40.717 CET] [debug] Migrating total bytes:        2281979904
[2019-03-04T21:27:40.717 CET] [debug] Migrating remaining bytes:    1936412672
[2019-03-04T21:27:41.218 CET] [debug] Migrating total bytes:        2281979904
[2019-03-04T21:27:41.218 CET] [debug] Migrating remaining bytes:    1550688256
[2019-03-04T21:27:41.719 CET] [debug] Migrating total bytes:        2281979904
[2019-03-04T21:27:41.719 CET] [debug] Migrating remaining bytes:    1120489472
[2019-03-04T21:27:42.220 CET] [debug] Migrating total bytes:        2281979904
[2019-03-04T21:27:42.220 CET] [debug] Migrating remaining bytes:    647135232
[2019-03-04T21:27:42.720 CET] [debug] EVENT {"data":{"pass":2},"event":"MIGRATION_PASS","timestamp":{"microseconds":651870,"seconds":1551731262}}
[2019-03-04T21:27:42.721 CET] [debug] EVENT {"data":{"pass":3},"event":"MIGRATION_PASS","timestamp":{"microseconds":652970,"seconds":1551731262}}
[2019-03-04T21:27:42.805 CET] [debug] EVENT {"data":{"status":"completed"},"event":"MIGRATION","timestamp":{"microseconds":805011,"seconds":1551731262}}
[2019-03-04T21:27:42.805 CET] [debug] Migrating total bytes:        2281979904
[2019-03-04T21:27:42.805 CET] [debug] Migrating remaining bytes:    0
[2019-03-04T21:27:42.808 CET] [debug] Memory dump completed.
[2019-03-04T21:27:42.844 CET] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":844078,"seconds":1551731262}}
[2019-03-04T21:27:42.933 CET] [debug] backend process exited: 0
[2019-03-04T21:27:42.934 CET] [debug] sysread failed: 
[2019-03-04T21:27:42.938 CET] [debug] THERE IS NOTHING TO READ 15 4 3
[2019-03-04T21:27:42.939 CET] [debug] killing command server 32935 because test execution ended
[2019-03-04T21:27:42.939 CET] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20083/zHZn27HJZZl0510M/broadcast
last frame
[2019-03-04T21:27:42.994 CET] [debug] Driver backend collected unknown process with pid 32940 and exit status: 0
[2019-03-04T21:27:43.003 CET] [debug] commands process exited: 0
[2019-03-04T21:27:44.004 CET] [debug] done with command server
[2019-03-04T21:27:44.004 CET] [debug] killing autotest process 32937
[2019-03-04T21:27:44.004 CET] [debug] sysread failed: 
[2019-03-04T21:27:44.005 CET] [debug] /var/lib/openqa/share/tests/opensuse/tests/installation/first_boot.pm:107 called bootbasetest::post_fail_hook
[2019-03-04T21:27:44.005 CET] [debug] <<< testapi::select_console(testapi_console='root-console')
[2019-03-04T21:27:44.008 CET] [debug] post_fail_hook failed: syswrite failed Broken pipe at /usr/lib/os-autoinst/myjsonrpc.pm line 40.
myjsonrpc::send_json(GLOB(0xaaaafb7cb6b8), HASH(0xaaaafb808fa8)) called at /usr/lib/os-autoinst/autotest.pm line 320
autotest::query_isotovideo("backend_select_console", HASH(0xaaaafdffa9b0)) called at /usr/lib/os-autoinst/testapi.pm line 1470
testapi::select_console("root-console") called at /var/lib/openqa/share/tests/opensuse/lib/bootbasetest.pm line 22
bootbasetest::post_fail_hook("bootbasetest") called at /var/lib/openqa/share/tests/opensuse/tests/installation/first_boot.pm line 107
first_boot::post_fail_hook(first_boot=HASH(0xaaaafce9bb18)) called at /usr/lib/os-autoinst/basetest.pm line 324
eval {...} called at /usr/lib/os-autoinst/basetest.pm line 324
basetest::run_post_fail(first_boot=HASH(0xaaaafce9bb18), "test first_boot died") called at /usr/lib/os-autoinst/basetest.pm line 377
basetest::runtest(first_boot=HASH(0xaaaafce9bb18)) called at /usr/lib/os-autoinst/autotest.pm line 364
eval {...} called at /usr/lib/os-autoinst/autotest.pm line 364
autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 221
eval {...} called at /usr/lib/os-autoinst/autotest.pm line 221
autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 274
autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0xaaaafd4855d8)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 325
eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 325
Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0xaaaafd4855d8), CODE(0xaaaafd49e9f8)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 476
Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0xaaaafd4855d8)) called at /usr/lib/os-autoinst/autotest.pm line 275
autotest::start_process() called at /usr/bin/isotovideo line 296
[2019-03-04T21:27:44.017 CET] [debug] syswrite failed Broken pipe at /usr/lib/os-autoinst/myjsonrpc.pm line 40.
myjsonrpc::send_json(GLOB(0xaaaafb7cb6b8), HASH(0xaaaafdfff230)) called at /usr/lib/os-autoinst/autotest.pm line 320
autotest::query_isotovideo("set_current_test", HASH(0xaaaafdffa9b0)) called at /usr/lib/os-autoinst/autotest.pm line 181
autotest::set_current_test(undef) called at /usr/lib/os-autoinst/basetest.pm line 288
basetest::fail_if_running(first_boot=HASH(0xaaaafce9bb18)) called at /usr/lib/os-autoinst/basetest.pm line 327
basetest::run_post_fail(first_boot=HASH(0xaaaafce9bb18), "test first_boot died") called at /usr/lib/os-autoinst/basetest.pm line 377
basetest::runtest(first_boot=HASH(0xaaaafce9bb18)) called at /usr/lib/os-autoinst/autotest.pm line 364
eval {...} called at /usr/lib/os-autoinst/autotest.pm line 364
autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 221
eval {...} called at /usr/lib/os-autoinst/autotest.pm line 221
autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 274
autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0xaaaafd4855d8)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 325
eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 325
Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0xaaaafd4855d8), CODE(0xaaaafd49e9f8)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 476
Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0xaaaafd4855d8)) called at /usr/lib/os-autoinst/autotest.pm line 275
autotest::start_process() called at /usr/bin/isotovideo line 296
[2019-03-04T21:27:44.041 CET] [debug] [autotest] process exited: 0
[2019-03-04T21:27:45.041 CET] [debug] done with autotest process
[2019-03-04T21:27:45.042 CET] [debug] isotovideo failed
[2019-03-04T21:27:45.043 CET] [debug] killing backend process 32939
[2019-03-04T21:27:45.043 CET] [debug] done with backend process
32933: EXIT 1
[2019-03-04T21:27:45.0282 CET] [info] Isotovideo exit status: 1