Bug 1356622
| Summary: | [hammer] product create fails with error: PG::Error: ERROR: duplicate key value violates unique constraint "index_katello_pools_on_cp_id" | ||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | Red Hat Satellite | Reporter: | Sachin Ghai <sghai> | ||||||||||
| Component: | Repositories | Assignee: | Justin Sherrill <jsherril> | ||||||||||
| Status: | CLOSED ERRATA | QA Contact: | Sachin Ghai <sghai> | ||||||||||
| Severity: | high | Docs Contact: | |||||||||||
| Priority: | unspecified | ||||||||||||
| Version: | 6.2.0 | CC: | bbuckingham, jsherril, sghai | ||||||||||
| Target Milestone: | Unspecified | Keywords: | Triaged | ||||||||||
| Target Release: | Unused | ||||||||||||
| Hardware: | Unspecified | ||||||||||||
| OS: | Unspecified | ||||||||||||
| URL: | http://projects.theforeman.org/issues/15755 | ||||||||||||
| Whiteboard: | |||||||||||||
| 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: | Story Points: | --- | |||||||||||
| Clone Of: | Environment: | ||||||||||||
| Last Closed: | 2016-07-27 11:28:07 UTC | Type: | Bug | ||||||||||
| Regression: | --- | Mount Type: | --- | ||||||||||
| Documentation: | --- | CRM: | |||||||||||
| Verified Versions: | Category: | --- | |||||||||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||||||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||||||||
| Embargoed: | |||||||||||||
| Attachments: |
|
||||||||||||
Hi Sachin, can you attach the foreman-debug or stack trace from the production.log? Created attachment 1180045 [details]
complete stracktrace
Created attachment 1180049 [details]
foreman-debug
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'
Couple of notes here: * This is a race condition and doesn't happen 100% of the time * Resuming the task should resolve the error Created redmine issue http://projects.theforeman.org/issues/15755 from this bug Upstream bug assigned to jsherril Upstream bug assigned to jsherril Moving to POST since upstream bug http://projects.theforeman.org/issues/15755 has been closed 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 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'
Created attachment 1182332 [details]
complete exception from production.log
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' Created attachment 1182333 [details]
foreman-debug
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 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 |
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: