action #60035

[unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)

Added by okurz 3 months ago. Updated about 1 month ago.

Status:ResolvedStart date:19/11/2019
Priority:NormalDue date:
Assignee:andriinikitin% Done:

100%

Category:Concrete Bugs
Target version:Current Sprint
Difficulty:
Duration:

Description

Observation

https://github.com/os-autoinst/openQA/pull/2506 reported a failed check from OBS package test: https://build.opensuse.org/package/show/devel:openQA:TestGithub:PR-2506/openQA pointing to https://build.opensuse.org/package/live_build_log/devel:openQA:TestGithub:PR-2506/openQA/openSUSE_Tumbleweed/x86_64 showing

[ 1372s]     #   Failed test 'Queue limit is reached 4=(2 running + 2 scheduled)'
[ 1372s]     #   at ./t/api/14-plugin_obs_rsync_async.t line 123.
[ 1372s]     #          got: '201'
[ 1372s]     #     expected: '507'
[ 1379s]     # Looks like you failed 1 test of 22.
[ 1379s] #   Failed test 'test concurrenctly long running jobs'
[ 1379s] #   at ./t/api/14-plugin_obs_rsync_async.t line 136.
[ 1379s] #   Failed test 'Number of finished jobs 6'
[ 1379s] #   at ./t/api/14-plugin_obs_rsync_async.t line 142.
[ 1388s] #   Failed test 'Number of finished jobs 11'
[ 1388s] #   at ./t/api/14-plugin_obs_rsync_async.t line 152.
[ 1388s] #   Failed test 'Number of finished jobs 11'
[ 1388s] #   at ./t/api/14-plugin_obs_rsync_async.t line 160.
[ 1394s] # Looks like you failed 4 tests of 9.
[ 1394s] ./t/api/14-plugin_obs_rsync_async.t ....... 

Steps to reproduce

This seems to have happened only in OBS tests so far, not within circle CI

History

#1 Updated by andriinikitin 3 months ago

  • Status changed from New to Resolved
  • Assignee set to andriinikitin
  • Target version set to Current Sprint
  • % Done changed from 0 to 100

#2 Updated by okurz 3 months ago

  • Status changed from Resolved to Feedback

please keep the ticket open until all work on it is done, see https://progress.opensuse.org/projects/openqav3/wiki/Wiki#ticket-workflow for the workflow. I know, in bugzilla RESOLVED is used differently ;)

#3 Updated by okurz 3 months ago

Unfortunately it seems this did not help with the test results in OBS. https://build.opensuse.org/package/live_build_log/devel:openQA/openQA/openSUSE_Tumbleweed/x86_64 shows

[  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

#4 Updated by andriinikitin 3 months ago

  • Status changed from Feedback to In Progress

#6 Updated by okurz 3 months ago

  • Subject changed from [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests to [unstable] flaky/sporadic failure of plugin_obs_rsync_async in OBS tests (and circle CI)

It seems we can now reproduce some problems within circleci as well, e.g. see https://app.circleci.com/jobs/github/os-autoinst/openQA/7823 on master

#7 Updated by okurz 3 months ago

The PR mentioned was merged two days ago, tests failed after that.

details from circleci:

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'

#8 Updated by andriinikitin 3 months ago

okurz wrote:

The PR mentioned was merged two days ago, tests failed after that.

The new failure is not related to timing issues, which were observed on OBS and the root cause must be in # Premature connection close.
I have no clue so far what can cause such transport errors so PUT request returned no status code at all.

I will try to reproduce this new problem, but I am very skeptical because the test was run under stress many times.
So, if somebody sees such failure again please provide new details here as well.

#9 Updated by okurz 3 months ago

This seems to fail more often on circle CI now, e.g. take a look into https://circleci.com/workflow-run/d4a9f572-22c4-4983-8fe1-8660c3b659a7 . Maybe the ssh environment on circle CI helps to reproduce more easily?

#10 Updated by andriinikitin 3 months ago

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:

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

So working on it

#12 Updated by andriinikitin about 1 month ago

  • Status changed from In Progress to Resolved

andriinikitin wrote:

Suspect https://github.com/mojolicious/minion/issues/90

Resolving with assumption that fix of issue above inside mojolicious/minion 10.01 fixes last test failures as well.

Also available in: Atom PDF