QA » openQA Project

PR was merged

Please see https://github.com/os-autoinst/openQA/pull/2439#discussion_r339448791

New PR: https://github.com/os-autoinst/openQA/pull/2445

FYI, this is not a bug. The log message was printed in every job on purpose to debug misconfigured workers. Specifically the exact kind of misconfiguration which has been blocking https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/8329 for the past month.

Edit: And yes, the test schedule does change when the log line gets printed the first time. From empty to something.

MDoucha wrote:

FYI, this is not a bug. The log message was printed in every job on purpose to debug misconfigured workers. Specifically the exact kind of misconfiguration which has been blocking https://github.com/os-autoinst/os-autoinst-distri-opensuse/pull/8329 for the past month.

Edit: And yes, the test schedule does change when the log line gets printed the first time. From empty to something.

Would you mind clarifying the use case here? How is the message being used for debugging?

The message, the way I read it, suggests the schedule changed, which implies it's not the usual schedule but it was explicitly updated. That's also what was discussed when the code was being worked on. If that were shown in every test regardless it would seem to defeat the point?

May I have a try? I am interested in this feature, although I am not familiar with this.

I did some tests about this issue, here is test report:
For now we check that if the test_order has been changed by checking if the current_test_module exists or the file test_order.json modify time/size is different from before value. There are some reasons that maybe we should not use current_test_module

1. the current test name is null between a test module finish and another test module start. In some case, the process can last more than 1 min. Here is an example: The message in os-autoinst.log

[2020-05-28T10:37:47.903 CST] [debug] ||| finished zypper_up update at 2020-05-28 02:37:47 (42 s)
[2020-05-28T10:37:47.904 CST] [debug] Creating a VM snapshot lastgood
[2020-05-28T10:37:47.905 CST] [debug] Saving snapshot (Current VM state is running).
...
[2020-05-28T10:38:25.585 CST] [debug] Snapshot complete
[2020-05-28T10:38:25.640 CST] [debug] ||| starting system_prepare tests/console/system_prepare.pm

Before ||| finished, the function done is called and it will set the current_test null.
here is the content of autoinst-status.json

[2020-05-28T10:38:24.0133 CST] [error] the test_status is {
  'status' => 'running',
  'test_execution_paused' => 0,
  'current_test' => undef
}

So from 10:37:47.904 to 10:38:25.640, the current_test is null, the log Test schedule has changed will be printed many times.

1. When all test modules have been finished, the current_test will be set null, but there is still other mission, e.g. creating qcow file. During this process, the current_test does not exists, and the log Test schedule has changed... will be printed many times. Here is an example:

[2020-05-27T17:50:26.901 CST] [debug] ||| finished shutdown_ltp kernel at 2020-05-27 09:50:26 (26 s)
[2020-05-27T17:50:26.903 CST] [debug] stopping autotest process 24786
[2020-05-27T17:50:26.909 CST] [debug] [autotest] process exited: 0
[2020-05-27T17:50:26.909 CST] [debug] done with autotest process
[2020-05-27T17:50:26.910 CST] [debug] terminating command server 24783 because test execution ended
[2020-05-27T17:50:26.910 CST] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/4_8v1amG6lqwzlWH/broadcast
[2020-05-27T17:50:26.924 CST] [debug] commands process exited: 0
[2020-05-27T17:50:26.924 CST] [debug] done with command server
[2020-05-27T17:50:26.924 CST] [debug] isotovideo done
[2020-05-27T17:50:26.925 CST] [debug] BACKEND SHUTDOWN 1
[2020-05-27T17:50:26.926 CST] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2020-05-27T17:50:28.964 CST] [debug] flushing frames
[2020-05-27T17:50:28.991 CST] [debug] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 24790 (/usr/bin/isotovideo: backen)
[2020-05-27T17:50:28.993 CST] [debug] sending magic and exit
[2020-05-27T17:50:28.993 CST] [debug] received magic close
[2020-05-27T17:50:29.026 CST] [debug] backend process exited: 0
[2020-05-27T17:50:29.027 CST] [info] ::: backend::qemu::do_extract_assets: Extracting (?^:^hd0$)
[2020-05-27T17:50:29.027 CST] [debug] running nice ionice qemu-img convert -c -O qcow2 /var/lib/openqa/pool/1/raid/hd0-overlay1 assets_public/sle-12-SP5-x86_64-4.12.14-212.1.gd51ffe9-Server-DVD-Incidents-Kernel@64bit-with-ltp.qcow2
[2020-05-27T17:53:47.656 CST] [debug] running qemu-img info --output=json assets_public/sle-12-SP5-x86_64-4.12.14-212.1.gd51ffe9-Server-DVD-Incidents-Kernel@64bit-with-ltp.qcow2
[2020-05-27T17:53:47.676 CST] [debug] stopping backend process 24790
[2020-05-27T17:53:47.676 CST] [debug] done with backend process

And the log in worker-log

[2020-05-27T17:52:21.0689 CST] [error] the test_status is {
  'test_execution_paused' => 0,
  'status' => 'finished',
  'current_test' => ''
}

In above examples, the test schedule has not changed. Because of the current_test_module does not exist, there are many logs. And there is one problem, in these situations, the openQA will update the job modules again and again, because openQA will update job modules when test_order is not empty.

pr: https://github.com/os-autoinst/openQA/pull/3145

Another attempt at fixing this: https://github.com/os-autoinst/openQA/pull/3180

https://github.com/os-autoinst/openQA/pull/3180 was merged

Created a related PR to avoid unnecessary schedule reloads: https://github.com/os-autoinst/openQA/pull/3183