Bug 1479582 - HTTP 429 Too Many Requests Error during Refresh of OpenShift Provider
HTTP 429 Too Many Requests Error during Refresh of OpenShift Provider
Status: CLOSED DUPLICATE of bug 1472532
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Providers (Show other bugs)
5.7.0
Unspecified Unspecified
unspecified Severity high
: GA
: cfme-future
Assigned To: Federico Simoncelli
Einat Pacifici
container
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2017-08-08 17:17 EDT by myoder
Modified: 2017-08-30 09:11 EDT (History)
10 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2017-08-30 09:11:16 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: Bug
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: Container Management


Attachments (Terms of Use)

  None (edit)
Description myoder 2017-08-08 17:17:43 EDT
Description of problem:

During a refresh of OCP provider, getting a 429 'Too Many Requests' error.

[----] I, [2017-08-03T03:15:15.975151 #22132:843140]  INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::Refresher#refresh) Refreshing all targets...
[----] I, [2017-08-03T03:15:15.975276 #22132:843140]  INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::Refresher#refresh) EMS: [CTC Core], id: [10000000000001] Refreshing targets for EMS...
[----] I, [2017-08-03T03:15:15.975368 #22132:843140]  INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::Refresher#refresh) EMS: [CTC Core], id: [10000000000001]   ManageIQ::Providers::OpenshiftEnterprise::Containe
rManager [CTC Core] id [10000000000001]
[----] I, [2017-08-03T03:15:15.975470 #22132:843140]  INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::Refresher#refresh_targets_for_ems) EMS: [CTC Core], id: [10000000000001] Refreshing target ManageIQ::Provider
s::OpenshiftEnterprise::ContainerManager [CTC Core] id [10000000000001]...
[----] I, [2017-08-03T03:15:15.975559 #22132:843140]  INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager#with_provider_connection) Connecting through ManageIQ::Providers::OpenshiftEnterprise::ContainerManager: [CTC 
Core]
[----] E, [2017-08-03T03:15:16.670336 #22132:843140] ERROR -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::Refresher#refresh) EMS: [CTC Core], id: [10000000000001] Refresh failed
[----] E, [2017-08-03T03:15:16.670655 #22132:843140] ERROR -- : [KubeException]: 429 Too Many Requests  Method:[rescue in block in refresh]
[----] E, [2017-08-03T03:15:16.670791 #22132:843140] ERROR -- : /opt/rh/cfme-gemset/gems/kubeclient-2.3.0/lib/kubeclient/common.rb:107:in `rescue in handle_exception'
/opt/rh/cfme-gemset/gems/kubeclient-2.3.0/lib/kubeclient/common.rb:99:in `handle_exception'
/opt/rh/cfme-gemset/gems/kubeclient-2.3.0/lib/kubeclient/common.rb:438:in `fetch_entities'
/opt/rh/cfme-gemset/gems/kubeclient-2.3.0/lib/kubeclient/common.rb:428:in `load_entities'
/opt/rh/cfme-gemset/gems/kubeclient-2.3.0/lib/kubeclient/common.rb:111:in `discover'
/opt/rh/cfme-gemset/gems/kubeclient-2.3.0/lib/kubeclient/common.rb:78:in `method_missing'
/var/www/miq/vmdb/app/models/manageiq/providers/kubernetes/container_manager/refresher_mixin.rb:16:in `block in fetch_entities'
/var/www/miq/vmdb/app/models/manageiq/providers/kubernetes/container_manager/refresher_mixin.rb:14:in `each'
/var/www/miq/vmdb/app/models/manageiq/providers/kubernetes/container_manager/refresher_mixin.rb:14:in `each_with_object'
/var/www/miq/vmdb/app/models/manageiq/providers/kubernetes/container_manager/refresher_mixin.rb:14:in `fetch_entities'
/var/www/miq/vmdb/app/models/manageiq/providers/openshift/container_manager/refresher.rb:17:in `block in parse_legacy_inventory'
/var/www/miq/vmdb/app/models/ext_management_system.rb:362:in `with_provider_connection'
/var/www/miq/vmdb/app/models/manageiq/providers/openshift/container_manager/refresher.rb:16:in `parse_legacy_inventory'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:122:in `block in parse_targeted_inventory'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:122:in `parse_targeted_inventory'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:87:in `block in refresh_targets_for_ems'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:86:in `refresh_targets_for_ems'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:24:in `block (2 levels) in refresh'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:24:in `block in refresh'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:14:in `each'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:14:in `refresh'
/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:10:in `refresh'
/var/www/miq/vmdb/app/models/ems_refresh.rb:91:in `block in refresh'
/var/www/miq/vmdb/app/models/ems_refresh.rb:90:in `each'
/var/www/miq/vmdb/app/models/ems_refresh.rb:90:in `refresh'
/var/www/miq/vmdb/app/models/miq_queue.rb:347:in `block in deliver'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:91:in `block in timeout'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `block in catch'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `catch'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `catch'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:106:in `timeout'
/var/www/miq/vmdb/app/models/miq_queue.rb:343:in `deliver'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:106:in `deliver_queue_message'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:134:in `deliver_message'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:152:in `block in do_work'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `loop'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `do_work'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:334:in `block in do_work_loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `do_work_loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:153:in `run'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:128:in `start'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:21:in `start_worker'
/var/www/miq/vmdb/app/models/miq_worker.rb:343:in `block in start'
/opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork'
/opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork'
/var/www/miq/vmdb/app/models/miq_worker.rb:341:in `start'
/var/www/miq/vmdb/app/models/miq_worker.rb:270:in `start_worker'
/var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:68:in `start_worker_for_ems'
/var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:46:in `block in sync_workers'
/var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:45:in `each'
/var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:45:in `sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:52:in `block in sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `each'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:22:in `monitor_workers'
/var/www/miq/vmdb/app/models/miq_server.rb:346:in `block in monitor'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block'
/var/www/miq/vmdb/app/models/miq_server.rb:346:in `monitor'
/var/www/miq/vmdb/app/models/miq_server.rb:368:in `block (2 levels) in monitor_loop'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block'
/var/www/miq/vmdb/app/models/miq_server.rb:368:in `block in monitor_loop'
/var/www/miq/vmdb/app/models/miq_server.rb:367:in `loop'
/var/www/miq/vmdb/app/models/miq_server.rb:367:in `monitor_loop'
/var/www/miq/vmdb/app/models/miq_server.rb:250:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:65:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:92:in `start'
/var/www/miq/vmdb/lib/workers/bin/evm_server.rb:4:in `<main>'
[----] E, [2017-08-03T03:15:16.670899 #22132:843140] ERROR -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::Refresher#refresh) EMS: [CTC Core], id: [10000000000001] Unable to perform refresh for the following targets:
[----] E, [2017-08-03T03:15:16.671046 #22132:843140] ERROR -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::Refresher#refresh)  --- ManageIQ::Providers::OpenshiftEnterprise::ContainerManager [CTC Core] id [10000000000
001]
[----] I, [2017-08-03T03:15:16.700872 #22132:843140]  INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::Refresher#refresh) Refreshing all targets...Complete
[----] E, [2017-08-03T03:15:16.701124 #22132:843140] ERROR -- : MIQ(MiqQueue#deliver) Message id: [10000366715709], Error: [HTTP status code 429, 429 Too Many Requests]
[----] E, [2017-08-03T03:15:16.701282 #22132:843140] ERROR -- : [EmsRefresh::Refreshers::EmsRefresherMixin::PartialRefreshError]: HTTP status code 429, 429 Too Many Requests  Method:[rescue in deliver]
[----] E, [2017-08-03T03:15:16.701439 #22132:843140] ERROR -- : /var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:50:in `refresh'

/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:10:in `refresh'
/var/www/miq/vmdb/app/models/ems_refresh.rb:91:in `block in refresh'
/var/www/miq/vmdb/app/models/ems_refresh.rb:90:in `each'
/var/www/miq/vmdb/app/models/ems_refresh.rb:90:in `refresh'
/var/www/miq/vmdb/app/models/miq_queue.rb:347:in `block in deliver'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:91:in `block in timeout'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `block in catch'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `catch'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `catch'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:106:in `timeout'
/var/www/miq/vmdb/app/models/miq_queue.rb:343:in `deliver'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:106:in `deliver_queue_message'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:134:in `deliver_message'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:152:in `block in do_work'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `loop'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `do_work'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:334:in `block in do_work_loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:331:in `do_work_loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:153:in `run'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:128:in `start'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:21:in `start_worker'
/var/www/miq/vmdb/app/models/miq_worker.rb:343:in `block in start'
/opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork'
/opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork'
/var/www/miq/vmdb/app/models/miq_worker.rb:341:in `start'
/var/www/miq/vmdb/app/models/miq_worker.rb:270:in `start_worker'
/var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:68:in `start_worker_for_ems'
/var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:46:in `block in sync_workers'
/var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:45:in `each'
/var/www/miq/vmdb/app/models/mixins/per_ems_worker_mixin.rb:45:in `sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:52:in `block in sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `each'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:22:in `monitor_workers'
/var/www/miq/vmdb/app/models/miq_server.rb:346:in `block in monitor'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block'
/var/www/miq/vmdb/app/models/miq_server.rb:346:in `monitor'
/var/www/miq/vmdb/app/models/miq_server.rb:368:in `block (2 levels) in monitor_loop'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block'
/var/www/miq/vmdb/app/models/miq_server.rb:368:in `block in monitor_loop'
/var/www/miq/vmdb/app/models/miq_server.rb:367:in `loop'
/var/www/miq/vmdb/app/models/miq_server.rb:367:in `monitor_loop'
/var/www/miq/vmdb/app/models/miq_server.rb:250:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:65:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:92:in `start'
/var/www/miq/vmdb/lib/workers/bin/evm_server.rb:4:in `<main>'

Version-Release number of selected component (if applicable):
CFME 5.7.1.3

How reproducible:
customer environment

Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:
Comment 5 Eric Rich 2017-08-11 10:08:38 EDT
This might be similar to https://bugzilla.redhat.com/show_bug.cgi?id=1472532

The fix could involve any of the following: https://bugzilla.redhat.com/show_bug.cgi?id=1472532#c1
Comment 6 Eric Rich 2017-08-11 10:36:22 EDT
(In reply to Eric Rich from comment #5)
See config changes posted with https://bugzilla.redhat.com/show_bug.cgi?id=1472532#c5
Comment 11 Beni Paskin-Cherniavsky 2017-08-16 08:10:20 EDT
I don't know if CFME refresh has backoff logic (none in the Openshift provider or client, there might be some in core refresh scheduling?).
But it's not doing that many requests — about 20 (serial) per refresh.
I only see 3 refreshes fail, 2 with ECONNREFUSED, 1 with 429 Too Many Requests.

However I see 169 start_event_monitor attempts failing ECONNREFUSED, retrying about once per second, which might contribute to load on Openshift API.

other errors:
- workers not starting because exceeded 60% of swap
- 5 times: RefreshWorker has not responded in 7215 seconds, restarting worker 
- MiqPriorityWorker 38 messages: timed out after 600 seconds
- tons of metrics collection errors - a mix of:
  - Hawkular metrics service unavailable: Connection reset by peer - SSL_connect
  - Hawkular metrics service unavailable: <html>...JBWEB000065: HTTP Status 403...Access to the specified resource has been forbidden.

(P.S. tip for searching the log: grep -v last_refresh_error)

=> I'd say CFME itself is not impacted – it tolerates the errors well by retrying – too well and ought to have some backoff.
In this specific case honoring 429 Retry-After header would not help, most errors are ECONNREFUSED (which might reflect Openshift being even more overloaded?).  Could do universal backoff on any error.

=> This appliance needs more RAM.  Being deep into swap can make it painfully slow and exacerbate timeouts...

Note You need to log in before you can comment on or make changes to this bug.