Bugzilla (bugzilla.redhat.com) will be under maintenance for infrastructure upgrades and will not be available on July 31st between 12:30 AM - 05:30 AM UTC. We appreciate your understanding and patience. You can follow status.redhat.com for details.
Bug 1415130 - candlepin - race condition on multiple POST/PUT requests to uri=/candlepin/content/
Summary: candlepin - race condition on multiple POST/PUT requests to uri=/candlepin/co...
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Candlepin
Version: 6.2.7
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: Unspecified
Assignee: satellite6-bugs
QA Contact: Roman Plevka
URL:
Whiteboard:
Depends On: 1440920
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-01-20 11:13 UTC by Roman Plevka
Modified: 2021-06-10 11:51 UTC (History)
8 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1440920 (view as bug list)
Environment:
Last Closed: 2018-09-04 18:02:29 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1363701 1 None None None 2021-06-10 11:26:15 UTC

Internal Links: 1363701

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.


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