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 1356622 - [hammer] product create fails with error: PG::Error: ERROR: duplicate key value violates unique constraint "index_katello_pools_on_cp_id"
Summary: [hammer] product create fails with error: PG::Error: ERROR: duplicate key v...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Repositories
Version: 6.2.0
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: Unspecified
Assignee: Justin Sherrill
QA Contact: Sachin Ghai
URL: http://projects.theforeman.org/issues...
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-07-14 13:42 UTC by Sachin Ghai
Modified: 2019-09-26 17:31 UTC (History)
3 users (show)

Fixed In Version: rubygem-katello-3.0.0.67-1,rubygem-katello-3.0.0.68-1
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-07-27 11:28:07 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
complete stracktrace (29.12 KB, text/plain)
2016-07-15 06:24 UTC, Sachin Ghai 		no flags Details
foreman-debug (537.91 KB, application/x-xz)
2016-07-15 06:35 UTC, Sachin Ghai 		no flags Details
complete exception from production.log (72.68 KB, text/plain)
2016-07-21 07:05 UTC, Sachin Ghai 		no flags Details
foreman-debug (488.23 KB, application/x-xz)
2016-07-21 07:12 UTC, Sachin Ghai 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
Foreman Issue Tracker 15755 0 Normal Closed [hammer] product create fails with error: PG::Error: ERROR: duplicate key value violates unique constraint "index_kate... 2020-03-19 19:05:48 UTC

Description Sachin Ghai 2016-07-14 13:42:45 UTC 
Description of problem:
Product create test in our automation failed due to below issue:

