https://progress.opensuse.org/https://progress.opensuse.org/themes/openSUSE/favicon/favicon.ico?15829177842019-11-19T17:33:40ZopenSUSE Project Management ToolopenQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2585932019-11-19T17:33:40Zandriinikitinandrii.nikitin@suse.com
<ul><li><strong>Status</strong> changed from <i>New</i> to <i>Resolved</i></li><li><strong>Assignee</strong> set to <i>andriinikitin</i></li><li><strong>Target version</strong> set to <i>Current Sprint</i></li><li><strong>% Done</strong> changed from <i>0</i> to <i>100</i></li></ul><p><a href="https://github.com/os-autoinst/openQA/pull/2523" class="external">https://github.com/os-autoinst/openQA/pull/2523</a></p>
openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2586082019-11-19T18:26:26Zokurzokurz@suse.com
<ul><li><strong>Status</strong> changed from <i>Resolved</i> to <i>Feedback</i></li></ul><p>please keep the ticket open until all work on it is done, see <a href="https://progress.opensuse.org/projects/openqav3/wiki/Wiki#ticket-workflow" class="external">https://progress.opensuse.org/projects/openqav3/wiki/Wiki#ticket-workflow</a> for the workflow. I know, in bugzilla RESOLVED is used differently ;)</p>
openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2591002019-11-21T21:41:02Zokurzokurz@suse.com
<ul></ul><p>Unfortunately it seems this did not help with the test results in OBS. <a href="https://build.opensuse.org/package/live_build_log/devel:openQA/openQA/openSUSE_Tumbleweed/x86_64">https://build.opensuse.org/package/live_build_log/devel:openQA/openQA/openSUSE_Tumbleweed/x86_64</a> shows</p>
<pre><code>[ 995s] # Failed test 'Queue limit is reached 4=(2 running + 2 scheduled)'
[ 995s] # at ./t/api/14-plugin_obs_rsync_async.t line 123.
[ 995s] # got: '201'
[ 995s] # expected: '507'
[ 1004s] # Looks like you failed 1 test of 22.
[ 1004s] # Failed test 'test concurrenctly long running jobs again'
[ 1004s] # at ./t/api/14-plugin_obs_rsync_async.t line 146.
[ 1004s] # Failed test 'Number of finished jobs 11'
[ 1004s] # at ./t/api/14-plugin_obs_rsync_async.t line 152.
[ 1005s] # Failed test 'Number of finished jobs 11'
[ 1005s] # at ./t/api/14-plugin_obs_rsync_async.t line 160.
[ 1010s] # Looks like you failed 3 tests of 9.
[ 1011s] ./t/api/14-plugin_obs_rsync_async.t .......
[ 1011s] [INFO] using database schema "tmp_wDueAeaEeFgj9YtV"
[ 1011s] [info] [pid:5453] setting database search path to tmp_wDueAeaEeFgj9YtV when registering Minion plugin
[ 1011s] [info] Loading external plugin ObsRsync
[ 1011s] # starting gru
[ 1011s] # Subtest: test concurrenctly long running jobs
[ 1011s] [info] [pid:5469] setting database search path to tmp_wDueAeaEeFgj9YtV when registering Minion plugin
[ 1011s] [debug] [a1506d2f] PUT "/api/v1/obs_rsync/MockProjectLongProcessing/runs"
[ 1011s] [debug] [a1506d2f] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [info] Loading external plugin ObsRsync
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [a1506d2f] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [a1506d2f] 201 Created (0.318906s, 3.136/s)
[ 1011s] ok 1 - PUT /api/v1/obs_rsync/MockProjectLongProcessing/runs
[ 1011s] ok 2 - first request to MockProjectLongProcessing should start
[ 1011s] [info] Worker 5469 started
[ 1011s] [debug] Process 5474 is performing job "1" with task "obs_rsync_run"
[ 1011s] [debug] [d3340a35] PUT "/api/v1/obs_rsync/MockProjectLongProcessing/runs"
[ 1011s] [debug] [d3340a35] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [d3340a35] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [d3340a35] 200 OK (0.072102s, 13.869/s)
[ 1011s] ok 3 - PUT /api/v1/obs_rsync/MockProjectLongProcessing/runs
[ 1011s] ok 4 - second request to MockProjectLongProcessing should be queued
[ 1011s] [debug] Process 5478 is performing job "2" with task "obs_rsync_run"
[ 1011s] [debug] [874a5b11] PUT "/api/v1/obs_rsync/MockProjectLongProcessing/runs"
[ 1011s] [debug] [874a5b11] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [874a5b11] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [874a5b11] 208 Already Reported (0.018692s, 53.499/s)
[ 1011s] ok 5 - PUT /api/v1/obs_rsync/MockProjectLongProcessing/runs
[ 1011s] ok 6 - third request to MockProjectLongProcessing should report already in queue
[ 1011s] [debug] [b821f841] PUT "/api/v1/obs_rsync/MockProjectLongProcessing1/runs"
[ 1011s] [debug] [b821f841] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [b821f841] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [b821f841] 201 Created (0.044756s, 22.343/s)
[ 1011s] ok 7 - PUT /api/v1/obs_rsync/MockProjectLongProcessing1/runs
[ 1011s] ok 8 - first request to MockProjectLongProcessing1 should start
[ 1011s] [debug] Process 5480 is performing job "3" with task "obs_rsync_run"
[ 1011s] [debug] [64e443d6] PUT "/api/v1/obs_rsync/MockProjectLongProcessing/runs"
[ 1011s] [debug] [64e443d6] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [64e443d6] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [64e443d6] 208 Already Reported (0.024153s, 41.403/s)
[ 1011s] ok 9 - PUT /api/v1/obs_rsync/MockProjectLongProcessing/runs
[ 1011s] ok 10 - request for MockProjectLongProcessing still reports in queue
[ 1011s] [debug] [f8747bba] PUT "/api/v1/obs_rsync/MockProjectLongProcessing1/runs"
[ 1011s] [debug] [f8747bba] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [f8747bba] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [f8747bba] 200 OK (0.053503s, 18.691/s)
[ 1011s] ok 11 - PUT /api/v1/obs_rsync/MockProjectLongProcessing1/runs
[ 1011s] ok 12 - second request to MockProjectLongProcessing1 is queued
[ 1011s] [debug] [e45752b0] PUT "/api/v1/obs_rsync/MockProjectLongProcessing1/runs"
[ 1011s] [debug] [e45752b0] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Process 5484 is performing job "4" with task "obs_rsync_run"
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [e45752b0] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [e45752b0] 208 Already Reported (0.032391s, 30.873/s)
[ 1011s] ok 13 - PUT /api/v1/obs_rsync/MockProjectLongProcessing1/runs
[ 1011s] ok 14 - now MockProjectLongProcessing1 should report already in queue
[ 1011s] [debug] [f3542cb8] PUT "/api/v1/obs_rsync/Proj1/runs"
[ 1011s] [debug] [f3542cb8] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [f3542cb8] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [f3542cb8] 507 Insufficient Storage (0.034048s, 29.370/s)
[ 1011s] ok 15 - PUT /api/v1/obs_rsync/Proj1/runs
[ 1011s] ok 16 - Queue limit is reached 4=(2 running + 2 scheduled)
[ 1011s] [debug] [e2a4fc65] PUT "/api/v1/obs_rsync/MockProjectLongProcessing1/runs"
[ 1011s] [debug] [e2a4fc65] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [e2a4fc65] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [e2a4fc65] 208 Already Reported (0.021511s, 46.488/s)
[ 1011s] ok 17 - PUT /api/v1/obs_rsync/MockProjectLongProcessing1/runs
[ 1011s] ok 18 - MockProjectLongProcessing1 still in queue
[ 1011s] [debug] [93b19dcf] PUT "/api/v1/obs_rsync/WRONGPROJECT/runs"
[ 1011s] [debug] [93b19dcf] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [93b19dcf] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [93b19dcf] 404 Not Found (0.030758s, 32.512/s)
[ 1011s] ok 19 - PUT /api/v1/obs_rsync/WRONGPROJECT/runs
[ 1011s] ok 20 - trigger rsync wrong project still returns error
[ 1011s] [debug] Process 5492 is performing job "2" with task "obs_rsync_run"
[ 1011s] [debug] Process 5494 is performing job "4" with task "obs_rsync_run"
[ 1011s] [debug] [1ed583c8] PUT "/api/v1/obs_rsync/Proj1/runs"
[ 1011s] [debug] [1ed583c8] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [1ed583c8] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [1ed583c8] 201 Created (0.038928s, 25.688/s)
[ 1011s] ok 21 - PUT /api/v1/obs_rsync/Proj1/runs
[ 1011s] ok 22 - Proj1 just starts as gru should empty queue for now
[ 1011s] 1..22
[ 1011s] ok 1 - test concurrenctly long running jobs
[ 1011s] [debug] Process 5506 is performing job "5" with task "obs_rsync_run"
[ 1011s] ok 2 - Number of finished jobs 5
[ 1011s] # Subtest: test concurrenctly long running jobs again
[ 1011s] [debug] [442c4d0d] PUT "/api/v1/obs_rsync/MockProjectLongProcessing/runs"
[ 1011s] [debug] [442c4d0d] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [442c4d0d] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [442c4d0d] 201 Created (0.014914s, 67.051/s)
[ 1011s] ok 1 - PUT /api/v1/obs_rsync/MockProjectLongProcessing/runs
[ 1011s] ok 2 - first request to MockProjectLongProcessing should start
[ 1011s] [debug] Process 5510 is performing job "6" with task "obs_rsync_run"
[ 1011s] [debug] [1c607c49] PUT "/api/v1/obs_rsync/MockProjectLongProcessing/runs"
[ 1011s] [debug] [1c607c49] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [1c607c49] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [1c607c49] 200 OK (0.054963s, 18.194/s)
[ 1011s] ok 3 - PUT /api/v1/obs_rsync/MockProjectLongProcessing/runs
[ 1011s] ok 4 - second request to MockProjectLongProcessing should be queued
[ 1011s] [debug] [4631cdbb] PUT "/api/v1/obs_rsync/MockProjectLongProcessing/runs"
[ 1011s] [debug] [4631cdbb] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [4631cdbb] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [4631cdbb] 208 Already Reported (0.009278s, 107.782/s)
[ 1011s] ok 5 - PUT /api/v1/obs_rsync/MockProjectLongProcessing/runs
[ 1011s] ok 6 - third request to MockProjectLongProcessing should report already in queue
[ 1011s] [debug] [9909c54a] PUT "/api/v1/obs_rsync/MockProjectLongProcessing1/runs"
[ 1011s] [debug] [9909c54a] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Process 5514 is performing job "7" with task "obs_rsync_run"
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [9909c54a] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [9909c54a] 201 Created (0.049916s, 20.034/s)
[ 1011s] ok 7 - PUT /api/v1/obs_rsync/MockProjectLongProcessing1/runs
[ 1011s] ok 8 - first request to MockProjectLongProcessing1 should start
[ 1011s] [debug] [f1ac37e4] PUT "/api/v1/obs_rsync/MockProjectLongProcessing/runs"
[ 1011s] [debug] [f1ac37e4] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [f1ac37e4] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [f1ac37e4] 208 Already Reported (0.025821s, 38.728/s)
[ 1011s] ok 9 - PUT /api/v1/obs_rsync/MockProjectLongProcessing/runs
[ 1011s] ok 10 - request for MockProjectLongProcessing still reports in queue
[ 1011s] [debug] Process 5521 is performing job "7" with task "obs_rsync_run"
[ 1011s] [debug] Process 5523 is performing job "8" with task "obs_rsync_run"
[ 1011s] [debug] [5b053b64] PUT "/api/v1/obs_rsync/MockProjectLongProcessing1/runs"
[ 1011s] [debug] [5b053b64] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [5b053b64] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [5b053b64] 200 OK (0.030308s, 32.995/s)
[ 1011s] ok 11 - PUT /api/v1/obs_rsync/MockProjectLongProcessing1/runs
[ 1011s] ok 12 - second request to MockProjectLongProcessing1 is queued
[ 1011s] [debug] Process 5529 is performing job "9" with task "obs_rsync_run"
[ 1011s] [debug] [1da91808] PUT "/api/v1/obs_rsync/MockProjectLongProcessing1/runs"
[ 1011s] [debug] [1da91808] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [1da91808] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [1da91808] 208 Already Reported (0.025477s, 39.251/s)
[ 1011s] ok 13 - PUT /api/v1/obs_rsync/MockProjectLongProcessing1/runs
[ 1011s] ok 14 - now MockProjectLongProcessing1 should report already in queue
[ 1011s] [debug] [f1a5c4a4] PUT "/api/v1/obs_rsync/Proj1/runs"
[ 1011s] [debug] [f1a5c4a4] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [f1a5c4a4] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [f1a5c4a4] 201 Created (0.014915s, 67.047/s)
[ 1011s] ok 15 - PUT /api/v1/obs_rsync/Proj1/runs
[ 1011s] not ok 16 - Queue limit is reached 4=(2 running + 2 scheduled)
[ 1011s] [debug] Process 5531 is performing job "10" with task "obs_rsync_run"
[ 1011s] [debug] [189b1725] PUT "/api/v1/obs_rsync/MockProjectLongProcessing1/runs"
[ 1011s] [debug] [189b1725] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [189b1725] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [189b1725] 208 Already Reported (0.014866s, 67.268/s)
[ 1011s] ok 17 - PUT /api/v1/obs_rsync/MockProjectLongProcessing1/runs
[ 1011s] ok 18 - MockProjectLongProcessing1 still in queue
[ 1011s] [debug] [b7b4aa6a] PUT "/api/v1/obs_rsync/WRONGPROJECT/runs"
[ 1011s] [debug] [b7b4aa6a] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [b7b4aa6a] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [b7b4aa6a] 404 Not Found (0.008695s, 115.009/s)
[ 1011s] ok 19 - PUT /api/v1/obs_rsync/WRONGPROJECT/runs
[ 1011s] ok 20 - trigger rsync wrong project still returns error
[ 1011s] [debug] Process 5539 is performing job "9" with task "obs_rsync_run"
[ 1011s] [debug] Process 5541 is performing job "10" with task "obs_rsync_run"
[ 1011s] [debug] [11d8657c] PUT "/api/v1/obs_rsync/Proj1/runs"
[ 1011s] [debug] [11d8657c] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [11d8657c] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [11d8657c] 201 Created (0.027174s, 36.800/s)
[ 1011s] ok 21 - PUT /api/v1/obs_rsync/Proj1/runs
[ 1011s] ok 22 - Proj1 just starts as gru should empty queue for now
[ 1011s] 1..22
[ 1011s] not ok 3 - test concurrenctly long running jobs again
[ 1011s] [debug] Process 5553 is performing job "11" with task "obs_rsync_run"
[ 1011s] not ok 4 - Number of finished jobs 11
[ 1011s] [debug] [fedafe2d] PUT "/api/v1/obs_rsync/MockProjectError/runs"
[ 1011s] [debug] [fedafe2d] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 1011s] [debug] API key from client: *ARTHURKEY01*
[ 1011s] [debug] Key is for user 'arthur'
[ 1011s] [debug] API auth by user: arthur, operator: 1
[ 1011s] [debug] [fedafe2d] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 1011s] [debug] [fedafe2d] 201 Created (0.018848s, 53.056/s)
[ 1011s] ok 5 - PUT /api/v1/obs_rsync/MockProjectError/runs
[ 1011s] ok 6 - Start another mock project
[ 1011s] [debug] Process 5557 is performing job "12" with task "obs_rsync_run"
[ 1011s] [error] [pid:5557] Gru command issue: {
[ 1011s] 'code' => 256,
[ 1011s] 'message' => 'Mock Error'
[ 1011s] }
[ 1011s] not ok 7 - Number of finished jobs 11
[ 1011s] ok 8 - Number of failed jobs 1
[ 1011s] ok 9 - Correct error message
[ 1011s] [info] Worker 5469 stopped
[ 1011s] 1..9
[ 1011s] Dubious, test returned 3 (wstat 768, 0x300)
[ 1011s] Failed 3/9 subtests
[ 1011s] [2019-11-21 20:39:30.07125] [5565] [warn] No configuration file supplied, will fallback to default configuration
[ 1011s] [2019-11-21 20:39:30.07838] [5565] [warn] No configuration file supplied, will fallback to default configuration
[ 1011s] [2019-11-21 20:39:30.08469] [5565] [warn] No configuration file supplied, will fallback to default configuration
[ 1011s] [2019-11-21 20:39:30.09104] [5565] [warn] No configuration file supplied, will fallback to default configuration
[ 1011s] ./t/config.t ..............................
[ 1011s] # Subtest: Test configuration default modes
[ 1011s] ok 1 - config has openid_secret
[ 1011s] ok 2 - "test" configuration
[ 1011s] ok 3 - right "development" configuration
[ 1011s] ok 4 - right default configuration
[ 1011s] ok 5 - right default configuration
[ 1011s] 1..5
[ 1011s] ok 1 - Test configuration default modes
[ 1011s] # Subtest: Test configuration override from file
[ 1011s] ok 1
[ 1011s] ok 2 - suse mirror
[ 1011s] ok 3 - audit blacklist
[ 1011s] ok 4 - referers parsed correctly
[ 1011s] 1..4
[ 1011s] ok 2 - Test configuration override from file
[ 1011s] # Subtest: trim whitespace characters from both ends of openqa.ini value
[ 1011s] openQArepo iso ok 1 - appname
[ 1011s] ok 2 - hide_asset_types
[ 1011s] ok 3 - recognized_referers
[ 1011s] 1..3
[ 1011s] ok 3 - trim whitespace characters from both ends of openqa.ini value
[ 1011s] ok 4 - no (unexpected) warnings (via done_testing)
[ 1011s] 1..4
[ 1011s] ok
[ 1011s]
[ 1011s] Test Summary Report
[ 1011s] -------------------
[ 1011s] ./t/api/14-plugin_obs_rsync_async.t (Wstat: 768 Tests: 9 Failed: 3)
[ 1011s] Failed tests: 3-4, 7
[ 1011s] Non-zero exit status: 3
</code></pre> openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2592232019-11-22T10:05:47Zandriinikitinandrii.nikitin@suse.com
<ul><li><strong>Status</strong> changed from <i>Feedback</i> to <i>In Progress</i></li></ul><p>I've branched repo and stress running the test, so far no failure <br>
<a href="https://build.opensuse.org/package/live_build_log/home:andriinikitin:branches:devel:openQA/openQA/openSUSE_Tumbleweed/x86_64" class="external">https://build.opensuse.org/package/live_build_log/home:andriinikitin:branches:devel:openQA/openQA/openSUSE_Tumbleweed/x86_64</a></p>
openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2593822019-11-24T00:42:38Zandriinikitinandrii.nikitin@suse.com
<ul></ul><p><a href="https://github.com/os-autoinst/openQA/pull/2544" class="external">https://github.com/os-autoinst/openQA/pull/2544</a></p>
openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2606542019-11-28T18:37:25Zokurzokurz@suse.com
<ul><li><strong>Subject</strong> changed from <i>[unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests</i> to <i>[unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)</i></li></ul><p>It seems we can now reproduce some problems within circleci as well, e.g. see <a href="https://app.circleci.com/jobs/github/os-autoinst/openQA/7823" class="external">https://app.circleci.com/jobs/github/os-autoinst/openQA/7823</a> on master</p>
openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2606572019-11-28T18:39:27Zokurzokurz@suse.com
<ul></ul><p>The PR mentioned was merged two days ago, tests failed after that.</p>
<p>details from circleci:</p>
<pre><code>t/api/14-plugin_obs_rsync_async.t .. 2/? # Premature connection close
# Failed test 'PUT /api/v1/obs_rsync/MockProjectLongProcessing1/runs'
# at t/api/14-plugin_obs_rsync_async.t line 142.
# Failed test 'second request to MockProjectLongProcessing1 is queued'
# at t/api/14-plugin_obs_rsync_async.t line 142.
# got: undef
# expected: '200'
# Failed test 'now MockProjectLongProcessing1 should report already in queue'
# at t/api/14-plugin_obs_rsync_async.t line 144.
# got: '200'
# expected: '208'
</code></pre> openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2608102019-11-29T14:14:16Zandriinikitinandrii.nikitin@suse.com
<ul></ul><p>okurz wrote:</p>
<blockquote>
<p>The PR mentioned was merged two days ago, tests failed after that.</p>
</blockquote>
<p>The new failure is not related to timing issues, which were observed on OBS and the root cause must be in <code># Premature connection close</code>.<br>
I have no clue so far what can cause such transport errors so PUT request returned no status code at all.</p>
<p>I will try to reproduce this new problem, but I am very skeptical because the test was run under stress many times.<br>
So, if somebody sees such failure again please provide new details here as well.</p>
openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2636302019-12-10T19:41:39Zokurzokurz@suse.com
<ul></ul><p>This seems to fail more often on circle CI now, e.g. take a look into <a href="https://circleci.com/workflow-run/d4a9f572-22c4-4983-8fe1-8660c3b659a7" class="external">https://circleci.com/workflow-run/d4a9f572-22c4-4983-8fe1-8660c3b659a7</a> . Maybe the ssh environment on circle CI helps to reproduce more easily?</p>
openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2638312019-12-11T10:54:40Zandriinikitinandrii.nikitin@suse.com
<ul></ul><p>I've managed to reproduce the problem in CI session and the most suspicious symptom is that the jobs look like retried when problem happens and I cannot think about any reason why it happens:</p>
<pre><code>[debug] Process 20872 is performing job "7" with task "obs_rsync_run"
[debug] Process 20874 is performing job "8" with task "obs_rsync_run"
[debug] Process 20881 is performing job "7" with task "obs_rsync_run"
[debug] Process 20883 is performing job "8" with task "obs_rsync_run"
[debug] Process 20890 is performing job "7" with task "obs_rsync_run"
[debug] Process 20892 is performing job "8" with task "obs_rsync_run"
</code></pre>
<p>So working on it</p>
openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2650192019-12-16T11:31:39Zandriinikitinandrii.nikitin@suse.com
<ul></ul><p>Suspect <a href="https://github.com/mojolicious/minion/issues/90" class="external">https://github.com/mojolicious/minion/issues/90</a></p>
openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2686762020-01-07T08:30:26Zandriinikitinandrii.nikitin@suse.com
<ul><li><strong>Status</strong> changed from <i>In Progress</i> to <i>Resolved</i></li></ul><p>andriinikitin wrote:</p>
<blockquote>
<p>Suspect <a href="https://github.com/mojolicious/minion/issues/90" class="external">https://github.com/mojolicious/minion/issues/90</a></p>
</blockquote>
<p>Resolving with assumption that fix of issue above inside mojolicious/minion 10.01 fixes last test failures as well.</p>
openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2950912020-04-22T12:14:00Zokurzokurz@suse.com
<ul><li><strong>Status</strong> changed from <i>Resolved</i> to <i>Workable</i></li></ul><p>seen again in OBS tests, e.g. <a href="https://build.opensuse.org/package/live_build_log/devel:openQA/openQA/openSUSE_Factory/x86_64">https://build.opensuse.org/package/live_build_log/devel:openQA/openQA/openSUSE_Factory/x86_64</a> showing:</p>
<pre><code>[ 950s] [debug] Process 6294 is performing job "6" with task "obs_rsync_run"
[ 950s] [debug] Process 6296 is performing job "8" with task "obs_rsync_run"
[ 950s] not ok 21 - PUT /api/v1/obs_rsync/Proj1/runs
[ 950s] not ok 22 - Proj1 just starts as gru should empty queue for now
[ 950s] 1..22
[ 950s] not ok 3 - test concurrenctly long running jobs again
[ 950s] not ok 4 - Number of finished jobs
[ 950s] [debug] [LFBuzqkK] PUT "/api/v1/obs_rsync/MockProjectError/runs"
[ 950s] [debug] [LFBuzqkK] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 950s] [debug] API key from client: *ARTHURKEY01*
[ 950s] [debug] Key is for user 'arthur'
[ 950s] [debug] API auth by user: arthur, operator: 1
[ 950s] [debug] [LFBuzqkK] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 950s] [debug] [LFBuzqkK] 201 Created (0.009969s, 100.311/s)
[ 950s] ok 5 - PUT /api/v1/obs_rsync/MockProjectError/runs
[ 950s] ok 6 - Start another mock project
[ 950s] [debug] Process 6306 is performing job "9" with task "obs_rsync_run"
[ 950s] [error] ObsRsync#_run failed (256): Mock Error
[ 950s] [error] Gru job error: {
[ 950s] 'code' => 256,
[ 950s] 'message' => 'Mock Error'
[ 950s] }
[ 950s] not ok 7 - Number of finished jobs
[ 950s] ok 8 - Number of finished jobs
[ 950s] ok 9 - Correct error message
[ 950s] # Subtest: test max retry count
[ 950s] [debug] [t9OnK07J] PUT "/api/v1/obs_rsync/Proj1/runs"
[ 950s] [debug] [t9OnK07J] Routing to controller "OpenQA::WebAPI::Controller::API::V1" and action "auth_operator"
[ 950s] [debug] API key from client: *ARTHURKEY01*
[ 950s] [debug] Key is for user 'arthur'
[ 950s] [debug] API auth by user: arthur, operator: 1
[ 950s] [debug] [t9OnK07J] Routing to controller "OpenQA::WebAPI::Plugin::ObsRsync::Controller::Gru" and action "run"
[ 950s] [debug] [t9OnK07J] 201 Created (0.008882s, 112.587/s)
[ 950s] ok 1 - PUT /api/v1/obs_rsync/Proj1/runs
[ 950s] ok 2 - trigger rsync
[ 950s] [debug] Process 6312 is performing job "10" with task "obs_rsync_run"
[ 950s] [debug] Process 6319 is performing job "10" with task "obs_rsync_run"
[ 950s] [debug] Process 6325 is performing job "10" with task "obs_rsync_run"
[ 950s] not ok 3 - Job should retry succeed
[ 950s] ok 4 - Job retris is correct
[ 950s] ok 5 - Job retry result is hash
[ 950s] ok 6 - Job retry message
[ 950s] 1..6
[ 950s] not ok 10 - test max retry count
[ 950s] [info] Worker 6233 stopped
[ 950s] 1..10
[ 950s] Dubious, test returned 6 (wstat 1536, 0x600)
[ 950s] Failed 6/10 subtests
[ 950s] [2020-04-22 11:59:40.13890] [6336] [warn] No configuration file supplied, will fallback to default configuration
[ 950s] [2020-04-22 11:59:40.14292] [6336] [warn] No configuration file supplied, will fallback to default configuration
[ 951s] [2020-04-22 11:59:40.14611] [6336] [warn] No configuration file supplied, will fallback to default configuration
[ 951s] [2020-04-22 11:59:40.14921] [6336] [warn] No configuration file supplied, will fallback to default configuration
</code></pre> openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2951092020-04-22T13:26:44Zokurzokurz@suse.com
<ul></ul><p>Something similar I observed now in <a href="https://app.circleci.com/pipelines/github/os-autoinst/openQA/2445/workflows/f3d8ef11-04c4-4023-b9c8-db44a0d0411e/jobs/22991">https://app.circleci.com/pipelines/github/os-autoinst/openQA/2445/workflows/f3d8ef11-04c4-4023-b9c8-db44a0d0411e/jobs/22991</a></p>
<pre><code>[13:14:31] t/api/14-plugin_obs_rsync_async.t .. # Premature connection close
# Failed test 'PUT /api/v1/obs_rsync/Proj1/runs'
# at t/api/14-plugin_obs_rsync_async.t line 165.
# Failed test 'Proj1 just starts as gru should empty queue for now'
# at t/api/14-plugin_obs_rsync_async.t line 165.
# got: undef
# expected: '201'
# Looks like you failed 2 tests of 22.
[13:14:31] t/api/14-plugin_obs_rsync_async.t .. 1/?
# Failed test 'test concurrenctly long running jobs'
# at t/api/14-plugin_obs_rsync_async.t line 170.
# Failed test 'Number of finished jobs'
# at t/api/14-plugin_obs_rsync_async.t line 175.
# got: '4'
# expected: '5'
# Premature connection close
# Failed test 'PUT /api/v1/obs_rsync/Proj1/runs'
# at t/api/14-plugin_obs_rsync_async.t line 165.
# Failed test 'Proj1 just starts as gru should empty queue for now'
# at t/api/14-plugin_obs_rsync_async.t line 165.
# got: undef
# expected: '201'
# Looks like you failed 2 tests of 22.
[13:14:31] t/api/14-plugin_obs_rsync_async.t .. 3/?
# Failed test 'test concurrenctly long running jobs again'
# at t/api/14-plugin_obs_rsync_async.t line 179.
# Failed test 'Number of finished jobs'
# at t/api/14-plugin_obs_rsync_async.t line 184.
# got: '8'
# expected: '10'
[13:14:31] t/api/14-plugin_obs_rsync_async.t .. 7/?
# Failed test 'Number of finished jobs'
# at t/api/14-plugin_obs_rsync_async.t line 191.
# got: '8'
# expected: '10'
# Failed test 'Job should retry succeed'
# at t/api/14-plugin_obs_rsync_async.t line 214.
# got: '9'
# expected: '11'
# Looks like you failed 1 test of 6.
[13:14:31] t/api/14-plugin_obs_rsync_async.t .. 10/?
# Failed test 'test max retry count'
# at t/api/14-plugin_obs_rsync_async.t line 224.
# Looks like you failed 6 tests of 10.
</code></pre>
<p>could be related to <a class="issue tracker-4 status-3 priority-3 priority-lowest closed behind-schedule" title="action: Monitoring for "scheduled but not executed" (was: perl-Mojolicious-8.37 broke WS connection for (... (Resolved)" href="https://progress.opensuse.org/issues/65975">#65975</a></p>
openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2953182020-04-23T07:20:36Zandriinikitinandrii.nikitin@suse.com
<ul></ul><p>My understanding:<br>
From <code>Premature connection close</code> it looks that gru met some problem.<br>
It is hard to troubleshoot when gru logs are suppressed in test environment.<br>
At the same time no code around this test was changed for weeks.<br>
And the PR and OBS are having other transport problems related to Mojo version recently.<br>
So I'd say it is safe to ignore this failure until all other is stable.<br>
Otherwise it is blocked by the fact that gru logs are not accessible in test environment (or I do need help how to access them).</p>
openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2953272020-04-23T07:32:44Zandriinikitinandrii.nikitin@suse.com
<ul></ul><p>Yeah, I'd definitely blame these from Mojo change log:</p>
<pre><code>8.39 2020-04-22
- Fixed a bug in Mojo::Server::Daemon where active connections could get the
keep-alive timeout assigned instead of the inactivity timeout.
- Fixed a race condition in Mojo::UserAgent where test servers would close
connections prematurely.
</code></pre> openQA Project - action #60035: [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)https://progress.opensuse.org/issues/60035?journal_id=2968762020-04-29T09:57:10Zokurzokurz@suse.com
<ul><li><strong>Status</strong> changed from <i>Workable</i> to <i>Resolved</i></li></ul><p>We are back to stable with a newer mojo Version</p>