QA (public) » openQA Project (public)

This is an autogenerated message for openQA integration by the openqa_review script:

This bug is still referenced in a failing openQA test: qam-vsftpd-client
https://openqa.suse.de/tests/4118883

To prevent further reminder comments one of the following options should be followed:

1. The test scenario is fixed by applying the bug fix to the tested product or the test is adjusted
2. The openQA job group is moved to "Released"
3. The label in the openQA scenario is removed

This is an autogenerated message for openQA integration by the openqa_review script:

This bug is still referenced in a failing openQA test: qam-salt-minion
https://openqa.suse.de/tests/4196266

To prevent further reminder comments one of the following options should be followed:

1. The test scenario is fixed by applying the bug fix to the tested product or the test is adjusted
2. The openQA job group is moved to "Released"
3. The label in the openQA scenario is removed

This is an autogenerated message for openQA integration by the openqa_review script:

This bug is still referenced in a failing openQA test: mru-install-multipath-remote
https://openqa.suse.de/tests/4256295

To prevent further reminder comments one of the following options should be followed:

1. The test scenario is fixed by applying the bug fix to the tested product or the test is adjusted
2. The openQA job group is moved to "Released"
3. The label in the openQA scenario is removed

This is an autogenerated message for openQA integration by the openqa_review script:

This bug is still referenced in a failing openQA test: mru-install-multipath-remote
https://openqa.suse.de/tests/4338220

To prevent further reminder comments one of the following options should be followed:

1. The test scenario is fixed by applying the bug fix to the tested product or the test is adjusted
2. The openQA job group is moved to "Released"
3. The label in the openQA scenario is removed

This is an autogenerated message for openQA integration by the openqa_review script:

This bug is still referenced in a failing openQA test: mru-install-multipath-remote
https://openqa.suse.de/tests/4388463

To prevent further reminder comments one of the following options should be followed:

1. The test scenario is fixed by applying the bug fix to the tested product or the test is adjusted
2. The openQA job group is moved to "Released"
3. The label in the openQA scenario is removed

It became urgent because it's every day issue since it has been created and you literally asked for it with your professionalism.
I don't think it's related to one worker, I have seen it on "all" workers.

https://openqa.suse.de/tests/4499071
https://openqa.suse.de/tests/4499158

At least I think we can crosscheck for worker instances that are outside the correctly configured range, e.g. on each worker:

numworkers=$(sed -n "s/# numofworkers: //p" /etc/openqa/workers.ini)
for i in $(sudo systemctl --no-legend list-units -t service --state=active openqa-worker@\* | sed -n "s/^.*@\([0-9]\+\).*$/\1/p"); do test $i -gt $numworkers && echo "openqa-worker@$i active but higher than numworkers: $numworkers"; done

Executing that within a salt cmd.run is tricky and will not be parsed correctly so I put that into https://w3.suse.de/~okurz/check_num_openqa_workers and call with sudo salt -l error --state-output=changes -C 'G@roles:worker' cmd.run 'curl -s https://w3.suse.de/~okurz/check_num_openqa_workers | sh -' which confirms that there are no more superfluous worker instances after stopping the ones on openqaworker3.

For the mentioned jobs from #65118#note-12 both jobs are "parallel_failed" so we have to look for the error on the parallel jobs. For the first the parallel one is https://openqa.suse.de/tests/4499072 which ran on openqaworker3:14 , i.e. the misconfigured one which shouldn't happen anymore until something/someone restarts wrong worker instances. Also the autoinst-log.txt in https://openqa.suse.de/tests/4499072/file/autoinst-log.txt shows the expected error message "Failed to run dbus command 'set_vlan' with arguments 'tap13 17' : 'tap13' is not connected to bridge 'br1'".

The other job stopped in https://openqa.suse.de/tests/4499165#step/smt_client1/10 with "# Test died: mydie at /usr/lib/os-autoinst/lockapi.pm line 41." and no dbus error. Details from autoinst-log.txt:

