UsageManagerImpl.parse() rewind to the oldest unprocessed usage event is unbounded

[Alpha162]

problem

Split out of #13399 at @DaanHoogland's request.

UsageManagerImpl.parse() correctly derives its start date from the last successful job:

long lastSuccess = _usageJobDao.getLastJobSuccessDateMillis();
if (lastSuccess != 0) {
    startDateMillis = lastSuccess + 1;
}

and then overwrites it with the create date of the oldest unprocessed event, moving it only ever earlier:

// make sure start date is before all of our un-processed events
Date oldestEventDate = events.get(0).getCreateDate();
if (oldestEventDate.getTime() < startDateMillis) {
    startDateMillis = oldestEventDate.getTime();
    startDate = new Date(startDateMillis);
}

events comes from UsageEventDaoImpl.listLatestEvents() — WHERE processed = 0 AND created <= ? ORDER BY createDate ASC, with no limit and no floor.

Consequence: any event that can never be successfully processed pins the aggregation start date permanently. Each subsequent run re-aggregates from that date to the present, growing by one aggregation range per range elapsed. The job continues to report success = 1 throughout, so nothing surfaces as an error.

Measured on an affected 4.22.1.0 deployment:

• 1,678 consecutive successful jobs whose start_millis never advanced past a single event 71 days earlier
• exec_time of 2,555,055 ms (42.6 min) per hourly run, growing by 24 aggregation periods per day
• cloud_usage at 54.4M rows / 14 GB, of which roughly 150k rows were genuine; duplicate counts were an exact multiple of the number of replays

Not specific to one event type: #13112 was reported on 4.21.0.0 against usage_type = 13, predating the volume-specific trigger in #13399. The rewind is the common mechanism; the triggering event type varies.

versions

Observed on CloudStack 4.22.1.0 (EL9 packages), MySQL 8.x / InnoDB, with usage.stats.job.aggregation.range = 60 and usage.stats.job.exec.time = 00:15.

#13112 reports the same mechanism on 4.21.0.0, so this is not new in 4.22.

The steps to reproduce the bug

1. Have any row in cloud_usage.usage_event that cannot be successfully processed, Usage Server repeatedly reprocesses historical usage and creates duplicate cloud_usage records for usage_type=1 #13399 gives one reliable route, but the mechanism is independent of cause.
2. Let the usage job run on its normal schedule.
3. SELECT id, start_date, end_date, exec_time FROM cloud_usage.usage_job WHERE success = 1 ORDER BY id DESC LIMIT 5; — start_date stays pinned at the oldest unprocessed event's created while end_date advances.
4. TIMESTAMPDIFF(HOUR, start_date, end_date) grows without bound, as does exec_time.
5. Row counts in cloud_usage.cloud_usage per period equal the number of times that period has been re-aggregated.

What to do about it?

Bound the rewind, and/or provide a way to quarantine or age out events that repeatedly fail to process, so one unprocessable row cannot halt aggregation indefinitely.

This is a design decision rather than an obvious patch, which is why it's raised separately from #13399.

[Alpha162]

Some production data for this, from a 4.22.1.0 cluster where the rewind had the aggregation window pinned for ten weeks.

cloud_usage.usage_job grouped by the recorded aggregation start:

start_date            jobs
2026-06-04 16:50:51   1676
2026-06-02 00:00:00      1
2026-06-03 00:00:00      1
2026-06-04 00:00:00      1
2026-08-14 16:00:00      1

1,676 consecutive jobs, every one success = 1, all re-aggregating from the same instant. That timestamp is the created value of cloud_usage.usage_event id 1 (the first event the cluster ever emitted, and one that had never been processed). Nothing moved the window forward for ten weeks.

The same table grouped by the day the aggregation window started rather than the day the job ran, which is why the whole pinned period collapses into one row:

d            jobs  min_ms   max_ms
2026-06-02      1     252      252
2026-06-03      1     116      116
2026-06-04   1677     570  3139799
2026-08-14      8    2143     2483
2026-08-15     24    2096     2361
2026-08-16     24    2099     2323
2026-08-17     20    2094     2263

Within the pinned group exec_time grows from 570 ms on the first run to 3,139,799 ms, 52 minutes of every hour (on the last, since each run re-covered one more hourly period than the one before). cloud_usage reached 54,460,998 rows / 14 GB against roughly 150k genuine records.

Remediation was to force the six unprocessed events processed:

UPDATE cloud_usage.usage_event SET processed = 1 WHERE id IN (1,2,3,4,5,6);

Update the flag rather than deleting the rows; getMostRecentEventId() is ORDER BY id DESC LIMIT 1 over the whole table and returns 0 on an empty one, which triggers COPY_ALL_EVENTS and re-copies every event with processed = 0.

From the next run onward the window advanced hourly and exec_time settled at ~2.1 s, as the 14 Aug row onward shows. Same code, same data volume, six rows changed, roughly a 1,460× reduction.

Two things made this hard to spot: all 1,676 of those runs recorded success = 1, and usage.sanity.check.interval was NULL, so the check that might have caught it was disabled.

On how the events got stuck in the first place, a duplicate-key failure on usage_volume (#13909) whose exception left the caller's transaction unbalanced (#13905), so the batch's processed flags were silently discarded. The rewind then pinned to them indefinitely.