diff --git a/AGENT.md b/AGENT.md index 9c5fae9..855fb09 100644 --- a/AGENT.md +++ b/AGENT.md @@ -42,7 +42,14 @@ just test-hoglake-e2e # Kafka -> main.py -> hoglake end to end Both boot the server image pinned by digest in `tests/hoglake_stack/stack.py` (bump procedure is in the comment there; `HOGLAKE_SERVER_IMAGE` overrides it -for a run against a locally built server). CI sets +for a run against a locally built server). `stack.compose` resolves that pin +INTO the environment compose interpolates from, and that line is the pin: +without it the compose file's own `:latest` default won the substitution and +`DEFAULT_IMAGE` only reached the `docker pull`, so the digest was downloaded +and the container ran whatever `:latest` happened to be locally. A contract +suite asserting a server nobody chose goes green on the wrong behaviour — +which is how a 1.3.7 typed refusal came back as its pre-1.3.6 wire code +against a two-week-stale local tag. CI sets `MILLPOND_REQUIRE_DOCKER_STACK=1`, which turns "no docker" and "image unavailable" from skips into failures — locally it stays unset so a machine without docker still runs everything else. @@ -166,7 +173,7 @@ Millpond has two independent credential paths that must not interfere (the lake- - **Kafka (MSK)**: SASL/OAUTHBEARER via IRSA. The `aws-msk-iam-sasl-signer-python` library uses the standard AWS credential chain (IRSA projected token → STS → temporary creds). - **S3 (lake data)**: Static IAM credentials via `DUCKDB_S3_ACCESS_KEY_ID` / `_SECRET_ACCESS_KEY`. DuckDB's S3 secret does accept `PROVIDER credential_chain` for IRSA — the maintenance tools (`tools/ducklake_maintenance.py`) use that fallback when no static keys are set, for the per-tenant duckling path. The millpond writer itself still uses `PROVIDER config` with static keys because megaduck/viaduck have an IAM-user Secret synced via ExternalSecret and the writer's startup hasn't been migrated. Switching the writer to credential_chain is a separate change. -- **S3 (hoglake data)**: `HOGLAKE_S3_ACCESS_KEY` / `HOGLAKE_S3_SECRET_KEY`, and they are optional as a PAIR. pyhoglake's `S3Config` passes each key to pyarrow's `S3FileSystem` only when it is not None, so with neither set pyarrow uses the AWS SDK default credential chain — which in Kubernetes is the ServiceAccount's web-identity token (IRSA), the model the hoglake server itself uses. Static keys stay for MinIO (local dev, CI). `config.load()` refuses one without the other and names both variables. pyarrow refuses half a pair too (`S3FileSystem(access_key=...)` with no secret raises `ValueError`), but only when pyhoglake first builds the filesystem and without naming either variable — the config check is about where and how the failure lands, not about a silent fallback that does not exist. `HOGLAKE_S3_ENDPOINT` and `HOGLAKE_S3_REGION` are independent of the key pair — the region is still needed under IRSA. The names are deliberately non-standard for the same reason the DuckLake ones are (see the paragraph below): under `AWS_ACCESS_KEY_ID` / `AWS_SECRET_ACCESS_KEY` they would take precedence in the chain and shadow IRSA for MSK IAM auth. With neither key set, the hoglake write path and MSK auth resolve the SAME IRSA identity, which is the intent. +- **S3 (hoglake data)**: `HOGLAKE_S3_ACCESS_KEY` / `HOGLAKE_S3_SECRET_KEY`, and they are optional as a PAIR. pyhoglake's `S3Config` passes each key to pyarrow's `S3FileSystem` only when it is not None, so with neither set pyarrow uses the AWS SDK default credential chain — which in Kubernetes is the ServiceAccount's web-identity token (IRSA), the model the hoglake server itself uses. Static keys stay for MinIO (local dev, CI). `config.load()` refuses one without the other and names both variables. pyarrow refuses half a pair too (`S3FileSystem(access_key=...)` with no secret raises `ValueError`), but only when pyhoglake first builds the filesystem and without naming either variable — the config check is about where and how the failure lands, not about a silent fallback that does not exist. `HOGLAKE_S3_ENDPOINT` and `HOGLAKE_S3_REGION` are independent of the key pair — the region is still needed under IRSA, and since the pyhoglake 1.3.7 pin it matters MORE, not less. The `fast-upload` extra puts every object at or under 8 MiB up through boto3 instead of pyarrow, so there are now TWO clients on the write path, and `S3Config.put_client` gives the boto3 one the same explicit fields as `S3Config.filesystem` gives pyarrow: each key only when it is not None (so keys-absent still means "resolve from the default chain", which under IRSA is the ServiceAccount's web-identity token), the same endpoint override with the same path-style addressing, and the region when one is set. It also sets botocore's `ignore_configured_endpoint_urls`, because botocore honours `AWS_ENDPOINT_URL` / `AWS_ENDPOINT_URL_S3` and `S3FileSystem` reads none of them — without that one flush could put its small objects in one store and its large ones in another and register both under the same uris. What is NOT identical is the chain underneath: botocore's versus the AWS C++ SDK's inside Arrow, and with `region=None` Arrow resolves the bucket's region while botocore falls back to its own default and leans on S3's region redirect. So: set `HOGLAKE_S3_REGION`. The same split is why the startup probe's old claim — that it issues the write path's own call — is now only true for an object too large for the fast path; it still proves the grant and the credential source, which is what it is for. The names are deliberately non-standard for the same reason the DuckLake ones are (see the paragraph below): under `AWS_ACCESS_KEY_ID` / `AWS_SECRET_ACCESS_KEY` they would take precedence in the chain and shadow IRSA for MSK IAM auth. With neither key set, the hoglake write path and MSK auth resolve the SAME IRSA identity, which is the intent. The S3 credentials do not use the standard `AWS_ACCESS_KEY_ID` / `AWS_SECRET_ACCESS_KEY` — those take precedence in the credential chain and would shadow IRSA for MSK IAM auth. Do not change the S3 credential env var names to the standard AWS names. @@ -258,9 +265,21 @@ records=26402 files=31 partitions=31 arrow_bytes=268435456 trigger=size millpond offsets clickhouse_events_json p3:4128819-4155470 p19:4130021-4156802 ... (32) ``` -Line 1 is a fixed sequence of `key=value` pairs in a fixed order, with no space inside any value (only the version can carry one, so `_message_token` replaces whitespace there). Line 2 lists every partition range sorted by partition number, names the topic once, and ends with the range count; a flush spanning two topics writes one such line per topic. THE OFFSET RANGES ARE THE REASON THE MESSAGE EXISTS: a snapshot's author names the pipeline and its files name object keys, and nothing else ties a published snapshot to a position in the topic — so without them nobody can answer "is offset X in the lake", audit a replay after a crash, or reconcile a gap without reading parquet. Rules for anything that touches it: the text must stay DETERMINISTIC for a given flush (the in-process retry re-sends the frozen payload, and a rebuild in a new process must produce the same text, so nothing wall-clock, random or per-attempt may enter it); it is FORMATTED BEFORE THE UPLOAD in `_prepare` and only attached to the payload afterwards, because everything that can raise after `prepare_append_files` must account for the objects it abandons (`_count_orphans`) and a formatting failure has no such arm — `test_a_formatter_failure_happens_before_any_upload` and a source-order assertion both pin that ordering; the offsets line is bounded at 16 KiB (`_MESSAGE_OFFSETS_LIMIT`), which holds about 780 ranges so that ONE pod owning a whole 512-partition topic (about 10.5 KiB) is never truncated, and over the bound it degrades to `... (+ more)` rather than growing, while the summary line is never truncated; `partitions` counts the partition tuples the fanout produced, which is 0 on an unpartitioned table and equals `files` under the one-file-per-tuple fanout (a `(None,)` tuple, which Iceberg gives a null source value, IS a partition and is counted); `files` is `len(groups)` and must not be read back off the payload, which would re-introduce a post-upload dependency; and `table=` is the destination incarnation (`self._table_uuid`), there for the same reason it is in the idempotency key — without it a range published into a dropped-and-recreated table produces a message byte-identical to its predecessor's. The trigger vocabulary in the message is `size` / `interval` / `final` / `unknown` while `metrics.batches_flushed_total` labels the interval trigger `time` — `_MESSAGE_TRIGGERS` maps the two, in one place, because a rename of the live metric label breaks the existing series and gives no benefit. `millpond=` comes from `cfg.service_version`, read ONCE at construction, so the message and the OTLP `service.version` resource attribute can never disagree about which build wrote a snapshot. `arrow_bytes=` is `batch.nbytes` as `write()` received it (before the unwritable columns are dropped and `_inserted_at` is stamped), which is APPROXIMATELY the flush gate's `pending_bytes` and not equal to it: the gate measures per accumulated table and the sink gets the consolidated one, so the concat, its type promotion and the sort move it — about +0.75% for a sorted flush, about +10% with schema drift. Do not document it as the gate value. The shutdown flush passes `final` explicitly (main.py's finally block), which also makes `batches_flushed_total{trigger="final"}` a series that did not exist before — it used to count as an ordinary interval flush. +Line 1 is a fixed sequence of `key=value` pairs in a fixed order, with no space inside any value (only the version can carry one, so `_message_token` replaces whitespace there). Line 2 lists every partition range sorted by partition number, names the topic once, and ends with the range count; a flush spanning two topics writes one such line per topic. THE OFFSET RANGES ARE THE REASON THE MESSAGE EXISTS: a snapshot's author names the pipeline and its files name object keys, and nothing else ties a published snapshot to a position in the topic — so without them nobody can answer "is offset X in the lake", audit a replay after a crash, or reconcile a gap without reading parquet. Rules for anything that touches it: the text must stay DETERMINISTIC for a given flush (the in-process retry re-sends the frozen payload, and a rebuild in a new process must produce the same text, so nothing wall-clock, random or per-attempt may enter it); it is FORMATTED BEFORE THE UPLOAD in `_prepare` and only attached to the payload afterwards, because everything that can raise after `prepare_append_tables` must account for the objects it abandons (`_count_orphans`) and a formatting failure has no such arm — `test_a_formatter_failure_happens_before_any_upload` and a source-order assertion both pin that ordering; the offsets line is bounded at 16 KiB (`_MESSAGE_OFFSETS_LIMIT`), which holds about 780 ranges so that ONE pod owning a whole 512-partition topic (about 10.5 KiB) is never truncated, and over the bound it degrades to `... (+ more)` rather than growing, while the summary line is never truncated; `partitions` counts the partition tuples the fanout produced, which is 0 on an unpartitioned table and equals `files` under the one-file-per-tuple fanout (a `(None,)` tuple, which Iceberg gives a null source value, IS a partition and is counted); `files` is `len(groups)` and must not be read back off the payload, which would re-introduce a post-upload dependency; and `table=` is the destination incarnation (`self._table_uuid`), there for the same reason it is in the idempotency key — without it a range published into a dropped-and-recreated table produces a message byte-identical to its predecessor's. The trigger vocabulary in the message is `size` / `interval` / `final` / `unknown` while `metrics.batches_flushed_total` labels the interval trigger `time` — `_MESSAGE_TRIGGERS` maps the two, in one place, because a rename of the live metric label breaks the existing series and gives no benefit. `millpond=` comes from `cfg.service_version`, read ONCE at construction, so the message and the OTLP `service.version` resource attribute can never disagree about which build wrote a snapshot. `arrow_bytes=` is `batch.nbytes` as `write()` received it (before the unwritable columns are dropped and `_inserted_at` is stamped), which is APPROXIMATELY the flush gate's `pending_bytes` and not equal to it: the gate measures per accumulated table and the sink gets the consolidated one, so the concat, its type promotion and the sort move it — about +0.75% for a sorted flush, about +10% with schema drift. Do not document it as the gate value. The shutdown flush passes `final` explicitly (main.py's finally block), which also makes `batches_flushed_total{trigger="final"}` a series that did not exist before — it used to count as an ordinary interval flush. -`HoglakeSink.__init__` makes two network calls before the pod can claim readiness: it resolves the catalog, then probes object storage once (`_probe_object_store`) with a zero-byte upload of a fixed marker key, `/_millpond/probe`, through the `S3FileSystem` pyhoglake builds. Zero-byte upload, not a single PutObject: pyarrow's `open_output_stream` opens a multipart upload eagerly, so closing an empty stream sends CreateMultipartUpload → UploadPart(1, 0 bytes) → CompleteMultipartUpload — one empty part, accepted by S3 and MinIO, all three calls authorised by `s3:PutObject` (`s3:AbortMultipartUpload` is not exercised on the success path; it covers an upload that dies half-way). An upload, not a LIST, for three independent reasons: it is the SAME `open_output_stream` call the flush path uploads parquet with (pyhoglake 1.3.0 `client.py:1051` in `prepare_append_files`, `_upload` at `:1353`), so it is mechanically predictive of the write path; the sink's role carries write access under the data path and NOT `ListBucket`, so a LIST tests the wrong grant; and pyarrow's `get_file_info(FileSelector(..., allow_not_found=True))` maps a `NoSuchBucket` 404 onto an empty listing, so a bucket typo in `HOGLAKE_DATA_PATH` passed the probe and failed on the first flush — after the catalog row had frozen the bad path, which hoglake has no route to undo (`allow_not_found=False` does not distinguish the two either: an empty prefix raises the same `FileNotFoundError`). The marker key is fixed, so each boot overwrites it; hoglake ignores objects it never registered (`cleanup` drains only server-queued paths, `verify` is metadata-only), so it is inert, not orphan debt. Failure is a permanent `HoglakeSinkError` naming the marker URI, the catalog, the credential source ("static HOGLAKE_S3_* keys" vs "the AWS default credential chain (IRSA in Kubernetes)"), the SDK's error text and the setting to check (the bucket on `NoSuchBucket` — the data path is frozen in the catalog row, so `HOGLAKE_DATA_PATH` only matters while the catalog is being created; `HOGLAKE_S3_REGION` / `AWS_REGION` on `AuthorizationHeaderMalformed` or `PermanentRedirect`; the static keys on `InvalidAccessKeyId` / `SignatureDoesNotMatch`); never retried, never a liveness check. The probe's success line is the single startup log of the credential source — never the key — and there is no metric. A pyhoglake that stops exposing the private filesystem accessor is a hard startup failure, not a skipped probe: a guard that stops guarding on an attribute rename still reads as verified. +`HoglakeSink.__init__` makes two network calls before the pod can claim readiness: it resolves the catalog, then probes object storage once (`_probe_object_store`) with a zero-byte upload of a fixed marker key, `/_millpond/probe`, through the `S3FileSystem` pyhoglake builds. Zero-byte upload, not a single PutObject: pyarrow's `open_output_stream` opens a multipart upload eagerly, so closing an empty stream sends CreateMultipartUpload → UploadPart(1, 0 bytes) → CompleteMultipartUpload — one empty part, accepted by S3 and MinIO, all three calls authorised by `s3:PutObject` (`s3:AbortMultipartUpload` is not exercised on the success path; it covers an upload that dies half-way). An upload, not a LIST, for three independent reasons: it issues a real write request under the sink's own credentials and so proves the grant the flush path needs (`s3:PutObject` under the data path, and nothing else); the sink's role carries write access under the data path and NOT `ListBucket`, so a LIST tests the wrong grant; and pyarrow's `get_file_info(FileSelector(..., allow_not_found=True))` maps a `NoSuchBucket` 404 onto an empty listing, so a bucket typo in `HOGLAKE_DATA_PATH` passed the probe and failed on the first flush — after the catalog row had frozen the bad path, which hoglake has no route to undo (`allow_not_found=False` does not distinguish the two either: an empty prefix raises the same `FileNotFoundError`). The marker key is fixed, so each boot overwrites it; hoglake ignores objects it never registered (`cleanup` drains only server-queued paths, `verify` is metadata-only), so it is inert, not orphan debt. Failure is a permanent `HoglakeSinkError` naming the marker URI, the catalog, the credential source ("static HOGLAKE_S3_* keys" vs "the AWS default credential chain (IRSA in Kubernetes)"), the SDK's error text and the setting to check (the bucket on `NoSuchBucket` — the data path is frozen in the catalog row, so `HOGLAKE_DATA_PATH` only matters while the catalog is being created; `HOGLAKE_S3_REGION` / `AWS_REGION` on `AuthorizationHeaderMalformed` or `PermanentRedirect`; the static keys on `InvalidAccessKeyId` / `SignatureDoesNotMatch`); never retried, never a liveness check. The probe's success line is the single startup log of the credential source — never the key — and there is no metric. A pyhoglake that stops exposing the private filesystem accessor is a hard startup failure, not a skipped probe: a guard that stops guarding on an attribute rename still reads as verified. ONE CLAIM THIS PARAGRAPH USED TO MAKE AND NO LONGER CAN: that the probe issues the SAME `open_output_stream` call the flush path uploads parquet with. Since the 1.3.7 pin the flush puts every object at or under 8 MiB up through boto3's `put_object` (`pyhoglake/upload.py`, `perform_upload`) and only a larger one through the stream, so the probe exercises the fallback transport and Arrow's credential chain rather than botocore's. The grant is identical and the explicit S3 configuration is identical — see the credential-isolation section for exactly how far that parity goes and where it stops (region resolution). + +A STEADY-STATE HOGLAKE FLUSH MAKES ONE CATALOG REQUEST: the commit. Three things were removed to get there and they only work together. (1) `_prepare` calls `table.prepare_append_tables([(part, partition_values), ...])`, which encodes each already-partitioned Arrow table straight to a parquet buffer and uploads the buffers — no temp directory, no fsync, no re-read for the footer and no second re-read for the upload — with the uploads fanned out 64-wide (`PYHOGLAKE_UPLOAD_CONCURRENCY`, now validated at `config.load()` because pyhoglake refuses a bad value permanently on the first flush) and every object at or under 8 MiB sent as a single boto3 `PutObject`. Peak memory is about THREE Arrow-sized copies plus the parquet, not one plus the parquet: main.py's `consolidated` (held across the whole retry loop), `aligned` from `select().cast()` (a real copy for every column whose type changed), `groups` from `data.filter(mask)` per tuple, and every encoded buffer at once (pyhoglake validates every group before the first upload, which is what keeps a refusal from orphaning objects). What makes it a non-issue is the last term: the prod-us events writer's ~105K rows over ~271 partitions encode to a few MiB. The Arrow side is bounded by `MILLPOND_FLUSH_SIZE` — 100 MiB at the code default and ~1 GiB in the prod-us values file, which is the figure the 16 GiB pod sizing was done against, so do not read ~1 GiB as a property of the code. Do NOT "optimise" it back onto disk on the strength of the old comment's 100MB-doubling argument. (2) The commit KEEPS its `read_snapshot` — `payload.pop("read_snapshot", None)` is gone. `prepare_append_*` binds it to the snapshot the `TableInfo` was resolved at, and the server's conflict scan over that window answers precisely the question the sink used to re-read the table to answer. (3) Because the server answers it, the sink caches the destination's shape (`self._live_info`, read through `_table_info`, with `_adopt_info` as the one place columns and specs are taken from the same read) instead of reading it at the top of every `_prepare`, and `_check_destination_still_ours` — a second `table.info()` immediately before every commit, which is where the incarnation and partition-spec guards lived — is deleted outright. Every remaining read passes `totals=False`; the writer needs the uuid, the columns and the specs, and the totals are a count plus two sums over every live file row (~15M on prod-us), which was the whole cost of the call. THE CACHE HAS A TTL AND IT IS NOT HYGIENE — `_live_info_ttl_s` is a quarter of the catalog's snapshot retention, read from `Catalog._retention_seconds()` so it is the same cached value pyhoglake's own threshold uses, and the factor matters: pyhoglake refreshes `Table._cache` at retention/2, the commit's `read_snapshot` moves forward with that refresh, and a sink staler than pyhoglake would compute partition values under a spec the conflict window can no longer see. A quarter makes "this cache is never staler than `Table._cache`" hold by construction, because every refresh here goes through `table.info()`, which re-seeds that cache in the same call. `inf` (retention disabled) means never, and is correct: pyhoglake's cache never ages out either, so the basis stays pinned at the sink's own read and any later alter is inside the window. The clock is `self._monotonic`, injected so a test can cross the TTL without sleeping. The TTL refresh also runs `_reconcile_specs` on the info it just read (no second request), which is the only thing that makes the "config disagrees with the live layout => stop" tripwire fire on a long-lived pod rather than only at startup. + +The guards did not go away, they moved onto the server's typed refusals (`_DESTINATION_MOVED`, handled in `_commit_prepared` by `_destination_moved`). The server side of the partition-spec guard: `AlterService.alterTable` mints exactly one `table_altered` change row per alter whatever the op list, and `CommitService.checkConflicts` counts `table_dropped`/`table_altered` on every touched table since `read_snapshot` — binding the row-content kinds only to a guarded request's DELETE targets, so for millpond's append-only commit every row the scan can match is DDL and the refusal is always `ddl_since_read_snapshot` rather than a bare conflict. DO NOT READ THAT AS "the basis covers spec drift on its own" — an earlier version of this paragraph did, and it was wrong. The window only covers drift inside it, and only the sink's TTL keeps every spec change inside it (see (3) above and `_live_info_ttl_s`); the two mechanisms are one guard, and removing either reopens silently mis-partitioned files that no later read can detect. What the server does do strictly better than the client-side check it replaced is the TIMING: the check runs inside the commit transaction under the catalog lock, so there is no residual window between checking and committing — which the client-side read admitted to having and could not close. Column drift is the one thing the basis is not needed for at all: pyhoglake compares the encoded footer against the destination schema built from its own read, so an unseen column is a `ValidationError` the alignment self-heal answers. A drop+recreate is covered by neither the window nor the TTL (the scan keys on the resolved, new table id) and is closed solely by `expected_table_uuid`. A drop+recreate is the one drift the basis does not cover (the scan keys on the resolved, new table id) and stays closed by `expected_table_uuid` -> 409 `table_recreated`, which `_prepare` pins to the resolved-and-reconciled incarnation. A basis below the expiry floor is a 410 `ReadSnapshotExpiredError`. All three are `re_prepare`, not retryable: the payload's basis is frozen, the floor only moves forward and an alter does not un-happen, so `_destination_moved` discards the payload (its uploads are orphans, counted), drops `self._live_info`, passes the `Table` to `commit_prepared` so pyhoglake drops ITS writer cache too, and raises ONE retryable `HoglakeSinkError` with the server's exception as `__cause__`. The conversion is load-bearing in both directions: `DdlSinceReadSnapshotError` subclasses `CommitConflictError`, which `is_retryable` calls retryable, so leaving it alone livelocks on a payload that can never be accepted; `ReadSnapshotExpiredError` subclasses `ExpiredError`, which `is_retryable` calls permanent, so leaving THAT alone crashes the pod on a flush a rebuild publishes cleanly. An ordinary `CommitConflictError` keeps the behaviour it always had here (the server judged it, so the payload is dropped and the flush rebuilds under fresh object names), which is why the isinstance arms are ordered subclass-first. + +`millpond_hoglake_orphaned_files_total` now carries a `reason` label with one fixed value per abandonment site — `prepare_failed`, `commit_refused`, `ddl_since_read_snapshot`, `table_recreated`, `read_snapshot_expired`, `already_published`, `superseded`, `shutdown`. `_count_orphans` takes `reason` keyword-only beside the operator-facing `why` sentence, because the two answer to different readers (a dashboard groups by a small fixed vocabulary; the log line has to name this table and this fanout width). Summing over `reason` reproduces the old unlabeled series. + +The sink's cached shape is dropped on EVERY `HoglakeError` out of `commit_prepared` — not only the typed refusals — because pyhoglake's own invalidation predicate is wider than the typed set: it drops `Table._cache` on a `re_prepare` refusal, on a 410, and on any non-retryable refusal whose `read_snapshot` matched that cache (`_basis_was_cached`), which takes in the reused-key 422 that `_accept_already_published` turns into SUCCESS and a 5xx, since `HoglakeError.retryable` is False on the base class. Any of those leaves pyhoglake re-reading on its next prepare and the sink not, so pyhoglake's basis moves forward first and the spec-drift hole reopens INSIDE the TTL. The rule is deliberately "any event that can drop pyhoglake's cache drops ours" (`_drop_cached_shape`) rather than a second copy of `_basis_was_cached`; it over-drops on a plain `commit_conflict`, which costs one read on a rebuild that refusal already forces. Transport failures are excluded: nothing was judged, pyhoglake's cache is untouched, and the payload is replayed verbatim with its basis frozen. A `table_recreated` refusal is the one that calls the full `reset_caches()` instead, because a recreation invalidates the IDENTITY: `_table_uuid` is what `_prepare` pins `expected_table_uuid` to and what `_flush_key` hashes, so dropping only the shape leaves a retry re-preparing against the corpse under the same key, refused identically for the whole budget. + +A FRESH SHAPE IS NOT A RECONCILED SHAPE. `_adopt_info` is reached from schema evolution (`_add_column`, `_promote_column`, their alter receipts) and from `write()`'s alignment self-heal, all of which adopt whatever layout is live and re-stamp the TTL clock with no config check — so `_table_info`'s fresh-path early return used to skip `_reconcile_specs` for exactly the shapes that arrived without one, and a pod drifting columns often enough could postpone the TTL's reconciliation indefinitely while writing under an externally re-specced layout. The fresh path now compares `_spec_identity(info)` (partition + sort tuples, deliberately NOT columns — an `add_column` is not a layout change config has an opinion about) against `_reconciled_specs`, the verdict `_reconcile_specs` records, and re-runs the check when they differ. No table read, and once per actual spec change rather than once per flush. + +Two costs, both deliberate and both measured by the local-stack suites rather than argued. A concurrent `add_column` by another pod now REFUSES the in-flight flush instead of being invisible to it, so a producer rollout spends one rebuild (and one flush's parquet) per racing DDL — `test_concurrent_writers_evolving_and_appending` drives `_write_with_retry` for exactly that reason, and a test that calls `sink.write` directly through a DDL race will see the refusal. And pyhoglake skips its own incarnation pre-flight while its writer cache is warm, so a drop+recreate is caught by the server at the commit rather than before the upload: that flush's objects are orphaned (`test_a_warm_cache_pays_one_flush_of_uploads_for_a_recreation` measures it against the bucket). The server's `HOGLAKE_REFUSE_BLIND_PARTITIONED_APPENDS` flag is the reason the basis is not optional for much longer: it refuses a partitioned append that carries no `read_snapshot`, and millpond was the fleet's reason for keeping it off. The sink also publishes three optional hooks the retry loop duck-types off it, none of which `DuckLakeSink` implements: `is_retryable(exc)` (a veto — a permanent 422 re-raises immediately instead of burning the budget), `write_retry_budget()` and `retry_after_hint()`. @@ -591,7 +610,7 @@ Prometheus metrics and health checks on port 8000 via a custom `http.server.HTTP | `duckdb==1.5.5` | DuckDB Python client (pinned; the ducklake extension is sensitive to minor-version moves) | | `pyducklake>=1.0.17` | Our DuckLake Python API (unused yet; lockstep canary for the duckdb pin) | | `pyarrow>=21.0` | Arrow tables, zero-copy DuckDB integration (floor set by pyhoglake 1.3.0) | -| `pyhoglake>=1.3.0` | Hoglake destination client; 1.3.0 is the floor so a uuid column's parquet carries the UUID logical annotation | +| `pyhoglake[fast-upload]>=1.3.7` | Hoglake destination client. 1.3.0 was the first floor, so a uuid column's parquet carries the UUID logical annotation; 1.3.7 adds `prepare_append_tables` (Arrow -> buffer -> one `PutObject`, 64 uploads in flight), the typed commit refusals that let the sink stop re-reading the table before every commit, and `info(totals=False)`. The `fast-upload` extra is boto3: without it pyhoglake warns and falls back to pyarrow's three-request multipart writer for every small object | | `orjson>=3.10` | Fast JSON parsing (Rust) | | `prometheus-client>=0.21` | Metrics exposition | | `pytz>=2024.1` | Required by duckdb's TIMESTAMPTZ Python conversion (1.5.x doesn't accept stdlib zoneinfo) | @@ -609,9 +628,12 @@ wire contract is the server's OpenAPI spec, pinned per release tag: - v1.2.0: - A live server also serves its own copy at `/openapi.yaml`. -When the `pyhoglake` dependency lands here, the `[tool.uv]` -`exclude-newer` cooldown will exclude a fresh release; add a fixed-date -carve-out like the existing pyducklake one. +The `[tool.uv]` `exclude-newer` cooldown excludes a fresh release, so +`exclude-newer-package` carries a fixed-date carve-out for `pyhoglake` +alongside the pyducklake one. BUMP BOTH TOGETHER: the version floor in +`[project].dependencies` and that date. A floor the cooldown cannot +reach makes `uv lock` fail with a resolution error that says nothing +about the date. ## Project Structure diff --git a/README.md b/README.md index 931eb74..72af304 100644 --- a/README.md +++ b/README.md @@ -48,7 +48,7 @@ Millpond writes to one of two destinations, selected by `MILLPOND_DESTINATION` ( | | DuckLake | Hoglake | |---|---|---| | Catalog | Postgres (via DuckDB ducklake extension) | The hoglake control plane (REST service over Postgres; clients never touch its database) | -| Storage | S3 / S3-compatible | S3 / S3-compatible — millpond writes the parquet itself via pyhoglake and registers it in a footer-shipping commit; the server never opens data files | +| Storage | S3 / S3-compatible | S3 / S3-compatible — millpond writes the parquet itself via pyhoglake and registers it in a footer-shipping commit; the server never opens data files. Each partition group is encoded from Arrow straight to a buffer and uploaded as a single `PutObject` (boto3, objects ≤ 8 MiB), 64 in flight; no temp files, and a 271-file flush is ~5 waves of round trips rather than 271 serial three-request multipart uploads | | Reader ecosystem | DuckDB-native; growing third-party support | hoglake duckdb-client, Trino connector, changefeed consumers (hedgerow) | | Partitioning | Caller-supplied via `DUCKLAKE_PARTITION_BY`; arbitrary DDL expression | `HOGLAKE_PARTITION_BY` mapped onto Iceberg-semantics transforms (`identity`, `year`, `month`, `day`, `hour`, `bucket(col, N)`) at table creation, verified afterwards, and reconciled against the live table on every resolve; one parquet file per partition tuple per flush, all in one atomic commit | | Sort order | Not declared (batches pre-sorted via `MILLPOND_SORT_BY`) | `MILLPOND_SORT_BY` additionally declared as the table's sort order at creation (advisory for writers, binding for hoglake compaction), and reconciled like the partition spec | @@ -56,9 +56,9 @@ Millpond writes to one of two destinations, selected by `MILLPOND_DESTINATION` ( | VARIANT dual-write | Supported (`MILLPOND_VARIANT_COLUMNS`) | **Not supported — rejected at startup.** Events land as TEXT (`properties` stays a JSON string). Deferred until hoglake grows a variant path millpond can target. | | Maintenance tooling | Bundled (`tools/ducklake_maintenance.py` CronJob CLI, `tools/ducklake_metrics.py` exporter — daemon or one-shot push) | Server-side (hoglake expiry/cleanup/compaction loops) — nothing bundled here | | `_inserted_at` column | Added at INSERT via DuckDB `NOW()` (per-row, microsecond drift possible within a flush) | Stamped Arrow-side, one timestamptz value per flush (every row in a flush shares it) | -| Multi-pod concurrent writes | Native; idempotent DDL handles races | Native; appends never conflict with appends, concurrent DDL 409s are absorbed by re-resolve, and the incarnation guard (`expected_table_uuid`) refuses cross-incarnation appends atomically | +| Multi-pod concurrent writes | Native; idempotent DDL handles races | Native; appends never conflict with appends. Each commit carries the `read_snapshot` its files were built against, so DDL landing in between is refused as `ddl_since_read_snapshot` — not a wrong file — and the flush rebuilds against a fresh read; the incarnation guard (`expected_table_uuid`) refuses cross-incarnation appends atomically | | Startup validation | Connects in the sink constructor | Resolves the catalog in the sink constructor, so a bad URL, bad credentials or a missing catalog fails before the pod claims readiness | -| Commit retries | `DUCKLAKE_MAX_RETRY_COUNT` (inner loop, default 100) under millpond's 3 outer attempts | `HOGLAKE_MAX_RETRY_COUNT` outer attempts (default 8; there is no inner loop), honoring the server's `Retry-After` on 503 backpressure as a floor under the exponential curve | +| Commit retries | `DUCKLAKE_MAX_RETRY_COUNT` (inner loop, default 100) under millpond's 3 outer attempts | `HOGLAKE_MAX_RETRY_COUNT` outer attempts (default 6; there is no inner loop), honoring the server's `Retry-After` on 503 backpressure as a floor under the exponential curve | Both sinks (`millpond/ducklake.py`, `millpond/hoglake.py`) implement the `Sink` protocol (`millpond/sink.py`) and expose three methods to `main.py`: `write(batch) -> int`, `reset_caches()`, `close()`. `make_sink(cfg)` dispatches on the destination with lazy backend imports. @@ -74,18 +74,20 @@ The hoglake path is stronger than that *within a process*, and it has to be. The | Pod dies after the commit applied, before the offsets committed, and the rebuilt flush cuts at the *same* boundary | Recognized by its key and accepted without republishing (`…{outcome="already_published"}`); the flush reports **zero** rows written, because this process published none. The rebuilt upload is orphaned — see below. | | …and the rebuilt flush cuts at a *different* boundary | A different publication by every name anyone has: **the rows land twice**. At-least-once, as above. | | Commit refused (409 conflict, 422 validation) | Zero rows registered, atomically. The prepared payload is dropped (the server has judged it; an identical resend gets the identical answer) and the uploaded parquet is orphaned. | +| Destination altered since the flush's `read_snapshot` (another pod's `add_column`, a re-spec) | Refused as 409 `ddl_since_read_snapshot` — atomically, zero rows. The payload is dropped (its basis is frozen, so replaying is a livelock), the sink's cached table shape is dropped, and the flush rebuilds against a fresh read. Retryable through `_write_with_retry`; the refused flush's parquet is orphaned. | +| The flush's `read_snapshot` fell below the catalog's expiry floor before the commit | Refused 410. Same recovery: the server cannot evaluate a conflict window it no longer retains, the floor only moves forward, so the payload is dropped and the flush rebuilds at a retained snapshot. | | Pod dies before the commit is sent | Nothing published; Kafka replays. The upload, if it happened, is orphaned. | -| Table dropped and recreated under the same name | Refused, never published, in both halves of the window. A recreation the sink has not re-resolved (its cached handle is a *name*, not an incarnation) is caught by the client pre-flight, before anything is uploaded; one that lands after the upload is caught before the commit is sent, or by the server's own `expected_table_uuid` guard, and the prepared payload is dropped and orphaned. Retryable either way: the flush re-resolves, reconciles the recreated table against config, and rebuilds against it — under a key that names the live incarnation, so the new table can never answer from its predecessor's receipt. | +| Table dropped and recreated under the same name | Refused, never published. `_prepare` pins `expected_table_uuid` to the incarnation the sink resolved *and reconciled*, so a recreation is caught either by pyhoglake's pre-flight re-resolve (on a cold writer cache — no upload spent) or by the server's own guard at the commit, as 409 `table_recreated` (on a warm one — that flush's upload is orphaned, which is the price of making the steady-state flush read nothing). Retryable either way: the flush re-resolves, reconciles the recreated table against config, and rebuilds against it — under a key that names the live incarnation, so the new table can never answer from its predecessor's receipt. One case is *not* a refusal and should not be: a commit that applied to the old incarnation and whose response was lost is answered from its **receipt** on replay, before the server resolves any table, so the sink accepts it even though the name now resolves to the new table. Those rows were published — into the table that existed when the commit landed; the drop destroyed them afterwards, which is what a drop does. Re-publishing them into the new incarnation would publish the same flush twice. | -**Orphaned objects are a real, unreclaimed cost.** Hoglake's `cleanup` reclaims only files the *server* queued for removal (snapshot expiry, table drop, compaction staging); files a client uploaded are not in that set, and automated cleanup for them is explicitly future work on the hoglake side. Every parquet millpond uploads without registering is therefore billed storage until somebody deletes it. `millpond_hoglake_orphaned_files_total` counts them, and the warning that accompanies every increment names the **full object URI of each one** (capped per line, with a count of any it left out). +**Orphaned objects are a real, unreclaimed cost.** Hoglake's `cleanup` reclaims only files the *server* queued for removal (snapshot expiry, table drop, compaction staging); files a client uploaded are not in that set, and automated cleanup for them is explicitly future work on the hoglake side. Every parquet millpond uploads without registering is therefore billed storage until somebody deletes it. `millpond_hoglake_orphaned_files_total` counts them, and the warning that accompanies every increment names the **full object URI of each one** (capped per line, with a count of any it left out). The counter carries a `reason` label — one fixed value per abandonment site: `prepare_failed`, `commit_refused`, `ddl_since_read_snapshot`, `table_recreated`, `read_snapshot_expired`, `already_published`, `superseded`, `shutdown` — so a routine shutdown orphan and a re-spec quietly refusing every flush are different series rather than the same number. Summing over `reason` gives the total. > **Delete those URIs, never the `…/{idempotency_key}/` prefix they share.** Object names under that prefix are `{uuid4}-{index}.parquet`, so a retry under the *same* key uploads fresh names beside the old ones. Sweeping the prefix after a later attempt succeeded deletes live, committed files. (An earlier revision of this document, and of the log line itself, advised exactly that sweep. It was wrong.) -The counter is **exact**, on every path. Where a prepared payload exists the files are known to be in object storage and known to number `len(files)`: a commit the server refuses, a rebuilt flush the receipt declines, a payload superseded by the next flush, and a payload still unpublished at `close()`. A flush that fails *inside* `prepare` used to be the gap — millpond had no way to know how far the upload loop got, so it counted nothing and logged an invented upper bound. pyhoglake ≥ 1.1.1 closes it: every exception leaving `prepare_append_files` carries `uploaded_files` (uploads whose output stream closed cleanly) and `uploaded_uris` (their URIs), and a refusal raised before the first upload carries `0` / `()`. millpond reads those rather than reasoning about where in someone else's loop a given failure fires — a deduction that was wrong twice on this branch. Retries do not inflate anything: a held payload is re-sent, not re-uploaded. +The counter is **exact**, on every path. Where a prepared payload exists the files are known to be in object storage and known to number `len(files)`: a commit the server refuses, a rebuilt flush the receipt declines, a payload superseded by the next flush, and a payload still unpublished at `close()`. A flush that fails *inside* `prepare` used to be the gap — millpond had no way to know how far the upload loop got, so it counted nothing and logged an invented upper bound. pyhoglake ≥ 1.1.1 closes it: every exception leaving `prepare_append_tables` carries `uploaded_files` (uploads that completed without error) and `uploaded_uris` (their URIs), and a refusal raised before the first upload carries `0` / `()`. millpond reads those rather than reasoning about where in someone else's loop a given failure fires — a deduction that was wrong twice on this branch, and one the concurrent fan-out now makes impossible in principle: uploads run 64 at a time, so the URIs are *not* a contiguous prefix of the groups (group 7 can land while group 6 fails) and nothing about a file can be inferred from a position or a count. Only the URIs are meaningful. Retries do not inflate anything: a held payload is re-sent, not re-uploaded. Two caveats remain, both pushing the same way — the counter can *undercount*, and still never invents an object: -- **The file a `prepare` failed on is in neither number.** Its upload may never have opened, or may have closed badly over a *truncated* object that really is in storage. The count is therefore a lower bound on objects present, and that one file has to be treated as possibly-there. The warning says so. +- **The file a `prepare` failed on is in neither number.** Its request may never have been accepted, or a multipart close may have failed over a *truncated* object that really is in storage. The count is therefore a lower bound on objects present, and that one file has to be treated as possibly-there. The warning says so. - **The stamp is best effort at the source.** An older pyhoglake does not set the attributes at all, and pyhoglake suppresses the `AttributeError` from an exception type whose `__slots__` refuse them. millpond reads with a `getattr` default of `0`, so either case books nothing rather than raising a second error over a live object-store failure. And, as before, nothing can count the orphan a `SIGKILL` leaves between the upload and the commit. @@ -188,7 +190,7 @@ MILLPOND_TYPED_COLUMNS=uuid:uuid,person_id:uuid,team_id:bigint,project_id:bigint Plain `pa.binary(16)` — the same bytes without the extension type — is **not** used, and a batch that carries one is adopted into `pa.uuid()` rather than passed through. The reason is DuckLake: there the bare form lands as a `BLOB`, silently, from byte-identical data. On hoglake it would now survive either way, because `_prepare` casts to a schema that names `pa.uuid()` and that cast upgrades the bare form — but the coercer has one output type, not one per destination. (A `binary`/`large_binary` column whose values are all exactly 16 bytes is adopted the same way; other widths are nulled per value.) -**The uploaded parquet carries the UUID annotation** (pyhoglake ≥ 1.3.0). pyarrow stamps `FIXED_LEN_BYTE_ARRAY(16)` + `LogicalTypeAnnotation.uuidType()` for `pa.uuid()` and nothing at all for `pa.binary(16)`, and that annotation is what an Iceberg reader — the Trino hoglake connector among them — binds a `uuid` column through. `HoglakeSink._prepare` casts each batch to `columns_to_arrow_schema(info.columns)`, and since 1.3.0 that schema names `pa.uuid()` for a uuid column, so the coercer's extension column passes through unchanged and the annotation reaches the file. 1.3.0 also accepts **both** spellings on append (`pa.uuid()` and bare `fixed_size_binary(16)`), so a mixed fleet where some pods predate this pin keeps writing to the same table. Before 1.3.0 the schema named `pa.binary(16)`, the annotation was lost, and writing it anyway had the file refused — the two sides had to move together, which is why the floor is a pin rather than a workaround here. (1.3.0 requires pyarrow ≥ 21, which is why millpond's pyarrow floor moved with it.) +**The uploaded parquet carries the UUID annotation** (pyhoglake ≥ 1.3.0; the encode moved into `prepare_append_tables` at 1.3.7 and the comparison with it, so the contract is unchanged — the footer is checked against the destination schema either way). pyarrow stamps `FIXED_LEN_BYTE_ARRAY(16)` + `LogicalTypeAnnotation.uuidType()` for `pa.uuid()` and nothing at all for `pa.binary(16)`, and that annotation is what an Iceberg reader — the Trino hoglake connector among them — binds a `uuid` column through. `HoglakeSink._prepare` casts each batch to `columns_to_arrow_schema(info.columns)`, and since 1.3.0 that schema names `pa.uuid()` for a uuid column, so the coercer's extension column passes through unchanged and the annotation reaches the file. 1.3.0 also accepts **both** spellings on append (`pa.uuid()` and bare `fixed_size_binary(16)`), so a mixed fleet where some pods predate this pin keeps writing to the same table. Before 1.3.0 the schema named `pa.binary(16)`, the annotation was lost, and writing it anyway had the file refused — the two sides had to move together, which is why the floor is a pin rather than a workaround here. (1.3.0 requires pyarrow ≥ 21, which is why millpond's pyarrow floor moved with it.) **Downstream stages work on the storage array.** `pa.uuid()` is an extension type and pyarrow's compute kernels refuse one, so the two pre-sink stages reach past it to the `fixed_size_binary(16)` storage: @@ -386,14 +388,17 @@ Read only when `MILLPOND_DESTINATION=hoglake`. Names are validated at startup ag | `HOGLAKE_S3_ENDPOINT` | no | | S3 endpoint override (MinIO etc.); unset = AWS. Independent of the keys. | | `HOGLAKE_S3_REGION` | no | | S3 region. Independent of the keys. Under the default credential chain the SDK falls back to `AWS_REGION`, which the IRSA webhook injects, so this is not strictly required — set it anyway, so a pod pointed at a bucket in another region fails the startup probe instead of signing for the wrong one. | | `HOGLAKE_PARTITION_BY` | no | | Comma-separated partition expression mapped to hoglake transforms at table creation: bare `col` (identity), `year(col)`/`month(col)`/`day(col)`/`hour(col)`, `bucket(col, N)`. Anything outside that vocabulary refuses startup with a clear error — never a per-batch failure. Typical: `team_id,month(_inserted_at)`. | -| `HOGLAKE_MAX_RETRY_COUNT` | no | `8` | Write-path retry attempts. The DuckLake counterpart tunes an *inner* loop under millpond's 3 outer attempts; hoglake has no inner loop, so this IS the budget. Must be positive, and bounded with the timeout below. | +| `HOGLAKE_MAX_RETRY_COUNT` | no | `6` | Write-path retry attempts. The DuckLake counterpart tunes an *inner* loop under millpond's 3 outer attempts; hoglake has no inner loop, so this IS the budget. Must be positive, and bounded with the timeout below. | | `HOGLAKE_REQUEST_TIMEOUT_S` | no | `45` | Per-request HTTP timeout for the catalog client. Deliberately above pyhoglake's hardcoded 30s, which equals the server's own commit-lock admission bound: at an equal timeout the client gives up at the instant the server would have answered `503` + `Retry-After`, so its explicit backpressure signal is nearly unreachable and arrives as a transport failure instead. | +| `PYHOGLAKE_UPLOAD_CONCURRENCY` | no | `64` | pyhoglake's own variable, not millpond's, but validated at `config.load()` the same way every millpond knob is: pyhoglake reads it on the upload path and refuses a bad value as a permanent client-side error, so an unvalidated typo starts the pod cleanly and crashes its first flush. Must be a positive integer; it is capped at the flush's group count anyway, so a value wider than the fan-out only costs threads. | -`HOGLAKE_MAX_RETRY_COUNT` x `HOGLAKE_REQUEST_TIMEOUT_S` bounds how long one flush can sit inside `sink.write()`, and the consume loop is single-threaded: the liveness probe fails the pod after 480s without a poll. **`load()` refuses a combination that can exceed it** — the defaults come to ~474s of the 480s, which is deliberately close to the line (a catalog that has answered nothing in eight minutes is one the pod should die over) but leaves a raise of either knob nowhere to hide. +`HOGLAKE_MAX_RETRY_COUNT` x (`HOGLAKE_REQUEST_TIMEOUT_S` + a per-attempt encode-and-upload allowance) bounds how long one flush can sit inside `sink.write()`, and the consume loop is single-threaded: the liveness probe fails the pod after 480s without a poll. **`load()` refuses a combination that can exceed it** at startup — the defaults come to ~429s of the 480s, leaving ~51s of margin. The allowance is charged *per attempt* because a hoglake retry rebuilds rather than replays whenever the server refuses the commit as `ddl_since_read_snapshot`: the uploaded payload is discarded and the next attempt re-encodes and re-uploads the whole fanout. That term is why the default is 6 rather than 8 — under a model that priced the local work at zero, 8 fit by about 6 seconds, which is inside the error bar of every term in it, and the failure being guarded against is a `SIGKILL` mid-flush with nothing in the pod's own logs. + +**The startup check is a sanity model; the enforcement is a wall clock at runtime.** Three costs are invisible to `attempts x (timeout + prepare)`: `Retry-After` floors each backoff *gap* and only the gap is clamped (at 30s), so six attempts and five floored gaps already exceed the budget on their own; a rebuild — which every `ddl_since_read_snapshot` refusal forces — re-resolves the namespace and table and re-reads the shape, each under its own HTTP timeout; and boto3 retries four times at a 30s read timeout *per object* while `prepare_append_tables` waits for every in-flight upload before it re-raises, so a stalled object store can hold one prepare well past its allowance. Each is bounded alone and none of them together. So before every backoff sleep the retry loop asks whether elapsed + that sleep + the next attempt's reservation would pass `480s - 30s` of margin, and if it would, it stops and re-raises the last error. The outcome is the one exhausting the attempts already gives — crash, restart, replay from Kafka, offsets never advanced — except that it happens while the process can still say why, logged as `flush_deadline_exceeded=true` with the attempts used and the elapsed time, and counted on `millpond_errors_total{type="flush_deadline_exceeded"}`. DuckLake does not publish a deadline (its outer three attempts cannot approach it, and it carries its own inner bound), so that path is unchanged. **The object-store keys are optional, and optional as a PAIR.** Set both for static credentials — that is the MinIO shape, used by local dev and CI. Set neither and pyhoglake passes no key to pyarrow's `S3FileSystem`, which falls through to the AWS SDK's default credential chain; in Kubernetes that is the ServiceAccount's web-identity token (IRSA), the same way the hoglake server itself authenticates, so a pod needs no Secret at all. One key without the other is refused at startup, naming both variables. pyarrow would refuse it too (`S3FileSystem(access_key=...)` with no secret raises `ValueError`), but only when pyhoglake first builds the filesystem and in a message that names neither variable — the config check just moves that to the front and says which half is missing. `HOGLAKE_S3_ENDPOINT` and `HOGLAKE_S3_REGION` are independent of the choice. -**The minimum grant is small.** The sink needs `s3:PutObject` under its data path, plus `s3:AbortMultipartUpload` so an interrupted upload can be cleaned up, and nothing else — it never lists the bucket, and the catalog (not the client) owns every read. The startup probe below issues the same `open_output_stream` call the flush path uploads with, so what it proves is the write request millpond will actually make. +**The minimum grant is small.** The sink needs `s3:PutObject` under its data path, plus `s3:AbortMultipartUpload` so an interrupted multipart upload can be cleaned up, and nothing else — it never lists the bucket, and the catalog (not the client) owns every read. The grant is the same whichever transport a given object takes: with boto3 present (the `pyhoglake[fast-upload]` extra, which millpond pins) an object at or under 8 MiB is one `PutObject` and a larger one is a multipart upload. The startup probe below issues a real write under that grant. **The catalog client has no authentication or TLS credential surface.** The hoglake control plane does not authenticate requests in this version, and `HoglakeClient` accepts no token, header, client certificate or verification setting — `HOGLAKE_URL` must therefore be a trusted-network endpoint (cluster-internal service DNS, not a public hostname). The `HOGLAKE_S3_*` credentials are object-store credentials only; they have nothing to do with reaching the catalog. @@ -401,10 +406,17 @@ Semantics on the hoglake path: - **Text only.** `properties` and every other JSON payload lands as a string column, exactly as the arrow converter produces it. `MILLPOND_VARIANT_COLUMNS` combined with `MILLPOND_DESTINATION=hoglake` is a startup error (hoglake has no VARIANT column type — deferred, not silently skipped). - **Startup.** The catalog is resolved when the sink is constructed, so a wrong `HOGLAKE_URL`, an unreachable control plane or a missing catalog (without `HOGLAKE_DATA_PATH`) fails at startup rather than on the first flush, after the pod has passed its probes and built lag. -- **Credential probe.** The catalog resolve proves the control plane is reachable and says nothing about object storage, and pyarrow resolves S3 credentials lazily — so a role without the write grant used to surface as an S3 403 on the first upload, at the same bad moment. The constructor therefore performs a zero-byte upload of a marker object at `/_millpond/probe` and refuses to start if it fails. Not literally one `PutObject`: pyarrow's `open_output_stream` opens a multipart upload eagerly, so an empty stream closes as CreateMultipartUpload → UploadPart(1, 0 bytes) → CompleteMultipartUpload (one empty part, which S3 and MinIO both accept), all three authorised by `s3:PutObject`. An upload rather than a listing, for three reasons: it is the *same* `open_output_stream` call pyhoglake uploads each parquet file with, so it is mechanically predictive of the write path rather than a nearby cheap operation; it tests the grant the sink actually has, never `ListBucket`; and it cannot pass on a bucket that does not exist — pyarrow's listing maps a `NoSuchBucket` 404 onto an empty prefix, so a typo in `HOGLAKE_DATA_PATH` read as healthy and then failed on the first flush, after the catalog row had frozen the bad path. The marker key is fixed, so every boot overwrites it: at most one object per catalog data path, and hoglake never touches objects it did not register (`cleanup` drains only server-queued paths, `verify` is metadata-only), so it is inert rather than orphan debt. The refusal names the marker path, the catalog, the credential source in use and the SDK's own error text, plus the setting to look at — the bucket on `NoSuchBucket`, `HOGLAKE_S3_REGION` / the pod's `AWS_REGION` on `AuthorizationHeaderMalformed` or `PermanentRedirect`, and the static `HOGLAKE_S3_*` keys on `InvalidAccessKeyId` / `SignatureDoesNotMatch`. It is not retried and it is not a liveness check: a missing grant is config, and config does not heal by waiting. The probe's one log line is also the startup record of the credential source (never the key). There is no metric. +- **Credential probe.** The catalog resolve proves the control plane is reachable and says nothing about object storage, and pyarrow resolves S3 credentials lazily — so a role without the write grant used to surface as an S3 403 on the first upload, at the same bad moment. The constructor therefore performs a zero-byte upload of a marker object at `/_millpond/probe` and refuses to start if it fails. Not literally one `PutObject`: pyarrow's `open_output_stream` opens a multipart upload eagerly, so an empty stream closes as CreateMultipartUpload → UploadPart(1, 0 bytes) → CompleteMultipartUpload (one empty part, which S3 and MinIO both accept), all three authorised by `s3:PutObject`. An upload rather than a listing, for three reasons: it exercises the grant the flush path needs under the sink's own credentials; it tests the grant the sink actually has, never `ListBucket`; and it cannot pass on a bucket that does not exist — pyarrow's listing maps a `NoSuchBucket` 404 onto an empty prefix, so a typo in `HOGLAKE_DATA_PATH` read as healthy and then failed on the first flush, after the catalog row had frozen the bad path. The marker key is fixed, so every boot overwrites it: at most one object per catalog data path, and hoglake never touches objects it did not register (`cleanup` drains only server-queued paths, `verify` is metadata-only), so it is inert rather than orphan debt. The refusal names the marker path, the catalog, the credential source in use and the SDK's own error text, plus the setting to look at — the bucket on `NoSuchBucket`, `HOGLAKE_S3_REGION` / the pod's `AWS_REGION` on `AuthorizationHeaderMalformed` or `PermanentRedirect`, and the static `HOGLAKE_S3_*` keys on `InvalidAccessKeyId` / `SignatureDoesNotMatch`. It is not retried and it is not a liveness check: a missing grant is config, and config does not heal by waiting. The probe's one log line is also the startup record of the credential source (never the key). There is no metric. + + One thing it stopped proving at pyhoglake 1.3.7, stated because the old claim was that it was *mechanically* the write path's own call: the flush now uploads small objects through boto3's `put_object`, while the probe still uses `open_output_stream`. The grant is the same and the explicit configuration is the same — pyhoglake builds both clients from one `S3Config` and gives them the same keys, endpoint override (with the same path-style addressing) and region, and refuses ambient `AWS_ENDPOINT_URL*` on both sides so one flush can never split across two stores. What differs is the credential *chain* underneath: botocore's for the fast path, the AWS C++ SDK's inside Arrow for the probe. For a static-key or keys-absent-under-IRSA deployment both resolve the same identity, which is every millpond deployment; the divergence worth knowing about is region, where botocore falls back to its own default and leans on S3's redirect while Arrow resolves the bucket's — so set `HOGLAKE_S3_REGION` explicitly even under IRSA. - **Bootstrap.** First write ensures namespace → table (concurrent creation by other pods is tolerated at every level) and declares the partition spec + sort order in one alter with field ids resolved from the created schema, then verifies the result. A partition column missing from the schema is fatal; a missing sort field skips the sort-order declaration with a warning (batches are still pre-sorted on present fields). - **Reconciliation.** Creation is two round trips, so a failure between them leaves a table that exists and has no layout. Every later resolve therefore compares the live partition spec and sort order against config: a match proceeds, an unspecced table that config says should be specced gets its declaration (the recovery), and any genuine divergence — a changed `HOGLAKE_PARTITION_BY`, a changed bucket count, a partitioned table under a config that says nothing — is fatal and stays fatal, with the live spec printed in `HOGLAKE_PARTITION_BY`'s own grammar. The intent is that a config typo can never leave a permanently unpartitioned table behind. Two consequences to plan for: **changing the partition spec of a live table is not supported by changing config** (point the pipeline at a new table), and a table whose sort order was declared by something else needs `MILLPOND_SORT_BY` set to match. - **Publication.** Each flush is a prepared upload plus one idempotent commit keyed on its Kafka offset range — see [Destination](#destination) for what that guarantees and what it orphans. +- **Zero catalog reads per steady-state flush.** The flush path needs the destination's columns and specs, and used to read them twice per flush: once at the top of `_prepare` and again in a pre-commit check that the table had not moved under the uploaded payload (plus pyhoglake's own catalog head read). On prod-us each of those carried a live-totals scan — a count and two sums over every live file row, ~15M of them. Now the shape is cached on the sink and the commit carries the `read_snapshot` it was resolved at, which is what makes caching safe rather than optimistic: the server's conflict check on that basis is exactly the question the re-read was asking ("has anything altered, dropped or recreated this table since I looked"), and anything that has comes back as a typed refusal — `ddl_since_read_snapshot`, `table_recreated`, or 410 when the basis itself expired — with zero rows written. The sink then drops its cached shape and the flush rebuilds against a fresh read. Every read it does make passes `totals=False`; the writer has never read a total. + + **The cache has a TTL, and it is load-bearing rather than hygienic.** The conflict window only covers drift *inside* it, and `read_snapshot` comes from pyhoglake's writer cache, which refreshes itself at half the catalog's snapshot retention. Past such a refresh the basis sits *ahead* of an older `ALTER`, so a partition-spec change the sink has not noticed would be outside the window — and nothing on the file or in the request records which transform a partition value was computed under, so the server would accept the files and stamp them with the live `spec_id` while they carried values from the superseded spec. Silent, permanent mis-pruning of every future scan. The sink therefore re-reads at a *quarter* of the retention, half of pyhoglake's threshold, which makes the invariant "this cache is never staler than pyhoglake's" hold by construction (every refresh here goes through `Table.info()`, which re-seeds that cache in the same call). That periodic re-read is also the only point at which a long-lived pod re-checks config against the live layout, so the "a pod that disagrees with the table it writes to stops" rule below now fires on a running fleet and not only at pod start. In steady state it is still zero reads per flush — one read per quarter-retention per pod. + + Precisely what is covered by what: **column** drift needs no TTL (pyhoglake builds the destination schema from its own read and compares it against the encoded parquet footer, so an unseen column is a `ValidationError` the alignment self-heal answers); **spec** drift is covered by the TTL *plus* the conflict window, as above; a **drop + recreate** is covered by neither, because the conflict scan keys on the resolved (new) table id — it is closed solely by `expected_table_uuid` → 409 `table_recreated`. A cache stale within the TTL costs at most one refused flush's uploads; a cache stale *past* it is what the TTL exists to make unreachable. - **Snapshot message.** Every commit records an author (`millpond//`) and a message. The message says what the flush was and where it came from in Kafka: ``` @@ -546,7 +558,7 @@ The flush path has two failure points, each with its own retry policy: | Operation | Attempts | Backoff between failures | On exhaustion | |-----------|----------|--------------------------|---------------| | Lake write (DuckLake) | 3 | 1s then 2s, each jittered upward by up to 25% (last attempt raises immediately) | Re-raise → pod crashes, K8s restarts, replays from last committed offset | -| Lake write (hoglake) | `HOGLAKE_MAX_RETRY_COUNT`, default 8 | 1s doubling, capped at 30s, jittered upward by up to 25%, floored by the server's `Retry-After` when it sends one | as above | +| Lake write (hoglake) | `HOGLAKE_MAX_RETRY_COUNT`, default 6 | 1s doubling, capped at 30s, jittered upward by up to 25%, floored by the server's `Retry-After` when it sends one | as above | | Offset commit | 3 | 0.5s, 1s (last attempt raises immediately) | Re-raise → pod crashes, replays from last committed offset (duplicates bounded by one flush batch) | The two write budgets differ because the backends do: DuckLake retries *internally* (`DUCKLAKE_MAX_RETRY_COUNT`, default 100) underneath millpond's three attempts, while pyhoglake issues one request and raises. Three attempts against a catalog whose backpressure signal is `503` + `Retry-After: 1` — an explicit "the commit queue is convoyed, ask again" — is a crash loop wearing a retry policy's clothes. diff --git a/millpond/config.py b/millpond/config.py index 8aaf6b3..9b1d713 100644 --- a/millpond/config.py +++ b/millpond/config.py @@ -777,11 +777,70 @@ def _bad(entry: str, why: str) -> RuntimeError: _BACKOFF_JITTER = 0.25 +# Local work every hoglake attempt does before it issues its commit, and +# therefore outside the request timeout the model used to be built +# entirely from: encode the fanout's parquet and upload it. It is charged +# PER ATTEMPT because a rebuild really does redo it — which it did not +# used to, because a refused commit was replayed rather than rebuilt, and +# a `ddl_since_read_snapshot` refusal is now a routine per-attempt cost +# while a producer rollout adds columns under a running fleet. +# +# BASIS, so the number is auditable rather than round: the local-stack +# integration suite flushes 9 rows over 3 partitions and the slowest +# observed `_prepare` in those runs is well under a second, which says +# nothing about production. The figure that does is the hoglake-side +# measurement the upload path was built from — ~4.3 s to encode and +# ~5 waves of round trips to upload the prod-us events writer's ~105K +# rows over ~271 partitions, call it ~10 s with the object store +# misbehaving — doubled for headroom. It is NOT measured on this side; +# it is a deliberate over-estimate whose only job is to stop the default +# budget from sitting inside the measurement error of the liveness +# deadline. Re-derive it from a real prod flush profile before trusting +# it to more than that. +_PREPARE_ALLOWANCE_S = 20.0 + + def _hoglake_worst_case_flush_s(max_retries: int, timeout_s: float) -> float: """Longest a single sink.write() can take: every attempt spending its - full request timeout, with the whole backoff ladder between them.""" + full request timeout plus its own encode-and-upload, with the whole + backoff ladder between them.""" ladder = sum(min(_BACKOFF_BASE_S * (2**attempt), _BACKOFF_CAP_S) for attempt in range(max(0, max_retries - 1))) - return max_retries * timeout_s + ladder * (1 + _BACKOFF_JITTER) + return max_retries * (timeout_s + _PREPARE_ALLOWANCE_S) + ladder * (1 + _BACKOFF_JITTER) + + +# How much of the liveness budget the runtime deadline refuses to spend, +# so that the attempt it lets through still has room to finish and the +# consume loop still has room to record a poll afterwards. The startup +# model has no margin of its own because it is not the enforcement. +_FLUSH_DEADLINE_MARGIN_S = 30.0 + + +def hoglake_flush_deadline(timeout_s: float) -> tuple[float, float]: + """(wall-clock budget for one flush, cost to reserve per attempt). + + The RUNTIME half of the liveness story, read by + `main._write_with_retry` before every backoff sleep. The startup + model below cannot see what a real flush actually spends: + + * `_retry_delay` floors each gap with the server's own `Retry-After` + and clamps only the GAP (30 s), not the sum — six attempts and + five floored gaps already exceed the budget on their own; + * a rebuild (which is what every `ddl_since_read_snapshot` refusal + forces) re-resolves the namespace and table and re-reads the + shape, each under its own HTTP timeout, none of which the + attempts x timeout product counts; + * boto3's upload client retries four times at a 30 s read timeout + per object and `prepare_append_tables` waits for every in-flight + upload before it re-raises, so a stalled object store can put one + prepare well past `_PREPARE_ALLOWANCE_S`. + + Each of those is bounded on its own and none of them is bounded + TOGETHER, which is what a wall clock is for. Returned as a pair + rather than read off module constants by main.py so the whole + model — budget, margin and per-attempt reservation — stays in the + file that owns the arithmetic. + """ + return _LIVENESS_BUDGET_S - _FLUSH_DEADLINE_MARGIN_S, timeout_s + _PREPARE_ALLOWANCE_S def _check_hoglake_liveness_budget(max_retries: int, timeout_s: float) -> None: @@ -792,6 +851,14 @@ def _check_hoglake_liveness_budget(max_retries: int, timeout_s: float) -> None: one values-file edit away, and springing it looks like a pod SIGKILLed mid-flush with no explanation in its own logs. The arithmetic that comment describes is now the check. + + A SANITY MODEL, NOT THE ENFORCEMENT. It prices attempts x (timeout + + prepare) plus the unfloored ladder, which is a lower bound on what a + flush can spend — see `hoglake_flush_deadline` for the three things + it cannot see. Its job is to refuse a budget that is obviously + impossible at config time, where the operator can still fix it; the + runtime deadline in `main._write_with_retry` is what actually keeps + a flush inside the liveness window. """ worst = _hoglake_worst_case_flush_s(max_retries, timeout_s) if worst <= _LIVENESS_BUDGET_S: @@ -804,6 +871,47 @@ def _check_hoglake_liveness_budget(max_retries: int, timeout_s: float) -> None: ) +# pyhoglake's upload fan-out knob. Not a millpond variable, which is +# exactly why it is checked here: pyhoglake reads it inside +# `resolve_concurrency`, on the prepared-append path, and refuses a bad +# value as a client-side `ValidationError` — which millpond's +# `is_retryable` correctly calls PERMANENT. So a typo'd fan-out is a pod +# that starts clean, passes its probes, takes its partitions, and then +# crashes on its first flush with a 422-shaped error about a value no +# millpond code mentions. Every other knob is validated at load; this one +# was only not because it belongs to someone else. +_UPLOAD_CONCURRENCY_ENV = "PYHOGLAKE_UPLOAD_CONCURRENCY" + + +def _check_upload_concurrency() -> None: + """Refuse a PYHOGLAKE_UPLOAD_CONCURRENCY pyhoglake would refuse. + + Parsed exactly as `pyhoglake.upload.resolve_concurrency` parses it — + strip, `int()`, reject below 1 — so this cannot refuse a value + pyhoglake accepts or accept one it refuses. Unset is the library's + default (64) and is left alone; an upper bound is deliberately NOT + imposed, because the ceiling is the object store's and pyhoglake + caps the fan-out at the group count anyway. + """ + raw = os.environ.get(_UPLOAD_CONCURRENCY_ENV, "").strip() + if not raw: + return + try: + value = int(raw) + except ValueError: + raise RuntimeError( + f"{_UPLOAD_CONCURRENCY_ENV} must be a positive integer, got {raw!r}. pyhoglake reads it " + f"on the upload path and refuses a bad value permanently, so this would crash the first " + f"flush rather than the pod start." + ) from None + if value < 1: + raise RuntimeError( + f"{_UPLOAD_CONCURRENCY_ENV} must be a positive integer, got {value}. pyhoglake reads it " + f"on the upload path and refuses a bad value permanently, so this would crash the first " + f"flush rather than the pod start." + ) + + _S3_URI = re.compile(r"^s3://[a-z0-9][a-z0-9.\-]{1,61}[a-z0-9](/.*)?$") @@ -897,16 +1005,29 @@ def _load_hoglake_fields() -> dict: # failure instead — the one outcome that has to hold a prepared # payload and resend it blind. # - # The defaults (8 attempts x 45s, plus a jittered ladder main.py caps - # at 30s a step) come to ~474s of the 480s budget. That is the - # all-eight-attempts-black-hole case and it is deliberately close to - # the line: a catalog that has not answered a single request in eight - # minutes is one this pod should be dying over. What the check - # prevents is the same arithmetic going unnoticed when an operator - # raises either knob. - max_retries = _positive_int("HOGLAKE_MAX_RETRY_COUNT", 8) + # The model charges each attempt its request timeout AND a + # _PREPARE_ALLOWANCE_S of local encode-and-upload, because on the + # hoglake path a retry REBUILDS the flush rather than replaying it + # whenever the server refuses the commit as `ddl_since_read_snapshot` + # — which a producer rollout adding columns under a running fleet + # makes a routine per-attempt cost, not a rarity. That term is what + # moved the default: 8 attempts x (45s + 20s) plus the jittered + # ladder is ~634s, well past the 480s deadline, so the default is 6 + # attempts (~429s, leaving ~51s of margin). The previous default of 8 + # fit only because the model did not charge for the work outside the + # request, and "deliberately close to the line" is not a thing to be + # about a SIGKILL: a flush that is killed mid-commit is the one + # outcome with no error in the pod's own logs. + # + # Six is still a real ladder against the case the ladder exists for + # (a convoyed catalog answering 503 + Retry-After, which main.py + # honours as a floor), and an operator who wants more has to lower + # the timeout to buy it — which is the trade being made explicit + # rather than discovered. + max_retries = _positive_int("HOGLAKE_MAX_RETRY_COUNT", 6) timeout_s = _positive_float("HOGLAKE_REQUEST_TIMEOUT_S", 45.0) _check_hoglake_liveness_budget(max_retries, timeout_s) + _check_upload_concurrency() partition_raw = os.environ.get("HOGLAKE_PARTITION_BY", "").strip() if not partition_raw and os.environ.get("DUCKLAKE_PARTITION_BY", "").strip(): diff --git a/millpond/hoglake.py b/millpond/hoglake.py index 442ad9e..7ded4de 100644 --- a/millpond/hoglake.py +++ b/millpond/hoglake.py @@ -3,8 +3,11 @@ The hoglake control plane is a *service* (Kotlin/Ktor + Postgres): clients write parquet to object storage themselves and register the files via footer-shipping commits — the server never opens data files on the write -path. pyhoglake owns that writer path (field-id-stamped parquet, footer -stat extraction, one-commit registration, partitioned fanout appends); +path. pyhoglake owns that writer path (field-id-stamped parquet encoded +straight from Arrow to a buffer, footer stat extraction, concurrent +single-request uploads, one-commit registration, partitioned fanout +appends, and the `read_snapshot` basis the server's conflict check +answers "did DDL touch this table since my read" against); this module owns everything millpond-shaped around it: * startup catalog resolution (in `__init__`, so a bad URL or an absent @@ -65,8 +68,7 @@ from __future__ import annotations import logging -import os -import tempfile +import time import uuid from collections.abc import Sequence from dataclasses import dataclass @@ -75,18 +77,19 @@ import httpx import pyarrow as pa import pyarrow.compute as pc -import pyarrow.parquet as pq from pyhoglake import ( AlreadyExistsError, AlterOp, Column, CommitConflictError, + DdlSinceReadSnapshotError, ExpiredError, HoglakeClient, HoglakeError, IncarnationChangedError, MalformedResponseError, NotFoundError, + ReadSnapshotExpiredError, S3Config, UnsupportedTypeError, ValidationError, @@ -97,6 +100,7 @@ from millpond import arrow_converter, metrics from millpond.config import Config +from millpond.config import hoglake_flush_deadline as config_hoglake_flush_deadline from millpond.sink import SAFE_IDENTIFIER, check_reserved_collision log = logging.getLogger(__name__) @@ -264,10 +268,12 @@ def _probe_hint(sdk_error: str, credential_source: str) -> str: # The refusals pyhoglake raises when a PREPARED file's columns do not # match the destination's, quoted from its source so a re-align is # attempted for the cases a re-align can actually fix: -# * pyhoglake/client.py:901 — the strict schema/field-id comparison on -# the ordinary (non-variant) prepare path, which is the one millpond -# takes; -# * pyhoglake/parquet_schema.py:173 — the same refusal on the variant +# * pyhoglake/client.py:2126 (`_encode_group`, 1.3.7) — the strict +# schema/field-id comparison on the ordinary (non-variant) prepare +# path, which is the one millpond takes. It runs on the ENCODED +# footer, not on the Arrow schema handed in, which is what makes it +# the check a stale cached shape trips: see `_table_info`; +# * pyhoglake/parquet_schema.py:197 — the same refusal on the variant # validation path. # Deliberately NOT here: "prepared file partition arity differs from # destination" (a spec change, which re-aligning columns cannot fix) and @@ -280,6 +286,46 @@ def _probe_hint(sdk_error: str, credential_source: str) -> str: "prepared Parquet columns differ from destination", ) +# The server's typed "the destination moved under your basis" refusals — +# the three pyhoglake flags `re_prepare` rather than `retryable`. Every +# one of them is a commit the server judged and refused atomically with +# zero rows written, and every one of them is cleared by a flush REBUILT +# against a fresh read rather than by resending this payload: a prepared +# request's `read_snapshot` is frozen, the expiry floor only moves +# forward, and an alter does not un-happen. +# +# BOTH are subclasses, and the ARM ORDER in `_commit_prepared` is what +# keeps each on the right path — not, as an earlier version of this +# comment claimed, a difference in whether the payload is replayed. It +# never is: `_is_answered_refusal` discards the payload for ANY 409, a +# plain `commit_conflict` included, and that is deliberate (see +# `_commit_prepared`). What the ordering actually buys: +# +# * `DdlSinceReadSnapshotError` subclasses `CommitConflictError`, so +# without the typed arm first it would be discarded and then +# classified RETRYABLE by `is_retryable`'s conflict arm — correct by +# accident, since the rebuild does clear it, but it would reach +# main.py as "the catalog is contended" and be counted as OCC +# contention rather than as a layout race. +# * `ReadSnapshotExpiredError` subclasses `ExpiredError`, so without +# the typed arm it would be discarded and then classified PERMANENT +# by `is_retryable`'s `ExpiredError` arm — main.py re-raises +# immediately and the pod crashes on a flush a rebuild publishes +# cleanly. That one is not correct by accident, which is why the +# order is load-bearing rather than tidy. +_DESTINATION_MOVED: tuple[type[HoglakeError], ...] = ( + DdlSinceReadSnapshotError, + IncarnationChangedError, + ReadSnapshotExpiredError, +) + +# What the sink assumes the catalog's snapshot retention is when it +# cannot read one, mirroring pyhoglake's own +# `_ASSUMED_RETENTION_SECONDS`. Mirrored rather than imported because it +# is a private module constant; the VALUE matters less than the two +# sides agreeing, and `_live_info_ttl_s` explains why. +_ASSUMED_RETENTION_S = 1800.0 + # How long the offsets line of a commit message may be, in bytes. The # server stores `message` as unbounded text, so this bound is millpond's # own: a snapshot row whose message is larger than the rest of the @@ -371,9 +417,10 @@ def is_retryable(exc: BaseException) -> bool: disagrees with config, a partition column that is not in the table, a declaration the server did not apply). They are statements about the config or the code, and a retry cannot - change either. The one flagged `retryable=True` — the partition - spec moving under a prepared payload — is the exception, because - a REBUILT flush genuinely clears it. + change either. The ones flagged `retryable=True` are the + exception: `_destination_moved` raises one for each of the + server's three re-prepare refusals, and a REBUILT flush + genuinely clears all three. * `ValueError` / `KeyError` / `TypeError` — millpond's own validation (`check_reserved_collision`) and the pyarrow misuse that a schema race can produce. Same argument: waiting @@ -383,6 +430,19 @@ def is_retryable(exc: BaseException) -> bool: read_snapshot below the catalog's expiry floor; only a fresh plan fixes that), `MalformedResponseError` (wire-contract violation), and any other 4xx. + + THE THREE TYPED COMMIT REFUSALS DO NOT REACH HERE, and that is why + their classification below reads oddly: `DdlSinceReadSnapshotError` + (a `CommitConflictError` subclass, so the retryable arm would claim + it) and `ReadSnapshotExpiredError` (an `ExpiredError`, so the + permanent arm would) are both converted by `_commit_prepared` into + `HoglakeSinkError(retryable=True)` — one verdict, carried on the + exception itself, for the one recovery all three have. Reading the + flags here instead would say "retryable" for a payload whose basis is + frozen, which is a livelock, and "permanent" for a flush a rebuild + publishes cleanly, which is a crash. `IncarnationChangedError` keeps + its own retryable verdict for the PRE-UPLOAD shape, which is still + raised straight out of the client's pre-flight. """ # This sink's own refusals, first: they carry their own verdict. if isinstance(exc, HoglakeSinkError): @@ -450,12 +510,22 @@ def _is_answered_refusal(exc: BaseException) -> bool: is still worth holding: hold for transport-uncertain (no status, a timeout, a reset) and for 5xx, drop for an answered 4xx refusal. - BOTH codes reach here. pyhoglake maps every wire 422 to + ALL THREE codes reach here. pyhoglake maps every wire 422 to `ValidationError` and every wire 409 to a conflict class, and `_commit_prepared` catches their common base in one arm so this function is the only place the rule is written down. + + 410 joined them with the typed refusals: a commit's 410 is its own + `read_snapshot` below the catalog's expiry floor + (`ReadSnapshotExpiredError`), which the server answered by refusing + to evaluate a conflict window it cannot see — one judged + transaction, zero rows. It is only ever reached from the commit's + except arm, where a 410 can mean nothing else. The typed arm above + it discards the payload itself, so this is the backstop rather than + the mechanism; it is here because a rule stated for two of three + answered refusals is a rule nobody can rely on. """ - return isinstance(exc, HoglakeError) and exc.status_code in (409, 422) + return isinstance(exc, HoglakeError) and exc.status_code in (409, 410, 422) # How many orphan uris one warning line will carry. The fanout is one @@ -467,10 +537,17 @@ def _is_answered_refusal(exc: BaseException) -> bool: _ORPHAN_URIS_LOGGED = 20 -def _count_orphans(count: int, why: str, uris: Sequence[str] = ()) -> None: +def _count_orphans(count: int, why: str, uris: Sequence[str] = (), *, reason: str) -> None: """Record parquet objects uploaded to the lake that no commit references. + `reason` is the metric's `reason` label and `why` the operator-facing + sentence. Two arguments rather than one because they answer to + different readers: the label has to be a small fixed vocabulary a + dashboard can group by, and the sentence has to name this table, + this fanout width and this status code. Keyword-only so a new call + site cannot acquire a reason by argument position. + Nothing on the server side reclaims a client's uploads, so this counter is the whole observability story for them; an uncounted orphan path is storage nobody can find. Every path that can leave one @@ -500,7 +577,7 @@ def _count_orphans(count: int, why: str, uris: Sequence[str] = ()) -> None: ) else: log.warning("Orphaned %d uploaded parquet file(s) in the lake: %s", count, why) - metrics.hoglake_orphaned_files_total.inc(count) + metrics.hoglake_orphaned_files_total.labels(reason=reason).inc(count) def _is_alignment_refusal(exc: ValidationError) -> bool: @@ -641,6 +718,19 @@ def _sort_tuples(spec) -> tuple[tuple[int, str, str], ...]: return tuple((f.source_field_id, f.direction, f.null_order) for f in spec.fields) +def _spec_identity(info) -> tuple: + """A TableInfo's LAYOUT as comparable tuples: (partition, sort). + + The unit `_reconcile_specs`' verdict is recorded against and + `_table_info` compares an adopted shape to. Columns are deliberately + not in it — a concurrent `add_column` changes the shape without + changing the layout config has an opinion about, and treating that as + a reconciliation-worthy change would run the config check on every + schema-evolution flush for no reason. + """ + return (_partition_tuples(info.partition_spec), _sort_tuples(info.sort_spec)) + + def _describe_partition(spec, live_columns) -> str: """A live spec in HOGLAKE_PARTITION_BY's own grammar, so the operator can paste the fix straight into the values file.""" @@ -881,6 +971,34 @@ def __init__(self, cfg: Config): # — is named from THIS value. self._table_uuid: str | None = None self._live_columns: dict[str, Column] = {} + # The last `TableInfo` read for the destination — the columns AND + # the specs the flush path builds against. Held here rather than + # re-read per flush: see `_table_info` for why that is safe and + # `_destination_moved` for what drops it. + # + # pyhoglake keeps its own copy (`Table._info`, paired with the + # snapshot it was read at in `Table._cache`) and that is the one + # the commit's `read_snapshot` comes from, but it exposes only + # `Table.columns` publicly — not the partition spec, which the + # fanout needs. So this is millpond's copy of the same read, not + # a second source of truth: both are seeded from a `table.info()` + # or a `table.alter()` on the same handle, and the server's + # conflict check on `read_snapshot` is what makes a disagreement + # between them a refusal rather than a wrong file. + self._live_info = None + # When `_live_info` was read, on the MONOTONIC clock, and the + # clock itself — injected so a test can drive the TTL without + # sleeping out a catalog retention period. `_live_info_ttl_s` is + # the whole argument for why there is a TTL at all. + self._live_info_read_at: float | None = None + self._monotonic = time.monotonic + # The (partition, sort) spec tuples `_reconcile_specs` last + # validated against config. See `_table_info`: a shape adopted by + # schema evolution or the alignment self-heal is FRESH but has + # not been reconciled, and without this the fresh-path early + # return skipped the config check for as long as evolution kept + # re-stamping the clock. + self._reconciled_specs: tuple | None = None # The in-flight flush's uploaded-and-not-yet-published commit # request, held IN MEMORY for the lifetime of the flush so a # retry replays it rather than building a second one. Survives @@ -892,10 +1010,6 @@ def __init__(self, cfg: Config): # depends on the live table incarnation, which the retry path # deliberately does not re-resolve. self._prepared_offsets: tuple | None = None - # The live partition spec `_prepare` computed its partition - # VALUES under. A spec change between prepare and commit would - # stamp those values with a spec_id they were not computed for. - self._prepared_spec: tuple[tuple[int, str, int | None], ...] = () # How many times this payload has been sent. >1 on success means # the commit was RESOLVED BY REPLAY: the server either answered # from its receipt or applied it now, and either way the rows @@ -1001,7 +1115,7 @@ def write( # resolved and never will — a different offset range, or an # anonymous batch, which has no identity to replay under. Its # upload is already in object storage with nothing referencing it. - self._discard_prepared("superseded by a new flush") + self._discard_prepared("superseded by a new flush", reason="superseded") batch = self._stamp_inserted_at(batch) table = self._ensure_table(batch.schema) @@ -1028,7 +1142,11 @@ def write( # one. if not _is_alignment_refusal(e): raise - self._adopt_columns(table.info().columns) + # `totals=False`: a writer read wants the uuid, the columns + # and the specs, and the totals are a count plus two sums + # over every live file row of the table (~15M on prod-us). + # This sink has never read one. + self._adopt_info(table.info(totals=False)) batch = self._null_fill_missing(batch) payload = self._prepare(table, batch, key, facts) self._prepared = payload @@ -1051,13 +1169,34 @@ def reset_caches(self) -> None: self._table = None self._table_uuid = None self._live_columns = {} + # The cached shape goes with the handle it was read through: a + # reset means "re-resolve the destination", and keeping a shape + # read off the old handle would let the next flush build against + # a table this pod has not re-reconciled. + self._drop_cached_shape() + + def _drop_cached_shape(self) -> None: + """Forget the destination's cached shape, so the next flush + re-reads it. + + Separate from `reset_caches()` because it is a strictly smaller + thing: the resolved handle and the incarnation stay, which is + right for every event that invalidates the SHAPE without + invalidating the identity (a commit refusal, a 410, a reused-key + 422). `reset_caches()` is the superset and calls this. + """ + self._live_info = None + self._live_info_read_at = None + # The reconciliation verdict belongs to the shape it was reached + # on; a new read has to be re-checked against config. + self._reconciled_specs = None def close(self) -> None: # A payload still held at shutdown is an upload nobody will ever # reference: SIGTERM between prepare and commit. Nothing on the # server reclaims client uploads, so the count is the only trace # it leaves. - self._discard_prepared("the sink closed before its commit resolved") + self._discard_prepared("the sink closed before its commit resolved", reason="shutdown") self._client.close() # -- retry policy (read by main._write_with_retry) --------------------- @@ -1083,6 +1222,29 @@ def write_retry_budget(self) -> tuple[int, float]: deadline.""" return self._cfg.hoglake_max_retry_count, _WRITE_BASE_DELAY_S + def write_flush_deadline(self) -> tuple[float, float]: + """(wall-clock budget for one flush, seconds to reserve for the + next attempt) — the runtime liveness bound main.py enforces. + + The attempt COUNT was never the real limit. The consume loop is + single threaded, so every second a flush spends retrying is a + second `server.HealthState` sees no poll, and three of the things + a flush spends it on are invisible to the startup arithmetic: the + server's `Retry-After` floors each backoff gap (clamped per gap, + not in sum), a rebuild re-resolves the destination and re-reads + its shape under their own timeouts, and a stalled object store + can hold one `prepare_append_tables` far past its allowance + because boto3 retries per object and the fan-out waits for every + upload in flight before it re-raises. + + So main.py stops on the CLOCK instead, and the outcome is the one + exhausting the attempts already produces — raise the last error, + crash, restart, replay from Kafka — except that it happens while + the process can still say why. `DuckLakeSink` does not implement + this: its inner loop has its own bound and its outer three + attempts cannot approach the deadline.""" + return config_hoglake_flush_deadline(self._cfg.hoglake_request_timeout_s) + def _note_response(self, response) -> None: """httpx response hook: remember a Retry-After from a response that is telling us to back off. Deliberately narrow — only @@ -1183,24 +1345,69 @@ def _flush_key(self, table_uuid: str | None, kafka_offsets) -> str: return str(uuid.uuid5(_IDEMPOTENCY_NAMESPACE, name)) def _prepare(self, table, batch: pa.Table, key: str, facts: _FlushFacts) -> dict: - """Write the batch's parquet, upload it, and return the commit + """Encode the batch's parquet, upload it, and return the commit request — WITHOUT publishing it. The split is what makes the retry safe: after this returns, the - files exist in object storage and the request that registers them - is a value we can hold and re-send verbatim. pyhoglake's - `prepare_append_files` owns the upload (streamed from disk in - chunks, so a 100MB flush never doubles in RAM the way an - in-memory serialize does) and the registration's stats/footer - conventions. + objects exist in object storage and the request that registers + them is a value we can hold and re-send verbatim. pyhoglake's + `prepare_append_tables` owns the encode, the upload and the + registration's stats/footer conventions; each group goes straight + from Arrow to a parquet buffer to one `PutObject`, with no temp + file to write, fsync, re-read for the footer and re-read for the + upload. + + MEMORY, because the disk path's whole argument was about it, + and the honest accounting is bigger than "input plus buffers". + Alive at once, at the moment the uploads run: + + * main.py's `consolidated` table, which the retry loop holds for + the whole of `_write_with_retry` — so it survives every + attempt, not just this one; + * `aligned`, the result of `select(...).cast(target)`. A cast + that changes a type (int32 -> int64, string -> uuid) allocates + a new buffer; one that does not is zero-copy, so this is + somewhere between a few columns and a full copy depending on + how much the batch drifted; + * `groups`, which `_partition_groups` materialises with + `data.filter(mask)` per tuple — a full copy of the rows, + partitioned, so about one more `aligned` in total; + * every encoded parquet buffer, which pyhoglake holds all of at + once because it validates every group before the first upload + starts (that is what keeps a refusal from orphaning objects). + + So roughly THREE Arrow-sized copies plus the parquet, not one + plus the parquet. What makes it a non-issue is the last term + being small: the prod-us events writer's ~105K rows over ~271 + partitions encode to a few MiB, because parquet of a sorted, + dictionary-friendly column set is a fraction of its Arrow + representation and the per-group split means no single buffer is + the whole flush. The Arrow side is bounded by MILLPOND_FLUSH_SIZE + — 100 MiB at the code default, and ~1 GiB in the prod-us values + file, which is the figure the 16 GiB pod sizing was done + against; do not read that number as a property of the code. + Nothing is held twice within this method: there is no temp file + and the upload reads the buffer it was handed. Partition fanout is ours to compute because the prepared path puts row-to-partition correctness on the caller — transform math still comes from pyhoglake.transforms, so the Iceberg semantics have exactly one implementation. + + Destinations with a `variant` column are refused by + `prepare_append_tables` (an Arrow rewrite drops the native + parquet VARIANT annotation). Nothing is done about that here and + nothing needs to be: millpond cannot produce such a destination + (`config.load()` rejects MILLPOND_VARIANT_COLUMNS for this + backend, and `table_schema_for_batch` has no variant mapping), + and pointing this sink at someone else's variant table already + failed one line later than it does now — + `columns_to_arrow_schema` raises `UnsupportedTypeError` for a + variant column. Either way it is a permanent refusal that names + the reason, which is the right answer for a destination this + backend does not support. """ - info = table.info() - self._adopt_columns(info.columns) + info = self._table_info(table) target = columns_to_arrow_schema(info.columns) # Null-fill against THESE columns, not the ones the caller # aligned to. `_evolve_and_align` filled against the schema it @@ -1215,12 +1422,11 @@ def _prepare(self, table, batch: pa.Table, key: str, facts: _FlushFacts) -> dict batch = self._null_fill_missing(batch) aligned = batch.select(list(target.names)).cast(target) groups = _partition_groups(aligned, info) - self._prepared_spec = _partition_tuples(info.partition_spec) # Formatted BEFORE the first byte is uploaded, and that ordering # is a safety property, not a style choice. Everything that can # fail after the upload has to account for the objects it # abandons — that is what the `_count_orphans` arm around - # `prepare_append_files` is for. A formatting failure raised + # `prepare_append_tables` is for. A formatting failure raised # after it (a future field that is not a string, say) would # leave those objects with no count, no log and no metric, and # the retry loop would call the TypeError transient and spend @@ -1244,89 +1450,88 @@ def _prepare(self, table, batch: pa.Table, key: str, facts: _FlushFacts) -> dict table_uuid=self._table_uuid, kafka_offsets=facts.kafka_offsets, ) - with tempfile.TemporaryDirectory(prefix="millpond-hoglake-") as tmp: - files = [] - for index, (partition_values, part) in enumerate(groups): - path = os.path.join(tmp, f"part-{index}.parquet") - pq.write_table(part, path) - files.append((path, partition_values)) - try: - payload = table.prepare_append_files( - files, - idempotency_key=key, - # PINNED, not defaulted. Left to its default, - # pyhoglake reads `self.table_uuid` off its own - # `_info` — which the `table.info()` at the top of - # this method has just rebased onto whatever the name - # resolves to NOW. The client's pre-flight, the - # server's guard and `_check_destination_still_ours` - # would then all compare fresh against fresh and pass - # over a drop+recreate that happened under the cached - # handle. Naming the resolved-and-reconciled - # incarnation instead makes the pre-flight fire, and - # `IncarnationChangedError` is retryable, so - # reset_caches re-resolves and `_reconcile_specs` - # finally runs against the table we are writing to. - expected_table_uuid=self._table_uuid, - ) - except Exception as e: - # ONE arm, because there is now one question and - # pyhoglake answers it. Since 1.1.1 every exception - # leaving `prepare_append_files` carries what it had - # already written: `uploaded_files` is how many uploads - # CLOSED cleanly, `uploaded_uris` names exactly those. - # A refusal raised before the first upload carries 0 and - # (), so the same read covers the validation refusals, - # the catalog-side failures and the object-store ones - # alike. - # - # This used to be three arms whose only content was an - # argument about where in someone else's control flow - # each failure could fire ("a validation refusal is a - # property of the whole set, so it fires at index 0"; - # "the catalog work all precedes the upload loop"). The - # arguments were re-derived from pyhoglake's source and - # happened to hold, but deducing another library's - # progress is exactly the defect class this branch - # already shipped twice — once booking a whole fanout - # that was never uploaded, once booking N-1 for a - # refusal that self-heals into a successful flush. Read - # the number; do not reconstruct it. - # - # getattr with defaults, and not only for an older - # client: pyhoglake stamps best-effort and suppresses - # the AttributeError from an exception type whose - # __slots__ refuse the attributes. Zero is then the - # honest answer, and raising an AttributeError over a - # live object-store failure is not. - # - # The file that FAILED is in neither number — its upload - # may never have opened, or may have closed badly over a - # TRUNCATED object that really is there. So the count is - # a lower bound on objects present, and the log says so. - _count_orphans( - int(getattr(e, "uploaded_files", 0)), - f"the prepared upload of {self._cfg.hoglake_namespace}.{self._cfg.hoglake_table} " - f"failed partway through a {len(files)}-file fanout. The file it failed on is not " - "among these and is not counted, but a failed close can leave a truncated object, " - "so treat it as possibly present too", - getattr(e, "uploaded_uris", ()), - ) - raise - # Blind append, exactly as `Table.append` does it. - # `prepare_append_files` pins `read_snapshot` to the catalog head - # at prepare time, and the server's conflict scan then fails the - # commit with a 409 if any DDL touched this table since — which - # for millpond means "another pod added a column", the single - # most likely thing to happen during a producer rollout. A - # prepared payload cannot survive that: its read_snapshot is - # frozen, so the conflict is permanent and the only way out is - # re-uploading under a new registration. Appends never conflict - # with appends, so dropping the field restores the semantics the - # non-idempotent path always had, and the incarnation guard - # (expected_table_uuid, which prepare_append_files puts on the - # entry) remains the real safety mechanism. - payload.pop("read_snapshot", None) + try: + payload = table.prepare_append_tables( + [(part, partition_values) for partition_values, part in groups], + idempotency_key=key, + # PINNED, not defaulted. Left to its default, pyhoglake + # reads `self.table_uuid` off its own `_info` — which any + # refresh of its cache rebases onto whatever the name + # resolves to NOW. The client's pre-flight and the + # server's guard would then both compare fresh against + # fresh and pass over a drop+recreate that happened under + # the cached handle. Naming the resolved-and-reconciled + # incarnation instead makes the guards fire, and + # `IncarnationChangedError` is retryable, so reset_caches + # re-resolves and `_reconcile_specs` finally runs against + # the table we are writing to. + expected_table_uuid=self._table_uuid, + ) + except Exception as e: + # ONE arm, because there is now one question and pyhoglake + # answers it. Since 1.1.1 every exception leaving + # `prepare_append_files` / `prepare_append_tables` carries + # what it had already written: `uploaded_files` is how many + # uploads CLOSED cleanly, `uploaded_uris` names exactly + # those. A refusal raised before the first upload carries 0 + # and (), so the same read covers the validation refusals, + # the catalog-side failures and the object-store ones alike. + # + # This used to be three arms whose only content was an + # argument about where in someone else's control flow each + # failure could fire ("a validation refusal is a property of + # the whole set, so it fires at index 0"; "the catalog work + # all precedes the upload loop"). The arguments were + # re-derived from pyhoglake's source and happened to hold, + # but deducing another library's progress is exactly the + # defect class this branch already shipped twice — once + # booking a whole fanout that was never uploaded, once + # booking N-1 for a refusal that self-heals into a successful + # flush. Read the number; do not reconstruct it. The + # concurrent fan-out makes that literal rather than merely + # prudent: the uris are no longer a contiguous PREFIX of the + # groups, because group 7 can land while group 6 fails, so + # position and count say nothing about any particular file. + # + # getattr with defaults, and not only for an older client: + # pyhoglake stamps best-effort and suppresses the + # AttributeError from an exception type whose __slots__ + # refuse the attributes. Zero is then the honest answer, and + # raising an AttributeError over a live object-store failure + # is not. + # + # The file that FAILED is in neither number — its upload may + # never have opened, or may have closed badly over a + # TRUNCATED object that really is there. So the count is a + # lower bound on objects present, and the log says so. + _count_orphans( + int(getattr(e, "uploaded_files", 0)), + f"the prepared upload of {self._cfg.hoglake_namespace}.{self._cfg.hoglake_table} " + f"failed partway through a {len(groups)}-file fanout. The file it failed on is not " + "among these and is not counted, but a failed close can leave a truncated object, " + "so treat it as possibly present too", + getattr(e, "uploaded_uris", ()), + reason="prepare_failed", + ) + raise + # `read_snapshot` STAYS ON THE PAYLOAD, and it is the conflict + # basis the whole zero-read flush rests on: `prepare_append_*` + # binds it to the snapshot the cached `TableInfo` was resolved + # at, and the server's conflict scan then answers exactly the + # question this sink used to re-read the table to answer — "did + # anything alter, drop or recreate this table since my read". + # Anything that did comes back as a typed, non-retryable refusal + # (`ddl_since_read_snapshot` / `table_recreated` / + # `ReadSnapshotExpiredError`), which `_commit_prepared` answers + # by discarding the payload and rebuilding against a fresh read + # — the recovery a frozen payload actually has. Stripping it + # (which this module did, back when the only answer was an + # untyped retryable 409 that a replay could never clear) also + # leaves the commit with NO conflict window at all, and the + # server's HOGLAKE_REFUSE_BLIND_PARTITIONED_APPENDS flag exists + # to refuse that shape once the fleet stops sending it: a + # partitioned append whose values were computed under a spec + # nobody can prove is still live. payload["author"] = self._author # Attached HERE, with the payload, and not at commit time: the # payload is held across retries and re-sent verbatim, so a @@ -1362,12 +1567,51 @@ def _commit_prepared(self) -> int: if payload is None: # unreachable; an explicit raise, not an assert (python -O strips those) raise HoglakeSinkError("_commit_prepared called with no prepared payload") files = payload["appends"][0]["files"] - self._check_destination_still_ours(payload) self._prepared_sends += 1 replayed = self._prepared_sends > 1 try: - self._catalog.commit_prepared(payload) + # `table=` whenever the sink still holds the handle the + # payload was prepared from: pyhoglake then invalidates THAT + # Table's writer cache on a `re_prepare` refusal, so the + # rebuild cannot send the same stale `read_snapshot` and take + # the same refusal again. `reset_caches()` drops the handle + # and so the cache with it, which is the other way out — but + # one that depends on main.py calling it, and a livelock is + # too expensive a thing to leave to a caller's manners. None + # here is the cross-process form (a replay after a reset), + # where there is no cache left to invalidate. + self._catalog.commit_prepared(payload, table=self._table) except HoglakeError as e: + # FIRST, before any branch, and unconditionally for the whole + # HoglakeError family: drop our cached shape. + # + # THE INVARIANT IS "THE SINK IS NEVER STALER THAN + # PYHOGLAKE'S CACHE" (see `_live_info_ttl_s`), and the TTL + # alone does not hold it here. pyhoglake drops `Table._cache` + # on a `re_prepare` refusal, on a 410, AND on any + # non-retryable refusal whose `read_snapshot` matched that + # cache (`_basis_was_cached`) — which includes the reused-key + # 422 this method turns into SUCCESS, and a 5xx, since + # `HoglakeError.retryable` is False on the base class. Every + # one of those leaves pyhoglake re-reading on its next + # prepare and us not, so pyhoglake's basis moves forward + # first and the same-arity spec-drift hole reopens INSIDE the + # TTL — the exact state the quarter-retention exists to make + # unreachable. + # + # So the rule is not "mirror pyhoglake's predicate" (two + # copies of someone else's invalidation logic, drifting) but + # "any event that can drop pyhoglake's cache drops ours". It + # over-drops on a plain `commit_conflict`, where pyhoglake + # keeps its cache; the cost is one table read on the rebuild + # that refusal already forces, and the alternative is + # re-deriving `_basis_was_cached` from a private helper. + # + # Transport failures are deliberately NOT here: they are not + # HoglakeErrors, nothing was judged, pyhoglake's cache is + # untouched, and the payload is replayed verbatim with its + # basis frozen — so there is nothing to be stale about. + self._drop_cached_shape() # ONE arm, deliberately. Split across `except ValidationError` # and `except HoglakeError` this read as two rules, but # pyhoglake maps every 422 on the wire to `ValidationError` @@ -1377,8 +1621,10 @@ def _commit_prepared(self) -> int: # stated differently in each. if isinstance(e, ValidationError) and _REUSED_KEY_MARKER in _error_text(e): return self._accept_already_published(payload, files) + if isinstance(e, _DESTINATION_MOVED): + raise self._destination_moved(e) from e if _is_answered_refusal(e): - self._discard_prepared(f"the server refused the commit with a {e.status_code}") + self._discard_prepared(f"the server refused the commit with a {e.status_code}", reason="commit_refused") raise # One parquet per partition tuple per flush (fanout appends) — # the hoglake compaction-debt feed rate. Counted AFTER the commit @@ -1397,51 +1643,134 @@ def _commit_prepared(self) -> int: self._clear_prepared() return rows - def _check_destination_still_ours(self, payload: dict) -> None: - """Re-read the destination immediately before publishing, and - refuse to publish into a table that moved under the payload. - - Two things can move between prepare and commit, and the server - catches neither on the commit path: - - * the INCARNATION — it does check `expected_table_uuid`, but it - answers with a bare 409, and by then the upload is spent. This - just says so earlier and in millpond's own words. - * the PARTITION SPEC. A file is registered with its partition - VALUES and stamped with the table's CURRENT spec_id; the server - validates the arity and nothing else, because it never opens - the file. Re-spec a table from `identity(team_id)` to - `bucket(team_id, 16)` — same arity — while a payload is in - flight, and the file lands stamped as bucketed while carrying - identity values. Every future scan prunes it wrongly, forever, - with nothing anywhere saying so. - - The window this closes is prepare-to-commit, which is the wide - one (it contains the upload). The residual — a spec change - between this check and the server taking the commit lock — is not - closable from the client; it needs the server to validate values - it deliberately does not read. + def _destination_moved(self, refused: HoglakeError) -> HoglakeSinkError: + """Turn one of the server's typed re-prepare refusals into this + sink's own retryable stop, having abandoned the payload it refused. + + THIS IS WHERE THE PRE-COMMIT TABLE READ WENT. The sink used to + re-read the destination immediately before every publish, to + refuse a table that had moved under an already-uploaded payload: + + * the INCARNATION, because the server's `expected_table_uuid` + guard answered with a bare 409 that said nothing about which + table it meant; + * the PARTITION SPEC, because a file is registered with the + partition VALUES the client computed and stamped with the + table's CURRENT spec_id. Re-spec from `identity(team_id)` to + `bucket(team_id, 16)` — same arity, so the server's arity check + passes — while a payload is in flight, and the file lands + stamped as bucketed while carrying identity values. Every + future scan prunes it wrongly, forever, with nothing anywhere + saying so. + + Both are now answered by the payload's own `read_snapshot`, + atomically and under the commit lock. What that is and is not: + + * a partition-spec change is an ALTER, and + `AlterService.alterTable` mints exactly one `table_altered` + change row per alter regardless of op count. An append-only + commit's conflict scan counts `table_dropped` and + `table_altered` on every table it touches since + `read_snapshot` (`CommitService.checkConflicts`), and binds + nothing else for an append — `requireUnchangedTables` scopes + the row-content kinds to DELETE targets — so every row it can + match is DDL and the refusal is always the typed + `ddl_since_read_snapshot`, never a bare conflict. Schema DDL + (another pod's add_column) lands in the same arm, which is why + stripping `read_snapshot` used to be necessary and is now + wrong. + * THE WINDOW ONLY COVERS DRIFT INSIDE IT, and for the partition + spec that is NOT automatic — it is bought by + `_live_info_ttl_s`. `read_snapshot` comes from pyhoglake's + writer cache, which refreshes itself at half the catalog's + retention; past a refresh the basis sits AHEAD of an older + alter, the scan finds nothing, and a payload built under the + superseded spec is accepted and stamped with the live spec_id. + Re-reading this sink's own copy at a quarter of the retention + is what makes that state unreachable: the sink is never staler + than `Table._cache`, so a spec the commit cannot see is a spec + no flush is still computing under. This bullet is the whole + reason the TTL exists; deleting it reopens silent permanent + mis-pruning. + * a drop+recreate is covered by NEITHER the window nor the TTL, + because the scan keys on the resolved (new) table id. It is + closed solely by `expected_table_uuid` -> 409 + `table_recreated`, which `_prepare` pins to the + resolved-and-reconciled incarnation. + * and a `read_snapshot` that sank below the catalog's expiry + floor is a 410: the server cannot evaluate the conflict window + at all, so it refuses rather than accepting on a basis it + cannot check. + + What the server DOES do strictly better than the read this + replaced is the timing: the check is inside the commit + transaction under the catalog lock, so there is no residual + window between checking and committing — which the client-side + read admitted to having and could not close. + + Each is non-retryable AS THIS PAYLOAD — the basis is frozen in a + request that must be replayed byte-identically, and the floor and + the alter only ever move forward — and each is cleared by a + REBUILT flush. So the payload is discarded (its uploads are + orphans, counted by `_discard_prepared`), the sink's cached table + info is dropped so the rebuild reads fresh, and the refusal + becomes a `HoglakeSinkError(retryable=True)`: one type, because + there is one recovery, and retryable because `is_retryable` would + otherwise call `ReadSnapshotExpiredError` permanent and re-raise + instead of rebuilding. The server's own exception stays attached + as `__cause__`. """ - expected = payload["appends"][0].get("expected_table_uuid") - info = self._live_table().info() - if expected is not None and info.table_uuid != expected: - self._discard_prepared("the destination table was recreated before the commit") - raise IncarnationChangedError( - f"table {self._cfg.hoglake_namespace}.{self._cfg.hoglake_table} was recreated " - f"while this flush was in flight: prepared against table_uuid {expected}, the " - f"name now resolves to {info.table_uuid}. The prepared upload is abandoned; the " - f"flush rebuilds against the live incarnation." + table_name = f"{self._cfg.hoglake_namespace}.{self._cfg.hoglake_table}" + prepared_for = (self._prepared or {}).get("appends", [{}])[0].get("expected_table_uuid") + if isinstance(refused, IncarnationChangedError): + reason = "table_recreated" + why = "the destination table was recreated before the commit" + message = ( + f"table {table_name} was recreated while this flush was in flight: prepared " + f"against table_uuid {prepared_for}, which the name no longer resolves to " + f"({refused}). The prepared upload is abandoned; the flush rebuilds against the " + f"live incarnation." ) - live_spec = _partition_tuples(info.partition_spec) - if live_spec != self._prepared_spec: - self._discard_prepared("the partition spec changed before the commit") - raise HoglakeSinkError( - f"partition spec of {self._cfg.hoglake_namespace}.{self._cfg.hoglake_table} " - f"changed while this flush was in flight (prepared under {self._prepared_spec}, " - f"live {live_spec}); the prepared files carry values computed under the old spec " - f"and would be registered under the new spec_id. Rebuilding the flush.", - retryable=True, + elif isinstance(refused, ReadSnapshotExpiredError): + reason = "read_snapshot_expired" + why = "the prepared commit's read_snapshot fell below the catalog's expiry floor" + message = ( + f"the conflict basis of this flush to {table_name} expired before the commit " + f"landed ({refused}); the server cannot judge the prepared files against a " + f"snapshot it no longer retains. The prepared upload is abandoned; the flush " + f"rebuilds against a retained snapshot." ) + else: + reason = "ddl_since_read_snapshot" + why = "DDL landed on the destination before the commit" + message = ( + f"schema or partition spec of {table_name} changed while this flush was in " + f"flight ({refused}); the prepared files were built against the old layout and " + f"would be registered under the new one. Rebuilding the flush." + ) + self._discard_prepared(why, reason=reason) + # The cached shape is stale BY THE SERVER'S OWN STATEMENT, so the + # rebuild must read rather than re-derive the same doomed payload + # from it. pyhoglake invalidates its own cache on these refusals + # (`Catalog._commit` does it for a `re_prepare`); this is the half + # that lives on millpond's side of the line. + if isinstance(refused, IncarnationChangedError): + # A RECREATION INVALIDATES THE IDENTITY, NOT JUST THE SHAPE, + # so this one needs the full reset. `self._table` is a handle + # to a name and `self._table_uuid` is the dead incarnation — + # and `_table_uuid` is what `_prepare` pins + # `expected_table_uuid` to AND what `_flush_key` hashes. Drop + # only the shape and a retry re-prepares against the corpse: + # same expected uuid, same key, refused identically, for the + # whole retry budget. main.py's loop calls `reset_caches()` + # between attempts and would mask it, which is exactly why it + # is wrong to rely on: a caller that retries without + # resetting (or any future one) gets a livelock out of a + # refusal that is supposed to be recoverable. + self.reset_caches() + else: + self._drop_cached_shape() + return HoglakeSinkError(message, retryable=True) def _accept_already_published(self, payload: dict, files: list) -> int: """The receipt exists and our request is not the one it was @@ -1459,9 +1788,30 @@ def _accept_already_published(self, payload: dict, files: list) -> int: already there. What this must never do is accept on the strength of a receipt - that belongs somewhere else, so the incarnation is checked - against the live table first (`_check_destination_still_ours` - already ran; this re-states the invariant it upholds). + that belongs somewhere else, and nothing here has to check that + because `_flush_key` already has: `table_uuid` is one of the + components hashed into the key, so a receipt found under THIS key + was written by a commit to THIS incarnation. The key is the + whole of that argument, and it has to be, because NOTHING + re-checks the live incarnation at replay time — not this method, + and not the server. + + THE SERVER ANSWERS FROM THE RECEIPT BEFORE IT RESOLVES ANY + TABLE. `CommitService.doCommit` looks the receipt up first + (v1.3.7, lines ~456-527) and returns it on a hit; table + resolution and the `expected_table_uuid` check are after that + (~555+). So the sequence commit-applies-to-A, response-lost, + A-dropped-and-recreated-as-B, replay returns A's receipt and this + sink accepts — with no 409 `table_recreated` anywhere, even + though the name now resolves to B. + + That is the intended exactly-once-by-key semantics, not a hole in + it. The rows WERE published, into the table that existed when the + commit landed. The drop destroyed them afterwards, which is what + a drop does. Re-publishing them into B would publish the same + flush twice — and the flush's own offsets have already advanced + past it, so there would be nothing to tell the two apart later. + Accepting is the only answer that does not invent a write. Rows returned: ZERO. This process published nothing — some earlier one did — and `records_written_total` counts rows this @@ -1506,22 +1856,16 @@ def _accept_already_published(self, payload: dict, files: list) -> int: len(files), ) metrics.hoglake_commit_replays_total.labels(outcome="already_published").inc() - _count_orphans(len(files), "the offset range was already published", [f["path"] for f in files]) + _count_orphans( + len(files), + "the offset range was already published", + [f["path"] for f in files], + reason="already_published", + ) self._clear_prepared() return 0 - def _live_table(self): - """The destination table handle, resolved if the cache is empty. - - Deliberately NOT cached into `self._table`: that cache means - "resolved and reconciled by `_ensure_table`", and a handle - fetched here has been through neither. - """ - if self._table is not None: - return self._table - return self._catalog.namespace(self._cfg.hoglake_namespace).table(self._cfg.hoglake_table) - - def _discard_prepared(self, why: str) -> None: + def _discard_prepared(self, why: str, *, reason: str) -> None: """Drop a prepared payload that will never be published, and account for the upload it leaves behind.""" if self._prepared is None: @@ -1533,14 +1877,13 @@ def _discard_prepared(self, why: str) -> None: len(files), why, ) - _count_orphans(len(files), why, [f["path"] for f in files]) + _count_orphans(len(files), why, [f["path"] for f in files], reason=reason) self._clear_prepared() def _clear_prepared(self) -> None: self._prepared = None self._prepared_rows = 0 self._prepared_offsets = None - self._prepared_spec = () self._prepared_sends = 0 # -- metadata column --------------------------------------------------- @@ -1604,12 +1947,28 @@ def _probe_object_store(self, catalog) -> None: The shape is chosen for three reasons: - * It is the SAME call the flush path makes. pyhoglake uploads - each parquet file with `_filesystem().open_output_stream(...)` - (client.py:971 in `prepare_append_files`, and `_upload` at - :1280, at the pinned 1.1.1), so what the probe proves at - startup is mechanically the request the write path will issue - — not a nearby operation chosen for being cheap. + * It issues a real write request with the sink's own + credentials, which is the point of writing rather than + looking. It is no longer the same CALL the flush path makes, + and that claim died at pyhoglake 1.3.7: with boto3 present (the `fast-upload` extra, which + millpond pins) `prepare_append_tables` puts every object at or + under 8 MiB up as a single boto3 `put_object` + (`pyhoglake/upload.py`, `perform_upload`), and only a larger + one still takes `open_output_stream`. So the probe exercises + the fallback transport rather than the hot one, and in + particular it resolves credentials through Arrow's C++ SDK + chain while the hot path resolves them through botocore's. + pyhoglake hands both the same explicit fields — access key, + secret key, endpoint override with the same path-style + addressing, region when one is set — and refuses ambient + endpoint configuration on both sides, so a static-key or + IRSA-by-omission deployment proves the same identity either + way. What the probe does NOT cover is a divergence between the + two chains themselves (botocore falls back to its own default + region and leans on S3's region redirect where Arrow resolves + the bucket's region), which is the one reason + `HOGLAKE_S3_REGION` is worth setting explicitly even under + IRSA. * It proves the grant the sink actually needs. The role carries write access under this prefix and nothing else — a LIST would test `s3:ListBucket`, a permission the role is not meant to @@ -1765,11 +2124,11 @@ def _declare_specs(self, table, *, partition: bool = True, sort: bool = True) -> # declared the same thing — which the verification below # proves rather than assumes. log.info("Hoglake spec DDL raced another writer, continuing: %s", e) - info = table.info() - self._adopt_columns(info.columns) + info = table.info(totals=False) + self._adopt_info(info) self._verify_specs(info) - def _reconcile_specs(self, table) -> None: + def _reconcile_specs(self, table, info=None) -> None: """Compare the live partition spec / sort order of an EXISTING table against config. @@ -1784,12 +2143,17 @@ def _reconcile_specs(self, table) -> None: The one divergence that is NOT an error is an unspecced table that config says should be specced: that is the create-then-alter - window reopening, and declaring the spec is the recovery.""" + window reopening, and declaring the spec is the recovery. + + `info` lets a caller that has JUST read the table hand its copy + over instead of paying a second request — which is what + `_table_info` does on every TTL refresh, and the reason this + check is no longer a pod-start-only tripwire. Omitted, it reads.""" # No early out when both knobs are unset: "config says # unpartitioned, the table is partitioned" is the destination-flip # case, and it is the one this check exists for. - info = table.info() - self._adopt_columns(info.columns) + if info is None: + info = self._adopt_info(table.info(totals=False)) want_partition = self._want_partition_fields() live_partition = _partition_tuples(info.partition_spec) if live_partition and live_partition != want_partition: @@ -1832,6 +2196,13 @@ def _reconcile_specs(self, table) -> None: # The sort alone: the partition spec is already live and # already matches (the mismatch check above ran first). self._declare_specs(table, partition=False) + # The verdict, recorded against the shape it was reached ON — + # `self._live_info` rather than `info`, because a declaration + # above re-adopts a post-alter shape and THAT is what the next + # flush will build from. `_table_info` compares against this to + # decide whether an adopted shape still has a verdict; see the + # "a fresh shape is not a reconciled shape" note there. + self._reconciled_specs = _spec_identity(self._live_info or info) def _verify_specs(self, info) -> None: """Post-condition on the declaration: the live layout IS what @@ -1935,6 +2306,182 @@ def _spec_ops(self, *, partition: bool = True, sort: bool = True) -> list[AlterO def _adopt_columns(self, columns) -> None: self._live_columns = {c.name: c for c in columns} + def _adopt_info(self, info): + """Take a `TableInfo` as the destination's live shape, and stamp + when it was read. + + One function, so the columns and the specs can never come from + two different reads: `_live_columns` drives schema evolution and + `info.partition_spec` drives the fanout, and a flush that + computed partition values under one read while aligning columns + to another would register files nothing could detect as wrong. + + Every producer of a whole `TableInfo` routes through here — an + `info()` read and an `alter()` receipt alike. pyhoglake's + `Table.alter` re-seeds its OWN writer cache from the same + receipt (at the post-alter snapshot) and `Table.info` does the + same through `Table._adopt`, so every stamp taken here coincides + with a stamp taken there. `_live_info_ttl_s` depends on that. + """ + self._live_info = info + self._live_info_read_at = self._monotonic() + self._adopt_columns(info.columns) + return info + + def _live_info_ttl_s(self) -> float: + """How long the cached shape may be used before it is re-read: + a QUARTER of the catalog's snapshot retention. + + THE NUMBER IS NOT A GUESS, it is half of pyhoglake's own + threshold, and the factor-of-two is the only thing standing + between this sink and silently mis-partitioned files. + + `Table._cache_is_usable` lets pyhoglake prepare against its + cached info while that cache is younger than retention/2; past + that, `_prepared_read` re-reads and the `read_snapshot` it sends + moves forward with it. Suppose the sink had no TTL. A pod runs + for an hour, an operator re-specs the table from + `identity(team_id)` to `bucket(team_id, 16)`, pyhoglake's cache + ages out and self-refreshes past the alter, and the next flush: + computes partition values from the sink's hour-old spec + (identity), passes pyhoglake's only structural check on them + (arity, which is 1 either way), passes the footer/schema compare + (no column changed), and commits with a `read_snapshot` NEWER + than the alter — so the conflict scan finds nothing, the server + accepts, and the files are stamped with the live spec_id while + carrying values computed under the old transform. Every future + scan prunes them wrongly, forever, with nothing anywhere saying + so. That is the hazard the deleted pre-commit table read used to + catch, and a TTH strictly shorter than pyhoglake's is what + replaces it: the sink always re-reads FIRST, so the spec it + computes under is never older than the basis the commit carries. + Expressed as an invariant — THIS CACHE IS NEVER STALER THAN + `Table._cache` — which holds by construction because every + refresh here goes through `table.info()`, which re-seeds that + cache in the same call. + + Retention comes from `Catalog._retention_seconds()`: the SAME + cached value pyhoglake's own threshold is computed from, so the + two cannot disagree about the period even when an operator + shortens retention live and one side has not noticed yet. It is + one options GET per Catalog object, not per flush, so this stays + a zero-request check in steady state. A private accessor, hence + the guard: a pyhoglake that renames it falls back to the same + assumed retention pyhoglake assumes when it cannot read one, + which keeps the factor-of-two intact. + + `inf` (retention disabled) is correct as "never re-read for + staleness": with no expiry floor pyhoglake's cache never ages + out either, so its `read_snapshot` stays pinned at the sink's own + read and any later alter is INSIDE the conflict window — the + commit is refused rather than accepted wrong. The invariant holds + trivially there; it is the finite case that needs the quarter. + """ + read = getattr(self._catalog, "_retention_seconds", None) + if read is None: + return _ASSUMED_RETENTION_S / 4 + try: + retention = read() + except Exception: # noqa: BLE001 - a retention read must never fail a flush + return _ASSUMED_RETENTION_S / 4 + if not isinstance(retention, int | float) or isinstance(retention, bool) or retention <= 0: + # Includes a test double that answers something unusable: + # falling back is right, silently treating the TTL as zero or + # as infinite is not. + return _ASSUMED_RETENTION_S / 4 + return float(retention) / 4 + + def _live_info_is_fresh(self) -> bool: + if self._live_info is None or self._live_info_read_at is None: + return False + return self._monotonic() - self._live_info_read_at < self._live_info_ttl_s() + + def _table_info(self, table): + """The destination's live shape, from this sink's cached copy, + re-reading only on a cold cache or past `_live_info_ttl_s`. + + ZERO TABLE READS PER STEADY-STATE FLUSH is the point, and the + correctness argument is not "the shape probably has not + changed". It is two things together, and neither is sufficient + alone: + + * THE CONFLICT WINDOW. The commit carries the `read_snapshot` + this shape was resolved at, and the server refuses it if + anything altered, dropped or recreated the table since — + atomically, zero rows written, as the typed + `ddl_since_read_snapshot` (or 410 when the basis itself + expired), after which `_destination_moved` drops this cache and + the flush rebuilds against a fresh read. + * THE TTL, because the window only covers drift that is INSIDE + it. pyhoglake refreshes its own cache at retention/2 and the + `read_snapshot` moves forward with it, so a spec change older + than that would be outside the window with nothing on the file + to contradict it. Re-reading at retention/4 keeps this cache + at least as fresh as pyhoglake's, which is what keeps every + spec change the commit cannot see from existing. See + `_live_info_ttl_s` for the worked example. + + So, precisely: + + * COLUMN drift is caught without the TTL. pyhoglake builds the + destination schema from its OWN (possibly fresher) read and + compares it against the encoded parquet footer, so a column + this copy has not seen is a `ValidationError` — + `write()`'s alignment self-heal answers it by re-reading, + null-filling and preparing once more. + * SPEC drift is caught by the TTL plus the conflict window, as + above. Nothing on the file or in the request encodes the + transform a partition value was computed under, which is why + there is no third mechanism to fall back on. + * A DROP + RECREATE is covered by NEITHER: the conflict scan + keys on the resolved (new) table id, so the old incarnation's + `table_dropped` row is outside its window. It is closed solely + by `expected_table_uuid` -> 409 `table_recreated`, which + `_prepare` pins to the resolved-and-reconciled incarnation. + + The periodic re-read is also the ONLY place a long-lived pod can + notice that config and the live layout have diverged, so it runs + `_reconcile_specs` on the info it just read. Without that, the + "a pod that disagrees with the table it writes to stops" rule + the README advertises only ever fired at pod start, and a + re-spec under a running fleet produced the silent mis-partitioning + above on every pod that had not restarted. + + `totals=False` on the read: the writer needs the uuid, the + columns and the specs. The totals are a count and two sums over + every live file row of the table, which on prod-us is ~15M rows + and the whole cost of the call, and nothing in this sink has ever + read one. + """ + if self._live_info_is_fresh(): + if _spec_identity(self._live_info) != self._reconciled_specs: + # A FRESH SHAPE IS NOT NECESSARILY A RECONCILED ONE, and + # the early return above used to assume it was. + # `_adopt_info` is reached from schema evolution + # (`_add_column`, `_promote_column`, their alter + # receipts) and from `write()`'s alignment self-heal — + # all of which adopt whatever layout is live and re-stamp + # the clock, with no config check anywhere. So an + # external re-spec picked up through one of those paths + # was written under, and a pod drifting columns often + # enough could postpone the TTL's own reconciliation + # indefinitely by keeping the shape perpetually fresh. + # + # Comparing layouts costs no request, so the check runs + # whenever the layout is not the one a verdict was + # reached on — which is once per actual spec change, not + # once per flush. + self._reconcile_specs(table, self._live_info) + return self._live_info + info = self._adopt_info(table.info(totals=False)) + # Against the info just read, so this costs no second request — + # and AFTER the adopt, because the comparison resolves config + # column names through `self._live_columns`. + self._reconcile_specs(table, info) + # `_reconcile_specs` may declare a missing spec, which re-adopts + # a post-alter info; return the field rather than the local. + return self._live_info + def _evolve_and_align(self, table, batch: pa.Table) -> pa.Table: """Reconcile the batch schema with the live table schema. @@ -2139,8 +2686,7 @@ def _add_columns(self, table, fields: list[pa.Field]) -> list[str]: return failed if len(add_ops) > 1: try: - info = table.alter(add_ops) - self._adopt_columns(info.columns) + self._adopt_info(table.alter(add_ops)) metrics.schema_columns_added_total.inc(len(add_ops)) return failed except HoglakeError as e: @@ -2160,14 +2706,13 @@ def _add_column(self, table, field: pa.Field) -> bool: return False log.info("Schema evolution: adding hoglake column %s (%s)", field.name, type_name) try: - info = table.alter([ops.add_column(field.name, field.type)]) - self._adopt_columns(info.columns) + self._adopt_info(table.alter([ops.add_column(field.name, field.type)])) metrics.schema_columns_added_total.inc() return True except CommitConflictError: # Concurrent DDL — typically another pod adding the same # column. Re-resolve; present means someone won the race. - self._adopt_columns(table.info().columns) + self._adopt_info(table.info(totals=False)) if field.name in self._live_columns: log.info("Column %s added by another writer, continuing", field.name) return True @@ -2185,11 +2730,10 @@ def _promote_column(self, table, name: str, from_type: str, to_type: str) -> Non cast decides per value.""" log.info("Schema evolution: promoting hoglake column %s from %s to %s", name, from_type, to_type) try: - info = table.alter([ops.promote_column(name, to_type)]) - self._adopt_columns(info.columns) + self._adopt_info(table.alter([ops.promote_column(name, to_type)])) metrics.schema_columns_widened_total.inc() except CommitConflictError: - self._adopt_columns(table.info().columns) + self._adopt_info(table.info(totals=False)) live = self._live_columns.get(name) if live is not None and live.type == to_type: log.info("Column %s promoted by another writer, continuing", name) diff --git a/millpond/main.py b/millpond/main.py index 32ebcc2..c509dcf 100644 --- a/millpond/main.py +++ b/millpond/main.py @@ -620,7 +620,29 @@ def _retry_delay(sink, attempt: int, base: float) -> float: return min(delay + random.uniform(0.0, delay * _RETRY_JITTER), _RETRY_AFTER_MAX_S) -def _write_with_retry(sink, consolidated, *, destination: str = "ducklake", write_kwargs=None): +def _flush_deadline(sink) -> tuple[float, float] | None: + """(wall-clock budget for one flush, seconds to reserve per attempt), + or None when this sink does not bound its flushes by the clock. + + A duck-typed hook like `is_retryable` and `write_retry_budget`, so + DuckLake — whose outer three attempts cannot approach the liveness + deadline, and which carries its own inner bound — is unaffected by + not implementing it. + """ + deadline = getattr(sink, "write_flush_deadline", None) + if deadline is None: + return None + return deadline() + + +def _write_with_retry( + sink, + consolidated, + *, + destination: str = "ducklake", + write_kwargs=None, + now=time.monotonic, +): """Write to the sink with exponential backoff on transient failures. Returns the record count the sink actually wrote (0 when it skipped the @@ -637,10 +659,29 @@ def _write_with_retry(sink, consolidated, *, destination: str = "ducklake", writ (a permanent 422 is not worth three attempts and a backoff; crash the pod now and let the operator see it), and may publish its own retry budget and Retry-After hint. + + THE ATTEMPT COUNT IS NOT THE ONLY BOUND. A sink that publishes + `write_flush_deadline()` also gets a wall-clock one, checked before + every backoff sleep: if the elapsed time plus that sleep plus what + the next attempt is expected to cost would pass the budget, the loop + stops and re-raises the last error instead of starting an attempt it + cannot finish. The outcome is the one exhausting the attempts already + produces — crash, restart, replay from Kafka, offsets never + advanced — with the difference that it happens while the process can + still log WHY. Without it the next attempt runs, the consume loop + (single threaded) records no poll, and `server.HealthState` SIGKILLs + the pod mid-flush: the one failure that leaves nothing in its own + logs. See `config.hoglake_flush_deadline` for the three costs the + startup model cannot see. + + `now` is the clock, injectable so the deadline is testable without + spending eight minutes of it. """ write_kwargs = write_kwargs or {} max_attempts, base_delay = _write_retry_budget(sink) classify_retryable = getattr(sink, "is_retryable", None) + deadline = _flush_deadline(sink) + started = now() for attempt in range(max_attempts): try: return sink.write(consolidated, **write_kwargs) @@ -660,6 +701,34 @@ def _write_with_retry(sink, consolidated, *, destination: str = "ducklake", writ if attempt == max_attempts - 1: raise delay = _retry_delay(sink, attempt, base_delay) + if deadline is not None: + budget_s, attempt_cost_s = deadline + elapsed = now() - started + if elapsed + delay + attempt_cost_s > budget_s: + # Measured BEFORE the sleep, and including it: the + # question is whether the attempt this sleep leads to + # can finish inside the budget, not whether we are + # already past it. Logged as a distinct, greppable + # fact rather than folded into the generic retry + # warning, because "the pod gave up early on purpose" + # and "the pod ran out of attempts" look identical in + # the exception and lead to different investigations. + log.error( + "Write failed and the flush deadline leaves no room for another attempt " + "(flush_deadline_exceeded=true attempts=%d/%d elapsed=%.1fs next_delay=%.1fs " + "attempt_reserve=%.1fs budget=%.1fs type=%s); raising rather than being killed " + "mid-flush by the liveness probe", + attempt + 1, + max_attempts, + elapsed, + delay, + attempt_cost_s, + budget_s, + error_type, + exc_info=True, + ) + metrics.errors_total.labels(type="flush_deadline_exceeded").inc() + raise log.warning( "Write failed (attempt %d/%d, type=%s), retrying in %.1fs", attempt + 1, diff --git a/millpond/metrics.py b/millpond/metrics.py index e9222ec..f3f569f 100644 --- a/millpond/metrics.py +++ b/millpond/metrics.py @@ -290,10 +290,18 @@ def labels(self, **kwargs): # # And, as before, nothing can count the orphan a SIGKILL leaves between # the upload and the commit. +# `reason` is the call site that abandoned them, from a fixed set — one +# per `_count_orphans` caller in hoglake.py: `prepare_failed`, +# `commit_refused`, `ddl_since_read_snapshot`, `table_recreated`, +# `read_snapshot_expired`, `already_published`, `superseded`, +# `shutdown`. Unlabeled, every one of those funneled into a single +# number and the only way to tell a routine shutdown orphan from a +# re-spec quietly refusing every flush was to read the logs. Summing +# over `reason` reproduces the old series exactly. _hoglake_orphaned_files_total = Counter( "millpond_hoglake_orphaned_files_total", "Parquet objects uploaded to the lake but never registered in a commit", - ["pipeline", "broker_source"], + ["pipeline", "broker_source", "reason"], ) # librdkafka internal stats (via statistics.interval.ms callback) @@ -433,7 +441,7 @@ def init(pipeline: str, broker_source: str = ""): variant_write_fallback_total = _variant_write_fallback_total.labels(pipeline=pipeline, broker_source=bs) hoglake_files_written_total = _hoglake_files_written_total.labels(pipeline=pipeline, broker_source=bs) hoglake_commit_replays_total = _AutoCommonLabels(_hoglake_commit_replays_total, pipeline, bs) - hoglake_orphaned_files_total = _hoglake_orphaned_files_total.labels(pipeline=pipeline, broker_source=bs) + hoglake_orphaned_files_total = _AutoCommonLabels(_hoglake_orphaned_files_total, pipeline, bs) variant_values_coerced_total = _variant_values_coerced_total.labels(pipeline=pipeline, broker_source=bs) rdkafka_replyq = _rdkafka_replyq.labels(pipeline=pipeline, broker_source=bs) rdkafka_msg_cnt = _rdkafka_msg_cnt.labels(pipeline=pipeline, broker_source=bs) diff --git a/pyproject.toml b/pyproject.toml index 447d8a5..6dc22bd 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -51,7 +51,30 @@ dependencies = [ # and an Iceberg reader (the Trino hoglake connector among them) binds a # uuid column through that annotation. 1.3.0 also accepts BOTH spellings # on append, so a mixed fleet writing either one keeps working. - "pyhoglake>=1.3.0", + # 1.3.7 is the floor now, for the flush path's shape rather than for a + # type: `prepare_append_tables` encodes each already-partitioned Arrow + # table straight to a buffer (no temp file to write, fsync, re-read for + # the footer and re-read for the upload), uploads the buffers + # CONCURRENTLY, and returns the same commit request the file path + # returns for the same rows. With it come the typed non-retryable + # commit refusals the sink now reads instead of re-reading the table + # before every commit — `ddl_since_read_snapshot` + # (DdlSinceReadSnapshotError), `table_recreated` + # (IncarnationChangedError), `ReadSnapshotExpiredError` — plus + # `Table.info(totals=False)`, which skips a count and two sums over + # every live file row of the table on a read the writer makes for the + # uuid, the columns and the specs and has never read a total from. + # The `fast-upload` EXTRA pulls boto3 in: pyarrow's S3 output stream + # always opens a multipart upload (CreateMultipartUpload + UploadPart + + # CompleteMultipartUpload, three round trips for a 12 KiB file), and + # with boto3 present pyhoglake puts anything at or under 8 MiB up as a + # single `PutObject` instead. A partitioned flush is hundreds of small + # files, so that is the difference between ~3 and ~1 requests each, + # fanned out 64-wide rather than serial. Without the extra pyhoglake + # logs a warning and falls back to the streaming path, which is a + # silent 3x on the writer's dominant cost — hence the extra is part of + # the dependency spec and not left to the deployment to remember. + "pyhoglake[fast-upload]>=1.3.7", # 21 because pyhoglake 1.3.0 requires it. Declared here rather than left # to resolve transitively: millpond imports pyarrow directly on every # path, so its floor is millpond's business to state. @@ -124,12 +147,13 @@ exclude-newer = "7 days" # channel. Fixed date, not a rolling window — future pyducklake releases # re-enter the cooldown until this date is bumped alongside an intentional # version bump. -# Same carve-out shape for pyhoglake: 1.3.0 was published 2026-09-23 and -# is needed now for the parquet UUID annotation on uuid columns. Fixed -# date, not a rolling window — future pyhoglake releases re-enter the -# cooldown until this date is bumped alongside an intentional version -# bump. -exclude-newer-package = { pyducklake = "2026-08-14T00:00:00Z", pyhoglake = "2026-09-23T22:00:00Z" } +# Same carve-out shape for pyhoglake: 1.3.7 was published 2026-10-01 and +# is needed now for `prepare_append_tables` (buffer encode + concurrent +# single-request uploads), the typed commit refusals that retire the +# per-flush table read, and `info(totals=False)`. Fixed date, not a +# rolling window — future pyhoglake releases re-enter the cooldown until +# this date is bumped alongside an intentional version bump. +exclude-newer-package = { pyducklake = "2026-08-14T00:00:00Z", pyhoglake = "2026-10-01T02:00:00Z" } constraint-dependencies = [ "pygments>=2.20.0", "requests>=2.33.0", diff --git a/tests/e2e/test_hoglake_e2e.py b/tests/e2e/test_hoglake_e2e.py index 45256eb..adc67fb 100644 --- a/tests/e2e/test_hoglake_e2e.py +++ b/tests/e2e/test_hoglake_e2e.py @@ -15,6 +15,7 @@ from __future__ import annotations import json +import logging import os import signal import subprocess @@ -48,6 +49,14 @@ def e2e_stack(): stack.ensure_available() stack.up(profile="e2e") try: + # Same pin assertion as the integration suite: read the image + # back off the daemon rather than trusting the substitution. See + # tests/hoglake_stack/stack.py's `running_server_image`. + running = stack.running_server_image() + assert running == stack.server_image(), ( + f"the hoglake-server container is running {running!r}, not the pinned {stack.server_image()!r}" + ) + logging.getLogger(__name__).warning("hoglake server image under test: %s", running) stack.make_bucket(BUCKET) _wait_for_kafka() yield stack diff --git a/tests/hoglake_stack/docker-compose.yaml b/tests/hoglake_stack/docker-compose.yaml index f8c5da8..c703947 100644 --- a/tests/hoglake_stack/docker-compose.yaml +++ b/tests/hoglake_stack/docker-compose.yaml @@ -6,9 +6,19 @@ # bound to 127.0.0.1 so this stack can coexist with a live hoglake dev # environment on the same machine. # -# Server image: ghcr.io/posthog/hoglake-server:latest by default; -# override with HOGLAKE_SERVER_IMAGE (e.g. an image built from a local -# hoglake checkout's server/Dockerfile). +# Server image: HOGLAKE_SERVER_IMAGE, and it is REQUIRED (`:?`) rather +# than defaulted. tests/hoglake_stack/stack.py sets it from DEFAULT_IMAGE +# — a pinned multi-arch digest — on every compose call, and an operator +# overrides it in the environment to run against a locally built server +# (e.g. an image from a hoglake checkout's server/Dockerfile). +# +# It used to default to `:latest`, and that default silently WON: the +# only thing stack.py did with DEFAULT_IMAGE was `docker pull` it, so +# the digest was downloaded and the container ran whatever `:latest` +# resolved to locally. These suites are contract tests — a stale +# `:latest` means they assert a server nobody chose, and a green run +# proves nothing. Mandatory here so a bare `docker compose up` in this +# directory fails loudly instead of resurrecting the old behaviour. # # The `e2e` profile adds a single-node KRaft Kafka for the end-to-end # pipeline test; the integration tests don't boot it. @@ -49,7 +59,7 @@ services: retries: 15 hoglake-server: - image: ${HOGLAKE_SERVER_IMAGE:-ghcr.io/posthog/hoglake-server:latest} + image: ${HOGLAKE_SERVER_IMAGE:?set by tests/hoglake_stack/stack.py (DEFAULT_IMAGE, or your own override)} environment: HOGLAKE_INSTANCE_NAME: millpond-hog-it HOGLAKE_JDBC_URL: jdbc:postgresql://postgres:5432/hoglake diff --git a/tests/hoglake_stack/stack.py b/tests/hoglake_stack/stack.py index f267b3b..f4f7795 100644 --- a/tests/hoglake_stack/stack.py +++ b/tests/hoglake_stack/stack.py @@ -49,7 +49,7 @@ # locally before pushing, and say in the commit message what changed on # the server side. HOGLAKE_SERVER_IMAGE overrides this for a one-off run # against a locally built server (e.g. while developing a server change). -DEFAULT_IMAGE = "ghcr.io/posthog/hoglake-server@sha256:c95500cae32940270e94228dfae6787b6bfa32d33729ec059204f14d950865c7" +DEFAULT_IMAGE = "ghcr.io/posthog/hoglake-server@sha256:57485a90ee5cca260f5d8a7958ab5653dd8b5419d4a3a3b997f704643d467523" # CI sets this. Without it, a machine with no Docker (or no access to # ghcr.io) skips the docker-gated suites so local unit-test runs stay @@ -68,9 +68,17 @@ def compose(*args: str, profile: str | None = None, check: bool = True) -> subpr if profile: cmd += ["--profile", profile] cmd += list(args) - # The compose file falls back to hoglake-server:latest. Hand it the - # pinned image explicitly, otherwise a new server release changes - # what CI tests against without any commit here. + # HOGLAKE_SERVER_IMAGE is RESOLVED HERE, into the environment compose + # interpolates from, and that is the whole reason the pin exists. + # Without it the compose file's own default (`:latest`) won the + # substitution and `DEFAULT_IMAGE` only ever reached `ensure_image`'s + # pull — so the digest was downloaded, the container ran whatever + # `:latest` happened to resolve to locally, and these contract suites + # asserted a server nobody had chosen. (Found the hard way: a 1.3.7 + # typed refusal came back as its pre-1.3.6 wire code because the + # local `:latest` was two weeks stale.) `server_image` already + # honours an explicit override, so passing it through here keeps the + # one-off local-build escape hatch working. env = {**os.environ, "HOGLAKE_SERVER_IMAGE": server_image()} return subprocess.run(cmd, check=check, capture_output=True, text=True, timeout=600, env=env) @@ -141,6 +149,26 @@ def up(profile: str | None = None) -> None: wait_http_ok(f"{SERVER_URL}/healthz") +def running_server_image() -> str: + """The image the server CONTAINER is actually running, read back off + the daemon. + + Separate from `server_image()` (what we asked for) on purpose: the + gap between those two is how the pin went unenforced for two weeks + while every comment in this file said it was pinned. Asserting the + two are equal is the only form of that claim nothing can quietly + falsify. + """ + out = subprocess.run( + ["docker", "inspect", "-f", "{{.Config.Image}}", f"{PROJECT}-hoglake-server-1"], + capture_output=True, + text=True, + timeout=60, + check=True, + ) + return out.stdout.strip() + + def down() -> None: # --remove-orphans catches profile services (kafka) even when the # teardown call doesn't pass the profile. diff --git a/tests/integration/test_hoglake_integration.py b/tests/integration/test_hoglake_integration.py index 33ca43c..88687ae 100644 --- a/tests/integration/test_hoglake_integration.py +++ b/tests/integration/test_hoglake_integration.py @@ -16,6 +16,7 @@ import contextlib import logging import os +import re import tempfile import threading import uuid @@ -28,7 +29,7 @@ import pyarrow.parquet as pq import pytest from pyarrow import fs as pafs -from pyhoglake import IncarnationChangedError, NotFoundError, ValidationError +from pyhoglake import CommitConflictError, IncarnationChangedError, NotFoundError, ValidationError from pyhoglake.types import columns_to_arrow_schema from millpond.hoglake import HoglakeSink, HoglakeSinkError, is_retryable, table_schema_for_batch @@ -83,6 +84,20 @@ def hog_stack(): stack.ensure_available() stack.up() try: + # The pin, ASSERTED rather than asserted-in-a-comment. These are + # contract tests against a specific server build, and for two + # weeks the container ran whatever `:latest` resolved to locally + # while every comment in stack.py said it was pinned by digest — + # because the digest only ever reached `docker pull`. Reading the + # image back off the daemon is the one check that cannot be + # falsified by a substitution going wrong. + running = stack.running_server_image() + assert running == stack.server_image(), ( + f"the hoglake-server container is running {running!r}, not the pinned " + f"{stack.server_image()!r} — the compose image substitution is not taking effect, so " + f"these contract tests would assert against a server nobody chose" + ) + logging.getLogger(__name__).warning("hoglake server image under test: %s", running) stack.make_bucket(BUCKET) yield stack finally: @@ -176,6 +191,19 @@ def _snapshots(client, cfg) -> list: return [s for s in client.catalog(cfg.hoglake_catalog).snapshots() if s.author == author] +def _read_all(client, cfg) -> pa.Table: + """Every live row of the table, concatenated across its files. + + Schemas differ between files when a flush predates a column, so the + concat promotes rather than demanding identity — which is also what + makes "this column is null in files written before it existed" a + usable assertion. + """ + tables = [_read_parquet(f.path) for f in _table(client, cfg).files()] + assert tables, "the table has no live files" + return pa.concat_tables(tables, promote_options="permissive") + + def _read_parquet(path: str) -> pa.Table: s3 = pafs.S3FileSystem( access_key=stack.S3_ACCESS_KEY, @@ -474,6 +502,25 @@ def test_new_column_added_and_old_column_null_filled(self, hog_stack, client): assert second.column("event").null_count == 2 # null-filled def test_concurrent_writers_evolving_and_appending(self, hog_stack, client): + """Two pods adding columns and appending at once still converge — + now THROUGH the retry loop, which is the shape production runs. + + It used to converge with no retry at all, because the sink + stripped `read_snapshot` off the payload and a commit with no + conflict basis cannot be refused for a DDL race. With the basis + on, the other writer's `add_column` landing between this flush's + read and its commit is refused as `ddl_since_read_snapshot` — + atomically, zero rows written — and the recovery is the rebuild + `_write_with_retry` drives: `reset_caches`, re-resolve, re-align + against the new column, upload again, commit. That refusal is the + POINT of the basis (a payload built against the old layout is + exactly what must not be registered under the new one), so the + test asserts convergence under the real retry rather than + pretending the refusal does not happen. The cost is the refused + flush's parquet, which the orphan counter books. + """ + from millpond.main import _write_with_retry + cfg = _fresh() settle = HoglakeSink(_fresh(hoglake_table=cfg.hoglake_table)) settle.write(_batch(1)) # settle creation before the race @@ -486,7 +533,12 @@ def writer(idx: int): try: for round_ in range(3): extra = {f"col_w{idx}_{round_}": [f"v{idx}"] * 2} - s.write(_batch(2, teams=(idx,), extra_cols=extra)) + _write_with_retry( + s, + _batch(2, teams=(idx,), extra_cols=extra), + destination="hoglake", + write_kwargs={"kafka_offsets": (("events", idx, round_, round_),)}, + ) except BaseException as e: # noqa: BLE001 - collected for assertion errors.append(e) finally: @@ -503,6 +555,21 @@ def writer(idx: int): for idx in (1, 2): for round_ in range(3): assert f"col_w{idx}_{round_}" in names + # PER FLUSH, not just in total. The retry loop rebuilds a refused + # flush and re-uploads it, and the total would be right either + # way if one flush landed twice while another landed not at all + # (the refusals are concurrent, so the two errors cancel). Each + # round's marker column is written by exactly one flush of + # exactly 2 rows, so its non-null count is that flush's + # publication count. + rows = _read_all(client, cfg) + for idx in (1, 2): + for round_ in range(3): + column = f"col_w{idx}_{round_}" + landed = [v for v in rows.column(column).to_pylist() if v is not None] + assert landed == [f"v{idx}", f"v{idx}"], ( + f"{column} landed {len(landed)} time(s), not 2 — a refused flush was published twice or lost" + ) class TestRestartAndReset: @@ -531,17 +598,22 @@ def test_new_sink_instance_resumes_existing_table(self, hog_stack, client): s2.close() assert _record_count(client, cfg) == 6 - def test_external_drop_recreate_recovers_after_reset(self, hog_stack, client): + def test_external_drop_recovers_after_reset(self, hog_stack, client): cfg = _fresh() sink = HoglakeSink(cfg) try: sink.write(_batch(2)) _table(client, cfg).drop() - # The cached handle points at a dead incarnation: either the - # client's pre-flight re-resolve or the server's - # expected_table_uuid guard refuses it. Both are retryable — - # reset_caches adopts the live table on the next attempt. - with pytest.raises((IncarnationChangedError, NotFoundError)) as caught: + # The cached handle names a table that no longer resolves. + # WHICH refusal depends on how far the flush gets, and all of + # them are retryable, so the test accepts the family rather + # than one of them: the client's pre-flight re-resolve + # (`NotFoundError`, only on a cold writer cache — see + # `test_a_pre_upload_refusal_really_does_carry_zero`), or the + # commit, which the server answers 409 `table_dropped` -> + # `CommitConflictError`. `reset_caches` adopts the live table + # on the next attempt either way. + with pytest.raises((CommitConflictError, IncarnationChangedError, NotFoundError)) as caught: sink.write(_batch(2)) assert is_retryable(caught.value) is True sink.reset_caches() @@ -551,16 +623,28 @@ def test_external_drop_recreate_recovers_after_reset(self, hog_stack, client): assert _record_count(client, cfg) == 3 def test_external_drop_recreate_is_refused_not_published(self, hog_stack, client): - # The RECREATE case, which the drop-only test above cannot reach. - # Once the name resolves again, every check that was supposed to - # catch this passed: `_prepare`'s own `table.info()` adopts the - # new incarnation into the pyhoglake handle, and a defaulted - # `expected_table_uuid` is then read off that same refreshed - # value — so the client pre-flight, the server's guard and - # `_check_destination_still_ours` all compared fresh against - # fresh. The commit landed on a table this sink had never - # reconciled, and the only thing still naming the dead one was - # the idempotency key. + """The RECREATE case, which the drop-only test above cannot reach. + + Once the name resolves again, every check that was supposed to + catch this used to pass: `_prepare`'s own `table.info()` adopted + the new incarnation into the pyhoglake handle, and a defaulted + `expected_table_uuid` was then read off that same refreshed value + — so the client pre-flight, the server's guard and the + (now-retired) pre-commit destination read all compared fresh + against fresh. The commit landed on a table this sink had never + reconciled, and the only thing still naming the dead one was the + idempotency key. + + What closes it is `_prepare` pinning `expected_table_uuid` to the + resolved-and-reconciled incarnation, which is unchanged. WHERE it + is caught moved: the sink no longer re-reads the destination + before the commit, and pyhoglake skips its own pre-flight + re-resolve while its writer cache is warm — so the refusal is the + server's 409 `table_recreated`, after the upload. millpond + converts it to a retryable `HoglakeSinkError`, discards the + payload and books its parquet as an orphan, which is the cost of + catching it one round trip later. + """ cfg = _fresh() sink = HoglakeSink(cfg) try: @@ -571,9 +655,10 @@ def test_external_drop_recreate_is_refused_not_published(self, hog_stack, client reborn = ns.create_table(cfg.hoglake_table, table_schema_for_batch(_batch(1).schema)) assert reborn.table_uuid != dead - with pytest.raises(IncarnationChangedError) as caught: + with pytest.raises(HoglakeSinkError, match="recreated") as caught: sink.write(_batch(2), kafka_offsets=(("events", 0, 2, 3),)) assert is_retryable(caught.value) is True + assert isinstance(caught.value.__cause__, IncarnationChangedError) assert _record_count(client, cfg) == 0, "the flush published across incarnations" # Retryable, so main.py resets and re-resolves — which is @@ -836,29 +921,80 @@ def prepare_then_respec(self, table, batch, key, facts): assert _record_count(client, cfg) == 6 -class _FailNthUpload: - """The real S3 filesystem, with the Nth `open_output_stream` refused. +class _FailNthRequest: + """Refuse the Nth upload REQUEST of a fan-out, counted across both + transports and thread-safely. + + Two things it has to cope with that the old filesystem-only wrapper + did not. pyhoglake 1.3.7 sends any object at or under 8 MiB as a + single boto3 `put_object` (the `fast-upload` extra, which millpond + pins) and only a larger one through pyarrow's + `open_output_stream` — so a wrapper that only intercepts the stream + never fires for a real millpond flush, which is hundreds of ~12 KiB + files. And the fan-out is CONCURRENT, so "the Nth call" is whichever + thread claims the counter third; the lock is what keeps that exactly + one refusal rather than nondeterministically zero or two. + + Which group fails is deliberately not pinned. Every group is + submitted at once (the fan-out is wider than this test's group + count), the failure cancels nothing that has already started, and + `run_uploads` waits for the rest — so exactly one object is missing + and the others really are in MinIO, which is the claim: the count + pyhoglake stamps is checkable against the bucket instead of against + another fake. What is NOT checkable any more is that the landed set + is a PREFIX of the groups, and that is the point of reading the uris + rather than the count.""" + + def __init__(self, fail_on: int): + self._fail_on = fail_on + self._lock = threading.Lock() + self.calls = 0 + + def claim(self) -> bool: + with self._lock: + self.calls += 1 + return self.calls == self._fail_on + - Wrapping the filesystem rather than mocking pyhoglake is the point: - every upload before the Nth is a real object really in MinIO, so the - count pyhoglake stamps can be checked against the bucket instead of - against another fake.""" +class _FailNthStream: + """The real S3 filesystem with `_FailNthRequest` in front of its + output stream — the transport a too-large object still takes.""" - def __init__(self, real, fail_on: int): + def __init__(self, real, gate: _FailNthRequest): self._real = real - self._fail_on = fail_on - self.calls = 0 + self._gate = gate def open_output_stream(self, path, *a, **kw): - self.calls += 1 - if self.calls == self._fail_on: - raise OSError(f"injected object-store failure on upload {self.calls}") + if self._gate.claim(): + raise OSError(f"injected object-store failure on upload {self._gate.calls}") return self._real.open_output_stream(path, *a, **kw) def __getattr__(self, name): return getattr(self._real, name) +class _FailNthPut: + """The real boto3 client with the same gate in front of `put_object` + — the transport every object in a millpond flush actually takes. + + The OSError is raised rather than a botocore fault on purpose: + `perform_upload` translates botocore's taxonomy into `OSError` + anyway, so this is the exception shape the caller sees either way and + the one millpond's `is_retryable` classifies.""" + + def __init__(self, real, gate: _FailNthRequest): + self._real = real + self._gate = gate + + def put_object(self, **kw): + if self._gate.claim(): + raise OSError(f"injected object-store failure on upload {self._gate.calls}") + return self._real.put_object(**kw) + + def __getattr__(self, name): + return getattr(self._real, name) + + class TestPrepareOrphanAccounting: """What a failed `prepare_append_files` leaves behind, measured against the bucket rather than deduced. @@ -877,16 +1013,26 @@ def test_a_mid_fanout_failure_counts_and_names_the_objects_that_landed(self, hog try: sink.write(_batch(3, teams=(1,))) # bootstrap, so the table exists before = {o for o in _list_objects(DATA_PATH, cfg) if o.endswith(".parquet")} - real = sink._client._filesystem() - sink._client._fs = _FailNthUpload(real, fail_on=3) + # Both transports, one gate: the bootstrap flush above has + # already built and cached both clients, and the 3-way + # fan-out below asks for a pool no wider than the one they + # got, so neither is rebuilt out from under the wrapper. + real_fs = sink._client._filesystem() + real_put = sink._client._put_client(1) + gate = _FailNthRequest(fail_on=3) + sink._client._fs = _FailNthStream(real_fs, gate) + if real_put is not None: + sink._client._put = _FailNthPut(real_put, gate) with caplog.at_level(logging.WARNING, logger="millpond.hoglake"), pytest.raises(OSError) as caught: sink.write(_batch(9, teams=(1, 2, 3))) finally: - sink._client._fs = real + sink._client._fs = real_fs + sink._client._put = real_put sink.close() # pyhoglake's own accounting: two uploads closed cleanly, the # third raised and is in neither number. + assert gate.calls == 3, "the injected failure never fired — which transport did the upload take?" assert caught.value.uploaded_files == 2 assert len(caught.value.uploaded_uris) == 2 @@ -906,11 +1052,20 @@ def test_a_mid_fanout_failure_counts_and_names_the_objects_that_landed(self, hog assert "truncated" in caplog.text def test_a_pre_upload_refusal_really_does_carry_zero(self, hog_stack, client): - # The other half of the contract, and the one millpond used to - # assert from first principles: a refusal raised before the first - # upload reports 0 / (). Driven through a real drop+recreate - # under the sink's cached handle, so the real client pre-flight - # raises it. + """The other half of the contract, and the one millpond used to + assert from first principles: a refusal raised before the first + upload reports 0 / (). Driven through a real drop+recreate under + the sink's cached handle, so the real client pre-flight raises + it. + + `invalidate()` is what makes the pre-flight run at all, and it is + the condition rather than a convenience: pyhoglake 1.3.7 SKIPS + its incarnation re-resolve while its writer cache is warm (that + is the whole of "zero table reads per flush"), so on a warm cache + this same sequence is caught by the server at the commit instead + — see the test below. A cold cache is the ordinary state after a + restart, after any `re_prepare` refusal, and once per + half-retention.""" cfg = _fresh() sink = HoglakeSink(cfg) try: @@ -919,6 +1074,7 @@ def test_a_pre_upload_refusal_really_does_carry_zero(self, hog_stack, client): ns = client.catalog(cfg.hoglake_catalog).namespace(cfg.hoglake_namespace) ns.table(cfg.hoglake_table).drop() ns.create_table(cfg.hoglake_table, table_schema_for_batch(_batch(1).schema)) + sink._table.invalidate() with pytest.raises(IncarnationChangedError) as caught: sink.write(_batch(2)) finally: @@ -929,6 +1085,146 @@ def test_a_pre_upload_refusal_really_does_carry_zero(self, hog_stack, client): after = {o for o in _list_objects(DATA_PATH, cfg) if o.endswith(".parquet")} assert after == before + def test_a_warm_cache_pays_one_flush_of_uploads_for_a_recreation(self, hog_stack, client, caplog): + """The cost of the skipped pre-flight, measured rather than + argued: with a warm writer cache the recreation is caught by the + server's `expected_table_uuid` guard AFTER the upload, so that + flush's parquet is in the bucket with nothing referencing it. + + This is the trade the zero-read flush makes — one flush's objects + for one table GET per flush, forever — and the orphan counter and + its log are the whole accounting for it, so they are what gets + asserted.""" + cfg = _fresh() + sink = HoglakeSink(cfg) + try: + sink.write(_batch(2)) + before = {o for o in _list_objects(DATA_PATH, cfg) if o.endswith(".parquet")} + ns = client.catalog(cfg.hoglake_catalog).namespace(cfg.hoglake_namespace) + ns.table(cfg.hoglake_table).drop() + ns.create_table(cfg.hoglake_table, table_schema_for_batch(_batch(1).schema)) + with caplog.at_level(logging.WARNING, logger="millpond.hoglake"): + with pytest.raises(HoglakeSinkError, match="recreated") as caught: + sink.write(_batch(2)) + assert isinstance(caught.value.__cause__, IncarnationChangedError) + assert is_retryable(caught.value) is True + finally: + sink.close() + after = {o for o in _list_objects(DATA_PATH, cfg) if o.endswith(".parquet")} + orphans = after - before + assert len(orphans) == 1, "the refused flush's upload should be in the bucket, unreferenced" + assert "Orphaned 1 uploaded parquet file(s)" in caplog.text + for path in orphans: + assert path in caplog.text + assert _record_count(client, cfg) == 0 # nothing published to the new incarnation + + +class TestOneRequestPerFlush: + """The wire-level form of the zero-reads claim, which the unit tests + cannot make. + + They assert on the mock handles millpond itself calls, so they are + blind to anything pyhoglake issues inside `prepare_append_tables` — + its catalog head refresh, its incarnation re-resolve. What an + operator cares about is the request count against the control plane, + so count THAT: an httpx event hook on the sink's own client, which + already has one for `Retry-After`. + """ + + def _counted(self, sink) -> list[str]: + """Every catalog request this sink makes, newest last.""" + seen: list[str] = [] + + def record(response): + seen.append(f"{response.request.method} {response.request.url.path}") + + sink._client._http.event_hooks["response"].append(record) + return seen + + def test_the_steady_state_flush_is_one_commit_and_nothing_else(self, hog_stack, client): + cfg = _fresh(hoglake_partition_by=(("team_id", "identity", None),)) + sink = HoglakeSink(cfg) + try: + sink.write(_batch(3, teams=(1,))) # bootstrap: creates, declares, reconciles + seen = self._counted(sink) + for i in range(5): + sink.write(_batch(3, teams=(1, 2)), kafka_offsets=(("events", 0, i, i),)) + finally: + sink.close() + # FLAT, and flat at one: five flushes, five requests, every one + # of them the commit. Not "few" — exactly the commits, because a + # per-flush table GET carried a live-totals scan and the point of + # the whole change is that it is gone. + assert seen == ["POST /v1/catalogs/" + cfg.hoglake_catalog + "/commit/prepared"] * 5, seen + + def test_the_bootstrap_flush_is_the_only_one_that_reads(self, hog_stack, client): + # The reads that remain, named: resolve the catalog, resolve (or + # create) namespace and table, reconcile the specs. All of them + # are once per sink, and the assertion is that the SECOND flush + # adds none of them back. + cfg = _fresh() + sink = HoglakeSink(cfg) + seen = self._counted(sink) + try: + sink.write(_batch(2), kafka_offsets=(("events", 0, 0, 1),)) + bootstrap = len(seen) + sink.write(_batch(2), kafka_offsets=(("events", 0, 2, 3),)) + finally: + sink.close() + assert len(seen) - bootstrap == 1, seen[bootstrap:] + assert seen[-1].endswith("/commit/prepared") + + def test_no_read_asks_for_the_live_totals(self, hog_stack, client): + """The totals scan is a count and two sums over every live file + row of the table; the writer has never read one. Asserted on the + wire, so it covers pyhoglake's reads and not only millpond's. + + The selector is the ENDPOINT, not the query string. Selecting on + `totals=` was a tautology: a read that omitted the parameter — + the exact regression this test exists to catch — was filtered + out of the set before the assertion ran, so the only way to fail + was to send `totals=true` explicitly, which no code path does. + + Fixing that immediately found one such read, which is why the + assertion below is in two parts. `Namespace.table(name)` — + pyhoglake's table RESOLVE, which `_ensure_table` calls — issues a + bare `GET /tables/` and takes no parameter at all, so it + pays the live-totals scan and millpond cannot ask it not to. + That is one scan per resolve (per sink, plus one per + `reset_caches()`), never per flush, so it does not touch the + steady-state claim above; the bound here is what keeps it that + way. Removing it needs a `totals` argument on `Namespace.table` + upstream. + """ + cfg = _fresh() + sink = HoglakeSink(cfg) + requests: list[tuple[str, str, str]] = [] + sink._client._http.event_hooks["response"].append( + lambda r: requests.append((r.request.method, r.request.url.path, str(r.request.url))) + ) + try: + sink.write(_batch(2)) + sink.write(_batch(2)) + finally: + sink.close() + # Every GET of a single table, whatever it asked for: the path + # ends at `/tables/` with no further segment (so `/files`, + # `/scan`, `/alter` and the table LIST are all out). + table_endpoint = re.compile(r"/tables/[^/]+$") + table_gets = [url for method, path, url in requests if method == "GET" and table_endpoint.search(path)] + assert table_gets, "no table read happened at all; this test would pass vacuously" + asked = [url for url in table_gets if "totals=" in url] + unasked = [url for url in table_gets if "totals=" not in url] + # Every read that CAN say so, does. + assert asked, "no read carried the parameter at all; this half would pass vacuously" + assert all("totals=false" in url for url in asked), asked + # And the only reads that cannot are the resolves: one sink, two + # flushes, no reset between them, so exactly one. A millpond read + # that stopped passing `totals=False` would land in this bucket + # and break the count — which is the property the old + # query-string selector did not have. + assert len(unasked) == 1, unasked + class TestAtLeastOnce: def test_server_outage_no_offset_advance_then_clean_retry(self, hog_stack, client): @@ -1124,9 +1420,16 @@ def test_a_bare_fixed_size_binary_file_still_prepares(self, hog_stack, client): path = os.path.join(tmp, "part-0.parquet") pq.write_table(rows, path) assert pq.ParquetFile(path).schema.column(0).logical_type.type == "NONE" + # `prepare_append_files`, not `_tables`: the FILE path is + # what a variant-aware or old-spelling writer uses, and + # the bare `fixed_size_binary(16)` form cannot be + # produced from Arrow through the table path at all. payload = table.prepare_append_files([(path, None)], idempotency_key=str(uuid.uuid4())) - payload.pop("read_snapshot", None) - client.catalog(cfg.hoglake_catalog).commit_prepared(payload) + # `read_snapshot` stays on, as it does on every millpond + # commit now: appends do not conflict with appends, so the + # basis costs this commit nothing and sending it is the shape + # the fleet is moving to. + client.catalog(cfg.hoglake_catalog).commit_prepared(payload, table=table) finally: sink.close() assert _record_count(client, cfg) == 4 diff --git a/tests/unit/test_config.py b/tests/unit/test_config.py index 7530e9c..edb7212 100644 --- a/tests/unit/test_config.py +++ b/tests/unit/test_config.py @@ -1,3 +1,5 @@ +import os + import pytest from millpond.config import _parse_ordinal, load @@ -968,8 +970,15 @@ def test_optionals_default_to_none(self): def test_retry_and_timeout_defaults(self): # The pair bounds the worst case a single flush can spend inside # sink.write(); see the comment in _load_hoglake_fields. - cfg = load() - assert cfg.hoglake_max_retry_count == 8 + # + # SIX, not the eight this used to be. The worst-case model now + # charges every attempt a _PREPARE_ALLOWANCE_S of local + # encode-and-upload as well as its request timeout, because a + # commit the server refuses as `ddl_since_read_snapshot` is + # REBUILT rather than replayed — and under the old model eight + # attempts only fit because that work was free. + cfg = load() + assert cfg.hoglake_max_retry_count == 6 # 45, not pyhoglake's 30: the server's commit-lock admission # bound is 30s, so an equal client timeout gave up at the same # instant the server would have answered 503 + Retry-After, and @@ -977,6 +986,42 @@ def test_retry_and_timeout_defaults(self): # transport-uncertain failure instead. assert cfg.hoglake_request_timeout_s == 45.0 + @pytest.mark.parametrize("value", ["0", "-1", "sixty-four", "64.0", ""]) + def test_a_bad_upload_concurrency_is_refused_at_load(self, monkeypatch, value): + # pyhoglake reads PYHOGLAKE_UPLOAD_CONCURRENCY on the upload path + # and refuses a bad one as a client-side ValidationError, which + # is_retryable correctly calls permanent — so without this the + # pod starts clean, takes its partitions and crashes on its first + # flush over a variable no millpond code mentions. "" is the + # exception: an empty value is "unset" to pyhoglake too. + monkeypatch.setenv("PYHOGLAKE_UPLOAD_CONCURRENCY", value) + if value == "": + assert load().destination == "hoglake" + return + with pytest.raises(RuntimeError, match="PYHOGLAKE_UPLOAD_CONCURRENCY"): + load() + + def test_a_good_upload_concurrency_loads(self, monkeypatch): + monkeypatch.setenv("PYHOGLAKE_UPLOAD_CONCURRENCY", " 32 ") + assert load().destination == "hoglake" + + def test_the_check_matches_pyhoglakes_own_parse(self): + # One grammar, two readers: a check that refused what pyhoglake + # accepts (or accepted what it refuses) would be worse than none. + from pyhoglake.upload import resolve_concurrency + + from millpond.config import _check_upload_concurrency + + for value in ("0", "-1", "sixty-four", "64.0"): + os.environ["PYHOGLAKE_UPLOAD_CONCURRENCY"] = value + try: + with pytest.raises(RuntimeError): + _check_upload_concurrency() + with pytest.raises(Exception): # noqa: B017,PT011 - pyhoglake's own ValidationError + resolve_concurrency(8, None) + finally: + del os.environ["PYHOGLAKE_UPLOAD_CONCURRENCY"] + def test_a_retry_budget_that_outlives_liveness_is_refused(self, monkeypatch): # HOGLAKE_MAX_RETRY_COUNT was unbounded while its interaction # with the liveness deadline lived in a comment — so the @@ -999,6 +1044,23 @@ def test_the_defaults_fit_inside_the_liveness_budget(self): cfg = load() worst = _hoglake_worst_case_flush_s(cfg.hoglake_max_retry_count, cfg.hoglake_request_timeout_s) assert worst <= _LIVENESS_BUDGET_S + # With MARGIN, not by a hair. The old defaults cleared the + # deadline by ~6s of 480, which is inside the error bar of every + # term in the model — and the failure it guards is a SIGKILL + # mid-flush with nothing in the pod's logs. + assert _LIVENESS_BUDGET_S - worst >= 30.0 + + def test_the_model_charges_every_attempt_for_its_own_prepare(self): + # The hoglake retry REBUILDS: a `ddl_since_read_snapshot` refusal + # discards the uploaded payload, so the next attempt re-encodes + # and re-uploads the whole fanout. A model that only counted + # request timeouts priced that at zero and let the default budget + # sit ~6s inside the liveness deadline. + from millpond.config import _PREPARE_ALLOWANCE_S, _hoglake_worst_case_flush_s + + one = _hoglake_worst_case_flush_s(1, 10.0) + two = _hoglake_worst_case_flush_s(2, 10.0) + assert two - one >= 10.0 + _PREPARE_ALLOWANCE_S @pytest.mark.parametrize( "value", diff --git a/tests/unit/test_hoglake.py b/tests/unit/test_hoglake.py index 0814290..c231aa4 100644 --- a/tests/unit/test_hoglake.py +++ b/tests/unit/test_hoglake.py @@ -20,6 +20,7 @@ AlreadyExistsError, Column, CommitConflictError, + DdlSinceReadSnapshotError, ExpiredError, HoglakeError, IncarnationChangedError, @@ -27,6 +28,7 @@ NotFoundError, PartitionField, PartitionSpec, + ReadSnapshotExpiredError, UnsupportedTypeError, ValidationError, ) @@ -90,6 +92,76 @@ class _FakeInfo: table_uuid: str = TABLE_UUID +def _wire_info(table, state): + """Make `table.info` answer the live state AND refuse a read that + asks for the live totals. + + The sink has never read a total, and the scan that produces one is a + count plus two sums over every live file row of the table — ~15M on + prod-us, which is the whole cost of the call. The enforcement is + here, per call, rather than only in an after-the-fact loop over + `call_args_list`: a loop asserts what the calls looked like in the + one test that checks them, while this asserts it at every call site + in every test, so a mutation that drops `totals=False` from ONE of + the four (`_table_info`, `_declare_specs`'s conflict path, + `_add_column`, `_promote_column`) fails in the test that exercises + that site. + + Tests that need `info` to answer differently over time replace this + side_effect with their own; `_info_sequence` keeps the totals guard + for them. + """ + table.info.side_effect = _guarded_info(lambda: state) + + +def _guarded_info(answer): + """An `info` stand-in that asserts `totals=False` and then defers to + `answer()` for the TableInfo to return.""" + + def info(*args, **kwargs): + assert kwargs.get("totals") is False, ( + f"table.info() called with totals={kwargs.get('totals')!r}: every read on the writer " + "path must pass totals=False (the live-totals scan is the whole cost of the call)" + ) + return answer() + + return info + + +def _set_info(table, info): + """Point `table.info` at a new TableInfo, keeping the totals guard. + + Assigning `table.info.return_value` does NOT work: `_wire_info` + installs a `side_effect`, which Mock consults first, so the + assignment would be silently ignored and the test would keep seeing + the original state. (It was, for three tests, until the guard went + in.) Go through here. + """ + table.info.side_effect = _guarded_info(lambda: info) + + +def _set_info_sequence(table, infos): + """`table.info` answers each of `infos` in turn and then repeats the + last, keeping the totals guard. + + For the concurrent-DDL paths, where the POINT is that two reads of + the same table disagree: the resolve sees the shape before another + writer's alter and the post-409 re-resolve sees it after. A single + `_set_info` cannot express that, and using one made + `test_conflict_on_add_reresolves_and_proceeds` vacuous for as long + as it existed — the pre-set shape already contained the column, so + no add was ever attempted and the 409 handler it was named for never + ran. + """ + remaining = list(infos) + assert remaining, "need at least one info" + + def answer(): + return remaining.pop(0) if len(remaining) > 1 else remaining[0] + + table.info.side_effect = _guarded_info(answer) + + def _wire_dynamic_alter(table, state: _FakeInfo): """Make the mock table's alter() behave like the real server: apply the ops to the live table state and return the post-alter info, @@ -123,41 +195,97 @@ def do_alter(ops_list): table.alter.side_effect = do_alter -# Captured before the autouse fixture below replaces it: one test needs -# the REAL serializer, because everything else in this file asserts on -# the in-memory table that reaches `pq.write_table` and therefore never -# exercises the cast or the file it produces. -_REAL_WRITE_TABLE = pq.write_table - +# The groups the sink handed to `prepare_append_tables`, newest flush +# last — (partition_values, pa.Table) pairs, in the order the fanout +# produced them. The sink no longer writes parquet to disk at all: it +# encodes each already-partitioned Arrow table in pyhoglake, so the batch +# that lands in the lake is the one that reaches `prepare_append_tables`, +# which is what these tests assert on. `_PREPARED_GROUPS` keeps every +# group of every flush; `_WRITTEN` is the flattened table list the +# `_published` helper reads. +_PREPARED_GROUPS: list[list[tuple[tuple[str | None, ...] | None, pa.Table]]] = [] _WRITTEN: list[pa.Table] = [] @pytest.fixture(autouse=True) -def _capture_parquet(monkeypatch): - """Capture what the sink serializes instead of writing it to disk. - - The sink no longer hands pyarrow tables to `Table.append`: it writes - local parquet, uploads it, and registers the upload in a separate - idempotent commit. The batch that lands in the lake is therefore the - one that reaches `pq.write_table`, which is what these tests assert - on.""" +def _capture_parquet(): + """Reset the per-test capture of what the sink prepared. + + Nothing is monkeypatched any more — the capture happens in + `_wire_prepared_commit`'s stand-in for `prepare_append_tables`, which + is where the Arrow tables now arrive. The fixture stays autouse so a + test that reads `_published()` cannot see the previous test's + groups.""" + _PREPARED_GROUPS.clear() _WRITTEN.clear() - monkeypatch.setattr(hoglake.pq, "write_table", lambda table, path, **kw: _WRITTEN.append(table)) return _WRITTEN +def _flush_key_for(sink, offsets, table_uuid=TABLE_UUID) -> str: + """The idempotency key this sink would mint for (incarnation, + offsets). Module-level because two classes need it.""" + return sink._flush_key(table_uuid, offsets) + + +def _orphans(mock_metrics) -> list[tuple[str, int]]: + """Every orphan increment booked on a patched metrics module, as + (reason, count) in call order. + + The counter is labeled now, so `.inc` lives on the child + `.labels(...)` returns — one shared mock whatever the label value, so + the reasons and the counts have to be paired by index. That is sound + here because `_count_orphans` is the only writer and it labels + immediately before it increments; this helper asserts the two lists + are the same length so a future call site that breaks the pairing + fails loudly instead of reporting a wrong reason. + + Asserting on the pair rather than the count alone is the point: the + reason label is what tells a routine shutdown orphan from a re-spec + refusing every flush, and an unasserted label is a label that drifts. + """ + metric = mock_metrics.hoglake_orphaned_files_total + reasons = [call.kwargs["reason"] for call in metric.labels.call_args_list] + counts = [call.args[0] for call in metric.labels.return_value.inc.call_args_list] + assert len(reasons) == len(counts), ( + f"{len(reasons)} labels() call(s) against {len(counts)} inc() call(s): " + "something increments the orphan counter without labeling it, or vice versa" + ) + return list(zip(reasons, counts, strict=True)) + + def _published(_table=None) -> pa.Table: - """The (single) batch the last flush serialized for upload.""" + """The (single) batch the last flush prepared for upload.""" assert _WRITTEN, "nothing was written" return _WRITTEN[-1] +def _groups() -> list[tuple[tuple[str | None, ...] | None, pa.Table]]: + """The (partition_values, table) groups of the last flush.""" + assert _PREPARED_GROUPS, "nothing was prepared" + return _PREPARED_GROUPS[-1] + + +def _real_encode(group: pa.Table) -> pa.Table: + """`group` through a real parquet round trip, the way pyhoglake's + `_encode_group` does it (buffer, not a temp file). + + The mock `prepare_append_tables` below never serializes, so a test + that cares about the FILE — the cast, the logical annotations, the + column order the footer carries — has to encode one itself. This is + the same two calls pyhoglake makes (`pq.write_table` into a + `BufferOutputStream`, then read the footer back), so what it proves + is what the destination would be sent.""" + sink = pa.BufferOutputStream() + pq.write_table(group, sink) + return pq.ParquetFile(pa.BufferReader(sink.getvalue())) + + def _wire_prepared_commit(table, catalog): - """Mock the prepared-append handshake: prepare_append_files returns a - commit request naming one file per partition group, and - Catalog.commit_prepared publishes it.""" + """Mock the prepared-append handshake: prepare_append_tables captures + the Arrow groups and returns a commit request naming one file per + group, and Catalog.commit_prepared publishes it.""" - def prepare(files, *, idempotency_key, expected_table_uuid=None, **kwargs): + def prepare(groups, *, idempotency_key, expected_table_uuid=None, **kwargs): # pyhoglake pins the guard to the incarnation the CALLER names # (`expected = expected_table_uuid or self.table_uuid`) and then # fast-fails, BEFORE the first upload, when the name now binds to @@ -169,6 +297,19 @@ def prepare(files, *, idempotency_key, expected_table_uuid=None, **kwargs): raise IncarnationChangedError( f"table was recreated: expected table_uuid {expected}, name now resolves to {table.table_uuid}" ) + # The real method REQUIRES each group's schema to be the + # destination's, field ids included, and checks it on the encoded + # footer. Assert the half a mock can assert — that the field ids + # are on the schema the sink handed over — so a sink that stopped + # casting to `columns_to_arrow_schema(info.columns)` fails here + # rather than in the live suite. + for part, _values in groups: + for field in part.schema: + assert field.metadata and b"PARQUET:field_id" in field.metadata, ( + f"group schema field {field.name!r} carries no PARQUET:field_id" + ) + _PREPARED_GROUPS.append([(values, part) for part, values in groups]) + _WRITTEN.extend(part for part, _values in groups) return { "idempotency_key": idempotency_key, "read_snapshot": 41, @@ -178,14 +319,21 @@ def prepare(files, *, idempotency_key, expected_table_uuid=None, **kwargs): "table": "events", "expected_table_uuid": expected, "files": [ - {"path": f"s3://bucket/lake/{idempotency_key}/{i}.parquet", "partition_values": values} - for i, (_path, values) in enumerate(files) + # `list(values)`, as the real `prepare_append_tables` + # writes it (and omitted entirely for an + # unpartitioned table, which is what `values is + # None` means here). + { + "path": f"s3://bucket/lake/{idempotency_key}/{i}.parquet", + **({} if values is None else {"partition_values": list(values)}), + } + for i, (_part, values) in enumerate(groups) ], } ], } - table.prepare_append_files.side_effect = prepare + table.prepare_append_tables.side_effect = prepare catalog.commit_prepared.return_value = MagicMock(snapshot_id=7, schema_version=1) @@ -199,10 +347,17 @@ def _mock_stack(columns, partition_spec=None, sort_spec=None): state = _FakeInfo(columns=tuple(columns), partition_spec=partition_spec, sort_spec=sort_spec) table.columns = state.columns table.table_uuid = state.table_uuid - table.info.return_value = state + _wire_info(table, state) table.state = state _wire_dynamic_alter(table, state) client.catalog.return_value = catalog + # The catalog's snapshot retention, which is what the sink's cached + # shape derives its TTL from (`_live_info_ttl_s` = retention/4, half + # pyhoglake's own threshold). A real number, not a Mock: the sink + # falls back to an assumed retention for anything unusable, and a + # test driving the TTL against the fallback would be testing a + # number no deployment has. + catalog._retention_seconds.return_value = 3600.0 # A real string, because the startup credential probe derives the # object-store prefix from it: a MagicMock data_path would let a # probe that never formed a usable path still look healthy. @@ -259,7 +414,7 @@ def _batch(**cols) -> pa.Table: def _stamped(exc: BaseException, count: int, uris: tuple[str, ...] | None = None) -> BaseException: """An exception as pyhoglake>=1.1.1 hands it back from - `prepare_append_files`: `uploaded_files` is how many uploads CLOSED + `prepare_append_tables`: `uploaded_files` is how many uploads CLOSED cleanly and `uploaded_uris` names exactly those, in order. A refusal raised before the first upload carries 0 / ().""" exc.uploaded_files = count @@ -720,35 +875,33 @@ def _uuid_columns(self): _col("_inserted_at", "timestamptz", 5, 5), ] - def _written(self, monkeypatch): - monkeypatch.setattr(hoglake.pq, "write_table", _REAL_WRITE_TABLE) - s, client, catalog, ns, table = _sink(columns=self._uuid_columns()) - captured: dict[str, list] = {} - prepared = table.prepare_append_files.side_effect - - def prepare(files, **kwargs): - captured["files"] = [pq.ParquetFile(path) for path, _ in files] - return prepared(files, **kwargs) + def _written(self): + """The parquet file this flush's single group encodes to. - table.prepare_append_files.side_effect = prepare + The sink hands Arrow tables to `prepare_append_tables` now, so + the file is produced HERE, by the same buffer round trip + pyhoglake's `_encode_group` performs. What it proves is + unchanged: the destination schema `_prepare` casts to is what + decides the file's physical type and logical annotation.""" + s, client, catalog, ns, table = _sink(columns=self._uuid_columns()) batch = coerce_typed_columns( pa.table({"uuid": [self.RAW], "event": ["e"], "team_id": [1]}), (("uuid", "uuid"),), ) s.write(batch) - return captured["files"][0] + return _real_encode(_published()) - def test_coerced_column_aligns_to_the_live_uuid_column(self, monkeypatch): + def test_coerced_column_aligns_to_the_live_uuid_column(self): # No add_column, no promote: `pa.uuid()` already IS the live type, # and since pyhoglake 1.3.0 it is also the type the destination schema # names, so `_prepare`'s cast is a no-op rather than a downgrade. - pf = self._written(monkeypatch) + pf = self._written() assert pf.schema.column(0).name == "uuid" assert pf.schema.column(0).physical_type == "FIXED_LEN_BYTE_ARRAY" assert pf.schema.column(0).length == 16 assert pf.read().column("uuid").to_pylist() == [uuid.UUID(self.RAW)] - def test_uploaded_parquet_carries_the_uuid_logical_annotation(self, monkeypatch): + def test_uploaded_parquet_carries_the_uuid_logical_annotation(self): """The file carries the parquet `LogicalTypeAnnotation.uuidType()` an Iceberg reader binds a uuid column through — the Trino hoglake connector among them. @@ -758,14 +911,14 @@ def test_uploaded_parquet_carries_the_uuid_logical_annotation(self, monkeypatch) `uuid` column with plain `pa.binary(16)` (`types.py` `coltype_to_arrow`), for which pyarrow stamps no logical type at all. Casting to `pa.uuid()` from the millpond side instead did produce the - annotation and then had the file REFUSED, because - `prepare_append_files` compared + annotation and then had the file REFUSED, because the + prepared-append path compared `parquet.schema_arrow.equals(columns_to_arrow_schema(...))` exactly — so the two spellings had to move together, which is what 1.3.0 did: `coltype_to_arrow("uuid")` returns `pa.uuid()` and append accepts either spelling. Nothing on this side changed; the pin did the work. """ - pf = self._written(monkeypatch) + pf = self._written() assert pf.schema.column(0).logical_type.type == "UUID" assert pf.schema_arrow.field("uuid").type == pa.uuid() @@ -1040,7 +1193,7 @@ def test_inserted_at_collision_raises_before_any_table_work(self): with pytest.raises(ValueError, match="Hoglake-reserved"): s.write(pa.table({"_inserted_at": ["x"], "uuid": ["a"]})) ns.table.assert_not_called() - table.prepare_append_files.assert_not_called() + table.prepare_append_tables.assert_not_called() @pytest.mark.parametrize("name", ["year", "month", "day", "hour"]) def test_hive_names_are_ordinary_columns_for_hoglake(self, name): @@ -1223,6 +1376,40 @@ def test_partition_spec_set_with_resolved_field_ids(self): assert fields[1]["source_field_id"] == 5 # _inserted_at assert fields[1]["transform"] == "month" + def test_a_spec_ddl_race_verifies_the_winners_spec_instead_of_trusting_it(self): + """The create-then-declare window with two pods in it: both + declare the same config-identical specs, the loser gets a 409, + and it re-reads rather than assuming the winner declared what it + would have. + + The re-read is the point and it had no test — `_declare_specs`' + `except CommitConflictError` arm is one of the sink's three + concurrent-DDL re-resolves, and the only thing standing between + "the winner declared the same thing" (an assumption) and + `_verify_specs` proving it. + """ + cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) + s, ns, table = self._create_flow(cfg) + table.alter.side_effect = CommitConflictError("concurrent DDL", status_code=409) + # What the winner actually declared, which is what the loser's + # re-read has to return for the verification to pass. + _set_info(table, _FakeInfo(columns=tuple(_EVENTS_COLUMNS), partition_spec=_spec(("team_id", "identity")))) + assert s.write(_batch()) == 1 + assert table.info.called, "the losing pod must re-read rather than trust the winner" + + def test_a_spec_ddl_race_whose_winner_declared_something_else_still_stops(self): + # The verification is not decoration: if the re-read shows a + # layout config did not ask for, the pod stops rather than + # writing under it. (A 409 from a pod with DIFFERENT config is + # exactly how that happens.) + cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) + s, ns, table = self._create_flow(cfg) + table.alter.side_effect = CommitConflictError("concurrent DDL", status_code=409) + _set_info(table, _FakeInfo(columns=tuple(_EVENTS_COLUMNS), partition_spec=_spec(("team_id", "bucket", 16)))) + with pytest.raises(RuntimeError, match="partition spec"): + s.write(_batch()) + assert s._table is None # nothing cached: the next attempt re-checks + def test_bucket_param_carried(self): cfg = _cfg(hoglake_partition_by=(("team_id", "bucket", 16),)) s, ns, table = self._create_flow(cfg) @@ -1301,7 +1488,7 @@ def test_a_bad_spec_keeps_failing_on_every_later_attempt(self): s.write(_batch()) s.reset_caches() assert table.alter.call_count == 3 - table.prepare_append_files.assert_not_called() + table.prepare_append_tables.assert_not_called() def test_post_condition_catches_a_spec_the_server_did_not_apply(self): # Belt and braces: if the alter reports success but the live spec @@ -1405,7 +1592,7 @@ def test_returns_record_count(self): s, *_, table = _sink() out = s.write(_batch()) assert out == 1 - assert table.prepare_append_files.call_count == 1 + assert table.prepare_append_tables.call_count == 1 def test_inserted_at_stamped_once_per_flush(self): s, *_, table = _sink() @@ -1450,13 +1637,64 @@ def test_add_failure_drops_column_and_continues(self, mock_metrics): def test_conflict_on_add_reresolves_and_proceeds(self, mock_metrics): # Another writer added the column concurrently: the 409 must not # fail the flush; re-resolve shows the column present. + # + # The two reads have to DISAGREE for this to test anything. With + # one pre-set shape that already carried `new_col`, the bootstrap + # resolve adopted it, `_evolve_and_align` found nothing to add, + # and the 409 handler this test is named for never executed — + # which is how it passed for months while covering nothing. The + # sequence is: resolve sees the old schema (so the add is + # attempted and conflicts), re-resolve sees the other writer's + # column. cols_after = _EVENTS_COLUMNS + [_col("new_col", "string", 6, 6)] s, client, catalog, ns, table = _sink() table.alter.side_effect = CommitConflictError("concurrent DDL", status_code=409) - table.info.return_value = _FakeInfo(columns=tuple(cols_after)) + _set_info_sequence( + table, + [_FakeInfo(columns=tuple(_EVENTS_COLUMNS)), _FakeInfo(columns=tuple(cols_after))], + ) s.write(pa.table({"uuid": ["a"], "new_col": ["x"]})) + add_ops = [o for c in table.alter.call_args_list for o in c.args[0] if o.op == "add_column"] + assert [o.body["column"]["name"] for o in add_ops] == ["new_col"], "the add was never attempted" appended = _published(table) assert "new_col" in appended.column_names + assert appended.column("new_col").to_pylist() == ["x"] + + @patch("millpond.hoglake.metrics") + def test_conflict_on_promote_reresolves_and_proceeds(self, mock_metrics): + # The same race on the OTHER evolution op, which had no test at + # all: two pods both widen `team_id` long->... no, `count` + # int->long, one of them loses the DDL race, and the loser's + # re-resolve shows the column already at the target type. Same + # posture as the add: degrade, do not fail the flush. + cols_before = _EVENTS_COLUMNS + [_col("count", "int", 6, 6)] + cols_after = _EVENTS_COLUMNS + [_col("count", "long", 6, 6)] + s, client, catalog, ns, table = _sink(columns=cols_before) + table.alter.side_effect = CommitConflictError("concurrent DDL", status_code=409) + _set_info_sequence( + table, + [_FakeInfo(columns=tuple(cols_before)), _FakeInfo(columns=tuple(cols_after))], + ) + s.write(pa.table({"uuid": ["a"], "count": pa.array([7], pa.int64())})) + promote_ops = [o for c in table.alter.call_args_list for o in c.args[0] if o.op == "promote_column"] + assert promote_ops and promote_ops[0].body == {"name": "count", "to": "long"} + # The winner's widening is what the flush writes against. + assert _published(table).column("count").type == pa.int64() + mock_metrics.schema_columns_widened_total.inc.assert_called_once() + + @patch("millpond.hoglake.metrics") + def test_a_promote_conflict_the_winner_did_not_resolve_degrades(self, mock_metrics): + # The other half: the 409 was not another pod declaring the same + # widening, so the re-resolve still shows the narrow type. The + # column stays as it is and the append-side cast decides per + # value — logged and metricked, never fatal. + cols_before = _EVENTS_COLUMNS + [_col("count", "int", 6, 6)] + s, client, catalog, ns, table = _sink(columns=cols_before) + table.alter.side_effect = CommitConflictError("concurrent DDL", status_code=409) + _set_info(table, _FakeInfo(columns=tuple(cols_before))) + assert s.write(pa.table({"uuid": ["a"], "count": pa.array([7], pa.int64())})) == 1 + mock_metrics.schema_columns_widened_total.inc.assert_not_called() + mock_metrics.errors_total.labels.assert_any_call(type="schema") @patch("millpond.hoglake.metrics") def test_several_new_columns_share_one_alter(self, mock_metrics): @@ -1533,29 +1771,26 @@ def test_unpromotable_mismatch_left_to_append_cast(self, mock_metrics): s, *_, table = _sink() s.write(pa.table({"uuid": ["a"], "team_id": pa.array([None], type=pa.string())})) assert table.alter.call_count == 0 - assert table.prepare_append_files.call_count == 1 + assert table.prepare_append_tables.call_count == 1 class TestRealSerialization: - """Every other test here reads the in-memory table handed to - `pq.write_table`, which the autouse fixture replaces with a no-op — - so the cast and the file it produces were never unit-exercised at - all. This one writes real parquet and reads it back.""" - - def test_the_file_written_is_the_table_cast_to_the_destination(self, monkeypatch): - monkeypatch.setattr(hoglake.pq, "write_table", _REAL_WRITE_TABLE) + """Every other test here reads the in-memory Arrow table the sink + handed to `prepare_append_tables`, which the mock never serializes — + so the parquet that lands in the lake was never unit-exercised at + all. This one encodes it the way pyhoglake's `_encode_group` does + (into a buffer, no temp file) and reads the footer back. + + The disk path this replaced wrote a real temp file per group and read + it with `pq.read_table`. Same two assertions, one less filesystem: + `_prepare` casts to the destination schema and pyhoglake encodes + exactly what it is given.""" + + def test_the_file_written_is_the_table_cast_to_the_destination(self): s, client, catalog, ns, table = _sink() - captured: dict[str, list] = {} - prepared = table.prepare_append_files.side_effect - - def prepare(files, **kwargs): - captured["files"] = [pq.read_table(path) for path, _ in files] - return prepared(files, **kwargs) - - table.prepare_append_files.side_effect = prepare # team_id arrives as int32; the live column is `long`. s.write(pa.table({"uuid": ["a"], "team_id": pa.array([5], type=pa.int32())})) - written = captured["files"][0] + written = _real_encode(_published()).read() # Column ORDER is the destination's, not the batch's: the # prepared path compares schemas position by position. assert written.schema.names == [c.name for c in _EVENTS_COLUMNS] @@ -1565,21 +1800,25 @@ def prepare(files, **kwargs): assert written.column("_inserted_at").null_count == 0 assert written.column("properties").null_count == 1 # absent upstream, null-filled - def test_a_partitioned_flush_writes_one_real_file_per_tuple(self, monkeypatch): - monkeypatch.setattr(hoglake.pq, "write_table", _REAL_WRITE_TABLE) + def test_the_encoded_file_carries_the_destination_field_ids(self): + # The comparison `prepare_append_tables` actually runs is on the + # ENCODED footer, field ids included — so a group whose schema + # carries them is only half the proof; they have to survive the + # encode. `PARQUET:field_id` metadata is what pyarrow writes into + # the parquet SchemaElement slots. + s, client, catalog, ns, table = _sink() + s.write(pa.table({"uuid": ["a"], "team_id": pa.array([5], type=pa.int32())})) + schema = _real_encode(_published()).schema_arrow + ids = [int(schema.field(c.name).metadata[b"PARQUET:field_id"]) for c in _EVENTS_COLUMNS] + assert ids == [c.field_id for c in _EVENTS_COLUMNS] + + def test_a_partitioned_flush_writes_one_real_file_per_tuple(self): cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) s, client, catalog, ns, table = _sink(cfg, partition_spec=_spec(("team_id", "identity"))) - captured: dict[str, list] = {} - prepared = table.prepare_append_files.side_effect - - def prepare(files, **kwargs): - captured["files"] = [(values, pq.read_table(path)) for path, values in files] - return prepared(files, **kwargs) - - table.prepare_append_files.side_effect = prepare s.write(pa.table({"uuid": ["a", "b", "c"], "team_id": [3, 1, 3]})) - assert [values for values, _ in captured["files"]] == [("3",), ("1",)] - assert [t.column("uuid").to_pylist() for _, t in captured["files"]] == [["a", "c"], ["b"]] + files = [(values, _real_encode(part).read()) for values, part in _groups()] + assert [values for values, _ in files] == [("3",), ("1",)] + assert [t.column("uuid").to_pylist() for _, t in files] == [["a", "c"], ["b"]] class TestPartitionGrouping: @@ -1670,7 +1909,7 @@ class TestIdempotentPublication: OFFSETS = (("events", 0, 30, 41), ("events", 1, 9, 17)) def _key(self, sink, offsets, table_uuid=TABLE_UUID): - return sink._flush_key(table_uuid, offsets) + return _flush_key_for(sink, offsets, table_uuid) def test_key_is_derived_from_the_offsets(self): s, *_ = _sink() @@ -1728,7 +1967,7 @@ def test_a_stale_handle_refuses_rather_than_publishing_across_incarnations(self, # and that handle is a NAME, not an incarnation. A drop+recreate # underneath it used to be invisible to every guard at once: # `_prepare`'s own `table.info()` rebases pyhoglake's pinned - # `_info` onto the new incarnation before `prepare_append_files` + # `_info` onto the new incarnation before `prepare_append_tables` # reads `self.table_uuid` off it, so the client's pre-flight, the # server's `expected_table_uuid` and # `_check_destination_still_ours` all compared fresh against @@ -1744,7 +1983,7 @@ def test_a_stale_handle_refuses_rather_than_publishing_across_incarnations(self, assert s.write(_rows(2), kafka_offsets=(("events", 0, 0, 1),)) == 2 reborn = "deadbeef-0000-0000-0000-000000000000" - table.info.return_value = _FakeInfo(columns=tuple(_EVENTS_COLUMNS), table_uuid=reborn) + _set_info(table, _FakeInfo(columns=tuple(_EVENTS_COLUMNS), table_uuid=reborn)) table.table_uuid = reborn with pytest.raises(IncarnationChangedError): @@ -1754,7 +1993,7 @@ def test_a_stale_handle_refuses_rather_than_publishing_across_incarnations(self, # The pre-flight refuses before the first upload, so there is no # orphan to count and counting one would send an operator # sweeping for an object that does not exist. - mock_metrics.hoglake_orphaned_files_total.inc.assert_not_called() + assert _orphans(mock_metrics) == [] # Retryable: main.py resets caches, the next attempt re-resolves # — which is what finally puts the recreated table through @@ -1778,15 +2017,25 @@ def test_commit_carries_the_derived_key(self): assert payload["idempotency_key"] == self._key(s, self.OFFSETS) assert payload["author"] == "millpond/events/0" - def test_payload_is_a_blind_append(self): - # prepare_append_files pins read_snapshot to the catalog head, - # and the server then 409s the commit if ANY DDL touched this - # table since — which for millpond means "another pod added a - # column". A frozen payload can never clear that conflict. - # Appends never conflict with appends, so the field comes off. + def test_the_payload_keeps_its_read_snapshot(self): + # The field used to come OFF here. `prepare_append_*` binds + # `read_snapshot` to the snapshot the table info was resolved at, + # and the server 409s the commit if any DDL touched this table + # since — which for millpond means "another pod added a column". + # A frozen payload can never clear that by replaying, and before + # the typed refusals the answer was an untyped retryable 409, so + # the sink stripped the field and bought itself a commit with no + # conflict window at all. + # + # Now the refusal is `ddl_since_read_snapshot` / + # `table_recreated` / a 410, each of which `_commit_prepared` + # answers by discarding the payload and rebuilding — the recovery + # a frozen payload actually has. So the basis stays on, which is + # what lets the server refuse a DDL race at all, and what + # HOGLAKE_REFUSE_BLIND_PARTITIONED_APPENDS will require. s, client, catalog, ns, table = _sink() s.write(_batch(), kafka_offsets=self.OFFSETS) - assert "read_snapshot" not in catalog.commit_prepared.call_args.args[0] + assert catalog.commit_prepared.call_args.args[0]["read_snapshot"] == 41 def test_retry_replays_the_same_payload_without_re_uploading(self): s, client, catalog, ns, table = _sink() @@ -1796,7 +2045,7 @@ def test_retry_replays_the_same_payload_without_re_uploading(self): # The retry path invalidates caches first, exactly as main.py does. s.reset_caches() assert s.write(_rows(3), kafka_offsets=self.OFFSETS) == 3 - assert table.prepare_append_files.call_count == 1 # no second upload + assert table.prepare_append_tables.call_count == 1 # no second upload first, second = (c.args[0] for c in catalog.commit_prepared.call_args_list) assert first == second # byte-identical replay @@ -1833,7 +2082,7 @@ def test_a_different_flush_prepares_again(self): s, client, catalog, ns, table = _sink() s.write(_batch(), kafka_offsets=self.OFFSETS) s.write(_batch(), kafka_offsets=(("events", 0, 42, 99),)) - assert table.prepare_append_files.call_count == 2 + assert table.prepare_append_tables.call_count == 2 keys = {c.args[0]["idempotency_key"] for c in catalog.commit_prepared.call_args_list} assert len(keys) == 2 @@ -1848,11 +2097,11 @@ def test_a_held_payload_is_never_replayed_for_a_different_flush(self, mock_metri s.write(_rows(3), kafka_offsets=self.OFFSETS) moved_on = (("events", 0, 42, 99),) assert s.write(_rows(7), kafka_offsets=moved_on) == 7 - assert table.prepare_append_files.call_count == 2 # rebuilt, not replayed + assert table.prepare_append_tables.call_count == 2 # rebuilt, not replayed sent = catalog.commit_prepared.call_args.args[0] assert sent["idempotency_key"] == self._key(s, moved_on) # The abandoned upload is an orphan and is counted as one. - mock_metrics.hoglake_orphaned_files_total.inc.assert_called_once_with(1) + assert _orphans(mock_metrics) == [("superseded", 1)] def test_a_retry_is_recognized_by_its_kafka_identity_not_by_a_re_derived_key(self): # The identity the payload was BUILT for is what makes a retry a @@ -1873,31 +2122,41 @@ def test_a_retry_is_recognized_by_its_kafka_identity_not_by_a_re_derived_key(sel s.write(_rows(3), kafka_offsets=self.OFFSETS) s.reset_caches() reborn = "deadbeef-0000-0000-0000-000000000000" - table.info.return_value = _FakeInfo(columns=tuple(_EVENTS_COLUMNS), table_uuid=reborn) + _set_info(table, _FakeInfo(columns=tuple(_EVENTS_COLUMNS), table_uuid=reborn)) table.table_uuid = reborn - with pytest.raises(IncarnationChangedError): + # The replay is sent verbatim and the SERVER judges it: the + # payload's own `expected_table_uuid` still names the dead + # incarnation, so the commit comes back 409 `table_recreated`. + catalog.commit_prepared.side_effect = IncarnationChangedError( + "table_recreated", status_code=409, table="analytics.events" + ) + with pytest.raises(hoglake.HoglakeSinkError, match="recreated"): s.write(_rows(3), kafka_offsets=self.OFFSETS) - assert table.prepare_append_files.call_count == 1 # replayed and judged, never rebuilt - - def test_the_commit_time_lookup_never_becomes_the_reconciled_cache(self): - # `_live_table` resolves a bare handle for the pre-commit - # incarnation/spec check, and must not cache it: `self._table` - # means "resolved AND reconciled by `_ensure_table`", and a - # handle fetched here has been through neither. Caching it would - # let the next flush write under a layout this pod never checked - # against config. + assert table.prepare_append_tables.call_count == 1 # replayed and judged, never rebuilt + assert catalog.commit_prepared.call_args.args[0]["appends"][0]["expected_table_uuid"] == TABLE_UUID + + def test_a_replay_resolves_nothing_and_leaves_no_reconciled_cache(self): + # The replay path short-circuits to the commit, so after a + # `reset_caches()` it touches neither the namespace nor the + # table: there is no handle to resolve and nothing to reconcile, + # and `self._table` must stay empty — that cache means "resolved + # AND reconciled by `_ensure_table`", and a flush writing under a + # layout this pod never checked against config is the thing it + # guards. (Before the pre-commit destination read was retired, + # this was a statement about `_live_table` deliberately not + # caching the bare handle it fetched. Now there is no such read, + # which is a stronger version of the same guarantee.) s, client, catalog, ns, table = _sink() catalog.commit_prepared.side_effect = [httpx.ReadTimeout("lost"), MagicMock(), MagicMock()] with pytest.raises(httpx.ReadTimeout): s.write(_rows(2), kafka_offsets=self.OFFSETS) - # main.py's retry path: caches dropped, so the replay's - # destination check is what resolves the handle. s.reset_caches() + resolves = ns.table.call_count assert s.write(_rows(2), kafka_offsets=self.OFFSETS) == 2 assert s._table is None + assert ns.table.call_count == resolves # the replay resolved nothing # ...and the consequence that makes it matter: the next ordinary # flush still goes through `_ensure_table`'s resolve-and-reconcile. - resolves = ns.table.call_count assert s.write(_rows(2), kafka_offsets=(("events", 0, 42, 43),)) == 2 assert ns.table.call_count > resolves @@ -1914,7 +2173,7 @@ def test_an_empty_offset_tuple_is_not_an_identity(self): with pytest.raises(httpx.ReadTimeout): s.write(_rows(3), kafka_offsets=()) assert s.write(_rows(7), kafka_offsets=()) == 7 - assert table.prepare_append_files.call_count == 2 # rebuilt, never replayed + assert table.prepare_append_tables.call_count == 2 # rebuilt, never replayed @patch("millpond.hoglake.metrics") def test_key_reused_with_a_different_payload_publishes_nothing(self, mock_metrics): @@ -1944,24 +2203,51 @@ def test_key_reused_with_a_different_payload_publishes_nothing(self, mock_metric mock_metrics.hoglake_commit_replays_total.labels.assert_called_once_with(outcome="already_published") # The upload we just made is unreferenced and nothing will # reclaim it — say so in a metric rather than in nothing. - mock_metrics.hoglake_orphaned_files_total.inc.assert_called_once_with(1) + assert _orphans(mock_metrics) == [("already_published", 1)] assert s._prepared is None - def test_a_reused_key_against_a_recreated_table_is_not_accepted(self): - # A receipt from the PREVIOUS incarnation must never stand in for - # a publication to this one. (The key names the incarnation, so - # this is belt and braces on the same invariant.) + @patch("millpond.hoglake.metrics") + def test_a_receipt_is_only_accepted_for_this_incarnation(self, mock_metrics): + """A receipt from the PREVIOUS incarnation must never stand in for + a publication to this one. + + This used to be checked by re-reading the table immediately + before the commit and comparing uuids. That read is gone, and the + invariant now rests on two things the server cannot get wrong: + the key NAMES the incarnation (`_flush_key` hashes + `self._table_uuid` in, so a receipt under this key was written by + a commit to this table_uuid — see + `test_key_names_the_table_incarnation`), and the payload carries + `expected_table_uuid`, which a recreated destination answers with + 409 `table_recreated` rather than with a receipt. The 409 arrives + as a refusal, not an acceptance: nothing is published, the + payload is discarded and its upload is counted.""" s, client, catalog, ns, table = _sink() - catalog.commit_prepared.side_effect = ValidationError( - "validation", status_code=422, detail="idempotency_key reused with a different request" + catalog.commit_prepared.side_effect = IncarnationChangedError( + "table_recreated", + status_code=409, + detail="table 'analytics.events' no longer has the expected UUID", + table="analytics.events", ) - infos = [_FakeInfo(columns=tuple(_EVENTS_COLUMNS)), _FakeInfo(columns=tuple(_EVENTS_COLUMNS))] - infos.append(_FakeInfo(columns=tuple(_EVENTS_COLUMNS), table_uuid="deadbeef-0000-0000-0000-000000000000")) - table.info.side_effect = infos - with pytest.raises(IncarnationChangedError): + with pytest.raises(hoglake.HoglakeSinkError, match="recreated"): s.write(_rows(5), kafka_offsets=self.OFFSETS) assert s._prepared is None - + mock_metrics.hoglake_commit_replays_total.labels.assert_not_called() + assert _orphans(mock_metrics) == [("table_recreated", 1)] + + # NO UNIT TEST for the composite case "a reused-key 422 arrives for + # a FOREIGN incarnation". It used to live here as + # `test_a_reused_key_against_a_recreated_table_is_not_accepted`, and + # it worked by sequencing the pre-commit table read the sink no + # longer makes — so the unit-level version could only assert against + # a mechanism that is gone. The invariant it guarded is now two + # things, each tested on its own above (`table_uuid` is inside + # `_flush_key`, so a receipt under this key belongs to this + # incarnation; and the server answers a recreated destination with + # 409 `table_recreated` rather than from a receipt). The composite + # sequence itself is covered end to end against a real server by + # `test_a_recreated_table_does_not_answer_from_the_old_receipt` in + # tests/integration/test_hoglake_integration.py. @pytest.mark.parametrize( "detail", [ @@ -2022,10 +2308,13 @@ class TestRefusedCommitsDropThePayload: OFFSETS = (("events", 0, 30, 41),) + # The three typed "the destination moved" refusals are NOT here: they + # are converted to a retryable `HoglakeSinkError` and have their own + # class (`TestTypedDestinationMovedRefusals`), which asserts the same + # discard-and-re-resolve shape plus the cache drop they add. @pytest.mark.parametrize( "exc", [ - IncarnationChangedError("table was recreated", status_code=409, detail="the table was recreated"), CommitConflictError("commit_conflict", status_code=409, detail="removal queue collision"), ValidationError("validation", status_code=422, detail="path outside the catalog data path"), ], @@ -2037,13 +2326,13 @@ def test_an_answered_refusal_drops_the_payload_and_re_resolves(self, mock_metric with pytest.raises(type(exc)): s.write(_rows(2), kafka_offsets=self.OFFSETS) assert s._prepared is None - mock_metrics.hoglake_orphaned_files_total.inc.assert_called_once_with(1) + assert _orphans(mock_metrics) == [("commit_refused", 1)] # The next attempt (main.py resets caches first) rebuilds rather # than re-sending a request the server already judged. catalog.commit_prepared.side_effect = None s.reset_caches() assert s.write(_rows(2), kafka_offsets=self.OFFSETS) == 2 - assert table.prepare_append_files.call_count == 2 + assert table.prepare_append_tables.call_count == 2 assert ns.table.call_count == 2 # the table WAS re-resolved def test_transport_uncertainty_keeps_the_payload(self): @@ -2093,13 +2382,13 @@ def test_a_prepare_refusal_that_uploaded_nothing_counts_zero(self, mock_metrics, # and `write()` self-heals into a flush that SUCCEEDS. cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) s, client, catalog, ns, table = _sink(cfg, partition_spec=_spec(("team_id", "identity"))) - table.prepare_append_files.side_effect = _stamped(ValidationError(detail, status_code=None), 0) + table.prepare_append_tables.side_effect = _stamped(ValidationError(detail, status_code=None), 0) with pytest.raises(ValidationError): s.write( pa.table({"uuid": [f"u{i}" for i in range(rows)], "team_id": list(range(rows))}), kafka_offsets=self.OFFSETS, ) - mock_metrics.hoglake_orphaned_files_total.inc.assert_not_called() + assert _orphans(mock_metrics) == [] @pytest.mark.parametrize( "exc", @@ -2119,10 +2408,10 @@ def test_a_prepare_that_fails_before_the_first_byte_is_not_counted(self, mock_me # fanout) cannot book 64 phantom orphans a flush. cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) s, client, catalog, ns, table = _sink(cfg, partition_spec=_spec(("team_id", "identity"))) - table.prepare_append_files.side_effect = _stamped(exc, 0) + table.prepare_append_tables.side_effect = _stamped(exc, 0) with pytest.raises(type(exc)): s.write(pa.table({"uuid": ["a", "b", "c"], "team_id": [1, 2, 3]}), kafka_offsets=self.OFFSETS) - mock_metrics.hoglake_orphaned_files_total.inc.assert_not_called() + assert _orphans(mock_metrics) == [] @patch("millpond.hoglake.metrics") def test_a_prepare_that_failed_mid_fanout_counts_exactly_what_landed(self, mock_metrics, caplog): @@ -2133,10 +2422,10 @@ def test_a_prepare_that_failed_mid_fanout_counts_exactly_what_landed(self, mock_ cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) s, client, catalog, ns, table = _sink(cfg, partition_spec=_spec(("team_id", "identity"))) uris = (f"{_URI_BASE}/aaaa-0.parquet", f"{_URI_BASE}/bbbb-1.parquet") - table.prepare_append_files.side_effect = _stamped(OSError("S3 reset midway"), 2, uris) + table.prepare_append_tables.side_effect = _stamped(OSError("S3 reset midway"), 2, uris) with caplog.at_level(logging.WARNING, logger="millpond.hoglake"), pytest.raises(OSError): s.write(pa.table({"uuid": ["a", "b", "c"], "team_id": [1, 2, 3]}), kafka_offsets=self.OFFSETS) - mock_metrics.hoglake_orphaned_files_total.inc.assert_called_once_with(2) + assert _orphans(mock_metrics) == [("prepare_failed", 2)] assert "Orphaned 2 uploaded parquet file(s)" in caplog.text @patch("millpond.hoglake.metrics") @@ -2149,7 +2438,7 @@ def test_the_orphan_log_names_the_uris_and_retracts_the_prefix_sweep(self, mock_ cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) s, client, catalog, ns, table = _sink(cfg, partition_spec=_spec(("team_id", "identity"))) uris = (f"{_URI_BASE}/aaaa-0.parquet", f"{_URI_BASE}/bbbb-1.parquet") - table.prepare_append_files.side_effect = _stamped(OSError("S3 reset midway"), 2, uris) + table.prepare_append_tables.side_effect = _stamped(OSError("S3 reset midway"), 2, uris) with caplog.at_level(logging.WARNING, logger="millpond.hoglake"), pytest.raises(OSError): s.write(pa.table({"uuid": ["a", "b", "c"], "team_id": [1, 2, 3]}), kafka_offsets=self.OFFSETS) for uri in uris: @@ -2168,10 +2457,10 @@ def test_the_file_that_failed_is_uncounted_but_flagged_as_possibly_there(self, m cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) s, client, catalog, ns, table = _sink(cfg, partition_spec=_spec(("team_id", "identity"))) uris = (f"{_URI_BASE}/aaaa-0.parquet",) - table.prepare_append_files.side_effect = _stamped(OSError("close failed"), 1, uris) + table.prepare_append_tables.side_effect = _stamped(OSError("close failed"), 1, uris) with caplog.at_level(logging.WARNING, logger="millpond.hoglake"), pytest.raises(OSError): s.write(pa.table({"uuid": ["a", "b", "c"], "team_id": [1, 2, 3]}), kafka_offsets=self.OFFSETS) - mock_metrics.hoglake_orphaned_files_total.inc.assert_called_once_with(1) + assert _orphans(mock_metrics) == [("prepare_failed", 1)] assert "truncated" in caplog.text @patch("millpond.hoglake.metrics") @@ -2181,10 +2470,10 @@ def test_a_wide_fanout_logs_a_capped_list_and_says_what_it_omitted(self, mock_me cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) s, client, catalog, ns, table = _sink(cfg, partition_spec=_spec(("team_id", "identity"))) uris = tuple(f"{_URI_BASE}/f{i:03d}-{i}.parquet" for i in range(25)) - table.prepare_append_files.side_effect = _stamped(OSError("S3 reset midway"), len(uris), uris) + table.prepare_append_tables.side_effect = _stamped(OSError("S3 reset midway"), len(uris), uris) with caplog.at_level(logging.WARNING, logger="millpond.hoglake"), pytest.raises(OSError): s.write(pa.table({"uuid": ["a", "b", "c"], "team_id": [1, 2, 3]}), kafka_offsets=self.OFFSETS) - mock_metrics.hoglake_orphaned_files_total.inc.assert_called_once_with(25) + assert _orphans(mock_metrics) == [("prepare_failed", 25)] listed = [uri for uri in uris if uri in caplog.text] assert len(listed) == hoglake._ORPHAN_URIS_LOGGED assert listed == list(uris[: hoglake._ORPHAN_URIS_LOGGED]) @@ -2202,11 +2491,11 @@ def test_an_older_client_without_the_attributes_counts_zero(self, mock_metrics, s, client, catalog, ns, table = _sink(cfg, partition_spec=_spec(("team_id", "identity"))) bare = OSError("S3 reset midway") assert not hasattr(bare, "uploaded_files") - table.prepare_append_files.side_effect = bare + table.prepare_append_tables.side_effect = bare with caplog.at_level(logging.WARNING, logger="millpond.hoglake"), pytest.raises(OSError) as caught: s.write(pa.table({"uuid": ["a", "b", "c"], "team_id": [1, 2, 3]}), kafka_offsets=self.OFFSETS) assert caught.value is bare # the original error, not an AttributeError over it - mock_metrics.hoglake_orphaned_files_total.inc.assert_not_called() + assert _orphans(mock_metrics) == [] @patch("millpond.hoglake.metrics") def test_a_discarded_payload_names_the_objects_it_orphans(self, mock_metrics, caplog): @@ -2244,7 +2533,622 @@ def test_close_counts_an_unpublished_payload(self, mock_metrics): with pytest.raises(httpx.ReadTimeout): s.write(_rows(2), kafka_offsets=self.OFFSETS) s.close() - mock_metrics.hoglake_orphaned_files_total.inc.assert_called_once_with(1) + assert _orphans(mock_metrics) == [("shutdown", 1)] + + +class TestZeroSinkSideReadsPerFlush: + """The steady-state flush makes no SINK-SIDE catalog read. + + Sink-side, precisely: these are mock assertions on the handles + millpond itself calls, so they cannot see a read pyhoglake makes + inside `prepare_append_tables` (its own head refresh, its + incarnation re-resolve). The wire-level claim — that the whole + flush is one request — is asserted against a real server in + `tests/integration/test_hoglake_integration.py` + (`TestOneRequestPerFlush`), which counts HTTP requests through the + sink's own httpx client. + + What used to happen per flush: a `table.info()` at the top of + `_prepare` (whose live-totals scan is a count and two sums over every + live file row — ~15M on prod-us) and a second one in the pre-commit + destination check, plus pyhoglake's own catalog head read. The basis + the server needs to prove the files match the destination is now the + payload's `read_snapshot`, so the shape is cached and the reads are + gone: one identity read per resolve, nothing per flush.""" + + OFFSETS = (("events", 0, 30, 41),) + + def test_the_first_flush_reads_the_table_once(self): + s, client, catalog, ns, table = _sink() + assert s.write(_batch(), kafka_offsets=self.OFFSETS) == 1 + # `_ensure_table` -> `_reconcile_specs`, which is the read that + # seeds the cache. `_prepare` adds none. + assert table.info.call_count == 1 + + def test_the_second_flush_reads_nothing(self): + s, client, catalog, ns, table = _sink() + s.write(_batch(), kafka_offsets=self.OFFSETS) + table.info.reset_mock() + ns.table.reset_mock() + catalog.namespace.reset_mock() + catalog.refresh.reset_mock() + assert s.write(_batch(), kafka_offsets=(("events", 0, 42, 43),)) == 1 + assert table.info.call_count == 0 + # ...and no catalog GET either: no namespace resolve, no table + # resolve, no head read. The commit is the only request. + assert ns.table.call_count == 0 + assert catalog.namespace.call_count == 0 + assert catalog.commit_prepared.call_count == 2 + + def test_a_long_run_of_flushes_still_reads_nothing(self): + # The per-flush cost has to be flat, not amortized: a read every + # Nth flush is still a live-totals scan on prod-us. + s, client, catalog, ns, table = _sink() + for i in range(10): + s.write(_batch(), kafka_offsets=(("events", 0, i, i),)) + assert table.info.call_count == 1 + + def test_every_info_read_skips_the_live_totals(self): + # Bootstrap, reconciliation, the alignment self-heal and the + # cache refresh all read for the uuid, the columns and the specs. + # None of them has ever read a total, and the scan that produces + # them is the whole cost of the call. + cols_after = _EVENTS_COLUMNS + [_col("other_writer_col", "string", 6, 6)] + s, client, catalog, ns, table = _sink() + prepared = table.prepare_append_tables.side_effect + calls = {"n": 0} + + def prepare(groups, **kwargs): + calls["n"] += 1 + if calls["n"] == 1: + raise ValidationError("prepared Parquet schema/field IDs differ from destination", status_code=None) + return prepared(groups, **kwargs) + + table.prepare_append_tables.side_effect = prepare + _set_info(table, _FakeInfo(columns=tuple(cols_after))) + assert s.write(_batch(), kafka_offsets=self.OFFSETS) == 1 + assert table.info.call_count >= 2 # reconcile + the self-heal refresh + for call in table.info.call_args_list: + assert call.kwargs.get("totals") is False, f"info read without totals=False: {call}" + + def test_a_reset_makes_the_next_flush_read_again(self): + # The cached shape belongs to the handle it was read through, so + # a reset drops it: otherwise the flush after a re-resolve would + # build against a shape read off the old handle, which this pod + # has not re-reconciled against config. + s, client, catalog, ns, table = _sink() + s.write(_batch(), kafka_offsets=self.OFFSETS) + assert s._live_info is not None + s.reset_caches() + assert s._live_info is None + table.info.reset_mock() + assert s.write(_batch(), kafka_offsets=(("events", 0, 42, 43),)) == 1 + assert table.info.call_count == 1 + + +class TestTheCachedShapeHasATtl: + """The cache is only safe because it expires sooner than pyhoglake's. + + `read_snapshot` — the commit's whole conflict basis — comes from + `Table._cache`, which pyhoglake refreshes at half the catalog's + snapshot retention. Once that happens the basis sits AHEAD of any + earlier `ALTER`, so the server's conflict scan finds nothing. A sink + holding an older partition spec would then compute values under the + superseded transform, pass pyhoglake's only structural check on them + (arity, unchanged by a same-arity re-spec), pass the footer compare + (no column moved), and have the commit ACCEPTED with the live + spec_id stamped on files carrying the old spec's values. Nothing on + the file or in the request records which transform produced a + partition value, so no later read can detect it: every scan prunes + those files wrongly, forever. + + Re-reading at a QUARTER of the retention is what makes that state + unreachable — the sink always refreshes first, so the spec it + computes under is never older than the basis the commit carries. + These tests fail if `_live_info_ttl_s` is removed or raised above + pyhoglake's half. + """ + + OFFSETS = (("events", 0, 30, 41),) + RETENTION_S = 3600.0 + + def _clocked(self, cfg=None, **kw): + """A sink whose clock this test drives. `now()` advances it.""" + s, client, catalog, ns, table = _sink(cfg, **kw) + clock = {"t": 1000.0} + s._monotonic = lambda: clock["t"] + # Re-stamp what the bootstrap read took on the real clock, so + # "age" is measured from this test's zero. + s._live_info_read_at = clock["t"] + return s, catalog, table, clock + + def test_the_ttl_is_half_of_pyhoglakes_threshold(self): + # The INVARIANT, as arithmetic rather than as prose: pyhoglake + # prepares against its cache while it is younger than + # retention/2, so anything at retention/2 or above here would let + # the sink be the staler of the two. + s, catalog, table, clock = self._clocked() + assert s._live_info_ttl_s() == self.RETENTION_S / 4 + assert s._live_info_ttl_s() < self.RETENTION_S / 2 + + def test_before_the_ttl_a_second_flush_reads_nothing(self): + s, catalog, table, clock = self._clocked() + s.write(_batch(), kafka_offsets=self.OFFSETS) + table.info.reset_mock() + clock["t"] += self.RETENTION_S / 4 - 1 + assert s.write(_batch(), kafka_offsets=(("events", 0, 42, 43),)) == 1 + assert table.info.call_count == 0 + + def test_past_the_ttl_the_flush_re_reads_and_uses_the_new_spec(self, monkeypatch): + """THE P1 CASE, and the one that cannot be seen from outside. + + A same-arity re-spec lands while this pod is running. pyhoglake's + own cache self-refreshes past it, carrying the conflict window + with it, so the commit is ACCEPTED — and the only thing wrong + with the files is that their partition values were computed under + a transform nothing records. The sink has to notice the new spec + before pyhoglake stops refusing on its behalf. + + `_reconcile_specs` is stubbed out for this test alone, because + the two things the TTL refresh buys are independent and have to + be asserted separately: ANY live spec that differs from config is + fatal to that check, so leaving it in means every re-spec + scenario ends in its exception and the value computation below is + never reached. The tripwire is the next test's subject. + """ + cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) + s, catalog, table, clock = self._clocked(cfg, partition_spec=_spec(("team_id", "identity"))) + monkeypatch.setattr(hoglake.HoglakeSink, "_reconcile_specs", lambda self, table, info=None: None) + s.write(pa.table({"uuid": ["a"], "team_id": [1]}), kafka_offsets=self.OFFSETS) + assert [values for values, _ in _groups()] == [("1",)], "flush 1 should use identity values" + + # The re-spec, and a clock past the TTL. + _set_info(table, _FakeInfo(columns=tuple(_EVENTS_COLUMNS), partition_spec=_spec(("team_id", "bucket", 16)))) + table.info.reset_mock() + clock["t"] += self.RETENTION_S / 4 + 1 + + assert s.write(pa.table({"uuid": ["b"], "team_id": [1]}), kafka_offsets=(("events", 0, 42, 43),)) == 1 + assert table.info.call_count == 1, "the TTL must force exactly one re-read" + values = [v for v, _ in _groups()] + # bucket(1, 16) is not the identity string "1" — the point is + # that the VALUES moved, not which bucket it is. + assert values != [("1",)], "the flush is still computing values under the superseded spec" + assert len(values) == 1 and values[0][0] is not None + # And the registration carries them, so what would have been + # mis-stamped is what the commit now describes. + assert _committed(catalog)["appends"][0]["files"][0]["partition_values"] == list(values[0]) + + def test_a_shape_adopted_without_a_config_check_is_still_reconciled(self): + """A FRESH shape is not necessarily a RECONCILED one. + + `_adopt_info` is reached from schema evolution and from + `write()`'s alignment self-heal, and all of those adopt whatever + layout is live and re-stamp the TTL clock with no config check + anywhere. The fresh-path early return in `_table_info` therefore + skipped `_reconcile_specs` entirely for those shapes — and a pod + drifting columns often enough could keep the shape perpetually + fresh and postpone the TTL's own reconciliation indefinitely, + writing under an externally re-specced layout the whole time. + + Driven through the self-heal, which is the shortest path to + "adopted a fresh external shape mid-flush" that does not involve + the clock at all: no TTL has expired here. + """ + cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) + s, catalog, table, clock = self._clocked(cfg, partition_spec=_spec(("team_id", "identity"))) + s.write(pa.table({"uuid": ["a"], "team_id": [1]}), kafka_offsets=self.OFFSETS) + + # The external re-spec, picked up by the self-heal's refresh + # rather than by a TTL refresh: the clock does not move. + respecced = _FakeInfo(columns=tuple(_EVENTS_COLUMNS), partition_spec=_spec(("team_id", "bucket", 16))) + _set_info(table, respecced) + prepared = table.prepare_append_tables.side_effect + calls = {"n": 0} + + def prepare(groups, **kwargs): + calls["n"] += 1 + if calls["n"] == 1: + raise ValidationError("prepared Parquet schema/field IDs differ from destination", status_code=None) + return prepared(groups, **kwargs) + + table.prepare_append_tables.side_effect = prepare + with pytest.raises(hoglake.HoglakeSinkError, match="does not match"): + s.write(pa.table({"uuid": ["b"], "team_id": [1]}), kafka_offsets=(("events", 0, 42, 43),)) + + def test_a_reconciled_layout_is_not_re_checked_every_flush(self): + # The check is keyed on the LAYOUT, not on the shape: a + # concurrent add_column changes the columns and must not drag + # the config comparison onto every schema-evolution flush. + cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) + s, catalog, table, clock = self._clocked(cfg, partition_spec=_spec(("team_id", "identity"))) + s.write(pa.table({"uuid": ["a"], "team_id": [1]}), kafka_offsets=self.OFFSETS) + with patch.object(hoglake.HoglakeSink, "_reconcile_specs") as reconcile: + for i in range(5): + s.write(pa.table({"uuid": ["b"], "team_id": [1]}), kafka_offsets=(("events", 0, i, i),)) + reconcile.assert_not_called() + + def test_past_the_ttl_a_config_divergence_finally_stops_the_pod(self): + # The second thing the periodic re-read buys: before it, the + # "config disagrees with the live layout => stop" tripwire ran + # only at pod start, so a re-spec under a running fleet was + # silent on every pod that had not restarted. + cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) + s, catalog, table, clock = self._clocked(cfg, partition_spec=_spec(("team_id", "identity"))) + s.write(pa.table({"uuid": ["a"], "team_id": [1]}), kafka_offsets=self.OFFSETS) + _set_info(table, _FakeInfo(columns=tuple(_EVENTS_COLUMNS), partition_spec=_spec(("team_id", "bucket", 16)))) + clock["t"] += self.RETENTION_S / 4 + 1 + with pytest.raises(hoglake.HoglakeSinkError, match="does not match"): + s.write(pa.table({"uuid": ["b"], "team_id": [1]}), kafka_offsets=(("events", 0, 42, 43),)) + + def test_the_refresh_re_reads_once_not_once_per_flush(self): + s, catalog, table, clock = self._clocked() + s.write(_batch(), kafka_offsets=self.OFFSETS) + clock["t"] += self.RETENTION_S / 4 + 1 + table.info.reset_mock() + for i in range(5): + s.write(_batch(), kafka_offsets=(("events", 0, i, i),)) + assert table.info.call_count == 1, "the refresh must re-stamp the clock, not re-read every flush" + + def test_an_unreadable_retention_falls_back_rather_than_disabling_the_ttl(self): + # pyhoglake answers its own assumed retention when the options + # read fails, and the fallback has to keep the factor-of-two: a + # TTL of zero would read per flush, and an infinite one would + # reopen the hazard above. + s, catalog, table, clock = self._clocked() + catalog._retention_seconds.side_effect = HoglakeError("options unavailable", status_code=503) + assert s._live_info_ttl_s() == hoglake._ASSUMED_RETENTION_S / 4 + + @pytest.mark.parametrize("answer", [None, 0, -1, "3600", True]) + def test_an_unusable_retention_value_falls_back(self, answer): + # A pyhoglake that changes the return shape (or a test double + # that answers a Mock) must not silently make the TTL zero or + # infinite — both are the hazard, in opposite directions. + s, catalog, table, clock = self._clocked() + catalog._retention_seconds.return_value = answer + assert s._live_info_ttl_s() == hoglake._ASSUMED_RETENTION_S / 4 + + def test_a_missing_accessor_falls_back(self): + # `_retention_seconds` is private. A rename must degrade to the + # assumed retention, not to an exception on the write path. + s, catalog, table, clock = self._clocked() + del catalog._retention_seconds + catalog.mock_add_spec(["data_path", "commit_prepared", "namespace", "refresh"]) + assert s._live_info_ttl_s() == hoglake._ASSUMED_RETENTION_S / 4 + + def test_retention_disabled_never_expires_and_that_is_correct(self): + # inf: pyhoglake's cache never ages out either, so the basis + # stays pinned at the sink's own read and ANY later alter is + # inside the conflict window. The invariant holds trivially. + s, catalog, table, clock = self._clocked() + catalog._retention_seconds.return_value = float("inf") + s.write(_batch(), kafka_offsets=self.OFFSETS) + table.info.reset_mock() + clock["t"] += 10**9 + assert s.write(_batch(), kafka_offsets=(("events", 0, 42, 43),)) == 1 + assert table.info.call_count == 0 + + +class TestTypedDestinationMovedRefusals: + """The three refusals that say "the destination moved under your + basis", which is what retired the pre-commit destination read. + + Each is a commit the server judged and refused atomically with zero + rows written, each is permanent for THIS payload (a prepared + request's `read_snapshot` is frozen, the expiry floor only moves + forward, an alter does not un-happen), and each is cleared by a + REBUILT flush. So all three take one path: discard the payload (its + upload is an orphan and is counted), drop the cached shape so the + rebuild reads fresh, and raise one retryable `HoglakeSinkError`. + + The conversion is load-bearing, not cosmetic. + `DdlSinceReadSnapshotError` subclasses `CommitConflictError` — which + `is_retryable` calls retryable — so leaving it alone would replay a + payload whose basis can never be accepted. `ReadSnapshotExpiredError` + subclasses `ExpiredError`, which `is_retryable` calls permanent, so + leaving THAT alone would crash the pod on a flush a rebuild + publishes cleanly.""" + + OFFSETS = (("events", 0, 30, 41),) + + # (exception, message substring, expected orphan `reason` label). + # The label is parametrized rather than asserted loosely because it + # is the only thing that tells these three apart on a dashboard. + REFUSALS = [ + pytest.param( + DdlSinceReadSnapshotError( + "ddl_since_read_snapshot", + status_code=409, + detail="concurrent DDL since snapshot 41 on table(s): analytics.events", + tables=("analytics.events",), + read_snapshot=41, + ), + "schema or partition spec", + "ddl_since_read_snapshot", + id="ddl_since_read_snapshot", + ), + pytest.param( + IncarnationChangedError( + "table_recreated", + status_code=409, + detail="table 'analytics.events' no longer has the expected UUID", + table="analytics.events", + ), + "recreated", + "table_recreated", + id="table_recreated", + ), + pytest.param( + ReadSnapshotExpiredError( + "expired", + status_code=410, + detail="read_snapshot 41 is below the expiry floor (earliest retained snapshot is 90)", + ), + "expired before the commit", + "read_snapshot_expired", + id="read_snapshot_expired", + ), + ] + + @pytest.mark.parametrize(("exc", "match", "reason"), REFUSALS) + @patch("millpond.hoglake.metrics") + def test_the_payload_is_discarded_and_the_cache_dropped(self, mock_metrics, exc, match, reason): + s, client, catalog, ns, table = _sink() + catalog.commit_prepared.side_effect = exc + with pytest.raises(hoglake.HoglakeSinkError, match=match) as caught: + s.write(_rows(2), kafka_offsets=self.OFFSETS) + # The server's own exception stays reachable: the operator needs + # the wire code, and a future caller may want to branch on it. + assert caught.value.__cause__ is exc + assert caught.value.retryable is True + assert hoglake.is_retryable(caught.value) is True + assert s._prepared is None + assert s._live_info is None + assert _orphans(mock_metrics) == [(reason, 1)] + mock_metrics.hoglake_files_written_total.inc.assert_not_called() + mock_metrics.hoglake_commit_replays_total.labels.assert_not_called() + + @pytest.mark.parametrize(("exc", "match", "reason"), REFUSALS) + @patch("millpond.hoglake.metrics") + def test_the_retry_rebuilds_against_a_fresh_read_and_commits(self, mock_metrics, exc, match, reason): + s, client, catalog, ns, table = _sink() + catalog.commit_prepared.side_effect = [exc, MagicMock(snapshot_id=8, schema_version=1)] + with pytest.raises(hoglake.HoglakeSinkError): + s.write(_rows(2), kafka_offsets=self.OFFSETS) + table.info.reset_mock() + # main.py's retry loop: reset_caches, then the same flush again. + s.reset_caches() + assert s.write(_rows(2), kafka_offsets=self.OFFSETS) == 2 + # Rebuilt, not replayed — the refused payload's basis could never + # be accepted, so re-sending it is a livelock. + assert table.prepare_append_tables.call_count == 2 + assert table.info.call_count == 1 # read fresh + assert ns.table.call_count == 2 # the destination WAS re-resolved + + @patch("millpond.hoglake.metrics") + def test_the_rebuild_computes_values_under_the_spec_that_refused_it(self, mock_metrics): + """ "Rebuilds against a fresh read" has to mean the LAYOUT, not + just the columns. + + `ddl_since_read_snapshot` is what a same-arity re-spec looks like + from the client, and a rebuild that re-read the columns but kept + the old partition spec would upload a second set of + mis-partitioned files and have them accepted — the refusal would + have bought nothing. So: flush 1 under `identity(team_id)` is + refused, the live spec is `bucket(team_id, 16)` by the time the + retry reads it, and the retry's groups, registrations and commit + message all have to describe the bucketed layout. + """ + cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) + s, client, catalog, ns, table = _sink(cfg, partition_spec=_spec(("team_id", "identity"))) + catalog.commit_prepared.side_effect = [ + DdlSinceReadSnapshotError( + "ddl_since_read_snapshot", + status_code=409, + detail="concurrent DDL since snapshot 41 on table(s): analytics.events", + tables=("analytics.events",), + read_snapshot=41, + ), + MagicMock(snapshot_id=8, schema_version=1), + ] + batch = pa.table({"uuid": ["a", "b", "c"], "team_id": [1, 2, 3]}) + with pytest.raises(hoglake.HoglakeSinkError, match="partition spec"): + s.write(batch, kafka_offsets=self.OFFSETS) + identity_values = [v for v, _ in _groups()] + assert identity_values == [("1",), ("2",), ("3",)] + + # The re-spec the server refused the commit over. Config moves + # with it, because a pod whose config disagreed with the live + # spec is the case `_reconcile_specs` stops outright. + s._cfg = _cfg(hoglake_partition_by=(("team_id", "bucket", 16),)) + _set_info(table, _FakeInfo(columns=tuple(_EVENTS_COLUMNS), partition_spec=_spec(("team_id", "bucket", 16)))) + s.reset_caches() + assert s.write(batch, kafka_offsets=self.OFFSETS) == 3 + + bucket_values = [v for v, _ in _groups()] + assert bucket_values != identity_values, "the rebuild kept the superseded spec's values" + assert all(v[0] is not None for v in bucket_values) + payload = _committed(catalog) + registered = [tuple(f["partition_values"]) for f in payload["appends"][0]["files"]] + assert registered == bucket_values + # The message counts the rebuilt fanout, not the refused one. + summary = payload["message"].split("\n")[0] + assert f"records=3 files={len(bucket_values)} partitions={len(bucket_values)} " in summary + + @pytest.mark.parametrize(("exc", "match", "reason"), REFUSALS) + @patch("millpond.hoglake.metrics") + def test_the_rebuild_reads_fresh_even_without_a_reset(self, mock_metrics, exc, match, reason): + """The recovery lives on the refusal, not on `reset_caches()`: a + caller that retries without resetting must still not rebuild the + same doomed payload. + + For a RECREATION that means more than dropping the shape, and + this test used to pass without proving it — the simulated + recreation left `table.table_uuid` alone, so the rebuild + re-prepared against an incarnation that was still (as far as the + mock was concerned) live, and a sink that had kept + `self._table_uuid` would have looked fine. Now the uuid moves, + which is what makes the assertions below bite: `_table_uuid` is + what `_prepare` pins `expected_table_uuid` to AND what + `_flush_key` hashes, so a sink that only dropped the shape + rebuilds with the dead incarnation's guard and key and is refused + identically for the whole retry budget. + """ + s, client, catalog, ns, table = _sink() + catalog.commit_prepared.side_effect = [exc, MagicMock(snapshot_id=8, schema_version=1)] + with pytest.raises(hoglake.HoglakeSinkError): + s.write(_rows(2), kafka_offsets=self.OFFSETS) + # The payload AND its identity go, so the next write cannot be + # recognized as a replay of it — which is what makes the + # following call a rebuild rather than a resend. + assert table.prepare_append_tables.call_count == 1 + assert s._prepared_offsets is None + + reborn = "deadbeef-0000-0000-0000-000000000000" + if isinstance(exc, IncarnationChangedError): + # The drop+recreate the server just refused over, now + # visible to the client: the name resolves to a new uuid. + _set_info(table, _FakeInfo(columns=tuple(_EVENTS_COLUMNS), table_uuid=reborn)) + table.table_uuid = reborn + # ...and the handle itself must have been dropped, or the + # rebuild never re-resolves and never sees any of that. + assert s._table is None + assert s._table_uuid is None + + table.info.reset_mock() + assert s.write(_rows(2), kafka_offsets=self.OFFSETS) == 2 + assert table.info.call_count == 1 + assert table.prepare_append_tables.call_count == 2 + + if isinstance(exc, IncarnationChangedError): + expected = table.prepare_append_tables.call_args.kwargs["expected_table_uuid"] + assert expected == reborn, "the rebuild still names the dead incarnation" + published = catalog.commit_prepared.call_args.args[0]["idempotency_key"] + assert published == _flush_key_for(s, self.OFFSETS, reborn) + assert published != _flush_key_for(s, self.OFFSETS, TABLE_UUID) + + @pytest.mark.parametrize(("exc", "match", "reason"), REFUSALS) + def test_pyhoglake_is_told_to_invalidate_its_own_cache_too(self, exc, match, reason): + # millpond's cached shape is only half of it: the + # `read_snapshot` a prepare sends comes from pyhoglake's writer + # cache, so a rebuild against a stale ONE of those re-sends the + # refused basis. Passing the Table is what makes pyhoglake drop + # it on a `re_prepare` refusal, and it is not optional dressing — + # without it the only other way out is `reset_caches()`, which is + # main.py's to call. + s, client, catalog, ns, table = _sink() + catalog.commit_prepared.side_effect = exc + with pytest.raises(hoglake.HoglakeSinkError): + s.write(_rows(2), kafka_offsets=self.OFFSETS) + assert catalog.commit_prepared.call_args.kwargs["table"] is table + + @patch("millpond.hoglake.metrics") + def test_a_plain_commit_conflict_takes_the_ordinary_answered_path(self, mock_metrics): + # `DdlSinceReadSnapshotError` is a SUBCLASS of + # `CommitConflictError`, so the arms are ordered: only the + # subclass is converted, and an ordinary OCC 409 keeps the + # behaviour it has always had here — the server judged it, so the + # payload is dropped and the flush rebuilds under fresh object + # names (which is also what clears the one plain 409 an + # append-only prepared commit can actually take, a removal-queue + # path collision). + s, client, catalog, ns, table = _sink() + catalog.commit_prepared.side_effect = CommitConflictError( + "commit_conflict", status_code=409, detail="removal queue collision" + ) + with pytest.raises(CommitConflictError): + s.write(_rows(2), kafka_offsets=self.OFFSETS) + assert s._prepared is None + # NOT the typed path: no `HoglakeSinkError`, the server's own + # exception propagates, and the handle survives (only a + # recreation invalidates the identity). + assert s._table is not None + assert s._table_uuid == TABLE_UUID + # The cached SHAPE goes, though, and that is the one thing a + # plain 409 shares with the typed refusals: pyhoglake's + # invalidation predicate is its own, so the only way to keep + # "the sink is never staler than pyhoglake's cache" true without + # re-deriving `_basis_was_cached` here is to drop ours on every + # judged commit. Over-dropping costs one read on the rebuild + # this refusal already forces. + assert s._live_info is None + + +class TestTheCacheNeverOutlivesPyhoglakes: + """Every commit the SERVER answered drops the sink's cached shape. + + pyhoglake drops `Table._cache` on a `re_prepare` refusal, on a 410, + and on any non-retryable refusal whose `read_snapshot` matched that + cache — a set that includes the reused-key 422 millpond turns into + SUCCESS and a 5xx (`HoglakeError.retryable` is False on the base + class). Each of those leaves pyhoglake re-reading on its next + prepare and the sink not, so pyhoglake's basis moves forward first + and the same-arity spec-drift hole the TTL exists to close reopens + INSIDE the TTL. + + The rule is therefore not "mirror pyhoglake's predicate" but "any + event that can drop pyhoglake's cache drops ours", which is every + `HoglakeError` out of the commit. These tests pin the two cases that + are easiest to miss, because neither looks like a cache event: one + of them is a success and the other is a flat refusal. + """ + + OFFSETS = (("events", 0, 30, 41),) + + @patch("millpond.hoglake.metrics") + def test_a_reused_key_accept_still_drops_the_shape(self, mock_metrics): + # The 422 that becomes success. pyhoglake invalidates on it + # (non-retryable, basis cached) while millpond returns 0 rows and + # carries on — so without the drop this is the one path that + # ends in a HEALTHY sink holding a shape staler than pyhoglake's. + s, client, catalog, ns, table = _sink() + catalog.commit_prepared.side_effect = ValidationError( + "validation", status_code=422, detail="idempotency_key reused with a different request" + ) + assert s.write(_rows(5), kafka_offsets=self.OFFSETS) == 0 + assert s._live_info is None + catalog.commit_prepared.side_effect = None + table.info.reset_mock() + assert s.write(_rows(2), kafka_offsets=(("events", 0, 42, 43),)) == 2 + assert table.info.call_count == 1 + + @patch("millpond.hoglake.metrics") + def test_a_plain_answered_refusal_drops_the_shape(self, mock_metrics): + s, client, catalog, ns, table = _sink() + catalog.commit_prepared.side_effect = ValidationError( + "validation", status_code=422, detail="path outside the catalog data path" + ) + with pytest.raises(ValidationError): + s.write(_rows(2), kafka_offsets=self.OFFSETS) + assert s._live_info is None + catalog.commit_prepared.side_effect = None + table.info.reset_mock() + assert s.write(_rows(2), kafka_offsets=(("events", 0, 42, 43),)) == 2 + assert table.info.call_count == 1 + + @patch("millpond.hoglake.metrics") + def test_a_5xx_drops_the_shape_but_keeps_the_payload(self, mock_metrics): + # `HoglakeError.retryable` is False on the base class, so + # pyhoglake's `_basis_was_cached` arm invalidates on a 503 too. + # The PAYLOAD still survives — a 5xx is not a verdict on the + # request — so this is a drop that must not become a discard. + s, client, catalog, ns, table = _sink() + catalog.commit_prepared.side_effect = HoglakeError("commit_queue_timeout", status_code=503) + with pytest.raises(HoglakeError): + s.write(_rows(2), kafka_offsets=self.OFFSETS) + assert s._live_info is None + assert s._prepared is not None + + def test_a_transport_failure_keeps_the_shape(self): + # The other side of the rule. Nothing was judged, pyhoglake's + # cache is untouched, and the payload is replayed verbatim with + # its basis frozen — so there is nothing to be stale about, and + # dropping would buy a read per flapping network. + s, client, catalog, ns, table = _sink() + catalog.commit_prepared.side_effect = httpx.ReadTimeout("no response") + with pytest.raises(httpx.ReadTimeout): + s.write(_rows(2), kafka_offsets=self.OFFSETS) + assert s._live_info is not None + assert s._prepared is not None class TestSpecChangeUnderAPreparedPayload: @@ -2252,7 +3156,18 @@ class TestSpecChangeUnderAPreparedPayload: and the spec_id the table has when the commit lands. The server never opens the file, so a same-arity re-spec between prepare and commit stamps identity values as bucket values — silent, permanent - mis-pruning of every future scan.""" + mis-pruning of every future scan. + + THE GUARD MOVED. The sink used to re-read the destination + immediately before every publish and compare the live spec against + the one `_prepare` computed under. Now the payload carries its own + `read_snapshot` and the SERVER answers it: a partition-spec change is + an alter, every alter mints one `table_altered` change row, and an + append-only commit's conflict scan over + (`table_dropped`, `table_altered`) since that snapshot is therefore + always the typed `ddl_since_read_snapshot` — atomically, under the + commit lock, with no client-side read and no residual window between + the check and the commit.""" OFFSETS = (("events", 0, 30, 41),) @@ -2260,21 +3175,29 @@ class TestSpecChangeUnderAPreparedPayload: def test_a_same_arity_spec_change_refuses_the_commit(self, mock_metrics): cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) s, client, catalog, ns, table = _sink(cfg, partition_spec=_spec(("team_id", "identity"))) - prepared = table.prepare_append_files.side_effect - - def prepare(files, **kwargs): - # The re-spec lands while the upload is in flight. - table.info.return_value = _FakeInfo( - columns=tuple(_EVENTS_COLUMNS), partition_spec=_spec(("team_id", "bucket", 16)) - ) - return prepared(files, **kwargs) - - table.prepare_append_files.side_effect = prepare - with pytest.raises(RuntimeError, match="partition spec"): + # The re-spec lands while the upload is in flight; the server + # sees it in the conflict window and refuses the commit. + catalog.commit_prepared.side_effect = DdlSinceReadSnapshotError( + "ddl_since_read_snapshot", + status_code=409, + detail="concurrent DDL since snapshot 41 on table(s): analytics.events", + tables=("analytics.events",), + read_snapshot=41, + ) + with pytest.raises(hoglake.HoglakeSinkError, match="partition spec"): s.write(pa.table({"uuid": ["a"], "team_id": [1]}), kafka_offsets=self.OFFSETS) - catalog.commit_prepared.assert_not_called() assert s._prepared is None - mock_metrics.hoglake_orphaned_files_total.inc.assert_called_once_with(1) + assert _orphans(mock_metrics) == [("ddl_since_read_snapshot", 1)] + + def test_the_payload_carries_the_basis_that_makes_that_answerable(self): + # Without `read_snapshot` the commit has no conflict window at + # all: the file registers its old-spec values under the new + # spec_id and nothing anywhere can detect it. (It is also the + # shape HOGLAKE_REFUSE_BLIND_PARTITIONED_APPENDS will refuse.) + cfg = _cfg(hoglake_partition_by=(("team_id", "identity", None),)) + s, client, catalog, ns, table = _sink(cfg, partition_spec=_spec(("team_id", "identity"))) + s.write(pa.table({"uuid": ["a"], "team_id": [1]}), kafka_offsets=self.OFFSETS) + assert catalog.commit_prepared.call_args.args[0]["read_snapshot"] == 41 def test_the_refusal_is_retryable(self): # Unlike the sink's other stops: a REBUILT flush computes its @@ -2298,83 +3221,98 @@ def test_zero_row_batch_never_reaches_the_commit(self): class TestConcurrentAddDuringAppend: """The concurrent-`add_column` race, in both halves. - `_evolve_and_align` null-fills against the columns it resolved; a - beat later `_prepare` adopts a FRESH `table.info()`. Another writer's - add_column in that window puts a name in the target schema the batch - does not carry. The alignment must survive that on its own, and the - self-heal behind it must match the refusals pyhoglake ACTUALLY - raises. + `_evolve_and_align` null-fills against the columns it resolved; + `_prepare` then aligns against the sink's cached `TableInfo`. Another + writer's add_column puts a name in one of those and not the other. + The alignment must survive that on its own, and the self-heal behind + it must match the refusals pyhoglake ACTUALLY raises. + + WHAT CHANGED with the zero-read flush: `_prepare` no longer takes a + fresh `table.info()`, so the window is no longer "between + `_evolve_and_align` and `_prepare`" — it is between the read that + seeded the cache and the commit. Both halves below still hold, and + the second one is now the PRIMARY path rather than a second line of + defence: a cached shape that has gone stale is caught by + `prepare_append_tables` comparing the encoded footer against the + destination schema it builds from its own (fresher) read, and the + self-heal answers it. """ - def test_column_added_between_align_and_prepare_is_null_filled(self): + def test_a_cached_column_the_batch_lacks_is_null_filled_not_a_keyerror(self): # The live-suite failure (`KeyError: Field "col_w1_0" does not # exist in schema`): pa.Table.select raises KeyError, not a # ValidationError, so the self-heal never fired for its own # motivating case — and KeyError classifies as retryable, so the # pod burned its whole budget and then crashed. # - # This test is also what retires the KeyError arm the self-heal - # once carried: `_prepare` null-fills against `info.columns` and - # then selects names from that same object, so the select can - # only ever narrow. The column below arriving between the two - # resolves is exactly the case that used to raise, and it is + # The invariant that retires that arm is unchanged by the cache: + # `_prepare` null-fills against the SAME info object it then + # selects names from, so the select can only ever narrow. Here + # the cached shape carries a column `_evolve_and_align` never saw + # (another writer added it before this pod resolved the table), + # which is exactly the shape that used to raise — and it is # null-filled without the self-heal being consulted at all. cols_after = _EVENTS_COLUMNS + [_col("other_writer_col", "string", 6, 6)] s, client, catalog, ns, table = _sink() - before = _FakeInfo(columns=tuple(_EVENTS_COLUMNS)) - after = _FakeInfo(columns=tuple(cols_after)) - # _ensure_table resolves against the old schema; _prepare adopts - # the new one. The window is one round trip wide in production. - table.info.side_effect = [before, after, after, after] + _set_info(table, _FakeInfo(columns=tuple(cols_after))) + # `table.columns` is what `_ensure_table` adopts first and it is + # the OLD shape; the cached info the flush aligns to is the new + # one. One round trip apart in production. + table.columns = tuple(_EVENTS_COLUMNS) assert s.write(_batch()) == 1 published = _published(table) assert "other_writer_col" in published.column_names assert published.column("other_writer_col").null_count == published.num_rows - assert table.prepare_append_files.call_count == 1 # no self-heal round needed + assert table.prepare_append_tables.call_count == 1 # no self-heal round needed @patch("millpond.hoglake.metrics") def test_align_refusal_refreshes_and_reappends_once(self, mock_metrics): - """The self-heal behind the null-fill, on the message pyhoglake - really raises: `prepare_append_files` compares the parquet's - schema (field IDs included) against the destination and refuses - with "prepared Parquet schema/field IDs differ from destination" - (client.py:901). The sink must refresh the live schema, - null-fill, and prepare ONCE more.""" + """The self-heal, on the message pyhoglake really raises: + `prepare_append_tables` compares the ENCODED parquet's schema + (field IDs included) against the destination and refuses with + "prepared Parquet schema/field IDs differ from destination" + (`_encode_group`, client.py:2126 at 1.3.7). The sink must refresh + the live schema, null-fill, and prepare ONCE more. + + This is the arm that makes the cached shape safe: pyhoglake's own + cache can refresh to a newer snapshot than millpond's copy, and + when it does, a column added in between shows up as this refusal + rather than as a file that silently does not match.""" cols_after = _EVENTS_COLUMNS + [_col("other_writer_col", "string", 6, 6)] s, client, catalog, ns, table = _sink() - prepared = table.prepare_append_files.side_effect + prepared = table.prepare_append_tables.side_effect calls = {"n": 0} - def prepare(files, **kwargs): + def prepare(groups, **kwargs): calls["n"] += 1 if calls["n"] == 1: raise ValidationError("prepared Parquet schema/field IDs differ from destination", status_code=None) - return prepared(files, **kwargs) + return prepared(groups, **kwargs) - table.prepare_append_files.side_effect = prepare - table.info.return_value = _FakeInfo(columns=tuple(cols_after)) + table.prepare_append_tables.side_effect = prepare + _set_info(table, _FakeInfo(columns=tuple(cols_after))) assert s.write(_batch()) == 1 - assert table.prepare_append_files.call_count == 2 + assert table.prepare_append_tables.call_count == 2 retried = _published(table) assert "other_writer_col" in retried.column_names assert retried.column("other_writer_col").null_count == retried.num_rows @patch("millpond.hoglake.metrics") def test_variant_path_column_refusal_also_self_heals(self, mock_metrics): - # The other real refusal string (parquet_schema.py:173). + # The other real refusal string (parquet_schema.py:197). s, client, catalog, ns, table = _sink() - prepared = table.prepare_append_files.side_effect + prepared = table.prepare_append_tables.side_effect calls = {"n": 0} - def prepare(files, **kwargs): + def prepare(groups, **kwargs): calls["n"] += 1 if calls["n"] == 1: raise ValidationError("prepared Parquet columns differ from destination", status_code=None) - return prepared(files, **kwargs) + return prepared(groups, **kwargs) - table.prepare_append_files.side_effect = prepare + table.prepare_append_tables.side_effect = prepare assert s.write(_batch()) == 1 - assert table.prepare_append_files.call_count == 2 + assert table.prepare_append_tables.call_count == 2 @patch("millpond.hoglake.metrics") def test_partition_arity_refusal_is_not_an_alignment_refusal(self, mock_metrics): @@ -2382,30 +3320,30 @@ def test_partition_arity_refusal_is_not_an_alignment_refusal(self, mock_metrics) # spec problem, not a column problem: re-aligning cannot fix it, # so it must not consume the one self-heal. s, *_, table = _sink() - table.prepare_append_files.side_effect = ValidationError( + table.prepare_append_tables.side_effect = ValidationError( "prepared file partition arity differs from destination", status_code=None ) with pytest.raises(ValidationError): s.write(_batch()) - assert table.prepare_append_files.call_count == 1 + assert table.prepare_append_tables.call_count == 1 @patch("millpond.hoglake.metrics") def test_other_validation_errors_still_raise(self, mock_metrics): s, *_, table = _sink() - table.prepare_append_files.side_effect = ValidationError("prepared file must contain rows", status_code=None) + table.prepare_append_tables.side_effect = ValidationError("prepared file must contain rows", status_code=None) with pytest.raises(ValidationError): s.write(_batch()) - assert table.prepare_append_files.call_count == 1 + assert table.prepare_append_tables.call_count == 1 @patch("millpond.hoglake.metrics") def test_persistent_align_refusal_raises_after_one_retry(self, mock_metrics): s, *_, table = _sink() - table.prepare_append_files.side_effect = ValidationError( + table.prepare_append_tables.side_effect = ValidationError( "prepared Parquet schema/field IDs differ from destination", status_code=None ) with pytest.raises(ValidationError): s.write(_batch()) - assert table.prepare_append_files.call_count == 2 + assert table.prepare_append_tables.call_count == 2 class TestWriteFailurePropagation: @@ -2413,13 +3351,13 @@ def test_append_failure_raises(self): # At-least-once: a failed write must surface to main.py's retry # loop; offsets only commit after write() returns. s, *_, table = _sink() - table.prepare_append_files.side_effect = CommitConflictError("conflict", status_code=409) + table.prepare_append_tables.side_effect = CommitConflictError("conflict", status_code=409) with pytest.raises(CommitConflictError): s.write(_batch()) def test_incarnation_change_raises(self): s, *_, table = _sink() - table.prepare_append_files.side_effect = IncarnationChangedError("recreated") + table.prepare_append_tables.side_effect = IncarnationChangedError("recreated") with pytest.raises(IncarnationChangedError): s.write(_batch()) @@ -2718,7 +3656,7 @@ def test_the_message_is_identical_on_a_replay(self, mock_metrics): s.write(_batch(), kafka_offsets=self.OFFSETS, trigger="size") first, second = (c[0][0]["message"] for c in catalog.commit_prepared.call_args_list) assert first == second - assert table.prepare_append_files.call_count == 1 # replayed, not rebuilt + assert table.prepare_append_tables.call_count == 1 # replayed, not rebuilt def test_a_rebuilt_flush_of_the_same_identity_says_the_same_thing(self): # The across-a-restart case: a new process rebuilds the flush @@ -2739,7 +3677,7 @@ class TestTheMessageCannotOrphanAnUpload: `_prepare` splits into "upload the objects" and "hold the request that registers them". Everything that can fail after the upload has - to be accounted for: `prepare_append_files` failures go through + to be accounted for: `prepare_append_tables` failures go through `_count_orphans`, which names the objects nobody will ever reference. A formatting bug raising after the upload — a `TypeError` on some future field, say — would leave those objects @@ -2760,7 +3698,7 @@ def test_a_formatter_failure_happens_before_any_upload(self, monkeypatch): # Nothing was serialized, nothing was uploaded, nothing was # committed — so there is nothing to orphan and nothing to count. assert _WRITTEN == [] - table.prepare_append_files.assert_not_called() + table.prepare_append_tables.assert_not_called() catalog.commit_prepared.assert_not_called() def test_the_message_is_formatted_before_the_upload_call(self): @@ -2771,4 +3709,4 @@ def test_the_message_is_formatted_before_the_upload_call(self): import inspect body = inspect.getsource(hoglake.HoglakeSink._prepare) - assert body.index("format_commit_message(") < body.index("prepare_append_files(") + assert body.index("format_commit_message(") < body.index("prepare_append_tables(") diff --git a/tests/unit/test_main.py b/tests/unit/test_main.py index 5dac5a4..2d2bcd3 100644 --- a/tests/unit/test_main.py +++ b/tests/unit/test_main.py @@ -1,3 +1,4 @@ +import logging from unittest.mock import MagicMock, patch import duckdb @@ -132,6 +133,121 @@ def test_resets_caches_on_retry(self, exc): ] +class TestFlushDeadline: + """The wall-clock bound on one flush, which the attempt count is not. + + The consume loop is single threaded, so every second a flush spends + retrying is a second `server.HealthState` sees no poll. Three costs + are invisible to the startup model: the server's `Retry-After` + floors each backoff gap (clamped per gap, never in sum), a rebuild + re-resolves the destination and re-reads its shape under their own + timeouts, and a stalled object store can hold one prepare far past + its allowance. So the loop stops on the clock — raising the last + error, which is the outcome exhausting the attempts already gives, + except that it happens while the process can still log why rather + than being SIGKILLed mid-flush with nothing in its own logs. + """ + + def _sink(self, budget_s=450.0, attempt_cost_s=65.0, attempts=6): + sink = MagicMock(spec=["write", "reset_caches", "close", "write_retry_budget", "write_flush_deadline"]) + sink.write.side_effect = OSError("S3 timeout") + sink.write_retry_budget.return_value = (attempts, 1.0) + sink.write_flush_deadline.return_value = (budget_s, attempt_cost_s) + return sink + + def _clock(self, step_s: float): + """A clock that advances `step_s` on every reading, so each + attempt's elapsed time grows without anything sleeping.""" + t = {"now": 0.0} + + def now(): + t["now"] += step_s + return t["now"] + + return now + + def test_a_flush_that_cannot_finish_another_attempt_stops_early(self): + # 100s per reading against a 450s budget and a 65s reservation: + # the deadline bites well before the 6 attempts run out. + sink = self._sink() + with patch("millpond.main.time"), pytest.raises(OSError): + _write_with_retry(sink, pa.table({"a": [1]}), destination="hoglake", now=self._clock(100.0)) + assert sink.write.call_count < 6, "the attempt budget was spent despite the deadline" + + def test_the_early_stop_is_logged_as_its_own_fact(self, caplog): + # "gave up on purpose" and "ran out of attempts" look identical + # in the exception and lead to different investigations, so the + # flag is greppable and the numbers behind the decision are on + # the line. + sink = self._sink() + with ( + caplog.at_level(logging.ERROR, logger="millpond.main"), + patch("millpond.main.time"), + pytest.raises(OSError), + ): + _write_with_retry(sink, pa.table({"a": [1]}), destination="hoglake", now=self._clock(100.0)) + assert "flush_deadline_exceeded=true" in caplog.text + assert "elapsed=" in caplog.text + assert "budget=450.0s" in caplog.text + assert "attempts=" in caplog.text + + @patch("millpond.main.metrics") + def test_the_early_stop_is_counted(self, mock_metrics): + sink = self._sink() + with patch("millpond.main.time"), pytest.raises(OSError): + _write_with_retry(sink, pa.table({"a": [1]}), destination="hoglake", now=self._clock(100.0)) + mock_metrics.errors_total.labels.assert_any_call(type="flush_deadline_exceeded") + + def test_a_fast_flush_spends_its_whole_attempt_budget(self): + # The negative, and the one that matters most: the deadline must + # not shorten the ladder a healthy-but-convoyed catalog needs. + # A clock that barely moves leaves every attempt affordable. + sink = self._sink() + with patch("millpond.main.time"), pytest.raises(OSError): + _write_with_retry(sink, pa.table({"a": [1]}), destination="hoglake", now=self._clock(0.01)) + assert sink.write.call_count == 6 + + @patch("millpond.main.metrics") + def test_a_fast_flush_is_not_counted_as_a_deadline_stop(self, mock_metrics): + sink = self._sink() + with patch("millpond.main.time"), pytest.raises(OSError): + _write_with_retry(sink, pa.table({"a": [1]}), destination="hoglake", now=self._clock(0.01)) + for call in mock_metrics.errors_total.labels.call_args_list: + assert call.kwargs.get("type") != "flush_deadline_exceeded" + + def test_a_sink_without_the_hook_is_unbounded_by_the_clock(self): + # DuckLake: three outer attempts over an inner loop with its own + # bound. Adding a deadline it never asked for would change a + # deployed path for no reason. + sink = MagicMock(spec=["write", "reset_caches", "close"]) + sink.write.side_effect = OSError("S3 timeout") + with patch("millpond.main.time"), pytest.raises(OSError): + _write_with_retry(sink, pa.table({"a": [1]}), now=self._clock(10_000.0)) + assert sink.write.call_count == 3 + + def test_the_deadline_never_blocks_the_first_attempt(self): + # However far behind the pod already is, the flush gets one try: + # refusing to attempt at all would advance nothing and crash on + # a batch that might have landed. + sink = self._sink(budget_s=1.0, attempt_cost_s=1000.0) + with patch("millpond.main.time"), pytest.raises(OSError): + _write_with_retry(sink, pa.table({"a": [1]}), destination="hoglake", now=self._clock(500.0)) + assert sink.write.call_count == 1 + + def test_the_hoglake_sinks_own_numbers_fit_the_budget(self): + # The hook's values, not a fixture's: the per-attempt reservation + # has to be the request timeout plus the prepare allowance, and + # the budget has to be the liveness deadline less the margin. + from millpond.config import _LIVENESS_BUDGET_S, _PREPARE_ALLOWANCE_S, hoglake_flush_deadline + + budget_s, attempt_cost_s = hoglake_flush_deadline(45.0) + assert attempt_cost_s == 45.0 + _PREPARE_ALLOWANCE_S + assert budget_s < _LIVENESS_BUDGET_S + # And the default ladder still fits inside it, or the deadline + # would be cutting healthy flushes short rather than doomed ones. + assert budget_s >= 6 * attempt_cost_s + + class TestWriteWithRetryErrorLabels: """The metric label distinguishes catalog-contention retries from every other write failure. Without this split, an alert on diff --git a/uv.lock b/uv.lock index f3b0b55..ce67715 100644 --- a/uv.lock +++ b/uv.lock @@ -8,7 +8,7 @@ exclude-newer-span = "P7D" [options.exclude-newer-package] pyducklake = "2026-08-14T00:00:00Z" -pyhoglake = "2026-09-23T22:00:00Z" +pyhoglake = "2026-10-01T02:00:00Z" [manifest] constraints = [ @@ -330,7 +330,7 @@ dependencies = [ { name = "psycopg", extra = ["binary"] }, { name = "pyarrow" }, { name = "pyducklake" }, - { name = "pyhoglake" }, + { name = "pyhoglake", extra = ["fast-upload"] }, { name = "pytz" }, { name = "pyyaml" }, ] @@ -360,7 +360,7 @@ requires-dist = [ { name = "psycopg", extras = ["binary"], specifier = ">=3.2" }, { name = "pyarrow", specifier = ">=21.0" }, { name = "pyducklake", specifier = ">=1.0.17" }, - { name = "pyhoglake", specifier = ">=1.3.0" }, + { name = "pyhoglake", extras = ["fast-upload"], specifier = ">=1.3.7" }, { name = "pytz", specifier = ">=2024.1" }, { name = "pyyaml", specifier = ">=6.0.3" }, ] @@ -704,16 +704,21 @@ wheels = [ [[package]] name = "pyhoglake" -version = "1.3.0" +version = "1.3.7" source = { registry = "https://pypi.org/simple" } dependencies = [ { name = "httpx" }, { name = "pyarrow" }, { name = "thrift" }, ] -sdist = { url = "https://files.pythonhosted.org/packages/7d/bc/b6cf3237c2de30054c84ce41ecca5eab725c42ad2b4eed742f9b6b6bcd1f/pyhoglake-1.3.0.tar.gz", hash = "sha256:686fd6bb3ce52ce15b98fb109d200ea8db3e178d6c00f88a4f5acb6927f415d6", size = 174521, upload-time = "2026-09-23T21:57:11.198Z" } +sdist = { url = "https://files.pythonhosted.org/packages/c7/51/933792f342f60c7a5fdc8d333877dc611aae353d316b803428b85072a110/pyhoglake-1.3.7.tar.gz", hash = "sha256:b04611ce4743680b5ebd150a87a3fdff3b526ac8c5169c2e7dc1813901be45c8", size = 228005, upload-time = "2026-10-01T01:55:03.377Z" } wheels = [ - { url = "https://files.pythonhosted.org/packages/bc/eb/1002cde0561464c56052d3adadcc754a1366c23e8bc5937c3bbe43049878/pyhoglake-1.3.0-py3-none-any.whl", hash = "sha256:ea1047bad214e6c510f4f24681effc3ac334a0ce349ce970c1046b87df0b116a", size = 68567, upload-time = "2026-09-23T21:57:09.852Z" }, + { url = "https://files.pythonhosted.org/packages/18/a0/de5581285653960cc76076ad80431b51408dca75374a779ab377a13e69b0/pyhoglake-1.3.7-py3-none-any.whl", hash = "sha256:25587845317df34cd15344bcb841ae66ae346a5e8b3820c390256b15d521153f", size = 96244, upload-time = "2026-10-01T01:55:02.035Z" }, +] + +[package.optional-dependencies] +fast-upload = [ + { name = "boto3" }, ] [[package]]