diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index b6bf22e83..bede35fe2 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -112,6 +112,26 @@ jobs: run: node module/tools/migration-pairing-gate.mjs check - name: Validate every service test-target catalog run: node module/tools/test-targets-gate.mjs check + # The alert pack is PromQL that no service runs, so an alert that cannot + # fire goes unnoticed until the failure it was for. promtool evaluates + # each alert in slo_pack.json, as the Prometheus rule its id and + # expression make, over the series the pack's rule tests feed it. + - name: Test the alert pack's rules with promtool + env: + PROMETHEUS_VERSION: "3.15.0" + PROMETHEUS_SHA256: 2a542df32eac02ee17b9d844fb2aa1de00dafa5476579ba8a3ba862e9d572ea0 + run: | + work="$(mktemp -d)" + archive="prometheus-${PROMETHEUS_VERSION}.linux-amd64" + curl -fsSL -o "${work}/${archive}.tar.gz" \ + "https://github.com/prometheus/prometheus/releases/download/v${PROMETHEUS_VERSION}/${archive}.tar.gz" + echo "${PROMETHEUS_SHA256} ${work}/${archive}.tar.gz" | sha256sum -c - + tar -xzf "${work}/${archive}.tar.gz" -C "${work}" --strip-components=1 "${archive}/promtool" + pack=module/services/accounts/code/pkg/metrics + jq '{groups: [{name: "slo_pack", rules: [.alerts[] | {alert: .id, expr: .expression}]}]}' \ + "${pack}/slo_pack.json" > "${work}/slo_pack.rules.json" + cp "${pack}/slo_pack_test.yml" "${work}/" + "${work}/promtool" test rules "${work}/slo_pack_test.yml" # The author and committer email are the half of the naming boundary the tree scan cannot # see, and the half that cannot be scrubbed: they are part of the commit object, so # changing one rewrites every descendant hash. Scoped to the commits this change proposes diff --git a/PLATFORM_REFERENCE.md b/PLATFORM_REFERENCE.md index 8ab9561ec..d103869c9 100644 --- a/PLATFORM_REFERENCE.md +++ b/PLATFORM_REFERENCE.md @@ -203,12 +203,17 @@ Gated by tenant-admin or platform role (`src/components/auth/role-gate.tsx`). analog of the audit's `delegation_jti` + `caused_by` chain + ceiling-snapshot hash. - **Retention/redaction, 🟡:** `RunRetention` deletes per - `data_retention_policies`; export payloads are PII-redacted. The audit's named - two-tier (7-year content-free / 90-day full) split is not a distinct construct - yet — it is the compliance tier planned under + `data_retention_policies`, counted from the database's clock, and retires + audit events by dropping each monthly partition whose recorded range ends + before the window + ([DATABASE_AUTHORITY.md](./module/DATABASE_AUTHORITY.md#audit-retention-drops-a-partition-by-its-recorded-range-under-lock)); + a run that fails in any part is an error the alert pack watches + ([MEASUREMENT_RUNBOOKS.md](./module/MEASUREMENT_RUNBOOKS.md#retention)); + export payloads are PII-redacted. The audit's named two-tier (7-year + content-free / 90-day full) split is not a distinct construct yet — it is the + compliance tier planned under [ADR 0006](./module/docs/adr/0006-audit-sink-and-retention-tiers.md) (tiered - retention + a swappable compliance sink; note today's `RunRetention` is a - no-op because it collides with the immutability trigger). + retention + a swappable compliance sink). - **Read auditing, ⬜:** bulk reads are RLS-scoped but not themselves logged as audit events. The audit's "audit the access set (IDs, capped, dedupe window)" pattern — and its 11k-rows-from-a-poller cautionary tale — is unbuilt. diff --git a/RELEASE_GATES.md b/RELEASE_GATES.md index 2bd4d811a..77740124f 100644 --- a/RELEASE_GATES.md +++ b/RELEASE_GATES.md @@ -437,7 +437,7 @@ reverse, fails the `release-contract` job. | Job | What it guards | What it runs | | --- | --- | --- | -| `base-integrity` | the frontend workspace install graph and public-claim scan (`module-verify.mjs`), plus the RLS-migration, migration-pairing, reference-aware migration upgrade, and generated-pin gates | `node --test` for each gate's own suite, then `node module/tools/.mjs check`; migration reference validation runs on every candidate, with PostgreSQL upgrade and clean-install replay scoped to migration/runner inputs (see [migration policy](module/services/store/migrations/README.md)) | +| `base-integrity` | the frontend workspace install graph and public-claim scan (`module-verify.mjs`), plus the RLS-migration, migration-pairing, reference-aware migration upgrade, and generated-pin gates, and the alert pack's rules | `node --test` for each gate's own suite, then `node module/tools/.mjs check`; migration reference validation runs on every candidate, with PostgreSQL upgrade and clean-install replay scoped to migration/runner inputs (see [migration policy](module/services/store/migrations/README.md)); `promtool test rules` over the alerts in `slo_pack.json`, with the tests in `slo_pack_test.yml` beside it, on a pinned, checksum-verified promtool | | `authz-coverage` | the generated authorization catalog: RBAC coverage, audit coverage, and permission no-broadening against `main` | `node module/tools/authz-coverage-gate.mjs`, plus `go test` for the gateway header-lockstep and adapter enforcement tests | | `release-contract` | this gating graph itself, and the Dependabot configuration that feeds it | `node --test scripts/ci/release-gates.test.mjs`, `node --test scripts/ci/dependabot-coverage.test.mjs`, `node scripts/ci/release-gates.mjs check`, `node scripts/ci/dependabot-coverage.mjs check` | | `docs-sync` | the generated interface docs and the story-trace tests (#516) | `node module/tools/interface-docs-gate.mjs check`, `node module/tools/story-trace-gate.mjs tests` | diff --git a/module/DATABASE_AUTHORITY.md b/module/DATABASE_AUTHORITY.md index b6bc9cfde..c1aa31212 100644 --- a/module/DATABASE_AUTHORITY.md +++ b/module/DATABASE_AUTHORITY.md @@ -588,6 +588,104 @@ attached or detached, now needs a `BYPASSRLS` role to read every row, which the partition offload planned in [ADR 0006](./docs/adr/0006-audit-sink-and-retention-tiers.md) has to provision. +## Audit retention drops a partition by its recorded range, under lock + +Audit retention is a partition drop, and a dropped partition cannot be +recovered. `audit_events_drop_partitions_before(cutoff)`, as migration +`34_audit_retention_partition_bounds` defines it, drops a monthly partition only +when the upper bound PostgreSQL records for it ends by the cutoff. Earlier +releases cut a partition's bounds at the midnights of the session zone that +created it, so the function reads each bound from `pg_get_expr(relpartbound)`, +never from the month in the name, and renders and reads it under a `DateStyle` +and `TimeZone` it pins, never the caller's. It never drops a partition whose +bounds are not a bounded range (`DEFAULT`, `MINVALUE`, `MAXVALUE`) or whose +detach has begun. + +The cutoff is one the `audit_events` retention policy allows by the database's +clock. The function refuses (SQLSTATE 22023) a cutoff later than the start of +its transaction less the policy's window, a missing one, and any when there is +no policy, so a caller whose clock runs ahead cannot drop a partition still +inside the window. Once something is due it reads the policy again, with a row +lock (`FOR SHARE NOWAIT`) it holds until it commits, and checks the cutoff +against that, so the window it keeps to is the one in force when it commits: a +change to the policy made while a run waits for its locks waits in turn for the +run, and one already under way when the run reads the policy makes the run +refuse (55P03) rather than wait. A window is a positive number of days: +`data_retention_policies` refuses any other with a check constraint, and the +migration that added it refuses to apply while a policy holds one, naming it, +rather than leave retention to guess what it meant. + +When something is due the function locks `audit_events` `ACCESS EXCLUSIVE` and +decides again from the catalog as it stands once the lock is held, so a +partition detached while it waited is left alone. That lock stops a partition +being created, attached, detached or given other bounds, but not renamed, and +`LOCK TABLE` finds the table it locks by name: a partition renamed away while a +`LOCK TABLE` waits for it, and another renamed to its name, would lead that +`LOCK TABLE` on to the other one, and to a second wait. So the function locks +each partition it chose by identity, under the name it has at that moment, with +`LOCK TABLE ... NOWAIT` tried again until its deadline rather than a wait in the +lock queue, and refuses unless the lock it holds is on that very partition. +Holding them all, it decides a third time. It drops them only if exactly those +are still due, and otherwise drops nothing (55000). Only a READ COMMITTED +statement reads the catalog as it stands, so the function refuses any other +isolation level (25000). `DropAuditPartitionsBefore` opens its own control-plane +transaction at READ COMMITTED when its caller has none, whatever the database's +default isolation, and that is how `RunRetention` calls it. The function waits +ten seconds in all for its locks, not ten for each: it takes the policy's table +and `audit_events` each in a statement of its own, after setting `lock_timeout` +to what remains of ten seconds from its start, and each partition it locks with +`NOWAIT`, tried again until then. Each `DROP` runs under what remains too, which +bounds its wait for the DEFAULT partition, if there is one, which dropping a +range partition also locks. It gives up with 55P03, dropping nothing, once +nothing remains. When nothing is due it takes no lock at all: it reads bounds +with `pg_get_expr(relpartbound, 0)`, which does not open the partition. + +`RunRetention` counts every window back from the database's clock, in days of +24 hours, so the cutoff it passes is exactly the window before the database's +present, and always in the past. It refuses a window that is not a positive +number of days. A run goes on past a part that fails and returns every failure +together; the scheduler logs that as an error and sets the gauge +`saas.retention.failing` to 1 for each failed part, and back to 0 once a run no +longer fails it. The alert pack's `retention_failures` alert fires while a part +reads 1, from the first scrape after the failure, and CI tests it with +`promtool` ([MEASUREMENT_RUNBOOKS.md](./MEASUREMENT_RUNBOOKS.md#retention)). +`pkg/infra/postgres_audit_retention_test.go` holds the function's rules against +PostgreSQL, and the retention tests in `pkg/business` hold the window's. + +## Audit partitions are provisioned at UTC midnights, within ten seconds of waiting + +`audit_events_provision_partitions(months_ahead)` is the store's one +provisioning call, at startup and on every retention run, whatever the +policies. It creates the partitions of the months from the previous one to +`months_ahead` ahead, by the database's clock in UTC, then brings every +partition's row-level security in step with the parent's. +`audit_events_ensure_partition(month)` and `audit_events_secure_all_partitions()` +remain for migrations and operators. Execute on all three stays with +`app_control_plane`. + +Creating a partition locks `audit_events` `ACCESS EXCLUSIVE`, which audit writes +queue behind, so provisioning takes that lock only when a month lacks its +partition, decides again under the lock what to create, and waits ten seconds in +all for every lock it takes, like retention, before giving up with 55P03 and +creating nothing. The months ahead are provisioned in advance, so a call that +gives up leaves the next one time to try again. Bringing a partition in step +locks it only when it is out of step, by identity as retention does, and decides +again under that lock what to change. A partition locked that way is tried again +rather than waited for in the queue, so one that other sessions keep in use +throughout can make the call give up at its deadline, and the next run tries +again. Bringing every partition in step reads the list of partitions holding +`audit_events` `ACCESS SHARE`, so a retention run cannot drop a partition the +call has listed before it reaches it. + +A new partition's bounds are UTC midnights, whatever the zone of the session +that provisions it. A partition an earlier release cut at another zone's +midnight still borders it, and a range from UTC midnight would overlap one cut +west of UTC or leave a gap after one cut east of it, where an insert would find +no partition. So a new partition starts where its predecessor ends, and ends +where its successor starts, when that neighbour's bound lies within a day of +the UTC midnight. `pkg/infra/postgres_audit_provisioning_test.go` holds these +rules against PostgreSQL. + ## SECURITY DEFINER functions list pg_temp last A `SECURITY DEFINER` function runs with its owner's authority. Unless its diff --git a/module/MEASUREMENT_RUNBOOKS.md b/module/MEASUREMENT_RUNBOOKS.md index 2b1022a84..36c1ed2af 100644 --- a/module/MEASUREMENT_RUNBOOKS.md +++ b/module/MEASUREMENT_RUNBOOKS.md @@ -70,3 +70,29 @@ provider responses into an incident channel. 4. Re-send the corrected provider quantity with a stable reconciliation key. 5. Verify source events, aggregate, customer history, entitlement limit, and provider quantity agree after the late-arrival window. + +## `retention` + +1. Read the accounts `retention` log line `scheduled run failed`. It names each + failed resource, the step (`load`, `provision`, `policy` or `remove`) and the + database's error. `saas.retention.failing` is 1 for the same resource and + step until a run no longer fails it, and carries no record. +2. SQLSTATE 55P03 means retention or audit partition provisioning waited ten + seconds in all for its locks and gave up, or found the `audit_events` policy + being changed: nothing was dropped or created. Find the transaction holding + `audit_events`, one of its partitions or the policy's row in `pg_locks` and + `pg_stat_activity`. The next run, a day later or at the next restart, tries + again, and partitions are provisioned three months ahead, so one refusal does + not stop audit writes. +3. SQLSTATE 55000 means an audit partition retention chose was renamed out of + its names, or a partition it or provisioning was locking was dropped, while + it waited for the lock, and nothing was dropped or changed. Look for the + session renaming or dropping audit partitions; the next run decides again + from the catalog as it stands. +4. A `policy` failure is a `data_retention_policies` window that is not a + positive number of days, and SQLSTATE 22023 from the audit drop is a cutoff + later than the `audit_events` policy allows by the database's clock. Correct + the policy or the caller; never widen the check. +5. Confirm the next run reports no failure, which clears the alert, and that the + partitions past the `audit_events` window are gone while the months ahead + exist. diff --git a/module/services/accounts/code/pkg/business/audit_typed_integration_test.go b/module/services/accounts/code/pkg/business/audit_typed_integration_test.go index ef6ce41f8..e50e39b73 100644 --- a/module/services/accounts/code/pkg/business/audit_typed_integration_test.go +++ b/module/services/accounts/code/pkg/business/audit_typed_integration_test.go @@ -11,6 +11,7 @@ import ( "github.com/stretchr/testify/require" "accounts/pkg/business" + "accounts/pkg/infra/storetx" ) // TestAuditEventTypes_Parity verifies the DB projection reconciles exactly to @@ -126,7 +127,9 @@ func TestQueryAuditLog_FiltersByNamespace(t *testing.T) { // TestAuditRetention_DropsOldPartitions proves retention actually removes data // now: it drops whole partitions whose range is entirely older than the cutoff // (which the append-only trigger would have blocked as a row DELETE), while -// leaving current-month data intact. +// leaving current-month data intact. The old month lies far past any window +// the audit_events policy keeps, since a cutoff the policy does not allow is +// refused. func TestAuditRetention_DropsOldPartitions(t *testing.T) { clearData(t) ctx := testCtx @@ -134,7 +137,11 @@ func TestAuditRetention_DropsOldPartitions(t *testing.T) { _, org := mustUserAndOrg(t, ctx, "ret@audit-test.com", "ret-audit", "Retention Co") require.NoError(t, testStore.WithControlPlane(ctx, func(ctx context.Context) error { - return testStore.EnsureAuditPartitions(ctx, 3) + if err := testStore.EnsureAuditPartitions(ctx, 3); err != nil { + return err + } + _, err := storetx.Tx(ctx).Exec(ctx, `SELECT audit_events_ensure_partition('2000-02-15'::date)`) + return err })) // A current-month event we expect to survive retention. @@ -144,18 +151,17 @@ func TestAuditRetention_DropsOldPartitions(t *testing.T) { }) })) - // Cutoff = first instant of the current month. The empty prior-month - // partitions (seeded at migration + EnsureAuditPartitions) are entirely - // older than the cutoff and must be dropped; the current partition must not. - now := time.Now().UTC() - cutoff := time.Date(now.Year(), now.Month(), 1, 0, 0, 0, 0, time.UTC) + // The February 2000 partition is entirely older than the cutoff and must be + // dropped; the current partition must not. + cutoff := time.Date(2000, 3, 1, 0, 0, 0, 0, time.UTC) var dropped int64 require.NoError(t, testStore.WithControlPlane(ctx, func(ctx context.Context) error { var err error dropped, err = testStore.DropAuditPartitionsBefore(ctx, cutoff) return err })) - require.Positive(t, dropped, "expected at least one old empty partition to be dropped") + require.Positive(t, dropped, "expected the old partition to be dropped") + now := time.Now().UTC() // Current-month data survives. past := now.Add(-time.Hour) diff --git a/module/services/accounts/code/pkg/business/retention.go b/module/services/accounts/code/pkg/business/retention.go index bb4c8a816..54ec4a001 100644 --- a/module/services/accounts/code/pkg/business/retention.go +++ b/module/services/accounts/code/pkg/business/retention.go @@ -3,6 +3,7 @@ package business import ( "context" "fmt" + "strings" "time" "github.com/codefly-dev/core/wool" @@ -16,56 +17,162 @@ type githubAppSetupRetentionStore interface { DeleteExpiredGitHubAppSetups(ctx context.Context, before time.Time) (int64, error) } -// RunRetention loads all data retention policies and deletes records older -// than the configured retention period for each resource type. Returns a -// summary of deleted counts per resource type. +// earliestStoredInstant is the earliest instant a PostgreSQL timestamp with +// time zone can hold, 24 November 4714 BC at 00:00 UTC. No record is older. +var earliestStoredInstant = time.Date(-4713, time.November, 24, 0, 0, 0, 0, time.UTC) + +// retentionCutoff returns the instant before which a record has outlived a +// window of days, counted back from now, and whether any record can be that +// old. A window that is not a positive number of days is an error: read +// literally, zero days reaches every record written before now, and fewer +// reach records written after it. A day is 24 hours wherever the process runs: +// the window is counted back in UTC, where every day has 24, so the cutoff is +// exactly days*24h before now, and stays before now however long the window +// is, where a time.Duration overflows past 106751 days. A window reaching back +// past earliestStoredInstant has nothing older than its cutoff to remove. +func retentionCutoff(now time.Time, days int) (before time.Time, anyOlder bool, err error) { + if days <= 0 { + return time.Time{}, false, fmt.Errorf("a retention window is a positive number of days, not %d", days) + } + before = now.UTC().AddDate(0, 0, -days) + return before, !before.Before(earliestStoredInstant), nil +} + +// RetentionStep names the part of a retention run that failed. +type RetentionStep string + +const ( + // RetentionStepLoad is reading the policies, or the database clock every + // cutoff is counted from. + RetentionStepLoad RetentionStep = "load" + // RetentionStepProvision is provisioning audit partitions. + RetentionStepProvision RetentionStep = "provision" + // RetentionStepPolicy is a policy no run can apply: its window is not a + // positive number of days. + RetentionStepPolicy RetentionStep = "policy" + // RetentionStepRemove is removing a resource's expired records. + RetentionStepRemove RetentionStep = "remove" +) + +// RetentionFailure is one failed part of a retention run. +type RetentionFailure struct { + Resource string + Step RetentionStep + Err error +} + +// RetentionError is a retention run that did not do all it should. A run goes +// on past a failing part, so the error lists every failure, and the counts the +// run returns beside it are those of the parts that succeeded. +type RetentionError struct { + Failures []RetentionFailure +} + +func (e *RetentionError) Error() string { + parts := make([]string, len(e.Failures)) + for i, f := range e.Failures { + parts[i] = fmt.Sprintf("%s %s: %v", f.Resource, f.Step, f.Err) + } + return "retention failed: " + strings.Join(parts, "; ") +} + +func (e *RetentionError) Unwrap() []error { + errs := make([]error, len(e.Failures)) + for i, f := range e.Failures { + errs[i] = f.Err + } + return errs +} + +// RunRetention provisions audit partitions, then deletes, for each resource +// with a retention policy, the records older than its window, counted back from +// the database's clock. It returns the number of records removed per resource. +// A failing part does not stop the others, and every failure comes back in one +// *RetentionError beside the counts of the parts that succeeded, so the caller +// reports a run that did not do all it should rather than a log line. // // Cross-tenant by nature: retention is a platform-wide cleanup that // must touch every tenant's rows. audit_events + webhook_deliveries // are RLS-protected — wrap each delete in WithControlPlane so the policy // lets the cross-tenant scan through. sessions and notifications are -// in the skip-list (user-scoped) but we still bypass for symmetry. +// in the skip-list (user-scoped) but we still bypass for symmetry. The audit +// partition drop runs in a control-plane transaction the store opens for it. func (s *Service) RunRetention(ctx context.Context) (map[string]int64, error) { w := wool.Get(ctx).In("RunRetention") - policies, err := s.store.GetRetentionPolicies(ctx) + deleted := make(map[string]int64) + var failures []RetentionFailure + fail := func(resource string, step RetentionStep, err error) { + failures = append(failures, RetentionFailure{Resource: resource, Step: step, Err: err}) + } + outcome := func() (map[string]int64, error) { + if len(failures) > 0 { + return deleted, &RetentionError{Failures: failures} + } + return deleted, nil + } + + // Audit writes need the months ahead to have partitions whatever the + // policies say, so they are provisioned on every run, policy or none. + if err := s.store.WithControlPlane(ctx, func(ctx context.Context) error { + return s.store.EnsureAuditPartitions(ctx, 3) + }); err != nil { + fail("audit_events", RetentionStepProvision, err) + } + + // Every cutoff is counted from the database's clock. The windows are the + // database's records, and a process clock running ahead would otherwise + // remove records still inside them. + now, err := s.store.DatabaseNow(ctx) if err != nil { - return nil, w.Wrapf(err, "cannot load retention policies") + fail("data_retention_policies", RetentionStepLoad, fmt.Errorf("read the database clock: %w", err)) + return outcome() } - deleted := make(map[string]int64) + policies, err := s.store.GetRetentionPolicies(ctx) + if err != nil { + fail("data_retention_policies", RetentionStepLoad, err) + } for _, p := range policies { - before := time.Now().Add(-time.Duration(p.RetentionDays) * 24 * time.Hour) + before, anyOlder, windowErr := retentionCutoff(now, p.RetentionDays) + if windowErr != nil { + fail(p.ResourceType, RetentionStepPolicy, windowErr) + continue + } var count int64 - bypassErr := s.store.WithControlPlane(ctx, func(ctx context.Context) error { - var bErr error - switch p.ResourceType { - case "audit_events": - // audit_events is append-only and range-partitioned by - // created_at: retention drops whole partitions older than the - // window (DDL that sidesteps the immutability trigger) rather - // than issuing a row DELETE the trigger would reject. Provision - // upcoming partitions on the same cycle so writes never hit a - // missing range. - if ensureErr := s.store.EnsureAuditPartitions(ctx, 3); ensureErr != nil { - w.Warn(fmt.Sprintf("audit partition provisioning failed: %v", ensureErr)) + var removeErr error + switch { + case !anyOlder: + // Nothing is older than the cutoff. + case p.ResourceType == "audit_events": + // audit_events is append-only and range-partitioned by created_at: + // retention drops whole partitions older than the window (DDL that + // sidesteps the immutability trigger) rather than issuing a row + // DELETE the trigger would reject. The drop decides which partitions + // are due once it holds its lock, from the catalog as it stands then, + // which takes a transaction of its own: the store opens one at READ + // COMMITTED, outside the one that provisioned partitions above. + count, removeErr = s.store.DropAuditPartitionsBefore(ctx, before) + default: + removeErr = s.store.WithControlPlane(ctx, func(ctx context.Context) error { + var bErr error + switch p.ResourceType { + case "sessions": + count, bErr = s.store.DeleteOldSessions(ctx, before) + case "webhook_deliveries": + count, bErr = s.store.DeleteOldWebhookDeliveries(ctx, before) + case "notifications": + count, bErr = s.store.DeleteOldNotifications(ctx, before) + default: + w.Debug("unknown retention resource type", wool.Field("type", p.ResourceType)) } - count, bErr = s.store.DropAuditPartitionsBefore(ctx, before) - case "sessions": - count, bErr = s.store.DeleteOldSessions(ctx, before) - case "webhook_deliveries": - count, bErr = s.store.DeleteOldWebhookDeliveries(ctx, before) - case "notifications": - count, bErr = s.store.DeleteOldNotifications(ctx, before) - default: - w.Debug("unknown retention resource type", wool.Field("type", p.ResourceType)) - } - return bErr - }) - - if bypassErr != nil { - w.Warn(fmt.Sprintf("retention cleanup for %s failed: %v", p.ResourceType, bypassErr)) + return bErr + }) + } + + if removeErr != nil { + fail(p.ResourceType, RetentionStepRemove, removeErr) continue } deleted[p.ResourceType] = count @@ -79,15 +186,14 @@ func (s *Service) RunRetention(ctx context.Context) (map[string]int64, error) { // retention data. Remove expired rows after a short forensic window even // when an operator has not configured a generic retention policy. if ceremonyStore, ok := s.store.(authenticationCeremonyRetentionStore); ok { - bypassErr := s.store.WithControlPlane(ctx, func(ctx context.Context) error { - webauthn, mfaLogin, clientCodes, err := ceremonyStore.DeleteExpiredAuthenticationCeremonies(ctx, time.Now().Add(-24*time.Hour)) + if err := s.store.WithControlPlane(ctx, func(ctx context.Context) error { + webauthn, mfaLogin, clientCodes, err := ceremonyStore.DeleteExpiredAuthenticationCeremonies(ctx, now.Add(-24*time.Hour)) deleted["webauthn_ceremonies"] = webauthn deleted["mfa_login_transactions"] = mfaLogin deleted["client_authorization_codes"] = clientCodes return err - }) - if bypassErr != nil { - w.Warn("authentication ceremony cleanup failed", wool.ErrField(bypassErr)) + }); err != nil { + fail("authentication_ceremonies", RetentionStepRemove, err) } } @@ -96,17 +202,16 @@ func (s *Service) RunRetention(ctx context.Context) (map[string]int64, error) { // on the same forensic window so an abandoned connect attempt does not leave // a row behind permanently. if setupStore, ok := s.store.(githubAppSetupRetentionStore); ok { - bypassErr := s.store.WithControlPlane(ctx, func(ctx context.Context) error { - setups, err := setupStore.DeleteExpiredGitHubAppSetups(ctx, time.Now().Add(-24*time.Hour)) + if err := s.store.WithControlPlane(ctx, func(ctx context.Context) error { + setups, err := setupStore.DeleteExpiredGitHubAppSetups(ctx, now.Add(-24*time.Hour)) deleted["github_app_setups"] = setups return err - }) - if bypassErr != nil { - w.Warn("github app setup cleanup failed", wool.ErrField(bypassErr)) + }); err != nil { + fail("github_app_setups", RetentionStepRemove, err) } } - return deleted, nil + return outcome() } // PurgeExpiredWorkContextReplays reclaims single-use replay markers whose diff --git a/module/services/accounts/code/pkg/business/retention_cutoff_test.go b/module/services/accounts/code/pkg/business/retention_cutoff_test.go new file mode 100644 index 000000000..d9130c356 --- /dev/null +++ b/module/services/accounts/code/pkg/business/retention_cutoff_test.go @@ -0,0 +1,27 @@ +package business + +import ( + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +// A day of a retention window is 24 hours in whatever zone the process runs. +// Counted by the calendar in a zone that keeps daylight saving time, a window +// crossing the spring change would end an hour later, removing records an hour +// short of the window, and one crossing the autumn change an hour earlier. +func TestRetentionCutoffCountsDaysOf24HoursInAnyZone(t *testing.T) { + newYork, err := time.LoadLocation("America/New_York") + require.NoError(t, err) + for _, now := range []time.Time{ + time.Date(2027, time.March, 15, 12, 0, 0, 0, newYork), // 30 days back crosses 14 March + time.Date(2027, time.November, 15, 12, 0, 0, 0, newYork), // 30 days back crosses 7 November + } { + before, anyOlder, err := retentionCutoff(now, 30) + require.NoError(t, err) + require.True(t, anyOlder) + want := now.Add(-30 * 24 * time.Hour) + require.True(t, before.Equal(want), "30 days before %s is %s, not %s", now, want, before) + } +} diff --git a/module/services/accounts/code/pkg/business/retention_test.go b/module/services/accounts/code/pkg/business/retention_test.go new file mode 100644 index 000000000..c5e252b25 --- /dev/null +++ b/module/services/accounts/code/pkg/business/retention_test.go @@ -0,0 +1,220 @@ +package business_test + +import ( + "context" + "errors" + "testing" + "time" + + "github.com/stretchr/testify/require" + + "accounts/pkg/business" +) + +// retentionStoreFake records what RunRetention asks of the store, and whether +// each call ran inside a control-plane transaction. Its clock is the database's, +// and each part can be made to fail. +type retentionStoreFake struct { + business.Store + policies []*business.RetentionPolicy + databaseNow time.Time + clockErr error + ensureErr error + removeErr map[string]error + inControlPlane bool + ensured []bool + cutoffs map[string][]time.Time + auditDrops []bool +} + +// retentionDatabaseNow is the database's clock in these tests: a fixed instant, +// hours away from the process's, with a fraction of a second, in a zone that +// keeps daylight saving time, so a cutoff counted from anything else, or in +// another zone, shows. +var retentionDatabaseNow = func() time.Time { + newYork, err := time.LoadLocation("America/New_York") + if err != nil { + panic(err) + } + return time.Date(2024, time.March, 11, 0, 30, 0, 123456789, newYork) +}() + +func newRetentionStoreFake(policies ...*business.RetentionPolicy) *retentionStoreFake { + return &retentionStoreFake{ + policies: policies, + databaseNow: retentionDatabaseNow, + removeErr: map[string]error{}, + cutoffs: map[string][]time.Time{}, + } +} + +func (f *retentionStoreFake) GetRetentionPolicies(context.Context) ([]*business.RetentionPolicy, error) { + return f.policies, nil +} + +func (f *retentionStoreFake) DatabaseNow(context.Context) (time.Time, error) { + return f.databaseNow, f.clockErr +} + +func (f *retentionStoreFake) WithControlPlane(ctx context.Context, fn func(context.Context) error) error { + f.inControlPlane = true + defer func() { f.inControlPlane = false }() + return fn(ctx) +} + +func (f *retentionStoreFake) EnsureAuditPartitions(context.Context, int) error { + f.ensured = append(f.ensured, f.inControlPlane) + return f.ensureErr +} + +func (f *retentionStoreFake) remove(resource string, before time.Time) (int64, error) { + f.cutoffs[resource] = append(f.cutoffs[resource], before) + if err := f.removeErr[resource]; err != nil { + return 0, err + } + return 1, nil +} + +func (f *retentionStoreFake) DropAuditPartitionsBefore(_ context.Context, before time.Time) (int64, error) { + f.auditDrops = append(f.auditDrops, f.inControlPlane) + return f.remove("audit_events", before) +} + +func (f *retentionStoreFake) DeleteOldSessions(_ context.Context, before time.Time) (int64, error) { + return f.remove("sessions", before) +} + +func (f *retentionStoreFake) DeleteOldWebhookDeliveries(_ context.Context, before time.Time) (int64, error) { + return f.remove("webhook_deliveries", before) +} + +func (f *retentionStoreFake) DeleteOldNotifications(_ context.Context, before time.Time) (int64, error) { + return f.remove("notifications", before) +} + +var retainedResourceTypes = []string{"audit_events", "sessions", "webhook_deliveries", "notifications"} + +func retentionPolicies(days int) []*business.RetentionPolicy { + var policies []*business.RetentionPolicy + for _, resource := range retainedResourceTypes { + policies = append(policies, &business.RetentionPolicy{ResourceType: resource, RetentionDays: days}) + } + return policies +} + +func runRetention(t *testing.T, store *retentionStoreFake) (map[string]int64, error) { + t.Helper() + service, err := business.NewService(store) + require.NoError(t, err) + return service.RunRetention(context.Background()) +} + +// retentionFailures lists a run's failed parts as "resource step". +func retentionFailures(t *testing.T, err error) []string { + t.Helper() + var run *business.RetentionError + require.ErrorAs(t, err, &run, "a run that did not do all it should says so") + var failed []string + for _, failure := range run.Failures { + require.Error(t, failure.Err) + failed = append(failed, failure.Resource+" "+string(failure.Step)) + } + return failed +} + +// A window that is not a positive number of days is a policy no run can apply. +// Read literally, zero days reaches every record written before the run, and +// fewer reach records written after it, so the run removes nothing for it and +// reports the policy as a failure, rather than reading it as anything else. +// Audit partitions are still provisioned: writes need them whatever the window. +func TestRetentionRefusesAWindowThatIsNotAPositiveNumberOfDays(t *testing.T) { + for _, days := range []int{0, -1, -365} { + store := newRetentionStoreFake(retentionPolicies(days)...) + deleted, err := runRetention(t, store) + require.Equal(t, []string{"audit_events policy", "sessions policy", "webhook_deliveries policy", "notifications policy"}, + retentionFailures(t, err), "retention_days=%d is reported for every resource", days) + require.Empty(t, store.cutoffs, "retention_days=%d removes nothing", days) + require.Empty(t, deleted, "retention_days=%d reports nothing removed", days) + require.Equal(t, []bool{true}, store.ensured, "audit partitions are provisioned whatever the window") + } +} + +// A window is counted back from the database's clock, in days of 24 hours, so +// its cutoff is exactly the window before the database's present however long +// the window is, including past the 106751 days a time.Duration can hold, and +// whatever this process's clock says. A window reaching back past the earliest +// instant a timestamp can hold has nothing older than it, and removes nothing. +func TestRetentionCountsEachWindowBackFromTheDatabaseClock(t *testing.T) { + for _, days := range []int{1, 10, 365, 106751, 106752, 150000, 213503, 213504, 213600, 999999, 2_000_000, 9999999, 2147483647} { + store := newRetentionStoreFake(retentionPolicies(days)...) + _, err := runRetention(t, store) + require.NoError(t, err) + + window := int64(days) * 24 * 60 * 60 + want := time.Unix(retentionDatabaseNow.Unix()-window, int64(retentionDatabaseNow.Nanosecond())) + reachable := !want.Before(time.Date(-4713, time.November, 24, 0, 0, 0, 0, time.UTC)) + for _, resource := range retainedResourceTypes { + cutoffs := store.cutoffs[resource] + if !reachable { + require.Empty(t, cutoffs, "retention_days=%d reaches past every record; %s removes nothing", days, resource) + continue + } + require.Len(t, cutoffs, 1, "retention_days=%d: %s", days, resource) + require.True(t, cutoffs[0].Equal(want), + "retention_days=%d: the %s cutoff is %s, %d days of 24 hours before the database's clock, not %s", + days, resource, want, days, cutoffs[0]) + } + } +} + +// A run goes on past a part that fails, and reports every failure together, +// with the counts of the parts that succeeded: one resource's lock wait or +// broken table does not stop the others' retention, nor hide behind their +// success. +func TestRetentionReportsEveryFailedPartAndGoesOn(t *testing.T) { + store := newRetentionStoreFake(retentionPolicies(30)...) + store.ensureErr = errors.New("provisioning waited too long") + store.removeErr["audit_events"] = errors.New("drop waited too long") + store.removeErr["sessions"] = errors.New("sessions unavailable") + + deleted, err := runRetention(t, store) + require.Equal(t, []string{"audit_events provision", "audit_events remove", "sessions remove"}, retentionFailures(t, err)) + require.Equal(t, map[string]int64{"webhook_deliveries": 1, "notifications": 1}, deleted, + "the resources that succeeded are counted, and only they") + for _, resource := range retainedResourceTypes { + require.Len(t, store.cutoffs[resource], 1, "%s was attempted", resource) + } +} + +// Without the database's clock no cutoff can be counted, so the run removes +// nothing and says why. +func TestRetentionRemovesNothingWithoutTheDatabaseClock(t *testing.T) { + store := newRetentionStoreFake(retentionPolicies(30)...) + store.clockErr = errors.New("database unavailable") + deleted, err := runRetention(t, store) + require.Equal(t, []string{"data_retention_policies load"}, retentionFailures(t, err)) + require.Empty(t, store.cutoffs) + require.Empty(t, deleted) +} + +// Audit writes need the months ahead to have partitions whatever the policies +// say, so a run provisions them with no audit_events policy at all. +func TestRetentionProvisionsAuditPartitionsWhateverThePolicies(t *testing.T) { + store := newRetentionStoreFake(&business.RetentionPolicy{ResourceType: "sessions", RetentionDays: 90}) + _, err := runRetention(t, store) + require.NoError(t, err) + require.Equal(t, []bool{true}, store.ensured, "partitions are provisioned, in a control-plane transaction") + require.Empty(t, store.auditDrops, "with no audit_events policy, nothing is dropped") +} + +// The audit drop decides which partitions are due once it holds its lock, from +// the catalog as it stands then, which takes a transaction of its own: the drop +// runs outside the control-plane transaction that provisions partitions, and the +// store opens it at READ COMMITTED. +func TestRetentionDropsAuditPartitionsOutsideTheProvisioningTransaction(t *testing.T) { + store := newRetentionStoreFake(&business.RetentionPolicy{ResourceType: "audit_events", RetentionDays: 365}) + _, err := runRetention(t, store) + require.NoError(t, err) + require.Equal(t, []bool{true}, store.ensured, "partitions are provisioned in a control-plane transaction") + require.Equal(t, []bool{false}, store.auditDrops, "the drop runs in a transaction of its own") +} diff --git a/module/services/accounts/code/pkg/business/store.go b/module/services/accounts/code/pkg/business/store.go index 654c18dc6..f6b6ccef6 100644 --- a/module/services/accounts/code/pkg/business/store.go +++ b/module/services/accounts/code/pkg/business/store.go @@ -558,6 +558,11 @@ type Store interface { SyncAuditEventTypes(ctx context.Context, defs []AuditEventDefinition) error ListAuditEventTypes(ctx context.Context) ([]AuditEventTypeRow, error) EnsureAuditPartitions(ctx context.Context, months int) error + // DropAuditPartitionsBefore drops the audit partitions whose recorded range + // ends by `before`, which must be no later than the audit_events retention + // policy allows by the database's clock. It runs on a transaction already on + // ctx, which must be READ COMMITTED, or else in a control-plane transaction + // of its own at READ COMMITTED. DropAuditPartitionsBefore(ctx context.Context, before time.Time) (int64, error) // Invitations @@ -888,6 +893,9 @@ type Store interface { // append-only trigger blocks that — but a partition drop; see // DropAuditPartitionsBefore above. GetRetentionPolicies(ctx context.Context) ([]*RetentionPolicy, error) + // DatabaseNow reads the database's clock. Retention counts every cutoff + // from it rather than from this process's clock, which may run ahead. + DatabaseNow(ctx context.Context) (time.Time, error) DeleteOldSessions(ctx context.Context, before time.Time) (int64, error) DeleteOldWebhookDeliveries(ctx context.Context, before time.Time) (int64, error) DeleteOldNotifications(ctx context.Context, before time.Time) (int64, error) diff --git a/module/services/accounts/code/pkg/infra/postgres_audit_provisioning_test.go b/module/services/accounts/code/pkg/infra/postgres_audit_provisioning_test.go new file mode 100644 index 000000000..a60a70b10 --- /dev/null +++ b/module/services/accounts/code/pkg/infra/postgres_audit_provisioning_test.go @@ -0,0 +1,400 @@ +//go:build !pure + +package infra_test + +import ( + "context" + "fmt" + "strings" + "sync" + "testing" + "time" + + codefly "github.com/codefly-dev/sdk-go" + "github.com/google/uuid" + "github.com/jackc/pgx/v5" + "github.com/jackc/pgx/v5/pgconn" + "github.com/jackc/pgx/v5/pgxpool" + "github.com/stretchr/testify/require" + + "accounts/pkg/infra/storetx" +) + +// Audit partition provisioning creates the months audit writes land in, at +// startup and on each retention tick, through the store's SECURITY DEFINER +// functions. These tests hold it to bounds that do not depend on the session +// that provisions, to neighbours an earlier release cut at another zone's +// midnight, and to giving up rather than holding audit writes behind a lock it +// cannot have. + +// A new partition is bounded by UTC midnights whatever the zone of the session +// that provisions it, so its range does not depend on who ran the call. +func TestANewPartitionIsBoundedByUTCMidnightsWhateverTheSessionsZone(t *testing.T) { + for _, zone := range []string{"America/New_York", "Asia/Kolkata", "Pacific/Auckland", "UTC"} { + t.Run(zone, func(t *testing.T) { + asRetention(t, func(ctx context.Context, tx pgx.Tx) { + retentionEnsureMonth(t, ctx, tx, zone, "2002-05-15") + lower, upper := retentionBounds(t, ctx, tx, "audit_events_2002_05") + require.Equal(t, time.Date(2002, 5, 1, 0, 0, 0, 0, time.UTC), lower) + require.Equal(t, time.Date(2002, 6, 1, 0, 0, 0, 0, time.UTC), upper) + }) + }) + } +} + +// A partition an earlier release cut at another zone's midnight still borders +// the months provisioned after it. A new month starts where its predecessor ends +// and ends where its successor starts: a range from UTC midnight would overlap a +// neighbour cut west of UTC, which PostgreSQL refuses, or leave a gap beside one +// cut east of it, where an insert finds no partition. Every instant at the seam +// lands in one of the two. +func TestANewPartitionMeetsANeighbourCutAtAnotherZonesMidnight(t *testing.T) { + const month = "audit_events_2002_08" + for _, tc := range []struct { + name, zone, neighbourDay, neighbour string + neighbourIsNext bool + }{ + {"after a month cut west of UTC", "America/New_York", "2002-07-15", "audit_events_2002_07", false}, + {"after a month cut east of UTC", "Asia/Tokyo", "2002-07-15", "audit_events_2002_07", false}, + {"before a month cut west of UTC", "America/New_York", "2002-09-15", "audit_events_2002_09", true}, + {"before a month cut east of UTC", "Asia/Tokyo", "2002-09-15", "audit_events_2002_09", true}, + } { + t.Run(tc.name, func(t *testing.T) { + asRetention(t, func(ctx context.Context, tx pgx.Tx) { + retentionLegacyMonth(t, ctx, tx, tc.zone, tc.neighbourDay) + retentionEnsureMonth(t, ctx, tx, "UTC", "2002-08-15") + + neighbourLower, neighbourUpper := retentionBounds(t, ctx, tx, tc.neighbour) + lower, upper := retentionBounds(t, ctx, tx, month) + seam, earlier, later := lower, tc.neighbour, month + if tc.neighbourIsNext { + seam, earlier, later = upper, month, tc.neighbour + require.Equal(t, time.Date(2002, 8, 1, 0, 0, 0, 0, time.UTC), lower, "the month starts at UTC midnight") + require.Equal(t, neighbourLower, upper, "and ends where its successor starts") + } else { + require.Equal(t, neighbourUpper, lower, "the month starts where its predecessor ends") + require.Equal(t, time.Date(2002, 9, 1, 0, 0, 0, 0, time.UTC), upper, "and ends at UTC midnight") + } + require.NotZero(t, seam.Hour(), "the premise: the neighbour's bound is not a UTC midnight") + + _, err := tx.Exec(ctx, `SET LOCAL ROLE app_control_plane`) + require.NoError(t, err) + require.Equal(t, earlier, retentionInsertEvent(t, ctx, tx, seam.Add(-time.Second)), "the last second before the seam") + require.Equal(t, later, retentionInsertEvent(t, ctx, tx, seam), "the seam itself") + }) + }) + } +} + +// Creating a partition takes audit_events ACCESS EXCLUSIVE, which every audit +// write queues behind for as long as provisioning waits for it. Behind a reader +// that does not finish, provisioning gives up after ten seconds and creates +// nothing; with nothing to create it takes no such lock and does not wait at +// all; once the reader is gone, the partition is created. +func TestProvisioningRefusesInsteadOfHangingBehindAReader(t *testing.T) { + const probe = "audit_events_1989_01" + retentionDropTableAfter(t, probe) + // A provisioning call that does not bound its own wait fails here on this + // deadline, rather than hang the suite. + ensure := func() error { + ctx, cancel := context.WithTimeout(testCtx, 30*time.Second) + defer cancel() + return testStore.WithControlPlane(ctx, func(ctx context.Context) error { + _, err := storetx.Tx(ctx).Exec(ctx, `SELECT audit_events_ensure_partition('1989-01-15'::date)`) + return err + }) + } + provision := func() error { + return testStore.WithControlPlane(testCtx, func(ctx context.Context) error { + return testStore.EnsureAuditPartitions(ctx, 3) + }) + } + require.NoError(t, provision(), "the premise: every month the store provisions exists") + + release := retentionHoldReader(t) + started := time.Now() + err := ensure() + var pgErr *pgconn.PgError + require.ErrorAs(t, err, &pgErr, "provisioning gave up for want of its lock") + require.Equal(t, "55P03", pgErr.Code, "lock_not_available") + require.Less(t, time.Since(started), 11*time.Second) + exists, _ := retentionPartitionRows(t, probe) + require.False(t, exists, "provisioning that gave up created nothing") + + started = time.Now() + require.NoError(t, provision(), "with nothing to create, provisioning does not wait for the reader") + require.Less(t, time.Since(started), 5*time.Second) + + release() + require.NoError(t, ensure()) + exists, _ = retentionPartitionRows(t, probe) + require.True(t, exists, "with the reader gone, the partition is created") +} + +// Provisioning waits ten seconds in all for its locks, not ten for each. One +// session holds audit_events, which creating a new month needs, for six seconds; +// another holds an existing partition, whose policies bringing it in step reads, +// until provisioning is over. Provisioning gives up when its ten seconds are +// spent, and creates nothing. +func TestProvisioningWaitsTenSecondsInAllForItsLocks(t *testing.T) { + const held = "audit_events_1989_06" + retentionDropTableAfter(t, held) + retentionProvisionMonth(t, "1989-06-15", time.Date(1989, 6, 10, 12, 0, 0, 0, time.UTC), uuid.NewString()) + + dsn, err := codefly.For(testCtx).Service("store").Secret("postgres", "owner-connection") + require.NoError(t, err) + hold := func(statement string) (release func()) { + conn, err := pgx.Connect(testCtx, dsn) + require.NoError(t, err) + t.Cleanup(func() { _ = conn.Close(testCtx) }) + _, err = conn.Exec(testCtx, `BEGIN; `+statement) + require.NoError(t, err) + var once sync.Once + release = func() { once.Do(func() { _, err := conn.Exec(testCtx, `COMMIT`); require.NoError(t, err) }) } + t.Cleanup(release) + return release + } + awaitWaiting := func(relation, mode string) { + require.Eventually(t, func() bool { + var waiting int + err := testPool.QueryRow(testCtx, ` + SELECT count(*) FROM pg_locks WHERE relation = to_regclass($1) AND mode = $2 AND NOT granted`, + relation, mode).Scan(&waiting) + return err == nil && waiting > 0 + }, 10*time.Second, 20*time.Millisecond, "provisioning never waited for %s", relation) + } + + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + // A month ahead that no call has provisioned, so this call must create it. + var ahead int + require.NoError(t, conn.QueryRow(ctx, ` + SELECT min(k) FROM generate_series(4, 24) AS k + WHERE to_regclass('public.audit_events_' || + to_char(date_trunc('month', now() AT TIME ZONE 'UTC') + make_interval(months => k), 'YYYY_MM')) IS NULL`, + ).Scan(&ahead)) + + releaseParent := hold(`LOCK TABLE ONLY public.audit_events IN ACCESS SHARE MODE`) + releasePartition := hold(`LOCK TABLE public.` + held + ` IN ACCESS EXCLUSIVE MODE`) + + tx, err := conn.Begin(ctx) + require.NoError(t, err) + defer func() { _ = tx.Rollback(ctx) }() + _, err = tx.Exec(ctx, `SET LOCAL ROLE app_control_plane`) + require.NoError(t, err) + type outcome struct { + err error + elapsed time.Duration + } + ran := make(chan outcome, 1) + go func() { + started := time.Now() + _, err := tx.Exec(ctx, `SELECT audit_events_provision_partitions($1)`, ahead) + ran <- outcome{err, time.Since(started)} + }() + awaitWaiting("public.audit_events", "AccessExclusiveLock") + time.Sleep(6 * time.Second) + releaseParent() + awaitWaiting("public."+held, "AccessShareLock") + + select { + case got := <-ran: + var pgErr *pgconn.PgError + require.ErrorAs(t, got.err, &pgErr, "provisioning gave up for want of its locks") + require.Equal(t, "55P03", pgErr.Code, "lock_not_available") + require.Less(t, got.elapsed, 11*time.Second, "ten seconds of waiting in all, not ten for each lock") + case <-time.After(30 * time.Second): + t.Fatal("provisioning went on waiting past its ten seconds") + } + releasePartition() + }) +} + +// Bringing a partition in step locks the partition, not its name. While +// provisioning tries for a partition out of step, an operator renames it away +// and another partition to its name, and a reader that queued for the old name +// ends up holding that other partition to the end. Provisioning brings the +// partition it listed in step, under its new name, without waiting for that +// reader, and leaves the other partition as it was. The partition is out of +// step for want of policies, so provisioning reads it without opening it, and +// its first wait is for the partition's lock. +func TestBringingAPartitionInStepLocksThePartitionNotItsName(t *testing.T) { + const target, other, renamed, tmp = "audit_events_1993_06", "audit_events_1993_07", "audit_events_1993_06_renamed", "audit_events_1993_07_tmp" + for _, table := range []string{target, other, renamed, tmp} { + retentionDropTableAfter(t, table) + } + retentionProvisionMonth(t, "1993-06-15", time.Date(1993, 6, 10, 12, 0, 0, 0, time.UTC), uuid.NewString()) + retentionProvisionMonth(t, "1993-07-15", time.Date(1993, 7, 10, 12, 0, 0, 0, time.UTC), uuid.NewString()) + policies := func(table string) (count int) { + require.NoError(t, testPool.QueryRow(testCtx, + `SELECT count(*) FROM pg_policy WHERE polrelid = to_regclass('public.' || $1)`, table).Scan(&count)) + return count + } + require.NoError(t, testStore.WithControlPlane(testCtx, func(ctx context.Context) error { + return testStore.EnsureAuditPartitions(ctx, 3) + }), "the premise: every month provisioning makes exists") + operator := retentionSession(t) + _, err := operator.Exec(testCtx, `DO $$ + DECLARE + pol record; + BEGIN + FOR pol IN SELECT polname FROM pg_policy WHERE polrelid = 'public.`+target+`'::regclass LOOP + EXECUTE format('DROP POLICY %I ON public.`+target+`', pol.polname); + END LOOP; + END $$`) + require.NoError(t, err) + inStep := policies(other) + require.Zero(t, policies(target), "the premise: a partition out of step") + require.Positive(t, inStep) + + reader := retentionSession(t) + _, err = reader.Exec(testCtx, `BEGIN; LOCK TABLE ONLY public.`+target+` IN ACCESS SHARE MODE`) + require.NoError(t, err) + // The operator holds the other partition first, then waits for the target + // behind the reader. + renames := make(chan error, 1) + go func() { + _, err := operator.Exec(testCtx, `BEGIN; + ALTER TABLE public.`+other+` RENAME TO `+tmp+`; + ALTER TABLE public.`+target+` RENAME TO `+renamed+`; + ALTER TABLE public.`+tmp+` RENAME TO `+target+`; + COMMIT`) + renames <- err + }() + retentionAwaitWaiters(t, "public."+target, 1) + follower := retentionSession(t) + followed := make(chan error, 1) + go func() { + _, err := follower.Exec(testCtx, `BEGIN; LOCK TABLE public.`+target+` IN ACCESS SHARE MODE`) + followed <- err + }() + retentionAwaitWaiters(t, "public."+target, 2) + + type outcome struct { + err error + elapsed time.Duration + } + provisioned := make(chan outcome, 1) + go func() { + started := time.Now() + err := testStore.WithControlPlane(testCtx, func(ctx context.Context) error { + return testStore.EnsureAuditPartitions(ctx, 3) + }) + provisioned <- outcome{err, time.Since(started)} + }() + // Provisioning is at the target: trying for it, or queued for it. + require.Eventually(t, func() bool { + var waiting int + err := reader.QueryRow(testCtx, ` + SELECT count(*) FROM pg_stat_activity + WHERE query LIKE '%audit_events_provision_partitions%' AND pid <> pg_backend_pid() + AND (wait_event = 'PgSleep' OR wait_event_type = 'Lock')`).Scan(&waiting) + return err == nil && waiting > 0 + }, 10*time.Second, 20*time.Millisecond, "provisioning never came to the target") + _, err = reader.Exec(testCtx, `COMMIT`) + require.NoError(t, err) + require.NoError(t, <-renames, "the premise: the renames committed while provisioning tried for the target") + require.NoError(t, <-followed, "the premise: the follower holds the partition that took the target's name") + + select { + case got := <-provisioned: + require.NoError(t, got.err, "provisioning did not wait for the follower") + require.Less(t, got.elapsed, 11*time.Second) + case <-time.After(30 * time.Second): + t.Fatal("provisioning went on waiting past its ten seconds") + } + require.Equal(t, inStep, policies(renamed), "the partition it listed is in step, under its new name") + require.Equal(t, inStep, policies(target), "and the one that took its name is as it was") + _, err = follower.Exec(testCtx, `ROLLBACK`) + require.NoError(t, err) +} + +// Bringing every partition in step reads the list of partitions holding +// audit_events ACCESS SHARE, so a retention run cannot drop one it has listed +// before it reaches it. The call starts while retention waits for audit_events +// behind a reader, and queues behind retention; retention drops a partition, +// and the call, listing what is left, brings every partition in step. That +// holds for the store's provisioning call and for the one operators run. +func TestBringingEveryPartitionInStepSurvivesARetentionRunThatDropsOne(t *testing.T) { + for _, tc := range []struct { + name string + call func(ctx context.Context) error + }{ + {"provisioning", func(ctx context.Context) error { return testStore.EnsureAuditPartitions(ctx, 3) }}, + {"securing every partition", func(ctx context.Context) error { + _, err := storetx.Tx(ctx).Exec(ctx, `SELECT audit_events_secure_all_partitions()`) + return err + }}, + } { + t.Run(tc.name, func(t *testing.T) { + const march = "audit_events_1989_03" + retentionDropTableAfter(t, march) + retentionProvisionMonth(t, "1989-03-15", time.Date(1989, 3, 10, 12, 0, 0, 0, time.UTC), uuid.NewString()) + call := func() error { return testStore.WithControlPlane(testCtx, tc.call) } + require.NoError(t, call(), "the premise: the call succeeds with nothing else running") + + release := retentionHoldReader(t) + ran := make(chan retentionOutcome, 1) + go func() { + dropped, err := retentionCommitted(time.Date(1989, 4, 1, 0, 0, 0, 0, time.UTC)) + ran <- retentionOutcome{dropped, err} + }() + retentionAwaitQueuedLocks(t, 1) + called := make(chan error, 1) + go func() { called <- call() }() + require.Eventually(t, func() bool { + var waiting int + err := testPool.QueryRow(testCtx, ` + SELECT count(*) FROM pg_locks + WHERE relation = 'public.audit_events'::regclass AND mode = 'AccessShareLock' AND NOT granted`).Scan(&waiting) + return err == nil && waiting > 0 + }, 10*time.Second, 20*time.Millisecond, "the call never queued behind retention") + release() + + got := <-ran + require.NoError(t, got.err) + require.Equal(t, int64(1), got.dropped, "the premise: retention dropped a partition while the call waited") + require.NoError(t, <-called, "every partition left is brought in step") + }) + } +} + +// Provisioning and retention are DDL on the audit table, so execute on their +// entry points stays with the control plane, and on the functions they share +// with nobody but their owner. +func TestOnlyTheControlPlaneProvisionsOrRetiresAuditPartitions(t *testing.T) { + for _, tc := range []struct { + function string + controlPlane bool + }{ + {"audit_events_provision_partitions(integer)", true}, + {"audit_events_ensure_partition(date)", true}, + {"audit_events_secure_all_partitions()", true}, + {"audit_events_drop_partitions_before(timestamptz)", true}, + {"audit_events_create_partitions(date[], timestamptz)", false}, + {"audit_events_secure_partition_within(regclass, timestamptz)", false}, + {"audit_events_secure_partition(regclass)", false}, + {"audit_partition_lock_budget(timestamptz)", false}, + {"audit_partition_lock(regclass, timestamptz)", false}, + {"audit_partitions_due(timestamptz)", false}, + } { + t.Run(strings.SplitN(tc.function, "(", 2)[0], func(t *testing.T) { + var publicMay, controlPlaneMay, tenantMay bool + var config []string + require.NoError(t, testStore.WithControlPlane(testCtx, func(ctx context.Context) error { + return storetx.Tx(ctx).QueryRow(ctx, fmt.Sprintf(` + SELECT proacl IS NULL OR EXISTS (SELECT 1 FROM aclexplode(proacl) a WHERE a.grantee = 0 AND a.privilege_type = 'EXECUTE'), + has_function_privilege('app_control_plane', oid, 'EXECUTE'), + has_function_privilege('app_tenant', oid, 'EXECUTE'), + COALESCE(proconfig, ARRAY[]::text[]) + FROM pg_proc WHERE oid = 'public.%s'::regprocedure`, tc.function), + ).Scan(&publicMay, &controlPlaneMay, &tenantMay, &config) + })) + require.False(t, publicMay) + require.Equal(t, tc.controlPlane, controlPlaneMay) + require.False(t, tenantMay) + if tc.controlPlane { + require.Contains(t, config, "lock_timeout=10s", "every entry point bounds its waits") + } + }) + } +} diff --git a/module/services/accounts/code/pkg/infra/postgres_audit_registry.go b/module/services/accounts/code/pkg/infra/postgres_audit_registry.go index de4bf1b63..bd45be256 100644 --- a/module/services/accounts/code/pkg/infra/postgres_audit_registry.go +++ b/module/services/accounts/code/pkg/infra/postgres_audit_registry.go @@ -9,6 +9,7 @@ import ( "github.com/jackc/pgx/v5" "accounts/pkg/business" + "accounts/pkg/infra/storetx" ) // SyncAuditEventTypes upserts the code catalog into the audit_event_types @@ -106,24 +107,22 @@ func (s *PostgresStore) ListAuditEventTypes(ctx context.Context) ([]business.Aud } // EnsureAuditPartitions provisions the current month plus the next `months` -// (and the previous month, to absorb clock skew / late writes) via the -// SECURITY DEFINER maintenance function, then brings every partition's -// row-level security back in step with the parent's. Retention keeps far more -// months than this window provisions, and a partition queried by name is -// checked against its own policies, so a policy change on audit_events must -// reach the older partitions too. Called at startup and on each retention tick. +// (and the previous month, to absorb late writes), by the database's clock in +// UTC, then brings every partition's row-level security back in step with the +// parent's. Retention keeps far more months than this window provisions, and a +// partition queried by name is checked against its own policies, so a policy +// change on audit_events must reach the older partitions too. Called at startup +// and on each retention tick. +// +// It is one call to audit_events_provision_partitions, so its waits for locks +// add up to ten seconds at most: creating a partition takes audit_events ACCESS +// EXCLUSIVE, which audit writes queue behind, and is the only lock it takes +// when every partition is in step. When the ten seconds run out it fails with +// SQLSTATE 55P03 and creates nothing; the months ahead are provisioned in +// advance, so the next call has time to try again. func (s *PostgresStore) EnsureAuditPartitions(ctx context.Context, months int) error { - q := s.getQueryExecutor(ctx) - base := time.Now().UTC() - for m := -1; m <= months; m++ { - month := base.AddDate(0, m, 0) - first := time.Date(month.Year(), month.Month(), 1, 0, 0, 0, 0, time.UTC) - if _, err := q.Exec(ctx, `SELECT audit_events_ensure_partition($1::date)`, first); err != nil { - return fmt.Errorf("ensure audit partition %s: %w", first.Format("2006-01"), err) - } - } - if _, err := q.Exec(ctx, `SELECT audit_events_secure_all_partitions()`); err != nil { - return fmt.Errorf("secure audit partitions: %w", err) + if _, err := s.getQueryExecutor(ctx).Exec(ctx, `SELECT audit_events_provision_partitions($1)`, months); err != nil { + return fmt.Errorf("provision audit partitions: %w", err) } return nil } @@ -131,10 +130,37 @@ func (s *PostgresStore) EnsureAuditPartitions(ctx context.Context, months int) e // DropAuditPartitionsBefore drops every monthly partition whose entire range is // older than `before`, returning the number dropped. This is how audit // retention runs — DDL that never trips the append-only trigger. +// +// The database decides which partitions are older, from the bounds it holds for +// each, never from the month in a name or the settings this session runs with, +// and it decides once it holds its lock on audit_events, from the catalog as it +// stands then. A statement reads the catalog as it stands only at READ +// COMMITTED, so the function refuses a transaction at any other level with +// SQLSTATE 25000. On a transaction already on ctx it runs there; with none it +// opens a control-plane transaction of its own at READ COMMITTED, whatever the +// database's default isolation, which is how scheduled retention calls it. +// +// It refuses a `before` later than the audit_events retention policy allows by +// the database's clock, or with no policy at all (22023), so a caller whose +// clock runs ahead cannot drop a partition still inside the window. Its waits +// for locks add up to ten seconds at most; past that it fails with 55P03 and +// drops nothing, and the next scheduled run tries again. A partition whose +// bounds are not a bounded range, or whose detach has begun, is never dropped. func (s *PostgresStore) DropAuditPartitionsBefore(ctx context.Context, before time.Time) (int64, error) { - q := s.getQueryExecutor(ctx) + if storetx.Tx(ctx) == nil { + // A deliberate control-plane elevation, counted with the direct + // WithControlPlane call sites. + recordControlPlane(ctx) + var dropped int64 + err := s.withControlPlaneTx(ctx, pgx.TxOptions{IsoLevel: pgx.ReadCommitted}, func(ctx context.Context) error { + var err error + dropped, err = s.DropAuditPartitionsBefore(ctx, before) + return err + }) + return dropped, err + } var dropped int64 - if err := q.QueryRow(ctx, `SELECT audit_events_drop_partitions_before($1)`, before).Scan(&dropped); err != nil { + if err := s.getQueryExecutor(ctx).QueryRow(ctx, `SELECT audit_events_drop_partitions_before($1)`, before).Scan(&dropped); err != nil { return 0, err } return dropped, nil diff --git a/module/services/accounts/code/pkg/infra/postgres_audit_retention_test.go b/module/services/accounts/code/pkg/infra/postgres_audit_retention_test.go new file mode 100644 index 000000000..59e5355fe --- /dev/null +++ b/module/services/accounts/code/pkg/infra/postgres_audit_retention_test.go @@ -0,0 +1,1548 @@ +//go:build !pure + +package infra_test + +import ( + "context" + "errors" + "fmt" + "net/url" + "os" + "path/filepath" + "slices" + "sync" + "testing" + "time" + + codefly "github.com/codefly-dev/sdk-go" + "github.com/google/uuid" + "github.com/jackc/pgx/v5" + "github.com/jackc/pgx/v5/pgconn" + "github.com/jackc/pgx/v5/pgtype" + "github.com/jackc/pgx/v5/pgxpool" + "github.com/stretchr/testify/require" + + "accounts/pkg/business" + "accounts/pkg/infra" + "accounts/pkg/infra/storetx" +) + +// Audit retention runs on a schedule with nobody watching, through +// audit_events_drop_partitions_before. These tests hold it to what PostgreSQL +// records about a partition, not to what the partition is called, and to +// refusing rather than hanging when it cannot take its locks. +// +// Every probe month lies years before the install provisions anything, so a +// cutoff in it cannot reach a real partition. The tests that only need a +// transaction's worth of state run in one that rolls back, as the owner of the +// tables, so a partition they create, or retention drops, does not outlive them. + +// retentionSetZone sets the session's time zone for the rest of the +// transaction, the way a client's zone setting reaches the server. +func retentionSetZone(t *testing.T, ctx context.Context, tx pgx.Tx, zone string) { + t.Helper() + _, err := tx.Exec(ctx, `SELECT set_config('TimeZone', $1, true)`, zone) + require.NoError(t, err) +} + +// retentionEnsureMonth provisions the monthly partition holding day, the way the +// store does, from a session in zone: its bounds are UTC midnights whatever the +// zone, met to any neighbour an earlier release cut at another zone's midnight. +func retentionEnsureMonth(t *testing.T, ctx context.Context, tx pgx.Tx, zone, day string) { + t.Helper() + retentionSetZone(t, ctx, tx, zone) + _, err := tx.Exec(ctx, fmt.Sprintf(`SELECT audit_events_ensure_partition('%s'::date)`, day)) + require.NoError(t, err) +} + +// retentionLegacyMonth creates the monthly partition holding day the way +// releases before migration 34 did, from a session in zone: its bounds are that +// zone's midnights. Deployments still hold partitions cut this way, and +// retention and provisioning are held to them too. +func retentionLegacyMonth(t *testing.T, ctx context.Context, tx pgx.Tx, zone, day string) { + t.Helper() + retentionSetZone(t, ctx, tx, zone) + inMonth, err := time.Parse(time.DateOnly, day) + require.NoError(t, err) + first := time.Date(inMonth.Year(), inMonth.Month(), 1, 0, 0, 0, 0, time.UTC) + _, err = tx.Exec(ctx, fmt.Sprintf(`CREATE TABLE public.%s PARTITION OF public.audit_events FOR VALUES FROM ('%s') TO ('%s')`, + pgx.Identifier{"audit_events_" + first.Format("2006_01")}.Sanitize(), + first.Format(time.DateOnly), first.AddDate(0, 1, 0).Format(time.DateOnly))) + require.NoError(t, err) +} + +// retentionBounds reads the range PostgreSQL records for a partition, as +// instants. It reads it in ISO and UTC, which the rest of the transaction keeps. +func retentionBounds(t *testing.T, ctx context.Context, tx pgx.Tx, partition string) (lower, upper time.Time) { + t.Helper() + _, err := tx.Exec(ctx, `SELECT set_config('DateStyle', 'ISO, MDY', true), set_config('TimeZone', 'UTC', true)`) + require.NoError(t, err) + require.NoError(t, tx.QueryRow(ctx, ` + SELECT r[1]::timestamptz, r[2]::timestamptz + FROM pg_class c, + regexp_match(pg_get_expr(c.relpartbound, 0), '^FOR VALUES FROM \(''([^'']+)''\) TO \(''([^'']+)''\)$') AS r + WHERE c.oid = to_regclass('public.' || $1)`, partition).Scan(&lower, &upper)) + return lower.UTC(), upper.UTC() +} + +// retentionPartitions lists the partitions attached to audit_events, by name. +func retentionPartitions(t *testing.T, ctx context.Context, tx pgx.Tx) []string { + t.Helper() + rows, err := tx.Query(ctx, ` + SELECT c.relname::text + FROM pg_inherits i JOIN pg_class c ON c.oid = i.inhrelid + WHERE i.inhparent = 'public.audit_events'::regclass + ORDER BY 1`) + require.NoError(t, err) + names, err := pgx.CollectRows(rows, pgx.RowTo[string]) + require.NoError(t, err) + return names +} + +// retentionInsertEvent commits a platform event at an explicit instant and +// returns the partition PostgreSQL routed it to. +func retentionInsertEvent(t *testing.T, ctx context.Context, tx pgx.Tx, at time.Time) string { + t.Helper() + id := uuid.NewString() + _, err := tx.Exec(ctx, + `INSERT INTO audit_events (id, event_type, resource, created_at) VALUES ($1, $2, 'example', $3)`, + id, string(business.EventAuthLogin), at) + require.NoError(t, err) + var partition string + require.NoError(t, tx.QueryRow(ctx, `SELECT tableoid::regclass::text FROM audit_events WHERE id = $1`, id).Scan(&partition)) + return partition +} + +// retentionRowsIn counts the rows a partition holds, read through the parent. +func retentionRowsIn(t *testing.T, ctx context.Context, tx pgx.Tx, partition string) int64 { + t.Helper() + var rows int64 + require.NoError(t, tx.QueryRow(ctx, + `SELECT count(*) FROM audit_events WHERE tableoid = to_regclass('public.' || $1)`, partition).Scan(&rows)) + return rows +} + +// asRetention runs fn in a transaction that rolls back, as the owner of the +// audit tables, and hands it the context a store method needs to run in that +// transaction. A test that wants the role retention runs as switches to it +// itself, after the DDL only the owner may run. +func asRetention(t *testing.T, fn func(ctx context.Context, tx pgx.Tx)) { + t.Helper() + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + tx, err := conn.Begin(ctx) + require.NoError(t, err) + defer func() { _ = tx.Rollback(ctx) }() + fn(ctx, tx) + }) +} + +// runRetentionIn runs the scheduled retention call as the control-plane role, +// from a UTC session, inside tx. +func runRetentionIn(t *testing.T, ctx context.Context, tx pgx.Tx, cutoff time.Time) int64 { + t.Helper() + _, err := tx.Exec(ctx, `SET LOCAL ROLE app_control_plane`) + require.NoError(t, err) + retentionSetZone(t, ctx, tx, "UTC") + dropped, err := testStore.DropAuditPartitionsBefore(infra.BindControlPlaneTx(ctx, tx), cutoff) + require.NoError(t, err) + return dropped +} + +// A partition an earlier release created from a session whose zone is not UTC +// has bounds on that zone's midnights, so audit_events_1996_08 created from New +// York ends at 04:00 UTC on 1 September. Retention run from UTC with a cutoff of 1 September 00:00 +// UTC must leave it alone: its last four hours hold September's events, which +// are newer than the cutoff. Choosing it by its name, read in the UTC session, +// dropped it and them. +func TestRetentionKeepsAPartitionThatEndsAfterTheCutoffWhateverZoneCreatedIt(t *testing.T) { + asRetention(t, func(ctx context.Context, tx pgx.Tx) { + retentionLegacyMonth(t, ctx, tx, "America/New_York", "1996-07-15") + retentionLegacyMonth(t, ctx, tx, "America/New_York", "1996-08-15") + retentionEnsureMonth(t, ctx, tx, "UTC", "1996-06-15") + + _, err := tx.Exec(ctx, `SET LOCAL ROLE app_control_plane`) + require.NoError(t, err) + cutoff := time.Date(1996, 9, 1, 0, 0, 0, 0, time.UTC) + + // The premise: a September event, newer than the cutoff, is held by the + // partition named for August; an August one is held by July's. + require.Equal(t, "audit_events_1996_08", + retentionInsertEvent(t, ctx, tx, cutoff.Add(2*time.Hour)), "the premise: the partition named for August ends after the cutoff") + require.Equal(t, "audit_events_1996_07", + retentionInsertEvent(t, ctx, tx, time.Date(1996, 8, 1, 2, 0, 0, 0, time.UTC)), "the premise: the partition named for July ends in August") + + before := retentionPartitions(t, ctx, tx) + dropped := runRetentionIn(t, ctx, tx, cutoff) + after := retentionPartitions(t, ctx, tx) + + require.Contains(t, after, "audit_events_1996_08", "a partition that ends after the cutoff is not dropped") + require.Equal(t, int64(1), retentionRowsIn(t, ctx, tx, "audit_events_1996_08"), "the events newer than the cutoff survive") + require.NotContains(t, after, "audit_events_1996_07", "a partition that ends before the cutoff is dropped") + require.NotContains(t, after, "audit_events_1996_06", "a partition that ends before the cutoff is dropped") + require.Equal(t, int64(len(before)-len(after)), dropped, "the count is the partitions that went") + require.Equal(t, int64(2), dropped) + }) +} + +// The same partitions, retention run from a session in the creator's zone: the +// answer does not depend on the zone retention runs in. +func TestRetentionDecidesAlikeFromAnyZone(t *testing.T) { + for _, zone := range []string{"UTC", "America/New_York", "Asia/Kolkata", "Pacific/Auckland"} { + t.Run(zone, func(t *testing.T) { + asRetention(t, func(ctx context.Context, tx pgx.Tx) { + retentionLegacyMonth(t, ctx, tx, "America/New_York", "1996-07-15") + retentionLegacyMonth(t, ctx, tx, "America/New_York", "1996-08-15") + + _, err := tx.Exec(ctx, `SET LOCAL ROLE app_control_plane`) + require.NoError(t, err) + retentionSetZone(t, ctx, tx, zone) + // 1996-09-01 04:00 UTC, the instant audit_events_1996_08 ends. + end := time.Date(1996, 9, 1, 4, 0, 0, 0, time.UTC) + + dropped, err := testStore.DropAuditPartitionsBefore(infra.BindControlPlaneTx(ctx, tx), end.Add(-time.Second)) + require.NoError(t, err) + require.Equal(t, int64(1), dropped, "one second before the end, only July is due") + require.True(t, slices.Contains(retentionPartitions(t, ctx, tx), "audit_events_1996_08")) + + dropped, err = testStore.DropAuditPartitionsBefore(infra.BindControlPlaneTx(ctx, tx), end) + require.NoError(t, err) + require.Equal(t, int64(1), dropped, "at the end, August is due") + require.False(t, slices.Contains(retentionPartitions(t, ctx, tx), "audit_events_1996_08")) + }) + }) + } +} + +// A partition whose bounds are not a quoted FROM/TO pair is never dropped, +// whatever it is called: a cutoff rule cannot say what a DEFAULT partition holds, +// and a range open at either end has no month. Each probe carries a monthly name +// that a name-based rule would take for one older than the cutoff. +func TestRetentionNeverDropsAPartitionWhoseBoundsItCannotRead(t *testing.T) { + for _, tc := range []struct { + name string + ddl string + partition string + eventAt time.Time + cutoff time.Time + // older is a monthly partition created beside the probe that retention + // must still drop: refusing the probe is not the end of the run. + older string + }{ + { + name: "DEFAULT", + ddl: `CREATE TABLE public.audit_events_1997_03 PARTITION OF public.audit_events DEFAULT`, + partition: "audit_events_1997_03", + eventAt: time.Date(1997, 3, 10, 12, 0, 0, 0, time.UTC), + cutoff: time.Date(1997, 5, 1, 0, 0, 0, 0, time.UTC), + older: "audit_events_1997_01", + }, + { + name: "MINVALUE", + ddl: `CREATE TABLE public.audit_events_1997_03 PARTITION OF public.audit_events FOR VALUES FROM (MINVALUE) TO ('1997-04-01 00:00:00+00')`, + partition: "audit_events_1997_03", + eventAt: time.Date(1997, 3, 10, 12, 0, 0, 0, time.UTC), + cutoff: time.Date(1997, 5, 1, 0, 0, 0, 0, time.UTC), + }, + { + // Open at the top, so it can only start after every partition there + // is, and a cutoff is never later than the present: only its name + // can make it look older than the cutoff. + name: "MAXVALUE", + ddl: `CREATE TABLE public.audit_events_1997_04 PARTITION OF public.audit_events FOR VALUES FROM ('2200-03-01 00:00:00+00') TO (MAXVALUE)`, + partition: "audit_events_1997_04", + eventAt: time.Date(2200, 3, 10, 12, 0, 0, 0, time.UTC), + cutoff: time.Date(1997, 5, 1, 0, 0, 0, 0, time.UTC), + older: "audit_events_1997_01", + }, + } { + t.Run(tc.name, func(t *testing.T) { + asRetention(t, func(ctx context.Context, tx pgx.Tx) { + if tc.older != "" { + retentionEnsureMonth(t, ctx, tx, "UTC", "1997-01-15") + } + _, err := tx.Exec(ctx, tc.ddl) + require.NoError(t, err) + _, err = tx.Exec(ctx, `SET LOCAL ROLE app_control_plane`) + require.NoError(t, err) + require.Equal(t, tc.partition, retentionInsertEvent(t, ctx, tx, tc.eventAt), "the premise: the probe holds an event") + + before := retentionPartitions(t, ctx, tx) + dropped := runRetentionIn(t, ctx, tx, tc.cutoff) + after := retentionPartitions(t, ctx, tx) + + require.Contains(t, after, tc.partition, "a partition whose bounds are not a month's is not dropped") + require.Equal(t, int64(1), retentionRowsIn(t, ctx, tx, tc.partition), "its event survives") + require.Equal(t, int64(len(before)-len(after)), dropped) + if tc.older != "" { + require.NotContains(t, after, tc.older, "the run goes on past a partition it will not drop") + } + }) + }) + } +} + +// retentionRetire drops what a test left behind, by the retention function, so +// no probe month outlives the test that provisioned it. +func retentionRetire(t *testing.T, before string) { + t.Helper() + t.Cleanup(func() { + require.NoError(t, testStore.WithControlPlane(testCtx, func(ctx context.Context) error { + _, err := storetx.Tx(ctx).Exec(ctx, `SELECT audit_events_drop_partitions_before($1::timestamptz)`, before) + return err + })) + }) +} + +// retentionCommitted runs the scheduled retention call in its own committed +// control-plane transaction, from a UTC session. +func retentionCommitted(cutoff time.Time) (int64, error) { + var dropped int64 + err := testStore.WithControlPlane(testCtx, func(ctx context.Context) error { + if _, err := storetx.Tx(ctx).Exec(ctx, `SELECT set_config('TimeZone', 'UTC', true)`); err != nil { + return err + } + var err error + dropped, err = testStore.DropAuditPartitionsBefore(ctx, cutoff) + return err + }) + return dropped, err +} + +func retentionPartitionRows(t *testing.T, name string) (exists bool, rows int64) { + t.Helper() + require.NoError(t, testStore.WithControlPlane(testCtx, func(ctx context.Context) error { + tx := storetx.Tx(ctx) + if err := tx.QueryRow(ctx, `SELECT to_regclass('public.' || $1) IS NOT NULL`, name).Scan(&exists); err != nil || !exists { + return err + } + return tx.QueryRow(ctx, `SELECT count(*) FROM audit_events WHERE tableoid = to_regclass('public.' || $1)`, name).Scan(&rows) + })) + return exists, rows +} + +// A writer that does not finish makes retention refuse, not hang: the function +// bounds its wait for the table's lock, drops nothing, and a later run, when the +// writer is gone, drops the partition. And a run with nothing due takes no lock +// the writer holds up, so it neither waits for the writer nor fails because of +// it: retention runs on a schedule and a partition comes due about once a month. +func TestRetentionRefusesInsteadOfHangingBehindAWriterThatDoesNotFinish(t *testing.T) { + retentionRetire(t, "1999-01-01") + require.NoError(t, testStore.WithControlPlane(testCtx, func(ctx context.Context) error { + tx := storetx.Tx(ctx) + retentionSetZone(t, ctx, tx, "UTC") + _, err := tx.Exec(ctx, `SELECT audit_events_ensure_partition('1998-03-15'::date)`) + return err + })) + + inserted, release, finished := make(chan struct{}), make(chan struct{}), make(chan struct{}) + var writerErr error + go func() { + defer close(finished) + writerErr = testStore.WithControlPlane(testCtx, func(ctx context.Context) error { + if _, err := storetx.Tx(ctx).Exec(ctx, + `INSERT INTO audit_events (id, event_type, resource, created_at) VALUES ($1, $2, 'example', $3)`, + uuid.NewString(), string(business.EventAuthLogin), time.Date(1998, 3, 10, 12, 0, 0, 0, time.UTC)); err != nil { + return err + } + close(inserted) + <-release + return nil + }) + }() + select { + case <-inserted: + case <-finished: + t.Fatalf("the writer failed before it held the partition: %v", writerErr) + } + var releaseOnce sync.Once + releaseWriter := func() { releaseOnce.Do(func() { close(release) }) } + t.Cleanup(func() { releaseWriter(); <-finished }) + + // Nothing is due: the cutoff precedes the end of the only old partition. + started := time.Now() + dropped, err := retentionCommitted(time.Date(1998, 3, 1, 0, 0, 0, 0, time.UTC)) + require.NoError(t, err, "a run with nothing due does not wait for a writer") + require.Zero(t, dropped) + require.Less(t, time.Since(started), 5*time.Second) + + // Something is due, behind a writer that is not finishing. + type outcome struct { + dropped int64 + err error + } + refused := make(chan outcome, 1) + go func() { + dropped, err := retentionCommitted(time.Date(1998, 4, 1, 0, 0, 0, 0, time.UTC)) + refused <- outcome{dropped, err} + }() + select { + case got := <-refused: + var pgErr *pgconn.PgError + require.ErrorAs(t, got.err, &pgErr, "retention refused for want of the lock") + require.Equal(t, "55P03", pgErr.Code, "lock_not_available: the wait is bounded") + require.Zero(t, got.dropped) + case <-time.After(45 * time.Second): + t.Fatal("retention hung behind a writer that had not finished") + } + exists, _ := retentionPartitionRows(t, "audit_events_1998_03") + require.True(t, exists, "a refused run drops nothing") + + releaseWriter() + <-finished + require.NoError(t, writerErr) + exists, rows := retentionPartitionRows(t, "audit_events_1998_03") + require.True(t, exists) + require.Equal(t, int64(1), rows, "the writer's row was never at risk") + dropped, err = retentionCommitted(time.Date(1998, 4, 1, 0, 0, 0, 0, time.UTC)) + require.NoError(t, err) + require.Equal(t, int64(1), dropped, "the next run, with the writer gone, drops the partition") + exists, _ = retentionPartitionRows(t, "audit_events_1998_03") + require.False(t, exists) +} + +// When nothing is due the function takes no lock at all. It reads bounds without +// opening a partition, so a session holding one ACCESS EXCLUSIVE -- another run +// dropping it, or DDL on it -- does not hold up a run that drops nothing. +func TestRetentionTakesNoLockWhenNothingIsDue(t *testing.T) { + const held = "audit_events_1991_03" + retentionRetire(t, "1992-01-01") + retentionProvisionMonth(t, "1991-03-15", time.Date(1991, 3, 10, 12, 0, 0, 0, time.UTC), uuid.NewString()) + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + tx, err := conn.Begin(ctx) + require.NoError(t, err) + defer func() { _ = tx.Rollback(ctx) }() + _, err = tx.Exec(ctx, `LOCK TABLE public.`+held+` IN ACCESS EXCLUSIVE MODE`) + require.NoError(t, err) + + // Nothing is due: the partition ends after the cutoff. + started := time.Now() + dropped, err := retentionCommitted(time.Date(1991, 3, 20, 0, 0, 0, 0, time.UTC)) + require.NoError(t, err, "a run with nothing due does not wait for the partition") + require.Zero(t, dropped) + require.Less(t, time.Since(started), 5*time.Second) + }) +} + +// The migration replaced the function's body, and CREATE OR REPLACE keeps its +// owner and grants; what it must have changed is the wait and the settings it +// reads bounds under. Execute stays with the control plane alone: retention is +// DDL on the audit table, and no tenant transaction may run it. +func TestRetentionFunctionBoundsItsLockWaitAndKeepsItsGrants(t *testing.T) { + var config []string + var publicMayExecute, controlPlaneMay, tenantMay bool + require.NoError(t, testStore.WithControlPlane(testCtx, func(ctx context.Context) error { + return storetx.Tx(ctx).QueryRow(ctx, ` + SELECT COALESCE(proconfig, ARRAY[]::text[]), + proacl IS NULL OR EXISTS (SELECT 1 FROM aclexplode(proacl) a WHERE a.grantee = 0 AND a.privilege_type = 'EXECUTE'), + has_function_privilege('app_control_plane', oid, 'EXECUTE'), + has_function_privilege('app_tenant', oid, 'EXECUTE') + FROM pg_proc + WHERE oid = 'public.audit_events_drop_partitions_before(timestamptz)'::regprocedure`, + ).Scan(&config, &publicMayExecute, &controlPlaneMay, &tenantMay) + })) + require.Contains(t, config, "lock_timeout=10s", "a stuck writer is a refusal, not a hang") + require.Contains(t, config, "DateStyle=ISO, MDY", "a bound is rendered with its UTC offset, whatever the caller's DateStyle") + require.Contains(t, config, "TimeZone=UTC", "a bound is rendered in one zone, whatever the caller's") + require.False(t, publicMayExecute) + require.True(t, controlPlaneMay) + require.False(t, tenantMay) +} + +// A partition's upper bound is read back as the instant PostgreSQL recorded, +// whatever DateStyle the session running retention uses. Any DateStyle but ISO +// renders a timestamp with time zone with its zone's abbreviation instead of +// its UTC offset, and an abbreviation does not name one offset, so the function +// renders and reads every bound under settings it pins itself. +func TestRetentionReadsEveryBoundAsTheInstantPostgreSQLRecorded(t *testing.T) { + for _, style := range []string{"SQL, DMY", "Postgres", "German"} { + t.Run(style, func(t *testing.T) { + asRetention(t, func(ctx context.Context, tx pgx.Tx) { + retentionEnsureMonth(t, ctx, tx, "UTC", "1996-07-15") + retentionEnsureMonth(t, ctx, tx, "UTC", "1996-08-15") + _, err := tx.Exec(ctx, `SET LOCAL ROLE app_control_plane`) + require.NoError(t, err) + + // audit_events_1996_08 ends at 1996-09-01 00:00 UTC. An event a + // quarter of an hour before that is newer than a cutoff half an + // hour before it, so the partition holding it is not due. + end := time.Date(1996, 9, 1, 0, 0, 0, 0, time.UTC) + require.Equal(t, "audit_events_1996_08", retentionInsertEvent(t, ctx, tx, end.Add(-15*time.Minute))) + + retentionSetZone(t, ctx, tx, "Europe/Dublin") + _, err = tx.Exec(ctx, `SELECT set_config('DateStyle', $1, true)`, style) + require.NoError(t, err) + dropped, err := testStore.DropAuditPartitionsBefore(infra.BindControlPlaneTx(ctx, tx), end.Add(-30*time.Minute)) + require.NoError(t, err) + + after := retentionPartitions(t, ctx, tx) + require.Contains(t, after, "audit_events_1996_08", "a partition that ends after the cutoff is not dropped") + require.Equal(t, int64(1), retentionRowsIn(t, ctx, tx, "audit_events_1996_08"), "the event newer than the cutoff survives") + require.NotContains(t, after, "audit_events_1996_07", "a partition that ends before the cutoff is dropped") + require.Equal(t, int64(1), dropped) + }) + }) + } +} + +// The cutoff is one the audit_events policy allows by the database's clock: no +// later than the start of the transaction less the policy's window. A later one +// reaches partitions still inside the window -- the one holding the present and +// those provisioned ahead of it, or one a caller whose clock runs ahead counts +// as old -- so the function refuses it, and a missing one, and any at all when +// there is no policy, and drops nothing. +func TestRetentionRefusesACutoffThePolicyDoesNotAllow(t *testing.T) { + for _, tc := range []struct { + name string + noPolicy bool + cutoff func(allowed time.Time) any + }{ + {name: "after the present partition ends", cutoff: func(time.Time) any { return time.Now().AddDate(0, 2, 0) }}, + {name: "infinity", cutoff: func(time.Time) any { return pgtype.Timestamptz{InfinityModifier: pgtype.Infinity, Valid: true} }}, + {name: "NULL", cutoff: func(time.Time) any { return nil }}, + {name: "a second later than the policy allows", cutoff: func(allowed time.Time) any { return allowed.Add(time.Second) }}, + {name: "from a clock eleven hours ahead", cutoff: func(allowed time.Time) any { return allowed.Add(11 * time.Hour) }}, + {name: "with no policy", noPolicy: true, cutoff: func(allowed time.Time) any { return allowed.AddDate(-10, 0, 0) }}, + } { + t.Run(tc.name, func(t *testing.T) { + asRetention(t, func(ctx context.Context, tx pgx.Tx) { + retentionSetZone(t, ctx, tx, "UTC") + var allowed time.Time + require.NoError(t, tx.QueryRow(ctx, ` + SELECT now() - make_interval(days => retention_days) + FROM data_retention_policies WHERE resource_type = 'audit_events'`).Scan(&allowed)) + _, err := tx.Exec(ctx, `SET LOCAL ROLE app_control_plane`) + require.NoError(t, err) + // Other tests may have written to the present partition too, so + // the check is that it keeps every row it had. + present := retentionInsertEvent(t, ctx, tx, time.Now()) + before, rows := retentionPartitions(t, ctx, tx), retentionRowsIn(t, ctx, tx, present) + + attempt, err := tx.Begin(ctx) + require.NoError(t, err) + if tc.noPolicy { + _, err = attempt.Exec(ctx, `DELETE FROM data_retention_policies WHERE resource_type = 'audit_events'`) + require.NoError(t, err) + } + var dropped int64 + err = attempt.QueryRow(ctx, `SELECT audit_events_drop_partitions_before($1)`, tc.cutoff(allowed)).Scan(&dropped) + var pgErr *pgconn.PgError + require.ErrorAs(t, err, &pgErr, "a cutoff the policy does not allow is refused") + require.Equal(t, "22023", pgErr.Code, "invalid_parameter_value") + require.NoError(t, attempt.Rollback(ctx)) + + require.Equal(t, before, retentionPartitions(t, ctx, tx), "a refused run drops nothing") + require.Equal(t, rows, retentionRowsIn(t, ctx, tx, present), "the present's events survive") + }) + }) + } +} + +// A caller whose clock runs eleven hours ahead counts a partition still inside +// the window as old. The function holds the cutoff to the policy by the +// database's clock, so it refuses that one, and the partition and its event +// survive; at the cutoff the policy allows the partition is not due, since it +// ends after it. The policy's window is moved, inside the transaction, to end in +// 1970, where no other partition lies. +func TestRetentionKeepsAPartitionInsideTheWindowWhateverTheCallersClock(t *testing.T) { + asRetention(t, func(ctx context.Context, tx pgx.Tx) { + retentionSetZone(t, ctx, tx, "UTC") + var allowed time.Time + require.NoError(t, tx.QueryRow(ctx, ` + UPDATE data_retention_policies SET retention_days = now()::date - date '1970-06-15' + WHERE resource_type = 'audit_events' + RETURNING now() - make_interval(days => retention_days)`).Scan(&allowed)) + const probe = "audit_events_1970_06" + _, err := tx.Exec(ctx, fmt.Sprintf(`CREATE TABLE public.%s PARTITION OF public.audit_events FOR VALUES FROM ('%s') TO ('%s')`, + probe, allowed.Add(-time.Hour).Format(time.RFC3339Nano), allowed.Add(time.Hour).Format(time.RFC3339Nano))) + require.NoError(t, err) + _, err = tx.Exec(ctx, `SET LOCAL ROLE app_control_plane`) + require.NoError(t, err) + require.Equal(t, probe, retentionInsertEvent(t, ctx, tx, allowed.Add(30*time.Minute)), + "the premise: the partition holds an event inside the window") + + attempt, err := tx.Begin(ctx) + require.NoError(t, err) + _, err = testStore.DropAuditPartitionsBefore(infra.BindControlPlaneTx(ctx, attempt), allowed.Add(11*time.Hour)) + var pgErr *pgconn.PgError + require.ErrorAs(t, err, &pgErr, "the cutoff of a clock eleven hours ahead is refused") + require.Equal(t, "22023", pgErr.Code) + require.NoError(t, attempt.Rollback(ctx)) + require.Contains(t, retentionPartitions(t, ctx, tx), probe) + require.Equal(t, int64(1), retentionRowsIn(t, ctx, tx, probe), "the event inside the window survives") + + require.Zero(t, runRetentionIn(t, ctx, tx, allowed), "at the cutoff the policy allows, the partition is not due") + require.Equal(t, int64(1), retentionRowsIn(t, ctx, tx, probe)) + }) +} + +// The function decides under its lock from the catalog as it stands once the +// lock is held, and a statement reads the catalog as it stands only at READ +// COMMITTED: at REPEATABLE READ or SERIALIZABLE every statement reads the +// snapshot the transaction took first, before the lock. It refuses to run at +// either, and drops nothing. +func TestRetentionRunsOnlyAtReadCommitted(t *testing.T) { + for _, level := range []pgx.TxIsoLevel{pgx.RepeatableRead, pgx.Serializable} { + t.Run(string(level), func(t *testing.T) { + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + tx, err := conn.BeginTx(ctx, pgx.TxOptions{IsoLevel: level}) + require.NoError(t, err) + defer func() { _ = tx.Rollback(ctx) }() + retentionEnsureMonth(t, ctx, tx, "UTC", "1996-03-15") + _, err = tx.Exec(ctx, `SET LOCAL ROLE app_control_plane`) + require.NoError(t, err) + + attempt, err := tx.Begin(ctx) + require.NoError(t, err) + _, err = testStore.DropAuditPartitionsBefore(infra.BindControlPlaneTx(ctx, attempt), time.Date(1996, 5, 1, 0, 0, 0, 0, time.UTC)) + var pgErr *pgconn.PgError + require.ErrorAs(t, err, &pgErr, "retention refuses a transaction that reads one snapshot throughout") + require.Equal(t, "25000", pgErr.Code, "invalid_transaction_state") + require.NoError(t, attempt.Rollback(ctx)) + require.Contains(t, retentionPartitions(t, ctx, tx), "audit_events_1996_03", "a refused run drops nothing") + }) + }) + } +} + +// retentionProvisionMonth commits the monthly partition holding day, created +// from a UTC session, and one event at eventAt in the organization org. +func retentionProvisionMonth(t *testing.T, day string, eventAt time.Time, org string) { + t.Helper() + require.NoError(t, testStore.WithControlPlane(testCtx, func(ctx context.Context) error { + tx := storetx.Tx(ctx) + if _, err := tx.Exec(ctx, `SELECT set_config('TimeZone', 'UTC', true)`); err != nil { + return err + } + if _, err := tx.Exec(ctx, `SELECT audit_events_ensure_partition($1::date)`, day); err != nil { + return err + } + _, err := tx.Exec(ctx, + `INSERT INTO audit_events (id, event_type, resource, org_id, created_at) VALUES ($1, $2, 'example', $3, $4)`, + uuid.NewString(), string(business.EventAuthLogin), org, eventAt) + return err + })) +} + +// retentionDropTableAfter drops table, as its owner, once the test is over, +// whether retention dropped it, a test detached it, or it is still attached. +func retentionDropTableAfter(t *testing.T, table string) { + t.Helper() + t.Cleanup(func() { + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + _, err := conn.Exec(ctx, `DROP TABLE IF EXISTS public.`+pgx.Identifier{table}.Sanitize()) + require.NoError(t, err) + }) + }) +} + +// retentionHoldReader opens a control-plane transaction that has read +// audit_events, so holds ACCESS SHARE on it and on every partition, and keeps +// it open until the returned release is called. +func retentionHoldReader(t *testing.T) (release func()) { + t.Helper() + reading, done, finished := make(chan struct{}), make(chan struct{}), make(chan struct{}) + var readerErr error + go func() { + defer close(finished) + readerErr = testStore.WithControlPlane(testCtx, func(ctx context.Context) error { + var rows int64 + if err := storetx.Tx(ctx).QueryRow(ctx, `SELECT count(*) FROM audit_events`).Scan(&rows); err != nil { + return err + } + close(reading) + <-done + return nil + }) + }() + select { + case <-reading: + case <-finished: + t.Fatalf("the reader failed before it held audit_events: %v", readerErr) + } + var once sync.Once + release = func() { once.Do(func() { close(done); <-finished }) } + t.Cleanup(release) + return release +} + +// retentionAwaitQueuedLocks waits until n sessions wait for an ACCESS EXCLUSIVE +// lock on audit_events. +func retentionAwaitQueuedLocks(t *testing.T, n int) { + t.Helper() + require.Eventually(t, func() bool { + var queued int + err := testPool.QueryRow(testCtx, ` + SELECT count(*) FROM pg_locks + WHERE locktype = 'relation' AND relation = 'public.audit_events'::regclass + AND mode = 'AccessExclusiveLock' AND NOT granted`).Scan(&queued) + return err == nil && queued >= n + }, 30*time.Second, 20*time.Millisecond, "%d sessions never queued for audit_events", n) +} + +// detachPending reports whether table is a partition of audit_events whose +// detach has begun and not finished. +func detachPending(table string) (bool, error) { + var pending bool + err := testPool.QueryRow(testCtx, ` + SELECT inhdetachpending FROM pg_inherits + WHERE inhrelid = to_regclass('public.' || $1) AND inhparent = 'public.audit_events'::regclass`, table).Scan(&pending) + if errors.Is(err, pgx.ErrNoRows) { + return false, nil + } + return pending, err +} + +func retentionDetachPending(t *testing.T, table string) bool { + t.Helper() + pending, err := detachPending(table) + require.NoError(t, err) + return pending +} + +// retentionOwnerRows counts table's rows in the organization org, read by name +// as the table's owner: the partitions force row-level security, so the owner +// sees an organization's rows only with that organization bound. +func retentionOwnerRows(t *testing.T, ctx context.Context, conn *pgxpool.Conn, table, org string) int64 { + t.Helper() + tx, err := conn.Begin(ctx) + require.NoError(t, err) + defer func() { _ = tx.Rollback(ctx) }() + _, err = tx.Exec(ctx, `SELECT set_config('app.current_org_id', $1, true)`, org) + require.NoError(t, err) + var rows int64 + require.NoError(t, tx.QueryRow(ctx, `SELECT count(*) FROM public.`+pgx.Identifier{table}.Sanitize()).Scan(&rows)) + return rows +} + +type retentionOutcome struct { + dropped int64 + err error +} + +// The decision is taken again once the lock is held. A partition detached +// while retention waited for its lock -- an operator keeping that month out of +// retention -- is no longer audit_events', and the run leaves it, and its +// events, alone. +func TestRetentionLeavesAPartitionDetachedWhileItWaitedForItsLock(t *testing.T) { + const kept = "audit_events_1995_02" + org := uuid.NewString() + retentionRetire(t, "1996-01-01") + retentionDropTableAfter(t, kept) + retentionProvisionMonth(t, "1995-02-15", time.Date(1995, 2, 10, 12, 0, 0, 0, time.UTC), org) + + release := retentionHoldReader(t) + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + detached := make(chan error, 1) + go func() { + _, err := conn.Exec(ctx, `ALTER TABLE public.audit_events DETACH PARTITION public.`+kept) + detached <- err + }() + retentionAwaitQueuedLocks(t, 1) + + // Retention finds the partition due before it locks audit_events, and + // then waits for that lock behind the detach. + ran := make(chan retentionOutcome, 1) + go func() { + dropped, err := retentionCommitted(time.Date(1995, 4, 1, 0, 0, 0, 0, time.UTC)) + ran <- retentionOutcome{dropped, err} + }() + retentionAwaitQueuedLocks(t, 2) + release() + + require.NoError(t, <-detached, "the premise: the detach committed while retention waited") + got := <-ran + require.NoError(t, got.err) + require.Zero(t, got.dropped, "a partition that left audit_events is not retention's") + exists, _ := retentionPartitionRows(t, kept) + require.True(t, exists, "the detached table survives") + require.Equal(t, int64(1), retentionOwnerRows(t, ctx, conn, kept, org), "and its events") + }) +} + +// A partition whose DETACH ... CONCURRENTLY has begun and not finished is +// leaving audit_events, and is never dropped. The detach commits the partition +// as pending, then waits for every transaction that may still see it; +// interrupted there, it leaves the partition pending until someone finalizes it. +func TestRetentionNeverDropsAPartitionBeingDetached(t *testing.T) { + const pending = "audit_events_1995_05" + org := uuid.NewString() + retentionRetire(t, "1996-01-01") + retentionDropTableAfter(t, pending) + retentionProvisionMonth(t, "1995-05-15", time.Date(1995, 5, 10, 12, 0, 0, 0, time.UTC), org) + + release := retentionHoldReader(t) + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + detached := make(chan error, 1) + go func() { + _, err := conn.Exec(ctx, `ALTER TABLE public.audit_events DETACH PARTITION public.`+pending+` CONCURRENTLY`) + detached <- err + }() + require.Eventually(t, func() bool { + isPending, err := detachPending(pending) + return err == nil && isPending + }, 30*time.Second, 20*time.Millisecond, "the detach never committed its first phase") + require.NoError(t, conn.Conn().PgConn().CancelRequest(ctx)) + var pgErr *pgconn.PgError + require.ErrorAs(t, <-detached, &pgErr) + require.Equal(t, "57014", pgErr.Code, "the premise: the detach was interrupted") + release() + require.True(t, retentionDetachPending(t, pending), "the premise: the partition is pending detach") + + dropped, err := retentionCommitted(time.Date(1995, 7, 1, 0, 0, 0, 0, time.UTC)) + require.NoError(t, err) + require.Zero(t, dropped, "a partition being detached is not dropped") + require.True(t, retentionDetachPending(t, pending)) + require.Equal(t, int64(1), retentionOwnerRows(t, ctx, conn, pending, org), "its events survive") + }) +} + +// Two runs at once drop each due partition once, and neither fails: the second +// waits for the first's lock, then decides from the catalog as the first left +// it. +func TestTwoRetentionRunsAtOnceDropEachPartitionOnce(t *testing.T) { + retentionRetire(t, "1996-01-01") + org := uuid.NewString() + retentionProvisionMonth(t, "1995-08-15", time.Date(1995, 8, 10, 12, 0, 0, 0, time.UTC), org) + retentionProvisionMonth(t, "1995-09-15", time.Date(1995, 9, 10, 12, 0, 0, 0, time.UTC), org) + + release := retentionHoldReader(t) + ran := make(chan retentionOutcome, 2) + for queued := 1; queued <= 2; queued++ { + go func() { + dropped, err := retentionCommitted(time.Date(1995, 11, 1, 0, 0, 0, 0, time.UTC)) + ran <- retentionOutcome{dropped, err} + }() + retentionAwaitQueuedLocks(t, queued) + } + release() + + var total int64 + for range 2 { + got := <-ran + require.NoError(t, got.err) + total += got.dropped + } + require.Equal(t, int64(2), total, "each due partition is dropped once") + for _, name := range []string{"audit_events_1995_08", "audit_events_1995_09"} { + exists, _ := retentionPartitionRows(t, name) + require.False(t, exists) + } +} + +// retentionSession opens a session of the tables' owner outside every pool, to +// hold a lock in, or change the catalog from, while retention runs in another. +func retentionSession(t *testing.T) *pgx.Conn { + t.Helper() + dsn, err := codefly.For(testCtx).Service("store").Secret("postgres", "owner-connection") + require.NoError(t, err) + conn, err := pgx.Connect(testCtx, dsn) + require.NoError(t, err) + t.Cleanup(func() { _ = conn.Close(testCtx) }) + return conn +} + +// retentionAwaitWaiters waits until n sessions wait for a lock on relation. +func retentionAwaitWaiters(t *testing.T, relation string, n int) { + t.Helper() + require.Eventually(t, func() bool { + var waiting int + err := testPool.QueryRow(testCtx, ` + SELECT count(*) FROM pg_locks WHERE relation = to_regclass($1) AND NOT granted`, relation).Scan(&waiting) + return err == nil && waiting >= n + }, 10*time.Second, 20*time.Millisecond, "%d sessions never waited for %s", n, relation) +} + +// retentionAwaitHolding waits until a session holds relation ACCESS EXCLUSIVE. +// Retention holding audit_events is trying for the partitions it chose, one +// after another, without queueing for them; holding one of them, it has moved +// on to the next. +func retentionAwaitHolding(t *testing.T, relation string) { + t.Helper() + require.Eventually(t, func() bool { + var held int + err := testPool.QueryRow(testCtx, ` + SELECT count(*) FROM pg_locks + WHERE relation = to_regclass($1) AND mode = 'AccessExclusiveLock' AND granted`, relation).Scan(&held) + return err == nil && held > 0 + }, 10*time.Second, 20*time.Millisecond, "nothing came to hold %s", relation) +} + +// retentionKeepPolicy puts the audit_events retention policy back as it is now +// once the test is over, whatever the test changes it to, or if it deletes it. +func retentionKeepPolicy(t *testing.T) { + t.Helper() + var id string + var days int + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + require.NoError(t, conn.QueryRow(ctx, ` + SELECT id::text, retention_days FROM data_retention_policies WHERE resource_type = 'audit_events'`).Scan(&id, &days)) + }) + t.Cleanup(func() { + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + _, err := conn.Exec(ctx, ` + INSERT INTO data_retention_policies (id, resource_type, retention_days) VALUES ($1, 'audit_events', $2) + ON CONFLICT (resource_type) DO UPDATE SET retention_days = EXCLUDED.retention_days`, id, days) + require.NoError(t, err) + }) + }) +} + +// Holding audit_events does not stop a partition being renamed, and LOCK TABLE +// finds the table it locks by name. Retention chooses March and tries for it +// while a reader holds it, and meanwhile an operator renames March away and +// April to March's name. Retention locks the partition it chose, under whatever +// name it then has, so it never reaches April, which ends after the cutoff, or +// April's event. Renamed out of retention's names, March is no longer due once +// retention holds it, and the run drops nothing; renamed to another month's +// name it is still due, and the run drops it. Either way the next run, deciding +// from the catalog as the renames left it, finds nothing due. +func TestRetentionNeverDropsThePartitionThatTookTheNameOfOneItChose(t *testing.T) { + const march, april = "audit_events_1994_03", "audit_events_1994_04" + for _, tc := range []struct { + name, renamed string + dropped int64 + }{ + {"out of retention's names", "audit_events_1994_03_renamed", 0}, + {"to another month's name", "audit_events_1993_12", 1}, + } { + t.Run(tc.name, func(t *testing.T) { + org := uuid.NewString() + for _, table := range []string{march, april, tc.renamed} { + retentionDropTableAfter(t, table) + } + retentionProvisionMonth(t, "1994-03-15", time.Date(1994, 3, 10, 12, 0, 0, 0, time.UTC), org) + retentionProvisionMonth(t, "1994-04-15", time.Date(1994, 4, 2, 12, 0, 0, 0, time.UTC), org) + cutoff := time.Date(1994, 4, 1, 0, 0, 0, 0, time.UTC) + + reader := retentionSession(t) + _, err := reader.Exec(testCtx, `BEGIN; LOCK TABLE ONLY public.`+march+` IN ACCESS SHARE MODE`) + require.NoError(t, err) + operator := retentionSession(t) + renames := make(chan error, 1) + go func() { + _, err := operator.Exec(testCtx, `BEGIN; + ALTER TABLE public.`+march+` RENAME TO `+tc.renamed+`; + ALTER TABLE public.`+april+` RENAME TO `+march+`; + COMMIT`) + renames <- err + }() + retentionAwaitWaiters(t, "public."+march, 1) + + ran := make(chan retentionOutcome, 1) + go func() { + dropped, err := retentionCommitted(cutoff) + ran <- retentionOutcome{dropped, err} + }() + retentionAwaitHolding(t, "public.audit_events") + _, err = reader.Exec(testCtx, `COMMIT`) + require.NoError(t, err) + require.NoError(t, <-renames, "the premise: the renames committed while retention tried for March") + + got := <-ran + if tc.dropped == 0 { + var pgErr *pgconn.PgError + require.ErrorAs(t, got.err, &pgErr, "retention refused") + require.Equal(t, "55000", pgErr.Code, "object_not_in_prerequisite_state") + } else { + require.NoError(t, got.err) + } + require.Equal(t, tc.dropped, got.dropped) + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + require.Equal(t, int64(1), retentionOwnerRows(t, ctx, conn, march, org), "April, under March's name, keeps its event") + }) + exists, _ := retentionPartitionRows(t, tc.renamed) + require.Equal(t, tc.dropped == 0, exists, "March is dropped only while it is still due") + + dropped, err := retentionCommitted(cutoff) + require.NoError(t, err) + require.Zero(t, dropped, "the next run decides from the catalog as the renames left it") + }) + } +} + +// A rename that hands the name of a partition retention is trying for to a +// table another session holds costs retention no second wait. Retention holds +// audit_events, which every audit write queues behind, so its ten seconds are +// ten seconds in all: it tries for March under the name March has at each +// attempt, and never queues for whatever table holds March's old name. +func TestARenameWhileRetentionTriesForAPartitionCostsItNoSecondWait(t *testing.T) { + const march, april, moved, tmp = "audit_events_1985_03", "audit_events_1985_04", "audit_events_1985_03_moved", "audit_events_1985_04_tmp" + for _, table := range []string{march, april, moved, tmp} { + retentionDropTableAfter(t, table) + } + org := uuid.NewString() + retentionProvisionMonth(t, "1985-03-15", time.Date(1985, 3, 10, 12, 0, 0, 0, time.UTC), org) + retentionProvisionMonth(t, "1985-04-15", time.Date(1985, 4, 10, 12, 0, 0, 0, time.UTC), org) + + reader := retentionSession(t) + _, err := reader.Exec(testCtx, `BEGIN; LOCK TABLE ONLY public.`+march+` IN ACCESS SHARE MODE`) + require.NoError(t, err) + // The operator holds April first, then waits for March behind the reader. + operator := retentionSession(t) + renames := make(chan error, 1) + go func() { + _, err := operator.Exec(testCtx, `BEGIN; + ALTER TABLE public.`+april+` RENAME TO `+tmp+`; + ALTER TABLE public.`+march+` RENAME TO `+moved+`; + ALTER TABLE public.`+tmp+` RENAME TO `+march+`; + COMMIT`) + renames <- err + }() + retentionAwaitWaiters(t, "public."+march, 1) + // A second reader queues for March by name behind the operator: granted + // March, it follows the name to April and keeps April to the end. + follower := retentionSession(t) + followed := make(chan error, 1) + go func() { + _, err := follower.Exec(testCtx, `BEGIN; LOCK TABLE public.`+march+` IN ACCESS SHARE MODE`) + followed <- err + }() + retentionAwaitWaiters(t, "public."+march, 2) + + type outcome struct { + dropped int64 + err error + elapsed time.Duration + } + ran := make(chan outcome, 1) + go func() { + started := time.Now() + dropped, err := retentionCommitted(time.Date(1985, 4, 1, 0, 0, 0, 0, time.UTC)) + ran <- outcome{dropped, err, time.Since(started)} + }() + retentionAwaitHolding(t, "public.audit_events") + time.Sleep(6 * time.Second) + _, err = reader.Exec(testCtx, `COMMIT`) + require.NoError(t, err) + require.NoError(t, <-renames, "the premise: the renames committed while retention tried for March") + require.NoError(t, <-followed, "the premise: the follower holds the table that took March's name") + + select { + case got := <-ran: + var pgErr *pgconn.PgError + require.ErrorAs(t, got.err, &pgErr, "March, renamed out of retention's names, is no longer due") + require.Equal(t, "55000", pgErr.Code, "object_not_in_prerequisite_state") + require.Zero(t, got.dropped) + require.Less(t, got.elapsed, 11*time.Second, "ten seconds of waiting in all, with audit_events held") + case <-time.After(30 * time.Second): + t.Fatal("retention went on waiting past its ten seconds") + } + _, err = follower.Exec(testCtx, `ROLLBACK`) + require.NoError(t, err) +} + +// Renaming a partition out of retention's names keeps it from retention, and +// does so even while a run that chose it waits for a lock: the run, holding +// every partition it chose, reads which are due once more, and drops none when +// one is no longer. Retention chooses February and March and tries for +// February while a reader holds it; an operator renames March out of +// retention's names meanwhile. The run drops nothing, and the next one drops +// February alone. +func TestRetentionKeepsAPartitionRenamedOutOfItsNamesWhileItWaits(t *testing.T) { + const february, march, kept = "audit_events_1994_02", "audit_events_1994_03", "audit_events_1994_03_kept" + org := uuid.NewString() + for _, table := range []string{february, march, kept} { + retentionDropTableAfter(t, table) + } + retentionProvisionMonth(t, "1994-02-15", time.Date(1994, 2, 10, 12, 0, 0, 0, time.UTC), org) + retentionProvisionMonth(t, "1994-03-15", time.Date(1994, 3, 10, 12, 0, 0, 0, time.UTC), org) + cutoff := time.Date(1994, 4, 1, 0, 0, 0, 0, time.UTC) + + reader := retentionSession(t) + _, err := reader.Exec(testCtx, `BEGIN; LOCK TABLE ONLY public.`+february+` IN ACCESS SHARE MODE`) + require.NoError(t, err) + ran := make(chan retentionOutcome, 1) + go func() { + dropped, err := retentionCommitted(cutoff) + ran <- retentionOutcome{dropped, err} + }() + retentionAwaitHolding(t, "public.audit_events") + _, err = retentionSession(t).Exec(testCtx, `ALTER TABLE public.`+march+` RENAME TO `+kept) + require.NoError(t, err, "the premise: March is renamed while retention tries for February") + _, err = reader.Exec(testCtx, `COMMIT`) + require.NoError(t, err) + + got := <-ran + var pgErr *pgconn.PgError + require.ErrorAs(t, got.err, &pgErr, "retention refused") + require.Equal(t, "55000", pgErr.Code, "object_not_in_prerequisite_state") + require.Zero(t, got.dropped) + + dropped, err := retentionCommitted(cutoff) + require.NoError(t, err) + require.Equal(t, int64(1), dropped, "the next run drops February alone") + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + require.Equal(t, int64(1), retentionOwnerRows(t, ctx, conn, kept, org), "March, renamed out, keeps its event") + }) +} + +// Dropping a range partition also locks the DEFAULT partition ACCESS +// EXCLUSIVE, since the DEFAULT partition's constraint changes, and the DROP +// waits for it within what remains of retention's ten seconds. One reader holds +// a due partition for six seconds and another holds the DEFAULT partition +// throughout: retention gives up at ten seconds, drops nothing, and the next +// run, with the DEFAULT partition free, drops the partition. +func TestRetentionWaitsForTheDefaultPartitionWithinItsTenSeconds(t *testing.T) { + const march, defaultPartition = "audit_events_1986_03", "audit_events_default_probe" + retentionDropTableAfter(t, defaultPartition) + retentionDropTableAfter(t, march) + retentionProvisionMonth(t, "1986-03-15", time.Date(1986, 3, 10, 12, 0, 0, 0, time.UTC), uuid.NewString()) + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + _, err := conn.Exec(ctx, `CREATE TABLE public.`+defaultPartition+` PARTITION OF public.audit_events DEFAULT`) + require.NoError(t, err) + }) + + t.Run("the premise: the drop locks the DEFAULT partition", func(t *testing.T) { + const february = "audit_events_1986_02" + retentionDropTableAfter(t, february) + retentionProvisionMonth(t, "1986-02-15", time.Date(1986, 2, 10, 12, 0, 0, 0, time.UTC), uuid.NewString()) + var held bool + require.NoError(t, testStore.WithControlPlane(testCtx, func(ctx context.Context) error { + if _, err := testStore.DropAuditPartitionsBefore(ctx, time.Date(1986, 3, 1, 0, 0, 0, 0, time.UTC)); err != nil { + return err + } + return storetx.Tx(ctx).QueryRow(ctx, ` + SELECT EXISTS (SELECT 1 FROM pg_locks + WHERE pid = pg_backend_pid() AND relation = to_regclass($1) + AND mode = 'AccessExclusiveLock' AND granted)`, "public."+defaultPartition).Scan(&held) + })) + require.True(t, held) + }) + + reader := retentionSession(t) + _, err := reader.Exec(testCtx, `BEGIN; LOCK TABLE ONLY public.`+march+` IN ACCESS SHARE MODE`) + require.NoError(t, err) + defaultReader := retentionSession(t) + _, err = defaultReader.Exec(testCtx, `BEGIN; LOCK TABLE ONLY public.`+defaultPartition+` IN ACCESS SHARE MODE`) + require.NoError(t, err) + + type outcome struct { + dropped int64 + err error + elapsed time.Duration + } + cutoff := time.Date(1986, 4, 1, 0, 0, 0, 0, time.UTC) + ran := make(chan outcome, 1) + go func() { + started := time.Now() + dropped, err := retentionCommitted(cutoff) + ran <- outcome{dropped, err, time.Since(started)} + }() + retentionAwaitHolding(t, "public.audit_events") + time.Sleep(6 * time.Second) + _, err = reader.Exec(testCtx, `COMMIT`) + require.NoError(t, err) + + select { + case got := <-ran: + var pgErr *pgconn.PgError + require.ErrorAs(t, got.err, &pgErr, "retention gave up for want of the DEFAULT partition") + require.Equal(t, "55P03", pgErr.Code, "lock_not_available") + require.Zero(t, got.dropped) + require.Less(t, got.elapsed, 11*time.Second, "ten seconds of waiting in all, with audit_events held") + case <-time.After(30 * time.Second): + t.Fatal("retention went on waiting past its ten seconds") + } + exists, rows := retentionPartitionRows(t, march) + require.True(t, exists, "a run that gave up dropped nothing") + require.Equal(t, int64(1), rows) + + _, err = defaultReader.Exec(testCtx, `COMMIT`) + require.NoError(t, err) + dropped, err := retentionCommitted(cutoff) + require.NoError(t, err) + require.Equal(t, int64(1), dropped, "with the DEFAULT partition free, the next run drops March") +} + +// A run drops everything it chose or nothing. A view on March makes March's +// DROP fail after February's has gone through, and February comes back with +// it, event and all. +func TestRetentionDropsEverythingItChoseOrNothing(t *testing.T) { + const february, march, view = "audit_events_1987_02", "audit_events_1987_03", "audit_events_1987_03_probe" + org := uuid.NewString() + retentionDropTableAfter(t, february) + retentionDropTableAfter(t, march) + retentionProvisionMonth(t, "1987-02-15", time.Date(1987, 2, 10, 12, 0, 0, 0, time.UTC), org) + retentionProvisionMonth(t, "1987-03-15", time.Date(1987, 3, 10, 12, 0, 0, 0, time.UTC), org) + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + _, err := conn.Exec(ctx, `CREATE VIEW public.`+view+` AS SELECT id FROM public.`+march) + require.NoError(t, err) + }) + t.Cleanup(func() { + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + _, err := conn.Exec(ctx, `DROP VIEW IF EXISTS public.`+view) + require.NoError(t, err) + }) + }) + + dropped, err := retentionCommitted(time.Date(1987, 4, 1, 0, 0, 0, 0, time.UTC)) + var pgErr *pgconn.PgError + require.ErrorAs(t, err, &pgErr, "March's DROP fails") + require.Equal(t, "2BP01", pgErr.Code, "dependent_objects_still_exist") + require.Zero(t, dropped) + for _, partition := range []string{february, march} { + exists, rows := retentionPartitionRows(t, partition) + require.True(t, exists, partition) + require.Equal(t, int64(1), rows, partition) + } +} + +// A partition detached and attached again with wider bounds while retention +// waits for audit_events ends after the cutoff once retention holds the lock, +// and is kept. +func TestRetentionKeepsAPartitionReattachedWithWiderBoundsWhileItWaits(t *testing.T) { + const march = "audit_events_1988_03" + retentionDropTableAfter(t, march) + retentionProvisionMonth(t, "1988-03-15", time.Date(1988, 3, 10, 12, 0, 0, 0, time.UTC), uuid.NewString()) + release := retentionHoldReader(t) + operator := retentionSession(t) + reattached := make(chan error, 1) + go func() { + _, err := operator.Exec(testCtx, `BEGIN; + ALTER TABLE public.audit_events DETACH PARTITION public.`+march+`; + ALTER TABLE public.audit_events ATTACH PARTITION public.`+march+` FOR VALUES FROM ('1988-03-01 00:00+00') TO ('1988-07-01 00:00+00'); + COMMIT`) + reattached <- err + }() + retentionAwaitQueuedLocks(t, 1) + ran := make(chan retentionOutcome, 1) + go func() { + dropped, err := retentionCommitted(time.Date(1988, 4, 1, 0, 0, 0, 0, time.UTC)) + ran <- retentionOutcome{dropped, err} + }() + retentionAwaitQueuedLocks(t, 2) + release() + + require.NoError(t, <-reattached, "the premise: the partition was attached again, wider, while retention waited") + got := <-ran + require.NoError(t, got.err) + require.Zero(t, got.dropped, "it ends after the cutoff now") + exists, _ := retentionPartitionRows(t, march) + require.True(t, exists) +} + +// A run holds the audit_events policy it keeps to until it commits. A change +// to the policy made while the run waits for audit_events, or tries for the +// partition it drops, waits in turn for the run: whether it extends the +// window or deletes the policy to keep every record, it cannot commit under a +// run that decided by the policy it replaces. It goes through once the run +// has committed. +func TestAPolicyChangeWaitsForARetentionRunUnderWay(t *testing.T) { + const due = "audit_events_1994_01" + for _, change := range []struct{ name, statement string }{ + {"extending the window", `UPDATE data_retention_policies SET retention_days = 20000 WHERE resource_type = 'audit_events'`}, + {"deleting the policy", `DELETE FROM data_retention_policies WHERE resource_type = 'audit_events'`}, + } { + for _, held := range []string{"audit_events", due} { + t.Run(change.name+" while it waits for "+held, func(t *testing.T) { + retentionDropTableAfter(t, due) + retentionProvisionMonth(t, "1994-01-15", time.Date(1994, 1, 10, 12, 0, 0, 0, time.UTC), uuid.NewString()) + retentionKeepPolicy(t) + + holder := retentionSession(t) + _, err := holder.Exec(testCtx, `BEGIN; LOCK TABLE ONLY public.`+held+` IN ACCESS SHARE MODE`) + require.NoError(t, err) + ran := make(chan retentionOutcome, 1) + go func() { + dropped, err := retentionCommitted(time.Date(1994, 2, 1, 0, 0, 0, 0, time.UTC)) + ran <- retentionOutcome{dropped, err} + }() + if held == "audit_events" { + retentionAwaitWaiters(t, "public.audit_events", 1) + } else { + retentionAwaitHolding(t, "public.audit_events") + } + + operator := retentionSession(t) + _, err = operator.Exec(testCtx, `BEGIN; SET LOCAL lock_timeout = '1s'; `+change.statement) + var pgErr *pgconn.PgError + require.ErrorAs(t, err, &pgErr, "the change waits for the run") + require.Equal(t, "55P03", pgErr.Code, "lock_not_available") + _, err = operator.Exec(testCtx, `ROLLBACK`) + require.NoError(t, err) + + _, err = holder.Exec(testCtx, `COMMIT`) + require.NoError(t, err) + got := <-ran + require.NoError(t, got.err) + require.Equal(t, int64(1), got.dropped, "the run kept to the policy it held") + _, err = operator.Exec(testCtx, change.statement) + require.NoError(t, err, "once the run has committed, the change goes through") + }) + } + } +} + +// The cutoff is checked against the policy as the run reads it under its row +// lock, not as it read it before. A run finds a partition due, then waits to +// lock the policy behind an operator who has the table to themselves and +// extends the window; once the change commits, the run reads the new window, +// refuses the cutoff, and drops nothing. +func TestRetentionKeepsToAPolicyChangedWhileItWaitsToLockIt(t *testing.T) { + const due = "audit_events_1994_09" + retentionDropTableAfter(t, due) + retentionProvisionMonth(t, "1994-09-15", time.Date(1994, 9, 10, 12, 0, 0, 0, time.UTC), uuid.NewString()) + retentionKeepPolicy(t) + + operator := retentionSession(t) + _, err := operator.Exec(testCtx, `BEGIN; LOCK TABLE data_retention_policies IN EXCLUSIVE MODE`) + require.NoError(t, err) + ran := make(chan retentionOutcome, 1) + go func() { + dropped, err := retentionCommitted(time.Date(1994, 10, 1, 0, 0, 0, 0, time.UTC)) + ran <- retentionOutcome{dropped, err} + }() + retentionAwaitWaiters(t, "public.data_retention_policies", 1) + _, err = operator.Exec(testCtx, ` + UPDATE data_retention_policies SET retention_days = 20000 WHERE resource_type = 'audit_events'; + COMMIT`) + require.NoError(t, err) + + got := <-ran + var pgErr *pgconn.PgError + require.ErrorAs(t, got.err, &pgErr, "the run keeps to the window the change left") + require.Equal(t, "22023", pgErr.Code, "invalid_parameter_value") + require.Zero(t, got.dropped) + exists, _ := retentionPartitionRows(t, due) + require.True(t, exists) +} + +// A change to the policy already under way when a run, having found something +// due, reads the policy again makes the run refuse rather than wait: which +// window the change leaves is unknown until it commits. The run drops nothing, +// at once, and the next run keeps to what the change left -- here a window +// that does not allow the cutoff. +func TestRetentionRefusesWhileItsPolicyIsBeingChanged(t *testing.T) { + const due = "audit_events_1994_06" + retentionDropTableAfter(t, due) + retentionProvisionMonth(t, "1994-06-15", time.Date(1994, 6, 10, 12, 0, 0, 0, time.UTC), uuid.NewString()) + retentionKeepPolicy(t) + cutoff := time.Date(1994, 7, 1, 0, 0, 0, 0, time.UTC) + + operator := retentionSession(t) + _, err := operator.Exec(testCtx, `BEGIN; UPDATE data_retention_policies SET retention_days = 20000 WHERE resource_type = 'audit_events'`) + require.NoError(t, err) + started := time.Now() + dropped, err := retentionCommitted(cutoff) + var pgErr *pgconn.PgError + require.ErrorAs(t, err, &pgErr, "the run refused") + require.Equal(t, "55P03", pgErr.Code, "lock_not_available") + require.Zero(t, dropped) + require.Less(t, time.Since(started), 5*time.Second, "without waiting for the change") + exists, _ := retentionPartitionRows(t, due) + require.True(t, exists) + + _, err = operator.Exec(testCtx, `COMMIT`) + require.NoError(t, err) + _, err = retentionCommitted(cutoff) + require.ErrorAs(t, err, &pgErr, "the next run keeps to the window the change left") + require.Equal(t, "22023", pgErr.Code, "invalid_parameter_value") + exists, _ = retentionPartitionRows(t, due) + require.True(t, exists) +} + +// withSessionDefault returns connection with a server setting every session it +// opens starts with. +func withSessionDefault(t *testing.T, connection, setting, value string) string { + t.Helper() + if parsed, err := url.Parse(connection); err == nil && (parsed.Scheme == "postgres" || parsed.Scheme == "postgresql") { + query := parsed.Query() + query.Set(setting, value) + parsed.RawQuery = query.Encode() + return parsed.String() + } + return connection + " " + setting + "=" + value +} + +// The store's own retention call runs at READ COMMITTED whatever isolation the +// database gives a transaction by default, so the function's refusal never +// stops scheduled retention. A caller's own transaction at another level is +// refused and drops nothing. +func TestRetentionRunsAtReadCommittedWhateverTheDatabaseDefault(t *testing.T) { + const due = "audit_events_1995_10" + retentionRetire(t, "1996-01-01") + retentionProvisionMonth(t, "1995-10-15", time.Date(1995, 10, 10, 12, 0, 0, 0, time.UTC), uuid.NewString()) + + secret := func(key string) string { + value, err := codefly.For(testCtx).Service("store").Secret("postgres", key) + require.NoError(t, err) + return value + } + store, err := infra.NewPostgresStoreWithCapabilities(testCtx, + secret("read-only-connection"), secret("read-write-connection"), + withSessionDefault(t, secret("control-plane-connection"), "default_transaction_isolation", "serializable")) + require.NoError(t, err) + t.Cleanup(store.Close) + + var level string + require.NoError(t, store.WithControlPlane(testCtx, func(ctx context.Context) error { + return storetx.Tx(ctx).QueryRow(ctx, `SELECT current_setting('transaction_isolation')`).Scan(&level) + })) + require.Equal(t, "serializable", level, "the premise: this store's transactions default to SERIALIZABLE") + + cutoff := time.Date(1995, 12, 1, 0, 0, 0, 0, time.UTC) + err = store.WithControlPlane(testCtx, func(ctx context.Context) error { + _, err := store.DropAuditPartitionsBefore(ctx, cutoff) + return err + }) + var pgErr *pgconn.PgError + require.ErrorAs(t, err, &pgErr, "a caller's SERIALIZABLE transaction is refused") + require.Equal(t, "25000", pgErr.Code, "invalid_transaction_state") + exists, _ := retentionPartitionRows(t, due) + require.True(t, exists, "a refused run drops nothing") + + dropped, err := store.DropAuditPartitionsBefore(testCtx, cutoff) + require.NoError(t, err, "with no transaction of its caller's, retention opens its own at READ COMMITTED") + require.Equal(t, int64(1), dropped) + exists, _ = retentionPartitionRows(t, due) + require.False(t, exists) +} + +// The function waits ten seconds in all for its locks, not ten for each: +// lock_timeout bounds one wait, and a run that drops two partitions waits for +// audit_events and then for each partition, holding audit_events ACCESS +// EXCLUSIVE, which audit writes queue behind. Two sessions each hold a due +// partition; the first lets go after six seconds, the second not until the run +// is over. The run gives up when its ten seconds are spent, drops nothing, and +// a later run drops both. +func TestRetentionWaitsTenSecondsInAllForItsLocks(t *testing.T) { + retentionRetire(t, "1993-01-01") + for _, day := range []string{"1992-01-15", "1992-02-15"} { + retentionProvisionMonth(t, day, time.Date(1992, 1, 10, 12, 0, 0, 0, time.UTC), uuid.NewString()) + } + dsn, err := codefly.For(testCtx).Service("store").Secret("postgres", "owner-connection") + require.NoError(t, err) + hold := func(partition string) (release func()) { + conn, err := pgx.Connect(testCtx, dsn) + require.NoError(t, err) + t.Cleanup(func() { _ = conn.Close(testCtx) }) + _, err = conn.Exec(testCtx, `BEGIN; LOCK TABLE ONLY public.`+pgx.Identifier{partition}.Sanitize()+` IN ACCESS SHARE MODE`) + require.NoError(t, err) + var once sync.Once + release = func() { once.Do(func() { _, err := conn.Exec(testCtx, `COMMIT`); require.NoError(t, err) }) } + t.Cleanup(release) + return release + } + releaseFirst := hold("audit_events_1992_01") + releaseSecond := hold("audit_events_1992_02") + + type outcome struct { + dropped int64 + err error + elapsed time.Duration + } + ran := make(chan outcome, 1) + go func() { + started := time.Now() + dropped, err := retentionCommitted(time.Date(1992, 3, 1, 0, 0, 0, 0, time.UTC)) + ran <- outcome{dropped, err, time.Since(started)} + }() + // Holding audit_events, retention tries for the first partition, then, + // holding that, for the second. + retentionAwaitHolding(t, "public.audit_events") + time.Sleep(6 * time.Second) + releaseFirst() + retentionAwaitHolding(t, "public.audit_events_1992_01") + + select { + case got := <-ran: + var pgErr *pgconn.PgError + require.ErrorAs(t, got.err, &pgErr, "retention gave up for want of its locks") + require.Equal(t, "55P03", pgErr.Code, "lock_not_available") + require.Zero(t, got.dropped) + require.Less(t, got.elapsed, 11*time.Second, "ten seconds of waiting in all, not ten for each lock") + case <-time.After(30 * time.Second): + t.Fatal("retention went on waiting past its ten seconds") + } + for _, partition := range []string{"audit_events_1992_01", "audit_events_1992_02"} { + exists, _ := retentionPartitionRows(t, partition) + require.True(t, exists, "a run that gave up dropped nothing") + } + + releaseSecond() + dropped, err := retentionCommitted(time.Date(1992, 3, 1, 0, 0, 0, 0, time.UTC)) + require.NoError(t, err) + require.Equal(t, int64(2), dropped, "with its locks free, the next run drops both") +} + +// A retention window is a positive number of days, and the table refuses any +// other, so no writer can leave a window retention would have to read as +// something it does not say. +func TestARetentionPolicyKeepsRecordsForAPositiveNumberOfDays(t *testing.T) { + asRetention(t, func(ctx context.Context, tx pgx.Tx) { + for _, days := range []int{0, -1} { + for _, statement := range []string{ + `UPDATE data_retention_policies SET retention_days = $1 WHERE resource_type = 'sessions'`, + `INSERT INTO data_retention_policies (resource_type, retention_days) VALUES ('example_records', $1)`, + } { + attempt, err := tx.Begin(ctx) + require.NoError(t, err) + _, err = attempt.Exec(ctx, statement, days) + var pgErr *pgconn.PgError + require.ErrorAs(t, err, &pgErr, "%d days is refused: %s", days, statement) + require.Equal(t, "23514", pgErr.Code, "check_violation") + require.NoError(t, attempt.Rollback(ctx)) + } + } + }) +} + +// Migration 34 down, then up again, leaves every audit maintenance function as +// it found it -- definition, owner and grants -- and a second up refuses rather +// than apply twice. +func TestTheRetentionMigrationReplaysDownThenUp(t *testing.T) { + read := func(direction string) string { + paths, err := filepath.Glob("../../../../store/migrations/*_audit_retention_partition_bounds." + direction + ".sql") + require.NoError(t, err) + require.Len(t, paths, 1, "the migration's %s half", direction) + body, err := os.ReadFile(paths[0]) + require.NoError(t, err) + return string(body) + } + up, down := read("up"), read("down") + const functions = ` + SELECT string_agg(p.oid::regprocedure::text || ' ' || pg_get_userbyid(p.proowner) || ' ' || + coalesce(p.proacl::text, '') || ' ' || md5(pg_get_functiondef(p.oid)), E'\n' ORDER BY 1) + FROM pg_proc p + WHERE p.pronamespace = 'public'::regnamespace AND p.proname LIKE 'audit%'` + asMigrationOwner(t, func(ctx context.Context, conn *pgxpool.Conn) { + tx, err := conn.Begin(ctx) + require.NoError(t, err) + defer func() { _ = tx.Rollback(ctx) }() + var before, after string + require.NoError(t, tx.QueryRow(ctx, functions).Scan(&before)) + _, err = tx.Exec(ctx, down) + require.NoError(t, err, "down") + _, err = tx.Exec(ctx, up) + require.NoError(t, err, "up again") + require.NoError(t, tx.QueryRow(ctx, functions).Scan(&after)) + require.Equal(t, before, after) + + _, err = tx.Exec(ctx, up) + var pgErr *pgconn.PgError + require.ErrorAs(t, err, &pgErr, "a second up refuses") + require.Equal(t, "42710", pgErr.Code, "duplicate_object: the constraint is there already") + }) +} + +// The migration that made a window a positive number of days refuses to apply +// while a policy holds one that is not, and names it: which window was meant is +// the operator's to say, not retention's to guess. +func TestTheRetentionMigrationRefusesAWindowThatIsNotPositive(t *testing.T) { + paths, err := filepath.Glob("../../../../store/migrations/*_audit_retention_partition_bounds.up.sql") + require.NoError(t, err) + require.Len(t, paths, 1, "the migration that holds the rule") + migration, err := os.ReadFile(paths[0]) + require.NoError(t, err) + asRetention(t, func(ctx context.Context, tx pgx.Tx) { + _, err := tx.Exec(ctx, ` + ALTER TABLE data_retention_policies DROP CONSTRAINT data_retention_policies_retention_days_positive; + UPDATE data_retention_policies SET retention_days = 0 WHERE resource_type = 'sessions'`) + require.NoError(t, err, "the premise: a policy from before the rule") + _, err = tx.Exec(ctx, string(migration)) + var pgErr *pgconn.PgError + require.ErrorAs(t, err, &pgErr, "the migration refuses") + require.Equal(t, "23514", pgErr.Code, "check_violation") + require.Contains(t, pgErr.Message, "sessions (0 days)", "and names the policy") + }) +} diff --git a/module/services/accounts/code/pkg/infra/postgres_retention.go b/module/services/accounts/code/pkg/infra/postgres_retention.go index fff280c46..df0f8db6e 100644 --- a/module/services/accounts/code/pkg/infra/postgres_retention.go +++ b/module/services/accounts/code/pkg/infra/postgres_retention.go @@ -7,6 +7,15 @@ import ( "accounts/pkg/business" ) +// DatabaseNow reads the database's clock, the one every retention cutoff is +// counted from: the policy window is the database's, and an application clock +// running ahead must not move it. +func (s *PostgresStore) DatabaseNow(ctx context.Context) (time.Time, error) { + var now time.Time + err := s.getQueryExecutor(ctx).QueryRow(ctx, `SELECT clock_timestamp()`).Scan(&now) + return now, err +} + func (s *PostgresStore) GetRetentionPolicies(ctx context.Context) ([]*business.RetentionPolicy, error) { q := s.getQueryExecutor(ctx) rows, err := q.Query(ctx, ` diff --git a/module/services/accounts/code/pkg/infra/testdata/control_plane_call_sites.txt b/module/services/accounts/code/pkg/infra/testdata/control_plane_call_sites.txt index 8fda4b3a0..7c08bb083 100644 --- a/module/services/accounts/code/pkg/infra/testdata/control_plane_call_sites.txt +++ b/module/services/accounts/code/pkg/infra/testdata/control_plane_call_sites.txt @@ -122,6 +122,7 @@ pkg/business/retention.go: (*Service).PurgeExpiredWorkContextReplays: WithContro pkg/business/retention.go: (*Service).RunRetention: WithControlPlane pkg/business/retention.go: (*Service).RunRetention: WithControlPlane pkg/business/retention.go: (*Service).RunRetention: WithControlPlane +pkg/business/retention.go: (*Service).RunRetention: WithControlPlane pkg/business/service.go: (*Service).AssignRole: WithControlPlane pkg/business/service.go: (*Service).CheckPermission: WithControlPlane pkg/business/service.go: (*Service).CreateRole: WithControlPlane @@ -166,6 +167,7 @@ pkg/infra/postgres.go: (*PostgresStore).LinkIdentity: txbind.BindRequest pkg/infra/postgres.go: (*PostgresStore).RegisterUser: pgx.BeginTxFunc(controlPlane) pkg/infra/postgres.go: (*PostgresStore).RegisterUser: txbind.BindControlPlane pkg/infra/postgres.go: (*PostgresStore).RunInTransaction: txbind.BindRequest +pkg/infra/postgres_audit_registry.go: (*PostgresStore).DropAuditPartitionsBefore: withControlPlaneTx pkg/infra/postgres_auth_bootstrap.go: (*PostgresStore).WithAuthBootstrapTx: withControlPlaneTx pkg/infra/postgres_auth_bootstrap.go: (*PostgresStore).WithAuthLookupTx: withControlPlaneTx pkg/infra/postgres_client_authorization.go: (*PostgresStore).ConsumeClientAuthorizationCode: WithControlPlane diff --git a/module/services/accounts/code/pkg/metrics/slo_pack.json b/module/services/accounts/code/pkg/metrics/slo_pack.json index 87e17c39f..66bf81ef7 100644 --- a/module/services/accounts/code/pkg/metrics/slo_pack.json +++ b/module/services/accounts/code/pkg/metrics/slo_pack.json @@ -123,6 +123,14 @@ "runbook": "usage-reconciliation", "expression_language": "promql", "expression": "max_over_time(saas_usage_reconciliation_discrepancy[1h]) != 0" + }, + { + "id": "retention_failures", + "signal": "saas.retention.failing", + "condition": "the most recent scheduled retention run failed in some part", + "runbook": "retention", + "expression_language": "promql", + "expression": "saas_retention_failing > 0" } ] } diff --git a/module/services/accounts/code/pkg/metrics/slo_pack_test.yml b/module/services/accounts/code/pkg/metrics/slo_pack_test.yml new file mode 100644 index 000000000..ed4f31e5d --- /dev/null +++ b/module/services/accounts/code/pkg/metrics/slo_pack_test.yml @@ -0,0 +1,82 @@ +# promtool rule tests for the alerts in slo_pack.json. Each alert there becomes +# a Prometheus alerting rule named by its id, with its expression, and these +# tests feed those rules series and say what fires. CI's "Test the alert pack's +# rules with promtool" step writes the rules beside this file and runs them; by +# hand, from this directory: +# +# jq '{groups: [{name: "slo_pack", rules: [.alerts[] | {alert: .id, expr: .expression}]}]}' \ +# slo_pack.json > slo_pack.rules.json +# promtool test rules slo_pack_test.yml +# +# Loading the rules parses every alert's expression, so an expression +# Prometheus cannot run fails here too. + +rule_files: + - slo_pack.rules.json + +evaluation_interval: 1m + +tests: + # Retention runs at startup and then once a day. saas_retention_failing is 1 + # for each part of the most recent run that failed, so the scrape after a + # failed run is the first sample of its series: the alert needs no earlier + # one, where a counter's increase over its first sample is 0. + - name: retention_failures, the first failed run alerts at once + interval: 1m + input_series: + - series: 'saas_retention_failing{resource="audit_events",step="remove"}' + values: '_ 1x120' + alert_rule_test: + - eval_time: 0m + alertname: retention_failures + exp_alerts: [] + - eval_time: 1m + alertname: retention_failures + exp_alerts: + - exp_labels: + resource: audit_events + step: remove + - eval_time: 2h + alertname: retention_failures + exp_alerts: + - exp_labels: + resource: audit_events + step: remove + + # A part the run before failed reads 0 once a run no longer fails it. + - name: retention_failures, a run that no longer fails a part clears it + interval: 1m + input_series: + - series: 'saas_retention_failing{resource="sessions",step="policy"}' + values: '1x5 0x60' + alert_rule_test: + - eval_time: 5m + alertname: retention_failures + exp_alerts: + - exp_labels: + resource: sessions + step: policy + - eval_time: 6m + alertname: retention_failures + exp_alerts: [] + + # Each failed part alerts on its own, by resource and step. + - name: retention_failures, each failed part alerts + interval: 1m + input_series: + - series: 'saas_retention_failing{resource="audit_events",step="provision"}' + values: '1x10' + - series: 'saas_retention_failing{resource="data_retention_policies",step="load"}' + values: '0x10' + - series: 'saas_retention_failing{resource="retention",step="run"}' + values: '1x10' + alert_rule_test: + - eval_time: 5m + alertname: retention_failures + exp_alerts: + - exp_labels: + resource: audit_events + step: provision + - exp_labels: + resource: retention + step: run diff --git a/module/services/accounts/code/retention_telemetry.go b/module/services/accounts/code/retention_telemetry.go new file mode 100644 index 000000000..ed0969a8e --- /dev/null +++ b/module/services/accounts/code/retention_telemetry.go @@ -0,0 +1,96 @@ +package main + +import ( + "context" + "errors" + "sync" + + "github.com/codefly-dev/core/wool" + "go.opentelemetry.io/otel/attribute" + otelmetric "go.opentelemetry.io/otel/metric" + + "accounts/pkg/business" +) + +// retentionFailingMetric is 1 for each part of the most recent scheduled +// retention run that failed, by resource and step, and 0 for a part an earlier +// run failed and the most recent did not. The alert pack's retention_failures +// alert reads it, as saas_retention_failing, so a run that did not do all it +// should reaches someone instead of ending as a log line. It is a gauge because +// a counter cannot alert on a first failure: its first sample is already 1, and +// Prometheus sees no increase in a series it never saw lower. +const retentionFailingMetric = "saas.retention.failing" + +// retentionPart is one part of a retention run, as the gauge labels it. +type retentionPart struct { + resource, step string +} + +func (p retentionPart) attributes() otelmetric.MeasurementOption { + return otelmetric.WithAttributes(attribute.String("resource", p.resource), attribute.String("step", p.step)) +} + +type retentionTelemetry struct { + failing otelmetric.Int64Gauge + + mu sync.Mutex + // failed holds the parts the last reported run failed, which the next + // report sets back to 0 if its run does not fail them. + failed map[retentionPart]bool +} + +func newRetentionTelemetry(meter otelmetric.Meter) (*retentionTelemetry, error) { + failing, err := meter.Int64Gauge(retentionFailingMetric, + otelmetric.WithDescription("1 for each part of the most recent scheduled retention run that failed, by resource and step.")) + if err != nil { + return nil, err + } + return &retentionTelemetry{failing: failing}, nil +} + +// runScheduledRetention runs one retention pass and reports it: what it removed +// as information, a run that failed in any part as an error, and every run to +// the gauge the alert pack watches. +func runScheduledRetention(ctx context.Context, service *business.Service, metrics *retentionTelemetry) { + w := wool.Get(ctx).In("retention") + deleted, err := service.RunRetention(ctx) + for kind, count := range deleted { + if count > 0 { + w.Info("deleted records", wool.Field("count", count), wool.Field("kind", kind)) + } + } + metrics.report(ctx, err) + if err != nil { + w.Error("scheduled run failed", wool.ErrField(err)) + } +} + +// report sets the gauge for a run that ended with err: 1 for each part it +// failed -- each failure of a *business.RetentionError, or the run as a whole +// for any other error -- and 0 for each part the run before failed and this +// one did not. +func (t *retentionTelemetry) report(ctx context.Context, err error) { + failed := map[retentionPart]bool{} + var run *business.RetentionError + switch { + case err == nil: + case errors.As(err, &run): + for _, failure := range run.Failures { + failed[retentionPart{failure.Resource, string(failure.Step)}] = true + } + default: + failed[retentionPart{"retention", "run"}] = true + } + + t.mu.Lock() + defer t.mu.Unlock() + for part := range t.failed { + if !failed[part] { + t.failing.Record(ctx, 0, part.attributes()) + } + } + for part := range failed { + t.failing.Record(ctx, 1, part.attributes()) + } + t.failed = failed +} diff --git a/module/services/accounts/code/retention_telemetry_test.go b/module/services/accounts/code/retention_telemetry_test.go new file mode 100644 index 000000000..39232c176 --- /dev/null +++ b/module/services/accounts/code/retention_telemetry_test.go @@ -0,0 +1,169 @@ +package main + +import ( + "context" + "errors" + "net/http" + "net/http/httptest" + "os" + "strings" + "testing" + "time" + + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promhttp" + "github.com/stretchr/testify/require" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" + + "accounts/pkg/business" + "accounts/pkg/metrics" +) + +// retentionTelemetryFor registers the retention gauge with a provider whose +// reader the test collects from. +func retentionTelemetryFor(t *testing.T) (*sdkmetric.ManualReader, *retentionTelemetry) { + t.Helper() + reader := sdkmetric.NewManualReader() + provider := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + t.Cleanup(func() { _ = provider.Shutdown(context.Background()) }) + telemetry, err := newRetentionTelemetry(provider.Meter("retention-test")) + require.NoError(t, err) + return reader, telemetry +} + +// retentionFailing reads the gauge, by "resource step". +func retentionFailing(t *testing.T, reader *sdkmetric.ManualReader) map[string]int64 { + t.Helper() + var collected metricdata.ResourceMetrics + require.NoError(t, reader.Collect(context.Background(), &collected)) + failing := map[string]int64{} + for _, scope := range collected.ScopeMetrics { + for _, m := range scope.Metrics { + if m.Name != retentionFailingMetric { + continue + } + gauge, ok := m.Data.(metricdata.Gauge[int64]) + require.True(t, ok, "%s is a gauge", retentionFailingMetric) + for _, point := range gauge.DataPoints { + resource, _ := point.Attributes.Value("resource") + step, _ := point.Attributes.Value("step") + failing[resource.AsString()+" "+step.AsString()] = point.Value + } + } + } + return failing +} + +// Each part the most recent run failed reads 1, by resource and step, and a +// part an earlier run failed reads 0 once a run no longer fails it; any other +// error is the run as a whole failing. Nothing is reported for a part that +// never failed. +func TestTheGaugeReadsOneForEachPartTheLastRunFailed(t *testing.T) { + reader, telemetry := retentionTelemetryFor(t) + ctx := context.Background() + removal := business.RetentionFailure{Resource: "audit_events", Step: business.RetentionStepRemove, Err: errors.New("lock not available")} + policy := business.RetentionFailure{Resource: "sessions", Step: business.RetentionStepPolicy, Err: errors.New("not a positive number of days")} + + telemetry.report(ctx, nil) + require.Empty(t, retentionFailing(t, reader)) + + telemetry.report(ctx, &business.RetentionError{Failures: []business.RetentionFailure{removal, policy}}) + require.Equal(t, map[string]int64{"audit_events remove": 1, "sessions policy": 1}, retentionFailing(t, reader)) + + telemetry.report(ctx, &business.RetentionError{Failures: []business.RetentionFailure{policy}}) + require.Equal(t, map[string]int64{"audit_events remove": 0, "sessions policy": 1}, retentionFailing(t, reader)) + + telemetry.report(ctx, nil) + require.Equal(t, map[string]int64{"audit_events remove": 0, "sessions policy": 0}, retentionFailing(t, reader)) + + telemetry.report(ctx, errors.New("anything else")) + require.Equal(t, map[string]int64{"audit_events remove": 0, "sessions policy": 0, "retention run": 1}, retentionFailing(t, reader)) +} + +// scheduledRetentionStore is a store which holds no retention policy and whose +// audit partition provisioning fails while provisionErr is set. +type scheduledRetentionStore struct { + business.Store + provisionErr error +} + +func (*scheduledRetentionStore) WithControlPlane(ctx context.Context, fn func(context.Context) error) error { + return fn(ctx) +} + +func (s *scheduledRetentionStore) EnsureAuditPartitions(context.Context, int) error { + return s.provisionErr +} + +func (*scheduledRetentionStore) DatabaseNow(context.Context) (time.Time, error) { + return time.Date(2026, time.October, 11, 12, 0, 0, 0, time.UTC), nil +} + +func (*scheduledRetentionStore) GetRetentionPolicies(context.Context) ([]*business.RetentionPolicy, error) { + return nil, nil +} + +// The scheduler reports every run to the gauge the alert pack watches, not only +// to its log: a run that failed sets it, and the next run that does not clears +// it. +func TestAScheduledRetentionRunReportsToTheGauge(t *testing.T) { + reader, telemetry := retentionTelemetryFor(t) + store := &scheduledRetentionStore{provisionErr: errors.New("provisioning waited ten seconds for its locks")} + service, err := business.NewService(store) + require.NoError(t, err) + + runScheduledRetention(context.Background(), service, telemetry) + require.Equal(t, map[string]int64{"audit_events provision": 1}, retentionFailing(t, reader)) + + store.provisionErr = nil + runScheduledRetention(context.Background(), service, telemetry) + require.Equal(t, map[string]int64{"audit_events provision": 0}, retentionFailing(t, reader)) +} + +// The alert pack's retention alert reads the gauge under the name the /metrics +// scrape serves it by, which is also the series the pack's promtool tests feed +// the alert: a failed run's first scrape carries a 1, with no earlier sample. +func TestTheRetentionAlertReadsTheGaugeAsItIsScraped(t *testing.T) { + registry := prometheus.NewRegistry() + exporter, err := newScrapeExporter(registry) + require.NoError(t, err) + provider := sdkmetric.NewMeterProvider(sdkmetric.WithReader(exporter)) + t.Cleanup(func() { _ = provider.Shutdown(context.Background()) }) + telemetry, err := newRetentionTelemetry(provider.Meter("github.com/codefly-dev/module-saas-starter/accounts")) + require.NoError(t, err) + telemetry.report(context.Background(), &business.RetentionError{Failures: []business.RetentionFailure{ + {Resource: "audit_events", Step: business.RetentionStepRemove, Err: errors.New("lock not available")}, + }}) + + recorder := httptest.NewRecorder() + promhttp.HandlerFor(registry, promhttp.HandlerOpts{}).ServeHTTP(recorder, + httptest.NewRequest(http.MethodGet, "http://accounts.internal/metrics", nil)) + require.Equal(t, http.StatusOK, recorder.Code) + scraped := strings.ReplaceAll(retentionFailingMetric, ".", "_") + body := recorder.Body.String() + require.Contains(t, body, "# TYPE "+scraped+" gauge\n") + var sample string + for _, line := range strings.Split(body, "\n") { + if strings.HasPrefix(line, scraped+"{") { + sample = line + } + } + require.Contains(t, sample, `resource="audit_events"`) + require.Contains(t, sample, `step="remove"`) + require.True(t, strings.HasSuffix(sample, "} 1"), "the failed part reads 1: %s", sample) + + pack, err := metrics.DefaultSLOPack() + require.NoError(t, err) + var expression string + for _, alert := range pack.Alerts { + if alert.ID == "retention_failures" { + require.Equal(t, "retention", alert.Runbook) + expression = alert.Expression + } + } + require.Contains(t, expression, scraped, "the alert reads the gauge by its scraped name") + tests, err := os.ReadFile("pkg/metrics/slo_pack_test.yml") + require.NoError(t, err) + require.Contains(t, string(tests), scraped+"{", "the promtool tests feed the alert the series the scrape serves") +} diff --git a/module/services/accounts/code/telemetry_metrics.go b/module/services/accounts/code/telemetry_metrics.go index b088b2346..61de19705 100644 --- a/module/services/accounts/code/telemetry_metrics.go +++ b/module/services/accounts/code/telemetry_metrics.go @@ -33,12 +33,7 @@ func enableOTELMetrics(ctx context.Context, serviceName, endpoint string) (*otel return nil, err } registry := prometheus.NewRegistry() - scrapeExporter, err := otelprometheus.New( - otelprometheus.WithRegisterer(registry), - otelprometheus.WithResourceAsConstantLabels( - attribute.NewAllowKeysFilter("service.name"), - ), - ) + scrapeExporter, err := newScrapeExporter(registry) if err != nil { return nil, err } @@ -71,6 +66,17 @@ func enableOTELMetrics(ctx context.Context, serviceName, endpoint string) (*otel }, nil } +// newScrapeExporter is the exporter the /metrics scrape serves: the names it +// gives instruments are the ones the alert pack's expressions read. +func newScrapeExporter(registry prometheus.Registerer) (*otelprometheus.Exporter, error) { + return otelprometheus.New( + otelprometheus.WithRegisterer(registry), + otelprometheus.WithResourceAsConstantLabels( + attribute.NewAllowKeysFilter("service.name"), + ), + ) +} + func startGCActivityMetrics(provider *metric.MeterProvider) error { meter := provider.Meter("github.com/codefly-dev/module-saas-starter/go-runtime") cycleCount, err := meter.Int64ObservableCounter( diff --git a/module/services/accounts/code/work.go b/module/services/accounts/code/work.go index fe20ce73a..8840d0fdc 100644 --- a/module/services/accounts/code/work.go +++ b/module/services/accounts/code/work.go @@ -1161,21 +1161,17 @@ func doWork(ctx context.Context) (Clean, error) { // Start background data retention goroutine. Runs once on startup and // then every 24 hours, deleting records older than their configured - // retention period. + // retention period. A run that fails in any part is an error, and sets + // saas.retention.failing, which the alert pack watches: nobody reads the + // log of a job that runs once a day. + retentionMetrics, err := newRetentionTelemetry(otel.Meter("github.com/codefly-dev/module-saas-starter/accounts")) + if err != nil { + return nil, fmt.Errorf("register retention metrics: %w", err) + } retentionCtx, retentionCancel := context.WithCancel(ctx) go func() { rw := wool.Get(retentionCtx).In("retention") - runRetention := func() { - if deleted, err := service.RunRetention(retentionCtx); err != nil { - rw.Warn("scheduled run failed", wool.ErrField(err)) - } else { - for k, v := range deleted { - if v > 0 { - rw.Info("deleted records", wool.Field("count", v), wool.Field("kind", k)) - } - } - } - } + runRetention := func() { runScheduledRetention(retentionCtx, service, retentionMetrics) } // Single-use replay markers expire with their token (≤ 15 min), so they // are swept far more often than the daily retention pass or they would // pile up for a day before reclamation. diff --git a/module/services/store/migrations/34_audit_retention_partition_bounds.down.sql b/module/services/store/migrations/34_audit_retention_partition_bounds.down.sql new file mode 100644 index 000000000..cb8dbdddd --- /dev/null +++ b/module/services/store/migrations/34_audit_retention_partition_bounds.down.sql @@ -0,0 +1,165 @@ +-- Reverts migration 34. Retention and provisioning give up its rules: what +-- retention drops depends again on the zone of the session that runs it and of +-- the one that created each partition, it accepts a cutoff the policy does not +-- allow, a partition being detached, or detached or renamed while it ran, is +-- dropped like any other, and neither retention nor provisioning bounds its +-- wait for a lock. +-- A new partition's bounds are again the creating session's midnights, and +-- data_retention_policies accepts a window that is not a positive number of days. +-- +-- Each function is restored as the migration that last defined it left it -- +-- audit_events_drop_partitions_before as migration 12 left it, +-- audit_events_ensure_partition and the one-argument +-- audit_events_secure_partition as migration 11 did, and +-- audit_events_secure_all_partitions as migration 13 did -- search_path +-- included. CREATE OR REPLACE replaces every SET clause, so lock_timeout, +-- DateStyle and TimeZone go with migration 34, and keeps owners and grants. The +-- functions migration 34 added are dropped once nothing calls them. + +ALTER TABLE public.data_retention_policies + DROP CONSTRAINT data_retention_policies_retention_days_positive; + +CREATE OR REPLACE FUNCTION public.audit_events_drop_partitions_before(cutoff timestamp with time zone) RETURNS integer + LANGUAGE plpgsql SECURITY DEFINER + SET search_path TO 'public', 'pg_temp' + AS $_$ +DECLARE + part RECORD; + dropped INT := 0; + upper_bound TIMESTAMPTZ; +BEGIN + FOR part IN + SELECT c.relname + FROM pg_inherits i + JOIN pg_class c ON c.oid = i.inhrelid + JOIN pg_class p ON p.oid = i.inhparent + WHERE p.relname = 'audit_events' + AND c.relname ~ '^audit_events_[0-9]{4}_[0-9]{2}$' + LOOP + -- Upper bound = first instant of the month AFTER the partition's month, + -- derived from the deterministic partition name. + upper_bound := date_trunc( + 'month', + to_date(substring(part.relname FROM 'audit_events_([0-9]{4}_[0-9]{2})'), 'YYYY_MM') + ) + INTERVAL '1 month'; + IF upper_bound <= cutoff THEN + EXECUTE format('DROP TABLE %I', part.relname); + dropped := dropped + 1; + END IF; + END LOOP; + RETURN dropped; +END; +$_$; + +CREATE OR REPLACE FUNCTION public.audit_events_secure_partition(target regclass) RETURNS void + LANGUAGE plpgsql + SET search_path TO 'pg_catalog', 'public', 'pg_temp' + AS $$ +DECLARE + parent CONSTANT regclass := 'public.audit_events'::regclass; + pol record; + role_list text; + drifted boolean; +BEGIN + IF NOT EXISTS (SELECT 1 FROM pg_catalog.pg_inherits WHERE inhrelid = target AND inhparent = parent) THEN + RAISE EXCEPTION '% is not a partition of %', target, parent; + END IF; + + IF NOT (SELECT relrowsecurity FROM pg_catalog.pg_class WHERE oid = target) THEN + EXECUTE format('ALTER TABLE %s ENABLE ROW LEVEL SECURITY', target); + END IF; + IF NOT (SELECT relforcerowsecurity FROM pg_catalog.pg_class WHERE oid = target) THEN + EXECUTE format('ALTER TABLE %s FORCE ROW LEVEL SECURITY', target); + END IF; + + -- Rewrite the partition's policies only when they differ from the parent's, + -- so a partition already in step takes no lock here. + SELECT EXISTS ( + (SELECT polname, polpermissive, polcmd, polroles, + pg_get_expr(polqual, polrelid), pg_get_expr(polwithcheck, polrelid) + FROM pg_catalog.pg_policy WHERE polrelid = parent + EXCEPT + SELECT polname, polpermissive, polcmd, polroles, + pg_get_expr(polqual, polrelid), pg_get_expr(polwithcheck, polrelid) + FROM pg_catalog.pg_policy WHERE polrelid = target) + UNION ALL + (SELECT polname, polpermissive, polcmd, polroles, + pg_get_expr(polqual, polrelid), pg_get_expr(polwithcheck, polrelid) + FROM pg_catalog.pg_policy WHERE polrelid = target + EXCEPT + SELECT polname, polpermissive, polcmd, polroles, + pg_get_expr(polqual, polrelid), pg_get_expr(polwithcheck, polrelid) + FROM pg_catalog.pg_policy WHERE polrelid = parent) + ) INTO drifted; + IF NOT drifted THEN + RETURN; + END IF; + + FOR pol IN SELECT polname FROM pg_catalog.pg_policy WHERE polrelid = target LOOP + EXECUTE format('DROP POLICY %I ON %s', pol.polname, target); + END LOOP; + FOR pol IN + SELECT polname, polpermissive, polcmd, polroles, + pg_get_expr(polqual, polrelid) AS qual, + pg_get_expr(polwithcheck, polrelid) AS with_check + FROM pg_catalog.pg_policy WHERE polrelid = parent ORDER BY polname + LOOP + -- Role 0 in polroles is PUBLIC. + SELECT string_agg(CASE WHEN grantee.role_oid = 0 THEN 'PUBLIC' ELSE quote_ident(r.rolname) END, ', ' ORDER BY grantee.ordinal) + INTO role_list + FROM unnest(pol.polroles) WITH ORDINALITY AS grantee(role_oid, ordinal) + LEFT JOIN pg_catalog.pg_roles r ON r.oid = grantee.role_oid; + EXECUTE format('CREATE POLICY %I ON %s AS %s FOR %s TO %s%s%s', + pol.polname, + target, + CASE WHEN pol.polpermissive THEN 'PERMISSIVE' ELSE 'RESTRICTIVE' END, + CASE pol.polcmd WHEN 'r' THEN 'SELECT' WHEN 'a' THEN 'INSERT' WHEN 'w' THEN 'UPDATE' WHEN 'd' THEN 'DELETE' ELSE 'ALL' END, + role_list, + CASE WHEN pol.qual IS NULL THEN '' ELSE format(' USING (%s)', pol.qual) END, + CASE WHEN pol.with_check IS NULL THEN '' ELSE format(' WITH CHECK (%s)', pol.with_check) END); + END LOOP; +END; +$$; + +CREATE OR REPLACE FUNCTION public.audit_events_ensure_partition(month date) RETURNS void + LANGUAGE plpgsql SECURITY DEFINER + SET search_path TO 'pg_catalog', 'public', 'pg_temp' + AS $$ +DECLARE + start_date DATE := date_trunc('month', month)::date; + end_date DATE := (date_trunc('month', month) + INTERVAL '1 month')::date; + part_name TEXT := 'audit_events_' || to_char(start_date, 'YYYY_MM'); +BEGIN + IF to_regclass('public.' || part_name) IS NULL THEN + EXECUTE format( + 'CREATE TABLE public.%I PARTITION OF public.audit_events FOR VALUES FROM (%L) TO (%L)', + part_name, start_date, end_date + ); + END IF; + PERFORM public.audit_events_secure_partition(to_regclass('public.' || quote_ident(part_name))); +END; +$$; + +CREATE OR REPLACE FUNCTION public.audit_events_secure_all_partitions() RETURNS void + LANGUAGE plpgsql SECURITY DEFINER + SET search_path TO 'pg_catalog', 'public', 'pg_temp' + AS $$ +DECLARE + part regclass; +BEGIN + FOR part IN + SELECT inhrelid::regclass FROM pg_catalog.pg_inherits + WHERE inhparent = 'public.audit_events'::regclass + ORDER BY inhrelid + LOOP + PERFORM public.audit_events_secure_partition(part); + END LOOP; +END; +$$; + +DROP FUNCTION public.audit_events_provision_partitions(integer); +DROP FUNCTION public.audit_events_create_partitions(date[], timestamp with time zone); +DROP FUNCTION public.audit_events_secure_partition_within(regclass, timestamp with time zone); +DROP FUNCTION public.audit_partitions_due(timestamp with time zone); +DROP FUNCTION public.audit_partition_lock(regclass, timestamp with time zone); +DROP FUNCTION public.audit_partition_lock_budget(timestamp with time zone); diff --git a/module/services/store/migrations/34_audit_retention_partition_bounds.up.sql b/module/services/store/migrations/34_audit_retention_partition_bounds.up.sql new file mode 100644 index 000000000..90445d418 --- /dev/null +++ b/module/services/store/migrations/34_audit_retention_partition_bounds.up.sql @@ -0,0 +1,602 @@ +-- Migration 34: audit retention and audit partition provisioning act on the +-- ranges PostgreSQL records, decide under lock, and wait ten seconds at most; +-- a retention window is a positive number of days. +-- +-- A RETENTION WINDOW IS A POSITIVE NUMBER OF DAYS. data_retention_policies says +-- how many days each resource's records are kept. A window of zero days, or +-- fewer, deleted every record older than the run, and retention now refuses one +-- rather than read it as anything else. The table therefore refuses one too, and +-- this migration refuses to apply while a policy holds one: which window was +-- meant is the operator's to say, and a migration that refuses is recoverable +-- where a deletion is not. +-- +-- RETENTION, audit_events_drop_partitions_before, runs on a schedule with nobody +-- watching, and a dropped partition cannot be recovered. What it may drop is held +-- by the rules below. +-- +-- The bounds are the partition's own. A partition's name spells a month, but an +-- earlier release cut its bounds at the midnights of the session zone that +-- created it: created from New York, audit_events_2026_08 ends at 2026-09-01 +-- 04:00 UTC, so a cutoff of 2026-09-01 00:00 UTC leaves it, and its last four +-- hours of events, alone. Each candidate's upper bound is read from +-- pg_get_expr(relpartbound) and parsed back, never derived from the name. +-- audit_events.created_at is timestamp with time zone, so the bound renders as an +-- instant, and the function renders and reads it under a DateStyle and TimeZone +-- it pins itself. ISO renders an instant with its numeric UTC offset, which reads +-- back as the same instant. Every other DateStyle renders it with the session +-- zone's abbreviation, and an abbreviation does not name one offset, so the +-- caller's settings would choose the instant the bound reads as. A partition +-- whose bounds are not a quoted FROM/TO pair -- DEFAULT, or a range open at +-- either end (MINVALUE, MAXVALUE) -- is never dropped: a cutoff rule cannot tell +-- what it holds. Only monthly-named partitions are candidates; the name selects +-- what retention may consider, and the bounds decide what it drops. +-- +-- The cutoff is one the policy allows, by this database's clock. The function +-- reads the audit_events policy and refuses, with invalid_parameter_value +-- (22023), a cutoff later than the start of its transaction less the policy's +-- window, a missing one, and any when there is no policy. A caller's clock +-- therefore cannot move the window: a cutoff computed on a clock running hours +-- ahead is refused, not honoured by dropping a partition still inside the +-- window. Days are of 24 hours, counted in UTC. +-- +-- The policy is the one in force when the drop commits. Once something is due +-- the function reads the policy again, with a row lock it holds until it +-- commits, and checks the cutoff against that: a change to the policy made +-- while the run waits for its locks waits in turn for the run to commit, and one +-- committed before is the policy the run keeps to. It does not wait for the +-- row: a change under way when it reads makes it refuse, with +-- lock_not_available (55P03), and the next run keeps to what the change leaves. +-- +-- A partition being detached is not retention's. One whose DETACH ... +-- CONCURRENTLY has begun and not finished is leaving audit_events, and is never +-- dropped. +-- +-- It decides under lock, from the catalog as it stands once the lock is held. +-- When something is due the function locks audit_events ACCESS EXCLUSIVE and +-- reads the catalog again: from then until the drop commits, no partition can +-- be created, attached, detached or given other bounds. That lock does not stop +-- a partition being renamed, and LOCK TABLE finds the table it locks by name: +-- were a partition renamed away while the function waited for it, and another +-- renamed to its name, a waiting LOCK TABLE would go on to lock that other one. +-- So the function locks each partition it chose by identity, under the name it +-- has at that moment and without waiting in LOCK TABLE, refusing unless the +-- lock it holds is on that very partition. Holding them all, it reads the +-- catalog a third time. It drops them only if exactly those are still due, and +-- otherwise drops nothing, with object_not_in_prerequisite_state (55000). Each +-- read sees what committed while the function waited only if it takes a +-- snapshot of its own, which a statement does at READ COMMITTED. At REPEATABLE +-- READ or SERIALIZABLE every statement reads the snapshot the transaction took +-- first, before the lock, in which a partition detached meanwhile is still +-- attached and due. The function therefore runs only at READ COMMITTED, and +-- refuses any other level with invalid_transaction_state (25000); the store's +-- retention call opens its transaction at READ COMMITTED, whatever the database +-- default. The lock order is the one inserters use (parent, then partition), so +-- it cannot deadlock with them, and a writer that arrives meanwhile waits for +-- the drop to commit. +-- +-- It waits ten seconds at most, in all. lock_timeout bounds one wait, and the +-- function may wait more than once: for the policy's table, for audit_events, +-- then for each partition it drops. So it takes the policy's table and +-- audit_events each in a statement of its own, after setting lock_timeout to +-- what remains of ten seconds from its start, and a partition with +-- LOCK TABLE ... NOWAIT, tried again until those ten seconds are spent. Each +-- DROP runs under what remains too, which bounds its wait for the DEFAULT +-- partition, if there is one: dropping a range partition locks it as well. It +-- refuses with lock_not_available (55P03) once nothing remains. A run that +-- cannot have its locks in time drops nothing, and the next scheduled run tries +-- again, instead of holding audit writes behind it for as long as a reader +-- runs. When nothing is due the function takes no lock at all: a partition +-- comes due about once a month, and locking the table on every run would stall +-- audit writes behind any long reader for a drop that never happens. It reads +-- bounds without opening the partitions (pg_get_expr with no relation, which a +-- bound, holding no column reference, does not need), so that read waits for +-- nothing either. +-- +-- PROVISIONING, audit_events_provision_partitions, which the store calls at +-- startup and on each retention tick, creates the months from the previous one +-- to months_ahead ahead, by this database's clock, and brings every partition's +-- row-level security in step with the parent's, all under one ten-second +-- budget. audit_events_ensure_partition and audit_events_secure_all_partitions, +-- which migrations and operators call, keep their signatures and get a budget of +-- their own. Creating a partition locks audit_events ACCESS EXCLUSIVE, the lock +-- retention takes, and it is taken the same way: only when a month lacks its +-- partition, in a statement of its own, within the budget, deciding again under +-- the lock what to create. Bringing a partition's row security in step locks +-- the partition only when it is out of step, by identity as retention does, and +-- decides again under that lock what to change. Bringing every partition in +-- step reads the list of partitions holding audit_events ACCESS SHARE, so none +-- it lists can be dropped before it reaches it. +-- +-- A new partition's bounds are UTC midnights, whatever the zone of the session +-- that creates it, so its range no longer depends on who provisioned it. A +-- partition an earlier release cut at another zone's midnight still borders it, +-- and a range starting at UTC midnight would overlap one cut west of UTC, which +-- PostgreSQL refuses, or leave a gap after one cut east of it, where an insert +-- finds no partition. So a new partition starts where its predecessor ends, and +-- ends where its successor starts, when that neighbour's bound lies within a day +-- of the UTC midnight; every other partition stays out of its range. +-- +-- The signatures, return values, owners and grants of the existing functions +-- are unchanged: CREATE OR REPLACE keeps the owner and the ACL. Their +-- search_path lists pg_catalog first and pg_temp last, like every other definer +-- function here. + +DO $$ +DECLARE + invalid text; +BEGIN + SELECT string_agg(format('%s (%s days)', resource_type, retention_days), ', ' ORDER BY resource_type) + INTO invalid + FROM public.data_retention_policies + WHERE retention_days <= 0; + IF invalid IS NOT NULL THEN + RAISE EXCEPTION USING + MESSAGE = format('data_retention_policies keeps records for a number of days that is not positive: %s', invalid), + DETAIL = 'A window of zero days or fewer deleted every record older than the run, and retention now refuses one.', + HINT = 'Set each to the number of days its records are kept, or delete the policy to keep them indefinitely, then apply this migration again.', + ERRCODE = 'check_violation'; + END IF; +END +$$; + +ALTER TABLE public.data_retention_policies + ADD CONSTRAINT data_retention_policies_retention_days_positive CHECK (retention_days > 0); + +-- audit_partition_lock_budget sets lock_timeout, until the calling maintenance +-- function returns, to what remains before deadline, and refuses once nothing +-- does. Every audit partition function calls it before each statement that may +-- wait for a lock, and each such statement waits for one lock at most, so the +-- waits of one call add up to its budget at most. A partition is locked by +-- audit_partition_lock, which never waits in LOCK TABLE and stops trying at the +-- same deadline. Owned by the migration principal and called only from the +-- functions below. +CREATE FUNCTION public.audit_partition_lock_budget(deadline timestamp with time zone) RETURNS void + LANGUAGE plpgsql + SET search_path TO 'pg_catalog', 'public', 'pg_temp' + AS $$ +DECLARE + remaining_ms CONSTANT bigint := floor(extract(epoch FROM deadline - clock_timestamp()) * 1000); +BEGIN + IF remaining_ms < 1 THEN + RAISE EXCEPTION 'audit partition maintenance has waited for its locks as long as it may' + USING ERRCODE = 'lock_not_available'; + END IF; + PERFORM set_config('lock_timeout', remaining_ms::text, true); +END; +$$; + +REVOKE ALL ON FUNCTION public.audit_partition_lock_budget(timestamp with time zone) FROM PUBLIC; + +-- audit_partition_lock(target, deadline) locks target ACCESS EXCLUSIVE before +-- deadline, and refuses unless the lock it then holds is on target itself. +-- LOCK TABLE finds the table it locks by name, and a name can pass to another +-- table while a lock is awaited: were target renamed away and another table +-- renamed to its name meanwhile, a waiting LOCK TABLE would go on to that other +-- table and wait for it too, with the same lock_timeout, past the deadline. So +-- this never waits in LOCK TABLE. It tries with NOWAIT, under the name target +-- has at that moment, and tries again every 50 milliseconds until deadline, so a +-- partition renamed meanwhile is still the one it locks. Trying again gives up +-- the place a waiting lock keeps in the queue: retention tries holding +-- audit_events ACCESS EXCLUSIVE, which every query through the parent waits for, +-- so only a session using the partition directly can hold it off. Once target +-- is held it cannot be renamed, so each statement after this one that names it +-- reaches it. Owned by the migration principal and called only from the +-- functions below. +CREATE FUNCTION public.audit_partition_lock(target regclass, deadline timestamp with time zone) RETURNS void + LANGUAGE plpgsql + SET search_path TO 'pg_catalog', 'public', 'pg_temp' + AS $$ +DECLARE + named text; +BEGIN + LOOP + SELECT format('%I.%I', n.nspname, c.relname) INTO named + FROM pg_catalog.pg_class c + JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace + WHERE c.oid = target; + EXIT WHEN named IS NULL; + BEGIN + EXECUTE format('LOCK TABLE %s IN ACCESS EXCLUSIVE MODE NOWAIT', named); + EXIT; + EXCEPTION WHEN lock_not_available OR undefined_table THEN + -- Held by another session, or renamed since it was looked up. + NULL; + END; + IF clock_timestamp() >= deadline THEN + RAISE EXCEPTION 'audit partition maintenance has waited for its locks as long as it may' + USING ERRCODE = 'lock_not_available'; + END IF; + PERFORM pg_sleep(least(0.05, extract(epoch FROM deadline - clock_timestamp()))); + END LOOP; + IF NOT EXISTS ( + SELECT 1 FROM pg_catalog.pg_locks l + WHERE l.locktype = 'relation' + AND l.database = (SELECT d.oid FROM pg_catalog.pg_database d WHERE d.datname = current_database()) + AND l.relation = target + AND l.pid = pg_backend_pid() + AND l.mode = 'AccessExclusiveLock' + AND l.granted + ) THEN + RAISE EXCEPTION 'audit partition % was dropped, or its name passed to another table, while maintenance waited for its lock', coalesce(named, target::text) + USING ERRCODE = 'object_not_in_prerequisite_state', + HINT = 'Nothing was changed. The next run decides again from the catalog as it then stands.'; + END IF; +END; +$$; + +REVOKE ALL ON FUNCTION public.audit_partition_lock(regclass, timestamp with time zone) FROM PUBLIC; + +-- audit_partitions_due(cutoff) is what retention drops: the partitions of +-- audit_events with a monthly name, not being detached, whose recorded range +-- ends at or before cutoff, in name order, or NULL when there are none. It reads +-- their bounds without opening them, so it waits for no lock. Owned by the +-- migration principal and called only from audit_events_drop_partitions_before. +CREATE FUNCTION public.audit_partitions_due(cutoff timestamp with time zone) RETURNS regclass[] + LANGUAGE sql + SET search_path TO 'pg_catalog', 'public', 'pg_temp' + SET datestyle TO 'ISO, MDY' + SET timezone TO 'UTC' + AS $$ + SELECT array_agg(candidate.part ORDER BY candidate.name) + FROM ( + SELECT c.oid::regclass AS part, + c.relname AS name, + -- NULL when the bounds are not a quoted FROM/TO pair, which + -- the comparison below then leaves out. + (regexp_match(pg_get_expr(c.relpartbound, 0), + '^FOR VALUES FROM \(''([^'']+)''\) TO \(''([^'']+)''\)$'))[2]::timestamp with time zone AS upper_bound + FROM pg_inherits i + JOIN pg_class c ON c.oid = i.inhrelid + WHERE i.inhparent = 'public.audit_events'::regclass + AND NOT i.inhdetachpending + AND c.relkind = 'r' + AND c.relnamespace = 'public'::regnamespace + AND c.relname ~ '^audit_events_[0-9]{4}_[0-9]{2}$' + ) candidate + WHERE candidate.upper_bound <= cutoff +$$; + +REVOKE ALL ON FUNCTION public.audit_partitions_due(timestamp with time zone) FROM PUBLIC; + +CREATE OR REPLACE FUNCTION public.audit_events_drop_partitions_before(cutoff timestamp with time zone) RETURNS integer + LANGUAGE plpgsql SECURITY DEFINER + SET search_path TO 'pg_catalog', 'public', 'pg_temp' + SET lock_timeout TO '10s' + SET datestyle TO 'ISO, MDY' + SET timezone TO 'UTC' + AS $$ +DECLARE + deadline CONSTANT timestamp with time zone := clock_timestamp() + interval '10 seconds'; + window_days integer; + latest timestamp with time zone; + due regclass[]; + part regclass; + dropped integer := 0; +BEGIN + FOR pass IN 1..2 LOOP + -- Pass 1 reads the policy with no lock, to refuse a cutoff it does not + -- allow before taking any, and returns when nothing is due. Pass 2, + -- once something is, reads it again with a row lock held until the + -- drop commits, so the cutoff is held to the policy in force then. + IF pass = 1 THEN + SELECT p.retention_days INTO window_days + FROM public.data_retention_policies p + WHERE p.resource_type = 'audit_events'; + ELSE + PERFORM public.audit_partition_lock_budget(deadline); + SELECT p.retention_days INTO window_days + FROM public.data_retention_policies p + WHERE p.resource_type = 'audit_events' + FOR SHARE NOWAIT; + END IF; + IF window_days IS NULL THEN + RAISE EXCEPTION 'audit_events has no retention policy, so no partition is due' + USING ERRCODE = 'invalid_parameter_value'; + END IF; + -- A window reaching back past the earliest instant a timestamp holds, + -- 24 November 4714 BC, retains every partition. + latest := CASE WHEN window_days < now()::date - '4714-11-24 BC'::date + THEN now() - make_interval(days => window_days) + ELSE '-infinity'::timestamp with time zone END; + IF cutoff IS NULL THEN + RAISE EXCEPTION 'audit retention needs a cutoff' + USING ERRCODE = 'invalid_parameter_value'; + END IF; + IF cutoff > latest THEN + RAISE EXCEPTION 'audit retention cutoff % is later than the audit_events policy of % days allows', cutoff, window_days + USING ERRCODE = 'invalid_parameter_value', + DETAIL = format('The latest cutoff the policy allows is %s.', latest); + END IF; + IF pass = 1 THEN + -- PostgreSQL runs READ UNCOMMITTED as READ COMMITTED. + IF current_setting('transaction_isolation') NOT IN ('read committed', 'read uncommitted') THEN + RAISE EXCEPTION 'audit retention runs only at READ COMMITTED, not %', upper(current_setting('transaction_isolation')) + USING ERRCODE = 'invalid_transaction_state', + HINT = 'Run it in a transaction begun with ISOLATION LEVEL READ COMMITTED.'; + END IF; + IF public.audit_partitions_due(cutoff) IS NULL THEN + RETURN 0; + END IF; + END IF; + END LOOP; + + -- With audit_events held, no partition can be created, attached, detached + -- or given other bounds until the drop commits. + PERFORM public.audit_partition_lock_budget(deadline); + LOCK TABLE ONLY public.audit_events IN ACCESS EXCLUSIVE MODE; + due := public.audit_partitions_due(cutoff); + IF due IS NULL THEN + RETURN 0; + END IF; + + -- A partition can still be renamed until it is held itself. Each is locked + -- by identity; with all of them held, the choice is made once more, and + -- must come out the same. + FOREACH part IN ARRAY due LOOP + PERFORM public.audit_partition_lock(part, deadline); + END LOOP; + IF public.audit_partitions_due(cutoff) IS DISTINCT FROM due THEN + RAISE EXCEPTION 'the audit partitions due changed while retention waited for their locks, so it dropped none' + USING ERRCODE = 'object_not_in_prerequisite_state', + HINT = 'The next run decides again from the catalog as it then stands.'; + END IF; + FOREACH part IN ARRAY due LOOP + -- Dropping a range partition also locks the DEFAULT partition, if + -- there is one, by identity, since its constraint changes: the first + -- DROP waits for it no longer than what remains. + PERFORM public.audit_partition_lock_budget(deadline); + EXECUTE format('DROP TABLE %s', part); + dropped := dropped + 1; + END LOOP; + RETURN dropped; +END; +$$; + +-- audit_events_secure_partition_within(target, deadline) brings one partition's +-- row security in step with the parent's, as migration 11's +-- audit_events_secure_partition did, and waits for its locks only until +-- deadline. A policy's expressions render only with their table open, which +-- waits for a session holding the table ACCESS EXCLUSIVE, so the parent's and +-- the partition's are read in statements of their own. A partition already in +-- step takes no lock beyond those reads; one out of step is locked by identity +-- and read again under that lock, which decides what to change. +CREATE FUNCTION public.audit_events_secure_partition_within(target regclass, deadline timestamp with time zone) RETURNS void + LANGUAGE plpgsql + SET search_path TO 'pg_catalog', 'public', 'pg_temp' + AS $$ +DECLARE + parent CONSTANT regclass := 'public.audit_events'::regclass; + pol record; + role_list text; + enable_rls boolean; + force_rls boolean; + wanted text[]; + carried text[]; +BEGIN + FOR pass IN 1..2 LOOP + -- Pass 1 reads whether the partition is in step without locking it. + -- Pass 2 holds it, and reads again what to change. + IF pass = 2 THEN + PERFORM public.audit_partition_lock(target, deadline); + END IF; + IF NOT EXISTS (SELECT 1 FROM pg_catalog.pg_inherits WHERE inhrelid = target AND inhparent = parent) THEN + RAISE EXCEPTION '% is not a partition of %', target, parent; + END IF; + SELECT NOT c.relrowsecurity, NOT c.relforcerowsecurity INTO enable_rls, force_rls + FROM pg_catalog.pg_class c WHERE c.oid = target; + + PERFORM public.audit_partition_lock_budget(deadline); + SELECT array_agg(concat_ws(chr(31), polname, polpermissive, polcmd, polroles::text, + coalesce(pg_get_expr(polqual, polrelid), ''), coalesce(pg_get_expr(polwithcheck, polrelid), '')) + ORDER BY polname) + INTO wanted FROM pg_catalog.pg_policy WHERE polrelid = parent; + PERFORM public.audit_partition_lock_budget(deadline); + SELECT array_agg(concat_ws(chr(31), polname, polpermissive, polcmd, polroles::text, + coalesce(pg_get_expr(polqual, polrelid), ''), coalesce(pg_get_expr(polwithcheck, polrelid), '')) + ORDER BY polname) + INTO carried FROM pg_catalog.pg_policy WHERE polrelid = target; + + IF NOT enable_rls AND NOT force_rls AND wanted IS NOT DISTINCT FROM carried THEN + RETURN; + END IF; + END LOOP; + + IF enable_rls THEN + EXECUTE format('ALTER TABLE %s ENABLE ROW LEVEL SECURITY', target); + END IF; + IF force_rls THEN + EXECUTE format('ALTER TABLE %s FORCE ROW LEVEL SECURITY', target); + END IF; + IF wanted IS NOT DISTINCT FROM carried THEN + RETURN; + END IF; + + FOR pol IN SELECT polname FROM pg_catalog.pg_policy WHERE polrelid = target LOOP + EXECUTE format('DROP POLICY %I ON %s', pol.polname, target); + END LOOP; + FOR pol IN + SELECT polname, polpermissive, polcmd, polroles, + pg_get_expr(polqual, polrelid) AS qual, + pg_get_expr(polwithcheck, polrelid) AS with_check + FROM pg_catalog.pg_policy WHERE polrelid = parent ORDER BY polname + LOOP + -- Role 0 in polroles is PUBLIC. + SELECT string_agg(CASE WHEN grantee.role_oid = 0 THEN 'PUBLIC' ELSE quote_ident(r.rolname) END, ', ' ORDER BY grantee.ordinal) + INTO role_list + FROM unnest(pol.polroles) WITH ORDINALITY AS grantee(role_oid, ordinal) + LEFT JOIN pg_catalog.pg_roles r ON r.oid = grantee.role_oid; + EXECUTE format('CREATE POLICY %I ON %s AS %s FOR %s TO %s%s%s', + pol.polname, + target, + CASE WHEN pol.polpermissive THEN 'PERMISSIVE' ELSE 'RESTRICTIVE' END, + CASE pol.polcmd WHEN 'r' THEN 'SELECT' WHEN 'a' THEN 'INSERT' WHEN 'w' THEN 'UPDATE' WHEN 'd' THEN 'DELETE' ELSE 'ALL' END, + role_list, + CASE WHEN pol.qual IS NULL THEN '' ELSE format(' USING (%s)', pol.qual) END, + CASE WHEN pol.with_check IS NULL THEN '' ELSE format(' WITH CHECK (%s)', pol.with_check) END); + END LOOP; +END; +$$; + +REVOKE ALL ON FUNCTION public.audit_events_secure_partition_within(regclass, timestamp with time zone) FROM PUBLIC; + +-- The one-argument form, which migrations 11 and 13 called, keeps its signature +-- and gets a budget of its own. +CREATE OR REPLACE FUNCTION public.audit_events_secure_partition(target regclass) RETURNS void + LANGUAGE plpgsql + SET search_path TO 'pg_catalog', 'public', 'pg_temp' + SET lock_timeout TO '10s' + AS $$ +BEGIN + PERFORM public.audit_events_secure_partition_within(target, clock_timestamp() + interval '10 seconds'); +END; +$$; + +-- audit_events_create_partitions creates the partition of each month in months +-- that has none, with UTC bounds that meet its neighbours, and secures each one +-- in the transaction that creates it, waiting for its locks only until +-- deadline. Owned by the migration principal and called only from the +-- provisioning functions below. +CREATE FUNCTION public.audit_events_create_partitions(months date[], deadline timestamp with time zone) RETURNS void + LANGUAGE plpgsql + SET search_path TO 'pg_catalog', 'public', 'pg_temp' + SET datestyle TO 'ISO, MDY' + SET timezone TO 'UTC' + AS $$ +DECLARE + parent CONSTANT regclass := 'public.audit_events'::regclass; + bounds CONSTANT text := '^FOR VALUES FROM \(''([^'']+)''\) TO \(''([^'']+)''\)$'; + month date; + part_name text; + start_utc timestamp with time zone; + end_utc timestamp with time zone; + lo timestamp with time zone; + hi timestamp with time zone; +BEGIN + IF NOT EXISTS ( + SELECT 1 FROM unnest(months) AS m + WHERE to_regclass('public.' || quote_ident('audit_events_' || to_char(m, 'YYYY_MM'))) IS NULL + ) THEN + RETURN; + END IF; + + -- Under the lock no partition can be created, attached or detached, so what + -- is read next stays true until the transaction ends. + PERFORM public.audit_partition_lock_budget(deadline); + LOCK TABLE ONLY public.audit_events IN ACCESS EXCLUSIVE MODE; + + FOREACH month IN ARRAY months LOOP + part_name := 'audit_events_' || to_char(month, 'YYYY_MM'); + CONTINUE WHEN to_regclass('public.' || quote_ident(part_name)) IS NOT NULL; + start_utc := date_trunc('month', month::timestamp) AT TIME ZONE 'UTC'; + end_utc := (date_trunc('month', month::timestamp) + interval '1 month') AT TIME ZONE 'UTC'; + + WITH attached AS ( + SELECT range[1]::timestamp with time zone AS lower_bound, + range[2]::timestamp with time zone AS upper_bound + FROM pg_catalog.pg_inherits i + JOIN pg_catalog.pg_class c ON c.oid = i.inhrelid + CROSS JOIN LATERAL regexp_match(pg_catalog.pg_get_expr(c.relpartbound, 0), bounds) AS range + WHERE i.inhparent = parent + ) + SELECT coalesce((SELECT max(upper_bound) FROM attached + WHERE lower_bound < start_utc + AND upper_bound > start_utc - interval '1 day' + AND upper_bound < start_utc + interval '1 day'), start_utc), + coalesce((SELECT min(lower_bound) FROM attached + WHERE upper_bound > end_utc + AND lower_bound > end_utc - interval '1 day' + AND lower_bound < end_utc + interval '1 day'), end_utc) + INTO lo, hi; + -- Its neighbours already hold the whole month. + CONTINUE WHEN lo >= hi; + + EXECUTE format('CREATE TABLE public.%I PARTITION OF public.audit_events FOR VALUES FROM (%L) TO (%L)', + part_name, lo, hi); + PERFORM public.audit_events_secure_partition_within(to_regclass('public.' || quote_ident(part_name)), deadline); + END LOOP; +END; +$$; + +REVOKE ALL ON FUNCTION public.audit_events_create_partitions(date[], timestamp with time zone) FROM PUBLIC; + +-- A partition is secured in the same transaction that creates it, and an +-- existing one is brought back in step whenever it is ensured, so none is ever +-- readable by name without the parent's policies. +CREATE OR REPLACE FUNCTION public.audit_events_ensure_partition(month date) RETURNS void + LANGUAGE plpgsql SECURITY DEFINER + SET search_path TO 'pg_catalog', 'public', 'pg_temp' + SET lock_timeout TO '10s' + AS $$ +DECLARE + deadline CONSTANT timestamp with time zone := clock_timestamp() + interval '10 seconds'; + part regclass; +BEGIN + PERFORM public.audit_events_create_partitions(ARRAY[month], deadline); + part := to_regclass('public.' || quote_ident('audit_events_' || to_char(month, 'YYYY_MM'))); + IF part IS NOT NULL THEN + PERFORM public.audit_events_secure_partition_within(part, deadline); + END IF; +END; +$$; + +CREATE OR REPLACE FUNCTION public.audit_events_secure_all_partitions() RETURNS void + LANGUAGE plpgsql SECURITY DEFINER + SET search_path TO 'pg_catalog', 'public', 'pg_temp' + SET lock_timeout TO '10s' + AS $$ +DECLARE + deadline CONSTANT timestamp with time zone := clock_timestamp() + interval '10 seconds'; + part regclass; +BEGIN + -- Holding audit_events, no partition listed below can be dropped or + -- detached before it is reached. + PERFORM public.audit_partition_lock_budget(deadline); + LOCK TABLE ONLY public.audit_events IN ACCESS SHARE MODE; + FOR part IN + SELECT inhrelid::regclass FROM pg_catalog.pg_inherits + WHERE inhparent = 'public.audit_events'::regclass + ORDER BY inhrelid + LOOP + PERFORM public.audit_events_secure_partition_within(part, deadline); + END LOOP; +END; +$$; + +-- audit_events_provision_partitions is the store's one provisioning call: the +-- months from the previous one to months_ahead ahead of this one, by this +-- database's clock in UTC, then every partition's row security, all within ten +-- seconds of waiting. Execute is the control plane's alone, like the functions +-- it replaces in that call. +CREATE FUNCTION public.audit_events_provision_partitions(months_ahead integer) RETURNS void + LANGUAGE plpgsql SECURITY DEFINER + SET search_path TO 'pg_catalog', 'public', 'pg_temp' + SET lock_timeout TO '10s' + AS $$ +DECLARE + deadline CONSTANT timestamp with time zone := clock_timestamp() + interval '10 seconds'; + this_month CONSTANT date := date_trunc('month', now() AT TIME ZONE 'UTC')::date; + part regclass; +BEGIN + IF months_ahead IS NULL OR months_ahead < 0 OR months_ahead > 24 THEN + RAISE EXCEPTION 'audit partitions are provisioned from 0 to 24 months ahead, not %', coalesce(months_ahead::text, 'NULL') + USING ERRCODE = 'invalid_parameter_value'; + END IF; + PERFORM public.audit_events_create_partitions( + ARRAY(SELECT (this_month + make_interval(months => m))::date FROM generate_series(-1, months_ahead) AS m ORDER BY m), + deadline); + -- Holding audit_events, no partition listed below can be dropped or + -- detached before it is reached. + PERFORM public.audit_partition_lock_budget(deadline); + LOCK TABLE ONLY public.audit_events IN ACCESS SHARE MODE; + FOR part IN + SELECT inhrelid::regclass FROM pg_catalog.pg_inherits + WHERE inhparent = 'public.audit_events'::regclass + ORDER BY inhrelid + LOOP + PERFORM public.audit_events_secure_partition_within(part, deadline); + END LOOP; +END; +$$; + +REVOKE ALL ON FUNCTION public.audit_events_provision_partitions(integer) FROM PUBLIC; +GRANT EXECUTE ON FUNCTION public.audit_events_provision_partitions(integer) TO app_control_plane;