[2020-07-29T06:07:29.616 CEST] [debug] <<< testapi::record_info(title="Paused", output="Wait for smt_setup (on parent job)", result="ok")
[2020-07-29T06:07:29.691 CEST] [info] ::: lockapi::_try_lock: Retry 1 of 7...
[2020-07-29T06:07:39.758 CEST] [info] ::: lockapi::_try_lock: Retry 2 of 7...
[2020-07-29T06:07:49.828 CEST] [info] ::: lockapi::_try_lock: Retry 3 of 7...
[2020-07-29T06:07:59.916 CEST] [info] ::: lockapi::_try_lock: Retry 4 of 7...
[2020-07-29T06:08:10.001 CEST] [info] ::: lockapi::_try_lock: Retry 5 of 7...
[2020-07-29T06:08:20.118 CEST] [info] ::: lockapi::_try_lock: Retry 6 of 7...
[2020-07-29T06:08:30.207 CEST] [info] ::: lockapi::_try_lock: Retry 7 of 7...
[2020-07-29T06:08:40.208 CEST] [debug] tests/smt/smt_client1.pm:32 called lockapi::barrier_wait
[2020-07-29T06:08:40.208 CEST] [debug] <<< bmwqemu::mydie(cause_of_death="barrier 'smt_setup': lock owner already finished")
[2020-07-29T06:08:40.297 CEST] [info] ::: basetest::runtest: # Test died: mydie at /usr/lib/os-autoinst/lockapi.pm line 41.

That I don't understand yet but for sure it is not the same problem as for the other job.

With the SQL query select jobs.id,t_finished,state,result,test,reason,host from jobs, comments, workers where t_finished >= '2020-07-20' and jobs.id = comments.job_id and comments.text ~ '65118' and workers.id = assigned_worker_id; I look for all jobs with the ticket id in comment. To exclude openqaworker3 which was ill-configured I am using the SQL query:

select jobs.id,t_finished,state,result,test,reason,host from jobs, comments, workers where t_finished >= '2020-07-20' and jobs.id = comments.job_id and comments.text ~ '65118' and workers.id = assigned_worker_id and host != 'openqaworker3';

which shows me 40 jobs right now. The latest job failed in https://openqa.suse.de/tests/4508248#step/boot_to_desktop/5 in the scenario "sle-12-SP4-Server-DVD-Updates-x86_64-mru-install-multipath-remote@64bit" with details

[2020-07-30T21:28:41.047 CEST] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
[2020-07-30T21:28:41.315 CEST] [debug] tests/boot/boot_to_desktop.pm:42 called opensusebasetest::wait_boot -> lib/opensusebasetest.pm:1022 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:920 called opensusebasetest::handle_displaymanager_login -> lib/opensusebasetest.pm:753 called testapi::assert_screen
[2020-07-30T21:28:41.316 CEST] [debug] <<< testapi::assert_screen(mustmatch=[
  "displaymanager",
  "emergency-shell",
  "emergency-mode"
], timeout=300)
…
[2020-07-30T21:33:49.497 CEST] [debug] >>> testapi::_check_backend_response: match=displaymanager,emergency-mode,emergency-shell timed out after 300 (assert_screen)
[2020-07-30T21:33:49.539 CEST] [info] ::: basetest::runtest: # Test died: no candidate needle with tag(s) 'displaymanager, emergency-shell, emergency-mode' matched

while it looks like the system is still stuck in the PXE boot menu not acting on the "ret" that was pressed. I do not see the relation to the problem described in before at all.

@dzedro can you explain why you think that for example https://openqa.suse.de/tests/4508248# also fails due to problems of the network between the SUT VMs?

Because it's MM and the failure (websocket refusing connection) is always on parent, often supportserver or just the test to which other test is PARALLEL_WITH.

I can confirm what @okurz said:

The message "isotovideo: unable to inform websocket clients…" is definitely not the cause of any problems besides avoidable error messages within the developer mode. This message would never cause a job to fail (be it a MM test or not).

However, a MM test which failed because a parallel job failed is indeed likely to contain the "isotovideo: unable to inform websocket clients…" message. That is because such a MM test is stopped by the worker which messes with the usual termination of isotovideo (to ensure there are no leftover processes). Hence isotovideo's web socket server might have already been terminated at this point. So if you want to know why your MM test failed this message is not a clue.

Not sure how to improve the error message to be less confusing. A simple solution would be to always also log additionally: "This only affects the developer mode and is unrelated to the test execution."
I've already tried that but only covered one place where the error is possibly logged and I suppose my phrasing wasn't too helpful as well.

Another solution would be to suppress the error message completely but I don't like that because it can make debugging extra-hard.

Nobody said anything about "isotovideo: unable to inform websocket clients…" being root cause.
The message is symptom which is there always in this MM failure...

