openQA Project (public)

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.

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)
…

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"}

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).

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.

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.

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.

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.

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.

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.)

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.)