Bug 1009536

Summary:	Reoccurring Duplicate entry in cp_pool exception
Product:	[Community] Candlepin	Reporter:	Dennis Crissman <dcrissman>
Component:	candlepin	Assignee:	candlepin-bugs
Status:	CLOSED CURRENTRELEASE	QA Contact:	Katello QA List <katello-qa-list>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	0.9	CC:	ckozak, dcrissman, dgoodwin
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2014-04-04 12:31:19 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:

Description Dennis Crissman 2013-09-18 15:19:22 UTC

This exception appears at various times in various environments for unknown reasons and fills up the log files and prevents refreshes from finishing for this owner.



-04:00]  [app:] ERROR org.hibernate.jdbc.AbstractBatcher - Exception executing batch: 
.556049-04:00]  [app:java.lang.RuntimeException] java.sql.BatchUpdateException: Duplicate entry '3013983-master' for key 'subscriptionId'
.556056-04:00]  [app:]    at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:2443)
.556056-04:00]  [app:]    at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
.556059-04:00]  [app:]    at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
.556059-04:00]  [app:]    at org.hibernate.jdbc.AbstractBatcher.prepareStatement(AbstractBatcher.java:114)
.556061-04:00]  [app:]    at org.hibernate.jdbc.AbstractBatcher.prepareStatement(AbstractBatcher.java:109)
.556061-04:00]  [app:]    at org.hibernate.jdbc.AbstractBatcher.prepareBatchStatement(AbstractBatcher.java:244)
.556241-04:00]  [app:]    at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2242)
.556241-04:00]  [app:]    at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2678)
.556265-04:00]  [app:]    at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:79)
.556265-04:00]  [app:]    at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:278)
.556268-04:00]  [app:]    at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:262)
.556268-04:00]  [app:]    at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:166)
.556271-04:00]  [app:]    at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321)
.556271-04:00]  [app:]    at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:50)
.556274-04:00]  [app:]    at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1030)
.556274-04:00]  [app:]    at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:367)
.556277-04:00]  [app:]    at org.hibernate.transaction.JDBCTransaction.commit(JDBCTransaction.java:137)
.556277-04:00]  [app:]    at org.hibernate.ejb.TransactionImpl.commit(TransactionImpl.java:54)
.556279-04:00]  [app:]    at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:71)
.556279-04:00]  [app:]    at com.google.inject.internal.InterceptorStackCallback$InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:72)
.556282-04:00]  [app:]    at com.google.inject.internal.InterceptorStackCallback.intercept(InterceptorStackCallback.java:52)
.556282-04:00]  [app:]    at org.candlepin.pinsetter.tasks.RefreshPoolsJob$$EnhancerByGuice$$c2e08334.execute(<generated>)
.556285-04:00]  [app:]    at org.candlepin.pinsetter.core.TransactionalPinsetterJob.execute(TransactionalPinsetterJob.java:50)
.556285-04:00]  [app:]    at org.quartz.core.JobRunShell.run(Unknown Source)
.556287-04:00]  [app:]    at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(Unknown Source)
.556548-04:00]  [app:]    aused by: java.sql.BatchUpdateException: Duplicate entry '3013983-master' for key 'subscriptionId'
.556548-04:00]  [app:]    at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2054)
.556553-04:00]  [app:]    at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1467)
.556553-04:00]  [app:]    at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:2429)
.556556-04:00]  [app:]    ... 24 more
.556556-04:00]  [app:]    aused by: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Duplicate entry '3013983-master' for key 'subscriptionId'
.556559-04:00]  [app:]    at sun.reflect.GeneratedConstructorAccessor698.newInstance(Unknown Source)
.556559-04:00]  [app:]    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
.556562-04:00]  [app:]    at java.lang.reflect.Constructor.newInstance(Constructor.java:532)
.556562-04:00]  [app:]    at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
.556565-04:00]  [app:]    at com.mysql.jdbc.Util.getInstance(Util.java:386)
.556565-04:00]  [app:]    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1040)
.556638-04:00]  [app:]    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4074)
.556638-04:00]  [app:]    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4006)
.556643-04:00]  [app:]    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)
.556643-04:00]  [app:]    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2629)
.556730-04:00]  [app:]    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2719)
.556730-04:00]  [app:]    at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
.556735-04:00]  [app:]    at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2450)
.556804-04:00]  [app:]    at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2006)
.556804-04:00]  [app:]    ... 26 more




