Bug 1553845 - concurrent registration occasionally fails with "host_id has already been taken" error
Summary: concurrent registration occasionally fails with "host_id has already been tak...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Registration
Version: 6.2.14
Hardware: Unspecified
OS: Unspecified
unspecified
high with 3 votes vote
Target Milestone: Unspecified
Assignee: Justin Sherrill
QA Contact: jcallaha
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-03-09 17:06 UTC by Chris Duryee
Modified: 2019-08-12 14:04 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1563261 1563262 (view as bug list)
Environment:
Last Closed: 2018-05-21 20:16:44 UTC
Target Upstream Version:


Attachments (Terms of Use)
container.log (15.00 MB, text/plain)
2018-04-30 20:04 UTC, jcallaha
no flags Details


Links
System ID Priority Status Summary Last Updated
Foreman Issue Tracker 22850 Normal Closed concurrent registration occasionally fails with "host_id has already been taken" error 2020-03-27 17:20:53 UTC
Red Hat Product Errata RHBA-2018:1672 None None None 2018-05-21 20:17:13 UTC

Description Chris Duryee 2018-03-09 17:06:34 UTC
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.

Comment 1 Chris Duryee 2018-03-09 18:30:23 UTC
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'

Comment 2 Chris Duryee 2018-03-09 19:49:28 UTC
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.

Comment 3 Justin Sherrill 2018-03-12 09:54:34 UTC
Created redmine issue http://projects.theforeman.org/issues/22850 from this bug

Comment 4 pm-sat@redhat.com 2018-03-12 10:14:13 UTC
Upstream bug assigned to jsherril@redhat.com

Comment 5 pm-sat@redhat.com 2018-03-12 10:14:15 UTC
Upstream bug assigned to jsherril@redhat.com

Comment 7 pm-sat@redhat.com 2018-03-15 14:14:36 UTC
Moving this bug to POST for triage into Satellite 6 since the upstream issue http://projects.theforeman.org/issues/22850 has been resolved.

Comment 9 sthirugn@redhat.com 2018-04-04 20:40:15 UTC
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

Comment 11 jcallaha 2018-04-30 20:03:53 UTC
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

Comment 12 jcallaha 2018-04-30 20:04:22 UTC
Created attachment 1428939 [details]
container.log

Comment 15 errata-xmlrpc 2018-05-21 20:16:44 UTC
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


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