Repository navigation
fix(audit): record what actually happened, not just what was submitted - #182
Conversation
audit_events had one INSERT and two SELECTs. No UPDATE anywhere. Every row
was written with status "submitted" and stayed that way forever, so the audit
log recorded intent and never outcome — the actual result of an operation
could only be learned by going and asking Argo yourself.
This is the residual left open by F20.
Two paths close a row, because one is not enough.
The Argo completion webhook already existed, already verified an HMAC
(gitops#828), and already returned 200 — it just logged and dropped the event
on the floor. It now maps phase through PhaseToOpStatus and closes the row.
That covers create-tenant, delete-tenant*, openclaw-*, platform-skill-* and
mctl-agents-* — everything WorkflowNamespace routes to argo-workflows.
It cannot cover the rest, and not for want of retries. The exit hook reads
ARGO_WEBHOOK_SECRET from an ExternalSecret that exists only in the
argo-workflows namespace and exits silently when it is absent, so
deploy-service, provision-database, retire-service, preview-deploy,
scale-service and rollback-service — the bulk of operations by volume — never
send an event at all. Copying the secret into tenant namespaces would fix the
coverage and destroy the authentication: any tenant workload could then read
it and forge completions for other tenants' workflows. So the second path is a
reconciler that reads Argo directly with mctl-api's own RBAC, every 3 minutes,
over rows still "submitted" within a 7-day lookback.
A workflow that is simply gone gets status "expired" rather than a guess, and
only after 72h — Argo's ttlStrategy.secondsAfterFailure — so a row is not
closed while its workflow merely has not been created yet.
UPDATE in place, not a second "completion" row: GetByWorkflow reads ORDER BY
timestamp DESC LIMIT 1, so a completion row (which carries no params) would
become the newest match and break auditEntryTenant, which is what authorizes
GET /workflows/{name}/logs for non-admins. Updating in place also keeps the
submission timestamp, so ListWorkflows and ListAudit stay ordered by time
submitted.
Idempotency needs no coordination between the two paths: the UPDATE carries
`AND status NOT IN (terminal)`, so whichever arrives second changes zero rows.
Redelivery, and a webhook racing the reconciler, are both no-ops.
phaseToOpStatus is now exported rather than duplicated, so there stays exactly
one mapping from Argo phases to audit statuses.
Index on audit_events(workflow) added — GetByWorkflow was already doing a
sequential scan on every workflow read, and UpdateStatus would have added
another per completion. Created CONCURRENTLY in its own Exec because that
cannot run inside a transaction and pgx wraps multi-statement Execs in one;
partial, since most denied rows have no workflow. A failure there logs a
warning instead of failing startup — the index is a performance property, not
a correctness one.
Tests cover the three terminal phases, that Running leaves the row alone, that
redelivery cannot reopen a closed row, that an unknown workflow is still
acknowledged (cron workflows have no audit row), and the in-memory logger's
matching behaviour including message preservation.
|
Bugbot is not enabled for your account, so this pull request was not reviewed. Enable Bugbot in the Cursor dashboard to get automatic reviews on future PRs. |
|
Claude finished @mashkovd's task in 6m 5s —— View job Review complete — changes requested
Posted a REQUEST_CHANGES review with 3 P2 and 1 P3 inline findings, all on the new
The webhook-closure path itself ( |
Antigravity (agy) review — informationalModel: gemini-3.1-pro-high. Here is the review of the provided diff. Finding 1: Missing Context Timeout in Reconciler I/OSeverity: P2 reqCtx, reqCancel := context.WithTimeout(ctx, 10*time.Second)
defer reqCancel()
status, err := r.exec.GetWorkflowStatus(reqCtx, ns, e.WorkflowName)Finding 2: Workflow Starvation Due to Queue Query LimitSeverity: P2 Finding 3: Missing Test Coverage for Reconciler LogicSeverity: P2 Finding 4: Swallowed Kubernetes API ErrorsSeverity: P3 if err != nil {
if apierrors.IsNotFound(err) && time.Since(e.Timestamp) > r.gcGrace {
// ... UpdateStatus("expired") logic ...
} else if !apierrors.IsNotFound(err) {
slog.Error("audit reconciler: failed to get workflow status", "workflow", e.WorkflowName, "error", err)
}
continue
} |
| } | ||
|
|
||
| func (r *auditReconciler) reconcileOnce(ctx context.Context) { | ||
| pending := r.log.ListByStatus("submitted", r.lookback, r.batch) |
There was a problem hiding this comment.
P2: ListByStatus (both the Postgres and in-memory implementations) orders by timestamp DESC and this call caps the result at r.batch (200). Under a sustained backlog of more than 200 concurrently-submitted rows, this always returns the newest 200 — older rows are never examined by any pass as long as >= batch newer rows remain unresolved. Given the 7-day lookback, a stuck older row can silently age out of the window and never get closed, which is exactly the failure mode this reconciler exists to fix. Consider ordering oldest-first (or otherwise prioritizing age) so a backlog drains deterministically instead of potentially starving the tail.
| continue | ||
| } | ||
|
|
||
| status, err := r.exec.GetWorkflowStatus(ctx, ns, e.WorkflowName) |
There was a problem hiding this comment.
P2: this call has no per-request timeout/deadline. ctx here is the long-lived process context passed from cmd/api/main.go (only cancelled on shutdown), and rest.Config in operations.NewExecutor sets no client-side Timeout either. If the Kubernetes/Argo API is slow or unreachable for one workflow lookup, this single call can block indefinitely, stalling the whole reconcileOnce pass (and therefore every other pending row in the batch) until it returns or the process shuts down. Consider wrapping this call in a short context.WithTimeout per item, similar to how PostgresLogger.UpdateStatus/ListByStatus bound their own calls.
| } | ||
| } | ||
|
|
||
| func (r *auditReconciler) reconcileOnce(ctx context.Context) { |
There was a problem hiding this comment.
P2: no test coverage for reconcileOnce's branching (operation removed from registry → skip, empty namespace → skip, NotFound within grace → skip, NotFound past gcGrace → expired, other error → retry later, non-terminal phase → skip, terminal phase → UpdateStatus). This is genuinely intricate logic and the diff adds tests only for the webhook path and the in-memory logger, not this reconciler. The repo already has fakeExecutor (internal/api/smoke_test.go:161) implementing WorkflowExecutor.GetWorkflowStatus, which is close to what's needed here — but auditReconciler depends on the concrete *operations.Executor/*operations.Registry rather than an interface, so that fake can't be reused as-is. Worth either accepting the small interfaces (there's precedent in internal/api/interfaces.go's WorkflowExecutor) or adding a k8s fake-dynamic-client-backed test, so the gc-grace/expiry logic in particular gets exercised before merge.
| SET status = $2, | ||
| message = CASE WHEN $3 = '' THEN message ELSE $3 END | ||
| WHERE workflow = $1 | ||
| AND status NOT IN ('succeeded', 'failed', 'error', 'expired')`, |
There was a problem hiding this comment.
P3: this hardcoded status list duplicates audit.TerminalStatuses (internal/audit/logger.go:60). If a status is ever added there, this WHERE clause silently drifts out of sync (redelivery could then reopen a row the Go layer already considers terminal). Not urgent, but worth building this list from TerminalStatuses or adding a test that asserts parity.
There was a problem hiding this comment.
Has P1/P2 findings, changes requested: 3 P2, 1 P3. The webhook-closure path and in-memory logger are well covered by tests and look correct (redelivery no-op, terminal-status guard, message-preservation all verified). The new auditReconciler is where the concerns are: (1) ListByStatus's ORDER BY timestamp DESC LIMIT batch can starve older backlog rows out of the 7-day lookback under sustained load; (2) GetWorkflowStatus is called with no per-item timeout, so one hung k8s call can stall the whole pass; (3) none of reconcileOnce's branching has test coverage. Plus one P3 nit on a duplicated terminal-status literal in SQL.
Addresses the four findings on #182. P2 — starvation. ListByStatus returned newest-first and reconcileOnce caps at batch (200). With a sustained backlog above that cap the oldest rows would never be examined by any pass, which is precisely backwards: an old submitted row is the one most likely to be genuinely stuck. Both implementations now return oldest-first, and the interface documents it as a work queue rather than a feed. TestReconcileDrainsOldestFirst fails against the old ordering. P2 — unbounded lookups. GetWorkflowStatus ran on the process-lifetime context, and neither rest.Config nor the caller sets a client timeout, so one slow or unreachable read could stall an entire pass. Each lookup now gets its own 10s deadline; the fake asserts the context it receives actually carries one. P2 — the reconciler's branching had no tests. It does now, one per branch: terminal phases close the row (all three), a tenant-namespaced operation is looked up in the tenant's namespace, Running is left alone, NotFound inside the grace window is left alone while NotFound past it expires with a reason, a transport error leaves the row for the next pass, an unknown operation and a missing tenant are both skipped without a lookup, rows outside the lookback are ignored, and an already-terminal row is never touched. Testing it needed a seam: the reconciler now holds a one-method workflowStatusGetter rather than *operations.Executor, which the executor satisfies unchanged. P3 — the terminal status list was written out in the UPDATE's WHERE clause and duplicated audit.TerminalStatuses. Drift there would let redelivery reopen a row the Go layer considers closed, so the clause is now `NOT (status = ANY($4))` fed from TerminalStatuses directly. Also: Logger.Log now honours a caller-supplied Timestamp instead of always stamping now. Production paths leave it zero and are unaffected; the age-dependent tests set it rather than reaching into the logger's internals.
|
Claude finished @mashkovd's task in 1m 47s —— View job Review complete — approved
Posted an APPROVE review bound to commit This commit (
One new P3 (non-blocking) on audit_reconcile.go:113: non- The webhook-closure path, in-memory logger, and status-mapping export ( |
| } | ||
| ns := operations.WorkflowNamespace(op.WorkflowTemplate, auditEntryTenant(&e)) | ||
| if ns == "" { | ||
| continue |
There was a problem hiding this comment.
P3: non-NotFound errors from GetWorkflowStatus (RBAC denial, 500, timeout from lookupTimeout firing) are silently swallowed here — the row is left for the next pass, which is correct, but there's no log line, so an operator has no way to tell "this row is stuck because Argo is unreachable" from "this row just hasn't been resolved yet." Consider an slog.Warn on the non-NotFound branch. Not blocking — the earlier P2s (drain order, per-item timeout, test coverage) are what mattered and are all fixed in this commit.
There was a problem hiding this comment.
No P1/P2 findings (1 P3). All three P2s from the prior review are fixed in this commit: ListByStatus now drains oldest-first (ORDER BY timestamp ASC in postgres, insertion-order iteration in-memory), GetWorkflowStatus is called under a per-item context.WithTimeout (lookupTimeout, 10s default), and audit_reconcile_test.go adds thorough table-driven coverage of reconcileOnce's branching via a new workflowStatusGetter interface + fakeStatusGetter (terminal phases, running, NotFound within/past gcGrace, transport errors, unknown operation, missing namespace, oldest-first draining under a small batch, lookback exclusion, already-terminal rows). The P3 (terminal-status duplication) is also fixed — postgres.go's UPDATE now takes TerminalStatuses as a query parameter instead of a hardcoded literal. Good to merge.
Antigravity (agy) review — informationalModel: gemini-3.1-pro-high. Finding 1
Finding 2
Finding 3
|
Addresses the P3 on #182. A row left for the next pass is correct, but an RBAC denial, a 500 or a lookupTimeout firing looked identical to "not resolved yet" from outside. NotFound stays quiet: inside the grace window it is the expected case, not a fault.
|
Claude finished @mashkovd's task in 1m 9s —— View job Review complete — approved
Posted an APPROVE review bound to commit Between if !apierrors.IsNotFound(err) {
slog.Warn("audit reconcile: workflow lookup failed",
"workflow", e.WorkflowName, "namespace", ns, "error", err)
}This resolves the P3 raised in the prior review round ( No other files changed in this commit. All prior P2s (oldest-first draining, per-item lookup timeout, Wasn't able to run |
There was a problem hiding this comment.
No P1/P2 findings (0 new P3). This commit is a single, precisely-scoped fix: it adds an slog.Warn on the non-NotFound branch of reconcileOnce in internal/api/audit_reconcile.go, resolving the P3 raised on the prior commit (d514d43) — operators can now distinguish a row stuck because Argo/k8s is unreachable or denying the request from one that simply hasn't resolved yet. The NotFound-within-grace path remains silent as intended. No other files changed since d514d43, which was already approved. Good to merge.
Antigravity (agy) review — informationalModel: gemini-3.1-pro-high. Here are the findings from the review: 1. Missing error wrapping in I/O operations
2. Missing test coverage for new database operations
|
… index it Three findings from the agy reviewer, all correct. P1 — head-of-line blocking, which my own previous fix created. Draining oldest-first stopped newer rows from starving the old ones, and introduced the mirror image: a row that cannot be resolved yet is left untouched, so it stays among the oldest and is re-read every pass. A few hundred still-Running workflows would occupy the whole batch indefinitely and no newer completed workflow would ever be closed. ListByStatus now takes a timestamp cursor and reconcileOnce pages through the backlog with it, bounded by maxPerPass (2000) so a large backlog cannot turn one tick into an unbounded walk. TestReconcilePagesPastUnresolvableRows fails against single-page behaviour with "the pass never got past the stuck rows". TestReconcileDrainsOldestFirst was asserting the old single-page semantics, so it now checks the order of lookups rather than that only one happened — oldest-first is the property that matters, and paging is what makes it safe. P3 — the Postgres UPDATE matched every non-terminal row sharing a workflow name while the in-memory implementation updated exactly one. Argo names carry a generated suffix so collisions are unlikely, but "close every historical run with this name" is not a behaviour to leave to chance in an audit table. Scoped to the newest match via a subquery. P3 — added a composite index on (status, timestamp) for the queue query. The existing timestamp-only index would have Postgres walk it discarding every already-terminal row, which is nearly all of them once the table grows.
|
Claude finished @mashkovd's task in 3m 43s —— View job Review complete — changes requested
Posted a REQUEST_CHANGES review bound to commit This commit (
But the fix for the other Antigravity finding (cross-workflow
Wasn't able to run |
Antigravity (agy) review — informationalModel: gemini-3.1-pro-high. Here are the findings from reviewing the diff: Finding 1 Finding 2 Finding 3 Finding 4 Finding 5 |
| SELECT id FROM audit_events | ||
| WHERE workflow = $1 AND NOT (status = ANY($4)) | ||
| ORDER BY timestamp DESC | ||
| LIMIT 1 |
There was a problem hiding this comment.
P2: scoping the update to the newest row via id IN (SELECT ... LIMIT 1) moves the NOT (status = ANY($4)) terminal guard out of the top-level WHERE and into an uncorrelated subquery. That subquery has no outer-row dependency, so Postgres evaluates it once as an InitPlan and caches the resulting id — it is not re-run when EvalPlanQual re-checks the top-level predicate after a lock wait.
Concretely: if the webhook and the reconciler race to close the same workflow, both can select the same id (row still submitted when each subquery runs). The first to acquire the row lock updates and commits. The second, unblocked afterward, re-evaluates only id IN (<cached id>) — which still trivially matches, since id didn't change — and proceeds to overwrite the now-terminal row (e.g. clobbering succeeded with a stale failed, or just the message). That's exactly the "whichever path arrives second changes zero rows" guarantee this PR's description calls out as the point of the guard, and it no longer holds under genuine concurrency (which the reconciler racing the webhook is designed to allow).
Suggested fix: keep the guard on the outer, directly-evaluated predicate too, so EvalPlanQual re-checks it against the post-lock row version:
UPDATE audit_events
SET status = $2,
message = CASE WHEN $3 = '' THEN message ELSE $3 END
WHERE workflow = $1
AND NOT (status = ANY($4))
AND id IN (
SELECT id FROM audit_events
WHERE workflow = $1 AND NOT (status = ANY($4))
ORDER BY timestamp DESC
LIMIT 1
)| if e.Status != status || e.Timestamp.Before(cutoff) { | ||
| continue | ||
| } | ||
| if !after.IsZero() && !e.Timestamp.After(after) { |
There was a problem hiding this comment.
P3: the cursor advances with a strict after comparison (mirrored in postgres.go's timestamp > $4), keyed off pending[len(pending)-1].Timestamp. If two or more rows in the same status share that exact timestamp and the page boundary falls between them (batch-sized page ends mid-tie), the remaining tied rows are skipped for the rest of this pass — the next page's timestamp > cursor excludes them too since they're not strictly greater. Not a permanent loss (the next reconcileOnce call restarts the cursor at the zero time and re-lists from the beginning), just a one-pass (3-minute) delay. Worth a code comment if this is accepted as intentional, since it's easy to mistake for a correctness bug on first read.
There was a problem hiding this comment.
Has P1/P2 findings, changes requested: 1 P2, 1 P3. This commit correctly addresses the prior Antigravity findings on queue starvation (cursor-based paging in ListByStatus, bounded by maxPerPass) and the missing composite index (audit_events_queue), both well tested. However, the fix for cross-workflow UPDATE scoping introduces a new issue: in internal/audit/postgres.go's UpdateStatus, the terminal-status guard now lives only inside an uncorrelated subquery (id IN (SELECT ... LIMIT 1)), which Postgres evaluates once as a cached InitPlan rather than re-checking via EvalPlanQual when a concurrent UPDATE forces a lock wait — so two genuinely concurrent close attempts on the same workflow (webhook racing the reconciler, which this PR explicitly designs for) can both succeed, breaking the 'whichever path arrives second changes zero rows' guarantee the PR describes. See inline comment for a one-line fix (duplicate the guard onto the outer WHERE). Also a P3 nit on the cursor's strict timestamp comparison under timestamp ties.
Addresses the P2 on #182, which is a defect I introduced in the previous commit while fixing a different one. Scoping the update to the newest row moved `NOT (status = ANY($4))` into an `id IN (SELECT ...)` subquery. That subquery is uncorrelated, so Postgres evaluates it once as an InitPlan and caches the id — and EvalPlanQual, which re-checks the predicate after a lock wait, only re-evaluates the top level. So when the webhook and the reconciler race the same workflow, both subqueries run while the row is still submitted and select the same id. The winner closes it. The loser wakes, re-checks `id IN (<cached id>)`, still matches, and overwrites a row that is already terminal — a stale `failed` landing on top of `succeeded`. Exactly the idempotency the guard was there to provide, undone by moving it. The guard is now in both places. The subquery copy picks the right row; the top-level copy is the one EvalPlanQual re-evaluates, and is what actually makes the update idempotent. The comment says so, because a reader will otherwise delete one of them as redundant. Also documents the P3: the cursor uses a strict `>` comparison, so a page boundary landing mid-tie skips the tied remainder for the rest of that pass. Nothing is lost — the next pass restarts the cursor at zero — so the cost is one 3-minute cycle, which is not worth threading a compound (timestamp, id) cursor through the interface to avoid.
|
Claude finished @mashkovd's task in 1m 12s —— View job Review complete — approved
Posted an APPROVE review bound to commit This commit ( WHERE id IN (
SELECT id FROM audit_events
WHERE workflow = $1 AND NOT (status = ANY($4))
ORDER BY timestamp DESC
LIMIT 1
)
AND NOT (status = ANY($4)) -- new: duplicated on the outer WHEREThe subquery that picks "the newest matching row" is uncorrelated (no reference to the outer query), so Postgres evaluates it once as a cached Duplicating The only other change in this commit is a clarifying comment added to All prior findings across earlier commits (drain order, per-item lookup timeout, reconciler test coverage, terminal-status duplication, queue starvation/pagination, composite index, non- Wasn't able to run |
There was a problem hiding this comment.
No P1/P2 findings (0 P3). This commit fixes exactly the P2 raised on fa0a152: the terminal-status guard AND NOT (status = ANY($4)) is now duplicated on the outer, directly-evaluated WHERE clause of UpdateStatus in internal/audit/postgres.go, in addition to the uncorrelated subquery. Since Postgres caches an uncorrelated subquery as an InitPlan and does not re-run it during EvalPlanQual's post-lock-wait re-check, the guard now living on the outer predicate is what actually gets re-evaluated against the row's current state — restoring the 'whichever path arrives second changes zero rows' idempotency guarantee under a genuine webhook/reconciler race. The only other change is a clarifying comment in internal/audit/logger.go (no logic change). Good to merge.
Antigravity (agy) review — informationalModel: gemini-3.1-pro-high. No significant issues found. |
golangci-lint gocritic rangeValCopy: audit.Entry is 192 bytes and the loop runs over every pending row on each tick.
|
Claude finished @mashkovd's task in 39s —— View job Review complete — approved
Posted an APPROVE review bound to commit This commit ( All prior P1/P2 findings from earlier review rounds on this PR (drain order, per-item lookup timeout, reconciler test coverage, terminal-status duplication, queue pagination/starvation, composite index, non- Wasn't able to run |
There was a problem hiding this comment.
Trivial style-only change: switches the reconcileBatch loop from range-by-value to an indexed pointer (avoids copying audit.Entry, a 192-byte struct, per gocritic rangeValCopy). No logic change — e is used read-only, no aliasing hazard. All prior P1/P2 findings across earlier commits remain fixed.
Antigravity (agy) review — informationalModel: gemini-3.1-pro-high. Severity: P2 Concrete failure scenario: When this happens, the Proposed fix: for rows.Next() {
e, err := scanAuditEntry(rows.Scan)
if err != nil {
slog.Error("audit postgres: scan failed", "error", err)
continue
}
entries = append(entries, e)
}
if err := rows.Err(); err != nil {
slog.Error("audit postgres: rows error", "status", status, "error", err)
}
return entries |
audit_eventshad one INSERT and two SELECTs. No UPDATE anywhere. Every row was written with statussubmittedand stayed that way forever, so the audit log recorded intent and never outcome — the actual result of an operation could only be learned by going and asking Argo yourself.This is the residual left open by F20.
Two paths, because one is not enough
The webhook.
HandleArgoWorkflowCompletealready existed, already verified an HMAC (gitops#828), and already returned 200 — it just logged and dropped the event. It now mapsphasethroughPhaseToOpStatusand closes the row.That covers what
WorkflowNamespaceroutes toargo-workflows: create-tenant, delete-tenant*, openclaw-, platform-skill-, mctl-agents-*.It cannot cover the rest, and not for want of retries. The exit hook reads
ARGO_WEBHOOK_SECRETfrom an ExternalSecret that exists only in the argo-workflows namespace and exits silently when absent:So
deploy-service,provision-database,retire-service,preview-deploy,scale-service,rollback-service— the bulk of operations by volume — never send an event at all.Copying the secret into tenant namespaces would fix the coverage and destroy the authentication: any tenant workload could then read it and forge completion events for other tenants' workflows. So the second path is a reconciler that reads Argo directly using mctl-api's own RBAC — every 3 minutes, over rows still
submittedwithin a 7-day lookback.A workflow that is simply gone gets
expiredrather than a guess, and only after 72h (Argo'sttlStrategy.secondsAfterFailure), so a row is never closed while its workflow merely has not been created yet.UPDATE in place, not a second row
GetByWorkflowreadsORDER BY timestamp DESC LIMIT 1. A "completion" row carries noparams, so it would become the newest match and breakauditEntryTenant— which is what authorizesGET /workflows/{name}/logsfor non-admins. Updating in place also preserves the submission timestamp, soListWorkflowsandListAuditstay ordered by time submitted.Idempotency needs no coordination
The UPDATE carries
AND status NOT IN ('succeeded','failed','error','expired'). Whichever path arrives second changes zero rows. Redelivery and a webhook racing the reconciler are both no-ops — no locking, no dedupe table.phaseToOpStatusis now exported rather than duplicated, so exactly one mapping from Argo phases to audit statuses exists in the codebase.Index
Added on
audit_events(workflow).GetByWorkflowwas already doing a sequential scan on every workflow read, andUpdateStatuswould have added another per completion.Created
CONCURRENTLYin its ownExec— it cannot run inside a transaction and pgx wraps multi-statement Execs in one. Partial (WHERE workflow <> ''), since most denied rows have no workflow. A failure logs a warning instead of failing startup: the index is a performance property, not a correctness one.Tests
Three terminal phases close the row;
Runningleaves it alone; redelivery cannot reopen a closed row; an unknown workflow is still acknowledged with 200 (cron workflows have no audit row); plus the in-memory logger's matching,maxAge/limithandling, and message-preservation behaviour.go build,go vet,go test ./...(15 packages) all pass.