1405085 – ActiveRecord::StatementInvalid on host registration

Red Hat Satellite engineering is moving the tracking of its product development work on Satellite to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "Satellite project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs will be migrated starting at the end of May. If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "Satellite project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/SAT-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1405085 - ActiveRecord::StatementInvalid on host registration

Summary: ActiveRecord::StatementInvalid on host registration

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Satellite
Classification:	Red Hat
Component:	Hosts - Content
Sub Component:
Version:	6.2.6
Hardware:	Unspecified
OS:	Unspecified
Priority:	urgent
Severity:	high
Target Milestone:	Unspecified
Assignee:	Justin Sherrill
QA Contact:	Roman Plevka
Docs Contact:
URL:
Whiteboard:
Duplicates (2):	1412154 1418222 (view as bug list)
Depends On:
Blocks:	1412784 1419953 1421259
TreeView+	depends on / blocked

Reported:	2016-12-15 14:50 UTC by Roman Plevka
Modified:	2019-06-13 21:25 UTC (History)
CC List:	13 users (show)
Fixed In Version:	rubygem-katello-3.0.0.103-1,rubygem-katello-3.0.0.103-1
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Clones:	1412784 1419953 (view as bug list)
Environment:
Last Closed:	2017-03-06 08:35:56 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)
foreman-debug (3.20 MB, application/x-xz) 2016-12-15 14:52 UTC, Roman Plevka	no flags	Details
backtrace (8.22 KB, text/plain) 2017-01-17 16:09 UTC, Justin Sherrill	no flags	Details
View All

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Foreman Issue Tracker	18122	0	Urgent	Closed	ActiveRecord::StatementInvalid on host registration	2020-03-15 16:32:20 UTC
Red Hat Product Errata	RHBA-2017:0447	0	normal	SHIPPED_LIVE	Satellite 6.2.8 Async Bug Release	2017-03-06 13:23:41 UTC

Description Roman Plevka 2016-12-15 14:50:05 UTC

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)

Comment 1 Roman Plevka 2016-12-15 14:52:27 UTC

Created attachment 1232200 [details]
foreman-debug

the issue occured at 2016-12-13 10:13:18

Comment 3 Tasos Papaioannou 2017-01-12 19:03:41 UTC

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'

Comment 4 Roman Plevka 2017-01-12 20:46:56 UTC

*** Bug 1412154 has been marked as a duplicate of this bug. ***

Comment 5 Jason Montleon 2017-01-16 19:09:39 UTC

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

Comment 6 Ann Marie Rubin 2017-01-16 19:25:05 UTC

blocks qci 1.1 GA (14-Feb-17).

Comment 7 Justin Sherrill 2017-01-17 16:09:02 UTC

Created attachment 1241876 [details]
backtrace

attaching backtrace in case pastebin dies

Comment 8 Justin Sherrill 2017-01-18 00:07:24 UTC

Created redmine issue http://projects.theforeman.org/issues/18122 from this bug

Comment 10 Satellite Program 2017-01-18 01:09:14 UTC

Upstream bug assigned to jsherril

Comment 11 Satellite Program 2017-01-18 01:09:18 UTC

Upstream bug assigned to jsherril

Comment 13 Satellite Program 2017-01-24 21:09:24 UTC

Moving this bug to POST for triage into Satellite 6 since the upstream issue http://projects.theforeman.org/issues/18122 has been resolved.

Comment 14 jcallaha 2017-02-02 15:00:39 UTC

*** Bug 1418222 has been marked as a duplicate of this bug. ***

Comment 16 Tasos Papaioannou 2017-02-07 19:24:29 UTC

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.

Comment 17 Roman Plevka 2017-02-24 07:44:19 UTC

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"

Comment 18 Roman Plevka 2017-02-24 07:45:31 UTC

(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"

Comment 23 errata-xmlrpc 2017-03-06 08:35:56 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-2017:0447

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