Bug 1415130

Summary:	candlepin - race condition on multiple POST/PUT requests to uri=/candlepin/content/
Product:	Red Hat Satellite	Reporter:	Roman Plevka <rplevka>
Component:	Candlepin	Assignee:	satellite6-bugs <satellite6-bugs>
Status:	CLOSED WONTFIX	QA Contact:	Roman Plevka <rplevka>
Severity:	high	Docs Contact:
Priority:	high
Version:	6.2.7	CC:	bkearney, hmore, igreen, jcallaha, mverma, rplevka, tcarlin, tomerle
Target Milestone:	Unspecified	Keywords:	Triaged
Target Release:	Unused
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:
Clones:	1440920 (view as bug list)		Environment:
Last Closed:	2018-09-04 18:02:29 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:
Bug Depends On:	1440920
Bug Blocks:

Description Roman Plevka 2017-01-20 11:13:24 UTC

Description of problem:
Duplicate key violation error is triggered if there are concurrent tasks POSTing to uri=/candlepin/content/ at the same time:

<pre>
2017-01-06 12:03:56,378 [thread=http-8443-6] [req=...0653, org=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2017-01-06 12:03:56,379 [thread=http-8443-6] [req=...0653, org=] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=2
2017-01-06 12:03:57,076 [thread=http-8443-6] [req=...9f2d, org=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=POST, uri=/candlepin/content/
2017-01-06 12:03:57,078 [thread=http-8443-4] [req=...6e50, org=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=POST, uri=/candlepin/content/
2017-01-06 12:03:57,084 [thread=http-8443-6] [req=...9f2d, org=] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=8
2017-01-06 12:03:57,090 [thread=http-8443-4] [req=...6e50, org=] WARN  org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: 23505
2017-01-06 12:03:57,091 [thread=http-8443-4] [req=...6e50, org=] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - ERROR: duplicate key value violates unique constraint "cp_content_pkey"
2017-01-06 12:03:57,105 [thread=http-8443-4] [req=...6e50, org=] ERROR org.candlepin.common.exceptions.mappers.CandlepinExceptionMapper - Runtime Error could not execute statement at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse:2,102
org.hibernate.exception.ConstraintViolationException: could not execute statement
...
(see attachments for a complete log)
</pre>

Version-Release number of selected component (if applicable):
satellite 6.2.7-1
candlepin-0.9.54.15-1.el7.noarch

How reproducible:
this is hard to 100% reproduce from katello, 
but having a many concurrent `repository create` tasks should eventually throw the error. (the goal is to get the concurrent POST requests to candlepin which is just 1 of many tasks performed during the repo create).
Sending the requests directly to candlepin manually should do.

Actual results:
Runtime Error could not execute statement at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse:2,102

Expected results:
no race condition happens, task finishes successfully

Additional info:

Comment 2 Barnaby Court 2017-01-20 16:24:19 UTC

Were these two parallel posts to create a content object with the same id and/or label?

Comment 4 Roman Plevka 2017-01-20 23:05:49 UTC

The 2 parallel posts used different orgs, different product ids, urls and names (labels).

looking at the robottelo masterlog, the failed test executed the hammer repo create command 2 seconds before another test (which i believe is the one that caused the collision) which uses the API call to create the repo which seemed to be faster and finished before the hammer command completed.

so the chronology was:
TEST1 - 2017-01-06 12:03:53 - robottelo.ssh - DEBUG - >>> LANG=en_US.UTF-8  hammer -v -u admin -p changeme --output=csv repository create --product-id="61" --name="mAazlFJfFfCEDTK" --publish-via-http="true" --url="http://inecas.fedorapeople.org/fakerepos/zoo3/" --content-type="yum"

TEST2 - 2017-01-06 12:03:55 - robottelo - DEBUG - Started Test: DRPMRepositoryTestCase/test_positive_sync_publish_cv

TEST2 - 2017-01-06 12:03:55 - nailgun.client - DEBUG - Making HTTP POST request to https://qe-sat62-rhel6.satqe.lab.eng.rdu2.redhat.com/katello/api/v2/repositories with options {'verify': False, 'auth': ('admin', 'changeme'), 'headers': {'content-type': 'application/json'}} and data {"product_id": 60, "content_type": "yum", "url": "https://repos.fedorapeople.org/repos/pulp/pulp/fixtures/drpm/", "name": "LBuDilEzuEq"}.

TEST2 - 2017-01-06 12:03:57 - nailgun.client - DEBUG - Received HTTP 200 response:   {"content_type":"yum","docker_upstream_name":null,"mirror_on_sync":


TEST1 - 2017-01-06 12:03:57 - robottelo.ssh - DEBUG - <<< stderr
[ERROR 2017-01-06 12:03:57 Exception] Task 6f37d911-1a1e-4c27-8db9-92ed4c3b8781: Katello::Errors::Candlepin...{the rest of the error fromdescription}

Comment 5 Roman Plevka 2017-01-20 23:46:46 UTC

executing a lot of asynchronous `hammer repository create` commands using a simple loop:

`for i in {100..200}; do hammer --csv -u admin -p changeme repository create --name foo-${i} --product-id 17 --organization-id 1 --content-type yum --url http://foo.bar/baz; done`

i wasn't able to reproduce the above traceback, however i got another one with different key:

2017-01-20 18:39:48,874 [thread=http-8443-1] [req=17425844-2aa8-4f28-96d8-5ebe72c3062d, org=Default_Organization] WARN  org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: 23505
2017-01-20 18:39:48,874 [thread=http-8443-1] [req=17425844-2aa8-4f28-96d8-5ebe72c3062d, org=Default_Organization] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - ERROR: duplicate key value violates unique constraint "cp_env_cnt_env_id_cntid_ky"
2017-01-20 18:39:48,877 [thread=http-8443-1] [req=17425844-2aa8-4f28-96d8-5ebe72c3062d, org=Default_Organization] ERROR org.candlepin.common.exceptions.mappers.CandlepinExceptionMapper - Runtime Error could not execute statement at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse:2,102
org.hibernate.exception.ConstraintViolationException: could not execute statement
        at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:129) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:125) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:110) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:136) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:58) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3067) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3509) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:88) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.engine.spi.ActionQueue.execute(ActionQueue.java:377) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:369) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:286) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:339) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:52) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1234) ~[hibernate-core-4.2.5.Final.jar:4.2.5.Final]
        at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:996) ~[hibernate-entitymanager-4.2.5.Final.jar:4.2.5.Final]
        at org.candlepin.model.AbstractHibernateCurator.flush(AbstractHibernateCurator.java:371) ~[AbstractHibernateCurator.class:na]
        at org.candlepin.model.AbstractHibernateCurator.save(AbstractHibernateCurator.java:366) ~[AbstractHibernateCurator.class:na]
        at org.candlepin.model.AbstractHibernateCurator.create(AbstractHibernateCurator.java:112) ~[AbstractHibernateCurator.class:na]
        at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:66) ~[guice-persist-3.0.jar:na]
        at org.candlepin.resource.EnvironmentResource.promoteContent(EnvironmentResource.java:207) ~[EnvironmentResource.class:na]
        at sun.reflect.GeneratedMethodAccessor226.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_121]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_121]
        at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:168) ~[resteasy-jaxrs-2.3.10.Final.jar:na]
        at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:269) ~[resteasy-jaxrs-2.3.10.Final.jar:na]
        at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:227) ~[resteasy-jaxrs-2.3.10.Final.jar:na]
        at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:216) ~[resteasy-jaxrs-2.3.10.Final.jar:na]