DEBUG - >>> [qe-sat6-rhel7.satqe.lab.eng.rdu2.redhat.com] LANG=en_US.UTF-8  hammer -v -u admin -p changeme --output=csv product create --organization-id="616" --description="esVuNKYtkkFdqLxnDWyj" --name="<s>vyANYEvHYQOgLrcXrSiUWeKnAlebUTzbGMDTtqEnbwdUvbnxszNZjGbHXBHnnPNcvyGnVWCnyjTgNWM</s>" --label="nJgGLepWIpffwFjTVBEq"
2016-07-13 11:19:57 - robottelo.ssh - INFO - Instantiated Paramiko client 0x7f11b4baacd0
2016-07-13 11:20:01 - robottelo.ssh - INFO - Destroying Paramiko client 0x7f11b4baacd0
2016-07-13 11:20:01 - robottelo.ssh - INFO - Destroyed Paramiko client 0x7f11b4baacd0
2016-07-13 11:20:01 - robottelo.ssh - DEBUG - <<< stderr
[ERROR 2016-07-13 11:20:01 Exception] Task 3021f78f-1b7f-4814-89ba-0f7734a2ae69: ActiveRecord::RecordNotUnique: PG::Error: ERROR:  duplicate key value violates unique constraint "index_katello_pools_on_cp_id"
DETAIL:  Key (cp_id)=(ff80808155e4aaf80155e4d7e01207b8) already exists.
: INSERT INTO "katello_pools" ("cp_id", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"
Could not create the product:
  Task 3021f78f-1b7f-4814-89ba-0f7734a2ae69: ActiveRecord::RecordNotUnique: PG::Error: ERROR:  duplicate key value violates unique constraint "index_katello_pools_on_cp_id"
  DETAIL:  Key (cp_id)=(ff80808155e4aaf80155e4d7e01207b8) already exists.
  : INSERT INTO "katello_pools" ("cp_id", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"
[ERROR 2016-07-13 11:20:01 Exception] 


This is then reproducible on my setup when I was trying to create multiple product/repo one after another. So looks like issue with some race condition


Could not create the product:
  Task 082171b1-5b16-46e4-a96a-e4e89adac94b: ActiveRecord::RecordNotUnique: PG::Error: ERROR:  duplicate key value violates unique constraint "index_katello_pools_on_cp_id"
  DETAIL:  Key (cp_id)=(8a93a2bd55e8245f0155e8ef7e5b03a1) already exists.
  : INSERT INTO "katello_pools" ("cp_id", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"
Product name is Sat6Tools7 and id is: 142
Could not create the repository:
  Task 6b379314-b07c-4aa1-9dec-2a13202f15e2: Katello::Errors::CandlepinError: Runtime Error RESTEASY001185: Could not find resource for relative : /products//content/1468491862827 of full path: https://localhost:8443/candlepin/products//content/1468491862827?enabled=true at org.jboss.resteasy.core.registry.PathParamSegment.matchPattern:209 


Version-Release number of selected component (if applicable):
sat62 GA snap20.1

How reproducible:


Steps to Reproduce:
1. create product A/repo A
2. create product B/ repo B
3.

Actual results:
Could not create the product:
  Task 082171b1-5b16-46e4-a96a-e4e89adac94b: ActiveRecord::RecordNotUnique: PG::Error: ERROR:  duplicate key value violates unique constraint "index_katello_pools_on_cp_id"
  DETAIL:  Key (cp_id)=(8a93a2bd55e8245f0155e8ef7e5b03a1) already exists.
  : INSERT INTO "katello_pools" ("cp_id", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"
Product name is Sat6Tools7 and id is: 142

Expected results:
product create should work

Additional info:
Comment 2 Brad Buckingham 2016-07-14 14:16:42 UTC 
Hi Sachin, can you attach the foreman-debug or stack trace from the production.log?
Comment 3 Sachin Ghai 2016-07-15 06:24:15 UTC 
Created attachment 1180045 [details]
complete stracktrace
Comment 4 Sachin Ghai 2016-07-15 06:35:14 UTC 
Created attachment 1180049 [details]
foreman-debug
Comment 5 Sachin Ghai 2016-07-20 07:54:08 UTC 
I see this issue with snap 20.3 on our automation run:

2016-07-20 00:33:40 - robottelo.ssh - DEBUG - >>> [qe-sat6-rhel7.satqe.lab.eng.rdu2.redhat.com] LANG=en_US.UTF-8  hammer -v -u admin -p changeme --output=csv product create --organization-id="662" --description="sPFBdxdcCQPNdfIPELsg" --name="PdBWXeGhQv" --label="WcLnjOGzWryMJfRMFFWk"
2016-07-20 00:33:40 - robottelo.ssh - INFO - Instantiated Paramiko client 0x7f01a10abb50
2016-07-20 00:33:45 - robottelo.ssh - INFO - Destroying Paramiko client 0x7f01a10abb50
2016-07-20 00:33:45 - robottelo.ssh - INFO - Destroyed Paramiko client 0x7f01a10abb50
2016-07-20 00:33:45 - robottelo.ssh - DEBUG - <<< stderr
[ERROR 2016-07-20 00:33:45 Exception] Task 3259b7e6-c76c-49b1-a3b6-98cbd305fc9e: ActiveRecord::RecordNotUnique: PG::Error: ERROR:  duplicate key value violates unique constraint "index_katello_pools_on_cp_id"
DETAIL:  Key (cp_id)=(ff808081560665bf01560694b5f2087e) already exists.
: INSERT INTO "katello_pools" ("cp_id", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"
Could not create the product:
  Task 3259b7e6-c76c-49b1-a3b6-98cbd305fc9e: ActiveRecord::RecordNotUnique: PG::Error: ERROR:  duplicate key value violates unique constraint "index_katello_pools_on_cp_id"
  DETAIL:  Key (cp_id)=(ff808081560665bf01560694b5f2087e) already exists.
  : INSERT INTO "katello_pools" ("cp_id", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"
[ERROR 2016-07-20 00:33:45 Exception] 

RestClient::InternalServerError (500 Internal Server Error):
    /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-1.6.7/lib/restclient/abstract_response.rb:48:in `return!'
    /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-bindings-0.0.16/lib/apipie_bindings/api.rb:308:in `block in rest_client_call_block'
    /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-1.6.7/lib/restclient/request.rb:228:in `call'
    /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-1.6.7/lib/restclient/request.rb:228:in `process_result'
    /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-1.6.7/lib/restclient/request.rb:178:in `block in transmit'
    /opt/rh/rh-ruby22/root/usr/share/ruby/net/http.rb:853:in `start'
    /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-1.6.7/lib/restclient/request.rb:172:in `transmit'
    /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-1.6.7/lib/restclient/request.rb:64:in `execute'
    /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-1.6.7/lib/restclient/request.rb:33:in `execute'
    /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-1.6.7/lib/restclient/resource.rb:67:in `post'
    /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-bindings-0.0.16/lib/apipie_bindings/api.rb:295:in `call_client'
    /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-bindings-0.0.16/lib/apipie_bindings/api.rb:224:in `http_call'
    /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-bindings-0.0.16/lib/apipie_bindings/api.rb:174:in `call_action'
    /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-bindings-0.0.16/lib/apipie_bindings/api.rb:169:in `call'
    /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-bindings-0.0.16/lib/apipie_bindings/resource.rb:14:in `call'
    /opt/theforeman/tfm/root/usr/share/gems/gems/hammer_cli-0.5.1.11/lib/hammer_cli/apipie/command.rb:43:in `send_request'
    /opt/theforeman/tfm/root/usr/share/gems/gems/hammer_cli_foreman-0.5.1.9/lib/hammer_cli_foreman/commands.rb:190:in `send_request'
    /opt/theforeman/tfm/root/usr/share/gems/gems/hammer_cli-0.5.1.11/lib/hammer_cli/apipie/command.rb:34:in `execute'
    /opt/theforeman/tfm/root/usr/share/gems/gems/clamp-1.0.0/lib/clamp/command.rb:68:in `run'
    /opt/theforeman/tfm/root/usr/share/gems/gems/hammer_cli-0.5.1.11/lib/hammer_cli/abstract.rb:22:in `run'
Comment 6 Justin Sherrill 2016-07-20 12:34:49 UTC 
Couple of notes here:

* This is a race condition and doesn't happen 100% of the time
* Resuming the task should resolve the error
Comment 7 Justin Sherrill 2016-07-20 13:04:51 UTC 
Created redmine issue http://projects.theforeman.org/issues/15755 from this bug
Comment 8 Bryan Kearney 2016-07-20 16:04:48 UTC 
Upstream bug assigned to jsherril
Comment 9 Bryan Kearney 2016-07-20 16:04:50 UTC 
Upstream bug assigned to jsherril
Comment 10 Bryan Kearney 2016-07-20 20:04:44 UTC 
Moving to POST since upstream bug http://projects.theforeman.org/issues/15755 has been closed
Comment 11 Sachin Ghai 2016-07-21 07:02:17 UTC 
I tried to validate this with sat62 GA snap21.

This time error message is slightly different. Again, this is occurring while creating product/repo one after another.

Product created
Product name is Sat6Tools and id is: 141
Repository created
Repo name is: sat6tool6 and id is: 1
[............................................................................................................................................] [100%]
New packages: 53 (10.8 MB).
Product created
Product name is Sat6Tools7 and id is: 142
Repository created
Repo name is: sat6tool7 and id is: 2
[............................................................................................................................................] [100%]
New packages: 49 (6.02 MB).
Product created
Product name is Sat6Capsule and id is: 143
Repository created
Repo name is: capsule6 and id is: 3
[............................................................................................................................................] [100%]
New packages: 141 (243 MB).
Could not create the product:
  Task 67db6706-88eb-4936-b240-ead1c664cd07: ActiveRecord::StatementInvalid: PG::Error: ERROR:  current transaction is aborted, commands ignored until end of transaction block
  : SELECT  "katello_pools".* FROM "katello_pools"  WHERE "katello_pools"."cp_id" = '8a90e00c560c1c1c01560c352f4f03af'  ORDER BY "katello_pools"."id" ASC LIMIT 1
Product name is Sat6Capsule7 and id is: 144
Could not create the repository:
  Task 6f5e14f1-372d-48c1-b202-6d9a2fa30bad: Katello::Errors::CandlepinError: Runtime Error RESTEASY001185: Could not find resource for relative : /products//content/1469083632512 of full path: https://localhost:8443/candlepin/products//content/1469083632512?enabled=true at org.jboss.resteasy.core.registry.PathParamSegment.matchPattern:209
Repo name is: capsule7 and id is: 4
Comment 12 Sachin Ghai 2016-07-21 07:03:03 UTC 
exception from logs:
=======================

2016-07-21 02:47:05 [app] [I] Processing by Katello::Api::V2::ProductsController#create as JSON
2016-07-21 02:47:05 [app] [I]   Parameters: {"organization_id"=>1, "name"=>"Sat6Capsule7", "api_version"=>"v2", "product"=>{"name"=>"Sat6Capsule7", "organization_id"=>1}}
2016-07-21 02:47:05 [app] [I] Authorized user admin(Admin User)
2016-07-21 02:47:07 [foreman-tasks/action] [E] PG::Error: ERROR:  current transaction is aborted, commands ignored until end of transaction block
 | : SELECT  "katello_pools".* FROM "katello_pools"  WHERE "katello_pools"."cp_id" = '8a90e00c560c1c1c01560c352f4f03af'  ORDER BY "katello_pools"."id" ASC 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'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/connection_adapters/abstract_adapter.rb:373:in `block in log'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activesupport-4.1.5/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/connection_adapters/abstract_adapter.rb:367:in `log'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/connection_adapters/postgresql_adapter.rb:822:in `exec_no_cache'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/connection_adapters/postgresql/database_statements.rb:137:in `exec_query'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/connection_adapters/postgresql_adapter.rb:954:in `select'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/connection_adapters/abstract/database_statements.rb:24:in `select_all'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/connection_adapters/abstract/query_cache.rb:70:in `select_all'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/querying.rb:39:in `find_by_sql'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/relation.rb:604:in `exec_queries'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/relation.rb:486:in `load'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/relation.rb:231:in `to_a'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/relation/finder_methods.rb:465:in `find_nth_with_limit'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/relation/finder_methods.rb:459:in `find_nth'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/relation/finder_methods.rb:132:in `first'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/protected_attributes-1.1.3/lib/active_record/mass_assignment_security/relation.rb:35:in `first_or_create'
Comment 13 Sachin Ghai 2016-07-21 07:05:04 UTC 
Created attachment 1182332 [details]
complete exception from production.log
Comment 14 Sachin Ghai 2016-07-21 07:07:57 UTC 
this is what I see in candlepin logs:
======================================

2016-07-21 02:47:12,582 [thread=http-bio-8443-exec-5] [req=7890842a-51c2-49ab-800b-424815f279ed, org=] ERROR org.candlepin.common.exceptions.mappers.CandlepinExceptionMapper - Runtime Error RESTEASY001185: Could not find resource for relative : /products//content/1469083632512 of full path: https://localhost:8443/candlepin/products//content/1469083632512?enabled=true at org.jboss.resteasy.core.registry.PathParamSegment.matchPattern:209
org.jboss.resteasy.spi.NotFoundException: RESTEASY001185: Could not find resource for relative : /products//content/1469083632512 of full path: https://localhost:8443/candlepin/products//content/1469083632512?enabled=true
	
at the same time exception in production.log:
==================================
2016-07-21 02:47:12 [app] [E] ForemanTasks::TaskError: Task 6f5e14f1-372d-48c1-b202-6d9a2fa30bad: Katello::Errors::CandlepinError: Runtime Error RESTEASY001185: Could not find resource for relative : /products//content/1469083632512 of full path: https://localhost:8443/candlepin/products//content/1469083632512?enabled=true at org.jboss.resteasy.core.registry.PathParamSegment.matchPattern:209
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.6/lib/foreman_tasks.rb:40:in `block in sync_task'
Comment 15 Sachin Ghai 2016-07-21 07:12:36 UTC 
Created attachment 1182333 [details]
foreman-debug
Comment 16 Sachin Ghai 2016-07-22 06:36:35 UTC 
Verified with sat62 GA snap21.1 RC build.

Issue has been fixed. I created multipl product/repos one after another and don't see the reported issue.

------------------
Product created
Product name is Sat6Tools and id is: 141
Repository created
Repo name is: sat6tool6 and id is: 1
[............................................................................................................................................] [100%]
New packages: 53 (10.8 MB).
Product created
Product name is Sat6Tools7 and id is: 142
Repository created
Repo name is: sat6tool7 and id is: 2
[............................................................................................................................................] [100%]
New packages: 49 (6.02 MB).
Product created
Product name is Sat6Capsule and id is: 143
Repository created
Repo name is: capsule6 and id is: 3
[............................................................................................................................................] [100%]
New packages: 141 (243 MB).
Product created
Product name is Sat6Capsule7 and id is: 144
Repository created
Repo name is: capsule7 and id is: 4
[............................................................................................................................................] [100%]
New packages: 146 (84.1 MB).
Product created
Product name is RHEL6 and id is: 145
Repository created
Repo name is: RHEL68_x86_64 and id is: 5
[............................................................................................................................................] [100%]
New packages: 3855 (3.32 GB).
Product created
Product name is RHEL7 and id is: 146
Repository created
Repo name is: RHEL7_x86_64 and id is: 6
[............................................................................................................................................] [100%]
New packages: 4620 (3.36 GB).
Repository enabled
Comment 17 Bryan Kearney 2016-07-27 11:28:07 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-2016:1501
Note You need to log in before you can comment on or make changes to this bug.