dzedro wrote:

Nobody said anything about "isotovideo: unable to inform websocket clients…" being root cause.
The message is symptom which is there always in this MM failure...

but this is what the subject line of your ticket says: "multimachine test fails due to websocket refusing connection" …

@mkittler You created https://github.com/os-autoinst/os-autoinst/pull/1500 . We should also keep in mind our history for related work, just to not run into regressions or back-and-forth: #45191 and #57707

What I found as reproducer for a "Connection refused" message started from os-autoinst/t/data/:

timeout -s INT -v 4 ../../isotovideo -d casedir=/home/okurz/local/os-autoinst/os-autoinst/t/data/tests

yielding

[2020-08-05T20:20:28.158 CEST] [debug] <<< testapi::assert_screen(mustmatch="core", timeout=15, no_wait=1)
[2020-08-05T20:20:28.175 CEST] [debug] no match: 14.9s, best candidate: boot-core (0.00)
[2020-08-05T20:20:28.276 CEST] [debug] no change: 14.8s
…
[2020-08-05T20:20:28.819 CEST] [debug] no change: 14.3s
timeout: sending signal INT to command ‘../../isotovideo’
[2020-08-05T20:20:28.839 CEST] [debug] isotovideo received signal INT
[2020-08-05T20:20:28.840 CEST] [debug] isotovideo received signal INT
[2020-08-05T20:20:28.840 CEST] [debug] QEMU: qemu-system-x86_64: terminating on signal 2 from pid 27273 (timeout)
[2020-08-05T20:20:28.841 CEST] [debug] no change: 14.3s
[2020-08-05T20:20:28.842 CEST] [debug] terminating command server 27278 because test execution ended
[2020-08-05T20:20:28.842 CEST] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:15223/PYkrRjvtBG/broadcast
[2020-08-05T20:20:28.848 CEST] [debug] commands process exited: 0
[2020-08-05T20:20:28.851 CEST] [debug] isotovideo: unable to inform websocket clients about stopping command server: Connection refused at ../../isotovideo line 175.

[2020-08-05T20:20:28.851 CEST] [debug] [autotest] process exited: 0
[2020-08-05T20:20:28.852 CEST] [debug] done with command server
[2020-08-05T20:20:28.852 CEST] [debug] stopping autotest process 27281
[2020-08-05T20:20:28.852 CEST] [debug] done with autotest process
[2020-08-05T20:20:28.852 CEST] [debug] isotovideo failed
[2020-08-05T20:20:28.853 CEST] [debug] stopping backend process 27298
[2020-08-05T20:20:28.854 CEST] [debug] backend got TERM
[2020-08-05T20:20:28.854 CEST] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2020-08-05T20:20:30.866 CEST] [debug] flushing frames
[2020-08-05T20:20:30.870 CEST] [debug] sending magic and exit
[2020-08-05T20:20:31.059 CEST] [debug] done with backend process
27274: EXIT 1

Created https://github.com/os-autoinst/os-autoinst/pull/1501 with my ideas.

okurz wrote:

dzedro wrote:

Nobody said anything about "isotovideo: unable to inform websocket clients…" being root cause.
The message is symptom which is there always in this MM failure...

but this is what the subject line of your ticket says: "multimachine test fails due to websocket refusing connection" …

@mkittler You created https://github.com/os-autoinst/os-autoinst/pull/1500 . We should also keep in mind our history for related work, just to not run into regressions or back-and-forth: #45191 and #57707

Yes, because all this MM failures have it in log, if there is root cause which is causing this or another description which is describing the issue more accurate then great.

change has been deployed to osd already.

I added workaround on QAM MM jobs, made MM jobs run on same worker with WORKER_CLASS=openqaworker. Tried to split it between all MM workers to not load only on and possibly delay the runs. Now there are no or much less failures.

I removed the workaround from few MM tests.

Removed workaround on all tests, could see failures related to this issue.

With the SQL query select jobs.id,t_finished,state,result,test,reason,host from jobs, comments, workers where t_finished >= '2020-09-14' and jobs.id = comments.job_id and comments.text ~ '65118' and workers.id = assigned_worker_id; I found no jobs labeled with this ticket since 2020-09-14, have you found any?

See for the reason of tracker change: http://mailman.suse.de/mailman/private/qa-sle/2020-October/002722.html