Bug 1553845
| Summary: | concurrent registration occasionally fails with "host_id has already been taken" error | ||||||
|---|---|---|---|---|---|---|---|
| Product: | Red Hat Satellite | Reporter: | Chris Duryee <cduryee> | ||||
| Component: | Registration | Assignee: | Justin Sherrill <jsherril> | ||||
| Status: | CLOSED ERRATA | QA Contact: | jcallaha | ||||
| Severity: | high | Docs Contact: | |||||
| Priority: | unspecified | ||||||
| Version: | 6.2.14 | CC: | andrew.schofield, kabbott, rplevka, sthirugn, zhunting | ||||
| Target Milestone: | Unspecified | Keywords: | Triaged | ||||
| Target Release: | Unused | ||||||
| Hardware: | Unspecified | ||||||
| OS: | Unspecified | ||||||
| Whiteboard: | |||||||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | |||||||
| : | 1563261 1563262 (view as bug list) | Environment: | |||||
| Last Closed: | 2018-05-21 20:16:44 UTC | Type: | Bug | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Embargoed: | |||||||
| Attachments: |
|
||||||
similar stack trace, might be related 2018-03-09 13:16:54 [foreman-tasks/action] [E] Failed Candlepin Event: Validation failed: Host has already been taken 2018-03-09 13:16:54 [foreman-tasks/action] [E] /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/validations.rb:57:in `save!' /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/attribute_methods/dirty.rb:29:in `save!' /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/transactions.rb:273:in `block in save!' /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/transactions.rb:329:in `block in with_transaction_returning_status' /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/connection_adapters/abstract/database_statements.rb:201:in `block in transaction' /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/connection_adapters/abstract/database_statements.rb:209:in `within_new_transaction' /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/connection_adapters/abstract/database_statements.rb:201:in `transaction' /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/transactions.rb:208:in `transaction' /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/transactions.rb:326:in `with_transaction_returning_status' /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/transactions.rb:273:in `save!' /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.163/app/models/katello/host/subscription_facet.rb:74:in `update_subscription_status' /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.163/app/lib/actions/candlepin/import_pool_handler.rb:75:in `reindex_consumer' /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.163/app/lib/actions/candlepin/import_pool_handler.rb:41:in `handle' /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.163/app/lib/actions/candlepin/listen_on_candlepin_events.rb:183:in `act_on_event' /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.163/app/lib/actions/candlepin/listen_on_candlepin_events.rb:90:in `block in run' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matchers/abstract.rb:74:in `block in assigns' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matchers/abstract.rb:73:in `tap' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matchers/abstract.rb:73:in `assigns' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matching.rb:56:in `match_value' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matching.rb:36:in `block in match?' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matching.rb:35:in `each' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matching.rb:35:in `match?' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matching.rb:23:in `match' /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.163/app/lib/actions/candlepin/listen_on_candlepin_events.rb:77:in `run' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/action.rb:506:in `block (3 levels) in execute_run' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/middleware/stack.rb:26:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/middleware/stack.rb:26:in `pass' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/middleware.rb:17:in `pass' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/action/progress.rb:30:in `with_progress_calculation' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/action/progress.rb:16:in `run' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/middleware/stack.rb:22:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/middleware/stack.rb:26:in `pass' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/middleware.rb:17:in `pass' /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.163/app/lib/actions/middleware/keep_locale.rb:11:in `block in run' /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.163/app/lib/actions/middleware/keep_locale.rb:22:in `with_locale' /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.163/app/lib/actions/middleware/keep_locale.rb:11:in `run' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/middleware/stack.rb:22:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/middleware/stack.rb:26:in `pass' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/middleware.rb:17:in `pass' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/middleware.rb:30:in `run' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/middleware/stack.rb:22:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/middleware/world.rb:30:in `execute' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/action.rb:505:in `block (2 levels) in execute_run' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/action.rb:504:in `catch' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/action.rb:504:in `block in execute_run' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/action.rb:419:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/action.rb:419:in `block in with_error_handling' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/action.rb:419:in `catch' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/action.rb:419:in `with_error_handling' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/action.rb:499:in `execute_run' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/action.rb:260:in `execute' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:9:in `block (2 levels) in execute' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/execution_plan/steps/abstract.rb:155:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/execution_plan/steps/abstract.rb:155:in `with_meta_calculation' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:8:in `block in execute' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:22:in `open_action' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:7:in `execute' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/executors/parallel/worker.rb:15:in `block in on_message' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matchers/abstract.rb:74:in `block in assigns' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matchers/abstract.rb:73:in `tap' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matchers/abstract.rb:73:in `assigns' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matching.rb:56:in `match_value' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matching.rb:36:in `block in match?' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matching.rb:35:in `each' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matching.rb:35:in `match?' /opt/theforeman/tfm/root/usr/share/gems/gems/algebrick-0.7.3/lib/algebrick/matching.rb:23:in `match' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/executors/parallel/worker.rb:12:in `on_message' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/context.rb:46:in `on_envelope' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass' /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.6/lib/dynflow/actor.rb:26:in `on_envelope' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/termination.rb:55:in `on_envelope' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/core.rb:161:in `process_envelope' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/core.rb:95:in `block in on_envelope' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/core.rb:118:in `block (2 levels) in schedule_execution' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `block in synchronize' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `synchronize' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `synchronize' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/core.rb:115:in `block in schedule_execution' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/serialized_execution.rb:18:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/serialized_execution.rb:18:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/serialized_execution.rb:96:in `work' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/serialized_execution.rb:77:in `block in call_job' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:333:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:333:in `run_task' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:322:in `block (3 levels) in create_worker' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:305:in `loop' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:305:in `block (2 levels) in create_worker' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:304:in `catch' /opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:304:in `block in create_worker' /opt/theforeman/tfm/root/usr/share/gems/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `call' /opt/theforeman/tfm/root/usr/share/gems/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context' repro steps: in one terminal on satellite, 'watch "grep host_id /var/log/foreman/production.log"' to see if error occurs on content host machine, run "for x in `seq 1 100`; do python flood.py --image ch-d --tag rhel7 --satellite satellite.example.com --name japan$x --key rhel7ak --count 2 --exit-criteria register; done" error should appear shortly. Note that if you use count=5, there is a lower chance of the error happening. Count=2 makes it more likely. If you disable candlepin amqp messages via /etc/candlepin/candlepin.conf, the error will not happen. It's likely that there is a race condition between registration and ListenOnCandlepinEvents messages. Created redmine issue http://projects.theforeman.org/issues/22850 from this bug Upstream bug assigned to jsherril Upstream bug assigned to jsherril Moving this bug to POST for triage into Satellite 6 since the upstream issue http://projects.theforeman.org/issues/22850 has been resolved. Moving to 6.2.15 as this is required for an other must 6.2.15 bug https://bugzilla.redhat.com/show_bug.cgi?id=1514508 Verified in Satellite 6.2.15 Snap 2. I ran the flood.py script provided by [1] to register 10k hosts to the satellite with 50 running simultaneously throughout the process. None of the registrations encountered the error presented in this bug. Additionally, the only tasks associated with the new hosts were package profile updates. container.log (attached) contains the registration details for each of the hosts. -bash-4.2# grep taken container.log | wc -l 0 Follow up. I also ran two other flood sessions of 30k hosts (50 concurrent) and none of those encountered the error. [1] - https://github.com/JacobCallahan/content-host-d Created attachment 1428939 [details]
container.log
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2018:1672 |
Description of problem: If you run a number of concurrent registrations, you will occasionally get this error 2018-03-09 11:01:08 f2291934 [app] [I] Started POST "/rhsm/consumers?owner=Default_Organization&activation_keys=rhel7ak" for 10.8.0.69 at 2018-03-09 11:01:08 -0500 2018-03-09 11:01:08 f2291934 [app] [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_activate as JSON 2018-03-09 11:01:08 f2291934 [app] [I] Parameters: {"facts"=>"[FILTERED]", "installedProducts"=>[{"productName"=>"Red Hat Enterprise Linux Server", "arch"=>"x86_64", "version"=>"7.4", "productId"=>"69"}], "type"=>"system", "name"=>"uganda2", "contentTags"=>["rhel-7", "rhel-7-server"], "owner"=>"Default_Organization", "activation_keys"=>"rhel7ak"} 2018-03-09 11:01:11 f2291934 [audit] [I] [uganda2] deleted 0 (5.0ms) 2018-03-09 11:01:11 f2291934 [audit] [I] [uganda2] updated 0 (2.8ms) 2018-03-09 11:01:12 f2291934 [audit] [I] [uganda2] added 111 (847.1ms) 2018-03-09 11:01:12 f2291934 [app] [I] Import facts for 'uganda2' completed. Added: 111, Updated: 0, Deleted 0 facts 2018-03-09 11:01:12 f2291934 [katello/cp_proxy] [E] <Class> ActiveRecord::RecordInvalid 2018-03-09 11:01:12 f2291934 [katello/cp_proxy] [E] host_id: ["has already been taken"] 2018-03-09 11:01:12 f2291934 [app] [I] Completed 422 Unprocessable Entity in 4250ms (Views: 0.4ms | ActiveRecord: 229.6ms) NOTE: this seems to only occur after 1514508 (6.2.15) is applied. Version-Release number of selected component (if applicable): 6.2.14 + hotfix for 1514508 How reproducible: maybe 10-20% of time, but sometimes you'll get a number of runs with no error. Steps to Reproduce: 1. register two hosts at same time Actual results: error Expected results: no error Additional info: the host records all seeem OK in the satellite. clean_backend_objects does not find any missing records, and the host works OK. I am not sure yet why flood.py does not return when the 422 is returned, when I connect to the docker host I don't see anything waiting.