...

(where 100 async calls is probably needlessly much to reproduce this)

- if you think, this should be reported as a standalone bug, just tell me, I'll do that

Comment 6 Barnaby Court 2017-01-23 19:10:28 UTC

For the issue in comment 5, can you provide more of the Candlepin log file around that error. I am looking specifically to see what calls where made concurrently at that point. My suspicion is that there were multiple calls to add the same content set to an environment.

Comment 8 Roman Plevka 2017-01-30 12:39:03 UTC

multiple POST/PUT requests to uri=/candlepin/content/ might not be the issue.
I just hit the same issue on creating multiple products, this time the last 2 transactions were:

2017-01-27 19:22:49,544 [thread=http-8443-5] [req=...7016dbf243c5, org=] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - ERROR: duplicate key value violates unique constraint "cp_product_pkey"
2017-01-27 19:22:49,562 [thread=http-8443-1] [req=...be317ca63fcc, org=] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=62
2017-01-27 19:22:49,572 [thread=http-8443-5] [req=...7016dbf243c5, org=] ERROR org.candlepin.common.exceptions.mappers.CandlepinExceptionMapper - Runtime Error could not execute statement at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse:2,102
org.hibernate.exception.ConstraintViolationException: could not execute statement

Comment 9 Roman Plevka 2017-01-30 12:40:27 UTC

