Skip to content

fix(album-metadata-backfill): wrap verifyComplete in tx + SET LOCAL (BS#1022)#1024

Merged
jakebromberg merged 1 commit into
mainfrom
fix-1022-verify-tx-statement-timeout
May 23, 2026
Merged

fix(album-metadata-backfill): wrap verifyComplete in tx + SET LOCAL (BS#1022)#1024
jakebromberg merged 1 commit into
mainfrom
fix-1022-verify-tx-statement-timeout

Conversation

@jakebromberg

Copy link
Copy Markdown
Member

Summary

The dual-count fix shipped in #1020 didn't fully resolve the verify-step timeout reported in #1019. On the 2026-05-22 prod re-run, the new count(DISTINCT album_id) WHERE metadata_attempt_at IS NOT NULL over ~2.6M flowsheet rows still tripped the backend's 5 s default statement_timeout — the partial index from #660 (idx_flowsheet_metadata_drain) covers the IS NULL partition only, so the verify walks the un-indexed opposite partition.

This PR wraps verifyComplete in db.transaction + SET LOCAL statement_timeout so the per-tx timeout actually scopes (postgres-js auto-commits per execute otherwise). Both statements run on the closure-bound tx handle; the timeout is read from ALBUM_METADATA_BACKFILL_VERIFY_TIMEOUT_MS (default 120000), following the operational-knob pattern of BS#995 / BS#1017 on this job family.

Closes #1022.

Background

Fix shape

const verifyComplete = async (): Promise<void> => {
  const timeoutMs = parseVerifyTimeoutMs(process.env[VERIFY_TIMEOUT_MS_ENV]);

  await db.transaction(async (tx) => {
    await tx.execute(sql.raw(`SET LOCAL statement_timeout = '${timeoutMs}ms'`));
    const result = await tx.execute(sql`
      SELECT
        (SELECT count(*)::int FROM "wxyc_schema"."album_metadata") AS actual,
        (SELECT count(DISTINCT "album_id")::int FROM "wxyc_schema"."flowsheet"
          WHERE "album_id" IS NOT NULL
            AND "metadata_attempt_at" IS NOT NULL) AS expected
    `);
    // existing actual >= expected logic preserved
  });
};

The transaction wrapper sunsets naturally with D4 (#900) when the inline columns drop and the verify shape changes; the doc comment calls this out so a future "this wrapper looks unnecessary" cleanup doesn't regress the fix.

Env knob

ALBUM_METADATA_BACKFILL_VERIFY_TIMEOUT_MS (default 120000 / 120 s) is documented in docs/env-vars.md alongside ALBUM_PLAYS_REFRESH_TIMEOUT_MS (the closest precedent — same per-statement-timeout pattern on a dedicated path). Non-numeric or non-positive values raise at job startup rather than silently defaulting.

Test plan

Unit-level (in tests/unit/jobs/album-metadata-backfill/job.test.ts):

  • tx-binding pin: per-test fake-tx with its own execute spy; assert both SET LOCAL and the dual-count SELECT go through tx.execute and db.execute is never called inside the transaction body. The real failure mode the prior PR missed wasn't call-ordering — it was the two statements landing on different pooled connections.
  • SET LOCAL is the first transaction statement, dual-count SELECT the second.
  • Default 120000ms when env is unset.
  • Custom value when env is set (e.g. 90000'90000ms').
  • Throws on non-numeric env.
  • Throws on non-positive env (0).
  • actual >= expected invariant preserved (passes on =, passes on >).
  • Throws with both counts + the idempotent re-run hint when short.
  • Dual-count comparison preserved (anti-asserts LEFT JOIN).

Local CI gates run against the affected workspace:

  • npm run test:unit -- tests/unit/jobs/album-metadata-backfill/job.test.ts — 22/22 green
  • npm run test:unit -- --testPathPatterns='album-metadata-backfill|albumMetadataProjection|flowsheet.getEntriesByRange' — 29/29 green
  • npm run test:unit -- --testPathPatterns='library-identity-consumer' — 52/52 green (the other db.transaction consumer; no shared-mock changes made)
  • npx eslint jobs/album-metadata-backfill tests/unit/jobs/album-metadata-backfill — 0 errors, 2 pre-existing warnings
  • npx prettier --check jobs/album-metadata-backfill tests/unit/jobs/album-metadata-backfill docs/env-vars.md — clean
  • npx tsc --noEmit -p jobs/album-metadata-backfill/tsconfig.json — clean

The (optional) integration test asserting current_setting('statement_timeout') mid-transaction was discussed in the review and deferred — happy to add as a follow-up if you want belt-and-suspenders. The unit tests pin the load-bearing behavior (tx-binding + statement ordering + env wiring + invariant).

Prod re-run

Held until BS#1011's drain finishes. Expected outcome once unblocked: 0 new INSERTs (idempotent), ANALYZE re-runs, dual-count verify logs Verification passed: album_metadata=7101 >= expected=7101 and exits 0.

Alternative considered

Adding a partial index on flowsheet(album_id) WHERE metadata_attempt_at IS NOT NULL would also unblock the verify, but the index has no other reader and sunsets with D4. The transaction wrapper is the proportionally-smaller fix with a natural deletion path.

…BS#1022)

The dual-count comparison shipped in PR #1020 traded one un-indexed scan for
another: count(DISTINCT album_id) WHERE metadata_attempt_at IS NOT NULL walks
the opposite partition from the drain partial index (#660), still ~2.6M rows
on a heap scan, still tripped the backend's 5s default statement_timeout on
the 2026-05-22 prod re-run.

Wrap verifyComplete in db.transaction so SET LOCAL statement_timeout actually
scopes (postgres-js auto-commits per execute otherwise). Both SET LOCAL and
the dual-count SELECT execute through the closure-bound tx handle. Timeout is
read from ALBUM_METADATA_BACKFILL_VERIFY_TIMEOUT_MS (default 120000ms),
following the operational-knob pattern from BS#995 / BS#1017 on the same job
family.

Unit tests pin tx-binding by installing a per-call fake-tx with its own
execute spy and asserting db.execute is never called inside the transaction
body — the real failure mode the previous PR missed wasn't call-ordering, it
was the two statements landing on different pooled connections.

Closes #1022.
@jakebromberg jakebromberg merged commit b05b002 into main May 23, 2026
5 checks passed
@jakebromberg jakebromberg deleted the fix-1022-verify-tx-statement-timeout branch May 23, 2026 15:18
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Development

Successfully merging this pull request may close these issues.

album-metadata-backfill verifyComplete still times out at 5s after PR #1020

1 participant