mysql> select * from cp_pool where subscriptionId = '3013983';
+----------------------------------+---------------------+---------------------+---------------+--------------------+----------------+---------------------+-----------+---------------------------------------------------+----------+----------------------+---------------------+----------------+----------------------------------+----------------------+--------------------+---------+-------------+------------------+--------------------+---------------+-------------------+
| id                               | created             | updated             | accountNumber | activeSubscription | contractNumber | endDate             | productId | productName                                       | quantity | restrictedToUsername | startDate           | subscriptionId | owner_id                         | sourceEntitlement_id | subscriptionSubKey | version | orderNumber | derivedProductId | derivedProductName | sourceStackId | sourceConsumer_id |
+----------------------------------+---------------------+---------------------+---------------+--------------------+----------------+---------------------+-----------+---------------------------------------------------+----------+----------------------+---------------------+----------------+----------------------------------+----------------------+--------------------+---------+-------------+------------------+--------------------+---------------+-------------------+
| 8a9bf98b4113267f01413145e3234705 | 2013-09-18 09:32:45 | 2013-09-18 09:32:45 | 5353302       |                   | 10274518       | 2014-09-17 23:59:59 | MCT0988   | Red Hat Enterprise Linux, Basic (up to 2 sockets) |        8 | NULL                 | 2013-09-18 00:00:00 | 3013983        | 8a9bf98b4113267f01413145cecf3e43 | NULL                 | derived            |       0 | NULL        | NULL             | NULL               | NULL          | NULL              |
| 8a9bf98b4113267f01413145e2fa46df | 2013-09-18 09:32:45 | 2013-09-18 09:32:45 | 5353302       |                   | 10274518       | 2014-09-17 23:59:59 | MCT0988   | Red Hat Enterprise Linux, Basic (up to 2 sockets) |        2 | NULL                 | 2013-09-18 00:00:00 | 3013983        | 8a9bf98b4113267f01413145cecf3e43 | NULL                 | master             |       0 | NULL        | NULL             | NULL               | NULL          | NULL              |
+----------------------------------+---------------------+---------------------+---------------+--------------------+----------------+---------------------+-----------+---------------------------------------------------+----------+----------------------+---------------------+----------------+----------------------------------+----------------------+--------------------+---------+-------------+------------------+--------------------+---------------+-------------------+
2 rows in set (3.09 sec)



mysql> select * from cp_owner where id = '8a9bf98b4113267f01413145cecf3e43';
+----------------------------------+---------------------+---------------------+-------------+---------+--------------+---------------+---------------------+-------------+
| id                               | created             | updated             | displayName | account | parent_owner | contentPrefix | defaultServiceLevel | upstream_id |
+----------------------------------+---------------------+---------------------+-------------+---------+--------------+---------------+---------------------+-------------+
| 8a9bf98b4113267f01413145cecf3e43 | 2013-09-18 09:32:40 | 2013-09-18 09:32:40 | 7036698     | 7036698 | NULL         | NULL          | NULL                | NULL        |
+----------------------------------+---------------------+---------------------+-------------+---------+--------------+---------------+---------------------+-------------+
1 row in set (0.01 sec)

Comment 1 Dennis Crissman 2013-09-18 20:19:01 UTC

This is from a different run, but interesting that the cp_job table marks it as complete (3) rather than a 5.

| refresh_pools_cc7ee66a-64b8-4e68-ae60-1eb9349d4317 | 2013-09-18 16:13:07 | 2013-09-18 16:16:09 | 2013-09-18 16:13:08 | java.sql.BatchUpdateException: Duplicate entry '3013988-master' for key 'subscriptionId'  | 2013-09-18 16:13:07 |     3 | async group | candlepin_admin      | 7036663                              |          0 |

Comment 2 Dennis Crissman 2013-09-30 14:27:46 UTC

The manual solution to resolve this issue, is to delete the pools for the offending subscription, then to run a pool refresh.

Comment 3 Devan Goodwin 2013-10-01 12:43:00 UTC

Delete the pool or the outstanding entitlements?

Also how exactly are you doing the delete?

And when you mentioned manually triggering a refresh pools, how exactly is that being run?

Comment 4 Devan Goodwin 2013-10-01 12:46:17 UTC

Sorry confused issues, wrong comment above.

Comment 5 Dennis Crissman 2013-10-01 12:55:33 UTC

(For the record, this particular instance was in stage, I do not have the ability to delete pools in prod myself)

Deleted the pool, no entitlements were deleted to the best of my knowledge.

I used the candlepin api: DELETE /candlepin/pools/<pool_uuid>

For the manual refresh, I again simply mean a direct call to api: PUT /candlepin/owners/<owner_key>/subscriptions?auto_create_owner=true

Comment 6 Carter Kozak 2014-04-04 12:31:19 UTC

> BatchUpdateException: Duplicate entry '3013983-master' for key 'subscriptionId'

Judging from this and the date posted, this problem is already solved.  We don't use a unique constraint on subscriptionId/subscriptionKey.  We probably should enforce uniqueness though, but they're nullable so it'll be a bigger change.

If this is still occurring, please let me know.