oops, omitted the logs before the error:

2017-01-27 19:22:49,008 [thread=http-8443-5] [req=428fb27a41ff, org=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/status
2017-01-27 19:22:49,013 [thread=http-8443-5] [req=428fb27a41ff, org=] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=5
2017-01-27 19:22:49,442 [thread=http-8443-5] [req=7016dbf243c5, org=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=POST, uri=/candlepin/products/
2017-01-27 19:22:49,500 [thread=http-8443-1] [req=be317ca63fcc, org=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=POST, uri=/candlepin/products/
<put the error logs here>

Comment 10 Barnaby Court 2017-01-30 16:10:06 UTC

For the two product creates that collided, do you have the body for the two post statements?

Comment 12 Roman Plevka 2017-02-23 14:00:43 UTC

automation keeps hitting this at various places, while creating repos concurrently:

2017-02-21 08:28:34,237 [thread=http-8443-8] [req=...222, org=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=POST, uri=/candlepin/content/
2017-02-21 08:28:34,237 [thread=http-8443-10] [req=...c8b, org=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=POST, uri=/candlepin/content/
2017-02-21 08:28:34,238 [thread=http-8443-7] [req=...6ef, org=] INFO  org.candlepin.common.filter.LoggingFilter - Request: verb=GET, uri=/candlepin/subscriptions/ff8080815a60d21c015a60d77d0200e7
2017-02-21 08:28:34,242 [thread=http-8443-8] [req=...222, org=] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=5
2017-02-21 08:28:34,250 [thread=http-8443-7] [req=...6ef, org=] INFO  org.candlepin.common.filter.LoggingFilter - Response: status=200, content-type="application/json", time=12
2017-02-21 08:28:34,251 [thread=http-8443-10] [req=...c8b, org=] WARN  org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 0, SQLState: 23505
2017-02-21 08:28:34,251 [thread=http-8443-10] [req=...c8b, org=] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - ERROR: duplicate key value violates unique constraint "cp_content_pkey"
2017-02-21 08:28:34,266 [thread=http-8443-10] [req=...c8b, org=] ERROR org.candlepin.common.exceptions.mappers.CandlepinExceptionMapper - Runtime Error could not execute statement at org.postgresql.core.v3.QueryExecutorImpl
...

Comment 13 Thom Carlin 2017-03-13 16:35:57 UTC

Also seeing this in Sat 6.2.8 when enabling multiple Red Hat Repositories within a few seconds

Comment 14 Thom Carlin 2017-03-13 16:42:28 UTC

In my case, SCL 7.3, then SCL 7Server

Comment 20 Bryan Kearney 2018-09-04 18:02:29 UTC

Thank you for your interest in Satellite 6. We have evaluated this request, and we do not expect this to be implemented in the product in the foreseeable future. We are therefore closing this out as WONTFIX. If you have any concerns about this, please feel free to contact Rich Jerrido or Bryan Kearney. Thank you.