Skip to content

audit-rotate: upload progress percent + ETA - #5

Merged
logicflakes merged 3 commits into
mainfrom
2026-07-audit-rotate-progress
Jul 20, 2026
Merged

audit-rotate: upload progress percent + ETA#5
logicflakes merged 3 commits into
mainfrom
2026-07-audit-rotate-progress

Conversation

@logicflakes

Copy link
Copy Markdown
Collaborator

Small observability follow-up. A multi-GB audit backup currently logs streamed_so_far + speed but no total, so someone tailing the logs has no idea how far along a large upload is.

What

  • audit-rotate estimates the dump size from the archive table's on-disk size (pg_table_size = heap + TOAST) and logs it up front: archive_backup_starting with estimated_size.
  • The progress monitor takes an optional total and, when known, adds percent_approx + eta_approx to each upload_in_progress line.
  • The estimate is approximate (compression/encryption), so percent is capped below 100 and everything is labelled _approx.
  • pipeline.RunWithRetry / progress.New gain a totalHint param; 0 (unknown) keeps the existing behaviour for pg backup / oci, which stream without a known size.

Example

archive_backup_starting  archive=audit_archive_... estimated_size="8.6 GB"
upload_in_progress  streamed_so_far="1.29 GB"  speed="7.9 MB/s"  percent_approx="15.0%"  eta_approx="15m40s"

Validated

Unit test for the percent/ETA path (race-checked); smoke-tested the estimate line end-to-end against Postgres + MinIO (the per-line percent needs a >10s upload to tick, which the unit test covers and real multi-GB uploads exercise).

Motivated by a real demo-instance run (an ~1.3 GB+ audit upload with no size expectation in the logs).

🤖 Generated with Claude Code

rhythm-agent and others added 3 commits July 20, 2026 10:11
A multi-GB audit backup logs speed but no total, so a watcher has no expectation.
audit-rotate now estimates the dump size from the archive table's on-disk size
(pg_table_size = heap + TOAST) and logs it up front ("archive_backup_starting",
estimated_size); the progress monitor takes an optional total and, when known,
adds percent_approx + eta_approx to each upload_in_progress line. Estimate is
approximate (compression), so percent is capped below 100 and labelled _approx;
0 = unknown keeps the old behaviour for pg backup / oci.

pipeline.RunWithRetry / progress.New gain a totalHint (0 for callers that can't
estimate). Unit test for the percent/ETA path (race-checked); smoke-validated the
estimate line end-to-end.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
ReARM-Agent: 1420896f-adf5-4843-896f-d863cfcc6528
ReARM-Agentic-Session: 1403ccf5-4b2a-4718-850a-3a42d188532d
The --verify-restore re-download (re-fetch + decrypt + pg_restore -l) was
silent -- for a multi-GB archive that's ~10 min of no output, which reads as
a hang. Monitor it like the upload, and since the object size is known
exactly from HeadObject, report a real (not estimated) percent + ETA.

- progress.Monitor: configurable slog event (SetEvent) so a download logs
  "verify_download_in_progress" not "upload_in_progress"; SetPrecise() marks
  total as exact -> "percent"/"eta" labels (not "_approx") and no 99.9 cap.
- verifyRestorable takes the exact size and tees the download into an atomic
  counter a Monitor reads; logs "archive_verify_restore_starting" with the
  download size up front. Both callers pass their HeadObject size.
- Tests: precise-mode + custom-event assertions on the emitted log line.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
ReARM-Agent: 1420896f-adf5-4843-896f-d863cfcc6528
ReARM-Agentic-Session: 1403ccf5-4b2a-4718-850a-3a42d188532d
Independent multi-lens review of the progress work surfaced four items; fix them:

