diff --git a/CHANGELOG.md b/CHANGELOG.md index a81f57b7..69f9df64 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,33 @@ # Changelog +## Unreleased + +### Added + +- `pipeline.drain_deadline_seconds` bounds the whole shutdown after SIGTERM. + The final batch, the managers' final poll and the state syncs share one + deadline, 30 seconds by default. When it passes the process exits 15 with + `system.lifecycle.drain_incomplete`. Nothing unwritten was committed, and + the next start replays it. +- `/healthz` reports `starting`, `healthy`, `degraded` or `failed`, with a + `reason`. `degraded` means a sink's retry ladder is running, or the + pipeline recorded an error inside the last flush interval. `failed` answers + 503 and the other three answer 200. The previous `ok` and `stuck` bodies + are now `healthy` and `failed`, and their HTTP codes did not change. +- `sqlflow validate` warns when a sink's `retry.deadline_seconds` is longer + than the drain deadline. +- `/stats` carries `errors` and `last_error` under `progress`. + +### Fixed + +- A SIGTERM that arrived while a batch was being flushed aborted the flush, + and the process exited with the sink's error instead of draining. The + batch now finishes inside the drain deadline. +- A cancel during a table manager's regular poll skipped its final poll, and + a final poll that failed was logged while the process exited 0. The final + poll always runs, and its failure is the exit code. +- One failed flush counted as three errors. + ## v1.0.0 — sqlflow, the Go engine SQLFlow now ships a second engine: **sqlflow**, a Go rewrite of the Python diff --git a/docs/coverage/features.yml b/docs/coverage/features.yml index 32d69af7..6f486a19 100644 --- a/docs/coverage/features.yml +++ b/docs/coverage/features.yml @@ -120,6 +120,10 @@ features: description: The process exit status carries the error code a supervisor reads. requires: [unit, release] + - id: lifecycle.health + description: /healthz reports starting, healthy, degraded or failed, with a reason. + requires: [unit, release] + # --- The batch loop ----------------------------------------------------- - id: core.consume_loop description: Accumulates a batch, flushes it, and commits in that order. diff --git a/docs/coverage/invariants.yml b/docs/coverage/invariants.yml index c810021a..2dbdd8db 100644 --- a/docs/coverage/invariants.yml +++ b/docs/coverage/invariants.yml @@ -353,10 +353,14 @@ invariants: family: lifecycle class: liveness applies_to: pipeline - claim: The drain finishes or fails inside its deadline. + claim: > + A drain finishes or fails inside pipeline.drain_deadline_seconds. A sink + that never answers cannot hold the process past it: the loop returns + system.lifecycle.drain_incomplete, commits nothing for the batch it + could not write, and the next start replays it. verified_by: harness requires: [] - tracked_by: "#161" + enforced: true - id: lifecycle.close.idempotent family: lifecycle @@ -452,3 +456,15 @@ invariants: requires: [] enforced: true violated_once: ["#267"] + + - id: manager.drain.bounded + family: lifecycle + class: liveness + applies_to: manager + claim: > + The final poll after a cancel finishes or fails inside the drain + deadline. A sink that never answers cannot hold the process past it, + and every closed window it did not deliver stays in the state table. + verified_by: harness + requires: [] + enforced: true diff --git a/docs/coverage/matrix.md b/docs/coverage/matrix.md index 17d335d8..878c51f9 100644 --- a/docs/coverage/matrix.md +++ b/docs/coverage/matrix.md @@ -41,6 +41,7 @@ added, and this page changes only when a status does. | `state.corruption` | A damaged state file fails the start rather than silently resetting. | ✅ | — | ✅ | | `lifecycle.drain` | SIGTERM writes the buffered batch before exiting. | ✅ | — | ✅ | | `lifecycle.exit_codes` | The process exit status carries the error code a supervisor reads. | ✅ | — | ✅ | +| `lifecycle.health` | /healthz reports starting, healthy, degraded or failed, with a reason. | ✅ | — | ✅ | | `core.consume_loop` | Accumulates a batch, flushes it, and commits in that order. | ✅ | — | — | | `error.taxonomy` | Every failure carries a class.domain.reason code. | ✅ | — | — | | `error.raise` | Policy RAISE stops the pipeline on a bad record. | ✅ | — | — | @@ -60,7 +61,7 @@ added, and this page changes only when a status does. | `tooling.conformance` | The harness proves the declared invariants for any integration. | ✅ | — | — | | `tooling.coverage` | Tests attribute to features and invariants, and the registries match the code. | ✅ | — | — | -**37 features declared. 37 have at least one passing test attributed at every level they require, so 0 gap(s).** +**38 features declared. 38 have at least one passing test attributed at every level they require, so 0 gap(s).** That sentence counts attribution, not proof. A feature is green here when a test named for it ran and passed; it says nothing about whether the @@ -68,7 +69,7 @@ integration behind it keeps a batch it could not deliver, or commits offsets only after a flush. Those are invariants, they are counted separately below, and the two numbers are not interchangeable. -**37 invariants declared: 31 safety and 6 liveness. Of 142 (invariant, integration) cells: 63 proven, 51 missing, 0 skipped, 0 failing, 28 exempt. 0 gap(s).** +**38 invariants declared: 31 safety and 7 liveness. Of 143 (invariant, integration) cells: 66 proven, 49 missing, 0 skipped, 0 failing, 28 exempt. 0 gap(s).** Safety says nothing bad happens. Liveness says something good eventually does, and the two are not interchangeable: a sink that @@ -185,6 +186,7 @@ drains. An invariant holds only if it holds on all four. | --- | --- | --- | | `manager.publish.eventually` | A closed window reaches the sink without anything else happening. The loop polls on its own, and a window that closes is published. | ✅ u | | `manager.failure.exits` | A poll the sink refuses stops the manager with the sink's error, after one attempt, and the process exits with its code. The sink ran its retry ladder before the error arrived, so the manager does not retry in place, and a window the destination will not take is never collected, written and refused every tick while the process reports healthy. *(violated once: #267)* | ✅ u | +| `manager.drain.bounded` | The final poll after a cancel finishes or fails inside the drain deadline. A sink that never answers cannot hold the process past it, and every closed window it did not deliver stays in the state table. | ✅ u | These lifecycle invariants are properties of the consume loop rather than of anything a config file names. The columns are @@ -197,6 +199,6 @@ drains. An invariant holds only if it holds on all four. | --- | --- | --- | --- | | `pipeline.flush.eventually` | A batch that never reaches batchSize still reaches the sink, within the flush interval. | ✅ u | ✅ u | | `pipeline.progress.no_silent_stall` | A configuration cannot remove the flush ticker. flush_interval_seconds absent, zero or negative all run with the thirty second default, so a batch a low-traffic topic never fills still leaves on time. This entry previously claimed the opposite, that zero removed the ticker and stalled such a topic forever; the run command has always defaulted it. Pinned by TestCliInvocation_FlushIntervalNeverZero, not by the harness, and unenforced for that reason: the harness drives a pipeline that is already constructed, and this is a property of resolving the config before construction. There is nothing per-subject to observe, so demanding a cell from every subject would buy a fake rather than a proof. The liveness the harness can see is pipeline.flush.eventually, which it proves. | ❌ missing | ❌ missing | -| `lifecycle.drain.bounded` | The drain finishes or fails inside its deadline. *(declared, tracked by #161)* | ❌ missing | ❌ missing | +| `lifecycle.drain.bounded` | A drain finishes or fails inside pipeline.drain_deadline_seconds. A sink that never answers cannot hold the process past it: the loop returns system.lifecycle.drain_incomplete, commits nothing for the batch it could not write, and the next start replays it. | ✅ u | ✅ u | | `pipeline.batch.timeout` | A batch whose query exceeds the timeout fails the batch, not the process. *(declared, tracked by #163)* | ❌ missing | ❌ missing | diff --git a/docs/coverage/status/features.yml b/docs/coverage/status/features.yml index 95d88619..3fb307a0 100644 --- a/docs/coverage/status/features.yml +++ b/docs/coverage/status/features.yml @@ -15,6 +15,7 @@ handler.inferred_mem: {unit: covered, integration: not_required, release: covere handler.structured: {unit: covered, integration: not_required, release: covered} lifecycle.drain: {unit: covered, integration: not_required, release: covered} lifecycle.exit_codes: {unit: covered, integration: not_required, release: covered} +lifecycle.health: {unit: covered, integration: not_required, release: covered} manager.tumbling_window: {unit: covered, integration: not_required, release: covered} observability.debug_api: {unit: covered, integration: not_required, release: not_required} observability.metrics: {unit: covered, integration: not_required, release: not_required} diff --git a/docs/coverage/status/manager.tumbling_window.yml b/docs/coverage/status/manager.tumbling_window.yml index c73b7c29..b92b5873 100644 --- a/docs/coverage/status/manager.tumbling_window.yml +++ b/docs/coverage/status/manager.tumbling_window.yml @@ -2,5 +2,6 @@ # One line per invariant that applies to manager.tumbling_window, sorted by id: the status of each level. manager.delete.after_flush: {unit: covered, integration: missing, release: missing} manager.delete.nothing_on_failure: {unit: covered, integration: missing, release: missing} +manager.drain.bounded: {unit: covered, integration: missing, release: missing} manager.failure.exits: {unit: covered, integration: missing, release: missing} manager.publish.eventually: {unit: covered, integration: missing, release: missing} diff --git a/docs/coverage/status/pipeline.stateful.yml b/docs/coverage/status/pipeline.stateful.yml index baa8e3a3..a049ebf0 100644 --- a/docs/coverage/status/pipeline.stateful.yml +++ b/docs/coverage/status/pipeline.stateful.yml @@ -2,7 +2,7 @@ # One line per invariant that applies to pipeline.stateful, sorted by id: the status of each level. error.bad_record.threshold: {unit: missing, integration: missing, release: missing} error.dlq.carries_provenance: {unit: missing, integration: missing, release: missing} -lifecycle.drain.bounded: {unit: missing, integration: missing, release: missing} +lifecycle.drain.bounded: {unit: covered, integration: missing, release: missing} lifecycle.drain.on_cancel: {unit: covered, integration: missing, release: missing} pipeline.batch.timeout: {unit: missing, integration: missing, release: missing} pipeline.commit.after_flush: {unit: covered, integration: missing, release: missing} diff --git a/docs/coverage/status/pipeline.stateless.yml b/docs/coverage/status/pipeline.stateless.yml index cd087612..5f8fb18f 100644 --- a/docs/coverage/status/pipeline.stateless.yml +++ b/docs/coverage/status/pipeline.stateless.yml @@ -2,7 +2,7 @@ # One line per invariant that applies to pipeline.stateless, sorted by id: the status of each level. error.bad_record.threshold: {unit: missing, integration: missing, release: missing} error.dlq.carries_provenance: {unit: missing, integration: missing, release: missing} -lifecycle.drain.bounded: {unit: missing, integration: missing, release: missing} +lifecycle.drain.bounded: {unit: covered, integration: missing, release: missing} lifecycle.drain.on_cancel: {unit: covered, integration: missing, release: missing} pipeline.batch.timeout: {unit: missing, integration: missing, release: missing} pipeline.commit.after_flush: {unit: covered, integration: missing, release: missing} diff --git a/docs/superpowers/plans/2026-09-12-process-contract.md b/docs/superpowers/plans/2026-09-12-process-contract.md new file mode 100644 index 00000000..e23e6e92 --- /dev/null +++ b/docs/superpowers/plans/2026-09-12-process-contract.md @@ -0,0 +1,1802 @@ +# Process contract implementation plan + +> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. + +**Goal:** Bound the shutdown with one configurable deadline that exits 15 when it passes, and make `/healthz` report starting, healthy, degraded or failed. + +**Architecture:** `core.DrainBudget` is one deadline shared by the turbine's final batch, the managers' final poll and run's state syncs. The turbine classifies a drain that ran out of time as `system.lifecycle.drain_incomplete`, which `errs.ExitCode` maps to 15. A `health` struct in `internal/cli/run` collects failures and in-flight retries, and one pure function turns it plus the progress snapshot into a status. Both properties are proven in the conformance harness and enforced in the registry. + +**Tech Stack:** Go 1.2x, cobra, zeebo/assert, the conformance harness in `internal/conformance`, the coverage registry under `docs/coverage`, pytest for tooling and release tests, Astro for the site. + +**Spec:** `docs/superpowers/specs/2026-09-12-process-contract-design.md` + +## Global Constraints + +- No em dashes anywhere: code comments, docs, commit messages, YAML. +- No attribution lines in commits or PRs. +- Every Go test calls `coverage.Covers(t, ...)` first in its body. +- Comments and docs in Google Technical Writing One style. Plain declarative sentences. +- `uv run python`, never bare `python3`. +- Status files under `docs/coverage/status/` are regenerated from CI's report artifacts (`gh run download -n report-unit -n report-integration -n report-release`, then `make coverage-write`), never from a local run. +- The worktree is `$S/sqlflow-161` on branch `feat/process-contract`, where `S=/private/tmp/claude-501/-Users-danielmican-code-github-com-turbolytics-turbolytics-io/3d504d24-b5b3-4502-848a-732b4e380d07/scratchpad`. Never edit `/Users/danielmican/code/github.com/turbolytics/sql-flow`. +- Site work happens in `/Users/danielmican/code/github.com/turbolytics/turbolytics.io` on a new branch `docs/process-contract` from `main`. The working tree there carries an unrelated dirty edit to `tumbling-window-postgres.md`; do not commit it. +- Run `gofmt -l internal/ cmd/` before every Go commit. + +--- + +## File structure + +sql-flow: + +- Create `internal/core/drain.go`: `DrainBudget`, `DefaultDrainDeadline`, `WithDrainBudget`. +- Create `internal/core/drain_test.go`. +- Modify `internal/core/turbine.go`: the `drain` field, the `ctx.Done` branch, error stamps in `recordError`, the two new `Progress` fields. +- Modify `internal/core/progress.go`: `Progress` gains `LastError` and `Errors`. +- Modify `internal/errs/registry.go`, `internal/errs/exit.go`, `internal/errs/testdata/codes.golden`, `internal/errs/errs_test.go`. +- Modify `internal/managers/tumbling.go`: `WithDrainBudget`, final poll on the budget. +- Modify `internal/sinks/retry.go`, `internal/sinks/init.go`: `onSettle`, `RetryEvents`, `WithRetryEvents`. +- Modify `internal/config/config.go`, `internal/validate/schemas/config.json`, `internal/cli/testdata/config_example.golden`: `drain_deadline_seconds`. +- Create `internal/validate/drain.go` and `internal/validate/drain_test.go`: the `pipeline.drain_deadline` check. +- Modify `internal/validate/validate.go`: call the check. +- Create `internal/cli/run/health.go` and `internal/cli/run/health_status_test.go`. +- Modify `internal/cli/run/metrics.go`, `internal/cli/run/health_test.go`, `internal/cli/run/metrics_test.go`: the new mux parameter and statuses. +- Modify `internal/cli/run/root.go`, `internal/cli/run/managers.go`: build the budget, the health, wire both. +- Modify `internal/cli/exit_test.go`: the exit 15 mapping. +- Modify `internal/conformance/pipeline.go`, `internal/conformance/manager.go`: the two `drain.bounded` checks and the hanging sink. +- Modify `docs/coverage/invariants.yml`, `docs/coverage/features.yml`. +- Modify `tests/release/test_image.py`: `EXIT_DRAIN_INCOMPLETE`, the health release test. +- Modify `CHANGELOG.md`. + +turbolytics.io: + +- Create `src/content/docs/sqlflow/operations/running-in-production.md`. +- Modify `src/content/docs/sqlflow/introduction/configuration.md`, `src/content/docs/sqlflow/operations/handling-errors.md`, `tests/build.test.ts`. + +--- + +### Task 1: The taxonomy code and exit code 15 + +**Files:** +- Modify: `internal/errs/registry.go` +- Modify: `internal/errs/exit.go` +- Modify: `internal/errs/testdata/codes.golden` +- Test: `internal/errs/errs_test.go` + +**Interfaces:** +- Produces: `errs.CodeDrainIncomplete Code = "system.lifecycle.drain_incomplete"`, `errs.ExitDrainIncomplete = 15`. + +- [ ] **Step 1: Write the failing test** + +Append to `internal/errs/errs_test.go`: + +```go +// A drain that ran out of time is its own exit code. It is retryable, because +// nothing unwritten was committed and the next start replays it; the code +// exists so an operator can see the tail was replayed rather than written. +func TestLifecycleExitCodes_DrainIncompleteExitsFifteen(t *testing.T) { + coverage.Covers(t, "lifecycle.exit_codes") + err := New(CodeDrainIncomplete, "drain deadline 1s reached") + + assert.Equal(t, ExitDrainIncomplete, ExitCode(err)) + assert.Equal(t, 15, ExitDrainIncomplete) + assert.That(t, Retryable(ExitDrainIncomplete)) + + def, ok := Lookup(CodeDrainIncomplete) + assert.That(t, ok) + assert.That(t, strings.Contains(def.Action, "drain_deadline_seconds")) +} +``` + +- [ ] **Step 2: Run it** + +Run: `cd $S/sqlflow-161 && go test ./internal/errs/ -run DrainIncomplete` +Expected: FAIL, `undefined: CodeDrainIncomplete`. + +- [ ] **Step 3: Add the code, the definition and the exit code** + +In `internal/errs/registry.go`, after the `CodeBatchInternal` line: + +```go + // Lifecycle: the process stopping. A drain that ran out of time is not a + // sink failure and not a user error. Nothing unwritten was committed, so + // nothing is lost; the code says the tail was replayed rather than + // written. + CodeDrainIncomplete Code = "system.lifecycle.drain_incomplete" +``` + +In the `registry` map, after the `CodeBatchInternal` entry: + +```go + CodeDrainIncomplete: { + CodeDrainIncomplete, + "The drain deadline passed before the buffered batch or the closed windows were written.", + "Nothing is lost: what was not written was not committed, and the next start replays it. Raise pipeline.drain_deadline_seconds if the sink needs longer, or check the sink.", + }, +``` + +In `internal/errs/exit.go`, after `ExitStateCorrupt`: + +```go + // ExitDrainIncomplete marks a stop that ran out of time. Retryable: + // nothing unwritten was committed, and the next start replays it. The + // code exists so an operator can see that the tail of the stream was + // replayed rather than written. + ExitDrainIncomplete = 15 +``` + +Add `CodeDrainIncomplete: ExitDrainIncomplete,` to `exitCodes`. + +- [ ] **Step 4: Update the golden and run the package** + +Run: `cd $S/sqlflow-161 && UPDATE_GOLDEN=1 go test ./internal/errs/ -run RegistryIsAppendOnly && go test ./internal/errs/` +Expected: PASS. `git diff internal/errs/testdata/codes.golden` shows one added line and no removals. + +- [ ] **Step 5: Commit** + +```bash +git add internal/errs +git commit -m "errs: system.lifecycle.drain_incomplete exits 15" +``` + +--- + +### Task 2: `core.DrainBudget` and the bounded final batch + +**Files:** +- Create: `internal/core/drain.go` +- Create: `internal/core/drain_test.go` +- Modify: `internal/core/turbine.go` (the struct, `NewTurbine`, the `ctx.Done` branch) + +**Interfaces:** +- Produces: `core.NewDrainBudget(d time.Duration) *DrainBudget`, `(*DrainBudget).Context() context.Context`, `(*DrainBudget).Exceeded() bool`, `(*DrainBudget).Stop()`, `core.DefaultDrainDeadline = 30 * time.Second`, `core.WithDrainBudget(b *DrainBudget) TurbineOption`. +- Consumes: `errs.CodeDrainIncomplete` from Task 1. + +- [ ] **Step 1: Write the failing tests** + +Create `internal/core/drain_test.go`: + +```go +package core + +import ( + "context" + "errors" + "sync" + "testing" + "time" + + "github.com/apache/arrow-go/v18/arrow" + "github.com/turbolytics/sql-flow/internal/coverage" + "github.com/turbolytics/sql-flow/internal/errs" + "github.com/zeebo/assert" +) + +// The budget is one clock. Every caller after the first gets the same +// context, so the turbine's final batch and the managers' final poll spend +// the same seconds rather than each getting a fresh deadline. +func TestLifecycleDrain_BudgetIsOneClock(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + b := NewDrainBudget(50 * time.Millisecond) + defer b.Stop() + + assert.That(t, !b.Exceeded()) + first := b.Context() + second := b.Context() + assert.That(t, first == second) + + <-first.Done() + assert.That(t, b.Exceeded()) + assert.That(t, errors.Is(first.Err(), context.DeadlineExceeded)) +} + +// hangingSink blocks in Flush until its context ends. It is the sink a drain +// deadline exists for: one that neither succeeds nor fails on its own. +type hangingSink struct { + mu sync.Mutex + flushes int +} + +func (s *hangingSink) WriteTable(context.Context, arrow.Table) error { return nil } + +func (s *hangingSink) Flush(ctx context.Context) error { + s.mu.Lock() + s.flushes++ + s.mu.Unlock() + <-ctx.Done() + return ctx.Err() +} + +// A sink that never answers must not hold the process past the deadline. +// The loop returns inside the budget with the drain code, and the rows stay +// unwritten and uncommitted for the next start to replay. +func TestLifecycleDrain_DeadlineBoundsTheFinalBatch(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + src := newBlockingSource(messages(10)) + sink := &hangingSink{} + h := &drainHandler{wrote: make(chan struct{})} + budget := NewDrainBudget(200 * time.Millisecond) + defer budget.Stop() + + tb := NewTurbine(src, h, sink, 1000, time.Hour, &sync.Mutex{}, + PipelineErrorPolicies{}, WithDrainBudget(budget)) + + ctx, cancel := context.WithCancel(context.Background()) + defer close(src.release) + + var ( + err error + done = make(chan struct{}) + ) + go func() { + defer close(done) + _, err = tb.ConsumeLoop(ctx, 0) + }() + + for i := 0; i < 10; i++ { + <-h.wrote + } + started := time.Now() + cancel() + + select { + case <-done: + case <-time.After(5 * time.Second): + t.Fatal("the drain outlived its deadline by more than 5s") + } + + assert.That(t, time.Since(started) < 2*time.Second) + assert.Error(t, err) + assert.Equal(t, errs.CodeDrainIncomplete, errs.CodeOf(err)) + assert.That(t, budget.Exceeded()) +} + +// A sink that fails for its own reason during the drain keeps its own code. +// Only running out of time is a drain failure. +func TestLifecycleDrain_ASinkFailureInsideTheDeadlineKeepsItsCode(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + src := newBlockingSource(messages(3)) + sink := &fakeSink{flushErr: errs.New(errs.CodeSinkWriteFailed, "rejected")} + h := &drainHandler{wrote: make(chan struct{})} + budget := NewDrainBudget(5 * time.Second) + defer budget.Stop() + + tb := NewTurbine(src, h, sink, 1000, time.Hour, &sync.Mutex{}, + PipelineErrorPolicies{}, WithDrainBudget(budget)) + + ctx, cancel := context.WithCancel(context.Background()) + defer close(src.release) + + var ( + err error + done = make(chan struct{}) + ) + go func() { + defer close(done) + _, err = tb.ConsumeLoop(ctx, 0) + }() + for i := 0; i < 3; i++ { + <-h.wrote + } + cancel() + <-done + + assert.Equal(t, errs.CodeSinkWriteFailed, errs.CodeOf(err)) + assert.That(t, !budget.Exceeded()) +} +``` + +Check `fakeSink` in `internal/core/turbine_test.go` for the field that makes Flush fail. If it is not `flushErr`, use the field that exists. + +- [ ] **Step 2: Run them** + +Run: `cd $S/sqlflow-161 && go test ./internal/core/ -run 'LifecycleDrain_(Budget|Deadline|ASink)'` +Expected: FAIL, `undefined: NewDrainBudget`. + +- [ ] **Step 3: Write `internal/core/drain.go`** + +```go +package core + +import ( + "context" + "sync" + "time" +) + +// DefaultDrainDeadline bounds a shutdown that the config did not bound. +// Thirty seconds is Kubernetes' default terminationGracePeriodSeconds, so a +// pipeline with no setting at all still finishes or fails before the +// supervisor stops waiting. +const DefaultDrainDeadline = 30 * time.Second + +// DrainBudget is one deadline for everything a shutdown does. +// +// After a SIGTERM four things reach DuckDB or a sink: the turbine's final +// batch, a state sync, each manager's final poll and a second sync. A deadline +// per step would let the shutdown take four deadlines; a supervisor gives it +// one. So the budget starts its clock on the first call to Context and hands +// the same context to every caller after that. +type DrainBudget struct { + deadline time.Duration + once sync.Once + ctx context.Context + cancel context.CancelFunc +} + +// NewDrainBudget makes a budget whose clock has not started. +func NewDrainBudget(deadline time.Duration) *DrainBudget { + if deadline <= 0 { + deadline = DefaultDrainDeadline + } + return &DrainBudget{deadline: deadline} +} + +// Context starts the clock on the first call and returns the same context on +// every call after it. +func (b *DrainBudget) Context() context.Context { + b.once.Do(func() { + b.ctx, b.cancel = context.WithTimeout(context.Background(), b.deadline) + }) + return b.ctx +} + +// Exceeded reports whether the deadline has passed. False before the clock +// starts. +func (b *DrainBudget) Exceeded() bool { + if b.ctx == nil { + return false + } + return b.ctx.Err() != nil +} + +// Deadline is what the budget was built with, for log lines and errors. +func (b *DrainBudget) Deadline() time.Duration { return b.deadline } + +// Stop releases the timer. Safe before the clock starts. +func (b *DrainBudget) Stop() { + if b.cancel != nil { + b.cancel() + } +} + +// WithDrainBudget bounds the turbine's final batch. A turbine built without +// one gets DefaultDrainDeadline. +func WithDrainBudget(b *DrainBudget) TurbineOption { + return func(t *Turbine) { t.drain = b } +} +``` + +Note `Exceeded` reads `b.ctx` without the `once`. `Context` is called from the loop goroutine before anyone asks `Exceeded`; if the race detector objects, guard both with a `sync.Mutex` instead of `sync.Once`. + +- [ ] **Step 4: Wire it into the turbine** + +In `internal/core/turbine.go`, add to the `Turbine` struct beside `errorPolicy`: + +```go + // drain bounds the final batch after a cancel. Shared with the managers + // and run's state syncs, so one deadline covers the whole shutdown. + drain *DrainBudget +``` + +In `NewTurbine`, after the options loop, default it: + +```go + if t.drain == nil { + t.drain = NewDrainBudget(DefaultDrainDeadline) + } +``` + +Replace the `ctx.Done` branch's drain with: + +```go + case <-ctx.Done(): + t.logger.Info("context done, draining the consumer loop") + t.running = false + // The source delivered this batch, but nothing has written it yet. + // Returning without it drops the tail of every graceful shutdown. + // + // The drain runs on the budget's context, not the cancelled one: + // every step below reaches DuckDB and the sink, and the cancelled + // ctx would fail the exact work the drain exists to finish. The + // budget bounds it instead, because a supervisor gives a stop a + // fixed time and then kills the process with nothing recorded. + if numBatchMessages > 0 { + drainCtx := t.drain.Context() + if err := t.processBatch(drainCtx, numBatchMessages); err != nil { + if drainCtx.Err() != nil { + err = errs.Wrap(errs.CodeDrainIncomplete, err, + "drain deadline %s reached with %d messages buffered", + t.drain.Deadline(), numBatchMessages) + } + t.recordError(ctx, err, phaseSinkFlush, "error draining the final batch") + return nil, err + } + } + t.logThroughput() + return t.stats, nil +``` + +- [ ] **Step 5: Run the core package with the race detector** + +Run: `cd $S/sqlflow-161 && go test -short -race ./internal/core/` +Expected: PASS, including `TestLifecycleDrain_CancelDrainsTheBufferedBatch`, which now runs under the default budget. + +- [ ] **Step 6: Commit** + +```bash +git add internal/core/drain.go internal/core/drain_test.go internal/core/turbine.go +git commit -m "core: the final batch after a cancel runs on a drain budget" +``` + +--- + +### Task 3: The manager's final poll on the budget + +**Files:** +- Modify: `internal/managers/tumbling.go` +- Test: `internal/managers/tumbling_test.go` + +**Interfaces:** +- Produces: `managers.WithDrainBudget(b *core.DrainBudget) TumblingOption`. +- Consumes: `core.DrainBudget` from Task 2. + +- [ ] **Step 1: Write the failing test** + +Append to `internal/managers/tumbling_test.go`, using the helpers already there (`newTestConn` or whatever the file names its connection helper, `seedWindows`, `countRows`, and the sink double the failed-flush tests use). Read `TestManagerTumblingWindow__FinalPollOnShutdownPublishesAClosedWindow` at line 444 first and copy its setup: + +```go +// The final poll runs on the shutdown budget. A sink that never answers +// must not hold the process past it, and the windows stay in the table for +// the next start. +func TestManagerTumblingWindow__FinalPollStopsAtTheDrainDeadline(t *testing.T) { + coverage.Covers(t, "manager.tumbling_window") + conn := newTestConn(t) + seedWindows(t, conn) + sink := &hangingSink{} + budget := core.NewDrainBudget(200 * time.Millisecond) + defer budget.Stop() + + m := NewTumbling(conn, collectSQL, deleteSQL, time.Hour, sink, &sync.Mutex{}, + WithDrainBudget(budget)) + + ctx, cancel := context.WithCancel(context.Background()) + done := make(chan error, 1) + go func() { done <- m.Start(ctx) }() + cancel() + + select { + case err := <-done: + assert.Error(t, err) + case <-time.After(5 * time.Second): + t.Fatal("the final poll outlived the drain deadline") + } + assert.Equal(t, int64(2), countRows(t, conn, "windows")) +} +``` + +Define `hangingSink` in the test file the same way as Task 2's. Replace `newTestConn`, `collectSQL`, `deleteSQL`, `"windows"` and the seeded count with the names and values the file already uses. + +- [ ] **Step 2: Run it** + +Run: `cd $S/sqlflow-161 && go test ./internal/managers/ -run FinalPollStopsAtTheDrainDeadline` +Expected: FAIL, `undefined: WithDrainBudget`. + +- [ ] **Step 3: Add the option and use it** + +In `internal/managers/tumbling.go`, add a field to `Tumbling`: + +```go + // drain bounds the final poll. Shared with the turbine, so one deadline + // covers the whole shutdown. + drain *core.DrainBudget +``` + +Default it in `NewTumbling` after the options loop: + +```go + if m.drain == nil { + m.drain = core.NewDrainBudget(core.DefaultDrainDeadline) + } +``` + +Add the option beside `WithLogger`: + +```go +// WithDrainBudget bounds the final poll after a cancel. +func WithDrainBudget(b *core.DrainBudget) TumblingOption { + return func(m *Tumbling) { m.drain = b } +} +``` + +In `Start`, replace `m.Poll(context.Background())` in the `ctx.Done` branch with `m.Poll(m.drain.Context())`. + +- [ ] **Step 4: Run the package** + +Run: `cd $S/sqlflow-161 && go test -short -race ./internal/managers/` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add internal/managers +git commit -m "managers: the final poll runs on the drain budget" +``` + +--- + +### Task 4: Config key, schema, and the validate warning + +**Files:** +- Modify: `internal/config/config.go` +- Modify: `internal/validate/schemas/config.json` +- Modify: `internal/cli/testdata/config_example.golden` +- Create: `internal/validate/drain.go` +- Create: `internal/validate/drain_test.go` +- Modify: `internal/validate/validate.go` +- Modify: `internal/cli/run/metrics.go` (`drainDeadlineFor`) + +**Interfaces:** +- Produces: `config.Pipeline.DrainDeadlineSeconds int` (`yaml:"drain_deadline_seconds,omitempty"`), `run.drainDeadlineFor(seconds int) time.Duration`, validate check id `pipeline.drain_deadline`. + +- [ ] **Step 1: Add the key** + +In `internal/config/config.go`, after `FlushIntervalSeconds`: + +```go + // Longest a shutdown may take after SIGTERM: the final batch, the + // managers' final poll and the state syncs share it. Absent means 30. + // When it passes the process exits 15 and the next start replays what + // was not written. + DrainDeadlineSeconds int `yaml:"drain_deadline_seconds,omitempty"` +``` + +In `internal/validate/schemas/config.json`, after the `flush_interval_seconds` property in the pipeline block: + +```json + "drain_deadline_seconds": { + "type": "integer", + "minimum": 1, + "description": "Longest a shutdown may take after SIGTERM: the final batch, the\nmanagers' final poll and the state syncs share it. Absent means 30.\nWhen it passes the process exits 15 and the next start replays what\nwas not written." + }, +``` + +Check how `config example` orders keys (schema order or struct order) by regenerating the golden: `UPDATE_GOLDEN=1 go test ./internal/cli/ -run Example`. Read the diff. It must add only the new key with its comment. + +- [ ] **Step 2: Add `drainDeadlineFor`** + +In `internal/cli/run/metrics.go`, after `flushIntervalFor`: + +```go +// drainDeadlineFor is the one place the drain deadline is decided. Absent, +// zero and negative all mean the default, for the same reason as the flush +// interval: a shutdown the config forgot to bound is still bounded. +func drainDeadlineFor(seconds int) time.Duration { + if seconds > 0 { + return time.Duration(seconds) * time.Second + } + return core.DefaultDrainDeadline +} +``` + +Add to `internal/cli/run/metrics_test.go`, next to the flush interval test: + +```go +func TestLifecycleDrain_DeadlineDefaultsWhenAbsent(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + assert.Equal(t, core.DefaultDrainDeadline, drainDeadlineFor(0)) + assert.Equal(t, core.DefaultDrainDeadline, drainDeadlineFor(-5)) + assert.Equal(t, 45*time.Second, drainDeadlineFor(45)) +} +``` + +- [ ] **Step 3: Write the failing validate test** + +Create `internal/validate/drain_test.go`: + +```go +package validate + +import ( + "context" + "testing" + + "github.com/turbolytics/sql-flow/internal/coverage" + "github.com/zeebo/assert" +) + +const drainConfig = `pipeline: + batch_size: 1 + drain_deadline_seconds: %d + source: + type: kafka + kafka: + brokers: ["localhost:9092"] + group_id: g + auto_offset_reset: earliest + topics: ["t"] + handler: + type: handlers.InferredMemBatch + sql: SELECT 1 + sink: + type: clickhouse + clickhouse: + dsn: clickhouse://localhost:9000 + table: t + retry: + deadline_seconds: 20 +` + +// hasCheck reports whether the report carries the check at that status. +func hasCheck(rep Report, id string, status Status) bool { + for _, c := range rep.Checks { + if c.ID == id && c.Status == status { + return true + } + } + return false +} + +// A drain deadline shorter than a sink's retry deadline is a choice, not a +// fault: the operator wants the process out. They are told what it costs. +func TestValidateSchema_ShortDrainDeadlineWarns(t *testing.T) { + coverage.Covers(t, "validate.schema") + rep, err := Validate(context.Background(), Request{ + Path: "drain.yml", Config: fmt.Sprintf(drainConfig, 5)}) + assert.NoError(t, err) + assert.That(t, rep.OK) + + var warned bool + for _, d := range rep.Diagnostics { + if d.Severity == SeverityWarning && d.Code == "user.config.invalid" { + warned = true + assert.That(t, strings.Contains(d.Message, "drain_deadline_seconds")) + assert.That(t, strings.Contains(d.Message, "retry.deadline_seconds")) + } + } + assert.That(t, warned) + assert.That(t, hasCheck(rep, "pipeline.drain_deadline", StatusWarn)) +} + +func TestValidateSchema_LongDrainDeadlinePasses(t *testing.T) { + coverage.Covers(t, "validate.schema") + rep, err := Validate(context.Background(), Request{ + Path: "drain.yml", Config: fmt.Sprintf(drainConfig, 60)}) + assert.NoError(t, err) + assert.That(t, rep.OK) + assert.That(t, hasCheck(rep, "pipeline.drain_deadline", StatusPass)) +} +``` + +Add `fmt` and `strings` to the imports. Read `report.go` for the exact `Status` and `Severity` constant names; if there is no warning status for a check, use `StatusPass` for the check and keep the warning diagnostic. + +- [ ] **Step 4: Run it** + +Run: `cd $S/sqlflow-161 && go test ./internal/validate/ -run DrainDeadline` +Expected: FAIL, no `pipeline.drain_deadline` check. + +- [ ] **Step 5: Write the check** + +Create `internal/validate/drain.go`: + +```go +package validate + +import ( + "fmt" + + "github.com/turbolytics/sql-flow/internal/config" + "github.com/turbolytics/sql-flow/internal/core" + "github.com/turbolytics/sql-flow/internal/errs" + "github.com/turbolytics/sql-flow/internal/sinks" + "gopkg.in/yaml.v3" +) + +// checkDrainDeadline warns when a sink's retry ladder can outlive the drain. +// +// A short drain deadline is a legitimate choice: the operator wants the +// process out in five seconds whatever the sink is doing. It is a warning +// because that choice has a cost they may not have priced: a drain that hits +// a retrying sink exits 15 before the ladder finishes, and the tail replays +// on the next start. +func checkDrainDeadline(rendered []byte, rep *Report) { + var conf config.Conf + if err := yaml.Unmarshal(rendered, &conf); err != nil { + // The schema check has already reported the parse failure. + rep.SetCheck("pipeline.drain_deadline", StatusSkipped, + "the config did not parse, so there was no pipeline to check") + return + } + + drain := core.DefaultDrainDeadline + if conf.Pipeline.DrainDeadlineSeconds > 0 { + drain = time.Duration(conf.Pipeline.DrainDeadlineSeconds) * time.Second + } + + type ladder struct { + name string + retry *config.SinkRetry + } + ladders := []ladder{{"pipeline.sink", conf.Pipeline.Sink.Retry}} + if conf.Pipeline.OnError != nil && conf.Pipeline.OnError.DLQ != nil { + ladders = append(ladders, ladder{"pipeline.on_error.dlq", conf.Pipeline.OnError.DLQ.Retry}) + } + if conf.Tables != nil { + for _, table := range conf.Tables.SQL { + if table.Manager != nil { + ladders = append(ladders, ladder{ + fmt.Sprintf("tables.sql[%s].manager.sink", table.Name), + table.Manager.Sink.Retry}) + } + } + } + + status := StatusPass + for _, l := range ladders { + policy := sinks.RetryPolicyFrom(l.retry) + if policy.Deadline <= drain { + continue + } + status = StatusWarn + rep.Add(diagnostic(errs.CodeConfigInvalid, SeverityWarning, fmt.Sprintf( + "pipeline.drain_deadline_seconds is %s and %s retry.deadline_seconds is %s, "+ + "so a drain that hits a retrying sink exits 15 before the ladder finishes", + drain, l.name, policy.Deadline), nil)) + } + rep.SetCheck("pipeline.drain_deadline", status, "") +} +``` + +Add the `time` import. Check whether `internal/validate` may import `internal/sinks` without a cycle (`go build ./...` says). If it cycles, copy the four default constants into `internal/config` as `DefaultSinkRetryDeadlineSeconds` and read them from there instead, and make `sinks.RetryPolicyFrom` use the config constant so there is one source. + +In `internal/validate/validate.go`, after `checkSchema(rendered, &rep)`: + +```go + checkDrainDeadline(rendered, &rep) +``` + +Read `report.go` to confirm whether a warning-status check keeps `rep.OK` true. `Finish` decides `OK`; if it counts warning checks as failures, the test in Step 3 tells you, and the check should report `StatusPass` with the warning diagnostic instead. + +- [ ] **Step 6: Run the packages** + +Run: `cd $S/sqlflow-161 && go build ./... && go test -short ./internal/validate/ ./internal/cli/ ./internal/cli/run/ ./internal/config/` +Expected: PASS. If `TestValidate...` in `internal/cli/validate_test.go` compares text output against a golden, regenerate it the same way and read the diff. + +- [ ] **Step 7: Commit** + +```bash +git add internal/config internal/validate internal/cli +git commit -m "config: pipeline.drain_deadline_seconds, and validate warns when a retry ladder outlives it" +``` + +--- + +### Task 5: Retry events from the ladder + +**Files:** +- Modify: `internal/sinks/retry.go` +- Modify: `internal/sinks/init.go` +- Test: `internal/sinks/retry_test.go` + +**Interfaces:** +- Produces: `sinks.RetryEvents{Retry func(sinkType string, attempt int, err error); Settle func(sinkType string)}`, `sinks.WithRetryEvents(e RetryEvents) Option`, `retrying.onSettle func()`. + +- [ ] **Step 1: Write the failing test** + +Append to `internal/sinks/retry_test.go`: + +```go +// The health endpoint needs to know when a ladder is running and when it has +// stopped, whichever way it stopped. Settle fires once per flush that +// retried at all, after success or after the last failure. +func TestSinkRetry_SettleFiresAfterALadderEitherWay(t *testing.T) { + coverage.Covers(t, "sink.retry") + + settled := 0 + retries := 0 + run := func(failures int) error { + sink := &flakySink{failures: failures, err: errors.New("connection reset by peer")} + r := newRetrying(sink, testPolicy()) + r.onRetry = func(int, error) { retries++ } + r.onSettle = func() { settled++ } + assert.NoError(t, r.WriteTable(context.Background(), nil)) + return r.Flush(context.Background()) + } + + // Succeeds on the second attempt: one retry, one settle. + assert.NoError(t, run(1)) + assert.Equal(t, 1, retries) + assert.Equal(t, 1, settled) + + // Never succeeds: the ladder is spent, and it still settles. + assert.Error(t, run(99)) + assert.Equal(t, 2, settled) + + // Succeeds first time: no ladder ran, nothing to settle. + assert.NoError(t, run(0)) + assert.Equal(t, 2, settled) +} +``` + +- [ ] **Step 2: Run it** + +Run: `cd $S/sqlflow-161 && go test ./internal/sinks/ -run SettleFires` +Expected: FAIL, `r.onSettle undefined`. + +- [ ] **Step 3: Add `onSettle`** + +In `retrying`, after `onRetry`: + +```go + // onSettle reports that a ladder which retried at least once has + // stopped, whether it delivered or gave up. The health endpoint clears + // its "retrying" state on it. + onSettle func() +``` + +Set `onSettle: func() {}` in `newRetrying`. In `Flush`, wrap the loop so that every return after the first retry settles: + +```go + retried := false + defer func() { + if retried { + r.onSettle() + } + }() + + for attempt := 1; ; attempt++ { + ... + r.onRetry(attempt, err) + retried = true + ... + } +``` + +Place `retried = true` on the line after `r.onRetry(attempt, err)`. + +- [ ] **Step 4: Add the option in `init.go`** + +```go +// RetryEvents is told when a sink's retry ladder runs. Retry fires per failed +// attempt that will be tried again; Settle fires once when a ladder that +// retried at all stops, whether it delivered or gave up. +type RetryEvents struct { + Retry func(sinkType string, attempt int, err error) + Settle func(sinkType string) +} + +// WithRetryEvents wires the ladder's events to a listener. The retry counter +// records regardless; this is for the health endpoint. +func WithRetryEvents(e RetryEvents) Option { + return func(o *options) { o.retryEvents = e } +} +``` + +Add `retryEvents RetryEvents` to `options`. In `New`, after `r.onRetry = retryCounter(...)`: + +```go + if o.retryEvents.Retry != nil { + counter := r.onRetry + notify := o.retryEvents.Retry + r.onRetry = func(attempt int, err error) { + counter(attempt, err) + notify(sink.Type, attempt, err) + } + } + if o.retryEvents.Settle != nil { + notify := o.retryEvents.Settle + r.onSettle = func() { notify(sink.Type) } + } +``` + +- [ ] **Step 5: Run the package** + +Run: `cd $S/sqlflow-161 && go test -short -race ./internal/sinks/` +Expected: PASS. + +- [ ] **Step 6: Commit** + +```bash +git add internal/sinks +git commit -m "sinks: the retry ladder reports when it settles" +``` + +--- + +### Task 6: Progress carries the error clock + +**Files:** +- Modify: `internal/core/progress.go` +- Modify: `internal/core/turbine.go` (`recordError`, `Progress()`) +- Test: `internal/core/progress_test.go` + +**Interfaces:** +- Produces: `core.Progress.LastError time.Time`, `core.Progress.Errors int64`. + +- [ ] **Step 1: Write the failing test** + +Append to `internal/core/progress_test.go`: + +```go +// The health endpoint calls a pipeline degraded when it recorded an error +// inside the last interval, so the snapshot has to carry when that was. +func TestCoreConsumeLoop_ProgressRecordsTheLastError(t *testing.T) { + coverage.Covers(t, "core.consume_loop") + src := &fakeSource{batches: [][]Message{{{Value: []byte("bad")}, {Value: []byte("ok")}}}} + h := &failingHandler{failWriteOn: "bad"} + sink := &fakeSink{} + tb := NewTurbine(src, h, sink, 2, time.Second, &sync.Mutex{}, + PipelineErrorPolicies{Policy: PolicyIgnore}) + + before := time.Now().UTC() + _, err := tb.ConsumeLoop(context.Background(), 0) + assert.NoError(t, err) + + p := tb.Progress() + assert.Equal(t, int64(1), p.Errors) + assert.That(t, !p.LastError.Before(before)) +} +``` + +- [ ] **Step 2: Run it** + +Run: `cd $S/sqlflow-161 && go test ./internal/core/ -run ProgressRecordsTheLastError` +Expected: FAIL, `p.Errors undefined`. + +- [ ] **Step 3: Add the fields** + +In `internal/core/progress.go`: + +```go +type Progress struct { + LastArrival time.Time + LastCommit time.Time + // LastError is when the loop last recorded an error, and Errors is how + // many it has recorded. In memory only: they describe this process, not + // the durable state, so the progress table does not carry them. + LastError time.Time + Errors int64 + Messages int64 +} +``` + +Check that `ProgressStore.Record` builds its UPDATE from named fields rather than the whole struct, so the two new fields do not reach SQL. If it uses the struct wholesale, leave the SQL as it was and pass only the three columns it wrote before. + +In `turbine.go`, add two atomics to the struct beside `commits`: + +```go + // lastErrorUnixNano and errorCount feed Progress without taking the + // lock: recordError runs on paths that may already hold it. + lastErrorUnixNano atomic.Int64 + errorCount atomic.Int64 +``` + +At the top of `recordError`: + +```go + t.lastErrorUnixNano.Store(time.Now().UnixNano()) + t.errorCount.Add(1) +``` + +In `Progress()`: + +```go +func (t *Turbine) Progress() Progress { + t.lock.Lock() + p := t.snapshot + t.lock.Unlock() + if ns := t.lastErrorUnixNano.Load(); ns != 0 { + p.LastError = time.Unix(0, ns).UTC() + } + p.Errors = t.errorCount.Load() + return p +} +``` + +- [ ] **Step 4: Run the package** + +Run: `cd $S/sqlflow-161 && go test -short -race ./internal/core/` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add internal/core +git commit -m "core: Progress carries the last error and the error count" +``` + +--- + +### Task 7: The health status function and the endpoint + +**Files:** +- Create: `internal/cli/run/health.go` +- Create: `internal/cli/run/health_status_test.go` +- Modify: `internal/cli/run/metrics.go` +- Modify: `internal/cli/run/health_test.go` +- Modify: `internal/cli/run/metrics_test.go` (every `newHTTPMux` call gains a `nil` health argument) +- Modify: `docs/coverage/features.yml` + +**Interfaces:** +- Produces: `type health struct`, `newHealth() *health`, `(*health).Fail(err error)`, `(*health).Retry(sinkType string, attempt int, err error)`, `(*health).Settle(sinkType string)`, `(*health).Snapshot() healthSnapshot`, `type healthFunc func() healthSnapshot`, `healthStatus(p core.Progress, commitAge float64, snap healthSnapshot, interval time.Duration, now time.Time) (status, reason string, httpCode int)`. +- `newHTTPMux(registry, stats, collect, progress, health healthFunc, interval, now)`. + +- [ ] **Step 1: Add the feature** + +In `docs/coverage/features.yml`, after `lifecycle.exit_codes`: + +```yaml + - id: lifecycle.health + description: /healthz reports starting, healthy, degraded or failed, with a reason. + requires: [unit, release] +``` + +- [ ] **Step 2: Write the failing status test** + +Create `internal/cli/run/health_status_test.go`: + +```go +package run + +import ( + "errors" + "net/http" + "testing" + "time" + + "github.com/turbolytics/sql-flow/internal/core" + "github.com/turbolytics/sql-flow/internal/coverage" + "github.com/zeebo/assert" +) + +// The four states, one table. The first matching rule wins: a recorded +// failure beats everything, then the commit clock, then a retry in flight, +// then a recent error, then a pipeline that has not committed yet. +func TestLifecycleHealth_StatusTable(t *testing.T) { + coverage.Covers(t, "lifecycle.health") + now := time.Date(2026, 9, 12, 12, 0, 0, 0, time.UTC) + interval := 30 * time.Second + recent := core.Progress{LastCommit: now.Add(-10 * time.Second)} + + cases := []struct { + name string + p core.Progress + commitAge float64 + snap healthSnapshot + status string + reason string + httpStatus int + }{ + {"healthy", recent, 10, healthSnapshot{}, "healthy", "", http.StatusOK}, + {"starting", core.Progress{}, 5, healthSnapshot{}, "starting", "no commit yet", http.StatusOK}, + {"stuck is failed", recent, 91, healthSnapshot{}, "failed", "no commit for 91s", http.StatusServiceUnavailable}, + {"never committed past the grace", core.Progress{}, 120, healthSnapshot{}, "failed", "no commit for 120s", http.StatusServiceUnavailable}, + {"retrying", recent, 10, healthSnapshot{retrying: map[string]int{"clickhouse": 2}}, + "degraded", "sink clickhouse is retrying, attempt 2", http.StatusOK}, + {"recent error", core.Progress{LastCommit: recent.LastCommit, LastError: now.Add(-5 * time.Second), Errors: 3}, + 10, healthSnapshot{}, "degraded", "3 errors recorded, last 5s ago", http.StatusOK}, + {"old error", core.Progress{LastCommit: recent.LastCommit, LastError: now.Add(-time.Hour), Errors: 3}, + 10, healthSnapshot{}, "healthy", "", http.StatusOK}, + {"failure wins", recent, 10, healthSnapshot{failure: errors.New("[system.sink.write_failed] rejected")}, + "failed", "[system.sink.write_failed] rejected", http.StatusServiceUnavailable}, + } + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + status, reason, code := healthStatus(c.p, c.commitAge, c.snap, interval, now) + assert.Equal(t, c.status, status) + assert.Equal(t, c.reason, reason) + assert.Equal(t, c.httpStatus, code) + }) + } +} + +// Fail keeps the first failure. A drain that then times out is a consequence, +// and the endpoint should name the cause. +func TestLifecycleHealth_FirstFailureIsKept(t *testing.T) { + coverage.Covers(t, "lifecycle.health") + h := newHealth() + h.Fail(errors.New("first")) + h.Fail(errors.New("second")) + assert.Equal(t, "first", h.Snapshot().failure.Error()) +} + +func TestLifecycleHealth_RetryAndSettle(t *testing.T) { + coverage.Covers(t, "lifecycle.health") + h := newHealth() + h.Retry("clickhouse", 1, errors.New("reset")) + h.Retry("clickhouse", 2, errors.New("reset")) + assert.Equal(t, 2, h.Snapshot().retrying["clickhouse"]) + h.Settle("clickhouse") + assert.Equal(t, 0, len(h.Snapshot().retrying)) +} +``` + +- [ ] **Step 3: Run it** + +Run: `cd $S/sqlflow-161 && go test ./internal/cli/run/ -run LifecycleHealth` +Expected: FAIL, `undefined: healthStatus`. + +- [ ] **Step 4: Write `internal/cli/run/health.go`** + +```go +package run + +import ( + "fmt" + "net/http" + "sort" + "sync" + "time" + + "github.com/turbolytics/sql-flow/internal/core" +) + +// health is what the process knows about itself that the progress snapshot +// does not: a failure that has stopped the loop, and a sink whose retry +// ladder is running. +type health struct { + mu sync.Mutex + failure error + retrying map[string]int +} + +func newHealth() *health { + return &health{retrying: map[string]int{}} +} + +// Fail records the failure that is stopping the process. The first one is +// kept: a drain that then runs out of time is a consequence, and the endpoint +// should name the cause. +func (h *health) Fail(err error) { + if err == nil { + return + } + h.mu.Lock() + defer h.mu.Unlock() + if h.failure == nil { + h.failure = err + } +} + +// Retry records a ladder attempt in flight for one sink type. +func (h *health) Retry(sinkType string, attempt int, _ error) { + h.mu.Lock() + defer h.mu.Unlock() + h.retrying[sinkType] = attempt +} + +// Settle clears the ladder for one sink type. +func (h *health) Settle(sinkType string) { + h.mu.Lock() + defer h.mu.Unlock() + delete(h.retrying, sinkType) +} + +// healthSnapshot is one read of health, safe to hand to the status function. +type healthSnapshot struct { + failure error + retrying map[string]int +} + +func (h *health) Snapshot() healthSnapshot { + h.mu.Lock() + defer h.mu.Unlock() + out := healthSnapshot{failure: h.failure, retrying: make(map[string]int, len(h.retrying))} + for k, v := range h.retrying { + out.retrying[k] = v + } + return out +} + +// healthFunc reads the process's health. Nil means there is none to read. +type healthFunc func() healthSnapshot + +// healthStatus is the table behind /healthz. The first matching rule wins. +// +// 200 means "do not restart" and 503 means "restart, or let it exit". A +// retrying sink and a recent error are both 200: restarting a pipeline whose +// sink is on its second attempt turns a blip into a rebalance. +func healthStatus(p core.Progress, commitAge float64, snap healthSnapshot, + interval time.Duration, now time.Time) (status, reason string, httpCode int) { + + if snap.failure != nil { + return "failed", snap.failure.Error(), http.StatusServiceUnavailable + } + if commitAge > float64(stuckIntervals)*interval.Seconds() { + return "failed", fmt.Sprintf("no commit for %.0fs", commitAge), http.StatusServiceUnavailable + } + if len(snap.retrying) > 0 { + sinks := make([]string, 0, len(snap.retrying)) + for s := range snap.retrying { + sinks = append(sinks, s) + } + sort.Strings(sinks) + return "degraded", fmt.Sprintf("sink %s is retrying, attempt %d", + sinks[0], snap.retrying[sinks[0]]), http.StatusOK + } + if !p.LastError.IsZero() && now.Sub(p.LastError) <= interval { + return "degraded", fmt.Sprintf("%d errors recorded, last %.0fs ago", + p.Errors, now.Sub(p.LastError).Seconds()), http.StatusOK + } + if p.LastCommit.IsZero() { + return "starting", "no commit yet", http.StatusOK + } + return "healthy", "", http.StatusOK +} +``` + +- [ ] **Step 5: Change the mux** + +In `internal/cli/run/metrics.go`, add `health healthFunc` after `progress progressFunc` in `newHTTPMux`'s parameters. Replace the `/healthz` handler: + +```go + if progress != nil { + mux.HandleFunc("/healthz", func(w http.ResponseWriter, r *http.Request) { + p, _, commit := ages() + var snap healthSnapshot + if health != nil { + snap = health() + } + status, reason, code := healthStatus(p, commit, snap, interval, now()) + + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(code) + body := map[string]any{ + "status": status, + "commit_age_seconds": commit, + "interval_seconds": interval.Seconds(), + } + if reason != "" { + body["reason"] = reason + } + _ = json.NewEncoder(w).Encode(body) + }) + } +``` + +Add `"last_error": p.LastError` and `"errors": p.Errors` to the `/stats` progress map. + +Thread `health` through `newMeterProvider` as a new parameter after `progress`, and pass it to `newHTTPMux`. Update every caller: `health_test.go` (two), `metrics_test.go` (seven), `root.go` (one, in Task 8). + +- [ ] **Step 6: Update `health_test.go`** + +In `TestObservabilityMetrics_HealthzTellsIdleFromStuck`: change `coverage.Covers` to `"lifecycle.health"`, the expected first status from `"ok"` to `"healthy"`, the stuck status from `"stuck"` to `"failed"` with `assert.Equal(t, "no commit for 91s", body["reason"])`, the fresh-pipeline status to `"starting"`, and the final never-committed status to `"failed"`. Add `nil` as the health argument. Leave `TestObservabilityMetrics_HealthzAbsentWithoutProgress` under `observability.metrics` with the extra `nil`. + +Add a test that the mux reads the health: + +```go +func TestLifecycleHealth_EndpointReportsAFailure(t *testing.T) { + coverage.Covers(t, "lifecycle.health") + h := newHealth() + p := core.Progress{LastCommit: time.Now().Add(-time.Second)} + mux := newHTTPMux(nil, nil, nil, func() core.Progress { return p }, h.Snapshot, + 30*time.Second, time.Now) + srv := httptest.NewServer(mux) + defer srv.Close() + + h.Fail(errors.New("[system.sink.write_failed] rejected")) + resp, err := http.Get(srv.URL + "/healthz") + assert.NoError(t, err) + defer resp.Body.Close() + var body map[string]any + _ = json.NewDecoder(resp.Body).Decode(&body) + assert.Equal(t, http.StatusServiceUnavailable, resp.StatusCode) + assert.Equal(t, "failed", body["status"]) + assert.Equal(t, "[system.sink.write_failed] rejected", body["reason"]) +} +``` + +- [ ] **Step 7: Run the package and the tooling** + +Run: `cd $S/sqlflow-161 && go build ./... && go test -short -race ./internal/cli/run/ && uv run pytest tests/tooling -q` +Expected: Go PASS. Tooling may fail on the matrix page being stale; run `make coverage-page` and rerun. + +- [ ] **Step 8: Commit** + +```bash +git add internal/cli/run docs/coverage +git commit -m "run: /healthz reports starting, healthy, degraded or failed" +``` + +--- + +### Task 8: Wire the budget and the health in `run` + +**Files:** +- Modify: `internal/cli/run/root.go` +- Modify: `internal/cli/run/managers.go` +- Test: `internal/cli/exit_test.go` + +**Interfaces:** +- Consumes: everything above. `buildManagedTables` gains two parameters: `budget *core.DrainBudget` and `events sinks.RetryEvents`. + +- [ ] **Step 1: Build the budget and the health** + +In `root.go`, change the `RunE` signature to a named return, `RunE: func(cmd *cobra.Command, args []string) (runErr error) {`, so the deferred block can set it. + +After `flushInterval := flushIntervalFor(...)`: + +```go + // One deadline for the whole shutdown, started when the signal + // arrives. The turbine's final batch, the managers' final poll + // and the two state syncs below all spend it. + budget := core.NewDrainBudget(drainDeadlineFor(conf.Pipeline.DrainDeadlineSeconds)) + defer budget.Stop() + + // What /healthz knows that the progress snapshot does not. + hs := newHealth() + retryEvents := sinks.RetryEvents{Retry: hs.Retry, Settle: hs.Settle} +``` + +Pass `hs.Snapshot` to `newMeterProvider` as the health argument. + +Add `sinks.WithRetryEvents(retryEvents)` to the pipeline `sinks.New` call and to the DLQ call in `newErrorPolicies` (give `newErrorPolicies` an `events sinks.RetryEvents` parameter). Add `core.WithDrainBudget(budget)` to the turbine options. + +In `managers.go`, add `budget *core.DrainBudget` and `events sinks.RetryEvents` parameters to `buildManagedTables`, pass `sinks.WithRetryEvents(events)` to its `sinks.New` and `managers.WithDrainBudget(budget)` to `NewTumbling`. + +- [ ] **Step 2: Report failures to the health and check the budget** + +The manager goroutine already calls `failRun(err)` (from #270); add `hs.Fail(err)` beside it. + +Change the deferred manager block to run its syncs on the budget and to set the return when the budget ran out: + +```go + defer func() { + drainCtx := budget.Context() + if err := turbine.SyncState(drainCtx); err != nil { + l.Error("failed to sync state before final poll", zap.Error(err)) + } + stopManagers() + managerWG.Wait() + if err := turbine.SyncState(drainCtx); err != nil { + l.Error("failed to sync state after final poll", zap.Error(err)) + } + if budget.Exceeded() && runErr == nil { + runErr = errs.New(errs.CodeDrainIncomplete, + "drain deadline %s reached before the managers' final poll finished", + budget.Deadline()) + hs.Fail(runErr) + l.Error("drain incomplete", zap.Error(runErr)) + } + }() +``` + +Careful: `budget.Context()` here starts the clock if the loop never did, which is the case when the loop exited on `--max-msgs` rather than a signal. That is fine: a clean exit's syncs finish in milliseconds. + +After `stats, err := turbine.ConsumeLoop(runCtx, maxMsgs)` and `stopSignals()`, when `err != nil`, add `hs.Fail(err)` before returning. Where the manager cause is returned, `hs.Fail(cause)` too. + +- [ ] **Step 3: Add the exit code test** + +Append to `internal/cli/exit_test.go`: + +```go +// A drain that ran out of time exits 15, and a supervisor may restart it: +// nothing unwritten was committed. +func TestLifecycleExitCodes_DrainIncompleteIsRetryable(t *testing.T) { + coverage.Covers(t, "lifecycle.exit_codes") + err := errs.New(errs.CodeDrainIncomplete, "drain deadline 30s reached") + code := errs.ExitCode(err) + assert.Equal(t, errs.ExitDrainIncomplete, code) + assert.That(t, errs.Retryable(code)) +} +``` + +- [ ] **Step 4: Build, vet, test** + +Run: `cd $S/sqlflow-161 && go build ./... && go vet ./... && gofmt -l internal/ cmd/ && go test -short -race ./internal/cli/... ./internal/core/ ./internal/managers/ ./internal/sinks/` +Expected: PASS, `gofmt -l` prints nothing. + +- [ ] **Step 5: Run a stateful example end to end** + +Use the local Kafka on the `sqlflow` docker network (see the memory file `sqlflow-local-verification-setup`). Build the binary, run `dev/config/examples/kafka.stateful.window.yml` with `SQLFLOW_STATE_PATH` in the scratchpad, produce a few messages, curl `:8000/healthz` and confirm `starting` then `healthy`, send SIGTERM and confirm exit 0 with a `draining` log line. If Kafka is not up, note it in the PR and rely on the release test. + +- [ ] **Step 6: Commit** + +```bash +git add internal/cli +git commit -m "run: one drain budget for the shutdown, and the health endpoint sees failures and retries" +``` + +--- + +### Task 9: Harness checks for `lifecycle.drain.bounded` and `manager.drain.bounded` + +**Files:** +- Modify: `internal/conformance/pipeline.go` +- Modify: `internal/conformance/manager.go` +- Modify: `docs/coverage/invariants.yml` +- Test: the existing `TestPipeline*_Conformance` and `TestManagerTumblingWindow_Conformance` tests run the new checks. + +**Interfaces:** +- Consumes: `core.WithDrainBudget`, `core.NewDrainBudget`, `managers.WithDrainBudget` (through the subject's `New`). +- The `recordingSink` gains `hang bool`: `Flush` blocks until the context ends and records `flush-failed`. +- `PipelineSubject` gains nothing; `runPipeline` gains a `faults.hang` field and a `drainBudget` it applies through `WithDrainBudget`. +- `ManagerSubject.New` gains a fourth parameter, `budget *core.DrainBudget`. Update `internal/managers/conformance_test.go` to pass `WithDrainBudget(budget)`. + +- [ ] **Step 1: Register the invariants** + +In `docs/coverage/invariants.yml`, change `lifecycle.drain.bounded`: + +```yaml + - id: lifecycle.drain.bounded + family: lifecycle + class: liveness + applies_to: pipeline + claim: > + A drain finishes or fails inside pipeline.drain_deadline_seconds. A sink + that never answers cannot hold the process past it: the loop returns + system.lifecycle.drain_incomplete, commits nothing for the batch it + could not write, and the next start replays it. + verified_by: harness + requires: [] + enforced: true +``` + +Add after `manager.failure.exits`: + +```yaml + - id: manager.drain.bounded + family: lifecycle + class: liveness + applies_to: manager + claim: > + The final poll after a cancel finishes or fails inside the drain + deadline. A sink that never answers cannot hold the process past it, + and every closed window it did not deliver stays in the state table. + verified_by: harness + requires: [] + enforced: true +``` + +Update the header comment's count if it names a total, and update `internal/coverage/registry_test.go` and `tests/tooling/test_registries.py` if either asserts an invariant count. + +- [ ] **Step 2: The hanging sink and the pipeline check** + +In `pipeline.go`, add `hang bool` to `recordingSink` and to `faults`. In `recordingSink.Flush`, before the `fail` branch: + +```go + if hang { + // The sink a drain deadline exists for: one that neither succeeds + // nor fails until the caller gives up. + <-ctx.Done() + s.rec.record("flush-failed") + return ctx.Err() + } +``` + +Read `hang` under the mutex with `inner` and `fail`. In `runPipeline`, set `sink.hang = f.hang`, and when `f.hang` is set build the turbine with `core.WithDrainBudget(core.NewDrainBudget(drainBudget))` where: + +```go +// drainBudget is the deadline the bounded-drain scenario runs under. Short +// enough that the check is fast, long enough that a machine under load still +// reaches the flush before the clock starts. +const drainBudget = 300 * time.Millisecond +``` + +Add the constant `drainBounded = "lifecycle.drain.bounded"` and the check: + +```go +// checkDrainBounded cancels mid-run against a sink that never answers, and +// holds that the loop returned inside the deadline with the drain code and +// committed nothing. +func checkDrainBounded(t *testing.T, s PipelineSubject) error { + t.Helper() + started := time.Now() + run := runPipeline(t, s, TriggerDrain, faults{hang: true}) + took := time.Since(started) + + if run.err == nil { + return fmt.Errorf("drain.bounded: the sink never answered and the pipeline reported a clean stop") + } + if errs.CodeOf(run.err) != errs.CodeDrainIncomplete { + return fmt.Errorf("drain.bounded: the drain ran out of time and reported %s; "+ + "want %s so an operator can see the tail was replayed", errs.CodeOf(run.err), + errs.CodeDrainIncomplete) + } + if took > 10*drainBudget { + return fmt.Errorf("drain.bounded: a %s deadline held the process for %s", drainBudget, took) + } + for _, e := range run.events { + if e == "commit" || e == "save-offsets" { + return fmt.Errorf("drain.bounded: the sink never took the batch and the "+ + "pipeline did %s; the next start would skip those rows", list(run.events)) + } + } + return nil +} +``` + +`runPipeline` must not fail the test when `run.err` is set for this scenario; read it to see how `err` is captured (it returns `outcome.err`, so this should already hold). + +Add `bounded := verdict{invariant: drainBounded}` in `pipelineVerdicts`, run `checkDrainBounded` after `checkDrain`, and append `bounded` to the returned slice. + +- [ ] **Step 3: The manager check** + +In `manager.go`, change `New` to `func(t *testing.T, sink core.Sink, poll time.Duration, budget *core.DrainBudget) Manager`. Pass `core.NewDrainBudget(managerWait)` from `newManagerRun` for the existing checks so nothing changes for them. + +Add `managerDrainBounded = "manager.drain.bounded"` to the constants. The pipeline file already defines `drainBounded`, `drainBudget` and `checkDrainBounded` in this package, so the manager's names differ: + +```go +// checkManagerDrainBounded cancels Start against a sink that never answers +// and holds that it returns inside the deadline with every window still in +// the table. +func checkManagerDrainBounded(t *testing.T, s ManagerSubject) error { + t.Helper() + s.Seed(t, seededWindows) + rec := &Recorder{} + sink := newRecordingSink(rec, nil, noop.NewMeterProvider()) + sink.hang = true + budget := core.NewDrainBudget(drainBudget) + defer budget.Stop() + m := s.New(t, sink.counted, time.Hour, budget) + + ctx, cancel := context.WithCancel(context.Background()) + done := make(chan error, 1) + go func() { done <- m.Start(ctx) }() + cancel() + + select { + case err := <-done: + if err == nil { + return fmt.Errorf("the sink never answered the final poll and Start returned nil") + } + case <-time.After(managerWait): + return fmt.Errorf("a %s drain deadline held the final poll for %s", drainBudget, managerWait) + } + if left := s.Remaining(t); left != seededWindows { + return fmt.Errorf("the final poll ran out of time and %d of %d windows are gone "+ + "from the state table", seededWindows-left, seededWindows) + } + return nil +} +``` + +Add `bounded := verdict{invariant: managerDrainBounded}` to `managerVerdicts`, run `checkManagerDrainBounded`, and append it to the returned slice. In `internal/managers/conformance_test.go`, add the `budget` parameter and `WithDrainBudget(budget)`. + +- [ ] **Step 4: Run the harness and the registries** + +Run: `cd $S/sqlflow-161 && go test -short -race ./internal/conformance/ ./internal/sinks/ ./internal/managers/ ./internal/coverage/ && uv run pytest tests/tooling -q && make coverage-page` +Expected: PASS. Commit the regenerated `docs/coverage/matrix.md` if it changed. + +- [ ] **Step 5: Commit** + +```bash +git add internal/conformance internal/managers docs/coverage +git commit -m "conformance: a drain finishes inside its deadline, for the loop and for the manager" +``` + +--- + +### Task 10: Release test for the health endpoint, changelog, PR + +**Files:** +- Modify: `tests/release/test_image.py` +- Modify: `CHANGELOG.md` + +- [ ] **Step 1: Add the constant and the test** + +After `EXIT_SINK_UNREACHABLE = 12` add `EXIT_DRAIN_INCOMPLETE = 15`. Read how `TERMINAL_EXITS` is built and leave 15 out of it. + +Copy `test_turbostats_endpoint_serves_the_bundle` as: + +```python +@pytest.mark.covers("lifecycle.health") +def test_lifecycle_health_reports_healthy_once_committed(image, stack): + """The shipped image answers /healthz with the four-state body. + + A pipeline that has consumed nothing is starting. After the first idle + tick commits, it is healthy. Both answer 200: neither is a reason for a + supervisor to restart it. + """ + topic = f"healthz-{int(time.time())}" + + with container_writable_dir() as state_dir: + container = DockerContainer(image) \ + .with_volume_mapping(settings.DEV_DIR, "/tmp/conf") \ + .with_volume_mapping(state_dir, "/state", "rw") \ + .with_env("SQLFLOW_KAFKA_BROKERS", "kafka:9092") \ + .with_env("SQLFLOW_STATE_PATH", "/state/state.db") \ + .with_env("SQLFLOW_TOPIC", topic) \ + .with_env("SQLFLOW_GROUP_ID", topic) \ + .with_exposed_ports(8000) \ + .with_network(stack.network) \ + .with_command("run /tmp/conf/config/examples/kafka.stateful.window.yml") + container.start() + try: + wait_for_logs(container, "consumer loop starting", timeout=90) + port = container.get_exposed_port(8000) + first = requests.get(f"http://localhost:{port}/healthz", timeout=10) + # The example's flush interval is 30s; the idle tick after it is + # the first commit. + deadline = time.time() + 90 + body = first.json() + while body["status"] == "starting" and time.time() < deadline: + time.sleep(2) + body = requests.get(f"http://localhost:{port}/healthz", timeout=10).json() + finally: + container.stop() + + assert first.status_code == 200 + assert first.json()["status"] in ("starting", "healthy") + assert body["status"] == "healthy", body +``` + +Check the example's `flush_interval_seconds` and set the polling deadline to three times it. + +- [ ] **Step 2: Changelog** + +Find the most recent version heading in `CHANGELOG.md`. If there is an unreleased section, add there; otherwise add `## Unreleased` above the newest heading with: + +```markdown +## Unreleased + +### Added +- `pipeline.drain_deadline_seconds` bounds the whole shutdown: the final + batch, the managers' final poll and the state syncs share one deadline, + 30 seconds by default. When it passes the process exits 15 + (`system.lifecycle.drain_incomplete`); nothing unwritten was committed and + the next start replays it. +- `/healthz` reports `starting`, `healthy`, `degraded` or `failed` with a + `reason`. `degraded` means a sink retry ladder is running or the loop + recorded an error inside the last flush interval. `failed` is HTTP 503; the + other three are 200. The former `ok` and `stuck` bodies are `healthy` and + `failed`. +- `sqlflow validate` warns when a sink's `retry.deadline_seconds` is longer + than the drain deadline. +``` + +- [ ] **Step 3: Run everything local, push, open the PR** + +Run: `cd $S/sqlflow-161 && make test-go` +Expected: PASS. + +```bash +git add tests/release/test_image.py CHANGELOG.md +git commit -m "release: /healthz answers healthy from the image" +git push -u origin feat/process-contract +gh pr create --title "Process contract: a bounded drain that exits 15, and a four-state health endpoint" --body-file - <<'EOF' +Closes #161. + +Design: docs/superpowers/specs/2026-09-12-process-contract-design.md + +- `pipeline.drain_deadline_seconds`, default 30, bounds the whole shutdown through one `core.DrainBudget` shared by the turbine, the managers and run's state syncs. When it passes the process exits 15 with `system.lifecycle.drain_incomplete`. Nothing unwritten was committed. +- `/healthz` reports `starting`, `healthy`, `degraded` or `failed` with a `reason`. The HTTP codes for the two previous states do not change. +- `lifecycle.drain.bounded` is proven by the harness and enforced. `manager.drain.bounded` is added and enforced. +- `sqlflow validate` warns when a retry ladder can outlive the drain. + +Exit codes, the config-error terminal exit and the SIGTERM drain were already on main; the spec's first table says what shipped when. +EOF +``` + +- [ ] **Step 4: Coverage status from CI** + +After CI's first run on the PR: `gh run list --branch feat/process-contract --limit 1`, then `gh run download -n report-unit -n report-integration -n report-release`, `make coverage-write`, commit `docs/coverage/status` and `docs/coverage/matrix.md` as `coverage: status from CI run `, push. Repeat if `coverage-check` fails on a stale file after a rebase. + +--- + +### Task 11: Site docs + +**Files:** +- Create: `src/content/docs/sqlflow/operations/running-in-production.md` +- Modify: `src/content/docs/sqlflow/introduction/configuration.md` +- Modify: `src/content/docs/sqlflow/operations/handling-errors.md` +- Modify: `tests/build.test.ts` + +Work in `/Users/danielmican/code/github.com/turbolytics/turbolytics.io` on `git checkout -b docs/process-contract main`. Do not stage the dirty `tumbling-window-postgres.md`. + +- [ ] **Step 1: Add the route to the build test** + +In `tests/build.test.ts`, after `'docs/sqlflow/operations/handling-errors/index.html',` add `'docs/sqlflow/operations/running-in-production/index.html',`. Run `npm test` and confirm it fails on the missing route. + +- [ ] **Step 2: Write the page** + +```markdown +--- +title: "Running in Production" +order: 2 +--- + +sqlflow is one process with one config file. A supervisor starts it, reads its exit code when it stops, and polls one HTTP endpoint while it runs. This page documents those three contracts. + +## Exit codes + +The exit code tells the supervisor whether to restart. It is a projection of the [error code](/docs/sqlflow/operations/handling-errors) the process logged: a code in the `user` class exits 10, and the system codes map to the rest. + +| Exit | Meaning | Restart | +|------|---------|---------| +| 0 | Clean stop, including a drain on SIGTERM. | No | +| 1 | A failure sqlflow could not classify. | Yes | +| 10 | A user error: config, SQL, credentials, data. It fails the same way every time. | No | +| 11 | The source refused a connection or stopped answering. | Yes | +| 12 | The sink refused a connection or stopped answering after the retry ladder. | Yes | +| 13 | A declared resource limit was exceeded. | Yes | +| 14 | The state file exists but cannot be read. Preserve it and start from a new path. | No | +| 15 | The drain deadline passed with rows unwritten. Nothing was lost; the next start replays them. | Yes | + +2 is cobra's usage error and is never a pipeline failure. + +A supervisor that restarts on 10 or 14 loops forever into the same failure. Kubernetes has no per-code policy, so set `restartPolicy: Always` and alert on `CrashLoopBackOff`; systemd can express it directly: + +```ini +[Service] +Restart=on-failure +RestartPreventExitStatus=10 14 +``` + +## Health + +Every `sqlflow run` serves `GET /healthz` on port 8000. The body has one `status` field and, when the status is not `healthy`, a `reason`. + +| status | HTTP | Meaning | +|--------|------|---------| +| `starting` | 200 | No commit yet, inside the first three flush intervals. | +| `healthy` | 200 | A commit inside the last three intervals, no retry running, no error in the last interval. | +| `degraded` | 200 | A sink's retry ladder is running, or the pipeline recorded an error inside the last flush interval. | +| `failed` | 503 | No commit for three intervals, or the pipeline has failed and is stopping. | + +200 means do not restart. 503 means restart, or let the process exit. + +```bash +curl -s localhost:8000/healthz +{"status":"degraded","reason":"sink clickhouse is retrying, attempt 2","commit_age_seconds":4,"interval_seconds":30} +``` + +The commit clock moves on every batch and on every idle tick, so a topic that delivers nothing for an hour is `healthy`. That is deliberate: a pipeline on a trickle looks dead to anything watching message counts. + +A Kubernetes liveness probe: + +```yaml +livenessProbe: + httpGet: + path: /healthz + port: 8000 + periodSeconds: 30 + failureThreshold: 3 +``` + +`GET /stats` on the same port carries the raw ages and, for a pipeline with a state path, the state file's size and row counts. + +## Stopping + +SIGTERM starts a drain. The pipeline writes the batch it was holding, runs each table manager's final poll so windows that closed during the last interval are published, commits state, and exits 0. + +`pipeline.drain_deadline_seconds` bounds the whole drain. The default is 30 seconds, which is also Kubernetes' default `terminationGracePeriodSeconds`. If the deadline passes, the process exits 15. The batch it could not write was never committed, so the next start replays it. Set the deadline below the supervisor's grace period, or the supervisor's SIGKILL lands first and leaves no record. + +```yaml +pipeline: + drain_deadline_seconds: 20 +``` + +A second SIGTERM during the drain stops the process at once. + +`sqlflow validate` warns when a sink's `retry.deadline_seconds` is longer than the drain deadline, because a drain that hits a retrying sink then exits 15 before the ladder finishes. +``` + +Check the exact `/stats` fields against `metrics.go` before claiming them. Link `sqlflow validate` to the local development page if it documents the command. + +- [ ] **Step 3: Configuration page** + +In `introduction/configuration.md`, add `drain_deadline_seconds: ` after `flush_interval_seconds` in the pipeline block. After the batch size and flush interval section, add: + +```markdown +### Drain deadline + +`drain_deadline_seconds` bounds the shutdown after SIGTERM. It defaults to 30. [Running in production](/docs/sqlflow/operations/running-in-production#stopping) describes what happens when it passes. +``` + +In the every-option listing, add the key with its comment after `flush_interval_seconds`, matching the regenerated `config example` golden from Task 4. + +- [ ] **Step 4: Handling errors page** + +Change the RAISE bullet to link the new page: `A malformed message exits \`10\`; [Running in production](/docs/sqlflow/operations/running-in-production#exit-codes) lists every code.` Delete the paragraph starting "One case sits on the wrong side of that line" through the closing "Read the wrapped message" sentence, and replace it with: `A value the sink's driver cannot encode is a user error and is not retried. The error names the column and the value.` + +- [ ] **Step 5: Build, test, commit, push, PR** + +```bash +npm test +git add src/content/docs/sqlflow/operations/running-in-production.md src/content/docs/sqlflow/introduction/configuration.md src/content/docs/sqlflow/operations/handling-errors.md tests/build.test.ts +git commit -m "docs: running in production, the exit codes, the health states and the drain deadline" +git push -u origin docs/process-contract +gh pr create --title "docs: running in production" --body "Documents exit codes, the four /healthz states and pipeline.drain_deadline_seconds from sql-flow #161. Merge after the sql-flow PR ships in a release, and pin the version note at the bottom of the page to that tag." +``` + +Hold the merge until the sql-flow change is released. The user runs releases by hand. diff --git a/docs/superpowers/specs/2026-09-12-process-contract-design.md b/docs/superpowers/specs/2026-09-12-process-contract-design.md new file mode 100644 index 00000000..5d74bb40 --- /dev/null +++ b/docs/superpowers/specs/2026-09-12-process-contract-design.md @@ -0,0 +1,295 @@ +# Process contract: a bounded drain and a health endpoint with four states + +Issue #161. Verified against `main` at be9412c on 2026-09-12. + +## What the issue asked for, and what already shipped + +| Scope item | State on main | +| --- | --- | +| Documented exit codes by failure class | Done. `errs.ExitCode` maps the taxonomy to 0, 1, 10 to 14. `errs.Retryable` says which a supervisor may restart. Covered by `lifecycle.exit_codes` at unit and release. | +| A config error exits with a terminal code | Done. Class `user` exits 10, `Retryable(10)` is false. | +| Config from file and env, no writes outside the working directory | Done. | +| SIGTERM drains | Done in #159. The final batch flushes through `context.WithoutCancel`. `lifecycle.drain.on_cancel` is enforced. | +| A configurable drain deadline with a distinct exit code | Not done. The drain runs on `context.Background`. Only the sink retry ladder's own deadline bounds it, and a sink that blocks inside one attempt is not bounded at all. `lifecycle.drain.bounded` is `tracked_by: "#161"` with no evidence. | +| A health endpoint with starting, healthy, degraded and failed | Half done. `/healthz` on `:8000` answers `ok` or `stuck`. Nothing distinguishes a pipeline before its first commit, a pipeline whose sink is retrying, or a pipeline that has failed and is on its way out. | + +This design covers the last two rows. Nothing else in the issue changes. + +## The drain deadline + +### The problem + +A supervisor gives a process a fixed time to stop. Kubernetes calls it +`terminationGracePeriodSeconds` and sends SIGKILL when it passes. Today +sqlflow's shutdown has no bound of its own, so the operator cannot know +whether a stop finished, and a SIGKILL that lands mid-drain leaves no record +that the tail of the stream was not written. + +The shutdown does four things after the signal, all on `context.Background`: + +1. The turbine flushes the buffered batch and commits (`ConsumeLoop`, the + `ctx.Done` branch). +2. Run syncs state so the managers' final poll sees a fresh clock. +3. Each manager polls once more and publishes the windows that closed. +4. Run syncs state again so those deletes are durable. + +### The change + +One budget for the whole shutdown, started when the signal arrives. + +`core.DrainBudget` holds one deadline. Its `Context()` starts the clock on +the first call and returns the same context to every caller after that, so +the turbine's final batch, both state syncs and the managers' final poll +spend the same seconds. `Exceeded()` reports whether the deadline passed. + +```go +type DrainBudget struct { + deadline time.Duration + mu sync.Mutex + ctx context.Context + cancel context.CancelFunc +} + +func NewDrainBudget(deadline time.Duration) *DrainBudget +func (b *DrainBudget) Context() context.Context +func (b *DrainBudget) Exceeded() bool +func (b *DrainBudget) Stop() +``` + +The turbine takes `core.WithDrainBudget(b)`. Every batch runs on a context +that is not cancelled when the run is: it ends when the budget's deadline +passes after the cancel. So a SIGTERM that lands during a flush lets that +flush finish inside the deadline, and the drain of whatever is still buffered +runs on the same clock. A turbine built without a budget gets +`core.DefaultDrainDeadline`, thirty seconds, so a caller that does not care +still gets a bound. + +The manager takes `managers.WithDrainBudget(b)`. Its final poll runs on +`b.Context()` instead of `context.Background`. + +Run builds the budget from config, hands it to the turbine and every manager, +and runs its two state syncs on `b.Context()`. + +### When the deadline passes + +The batch context ends. The retry ladder stops on a cancelled context and +returns the sink's error, and a sink blocked inside one attempt returns when +its client honours the context. DuckDB through the ADBC driver manager +ignores the context entirely, so a statement or commit already in flight +there runs to completion; the deadline bounds the sink, not DuckDB. Either +way: + +- The batch's transaction rolls back. Offsets that were committed stay + committed. The rows the drain could not write replay on the next start, + which is the same at-least-once outcome as a crash. +- The failure is classified as `system.lifecycle.drain_incomplete`. Run + returns it, and the process exits `15`. + +The classification happens in the turbine, which is the only place that +knows the drain was in progress: when a batch fails and the budget's deadline +has passed, the error is wrapped with the new code. The +managers' final poll and the state syncs run inside run's deferred block, so +run checks `b.Exceeded()` after that block and returns the coded error when +the loop itself returned nil. + +A second SIGTERM during the drain still kills the process at once. #159 +restores default signal handling before the drain starts, and that stays. + +### Exit code 15 + +```go +// ExitDrainIncomplete marks a stop that ran out of time. Retryable: nothing +// was lost, because nothing unwritten was committed, and the next start +// replays it. The code exists so an operator can see that the tail of the +// stream was replayed rather than written. +ExitDrainIncomplete = 15 +``` + +`Retryable(15)` is true. The taxonomy gains one code in a new domain: + +| Code | Summary | Action | +| --- | --- | --- | +| `system.lifecycle.drain_incomplete` | The drain deadline passed before the buffered batch or the closed windows were written. | Nothing is lost: what was not written was not committed, and the next start replays it. Raise `pipeline.drain_deadline_seconds` if the sink needs longer, or check the sink. | + +`exitCodes` gains the entry. The golden file gains the line. The registry is +append-only, so this is an addition and nothing moves. + +### Configuration + +```yaml +pipeline: + drain_deadline_seconds: 30 # default 30, minimum 1 +``` + +The schema declares it as an integer with a minimum of 1. `flushIntervalFor` +has a sibling, `drainDeadlineFor`, that turns absent, zero and negative into +the default. + +`sqlflow validate` warns when the drain deadline is shorter than any sink's +`retry.deadline_seconds`, counting the pipeline sink, the DLQ sink and every +manager sink. A short drain deadline is a legitimate choice, so it is a +warning: the operator is told that a drain which hits a retrying sink exits +15 before the ladder finishes. The check is `pipeline.drain_deadline` and it +reads the rendered config, which the schema check has already parsed. + +### Evidence + +`lifecycle.drain.bounded` loses `tracked_by` and gains `enforced: true`. The +pipeline harness proves it with a seventh verdict: the recording sink gets a +`hang` flag that makes `Flush` block until its context ends, the run uses a +budget of a few hundred milliseconds, and the check holds that + +- `ConsumeLoop` returns inside a bound several times the budget, +- the error's code is `system.lifecycle.drain_incomplete`, +- the events end in `flush-failed` with no `commit` after it, +- the rows the sink delivered are zero. + +The manager gets the same claim as `manager.drain.bounded`, family +`lifecycle`, class `liveness`, `applies_to: manager`, enforced. The manager +harness proves it with a hanging sink and a cancelled `Start`: `Start` +returns inside the bound with an error, and `Remaining` still holds every +seeded window. + +`internal/cli/exit_test.go` gains a case for the mapping, and the coverage +registry tests keep the invariant count and kind set honest. + +## Health + +### The problem + +`/healthz` has two states, and both are about one signal, the commit clock. +An operator asking "should I restart this" gets the right answer from it. An +operator asking "is it doing what I deployed" does not: a pipeline whose sink +is on its third retry, a pipeline that has not committed once since it +started, and a pipeline that has failed and is draining all answer `ok`. + +### The change + +One endpoint, one `status` field, four values, and a `reason` that says why. + +| status | HTTP | when | +| --- | --- | --- | +| `starting` | 200 | No commit yet, and the server started less than three flush intervals ago. | +| `healthy` | 200 | A commit inside the last three intervals, no retry in progress, no error in the last interval. | +| `degraded` | 200 | A sink's retry ladder is in progress, or the loop recorded an error inside the last flush interval. | +| `failed` | 503 | No commit for three intervals. Or the loop returned an error, a manager stopped, or the drain deadline passed, and the process is on its way out. | + +200 means "do not restart". 503 means "restart, or let it exit". Today's +`stuck` becomes `failed` with `reason: "no commit for 91s"`. The HTTP codes +for the two existing states do not change, so a liveness probe written +against `ok` and `stuck` keeps behaving; only the body's `status` string +changes. + +Rules are evaluated in this order and the first match wins: a recorded +failure, then the commit age, then a retry in progress, then a recent error, +then no commit yet, then healthy. + +```json +{"status":"degraded","reason":"sink clickhouse is retrying, attempt 2","commit_age_seconds":4.2} +{"status":"failed","reason":"[system.sink.write_failed] sink rejected the batch: ...","commit_age_seconds":12.0} +``` + +### Where the signals come from + +`core.Progress` gains two fields the turbine already knows: + +```go +type Progress struct { + LastArrival time.Time + LastCommit time.Time + LastError time.Time + Messages int64 + Errors int64 +} +``` + +`recordError` stamps `LastError` and increments `Errors` under the lock. The +progress table on disk does not change; these two fields are in-memory only, +because they describe this process rather than the durable state. + +Retry in progress comes from the ladder. `retrying` already calls `onRetry` +per failed attempt. It gains `onSettle`, called when `Flush` returns after at +least one retry, whether it succeeded or gave up. `sinks.New` takes a new +option: + +```go +// RetryEvents is told when a sink's retry ladder is running. +type RetryEvents struct { + Retry func(sinkType string, attempt int, err error) + Settle func(sinkType string) +} + +func WithRetryEvents(e RetryEvents) Option +``` + +The existing counter stays wired; the option's callbacks run beside it. + +`internal/cli/run/health.go` holds the state the endpoint reads: + +```go +type health struct { + mu sync.Mutex + failure error + retrying map[string]int // sink type -> attempt, present while a ladder runs +} + +func (h *health) Fail(err error) +func (h *health) Retry(sinkType string, attempt int, err error) +func (h *health) Settle(sinkType string) +func (h *health) Snapshot() (failure error, retrying map[string]int) +``` + +Run calls `Fail` when `ConsumeLoop` returns an error, when a manager's cause +fires, and when the drain budget is exceeded. It passes `Retry` and `Settle` +to every `sinks.New` call: the pipeline sink, the DLQ sink and each manager +sink. + +`newHTTPMux` takes a `healthFunc func() healthSnapshot` alongside the +progress function. The snapshot bundles the failure and the retrying map; +the progress and its ages come from the existing `progressFunc`. The status +rules live in one pure function, +`healthStatus(snapshot, interval) (status, reason string, code int)`, so the +table above is one test. + +### What does not change + +`/stats` keeps its shape and gains the two new progress fields under +`progress`. `/metrics` and `/turbostats/v1` do not change. The endpoint stays +absent when there is no progress source, as today. + +## Documentation + +On turbolytics.io: + +- New page `operations/running-in-production.md`, order 2. Sections: exit + codes (the table with a retryable column), the health endpoint (the four + states, a curl example, a Kubernetes liveness probe), stopping a pipeline + (SIGTERM, the drain, `drain_deadline_seconds`, exit 15). +- `introduction/configuration.md` adds `drain_deadline_seconds` to the + pipeline section and to the every-option listing. +- `operations/handling-errors.md` links the new page from the RAISE bullet + that mentions exit `10`, and drops the paragraph that says an encode + failure is retried. #269 fixed that after the paragraph was written. + +In sql-flow: `CHANGELOG.md` gains entries for the deadline, the exit code and +the health states. The tumbling window docs on the site already say a refused +publish stops the process, from #270. + +## Coverage + +- `docs/coverage/invariants.yml`: `lifecycle.drain.bounded` enforced, no + `tracked_by`; `manager.drain.bounded` added. +- `docs/coverage/features.yml`: `lifecycle.health`, "The health endpoint + reports starting, healthy, degraded and failed", requires `[unit, + release]`. The release test reads `/healthz` from the image and holds that + a running pipeline answers `healthy` with HTTP 200. +- Status files are regenerated from CI's report artifacts after the PR's + first run, never locally. + +## Out of scope + +- A readiness endpoint separate from liveness. One endpoint with a `status` + string serves both, and nothing routes traffic to a pipeline. +- Health for the Python engine. +- Bounding the start. A source or sink that never answers during `Start` is + #268's problem, and the probe already fails the start once for a sink. diff --git a/internal/cli/exit_test.go b/internal/cli/exit_test.go index 888548e4..2ca83c49 100644 --- a/internal/cli/exit_test.go +++ b/internal/cli/exit_test.go @@ -129,3 +129,29 @@ func TestLifecycleExitCodes_UsageErrorStillPrintsUsage(t *testing.T) { t.Errorf("a usage error lost its usage text:\n%s", output) } } + +// A drain that ran out of time exits 15 through cobra, and a supervisor may +// restart it: nothing unwritten was committed. The mapping is errs' test; +// this one holds that the code survives the command boundary, the way the +// corrupt state file's does. +func TestLifecycleExitCodes_DrainIncompleteSurvivesCobra(t *testing.T) { + coverage.Covers(t, "lifecycle.exit_codes") + root := NewRootCommand() + root.AddCommand(&cobra.Command{ + Use: "drain-fixture", + RunE: func(cmd *cobra.Command, args []string) error { + return errs.New(errs.CodeDrainIncomplete, "drain deadline 30s reached") + }, + }) + root.SetArgs([]string{"drain-fixture"}) + var out bytes.Buffer + root.SetOut(&out) + root.SetErr(&out) + + code := execute(root) + + assert.Equal(t, errs.ExitDrainIncomplete, code) + assert.That(t, errs.Retryable(code)) + assert.That(t, strings.Contains(out.String(), string(errs.CodeDrainIncomplete))) + assert.That(t, !strings.Contains(out.String(), "Flags:")) +} diff --git a/internal/cli/run/flush_interval_test.go b/internal/cli/run/flush_interval_test.go index ff615c49..558f0591 100644 --- a/internal/cli/run/flush_interval_test.go +++ b/internal/cli/run/flush_interval_test.go @@ -4,6 +4,7 @@ import ( "testing" "time" + "github.com/turbolytics/sql-flow/internal/core" "github.com/turbolytics/sql-flow/internal/coverage" "github.com/zeebo/assert" ) @@ -20,3 +21,12 @@ func TestCliInvocation_FlushIntervalNeverZero(t *testing.T) { assert.Equal(t, 45*time.Second, flushIntervalFor(45)) assert.Equal(t, time.Second, flushIntervalFor(1)) } + +// The drain deadline resolves the way the flush interval does. A config that +// omits it, or writes a nonsense value past the schema, still gets a bound. +func TestLifecycleDrain_DeadlineDefaultsWhenAbsent(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + assert.Equal(t, core.DefaultDrainDeadline, drainDeadlineFor(0)) + assert.Equal(t, core.DefaultDrainDeadline, drainDeadlineFor(-5)) + assert.Equal(t, 45*time.Second, drainDeadlineFor(45)) +} diff --git a/internal/cli/run/health.go b/internal/cli/run/health.go new file mode 100644 index 00000000..e9226f82 --- /dev/null +++ b/internal/cli/run/health.go @@ -0,0 +1,118 @@ +package run + +import ( + "fmt" + "net/http" + "sort" + "sync" + "time" + + "github.com/turbolytics/sql-flow/internal/core" +) + +// health is what the process knows about itself that the progress snapshot +// does not: a failure that has stopped the loop, and the sinks whose retry +// ladders are running, keyed the way sinks.RetryEvents names them, role/type. +type health struct { + mu sync.Mutex + failure error + retrying map[string]int +} + +func newHealth() *health { + return &health{retrying: map[string]int{}} +} + +// Fail records the failure that is stopping the process. The first one is +// kept: a drain that then runs out of time is a consequence, and the endpoint +// should name the cause. +func (h *health) Fail(err error) { + if err == nil { + return + } + h.mu.Lock() + defer h.mu.Unlock() + if h.failure == nil { + h.failure = err + } +} + +// Retry records a ladder attempt in flight for one sink. It matches +// sinks.RetryEvents.Retry. +func (h *health) Retry(sink string, attempt int, _ error) { + h.mu.Lock() + defer h.mu.Unlock() + h.retrying[sink] = attempt +} + +// Settle clears the ladder for one sink. It matches sinks.RetryEvents.Settle. +func (h *health) Settle(sink string) { + h.mu.Lock() + defer h.mu.Unlock() + delete(h.retrying, sink) +} + +// healthSnapshot is one read of health. The map is a copy, so the status +// function never races a ladder. +type healthSnapshot struct { + failure error + retrying map[string]int +} + +// Snapshot copies the current state out from under the lock. +func (h *health) Snapshot() healthSnapshot { + h.mu.Lock() + defer h.mu.Unlock() + out := healthSnapshot{ + failure: h.failure, + retrying: make(map[string]int, len(h.retrying)), + } + for sink, attempt := range h.retrying { + out.retrying[sink] = attempt + } + return out +} + +// healthFunc reads the process's health. A mux built without one reports on +// progress alone. +type healthFunc func() healthSnapshot + +// healthStatus is the table behind /healthz. The first matching rule wins. +// +// 200 means "do not restart" and 503 means "restart, or let it exit". A +// retrying sink and a recent error both answer 200: restarting a pipeline +// whose sink is on its second attempt turns a blip into a cold start and a +// rebalance, which is the cost the retry ladder exists to avoid. +// +// commitAge is measured from when the server started until the first commit, +// so a pipeline that never commits becomes failed once the grace runs out. +func healthStatus(p core.Progress, commitAge float64, snap healthSnapshot, + interval time.Duration, now time.Time) (status, reason string, httpCode int) { + + if snap.failure != nil { + return "failed", snap.failure.Error(), http.StatusServiceUnavailable + } + if commitAge > float64(stuckIntervals)*interval.Seconds() { + return "failed", fmt.Sprintf("no commit for %.0fs", commitAge), + http.StatusServiceUnavailable + } + if len(snap.retrying) > 0 { + // Named in key order, so the reason is stable between scrapes while + // two ladders run. + names := make([]string, 0, len(snap.retrying)) + for sink := range snap.retrying { + names = append(names, sink) + } + sort.Strings(names) + return "degraded", fmt.Sprintf("sink %s is retrying, attempt %d", + names[0], snap.retrying[names[0]]), http.StatusOK + } + if !p.LastError.IsZero() && now.Sub(p.LastError) <= interval { + return "degraded", fmt.Sprintf("%d errors recorded, last %.0fs ago", + p.Errors, now.Sub(p.LastError).Seconds()), http.StatusOK + } + if p.LastCommit.IsZero() { + return "starting", "no commit yet", http.StatusOK + } + return "healthy", "", http.StatusOK +} diff --git a/internal/cli/run/health_status_test.go b/internal/cli/run/health_status_test.go new file mode 100644 index 00000000..237d8ba1 --- /dev/null +++ b/internal/cli/run/health_status_test.go @@ -0,0 +1,110 @@ +package run + +import ( + "errors" + "net/http" + "testing" + "time" + + "github.com/turbolytics/sql-flow/internal/core" + "github.com/turbolytics/sql-flow/internal/coverage" + "github.com/zeebo/assert" +) + +// The four states, one table. The first matching rule wins: a recorded +// failure beats everything, then the commit clock, then a retry in flight, +// then a recent error, then a pipeline that has not committed yet. +func TestLifecycleHealth_StatusTable(t *testing.T) { + coverage.Covers(t, "lifecycle.health") + now := time.Date(2026, 9, 12, 12, 0, 0, 0, time.UTC) + interval := 30 * time.Second + committed := now.Add(-10 * time.Second) + + cases := []struct { + name string + p core.Progress + commitAge float64 + snap healthSnapshot + status string + reason string + code int + }{ + {"healthy", core.Progress{LastCommit: committed}, 10, healthSnapshot{}, + "healthy", "", http.StatusOK}, + {"starting", core.Progress{}, 5, healthSnapshot{}, + "starting", "no commit yet", http.StatusOK}, + {"stuck is failed", core.Progress{LastCommit: committed}, 91, healthSnapshot{}, + "failed", "no commit for 91s", http.StatusServiceUnavailable}, + {"never committed past the grace", core.Progress{}, 120, healthSnapshot{}, + "failed", "no commit for 120s", http.StatusServiceUnavailable}, + {"retrying", core.Progress{LastCommit: committed}, 10, + healthSnapshot{retrying: map[string]int{"pipeline/clickhouse": 2}}, + "degraded", "sink pipeline/clickhouse is retrying, attempt 2", http.StatusOK}, + {"two sinks retrying names the first by key", core.Progress{LastCommit: committed}, 10, + healthSnapshot{retrying: map[string]int{"pipeline/iceberg": 1, "manager/clickhouse": 3}}, + "degraded", "sink manager/clickhouse is retrying, attempt 3", http.StatusOK}, + {"recent error", core.Progress{LastCommit: committed, LastError: now.Add(-5 * time.Second), Errors: 3}, + 10, healthSnapshot{}, + "degraded", "3 errors recorded, last 5s ago", http.StatusOK}, + {"an error older than an interval is history", core.Progress{LastCommit: committed, LastError: now.Add(-time.Hour), Errors: 3}, + 10, healthSnapshot{}, + "healthy", "", http.StatusOK}, + {"retrying before the first commit is degraded, not starting", core.Progress{}, 5, + healthSnapshot{retrying: map[string]int{"pipeline/clickhouse": 1}}, + "degraded", "sink pipeline/clickhouse is retrying, attempt 1", http.StatusOK}, + {"a failure beats a fresh commit", core.Progress{LastCommit: committed}, 10, + healthSnapshot{failure: errors.New("[system.sink.write_failed] rejected")}, + "failed", "[system.sink.write_failed] rejected", http.StatusServiceUnavailable}, + } + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + coverage.Covers(t, "lifecycle.health") + status, reason, code := healthStatus(c.p, c.commitAge, c.snap, interval, now) + assert.Equal(t, c.status, status) + assert.Equal(t, c.reason, reason) + assert.Equal(t, c.code, code) + }) + } +} + +// Fail keeps the first failure. A drain that then times out is a consequence, +// and the endpoint should name the cause. +func TestLifecycleHealth_FirstFailureIsKept(t *testing.T) { + coverage.Covers(t, "lifecycle.health") + h := newHealth() + h.Fail(nil) + assert.Nil(t, h.Snapshot().failure) + h.Fail(errors.New("first")) + h.Fail(errors.New("second")) + assert.Equal(t, "first", h.Snapshot().failure.Error()) +} + +// A retry is in flight from its first failed attempt until the ladder +// settles. The snapshot is a copy, so a reader cannot race the ladder. +func TestLifecycleHealth_RetryAndSettle(t *testing.T) { + coverage.Covers(t, "lifecycle.health") + h := newHealth() + h.Retry("pipeline/clickhouse", 1, errors.New("reset")) + h.Retry("pipeline/clickhouse", 2, errors.New("reset")) + + snap := h.Snapshot() + assert.Equal(t, 2, snap.retrying["pipeline/clickhouse"]) + + h.Settle("pipeline/clickhouse") + assert.Equal(t, 0, len(h.Snapshot().retrying)) + assert.Equal(t, 2, snap.retrying["pipeline/clickhouse"]) +} + +// The pipeline's sink and a manager's sink of the same type are two ladders. +// One settling leaves the other in flight. +func TestLifecycleHealth_TwoSinksOfOneTypeAreTwoLadders(t *testing.T) { + coverage.Covers(t, "lifecycle.health") + h := newHealth() + h.Retry("pipeline/clickhouse", 3, errors.New("reset")) + h.Retry("manager/clickhouse", 1, errors.New("reset")) + h.Settle("manager/clickhouse") + + snap := h.Snapshot() + assert.Equal(t, 1, len(snap.retrying)) + assert.Equal(t, 3, snap.retrying["pipeline/clickhouse"]) +} diff --git a/internal/cli/run/health_test.go b/internal/cli/run/health_test.go index 3861ac64..81769645 100644 --- a/internal/cli/run/health_test.go +++ b/internal/cli/run/health_test.go @@ -2,6 +2,7 @@ package run import ( "encoding/json" + "errors" "net/http" "net/http/httptest" "testing" @@ -15,9 +16,13 @@ import ( // Idle is healthy: the commit clock keeps moving while nothing arrives, and // that is the whole point. A pipeline on a trickle looks dead to anything // watching message counts, so the health check watches commits instead. -// Stuck is three intervals without one, and the body says how old it is. -func TestObservabilityMetrics_HealthzTellsIdleFromStuck(t *testing.T) { - coverage.Covers(t, "observability.metrics") +// Three intervals without one is failed, and the reason says how old it is. +// +// This endpoint answered "ok" and "stuck" before it had four states. The HTTP +// codes for those two did not change, so a probe written against them keeps +// working; only the status string in the body did. +func TestLifecycleHealth_HealthzTellsIdleFromStuck(t *testing.T) { + coverage.Covers(t, "lifecycle.health") clock := time.Date(2026, 9, 10, 12, 0, 0, 0, time.UTC) now := func() time.Time { return clock } p := core.Progress{ @@ -25,7 +30,7 @@ func TestObservabilityMetrics_HealthzTellsIdleFromStuck(t *testing.T) { LastCommit: clock.Add(-20 * time.Second), Messages: 42, } - mux := newHTTPMux(nil, nil, nil, func() core.Progress { return p }, 30*time.Second, now) + mux := newHTTPMux(nil, nil, nil, func() core.Progress { return p }, nil, 30*time.Second, now) srv := httptest.NewServer(mux) defer srv.Close() @@ -41,7 +46,9 @@ func TestObservabilityMetrics_HealthzTellsIdleFromStuck(t *testing.T) { // An hour with no message, a commit twenty seconds ago: healthy. code, body := get("/healthz") assert.Equal(t, http.StatusOK, code) - assert.Equal(t, "ok", body["status"]) + assert.Equal(t, "healthy", body["status"]) + _, hasReason := body["reason"] + assert.That(t, !hasReason) // /stats carries both ages, so a dashboard can show "quiet for an hour" // without calling that an outage. @@ -51,18 +58,20 @@ func TestObservabilityMetrics_HealthzTellsIdleFromStuck(t *testing.T) { assert.Equal(t, float64(3600), prog["arrival_age_seconds"]) assert.Equal(t, float64(20), prog["commit_age_seconds"]) - // Three intervals without a commit: stuck. + // Three intervals without a commit: failed. p.LastCommit = clock.Add(-91 * time.Second) code, body = get("/healthz") assert.Equal(t, http.StatusServiceUnavailable, code) - assert.Equal(t, "stuck", body["status"]) + assert.Equal(t, "failed", body["status"]) + assert.Equal(t, "no commit for 91s", body["reason"]) assert.Equal(t, float64(91), body["commit_age_seconds"]) // Nothing recorded yet, which is every pipeline for its first interval. - // Healthy, measured from when the server started, not from the epoch. + // Starting, measured from when the server started, not from the epoch. p = core.Progress{} code, body = get("/healthz") assert.Equal(t, http.StatusOK, code) + assert.Equal(t, "starting", body["status"]) assert.Equal(t, float64(0), body["commit_age_seconds"]) // A pipeline that never commits is stuck once the grace runs out, even @@ -70,14 +79,55 @@ func TestObservabilityMetrics_HealthzTellsIdleFromStuck(t *testing.T) { clock = clock.Add(2 * time.Minute) code, body = get("/healthz") assert.Equal(t, http.StatusServiceUnavailable, code) - assert.Equal(t, "stuck", body["status"]) + assert.Equal(t, "failed", body["status"]) +} + +// The endpoint reads the process's health as well as its progress. A failure +// run records turns a pipeline that committed a second ago into a 503 whose +// reason is the error, and a ladder in flight is degraded with a 200. +func TestLifecycleHealth_EndpointReportsFailuresAndRetries(t *testing.T) { + coverage.Covers(t, "lifecycle.health") + clock := time.Date(2026, 9, 12, 12, 0, 0, 0, time.UTC) + now := func() time.Time { return clock } + p := core.Progress{LastCommit: clock.Add(-time.Second)} + h := newHealth() + mux := newHTTPMux(nil, nil, nil, func() core.Progress { return p }, h.Snapshot, + 30*time.Second, now) + srv := httptest.NewServer(mux) + defer srv.Close() + + get := func() (int, map[string]any) { + resp, err := http.Get(srv.URL + "/healthz") + assert.NoError(t, err) + defer resp.Body.Close() + var body map[string]any + _ = json.NewDecoder(resp.Body).Decode(&body) + return resp.StatusCode, body + } + + h.Retry("pipeline/clickhouse", 2, errors.New("connection reset by peer")) + code, body := get() + assert.Equal(t, http.StatusOK, code) + assert.Equal(t, "degraded", body["status"]) + assert.Equal(t, "sink pipeline/clickhouse is retrying, attempt 2", body["reason"]) + + h.Settle("pipeline/clickhouse") + code, body = get() + assert.Equal(t, http.StatusOK, code) + assert.Equal(t, "healthy", body["status"]) + + h.Fail(errors.New("[system.sink.write_failed] rejected")) + code, body = get() + assert.Equal(t, http.StatusServiceUnavailable, code) + assert.Equal(t, "failed", body["status"]) + assert.Equal(t, "[system.sink.write_failed] rejected", body["reason"]) } // Without a progress source there is no health to report, and the endpoint // must not exist rather than answer "ok" for a pipeline it cannot see. func TestObservabilityMetrics_HealthzAbsentWithoutProgress(t *testing.T) { coverage.Covers(t, "observability.metrics") - mux := newHTTPMux(nil, nil, nil, nil, 30*time.Second, time.Now) + mux := newHTTPMux(nil, nil, nil, nil, nil, 30*time.Second, time.Now) srv := httptest.NewServer(mux) defer srv.Close() diff --git a/internal/cli/run/managers.go b/internal/cli/run/managers.go index 8a2cbfea..47d7dc4f 100644 --- a/internal/cli/run/managers.go +++ b/internal/cli/run/managers.go @@ -8,6 +8,7 @@ import ( "github.com/apache/arrow-adbc/go/adbc" "github.com/turbolytics/sql-flow/internal/config" + "github.com/turbolytics/sql-flow/internal/core" "github.com/turbolytics/sql-flow/internal/managers" "github.com/turbolytics/sql-flow/internal/sinks" "go.opentelemetry.io/otel/metric" @@ -23,6 +24,8 @@ func buildManagedTables( lock *sync.Mutex, l *zap.Logger, mp metric.MeterProvider, + budget *core.DrainBudget, + events sinks.RetryEvents, ) ([]*managers.Tumbling, error) { if conf.Tables == nil { return nil, nil @@ -40,7 +43,8 @@ func buildManagedTables( // counters on this sink, sink_rows_written would report zero for it. sink, err := sinks.New(ctx, table.Manager.Sink, conn, sinks.WithMeterProvider(mp), - sinks.WithSinkRole("manager")) + sinks.WithSinkRole("manager"), + sinks.WithRetryEvents(events)) if err != nil { return nil, fmt.Errorf("table %q manager sink: %w", table.Name, err) } @@ -54,8 +58,48 @@ func buildManagedTables( sink, lock, managers.WithLogger(l), + managers.WithDrainBudget(budget), )) } return built, nil } + +// managerGroup runs every table manager and keeps the first error any of +// them returned. run reads it after the shutdown, because a manager that +// fails while the loop is running cancels the run itself, and one that fails +// in its final poll has nobody left to tell: the loop has already returned. +// Before this, that second failure was logged and the process exited 0 with +// windows unpublished. +type managerGroup struct { + wg sync.WaitGroup + mu sync.Mutex + first error +} + +// start runs m until ctx ends. onFail is called with any error m returns, +// so the caller can cancel the run and mark the process failed. +func (g *managerGroup) start(ctx context.Context, m *managers.Tumbling, onFail func(error)) { + g.wg.Add(1) + go func() { + defer g.wg.Done() + err := m.Start(ctx) + if err == nil { + return + } + g.mu.Lock() + if g.first == nil { + g.first = err + } + g.mu.Unlock() + onFail(err) + }() +} + +// wait blocks until every manager has returned and reports the first error. +func (g *managerGroup) wait() error { + g.wg.Wait() + g.mu.Lock() + defer g.mu.Unlock() + return g.first +} diff --git a/internal/cli/run/managers_test.go b/internal/cli/run/managers_test.go new file mode 100644 index 00000000..eaddede4 --- /dev/null +++ b/internal/cli/run/managers_test.go @@ -0,0 +1,77 @@ +package run + +import ( + "context" + "errors" + "sync" + "testing" + "time" + + "github.com/apache/arrow-go/v18/arrow" + "github.com/turbolytics/sql-flow/internal/core" + "github.com/turbolytics/sql-flow/internal/coverage" + "github.com/turbolytics/sql-flow/internal/errs" + "github.com/turbolytics/sql-flow/internal/managers" + "github.com/zeebo/assert" +) + +// hangingSink blocks in Flush until its context ends. +type hangingSink struct{} + +func (hangingSink) WriteTable(context.Context, arrow.Table) error { return nil } +func (hangingSink) Flush(ctx context.Context) error { + <-ctx.Done() + return ctx.Err() +} + +// A manager whose final poll runs out of drain deadline reports it through +// the group, with the drain code, so run exits 15 rather than 0 with the +// window still in the table. The failure also reaches onFail, which is how +// /healthz learns of it. +func TestLifecycleDrain_AFailedFinalPollReachesTheRun(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + conn := rowsTestConn(t) + rowsTestExec(t, conn, "CREATE TABLE agg (id BIGINT)") + rowsTestExec(t, conn, "INSERT INTO agg VALUES (1), (2), (3)") + + budget := core.NewDrainBudget(200 * time.Millisecond) + defer budget.Stop() + m := managers.NewTumbling(conn, "SELECT id FROM agg", "DELETE FROM agg", + time.Hour, hangingSink{}, &sync.Mutex{}, managers.WithDrainBudget(budget)) + + var ( + group managerGroup + mu sync.Mutex + failed []error + ) + ctx, cancel := context.WithCancel(context.Background()) + group.start(ctx, m, func(err error) { + mu.Lock() + failed = append(failed, err) + mu.Unlock() + }) + cancel() + err := group.wait() + + assert.Equal(t, errs.CodeDrainIncomplete, errs.CodeOf(err)) + mu.Lock() + defer mu.Unlock() + assert.Equal(t, 1, len(failed)) + assert.That(t, errors.Is(failed[0], err)) +} + +// A clean final poll reports nothing, so a clean stop stays exit 0. +func TestLifecycleDrain_ACleanFinalPollReportsNothing(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + conn := rowsTestConn(t) + rowsTestExec(t, conn, "CREATE TABLE agg (id BIGINT)") + + m := managers.NewTumbling(conn, "SELECT id FROM agg", "DELETE FROM agg", + time.Hour, hangingSink{}, &sync.Mutex{}) + + var group managerGroup + ctx, cancel := context.WithCancel(context.Background()) + group.start(ctx, m, func(err error) { t.Errorf("onFail called: %v", err) }) + cancel() + assert.NoError(t, group.wait()) +} diff --git a/internal/cli/run/metrics.go b/internal/cli/run/metrics.go index 13fe4ed4..65c019c2 100644 --- a/internal/cli/run/metrics.go +++ b/internal/cli/run/metrics.go @@ -49,7 +49,8 @@ const stuckIntervals = 3 // would answer with nothing is absent rather than half-working. func newHTTPMux(registry *prom.Registry, stats statsFunc, collect func(context.Context) (turbostats.Bundle, error), - progress progressFunc, interval time.Duration, now func() time.Time) *http.ServeMux { + progress progressFunc, health healthFunc, interval time.Duration, + now func() time.Time) *http.ServeMux { mux := http.NewServeMux() started := now() @@ -97,7 +98,9 @@ func newHTTPMux(registry *prom.Registry, stats statsFunc, out["progress"] = map[string]any{ "last_arrival": p.LastArrival, "last_commit": p.LastCommit, + "last_error": p.LastError, "messages": p.Messages, + "errors": p.Errors, "arrival_age_seconds": arrival, "commit_age_seconds": commit, } @@ -112,23 +115,24 @@ func newHTTPMux(registry *prom.Registry, stats statsFunc, if progress != nil { mux.HandleFunc("/healthz", func(w http.ResponseWriter, r *http.Request) { - _, _, commit := ages() - w.Header().Set("Content-Type", "application/json") - - if commit > float64(stuckIntervals)*interval.Seconds() { - w.WriteHeader(http.StatusServiceUnavailable) - _ = json.NewEncoder(w).Encode(map[string]any{ - "status": "stuck", - "commit_age_seconds": commit, - "interval_seconds": interval.Seconds(), - }) - return + p, _, commit := ages() + var snap healthSnapshot + if health != nil { + snap = health() } + status, reason, code := healthStatus(p, commit, snap, interval, now()) - _ = json.NewEncoder(w).Encode(map[string]any{ - "status": "ok", + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(code) + body := map[string]any{ + "status": status, "commit_age_seconds": commit, - }) + "interval_seconds": interval.Seconds(), + } + if reason != "" { + body["reason"] = reason + } + _ = json.NewEncoder(w).Encode(body) }) } @@ -150,7 +154,8 @@ func newHTTPMux(registry *prom.Registry, stats statsFunc, // nothing -- so there was nothing for a bundle to read. func newMeterProvider(exporter string, serveTurbostats bool, static turbostats.Static, l *zap.Logger, stats statsFunc, - progress progressFunc, interval time.Duration) (metric.MeterProvider, error) { + progress progressFunc, health healthFunc, + interval time.Duration) (metric.MeterProvider, error) { reader := sdkmetric.NewManualReader() opts := []sdkmetric.Option{sdkmetric.WithReader(reader)} @@ -183,7 +188,7 @@ func newMeterProvider(exporter string, serveTurbostats bool, return turbostats.Collect(ctx, static, reader, stats) } } - mux := newHTTPMux(registry, stats, collect, progress, interval, time.Now) + mux := newHTTPMux(registry, stats, collect, progress, health, interval, time.Now) go func() { routes := []string{} @@ -216,3 +221,13 @@ func flushIntervalFor(seconds int) time.Duration { } return 30 * time.Second } + +// drainDeadlineFor is the one place the drain deadline is decided. Absent, +// zero and negative all mean the default, for the same reason as the flush +// interval: a shutdown the config forgot to bound is still bounded. +func drainDeadlineFor(seconds int) time.Duration { + if seconds > 0 { + return time.Duration(seconds) * time.Second + } + return core.DefaultDrainDeadline +} diff --git a/internal/cli/run/metrics_test.go b/internal/cli/run/metrics_test.go index 097e3d48..ef1d06b7 100644 --- a/internal/cli/run/metrics_test.go +++ b/internal/cli/run/metrics_test.go @@ -38,7 +38,7 @@ func TestObservabilityMetrics_StatsHandler_ReportsState(t *testing.T) { Offsets: []core.OffsetStat{{Topic: "events", Partition: 0, Offset: 999, LeaderEpoch: 7}}, } - mux := newHTTPMux(nil, func() (*core.StateStats, error) { return want, nil }, nil, nil, 30*time.Second, time.Now) + mux := newHTTPMux(nil, func() (*core.StateStats, error) { return want, nil }, nil, nil, nil, 30*time.Second, time.Now) rec := httptest.NewRecorder() mux.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/stats", nil)) @@ -65,7 +65,7 @@ func TestObservabilityMetrics_StatsHandler_ReportsState(t *testing.T) { // endpoint stays useful for the counters even when nothing is durable. func TestObservabilityMetrics_StatsHandler_NullStateWithoutAStateDatabase(t *testing.T) { coverage.Covers(t, "observability.metrics") - mux := newHTTPMux(nil, func() (*core.StateStats, error) { return nil, nil }, nil, nil, 30*time.Second, time.Now) + mux := newHTTPMux(nil, func() (*core.StateStats, error) { return nil, nil }, nil, nil, nil, 30*time.Second, time.Now) rec := httptest.NewRecorder() mux.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/stats", nil)) @@ -83,7 +83,7 @@ func TestObservabilityMetrics_StatsHandler_ReportsCollectionFailure(t *testing.T coverage.Covers(t, "observability.metrics") mux := newHTTPMux(nil, func() (*core.StateStats, error) { return nil, errors.New("state database unreadable") - }, nil, nil, 30*time.Second, time.Now) + }, nil, nil, nil, 30*time.Second, time.Now) rec := httptest.NewRecorder() mux.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/stats", nil)) @@ -94,7 +94,7 @@ func TestObservabilityMetrics_StatsHandler_ReportsCollectionFailure(t *testing.T // endpoint must not be registered as a half-working route. func TestObservabilityMetrics_StatsHandler_AbsentWithoutAProvider(t *testing.T) { coverage.Covers(t, "observability.metrics") - mux := newHTTPMux(nil, nil, nil, nil, 30*time.Second, time.Now) + mux := newHTTPMux(nil, nil, nil, nil, nil, 30*time.Second, time.Now) rec := httptest.NewRecorder() mux.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/stats", nil)) @@ -320,7 +320,7 @@ func TestStateCommitLatencyUnitIsNameNeutral(t *testing.T) { // answers with nothing is worse than none. func TestObservabilityTurbostats_RouteAbsentWithoutACollector(t *testing.T) { coverage.Covers(t, "observability.turbostats") - mux := newHTTPMux(nil, nil, nil, nil, 30*time.Second, time.Now) + mux := newHTTPMux(nil, nil, nil, nil, nil, 30*time.Second, time.Now) rec := httptest.NewRecorder() mux.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/turbostats/v1", nil)) @@ -331,7 +331,7 @@ func TestObservabilityTurbostats_RouteServesTheBundle(t *testing.T) { coverage.Covers(t, "observability.turbostats") mux := newHTTPMux(nil, nil, func(context.Context) (turbostats.Bundle, error) { return turbostats.Bundle{V: turbostats.Version}, nil - }, nil, 30*time.Second, time.Now) + }, nil, nil, 30*time.Second, time.Now) rec := httptest.NewRecorder() mux.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/turbostats/v1", nil)) @@ -370,7 +370,7 @@ func TestObservabilityTurbostats_ManualReaderLeavesExportedNamesAlone(t *testing // nothing unless Prometheus was on. func TestObservabilityTurbostats_ProviderExistsWithoutAnExporter(t *testing.T) { coverage.Covers(t, "observability.turbostats") - mp, err := newMeterProvider("", false, turbostats.Static{}, zap.NewNop(), nil, nil, 30*time.Second) + mp, err := newMeterProvider("", false, turbostats.Static{}, zap.NewNop(), nil, nil, nil, 30*time.Second) assert.NoError(t, err) assert.That(t, mp != nil) @@ -381,6 +381,6 @@ func TestObservabilityTurbostats_ProviderExistsWithoutAnExporter(t *testing.T) { func TestObservabilityTurbostats_RejectsAnUnknownExporter(t *testing.T) { coverage.Covers(t, "observability.metrics") - _, err := newMeterProvider("statsd", false, turbostats.Static{}, zap.NewNop(), nil, nil, 30*time.Second) + _, err := newMeterProvider("statsd", false, turbostats.Static{}, zap.NewNop(), nil, nil, nil, 30*time.Second) assert.Error(t, err) } diff --git a/internal/cli/run/root.go b/internal/cli/run/root.go index 9d0e8af2..609ad04d 100644 --- a/internal/cli/run/root.go +++ b/internal/cli/run/root.go @@ -9,7 +9,6 @@ import ( "github.com/turbolytics/sql-flow/internal/duckdb" "github.com/turbolytics/sql-flow/internal/handlers" "github.com/turbolytics/sql-flow/internal/logging" - "github.com/turbolytics/sql-flow/internal/managers" "github.com/turbolytics/sql-flow/internal/sinks" "github.com/turbolytics/sql-flow/internal/sources" "go.uber.org/zap" @@ -39,6 +38,7 @@ func newErrorPolicies( conf *config.Conf, conn adbc.Connection, mp metric.MeterProvider, + events sinks.RetryEvents, ) (core.PipelineErrorPolicies, error) { var policies core.PipelineErrorPolicies @@ -62,7 +62,8 @@ func newErrorPolicies( // healthier the more records it rejects. dlqSink, err := sinks.New(ctx, *onError.DLQ, conn, sinks.WithMeterProvider(mp), - sinks.WithSinkRole("dlq")) + sinks.WithSinkRole("dlq"), + sinks.WithRetryEvents(events)) if err != nil { return policies, fmt.Errorf("pipeline.on_error dlq: %w", err) } @@ -89,7 +90,7 @@ func NewCommand() *cobra.Command { // Zero args for the -c form, one for the Python engine's positional // form. See resolveConfigPath. Args: cobra.MaximumNArgs(1), - RunE: func(cmd *cobra.Command, args []string) error { + RunE: func(cmd *cobra.Command, args []string) (runErr error) { logger, levelErr := logging.New() defer logger.Sync() l := logger.Named("sqlflow.run") @@ -223,6 +224,19 @@ func NewCommand() *cobra.Command { flushInterval := flushIntervalFor(conf.Pipeline.FlushIntervalSeconds) + // One deadline for the whole shutdown. Its clock starts when the + // first step of the drain asks for it, and the turbine's final + // batch, both state syncs and every manager's final poll spend + // it. A supervisor gives a stop one grace period, not four. + budget := core.NewDrainBudget(drainDeadlineFor(conf.Pipeline.DrainDeadlineSeconds)) + defer budget.Stop() + + // What /healthz knows that the progress snapshot does not: the + // failure stopping the process, and the sinks whose retry ladders + // are running. + hs := newHealth() + retryEvents := sinks.RetryEvents{Retry: hs.Retry, Settle: hs.Settle} + // State wiring. Everything below is skipped for a pipeline with no // state path, which then behaves exactly as it did before. var ( @@ -310,7 +324,7 @@ func NewCommand() *cobra.Command { } meterProvider, err := newMeterProvider(metricsExporter, serveTurbostats, static, l, - statsFn, progressFn, flushInterval) + statsFn, progressFn, hs.Snapshot, flushInterval) if err != nil { return err } @@ -357,7 +371,8 @@ func NewCommand() *cobra.Command { // its destination stops the start instead of waiting it out. sink, err := sinks.New(ctx, conf.Pipeline.Sink, conn, sinks.WithMeterProvider(meterProvider), - sinks.WithSinkRole(core.SinkRolePipeline)) + sinks.WithSinkRole(core.SinkRolePipeline), + sinks.WithRetryEvents(retryEvents)) if err != nil { return err } @@ -380,7 +395,7 @@ func NewCommand() *cobra.Command { }() } - errorPolicies, err := newErrorPolicies(ctx, conf, conn, meterProvider) + errorPolicies, err := newErrorPolicies(ctx, conf, conn, meterProvider, retryEvents) if err != nil { return err } @@ -396,11 +411,13 @@ func NewCommand() *cobra.Command { append([]core.TurbineOption{ core.WithTurbineLogger(l), core.WithMetrics(pipelineMetrics), + core.WithDrainBudget(budget), }, turbineOpts...)..., ) liveTurbine.Store(turbine) - managedTables, err := buildManagedTables(ctx, conf, conn, lock, l, meterProvider) + managedTables, err := buildManagedTables(ctx, conf, conn, lock, l, meterProvider, + budget, retryEvents) if err != nil { return err } @@ -419,34 +436,45 @@ func NewCommand() *cobra.Command { runCtx, failRun := context.WithCancelCause(ctx) defer failRun(nil) managerCtx, stopManagers := context.WithCancel(context.Background()) - var managerWG sync.WaitGroup + var group managerGroup for _, m := range managedTables { - managerWG.Add(1) - go func(m *managers.Tumbling) { - defer managerWG.Done() - if err := m.Start(managerCtx); err != nil { - l.Error("table manager stopped", zap.Error(err)) - failRun(err) - } - }(m) + group.start(managerCtx, m, func(err error) { + l.Error("table manager stopped", zap.Error(err)) + hs.Fail(err) + failRun(err) + }) } defer func() { + // Every step below spends the drain budget. On a stop that + // was not a signal, --max-msgs or a closed source, this starts + // the clock, and the steps finish in milliseconds. + drainCtx := budget.Context() // Close the open transaction first. The managers' final poll // runs on this connection, and its close predicate is // evaluated against the transaction's clock -- which is // frozen at the last commit until this runs. - if err := turbine.SyncState(context.Background()); err != nil { + if err := turbine.SyncState(drainCtx); err != nil { l.Error("failed to sync state before final poll", zap.Error(err)) } stopManagers() - managerWG.Wait() + managerErr := group.wait() // And again afterwards, so what that poll published is // actually deleted. Without this the delete is rolled back // when the connection closes, and every clean shutdown // guarantees a republished window on the next start. - if err := turbine.SyncState(context.Background()); err != nil { + if err := turbine.SyncState(drainCtx); err != nil { l.Error("failed to sync state after final poll", zap.Error(err)) } + // A manager whose final poll failed is a stop that did not + // finish, whatever the loop reported: its windows are still + // in the table, and the next start publishes them. The + // manager says why, and a poll the drain deadline ended + // carries the drain code. A failure during the run reached + // here through failRun already, and the loop's own error + // outranks this one. + if managerErr != nil && runErr == nil { + runErr = managerErr + } }() // Cancelled before the reader connection closes. Left running, a @@ -482,6 +510,7 @@ func NewCommand() *cobra.Command { return cause } if err != nil { + hs.Fail(err) l.Error("failed to consume loop", zap.Error(err)) return err } diff --git a/internal/cli/run/row_roles_test.go b/internal/cli/run/row_roles_test.go index 4f09b4d0..743dc2ac 100644 --- a/internal/cli/run/row_roles_test.go +++ b/internal/cli/run/row_roles_test.go @@ -13,6 +13,7 @@ import ( "github.com/turbolytics/sql-flow/internal/config" "github.com/turbolytics/sql-flow/internal/coverage" "github.com/turbolytics/sql-flow/internal/duckdb" + "github.com/turbolytics/sql-flow/internal/sinks" "github.com/zeebo/assert" sdkmetric "go.opentelemetry.io/otel/sdk/metric" "go.opentelemetry.io/otel/sdk/metric/metricdata" @@ -104,7 +105,7 @@ func TestDLQRowsCarryTheDLQRole(t *testing.T) { DLQ: &config.Sink{Type: "console"}, } - policies, err := newErrorPolicies(context.Background(), conf, nil, mp) + policies, err := newErrorPolicies(context.Background(), conf, nil, mp, sinks.RetryEvents{}) assert.NoError(t, err) assert.That(t, policies.DLQSink != nil) @@ -152,7 +153,8 @@ func TestWindowManagerRowsAreCounted(t *testing.T) { } built, err := buildManagedTables( - context.Background(), conf, conn, &sync.Mutex{}, zap.NewNop(), mp) + context.Background(), conf, conn, &sync.Mutex{}, zap.NewNop(), mp, + nil, sinks.RetryEvents{}) assert.NoError(t, err) assert.Equal(t, 1, len(built)) diff --git a/internal/cli/testdata/config_example.golden b/internal/cli/testdata/config_example.golden index 67488512..4f7d4590 100644 --- a/internal/cli/testdata/config_example.golden +++ b/internal/cli/testdata/config_example.golden @@ -111,6 +111,11 @@ pipeline: batch_size: # Longest a partial batch waits before it is invoked anyway. flush_interval_seconds: + # Longest a shutdown may take after SIGTERM. The final batch, the + # managers' final poll and the state syncs share it. Absent means 30. + # When it passes the process exits 15, and the next start replays what + # was not written. + drain_deadline_seconds: # Where the pipeline keeps its DuckDB state. Absent means in-memory, and # state is lost on a crash. state: diff --git a/internal/config/config.go b/internal/config/config.go index dcd27e60..7ee28954 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -312,6 +312,11 @@ type Pipeline struct { BatchSize int `yaml:"batch_size,omitempty"` // Longest a partial batch waits before it is invoked anyway. FlushIntervalSeconds int `yaml:"flush_interval_seconds,omitempty"` + // Longest a shutdown may take after SIGTERM. The final batch, the + // managers' final poll and the state syncs share it. Absent means 30. + // When it passes the process exits 15, and the next start replays what + // was not written. + DrainDeadlineSeconds int `yaml:"drain_deadline_seconds,omitempty" jsonschema:"minimum=1"` // Where the pipeline keeps its DuckDB state. Absent means in-memory, and // state is lost on a crash. State *StateConf `yaml:"state,omitempty"` diff --git a/internal/config/defaults.go b/internal/config/defaults.go new file mode 100644 index 00000000..f79662f1 --- /dev/null +++ b/internal/config/defaults.go @@ -0,0 +1,36 @@ +package config + +// Defaults that more than one package reads. They live here, beside the +// fields they fill in, because `sqlflow validate` compares them and must not +// import the packages that act on them: internal/sinks and internal/core link +// DuckDB, and validate is the check that runs without it. + +// DefaultDrainDeadlineSeconds is pipeline.drain_deadline_seconds when the +// config omits it. Thirty is Kubernetes' default +// terminationGracePeriodSeconds, so a pipeline with no setting still finishes +// or fails its drain before the supervisor stops waiting. +const DefaultDrainDeadlineSeconds = 30 + +// The sink retry ladder's defaults, for the fields of SinkRetry the config +// omits. +const ( + DefaultSinkRetryMaxAttempts = 4 + DefaultSinkRetryDeadlineSeconds = 10 +) + +// SinkRetries reports whether a sink type is wrapped in a retry ladder. +// +// Only the sinks that cross a network to somebody else's server. Kafka is +// excluded on purpose: it hands records to franz-go, which already retries a +// produce with its own backoff, and a second ladder on top of that one delays +// the report without improving delivery. Console, noop and sqlcommand reach +// nothing that can be temporarily unavailable -- sqlcommand writes through the +// pipeline's own DuckDB connection, and a failure there is not a blip. +func SinkRetries(sinkType string) bool { + switch sinkType { + case "clickhouse", "iceberg": + return true + default: + return false + } +} diff --git a/internal/conformance/conformance_test.go b/internal/conformance/conformance_test.go index 3799e2ec..7fa49d58 100644 --- a/internal/conformance/conformance_test.go +++ b/internal/conformance/conformance_test.go @@ -819,11 +819,12 @@ func TestToolingConformancePipelines_AStatelessSubjectSkipsStateInvariants(t *te assert.True(t, strings.Contains(vs[onlyDeliveredRows].skipped, "read back")) assert.Equal(t, "", vs[stateWithOffsets].failure) - // The other four still apply to a stateless pipeline. + // The other five still apply to a stateless pipeline. assert.Equal(t, "", vs[commitAfterFlush].failure) assert.Equal(t, "", vs[commitNothingOnFail].failure) assert.Equal(t, "", vs[drainOnCancel].failure) assert.Equal(t, "", vs[shutdownDelivered].failure) + assert.Equal(t, "", vs[drainBounded].failure) } // Every invariant the pipeline harness judges must be declared, or its marker @@ -899,15 +900,15 @@ func pipelineVerdictsFor(t *testing.T, s PipelineSubject) map[string]verdict { for _, v := range pipelineVerdicts(t, s) { out[v.invariant] = v } - assert.Equal(t, 7, len(out)) + assert.Equal(t, 8, len(out)) return out } -// The liveness claim is the only one that says the pipeline does anything. -// Every safety verdict above holds for a pipeline that never flushes, so a -// harness that judged safety alone would call a permanently stalled loop -// conformant. -func TestToolingConformancePipelines_JudgeOneLivenessClaim(t *testing.T) { +// The liveness claims are the ones that say the pipeline does anything. Every +// safety verdict above holds for a pipeline that never flushes, so a harness +// that judged safety alone would call a permanently stalled loop conformant. +// Two now: the batch reaches the sink, and a drain ends. +func TestToolingConformancePipelines_JudgeTheLivenessClaims(t *testing.T) { coverage.Covers(t, "tooling.conformance") vs := pipelineVerdictsFor(t, PipelineSubject{ @@ -916,8 +917,10 @@ func TestToolingConformancePipelines_JudgeOneLivenessClaim(t *testing.T) { Options: func(*Recorder) []core.TurbineOption { return nil }, }) - assert.Equal(t, "", vs[flushEventually].failure) - assert.Equal(t, "", vs[flushEventually].skipped) + for _, id := range []string{flushEventually, drainBounded} { + assert.Equal(t, "", vs[id].failure) + assert.Equal(t, "", vs[id].skipped) + } } // TestHarnessSinkCarriesRowCounters guards why sink.rows.counted_on_delivery diff --git a/internal/conformance/manager.go b/internal/conformance/manager.go index 3c065d7f..dd507225 100644 --- a/internal/conformance/manager.go +++ b/internal/conformance/manager.go @@ -37,9 +37,10 @@ type ManagerSubject struct { Integration string // New builds the manager around the sink the harness supplies, polling at - // the given interval. The harness owns the sink so it can fail a flush - // and record what the manager asked of it. - New func(t *testing.T, sink core.Sink, poll time.Duration) Manager + // the given interval, with its final poll bounded by the budget. The + // harness owns the sink so it can fail a flush and record what the + // manager asked of it, and owns the budget so it can run one out. + New func(t *testing.T, sink core.Sink, poll time.Duration, budget *core.DrainBudget) Manager // Seed replaces the state table's contents with n closed windows. Seed func(t *testing.T, n int) @@ -85,6 +86,7 @@ const ( deleteNothingOnFail = "manager.delete.nothing_on_failure" publishEventually = "manager.publish.eventually" failureExits = "manager.failure.exits" + managerDrainBounded = "manager.drain.bounded" ) // seededWindows is how many closed windows each check starts with. Two, @@ -106,6 +108,7 @@ func managerVerdicts(t *testing.T, s ManagerSubject) []verdict { onFailure := verdict{invariant: deleteNothingOnFail} eventually := verdict{invariant: publishEventually} exits := verdict{invariant: failureExits} + bounded := verdict{invariant: managerDrainBounded} if err := checkDeleteAfterFlush(t, s); err != nil { afterFlush.failure = err.Error() @@ -119,8 +122,11 @@ func managerVerdicts(t *testing.T, s ManagerSubject) []verdict { if err := checkFailureExits(t, s); err != nil { exits.failure = err.Error() } + if err := checkManagerDrainBounded(t, s); err != nil { + bounded.failure = err.Error() + } - return []verdict{afterFlush, onFailure, eventually, exits} + return []verdict{afterFlush, onFailure, eventually, exits, bounded} } // newManagerRun seeds the state table and builds the manager on a recording @@ -132,7 +138,63 @@ func newManagerRun(t *testing.T, s ManagerSubject, fail bool) (Manager, *Recorde rec := &Recorder{} sink := newRecordingSink(rec, nil, noop.NewMeterProvider()) sink.fail = fail - return s.New(t, sink.counted, managerPoll), rec, sink + // The default deadline, so no check but the bounded one can run it out. + budget := core.NewDrainBudget(core.DefaultDrainDeadline) + t.Cleanup(budget.Stop) + return s.New(t, sink.counted, managerPoll, budget), rec, sink +} + +// checkManagerDrainBounded cancels Start against a sink that never answers +// and holds that it returns inside the drain deadline, with every closed +// window still in the state table for the next start to publish. +// +// The final poll is the manager's drain. Before #161 it ran on a context with +// no deadline, so a destination that stopped answering during shutdown held +// the process until the supervisor killed it. +func checkManagerDrainBounded(t *testing.T, s ManagerSubject) error { + t.Helper() + s.Seed(t, seededWindows) + sink := newRecordingSink(&Recorder{}, nil, noop.NewMeterProvider()) + sink.hang = true + sink.release = make(chan struct{}) + watchdog := time.AfterFunc(drainBoundedWait, func() { close(sink.release) }) + defer watchdog.Stop() + budget := core.NewDrainBudget(drainBudget) + defer budget.Stop() + // An hour between polls, so the only poll that runs is the final one. + m := s.New(t, sink.counted, time.Hour, budget) + + ctx, cancel := context.WithCancel(context.Background()) + done := make(chan error, 1) + started := time.Now() + go func() { done <- m.Start(ctx) }() + cancel() + + select { + case err := <-done: + if err == nil { + return fmt.Errorf("the sink never answered the final poll and Start " + + "returned nil, so the shutdown reports windows published that were not") + } + case <-time.After(2 * drainBoundedWait): + return fmt.Errorf("a %s drain deadline held the final poll past %s against "+ + "a sink that never answered, and the watchdog could not release it", + drainBudget, 2*drainBoundedWait) + } + if took := time.Since(started); took >= drainBoundedWait { + return fmt.Errorf("a %s drain deadline held the final poll for %s against "+ + "a sink that never answered", drainBudget, took) + } + if sink.Flushes() != 1 { + return fmt.Errorf("the final poll flushed %d times; want the one attempt the "+ + "deadline ended", sink.Flushes()) + } + if left := s.Remaining(t); left != seededWindows { + return fmt.Errorf("the final poll ran out of time and %d of %d closed windows "+ + "are gone from the state table. They were never delivered, so a restart "+ + "cannot publish them", seededWindows-left, seededWindows) + } + return nil } // checkDeleteAfterFlush holds that the state table still has every closed diff --git a/internal/conformance/pipeline.go b/internal/conformance/pipeline.go index e7212154..f9ebcf79 100644 --- a/internal/conformance/pipeline.go +++ b/internal/conformance/pipeline.go @@ -30,6 +30,7 @@ import ( "github.com/apache/arrow-go/v18/arrow/memory" "github.com/turbolytics/sql-flow/internal/core" "github.com/turbolytics/sql-flow/internal/coverage" + "github.com/turbolytics/sql-flow/internal/errs" "go.opentelemetry.io/otel/metric" ) @@ -151,6 +152,7 @@ const ( commitNothingOnFail = "pipeline.commit.nothing_on_failure" stateWithOffsets = "pipeline.state.with_offsets" drainOnCancel = "lifecycle.drain.on_cancel" + drainBounded = "lifecycle.drain.bounded" flushEventually = "pipeline.flush.eventually" shutdownDelivered = "pipeline.shutdown.commits_only_delivered" onlyDeliveredRows = "pipeline.commit.only_delivered_rows" @@ -170,6 +172,7 @@ func pipelineVerdicts(t *testing.T, s PipelineSubject) []verdict { onFailure := verdict{invariant: commitNothingOnFail} withOffsets := verdict{invariant: stateWithOffsets} drain := verdict{invariant: drainOnCancel} + bounded := verdict{invariant: drainBounded} eventually := verdict{invariant: flushEventually} shutdown := verdict{invariant: shutdownDelivered} delivered := verdict{invariant: onlyDeliveredRows} @@ -230,6 +233,12 @@ func pipelineVerdicts(t *testing.T, s PipelineSubject) []verdict { } } + // The liveness half of the drain. on_cancel says the buffered rows are + // written; this says the attempt ends, against a sink that never answers. + if err := checkDrainBounded(t, s); err != nil { + bounded.failure = err.Error() + } + // The outcome, not the order. after_flush asserts the sequence the loop // happens to use; this asserts the guarantee that sequence exists for, and // it needs a destination to count. @@ -244,15 +253,15 @@ func pipelineVerdicts(t *testing.T, s PipelineSubject) []verdict { } } - // The only liveness claim here. Everything above says the pipeline does + // The progress claim. The safety checks above say the pipeline does // nothing wrong; this says it does something. A sink that never flushed // would satisfy every one of them and fail this one alone. if err := checkFlushEventually(t, s); err != nil { eventually.failure = err.Error() } - return []verdict{afterFlush, onFailure, withOffsets, drain, eventually, - delivered, shutdown} + return []verdict{afterFlush, onFailure, withOffsets, drain, bounded, + eventually, delivered, shutdown} } // checkCommitAfterFlush runs one trigger and holds the event order. @@ -451,6 +460,53 @@ func committedPastDelivery(run outcome) error { return nil } +// checkDrainBounded cancels mid-run against a sink that never answers, and +// holds that the loop returns inside the drain deadline with the drain code +// and commits nothing after the flush it could not finish. +// +// Before #161 the drain ran on a context with no deadline, so this run would +// have waited on the sink for as long as the sink chose. A supervisor does +// not wait that long: it kills the process, and nothing records that the tail +// of the stream was replayed rather than written. +func checkDrainBounded(t *testing.T, s PipelineSubject) error { + t.Helper() + started := time.Now() + run := runPipeline(t, s, TriggerDrain, faults{hang: true}) + took := time.Since(started) + + if took >= drainBoundedWait { + return fmt.Errorf("drain.bounded: a %s drain deadline held the pipeline for %s "+ + "against a sink that never answered", drainBudget, took) + } + if run.err == nil { + return fmt.Errorf("drain.bounded: the sink never answered and the pipeline " + + "reported a clean stop, so a supervisor cannot tell the tail was replayed") + } + if code := errs.CodeOf(run.err); code != errs.CodeDrainIncomplete { + return fmt.Errorf("drain.bounded: the drain ran out of time and reported %s; "+ + "want %s", code, errs.CodeDrainIncomplete) + } + + last := -1 + for i, e := range run.events { + if e == "flush-failed" { + last = i + } + } + if last < 0 { + return fmt.Errorf("drain.bounded: the pipeline did %s and never reached the "+ + "sink, so the deadline bounded nothing", list(run.events)) + } + for _, e := range run.events[last+1:] { + if e == "commit" || e == "save-offsets" { + return fmt.Errorf("drain.bounded: the sink never took the batch and the "+ + "pipeline then did %s; the next start would skip those rows", + list(run.events[last:])) + } + } + return nil +} + func ackedText(offset int64, ok bool) string { if !ok { return "nothing" @@ -578,6 +634,10 @@ type faults struct { // shutdown runs run's commits after the loop returns: a state sync before // the managers' final poll and one after it. shutdown bool + + // hang makes the sink's Flush block until its context ends, and runs the + // pipeline under drainBudget. + hang bool } // outcome is what one run produced. @@ -601,6 +661,16 @@ type outcome struct { stalled bool } +// drainBudget is the deadline the bounded-drain scenario runs under. Short, so +// the check is fast; the check's own bound is many times it, so a loaded CI +// machine does not turn scheduling delay into a failed invariant. +const drainBudget = 300 * time.Millisecond + +// drainBoundedWait is how long the bounded-drain check lets the whole run +// take, from start to return. Many times drainBudget on purpose: #245 failed +// on CI because a tight bound measured the machine. +const drainBoundedWait = 5 * time.Second + // drainRows is the number of messages the drain scenario buffers. Small, and // larger than one, so a drain that writes a partial batch is visible. const drainRows = 10 @@ -636,6 +706,14 @@ func runPipeline(t *testing.T, s PipelineSubject, trigger Trigger, f faults) out inner = s.NewSink(t) } sink := newRecordingSink(rec, inner, nil) + sink.hang = f.hang + if f.hang { + // The check's bound, enforced from outside the pipeline. A drain that + // ignores its deadline is released here and reported as too slow. + sink.release = make(chan struct{}) + watchdog := time.AfterFunc(drainBoundedWait, func() { close(sink.release) }) + defer watchdog.Stop() + } // Break the destination where there is one, so the flush fails the way it // would in production. Only a subject with nothing to break needs the // harness to fake it. @@ -705,8 +783,14 @@ func runPipeline(t *testing.T, s PipelineSubject, trigger Trigger, f faults) out defer cancel() handler.cancel = cancel + opts := s.Options(rec) + if f.hang { + budget := core.NewDrainBudget(drainBudget) + defer budget.Stop() + opts = append(opts, core.WithDrainBudget(budget)) + } tb := core.NewTurbine(src, handler, sink.counted, batchSize, interval, - &sync.Mutex{}, core.PipelineErrorPolicies{}, s.Options(rec)...) + &sync.Mutex{}, core.PipelineErrorPolicies{}, opts...) stalled := false if flushed != nil { @@ -1050,6 +1134,14 @@ type recordingSink struct { inner core.Sink fail bool + // hang makes Flush block until its context ends: the sink a drain + // deadline exists for, one that neither succeeds nor fails on its own. + // release ends the block regardless. The harness closes it when the + // check's own bound passes, so a pipeline that ignores its deadline fails + // the check instead of hanging the suite. + hang bool + release chan struct{} + // counted is this sink wrapped in the row counters, and it is what the // pipeline is given. counted core.Sink @@ -1088,9 +1180,18 @@ func (s *recordingSink) WriteTable(ctx context.Context, batch arrow.Table) error func (s *recordingSink) Flush(ctx context.Context) error { s.mu.Lock() s.flushes++ - inner, fail := s.inner, s.fail + inner, fail, hang, release := s.inner, s.fail, s.hang, s.release s.mu.Unlock() + if hang { + select { + case <-ctx.Done(): + case <-release: + } + s.rec.record("flush-failed") + return errors.New("conformance: sink never answered") + } + // The synthetic failure is for subjects with no destination to break. A // subject that has one gets a real error from a really broken sink. if fail { diff --git a/internal/core/drain.go b/internal/core/drain.go new file mode 100644 index 00000000..cd4a2d26 --- /dev/null +++ b/internal/core/drain.go @@ -0,0 +1,80 @@ +package core + +import ( + "context" + "sync" + "time" + + "github.com/turbolytics/sql-flow/internal/config" +) + +// DefaultDrainDeadline bounds a shutdown that the config did not bound. The +// value is declared in config.DefaultDrainDeadlineSeconds, where `sqlflow +// validate` reads it without linking DuckDB. +const DefaultDrainDeadline = config.DefaultDrainDeadlineSeconds * time.Second + +// DrainBudget is one deadline for everything a shutdown does. +// +// After a SIGTERM four things reach DuckDB or a sink: the turbine's final +// batch, a state sync, each manager's final poll and a second sync. A deadline +// per step would let the shutdown take four deadlines, and a supervisor gives +// it one. So the budget starts its clock on the first call to Context and +// hands the same context to every caller after that. +// +// The consume loop and every manager goroutine call it, so it is guarded by +// a mutex rather than left to the order the goroutines happen to run in. +type DrainBudget struct { + deadline time.Duration + + mu sync.Mutex + ctx context.Context + cancel context.CancelFunc +} + +// NewDrainBudget makes a budget whose clock has not started. Zero and +// negative mean DefaultDrainDeadline. +func NewDrainBudget(deadline time.Duration) *DrainBudget { + if deadline <= 0 { + deadline = DefaultDrainDeadline + } + return &DrainBudget{deadline: deadline} +} + +// Context starts the clock on the first call and returns the same context on +// every call after it. +func (b *DrainBudget) Context() context.Context { + b.mu.Lock() + defer b.mu.Unlock() + if b.ctx == nil { + b.ctx, b.cancel = context.WithTimeout(context.Background(), b.deadline) + } + return b.ctx +} + +// Exceeded reports whether the deadline has passed. False before the clock +// starts. +func (b *DrainBudget) Exceeded() bool { + b.mu.Lock() + defer b.mu.Unlock() + return b.ctx != nil && b.ctx.Err() != nil +} + +// Deadline is what the budget was built with, for log lines and errors. +func (b *DrainBudget) Deadline() time.Duration { return b.deadline } + +// Stop releases the timer. Safe before the clock starts. A context handed +// out before Stop ends with context.Canceled, which Exceeded also reports, so +// call Stop only once nothing is draining. +func (b *DrainBudget) Stop() { + b.mu.Lock() + defer b.mu.Unlock() + if b.cancel != nil { + b.cancel() + } +} + +// WithDrainBudget bounds the turbine's final batch. A turbine built without +// one gets DefaultDrainDeadline. +func WithDrainBudget(b *DrainBudget) TurbineOption { + return func(t *Turbine) { t.drain = b } +} diff --git a/internal/core/drain_test.go b/internal/core/drain_test.go new file mode 100644 index 00000000..60038e65 --- /dev/null +++ b/internal/core/drain_test.go @@ -0,0 +1,293 @@ +package core + +import ( + "context" + "errors" + "sync" + "testing" + "time" + + "github.com/apache/arrow-go/v18/arrow" + "github.com/turbolytics/sql-flow/internal/coverage" + "github.com/turbolytics/sql-flow/internal/errs" + "github.com/zeebo/assert" +) + +// The budget is one clock. Every caller after the first gets the same +// context, so the turbine's final batch and the managers' final poll spend +// the same seconds rather than each getting a fresh deadline. +func TestLifecycleDrain_BudgetIsOneClock(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + b := NewDrainBudget(50 * time.Millisecond) + defer b.Stop() + + assert.That(t, !b.Exceeded()) + first := b.Context() + second := b.Context() + assert.That(t, first == second) + + <-first.Done() + assert.That(t, b.Exceeded()) + assert.That(t, errors.Is(first.Err(), context.DeadlineExceeded)) +} + +// A budget built with no deadline still has one. A shutdown the config +// forgot to bound is bounded anyway. +func TestLifecycleDrain_ZeroDeadlineMeansTheDefault(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + assert.Equal(t, DefaultDrainDeadline, NewDrainBudget(0).Deadline()) + assert.Equal(t, DefaultDrainDeadline, NewDrainBudget(-time.Second).Deadline()) +} + +// hangingSink blocks in Flush until its context ends. It is the sink a drain +// deadline exists for: one that neither succeeds nor fails on its own. +type hangingSink struct { + mu sync.Mutex + flushes int +} + +func (s *hangingSink) WriteTable(context.Context, arrow.Table) error { return nil } + +func (s *hangingSink) Flush(ctx context.Context) error { + s.mu.Lock() + s.flushes++ + s.mu.Unlock() + <-ctx.Done() + return ctx.Err() +} + +// rejectingSink refuses every flush with a coded error, immediately. +type rejectingSink struct{ err error } + +func (s *rejectingSink) WriteTable(context.Context, arrow.Table) error { return nil } +func (s *rejectingSink) Flush(context.Context) error { return s.err } + +// drainRun buffers n messages, cancels, and returns what ConsumeLoop returned +// and how long the drain took after the cancel. +func drainRun(t *testing.T, n int, sink Sink, opts ...TurbineOption) (error, time.Duration) { + t.Helper() + src := newBlockingSource(messages(n)) + h := &drainHandler{wrote: make(chan struct{})} + tb := NewTurbine(src, h, sink, 1000, time.Hour, &sync.Mutex{}, + PipelineErrorPolicies{}, opts...) + + ctx, cancel := context.WithCancel(context.Background()) + defer close(src.release) + + var ( + err error + done = make(chan struct{}) + ) + go func() { + defer close(done) + _, err = tb.ConsumeLoop(ctx, 0) + }() + + for i := 0; i < n; i++ { + <-h.wrote + } + started := time.Now() + cancel() + + select { + case <-done: + case <-time.After(5 * time.Second): + t.Fatal("the drain outlived its deadline by more than 5s") + } + return err, time.Since(started) +} + +// A sink that never answers must not hold the process past the deadline. +// The loop returns inside the budget with the drain code, and the rows stay +// unwritten and uncommitted for the next start to replay. +func TestLifecycleDrain_DeadlineBoundsTheFinalBatch(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + budget := NewDrainBudget(200 * time.Millisecond) + defer budget.Stop() + + err, took := drainRun(t, 10, &hangingSink{}, WithDrainBudget(budget)) + + assert.That(t, took < 2*time.Second) + assert.Error(t, err) + assert.Equal(t, errs.CodeDrainIncomplete, errs.CodeOf(err)) + assert.That(t, budget.Exceeded()) +} + +// A sink that fails for its own reason during the drain keeps its own code. +// Only running out of time is a drain failure. +func TestLifecycleDrain_ASinkFailureInsideTheDeadlineKeepsItsCode(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + budget := NewDrainBudget(5 * time.Second) + defer budget.Stop() + + sink := &rejectingSink{err: errs.New(errs.CodeSinkWriteFailed, "rejected")} + err, _ := drainRun(t, 3, sink, WithDrainBudget(budget)) + + assert.Equal(t, errs.CodeSinkWriteFailed, errs.CodeOf(err)) + assert.That(t, !budget.Exceeded()) +} + +// expiryTx records whether each boundary call arrived on a live context. +type expiryTx struct { + mu sync.Mutex + events []string +} + +func (x *expiryTx) record(call string, ctx context.Context) error { + x.mu.Lock() + defer x.mu.Unlock() + if ctx.Err() != nil { + x.events = append(x.events, call+"-on-expired-context") + return ctx.Err() + } + x.events = append(x.events, call) + return nil +} + +func (x *expiryTx) Commit(ctx context.Context) error { return x.record("commit", ctx) } +func (x *expiryTx) Rollback(ctx context.Context) error { return x.record("rollback", ctx) } + +// The batch the drain could not write is rolled back on a live context even +// though the deadline has passed. The DuckDB driver ignores the context on a +// rollback, so this guards a transaction that honours it: refused, it would +// leave the handler's writes in the open transaction for the next state sync +// to commit without their offsets, and a replay would count them twice. +func TestLifecycleDrain_RollbackOutlivesTheDeadline(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + budget := NewDrainBudget(100 * time.Millisecond) + defer budget.Stop() + + var offsetEvents []string + tx := &expiryTx{} + err, _ := drainRun(t, 5, &hangingSink{}, WithDrainBudget(budget), + WithStateStore(&fakeOffsetStore{events: &offsetEvents}, tx)) + + assert.Equal(t, errs.CodeDrainIncomplete, errs.CodeOf(err)) + tx.mu.Lock() + defer tx.mu.Unlock() + assert.DeepEqual(t, []string{"rollback"}, tx.events) +} + +// gatedSink blocks in Flush until released or until its context ends, and +// says which one happened. +type gatedSink struct { + entered chan struct{} + release chan struct{} + mu sync.Mutex + rows int64 + pending int64 + flushes int +} + +func newGatedSink() *gatedSink { + return &gatedSink{entered: make(chan struct{}, 1), release: make(chan struct{})} +} + +func (s *gatedSink) WriteTable(_ context.Context, batch arrow.Table) error { + s.mu.Lock() + defer s.mu.Unlock() + if batch != nil { + s.pending += batch.NumRows() + } + return nil +} + +func (s *gatedSink) Flush(ctx context.Context) error { + s.mu.Lock() + s.flushes++ + s.mu.Unlock() + select { + case s.entered <- struct{}{}: + default: + } + select { + case <-s.release: + s.mu.Lock() + s.rows += s.pending + s.pending = 0 + s.mu.Unlock() + return nil + case <-ctx.Done(): + return ctx.Err() + } +} + +// A SIGTERM that lands while a batch is being flushed does not abort the +// flush. The batch keeps the drain deadline, finishes, and the loop stops +// clean with the rows delivered. Before this, the cancel killed the flush at +// once, the loop returned the sink's error, and the batch replayed on the +// next start for no reason. +func TestLifecycleDrain_ACancelDuringAFlushLetsItFinish(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + src := newBlockingSource(messages(5)) + sink := newGatedSink() + budget := NewDrainBudget(5 * time.Second) + defer budget.Stop() + tb := NewTurbine(src, &fakeHandler{}, sink, 5, time.Hour, &sync.Mutex{}, + PipelineErrorPolicies{}, WithDrainBudget(budget)) + + ctx, cancel := context.WithCancel(context.Background()) + defer close(src.release) + done := make(chan error, 1) + go func() { + _, err := tb.ConsumeLoop(ctx, 0) + done <- err + }() + + <-sink.entered + cancel() + select { + case err := <-done: + t.Fatalf("the loop returned %v while the batch was still being flushed", err) + case <-time.After(200 * time.Millisecond): + } + close(sink.release) + + select { + case err := <-done: + assert.NoError(t, err) + case <-time.After(5 * time.Second): + t.Fatal("the loop did not return after the flush finished") + } + sink.mu.Lock() + defer sink.mu.Unlock() + assert.Equal(t, int64(5), sink.rows) + assert.Equal(t, 1, sink.flushes) +} + +// The same cancel against a flush that never finishes: the drain deadline +// ends it, and the loop reports the drain as incomplete rather than the +// sink's own error. +func TestLifecycleDrain_ACancelDuringAFlushIsBoundedByTheDeadline(t *testing.T) { + coverage.Covers(t, "lifecycle.drain") + src := newBlockingSource(messages(5)) + sink := newGatedSink() + budget := NewDrainBudget(300 * time.Millisecond) + defer budget.Stop() + tb := NewTurbine(src, &fakeHandler{}, sink, 5, time.Hour, &sync.Mutex{}, + PipelineErrorPolicies{}, WithDrainBudget(budget)) + + ctx, cancel := context.WithCancel(context.Background()) + defer close(src.release) + done := make(chan error, 1) + go func() { + _, err := tb.ConsumeLoop(ctx, 0) + done <- err + }() + + <-sink.entered + started := time.Now() + cancel() + var err error + select { + case err = <-done: + case <-time.After(5 * time.Second): + t.Fatal("the drain outlived its deadline") + } + took := time.Since(started) + + assert.Equal(t, errs.CodeDrainIncomplete, errs.CodeOf(err)) + assert.That(t, took >= 250*time.Millisecond) + assert.That(t, took < 3*time.Second) + assert.Equal(t, int64(1), tb.Progress().Errors) +} diff --git a/internal/core/progress.go b/internal/core/progress.go index 45923934..f6f0c6eb 100644 --- a/internal/core/progress.go +++ b/internal/core/progress.go @@ -14,11 +14,17 @@ import ( // stream from a replay; /stats and /healthz read the in-memory copy. const progressTable = "sqlflow_progress" -// Progress is the pipeline's liveness in three facts. Wall clock, UTC. +// Progress is the pipeline's liveness. Wall clock, UTC. type Progress struct { LastArrival time.Time LastCommit time.Time Messages int64 + + // LastError is when the loop last recorded an error, and Errors is how + // many it has recorded. In memory only: they describe this process, not + // the durable state, so the progress table does not carry them. + LastError time.Time + Errors int64 } // progressSaver is what the Turbine needs; ProgressStore is the DuckDB one. diff --git a/internal/core/progress_test.go b/internal/core/progress_test.go index 0d702898..30d3bd81 100644 --- a/internal/core/progress_test.go +++ b/internal/core/progress_test.go @@ -275,3 +275,26 @@ func TestStateDurability_ProgressNeverReportsAnArrivalOlderThanTheNewest(t *test close(src.release) <-done } + +// The health endpoint calls a pipeline degraded when it recorded an error +// inside the last interval, so the snapshot has to carry when that was and +// how many there have been. +func TestCoreConsumeLoop_ProgressRecordsTheLastError(t *testing.T) { + coverage.Covers(t, "core.consume_loop") + src := &fakeSource{batches: [][]Message{{{Value: []byte("bad")}, {Value: []byte("ok")}}}} + h := &failingHandler{failWriteOn: "bad"} + tb := NewTurbine(src, h, &fakeSink{}, 2, time.Second, &sync.Mutex{}, + PipelineErrorPolicies{Policy: PolicyIgnore}) + + assert.Equal(t, int64(0), tb.Progress().Errors) + assert.That(t, tb.Progress().LastError.IsZero()) + + before := time.Now().UTC() + _, err := tb.ConsumeLoop(context.Background(), 0) + assert.NoError(t, err) + + p := tb.Progress() + assert.Equal(t, int64(1), p.Errors) + assert.That(t, !p.LastError.Before(before)) + assert.That(t, !p.LastError.After(time.Now().UTC())) +} diff --git a/internal/core/turbine.go b/internal/core/turbine.go index 8730822d..a16f22cd 100644 --- a/internal/core/turbine.go +++ b/internal/core/turbine.go @@ -265,6 +265,16 @@ type Turbine struct { stats *Stats errorPolicy PipelineErrorPolicies + // drain bounds the final batch after a cancel. Shared with the managers + // and run's state syncs, so one deadline covers the whole shutdown. + drain *DrainBudget + + // lastErrorUnixNano and errorCount feed Progress. Atomics rather than + // fields under lock, because recordError runs on paths that already + // hold it. + lastErrorUnixNano atomic.Int64 + errorCount atomic.Int64 + // lagAttrCache keeps one attribute set per topic and partition, so the // per-message lag metric costs no allocation. Touched only by mark, on // the consume-loop goroutine. @@ -334,8 +344,14 @@ func WithProgressWriteInterval(d time.Duration) TurbineOption { // nothing has been recorded yet. func (t *Turbine) Progress() Progress { t.lock.Lock() - defer t.lock.Unlock() - return t.snapshot + p := t.snapshot + t.lock.Unlock() + + if ns := t.lastErrorUnixNano.Load(); ns != 0 { + p.LastError = time.Unix(0, ns).UTC() + } + p.Errors = t.errorCount.Load() + return p } // commitCount is how many state commits have succeeded; tests wait on it. @@ -492,6 +508,10 @@ func NewTurbine( opt(t) } + if t.drain == nil { + t.drain = NewDrainBudget(DefaultDrainDeadline) + } + return t } @@ -578,6 +598,16 @@ func (t *Turbine) ConsumeLoop(ctx context.Context, maxMsgs int) (stats *Stats, e return nil, err } + // Every batch runs on batchCtx, not ctx. A SIGTERM arrives as ctx being + // cancelled, and a busy pipeline is usually inside a flush when it does. + // On ctx the cancel aborted that flush at once, the loop returned the + // sink's error, and the drain never ran: the process exited with a + // retryable code and replayed a batch it could have finished. batchCtx + // ends when the drain budget does, so the batch in flight gets the same + // deadline the drain gets, and one clock covers both. + batchCtx, stopBatches := t.batchContext(ctx) + defer stopBatches() + numBatchMessages := 0 totalConsumed := int64(0) hitMax := false @@ -611,8 +641,8 @@ func (t *Turbine) ConsumeLoop(ctx context.Context, maxMsgs int) (stats *Stats, e case msgBatch, ok = <-stream: case <-flushC: if numBatchMessages > 0 { - if err := t.processBatch(ctx, numBatchMessages); err != nil { - return nil, err + if err := t.processBatch(batchCtx, numBatchMessages); err != nil { + return nil, t.drainError(err, numBatchMessages) } numBatchMessages = 0 continue @@ -625,7 +655,7 @@ func (t *Turbine) ConsumeLoop(ctx context.Context, maxMsgs int) (stats *Stats, e // silently, with the rows still reported as live state. This tick // is also what makes a table manager's deletes durable while no // messages are arriving. - if err := t.commitState(ctx); err != nil { + if err := t.commitState(batchCtx); err != nil { t.recordError(ctx, err, phaseStateCommit, "error committing state on idle tick") return nil, err } @@ -636,12 +666,14 @@ func (t *Turbine) ConsumeLoop(ctx context.Context, maxMsgs int) (stats *Stats, e // The source delivered this batch, but nothing has written it yet. // Returning without it drops the tail of every graceful shutdown. // - // The drain runs on a context of its own. Every step below reaches - // DuckDB and the sink. The cancelled ctx would fail the exact work - // the drain exists to finish. + // batchCtx is still live here: the cancel that ended ctx started + // the drain budget's clock, and batchCtx ends with that clock. So + // the drain has the whole deadline, and the same one the batch in + // flight had. if numBatchMessages > 0 { - if err := t.processBatch(context.WithoutCancel(ctx), numBatchMessages); err != nil { - t.recordError(ctx, err, phaseSinkFlush, "error draining the final batch") + if err := t.processBatch(batchCtx, numBatchMessages); err != nil { + err = t.drainError(err, numBatchMessages) + t.logger.Error("error draining the final batch", zap.Error(err)) return nil, err } } @@ -723,8 +755,9 @@ func (t *Turbine) ConsumeLoop(ctx context.Context, maxMsgs int) (stats *Stats, e case <-ctx.Done(): t.logger.Info("context done at a batch boundary, draining the batch") t.running = false - if err := t.processBatch(context.WithoutCancel(ctx), numBatchMessages); err != nil { - t.recordError(ctx, err, phaseSinkFlush, "error draining the final batch") + if err := t.processBatch(batchCtx, numBatchMessages); err != nil { + err = t.drainError(err, numBatchMessages) + t.logger.Error("error draining the final batch", zap.Error(err)) return nil, err } t.logThroughput() @@ -733,8 +766,8 @@ func (t *Turbine) ConsumeLoop(ctx context.Context, maxMsgs int) (stats *Stats, e } p0 := time.Now() - if err := t.processBatch(ctx, numBatchMessages); err != nil { - return nil, err + if err := t.processBatch(batchCtx, numBatchMessages); err != nil { + return nil, t.drainError(err, numBatchMessages) } batchTook += time.Since(p0) numBatchMessages = 0 @@ -757,8 +790,8 @@ func (t *Turbine) ConsumeLoop(ctx context.Context, maxMsgs int) (stats *Stats, e // reached or the source ended — still has to reach the sink, otherwise // messages counted as consumed are silently dropped. if numBatchMessages > 0 { - if err := t.processBatch(ctx, numBatchMessages); err != nil { - return nil, err + if err := t.processBatch(batchCtx, numBatchMessages); err != nil { + return nil, t.drainError(err, numBatchMessages) } } @@ -766,6 +799,39 @@ func (t *Turbine) ConsumeLoop(ctx context.Context, maxMsgs int) (stats *Stats, e return t.stats, nil } +// batchContext derives the context every batch runs on. It is not cancelled +// when run is; it ends when the drain budget's deadline passes after run was +// cancelled, and the budget's clock starts at that cancel. Stop it when the +// loop returns, or the goroutine outlives the run. +func (t *Turbine) batchContext(run context.Context) (context.Context, context.CancelFunc) { + batchCtx, cancel := context.WithCancel(context.WithoutCancel(run)) + go func() { + select { + case <-run.Done(): + case <-batchCtx.Done(): + return + } + select { + case <-t.drain.Context().Done(): + cancel() + case <-batchCtx.Done(): + } + }() + return batchCtx, cancel +} + +// drainError classifies a batch failure that happened after the drain +// deadline passed. The batch was not delivered whatever the sink said, and +// the code says why a supervisor sees a retryable exit: the stop ran out of +// time, and the next start replays what was not written. +func (t *Turbine) drainError(err error, buffered int) error { + if !t.drain.Exceeded() { + return err + } + return errs.Wrap(errs.CodeDrainIncomplete, err, + "drain deadline %s reached with %d messages buffered", t.drain.Deadline(), buffered) +} + // writeMessage hands the message to the handler, with its source metadata if // the handler can use it. func (t *Turbine) writeMessage(msg Message) error { @@ -820,6 +886,8 @@ func (t *Turbine) recordPhase(ctx context.Context, phase string, took time.Durat // need the caching the per-message paths use. func (t *Turbine) recordError(ctx context.Context, err error, phase, message string) { t.stats.NumErrors++ + t.lastErrorUnixNano.Store(time.Now().UnixNano()) + t.errorCount.Add(1) code := errs.CodeOf(err) t.metrics.ErrorCount.Add(ctx, 1, metric.WithAttributes( @@ -973,7 +1041,13 @@ func (t *Turbine) rollbackState(ctx context.Context) { } t.lock.Lock() defer t.lock.Unlock() - if err := t.stateTx.Rollback(ctx); err != nil { + // Without cancellation. A rollback is local and must happen. The DuckDB + // driver ignores the context on a rollback today, so this changes nothing + // there; it is for any transaction that does honour it, where a rollback + // refused on an expired drain context would leave this batch's writes in + // the transaction for the next state sync to commit without their + // offsets. The harness's recording transaction is one. + if err := t.stateTx.Rollback(context.WithoutCancel(ctx)); err != nil { t.logger.Error("rollback failed", zap.Error(err)) } } @@ -997,7 +1071,7 @@ func (t *Turbine) commitState(ctx context.Context) error { defer t.lock.Unlock() if err := t.offsets.Save(ctx, t.marks); err != nil { - if rbErr := t.stateTx.Rollback(ctx); rbErr != nil { + if rbErr := t.stateTx.Rollback(context.WithoutCancel(ctx)); rbErr != nil { t.logger.Error("rollback after failed offset save", zap.Error(rbErr)) } return errs.Wrap(errs.CodeStateCommitFailed, err, "saving offsets") @@ -1007,7 +1081,7 @@ func (t *Turbine) commitState(ctx context.Context) error { // The commit itself failed, so the transaction is still open and // still holds this batch's writes; roll it back explicitly rather // than leaving them to leak into the next batch. - if rbErr := t.stateTx.Rollback(ctx); rbErr != nil { + if rbErr := t.stateTx.Rollback(context.WithoutCancel(ctx)); rbErr != nil { t.logger.Error("rollback after failed commit", zap.Error(rbErr)) } return errs.Wrap(errs.CodeStateCommitFailed, err, "committing state") @@ -1237,10 +1311,8 @@ func (t *Turbine) logThroughput() { } } +// flush sends the buffered batch. The caller records a failure once; a +// second record here counted every failed flush twice. func (t *Turbine) flush(ctx context.Context, batch arrow.Table) error { - if err := t.sink.Flush(ctx); err != nil { - t.recordError(ctx, err, phaseSinkFlush, "flush error") - return err - } - return nil + return t.sink.Flush(ctx) } diff --git a/internal/errs/errs_test.go b/internal/errs/errs_test.go index 7a24d93d..f943709d 100644 --- a/internal/errs/errs_test.go +++ b/internal/errs/errs_test.go @@ -262,3 +262,19 @@ func TestErrorTaxonomy_EncodeFailedIsAUserErrorThatExitsTerminal(t *testing.T) { assert.True(t, ok) assert.True(t, strings.Contains(def.Action, "handler SQL")) } + +// A drain that ran out of time is its own exit code. It is retryable, because +// nothing unwritten was committed and the next start replays it; the code +// exists so an operator can see the tail was replayed rather than written. +func TestLifecycleExitCodes_DrainIncompleteExitsFifteen(t *testing.T) { + coverage.Covers(t, "lifecycle.exit_codes") + err := New(CodeDrainIncomplete, "drain deadline 1s reached") + + assert.Equal(t, ExitDrainIncomplete, ExitCode(err)) + assert.Equal(t, 15, ExitDrainIncomplete) + assert.That(t, Retryable(ExitDrainIncomplete)) + + def, ok := Lookup(CodeDrainIncomplete) + assert.That(t, ok) + assert.That(t, strings.Contains(def.Action, "drain_deadline_seconds")) +} diff --git a/internal/errs/exit.go b/internal/errs/exit.go index ef21638d..920f5654 100644 --- a/internal/errs/exit.go +++ b/internal/errs/exit.go @@ -36,6 +36,12 @@ const ( // ExitStateCorrupt marks a state file that cannot be read. Terminal: a // restart reads the same bytes. An operator has to look at it. ExitStateCorrupt = 14 + + // ExitDrainIncomplete marks a stop that ran out of time. Retryable: + // nothing unwritten was committed, and the next start replays it. The + // code exists so an operator can see that the tail of the stream was + // replayed rather than written. + ExitDrainIncomplete = 15 ) // exitCodes overrides the class default for codes whose remedy is more @@ -44,6 +50,7 @@ var exitCodes = map[Code]int{ CodeStateCorrupt: ExitStateCorrupt, CodeSourceUnreachable: ExitSourceUnreachable, CodeSinkUnreachable: ExitSinkUnreachable, + CodeDrainIncomplete: ExitDrainIncomplete, } // ExitCode maps an error to the code the process should exit with. diff --git a/internal/errs/registry.go b/internal/errs/registry.go index 3f12e72d..96fe13c1 100644 --- a/internal/errs/registry.go +++ b/internal/errs/registry.go @@ -64,6 +64,13 @@ const ( // Batch orchestration. CodeBatchInternal Code = "system.batch.internal" + // Lifecycle: the process stopping. A drain that ran out of time is not a + // sink failure and not a user error. Nothing unwritten was committed, so + // nothing is lost; the code says the tail was replayed rather than + // written. + CodeDrainIncomplete Code = "system.lifecycle.drain_incomplete" + CodeLifecycleInternal Code = "system.lifecycle.internal" + // The last resort. CodeOf returns it for an error carrying no code, so an // unclassified failure still reports as ours rather than the user's. CodeInternalUnexpected Code = "system.internal.unexpected" @@ -199,6 +206,16 @@ var registry = map[Code]Definition{ "A batch failed for a reason the specific codes do not cover.", "Report it with the surrounding log lines.", }, + CodeDrainIncomplete: { + CodeDrainIncomplete, + "The drain deadline passed before the buffered batch or the closed windows were written.", + "Nothing is lost: what was not written was not committed, and the next start replays it. Raise pipeline.drain_deadline_seconds if the sink needs longer, or check the sink.", + }, + CodeLifecycleInternal: { + CodeLifecycleInternal, + "Starting or stopping the process failed for a reason the specific codes do not cover.", + "Report it with the surrounding log lines.", + }, CodeInternalUnexpected: { CodeInternalUnexpected, "An error reached the boundary carrying no code.", diff --git a/internal/errs/testdata/codes.golden b/internal/errs/testdata/codes.golden index 8a4d1c1a..df96c84d 100644 --- a/internal/errs/testdata/codes.golden +++ b/internal/errs/testdata/codes.golden @@ -1,5 +1,7 @@ system.batch.internal system.internal.unexpected +system.lifecycle.drain_incomplete +system.lifecycle.internal system.sink.internal system.sink.unreachable system.sink.write_failed diff --git a/internal/managers/conformance_test.go b/internal/managers/conformance_test.go index 0dfd44de..aa5ad253 100644 --- a/internal/managers/conformance_test.go +++ b/internal/managers/conformance_test.go @@ -29,8 +29,9 @@ func TestManagerTumblingWindow_Conformance(t *testing.T) { conformance.Managers(t, conformance.ManagerSubject{ Integration: "manager.tumbling_window", - New: func(t *testing.T, sink core.Sink, poll time.Duration) conformance.Manager { - return NewTumbling(conn, collectSQL, deleteSQL, poll, sink, &sync.Mutex{}) + New: func(t *testing.T, sink core.Sink, poll time.Duration, budget *core.DrainBudget) conformance.Manager { + return NewTumbling(conn, collectSQL, deleteSQL, poll, sink, &sync.Mutex{}, + WithDrainBudget(budget)) }, // Every seeded row is ten minutes old, so the close predicate the diff --git a/internal/managers/tumbling.go b/internal/managers/tumbling.go index 2a439b78..b3f62adb 100644 --- a/internal/managers/tumbling.go +++ b/internal/managers/tumbling.go @@ -12,6 +12,7 @@ import ( "github.com/apache/arrow-go/v18/arrow" "github.com/apache/arrow-go/v18/arrow/array" "github.com/turbolytics/sql-flow/internal/core" + "github.com/turbolytics/sql-flow/internal/errs" "go.uber.org/zap" ) @@ -32,6 +33,10 @@ type Tumbling struct { // both run against the same DuckDB connection. lock *sync.Mutex logger *zap.Logger + + // drain bounds the final poll after a cancel. Shared with the turbine, + // so one deadline covers the whole shutdown. + drain *core.DrainBudget } func NewTumbling( @@ -59,6 +64,9 @@ func NewTumbling( for _, opt := range opts { opt(m) } + if m.drain == nil { + m.drain = core.NewDrainBudget(core.DefaultDrainDeadline) + } return m } @@ -70,6 +78,12 @@ func WithLogger(l *zap.Logger) TumblingOption { } } +// WithDrainBudget bounds the final poll after a cancel. A manager built +// without one gets core.DefaultDrainDeadline. +func WithDrainBudget(b *core.DrainBudget) TumblingOption { + return func(m *Tumbling) { m.drain = b } +} + // Start polls until the context is cancelled, then polls once more so windows // that closed during the final interval are not stranded in the table. // @@ -91,18 +105,40 @@ func (m *Tumbling) Start(ctx context.Context) error { for { select { case <-ticker.C: - if err := m.Poll(ctx); err != nil { + err := m.Poll(ctx) + if err != nil && ctx.Err() == nil { m.logger.Error("poll failed, stopping the manager", zap.Error(err)) return fmt.Errorf("tumbling window manager: %w", err) } - case <-ctx.Done(): - if err := m.Poll(context.Background()); err != nil { - m.logger.Error("final poll failed", zap.Error(err)) - return fmt.Errorf("tumbling window manager: final poll: %w", err) + if ctx.Err() == nil { + continue } - return nil + // The cancel landed during that poll, and the poll failed + // because of it or finished just before it. Either way the + // final poll below is the one that counts: returning here + // skipped it, and a window that closed during the last interval + // stayed in the table with the process reporting a clean stop. + case <-ctx.Done(): } + return m.finalPoll() + } +} + +// finalPoll publishes what closed during the last interval, on the drain +// budget. A poll the deadline ended is reported as the drain running out of +// time, not as the sink's own failure: the windows are still in the table, +// and the next start publishes them. +func (m *Tumbling) finalPoll() error { + err := m.Poll(m.drain.Context()) + if err == nil { + return nil + } + if m.drain.Exceeded() { + err = errs.Wrap(errs.CodeDrainIncomplete, err, + "drain deadline %s reached before the final poll finished", m.drain.Deadline()) } + m.logger.Error("final poll failed", zap.Error(err)) + return fmt.Errorf("tumbling window manager: final poll: %w", err) } // Poll publishes any closed windows and removes them from the table. diff --git a/internal/managers/tumbling_test.go b/internal/managers/tumbling_test.go index e0772ef3..efc2b089 100644 --- a/internal/managers/tumbling_test.go +++ b/internal/managers/tumbling_test.go @@ -6,6 +6,7 @@ import ( "github.com/turbolytics/sql-flow/internal/core" "github.com/turbolytics/sql-flow/internal/coverage" "github.com/turbolytics/sql-flow/internal/duckdb" + "github.com/turbolytics/sql-flow/internal/errs" "os" "path/filepath" "sync" @@ -742,3 +743,97 @@ func TestManagerTumblingWindow__ReplayStillClosesEachWindowOnce(t *testing.T) { assert.Equal(t, int64(2), rows) assert.Equal(t, int64(1), countRows(t, conn, "agg_cities_count")) } + +// hangingSink blocks in Flush until its context ends: the sink a drain +// deadline exists for. +type hangingSink struct{} + +func (hangingSink) WriteTable(context.Context, arrow.Table) error { return nil } + +func (hangingSink) Flush(ctx context.Context) error { + <-ctx.Done() + return ctx.Err() +} + +// The final poll runs on the shutdown budget. A sink that never answers must +// not hold the process past it, and the closed window stays in the table for +// the next start to publish. +func TestManagerTumblingWindow__FinalPollStopsAtTheDrainDeadline(t *testing.T) { + coverage.Covers(t, "manager.tumbling_window") + conn, cleanup := newTestConn(t) + defer cleanup() + seedWindows(t, conn) + + budget := core.NewDrainBudget(200 * time.Millisecond) + defer budget.Stop() + m := NewTumbling(conn, collectSQL, deleteSQL, time.Hour, hangingSink{}, &sync.Mutex{}, + WithDrainBudget(budget)) + + ctx, cancel := context.WithCancel(context.Background()) + done := make(chan error, 1) + go func() { done <- m.Start(ctx) }() + cancel() + + select { + case err := <-done: + assert.Equal(t, errs.CodeDrainIncomplete, errs.CodeOf(err)) + case <-time.After(5 * time.Second): + t.Fatal("the final poll outlived the drain deadline") + } + assert.That(t, budget.Exceeded()) + // Two closed rows and one open: nothing was deleted. + assert.Equal(t, int64(3), countRows(t, conn, "agg_cities_count")) +} + +// countingHangingSink is a hangingSink that counts its flushes. +type countingHangingSink struct { + hangingSink + mu sync.Mutex + flushes int + entered chan struct{} +} + +func (s *countingHangingSink) Flush(ctx context.Context) error { + s.mu.Lock() + s.flushes++ + s.mu.Unlock() + select { + case s.entered <- struct{}{}: + default: + } + return s.hangingSink.Flush(ctx) +} + +// A cancel that lands during a regular poll still gets a final poll. The +// regular poll fails because its context ended, and Start used to return +// that failure without ever running the final poll, so a window that closed +// during the last interval stayed in the table. +func TestManagerTumblingWindow__ACancelDuringAPollStillRunsTheFinalPoll(t *testing.T) { + coverage.Covers(t, "manager.tumbling_window") + conn, cleanup := newTestConn(t) + defer cleanup() + seedWindows(t, conn) + + sink := &countingHangingSink{entered: make(chan struct{}, 1)} + budget := core.NewDrainBudget(200 * time.Millisecond) + defer budget.Stop() + m := NewTumbling(conn, collectSQL, deleteSQL, 10*time.Millisecond, sink, &sync.Mutex{}, + WithDrainBudget(budget)) + + ctx, cancel := context.WithCancel(context.Background()) + done := make(chan error, 1) + go func() { done <- m.Start(ctx) }() + + <-sink.entered + cancel() + select { + case err := <-done: + assert.Equal(t, errs.CodeDrainIncomplete, errs.CodeOf(err)) + case <-time.After(5 * time.Second): + t.Fatal("Start did not return after the cancel") + } + sink.mu.Lock() + defer sink.mu.Unlock() + assert.Equal(t, 2, sink.flushes) + assert.Equal(t, int64(3), countRows(t, conn, "agg_cities_count")) +} diff --git a/internal/sinks/init.go b/internal/sinks/init.go index 28b8ae8a..5dedef6b 100644 --- a/internal/sinks/init.go +++ b/internal/sinks/init.go @@ -30,6 +30,26 @@ type Option func(*options) type options struct { meterProvider metric.MeterProvider role string + retryEvents RetryEvents +} + +// RetryEvents is told when a sink's retry ladder runs. Retry fires per failed +// attempt that will be tried again. Settle fires once when a ladder that +// retried at all stops, whether it delivered, gave up, or was cancelled. +// +// sink names the ladder as role/type, "pipeline/clickhouse" or +// "manager/clickhouse". The type alone was one key for every sink of that +// type, so a manager's ladder settling cleared the pipeline's from the +// health endpoint while it was still running. +type RetryEvents struct { + Retry func(sink string, attempt int, err error) + Settle func(sink string) +} + +// WithRetryEvents adds a listener to the sink's retry ladder. The retry +// counter records regardless. A sink with no ladder never calls it. +func WithRetryEvents(e RetryEvents) Option { + return func(o *options) { o.retryEvents = e } } // WithSinkRole names what this sink is for: "pipeline", "dlq" or "manager". @@ -85,39 +105,37 @@ func New(ctx context.Context, sink config.Sink, conn adbc.Connection, opts ...Op role = core.SinkRolePipeline } + return wrap(built, sink, role, o), nil +} + +// wrap puts the retry ladder and the row counters around a built sink. It is +// the part of New that needs no destination, so it is tested without one. +func wrap(built core.Sink, sink config.Sink, role string, o options) core.Sink { policy := RetryPolicyFrom(sink.Retry) if !retriesHelp(sink.Type) || !policy.Enabled() { - return core.NewCountingSink(built, o.meterProvider, sink.Type, role), nil + return core.NewCountingSink(built, o.meterProvider, sink.Type, role) } r := newRetrying(built, policy) r.onRetry = retryCounter(o.meterProvider, sink.Type) + r.listen(role+"/"+sink.Type, o.retryEvents) // Outside the ladder, so one logical flush is one counted flush. The // totals come out the same either way -- retrying.WriteTable delegates and // a failed attempt adds nothing -- but the invariant needs the position // pinned to mean anything. - return core.NewCountingSink(r, o.meterProvider, sink.Type, role), nil + return core.NewCountingSink(r, o.meterProvider, sink.Type, role) } // retriesHelp reports whether a retry ladder belongs around a sink type. // -// Only the sinks that cross a network to somebody else's server. Kafka is -// excluded on purpose: it hands records to franz-go, which already retries a -// produce with its own backoff, and a second ladder on top of that one delays -// the report without improving delivery. Console, noop and sqlcommand reach -// nothing that can be temporarily unavailable -- sqlcommand writes through the -// pipeline's own DuckDB connection, and a failure there is not a blip. +// The list lives in config.SinkRetries, where `sqlflow validate` can read it +// without linking DuckDB. See that function for why these sinks and no others. // // Kept as a function of the type alone so the policy is testable without // building a sink, which would dial. func retriesHelp(sinkType string) bool { - switch sinkType { - case "clickhouse", "iceberg": - return true - default: - return false - } + return config.SinkRetries(sinkType) } // builders constructs each sink type. diff --git a/internal/sinks/policy.go b/internal/sinks/policy.go index 0b61628d..ae677c16 100644 --- a/internal/sinks/policy.go +++ b/internal/sinks/policy.go @@ -14,11 +14,15 @@ import ( // Retrying is on by default. Before this, one refused connection killed the // process, which cost a cold start, a group rejoin and a rebalance to recover // from a blip. That default was the defect, not a safe baseline. +// +// The attempt count and deadline are declared in internal/config, because +// `sqlflow validate` compares the deadline with the drain deadline and must +// not link this package. const ( - DefaultRetryMaxAttempts = 4 + DefaultRetryMaxAttempts = config.DefaultSinkRetryMaxAttempts DefaultRetryInitialBackoff = 100 * time.Millisecond DefaultRetryMaxBackoff = 2 * time.Second - DefaultRetryDeadline = 10 * time.Second + DefaultRetryDeadline = config.DefaultSinkRetryDeadlineSeconds * time.Second ) // RetryPolicyFrom resolves a config block into a policy, filling in defaults diff --git a/internal/sinks/retry.go b/internal/sinks/retry.go index b22b36cb..2e9558c1 100644 --- a/internal/sinks/retry.go +++ b/internal/sinks/retry.go @@ -46,15 +46,40 @@ type retrying struct { // onRetry reports an attempt that failed and will be tried again, so a // stalled sink is visible before the deadline fires. onRetry func(attempt int, err error) + + // onSettle reports that a ladder which retried at least once has + // stopped, whether it delivered, gave up, or was cancelled. The health + // endpoint clears its "retrying" state on it. + onSettle func() } func newRetrying(inner core.Sink, policy RetryPolicy) *retrying { return &retrying{ - inner: inner, - policy: policy, - sleep: sleepCtx, - now: time.Now, - onRetry: func(int, error) {}, + inner: inner, + policy: policy, + sleep: sleepCtx, + now: time.Now, + onRetry: func(int, error) {}, + onSettle: func() {}, + } +} + +// listen adds a RetryEvents listener beside whatever the ladder already +// reports to, naming the sink on every event. +func (r *retrying) listen(sink string, e RetryEvents) { + if e.Retry != nil { + previous, notify := r.onRetry, e.Retry + r.onRetry = func(attempt int, err error) { + previous(attempt, err) + notify(sink, attempt, err) + } + } + if e.Settle != nil { + previous, notify := r.onSettle, e.Settle + r.onSettle = func() { + previous() + notify(sink) + } } } @@ -97,6 +122,15 @@ func (r *retrying) Flush(ctx context.Context) error { backoff := clamp(r.policy.InitialBackoff, maxBackoff) deadline := r.now().Add(r.policy.Deadline) + // Every return below settles a ladder that retried, so a listener never + // holds a "retrying" state for a flush that has finished. + retried := false + defer func() { + if retried { + r.onSettle() + } + }() + for attempt := 1; ; attempt++ { err := r.inner.Flush(ctx) if err == nil { @@ -125,6 +159,7 @@ func (r *retrying) Flush(ctx context.Context) error { } r.onRetry(attempt, err) + retried = true if sleepErr := r.sleep(ctx, backoff); sleepErr != nil { // The context ended. Report the sink's failure rather than the // cancellation: the sink is why this batch did not land. diff --git a/internal/sinks/retry_test.go b/internal/sinks/retry_test.go index b8ebf521..7a204ff4 100644 --- a/internal/sinks/retry_test.go +++ b/internal/sinks/retry_test.go @@ -357,3 +357,116 @@ func TestSinkRetry_UncodedErrorRunsTheWholeLadder(t *testing.T) { assert.Equal(t, p.MaxAttempts, inner.attempts) assert.Equal(t, errs.CodeSinkUnreachable, errs.CodeOf(err)) } + +// The health endpoint needs to know when a ladder is running and when it has +// stopped, whichever way it stopped. Settle fires once per flush that retried +// at all: after a success, after the last failure, and after a cancel. +func TestSinkRetry_SettleFiresOnceAfterALadderEitherWay(t *testing.T) { + coverage.Covers(t, "sink.retry") + + run := func(ctx context.Context, failures int) (retries, settles int, err error) { + sink := &flakySink{failures: failures, err: errors.New("connection reset by peer")} + r := newRetrying(sink, testPolicy()) + r.onRetry = func(int, error) { retries++ } + r.onSettle = func() { settles++ } + assert.NoError(t, r.WriteTable(ctx, nil)) + return retries, settles, r.Flush(ctx) + } + + // Delivered on the second attempt: one retry, one settle. + retries, settles, err := run(context.Background(), 1) + assert.NoError(t, err) + assert.Equal(t, 1, retries) + assert.Equal(t, 1, settles) + + // Never delivered: the ladder is spent, and it still settles once. + retries, settles, err = run(context.Background(), 99) + assert.Error(t, err) + assert.Equal(t, testPolicy().MaxAttempts-1, retries) + assert.Equal(t, 1, settles) + + // Delivered first time: no ladder ran, so nothing settles. + _, settles, err = run(context.Background(), 0) + assert.NoError(t, err) + assert.Equal(t, 0, settles) + + // Cancelled mid-ladder, which is what a drain deadline does: it settles, + // or /healthz reports a retry in flight for a process that stopped one. + ctx, cancel := context.WithCancel(context.Background()) + sink := &flakySink{failures: 99, err: errors.New("connection reset by peer")} + r := newRetrying(sink, testPolicy()) + settles = 0 + r.onRetry = func(int, error) { cancel() } + r.onSettle = func() { settles++ } + assert.Error(t, r.Flush(ctx)) + assert.Equal(t, 1, settles) +} + +// A failure the ladder does not retry never starts one, so nothing settles. +func TestSinkRetry_ARejectedWriteNeverSettles(t *testing.T) { + coverage.Covers(t, "sink.retry") + sink := &flakySink{failures: 99, err: errs.New(errs.CodeSinkWriteFailed, "rejected")} + r := newRetrying(sink, testPolicy()) + settles := 0 + r.onSettle = func() { settles++ } + assert.Error(t, r.Flush(context.Background())) + assert.Equal(t, 0, settles) +} + +// RetryEvents reach the listener with the sink's type, beside the counter the +// ladder already reports to. +func TestSinkRetry_RetryEventsNameTheSinkType(t *testing.T) { + coverage.Covers(t, "sink.retry") + sink := &flakySink{failures: 2, err: errors.New("connection reset by peer")} + r := newRetrying(sink, testPolicy()) + + counted := 0 + r.onRetry = func(int, error) { counted++ } + + var retried []string + var attempts []int + settled := "" + r.listen("pipeline/clickhouse", RetryEvents{ + Retry: func(sinkType string, attempt int, _ error) { + retried = append(retried, sinkType) + attempts = append(attempts, attempt) + }, + Settle: func(sinkType string) { settled = sinkType }, + }) + + assert.NoError(t, r.Flush(context.Background())) + assert.Equal(t, 2, counted) + assert.DeepEqual(t, []string{"pipeline/clickhouse", "pipeline/clickhouse"}, retried) + assert.DeepEqual(t, []int{1, 2}, attempts) + assert.Equal(t, "pipeline/clickhouse", settled) +} + +// The events reach a listener handed to New through WithRetryEvents, named +// role/type, on a sink the ladder wraps. A sink the ladder does not wrap +// never calls them. This is the wiring /healthz depends on, and nothing else +// exercises it: every other test hands the ladder its listener directly. +func TestSinkRetry_NewWiresRetryEventsByRoleAndType(t *testing.T) { + coverage.Covers(t, "sink.retry") + inner := &flakySink{failures: 1, err: errors.New("connection reset by peer")} + var retried, settled []string + o := options{retryEvents: RetryEvents{ + Retry: func(sink string, _ int, _ error) { retried = append(retried, sink) }, + Settle: func(sink string) { settled = append(settled, sink) }, + }} + // A fast ladder, or the test waits out the default backoff. + conf := config.Sink{Type: "clickhouse", Retry: &config.SinkRetry{InitialBackoffMS: 1}} + + s := wrap(inner, conf, "manager", o) + assert.NoError(t, s.WriteTable(context.Background(), nil)) + assert.NoError(t, s.Flush(context.Background())) + assert.DeepEqual(t, []string{"manager/clickhouse"}, retried) + assert.DeepEqual(t, []string{"manager/clickhouse"}, settled) + + // Kafka gets no ladder, so a failing flush fires nothing. + retried, settled = nil, nil + kafka := wrap(&flakySink{failures: 99, err: errors.New("down")}, + config.Sink{Type: "kafka"}, "pipeline", o) + assert.Error(t, kafka.Flush(context.Background())) + assert.Equal(t, 0, len(retried)) + assert.Equal(t, 0, len(settled)) +} diff --git a/internal/validate/drain.go b/internal/validate/drain.go new file mode 100644 index 00000000..8dedf5b8 --- /dev/null +++ b/internal/validate/drain.go @@ -0,0 +1,105 @@ +package validate + +import ( + "fmt" + "strings" + "time" + + "github.com/turbolytics/sql-flow/internal/config" + "github.com/turbolytics/sql-flow/internal/errs" + "gopkg.in/yaml.v3" +) + +// checkDrainDeadline warns when the sinks' retry ladders can outlive the +// drain. +// +// A short drain deadline is a legitimate choice: the operator wants the +// process out in five seconds whatever the sink is doing. So this is a +// warning and the check passes. What the operator may not have priced is that +// a drain which reaches a retrying sink exits 15 before the ladder finishes, +// and the tail of the stream replays on the next start. +// +// Every sink the pipeline builds is counted, and their ladders are summed: +// the pipeline's own, the dead-letter queue's, and each table manager's all +// spend the one drain budget, and the shutdown runs the loop's flush and then +// each manager's final poll in turn. +func checkDrainDeadline(rendered []byte, rep *Report) { + var conf config.Conf + if err := yaml.Unmarshal(rendered, &conf); err != nil { + // checkSchema has already reported why the YAML did not parse. + rep.SetCheck("pipeline.drain_deadline", StatusSkipped, + "the config did not parse, so there was no pipeline to check") + return + } + + drain := seconds(conf.Pipeline.DrainDeadlineSeconds, config.DefaultDrainDeadlineSeconds) + + type named struct { + path string + sink config.Sink + } + sinks := []named{{"pipeline.sink", conf.Pipeline.Sink}} + if conf.Pipeline.OnError != nil && conf.Pipeline.OnError.DLQ != nil { + sinks = append(sinks, named{"pipeline.on_error.dlq", *conf.Pipeline.OnError.DLQ}) + } + if conf.Tables != nil { + for _, table := range conf.Tables.SQL { + if table.Manager != nil { + sinks = append(sinks, named{ + fmt.Sprintf("tables.sql[%s].manager.sink", table.Name), + table.Manager.Sink, + }) + } + } + } + + var ( + total time.Duration + ladders []string + ) + for _, s := range sinks { + ladder, ok := ladderDeadline(s.sink) + if !ok { + continue + } + total += ladder + ladders = append(ladders, fmt.Sprintf("%s retry.deadline_seconds is %s", s.path, ladder)) + } + if total > drain { + rep.Add(diagnostic(errs.CodeConfigInvalid, SeverityWarning, fmt.Sprintf( + "pipeline.drain_deadline_seconds is %s and the retry ladders it has to cover "+ + "add up to %s (%s), so a drain that reaches a retrying sink exits 15 "+ + "before the ladders finish", + drain, total, strings.Join(ladders, ", ")), nil)) + } + rep.SetCheck("pipeline.drain_deadline", StatusPass, "") +} + +// ladderDeadline is the retry deadline a sink runs under, and false when the +// sink gets no ladder: its type is not wrapped, or max_attempts turns +// retrying off. +func ladderDeadline(s config.Sink) (time.Duration, bool) { + if !config.SinkRetries(s.Type) { + return 0, false + } + attempts, deadline := config.DefaultSinkRetryMaxAttempts, 0 + if s.Retry != nil { + if s.Retry.MaxAttempts > 0 { + attempts = s.Retry.MaxAttempts + } + deadline = s.Retry.DeadlineSeconds + } + if attempts <= 1 { + return 0, false + } + return seconds(deadline, config.DefaultSinkRetryDeadlineSeconds), true +} + +// seconds resolves a configured value the way the engine does: absent, zero +// and negative mean the default. +func seconds(configured, fallback int) time.Duration { + if configured > 0 { + return time.Duration(configured) * time.Second + } + return time.Duration(fallback) * time.Second +} diff --git a/internal/validate/drain_test.go b/internal/validate/drain_test.go new file mode 100644 index 00000000..9e597be3 --- /dev/null +++ b/internal/validate/drain_test.go @@ -0,0 +1,183 @@ +package validate + +import ( + "context" + "fmt" + "strings" + "testing" + + "github.com/turbolytics/sql-flow/internal/coverage" + "github.com/zeebo/assert" +) + +// drainConfig is a pipeline the test fills in three ways: the drain deadline +// line, the sink type, and the sink's retry block. It carries both a +// clickhouse and a kafka block so either type validates. +const drainConfig = `pipeline: + batch_size: 1 + %s + source: + type: kafka + kafka: + brokers: ["localhost:9092"] + group_id: g + auto_offset_reset: earliest + topics: ["t"] + handler: + type: handlers.InferredMemBatch + sql: SELECT 1 + sink: + type: %s + clickhouse: + dsn: clickhouse://localhost:9000 + table: t + kafka: + brokers: ["localhost:9092"] + topic: out +%s +` + +const twentySecondLadder = ` retry: + deadline_seconds: 20` + +func validateDrain(t *testing.T, drainLine, sinkType, retry string) Report { + t.Helper() + rep, err := Validate(context.Background(), Request{ + Path: "drain.yml", + Config: fmt.Sprintf(drainConfig, drainLine, sinkType, retry), + }) + assert.NoError(t, err) + return rep +} + +// drainWarnings returns the diagnostics the drain check raised. +func drainWarnings(rep Report) []Diagnostic { + var out []Diagnostic + for _, d := range rep.Diagnostics { + if strings.Contains(d.Message, "drain_deadline_seconds") { + out = append(out, d) + } + } + return out +} + +// A drain deadline shorter than a sink's retry deadline is a choice, not a +// fault: the operator wants the process out. They are told what it costs, and +// the config stays valid. +func TestValidateSchema_ShortDrainDeadlineWarns(t *testing.T) { + coverage.Covers(t, "validate.schema") + rep := validateDrain(t, "drain_deadline_seconds: 5", "clickhouse", twentySecondLadder) + + assert.That(t, rep.OK) + assert.Equal(t, StatusPass, checkStatus(t, rep, "pipeline.drain_deadline")) + + warnings := drainWarnings(rep) + assert.Equal(t, 1, len(warnings)) + assert.Equal(t, SeverityWarning, warnings[0].Severity) + assert.That(t, strings.Contains(warnings[0].Message, "retry.deadline_seconds")) + assert.That(t, strings.Contains(warnings[0].Message, "pipeline.sink")) + assert.That(t, strings.Contains(warnings[0].Message, "exits 15")) +} + +func TestValidateSchema_LongDrainDeadlineIsQuiet(t *testing.T) { + coverage.Covers(t, "validate.schema") + rep := validateDrain(t, "drain_deadline_seconds: 60", "clickhouse", twentySecondLadder) + + assert.That(t, rep.OK) + assert.Equal(t, StatusPass, checkStatus(t, rep, "pipeline.drain_deadline")) + assert.Equal(t, 0, len(drainWarnings(rep))) +} + +// The defaults agree with each other: a thirty-second drain outlasts a +// ten-second ladder, so a config that sets neither says nothing. +func TestValidateSchema_DefaultDrainOutlastsTheDefaultLadder(t *testing.T) { + coverage.Covers(t, "validate.schema") + rep := validateDrain(t, "", "clickhouse", "") + assert.That(t, rep.OK) + assert.Equal(t, 0, len(drainWarnings(rep))) +} + +// A sink with no ladder has nothing to outlive the drain. The Kafka sink +// hands retries to its client, so a short drain there is not warned about +// even with a retry block present. +func TestValidateSchema_ShortDrainOnASinkWithNoLadderIsQuiet(t *testing.T) { + coverage.Covers(t, "validate.schema") + rep := validateDrain(t, "drain_deadline_seconds: 5", "kafka", twentySecondLadder) + assert.That(t, rep.OK) + assert.Equal(t, 0, len(drainWarnings(rep))) +} + +// max_attempts: 1 turns the ladder off, so its deadline never runs. +func TestValidateSchema_ShortDrainWithRetryingOffIsQuiet(t *testing.T) { + coverage.Covers(t, "validate.schema") + rep := validateDrain(t, "drain_deadline_seconds: 5", "clickhouse", + " retry:\n max_attempts: 1\n deadline_seconds: 20") + assert.That(t, rep.OK) + assert.Equal(t, 0, len(drainWarnings(rep))) +} + +// The ladders share the drain budget, so they are summed. Two ten-second +// ladders under a fifteen-second drain warn, and the warning names both. +func TestValidateSchema_LaddersAreSummedAgainstTheDrain(t *testing.T) { + coverage.Covers(t, "validate.schema") + rep, err := Validate(context.Background(), Request{Path: "drain.yml", Config: ` +tables: + sql: + - name: agg + sql: CREATE TABLE agg (id INT) + manager: + tumbling_window: + collect_closed_windows_sql: SELECT id FROM agg + delete_closed_windows_sql: DELETE FROM agg + sink: + type: iceberg + iceberg: + catalog_name: c + table_name: t + retry: + deadline_seconds: 10 +pipeline: + batch_size: 1 + drain_deadline_seconds: 15 + source: + type: kafka + kafka: + brokers: ["localhost:9092"] + group_id: g + auto_offset_reset: earliest + topics: ["t"] + handler: + type: handlers.InferredMemBatch + sql: SELECT 1 + on_error: + policy: DLQ + dlq: + type: clickhouse + clickhouse: + dsn: clickhouse://localhost:9000 + table: dlq + retry: + deadline_seconds: 10 + sink: + type: console +`}) + assert.NoError(t, err) + assert.That(t, rep.OK) + + warnings := drainWarnings(rep) + assert.Equal(t, 1, len(warnings)) + msg := warnings[0].Message + assert.That(t, strings.Contains(msg, "add up to 20s")) + assert.That(t, strings.Contains(msg, "pipeline.on_error.dlq retry.deadline_seconds is 10s")) + assert.That(t, strings.Contains(msg, "tables.sql[agg].manager.sink retry.deadline_seconds is 10s")) + // The console sink has no ladder and is not in the sum. + assert.That(t, !strings.Contains(msg, "pipeline.sink")) +} + +// The schema rejects a drain deadline of zero. Absent means the default; a +// zero written down is a mistake. +func TestValidateSchema_ZeroDrainDeadlineFails(t *testing.T) { + coverage.Covers(t, "validate.schema") + rep := validateDrain(t, "drain_deadline_seconds: 0", "clickhouse", "") + assert.That(t, !rep.OK) +} diff --git a/internal/validate/schemas/config.json b/internal/validate/schemas/config.json index 60e04607..68d3f8fd 100644 --- a/internal/validate/schemas/config.json +++ b/internal/validate/schemas/config.json @@ -440,6 +440,11 @@ "type": "integer", "description": "Longest a partial batch waits before it is invoked anyway." }, + "drain_deadline_seconds": { + "type": "integer", + "minimum": 1, + "description": "Longest a shutdown may take after SIGTERM. The final batch, the\nmanagers' final poll and the state syncs share it. Absent means 30.\nWhen it passes the process exits 15, and the next start replays what\nwas not written." + }, "state": { "properties": { "path": { diff --git a/internal/validate/validate.go b/internal/validate/validate.go index 0f36373e..1cabce5e 100644 --- a/internal/validate/validate.go +++ b/internal/validate/validate.go @@ -36,6 +36,7 @@ func Validate(ctx context.Context, req Request) (Report, error) { } checkSchema(rendered, &rep) + checkDrainDeadline(rendered, &rep) demoteUnsuppliedVariableErrors(&rep) diff --git a/tests/release/test_image.py b/tests/release/test_image.py index 3fa5e67a..68e71317 100644 --- a/tests/release/test_image.py +++ b/tests/release/test_image.py @@ -236,6 +236,8 @@ def run_docker_container(image, command): EXIT_SINK_UNREACHABLE = 12 EXIT_RESOURCE_LIMIT = 13 EXIT_STATE_CORRUPT = 14 +# Retryable: nothing unwritten was committed, and the next start replays it. +EXIT_DRAIN_INCOMPLETE = 15 # A supervisor must stop on these rather than restart into the same failure. TERMINAL_EXITS = {EXIT_USER_ERROR, EXIT_STATE_CORRUPT} @@ -1004,3 +1006,56 @@ def test_turbostats_endpoint_serves_the_bundle(image, stack): # absent rather than 1970. assert "last_message_at" not in bundle assert bundle["pipeline"]["message_count"] == 0 + + +@pytest.mark.covers("lifecycle.health") +def test_lifecycle_health_reports_healthy_once_committed(image, stack): + """The shipped image answers /healthz with the four-state body. + + Before the first commit the pipeline is starting. The first idle tick + commits, and from then on it is healthy. Both answer 200: neither is a + reason for a supervisor to restart it. + + Driven against the image because what ships is the mux, the health state + run wires into it and the port together, and a unit test proves none of + those joined up. + """ + topic = f"healthz-{int(time.time())}" + # The example sets no flush_interval_seconds, so the idle tick is the + # thirty second default. Three of them is the most the first commit can + # take before /healthz calls the pipeline failed. + wait_seconds = 90 + + with container_writable_dir() as state_dir: + container = DockerContainer(image) \ + .with_volume_mapping(settings.DEV_DIR, "/tmp/conf") \ + .with_volume_mapping(state_dir, "/state", "rw") \ + .with_env("SQLFLOW_KAFKA_BROKERS", "kafka:9092") \ + .with_env("SQLFLOW_STATE_PATH", "/state/state.db") \ + .with_env("SQLFLOW_TOPIC", topic) \ + .with_env("SQLFLOW_GROUP_ID", topic) \ + .with_exposed_ports(8000) \ + .with_network(stack.network) \ + .with_command("run /tmp/conf/config/examples/kafka.stateful.window.yml") + container.start() + try: + wait_for_logs(container, "consumer loop starting", timeout=90) + url = f"http://localhost:{container.get_exposed_port(8000)}/healthz" + first = requests.get(url, timeout=10) + seen = [first.json()["status"]] + deadline = time.time() + wait_seconds + last = first + while seen[-1] != "healthy" and time.time() < deadline: + time.sleep(2) + last = requests.get(url, timeout=10) + seen.append(last.json()["status"]) + finally: + container.stop() + + assert first.status_code == 200, first.text + assert seen[0] in ("starting", "healthy"), seen + assert last.status_code == 200, last.text + assert seen[-1] == "healthy", f"never healthy in {wait_seconds}s: {seen}" + # A pipeline that never left starting and never failed is the only other + # way through this loop, and the assertion above catches it. + assert "failed" not in seen, seen