Bug 1405085

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

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