Bugzilla will be upgraded to version 5.0. The upgrade date is tentatively scheduled for 2 December 2018, pending final testing and feedback.
Bug 1553845 - concurrent registration occasionally fails with "host_id has already been taken" error
concurrent registration occasionally fails with "host_id has already been tak...
Status: CLOSED ERRATA
Product: Red Hat Satellite 6
Classification: Red Hat
Component: Registration (Show other bugs)
6.2.14
Unspecified Unspecified
unspecified Severity high with 3 votes (vote)
: 6.2.15
: Unused
Assigned To: Justin Sherrill
jcallaha
: Triaged
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2018-03-09 12:06 EST by Chris Duryee
Modified: 2018-05-30 11:35 EDT (History)
5 users (show)

See Also:
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 16:16:44 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


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


External Trackers
Tracker ID Priority Status Summary Last Updated
Foreman Issue Tracker 22850 None None None 2018-03-12 05:54 EDT
Red Hat Product Errata RHBA-2018:1672 None None None 2018-05-21 16:17 EDT

  None (edit)
Description Chris Duryee 2018-03-09 12:06:34 EST
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 13:30:23 EST
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 14:49:28 EST
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 05:54:34 EDT
Created redmine issue http://projects.theforeman.org/issues/22850 from this bug
Comment 4 pm-sat@redhat.com 2018-03-12 06:14:13 EDT
Upstream bug assigned to jsherril@redhat.com
Comment 5 pm-sat@redhat.com 2018-03-12 06:14:15 EDT
Upstream bug assigned to jsherril@redhat.com
Comment 7 pm-sat@redhat.com 2018-03-15 10:14:36 EDT
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 16:40:15 EDT
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 16:03:53 EDT
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 16:04 EDT
Created attachment 1428939 [details]
container.log
Comment 15 errata-xmlrpc 2018-05-21 16:16:44 EDT
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.