Hide Forgot
Description of problem: 2016-12-13 10:13:13 - robottelo.ssh - DEBUG - >>> subscription-manager register --org QZRoQT --activationkey ijB6dZv1vA --force 2016-12-13 10:13:19 - robottelo.ssh - DEBUG - <<< stderr ERROR: current transaction is aborted, commands ignored until end of transaction block the complete stacktrace from production.log: http://pastebin.test.redhat.com/439682 Also attaching foreman-debug output Version-Release number of selected component (if applicable): 6.2.6 snap#2 Actual results: PG::Error: ERROR: current transaction is aborted, commands ignored until end of transaction block | : SELECT "fact_names".* FROM "fact_names" WHERE "fact_names"."type" IN ('Katello::RhsmFactName') AND "fact_names"."name" = 'dmi' ORDER BY fact_names.name LIMIT 1 (ActiveRecord::StatementInvalid)
Created attachment 1232200 [details] foreman-debug the issue occured at 2016-12-13 10:13:18
I've reproduced the same error in QuickStart Cloud Installer build QCI-1.1-RHEL-7-20170111.t.8, which uses Satellite 6.2.6 rpms: foreman-1.11.0.61-1.el7sat.noarch satellite-6.2.6-2.0.el7sat.noarch The postgres logs show: 2017-01-12 12:56:48 EST ERROR: duplicate key value violates unique constraint "index_fact_names_on_name_and_type" 2017-01-12 12:56:48 EST DETAIL: Key (name, type)=(dmi::memory::serial_number, Katello::RhsmFactName) already exists. 2017-01-12 12:56:48 EST STATEMENT: INSERT INTO "fact_names" ("ancestry", "created_at", "name", "short_name", "type", "updated_at") VALUES ($1, $2, $3, $4, $5, $6) RETURNING "id" 2017-01-12 12:56:48 EST ERROR: current transaction is aborted, commands ignored until end of transaction block 2017-01-12 12:56:48 EST STATEMENT: SELECT "fact_names".* FROM "fact_names" WHERE "fact_names"."type" IN ('Katello::RhsmFactName') AND "fact_names"."name" = 'dmi' ORDER BY fact_names.name LIMIT 1 In the database, I can see that the fact name does exist, and was created a few seconds prior to the unique constraint violation: foreman=# select * from fact_names where name = 'dmi::memory::serial_number'; id | name | updated_at | created_at | compose | short_name | type | ancestry -----+----------------------------+----------------------------+----------------------------+---------+---------------+-----------------------+---------- 282 | dmi::memory::serial_number | 2017-01-12 17:56:45.784919 | 2017-01-12 17:56:45.784919 | f | serial_number | Katello::RhsmFactName | 118/135 (1 row) This might be a race condition / locking issue between two systems that registered and uploaded their facts simultaneously. From production.log: 1st registration: 2017-01-12 12:56:44 [app] [I] Started POST "/rhsm/consumers?owner=Default_Organization&activation_keys=OpenShift-tpapaioa_1-OpenShift" for 192.168.100.128 at 2017-01-12 12:56:44 -0500 2017-01-12 12:56:44 [app] [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_activate as JSON 2017-01-12 12:56:44 [app] [I] Parameters: {"facts"=>"[FILTERED]", "installedProducts"=>[{"productName"=>"Red Hat Enterprise Linux Server", "arch"=>"x86_64", "version"=>"7.3", "productId"=>"69"}], "type"=>"system", "name"=>"tpapaioa-1-ocp-master1.localdomain", "contentTags"=>["rhel-7", "rhel-7-server"], "owner"=>"Default_Organization", "activation_keys"=>"OpenShift-tpapaioa_1-OpenShift"} 2nd registration: 2017-01-12 12:56:44 [app] [I] Started POST "/rhsm/consumers?owner=Default_Organization&activation_keys=OpenShift-tpapaioa_1-OpenShift" for 192.168.100.130 at 2017-01-12 12:56:44 -0500 2017-01-12 12:56:44 [app] [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_activate as JSON 2017-01-12 12:56:44 [app] [I] Parameters: {"facts"=>"[FILTERED]", "installedProducts"=>[{"productName"=>"Red Hat Enterprise Linux Server", "arch"=>"x86_64", "version"=>"7.3", "productId"=>"69"}], "type"=>"system", "name"=>"tpapaioa-1-ocp-node1.localdomain", "contentTags"=>["rhel-7", "rhel-7-server"], "owner"=>"Default_Organization", "activation_keys"=>"OpenShift-tpapaioa_1-OpenShift"} Completed import of facts: 2017-01-12 12:56:46 [app] [I] Import facts for 'localhost' completed. Added: 142, Updated: 1, Deleted 0 facts Failed import of facts 2 seconds later: 2017-01-12 12:56:48 [foreman-tasks/action] [E] PG::Error: ERROR: current transaction is aborted, commands ignored until end of transaction block | : SELECT "fact_names".* FROM "fact_names" WHERE "fact_names"."type" IN ('Katello::RhsmFactName') AND "fact_names"."name" = 'dmi' ORDER BY fact_names.name LIMIT 1 (ActiveRecord::StatementInvalid) | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/connection_adapters/postgresql_adapter.rb:822:in `exec' | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/connection_adapters/postgresql_adapter.rb:822:in `block in exec_no_cache'
*** Bug 1412154 has been marked as a duplicate of this bug. ***
I hit the same with an openstack deployment today: Jan 16 13:50:19 host-192-168-150-10 os-collect-config: [2017-01-16 13:50:19,994] (heat-config) [INFO] {"deploy_stdout": "HTTP/1.1 200 OK\r\nStatus: 200 OK\r\nSatellite 6 detected at https://qci.example.com\nPreparing... ########################################\nUpdating / installing...\nkatello-ca-consumer-qci.example.com-1.########################################\n", "deploy_stderr": " % Total % Received % Xferd Average Speed Time Time Time Current\n Dload Upload Total Spent Left Speed\n\r 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0\r100 6526 100 6526 0 0 43376 0 --:--:-- --:--:-- --:--:-- 43506\nERROR: current transaction is aborted, commands ignored until end of transaction block\n\n", "deploy_status_code": 70} Jan 16 13:50:19 host-192-168-150-10 os-collect-config: [2017-01-16 13:50:19,994] (heat-config) [DEBUG] [2017-01-16 13:45:33,900] (heat-config) [INFO] REG_ACTIVATION_KEY=OpenStack_Undercloud-osp1-OpenStack_Undercloud
blocks qci 1.1 GA (14-Feb-17).
Created attachment 1241876 [details] backtrace attaching backtrace in case pastebin dies
Created redmine issue http://projects.theforeman.org/issues/18122 from this bug
Upstream bug assigned to jsherril
Moving this bug to POST for triage into Satellite 6 since the upstream issue http://projects.theforeman.org/issues/18122 has been resolved.
*** Bug 1418222 has been marked as a duplicate of this bug. ***
This seems to be an issue again, on QCI-1.1-RHEL-7-20170203.t.0, which has the patch applied to tfm-rubygem-katello. A deployment of OCP (1 master + 1 worker) failed during registration of the nodes to the Satellite. /var/log/foreman/production.log shows: **** 2017-02-07 13:24:13 [app] [I] Started POST "/rhsm/consumers?owner=Default_Organization&activation_keys=OpenShift-tpapaioa_2-OpenShift" for 192.168.100.128 at 2017-02-07 13:24:13 -0500 2017-02-07 13:24:13 [app] [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_activate as JSON 2017-02-07 13:24:13 [app] [I] Parameters: {"facts"=>"[FILTERED]", "installedProducts"=>[{"productName"=>"Red Hat Enterprise Linux Server", "arch"=>"x86_64", "version"=>"7.3", "productId"=>"69"}], "type"=>"system", "name"=>"tpapaioa-2-ocp-master1.example.com", "contentTags"=>["rhel-7", "rhel-7-server"], "owner"=>"Default_Organization", "activation_keys"=>"OpenShift-tpapaioa_2-OpenShift"} 2017-02-07 13:24:14 [app] [I] Started POST "/rhsm/consumers?owner=Default_Organization&activation_keys=OpenShift-tpapaioa_2-OpenShift" for 192.168.100.130 at 2017-02-07 13:24:14 -0500 2017-02-07 13:24:14 [app] [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_activate as JSON 2017-02-07 13:24:14 [app] [I] Parameters: {"facts"=>"[FILTERED]", "installedProducts"=>[{"productName"=>"Red Hat Enterprise Linux Server", "arch"=>"x86_64", "version"=>"7.3", "productId"=>"69"}], "type"=>"system", "name"=>"tpapaioa-2-ocp-node1.example.com", "contentTags"=>["rhel-7", "rhel-7-server"], "owner"=>"Default_Organization", "activation_keys"=>"OpenShift-tpapaioa_2-OpenShift"} [...] 2017-02-07 13:24:20 [foreman-tasks/action] [E] Validation failed: Name has already been taken (ActiveRecord::RecordInvalid) | /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/protected_attributes-1.1.3/lib/active_record/mass_assignment_security/validations.rb:17:in `create!' | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/relation.rb:140:in `block in create!' | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/relation.rb:285:in `scoping' | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/relation.rb:140:in `create!' | /opt/theforeman/tfm/root/usr/share/gems/gems/protected_attributes-1.1.3/lib/active_record/mass_assignment_security/relation.rb:42:in `first_or_create!' | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.95/app/models/katello/rhsm_fact_importer.rb:29:in `add_fact_name' | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.95/app/models/katello/rhsm_fact_importer.rb:21:in `block in add_new_facts' | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.95/app/models/katello/rhsm_fact_importer.rb:21:in `each' | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.95/app/models/katello/rhsm_fact_importer.rb:21:in `add_new_facts' | /usr/share/foreman/app/services/fact_importer.rb:41:in `import!' | /usr/share/foreman/app/models/host/base.rb:148:in `import_facts' | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.95/app/models/katello/host/subscription_facet.rb:83:in `update_facts' | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.95/app/lib/actions/katello/host/register.rb:54:in `run' | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/action.rb:506:in `block (3 levels) in execute_run' | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/middleware/stack.rb:26: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' 2017-02-07 13:24:20 [katello/cp_proxy] [E] ForemanTasks::TaskError: Task 52ac260a-46b7-4ee8-9544-4127660f41ec: ActiveRecord::RecordInvalid: Validation failed: Name has already been taken | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.11/lib/foreman_tasks.rb:40:in `block in sync_task' | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.11/lib/foreman_tasks.rb:39:in `tap' | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.11/lib/foreman_tasks.rb:39:in `sync_task' | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.11/lib/foreman_tasks/triggers.rb:22:in `sync_task' | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.95/app/controllers/katello/api/rhsm/candlepin_proxies_controller.rb:227:in `consumer_activate' [...] | /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' 2017-02-07 13:24:20 [app] [I] Completed 500 Internal Server Error in 6432ms (Views: 7.3ms | ActiveRecord: 83.6ms) 2017-02-07 13:24:21 [app] [I] Import facts for 'tpapaioa-2-ocp-node1.example.com' completed. Added: 142, Updated: 1, Deleted 0 facts **** There is nothing logged in /var/lib/pgsql/data/pg_log/postgresql-Tue.log this time, however. So the Satellite code change may have fixed the postgres error but not the overall race condition when updating/importing rhsm facts.
Our test reveals another error on 6.2.8 snap#3 (which should have the patch included): 2017-02-21 08:21:41 - robottelo.ssh - DEBUG - <<< stderr Task 98dd717a-a9f3-4d03-9e36-2b659e1d8e0b: ActiveRecord::RecordNotUnique: PG::Error: ERROR: duplicate key value violates unique constraint "index_operatingsystems_on_title" : INSERT INTO "operatingsystems" ("created_at", "major", "minor", "name", "title", "type", "updated_at") VALUES ($1, $2, $3, $4, $5, $6, $7) RETURNING "id"
(In reply to Roman Plevka from comment #17) > Our test reveals another error on 6.2.8 snap#3 (which should have the patch > included): > > 2017-02-21 08:21:41 - robottelo.ssh - DEBUG - <<< stderr > Task 98dd717a-a9f3-4d03-9e36-2b659e1d8e0b: ActiveRecord::RecordNotUnique: > PG::Error: ERROR: duplicate key value violates unique constraint > "index_operatingsystems_on_title" > : INSERT INTO "operatingsystems" ("created_at", "major", "minor", "name", > "title", "type", "updated_at") VALUES ($1, $2, $3, $4, $5, $6, $7) RETURNING > "id" i missed the first line with the command, where this occurred, so here it is again: subscription-manager register --org J6sd7t --activationkey msgXbCefyh --force Task 98dd717a-a9f3-4d03-9e36-2b659e1d8e0b: ActiveRecord::RecordNotUnique: PG::Error: ERROR: duplicate key value violates unique constraint "index_operatingsystems_on_title" : INSERT INTO "operatingsystems" ("created_at", "major", "minor", "name", "title", "type", "updated_at") VALUES ($1, $2, $3, $4, $5, $6, $7) RETURNING "id"
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-2017:0447