Note: This is a beta release of Red Hat Bugzilla 5.0. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Also email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback here.
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 6
Classification: Red Hat
Component: Repositories
Version: 6.2.0
Hardware: Unspecified
OS: Unspecified
unspecified
high vote
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-04-01 20:27 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


Attachments (Terms of Use)
complete stracktrace (deleted)
2016-07-15 06:24 UTC, Sachin Ghai
no flags Details
foreman-debug (deleted)
2016-07-15 06:35 UTC, Sachin Ghai
no flags Details
complete exception from production.log (deleted)
2016-07-21 07:05 UTC, Sachin Ghai
no flags Details
foreman-debug (deleted)
2016-07-21 07:12 UTC, Sachin Ghai
no flags Details


Links
System ID Priority Status Summary Last Updated
Foreman Issue Tracker 15755 None None None 2016-07-20 14:01:58 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@redhat.com

Comment 9 Bryan Kearney 2016-07-20 16:04:50 UTC
Upstream bug assigned to jsherril@redhat.com

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.