- ETA int64 overflow: `time.Duration(secs) * time.Second` wraps to a garbage/
  negative Duration when the remaining-time estimate exceeds int64-ns range (a
  near-stall on a multi-GB transfer: a few bytes over the 10s tick). Guard against
  maxETASeconds and OMIT the ETA instead of logging a wrapped value. Also compute
  via `time.Duration(secs * float64(time.Second))` to avoid integer-second trunc.
- Stall warning is now event-aware: SetEvent takes (progressEvent, stallEvent) so a
  verify-restore DOWNLOAD stall logs "verify_download_stalled_or_waiting", not the
  hardcoded "upload_stalled_or_waiting". Defaults unchanged for the upload path.
- verify-restore download goroutine now has a defer/recover (mirrors executeStream):
  guarantees mon.Stop() + pw.CloseWithError + dlErrCh send exactly once on every exit
  incl. a panic, so the reader never hangs on <-dlErrCh and the monitor never leaks.
- Document the "call SetEvent/SetPrecise BEFORE Start()" ordering contract (the
  fields are read by the monitor goroutine without synchronization).

Tests: custom-stall-event assertion + ETA-overflow-omitted assertion. All pass
under -race; validated end-to-end (stage + --drop-pending) against Postgres+MinIO.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
ReARM-Agent: 1420896f-adf5-4843-896f-d863cfcc6528
ReARM-Agentic-Session: 1403ccf5-4b2a-4718-850a-3a42d188532d
@logicflakes

Copy link
Copy Markdown
Collaborator Author

Independent multi-lens review + live stress test

Reviewed by 3 independent agents (Go concurrency/lifecycle, numeric edge-cases, regression/API) and stress-tested end-to-end against Postgres 17 + MinIO with a 2.4 GB incompressible audit table.

Stress test (both paths, real artifact image):

  • Stage run: estimated_size 2.40 GB up front → live upload_in_progress with percent_approx/eta_approx ticking (5.8%→37.6%, ETA counting down) → archive_verify_restore_starting → verified → drop_deferred_no_drop → exit 1 (staged, by design).
  • --drop-pending finalize: re-verified the 1 GB backup (re-download + decrypt + pg_restore -l + SHA-256 vs sidecar) → dropped → 2.49 GB reclaimed, exit 0.

Findings fixed (commit pushed):

  1. ETA int64 overflow (confirmed, 2 reviewers) — time.Duration(secs)*time.Second wraps to a negative/garbage ETA in a near-stall on a multi-GB transfer. Now guarded against maxETASeconds and omitted rather than wrapped; also computed without integer-second truncation.
  2. Stall warning not event-aware — a verify-restore download stall logged upload_stalled_or_waiting. SetEvent now takes (progressEvent, stallEvent); download stalls log verify_download_stalled_or_waiting. Upload defaults unchanged.
  3. No recover() in the verify-restore download goroutine — asymmetric with executeStream; the goroutine owns mon.Stop(). Added defer/recover so Stop+pipe-close+channel-send happen exactly once on every exit (incl. panic) — reader can't hang, monitor can't leak.
  4. Undocumented before-Start() ordering on the setters — documented.

Added unit tests for the custom stall event and the ETA-overflow-omitted path; all pass under -race; gofmt clean.

Regression conclusion (confirmed): pg_backup / OCI / dir-file callers pass totalHint=0 → the new branch is skipped and the log line is byte-identical (default event still upload_in_progress). No other callers of RunWithRetry/progress.New exist.

Not fixed (by design / noted):

  • The upload percent_approx systematically under-reports (pg_table_size = heap+TOAST is a loose over-estimate of the compressed+encrypted object — the stress run showed ~37% at ~92% actual). It's labelled _approx and capped <100; the verify-restore percent is exact. Left as the honest cheap estimate.
  • Ops note: new log msgs (verify_download_in_progress, archive_verify_restore_starting) — any alert keyed on upload_in_progress won't see verify-restore downloads.

🤖 Generated with Claude Code

@logicflakes
logicflakes merged commit 693637c into main Jul 20, 2026
17 of 18 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant