Alpha162 commented on issue #13399:
URL: https://github.com/apache/cloudstack/issues/13399#issuecomment-5296293522
**Same issue on 4.22.1.0. I think we have the root cause, with heavy
assistance from Claude — there are two defects compounding, and the trigger is
unconditional.**
### TL;DR
`createVolumeHelperEvent()` issues **two** inserts into `usage_volume` for a
single `VOLUME.CREATE`, with identical `(volume_id, created)`. The table's
unique key is `(volume_id, created)`. The second insert can therefore **never**
succeed. `GenericDaoBase.persist()` then leaves the caller's transaction
unbalanced on the exception path, so the batch's `processed` flags are silently
discarded — which pins the aggregation start date forever via the rewind in
`parse()`.
The `catch (EntityExistsException)` in `createHelperRecord()` is intended to
log-and-continue, but by the time it runs the enclosing transaction is already
unrecoverable, so continuing achieves nothing.
### Defect 1 — the duplicate insert is guaranteed by construction
`UsageManagerImpl.createVolumeHelperEvent()`, `EVENT_VOLUME_CREATE` branch
(4.22.1.0, ~L1478-1486):
volumeVO = new UsageVolumeVO(volId, ..., null, event.getSize(),
event.getCreateDate(), null);
_usageVolumeDao.persist(volumeVO); // vm_id = NULL
if (event.getVmId() != null) {
volumeVO = new UsageVolumeVO(volId, ..., event.getVmId(),
event.getSize(), event.getCreateDate(), null);
_usageVolumeDao.persist(volumeVO); // vm_id set,
SAME volId + createDate
}
Against the current schema:
UNIQUE KEY `id` (`volume_id`,`created`)
`vm_id` and the second `persist()` were added in 4.22.1; the unique key was
not widened to include it. Insert #1 succeeds, insert #2 always violates the
constraint.
**Trigger: any `VOLUME.CREATE` where `vm_id` is set — i.e. every ROOT disk,
i.e. every VM creation.** We do **not** run Linstor, so this is not
plugin-specific.
### Defect 2 — `persist()` leaves the caller's transaction unbalanced
`GenericDaoBase.persist()` (~L1625-1682):
final TransactionLegacy txn = TransactionLegacy.currentTxn(); // the
CALLER's transaction
try {
txn.start(); // pushes a START_TXN nesting level
...
pstmt.executeUpdate(); // throws here
...
txn.commit(); // never reached
} catch (final SQLException e) {
logger.error("DB Exception on: " + pstmt, e);
handleEntityExistsException(e); // throws EntityExistsException
throw new CloudRuntimeException("Unable to persist on DB, due to: "
+ e.getLocalizedMessage());
}
// no finally — the pushed nesting level is never released
`persist()` does not own a transaction; it joins the caller's (`usageTxn`,
opened in `parse()`). With no `finally`, the nesting level pushed by
`txn.start()` is never popped when `executeUpdate()` throws. `parse()`'s
`usageTxn.commit()` then finds the transaction unbalanced, and
`TransactionLegacy.commit()` (L723-727) no-ops:
public boolean commit() {
if (!_txn) {
LOGGER.warn("txn: Commit called when it is not a transaction: "
+ buildName());
return false;
}
Everything in that transaction is discarded — including the
`event.setProcessed(true)` updates for the whole batch, and the *successful*
insert #1.
### Defect 3 (arguably by design) — the rewind has no lower bound
`parse()` (~L697-703):
Date oldestEventDate = events.get(0).getCreateDate();
if (oldestEventDate.getTime() < startDateMillis) {
startDateMillis = oldestEventDate.getTime();
startDate = new Date(startDateMillis);
}
`events` is `listLatestEvents()` — `WHERE processed = 0 AND created <= ?
ORDER BY createDate ASC`. Because defect 2 means those flags never persist, and
this rewind only ever moves *backwards*, a single permanently-unprocessed event
pins the aggregation start indefinitely. The checkpoint lookup itself
(`getLastJobSuccessDateMillis()`) is correct — its result is simply overwritten.
### Evidence from our environment
Unusually clean, because this happened on a brand-new cluster: the six stuck
events are **ids 1-6, the first six events the deployment ever emitted**.
SELECT COUNT(*), SUM(processed=0), MIN(CASE WHEN processed=0 THEN
created END)
FROM cloud_usage.usage_event;
-- 319 total, 6 unprocessed, oldest 2026-06-04 16:50:51
SELECT COUNT(*) AS successes, MAX(start_millis) FROM
cloud_usage.usage_job WHERE success = 1;
-- 1678 successes, MAX(start_millis) = 1780591851000 = 2026-06-04
16:50:51
1,678 successful jobs, and `MAX(start_millis)` never once advanced past the
oldest unprocessed event. `exec_time` on recent jobs is **2,555,055 ms (42.6
min)** of every hour, growing by 24 hourly periods per day.
**The insert rolls back — confirmed:**
SELECT * FROM cloud_usage.usage_volume WHERE volume_id = <vol>; --
Empty set
CHECK TABLE cloud_usage.usage_volume; -- OK
The colliding row does not exist at rest and the index is sound.
`usage_volume` holds 33 rows with `AUTO_INCREMENT=3481` — the gap is ~1,670
failed inserts consuming IDs, one per hourly run since June.
**Log timing places the failure at the batch commit, not the final one:**
00:00:24,103 INFO Parsing usage records between [...23:00:00] and
[...23:59:59]
00:00:24,521 ERROR DB Exception ... Duplicate entry '<vol>-2026-06-04
19:45:04' for key 'usage_volume.id'
00:00:24,523 WARN Failed to create usage event id: 6 type:
VOLUME.CREATE due to Entity already exists
00:00:24,651 WARN txn: Commit called when it is not a transaction:
00:42:54,429 INFO usage job complete
The commit warning fires 128 ms after the constraint violation and **42
minutes before the job completes**, placing it at the `usageTxn.commit()`
following the event loop rather than the job's final commit.
**Duplication is exactly quantifiable.** For any single hour, every
duplicate count is an exact multiple of the number of runs that have covered
it. Example for one hour that had been re-aggregated 61 times:
SELECT account_id, usage_type, start_date, end_date, COUNT(*) AS copies
FROM cloud_usage.cloud_usage
WHERE start_date >= '<hour>' AND start_date < '<hour+1>'
GROUP BY account_id, usage_type, start_date, end_date ORDER BY copies
DESC;
-- 793 (=61x13), 732 (=61x12), 244 (=61x4), 183 (=61x3), 122 (=61x2), 61
(=61x1)
i.e. `copies = resource_instances x re-aggregations`. `cloud_usage`
currently holds **54,460,998 rows / 14.08 GB** where roughly 150 K rows are
genuine, growing ~3.2 M rows (~830 MB) per day and accelerating.
### Why the existing workaround only lasts a few days
Re: the report above that clearing the stuck state works and then regresses
"after some days" — that isn't time-based. Because defect 1 fires on **every**
`VOLUME.CREATE` with `vm_id` set, the next VM created re-wedges it
deterministically. On a cluster with regular instance churn it will recur
almost immediately.
### Suggested fixes
1. **`GenericDaoBase.persist()` needs a `finally` that releases the nesting
level.** This is the highest-value fix — it repairs a whole class of bug, since
any caught `EntityExistsException` anywhere in the codebase currently leaves
the caller's transaction silently unrecoverable while the caller believes it
recovered.
2. **Reconcile `createVolumeHelperEvent()` with the schema.** Either widen
the unique key to `(volume_id, created, vm_id)`, or don't emit two rows for the
same `(volume_id, created)`. **Open question for maintainers:** does
`VolumeUsageParser` aggregate both rows? If so, widening the key would swap a
wedged usage server for silently double-counted volume usage, which seems
worse. Someone who knows the intent behind adding `vm_id` should decide this.
3. **Bound the rewind in `parse()`** so a permanently-unprocessable event
cannot pin aggregation indefinitely — defence in depth, independent of 1 and 2.
### Operator workaround (mitigation, not a fix)
UPDATE cloud_usage.usage_event SET processed = 1 WHERE id IN (<stuck
ids>);
Do **not** delete the rows — `getMostRecentEventId()` is `ORDER BY id DESC
LIMIT 1` over the whole table, so emptying it returns 0 and triggers
`COPY_ALL_EVENTS`, re-copying every event with `processed = 0`.
Worth monitoring the age of the oldest unprocessed event, since this will
recur:
SELECT COALESCE(TIMESTAMPDIFF(MINUTE, MIN(created), NOW()), 0)
FROM cloud_usage.usage_event WHERE processed = 0;
### Environment
- CloudStack **4.22.1.0** (EL9 packages, unmodified upstream build —
stack-trace line numbers match the `4.22.1.0` tag exactly across
`UsageManagerImpl`, `GenericDaoBase` and `TransactionLegacy`)
- MySQL 8.x / InnoDB
- `usage.stats.job.aggregation.range = 60`, `usage.stats.job.exec.time =
00:15`, both timezones UTC
- `usage.sanity.check.interval` unset
- No Linstor
---
---
--
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]
