Project

General

Profile

Actions
Copy link

action #60035

closed

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

Added by okurz over 4 years ago. Updated about 4 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
andriinikitin
Category:
Regressions/Crashes
Target version:
Current Sprint
Start date:
2019-11-19
Due date:
% Done:

100%

Estimated time:

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

Actions
Copy link
 #1

Updated by andriinikitin over 4 years ago

  • Status changed from New to Resolved
  • Assignee set to andriinikitin
  • Target version set to Current Sprint
  • % Done changed from 0 to 100
Actions
Copy link
 #2

Updated by okurz over 4 years 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 ;)

Actions
Copy link
 #3

Updated by okurz over 4 years 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
Actions
Copy link
 #4

Updated by andriinikitin over 4 years ago

  • Status changed from Feedback to In Progress
Actions
Copy link
 #6

Updated by okurz over 4 years 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

Actions
Copy link
 #7

Updated by okurz over 4 years 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'
Actions
Copy link
 #8

Updated by andriinikitin over 4 years 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.

Actions
Copy link
 #9

Updated by okurz over 4 years 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?

Actions
Copy link
 #10

Updated by andriinikitin over 4 years 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

Actions
Copy link
 #12

Updated by andriinikitin over 4 years 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.

Actions
Copy link
 #13

Updated by okurz about 4 years ago

  • Status changed from Resolved to Workable

seen again in OBS tests, e.g. https://build.opensuse.org/package/live_build_log/devel:openQA/openQA/openSUSE_Factory/x86_64 showing:

[  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
Actions
Copy link
 #14

Updated by okurz about 4 years ago

Something similar I observed now in https://app.circleci.com/pipelines/github/os-autoinst/openQA/2445/workflows/f3d8ef11-04c4-4023-b9c8-db44a0d0411e/jobs/22991

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

could be related to #65975

Actions
Copy link
 #15

Updated by andriinikitin about 4 years ago

My understanding:
From Premature connection close it looks that gru met some problem.
It is hard to troubleshoot when gru logs are suppressed in test environment.
At the same time no code around this test was changed for weeks.
And the PR and OBS are having other transport problems related to Mojo version recently.
So I'd say it is safe to ignore this failure until all other is stable.
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).

Actions
Copy link
 #16

Updated by andriinikitin about 4 years ago

Yeah, I'd definitely blame these from Mojo change log:

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.
Actions
Copy link
 #17

Updated by okurz about 4 years ago

  • Status changed from Workable to Resolved

We are back to stable with a newer mojo Version

Actions
Copy link

Also available in: Atom PDF