Actions
action #111004
closedTimeout of test API functions not enforced if backend gets stuck, e.g. on the VNC socket size:M
Description
Observation¶
As seen in #99345, the wait_screen_change() timeout appears not to work.
[2022-05-11T13:46:24.602260+02:00] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
XIO: fatal IO error 4 (Interrupted system call) on X server ":37191"
after 23426 requests (23426 known processed) with 0 events remaining.
XIO: fatal IO error 11 (Resource temporarily unavailable) on X server ":34867"
after 28852 requests (28852 known processed) with 0 events remaining.
[2022-05-11T15:36:53.708309+02:00] [debug] autotest received signal TERM, saving results of current test before exiting
[2022-05-11T15:36:53.708518+02:00] [debug] isotovideo received signal TERM
[2022-05-11T15:36:53.708516+02:00] [debug] backend got TERM
Acceptance criteria¶
- AC1: wait_screen_change() timeout works again
Suggestions¶
- Add unit tests for wait_screen_change() or improve existing tests
- Tests in this scenario have a very high fail rate and can serve as reproducer: https://openqa.suse.de/tests/latest?arch=s390x&distri=sle&flavor=Server-DVD-Incidents-Minimal&machine=s390x-zVM-vswitch-l3&test=qam-minimal-full&version=12-SP5#next_previous
Files
Updated by livdywan almost 2 years ago
- Related to action #99345: [tools][qem] Incomplete test runs on s390x with auto_review:"backend died: Error connecting to VNC server.*s390.*Connection timed out":retry size:M added
Updated by mkittler almost 2 years ago
- Status changed from Workable to In Progress
PR for adding a unit test of wait_screen_change: https://github.com/os-autoinst/os-autoinst/pull/2056
However, the problem does not lie within that function. I suspect the backend is not responding anymore. Since the timeout is merely implemented as a check in autotest it is not effective if the backend hangs. Considering we don't even see the first log message I suspect it already hangs on query_isotovideo('backend_set_reference_screenshot');.
Looking further up in the logs of https://openqa.suse.de/tests/8735098/logfile?filename=autoinst-log.txt it also looks like the backend is even not responding anymore before the wait_screen_change call.
Updated by mkittler almost 2 years ago
There was a VNC stall in the middle so maybe that's where the backend got stuck:
[2022-05-11T13:46:17.067863+02:00] [debug] tests/installation/select_patterns.pm:28 called y2_installbase::process_patterns -> lib/y2_installbase.pm:202 called y2_installbase::select_specific_patterns_by_iteration -> lib/y2_installbase.pm:291 called testapi::check_screen
[2022-05-11T13:46:17.067985+02:00] [debug] <<< testapi::check_screen(mustmatch="on-pattern", timeout=1)
[2022-05-11T13:46:21.099030+02:00] [warn] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 3.13 seconds for 48 candidate needles - make your needles more specific
[2022-05-11T13:46:21.099179+02:00] [debug] no match: 0.1s, best candidate: on-pattern-puppet-20170523 (0.51)
[2022-05-11T13:46:21.099585+02:00] [debug] considering VNC stalled, no update for 4.84 seconds
[2022-05-11T13:46:23.975090+02:00] [warn] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.87 seconds for 48 candidate needles - make your needles more specific
[2022-05-11T13:46:23.975223+02:00] [debug] no match: -3.1s, best candidate: on-pattern-puppet-20170523 (0.51)
[2022-05-11T13:46:24.127396+02:00] [debug] >>> testapi::_check_backend_response: match=on-pattern timed out after 1 (check_screen)
[2022-05-11T13:46:24.151613+02:00] [debug] tests/installation/select_patterns.pm:28 called y2_installbase::process_patterns -> lib/y2_installbase.pm:202 called y2_installbase::select_specific_patterns_by_iteration -> lib/y2_installbase.pm:315 called testapi::check_screen
[2022-05-11T13:46:24.151789+02:00] [debug] <<< testapi::check_screen(mustmatch=[
"current-pattern-selected",
"on-category"
], timeout=0)
[2022-05-11T13:46:24.499413+02:00] [debug] no match: -0.1s, best candidate: on-category-20141218 (0.85)
[2022-05-11T13:46:24.585063+02:00] [debug] >>> testapi::_check_backend_response: match=current-pattern-selected,on-category timed out after 0 (check_screen)
[2022-05-11T13:46:24.602133+02:00] [debug] tests/installation/select_patterns.pm:28 called y2_installbase::process_patterns -> lib/y2_installbase.pm:202 called y2_installbase::select_specific_patterns_by_iteration -> lib/y2_installbase.pm:334 called y2_installbase::move_down -> lib/y2_installbase.pm:178 called testapi::wait_screen_change
[2022-05-11T13:46:24.602260+02:00] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
XIO: fatal IO error 4 (Interrupted system call) on X server ":37191"
after 23426 requests (23426 known processed) with 0 events remaining.
XIO: fatal IO error 11 (Resource temporarily unavailable) on X server ":34867"
after 28852 requests (28852 known processed) with 0 events remaining.
[2022-05-11T15:36:53.708309+02:00] [debug] autotest received signal TERM, saving results of current test before exiting
It also doesn't help to set the timeout of the previous check_screen to 0 like in the failing s390x tests. In my tests I'm always getting
[2022-05-13T15:27:47.872693+02:00] [debug] considering VNC stalled, no update for 1652448467.87 seconds
but that's not the case in the s390x examples. I suppose that means the backend is stuck in these tests for real and does not even check for a stalled VNC connection anymore.
Updated by openqa_review almost 2 years ago
- Due date set to 2022-05-28
Setting due date based on mean cycle time of SUSE QE Tools
Updated by mkittler almost 2 years ago
I've been trying to replicate the situation locally. So I've adjusted the tests of os-autoinst itself so there's a check_screen followed by a wait_screen_change. I also changed the VNC code so it won't read any messages anymore at some point. However, so far I wasn't able to reproduce the issue (all timeouts were handled and the backend didn't get stuck).
OS_AUTOINST_SIMULATE_VNC_CONSOLE_STUCK=10 RUN_DEBUGVIEWER=1 RUN_VNCVIEWER=1 os-autoinst-test t/99-full-stack.t
…
[2022-05-13T14:57:10.434695+02:00] [debug] considering VNC stalled, no update for 1652446630.43 seconds
[2022-05-13T14:57:10.436234+02:00] [warn] !!! (eval): Receiving VNC message: 898
[2022-05-13T14:57:10.436354+02:00] [warn] !!! (eval): Assuming VNC is stuck
[2022-05-13T14:57:10.684879+02:00] [warn] !!! (eval): Receiving VNC message: 899
[2022-05-13T14:57:10.684981+02:00] [warn] !!! (eval): Assuming VNC is stuck
[2022-05-13T14:57:10.881332+02:00] [debug] no match: -0.8s, best candidate: boot-on_prompt (0.00)
[2022-05-13T14:57:10.967133+02:00] [warn] !!! (eval): Receiving VNC message: 900
[2022-05-13T14:57:10.967243+02:00] [warn] !!! (eval): Assuming VNC is stuck
[2022-05-13T14:57:10.967361+02:00] [debug] considering VNC stalled, no update for 1652446630.97 seconds
[2022-05-13T14:57:10.968502+02:00] [warn] !!! (eval): Receiving VNC message: 901
[2022-05-13T14:57:10.968603+02:00] [warn] !!! (eval): Assuming VNC is stuck
[2022-05-13T14:57:11.071590+02:00] [debug] >>> testapi::_check_backend_response: match=on_prompt timed out after 60 (check_screen)
[2022-05-13T14:57:11.100990+02:00] [debug] tests/assert_screen.pm:10 called testapi::wait_screen_change
[2022-05-13T14:57:11.101181+02:00] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
wait screen change callback
[2022-05-13T14:57:11.105489+02:00] [debug] waiting for screen change: 0 1000000
[2022-05-13T14:57:11.217325+02:00] [warn] !!! (eval): Receiving VNC message: 902
[2022-05-13T14:57:11.217423+02:00] [warn] !!! (eval): Assuming VNC is stuck
[2022-05-13T14:57:11.467890+02:00] [warn] !!! (eval): Receiving VNC message: 903
[2022-05-13T14:57:11.467984+02:00] [warn] !!! (eval): Assuming VNC is stuck
[2022-05-13T14:57:11.468078+02:00] [debug] considering VNC stalled, no update for 1652446631.47 seconds
[2022-05-13T14:57:11.469788+02:00] [warn] !!! (eval): Receiving VNC message: 904
[2022-05-13T14:57:11.469899+02:00] [warn] !!! (eval): Assuming VNC is stuck
[2022-05-13T14:57:11.607811+02:00] [debug] waiting for screen change: 0 1000000
…
[2022-05-13T14:57:20.732588+02:00] [warn] !!! (eval): Receiving VNC message: 959
[2022-05-13T14:57:20.732736+02:00] [warn] !!! (eval): Assuming VNC is stuck
[2022-05-13T14:57:20.983308+02:00] [warn] !!! (eval): Receiving VNC message: 960
[2022-05-13T14:57:20.983390+02:00] [warn] !!! (eval): Assuming VNC is stuck
[2022-05-13T14:57:20.983470+02:00] [debug] considering VNC stalled, no update for 1652446640.98 seconds
[2022-05-13T14:57:20.984767+02:00] [warn] !!! (eval): Receiving VNC message: 961
[2022-05-13T14:57:20.984910+02:00] [warn] !!! (eval): Assuming VNC is stuck
[2022-05-13T14:57:21.232080+02:00] [debug] >>> testapi::wait_screen_change: timed out
[2022-05-13T14:57:21.232245+02:00] [debug] tests/assert_screen.pm:11 called testapi::assert_screen
[2022-05-13T14:57:21.232391+02:00] [debug] <<< testapi::assert_screen(mustmatch="on_prompt", no_wait=1, timeout=30)
…
Updated by mkittler almost 2 years ago
I'm currently looking at https://openqa.suse.de/tests/8764272#live via the developer mode. It appears to be stuck at:
[2022-05-16T11:59:55.339136+02:00] [debug] <<< testapi::check_screen(mustmatch="on-pattern", timeout=1)
[2022-05-16T11:59:58.313788+02:00] [warn] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.97 seconds for 48 candidate needles - make your needles more specific
[2022-05-16T11:59:58.313897+02:00] [debug] no match: 0.9s, best candidate: on-pattern-web-20180814 (0.80)
[2022-05-16T12:00:01.125745+02:00] [warn] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.81 seconds for 48 candidate needles - make your needles more specific
[2022-05-16T12:00:01.125851+02:00] [debug] no match: -2.0s, best candidate: on-pattern-web-20180814 (0.80)
[2022-05-16T12:00:01.263119+02:00] [debug] >>> testapi::_check_backend_response: match=on-pattern timed out after 1 (check_screen)
[2022-05-16T12:00:01.283039+02:00] [debug] tests/installation/select_patterns.pm:28 called y2_installbase::process_patterns -> lib/y2_installbase.pm:202 called y2_installbase::select_specific_patterns_by_iteration -> lib/y2_installbase.pm:315 called testapi::check_screen
[2022-05-16T12:00:01.283208+02:00] [debug] <<< testapi::check_screen(mustmatch=[
"current-pattern-selected",
"on-category"
], timeout=0)
[2022-05-16T12:00:01.698565+02:00] [debug] no match: -0.1s, best candidate: current-pattern-selected-20210614 (0.67)
[2022-05-16T12:00:01.785800+02:00] [debug] >>> testapi::_check_backend_response: match=current-pattern-selected,on-category timed out after 0 (check_screen)
[2022-05-16T12:00:01.803546+02:00] [debug] tests/installation/select_patterns.pm:28 called y2_installbase::process_patterns -> lib/y2_installbase.pm:202 called y2_installbase::select_specific_patterns_by_iteration -> lib/y2_installbase.pm:334 called y2_installbase::move_down -> lib/y2_installbase.pm:178 called testapi::wait_screen_change
[2022-05-16T12:00:01.803690+02:00] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2022-05-16T12:00:01.804530+02:00] [debug] tests/installation/select_patterns.pm:28 called y2_installbase::process_patterns -> lib/y2_installbase.pm:202 called y2_installbase::select_specific_patterns_by_iteration -> lib/y2_installbase.pm:334 called y2_installbase::move_down -> lib/y2_installbase.pm:178 called testapi::wait_screen_change -> lib/y2_installbase.pm:178 called testapi::send_key
[2022-05-16T12:00:01.804644+02:00] [debug] <<< testapi::send_key(key="down", wait_screen_change=0, do_wait=0)
That's from the live log. Maybe the send_key is cut off in the uploaded logs so it only appears that wait_screen_change is the last command it gets stuck on?
The developer console looks like this:
status: Connecting to wss://openqa.suse.de/liveviewhandler/tests/8764272/developer/ws-proxy
status: Using proxy: yes
status: Connection opened
<== {"data":null,"type":"info","what":"connecting to os-autoinst command server at ws:\/\/10.160.0.147:20013\/9t10sTRf__Zag5lT\/ws"}
<== {"data":null,"type":"info","what":"reusing previous connection to os-autoinst command server at ws:\/\/10.160.0.147:20013\/9t10sTRf__Zag5lT\/ws"}
status: tunnelled connection to os-autoinst concluded
==> {"cmd":"status"}
<== {"data":{"current_api_function":"check_screen","current_test_full_name":"installation-select_patterns","devel_mode_major_version":1,"devel_mode_minor_version":1,"developer_id":126,"developer_name":"mkittler","developer_session_started_at":"2022-05-16T09:58:12","developer_session_tab_count":1,"outstanding_files":null,"outstanding_images":null,"pause_on_next_command":0,"pause_on_screen_mismatch":false,"pause_test_name":null,"running":"select_patterns","tags":null,"test_execution_paused":0,"upload_up_to_current_module":null},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":["current-pattern-selected","on-category"],"timeout":0},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":null,"type":"info","what":"connecting to os-autoinst command server at ws:\/\/10.160.0.147:20013\/9t10sTRf__Zag5lT\/ws"}
<== {"data":null,"type":"info","what":"reusing previous connection to os-autoinst command server at ws:\/\/10.160.0.147:20013\/9t10sTRf__Zag5lT\/ws"}
status: tunnelled connection to os-autoinst concluded
==> {"cmd":"status"}
<== {"data":{"current_api_function":"check_screen","current_test_full_name":"installation-select_patterns","devel_mode_major_version":1,"devel_mode_minor_version":1,"developer_id":126,"developer_name":"mkittler","developer_session_started_at":"2022-05-16T09:58:12","developer_session_tab_count":2,"outstanding_files":null,"outstanding_images":null,"pause_on_next_command":0,"pause_on_screen_mismatch":false,"pause_test_name":null,"running":"select_patterns","tags":null,"test_execution_paused":0,"upload_up_to_current_module":null},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"check_screen","current_test_full_name":"installation-select_patterns","devel_mode_major_version":1,"devel_mode_minor_version":1,"developer_id":126,"developer_name":"mkittler","developer_session_started_at":"2022-05-16T09:58:12","developer_session_tab_count":2,"outstanding_files":null,"outstanding_images":null,"pause_on_next_command":0,"pause_on_screen_mismatch":false,"pause_test_name":null,"running":"select_patterns","tags":null,"test_execution_paused":0,"upload_up_to_current_module":null},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"tGNOJBLD"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"WSJVbqMz","key":" "}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"dSdlAOeS"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":0,"mustmatch":["current-pattern-unselected","current-pattern-autoselected"],"timeout":8},"current_api_function":"assert_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"MuXIclKS"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"loRxZuaD","key":"down"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"WcWvgYbE"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"HUXseTvO"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":"on-pattern","timeout":1},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"outstanding_files":0,"outstanding_images":0,"upload_up_to":null,"upload_up_to_current_module":null},"type":"info","what":"upload progress"}
<== {"data":{"check_screen":{"check":1,"mustmatch":["current-pattern-selected","on-category"],"timeout":0},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"ErYtsMSA"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"OPlOWwjS","key":" "}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"rxWHpCPj"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"AAVCgDbF"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"FcUhVxCJ"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"cUMzNagC"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"vBwwwtwy"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"krxZFyHp"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"JoVQTuQD"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"hkQCJUGv"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"VIgiLcvk"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"HkVbzOCD"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"lyVXoPPw"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"QpqqpAbQ"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"PjiilMJv"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"CogFnsTl"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"vgPIRKAO"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"qytGEOQQ"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"UjTKXRNn"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"wijWxdBQ"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"qWSnnZHF"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"JZDMfVQE"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"last_screenshot_data","last_screenshot_data":{"cmd":"backend_last_screenshot_data","json_cmd_token":"yttofPsg"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":0,"mustmatch":["current-pattern-unselected","current-pattern-autoselected"],"timeout":8},"current_api_function":"assert_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"alIIvNgQ"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"gkNPHqtz","key":"down"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"dROLDDlP"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"jVutFmmm"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":"on-pattern","timeout":1},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":["current-pattern-selected","on-category"],"timeout":0},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"THNwBjJH"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"UZLCkRQB","key":"down"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"rYKeLYzA"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"xCoMQeAw"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":"on-pattern","timeout":1},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":["current-pattern-selected","on-category"],"timeout":0},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"UQFgLwJN"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"iPYpGWRJ","key":" "}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"nVkgkUyo"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"jbYHMtni"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":0,"mustmatch":["current-pattern-unselected","current-pattern-autoselected"],"timeout":8},"current_api_function":"assert_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"xKRpaHdn"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"qdjkINSg","key":"down"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"oNgHyDjt"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"ucEGIqUn"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":"on-pattern","timeout":1},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":["current-pattern-selected","on-category"],"timeout":0},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"Lbhrmutn"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"tDruKQUy","key":" "}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"YWFGjaEW"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"pcxmFeUG"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":0,"mustmatch":["current-pattern-unselected","current-pattern-autoselected"],"timeout":8},"current_api_function":"assert_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"ixyhStWp"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"qntqBOBZ","key":"down"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"lHKnpnIt"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"WPEgmICz"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":"on-pattern","timeout":1},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":["current-pattern-selected","on-category"],"timeout":0},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"ECyLpZVE"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"EjSFmxHn","key":"down"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"zIPpgDbg"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"WksmkgpR"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":"on-pattern","timeout":1},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":["current-pattern-selected","on-category"],"timeout":0},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"kdFwAPPc"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"ZCehkQKa","key":"down"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"cmdSPmet"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"jszviymL"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":"on-pattern","timeout":1},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":["current-pattern-selected","on-category"],"timeout":0},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"YBFiniTb"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"syQpsyVc","key":"down"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"HIbvgnnA"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"SulWXJzC"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":"on-pattern","timeout":1},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":["current-pattern-selected","on-category"],"timeout":0},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"PZElAwdK"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"GIaLqqaB","key":"down"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"HMlobaXj"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"VewUIeji"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":"on-pattern","timeout":1},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":["current-pattern-selected","on-category"],"timeout":0},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"jnHFDFzh"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"ITqsSiBY","key":"down"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"oVrUNEao"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"mqioRApQ"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":"on-pattern","timeout":1},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":["current-pattern-selected","on-category"],"timeout":0},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"vTbhAVdR"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"kjVpQRPi","key":"down"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"ExDcjZSD"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"tstDtKWH"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":"on-pattern","timeout":1},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":["current-pattern-selected","on-category"],"timeout":0},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"tzQhSUCT"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"HRAFxkHR","key":"down"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"cCYTXsNH"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"similiarity_to_reference","similiarity_to_reference":{"cmd":"backend_similiarity_to_reference","json_cmd_token":"uSteeysJ"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":"on-pattern","timeout":1},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"check_screen":{"check":1,"mustmatch":["current-pattern-selected","on-category"],"timeout":0},"current_api_function":"check_screen"},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"set_reference_screenshot","set_reference_screenshot":{"cmd":"backend_set_reference_screenshot","json_cmd_token":"NTaqenve"}},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","send_key":{"cmd":"backend_send_key","json_cmd_token":"yOXHILZe","key":"down"}},"type":"info","what":"cmdsrvmsg"}
status: Connection closed, trying to reconnect in 500 ms
status: Connecting to wss://openqa.suse.de/liveviewhandler/tests/8764272/developer/ws-proxy
status: Using proxy: yes
status: Connection error: error (check JavaScript console for details)
status: Connection closed, trying to reconnect in 500 ms
status: Connecting to wss://openqa.suse.de/liveviewhandler/tests/8764272/developer/ws-proxy
status: Using proxy: yes
status: Connection error: error (check JavaScript console for details)
status: Connection closed, trying to reconnect in 500 ms
status: Connecting to wss://openqa.suse.de/liveviewhandler/tests/8764272/developer/ws-proxy
status: Using proxy: yes
status: Connection error: error (check JavaScript console for details)
status: Connection closed, trying to reconnect in 500 ms
status: Connecting to wss://openqa.suse.de/liveviewhandler/tests/8764272/developer/ws-proxy
status: Using proxy: yes
status: Connection opened
<== {"data":null,"type":"info","what":"connecting to os-autoinst command server at ws:\/\/10.160.0.147:20013\/9t10sTRf__Zag5lT\/ws"}
<== {"data":null,"type":"info","what":"connected to os-autoinst command server"}
status: tunnelled connection to os-autoinst concluded
==> {"cmd":"status"}
<== {"data":{"set_pause_on_screen_mismatch":false},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"ret":1},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","current_test_full_name":"installation-select_patterns","devel_mode_major_version":1,"devel_mode_minor_version":1,"developer_id":126,"developer_name":"mkittler","developer_session_started_at":"2022-05-16T09:58:12","developer_session_tab_count":2,"outstanding_files":0,"outstanding_images":0,"pause_on_next_command":0,"pause_on_screen_mismatch":false,"pause_test_name":null,"running":"select_patterns","tags":null,"test_execution_paused":0,"upload_up_to_current_module":null},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","current_test_full_name":"installation-select_patterns","devel_mode_major_version":1,"devel_mode_minor_version":1,"developer_id":126,"developer_name":"mkittler","developer_session_started_at":"2022-05-16T09:58:12","developer_session_tab_count":2,"outstanding_files":0,"outstanding_images":0,"pause_on_next_command":0,"pause_on_screen_mismatch":false,"pause_test_name":null,"running":"select_patterns","tags":null,"test_execution_paused":0,"upload_up_to_current_module":null},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","current_test_full_name":"installation-select_patterns","devel_mode_major_version":1,"devel_mode_minor_version":1,"developer_id":126,"developer_name":"mkittler","developer_session_started_at":"2022-05-16T09:58:12","developer_session_tab_count":2,"outstanding_files":0,"outstanding_images":0,"pause_on_next_command":0,"pause_on_screen_mismatch":false,"pause_test_name":null,"running":"select_patterns","tags":null,"test_execution_paused":0,"upload_up_to_current_module":null},"type":"info","what":"cmdsrvmsg"}
<== {"data":null,"type":"info","what":"connecting to os-autoinst command server at ws:\/\/10.160.0.147:20013\/9t10sTRf__Zag5lT\/ws"}
<== {"data":null,"type":"info","what":"reusing previous connection to os-autoinst command server at ws:\/\/10.160.0.147:20013\/9t10sTRf__Zag5lT\/ws"}
status: tunnelled connection to os-autoinst concluded
==> {"cmd":"status"}
<== {"data":{"current_api_function":"send_key","current_test_full_name":"installation-select_patterns","devel_mode_major_version":1,"devel_mode_minor_version":1,"developer_id":126,"developer_name":"mkittler","developer_session_started_at":"2022-05-16T09:58:12","developer_session_tab_count":2,"outstanding_files":0,"outstanding_images":0,"pause_on_next_command":0,"pause_on_screen_mismatch":false,"pause_test_name":null,"running":"select_patterns","tags":null,"test_execution_paused":0,"upload_up_to_current_module":null},"type":"info","what":"cmdsrvmsg"}
<== {"data":null,"type":"info","what":"connecting to os-autoinst command server at ws:\/\/10.160.0.147:20013\/9t10sTRf__Zag5lT\/ws"}
<== {"data":null,"type":"info","what":"reusing previous connection to os-autoinst command server at ws:\/\/10.160.0.147:20013\/9t10sTRf__Zag5lT\/ws"}
status: tunnelled connection to os-autoinst concluded
==> {"cmd":"status"}
<== {"data":{"current_api_function":"send_key","current_test_full_name":"installation-select_patterns","devel_mode_major_version":1,"devel_mode_minor_version":1,"developer_id":126,"developer_name":"mkittler","developer_session_started_at":"2022-05-16T09:58:12","developer_session_tab_count":3,"outstanding_files":0,"outstanding_images":0,"pause_on_next_command":0,"pause_on_screen_mismatch":false,"pause_test_name":null,"running":"select_patterns","tags":null,"test_execution_paused":0,"upload_up_to_current_module":null},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","current_test_full_name":"installation-select_patterns","devel_mode_major_version":1,"devel_mode_minor_version":1,"developer_id":126,"developer_name":"mkittler","developer_session_started_at":"2022-05-16T09:58:12","developer_session_tab_count":3,"outstanding_files":0,"outstanding_images":0,"pause_on_next_command":0,"pause_on_screen_mismatch":false,"pause_test_name":null,"running":"select_patterns","tags":null,"test_execution_paused":0,"upload_up_to_current_module":null},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","current_test_full_name":"installation-select_patterns","devel_mode_major_version":1,"devel_mode_minor_version":1,"developer_id":126,"developer_name":"mkittler","developer_session_started_at":"2022-05-16T09:58:12","developer_session_tab_count":3,"outstanding_files":0,"outstanding_images":0,"pause_on_next_command":0,"pause_on_screen_mismatch":false,"pause_test_name":null,"running":"select_patterns","tags":null,"test_execution_paused":0,"upload_up_to_current_module":null},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"category":"cmdsrv-connection","code":1006,"reason":null},"type":"error","what":"connection to os-autoinst command server lost"}
status: Connection closed, trying to reconnect in 500 ms
status: Connecting to wss://openqa.suse.de/liveviewhandler/tests/8764272/developer/ws-proxy
status: Using proxy: yes
status: Connection opened
<== {"data":null,"type":"info","what":"connecting to os-autoinst command server at ws:\/\/10.160.0.147:20013\/9t10sTRf__Zag5lT\/ws"}
<== {"data":null,"type":"info","what":"reusing previous connection to os-autoinst command server at ws:\/\/10.160.0.147:20013\/9t10sTRf__Zag5lT\/ws"}
status: tunnelled connection to os-autoinst concluded
==> {"cmd":"status"}
<== {"data":{"current_api_function":"send_key","current_test_full_name":"installation-select_patterns","devel_mode_major_version":1,"devel_mode_minor_version":1,"developer_id":126,"developer_name":"mkittler","developer_session_started_at":"2022-05-16T09:58:12","developer_session_tab_count":3,"outstanding_files":0,"outstanding_images":0,"pause_on_next_command":0,"pause_on_screen_mismatch":false,"pause_test_name":null,"running":"select_patterns","tags":null,"test_execution_paused":0,"upload_up_to_current_module":null},"type":"info","what":"cmdsrvmsg"}
<== {"data":{"current_api_function":"send_key","current_test_full_name":"installation-select_patterns","devel_mode_major_version":1,"devel_mode_minor_version":1,"developer_id":126,"developer_name":"mkittler","developer_session_started_at":"2022-05-16T09:58:12","developer_session_tab_count":3,"outstanding_files":0,"outstanding_images":0,"pause_on_next_command":0,"pause_on_screen_mismatch":false,"pause_test_name":null,"running":"select_patterns","tags":null,"test_execution_paused":0,"upload_up_to_current_module":null},"type":"info","what":"cmdsrvmsg"}
Updated by mkittler almost 2 years ago
Looks like I killed the job by sending an arbitrary backend command via web sockets:
[2022-05-16T12:17:43.436137+02:00] [warn] cmdsrv: failed to decode message
isotovideo: we need to implement a backend queue at /usr/lib/os-autoinst/OpenQA/Isotovideo/CommandHandler.pm line 126.
OpenQA::Isotovideo::CommandHandler::_pass_command_to_backend_unless_paused(OpenQA::Isotovideo::CommandHandler=HASH(0x55f795fb92c8), HASH(0x55f7963c89c0), "eject_cd") called at /usr/lib/os-autoinst/OpenQA/Isotovideo/CommandHandler.pm line 72
OpenQA::Isotovideo::CommandHandler::process_command(OpenQA::Isotovideo::CommandHandler=HASH(0x55f795fb92c8), GLOB(0x55f791bcd540), HASH(0x55f7963c89c0)) called at /usr/bin/isotovideo line 353
So isotovideo is definitely in the state where it still waits for the backend to respond (but would otherwise be responsive itself). And the command server also seems still responsive. So it is likely the backend which doesn't provide a response (as already assumed anyways).
Updated by mkittler almost 2 years ago
- Subject changed from wait_screen_change ignores the timeout size:M to Timeout of test API functions not enforced if backend gets stuck, e.g. on the VNC socket size:M
The send_key backend command boils down to sending data over the VNC socket - in a blocking manner. All our VNC code (receiving and sending) is actually blocking. The only exception is waiting for a new message. However, if the connection gets stuck after a while reading further data of that message (after the start of the message) or when we send any data the backend process can get stuck on the read/write from/to the VNC socket. Then also the test driver will get stuck waiting for the backend's message. Any timeout implemented on e.g. test driver level is toothless. The only effective timeouts are the timeout on the socket (Error connecting to VNC server.*s390.*Connection timed out) and the timeout for the full test execution enforced by the worker (test execution exceeded MAX_JOB_TIME). And those are also the only two different error messages we're getting for problem (this ticket and #99345).
Updated by mkittler almost 2 years ago
PR for having an explicit timeout on the socket: https://github.com/os-autoinst/os-autoinst/pull/2061 - I'm currently trying it out on openqaworker2.
Note that the VNC code cannot be made easily made async so I guess this is the best approach. It still means that functions like wait_screen_change will hang up to a minute (for remote VNC connections) but I guess we can live with that as long as the test isn't completely stuck running into the overall timeout.
Updated by mkittler almost 2 years ago
I'm currently seeing another occurrence where it is stuck at wait_screen_change(). The internal backend command it is stuck at is set_reference_screenshot. So it is actually stuck before the actually waiting part of wait_screen_change() takes place.
I've attached on the backend via strace and it is pretty clear that it hangs on a blocking read:
martchus@openqaworker2:~/patches> sudo strace -p 15119
strace: Process 15119 attached
read(24,
I suspect it is a read on the VNC socket.
Updated by mkittler almost 2 years ago
My test job (https://openqa.suse.de/tests/8765381) now hangs in the same situation:
martchus@openqaworker2:~> sudo strace -p 12689
strace: Process 12689 attached
read(24,
Unfortunately I don't have the previous strace log because my VPN connection broke in the middle.
However, there are occurrences of 24 before in my terminal history:
select(24, [8 13 19], [8 13], NULL, {tv_sec=0, tv_usec=7619}) = 1 (out [8], left {tv_sec=0, tv_usec=7616})
write(8, "E 2359340\n", 10) = 10
openat(AT_FDCWD, "serial0", O_RDONLY) = 24
ioctl(24, TCGETS, 0x7ffc05c61900) = -1 ENOTTY (Unpassender IOCTL (I/O-Control) für das Gerät)
lseek(24, 0, SEEK_CUR) = 0
fstat(24, {st_mode=S_IFREG|0644, st_size=2248, ...}) = 0
fcntl(24, F_SETFD, FD_CLOEXEC) = 0
lseek(24, 2246, SEEK_SET) = 2246
lseek(24, 0, SEEK_CUR) = 2246
fstat(24, {st_mode=S_IFREG|0644, st_size=2248, ...}) = 0
read(24, "\r\n", 8192) = 2
read(24, "", 8192) = 0
close(24) = 0
select(24, [8 13 19], [8 13], NULL, {tv_sec=0, tv_usec=240792}) = 1 (out [8], left {tv_sec=0, tv_usec=240790})
Calls of that pattern are repeating (also with openat(AT_FDCWD, "serial0", O_RDONLY) = 24). Otherwise 24 is only used in select() calls.
So the blocking read is actually about the serial file. The serial file is where it should be and reading from it is not a problem. So I find it rather strange that the backend is stuck reading it.
I started another job. This time I've been following the strace log more closely from the beginning. Here it is quite clear that 24 is the VNC socket:
socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 24
ioctl(24, TCGETS, 0x7fffc89d9680) = -1 ENOTTY (Unpassender IOCTL (I/O-Control) für das Gerät)
lseek(24, 0, SEEK_CUR) = -1 ESPIPE (Nicht erlaubter Seek)
ioctl(24, TCGETS, 0x7fffc89d9680) = -1 ENOTTY (Unpassender IOCTL (I/O-Control) für das Gerät)
lseek(24, 0, SEEK_CUR) = -1 ESPIPE (Nicht erlaubter Seek)
fcntl(24, F_SETFD, FD_CLOEXEC) = 0
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
connect(24, {sa_family=AF_INET, sin_port=htons(5901), sin_addr=inet_addr("10.162.42.104")}, 16) = -1 EINPROGRESS (Die Operation ist jetzt in Bearbeitung)
select(32, NULL, [24], [24], {tv_sec=60, tv_usec=0}) = 1 (out [24], left {tv_sec=59, tv_usec=999668})
connect(24, {sa_family=AF_INET, sin_port=htons(5901), sin_addr=inet_addr("10.162.42.104")}, 16) = 0
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
setsockopt(24, SOL_SOCKET, SO_DEBUG, [1], 4) = -1 EACCES (Keine Berechtigung)
read(24, "RFB 003.008\n", 8192)
write(24, "RFB 003.008\n", 12) = 12
When I now open the serial log while the VNC connection is still ok I get:
openat(AT_FDCWD, "serial0", O_RDONLY) = 25
ioctl(25, TCGETS, 0x7fffc89d95c0) = -1 ENOTTY (Unpassender IOCTL (I/O-Control) für das Gerät)
lseek(25, 0, SEEK_CUR) = 0
fstat(25, {st_mode=S_IFREG|0644, st_size=2318, ...}) = 0
fcntl(25, F_SETFD, FD_CLOEXEC) = 0
lseek(25, 2306, SEEK_SET) = 2306
lseek(25, 0, SEEK_CUR) = 2306
fstat(25, {st_mode=S_IFREG|0644, st_size=2318, ...}) = 0
read(25, "\r\nMZsvh-0-\r\n", 8192) = 12
read(25, "", 8192) = 0
close(25) = 0
So the file number of serial0 is now 25 instead of 24. I assume it is simply the next integer after the VNC socket and when I looked at the last job's strace the VNC socket was already broken so the serial log ended up as 24. So this is about the VNC socket and serial0 is just a distraction. Unfortunately, this run actually succeeded (https://openqa.suse.de/tests/8765966) so I couldn't gather any further information about the error case.
By the way, it seems that our attempt of disabling Naegle's algorithm for the VNC connection results in a permission error.
Updated by mkittler almost 2 years ago
I did another test run. strace output shortly before VNC gets stuck: https://openqa.suse.de/tests/8770715
select(24, [8 13 19], [8 13], NULL, {tv_sec=0, tv_usec=94375}) = 1 (out [8], left {tv_sec=0, tv_usec=94370})
write(8, "R\n", 2) = 2
select(24, [13 19], [13], NULL, {tv_sec=0, tv_usec=87292}) = 1 (in [13], left {tv_sec=0, tv_usec=44014})
select(16, [13], NULL, NULL, NULL) = 1 (in [13])
read(13, "{\"arguments\":{\"cmd\":\"backend_set"..., 8000000) = 146
write(16, "{\"json_cmd_token\":\"lbzurMnM\",\"rs"..., 38) = 38
select(24, [13 19], [13], NULL, {tv_sec=0, tv_usec=43540}) = 1 (in [13], left {tv_sec=0, tv_usec=43042})
select(16, [13], NULL, NULL, NULL) = 1 (in [13])
read(13, "{\"arguments\":{\"cmd\":\"backend_sen"..., 8000000) = 127
write(24, "\4\1\0\0\0\0\377T", 8) = 8
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=33333000}, NULL) = 0
write(24, "\4\0\0\0\0\0\377T", 8) = 8
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=33333000}, NULL) = 0
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(24, "\0\0\377\377\1@\0\200\1@\0\25\0\0\0\20\0\0\0\vb\324LEF\0\0\0\0\377\377\1"..., 8192) = 4096
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(24, 0x564f53966f90, 8192) = -1 EAGAIN (Die Ressource ist zur Zeit nicht verfügbar)
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
write(24, "\3\1\0\0\0\0\4\0\3\0", 10) = 10
select(24, [13 19], [13], NULL, {tv_sec=0, tv_usec=199979}) = 0 (Timeout)
write(16, "{\"json_cmd_token\":\"BxXEcyfh\",\"rs"..., 39) = 39
select(24, [13 19], [13], NULL, {tv_sec=0, tv_usec=48073}) = 1 (in [13], left {tv_sec=0, tv_usec=47865})
select(16, [13], NULL, NULL, NULL) = 1 (in [13])
read(13, "{\"arguments\":{\"cmd\":\"backend_sim"..., 8000000) = 146
write(16, "{\"json_cmd_token\":\"BWrrkHwz\",\"rs"..., 54) = 54
select(24, [13 19], [13], NULL, {tv_sec=0, tv_usec=46307}) = 0 (Timeout)
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(24, 0x564f53966f90, 8192) = -1 EAGAIN (Die Ressource ist zur Zeit nicht verfügbar)
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
write(24, "\3\1\0\0\0\0\4\0\3\0", 10) = 10
select(24, [13 19], [13], NULL, {tv_sec=0, tv_usec=130810}) = 0 (Timeout)
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(24, 0x564f53966f90, 8192) = -1 EAGAIN (Die Ressource ist zur Zeit nicht verfügbar)
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
…
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(24, 0x564f53966f90, 8192) = -1 EAGAIN (Die Ressource ist zur Zeit nicht verfügbar)
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
write(24, "\3\0\0\0\0\0\0\20\0\20", 10) = 10
write(24, "\3\0\0\0\0\0\4\0\3\0", 10) = 10
write(16, "{\"json_cmd_token\":\"lVEZpqvT\",\"rs"..., 38) = 38
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(24, 0x564f53966f90, 8192) = -1 EAGAIN (Die Ressource ist zur Zeit nicht verfügbar)
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
write(24, "\3\0\0\0\0\0\0\20\0\20", 10) = 10
write(24, "\3\1\0\0\0\0\4\0\3\0", 10) = 10
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(24, 0x564f53966f90, 8192) = -1 EAGAIN (Die Ressource ist zur Zeit nicht verfügbar)
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
…
select(24, [8 13 19], [8 13], NULL, {tv_sec=0, tv_usec=500000}) = 2 (in [13], out [8], left {tv_sec=0, tv_usec=499993})
write(8, "R\n", 2) = 2
select(16, [13], NULL, NULL, NULL) = 1 (in [13])
read(13, "{\"cmd\":\"check_asserted_screen\",\""..., 8000000) = 60
flock(2, LOCK_EX) = 0
write(2, "\33[31m", 5) = 5
flock(2, LOCK_UN) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}) = 0
flock(2, LOCK_EX) = 0
write(2, "[2022-05-17T10:33:35.428262+02:0"..., 188) = 188
flock(2, LOCK_UN) = 0
flock(2, LOCK_EX) = 0
write(2, "\33[0m", 4) = 4
flock(2, LOCK_UN) = 0
flock(2, LOCK_EX) = 0
write(2, "\33[37m", 5) = 5
flock(2, LOCK_UN) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}) = 0
flock(2, LOCK_EX) = 0
write(2, "[2022-05-17T10:33:35.428699+02:0"..., 110) = 110
flock(2, LOCK_UN) = 0
flock(2, LOCK_EX) = 0
write(2, "\33[0m", 4) = 4
flock(2, LOCK_UN) = 0
write(16, "{\"json_cmd_token\":\"ZZKBzviw\",\"rs"..., 9735570) = 9735570
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(24, "\0\0\377\377\0\0\0\0\0\20\0\20\0\0\0\20\0\0\0\tbd`\0\0\0\0\377\377\0\0\0"..., 8192) = 8192
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
read(24, "\20J\226\361\22\3\334\327\25\302q\231Zt\334!X\212\357_*\221\303^\274~->\257\7\36h"..., 8192) = 8192
read(24, "\27\22zl\372\301\17\312y \243:\250\v\303\234\364\321\30D\251\216\233\326\316\340\23\26\0es\10"..., 8192) = 8192
read(24, "8\225\335\326\204\342>d\23Z}\332\336\206(\262\355\7\220E\235#\21\316FL\16!\257\4\325\7"..., 8192) = 8192
read(24, "x\342\211;rJ6s\321\325\303\241\315\203j]\251l\36PJ\231\360\254\270\246T\240\330\340\331\211"..., 8192) = 98
read(24,
I manually connected via vncviewer -Shared s390qa102.qa.suse.de:5901 and it generally worked - although the output looked a bit distorted. As if the VNC server on the other end had some trouble. I tried to connect again and got the same distorted image. An interaction with the system was not possible as well. I tried several times again and it never worked. So even if we'd manage to implement a re-connect it would likely be pointless. It also means that the network connectivity isn't at fault; it is the VNC server it self. I could also reach s390qa102.qa.suse.de from openqaworker2.
I still don't understand why the backend is stuck. I specified a timeout on socket creation so I'd expect that the blocking operations should abort after one minute.
Just for the record, that's what I've got:
vncviewer -Shared s390qa102.qa.suse.de:5901
TigerVNC Viewer 64-bit v1.12.0
Copyright (C) 1999-2021 TigerVNC Team and many others (see README.rst)
See https://www.tigervnc.org for information on TigerVNC.
Tue May 17 11:15:33 2022
DecodeManager: Detected 8 CPU core(s)
DecodeManager: Creating 4 decoder thread(s)
CConn: Verbunden mit Rechner s390qa102.qa.suse.de, Port 5901
CConnection: Server supports RFB protocol version 3.8
CConnection: Using RFB protocol version 3.8
CConnection: Choosing security type VeNCrypt(19)
CVeNCrypt: Choosing security type TLSVnc (258)
Tue May 17 11:15:35 2022
CConn: Pixelformat depth 24 (32bpp) little-endian rgb888 wird verwendet
CConnection: Enabling continuous updates
Updated by mkittler almost 2 years ago
Looks like there's a very easy way to tell what fd is what:
martchus@openqaworker2:/var/lib/openqa/pool/2> sudo ls -l /proc/14082/fd
insgesamt 0
lr-x------ 1 _openqa-worker nogroup 64 17. Mai 11:22 0 -> 'pipe:[6524790]'
l-wx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 1 -> /var/lib/openqa/pool/2/autoinst-log.txt
l-wx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 10 -> 'pipe:[6524791]'
lr-x------ 1 _openqa-worker nogroup 64 17. Mai 11:22 11 -> 'pipe:[6524792]'
l-wx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 12 -> 'pipe:[6524792]'
lr-x------ 1 _openqa-worker nogroup 64 17. Mai 11:22 13 -> 'pipe:[6524793]'
lrwx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 14 -> 'socket:[6581864]'
lr-x------ 1 _openqa-worker nogroup 64 17. Mai 11:22 15 -> 'pipe:[6484804]'
l-wx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 16 -> 'pipe:[6524794]'
lrwx------ 1 _openqa-worker nogroup 64 17. Mai 10:23 17 -> 'socket:[6588433]'
l-wx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 18 -> 'pipe:[6524795]'
lrwx------ 1 _openqa-worker nogroup 64 17. Mai 10:23 19 -> 'socket:[6588434]'
l-wx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 2 -> /var/lib/openqa/pool/2/autoinst-log.txt
l-wx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 20 -> 'pipe:[6524796]'
l-wx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 21 -> 'pipe:[6484803]'
lr-x------ 1 _openqa-worker nogroup 64 17. Mai 11:22 22 -> 'pipe:[6484805]'
lrwx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 23 -> 'socket:[6588437]'
lrwx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 24 -> 'socket:[6601713]'
lrwx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 3 -> 'socket:[6524784]'
lrwx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 4 -> 'socket:[6524788]'
l-wx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 5 -> /var/lib/openqa/pool/2/autoinst-log.txt
l-wx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 6 -> /var/lib/openqa/pool/2/autoinst-log.txt
lr-x------ 1 _openqa-worker nogroup 64 17. Mai 11:22 7 -> 'pipe:[6524790]'
l-wx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 8 -> 'pipe:[6581859]'
l-wx------ 1 _openqa-worker nogroup 64 17. Mai 11:22 9 -> /var/lib/openqa/pool/2/video_time.vtt
martchus@openqaworker2:/var/lib/openqa/pool/2> sudo cat /proc/14082/fdinfo/24
pos: 0
flags: 02000002
mnt_id: 9
The socket still counts as an established connection:
martchus@openqaworker2:/var/lib/openqa/pool/2> sudo lsof -i -a -p 14082
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
/usr/bin/ 14082 _openqa-worker 14u IPv4 6581864 0t0 TCP localhost:53504->localhost:38359 (ESTABLISHED)
/usr/bin/ 14082 _openqa-worker 17u IPv4 6588433 0t0 TCP openqaworker2.suse.de:46216->10.162.42.102:ssh (ESTABLISHED)
/usr/bin/ 14082 _openqa-worker 19u IPv4 6588434 0t0 TCP openqaworker2.suse.de:46218->10.162.42.102:ssh (ESTABLISHED)
/usr/bin/ 14082 _openqa-worker 23u IPv4 6588437 0t0 TCP localhost:47110->localhost:58369 (ESTABLISHED)
/usr/bin/ 14082 _openqa-worker 24u IPv4 6601713 0t0 TCP openqaworker2.suse.de:47604->10.162.42.102:5901 (ESTABLISHED)
Judging by the comment on the second answer of https://stackoverflow.com/questions/8284243/how-do-i-set-so-rcvtimeo-on-a-socket-in-perl the timeout specified when constructing the socket only applies to connect/accept. Maybe I can use the solution from the accepted answer.
Updated by mkittler almost 2 years ago
It actually kind of works:
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(24, "\0\0\377\377\0\0\0\0\0\20\0\20\0\0\0\20\0\0\0\vx\234bd`\0\0\0\0\377\377\0"..., 8192) = 8192
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
read(24, "L\307\5@\242\22H\274m,\311h5\203\202\"\361\215{ &\35\345\204|\302\262\264\363\264$\23"..., 8192) = 8192
read(24, "\363>\3579s\22\316\26_\2\32(\362'\342\33\263|W\360\355\267\253g\227\357\362\365\213+\333|"..., 8192) = 8192
read(24, "\253\36\220{\351%V\332Z\335+\246@\2268\353\271\255\264\271\306\4\306\207\275Y\351Fe\2551\375"..., 8192) = 8192
read(24, "\217\3502\211\356G\311(\372\352XY\275\352|.....\256\357\273\204\3063\327\20\265\320\343\247"..., 8192) = 8192
read(24, "\354$\311\2137\3602\340XOCO\336\300\325\222\36\222\217\374\232\376O\2574\270+\263\301H\377\2"..., 8192) = 6339
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(24, 0x560562a6ea80, 8192) = -1 EAGAIN (Die Ressource ist zur Zeit nicht verfügbar)
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
write(24, "\3\1\0\0\0\0\4\0\3\0", 10) = 10
select(24, [13 19], [13], NULL, {tv_sec=0, tv_usec=25722}) = 0 (Timeout)
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(24, 0x560562a6ea80, 8192) = -1 EAGAIN (Die Ressource ist zur Zeit nicht verfügbar)
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}) = 0
select(24, [8 13 19], [8 13], NULL, {tv_sec=0, tv_usec=217767}) = 1 (out [8], left {tv_sec=0, tv_usec=217763})
Apparently we don't handle EAGAIN so it just continues with the next read which also times out. However, then it is able to move on. And what I find most surprisingly, it even continues to work. While vncviewer still appears stuck very shortly after connecting, os-autoinst's VNC client is still working. Well, at some point it got caught up again:
select(24, [13 19], [13], NULL, {tv_sec=0, tv_usec=41998}) = 0 (Timeout)
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(24, "\0\0\377\377\0\0\0\0\4\0\0\23\0\0\0\20\0\0\0\vbd` \t\1\0\0\0\377\377\0"..., 8192) = 8192
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
read(24, "Y\330\370\33\230Uey\340\332D\331\32\30y\244\370\330\31\204\370\244\365\\\30\224\204\225\265\331\220\265"..., 8192) = 8192
read(24, "\306\243O\321\362_\355\277\364u<X!}\371\303\267\214`\225\24-\377j\371\373\243\25\266:z\356"..., 8192) = 8192
read(24, "w;\341\242\t\23B\244 8\201\24|\366\6\262\213\250\27M\30\20B\5\277\t\250\240\263;\\\367"..., 8192) = 8192
read(24, "}(n\347\271\204\"\332\310m\326\\\360Q\223\234bT\324sL\227\225\240\323U\347c\32\0255\256"..., 8192) = 8192
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
read(24, "\3130\311\32\216\336\313\271\232AJ\250\27\366\324yF\253J\16\354d\264M\270\246\25\330#Nr\333"..., 8192) = 8192
read(24, "\3\335w\315,\277\365\232\227\361\223\25n\232B\250\3469b\350z\221\347\342?\271\6\272#\311j\3"..., 8192) = 2853
read(24, 0x560562a6ea80, 8192) = -1 EAGAIN (Die Ressource ist zur Zeit nicht verfügbar)
read(24,
However, it could again continue. (I'm now not scrolling up again to copy the continued logs.)
So I'm committing my changes which I'm currently testing on openqaworker2 and push them to https://github.com/os-autoinst/os-autoinst/pull/2061.
Updated by mkittler almost 2 years ago
I've updated the PR and added another commit to set the timeout portably in C++. The verification run for this is still running: https://openqa.suse.de/tests/8771207#live
However, it already looks good. strace also clearly shows the additional syscalls to set the timeout:
socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 24
ioctl(24, TCGETS, 0x7ffe02ec12c0) = -1 ENOTTY (Unpassender IOCTL (I/O-Control) für das Gerät)
lseek(24, 0, SEEK_CUR) = -1 ESPIPE (Nicht erlaubter Seek)
ioctl(24, TCGETS, 0x7ffe02ec12c0) = -1 ENOTTY (Unpassender IOCTL (I/O-Control) für das Gerät)
lseek(24, 0, SEEK_CUR) = -1 ESPIPE (Nicht erlaubter Seek)
fcntl(24, F_SETFD, FD_CLOEXEC) = 0
fcntl(24, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(24, F_SETFL, O_RDWR|O_NONBLOCK) = 0
connect(24, {sa_family=AF_INET, sin_port=htons(5901), sin_addr=inet_addr("10.162.42.102")}, 16) = -1 EINPROGRESS (Die Operation ist jetzt in Bearbeitung)
select(32, NULL, [24], [24], {tv_sec=60, tv_usec=0}) = 1 (out [24], left {tv_sec=59, tv_usec=994384})
connect(24, {sa_family=AF_INET, sin_port=htons(5901), sin_addr=inet_addr("10.162.42.102")}, 16) = 0
fcntl(24, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(24, F_SETFL, O_RDWR) = 0
setsockopt(24, SOL_SOCKET, SO_DEBUG, [1], 4) = -1 EACCES (Keine Berechtigung)
setsockopt(24, SOL_SOCKET, SO_RCVTIMEO_OLD, "<\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 16) = 0
setsockopt(24, SOL_SOCKET, SO_SNDTIMEO_OLD, "<\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 16) = 0
read(24, "RFB 003.008\n", 8192) = 12
write(24, "RFB 003.008\n", 12) = 12
(The first setsockopt call was failing with EACCESS before but that's unrelated. It is for our attempt to disable Naegle's algorithm which apparently doesn't work.)
Updated by mkittler almost 2 years ago
The PR has been merged and I have tested the changes in production on two jobs. Considering the strace log the tests would have been stuck but they passed with the changes. I'll keep the changes on openqaworker2 (but of course removed my repo again).
Since I currently don't see any other reason why the backend would be stuck I'm resolving the issue. (We do blocking file I/O but I suppose it is ok.)
Updated by mkittler almost 2 years ago
- Status changed from In Progress to Resolved
Updated by okurz almost 2 years ago
- Related to action #113282: Many incompletes due to VNC error "backend died: unexpected end of data at /usr/lib/os-autoinst/consoles/VNC.pm line 183.", especially on o3/aarch64 size:M added
Actions