sbrueseke commented on issue #13399:
URL: https://github.com/apache/cloudstack/issues/13399#issuecomment-5193866741
@DaanHoogland we are getting closer. It looks like it is always a
VOLUME.CREATE event which causes usage to fail.
grep -nE "Duplicate entry|IntegrityConstraint|Failed to create
usage|Exception" /var/log/cloudstack/usage/usage.log
```
195366:2026-08-05 16:15:10,986 ERROR
[usage.dao.UsageVolumeDaoImpl_EnhancerByCloudStack_3338cf7d] (Usage-Job-1:[])
(logid:) DB Exception on: HikariProxyPreparedStatement@410370443 wrapping
com.mysql.cj.jdbc.ServerPreparedStatement[56]: INSERT INTO usage_volume
(usage_volume.zone_id, usage_volume.account_id, usage_volume.domain_id,
usage_volume.volume_id, usage_volume.disk_offering_id,
usage_volume.template_id, usage_volume.size, usage_volume.vm_id,
usage_volume.created, usage_volume.deleted) VALUES (1, 2, 1, 2007, 6, 316,
107374182400, 1874, '2026-08-05 09:40:05', NULL)
java.sql.SQLIntegrityConstraintViolationException: Duplicate entry
'2007-2026-08-05 09:40:05' for key 'usage_volume.id'
195367: at
com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:118)
195368: at
com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122)
195401:2026-08-05 16:15:10,986 DEBUG [db.Transaction.Transaction]
(Usage-Job-1:[]) (logid:) Rolling back the transaction: Time = 2242 Name =
-UsageManagerImpl.parse:693-UsageManagerImpl.runInContextInternal:427-UsageManagerImpl$1.runInContext:361-ManagedContextRunnable$1.run:49-DefaultManagedContext$1.call:56-DefaultManagedContext.callWithContext:103-DefaultManagedContext.runWithContext:53-ManagedContextRunnable.run:46-UsageManagerImpl.run:366-Executors$RunnableAdapter.call:539-FutureTask.runAndReset:305-ScheduledThreadPoolExecutor$ScheduledFutureTask.run:305;
called by
-TransactionLegacy.rollback:905-TransactionLegacy.removeUpTo:848-TransactionLegacy.close:672-TransactionContextBuilder.interceptException:63-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:131-UsageManagerImpl.createVolumeHelperEvent:1483-UsageManagerImpl.createHelperRecord:959-UsageManagerImpl.parse:711-UsageManagerImpl.runInContextInternal:427-UsageManagerImpl$1.runInContext:361-ManagedContex
tRunnable$1.run:49-DefaultManagedContext$1.call:56
195402:2026-08-05 16:15:10,991 WARN
[cloud.usage.UsageManagerImpl_EnhancerByCloudStack_3727543e] (Usage-Job-1:[])
(logid:) Failed to create usage event id: 826827 type: VOLUME.CREATE due to
Entity already exists javax.persistence.EntityExistsException: Entity already
exists
195403: at
com.cloud.utils.db.GenericDaoBase.handleEntityExistsException(GenericDaoBase.java:892)
195427:Caused by: java.sql.SQLIntegrityConstraintViolationException:
Duplicate entry '2007-2026-08-05 09:40:05' for key 'usage_volume.id'
195428: at
com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:118)
195429: at
com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122)
```
SELECT id, type, resource_id, created, processed FROM usage_event WHERE
processed = 0
```
+--------+-------------------------+-------------+---------------------+-----------+
| id | type | resource_id | created |
processed |
+--------+-------------------------+-------------+---------------------+-----------+
| 826822 | BACKUP.USAGE.METRIC | 1693 | 2026-08-05 09:39:00 |
0 |
| 826823 | BACKUP.USAGE.METRIC | 1182 | 2026-08-05 09:39:00 |
0 |
| 826824 | BACKUP.USAGE.METRIC | 963 | 2026-08-05 09:39:00 |
0 |
| 826825 | BACKUP.USAGE.METRIC | 1485 | 2026-08-05 09:39:00 |
0 |
| 826826 | BACKUP.USAGE.METRIC | 474 | 2026-08-05 09:39:00 |
0 |
| 826827 | VOLUME.CREATE | 2007 | 2026-08-05 09:40:05 |
0 |
+--------+-------------------------+-------------+---------------------+-----------+
```
SELECT id, type, resource_id, created, processed FROM
cloud_usage.usage_event WHERE resource_id = 2007 ORDER BY id;
```
+--------+---------------------+-------------+---------------------+-----------+
| id | type | resource_id | created |
processed |
+--------+---------------------+-------------+---------------------+-----------+
| 10042 | SNAPSHOT.ON_PRIMARY | 2007 | 2024-10-01 00:41:56 |
1 |
| 10085 | SNAPSHOT.CREATE | 2007 | 2024-10-01 01:41:13 |
1 |
| 10698 | SNAPSHOT.DELETE | 2007 | 2024-10-08 01:57:17 |
1 |
| 66660 | NET.RULEADD | 2007 | 2025-09-29 10:31:48 |
1 |
| 67980 | NET.RULEDELETE | 2007 | 2025-10-06 09:43:21 |
1 |
| 826827 | VOLUME.CREATE | 2007 | 2026-08-05 09:40:05 |
0 |
| 826834 | VOLUME.DELETE | 2007 | 2026-08-05 09:43:04 |
1 |
+--------+---------------------+-------------+---------------------+-----------+
```
It looks like usage cron is doing the INSERT twice:
grep -i "usage_volume" /var/lib/mysql/mgmt-server.log | grep 2007
```
2026-08-05T15:15:10.854502Z 98385 Execute SELECT usage_volume.id,
usage_volume.zone_id, usage_volume.account_id, usage_volume.domain_id,
usage_volume.volume_id, usage_volume.disk_offering_id,
usage_volume.template_id, usage_volume.size, usage_volume.vm_id,
usage_volume.created, usage_volume.deleted FROM usage_volume WHERE
usage_volume.account_id = 2 AND usage_volume.volume_id = 2007 AND
usage_volume.deleted IS NULL
2026-08-05T15:15:10.856192Z 98385 Execute INSERT INTO usage_volume
(usage_volume.zone_id, usage_volume.account_id, usage_volume.domain_id,
usage_volume.volume_id, usage_volume.disk_offering_id,
usage_volume.template_id, usage_volume.size, usage_volume.vm_id,
usage_volume.created, usage_volume.deleted) VALUES (1, 2, 1, 2007, 6, 316,
107374182400, NULL, '2026-08-05 09:40:05', NULL)
2026-08-05T15:15:10.860104Z 98385 Execute INSERT INTO usage_volume
(usage_volume.zone_id, usage_volume.account_id, usage_volume.domain_id,
usage_volume.volume_id, usage_volume.disk_offering_id,
usage_volume.template_id, usage_volume.size, usage_volume.vm_id,
usage_volume.created, usage_volume.deleted) VALUES (1, 2, 1, 2007, 6, 316,
107374182400, 1874, '2026-08-05 09:40:05', NULL)
```
Claude tells me that this is a regression from 4.22.0, because the vm_id was
added to a volume usage record.
There is a broken case EventTypes.EVENT_VOLUME_CREATE in
usage/src/main/java/com/cloud/usage/UsageManagerImpl.java.
The `listByVolumeId(...) → deleteExistingVolumeUsage(...)` check runs before
both inserts and only finds rows that have already been committed. However, the
two problematic inserts are produced by the same code block immediately one
after another within the same transaction — and the safeguard doesn't protect
against that.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
